Bug 2202 - 100% CPU usage every minute with musicmagic
: 100% CPU usage every minute with musicmagic
Status: RESOLVED FIXED
Product: Logitech Media Server
Classification: Unclassified
Component: MusicIP
: 6.2.0
: PC Linux (other)
: P2 normal (vote)
: ---
Assigned To: Dan Sully
:
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2005-09-26 14:23 UTC by John Gorst
Modified: 2011-03-16 04:19 UTC (History)
2 users (show)

See Also:
Category: ---


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description John Gorst 2005-09-26 14:23:35 UTC
>
> Using latest nightly 23/9, mandrake linux, pentium 3 1ghz, musicmagic, SB1
>
> Around every one minute slimserver takes up 100% of my processor useage making
the server unuseable for interactive tasks for a few seconds. Music or scrolling
on my SB1 is not affected. This occurs again about a minute after CPU useage
returns to normal.
>
> Any idea what even can be occurring around about every minute?
>
> This occurs with or without the web interface open and with or without the SB1
playing or not (or even switched off).
>
> I cant think of anything special other than music magic.
>
> This problem seemed to start occurring in a nighlty around abotu 2 weeks ago.


Just disabled MusicMagic plugin and this behaviour is resolved.

The output of --d_musicmagic is included below.
Note the read of the ?musicmagic cache every one minute, presumeably to see if
the musicmagic database has been updated. Also the missing file.

Whilst sometimes it only takes a second to read this file, at other times it
takes upto 3 seconds. It actually makes the desktop unuseable for 4 seconds,
with a 4 second pause on the 'top' output.

I have the "musicmagic reload interval" set to 6000, so I dont understand why
this is being updated so often. Any ideas?

2005-09-26 21:33:40.3487 MusicMagic: Testing for API on localhost:10002
2005-09-26 21:33:40.8243 MusicMagic: Predixis MusicMagic Mixer. Version 1.1.6
(note same problemw ith old version of msuicmagic)

2005-09-26 21:33:40.8265 MusicMagic: get filters list
2005-09-26 21:33:42.1182 MusicMagic: get filters list
file error - plugins/MusicMagic/mixerlink.html: not found
file error - plugins/MusicMagic/mixerlink.html: not found
(snip)
file error - plugins/MusicMagic/mixerlink.html: not found
file error - plugins/MusicMagic/mixerlink.html: not found
file error - plugins/MusicMagic/mixerlink.html: not found
2005-09-26 21:34:41.5838 MusicMagic: read cacheid of 1126148026
2005-09-26 21:34:41.7699 MusicMagic: got status - idle
2005-09-26 21:35:44.6747 MusicMagic: read cacheid of 1126148026
2005-09-26 21:35:44.8549 MusicMagic: got status - idle
2005-09-26 21:36:45.1854 MusicMagic: read cacheid of 1126148026
2005-09-26 21:36:48.9182 MusicMagic: got status - idle
2005-09-26 21:37:51.8544 MusicMagic: read cacheid of 1126148026
2005-09-26 21:37:52.0355 MusicMagic: got status - idle
Comment 1 KDF 2005-09-26 14:38:04 UTC
There is no file being read.  There is only a once per minute call to the MMM
http api to get the cacheid. This call should be non-blocking and time out after
a max of 5 seconds.  the missing file is an odd one.  I have only see it when
MMM plugin has crashed due to a bad bit of code that I've tested.

Comment 2 KDF 2005-09-26 14:42:18 UTC
what skin are you using?
Comment 3 John Gorst 2005-09-26 14:48:12 UTC
Would it be possible to decrease the frequency of checking the cache ID? If I am
only rescanning the musicmagic database (if there is a change) every 6000
seconds, do I really need to check the cache ID every 60 seconds? Perhaps this
could be an option, or it could be set as the same value as checking for an
updated musicmagic database

Why would checking a cacheid via the HTTP API result in 100% CPU usage by
slimserver (not musicmagic)?

I am using default or ExBrowse3. However the same problem occurs when no web
interface is loaded up.
Comment 4 KDF 2005-09-26 15:35:00 UTC
er...do you still see "file error - plugins/MusicMagic/mixerlink.html: not
found" with no web interface loaded?
Comment 5 KDF 2005-09-26 23:23:09 UTC
the cacheid check could be done less often, but then the scan trigger would be
off by as much as that value.  The cacheid check is part of detecting whether or
not the library has changed.  If the check were to happen just seconds before an
interval of say 4 hours, then it would be another 4 hours. 

I still suspect that there is something else going on here becuase I run MMM and
slimserver on a Mandrake 10.1 install, Athlon 2k w/ 768M RAM.  The cpu usage at
the time of the cache check is only a very short spike of just over 30%.  Given
that what you are seeing is not at all like this, I expect that simply delaying
the cachid will not really solve the problem.  you will still be stuck
unresponsive for 4 seconds at every check.

Are you running both on the same system?
Comment 6 John Gorst 2005-09-27 10:49:53 UTC
My mistake. I dont get the file error when no web interface is loaded. However I
do get the pauses/high CPU usegae with or without the web interface loaded.

Running both on the same system.
My server is a lot less powered than yours, Pentium 3 1ghz - so the short spike
on your system could be a lot longer on mine!

Is there any way I can access teh MMM web API from another comptuer, and request
the cache ID. I will then be able to see if the system pauses for a while or
not. If it does it is a MMM problem (or my server is underpowered), if it doesnt
then it is a slimserver problem.  
Comment 7 KDF 2005-09-27 11:43:50 UTC
you can try adding this at line 1240 of Plugins/MusicMagic/Plugin.pm:
	$setupPrefs{'MMSHost'} = %{&setupCategory}->{'Prefs'}->{'MMSHost'};
then restart server.
This will add a pref in server settings->plugins to set the MMM host (can be IP
or named addy). slimserver should use this when it then tries to connect to mmm api.

It won't be an operational solution, but it could help to isolate the issues
Comment 8 John Gorst 2005-09-27 11:51:27 UTC
Just read the developement page for mmm.
Does acessing http://localhost:10002/api/cacheid do the same thing that
slimserver does when trying to find the cahce ID?

If so, doing that from firefox either on the server or on a different computer
does not cause cause a pause or a significant increase in CPU useage. So
therefor the problem must lie in the slimserver side?

What does slimserver do just before or after checking the cacheid? 
Comment 9 KDF 2005-09-27 11:56:17 UTC
this is exactly what the server does, then it issues:
http://$MMSHost:$MMSport/api/getStatus
then it reads a couple prefs and does some math.  NONE of these should ever be
intensive.  However, if the MMM API were to be slow to respond, that could be a
problem.  an HTTP api isn't the nicest thing to have to deal with. using
AsyncHTTP may help if it can be used here.
Comment 10 John Gorst 2005-09-27 13:22:46 UTC
Using firefox on the local or remote system MMM responds very quickly to either
the /api/cacheid or the /api/getstatus commands, virtually instantaneously.

What else specifically does the MMM plugin do every minute. I just have a
sneaking suspicion that slimserver has difficulty saving to my preference file
(had a problem a week or so ago, but deleting and reseting the preferences on
the slimserver.conf file cleared it up).
Comment 11 Dan Sully 2005-10-12 00:01:21 UTC
kdf - any thoughts here?
Comment 12 KDF 2005-10-12 00:24:50 UTC
already gave all the ideas I had on this.  I dont see the problem on my setup, so I guess john may be 
right that it is something else in combination. d_prefs, d_musicmagic...?
Comment 13 Blackketter Dean 2005-10-13 13:49:10 UTC
John: any news here?
Comment 14 John Gorst 2005-10-15 02:36:59 UTC
Sorry no, a bit of a mystery. I have disabled MMM for a while now as it was
messign up some of the realtime tasks running on my server.

As far as I can tell (accessing the MMM api via the web service) it is not
musicmagic that is hogging the cpu or being slow to respnd causing slimserver to
hog the cpu whist waiting.

It must be something that the MMM plugin for slimserver is doing (?unique to my
system) after accessing the MMM api every minute causing the cpu to rise.

Comment 15 Sue Chastain 2005-10-23 19:09:05 UTC
For the record, this is not just John. I was having the same problem (see 
http://forums.slimdevices.com/showthread.php?t=16811) until I changed the 
reload interval to 0.
Comment 16 Dan Sully 2005-10-23 19:58:32 UTC
Sue, John - what version of MMM are each of you running?

What does the output of --d_musicmagic say?

Thanks.
Comment 17 Sue Chastain 2005-10-23 20:31:00 UTC
Version 1.1.6. I reset the reload interval to 60 seconds with  --d_musicmagic 
enabled, then forced a change to the MMM database. Here's the log. 

2005-10-23 23:12:09.6724 MusicMagic: Testing for API on localhost:10002
2005-10-23 23:12:09.9429 MusicMagic: Predixis MusicMagic Mixer. Version 1.1.6

2005-10-23 23:12:09.9438 MusicMagic: get filters list
2005-10-23 23:12:10.0820 MusicMagic: found filters:
2005-10-23 23:12:10.0822 MusicMagic:	! No Junk
2005-10-23 23:12:10.0822 MusicMagic:	1 Month New
2005-10-23 23:12:10.0823 MusicMagic:	1980's
2005-10-23 23:12:10.0823 MusicMagic:	1990's
2005-10-23 23:12:10.0824 MusicMagic:	Added within 1 month
2005-10-23 23:12:10.0824 MusicMagic:	Added within 2 days
2005-10-23 23:12:10.0825 MusicMagic:	Analysis NOT Stored
2005-10-23 23:12:10.0825 MusicMagic:	Analysis Stored
2005-10-23 23:12:10.0826 MusicMagic:	Exclude Live Tracks
2005-10-23 23:12:10.0827 MusicMagic:	Favorite Genres
2005-10-23 23:12:10.0827 MusicMagic:	No Country
2005-10-23 23:12:10.0828 MusicMagic:	No Year
2005-10-23 23:12:10.0828 MusicMagic:	Not Analyzed
2005-10-23 23:12:10.0829 MusicMagic:	Not Enabled
2005-10-23 23:12:10.0829 MusicMagic:	Not Rated and Enabled
2005-10-23 23:12:10.0830 MusicMagic:	Rated
2005-10-23 23:12:10.0830 MusicMagic:	Rated 3 or higher
2005-10-23 23:12:10.0833 MusicMagic:	Remove these artists
2005-10-23 23:12:10.3624 MusicMagic: get filters list
2005-10-23 23:12:10.6310 MusicMagic: found filters:
2005-10-23 23:12:10.6313 MusicMagic:	! No Junk
2005-10-23 23:12:10.6314 MusicMagic:	1 Month New
2005-10-23 23:12:10.6315 MusicMagic:	1980's
2005-10-23 23:12:10.6316 MusicMagic:	1990's
2005-10-23 23:12:10.6317 MusicMagic:	Added within 1 month
2005-10-23 23:12:10.6318 MusicMagic:	Added within 2 days
2005-10-23 23:12:10.6320 MusicMagic:	Analysis NOT Stored
2005-10-23 23:12:10.6321 MusicMagic:	Analysis Stored
2005-10-23 23:12:10.6321 MusicMagic:	Exclude Live Tracks
2005-10-23 23:12:10.6322 MusicMagic:	Favorite Genres
2005-10-23 23:12:10.6324 MusicMagic:	No Country
2005-10-23 23:12:10.6325 MusicMagic:	No Year
2005-10-23 23:12:10.6326 MusicMagic:	Not Analyzed
2005-10-23 23:12:10.6327 MusicMagic:	Not Enabled
2005-10-23 23:12:10.6328 MusicMagic:	Not Rated and Enabled
2005-10-23 23:12:10.6329 MusicMagic:	Rated
2005-10-23 23:12:10.6330 MusicMagic:	Rated 3 or higher
2005-10-23 23:12:10.6331 MusicMagic:	Remove these artists
2005-10-23 23:13:10.0378 MusicMagic: read cacheid of 1130123578
2005-10-23 23:13:10.1162 MusicMagic: got status - analyzing
2005-10-23 23:13:10.1168 MusicMagic: music library has changed!
2005-10-23 23:13:10.1171 	MusicMagic Details: 
		Cacheid - 1130123578
		LastCacheid - 1129693602

		Reload Interval - 60
		Last Scan - 0
2005-10-23 23:13:10.1177 MusicMagic: using musicmagic: Predixis MusicMagic 
Mixer. Version 1.1.6

2005-10-23 23:13:10.1180 MusicMagic: start export
2005-10-23 23:13:10.1206 MusicMagic: export mode is: start
2005-10-23 23:13:10.2091 MusicMagic: Got 11003 song(s).
2005-10-23 23:13:10.2097 MusicMagic: export mode is: songs
2005-10-23 23:13:10.2981 MusicMagic: Exporting song 1: K:\MP3\Creedence 
Clearwater Revival\Assorted\CCR - Proud Mary.mp3
2005-10-23 23:13:10.3927 MusicMagic: export mode is: songs
2005-10-23 23:13:10.5422 MusicMagic: Exporting song 2: K:\MP3\Creedence 
Clearwater Revival\Assorted\CCR - Run Through The Jungle.mp3
2005-10-23 23:13:10.5862 MusicMagic: export mode is: songs
2005-10-23 23:13:10.6654 MusicMagic: Exporting song 3: K:\MP3\Creedence 
Clearwater Revival\Assorted\CCR - Someday Never Comes.mp3
2005-10-23 23:13:10.7024 MusicMagic: export mode is: songs
2005-10-23 23:13:10.7825 MusicMagic: Exporting song 4: K:\MP3\Creedence 
Clearwater Revival\Assorted\CCR - Susie Q (Part 2).mp3
2005-10-23 23:13:11.0120 MusicMagic: export mode is: songs
2005-10-23 23:13:11.0992 MusicMagic: Exporting song 5: K:\MP3\Creedence 
Clearwater Revival\Assorted\CCR - Susie Q.mp3
2005-10-23 23:13:11.1270 MusicMagic: export mode is: songs
2005-10-23 23:13:11.2145 MusicMagic: Exporting song 6: K:\MP3\Creedence 
Clearwater Revival\Assorted\CCR - Sweet Hitch-Hiker.mp3
2005-10-23 23:13:11.2591 MusicMagic: export mode is: songs
2005-10-23 23:13:11.3375 MusicMagic: Exporting song 7: K:\MP3\Creedence 
Clearwater Revival\Assorted\CCR - The Midnight Special.mp3
2005-10-23 23:13:11.6116 MusicMagic: export mode is: songs
2005-10-23 23:13:11.6874 MusicMagic: Exporting song 8: K:\MP3\Creedence 
Clearwater Revival\Assorted\CCR - Travelin' Band.mp3
2005-10-23 23:13:11.7264 MusicMagic: export mode is: songs
2005-10-23 23:13:11.8105 MusicMagic: Exporting song 9: K:\MP3\Creedence 
Clearwater Revival\Assorted\CCR - Up Around The Bend.mp3
2005-10-23 23:13:11.8560 MusicMagic: export mode is: songs
2005-10-23 23:13:11.9305 MusicMagic: Exporting song 10: K:\MP3\Creedence 
Clearwater Revival\Assorted\CCR - Walk On The Water.mp3
2005-10-23 23:13:12.1140 MusicMagic: export mode is: songs
2005-10-23 23:13:12.2161 MusicMagic: Exporting song 11: K:\MP3\Creedence 
Clearwater Revival\Assorted\CCR - Who'll Stop the Rain.mp3
2005-10-23 23:13:12.2522 MusicMagic: export mode is: songs
2005-10-23 23:13:12.3452 MusicMagic: Exporting song 12: K:\MP3\Crowded 
House\1986 - Crowded House\01 Mean To Me.mp3
2005-10-23 23:13:12.5822 MusicMagic: export mode is: songs
2005-10-23 23:13:12.6885 MusicMagic: Exporting song 13: K:\MP3\Crowded 
House\1986 - Crowded House\02 World Where You Live.mp3
.
.
.
.
this continues for every song in my library (I'm assuming… it's still going as 
I type this), with heavy slim.exe CPU usage the whole time. The CPU spike 
begins right about the time of the "2005-10-23 23:13:10.1180 MusicMagic: start 
export" line and slim.exe remains at 40-100% CPU usage through the process 
which continues for quite a long time… an hour or more. During this time my PC 
is nearly impossible to use.
Comment 18 Sue Chastain 2005-10-23 21:12:17 UTC
Ok, it continued like that for nearly an hour. Here's the last part of the log:

2005-10-24 00:06:29.4462 MusicMagic: Exporting song 11003: K:\MP3\Phil 
Collins\Hits\04 You Can't Hurry Love.mp3
2005-10-24 00:06:29.6281 MusicMagic: export mode is: playlists
2005-10-24 00:07:06.1984 MusicMagic: got playlist Commitments with 24 items.
2005-10-24 00:07:07.7254 MusicMagic: got playlist Dave Matthews Some 
Devil+Bonus with 19 items.
2005-10-24 00:07:11.1809 MusicMagic: got playlist DMB by Year with 91 items.
2005-10-24 00:07:13.3819 MusicMagic: got playlist DMB-Lillywhite sessions with 
12 items.
2005-10-24 00:07:14.6454 MusicMagic: got playlist DMB-Sexy with 21 items.
2005-10-24 00:07:18.8689 MusicMagic: got playlist DMB-Sexy-CD Length with 16 
items.
2005-10-24 00:07:24.3286 MusicMagic: got playlist Exercise Songs with 48 items.
2005-10-24 00:07:27.8787 MusicMagic: got playlist Fun and Upbeat with 36 items.
2005-10-24 00:07:31.0469 MusicMagic: got playlist Gimme Some Lovin with 125 
items.
2005-10-24 00:07:36.1994 MusicMagic: got playlist Instrumental with 211 items.
2005-10-24 00:07:41.0145 MusicMagic: got playlist INXS-Favorites with 68 items.
2005-10-24 00:07:44.5387 MusicMagic: got playlist INXS-Sexy with 13 items.
2005-10-24 00:07:45.8192 MusicMagic: got playlist Lovin' Songs with 48 items.
2005-10-24 00:07:46.3890 MusicMagic: got playlist Mellow with 40 items.
2005-10-24 00:07:47.4457 MusicMagic: got playlist New Music with 53 items.
2005-10-24 00:07:49.0798 MusicMagic: got playlist Party Mix Mellow with 149 
items.
2005-10-24 00:07:50.0811 MusicMagic: got playlist Relax MMM with 27 items.
2005-10-24 00:07:50.6845 MusicMagic: got playlist Sleep with 36 items.
2005-10-24 00:07:51.0993 MusicMagic: got playlist Temp with 27 items.
2005-10-24 00:07:51.5243 MusicMagic: got playlist U2 - Love Songs with 22 items.
2005-10-24 00:07:51.9305 MusicMagic: got playlist U2 Vertigo Setlist with 22 
items.
2005-10-24 00:07:53.4852 MusicMagic: got playlist U2-All Studio Albums Random 
with 130 items.
2005-10-24 00:07:54.4261 MusicMagic: got playlist Who Ultimate Collection with 
37 items.
2005-10-24 00:07:54.8641 MusicMagic: got playlist Wish You Were Here with 26 
items.
2005-10-24 00:07:55.0996 MusicMagic: got playlist Zapped Songs with 0 items.
2005-10-24 00:07:55.1328 MusicMagic: export mode is: duplicates
2005-10-24 00:07:55.1333 MusicMagic: Checking for duplicates.
2005-10-24 00:08:00.7437 MusicMagic: finished export (11002 records)
2005-10-24 00:08:00.7442 MusicMagic: done Scanning
2005-10-24 00:08:07.4487 MusicMagic: read cacheid of 1130123595
2005-10-24 00:08:07.5272 MusicMagic: got status - idle
.
.
.
at the "got playlist" stage in the log, the CPU went up to 100% usage and 
stayed there through the importing of playlists. Once it was done slim.exe went 
down to 5-25% CPU usage.
Comment 19 Dan Sully 2005-10-24 11:02:52 UTC
So I think what needs to happen here is processing of songs & playlists in MMM (and MoodLogic probably)
needs to move to a more scheduler based approach - where it yields control back to SlimServer in 
between each song that's processed.
Comment 20 KDF 2005-10-24 11:17:01 UTC
each call to the MMM api already returns control to the scheduler.
Comment 21 Dan Sully 2005-10-24 11:21:20 UTC
Not once inside the loop for fetching playlists, etc.
Comment 22 KDF 2005-10-24 11:25:17 UTC
right.  yuk. relatively simple change, much slower scan. but, can't be helped.
Comment 23 Dan Sully 2005-10-24 12:53:56 UTC
kdf - do you have a patch coming, or should I work on it?
Comment 24 KDF 2005-10-24 12:56:28 UTC
I haven't got anything now (day job) but I could take care of it if you have too
much already.  when do you need it?
Comment 25 Dan Sully 2005-10-24 12:58:38 UTC
Well, it's not going to make it for 6.2 either way - would like to target 6.2.1 though, which will be in a 
week or two.
Comment 26 KDF 2005-10-24 13:09:05 UTC
I'm on it.  There is also an option to grab the playlist as an m3u, so I might
investigate that and let Parse.pm take care of it from there.
Comment 27 KDF 2005-10-24 18:48:17 UTC
possible fix in trunk at change 4756
Comment 28 KDF 2005-10-25 12:38:37 UTC
Dan also merged this fix with the 6.2.1 nightly builds.  Please test and let us
know if this helps.
Comment 29 Sue Chastain 2005-10-25 12:45:23 UTC
I can't seem to find a Windows *.exe version. Maybe I'm too early?
Comment 30 KDF 2005-10-25 12:51:51 UTC
I think the build was broken for today.  Dan mentioned running a new one at some
poitn today, but has probably been rather busy (I woke to over 300 emails
myself).  The changes were put in this morning, so it would normally be
tomorrow's build anyway.
Comment 31 John Gorst 2005-10-26 13:19:14 UTC
Just upgraded to the latest 6.5 nightly and have a major bug with MM, I was
trying to see if the patch helped my 100% spikes

I get the following at the command line with d_musicmagic turned on (after the
bit of scannign all the songs):
5-10-26 21:15:14.7599 MusicMagic: export mode is: playlists
2005-10-26 21:15:14.7706 MusicMagic: export mode is: playlists
2005-10-26 21:15:14.7907 MusicMagic: export mode is: playlists
2005-10-26 21:15:14.7993 MusicMagic: export mode is: playlists
2005-10-26 21:15:14.8076 MusicMagic: export mode is: playlists
2005-10-26 21:15:14.8164 MusicMagic: export mode is: playlists
2005-10-26 21:15:14.8248 MusicMagic: export mode is: playlists
2005-10-26 21:15:14.8429 MusicMagic: export mode is: playlists
2005-10-26 21:15:14.8522 MusicMagic: export mode is: playlists
2005-10-26 21:15:14.8795 MusicMagic: export mode is: playlists
2005-10-26 21:15:14.8883 MusicMagic: export mode is: playlists
2005-10-26 21:15:14.8968 MusicMagic: export mode is: playlists
2005-10-26 21:15:14.9052 MusicMagic: export mode is: playlists
2005-10-26 21:15:14.9228 MusicMagic: export mode is: playlists
2005-10-26 21:15:14.9335 MusicMagic: export mode is: playlists

This seems to go on for ever taking up all my CPU
Comment 32 KDF 2005-10-26 13:32:29 UTC
do you have any playlists?

what if you try adding this line after line 747 of Plugins/MusicMagic/Plugin.pm:
$export = 'duplicates' unless @playlists;

and can you add d_remotestream when you do this?  I want to see what calls are
being made to MMM if the loop continues.

thanks.
Comment 33 John Gorst 2005-10-26 14:40:52 UTC
Adding that line in solved the problem with the recurring exportplaylist message.

However using tonights 6.5 nightly none of the recent patches have made any
difference to the high CPU useage I am seeing every 60 seconds. Here is the log
entry with d_musicmagic and d_remtoestream turned one:

2005-10-26 22:38:40.0601 Opening connection to
http://localhost:10002/api/cacheid?contents: [localhost on port 10002 with path
/api/cacheid?contents with timeout 5]
2005-10-26 22:38:40.0644 Request: GET /api/cacheid?contents HTTP/1.0
Accept: */*
Cache-Control: no-cache
User-Agent: iTunes/4.7.1 (Linux; N; Linux; i686-linux; EN; iso-8859-1)
SlimServer/6.5b1/4826
Icy-MetaData: 1
Connection: close
Host: localhost:10002

2005-10-26 22:38:40.0687 Response: HTTP/1.0 200 OK
2005-10-26 22:38:40.0710 header: Content-Type: text/plain
2005-10-26 22:38:40.0730 header:
2005-10-26 22:38:40.0742 Recieved final blank line...
2005-10-26 22:38:40.0751 opened stream!
2005-10-26 22:38:42.9724 MusicMagic: read cacheid of 1129384331
2005-10-26 22:38:42.9745 Opening connection to
http://localhost:10002/api/getStatus: [localhost on port 10002 with path
/api/getStatus with timeout 5]
2005-10-26 22:38:42.9787 Request: GET /api/getStatus HTTP/1.0
Accept: */*
Cache-Control: no-cache
User-Agent: iTunes/4.7.1 (Linux; N; Linux; i686-linux; EN; iso-8859-1)
SlimServer/6.5b1/4826
Icy-MetaData: 1
Connection: close
Host: localhost:10002

2005-10-26 22:38:42.9819 Response: HTTP/1.0 200 OK
2005-10-26 22:38:42.9842 header: Content-Type: text/plain
2005-10-26 22:38:42.9861 header:
2005-10-26 22:38:42.9872 Recieved final blank line...
2005-10-26 22:38:42.9881 opened stream!
2005-10-26 22:38:42.9891 Slim::Player::Protocols::HTTP - in DESTROY
2005-10-26 22:38:42.9900 Slim::Player::Protocols::HTTP About to close socket to:
[http://localhost:10002/api/cacheid?contents]
2005-10-26 22:38:43.1669 MusicMagic: got status - idle
2005-10-26 22:38:43.1690 Slim::Player::Protocols::HTTP - in DESTROY
2005-10-26 22:38:43.1702 Slim::Player::Protocols::HTTP About to close socket to:
[http://localhost:10002/api/getStatus]
Comment 34 KDF 2005-10-26 15:24:16 UTC
well, lets just try changing line 309...
Slim::Utils::Timers::setTimer(0, (Time::HiRes::time() + 60), \&checker);

change 60 to something like 120.

I expect your spikes will follow that timing.  What I dont understand is why it
takes several seconds at 100% to do that. a 1g p3 shouldn't be THAT
underpowered. I can't even get more than 50% while running slimserver, MMM, a
schematic capture  and layout program, firefox browsing bugs database and 5
minute refresh on a webmail page, outlook and softsqueeze playing music.  p4 1.4G
Comment 35 Sue Chastain 2005-10-26 15:53:08 UTC
I just got a chance to try 6.2.1 and it was pretty much the same as before 
except the scan took about half the time it did before. That might be due to 
less network congestion at the time of the scan, though. (All my music is on a 
network disk.)
Comment 36 Blackketter Dean 2005-11-04 15:14:05 UTC
KDF: where do we stand on this?  Are the useful fixes in for 6.2.1?
Comment 37 KDF 2005-11-04 15:18:50 UTC
I put in what I could.  I was never able to reproduce and the fixes seem to have
had ZERO effect for those who suffer from it. Next plan was to just set the
checker to 120 (as I suggested above) and re-assign to someone else who can
actually do something useful with it.
Comment 38 KDF 2005-11-04 17:28:12 UTC
changed the checker timing in trunk at chagne 5051
Comment 39 John Gorst 2005-11-05 00:26:46 UTC
I will test this change after w/e (damn work!)
Comment 40 John Gorst 2006-03-25 16:00:30 UTC
Just to add a comment to this bug.

I have upgraded to a Athlon64 3000 system running debian (vs P3 1ghz running mandrake).

Still running into the CPU spike problem - kicks is as regular as clock work when I am playing quake on my system! If I disable musicmagic then the problem is resolved.

I know that runnign games on my slimserver is not ideal - but in reality people only have one comptuer and will expect to be able to run normal things on it with slimserver installed (obviously they cant necessarily expect non-choppy msuic if they are playing quake!!)

I propose that there should be an option to increase the chache-id checker timing. For example I could set it to be every 24 hours - and have the music-magic reload interval as 60 seconds. If I was lucky the cpu skie would then be in the middle of the night.

This option could be in the wb interface. However it is pretty 'advanced' and may only be necessary for a few people to set. Therefore it coudl just be an option in slimserver.pref file? I woudl be willing to do a wiki page to document this.

Ideally I should be able to tell slimserver to only check the cache-id and the do a music-magic reload at a set time (e.g. 2am) - but that woudl be iceing.
Comment 41 KDF 2006-03-25 19:48:52 UTC
what you have failed to add to your comment is the confirmation that the spike has moved to every 2 minutes to correlate with the change that I mentioned above.  Without that, there is absolutely nothing to show that it is the cacheid check and thus the whole premise of a pref is pointless.  It is also very hard to justify a pref when this is still not reproducable.  Personally, I'd rather nix the checks and make the who bloody thing tie into the manual or scheduled rescan triggers ONLY.  however, this is probably all pointless after the split-scanner branch gets into the mainstream

Comment 42 Dan Sully 2006-06-14 19:36:39 UTC
The scanner is split off from the main process in 6.5 now - closing this bug.

If there's a more specific issue, please open a new bug.

Thanks.