"No processes were matched" after set parameter KINETO_DAEMON_INIT_DELAY_S

[KepingYan]

Test script: scripts/pytorch/linear_model_example.py
If I run it with command KINETO_USE_DAEMON=1 python3 scripts/pytorch/linear_model_example.py, I will meet this error as described in docs manifests as a segfault.
Then I add parameter KINETO_DAEMON_INIT_DELAY_S to run this script KINETO_USE_DAEMON=1 KINETO_DAEMON_INIT_DELAY_S=3 python3 scripts/pytorch/linear_model_example.py, but the trace file won't be generated as expected.

$ dyno gputrace --log-file /tmp/libkineto_trace.json
Kineto config =
ACTIVITIES_LOG_FILE=/tmp/libkineto_trace.json
PROFILE_START_TIME=0
ACTIVITIES_DURATION_MSECS=500
PROFILE_REPORT_INPUT_SHAPES=false
PROFILE_PROFILE_MEMORY=false
PROFILE_WITH_STACK=false
PROFILE_WITH_FLOPS=false
PROFILE_WITH_MODULES=false
response length = 133
response = {"activityProfilersBusy":0,"activityProfilersTriggered":[],"eventProfilersBusy":0,"eventProfilersTriggered":[],"processesMatched":[]}
No processes were matched, please check --job-id or --pids flags

Environment:

Ubuntu 22.04
torch     2.4.0
dynolog install:
wget https://github.com/facebookincubator/dynolog/releases/download/v0.3.2/dynolog_0.3.2-0-amd64.deb
sudo dpkg -i dynolog_0.3.2-0-amd64.deb
sudo systemctl restart dynolog

[briancoutinho]

Hi @KepingYan , do you see this print "INFO:2022-10-22 00:59:13 151209:151209 init.cpp:98] Registering daemon config loader" docs
We can run dynolog, example script and dyno cmd in 3 different shells to get the expected behavior.

Also to help debug, does the machine have GPUs? Ideally, this should work for both CPU only and CPU+GPU systems but just checking

[htbig]

i have met the same thing,i have gpu,and i also see "INFO:2024-10-01 12:29:42 271363:271364 init.cpp:131] Registering daemon config loader, cpuOnly = 0",but i also see "response = {"activityProfilersBusy":0,"activityProfilersTriggered":[],"eventProfilersBusy":0,"eventProfilersTriggered":[],"processesMatched":[]}
No processes were matched, please check --job-id or --pids flags",i have point the --pids like this:sudo ./build/bin/dyno gputrace --log-file ./a.log --pids 271363

[htbig]

@KepingYan ,i have resolved this problem by add time.sleep(5) before i use GPU device in my script. you should have a try.

[KepingYan]

Hi @briancoutinho, this is the log of python scripts/pytorch/linear_model_example.py terminal, and it is executed on CPU+GPU(V100) systems.

$ KINETO_USE_DAEMON=1 KINETO_DAEMON_INIT_DELAY_S=1 python3 scripts/pytorch/linear_model_example.py
INFO:2024-10-09 14:45:19 384686:384687 init.cpp:131] Registering daemon config loader, cpuOnly =  0
ERROR: External init callback must run in same thread as registerClient (-932395456 != 2078357312)
cuda:0
99 874.3150024414062
10099 8.817167282104492
20099 8.817167282104492
30099 8.817168235778809
40099 8.817168235778809
50099 8.817168235778809
60099 8.817168235778809
70099 8.817168235778809
80099 8.817168235778809
90099 8.817168235778809
100099 8.817168235778809
110099 8.817168235778809
120099 8.817168235778809
130099 8.817168235778809
140099 8.817168235778809
150099 8.817168235778809
160099 8.817168235778809
170099 8.817168235778809
180099 8.817168235778809
190099 8.817168235778809
Result: y = 1.862860976586944e-09 + 0.8567266464233398 x + -1.0942008188408181e-08 x^2 + -0.09332837164402008 x^3

I've tried @htbig advice, but it doesn't work for my environment.

[zdddddda]

Test script: scripts/pytorch/linear_model_example.py If I run it with command KINETO_USE_DAEMON=1 python3 scripts/pytorch/linear_model_example.py, I will meet this error as described in docs manifests as a segfault. Then I add parameter KINETO_DAEMON_INIT_DELAY_S to run this script KINETO_USE_DAEMON=1 KINETO_DAEMON_INIT_DELAY_S=3 python3 scripts/pytorch/linear_model_example.py, but the trace file won't be generated as expected.

$ dyno gputrace --log-file /tmp/libkineto_trace.json
Kineto config =
ACTIVITIES_LOG_FILE=/tmp/libkineto_trace.json
PROFILE_START_TIME=0
ACTIVITIES_DURATION_MSECS=500
PROFILE_REPORT_INPUT_SHAPES=false
PROFILE_PROFILE_MEMORY=false
PROFILE_WITH_STACK=false
PROFILE_WITH_FLOPS=false
PROFILE_WITH_MODULES=false
response length = 133
response = {"activityProfilersBusy":0,"activityProfilersTriggered":[],"eventProfilersBusy":0,"eventProfilersTriggered":[],"processesMatched":[]}
No processes were matched, please check --job-id or --pids flags

Environment:

Ubuntu 22.04
torch     2.4.0
dynolog install:
wget https://github.com/facebookincubator/dynolog/releases/download/v0.3.2/dynolog_0.3.2-0-amd64.deb
sudo dpkg -i dynolog_0.3.2-0-amd64.deb
sudo systemctl restart dynolog

I have the same question. How do you solve it?

[zdddddda]

Restart dynolog.service failed.
Jan 16 22:16:03 systemd[1]: dynolog.service: Service RestartSec=100ms expired, scheduling restart.
Jan 16 22:16:03 systemd[1]: dynolog.service: Scheduled restart job, restart counter is at 5.
Jan 16 22:16:03 systemd[1]: Stopped Dynolog performance monitoring daemon.
Jan 16 22:16:03 systemd[1]: dynolog.service: Start request repeated too quickly.
Jan 16 22:16:03 systemd[1]: dynolog.service: Failed with result 'signal'.
Jan 16 22:16:03 systemd[1]: Failed to start Dynolog performance monitoring daemon.

[yinghai]

I had the same issue.

client

KINETO_USE_DAEMON=1 KINETO_DAEMON_INIT_DELAY_S=3 python scripts/pytorch/linear_model_example.py
INFO:2025-01-29 01:45:27 43221:43222 init.cpp:135] Registering daemon config loader, cpuOnly =  0
ERROR: External init callback must run in same thread as registerClient (375600704 != -775577600)
cuda:0
99 316.04437255859375
...

then dyno

response = {"activityProfilersBusy":0,"activityProfilersTriggered":[],"eventProfilersBusy":0,"eventProfilersTriggered":[],"processesMatched":[]}
No processes were matched, please check --job-id or --pids flags

server side

./build/bin/dynolog --enable_ipc_monitor


I20250129 01:45:33.642140 43206 LibkinetoConfigManager.cpp:266] Initiating on-demand GPU profiling for job ID 0, pids [0]
I20250129 01:45:33.642149 43206 LibkinetoConfigManager.cpp:307] On-demand request: 0 matching processes
I20250129 01:45:33.642153 43206 LibkinetoConfigManager.cpp:315] Installed activity profiler config for 0 process(es) (0 busy)

[yinghai]

Initiating on-demand GPU profiling for job ID 0, pids [0]

this seems pretty weird?

[yinghai]

More info. When i start the script without KINETO_DAEMON_INIT_DELAY_S=3, on the dyno_log server side, I can see that the script PID is registered

I20250129 04:42:10.183240 43204 LibkinetoConfigManager.cpp:194] Registered process (43690, 25650, 24880, 1428) for job 0.
I20250129 04:42:10.183279 43204 IPCMonitor.cpp:84] getLibkinetoOnDemandRequest() : job id 0 pids = 43690

when I start the script with KINETO_DAEMON_INIT_DELAY_S=3, however, there is no log on the dyno_log server side which seems to suggest that the pytorch program is not sending the message to dyno_log server?

[yinghai]

On the client side, when I don't use KINETO_DAEMON_INIT_DELAY_S=3, I see a bunch of kineto logs being printed out

INFO:2025-01-29 05:13:33 44126:44126 init.cpp:135] Registering daemon config loader, cpuOnly =  1
INFO:2025-01-29 05:13:36 44126:44126 CuptiActivityProfiler.cpp:241] CUDA versions. CUPTI: 22; Runtime: 12040; Driver: 12040
INFO:2025-01-29 05:13:36 44126:44126 DaemonConfigLoader.cpp:64] Setting communication fabric enabled = 1
INFO:2025-01-29 05:13:36 44126:44128 DaemonConfigLoader.cpp:64] Setting communication fabric enabled = 1
INFO:2025-01-29 05:13:36 44126:44126 IpcFabricConfigClient.cpp:88] Setting up IPC Fabric at endpoint: dynoconfigclientc45743f1-92bd-46e5-a6fa-2e4d1a9484fe stat
us = initialized

which makes sense as then it will send message to dynolog server
https://github.com/pytorch/kineto/blob/09e10ad38fdcdcba065f2e5871a219fa9a9f0067/libkineto/src/IpcFabricConfigClient.cpp#L151-L175

but when I use KINETO_DAEMON_INIT_DELAY_S=3, I only got

INFO:2025-01-29 05:25:14 44304:44305 init.cpp:135] Registering daemon config loader, cpuOnly =  0
ERROR: External init callback must run in same thread as registerClient (1258501696 != 107225088)

no log like INFO:2025-01-29 05:13:36 44126:44126 IpcFabricConfigClient.cpp:88] Setting up IPC Fabric at endpoint: dynoconfigclientc45743f1-92bd-46e5-a6fa-2e4d1a9484fe stat

I wonder if

ERROR: External init callback must run in same thread as registerClient (1258501696 != 107225088)

is legit error that is preventing kineto init from making further progress?

[yinghai]

Update
I was able to build pytorch/kineto and play around, so far I think

ERROR: External init callback must run in same thread as registerClient (1258501696 != 107225088)

is not related as even if I patch pytorch/pytorch@c934ed6 and make the above error go away, the issue still exists.

So far I was able to localize the issue being
https://github.com/pytorch/kineto/blob/d9753139d181b9ff42872465aac0e5d3018be415/libkineto/src/ActivityProfilerProxy.cpp#L27 not being called when cpu_only=0, while it is called when cpu_only=1.

@briancoutinho do you know how the init() function above is triggered?

[yinghai]

traced a bit more, I think the difference is when cpu_only=1, we hit this code path
https://github.com/pytorch/kineto/blob/0cded49b0cce22f7d777861db5c937da7f3e22db/libkineto/src/init.cpp#L221
which triggers the libkineto::api().initProfilerIfRegistered(); call.

When cpu_only=0, supposingly we should hit this function https://github.com/pytorch/kineto/blob/0cded49b0cce22f7d777861db5c937da7f3e22db/libkineto/src/init.cpp#L62 upon first cuda context creation: https://github.com/pytorch/kineto/blob/0cded49b0cce22f7d777861db5c937da7f3e22db/libkineto/src/init.cpp#L153-L154 but looks like this is not being triggered. Will check why.

[yinghai]

these operations are all successful
https://github.com/pytorch/kineto/blob/0cded49b0cce22f7d777861db5c937da7f3e22db/libkineto/src/init.cpp#L146-L156

I guess somehow the cupti RESOURCE_CONTEXT_CREATED hook is not reliable anymore.

my cuda info

Driver Version: 550.144.03     CUDA Version: 12.4

[briancoutinho]

Hi @yinghai , just wanted to confirm, the original issue is caused by
"External init callback must run in same thread as registerClient"

The issue is when we add the delay, PyTorch uses a different thread to init the profiler state, and this was clashing with this check. It used to work before but it started failing here at some point in PyTorch-
https://github.com/pytorch/kineto/blob/d9753139d181b9ff42872465aac0e5d3018be415/libkineto/src/libkineto_api.cpp#L23-L31

Fix

In a more recent versions of PyTorch, you don't need the delay anymore and the init function is called when we "import torch". You shared the patch above too
pytorch/pytorch#131448

Init Flow explanation

For completeness, just wanted to share the init flow

1. With above patch, when torch is loaded it will cal libkineto_init from "global_kineto_init()" function. Cpu only will be set to 0 assuming a CUDA build.
2. For actual init
   2a If it is a CPU build the init is done immediately.
   https://github.com/pytorch/kineto/blob/d9753139d181b9ff42872465aac0e5d3018be415/libkineto/src/init.cpp#L220-L221
   2.b For a CUDA build, the init is registered as a callback on the creation of a CUDA Context
   https://github.com/pytorch/kineto/blob/d9753139d181b9ff42872465aac0e5d3018be415/libkineto/src/init.cpp#L142-L158
   The callback function is "initProfilers()".
3. Either options above will call the underlying functions in ActivityProfiler* files -> that eventually register with dynolog.

I think callbacks were not triggered, could you check if you run "nvidia-smi" that the process id shows up? Then it means there is a valid CUDA context.

[briancoutinho]

Catching up on other messages. I am not sure why we are not triggering on CUDA context creation.

With your patched build we should not be delaying the init as well. Just to confirm, can you remove the delay variable too

KINETO_USE_DAEMON=1 python scripts/pytorch/linear_model_example.py