mikebrady
commented
1 year ago Thanks for the post. It might be worth checking that power management if definitely off on Wi-Fi. See the TROUBLESHOOTING guide for a bit more information.
Closed Simon-Says-eng closed 1 year ago
mikebrady
commented
1 year ago Thanks for the post. It might be worth checking that power management if definitely off on Wi-Fi. See the TROUBLESHOOTING guide for a bit more information.
Simon-Says-eng
commented
1 year ago Thanks for the post. It might be worth checking that power management if definitely off on Wi-Fi. See the TROUBLESHOOTING guide for a bit more information.
The device has no built in functionality for wifi. It is cabled direct to the Router. I cannot find a power management setting for cabled connection. Do you think the network is the problem?
mikebrady
commented
1 year ago Thanks. It’s often a problem alright. Given that the DAC is starved of audio it seems like a possibility. Another possibility is that the device is bogging down due to having to do lots of interpolation. If you set it to “basic” it will use the low-power version rather than using “soxr”. If you enable statistics you might get a little more information. [Edit] Spelling!
Simon-Says-eng
commented
1 year ago I have set the interpolation to basic, but it didn't make any difference in the processor load. During normal playback, it only utilizes around 10% of a single core out of the available four. I have been unable to identify the problem using the statistics option. Below, you'll find the logs from my latest attempt.
0.004521139 "shairport.c:1729" Started!
0.000263445 "shairport.c:1756" software version: "3.3.8-libdaemon-OpenSSL-Avahi-ALSA-jack-pa-dummy-stdout-pipe-soxr-convolution-metadata-mqtt-dbus-mpris-sysconfdir:/etc"
0.000088245 "shairport.c:1762" log verbosity is 1.
0.000180574 "audio_alsa.c:1015" alsa: alsa_maximum_stall_time of 0.200000 sec.
0.000163367 "audio_alsa.c:1299" alsa: disable_standby_mode is "never".
0.000068079 "audio_alsa.c:1303" alsa: disable_standby_mode_silence_threshold is 0.040000 seconds.
0.000066330 "audio_alsa.c:1305" alsa: disable_standby_mode_silence_scan_interval is 0.004000 seconds.
0.000148159 "audio_alsa.c:1345" alsa: output device name is "default".
0.000588761 "shairport.c:1810" disable resend requests is off.
0.000129785 "shairport.c:1811" diagnostic_drop_packet_fraction is 0.000000. A value of 0.0 means no packets will be dropped deliberately.
0.000078413 "shairport.c:1815" statistics_requester status is 1.
0.000059580 "shairport.c:1817" daemon status is 0.
0.000064205 "shairport.c:1818" daemon pid file path is "/run/shairport-sync/shairport-sync.pid".
0.000059372 "shairport.c:1820" rtsp listening port is 5000.
0.000057955 "shairport.c:1821" udp base port is 6001.
0.000056414 "shairport.c:1822" udp port range is 10.
0.000055164 "shairport.c:1823" player name is "Nanopineo".
0.000056497 "shairport.c:1824" backend is "alsa".
0.000054705 "shairport.c:1825" run_this_before_play_begins action is "(null)".
0.000051623 "shairport.c:1826" run_this_after_play_ends action is "(null)".
0.000076204 "shairport.c:1827" wait-cmd status is 0.
0.000108078 "shairport.c:1828" run_this_before_play_begins may return output is 0.
0.000066496 "shairport.c:1829" run_this_if_an_unfixable_error_is_detected action is "(null)".
0.000062122 "shairport.c:1830" run_this_before_entering_active_state action is "(null)".
0.000058830 "shairport.c:1831" run_this_after_exiting_active_state action is "(null)".
0.000059664 "shairport.c:1832" active_state_timeout is 10.000000 seconds.
0.000072288 "shairport.c:1833" mdns backend "(null)".
0.000057288 "shairport.c:1835" interpolation setting is "basic".
0.000057747 "shairport.c:1838" interpolation soxr_delay_threshold is 30.
0.000057747 "shairport.c:1839" resync time is 0.050000 seconds.
0.000061997 "shairport.c:1840" allow a session to be interrupted: 0.
0.000056789 "shairport.c:1841" busy timeout time is 120.
0.000056705 "shairport.c:1842" drift tolerance is 0.001995 seconds.
0.000061247 "shairport.c:1843" password is "(null)".
0.000054456 "shairport.c:1844" ignore_volume_control is 0.
0.000057205 "shairport.c:1848" volume_max_db is not set
0.000054414 "shairport.c:1849" volume range in dB (zero means use the range specified by the mixer): 0.
0.000059705 "shairport.c:1851" volume_range_combined_hardware_priority (1 means hardware mixer attenuation is used first) is 0.
0.000061372 "shairport.c:1855" playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
0.000061163 "shairport.c:1857" disable_synchronization is 0.
0.000055872 "shairport.c:1858" use_mmap_if_available is 1.
0.000056789 "shairport.c:1859" output_format automatic selection is enabled.
0.000058289 "shairport.c:1863" output_rate automatic selection is enabled.
0.000060413 "shairport.c:1867" audio backend desired buffer length is 0.200000 seconds.
0.000062914 "shairport.c:1869" audio_backend_buffer_interpolation_threshold_in_seconds is 0.120000 seconds.
0.000065330 "shairport.c:1871" audio backend latency offset is 0.000000 seconds.
0.000062246 "shairport.c:1873" audio backend silence lead-in time is "auto".
0.000056164 "shairport.c:1877" zeroconf regtype is "_raop._tcp".
0.000057955 "shairport.c:1878" decoders_supported field is 1.
0.000056581 "shairport.c:1879" use_apple_decoder is 0.
0.000055789 "shairport.c:1880" alsa_use_hardware_mute is 0.
0.000055205 "shairport.c:1884" no special mdns service interface was requested.
0.000405687 "shairport.c:1887" configuration file name "/etc/shairport-sync.conf" resolves to "/etc/shairport-sync.conf".
0.000092287 "shairport.c:1894" metadata enabled is 1.
0.000060080 "shairport.c:1895" metadata pipename is "/tmp/shairport-sync-metadata".
0.000191365 "shairport.c:1896" metadata socket address is "(null)" port 0.
0.000071122 "shairport.c:1898" metadata socket packet size is "500".
0.000059413 "shairport.c:1899" get-coverart is 1.
0.000056414 "shairport.c:1902" mqtt is disabled.
0.000055247 "shairport.c:1903" mqtt hostname is (null), port is 1883.
0.000059414 "shairport.c:1904" mqtt topic is /Nanopineo.
0.000097203 "shairport.c:1905" mqtt will not publish raw metadata.
0.000065955 "shairport.c:1906" mqtt will not publish parsed metadata.
0.000174032 "shairport.c:1907" mqtt will not publish cover Art.
0.000067997 "shairport.c:1908" mqtt remote control is disabled.
0.000060080 "shairport.c:1912" convolution is 0.
0.000057164 "shairport.c:1913" convolution IR file is "(null)"
0.000057455 "shairport.c:1914" convolution max length 8192
0.000056289 "shairport.c:1915" convolution gain is 0.000000
0.000059455 "shairport.c:1917" loudness is 0.
0.000054497 "shairport.c:1918" loudness reference level is -20.000000
0.000587636 "rtsp.c:1665" metadata pipe name is "/tmp/shairport-sync-metadata".
0.038582117 "mpris-service.c:341" MPRIS service started at "org.mpris.MediaPlayer2.ShairportSync" on the system bus.
0.005267309 "dbus-service.c:548" >> setting loudness threshold to -20.000000.
0.000293443 "dbus-service.c:561" >> setting drift tolerance to 0.001995 seconds
0.000344523 "dbus-service.c:909" >> ALACDecoder set to "hammerton"
0.000275903 "dbus-service.c:914" >> Active set to "false"
0.000317567 "dbus-service.c:919" >> disable standby mode set to "off"
0.000364022 "dbus-service.c:937" >> interpolation set to "basic" (soxr support built in)
0.000261945 "dbus-service.c:456" >> deactivating disable standby
0.000320483 "dbus-service.c:538" >> deactivating loudness
0.000340899 "dbus-service.c:472" >> deactivating convolution
0.000687256 "dbus-service.c:441" >> log verbosity set to 1.
0.000243946 "dbus-service.c:425" >> start logging statistics
0.000284110 "dbus-service.c:390" >> stop including elapsed time in logs
0.000715588 "dbus-service.c:400" >> start including delta time in logs
0.000593052 "dbus-service.c:413" >> start including file and line in logs
0.001309140 "dbus-service.c:1045" Shairport Sync native D-Bus service started at "org.gnome.ShairportSync" on the system bus.
0.008254237 "mdns_avahi.c:375" avahi_dacp_monitor_start Avahi DACP monitor successfully started
18.898855082 "rtsp.c:1057" Connection 2: SETUP DACP-ID "56D51E2E14CC5350" from 2a02:8070:d286:97c0:1d05:c75d:c0d9:2132 to 2a02:8070:d286:97c0:68e5:e5:6bf0:7f85 with UDP ports Control: 6001, Timing: 6002 and Audio: 6003.
0.014142555 "audio_alsa.c:528" alsa: output format chosen is "S32".
0.000361023 "audio_alsa.c:569" alsa: output speed chosen is 44100.
0.008113077 "player.c:1937" sync error in milliseconds, net correction in ppm, corrections in ppm, total packets, missing packets, late packets, too late packets, resend requests, min DAC queue size, min buffer occupancy, max buffer occupancy, source nominal frames per second, source actual frames per second, output frames per second, source clock drift in ppm, source clock drift sample count, rough calculated correction in ppm
0.978016272 "player.c:1647" Playback Stopped. Total playing time 00:00:01. Input: 0.00 frames per second.
1.053842573 "rtsp.c:1057" Connection 3: SETUP DACP-ID "56D51E2E14CC5350" from 2a02:8070:d286:97c0:1d05:c75d:c0d9:2132 to 2a02:8070:d286:97c0:68e5:e5:6bf0:7f85 with UDP ports Control: 6001, Timing: 6002 and Audio: 6003.
0.007989584 "audio_alsa.c:528" alsa: output format chosen is "S32".
0.000827373 "audio_alsa.c:569" alsa: output speed chosen is 44100.
0.014021645 "player.c:1937" sync error in milliseconds, net correction in ppm, corrections in ppm, total packets, missing packets, late packets, too late packets, resend requests, min DAC queue size, min buffer occupancy, max buffer occupancy, source nominal frames per second, source actual frames per second, output frames per second, source clock drift in ppm, source clock drift sample count, rough calculated correction in ppm
9.817684307 "player.c:2744" -0.14, 0.0, 0.0, 1003, 0, 0, 0, 0, 8524, 204, 227, 44100.05, 44367.34, 44100.26, 0.00, 0, 4.60
8.006239483 "player.c:2744" -0.55, 0.0, 0.0, 2006, 0, 0, 0, 0, 8492, 222, 227, 44099.99, 44219.53, 44101.83, 0.00, 0, 41.64
8.008195964 "player.c:2744" -0.97, 0.0, 0.0, 3009, 0, 0, 0, 0, 8444, 222, 227, 44100.02, 44153.82, 44102.19, 0.00, 0, 49.31
8.004565736 "player.c:2744" -1.39, 0.0, 0.0, 4012, 0, 0, 0, 0, 8444, 222, 227, 44099.99, 44144.85, 44101.89, 0.00, 0, 43.11
8.009199620 "player.c:2744" -1.83, 39.7, 39.7, 5015, 0, 0, 0, 0, 8418, 221, 227, 44100.00, 44130.50, 44102.11, 0.00, 0, 47.74
8.004513490 "player.c:2744" -1.93, 51.0, 51.0, 6018, 0, 0, 0, 0, 8410, 222, 227, 44100.00, 44129.04, 44102.14, 0.00, 1, 48.55
8.004209632 "player.c:2744" -1.95, 25.5, 25.5, 7021, 0, 0, 0, 0, 8418, 222, 227, 44099.99, 44132.16, 44102.06, 0.00, 1, 46.87
8.004531294 "player.c:2744" -1.96, 53.8, 53.8, 8024, 0, 0, 0, 0, 8415, 221, 227, 44100.01, 44124.80, 44102.12, 0.00, 1, 47.88
8.008413885 "player.c:2744" -2.07, 141.6, 141.6, 9027, 0, 0, 0, 0, 8414, 222, 227, 44100.00, 44115.14, 44102.30, 0.00, 2, 52.12
8.004027028 "player.c:2744" -2.01, 51.0, 51.0, 10030, 0, 0, 0, 0, 8411, 222, 227, 44100.00, 44115.56, 44102.14, 0.00, 2, 48.70
8.005646362 "player.c:2744" -1.98, 56.6, 56.6, 11033, 0, 0, 0, 0, 8406, 222, 227, 44100.00, 44115.63, 44102.14, 0.00, 2, 48.45
8.007203406 "player.c:2744" -1.97, 51.0, 51.0, 12036, 0, 0, 0, 0, 8431, 221, 227, 44100.00, 44113.30, 44102.26, 0.00, 2, 51.31
8.005137971 "player.c:2744" -1.93, 53.8, 53.8, 13039, 0, 0, 0, 0, 8411, 222, 227, 44100.00, 44113.70, 44102.22, 0.00, 2, 50.45
8.003989488 "player.c:2744" -1.98, 39.7, 39.7, 14042, 0, 0, 0, 0, 8449, 222, 227, 44100.00, 44109.63, 44102.30, 0.00, 2, 52.02
8.009926741 "player.c:2744" -1.97, 62.3, 62.3, 15045, 0, 0, 0, 0, 8423, 221, 227, 44100.00, 44110.51, 44102.29, 0.00, 2, 52.07
8.003686852 "player.c:2744" -1.97, 51.0, 51.0, 16048, 0, 0, 0, 0, 8432, 222, 227, 44100.00, 44111.42, 44102.23, 0.00, 2, 50.61
8.004699842 "player.c:2744" -1.99, 48.2, 48.2, 17051, 0, 0, 0, 0, 8415, 222, 227, 44100.00, 44109.25, 44102.25, 0.00, 2, 51.00
8.005046240 "player.c:2744" -1.77, 8.5, 19.8, 18054, 0, 0, 0, 0, 8448, 222, 227, 44100.00, 44109.79, 44102.29, 0.00, 4, 51.93
8.007771059 "player.c:2744" -1.97, 59.5, 59.5, 19057, 0, 0, 0, 0, 8423, 221, 227, 44100.00, 44108.37, 44102.21, 0.00, 5, 50.14
8.006094686 "player.c:2744" -1.98, 82.1, 82.1, 20060, 0, 0, 0, 0, 8407, 222, 227, 44100.00, 44108.57, 44102.20, 0.00, 6, 49.88
3.671094187 "audio_alsa.c:1700" alsa: underrun while writing 352 samples to alsa device.
0.019281006 "audio_alsa.c:1700" alsa: underrun while writing 353 samples to alsa device.
0.014891024 "audio_alsa.c:1726" alsa: device status returns fault status -32 and SND_PCM_STATE_* 3 for play.
0.005797493 "audio_alsa.c:1700" alsa: underrun while writing 352 samples to alsa device.
0.013887367 "audio_alsa.c:1726" alsa: device status returns fault status -32 and SND_PCM_STATE_* 3 for play.
0.011110886 "audio_alsa.c:1700" alsa: underrun while writing 352 samples to alsa device.
0.014097315 "audio_alsa.c:1726" alsa: device status returns fault status -32 and SND_PCM_STATE_* 3 for play.
0.011063846 "audio_alsa.c:1700" alsa: underrun while writing 352 samples to alsa device.
0.023814022 "audio_alsa.c:1700" alsa: underrun while writing 353 samples to alsa device.
0.025597555 "audio_alsa.c:1700" alsa: underrun while writing 8626 samples to alsa device.
0.023003689 "audio_alsa.c:1700" alsa: underrun while writing 352 samples to alsa device.
0.063522392 "audio_alsa.c:1700" alsa: underrun while writing 352 samples to alsa device.
0.014621496 "audio_alsa.c:1700" alsa: underrun while writing 353 samples to alsa device.
4.091460306 "player.c:2744" -4.74, 549.5, 549.5, 21063, 0, 0, 0, 0, 0, 222, 227, 0.00, 39423.81, 44100.33, 0.00, 7,1000000.00
8.010659701 "player.c:2744" -1.77, 11.3, 11.3, 22066, 0, 0, 0, 0, 8443, 222, 227, 44100.06, 44068.57, 44101.74, 0.00, 7, 38.18
8.002835065 "player.c:2744" -1.95, 42.5, 48.2, 23069, 0, 0, 0, 0, 8411, 222, 227, 44100.03, 44095.26, 44102.42, 0.00, 7, 54.13
8.005041373 "player.c:2744" -1.99, 53.8, 53.8, 24072, 0, 0, 0, 0, 8447, 222, 227, 44100.02, 44089.02, 44102.20, 0.00, 7, 49.30
8.009269822 "player.c:2744" -1.96, 53.8, 53.8, 25075, 0, 0, 0, 0, 8438, 221, 227, 44100.01, 44096.64, 44102.36, 0.00, 7, 53.37
8.004713181 "player.c:2744" -1.95, 48.2, 48.2, 26078, 0, 0, 0, 0, 8414, 222, 227, 44100.01, 44100.76, 44102.15, 0.00, 7, 48.52
8.004582355 "player.c:2744" -1.97, 59.5, 59.5, 27081, 0, 0, 0, 0, 8420, 222, 227, 44100.00, 44097.19, 44102.28, 0.00, 7, 51.82
8.007578950 "player.c:2744" -1.97, 42.5, 42.5, 28084, 0, 0, 0, 0, 8397, 222, 227, 44100.00, 44082.70, 44102.29, 0.00, 7, 51.81
Thanks again. There is indeed no sign of the system bogging down, and those interpolation figures and error levels all look fine.
Okay, so the next thing to look at is the output device — you have selected left it at default. Could you identify the output device you want to output to and set the output device to it? The reason is that we don’t know what happens between the alsa default and the actual hardware. The alsa output devices will be listed at the end of the --help text.
Simon-Says-eng
commented
1 year ago Setting the output device keeps the error. I kept the log a little bit longer.
I also found in the configuration the option audio_backend_buffer_desired_length_in_seconds = 0.2; // If set too small, buffer underflow occurs on low-powered machines. but playing with this value does not improve the situation.
0.004576182 "shairport.c:1729" Started!
0.000258570 "shairport.c:1756" software version: "3.3.8-libdaemon-OpenSSL-Avahi-ALSA-jack-pa-dummy-stdout-pipe-soxr-convolution-metadata-mqtt-dbus-mpris-sysconfdir:/etc"
0.000082620 "shairport.c:1762" log verbosity is 1.
0.000175033 "audio_alsa.c:1015" alsa: alsa_maximum_stall_time of 0.200000 sec.
0.000178741 "audio_alsa.c:1299" alsa: disable_standby_mode is "never".
0.000064371 "audio_alsa.c:1303" alsa: disable_standby_mode_silence_threshold is 0.040000 seconds.
0.000067955 "audio_alsa.c:1305" alsa: disable_standby_mode_silence_scan_interval is 0.004000 seconds.
0.000151409 "audio_alsa.c:1345" alsa: output device name is "hw:I2Smaster".
0.000529890 "shairport.c:1810" disable resend requests is off.
0.000120160 "shairport.c:1811" diagnostic_drop_packet_fraction is 0.000000. A value of 0.0 means no packets will be dropped deliberately.
0.000076746 "shairport.c:1815" statistics_requester status is 1.
0.000061414 "shairport.c:1817" daemon status is 0.
0.000064705 "shairport.c:1818" daemon pid file path is "/run/shairport-sync/shairport-sync.pid".
0.000058747 "shairport.c:1820" rtsp listening port is 5000.
0.000056413 "shairport.c:1821" udp base port is 6001.
0.000056373 "shairport.c:1822" udp port range is 10.
0.000054455 "shairport.c:1823" player name is "Nanopineo".
0.000121202 "shairport.c:1824" backend is "alsa".
0.000064455 "shairport.c:1825" run_this_before_play_begins action is "(null)".
0.000058872 "shairport.c:1826" run_this_after_play_ends action is "(null)".
0.000057081 "shairport.c:1827" wait-cmd status is 0.
0.000055788 "shairport.c:1828" run_this_before_play_begins may return output is 0.
0.000053581 "shairport.c:1829" run_this_if_an_unfixable_error_is_detected action is "(null)".
0.000059955 "shairport.c:1830" run_this_before_entering_active_state action is "(null)".
0.000060705 "shairport.c:1831" run_this_after_exiting_active_state action is "(null)".
0.000059039 "shairport.c:1832" active_state_timeout is 10.000000 seconds.
0.000072288 "shairport.c:1833" mdns backend "(null)".
0.000055497 "shairport.c:1835" interpolation setting is "basic".
0.000056581 "shairport.c:1838" interpolation soxr_delay_threshold is 30.
0.000056830 "shairport.c:1839" resync time is 0.050000 seconds.
0.000061538 "shairport.c:1840" allow a session to be interrupted: 0.
0.000056789 "shairport.c:1841" busy timeout time is 120.
0.000055706 "shairport.c:1842" drift tolerance is 0.001995 seconds.
0.000060913 "shairport.c:1843" password is "(null)".
0.000053622 "shairport.c:1844" ignore_volume_control is 0.
0.000056956 "shairport.c:1848" volume_max_db is not set
0.000054914 "shairport.c:1849" volume range in dB (zero means use the range specified by the mixer): 0.
0.000060580 "shairport.c:1851" volume_range_combined_hardware_priority (1 means hardware mixer attenuation is used first) is 0.
0.000062413 "shairport.c:1855" playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
0.000061414 "shairport.c:1857" disable_synchronization is 0.
0.000055955 "shairport.c:1858" use_mmap_if_available is 1.
0.000056831 "shairport.c:1859" output_format automatic selection is enabled.
0.000057330 "shairport.c:1863" output_rate automatic selection is enabled.
0.000057456 "shairport.c:1867" audio backend desired buffer length is 0.200000 seconds.
0.000061455 "shairport.c:1869" audio_backend_buffer_interpolation_threshold_in_seconds is 0.120000 seconds.
0.000066996 "shairport.c:1871" audio backend latency offset is 0.000000 seconds.
0.000062122 "shairport.c:1873" audio backend silence lead-in time is "auto".
0.000058539 "shairport.c:1877" zeroconf regtype is "_raop._tcp".
0.000056997 "shairport.c:1878" decoders_supported field is 1.
0.000056705 "shairport.c:1879" use_apple_decoder is 0.
0.000056497 "shairport.c:1880" alsa_use_hardware_mute is 0.
0.000058164 "shairport.c:1884" no special mdns service interface was requested.
0.000129077 "shairport.c:1887" configuration file name "/etc/shairport-sync.conf" resolves to "/etc/shairport-sync.conf".
0.000073204 "shairport.c:1894" metadata enabled is 1.
0.000057289 "shairport.c:1895" metadata pipename is "/tmp/shairport-sync-metadata".
0.000058205 "shairport.c:1896" metadata socket address is "(null)" port 0.
0.000060122 "shairport.c:1898" metadata socket packet size is "500".
0.000056872 "shairport.c:1899" get-coverart is 1.
0.000055122 "shairport.c:1902" mqtt is disabled.
0.000054831 "shairport.c:1903" mqtt hostname is (null), port is 1883.
0.000058289 "shairport.c:1904" mqtt topic is /Nanopineo.
0.000055663 "shairport.c:1905" mqtt will not publish raw metadata.
0.000056914 "shairport.c:1906" mqtt will not publish parsed metadata.
0.000058789 "shairport.c:1907" mqtt will not publish cover Art.
0.000057164 "shairport.c:1908" mqtt remote control is disabled.
0.000056872 "shairport.c:1912" convolution is 0.
0.000056538 "shairport.c:1913" convolution IR file is "(null)"
0.000055873 "shairport.c:1914" convolution max length 8192
0.000057247 "shairport.c:1915" convolution gain is 0.000000
0.000058913 "shairport.c:1917" loudness is 0.
0.000054997 "shairport.c:1918" loudness reference level is -20.000000
0.000555847 "rtsp.c:1665" metadata pipe name is "/tmp/shairport-sync-metadata".
0.037281291 "mpris-service.c:341" MPRIS service started at "org.mpris.MediaPlayer2.ShairportSync" on the system bus.
0.005065740 "dbus-service.c:548" >> setting loudness threshold to -20.000000.
0.000306276 "dbus-service.c:561" >> setting drift tolerance to 0.001995 seconds
0.000188740 "dbus-service.c:909" >> ALACDecoder set to "hammerton"
0.000136035 "dbus-service.c:914" >> Active set to "false"
0.000241737 "dbus-service.c:919" >> disable standby mode set to "off"
0.000163534 "dbus-service.c:937" >> interpolation set to "basic" (soxr support built in)
0.000194990 "dbus-service.c:456" >> deactivating disable standby
0.000130410 "dbus-service.c:538" >> deactivating loudness
0.000116535 "dbus-service.c:472" >> deactivating convolution
0.000331900 "dbus-service.c:441" >> log verbosity set to 1.
0.000230905 "dbus-service.c:425" >> start logging statistics
0.000141159 "dbus-service.c:390" >> stop including elapsed time in logs
0.000144659 "dbus-service.c:400" >> start including delta time in logs
0.000134035 "dbus-service.c:413" >> start including file and line in logs
0.000328233 "dbus-service.c:1045" Shairport Sync native D-Bus service started at "org.gnome.ShairportSync" on the system bus.
0.013625466 "mdns_avahi.c:375" avahi_dacp_monitor_start Avahi DACP monitor successfully started
5.691445936 "rtsp.c:1057" Connection 2: SETUP DACP-ID "B78C9B05B458E0C8" from 2a02:8070:d286:97c0:1d05:c75d:c0d9:2132 to 2a02:8070:d286:97c0:68e5:e5:6bf0:7f85 with UDP ports Control: 6001, Timing: 6002 and Audio: 6003.
0.009284064 "audio_alsa.c:528" alsa: output format chosen is "S24".
0.000160492 "audio_alsa.c:569" alsa: output speed chosen is 44100.
0.007705646 "player.c:1937" sync error in milliseconds, net correction in ppm, corrections in ppm, total packets, missing packets, late packets, too late packets, resend requests, min DAC queue size, min buffer occupancy, max buffer occupancy, source nominal frames per second, source actual frames per second, output frames per second, source clock drift in ppm, source clock drift sample count, rough calculated correction in ppm
9.829180833 "player.c:2744" -0.29, 0.0, 0.0, 1003, 0, 0, 0, 0, 8246, 196, 227, 44100.11, 44267.38, 44100.93, 0.00, 0, 18.65
8.003904757 "player.c:2744" -0.70, 0.0, 0.0, 2006, 0, 0, 0, 0, 7720, 183, 227, 44100.00, 44131.77, 44102.34, 0.00, 0, 53.12
8.002660154 "player.c:2744" -0.63, 0.0, 0.0, 3009, 0, 0, 0, 0, 8328, 203, 227, 44100.02, 44130.21, 44102.14, 0.00, 0, 48.24
8.005758536 "player.c:2744" -0.89, 0.0, 0.0, 4012, 0, 0, 0, 0, 8453, 221, 227, 44100.03, 44126.29, 44102.30, 0.00, 0, 51.66
8.010004402 "player.c:2744" -1.30, 0.0, 0.0, 5015, 0, 0, 0, 0, 8448, 222, 227, 44100.02, 44114.98, 44102.35, 0.00, 0, 52.85
8.002411209 "player.c:2744" -1.72, 2.8, 2.8, 6018, 0, 0, 0, 0, 8408, 222, 227, 44100.02, 44115.37, 44102.27, 0.00, 0, 51.17
8.005116861 "player.c:2744" -1.96, 45.3, 45.3, 7021, 0, 0, 0, 0, 8434, 221, 227, 44100.00, 44109.13, 44102.31, 0.00, 0, 52.47
8.010578038 "player.c:2744" -1.98, 48.2, 48.2, 8024, 0, 0, 0, 0, 8412, 221, 227, 44100.01, 44110.04, 44102.15, 0.00, 0, 48.48
8.002643155 "player.c:2744" -1.96, 56.6, 56.6, 9027, 0, 0, 0, 0, 8447, 221, 227, 44100.01, 44106.97, 44102.29, 0.00, 0, 51.85
8.004722382 "player.c:2744" -1.94, 51.0, 51.0, 10030, 0, 0, 0, 0, 8417, 222, 227, 44100.00, 44108.22, 44102.14, 0.00, 0, 48.41
8.010230098 "player.c:2744" -2.01, 76.5, 76.5, 11033, 0, 0, 0, 0, 8400, 222, 227, 44100.00, 44109.16, 44102.27, 0.00, 1, 51.43
8.004208533 "player.c:2744" -1.96, 53.8, 53.8, 12036, 0, 0, 0, 0, 8400, 221, 227, 44100.01, 44106.40, 44102.16, 0.00, 1, 48.82
8.005474968 "player.c:2744" -2.00, 56.6, 56.6, 13039, 0, 0, 0, 0, 8417, 222, 227, 44100.01, 44107.23, 44102.31, 0.00, 1, 52.34
8.002920766 "player.c:2744" -1.95, 45.3, 45.3, 14042, 0, 0, 0, 0, 8409, 222, 227, 44100.01, 44104.43, 44102.19, 0.00, 1, 49.53
8.008763132 "player.c:2744" -1.96, 59.5, 59.5, 15045, 0, 0, 0, 0, 8421, 222, 227, 44100.00, 44105.94, 44102.30, 0.00, 1, 52.04
8.004713590 "player.c:2744" -1.99, 82.1, 82.1, 16048, 0, 0, 0, 0, 8395, 222, 227, 44100.01, 44106.59, 44102.23, 0.00, 2, 50.37
8.004643385 "player.c:2744" -1.98, 53.8, 53.8, 17051, 0, 0, 0, 0, 8422, 222, 227, 44100.01, 44104.88, 44102.18, 0.00, 3, 49.24
8.009478720 "player.c:2744" -1.96, 45.3, 45.3, 18054, 0, 0, 0, 0, 8406, 222, 227, 44100.01, 44105.71, 44102.30, 0.00, 4, 52.02
2.849551334 "audio_alsa.c:1700" alsa: underrun while writing 352 samples to alsa device.
0.033459571 "audio_alsa.c:1700" alsa: underrun while writing 8628 samples to alsa device.
0.062140014 "audio_alsa.c:1700" alsa: underrun while writing 352 samples to alsa device.
0.024305292 "audio_alsa.c:1700" alsa: underrun while writing 353 samples to alsa device.
0.014407926 "audio_alsa.c:1700" alsa: underrun while writing 8678 samples to alsa device.
0.015667528 "audio_alsa.c:1700" alsa: underrun while writing 352 samples to alsa device.
0.017860373 "audio_alsa.c:1700" alsa: underrun while writing 352 samples to alsa device.
0.023085355 "audio_alsa.c:1700" alsa: underrun while writing 352 samples to alsa device.
0.014610374 "audio_alsa.c:1700" alsa: underrun while writing 352 samples to alsa device.
0.017608470 "audio_alsa.c:1700" alsa: underrun while writing 353 samples to alsa device.
0.013800624 "audio_alsa.c:1700" alsa: underrun while writing 8729 samples to alsa device.
0.017270278 "audio_alsa.c:1700" alsa: underrun while writing 352 samples to alsa device.
0.016472237 "audio_alsa.c:1700" alsa: underrun while writing 352 samples to alsa device.
0.023128811 "audio_alsa.c:1700" alsa: underrun while writing 352 samples to alsa device.
0.017235780 "audio_alsa.c:1700" alsa: underrun while writing 352 samples to alsa device.
0.014238102 "audio_alsa.c:1700" alsa: underrun while writing 353 samples to alsa device.
0.018948150 "audio_alsa.c:1700" alsa: underrun while writing 8617 samples to alsa device.
0.014590625 "audio_alsa.c:1700" alsa: underrun while writing 352 samples to alsa device.
0.030905245 "audio_alsa.c:1700" alsa: underrun while writing 352 samples to alsa device.
0.017791918 "audio_alsa.c:1700" alsa: underrun while writing 352 samples to alsa device.
0.023039066 "audio_alsa.c:1700" alsa: underrun while writing 353 samples to alsa device.
0.015077975 "audio_alsa.c:1700" alsa: underrun while writing 8714 samples to alsa device.
0.017095579 "audio_alsa.c:1700" alsa: underrun while writing 352 samples to alsa device.
0.016136837 "audio_alsa.c:1700" alsa: underrun while writing 352 samples to alsa device.
0.030678923 "audio_alsa.c:1700" alsa: underrun while writing 352 samples to alsa device.
0.017251696 "audio_alsa.c:1700" alsa: underrun while writing 353 samples to alsa device.
4.628924395 "player.c:2744" -7.53, 846.9, 846.9, 19057, 0, 0, 0, 0, 0, 222, 227, 44100.02, 43568.25, 44099.22, 0.00, 5, -18.13
8.002751066 "player.c:2744" -1.98, 59.5, 59.5, 20060, 0, 0, 0, 0, 8409, 222, 227, 44100.02, 44084.94, 44102.07, 0.00, 6, 46.58
8.009331312 "player.c:2744" -1.95, 42.5, 42.5, 21063, 0, 0, 0, 0, 8426, 221, 227, 44100.00, 44018.20, 44102.48, 0.00, 6, 56.26
8.004259072 "player.c:2744" -2.02, 70.8, 70.8, 22066, 0, 0, 0, 0, 8413, 221, 227, 44099.98, 44090.20, 44102.32, 0.00, 7, 53.17
8.004919121 "player.c:2744" -1.94, 51.0, 51.0, 23069, 0, 0, 0, 0, 8419, 222, 227, 44099.99, 44096.16, 44102.51, 0.00, 8, 57.23
8.005489092 "player.c:2744" -1.94, 31.2, 31.2, 24072, 0, 0, 0, 0, 8413, 222, 227, 44099.98, 44092.35, 44102.40, 0.00, 8, 54.69
8.006987969 "player.c:2744" -1.95, 51.0, 51.0, 25075, 0, 0, 0, 0, 8391, 222, 227, 44100.00, 44098.59, 44102.38, 0.00, 8, 54.06
8.006682795 "player.c:2744" -1.99, 53.8, 53.8, 26078, 0, 0, 0, 0, 8414, 221, 227, 44100.00, 44100.33, 44102.41, 0.00, 8, 54.69
8.003925688 "player.c:2744" -1.97, 48.2, 48.2, 27081, 0, 0, 0, 0, 8415, 221, 227, 44099.99, 44097.57, 44102.27, 0.00, 8, 51.71
8.007989687 "player.c:2744" -1.98, 85.0, 85.0, 28084, 0, 0, 0, 0, 8432, 222, 227, 44099.99, 44081.54, 44102.36, -0.25, 9, 54.01
8.004620776 "player.c:2744" -1.95, 53.8, 53.8, 29087, 0, 0, 0, 0, 8403, 222, 227, 44100.00, 44097.06, 44102.32, -1.82, 10, 54.64
1.741363760 "audio_alsa.c:1700" alsa: underrun while writing 352 samples to alsa device.
0.024233462 "audio_alsa.c:1700" alsa: underrun while writing 353 samples to alsa device.
4.413603284 "audio_alsa.c:1700" alsa: underrun while writing 352 samples to alsa device.
0.033385283 "audio_alsa.c:1700" alsa: underrun while writing 8659 samples to alsa device.
0.022016076 "audio_alsa.c:1700" alsa: underrun while writing 352 samples to alsa device.
0.017274362 "audio_alsa.c:1700" alsa: underrun while writing 352 samples to alsa device.
0.023522666 "audio_alsa.c:1700" alsa: underrun while writing 352 samples to alsa device.
0.023325134 "audio_alsa.c:1700" alsa: underrun while writing 353 samples to alsa device.
0.014488588 "audio_alsa.c:1700" alsa: underrun while writing 8727 samples to alsa device.
0.017128203 "audio_alsa.c:1700" alsa: underrun while writing 352 samples to alsa device.
0.016981710 "audio_alsa.c:1700" alsa: underrun while writing 352 samples to alsa device.
0.023868148 "audio_alsa.c:1700" alsa: underrun while writing 352 samples to alsa device.
0.023049232 "audio_alsa.c:1700" alsa: underrun while writing 353 samples to alsa device.
0.026337729 "audio_alsa.c:1700" alsa: underrun while writing 8597 samples to alsa device.
0.046723931 "audio_alsa.c:1700" alsa: underrun while writing 352 samples to alsa device.
0.030288484 "audio_alsa.c:1700" alsa: underrun while writing 353 samples to alsa device.
0.019089227 "audio_alsa.c:1700" alsa: underrun while writing 353 samples to alsa device.
1.488716583 "player.c:2744" -6.71, 1008.3, 1008.3, 30090, 0, 0, 0, 0, 0, 222, 227, 44099.57, 0.00, 0.00, -1.82, 10, 0.00Thanks again. So, I wonder if it would be possible to temporarily switch out the DAC for a USB DAC, if you have one lying about, to see if the problem is somehow associated with the DAC?
Simon-Says-eng
commented
1 year ago Good idea. I borrowed today a little ugreen USB DAC. It worked better but not perfect. It seems a little bit as it is the "Sync Error ms". I have also built it from sources. But the error is the same as with the apt version.
shairport-sync -v
0.003004584 "shairport.c:2248" Startup in AirPlay 2 mode, with features 0x405c4a00,0x1c340 on device "46:8d:93:2a:a1:69".
0.000167875 "shairport.c:2287" Version String: "4.2-1-g12ad72c4-AirPlay2-smi9-OpenSSL-Avahi-ALSA-soxr-sysconfdir:/etc"
0.000049208 "shairport.c:2306" Command Line: "shairport-sync -v".
0.000608083 "shairport.c:2342" Log Verbosity is 1.
0.000116167 "audio_alsa.c:1020" alsa: alsa_maximum_stall_time of 0.200000 sec.
0.000079333 "audio_alsa.c:1309" alsa: disable_standby_mode is "never".
0.000026667 "audio_alsa.c:1313" alsa: disable_standby_mode_silence_threshold is 0.040000 seconds.
0.000022500 "audio_alsa.c:1315" alsa: disable_standby_mode_silence_scan_interval is 0.004000 seconds.
0.000061000 "audio_alsa.c:1355" alsa: output device name is "hw:Device".
0.000385417 "shairport.c:2390" disable_resend_requests is off.
0.000063958 "shairport.c:2391" diagnostic_drop_packet_fraction is 0.000000. A value of 0.0 means no packets will be dropped deliberately.
0.000035833 "shairport.c:2395" statistics_requester status is 1.
0.000023125 "shairport.c:2400" rtsp listening port is 7000.
0.000020167 "shairport.c:2401" udp base port is 6001.
0.000019375 "shairport.c:2402" udp port range is 10.
0.000020833 "shairport.c:2403" player name is "Nanopineo".
0.000020167 "shairport.c:2404" backend is "alsa".
0.000018958 "shairport.c:2405" run_this_before_play_begins action is "(null)".
0.000020250 "shairport.c:2406" run_this_after_play_ends action is "(null)".
0.000019125 "shairport.c:2407" wait-cmd status is 0.
0.000018875 "shairport.c:2408" run_this_before_play_begins may return output is 0.
0.000019500 "shairport.c:2409" run_this_if_an_unfixable_error_is_detected action is "(null)".
0.000020500 "shairport.c:2411" run_this_before_entering_active_state action is "(null)".
0.000019875 "shairport.c:2413" run_this_after_exiting_active_state action is "(null)".
0.000019584 "shairport.c:2415" active_state_timeout is 10.000000 seconds.
0.000027666 "shairport.c:2416" mdns backend "(null)".
0.000020000 "shairport.c:2418" interpolation setting is "basic".
0.000020542 "shairport.c:2422" interpolation soxr_delay_threshold is 30000000.
0.000019833 "shairport.c:2423" resync time is 0.050000 seconds.
0.000020125 "shairport.c:2424" resync recovery time is 0.100000 seconds.
0.000021042 "shairport.c:2425" allow a session to be interrupted: 0.
0.000018458 "shairport.c:2426" busy timeout time is 0.
0.000018709 "shairport.c:2427" drift tolerance is 0.002000 seconds.
0.000021416 "shairport.c:2428" password is "(null)".
0.000018500 "shairport.c:2429" default airplay volume is: -24.000000.
0.000024542 "shairport.c:2430" high threshold airplay volume is: -16.000000.
0.000023083 "shairport.c:2432" check for higher-than-threshold volume for new play session is disabled.
0.000020709 "shairport.c:2438" ignore_volume_control is 0.
0.000019583 "shairport.c:2442" volume_max_db is not set
0.000018250 "shairport.c:2443" volume range in dB (zero means use the range specified by the mixer): 0.
0.000020625 "shairport.c:2445" volume_range_combined_hardware_priority (1 means hardware mixer attenuation is used first) is 0.
0.000021833 "shairport.c:2449" playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
0.000020750 "shairport.c:2451" disable_synchronization is 0.
0.000018709 "shairport.c:2452" use_mmap_if_available is 1.
0.000018875 "shairport.c:2453" output_format automatic selection is enabled.
0.000018916 "shairport.c:2457" output_rate automatic selection is enabled.
0.000018750 "shairport.c:2461" audio backend desired buffer length is 0.200000 seconds.
0.000021834 "shairport.c:2463" audio_backend_buffer_interpolation_threshold_in_seconds is 0.120000 seconds.
0.000021708 "shairport.c:2465" audio backend latency offset is 0.000000 seconds.
0.000020500 "shairport.c:2467" audio backend silence lead-in time is "auto".
0.000019208 "shairport.c:2471" zeroconf regtype is "_raop._tcp".
0.000019834 "shairport.c:2472" decoders_supported field is 1.
0.000019833 "shairport.c:2473" use_apple_decoder is 0.
0.000019292 "shairport.c:2474" alsa_use_hardware_mute is 0.
0.000018916 "shairport.c:2478" no special mdns service interface was requested.
0.000063917 "shairport.c:2481" configuration file name "/etc/shairport-sync.conf" resolves to "/etc/shairport-sync.conf".
0.000027583 "shairport.c:2511" loudness is 0.
0.000018625 "shairport.c:2512" loudness reference level is -20.000000
0.005825417 "shairport.c:2610" NQPTP is online.
20.762538176 "rtsp.c:2914" Connection 1: AP2 PTP connection from 2a02:8070:d286:97c0:dd20:314c:5909:37ae:50330 ("iPhone von Bernd (2)") to self at 2a02:8070:d286:97c0:68e5:e5:6bf0:7f85:7000.
2.143272960 "rtsp.c:3330" Connection 1. AP2 Buffered Audio Stream.
0.827089000 "player.c:2813" Connection 1: Playback started at frame 3642001894 -- AirPlay 2 Buffered.
7.920650004 "player.c:2629" Sync Error ms | Net Sync PPM | All Sync PPM | Min DAC Queue | Min Buffers | Min Buffer Size | Output FPS (r) | Output FPS (c)
0.000153917 "player.c:2629" 1.28 -117.3 117.3 7361 46 275k N/A N/A
8.019612920 "player.c:2629" 0.12 -39.7 56.6 7341 46 3880k 44083.57 44085.87
8.003017796 "player.c:2629" -0.06 19.8 19.8 7294 46 3867k 44091.77 44094.07
8.024240003 "player.c:2629" -0.07 31.2 31.2 7327 46 3861k 44094.53 44096.83
7.998207296 "player.c:2629" -0.17 48.2 48.2 7321 46 3901k 44097.26 44099.58
7.985966670 "player.c:2629" -0.12 42.5 42.5 7322 46 3867k 44095.60 44097.93
8.025158129 "player.c:2629" -0.16 42.5 42.5 7315 46 3879k 44098.16 44100.49
8.010488546 "player.c:2629" -0.15 48.2 48.2 7323 46 3607k 44100.00 44102.33
7.993580170 "player.c:2629" -0.27 51.0 51.0 7288 46 3314k 44097.26 44099.59
8.018749796 "player.c:2629" -0.13 53.8 53.8 7317 46 3024k 44098.17 44100.51
7.993634837 "player.c:2629" -0.14 39.7 39.7 7326 46 2735k 44098.35 44100.69
8.005445670 "player.c:2629" -0.30 70.8 70.8 7333 46 2454k 44100.00 44102.34
8.000788004 "player.c:2629" -0.23 51.0 51.0 7315 46 2169k 44098.17 44100.50
8.002225254 "player.c:2629" -0.11 59.5 59.5 7312 46 1898k 44098.30 44100.64
8.022944420 "player.c:2629" -0.20 45.3 45.3 7333 46 1628k 44098.42 44100.76
8.010776379 "player.c:2629" -0.22 53.8 53.8 7314 46 1343k 44099.27 44101.60
8.007153629 "player.c:2629" -0.24 62.3 62.3 7318 46 1055k 44099.31 44101.65
7.988573171 "player.c:2629" -0.16 36.8 36.8 7314 46 771k 44099.36 44101.70
8.018201545 "player.c:2629" -0.19 62.3 62.3 7322 46 471k 44099.39 44101.73
7.988246129 "player.c:2629" -0.13 65.1 65.1 7319 46 168k 44099.71 44102.04
8.951260087 "player.c:2629" -0.22 31.2 31.2 7317 0 0 N/A N/A
7.998596213 "player.c:2629" -0.28 68.0 68.0 7315 46 3043k 44100.02 44102.34
8.015082920 "player.c:2629" -0.19 56.6 56.6 7266 46 3598k 44094.57 44096.89
8.007335962 "player.c:2629" -0.13 45.3 45.3 7325 46 3686k 44094.50 44096.82
8.018200212 "player.c:2629" -0.31 59.5 59.5 7320 46 3773k 44095.91 44098.23
8.008538171 "player.c:2629" -0.15 68.0 68.0 7317 46 3920k 44096.72 44099.04
7.996807879 "player.c:2629" -0.16 56.6 56.6 7318 46 3869k 44100.01 44102.32
7.992423420 "player.c:2629" -0.24 56.6 56.6 7307 46 3907k 44100.02 44102.33
7.999732962 "player.c:2629" -0.28 56.6 56.6 7316 46 3876k 44097.95 44100.25
8.036782421 "player.c:2629" -0.15 42.5 42.5 7340 46 3881k 44100.01 44102.31
7.998071920 "player.c:2629" -0.26 73.6 73.6 7312 46 3999k 44100.00 44102.30
7.994117337 "player.c:2629" -0.19 42.5 42.5 7316 46 3932k 44101.01 44103.30
7.995263629 "player.c:2629" -0.27 65.1 65.1 7320 46 3935k 44099.54 44101.83
8.019060296 "player.c:2629" -0.26 51.0 51.0 7292 46 3892k 44100.00 44102.29
8.000407379 "player.c:2629" -0.16 48.2 48.2 7339 46 3906k 44100.39 44102.68
7.999325670 "player.c:2629" -0.15 62.3 62.3 7273 46 3983k 44099.27 44101.55
8.008768087 "player.c:2629" -0.28 48.2 48.2 7316 46 3918k 44099.32 44101.60
8.015640504 "player.c:2629" -0.10 53.8 53.8 7315 46 3918k 44100.32 44102.60
8.000680254 "player.c:2629" -0.20 65.1 65.1 7277 46 3912k 44099.70 44101.98
8.016768337 "player.c:2629" -0.19 36.8 36.8 7274 46 3785k 44099.14 44101.41
7.990566587 "player.c:2629" -0.21 59.5 59.5 7320 46 3520k 44100.00 44102.27
8.006354004 "player.c:2629" -0.23 45.3 45.3 7328 46 3249k 44099.48 44101.75
8.029003254 "player.c:2629" -0.14 68.0 68.0 7316 46 2953k 44099.75 44102.02
7.989973337 "player.c:2629" -0.21 62.3 62.3 7324 46 2657k 44100.00 44102.26
8.027652754 "player.c:2629" -0.15 45.3 45.3 7320 46 2358k 44100.01 44102.27
7.986342712 "player.c:2629" -0.14 56.6 56.6 7316 46 2064k 44099.56 44101.82
8.002701962 "player.c:2629" -0.22 53.8 53.8 7318 46 1825k 44099.58 44101.84
8.023922587 "player.c:2629" -0.18 48.2 48.2 7313 46 1534k 44099.80 44102.05
7.989382879 "player.c:2629" -0.15 65.1 65.1 7315 46 1242k 44100.00 44102.25
8.008557754 "player.c:2629" -0.12 51.0 51.0 7318 46 951k 44100.19 44102.44
8.018268004 "player.c:2629" -0.18 51.0 51.0 7317 46 658k 44100.18 44102.43
7.997766712 "player.c:2629" -0.19 56.6 56.6 7324 46 366k 44100.18 44102.42
8.023343420 "player.c:2629" -0.20 59.5 59.5 7313 46 79k 44100.00 44102.25
4.253599627 "player.c:2884" Large negative (i.e. early) sync error of -5270 frames (-0.119501 seconds), at frame: 2633794173.
5.215102294 "player.c:2629" -1.72 68.0 68.0 25 0 0 N/A N/A
8.023304379 "player.c:2629" -1.36 300.2 300.2 7264 46 3773k 44094.53 44096.81
8.002517879 "player.c:2629" -0.24 90.6 90.6 7325 46 3683k 44097.29 44099.57
8.006554879 "player.c:2629" -0.14 51.0 51.0 7328 46 3675k 44094.49 44096.77
8.000677670 "player.c:2629" -0.24 51.0 51.0 7323 46 3687k 44099.99 44102.27
7.988649129 "player.c:2629" -0.15 56.6 56.6 7323 46 3689k 44095.62 44097.90
8.005668421 "player.c:2629" -0.26 53.8 53.8 7310 46 3683k 44098.17 44100.45
8.013143420 "player.c:2629" -0.22 51.0 51.0 7317 46 3685k 44098.42 44100.70
8.003539671 "player.c:2629" -0.15 53.8 53.8 7288 46 3676k 44099.31 44101.58
8.021452420 "player.c:2629" -0.18 42.5 42.5 7328 46 3639k 44097.56 44099.84
7.990375712 "player.c:2629" -0.22 48.2 48.2 7310 46 3583k 44099.45 44101.72
8.013217046 "player.c:2629" -0.15 62.3 62.3 7314 46 3592k 44099.50 44101.77
8.018491254 "player.c:2629" -0.12 48.2 48.2 7339 46 3592k 44100.00 44102.27
8.005929878 "player.c:2629" -0.19 56.6 56.6 7313 46 3584k 44098.73 44101.00
7.999797713 "player.c:2629" -0.21 51.0 51.0 7269 46 3579k 44099.60 44101.87
8.021628045 "player.c:2629" -0.19 62.3 62.3 7322 46 3582k 44099.27 44101.54
7.991770379 "player.c:2629" -0.16 56.6 56.6 7319 46 3576k 44098.96 44101.23
7.992069295 "player.c:2629" -0.18 39.7 39.7 7315 46 3295k 44098.71 44100.97
8.028170254 "player.c:2629" -0.18 59.5 59.5 7322 46 3020k 44100.00 44102.26
7.984223462 "player.c:2629" -0.16 42.5 42.5 7318 46 2753k 44098.84 44101.10
8.004810629 "player.c:2629" -0.20 62.3 62.3 7314 46 2486k 44099.45 44101.71
8.006271087 "player.c:2629" -0.23 45.3 45.3 7273 46 2222k 44098.96 44101.22
8.025232296 "player.c:2629" -0.11 51.0 51.0 7326 46 1990k 44099.51 44101.77
8.006094504 "player.c:2629" -0.12 56.6 56.6 7314 46 1773k 44099.28 44101.55
7.998566712 "player.c:2629" -0.22 53.8 53.8 7305 46 1507k 44099.31 44101.57
8.017468170 "player.c:2629" -0.28 51.0 51.0 7311 46 1241k 44099.34 44101.60
7.995044171 "player.c:2629" -0.17 59.5 59.5 7318 46 973k 44099.79 44102.05
8.000912754 "player.c:2629" -0.28 45.3 45.3 7299 46 706k 44100.00 44102.26
8.028574920 "player.c:2629" -0.25 59.5 59.5 7315 46 438k 44099.22 44101.47
7.996958046 "player.c:2629" -0.19 48.2 48.2 7300 46 167k 44100.00 44102.25
8.825548129 "player.c:2629" -0.24 42.5 42.5 7315 0 0 N/A N/A
8.002749879 "player.c:2629" -0.19 28.3 28.3 7316 46 2253k 44094.41 44096.64
8.011392712 "player.c:2629" -0.19 56.6 56.6 7316 46 3603k 44108.25 44110.48
8.012697962 "player.c:2629" -0.22 56.6 56.6 7311 46 3678k 44103.62 44105.85
8.003448920 "player.c:2629" -0.12 56.6 56.6 7333 46 3637k 44104.09 44106.32
8.025800171 "player.c:2629" -0.29 59.5 59.5 7319 46 3660k 44101.09 44103.33
7.989505879 "player.c:2629" -0.08 48.2 48.2 7315 46 3664k 44101.82 44104.05
8.016508712 "player.c:2629" -0.18 48.2 48.2 7317 46 3660k 44100.00 44102.23
7.984282712 "player.c:2629" -0.27 53.8 53.8 7321 46 3691k 44100.66 44102.90
8.003439170 "player.c:2629" -0.20 59.5 59.5 7320 46 3649k 44100.59 44102.82
8.034364546 "player.c:2629" -0.15 45.3 45.3 7323 46 3645k 44101.65 44103.88
7.980879754 "player.c:2629" -0.25 51.0 51.0 7318 46 3637k 44100.49 44102.72
8.020406920 "player.c:2629" -0.26 56.6 56.6 7287 46 3624k 44101.37 44103.61
8.015988629 "player.c:2629" -0.20 51.0 51.0 7316 46 3683k 44100.42 44102.66
7.994701004 "player.c:2629" -0.23 56.6 56.6 7321 46 3643k 44101.17 44103.41
8.007450837 "player.c:2629" -0.12 53.8 53.8 7317 46 3629k 44100.36 44102.59
^C 4.103477919 "player.c:1768" Connection 1: Playback stopped. Total playing time 00:13:19. Output: 44100.36 (raw), 44102.59 (corrected) frames per second.
0.005780875 "player.c:393" 1024 buffers allocated, 1024 buffers released.
0.007367000 "shairport.c:1721" normal exitThanks. That looks like it's working properly. Let me explain a few of the features:
Sync Error ms -- this is the average error, in milliseconds, in synchronisation. Thus, for example, the average sync error is normal well under 0.001 seconds, which is pretty good.Net Sync PPM -- this is the average amount of clock correction needed to keep the output device in sync with the audio, it's in parts per million (PPM). Loosely speaking, it's around 50 parts per million, which isn't bad.All Sync PPM is the total number of corrections make, in PPM, and should not be much higher than the Net Sync; if it is, it means the sync correction is overshooting.Min Buffer Size is the amount of compressed audio material in a buffer waiting to be played. This reduces as the track nears its end. When the track is over, the buffer is empty and the system has to resync again to the start of the next track -- that's the cause of the 4.253599627 "player.c:2884" Large negative (i.e. early) sync error of -5270 frames message, essentially a bogus message.Output FPS (c) is an attempt at calculating the true output rate of the DAC, nominally 44100 fps. It relies on having a good quality NTP synchronisation, and the longer you leave it without interruption, the more accurate it should become. If looks as if the DAC is running a little fast.Anyway, overall, my guess now is that there is some issue with the audio hat. Maybe a not-quite-fully compatible driver or something? Is anything else running on the system that might be interfering with it? An LCD screen or something using the output pins?
Simon-Says-eng
commented
1 year ago I have now disabled all other io functions and no other processes are running which are not os relevant.
I also have no problem if I play some other wav files over aplay. Do you have any other idea to debug the error? I already ordered 4 of the hats so I would like to use them.
mikebrady
commented
1 year ago Thanks for the update. It would be worth trying aplay ensuring the frame rate is 44100 and stereo (“CD quality”) — it seems to default to 48000. If that works without issue, then I’m a bit stumped. Given that Shairport Sync (“SPS”) is working with USB, it does seem to be something external to SPS. One difference between SPS and something like aplay is that the network has to be active. Could there be interference between the network and the I2S driver, I wonder? Can you try the DACs on a Raspberry Pi to see how well they work?
mikebrady
commented
1 year ago Hello again, @Simon-Says-eng.
It might just be worth changing the audio_backend_buffer_desired_length_in_seconds to something like a full second: 1.0. This will give the system longer to recover before the DAC buffer empties. The downside is that software volume control takes longer to work.
Worth a try, for sure, and easy to do.
Simon-Says-eng
commented
1 year ago today i could check the higher audio_backend_buffer_desired_length_in_seconds. It seemed first good but after a few tries i got the error again, the logs are below. Do you have a idea how i could do a long time test of a fixed bitrate audio in aplay? i could not find a long enough audio wav file. The command to try it was currently.
curl https://www.ee.columbia.edu/~dpwe/sounds/music/temple_of_love-sisters_of_mercy.wav | aplay
root@DietPi:~# shairport-sync -v --statistics
0.003682083 "shairport.c:2248" Startup in AirPlay 2 mode, with features 0x405fca00,0x1c340 on device "ba:92:dc:8f:f4:83".
0.000302500 "shairport.c:2287" Version String: "4.2-AirPlay2-smi9-OpenSSL-Avahi-ALSA-stdout-pipe-soxr-metadata-mqtt-dbus-mpris-sysconfdir:/usr/local/etc"
0.000050292 "shairport.c:2306" Command Line: "shairport-sync -v --statistics".
0.000898417 "shairport.c:2342" Log Verbosity is 1.
0.000149625 "audio_alsa.c:1020" alsa: alsa_maximum_stall_time of 0.200000 sec.
0.000108291 "audio_alsa.c:1309" alsa: disable_standby_mode is "never".
0.000032334 "audio_alsa.c:1313" alsa: disable_standby_mode_silence_threshold is 0.040000 seconds.
0.000028333 "audio_alsa.c:1315" alsa: disable_standby_mode_silence_scan_interval is 0.004000 seconds.
0.000047708 "audio_alsa.c:1355" alsa: output device name is "default".
0.000462292 "shairport.c:2390" disable_resend_requests is off.
0.000089708 "shairport.c:2391" diagnostic_drop_packet_fraction is 0.000000. A value of 0.0 means no packets will be dropped deliberately.
0.000043709 "shairport.c:2395" statistics_requester status is 1.
0.000026500 "shairport.c:2400" rtsp listening port is 7000.
0.000025375 "shairport.c:2401" udp base port is 6001.
0.000024708 "shairport.c:2402" udp port range is 10.
0.000025375 "shairport.c:2403" player name is "DietPi".
0.000024417 "shairport.c:2404" backend is "alsa".
0.000025791 "shairport.c:2405" run_this_before_play_begins action is "(null)".
0.000025875 "shairport.c:2406" run_this_after_play_ends action is "(null)".
0.000025709 "shairport.c:2407" wait-cmd status is 0.
0.000024791 "shairport.c:2408" run_this_before_play_begins may return output is 0.
0.000025500 "shairport.c:2409" run_this_if_an_unfixable_error_is_detected action is "(null)".
0.000025875 "shairport.c:2411" run_this_before_entering_active_state action is "(null)".
0.000024792 "shairport.c:2413" run_this_after_exiting_active_state action is "(null)".
0.000025417 "shairport.c:2415" active_state_timeout is 10.000000 seconds.
0.000033500 "shairport.c:2416" mdns backend "(null)".
0.000023875 "shairport.c:2418" interpolation setting is "auto".
0.000022500 "shairport.c:2422" interpolation soxr_delay_threshold is 30000000.
0.000025666 "shairport.c:2423" resync time is 0.050000 seconds.
0.000028042 "shairport.c:2424" resync recovery time is 0.100000 seconds.
0.000026833 "shairport.c:2425" allow a session to be interrupted: 0.
0.000025667 "shairport.c:2426" busy timeout time is 0.
0.000023583 "shairport.c:2427" drift tolerance is 0.002000 seconds.
0.000026459 "shairport.c:2428" password is "(null)".
0.000023875 "shairport.c:2429" default airplay volume is: -24.000000.
0.000029583 "shairport.c:2430" high threshold airplay volume is: -16.000000.
0.000036667 "shairport.c:2432" check for higher-than-threshold volume for new play session is disabled.
0.000026625 "shairport.c:2438" ignore_volume_control is 0.
0.000025000 "shairport.c:2442" volume_max_db is not set
0.000023625 "shairport.c:2443" volume range in dB (zero means use the range specified by the mixer): 0.
0.000026250 "shairport.c:2445" volume_range_combined_hardware_priority (1 means hardware mixer attenuation is used first) is 0.
0.000026833 "shairport.c:2449" playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
0.000026167 "shairport.c:2451" disable_synchronization is 0.
0.000024458 "shairport.c:2452" use_mmap_if_available is 1.
0.000024542 "shairport.c:2453" output_format automatic selection is enabled.
0.000024958 "shairport.c:2457" output_rate automatic selection is enabled.
0.000024333 "shairport.c:2461" audio backend desired buffer length is 1.000000 seconds.
0.000026959 "shairport.c:2463" audio_backend_buffer_interpolation_threshold_in_seconds is 0.120000 seconds.
0.000028125 "shairport.c:2465" audio backend latency offset is 0.000000 seconds.
0.000026625 "shairport.c:2467" audio backend silence lead-in time is "auto".
0.000024166 "shairport.c:2471" zeroconf regtype is "_raop._tcp".
0.000024875 "shairport.c:2472" decoders_supported field is 1.
0.000024167 "shairport.c:2473" use_apple_decoder is 0.
0.000023792 "shairport.c:2474" alsa_use_hardware_mute is 0.
0.000023916 "shairport.c:2478" no special mdns service interface was requested.
0.000099459 "shairport.c:2481" configuration file name "/usr/local/etc/shairport-sync.conf" resolves to "/usr/local/etc/shairport-sync.conf".
0.000035875 "shairport.c:2488" metadata enabled is 1.
0.000025291 "shairport.c:2489" metadata pipename is "/tmp/shairport-sync-metadata".
0.000026042 "shairport.c:2490" metadata socket address is "(null)" port 0.
0.000025250 "shairport.c:2492" metadata socket packet size is "500".
0.000024333 "shairport.c:2493" get-coverart is 1.
0.000023792 "shairport.c:2496" mqtt is disabled.
0.000023625 "shairport.c:2497" mqtt hostname is (null), port is 1883.
0.000025417 "shairport.c:2498" mqtt topic is /DietPi.
0.000024000 "shairport.c:2499" mqtt will not publish raw metadata.
0.000024916 "shairport.c:2500" mqtt will not publish parsed metadata.
0.000024459 "shairport.c:2501" mqtt will not publish cover Art.
0.000024541 "shairport.c:2502" mqtt remote control is disabled.
0.000023667 "shairport.c:2511" loudness is 0.
0.000023208 "shairport.c:2512" loudness reference level is -20.000000
0.000317292 "rtsp.c:4178" metadata pipe name is "/tmp/shairport-sync-metadata".
0.011684750 "shairport.c:2610" NQPTP is online.
0.010582375 "dbus-service.c:610" >> setting loudness threshold to -20.000000.
0.000323000 "dbus-service.c:623" >> setting drift tolerance to 0.002000 seconds.
0.000199750 "dbus-service.c:1020" >> ALACDecoder set to "hammerton"
0.000108083 "dbus-service.c:1025" >> Active set to "false"
0.000152042 "dbus-service.c:1030" >> disable standby mode set to "off"
0.000133667 "dbus-service.c:1051" >> interpolation set to "auto" (soxr support built in)
0.000149083 "dbus-service.c:518" >> deactivating disable standby
0.000130292 "dbus-service.c:600" >> deactivating loudness
0.000351250 "dbus-service.c:503" >> log verbosity set to 1.
0.000129791 "dbus-service.c:483" >> start logging statistics
0.000098500 "dbus-service.c:448" >> stop including elapsed time in logs
0.000104792 "dbus-service.c:458" >> start including delta time in logs
0.000098292 "dbus-service.c:471" >> start including file and line in logs
0.000281541 "dbus-service.c:1167" Shairport Sync native D-Bus service started at "org.gnome.ShairportSync" on the system bus.
0.002644292 "mpris-service.c:342" MPRIS service started at "org.mpris.MediaPlayer2.ShairportSync" on the system bus.
1.487786792 "shairport.c:254" "soxr" interpolation has been chosen.
22.660884303 "rtsp.c:2914" Connection 1: AP2 PTP connection from 2a02:8070:d286:97c0:312e:9a53:7de1:e783:64293 ("MacBook Pro von Bernd") to self at 2a02:8070:d286:97c0:b892:dcff:fe8f:f483:7000.
1.108173209 "rtsp.c:3276" Connection 1. AP2 Realtime Audio Stream.
2.006939042 "rtp.c:1741" AP2 Realtime Clock receiver initialised.
0.067832167 "player.c:2804" Connection 1: Playback started at frame 2008941274 -- AirPlay 2 Realtime.
7.075030462 "player.c:2629" Sync Error ms | Net Sync PPM | All Sync PPM | Missing | Late | Too Late | Resend Reqs | Min DAC Queue | Min Buffers | Max Buffers | Received FPS | Output FPS (r) | Output FPS (c)
0.000188708 "player.c:2629" 0.09 0.0 0.0 0 0 0 0 5679 113 235 44213.16 N/A N/A
8.008797504 "player.c:2629" -0.15 0.0 0.0 0 0 0 0 42773 125 129 44106.44 44100.73 44100.74
7.983406587 "player.c:2629" -0.41 0.0 0.0 0 0 0 0 42725 121 129 44151.71 44100.06 44100.06
8.009529504 "player.c:2629" -0.71 0.0 0.0 0 0 0 0 42741 125 129 44131.88 44099.82 44099.82
8.009943754 "player.c:2629" -1.05 0.0 0.0 0 0 0 0 42709 125 129 44129.56 44100.20 44100.20
7.141662753 "player.c:2689" Delay error -32 when checking running latency.
0.000230917 "audio_alsa.c:1751" alsa: recovering from a previous underrun.
0.027901416 "player.c:2884" Large negative (i.e. early) sync error of -43075 frames (-0.976757 seconds), at frame: 2011019482.
0.128471667 "player.c:2884" Large negative (i.e. early) sync error of -32398 frames (-0.734649 seconds), at frame: 2011024058.
0.118215209 "player.c:2884" Large negative (i.e. early) sync error of -21724 frames (-0.492608 seconds), at frame: 2011028634.
0.089429333 "player.c:2884" Large negative (i.e. early) sync error of -11040 frames (-0.250340 seconds), at frame: 2011033210.
0.716062917 "player.c:2629" -11.48 201.1 201.1 0 0 0 0 0 124 154 0.00 45160.15 45160.15
7.797513379 "player.c:2629" -2.72 699.6 699.6 0 0 0 0 5120 122 236 44263.42 44988.07 44988.07
8.011359962 "player.c:2629" -1.97 45.3 45.3 0 0 0 0 42619 124 129 44140.33 44861.05 44861.05
8.009666129 "player.c:2629" -1.98 48.2 48.2 0 2 0 1 42621 122 129 44098.51 44765.96 44765.96
8.010628670 "player.c:2629" -1.96 59.5 59.5 0 4 0 2 42595 120 129 44115.84 44691.88 44691.89
with audacity i was able to create a 10 minute sine wave with 44100Hz. Unfortunately, it came to the same effect as before. If it is played directly locally with aplay, it works without stuttering. With Shairplay it comes already after 2 minutes to problems. i dont get it what it can be.
root@DietPi:~# aplay sinus_24bit-PCM_44100Hz_Stereo_10Min.wav
Playing WAVE 'sinus_24bit-PCM_44100Hz_Stereo_10Min.wav' : Signed 24 bit Little Endian in 3bytes, Rate 44100 Hz, Stereo 0.110084209 "player.c:2813" Connection 1: Playback started at frame 3418487965 -- AirPlay 2 Buffered.
13.095455339 "player.c:2629" Sync Error ms | Net Sync PPM | All Sync PPM | Min DAC Queue | Min Buffers | Min Buffer Size | Output FPS (r) | Output FPS (c)
0.000206792 "player.c:2629" -0.29 0.0 0.0 23629 9 134k N/A N/A
7.999309296 "player.c:2629" -0.65 0.0 0.0 42658 46 2154k 44100.67 44100.67
8.026963670 "player.c:2629" -0.98 0.0 0.0 42642 46 2139k 44100.07 44100.07
8.005783962 "player.c:2629" -1.31 0.0 0.0 42642 46 2139k 44100.05 44100.05
8.008585296 "player.c:2629" -1.60 0.0 0.0 42610 46 2149k 44100.25 44100.25
7.982529670 "player.c:2629" -1.88 17.0 17.0 42502 44 2139k 44100.25 44100.25
8.014845504 "player.c:2629" -1.95 45.3 45.3 42597 46 2139k 44100.21 44100.21
8.006233962 "player.c:2629" -1.97 39.7 39.7 42604 46 2139k 44100.15 44100.15
8.006140504 "player.c:2629" -1.98 45.3 45.3 42490 46 2139k 44100.13 44100.13
8.024434670 "player.c:2629" -1.98 53.8 53.8 42503 45 2148k 44100.07 44100.07
8.010446171 "player.c:2629" -1.98 42.5 42.5 42444 45 2139k 44100.10 44100.10
2.464853168 "audio_alsa.c:1753" alsa: underrun while writing 352 samples to alsa device.
0.034209625 "player.c:2884" Large negative (i.e. early) sync error of -42756 frames (-0.969524 seconds), at frame: 3422498205.
0.137537083 "player.c:2884" Large negative (i.e. early) sync error of -32079 frames (-0.727415 seconds), at frame: 3422502781.
0.083882334 "player.c:2884" Large negative (i.e. early) sync error of -21399 frames (-0.485238 seconds), at frame: 3422507357.
0.123825000 "player.c:2884" Large negative (i.e. early) sync error of -10735 frames (-0.243424 seconds), at frame: 3422511933.
5.134929585 "player.c:2629" -12.50 832.7 832.7 0 41 2138k 44580.65 44580.65
8.006514254 "player.c:2629" -1.97 42.5 42.5 42594 46 2139k 44540.61 44540.61
^C 1.488687543 "player.c:1768" Connection 1: Playback stopped. Total playing time 00:01:50. Output: 44540.61 (raw), 44540.61 (corrected) frames per second.
0.005478166 "player.c:393" 1024 buffers allocated, 1024 buffers released.
0.015312042 "shairport.c:1721" normal exitThanks for your detective work. It's a real puzzle -- some kind of interference, maybe (?) between network activity and the I2S (?) output device. I'm a bit stumped, to be honest -- not having the device, I'm afraid I can't replicate your situation to investigate...
github-actions[bot]
commented
1 year ago This issue has been inactive for 45 days so will be closed 7 days from now. To prevent this, please remove the "stale" label or post a comment.
What happened?
I've been experiencing audio dropouts during playback when running Shairport-Sync on a Nanopi Neo LTS system equipped with a PCM5102A audio hat. During the Dropouts the Shairport Sync Task is using 100% of the CPU for about 2 Seconds. The Dropouts can also be seen in the Log as Sample Underruns.
Any suggestions on how to troubleshoot or resolve this issue would be appreciated. Thank you in advance for your help.
Relevant log output
Configuration Information.
uname -a
shairport-sync -V
Hardware: Nanopi Neo LTS with PCM5102A Audio Hat OS: Armbian_23.02.2_Nanopineo_jammy_current_5.15.93 also tried with DietPi_NanoPiNEO-ARMv7-Bullseye with same result.
How did you install Shairport Sync?
A package manager (apt, apt install, yum, pkg, etc.)
Check previous issues