INTERACT FORUM

Please login or register.

Login with username, password and session length
Advanced search  
Pages: [1]   Go Down

Author Topic: CPU Usage  (Read 2150 times)

mattkhan

  • MC Beta Team
  • Citizen of the Universe
  • *****
  • Posts: 4226
CPU Usage
« on: October 01, 2014, 06:17:22 pm »

I had intermittent audio drop outs earlier tonight while playing a mix of vanilla stereo/multichannel FLAC tracks. This usually results in CPU load of maybe ~5% (i.e. trivial) but when I looked at the box tonight it was, relatively speaking, caning it quite hard (see attachment). The network load makes me think that it must have been doing some sort of import/analysis (of what, I do not know) but that's just speculation.

I then went to ask jriver to dump the logs and it promptly crashed on me (CPU problem solved!). I restarted and it seems, currently, happy again.

I realise this is a thoroughly non specific post but that's basically my point, how exactly am I meant to get visibility into what MC is doing? The logs have are unhelpful as they just seem to provide basic info logging for normal day to day events while also having not immediately obvious timestamps

for example

0000047: 5764: General: JRWebApp::InitInstance: Success
0000047: 5764: General: JRWebApp::InitInstance: Finish (47 ms)
0000047: 5764: General: JRWebApp::Run: Start
0000047: 5764: General: JRWebApp::Run: Running message loop
273348438: 3156: General: CViewHeaderWnd::Initialize: Start
273348453: 3156: General: CViewHeaderWnd::Initialize: Finish (15 ms)
273348453: 3156: General: CMCViewContainerWnd::Create: Finish (125 ms)

I'm guessing the 1st one is ms since startup (an always annoying format for initial debugging) but no idea what the 2nd one is.

Ultimately my question is what's the best way to see what jriver is doing so that you can do something about anomalous behaviour while it is happening? (and without resorting to kill/restart cycle)

Logged

JimH

  • Administrator
  • Citizen of the Universe
  • *****
  • Posts: 72438
  • Where did I put my teeth?
Re: CPU Usage
« Reply #1 on: October 01, 2014, 06:25:35 pm »

What build are you using?  20.0.20 is at the top of the MC20 board.
Logged

glynor

  • MC Beta Team
  • Citizen of the Universe
  • *****
  • Posts: 19608
Re: CPU Usage
« Reply #2 on: October 01, 2014, 06:40:24 pm »

I'm guessing the 1st one is ms since startup (an always annoying format for initial debugging) but no idea what the 2nd one is.

The first is ms since launched.

The second parameter is the thread ID.  So, scanning through the log you can see that any item from thread 5764 is on the startup thread (which is also the thread used for the UI, generally).  All others are child worker threads.  Tip: If you use Notepad++ to view it, and you really should be, then you can just select this number, and it'll highlight all the matching entries.

Next is the logging category.  In the old days you could enable logging of just certain categories, though they're still useful to see generally what the message is about.  The next one I'm not sure about, but I think is the class name.

Then lastly the message, with the duration in parenthesis if applicable.
Logged
"Some cultures are defined by their relationship to cheese."

Visit me on the Interweb Thingie: http://glynor.com/

glynor

  • MC Beta Team
  • Citizen of the Universe
  • *****
  • Posts: 19608
Re: CPU Usage
« Reply #3 on: October 01, 2014, 06:47:29 pm »

PS. Using ms there is really the only thing that makes sense.  Computers do not operate at the scale of seconds.  A second is often an eternity for application code, and it is always an eternity for modern CPUs.

Using milliseconds is the only way to reveal latencies that measure well below a second, but which can be iterated over and over so substantially impact performance.

You could convert to human-readable times plus milliseconds, but that's just adding overhead to an inherently nerdy feature, and kind of obfuscates looking at individual lines (as it is, each line has a "number", almost always distinct except for very low-latency events).

What generally matters is not the specific time individual events occurred, but the difference between the lines.  In yours, something is obviously badly wrong if those two lines are side-by-side.  I don't need to do ms conversion math to figure that out.
Logged
"Some cultures are defined by their relationship to cheese."

Visit me on the Interweb Thingie: http://glynor.com/

glynor

  • MC Beta Team
  • Citizen of the Universe
  • *****
  • Posts: 19608
Re: CPU Usage
« Reply #4 on: October 01, 2014, 06:50:30 pm »

For the record, smells like Anti-Virus to me.
http://wiki.jriver.com/index.php/Troubleshooting_Guide
Logged
"Some cultures are defined by their relationship to cheese."

Visit me on the Interweb Thingie: http://glynor.com/

Hendrik

  • Administrator
  • Citizen of the Universe
  • *****
  • Posts: 10935
Re: CPU Usage
« Reply #5 on: October 02, 2014, 01:28:54 am »

Note that when something like JRWeb launches (like in your example log excerpt), it'll start its own time count since its own start, and not from the main MC start, which is why you can have tiny numbers for JRWeb things while being surrounded by huge numbers from the main MC process.
Logged
~ nevcairiel
~ Author of LAV Filters

mattkhan

  • MC Beta Team
  • Citizen of the Universe
  • *****
  • Posts: 4226
Re: CPU Usage
« Reply #6 on: October 02, 2014, 03:16:11 am »

What build are you using?  20.0.20 is at the top of the MC20 board.
the current stable version at the time of writing (which IIRC was 20.0.17)

PS. Using ms there is really the only thing that makes sense.  Computers do not operate at the scale of seconds.  A second is often an eternity for application code, and it is always an eternity for modern CPUs.
thanks for confirming the log format. FWIW I think it's a suboptimal pattern for a log file that is visible to a human, the need to convert means that you can't easily scan the log for a particular time period so you can correlate the log to an event in the real world. The precision is also a bit of an illusion as the initial line is not in the same format so you can't even calculate an accurate timestamp anyway.

Code: [Select]
0000000: 3156: General: Starting logging: Date: 28/09/2014 20:05
Something like this (produced when you pass -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps to a jvm) would be better

Code: [Select]
2014-10-02T08:46:37.548+0100: 2.822: [GC 20480K->8357K(75776K), 0.0182880 secs]
a minor change and not v important but it would improve the utility of those logs imv.

For the record, smells like Anti-Virus to me.
http://wiki.jriver.com/index.php/Troubleshooting_Guide
does AV activity produce high cpu usage in jriver or in the av app?
Logged

glynor

  • MC Beta Team
  • Citizen of the Universe
  • *****
  • Posts: 19608
Re: CPU Usage
« Reply #7 on: October 02, 2014, 09:08:06 am »

Note that when something like JRWeb launches (like in your example log excerpt), it'll start its own time count since its own start, and not from the main MC start, which is why you can have tiny numbers for JRWeb things while being surrounded by huge numbers from the main MC process.

Ah, yes.  I didn't notice that.  Should have looked more closely.

So, the 5764 thread is NOT the startup thread, but the thread for JRWeb.  Always hard to look at a tiny log snippet.
Logged
"Some cultures are defined by their relationship to cheese."

Visit me on the Interweb Thingie: http://glynor.com/

glynor

  • MC Beta Team
  • Citizen of the Universe
  • *****
  • Posts: 19608
Re: CPU Usage
« Reply #8 on: October 02, 2014, 09:12:35 am »

does AV activity produce high cpu usage in jriver or in the av app?

I've definitely had Windows Defender and Symantec Endpoint Protection cause high CPU usage in Media Center's processes.  It does not happen on all, or even most, of my machines.  But I've seen it (particularly on laptops).

I think it is because the AV program decides to interfere with MC's access to the Library files on disk, but it probably happens for a variety of reasons.  Excluding MC's processes has typically put a stop to it for me.
Logged
"Some cultures are defined by their relationship to cheese."

Visit me on the Interweb Thingie: http://glynor.com/

mattkhan

  • MC Beta Team
  • Citizen of the Universe
  • *****
  • Posts: 4226
Re: CPU Usage
« Reply #9 on: October 02, 2014, 09:44:48 am »

I've definitely had Windows Defender and Symantec Endpoint Protection cause high CPU usage in Media Center's processes.  It does not happen on all, or even most, of my machines.  But I've seen it (particularly on laptops).

I think it is because the AV program decides to interfere with MC's access to the Library files on disk, but it probably happens for a variety of reasons.  Excluding MC's processes has typically put a stop to it for me.
OK ta. I thought I'd excluded them but will double check that.
Logged
Pages: [1]   Go Up