mikebrady / shairport-sync

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

Playback choppy 2 #742

Closed abid76 closed 6 years ago

abid76 commented 6 years ago

Hi there,

first of all thanks a lot for your great commitment to this software :-)

I have shairport-sync running on a raspberry 3 with raspbian stretch installed.

I encounter small interruptions in playback ("choppiness") occasionally. I am also using a DCH-M225 which does also expose this issue but very seldom.

I read #346 and then tried increasing buffer using audio_backend_buffer_desired_length_in_seconds = 0.5; but nothing changed. Using disable_synchronization = "yes"; also didn't solve the problem.

Is there anything else I can do about it?

Here is the log output. Please let me know if there is any additional information which I can provide.

Sep 11 23:29:39 raspberrypi shairport-sync[15007]: alsa output device name is "hw:0".
Sep 11 23:29:39 raspberrypi shairport-sync[15007]: Lowest dB value is a mute
Sep 11 23:29:39 raspberrypi shairport-sync[15007]: Hardware mixer has dB volume from -102.380000 to 4.000000.
Sep 11 23:29:39 raspberrypi shairport-sync[15007]: The processor is running little-endian.
Sep 11 23:29:39 raspberrypi shairport-sync[15007]: Version: "3.2.1-OpenSSL-Avahi-ALSA-sysconfdir:/etc"
Sep 11 23:29:39 raspberrypi shairport-sync[15007]: statistics_requester status is 1.
Sep 11 23:29:39 raspberrypi shairport-sync[15007]: daemon status is 0.
Sep 11 23:29:39 raspberrypi shairport-sync[15007]: deamon pid file path is "/var/run/shairport-sync/shairport-sync.pid".
Sep 11 23:29:39 raspberrypi shairport-sync[15007]: rtsp listening port is 5000.
Sep 11 23:29:39 raspberrypi shairport-sync[15007]: udp base port is 6001.
Sep 11 23:29:39 raspberrypi shairport-sync[15007]: udp port range is 100.
Sep 11 23:29:39 raspberrypi shairport-sync[15007]: player name is "Raspberry".
Sep 11 23:29:39 raspberrypi shairport-sync[15007]: backend is "(null)".
Sep 11 23:29:39 raspberrypi shairport-sync[15007]: on-start action is "(null)".
Sep 11 23:29:39 raspberrypi shairport-sync[15007]: on-stop action is "(null)".
Sep 11 23:29:39 raspberrypi shairport-sync[15007]: wait-cmd status is 0.
Sep 11 23:29:39 raspberrypi shairport-sync[15007]: on-start returns output is 0.
Sep 11 23:29:39 raspberrypi shairport-sync[15007]: mdns backend "(null)".
Sep 11 23:29:39 raspberrypi shairport-sync[15007]: userSuppliedLatency is 0.
Sep 11 23:29:39 raspberrypi shairport-sync[15007]: stuffing option is "0" (0-basic, 1-soxr).
Sep 11 23:29:39 raspberrypi shairport-sync[15007]: resync time is 0.050000 seconds.
Sep 11 23:29:39 raspberrypi shairport-sync[15007]: allow a session to be interrupted: 0.
Sep 11 23:29:39 raspberrypi shairport-sync[15007]: busy timeout time is 120.
Sep 11 23:29:39 raspberrypi shairport-sync[15007]: drift tolerance is 0.001995 seconds.
Sep 11 23:29:39 raspberrypi shairport-sync[15007]: password is "(null)".
Sep 11 23:29:39 raspberrypi shairport-sync[15007]: ignore_volume_control is 0.
Sep 11 23:29:39 raspberrypi shairport-sync[15007]: volume_max_db is not set
Sep 11 23:29:39 raspberrypi shairport-sync[15007]: playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
Sep 11 23:29:39 raspberrypi shairport-sync[15007]: disable_synchronization is 1.
Sep 11 23:29:39 raspberrypi shairport-sync[15007]: use_mmap_if_available is 1.
Sep 11 23:29:39 raspberrypi shairport-sync[15007]: output_rate is 44100.
Sep 11 23:29:39 raspberrypi shairport-sync[15007]: output_format is 3 (0-unknown, 1-S8, 2-U8, 3-S16, 4-S24, 5-S24_3LE, 6-S24_3BE, 7-S32).
Sep 11 23:29:39 raspberrypi shairport-sync[15007]: audio backend desired buffer length is 0.500000 seconds.
Sep 11 23:29:39 raspberrypi shairport-sync[15007]: audio backend latency offset is 0.000000 seconds.
Sep 11 23:29:39 raspberrypi shairport-sync[15007]: audio backend silence lead-in time is -1.000000 seconds. A value -1.0 means use the default.
Sep 11 23:29:39 raspberrypi shairport-sync[15007]: volume range in dB (zero means use the range specified by the mixer): 30.
Sep 11 23:29:39 raspberrypi shairport-sync[15007]: zeroconf regtype is "_raop._tcp".
Sep 11 23:29:39 raspberrypi shairport-sync[15007]: decoders_supported field is 1.
Sep 11 23:29:39 raspberrypi shairport-sync[15007]: use_apple_decoder is 0.
Sep 11 23:29:39 raspberrypi shairport-sync[15007]: alsa_use_hardware_mute is 0.
Sep 11 23:29:39 raspberrypi shairport-sync[15007]: no special mdns service interface was requested.
Sep 11 23:29:39 raspberrypi shairport-sync[15007]: configuration file name "/etc/shairport-sync.conf" resolves to "/etc/shairport-sync.conf".
Sep 11 23:29:39 raspberrypi shairport-sync[15007]: loudness is 0.
Sep 11 23:29:39 raspberrypi shairport-sync[15007]: loudness reference level is -20.000000
Sep 11 23:29:39 raspberrypi shairport-sync[15007]: disable resend requests is off.
Sep 11 23:29:39 raspberrypi shairport-sync[15007]: diagnostic_drop_packet_fraction is 0.000000. A value of 0.0 means no packets will be dropped deliberately.
Sep 11 23:29:40 raspberrypi shairport-sync[15007]: avahi: service 'EA52914C53E5@Raspberry' group is not yet committed.
Sep 11 23:29:40 raspberrypi shairport-sync[15007]: avahi: request to add "_raop._tcp" service without metadata
Sep 11 23:29:40 raspberrypi shairport-sync[15007]: avahi: service 'EA52914C53E5@Raspberry' group is registering.
Sep 11 23:29:40 raspberrypi shairport-sync[15007]: avahi: service 'EA52914C53E5@Raspberry' successfully added.
Sep 11 23:29:47 raspberrypi shairport-sync[15007]: New RTSP connection from [2003:e9:6f0d:3332:c1e0:7d95:219:de9]:53332 to self at [2003:e9:6f0d:3332:a919:b3c1:b6fa:c5b1]:5000 on conversation thread 1.
Sep 11 23:29:51 raspberrypi shairport-sync[15007]: RTSP thread 1 received an RTSP Packet of type "ANNOUNCE":
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   Type: "Content-Length", content: "686"
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   Type: "Content-Type", content: "application/sdp"
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   Type: "CSeq", content: "3"
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   Type: "DACP-ID", content: "E1A2823C074BA83C"
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   Type: "Active-Remote", content: "602176656"
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   Type: "User-Agent", content: "AirPlay/366.74.2"
Sep 11 23:29:51 raspberrypi shairport-sync[15007]: Connection 1: ANNOUNCE
Sep 11 23:29:51 raspberrypi shairport-sync[15007]: Play connection from user agent "AirPlay/366.74.2" on RTSP conversation thread 1.
Sep 11 23:29:51 raspberrypi shairport-sync[15007]: AirPlay version 366 detected.
Sep 11 23:29:51 raspberrypi shairport-sync[15007]: RTSP thread 1: RTSP Response:
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   Type: "CSeq", content: "3"
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   Type: "Server", content: "AirTunes/105.1"
Sep 11 23:29:51 raspberrypi shairport-sync[15007]: RTSP thread 1 received an RTSP Packet of type "SETUP":
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   Type: "Transport", content: "RTP/AVP/UDP;unicast;mode=record;timing_port=50019;control_port=63264"
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   Type: "CSeq", content: "4"
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   Type: "DACP-ID", content: "E1A2823C074BA83C"
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   Type: "Active-Remote", content: "602176656"
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   Type: "User-Agent", content: "AirPlay/366.74.2"
Sep 11 23:29:51 raspberrypi shairport-sync[15007]: Connection 1: SETUP -- Active-Remote string seen: "602176656".
Sep 11 23:29:51 raspberrypi shairport-sync[15007]: Connection 1: SETUP -- DACP-ID string seen: "E1A2823C074BA83C".
Sep 11 23:29:51 raspberrypi shairport-sync[15007]: Connection 1: SETUP -- Connection from 2003:e9:6f0d:3332:c1e0:7d95:219:de9 to self at 2003:e9:6f0d:3332:a919:b3c1:b6fa:c5b1.
Sep 11 23:29:51 raspberrypi shairport-sync[15007]: RTSP thread 1: RTSP Response:
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   Type: "CSeq", content: "4"
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   Type: "Server", content: "AirTunes/105.1"
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   Type: "Transport", content: "RTP/AVP/UDP;unicast;interleaved=0-1;mode=record;control_port=6001;timing_port=6002;server_port=6003"
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   Type: "Session", content: "1"
Sep 11 23:29:51 raspberrypi shairport-sync[15007]: RTSP thread 1 received an RTSP Packet of type "RECORD":
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   Type: "CSeq", content: "5"
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   Type: "DACP-ID", content: "E1A2823C074BA83C"
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   Type: "Active-Remote", content: "602176656"
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   Type: "User-Agent", content: "AirPlay/366.74.2"
Sep 11 23:29:51 raspberrypi shairport-sync[15007]: Connection 1: RECORD
Sep 11 23:29:51 raspberrypi shairport-sync[15007]: RTSP thread 1: RTSP Response:
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   Type: "CSeq", content: "5"
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   Type: "Server", content: "AirTunes/105.1"
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   Type: "Audio-Latency", content: "11025"
Sep 11 23:29:51 raspberrypi shairport-sync[15007]: RTSP thread 1 received an RTSP Packet of type "SET_PARAMETER":
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   Type: "Content-Length", content: "20"
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   Type: "Content-Type", content: "text/parameters"
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   Type: "CSeq", content: "6"
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   Type: "DACP-ID", content: "E1A2823C074BA83C"
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   Type: "Active-Remote", content: "602176656"
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   Type: "User-Agent", content: "AirPlay/366.74.2"
Sep 11 23:29:51 raspberrypi shairport-sync[15007]: RTSP thread 1: RTSP Response:
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   Type: "CSeq", content: "6"
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   Type: "Server", content: "AirTunes/105.1"
Sep 11 23:29:51 raspberrypi shairport-sync[15007]: sync error in milliseconds, total packets, missing packets, late packets, too late packets, resend requests, min DAC queue size, min buffer occupancy, max buffer occupancy
Sep 11 23:29:51 raspberrypi shairport-sync[15007]: RTSP thread 1 received an RTSP Packet of type "SET_PARAMETER":
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   Type: "Content-Length", content: "20"
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   Type: "Content-Type", content: "text/parameters"
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   Type: "CSeq", content: "7"
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   Type: "DACP-ID", content: "E1A2823C074BA83C"
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   Type: "Active-Remote", content: "602176656"
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   Type: "User-Agent", content: "AirPlay/366.74.2"
Sep 11 23:29:51 raspberrypi shairport-sync[15007]: RTSP thread 1: RTSP Response:
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   Type: "CSeq", content: "7"
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   Type: "Server", content: "AirTunes/105.1"
Sep 11 23:29:51 raspberrypi shairport-sync[15007]: RTSP thread 1 received an RTSP Packet of type "FLUSH":
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   Type: "RTP-Info", content: "seq=2462;rtptime=149872627"
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   Type: "CSeq", content: "8"
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   Type: "DACP-ID", content: "E1A2823C074BA83C"
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   Type: "Active-Remote", content: "602176656"
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   Type: "User-Agent", content: "AirPlay/366.74.2"
Sep 11 23:29:51 raspberrypi shairport-sync[15007]: RTSP thread 1: RTSP Response:
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   Type: "CSeq", content: "8"
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   Type: "Server", content: "AirTunes/105.1"
Sep 11 23:29:51 raspberrypi shairport-sync[15007]: Resend interval for latency of 88200 frames is 31 frames.
Sep 11 23:29:51 raspberrypi shairport-sync[15007]: Hammerton Decoder used on encrypted audio.
Sep 11 23:29:51 raspberrypi shairport-sync[15007]: PCM handle name = 'hw:0'
Sep 11 23:29:51 raspberrypi shairport-sync[15007]: alsa device parameters:
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   access type = MMAP_INTERLEAVED
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   format = 'S16_LE' (Signed 16 bit Little Endian)
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   subformat = 'STD' (Standard)
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   number of channels = 2
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   number of significant bits = 16
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   rate = 44100 frames per second (precisely).
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   precise (rational) rate = 0.000 frames per second (i.e. 0/1088784512).
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   period_time = 5804 us (>).
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   period_size = 256 frames (precisely).
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   buffer_time = 743038 us (>).
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   buffer_size = 32768 frames (>).
Sep 11 23:29:51 raspberrypi shairport-sync[15007]:   periods_per_buffer = 128 (precisely).
Sep 11 23:29:51 raspberrypi shairport-sync[15007]: waiting for a mutex, maximum expected time of 30000 microseconds exceeded "player.c:495".
Sep 11 23:29:53 raspberrypi shairport-sync[15007]: debug_mutex_lock at "player.c:495" expected max wait: 0.030000000, actual wait: 1.321096696 sec.
Sep 11 23:29:56 raspberrypi sudo[15024]:       pi : TTY=pts/0 ; PWD=/home/pi ; USER=root ; COMMAND=/bin/journalctl -f -n 100
Sep 11 23:29:56 raspberrypi sudo[15024]: pam_unix(sudo:session): session opened for user root by pi(uid=0)
Sep 11 23:30:01 raspberrypi shairport-sync[15007]:        0.0,        1003,      0,     64,      0,     64,  171,  186
Sep 11 23:30:09 raspberrypi shairport-sync[15007]:        0.0,        2006,    108,    190,      0,    190,    0,  186
Sep 11 23:30:14 raspberrypi shairport-sync[15007]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8940.0,    50356.5,  2038906.0.
Sep 11 23:30:17 raspberrypi shairport-sync[15007]:        0.0,        3009,    108,    195,      0,    195,  175,  186
Sep 11 23:30:25 raspberrypi shairport-sync[15007]:        0.0,        4012,    108,    195,      0,    195,  177,  186
Sep 11 23:30:33 raspberrypi shairport-sync[15007]:        0.0,        5015,    108,    196,      0,    196,  178,  186
Sep 11 23:30:34 raspberrypi shairport-sync[15007]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7992.4,    11947.0,    58443.0.
Sep 11 23:30:41 raspberrypi shairport-sync[15007]:        0.0,        6018,    108,    198,      0,    198,  178,  186
Sep 11 23:30:49 raspberrypi shairport-sync[15007]:        0.0,        7021,    108,    199,      0,    199,  178,  186
Sep 11 23:30:54 raspberrypi shairport-sync[15007]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7993.5,    12072.9,    59656.0.
Sep 11 23:30:57 raspberrypi shairport-sync[15007]:        0.0,        8024,    108,    203,      0,    203,  178,  186
Sep 11 23:31:05 raspberrypi shairport-sync[15007]:        0.0,        9027,    108,    217,      0,    217,  163,  186
Sep 11 23:31:13 raspberrypi shairport-sync[15007]:        0.0,       10030,    108,    249,      0,    250,  175,  186
mikebrady commented 6 years ago

Thanks for the report. Could you turn sync on again and give us a longer run of those stats and packet reception figures please?

abid76 commented 6 years ago

"Unfortunately" since my last post there has been almost no interruptions. Exception: when I picked up the device (iPhone 6s) in my hands (which was lying on the floor) there was a short interruption. At about this time the log said Sep 12 20:31:11 raspberrypi shairport-sync[31694]: Time ping turnaround time: 342883 us -- it looks like a timing ping was lost. (see below).

Here's the output:

Sep 12 20:24:56 raspberrypi shairport-sync[31694]:       -0.2,       0.0,       0.0,        1003,      0,      0,      0,      0,   7700,  170,  225
Sep 12 20:25:04 raspberrypi shairport-sync[31694]:        0.1,       0.0,       0.0,        2006,      0,      0,      0,      0,  21572,  170,  187
Sep 12 20:25:05 raspberrypi shairport-sync[31694]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7985.1,    16589.2,   138251.0.
Sep 12 20:25:12 raspberrypi shairport-sync[31694]:        0.2,       0.0,       0.0,        3009,      0,      0,      0,      0,  21583,  178,  187
Sep 12 20:25:20 raspberrypi shairport-sync[31694]:        0.3,       0.0,       0.0,        4012,      0,      1,      0,      1,  21583,  178,  187
Sep 12 20:25:25 raspberrypi shairport-sync[31694]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7989.2,    12172.0,    71296.0.
Sep 12 20:25:28 raspberrypi shairport-sync[31694]:        0.3,       0.0,       0.0,        5015,      0,      2,      0,      2,  21586,  179,  187
Sep 12 20:25:36 raspberrypi shairport-sync[31694]:        0.6,       0.0,       0.0,        6018,      0,      2,      0,      2,  21602,  166,  187
Sep 12 20:25:44 raspberrypi shairport-sync[31694]:        0.7,       0.0,       0.0,        7021,      0,     26,      0,     26,  21604,  160,  187
Sep 12 20:25:45 raspberrypi shairport-sync[31694]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8056.2,    12710.6,   197095.0.
Sep 12 20:25:52 raspberrypi shairport-sync[31694]:        0.4,       0.0,       0.0,        8024,      0,     26,      0,     26,  21591,  179,  187
Sep 12 20:26:00 raspberrypi shairport-sync[31694]:        0.3,       0.0,       0.0,        9027,      0,     28,      0,     28,  21558,  179,  187
Sep 12 20:26:05 raspberrypi shairport-sync[31694]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7999.4,    12918.7,   149477.0.
Sep 12 20:26:08 raspberrypi shairport-sync[31694]:        0.3,       0.0,       0.0,       10030,      0,     30,      0,     30,  21587,  167,  187
Sep 12 20:26:16 raspberrypi shairport-sync[31694]:        0.2,      -5.7,       5.7,       11033,      0,     32,      0,     32,  21531,  177,  187
Sep 12 20:26:24 raspberrypi shairport-sync[31694]:        0.1,       0.0,       0.0,       12036,      0,     33,      0,     33,  21561,  179,  187
Sep 12 20:26:25 raspberrypi shairport-sync[31694]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7989.8,    11934.9,    63754.0.
Sep 12 20:26:32 raspberrypi shairport-sync[31694]:        0.2,       0.0,       0.0,       13039,      0,     42,      0,     42,  21581,  179,  187
Sep 12 20:26:40 raspberrypi shairport-sync[31694]:        0.4,       0.0,       0.0,       14042,      0,     44,      0,     44,  21594,  170,  187
Sep 12 20:26:45 raspberrypi shairport-sync[31694]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8016.8,    12350.5,   100577.0.
Sep 12 20:26:48 raspberrypi shairport-sync[31694]:        0.3,       0.0,       0.0,       15045,      0,     44,      0,     44,  21572,  179,  187
Sep 12 20:26:56 raspberrypi shairport-sync[31694]:       -0.1,       0.0,       0.0,       16048,      0,     44,      0,     44,  21569,  178,  187
Sep 12 20:27:04 raspberrypi shairport-sync[31694]:       -0.2,       0.0,       0.0,       17051,      0,     45,      0,     45,  21562,  169,  187
Sep 12 20:27:05 raspberrypi shairport-sync[31694]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7988.4,    13011.6,   144508.0.
Sep 12 20:27:12 raspberrypi shairport-sync[31694]:       -0.3,       0.0,       0.0,       18054,      0,     47,      0,     47,  21557,  177,  188
Sep 12 20:27:20 raspberrypi shairport-sync[31694]:       -0.2,       0.0,       0.0,       19057,      0,     47,      0,     47,  21561,  178,  187
Sep 12 20:27:25 raspberrypi shairport-sync[31694]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7978.9,    12106.8,    71313.0.
Sep 12 20:27:28 raspberrypi shairport-sync[31694]:       -0.8,       2.8,       2.8,       20060,      0,     48,      0,     48,  21253,  176,  187
Sep 12 20:27:36 raspberrypi shairport-sync[31694]:       -0.4,       0.0,       0.0,       21063,      0,     48,      0,     48,  21559,  181,  202
Sep 12 20:27:44 raspberrypi shairport-sync[31694]:       -0.4,       0.0,       0.0,       22066,      0,     49,      0,     49,  21554,  183,  202
Sep 12 20:27:45 raspberrypi shairport-sync[31694]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7943.2,    18066.8,   153501.0.
Sep 12 20:27:52 raspberrypi shairport-sync[31694]:       -0.5,       0.0,       0.0,       23069,      0,     51,      0,     51,  21536,  187,  202
Sep 12 20:28:00 raspberrypi shairport-sync[31694]:       -0.5,       2.8,       2.8,       24072,      0,     54,      0,     54,  21559,  187,  202
Sep 12 20:28:05 raspberrypi shairport-sync[31694]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8019.1,    19548.1,   125887.0.
Sep 12 20:28:08 raspberrypi shairport-sync[31694]:       -0.3,       0.0,       0.0,       25075,      0,     58,      0,     58,  21368,  179,  202
Sep 12 20:28:16 raspberrypi shairport-sync[31694]:        0.4,       0.0,       0.0,       26078,      0,     58,      0,     58,  21575,  189,  202
Sep 12 20:28:24 raspberrypi shairport-sync[31694]:        1.0,       0.0,       0.0,       27081,      0,     58,      0,     58,  21544,  188,  202
Sep 12 20:28:25 raspberrypi shairport-sync[31694]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7990.8,    19330.5,   154382.0.
Sep 12 20:28:32 raspberrypi shairport-sync[31694]:       -0.7,       0.0,       0.0,       28084,      0,     58,      0,     58,  21545,  189,  202
Sep 12 20:28:40 raspberrypi shairport-sync[31694]:       -0.7,       0.0,       0.0,       29087,      0,     58,      0,     58,  21545,  187,  202
Sep 12 20:28:45 raspberrypi shairport-sync[31694]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7981.4,    19319.3,   121182.0.
Sep 12 20:28:48 raspberrypi shairport-sync[31694]:       -0.5,       0.0,       0.0,       30090,      0,     58,      0,     58,  21541,  188,  202
Sep 12 20:28:56 raspberrypi shairport-sync[31694]:        0.3,       0.0,       0.0,       31093,      0,     59,      0,     59,  21590,  187,  201
Sep 12 20:29:04 raspberrypi shairport-sync[31694]:        0.4,       0.0,       0.0,       32096,      0,     60,      0,     60,  21587,  179,  201
Sep 12 20:29:05 raspberrypi shairport-sync[31694]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7989.0,    19744.3,   164753.0.
Sep 12 20:29:12 raspberrypi shairport-sync[31694]:       -0.2,       0.0,       0.0,       33099,      0,     60,      0,     60,  21543,  186,  202
Sep 12 20:29:20 raspberrypi shairport-sync[31694]:       -0.0,       0.0,       0.0,       34102,      0,     61,      0,     61,  21567,  189,  202
Sep 12 20:29:25 raspberrypi shairport-sync[31694]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7993.4,    19244.6,   121355.0.
Sep 12 20:29:28 raspberrypi shairport-sync[31694]:       -0.0,       0.0,       0.0,       35105,      0,     61,      0,     61,  21527,  187,  202
Sep 12 20:29:36 raspberrypi shairport-sync[31694]:       -0.9,       0.0,       0.0,       36108,      0,     61,      0,     61,  21532,  189,  203
Sep 12 20:29:44 raspberrypi shairport-sync[31694]:       -0.9,       0.0,       0.0,       37111,      0,     61,      0,     61,  21534,  189,  202
Sep 12 20:29:44 raspberrypi shairport-sync[31694]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7976.6,    19250.2,    98368.0.
Sep 12 20:29:52 raspberrypi shairport-sync[31694]:       -1.0,       0.0,       0.0,       38114,      0,     61,      0,     61,  21533,  182,  203
Sep 12 20:30:00 raspberrypi shairport-sync[31694]:       -0.7,       0.0,       0.0,       39117,      0,     64,      0,     64,  21524,  185,  202
Sep 12 20:30:05 raspberrypi shairport-sync[31694]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8036.3,    19915.8,   157054.0.
Sep 12 20:30:08 raspberrypi shairport-sync[31694]:       -1.0,       0.0,       0.0,       40120,      0,     64,      0,     64,  21528,  171,  204
Sep 12 20:30:16 raspberrypi shairport-sync[31694]:       -0.9,       0.0,       0.0,       41123,      0,     64,      0,     64,  21536,  180,  187
Sep 12 20:30:24 raspberrypi shairport-sync[31694]:       -0.5,       0.0,       0.0,       42126,      0,     64,      0,     64,  21533,  180,  187
Sep 12 20:30:25 raspberrypi shairport-sync[31694]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7981.3,    12073.3,   112068.0.
Sep 12 20:30:32 raspberrypi shairport-sync[31694]:       -1.0,       0.0,       0.0,       43129,      0,     64,      0,     64,  21529,  178,  187
Sep 12 20:30:40 raspberrypi shairport-sync[31694]:       -1.0,       0.0,       0.0,       44132,      0,     64,      0,     64,  21528,  180,  187
Sep 12 20:30:45 raspberrypi shairport-sync[31694]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7992.3,    12039.0,    61592.0.
Sep 12 20:30:48 raspberrypi shairport-sync[31694]:       -1.0,       0.0,       0.0,       45135,      0,     66,      0,     66,  21507,  179,  187
Sep 12 20:30:56 raspberrypi shairport-sync[31694]:       -1.4,       0.0,       0.0,       46138,      0,     67,      0,     67,  21507,  173,  187
Sep 12 20:31:04 raspberrypi shairport-sync[31694]:       -1.2,       0.0,       0.0,       47141,      0,     85,      0,     85,  21521,  167,  187
Sep 12 20:31:05 raspberrypi shairport-sync[31694]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8037.8,    13230.4,   143115.0.
Sep 12 20:31:11 raspberrypi shairport-sync[31694]: Time ping turnaround time: 342883 us -- it looks like a timing ping was lost.
Sep 12 20:31:12 raspberrypi shairport-sync[31694]:       -1.2,       0.0,       0.0,       48144,      0,     97,      0,     97,  21523,  105,  187
Sep 12 20:31:20 raspberrypi shairport-sync[31694]:       -1.2,       0.0,       0.0,       49147,      0,    105,      0,    105,  21520,  153,  187
Sep 12 20:31:25 raspberrypi shairport-sync[31694]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8063.2,    22542.4,   617921.0.
Sep 12 20:31:28 raspberrypi shairport-sync[31694]:       -1.3,       0.0,       0.0,       50150,      0,    109,      0,    109,  21509,  167,  187
Sep 12 20:31:36 raspberrypi shairport-sync[31694]:       -1.3,       0.0,       0.0,       51153,      0,    119,      0,    119,  21517,  156,  187
Sep 12 20:31:44 raspberrypi shairport-sync[31694]:       -1.3,       0.0,       0.0,       52156,      0,    120,      0,    120,  21509,  170,  187
Sep 12 20:31:45 raspberrypi shairport-sync[31694]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8015.6,    17396.2,   220009.0.
Sep 12 20:31:52 raspberrypi shairport-sync[31694]:       -1.3,       0.0,       0.0,       53159,      0,    122,      0,    122,  21497,  154,  187
Sep 12 20:32:00 raspberrypi shairport-sync[31694]:       -1.3,       0.0,       0.0,       54162,      0,    122,      0,    122,  21515,  158,  187
Sep 12 20:32:05 raspberrypi shairport-sync[31694]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7981.3,    21468.8,   254930.0.
Sep 12 20:32:08 raspberrypi shairport-sync[31694]:       -0.7,       0.0,       0.0,       55165,      0,    122,      0,    122,  21220,  160,  187
abid76 commented 6 years ago

UPDATE: I again encounterd a short interruption. Again you see the log message: Sep 12 20:38:51 raspberrypi shairport-sync[31694]: Time ping turnaround time: 1196800 us -- it looks like a timing ping was lost.

Log output:

Sep 12 20:35:28 raspberrypi shairport-sync[31694]:       -0.2,       0.0,       0.0,       80240,      0,    150,      0,    150,  21569,  177,  187
Sep 12 20:35:36 raspberrypi shairport-sync[31694]:       -0.7,       0.0,       0.0,       81243,      0,    152,      0,    152,  21526,  179,  187
Sep 12 20:35:44 raspberrypi shairport-sync[31694]:       -1.8,     206.8,     206.8,       82246,      0,    152,      0,    152,  21475,  181,  187
Sep 12 20:35:45 raspberrypi shairport-sync[31694]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7989.6,    11950.7,    53423.0.
Sep 12 20:35:52 raspberrypi shairport-sync[31694]:       -0.2,      17.0,      17.0,       83249,      0,    155,      0,    155,  21507,  176,  187
Sep 12 20:36:00 raspberrypi shairport-sync[31694]:       -0.2,      56.6,      56.6,       84252,      0,    158,      0,    158,  21492,  177,  187
Sep 12 20:36:05 raspberrypi shairport-sync[31694]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8011.3,    13093.4,   133952.0.
Sep 12 20:36:08 raspberrypi shairport-sync[31694]:        0.9,     -19.8,      19.8,       85255,      0,    162,      0,    163,  21315,  169,  187
Sep 12 20:36:16 raspberrypi shairport-sync[31694]:        0.4,       0.0,       0.0,       86258,      0,    163,      0,    163,  21552,  178,  187
Sep 12 20:36:24 raspberrypi shairport-sync[31694]:       -1.0,       5.7,       5.7,       87261,      0,    169,      0,    170,  21497,  180,  187
Sep 12 20:36:25 raspberrypi shairport-sync[31694]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8001.5,    12271.7,    76935.0.
Sep 12 20:36:32 raspberrypi shairport-sync[31694]:       -0.6,     -22.7,     356.9,       88264,      0,    170,      0,    171,  21487,  174,  187
Sep 12 20:36:40 raspberrypi shairport-sync[31694]:        0.4,       0.0,       0.0,       89267,      0,    173,      0,    174,  21557,  175,  187
Sep 12 20:36:45 raspberrypi shairport-sync[31694]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8017.3,    12126.3,    89880.0.
Sep 12 20:36:48 raspberrypi shairport-sync[31694]:        1.2,     -25.5,      25.5,       90270,      0,    183,      0,    184,  21553,  176,  187
Sep 12 20:36:56 raspberrypi shairport-sync[31694]:        0.8,       0.0,       0.0,       91273,      0,    188,      0,    189,  21607,  177,  187
Sep 12 20:37:04 raspberrypi shairport-sync[31694]:        0.4,       0.0,       0.0,       92276,      0,    197,      0,    198,  21575,  168,  187
Sep 12 20:37:05 raspberrypi shairport-sync[31694]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8032.7,    13109.2,   149693.0.
Sep 12 20:37:12 raspberrypi shairport-sync[31694]:        0.1,       0.0,       0.0,       93279,      0,    204,      0,    205,  21550,  178,  187
Sep 12 20:37:20 raspberrypi shairport-sync[31694]:        0.1,       0.0,       0.0,       94282,      0,    208,      0,    209,  21567,  179,  187
Sep 12 20:37:25 raspberrypi shairport-sync[31694]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8039.1,    12244.0,    67101.0.
Sep 12 20:37:28 raspberrypi shairport-sync[31694]:        0.8,       2.8,       2.8,       95285,      0,    217,      0,    218,  21305,  178,  187
Sep 12 20:37:36 raspberrypi shairport-sync[31694]:        0.8,       0.0,       0.0,       96288,      0,    219,      0,    220,  21584,  176,  187
Sep 12 20:37:44 raspberrypi shairport-sync[31694]:        0.6,       0.0,       0.0,       97291,      0,    224,      0,    225,  21575,  179,  187
Sep 12 20:37:45 raspberrypi shairport-sync[31694]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8022.4,    12009.2,    72187.0.
Sep 12 20:37:52 raspberrypi shairport-sync[31694]:        0.4,       0.0,       0.0,       98294,      0,    233,      0,    234,  21562,  178,  187
Sep 12 20:38:00 raspberrypi shairport-sync[31694]:        0.2,       0.0,       0.0,       99297,      0,    233,      0,    234,  21555,  175,  187
Sep 12 20:38:05 raspberrypi shairport-sync[31694]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7989.3,    12971.1,   136239.0.
Sep 12 20:38:08 raspberrypi shairport-sync[31694]:        0.7,       0.0,       0.0,      100300,      0,    235,      0,    236,  21549,  168,  187
Sep 12 20:38:16 raspberrypi shairport-sync[31694]:        0.4,       0.0,       0.0,      101303,      0,    235,      0,    236,  21566,  178,  187
Sep 12 20:38:24 raspberrypi shairport-sync[31694]:        0.8,       0.0,       0.0,      102306,      0,    235,      0,    236,  21573,  180,  187
Sep 12 20:38:25 raspberrypi shairport-sync[31694]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.1,    12222.9,    76724.0.
Sep 12 20:38:26 raspberrypi shairport-sync[31694]: RTSP thread 2 received an RTSP Packet of type "SET_PARAMETER":
Sep 12 20:38:26 raspberrypi shairport-sync[31694]:   Type: "Content-Length", content: "20"
Sep 12 20:38:26 raspberrypi shairport-sync[31694]:   Type: "Content-Type", content: "text/parameters"
Sep 12 20:38:26 raspberrypi shairport-sync[31694]:   Type: "CSeq", content: "419"
Sep 12 20:38:26 raspberrypi shairport-sync[31694]:   Type: "DACP-ID", content: "33522A8480101B41"
Sep 12 20:38:26 raspberrypi shairport-sync[31694]:   Type: "Active-Remote", content: "2082726399"
Sep 12 20:38:26 raspberrypi shairport-sync[31694]:   Type: "User-Agent", content: "AirPlay/366.74.2"
Sep 12 20:38:26 raspberrypi shairport-sync[31694]: RTSP thread 2: RTSP Response:
Sep 12 20:38:26 raspberrypi shairport-sync[31694]:   Type: "CSeq", content: "419"
Sep 12 20:38:26 raspberrypi shairport-sync[31694]:   Type: "Server", content: "AirTunes/105.1"
Sep 12 20:38:26 raspberrypi shairport-sync[31694]: RTSP thread 2 received an RTSP Packet of type "SET_PARAMETER":
Sep 12 20:38:26 raspberrypi shairport-sync[31694]:   Type: "Content-Length", content: "20"
Sep 12 20:38:26 raspberrypi shairport-sync[31694]:   Type: "Content-Type", content: "text/parameters"
Sep 12 20:38:26 raspberrypi shairport-sync[31694]:   Type: "CSeq", content: "420"
Sep 12 20:38:26 raspberrypi shairport-sync[31694]:   Type: "DACP-ID", content: "33522A8480101B41"
Sep 12 20:38:26 raspberrypi shairport-sync[31694]:   Type: "Active-Remote", content: "2082726399"
Sep 12 20:38:26 raspberrypi shairport-sync[31694]:   Type: "User-Agent", content: "AirPlay/366.74.2"
Sep 12 20:38:26 raspberrypi shairport-sync[31694]: RTSP thread 2: RTSP Response:
Sep 12 20:38:26 raspberrypi shairport-sync[31694]:   Type: "CSeq", content: "420"
Sep 12 20:38:26 raspberrypi shairport-sync[31694]:   Type: "Server", content: "AirTunes/105.1"
Sep 12 20:38:32 raspberrypi shairport-sync[31694]:        0.4,       0.0,       0.0,      103309,      0,    235,      0,    236,  21581,  181,  187
Sep 12 20:38:40 raspberrypi shairport-sync[31694]:       -0.1,       0.0,       0.0,      104312,      0,    235,      0,    236,  21541,  169,  187
Sep 12 20:38:45 raspberrypi shairport-sync[31694]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7989.5,    12569.4,   152330.0.
Sep 12 20:38:48 raspberrypi shairport-sync[31694]:        0.3,       0.0,       0.0,      105315,     38,    235,      0,    274,  21568,   54,  187
Sep 12 20:38:51 raspberrypi shairport-sync[31694]: Time ping turnaround time: 1196800 us -- it looks like a timing ping was lost.
Sep 12 20:38:56 raspberrypi shairport-sync[31694]:       -0.6,       0.0,       0.0,      106318,    345,    326,     97,    507,  21531,   38,  187
Sep 12 20:39:04 raspberrypi shairport-sync[31694]:        0.2,       0.0,       0.0,      107321,    345,    330,     97,    511,  21514,  168,  187
Sep 12 20:39:08 raspberrypi shairport-sync[31694]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     9370.2,    37908.5,  1201012.0.
Sep 12 20:39:12 raspberrypi shairport-sync[31694]:        0.1,       0.0,       0.0,      108324,    345,    330,     97,    511,  21556,  177,  187
mikebrady commented 6 years ago

Thanks for the update. The log suggests that there is a serious problem with your network.

  1. Timing pings should be returned in a small number of milliseconds, typically less than 3. In your logs, however, one took well over a second; another took over 300 milliseconds. These are indications of a network problem of some sort.
  2. The packet reception interval statistics also indicate problems. The first number is the average interval between packets, which should be 7.98186 milliseconds. The second number is the standard deviation of the intervals, the smaller the better. The third figure is the longest time between successive packets. It should be a little less than 8 milliseconds, as above, but it is often around 80 milliseconds, and occasionally is a over 600 milliseconds and once it shows up as a huge 1.2 seconds. (In 1.2 seconds, around 150 packets should have come through!)
  3. A considerable number of packets are lost and need to be resent.

The missing time pings and very long occasional maximum interval figures indicate a network that occasionally blocks traffic for extended periods, leading eventually to Shairport Sync running out of audio to play -- hence the stuttering.

Here is a log from a session between an iPad and Shairport Sync, both on not-too-good WiFi connections:

Sep 13 10:46:10 raspberrypi shairport-sync[22132]:       -0.1,       0.0,       0.0,        1003,      0,      7,      0,      7,   6139,  209,  230
Sep 13 10:46:18 raspberrypi shairport-sync[22132]:       -0.6,       0.0,       0.0,        2006,      0,      7,      0,      7,   6091,  220,  230
Sep 13 10:46:20 raspberrypi shairport-sync[22132]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8005.0,    14287.4,   156552.0.
Sep 13 10:46:26 raspberrypi shairport-sync[22132]:       -0.6,       0.0,       0.0,        3009,      0,      7,      0,      7,   6099,  218,  230
Sep 13 10:46:34 raspberrypi shairport-sync[22132]:       -0.3,       0.0,       0.0,        4012,      0,      7,      0,      7,   6123,  221,  230
Sep 13 10:46:40 raspberrypi shairport-sync[22132]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7977.1,    13460.6,    85921.0.
Sep 13 10:46:42 raspberrypi shairport-sync[22132]:       -0.2,       0.0,       0.0,        5015,      0,      7,      0,      7,   6119,  218,  230
Sep 13 10:46:50 raspberrypi shairport-sync[22132]:       -0.4,       0.0,       0.0,        6018,      0,      7,      0,      7,   6119,  220,  230
Sep 13 10:46:58 raspberrypi shairport-sync[22132]:       -0.2,       0.0,       0.0,        7021,      0,      7,      0,      7,   6115,  219,  230
Sep 13 10:47:00 raspberrypi shairport-sync[22132]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7980.5,    13211.8,    83177.0.
Sep 13 10:47:06 raspberrypi shairport-sync[22132]:       -0.2,       0.0,       0.0,        8024,      0,      7,      0,      7,   6135,  221,  230
Sep 13 10:47:14 raspberrypi shairport-sync[22132]:       -0.1,       0.0,       0.0,        9027,      0,      7,      0,      7,   6131,  222,  231
Sep 13 10:47:20 raspberrypi shairport-sync[22132]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7978.4,    13242.5,    71497.0.
Sep 13 10:47:22 raspberrypi shairport-sync[22132]:       -0.1,       0.0,       0.0,       10030,      0,      7,      0,      7,   6135,  221,  230
Sep 13 10:47:30 raspberrypi shairport-sync[22132]:        0.1,       0.0,       0.0,       11033,      0,      7,      0,      7,   6127,  222,  230
Sep 13 10:47:38 raspberrypi shairport-sync[22132]:        0.2,       0.0,       0.0,       12036,      0,      7,      0,      7,   6147,  221,  230
Sep 13 10:47:40 raspberrypi shairport-sync[22132]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.5,    13223.8,    70978.0.
Sep 13 10:47:46 raspberrypi shairport-sync[22132]:        0.5,       0.0,       0.0,       13039,      0,      7,      0,      7,   6163,  222,  230
Sep 13 10:47:54 raspberrypi shairport-sync[22132]:        0.3,       0.0,       0.0,       14042,      0,      7,      0,      7,   6147,  222,  231
Sep 13 10:48:00 raspberrypi shairport-sync[22132]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.8,    13196.4,    72542.0.
Sep 13 10:48:02 raspberrypi shairport-sync[22132]:        0.4,       0.0,       0.0,       15045,      0,      7,      0,      7,   6147,  222,  230
Sep 13 10:48:10 raspberrypi shairport-sync[22132]:        0.4,       0.0,       0.0,       16048,      0,      7,      0,      7,   6159,  222,  230
Sep 13 10:48:18 raspberrypi shairport-sync[22132]:        0.9,       0.0,       0.0,       17051,      0,      7,      0,      7,   6155,  222,  231
Sep 13 10:48:20 raspberrypi shairport-sync[22132]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.7,    13129.1,    70816.0.
Sep 13 10:48:26 raspberrypi shairport-sync[22132]:        1.2,       0.0,       0.0,       18054,      0,      7,      0,      7,   6187,  221,  230
Sep 13 10:48:34 raspberrypi shairport-sync[22132]:        1.1,       0.0,       0.0,       19057,      0,      7,      0,      7,   6179,  219,  230
Sep 13 10:48:40 raspberrypi shairport-sync[22132]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7978.1,    13082.1,    67322.0.
Sep 13 10:48:42 raspberrypi shairport-sync[22132]:        0.8,       0.0,       0.0,       20060,      0,      7,      0,      7,   6175,  222,  230
Sep 13 10:48:50 raspberrypi shairport-sync[22132]:        0.8,       0.0,       0.0,       21063,      0,      7,      0,      7,   6167,  222,  230
Sep 13 10:48:58 raspberrypi shairport-sync[22132]:        1.0,       0.0,       0.0,       22066,      0,      7,      0,      7,   6179,  220,  230
Sep 13 10:49:00 raspberrypi shairport-sync[22132]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7978.8,    13177.7,    74739.0.
Sep 13 10:49:06 raspberrypi shairport-sync[22132]:        0.9,       0.0,       0.0,       23069,      0,      7,      0,      7,   6179,  221,  230
Sep 13 10:49:14 raspberrypi shairport-sync[22132]:        1.0,       0.0,       0.0,       24072,      0,      7,      0,      7,   6183,  222,  230
Sep 13 10:49:20 raspberrypi shairport-sync[22132]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7988.5,    13238.6,    74238.0.
Sep 13 10:49:22 raspberrypi shairport-sync[22132]:        1.2,     -99.1,      99.1,       25075,      0,      7,      0,      7,   6191,  221,  230
Sep 13 10:49:30 raspberrypi shairport-sync[22132]:        0.6,       0.0,       0.0,       26078,      0,      7,      0,      7,   6124,  218,  231
Sep 13 10:49:38 raspberrypi shairport-sync[22132]:        0.9,       0.0,       0.0,       27081,      0,      7,      0,      7,   6164,  222,  231
Sep 13 10:49:40 raspberrypi shairport-sync[22132]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7970.6,    13122.1,    77046.0.
Sep 13 10:49:46 raspberrypi shairport-sync[22132]:        1.4,     -14.2,      14.2,       28084,      0,      7,      0,      7,   6187,  221,  231
Sep 13 10:49:54 raspberrypi shairport-sync[22132]:        0.8,       0.0,       0.0,       29087,      0,      7,      0,      7,   6175,  222,  230
Sep 13 10:50:00 raspberrypi shairport-sync[22132]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7997.7,    13211.6,    65599.0.
Sep 13 10:50:02 raspberrypi shairport-sync[22132]:        0.8,       0.0,       0.0,       30090,      0,      7,      0,      7,   6175,  222,  230
Sep 13 10:50:10 raspberrypi shairport-sync[22132]:        0.7,       0.0,       0.0,       31093,      0,      7,      0,      7,   6171,  222,  230
Sep 13 10:50:18 raspberrypi shairport-sync[22132]:        0.6,       0.0,       0.0,       32096,      0,      7,      0,      7,   6167,  218,  231
Sep 13 10:50:20 raspberrypi shairport-sync[22132]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7972.2,    13447.9,    85532.0.
Sep 13 10:50:26 raspberrypi shairport-sync[22132]:        0.5,       0.0,       0.0,       33099,      0,      7,      0,      7,   6155,  220,  230
Sep 13 10:50:34 raspberrypi shairport-sync[22132]:        0.8,       0.0,       0.0,       34102,      0,      7,      0,      7,   6163,  221,  230
Sep 13 10:50:40 raspberrypi shairport-sync[22132]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7988.7,    13190.0,    71782.0.
Sep 13 10:50:42 raspberrypi shairport-sync[22132]:        0.7,       0.0,       0.0,       35105,      0,      7,      0,      7,   6171,  220,  230
Sep 13 10:50:50 raspberrypi shairport-sync[22132]:        1.1,       0.0,       0.0,       36108,      0,      7,      0,      7,   6191,  219,  230
Sep 13 10:50:58 raspberrypi shairport-sync[22132]:        0.9,       0.0,       0.0,       37111,      0,      7,      0,      7,   6179,  221,  230
Sep 13 10:51:00 raspberrypi shairport-sync[22132]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7969.5,    13224.0,    73951.0.
Sep 13 10:51:06 raspberrypi shairport-sync[22132]:        0.9,       0.0,       0.0,       38114,      0,      7,      0,      7,   6147,  224,  246
Sep 13 10:51:14 raspberrypi shairport-sync[22132]:        0.8,       0.0,       0.0,       39117,      0,      7,      0,      7,   6179,  232,  245
Sep 13 10:51:20 raspberrypi shairport-sync[22132]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7930.7,    18702.3,   133578.0.
Sep 13 10:51:22 raspberrypi shairport-sync[22132]:        0.8,       0.0,       0.0,       40120,      0,      7,      0,      7,   6175,  232,  245
Sep 13 10:51:30 raspberrypi shairport-sync[22132]:        1.5,    -116.1,     116.1,       41123,      0,      7,      0,      7,   6179,  232,  245
Sep 13 10:51:38 raspberrypi shairport-sync[22132]:        1.6,       0.0,       0.0,       42126,      0,      7,      0,      7,   6198,  230,  245
Sep 13 10:51:40 raspberrypi shairport-sync[22132]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7954.7,    18600.9,    93837.0.
Sep 13 10:51:46 raspberrypi shairport-sync[22132]:        0.3,       0.0,       0.0,       43129,      0,      7,      0,      7,   6146,  231,  246
Sep 13 10:51:54 raspberrypi shairport-sync[22132]:        0.3,       0.0,       0.0,       44132,      0,      7,      0,      7,   6150,  232,  245
Sep 13 10:52:00 raspberrypi shairport-sync[22132]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7986.4,    18700.4,   105816.0.
Sep 13 10:52:02 raspberrypi shairport-sync[22132]:        0.8,       0.0,       0.0,       45135,      0,      7,      0,      7,   6158,  231,  245
Sep 13 10:52:11 raspberrypi shairport-sync[22132]:        1.0,       0.0,       0.0,       46138,      0,      7,      0,      7,   6170,  233,  245
Sep 13 10:52:19 raspberrypi shairport-sync[22132]:        0.6,       0.0,       0.0,       47141,      0,      7,      0,      7,   6166,  231,  245
Sep 13 10:52:20 raspberrypi shairport-sync[22132]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7970.7,    18689.1,   104374.0.
Sep 13 10:52:27 raspberrypi shairport-sync[22132]:        0.7,       0.0,       0.0,       48144,      0,      7,      0,      7,   6170,  231,  245
Sep 13 10:52:35 raspberrypi shairport-sync[22132]:        0.7,       0.0,       0.0,       49147,      0,      7,      0,      7,   6170,  224,  245
Sep 13 10:52:40 raspberrypi shairport-sync[22132]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8037.1,    17424.8,   160433.0.
Sep 13 10:52:43 raspberrypi shairport-sync[22132]:        0.7,       0.0,       0.0,       50150,      0,      7,      0,      7,   6170,  223,  230
Sep 13 10:52:51 raspberrypi shairport-sync[22132]:        1.4,       0.0,       0.0,       51153,      0,      7,      0,      7,   6190,  222,  230
Sep 13 10:52:59 raspberrypi shairport-sync[22132]:        0.9,       0.0,       0.0,       52156,      0,      7,      0,      7,   6182,  223,  230
Sep 13 10:53:00 raspberrypi shairport-sync[22132]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7973.2,    12327.1,    55905.0.
Sep 13 10:53:07 raspberrypi shairport-sync[22132]:        0.9,       0.0,       0.0,       53159,      0,      7,      0,      7,   6182,  223,  231
Sep 13 10:53:15 raspberrypi shairport-sync[22132]:        1.1,       0.0,       0.0,       54162,      0,      7,      0,      7,   6186,  223,  231
Sep 13 10:53:20 raspberrypi shairport-sync[22132]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7985.3,    12365.8,    54772.0.
Sep 13 10:53:23 raspberrypi shairport-sync[22132]:        1.1,       0.0,       0.0,       55165,      0,      7,      0,      7,   6190,  223,  230
Sep 13 10:53:31 raspberrypi shairport-sync[22132]:        1.2,       0.0,       0.0,       56168,      0,      7,      0,      7,   6190,  223,  231
Sep 13 10:53:39 raspberrypi shairport-sync[22132]:        1.2,       0.0,       0.0,       57171,      0,      7,      0,      7,   6194,  223,  230
Sep 13 10:53:40 raspberrypi shairport-sync[22132]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7978.5,    12139.9,    56692.0.
Sep 13 10:53:47 raspberrypi shairport-sync[22132]:        1.4,       0.0,       0.0,       58174,      0,      7,      0,      7,   6194,  223,  230
Sep 13 10:53:55 raspberrypi shairport-sync[22132]:        1.3,       0.0,       0.0,       59177,      0,      7,      0,      7,   6194,  222,  231
Sep 13 10:54:00 raspberrypi shairport-sync[22132]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.8,    12053.8,    58284.0.
Sep 13 10:54:03 raspberrypi shairport-sync[22132]:        1.3,       0.0,       0.0,       60180,      0,      7,      0,      7,   6198,  222,  230
Sep 13 10:54:11 raspberrypi shairport-sync[22132]:        1.6,      -5.7,       5.7,       61183,      0,      7,      0,      7,   6206,  222,  231
Sep 13 10:54:19 raspberrypi shairport-sync[22132]:        1.8,       0.0,       0.0,       62186,      0,      7,      0,      7,   6212,  222,  230
Sep 13 10:54:20 raspberrypi shairport-sync[22132]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7977.8,    12085.5,    53232.0.
Sep 13 10:54:27 raspberrypi shairport-sync[22132]:        1.8,       0.0,       0.0,       63189,      0,      7,      0,      7,   6212,  222,  230
Sep 13 10:54:35 raspberrypi shairport-sync[22132]:        1.6,       0.0,       0.0,       64192,      0,      7,      0,      7,   6212,  221,  230
Sep 13 10:54:40 raspberrypi shairport-sync[22132]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7990.4,    12274.3,    59281.0.
Sep 13 10:54:43 raspberrypi shairport-sync[22132]:        1.8,       0.0,       0.0,       65195,      0,      7,      0,      7,   6208,  221,  230
Sep 13 10:54:51 raspberrypi shairport-sync[22132]:        1.8,       0.0,       0.0,       66198,      0,      7,      0,      7,   6212,  222,  230
Sep 13 10:54:59 raspberrypi shairport-sync[22132]:        1.8,      -2.8,       2.8,       67201,      0,      7,      0,      7,   6219,  222,  230
Sep 13 10:54:59 raspberrypi shairport-sync[22132]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7980.0,    12162.4,    53536.0.
Sep 13 10:55:07 raspberrypi shairport-sync[22132]:        1.9,     -17.0,      17.0,       68204,      0,      7,      0,      7,   6225,  223,  230
Sep 13 10:55:15 raspberrypi shairport-sync[22132]:        1.8,     -11.3,      11.3,       69207,      0,      7,      0,      7,   6225,  223,  230
Sep 13 10:55:19 raspberrypi shairport-sync[22132]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7978.5,    12245.9,    59140.0.
Sep 13 10:55:23 raspberrypi shairport-sync[22132]:        1.6,     -28.3,      28.3,       70210,      0,      7,      0,      7,   6201,  221,  231
Sep 13 10:55:31 raspberrypi shairport-sync[22132]:        1.9,     -70.8,      70.8,       71213,      0,      7,      0,      7,   6223,  223,  230
Sep 13 10:55:39 raspberrypi shairport-sync[22132]:        1.9,       0.0,       0.0,       72216,      0,      7,      0,      7,   6222,  222,  230
Sep 13 10:55:39 raspberrypi shairport-sync[22132]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7989.3,    12281.6,    56505.0.
Sep 13 10:55:47 raspberrypi shairport-sync[22132]:        1.7,     -36.8,      36.8,       73219,      0,      7,      0,      7,   6198,  222,  230
Sep 13 10:55:55 raspberrypi shairport-sync[22132]:        1.5,       0.0,       0.0,       74222,      0,      7,      0,      7,   6205,  222,  230
Sep 13 10:55:59 raspberrypi shairport-sync[22132]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7981.3,    12318.8,    61026.0.
Sep 13 10:56:03 raspberrypi shairport-sync[22132]:        1.4,       0.0,       0.0,       75225,      0,     13,      0,     13,   6205,  206,  230
Sep 13 10:56:11 raspberrypi shairport-sync[22132]:        1.3,       0.0,       0.0,       76228,      0,     19,      0,     19,   6201,  210,  230
abid76 commented 6 years ago

OK thanks for this detailed explanation.

I then tried three setups to see how a wifi/cable connection affects the figures: 1) device wifi / raspberry wifi 2) device wifi / raspberry LAN 3) device LAN / raspberry LAN

As expected the figures are best when both are connected via LAN (max packet reception is then around 30 ms). When I got you right the max packet reception should be about 8 ms. All values are far from 8 ms.

Is 8 ms also realistic when both (device and airplay receiver) are connected via wifi?

The results: 1) device wifi / raspberry wifi

Sep 13 19:27:54 raspberrypi shairport-sync[415]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8086.7,    18452.1,   123265.0.
Sep 13 19:27:59 raspberrypi shairport-sync[415]:       -1.9,      42.5,      42.5,        3009,     19,     26,      0,     26,   5920,  224,  230
Sep 13 19:28:07 raspberrypi shairport-sync[415]:       -1.8,       2.8,       2.8,        4012,     19,     36,      0,     36,   6058,  221,  230
Sep 13 19:28:14 raspberrypi shairport-sync[415]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8065.0,    15140.4,   185796.0.
Sep 13 19:28:15 raspberrypi shairport-sync[415]:       -1.0,       0.0,       0.0,        5015,     19,     49,      0,     49,   6058,  207,  230
Sep 13 19:28:23 raspberrypi shairport-sync[415]:        0.5,      48.2,     291.7,        6018,     19,     54,      0,     54,   6014,  214,  230
Sep 13 19:28:31 raspberrypi shairport-sync[415]:       -1.0,       2.8,       2.8,        7021,     19,     56,      0,     56,   6070,  223,  230
Sep 13 19:28:34 raspberrypi shairport-sync[415]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7968.3,    13926.1,   130321.0.
Sep 13 19:28:39 raspberrypi shairport-sync[415]:       -0.1,       2.8,       2.8,        8024,     19,     61,      0,     61,   6119,  224,  245
Sep 13 19:28:47 raspberrypi shairport-sync[415]:        0.4,       0.0,       0.0,        9027,     19,     64,      0,     64,   6151,  232,  245
Sep 13 19:28:54 raspberrypi shairport-sync[415]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8030.7,    19325.5,   147830.0.
Sep 13 19:28:55 raspberrypi shairport-sync[415]:        0.3,       0.0,       0.0,       10030,     19,     67,      0,     67,   6070,  228,  245
Sep 13 19:29:03 raspberrypi shairport-sync[415]:       -1.5,       0.0,       0.0,       11033,     19,     69,      0,     69,   6062,  232,  245
Sep 13 19:29:11 raspberrypi shairport-sync[415]:       -1.6,      85.0,      85.0,       12036,     19,     70,      0,     70,   6041,  233,  245
Sep 13 19:29:14 raspberrypi shairport-sync[415]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7990.2,    19199.7,    99825.0.
Sep 13 19:29:19 raspberrypi shairport-sync[415]:       -1.6,       0.0,       0.0,       13039,     19,     80,      0,     83,   6049,  233,  245
Sep 13 19:29:27 raspberrypi shairport-sync[415]:       -1.4,       2.8,       2.8,       14042,     19,     81,      0,     84,   6073,  233,  246
Sep 13 19:29:34 raspberrypi shairport-sync[415]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8024.2,    19070.4,   102139.0.
Sep 13 19:29:35 raspberrypi shairport-sync[415]:       -1.4,       0.0,       0.0,       15045,     19,     91,      0,     94,   6067,  231,  245
Sep 13 19:29:43 raspberrypi shairport-sync[415]:       -1.6,       0.0,       0.0,       16048,     19,     99,      0,    102,   6067,  231,  245
Sep 13 19:29:51 raspberrypi shairport-sync[415]:       -1.7,     102.0,     102.0,       17051,     19,    105,      0,    108,   5884,  230,  245
Sep 13 19:29:54 raspberrypi shairport-sync[415]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8036.4,    19136.6,    99515.0.
Sep 13 19:29:59 raspberrypi shairport-sync[415]:       -1.4,       8.5,       8.5,       18054,     19,    114,      0,    117,   6056,  233,  246
Sep 13 19:30:07 raspberrypi shairport-sync[415]:       -0.9,       0.0,       0.0,       19057,     19,    135,      0,    138,   6098,  221,  247
Sep 13 19:30:14 raspberrypi shairport-sync[415]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8109.8,    14831.0,   178079.0.
Sep 13 19:30:15 raspberrypi shairport-sync[415]:       -0.8,       2.8,       2.8,       20060,     19,    146,      0,    149,   6068,  222,  230
Sep 13 19:30:23 raspberrypi shairport-sync[415]:       -0.4,       5.7,       5.7,       21063,     19,    153,      0,    156,   5988,  224,  230
Sep 13 19:30:31 raspberrypi shairport-sync[415]:       -1.2,       2.8,       2.8,       22066,     19,    157,      0,    160,   6087,  224,  230
Sep 13 19:30:35 raspberrypi shairport-sync[415]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8028.3,    11692.0,    56677.0.
Sep 13 19:30:39 raspberrypi shairport-sync[415]:        0.1,       0.0,       0.0,       23069,     19,    168,      0,    171,   6092,  222,  230
Sep 13 19:30:47 raspberrypi shairport-sync[415]:       -0.6,       0.0,       0.0,       24072,     19,    176,      0,    179,   6114,  222,  230
Sep 13 19:30:55 raspberrypi shairport-sync[415]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8040.4,    11724.2,    53232.0.
Sep 13 19:30:55 raspberrypi shairport-sync[415]:       -0.6,       5.7,       5.7,       25075,     19,    180,      0,    183,   6114,  224,  230
Sep 13 19:31:03 raspberrypi shairport-sync[415]:       -0.4,       0.0,       0.0,       26078,     19,    197,      0,    200,   6109,  221,  230
Sep 13 19:31:11 raspberrypi shairport-sync[415]:       -0.8,       0.0,       0.0,       27081,     19,    204,      0,    207,   6103,  222,  245
Sep 13 19:31:15 raspberrypi shairport-sync[415]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8045.4,    15646.3,   169728.0.

2) device wifi / raspberry LAN

Sep 13 19:21:31 raspberrypi shairport-sync[420]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7980.1,    18709.6,   122097.0.
Sep 13 19:21:37 raspberrypi shairport-sync[420]:        0.0,       2.8,       2.8,        3009,      0,      4,      0,      4,   6135,  225,  231
Sep 13 19:21:45 raspberrypi shairport-sync[420]:       -0.1,       0.0,       0.0,        4012,      0,     14,      0,     14,   6133,  223,  230
Sep 13 19:21:51 raspberrypi shairport-sync[420]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8076.1,    15324.0,   222389.0.
Sep 13 19:21:53 raspberrypi shairport-sync[420]:       -0.1,       0.0,       0.0,        5015,      0,     26,      0,     26,   6122,  202,  231
Sep 13 19:22:01 raspberrypi shairport-sync[420]:       -0.1,       5.7,       5.7,        6018,      0,     32,      0,     32,   5939,  214,  231
Sep 13 19:22:09 raspberrypi shairport-sync[420]:       -0.1,       2.8,       2.8,        7021,      0,     34,      0,     34,   6135,  223,  230
Sep 13 19:22:11 raspberrypi shairport-sync[420]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8002.9,    14459.8,   116905.0.
Sep 13 19:22:17 raspberrypi shairport-sync[420]:       -0.2,       0.0,       0.0,        8024,      0,     48,      0,     48,   6125,  222,  231
Sep 13 19:22:25 raspberrypi shairport-sync[420]:       -0.1,       0.0,       0.0,        9027,      0,     64,      0,     64,   6133,  221,  231
Sep 13 19:22:32 raspberrypi shairport-sync[420]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8086.9,    12603.9,    60607.0.
Sep 13 19:22:33 raspberrypi shairport-sync[420]:       -0.1,       0.0,       0.0,       10030,      0,     68,      0,     68,   6131,  222,  230
Sep 13 19:22:41 raspberrypi shairport-sync[420]:       -0.2,       0.0,       0.0,       11033,      0,     74,      0,     74,   6128,  224,  230
Sep 13 19:22:49 raspberrypi shairport-sync[420]:       -0.3,       0.0,       0.0,       12036,      0,     76,      0,     76,   6126,  224,  230
Sep 13 19:22:52 raspberrypi shairport-sync[420]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8003.4,    12466.1,    56657.0.
Sep 13 19:22:57 raspberrypi shairport-sync[420]:       -0.3,       2.8,       2.8,       13039,      0,     85,      0,     85,   6123,  222,  231
Sep 13 19:23:05 raspberrypi shairport-sync[420]:       -0.4,       5.7,       5.7,       14042,      0,     91,      0,     91,   5996,  222,  231
Sep 13 19:23:12 raspberrypi shairport-sync[420]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8004.3,    15074.1,   170953.0.
Sep 13 19:23:13 raspberrypi shairport-sync[420]:       -0.5,       0.0,       0.0,       15045,      0,     99,      0,     99,   6115,  221,  246
Sep 13 19:23:21 raspberrypi shairport-sync[420]:       -0.2,       0.0,       0.0,       16048,      0,    104,      0,    104,   6123,  233,  245
Sep 13 19:23:29 raspberrypi shairport-sync[420]:       -0.4,       0.0,       0.0,       17051,      0,    104,      0,    104,   6122,  233,  245
Sep 13 19:23:32 raspberrypi shairport-sync[420]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8025.9,    18867.7,    93662.0.
Sep 13 19:23:37 raspberrypi shairport-sync[420]:       -0.5,       5.7,       5.7,       18054,      0,    107,      0,    107,   6009,  233,  246
Sep 13 19:23:45 raspberrypi shairport-sync[420]:       -0.5,       0.0,       0.0,       19057,      0,    112,      0,    112,   6111,  233,  246
Sep 13 19:23:52 raspberrypi shairport-sync[420]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8014.0,    18757.0,    92776.0.
Sep 13 19:23:53 raspberrypi shairport-sync[420]:       -0.5,       0.0,       0.0,       20060,      0,    121,      0,    121,   6111,  233,  246
Sep 13 19:24:01 raspberrypi shairport-sync[420]:       -0.6,       0.0,       0.0,       21063,      0,    122,      0,    122,   6113,  233,  246
Sep 13 19:24:09 raspberrypi shairport-sync[420]:       -0.6,       0.0,       0.0,       22066,      0,    131,      0,    132,   6102,  233,  246
Sep 13 19:24:12 raspberrypi shairport-sync[420]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8027.6,    18866.5,    92404.0.
Sep 13 19:24:17 raspberrypi shairport-sync[420]:       -0.6,       5.7,       5.7,       23069,      0,    137,      0,    137,   5989,  233,  245
Sep 13 19:24:25 raspberrypi shairport-sync[420]:       -0.7,       0.0,       0.0,       24072,      0,    145,      0,    145,   6108,  233,  245
Sep 13 19:24:32 raspberrypi shairport-sync[420]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8027.7,    18846.2,    94543.0.

3) device LAN / raspberry LAN

Sep 13 19:18:53 raspberrypi shairport-sync[420]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.4,     8015.6,    30636.0.
Sep 13 19:19:00 raspberrypi shairport-sync[420]:       -1.8,      45.3,      45.3,        3009,      0,      0,      0,      0,   6053,  261,  265
Sep 13 19:19:08 raspberrypi shairport-sync[420]:       -1.9,      93.5,      93.5,        4012,      0,      0,      0,      0,   6054,  261,  265
Sep 13 19:19:13 raspberrypi shairport-sync[420]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.6,     8204.9,    29992.0.
Sep 13 19:19:16 raspberrypi shairport-sync[420]:       -1.9,      96.3,      96.3,        5015,      0,      0,      0,      0,   5980,  261,  265
Sep 13 19:19:24 raspberrypi shairport-sync[420]:       -1.9,     104.8,     104.8,        6018,      0,      0,      0,      0,   6054,  261,  265
Sep 13 19:19:32 raspberrypi shairport-sync[420]:       -1.9,     119.0,     119.0,        7021,      0,      0,      0,      0,   5891,  261,  265
Sep 13 19:19:33 raspberrypi shairport-sync[420]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7980.5,     7887.0,    29076.0.
Sep 13 19:19:40 raspberrypi shairport-sync[420]:       -1.9,      99.1,      99.1,        8024,      0,      0,      0,      0,   6054,  261,  265
Sep 13 19:19:48 raspberrypi shairport-sync[420]:       -1.9,      93.5,      93.5,        9027,      0,      0,      0,      0,   6053,  261,  265
Sep 13 19:19:53 raspberrypi shairport-sync[420]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7983.6,     8085.8,    30675.0.
Sep 13 19:19:56 raspberrypi shairport-sync[420]:       -1.9,      99.1,      99.1,       10030,      0,      0,      0,      0,   6054,  261,  265
Sep 13 19:20:04 raspberrypi shairport-sync[420]:       -1.9,     107.6,     107.6,       11033,      0,      0,      0,      0,   6055,  261,  265
Sep 13 19:20:12 raspberrypi shairport-sync[420]:       -1.9,      93.5,      93.5,       12036,      0,      0,      0,      0,   6053,  261,  265
Sep 13 19:20:13 raspberrypi shairport-sync[420]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7972.1,     8089.0,    30181.0.
Sep 13 19:20:20 raspberrypi shairport-sync[420]:       -1.9,     113.3,     113.3,       13039,      0,      0,      0,      0,   6054,  261,  265
Sep 13 19:20:28 raspberrypi shairport-sync[420]:       -1.9,     102.0,     102.0,       14042,      0,      0,      0,      0,   6055,  261,  265
Sep 13 19:20:33 raspberrypi shairport-sync[420]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7985.6,     8168.4,    30190.0.
mikebrady commented 6 years ago

Thanks for that. The mean interval has simply got to be around 7.98186 milliseconds -- that's the transmission rate that corresponds to 44,100 frames per second.

In my experience, standard deviation figures -- a measure of the variability in the reception intervals -- seem to be okay up to the 20 millisecond range. The real problem with your original statistics seems to be the very long maximum intervals.

I also notice that quite a few packets need to be retransmitted with the device on WiFi, maybe indicative of a slightly dodgy network. Not enough to worry about on its own, but indicative.

It there any possibility that the router is poor quality or faulty or in need of a firmware update? (I'd guess that, given those occasional long outages, you would be experiencing outages on things like FaceTime or Skype from WiFi connected devices.)

abid76 commented 6 years ago

OK, thanks. The router is a Speedport 924v which is a "standard" consumer product, delivered by the biggest provider in Germany, Deutsche Telekom. I did not have any issues until now. Firmware is up to date. Maybe it's possible to get a new model from the provider as it is only rented.

But I have another problem. My raspberry is currently getting extremely hot (CPU temp over 90 degrees), so maybe I have to install shairport-sync on another one.

mikebrady commented 6 years ago

Thanks. I don’t have any knowledge of the modem, I’m afraid. The CPU temperature is interesting though. Shairport Sync should take about 20% of a CPU. You could use htop to see if something else is causing the CPU to be very busy.

abid76 commented 6 years ago

Sorry for the delay. I got a new router from my internet provider (Fritz!Box 7590) and since I installed it I did not experience any interruptions on playback 👍

Once I experienced the issue that my iPhone did not find the airplay service in the network. Here is some log output - the problems start at 07:04:53.... I'm not quite sure if it's a problem with the shairport-sync or with the raspbian's network service.

Maybe you have an idea whats going on?

Sep 27 06:17:34 raspberrypi wpa_supplicant[324]: wlan0: WPA: Group rekeying completed with 44:4e:6d:18:6d:29 [GTK=CCMP]
Sep 27 06:25:01 raspberrypi CRON[4191]: pam_unix(cron:session): session opened for user root by (uid=0)
Sep 27 06:25:01 raspberrypi CRON[4195]: (root) CMD (test -x /usr/sbin/anacron || ( cd / && run-parts --report /etc/cron.daily ))
Sep 27 06:25:03 raspberrypi liblogging-stdlog[391]:  [origin software="rsyslogd" swVersion="8.24.0" x-pid="391" x-info="http://www.rsyslog.com"] rsyslogd was HUPed
Sep 27 06:25:04 raspberrypi CRON[4191]: pam_unix(cron:session): session closed for user root
Sep 27 06:27:34 raspberrypi wpa_supplicant[324]: wlan0: WPA: Group rekeying completed with 44:4e:6d:18:6d:29 [GTK=CCMP]
Sep 27 06:37:34 raspberrypi wpa_supplicant[324]: wlan0: WPA: Group rekeying completed with 44:4e:6d:18:6d:29 [GTK=CCMP]
Sep 27 06:40:23 raspberrypi systemd[1]: Starting Daily apt upgrade and clean activities...
Sep 27 06:40:25 raspberrypi systemd[1]: Started Daily apt upgrade and clean activities.
Sep 27 06:40:25 raspberrypi systemd[1]: apt-daily-upgrade.timer: Adding 27min 39.376896s random time.
Sep 27 06:40:25 raspberrypi systemd[1]: apt-daily-upgrade.timer: Adding 10min 2.022120s random time.
Sep 27 06:47:34 raspberrypi wpa_supplicant[324]: wlan0: WPA: Group rekeying completed with 44:4e:6d:18:6d:29 [GTK=CCMP]
Sep 27 06:57:34 raspberrypi wpa_supplicant[324]: wlan0: WPA: Group rekeying completed with 44:4e:6d:18:6d:29 [GTK=CCMP]
Sep 27 07:04:53 raspberrypi shairport-sync[452]: New RTSP connection from 192.168.2.100:50905 to self at 192.168.2.50:5000 on conversation thread 3.
Sep 27 07:04:53 raspberrypi shairport-sync[452]: RTSP thread 3 received an RTSP Packet of type "ANNOUNCE":
Sep 27 07:04:53 raspberrypi shairport-sync[452]:   Type: "Content-Length", content: "641"
Sep 27 07:04:53 raspberrypi shairport-sync[452]:   Type: "Content-Type", content: "application/sdp"
Sep 27 07:04:53 raspberrypi shairport-sync[452]:   Type: "CSeq", content: "3"
Sep 27 07:04:53 raspberrypi shairport-sync[452]:   Type: "DACP-ID", content: "1F365725AEE31618"
Sep 27 07:04:53 raspberrypi shairport-sync[452]:   Type: "Active-Remote", content: "3214939238"
Sep 27 07:04:53 raspberrypi shairport-sync[452]:   Type: "User-Agent", content: "AirPlay/371.4.7"
Sep 27 07:04:53 raspberrypi shairport-sync[452]: Connection 3: ANNOUNCE
Sep 27 07:04:53 raspberrypi shairport-sync[452]: Play connection from user agent "AirPlay/371.4.7" on RTSP conversation thread 3.
Sep 27 07:04:53 raspberrypi shairport-sync[452]: AirPlay version 371 detected.
Sep 27 07:04:53 raspberrypi shairport-sync[452]: RTSP thread 3: RTSP Response:
Sep 27 07:04:53 raspberrypi shairport-sync[452]:   Type: "CSeq", content: "3"
Sep 27 07:04:53 raspberrypi shairport-sync[452]:   Type: "Server", content: "AirTunes/105.1"
Sep 27 07:04:53 raspberrypi shairport-sync[452]: RTSP thread 3 received an RTSP Packet of type "SETUP":
Sep 27 07:04:53 raspberrypi shairport-sync[452]:   Type: "Transport", content: "RTP/AVP/UDP;unicast;mode=record;timing_port=64760;control_port=63962"
Sep 27 07:04:53 raspberrypi shairport-sync[452]:   Type: "CSeq", content: "4"
Sep 27 07:04:53 raspberrypi shairport-sync[452]:   Type: "DACP-ID", content: "1F365725AEE31618"
Sep 27 07:04:53 raspberrypi shairport-sync[452]:   Type: "Active-Remote", content: "3214939238"
Sep 27 07:04:53 raspberrypi shairport-sync[452]:   Type: "User-Agent", content: "AirPlay/371.4.7"
Sep 27 07:04:53 raspberrypi shairport-sync[452]: Connection 3: SETUP -- Active-Remote string seen: "3214939238".
Sep 27 07:04:53 raspberrypi shairport-sync[452]: Connection 3: SETUP -- DACP-ID string seen: "1F365725AEE31618".
Sep 27 07:04:53 raspberrypi shairport-sync[452]: Connection 3: SETUP -- Connection from 192.168.2.100 to self at 192.168.2.50.
Sep 27 07:04:53 raspberrypi shairport-sync[452]: RTSP thread 3: RTSP Response:
Sep 27 07:04:53 raspberrypi shairport-sync[452]:   Type: "CSeq", content: "4"
Sep 27 07:04:53 raspberrypi shairport-sync[452]:   Type: "Server", content: "AirTunes/105.1"
Sep 27 07:04:53 raspberrypi shairport-sync[452]:   Type: "Transport", content: "RTP/AVP/UDP;unicast;interleaved=0-1;mode=record;control_port=6001;timing_port=6002;server_port=6003"
Sep 27 07:04:53 raspberrypi shairport-sync[452]:   Type: "Session", content: "1"
Sep 27 07:04:53 raspberrypi shairport-sync[452]: RTSP thread 3 received an RTSP Packet of type "RECORD":
Sep 27 07:04:53 raspberrypi shairport-sync[452]:   Type: "CSeq", content: "5"
Sep 27 07:04:53 raspberrypi shairport-sync[452]:   Type: "DACP-ID", content: "1F365725AEE31618"
Sep 27 07:04:53 raspberrypi shairport-sync[452]:   Type: "Active-Remote", content: "3214939238"
Sep 27 07:04:53 raspberrypi shairport-sync[452]:   Type: "User-Agent", content: "AirPlay/371.4.7"
Sep 27 07:04:53 raspberrypi shairport-sync[452]: Connection 3: RECORD
Sep 27 07:04:53 raspberrypi shairport-sync[452]: RTSP thread 3: RTSP Response:
Sep 27 07:04:53 raspberrypi shairport-sync[452]:   Type: "CSeq", content: "5"
Sep 27 07:04:53 raspberrypi shairport-sync[452]:   Type: "Server", content: "AirTunes/105.1"
Sep 27 07:04:53 raspberrypi shairport-sync[452]:   Type: "Audio-Latency", content: "11025"
Sep 27 07:04:53 raspberrypi shairport-sync[452]: RTSP thread 3 received an RTSP Packet of type "SET_PARAMETER":
Sep 27 07:04:53 raspberrypi shairport-sync[452]:   Type: "Content-Length", content: "20"
Sep 27 07:04:53 raspberrypi shairport-sync[452]:   Type: "Content-Type", content: "text/parameters"
Sep 27 07:04:53 raspberrypi shairport-sync[452]:   Type: "CSeq", content: "6"
Sep 27 07:04:53 raspberrypi shairport-sync[452]:   Type: "DACP-ID", content: "1F365725AEE31618"
Sep 27 07:04:53 raspberrypi shairport-sync[452]:   Type: "Active-Remote", content: "3214939238"
Sep 27 07:04:53 raspberrypi shairport-sync[452]:   Type: "User-Agent", content: "AirPlay/371.4.7"
Sep 27 07:04:53 raspberrypi shairport-sync[452]: RTSP thread 3: RTSP Response:
Sep 27 07:04:53 raspberrypi shairport-sync[452]:   Type: "CSeq", content: "6"
Sep 27 07:04:53 raspberrypi shairport-sync[452]:   Type: "Server", content: "AirTunes/105.1"
Sep 27 07:04:53 raspberrypi shairport-sync[452]: RTSP thread 3 received an RTSP Packet of type "SET_PARAMETER":
Sep 27 07:04:53 raspberrypi shairport-sync[452]:   Type: "Content-Length", content: "20"
Sep 27 07:04:53 raspberrypi shairport-sync[452]:   Type: "Content-Type", content: "text/parameters"
Sep 27 07:04:53 raspberrypi shairport-sync[452]:   Type: "CSeq", content: "7"
Sep 27 07:04:53 raspberrypi shairport-sync[452]:   Type: "DACP-ID", content: "1F365725AEE31618"
Sep 27 07:04:53 raspberrypi shairport-sync[452]:   Type: "Active-Remote", content: "3214939238"
Sep 27 07:04:53 raspberrypi shairport-sync[452]:   Type: "User-Agent", content: "AirPlay/371.4.7"
Sep 27 07:04:53 raspberrypi shairport-sync[452]: RTSP thread 3: RTSP Response:
Sep 27 07:04:53 raspberrypi shairport-sync[452]:   Type: "CSeq", content: "7"
Sep 27 07:04:53 raspberrypi shairport-sync[452]:   Type: "Server", content: "AirTunes/105.1"
Sep 27 07:04:53 raspberrypi shairport-sync[452]: Resend interval for latency of 77175 frames is 31 frames.
Sep 27 07:04:53 raspberrypi shairport-sync[452]: Hammerton Decoder used on encrypted audio.
Sep 27 07:04:53 raspberrypi shairport-sync[452]: RTSP thread 3 received an RTSP Packet of type "FLUSH":
Sep 27 07:04:53 raspberrypi shairport-sync[452]:   Type: "RTP-Info", content: "seq=22763;rtptime=1579334980"
Sep 27 07:04:53 raspberrypi shairport-sync[452]:   Type: "CSeq", content: "8"
Sep 27 07:04:53 raspberrypi shairport-sync[452]:   Type: "DACP-ID", content: "1F365725AEE31618"
Sep 27 07:04:53 raspberrypi shairport-sync[452]:   Type: "Active-Remote", content: "3214939238"
Sep 27 07:04:53 raspberrypi shairport-sync[452]:   Type: "User-Agent", content: "AirPlay/371.4.7"
Sep 27 07:04:53 raspberrypi shairport-sync[452]: RTSP thread 3: RTSP Response:
Sep 27 07:04:53 raspberrypi shairport-sync[452]:   Type: "CSeq", content: "8"
Sep 27 07:04:53 raspberrypi shairport-sync[452]:   Type: "Server", content: "AirTunes/105.1"
Sep 27 07:04:54 raspberrypi shairport-sync[452]: New RTSP connection from [2003:e9:6f20:8100:1cde:191d:6ee6:597d]:50904 to self at [2003:e9:6f20:8100:b136:73b1:b31c:efeb]:5000 on conversation thread 4.
Sep 27 07:04:54 raspberrypi shairport-sync[452]: Connection 4: RTSP thread terminated.
Sep 27 07:05:05 raspberrypi shairport-sync[452]: Time ping turnaround time: 950687 us -- it looks like a timing ping was lost.
Sep 27 07:07:05 raspberrypi shairport-sync[452]: As Yeats almost said, "Too long a silence / can make a stone of the heart" from RTSP conversation 3.
Sep 27 07:07:05 raspberrypi shairport-sync[452]: RTSP Channel unexpectedly closed or a serious error occured -- closing the player thread.
Sep 27 07:07:05 raspberrypi shairport-sync[452]: Cancelling timing, control and audio threads...
Sep 27 07:07:05 raspberrypi shairport-sync[452]: Cancel timing thread.
Sep 27 07:07:05 raspberrypi shairport-sync[452]: Join timing thread.
Sep 27 07:07:05 raspberrypi shairport-sync[452]: shutdown timing socket.
Sep 27 07:07:05 raspberrypi shairport-sync[452]: close timing socket.
Sep 27 07:07:05 raspberrypi shairport-sync[452]: Timing thread terminated.
Sep 27 07:07:05 raspberrypi shairport-sync[452]: Cancel control thread.
Sep 27 07:07:05 raspberrypi shairport-sync[452]: Join control thread.
Sep 27 07:07:05 raspberrypi shairport-sync[452]: shutdown control socket.
Sep 27 07:07:05 raspberrypi shairport-sync[452]: close control socket.
Sep 27 07:07:05 raspberrypi shairport-sync[452]: Control thread terminated.
Sep 27 07:07:05 raspberrypi shairport-sync[452]: Cancel audio thread.
Sep 27 07:07:05 raspberrypi shairport-sync[452]: Join audio thread.
Sep 27 07:07:05 raspberrypi shairport-sync[452]: shutdown audio socket.
Sep 27 07:07:05 raspberrypi shairport-sync[452]: close audio socket.
Sep 27 07:07:05 raspberrypi shairport-sync[452]: Audio thread terminated.
Sep 27 07:07:05 raspberrypi shairport-sync[452]: Freeing audio buffers and decoders.
Sep 27 07:07:05 raspberrypi shairport-sync[452]: Connection 3: player thread terminated.
Sep 27 07:07:05 raspberrypi shairport-sync[452]: Connection 3: RTSP thread terminated.
Sep 27 07:07:13 raspberrypi dhcpcd[409]: wlan0: fe80::464e:6dff:fe18:6d26 is unreachable, expiring it
Sep 27 07:07:34 raspberrypi wpa_supplicant[324]: wlan0: WPA: Group rekeying completed with 44:4e:6d:18:6d:29 [GTK=CCMP]
Sep 27 07:08:50 raspberrypi dhcpcd[409]: wlan0: fe80::464e:6dff:fe18:6d26 is unreachable, expiring it
Sep 27 07:08:52 raspberrypi systemd-timesyncd[299]: Timed out waiting for reply from [2001:638:504:2000::37]:123 (2.debian.pool.ntp.org).
Sep 27 07:09:02 raspberrypi systemd-timesyncd[299]: Timed out waiting for reply from [2a00:9e20:201::c0a2:a80c]:123 (2.debian.pool.ntp.org).
Sep 27 07:09:12 raspberrypi systemd-timesyncd[299]: Timed out waiting for reply from [2a02:2028:ff01:14::13]:123 (2.debian.pool.ntp.org).
Sep 27 07:09:23 raspberrypi systemd-timesyncd[299]: Timed out waiting for reply from [2a01:4f8:1c0c:6707::1]:123 (2.debian.pool.ntp.org).
Sep 27 07:09:33 raspberrypi systemd-timesyncd[299]: Timed out waiting for reply from 176.221.42.125:123 (2.debian.pool.ntp.org).
Sep 27 07:09:43 raspberrypi systemd-timesyncd[299]: Timed out waiting for reply from 165.227.159.15:123 (2.debian.pool.ntp.org).
Sep 27 07:09:53 raspberrypi systemd-timesyncd[299]: Timed out waiting for reply from 85.236.36.4:123 (2.debian.pool.ntp.org).
Sep 27 07:10:04 raspberrypi systemd-timesyncd[299]: Timed out waiting for reply from 80.151.151.109:123 (2.debian.pool.ntp.org).
mikebrady commented 6 years ago

That’s good news on the effect of the new router. The log is interesting. Something odd happens at 7:04:54 — an ipv6 connection is made from what looks to me a slightly unusual prefix, 2003... What is that, can you remember? Then, at 7:07:13 a log entry indicates that some local IPv6 address have become unreachable and then, later on, log entries show that access to time synchronization servers is lost. So, something strange happened on the network at 7:04:54 that seems to have messed up the network.

abid76 commented 6 years ago

The addresses with prefix 2003 are given by the internet provider. E.g. my iPhone has three ipv6 adresses in my home network: two with 2003 prefix and one with link local fe80 prefix. The router acts as DHCPv6 server and DHCPv4 server.

I'm not that familiar with ipv6 addresses. I suppose it's okay that the device has an address with 2003 prefix (as it is given by the internet provider).

I wonder about two things:

Maybe turning off the DCHPv6 server is an option ...

mikebrady commented 6 years ago

Thanks for that. I have seen iOS open an IPv6 and an IPv4 connection, so I don't think there is anything too peculiar about it. However, something else seems to be happening, which is that the Pi seems to lose connection with the time servers.

Can I ask, does (or did) the address fe80::464e:6dff:fe18:6d26 belong to the Pi or to some other device?

Reluctantly, I agree that turning off DHCPv6 might be worth experimenting with. If it works, then we will have to try to figure out what that means...

abid76 commented 6 years ago

fe80::464e:6dff:fe18:6d26 belongs to the router.

abid76 commented 6 years ago

I just wanted to let you know that my network problems (interruptions when playback, long packet reception intervals) again occured ... :-(

So it seems that there is some wifi network problem either regarding the raspberry or the router. It seems that there are two problems:

Here you see a log output where at 15:03 the connection to raspberry got lost (even ping failed):

Okt 03 15:01:00 raspberrypi shairport-sync[452]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8026.1,    27349.4,   993936.0.
Okt 03 15:01:20 raspberrypi shairport-sync[452]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7978.2,    19259.9,   101380.0.
Okt 03 15:01:40 raspberrypi shairport-sync[452]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7991.9,    19346.6,   102118.0.
Okt 03 15:02:00 raspberrypi shairport-sync[452]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8099.3,    19835.8,   205041.0.
Okt 03 15:02:20 raspberrypi shairport-sync[452]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8025.8,    19845.0,   161644.0.
Okt 03 15:02:40 raspberrypi shairport-sync[452]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7985.1,    19510.4,   110938.0.
Okt 03 15:03:18 raspberrypi wpa_supplicant[324]: wlan0: WPA: Group rekeying completed with 44:4e:6d:18:6d:29 [GTK=CCMP]
Okt 03 15:04:46 raspberrypi shairport-sync[452]: As Yeats almost said, "Too long a silence / can make a stone of the heart" from RTSP conversation 30.
Okt 03 15:04:46 raspberrypi shairport-sync[452]: RTSP Channel unexpectedly closed or a serious error occured -- closing the player thread.
Okt 03 15:04:46 raspberrypi shairport-sync[452]: Cancelling timing, control and audio threads...
Okt 03 15:04:46 raspberrypi shairport-sync[452]: Cancel timing thread.
Okt 03 15:04:46 raspberrypi shairport-sync[452]: shutdown timing socket.
Okt 03 15:04:46 raspberrypi shairport-sync[452]: close timing socket.
Okt 03 15:04:46 raspberrypi shairport-sync[452]: Join timing thread.
Okt 03 15:04:46 raspberrypi shairport-sync[452]: Timing thread terminated.

About ten minutes later the wifi connection got established again:

Okt 03 15:14:27 raspberrypi wpa_supplicant[324]: wlan0: Trying to associate with 44:4e:6d:18:6d:29 (SSID='sugar76-24' freq=2412 MHz)
Okt 03 15:14:27 raspberrypi wpa_supplicant[324]: wlan0: Associated with 44:4e:6d:18:6d:29
Okt 03 15:14:27 raspberrypi wpa_supplicant[324]: wlan0: WPA: Key negotiation completed with 44:4e:6d:18:6d:29 [PTK=CCMP GTK=CCMP]
Okt 03 15:14:27 raspberrypi wpa_supplicant[324]: wlan0: CTRL-EVENT-CONNECTED - Connection to 44:4e:6d:18:6d:29 completed [id=0 id_str=]
Okt 03 15:14:27 raspberrypi dhcpcd[409]: wlan0: carrier acquired
Okt 03 15:14:27 raspberrypi wpa_supplicant[324]: p2p-dev-wlan0: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=DE
Okt 03 15:14:27 raspberrypi dhcpcd[409]: wlan0: IAID eb:53:5f:9c
Okt 03 15:14:27 raspberrypi dhcpcd[409]: wlan0: probing address 192.168.2.50/24
Okt 03 15:14:27 raspberrypi dhcpcd[409]: wlan0: soliciting an IPv6 router
Okt 03 15:14:27 raspberrypi dhcpcd[409]: wlan0: Router Advertisement from fe80::464e:6dff:fe18:6d26
Okt 03 15:14:27 raspberrypi dhcpcd[409]: wlan0: adding address 2003:e9:6f13:2500:146a:ac37:104a:911a/64
Okt 03 15:14:27 raspberrypi dhcpcd[409]: wlan0: adding route to 2003:e9:6f13:2500::/64
Okt 03 15:14:27 raspberrypi dhcpcd[409]: wlan0: adding default route via fe80::464e:6dff:fe18:6d26
Okt 03 15:14:27 raspberrypi dhcpcd[409]: wlan0: requesting DHCPv6 information
Okt 03 15:14:29 raspberrypi avahi-daemon[423]: Leaving mDNS multicast group on interface wlan0.IPv6 with address fe80::ba27:ebff:fe53:5f9c.
Okt 03 15:14:29 raspberrypi avahi-daemon[423]: Joining mDNS multicast group on interface wlan0.IPv6 with address 2003:e9:6f13:2500:146a:ac37:104a:911a.
Okt 03 15:14:29 raspberrypi avahi-daemon[423]: Registering new address record for 2003:e9:6f13:2500:146a:ac37:104a:911a on wlan0.*.
Okt 03 15:14:29 raspberrypi avahi-daemon[423]: Withdrawing address record for fe80::ba27:ebff:fe53:5f9c on wlan0.
Okt 03 15:14:31 raspberrypi dhcpcd[409]: wlan0: using static address 192.168.2.50/24
Okt 03 15:14:31 raspberrypi avahi-daemon[423]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.2.50.
Okt 03 15:14:31 raspberrypi avahi-daemon[423]: New relevant interface wlan0.IPv4 for mDNS.
Okt 03 15:14:31 raspberrypi avahi-daemon[423]: Registering new address record for 192.168.2.50 on wlan0.IPv4.
Okt 03 15:14:31 raspberrypi dhcpcd[409]: wlan0: adding route to 192.168.2.0/24
Okt 03 15:14:31 raspberrypi dhcpcd[409]: wlan0: adding default route via 192.168.2.1
Okt 03 15:17:01 raspberrypi CRON[27243]: pam_unix(cron:session): session opened for user root by (uid=0)
Okt 03 15:17:01 raspberrypi CRON[27247]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Okt 03 15:17:01 raspberrypi CRON[27243]: pam_unix(cron:session): session closed for user root
Okt 03 15:22:18 raspberrypi shairport-sync[452]: New RTSP connection from [2003:e9:6f13:2500:1d5d:4c0a:ceb8:ed1c]:52681 to self at [2003:e9:6f13:2500:146a:ac37:104a:911a]:5000 on conversation thread 31.
Okt 03 15:22:21 raspberrypi shairport-sync[452]: RTSP thread 31 received an RTSP Packet of type "ANNOUNCE":
Okt 03 15:22:21 raspberrypi shairport-sync[452]:   Type: "Content-Length", content: "689"
Okt 03 15:22:21 raspberrypi shairport-sync[452]:   Type: "Content-Type", content: "application/sdp"
Okt 03 15:22:21 raspberrypi shairport-sync[452]:   Type: "CSeq", content: "3"
Okt 03 15:22:21 raspberrypi shairport-sync[452]:   Type: "DACP-ID", content: "11EDB82401806361"

This is log output from last night / early morning:

Okt 04 05:20:26 raspberrypi wpa_supplicant[324]: wlan0: Failed to initiate sched scan
Okt 04 05:20:31 raspberrypi wpa_supplicant[324]: wlan0: Failed to initiate sched scan
Okt 04 05:20:37 raspberrypi wpa_supplicant[324]: wlan0: Failed to initiate sched scan
Okt 04 05:20:43 raspberrypi wpa_supplicant[324]: wlan0: Failed to initiate sched scan
Okt 04 05:20:49 raspberrypi wpa_supplicant[324]: wlan0: Failed to initiate sched scan
Okt 04 05:20:55 raspberrypi wpa_supplicant[324]: wlan0: CTRL-EVENT-SSID-REENABLED id=0 ssid="sugar76-24"
Okt 04 05:20:55 raspberrypi wpa_supplicant[324]: wlan0: Trying to associate with 44:4e:6d:18:6d:29 (SSID='sugar76-24' freq=2437 MHz)
Okt 04 05:20:59 raspberrypi wpa_supplicant[324]: wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:00:00:00:00:00 status_code=16
Okt 04 05:20:59 raspberrypi wpa_supplicant[324]: wlan0: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="sugar76-24" auth_failures=18 duration=120 reason=CONN_FAILED
Okt 04 05:21:10 raspberrypi wpa_supplicant[324]: wlan0: Failed to initiate sched scan
Okt 04 05:21:16 raspberrypi wpa_supplicant[324]: wlan0: Failed to initiate sched scan
Okt 04 05:21:21 raspberrypi wpa_supplicant[324]: wlan0: Failed to initiate sched scan
...
Okt 04 06:47:59 raspberrypi avahi-daemon[423]: Joining mDNS multicast group on interface wlan0.IPv6 with address 2003:e9:6f13:2500:146a:ac37:104a:911a.
Okt 04 06:47:59 raspberrypi avahi-daemon[423]: Registering new address record for 2003:e9:6f13:2500:146a:ac37:104a:911a on wlan0.*.
Okt 04 06:47:59 raspberrypi avahi-daemon[423]: Withdrawing address record for fe80::ba27:ebff:fe53:5f9c on wlan0.
Okt 04 06:48:22 raspberrypi dhcpcd[409]: wlan0: carrier lost
Okt 04 06:48:22 raspberrypi wpa_supplicant[324]: wlan0: CTRL-EVENT-DISCONNECTED bssid=44:4e:6d:18:6d:29 reason=0 locally_generated=1
Okt 04 06:48:22 raspberrypi wpa_supplicant[324]: p2p-dev-wlan0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD
Okt 04 06:48:22 raspberrypi dhcpcd[409]: wlan0: deleting address 2003:e9:6f13:2500:146a:ac37:104a:911a/64
Okt 04 06:48:22 raspberrypi avahi-daemon[423]: Withdrawing address record for 2003:e9:6f13:2500:146a:ac37:104a:911a on wlan0.
Okt 04 06:48:22 raspberrypi dhcpcd[409]: wlan0: deleting default route via fe80::464e:6dff:fe18:6d26
Okt 04 06:48:22 raspberrypi avahi-daemon[423]: Leaving mDNS multicast group on interface wlan0.IPv6 with address 2003:e9:6f13:2500:146a:ac37:104a:911a.
Okt 04 06:48:22 raspberrypi dhcpcd[409]: wlan0: deleting route to 2003:e9:6f13:2500::/64
Okt 04 06:48:22 raspberrypi avahi-daemon[423]: Joining mDNS multicast group on interface wlan0.IPv6 with address fe80::ba27:ebff:fe53:5f9c.
Okt 04 06:48:22 raspberrypi avahi-daemon[423]: Registering new address record for fe80::ba27:ebff:fe53:5f9c on wlan0.*.
Okt 04 06:48:22 raspberrypi dhcpcd[409]: wlan0: deleting default route via 192.168.2.1
Okt 04 06:48:22 raspberrypi dhcpcd[409]: wlan0: deleting route to 192.168.2.0/24
Okt 04 06:48:22 raspberrypi avahi-daemon[423]: Withdrawing address record for 192.168.2.50 on wlan0.
Okt 04 06:48:22 raspberrypi avahi-daemon[423]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 192.168.2.50.
Okt 04 06:48:22 raspberrypi avahi-daemon[423]: Interface wlan0.IPv4 no longer relevant for mDNS.
Okt 04 06:48:23 raspberrypi wpa_supplicant[324]: wlan0: Trying to associate with 44:4e:6d:18:6d:29 (SSID='sugar76-24' freq=2437 MHz)
Okt 04 06:48:23 raspberrypi wpa_supplicant[324]: wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:00:00:00:00:00 status_code=16
Okt 04 06:48:24 raspberrypi wpa_supplicant[324]: wlan0: Trying to associate with 44:4e:6d:18:6d:29 (SSID='sugar76-24' freq=2437 MHz)

The ping from my MacBook to the raspberry shows extremely varying figures. The figures are similar when pinging my iPhone - this indicates that the wifi network itself is "slow".

Abids-MBP:~ Abid$ ping 192.168.2.50
PING 192.168.2.50 (192.168.2.50): 56 data bytes
64 bytes from 192.168.2.50: icmp_seq=0 ttl=64 time=6.897 ms
64 bytes from 192.168.2.50: icmp_seq=1 ttl=64 time=3.721 ms
64 bytes from 192.168.2.50: icmp_seq=2 ttl=64 time=4.295 ms
64 bytes from 192.168.2.50: icmp_seq=3 ttl=64 time=13.830 ms
64 bytes from 192.168.2.50: icmp_seq=4 ttl=64 time=93.853 ms
64 bytes from 192.168.2.50: icmp_seq=5 ttl=64 time=4.359 ms
64 bytes from 192.168.2.50: icmp_seq=6 ttl=64 time=28.431 ms
64 bytes from 192.168.2.50: icmp_seq=7 ttl=64 time=57.893 ms
64 bytes from 192.168.2.50: icmp_seq=8 ttl=64 time=99.651 ms
64 bytes from 192.168.2.50: icmp_seq=9 ttl=64 time=18.190 ms
64 bytes from 192.168.2.50: icmp_seq=10 ttl=64 time=7.745 ms
64 bytes from 192.168.2.50: icmp_seq=11 ttl=64 time=3.708 ms
64 bytes from 192.168.2.50: icmp_seq=12 ttl=64 time=9.499 ms
64 bytes from 192.168.2.50: icmp_seq=13 ttl=64 time=41.103 ms
64 bytes from 192.168.2.50: icmp_seq=14 ttl=64 time=4.067 ms
64 bytes from 192.168.2.50: icmp_seq=15 ttl=64 time=4.223 ms
64 bytes from 192.168.2.50: icmp_seq=16 ttl=64 time=21.096 ms
64 bytes from 192.168.2.50: icmp_seq=17 ttl=64 time=3.289 ms
64 bytes from 192.168.2.50: icmp_seq=18 ttl=64 time=20.095 ms
64 bytes from 192.168.2.50: icmp_seq=19 ttl=64 time=47.463 ms
64 bytes from 192.168.2.50: icmp_seq=20 ttl=64 time=106.254 ms
64 bytes from 192.168.2.50: icmp_seq=21 ttl=64 time=22.819 ms
mikebrady commented 6 years ago

Yes, it really looks like a network problem alright. Does anything like this happen on other devices, apart from the Pi? Are you using the Pi's built-in WiFi? And, last question for now, is the pi software reasonably up-to-date?

mikebrady commented 6 years ago

There's a command-line utility you can use to explore the quality of WiFi on the Pi -- wavemon. It might be worth installing and trying out.

abid76 commented 6 years ago

Does anything like this happen on other devices, apart from the Pi?

I never experienced any wifi problems with other devices (MacBook, iPhone, TV) except from my printer but the printer is a little buggy at all as it is a low cost product.

Are you using the Pi's built-in WiFi?

Yes, it has a static ip address configured by dhcpcd.conf

And, last question for now, is the pi software reasonably up-to-date?

Yes, I installed a fresh raspbian stretch about two months ago and ran the update procedure.

abid76 commented 6 years ago

There are a lot of wifi networks in my surroundings, especially on the 2.4 GHz frequency. The ping results are remarkably better on the 5GHz frequency. This seems to be an explanation for the shuttering, but not for the loss of the wifi connection.

wifi-networks

abid76 commented 6 years ago

Just wanted to give you an update. I tried out the new raspberry 3 B+ which can use the 5 GHz frequency.

The figures are better compared with the old raspberry on the 2.4 GHz frequency but still not very good.

Maybe it's just because of all the other wifi networks in my surroundings (see above).

Here are two Log outputs recorded both at the same time.

Raspberry 3 B+ 5 GHz:

Okt 10 00:07:54 raspberrypi5 shairport-sync[1217]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7990.8,    18583.8,    92712.0.
Okt 10 00:08:14 raspberrypi5 shairport-sync[1217]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8004.8,    20448.0,   163354.0.
Okt 10 00:08:34 raspberrypi5 shairport-sync[1217]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7966.0,    18553.0,    97119.0.
Okt 10 00:08:54 raspberrypi5 shairport-sync[1217]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7990.9,    18643.0,    92982.0.
Okt 10 00:09:14 raspberrypi5 shairport-sync[1217]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.9,    20614.6,   163790.0.
Okt 10 00:09:34 raspberrypi5 shairport-sync[1217]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7989.9,    18639.3,   136804.0.
Okt 10 00:09:54 raspberrypi5 shairport-sync[1217]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7990.4,    18439.1,    92002.0.
Okt 10 00:10:13 raspberrypi5 shairport-sync[1217]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7955.1,    20285.3,   164048.0.
Okt 10 00:10:33 raspberrypi5 shairport-sync[1217]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7929.1,    18587.1,   144998.0.
Okt 10 00:10:53 raspberrypi5 shairport-sync[1217]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7944.8,    18519.3,    92476.0.
Okt 10 00:11:13 raspberrypi5 shairport-sync[1217]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8028.9,    20427.3,   163999.0.
Okt 10 00:11:33 raspberrypi5 shairport-sync[1217]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7944.3,    18815.7,   159302.0.
Okt 10 00:11:53 raspberrypi5 shairport-sync[1217]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.4,    18550.5,    92724.0.
Okt 10 00:12:13 raspberrypi5 shairport-sync[1217]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8009.1,    20316.2,   164365.0.
Okt 10 00:12:33 raspberrypi5 shairport-sync[1217]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7972.8,    19060.4,   162973.0.
Okt 10 00:12:53 raspberrypi5 shairport-sync[1217]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.0,    18463.6,    92193.0.
Okt 10 00:13:13 raspberrypi5 shairport-sync[1217]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7991.9,    20195.2,   164815.0.
Okt 10 00:13:33 raspberrypi5 shairport-sync[1217]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7990.8,    19195.8,   164309.0.
Okt 10 00:13:53 raspberrypi5 shairport-sync[1217]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.3,    18571.8,    92742.0.
Okt 10 00:14:13 raspberrypi5 shairport-sync[1217]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7989.8,    20034.7,   162747.0.
Okt 10 00:14:33 raspberrypi5 shairport-sync[1217]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7991.7,    18965.0,   162669.0.
Okt 10 00:14:53 raspberrypi5 shairport-sync[1217]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7978.2,    18522.2,    92487.0.

Raspberry 3 B 2.4GHz:

Okt 10 00:07:54 raspberrypi shairport-sync[479]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7972.5,    19322.1,   157033.0.
    Okt 10 00:08:14 raspberrypi shairport-sync[479]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7981.5,    12216.0,   268181.0.
Okt 10 00:08:34 raspberrypi shairport-sync[479]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7981.6,    16476.1,   177615.0.
Okt 10 00:08:54 raspberrypi shairport-sync[479]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7981.8,    11827.2,   173799.0.
Okt 10 00:09:14 raspberrypi shairport-sync[479]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7982.8,    16231.8,   182877.0.
Okt 10 00:09:34 raspberrypi shairport-sync[479]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7990.5,    12049.5,   197619.0.
Okt 10 00:09:54 raspberrypi shairport-sync[479]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7976.0,    19667.7,   181129.0.
Okt 10 00:10:14 raspberrypi shairport-sync[479]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.9,    12601.6,   267609.0.
Okt 10 00:10:34 raspberrypi shairport-sync[479]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7978.4,    15841.2,   173067.0.
Okt 10 00:10:54 raspberrypi shairport-sync[479]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7981.5,    16826.1,   176297.0.
Okt 10 00:11:14 raspberrypi shairport-sync[479]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7981.7,    11483.6,   180899.0.
Okt 10 00:11:34 raspberrypi shairport-sync[479]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8007.3,    15683.8,   174421.0.
Okt 10 00:11:54 raspberrypi shairport-sync[479]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7987.9,    17275.5,   219556.0.
Okt 10 00:12:14 raspberrypi shairport-sync[479]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8102.6,    14077.4,   179270.0.
Okt 10 00:12:34 raspberrypi shairport-sync[479]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7968.8,    15538.9,   242629.0.
Okt 10 00:12:54 raspberrypi shairport-sync[479]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8036.8,    13239.7,   207743.0.
Okt 10 00:13:14 raspberrypi shairport-sync[479]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8006.3,    15118.3,   179116.0.
Okt 10 00:13:34 raspberrypi shairport-sync[479]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8016.5,    12046.0,   165688.0.
Okt 10 00:13:54 raspberrypi shairport-sync[479]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7992.6,    19702.7,   195253.0.
Okt 10 00:14:14 raspberrypi shairport-sync[479]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8003.8,    12014.7,   166921.0.
Okt 10 00:14:20 raspberrypi wpa_supplicant[308]: wlan0: WPA: Group rekeying completed with 44:4e:6d:18:6d:29 [GTK=CCMP]
Okt 10 00:14:34 raspberrypi shairport-sync[479]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8013.3,    16503.5,   270404.0.
Okt 10 00:14:55 raspberrypi shairport-sync[479]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8031.5,    17587.8,   265974.0.
Okt 10 00:15:15 raspberrypi shairport-sync[479]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7997.7,    11999.5,   175349.0.
mikebrady commented 6 years ago

Both of those look alright to me, TBH. It's just that sometimes the whole network gets into a bad state. Could it be a microwave in the vicinity, I wonder?

abid76 commented 6 years ago

Could it be a microwave in the vicinity, I wonder? Could be one of my neighbours ...

I'll close this issue as there has been neither any interruptions recently nor did I experience any problems in network discovery regarding the Bonjour (RAOP) service.

This is the case since I'm using the 5 GHz band together with a new Raspberry 3+. Maybe the new router also improved the network stability but I'm not sure about this.

Thanks for this time especially for your detailed explanation about the log figures which helped me a lot to understand what's going on 👍

mikebrady commented 6 years ago

Thanks.

bedrin commented 5 years ago

I had the same issues with my Zyxel Keenetic Extra II router. Fixed by changing the SID of 2.4GHz network to a different one (and obviously reconnecting old 2.4GHz devices to new network).

Raspberry was already using 5GHz before I made my change but my iPhone tended to connect to 2.4GHz network. When it was on 5GHz it was fine but I couldn't figure out what was the difference and it was just driving me crazy!