Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[Fork support] Performance regression during Prefork handling #38307

Open
villainb-dg opened this issue Dec 18, 2024 · 0 comments
Open

[Fork support] Performance regression during Prefork handling #38307

villainb-dg opened this issue Dec 18, 2024 · 0 comments
Assignees
@eugeneo
Labels
kind/bug lang/core priority/P2

Comments

@villainb-dg
Copy link

villainb-dg commented Dec 18, 2024 •
edited
Loading

What version of gRPC and what language are you using?

  • grpc >=1.61.0 (started at commit 86308f12
  • Python

What operating system (Linux, Windows,...) and version?

Linux 5.15.0 Ubuntu 20.04.1

What runtime / compiler are you using (e.g. python version or version of gcc)

  • Python 3.10
  • g++ 9.4.0

What did you do?

Following Python script runs forks repeatedly:

#!/usr/bin/env python3
import logging
import os
import time

import grpc

import helloworld_pb2
import helloworld_pb2_grpc

log = logging.getLogger(__file__)

def work_child():
    log.info("Finished doing work")


if __name__ == "__main__":
    logging.basicConfig(level=logging.INFO)
    threads = []
    channel = grpc.insecure_channel("localhost:50051")
    stub = helloworld_pb2_grpc.GreeterStub(channel)
    response = stub.SayHello(helloworld_pb2.HelloRequest(name="you"))

    for _ in range(100):
        childs = []
        for i in range(3):
            before = time.time()
            pid = os.fork()
            if pid == 0:  # Child
                log.info("Time in child to fork %f", time.time() - before)
                work_child()
                os._exit(0)
            else:
                log.info("Time in parent to fork %f", time.time() - before)
                childs.append(pid)
                c_pid, status = os.waitpid(pid, os.WNOHANG)
                log.info("PID %d status=%s c_pid=%d", pid, status, c_pid)

        for child in childs:
            pid, status = os.waitpid(child, 0)

When running the script before and after the aforementioned commit I observe fork time orders of magnitude higher for the 1 one of a batch (ie. ~0.3s instead of ~0.002s).

What did you expect to see?

I would expect to see consistent fork time of ~0.002s.

What did you see instead?

I see fork time of ~0.3s for some of the batchs. Consistently the first fork of a batch is the one impacted, the others are always around 0.002s.

INFO:test2.py:[Batch 0][Fork 0] Time in parent to fork 0.020984
INFO:test2.py:[Batch 0][Fork 0] Time in child to fork 0.021497
INFO:test2.py:[Batch 0][Fork 1] Time in parent to fork 0.020914
INFO:test2.py:[Batch 0][Fork 1] Time in child to fork 0.021431
INFO:test2.py:[Batch 0][Fork 2] Time in parent to fork 0.002166
INFO:test2.py:[Batch 0][Fork 2] Time in child to fork 0.002646
INFO:test2.py:[Batch 1][Fork 0] Time in parent to fork 0.320488     # <<<<<<< Long fork measured from parent
INFO:test2.py:[Batch 1][Fork 0] Time in child to fork 0.321145        # <<<<<<< Long fork measured from child
INFO:test2.py:[Batch 1][Fork 1] Time in parent to fork 0.021240
INFO:test2.py:[Batch 1][Fork 1] Time in child to fork 0.021920
INFO:test2.py:[Batch 1][Fork 2] Time in parent to fork 0.002624
INFO:test2.py:[Batch 1][Fork 2] Time in child to fork 0.003191
INFO:test2.py:[Batch 2][Fork 0] Time in parent to fork 0.320394      # <<<<<<< Long fork measured from parent
INFO:test2.py:[Batch 2][Fork 0] Time in child to fork 0.321048         # <<<<<<< Long fork measured from child
INFO:test2.py:[Batch 2][Fork 1] Time in parent to fork 0.002640
INFO:test2.py:[Batch 2][Fork 1] Time in child to fork 0.003286
INFO:test2.py:[Batch 2][Fork 2] Time in parent to fork 0.002485
INFO:test2.py:[Batch 2][Fork 2] Time in child to fork 0.003113
INFO:test2.py:[Batch 3][Fork 0] Time in parent to fork 0.002624
INFO:test2.py:[Batch 3][Fork 0] Time in child to fork 0.003245
INFO:test2.py:[Batch 3][Fork 1] Time in parent to fork 0.021043
INFO:test2.py:[Batch 3][Fork 1] Time in child to fork 0.021603
INFO:test2.py:[Batch 3][Fork 2] Time in parent to fork 0.020887
INFO:test2.py:[Batch 3][Fork 2] Time in child to fork 0.021427
INFO:test2.py:[Batch 4][Fork 0] Time in parent to fork 0.002417
INFO:test2.py:[Batch 4][Fork 0] Time in child to fork 0.002972
INFO:test2.py:[Batch 4][Fork 1] Time in parent to fork 0.020885
INFO:test2.py:[Batch 4][Fork 1] Time in child to fork 0.021430
INFO:test2.py:[Batch 4][Fork 2] Time in parent to fork 0.020883
INFO:test2.py:[Batch 4][Fork 2] Time in child to fork 0.021375
INFO:test2.py:[Batch 5][Fork 0] Time in parent to fork 0.320151
INFO:test2.py:[Batch 5][Fork 0] Time in child to fork 0.320711
INFO:test2.py:[Batch 5][Fork 1] Time in parent to fork 0.002324
INFO:test2.py:[Batch 5][Fork 1] Time in child to fork 0.002795
INFO:test2.py:[Batch 5][Fork 2] Time in parent to fork 0.021006
INFO:test2.py:[Batch 5][Fork 2] Time in child to fork 0.021553
INFO:test2.py:[Batch 6][Fork 0] Time in parent to fork 0.002245
INFO:test2.py:[Batch 6][Fork 0] Time in child to fork 0.002792
INFO:test2.py:[Batch 6][Fork 1] Time in parent to fork 0.020804
INFO:test2.py:[Batch 6][Fork 1] Time in child to fork 0.021338
INFO:test2.py:[Batch 6][Fork 2] Time in parent to fork 0.020722
INFO:test2.py:[Batch 6][Fork 2] Time in child to fork 0.021198

Anything else we should know about your project / environment?
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@eugeneo eugeneo

Labels
kind/bug lang/core priority/P2
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@eugeneo @yashykt @villainb-dg