IMatch constantly freezes

[JohnZeman]

Lately IMatch has been freezing on me, meaning it stops responding and all I see is the spinning icon telling me IMatch is busy.  The problem is it never ends.

It used to happen once in a great while, now it's happening almost constantly, and I have to force kill IMatch each time then restart it again.  After restarting it database diagnostics usually finds no problems.

I enabled debug logging and have attached the logs to this post.

[Mario]

You say lately. Can you recall what happened before this happened? Any change you made to IMatch or your image collection? Maybe installed other software, a virus checker update or similar?

In the backup log, I see a common warning about no spell checker dictionary being installed, disabling spell checking in the Metadata Panel, Attributes panel etc.

Then I see a warning that the folder "D:\Mine\Photos\Years\2020-2029\2025\06 June\" must be rescanned because a file newer than the folder was found.

That's it.

The database is moderate in size (100K files, 15K categories).

IMatch starts, logs the warning about the out-of-date folder.
Then a diagnosis is run.
Some cleanup and background processing.
A metadata template is applied.
Collections are rec recalculated.

Categories are updated.
I see SLOWCAT warnings for categories named 'Workflow' !Checks, UnCatergorized Images. Categories taken more than 2 seconds to update.

I see a ton of calls for ProcessYearsAgo, which is responsible for processing the @YearsAgo[] category formula. Do you use this often?

06.18 21:04:42 "Writeback All" favorite executed. IMatch shows the "Write-back Metadata" message box.
06.18 21:08:54 Message box is closed.
06.18 21:08:54 Writeback begins

06.18 21:08:59 CIMQueryManager::SearchMetabase
06.18 21:08:59 CIMSQLite::CreateTemporaryTableOid

06.18 21:08:59 Writeback completed for 4 files. There are more than 4 minutes (!) between these two log entries.

06.18 21:08:59 [49C0] CIMQueryManager::SearchMetabase
06.18 21:08:59 [49C0] CIMSQLite::CreateTemporaryTableOid

File records are updated in the database, entries are added to the background processing queue.

06.18 21:08:59 [5A10] PTMetabase::WriteBack completed for 4 files (4 workfiles) in 4844 ms.

06.18 21:08:59 File histories are written to the database, category updates etc.

06.18 21:08:59 CIMRelationManager::Propagate is called.
06.18 21:08:59 [7150] CIMCollectionManager::SetBookmark is called as part of metadata propagation

This is on the user interface thread, which means the UI is blocked until this continues!

06.18 21:08:59 [49C0] [375ms] CIMQueryManager::SearchMetabase from before completed

06.18 21:08:59 [49C0] A New call to CIMQueryManager::SearchMetabase
06.18 21:08:59 [49C0] a New call to CIMSQLite::CreateTemporaryTableOid

At 06.18 21:09:01 The background thread responsible for storing collections in the database falls into a loop where it tries to open a transaction, but cannot. This happens when another part of IMatch has open a database transaction. This is not uncommon when the system is busy, so it tries a few times and then goes to sleep for a second and then retries. 

Now things fall apart...

06.18 21:09:04 Background collection store retries...
06.18 21:09:06
06.18 21:09:09
06.18 21:09:11

...

06.18 21:11:12 The background thread trying to create a temporary table to search the database bails out:
06.18 21:11:12 [49C0] ##BLOCK: 18880 (49c0) 'CDBGroupTreeCalcDelegate' 
thread reports TranBegin wait loop: 600 133078ms.  Bad!

This is the background thread that calculates the counts shown in category trees. It runs all the time, updating counts for modified categories.

Basically, it all falls apart after this:

06.18 21:08:59 [7150] CIMRelationManager::Propagate
06.18 21:08:59 [7150] CIMCollectionManager::SetBookmark
06.18 21:08:59 [49C0] [375ms] CIMQueryManager::SearchMetabase completed
06.18 21:08:59 [49C0] CIMQueryManager::SearchMetabase same thread starts a new search
06.18 21:08:59 [49C0] CIMSQLite::CreateTemporaryTableOid

CIMRelationManager::Propagate was called once before and took 16 ms.
This time it never completes.

This is the last operation the user interface thread performs. Which means the UI is blocked and IMatch cannot respond any longer to user operations. Worst case.


At the same time,  the background thread that successfully ran SearchMetabase in 300ms in the same second tries to run another search but stops dead while trying to create a temporary table.

This looks as if something opened a transaction but never released it release it, starving all other threads and the user interface.
Normally, transactions take a few milliseconds or maybe a second when a ton of data needs to be written. IMatch performs millions of transactions in a normal session.

I cannot see a reason. Something the relation manager did, or SetBookmark did?
Why was the relation manager triggered? Because of the write-back? Something you did?

This looks similar to a problem reported by @ubacher in this thread https://www.photools.com/community/index.php/topic,15258.0.html. For him, writing back data sometimes takes a very long time, and the log also shows many TranBegin wait loop log entries.

This is all I can say at this time.

[JohnZeman]

Thanks Mario,

After I'd sent my post last night it occurred to me my problem does sound similar to what ubacher recently reported.

Yes I do use the formula categories in my Workflow section quite often, they monitor my metadata (location, description, etc.) to make sure I have all important tags filled in.

I'll keep monitoring this.

[Mario]

The @YearsAgo is puzzling. And of course what happens when the RelationManager kicks in and propagates/sets a bookmark. At least according to this log file this is when something unknown breaks and apparently opens an infinite transaction.

if you can reproduce this, but it works when you disable your file relations, we have some kind of proof for my assumption. I cannot even start to analyze this further. I have several relations running, some of which set collections. Never saw this problem though.

Need more info and data.

[JohnZeman]

@YearsAgo is an excessively long formula category (posted below) that returns images taken on the current date over the last 100 years.  When I created it a few years ago I got carried away and could shorten it now significantly.

I'll do some more testing today to see if I can narrow the problem down.

Code Select Expand

"Chronology" AND ("@YearsAgo" OR "@YearsAgo[1]" OR "@YearsAgo[2]" OR "@YearsAgo[3]" OR "@YearsAgo[4]" OR "@YearsAgo[5]" OR "@YearsAgo[6]" OR "@YearsAgo[7]" OR "@YearsAgo[8]" OR "@YearsAgo[9]" OR "@YearsAgo[10]" OR "@YearsAgo[11]" OR "@YearsAgo[12]" OR "@YearsAgo[13]" OR "@YearsAgo[14]" OR "@YearsAgo[15]" OR "@YearsAgo[16]" OR "@YearsAgo[17]" OR "@YearsAgo[18]" OR "@YearsAgo[19]" OR "@YearsAgo[20]" OR "@YearsAgo[21]" OR "@YearsAgo[22]" OR "@YearsAgo[23]" OR "@YearsAgo[24]" OR "@YearsAgo[25]" OR "@YearsAgo[26]" OR "@YearsAgo[27]" OR "@YearsAgo[28]" OR "@YearsAgo[29]" OR "@YearsAgo[30]" OR "@YearsAgo[31]" OR "@YearsAgo[32]" OR "@YearsAgo[33]" OR "@YearsAgo[34]" OR "@YearsAgo[35]" OR "@YearsAgo[36]" OR "@YearsAgo[37]" OR "@YearsAgo[38]" OR "@YearsAgo[39]" OR "@YearsAgo[40]" OR "@YearsAgo[41]" OR "@YearsAgo[42]" OR "@YearsAgo[43]" OR "@YearsAgo[44]" OR "@YearsAgo[45]" OR "@YearsAgo[46]" OR "@YearsAgo[47]" OR "@YearsAgo[48]" OR "@YearsAgo[49]" OR "@YearsAgo[50]" OR "@YearsAgo[51]" OR "@YearsAgo[52]" OR "@YearsAgo[53]" OR "@YearsAgo[54]" OR "@YearsAgo[55]" OR "@YearsAgo[56]" OR "@YearsAgo[57]" OR "@YearsAgo[58]" OR "@YearsAgo[59]" OR "@YearsAgo[60]" OR "@YearsAgo[61]" OR "@YearsAgo[62]" OR "@YearsAgo[63]" OR "@YearsAgo[64]" OR "@YearsAgo[65]" OR "@YearsAgo[66]" OR "@YearsAgo[67]" OR "@YearsAgo[68]" OR "@YearsAgo[69]" OR "@YearsAgo[70]" OR "@YearsAgo[71]" OR "@YearsAgo[72]" OR "@YearsAgo[73]" OR "@YearsAgo[74]" OR "@YearsAgo[75]" OR "@YearsAgo[76]" OR "@YearsAgo[77]" OR "@YearsAgo[78]" OR "@YearsAgo[79]" OR "@YearsAgo[80]" OR "@YearsAgo[81]" OR "@YearsAgo[82]" OR "@YearsAgo[83]" OR "@YearsAgo[84]" OR "@YearsAgo[85]" OR "@YearsAgo[86]" OR "@YearsAgo[87]" OR "@YearsAgo[88]" OR "@YearsAgo[89]" OR "@YearsAgo[90]" OR "@YearsAgo[91]" OR "@YearsAgo[92]" OR "@YearsAgo[93]" OR "@YearsAgo[94]" OR "@YearsAgo[95]" OR "@YearsAgo[96]" OR "@YearsAgo[97]" OR "@YearsAgo[98]" OR "@YearsAgo[99]" OR "@YearsAgo[100]")

[Mario]

This category is not really a problem. It's fast enough. I've just wondered why it is so often calculated.

[JohnZeman]

I have a follow up to this and unfortunately, it's not good news.

For a few days after my last update the problem seemed to stabilize but lately it has returned with a vengeance.  It finally reached the point where my database became completely unusable.  I've used this database since 2006 when I first joined the world of IMatch and I've never had problem with it before.

So using Macrium Reflect I restored a backup I had created before I had the problem but it did the same thing.

Next I restored the oldest backup I had from the beginning of the year, months before the problem had occurred, but it too had the same problem where IMatch just stops responding.

After that I created a brand new database from scratch, added a few hundred images to it, and it's fine, no hangups or unexpected delays.

So I can't help but wonder if the problem is not my original database at all, could it possibly be the problem is in another file IMatch uses to process that particular database since all restored database backups have the same problem?  Just guessing here but this is so strange.

If I have to I'll continue to build a brand new 100,000+ image database from scratch but that's going to take a lot of time and what will prevent that new database from becoming corrupt some day?

As an aside each time I had to forcibly terminate IMatch when I launched it again I always ran database diagnostics to make sure the database checked ok.

Debug logfile attached.

[Mario]

The log file shows an IMatch session where several folders were detected as outdated and IMatch started to process them in the background.

The execution times seem quite slow. ExifTool takes 1 to 1.5 seconds to extract metadata for individual files, which is OK-ish. But adding the imported data to the database takes several seconds, which is unusual. I see several related log entries. It looks like every write operation to the database file takes unusually long. The database has 10GB and handles 100K files, which is not that much.

The log file ends while IMatch is still importing metadata from images and updating the database, propagating metadata...

I see a few transaction being wait loops,  but most are only 0.2 seconds. A few are 1+ seconds, but that can happen when IMatch is importing metadata, indexing files, calculating categories and collections. Nothing real bad.

I'm sure it's not the age of the database. My personal 300K files database was created with IMatch 3, as was my one million large database (which grew over the years).

Please go to Edit > Preferences > Application and set the performance profile to "Low". See if this changes things. Also let IMatch finish ingesting all folders and files it has found out-of-date in "D:\Mine\Photos\Years\2020-2029\" and other folders.

[JohnZeman]

I changed preferences for performance to Low, it had been set on Performance (Default).

Then I left IMatch alone with my database for a full hour but when I came back to it again it immediately froze as soon as I tried to do anything so I had to force kill it again.

I'll give IMatch more time to process my database and see if that helps.

Thanks Mario

[JohnZeman]

Well as usual Mario it looks like you were right.

Once I left IMatch alone for another 2 hours so it could finish updating the latest changes to my database everything seems to have settled back down and is working normally again.

Hopefully this will be the end of this problem.

Thank you!

[Mario]

Before version 2025, IMatch relied on the "last modified" timestamp of folders to tell if they were changed externally. I then found out that this timestamp is not reliable.

IMatch now determines the most recent file in each folder during the initial folder scan (after opening the database)  and when a file newer than the folder's last modified timestamp is found, the folder is enqueued for processing. This was the case with your database, for several folders. And then IMatch got to work. It should have shown the activity in the status bar and in the Info & Activity Panel.