Print

Please login or register.
1 Hour 1 Day 1 Week 1 Month Forever
Login with username, password and session length

[Matt]

Plays all the way through track-to-track? :-)

You should turn off memory playback and just see if it fixes that.

It might not.

So then we need to keep digging for what else might be happening.

Since we load in a thread, I wouldn't expect it to lag.

Adjusting the buffering and prebuffering is a next step if that doesn't fix it.

We'll get there!

[zybex]

Matt, since Dawgincontrol provided a few more testcases where this also happens (for him), perhaps you can take a look at what MC is doing before/after it loads the next file into memory? Like, does it perhaps talk to the ASIO device in a way that might interfere with current playback? Does it try any extra network or disk access, perhaps to fetch lyrics or album cover? Does it have a "if (random(1000)<50) sleep(3000)" ? 

[Matt]

Matt, since Dawgincontrol provided a few more testcases where this also happens (for him), perhaps you can take a look at what MC is doing before/after it loads the next file into memory? Like, does it perhaps talk to the ASIO device in a way that might interfere with current playback? Does it try any extra network or disk access, perhaps to fetch lyrics or album cover? Does it have a "if (random(1000)<50) sleep(3000)" ? 

I'm really not sure.

Increasing pre-buffering and buffering would be good things to try.

[zybex]

What about resource locking when accessing the memory buffer? ie, the playback thread needs to read the next block from memory, but some common object is locked by the preloading thread while it processes the next file.
Changing prebuffer sizes would probably masquerade the issue (reduce the number of occurrences), but not eliminate it completely.

[Dawgincontrol]

Zybex brings an interesting note that I should have mentioned. 

I use WASAPI HDMI these days and not ASIO for interface..  I have also tried bitstreaming and not.  I have changed buffering settings also.  I use gapless with Internal Volume if that could possibly have anything to do with it.  I know the difficulty if you can't reproduce it. 

Maybe it's my Cambridge Audio receiver/dac that causes it.  Don't know. 

[Matt]

Zybex brings an interesting note that I should have mentioned. 

I use WASAPI HDMI these days and not ASIO for interface..  I have also tried bitstreaming and not.  I have changed buffering settings also.  I use gapless with Internal Volume if that could possibly have anything to do with it.  I know the difficulty if you can't reproduce it. 

Maybe it's my Cambridge Audio receiver/dac that causes it.  Don't know.

And what if you pick 500ms for the WASAPI buffering?

And pick 20 seconds for the prebuffering.

[Dawgincontrol]

And what if you pick 500ms for the WASAPI buffering?

And pick 20 seconds for the prebuffering.

Tried it.  It surfaced again eventually.

[Matt]

Tried it.  It surfaced again eventually.

Does the log offer any clues?

It just has never happened to me, so it's a puzzle.

[Dawgincontrol]

I'll try to log it next time it happens.  Iving should do the same.

[Iving]

I've tried and tried all buffer settings.

Saw this - and wonder if it helps: https://yabb.jriver.com/interact/index.php/topic,83403.0.html

"Media Center will not start to play the file until it has 2-20s of audio buffered. (which will come from the decoded audio cache if memory playback is enabled)

This is mostly for slow network devices rather than playing files off local drives."

Is this the "waiting" corresponding with the pause towards end of track?

It's waiting too long?

[Iving]

Here's the error-specific log.

By error-specific, I mean that log data immediately surround the error event.

That is - logging was reset/started just before the unwanted pause occurred. Not long after - when play started on the next track - the Log.txt file (in AppData) was opened and copy/pasted as below.

I don't know whether the error is, in fact, betrayed in the log. I hope it is. I hope the log facilitates diagnosis.

Media Center; Version: 28.0.32 (64-bit); Types: 2147483647
0000000: 2712: General: Starting logging: Date: 10/07/2021 07:46
0000000: 2712: General: More information about logging here: https://wiki.jriver.com/index.php/Logging
0000000: 2712: General: Log Reset: Logging reset
0001655: 2712: General: CMCResourceHelper::GetIsModalPopupShowing: Main window disabled
0009514: 3132: Playback: CMJWaveFeeder::Thread: Finished feeder loop (bCancel: 0, bPlayed: 1)
0009514: 3132: Playback: CMJWaveFeeder::Thread: Sending EOF
0009514: 3132: Playback: CPlayerZone::JRPlaybackEngine_EndOfFile: Start
0009514: 3132: Playback: CPlayerZone::PlayNextFile: bCanPlayNext=1, m_bPlaybackError=0
0009514: 3132: Playback: CPlayerZone::JRPlaybackEngine_EndOfFile: Finish (0 ms)
0009514: 3132: Playback: CMJWaveFeeder::Thread: Finish (201049 ms)
0009514: 2712: Playback: CPlayerZone::Next: Start
0009514: 2712: Playback: CPlayerZone::Next: Checking for invalid position
0009514: 2712: Playback: CPlayerZone::Next: Attempting next chapter
0009514: 2712: Playback: CPlayerZone::Next: Checking for next disabled
0009514: 2712: Playback: CPlayerZone::Next: Checking for display / internal mismatch
0009514: 2712: Playback: CPlayerZone::Next: Checking can play next state
0009514: 2712: Playback: CPlayerZone::Next: Updating position, old=28
0009514: 2712: Playback: CPlayerZone::Next:   new=29
0009514: 2712: Playback: CPlayerZone::Next: Play
0009514: 2712: Playback: CPlayerZone::Play: Start
0009514: 2712: Playback: CPlayerZoneDisplayInfoUpdateThread::Destructor: Start
0009514: 3124: Playback: CPlayerZoneDisplayInfoUpdateThread::Thread: Finish (201049 ms)
0009535: 2712: Playback: CPlayerZoneDisplayInfoUpdateThread::Destructor: Finish (20 ms)
0009535: 2712: Database: CDataHolder::Load: Field: Last Played; Files: 24593; Pointer bytes: 33824; Data bytes: 16488; Elapsed ms: 0.335
0009536: 2712: Database: CDataHolder::Load: Field: Last Played (album); Files: 24593; Pointer bytes: 197032; Data bytes: 16488; Elapsed ms: 0.564
0009538: 2712: Database: CSearchFilesHelper::GetResults: Search: [Album Artist (auto)]=[America] [Album]=[History /- America's Greatest Hits]; Elapsed ms: 1.622
0009538: 2712: Database: CDataHolder::Load: Field: Usage Reporting Info; Files: 24593; Pointer bytes: 0; Data bytes: 72; Elapsed ms: 0.024
0009538: 2712: Playback: CPlayerZone::Play: Handling exclusive playback zones
0009538: 2712: Playback: CPlayerZone::Play: Getting actual playback track
0009558: 2712: Playback: CPlayerZone::Play: Processing play for 'C:\Users\Host\Music\Popular\Black, Mary_Without The Fanfare_07_Ellis Island.flac'
0009558: 2712: Playback: CPlayerZone::Play: Updating internal track info
0009558: 2712: Playback: CPlayerZone::Play: Playing: <XMLFN version="1.0"><Item Name="Filename">C:\Users\Host\Music\Popular\Black, Mary_Without The Fanfare_07_Ellis Island.flac</Item><Item Name="PlaylistIndex">29</Item><Item Name="AlbumSequentialWithLastTrack">0</Item><Item Name="SampleRate">44100</Item><Item Name="VolumeReset">0</Item><Item Name="Channels">2</Item><Item Name="ErrorFreeMode">0</Item><Item Name="VolumePeakLevels"></Item><Item Name="MediaType">Audio</Item><Item Name="DatabaseKey">968</Item><Item Name="VolumeTrackMaxSafeGain">-1</Item><Item Name="Bitrate">851</Item><Item Name="Bookmark"></Item><Item Name="BitDepth">16</Item><Item Name="LengthInPCMBlocks"></Item><Item Name="DRMProtected"></Item><Item Name="VolumeLeveling">-10</Item><Item Name="DSP"></Item><Item Name="FileType">flac</Item></XMLFN>
0009558: 2712: Playback: CJRPlaybackEngine::Play: Start
0009559: 2712: Playback: CJRPlaybackEngine::Play: Volume protection: 0
0009559: 2712: Playback: CJRPlaybackEngine::Play: Playing: C:\Users\Host\Music\Popular\Black, Mary_Without The Fanfare_07_Ellis Island.flac
0009559: 2712: Playback: CJRPlaybackEngine::Play: Filetype: flac; Type: 1; Can play: 1; Playback object: 0xa4e48a5640
0009559: 2712: Playback: CJRPlaybackEngine::StartPlayFile: Start
0009559: 2712: Playback: CMJPlaybackType::Play: Start
0009559: 2712: Playback: CMJPlayerCore::Play: Start
0009559: 2712: Playback: CMJWaveFeeder::~CMJWaveFeeder: Start
0009559: 2712: Playback: CMJWaveFeeder::~CMJWaveFeeder: Cancel
0009559: 2712: Playback: CMJWaveFeeder::~CMJWaveFeeder: Stopping thread
0009559: 2712: Playback: CMJWaveFeeder::~CMJWaveFeeder: Deleting input source
0009559: 2712: General: CFlacDecoder::~CFlacDecoder: Start
0009559: 2712: General: CFlacDecoder::~CFlacDecoder: Finish (0 ms)
0009559: 2712: Playback: CMJWaveFeeder::~CMJWaveFeeder: Finish (0 ms)
0009559: 2712: Playback: CMJPlayerCore::Play: Created feeder helper for type flac (native: 1)
0009559: 2712: Playback: CMJWaveFeeder::Play: Start
0009559: 2712: General: CFlacDecoder::CFlacDecoder: Start
0009559: 2712: General: CFlacDecoder::CFlacDecoder: Finish (0 ms)
0009559: 2712: Playback: CMJWaveFeeder::Play: Finish (0 ms)
0009559: 2712: Playback: CMJPlayerCore::Play: Play succeeded
0009559: 2712: Playback: CMJPlayerCore::Play: Result: 1
0009559: 2712: Playback: CMJPlayerCore::Play: Finish (0 ms)
0009559: 2712: Playback: CMJPlaybackType::Play: Play result: 1
0009559: 2712: Playback: CMJPlaybackType::Play: Finish (0 ms)
0009559: 2712: Playback: CJRPlaybackEngine::StartPlayFile: Play returned: 1
0009559: 2712: Playback: CJRPlaybackEngine::StartPlayFile: Finish (0 ms)
0009559: 2712: Playback: CJRPlaybackEngine::Play: StartPlayFile returned 1
0009559: 2712: Playback: CJRPlaybackEngine::Play: Finish (0 ms)
0009559: 2712: Playback: CPlayerZone::Play: Play succeeded
0009559: 1720: Playback: CMJWaveFeeder::Thread: Start
0009559: 1720: Playback: CMJWaveFeeder::Thread: Adding skinning
0009559: 1720: Playback: CMJWaveFeeder::Thread: Opening file
0009559: 2712: Playback: CPlayerZoneDisplayInfoUpdateThreadPause::~CPlayerZoneDisplayInfoUpdateThreadPause: Start
0009559: 2712: Playback: CPlayerZoneDisplayInfoUpdateThreadPause::~CPlayerZoneDisplayInfoUpdateThreadPause: Finish (0 ms)
0009559: 2712: Playback: CPlayerZone::Play: Finish (45 ms)
0009559: 2712: Playback: CPlayerZone::Next: Applying database changes
0009559: 2952: Playback: CPlayerZoneDisplayInfoUpdateThread::Thread: Start
0009559: 2952: Playback: CPlayerZoneDisplayInfoUpdateThread::Thread: Zone: Player (id: 0)
0009560: 2712: Playback: CPlayerZone::Next: Finish (45 ms)
0009560: 1720: Playback: CMJWaveFeeder::Thread: Setting output format
0009560: 1720: Playback: CAutoConfigureAudioOutput::GetOutputFormat: Start
0009560: 1720: Playback: CAutoConfigureAudioOutput::GetOutputFormat: Using input format
0009560: 1720: Playback: CAutoConfigureAudioOutput::GetOutputFormat: Applying output format settings
0009560: 1720: Playback: CAutoConfigureAudioOutput::GetOutputFormat: 176.4 kHz 16bit 2ch
0009560: 1720: Playback: CAutoConfigureAudioOutput::GetOutputFormat: Finish (0 ms)
0009560: 1720: Playback: CMJWaveFeeder::Thread: Preparing to feed data
0009560: 1720: Playback: CMJWaveFeeder::Thread: Memory playback: 1; Maximum play buffer bytes: 4294967296; Grow by bytes: 33554432; System available bytes: 15907729408
0009560: 1720: Playback: CMJWaveFeeder::Thread: Running feeder loop
0018478: 2712: General: CMCUICore::SystemPowerManager_UpdateActions: Start
0018479: 2712: General: CMCUICore::SystemPowerManager_UpdateActions: UI Mode: -999; Playing: 1
0018479: 2712: General: CMCUICore::SystemPowerManager_UpdateActions: Finish (result: 0) (0 ms)
0019567: 1720: Playback: CPlayerZone::OnNewStream: Start
0019567: 1720: Playback: CPlayerZone::OnNewStream: Finish (0 ms)
0020551: 5020: Playback: CPlayerZoneDisplayInfoLoadImageThread::Thread: Start
0020551: 5020: Playback: CPlayerZoneDisplayInfoLoadImageThread::Thread: Image: 0000000000000000
0020551: 5020: Playback: CPlayerZoneDisplayInfoLoadImageThread::Thread: Finish (0 ms)

[AGAWA]

Remark about SQ in playback by Media player:
everything is being played from memory;
there always is suitable buffer to provide steady stream of data.
And it doesn't matter if the track or album is fully fetched to memory or buffer is being filled with data as music plays.
I do not see how SQ should differ in two scenarios.
Maybe someone can enlighten me in this matter.

[JimH]

Try turrning off Lyrics Lookup in options.

[Iving]

Try turrning off Lyrics Lookup in options.

Lyrics lookup has been unchecked since first setup. It's never been on.

[Matt]

What if you try a portable install to test for setting changes?  I think it would start with the defaults.

[Iving]

Does the log offer any clues?

Having posted the log, I'm hoping you can read it please?

[Iving]

Code is not my bag; however, this reads suspiciously.

0009559: 2712: Playback: CMJWaveFeeder::~CMJWaveFeeder: Start
0009559: 2712: Playback: CMJWaveFeeder::~CMJWaveFeeder: Cancel
0009559: 2712: Playback: CMJWaveFeeder::~CMJWaveFeeder: Stopping thread
0009559: 2712: Playback: CMJWaveFeeder::~CMJWaveFeeder: Deleting input source

?

[Iving]

This problem is JRiver specific.

All other players I have tried do not exhibit this pause towards the end of a track.

That is with the same ASIO audio path "all other things equal".

I have exhausted plausible settings in JRiver (and DVS ASIO on JRiver's behalf - since no other player seems to mind).

Thank you

[AGAWA]

0009514: 2712: Playback: CPlayerZoneDisplayInfoUpdateThread::Destructor: Start
0009514: 3124: Playback: CPlayerZoneDisplayInfoUpdateThread::Thread: Finish (201049 ms)
0009535: 2712: Playback: CPlayerZoneDisplayInfoUpdateThread::Destructor: Finish (20 ms)
0009535: 2712: Database: CDataHolder::Load: Field: Last Played; Files: 24593; Pointer bytes: 33824; Data bytes: 16488; Elapsed ms: 0.335
0009536: 2712: Database: CDataHolder::Load: Field: Last Played (album); Files: 24593; Pointer bytes: 197032; Data bytes: 16488; Elapsed ms: 0.564
0009538: 2712: Database: CSearchFilesHelper::GetResults: Search: [Album Artist (auto)]=[America] [Album]=[History /- America's Greatest Hits]; Elapsed ms: 1.622
0009538: 2712: Database: CDataHolder::Load: Field: Usage Reporting Info; Files: 24593; Pointer bytes: 0; Data bytes: 72; Elapsed ms: 0.024

add partial times and the result will be close to pause experienced

[zybex]

No, "1.622 ms" means 1622 microseconds = 1.6ms.
The first number on each line is the time in milliseconds since logging started. So your snippet here is just about 24ms long.

Looking at the original log, it looks like the pause is not logged. I also don't see the prebuffering or memory-load on the next song in this log (I don't know if these things are logged - Matt will know):

@1.65s: you minimized the main window (I think), and previous song is playing
<nothing logged for 8 seconds, presumably the pause happens here>
@9.51s: song finishes
@9.53s: updating display, updating some fields and indexes
@9.55s: preparing to play next song
@9.56s: start memory playback of next song
<nothing logged for 9 seconds>
@18.4s: some UI action
@19.5s: CPlayerZone::OnNewStream:Start - new stream of what?
@20.5s: updating UI? Cover?


It looks like the pause+preloading happened in that 8 seconds without logging, but there's another possibility - the log might just be a few seconds delayed relative to the actual playback due to buffering/prebuffering, so when JR logs that it has finished the current song (@9.5s), it may actually still be playing. That would mean the preloading of next song is what is logged around the 9.5s mark, and the hiccup would happen later, perhaps in that 2nd unlogged window.

MC developers could throw some light into it...

[MikeO3]

There is only one drive. The Optane PCI-e AIC. It is 900P 480 Gb. It has the o/s Windows 10 Pro and my flac files. Nothing else except Programs inc. JRiver!

Been reading this thread and was wondering if you could post info about your motherboard model, firmware version and the specific slots you have your ssd, video card and other hardware if you have.

Also posting Help>System Info and Benchmark would be useful to understand your configuration.

Insight into interupts and bus connections could a be a pointer for some of us types who look there before delving into thread creation or blocking issues. Been burned on high-end servers and workstations by misplaced pci cards before. Thanks for indulging my curiosity!

[Iving]

Been reading this thread and was wondering if you could post info about your motherboard model, firmware version and the specific slots you have your ssd, video card and other hardware if you have.

Also posting Help>System Info and Benchmark would be useful to understand your configuration.

Insight into interupts and bus connections could a be a pointer for some of us types who look there before delving into thread creation or blocking issues. Been burned on high-end servers and workstations by misplaced pci cards before. Thanks for indulging my curiosity!

ASUS Z270-WS with latest BIOS and Optane AIC in CPU direct slot 1. No other drives. No video card. This is not a wobbly PCI-e card problem! There are no other functional issues on this PC. Other players - fb2k and several besides - work fine "all things equal".

[Matt]

I put a ten second sleep in the open of the APE code to test.

Playback is still perfectly gapless since it's all threaded.

So I don't think it's stalling opening the file causing this.

It would still be good if you would turn off memory playback and confirm the gaps are gone.  I'm not sure you've done that yet, and we need to dig to figure it out.

[Iving]

there's another possibility - the log might just be a few seconds delayed relative to the actual playback due to buffering/prebuffering, so when JR logs that it has finished the current song (@9.5s), it may actually still be playing. That would mean the preloading of next song is what is logged around the 9.5s mark, and the hiccup would happen later, perhaps in that 2nd unlogged window.

It would still be good if you would turn off memory playback and confirm the gaps are gone.  I'm not sure you've done that yet, and we need to dig to figure it out.

Matt - you mean pauses are gone not gaps, right?

Yes - I just turned "play from memory" off. 1st Track OK. Second track paused at end i.e. fault under discussion. I counted the pause at 6-7 secs. This time in answer to zybex I took a longer log snapshot - from 1 min. prior to end of current track to 2 mins. into next track. Here it is:

Media Center; Version: 28.0.32 (64-bit); Types: 2147483647
0000000: 4076: General: Starting logging: Date: 11/07/2021 13:11
0000000: 4076: General: More information about logging here: https://wiki.jriver.com/index.php/Logging
0000000: 4076: General: Log Reset: Logging reset
0001699: 4076: General: CMCResourceHelper::GetIsModalPopupShowing: Main window disabled
0012038: 4076: General: CMCUICore::SystemPowerManager_UpdateActions: Start
0012038: 4076: General: CMCUICore::SystemPowerManager_UpdateActions: UI Mode: -999; Playing: 1
0012038: 4076: General: CMCUICore::SystemPowerManager_UpdateActions: Finish (result: 0) (0 ms)
0042038: 4076: General: CMCUICore::SystemPowerManager_UpdateActions: Start
0042038: 4076: General: CMCUICore::SystemPowerManager_UpdateActions: UI Mode: -999; Playing: 1
0042038: 4076: General: CMCUICore::SystemPowerManager_UpdateActions: Finish (result: 0) (0 ms)
0057093: 3224: Playback: CMJWaveFeeder::Thread: Finished feeder loop (bCancel: 0, bPlayed: 1)
0057093: 3224: Playback: CMJWaveFeeder::Thread: Sending EOF
0057093: 3224: Playback: CPlayerZone::JRPlaybackEngine_EndOfFile: Start
0057093: 3224: Playback: CPlayerZone::PlayNextFile: bCanPlayNext=1, m_bPlaybackError=0
0057093: 3224: Playback: CPlayerZone::JRPlaybackEngine_EndOfFile: Finish (0 ms)
0057093: 3224: Playback: CMJWaveFeeder::Thread: Finish (193235 ms)
0057093: 4076: Playback: CPlayerZone::Next: Start
0057093: 4076: Playback: CPlayerZone::Next: Checking for invalid position
0057093: 4076: Playback: CPlayerZone::Next: Attempting next chapter
0057093: 4076: Playback: CPlayerZone::Next: Checking for next disabled
0057093: 4076: Playback: CPlayerZone::Next: Checking for display / internal mismatch
0057093: 4076: Playback: CPlayerZone::Next: Checking can play next state
0057093: 4076: Playback: CPlayerZone::Next: Updating position, old=17
0057093: 4076: Playback: CPlayerZone::Next:   new=18
0057093: 4076: Playback: CPlayerZone::Next: Play
0057093: 4076: Playback: CPlayerZone::Play: Start
0057093: 4076: Playback: CPlayerZoneDisplayInfoUpdateThread::Destructor: Start
0057093: 4080: Playback: CPlayerZoneDisplayInfoUpdateThread::Thread: Finish (193236 ms)
0057114: 4076: Playback: CPlayerZoneDisplayInfoUpdateThread::Destructor: Finish (20 ms)
0057116: 4076: Database: CSearchFilesHelper::GetResults: Search: [Album Artist (auto)]=[Union Gap, The featuring Gary Puckett] [Album]=[The 60s U.S. Playlist /[Disc 1/]]; Elapsed ms: 2.068
0057116: 4076: Playback: CPlayerZone::Play: Handling exclusive playback zones
0057116: 4076: Playback: CPlayerZone::Play: Getting actual playback track
0057137: 4076: Playback: CPlayerZone::Play: Processing play for 'C:\Users\Host\Music\Popular\Various_Hillbilly Boogie [Disc 1]_04_Pan American Boogie_Glosson, Lonnie.flac'
0057137: 4076: Playback: CPlayerZone::Play: Updating internal track info
0057137: 4076: Playback: CPlayerZone::Play: Playing: <XMLFN version="1.0"><Item Name="Filename">C:\Users\Host\Music\Popular\Various_Hillbilly Boogie [Disc 1]_04_Pan American Boogie_Glosson, Lonnie.flac</Item><Item Name="PlaylistIndex">18</Item><Item Name="AlbumSequentialWithLastTrack">0</Item><Item Name="SampleRate">44100</Item><Item Name="VolumeReset">0</Item><Item Name="Channels">2</Item><Item Name="ErrorFreeMode">0</Item><Item Name="VolumePeakLevels"></Item><Item Name="MediaType">Audio</Item><Item Name="DatabaseKey">14594</Item><Item Name="VolumeTrackMaxSafeGain">-1</Item><Item Name="Bitrate">332</Item><Item Name="Bookmark"></Item><Item Name="BitDepth">16</Item><Item Name="LengthInPCMBlocks"></Item><Item Name="DRMProtected"></Item><Item Name="VolumeLeveling">-10</Item><Item Name="DSP"></Item><Item Name="FileType">flac</Item></XMLFN>
0057137: 4076: Playback: CJRPlaybackEngine::Play: Start
0057137: 4076: Playback: CJRPlaybackEngine::Play: Volume protection: 0
0057137: 4076: Playback: CJRPlaybackEngine::Play: Playing: C:\Users\Host\Music\Popular\Various_Hillbilly Boogie [Disc 1]_04_Pan American Boogie_Glosson, Lonnie.flac
0057137: 4076: Playback: CJRPlaybackEngine::Play: Filetype: flac; Type: 1; Can play: 1; Playback object: 0xf3547fea40
0057137: 4076: Playback: CJRPlaybackEngine::StartPlayFile: Start
0057137: 4076: Playback: CMJPlaybackType::Play: Start
0057137: 4076: Playback: CMJPlayerCore::Play: Start
0057137: 4076: Playback: CMJWaveFeeder::~CMJWaveFeeder: Start
0057138: 4076: Playback: CMJWaveFeeder::~CMJWaveFeeder: Cancel
0057138: 4076: Playback: CMJWaveFeeder::~CMJWaveFeeder: Stopping thread
0057138: 4076: Playback: CMJWaveFeeder::~CMJWaveFeeder: Deleting input source
0057138: 4076: General: CFlacDecoder::~CFlacDecoder: Start
0057138: 4076: General: CFlacDecoder::~CFlacDecoder: Finish (0 ms)
0057138: 4076: Playback: CMJWaveFeeder::~CMJWaveFeeder: Finish (0 ms)
0057138: 4076: Playback: CMJPlayerCore::Play: Created feeder helper for type flac (native: 1)
0057138: 4076: Playback: CMJWaveFeeder::Play: Start
0057138: 4076: General: CFlacDecoder::CFlacDecoder: Start
0057138: 4076: General: CFlacDecoder::CFlacDecoder: Finish (0 ms)
0057138: 4076: Playback: CMJWaveFeeder::Play: Finish (0 ms)
0057138: 4076: Playback: CMJPlayerCore::Play: Play succeeded
0057138: 4076: Playback: CMJPlayerCore::Play: Result: 1
0057138: 4076: Playback: CMJPlayerCore::Play: Finish (0 ms)
0057138: 4076: Playback: CMJPlaybackType::Play: Play result: 1
0057138: 4076: Playback: CMJPlaybackType::Play: Finish (0 ms)
0057138: 4076: Playback: CJRPlaybackEngine::StartPlayFile: Play returned: 1
0057138: 4076: Playback: CJRPlaybackEngine::StartPlayFile: Finish (0 ms)
0057138: 4076: Playback: CJRPlaybackEngine::Play: StartPlayFile returned 1
0057138: 3200: Playback: CMJWaveFeeder::Thread: Start
0057138: 4076: Playback: CJRPlaybackEngine::Play: Finish (0 ms)
0057138: 3200: Playback: CMJWaveFeeder::Thread: Adding skinning
0057138: 4076: Playback: CPlayerZone::Play: Play succeeded
0057138: 3200: Playback: CMJWaveFeeder::Thread: Opening file
0057138: 4076: Playback: CPlayerZoneDisplayInfoUpdateThreadPause::~CPlayerZoneDisplayInfoUpdateThreadPause: Start
0057138: 4076: Playback: CPlayerZoneDisplayInfoUpdateThreadPause::~CPlayerZoneDisplayInfoUpdateThreadPause: Finish (0 ms)
0057138: 4076: Playback: CPlayerZone::Play: Finish (44 ms)
0057138: 4076: Playback: CPlayerZone::Next: Applying database changes
0057138: 164: Playback: CPlayerZoneDisplayInfoUpdateThread::Thread: Start
0057138: 164: Playback: CPlayerZoneDisplayInfoUpdateThread::Thread: Zone: Player (id: 0)
0057138: 4076: Playback: CPlayerZone::Next: Finish (44 ms)
0057138: 3200: Playback: CMJWaveFeeder::Thread: Setting output format
0057138: 3200: Playback: CAutoConfigureAudioOutput::GetOutputFormat: Start
0057138: 3200: Playback: CAutoConfigureAudioOutput::GetOutputFormat: Using input format
0057138: 3200: Playback: CAutoConfigureAudioOutput::GetOutputFormat: Applying output format settings
0057138: 3200: Playback: CAutoConfigureAudioOutput::GetOutputFormat: 176.4 kHz 16bit 2ch
0057138: 3200: Playback: CAutoConfigureAudioOutput::GetOutputFormat: Finish (0 ms)
0057138: 3200: Playback: CMJWaveFeeder::Thread: Preparing to feed data
0057138: 3200: Playback: CMJWaveFeeder::Thread: Memory playback: 0; Maximum play buffer bytes: 4294967296; Grow by bytes: 33554432; System available bytes: 15644250112
0057138: 3200: Playback: CMJWaveFeeder::Thread: Running feeder loop
0058332: 4076: Database: MCDB::Save: Start
0058332: 4076: Database: MCDB::Save: Saving (bCleanDB: 0, bForce: 0)
0058332: 4076: Database: CMediaFileIOSave::Start: Start
0058332: 4076: Database: CMediaFileIOSave::Start: Saving: C:\Users\Host\AppData\Roaming\J River\Media Center 28\Library\curplaylist.jmd
0058332: 4076: Database: CMediaFileIOSave::Start: JRFile Open returned
0058332: 4076: Database: CMediaFileIOSave::Start: Finish (0 ms)
0058334: 4076: Database: CMediaFileIOSave::Start: Start
0058334: 4076: Database: CMediaFileIOSave::Start: Saving: C:\Users\Host\AppData\Roaming\J River\Media Center 28\Library\field (last played).jmd
0058334: 4076: Database: CMediaFileIOSave::Start: JRFile Open returned
0058334: 4076: Database: CMediaFileIOSave::Start: Finish (0 ms)
0058335: 4076: Database: CDataHolder::Save: Field: Last Played; Elapsed ms: 1.135
0058335: 4076: Database: CMediaFileIOSave::Start: Start
0058335: 4076: Database: CMediaFileIOSave::Start: Saving: C:\Users\Host\AppData\Roaming\J River\Media Center 28\Library\field (last played (album)).jmd
0058335: 4076: Database: CMediaFileIOSave::Start: JRFile Open returned
0058335: 4076: Database: CMediaFileIOSave::Start: Finish (0 ms)
0058336: 4076: Database: CDataHolder::Save: Field: Last Played (album); Elapsed ms: 1.188
0058336: 4076: Database: CMediaFileIOSave::Start: Start
0058336: 4076: Database: CMediaFileIOSave::Start: Saving: C:\Users\Host\AppData\Roaming\J River\Media Center 28\Library\field (number plays).jmd
0058336: 4076: Database: CMediaFileIOSave::Start: JRFile Open returned
0058336: 4076: Database: CMediaFileIOSave::Start: Finish (0 ms)
0058337: 4076: Database: CDataHolder::Save: Field: Number Plays; Elapsed ms: 0.977
0058337: 4076: Database: CMediaFileIOSave::Start: Start
0058337: 4076: Database: CMediaFileIOSave::Start: Saving: C:\Users\Host\AppData\Roaming\J River\Media Center 28\Library\field (date tagged).jmd
0058338: 4076: Database: CMediaFileIOSave::Start: JRFile Open returned
0058338: 4076: Database: CMediaFileIOSave::Start: Finish (0 ms)
0058339: 4076: Database: CDataHolder::Save: Field: Date Tagged; Elapsed ms: 1.725
0058339: 4076: Database: CMediaFileIOSave::Start: Start
0058339: 4076: Database: CMediaFileIOSave::Start: Saving: C:\Users\Host\AppData\Roaming\J River\Media Center 28\Library\field (date last opened).jmd
0058339: 4076: Database: CMediaFileIOSave::Start: JRFile Open returned
0058339: 4076: Database: CMediaFileIOSave::Start: Finish (0 ms)
0058340: 4076: Database: CDataHolder::Save: Field: Date Last Opened; Elapsed ms: 1.079
0058340: 4076: Database: CPlaylistsDB::Save: Start
0058340: 4076: Database: CPlaylistsDB::Save: Finish (0 ms)
0058340: 4076: Database: MCDB::Save: Finish (8 ms)
0067145: 3200: Playback: CPlayerZone::OnNewStream: Start
0067145: 3200: Playback: CPlayerZone::OnNewStream: Finish (0 ms)
0067436: 2984: Playback: CPlayerZoneDisplayInfoLoadImageThread::Thread: Start
0067436: 2984: Playback: CPlayerZoneDisplayInfoLoadImageThread::Thread: Image: 0000000000000000
0067436: 2984: Playback: CPlayerZoneDisplayInfoLoadImageThread::Thread: Finish (0 ms)
0072037: 4076: General: CMCUICore::SystemPowerManager_UpdateActions: Start
0072037: 4076: General: CMCUICore::SystemPowerManager_UpdateActions: UI Mode: -999; Playing: 1
0072037: 4076: General: CMCUICore::SystemPowerManager_UpdateActions: Finish (result: 0) (0 ms)
0102040: 4076: General: CMCUICore::SystemPowerManager_UpdateActions: Start
0102040: 4076: General: CMCUICore::SystemPowerManager_UpdateActions: UI Mode: -999; Playing: 1
0102040: 4076: General: CMCUICore::SystemPowerManager_UpdateActions: Finish (result: 0) (0 ms)
0132038: 4076: General: CMCUICore::SystemPowerManager_UpdateActions: Start
0132038: 4076: General: CMCUICore::SystemPowerManager_UpdateActions: UI Mode: -999; Playing: 1
0132038: 4076: General: CMCUICore::SystemPowerManager_UpdateActions: Finish (result: 0) (0 ms)
0162034: 4076: General: CMCUICore::SystemPowerManager_UpdateActions: Start
0162034: 4076: General: CMCUICore::SystemPowerManager_UpdateActions: UI Mode: -999; Playing: 1
0162034: 4076: General: CMCUICore::SystemPowerManager_UpdateActions: Finish (result: 0) (0 ms)
0178333: 4076: Database: MCDB::Save: Start
0178333: 4076: Database: MCDB::Save: Saving (bCleanDB: 0, bForce: 0)
0178334: 4076: Database: CPlaylistsDB::Save: Start
0178334: 4076: Database: CPlaylistsDB::Save: Finish (0 ms)
0178334: 4076: Database: CMediaFileIOSave::Start: Start
0178334: 4076: Database: CMediaFileIOSave::Start: Saving: C:\Users\Host\AppData\Roaming\J River\Media Center 28\Library\view state (index).jmd
0178334: 4076: Database: CMediaFileIOSave::Start: JRFile Open returned
0178334: 4076: Database: CMediaFileIOSave::Start: Finish (0 ms)
0178335: 4076: Database: MCDB::Save: Finish (2 ms)

[Matt]

Good it's still happening with memory playback off.

Could you try some MP3 or APE files on a different drive, just to test?  Keep memory playback off to keep things simple.

Thanks.  It might take a while, but hopefully we'll be able to figure this out.

[Matt]

Another thing we could try is you could send a library backup to matt at jriver dot com and I could try on my side with the exact same settings.

Thanks.

[Iving]

Good it's still happening with memory playback off.

Could you try some MP3 or APE files on a different drive, just to test?  Keep memory playback off to keep things simple.

Thanks.  It might take a while, but hopefully we'll be able to figure this out.

Matt - First I don't have any MP3 or APE. All I do is play flac 44.1 redbook rips from a hard drive. Second I don't have another drive on this PC (not even a CD/DVD). I could play from flash or an external HDD I suppose. But I'd have to do a bunch of conversions etc which I'm not familiar with so more research etc. This is not helped when your rationale for getting me to test not explained to me, and I do things like get log with no conversation about it. JimH tells me not to "debate" (implicit just obey) so I'm reluctant to explain these reservations to you. Please understand, I am just a potential customer evaluating your product waiting to buy. There is a glitch - 6 sec. pause at end of track as likely to occur as not - which no other player exhibits "all other things equal" i.e. with my perfectly good audiophile-dedicated machine exactly as is and with same audio path PC > 44.1 flac upsampled x 4 > ASIO > Dante. I have spent hours and hours trying to resolve this myself and co-operating with you. I also have a life and I want to play music. And I have a wife. And DIY. And work responsibilities. I will keep checking in to the thread. I'm still interested in JRiver. fb2k works fine. I'm evaluating HQ Player which has great SQ but is not user friendly (to me so far). Please understand. I am just a potential customer interested in your product for nice reasons.

[Iving]

Another thing we could try is you could send a library backup to matt at jriver dot com and I could try on my side with the exact same settings.

Thanks.

My Library proper is 1.5Tb.
The flac on my audiophile machine are some 400 Gb.
They are ordinary flac.
On my ordinary workhorse machine flac play fine in players inc. JRiver probably - but this is default sound device not ASIO/Dante.
So not really any point.
We know my flac can play fine in JRiver on PCs inc. one of my own.

Can you consider whether *in relation to audio/flac play* JRiver relies on Windows processes/settings/updates *that other players do not*.

Something "special" about JRiver?

Unless something obvious occurs to you *in relation to this question*, we could spend too much time on this.

:-)

[Matt]

Try making a new library and import only a single album.  Play that and test.

Sending me a backup would also be really nice.  If you want to figure it out, you might have to.

Thanks.

[AGAWA]

Dante network:
do not use Ethernet switches that support the EEE

[Dawgincontrol]

On mine it never had a problem with a single album.  Only in playlists and mixed plays. 

Iving up-samples all his files.  All of my problems were related to up-sampling also (Media Center can't send 88.2khz to my system, so I up-sample to 96) .  Have to think that's what the "pause/stutter" is related to. 

[Iving]

Dante network:
do not use Ethernet switches that support the EEE

All power saving settings are switched off wherever possible.

[Iving]

On mine it never had a problem with a single album.  Only in playlists and mixed plays. 

Iving up-samples all his files.  All of my problems were related to up-sampling also (Media Center can't send 88.2khz to my system, so I up-sample to 96) .  Have to think that's what the "pause/stutter" is related to.

Sure :-)

To evaluate I would have to do some serious re-setting down the line inc. RedNet Control, Devices in Dante Controller, Mutec MC-3+ USB Re-clocker and WC, DAC - some of which boxes are physically inaccessible in a "built" system, and all of which would have to be reversed afterwards ...
... to investigate a scenario I would never use (no upsampling) ...
... really just a Sox matter ...
... which works fine in fb2k anyway.

[Matt]

I just tried playing a 96 kHz album I have resampled with SoX to 192 kHz.  That also worked.

[Dawgincontrol]

It's been so random with mine.  It only happens on my 88,200 files in a mixed playlist and seems to be reliant on the next file not being so (or the previous).  It also happens whether I use SOX or not. 

I know it's not easy, just relaying where I ended up with my elimination and trials in search of the problem.  I tried a lot of different combinations.

[Matt]

If you have a few files where it happens over and over you could try sharing them with me.  Thanks.

[AGAWA]

for your interest:
https://yabb.jriver.com/interact/index.php/topic,103261.msg717134.html#msg717134

[Iving]

for your interest:
https://yabb.jriver.com/interact/index.php/topic,103261.msg717134.html#msg717134

Well that's very interesting.

Thank you

I hope the JRiver team can make sense of it/map its principles to this case.

I'm now about out of willingness to run unpromising diagnostic tests myself.

[Iving]

Here's another: https://yabb.jriver.com/interact/index.php/topic,111355.msg769597.html#msg769597.

Search "Dante Virtual" brings up quite a few entries. I shouldn't be surprised if triangulation of these offers the necessary insight.

[AGAWA]

https://forums.steinberg.net/t/pc-windows-asio-multiclient-driver-by-charlie-steinberg/20479

[MarcVRML]

Not sure if this thread is still active, but I can also report experiencing the problem of random pausing (lasting several seconds - at least 5) about 4 seconds prior to the end of a track during playback.

During these pauses, I have noticed that WMIPRVSE.exe occupies high CPU usage, and playback resumes when this CPU usage clears after a few seconds.

I'm running MC28.0.94 (64 bit) on Windows 10 Pro.

Plenty of RAM (64GB), fast SSD for music library (connected direct to mainboard, and not via USB), many MANY cores still available on the CPU (AMD Threadripper 3990X).

Playback pausing occurs at random, but always seems to be about 4-6 seconds from the end of a track, as if during the buffering process of loading the next track in for playback.

I'm experiencing this in my own smartlists, which select many tracks for playback at random.

I've tried changing pre-buffering from the default 6 seconds, down to 2 seconds and up to 20 seconds, as well as changing the fade-method between one track and another, and have observed this issue regardless of settings.

As with others reporting the issue, I have no problem playing the same tracks using other music players, such as MusicBee.

In terms of plugins, the only external 3rd party plugin I use is Unlimited.x64 at the end of the audio chain.

The full audio chain is :
Output format/
- Output encoding : None
- Sample Rate : (All at 48KHz, except 48Khz which shows "no change")
- Channels : 5.1 channels
- Mixing : No upmixing or downmixing
- Options : None

Adaptive Volume/
- Peak Level Normalize
- Options: Process Independently of Internal Volume

Effects/
- Environment : Jazz Club (2)
- Virtual Subwoofer : None
- Surround Field : Subtle Enhancement

Unlimited.x64
- Threshold : -3.0db
- Out : -0.11db
- Weight :  (all 0db)
- Character : 0.5
- Response : 0.5
 
I have heard the pause happen regardless of the number of channels being played (from stereo up to 6 channel 5.1 audio).

Library content is a mixture of flac and m4a. I haven't noticed any pattern in pauses when playing one or the other.

I see a LOT of great ideas on this thread, but very little in terms of productive debugging via logging with the JRiver team. I'm open to running a debug version of the software with any extra logging necessary in order to help the JRiver team get to the bottom of this.

FYI My hardware for the audio pipeline is PCM output via HDMI using my nVidia RTX3080 GPU, connected to my external amplifier. I'm using "Default Audio Device [WASAPI]" to get best audio.

Look forward to working with JRiver to resolve this problem once and for all.

Thanks!

[JimH]

During these pauses, I have noticed that WMIPRVSE.exe occupies high CPU usage, and playback resumes when this CPU usage clears after a few seconds.

Google WMIPRVSE.exe to read about it.  It's apparently Microsoft's.  I'm guessing it's running Windows Defender or something similar.

See if you can learn more by reading on the Internet.  I don't think it's a JRiver problem.

[MarcVRML]

Thanks Jim,

Windows Defender isn't running on my system - I use Malwarebytes Premium, and this registers with Windows Security and inherits what Defender would normally do. I've also set up exceptions within Malwarebytes to exempt my music drive from being scanned or monitored, and to exclude jriver's program folder from all detections, essentially meaning JRiver has unfettered access.

Having looked into WMIPRVSE, it appears to be related to the windows system monitoring and error reporting service. Does JRiver access the WMI API's internally at any point?

[MarcVRML]

Another observation about this issue which may make more sense to someone on JRiver's tech team ...

When the pause happens, it's always in the last few seconds of the track. However, I've noticed that after these pauses occur, when they resume the change of track information on the mini player is ahead of the audio playback. It's as if the player has switched to the next song at the right time, but because of the lag, I'm still hearing the tail end of the previous song.

My immediate thought is buffering, OR that the track duration is being misreported to the player.

[MarcVRML]

OK, some more info on this if it helps ... setting "Switch Tracks" to "Gapless" appears to work around the problem (although of course you lose the nice fade effect between tracks but that's a small price to pay I think).

If anyone else is seeing the problem of a 4-6 second pause in playback toward the end of their tracks when playing a shuffled playlist, please drop a note in reply. Thanks!

[Matt]

Jim sent me a library backup that lagged on track change.  It looked like it was the resampler in his case.  When I switched to SoX the problem went away for me.

[MarcVRML]

Thanks Matt - I haven't tried switching to SOX but will do so. In the interim, I can report that for the benefit of JRiver's developers, having run jriver extensively since my last post where track-blending was set to "gapless", I haven't had a single incident of pausing on playback.

[MarcVRML]

OK, after running JRiver since my last post using gapless transitions between songs, I've had zero problems.

However, I just accepted the auto update to version 28.0.105, and since that update went through I've had 2 incidents of pausing within a few seconds from track end despite gapless being the transition choice.

It might be coincidental of course, but I mention it in case the nature of the changes suggest where the root cause of this problem actually sits.