Print

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

[avid]

It doesn't always do this, but often from "cold" it can take almost 20 seconds to start playing a requested album. I think this is only on Linux, as I would have noticed over the previous 20 years using Windows! 

I attach a log of the first 20+ seconds - what on earth is it doing all that time??

[bob]

Spinning up a drive?
Or perhaps looking up lyrics? (turn that off in options if it's on to check)

[avid]

Spinning up a drive?

I don't think so. The entire library content is on SSD. And often it responds instantly. But there enough very long delays to bother me

I have just tried another album, and this time to took about 67 seconds to start playing!! If you look at this newer log and start around line 20229 of Previous Log.txt:

Code: [Select]

0131820: 139730553587648: Playback: CPlayerZone::Play: Processing play for '/ssd/Music/Alan Price/England My England/England My England.wma'There is then about 67 seconds of what looks like housekeeping, all of which occurred before I heard anything!

[bob]

Lots of variables.
Try a file format other than wma.
In options turn off filesystem support for import.
report back.

[avid]

Will do. It may take me a while, as most of the time MC responds instantly when playing albums.

I shall also experiment also with WMA albums. If they (sometimes) start fast, then that codec isn't the issue. Back in 2003, when I ripped my content, WMA was almost the height of quality! And nowadays, my aging ears have moved so far away from audiophile standards, that a ton of ripped WMA is no longer a problem for my listening.

[avid]

So far, so good ...

I disabled the option "Run auto-import in background", and am using MCC_IMPORT_AUTO_RUN_NOW only when my software needs it (often at 03:00 a.m.) . And so far I have not had long delays.

I shall leave the MC logging enabled for now, and I have added some of my own logging that would highlight any occurrences.

I will report back in a week or so if the problem has appeared to be gone.

[bob]

Thanks for the report.
The import thread runs at the lowest priority and the playback runs at the highest priority so I'm not sure why you have the issue but your solution is perfectly acceptable.

[avid]

Thanks Bob. I assumed that the threading works as you describe, and I have never noticed this issue on Windows for 10+years.

However, there were a couple of things in the log (the "Previous Log.txt") that looked odd to me.

One is "Found changes in FILE-BEING-PLAYED".  This seems to trigger some sort of reloading (a complete re-import?). But nothing should have changed that underlying file. And it was picked at random to be played.

And the second is the huge number of synchronous entries "General: RunProgram: Running blocking command via popen: stat -fc %T '/ssd/Music/FOLDERNAME/'". There are tens of thousands of these, and even at just a few ms for each call, they soon add up! And would sub-processes inherit the import thread's low priority? Just asking!

So these pointers may be indicative of an underlying cause - over to you!

But I am no longer waiting for a fix, as my work-around seems to be fine.

[bob]

Thanks Bob. I assumed that the threading works as you describe, and I have never noticed this issue on Windows for 10+years.

However, there were a couple of things in the log (the "Previous Log.txt") that looked odd to me.

One is "Found changes in FILE-BEING-PLAYED".  This seems to trigger some sort of reloading (a complete re-import?). But nothing should have changed that underlying file. And it was picked at random to be played.

And the second is the huge number of synchronous entries "General: RunProgram: Running blocking command via popen: stat -fc %T '/ssd/Music/FOLDERNAME/'". There are tens of thousands of these, and even at just a few ms for each call, they soon add up! And would sub-processes inherit the import thread's low priority? Just asking!

So these pointers may be indicative of an underlying cause - over to you!

But I am no longer waiting for a fix, as my work-around seems to be fine.

A bit spammy but
General: RunProgram: Running blocking command via popen stat -fc %T '/ssd/Music/FOLDERNAME/'"
Just means it's scanning media files for changes. That happens upon filesystem changes if that's enabled otherwise once every 2 hours on a timer.
I should probably remove that to reduce the logging spam but it also makes sense to turn off logging if you aren't meaning to generate on to send.

[avid]

There's still an issue here that feels like a thread priority one. I have just started playing an album and it took 20-22 seconds to start making a noise. And my 2 second poll of Playback/Info also showed no activity in that time.

I attach the tail end of the log. The file is "Sand In Your Shoes.mp3" starting at line 58 of the log.

There should be no auto-import happening, and I can't see any evidence of that.

[bob]

You've got some odd things going on with your network. For example:

5071325: 140392322287168: Sharing Plugins: CHTTPListenerWorker::HandleConnection: Finish (30878 ms)
5071325: 140391550547520: Sharing Plugins: CHTTPListenerWorker::HandleConnection: Finish (30146 ms)
Those are 2 different threads with 30 second delays

You are playing local material on a local output device right?
Try disabling media network and see what happens.

Also if you want to see thread priorities during playback you can do this:
ps -T -eo pid,tid,class,rtprio,ni,pri,comm | grep MediaCenter
From a terminal.

[avid]

Thanks.

I didn't spot those long (30+s) delays. But they may not be relevant because they occur after the music starts playing - and when it eventually starts, it always plays fine.

I did notice an awful lot of SSDP traffic in the log, But while there are multiple MC servers on the net, each has its own library, with local content and played though the local audio device. DLNA is enabled but not used. And the AVR has (unused) DLNA render capability too. I could perhaps turn off all three DLNA roles in MC.

Unfortunately it would be very difficult to disable the media network altogether. A single switch seems to enable everything, and I need MCWS for its control access. That MC can't really be used with the desktop UI only. And as the pauses only seem to happen every few albums, I need to track the occurrences in a normal working situation. Attached are my media network settings.

Annoyingly, this problem only occurs on the "live" domestic media machine (recently moved from Windows to Linux). It didn't happen on Windows, and doesn't on my main desktop dev/test/everything machine (also Windows). I'll spin up a Linux test machine by my desk and try experimenting with that - I can disable the media network on that one.

This may take some time!!

[avid]

I have now added code to my live software which:

• Notes the time at which I request to play an album
• On my regular 2 second poll, if it has not started playing within 2 seconds, I log the MC threads using the options you suggest
• Once it does start playing (which it always will eventually), if it has taken more than 10 seconds I attempt to preserve a copy of the MC Log.txt

This allows me to have the evidence of occurrences of the problem when I am not there or can't immediately deal with it.

It happened yesterday afternoon, and here are the logs from that.

Maybe we will eventually detect what activity in the log is significant

[avid]

And it has happened again this morning - logs attached.

I see that I have to be careful when copying the Log.txt as there seems to be a large unsaved in-core buffer. I am now allowing 10 seconds for the log to flush to the file. I will have to see if that is long enough. Is there any MCWS way to cause the logs to flush?

Let me know if there is additional logging or other info you want me to collect.

[avid]

And the next album did it as well - the issue is more frequent than I realised. And waiting 10 seconds was not enough for the MC log to flush to disk. I shall try 30 seconds.

Further logs attached. I shall stop sending logs now unless you ask for more info.

[Scobie]

The first time CPlayerZoneDisplayInfoUpdateThread is mentioned in each of the logs it takes a significant amount of time; 30-50 seconds.

After that it is pretty quick.

[bob]

The first time CPlayerZoneDisplayInfoUpdateThread is mentioned in each of the logs it takes a significant amount of time; 30-50 seconds.

After that it is pretty quick.

It takes 30-50 seconds to start? All that SHOULD be doing is updating the play progress for the zones. Perhaps there is a dead DLNA rendering device?

[avid]

It takes 30-50 seconds to start? All that SHOULD be doing is updating the play progress for the zones. Perhaps there is a dead DLNA rendering device?

It either starts playing instantly, as it always did (80% prob), or else there is a 15-30 second delay (20% prob). The only time I got a delay much larger than that was when I had background import enabled, though I would have hoped that would not impact on playing response either. Once it starts playing there are never any further pauses.

And for the last two or three logs posted I had switched off all three DLNA roles, as I do not currently use DLNA.

For all of yesterday, after the logs posted, there were never any further delays. And first thing this morning it also played fine. So, as an experiment, I rebooted the machine (at 07:33). And playing an album took 60 seconds to start. I attach Log.txt and also my software's log. And in that time, MCWS did not respond to Playback/Info. Search the logs for "Jolly Broom Man".

[bob]

MC doesn't start web services and DLNA immediately upon start, they are started with about a 30 second delay. That's why if you have DLNA enabled you don't see the tree fill in with renderers right away.

[avid]

MC doesn't start web services and DLNA immediately upon start, they are started with about a 30 second delay. That's why if you have DLNA enabled you don't see the tree fill in with renderers right away.

I turned off DLNA as I thought I wasn't using it. But I have just had to re-enable the DLNA Controller role, as that is necessary for TV streaming to work. But I was very impressed by the TV setup options UI that made it very clear what the issue was and how to address it!

However the delays happened both with and without the DLNA option.

[avid]

I noted in the changes for 31.0.57:

Fixed: Some thread sanitizer issues and locking of the PlayerCore for zone counts

Is that relevant here?

[bob]

I noted in the changes for 31.0.57:
Is that relevant here?

I don't think so but it's not certain. It's very low level.