View Issue Details

Jump to Notes
IDProjectCategoryView StatusDate SubmittedLast Update
0019566MMW 5Generalpublic2022-11-16 05:012023-12-14 19:21
Reporterdrakinite Assigned To 
PriorityurgentSeveritycrashReproducibilityhave not tried
Status assignedResolutionopen 
Product Version5.0.4 
Target Version5.2 
Summary0019566: Crash after installing NVIDIA graphics driver (Log ID: 0A505AD9)
DescriptionHaven't seen yet if it's reproducible. MM crashed while idle and the only significant thing I did was reinstall my graphics driver.
TagsNo tags attached.
Fixed in build

Activities

drakinite

2022-11-16 05:12

developer   ~0070340

Last edited: 2022-11-16 05:21

 Attempted again: Fresh install of NVIDIA graphics driver (GT 1060) with MM 5.0.4.2683 running. Log ID 0A5063BA

Edit: Reproducible on build 2685. Same log ID as the second one (0A5063BA). Attaching debug log (it includes a lot of nvidia events so I'll also attach one that's filtered to MM5 events

drakinite

2022-11-16 05:21

developer   ~0070341

issue-19566-filtered.log (13,904 bytes)    
00000001	0.00000000	[22572] MM5 [22976](R) BQ: Thread[22976] is executing new task now: TCollections.doRefreshCollections	
00000002	0.00004310	[22572] MM5 [22976](R) TCollection.getIsVisible: Music, FVisibleInMainTree: 1	
00000003	0.00007840	[22572] MM5 [22976](R) TCollection.getIsVisible: Classical Music, FVisibleInMainTree: 2	
00000004	0.00016540	[22572] MM5 [22976](R) DB open SQL: SELECT Songs.Id AS SongID  FROM Songs  WHERE Songs.TrackType in (3)  LIMIT 1	
00000005	0.00038070	[22572] MM5 [22976](R) TCollection.checkCollectionContainsData:Classical Music, query: SELECT Songs.Id AS SongID  FROM Songs  WHERE Songs.TrackType in (3)  LIMIT 1, res: true	
00000006	0.00042980	[22572] MM5 [22976](R) TCollection.getIsVisible: Podcasts, FVisibleInMainTree: 1	
00000007	0.00046200	[22572] MM5 [22976](R) TCollection.getIsVisible: Audiobooks, FVisibleInMainTree: 2	
00000008	0.00051990	[22572] MM5 [22976](R) DB open SQL: SELECT Songs.Id AS SongID  FROM Songs  WHERE Songs.TrackType in (2)  LIMIT 1	
00000009	0.00065660	[22572] MM5 [22976](R) TCollection.checkCollectionContainsData:Audiobooks, query: SELECT Songs.Id AS SongID  FROM Songs  WHERE Songs.TrackType in (2)  LIMIT 1, res: true	
00000010	0.00069860	[22572] MM5 [22976](R) TCollection.getIsVisible: Music Video, FVisibleInMainTree: 2	
00000011	0.00075290	[22572] MM5 [22976](R) DB open SQL: SELECT Songs.Id AS SongID  FROM Songs  WHERE Songs.TrackType in (4)  LIMIT 1	
00000012	0.00088310	[22572] MM5 [22976](R) TCollection.checkCollectionContainsData:Music Video, query: SELECT Songs.Id AS SongID  FROM Songs  WHERE Songs.TrackType in (4)  LIMIT 1, res: true	
00000013	0.00091920	[22572] MM5 [22976](R) TCollection.getIsVisible: Video, FVisibleInMainTree: 2	
00000014	0.00096190	[22572] MM5 [22976](R) DB open SQL: SELECT Songs.Id AS SongID  FROM Songs  WHERE Songs.TrackType in (5)  LIMIT 1	
00000015	0.00106810	[22572] MM5 [22976](R) TCollection.checkCollectionContainsData:Video, query: SELECT Songs.Id AS SongID  FROM Songs  WHERE Songs.TrackType in (5)  LIMIT 1, res: true	
00000016	0.00110170	[22572] MM5 [22976](R) TCollection.getIsVisible: TV, FVisibleInMainTree: 2	
00000017	0.00114490	[22572] MM5 [22976](R) DB open SQL: SELECT Songs.Id AS SongID  FROM Songs  WHERE Songs.TrackType in (6)  LIMIT 1	
00000018	0.00124820	[22572] MM5 [22976](R) TCollection.checkCollectionContainsData:TV, query: SELECT Songs.Id AS SongID  FROM Songs  WHERE Songs.TrackType in (6)  LIMIT 1, res: false	
00000019	1.62296128	[22572] MM5 [18108](R) Going 'Worker'to make final callback 18108	
00000020	3.00097609	[22572] MM5 [22976](R) Going 'Worker'to make final callback 22976	
00000021	5.05796337	[22572] MM5 [12148](R) Still waiting for event (callstacks) :	
00000022	5.05799532	[22572] MM5 [12148](R) Wait for event ID :1, delay :20000, callstack :	
00000023	5.05802441	[22572] MM5 [12148](R) Wait for event ID :1, delay :60000, callstack :	
00000024	5.05805206	[22572] MM5 [12148](R) Wait for event ID :1, delay :60000, callstack :	
00000026	15.08044147	[22572] MM5 [12148](R) Still waiting for event (callstacks) :	
00000027	15.08049297	[22572] MM5 [12148](R) Wait for event ID :1, delay :60000, callstack :	
00000028	15.08053398	[22572] MM5 [12148](R) Wait for event ID :1, delay :60000, callstack :	
00000801	22.82228088	[22572] MM5 [13492](R) TDevices.WMDeviceChangeToAll( wParam: 7 , lParam: 0)	
00000802	22.82235718	[22572] MM5 [13492](R) BQ: Currently running 1 threads of 30	
00000803	22.82284546	[22572] MM5 [13492](R) TDevices.WMDeviceChangeToAll( wParam: 7 , lParam: 0)	
00000804	22.82292557	[22572] MM5 [13492](R) BQ: Currently running 2 threads of 30	
00000805	22.82315254	[22572] MM5 [9140](R) BQ: Thread[9140] is executing new task now: TDevices.WMDeviceChangeToAll	
00000806	22.82341194	[22572] MM5 [17908](R) BQ: Thread[17908] is executing new task now: TDevices.WMDeviceChangeToAll	
00000807	22.82344246	[22572] MM5 [17908](R) TDevices.WMDeviceChangeToAll: already handled as last message	
00000808	22.82451248	[22572] iPod (MM5): [9140] DeviceChange: wParam: 7, devtype: -1	
00001548	25.08943939	[22572] MM5 [12148](R) Still waiting for event (callstacks) :	
00001549	25.08947754	[22572] MM5 [12148](R) Wait for event ID :1, delay :60000, callstack :	
00001550	25.08950615	[22572] MM5 [12148](R) Wait for event ID :1, delay :60000, callstack :	
00003868	26.61039352	[22572] MM5 [17908](R) Going 'Worker'to make final callback 17908	
00003869	26.61159706	[22572] MM5 [9140](R) Going 'Worker'to make final callback 9140	
00004091	27.82272720	[22572] MM5 [13492](R) TDevices.WMDeviceChangeToAll( wParam: 7 , lParam: 0)	
00004092	27.82279968	[22572] MM5 [13492](R) BQ: Currently running 1 threads of 30	
00004093	27.82312965	[22572] MM5 [13492](R) TDevices.WMDeviceChangeToAll( wParam: 7 , lParam: 0)	
00004094	27.82320023	[22572] MM5 [13492](R) BQ: Currently running 2 threads of 30	
00004095	27.82343102	[22572] MM5 [28712](R) BQ: Thread[28712] is executing new task now: TDevices.WMDeviceChangeToAll	
00004096	27.82361603	[22572] MM5 [340](R) BQ: Thread[340] is executing new task now: TDevices.WMDeviceChangeToAll	
00004097	27.82365417	[22572] MM5 [340](R) TDevices.WMDeviceChangeToAll: already handled as last message	
00004098	27.82471275	[22572] iPod (MM5): [28712] DeviceChange: wParam: 7, devtype: -1	
00004115	28.63006401	[22572] MM5 [13492](R) Check scheduled scan/sync for: MediaMonkey Server, Last scan: 1668575678313, Interval: 30000, now: 1668575708344	
00004116	28.63042641	[22572] MM5 [340](R) BQ: Thread[340] is executing new task now: Callstack: Script: file:///helpers/mediaSync.js ; Func: eval ; Row: 2860 ; Col: 20 	
00004121	28.63087654	[22572] MM5 [13492](R) sharing.getRemoteServers trace: Callstack: Script: file:///helpers/mediaSync.js ; Func: eval ; Row: 1949 ; Col: 47 	
00004138	28.63095665	[22572] MM5 [28712](R) BQ: Thread[28712] is executing new task now: Callstack: Script: file:///helpers/mediaSync.js ; Func: eval ; Row: 1949 ; Col: 47 	
00004143	28.63100243	[22572] MM5 [28712](R) TSharing.refreshRemoteServers starting	
00004144	28.63107491	[22572] MM5 [28712](R) DB open SQL: SELECT * FROM RemoteServers	
00004148	28.64156532	[22572] MM5 [28712](R) TSharing.refreshRemoteServers finished	
00004149	28.64245033	[22572] MM5 [13492](R) MediaMonkey Server is not syncable now	
00007610	31.86062050	[22572] MM5 [340](R) Going 'Worker'to make final callback 340	
00007611	31.86176872	[22572] MM5 [28712](R) Going 'Worker'to make final callback 28712	
00010592	35.10446167	[22572] MM5 [12148](R) Still waiting for event (callstacks) :	
00010593	35.10449219	[22572] MM5 [12148](R) Wait for event ID :1, delay :60000, callstack :	
00010594	35.10452271	[22572] MM5 [12148](R) Wait for event ID :1, delay :60000, callstack :	
00012257	45.12096786	[22572] MM5 [12148](R) Still waiting for event (callstacks) :	
00012258	45.12100601	[22572] MM5 [12148](R) Wait for event ID :1, delay :60000, callstack :	
00012259	45.12102890	[22572] MM5 [12148](R) Wait for event ID :1, delay :60000, callstack :	
00012263	48.63561249	[22572] MM5 [12148](R) New thread starting 1	
00012264	48.63645935	[22572] MM5 [11172](R) DB open SQL: SELECT Songs.ID, Songs.IDMedia, Songs.SongPath FROM Songs WHERE Songs.TrackType in (4,5,6,7) AND  NOT EXISTS (SELECT NULL FROM Covers WHERE Covers.IDSong=Songs.ID)	
00012265	48.63653183	[22572] MM5 [13492](R) registered task progress  1	
00012266	48.63705444	[22572] MM5 [11172](R) Going 'AutoCalcNormalization_Var'to make final callback 11172	
00012267	48.63707733	[22572] MM5 [11172](R) Thread 'AutoCalcNormalization_Var' is going to callback	
00012268	48.63741302	[22572] MM5 [13492](R) unregistered task progress  1	
00012269	48.63745117	[22572] MM5 [12148](R) BQ: Currently running 1 threads of 30	
00012270	48.63794708	[22572] MM5 [17576](R) BQ: Thread[17576] is executing new task now: SharedWindowsAppStartup	
00012271	48.63891220	[22572] MM5 [12148](R) BQ: Task took 63610 ms, stack: TCallBacks.ProcessEventDoneCallbacks	
00012272	49.00423813	[22572] MM5 [25656](R) MemRAM: 216.6 MB, MemPrivate: 182.3 MB, MemVirtual: 630.6 MB	
00012273	49.00426865	[22572] MM5 [25656](R) Allocated TBase: 8146, delta: 7896	
00012274	49.00429535	[22572] MM5 [25656](R) Allocated TGenThread: 2, delta: -4	
00012275	49.00432205	[22572] MM5 [25656](R) Allocated TTimer: 8, delta: 2	
00012276	49.00434875	[22572] MM5 [25656](R) Allocated TObjectPlus: 57, delta: 2	
00012277	49.00437927	[22572] MM5 [25656](R) Allocated TSharedObject: 7936, delta: 7722	
00012278	49.00440979	[22572] MM5 [25656](R) Allocated TSharedMediaObject: 41, delta: 33	
00012279	49.00443649	[22572] MM5 [25656](R) Allocated TSharedList: 224, delta: 167	
00012280	49.00445938	[22572] MM5 [25656](R) Allocated TSharedStringList: 17, delta: 10	
00012281	49.00448608	[22572] MM5 [25656](R) Allocated TSongListData: 6322, delta: 6322	
00012282	49.00451279	[22572] MM5 [25656](R) Allocated TSongList: 6, delta: 5	
00012283	49.00453949	[22572] MM5 [25656](R) Allocated TQueryPlus: 0, delta: -2	
00012284	49.00456238	[22572] MM5 [25656](R) Allocated TAlbum: 0, delta: 0	
00012285	49.00458908	[22572] MM5 [25656](R) Allocated TArtist: 0, delta: 0	
00012286	49.00461578	[22572] MM5 [25656](R) Allocated TPlaylist: 16, delta: 16	
00012287	49.00463867	[22572] MM5 [25656](R) Allocated TPodcast: 0, delta: 0	
00012288	49.00466537	[22572] MM5 [25656](R) Allocated TCover: 0, delta: 0	
00012289	49.00469208	[22572] MM5 [25656](R) Allocated TPromise: 1, delta: -1	
00012908	51.63849258	[22572] MM5 [17576](R) Going 'Worker'to make final callback 17576	
00012909	51.63943481	[22572] MM5 [12148](R) Going 'Worker'to make final callback 12148	
00015161	58.66709900	[22572] MM5 [13492](R) Check scheduled scan/sync for: MediaMonkey Server, Last scan: 1668575708344, Interval: 30000, now: 1668575738381	
00015162	58.66751862	[22572] MM5 [13492](R) BQ: Currently running 0 threads of 10	
00015163	58.66811371	[22572] MM5 [11012](R) BQ: Thread[11012] is executing new task now: Callstack: Script: file:///helpers/mediaSync.js ; Func: eval ; Row: 2860 ; Col: 20 	
00015168	58.66839600	[22572] MM5 [13492](R) sharing.getRemoteServers trace: Callstack: Script: file:///helpers/mediaSync.js ; Func: eval ; Row: 1949 ; Col: 47 	
00015185	58.66851807	[22572] MM5 [13492](R) BQ: Currently running 1 threads of 10	
00015186	58.66893387	[22572] MM5 [27616](R) BQ: Thread[27616] is executing new task now: Callstack: Script: file:///helpers/mediaSync.js ; Func: eval ; Row: 1949 ; Col: 47 	
00015191	58.66899872	[22572] MM5 [27616](R) TSharing.refreshRemoteServers starting	
00015192	58.66905594	[22572] MM5 [27616](R) DB open SQL: SELECT * FROM RemoteServers	
00015196	58.66942215	[22572] MM5 [27616](R) TSharing.refreshRemoteServers finished	
00015197	58.68046570	[22572] MM5 [13492](R) MediaMonkey Server is not syncable now	
00015198	61.66997910	[22572] MM5 [27616](R) Going 'Worker'to make final callback 27616	
00015199	61.67445755	[22572] MM5 [11012](R) Going 'Worker'to make final callback 11012	
00015321	72.98957825	[22572] MM5 [13492](R) TDevices.WMDeviceChangeToAll( wParam: 7 , lParam: 0)	
00015322	72.98965454	[22572] MM5 [13492](R) BQ: Currently running 0 threads of 10	
00015323	72.99028778	[22572] MM5 [30356](R) BQ: Thread[30356] is executing new task now: TDevices.WMDeviceChangeToAll	
00015324	72.99060822	[22572] MM5 [13492](R) TDevices.WMDeviceChangeToAll( wParam: 7 , lParam: 0)	
00015325	72.99074554	[22572] MM5 [13492](R) TDevices.WMDeviceChangeToAll( wParam: 7 , lParam: 0)	
00015326	72.99089813	[22572] MM5 [13492](R) TDevices.WMDeviceChangeToAll( wParam: 7 , lParam: 0)	
00015327	72.99160004	[22572] iPod (MM5): [30356] DeviceChange: wParam: 7, devtype: -1	
00015330	72.99169922	[22572] MM5 [30356](R) TDevices.WMDeviceChangeToAll: already handled as last message	
00015332	72.99175262	[22572] MM5 [30356](R) TDevices.WMDeviceChangeToAll: already handled as last message	
00015334	72.99179840	[22572] MM5 [30356](R) TDevices.WMDeviceChangeToAll: already handled as last message	
00015336	73.51045227	[22572] MM5 [13492](R) Main window is not minimized and hidden	
00015337	73.96185303	[22572] MM5 [13492](R) Main window is not minimized and hidden	
00015502	75.99198914	[22572] MM5 [30356](R) Going 'Worker'to make final callback 30356	
00017281	111.00395203	[22572] MM5 [22080](R) MemRAM: 217.7 MB, MemPrivate: 183.6 MB, MemVirtual: 628.4 MB	
00017282	111.00398254	[22572] MM5 [22080](R) Allocated TBase: 8148, delta: 2	
00017283	111.00402069	[22572] MM5 [22080](R) Allocated TGenThread: 0, delta: -2	
00017284	111.00404358	[22572] MM5 [22080](R) Allocated TTimer: 8, delta: 0	
00017285	111.00407410	[22572] MM5 [22080](R) Allocated TObjectPlus: 57, delta: 0	
00017286	111.00409698	[22572] MM5 [22080](R) Allocated TSharedObject: 7938, delta: 2	
00017287	111.00413513	[22572] MM5 [22080](R) Allocated TSharedMediaObject: 41, delta: 0	
00017288	111.00415802	[22572] MM5 [22080](R) Allocated TSharedList: 226, delta: 2	
00017289	111.00418854	[22572] MM5 [22080](R) Allocated TSharedStringList: 17, delta: 0	
00017290	111.00421143	[22572] MM5 [22080](R) Allocated TSongListData: 6322, delta: 0	
00017291	111.00423431	[22572] MM5 [22080](R) Allocated TSongList: 6, delta: 0	
00017292	111.00426483	[22572] MM5 [22080](R) Allocated TQueryPlus: 0, delta: 0	
00017293	111.00428772	[22572] MM5 [22080](R) Allocated TAlbum: 0, delta: 0	
00017294	111.00431061	[22572] MM5 [22080](R) Allocated TArtist: 0, delta: 0	
00017295	111.00434113	[22572] MM5 [22080](R) Allocated TPlaylist: 16, delta: 0	
00017296	111.00436401	[22572] MM5 [22080](R) Allocated TPodcast: 0, delta: 0	
00017297	111.00438690	[22572] MM5 [22080](R) Allocated TCover: 0, delta: 0	
00017298	111.00441742	[22572] MM5 [22080](R) Allocated TPromise: 1, delta: 0	
00017303	155.85673523	[22572] MM5 [5480](R) Disabling antifreeze detection
issue-19566-filtered.log (13,904 bytes)   
issue-19566.log (3,380,948 bytes)

Ludek

2022-11-16 11:21

developer   ~0070344

Last edited: 2022-11-16 11:27

 Based on the crash log it was UI thread freeze with JS callstack:
Callstack: Script: file:///mainwindow.js ; Func: undefined ; Row: 47 ; Col: 25

Watching the code there it is inside the
 app.listen(thisWindow, 'visibilitychanged', function (minimized, hidden, state) { .... }

So maybe the 'visibilitychanged' was somehow called too ofter during the NVIDIA graphics driver re-install?
If that was the case then we could add a prevention to not call it repeatedly?

Assigned to Petr as the 'visibilitychanged' event of window is his code/area. Note it might be valuable to test also with HW acceleration disabled to see whether it has any impact?

drakinite

2022-11-16 17:03

developer   ~0070348

1. Looks like disabling HW acceleration does prevent the crash.
2. The crash appears to occur during the "removing existing graphics driver" step (window stops responding and appears solid black/orange, see screenshot) and then the crash dialog appears a minute or so later.
3. Yes, tested it on both 5.0.3 and 5.01 and both crash during NVIDIA driver installation.
image.png (431,965 bytes)

drakinite

2023-04-05 16:54

developer   ~0071461

Last edited: 2023-12-14 19:21

 Note: Crash also occurs when updating Intel graphics drivers.

Edit: If it helps, got a crash ID CB7D34CC from music playing while Intel graphics drivers were being reinstalled