Integration File Cache - Inconsistent File Timestamps on Windows

[cs_pixinsight]

I seem to be having issues with the file cache functionality.  It works as expected for a while after gathering the noise estimates, etc., but if I try to integrate the same files the next morning PI has to reread them to gather all the statistics again.  Per the documentation it should be valid for 30 days if the files are not modified.

I checked several of them this morning and none of them have been modified since the morning of 5/2, but when I attempted to integrate them this morning PI recalculated the statistics on all of them.  If the modification time isn't being used to determine if the file has changed, then what would PI be using?

I'm wondering if I have a setting messed up, but I don't remember changing anything specific to this feature.  Is anyone else noticing this as it's a real time saving feature and I'd like to use it to the full potential.

Thanks, Craig

[cs_pixinsight]

Back at home tonight I did some more testing and verified settings.  Here's what I found:

• My persistent cache is enabled
• It is set to save for 30 days
• If I using ImageIntegration on 4 calibrated light frames all get analyzed for statistics and the stacked image is displayed
• If I immediately integrate the same 4 frames again the cache is fully utilized
• If I close PI, restart it and integrate the same 4 frames a random number of them will fail to use the cache and are analyzed again
• Sometimes its 1 frame, sometimes 2, etc.  I don't notice a pattern.

Craig

[Juan Conejero]

ImageIntegration's cache is based on the "time of last change" for each image file, just as the standard make utility for example. If the cache invalidates a file item, then either the file has been modified since it was added to the cache, or the file's timestamp has been changed since then.

The problem you are describing has not been reported before. If you are using Windows, could be some utility is changing timestamps for some files incorrectly? Some antivirus or firewall application?

[cs_pixinsight]

I checked the created, accessed and modified timestamps on the files - they don't change.  Also, the tests I ran are immediately after one another - within a minute at the most.  It's easily repeatable by simply integrating, closing PI, restarting and integrating the same images.  One more more images (in a set of 4) will always be reanalyzed.

What specifically does PI check to confirm the file hasn't been modified since the NTFS file modification timestamp isn't changing?

Is the cache readable?  I'd like to verify the times in the cache vs. on the file itself at different points in my testing.

Thanks,
Craig

[cs_pixinsight]

More testing and some interesting findings.  I also noticed changing the cache duration days in the cache preferences doesn't work.  I change it to 3, restart PI and it's back to 30 days again.

My machine is Windows 7 x64 using NTFS file systems.  Would someone with a similar setup try to duplicate this issue?

Checked File timestamps: 5/7/12 07:37

Last modified timestamps: 

8310:  ?Wednesday, ?May ?02, ?2012, ??9:57:14 AM
8311:  ?Wednesday, ?May ?02, ?2012, ??9:57:39 AM
8312:  Wednesday, ?May ?02, ?2012, ??9:58:04 AM
8313:  ?Wednesday, ?May ?02, ?2012, ??9:58:30 AM

Manually cleared memory and persistent cache

Run #1:  5/7/12 07:38:04

Console output:  All files are analyzed as expected

ImageIntegration: Global context

Opening files:
O:/fits/20120424_rho_ophiuchi_bdf_vng/registered/CSS_20120424_8310_c_cc_d_r.fit
Reading FITS: 32-bit floating point, 3 channel(s), 4674x4121 pixels: 100%
MRS noise evaluation: done.
Scale factors   :   1.00000  1.00000  1.00000
Zero offset     :  +0.000000e+000 +0.000000e+000 +0.000000e+000
Noise estimates :  1.463e-004 1.240e-004 1.283e-004
Weight          :     1.00000    1.00000    1.00000
O:/fits/20120424_rho_ophiuchi_bdf_vng/registered/CSS_20120424_8311_c_cc_d_r.fit
Reading FITS: 32-bit floating point, 3 channel(s), 4674x4121 pixels: 100%
MRS noise evaluation: done.
Scale factors   :   1.00049  0.99512  0.99103
Zero offset     :  -2.869638e-006 +2.261950e-006 +2.796412e-006
Noise estimates :  1.462e-004 1.242e-004 1.287e-004
Weight          :     1.00062    1.00600    1.01284
O:/fits/20120424_rho_ophiuchi_bdf_vng/registered/CSS_20120424_8312_c_cc_d_r.fit
Reading FITS: 32-bit floating point, 3 channel(s), 4674x4121 pixels: 100%
MRS noise evaluation: done.
Scale factors   :   0.98910  0.97635  0.97303
Zero offset     :  -1.987419e-005 -1.513364e-005 -1.352391e-005
Noise estimates :  1.474e-004 1.253e-004 1.297e-004
Weight          :     1.00713    1.02627    1.03314
O:/fits/20120424_rho_ophiuchi_bdf_vng/registered/CSS_20120424_8313_c_cc_d_r.fit
Reading FITS: 32-bit floating point, 3 channel(s), 4674x4121 pixels: 100%
MRS noise evaluation: done.
Scale factors   :   1.00844  0.97273  0.97011
Zero offset     :  -1.483737e-005 -8.663046e-006 -6.191432e-006
Noise estimates :  1.468e-004 1.250e-004 1.294e-004
Weight          :     0.97588    1.04010    1.04471

Integration of 4 images:
Pixel combination ......... average
Output normalization ...... additive
Pixel rejection ........... none

* Using 897 concurrent pixel stack(s) = 271.89 MB

* Integrating channel 1 of 3:
Integrating pixel rows:     0 ->   896: 100%
Integrating pixel rows:   897 ->  1793: 100%
Integrating pixel rows:  1794 ->  2690: 100%
Integrating pixel rows:  2691 ->  3587: 100%
Integrating pixel rows:  3588 ->  4120: 100%

* Integrating channel 2 of 3:
Integrating pixel rows:     0 ->   896: 100%
Integrating pixel rows:   897 ->  1793: 100%
Integrating pixel rows:  1794 ->  2690: 100%
Integrating pixel rows:  2691 ->  3587: 100%
Integrating pixel rows:  3588 ->  4120: 100%

* Integrating channel 3 of 3:
Integrating pixel rows:     0 ->   896: 100%
Integrating pixel rows:   897 ->  1793: 100%
Integrating pixel rows:  1794 ->  2690: 100%
Integrating pixel rows:  2691 ->  3587: 100%
Integrating pixel rows:  3588 ->  4120: 100%

MRS noise evaluation: /
** Warning: No convergence in MRS noise evaluation routine - using k-sigma noise estimate.|
** Warning: No convergence in MRS noise evaluation routine - using k-sigma noise estimate.done.
Computing noise scaling factors: done.

Gaussian noise estimates:
?sR = 3.322e-004
?sG = 1.585e-004
?sB = 1.661e-004

Reference SNR increments:
??s0R = 1.7300
??s0G = 3.0721
??s0B = 6.3496

Average SNR increments:
??sR = 1.7337
??sG = 3.0449
??sB = 6.2795

120.704 s

Run #2:  5/7/12 07:44:40

Rerun the same integration.  All files are now using the cache.  Notice the total run times, using the cache
is over 4 times faster.

ImageIntegration: Global context

Opening files:
O:/fits/20120424_rho_ophiuchi_bdf_vng/registered/CSS_20120424_8310_c_cc_d_r.fit
* Retrieved data from file cache.
Scale factors   :   1.00000  1.00000  1.00000
Zero offset     :  +0.000000e+000 +0.000000e+000 +0.000000e+000
Noise estimates :  1.463e-004 1.240e-004 1.283e-004
Weight          :     1.00000    1.00000    1.00000
O:/fits/20120424_rho_ophiuchi_bdf_vng/registered/CSS_20120424_8311_c_cc_d_r.fit
* Retrieved data from file cache.
Scale factors   :   1.00049  0.99512  0.99103
Zero offset     :  -2.869638e-006 +2.261950e-006 +2.796412e-006
Noise estimates :  1.462e-004 1.242e-004 1.287e-004
Weight          :     1.00062    1.00600    1.01284
O:/fits/20120424_rho_ophiuchi_bdf_vng/registered/CSS_20120424_8312_c_cc_d_r.fit
* Retrieved data from file cache.
Scale factors   :   0.98910  0.97635  0.97303
Zero offset     :  -1.987419e-005 -1.513364e-005 -1.352391e-005
Noise estimates :  1.474e-004 1.253e-004 1.297e-004
Weight          :     1.00713    1.02627    1.03314
O:/fits/20120424_rho_ophiuchi_bdf_vng/registered/CSS_20120424_8313_c_cc_d_r.fit
* Retrieved data from file cache.
Scale factors   :   1.00844  0.97273  0.97011
Zero offset     :  -1.483737e-005 -8.663046e-006 -6.191432e-006
Noise estimates :  1.468e-004 1.250e-004 1.294e-004
Weight          :     0.97588    1.04010    1.04471

Integration of 4 images:
Pixel combination ......... average
Output normalization ...... additive
Pixel rejection ........... none

* Using 897 concurrent pixel stack(s) = 271.89 MB

* Integrating channel 1 of 3:
Integrating pixel rows:     0 ->   896: 100%
Integrating pixel rows:   897 ->  1793: 100%
Integrating pixel rows:  1794 ->  2690: 100%
Integrating pixel rows:  2691 ->  3587: 100%
Integrating pixel rows:  3588 ->  4120: 100%

* Integrating channel 2 of 3:
Integrating pixel rows:     0 ->   896: 100%
Integrating pixel rows:   897 ->  1793: 100%
Integrating pixel rows:  1794 ->  2690: 100%
Integrating pixel rows:  2691 ->  3587: 100%
Integrating pixel rows:  3588 ->  4120: 100%

* Integrating channel 3 of 3:
Integrating pixel rows:     0 ->   896: 100%
Integrating pixel rows:   897 ->  1793: 100%
Integrating pixel rows:  1794 ->  2690: 100%
Integrating pixel rows:  2691 ->  3587: 100%
Integrating pixel rows:  3588 ->  4120: 100%

MRS noise evaluation: /
** Warning: No convergence in MRS noise evaluation routine - using k-sigma noise estimate.|
** Warning: No convergence in MRS noise evaluation routine - using k-sigma noise estimate.done.
Computing noise scaling factors: done.

Gaussian noise estimates:
?sR = 3.322e-004
?sG = 1.585e-004
?sB = 1.661e-004

Reference SNR increments:
??s0R = 1.7300
??s0G = 3.0721
??s0B = 6.3496

Average SNR increments:
??sR = 1.7337
??sG = 3.0449
??sB = 6.2795

28.424 s

Last modified timestamps are still: 

8310:  ?Wednesday, ?May ?02, ?2012, ??9:57:14 AM
8311:  ?Wednesday, ?May ?02, ?2012, ??9:57:39 AM
8312:  Wednesday, ?May ?02, ?2012, ??9:58:04 AM
8313:  ?Wednesday, ?May ?02, ?2012, ??9:58:30 AM

Close and restart PI.

Run #3:  5/7/12 07:49:02

Notice that 2 of 4 images are reanalyzed for statistics and the total run time has increased by over 2 times.
The file modification times have not changed since I started this test session, so the file cache should be used.
Most interesting of all is the Loaded cache line in the console output (shown in large green text below):  it
says 124 item(s) were loaded.  How can that be since I manually cleared the cache and only 4 images have
been analyzed at this point.  It should read 4 items.  Something is definitely wrong with the cache on my
machine if no one else can duplicate this.

ImageIntegration: Global context

* Loaded cache: 124 item(s)

Opening files:
O:/fits/20120424_rho_ophiuchi_bdf_vng/registered/CSS_20120424_8310_c_cc_d_r.fit
* Retrieved data from file cache.
Scale factors   :   1.00000  1.00000  1.00000
Zero offset     :  +0.000000e+000 +0.000000e+000 +0.000000e+000
Noise estimates :  1.463e-004 1.240e-004 1.283e-004
Weight          :     1.00000    1.00000    1.00000
O:/fits/20120424_rho_ophiuchi_bdf_vng/registered/CSS_20120424_8311_c_cc_d_r.fit
* Retrieved data from file cache.
Scale factors   :   1.00049  0.99512  0.99103
Zero offset     :  -2.869638e-006 +2.261950e-006 +2.796412e-006
Noise estimates :  1.462e-004 1.242e-004 1.287e-004
Weight          :     1.00062    1.00600    1.01284
O:/fits/20120424_rho_ophiuchi_bdf_vng/registered/CSS_20120424_8312_c_cc_d_r.fit
Reading FITS: 32-bit floating point, 3 channel(s), 4674x4121 pixels: 100%
MRS noise evaluation: done.
Scale factors   :   0.98910  0.97635  0.97303
Zero offset     :  -1.987419e-005 -1.513364e-005 -1.352391e-005
Noise estimates :  1.474e-004 1.253e-004 1.297e-004
Weight          :     1.00713    1.02627    1.03314
O:/fits/20120424_rho_ophiuchi_bdf_vng/registered/CSS_20120424_8313_c_cc_d_r.fit
Reading FITS: 32-bit floating point, 3 channel(s), 4674x4121 pixels: 100%
MRS noise evaluation: done.
Scale factors   :   1.00844  0.97273  0.97011
Zero offset     :  -1.483737e-005 -8.663046e-006 -6.191432e-006
Noise estimates :  1.468e-004 1.250e-004 1.294e-004
Weight          :     0.97588    1.04010    1.04471

Integration of 4 images:
Pixel combination ......... average
Output normalization ...... additive
Pixel rejection ........... none

* Using 897 concurrent pixel stack(s) = 271.89 MB

* Integrating channel 1 of 3:
Integrating pixel rows:     0 ->   896: 100%
Integrating pixel rows:   897 ->  1793: 100%
Integrating pixel rows:  1794 ->  2690: 100%
Integrating pixel rows:  2691 ->  3587: 100%
Integrating pixel rows:  3588 ->  4120: 100%

* Integrating channel 2 of 3:
Integrating pixel rows:     0 ->   896: 100%
Integrating pixel rows:   897 ->  1793: 100%
Integrating pixel rows:  1794 ->  2690: 100%
Integrating pixel rows:  2691 ->  3587: 100%
Integrating pixel rows:  3588 ->  4120: 100%

* Integrating channel 3 of 3:
Integrating pixel rows:     0 ->   896: 100%
Integrating pixel rows:   897 ->  1793: 100%
Integrating pixel rows:  1794 ->  2690: 100%
Integrating pixel rows:  2691 ->  3587: 100%
Integrating pixel rows:  3588 ->  4120: 100%

MRS noise evaluation: —
** Warning: No convergence in MRS noise evaluation routine - using k-sigma noise estimate./
** Warning: No convergence in MRS noise evaluation routine - using k-sigma noise estimate.done.
Computing noise scaling factors: done.

Gaussian noise estimates:
?sR = 3.322e-004
?sG = 1.585e-004
?sB = 1.661e-004

Reference SNR increments:
??s0R = 1.7300
??s0G = 3.0721
??s0B = 6.3496

Average SNR increments:
??sR = 1.7337
??sG = 3.0449
??sB = 6.2795

66.019 s

Last modified timestamps are still: 

8310:  ?Wednesday, ?May ?02, ?2012, ??9:57:14 AM
8311:  ?Wednesday, ?May ?02, ?2012, ??9:57:39 AM
8312:  Wednesday, ?May ?02, ?2012, ??9:58:04 AM
8313:  ?Wednesday, ?May ?02, ?2012, ??9:58:30 AM

[Juan Conejero]

Hi Craig,

I have been able to reproduce this behavior on a Windows 7 virtual machine. This is now a high-priority bug and I am working on it. Thank you for reporting this problem.

[cs_pixinsight]

Juan, glad to be of help.  Let me know if you need any further information to help with a resolution.

Craig

[ruediger]

[...]or the file's timestamp has been changed since then.
The problem you are describing has not been reported before.[...]

Could it be related to this problem: http://pixinsight.com/forum/index.php?topic=4202.0? Timestamps keep the same, but after some operations (for me it's dropping RAW files into PI) the internally stored modification time is not related to the computer's timezone anymore, jumping -2h from DST to UTC.

Rüdiger

[cs_pixinsight]

Juan, were you able to find a solution to this issue or do you need any further information to help find a solution?

Thanks,
Craig

[Juan Conejero]

Hi,

I think I have found the cause of this problem. Indeed it is related to time zones. I'll try to release an update as soon as possible.

Thank you for your patience!

[Juan Conejero]

Hi Craig,

I have fixed this bug in version 1.8.1 of the ImageIntegration module, which we have released as an update a while ago. The problem was not related to time zones, but to unreliable file times on Windows at the millisecond level.

On Linux/UNIX and Mac OS X, we use the standard stat POSIX function to get file data, including access and modification times. File times have one second resolution.

On Windows, we use the FindFirstFile(), FileTimeToSystemTime() and SystemTimeToTzSpecificLocalTime() APIs, These APIs provide resolution of one millisecond for file access and modification times. However, the reported milliseconds are unreliable, and were causing wrong cache invalidations in the ImageIntegration tool. I have fixed this problem by simply ignoring the milliseconds part in all file time comparisons.

Thank you for reporting this bug, and for your patience!

[cs_pixinsight]

Juan, this is terrific news.  I'll let you know how it works after I perform the upgrade and do some testing.

Craig

[cs_pixinsight]

Juan, this issue has been partially resolved.  PI now populates and reuses the ImgInt file cache properly, which was the main problem reported.  Thank you for getting this resolved as it will save me many hours of waiting.

The secondary issue reported about the preferences not keeping my "Keep days" setting is still not working.  If I open the ImgInt prefs and set the persistent cache to keep the image stats for 90 days, this change isn't remembered after restarting PI.  It is always reset back to 30 days.

Craig

[Juan Conejero]

The secondary issue reported about the preferences not keeping my "Keep days" setting is still not working.

This bug has been fixed in version 1.8.2 of the ImageIntegration module, which I have just released as an update. Sorry for all the trouble.