Image Batch Processor - Export hangs IMatch and takes minutes to complete

[Jingo]

Hi Mario - something strange going on for my system.  I setup a new Image Batch Process to export smallish JPG files to a thumb drive for a photo frame I have.  The export is as follows:
   200 dpi, JPG 95%, resize to 1280x800 (use cache), do not add files to database, always write Meta to files... that's it.

I drag 75 files to the process and let er rip.... from the log, I can see each files takes about 600ms to load and develop.. not bad at all! 

However, then the problem begins.... the program begins to just hang for minutes... the log shows me warnings:

Code Select Expand

  W>       Failed to index file 'R:\2018-08\S9+_20180815_102302.jpg'  'v:\develop\imatch5\src\imatchng\imbatchprocessor.cpp(1092)'

Hmm... it shouldn't even try to index the file since I said not to add them to the database... but this could be just a wording issue and more of an FYI I suppose...

However - the big issue occurs next... there are PTETWrapper removes for every file... and these are taking between 4 and 8 seconds to process each.... are these temp files that the program creates?  Why does it take so long to remove them from the system?

Code Select Expand

12.30 20:03:41+ 4328 [13840] 10  M>       <  6 [4328ms] PTETWrapper::ProcessRun
12.30 20:03:41+    0 [13840] 10  M>      <  5 [4328ms] PTETWrapper::Remove
12.30 20:03:41+    0 [13840] 10  M>      >  5 PTETWrapper::Remove  'v:\develop\imatch5\src\imengine\ptetwrapper.cpp(4064)'
12.30 20:03:41+    0 [13840] 10  M>       >  6 PTETWrapper::ProcessRun  'v:\develop\imatch5\src\imengine\ptetwrapper.cpp(3592)'
12.30 20:03:47+ 5547 [13840] 10  M>       <  6 [5547ms #sl] PTETWrapper::ProcessRun
12.30 20:03:47+    0 [13840] 10  M>      <  5 [5547ms #sl] PTETWrapper::Remove
12.30 20:03:47+    0 [13840] 10  M>      >  5 PTETWrapper::Remove  'v:\develop\imatch5\src\imengine\ptetwrapper.cpp(4064)'
12.30 20:03:47+    0 [13840] 10  M>       >  6 PTETWrapper::ProcessRun  'v:\develop\imatch5\src\imengine\ptetwrapper.cpp(3592)'
12.30 20:03:55+ 8188 [13840] 10  M>       <  6 [8188ms #sl] PTETWrapper::ProcessRun
12.30 20:03:55+    0 [13840] 10  M>      <  5 [8188ms #sl] PTETWrapper::Remove
12.30 20:03:55+    0 [13840] 10  M>      >  5 PTETWrapper::Remove  'v:\develop\imatch5\src\imengine\ptetwrapper.cpp(4064)'
12.30 20:03:55+    0 [13840] 10  M>       >  6 PTETWrapper::ProcessRun  'v:\develop\imatch5\src\imengine\ptetwrapper.cpp(3592)'

Log file attached... Thx!

[Mario]

Lots going on in that log file. Viewer/Quick View panel used all the time. BP running many batches? The log covers over 3 hours of IMatch usage...

The warning is normal. Ignore it. It is logged when the BP does not index a file (for example, when the output folder is not in the database).

You are writing metadata in your BP preset. IMatch does this by running ExifTool for each output file and telling it what to copy rom the original file.
I see a warning about IMatch being unable to index V:\Family_Photos\2019\2019-08\E-M5MarkII_08-14_P8141899.jpg_original'.
That is a backup file produced by ExifTool. It should only be there if something went wrong, because the IMatch / BP uses overwrite_original to overwrite the original without creating a copy.
But this is logged only once.

Another ExifTool warning about invalid GPS data in one file. Also not unusual.

ExifTool is run many times during these 3 hours.
At 20:01 the first call to PTETWrapper::Remove is logged. This function strips metadata from files. It is used under specific circumstances, e.g., when the BP does not copy any data from the source file but writes custom data to the output file. This has technical reasons.
Another BP preset used for that session? Because Remove() was not logged before.
It runs once for each output file in the current BP session. Nothing unusual. It takes between 0.2 and 5 seconds for each file. Not sure why it is so slow for some of these files. The file names are not logged because Remove() usually never fails and usually takes less than 1 s for a file. Not between 0.2 and 5 seconds (!) as on your system.
Not sure what drive R: is. Have you tried another output folder, just in case R: is very slow or some other software is interfering?

[Jingo]

Thanks Mario - it is just a simple BP to take selected images from my JPG database (on spinning disk) and export them to the right size for the photo frame to a USB stick (USB3 port).  The files appear to export quickly (I can see them filing to the USB Drive in Windows) - it is the IMatch BP process that seems to hang after the images are fully exported... when I did this for 10 images - it hung for only a minute so I didn't pay any attention... but when I exported over 70 images - the system hung for almost 5 minutes.  I get that "unresponsive blurry window" that happens when IMatch is not responding and need to wait until the process complete window eventually appears.

Yes - the .jpg_originals were left behind in that folder.... probably an abandoned process at some point when the system crashed.  I have removed those from the database.  I will try a new log session... and a different drive...

[Mario]

Writing an image is fast compared to writing metadata. And the BP first must create the output image and then copy over metadata from the source file and/or set custom metadata. This is what takes so long on the USB drive. Not sure why. My first test would be to repeat this but output to a normal built-in disk.  If this is much faster, the problem is identified.

[Jingo]

Writing an image is fast compared to writing metadata. And the BP first must create the output image and then copy over metadata from the source file and/or set custom metadata. This is what takes so long on the USB drive. Not sure why. My first test would be to repeat this but output to a normal built-in disk.  If this is much faster, the problem is identified.

First Test:
  Restart IM and export a new set of 72 images to the USB Drive... the images are exported VERY Quickly (these are only 400kb files) and verified on the "R" drive.. however, IMatch hangs after the export is complete for over 10 minutes.. the last entry in the debug log during the hang is:

Code Select Expand

12.31 15:45:31+    0 [11198] 05  I>                     ExifTool: Launching from 'C:\Program Files\photools.com\imatch6\exiftool.exe', using IMatch config file 'C:\Program Files\photools.com\imatch6\imatch_et.config' (C:\PROGRA~1\photools.com\imatch6\IMATCH~1.CON)

Refreshing the log during the hang does not show any additional lines...  I left it for awhile and when I came back, only these 2 lines show:

Code Select Expand

12.31 16:13:07+1655984 [11198] 05  M>                     < 20 [1761766ms #sl] CIMIEImageExport::Run
12.31 16:13:07+    0 [11198] 10  M>                    < 19 [1761766ms #sl] CIMIEManager::Execute


Second Test:

Same images... exported to SSD drive instead...

Images export very very fast (as expected) and then IMatch hangs at the same line of code.. but only for about 10 seconds this time:

Code Select Expand


12.31 16:20:15+    0 [11198] 05  I>                     ExifTool: Launching from 'C:\Program Files\photools.com\imatch6\exiftool.exe', using IMatch config file 'C:\Program Files\photools.com\imatch6\imatch_et.config' (C:\PROGRA~1\photools.com\imatch6\IMATCH~1.CON)

After a moment - the log shows:

Code Select Expand

12.31 16:20:38+23218 [11198] 05  M>                     < 20 [83140ms #sl] CIMIEImageExport::Run
12.31 16:20:38+    0 [11198] 10  M>                    < 19 [83140ms #sl] CIMIEManager::Execute


So, the Exiftool is doing "something" that takes a long time on the USB drive vs the fast SSD drive... is it writing out the metadata from the catalog once the files are already copied?  If so... then that is the culprit and I can modify my workflow to export to the SSD and then move the files in Windows (or via IM script) after the process completes.

EDIT - HMMmm  I just checked and I actually had the box for "write metadata all the time" set.. but none of the boxes above actually were checked so no metadata was included in the files.... as a test, I also exported to the R drive with the metadata all the time setting unchecked and it didn't make things go any quicker... so I'm stumped.

If the actual image files took a long time to export, that I could understand.. but the files are already written out to the drive while IMatch is hanging so something else must still be accessing the slower drive... like a verification or something?

[Mario]

Not enough info to work with. Always ZIP and attach the complete log.
The BP uses ExifTool (runs it) to copy metadata from the source to the destination file. And also when you set custom data and under some other conditions.
I've made a quick check with 20 files, mix of RAW and JPEG, JPEG output. The typical runtime for the ExifTool step is < 1 second.
Maybe your virus checker is triggered by IMatch launching a process, and intercepts the call for scanning the file or something? This would explain the delay.
How long does it take when you export only one image?