What does this warning in logfile mean

[hluxem]

Hello,

I had some sluggish behavior when Imatch starts up and then switching between folders and categories. I have seen this warning in the logfile. It sounds like something bad, but it may be just a warning and nothing serious. Any hint?

0 [C380] 01  W> <<ENGINE WARNING/PANIC>>: major:80 minor:500 d1:0 d2:0 s1:'' s2:''  'V:\develop\IMatch5\src\IMEngine\IMEngine5.cpp(1383)'

[Mario]

Including the ZIPped full log file would be helpful. Since I can then see what takes how long and what IMatch is doing when you think it feels sluggish.

The warning means that you have enabled the option to search for duplicates, but not selected a category to assign the duplicates to (or the category was deleted). See Edit > Preferences > Indexing.

IMatch reports this problem in the Dashboard to inform you. The warning you'll see there is:

IMatch is configured to automatically search for duplicates when ingesting files, but no category is set to assign the duplicates to. See Edit menu > Preferences > Indexing.

[hluxem]

The problem is that this is the last entry in the logfile. The log file is from last night and I did add a category to some master files. That seems to work fine with some files, but when I do that to 10000 files Imatch seems to be just idling. It's now idling for 9 hours. I think at this point I will have to kill and restart  Imatch. I will switch to debug logging.

[Mario]

The log starts at 06.23 23:08:44 and ends at 23:09:05, about 20 seconds.
Not even the reoccurring entries are written. This locks like IMatch is totally blocked, doing absolutely nothing.

Is maybe a dialog open on another (disconnected) monitor and IMatch is waiting for you to click OK?

[hluxem]

Is maybe a dialog open on another 

Never used a second monitor.

This logfile in debug mode maybe more helpful.

At 9:38 I selected 10 Masters and added a category, took about 3 s, then unassigned a category.
At 9:39 I selected 100 masters and added a category, took about 14 s, then unassigned a category.
At 9:42 I selected 1000 masters and added a category, it took more than 10 minutes but was done when I got back at 10:20 

[Mario]

The database manages 450,000 files and requires about 20 seconds to load and initialize the UI.
Is the E: drive a SSD?

IMatch reports two 'unusually' slow categories: 'States extended' and '0  Ecuador'.
How are these categories set up? Data-driven? Variable-based?

[15031ms #sl] CIMQueryManager::GetVariableGrouping

which indicates a variable-based category that takes 15 seconds to update...
There are a number of entries like this in the log.

I see a high number of calls to ValueCachePurge(), which is called to remove no longer used metadata from memory.
This indicates that something is running which accesses metadata for a lot of files, constantly requiring the cache to invalidate. The cache is purged fully, meaning that all data is flushed since it makes no sense to keep it since the possibility of reusing it in near time is low.

Something seems to be running over a lot of files, fetching metadata for each file. Maybe a variable-based category you sue?

The Edit > Preferences > Indexing dialog is opened and closed. Did you make any changes?

At 06.24 09:39:56 IMatch complains that too many files are selected to be merged for the Keywords Panel.
That's normal if more than 2000 files are selected and does not harm.

But now something strange happens.
IMatch performs operations which take no time (less than 10 ms, because no duration is logged).
But after each group of operations, there is a period of inactivity...

IMatch is updating categories, the relation manager is checking if categories need to be propagated, and there are many, many of these combination if operation. They take less less than 10ms, some take 15 or 20ms. Nothing.

But after each combination of these operations which modify the database, the log file records periods of inactivity. 500ms, 1500ms and more...

Basically, IMatch updates a category in the database. Then waits. Updates a category in the database. Waits. Updates a category. Waits. Very unusual. Because these operations are performed in loops, without any breaks or pauses.

It seems as it IMatch is halted/paused after each database update for a second or more.

And this is the typical behavior I see when a virus checker performs on-access scans on the database, stalling IMatch after each write until it has finished the scan. The database file has 22GB, and a virus checker may take a second or two to scan it.

Or, maybe the E: disk has a problem?


After hundreds of these update database / pause / update database / pause I see

At 06.24 10:05:48 I see this: [1427297ms #sl] CIMTaskGroup::Assign

1400 (!) seconds to assign files to a category.

And 99% of the time IMatch seems to pause, doing nothing. Or being stalled by something external that acts whenever the database file is modified.

Check your virus checker and make sure IMatch is configured as an exception.
Make sure your database is on the fastest disk (SSD). Maybe move it to C: to see if this changes the behavior.

[hluxem]

Is the E: drive a SSD?

All my drives are SSD drives, E is actually a fairly new one with read/write speed around 5000MB/s

E: disk has a problem?

How could I check this? I can copy the database to a different drive to see if I see the same issue.

IMatch reports two 'unusually' slow categories: 'States extended' and '0  Ecuador'.

Will check later, Imatch is not responding right now. The problem is not the start up.

Check your virus checker and make sure IMatch is configured as an exception.

I use only Windows security and have this folder defined as an exclusion:

C:\Program Files\photools.com\imatch6

It seems as it IMatch is halted/paused after each database update for a second or more.

It definitely feels like this. 
What I want to do is add a category to a lot of files, about 2/3 of them are master files which means the category would be propagated to the version. It's no problem for 10 or 100 files. If it's more than 2000 files it seems to take 2 to 3 s for each file. With 10000 files I had to kill Imatch after 9 hours. 

I see these entries changing in time depending on the number of files selected: 
06.24 12:47:06+  844 [B6DC] 50  M> >  0 CIMEngine5::SetGroup  'V:\develop\IMatch5\src\IMEngine\IMEngine5.cpp(10556)'
 
~15 ms when less than 100 files are selected, between ~ 850 and 1200 when 800 files are selected.

[hluxem]

I did multiple steps today trying to trouble shoot this.

Most noteworthy is that this only happens when category propagation is involved. I unchecked all relations, selected 90000 files and assigned a new category, it took less than a minute and Imatch was done.

I enabled the relation again and was probably too optimistic. I selected 5000 master files and assigned a new category. That was done at 4:26, 6 hours later Imatch is still not responding (blue circle).
The logfile is still written, the same group of 8 lines are repeated over and over in the log file.      

06.24 22:04:37+16797 [1CC0] 50  M> >  0 CIMEngine5::SetGroup  'V:\develop\IMatch5\src\IMEngine\IMEngine5.cpp(10556)'
06.24 22:04:37+  16 [1CC0] 50  M>  <  0 [16ms] CIMEngine5::SetGroup
06.24 22:04:37+    0 [1CC0] 50  M> >  0 CIMRelationManager::InnerGetPropagationGroups  'V:\develop\IMatch5\src\IMEngine\IMRelationManager.cpp(3317)'
06.24 22:04:37+    0 [1CC0] 50  M> >  0 CIMRelationManager::GetMasterDefs  'V:\develop\IMatch5\src\IMEngine\IMRelationManager.cpp(3273)'
06.24 22:04:37+    0 [1CC0] 50  M>  <  0 CIMRelationManager::GetMasterDefs
06.24 22:04:37+    0 [1CC0] 50  M> >  0 CIMEngine5::GetGroups  'V:\develop\IMatch5\src\IMEngine\IMEngine5.cpp(10061)'
06.24 22:04:37+  15 [1CC0] 50  M>  <  0 [15ms] CIMEngine5::GetGroups
06.24 22:04:37+    0 [1CC0] 50  M>  <  0 [15ms] CIMRelationManager::InnerGetPropagationGroups
06.24 22:04:54+17125 [1CC0] 50  M> >  0 CIMEngine5::SetGroup  'V:\develop\IMatch5\src\IMEngine\IMEngine5.cpp(10556)'

Only this time it looks like there is a whopping 17s pause. 
When I had 100 files selected, I saw 15ms or 15 s till Imatch responded again,  ~ 2.5 s and ~ 40 min wait time with 1000 files. I assume the total wait time correspond to the average time in this cycle multiplied by the number of files. That means for the 5000 files it will probably be around 24 hours. I let Imatch run and see tomorrow if it becomes responding again.

IMatch reports two 'unusually' slow categories: 'States extended' and '0  Ecuador'.
How are these categories set up? Data-driven? Variable-based?

States extended has indeed some formula based categories. 0 Ecuador is just a category with some subcategories and ~ 5000 files. I'm not touching either of this category. And the start-up is really not the problem.

I moved the database to a different SSD, no change.

And this is the typical behavior I see when a virus checker performs on-access scans on the database, stalling IMatch after each write until it has finished the scan. The database file has 22GB, and a virus checker may take a second or two to scan it.

In addition to the exclusion "C:\Program Files\photools.com\imatch6" I added the database folder as well. No change either.

[Mario]

How are your relation rule set up?
Maybe your scanning the entire database? Or you accidentally introduced recursion, where versions and masters depend on each other?

[hluxem]

How are your relation rule set up?
Maybe your scanning the entire database? Or you accidentally introduced recursion, where versions and masters depend on each other?

See attached screenshot. I don't think I ever stumbled across a recursion, I usually see one master and 1 or 2 version for each master. I did check the relation collections and there is no file in both collections.The setup has been like this for a while. I normally don't assign batches of 5000 files to a category, so I didn't notice this before.
 

 I selected 5000 master files and assigned a new category. That was done at 4:26, 6 hours later Imatch is still not responding (blue circle). ....
 That means for the 5000 files it will probably be around 24 hours

It indeed took about 24h to assign one category for 5000 files before Imatch became responsive again. Logfile "2024-06-25 5000 files with propagation IMATCH6_LOG" attached. While Imatch was circling in the background I could use the computer without any other problems.

I did another test, unchecked the version rules, selected 88853 files and assigned them to a category. This took about 5 minutes. 
Logfile "2024-06-24-25 88853 files no propagation IMATCH6_LOG" attached.
So, the propagation has a huge impact, and it seems to be exponential, as more files are involved as longer it takes for each file.
Not sure that there is anything else I can test at the moment.

[Mario]

I've made some performance tests, for comparison.

My largest database manages almost one million  (985,000) files.
Selecting 12,000 files and assigning them to a category takes 19-20 seconds on my over four year old PC.
Disabling all version rules brings that down to about 1.5 seconds.

The version rule in the screen shot searches 3 specific folders, four levels deep. I'm not sure how efficient this is.

When you assign a file to a category, IMatch has to
- check if the file is a master
- if that's the case, check if an which categories need to be propagated
- check if the file is already in the category (required for proper event bus handling)
- assign the file
- then, for each file in the version chain which receives propagated categories, propagate the category.

This is a lot of work to do for each file.
You assign 80,000 files to a category, using a database with 450,000 files...

Note: When debug logging is enabled, things are much slower since IMatch does log more and directly to disk (no in-memory caching and asynchronous bulk writing).

I've had a look at the routines involved in assigning multiple files to a category, and looking at the performance profiling data the "hot" spots which do most of the work are already optimized as much as possible.

Conclusions

Assigning 12,000 files to a category in a database with a million files and 2 version rules with category propagation takes about 19 seconds on my over 4 year old computer. Or about 10 seconds per 10,000 files. Database on a four year old .m2 SSD.

With version rules disabled, it takes 0.75 per 10,000 files, which is actually very impressive.

I have no idea why your system is so slow what is slowing down IMatch or what is causing the constant ~ 1 second delays basically after each database write. I have seen behavior like this only with virus checkers stepping in, halting IMatch while they do an on-access scan on the database file, then unlocking IMatch again. This of course brings down performance to a crawl.

[hluxem]

Thanks for looking into this!

This is really strange and my conclusion is to disable propagation and do a manual propagation when needed. 

I changed the rules to only propagate bookmarks. Propagating 80000 bookmarks is almost instantly. Just because I was curious, I added categories and xmp tags again to be propagated and it's now much better than before. Only 10 min for 5000 files. Much better than the 24 hours from 2 days ago, not nearly as fast as on your machine.

[Mario]

Did you test this with debug logging on?

I've repeated my test on my six month old Dell laptop and it is about 30% faster even than my workstation (due to faster RAM and a faster SSD).

Bookmarks involve a lot less work than categories, so this will always be faster.
To assign 5,000 files, my system takes less than 5 second. Not 10 minutes.
This must be something "external" badly interfering.

Not idea why you get faster responses after changing and re-establishing the file relations.
I have never seen or heard of such extremely slow processing times.

Did this happen suddenly? If so, maybe you recall what has changed before this happened?
Sometimes a virus checker update disables exceptions or ignores them, causing all kinds of weird behavior.
I have literally spend days over days on supporting users with "IMatch is slow" problems - and it was always the virus checker...