search

roc-streaming / roc-toolkit

Real-time audio streaming over the network.
https://roc-streaming.org
Mozilla Public License 2.0
1.09k stars 213 forks source link

PulseAudio io-latency larger than sess-latency #184

Open gavv opened 5 years ago

gavv commented 5 years ago

If the IO latency is set larger than the session latency, PulseAudio may request samples too rare and the receiver is blocked on PulseAudio sink longer than its session latency, thus no playback is even possible.

It is reproducing (every time) on my Raspberry Pi 3B (PulseAudio 10.0), but not reproducing on my laptop (PulseAudio 12.2).

gavv commented 5 years ago 
$ ./roc-recv -vv -s :10003 -r :10004 --io-latency 1s
[info] roc_sndio: initializing pulseaudio backend
[info] roc_sndio: initializing sox backend
[debug] roc_recv: pool: initializing: object_size=2056 poison=0
[debug] roc_recv: pool: initializing: object_size=2568 poison=0
[debug] roc_recv: pool: initializing: object_size=408 poison=0
[debug] roc_sndio: pulseaudio sink: opening sink: device=(null)
[debug] roc_sndio: pulseaudio sink: opening stream: device=(null) n_channels=2 sample_rate=44100
[debug] roc_sndio: pulseaudio sink: stream_latency=0
[info] roc_netio: udp receiver: opened port 0.0.0.0:10003
[info] roc_netio: udp receiver: opened port 0.0.0.0:10004
[debug] roc_sndio: pump: starting
[debug] roc_netio: transceiver: starting event loop
[info] roc_pipeline: receiver: creating session
[debug] roc_packet: delayed reader: initializing: delay=8820
[debug] roc_fec: of decoder: initializing Reed-Solomon decoder
[debug] roc_audio: watchdog: initializing: max_blank_duration=88200 max_drops_duration=88200 drop_detection_window=13230
[debug] roc_audio: resampler: initializing: window_interp=128 window_size=32 frame_size=640 channels_num=2
[debug] roc_audio: resampler reader: initializing window
[debug] roc_audio: latency monitor: initializing: target_latency=8820 in_rate=44100 out_rate=44100
[debug] roc_packet: router: detected new stream: source=475195216 flags=0x8u
[debug] roc_audio: depacketizer: ts=320 loss_ratio=0.00000
[debug] roc_audio: watchdog: status: bbbbbbbbbbbbbbbbbbbb
[debug] roc_audio: watchdog: status: bbbbbbbbbbbbbbbbbbbb
[debug] roc_audio: watchdog: status: bbbbbbbbbbbbbbbbbbbb
[debug] roc_packet: router: detected new stream: source=0 flags=0x10u
[debug] roc_packet: delayed reader: initial queue: delay=8820 queue=21012 packets=68
[debug] roc_packet: delayed reader: trimmed queue: delay=8820 queue=8961 packets=29
[debug] roc_fec: fec reader: repair queue: dropped=10
[debug] roc_audio: depacketizer: got first packet: zero_samples=22080
[debug] roc_fec: fec reader: repair queue: dropped=10
[debug] roc_fec: fec reader: got first packet in a block, start decoding: n_packets_before=1 sn=12499 sbn=5085
[debug] roc_audio: latency monitor: latency=8641 target=8820 fe=1.00000 trim_fe=1.00000 adj_fe=1.00000
[debug] roc_audio: watchdog: status: bbbbbbbbb...........
[debug] roc_fec: of decoder: repaired 0/17/30 .............XXXXXXX xxxxxxxxxx
[debug] roc_audio: depacketizer: dropping late packet: ts=83803314 pkt_ts=83801660
[debug] roc_fec: of decoder: repaired 0/16/30 ..............XXXXXX xxxxxxxxxx
[debug] roc_audio: depacketizer: fetched=0 dropped=1
[debug] roc_audio: depacketizer: dropping late packet: ts=83805874 pkt_ts=83801969
[debug] roc_fec: of decoder: repaired 0/15/30 ...............XXXXX xxxxxxxxxx
[debug] roc_audio: depacketizer: fetched=0 dropped=1
[debug] roc_audio: watchdog: status: .ibbbbbBbbbbbbbBbbbb
[debug] roc_audio: depacketizer: dropping late packet: ts=83808434 pkt_ts=83802278
[debug] roc_fec: of decoder: repaired 0/14/30 ................XXXX xxxxxxxxxx
[debug] roc_audio: depacketizer: fetched=0 dropped=1
[debug] roc_audio: depacketizer: dropping late packet: ts=83810994 pkt_ts=83802587
[debug] roc_fec: of decoder: repaired 0/13/30 .................XXX xxxxxxxxxx
[debug] roc_audio: depacketizer: fetched=0 dropped=1
[debug] roc_audio: depacketizer: dropping late packet: ts=83811634 pkt_ts=83802896
[debug] roc_audio: depacketizer: dropping late packet: ts=83811634 pkt_ts=83803205
[debug] roc_audio: depacketizer: dropping late packet: ts=83811634 pkt_ts=83803514
[debug] roc_audio: depacketizer: dropping late packet: ts=83811634 pkt_ts=83803823
[debug] roc_audio: depacketizer: dropping late packet: ts=83811634 pkt_ts=83804132
[debug] roc_audio: depacketizer: dropping late packet: ts=83811634 pkt_ts=83804441
[debug] roc_audio: depacketizer: dropping late packet: ts=83811634 pkt_ts=83804750
[debug] roc_audio: depacketizer: dropping late packet: ts=83811634 pkt_ts=83805059
[debug] roc_audio: depacketizer: dropping late packet: ts=83811634 pkt_ts=83805368
[debug] roc_audio: depacketizer: dropping late packet: ts=83811634 pkt_ts=83805677
[debug] roc_audio: depacketizer: dropping late packet: ts=83811634 pkt_ts=83805986
[debug] roc_audio: depacketizer: dropping late packet: ts=83811634 pkt_ts=83806295
[debug] roc_audio: depacketizer: dropping late packet: ts=83811634 pkt_ts=83806604
[debug] roc_audio: depacketizer: dropping late packet: ts=83811634 pkt_ts=83806913
[debug] roc_audio: depacketizer: dropping late packet: ts=83811634 pkt_ts=83807222
[debug] roc_audio: depacketizer: dropping late packet: ts=83811634 pkt_ts=83807531
[debug] roc_audio: depacketizer: dropping late packet: ts=83811634 pkt_ts=83807840
[debug] roc_audio: depacketizer: dropping late packet: ts=83811634 pkt_ts=83808149
[debug] roc_audio: depacketizer: dropping late packet: ts=83811634 pkt_ts=83808458
[debug] roc_audio: depacketizer: dropping late packet: ts=83811634 pkt_ts=83808767
[debug] roc_audio: depacketizer: dropping late packet: ts=83811634 pkt_ts=83809076
[debug] roc_audio: depacketizer: dropping late packet: ts=83811634 pkt_ts=83809385
[debug] roc_audio: depacketizer: dropping late packet: ts=83811634 pkt_ts=83809694
[debug] roc_audio: depacketizer: dropping late packet: ts=83811634 pkt_ts=83810003
[debug] roc_audio: depacketizer: dropping late packet: ts=83811634 pkt_ts=83810312
[debug] roc_audio: depacketizer: dropping late packet: ts=83811634 pkt_ts=83810621
[debug] roc_audio: depacketizer: dropping late packet: ts=83811634 pkt_ts=83810930
[debug] roc_audio: depacketizer: dropping late packet: ts=83811634 pkt_ts=83811239
[debug] roc_audio: depacketizer: fetched=1 dropped=28
[debug] roc_audio: watchdog: status: bbbBbbbbbbbBbD......
[debug] roc_fec: of decoder: repaired 0/22/30 ........XXXXXXXXXXXX xxxxxxxxxx
[debug] roc_audio: depacketizer: dropping late packet: ts=83825714 pkt_ts=83824835
[debug] roc_fec: of decoder: repaired 0/21/30 .........XXXXXXXXXXX xxxxxxxxxx
[debug] roc_audio: depacketizer: fetched=0 dropped=1
[debug] roc_audio: watchdog: status: ..............ibbBbb
[debug] roc_audio: depacketizer: dropping late packet: ts=83826994 pkt_ts=83825144
[debug] roc_fec: of decoder: repaired 0/20/30 ..........XXXXXXXXXX xxxxxxxxxx
[debug] roc_audio: depacketizer: fetched=0 dropped=1
[debug] roc_audio: depacketizer: dropping late packet: ts=83828274 pkt_ts=83825453
[debug] roc_fec: of decoder: repaired 0/19/30 ...........XXXXXXXXX xxxxxxxxxx
[debug] roc_audio: depacketizer: fetched=0 dropped=1
[debug] roc_audio: depacketizer: dropping late packet: ts=83829234 pkt_ts=83825762
[debug] roc_fec: of decoder: repaired 0/18/30 ............XXXXXXXX xxxxxxxxxx
[debug] roc_audio: depacketizer: fetched=0 dropped=1
[debug] roc_audio: depacketizer: dropping late packet: ts=83830514 pkt_ts=83826071
[debug] roc_fec: of decoder: repaired 0/17/30 .............XXXXXXX xxxxxxxxxx
[debug] roc_audio: depacketizer: fetched=0 dropped=1
[debug] roc_audio: depacketizer: dropping late packet: ts=83832434 pkt_ts=83826380
[debug] roc_audio: depacketizer: dropping late packet: ts=83832434 pkt_ts=83826689
[debug] roc_audio: depacketizer: dropping late packet: ts=83832434 pkt_ts=83826998
[debug] roc_audio: depacketizer: dropping late packet: ts=83832434 pkt_ts=83827307
[debug] roc_audio: depacketizer: dropping late packet: ts=83832434 pkt_ts=83827616
[debug] roc_audio: depacketizer: dropping late packet: ts=83832434 pkt_ts=83827925
[debug] roc_audio: depacketizer: dropping late packet: ts=83832434 pkt_ts=83828234
[debug] roc_audio: depacketizer: dropping late packet: ts=83832434 pkt_ts=83828543
[debug] roc_audio: depacketizer: dropping late packet: ts=83832434 pkt_ts=83828852
[debug] roc_audio: depacketizer: dropping late packet: ts=83832434 pkt_ts=83829161
[debug] roc_audio: depacketizer: dropping late packet: ts=83832434 pkt_ts=83829470
[debug] roc_audio: depacketizer: dropping late packet: ts=83832434 pkt_ts=83829779
[debug] roc_audio: depacketizer: dropping late packet: ts=83832434 pkt_ts=83830088
[debug] roc_audio: depacketizer: dropping late packet: ts=83832434 pkt_ts=83830397
[debug] roc_audio: depacketizer: dropping late packet: ts=83832434 pkt_ts=83830706
[debug] roc_audio: depacketizer: dropping late packet: ts=83832434 pkt_ts=83831015
[debug] roc_audio: depacketizer: dropping late packet: ts=83832434 pkt_ts=83831324
[debug] roc_audio: depacketizer: dropping late packet: ts=83832434 pkt_ts=83831633
[debug] roc_audio: depacketizer: dropping late packet: ts=83832434 pkt_ts=83831942
[debug] roc_audio: depacketizer: fetched=1 dropped=19
[debug] roc_audio: watchdog: status: bBbbbBbbBbbbBbbbbbD.
[debug] roc_fec: of decoder: repaired 0/21/30 .........XXXXXXXXXXX xxxxxxxxxx
[debug] roc_audio: depacketizer: dropping late packet: ts=83845554 pkt_ts=83843684
[debug] roc_fec: of decoder: repaired 0/20/30 ..........XXXXXXXXXX xxxxxxxxxx
[debug] roc_audio: depacketizer: fetched=0 dropped=1
[debug] roc_audio: watchdog: status: .............ibbbbbB
[debug] roc_audio: depacketizer: dropping late packet: ts=83848114 pkt_ts=83843993
[debug] roc_fec: of decoder: repaired 0/19/30 ...........XXXXXXXXX xxxxxxxxxx
[debug] roc_audio: depacketizer: fetched=0 dropped=1
[debug] roc_audio: depacketizer: dropping late packet: ts=83850674 pkt_ts=83844302
[debug] roc_fec: of decoder: repaired 0/18/30 ............XXXXXXXX xxxxxxxxxx
[debug] roc_audio: depacketizer: fetched=0 dropped=1
[debug] roc_audio: watchdog: status: bbbbbbbBbbbbbbbBbbbb
[debug] roc_audio: depacketizer: dropping late packet: ts=83852914 pkt_ts=83844611
[debug] roc_fec: of decoder: repaired 0/17/30 .............XXXXXXX xxxxxxxxxx
[debug] roc_audio: depacketizer: fetched=0 dropped=1
[debug] roc_audio: depacketizer: dropping late packet: ts=83853554 pkt_ts=83844920
[debug] roc_audio: depacketizer: dropping late packet: ts=83853554 pkt_ts=83845229
[debug] roc_audio: depacketizer: dropping late packet: ts=83853554 pkt_ts=83845538
[debug] roc_audio: depacketizer: dropping late packet: ts=83853554 pkt_ts=83845847
[debug] roc_audio: depacketizer: dropping late packet: ts=83853554 pkt_ts=83846156
[debug] roc_audio: depacketizer: dropping late packet: ts=83853554 pkt_ts=83846465
[debug] roc_audio: depacketizer: dropping late packet: ts=83853554 pkt_ts=83846774
[debug] roc_audio: depacketizer: dropping late packet: ts=83853554 pkt_ts=83847083
[debug] roc_audio: depacketizer: dropping late packet: ts=83853554 pkt_ts=83847392
[debug] roc_audio: depacketizer: dropping late packet: ts=83853554 pkt_ts=83847701
[debug] roc_audio: depacketizer: dropping late packet: ts=83853554 pkt_ts=83848010
[debug] roc_audio: depacketizer: dropping late packet: ts=83853554 pkt_ts=83848319
[debug] roc_audio: depacketizer: dropping late packet: ts=83853554 pkt_ts=83848628
[debug] roc_audio: depacketizer: dropping late packet: ts=83853554 pkt_ts=83848937
[debug] roc_audio: depacketizer: dropping late packet: ts=83853554 pkt_ts=83849246
[debug] roc_audio: depacketizer: dropping late packet: ts=83853554 pkt_ts=83849555
[debug] roc_audio: depacketizer: dropping late packet: ts=83853554 pkt_ts=83849864
[debug] roc_audio: depacketizer: dropping late packet: ts=83853554 pkt_ts=83850173
[debug] roc_audio: depacketizer: dropping late packet: ts=83853554 pkt_ts=83850482
[debug] roc_audio: depacketizer: dropping late packet: ts=83853554 pkt_ts=83850791
[debug] roc_audio: depacketizer: dropping late packet: ts=83853554 pkt_ts=83851100
[debug] roc_audio: depacketizer: dropping late packet: ts=83853554 pkt_ts=83851409
[debug] roc_audio: depacketizer: dropping late packet: ts=83853554 pkt_ts=83851718
[debug] roc_audio: depacketizer: dropping late packet: ts=83853554 pkt_ts=83852027
[debug] roc_audio: depacketizer: dropping late packet: ts=83853554 pkt_ts=83852336
[debug] roc_audio: depacketizer: dropping late packet: ts=83853554 pkt_ts=83852645
[debug] roc_audio: depacketizer: dropping late packet: ts=83853554 pkt_ts=83852954
[debug] roc_audio: depacketizer: fetched=1 dropped=27
[debug] roc_audio: watchdog: drops timeout reached: every window had drops during timeout: curr_read_pos=88320 last_pos_before_drops=0 drop_detection_window=13230 max_drops_duration=88200
[debug] roc_audio: watchdog: status: bbBbD...........
[info] roc_pipeline: receiver: removing session
[info] roc_pipeline: receiver: creating session
[debug] roc_packet: delayed reader: initializing: delay=8820
[debug] roc_fec: of decoder: initializing Reed-Solomon decoder
[debug] roc_audio: watchdog: initializing: max_blank_duration=88200 max_drops_duration=88200 drop_detection_window=13230
[debug] roc_audio: resampler: initializing: window_interp=128 window_size=32 frame_size=640 channels_num=2
[debug] roc_audio: resampler reader: initializing window
[debug] roc_audio: latency monitor: initializing: target_latency=8820 in_rate=44100 out_rate=44100
[debug] roc_packet: router: detected new stream: source=475195216 flags=0x8u
[debug] roc_packet: router: detected new stream: source=0 flags=0x10u
[debug] roc_packet: delayed reader: initial queue: delay=8820 queue=19776 packets=64
[debug] roc_packet: delayed reader: trimmed queue: delay=8820 queue=8961 packets=29
[debug] roc_fec: fec reader: repair queue: dropped=20
[debug] roc_audio: depacketizer: got first packet: zero_samples=0
[debug] roc_audio: depacketizer: ts=83875213 loss_ratio=0.00000
[debug] roc_audio: latency monitor: latency=8310 target=8820 fe=1.00000 trim_fe=1.00000 adj_fe=1.00000
[debug] roc_fec: fec reader: repair queue: dropped=10
[debug] roc_fec: fec reader: got first packet in a block, start decoding: n_packets_before=10 sn=12779 sbn=5099
...