Page 1 of 2

0.7.3 OS X 100% CPU Core Used

Posted: September 10th, 2012, 11:40 pm
by fanclerks
Recently I started noticing that SAB is utilizing a full CPU core on my Mac mini. The strange thing is it doesn't appear to be doing anything. There's nothing in the queue and it's not processing anything. I have no idea what is causing this to happen. I can restart SAB and it goes away for a while and then starts up again for no reason. I can tell when it's happening because I hear my fans go nuts. Anybody else seeing this and know what is causing it?

Re: 0.7.3 OS X 100% CPU Core Used

Posted: September 10th, 2012, 11:41 pm
by shypike
Which OSX are you using?

Re: 0.7.3 OS X 100% CPU Core Used

Posted: September 10th, 2012, 11:43 pm
by fanclerks
Sorry, I knew I should have been more clear. I'm running 10.8.1 with all updates installed. Let me know if you need php versions or anything.

Re: 0.7.3 OS X 100% CPU Core Used

Posted: September 10th, 2012, 11:47 pm
by shypike
Does going back to an older release solve things?
Do you have a lot of browser windows pointing at SABnzbd?
By the end of the week we'll release a specific Mountain Lion build.
Although I cannot reproduce your issue on my miniMac running ML.

Re: 0.7.3 OS X 100% CPU Core Used

Posted: September 10th, 2012, 11:50 pm
by fanclerks
I haven't tried reverting to an older version. I try to keep up to date with the latest and greatest. I've been running 0.7.3 since it got released I think and this just started recently. I rarely have any browser windows open to SAB. Only when I'm checking on something. It really seems like something recent happened. The logs don't show anything that I can tell though.

Re: 0.7.3 OS X 100% CPU Core Used

Posted: September 11th, 2012, 1:25 am
by shypike
Do you use a third-party tool to access SABnzbd, like a browser plugin (e.g. nzbStatus for Firefox)?

Re: 0.7.3 OS X 100% CPU Core Used

Posted: September 11th, 2012, 10:38 am
by fanclerks
I have iOS Apps that I use to access it sometimes, but haven't used in a while. Typically go through the web GUI.

Re: 0.7.3 OS X 100% CPU Core Used

Posted: September 12th, 2012, 1:01 pm
by shypike
Maybe you should join this thread: https://forums.sabnzbd.org/viewtopic.ph ... 38&p=70745
The problems could be related.

Re: 0.7.3 OS X 100% CPU Core Used

Posted: September 15th, 2012, 6:34 pm
by fanclerks
So I enabled the +debug for logging and waited for it to start pushing 100% on a core again. Here is what I saw:

2012-09-15 17:46:29,050::INFO::[postproc:627] Queue has finished, launching: None (None)
2012-09-15 17:46:30,983::DEBUG::[interface:400] API-call from 192.168.100.34 {'output': 'json', 'apikey': '624e43cdf0c763f87c29cc2a5bd1c389', 'mode': 'queue'}
2012-09-15 17:46:30,987::DEBUG::[interface:400] API-call from 192.168.100.34 {'output': 'json', 'apikey': '624e43cdf0c763f87c29cc2a5bd1c389', 'mode': 'history'}
2012-09-15 17:46:37,688::DEBUG::[interface:400] API-call from 192.168.100.34 {'output': 'json', 'apikey': '624e43cdf0c763f87c29cc2a5bd1c389', 'mode': 'queue'}
2012-09-15 17:46:37,692::DEBUG::[interface:400] API-call from 192.168.100.34 {'output': 'json', 'apikey': '624e43cdf0c763f87c29cc2a5bd1c389', 'mode': 'history'}

...

2012-09-15 17:50:18,008::DEBUG::[osxmenu:810] Launching caffeinate
2012-09-15 17:50:22,752::DEBUG::[interface:400] API-call from 192.168.100.34 {'output': 'json', 'apikey': '624e43cdf0c763f87c29cc2a5bd1c389', 'mode': 'queue'}
2012-09-15 17:50:22,756::DEBUG::[interface:400] API-call from 192.168.100.34 {'output': 'json', 'apikey': '624e43cdf0c763f87c29cc2a5bd1c389', 'mode': 'history'}
2012-09-15 17:50:29,379::DEBUG::[interface:400] API-call from 192.168.100.34 {'output': 'json', 'apikey': '624e43cdf0c763f87c29cc2a5bd1c389', 'mode': 'queue'}
2012-09-15 17:50:29,383::DEBUG::[interface:400] API-call from 192.168.100.34 {'output': 'json', 'apikey': '624e43cdf0c763f87c29cc2a5bd1c389', 'mode': 'history'}
2012-09-15 17:50:36,120::DEBUG::[interface:400] API-call from 192.168.100.34 {'output': 'json', 'apikey': '624e43cdf0c763f87c29cc2a5bd1c389', 'mode': 'queue'}

The caffeinate bit sounds a bit odd, but maybe it's required for SAB? IANAP though. The other thing I noticed is that when it was downloading something earlier, I noticed the CPU core usage also seemed to be fluctuating between 60-100% then also. I restarted and it seemed to go back to normal very light usage.

Re: 0.7.3 OS X 100% CPU Core Used

Posted: September 16th, 2012, 1:45 am
by shypike
Cafeinate is launched every five minutes as long as SABnzbd is downloading or post processing.
As long as the API calls aren't multiple times per second for a prolonged time,
it cannot be the cause.
It looks like you're able to trigger a situation with an endless loop,
but there's not enough info to go on.
It's a long shot, but could you try running SABnzbd with the menu symbol disabled?
You can disable it in Config->Special. Restart required.

Re: 0.7.3 OS X 100% CPU Core Used

Posted: September 16th, 2012, 9:46 am
by fanclerks
I've gone ahead and did the menu icon suggestion. The loop that you're talking about sounds like exactly what I'm seeing in the logs. It's those API calls being made every few miliseconds and it was happening for at least 5 mins before I restarted SAB. I guess we'll see if the loop happens again or not.

Re: 0.7.3 OS X 100% CPU Core Used

Posted: September 16th, 2012, 9:58 am
by fanclerks
Well that didn't take long. It's not showing the symbol in the menubar, but it's still doing it, and it does seem to possibly be linked to that caffeinate bit?

2012-09-16 09:43:16,399::INFO::[osxmenu:802] Starting caffeinate task
2012-09-16 09:55:19,234::DEBUG::[interface:400] API-call from 192.168.100.34 {'output': 'json', 'apikey': '624e43cdf0c763f87c29cc2a5bd1c389', 'mode': 'queue'}
2012-09-16 09:55:19,239::DEBUG::[interface:400] API-call from 192.168.100.34 {'output': 'json', 'apikey': '624e43cdf0c763f87c29cc2a5bd1c389', 'mode': 'history'}
2012-09-16 09:55:26,265::DEBUG::[interface:400] API-call from 192.168.100.34 {'output': 'json', 'apikey': '624e43cdf0c763f87c29cc2a5bd1c389', 'mode': 'queue'}
2012-09-16 09:55:26,269::DEBUG::[interface:400] API-call from 192.168.100.34 {'output': 'json', 'apikey': '624e43cdf0c763f87c29cc2a5bd1c389', 'mode': 'history'}
2012-09-16 09:55:32,938::DEBUG::[interface:400] API-call from 192.168.100.34 {'output': 'json', 'apikey': '624e43cdf0c763f87c29cc2a5bd1c389', 'mode': 'queue'}
2012-09-16 09:55:32,942::DEBUG::[interface:400] API-call from 192.168.100.34 {'output': 'json', 'apikey': '624e43cdf0c763f87c29cc2a5bd1c389', 'mode': 'history'}
2012-09-16 09:55:40,181::DEBUG::[interface:400] API-call from 192.168.100.34 {'output': 'json', 'apikey': '624e43cdf0c763f87c29cc2a5bd1c389', 'mode': 'queue'}
2012-09-16 09:55:40,185::DEBUG::[interface:400] API-call from 192.168.100.34 {'output': 'json', 'apikey': '624e43cdf0c763f87c29cc2a5bd1c389', 'mode': 'history'}
2012-09-16 09:55:48,359::DEBUG::[interface:400] API-call from 192.168.100.34 {'output': 'json', 'apikey': '624e43cdf0c763f87c29cc2a5bd1c389', 'mode': 'queue'}
2012-09-16 09:55:48,365::DEBUG::[interface:400] API-call from 192.168.100.34 {'output': 'json', 'apikey': '624e43cdf0c763f87c29cc2a5bd1c389', 'mode': 'history'}
2012-09-16 09:55:55,875::DEBUG::[interface:400] API-call from 192.168.100.34 {'output': 'json', 'apikey': '624e43cdf0c763f87c29cc2a5bd1c389', 'mode': 'queue'}
2012-09-16 09:55:55,881::DEBUG::[interface:400] API-call from 192.168.100.34 {'output': 'json', 'apikey': '624e43cdf0c763f87c29cc2a5bd1c389', 'mode': 'history'}
2012-09-16 09:56:04,888::DEBUG::[interface:400] API-call from 192.168.100.34 {'output': 'json', 'apikey': '624e43cdf0c763f87c29cc2a5bd1c389', 'mode': 'queue'}
2012-09-16 09:56:04,893::DEBUG::[interface:400] API-call from 192.168.100.34 {'output': 'json', 'apikey': '624e43cdf0c763f87c29cc2a5bd1c389', 'mode': 'history'}
2012-09-16 09:56:12,907::DEBUG::[interface:400] API-call from 192.168.100.34 {'output': 'json', 'apikey': '624e43cdf0c763f87c29cc2a5bd1c389', 'mode': 'queue'}
2012-09-16 09:56:12,911::DEBUG::[interface:400] API-call from 192.168.100.34 {'output': 'json', 'apikey': '624e43cdf0c763f87c29cc2a5bd1c389', 'mode': 'history'}
2012-09-16 09:56:21,016::DEBUG::[interface:400] API-call from 192.168.100.34 {'output': 'json', 'apikey': '624e43cdf0c763f87c29cc2a5bd1c389', 'mode': 'queue'}
2012-09-16 09:56:21,021::DEBUG::[interface:400] API-call from 192.168.100.34 {'output': 'json', 'apikey': '624e43cdf0c763f87c29cc2a5bd1c389', 'mode': 'history'}

Re: 0.7.3 OS X 100% CPU Core Used

Posted: September 16th, 2012, 10:18 am
by shypike
These API calls come from outside of SABnzbd.
SABnzbd's own web-skin does make API-calls, but they are not logged in this way.
But the log shown is quite reasonable.
Every 6 seconds two adjacent calls are made; this is not a problem.

A few more questions.
Which skin do you use (probably the default Plush)?
What is the refresh rare of the queue/history (shown in the Options popup)?
Does the CPU load go down when you close all browser windows and tabs connecting to SABnzbd?
Which utility do you use? The API calls are generated by an external utility.

It's very unlikely that "caffeinate" has anything to do with this.
You can test by renaming this utility temporarily (doing that while SABnzbd is not running).
It's here: /usr/bin/caffeinate

Re: 0.7.3 OS X 100% CPU Core Used

Posted: September 16th, 2012, 12:11 pm
by fanclerks
Oh wait a minute... so if it's external calls, I bet I know what it is. I bet it's Maraschino doing it.

Re: 0.7.3 OS X 100% CPU Core Used

Posted: September 16th, 2012, 12:18 pm
by fanclerks
Actually, scratch that. It still seems to be doing it. I'll have to mess around and see if I can figure out what is making those calls.