mikebrady / shairport-sync

AirPlay and AirPlay 2 audio player
Other
7.19k stars 570 forks source link

[Problem]: Very heavy stuttering with pipewire output module #1736

Closed haasn closed 9 months ago

haasn commented 1 year ago

What happened?

I hear very heavy stuttering. A recording is worth a thousand words: problem.webm

Relevant log output

Click to expand ```shell Sep 25 15:55:08 xor systemd[4207]: Started Shairport Sync - AirPlay Audio Receiver. Sep 25 15:55:08 xor shairport-sync[81217]: 0.001054398 "shairport.c:2252" Startup in AirPlay 2 mode, with features 0x405fca00,0x1c340 on device "e0:d5:5e:2a:8c:c0". Sep 25 15:55:08 xor shairport-sync[81217]: 0.000090911 "shairport.c:2291" Version String: "4.3.1-AirPlay2-smi10-OpenSSL-Avahi-ALSA-pa-pw-pipe-soxr-convolution-metadata-dbus-mpris-sysconfdir:/etc" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000013405 "shairport.c:2310" Command Line: "/usr/bin/shairport-sync --log-to-syslog --verbose --configfile=/home/nand/.config/shairport-sync.conf". Sep 25 15:55:08 xor shairport-sync[81217]: 0.000064952 "shairport.c:2346" Log Verbosity is 1. Sep 25 15:55:08 xor shairport-sync[81217]: 0.000261630 "audio_pw.c:201" pw: compiled with libpipewire 0.3.80 Sep 25 15:55:08 xor shairport-sync[81217]: 0.000016762 "audio_pw.c:202" pw: linked with libpipewire: 0.3.79 Sep 25 15:55:08 xor shairport-sync[81217]: 0.001655274 "shairport.c:2394" disable_resend_requests is off. Sep 25 15:55:08 xor shairport-sync[81217]: 0.000011252 "shairport.c:2395" diagnostic_drop_packet_fraction is 0.000000. A value of 0.0 means no packets will be dropped deliberately. Sep 25 15:55:08 xor shairport-sync[81217]: 0.000005159 "shairport.c:2399" statistics_requester status is 0. Sep 25 15:55:08 xor shairport-sync[81217]: 0.000005060 "shairport.c:2404" rtsp listening port is 7000. Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003947 "shairport.c:2405" udp base port is 6001. Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003737 "shairport.c:2406" udp port range is 10. Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003487 "shairport.c:2407" player name is "nand@xor". Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003316 "shairport.c:2408" backend is "pw". Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003517 "shairport.c:2409" run_this_before_play_begins action is "(null)". Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003586 "shairport.c:2410" run_this_after_play_ends action is "(null)". Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003347 "shairport.c:2411" wait-cmd status is 0. Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003366 "shairport.c:2412" run_this_before_play_begins may return output is 0. Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003036 "shairport.c:2413" run_this_if_an_unfixable_error_is_detected action is "(null)". Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003206 "shairport.c:2415" run_this_before_entering_active_state action is "(null)". Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003496 "shairport.c:2417" run_this_after_exiting_active_state action is "(null)". Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003176 "shairport.c:2419" active_state_timeout is 10.000000 seconds. Sep 25 15:55:08 xor shairport-sync[81217]: 0.000004238 "shairport.c:2420" mdns backend "(null)". Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003106 "shairport.c:2422" interpolation setting is "soxr". Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003166 "shairport.c:2426" interpolation soxr_delay_threshold is 30000000. Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003576 "shairport.c:2427" resync time is 0.050000 seconds. Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003507 "shairport.c:2428" resync recovery time is 0.100000 seconds. Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003376 "shairport.c:2429" allow a session to be interrupted: 0. Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003287 "shairport.c:2430" busy timeout time is 0. Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003035 "shairport.c:2431" drift tolerance is 0.002000 seconds. Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003417 "shairport.c:2432" password is "(null)". Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003105 "shairport.c:2433" default airplay volume is: -10.000000. Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003517 "shairport.c:2434" high threshold airplay volume is: -3.000000. Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003296 "shairport.c:2436" check for higher-than-threshold volume for new play session is disabled. Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003958 "shairport.c:2442" ignore_volume_control is 0. Sep 25 15:55:08 xor shairport-sync[81217]: 0.000004188 "shairport.c:2446" volume_max_db is not set Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003556 "shairport.c:2447" volume range in dB (zero means use the range specified by the mixer): 0. Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003427 "shairport.c:2449" volume_range_combined_hardware_priority (1 means hardware mixer attenuation is used first) is 0. Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003256 "shairport.c:2453" playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right). Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003867 "shairport.c:2455" disable_synchronization is 0. Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003707 "shairport.c:2456" use_mmap_if_available is 1. Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003436 "shairport.c:2457" output_format automatic selection is enabled. Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003216 "shairport.c:2461" output_rate automatic selection is enabled. Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003016 "shairport.c:2465" audio backend desired buffer length is 0.350000 seconds. Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003346 "shairport.c:2467" audio_backend_buffer_interpolation_threshold_in_seconds is 0.020000 seconds. Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003317 "shairport.c:2469" audio backend latency offset is 0.000000 seconds. Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003386 "shairport.c:2471" audio backend silence lead-in time is "auto". Sep 25 15:55:08 xor shairport-sync[81217]: 0.000002915 "shairport.c:2475" zeroconf regtype is "_raop._tcp". Sep 25 15:55:08 xor shairport-sync[81217]: 0.000002966 "shairport.c:2476" decoders_supported field is 1. Sep 25 15:55:08 xor shairport-sync[81217]: 0.000002976 "shairport.c:2477" use_apple_decoder is 0. Sep 25 15:55:08 xor shairport-sync[81217]: 0.000002905 "shairport.c:2478" alsa_use_hardware_mute is 0. Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003497 "shairport.c:2482" no special mdns service interface was requested. Sep 25 15:55:08 xor shairport-sync[81217]: 0.000008886 "shairport.c:2485" configuration file name "/home/nand/.config/shairport-sync.conf" resolves to "/home/nand/.config/shairport-sync.conf". Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003557 "shairport.c:2492" metadata enabled is 1. Sep 25 15:55:08 xor shairport-sync[81217]: 0.000002915 "shairport.c:2493" metadata pipename is "/tmp/shairport-sync-metadata". Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003457 "shairport.c:2494" metadata socket address is "(null)" port 0. Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003516 "shairport.c:2496" metadata socket packet size is "500". Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003537 "shairport.c:2497" get-coverart is 1. Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003547 "shairport.c:2510" convolution is 0. Sep 25 15:55:08 xor shairport-sync[81217]: 0.000002905 "shairport.c:2511" convolution IR file is "(null)" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003286 "shairport.c:2512" convolution max length 8192 Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003417 "shairport.c:2513" convolution gain is 0.000000 Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003296 "shairport.c:2515" loudness is 0. Sep 25 15:55:08 xor shairport-sync[81217]: 0.000002925 "shairport.c:2516" loudness reference level is -20.000000 Sep 25 15:55:08 xor shairport-sync[81217]: 0.000045586 "rtsp.c:4150" metadata pipe name is "/tmp/shairport-sync-metadata". Sep 25 15:55:08 xor shairport-sync[81217]: 0.000326973 "audio_pw.c:69" pw: remote 0 is named "pipewire-0" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000030437 "audio_pw.c:98" pw: registry: id=40 type=PipeWire:Interface:Node name="speaker.input" media_class="Audio/Sink" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000004659 "audio_pw.c:101" pw: object.serial = "40" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003998 "audio_pw.c:101" pw: factory.id = "18" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003757 "audio_pw.c:101" pw: client.id = "36" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000004047 "audio_pw.c:101" pw: node.description = "Main speaker" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000004018 "audio_pw.c:101" pw: node.name = "speaker.input" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003957 "audio_pw.c:101" pw: media.class = "Audio/Sink" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000006703 "audio_pw.c:98" pw: registry: id=41 type=PipeWire:Interface:Node name="speaker.output" media_class="Stream/Output/Audio" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000004438 "audio_pw.c:101" pw: object.serial = "41" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003557 "audio_pw.c:101" pw: factory.id = "18" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003797 "audio_pw.c:101" pw: client.id = "36" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003827 "audio_pw.c:101" pw: node.description = "Main speaker" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003647 "audio_pw.c:101" pw: node.name = "speaker.output" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003807 "audio_pw.c:101" pw: media.class = "Stream/Output/Audio" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000006091 "audio_pw.c:98" pw: registry: id=42 type=PipeWire:Interface:Node name="bass.input" media_class="Audio/Sink" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000004188 "audio_pw.c:101" pw: object.serial = "42" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003888 "audio_pw.c:101" pw: factory.id = "18" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000004358 "audio_pw.c:101" pw: client.id = "39" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000004318 "audio_pw.c:101" pw: node.description = "Bass enhancer" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000004188 "audio_pw.c:101" pw: node.name = "bass.input" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003917 "audio_pw.c:101" pw: media.class = "Audio/Sink" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000004729 "audio_pw.c:98" pw: registry: id=43 type=PipeWire:Interface:Node name="bass.output" media_class="Stream/Output/Audio" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003967 "audio_pw.c:101" pw: object.serial = "43" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003918 "audio_pw.c:101" pw: factory.id = "18" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003516 "audio_pw.c:101" pw: client.id = "39" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003507 "audio_pw.c:101" pw: node.description = "Bass enhancer" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003757 "audio_pw.c:101" pw: node.name = "bass.output" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003737 "audio_pw.c:101" pw: media.class = "Stream/Output/Audio" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000005059 "audio_pw.c:98" pw: registry: id=46 type=PipeWire:Interface:Node name="Midi-Bridge" media_class="Midi/Bridge" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003948 "audio_pw.c:101" pw: object.serial = "46" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000004188 "audio_pw.c:101" pw: factory.id = "10" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003897 "audio_pw.c:101" pw: client.id = "38" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000004258 "audio_pw.c:101" pw: node.name = "Midi-Bridge" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003587 "audio_pw.c:101" pw: media.class = "Midi/Bridge" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000108122 "audio_pw.c:98" pw: registry: id=66 type=PipeWire:Interface:Node name="alsa_output.usb-Focusrite_Scarlett_6i6_USB_00053528-00.pro-output-0" media_cla> Sep 25 15:55:08 xor shairport-sync[81217]: 0.000007635 "audio_pw.c:101" pw: object.serial = "66" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003937 "audio_pw.c:101" pw: object.path = "alsa:pcm:2:hw:2,0:playback" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003787 "audio_pw.c:101" pw: factory.id = "18" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003827 "audio_pw.c:101" pw: client.id = "38" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000005080 "audio_pw.c:101" pw: device.id = "54" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000004599 "audio_pw.c:101" pw: priority.session = "1500" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000004238 "audio_pw.c:101" pw: priority.driver = "1500" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000004268 "audio_pw.c:101" pw: node.description = "Focusrite Scarlett 6i6 Pro" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003917 "audio_pw.c:101" pw: node.name = "alsa_output.usb-Focusrite_Scarlett_6i6_USB_00053528-00.pro-output-0" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000004228 "audio_pw.c:101" pw: node.nick = "Scarlett 6i6 USB" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003897 "audio_pw.c:101" pw: media.class = "Audio/Sink" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000005010 "audio_pw.c:98" pw: registry: id=67 type=PipeWire:Interface:Node name="alsa_input.usb-Focusrite_Scarlett_6i6_USB_00053528-00.pro-input-0" media_class> Sep 25 15:55:08 xor shairport-sync[81217]: 0.000004137 "audio_pw.c:101" pw: object.serial = "67" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000004739 "audio_pw.c:101" pw: object.path = "alsa:pcm:2:hw:2,0:capture" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000004439 "audio_pw.c:101" pw: factory.id = "18" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003797 "audio_pw.c:101" pw: client.id = "38" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003867 "audio_pw.c:101" pw: device.id = "54" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000004017 "audio_pw.c:101" pw: priority.session = "2500" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003958 "audio_pw.c:101" pw: priority.driver = "2500" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000004378 "audio_pw.c:101" pw: node.description = "Focusrite Scarlett 6i6 Pro" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000004889 "audio_pw.c:101" pw: node.name = "alsa_input.usb-Focusrite_Scarlett_6i6_USB_00053528-00.pro-input-0" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000004138 "audio_pw.c:101" pw: node.nick = "Scarlett 6i6 USB" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000003737 "audio_pw.c:101" pw: media.class = "Audio/Source" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000803046 "shairport.c:2643" NQPTP is online. Sep 25 15:55:08 xor shairport-sync[81217]: 0.001777174 "dbus-service.c:610" >> setting loudness threshold to -20.000000. Sep 25 15:55:08 xor shairport-sync[81217]: 0.000018374 "dbus-service.c:623" >> setting drift tolerance to 0.002000 seconds. Sep 25 15:55:08 xor shairport-sync[81217]: 0.000021751 "dbus-service.c:1024" >> ALACDecoder set to "hammerton" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000005640 "dbus-service.c:1029" >> Active set to "false" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000005280 "dbus-service.c:1034" >> disable standby mode set to "off" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000005190 "dbus-service.c:1058" >> interpolation set to "soxr" Sep 25 15:55:08 xor shairport-sync[81217]: 0.000006392 "dbus-service.c:518" >> deactivating disable standby Sep 25 15:55:08 xor shairport-sync[81217]: 0.000005170 "dbus-service.c:600" >> deactivating loudness Sep 25 15:55:08 xor shairport-sync[81217]: 0.000004528 "dbus-service.c:534" >> deactivating convolution Sep 25 15:55:08 xor shairport-sync[81217]: 0.000014397 "dbus-service.c:503" >> log verbosity set to 1. Sep 25 15:55:08 xor shairport-sync[81217]: 0.000004809 "dbus-service.c:488" >> stop logging statistics Sep 25 15:55:08 xor shairport-sync[81217]: 0.000004639 "dbus-service.c:448" >> stop including elapsed time in logs Sep 25 15:55:08 xor shairport-sync[81217]: 0.000004889 "dbus-service.c:458" >> start including delta time in logs Sep 25 15:55:08 xor shairport-sync[81217]: 0.000004889 "dbus-service.c:471" >> start including file and line in logs Sep 25 15:55:08 xor shairport-sync[81217]: 0.000012253 "dbus-service.c:1174" Shairport Sync native D-Bus service started at "org.gnome.ShairportSync" on the session bus. Sep 25 15:55:08 xor shairport-sync[81217]: 0.000136106 "mpris-service.c:342" MPRIS service started at "org.mpris.MediaPlayer2.ShairportSync" on the session bus. Sep 25 15:55:23 xor shairport-sync[81217]: 15.008093434 "rtsp.c:2866" Connection 1: AP2 PTP connection from 109.192.222.233:49455 ("Supernova") to self at 192.168.0.20:7000. Sep 25 15:55:24 xor shairport-sync[81217]: 0.166927897 "audio_pw.c:368" pw: rate: 44100 Sep 25 15:55:24 xor shairport-sync[81217]: 0.000021009 "audio_pw.c:369" pw: channgels: 2 Sep 25 15:55:24 xor shairport-sync[81217]: 0.000005510 "audio_pw.c:370" pw: format: s16 Sep 25 15:55:24 xor shairport-sync[81217]: 0.000004769 "audio_pw.c:371" pw: samplesize: 2 Sep 25 15:55:24 xor shairport-sync[81217]: 0.000004479 "audio_pw.c:372" pw: stride: 4 Sep 25 15:55:24 xor shairport-sync[81217]: 0.000004769 "audio_pw.c:374" pw: latency: 882 samples (0.020s) Sep 25 15:55:24 xor shairport-sync[81217]: 0.000061726 "audio_pw.c:388" pw: connecting stream: target_id=4294967295 Sep 25 15:55:24 xor shairport-sync[81217]: 0.000011972 "audio_pw.c:119" pw: stream state changed unconnected -> connecting Sep 25 15:55:24 xor shairport-sync[81217]: 0.000686337 "audio_pw.c:406" pw: stream properties: Sep 25 15:55:24 xor shairport-sync[81217]: 0.000013836 "audio_pw.c:410" pw: media.type = "Audio" Sep 25 15:55:24 xor shairport-sync[81217]: 0.000006312 "audio_pw.c:410" pw: media.category = "Playback" Sep 25 15:55:24 xor shairport-sync[81217]: 0.000005530 "audio_pw.c:410" pw: media.role = "Music" Sep 25 15:55:24 xor shairport-sync[81217]: 0.000005861 "audio_pw.c:410" pw: application.name = "shairport-sync" Sep 25 15:55:24 xor shairport-sync[81217]: 0.000005240 "audio_pw.c:410" pw: node.name = "shairport-sync" Sep 25 15:55:24 xor shairport-sync[81217]: 0.000004950 "audio_pw.c:410" pw: node.latency = "882/44100" Sep 25 15:55:24 xor shairport-sync[81217]: 0.000005199 "audio_pw.c:410" pw: media.name = "shairport-sync" Sep 25 15:55:24 xor shairport-sync[81217]: 0.000005000 "audio_pw.c:410" pw: stream.is-live = "true" Sep 25 15:55:24 xor shairport-sync[81217]: 0.000004909 "audio_pw.c:410" pw: node.want-driver = "true" Sep 25 15:55:24 xor shairport-sync[81217]: 0.000004939 "audio_pw.c:410" pw: node.autoconnect = "true" Sep 25 15:55:24 xor shairport-sync[81217]: 0.000004759 "audio_pw.c:410" pw: media.class = "Stream/Output/Audio" Sep 25 15:55:24 xor shairport-sync[81217]: 0.000485100 "audio_pw.c:119" pw: stream state changed connecting -> paused Sep 25 15:55:24 xor shairport-sync[81217]: 0.000035356 "audio_pw.c:98" pw: registry: id=100 type=PipeWire:Interface:Node name="shairport-sync" media_class="Stream/Output/Audio" Sep 25 15:55:24 xor shairport-sync[81217]: 0.000008025 "audio_pw.c:101" pw: object.serial = "121" Sep 25 15:55:24 xor shairport-sync[81217]: 0.000004349 "audio_pw.c:101" pw: factory.id = "8" Sep 25 15:55:24 xor shairport-sync[81217]: 0.000003706 "audio_pw.c:101" pw: client.id = "93" Sep 25 15:55:24 xor shairport-sync[81217]: 0.000003647 "audio_pw.c:101" pw: application.name = "shairport-sync" Sep 25 15:55:24 xor shairport-sync[81217]: 0.000003457 "audio_pw.c:101" pw: node.name = "shairport-sync" Sep 25 15:55:24 xor shairport-sync[81217]: 0.000003316 "audio_pw.c:101" pw: media.class = "Stream/Output/Audio" Sep 25 15:55:24 xor shairport-sync[81217]: 0.000003627 "audio_pw.c:101" pw: media.type = "Audio" Sep 25 15:55:24 xor shairport-sync[81217]: 0.000003516 "audio_pw.c:101" pw: media.category = "Playback" Sep 25 15:55:24 xor shairport-sync[81217]: 0.000003277 "audio_pw.c:101" pw: media.role = "Music" Sep 25 15:55:24 xor shairport-sync[81217]: 0.178325254 "audio_pw.c:119" pw: stream state changed paused -> streaming Sep 25 15:55:24 xor shairport-sync[81217]: 0.000020519 "audio_pw.c:123" pw: stream node 100 Sep 25 15:56:38 xor shairport-sync[81217]: 74.591747231 "audio_pw.c:119" pw: stream state changed streaming -> paused ```

System Information.

System:
  Host: xor Kernel: 6.4.12-1-default arch: x86_64 bits: 64 compiler: gcc
    v: 13.2.1 Desktop: GNOME tk: GTK v: 3.24.38 wm: xmonad dm: SDDM
    Distro: openSUSE Tumbleweed 20230914
CPU:
  Info: 16-core model: AMD Ryzen Threadripper 1950X bits: 64 type: MT MCP MCM
    arch: Zen rev: 1 cache: L1: 1.5 MiB L2: 8 MiB L3: 32 MiB
  Speed (MHz): avg: 2216 high: 3400 min/max: 2200/3400 boost: enabled cores:
    1: 2200 2: 2200 3: 2200 4: 3400 5: 2200 6: 2200 7: 2200 8: 2200 9: 2200
    10: 1884 11: 2200 12: 2092 13: 2200 14: 2200 15: 2200 16: 2200 17: 1956
    18: 2200 19: 2200 20: 2200 21: 2200 22: 2200 23: 2200 24: 2200 25: 2200
    26: 2200 27: 2200 28: 2196 29: 2200 30: 2200 31: 2200 32: 2200
    bogomips: 217254
  Flags: avx avx2 ht lm nx pae sse sse2 sse3 sse4_1 sse4_2 sse4a ssse3 svm
Audio:
  Device-1: NVIDIA GA106 High Definition Audio vendor: Micro-Star MSI
    driver: snd_hda_intel v: kernel pcie: speed: 2.5 GT/s lanes: 8
    bus-ID: 09:00.1 chip-ID: 10de:228e
  Device-2: AMD Navi 21/23 HDMI/DP Audio driver: snd_hda_intel v: kernel
    pcie: speed: 16 GT/s lanes: 16 bus-ID: 44:00.1 chip-ID: 1002:ab28
  Device-3: Focusrite-Novation Focusrite Scarlett 6i6 driver: snd-usb-audio
    type: USB rev: 2.0 speed: 480 Mb/s lanes: 1 bus-ID: 5-3:3 chip-ID: 1235:8203
  API: ALSA v: k6.4.12-1-default status: kernel-api with: aoss
    type: oss-emulator
  Server-1: PipeWire v: 0.3.79 status: active with: 1: pipewire-pulse
    status: active 2: wireplumber status: active 3: pipewire-alsa type: plugin
    4: pw-jack type: plugin

Configuration Information.

>> Display Config Start.

From "uname -a":
 Linux xor 6.4.12-1-default #1 SMP PREEMPT_DYNAMIC Fri Aug 25 08:26:31 UTC 2023 (f5aa89b) x86_64 x86_64 x86_64 GNU/Linux

From /etc/os-release:
 openSUSE Tumbleweed

Shairport Sync Version String:
 4.3.1-AirPlay2-smi10-OpenSSL-Avahi-ALSA-pa-pw-pipe-soxr-convolution-metadata-dbus-mpris-sysconfdir:/etc

Command Line:
 shairport-sync --displayConfig

Configuration File:
 /etc/shairport-sync.conf

Configuration File Settings:
 general : 
 {
   name = "shairport@%h";
   interpolation = "soxr";
   output_backend = "pw";
   dbus_service_bus = "session";
   mpris_service_bus = "session";
 };

>> Display Config End.
>> Goodbye!

PulseAudio or PipeWire installed?

How did you install Shairport Sync?

A package manager (apt, apt install, yum, pkg, etc.)

Check previous issues

haasn commented 1 year ago

Using pa instead works fine, I should point out. (Except when it doesn't, but that's a separate issue)

mikebrady commented 1 year ago

Thanks for the post. Can you skip the pipewire stuff and go directly to the output device via the ALSA backend?

mikebrady commented 1 year ago

Using pa instead works fine, I should point out. (Except when it doesn't, but that's a separate issue)

Ah yes, so it's the pipewire backend. It needs work, by the look of it. TBH it's pretty low on the list of priorities right now, as is PulseAudio.

haasn commented 1 year ago

Using the alsa backend (with the pipewire alsa module) works fine initially, but after a few seconds I also get heavy stuttering with this spammed:

Sep 25 16:12:25 xor shairport-sync[90250]:         15.028266441 "audio_alsa.c:1754" alsa: underrun while writing 351 samples to alsa device.
Sep 25 16:12:25 xor shairport-sync[90250]:          0.019859479 "audio_alsa.c:1754" alsa: underrun while writing 351 samples to alsa device.
Sep 25 16:12:25 xor shairport-sync[90250]:          0.020032164 "audio_alsa.c:1754" alsa: underrun while writing 351 samples to alsa device.
Sep 25 16:12:25 xor shairport-sync[90250]:          0.020187674 "audio_alsa.c:1754" alsa: underrun while writing 351 samples to alsa device.
...
haasn commented 1 year ago

I should also point out that the pa module seems to have a regression where it will randomly fail to resume playback when the song ends and the next song starts. It worked fine in the past, so I don't know what would have changed.

mikebrady commented 1 year ago

Thanks for all that. What I was wondering is whether using the alsa backend to go directly to the output device -- not via the PipeWire adapter -- works well. It might be difficult to unhook PipeWire though.

I should also point out that the pa module seems to have a regression where it will randomly fail to resume playback when the song ends and the next song starts. It worked fine in the past, so I don't know what would have changed.

If you got a chance to find a way of getting to that to happen repeatedly, it would be great.

Actually, plugging in a spare sound card (e.g. a USB sound dongle if you have one lying around) might work -- PipeWire might not try to take it over.

haasn commented 1 year ago

Sure, I can do some direct-to-device tests in a bit. Though I imagine it will work fine.

(Just to be clear, I need this working over PipeWire, in the end, because my entire desktop audio stack is built around pipewire and shairport-sync is not the only thing on my system)

haasn commented 1 year ago

If you got a chance to find a way of getting to that to happen repeatedly, it would be great.

I'm not yet sure how to reproduce it consistently but I saw this when it happened again:

Sep 25 16:14:08 xor shairport-sync[90765]:          6.455496006 "rtsp.c:2866" Connection 1: AP2 PTP connection from 109.192.222.233:49489 ("Supernova") to self at 192.168.0.20:7000.
Sep 25 16:36:37 xor shairport-sync[90765]:       1348.797760686 "player.c:2887" Large positive (i.e. late) sync error of 2848 frames (0.064580 seconds), at frame: 1916366191.
Sep 25 16:36:37 xor shairport-sync[90765]:          0.240970364 "player.c:2912" Large negative (i.e. early) sync error of -2494 frames (-0.056553 seconds), at frame: 1916377455.
Sep 25 16:36:37 xor shairport-sync[90765]:          0.099668473 "player.c:2887" Large positive (i.e. late) sync error of 4046 frames (0.091746 seconds), at frame: 1916382031.
Sep 25 16:36:37 xor shairport-sync[90765]:          0.292538538 "player.c:2912" Large negative (i.e. early) sync error of -2446 frames (-0.055465 seconds), at frame: 1916394703.
Sep 25 16:36:37 xor shairport-sync[90765]:          0.108517309 "player.c:2887" Large positive (i.e. late) sync error of 4437 frames (0.100612 seconds), at frame: 1916399279.
Sep 25 16:36:38 xor shairport-sync[90765]:          0.292631833 "player.c:2912" Large negative (i.e. early) sync error of -2351 frames (-0.053311 seconds), at frame: 1916412303.
Sep 25 16:36:38 xor shairport-sync[90765]:          0.120208709 "player.c:2887" Large positive (i.e. late) sync error of 4949 frames (0.112222 seconds), at frame: 1916416879.
mikebrady commented 1 year ago

(Just to be clear, I need this working over PipeWire, in the end, because my entire desktop audio stack is built around pipewire and shairport-sync is not the only thing on my system)

Fair enough -- I'l take a look, but it might be a while.

mikebrady commented 1 year ago

If you got a chance to find a way of getting to that to happen repeatedly, it would be great.

I'm not yet sure how to reproduce it consistently but I saw this when it happened again:

Sep 25 16:14:08 xor shairport-sync[90765]:          6.455496006 "rtsp.c:2866" Connection 1: AP2 PTP connection from 109.192.222.233:49489 ("Supernova") to self at 192.168.0.20:7000.
Sep 25 16:36:37 xor shairport-sync[90765]:       1348.797760686 "player.c:2887" Large positive (i.e. late) sync error of 2848 frames (0.064580 seconds), at frame: 1916366191.
Sep 25 16:36:37 xor shairport-sync[90765]:          0.240970364 "player.c:2912" Large negative (i.e. early) sync error of -2494 frames (-0.056553 seconds), at frame: 1916377455.
Sep 25 16:36:37 xor shairport-sync[90765]:          0.099668473 "player.c:2887" Large positive (i.e. late) sync error of 4046 frames (0.091746 seconds), at frame: 1916382031.
Sep 25 16:36:37 xor shairport-sync[90765]:          0.292538538 "player.c:2912" Large negative (i.e. early) sync error of -2446 frames (-0.055465 seconds), at frame: 1916394703.
Sep 25 16:36:37 xor shairport-sync[90765]:          0.108517309 "player.c:2887" Large positive (i.e. late) sync error of 4437 frames (0.100612 seconds), at frame: 1916399279.
Sep 25 16:36:38 xor shairport-sync[90765]:          0.292631833 "player.c:2912" Large negative (i.e. early) sync error of -2351 frames (-0.053311 seconds), at frame: 1916412303.
Sep 25 16:36:38 xor shairport-sync[90765]:          0.120208709 "player.c:2887" Large positive (i.e. late) sync error of 4949 frames (0.112222 seconds), at frame: 1916416879.

Super. If you could just note the version string of Shairport Sync when it happens again, it would be very useful, thanks.

haasn commented 1 year ago

It's the same version as above:

mikebrady commented 1 year ago

I just pushed an update to the PipeWire backend, pw, into the development branch that might stop the stuttering. But the PipeWire backend doesn't do synchronisation, so eventually you will get overrun or underrun. Anyway, it might be better than what you have at present.

haasn commented 1 year ago

Exact same issue.

mikebrady commented 1 year ago

Apologies -- there was ambiguity in my previous message. The update was to the PipeWire (pw) backend, not the PulseAudio backend.

haasn commented 1 year ago

Yes, I'm referring to the issue from the original post.

Nemo157 commented 1 year ago

I also get similar stuttering with the pipewire backend while pulseaudio works fine, updating to 7fe48618742244b3dcb254b3d832e52013380de3 didn't change it.

If it was c04674683243b987de4a6da6760efd7416c5b224 that was meant to change stuff, it looks like that didn't actually change the latency number, just added a comment. Locally applying a patch to bump the latency to 200000 does appear to fix the stuttering (though I also get a lot of late packets so have to increase the drift tolerance).

mikebrady commented 1 year ago

Crikey, you are right. Apologies for that. I'll really fix it shortly. But, but, on Ubuntu 23.04 on a VM, the original code is very smooth:

image
haasn commented 1 year ago

On my end, on 4.3.1:

S   ID  QUANT   RATE    WAIT    BUSY   W/Q   B/Q  ERR FORMAT           NAME                                                                          
I   30      0      0   0,0us   0,0us  0,00  0,00    0                  Dummy-Driver
S   44      0      0    ---     ---   ---   ---     0                  Midi-Bridge
R   63    512  48000 230,0us   4,5us  0,02  0,00    0    S32LE 6 48000 alsa_output.usb-Focusrite_Scarlett_6i6_USB_00053528-00.pro-output-0
R   36      0      0   1,9us   1,4us  0,00  0,00    0         F32P 2 0  + speaker.input
R   37      0      0   1,8us  92,0us  0,00  0,01    0         F32P 3 0  + speaker.output
R   40      0      0   9,1us   3,5us  0,00  0,00    0         F32P 2 0  + bass.input
R   41      0      0   2,5us  87,7us  0,00  0,01    0         F32P 2 0  + bass.output
R   91    882  44100  25,9us   3,7us  0,00  0,00  296    S16LE 2 44100  + shairport-sync
S   64      0      0    ---     ---   ---   ---     0                  alsa_input.usb-Focusrite_Scarlett_6i6_USB_00053528-00.pro-input-0
I  101      0      0   0,0us   0,0us  0,00  0,00    0    S16LE 1 44100 speech-dispatcher-dummy

With your (fixed) patch:

S   ID  QUANT   RATE    WAIT    BUSY   W/Q   B/Q  ERR FORMAT           NAME                                                                          
I   30      0      0   0,0us   0,0us  0,00  0,00    0                  Dummy-Driver
S   44      0      0    ---     ---   ---   ---     0                  Midi-Bridge
R   63    128  48000  79,8us   2,9us  0,03  0,00    0    S32LE 6 48000 alsa_output.usb-Focusrite_Scarlett_6i6_USB_00053528-00.pro-output-0
R   36      0      0   1,7us   1,2us  0,00  0,00    0         F32P 2 0  + speaker.input
R   37      0      0   1,7us  10,6us  0,00  0,00    0         F32P 3 0  + speaker.output
R   40      0      0   7,9us   2,9us  0,00  0,00    0         F32P 2 0  + bass.input
R   41      0      0   2,3us  22,1us  0,00  0,01    0         F32P 2 0  + bass.output
R   93    230  44100  24,3us   5,0us  0,01  0,00    0    S16LE 2 44100  + shairport-sync
S   64      0      0    ---     ---   ---   ---     0                  alsa_input.usb-Focusrite_Scarlett_6i6_USB_00053528-00.pro-input-0
I  101      0      0   0,0us   0,0us  0,00  0,00    0    S16LE 1 44100 speech-dispatcher-dummy
haasn commented 1 year ago

I can confirm that the change to 200000 does appear to fix things for me.

Nemo157 commented 1 year ago

I wonder if in my case using a bluetooth sink is increasing the latency, though the numbers in pw-top look smaller (but I don't know what they mean exactly)

S   ID  QUANT   RATE    WAIT    BUSY   W/Q   B/Q  ERR FORMAT           NAME
R  100    128  48000  14.8us   9.4us  0.01  0.00    0    F32LE 2 48000 bluez_output.....1
R   93    230  44100   5.8us   2.5us  0.00  0.00    1    S16LE 2 44100  + shairport-sync
mikebrady commented 1 year ago

Just pushed that fix! Apologies again.

I can confirm that the change to 200000 does appear to fix things for me.

Good stuff, thanks. I really need to dig in to PipeWire to figure out how to measure the instantaneous latency, which is needed to do synchronised output.

mikebrady commented 1 year ago

... (but I don't know what they mean exactly)

Me neither!

haasn commented 1 year ago

By the way, there is some sort of UB when you exit the process with ^C:

^C         1.985204223 "rtsp.c:531" Connection 1: cancelled.
         0.002011422 "rtsp.c:542" Connection 1: joined.
         0.001219877 "audio_pw.c:119" pw: stream state changed paused -> unconnected
         0.001316138 "shairport.c:1725" normal exit
corrupted double-linked list
[1]    20876 IOT instruction (core dumped)  ./shairport-sync --verbose --configfile=/home/nand/.config/shairport-sync.con
mikebrady commented 1 year ago

Thanks, I'll take a look!

Nemo157 commented 1 year ago

Looks like my sink has a high (150ms) latency, so bumping it up to 200ms gets across that threshold:

> pw-cli enum-params 100 15
  Object: size 176, type Spa:Pod:Object:Param:Latency (262155), id Spa:Enum:ParamId:Latency (15)
[...]
    Prop: key Spa:Pod:Object:Param:Latency:minNs (6), flags 00000000
      Long 150000000
    Prop: key Spa:Pod:Object:Param:Latency:maxNs (7), flags 00000000
      Long 150000000
mikebrady commented 1 year ago

Very interesting indeed -- there's a lot to find out about PipeWire!

haasn commented 1 year ago

I still have the issue where it will sometimes just stop playing after a song transition, requiring restart of shairport-sync to fix. It seems like a different issue to the pa one, because this time I don't get log spam about sync errors. (And on pa, it's enough to just disconnect/reconnect, but with pw it seems I need to restart shairport-sync completely..)

mikebrady commented 1 year ago

By the way, there is some sort of UB when you exit the process with ^C:

^C         1.985204223 "rtsp.c:531" Connection 1: cancelled.
         0.002011422 "rtsp.c:542" Connection 1: joined.
         0.001219877 "audio_pw.c:119" pw: stream state changed paused -> unconnected
         0.001316138 "shairport.c:1725" normal exit
corrupted double-linked list
[1]    20876 IOT instruction (core dumped)  ./shairport-sync --verbose --configfile=/home/nand/.config/shairport-sync.con

It looks as if there is an over-zealous attempt to clean up when play is paused or stopped, and some functions are attempting to free memory allocations already free'd. Could be causing your other problem too -- further investigation under way...

haasn commented 1 year ago

Curious, I ran shairport-sync through asan/ubsan:

rtsp.c:1084:17: runtime error: null pointer passed as argument 2, which is declared to never be null
/usr/include/string.h:44:28: note: nonnull attribute specified here
SUMMARY: UndefinedBehaviorSanitizer: undefined-behavior rtsp.c:1084:17 in 
metadata_hub.c:685:27: runtime error: null pointer passed as argument 1, which is declared to never be null
/usr/include/string.h:196:35: note: nonnull attribute specified here
SUMMARY: UndefinedBehaviorSanitizer: undefined-behavior metadata_hub.c:685:27 in 
         0.122335939 "audio_pw.c:120" pw: stream state changed paused -> streaming
         0.000040085 "audio_pw.c:123" pw: stream node 94
metadata_hub.c:386:27: runtime error: load of misaligned address 0x7f6e8861f88f for type 'uint32_t' (aka 'unsigned int'), which requires 4 byte alignment
0x7f6e8861f88f: note: pointer points here
 00 00 00 04 00  02 62 9c 00 9c 61 73 64  6b 00 00 00 01 00 63 61  70 73 00 00 00 01 01 61  73 74 6d
             ^ 
SUMMARY: UndefinedBehaviorSanitizer: undefined-behavior metadata_hub.c:386:27 in 
player.c:2393:25: runtime error: left shift of negative value -144
SUMMARY: UndefinedBehaviorSanitizer: undefined-behavior player.c:2393:25 in 
player.c:2394:25: runtime error: left shift of negative value -1908
SUMMARY: UndefinedBehaviorSanitizer: undefined-behavior player.c:2394:25 in 

And on exit:

=================================================================
==64674==ERROR: AddressSanitizer: attempting double-free on 0x611000000f40 in thread T0:
    #0 0x5646b120ba55 in __interceptor_free /home/abuild/rpmbuild/BUILD/llvm-16.0.6.src/projects/compiler-rt/lib/asan/asan_malloc_linux.cpp:52:3
    #1 0x7efeb56fbbf6 in pw_array_clear /usr/src/debug/pipewire-0.3.80/x86_64-suse-linux/../src/pipewire/array.h:80:2
    #2 0x7efeb56fbbf6 in pw_properties_free /usr/src/debug/pipewire-0.3.80/x86_64-suse-linux/../src/pipewire/properties.c:359:2
    #3 0x7efeb56fbbf6 in pw_properties_free /usr/src/debug/pipewire-0.3.80/x86_64-suse-linux/../src/pipewire/properties.c:350:6
    #4 0x5646b136203e in deinit audio_pw.c
    #5 0x5646b125db63 in exit_function (/home/nand/dev/shairport-sync/shairport-sync+0x1f7b63) (BuildId: 224d90f42fc32cd29317233f994f3dba043a6e92)
    #6 0x7efeb4a95b25 in __run_exit_handlers /usr/src/debug/glibc-2.38/stdlib/exit.c:111:8
    #7 0x7efeb4a95c6f in exit /usr/src/debug/glibc-2.38/stdlib/exit.c:141:3
    #8 0x5646b125e6a5 in intHandler (/home/nand/dev/shairport-sync/shairport-sync+0x1f86a5) (BuildId: 224d90f42fc32cd29317233f994f3dba043a6e92)
    #9 0x7efeb4a931af  (/lib64/libc.so.6+0x3f1af) (BuildId: 7729cbd8376d2b42276cc2cc10693449ff810847)
    #10 0x7efeb4ae050d in __futex_abstimed_wait_common64 /usr/src/debug/glibc-2.38/nptl/futex-internal.c:57:12
    #11 0x7efeb4ae050d in __futex_abstimed_wait_common /usr/src/debug/glibc-2.38/nptl/futex-internal.c:87:9
    #12 0x7efeb4ae5b82 in __pthread_clockjoin_ex /usr/src/debug/glibc-2.38/nptl/pthread_join_common.c:102:14
    #13 0x5646b12684c4 in main (/home/nand/dev/shairport-sync/shairport-sync+0x2024c4) (BuildId: 224d90f42fc32cd29317233f994f3dba043a6e92)
    #14 0x7efeb4a7c1af in __libc_start_call_main /usr/src/debug/glibc-2.38/csu/../sysdeps/nptl/libc_start_call_main.h:58:16
    #15 0x7efeb4a7c278 in __libc_start_main@GLIBC_2.2.5 /usr/src/debug/glibc-2.38/csu/../csu/libc-start.c:360:3
    #16 0x5646b116edc4 in _start /home/abuild/rpmbuild/BUILD/glibc-2.38/csu/../sysdeps/x86_64/start.S:115

0x611000000f40 is located 0 bytes inside of 256-byte region [0x611000000f40,0x611000001040)
freed by thread T0 here:
    #0 0x5646b120ba55 in __interceptor_free /home/abuild/rpmbuild/BUILD/llvm-16.0.6.src/projects/compiler-rt/lib/asan/asan_malloc_linux.cpp:52:3
    #1 0x7efeb56fbbf6 in pw_array_clear /usr/src/debug/pipewire-0.3.80/x86_64-suse-linux/../src/pipewire/array.h:80:2
    #2 0x7efeb56fbbf6 in pw_properties_free /usr/src/debug/pipewire-0.3.80/x86_64-suse-linux/../src/pipewire/properties.c:359:2
    #3 0x7efeb56fbbf6 in pw_properties_free /usr/src/debug/pipewire-0.3.80/x86_64-suse-linux/../src/pipewire/properties.c:350:6

previously allocated by thread T0 here:
    #0 0x5646b120c171 in __interceptor_realloc /home/abuild/rpmbuild/BUILD/llvm-16.0.6.src/projects/compiler-rt/lib/asan/asan_malloc_linux.cpp:85:3
    #1 0x7efeb56fb972 in pw_array_ensure_size /usr/src/debug/pipewire-0.3.80/x86_64-suse-linux/../src/pipewire/array.h:104:7
    #2 0x7efeb56fb972 in properties_new /usr/src/debug/pipewire-0.3.80/x86_64-suse-linux/../src/pipewire/properties.c:72:2
    #3 0x7efeb56fb972 in pw_properties_new /usr/src/debug/pipewire-0.3.80/x86_64-suse-linux/../src/pipewire/properties.c:90:9

SUMMARY: AddressSanitizer: double-free /home/abuild/rpmbuild/BUILD/llvm-16.0.6.src/projects/compiler-rt/lib/asan/asan_malloc_linux.cpp:52:3 in __interceptor_free
==64674==ABORTING

Unfortunately, no log output when it "hangs" on song transition.

Edit: I did get this error again one time when it happened...

metadata_hub.c:447:20: runtime error: null pointer passed as argument 1, which is declared to never be null
/usr/include/string.h:196:35: note: nonnull attribute specified here
SUMMARY: UndefinedBehaviorSanitizer: undefined-behavior metadata_hub.c:447:20 in 
mikebrady commented 1 year ago

Many thanks for this. I hadn't tried the Undefined Behaviour Sanitizer before!

The PipeWire backend memory errors are fixable, but unfortunately the architecture is unsuitable, and will have to be re-written.

I'll re-run to Undefined Behaviour Sanitizer with the ALSA backend and see what it reveals. Thanks again.

mikebrady commented 12 months ago

An update has been pushed to the development branch with a completely rewritten PipeWire backend, which should be a lot more useful and should also provide full synchronisation.

It has been tested both on an Ubuntu 23.04 VM and a physical machine running Fedora 38. Both systems have plain ordinary audio systems -- no fancy additions.

The backend works well. However, it logs many errors in pw-top on Fedora (PipeWire 0.3.80) and none on Ubuntu (PipeWire 0.3.58). Not sure if this is a problem with PipeWire itself as there are no apparent ill-effects. Errors accumulate when Shairport Sync is idle -- they seem to be associated with when it has no buffers of audio to supply.

If you got a chance to try it out and report back, it would be appreciated.

BTW, the PulseAudio backend got a little attention too, with some bug fixes and stability improvements.

haasn commented 12 months ago

It seems very good so far. I get some of this:

        21.148052967 "rtsp.c:2899" Connection 1: AP2 PTP connection from 109.192.222.233:49406 ("Supernova") to self at 192.168.0.20:7000.
       961.735181571 "player.c:2885" Large positive (i.e. late) sync error of 2956 frames (0.067029 seconds), at frame: 3710596646.
         0.255544586 "player.c:2910" Large negative (i.e. early) sync error of -3632 frames (-0.082358 seconds), at frame: 3710607910.
       130.234182960 "player.c:2885" Large positive (i.e. late) sync error of 2880 frames (0.065306 seconds), at frame: 3716349618.
         0.221941839 "player.c:2910" Large negative (i.e. early) sync error of -4519 frames (-0.102472 seconds), at frame: 3716360882.
       265.918252101 "player.c:2885" Large positive (i.e. late) sync error of 2747 frames (0.062290 seconds), at frame: 3070033583.
         0.249450979 "player.c:2910" Large negative (i.e. early) sync error of -5441 frames (-0.123379 seconds), at frame: 3070044847.
       410.641649207 "player.c:2885" Large positive (i.e. late) sync error of 3418 frames (0.077506 seconds), at frame: 3713200340.
         0.281662608 "player.c:2910" Large negative (i.e. early) sync error of -4434 frames (-0.100544 seconds), at frame: 3713212308.
       137.856502773 "player.c:2885" Large positive (i.e. late) sync error of 2953 frames (0.066961 seconds), at frame: 3719291225.
         0.233721487 "player.c:2910" Large negative (i.e. early) sync error of -4717 frames (-0.106961 seconds), at frame: 3719302489.
       365.182728598 "player.c:2885" Large positive (i.e. late) sync error of 2528 frames (0.057324 seconds), at frame: 3735407565.
         0.221755149 "player.c:2910" Large negative (i.e. early) sync error of -4614 frames (-0.104626 seconds), at frame: 3735418477.
       351.131461350 "player.c:2885" Large positive (i.e. late) sync error of 2381 frames (0.053991 seconds), at frame: 3750902520.
         0.233679337 "player.c:2910" Large negative (i.e. early) sync error of -4401 frames (-0.099796 seconds), at frame: 3750913432.

But it's very infrequent, and probably correlated with song changes. (I didn't pay attention too much)

mikebrady commented 12 months ago

Great -- thanks for the report. I think you're right about the song changes. If you enable statistics, you'll see how much interpolation it's doing -- the less the better. It's probably doing more after each song change and then settling down.

Nemo157 commented 12 months ago

I can confirm it's working well for me too. No errors appearing in pw-top (on NixOS 23.05 with pipewire 0.3.71).

mikebrady commented 12 months ago

Just pushed an update that stops those errors that were being reported on PipeWire 0.3.80. They were underruns ("xruns") and seemed entirely harmless. In any case, they are now gone.

github-actions[bot] commented 9 months ago

This issue has been inactive for 28 days so will be closed 7 days from now. To prevent this, please remove the "stale" label or post a comment.