Indexing Slow

[Tveloso]

Mario, I know that you have not had time to work on this one yet.  I just wanted to post that I'm seeing this issue as well.

For me, the queue is moving, but very slowly. 

I did a write-back for a scope of 267 Files (most of which have one version to propagate to).  The write-back completed in just a few seconds, but when IMatch started reading the files back in, that moved very slowly (it's still underway as I write this with an estimate of another 19 minutes to complete - the initial estimate was 35 minutes):

   

Looking at the log, I see lots of entries for IMEngine5.cpp, line 9028, with several seconds between them (as low as 1 second, and as high as 12):

Code Select Expand

02.16 16:08:34+    0 [3B38] 05  M>  <  0 CIMEngine5::UpdateFileAttributes
02.16 16:08:44+10407 [7B3C] 05  M> >  0 CIMEngine5::UpdateFileAttributes  'V:\develop\IMatch5\src\IMEngine\IMEngine5.cpp(9028)'
02.16 16:08:44+    0 [7B3C] 05  M>  <  0 CIMEngine5::UpdateFileAttributes
02.16 16:08:47+ 3156 [61FC] 05  M> >  0 CIMEngine5::UpdateFileAttributes  'V:\develop\IMatch5\src\IMEngine\IMEngine5.cpp(9028)'
02.16 16:08:47+    0 [61FC] 05  M>  <  0 CIMEngine5::UpdateFileAttributes
02.16 16:08:54+ 6266 [7328] 05  M> >  0 CIMEngine5::UpdateFileAttributes  'V:\develop\IMatch5\src\IMEngine\IMEngine5.cpp(9028)'
02.16 16:08:54+    0 [7328] 05  M>  <  0 CIMEngine5::UpdateFileAttributes
02.16 16:09:02+ 8406 [7844] 05  M> >  0 CIMEngine5::UpdateFileAttributes  'V:\develop\IMatch5\src\IMEngine\IMEngine5.cpp(9028)'
02.16 16:09:02+    0 [7844] 05  M>  <  0 CIMEngine5::UpdateFileAttributes
02.16 16:09:04+ 2094 [7A0C] 05  M> >  0 CIMEngine5::UpdateFileAttributes  'V:\develop\IMatch5\src\IMEngine\IMEngine5.cpp(9028)'
02.16 16:09:04+    0 [7A0C] 05  M>  <  0 CIMEngine5::UpdateFileAttributes
02.16 16:09:09+ 5203 [78CC] 05  M> >  0 CIMEngine5::UpdateFileAttributes  'V:\develop\IMatch5\src\IMEngine\IMEngine5.cpp(9028)'
02.16 16:09:09+   15 [78CC] 05  M>  <  0 [15ms] CIMEngine5::UpdateFileAttributes
02.16 16:09:22+12532 [7A34] 05  M> >  0 CIMEngine5::UpdateFileAttributes  'V:\develop\IMatch5\src\IMEngine\IMEngine5.cpp(9028)'
02.16 16:09:22+    0 [7A34] 05  M>  <  0 CIMEngine5::UpdateFileAttributes
02.16 16:09:25+ 3109 [7A0C] 05  M> >  0 CIMEngine5::UpdateFileAttributes  'V:\develop\IMatch5\src\IMEngine\IMEngine5.cpp(9028)'
02.16 16:09:25+    0 [7A0C] 05  M>  <  0 CIMEngine5::UpdateFileAttributes
02.16 16:09:31+ 6234 [0DF4] 05  M> >  0 CIMEngine5::UpdateFileAttributes  'V:\develop\IMatch5\src\IMEngine\IMEngine5.cpp(9028)'
02.16 16:09:31+    0 [0DF4] 05  M>  <  0 CIMEngine5::UpdateFileAttributes
02.16 16:09:33+ 2094 [7A30] 05  M> >  0 CIMEngine5::UpdateFileAttributes  'V:\develop\IMatch5\src\IMEngine\IMEngine5.cpp(9028)'
02.16 16:09:33+   16 [7A30] 05  M>  <  0 [16ms] CIMEngine5::UpdateFileAttributes
02.16 16:09:39+ 5203 [7A34] 05  M> >  0 CIMEngine5::UpdateFileAttributes  'V:\develop\IMatch5\src\IMEngine\IMEngine5.cpp(9028)'
02.16 16:09:39+    0 [7A34] 05  M>  <  0 CIMEngine5::UpdateFileAttributes
02.16 16:09:41+ 2078 [78CC] 05  M> >  0 CIMEngine5::UpdateFileAttributes  'V:\develop\IMatch5\src\IMEngine\IMEngine5.cpp(9028)'

It has completed successfully now, and appears to have taken a little over 24 minutes (If I'm interpreting the log entries correctly, it appears the first post-write-back entry was at 16:05:56, and the last was at 16:30:19 - so not quite the 35 minutes originally estimated, but on that order).

The next time I have a batch of files to write-back, I'll turn on debug logging before doing so.

[Mario]

I have split this out of the other thread, because I think we're mixing too many things.
The problem of the OP was (apparently) solved by the Face Manager bugfix from yesterday. This also matches my findings in the log files provided, see my comment in the original thread.

You report slow indexing, different thing I believe.
The CIMEngine5::UpdateFileAttributes method is called to update file system data of a file in the database. For this, IMatch uses Windows file system methods to fetch file information, like size and time stamps. The method is called as part of the file processing. It takes between 0 and 15ms on your computer, which is fine.

You did not include the full log, so I cannot tell what happened at the time, and what was actually slowing down the indexing process.

[Mario]

Any needs on this? Else I'll close it.

[Tveloso]

Mario, I did a write-back for a small set of files the other night (67 files) and the issue didn't happen.

But they were all video files, and I wasn't sure if perhaps the different format could be playing a part in the issue not manifesting...or maybe more likely, the lack of Version propagations?

I'll have another set of still images to write back tonight (which will include propagating to versions), and I'll report back.

[Mario]

Debug logging enabled, it possible.
Writing back to MP4 files takes ExifTool longer. ExifTool creates a copy of the video, splines in the metadata, and if this is successful, it deletes the original video and renames the copy. I don't know if your videos are 100 MB or 4GB, so. But that's the only difference between images and videos when it comes to write-back.

[Tveloso]

I did a writeback for a scope of 514 Files (the majority of which had one version), which resulted in 944 Files being written back.

The writeback itself (including propagation to the Versions) completed in well under a minute (probably closer to 30 seconds), but the Reading Metadata process went quite a bit slower (an initial estimate was 29 minutes).

This seemed to be moving faster though, than it did with the smaller batch of files in the first post here (the initial estimate was about the same, but for a lot more files this time)...I took a Screenshot at about a third of the way through:

   

I'm afraid that I forgot to set Debug Logging before I started the writeback, but I did so pretty soon after the Reading Metadata process started, so hopefully this log shows something useful.  I'll send the log to the support email address.

[Mario]

Did you look at Windows Performance Monitor? Were all CPU's maxed out, was a disk maxed out, limiting how fast IMatch can process the files?

[Tveloso]

I'm afraid I didn't check performance monitor during that process.

In fact, I had to leave the room soon after I took the screenshot, and didn't come back until well after IMatch had finished updating the files.  So I don't have a good sense of how things were actually moving.  But it did seem to be faster than what I saw before (so maybe the issue didn't actually occur this time?)

I know that IMatch must do a great deal of work when updating files following a writeback, so perhaps this was a normal instance of that.

[Mario]

Indexing speed in IMatch 2025 is usually much, much faster than before, because IMatch better balances available resources.

Reading metadata mostly depends how fast ExifTool delivers the data, the file format, if the images contain XMP regions which require face detection.

A debug log shows me some timing, but equally important is what Performance Monitor shows in the "Performance" tab. Are all CPUs used? Is maybe the source or database disk at 100%?

I get very fast processing times for typical RAW, Phone DNG and JPG/TIFF files even on my notebook or in a VM with only 8GB RAM and 4 processor cores. IMatch squeezes out of the resources what is possible, controlled by the configured performance profile.

And of course, the virus checker, may be the reason why IMatch is slow.