Bug 2830 - MusicMagic Exporting songs takes hours...
: MusicMagic Exporting songs takes hours...
Status: RESOLVED FIXED
Product: Logitech Media Server
Classification: Unclassified
Component: MusicIP
: 6.5b1
: PC Windows (legacy)
: P2 normal (vote)
: ---
Assigned To: Dan Sully
:
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2006-01-16 18:27 UTC by treble
Modified: 2006-04-21 17:09 UTC (History)
3 users (show)

See Also:
Category: ---


Attachments
dunno why (455 bytes, patch)
2006-03-09 23:21 UTC, KDF
Details | Diff
Better patch (766 bytes, patch)
2006-03-09 23:58 UTC, Dan Sully
Details | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description treble 2006-01-16 18:27:19 UTC
Just installed the newest version of slimserver (6.5b1 - 5654 - Windows 2000 - EN - cp1252).

After a couple of hours it is still importing the MusicMagic Library. Looks like it is doing about 500 songs an hour..., and I have about 10,000 songs. With the 6.2 version it went way faster.
Comment 1 KDF 2006-01-16 19:00:21 UTC
I believe this is an MMM issue.  happens with latest RCs and have sent inquiry to Predixis regarding this.
Comment 2 treble 2006-01-16 19:30:19 UTC
Here are some entries from the logs...  Looks like it is going alphabetically through the song titles.

MusicMagic: Exporting song 1031: F:\Music\All Music\Music\' A B C D E\Clarence Clemons\1992 - The Big Man\01 - You're A Friend Of Mine.mp3
MusicMagic: export mode is: songs
MusicMagic: Exporting song 1032: F:\Music\All Music\Music\' K L M N O\Neil Young\2002 - Are You Passionate\01 - You're My Girl.mp3
MusicMagic: export mode is: songs
MusicMagic: Exporting song 1033: F:\Music\All Music\Music\' P Q R S T\Sade\1994 - The Best Of Sade\01 - Your Love Is King.mp3
MusicMagic: export mode is: songs
MusicMagic: Exporting song 1034: F:\Music\All Music\Music\VA\Kings Of African Music - 1997\01 - Youssou N'Dour - Set.mp3
MusicMagic: export mode is: songs
MusicMagic: Exporting song 1035: F:\Music\All Music\Music\' A B C D E\Black Uhuru\1981 - Red\01 - Youth Of Eglington.mp3
MusicMagic: export mode is: songs
MusicMagic: Exporting song 1036: F:\Music\All Music\Music\VA\CMJ New Music\Vol. 77, January 2000\01 - Zap Mama - Rafiki.mp3
MusicMagic: export mode is: songs
Comment 3 treble 2006-01-16 19:33:29 UTC
Regarding KDF's comment:
Thanks for the feedback.  Yes, hopefully Predixis has a fix...

I have been using MusicMagic 1.5 for a while now.  I think I upgraded to the new 1.5 version before I started using Slimserver 6.2.2 and then it went fast, or at least I didn't notice the hours of exporting.  I probably had 6.2.1 running before the MMM 1.5 upgrade.
Comment 4 KDF 2006-01-16 20:03:34 UTC
you can uninstall and go back to 6.2.1 if you wish to test this theory.  please report results if you do.
Comment 5 treble 2006-01-18 19:27:46 UTC
(In reply to comment #4)
> you can uninstall and go back to 6.2.1 if you wish to test this theory.  please
> report results if you do.

I went back to 6.2.1 and the MusicMagic scan went much faster.  Took less then an hour instead of one day for around 10K songs.  

Before downgrading I reinstalled the latest nightly of 6.5.  The scanning of MusicMagic took again so long.  So it seems to be something with 6.5.  Other then a missing date in front of the log entries, the log output looks the same....

Comment 6 KDF 2006-01-27 22:08:35 UTC
using a local copy at svn 5200, this scans 10k tracks in 20 minutes, which is normal.  I guess I'll try updating a bit at ta time to track down when things get slow.
Comment 7 KDF 2006-01-28 02:38:11 UTC
well, I got all the way up teh 5900 an 10400 tracks were taking between 890 and 1200 seconds to complete.  This was with MMM as teh ONLY source, no music folder.  However, after putting in the music folder and rescanning, I'm starting to see the long pauses after a few thousand songs. It seems to pause at the same place, at the end of a d_info block "updating file..."  long pause, then "numitems xxxx" an it goes again.  d_scan, d_sql, d_info, d_musicmagic show not much more than that.

will run one again using d_time and see if anything shows up in those waits

Comment 8 KDF 2006-01-28 03:08:19 UTC
once again, around song 6500, it started pausing.  d_time was not even showing any of the select_time: idlestreams messages.  CPU wnt up to 90% and just nothing at all in the log.  I guess the split-scanner will help with this, since it is sequential instead of the parallel scanning going on right now in 6.5. 
Comment 9 KDF 2006-03-07 19:49:52 UTC
d_http*, d_time, d_scheduler, d_scan, d_parse, d_musicmagic, d_import

The log is below.  note that there is a late timer, by nearly 12s.  Then it catches up.  Seems like something in the updateOrCreate is hooped.
-k


2006-03-07 19:46:52.1916 Updating file:///myth/music/Unsorted/PETER%20GABRIEL/Peter%20Gabriel%204/03%20-%20I%20Have%20The%20Touch.mp3 : bitrate to 104000
2006-03-07 19:47:03.9719 select_time: 0
2006-03-07 19:47:03.9728 firing timer 11.6633169651031 late.
2006-03-07 19:47:03.9752 settimer Normal: CODE(0x938caec), now: 1141789623.97523, time: 1141789624.2252 
2006-03-07 19:47:03.9761 select_time: 0
2006-03-07 19:47:03.9769 firing timer 11.0147929191589 late.
2006-03-07 19:47:03.9776 settimer Normal: CODE(0x92781d8), now: 1141789623.9776, time: 1141789624.96202 
2006-03-07 19:47:03.9862 select_time: 0
2006-03-07 19:47:03.9873 firing timer 10.9872369766235 late.
2006-03-07 19:47:03.9883 settimer Normal: CODE(0x92781d8), now: 1141789623.9883, time: 1141789624 
2006-03-07 19:47:03.9920 select_time: 0
2006-03-07 19:47:03.9929 firing timer 10.992870092392 late.
2006-03-07 19:47:03.9937 settimer Normal: CODE(0x92781d8), now: 1141789623.99364, time: 1141789624 
2006-03-07 19:47:03.9960 select_time: 0
2006-03-07 19:47:03.9969 firing timer 10.9967970848083 late.
2006-03-07 19:47:03.9976 settimer Normal: CODE(0x92781d8), now: 1141789623.99759, time: 1141789624 
2006-03-07 19:47:04.0008 select_time: 0
2006-03-07 19:47:04.0019 firing timer 11.0016191005707 late.
2006-03-07 19:47:04.0027 settimer Normal: CODE(0x92781d8), now: 1141789624.00269, time: 1141789625 
2006-03-07 19:47:04.0051 select_time: 0
2006-03-07 19:47:04.0061 firing timer 11.0060250759125 late.
2006-03-07 19:47:04.0070 settimer Normal: CODE(0x92781d8), now: 1141789624.00698, time: 1141789625 
2006-03-07 19:47:04.0094 select_time: 0
2006-03-07 19:47:04.0180 firing timer 10.9232640266418 late.
2006-03-07 19:47:04.0189 settimer Normal: CODE(0x95d7ebc), now: 1141789624.01887, time: 1141789625.01884 
2006-03-07 19:47:04.0197 select_time: 0
2006-03-07 19:47:04.0205 firing timer 10.9236240386963 late.
2006-03-07 19:47:04.0214 screenSaver idle display 3755.14645195007(mode:OFF.datetime)
2006-03-07 19:47:04.0224 settimer Normal: CODE(0x93f2670), now: 1141789624.02237, time: 1141789625.02126 
2006-03-07 19:47:04.0232 select_time: 0
2006-03-07 19:47:04.0241 firing timer 10.9237971305847 late.
2006-03-07 19:47:04.0248 screenSaver idle display 585.885517835617(mode:OFF.datetime)
2006-03-07 19:47:04.0257 settimer Normal: CODE(0x93f2670), now: 1141789624.02566, time: 1141789625.02468 
2006-03-07 19:47:04.0265 select_time: 0
2006-03-07 19:47:04.0273 firing timer 10.9174399375916 late.
2006-03-07 19:47:04.0281 screenSaver idle display 3809.13987112045(mode:OFF.datetime)
2006-03-07 19:47:04.0289 settimer Normal: CODE(0x93f2670), now: 1141789624.02891, time: 1141789625.02796 
2006-03-07 19:47:04.0299 select_time: 0
2006-03-07 19:47:04.0308 firing timer 10.9173061847687 late.
2006-03-07 19:47:04.0315 screenSaver idle display 3810.65717291832(mode:OFF.datetime)
2006-03-07 19:47:04.0324 settimer Normal: CODE(0x93f2670), now: 1141789624.0324, time: 1141789625.03145 
2006-03-07 19:47:04.0332 select_time: 0
2006-03-07 19:47:04.0342 firing timer 10.9166288375854 late.
2006-03-07 19:47:04.0350 screenSaver idle display 3806.07301998138(mode:OFF.datetime)
2006-03-07 19:47:04.0359 settimer Normal: CODE(0x93f2670), now: 1141789624.03583, time: 1141789625.03486 
2006-03-07 19:47:04.0367 select_time: 0
2006-03-07 19:47:04.0375 firing timer 10.9164800643921 late.
2006-03-07 19:47:04.0385 screenSaver idle display 3827.60209393501(mode:OFF.alarmtime)
2006-03-07 19:47:04.0395 settimer Normal: CODE(0x93f2670), now: 1141789624.03945, time: 1141789625.03837 
2006-03-07 19:47:04.0403 select_time: 0
2006-03-07 19:47:04.0411 firing timer 10.9166178703308 late.
2006-03-07 19:47:04.0420 settimer Normal: CODE(0x97f58b8), now: 1141789624.04199, time: 1141789625.04196 
2006-03-07 19:47:04.0428 select_time: 0
2006-03-07 19:47:04.0436 firing timer 1.91622400283813 late.
2006-03-07 19:47:04.0446 settimer Normal: CODE(0xa5fa404), now: 1141789624.04456, time: 1141789634.04454 
2006-03-07 19:47:04.0454 select_time: 0
2006-03-07 19:47:04.0518 firing timer 1.92190599441528 late.
2006-03-07 19:47:04.0527 settimer Normal: CODE(0xa5cef54), now: 1141789624.0527, time: 1141789634.05265 
2006-03-07 19:47:04.0535 select_time: 0
2006-03-07 19:47:04.0546 firing timer 0.054502010345459 late.
2006-03-07 19:47:04.0554 settimer Normal: CODE(0x92781d8), now: 1141789624.05537, time: 1141789625 
2006-03-07 19:47:04.0585 select_time: 0
2006-03-07 19:47:04.0594 firing timer 0.0593259334564209 late.
2006-03-07 19:47:04.0601 settimer Normal: CODE(0x92781d8), now: 1141789624.06013, time: 1141789625 
2006-03-07 19:47:04.0623 select_time: 0
Comment 10 KDF 2006-03-09 23:21:53 UTC
Created attachment 1162 [details]
dunno why

but this speeds things up BIGTIME.  I tracked it down to the $genreObj->delete and discovered that at some points it  was taking up to 40 seconds to do that one line.  adding this patch fixes this.  I have no idea why tracks are getting a "" genre that would need to be deleted.  I guess the delay is the server having to find the empty strings to delete.
Comment 11 Dan Sully 2006-03-09 23:58:11 UTC
Created attachment 1163 [details]
Better patch

Try this instead..
Comment 12 KDF 2006-03-10 20:24:43 UTC
*** Bug 3126 has been marked as a duplicate of this bug. ***
Comment 13 KDF 2006-03-10 20:50:47 UTC
updated patch works, with playlist folder and musicfolder scan simultaneously.  10400 tracks in 1700 seconds (as opposed to well ovoer 10 hours prior to the patch).  I've merged the patch into change 6553 for 6.5 and 6.2.2 builds.  Please let us know if that works better for you.
Comment 14 Dan Sully 2006-04-21 17:09:59 UTC
Fixes have been commited - closing this bug.

Please reopen if you have issues still.

Thanks.