AI: Single Queued entry run on ALL selected images upon Tab Switch

Started by Jingo, June 08, 2025, 04:10:06 PM

Previous topic - Next topic

Jingo

Just ran into an issue while Autotagging and hopeful you can reproduce:

  • Selected 7 photos
  • Alt-F7 on the last image to run the AI on the selected SINGLE IMAGE and apply to all 7 images
  • After a few seconds, 1 image queued in the Info & Activity Panel (great!).
  • As I have reported before, the queue often hangs unless I switch tabs so I changed to an open results tab and then back to the Media & Folder tab.
  • The Queue processed and the AI returned results.

However, I noticed the results were modified several times, the queue remained showing 1 item in the Info & Activity and the AI Processing message continued to display.  It looks like the AI ran many times instead of the single photo.  Not sure but I think the log showed it run 12 times (which is odd because there are only 7 photos selected).

Not sure what triggered the change (changing tabs? I do this all the time and this is second time I noticed the result change) but hopefully the attached log can shed some light.

Thx! - Andy.

Mario

QuoteAs I have reported before, the queue often hangs unless
This seems to be a very peculiar problem only on your PC, with your setup / database / settings / ... since no other user reported this (no bug in the bug report board) and nothing in my memory, exception some rare cases, which could have been caused by literally anything, from an AI hiccup to rate settings.

The AutoTagFilesInQueue task is executed when the user runs AutoTagger from the dialog box, a favorite, the Command Palette or via the "Run with last settings" keyboard shortcut. It enqueues the selected files (or one file) in the background processing queue and returns control to the user.

I see these calls in your log file:

06.08 08:17:40+  500 [421C] 10  I> AutoTagFilesInQueue: RunOnce for file [119876] and 1 selected files.
06.08 08:20:43+ 1406 [421C] 10  I> AutoTagFilesInQueue: RunOnce for file [119883] and 4 selected files.
06.08 08:26:22+  422 [421C] 10  I> AutoTagFilesInQueue: RunOnce for file [119908] and 1 selected files.
06.08 08:29:50+ 4813 [421C] 10  I> AutoTagFilesInQueue: RunOnce for file [119887] and 21 selected files.
06.08 09:07:00+  438 [421C] 10  I> AutoTagFilesInQueue: RunOnce for file [119784] and 2 selected files.
06.08 09:08:34+ 6079 [421C] 10  I> AutoTagFilesInQueue: RunOnce for file [119776] and 1 selected files.
06.08 09:30:09+  860 [421C] 10  I> AutoTagFilesInQueue: RunOnce for file [119754] and 27 selected files.

06.08 09:35:32+  844 [421C] 10  I> AutoTagFilesInQueue: RunOnce for file [119706] and 20 selected files.
06.08 09:36:25+  203 [421C] 10  I> AutoTagFilesInQueue: RunOnce for file [119706] and 20 selected files.
06.08 09:39:21+  250 [421C] 10  I> AutoTagFilesInQueue: RunOnce for file [119706] and 20 selected files.

06.08 09:39:54+ 4203 [421C] 10  I> AutoTagFilesInQueue: RunOnce for file [119723] and 2 selected files.

06.08 09:44:19+ 1875 [421C] 10  I> AutoTagFilesInQueue: RunOnce for file [119826] and 41 selected files.
06.08 09:44:36+  485 [421C] 10  I> AutoTagFilesInQueue: RunOnce for file [119826] and 41 selected files.

06.08 09:47:37+  125 [421C] 10  I> AutoTagFilesInQueue: RunOnce for file [119918] and 10 selected files.
06.08 09:58:09+ 7843 [421C] 10  I> AutoTagFilesInQueue: RunOnce for file [119816] and 12 selected files.
06.08 09:59:02+  360 [421C] 10  I> AutoTagFilesInQueue: RunOnce for file [119805] and 7 selected files.

Each AutoTagger run is triggered separate, with several seconds or even minutes in-between. This looks deliberate, not random.

Jingo

Yes.. I am adding the files to the queue using the Alt-F7 shortcut.  The issue in this case is the fact that the AI is running MULTIPLE times for each of those RunOnce requests.. 

I can see this via my metadata template which shows the AI Description as it gets updated multiple times for the same selected image.  

I'd be willing to post a video of it changing and showing the queue remaining at 1 if that would help - I just know video files are often large and cannot easily be added to posts.

Mario

But you enqueued the same files multiple times (for example, file 119706 and 20 selects is added to AutoTagger 3 times, with about a minute or so in-between) and then it's only natural that they are updated multiple times.

Jingo

Yes.. THAT was legit but there was an issue later with a different file.  Sorry... In that instance, I was correcting mistakes from the AI that misidentified a bird. Once I added a keyword for the correct bird, I asked the AI again and it used the keyword to correctly provide an updated description.

I'll test again with a fresh example and see if I can reproduce so things are cleaner.

Jingo

I just reproduced this again...

1 - Fresh start of Imatch
2 - 06.09 14:17:37 - use the Autotagger on group of 2 images... select the group, Alt-F7 on one image... results added to all images.  Great!
3 - 06.09 14:18:35 - use the Autotagger on group of 11 images.. same process.. images immediately processed and only run once.  Also Great - though does the autotagger run again for the same image 2 more times (06.09 14:18:44 & 06.09 14:19:44).
4 - 06.09 14:21:21 - use the Autotagger on group of 9 images... select the group, Alt-F7 on one image... entry queued but nothing happens.  Waited 2 minutes before switching to Dashboard tab. AI still doesn't run.  Switch back to Main Tab and AI runs (06.09 14:24:58).. multiple times again (additionally at 06.09 14:25:03 & 06.09 14:25:08)?

Results are updated multiple times in the AI Keywords/Description fields as I watch the metadata panel...  Log attached... DB analysis was clean.  Sorry to keep repeating myself but this seems odd to and I'm concerned I'm going to be charged more than needed for multiple hits to the AI (the calls are very cheap.. but still).... Thx - Andy.


Mario

I have no idea why this happens and there is nothing in the log which would indicate why this happens. Could be 100 different things which cause this to reschedule or the entry remain in the queue. All of this is massively parallel and literally dozens of things run in parallel at the same time on all processor cores.

There are even a ton of collections and category updates going on, the database is searched many times etc. all at the same time.

All can do is to add additional log file entries to try to catch what happens. If you concerned about cost, I suggest you stop using AutoTagger until we can figure out why this happens in the next or following IMatch releases.

You schedule these AutoTagger runs:

06.09 14:17:37+  297 [77D4] 10  I> AutoTagFilesInQueue: RunOnce for file [119929] and 1 selected files.
06.09 14:18:35+  219 [77D4] 10  I> AutoTagFilesInQueue: RunOnce for file [119939] and 10 selected files.
06.09 14:19:44+  16 [77D4] 10  I> AutoTagFilesInQueue: RunOnce for file [119939] and 10 selected files.
06.09 14:21:21+  391 [77D4] 10  I> AutoTagFilesInQueue: RunOnce for file [119947] and 9 selected files.


and AutoTagger prompts the AI as follows

06.09 14:17:39+    0 [4C54] 02  I> PTCAIConnectorGemini: [oid: 119929] 'F:\Family_Photos\2025\2025-06\ILCE-6700_06-08-IMG01249.jpg' in 2281 ms. 14 kw., 548 dlen.

06.09 14:18:38+    0 [4C54] 02  I> PTCAIConnectorGemini: [oid: 119939] 'F:\Family_Photos\2025\2025-06\ILCE-6700_06-08-IMG01259.jpg' in 2797 ms. 15 kw., 709 dlen.
06.09 14:18:44+    0 [7260] 02  I> PTCAIConnectorGemini: [oid: 119939] 'F:\Family_Photos\2025\2025-06\ILCE-6700_06-08-IMG01259.jpg' in 2359 ms. 15 kw., 571 dlen.
06.09 14:19:46+    0 [7260] 02  I> PTCAIConnectorGemini: [oid: 119939] 'F:\Family_Photos\2025\2025-06\ILCE-6700_06-08-IMG01259.jpg' in 2391 ms. 13 kw., 673 dlen.

06.09 14:25:01+    0 [6094] 02  I> PTCAIConnectorGemini: [oid: 119947] 'F:\Family_Photos\2025\2025-06\ILCE-6700_06-08-IMG01272.jpg' in 2531 ms. 14 kw., 639 dlen.
06.09 14:25:06+    0 [6094] 02  I> PTCAIConnectorGemini: [oid: 119947] 'F:\Family_Photos\2025\2025-06\ILCE-6700_06-08-IMG01272.jpg' in 2219 ms. 15 kw., 663 dlen.
06.09 14:25:11+    0 [7980] 02  I> PTCAIConnectorGemini: [oid: 119947] 'F:\Family_Photos\2025\2025-06\ILCE-6700_06-08-IMG01272.jpg' in 2390 ms. 14 kw., 740 dlen.

File 119929 is scheduled once and processed once.
File 119939 is scheduled twice and processed 3 times.
File 119947 is scheduled once and processed 3 times.

Anything ringing a bell? What else do you to at the time in IMatch?

My first idea would be that an entry remains in the queue, sometimes, for some reasons.
But AutoTagger removes an entry from the queue when it starts processing and it only puts it back into the queue when a problem is encountered (rate limit exceeded, AI responds with an error).
But that would be logged as a W>arning in the log, and I see only a legacy Windows version warning in your log file. No other warnings or errrors.

As I said, I can only add more logging and hope that I can somehow reproduce this here. Any hint you have, and detail, is important.

A first finding: 

I see calls to UnlockBatch in your log file. This is a method that is called when a thread could not process one or more update queue entries and, instead or releasing them as finished, unlocks them for later re-processing.

In case of AutoTagger, this can happen in these situations:
- the thread is killed but did not finish processing
- the thread was disabled but did not finish processing
- a rate limit was hit
- the AI returned an error
- The update queue was disabled
- IMatch is shutting down

The most likely case is "rate limit hit", but I did not log the precise reason for calling UnlockBatch in AutoTagger. I have added that.

But a rate limit exceeded would be logged as a AI service error (everything that is not "Success" is logged), and I don't see any AI service errors logged in the log file provided. This means this is not the case. Must be something else. I'll try to see if I can reproduce this somehow.

Jingo

Thanks Mario.. I know this is a tricky issue and hard to figure out.  Not that worried about the costs... but the multiple runs are obviously not needed so I'm just trying to help narrow down a cause (DB/workflow, AI or software).

For this session - I wasn't doing anything else in IMatch.. especially for that last File (119947). I selected the images, hit Alt-F7 and waited.  The queue didn't process so I did the "switching tabs" thing which forced the queue to be run.. but it ran multiple times.

The "rate limit" is a bit confusing to me.. I set them based on the Gemini free tier API help.  I'm more than willing to make changes to them if you think that might help.... I have not seen the pause message in the status bar so do not believe I am hitting the rate limits (shouldn't be as I only made 3 requests over 10 minutes in this session and rate limits is set to 30 per minute).

Glad the UnlockBatch might be a clue... please let me know if I can perform any other testing. 

Appreciate your help/review with this!

Mario

I now processed images for over an hour, using LM Studio with Gemma 3, OpenAI and Gemini. About 2,000 processed images, not once was there a problem or an UnlockBatch function call to place an image back into the queue.

So, no repro case so far.

I have added some extra logging for the next release. Maybe we can catch what the reason is for AutoTagger placing files back into the queue on your system.

The rate limit expired is normal, it should not be logged when there was no rate limit hit before. I have fixed that. Left-over from testing and only used when debug logging is enabled.

The rate limit dialed in in AutoTagger must match the rate limit of the tier you use with whatever model and AI you use. Only then AutoTagger can run with the best performance and without throttling.

Update

Processed more files with different AIs. Tried things like making IMatch busy otherwise, doing stuff. Never failed to process the files with AutoTagger, never stalled or paused. I've used my desktop computer and my Notebook.

Your workflow must have a very specific component or step sequence I cannot reproduce. I have done what I could. No sense in spending even more hours and money on this, trying to repro this. Maybe you can figure out more details or a sequence of step.

Jingo

Thx for trying at least.. once the new version comes out, I'll test again and see if the additional debug code shed any light on things.

I will try a fresh session again with a new debug log as well using my workflow across a few dozen images to see if I can reproduce.   Note that it should matter, but I do run a metadata template as a favorite in between AI requests to copy the AI Keywords and AI Description to appropriate XMP fields... pretty sure that isn't the issue but failed to mention that before.

Anyway.. thx again!

Mario

AutoTagger may put back elements into the Queue when it notices that the queue has become disabled for some reason (IMatch pauses/disables the queue for quite a number of operations, depending on estimated duration and if a running update queue could possible interfere).

Before putting back, AutoTagger checks if one or more elements were successfully processed in the current "run" and then releases them instead of putting them back for later re-processing. I wonder if your workflow somehow circumvents that or maybe it's a timing issue... 4, 8, 12, AutoTagger instances running at the same time, all processing entries from the queue, sending data to the AI, getting info back, updating keywords, descriptions and somehow, in-between all of that, you trigger an operation that pauses the queue just at the right moment...

As I said, I have been unable to reproduce this. But there is a billion PCs out there, any all are slightly different.

Jingo

Just updated to 2025.4.2 and reproduced the issue with the same steps unfortunately:

0 - Selected group of 3 images, Alt-F7 on one of the images
 Autotagger immediately ran and added the Keywords and Description. 
1 - Added keyword to the same single image
2 - Selected same group of 3 images, Alt-F7 on one of the images
  Autotagger immediately ran and added the Keywords and Description. 
3 - Run Metadata Template to move AI info to XMP info

4 - Added keyword to a new single image
5 - Selected group of 3 images, Alt-F7 on one of the images
  Autotagger did not run - image is queued and 1(busy) shows in the Info & Activity panel (but IM is just sitting there with no activity).

cbac49y41b.png

Debug log attached in case the additional items you may have added are helpful to diagnose.

Not sure if it helps.. but I do see that the successful entries all have a
CIMEngineAIAutoTagger::AutoTagFiles within the CIMEngineUpdateQueue::AddEntries @ (06.24 14:11:20 and 06.24 14:12:20)

However, the one that remains queued does not... just an AddEntries @ (06.24 14:15:51)

Jingo

Left IM running all night.. Queue has not processed. 

Switching tabs from Media & Folders to Categories and back does force the Queue to process so same process is needed.

I then see in the log an CimEngineUpdateQueue and the CimEngineAIAUtoTagger entry get added to the log (new version attached to show progression overnight and steps needed this morning to fire the queue).

I believe the Queue entry briefly showed a change from 1 (busy) to 1 (invalid) after I did the tab switch and saw the Autotagger running message appear... but, it processed correctly after that.

Not sure what else I can do... perhaps something is blocking the system from performing the CIMEngineUpdateQueue immediately all the time via a code check?

Thx!

Mario

I will again try to reproduce this. I've never experienced this and no other user reported this.
This might be very well something that happens only with your database.

I've looked at the log from yesterday and it looked OK. Entries were enqueues, the queue was not disabled or paused, the queue was signaled with type 10 (AutoTagger) after new entries were added etc. It should just run whatever is in the queue.

Issues like this are hard to debug, because he behavior may even depend on the number of processors installed, Windows thread pooling and whatnot. When I can reproduce it, I can fix it.

Jingo

No worries Mario... I was hopeful that the missing (and then added after my manual action) CimEngineAIAutoTagger  might be a clue into the issue... but I guess not.

Overall, it is simple for me to just switch tabs or perform some other activity which seems to "wake" IMatch up to process the queue entry so if no one is experiencing this.. it is ok and probably just my database.

I'm tempted to just create a new database, loading all the metadata from the files and "starting over" to see if that resolve things.. but at the end of the day, it is a minor issue with an easy workaround.

Always happy to share my DB if that might help as well.

Cheers! - Andy.