View Issue Details
| ID | Project | Category | View Status | Date Submitted | Last Update |
|---|---|---|---|---|---|
| 0015223 | MMW 5 | Podcasts | public | 2018-11-27 02:51 | 2019-05-15 20:41 |
| Reporter | rusty | Assigned To | |||
| Priority | urgent | Severity | crash | Reproducibility | sometimes |
| Status | closed | Resolution | reopened | ||
| Product Version | 5.0 | ||||
| Target Version | 5.0 | Fixed in Version | 5.0 | ||
| Summary | 0015223: MediaMonkey crashes on startup / experiences performance issues | ||||
| Description | This may be due to to either thumbnail generation OR to podcast updates (both are occurring in the background when the crash occurs). elog ID: F1D1D6C8 | ||||
| Tags | No tags attached. | ||||
| Attached Files | |||||
| Fixed in build | 2141 | ||||
| related to | 0014300 | closed | Ludek | MMW 5 | 'Reading files...' progress can stay forever |
| related to | 0015258 | closed | petr | MMW 5 | CPU Utilization sometimes stays at 50% on certain nodes |
| related to | 0015673 | closed | Ludek | MMW 5 | Occasional crash on startup (regression?) |
| related to | 0015236 | closed | Ludek | MMW v4 | Podcast updating is unnecessarily slow |
| related to | 0015283 | closed | Ludek | MMW 5 | Sync incomplete (due to locked DB) |
|
|
Based on the crash log there is "We haven't got Lock for 3 seconds !" assert in TDeviceCalculator.recalcAll() on the fCancelLock But analyzing the code there doesn't seem to be anything bad and it simply looks like the whole system (and all threads) were somehow frozen for several seconds (for some reason). I have seen this once on MM5 startup in the past (and also Peke was mentioning the similar issue) that sometimes (during MM5 startup) whole system looks like frozen (including Windows start menu). I guess whether it can be related to f_video plugin as I see in the log: 132.515s - PID:6976 - f_video:_DetectContainer:_Cannot detect container for D:\My Documents\Temp\dl\Geostorm 2017 1080p BRRip x264 AAC 5.1 - Hon3y\Geostorm 2017 1080p BRRip x264 AAC 5.1 - Hon3y.mkv. and later 142.718s - PID:6976 - f_video:_Launching process timeout 1:_WaitResult=258, StartMessage=2, decodeReason=8 Are you able to consistently reproduce the issue? And could you try whether it is related to the video info reading? e.g. by disabling f_video.dll plugin or removing the videos from NP? |
|
|
I can't consistently replicate the crash, however I can consistently replicate the poor performance on startup. It seems to be related to the combination of about 7 videos that MM5 always tries to generate thumbnails for (i.e. thumbnails never seem to get saved for these tracks). I had assumed that the failure to create these thumbnails (and the repeated attempts to do so on each startup was related to a permissions issue ( 0014345 ). But if it's due to a problem with these particular videos, I'll generate a debug log of what happens on startup. Edit: note that when f_video.dll is disabled, the thumbnail generation process is skipped. Note though: tagging operations also result in very high CPU utilization (rising from 30% to 60%). |
|
|
I cannot see any clear bug too, it seems, your HDD is extremely slow, already long time before thumb generation everything is loaded very very slowly. It slows everything down and probably sometimes can cause, that some lock is not available for more than 3s. I have made some adjustments, so thumbnail generation process is not started for files, which are not accessible, so this part should be a lot faster now. |
|
|
Resolving, please test with new build. |
|
|
With build 2136 I'm seeing 2 issues: 1) If podcasts have already been looked up, the 'hourglass' appears in the upper right corner for ~2 minutes on startup. Hovering the mouse over the hourglass causes a blank tooltip to appear (where normally the reason for the hourglass would appear). An hourglass should not appear without an accompanying status message. 2) On startup, when initially in a node that requires a web lookup and when podcasts haven't yet been downloaded: when I navigate to the Music > Location > D: node the 'hourglass' appears and the status bar indicates 'Reading files' for about 5 minutes before it goes away. Then it updates podcasts for another 5 minutes (during this10m period MM5 CPU utilization is at 75% ). Debug log attached in the next note. I believe that this is somehow related to |
|
|
In the log I see that it is really related to podcasts, there is one podcast SQL query that took more than 25 seconds on Rusty's machine. Strangely enough I have Rusty's database and the same query takes just 62 milliseconds !!! on my machine (same database). I will try to optimize the queries, but it looks that Rusty's machine really isn't in a good condition! |
|
|
a) SQL queries and DB access optimized in 2137 b) I see serious performance issues and high CPU activity when updating the "State Magazine Daily feed" ( http://feeds.feedburner.com/SlateMagazineDailyPodcast ) It has more than 8 MB of metadata to parse and MM is slow to parsing this (the feed includes almost 4K of episodes). Also opening the podcast link in a browser (e.g. Chrome) is very CPU intensive and takes over minute to parse and format the XML. => Significantly improved in 2137 + merged to MM4 as 0015236 |
|
|
Verified 2137 Note: In Firefox for me it takes less than 15s to download and show Feed. Only Feed photo takes longer. Same goes for NewsCrawler. |
|
|
In 2138, Podcast performance appears to be much improved, however there's still some sort of performance bottleneck on startup (I suspect related to thumbnail generation or avoidance thereof due to permission issues). In the attached log you can see: 1 startup 2 click Locations node --> normal performance 3 click Albums node --> 45s to load 4 click Locations node --> normal performance 5 click Albums node --> normal performance This behavior is repeatable i.e. at some point soon after startup, database performance seems to slow down for a period of time. Debug log attached. |
|
|
It is related to the Petr's re-working of Albums node (for the Albums+Tracks view), but also for the 'Art view' the albums are no longer loaded as album objects from the database, but whole tracklist (of all songs) is read from the database and albums are created from the tracklist. But from the log I see that the total tracklist loading time was 47078ms (47 seconds) for 12296 tracks on Rusty's machine. Started here: 00002880 22.11164093 [3056] MM5 [6868](R) TreeView.setNodePath FROM root/collection:1 TO root/collection:1/albums:1 00002881 22.12443924 [3056] MM5 [4828](R) DB open SQL: SELECT Songs.* FROM Songs WHERE Songs.TrackType in (0,4,3) 00002882 22.13508987 [3056] MM5 [6868](R) TreeView.setNodePath: this is the last expanded node, we are done, focus this node 00002883 22.16843987 [3056] MM5 [4828](R) ***** StandardSongQueryCopy starting finished here: 00003143 67.16497803 [3056] MM5 [1652](R) ***** StandardSongQueryCopy adding 2000 00003144 67.96675110 [3056] MM5 [10820](R) ***** StandardSongQueryCopy adding 4000 00003145 69.24507141 [3056] MM5 [4828](R) ***** StandardSongQueryCopy main loop finishing... isTaskTerminated: false 00003146 69.24529266 [3056] MM5 [4828](R) ***** StandardSongQueryCopy adding 4296 00003147 69.24955750 [3056] MM5 [4828](R) ***** total tracklist loading time 47078ms for 12296 Assigned to Petr for optimizations. ------------------------------------------------------- EDIT: On my machine (and Rusty's database) the same takes just 374ms for 12296 tracks. So it is 135x times faster on my 6 years old laptop (i7 @ 2.2 GHz / SSD) |
|
|
Tested build 2140, and the problem seems to be worse (could it be related to the fixes performed in 0015258 in this build? Anyhow, the issue is that soon after startup ( in Music > Location > D: > My Documents > Temp > DL > 226 50s & 60s Oldies (USA) (192kbps) ) --> Hourglass appears in upper right corner for about 2 minutes. Hovering over the hourglass ---> empty status bar appears Clicking the hourglass --> status bar doesn't appear at the bottom Log attached. Note that the hourglass appeared at around line 2300, and disappeared around line 2440. |
|
|
Here's a second log of the same issue, this time starting up in the Music node (just to show that the issue isn't related to Location node ). |
|
|
Note: I'm not sure if the slowness in the Album node ( 0015223:0051718 ) is a separate problem or not, but my suspicion is that it arose as a consequence of the startup slowness ('small hourglass' issue described above) which is related to thumbnail generation. |
|
|
Fixed |
|
|
Verified 2141. |
