V5.5 loading images in viewer or quickview takes up to 6 seconds

[joel23]

See subject.
Tested on two computers, one with an onboard video card, one with a GeForce 9500 GT.
Even in a W10 guest in VMware previews show up much faster in quickview while on V5.4.18

The only filetype which shows up fast with 5.5 is TIF, all others (JPG, DNG, PSD, RAW) take between 2 and 5 seconds to load, even small JPG when clicked them first.

I also noticed there must be something working like a preload, means the next images in the view are loaded much faster, but when I go say from an image at the end of the selection to one at the beginning it again takes again severall seconds to get a preview in V5.5.  Same after a new start of IM which is to explain 'cause the cache is only temporary.
Cache settings are switched to OFF.  Use embedded preview turned on.

For V5.4 I don't have any load time...
V5.4.18
12.07 14:54:09+    0 [15FC] 10  M>                > 15 CIMCacheManager::LoadCacheImage  'IMCacheManager.cpp(1264)'
12.07 14:54:09+    0 [15FC] 10  I>                    CM Load Begin [15950] from F:\PNG\12121\11_20\MEV83015.jpg
12.07 14:54:09+    0 [15FC] 10  M>                < 15 CIMCacheManager::LoadCacheImage
12.07 14:54:09+    0 [1ABC] 10  M>               > 15 PTPIP::LoadThumbnail  'PTPIP.cpp(2998)'
12.07 14:54:09+    0 [15FC] 10  M>                < 15 CIMCacheManager::GetCacheImage
12.07 14:54:09+    0 [15FC] 10  M>               < 14 CViewPaneFileWndContainerPreview::InnerLoad
12.07 14:54:09+    0 [0C90] 10  I>              FileHist Delegate: 1 of 1 events written in 0ms


V5.5
12.07 15:10:10+   47 [1358] 02  I>              F:\PNG\12121\11_20\MEV83015.jpg loaded in 5117ms. Result: 2


The zip-archiv contains two logs from each version with entries for the image mentioned above.

[attachment deleted by admin]

[Mario]

It seems that many of your files have virtual transformations or similar. This means that IMatch needs to apply rather costly processing on these files, which increases the standard load time for a typical JPEG file from 1 to 2 seconds to 5 seconds on your machine...not really snappy, but it is as fast as it gets as it seems.

And this means if you scroll faster than 5 seconds per image, IMatch cannot catch up.

Try with some JPEG files which have no virtual transformations, crops or similar. That measures the raw performance for loading files and bringing them into view (that takes only 50ms on your machine, once the file is loaded).

[joel23]

It seems that many of your files have virtual transformations or similar. This means that IMatch needs to apply rather costly processing on these files, which increases the standard load time for a typical JPEG file from 1 to 2 seconds to 5 seconds on your machine...not really snappy, but it is as fast as it gets as it seems.

And this means if you scroll faster than 5 seconds per image, IMatch cannot catch up.

Try with some JPEG files which have no virtual transformations, crops or similar. That measures the raw performance for loading files and bringing them into view (that takes only 50ms on your machine, once the file is loaded).

Hi Mario,
NONE of my photos have a virtual transformation - only some videos on my productions DB at home have, on which the load behavior for quickview is the same.

But the logs I provided are from a new and pretty small DB which has no videos at all. And as said PSD, JPG, DNG and RAW are effected by this. But not TIF.
May I ask what's the indicator is the log, which leads you to this conclusion?

[Mario]

Sorry, my fault. Misinterpretation.

For example, I see

F:\PNG\12121\11_20\MEV85014.jpg loaded in 5210ms.

this means that WIC took more than 5 seconds to load this JPEG file.
Even on my low-end tablet WIC rarely needs to load more than 1 second, even for 24 or 36 MP JPEG files.

All files from that folder take between 4 and 5 seconds to load. How many MP do these files have?
What kind of drive is F: ?

Please select the file above in a file window and then go to Help > Support > WIC diagnosis.
Maybe there's something strange with WIC going on.

[joel23]

I have no access to the other computer at the moment, but the drive F: was an iSCSI Lun from a netappp SAN - usually with 80MB/s

Here is some data from another computer (NVIDIA Graka)

JPG with 8MB on SSD
C:\Abstract\SmokeArt\CRW_15534-mb2.jpg loaded in 1248ms. Result: 2
12.12 10:12:14+    0 [15D0] 05  M>                  < 17 [63ms] CIMDXWnd::LoadFile
12.12 10:12:14+    0 [15D0] 10  M>                  > 17 CIMAnnoManager::GetContainer  'IMAnnoManager.cpp(194)'
12.12 10:12:14+    0 [15D0] 10  M>                  < 17 CIMAnnoManager::GetContainer
12.12 10:12:15+ 1170 [19AC] 50  M>                 < 16 [1342ms] CIMDXCacheManagerLoaderDelegate::InnerLoad
12.12 10:12:15+    0 [19AC] 50  M>                 > 16 CIMDXCacheManagerLoaderDelegate::InnerLoad  'IMDXCacheManager.cpp(359)'


WIC diag - latest FastPictureViewer Codec Pack, the result for JPGs is the same for both versions:
Testing file 'C:\Abstract\SmokeArt\CRW_15534-mb2.jpg'
   Thumbnail: Codec 'JPEG Rotator (FastPictureViewer Codec Pack)'
      (GetThumbnail failed (88982F44 Unknown error 0x88982F44).) 0x0 pixel in 0 ms.
   Preview: Codec 'JPEG Rotator (FastPictureViewer Codec Pack)'
      (GetPreview failed (88982F81 Unknown error 0x88982F81).) 0x0 pixel in 0 ms.
   Full resolution: Codec 'JPEG Rotator (FastPictureViewer Codec Pack)'
      () 5000x5000 pixel in 31 ms.

CR2 10,8 MB on ~ 100Mb/s HDD SATA3
There are no loading entries for PSD/DNG/CR2 in the log (was this always like this?) - just found entries for loading the cached preview.

WIC diag:
Testing file 'M:\Master\2015_01\_MG_16991.CR2'
   Thumbnail: Codec 'Canon Raw Decoder (FastPictureViewer Codec Pack)'
      () 160x104 pixel in 0 ms.
   Preview: Codec 'Canon Raw Decoder (FastPictureViewer Codec Pack)'
      (GetPreview failed (88982F81 Unknown error 0x88982F81).) 0x0 pixel in 0 ms.
   Full resolution: Codec 'Canon Raw Decoder (FastPictureViewer Codec Pack)'
      () 1936x1288 pixel in 16 ms.

RESULT: A codec for this file format is installed and it looks like it fully supports the format. The file does not contain an embedded preview.

[Mario]

If I understand you correctly, you're pulling the files over a network?
This can of course cause a slower performance. Try on the same PC with some of the files copied to a folder on the local hard disk. The difference in performance is what is added by the network. Bandwidth is not everything, it's also latency that counts. And the Windows WIC access pattern for the file - which may cause multiple reads and seeks instead of one downstream of the entire file. And then 80 MB/sec no longer apply.

[joel23]

If I understand you correctly, you're pulling the files over a network?

This was the case for the PC on which the logs came from.  But it is an iSCSI LUN attached as a local drive and not accessed via SMB protocol. It's not writing to the images here so pulling 8MB should not be a problem, especially because there was NO ONE else accessing the NETAPP Filer.

Anyway. I have the same results on my other PC (as I said in my last post) with a local SSD: 1.248ms for a JPG of 8 MB and for PSD/DNG even worse.

[Mario]

I'm not sure that I understand all the measures and what hardware it was performed on.
Please send me a sample image which takes 5 seconds to load on your system. According to the WIC diagnosis, it should take a lot less.
Let's see how quick it loads here or which WIC operation takes so much time.

[joel23]

Hi Mario,
I believe this behaviour has nothing to do with the image(s) themself or if they were loaded from a mapped LUN (F:)
Here are the results I get when loading an image from local drive (D:) and a mapped iSCSI LUN:
JPG 7,39MB
V5.5.0.5
D:\PNG\12121\11_20\MEV83019.jpg loaded in 4992ms. Result: 2
F:\PNG\12121\11_20\MEV83019.jpg loaded in 5085ms. Result: 2
F:\PNG\12121\11_20\MEV83019.jpg loaded in 5007ms. Result: 2
D:\PNG\12121\11_20\MEV83019.jpg loaded in 5179ms. Result: 2
F:\PNG\12121\11_20\MEV83019.jpg loaded in 5226ms. Result: 2

Not much difference.
This PC is not the fastes one - but even on my faster computer I got a noticeable longer loadtime compared to V5.4

But let's have a look to the logfile (also see attached image, there "CIMDXCacheManager::Purge"):

12.16 09:52:29+    0 [1854] 50  M>               > 14 CIMDXCacheManager::ClearPreloadQueue  'IMDXCacheManager.cpp(1962)'
12.16 09:52:29+    0 [1854] 50  M>               < 14 CIMDXCacheManager::ClearPreloadQueue
12.16 09:52:29+    0 [1854] 50  M>               > 14 CIMDXCacheManager::AddCacheItem  'IMDXCacheManager.cpp(1818)'
12.16 09:52:29+    0 [1854] 50  M>               < 14 CIMDXCacheManager::AddCacheItem
12.16 09:52:29+    0 [1874] 50  M>               > 14 CIMDXCacheManagerLoaderDelegate::InnerLoad  'IMDXCacheManager.cpp(359)'
12.16 09:52:29+    0 [1854] 05  M>               < 14 CIMDXWnd::LoadFile
12.16 09:52:29+    0 [1854] 10  M>               > 14 CIMAnnoManager::GetContainer  'IMAnnoManager.cpp(194)'
12.16 09:52:29+    0 [1854] 10  M>               < 14 CIMAnnoManager::GetContainer
12.16 09:52:34+ 4290 [1874] 03  I>               # Process Memory Info: WSC: 327MB, WSP: 521MB, PF: 1705142
12.16 09:52:34+   16 [1874] 50  M>               > 14 CIMDXCacheManager::Purge  'IMDXCacheManager.cpp(2032)'
12.16 09:52:34+    0 [1874] 50  M>               < 14 [16ms] CIMDXCacheManager::Purge
12.16 09:52:34+    0 [1874] 50  M>               > 14 CIMDXCacheManagerLoaderDelegate::ApplyTransforms  'IMDXCacheManager.cpp(728)'
12.16 09:52:34+    0 [1874] 50  M>               < 14 CIMDXCacheManagerLoaderDelegate::ApplyTransforms
12.16 09:52:35+ 1185 [1874] 50  M>              < 13 [5491ms] CIMDXCacheManagerLoaderDelegate::InnerLoad
12.16 09:52:35+    0 [1854] 02  I>             D:\PNG\12121\01_10\MEV83001.jpg loaded in 5491ms. Result: 2

The bold numbers on the left sums up to the total load time. 
What very noticeable is that (not above, but most of the time) "CIMDXCacheManager::Purge" takes 3-4 seconds and this always (and every time) happens before an image actual is loaded. Above this (purge or whatever) action starts at 09:52:29,.. and ends 09:52:34,..
According to procmon image loading starts at 09:52:34,09 ends at 09:52:35,29

12.16 09:06:38+ 3962 [08E8] 50  M>               > 14 CIMDXCacheManager::Purge  'IMDXCacheManager.cpp(2032)'
12.16 09:07:02+ 4181 [08E8] 50  M>               > 14 CIMDXCacheManager::Purge  'IMDXCacheManager.cpp(2032)'
12.16 09:07:18+ 4025 [08E8] 50  M>               > 14 CIMDXCacheManager::Purge  'IMDXCacheManager.cpp(2032)'


Cache Settings:
Working mode: Off
use embedded: yes
Purge: On or Off doesn't makes a difference

Viewer:
prel-oad: Off

[attachment deleted by admin]

[Mario]

CIMDXCacheManager::Purge takes 16 milliseconds. The runtime is in the [] brackets. The timeline on the left just shows the time the entry was logged, and since many things are processed in parallel at the same time you also have to consider the thread id first [number].

Your log file quote is out of sequence and useless, because I can see that loading the image took [5491ms] but I cannot see when it started because you left out part of the call stack in your quote and did not attach the full log.

[joel23]

CIMDXCacheManager::Purge takes 16 milliseconds. The runtime is in the [] brackets.

I know - but usually the higher value appears for CIMDXCacheManager::Purge, see attached image in the former post.
Attached here another log where the same image (MEV83001.jpg) was loaded twice, once when IM was started and once before it was closed.

[attachment deleted by admin]

[Mario]

It is indeed only the load image function on your system which is so slow (tip: search for #sl to find operations which took more than 5 seconds).
This method basically loads the image via WIC, transforms it to make it suitable for DirectX usage and then caches it in memory. The usual time for this is maybe one 1 second, usually less.

I have seen a bad performance decrease (20 seconds instead of 1 second) when the Histogram was enabled in the Viewer. The method used to calculate the histogram data caused DirectX to require 20 seconds to convert the file, instead of 0.2 seconds. Re-arranging that solved the problem (solved for the 5.5.4).

Send me one of your files so I can see what takes so long.
The WIC codec raw speed we already timed using Wic Diagnostics.
Do you display the file in the Viewer or QVP?
If in the Viewer, which options / overlays are enabled?

[joel23]

The WIC codec raw speed we already timed using Wic Diagnostics.
Do you display the file in the Viewer or QVP?

QVP but with Viewer it is was the same.

After starting this reply I checked what IMatch was doing before actually loading the image and I found severall activities in procmon which loaded the image again and again from offset 0 to a certain size (~1.8MB) and between that how it searched for or loaded the color profiles.
I thought I should have a look to my video card and there to the color profile settings. The profile used was an older (2013) calibrated one. As soon I changed that to systems sRGB profile, loadtimes are okay. Not "wow!" but as to expect on this machine.

Windows standard sRGB
12.16 17:06:55+  156 [147C] 50  M>             > 12 CIMDXCacheManager::Purge  'IMDXCacheManager.cpp(2032)'
12.16 17:06:55+    0 [147C] 50  M>             < 12 CIMDXCacheManager::Purge
12.16 17:06:55+    0 [147C] 50  M>             > 12 CIMDXCacheManagerLoaderDelegate::ApplyTransforms  'IMDXCacheManager.cpp(728)'
12.16 17:06:55+    0 [147C] 50  M>             < 12 CIMDXCacheManagerLoaderDelegate::ApplyTransforms
12.16 17:06:56+ 1108 [147C] 50  M>            < 11 [1264ms] CIMDXCacheManagerLoaderDelegate::InnerLoad
12.16 17:06:56+    0 [0778] 02  I>           D:\PNG\12121\01_10\MEV83003.jpg loaded in 1264ms. Result: 2
12.16 17:06:57+ 1841 [0778] 10  M>            > 11 CIMEngineUpdateQueue::Enable  'IMEngineUpdateQueue.cpp(2025)'

and back to the calibrated profile:
12.16 17:15:46+ 4571 [1F94] 50  M>             > 12 CIMDXCacheManager::Purge  'IMDXCacheManager.cpp(2032)'
12.16 17:15:46+    0 [1F94] 50  M>             < 12 CIMDXCacheManager::Purge
12.16 17:15:46+    0 [1F94] 50  M>             > 12 CIMDXCacheManagerLoaderDelegate::ApplyTransforms  'IMDXCacheManager.cpp(728)'
12.16 17:15:46+    0 [1F94] 50  M>             < 12 CIMDXCacheManagerLoaderDelegate::ApplyTransforms
12.16 17:15:47+ 1248 [1F94] 50  M>            < 11 [5819ms #sl] CIMDXCacheManagerLoaderDelegate::InnerLoad

Thanks a lot for looking into this Mario - guess it must be something similar on my other machine. I'll have a look to it later.

[Mario]

IMatch loads the first 'frame' of the image via Windows WIC. This is an atomic call (one function call).
When the image is loaded, it asks WIC for the color profile of the image. I don't know how Microsoft has this implemented in WIC, but usually the color profile should be loaded with the image.

IMatch itself loads the monitor color profile only once, unless the monitor changes or the window is moved to another monitor. The profile is cached.
I'm not sure what you mean with "between that how it searched for or loaded the color profile". Do you mean IMatch searched the Windows color profile folder over and over again?