Writing metadata back for one image takes over a minute

[ubacher]

I displayed the files of a category. A filter selected all images with a red label. I changed the description of
one Jpg file and then clicked the pencil to write the change to disk. (I used the File Notes App).
This took over one minute- meaning Imatch showed the hourglass that long.
The log file, in debug mode, is attached.
The file in question is 2005-01-01 031.JPG
The time it starts is around 14:49:20.

Note that I had written back the same file, together with others previously. See at 14:25:44
Logfile stopped here.

I just repeated it. I changed the Artist, using the metadata panel. Took long. I captured the exiftool output.
Attached.

I repeated this but changed only the rating. This went quick. Then I changed the rating on another image.
Went quick. Changing the rating back: took long. So it seems it is timing dependent.

[Mario]

And you report this as a bug, why? Something running slow on a computer is not a bug.

So it seems it is timing dependent.

Surely true. If your database is busy doing lots of stuff, things like re-importing images after write-back may take longer.

It takes almost 30 seconds to open the database, which is really on the slow side for a 200K database.
Do you have exclusions/exceptions for the database folder set in your virus checker? Note that IMatch 2025 has a different file name.

Your log file has 34000 lines, which requires a lot of time to read.
35 warnings.
146 entries about slow operations (taking longer than 5 seconds).

First thing I see many warnings like:

Code Select Expand

Not indexing 'C:\Users\ubach\AppData\Local\Temp\
Not indexing 'D:\Work-Temp\1
not harmful but may indicate that you have enabled the "Add to database" option for a Batch Processor preset for folders not in the database or something.

Regarding the "slow" entries in the log: Most of them are generated by super-slow data-driven or formula-based categories, for example:

Code Select Expand

RefreshGroup-Completed: 'testStackTop' in 75156 ms.
1 minute and 20 seconds to update this category alone!

By the looks of it, updating the data-driven categories takes so long and utilizes 100% of the disk/database for so long, other operations are delayed massively, including importing file data after write-back.

The write-back times are between 0.5s and 2s per file, which is perfectly normal.

I've explained that a number of times to you: Reduce the load on your system.
Delete or set to manual data-driven categories you don't need (always). Remove formula-based categories you don't need.

The load time of your database tells me that the computer is not that fast. The database should load in maybe 50% of that time. Double-check virus checker!
Your system reports 4 cores, which makes me thing it is al older notebook maybe?
It also runs Windows 10.

Your database has over 200,000 managed assets. That's small stock agency level.

That in combination sets limits of what IMatch can do, despite it being very fast. IMatch cannot process database faster than your computer and drive can read and write data. When the database is at 100% calculating expensive data-driven categories, pulling metadata for 200,000 files from the disk each time, operations like importing metadata after write-back will suffer and take much longer.

For comparison: I don't get these slow response times on my 5 year old workstation with a database holding a million files.
And my 18 month old laptop is almost and sometimes even faster than my workstation, with a super-fast m.2 SSD!

[ubacher]

Mario, you know I have been using Imatch for 20 years and this often quite intensively. So I have a good feel
for "how it feels and behaves". My observations thus show differences to previous versions - since it is the only
thing that changed. (Other than Win 10 updates which do what....).

Since 2025 I very frequently experience long delays in operations which I can not explain.
This reported one stands out for its simplicity.

What caught my attention are the entries where Imatch reports

Code Select Expand

I> CIMCollection::InnerCalculate: Failed to get transaction or CS lock for .....It seems this is where the unexpected delays come from.

My desktop is old and I have plans to update but except for some of the newer Photoshop functions there is actually no urgent need. Ditto for the laptop.

I am just waiting for a quiet period to get a new system.

[Mario]

Since 2025 I very frequently experience long delays in operations which I can not explain.

IMatch 2025 can utility all available processors and disk resources a lot better, especially on recent and modern computers which have 8, 12, 16 or more processor cores and very fast SSD storage.

The slow category updates and the logs about IMatch not getting a transaction in time is due to the fact that your system does not cope well.

Go to Edit > Preferences > Application and set the performance profile to Balanced or Low. The default is "Performance". IMatch then uses less parallel threads and lower limits for CPU and disk usage. While writing or indexing files, this leaves more "power" for background processes.

Still, a category that takes 70 seconds to update is really rare. How did you setup this category? Variables? Data-driven? Formula? Your database has 230,000 files, and pulling the metadata for 230,000 files every time this category needs an update will take time. Especially when the database is busy during write-back and re-indexing anyway.

[ubacher]

.... saction in time is due to the fact that your system does not cope well.

But it did before Imatch 2025!

.... set the performance profile to Balanced or Low.

Will try this.

Note that I do not complain about slow operation when the system is busy. It is just when the system is idle because Imatch has to wait for a semaphore and does not get it then it is frustrating.

[Mario]

IMatch uses only one semaphore, to prevent a database from being opened multiple times in parallel. Not sure what you mean.
When IMatch has to wait for a transaction and logs it, the system is over-busy, too many things going on at the same time or the disk containing the database or TEMP being utilized by other applications.

[ubacher]

When I say IM is waiting for a Semaphore I meant the entries when it has to wait and retry to get a lock.
This is how I interpret the entries in the log.

Code Select Expand

06.15 14:43:40+    0 [3F00] 10  I> InnerCalculate for [73] 'This Week'
06.15 14:43:41+ 1266 [3F00] 50  I> TranBegin wait loop: 4 1063ms.
06.15 14:43:41+  62 [3F00] 02  I> CIMCollection::InnerCalculate: Failed to get transaction or CS lock for 'This Week'
06.15 14:43:41+    0 [3F00] 10  M>  <  0 [1328ms] CIMCollection::InnerCalculate
06.15 14:43:43+ 1297 [3F00] 50  I> TranBegin wait loop: 4 1094ms.
06.15 14:43:44+ 1375 [3F00] 50  I> TranBegin wait loop: 4 1109ms.
06.15 14:43:45+ 1328 [3F00] 50  I> TranBegin wait loop: 4 1062ms.
06.15 14:43:47+ 1375 [3F00] 50  I> TranBegin wait loop: 4 1109ms.
06.15 14:43:48+ 1360 [3F00] 50  I> TranBegin wait loop: 4 1094ms.
06.15 14:43:49+ 1343 [3F00] 50  I> TranBegin wait loop: 4 1093ms.
06.15 14:43:51+ 1360 [3F00] 50  I> TranBegin wait loop: 4 1078ms.
06.15 14:43:52+ 1344 [3F00] 50  I> TranBegin wait loop: 4 1079ms.
06.15 14:43:52+  78 [3F00] 10  M> >  0 CIMCollection::InnerCalculate  'V:\develop\IMatch5\src\IMEngine\IMCollection.cpp(774)'s
It seems to wait one second, the retries. After 10 retries is probably gives up. Not sure what it does then - try some other way or skip the attempted action. I see entries interspersed such as 

Code Select Expand

> thread: [3][6a4] AddMoreThreads (1)but that does not seem to make a difference. 

When Imatch becomes unresponsive I observe the Task manager and the system is idle. To me it looks like the process it waits for to terminate (so it can get a lock on it and thus use it) has hung up.
If a subprocess/thread does not terminate it ought to be logged so one can find and eliminate the problem. I do realize that parallel processing is difficult to debug because the "bug" may be caused by an unusual timing.

[Mario]

If the database system cannot provide a transaction, another part of IMatch has a transaction open. Like your category, which takes 70 seconds to refresh. Collection updates are secondary, and when IMatch cannot get a transaction, it uses the collection as is and tries to update it next time.

TransBegin failed locks are always a sign of the disk / database system not copying.
Which of the several suggestions I've made in my reply did you implement so far and what was the outcome of each implemented change?

[ubacher]

I set the performance profile lower and lower ending a Minimal. Now it is generally slower. I had no time to document
the same problem as before - busy getting things done. Will report later.

I have to reiterate: The only thing that has changed is Imatch (with 2025). Unfortunately it is not possible to go back to
the previous version. I would do so immediately to get performance back.

[Mario]

IMatch 2025 is 20% to 50% faster for tasks like indexing files, ingesting metadata, face recognition. This is due to a much improved background processing service that can utilize all processor cores, all disks resources, memory etc.

Basically, IMatch can now use all 8 processor cores in your computer much better and with less loss. This may cause the disk system to become a throttle point, so IMatch also monitors disk utilization and balances things so that core utilization and disk utilization stay high (for best performance) but don't starve the rest of the system.

A small number of users had problems with instability issues caused by prolonged high load (e.g. IMatch indexing thousands of files in a row) (usually on notebooks) and these users could resolve this by reducing the overall load by using the Balanced or even Low performance profile.

This does not make IMatch slower in general, just tasks controlled by this setting: indexing, metadata read, face recognition, face recluster.

The only reason for slow performance we could see so far in your logs is that IMatch fails too often to acquire a transaction, which is usually caused by "too much going on". Your very expensive category that takes 70 seconds to update will cause such log entries.

John today reported a similar problem, with similar log file entries. In his log fiel, things start to go bonkers after he writes back some files, and the relation manager propagates metadata (a bookmark too). Now IMatch suddenly fails to acquire transactions and performs badly, even the UI becomes unresponsive. There is unfortunately no clue in the log file that points at the "thing" that causes the problem. More data needed.

I've asked this already, but did you update your virus checker exclusions (if you have any) to match the new file name used by IMatch 2025? Very important.

[JohnZeman]

John today reported a similar problem, with similar log file entries. In his log fiel, things start to go bonkers after he writes back some files, and the relation manager propagates metadata (a bookmark too). Now IMatch suddenly fails to acquire transactions and performs badly, even the UI becomes unresponsive. There is unfortunately no clue in the log file that points at the "thing" that causes the problem. More data needed.

I've asked this already, but did you update your virus checker exclusions (if you have any) to match the new file name used by IMatch 2025? Very important.

I just double checked my Windows Defender exclusions for IMatch 2025 and I believe they should be correct.

Code Select Expand

C:\Program Files\photools.com\imatch6\IMatch2025x64.exe

C:\My Data\Imatch Databases\My Main IMatch Database.imd5


[Mario]

Code Select Expand

C:\Program Files\photools.com\imatch6\IMatch2025x64.exe

C:\My Data\Imatch Databases\My Main IMatch Database.imd5


Please add an  exclusion for the entire folder (!) containing the database. The database system creates many short-lived temporary files in that folder and that should not trigger the virus checker.

[ubacher]

1. Yes, my defender settings are ok. (I had run into this after the switch to 2025)
2. My category which takes 70 seconds? How can I find in the log which category and how long it takes.
What does #slowcats show? What is slow? The time to update? How can I see the time it takes?
The number in brackets behind the name is not the time - is it?

[Mario]

#SLOWCATS is logged when a category takes more than 2 seconds to calculate.
To find execution times for categories (groups), search for 

Code Select Expand

RefreshGroup-Completed
The timings for the category I mentioned varies a lot, peaking at 70 seconds. During that time a lot is going on.
Since you have changed the performance profile now, see if the category still peaks at such high runtimes, or if everything is much smoother now.