Bugzilla – Bug 3896
initial scan doesn't do anything
Last modified: 2008-09-15 14:39:24 UTC
Using SlimServer Version: 6.5b1 - 8880 - Windows XP - EN - cp1252 with MySQL 5.0 and MusicMagic. Did a clean install of SlimServer, went into server settings, and selected "Clear and rescan everything." After 20 minutes, checked status and saw that no albums/tracks/artists/etc. were present. All MySQL tables except metainformation were empty. Running from command line with --d_cli --d_sql --d_mysql shows a few initial queries on startup, then this: 2006-08-09 12:35:55.2464 SELECT me.name, me.value FROM metainformation me WHERE ( name = ? ): 'isScanning' No errors are thrown. MySQL, MusicMagic, and SlimServer services are all running. I've verified the MySQL database user specified in slimserer.pref can connect to the database with no problem. So far I've waited 25 minutes with no more output from the CLI and no data appearing in MySQL. I can browse the music folder OK, when I do, tracks are added to the tracks table, but nothing is picked up by the scanner.
Forgot to mention, I am also using --d_scan. I am using MusicIP Mixer Version 1.7.
Update: After about 40 minutes, the scan finally began and the MySQL tables are filling up OK. Not sure if the long startup time counts as a bug or not, but I had not seen this behavior in previous versions (6.2., 6.3, or previous 6.5 builds).
I notice the same thing when starting a clear/rescan. Is it the evidence of some kind of bug or is it expected behavior? I never got a reply to the question posted in the forums. http://forums.slimdevices.com/showthread.php?t=25689
It sounds to me like a bug. Doesn't seem like it should take 20 minutes for scanning to start. That said, I haven't seen this behavior yet.
Jordan or Jim, are you still having this issue?
Yes, I believe so. Just ran a small test: I started a clear/rescan and it took 08:20 before the database began to be populated. The clear took place immediately, and isScanning went to 1 and lastRescanTime to 0 at the same time. During that time period disk activity was fairly low, then at 08:20 it began to be constant and very heavy. But I haven't had much time to do more extensive testing. I'd like to try Dan's suggestion (from the forums) to try some different debugging switches to see what's happening, and to try running with the built-in MySQL server.
Yeah Dan said you guys were talking about it on the forums, and that maybe it sounded like Jordan wasn't seeing this anymore.
Hey there - I actually am still seeing this issue (using SlimServer Version: 6.5b1 - 8984 - Windows XP - EN - cp1252). I am running a clear & rescan right now to look into a separate musicmagic issue, and it seems that there is still a long lag time between starting the scan and anything actually being scanned. I'm not sure exactly how long it is (I'm not using --d_sql at the moment and that's the easiest way I can tell in the log file when the scan actually begins picking up data) but I am using --d_musicmagic, --d_import, and --d_scan. I'm happy to post my log file here when my latest scan is done if it might help illuminate this issue.
Christopher, Started a clear and rescan last night. As you can see from the time stamps in these log file lines, there is a long delay between initiating the scan and the scan actually beginning: 2006-08-18 23:12:19.5352 Import: Starting Slim::Music::MusicFolderScan scan 2006-08-18 23:40:25.2660 Found 30079 files in \\Readynas_nv\media\Music
Jordan - can you run with --d_scan ? That will give me a better idea of what's going on. Your music collection is on a network drive, is everything tuned properly on the ReadyNAS?
Created attachment 1455 [details] Latest nightly log file (8/19/2006) Using --d_scan, --d_musicmagic, --d_import, --d_sql
Dan - sorry about the giant log file, I'm tracking a couple bugs at once at the moment and wanted to use one log file to capture information for each one. I believe everything is working fine on my NAS, I'm using the recommended settings and have not had any problems with it - and the long lag time for a scan did not occur in SlimServer 6.3.1 (or even in some older versions of 6.5 from a couple months back). Thanks for your help.
I also have my music files on a ReadyNAS separate from the SlimServer. The log below shows the 'delay' in populating the database - in this case about 7 1/2 minutes before the scan starts adding anything to the database. 2006-08-20 15:03:08.8429 Import: Adding Slim::Music::PlaylistFolderScan Scan 2006-08-20 15:03:08.8525 Import: Adding Slim::Music::MusicFolderScan Scan 2006-08-20 15:03:08.8947 Import: Wiped all in-memory caches. 2006-08-20 15:03:08.8948 Import: Start schema_clear 2006-08-20 15:03:08.9051 Import: Start schema_optimize 2006-08-20 15:03:10.7805 Import: End schema_optimize 2006-08-20 15:03:10.7808 Import: End schema_clear 2006-08-20 15:03:10.7809 Import: Wiped info database 2006-08-20 15:03:10.7810 Import: Starting Slim::Music::MusicFolderScan scan 2006-08-20 15:10:35.8132 Found 11588 files in \\bob\music\flac Is this simply the expected behavior, or is the time it's taking unexpectedly long for that many files? Overall, the clear/rescan takes about 30 minutes on my system, including the artwork scan. By arriving at that file count, SlimServer must have traversed the entire music folder directory tree at that point. I can't tell what other information is being gathered during this phase, but I'd assume some type of in-memory data structure is being constructed prior to looking into the files in-depth and adding the detailed track info to the database. I don't recall ever seeing this behavior prior to the split-scanner, but if that's how the new scanner works, then that's just how it works.
That's how the new scan works. We need to resolve any symlinks or windows short cuts to give a proper count (for the progress bar) we also need to do so to find new and removed files between disk and database.
Ok, that makes sense. Jordan's 22:00 to complete this pass for 30,000 files is in line with 7.5 minutes to count my 11,500 files. Are those the only reasons for making this pass through the music library? When doing a clear/rescan the disk vs. database issue doesn't exist. And I think we could both live without a progress bar if it takes that long just to count the files.
I agree, I could live without the progress bar if it's the cause of the long lag time - but if it's already in the works as a new feature, this isn't a huge deal, just a minor inconvenience. In fact, should I downgrade the severity of this bug from "major" to "minor" or something else? I don't know if you guys set the severities or if I should mess with it - I think I selected "major" initially because I thought the scan was never coming back at all.
To clarify: The on disk / on database check is only done when a rescan is requested, not a wipe / empty db. The progress bar right now is only on the command line, but in the future there will be a web status as well, which many have asked for, and will provide information about the status of the scan.
So perhaps I should change the summary of this bug to 'scanner progress bar on web ui' and mark it as an enhancement for 'future'? Or are there other remaining issues?
I think it can be closed as perhaps INVALID or WORKSFORME, since the behavior is apparently by design and a factor of needing to make that first pass through the music library in order to display a scan progress bar. I would change the summary to something like 'clear/rescan takes a long time to begin adding tracks to database' so that future searches might find it. I think a worthy enhancement request, though, would be an option to disable the scanning progress bar and this initial pass through the library. It remains to be seen what the time penalty is for servers with libraries on local disks - perhaps it's not as severe as what we're seeing with the library on an NAS. A time savings of 25% for a scan would be significant for those of us with large libraries.
FYI, The behavior is required, no matter if the progress bar is required or not. Finding 23k files on a 933Mhz pentium (with scsi disks) takes just over 30 seconds. 2006-08-22 16:34:29.9513 Import: Adding Slim::Music::PlaylistFolderScan Scan 2006-08-22 16:34:29.9714 Import: Adding Slim::Music::MusicFolderScan Scan 2006-08-22 16:34:29.9929 Import: Starting Slim::Music::MusicFolderScan scan 2006-08-22 16:34:29.9938 About to look for files in /var/music/music 2006-08-22 16:34:29.9960 For files with extensions in: [(?i-xsm:\.(?:ape|wma|shn|wav|wave|mp3|mp2|flc|flac|m4a|mov|m4b|mp4|mp+|mpc|ogg|aif|aiff|cue)$)] 2006-08-22 16:35:02.7909 Found 23305 files in /var/music/music
FYI, I checked in some changes the other day that has the scanner checkpointing to the database more often. Please give the latest nightly a try. Thanks
Jordan, is this still an issue?
Ping
I think the only remaining issue is whether or not the time being taken to run the scanner's initial pass across the network can be considered unusually high. Could just be a factor of the speed (or lack thereof) of the Infrant NAS.
Agreed, and is nothing we can really fix. The file scanning needs to happen one way or another. With the database commits happening more often, I'm going to close this bug.