Track changes taking 18+ seconds on Roon, not on ARC (ref#5XJ276)

Chris_Haklitch · November 8, 2024, 6:44am

What’s happening?

· I'm noticing slowness when using the Roon App or Roon ARC

Describe the issue

Track changes on Roon taking 18+ seconds when clicking Next Track; but not on Arc

Describe your network setup

Orbi mesh router. Roon ROCK and Endpoint hardwired to same router.

Chris_Haklitch · November 8, 2024, 6:49am

Pasting the log file, which looks like it was dropped.
This issue has become 100% recurrent, even when restarting Roon Server on the ROCK.
I have moved the ROCK to the same Router satellite as the endpoint (A DietPi RP4, but also Ropieee).
Music is stored on a NAS, and I at first thought it was read delays there, but even when optimizing the services on the NAS and watching Resource Monitor, the READ activity never spikes during track change. The request to the NAS seems to be held by Roon Server while it does… something here.

ALSO - the slowness on track change does NOT happen on ARC, which leads me to believe this is NOT a NAS or network issue, as I’d see similar delays in ARC. The issue only occurs on Roon client locally!

I’ve seen other tickets reporting issues related to updating PlayCount, but these logs look different.

Happy to help with additional info! Thank you!

Log extract showing 18 second delay on track change

11/08 06:20:18 Info: =======================================================================
11/08 06:20:18 Trace: Track             Dialogue (trackid=Dialogue,albumid=50:1:dc7a01bb-74ab-4c30-bf43-04c77d9bf1ee)
11/08 06:20:18 Trace:     Performance   
11/08 06:20:18 Info: Track             Dialogue (trackid=Dialogue,albumid=50:1:dc7a01bb-74ab-4c30-bf43-04c77d9bf1ee)
11/08 06:20:18 Info:     Performance   
11/08 06:20:18 Trace: Track             Ghetto Lights (trackid=Ghetto Lights,albumid=50:1:bde31d5d-5c43-498a-9fb9-fa582252b289)
11/08 06:20:18 Trace:     Performance   LibraryPerformance[38771061, LibraryWork[5178798, Ghetto Lights, by LibraryPerformer[1484922, Andrew Hill]]]
11/08 06:20:18 Info: Track             Ghetto Lights (trackid=Ghetto Lights,albumid=50:1:bde31d5d-5c43-498a-9fb9-fa582252b289)
11/08 06:20:18 Info:     Performance   LibraryPerformance[38771061, LibraryWork[5178798, Ghetto Lights, by LibraryPerformer[1484922, Andrew Hill]]]
11/08 06:20:18 Trace: Track             Jasper (trackid=Jasper,albumid=50:1:341e3da9-27bb-499a-b044-9bc88d26ef91)
11/08 06:20:18 Trace:     Performance   
11/08 06:20:18 Info: Track             Jasper (trackid=Jasper,albumid=50:1:341e3da9-27bb-499a-b044-9bc88d26ef91)
11/08 06:20:18 Info:     Performance   
11/08 06:20:18 Trace: [zone Gungnir USB] Playing 3 Items
11/08 06:20:18 Trace: [library] endmutation in 33ms
11/08 06:20:18 Info: 
--[ SignalPath ]---------------------------------------------
SignalPath Quality = Lossless
Elements:
    Source Format=Flac 44100/16/2 BitRate=755 Quality=Lossless
    Raat Device=Schiit Gungnir  Unison USB
    Output OutputType=Local_Alsa Quality=Lossless SubType= Model=Schiit Gungnir  Unison USB
------------------------------------------------------------
11/08 06:20:18 Info: [zone Gungnir USB] OnPlayFeedback Stopped
11/08 06:20:18 Info: [zone Gungnir USB] Canceling Pending Sleep
11/08 06:20:18 Trace: [zone Gungnir USB] Playing TransportItem
11/08 06:20:18 Info: [zone Gungnir USB] Canceling Pending Sleep
11/08 06:20:18 Info: [audio/env] [zoneplayer -> stream] All streams were disposed
11/08 06:20:18 Trace: [zone Gungnir USB] Selecting Source state=Stopped
11/08 06:20:18 Info: [library] recorded play for profile 4c54a200-0eb9-40d0-bdf2-5c5178a32bb8: mediaid=50:1:dc6e2197-5d88-4f54-8fee-fb42657b0fb1 metadataid=123:0:MT0003739240 contentid= libraryid=50:1:dc6e2197-5d88-4f54-8fee-fb42657b0fb1 isfromradio=False isfrommix=False isfrommobile=
11/08 06:20:18 Trace: [Gungnir USB] [zoneplayer/raat] Endpoint Schiit Gungnir  Unison USB State Changed: Playing => Prepared
11/08 06:20:18 Trace: [Schiit Gungnir  Unison USB] [raatclient] SENT [17]{"request":"end_stream"}
11/08 06:20:18 Debug: [raat/tcpaudiosource] disconnecting
11/08 06:20:18 Info: [audio/env] [zoneplayer -> stream -> endpoint] All streams were disposed
11/08 06:20:18 Trace: [Schiit Gungnir  Unison USB] [raatclient] GOT [15] {"status":"Ended"}
11/08 06:20:18 Trace: [Schiit Gungnir  Unison USB] [raatclient] GOT [17] {"status":"Success"}
11/08 06:20:18 Trace: [Gungnir USB] [Lossless, 16/44 FLAC => 16/44] [100% buf] [LOADING @ 0:00] Dialogue - Bobby Hutcherson / Joe Chambers
11/08 06:20:18 Info: [audio/env] [zoneplayer] All streams were disposed
11/08 06:20:18 Info: sleep 49ms after flush
11/08 06:20:18 Trace: [library] finished with 57 dirty tracks 8 dirty albums 13 dirty performers 34 dirty works 47 dirty performances 0 clumping tracks, 0 clumping auxfiles 0 compute tracks, 0 deleted tracks, 0 tracks to (re)load, 0 tracks to retain, 0 auxfiles to (re)load, 0 auxfiles to retain, and 103 changed objects
11/08 06:20:18 Info: [library/albumdetails] found 1 ingroup alternates, 0 other alternates
11/08 06:20:18 Debug: [query] Sooloos.Broker.Music.LibraryAlbum:8 dirty (< rebuild threshold of 4210.400000000001).  re-sorting item-by-item (internaltype=LibraryAlbum)
11/08 06:20:18 Trace: [music/searchindex] [search-index]  removed in 0ms: 1 albums, 0 tracks, 0 works, 0 performers, 0 labels, 0 genres
11/08 06:20:18 Trace: [music/searchindex] [search-index] added in 0ms: 1 albums, 0 tracks, 0 works, 0 performers, 0 labels, 0 genres
11/08 06:20:18 Trace: [music/searchindex] totals: 5263 albums, 61975 tracks, 24120 works, 38584 performers, 1227 labels, 926 genres
11/08 06:20:18 Info: [query] Sooloos.Broker.Music.LibraryAlbum: Process Removes/Adds (small) in 1ms
11/08 06:20:18 Debug: [query] Sooloos.Broker.Music.LibraryAlbum:8 dirty (< rebuild threshold of 4210.400000000001).  re-sorting item-by-item (internaltype=LibraryAlbum)
11/08 06:20:18 Info: [query] Sooloos.Broker.Music.LibraryAlbum: Process Removes/Adds (small) in 0ms
11/08 06:20:20 Debug: [query] Sooloos.Broker.Music.LibraryAlbum:8 dirty (< rebuild threshold of 4210.400000000001).  re-sorting item-by-item (internaltype=LibraryAlbum)
11/08 06:20:20 Info: [query] Sooloos.Broker.Music.LibraryAlbum: Process Removes/Adds (small) in 0ms
11/08 06:20:20 Debug: [query] Sooloos.Broker.Api.FolderItem:57 dirty items, rebuild threshold: 2000, rebuilding? False
11/08 06:20:20 Info: [query] Sooloos.Broker.Api.FolderItem: Process Removes/Adds (small) in 0ms
11/08 06:20:20 Debug: [query] Sooloos.Broker.Music.LibraryAlbum:8 dirty (< rebuild threshold of 4210.400000000001).  re-sorting item-by-item (internaltype=LibraryAlbum)
11/08 06:20:20 Info: [query] Sooloos.Broker.Music.LibraryAlbum: Process Removes/Adds (small) in 0ms
11/08 06:20:21 Debug: [query] Sooloos.Broker.Music.LibraryAlbum:8 dirty (< rebuild threshold of 4210.400000000001).  re-sorting item-by-item (internaltype=LibraryAlbum)
11/08 06:20:21 Info: [query] Sooloos.Broker.Music.LibraryAlbum: Process Removes/Adds (small) in 0ms
11/08 06:20:21 Debug: [query] Sooloos.Broker.Music.LibraryTrack:57 dirty (< rebuild threshold of 49580).  re-sorting item-by-item (internaltype=LibraryTrack)
11/08 06:20:21 Info: did adds 61975 - 57 items + 57 items => 61975 items (61891 compares)
11/08 06:20:21 Info: [query] Sooloos.Broker.Music.LibraryTrack:  Process Removes/Adds (medium) in 25ms
11/08 06:20:23 Debug: [query] Sooloos.Broker.Music.LibraryAlbum:8 dirty (< rebuild threshold of 4210.400000000001).  re-sorting item-by-item (internaltype=LibraryAlbum)
11/08 06:20:23 Info: [query] Sooloos.Broker.Music.LibraryAlbum: Process Removes/Adds (small) in 0ms
11/08 06:20:25 Debug: [query] Sooloos.Broker.Music.LibraryTrack:57 dirty (< rebuild threshold of 49580).  re-sorting item-by-item (internaltype=LibraryTrack)
11/08 06:20:25 Info: [query] Sooloos.Broker.Music.LibraryTrack: Process Removes/Adds (small) in 1ms
11/08 06:20:25 Debug: [query] Sooloos.Broker.Music.LibraryTrack:57 dirty (< rebuild threshold of 49580).  re-sorting item-by-item (internaltype=LibraryTrack)
11/08 06:20:25 Info: [query] Sooloos.Broker.Music.LibraryTrack: Process Removes/Adds (small) in 1ms
11/08 06:20:25 Debug: [query] Sooloos.Broker.Music.LibraryTrack:57 dirty (< rebuild threshold of 49580).  re-sorting item-by-item (internaltype=LibraryTrack)
11/08 06:20:25 Info: did adds 61975 - 57 items + 57 items => 61975 items (13354 compares)
11/08 06:20:25 Info: [query] Sooloos.Broker.Music.LibraryTrack:  Process Removes/Adds (medium) in 22ms
11/08 06:20:25 Debug: [query] Sooloos.Broker.Music.LibraryAlbum:8 dirty (< rebuild threshold of 4210.400000000001).  re-sorting item-by-item (internaltype=LibraryAlbum)
11/08 06:20:25 Info: [query] Sooloos.Broker.Music.LibraryAlbum: Process Removes/Adds (small) in 0ms
11/08 06:20:25 Debug: [query] Sooloos.Broker.Music.LibraryAlbum:8 dirty (< rebuild threshold of 4210.400000000001).  re-sorting item-by-item (internaltype=LibraryAlbum)
11/08 06:20:25 Info: [query] Sooloos.Broker.Music.LibraryAlbum: Process Removes/Adds (small) in 0ms
11/08 06:20:27 Debug: [query] Sooloos.Broker.Music.LibraryAlbum:8 dirty (< rebuild threshold of 4210.400000000001).  re-sorting item-by-item (internaltype=LibraryAlbum)
11/08 06:20:27 Info: [query] Sooloos.Broker.Music.LibraryAlbum: Process Removes/Adds (small) in 1ms
11/08 06:20:27 Debug: [query] Sooloos.Broker.Music.LibraryAlbum:8 dirty (< rebuild threshold of 4210.400000000001).  re-sorting item-by-item (internaltype=LibraryAlbum)
11/08 06:20:27 Info: [query] Sooloos.Broker.Music.LibraryAlbum: Process Removes/Adds (small) in 0ms
11/08 06:20:27 Debug: [query] Sooloos.Broker.Music.LibraryAlbum:8 dirty (< rebuild threshold of 4210.400000000001).  re-sorting item-by-item (internaltype=LibraryAlbum)
11/08 06:20:27 Info: [query] Sooloos.Broker.Music.LibraryAlbum: Process Removes/Adds (small) in 0ms
11/08 06:20:27 Debug: [query] Sooloos.Broker.Music.LibraryAlbum:8 dirty (< rebuild threshold of 4210.400000000001).  re-sorting item-by-item (internaltype=LibraryAlbum)
11/08 06:20:27 Info: [query] Sooloos.Broker.Music.LibraryAlbum: Process Removes/Adds (small) in 0ms
11/08 06:20:27 Debug: [query] Sooloos.Broker.Music.LibraryAlbum:8 dirty (< rebuild threshold of 4210.400000000001).  re-sorting item-by-item (internaltype=LibraryAlbum)
11/08 06:20:27 Info: [query] Sooloos.Broker.Music.LibraryAlbum: Process Removes/Adds (small) in 0ms
11/08 06:20:27 Debug: [query] Sooloos.Broker.Music.LibraryAlbum:8 dirty (< rebuild threshold of 4210.400000000001).  re-sorting item-by-item (internaltype=LibraryAlbum)
11/08 06:20:27 Info: [query] Sooloos.Broker.Music.LibraryAlbum: Process Removes/Adds (small) in 0ms
11/08 06:20:28 Trace: [Gungnir USB] [Lossless, 16/44 FLAC => 16/44] [100% buf] [LOADING @ 0:00] Dialogue - Bobby Hutcherson / Joe Chambers
11/08 06:20:28 Debug: [query] Sooloos.Broker.Music.LibraryAlbum:8 dirty (< rebuild threshold of 4210.400000000001).  re-sorting item-by-item (internaltype=LibraryAlbum)
11/08 06:20:28 Info: [query] Sooloos.Broker.Music.LibraryAlbum: Process Removes/Adds (small) in 1ms
11/08 06:20:28 Debug: [query] Sooloos.Broker.Music.LibraryAlbum:8 dirty (< rebuild threshold of 4210.400000000001).  re-sorting item-by-item (internaltype=LibraryAlbum)
11/08 06:20:28 Info: [query] Sooloos.Broker.Music.LibraryAlbum: Process Removes/Adds (small) in 0ms
11/08 06:20:29 Debug: [query] Sooloos.Broker.Music.LibraryAlbum:8 dirty (< rebuild threshold of 4210.400000000001).  re-sorting item-by-item (internaltype=LibraryAlbum)
11/08 06:20:29 Info: [query] Sooloos.Broker.Music.LibraryAlbum: Process Removes/Adds (small) in 0ms
11/08 06:20:31 Debug: [query] Sooloos.Broker.Music.LibraryAlbum:8 dirty (< rebuild threshold of 4210.400000000001).  re-sorting item-by-item (internaltype=LibraryAlbum)
11/08 06:20:31 Info: [query] Sooloos.Broker.Music.LibraryAlbum: Process Removes/Adds (small) in 0ms
11/08 06:20:31 Debug: [query] Sooloos.Broker.Music.LibraryAlbum:8 dirty (< rebuild threshold of 4210.400000000001).  re-sorting item-by-item (internaltype=LibraryAlbum)
11/08 06:20:31 Info: [query] Sooloos.Broker.Music.LibraryAlbum: Process Removes/Adds (small) in 0ms
11/08 06:20:31 Debug: [query] Sooloos.Broker.Music.LibraryAlbum:8 dirty (< rebuild threshold of 4210.400000000001).  re-sorting item-by-item (internaltype=LibraryAlbum)
11/08 06:20:31 Info: [query] Sooloos.Broker.Music.LibraryAlbum: Process Removes/Adds (small) in 0ms
11/08 06:20:31 Debug: [query] Sooloos.Broker.Music.LibraryAlbum:8 dirty (< rebuild threshold of 4210.400000000001).  re-sorting item-by-item (internaltype=LibraryAlbum)
11/08 06:20:31 Info: [query] Sooloos.Broker.Music.LibraryAlbum: Process Removes/Adds (small) in 0ms
11/08 06:20:31 Debug: [query] Sooloos.Broker.Music.LibraryAlbum:8 dirty (< rebuild threshold of 4210.400000000001).  re-sorting item-by-item (internaltype=LibraryAlbum)
11/08 06:20:31 Info: [query] Sooloos.Broker.Music.LibraryAlbum: Process Removes/Adds (small) in 0ms
11/08 06:20:31 Info: [stats] 11994mb Virtual, 7299mb Physical, 1608mb Managed, 433 Handles, 76 Threads
11/08 06:20:32 Debug: [query] Sooloos.Broker.Music.LibraryAlbum:8 dirty (< rebuild threshold of 4210.400000000001).  re-sorting item-by-item (internaltype=LibraryAlbum)
11/08 06:20:32 Info: [query] Sooloos.Broker.Music.LibraryAlbum: Process Removes/Adds (small) in 0ms
11/08 06:20:32 Debug: [query] Sooloos.Broker.Music.LibraryAlbum:8 dirty items, no items in query, rebuilding? False
11/08 06:20:32 Info: [query] Sooloos.Broker.Music.LibraryAlbum: Process Removes/Adds (small) in 0ms
11/08 06:20:32 Debug: [query] Sooloos.Broker.Music.LibraryAlbum:8 dirty (< rebuild threshold of 4210.400000000001).  re-sorting item-by-item (internaltype=LibraryAlbum)
11/08 06:20:32 Info: [query] Sooloos.Broker.Music.LibraryAlbum: Process Removes/Adds (small) in 0ms
11/08 06:20:32 Debug: [query] Sooloos.Broker.Music.LibraryAlbum:8 dirty (< rebuild threshold of 4210.400000000001).  re-sorting item-by-item (internaltype=LibraryAlbum)
11/08 06:20:32 Info: [query] Sooloos.Broker.Music.LibraryAlbum: Process Removes/Adds (small) in 0ms
11/08 06:20:32 Debug: [query] Sooloos.Broker.Music.LibraryAlbum:8 dirty items, no items in query, rebuilding? False
11/08 06:20:32 Info: [query] Sooloos.Broker.Music.LibraryAlbum: Process Removes/Adds (small) in 0ms
11/08 06:20:32 Debug: [query] Sooloos.Broker.Music.LibraryAlbum:8 dirty (< rebuild threshold of 4210.400000000001).  re-sorting item-by-item (internaltype=LibraryAlbum)
11/08 06:20:32 Info: [query] Sooloos.Broker.Music.LibraryAlbum: Process Removes/Adds (small) in 0ms
11/08 06:20:32 Debug: [query] Sooloos.Broker.Music.LibraryAlbum:8 dirty (< rebuild threshold of 4210.400000000001).  re-sorting item-by-item (internaltype=LibraryAlbum)
11/08 06:20:32 Info: [query] Sooloos.Broker.Music.LibraryAlbum: Process Removes/Adds (small) in 1ms
11/08 06:20:32 Debug: [query] Sooloos.Broker.Music.LibraryAlbum:8 dirty (< rebuild threshold of 4210.400000000001).  re-sorting item-by-item (internaltype=LibraryAlbum)
11/08 06:20:32 Info: [query] Sooloos.Broker.Music.LibraryAlbum: Process Removes/Adds (small) in 0ms
11/08 06:20:32 Debug: [query] Sooloos.Broker.Music.LibraryAlbum:8 dirty (< rebuild threshold of 4210.400000000001).  re-sorting item-by-item (internaltype=LibraryAlbum)
11/08 06:20:32 Info: [query] Sooloos.Broker.Music.LibraryAlbum: Process Removes/Adds (small) in 0ms
11/08 06:20:32 Debug: [query] Sooloos.Broker.Music.LibraryAlbum:8 dirty items, no items in query, rebuilding? False
11/08 06:20:32 Info: [query] Sooloos.Broker.Music.LibraryAlbum: Process Removes/Adds (small) in 0ms
11/08 06:20:32 Trace: [dbperf] flush 0 bytes, 0 ops in 4 ms (cumulative 995280846 bytes, 417423 ops in 293142 ms)
11/08 06:20:32 Trace: [library] endmutation in 14187ms
11/08 06:20:32 Debug: [query] Sooloos.Broker.Music.LibraryTrack:57 dirty (< rebuild threshold of 49580).  re-sorting item-by-item (internaltype=LibraryTrack)
11/08 06:20:32 Info: [query] Sooloos.Broker.Music.LibraryTrack: Process Removes/Adds (small) in 0ms
11/08 06:20:32 Debug: [query] Sooloos.Broker.Music.LibraryTrack:57 dirty (< rebuild threshold of 49580).  re-sorting item-by-item (internaltype=LibraryTrack)
11/08 06:20:32 Info: [query] Sooloos.Broker.Music.LibraryTrack: Process Removes/Adds (small) in 0ms
11/08 06:20:32 Trace: [library/playlist] saving playlist folder 10:1:2fbd43db-3328-4514-91b5-3303e447c95c [root]
11/08 06:20:32 Trace: finished updating 2 dirty playlists and 1 dirty playlist folders
11/08 06:20:32 Info: [Gungnir USB] [zoneplayer] Playing: /roon/sys/storage/smbmounts/RoonStorage_9dc70a987209d1cc5f578b772a10f9ad25a63d70/Lossless/JAZZ/Bobby Hutcherson - Dialogue (1965, Blue Note)/04 - Dialogue.flac
11/08 06:20:32 Info: [Gungnir USB] [zoneplayer] Queueing: /roon/sys/storage/smbmounts/RoonStorage_9dc70a987209d1cc5f578b772a10f9ad25a63d70/Lossless/JAZZ/Bobby Hutcherson - Dialogue (1965, Blue Note)/05 - Ghetto Lights.flac
11/08 06:20:32 Trace: [library] endmutation in 63ms
11/08 06:20:32 Info: [Gungnir USB] [zoneplayer]     Open Result (Playing):Result[Status=Success]
11/08 06:20:32 Info: [Gungnir USB] [zoneplayer] Starting playback
11/08 06:20:32 Trace: [Gungnir USB] [zoneplayer/raat] StartStream Sooloos.Broker.Transport.RaatZonePlayer+Endpoint: StreamFormat(channels=2, bitspersample=16, samplerate=44100, isdts=False) => StreamFormat(channels=2, bitspersample=16, samplerate=44100, isdts=False) streamid=252441928
11/08 06:20:32 Info: [zone Gungnir USB] OnPlayFeedback Playing
11/08 06:20:32 Trace: [Gungnir USB] [Lossless, 16/44 FLAC => 16/44] [100% buf] [PLAYING @ 0:00] Dialogue - Bobby Hutcherson / Joe Chambers
11/08 06:20:32 Trace: [prebuffer] ready 149940/441000 (34%) @ 0/602 sec
11/08 06:20:32 Debug: [easyhttp] [9858] GET to https://api.roonlabs.net/metadatatext/1/blobs?objectId=191:0:717685&type=biography&sourceLangs=Rovi-albums:en,Wikipedia:en,Rovi-artists:en,Rovi-compositions:en&tidal=max returned after 215 ms, status code: 200, request body size: 0 B
11/08 06:20:32 Trace: [library] endmutation in 81ms
11/08 06:20:32 Info: [Gungnir USB] [zoneplayer] Open result (Queueing): Result[Status=Success]
11/08 06:20:32 Trace: [Gungnir USB] [zoneplayer/raat] synced to endpoint Schiit Gungnir  Unison USB clock: realtime=18792922150114 rtt=0us offset=-21809737849us delta=-21809737849us
11/08 06:20:32 Trace: [Schiit Gungnir  Unison USB] [raatclient] SENT [18]{"request":"stream","stream_id":252441928,"first_seq":-1,"nak_port":-1,"buffer_size":10,"ready_threshold":0.2}
11/08 06:20:32 Trace: [Schiit Gungnir  Unison USB] [raatclient] GOT [18] {"status":"Buffering"}
11/08 06:20:32 Trace: [Gungnir USB] [zoneplayer/raat] Endpoint Schiit Gungnir  Unison USB State Changed: Prepared => Buffering
11/08 06:20:32 Trace: [Gungnir USB] [zoneplayer/raat] [zoneplayer/raat] selected Schiit Gungnir  Unison USB as clock master
11/08 06:20:32 Debug: [raat/tcpaudiosource] connecting to 192.168.1.21:43945
11/08 06:20:32 Debug: [raat/tcpaudiosource] connected
11/08 06:20:32 Trace: [dbperf] flush 0 bytes, 0 ops in 2 ms (cumulative 995280846 bytes, 417423 ops in 293144 ms)
11/08 06:20:32 Trace: [Schiit Gungnir  Unison USB] [raatclient] GOT [18] {"status":"Ready"}
11/08 06:20:32 Trace: [Gungnir USB] [zoneplayer/raat] Endpoint Schiit Gungnir  Unison USB State Changed: Buffering => Ready
11/08 06:20:32 Trace: [Gungnir USB] [zoneplayer/raat] wait for ready in 9ms
11/08 06:20:32 Trace: [Gungnir USB] [zoneplayer/raat] Adjusting playback start offset from 50ms to 69ms
11/08 06:20:32 Trace: [Gungnir USB] [zoneplayer/raat] Doing 'ASAP' Start since we are just playing to one device
11/08 06:20:32 Trace: [Schiit Gungnir  Unison USB] [raatclient] SENT [19]{"request":"start","min_offset":69342403,"stream_sample":0}
11/08 06:20:32 Trace: [Gungnir USB] [zoneplayer/raat] Endpoint Schiit Gungnir  Unison USB State Changed: Ready => Playing
11/08 06:20:32 Trace: [Schiit Gungnir  Unison USB] [raatclient] GOT [18] {"status":"Playing"}
11/08 06:20:32 Trace: [Schiit Gungnir  Unison USB] [raatclient] GOT [19] {"status":"Success","time":18793007961009}
11/08 06:20:33 Info: 
--[ SignalPath ]---------------------------------------------
SignalPath Quality = Lossless
Elements:
    Source Format=Flac 44100/16/2 BitRate=678 Quality=Lossless
    Raat Device=Schiit Gungnir  Unison USB
    Output OutputType=Local_Alsa Quality=Lossless SubType= Model=Schiit Gungnir  Unison USB
------------------------------------------------------------

connor · November 8, 2024, 3:47pm

Hi @Chris_Haklitch,

Two follow-up questions -

First, in more verbose logging that we’ve enabled for your account, we can see unprompted track transitions occurring without delay on this same DietPi → Schitt Zone. Just to confirm - this delay in track transition only occurs if you manually select Next Track via a Roon controller?

Second question - does this delay issue reproduce on any Zone in this setup with all DSP disabled? Play to the System Output of a controller, or even a networked device using another protocol (Airplay, Linn, etc.).

This ROCK occasionally fails to reach both other devices on the LAN and upstream servers. We can troubleshoot the former by checking for some common failure points with Roon and Orbi setups, but for the latter, we recommend you verify checking the assigned DNS server in your router is reliable (like Cloudflare, 1.1.1.1).

In your Orbi administration settings, verify that “Disable IGMP Proxying” is unchecked in the Advanced tab. Also, make sure IGMP Snooping is enabled, even if you only have one subnet (which is ideal). This setting is intertwined with multicast on Orbi mesh setups.

We’ll watch for your response. Thanks!

Chris_Haklitch · November 8, 2024, 10:14pm

Thanks Connor!

Oddly, and of course! The delay isn’t happening since I restarted by ROCK last night, hence why logs aren’t showing the delay since I reported.

I’ve taken the following actions so far:

Ensured the NUC bios cooling plan was NOT set to Fanless (although I am using a fanless case, I read this helps keep the CPU fully powered)
Updated my router DNS to be 1.1.1.1 / 1.0.0.1 (I had been using my ISP’s default DNS)
UNCHECKED Disable IGMP Proxying (i.e. it’s now enabled)

IGMP Snooping is apparently not possible to enable on these Orbi routers; I couldn’t find any option for it, even when searching.

I noticed something with the ROCK: the Roon Server Software running time shows 5790 days, 21 hours

When I was in bios I noticed the date was not set. I had unplugged the power to the NUC when I moved it to open BIOS. I thought this was odd. My assumption is when I unplugged it again to move it back to my stereo that the BIOS date was reset again - and this is why the Running time shows 5790 days?

Not sure how ROCK OS interacts with BIOS date, if it sets it, or would have issues connecting to the NAS or Roon services/APIs if the BIOS datetime is wrong. Does ROCK set bios time through an NTP server, but not retain it when unplugging it?

Maybe this is a CMOS battery issue? The device is ~3 years old.

I will continue to let this play and build a long playlist history. Issue seems to occur at night after playing music for a while.

Chris_Haklitch · November 8, 2024, 10:22pm

Also to answer some other questions I missed:

Yes, the delay in transition only occurs when clicking NEXT TRACK using a Roon controller (both IOS or Windows apps). A few days ago it would occur even when automatically transitioning tracks during Roon radio.
I will try to reproduce the delay when outputting to an Airplay endpoint of just the device locally when I notice the behavior again, maybe later tonight. When I briefly tried right now on Airplay to Dietpi, no delay (but also no delays at all right now)

daniel · November 14, 2024, 3:48pm

Hi @Chris_Haklitch,
We spoke to the development team about your case. How many smart playlists do you have? Depending on the number you have the track delays could have different causes.

Chris_Haklitch · November 15, 2024, 12:52am

Interesting!

I currently only have 3 Smart Playlists. But those range in track count from 923 to 2844 tracks.

Since I applied those changes, the delay isn’t as long or frequent. But it seems to creep up later in the night, after maybe a few hours of listening.

Chris_Haklitch · November 16, 2024, 1:39am

Hi @daniel - quick update. The heavy track change delays are happening right now, and seem to have started when I put on a Smart Playlist- the one with 2800+ tracks.

Even though I’ve now erased the queue, the performance is dog slow. Even pulling up an album details page is slow.

I also tried streaming to a different zone, then grouped two zones (both using Sonos protocol, no EQ or muse processing). Same slowness when initiating a track change!

connor · November 22, 2024, 4:39pm

Hi @Chris_Haklitch,

Thank you for your ongoing patience as we work behind the scenes to pinpoint the cause in diagnostic logging.

We have a quick A/B test to help isolate components in this database that correlate to performance slowdown.

First, create a Backup of your Roon database to retain everything as it is now.

Next, in the Tags browser, temporarily delete the tag BLACKICE.

Restart RoonServer and then load the smart playlist that has previously exacerbated performance issues. Please let us know if you can reproduce any slowdown and the approximate timestamp, if so.

Thank you again.

Thank you!