Freezing on repeated quick search

hintergrundrauschen · Fri Oct 11, 2013 10:45 am

MM freezes when repeatedly searching the archive using the search bar. As far as I can tell this happens a few seconds after the last of a few successful searches.

Running the latest beta [1662] with a very large archive on Win7 64, 8 GB RAM. The problem has been there with the previous beta, at least.

Code: Select all

...
[1516] 4908 DB open SQL: SELECT Songs.* 
[1516]  FROM Songs WHERE Songs.ID IN (SELECT rowid FROM SongsText WHERE SongsText MATCH ' kid* alex* ')  
[1516] OpenQuery - Preparing query SELECT Songs.* 
[1516]  FROM Songs WHERE Songs.ID IN (SELECT rowid FROM SongsText WHERE SongsText MATCH ' kid* alex* ')  
[1516] 4908 DB lock finished, took 118635.
[1516] Going 'FillingThread'to make final callback 4908
[1516] Thread 'FillingThread' is going to callback
[1516] SortAlbumListPreserveSelection called
[1516] TAlbumArtViewController::PrepareAlbumArtList - begin
[1516] TAlbumArtViewsManager::PrepareAlbumArtList - begin
[1516] TAlbumArtViewsManager::PrepareAlbumArtList - before fill
[1516] TAlbumArtViewsManager::PrepareAlbumArtList - end
[1516] TAlbumArtViewController::PrepareAlbumArtList - Albums generated
[1516] TAlbumArtViewController::PrepareAlbumArtList - Albums sorted
[1516] 4248 DB open SQL: SELECT IDView FROM NodeViews WHERE NodeType = ? 
[1516] 4248 DB lock finished, took 283.
[1516] 4248 DB open SQL: SELECT ID, Name, View FROM Views WHERE ID = ? 
[1516] 4248 DB lock finished, took 239.
[1516] TAlbumArtViewController::PrepareAlbumArtList - Albums groups generated
[1516] TAlbumArtViewController::PrepareAlbumArtList - Rows computed
[1516] TAlbumArtViewController::PrepareAlbumArtList - Albums selected
[1516] TAlbumArtViewController::PrepareAlbumArtList - end
[1516] TAlbumArtViewController.SelectSongs - Begin
[1516] BQ: Added new task. Currently 1 tasks in queue.
[1516] BQ: Starting a new task.
[1516] BQ: Currently running 0 threads of 8
[1516] BQ: Starting a new thread.
[1516] TGenThread.Create: ThreadName: BackgroundQueue , Running Threads: Internal: 1, All: 50
[1516] Thread 'BackgroundQueue' has started 3956
[1516] Thread registered, going to initialize 3956
[1516] Thread initialized 3956
[1516] UpdateSongPictures: C:\Users\Claude\Music\Depot\# Pop\K\Kid Alex\Colorz\Kid Alex - Intro.mp3
[1516] Added Cover Lists: 89
[1516] GetFileInfo: C:\Users\Claude\Music\Depot\# Pop\K\Kid Alex\Colorz\Kid Alex - Intro.mp3
[1516] GetFileInfo: readPictures=spAlways
[1516] GetFileInfo: C:\Users\Claude\Music\Depot\# Pop\K\Kid Alex\Colorz\Kid Alex - Intro.mp3
[1516] MP3.ReadHeader C:\Users\Claude\Music\Depot\# Pop\K\Kid Alex\Colorz\Kid Alex - Intro.mp3
[1516] MP3.ReadHeader - File size 1107586
[1516] MP3.ReadHeader - Found ID3v2, length: 14068
[1516] MP3.ReadHeader framestarts: 14078, 14078
[1516] MP3.ReadHeader finished
[1516] MP3: Going to read tag from C:\Users\Claude\Music\Depot\# Pop\K\Kid Alex\Colorz\Kid Alex - Intro.mp3
[1516] Added Covers: 109
[1516] MP3: Tag read from C:\Users\Claude\Music\Depot\# Pop\K\Kid Alex\Colorz\Kid Alex - Intro.mp3
[1516] 3956 DB prepare SQL: SELECT Songs.* FROM Songs WHERE Songs.IDMedia=? AND Songs.SongPath=?
[1516] 3956 DB query prepare finished, took 559.
[1516] 3956 DB open SQL: SELECT Songs.* FROM Songs WHERE Songs.IDMedia=? AND Songs.SongPath=? 
[1516] 3956 DB lock finished, took 55021.
[1516] GetFileInfo: Found in DB
[1516] UpdateSongPictures: CoverList.LoadForSongId, C:\Users\Claude\Music\Depot\# Pop\K\Kid Alex\Colorz\Kid Alex - Intro.mp3
[1516] 3956 DB open SQL: SELECT * FROM Covers WHERE IDSong=2856 ORDER BY CoverOrder 
[1516] OpenQuery - Preparing query SELECT * FROM Covers WHERE IDSong=2856 ORDER BY CoverOrder 
[1516] 3956 DB lock finished, took 21765.
[1516] Added Covers: 110
[1516] Remaining Covers: 109
[1516] Added Covers: 110
[1516] TryLoadDirectlyFromDBAndCache called for track C:\Users\Claude\Music\Depot\# Pop\K\Kid Alex\Colorz\Kid Alex - Intro.mp3
[1516] TGenThread.Create: ThreadName: ImageReader_Var , Running Threads: Internal: 2, All: 51
[1516] Thread 'ImageReader_Var' has started 1636
[1516] Thread registered, going to initialize 1636
[1516] Thread initialized 1636
[1516] TryLoadDirectlyFromDBAndCache called for track C:\Users\Claude\Music\Depot\# Pop\T\The Disco Boys\The Disco Boys Vol. 2\CD 2\Kid Alex - Aber.mp3
[1516] StretchStart
[1516] BQ: Added new task. Currently 1 tasks in queue.
[1516] BQ: Starting a new task.
[1516] BQ: Currently running 1 threads of 8
[1516] BQ: Starting a new thread.
[1516] TGenThread.Create: ThreadName: BackgroundQueue , Running Threads: Internal: 3, All: 52
[1516] BQ: Added new task. Currently 2 tasks in queue.
[1516] BQ: Starting a new task.
[1516] BQ: Currently running 2 threads of 8
[1516] BQ: Starting a new thread.
[1516] Thread 'BackgroundQueue' has started 3648
[1516] Thread registered, going to initialize 3648
[1516] Thread initialized 3648
[1516] TGenThread.Create: ThreadName: BackgroundQueue , Running Threads: Internal: 3, All: 53
[1516] BQ: Added new task. Currently 3 tasks in queue.
[1516] BQ: Starting a new task.
[1516] BQ: Currently running 3 threads of 8
[1516] BQ: Starting a new thread.
[1516] Thread 'BackgroundQueue' has started 3424
[1516] Thread registered, going to initialize 3424
[1516] Thread initialized 3424
[1516] TGenThread.Create: ThreadName: BackgroundQueue , Running Threads: Internal: 4, All: 54
[1516] StretchEnd
[1516] Thread 'BackgroundQueue' has started 5216
[1516] Thread registered, going to initialize 5216
[1516] Thread initialized 5216
[1516] Remaining Covers: 109
[1516] BQ: Added new task. Currently 1 tasks in queue.
[1516] BQ: Starting a new task.
[1516] BQ: There are threads waiting, resume one.
[1516] StretchStart
[1516] BQ: Added new task. Currently 1 tasks in queue.
[1516] BQ: Starting a new task.
[1516] BQ: There are threads waiting, resume one.
[1516] BQ: Added new task. Currently 2 tasks in queue.
[1516] BQ: Starting a new task.
[1516] BQ: There are threads waiting, resume one.
[1516] BQ: Added new task. Currently 2 tasks in queue.
[1516] BQ: Starting a new task.
[1516] BQ: There are threads waiting, resume one.
[1516] StretchEnd
[1516] TAlbumArtViewController.SelectSongs - End
[1516] Added Cover Lists: 90
[1516] 4248 DB open SQL: SELECT IDView FROM NodeViews WHERE NodeType = ? 
[1516] 1636 DB prepare SQL: SELECT Covers.* FROM Covers, Songs WHERE songs.idalbum=? AND covers.idsong=songs.id ORDER BY Covers.idsong
[1516] 4248 DB lock finished, took 404.
[1516] 1636 DB query prepare finished, took 231.
[1516] 4248 DB open SQL: SELECT ID, Name, View FROM Views WHERE ID = ? 
[1516] 1636 DB open SQL: SELECT Covers.* FROM Covers, Songs WHERE songs.idalbum=? AND covers.idsong=songs.id ORDER BY Covers.idsong 
[1516] 4248 DB lock finished, took 290.
[1516] 1636 DB lock finished, took 1055.
[1516] Added Covers: 110
[1516] Added Covers: 111
[1516] 4248 DB open SQL: SELECT IDView FROM NodeViews WHERE NodeType = ? 
[1516] 4248 DB lock finished, took 227.
[1516] 4248 DB open SQL: SELECT ID, Name, View FROM Views WHERE ID = ? 
[1516] 4248 DB lock finished, took 223.
[1516] Thread 'FillingThread'has finished 4908
[1516] TryLoadDirectlyFromDBAndCache called for track C:\Users\Claude\Music\Depot\# Pop\K\Kid Alex\Colorz\Kid Alex - Intro.mp3
[1516] TryLoadDirectlyFromDBAndCache - force load from cache C:\Users\Claude\AppData\Local\Temp\MMCache1087777978_1\Kid Alex - Intro-9EVB1MJMN48PA7BQ2C95XN1GI - SP1QDMPD9CRIZSXP8INYVIQIP499.bmp
[1516] Added Covers: 112
[1516] Added Covers: 113
[1516] Remaining Covers: 112
[1516] TryLoadDirectlyFromDBAndCache called for track C:\Users\Claude\Music\Depot\# Pop\T\The Disco Boys\The Disco Boys Vol. 2\CD 2\Kid Alex - Aber.mp3
[1516] Going 'BackgroundQueue'to make final callback 3956
[1516] Going 'BackgroundQueue'to make final callback 3648
[1516] Going 'BackgroundQueue'to make final callback 5216
[1516] DB: Deleting prepared query: SELECT Songs.* FROM Songs WHERE Songs.IDMedia=? AND Songs.SongPath=? 
[1516] Thread 'BackgroundQueue'has finished 3648
[1516] Thread 'BackgroundQueue'has finished 5216
[1516] Thread 'BackgroundQueue'has finished 3956
[1516] Going 'BackgroundQueue'to make final callback 3424
[1516] Thread 'BackgroundQueue'has finished 3424

Ludek · Post by **Ludek** » Fri Oct 11, 2013 4:17 pm

Hi, if it fozen it should generate Send log, did you send it? When?

If you copy/paste the text from debug window then I can't see the time column that is important when freeze occurs, could you attach the whole log file?
Or at least copy/paste from log file directly so that the time column is present?

hintergrundrauschen · Post by **hintergrundrauschen** » Fri Oct 11, 2013 5:27 pm

It never generates a send log when freezing.

I tried to set Debugview to save to file, but what was saved was even less than the displayed output. I will try to configure it correctly.

hintergrundrauschen · Post by **hintergrundrauschen** » Tue Oct 15, 2013 1:13 pm

Just sent you a crash report.

UI and controls freeze, the currently played song keeps playing regularly till its end. After that, MM stops playing.

To make sure, here's the saved debug output, starting from the beginning of the last of the quick searches onwards. The auto log (Log to...) is emtpy.

Code: Select all

00008539	20:00:07.255	[3272] TGenThread.Create: ThreadName: Fill_Var , Running Threads: Internal: 4, All: 57	
00008540	20:00:07.258	[3272] Thread 'Fill_Var' has started 856	
00008541	20:00:07.258	[3272] Thread registered, going to initialize 856	
00008542	20:00:07.258	[3272] Thread initialized 856	
00008543	20:00:07.258	[3272] ComboHelper::FillThread - lastPart = "k"; len = 1	
00008544	20:00:07.258	[3272] Thread 'Fill_Var' is going to callback	
00008545	20:00:07.262	[3272] Going 'Fill_Var'to make final callback 856	
00008546	20:00:07.262	[3272] Thread 'Fill_Var' is going to callback	
00008547	20:00:07.262	[3272] Thread 'Fill_Var'has finished 856	
00008548	20:00:07.399	[3272] TGenThread.Create: ThreadName: Fill_Var , Running Threads: Internal: 4, All: 57	
00008549	20:00:07.402	[3272] Thread 'Fill_Var' has started 4984	
00008550	20:00:07.402	[3272] Thread registered, going to initialize 4984	
00008551	20:00:07.402	[3272] Thread initialized 4984	
00008552	20:00:07.402	[3272] ComboHelper::FillThread - lastPart = "ki"; len = 2	
00008553	20:00:07.402	[3272] Thread 'Fill_Var' is going to callback	
00008554	20:00:07.407	[3272] Winamp Playlist sim - message 0 left to the default processing	
00008555	20:00:07.407	[3272] Winamp simulation window received messsage 0	
00008556	20:00:07.407	[3272] Going 'Fill_Var'to make final callback 4984	
00008557	20:00:07.407	[3272] Thread 'Fill_Var' is going to callback	
00008558	20:00:07.407	[3272] Thread 'Fill_Var'has finished 4984	
00008559	20:00:07.463	[3272] TGenThread.Create: ThreadName: Fill_Var , Running Threads: Internal: 4, All: 57	
00008560	20:00:07.466	[3272] Thread 'Fill_Var' has started 5088	
00008561	20:00:07.466	[3272] Thread registered, going to initialize 5088	
00008562	20:00:07.466	[3272] Thread initialized 5088	
00008563	20:00:07.466	[3272] ComboHelper::FillThread - lastPart = "ki"; len = 2	
00008564	20:00:07.466	[3272] Thread 'Fill_Var' is going to callback	
00008565	20:00:07.466	[3272] Winamp Playlist sim - message 0 left to the default processing	
00008566	20:00:07.466	[3272] Winamp simulation window received messsage 0	
00008567	20:00:07.467	[3272] Going 'Fill_Var'to make final callback 5088	
00008568	20:00:07.467	[3272] Thread 'Fill_Var' is going to callback	
00008569	20:00:07.467	[3272] Thread 'Fill_Var'has finished 5088	
00008570	20:00:07.559	[3272] TGenThread.Create: ThreadName: Fill_Var , Running Threads: Internal: 4, All: 57	
00008571	20:00:07.562	[3272] Thread 'Fill_Var' has started 4648	
00008572	20:00:07.562	[3272] Thread registered, going to initialize 4648	
00008573	20:00:07.562	[3272] Thread initialized 4648	
00008574	20:00:07.562	[3272] ComboHelper::FillThread - lastPart = "kin"; len = 3	
00008575	20:00:07.562	[3272] Thread 'Fill_Var' is going to callback	
00008576	20:00:07.563	[3272] Winamp Playlist sim - message 0 left to the default processing	
00008577	20:00:07.563	[3272] Winamp simulation window received messsage 0	
00008578	20:00:07.563	[3272] Going 'Fill_Var'to make final callback 4648	
00008579	20:00:07.563	[3272] Thread 'Fill_Var' is going to callback	
00008580	20:00:07.563	[3272] Thread 'Fill_Var'has finished 4648	
00008581	20:00:07.743	[3272] TGenThread.Create: ThreadName: Fill_Var , Running Threads: Internal: 4, All: 57	
00008582	20:00:07.746	[3272] Thread 'Fill_Var' has started 5044	
00008583	20:00:07.746	[3272] Thread registered, going to initialize 5044	
00008584	20:00:07.746	[3272] Thread initialized 5044	
00008585	20:00:07.746	[3272] ComboHelper::FillThread - lastPart = "king"; len = 4	
00008586	20:00:07.746	[3272] Thread 'Fill_Var' is going to callback	
00008587	20:00:07.747	[3272] Winamp Playlist sim - message 0 left to the default processing	
00008588	20:00:07.747	[3272] Winamp simulation window received messsage 0	
00008589	20:00:07.747	[3272] Going 'Fill_Var'to make final callback 5044	
00008590	20:00:07.747	[3272] Thread 'Fill_Var' is going to callback	
00008591	20:00:07.747	[3272] Thread 'Fill_Var'has finished 5044	
00008592	20:00:07.823	[3272] TGenThread.Create: ThreadName: Fill_Var , Running Threads: Internal: 4, All: 57	
00008593	20:00:07.826	[3272] Thread 'Fill_Var' has started 1008	
00008594	20:00:07.826	[3272] Thread registered, going to initialize 1008	
00008595	20:00:07.826	[3272] Thread initialized 1008	
00008596	20:00:07.826	[3272] ComboHelper::FillThread - lastPart = "kings"; len = 5	
00008597	20:00:07.826	[3272] Thread 'Fill_Var' is going to callback	
00008598	20:00:07.829	[3272] Winamp Playlist sim - message 0 left to the default processing	
00008599	20:00:07.829	[3272] Winamp simulation window received messsage 0	
00008600	20:00:07.829	[3272] Going 'Fill_Var'to make final callback 1008	
00008601	20:00:07.829	[3272] Thread 'Fill_Var' is going to callback	
00008602	20:00:07.829	[3272] Thread 'Fill_Var'has finished 1008	
00008603	20:00:07.903	[3272] TGenThread.Create: ThreadName: Fill_Var , Running Threads: Internal: 4, All: 57	
00008604	20:00:07.906	[3272] Thread 'Fill_Var' has started 2724	
00008605	20:00:07.906	[3272] Thread registered, going to initialize 2724	
00008606	20:00:07.906	[3272] Thread initialized 2724	
00008607	20:00:07.906	[3272] ComboHelper::FillThread - lastPart = "kings "; len = 6	
00008608	20:00:07.906	[3272] Thread 'Fill_Var' is going to callback	
00008609	20:00:07.907	[3272] Winamp Playlist sim - message 0 left to the default processing	
00008610	20:00:07.907	[3272] Winamp simulation window received messsage 0	
00008611	20:00:07.907	[3272] Going 'Fill_Var'to make final callback 2724	
00008612	20:00:07.907	[3272] Thread 'Fill_Var' is going to callback	
00008613	20:00:07.907	[3272] Thread 'Fill_Var'has finished 2724	
00008614	20:00:08.095	[3272] TGenThread.Create: ThreadName: Fill_Var , Running Threads: Internal: 4, All: 57	
00008615	20:00:08.098	[3272] Thread 'Fill_Var' has started 4924	
00008616	20:00:08.098	[3272] Thread registered, going to initialize 4924	
00008617	20:00:08.098	[3272] Thread initialized 4924	
00008618	20:00:08.098	[3272] ComboHelper::FillThread - lastPart = "kings o"; len = 7	
00008619	20:00:08.098	[3272] Thread 'Fill_Var' is going to callback	
00008620	20:00:08.099	[3272] Winamp Playlist sim - message 0 left to the default processing	
00008621	20:00:08.099	[3272] Winamp simulation window received messsage 0	
00008622	20:00:08.099	[3272] Going 'Fill_Var'to make final callback 4924	
00008623	20:00:08.099	[3272] Thread 'Fill_Var' is going to callback	
00008624	20:00:08.099	[3272] Thread 'Fill_Var'has finished 4924	
00008625	20:00:08.167	[3272] TGenThread.Create: ThreadName: Fill_Var , Running Threads: Internal: 4, All: 57	
00008626	20:00:08.170	[3272] Thread 'Fill_Var' has started 3228	
00008627	20:00:08.170	[3272] Thread registered, going to initialize 3228	
00008628	20:00:08.170	[3272] Thread initialized 3228	
00008629	20:00:08.170	[3272] ComboHelper::FillThread - lastPart = "kings of"; len = 8	
00008630	20:00:08.170	[3272] Thread 'Fill_Var' is going to callback	
00008631	20:00:08.173	[3272] Winamp Playlist sim - message 0 left to the default processing	
00008632	20:00:08.173	[3272] Winamp simulation window received messsage 0	
00008633	20:00:08.176	[3272] Going 'Fill_Var'to make final callback 3228	
00008634	20:00:08.176	[3272] Thread 'Fill_Var' is going to callback	
00008635	20:00:08.176	[3272] Thread 'Fill_Var'has finished 3228	
00008636	20:00:08.676	[3272] Remaining Cover Lists: 62	
00008637	20:00:08.682	[3272] Node Beinhaltet: "kingdom" going to clear SongList.	
00008638	20:00:08.947	[3272] Node Beinhaltet: "kings of" starting.	
00008639	20:00:08.947	[3272] Node Beinhaltet: "kings of" going to clear SongList.	
00008640	20:00:08.948	[3272] Events: Invoking event: OnChangedSelection	
00008641	20:00:08.948	[3272] Events: Successfully finished event: OnChangedSelection	
00008642	20:00:08.948	[3272] Events: Invoking event: SetMnuVisibility	
00008643	20:00:08.948	[3272] TEventedAutoObject Created, Class: TSDBTreeNode	
00008644	20:00:08.948	[3272] TEventedAutoObject Created, Class: TSDBTreeNode	
00008645	20:00:08.948	[3272] TEventedAutoObject Destroying, Class: TSDBTreeNode	
00008646	20:00:08.948	[3272] TEventedAutoObject Destroying, Class: TSDBTreeNode	
00008647	20:00:08.948	[3272] Events: Successfully finished event: SetMnuVisibility	
00008648	20:00:08.948	[3272] Events: Invoking event: Event_OnChangedSelection	
00008649	20:00:08.949	[3272] Events: Successfully finished event: Event_OnChangedSelection	
00008650	20:00:08.950	[3272] 3928 DB open SQL: SELECT IDView FROM NodeViews WHERE NodeType = ? 	
00008651	20:00:08.950	[3272] 3928 DB lock finished, took 287.	
00008652	20:00:08.950	[3272] 3928 DB open SQL: SELECT ID, Name, View FROM Views WHERE ID = ? 	
00008653	20:00:08.950	[3272] 3928 DB lock finished, took 246.	
00008654	20:00:08.955	[3272] Going to fill tracklist, NodeType: 13	
00008655	20:00:08.956	[3272] Going to start filling thread, FFillingThreadCnt = 14	
00008656	20:00:08.961	[3272] TGenThread.Create: ThreadName: FillingThread , Running Threads: Internal: 4, All: 57	
00008657	20:00:08.964	[3272] Thread 'FillingThread' has started 4112	
00008658	20:00:08.964	[3272] Thread registered, going to initialize 4112	
00008659	20:00:08.964	[3272] Thread initialized 4112	
00008660	20:00:08.965	[3272] Thread 'FillingThread' is going to callback	
00008661	20:00:08.969	[3272] 4112 DB open SQL: SELECT Songs.* 	
00008662	20:00:08.969	[3272]  FROM Songs WHERE Songs.ID IN (SELECT rowid FROM SongsText WHERE SongsText MATCH ' kings* of* ')  	
00008663	20:00:08.969	[3272] OpenQuery - Preparing query SELECT Songs.* 	
00008664	20:00:08.969	[3272]  FROM Songs WHERE Songs.ID IN (SELECT rowid FROM SongsText WHERE SongsText MATCH ' kings* of* ')  	
00008665	20:00:09.002	[3272] 4112 DB lock finished, took 94041.	
00008666	20:00:09.008	[3272] Going 'FillingThread'to make final callback 4112	
00008667	20:00:09.008	[3272] Thread 'FillingThread' is going to callback	
00008668	20:00:09.012	[3272] SortAlbumListPreserveSelection called	
00008669	20:00:09.012	[3272] TAlbumArtViewController::PrepareAlbumArtList - begin	
00008670	20:00:09.012	[3272] TAlbumArtViewsManager::PrepareAlbumArtList - begin	
00008671	20:00:09.012	[3272] TAlbumArtViewsManager::PrepareAlbumArtList - before fill	
00008672	20:00:09.012	[3272] TAlbumArtViewsManager::PrepareAlbumArtList - end	
00008673	20:00:09.012	[3272] TAlbumArtViewController::PrepareAlbumArtList - Albums generated	
00008674	20:00:09.012	[3272] TAlbumArtViewController::PrepareAlbumArtList - Albums sorted	
00008675	20:00:09.012	[3272] 3928 DB open SQL: SELECT IDView FROM NodeViews WHERE NodeType = ? 	
00008676	20:00:09.013	[3272] 3928 DB lock finished, took 311.	
00008677	20:00:09.013	[3272] 3928 DB open SQL: SELECT ID, Name, View FROM Views WHERE ID = ? 	
00008678	20:00:09.013	[3272] 3928 DB lock finished, took 231.	
00008679	20:00:09.013	[3272] TAlbumArtViewController::PrepareAlbumArtList - Albums groups generated	
00008680	20:00:09.014	[3272] TAlbumArtViewController::PrepareAlbumArtList - Rows computed	
00008681	20:00:09.014	[3272] TAlbumArtViewController::PrepareAlbumArtList - Albums selected	
00008682	20:00:09.014	[3272] TAlbumArtViewController::PrepareAlbumArtList - end	
00008683	20:00:09.015	[3272] TAlbumArtViewController.SelectSongs - Begin	
00008684	20:00:09.015	[3272] BQ: Added new task. Currently 1 tasks in queue.	
00008685	20:00:09.015	[3272] BQ: Starting a new task.	
00008686	20:00:09.015	[3272] BQ: There are threads waiting, resume one.	
00008687	20:00:09.073	[3272] Going 'BackgroundQueue'to make final callback 2868	
00008688	20:00:09.073	[3272] Going 'BackgroundQueue'to make final callback 4020	
00008689	20:00:09.073	[3272] Going 'BackgroundQueue'to make final callback 4812	
00008690	20:00:09.073	[3272] Thread 'BackgroundQueue'has finished 2868	
00008691	20:00:09.073	[3272] DB: Deleting prepared query: SELECT Songs.* FROM Songs WHERE Songs.IDMedia=? AND Songs.SongPath=? 	
00008692	20:00:09.073	[3272] Thread 'BackgroundQueue'has finished 4812	
00008693	20:00:09.073	[3272] Thread 'BackgroundQueue'has finished 4020	
00008694	20:00:09.079	[3272] UpdateSongPictures: C:\Users\Claude\Music\Depot\# Pop\K\Kings of Leon\Only By The Night\07 Kings of Leon - 17.mp3	
00008695	20:00:09.079	[3272] Added Cover Lists: 63	
00008696	20:00:09.079	[3272] GetFileInfo: C:\Users\Claude\Music\Depot\# Pop\K\Kings of Leon\Only By The Night\07 Kings of Leon - 17.mp3	
00008697	20:00:09.079	[3272] GetFileInfo: readPictures=spAlways	
00008698	20:00:09.079	[3272] GetFileInfo: C:\Users\Claude\Music\Depot\# Pop\K\Kings of Leon\Only By The Night\07 Kings of Leon - 17.mp3	
00008699	20:00:09.079	[3272] MP3.ReadHeader C:\Users\Claude\Music\Depot\# Pop\K\Kings of Leon\Only By The Night\07 Kings of Leon - 17.mp3	
00008700	20:00:09.079	[3272] MP3.ReadHeader - File size 4554987	
00008701	20:00:09.094	[3272] MP3.ReadHeader - Found ID3v2, length: 3900	
00008702	20:00:09.094	[3272] MP3.ReadHeader framestarts: 3910, 3910	
00008703	20:00:09.103	[3272] MP3.ReadHeader CheckMoreHeaders started	
00008704	20:00:09.103	[3272] MP3.ReadHeader CheckMoreHeaders Endtest: 6982	
00008705	20:00:09.103	[3272] MP3.ReadHeader CheckMoreHeaders finished	
00008706	20:00:09.103	[3272] MP3.ReadHeader finished	
00008707	20:00:09.103	[3272] MP3: Going to read tag from C:\Users\Claude\Music\Depot\# Pop\K\Kings of Leon\Only By The Night\07 Kings of Leon - 17.mp3	
00008708	20:00:09.108	[3272] MP3: Tag read from C:\Users\Claude\Music\Depot\# Pop\K\Kings of Leon\Only By The Night\07 Kings of Leon - 17.mp3	
00008709	20:00:09.108	[3272] 4220 DB prepare SQL: SELECT Songs.* FROM Songs WHERE Songs.IDMedia=? AND Songs.SongPath=?	
00008710	20:00:09.108	[3272] 4220 DB query prepare finished, took 485.	
00008711	20:00:09.108	[3272] 4220 DB open SQL: SELECT Songs.* FROM Songs WHERE Songs.IDMedia=? AND Songs.SongPath=? 	
00008712	20:00:09.138	[3272] 4220 DB lock finished, took 82257.	
00008713	20:00:09.138	[3272] GetFileInfo: Found in DB	
00008714	20:00:09.138	[3272] UpdateSongPictures: CoverList.LoadForSongId, C:\Users\Claude\Music\Depot\# Pop\K\Kings of Leon\Only By The Night\07 Kings of Leon - 17.mp3	
00008715	20:00:09.138	[3272] 4220 DB open SQL: SELECT * FROM Covers WHERE IDSong=57676 ORDER BY CoverOrder 	
00008716	20:00:09.138	[3272] OpenQuery - Preparing query SELECT * FROM Covers WHERE IDSong=57676 ORDER BY CoverOrder 	
00008717	20:00:09.143	[3272] TryLoadDirectlyFromDBAndCache called for track C:\Users\Claude\Music\Depot\# Pop\K\Kings of Leon\Only By The Night\07 Kings of Leon - 17.mp3	
00008718	20:00:09.149	[3272] TGenThread.Create: ThreadName: ImageReader_Var , Running Threads: Internal: 2, All: 55	
00008719	20:00:09.152	[3272] Thread 'ImageReader_Var' has started 5024	
00008720	20:00:09.152	[3272] Thread registered, going to initialize 5024	
00008721	20:00:09.152	[3272] Thread initialized 5024	
00008722	20:00:09.154	[3272] 4220 DB lock finished, took 44172.	
00008723	20:00:09.154	[3272] Added Covers: 97	
00008724	20:00:09.162	[3272] TryLoadDirectlyFromDBAndCache called for track C:\Users\Claude\Music\Depot\# Pop\K\Kings of Convenience\Declaration of Dependence\01 Kings Of Convenience - 24-25.mp3	
00008725	20:00:09.173	[3272] TryLoadDirectlyFromDBAndCache called for track C:\Users\Claude\Music\Depot\# Pop\K\Kings of Leon\Come Around Sundown\07 Kings Of Leon - Back Down South.mp3	
00008726	20:00:09.184	[3272] TryLoadDirectlyFromDBAndCache called for track C:\Users\Claude\Music\Depot\# Pop\M\Mambo Kings\16 Los Lobos - Beautiful Maria of My Sou.mp3	
00008727	20:00:09.232	[3272] StretchStart	
00008728	20:00:09.233	[3272] BQ: Added new task. Currently 1 tasks in queue.	
00008729	20:00:09.233	[3272] BQ: Starting a new task.	
00008730	20:00:09.233	[3272] BQ: Currently running 1 threads of 8	
00008731	20:00:09.233	[3272] BQ: Starting a new thread.	
00008732	20:00:09.239	[3272] TGenThread.Create: ThreadName: BackgroundQueue , Running Threads: Internal: 3, All: 56	
00008733	20:00:09.243	[3272] BQ: Added new task. Currently 2 tasks in queue.	
00008734	20:00:09.243	[3272] BQ: Starting a new task.	
00008735	20:00:09.243	[3272] BQ: Currently running 2 threads of 8	
00008736	20:00:09.243	[3272] BQ: Starting a new thread.	
00008737	20:00:09.243	[3272] Thread 'BackgroundQueue' has started 3240	
00008738	20:00:09.243	[3272] Thread registered, going to initialize 3240	
00008739	20:00:09.243	[3272] Thread initialized 3240	
00008740	20:00:09.249	[3272] TGenThread.Create: ThreadName: BackgroundQueue , Running Threads: Internal: 3, All: 57	
00008741	20:00:09.252	[3272] BQ: Added new task. Currently 3 tasks in queue.	
00008742	20:00:09.252	[3272] BQ: Starting a new task.	
00008743	20:00:09.252	[3272] BQ: Currently running 3 threads of 8	
00008744	20:00:09.252	[3272] BQ: Starting a new thread.	
00008745	20:00:09.253	[3272] Thread 'BackgroundQueue' has started 2936	
00008746	20:00:09.253	[3272] Thread registered, going to initialize 2936	
00008747	20:00:09.253	[3272] Thread initialized 2936	
00008748	20:00:09.259	[3272] TGenThread.Create: ThreadName: BackgroundQueue , Running Threads: Internal: 4, All: 58	
00008749	20:00:09.262	[3272] StretchEnd	
00008750	20:00:09.263	[3272] Thread 'BackgroundQueue' has started 2092	
00008751	20:00:09.263	[3272] Thread registered, going to initialize 2092	
00008752	20:00:09.263	[3272] Thread initialized 2092	
00008753	20:00:09.264	[3272] Remaining Covers: 96	
00008754	20:00:09.264	[3272] BQ: Added new task. Currently 1 tasks in queue.	
00008755	20:00:09.264	[3272] BQ: Starting a new task.	
00008756	20:00:09.264	[3272] BQ: There are threads waiting, resume one.	
00008757	20:00:09.346	[3272] StretchStart	
00008758	20:00:09.347	[3272] BQ: Added new task. Currently 1 tasks in queue.	
00008759	20:00:09.347	[3272] BQ: Starting a new task.	
00008760	20:00:09.347	[3272] BQ: There are threads waiting, resume one.	
00008761	20:00:09.347	[3272] BQ: Added new task. Currently 2 tasks in queue.	
00008762	20:00:09.347	[3272] BQ: Starting a new task.	
00008763	20:00:09.347	[3272] BQ: There are threads waiting, resume one.	
00008764	20:00:09.347	[3272] BQ: Added new task. Currently 2 tasks in queue.	
00008765	20:00:09.347	[3272] BQ: Starting a new task.	
00008766	20:00:09.347	[3272] BQ: There are threads waiting, resume one.	
00008767	20:00:09.350	[3272] StretchEnd	
00008768	20:00:09.411	[3272] Added Cover Lists: 64	
00008769	20:00:09.416	[3272] TAlbumArtViewController.SelectSongs - End	
00008770	20:00:09.417	[3272] 5024 DB prepare SQL: SELECT Covers.* FROM Covers, Songs WHERE songs.idalbum=? AND covers.idsong=songs.id ORDER BY Covers.idsong	
00008771	20:00:09.418	[3272] 3928 DB open SQL: SELECT IDView FROM NodeViews WHERE NodeType = ? 	
00008772	20:00:09.419	[3272] 5024 DB query prepare finished, took 202.	
00008773	20:00:09.419	[3272] 3928 DB lock finished, took 368.	
00008774	20:00:09.420	[3272] 5024 DB open SQL: SELECT Covers.* FROM Covers, Songs WHERE songs.idalbum=? AND covers.idsong=songs.id ORDER BY Covers.idsong 	
00008775	20:00:09.421	[3272] 3928 DB open SQL: SELECT ID, Name, View FROM Views WHERE ID = ? 	
00008776	20:00:09.421	[3272] 5024 DB lock finished, took 872.	
00008777	20:00:09.422	[3272] 3928 DB lock finished, took 54.	
00008778	20:00:09.422	[3272] Added Covers: 97	
00008779	20:00:09.423	[3272] 3928 DB open SQL: SELECT IDView FROM NodeViews WHERE NodeType = ? 	
00008780	20:00:09.424	[3272] Added Covers: 98	
00008781	20:00:09.424	[3272] 3928 DB lock finished, took 254.	
00008782	20:00:09.425	[3272] 3928 DB open SQL: SELECT ID, Name, View FROM Views WHERE ID = ? 	
00008783	20:00:09.426	[3272] 3928 DB lock finished, took 271.	
00008784	20:00:09.426	[3272] Thread 'FillingThread'has finished 4112	
00008785	20:00:09.430	[3272] TryLoadDirectlyFromDBAndCache called for track C:\Users\Claude\Music\Depot\# Pop\K\Kings of Leon\Only By The Night\07 Kings of Leon - 17.mp3	
00008786	20:00:09.430	[3272] TryLoadDirectlyFromDBAndCache - force load from cache C:\Users\Claude\AppData\Local\Temp\MMCache1087777978_1\07 Kings of Leon - 17-VCBM73X69MPP57I5F6HB5492Q - JQWI51UJKNZGNU1GRXB4SDXWY7120.bmp	
00008787	20:00:09.430	[3272] Added Covers: 99	
00008788	20:00:12.350	[3272] Going 'BackgroundQueue'to make final callback 4220	
00008789	20:00:12.350	[3272] Going 'BackgroundQueue'to make final callback 2092	
00008790	20:00:12.350	[3272] Going 'BackgroundQueue'to make final callback 3240	
00008791	20:00:12.350	[3272] DB: Deleting prepared query: SELECT Songs.* FROM Songs WHERE Songs.IDMedia=? AND Songs.SongPath=? 	
00008792	20:00:12.350	[3272] Thread 'BackgroundQueue'has finished 2092	
00008793	20:00:12.350	[3272] Thread 'BackgroundQueue'has finished 3240	
00008794	20:00:12.350	[3272] Thread 'BackgroundQueue'has finished 4220	
00008795	20:00:12.371	[3272] Going 'BackgroundQueue'to make final callback 2936	
00008796	20:00:12.371	[3272] Thread 'BackgroundQueue'has finished 2936	
00008797	20:03:10.450	[3272] INWMP3: OnStatus 6.	
00008798	20:03:10.600	[3272] INWMP3: OnStatus 4.	
00008799	20:03:10.790	[3272] INWMP3: OnEndOfStream	
00008800	20:03:16.081	[3272] INWMP3: Going to stop (286333; 279602)	
00008801	20:03:16.081	[3272] INWMP3: Stopping (286333; 279602)

The freeze happens at or after

00008796 20:00:12.371 [3272] Thread 'BackgroundQueue'has finished 2936. The last five entries are generated when the song finishes, of course.

Ludek · Post by **Ludek** » Tue Oct 15, 2013 4:11 pm

Thank you, I found the ELF that you've sent.

But I see in the log that it is not related to a search, but the freeze happened after approving "Locate Moved or Missing files" dialog.
Can you confirm it?

I see a problem there that I am going to fix, tracked here: http://www.ventismedia.com/mantis/view.php?id=11369

hintergrundrauschen · Fri Oct 18, 2013 12:36 pm

Ludek wrote:But I see in the log that it is not related to a search, but the freeze happened after approving "Locate Moved or Missing files" dialog.
Can you confirm it?

No, definitely. I have not used this option for weeks. I don't use any shortcut that might trigger this function. I have been reproducing this error several times after just starting up MM, starting to play music, and then executing several quick searches. If there's not some weird sort of ghost process of this function hiding in some temporary configuration file for weeks I have no idea how this might be possible...

Ludek · Post by **Ludek** » Mon Oct 21, 2013 5:02 am

In the log privided here I saw that you searched for "kings of" and it found files like
C:\Users\Claude\Music\Depot\# Pop\K\Kings of Leon\Only By The Night\07 Kings of Leon - 17.mp3

But I haven't seen a freeze. What do you mean by "freeze"? I guess that UI is still responsive, isn't it?

hintergrundrauschen · Post by **hintergrundrauschen** » Wed Oct 23, 2013 1:21 pm

Ludek wrote:In the log privided here I saw that you searched for "kings of" and it found files like
C:\Users\Claude\Music\Depot\# Pop\K\Kings of Leon\Only By The Night\07 Kings of Leon - 17.mp3

Yes.

Ludek wrote:But I haven't seen a freeze. What do you mean by "freeze"? I guess that UI is still responsive, isn't it?

No, UI is not responsive.In Win7, the mouse cursor becomes a blue, turning circle. The MM main window gets a white milk glass layer on top of it and will not respond to any interaction. In fact, mouse clicking will make Win7 system pop up a window telling me that the application does not respond. Hovering on top of the task bar MM window entry will pop up the regular mini window with album art and simple controls, but clicking on any won't do anything. As described before, the currently played song keeps playing regularly till its end. After that, MM stops playing.

Ludek · Post by **Ludek** » Wed Oct 23, 2013 5:59 pm

hintergrundrauschen wrote: No, UI is not responsive.In Win7, the mouse cursor becomes a blue, turning circle. The MM main window gets a white milk glass layer on top of it and will not respond to any interaction. In fact, mouse clicking will make Win7 system pop up a window telling me that the application does not respond. Hovering on top of the task bar MM window entry will pop up the regular mini window with album art and simple controls, but clicking on any won't do anything. As described before, the currently played song keeps playing regularly till its end. After that, MM stops playing.

Ok, so I suppose that MM throws the "Send error" dialogs to auto-send the crash log after 30 seconds of the UI freeze, isn't it? The previous that I found from you was related to http://www.ventismedia.com/mantis/view.php?id=11369.

Could you re-send it and type here when you send it and which build you tested, thank you.

hintergrundrauschen · Sat Oct 26, 2013 12:45 pm

Just sent another error report, running latest beta.

Also, MM crashed before, once, after giving the command to rename a whole album while playing it. Didn't get an error report,wasn't running dbgview, either.

Ludek · Post by **Ludek** » Tue Oct 29, 2013 10:59 am

I've watched logs from build 1667, but I can't seem to find your log there, what is your user name on the computer? Is it "hintergrundrauschen" ? I remember I saw that in the original crash log, but I cannot find sych a username between 1667 logs.

Also, how large is your database? Would you mind to compress the database file and post it to me so that I could try to simulate the issue?

Probably also complete log generate using DbgView (saved to file) could show more.

hintergrundrauschen · Post by **hintergrundrauschen** » Sat Nov 09, 2013 2:04 pm

Still happening on 1670. I don't know what conditions lead to a crash report, but I can't always wait for 5-15+ mins for the song to end, if that's a prerequisite.

I will try to upload my db as requested tomorrow.

Code: Select all


00104055	19:49:42.182	[1240] 4884 DB open SQL: SELECT Songs.* FROM Songs WHERE Songs.IDMedia=? AND Songs.SongPath=? 	
00104056	19:49:42.231	[1240] 4884 DB lock finished, took 46262.	
00104057	19:49:42.232	[1240] GetFileInfo: Found in DB	
00104058	19:49:42.232	[1240] UpdateSongPictures: CoverList.LoadForSongId, C:\Users\Claude\Music\Depot\# Pop\# VA\Unity - Athens 2004\Sting - A Thousand Years (feat. Mariza).mp3	
00104059	19:49:42.232	[1240] 4884 DB open SQL: SELECT * FROM Covers WHERE IDSong=1467 ORDER BY CoverOrder 	
00104060	19:49:42.232	[1240] OpenQuery - Preparing query SELECT * FROM Covers WHERE IDSong=1467 ORDER BY CoverOrder 	
00104061	19:49:42.233	[1240] 4884 DB lock finished, took 653.	
00104062	19:49:42.233	[1240] Added Covers: 152	
00104063	19:49:42.233	[1240] Remaining Covers: 151	
00104064	19:49:42.233	[1240] Added Covers: 152	
00104065	19:49:42.233	[1240] Remaining Covers: 151	
00104066	19:49:42.233	[1240] Remaining Cover Lists: 93	
00104067	19:49:42.233	[1240] Added Cover Lists: 94	
00104068	19:49:42.233	[1240] Added Covers: 152	
00104069	19:49:42.233	[1240] Added Covers: 153	
00104070	19:49:42.233	[1240] Remaining Covers: 152	
00104071	19:49:42.233	[1240] Remaining Covers: 151	
00104072	19:49:42.233	[1240] Remaining Cover Lists: 93	
00104073	19:49:42.233	[1240] Added Cover Lists: 94	
00104074	19:49:42.233	[1240] Added Covers: 152	
00104075	19:49:42.233	[1240] Added Covers: 153	
00104076	19:49:42.233	[1240] Track comparison failed: "Unity: Athens 2004"<>"Rhythms del Mundo" | Field: 2	
00104077	19:49:42.233	[1240] Track comparison failed: "A Thousand Years (feat. Mariza)"<>"Fragilidad" | Field: 0	
00104078	19:49:42.233	[1240] Track comparison failed: "Pop"<>"Latin" | Field: 6	
00104079	19:49:42.233	[1240] Track comparison failed: "05"<>"11" | Field: 9	
00104080	19:49:42.233	[1240] Track comparison failed: "Virgin/EMI TV"<>"" | Field: 60	
00104081	19:49:42.233	[1240] 4884 DB open SQL: SELECT PreviewStartTime, PreviewLength, CacheName, PreviewName, Copyright, Encoder, ISRC, InitialKey, Language, OrigLyricist, ParentalRating,PreGap, PostGap, TotalSamples, GaplessBytes, SignType, SignPart1, SignPart2, SignPart3, SignPart4, ContainerType, StreamCount, StreamInfo FROM Songs WHERE ID=? 	
00104082	19:49:42.234	[1240] 4884 DB lock finished, took 324.	
00104083	19:49:42.234	[1240] Remaining Covers: 152	
00104084	19:49:42.234	[1240] Remaining Covers: 151	
00104085	19:49:42.234	[1240] Remaining Cover Lists: 93	
00104086	19:49:42.234	[1240] Remaining Covers: 150	
00104087	19:49:42.234	[1240] Going 'ImageReader_Var'to make final callback 4884	
00104088	19:49:42.234	[1240] DB: Deleting prepared query: SELECT Covers.* FROM Covers, Songs WHERE songs.idalbum=? AND covers.idsong=songs.id ORDER BY Covers.idsong 	
00104089	19:49:42.234	[1240] DB: Deleting prepared query: SELECT PreviewStartTime, PreviewLength, CacheName, PreviewName, Copyright, Encoder, ISRC, InitialKey, Language, OrigLyricist, ParentalRating,PreGap, PostGap, TotalSamples, GaplessBytes, SignType, SignPart1, SignPart2, SignPart3, SignPart4, ContainerType, StreamCount, StreamInfo FROM Songs WHERE ID=? 	
00104090	19:49:42.234	[1240] DB: Deleting prepared query: SELECT Songs.* FROM Songs WHERE Songs.IDMedia=? AND Songs.SongPath=? 	
00104091	19:49:42.234	[1240] Thread 'ImageReader_Var'has finished 4884	
00104092	19:49:42.296	[1240] StretchStart	
00104093	19:49:42.297	[1240] BQ: Added new task. Currently 1 tasks in queue.	
00104094	19:49:42.297	[1240] BQ: Starting a new task.	
00104095	19:49:42.297	[1240] BQ: There are threads waiting, resume one.	
00104096	19:49:42.297	[1240] BQ: Added new task. Currently 2 tasks in queue.	
00104097	19:49:42.297	[1240] BQ: Starting a new task.	
00104098	19:49:42.297	[1240] BQ: There are threads waiting, resume one.	
00104099	19:49:42.297	[1240] BQ: Added new task. Currently 2 tasks in queue.	
00104100	19:49:42.298	[1240] BQ: Starting a new task.	
00104101	19:49:42.298	[1240] BQ: There are threads waiting, resume one.	
00104102	19:49:42.306	[1240] StretchEnd	
00104103	19:49:42.336	[1240] StretchStart	
00104104	19:49:42.336	[1240] BQ: Added new task. Currently 1 tasks in queue.	
00104105	19:49:42.336	[1240] BQ: Starting a new task.	
00104106	19:49:42.336	[1240] BQ: There are threads waiting, resume one.	
00104107	19:49:42.336	[1240] BQ: Added new task. Currently 2 tasks in queue.	
00104108	19:49:42.336	[1240] BQ: Starting a new task.	
00104109	19:49:42.337	[1240] BQ: There are threads waiting, resume one.	
00104110	19:49:42.337	[1240] BQ: Added new task. Currently 2 tasks in queue.	
00104111	19:49:42.337	[1240] BQ: Starting a new task.	
00104112	19:49:42.337	[1240] BQ: There are threads waiting, resume one.	
00104113	19:49:42.339	[1240] StretchEnd	
00104114	19:49:42.386	[1240] StretchStart	
00104115	19:49:42.386	[1240] BQ: Added new task. Currently 1 tasks in queue.	
00104116	19:49:42.386	[1240] BQ: Starting a new task.	
00104117	19:49:42.387	[1240] BQ: There are threads waiting, resume one.	
00104118	19:49:42.387	[1240] BQ: Added new task. Currently 2 tasks in queue.	
00104119	19:49:42.387	[1240] BQ: Starting a new task.	
00104120	19:49:42.387	[1240] BQ: There are threads waiting, resume one.	
00104121	19:49:42.387	[1240] BQ: Added new task. Currently 2 tasks in queue.	
00104122	19:49:42.387	[1240] BQ: Starting a new task.	
00104123	19:49:42.387	[1240] BQ: There are threads waiting, resume one.	
00104124	19:49:42.391	[1240] StretchEnd	
00104125	19:49:42.422	[1240] StretchStart	
00104126	19:49:42.422	[1240] BQ: Added new task. Currently 1 tasks in queue.	
00104127	19:49:42.422	[1240] BQ: Starting a new task.	
00104128	19:49:42.422	[1240] BQ: There are threads waiting, resume one.	
00104129	19:49:42.422	[1240] BQ: Added new task. Currently 2 tasks in queue.	
00104130	19:49:42.422	[1240] BQ: Starting a new task.	
00104131	19:49:42.422	[1240] BQ: There are threads waiting, resume one.	
00104132	19:49:42.423	[1240] BQ: Added new task. Currently 2 tasks in queue.	
00104133	19:49:42.423	[1240] BQ: Starting a new task.	
00104134	19:49:42.423	[1240] BQ: There are threads waiting, resume one.	
00104135	19:49:42.426	[1240] StretchEnd	
00104136	19:49:45.391	[1240] Going 'BackgroundQueue'to make final callback 3468	
00104137	19:49:45.391	[1240] Thread 'BackgroundQueue'has finished 3468	
00104138	19:49:45.426	[1240] Going 'BackgroundQueue'to make final callback 5912	
00104139	19:49:45.426	[1240] Going 'BackgroundQueue'to make final callback 6864	
00104140	19:49:45.426	[1240] Going 'BackgroundQueue'to make final callback 4432	
00104141	19:49:45.426	[1240] Thread 'BackgroundQueue'has finished 5912	
00104142	19:49:45.426	[1240] Thread 'BackgroundQueue'has finished 6864	
00104143	19:49:45.427	[1240] DB: Deleting prepared query: SELECT Songs.* FROM Songs WHERE Songs.IDMedia=? AND Songs.SongPath=? 	
00104144	19:49:45.427	[1240] Thread 'BackgroundQueue'has finished 4432	
00104145	19:49:46.519	[1240] TGenThread.Create: ThreadName: UpdateDriveLetters_Var , Running Threads: Internal: 0, All: 50	
00104146	19:49:46.525	[1240] PostponeComputerSleep: Enabled = 0	
00104147	19:49:46.526	[1240] Thread 'UpdateDriveLetters_Var' has started 7116	
00104148	19:49:46.526	[1240] Thread registered, going to initialize 7116	
00104149	19:49:46.526	[1240] Thread initialized 7116	
00104150	19:49:46.526	[1240] >UpdateDriveLetters - start<	
00104151	19:49:46.540	[1240] >UpdateDriveLetters - end<	
00104152	19:49:46.540	[1240] Going 'UpdateDriveLetters_Var'to make final callback 7116	
00104153	19:49:46.540	[1240] Thread 'UpdateDriveLetters_Var'has finished 7116	
00104154	19:49:53.934	[1240] TGenThread.Create: ThreadName: Fill_Var , Running Threads: Internal: 0, All: 50	
00104155	19:49:53.939	[1240] Thread 'Fill_Var' has started 5620	
00104156	19:49:53.940	[1240] Thread registered, going to initialize 5620	
00104157	19:49:53.940	[1240] Thread initialized 5620	
00104158	19:49:53.940	[1240] ComboHelper::FillThread - lastPart = "f"; len = 1	
00104159	19:49:53.940	[1240] Thread 'Fill_Var' is going to callback	
00104160	19:49:53.945	[1240] Winamp Playlist sim - message 0 left to the default processing	
00104161	19:49:53.945	[1240] Winamp simulation window received messsage 0	
00104162	19:49:53.946	[1240] Going 'Fill_Var'to make final callback 5620	
00104163	19:49:53.946	[1240] Thread 'Fill_Var' is going to callback	
00104164	19:49:53.946	[1240] Thread 'Fill_Var'has finished 5620	
00104165	19:49:54.054	[1240] TGenThread.Create: ThreadName: Fill_Var , Running Threads: Internal: 0, All: 50	
00104166	19:49:54.058	[1240] Thread 'Fill_Var' has started 7076	
00104167	19:49:54.058	[1240] Thread registered, going to initialize 7076	
00104168	19:49:54.059	[1240] Thread initialized 7076	
00104169	19:49:54.059	[1240] ComboHelper::FillThread - lastPart = "fu"; len = 2	
00104170	19:49:54.059	[1240] Thread 'Fill_Var' is going to callback	
00104171	19:49:54.065	[1240] Winamp Playlist sim - message 0 left to the default processing	
00104172	19:49:54.065	[1240] Winamp simulation window received messsage 0	
00104173	19:49:54.066	[1240] Going 'Fill_Var'to make final callback 7076	
00104174	19:49:54.066	[1240] Thread 'Fill_Var' is going to callback	
00104175	19:49:54.066	[1240] Thread 'Fill_Var'has finished 7076	
00104176	19:49:54.221	[1240] TGenThread.Create: ThreadName: Fill_Var , Running Threads: Internal: 0, All: 50	
00104177	19:49:54.229	[1240] Thread 'Fill_Var' has started 6196	
00104178	19:49:54.229	[1240] Thread registered, going to initialize 6196	
00104179	19:49:54.229	[1240] Thread initialized 6196	
00104180	19:49:54.229	[1240] ComboHelper::FillThread - lastPart = "fun"; len = 3	
00104181	19:49:54.229	[1240] Thread 'Fill_Var' is going to callback	
00104182	19:49:54.236	[1240] Winamp Playlist sim - message 0 left to the default processing	
00104183	19:49:54.236	[1240] Winamp simulation window received messsage 0	
00104184	19:49:54.237	[1240] Going 'Fill_Var'to make final callback 6196	
00104185	19:49:54.237	[1240] Thread 'Fill_Var' is going to callback	
00104186	19:49:54.237	[1240] Thread 'Fill_Var'has finished 6196	
00104187	19:49:54.365	[1240] TGenThread.Create: ThreadName: Fill_Var , Running Threads: Internal: 0, All: 50	
00104188	19:49:54.372	[1240] Thread 'Fill_Var' has started 5388	
00104189	19:49:54.372	[1240] Thread registered, going to initialize 5388	
00104190	19:49:54.373	[1240] Thread initialized 5388	
00104191	19:49:54.373	[1240] ComboHelper::FillThread - lastPart = "funk"; len = 4	
00104192	19:49:54.373	[1240] Thread 'Fill_Var' is going to callback	
00104193	19:49:54.383	[1240] Winamp Playlist sim - message 0 left to the default processing	
00104194	19:49:54.383	[1240] Winamp simulation window received messsage 0	
00104195	19:49:54.384	[1240] Going 'Fill_Var'to make final callback 5388	
00104196	19:49:54.384	[1240] Thread 'Fill_Var' is going to callback	
00104197	19:49:54.384	[1240] Thread 'Fill_Var'has finished 5388	
00104198	19:49:54.502	[1240] TGenThread.Create: ThreadName: Fill_Var , Running Threads: Internal: 0, All: 50	
00104199	19:49:54.507	[1240] Thread 'Fill_Var' has started 4136	
00104200	19:49:54.507	[1240] Thread registered, going to initialize 4136	
00104201	19:49:54.507	[1240] Thread initialized 4136	
00104202	19:49:54.507	[1240] ComboHelper::FillThread - lastPart = "funk "; len = 5	
00104203	19:49:54.507	[1240] Thread 'Fill_Var' is going to callback	
00104204	19:49:54.510	[1240] Winamp Playlist sim - message 0 left to the default processing	
00104205	19:49:54.510	[1240] Winamp simulation window received messsage 0	
00104206	19:49:54.513	[1240] Going 'Fill_Var'to make final callback 4136	
00104207	19:49:54.513	[1240] Thread 'Fill_Var' is going to callback	
00104208	19:49:54.513	[1240] Thread 'Fill_Var'has finished 4136	
00104209	19:49:54.711	[1240] TGenThread.Create: ThreadName: Fill_Var , Running Threads: Internal: 0, All: 50	
00104210	19:49:54.717	[1240] Thread 'Fill_Var' has started 5752	
00104211	19:49:54.717	[1240] Thread registered, going to initialize 5752	
00104212	19:49:54.717	[1240] Thread initialized 5752	
00104213	19:49:54.717	[1240] ComboHelper::FillThread - lastPart = "funk o"; len = 6	
00104214	19:49:54.717	[1240] Thread 'Fill_Var' is going to callback	
00104215	19:49:54.723	[1240] Winamp Playlist sim - message 0 left to the default processing	
00104216	19:49:54.723	[1240] Winamp simulation window received messsage 0	
00104217	19:49:54.723	[1240] Going 'Fill_Var'to make final callback 5752	
00104218	19:49:54.723	[1240] Thread 'Fill_Var' is going to callback	
00104219	19:49:54.723	[1240] Thread 'Fill_Var'has finished 5752	
00104220	19:49:55.007	[1240] TGenThread.Create: ThreadName: Fill_Var , Running Threads: Internal: 0, All: 50	
00104221	19:49:55.014	[1240] Thread 'Fill_Var' has started 6832	
00104222	19:49:55.014	[1240] Thread registered, going to initialize 6832	
00104223	19:49:55.014	[1240] Thread initialized 6832	
00104224	19:49:55.014	[1240] ComboHelper::FillThread - lastPart = "funk od"; len = 7	
00104225	19:49:55.014	[1240] Thread 'Fill_Var' is going to callback	
00104226	19:49:55.019	[1240] Winamp Playlist sim - message 0 left to the default processing	
00104227	19:49:55.019	[1240] Winamp simulation window received messsage 0	
00104228	19:49:55.020	[1240] Going 'Fill_Var'to make final callback 6832	
00104229	19:49:55.020	[1240] Thread 'Fill_Var' is going to callback	
00104230	19:49:55.020	[1240] Thread 'Fill_Var'has finished 6832	
00104231	19:49:55.511	[1240] Events: Invoking event: OnChangedSelection	
00104232	19:49:55.511	[1240] Events: Successfully finished event: OnChangedSelection	
00104233	19:49:55.512	[1240] Remaining Cover Lists: 92	
00104234	19:49:55.526	[1240] Node Beinhaltet: "sting" going to clear SongList.	
00104235	19:49:55.593	[1240] TGenThread.Create: ThreadName: Fill_Var , Running Threads: Internal: 0, All: 50	
00104236	19:49:55.597	[1240] Thread 'Fill_Var' has started 6812	
00104237	19:49:55.597	[1240] Thread registered, going to initialize 6812	
00104238	19:49:55.597	[1240] Thread initialized 6812	
00104239	19:49:55.597	[1240] ComboHelper::FillThread - lastPart = "funk ody"; len = 8	
00104240	19:49:55.597	[1240] Thread 'Fill_Var' is going to callback	
00104241	19:49:55.606	[1240] Winamp Playlist sim - message 0 left to the default processing	
00104242	19:49:55.607	[1240] Winamp simulation window received messsage 0	
00104243	19:49:55.618	[1240] Going 'Fill_Var'to make final callback 6812	
00104244	19:49:55.618	[1240] Thread 'Fill_Var' is going to callback	
00104245	19:49:55.618	[1240] Thread 'Fill_Var'has finished 6812	
00104246	19:49:55.802	[1240] Node Beinhaltet: "funk od" starting.	
00104247	19:49:55.802	[1240] Node Beinhaltet: "funk od" going to clear SongList.	
00104248	19:49:55.803	[1240] Events: Invoking event: OnChangedSelection	
00104249	19:49:55.804	[1240] Events: Successfully finished event: OnChangedSelection	
00104250	19:49:55.806	[1240] 1408 DB open SQL: SELECT IDView FROM NodeViews WHERE NodeType = ? 	
00104251	19:49:55.807	[1240] 1408 DB lock finished, took 575.	
00104252	19:49:55.807	[1240] 1408 DB open SQL: SELECT ID, Name, View FROM Views WHERE ID = ? 	
00104253	19:49:55.807	[1240] 1408 DB lock finished, took 451.	
00104254	19:49:55.826	[1240] Going to fill tracklist, NodeType: 13	
00104255	19:49:55.826	[1240] Going to start filling thread, FFillingThreadCnt = 20	
00104256	19:49:55.834	[1240] TGenThread.Create: ThreadName: FillingThread , Running Threads: Internal: 0, All: 50	
00104257	19:49:55.838	[1240] Thread 'FillingThread' has started 4448	
00104258	19:49:55.839	[1240] Thread registered, going to initialize 4448	
00104259	19:49:55.839	[1240] Thread initialized 4448	
00104260	19:49:55.839	[1240] Thread 'FillingThread' is going to callback	
00104261	19:49:55.845	[1240] 4448 DB open SQL: SELECT Songs.* 	
00104262	19:49:55.845	[1240]  FROM Songs WHERE Songs.ID IN (SELECT rowid FROM SongsText WHERE SongsText MATCH ' funk* od* ')  	
00104263	19:49:55.845	[1240] OpenQuery - Preparing query SELECT Songs.* 	
00104264	19:49:55.845	[1240]  FROM Songs WHERE Songs.ID IN (SELECT rowid FROM SongsText WHERE SongsText MATCH ' funk* od* ')  	
00104265	19:49:55.854	[1240] TGenThread.Create: ThreadName: Fill_Var , Running Threads: Internal: 1, All: 51	
00104266	19:49:55.858	[1240] Thread 'Fill_Var' has started 5512	
00104267	19:49:55.858	[1240] Thread registered, going to initialize 5512	
00104268	19:49:55.858	[1240] Thread initialized 5512	
00104269	19:49:55.858	[1240] ComboHelper::FillThread - lastPart = "funk odys"; len = 9	
00104270	19:49:55.858	[1240] Thread 'Fill_Var' is going to callback	
00104271	19:49:55.862	[1240] Winamp Playlist sim - message 0 left to the default processing	
00104272	19:49:55.862	[1240] Winamp simulation window received messsage 0	
00104273	19:49:55.864	[1240] 4448 DB lock finished, took 44808.	
00104274	19:49:55.866	[1240] Going 'FillingThread'to make final callback 4448	
00104275	19:49:55.866	[1240] Thread 'FillingThread' is going to callback	
00104276	19:49:55.872	[1240] SortAlbumListPreserveSelection called	
00104277	19:49:55.872	[1240] TAlbumArtViewController::PrepareAlbumArtList - begin	
00104278	19:49:55.872	[1240] TAlbumArtViewsManager::PrepareAlbumArtList - begin	
00104279	19:49:55.872	[1240] TAlbumArtViewsManager::PrepareAlbumArtList - before fill	
00104280	19:49:55.872	[1240] TAlbumArtViewsManager::PrepareAlbumArtList - end	
00104281	19:49:55.872	[1240] TAlbumArtViewController::PrepareAlbumArtList - Albums generated	
00104282	19:49:55.872	[1240] TAlbumArtViewController::PrepareAlbumArtList - Albums sorted	
00104283	19:49:55.872	[1240] 1408 DB open SQL: SELECT IDView FROM NodeViews WHERE NodeType = ? 	
00104284	19:49:55.873	[1240] 1408 DB lock finished, took 318.	
00104285	19:49:55.873	[1240] 1408 DB open SQL: SELECT ID, Name, View FROM Views WHERE ID = ? 	
00104286	19:49:55.873	[1240] 1408 DB lock finished, took 258.	
00104287	19:49:55.874	[1240] TAlbumArtViewController::PrepareAlbumArtList - Albums groups generated	
00104288	19:49:55.874	[1240] TAlbumArtViewController::PrepareAlbumArtList - Rows computed	
00104289	19:49:55.874	[1240] TAlbumArtViewController::PrepareAlbumArtList - Albums selected	
00104290	19:49:55.874	[1240] TAlbumArtViewController::PrepareAlbumArtList - end	
00104291	19:49:55.874	[1240] TAlbumArtViewController.SelectSongs - Begin	
00104292	19:49:55.875	[1240] BQ: Added new task. Currently 1 tasks in queue.	
00104293	19:49:55.875	[1240] BQ: Starting a new task.	
00104294	19:49:55.875	[1240] BQ: Currently running 0 threads of 8	
00104295	19:49:55.875	[1240] BQ: Starting a new thread.	
00104296	19:49:55.895	[1240] TGenThread.Create: ThreadName: BackgroundQueue , Running Threads: Internal: 2, All: 52	
00104297	19:49:55.895	[1240] Thread 'BackgroundQueue' has started 4736	
00104298	19:49:55.895	[1240] Thread registered, going to initialize 4736	
00104299	19:49:55.896	[1240] Thread initialized 4736	
00104300	19:49:55.945	[1240] UpdateSongPictures: C:\Users\Claude\Music\Depot\# Pop\I-J\Jamiroquai\A Funk Odyssey\Jamiroquai - Feel So Good.mp3	
00104301	19:49:55.945	[1240] Added Cover Lists: 93	
00104302	19:49:55.945	[1240] GetFileInfo: C:\Users\Claude\Music\Depot\# Pop\I-J\Jamiroquai\A Funk Odyssey\Jamiroquai - Feel So Good.mp3	
00104303	19:49:55.945	[1240] GetFileInfo: readPictures=spAlways	
00104304	19:49:55.945	[1240] GetFileInfo: C:\Users\Claude\Music\Depot\# Pop\I-J\Jamiroquai\A Funk Odyssey\Jamiroquai - Feel So Good.mp3	
00104305	19:49:55.945	[1240] MP3.ReadHeader C:\Users\Claude\Music\Depot\# Pop\I-J\Jamiroquai\A Funk Odyssey\Jamiroquai - Feel So Good.mp3	
00104306	19:49:55.945	[1240] MP3.ReadHeader - File size 6987126	
00104307	19:49:55.959	[1240] MP3.ReadHeader - Found ID3v2, length: 17184	
00104308	19:49:55.968	[1240] MP3.ReadHeader framestarts: 17194, 17194	
00104309	19:49:55.976	[1240] MP3.ReadHeader finished	
00104310	19:49:55.977	[1240] MP3: Going to read tag from C:\Users\Claude\Music\Depot\# Pop\I-J\Jamiroquai\A Funk Odyssey\Jamiroquai - Feel So Good.mp3	
00104311	19:49:55.978	[1240] TGenThread.Create: ThreadName: Fill_Var , Running Threads: Internal: 3, All: 53	
00104312	19:49:55.981	[1240] Added Covers: 151	
00104313	19:49:55.981	[1240] MP3: Tag read from C:\Users\Claude\Music\Depot\# Pop\I-J\Jamiroquai\A Funk Odyssey\Jamiroquai - Feel So Good.mp3	
00104314	19:49:55.981	[1240] 4736 DB prepare SQL: SELECT Songs.* FROM Songs WHERE Songs.IDMedia=? AND Songs.SongPath=?	
00104315	19:49:55.982	[1240] 4736 DB query prepare finished, took 552.	
00104316	19:49:55.982	[1240] 4736 DB open SQL: SELECT Songs.* FROM Songs WHERE Songs.IDMedia=? AND Songs.SongPath=? 	
00104317	19:49:55.982	[1240] Thread 'Fill_Var' has started 6652	
00104318	19:49:55.982	[1240] Thread registered, going to initialize 6652	
00104319	19:49:55.982	[1240] Thread initialized 6652	
00104320	19:49:55.982	[1240] ComboHelper::FillThread - lastPart = "funk odyss"; len = 10	
00104321	19:49:55.982	[1240] Thread 'Fill_Var' is going to callback	
00104322	19:49:55.987	[1240] TryLoadDirectlyFromDBAndCache called for track C:\Users\Claude\Music\Depot\# Pop\I-J\Jamiroquai\A Funk Odyssey\Jamiroquai - Feel So Good.mp3	
00104323	19:49:55.995	[1240] TGenThread.Create: ThreadName: ImageReader_Var , Running Threads: Internal: 4, All: 54	
00104324	19:49:55.997	[1240] 4736 DB lock finished, took 35463.	
00104325	19:49:55.998	[1240] GetFileInfo: Found in DB	
00104326	19:49:55.999	[1240] UpdateSongPictures: CoverList.LoadForSongId, C:\Users\Claude\Music\Depot\# Pop\I-J\Jamiroquai\A Funk Odyssey\Jamiroquai - Feel So Good.mp3	
00104327	19:49:55.999	[1240] 4736 DB open SQL: SELECT * FROM Covers WHERE IDSong=6239 ORDER BY CoverOrder 	
00104328	19:49:55.999	[1240] OpenQuery - Preparing query SELECT * FROM Covers WHERE IDSong=6239 ORDER BY CoverOrder 	
00104329	19:49:56.000	[1240] 4736 DB lock finished, took 721.	
00104330	19:49:56.000	[1240] Added Covers: 152	
00104331	19:49:56.000	[1240] Thread 'ImageReader_Var' has started 6716	
00104332	19:49:56.000	[1240] Remaining Covers: 151	
00104333	19:49:56.000	[1240] Thread registered, going to initialize 6716	
00104334	19:49:56.000	[1240] Added Covers: 152	
00104335	19:49:56.000	[1240] Thread initialized 6716	
00104336	19:49:56.011	[1240] TryLoadDirectlyFromDBAndCache called for track C:\Users\Claude\Music\Depot\# Soundtracks\GTA SA Official\BOUNCE FM\Johnny Harris - Odyssey.mp3	
00104337	19:49:56.017	[1240] TryLoadDirectlyFromDBAndCache called for track C:\Users\Claude\Music\Depot\# Exoten\GTA SA\Bounce\Johnny Harris - Odyssey.mp3	
00104338	19:49:56.027	[1240] Winamp Playlist sim - message 0 left to the default processing	
00104339	19:49:56.027	[1240] Winamp simulation window received messsage 0	
00104340	19:49:56.046	[1240] Going 'Fill_Var'to make final callback 6652	
00104341	19:49:56.046	[1240] Thread 'Fill_Var' is going to callback	
00104342	19:49:56.099	[1240] StretchStart	
00104343	19:49:56.100	[1240] BQ: Added new task. Currently 1 tasks in queue.	
00104344	19:49:56.100	[1240] BQ: Starting a new task.	
00104345	19:49:56.100	[1240] BQ: Currently running 1 threads of 8	
00104346	19:49:56.100	[1240] BQ: Starting a new thread.	
00104347	19:49:56.108	[1240] TGenThread.Create: ThreadName: BackgroundQueue , Running Threads: Internal: 5, All: 55	
00104348	19:49:56.112	[1240] BQ: Added new task. Currently 2 tasks in queue.	
00104349	19:49:56.112	[1240] BQ: Starting a new task.	
00104350	19:49:56.112	[1240] BQ: Currently running 2 threads of 8	
00104351	19:49:56.112	[1240] BQ: Starting a new thread.	
00104352	19:49:56.112	[1240] Thread 'BackgroundQueue' has started 7068	
00104353	19:49:56.113	[1240] Thread registered, going to initialize 7068	
00104354	19:49:56.113	[1240] Thread initialized 7068	
00104355	19:49:56.120	[1240] TGenThread.Create: ThreadName: BackgroundQueue , Running Threads: Internal: 5, All: 56	
00104356	19:49:56.124	[1240] BQ: Added new task. Currently 3 tasks in queue.	
00104357	19:49:56.124	[1240] BQ: Starting a new task.	
00104358	19:49:56.124	[1240] BQ: Currently running 3 threads of 8	
00104359	19:49:56.124	[1240] BQ: Starting a new thread.	
00104360	19:49:56.124	[1240] Thread 'BackgroundQueue' has started 2896	
00104361	19:49:56.124	[1240] Thread registered, going to initialize 2896	
00104362	19:49:56.124	[1240] Thread initialized 2896	
00104363	19:49:56.132	[1240] TGenThread.Create: ThreadName: BackgroundQueue , Running Threads: Internal: 6, All: 57	
00104364	19:49:56.136	[1240] StretchEnd	
00104365	19:49:56.136	[1240] Thread 'BackgroundQueue' has started 1616	
00104366	19:49:56.136	[1240] Thread registered, going to initialize 1616	
00104367	19:49:56.137	[1240] Thread initialized 1616	
00104368	19:49:56.140	[1240] Winamp Playlist sim - message 0 left to the default processing	
00104369	19:49:56.140	[1240] Winamp simulation window received messsage 0	
00104370	19:49:56.148	[1240] Remaining Covers: 151	
00104371	19:49:56.148	[1240] Thread 'Fill_Var'has finished 6652	
00104372	19:49:56.148	[1240] BQ: Added new task. Currently 1 tasks in queue.	
00104373	19:49:56.148	[1240] BQ: Starting a new task.	
00104374	19:49:56.148	[1240] BQ: There are threads waiting, resume one.	
00104375	19:49:56.198	[1240] TGenThread.Create: ThreadName: Fill_Var , Running Threads: Internal: 7, All: 57	
00104376	19:49:56.202	[1240] Thread 'Fill_Var' has started 1976	
00104377	19:49:56.202	[1240] Thread registered, going to initialize 1976	
00104378	19:49:56.203	[1240] Thread initialized 1976	
00104379	19:49:56.203	[1240] ComboHelper::FillThread - lastPart = "funk odysse"; len = 11	
00104380	19:49:56.203	[1240] Thread 'Fill_Var' is going to callback	
00104381	19:49:56.244	[1240] Winamp Playlist sim - message 0 left to the default processing	
00104382	19:49:56.244	[1240] Winamp simulation window received messsage 0	
00104383	19:49:56.252	[1240] StretchStart	
00104384	19:49:56.252	[1240] BQ: Added new task. Currently 1 tasks in queue.	
00104385	19:49:56.253	[1240] BQ: Starting a new task.	
00104386	19:49:56.253	[1240] BQ: There are threads waiting, resume one.	
00104387	19:49:56.253	[1240] BQ: Added new task. Currently 2 tasks in queue.	
00104388	19:49:56.253	[1240] BQ: Starting a new task.	
00104389	19:49:56.253	[1240] BQ: There are threads waiting, resume one.	
00104390	19:49:56.253	[1240] BQ: Added new task. Currently 2 tasks in queue.	
00104391	19:49:56.253	[1240] BQ: Starting a new task.	
00104392	19:49:56.253	[1240] BQ: There are threads waiting, resume one.	
00104393	19:49:56.257	[1240] StretchEnd	
00104394	19:49:56.286	[1240] Going 'Fill_Var'to make final callback 1976	
00104395	19:49:56.286	[1240] Thread 'Fill_Var' is going to callback	
00104396	19:49:56.290	[1240] Winamp Playlist sim - message 0 left to the default processing	
00104397	19:49:56.290	[1240] Winamp simulation window received messsage 0	
00104398	19:49:56.290	[1240] Thread 'Fill_Var'has finished 1976	
00104399	19:49:56.320	[1240] TAlbumArtViewController.SelectSongs - End	
00104400	19:49:56.320	[1240] 1408 DB open SQL: SELECT IDView FROM NodeViews WHERE NodeType = ? 	
00104401	19:49:56.320	[1240] Added Cover Lists: 94	
00104402	19:49:56.320	[1240] 6716 DB prepare SQL: SELECT Covers.* FROM Covers, Songs WHERE songs.idalbum=? AND covers.idsong=songs.id ORDER BY Covers.idsong	
00104403	19:49:56.320	[1240] 1408 DB lock finished, took 348.	
00104404	19:49:56.320	[1240] 6716 DB query prepare finished, took 216.	
00104405	19:49:56.320	[1240] 1408 DB open SQL: SELECT ID, Name, View FROM Views WHERE ID = ? 	
00104406	19:49:56.321	[1240] 6716 DB open SQL: SELECT Covers.* FROM Covers, Songs WHERE songs.idalbum=? AND covers.idsong=songs.id ORDER BY Covers.idsong 	
00104407	19:49:56.321	[1240] 1408 DB lock finished, took 257.	
00104408	19:49:56.321	[1240] 6716 DB lock finished, took 284.	
00104409	19:49:56.321	[1240] Added Covers: 152	
00104410	19:49:56.321	[1240] Added Covers: 153	
00104411	19:49:56.321	[1240] Added Covers: 154	
00104412	19:49:56.331	[1240] 1408 DB open SQL: SELECT IDView FROM NodeViews WHERE NodeType = ? 	
00104413	19:49:56.331	[1240] 1408 DB lock finished, took 236.	
00104414	19:49:56.331	[1240] 1408 DB open SQL: SELECT ID, Name, View FROM Views WHERE ID = ? 	
00104415	19:49:56.331	[1240] 1408 DB lock finished, took 232.	
00104416	19:49:56.332	[1240] Thread 'FillingThread'has finished 4448	
00104417	19:49:56.339	[1240] TryLoadDirectlyFromDBAndCache called for track C:\Users\Claude\Music\Depot\# Pop\I-J\Jamiroquai\A Funk Odyssey\Jamiroquai - Feel So Good.mp3	
00104418	19:49:56.339	[1240] TryLoadDirectlyFromDBAndCache - force load from cache C:\Users\Claude\AppData\Local\Temp\MMCache1087777978_2\Jamiroquai - Feel So Good-VCBM73X69MPP57I576MQJSRSE - 49GW9143N3781MAG82DS8D5C3716.bmp	
00104419	19:49:56.339	[1240] Added Covers: 155	
00104420	19:49:59.257	[1240] Going 'BackgroundQueue'to make final callback 7068	
00104421	19:49:59.257	[1240] Going 'BackgroundQueue'to make final callback 4736	
00104422	19:49:59.257	[1240] Going 'BackgroundQueue'to make final callback 1616	
00104423	19:49:59.257	[1240] Thread 'BackgroundQueue'has finished 7068	
00104424	19:49:59.257	[1240] DB: Deleting prepared query: SELECT Songs.* FROM Songs WHERE Songs.IDMedia=? AND Songs.SongPath=? 	
00104425	19:49:59.258	[1240] Thread 'BackgroundQueue'has finished 1616	
00104426	19:49:59.258	[1240] Thread 'BackgroundQueue'has finished 4736	
00104427	19:49:59.279	[1240] Going 'BackgroundQueue'to make final callback 2896	
00104428	19:49:59.279	[1240] Thread 'BackgroundQueue'has finished 2896

hintergrundrauschen · Post by **hintergrundrauschen** » Sat Nov 09, 2013 2:26 pm

Is there anything I can do to make MM generate an error report??

Code: Select all


00010009	20:17:20.737	[5248] TAlbumArtViewController::PrepareAlbumArtList - Albums groups generated
00010010	20:17:20.737	[5248] TAlbumArtViewController::PrepareAlbumArtList - Rows computed
00010011	20:17:20.737	[5248] TAlbumArtViewController::PrepareAlbumArtList - Albums selected
00010012	20:17:20.737	[5248] TAlbumArtViewController::PrepareAlbumArtList - end
00010013	20:17:20.742	[5248] TryLoadDirectlyFromDBAndCache called for track C:\Users\Claude\Music\Depot\# Pop\T\Tool\Undertow\01 Tool - Intolerance.mp3
00010014	20:17:20.743	[5248] TryLoadDirectlyFromDBAndCache - force load from cache C:\Users\Claude\AppData\Local\Temp\MMCache1087777978_2\01 Tool - Intolerance-ZYFCZ2E8EXUWF21S71GW5S35Y - J16MGK151ZT9AN4EYSFSSZHRG2914.bmp
00010015	20:17:20.743	[5248] Added Covers: 89
00010016	20:17:20.743	[5248] Remaining Covers: 88
00010017	20:17:20.743	[5248] StretchStart
00010018	20:17:20.743	[5248] BQ: Added new task. Currently 1 tasks in queue.
00010019	20:17:20.744	[5248] BQ: Starting a new task.
00010020	20:17:20.744	[5248] BQ: Currently running 0 threads of 8
00010021	20:17:20.744	[5248] BQ: Starting a new thread.
00010022	20:17:20.752	[5248] TGenThread.Create: ThreadName: BackgroundQueue , Running Threads: Internal: 1, All: 46
00010023	20:17:20.755	[5248] BQ: Added new task. Currently 2 tasks in queue.
00010024	20:17:20.755	[5248] BQ: Starting a new task.
00010025	20:17:20.755	[5248] BQ: Currently running 1 threads of 8
00010026	20:17:20.755	[5248] BQ: Starting a new thread.
00010027	20:17:20.756	[5248] Thread 'BackgroundQueue' has started 6012
00010028	20:17:20.756	[5248] Thread registered, going to initialize 6012
00010029	20:17:20.756	[5248] Thread initialized 6012
00010030	20:17:20.764	[5248] TGenThread.Create: ThreadName: BackgroundQueue , Running Threads: Internal: 1, All: 47
00010031	20:17:20.767	[5248] BQ: Added new task. Currently 3 tasks in queue.
00010032	20:17:20.767	[5248] BQ: Starting a new task.
00010033	20:17:20.767	[5248] BQ: Currently running 2 threads of 8
00010034	20:17:20.768	[5248] BQ: Starting a new thread.
00010035	20:17:20.768	[5248] Thread 'BackgroundQueue' has started 6976
00010036	20:17:20.768	[5248] Thread registered, going to initialize 6976
00010037	20:17:20.768	[5248] Thread initialized 6976
00010038	20:17:20.777	[5248] TGenThread.Create: ThreadName: BackgroundQueue , Running Threads: Internal: 2, All: 48
00010039	20:17:20.780	[5248] StretchEnd
00010040	20:17:20.781	[5248] Thread 'BackgroundQueue' has started 3468
00010041	20:17:20.781	[5248] Thread registered, going to initialize 3468
00010042	20:17:20.781	[5248] Thread initialized 3468
00010043	20:17:20.794	[5248] TAlbumArtViewController.SelectSongs - Begin
00010044	20:17:20.794	[5248] Events: Invoking event: OnChangedSelection
00010045	20:17:20.794	[5248] Events: Successfully finished event: OnChangedSelection
00010046	20:17:20.799	[5248] BQ: Added new task. Currently 1 tasks in queue.
00010047	20:17:20.799	[5248] BQ: Starting a new task.
00010048	20:17:20.799	[5248] BQ: There are threads waiting, resume one.
00010049	20:17:20.818	[5248] UpdateSongPictures: C:\Users\Claude\Music\Depot\# Pop\T\Tool\Undertow\01 Tool - Intolerance.mp3
00010050	20:17:20.818	[5248] Added Cover Lists: 52
00010051	20:17:20.818	[5248] GetFileInfo: C:\Users\Claude\Music\Depot\# Pop\T\Tool\Undertow\01 Tool - Intolerance.mp3
00010052	20:17:20.818	[5248] GetFileInfo: readPictures=spAlways
00010053	20:17:20.819	[5248] GetFileInfo: C:\Users\Claude\Music\Depot\# Pop\T\Tool\Undertow\01 Tool - Intolerance.mp3
00010054	20:17:20.819	[5248] MP3.ReadHeader C:\Users\Claude\Music\Depot\# Pop\T\Tool\Undertow\01 Tool - Intolerance.mp3
00010055	20:17:20.819	[5248] MP3.ReadHeader - File size 5743319
00010056	20:17:20.835	[5248] MP3.ReadHeader - Found ID3v2, length: 4392
00010057	20:17:20.835	[5248] MP3.ReadHeader framestarts: 4402, 4402
00010058	20:17:20.841	[5248] MP3.ReadHeader finished
00010059	20:17:20.841	[5248] MP3: Going to read tag from C:\Users\Claude\Music\Depot\# Pop\T\Tool\Undertow\01 Tool - Intolerance.mp3
00010060	20:17:20.843	[5248] MP3: Tag read from C:\Users\Claude\Music\Depot\# Pop\T\Tool\Undertow\01 Tool - Intolerance.mp3
00010061	20:17:20.843	[5248] 6976 DB prepare SQL: SELECT Songs.* FROM Songs WHERE Songs.IDMedia=? AND Songs.SongPath=?
00010062	20:17:20.844	[5248] 6976 DB query prepare finished, took 626.
00010063	20:17:20.844	[5248] 6976 DB open SQL: SELECT Songs.* FROM Songs WHERE Songs.IDMedia=? AND Songs.SongPath=? 
00010064	20:17:20.861	[5248] 6976 DB lock finished, took 40494.
00010065	20:17:20.861	[5248] GetFileInfo: Found in DB
00010066	20:17:20.861	[5248] UpdateSongPictures: CoverList.LoadForSongId, C:\Users\Claude\Music\Depot\# Pop\T\Tool\Undertow\01 Tool - Intolerance.mp3
00010067	20:17:20.862	[5248] 6976 DB open SQL: SELECT * FROM Covers WHERE IDSong=23568 ORDER BY CoverOrder 
00010068	20:17:20.862	[5248] OpenQuery - Preparing query SELECT * FROM Covers WHERE IDSong=23568 ORDER BY CoverOrder 
00010069	20:17:20.862	[5248] 6976 DB lock finished, took 572.
00010070	20:17:20.862	[5248] Added Covers: 89
00010071	20:17:20.882	[5248] TAlbumArtViewController.SelectSongs - End
00010072	20:17:20.882	[5248] 5232 DB open SQL: SELECT IDView FROM NodeViews WHERE NodeType = ? 
00010073	20:17:20.882	[5248] 5232 DB lock finished, took 248.
00010074	20:17:20.882	[5248] 5232 DB open SQL: SELECT ID, Name, View FROM Views WHERE ID = ? 
00010075	20:17:20.882	[5248] 5232 DB lock finished, took 258.
00010076	20:17:20.883	[5248] 5232 DB open SQL: SELECT IDView FROM NodeViews WHERE NodeType = ? 
00010077	20:17:20.883	[5248] 5232 DB lock finished, took 222.
00010078	20:17:20.883	[5248] 5232 DB open SQL: SELECT ID, Name, View FROM Views WHERE ID = ? 
00010079	20:17:20.884	[5248] 5232 DB lock finished, took 228.
00010080	20:17:20.884	[5248] Thread 'FillingThread'has finished 6416
00010081	20:17:20.885	[5248] Remaining Covers: 88
00010082	20:17:20.885	[5248] BQ: Added new task. Currently 1 tasks in queue.
00010083	20:17:20.885	[5248] BQ: Starting a new task.
00010084	20:17:20.885	[5248] BQ: There are threads waiting, resume one.
00010085	20:17:21.003	[5248] StretchStart
00010086	20:17:21.004	[5248] BQ: Added new task. Currently 1 tasks in queue.
00010087	20:17:21.004	[5248] BQ: Starting a new task.
00010088	20:17:21.004	[5248] BQ: There are threads waiting, resume one.
00010089	20:17:21.004	[5248] BQ: Added new task. Currently 2 tasks in queue.
00010090	20:17:21.004	[5248] BQ: Starting a new task.
00010091	20:17:21.004	[5248] BQ: There are threads waiting, resume one.
00010092	20:17:21.004	[5248] BQ: Added new task. Currently 2 tasks in queue.
00010093	20:17:21.004	[5248] BQ: Starting a new task.
00010094	20:17:21.005	[5248] BQ: Currently running 3 threads of 8
00010095	20:17:21.005	[5248] BQ: Starting a new thread.
00010096	20:17:21.013	[5248] TGenThread.Create: ThreadName: BackgroundQueue , Running Threads: Internal: 3, All: 47
00010097	20:17:21.017	[5248] Thread 'BackgroundQueue' has started 5784
00010098	20:17:21.017	[5248] Thread registered, going to initialize 5784
00010099	20:17:21.017	[5248] Thread initialized 5784
00010100	20:17:21.018	[5248] StretchEnd
00010101	20:17:24.018	[5248] Going 'BackgroundQueue'to make final callback 5784
00010102	20:17:24.018	[5248] Going 'BackgroundQueue'to make final callback 3468
00010103	20:17:24.018	[5248] Going 'BackgroundQueue'to make final callback 6976
00010104	20:17:24.018	[5248] Thread 'BackgroundQueue'has finished 5784
00010105	20:17:24.019	[5248] Thread 'BackgroundQueue'has finished 3468
00010106	20:17:24.019	[5248] DB: Deleting prepared query: SELECT Songs.* FROM Songs WHERE Songs.IDMedia=? AND Songs.SongPath=? 
00010107	20:17:24.019	[5248] Thread 'BackgroundQueue'has finished 6976
00010108	20:17:24.040	[5248] Going 'BackgroundQueue'to make final callback 6012
00010109	20:17:24.040	[5248] Thread 'BackgroundQueue'has finished 6012
00010110	20:17:26.947	[5248] TGenThread.Create: ThreadName: UpdateDriveLetters_Var , Running Threads: Internal: 0, All: 43
00010111	20:17:26.953	[5248] PostponeComputerSleep: Enabled = 0
00010112	20:17:26.954	[5248] Thread 'UpdateDriveLetters_Var' has started 5840
00010113	20:17:26.954	[5248] Thread registered, going to initialize 5840
00010114	20:17:26.955	[5248] Thread initialized 5840
00010115	20:17:26.955	[5248] >UpdateDriveLetters - start<
00010116	20:17:26.968	[5248] >UpdateDriveLetters - end<
00010117	20:17:26.968	[5248] Going 'UpdateDriveLetters_Var'to make final callback 5840
00010118	20:17:26.968	[5248] Thread 'UpdateDriveLetters_Var'has finished 5840
00010119	20:17:37.904	[5248] TGenThread.Create: ThreadName: Fill_Var , Running Threads: Internal: 0, All: 43
00010120	20:17:37.911	[5248] Thread 'Fill_Var' has started 4820
00010121	20:17:37.911	[5248] Thread registered, going to initialize 4820
00010122	20:17:37.912	[5248] Thread initialized 4820
00010123	20:17:37.912	[5248] ComboHelper::FillThread - lastPart = "a"; len = 1
00010124	20:17:37.912	[5248] Thread 'Fill_Var' is going to callback
00010125	20:17:37.917	[5248] Going 'Fill_Var'to make final callback 4820
00010126	20:17:37.917	[5248] Thread 'Fill_Var' is going to callback
00010127	20:17:37.917	[5248] Thread 'Fill_Var'has finished 4820
00010128	20:17:38.063	[5248] TGenThread.Create: ThreadName: Fill_Var , Running Threads: Internal: 0, All: 43
00010129	20:17:38.068	[5248] Thread 'Fill_Var' has started 5652
00010130	20:17:38.069	[5248] Thread registered, going to initialize 5652
00010131	20:17:38.069	[5248] Thread initialized 5652
00010132	20:17:38.069	[5248] ComboHelper::FillThread - lastPart = "as"; len = 2
00010133	20:17:38.069	[5248] Thread 'Fill_Var' is going to callback
00010134	20:17:38.072	[5248] Winamp Playlist sim - message 0 left to the default processing
00010135	20:17:38.072	[5248] Winamp simulation window received messsage 0
00010136	20:17:38.072	[5248] Going 'Fill_Var'to make final callback 5652
00010137	20:17:38.072	[5248] Thread 'Fill_Var' is going to callback
00010138	20:17:38.073	[5248] Thread 'Fill_Var'has finished 5652
00010139	20:17:38.129	[5248] TGenThread.Create: ThreadName: Fill_Var , Running Threads: Internal: 0, All: 43
00010140	20:17:38.134	[5248] Thread 'Fill_Var' has started 1976
00010141	20:17:38.134	[5248] Thread registered, going to initialize 1976
00010142	20:17:38.135	[5248] Thread initialized 1976
00010143	20:17:38.135	[5248] ComboHelper::FillThread - lastPart = "as"; len = 2
00010144	20:17:38.135	[5248] Thread 'Fill_Var' is going to callback
00010145	20:17:38.139	[5248] Winamp Playlist sim - message 0 left to the default processing
00010146	20:17:38.139	[5248] Winamp simulation window received messsage 0
00010147	20:17:38.139	[5248] Going 'Fill_Var'to make final callback 1976
00010148	20:17:38.139	[5248] Thread 'Fill_Var' is going to callback
00010149	20:17:38.140	[5248] Thread 'Fill_Var'has finished 1976
00010150	20:17:38.170	[5248] TGenThread.Create: ThreadName: Fill_Var , Running Threads: Internal: 0, All: 43
00010151	20:17:38.175	[5248] Thread 'Fill_Var' has started 6692
00010152	20:17:38.175	[5248] Thread registered, going to initialize 6692
00010153	20:17:38.175	[5248] Thread initialized 6692
00010154	20:17:38.176	[5248] ComboHelper::FillThread - lastPart = "ash"; len = 3
00010155	20:17:38.176	[5248] Thread 'Fill_Var' is going to callback
00010156	20:17:38.179	[5248] Winamp Playlist sim - message 0 left to the default processing
00010157	20:17:38.179	[5248] Winamp simulation window received messsage 0
00010158	20:17:38.180	[5248] Going 'Fill_Var'to make final callback 6692
00010159	20:17:38.180	[5248] Thread 'Fill_Var' is going to callback
00010160	20:17:38.180	[5248] Thread 'Fill_Var'has finished 6692
00010161	20:17:38.456	[5248] TGenThread.Create: ThreadName: Fill_Var , Running Threads: Internal: 0, All: 43
00010162	20:17:38.460	[5248] Thread 'Fill_Var' has started 6652
00010163	20:17:38.460	[5248] Thread registered, going to initialize 6652
00010164	20:17:38.460	[5248] Thread initialized 6652
00010165	20:17:38.460	[5248] ComboHelper::FillThread - lastPart = "ashc"; len = 4
00010166	20:17:38.461	[5248] Thread 'Fill_Var' is going to callback
00010167	20:17:38.464	[5248] Winamp Playlist sim - message 0 left to the default processing
00010168	20:17:38.464	[5248] Winamp simulation window received messsage 0
00010169	20:17:38.464	[5248] Going 'Fill_Var'to make final callback 6652
00010170	20:17:38.464	[5248] Thread 'Fill_Var' is going to callback
00010171	20:17:38.465	[5248] Thread 'Fill_Var'has finished 6652
00010172	20:17:38.688	[5248] TGenThread.Create: ThreadName: Fill_Var , Running Threads: Internal: 0, All: 43
00010173	20:17:38.695	[5248] Thread 'Fill_Var' has started 1268
00010174	20:17:38.695	[5248] Thread registered, going to initialize 1268
00010175	20:17:38.695	[5248] Thread initialized 1268
00010176	20:17:38.695	[5248] ComboHelper::FillThread - lastPart = "ashcr"; len = 5
00010177	20:17:38.696	[5248] Thread 'Fill_Var' is going to callback
00010178	20:17:38.698	[5248] Winamp Playlist sim - message 0 left to the default processing
00010179	20:17:38.698	[5248] Winamp simulation window received messsage 0
00010180	20:17:38.699	[5248] Going 'Fill_Var'to make final callback 1268
00010181	20:17:38.699	[5248] Thread 'Fill_Var' is going to callback
00010182	20:17:38.699	[5248] Thread 'Fill_Var'has finished 1268
00010183	20:17:38.920	[5248] TGenThread.Create: ThreadName: Fill_Var , Running Threads: Internal: 0, All: 43
00010184	20:17:38.927	[5248] Thread 'Fill_Var' has started 1136
00010185	20:17:38.927	[5248] Thread registered, going to initialize 1136
00010186	20:17:38.927	[5248] Thread initialized 1136
00010187	20:17:38.927	[5248] ComboHelper::FillThread - lastPart = "ashcro"; len = 6
00010188	20:17:38.927	[5248] Thread 'Fill_Var' is going to callback
00010189	20:17:38.932	[5248] Winamp Playlist sim - message 0 left to the default processing
00010190	20:17:38.932	[5248] Winamp simulation window received messsage 0
00010191	20:17:38.933	[5248] Going 'Fill_Var'to make final callback 1136
00010192	20:17:38.933	[5248] Thread 'Fill_Var' is going to callback
00010193	20:17:38.933	[5248] Thread 'Fill_Var'has finished 1136
00010194	20:17:39.168	[5248] TGenThread.Create: ThreadName: Fill_Var , Running Threads: Internal: 0, All: 43
00010195	20:17:39.174	[5248] Thread 'Fill_Var' has started 6512
00010196	20:17:39.174	[5248] Thread registered, going to initialize 6512
00010197	20:17:39.174	[5248] Thread initialized 6512
00010198	20:17:39.175	[5248] ComboHelper::FillThread - lastPart = "ashcrof"; len = 7
00010199	20:17:39.175	[5248] Thread 'Fill_Var' is going to callback
00010200	20:17:39.178	[5248] Winamp Playlist sim - message 0 left to the default processing
00010201	20:17:39.178	[5248] Winamp simulation window received messsage 0
00010202	20:17:39.178	[5248] Going 'Fill_Var'to make final callback 6512
00010203	20:17:39.178	[5248] Thread 'Fill_Var' is going to callback
00010204	20:17:39.178	[5248] Thread 'Fill_Var'has finished 6512
00010205	20:17:39.319	[5248] TGenThread.Create: ThreadName: Fill_Var , Running Threads: Internal: 0, All: 43
00010206	20:17:39.325	[5248] Thread 'Fill_Var' has started 4104
00010207	20:17:39.325	[5248] Thread registered, going to initialize 4104
00010208	20:17:39.325	[5248] Thread initialized 4104
00010209	20:17:39.325	[5248] ComboHelper::FillThread - lastPart = "ashcroft"; len = 8
00010210	20:17:39.325	[5248] Thread 'Fill_Var' is going to callback
00010211	20:17:39.328	[5248] Winamp Playlist sim - message 0 left to the default processing
00010212	20:17:39.328	[5248] Winamp simulation window received messsage 0
00010213	20:17:39.329	[5248] Going 'Fill_Var'to make final callback 4104
00010214	20:17:39.329	[5248] Thread 'Fill_Var' is going to callback
00010215	20:17:39.329	[5248] Thread 'Fill_Var'has finished 4104
00010216	20:17:39.803	[5248] Events: Invoking event: OnChangedSelection
00010217	20:17:39.803	[5248] Events: Successfully finished event: OnChangedSelection
00010218	20:17:39.813	[5248] Remaining Cover Lists: 51
00010219	20:17:39.826	[5248] Node Beinhaltet: "tool" going to clear SongList.
00010220	20:17:40.112	[5248] Node Beinhaltet: "ashcroft" starting.
00010221	20:17:40.112	[5248] Node Beinhaltet: "ashcroft" going to clear SongList.
00010222	20:17:40.114	[5248] Events: Invoking event: OnChangedSelection
00010223	20:17:40.114	[5248] Events: Successfully finished event: OnChangedSelection
00010224	20:17:40.117	[5248] 5232 DB open SQL: SELECT IDView FROM NodeViews WHERE NodeType = ? 
00010225	20:17:40.117	[5248] 5232 DB lock finished, took 550.
00010226	20:17:40.117	[5248] 5232 DB open SQL: SELECT ID, Name, View FROM Views WHERE ID = ? 
00010227	20:17:40.118	[5248] 5232 DB lock finished, took 458.
00010228	20:17:40.139	[5248] Going to fill tracklist, NodeType: 13
00010229	20:17:40.139	[5248] Going to start filling thread, FFillingThreadCnt = 33
00010230	20:17:40.148	[5248] TGenThread.Create: ThreadName: FillingThread , Running Threads: Internal: 0, All: 43
00010231	20:17:40.152	[5248] Thread 'FillingThread' has started 172
00010232	20:17:40.152	[5248] Thread registered, going to initialize 172
00010233	20:17:40.152	[5248] Thread initialized 172
00010234	20:17:40.152	[5248] Thread 'FillingThread' is going to callback
00010235	20:17:40.157	[5248] 172 DB open SQL: SELECT Songs.* 
00010236	20:17:40.157	[5248]  FROM Songs WHERE Songs.ID IN (SELECT rowid FROM SongsText WHERE SongsText MATCH ' ashcroft* ')  
00010237	20:17:40.157	[5248] OpenQuery - Preparing query SELECT Songs.* 
00010238	20:17:40.157	[5248]  FROM Songs WHERE Songs.ID IN (SELECT rowid FROM SongsText WHERE SongsText MATCH ' ashcroft* ')  
00010239	20:17:40.158	[5248] 172 DB lock finished, took 2040.
00010240	20:17:40.161	[5248] Going 'FillingThread'to make final callback 172
00010241	20:17:40.161	[5248] Thread 'FillingThread' is going to callback
00010242	20:17:40.175	[5248] SortAlbumListPreserveSelection called
00010243	20:17:40.176	[5248] TAlbumArtViewController::PrepareAlbumArtList - begin
00010244	20:17:40.176	[5248] TAlbumArtViewsManager::PrepareAlbumArtList - begin
00010245	20:17:40.176	[5248] TAlbumArtViewsManager::PrepareAlbumArtList - before fill
00010246	20:17:40.176	[5248] TAlbumArtViewsManager::PrepareAlbumArtList - end
00010247	20:17:40.176	[5248] TAlbumArtViewController::PrepareAlbumArtList - Albums generated
00010248	20:17:40.176	[5248] TAlbumArtViewController::PrepareAlbumArtList - Albums sorted
00010249	20:17:40.176	[5248] 5232 DB open SQL: SELECT IDView FROM NodeViews WHERE NodeType = ? 
00010250	20:17:40.176	[5248] 5232 DB lock finished, took 250.
00010251	20:17:40.177	[5248] 5232 DB open SQL: SELECT ID, Name, View FROM Views WHERE ID = ? 
00010252	20:17:40.177	[5248] 5232 DB lock finished, took 252.
00010253	20:17:40.178	[5248] TAlbumArtViewController::PrepareAlbumArtList - Albums groups generated
00010254	20:17:40.179	[5248] TAlbumArtViewController::PrepareAlbumArtList - Rows computed
00010255	20:17:40.179	[5248] TAlbumArtViewController::PrepareAlbumArtList - Albums selected
00010256	20:17:40.179	[5248] TAlbumArtViewController::PrepareAlbumArtList - end
00010257	20:17:40.181	[5248] TAlbumArtViewController.SelectSongs - Begin
00010258	20:17:40.186	[5248] BQ: Added new task. Currently 1 tasks in queue.
00010259	20:17:40.186	[5248] BQ: Starting a new task.
00010260	20:17:40.186	[5248] BQ: Currently running 0 threads of 8
00010261	20:17:40.186	[5248] BQ: Starting a new thread.
00010262	20:17:40.194	[5248] TGenThread.Create: ThreadName: BackgroundQueue , Running Threads: Internal: 1, All: 44
00010263	20:17:40.198	[5248] Thread 'BackgroundQueue' has started 5712
00010264	20:17:40.199	[5248] Thread registered, going to initialize 5712
00010265	20:17:40.199	[5248] Thread initialized 5712
00010266	20:17:40.228	[5248] UpdateSongPictures: C:\Users\Claude\Music\Depot\# Pop\G\Groovecatcher\After the Rain\05 Groovecatcher - Neonstrasse.mp3
00010267	20:17:40.228	[5248] Added Cover Lists: 52
00010268	20:17:40.228	[5248] GetFileInfo: C:\Users\Claude\Music\Depot\# Pop\G\Groovecatcher\After the Rain\05 Groovecatcher - Neonstrasse.mp3
00010269	20:17:40.228	[5248] GetFileInfo: readPictures=spAlways
00010270	20:17:40.228	[5248] GetFileInfo: C:\Users\Claude\Music\Depot\# Pop\G\Groovecatcher\After the Rain\05 Groovecatcher - Neonstrasse.mp3
00010271	20:17:40.228	[5248] MP3.ReadHeader C:\Users\Claude\Music\Depot\# Pop\G\Groovecatcher\After the Rain\05 Groovecatcher - Neonstrasse.mp3
00010272	20:17:40.228	[5248] MP3.ReadHeader - File size 6897664
00010273	20:17:40.243	[5248] MP3.ReadHeader - Found ID3v2, length: 960
00010274	20:17:40.243	[5248] MP3.ReadHeader framestarts: 970, 970
00010275	20:17:40.253	[5248] MP3.ReadHeader finished
00010276	20:17:40.253	[5248] MP3: Going to read tag from C:\Users\Claude\Music\Depot\# Pop\G\Groovecatcher\After the Rain\05 Groovecatcher - Neonstrasse.mp3
00010277	20:17:40.255	[5248] MP3: Tag read from C:\Users\Claude\Music\Depot\# Pop\G\Groovecatcher\After the Rain\05 Groovecatcher - Neonstrasse.mp3
00010278	20:17:40.255	[5248] 5712 DB prepare SQL: SELECT Songs.* FROM Songs WHERE Songs.IDMedia=? AND Songs.SongPath=?
00010279	20:17:40.256	[5248] 5712 DB query prepare finished, took 509.
00010280	20:17:40.256	[5248] 5712 DB open SQL: SELECT Songs.* FROM Songs WHERE Songs.IDMedia=? AND Songs.SongPath=? 
00010281	20:17:40.279	[5248] 5712 DB lock finished, took 52838.
00010282	20:17:40.279	[5248] GetFileInfo: Found in DB
00010283	20:17:40.279	[5248] UpdateSongPictures: CoverList.LoadForSongId, C:\Users\Claude\Music\Depot\# Pop\G\Groovecatcher\After the Rain\05 Groovecatcher - Neonstrasse.mp3
00010284	20:17:40.279	[5248] 5712 DB open SQL: SELECT * FROM Covers WHERE IDSong=3916 ORDER BY CoverOrder 
00010285	20:17:40.279	[5248] OpenQuery - Preparing query SELECT * FROM Covers WHERE IDSong=3916 ORDER BY CoverOrder 
00010286	20:17:40.279	[5248] 5712 DB lock finished, took 555.
00010287	20:17:40.279	[5248] Added Covers: 89
00010288	20:17:40.303	[5248] TryLoadDirectlyFromDBAndCache called for track C:\Users\Claude\Music\Depot\# Pop\G\Groovecatcher\After the Rain\05 Groovecatcher - Neonstrasse.mp3
00010289	20:17:40.311	[5248] TGenThread.Create: ThreadName: ImageReader_Var , Running Threads: Internal: 2, All: 45
00010290	20:17:40.315	[5248] Thread 'ImageReader_Var' has started 6604
00010291	20:17:40.316	[5248] Thread registered, going to initialize 6604
00010292	20:17:40.316	[5248] Thread initialized 6604
00010293	20:17:40.323	[5248] TryLoadDirectlyFromDBAndCache called for track C:\Users\Claude\Music\Depot\# Pop\R\Richard Ashcroft\Alone with Everybody\Richard Ashcroft - A Song for the Lovers.mp3
00010294	20:17:40.336	[5248] TryLoadDirectlyFromDBAndCache called for track C:\Users\Claude\Music\Depot\# Pop\U-Z\Unkle\Big Brother Is Watching You\CD 1\02 UNKLE - Lonely Years (feat. Richa.mp3
00010295	20:17:40.342	[5248] TryLoadDirectlyFromDBAndCache called for track C:\Users\Claude\Music\Depot\# Pop\S\Sergio Mendes\Encanto\01 Sérgio Mendes - The Look of Love (feat. F.mp3
00010296	20:17:40.349	[5248] TryLoadDirectlyFromDBAndCache called for track C:\Users\Claude\Music\Depot\# Pop\R\Richard Ashcroft\Keys to the World\Richard Ashcroft - Why Not Nothing.mp3
00010297	20:17:40.424	[5248] StretchStart
00010298	20:17:40.426	[5248] BQ: Added new task. Currently 1 tasks in queue.
00010299	20:17:40.426	[5248] BQ: Starting a new task.
00010300	20:17:40.426	[5248] BQ: Currently running 1 threads of 8
00010301	20:17:40.426	[5248] BQ: Starting a new thread.
00010302	20:17:40.434	[5248] TGenThread.Create: ThreadName: BackgroundQueue , Running Threads: Internal: 3, All: 46
00010303	20:17:40.437	[5248] BQ: Added new task. Currently 2 tasks in queue.
00010304	20:17:40.437	[5248] BQ: Starting a new task.
00010305	20:17:40.437	[5248] BQ: Currently running 2 threads of 8
00010306	20:17:40.437	[5248] BQ: Starting a new thread.
00010307	20:17:40.438	[5248] Thread 'BackgroundQueue' has started 5224
00010308	20:17:40.438	[5248] Thread registered, going to initialize 5224
00010309	20:17:40.438	[5248] Thread initialized 5224
00010310	20:17:40.446	[5248] TGenThread.Create: ThreadName: BackgroundQueue , Running Threads: Internal: 3, All: 47
00010311	20:17:40.449	[5248] BQ: Added new task. Currently 3 tasks in queue.
00010312	20:17:40.449	[5248] BQ: Starting a new task.
00010313	20:17:40.449	[5248] BQ: Currently running 3 threads of 8
00010314	20:17:40.449	[5248] BQ: Starting a new thread.
00010315	20:17:40.450	[5248] Thread 'BackgroundQueue' has started 6240
00010316	20:17:40.450	[5248] Thread registered, going to initialize 6240
00010317	20:17:40.450	[5248] Thread initialized 6240
00010318	20:17:40.459	[5248] TGenThread.Create: ThreadName: BackgroundQueue , Running Threads: Internal: 4, All: 48
00010319	20:17:40.462	[5248] Thread 'BackgroundQueue' has started 124
00010320	20:17:40.462	[5248] Thread registered, going to initialize 124
00010321	20:17:40.463	[5248] Thread initialized 124
00010322	20:17:40.468	[5248] StretchEnd
00010323	20:17:40.471	[5248] Remaining Covers: 88
00010324	20:17:40.471	[5248] BQ: Added new task. Currently 1 tasks in queue.
00010325	20:17:40.471	[5248] BQ: Starting a new task.
00010326	20:17:40.471	[5248] BQ: There are threads waiting, resume one.
00010327	20:17:40.574	[5248] StretchStart
00010328	20:17:40.575	[5248] BQ: Added new task. Currently 1 tasks in queue.
00010329	20:17:40.575	[5248] BQ: Starting a new task.
00010330	20:17:40.575	[5248] BQ: There are threads waiting, resume one.
00010331	20:17:40.576	[5248] BQ: Added new task. Currently 2 tasks in queue.
00010332	20:17:40.576	[5248] BQ: Starting a new task.
00010333	20:17:40.576	[5248] BQ: There are threads waiting, resume one.
00010334	20:17:40.576	[5248] BQ: Added new task. Currently 2 tasks in queue.
00010335	20:17:40.576	[5248] BQ: Starting a new task.
00010336	20:17:40.576	[5248] BQ: There are threads waiting, resume one.
00010337	20:17:40.586	[5248] StretchEnd
00010338	20:17:40.651	[5248] TAlbumArtViewController.SelectSongs - End
00010339	20:17:40.651	[5248] 5232 DB open SQL: SELECT IDView FROM NodeViews WHERE NodeType = ? 
00010340	20:17:40.651	[5248] Added Cover Lists: 53
00010341	20:17:40.651	[5248] 6604 DB prepare SQL: SELECT Covers.* FROM Covers, Songs WHERE songs.idalbum=? AND covers.idsong=songs.id ORDER BY Covers.idsong
00010342	20:17:40.651	[5248] 5232 DB lock finished, took 314.
00010343	20:17:40.651	[5248] 6604 DB query prepare finished, took 190.
00010344	20:17:40.651	[5248] 5232 DB open SQL: SELECT ID, Name, View FROM Views WHERE ID = ? 
00010345	20:17:40.651	[5248] 6604 DB open SQL: SELECT Covers.* FROM Covers, Songs WHERE songs.idalbum=? AND covers.idsong=songs.id ORDER BY Covers.idsong 
00010346	20:17:40.652	[5248] 5232 DB lock finished, took 257.
00010347	20:17:40.674	[5248] 6604 DB lock finished, took 52403.
00010348	20:17:40.674	[5248] Added Covers: 89
00010349	20:17:40.675	[5248] 5232 DB open SQL: SELECT IDView FROM NodeViews WHERE NodeType = ? 
00010350	20:17:40.675	[5248] 5232 DB lock finished, took 292.
00010351	20:17:40.675	[5248] 5232 DB open SQL: SELECT ID, Name, View FROM Views WHERE ID = ? 
00010352	20:17:40.675	[5248] 5232 DB lock finished, took 251.
00010353	20:17:40.676	[5248] Thread 'FillingThread'has finished 172
00010354	20:17:40.678	[5248] TryLoadDirectlyFromDBAndCache called for track C:\Users\Claude\Music\Depot\# Pop\G\Groovecatcher\After the Rain\05 Groovecatcher - Neonstrasse.mp3
00010355	20:17:40.679	[5248] TryLoadDirectlyFromDBAndCache - force load from cache C:\Users\Claude\AppData\Local\Temp\MMCache1087777978_2\05 Groovecatcher - Neonst-IBAYEF6EQT9H8G4IMCNB42PC5 - AHTVSFV1SV5CJ8R9SA88XHAH47965.bmp
00010356	20:17:40.679	[5248] Added Covers: 90
00010357	20:17:40.684	[5248] Added Covers: 91
00010358	20:17:40.709	[5248] Remaining Covers: 90
00010359	20:17:43.586	[5248] Going 'BackgroundQueue'to make final callback 5712
00010360	20:17:43.586	[5248] Going 'BackgroundQueue'to make final callback 6240
00010361	20:17:43.586	[5248] Going 'BackgroundQueue'to make final callback 5224
00010362	20:17:43.586	[5248] DB: Deleting prepared query: SELECT Songs.* FROM Songs WHERE Songs.IDMedia=? AND Songs.SongPath=? 
00010363	20:17:43.586	[5248] Thread 'BackgroundQueue'has finished 6240
00010364	20:17:43.586	[5248] Thread 'BackgroundQueue'has finished 5224
00010365	20:17:43.586	[5248] Thread 'BackgroundQueue'has finished 5712
00010366	20:17:43.607	[5248] Going 'BackgroundQueue'to make final callback 124
00010367	20:17:43.607	[5248] Thread 'BackgroundQueue'has finished 124

Ludek · Post by **Ludek** » Sun Nov 10, 2013 2:54 pm

If UI is frozen, then debug builds auto-generates crash report after 30 seconds of UI freeze or so. Alternativelly you should be able to find the error report as 'MediaMonkey.elf' located in the same folder as MediaMonkey.exe (or in some Win7 installations, at C:\Users\<user>\AppData\Roaming\EurekaLog\MediaMonkey ). There is also shortcut to invoke the crash report manually (left shift + rigth ctrl + Tab). But it is better (more descriptive) if you let auto-generate the freeze log.

Ludek · Post by **Ludek** » Mon Nov 11, 2013 10:13 am

I tried to reproduce the freeze with your database file that you posted me over PM, but I haven't been able to reproduce any freeze.

Nevertheless in the part of the debug log above I see some script/addons events invoked while searching. This could be reason for the freeze.
Could you please try to temporary rename Scripts folders from 'Script' to 'Scripts.off' so that we can exclude third party scripts/addons?

You need to rename two folders:
<MediaMonkey install folder>\Scripts\ (e.g. C:\Program Files\MediaMonkey\Scripts\)
AND
<User folder>\MediaMonkey\Scripts\ (e.g. C:\Users\<USERNAME>\AppData\Roaming\MediaMonkey\Scripts\)

Freezing on repeated quick search

Freezing on repeated quick search

Re: Freezing on repeated quick search

Re: Freezing on repeated quick search

Re: Freezing on repeated quick search

Re: Freezing on repeated quick search

Re: Freezing on repeated quick search

Re: Freezing on repeated quick search

Re: Freezing on repeated quick search

Re: Freezing on repeated quick search

Re: Freezing on repeated quick search

Re: Freezing on repeated quick search

Re: Freezing on repeated quick search

Re: Freezing on repeated quick search

Re: Freezing on repeated quick search

Re: Freezing on repeated quick search