Feedback on svn-1333

[grommet]

If I blow away the .db and start Firefly, it takes around 44 minutes to scan a ~20K file library now. (svn-1333 on Win32) Ouch. It’s definitely longer than earlier builds. (I’ll see if I can benchmark an old one again later.) iTunes clients work once again (no instant disconnect, like svn-1328)… and the connect speed is back to where it was from earlier builds. Thanks, Ron.

One “bug”: Firefly starts a rescan immediately after a full scan/load on startup… so, after finishing a 44 minute initial scan… it does it again immediately. IMHO, the rescan timer should start counting after the initial scan (or rescan) finishes. (I know I can “workaround” this by disabling the auto-rescan or setting the interval to something excessively long.)

2006-08-03 00:05:26 (76ea36f5): Full reload...

2006-08-03 00:05:27 (76ea36f5): Starting mp3 scan

2006-08-03 00:49:14 (76ea36f5): Processing static playlist: D:MusicMy PlaylistsKBER 90.5 FM Test Radio URL Playlist.m3u

2006-08-03 00:49:14 (76ea36f5): Playlist entry http:\wber.monroe.eduwber-high.m3u bad: Path not found

2006-08-03 00:49:14 (76ea36f5): Playlist entry  bad: Path not found

2006-08-03 00:49:14 (76ea36f5): Done processing playlist

2006-08-03 00:50:00 (76ea36f5): Starting web server from C:Program FilesFirefly Media Serveradmin-root on port 9999

2006-08-03 00:50:00 (76ea36f5): Registering rendezvous names

2006-08-03 00:50:01 (76ea36f5): Serving 20411 songs.  Startup complete in 2674 seconds

2006-08-03 00:50:01 (76ea36f5): Rescanning database

Note the “Rescanning database” at the end… right after the initial scan finished.

[fizze]

One “bug”: Firefly starts a rescan immediately after a full scan/load on startup… so, after finishing a 44 minute initial scan… it does it again immediately. IMHO, the rescan timer should start counting after the initial scan (or rescan) finishes. (I know I can “workaround” this by disabling the auto-rescan or setting the interval to something excessively long.)

It’s always been doing that.
I have set my rescan_period to 86400 (1 day), and its rescanning directly after the initial scan.

but the fact that my slug is running 24/7 more or less stable makes me dont worry about that.

[rpedde]

@grommet wrote:

One “bug”: Firefly starts a rescan immediately after a full scan/load on startup… so, after finishing a 44 minute initial scan… it does it again immediately. IMHO, the rescan timer should start counting after the initial scan (or rescan) finishes. (I know I can “workaround” this by disabling the auto-rescan or setting the interval to something excessively long.)

Fixed in svn.

I’d be interested in seeing your benchmark. What platform is this? Windows? If so, could you test it against 1311? I added the unicode translation stuff in that build, and that might be it.

— Ron

[grommet]

Yes, Windows. With svn-1311, it took about 38 minutes. This is pretty much the same speed as svn-1333. (Time difference is probably only related to what I’m doing on the same box while it’s scanning.)

2006-08-03 19:44:17 (76ea36f5): Full reload...

2006-08-03 19:44:18 (76ea36f5): Starting mp3 scan

2006-08-03 20:22:33 (76ea36f5): Processing static playlist: D:MusicMy PlaylistsKBER 90.5 FM Test Radio URL Playlist.m3u

2006-08-03 20:22:33 (76ea36f5): Playlist entry http:\wber.monroe.eduwber-high.m3u bad: Path not found

2006-08-03 20:22:33 (76ea36f5): Playlist entry  bad: Path not found

2006-08-03 20:22:33 (76ea36f5): Done processing playlist

2006-08-03 20:22:33 (76ea36f5): Scanning D:MusiciTunesiTunes Music Library.xml

2006-08-03 20:23:10 (76ea36f5): Starting web server from C:Program FilesFirefly Media Serveradmin-root on port 9999

2006-08-03 20:23:10 (76ea36f5): Registering rendezvous names

2006-08-03 20:23:11 (76ea36f5): Serving 20411 songs.  Startup complete in 2334 seconds

2006-08-03 20:23:11 (76ea36f5): Rescanning database

2006-08-03 20:25:48 (76ea36f5): Processing static playlist: D:MusicMy PlaylistsKBER 90.5 FM Test Radio URL Playlist.m3u

2006-08-03 20:25:48 (76ea36f5): Scanning D:MusiciTunesiTunes Music Library.xml

I’ll go back a few more versions when I have the chance and see when the slowdown really began. I know in svn-1206 (wow, that’s old)…. it was around 11 minutes. Is there any specific setting that I might have set that might cause a slowdown?

[rpedde]

@grommet wrote:

I’ll go back a few more versions when I have the chance and see when the slowdown really began. I know in svn-1206 (wow, that’s old)…. it was around 11 minutes. Is there any specific setting that I might have set that might cause a slowdown?

Probably at 1311. I added the stuff for proper unicode handling. I’m doing translations from utf-8 to unicode back and forth for every fopen, stat, or anything that requires a filename.

I’m guessing that’s it. I guess I could take a look at it again and see what I find on that. I didn’t imagine that would slow down scanning that much, but I bet that’s probably it. Don’t know what else changed on scans.

Particularly since I don’t see that on non-windows platforms. On my mac, for example, I’m doing a full scan of ~7k files in 270 seconds. That’s about on par with your 11 min/20k, and the only real difference is the unicode handling.

I don’t really have a windows box with a decent amount of songs on it, but I’ll try and replicate it.

[fizze]

I do have like 8K songs on my windows box, so I could test it and even compare it vs. the slug *lol*

In all seriousness, I can do that. Hope I find the time during the weekend.

I could even be over-funky and pick the HD from my slug and attach it to the windwos box, since its NTFS too. So its 1:1 the same library. Thinking about it, I also could copy the DB from the slug to that HD, so I have it in windoze 1:1, right ? Give n I use the same backend, that is.

[grommet]

I tried svn-1301 and got bad performance, too. So, it doesn’t look like it’s your Unicode translation. I guess that’s both good and bad… 8)

I had to go back to svn-1236 to get good initial scan performance. 20301 songs in 161 seconds (while the system is basically idle beyond Firefly and, at this point, with a very healthy system cache.) I also re-installed svn-1206, and it finished in 160 seconds, too.

A full scan under svn-1249, with the box doing nothing else, completed in 1188 seconds. So, it looks like a big performance impact was introduced after svn-1236… and a tiny bit more in later builds. Well, at least with Win32 on a SMP box. 😯 I guess I never noticed due to other issues and limiting my full scan rebuilds. My re-test of svn-1333 under similar conditions resulted in a 1498 second full scan.

While svn-1249 or up is doing the long initial scan, a single CPU is pegged at 100% most of the time and I/O seems minimal. (The songs.db file seems to jump to 9MB fairly quickly… and then growth slows down significantly. Not sure if that’s normal. The final size ends up around 32MB.)

Other related business: Can you add a “Rescanning database complete” message (or some statistic) to the Firefly log once it finishes a rescan. All I ever see in the log is “Rescanning database” at minimal debug levels, without a clue when it actually finishes. (I have no idea how long rescans take…)

[grommet]

Bug: Static iTunes playlists still sort by Artist name when seen on the SoundBridge… or something very close to that. For .m3u playlists, I can’t make sense of the order on the SoundBridge at all. (It really seems random.) In either case… no matter how it “really” sorts… it’s definitely not the order you see inside iTunes or in the .m3u files. ❓

For iTunes clients, the iTunes based playlists are sorted correctly (with correct_order=1 only). Yay. However, .m3u playlist entries are not in any obvious order… just like I see on the SoundBridge.

[rpedde]

@grommet wrote:

I had to go back to svn-1236 to get good initial scan performance. 20301 songs in 161 seconds (while the system is basically idle beyond Firefly and, at this point, with a very healthy system cache.) I also re-installed svn-1206, and it finished in 160 seconds, too.

Okay, I can track this down, then.

Other related business: Can you add a “Rescanning database complete” message (or some statistic) to the Firefly log once it finishes a rescan. All I ever see in the log is “Rescanning database” at minimal debug levels, without a clue when it actually finishes. (I have no idea how long rescans take…)

I’ll do something with that.

[grommet]

I still have to dig deeper, but it seems some of my track names/titles turned into filenames on a full rebuild scan (still svn-1333)… but only if the track was referenced in a .m3u based playlist. Not sure what is going on here… the rest of the metadata for the track is populated correctly. ❓

[Author]

Posts