module-profiler/pw-top ERR with node in different process is probably spurious
I've been looking at why Bluetooth nodes rack up the ERR count in pw-top. This seems to be because impl-node.c:process_node does not wait for the remote driver node async return to complete before emitting the complete
event, so that profiling data sometimes gets recorded at the same time as the remote node is still processing. I think this doesn't occur with ALSA nodes just because they run in the server process, so the process call is not async, and always completes first.
With some added debug (https://gitlab.freedesktop.org/pvir/pipewire/-/commits/bt-err-debug), things look like this:
# pipewire server process
[T][13:56:42.896603] pw.node | [ impl-node.c: 1624 node_ready()] 0x61d000028a80 (bluez_output.00_00_AB_CD_7A_DE.headset-head-unit): ready driver:1 exported:0 0x61d0
00028a80 status:2
[T][13:56:42.896624] pw.node | [ impl-node.c: 1054 resume_node()] 0x61d000028a80 (bluez_output.00_00_AB_CD_7A_DE.headset-head-unit): trigger peers 9614896808539
[T][13:56:42.896636] pw.node | [ impl-node.c: 1060 resume_node()] 0x61d000028a80 (bluez_output.00_00_AB_CD_7A_DE.headset-head-unit): state:0x7f1edc4e8008 pending:4/
4
[T][13:56:42.896649] pw.node | [ impl-node.c: 1060 resume_node()] 0x61d000028a80 (bluez_output.00_00_AB_CD_7A_DE.headset-head-unit): state:0x7f1edc4e8008 pending:3/
4
[T][13:56:42.896661] pw.node | [ impl-node.c: 1060 resume_node()] 0x61d00002b280 (pw-play): state:0x7f1edbe2e008 pending:1/1
[D][13:56:42.896672] pw.node | [ impl-node.c: 1093 process_node()] 0x61d00002b280 (pw-play) awaken for process
[T][13:56:42.896682] pw.node | [ impl-node.c: 1105 process_node()] 0x61d00002b280 (pw-play): process 9614896867028
[T][13:56:42.896694][ client-node.c: 932 impl_node_process()] 0x617000002720: send process driver:0x61d000028a80
[T][13:56:42.896708][ client-node.c: 943 impl_node_process()] 0x617000002720: send process async return
[T][13:56:42.896717] pw.node | [ impl-node.c: 1116 process_node()] 0x61d00002b280 (pw-play): process returns 0
[T][13:56:42.896727] pw.node | [ impl-node.c: 1145 process_node()] 0x61d00002b280: async continue
[D][13:56:42.896815] pw.node | [ impl-node.c: 1093 process_node()] 0x61d000028a80 (bluez_output.00_00_AB_CD_7A_DE.headset-head-unit) awaken for process
[T][13:56:42.896827] pw.node | [ impl-node.c: 1105 process_node()] 0x61d000028a80 (bluez_output.00_00_AB_CD_7A_DE.headset-head-unit): process 9614897011672
[T][13:56:42.896842][ client-node.c: 932 impl_node_process()] 0x6170000023a0: send process driver:0x61d000028a80
[T][13:56:42.896857][ client-node.c: 943 impl_node_process()] 0x6170000023a0: send process async return
[T][13:56:42.896869] pw.node | [ impl-node.c: 1116 process_node()] 0x61d000028a80 (bluez_output.00_00_AB_CD_7A_DE.headset-head-unit): process returns 0
[T][13:56:42.896890] pw.node | [ impl-node.c: 1132 process_node()] 0x61d000028a80 (bluez_output.00_00_AB_CD_7A_DE.headset-head-unit): graph completed wait:203133 run:62445 busy:265578 period:81838 cpu:4,270493:5,083025:5,204981 status:3
[T][13:56:42.896905] mod.profiler | [module-profiler.: 199 context_do_profile()] 0x61d000028a80 (bluez_output.00_00_AB_CD_7A_DE.headset-head-unit): do profile status:2
[T][13:56:42.896931] pw.node | [ impl-node.c: 1143 process_node()] 0x61d000028a80 (bluez_output.00_00_AB_CD_7A_DE.headset-head-unit): driver emit complete done
# at the same time, in wireplumber:
D 13:56:42.896504 spa.bluez5.sink.sc ../spa/plugins/bluez5/sco-sink.c:611:sco_on_timeout: 0x623000016d28: timer 9614896644587 42666666
T 13:56:42.896528 spa.bluez5.sink.sc ../spa/plugins/bluez5/sco-sink.c:633:sco_on_timeout: 0x623000016d28: 0
T 13:56:42.896537 mod.client-node ../src/modules/module-client-node/remote-node.c:1189:node_ready: node 0x61d000663a80: ready driver:1 exported:1 status:1
D 13:56:42.896888 pw.node ../src/pipewire/impl-node.c:1093:process_node: 0x61d000663a80 (bluez_output.00_00_AB_CD_7A_DE.headset-head-unit) awaken for process
T 13:56:42.896902 pw.node ../src/pipewire/impl-node.c:1105:process_node: 0x61d000663a80 (bluez_output.00_00_AB_CD_7A_DE.headset-head-unit): process 9614897084080
T 13:56:42.897047 spa.bluez5.sink.sc ../spa/plugins/bluez5/sco-sink.c:1259:impl_node_process: 0x623000016d28: queue buffer 0
T 13:56:42.897057 spa.bluez5.sink.sc ../spa/plugins/bluez5/sco-sink.c:1282:impl_node_process: 0x623000016d28: flush on process
T 13:56:42.897072 spa.bluez5.sink.sc ../spa/plugins/bluez5/sco-sink.c:526:flush_data: 0x623000016d28: send wrote:60 dt:9902009
T 13:56:42.897079 spa.bluez5.sink.sc ../spa/plugins/bluez5/sco-sink.c:531:flush_data: write socket data 60
T 13:56:42.897088 pw.node ../src/pipewire/impl-node.c:1116:process_node: 0x61d000663a80 (bluez_output.00_00_AB_CD_7A_DE.headset-head-unit): process returns 3
T 13:56:42.897095 pw.node ../src/pipewire/impl-node.c:1054:resume_node: 0x61d000663a80 (bluez_output.00_00_AB_CD_7A_DE.headset-head-unit): trigger peers 9614897278496
Profiler recording data with activation status 2 here triggers ERR count increase in pw-top. It changed from 3 to 2 during pw_context_driver_emit_complete
, apparently since the flag is on shared memory, and was changed due to the node in the remote process awakening for the async process call.
Probably it should somehow wait for the remote driver node to complete processing, before emitting the driver complete event.