Chord 2qute and my DOP challenge

michaelvv · 2017-08-04 9:34 am

Hi.

2 small 1-2 secs stops and I see absolutely nothing in the squeezelite.log.

Code:

/usr/bin/squeezelite -o front:CARD=D2Qute,DEV=0 -n michael -a :::0 -b 10000:10000 -D -p 45 -d all=debug -f /tmp/squeezelite.log -s 172.16.0.93 
[10:28:34.621373] stream_init:294 init stream
[10:28:34.621404] stream_init:295 streambuf size: 10240000
[10:28:34.622687] output_init_alsa:873 init output
[10:28:34.622707] output_init_alsa:902 requested alsa_buffer: 40 alsa_period: 4 format: any mmap: 0
[10:28:34.622718] output_init_common:347 outputbuf size: 10240000
[10:28:34.622743] output_init_common:371 idle timeout: 0
[10:28:34.627273] output_init_common:411 supported rates: 384000 352800 192000 176400 96000 88200 48000 44100 32000 
[10:28:34.768428] output_init_alsa:928 memory locked
[10:28:34.768601] output_init_alsa:951 set output sched fifo rt: 45
[10:28:34.768613] decode_init:153 init decode
[10:28:34.768628] output_thread:621 open output device: front:CARD=D2Qute,DEV=0
[10:28:34.769046] alsa_open:338 opening device at: 44100
[10:28:34.768655] register_dsd:625 using dsd to decode dsf,dff
[10:28:34.769369] alsa_open:389 opened device front:CARD=D2Qute,DEV=0 using format: S32_LE sample rate: 44100 mmap: 0
[10:28:34.769398] alsa_open:468 buffer: 40 period: 4 -> buffer size: 1764 period size: 441
[10:28:34.771124] register_ff:770 using ffmpeg to decode alc
[10:28:34.771145] register_ff:754 using ffmpeg to decode wma,wmap,wmal
[10:28:34.771150] register_faad:641 using faad to decode aac
[10:28:34.771154] register_vorbis:334 using vorbis to decode ogg
[10:28:34.771158] register_flac:286 using flac to decode flc
[10:28:34.771161] register_pcm:414 using pcm to decode aif,pcm
[10:28:34.771166] register_mad:413 using mad to decode mp3
[10:28:34.771169] decode_init:185 include codecs:  exclude codecs: 
[10:28:34.772091] slimproto:925 connecting to 172.16.0.93:3483
[10:28:34.772806] slimproto:964 connected
[10:28:34.772836] sendHELO:138 mac: fc:45:96:46:f0:8b
[10:28:34.772843] sendHELO:140 cap: Model=squeezelite,AccuratePlayPoints=1,HasDigitalOut=1,HasPolarityInversion=1,Firmware=v1.8.6-987,ModelName=SqueezeLite,MaxSampleRate=384000,dsf,dff,alc,wma,wmap,wmal,aac,ogg,flc,aif,pcm,mp3
[10:28:34.786909] process:526 strm
[10:28:34.786942] process_strm:272 strm command q
[10:28:34.786948] decode_flush:227 decode flush
[10:28:34.786953] output_flush:424 flush output buffer
[10:28:34.786957] sendSTAT:187 STAT: STMf
[10:28:34.786983] process:526 strm
[10:28:34.786993] process_strm:272 strm command q
[10:28:34.786999] decode_flush:227 decode flush
[10:28:34.787004] output_flush:424 flush output buffer
[10:28:34.787010] sendSTAT:187 STAT: STMf
[10:28:34.787017] process:526 setd
[10:28:34.787021] sendSETDName:246 set playername: michael
[10:28:34.787028] process:526 setd
[10:28:34.787038] process:526 aude
[10:28:34.787041] process_aude:420 enable spdif: 1 dac: 1
[10:28:34.787099] process:526 audg
[10:28:34.787112] process_audg:438 audg gainL: 65536 gainR: 65536 adjust: 1
[10:28:34.787116] set_volume:229 setting internal gain left: 65536 right: 65536
[10:28:36.998618] process:526 strm
[10:28:36.998642] process_strm:272 strm command t
[10:28:36.998647] sendSTAT:187 STAT: STMt
[10:28:40.998609] process:526 strm
[10:28:40.998634] process_strm:272 strm command t
[10:28:40.998639] sendSTAT:187 STAT: STMt
[10:28:44.998403] process:526 strm
[10:28:44.998429] process_strm:272 strm command t
[10:28:44.998435] sendSTAT:187 STAT: STMt
[10:28:46.190853] process:526 strm
[10:28:46.190877] process_strm:272 strm command q
[10:28:46.190882] decode_flush:227 decode flush
[10:28:46.190885] output_flush:424 flush output buffer
[10:28:46.190890] sendSTAT:187 STAT: STMf
[10:28:46.198494] process:526 audg
[10:28:46.198511] process_audg:438 audg gainL: 65536 gainR: 65536 adjust: 1
[10:28:46.198516] set_volume:229 setting internal gain left: 65536 right: 65536
[10:28:46.202258] process:526 strm
[10:28:46.202274] process_strm:272 strm command s
[10:28:46.202278] process_strm:347 strm s autostart: 1 transition period: 10 transition type: 0 codec: d
[10:28:46.202283] sendSTAT:187 STAT: STMf
[10:28:46.202296] codec_open:255 codec open: 'd'
[10:28:46.202313] stream_sock:393 connecting to 172.16.0.93:9000
[10:28:46.202521] stream_sock:422 header: GET /stream.mp3?player=fc:45:96:46:f0:8b HTTP/1.0


[10:28:46.202538] sendSTAT:187 STAT: STMc
[10:28:46.202546] process_strm:382 set fade mode: 0
[10:28:46.202556] process:526 audg
[10:28:46.202560] process_audg:438 audg gainL: 65536 gainR: 65536 adjust: 1
[10:28:46.202564] set_volume:229 setting internal gain left: 65536 right: 65536
[10:28:46.231055] stream_thread:180 headers: len: 115
HTTP/1.1 200 OK
Server: Logitech Media Server (7.9.0 - 1454098279)
Connection: close
Content-Type: audio/dsf


[10:28:46.231557] sendRESP:218 RESP
[10:28:46.279104] _read_header:192 id: DSD  len: 28 consume: 28
[10:28:46.279176] _read_header:159 DSF version: 1 format: 0
[10:28:46.279184] _read_header:169 channels: 2
[10:28:46.279188] _read_header:170 sample rate: 2822400
[10:28:46.279192] _read_header:171 lsb first: 1
[10:28:46.279195] _read_header:172 sample bytes: 110581632
[10:28:46.279198] _read_header:173 block size: 4096
[10:28:46.279202] _read_header:192 id: fmt  len: 52 consume: 52
[10:28:46.279205] _read_header:179 found dsd len: 221167628
[10:28:46.279209] dsd_decode:528 setting track_start
[10:28:46.279212] dsd_decode:539 DOP output
[10:28:46.285702] _output_frames:62 start buffer frames: 141312
[10:28:46.285729] _output_frames:147 track start sample rate: 176400 replay_gain: 0
[10:28:46.285740] sendSTAT:187 STAT: STMs
[10:28:46.285766] sendSTAT:187 STAT: STMt
[10:28:46.295778] output_thread:621 open output device: front:CARD=D2Qute,DEV=0
[10:28:46.301191] alsa_open:338 opening device at: 176400
[10:28:46.301508] alsa_open:389 opened device front:CARD=D2Qute,DEV=0 using format: S32_LE sample rate: 176400 mmap: 0
[10:28:46.301531] alsa_open:468 buffer: 40 period: 4 -> buffer size: 7056 period size: 1764
[10:28:48.287375] sendSTAT:187 STAT: STMt
[10:28:48.998171] process:526 strm
[10:28:48.998201] process_strm:272 strm command t
[10:28:48.998206] sendSTAT:187 STAT: STMt
[10:28:49.999269] sendSTAT:187 STAT: STMt
[10:28:51.000360] sendSTAT:187 STAT: STMt
[10:28:52.001452] sendSTAT:187 STAT: STMt
[10:28:52.998125] process:526 strm
[10:28:52.998156] process_strm:272 strm command t
[10:28:52.998161] sendSTAT:187 STAT: STMt
[10:28:53.999223] sendSTAT:187 STAT: STMt
[10:28:55.000370] sendSTAT:187 STAT: STMt
[10:28:56.001475] sendSTAT:187 STAT: STMt
[10:28:56.998514] process:526 strm
[10:28:56.998544] process_strm:272 strm command t
[10:28:56.998550] sendSTAT:187 STAT: STMt
[10:28:57.999621] sendSTAT:187 STAT: STMt
[10:28:59.000732] sendSTAT:187 STAT: STMt
[10:29:00.001851] sendSTAT:187 STAT: STMt
[10:29:00.998476] process:526 strm
[10:29:00.998507] process_strm:272 strm command t
[10:29:00.998512] sendSTAT:187 STAT: STMt
[10:29:01.999571] sendSTAT:187 STAT: STMt
[10:29:03.000662] sendSTAT:187 STAT: STMt
[10:29:04.001754] sendSTAT:187 STAT: STMt
[10:29:05.002847] sendSTAT:187 STAT: STMt
[10:29:06.003940] sendSTAT:187 STAT: STMt
[10:29:07.005033] sendSTAT:187 STAT: STMt
[10:29:08.006127] sendSTAT:187 STAT: STMt
[10:29:08.246608] process:526 strm
[10:29:08.246634] process_strm:272 strm command t
[10:29:08.246639] sendSTAT:187 STAT: STMt
[10:29:09.247701] sendSTAT:187 STAT: STMt
[10:29:10.248792] sendSTAT:187 STAT: STMt
[10:29:11.249891] sendSTAT:187 STAT: STMt
[10:29:12.250951] sendSTAT:187 STAT: STMt
[10:29:12.998847] process:526 strm
[10:29:12.998878] process_strm:272 strm command t
[10:29:12.998884] sendSTAT:187 STAT: STMt
[10:29:13.999948] sendSTAT:187 STAT: STMt
[10:29:15.001041] sendSTAT:187 STAT: STMt
[10:29:16.002134] sendSTAT:187 STAT: STMt
[10:29:16.998739] process:526 strm
[10:29:16.998770] process_strm:272 strm command t
[10:29:16.998775] sendSTAT:187 STAT: STMt
[10:29:17.999838] sendSTAT:187 STAT: STMt
[10:29:19.000935] sendSTAT:187 STAT: STMt
[10:29:20.002030] sendSTAT:187 STAT: STMt
[10:29:20.998896] process:526 strm
[10:29:20.998926] process_strm:272 strm command t
[10:29:20.998933] sendSTAT:187 STAT: STMt
[10:29:21.999996] sendSTAT:187 STAT: STMt
[10:29:23.001093] sendSTAT:187 STAT: STMt
[10:29:24.002183] sendSTAT:187 STAT: STMt
[10:29:24.999033] process:526 strm
[10:29:24.999064] process_strm:272 strm command t
[10:29:24.999069] sendSTAT:187 STAT: STMt
[10:29:26.000133] sendSTAT:187 STAT: STMt
[10:29:27.001253] sendSTAT:187 STAT: STMt
[10:29:28.002343] sendSTAT:187 STAT: STMt
[10:29:28.999157] process:526 strm
[10:29:28.999187] process_strm:272 strm command t
[10:29:28.999192] sendSTAT:187 STAT: STMt
[10:29:30.000250] sendSTAT:187 STAT: STMt
[10:29:31.001358] sendSTAT:187 STAT: STMt
[10:29:32.002452] sendSTAT:187 STAT: STMt
[10:29:32.999257] process:526 strm
[10:29:32.999287] process_strm:272 strm command t
[10:29:32.999292] sendSTAT:187 STAT: STMt
[10:29:34.000383] sendSTAT:187 STAT: STMt
[10:29:35.001474] sendSTAT:187 STAT: STMt
[10:29:36.002601] sendSTAT:187 STAT: STMt
[10:29:36.999293] process:526 strm
[10:29:36.999322] process_strm:272 strm command t
[10:29:36.999327] sendSTAT:187 STAT: STMt
[10:29:38.000386] sendSTAT:187 STAT: STMt
[10:29:39.001477] sendSTAT:187 STAT: STMt
[10:29:40.002572] sendSTAT:187 STAT: STMt
[10:29:40.999131] process:526 strm
[10:29:40.999161] process_strm:272 strm command t
[10:29:40.999166] sendSTAT:187 STAT: STMt
[10:29:42.000230] sendSTAT:187 STAT: STMt
[10:29:43.001325] sendSTAT:187 STAT: STMt
[10:29:44.002421] sendSTAT:187 STAT: STMt
[10:29:44.999210] process:526 strm
[10:29:44.999240] process_strm:272 strm command t
[10:29:44.999246] sendSTAT:187 STAT: STMt
[10:29:46.000307] sendSTAT:187 STAT: STMt
[10:29:47.001404] sendSTAT:187 STAT: STMt
[10:29:48.002494] sendSTAT:187 STAT: STMt
[10:29:48.999221] process:526 strm
[10:29:48.999251] process_strm:272 strm command t
[10:29:48.999257] sendSTAT:187 STAT: STMt
[10:29:50.000324] sendSTAT:187 STAT: STMt
[10:29:51.001418] sendSTAT:187 STAT: STMt
[10:29:52.002509] sendSTAT:187 STAT: STMt
[10:29:52.999614] process:526 strm
[10:29:52.999644] process_strm:272 strm command t
[10:29:52.999648] sendSTAT:187 STAT: STMt
[10:29:54.000713] sendSTAT:187 STAT: STMt
[10:29:55.001821] sendSTAT:187 STAT: STMt
[10:29:56.002907] sendSTAT:187 STAT: STMt
[10:29:57.003990] sendSTAT:187 STAT: STMt
[10:29:57.013993] process:526 strm
[10:29:57.014011] process_strm:272 strm command t
[10:29:57.014016] sendSTAT:187 STAT: STMt
[10:29:58.015076] sendSTAT:187 STAT: STMt
[10:29:59.016167] sendSTAT:187 STAT: STMt
[10:30:00.017259] sendSTAT:187 STAT: STMt
[10:30:00.999245] process:526 strm
[10:30:00.999276] process_strm:272 strm command t
[10:30:00.999281] sendSTAT:187 STAT: STMt
[10:30:02.000346] sendSTAT:187 STAT: STMt
[10:30:03.001439] sendSTAT:187 STAT: STMt
[10:30:04.002533] sendSTAT:187 STAT: STMt
[10:30:04.999420] process:526 strm
[10:30:04.999451] process_strm:272 strm command t
[10:30:04.999456] sendSTAT:187 STAT: STMt
[10:30:06.000522] sendSTAT:187 STAT: STMt
[10:30:07.001617] sendSTAT:187 STAT: STMt
[10:30:08.002713] sendSTAT:187 STAT: STMt
[10:30:08.999686] process:526 strm
[10:30:08.999716] process_strm:272 strm command t
[10:30:08.999721] sendSTAT:187 STAT: STMt
[10:30:10.000784] sendSTAT:187 STAT: STMt
[10:30:11.001873] sendSTAT:187 STAT: STMt
[10:30:12.002958] sendSTAT:187 STAT: STMt
[10:30:12.999520] process:526 strm
[10:30:12.999550] process_strm:272 strm command t
[10:30:12.999555] sendSTAT:187 STAT: STMt
[10:30:14.000622] sendSTAT:187 STAT: STMt
[10:30:15.001716] sendSTAT:187 STAT: STMt
[10:30:16.002809] sendSTAT:187 STAT: STMt
[10:30:16.999853] process:526 strm
[10:30:16.999884] process_strm:272 strm command t
[10:30:16.999889] sendSTAT:187 STAT: STMt
[10:30:18.000955] sendSTAT:187 STAT: STMt
[10:30:19.002049] sendSTAT:187 STAT: STMt
[10:30:20.003143] sendSTAT:187 STAT: STMt
[10:30:20.999736] process:526 strm
[10:30:20.999767] process_strm:272 strm command t
[10:30:20.999772] sendSTAT:187 STAT: STMt
[10:30:22.000835] sendSTAT:187 STAT: STMt
[10:30:23.001931] sendSTAT:187 STAT: STMt
[10:30:24.003042] sendSTAT:187 STAT: STMt
[10:30:24.999874] process:526 strm
[10:30:24.999905] process_strm:272 strm command t
[10:30:24.999910] sendSTAT:187 STAT: STMt
[10:30:26.000972] sendSTAT:187 STAT: STMt
[10:30:27.002068] sendSTAT:187 STAT: STMt
[10:30:28.003189] sendSTAT:187 STAT: STMt
[10:30:28.999955] process:526 strm
[10:30:28.999985] process_strm:272 strm command t
[10:30:28.999990] sendSTAT:187 STAT: STMt
[10:30:30.001053] sendSTAT:187 STAT: STMt
[10:30:31.002147] sendSTAT:187 STAT: STMt
[10:30:32.003244] sendSTAT:187 STAT: STMt
[10:30:33.000496] process:526 strm
[10:30:33.000525] process_strm:272 strm command t
[10:30:33.000530] sendSTAT:187 STAT: STMt
[10:30:34.001595] sendSTAT:187 STAT: STMt
[10:30:35.002691] sendSTAT:187 STAT: STMt
[10:30:36.003786] sendSTAT:187 STAT: STMt
[10:30:36.999882] process:526 strm
[10:30:36.999912] process_strm:272 strm command t
[10:30:36.999918] sendSTAT:187 STAT: STMt
[10:30:38.000982] sendSTAT:187 STAT: STMt
[10:30:39.002078] sendSTAT:187 STAT: STMt
[10:30:40.003171] sendSTAT:187 STAT: STMt
[10:30:40.999913] process:526 strm
[10:30:40.999943] process_strm:272 strm command t
[10:30:40.999949] sendSTAT:187 STAT: STMt
[10:30:42.001039] sendSTAT:187 STAT: STMt
[10:30:43.002137] sendSTAT:187 STAT: STMt
[10:30:44.003234] sendSTAT:187 STAT: STMt
[10:30:44.999988] process:526 strm
[10:30:45.000018] process_strm:272 strm command t
[10:30:45.000024] sendSTAT:187 STAT: STMt
[10:30:46.001089] sendSTAT:187 STAT: STMt
[10:30:47.002185] sendSTAT:187 STAT: STMt
[10:30:48.003278] sendSTAT:187 STAT: STMt
[10:30:48.999876] process:526 strm
[10:30:48.999905] process_strm:272 strm command t
[10:30:48.999910] sendSTAT:187 STAT: STMt
[10:30:50.000972] sendSTAT:187 STAT: STMt
[10:30:51.002076] sendSTAT:187 STAT: STMt
[10:30:52.003163] sendSTAT:187 STAT: STMt
[10:30:52.999982] process:526 strm
[10:30:53.000012] process_strm:272 strm command t
[10:30:53.000018] sendSTAT:187 STAT: STMt
[10:30:54.001083] sendSTAT:187 STAT: STMt
[10:30:55.002175] sendSTAT:187 STAT: STMt
[10:30:56.003273] sendSTAT:187 STAT: STMt
[10:30:57.000183] process:526 strm
[10:30:57.000213] process_strm:272 strm command t
[10:30:57.000218] sendSTAT:187 STAT: STMt
[10:30:58.001285] sendSTAT:187 STAT: STMt
[10:30:59.002375] sendSTAT:187 STAT: STMt
[10:31:00.003470] sendSTAT:187 STAT: STMt
[10:31:01.000080] process:526 strm
[10:31:01.000110] process_strm:272 strm command t
[10:31:01.000115] sendSTAT:187 STAT: STMt
[10:31:02.001178] sendSTAT:187 STAT: STMt
[10:31:03.002266] sendSTAT:187 STAT: STMt
[10:31:04.003358] sendSTAT:187 STAT: STMt
[10:31:05.000191] process:526 strm
[10:31:05.000221] process_strm:272 strm command t
[10:31:05.000227] sendSTAT:187 STAT: STMt
[10:31:06.001289] sendSTAT:187 STAT: STMt
[10:31:07.002380] sendSTAT:187 STAT: STMt
[10:31:08.003474] sendSTAT:187 STAT: STMt
[10:31:08.999962] process:526 strm
[10:31:08.999992] process_strm:272 strm command t
[10:31:08.999997] sendSTAT:187 STAT: STMt
[10:31:10.001061] sendSTAT:187 STAT: STMt
[10:31:11.002153] sendSTAT:187 STAT: STMt
[10:31:12.003245] sendSTAT:187 STAT: STMt

Please correct my If I'm wrong

phofman · 2017-08-04 9:55 am

I think the problem is really in the DAC. Does the music continue from the point it stopped, or is there a missing section?

If the music continues (i.e. no samples lost, only delayed), the async feedback for DoP from the DAC may not work correctly, asking the PC send too few samples, causing starvation. Theoretically we could diagnose this by monitoring the communication with wireshark and doing some verification calculations from the recorded packets.

If the music continues playing, just not output, it would hint at problem with the hardware of the DAC - power supply, DAC, output stage etc.

In any case - did you consider contacting the manufacturer? With the data gathered here, they should take your question seriously.

michaelvv · 2017-08-04 10:18 am

phofman said:
I think the problem is really in the DAC. Does the music continue from the point it stopped, or is there a missing section?

If the music continues (i.e. no samples lost, only delayed), the async feedback for DoP from the DAC may not work correctly, asking the PC send too few samples, causing starvation. Theoretically we could diagnose this by monitoring the communication with wireshark and doing some verification calculations from the recorded packets.

If the music continues playing, just not output, it would hint at problem with the hardware of the DAC - power supply, DAC, output stage etc.

In any case - did you consider contacting the manufacturer? With the data gathered here, they should take your question seriously.

If the music continues (i.e. no samples lost, only delayed), the async feedback for DoP from the DAC may not work correctly, asking the PC send too few samples, causing starvation.

This is what is happening , and only on DOP...

phofman · 2017-08-04 10:28 am

So playing samples is just interrupted, no part of music lost?

michaelvv · 2017-08-04 10:35 am

phofman said:
So playing samples is just interrupted, no part of music lost?

Exactly, And I have seen the same behavior when playing directly from SSD drive no
network at all.

Going through all kind of way too remove (services etc) and special lenovos tlp.

These things are shut down now, so I'm testing too see if it makes a difference.

phofman · 2017-08-04 10:46 am

The powerful CPU is idle all the time, other processes should not matter.

The period time (interval at which new audio samples are delivered from the playback application to the driver) is 10ms, buffer time (multiples of "periods" with prefilled samples in kernel) is 40ms (listed in hw_params - the xxx_size fields are in audio frames (stereo samples) - hence period_size of 1764 divided by 176400 sample rate in frames per second yields 0.01s = 10ms). That is plenty of time margin even for slow network transmission. Plus the player itself caches the incoming samples.

I will ask at the mailing list if we can troubleshoot the async transmission without actually capturing and consequently analysing USB communication.

phofman · 2017-08-04 11:15 am

I wonder - if the samples are just paused, total playback time of a single track should be:

total time of OK playback + time of pauses = total time of glitched playback.

If you could play the track from command line, you can measure total playback time using the time command (how long time the playback command runs). It should differ for the two cases.

You can time it manually with stopwatch. Also, it would be nice to know if the player application knows about the delay - perhaps squeezelite can log the moment it thinks the track has finished playing - you could time that too.

michaelvv · 2017-08-04 11:22 am

phofman said:
I wonder - if the samples are just paused, total playback time of a single track should be:

total time of OK playback + time of pauses = total time of glitched playback.

If you could play the track from command line, you can measure total playback time using the time command (how long time the playback command runs). It should differ for the two cases.

You can time it manually with stopwatch. Also, it would be nice to know if the player application knows about the delay - perhaps squeezelite can log the moment it thinks the track has finished playing - you could time that too.

I can easily follow what you mean, but right now I haven't had a glitch for ca 1 hour.
It's close to impossible to provoke it. I'm searching after anything unusual but can't find it.. The worst is I don't get anything in logs. Very frustrated.

phofman · 2017-08-04 11:40 am

I do not think the player knows about the glitch. Playback is timed by the DAC clock. It controls pace of data sent in USB frames by the USB controller via feedback messages. If it really asks for too few samples and the incoming buffer in the soundcard underruns - there is no way the controller -> driver -> playback app would know. They are not comparing the rate of outgoing samples with some internal timer to verify the DAC is consuming samples in the correct rate.

Much easier situation is with adaptive USB DAC where the consumption rate is controlled by the USB controller clock. Each 1ms/125us frame contains the corresponding number of samples and that's it, no feedback controlling the rate is taken into account.

A few years ago I analysed the adaptive packets with wireshark to confirm the outgoing rate is as steady as technically possible (with positive result). But again, I was just looking whether the number of samples in the frame corresponds to the calculated value for the current sample rate. The async com is way more complicated, the samples count varies in each frame and you would have to sum them to get some longer-time series. It is doable, but would require some scripting to parse and analyse the file with captured packets.

michaelvv · 2017-08-04 11:47 am

Yes I can see this is quite to impossible to debug.

The funny thing is that MPD , is 10-20 times more likely to make these hiccups than squeezelite.

Just tried it and almost every time I change Album it make this 1-2 secs stop, but It continue again.

Just have a 0.5-1 sec stop in squeezelite my second in 1.5 hour.

phofman · 2017-08-04 11:56 am

OK, then let's work in MPD. It is easier to control (and measure time if needed) remotely anyway.

Please send me the hw_params file for DoP in MPD so that we see the difference.

michaelvv · 2017-08-04 12:45 pm

I'll just collect some info about the MPD I have installed.

mpd --version

Code:

Music Player Daemon 0.20.9

Copyright (C) 2003-2007 Warren Dukes <warren.dukes@gmail.com>
Copyright 2008-2017 Max Kellermann <max.kellermann@gmail.com>
This is free software; see the source for copying conditions.  There is NO
warranty; not even MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.
cat /proc/asound/card1/pcm0p/sub0/hw_params
access: RW_INTERLEAVED
format: S32_LE
subformat: STD
channels: 2
rate: 176400 (176400/1)
period_size: 17640
buffer_size: 35280

Database plugins:
 simple proxy upnp

Storage plugins:
 local smbclient nfs curl

Neighbor plugins:
 smbclient upnp

Decoders plugins:
 [mad] mp3 mp2
 [vorbis] ogg oga
 [oggflac] ogg oga
 [flac] flac
 [opus] opus ogg oga
 [sndfile] wav aiff aif au snd paf iff svx sf voc w64 pvf xi htk caf sd2
 [audiofile] wav au aiff aif
 [dsdiff] dff
 [dsf] dsf
 [faad] aac
 [wavpack] wv
 [modplug] 669 amf ams dbm dfm dsm far it med mdl mod mtm mt2 okt s3m stm ult umx xm
 [ffmpeg] 16sv 3g2 3gp 4xm 8svx aa3 aac ac3 adx afc aif aifc aiff al alaw amr anim apc ape asf atrac au aud avi avm2 avs bap bfi c93 cak cin cmv cpk daud dct divx dts dv dvd dxa eac3 film flac flc fli fll flx flv g726 gsm gxf iss m1v m2v m2t m2ts m4a m4b m4v mad mj2 mjpeg mjpg mka mkv mlp mm mmf mov mp+ mp1 mp2 mp3 mp4 mpc mpeg mpg mpga mpp mpu mve mvi mxf nc nsv nut nuv oga ogm ogv ogx oma ogg omg opus psp pva qcp qt r3d ra ram rl2 rm rmvb roq rpl rvc shn smk snd sol son spx str swf tak tgi tgq tgv thp ts tsp tta xa xvid uv uv2 vb vid vob voc vp6 vmd wav webm wma wmv wsaud wsvga wv wve
 [gme] ay gbs gym hes kss nsf nsfe sap spc vgm vgz
 [pcm]

Filters:
 libsamplerate soxr

Tag plugins:
 id3tag

Output plugins:
 shout null fifo pipe alsa ao oss pulse jack httpd recorder

Encoder plugins:
 null vorbis opus lame wave flac

Archive plugins:
 [bz2] bz2
 [zzip] zip
 [iso] iso

Input plugins:
 file alsa archive curl ffmpeg smbclient nfs mms cdio_paranoia

Playlist plugins:
 extm3u m3u pls xspf asx rss soundcloud flac cue embcue

Protocols:
 file:// http:// https:// mms:// mmsh:// mmst:// mmsu:// gopher:// rtp:// rtsp:// rtmp:// rtmpt:// rtmps:// smb:// nfs:// cdda:// alsa://

Other features:
 avahi epoll icu inotify ipv6 systemd tcp un

cat /etc/mpd.conf

Code:

audio_buffer_size "4096"
auto_update "no"
bind_to_address "any"
buffer_before_play "25%"
db_file "/var/lib/mpd/mpd.db"
filesystem_charset "UTF-8"
gapless_mp3_playback "yes"
group "audio"
id3v1_encoding "UTF-8"
log_file "/var/lib/mpd/mpd.log"
log_level "default"
max_connections "20"
mixer_type "disabled"
music_directory "/musicmpd"
pid_file "/run/mpd/mpd.pid"
playlist_directory "/var/lib/mpd/playlists"
port "6600"
restore_paused "yes"
state_file "/var/lib/mpd/mpdstate"
volume_normalization "no"

audio_output {
  auto_channels "no"
  auto_format "no"
  auto_resample "no"
  buffer_time "200000"
  device "front:CARD=D2Qute,DEV=0"
  dop "yes"
  enabled "yes"
  mixer_type "none"
  name "Chord"
  period_time "1024000000"
  type "alsa"
  use_mmap "yes"
}

decoder {
  enabled "yes"
  plugin "ffmpeg"
}

input {
  plugin "curl"
}

cat /proc/asound/card1/pcm0p/sub0/hw_params

Code:

access: RW_INTERLEAVED
format: S32_LE
subformat: STD
channels: 2
rate: 176400 (176400/1)
period_size: 17640
buffer_size: 35280

cat /proc/asound/card1/stream0

Code:

Chord Electronics Ltd 2Qute at usb-0000:00:14.0-2, high speed : USB Audio

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

2 dropouts already I have been playing for Play Time: 0 days, 0:05:41

FINISHED NO MORE INFO IN THIS POST.

phofman · 2017-08-04 1:44 pm

Very good.

Can you get a relatively short DSD track where you could measure the time difference between overall playback of dropouts and no-dropouts?

When you raise mpd log level, can you see track start and finish times with precision to seconds in mpd log? I am looking for a simple way to measure the playback time, this would be the easiest. From looking at mpd source code, the native mpd log is problably only minutes-based. However logging to syslog (log = syslog) should log seconds.

Or a simple script using mpc idle should work. I do not have mpd installed now, but something like:

Code:

while true ; do
        mpc somehowplayyourdsdtrack
        echo -n "starting "
        date
        mpc idle
        echo -n "finished "
        date
done

You can store the nanosecond timestamp $(date +%s.%N) in some variable and calculate/print time difference for each run using

Code:

echo "$FINISHTIMESTAMP - $STARTTIMESTAMP" | bc -l

Or writing this in python would be way easier.

michaelvv · 2017-08-04 1:56 pm

phofman said:
Very good.

Can you get a relatively short DSD track where you could measure the time difference between overall playback of dropouts and no-dropouts?

When you raise mpd log level, can you see track start and finish times with precision to seconds in mpd log? I am looking for a simple way to measure the playback time, this would be the easiest. From looking at mpd source code, the native mpd log is problably only minutes-based. However logging to syslog (log = syslog) should log seconds.

Or a simple script using mpc idle should work. I do not have mpd installed now, but something like:

Code:

while true ; do mpc somehowplayyourdsdtrack echo -n "starting " date mpc idle echo -n "finished " date done

You can store the nanosecond timestamp $(date +%s.%N) in some variable and calculate/print time difference for each run using

Code:

echo "$FINISHTIMESTAMP - $STARTTIMESTAMP" | bc -l

Or writing this in python would be way easier.

I can code in PHP cgi and I have it installed so no problems.

The logging in mpd tried (default,verbose) it not very useful. Do you know if we can get and higher resolution in the timestamp ???

I'll start op my little php script right now...

phofman · 2017-08-04 2:06 pm

I do not think the native mpd logging offers more resolution than minutes http://git.musicpd.org/cgit/master/mpd.git/tree/src/LogBackend.cxx#n93

IMO it is better to measure from outside, using the script.

I am really curious whether overall playback times will reflect the dropouts. They should

michaelvv · 2017-08-04 2:09 pm

Okay I have mpc installed. Doc is very limited , so If you can help.
What I want to do, is just add a file I have on my harddrive (SMB) and play it.

Find out

mpc clear
but when I try a mpc load 'full path to file' I got an error, mayby another command I don't know...

Do you know.. ???

phofman · 2017-08-04 2:14 pm

MPD uses a prescanned database, playing a single local file is a bit more complicated - e.g. https://stackoverflow.com/questions/15659067/mpc-mpd-on-linux-how-to-play-local-wav-file

michaelvv · 2017-08-04 2:27 pm

phofman said:
MPD uses a prescanned database, playing a single local file is a bit more complicated - e.g. https://stackoverflow.com/questions/15659067/mpc-mpd-on-linux-how-to-play-local-wav-file

found this , seems to work ,and Again it gives the 1-2 secs when running it...

Code:

mpc clear; mpc search title "Name on the song" | mpc add; mpc play

phofman · 2017-08-04 2:43 pm

Great, now measuring the time difference should be simple (provided it can actually play without the glitches to get the reference time

).

michaelvv · 2017-08-04 3:13 pm

could be more elegant, but I need it fast...

Code:

<?php

/* 
 * To change this license header, choose License Headers in Project Properties.
 * To change this template file, choose Tools | Templates
 * and open the template in the editor.
 */

class mpd {
  
  var $ver="0.01";
  
  var $alsa_hw_params="/proc/asound/D2Qute/pcm0p/sub0/hw_params";
  var $no_stress=50000;
  
  var $starttime=0;
  
  function mpd() {
    
  }
  
  
  
  function WaitforSound() {
    $cmd="cat ".$this->alsa_hw_params;
 
    $running=1;
    
    while($running) {
    
      $res=trim(`$cmd`);
      //echo $res;
    
      if($res!="closed") {
        $running=0;
      }
      else
      {
        // don not stress the OS.
        usleep($this->no_stress);
      }  
    }
  }
  
  function WaitforNoSound($debug=0) {
    $cmd="cat ".$this->alsa_hw_params;
 
    $running=1;
    
    $write_loop=2;
    
    $loop=0;
    
    while($running) {
    
      $loop+=1;
      
      $res=trim(`$cmd`);
      //echo $res;
    
      if($res=="closed") {
        $running=0;
      }
      else
      {
        // don not stress the OS.
        
        if($debug && $loop==$write_loop) {
          $usedtime=sprintf("%.2f",MicroTime(TRUE)-$this->starttime);
          echo "Time Elapsed : $usedtime sec(s).\n";
          
          $loop=0;
        }
        
        usleep($this->no_stress);
      }  
    }
  }
  
  
  function PlaySong($song) {
    
    // first we need to clear the playlist
    
    echo "clear the playlist.\n";
    `mpc clear`;

    echo "wait for No sound.\n";
    $this->WaitforNoSound();

    $cmd="mpc search title "$song" | mpc add; mpc play";
    
    $this->starttime=MicroTime(TRUE);
    `$cmd`;
    
    echo "wait for Sound.\n";
    $this->WaitforSound();

    echo "wait for No sound.\n";
    $this->WaitforNoSound(1);

    $stoptime=MicroTime(TRUE);
    
    $usedtime=sprintf("%.2f",$stoptime-$this->starttime);
    
    echo "Total Used Playing Time $usedtime sec(s).\n\n";
    
  }
  
}


// Main program //

$mpd = new Mpd();

if(count($argv)==0) {
  print"Error register_argc_argv = On , need to be set in php.ini for cli.\n";
  exit;
}

$song=$argv[1];

if($song!="") {
  $mpd->PlaySong($song);
}
else {
  print"please choose a song !!!\n";
  print"php -q mpdtest.php 'song name'\n\n";
}

And how funny can it get. MPD skips the music , LMS (squeezelite) just stops, as you can see 2 runs exactly same
duration and I have hiccups in both...

Will do a couple more to see if it's the same..

1 run - 244.74 sec(s).
2 run - 244.74 sec(s).
3 run - 244.73 sec(s).
4 run - 244.65 sec(s).
5 run - 244.73 sec(s).

The actual number is 4.04 so it's pretty close..

Chord 2qute and my DOP challenge

Member

Member

Member

Member

Member

Member

Member

Member

Member

Member

Member

Member

Member

Member

Member

Member

Member

Member

Member

Member