RC2 - MM3 let's work CPU in overtime without telling me why

GeWi · Post by **GeWi** » Thu Nov 22, 2007 10:01 am

When I start up MM3 it consumes about 45% of the CPU time, but MM3 isn't telling the user what it's doing.
I'm quite sure this has to do with the function "Automaticaly analyze volume of unanalyzed tracks". This function is on and normally MM3 shows me a progress bar telling me something like "Analyzing track 123 of 14000 files".
But now nothing shows up in the task bars. When I disable the auto-analyze function nothing changes (MM3 keeps on eating 45% of processor time). But when I close MM3 and restart it, CPU usage goes down to almost zero after a few seconds. ((Restarting MM3 can though take quite some time because the first instance of MM3 is still running and closing down all threads. Today it took almost a minute.))
Enabling auto-analyze has an immediate effect. A restart isn't necessary.
The processor usage goes up to 45% again and stays there (for how long I don't know. I checked it for more than an hour now and it stays that high all the time).

I can imagine that this behavior is not a bug. MM3 is obviously doing something, but I would prefer MM3 letting me know what it is doing. A little message like ("Checking volume of all tracks") would make me happy again.

Post by **rusty** » Fri Nov 23, 2007 1:33 pm

Most likely, the Now Playing list is very large, and at startup, MM is matching the entries in the list with the entries in the DB (the list is stored as an .m3u file).

-Rusty

GeWi · Post by **GeWi** » Fri Nov 23, 2007 5:27 pm

Hi Rusty,

This may very well be the case, but isn't it strange this behavior disappears when auto-analyze is disabled and comes back when auto-analyze is enabled again?

Teknojnky · Post by **Teknojnky** » Fri Nov 23, 2007 6:27 pm

This happens with auto-analyize, if you run the debug viewer as its happening you can see that MM is processing files/database while calculating what files need analyzed.

This is repeatable for any new database that is imported from mm2, because mm 2 does not have album artist volume info.

GeWi · Post by **GeWi** » Mon Nov 26, 2007 7:59 am

I checked it again and the behavior is indeed related to the auto analyze function (not with the play now list because it happens too with an empty play now list).

If I synchronise my MP3-files with the ones on my the hard disc of my second computer (where I do all tagging etc...) auto-analyze is busy for several hours.

I have absolutely no problems with that, but I would prefer being informed about what MM3 is doing. This used to be the case (I believe I saw those messages even in the current build), but since a few days/weeks MM3 isn't telling me anymore it's doing a huge auto-analyze task.

Teknojnky · Post by **Teknojnky** » Tue Nov 27, 2007 12:11 pm

This still occurs with rc-3.

reproduction steps:

- ensure that auto-volume-analyze is OFF in mm3
- import a mm2 library
- enable auto-volume-analyze in the options
- watch cpu usage spike (nearly maxes out both my dual core cpu graph)
- after amount of time coorespondant to size of library, mm will finally start analyze process and indicate such in the status bar (analyzing volume 1 of however many need analyze).

edit:
what I expect is that mm should indicate what it is doing somehow, preferably in the status bar ("processing background analysis...") or some such.

GeWi · Post by **GeWi** » Wed Nov 28, 2007 6:41 am

As I couldn't use dbgview for a few weeks due to a bug in dgbview itself (but now fixed in release 1.74), I couldn't thoroughly check what was happening here.

DBGview tells me much more about this matter. It looks like MM3 (in this case RC3) is trapped in a loop. It keeps on locking and unlocking the same file, reading tags and writing tags over and over again.

What follows is a small part of the dbgview listing. In reality it is of course much longer and it keeps on repeating the same lines.

[2924] Locking file: M:\Mijn Mp3's\Ok\Frank Sinatra\The Legend\17 - Frank Sinatra - My happiness.mp3
[2924] Locked file: M:\Mijn Mp3's\Ok\Frank Sinatra\The Legend\17 - Frank Sinatra - My happiness.mp3
[2924] MP3: Going to write tag to M:\Mijn Mp3's\Ok\Frank Sinatra\The Legend\17 - Frank Sinatra - My happiness.mp3
[2924] MP3: Writing ID3v2
[2924] MP3: Updated ID3v2
[2924] MP3: Writing ID3v1
[2924] MP3: Updated ID3v1
[2924] 1880 DB exec SQL: UPDATE Songs SET FileLength=2263040, TrackModified=39414.523013762,FileModified=39414.523013762 WHERE ID=193248
[2924] 1880 DB lock successful.
[2924] 1880 DB lock finished, took 1060848.
[2924] Unlocking file: M:\Mijn Mp3's\Ok\Frank Sinatra\The Legend\17 - Frank Sinatra - My happiness.mp3
[2924] 1880 DB open SQL: SELECT ID,Album FROM Albums WHERE Album=? AND Artist=?
[2924] 1880 DB lock finished, took 91396.
[2924] 1880 DB exec SQL: UPDATE Songs SET SongPath=?, Artist=?, IdAlbum=?, Album=?, AlbumArtist=?, SongTitle=?, Genre=?, Year=?, IDMedia=?, SongLength=?, PlaybackPos=?, TrackNumber=?, BitRate=?, FileLength=?, Seekable=?, SamplingFrequency=?, Stereo=?, Copyrighted=?, Original=?, VBR=?, BPM=?, Author=?, Rating=?, AudioCDTrack=?, FileModified=?, MaxSample=?, NormalizeTrack=?, NormalizeAlbum=?, DateAdded=?, LastTimePlayed=?, PlayCounter=?, Custom1=?, Custom2=?, Custom3=?, Custom4=?, Custom5=?, SignType=?, SignPart1=?, SignPart2=?, SignPart3=?, SignPart4=?, Copyright=?, Publisher=?, Encoder=?, EncodedBy=?, Lyricist=?, Band=?, Conductor=?, Remixer=?, InvolvedPeople=?, OrigTitle=?, OrigArtist=?, OrigLyricist=?, GroupDesc=?, SubTitle=?, ISRC=?, InitialKey=?, Language=?, MediaType=?, RatingString=?, OrigYear=?, Tempo=?, Mood=?, Occasion=?, Quality=?, Lyrics=?, Comment=?, DiscNumber=?, PreGap=?, PostGap=?, TotalSamples=?, GaplessBytes=?, TrackModified=? WHERE ID=?
[2924] 1880 DB lock successful.
[2924] 1880 DB lock finished, took 923952.
[2924] 1880 DB exec SQL: DELETE FROM ArtistsSongs WHERE IDSong=?
[2924] 1880 DB lock successful.
[2924] 1880 DB lock finished, took 408040.
[2924] 1880 DB exec SQL: DELETE FROM GenresSongs WHERE IDSong=?
[2924] 1880 DB lock successful.
[2924] 1880 DB lock finished, took 206348.
[2924] 1880 DB open SQL: SELECT ID,Artist FROM Artists WHERE Artist=?
[2924] 1880 DB lock finished, took 104292.
[2924] 1880 DB exec SQL: INSERT INTO ArtistsSongs (PersonType,IDArtist,IDSong) VALUES (?,?,?)
[2924] 1880 DB lock successful.
[2924] 1880 DB lock finished, took 354592.
[2924] 1880 DB open SQL: SELECT IDGenre FROM Genres WHERE GenreName='Sconosciuto'
[2924] 1880 DB lock finished, took 444708.
[2924] 1880 DB exec SQL: INSERT INTO GenresSongs (IDGenre,IDSong) VALUES (?,?)
[2924] 1880 DB lock successful.
[2924] 1880 DB lock finished, took 169640.
[2924] 1880 DB open SQL: SELECT Count(*) FROM PathProcessing
[2924] 1880 DB lock finished, took 35836.
[2924] Locking file: M:\Mijn Mp3's\Ok\Frank Sinatra\The Legend\17 - Frank Sinatra - My happiness.mp3
[2924] Locked file: M:\Mijn Mp3's\Ok\Frank Sinatra\The Legend\17 - Frank Sinatra - My happiness.mp3
[2924] MP3: Going to write tag to M:\Mijn Mp3's\Ok\Frank Sinatra\The Legend\17 - Frank Sinatra - My happiness.mp3
[2924] MP3: Writing ID3v2
[2924] MP3: Updated ID3v2
[2924] MP3: Writing ID3v1
[2924] MP3: Updated ID3v1
[2924] 1880 DB exec SQL: UPDATE Songs SET FileLength=2263040, TrackModified=39414.523018287,FileModified=39414.523018287 WHERE ID=193248
[2924] 1880 DB lock successful.
[2924] 1880 DB lock finished, took 1032040.
[2924] Unlocking file: M:\Mijn Mp3's\Ok\Frank Sinatra\The Legend\17 - Frank Sinatra - My happiness.mp3
[2924] 1880 DB open SQL: SELECT ID,Album FROM Albums WHERE Album=? AND Artist=?
[2924] 1880 DB lock finished, took 88056.
[2924] 1880 DB exec SQL: UPDATE Songs SET SongPath=?, Artist=?, IdAlbum=?, Album=?, AlbumArtist=?, SongTitle=?, Genre=?, Year=?, IDMedia=?, SongLength=?, PlaybackPos=?, TrackNumber=?, BitRate=?, FileLength=?, Seekable=?, SamplingFrequency=?, Stereo=?, Copyrighted=?, Original=?, VBR=?, BPM=?, Author=?, Rating=?, AudioCDTrack=?, FileModified=?, MaxSample=?, NormalizeTrack=?, NormalizeAlbum=?, DateAdded=?, LastTimePlayed=?, PlayCounter=?, Custom1=?, Custom2=?, Custom3=?, Custom4=?, Custom5=?, SignType=?, SignPart1=?, SignPart2=?, SignPart3=?, SignPart4=?, Copyright=?, Publisher=?, Encoder=?, EncodedBy=?, Lyricist=?, Band=?, Conductor=?, Remixer=?, InvolvedPeople=?, OrigTitle=?, OrigArtist=?, OrigLyricist=?, GroupDesc=?, SubTitle=?, ISRC=?, InitialKey=?, Language=?, MediaType=?, RatingString=?, OrigYear=?, Tempo=?, Mood=?, Occasion=?, Quality=?, Lyrics=?, Comment=?, DiscNumber=?, PreGap=?, PostGap=?, TotalSamples=?, GaplessBytes=?, TrackModified=? WHERE ID=?
[2924] 1880 DB lock successful.
[2924] 1880 DB lock finished, took 715300.
[2924] 1880 DB exec SQL: DELETE FROM ArtistsSongs WHERE IDSong=?
[2924] 1880 DB lock successful.
[2924] 1880 DB lock finished, took 254140.
[2924] 1880 DB exec SQL: DELETE FROM GenresSongs WHERE IDSong=?
[2924] 1880 DB lock successful.
[2924] 1880 DB lock finished, took 116092.
[2924] 1880 DB open SQL: SELECT ID,Artist FROM Artists WHERE Artist=?
[2924] 1880 DB lock finished, took 70168.
[2924] 1880 DB exec SQL: INSERT INTO ArtistsSongs (PersonType,IDArtist,IDSong) VALUES (?,?,?)
[2924] 1880 DB lock successful.
[2924] 1880 DB lock finished, took 311368.
[2924] 1880 DB open SQL: SELECT IDGenre FROM Genres WHERE GenreName='Sconosciuto'
[2924] 1880 DB lock finished, took 281684.
[2924] 1880 DB exec SQL: INSERT INTO GenresSongs (IDGenre,IDSong) VALUES (?,?)
[2924] 1880 DB lock successful.
[2924] 1880 DB lock finished, took 155748.
[2924] 1880 DB open SQL: SELECT Count(*) FROM PathProcessing
[2924] 1880 DB lock finished, took 34416.
[2924] Locking file: M:\Mijn Mp3's\Ok\Frank Sinatra\The Legend\17 - Frank Sinatra - My happiness.mp3
[2924] Locked file: M:\Mijn Mp3's\Ok\Frank Sinatra\The Legend\17 - Frank Sinatra - My happiness.mp3

I have sent a copy of the MP3 file to Jiri.