IMatch crashed after changing Cache Preferences

[mosdubindi1]

Hello Mario,

After importing large number of ARW files, where all previews are OK, on the last import I've got very small preview for the images with the message saying something about cache.

Then I've checked the log (see attached).

It gives warning message:
W> Failed to create cache image for [438856] '\\DISKSTATION\DiskStation\01_Photo_Archive\01_Photo_Archive_Raw\15_Photo_Archive_Sony_a7RII\53_Crimea_11-29.01.2021\2021.01.16\_DSC4579.ARW' => 'C:\ProgramData\photools.com\IMatch6\previewcache\FA494332-907B-431A-84DD-CC90C4EB29DF\43\438856.jpg'. Check file system permissions and disk space.  'V:\develop\IMatch5\src\IMEngine\IMCacheManager.cpp(1354)'

I've checked photools.community and founded post related to the issue.

IMatch crashes when creating previews
https://www.photools.com/community/index.php/topic,13422.msg94627.html#msg94627

The recommendation for such type of warning message is:
a) Limit the cache size to something like 50 GB
b) Enable auto purging
c) Switch cache generation from "while indexing" (default) to on-demand

In fact, I do not have disk space limitation, but following on the recommendation, I've changed Preferences -> Cache as follows:

1. Max Cache size -> 50 GB 
2. Purge -> yes
3. After changing Working Mode to On-demand the database stop responding, I had to close it. After rebooting the computer, when running IMatch normally, the program is hanging on the first screen 'Initializing...'

My database is quite big, around 400000 photos.

I was trying to manipulate with imatch.pts.bak, but it does not help.

Could you pls. advise what to do:

1. Should I try to do something to wake up the database or better to restore it from the backup?
2. Once database is restored how to avoid the problem with 'W> Failed to create cache image' message? What Preferences -> Cache settings to use?

Thanks in advance,
Dmitry

[Mario]

In the IMATCH_LOG.txt there are 3443 warnings about IMatch being unable to produce a cache image.

That's an unusually high number and looks like either disk was full or the Windows WIC system crashed completely while trying to process ARW files. But I see no logs that IMatch was falling back to using LibRaw. Do you use LibRaw instead of WIC (photools.com RAW processing enabled under Edit > Preferences > Application)?

Was the disk full?

The log was not created in debug logging mode so the information available is minimal.


What's disturbing is that IMatch logged extremely long execution times for CIMEngine5::UpdateFileAttributes.
This function fetches information for a file from the file system (e.g. file size and last modified date) and stores it in the database.

The typical execution time for this function is maybe 0.1 seconds. But in your log file it is 6 to 70 (!) seconds.
This looks like something completely broke down in the file system or a virus checker kicked in and slowed down IMatch to a crawl or blocked it from writing and reading to/from the disk. Which would also explain the massive number of failed attempts to write to the cache folder.

When you say IMatch crashed, did IMatch produce a DUMP file? Or did it just become unresponsive?
If it became unresponsive, it might have been caused by the same issue that prevented it from writing to the cache folder and read times for file system data went from 0.1 seconds to 70 seconds. Which of course would cause IMatch to be dead in the water, unable to do anything, e.g. like updating the settings database...

Try this:

While starting IMatch, hold down <Ctrl> until you see Advanced Startup Options (Recovery)
Use the "Reset Workspace" option. In case your workspace was damaged for some reason.
Does this work?
Else repeat and try the "Start without Database" option.

Looking at the log file, it seems to me that a virus checker or similar kicked in, blocking IMatch from reading/writing data.
Which may even caused corruption in the database.

I don't have a log file for this, though.
The IMATCH_LOG.txt is from the breakdown and the backup log is from a session where you've loaded a small 100MB Test database?

[mosdubindi1]

Thank you Mario,

After using the "Reset Workspace" option, closing and open, the database finally gets back to life.

First re: your questions:

1. I use LibRaw as soon as WIC does not work with Sony ARW files (scrap view).
2. I did not notice whether the disk was full, should not be. But what I've noticed, after changing Cache Preferences, is that space on C: drive has increased. 
3. IMatch did not produced DUMP file, just stop responding.
4. I do not use external virus checker soft, only Win10 Virus & thread protection.
5. Correct IMATCH6_LOG.TXT is from the breakdown and backup is from test database.

Re: issue:

I've checked previews for those images imported before crash and cache for which was loaded OK. Now for entire database preview is generated on-demand, when click on the thumbnail.

Looks like when I changed these 2 settings at the same time:

b) Enable auto purging
c) Switch cache generation from "while indexing" (default) to on-demand

cache for the whole database has been purged. Maybe this is the reason that database was unresponsive for a long time as soon as the database is big.

According to Help  "Changing cache settings only affects cache images created after changing these settings."

Now the database is opened normally, diagnosis is OK. Attached pls. find log after the database is up and diagnosis log.

Purging all cache is not big problem, I left "On-demand" setting and will recreate cache if needed. Also I've set Auto purge to "no".

Hope I can continue using the database normally.

[Mario]

ache for the whole database has been purged.

How did you determine this?
Verified via the Dahboard or the Info & Activity Panel?
Opened the cache root folder for the database and looked for cache files?

The Cache Manager in IMatch purges files (when enabled) when it starts up (database being loaded or reloaded) and it checks for cache size and potential need to purge every 100 newly created or updated cache files.

In the latest log file, I see

CIMCacheManager::PurgeCache: 19481 files purged. 134 MB used by the cache.

and this too

208 seconds. Which is kinda normal, depending on how fast Windows can delete files on disk.

Sound like a lot? What was the cache size before and which max. size value have you configured?
How many cache files are left (see Info & Activity Panel "Files in cache perm)).

In the PurgeCache function, IMatch gets the maximum cache size from the settings.
It then deletes cache files sorted by last used until the total cache size is below the maximum cache size (-10% percent to allow growth without too many purges).

All this does not explain why IMatch took 70 seconds to fetch information about a file on disk...

[mosdubindi1]

I know that press on the file thumbnail before immediately open Quick View, now it is taking time to process (Loading...). Unfortunately, I did not record the number of cache files before crash, but it was much higher than now. 

Attached pls. find Info & Activity Panel screenshot. Files in cache perm. = 188.

Before crash Max. Cache Size was 10, then I've changed to 50 just before crash. Current settings attached. Maybe return to 10?

Also screenshot of C:\ProgramData\photools.com\imatch6\previewcache is attached.

22675969-49EF-41A7-B4CD-5AA8CFB4FCB1 - cache from test database 14,92 GB, 1290 files.
B855CA8F-E777-4DA8-9828-4F4FFF58355A - empty folder.
FA494332-907B-431A-84DD-CC90C4EB29DF - cache from work database 336,16 MB, 188 files.
IMWS - 665 KB

About 70 sec - maybe this is because I have files on NAS connected to computer and speed of connection is not high enough?

I have one more question to you - after crash, when I clone metadata template, it becomes inactive (grey) and I cannot use it. I cannot find what is this in Help or photools.community. Is it related to crash? Could you pls. help? 

[mosdubindi1]

image for metadata template inactive issue is missing, pls. see attached.

[Mario]

Note that the cache limit settings are per database, so this sums up.

About 70 sec - maybe this is because I have files on NAS connected to computer and speed of connection is not high enough?

I don't think so. Even a severely slow NAS, connected via a week WiFi should be able to return file data like "size" and "last modified" in a second. No 6, 20 or 70.

Keep an eye on log file entries like

CIMEngine5::UpdateFileAttributes with a < in front. It records the execution time if > 10ms.


Please don't mix very different topics (IMatch crash and metadata templates) in one thread. This only ever causes confusion. Start a new thread for each question.

I will do that once for you.

[mosdubindi1]

When closing the database, I've received error message (log is attached):

E> ...  'V:\develop\IMatch5\src\IMatchNG\IMDXCacheManager.cpp(1035)'

I'm really start worrying about stability of the database after crash. Maybe better to restore it from the backup? I never did this before, but as far as I understand it should completely restore the database on the moment of backup, so I will not lose anything.

If your advise will be to restore:
- which folder to use for restore - original or different?
- what about "Don't replace newer files"? Keep it ticked or not?

As for CIMEngine5::UpdateFileAttributes, I have no idea how to reduce the time. Will monitor a log files.

[Mario]

Your database is fine. You did run the diagnosis but it reported no issues.

What kind of drive is D:?
The background disk monitor in IMatch reports 5 failed attempts to query utilization data for that disk.

The reported error happened while IMatch was trying to create a cache image using LibRaw.
Debug logging (Help > Support > ...) was not enabled so the info is minimal. Can't tell the file name, but apparently an "unexpected" problem happened (since IMatch logs all usual problems).

[mosdubindi1]

Hello Mario,

About disk D: – this is normal SSD, which I use for the test database, so the error related to that disk looks accidental.

Finally the result of the crash is that I've lost cache for the whole database and cannot restore it from backup, as soon as option Packing cache was not active.

This is not big problem for me, however maybe better to stress in the Help, that shifting working mode from Default to On-demand together with Purge will result in deleting all cache. It could be sensitive for big databases, where to restore all cache is not fast exercise.

As for performance issue with "CIMEngine5::UpdateFileAttributes with a < in front", I will open another thread.

Thank you,
Dmitry

[Mario]

Finally the result of the crash is that I've lost cache for the whole database and cannot restore it from backup, as soon as option Packing cache was not active.

I have no idea how this could happen. The cache is just JPG files on your hard disk. A crash of IMatch will do nothing to the cache files.

Changing the cache settings and forcing IMatch to purge gigabytes of cache files will take a long time, especially when the virus checker is triggered and steps in (which happens quite often).

This is not big problem for me, however maybe better to stress in the Help, that shifting working mode from Default to On-demand together with Purge will result in deleting all cache

I cannot reproduce this. I'll try some more things.
You enabled purge, changed the purge threshold to a lower setting and switched from the default setting to on-demand
Then IMatch became unresponsive? You never clicked on the OK button, so the settings weren't even stored?

[mosdubindi1]

IMatch stopped responding immediately after switched from default to on-demand. It was no OK button visible after changing mode, just rotating round circle. Since nothing happened for a long time (maybe maybe IMatch purging a lot of cache), I pressed on screen and got Windows message Program is not responding. I have to stop program and then IMatch database was unresponsive for some time when I run it after closing. Then somehow after many attempts to run it was back. This situation I called crash. Maybe it was no crash, just IMatch was deleting cache all the time it was unresponsive.

[Mario]

IMatch database was unresponsive for some time when I run it after closing.

IMatch calls the purge cache method when a database loads. So this is to be expected.
This was not a crash. IMatch became unresponsive while deleting so many files. The purge cache is not designed for deleting that many files, it provides no feedback.

Since it works that way since 2016, I doubt putting effort into making this able to run in the background and provide user feedback is not worth the effort.

Changing the mode to on-demand does nothing as far as I can tell. The change becomes effective only after the dialog is closed with OK. Then the PurgeCache function is called, applying the new settings (and purging the cache in your case).

I will see if I can find out why all files were deleted. The loop check every 50 deleted files if the total cache size is below 90% if the configured maximum size and then stops. Maybe there is a side effect or problem with that. This is very old code (unchanged since 2016) and so I wonder what could cause this...

[Mario]

I've found something. Under some specific conditions and order of operations, the purge cache command could calculate the remaining cache size wrong, deleting all files in the cache!

Nice catch! Thank you for letting me know.
The code is from 2016 so I guess that this specific issue has not affected many users so far.
I've fixed this for the next release.