search

mikebrady / shairport-sync

AirPlay and AirPlay 2 audio player
Other
7.29k stars 574 forks source link

Airfoil Windows frequent stuttering and sometimes sound speedups #650

Closed dheijl closed 6 years ago

dheijl commented 6 years ago

Hi,

Thanks for sharing this with us all!

This is with the latest development version of shairport-sync on Ubuntu 16.04 (pulse audio), and the latest Airfoil for Windows, on a WiFi network with excellent throughput but high latency (up to 150 msec, via a powerline WiFi adapter). The "official" version of shairport-sync is totally unusable on this network with Airfoil: every few seconds sound drops out for at least a second, so I gave up. No trouble at all streaming from Itunes from Windows or local Spotify or web-players. When I recently saw an Airfoil mention in the development branch comments history, I decided to give the development version a try. It's much better, the drop-outs only lasting a fraction of a second with an occasional longer lapse and (infrequently) the sound speeding up.

I had already considered forking the github repo to experiment with an asynchronous receive thread for the input stream in player.c in the hope that buffering the Airfoil stream independently from the player logic might fix the missed frames problem (replacing the current network receive logic with a simple get buffer call). Could this potentially fix the latency problem? I am not familiar with the airplay/rtp/rtsp protocols, so messing with that is beyond me I'm afraid.

Synchronization is not an issue for me here, it just has to play the stuff just like Itunes would do it (the Linux laptop is connected to a 2-speaker hifi system with a TOS-link).

The log of a session:


$ shairport-sync -vvv
Looking for configuration file at full path "/etc/shairport-sync.conf"
alsa output device name is "default".
The processor is running little-endian.
Version: "3.2d23-OpenSSL-Avahi-ALSA-pa-soxr-metadata-sysconfdir:/etc"
statistics_requester status is 0.
daemon status is 0.
deamon pid file is "/var/run/shairport-sync/shairport-sync.pid".
rtsp listening port is 5000.
udp base port is 6001.
udp port range is 100.
player name is "Danny-Amilo-Si-1520".
backend is "(null)".
on-start action is "(null)".
on-stop action is "(null)".
wait-cmd status is 0.
on-start returns output is 0.
mdns backend "(null)".
userSuppliedLatency is 0.
stuffing option is "0" (0-basic, 1-soxr).
resync time is 0.050000 seconds.
allow a session to be interrupted: 0.
busy timeout time is 120.
drift tolerance is 0.001995 seconds.
password is "(null)".
ignore_volume_control is 0.
volume_max_db is not set
playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
disable_synchronization is 0.
use_mmap_if_available is 1.
output_rate is 44100.
output_format is 3 (0-unknown, 1-S8, 2-U8, 3-S16, 4-S24, 5-S24_3LE, 6-S24_3BE, 7-S32).
audio backend desired buffer length is 0.150000 seconds.
audio backend latency offset is 0.000000 seconds.
audio backend silence lead-in time is -1.000000 seconds. A value -1.0 means use the default.
volume range in dB (zero means use the range specified by the mixer): 0.
zeroconf regtype is "_raop._tcp".
decoders_supported field is 1.
use_apple_decoder is 0.
alsa_use_playback_switch_for_mute is 0.
no special mdns service interface was requested.
configuration file name "/etc/shairport-sync.conf" resolves to "/etc/shairport-sync.conf".
metadata enabled is 0.
metadata pipename is "(null)".
metadata socket address is "(null)" port 0.
metadata socket packet size is "500".
get-coverart is 0.
loudness is 0.
loudness reference level is -20.000000
avahi: avahi_register.
avahi: register_service.
avahi: service '7C41F9D07FDF@Danny-Amilo-Si-1520' group is not yet committed.
avahi: request to add "_raop._tcp" service without metadata
avahi: service '7C41F9D07FDF@Danny-Amilo-Si-1520' group is registering.
avahi: service '7C41F9D07FDF@Danny-Amilo-Si-1520' successfully added.
New RTSP connection from 192.168.0.135:53570 to self at 192.168.0.240:5000 on conversation thread 0.
Successfully created RTSP receiver thread 0.
    Apple-Challenge: 2or9zhnPlT//ObjjC34ejw.
    CSeq: 1.
    User-Agent: iTunes/7.6.2 (Windows; N;).
    Client-Instance: 0030592255AEFE55.
    DACP-ID: 7EA0E19442127974.
    Client-instance-identifier: d81ea4b6-b389-4960-99ca-175a28be8892.
RTSP thread 0 received an RTSP Packet of type "OPTIONS":
  Type: "Apple-Challenge", content: "2or9zhnPlT//ObjjC34ejw"
  Type: "CSeq", content: "1"
  Type: "User-Agent", content: "iTunes/7.6.2 (Windows; N;)"
  Type: "Client-Instance", content: "0030592255AEFE55"
  Type: "DACP-ID", content: "7EA0E19442127974"
  Type: "Client-instance-identifier", content: "d81ea4b6-b389-4960-99ca-175a28be8892"
Connection 0: OPTIONS
RTSP thread 0: RTSP Response:
  Type: "Apple-Response", content: "B8bc5zAtW4DmXmI+CuAmUL030piJsiExJpvy20WpjqHBRGz4bUvEGtdJYYED7/GKCppAydpUPeadD8kTpjMprj/8PAXNAfO5xeDl6Jmas3rmjY8oOwS9zGx+TlD/pfRCMzYiUEDIdRQYgfqHwcRbNP3sTPdk+2RGrXoY2BhM9TQ8uF4fPD+gvsOyQBgBZZbf39TdEi1uXjtD+J/otUrod/BemPeUec5Haq9lxuqSZfY9P8oGE0JsfU/FxccrrrC0eahzUQDRHMnfcdUlTJNUkCrwe8wY8Ikf6s4rn8S9RZVFTCNSAVy+XYTfmK8D9+9NmTweuXMuU9z836QCivWkkQ"
  Type: "CSeq", content: "1"
  Type: "Server", content: "AirTunes/105.1"
  Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER"
    Apple-Challenge: FZt7Pa3KHFa3gjxeAgHkrA.
    CSeq: 2.
    User-Agent: iTunes/7.6.2 (Windows; N;).
    Client-Instance: 0030592255AEFE55.
    DACP-ID: 7EA0E19442127974.
    Client-instance-identifier: d81ea4b6-b389-4960-99ca-175a28be8892.
RTSP thread 0 received an RTSP Packet of type "OPTIONS":
  Type: "Apple-Challenge", content: "FZt7Pa3KHFa3gjxeAgHkrA"
  Type: "CSeq", content: "2"
  Type: "User-Agent", content: "iTunes/7.6.2 (Windows; N;)"
  Type: "Client-Instance", content: "0030592255AEFE55"
  Type: "DACP-ID", content: "7EA0E19442127974"
  Type: "Client-instance-identifier", content: "d81ea4b6-b389-4960-99ca-175a28be8892"
Connection 0: OPTIONS
RTSP thread 0: RTSP Response:
  Type: "Apple-Response", content: "u1rPueecGIKk4W9US/ePG7fc42SD97iuV5i3xSlb/EBSsjQnA+eJTcJ5Y0ayXVrtsFwrdWEy5gkE9KB1izykdWN7Srx3+yIuv03yOmLZBGYGBuhXfuQErfprxjQgJBPxxazRAVhPaR9hYqjnxdtKcCHMaoDwnN5a0gwuNxcrl5N1MlvRedznAT6wgWb7DyCiG4rhROOapxXGr8Sdb6Hfr0YMqRz9XOaf1At86qGUVtIeP2asVB5ebVwV/jBr3PJFOV5t4s2kDS2g9KiIaJa4bbwrM+0SkHMhtNZRTXO2jhiKlMoSmRfOEC87DkHDHYJIzVdNkv64bbH71LJ//m3bkg"
  Type: "CSeq", content: "2"
  Type: "Server", content: "AirTunes/105.1"
  Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER"
    Apple-Challenge: I8RrIR/aiv73i2AdwybtLg.
    CSeq: 3.
    User-Agent: iTunes/7.6.2 (Windows; N;).
    Client-Instance: 0030592255AEFE55.
    DACP-ID: 7EA0E19442127974.
    Client-instance-identifier: d81ea4b6-b389-4960-99ca-175a28be8892.
RTSP thread 0 received an RTSP Packet of type "OPTIONS":
  Type: "Apple-Challenge", content: "I8RrIR/aiv73i2AdwybtLg"
  Type: "CSeq", content: "3"
  Type: "User-Agent", content: "iTunes/7.6.2 (Windows; N;)"
  Type: "Client-Instance", content: "0030592255AEFE55"
  Type: "DACP-ID", content: "7EA0E19442127974"
  Type: "Client-instance-identifier", content: "d81ea4b6-b389-4960-99ca-175a28be8892"
Connection 0: OPTIONS
RTSP thread 0: RTSP Response:
  Type: "Apple-Response", content: "wgdv2hzPBeuFHFPHsozD9bjYNtiwbV9lCfljZL9K5EB3jN+NrJNzrqnrk4eoB6fueaT6qVRv6OM3fOPMKbSyA1j5jxbAvmy3y3OStHVMVFASTCTRd7738prmfYa04xkj7kOW8HXSFjjj0VfBrr81LHlcoYHjdp1SDtHNmFgJipJZgSOuaNCxy6BQPy1Jw+dx+D35oCueAWNLWcQmM2sqFMP+b5cuQAiy0Ez4FaDY6m/RUYTsh6vfHn+xi4u/cAnWdwxvBFl2ZgkmEIj3h77JB9yl2dR8jAZ9CdbUj+y6vndo29dx07gHgwoHcmdVi0bnbb4BmS8RboLmvkaNjrjdug"
  Type: "CSeq", content: "3"
  Type: "Server", content: "AirTunes/105.1"
  Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER"
    Client-computer-name: DANNY-PC.
    Content-Type: application/sdp.
    Content-Length: 574.
    CSeq: 4.
    User-Agent: iTunes/7.6.2 (Windows; N;).
    Client-Instance: 0030592255AEFE55.
    DACP-ID: 7EA0E19442127974.
    Client-instance-identifier: d81ea4b6-b389-4960-99ca-175a28be8892.
RTSP thread 0 received an RTSP Packet of type "ANNOUNCE":
  Type: "Client-computer-name", content: "DANNY-PC"
  Type: "Content-Type", content: "application/sdp"
  Type: "Content-Length", content: "574"
  Type: "CSeq", content: "4"
  Type: "User-Agent", content: "iTunes/7.6.2 (Windows; N;)"
  Type: "Client-Instance", content: "0030592255AEFE55"
  Type: "DACP-ID", content: "7EA0E19442127974"
  Type: "Client-instance-identifier", content: "d81ea4b6-b389-4960-99ca-175a28be8892"
Connection 0: ANNOUNCE
RTSP conversation thread 0 has acquired play lock.
Play connection from user agent "iTunes/7.6.2 (Windows; N;)" on RTSP conversation thread 0.
RTSP thread 0: RTSP Response:
  Type: "CSeq", content: "4"
  Type: "Server", content: "AirTunes/105.1"
    Transport: RTP/AVP/UDP;unicast;interleaved=0-1;mode=record;control_port=6002;timing_port=6003.
    CSeq: 5.
    User-Agent: iTunes/7.6.2 (Windows; N;).
    Client-Instance: 0030592255AEFE55.
    DACP-ID: 7EA0E19442127974.
    Client-instance-identifier: d81ea4b6-b389-4960-99ca-175a28be8892.
RTSP thread 0 received an RTSP Packet of type "SETUP":
  Type: "Transport", content: "RTP/AVP/UDP;unicast;interleaved=0-1;mode=record;control_port=6002;timing_port=6003"
  Type: "CSeq", content: "5"
  Type: "User-Agent", content: "iTunes/7.6.2 (Windows; N;)"
  Type: "Client-Instance", content: "0030592255AEFE55"
  Type: "DACP-ID", content: "7EA0E19442127974"
  Type: "Client-instance-identifier", content: "d81ea4b6-b389-4960-99ca-175a28be8892"
Connection 0: SETUP
DACP-ID string seen: "7EA0E19442127974".
rtp_setup: cport=6002 tport=6003.
Set up play connection from 192.168.0.135 to self at 192.168.0.240 on RTSP conversation thread 0.
listening for audio, control and timing on ports 6001, 6002, 6003.
RTSP thread 0: RTSP Response:
  Type: "CSeq", content: "5"
  Type: "Server", content: "AirTunes/105.1"
  Type: "Transport", content: "RTP/AVP/UDP;unicast;interleaved=0-1;mode=record;control_port=6002;timing_port=6003;server_port=6001"
  Type: "Session", content: "1"
No latency has (yet) been specified. Setting 99225 (2.25 seconds) frames as a default.
Output frame bytes is 4.
Audio receiver -- Server RTP thread starting.
Control receiver -- Server RTP thread starting.
Output bit depth is 16.
Dithering will be enabled because the output volume is being altered in software
Timing receiver -- Server RTP thread starting.
Timing sender thread starting.
Set initial volume to -18.000000.
    Range: npt=0-.
    RTP-Info: seq=2086;rtptime=0.
    CSeq: 6.
    User-Agent: iTunes/7.6.2 (Windows; N;).
    Client-Instance: 0030592255AEFE55.
    DACP-ID: 7EA0E19442127974.
    Client-instance-identifier: d81ea4b6-b389-4960-99ca-175a28be8892.
    Session: 1.
RTSP thread 0 received an RTSP Packet of type "RECORD":
  Type: "Range", content: "npt=0-"
  Type: "RTP-Info", content: "seq=2086;rtptime=0"
  Type: "CSeq", content: "6"
  Type: "User-Agent", content: "iTunes/7.6.2 (Windows; N;)"
  Type: "Client-Instance", content: "0030592255AEFE55"
  Type: "DACP-ID", content: "7EA0E19442127974"
  Type: "Client-instance-identifier", content: "d81ea4b6-b389-4960-99ca-175a28be8892"
  Type: "Session", content: "1"
Connection 0: RECORD
Flush requested up to 4294967295. It seems as if 0 is special.
RTSP thread 0: RTSP Response:
  Type: "CSeq", content: "6"
  Type: "Server", content: "AirTunes/105.1"
  Type: "Audio-Latency", content: "11025"
    Content-Type: text/parameters.
    Content-Length: 11.
    CSeq: 7.
    User-Agent: iTunes/7.6.2 (Windows; N;).
    Client-Instance: 0030592255AEFE55.
    DACP-ID: 7EA0E19442127974.
    Client-instance-identifier: d81ea4b6-b389-4960-99ca-175a28be8892.
    Session: 1.
RTSP thread 0 received an RTSP Packet of type "SET_PARAMETER":
  Type: "Content-Type", content: "text/parameters"
  Type: "Content-Length", content: "11"
  Type: "CSeq", content: "7"
  Type: "User-Agent", content: "iTunes/7.6.2 (Windows; N;)"
  Type: "Client-Instance", content: "0030592255AEFE55"
  Type: "DACP-ID", content: "7EA0E19442127974"
  Type: "Client-instance-identifier", content: "d81ea4b6-b389-4960-99ca-175a28be8892"
  Type: "Session", content: "1"
Connection 0: SET_PARAMETER
AirPlay request to set volume to: 0.000000.
RTSP thread 0: RTSP Response:
  Type: "CSeq", content: "7"
  Type: "Server", content: "AirTunes/105.1"
New latency: 88200, sync latency: 77175, minimum latency: 0, maximum latency: 0, fixed offset: 11025.
syncing to seqno 51970.
Hammerton Decoder used on encrypted audio.
Output written with RW
PCM handle name = 'default'
alsa device parameters:
  access type = RW_INTERLEAVED
  format = 'S16_LE' (Signed 16 bit Little Endian)
  subformat = 'STD' (Standard)
  number of channels = 2
  number of significant bits = 16
  rate = 44100 frames per second (precisely).
  precise (rational) rate = 0.000 frames per second (i.e. 0/1088784512).
  period_time = 23219 us (>).
  period_size = 1024 frames (precisely).
  buffer_time = 23777233 us (>).
  buffer_size = 1048576 frames (>).
  periods_per_buffer = 1024 (precisely).
    CSeq: 8.
    User-Agent: iTunes/7.6.2 (Windows; N;).
    Client-Instance: 0030592255AEFE55.
    DACP-ID: 7EA0E19442127974.
    Client-instance-identifier: d81ea4b6-b389-4960-99ca-175a28be8892.
    Session: 1.
RTSP thread 0 received an RTSP Packet of type "OPTIONS":
  Type: "CSeq", content: "8"
  Type: "User-Agent", content: "iTunes/7.6.2 (Windows; N;)"
  Type: "Client-Instance", content: "0030592255AEFE55"
  Type: "DACP-ID", content: "7EA0E19442127974"
  Type: "Client-instance-identifier", content: "d81ea4b6-b389-4960-99ca-175a28be8892"
  Type: "Session", content: "1"
Connection 0: OPTIONS
RTSP thread 0: RTSP Response:
  Type: "CSeq", content: "8"
  Type: "Server", content: "AirTunes/105.1"
  Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER"
requesting resend of 1 packets starting at 52729.
requesting resend of 1 packets starting at 52730.
requesting resend of 1 packets starting at 52731.
requesting resend of 1 packets starting at 52732.
requesting resend of 1 packets starting at 52733.
requesting resend of 1 packets starting at 52734.
    CSeq: 9.
    User-Agent: iTunes/7.6.2 (Windows; N;).
    Client-Instance: 0030592255AEFE55.
    DACP-ID: 7EA0E19442127974.
    Client-instance-identifier: d81ea4b6-b389-4960-99ca-175a28be8892.
    Session: 1.
RTSP thread 0 received an RTSP Packet of type "OPTIONS":
  Type: "CSeq", content: "9"
  Type: "User-Agent", content: "iTunes/7.6.2 (Windows; N;)"
  Type: "Client-Instance", content: "0030592255AEFE55"
  Type: "DACP-ID", content: "7EA0E19442127974"
  Type: "Client-instance-identifier", content: "d81ea4b6-b389-4960-99ca-175a28be8892"
  Type: "Session", content: "1"
Connection 0: OPTIONS
RTSP thread 0: RTSP Response:
  Type: "CSeq", content: "9"
  Type: "Server", content: "AirTunes/105.1"
  Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER"
requesting resend of 1 packets starting at 53324.
requesting resend of 1 packets starting at 53325.
requesting resend of 1 packets starting at 53326.
requesting resend of 1 packets starting at 53327.
requesting resend of 1 packets starting at 53328.
    CSeq: 10.
    User-Agent: iTunes/7.6.2 (Windows; N;).
    Client-Instance: 0030592255AEFE55.
    DACP-ID: 7EA0E19442127974.
    Client-instance-identifier: d81ea4b6-b389-4960-99ca-175a28be8892.
    Session: 1.
RTSP thread 0 received an RTSP Packet of type "OPTIONS":
  Type: "CSeq", content: "10"
  Type: "User-Agent", content: "iTunes/7.6.2 (Windows; N;)"
  Type: "Client-Instance", content: "0030592255AEFE55"
  Type: "DACP-ID", content: "7EA0E19442127974"
  Type: "Client-instance-identifier", content: "d81ea4b6-b389-4960-99ca-175a28be8892"
  Type: "Session", content: "1"
Connection 0: OPTIONS
RTSP thread 0: RTSP Response:
  Type: "CSeq", content: "10"
  Type: "Server", content: "AirTunes/105.1"
  Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER"
requesting resend of 1 packets starting at 53962.
requesting resend of 1 packets starting at 53963.
requesting resend of 1 packets starting at 53964.
    CSeq: 11.
    User-Agent: iTunes/7.6.2 (Windows; N;).
    Client-Instance: 0030592255AEFE55.
    DACP-ID: 7EA0E19442127974.
    Client-instance-identifier: d81ea4b6-b389-4960-99ca-175a28be8892.
    Session: 1.
RTSP thread 0 received an RTSP Packet of type "OPTIONS":
  Type: "CSeq", content: "11"
  Type: "User-Agent", content: "iTunes/7.6.2 (Windows; N;)"
  Type: "Client-Instance", content: "0030592255AEFE55"
  Type: "DACP-ID", content: "7EA0E19442127974"
  Type: "Client-instance-identifier", content: "d81ea4b6-b389-4960-99ca-175a28be8892"
  Type: "Session", content: "1"
Connection 0: OPTIONS
RTSP thread 0: RTSP Response:
  Type: "CSeq", content: "11"
  Type: "Server", content: "AirTunes/105.1"
  Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER"
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8029.0,    30346.4,   213074.0.
requesting resend of 1 packets starting at 54714.
requesting resend of 1 packets starting at 54715.
requesting resend of 1 packets starting at 54716.
requesting resend of 1 packets starting at 54717.
requesting resend of 1 packets starting at 54718.
requesting resend of 1 packets starting at 54719.
    CSeq: 12.
    User-Agent: iTunes/7.6.2 (Windows; N;).
    Client-Instance: 0030592255AEFE55.
    DACP-ID: 7EA0E19442127974.
    Client-instance-identifier: d81ea4b6-b389-4960-99ca-175a28be8892.
    Session: 1.
RTSP thread 0 received an RTSP Packet of type "OPTIONS":
  Type: "CSeq", content: "12"
  Type: "User-Agent", content: "iTunes/7.6.2 (Windows; N;)"
  Type: "Client-Instance", content: "0030592255AEFE55"
  Type: "DACP-ID", content: "7EA0E19442127974"
  Type: "Client-instance-identifier", content: "d81ea4b6-b389-4960-99ca-175a28be8892"
  Type: "Session", content: "1"
Connection 0: OPTIONS
RTSP thread 0: RTSP Response:
  Type: "CSeq", content: "12"
  Type: "Server", content: "AirTunes/105.1"
  Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER"
requesting resend of 1 packets starting at 55464.
requesting resend of 1 packets starting at 55465.
requesting resend of 1 packets starting at 55466.
requesting resend of 1 packets starting at 55467.
requesting resend of 1 packets starting at 55468.
    CSeq: 13.
    User-Agent: iTunes/7.6.2 (Windows; N;).
    Client-Instance: 0030592255AEFE55.
    DACP-ID: 7EA0E19442127974.
    Client-instance-identifier: d81ea4b6-b389-4960-99ca-175a28be8892.
    Session: 1.
RTSP thread 0 received an RTSP Packet of type "OPTIONS":
  Type: "CSeq", content: "13"
  Type: "User-Agent", content: "iTunes/7.6.2 (Windows; N;)"
  Type: "Client-Instance", content: "0030592255AEFE55"
  Type: "DACP-ID", content: "7EA0E19442127974"
  Type: "Client-instance-identifier", content: "d81ea4b6-b389-4960-99ca-175a28be8892"
  Type: "Session", content: "1"
Connection 0: OPTIONS
RTSP thread 0: RTSP Response:
  Type: "CSeq", content: "13"
  Type: "Server", content: "AirTunes/105.1"
  Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER"
requesting resend of 1 packets starting at 55864.
requesting resend of 1 packets starting at 55865.
requesting resend of 1 packets starting at 55866.
requesting resend of 1 packets starting at 55867.
requesting resend of 1 packets starting at 55868.
requesting resend of 1 packets starting at 55869.
    CSeq: 14.
    User-Agent: iTunes/7.6.2 (Windows; N;).
    Client-Instance: 0030592255AEFE55.
    DACP-ID: 7EA0E19442127974.
    Client-instance-identifier: d81ea4b6-b389-4960-99ca-175a28be8892.
    Session: 1.
RTSP thread 0 received an RTSP Packet of type "OPTIONS":
  Type: "CSeq", content: "14"
  Type: "User-Agent", content: "iTunes/7.6.2 (Windows; N;)"
  Type: "Client-Instance", content: "0030592255AEFE55"
  Type: "DACP-ID", content: "7EA0E19442127974"
  Type: "Client-instance-identifier", content: "d81ea4b6-b389-4960-99ca-175a28be8892"
  Type: "Session", content: "1"
Connection 0: OPTIONS
RTSP thread 0: RTSP Response:
  Type: "CSeq", content: "14"
  Type: "Server", content: "AirTunes/105.1"
  Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER"
requesting resend of 1 packets starting at 56466.
requesting resend of 1 packets starting at 56467.
requesting resend of 1 packets starting at 56468.
requesting resend of 1 packets starting at 56469.
requesting resend of 1 packets starting at 56470.
    CSeq: 15.
    User-Agent: iTunes/7.6.2 (Windows; N;).
    Client-Instance: 0030592255AEFE55.
    DACP-ID: 7EA0E19442127974.
    Client-instance-identifier: d81ea4b6-b389-4960-99ca-175a28be8892.
    Session: 1.
RTSP thread 0 received an RTSP Packet of type "OPTIONS":
  Type: "CSeq", content: "15"
  Type: "User-Agent", content: "iTunes/7.6.2 (Windows; N;)"
  Type: "Client-Instance", content: "0030592255AEFE55"
  Type: "DACP-ID", content: "7EA0E19442127974"
  Type: "Client-instance-identifier", content: "d81ea4b6-b389-4960-99ca-175a28be8892"
  Type: "Session", content: "1"
Connection 0: OPTIONS
RTSP thread 0: RTSP Response:
  Type: "CSeq", content: "15"
  Type: "Server", content: "AirTunes/105.1"
  Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER"
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8067.1,    30386.3,   201578.0.
requesting resend of 1 packets starting at 57345.
requesting resend of 1 packets starting at 57346.
requesting resend of 1 packets starting at 57347.
requesting resend of 1 packets starting at 57348.
requesting resend of 1 packets starting at 57349.
requesting resend of 1 packets starting at 57350.
    CSeq: 16.
    User-Agent: iTunes/7.6.2 (Windows; N;).
    Client-Instance: 0030592255AEFE55.
    DACP-ID: 7EA0E19442127974.
    Client-instance-identifier: d81ea4b6-b389-4960-99ca-175a28be8892.
    Session: 1.
RTSP thread 0 received an RTSP Packet of type "OPTIONS":
  Type: "CSeq", content: "16"
  Type: "User-Agent", content: "iTunes/7.6.2 (Windows; N;)"
  Type: "Client-Instance", content: "0030592255AEFE55"
  Type: "DACP-ID", content: "7EA0E19442127974"
  Type: "Client-instance-identifier", content: "d81ea4b6-b389-4960-99ca-175a28be8892"
  Type: "Session", content: "1"
Connection 0: OPTIONS
RTSP thread 0: RTSP Response:
  Type: "CSeq", content: "16"
  Type: "Server", content: "AirTunes/105.1"
  Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER"
requesting resend of 1 packets starting at 57773.
requesting resend of 1 packets starting at 57774.
requesting resend of 1 packets starting at 57775.
requesting resend of 1 packets starting at 57776.
    CSeq: 17.
    User-Agent: iTunes/7.6.2 (Windows; N;).
    Client-Instance: 0030592255AEFE55.
    DACP-ID: 7EA0E19442127974.
    Client-instance-identifier: d81ea4b6-b389-4960-99ca-175a28be8892.
    Session: 1.
RTSP thread 0 received an RTSP Packet of type "OPTIONS":
  Type: "CSeq", content: "17"
  Type: "User-Agent", content: "iTunes/7.6.2 (Windows; N;)"
  Type: "Client-Instance", content: "0030592255AEFE55"
  Type: "DACP-ID", content: "7EA0E19442127974"
  Type: "Client-instance-identifier", content: "d81ea4b6-b389-4960-99ca-175a28be8892"
  Type: "Session", content: "1"
Connection 0: OPTIONS
RTSP thread 0: RTSP Response:
  Type: "CSeq", content: "17"
  Type: "Server", content: "AirTunes/105.1"
  Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER"
requesting resend of 1 packets starting at 58376.
    CSeq: 18.
    User-Agent: iTunes/7.6.2 (Windows; N;).
    Client-Instance: 0030592255AEFE55.
    DACP-ID: 7EA0E19442127974.
    Client-instance-identifier: d81ea4b6-b389-4960-99ca-175a28be8892.
    Session: 1.
RTSP thread 0 received an RTSP Packet of type "OPTIONS":
  Type: "CSeq", content: "18"
  Type: "User-Agent", content: "iTunes/7.6.2 (Windows; N;)"
  Type: "Client-Instance", content: "0030592255AEFE55"
  Type: "DACP-ID", content: "7EA0E19442127974"
  Type: "Client-instance-identifier", content: "d81ea4b6-b389-4960-99ca-175a28be8892"
  Type: "Session", content: "1"
Connection 0: OPTIONS
RTSP thread 0: RTSP Response:
  Type: "CSeq", content: "18"
  Type: "Server", content: "AirTunes/105.1"
  Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER"
    CSeq: 19.
    User-Agent: iTunes/7.6.2 (Windows; N;).
    Client-Instance: 0030592255AEFE55.
    DACP-ID: 7EA0E19442127974.
    Client-instance-identifier: d81ea4b6-b389-4960-99ca-175a28be8892.
    Session: 1.
RTSP thread 0 received an RTSP Packet of type "OPTIONS":
  Type: "CSeq", content: "19"
  Type: "User-Agent", content: "iTunes/7.6.2 (Windows; N;)"
  Type: "Client-Instance", content: "0030592255AEFE55"
  Type: "DACP-ID", content: "7EA0E19442127974"
  Type: "Client-instance-identifier", content: "d81ea4b6-b389-4960-99ca-175a28be8892"
  Type: "Session", content: "1"
Connection 0: OPTIONS
RTSP thread 0: RTSP Response:
  Type: "CSeq", content: "19"
  Type: "Server", content: "AirTunes/105.1"
  Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER"
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8026.7,    30261.3,   213417.0.
requesting resend of 1 packets starting at 59437.
requesting resend of 1 packets starting at 59704.
requesting resend of 1 packets starting at 59705.
requesting resend of 1 packets starting at 59706.
requesting resend of 1 packets starting at 59707.
requesting resend of 1 packets starting at 59708.
requesting resend of 1 packets starting at 59709.
requesting resend of 1 packets starting at 59710.
    CSeq: 20.
    User-Agent: iTunes/7.6.2 (Windows; N;).
    Client-Instance: 0030592255AEFE55.
    DACP-ID: 7EA0E19442127974.
    Client-instance-identifier: d81ea4b6-b389-4960-99ca-175a28be8892.
    Session: 1.
RTSP thread 0 received an RTSP Packet of type "OPTIONS":
  Type: "CSeq", content: "20"
  Type: "User-Agent", content: "iTunes/7.6.2 (Windows; N;)"
  Type: "Client-Instance", content: "0030592255AEFE55"
  Type: "DACP-ID", content: "7EA0E19442127974"
  Type: "Client-instance-identifier", content: "d81ea4b6-b389-4960-99ca-175a28be8892"
  Type: "Session", content: "1"
Connection 0: OPTIONS
RTSP thread 0: RTSP Response:
  Type: "CSeq", content: "20"
  Type: "Server", content: "AirTunes/105.1"
  Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER"
    CSeq: 21.
    User-Agent: iTunes/7.6.2 (Windows; N;).
    Client-Instance: 0030592255AEFE55.
    DACP-ID: 7EA0E19442127974.
    Client-instance-identifier: d81ea4b6-b389-4960-99ca-175a28be8892.
    Session: 1.
RTSP thread 0 received an RTSP Packet of type "OPTIONS":
  Type: "CSeq", content: "21"
  Type: "User-Agent", content: "iTunes/7.6.2 (Windows; N;)"
  Type: "Client-Instance", content: "0030592255AEFE55"
  Type: "DACP-ID", content: "7EA0E19442127974"
  Type: "Client-instance-identifier", content: "d81ea4b6-b389-4960-99ca-175a28be8892"
  Type: "Session", content: "1"
Connection 0: OPTIONS
RTSP thread 0: RTSP Response:
  Type: "CSeq", content: "21"
  Type: "Server", content: "AirTunes/105.1"
  Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER"
    CSeq: 22.
    User-Agent: iTunes/7.6.2 (Windows; N;).
    Client-Instance: 0030592255AEFE55.
    DACP-ID: 7EA0E19442127974.
    Client-instance-identifier: d81ea4b6-b389-4960-99ca-175a28be8892.
    Session: 1.
RTSP thread 0 received an RTSP Packet of type "OPTIONS":
  Type: "CSeq", content: "22"
  Type: "User-Agent", content: "iTunes/7.6.2 (Windows; N;)"
  Type: "Client-Instance", content: "0030592255AEFE55"
  Type: "DACP-ID", content: "7EA0E19442127974"
  Type: "Client-instance-identifier", content: "d81ea4b6-b389-4960-99ca-175a28be8892"
  Type: "Session", content: "1"
Connection 0: OPTIONS
RTSP thread 0: RTSP Response:
  Type: "CSeq", content: "22"
  Type: "Server", content: "AirTunes/105.1"
  Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER"
requesting resend of 1 packets starting at 61255.
requesting resend of 1 packets starting at 61256.
requesting resend of 1 packets starting at 61257.
requesting resend of 1 packets starting at 61258.
requesting resend of 1 packets starting at 61259.
requesting resend of 1 packets starting at 61757.
requesting resend of 1 packets starting at 61758.
requesting resend of 1 packets starting at 61759.
requesting resend of 1 packets starting at 61760.
requesting resend of 1 packets starting at 61761.
requesting resend of 1 packets starting at 61762.
requesting resend of 1 packets starting at 61763.
requesting resend of 1 packets starting at 61764.
requesting resend of 1 packets starting at 61765.
requesting resend of 1 packets starting at 61766.
requesting resend of 1 packets starting at 61767.
requesting resend of 1 packets starting at 61768.
requesting resend of 1 packets starting at 61769.
requesting resend of 1 packets starting at 61770.
requesting resend of 1 packets starting at 61771.
requesting resend of 1 packets starting at 61772.
requesting resend of 1 packets starting at 61773.
requesting resend of 1 packets starting at 61774.
requesting resend of 1 packets starting at 61775.
requesting resend of 1 packets starting at 61776.
requesting resend of 1 packets starting at 61777.
requesting resend of 1 packets starting at 61778.
requesting resend of 1 packets starting at 61779.
requesting resend of 1 packets starting at 61780.
requesting resend of 1 packets starting at 61781.
requesting resend of 1 packets starting at 61782.
requesting resend of 1 packets starting at 61783.
requesting resend of 1 packets starting at 61784.
requesting resend of 1 packets starting at 61785.
requesting resend of 1 packets starting at 61786.
requesting resend of 1 packets starting at 61787.
requesting resend of 1 packets starting at 61788.
requesting resend of 1 packets starting at 61789.
requesting resend of 1 packets starting at 61790.
requesting resend of 1 packets starting at 61791.
requesting resend of 1 packets starting at 61792.
requesting resend of 1 packets starting at 61793.
requesting resend of 1 packets starting at 61794.
requesting resend of 1 packets starting at 61795.
requesting resend of 1 packets starting at 61796.
requesting resend of 1 packets starting at 61797.
requesting resend of 1 packets starting at 61798.
requesting resend of 1 packets starting at 61799.
requesting resend of 1 packets starting at 61800.
requesting resend of 1 packets starting at 61801.
requesting resend of 1 packets starting at 61802.
requesting resend of 1 packets starting at 61803.
requesting resend of 1 packets starting at 61804.
requesting resend of 1 packets starting at 61805.
requesting resend of 1 packets starting at 61806.
requesting resend of 1 packets starting at 61807.
requesting resend of 1 packets starting at 61808.
requesting resend of 1 packets starting at 61809.
requesting resend of 1 packets starting at 61810.
requesting resend of 1 packets starting at 61811.
requesting resend of 1 packets starting at 61812.
requesting resend of 1 packets starting at 61813.
requesting resend of 1 packets starting at 61814.
requesting resend of 1 packets starting at 61815.
requesting resend of 1 packets starting at 61816.
requesting resend of 1 packets starting at 61817.
requesting resend of 1 packets starting at 61818.
requesting resend of 1 packets starting at 61819.
requesting resend of 1 packets starting at 61820.
requesting resend of 1 packets starting at 61821.
requesting resend of 1 packets starting at 61822.
requesting resend of 1 packets starting at 61823.
requesting resend of 1 packets starting at 61824.
requesting resend of 1 packets starting at 61825.
requesting resend of 1 packets starting at 61826.
requesting resend of 1 packets starting at 61827.
requesting resend of 1 packets starting at 61828.
requesting resend of 1 packets starting at 61829.
requesting resend of 1 packets starting at 61830.
requesting resend of 1 packets starting at 61831.
requesting resend of 1 packets starting at 61832.
requesting resend of 1 packets starting at 61833.
requesting resend of 1 packets starting at 61834.
requesting resend of 1 packets starting at 61835.
requesting resend of 1 packets starting at 61836.
requesting resend of 1 packets starting at 61837.
requesting resend of 1 packets starting at 61838.
requesting resend of 1 packets starting at 61839.
requesting resend of 1 packets starting at 61840.
requesting resend of 1 packets starting at 61841.
requesting resend of 1 packets starting at 61842.
requesting resend of 1 packets starting at 61843.
requesting resend of 1 packets starting at 61844.
requesting resend of 1 packets starting at 61845.
requesting resend of 1 packets starting at 61846.
requesting resend of 1 packets starting at 61847.
requesting resend of 1 packets starting at 61848.
requesting resend of 1 packets starting at 61849.
requesting resend of 1 packets starting at 61850.
requesting resend of 1 packets starting at 61851.
requesting resend of 1 packets starting at 61852.
requesting resend of 1 packets starting at 61853.
requesting resend of 1 packets starting at 61854.
requesting resend of 1 packets starting at 61892.
requesting resend of 1 packets starting at 61893.
requesting resend of 1 packets starting at 61894.
requesting resend of 1 packets starting at 61895.
requesting resend of 1 packets starting at 61896.
requesting resend of 1 packets starting at 61897.
requesting resend of 1 packets starting at 61898.
requesting resend of 1 packets starting at 61899.
    CSeq: 23.
    User-Agent: iTunes/7.6.2 (Windows; N;).
    Client-Instance: 0030592255AEFE55.
    DACP-ID: 7EA0E19442127974.
    Client-instance-identifier: d81ea4b6-b389-4960-99ca-175a28be8892.
    Session: 1.
RTSP thread 0 received an RTSP Packet of type "OPTIONS":
  Type: "CSeq", content: "23"
  Type: "User-Agent", content: "iTunes/7.6.2 (Windows; N;)"
  Type: "Client-Instance", content: "0030592255AEFE55"
  Type: "DACP-ID", content: "7EA0E19442127974"
  Type: "Client-instance-identifier", content: "d81ea4b6-b389-4960-99ca-175a28be8892"
  Type: "Session", content: "1"
Connection 0: OPTIONS
RTSP thread 0: RTSP Response:
  Type: "CSeq", content: "23"
  Type: "Server", content: "AirTunes/105.1"
  Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER"
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8357.0,    44326.2,  1175888.0.
requesting resend of 1 packets starting at 62155.
requesting resend of 1 packets starting at 62156.
requesting resend of 1 packets starting at 62157.
requesting resend of 1 packets starting at 62158.
requesting resend of 1 packets starting at 62159.
^Cshutdown requested...
avahi: avahi_unregister.
Request to shut down all rtsp conversation threads
asking playing threads to stop
RTSP conversation thread 0 shutdown requested.
Synchronously terminate playing thread of RTSP conversation thread 0.

Danny

mikebrady commented 6 years ago

Thanks for the interesting post. Do you mean 150 milliseconds or 150 microseconds? If it's 150 milliseconds, that is a really long latency and I imagine it would drive the code that looks for missing packets crazy.

The input packets are already handled by a separate reception thread, so you wouldn't be adding any extra functionality, I'm afraid.

So, I have two ideas. The first is for you, if you'd be kind enough, to repeat your experiments but with the log verbosity turned down to 1 and with statistics enabled. The statistics will give an idea of the amount of packet loss, numbers of retries, etc.

The second idea is for me to modify the code to turn off requests for resends of missing packets. Paradoxically, it might improve things. If it does, then we can experiment with different resend-request parameters.

dheijl commented 6 years ago

Thanks for the quick response, and yes it's Milliseconds!

~$ ping 192.168.0.135
PING 192.168.0.135 (192.168.0.135) 56(84) bytes of data.
64 bytes from 192.168.0.135: icmp_seq=1 ttl=128 time=54.5 ms
64 bytes from 192.168.0.135: icmp_seq=2 ttl=128 time=77.6 ms
64 bytes from 192.168.0.135: icmp_seq=3 ttl=128 time=4.56 ms
64 bytes from 192.168.0.135: icmp_seq=4 ttl=128 time=123 ms
64 bytes from 192.168.0.135: icmp_seq=5 ttl=128 time=27.4 ms
64 bytes from 192.168.0.135: icmp_seq=6 ttl=128 time=4.52 ms
64 bytes from 192.168.0.135: icmp_seq=7 ttl=128 time=90.2 ms
64 bytes from 192.168.0.135: icmp_seq=8 ttl=128 time=26.3 ms
64 bytes from 192.168.0.135: icmp_seq=9 ttl=128 time=4.84 ms
64 bytes from 192.168.0.135: icmp_seq=10 ttl=128 time=161 ms
64 bytes from 192.168.0.135: icmp_seq=11 ttl=128 time=26.8 ms
64 bytes from 192.168.0.135: icmp_seq=12 ttl=128 time=2.79 ms
64 bytes from 192.168.0.135: icmp_seq=13 ttl=128 time=128 ms
64 bytes from 192.168.0.135: icmp_seq=14 ttl=128 time=22.2 ms
^C
--- 192.168.0.135 ping statistics ---
14 packets transmitted, 14 received, 0% packet loss, time 13013ms
rtt min/avg/max/mdev = 2.791/53.967/161.658/51.382 ms

I know that the receiving already happens in a separate thread, but it does quite some work before queueing the buffer for playing, and I thought that this could be the reason for the missed packets if Airfoil sends bursts of packets. So my idea was to buffer all packets in a seperate thread without any processing at all.

The log with statistics on:

~$ shairport-sync --statistics -v
alsa output device name is "default".
Version: "3.2d23-OpenSSL-Avahi-ALSA-pa-soxr-metadata-sysconfdir:/etc"
statistics_requester status is 1.
daemon status is 0.
deamon pid file is "/var/run/shairport-sync/shairport-sync.pid".
rtsp listening port is 5000.
udp base port is 6001.
udp port range is 100.
player name is "Danny-Amilo-Si-1520".
backend is "(null)".
on-start action is "(null)".
on-stop action is "(null)".
wait-cmd status is 0.
on-start returns output is 0.
mdns backend "(null)".
stuffing option is "0" (0-basic, 1-soxr).
resync time is 0.050000 seconds.
allow a session to be interrupted: 0.
busy timeout time is 120.
drift tolerance is 0.001995 seconds.
password is "(null)".
ignore_volume_control is 0.
volume_max_db is not set
playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
disable_synchronization is 0.
use_mmap_if_available is 1.
output_rate is 44100.
output_format is 3 (0-unknown, 1-S8, 2-U8, 3-S16, 4-S24, 5-S24_3LE, 6-S24_3BE, 7-S32).
audio backend desired buffer length is 0.150000 seconds.
audio backend latency offset is 0.000000 seconds.
audio backend silence lead-in time is -1.000000 seconds. A value -1.0 means use the default.
volume range in dB (zero means use the range specified by the mixer): 0.
zeroconf regtype is "_raop._tcp".
decoders_supported field is 1.
use_apple_decoder is 0.
alsa_use_playback_switch_for_mute is 0.
no special mdns service interface was requested.
configuration file name "/etc/shairport-sync.conf" resolves to "/etc/shairport-sync.conf".
metadata enabled is 0.
metadata pipename is "(null)".
metadata socket address is "(null)" port 0.
metadata socket packet size is "500".
get-coverart is 0.
loudness is 0.
loudness reference level is -20.000000
avahi: avahi_register.
avahi: register_service.
avahi: request to add "_raop._tcp" service without metadata
avahi: service '7C41F9D07FDF@Danny-Amilo-Si-1520' successfully added.
New RTSP connection from 192.168.0.135:55024 to self at 192.168.0.240:5000 on conversation thread 0.
Play connection from user agent "iTunes/7.6.2 (Windows; N;)" on RTSP conversation thread 0.
DACP-ID string seen: "490A9E71034E4782".
Set up play connection from 192.168.0.135 to self at 192.168.0.240 on RTSP conversation thread 0.
No latency has (yet) been specified. Setting 99225 (2.25 seconds) frames as a default.
Output frame bytes is 4.
Output bit depth is 16.
Dithering will be enabled because the output volume is being altered in software
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
Set initial volume to -18.000000.
New latency: 88200, sync latency: 77175, minimum latency: 0, maximum latency: 0, fixed offset: 11025.
Hammerton Decoder used on encrypted audio.
Output written with RW
      -1.0,     210.2,     286.1,        1003,     21,      0,      0,     35,   5660,  186,  232
      -1.1,    -133.1,    1957.2,        2006,     94,      0,      0,     94,   5483,  181,  232
       0.8,    -348.4,    1957.2,        3009,    103,      0,      0,    103,   5698,  204,  232
       0.7,    -521.2,    1404.9,        4012,    122,      0,      0,    122,   5677,  202,  232
       0.2,    -130.3,    1535.2,        5015,    146,      0,      0,    146,   5910,  202,  230
      -0.0,    -144.5,    1804.2,        6018,    160,      0,      0,    166,   5520,  201,  231
       0.2,     371.0,    1843.9,        7021,    166,      0,      0,    166,   5722,  207,  232
       0.0,    -283.2,    1693.8,        8024,    166,      0,      0,    166,   5758,  204,  232
      -0.5,     175.6,    1161.3,        9027,    172,      0,      0,    172,   5815,  184,  232
      -0.7,     150.1,    1107.5,       10030,    175,      0,      0,    213,   5798,  143,  231
       2.2,    -798.7,    2186.6,       11033,    214,      0,      0,    214,   5550,  204,  232
      -1.1,     121.8,    1883.6,       12036,    224,      0,      0,    224,   5693,  204,  231
^Cshutdown requested...
avahi: avahi_unregister.
Request to shut down all rtsp conversation threads
asking playing threads to stop
Playback Stopped. Total playing time 00:01:45.

Thanks for looking into this!

Danny

dheijl commented 6 years ago

Switching to an access point with a much weaker signal (and lower throughput) that is not on the powerline gives much better results for latency:

~$ ping 192.168.0.135
PING 192.168.0.135 (192.168.0.135) 56(84) bytes of data.
64 bytes from 192.168.0.135: icmp_seq=1 ttl=128 time=6.63 ms
64 bytes from 192.168.0.135: icmp_seq=2 ttl=128 time=1.70 ms
64 bytes from 192.168.0.135: icmp_seq=3 ttl=128 time=3.87 ms
64 bytes from 192.168.0.135: icmp_seq=4 ttl=128 time=1.73 ms
64 bytes from 192.168.0.135: icmp_seq=5 ttl=128 time=17.0 ms
64 bytes from 192.168.0.135: icmp_seq=6 ttl=128 time=1.67 ms
64 bytes from 192.168.0.135: icmp_seq=68 ttl=128 time=1.45 ms
64 bytes from 192.168.0.135: icmp_seq=69 ttl=128 time=1.43 ms
64 bytes from 192.168.0.135: icmp_seq=70 ttl=128 time=1.49 ms
64 bytes from 192.168.0.135: icmp_seq=71 ttl=128 time=1.84 ms
64 bytes from 192.168.0.135: icmp_seq=72 ttl=128 time=1.86 ms
64 bytes from 192.168.0.135: icmp_seq=73 ttl=128 time=1.59 ms
64 bytes from 192.168.0.135: icmp_seq=74 ttl=128 time=4.17 ms
...snip...
64 bytes from 192.168.0.135: icmp_seq=75 ttl=128 time=1.48 ms
64 bytes from 192.168.0.135: icmp_seq=76 ttl=128 time=1.84 ms
64 bytes from 192.168.0.135: icmp_seq=77 ttl=128 time=1.55 ms
64 bytes from 192.168.0.135: icmp_seq=78 ttl=128 time=1.94 ms
64 bytes from 192.168.0.135: icmp_seq=79 ttl=128 time=1.50 ms
^C
--- 192.168.0.135 ping statistics ---
79 packets transmitted, 79 received, 0% packet loss, time 78129ms
rtt min/avg/max/mdev = 1.093/4.105/91.615/11.002 ms

Statistics:

~$ shairport-sync --statistics 
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
      10.6,   -1019.5,    1019.5,        1003,      0,      0,      0,      0,   6142,  222,  232
       0.8,    -560.8,    1268.9,        2006,      0,      0,      0,      0,   5888,  223,  232
      -1.8,      17.0,    2617.1,        3009,      0,      0,      0,      0,   5466,  205,  233
      -2.6,     385.2,    2367.9,        4012,      0,      0,      0,      0,   5589,  207,  233
       1.9,    -827.1,    2152.6,        5015,      0,      0,      0,      0,   5669,  223,  232
      -1.2,     430.5,    1489.8,        6018,      0,      0,      0,      0,   5743,  223,  232
      -0.7,      96.3,    1971.4,        7021,      0,      0,      0,      0,   5633,  224,  233
       1.0,    -436.2,    2198.0,        8024,      0,      0,      0,      0,   5672,  223,  233
      -0.2,     -28.3,    2113.0,        9027,      0,      0,      0,      0,   5766,  223,  232
      -1.2,     444.7,    1079.1,       10030,      0,      0,      0,      0,   5671,  222,  233
       0.6,     209.6,    1960.0,       11033,      0,      0,      0,      0,   5744,  206,  233
       2.7,   -1288.7,    2195.1,       12036,      0,      0,      0,      0,   5892,  207,  232
      -2.0,     776.1,    1489.8,       13039,      0,      0,      0,      0,   5809,  223,  232
       0.9,     116.1,    2365.1,       14042,      0,      0,      0,      0,   5802,  223,  233
       1.8,   -1155.6,    2039.3,       15045,      2,      0,      0,      2,   5537,  222,  232
      -1.8,     770.4,    1501.2,       16048,      2,      0,      0,      2,   5532,  223,  233
      -0.2,     -48.2,    1560.7,       17051,      2,      0,      0,      2,   5627,  223,  233
       1.2,    -903.5,    2025.2,       18054,      2,      0,      0,      2,   5487,  223,  232
      -1.2,       8.5,    1345.4,       19057,      2,      0,      0,      2,   5370,  222,  232
      -1.9,     563.6,    1645.6,       20060,      2,      0,      0,      2,   5690,  222,  233
       0.4,    -161.4,    1311.4,       21063,      2,      0,      0,      2,   5941,  206,  232
       0.9,    -300.2,     934.7,       22066,      2,      0,      0,      2,   5976,  207,  231
      -2.6,    -175.6,    1965.7,       23069,      2,      0,      0,      2,   5433,  208,  233
      -0.7,      87.8,    1277.4,       24072,      2,      0,      0,      2,   5496,  222,  233
       2.2,    -167.1,    2030.8,       25075,      2,      0,      0,      2,   5805,  221,  232
      -0.7,    -410.7,    1849.6,       26078,      2,      0,      0,      2,   5441,  222,  233
      -0.6,     682.6,    2195.1,       27081,      2,      0,      0,      2,   5776,  223,  232
       0.9,    -912.0,    1484.2,       28084,      2,      0,      0,      2,   5652,  222,  232
      -0.7,     -93.5,    1407.7,       29087,      2,      0,      0,      2,   5516,  222,  232
      -2.7,     611.8,    1348.2,       30090,      2,      0,      0,      2,   5568,  223,  233
      -2.0,     444.7,    2002.5,       31093,      2,      0,      0,      2,   5383,  222,  234
       0.4,    -657.1,     946.0,       32096,      2,      0,      0,      2,   5999,  224,  232
       0.1,    -722.3,    1504.0,       33099,      2,      0,      0,      2,   5577,  222,  232
      -2.2,     399.4,    1928.9,       34102,      2,      0,      0,      2,   5512,  204,  233
      -0.9,      90.6,    2062.0,       35105,      2,      0,      0,      2,   5585,  206,  233
      -1.2,     662.8,    2237.6,       36108,      2,      0,      0,      2,   5743,  224,  233
       0.3,    -739.3,    1464.4,       37111,      2,      0,      0,      2,   5344,  223,  233
       1.4,    -339.9,    1133.0,       38114,      2,      0,      0,      2,   6010,  223,  232
^CPlayback Stopped. Total playing time 00:05:11.

So the WiFi latency seems to cause all the problems. I might still have a go at my idea of reading packets without any processing in a separate thread though, and if I succeed (it's been almost 20 years since I did anything in C/C++ and/or Linux/Unix) I will let you know if it changed anything!

Danny

dheijl commented 6 years ago

I think my idea wouldn't make any difference, I increased the default Linux UDP buffer size from 16KB to 25 MB and it didn't make any difference, so the missing packets are getting lost elsewhere... I'll use the low latency access point.

Thanks again.

Danny

mikebrady commented 6 years ago

Thanks. Just incidentally, the third column shows a lot of overcorrection going on. Is this a Linux running in a VM, by any chance?

dheijl commented 6 years ago

No, the Linux runs on the physical machine (Linux Lite, core duo 1,8 GHz, 2GB ram). I'm going to increase the drift tolerance as synchronization is not an issue.

mikebrady commented 6 years ago

Good idea.

dheijl commented 6 years ago

It looks like the latest version has solved the Airfoil Windows problems, until recently I still had "static" issues every few seconds (packet loss).

No more sync errors now, and no packet loss. Just the occasional late packet. Could be the resend request on the wrong channel fix.

Thanks for all the good work!

mikebrady commented 6 years ago

Thanks for the update – that's good news indeed.