search

kwlzn / pytracing

a python trace profiler that outputs to chrome trace-viewer format (about://tracing).
MIT License
64 stars 17 forks source link

doesn't work with multiple processes #5

Open kylemcdonald opened 5 years ago

kylemcdonald commented 5 years ago

Testing the threading behavior, it seems to work:

from time import sleep
from multiprocessing import Process
from threading import Thread

from pytracing import TraceProfiler
tp = TraceProfiler(output=open('trace.out', 'w'))

def my_func():
    sleep(0.1)

def job():
    for i in range(10):
        my_func()

with tp.traced():
    worker = Thread(target=job)
    worker.start()
    worker.join()

Output:

[{"name": "setprofile", "cat": "/opt/conda/lib/python3.7/threading.py", "tid": "MainThread", "ph": "B", "pid": 31643, "ts": 1567737831818549.0, "args": {"function": "/opt/conda/lib/python3.7/threading.py:51:setprofile", "caller": "/opt/conda/lib/python3.7/site-packages/pytracing/pytracing.py:87"}},
{"name": "setprofile", "cat": "/opt/conda/lib/python3.7/threading.py", "tid": "MainThread", "ph": "E", "pid": 31643, "ts": 1567737831818581.8, "args": {"function": "/opt/conda/lib/python3.7/threading.py:59:setprofile", "caller": "/opt/conda/lib/python3.7/site-packages/pytracing/pytracing.py:87"}},
{"name": "install", "cat": "/opt/conda/lib/python3.7/site-packages/pytracing/pytracing.py", "tid": "MainThread", "ph": "E", "pid": 31643, "ts": 1567737831818595.5, "args": {"function": "/opt/conda/lib/python3.7/site-packages/pytracing/pytracing.py:87:install", "caller": "/opt/conda/lib/python3.7/site-packages/pytracing/pytracing.py:77"}},
{"name": "traced", "cat": "/opt/conda/lib/python3.7/site-packages/pytracing/pytracing.py", "tid": "MainThread", "ph": "E", "pid": 31643, "ts": 1567737831818607.2, "args": {"function": "/opt/conda/lib/python3.7/site-packages/pytracing/pytracing.py:79:traced", "caller": "/opt/conda/lib/python3.7/contextlib.py:112"}},
...
{"name": "my_func", "cat": "trace-test.py", "tid": "Thread-2", "ph": "B", "pid": 31643, "ts": 1567737832524081.0, "args": {"function": "trace-test.py:8:my_func", "caller": "trace-test.py:13"}},
{"name": "my_func", "cat": "trace-test.py", "tid": "Thread-2", "ph": "E", "pid": 31643, "ts": 1567737832624371.2, "args": {"function": "trace-test.py:9:my_func", "caller": "trace-test.py:13"}},
{"name": "my_func", "cat": "trace-test.py", "tid": "Thread-2", "ph": "B", "pid": 31643, "ts": 1567737832624472.8, "args": {"function": "trace-test.py:8:my_func", "caller": "trace-test.py:13"}},
{"name": "my_func", "cat": "trace-test.py", "tid": "Thread-2", "ph": "E", "pid": 31643, "ts": 1567737832724892.2, "args": {"function": "trace-test.py:9:my_func", "caller": "trace-test.py:13"}},
{"name": "my_func", "cat": "trace-test.py", "tid": "Thread-2", "ph": "B", "pid": 31643, "ts": 1567737832724994.5, "args": {"function": "trace-test.py:8:my_func", "caller": "trace-test.py:13"}},
{"name": "my_func", "cat": "trace-test.py", "tid": "Thread-2", "ph": "E", "pid": 31643, "ts": 1567737832825280.2, "args": {"function": "trace-test.py:9:my_func", "caller": "trace-test.py:13"}},
{"name": "job", "cat": "trace-test.py", "tid": "Thread-2", "ph": "E", "pid": 31643, "ts": 1567737832825382.8, "args": {"function": "trace-test.py:13:job", "caller": "/opt/conda/lib/python3.7/threading.py:865"}},
{"name": "run", "cat": "/opt/conda/lib/python3.7/threading.py", "tid": "Thread-2", "ph": "E", "pid": 31643, "ts": 1567737832825455.8, "args": {"function": "/opt/conda/lib/python3.7/threading.py:869:run", "caller": "/opt/conda/lib/python3.7/threading.py:917"}},
{"name": "_bootstrap_inner", "cat": "/opt/conda/lib/python3.7/threading.py", "tid": "Dummy-3", "ph": "E", "pid": 31643, "ts": 1567737832825514.5, "args": {"function": "/opt/conda/lib/python3.7/threading.py:966:_bootstrap_inner", "caller": "/opt/conda/lib/python3.7/threading.py:885"}},
{"name": "_stop", "cat": "/opt/conda/lib/python3.7/threading.py", "tid": "MainThread", "ph": "B", "pid": 31643, "ts": 1567737832826049.8, "args": {"function": "/opt/conda/lib/python3.7/threading.py:968:_stop", "caller": "/opt/conda/lib/python3.7/threading.py:1050"}},
{"name": "_stop", "cat": "/opt/conda/lib/python3.7/threading.py", "tid": "MainThread", "ph": "E", "pid": 31643, "ts": 1567737832826144.5, "args": {"function": "/opt/conda/lib/python3.7/threading.py:989:_stop", "caller": "/opt/conda/lib/python3.7/threading.py:1050"}},
{"name": "_wait_for_tstate_lock", "cat": "/opt/conda/lib/python3.7/threading.py", "tid": "MainThread", "ph": "E", "pid": 31643, "ts": 1567737832826194.5, "args": {"function": "/opt/conda/lib/python3.7/threading.py:1050:_wait_for_tstate_lock", "caller": "/opt/conda/lib/python3.7/threading.py:1032"}},
{"name": "join", "cat": "/opt/conda/lib/python3.7/threading.py", "tid": "MainThread", "ph": "E", "pid": 31643, "ts": 1567737832826239.8, "args": {"function": "/opt/conda/lib/python3.7/threading.py:1036:join", "caller": "trace-test.py:18"}},
{"name": "__exit__", "cat": "/opt/conda/lib/python3.7/contextlib.py", "tid": "MainThread", "ph": "B", "pid": 31643, "ts": 1567737832826285.0, "args": {"function": "/opt/conda/lib/python3.7/contextlib.py:116:__exit__", "caller": "trace-test.py:18"}},
{"name": "traced", "cat": "/opt/conda/lib/python3.7/site-packages/pytracing/pytracing.py", "tid": "MainThread", "ph": "B", "pid": 31643, "ts": 1567737832826331.8, "args": {"function": "/opt/conda/lib/python3.7/site-packages/pytracing/pytracing.py:79:traced", "caller": "/opt/conda/lib/python3.7/contextlib.py:119"}},
{"name": "shutdown", "cat": "/opt/conda/lib/python3.7/site-packages/pytracing/pytracing.py", "tid": "MainThread", "ph": "B", "pid": 31643, "ts": 1567737832826373.5, "args": {"function": "/opt/conda/lib/python3.7/site-packages/pytracing/pytracing.py:89:shutdown", "caller": "/opt/conda/lib/python3.7/site-packages/pytracing/pytracing.py:81"}},
{}]

Changing the one line to worker = Process(target=job) I get very long output that catches the Process being created and joined, but doesn't see anything inside. My current solution is to create a pytracing object for each Process, and then I'm going to try and rename/munge and concatenate the traces:

[{"name": "setprofile", "cat": "/opt/conda/lib/python3.7/threading.py", "tid": "MainThread", "ph": "B", "pid": 31646, "ts": 1567737927785154.8, "args": {"function": "/opt/conda/lib/python3.7/threading.py:51:setprofile", "caller": "/opt/conda/lib/python3.7/site-packages/pytracing/pytracing.py:87"}},
{"name": "setprofile", "cat": "/opt/conda/lib/python3.7/threading.py", "tid": "MainThread", "ph": "E", "pid": 31646, "ts": 1567737927785187.8, "args": {"function": "/opt/conda/lib/python3.7/threading.py:59:setprofile", "caller": "/opt/conda/lib/python3.7/site-packages/pytracing/pytracing.py:87"}},
{"name": "install", "cat": "/opt/conda/lib/python3.7/site-packages/pytracing/pytracing.py", "tid": "MainThread", "ph": "E", "pid": 31646, "ts": 1567737927785201.2, "args": {"function": "/opt/conda/lib/python3.7/site-packages/pytracing/pytracing.py:87:install", "caller": "/opt/conda/lib/python3.7/site-packages/pytracing/pytracing.py:77"}},
{"name": "traced", "cat": "/opt/conda/lib/python3.7/site-packages/pytracing/pytracing.py", "tid": "MainThread", "ph": "E", "pid": 31646, "ts": 1567737927785213.2, "args": {"function": "/opt/conda/lib/python3.7/site-packages/pytracing/pytracing.py:79:traced", "caller": "/opt/conda/lib/python3.7/contextlib.py:112"}},
...
{"name": "_Popen", "cat": "/opt/conda/lib/python3.7/multiprocessing/context.py", "tid": "MainThread", "ph": "E", "pid": 31646, "ts": 1567737927860661.2, "args": {"function": "/opt/conda/lib/python3.7/multiprocessing/context.py:277:_Popen", "caller": "/opt/conda/lib/python3.7/multiprocessing/context.py:223"}},
{"name": "_Popen", "cat": "/opt/conda/lib/python3.7/multiprocessing/context.py", "tid": "MainThread", "ph": "E", "pid": 31646, "ts": 1567737927860712.8, "args": {"function": "/opt/conda/lib/python3.7/multiprocessing/context.py:223:_Popen", "caller": "/opt/conda/lib/python3.7/multiprocessing/process.py:112"}},
{"name": "start", "cat": "/opt/conda/lib/python3.7/multiprocessing/process.py", "tid": "MainThread", "ph": "E", "pid": 31646, "ts": 1567737927860834.5, "args": {"function": "/opt/conda/lib/python3.7/multiprocessing/process.py:117:start", "caller": "trace-test.py:17"}},
{"name": "join", "cat": "/opt/conda/lib/python3.7/multiprocessing/process.py", "tid": "MainThread", "ph": "B", "pid": 31646, "ts": 1567737927860894.0, "args": {"function": "/opt/conda/lib/python3.7/multiprocessing/process.py:133:join", "caller": "trace-test.py:18"}},
{"name": "_check_closed", "cat": "/opt/conda/lib/python3.7/multiprocessing/process.py", "tid": "MainThread", "ph": "B", "pid": 31646, "ts": 1567737927860934.8, "args": {"function": "/opt/conda/lib/python3.7/multiprocessing/process.py:90:_check_closed", "caller": "/opt/conda/lib/python3.7/multiprocessing/process.py:137"}},
{"name": "_check_closed", "cat": "/opt/conda/lib/python3.7/multiprocessing/process.py", "tid": "MainThread", "ph": "E", "pid": 31646, "ts": 1567737927860978.2, "args": {"function": "/opt/conda/lib/python3.7/multiprocessing/process.py:92:_check_closed", "caller": "/opt/conda/lib/python3.7/multiprocessing/process.py:137"}},
{"name": "wait", "cat": "/opt/conda/lib/python3.7/multiprocessing/popen_fork.py", "tid": "MainThread", "ph": "B", "pid": 31646, "ts": 1567737927861044.5, "args": {"function": "/opt/conda/lib/python3.7/multiprocessing/popen_fork.py:41:wait", "caller": "/opt/conda/lib/python3.7/multiprocessing/process.py:140"}},
{"name": "poll", "cat": "/opt/conda/lib/python3.7/multiprocessing/popen_fork.py", "tid": "MainThread", "ph": "B", "pid": 31646, "ts": 1567737927861133.8, "args": {"function": "/opt/conda/lib/python3.7/multiprocessing/popen_fork.py:25:poll", "caller": "/opt/conda/lib/python3.7/multiprocessing/popen_fork.py:48"}},
{"name": "poll", "cat": "/opt/conda/lib/python3.7/multiprocessing/popen_fork.py", "tid": "MainThread", "ph": "E", "pid": 31646, "ts": 1567737928872964.5, "args": {"function": "/opt/conda/lib/python3.7/multiprocessing/popen_fork.py:39:poll", "caller": "/opt/conda/lib/python3.7/multiprocessing/popen_fork.py:48"}},
{"name": "wait", "cat": "/opt/conda/lib/python3.7/multiprocessing/popen_fork.py", "tid": "MainThread", "ph": "E", "pid": 31646, "ts": 1567737928873103.2, "args": {"function": "/opt/conda/lib/python3.7/multiprocessing/popen_fork.py:48:wait", "caller": "/opt/conda/lib/python3.7/multiprocessing/process.py:140"}},
{"name": "join", "cat": "/opt/conda/lib/python3.7/multiprocessing/process.py", "tid": "MainThread", "ph": "E", "pid": 31646, "ts": 1567737928873165.5, "args": {"function": "/opt/conda/lib/python3.7/multiprocessing/process.py:142:join", "caller": "trace-test.py:18"}},
{"name": "__exit__", "cat": "/opt/conda/lib/python3.7/contextlib.py", "tid": "MainThread", "ph": "B", "pid": 31646, "ts": 1567737928873231.2, "args": {"function": "/opt/conda/lib/python3.7/contextlib.py:116:__exit__", "caller": "trace-test.py:18"}},
{"name": "traced", "cat": "/opt/conda/lib/python3.7/site-packages/pytracing/pytracing.py", "tid": "MainThread", "ph": "B", "pid": 31646, "ts": 1567737928873288.2, "args": {"function": "/opt/conda/lib/python3.7/site-packages/pytracing/pytracing.py:79:traced", "caller": "/opt/conda/lib/python3.7/contextlib.py:119"}},
{"name": "shutdown", "cat": "/opt/conda/lib/python3.7/site-packages/pytracing/pytracing.py", "tid": "MainThread", "ph": "B", "pid": 31646, "ts": 1567737928873348.8, "args": {"function": "/opt/conda/lib/python3.7/site-packages/pytracing/pytracing.py:89:shutdown", "caller": "/opt/conda/lib/python3.7/site-packages/pytracing/pytracing.py:81"}},
{}]
AndreyOrb commented 4 months ago

It will not work because a new process forks from the existing one. It will execute again all lines, including imports and "tp = TraceProfiler(output=open('trace.out', 'w'))" But the file "trace.out" is already opened for writing by the main process, so this line will fail.

In addition, even if you comment lines related to TraceProfiler, the code will fail. The second process will execute "worker = Process(target=job)", thus opening the 3rd process. The 3rd process will open 4th process, etc. It's essentially a fork bomb.

When working with multiple processes it's important to use "if name == 'main':". This LOC will ensure that only main process executes the main program logic.