Extremely slow rescan after "force rescan"

[Pawel]

I performed "force rescan" on about 100000 images. In over 24 hours IMatch managed to rescan about 59000 images, however I had to restart the process several times because after processing some images IMatch stops doing anything - it just sits here with 0,5% CPU utilization and imports metadata with a speed of about 10 images every two minutes.
After "Dismissing" the "Importing metadata" dialog and restarting IMatch (close, wait for background tasks to complete, restart) there is a long pause, then about 1500-2500 images is imported and again hardly any activity...

What can I do to speed things up?

[sinus]

I do not know really.

But I would cut these 100'000 in 10 - 15 pieces. Gives more work, ok, but from my experiences IMatch works faster, if I take only, say 5'000 images instead 20'000.
I do not know, is this true with some technical explanation.

But I spottet for example, if I do a write-back (not rescan) of say, 50'000 images, it works much quicker, if I select not all 50'000, but pieces of 5'000 or even 3'000.

But as I said, this could be not true, it is only my feeling and my experience.

[Pawel]

OK, that might do the trick - although now I would like to finish the rescan I initiated yesterday, especially after 60000 files rescanned.

What I see is that after I restart IMatch everytime the queue of images to process is shorter: 77000, 60000, now 41136 - yet the processing seems to be stuck earlier and earlier everytime... Now, for example, after restart, IMatch processed about 2800 files, then sat for about 15 minutes doing nothing (0,5% CPU, 10 images/5 minutes), then suddently imported about 400 images in under three minutes and now for about 10 minutes it sits idle again.

[rafiki]

If there is a solution I'd like to know it. It took me days to rescan 80000 images.
(W10 64 bit, 16 GB RAM, Samsung 1TB 850 Pro SSD)

[Pawel]

IMATCH5_LOG.TXT is full of "database table is locked":

Code Select Expand

11.17 21:15:04+ 4218 [1938] 00  I>   # Process Memory Info: WSC: 450MB, WSP: 457MB (NEW PEAK), PF: 1260539
11.17 21:15:04+   16 [1938] 00  M>   <  2 [9969ms #sl] CMainFrame::LoadDatabase
11.17 21:15:04+    0 [1938] 00  M>  <  1 [20859ms #sl] CIMatchApp::InitInstance
11.17 21:15:05+  594 [1938] 00  M>  >  1 CIMGeoLocationManager::GetLocations  'IMGeoLocation.cpp(179)'
11.17 21:15:05+    0 [1938] 00  M>  <  1 CIMGeoLocationManager::GetLocations
11.17 21:15:38+33234 [2874] 02  I> Locking mode is EXCLUSIVE
11.17 21:15:38+    0 [2874] 02  I> Locking mode is EXCLUSIVE
11.17 21:15:38+    0 [2874] 02  I> Locking mode is EXCLUSIVE
11.17 21:16:23+44844 [2AF0] 01  W> 'database table is locked' [6]  'IMSQLite.cpp(2388)'
11.17 21:16:23+    0 [2AF0] 01  W> BEGIN IMMEDIATE TRANSACTION  'IMSQLite.cpp(2389)'
11.17 21:16:23+    0 [2AF0] 01  W> 'database table is locked' [6]  'IMSQLite.cpp(2394)'
11.17 21:16:23+    0 [2AF0] 01  W> BEGIN IMMEDIATE TRANSACTION  'IMSQLite.cpp(2395)'
11.17 21:16:28+ 4953 [0CD0] 01  W> 'database table is locked' [6]  'IMSQLite.cpp(2388)'
11.17 21:16:28+    0 [0CD0] 01  W> BEGIN IMMEDIATE TRANSACTION  'IMSQLite.cpp(2389)'
11.17 21:16:28+    0 [0CD0] 01  W> 'database table is locked' [6]  'IMSQLite.cpp(2394)'
11.17 21:16:28+    0 [0CD0] 01  W> BEGIN IMMEDIATE TRANSACTION  'IMSQLite.cpp(2395)'
11.17 21:16:30+ 2391 [1CC8] 01  W> 'database table is locked' [6]  'IMSQLite.cpp(2388)'
11.17 21:16:30+    0 [1CC8] 01  W> DELETE FROM md_tag_data WHERE oid = ?1 AND tag_oid = ?2  'IMSQLite.cpp(2389)'
11.17 21:16:30+    0 [1CC8] 01  W> 'database table is locked' [6]  'IMSQLite.cpp(2394)'
11.17 21:16:30+    0 [1CC8] 01  W> DELETE FROM md_tag_data WHERE oid = ?1 AND tag_oid = ?2  'IMSQLite.cpp(2395)'
11.17 21:17:23+52703 [2AF0] 01  W> 'database table is locked' [6]  'IMSQLite.cpp(2388)'
11.17 21:17:23+    0 [2AF0] 01  W> BEGIN IMMEDIATE TRANSACTION  'IMSQLite.cpp(2389)'
11.17 21:17:23+    0 [2AF0] 01  W> 'database table is locked' [6]  'IMSQLite.cpp(2394)'
11.17 21:17:23+    0 [2AF0] 01  W> BEGIN IMMEDIATE TRANSACTION  'IMSQLite.cpp(2395)'
11.17 21:17:30+ 7656 [1CC8] 01  W> 'database table is locked' [6]  'IMSQLite.cpp(2388)'
11.17 21:17:30+    0 [1CC8] 01  W> DELETE FROM md_tag_data WHERE oid = ?1 AND tag_oid = ?2  'IMSQLite.cpp(2389)'
11.17 21:17:30+    0 [1CC8] 01  W> 'database table is locked' [6]  'IMSQLite.cpp(2394)'
11.17 21:17:30+    0 [1CC8] 01  W> DELETE FROM md_tag_data WHERE oid = ?1 AND tag_oid = ?2  'IMSQLite.cpp(2395)'
11.17 21:18:23+52359 [2AF0] 01  W> 'database table is locked' [6]  'IMSQLite.cpp(2388)'
11.17 21:18:23+    0 [2AF0] 01  W> BEGIN IMMEDIATE TRANSACTION  'IMSQLite.cpp(2389)'
11.17 21:18:23+    0 [2AF0] 01  W> 'database table is locked' [6]  'IMSQLite.cpp(2394)'
11.17 21:18:23+    0 [2AF0] 01  W> BEGIN IMMEDIATE TRANSACTION  'IMSQLite.cpp(2395)'
11.17 21:18:31+ 7985 [1CC8] 01  W> 'database table is locked' [6]  'IMSQLite.cpp(2388)'


Closing IMatch takes forever (about 5 minutes) before exiftool tasks exit... Database diagnosis didn't help, neither compact and optimization or repair did.

After all exiftool tasks exit, IMatch logs this:

Code Select Expand

11.17 21:26:18+    0 [1CC8] 01  W> SELECT DISTINCT oid FROM md_tag_data WHERE flags & (1|2|4) AND IFNULL(lang,'') = ?1 UNION SELECT DISTINCT oid FROM md_tag_data_wb WHERE IFNULL(lang,'') = ?1 ORDER BY oid DESC  'IMSQLite.cpp(2389)'
11.17 21:26:18+    0 [1CC8] 01  W> 'library routine called out of sequence' [21]  'IMSQLite.cpp(932)'
11.17 21:26:18+    0 [1CC8] 01  W> 'library routine called out of sequence' [21]  'IMSQLite.cpp(2388)'
11.17 21:26:18+    0 [1CC8] 01  W> SELECT DISTINCT oid FROM md_tag_data WHERE flags & (1|2|4) AND IFNULL(lang,'') = ?1 UNION SELECT DISTINCT oid FROM md_tag_data_wb WHERE IFNULL(lang,'') = ?1 ORDER BY oid DESC  'IMSQLite.cpp(2389)'
11.17 21:26:18+    0 [1CC8] 01  W> 'library routine called out of sequence' [21]  'IMSQLite.cpp(932)'
11.17 21:26:18+    0 [1CC8] 01  W> 'library routine called out of sequence' [21]  'IMSQLite.cpp(2388)'
11.17 21:26:18+    0 [1CC8] 01  W> SELECT DISTINCT oid FROM md_tag_data WHERE flags & (1|2|4) AND IFNULL(lang,'') = ?1 UNION SELECT DISTINCT oid FROM md_tag_data_wb WHERE IFNULL(lang,'') = ?1 ORDER BY oid DESC  'IMSQLite.cpp(2389)'
11.17 21:26:18+    0 [1CC8] 01  W> 'library routine called out of sequence' [21]  'IMSQLite.cpp(932)'
11.17 21:26:18+    0 [1CC8] 01  W> 'library routine called out of sequence' [21]  'IMSQLite.cpp(2388)'
11.17 21:26:18+    0 [1CC8] 01  W> SELECT DISTINCT oid FROM md_tag_data WHERE flags & (1|2|4) AND IFNULL(lang,'') = ?1 UNION SELECT DISTINCT oid FROM md_tag_data_wb WHERE IFNULL(lang,'') = ?1 ORDER BY oid DESC  'IMSQLite.cpp(2389)'
11.17 21:26:18+    0 [1CC8] 01  W> 'library routine called out of sequence' [21]  'IMSQLite.cpp(932)'
11.17 21:26:18+    0 [1CC8] 01  W> 'library routine called out of sequence' [21]  'IMSQLite.cpp(2388)'
11.17 21:26:18+    0 [1CC8] 01  W> SELECT DISTINCT oid FROM md_tag_data WHERE flags & (1|2|4) AND IFNULL(lang,'') = ?1 UNION SELECT DISTINCT oid FROM md_tag_data_wb WHERE IFNULL(lang,'') = ?1 ORDER BY oid DESC  'IMSQLite.cpp(2389)'
11.17 21:26:18+    0 [1CC8] 01  W> 'library routine called out of sequence' [21]  'IMSQLite.cpp(932)'
11.17 21:26:18+    0 [1CC8] 01  W> 'library routine called out of sequence' [21]  'IMSQLite.cpp(2388)'
11.17 21:26:18+    0 [1CC8] 01  W> SELECT DISTINCT oid FROM md_tag_data WHERE flags & (1|2|4) AND IFNULL(lang,'') = ?1 UNION SELECT DISTINCT oid FROM md_tag_data_wb WHERE IFNULL(lang,'') = ?1 ORDER BY oid DESC  'IMSQLite.cpp(2389)'
11.17 21:26:18+   16 [1CC8] 02  I>     Database '' for thread 0 (0)  Database file read-only/on read-only media. Read-only requested.
11.17 21:26:18+    0 [1CC8] 02  I>     Failed to open file (3)
11.17 21:26:18+    0 [200C] 00  E> ...  'PTMetabase.cpp(2457)'
11.17 21:26:18+    0 [200C] 02  I>     Database '' for thread 200C (8204)  Database file read-only/on read-only media. Read-only requested.
11.17 21:26:18+    0 [0CD0] 00  E> ...  'PTMetabase.cpp(2457)'
11.17 21:26:18+    0 [1CC8] 02  I>     Database '' for thread 1CC8 (7368)  Database file read-only/on read-only media. Read-only requested.
11.17 21:26:18+    0 [0CD0] 02  I>     Database '' for thread CD0 (3280)  Database file read-only/on read-only media. Read-only requested.
11.17 21:26:18+    0 [0CD0] 02  I>     Failed to open file (3)
11.17 21:26:18+    0 [1CC8] 02  I>     Failed to open file (3)
11.17 21:26:18+    0 [200C] 02  I>     Failed to open file (3)
11.17 21:26:18+    0 [0CD0] 00  E> CIMSQ: Error: 'SQL logic error or missing database' [1] [Extended: 1]  'IMSQLite.cpp(230)'
11.17 21:26:18+    0 [200C] 00  E> CIMSQ: Error: 'SQL logic error or missing database' [1] [Extended: 1]  'IMSQLite.cpp(230)'
11.17 21:26:18+    0 [1CC8] 02  I>     Failed to open file (3)
11.17 21:26:18+    0 [0CD0] 00  E> ...  'IMEngineUpdateQueue.cpp(2851)'
11.17 21:26:18+    0 [200C] 00  E> ...  'IMEngineUpdateQueue.cpp(2851)'
11.17 21:26:18+    0 [1CC8] 01  W> 'library routine called out of sequence' [21]  'IMSQLite.cpp(2388)'
11.17 21:26:18+    0 [1CC8] 01  W> SELECT DISTINCT oid FROM md_tag_data WHERE flags & (1|2|4) AND IFNULL(lang,'') = ?1 UNION SELECT DISTINCT oid FROM md_tag_data_wb WHERE IFNULL(lang,'') = ?1 ORDER BY oid DESC  'IMSQLite.cpp(2389)'
11.17 21:26:18+    0 [1CC8] 01  W> 'library routine called out of sequence' [21]  'IMSQLite.cpp(932)'
11.17 21:26:18+    0 [1CC8] 01  W> 'library routine called out of sequence' [21]  'IMSQLite.cpp(2388)'
11.17 21:26:18+    0 [1CC8] 01  W> SELECT DISTINCT oid FROM md_tag_data WHERE flags & (1|2|4) AND IFNULL(lang,'') = ?1 UNION SELECT DISTINCT oid FROM md_tag_data_wb WHERE IFNULL(lang,'') = ?1 ORDER BY oid DESC  'IMSQLite.cpp(2389)'
11.17 21:26:18+    0 [1CC8] 01  W> 'library routine called out of sequence' [21]  'IMSQLite.cpp(932)'
11.17 21:26:18+    0 [1CC8] 01  W> 'library routine called out of sequence' [21]  'IMSQLite.cpp(2388)'
11.17 21:26:18+    0 [1CC8] 01  W> SELECT DISTINCT oid FROM md_tag_data WHERE flags & (1|2|4) AND IFNULL(lang,'') = ?1 UNION SELECT DISTINCT oid FROM md_tag_data_wb WHERE IFNULL(lang,'') = ?1 ORDER BY oid DESC  'IMSQLite.cpp(2389)'
11.17 21:26:18+    0 [1CC8] 01  W> 'library routine called out of sequence' [21]  'IMSQLite.cpp(932)'
11.17 21:26:18+    0 [1CC8] 01  W> 'library routine called out of sequence' [21]  'IMSQLite.cpp(2388)'
11.17 21:26:18+    0 [1CC8] 01  W> SELECT DISTINCT oid FROM md_tag_data WHERE flags & (1|2|4) AND IFNULL(lang,'') = ?1 UNION SELECT DISTINCT oid FROM md_tag_data_wb WHERE IFNULL(lang,'') = ?1 ORDER BY oid DESC  'IMSQLite.cpp(2389)'
11.17 21:26:18+    0 [1CC8] 01  W> 'library routine called out of sequence' [21]  'IMSQLite.cpp(932)'
11.17 21:26:18+    0 [1CC8] 01  W> 'library routine called out of sequence' [21]  'IMSQLite.cpp(2388)'
11.17 21:26:18+    0 [1CC8] 01  W> SELECT DISTINCT oid FROM md_tag_data WHERE flags & (1|2|4) AND IFNULL(lang,'') = ?1 UNION SELECT DISTINCT oid FROM md_tag_data_wb WHERE IFNULL(lang,'') = ?1 ORDER BY oid DESC  'IMSQLite.cpp(2389)'
11.17 21:26:18+    0 [1CC8] 01  W> 'library routine called out of sequence' [21]  'IMSQLite.cpp(932)'
11.17 21:26:18+    0 [1CC8] 01  W> 'library routine called out of sequence' [21]  'IMSQLite.cpp(2388)'
11.17 21:26:18+    0 [1CC8] 01  W> SELECT DISTINCT oid FROM md_tag_data WHERE flags & (1|2|4) AND IFNULL(lang,'') = ?1 UNION SELECT DISTINCT oid FROM md_tag_data_wb WHERE IFNULL(lang,'') = ?1 ORDER BY oid DESC  'IMSQLite.cpp(2389)'
11.17 21:26:18+    0 [1CC8] 01  W> 'library routine called out of sequence' [21]  'IMSQLite.cpp(932)'
11.17 21:26:18+    0 [1CC8] 01  W> 'library routine called out of sequence' [21]  'IMSQLite.cpp(2388)'
11.17 21:26:18+    0 [1CC8] 01  W> SELECT DISTINCT oid FROM md_tag_data WHERE flags & (1|2|4) AND IFNULL(lang,'') = ?1 UNION SELECT DISTINCT oid FROM md_tag_data_wb WHERE IFNULL(lang,'') = ?1 ORDER BY oid DESC  'IMSQLite.cpp(2389)'
11.17 21:26:18+    0 [1CC8] 01  W> 'library routine called out of sequence' [21]  'IMSQLite.cpp(932)'
11.17 21:26:18+    0 [1CC8] 01  W> 'library routine called out of sequence' [21]  'IMSQLite.cpp(2388)'
11.17 21:26:18+    0 [1CC8] 01  W> SELECT DISTINCT oid FROM md_tag_data WHERE flags & (1|2|4) AND IFNULL(lang,'') = ?1 UNION SELECT DISTINCT oid FROM md_tag_data_wb WHERE IFNULL(lang,'') = ?1 ORDER BY oid DESC  'IMSQLite.cpp(2389)'
11.17 21:26:18+    0 [1CC8] 01  W> 'library routine called out of sequence' [21]  'IMSQLite.cpp(932)'
11.17 21:26:18+    0 [1938] 00  I> # Logfile closed.


[Mario]

Run a diagnosis on the database.
Make sure that your virus checker does not interfere, exclude the entire folder containing the database.
Posting fragments of the log file out of sequence only spoils the community search engine, but does not give us any usable info.
Always ZIP and attach the entire log file. The cause of the problem may be 1000 lines above what you've posted.
It may be ExifTool choking on your files.
It may be the database running into trouble.
It may be the image library crashing on your files.
If the database records locks, IMatch is stalled by some external event. A virus checker or all instances of ExifTool choking on files at the same time is potential reason...
1000 potential reasons.
...

[Pawel]

I ran both the diagnosis and the compact and optimize on the database and even repair once, with no change for the better. Cleaning the temp folder nor disabling AV software didn't help neither. I uninstalled and reinstalled IMatch and to my surprise it did help - at the first run IMatch communicated there is new Exiftool version available (although it was the same 10.25 version it used before reinstallation) and resumed  rescanning images - this time it worked for 24+ hours with no hiccups and the rescan is finished now. Should the problem reappear (I hope not!) I will attach full log files.

[Mario]

The IMatch engine compares the version number reported by ExifTool with the version number of the last version used. If it finds a difference, it shows the message and updates the database with the schema data of the installed ExifTool version. I don't see a reason why this could wrongly identify ET. More likely something else was badly messed up with your installation. If it now works, great!