search

mikebrady / shairport-sync

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

audio glitch when turned on soxr #873

Closed chuhuanping closed 5 years ago

chuhuanping commented 5 years ago

pi@raspberrypi:~ $ cat /proc/asound/card1/stream0 Sony Sony Audio at usb-20980000.usb-1.3, high speed : USB Audio

Playback: Status: Running Interface = 1 Altset = 1 Packet Size = 72 Momentary freq = 44104 Hz (0x5.8357) Feedback Format = 16.16 Interface 1 Altset 1 Format: S32_LE Channels: 2 Endpoint: 1 OUT (ASYNC) Rates: 32000, 44100, 48000, 88200, 96000, 176400, 192000, 352800, 384000 Data packet interval: 125 us

I have a SONY USB DAC, which reports the wrong timing 44104Hz. I turned on soxr in CONF file,still can hear the glitch for each couple minutes.

> 0.037454906|Started!
>          0.005582837|software version: "3.3.2d2-OpenSSL-Avahi-ALSA-soxr-metadata-sysconfdir:/etc"
>          0.003320903|log verbosity is 1.
>          0.001717950|alsa: alsa_maximum_stall_time of 0.200000 sec.
>          0.001376960|alsa: disable_standby_mode is "never".
>          0.000291991|alsa: disable_standby_mode_silence_threshold is 0.040000 seconds.
>          0.002153937|alsa: disable_standby_mode_silence_scan_interval is 0.004000 seconds.
>          0.000433988|alsa: output device name is "hw:1".
>          0.008985737|disable resend requests is off.
>          0.002678922|diagnostic_drop_packet_fraction is 0.000000. A value of 0.0 means no packets will be dropped deliberately.
>          0.000431987|statistics_requester status is 0.
>          0.000202995|rtsp listening port is 5000.
>          0.002243934|udp base port is 6001.
>          0.001291962|udp port range is 10.
>          0.000233993|player name is "Raspberrypi".
>          0.000547984|backend is "(null)".
>          0.001648952|run_this_before_play_begins action is "(null)".
>          0.001441958|run_this_after_play_ends action is "(null)".
>          0.000376989|wait-cmd status is 0.
>          0.000198994|run_this_before_play_begins may return output is 0.
>          0.000442987|run_this_if_an_unfixable_error_is_detected action is "(null)".
>          0.001401959|run_this_before_entering_active_state action is  "(null)".
>          0.000608983|run_this_after_exiting_active_state action is  "(null)".
>          0.000207994|active_state_timeout is  10.000000 seconds.
>          0.000195994|mdns backend "(null)".
>          0.000420988|interpolation setting is "soxr".
>          0.002187936|interpolation soxr_delay_threshold is 30.
>          0.000252992|resync time is 0.050000 seconds.
>          0.000619982|allow a session to be interrupted: 0.
>          0.003415900|busy timeout time is 120.
>          0.000244993|drift tolerance is 0.001995 seconds.
>          0.000569984|password is "(null)".
>          0.000196994|ignore_volume_control is 1.
>          0.000180995|volume_max_db is not set
>          0.000378989|volume range in dB (zero means use the range specified by the mixer): 0.
>          0.002179936|volume_range_combined_hardware_priority (1 means hardware mixer attenuation is used first) is 0.
>          0.000484986|playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
>          0.001850946|disable_synchronization is 0.
>          0.000485985|use_mmap_if_available is 1.
>          0.001373960|output_format automatic selection is enabled.
>          0.000236993|output_rate automatic selection is enabled.
>          0.000499986|audio backend desired buffer length is 0.200000 seconds.
>          0.000219993|audio_backend_buffer_interpolation_threshold_in_seconds is 0.120000 seconds.
>          0.000474987|audio backend latency offset is 0.000000 seconds.
>          0.001608953|audio backend silence lead-in time is -1.000000 seconds. A value -1.0 means use the default.
>          0.001120967|zeroconf regtype is "_raop._tcp".
>          0.000279992|decoders_supported field is 3.
>          0.000541984|use_apple_decoder is 1.
>          0.000196994|alsa_use_hardware_mute is 0.
>          0.000475986|no special mdns service interface was requested.
>          0.001010971|configuration file name "/etc/shairport-sync.conf" resolves to "/etc/shairport-sync.conf".
>          0.000392988|metadata enabled is 1.
>          0.002112938|metadata pipename is "/tmp/shairport-sync-metadata".
>          0.001431959|metadata socket address is "(null)" port 0.
>          0.000234993|metadata socket packet size is "500".
>          0.000184994|get-coverart is 1.
>          0.000281992|loudness is 0.
>          0.001446958|loudness reference level is -20.000000
>          0.024194293|Unable to listen on IPv4 port 5000. The error is: "Address already in use".
>          0.003314903|Unable to listen on IPv6 port 5000. The error is: "Address already in use".
> 
> 
>
mikebrady commented 5 years ago

Thanks for the post. The log does not reveal anything unusual. If you could enable statistics and post a log including statistics covering the time of a glitch, it would be very useful.

chuhuanping commented 5 years ago 

Jul 04 07:03:45 raspberrypi systemd[1]: Started Shairport Sync - AirPlay Audio Receiver.
Jul 04 07:03:55 raspberrypi shairport-sync[824]: sync error in milliseconds, net correction in ppm, corrections in ppm, total packets, missing packets, late packets, too late packets, resend requests, min DAC queue size, min buffer occupancy, max buffer occupancy, source
Jul 04 07:04:05 raspberrypi shairport-sync[824]:       1.24,     -46.0,      46.0,        1003,      0,      0,      0,      0,   8203,  221,  241,   44100.04,   44139.28,   44097.66,      0.00,     0,    -53.85
Jul 04 07:04:13 raspberrypi shairport-sync[824]:       1.87,    -167.1,     167.1,        2006,      0,      0,      0,      0,   6149,  229,  244,   44099.96,   44183.40,   44091.84,      0.00,     0,   -184.25
Jul 04 07:04:21 raspberrypi shairport-sync[824]:       1.33,     -73.6,      73.6,        3009,      0,      0,      0,      0,   8230,  229,  242,   44100.00,   44008.72,   44093.33,      0.00,     0,   -151.13
Jul 04 07:04:29 raspberrypi shairport-sync[824]:       0.97,       0.0,       0.0,        4012,      0,      0,      0,      0,   8312,  229,  241,   44099.98,   44104.97,   44095.26,      0.00,     0,   -107.03
Jul 04 07:04:37 raspberrypi shairport-sync[824]:       0.90,     -36.8,      36.8,        5015,      0,      0,      0,      0,   5109,  229,  246,   44100.01,   44107.97,   44095.17,      0.00,     0,   -109.73
Jul 04 07:04:45 raspberrypi shairport-sync[824]:       1.73,    -110.5,     110.5,        6018,      0,      0,      0,      0,   7079,  229,  243,   44100.00,   44116.05,   44096.22,      0.00,     0,    -85.72
Jul 04 07:04:53 raspberrypi shairport-sync[824]:       1.29,     -11.3,      11.3,        7021,      0,      0,      0,      0,   8326,  229,  242,   44099.99,   44095.85,   44096.42,      0.00,     0,    -80.95
Jul 04 07:05:01 raspberrypi shairport-sync[824]:       1.80,    -141.6,     153.0,        8024,      0,      0,      0,      0,   7819,  229,  242,   44099.99,   44110.02,   44096.19,      0.00,     0,    -86.18
lines 1-18/18 (END)
pi@raspberrypi:~ $ sudo systemctl status shairport-sync
● shairport-sync.service - Shairport Sync - AirPlay Audio Receiver
   Loaded: loaded (/lib/systemd/system/shairport-sync.service; enabled; vendor preset: enabled)
   Active: active (running) since Thu 2019-07-04 07:03:45 CST; 2min 6s ago
 Main PID: 824 (shairport-sync)
   Memory: 4.5M
   CGroup: /system.slice/shairport-sync.service
           └─824 /usr/local/bin/shairport-sync

Jul 04 07:04:37 raspberrypi shairport-sync[824]:       0.90,     -36.8,      36.8,        5015,      0,      0,      0,      0,   5109,  229,  246,   44100.01,   44107.97,   44095.17,      0.00,     0,   -109.73
Jul 04 07:04:45 raspberrypi shairport-sync[824]:       1.73,    -110.5,     110.5,        6018,      0,      0,      0,      0,   7079,  229,  243,   44100.00,   44116.05,   44096.22,      0.00,     0,    -85.72
Jul 04 07:04:53 raspberrypi shairport-sync[824]:       1.29,     -11.3,      11.3,        7021,      0,      0,      0,      0,   8326,  229,  242,   44099.99,   44095.85,   44096.42,      0.00,     0,    -80.95
Jul 04 07:05:01 raspberrypi shairport-sync[824]:       1.80,    -141.6,     153.0,        8024,      0,      0,      0,      0,   7819,  229,  242,   44099.99,   44110.02,   44096.19,      0.00,     0,    -86.18
Jul 04 07:05:09 raspberrypi shairport-sync[824]:       1.85,    -203.9,     203.9,        9027,      0,      0,      0,      0,   4453,  229,  247,   44100.00,   44107.35,   44095.68,      0.00,     0,    -97.91
Jul 04 07:05:17 raspberrypi shairport-sync[824]:       1.08,      -5.7,       5.7,       10030,      0,      0,      0,      0,   8286,  229,  242,   44100.00,   44095.12,   44096.14,      0.00,     0,    -87.57
Jul 04 07:05:25 raspberrypi shairport-sync[824]:       0.69,       0.0,       0.0,       11033,      0,      0,      0,      0,   8359,  229,  241,   44100.00,   44097.80,   44096.76,      0.00,     0,    -73.57
Jul 04 07:05:33 raspberrypi shairport-sync[824]:       0.62,       0.0,       0.0,       12036,      0,      0,      0,      0,   8329,  229,  241,   44099.99,   44102.69,   44096.56,      0.00,     0,    -77.92
Jul 04 07:05:41 raspberrypi shairport-sync[824]:       1.25,      -2.8,       2.8,       13039,      0,      0,      0,      0,   8226,  229,  241,   44100.00,   44109.46,   44097.20,      0.00,     0,    -63.52
Jul 04 07:05:49 raspberrypi shairport-sync[824]:       1.58,     -28.3,      28.3,       14042,      0,      0,      0,      0,   8289,  229,  241,   44100.00,   44101.02,   44096.93,     -9.37,     9,    -60.24
mikebrady commented 5 years ago

Thanks for the update. It does look like something unusual happened between 07:05:01 and 07:05:09. The minimum DAC queue size, which should be nominally 8,450 to 8,800 frames, drops to 4,459, indicating a sudden load on the system.

Maybe the system is just too slow for the load it is under. To get an idea, could you let us know what model of Raspberry Pi you are using please?

Also, if you start with a log verbosity of 2 and post part of the log that looks something like the following:

Jul 04 08:31:45 RaspberryPi3BP shairport-sync[28500]:          0.583881380 "shairport.c:228" soxr_delay_index: 5.
Jul 04 08:31:45 RaspberryPi3BP shairport-sync[28500]:          0.000086875 "shairport.c:235" "soxr" interpolation has been chosen.

The soxr_delay_index is an indication of how long some soxr calculations take on the device, and the lower it is the better. If it is 30 or greater, the device is deemed too slow for soxr, and basic interpolation is chosen. This log (from a Pi 3B Plus) has a slightly different format – it's coming from an experimental edition of Shairport Sync.

Here is part of the log from a Pi B:

Jul 04 09:22:17 RaspberryPiB shairport-sync[7044]:          0.427157980|soxr_delay_index: 39.
Jul 04 09:22:17 RaspberryPiB shairport-sync[7044]:          0.005481769|"basic" interpolation has been chosen.

and here is one from a Pi Zero W:

Jul 04 09:56:05 zeropi shairport-sync[17150]:          0.466944996 "shairport.c:228" soxr_delay_index: 22.
Jul 04 09:56:05 zeropi shairport-sync[17150]:          0.003923966 "shairport.c:235" "soxr" interpolation has been chosen.

(Incidentally, the column that's fourth from the end of the statistics entries is an estimate of the true speed of the DAC. If the device's clock has been well conditioned by an ntp server and there are no DAC underruns, this figure should be accurate after a settling time. Furthermore, if you let the statistics run for maybe 10 or 15 minutes, you should also get an accurate estimate of the drift, in parts per million, between the source clock and the local device clock in the third column from the end.)

chuhuanping commented 5 years ago

0.593174146|soxr_delay_index: 22 First Generation RPI on default 700MHz CPU clock.

 0.020251491|sync error in milliseconds, net correction in ppm, corrections in ppm, total packets, missing packets, late packets, too late packets, resend requests, min DAC queue size, min buffer occupancy, max buffer occupancy, source nominal frames per second, source actual frames per second, output frames per second, source clock drift in ppm, source clock drift sample count, rough calculated correction in ppm
        10.051046642|     -0.52,       0.0,       0.0,        1003,      0,      0,      0,      0,   8634,  257,  258,   44096.51,   44096.17,   44094.09,      0.00,     0,    -54.97
         8.006335142|     -0.60,       0.0,       0.0,        2006,      0,      0,      0,      0,   8578,  257,  258,   44096.51,   44096.56,   44094.79,      0.00,     0,    -39.03
         8.006202189|     -0.54,       0.0,       0.0,        3009,      0,      0,      0,      0,   8611,  257,  258,   44096.51,   44096.48,   44096.72,      0.00,     0,      4.72
         8.006850246|     -0.62,       0.0,       0.0,        4012,      0,      0,      0,      0,   8628,  257,  258,   44096.51,   44096.42,   44096.33,      0.00,     0,     -4.27
         8.005811377|     -0.47,       0.0,       0.0,        5015,      0,      0,      0,      0,   8631,  257,  258,   44096.51,   44097.18,   44095.62,      0.00,     0,    -20.29
         8.006810484|      0.15,       0.0,       0.0,        6018,      0,      0,      0,      0,   8638,  257,  258,   44096.51,   44096.58,   44094.78,      0.00,     0,    -39.35
         8.006318660|      0.52,       0.0,       0.0,        7021,      0,      0,      0,      0,   8647,  257,  258,   44096.51,   44096.80,   44095.69,      0.00,     0,    -18.64
         8.007084829|      0.28,       0.0,       0.0,        8024,      0,      0,      0,      0,   8696,  257,  258,   44096.51,   44096.27,   44096.16,      0.00,     0,     -8.05
         8.005810083|      0.34,       0.0,       0.0,        9027,      0,      0,      0,      0,   8623,  257,  258,   44096.51,   44096.65,   44094.83,      0.00,     0,    -38.20
         8.007080295|      1.30,      -2.8,       2.8,       10030,      0,      0,      0,      0,   8581,  257,  258,   44096.51,   44096.42,   44095.27,      0.00,     0,    -28.11
         8.005736606|      1.00,       0.0,       0.0,       11033,      0,      0,      0,      0,   8710,  257,  258,   44096.51,   44096.47,   44095.37,      0.00,     0,    -25.92
         8.006001899|      0.92,       0.0,       0.0,       12036,      0,      0,      0,      0,   8660,  257,  258,   44096.51,   44096.75,   44095.48,      0.00,     0,    -23.41
         8.007380187|      1.10,       0.0,       0.0,       13039,      0,      0,      0,      0,   8609,  257,  258,   44096.51,   44096.43,   44095.55,      0.00,     0,    -21.83
         8.005865583|      1.23,      -2.8,       2.8,       14042,      0,      0,      0,      0,   8417,  256,  258,   44096.51,   44096.60,   44095.89,      0.00,     0,    -14.19
         8.006845932|      0.62,       0.0,       0.0,       15045,      0,      0,      0,      0,   8665,  257,  258,   44096.51,   44096.42,   44095.89,      0.58,     9,    -14.79
         8.005870364|      0.24,       0.0,       0.0,       16048,      0,      0,      0,      0,   8690,  257,  258,   44096.51,   44096.66,   44095.98,      1.09,    10,    -13.19
         8.007580742|      0.75,       0.0,       0.0,       17051,      0,      0,      0,      0,   8677,  257,  258,   44096.51,   44096.28,   44096.13,      0.58,    11,     -9.22
         8.005765248|      0.96,       0.0,       0.0,       18054,      0,      0,      0,      0,   8647,  257,  258,   44096.51,   44096.53,   44095.85,      0.58,    11,    -15.69
         8.005758726|      1.39,       0.0,       0.0,       19057,      0,      0,      0,      0,   8699,  257,  258,   44096.51,   44096.73,   44095.72,      1.38,    12,    -19.45
         8.006971191|      1.46,     -19.8,      19.8,       20060,      0,      0,      0,      0,   8635,  257,  258,   44096.51,   44096.52,   44095.72,      1.38,    12,    -19.42
         8.006556726|      1.20,       0.0,       0.0,       21063,      0,      0,      0,      0,   8575,  251,  258,   44096.51,   44096.56,   44095.92,      1.15,    14,    -14.72
         8.006418278|      1.32,       0.0,       0.0,       22066,      0,      0,      0,      0,   8589,  257,  258,   44096.51,   44096.51,   44096.01,      1.15,    14,    -12.61
         8.006264854|      1.24,      -2.8,       2.8,       23069,      0,      0,      0,      0,   8659,  257,  258,   44096.51,   44096.57,   44095.99,      0.88,    16,    -12.84
         8.005862457|      1.52,     -28.3,      28.3,       24072,      0,      0,      0,      0,   8612,  257,  258,   44096.51,   44096.72,   44095.91,      1.33,    17,    -15.06
         8.006868041|      1.27,      -2.8,       2.8,       25075,      0,      0,      0,      0,   8664,  257,  258,   44096.51,   44096.57,   44095.88,      1.60,    18,    -15.90
         8.008066638|      1.63,     -14.2,      14.2,       26078,      0,      0,      0,      0,   8683,  257,  258,   44096.51,   44096.62,   44095.80,      1.63,    19,    -17.80
         8.004342409|      1.65,     -45.3,      45.3,       27081,      0,      0,      0,      0,   8619,  256,  258,   44096.51,   44096.55,   44095.86,      1.82,    21,    -16.73
         8.006743013|      1.67,     -59.5,      59.5,       28084,      0,      0,      0,      0,   8448,  256,  258,   44096.51,   44096.64,   44095.86,      1.65,    22,    -16.48
         8.006936704|      2.56,    -801.6,     801.6,       29087,      0,      0,      0,      0,   4668,  256,  270,   44096.51,   44096.55,   44094.41,      1.91,    23,    -49.69
         8.008795363|      2.06,    -291.7,     291.7,       30090,      0,      0,      0,      0,   8398,  256,  259,   44096.51,   44096.66,   44094.07,      1.91,    23,    -57.39
         8.007411144|      1.80,     -96.3,      96.3,       31093,      0,      0,      0,      0,   8540,  257,  258,   44096.51,   44096.53,   44094.15,      2.07,    24,    -55.69
         8.002612053|      1.71,     -68.0,      68.0,       32096,      0,      0,      0,      0,   8616,  254,  258,   44096.51,   44096.60,   44094.24,      2.13,    25,    -53.73
         8.006068721|      1.24,       0.0,       0.0,       33099,      0,      0,      0,      0,   8719,  257,  258,   44096.51,   44096.63,   44094.33,      2.13,    25,    -51.73
         8.006932489|      1.31,     -19.8,      19.8,       34102,      0,      0,      0,      0,   8578,  253,  258,   44096.51,   44096.58,   44094.31,      2.15,    26,    -52.11
         8.005862338|      1.89,    -198.3,     198.3,       35105,      0,      0,      0,      0,   8270,  255,  259,   44096.51,   44096.68,   44094.06,      2.36,    27,    -57.94
         8.007036133|      1.73,     -56.6,      56.6,       36108,      0,      0,      0,      0,   8289,  256,  258,   44096.51,   44096.57,   44094.08,      2.52,    28,    -57.75
         8.005960018|      1.52,     -31.2,      31.2,       37111,      0,      0,      0,      0,   8505,  256,  258,   44096.51,   44096.64,   44094.07,      2.43,    30,    -57.90
         8.009340778|      1.50,     -14.2,      14.2,       38114,      0,      0,      0,      0,   8650,  257,  258,   44096.51,   44096.71,   44094.27,      2.65,    32,    -53.55
         8.003612849|      1.52,     -14.2,      14.2,       39117,      0,      0,      0,      0,   8594,  257,  258,   44096.51,   44096.64,   44094.17,      2.73,    33,    -55.89
         8.008493595|      1.84,    -184.1,     184.1,       40120,      0,      0,      0,      0,   8285,  257,  259,   44096.51,   44096.68,   44093.99,      2.73,    33,    -60.01
         8.004051660|      1.71,     -96.3,      96.3,       41123,      0,      0,      0,      0,   6742,  256,  263,   44096.51,   44096.65,   44094.01,      2.79,    34,    -59.54
         8.006037533|      1.83,    -107.6,     113.3,       42126,      0,      0,      0,      0,   6033,  257,  265,   44096.51,   44096.72,   44093.95,      2.91,    35,    -61.13
         8.007179450|      1.68,     -51.0,      51.0,       43129,      0,      0,      0,      0,   8452,  256,  258,   44096.51,   44096.60,   44093.99,      2.91,    35,    -60.12
         8.005976459|      1.80,    -130.3,     136.0,       44132,      0,      0,      0,      0,   7589,  257,  261,   44096.51,   44096.67,   44093.91,      3.00,    36,    -61.95
chuhuanping commented 5 years ago 
 0.016776422|avahi: request to add "_raop._tcp" service with metadata
         0.020685286|avahi: service 'AF31192A3A11@Raspberrypi' group is registering.
         0.880276623|avahi: service 'AF31192A3A11@Raspberrypi' successfully added.
         0.544709199|soxr_delay_index: 22.
         7.540158324|Connection 1: new connection from 192.168.11.2:57925 to self at 192.168.11.3:5000.
         0.011042618|Connection 1: Received an RTSP Packet of type "ANNOUNCE":
mikebrady commented 5 years ago

Many thanks. As far as I can see, it all looks pretty good except for that -801.6 ppm correction followed by another large one at -291.7, which are very large and does not look unnecessary – it's not followed by a drift in the opposite direction. The source clock drift is very low and stable, so it looks unlikely that clocks suddenly changed.

If you direct the output to the built-in DAC rather than the Sony USB, does the problem persist? Of course the quality won't be as good, but I wonder if the glitch is there on the built-in DAC.

chuhuanping commented 5 years ago

Rpi built-in DAC always fine, I checked by headphone.

mikebrady commented 5 years ago

Thanks. This may indicate a problem with the Sony USB system. However, there are a few things to try in Shairport Sync to work around the issue.

One thing to try is to set the use_precision_timing in the alsa section of the configuration file to "no". (It may be that the information being returned by the Sony driver for precision timing is incorrect.)

Another thing to try is to set the output_format to "S16", i.e. 16-bit operation, to see if the problem persists. If it goes away, then try one of the 24-bit settings, as they will sound somewhat better.

chuhuanping commented 5 years ago

Turning off "Precision timing" resolved my problem. Thanks

mikebrady commented 5 years ago

I’m glad it worked, and thanks for your efforts.