Print

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

[mattkhan]

This was reported on the mac board -> http://yabb.jriver.com/interact/index.php/topic,107840.msg748344.html#msg748344

It definitely happens for me on Windows.

Situation is

MC server instance on Windows
start playback of an album using the MC client (or jremote, doesn't matter which)
playback proceeds through the entire album
last song starts
last song terminates abruptly 30s or so before the end

If I play that last song alone, it plays through to the end as expected

nothing stands out in the logs, I see the following around the time playback terminates

Code: [Select]

2367687: 324: Playback: CMJWaveFeeder::Thread: Finished feeder loop (bCancel: 0, bPlayed: 1)
2367687: 324: Playback: CMJWaveFeeder::Thread: Sending EOF
2367687: 324: Playback: CPlayerZone::JRPlaybackEngine_EndOfFile: Start
2367687: 324: Playback: CPlayerZone::PlayNextFile: bCanPlayNext=1, m_bPlaybackError=0
2367687: 324: Playback: CPlayerZone::JRPlaybackEngine_EndOfFile: Finish (0 ms)
2367687: 324: Playback: CMJWaveFeeder::Thread: Finish (296484 ms)
2367687: 5396: Playback: CPlayerZone::Next: Start
2367687: 5396: Playback: CPlayerZone::Next: Checking for invalid position
2367687: 5396: Playback: CPlayerZone::Next: Attempting next chapter
2367687: 5396: Playback: CPlayerZone::Next: Checking for next disabled
2367687: 5396: Playback: CPlayerZone::Next: Checking for display / internal mismatch
2367687: 5396: Playback: CPlayerZone::Next: Checking can play next state
2367687: 5396: Playback: CPlayerZone::Next: Next track not playable
2367687: 5396: Playback: CPlayerZone::Next: Finish (0 ms)
2371047: 5396: TV: CTVRecordingManager::Process: Start
2371047: 5396: TV: CTVRecordingDatabase::GetActions: returning 0 actions
2371047: 5396: TV: CTVRecordingManager::PerformBackgroundTasks: Silent Days ago 0.0947337962934398, dialog days ago 0
2371047: 5396: TV: CTVRecordingManager::PerformBackgroundTasks: checking program cleanup timer.  Last cleanup 4.2777736656537195 hours ago
2371047: 5396: TV: CTVRecordingManager::Process: Finish (0 ms)
2373875: 5396: Playback: CPlayerZone::Stop: Start
2373875: 5396: Playback: CPlayerZoneDisplayInfoUpdateThread::Destructor: Start
2373875: 4104: Playback: CPlayerZoneDisplayInfoUpdateThread::Thread: Finish (302672 ms)
2373890: 5396: Playback: CPlayerZoneDisplayInfoUpdateThread::Destructor: Finish (15 ms)
2373890: 5396: Playback: CPlayerZone::Stop: Checking for not loaded playback engine
2373890: 5396: Playback: CPlayerZone::Stop: Firing stop to playback engine
2373890: 5396: Playback: CMJPlayerCore::Stop: Start
2373890: 5396: Playback: CMJPlayerCore::Stop: Fading out
2375390: 5396: Playback: CMJPlayerCore::Stop: Closing feeder thread
2375390: 5396: Playback: CMJWaveFeeder::~CMJWaveFeeder: Start
2375390: 5396: Playback: CMJWaveFeeder::~CMJWaveFeeder: Cancel
2375390: 5396: Playback: CMJWaveFeeder::~CMJWaveFeeder: Stopping thread
2375390: 5396: Playback: CMJWaveFeeder::~CMJWaveFeeder: Deleting input source
2375390: 5396: General: CFlacDecoder::~CFlacDecoder: Start
2375390: 5396: General: CFlacDecoder::~CFlacDecoder: Finish (0 ms)
2375390: 5396: Playback: CMJWaveFeeder::~CMJWaveFeeder: Finish (0 ms)
2375390: 5396: Playback: CMJPlayerCore::Stop: Closing main output bin
2375390: 5396: Playback: CWaveOutBin::DestroyBin: Start
2375390: 5396: Playback: CWaveOutBin::DestroyBin: Canceling play thread
2375390: 5396: Playback: CWaveOutBin::DestroyBin: Deleting play thread
2375390: 5396: Playback: CWaveOutBinPlayThread::~CWaveOutBinPlayThread: Start
2375406: 2784: Playback: CWaveOutBinPlayThread::Thread: Finish (2369172 ms)
2375406: 5396: Playback: CWaveOutBinPlayThread::~CWaveOutBinPlayThread: Finish (16 ms)
2375406: 5396: Playback: CWaveOutBin::DestroyBin: Deleting objects
2375422: 5396: Playback: CWaveOutBin::DestroyBin: Finish (32 ms)
2375422: 5396: Playback: CMJPlayerCore::Stop: Closing rights object
2375422: 5396: Playback: CMJPlayerCore::Stop: Deleting output plugin
2375422: 6436: Playback: CASIOPlugin::~CASIOPlugin: Start
2375453: 6436: Playback: CASIOPlugin::~CASIOPlugin: Stopping ASIO
2375468: 6436: Playback: CASIOPlugin::~CASIOPlugin: Disposing buffers
2375468: 6436: Playback: CASIOPlugin::~CASIOPlugin: Exiting ASIO
2375468: 6436: Playback: CASIOPlugin::~CASIOPlugin: Deleting ASIO wrapper
2375468: 6436: Playback: CASIOPlugin::~CASIOPlugin: Updating plugins
2375468: 6436: Playback: CASIOPlugin::~CASIOPlugin: Deleting buffers
2375484: 6436: Playback: CASIOPlugin::~CASIOPlugin: Finish (62 ms)
2375484: 5396: Playback: CMJPlayerCore::Stop: Updating play state
2375484: 5396: Playback: CMJPlayerCore::Stop: Finish (1594 ms)
2375500: 5396: Playback: CPlayerZone::Stop: Processing internal previous / next


[mattkhan]

I tried this on a Linux client of the same server and it worked OK. Note this behaviour is not specific to one album, it occurs on every album I have tried so far.

[mattkhan]

tried it on another windows client and no issue there either

I went back to the server and played another album & watched it more closely. I can now see what is going on though it seems a very strange. Basically I can see that by the time it gets to the last track, the playback status in the top panel of the mc client) is about 30s ahead of what is actually playing, i.e. by the time I actually hear the last track, jriver thinks it is 30s into that track. The track then continues playing normally and when it gets about 10s from the end, the logs show that it triggers the EOF

Code: [Select]

131432609: 8104: Playback: CMJWaveFeeder::Thread: Finished feeder loop (bCancel: 0, bPlayed: 1)
131432609: 8104: Playback: CMJWaveFeeder::Thread: Sending EOF
131432609: 8104: Playback: CPlayerZone::JRPlaybackEngine_EndOfFile: Start
131432609: 8104: Playback: CPlayerZone::PlayNextFile: bCanPlayNext=1, m_bPlaybackError=0
131432609: 8104: Playback: CPlayerZone::JRPlaybackEngine_EndOfFile: Finish (0 ms)
131432609: 8104: Playback: CMJWaveFeeder::Thread: Finish (297203 ms)
131432609: 5396: Playback: CPlayerZone::Next: Start
131432609: 5396: Playback: CPlayerZone::Next: Checking for invalid position
131432609: 5396: Playback: CPlayerZone::Next: Attempting next chapter
131432609: 5396: Playback: CPlayerZone::Next: Checking for next disabled
131432609: 5396: Playback: CPlayerZone::Next: Checking for display / internal mismatch
131432609: 5396: Playback: CPlayerZone::Next: Checking can play next state
131432609: 5396: Playback: CPlayerZone::Next: Next track not playable
131432625: 5396: Playback: CPlayerZone::Next: Finish (16 ms)
131438093: 5396: Playback: CPlayerZone::Stop: Start

once this completes then jriver terminates playback, the problem being that it hasn't actually completed playing back the track at all, instead it still has about 30s to go.

This behaviour seems quite bizarre but it's completely repeatable.

Any ideas? My thought is to verify whether it's gradually slipping behind or suddenly jumps (I would think the former) and then I guess it's trial and error turning features on and off (e.g. convolution) to see if that changes the behaviour. Extremely slow going to test though (and I've been using the same album each time so I'm slowly beginning to hate that album!)

[Hendrik]

Are you using SoX resampling and have resampling active during playback?

[mattkhan]

Are you using SoX resampling and have resampling active during playback?

yes I am

I'm just watching it track by track now and it actually seems to cut the end of each track and flips to the next track more eagerly than it seems it should (e.g. the track I was just on was 3:53 long but it cut over to the next at 3:50). This must be the effect of the not playing leading/trailing silence option? I don't recall setting this so I assume this is the default setting?

as an aside, I changed to lock it to 48kHz as I have found having a multi client capable device (Motu 1248) and multiple ASIO clients active can lead to undesiable behaviour (those clients fight over the sample rate).

[Hendrik]

Try without SoX (or without resampling), and see if it goes away. There is a known issue with SoX which we unfortunately can't reliabl reproduce yet.

[mattkhan]

Try without SoX (or without resampling), and see if it goes away. There is a known issue with SoX which we unfortunately can't reliabl reproduce yet.

resampling without SoX seems to correct the issue, I'll repeat with SoX again tomorrow just to be 100% sure.

Is this the known issue with SoX or is there something else?

[mattkhan]

i dont know if somebody already reported this. 
today i started to try the new sox upsampling. im upsampling from 44.1 to 48. and after a bunch of songs i noticed that the position bar at the top of standard view was already (or stil) halfway the song altough a new song was starting to play. so i tested a bit.
with sox on, after 20.12 minutes of music, the position bar was already 15 seconds in the next song still playing the previous song, before the next song started.
this does not happen when disabling sox for upsampling.

for when its important.
buffer is 6 seconds
not playing from memory
the files are played local from hd
latest build 22.0.18
playback to asio
did i forget something

 
gab

looks like this one is the same issue

[Hendrik]

Sounds like the same issue. The rather odd part about it however is that its so inconsistent. It happens for some people on some machines only, like its related to the hardware or audio drivers, but why would those care what we resample with. Its a very odd mystery.

Alas, SoX is marked as experimental. 

[mattkhan]

I'm using a Motu 1248 via asio atm. I can try it on this machine with another audio device (the HDMI out from the video card) if you like. I could also try using the motu wdm device (though I have no idea that's implemented as a wrapper on the same underlying driver).

[Hendrik]

I made some changes for the next build which should hopefully help with this issue. If it doesn't, we can try to figure out more related factors.

[AndrewFG]

I made some changes for the next build which should hopefully help with this issue. If it doesn't, we can try to figure out more related factors.

Lets keep our fingers crossed for this.

But just in case, (I hope this is not too presumptuous), I had a look at the sample code on the Sox resampler site on SourceForge, and highlighted the four tests that I would be investigating as potential reasons for a premature termination of the resampling "while" loop -- namely a) you ran out of input, b) the conversion failed, c) no output was written and/or d) you need to supply some more input bytes. (see attached screen shot of the sample code..)

[Hendrik]

Resampling into files and for real-time playback are two entirely different pairs of shoes. Do not worry, we know how to read examples and API documentation.

[MikeO]

Don't know if it's related but I seem to be skipping track 2 plays track 1 then track3

Always this pattern after that all is ok

Mike

[AndrewFG]

Do not worry, we know how to read examples and API documentation.

I know that Hendrik. I have the greatest respect for your achievements. But I am myself experienced enough to know that, sometimes, it just needs some dork to state the obvious..