0.7.3 OS X 100% CPU Core Used

[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?

[shypike]

Which OSX are you using?

[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.

[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.

[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.

[shypike]

Do you use a third-party tool to access SABnzbd, like a browser plugin (e.g. nzbStatus for Firefox)?

[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.

[shypike]

Maybe you should join this thread: https://forums.sabnzbd.org/viewtopic.ph ... 38&p=70745
The problems could be related.

[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.

[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.

[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.

[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'}

[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

[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.

[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.