Performance issues (not sure if bug)

[axel.hennig]

Since IMatch 2025 I run from time to time into "Performance issues".

It's difficult to describe and even more difficult to reproduce.

Following two things I've observed related to "Performance issues". Second one with log-file:

(1) Being in the People view, selecting one Person with unconfirmed Faces. Pressing F4 to open the Face Manager. Selecting one Face and pressing F2. The "Who is this?" screen pops up, but stays grey for minutes (i.e. no "Recent Persons" with A, B, C,... at the right, no Persons with 1, 2, 3,... at the left, no "Who is this?" at the top,... just grey).
(2) Log-file available: Writing back 50 jpg-images (no image larger than 5MB). Write-back went okay. But "Reading Metadata" stopped at 98% with 1s left for Minutes (screenshot what I mean with that).



I could make observation (2) work again via selecting another single jpg-image and clicked on write-back. After that everything went again smooth immediately.

Zipped log-file in Debug-mode attached, but not sure if there is something in...

[axel.hennig]

Now, I'm in the same situation with "Matching Faces" (see screenshot). Does not go away for several minutes.



There are "only" 101 Files with Unconfirmed Faces (seen in "Collections").

Unfortunately, I don't have the log-file in Debug-mode, only Normal-mode.

Maybe within the next few IMatch-sessions I will always use Debug-mode to be able to provide the log-files here.

Update: While writing this post, making screenshot, uploading log-file,... the situation didn't change within IMatch, so now what is seen in the screenshot above stays since more than 30 minutes and IMatch didn't crash. I can still work with it, view images,...

[Mario]

Looks like the queue is "paused" or does not know, for some reason, that there is work to do.

A log not in debug logging mode has zip info about the queue, so no use for the attached log.

Try to capture this with debug logging enabled.
Take note of what IMatch is doing at the time (keep the Info & Activity Panel open) and precisely which steps you did and in which order.

I've worked with face recognition and people yesterday for several hours (assigning persons, adding new persons, running AutoTagger) and I did not see this effect. Any detail is important.

The update queue is a massively "parallel" thing, doing many things for many things in IMatch at the same time. Different tasks get priority over other tasks, some IMatch operations pause the queue for the duration of the task etc.
There is also a watchdog that keeps an eye on the queue to see if it running.

When this happens again, go to Help > Support > Copy application logfile to make a snapshot.
Then e enqueue something, e.g. Shift+Ctrl+F5 > Reload Metadata or run AutoTagger. New tasks coming into the queue wake it up and cause it to wake up processing delegates. See if this helps. If it does and the queue starts processing again, make another snap shot of the log file.

ZIP and attach results.
Issues like this are super-tricky to figure out.

[axel.hennig]

Thanks for detailed explanation on what to do. Will try.

The log-file in my first post is also not showing anything? Because that one is in debug-log mode.

[axel.hennig]

Now, it happened again.

Thanks to your hints Mario. Hopefully I've got more information now.

I was in the People view when the problem occured. I had the "Show only Persons with unconfirmed Faces" turned on. Selected one Perseon, hit F4 and confirmed, ignored, deleted or assigned to the correct Person (via F2).

Then the problem occured. See screenshots below. Info & Activity did not change.





Debug-log file created (too large for forum; logA.zip)

I've tried the following, but nothing solved the problem

• Ctrl+Shift+F5 -> Normal rescan of single jpg-file
• Ctrl+Shift+F5 -> Reload metadata of single jpg-file
• People view -> select Person -> F4 -> F2 -> Assign correct Person
• Ctrl+Shift+F5 -> Force update of single jpg-file -> "Matching Faces (41%) 17s" (see screenshot above) disappeared but Info & Activity still at 0 of 1 (changed since log-file creation; see screenshot) -> Write-back needed
• Write-back
• Run Face-Recognition on several jpg-files

The following action solved the problem: Cancel Person Assignment Updates (see screenshot)



Afterwards, there are two files in the created Category "IMATCH_PROCESSING_QUEUE_FILES". One of this files contains the German umlaut "ö" (apart from space and brackets) in filename. The other file contains a '´' in the filename. Not sure if this is relevant.

Debug-log file created (too large for forum; logB.zip)

The output of the Metadata Analyst for the two "IMATCH_PROCESSING_QUEUE_FILES" is:

Metadata Analyst - Copy Warnings and Errors - first file with "ö"

Code Select Expand

Metadata Analyst Results. Version 2025.1.12. 2/14/2025 5:56:08 PM
File analyzed: E:\Pics\1990 - 1999\1999\Wöl\Wöl (Erik) 123.JPG
Errors: 0
Warnings: 2

Warning: [Metadata] Warnings: 'FileName encoding must be specified [x2]'
Warning: [Legacy IPTC] Character Set Encoding: unspecified.


Metadata Analyst - Copy Warnings and Errors - second file with '´'

Code Select Expand

Metadata Analyst Results. Version 2025.1.12. 2/14/2025 5:56:38 PM
File analyzed: E:\Pics\2000 - 2009\2000\Haus\Brigitte´s Zimmer 09.jpg
Errors: 0
Warnings: 2

Warning: [Metadata] Warnings: 'FileName encoding must be specified [x2]'
Warning: [Legacy IPTC] Character Set Encoding: unspecified.


[axel.hennig]

It happened again. Attached two Debug-log files. The one ending with "a" is the first extract (problem still available) and the one ending with "b" after problem solved via "Cancel Person Assignment Updates" (see post above).

I forgot to make a screenshot of the Info & Activity panel, but it still happened during Face confirming/deleting/ignoring/... when beeing in the Face Manager.

I can remember that the Info & Activity panel was showing:

Code Select Expand

Matching Faces
Searching for matching faces (0 of 9).

[axel.hennig]

Sorry for posting again, but the attached Debug-log file is from the same session as the attached log-files from the post above.

I.e. Problem occured (log-file post above ending 'a') -> Problem solved (log-file post above ending 'b') -> Problem occured (log-file this post ending 'c').

Afterwards I was further working WITHOUT solving the problem. What happened was that in the Info & Activity panel the "Searching for matching faces" switched from "1114 of 1115" to "0 of 1" and then increased to "0 of 2", "0 of 3",... after confirming/deleting/ignoring/... an additional face and again an additional face and....

The "Entries in Queue" within the Info & Activity panel also increased step by step. from 0 to 1, 2, 3,...

Screenshots taken at the same time:

[axel.hennig]

It happened again.

Now I had a more detailed look into the category "IMATCH_PROCESSING_QUEUE_FILES". Just one file was added and this file does not have any recognized face???

Why is the Info & Activity panel stuck with "Matching Faces" and if I cancel that via "Cancel Person Assignment Updates" the file added to  the category "IMATCH_PROCESSING_QUEUE_FILES" does not even have a face (no face region detected)?

[Mario]

I have not yet looked into this (and not experienced this myself).
I process bug reports in the order in which thy are incoming, sorted by severity. Lots of things come in per email, taking a lot of time to discuss and process. I will look in your report when I'm ready.

[axel.hennig]

Maybe better move this to "Bug reports" to not get loose track.

[axel.hennig]

I haven't observed this issue anymore since implementing this one:
https://www.photools.com/community/index.php/topic,14911.0.html

I suggest to close this bug-report and further monitor if it is really gone.

@Tveloso: What do you think?

[Tveloso]

Axel, I hadn't seen the issue with Matching Faces.  For me it was with Reading Metadata back in, following a WriteBack (like you mentioned in your initial post here).

For sure, the change Mario made to Face Manager has resolved the issue there...(which happened during / in conjunction with the Matching Faces / Reclustering process)

But I wonder if the stalled/slow Face Matching and Reading Metadata processes that we have both seen are either two different things, or perhaps the same underlying thing, that manifests in both?

I'll have another batch of files to write-back in the next couple of days, and will report back on whether or not the Reading Metadata phase has any trouble.

[axel.hennig]

Ah, sorry. Was mixing up things.

[Mario]

I'll have another batch of files to write-back in the next couple of days, and will report back on whether or not the Reading Metadata phase has any trouble.

Make sure to enable debug logging before you do that.
I could so far not reproduce this (and I have written back and reloaded tens of thousands of files on 3 computers over the past six months).

[Mario]

Regarding this post https://www.photools.com/community/index.php?msg=104355 with the big log file.

IMatch is reclustering different persons at high speed.
At 02.14 17:35:00 it reclusters person [922], then [75] etc.

Then it seems to fall info a loop.
It tries to recluster person [922] but does no actual work. The cause for this is typical that the database transaction time is currently to high or it could not acquire a database transaction to perform the recluster. Recluster is 99.6% "in database", where the database systems calls function in IMatch which do the actual face fingerprint matching. Very database-intensive.
This repeats over and over, until the log file ends.

Whit is interspersed between the numerous attempts to recluster person[922] are calls to IMWS, to fetch face and entity data.
These calls are used e.g. by the Face Manager and Person Editor to fetch data from IMatch for display purposes.

If the Face Manager was open while this log file was created (the old version, without the bug fix I've added yesterday), my best guess is that it caused the queue to stall, because it was requesting updated person and face data all the time, trying to work down the cached event list that caused it to reload every time.

I haven't observed this issue anymore since implementing this one:
https://www.photools.com/community/index.php/topic,14911.0.html

This would explain my findings outlined above.
The FM now updates only once, or when it has not received a "recluster-complete" event for more than one second. And this removes the "blocking" effect on the database that delayed the reclustering indefinitely.