One exposure in a series is longer than specified

[mcovington]

I've used BackyardNIKON several times to do sequences of 120-second exposures with my Nikon D5500, and, curiously, each time, the second or third exposure is a little longer than specified (long enough for PixInsight to object to stacking it).  Here is an example (the output of my free program EXIFLOG, which reads the camera EXIF data in the raw files):

2022-05-11 20:42:17  M3_LIGHT_120s_00001.NEF :      120s ISO   200  6016 x 4016  NIKON D5500
2022-05-11 20:44:53  M3_LIGHT_120s_00002.NEF :    119.9s ISO   200  6016 x 4016  NIKON D5500
2022-05-11 20:47:28  M3_LIGHT_120s_00003.NEF :    123.6s ISO   200  6016 x 4016  NIKON D5500  note extra duration
2022-05-11 20:50:07  M3_LIGHT_120s_00004.NEF :    119.8s ISO   200  6016 x 4016  NIKON D5500
2022-05-11 20:52:41  M3_LIGHT_120s_00005.NEF :    119.9s ISO   200  6016 x 4016  NIKON D5500
2022-05-11 20:55:17  M3_LIGHT_120s_00006.NEF :    119.9s ISO   200  6016 x 4016  NIKON D5500
2022-05-11 20:57:52  M3_LIGHT_120s_00007.NEF :    119.9s ISO   200  6016 x 4016  NIKON D5500
2022-05-11 21:00:27  M3_LIGHT_120s_00008.NEF :    119.9s ISO   200  6016 x 4016  NIKON D5500
2022-05-11 21:03:02  M3_LIGHT_120s_00009.NEF :    119.9s ISO   200  6016 x 4016  NIKON D5500
2022-05-11 21:05:38  M3_LIGHT_120s_00010.NEF :      120s ISO   200  6016 x 4016  NIKON D5500
2022-05-11 21:08:13  M3_LIGHT_120s_00011.NEF :    119.8s ISO   200  6016 x 4016  NIKON D5500
2022-05-11 21:10:48  M3_LIGHT_120s_00012.NEF :    119.9s ISO   200  6016 x 4016  NIKON D5500
2022-05-11 21:13:23  M3_LIGHT_120s_00013.NEF :    119.9s ISO   200  6016 x 4016  NIKON D5500
2022-05-11 21:15:58  M3_LIGHT_120s_00014.NEF :      120s ISO   200  6016 x 4016  NIKON D5500
2022-05-11 21:18:34  M3_LIGHT_120s_00015.NEF :    119.9s ISO   200  6016 x 4016  NIKON D5500
2022-05-11 21:21:09  M3_LIGHT_120s_00016.NEF :    119.8s ISO   200  6016 x 4016  NIKON D5500
2022-05-11 21:23:44  M3_LIGHT_120s_00017.NEF :    119.9s ISO   200  6016 x 4016  NIKON D5500
2022-05-11 21:26:19  M3_LIGHT_120s_00018.NEF :    119.8s ISO   200  6016 x 4016  NIKON D5500
2022-05-11 21:28:55  M3_LIGHT_120s_00019.NEF :      120s ISO   200  6016 x 4016  NIKON D5500
2022-05-11 21:31:30  M3_LIGHT_120s_00020.NEF :    119.9s ISO   200  6016 x 4016  NIKON D5500

Any ideas?

[admin]

Bulb sequence start and end are controlled by a computer timer, if your computer's CPU was taxed doing something else when the time came to send the end-bulb command, it is possible that it took a few seconds to get to it. This is rare, but the only way to figure it out is knowing what else the computer was doing at that time. This said 3 seconds is a long time

[mcovington]

OK, looking back, it is always the 3rd exposure in the series of 20 (x 120 seconds) that is lengthened.  One of them was 134 seconds.

I am not aware of the CPU being heavily loaded, and the fact that it is always the 3rd exposure (in 3 sessions so far) is what led me to think it was something in BackyardNIKON.  I will look for other things loading the CPU, but if any, it must have been background processes.

[admin]

In Settings -> Advance Settings, do you have the background process enabled or disabled?

[astroman133]

How much RAM memory is in the computer? If Window sees the amount of free RAM decreasing it can start swapping other programs out of memory to free some RAM. This swapping slows the computer down dramatically.

I had to upgrade my Windows 10 desktop PC from 8GB to 16 GB because Windows was  swapping programs in and out of memory even though there was 3 GB of RAM available.

 

[mcovington]

On 5/12/2022 at 10:42 AM, admin said:

In Settings -> Advance Settings, do you have the background process enabled or disabled?

I had it disabled, which I think was the default.   I have checked it and we'll see what happens next time, which may be several days from now.

[mcovington]

On 5/12/2022 at 12:34 PM, astroman133 said:

How much RAM memory is in the computer? If Window sees the amount of free RAM decreasing it can start swapping other programs out of memory to free some RAM. This swapping slows the computer down dramatically.

I had to upgrade my Windows 10 desktop PC from 8GB to 16 GB because Windows was  swapping programs in and out of memory even though there was 3 GB of RAM available.

 

8 GB, Windows 10 Pro.   It would be astonishing if this program actually required more than that.  I think this is a bug in ByNIKON, not a Windows interaction, because it always happens, and always happens to the third exposure in the series (of 20 2-minute exposures).

[astroman133]

The program does not require more than 8 GB. In fact, it uses much less than that but it has to share the RAM memory with all the other hundred or more programs that you can see in the Task Manager. BYN is a 32-bit .NET application and as such cannot use more than 2 GB. I use BYE and while its memory useage varies frequently it seems to average about 200MB while imaging.

A few months ago I added 8GB of RAM because I discovered that Windows was worried about the amount of free RAM, even though there was over 3GB available, and it started swapping out some programs to bring other programs into RAM. This continual swapping out programs and bringing others really slows the system to a crawl at times. I added 8 more GB of memory and that problem went away.

Then I found that some program running as part of the operating system, the Desktop Window Manager, was growing over time. It is common for programs to grab free memory, use it for some purpose, and then release it back to the system as available RAM. Over several days, the amount of free RAM would drop from 60 percent down to 10 percent. I updated the graphics driver and the problem went away. This is because the graphics driver was not correctly releasing memory back to Windows. Once again Windows started swapping active programs out of RAM to bring in other programs and the system slowed down.

I have no doubt that swapping was affecting the overall performance of my computer. Eliminating the causes of swapping improved the performance and everything is running much more smoothly. My point is that the performance issues for your system could easily have some other cause than a bug in BYN.

[s3igell]

If this "Delay" always occurs with your third shot, perhaps it is the result of File / Image Indexing being triggered by Windows OS and also by most every Image Processing Application you have installed on that Laptop.  I found that MS Paint and Adobe Lightroom and ACDSee each triggered Indexing on my Laptop, as well as Windows Media Player and the older iTunes App.

If you use your "regular daily-use" Laptop as your Image Capture Laptop, you will usually accumulate an ungodly number of background processes that are triggered when "something" is added to the File System.  It is the justification for all the "Scope-side Computer Systems" like ZWO ASIAir and Pegasus Astro, as well as those who have a modest Laptop running near the Scope that they then Remote-In with their bigger Laptop.

(Just food for thought...)

[mcovington]

Good point about indexing -- I will disable Windows indexing for the folder that the files are written into.

In some indoor tests (basically taking dark frames indoors) I have not had the problem again.  It is odd that I had it 3 times, very consistently, and now can't reproduce it.   It is possible that some update to Windows has cleared up the problem.

It is also possible that it was cleared up somehow by turning BackgroundWorker on and then turning it off again.  I decided to try to reproduce the problem without BackgroundWorker before testing whether turning that on would cure it.  As it happens I have not reproduced the problem again.

BTW, I understand very well that Windows is not a real-time OS and would gladly be using Linux if everything I needed were available for it.  (Linux isn't a real-time OS either but is easier to control.)  I'm a software developer myself in the daytime.

[admin]

The fact that you can't reproduce the issue again confirms it is environmental. Terminating a bulb sequence is 100% dependent on Windows timers to fire at the right time.... and if the computer resources are busy downing something else that significantly bog down basic resources such as disk I/O and memory swap, it is almost certain that the Windows timer will not fire off in time. Enabling and disabling the background work should have no impact, it is on, or it is off, there is nothing share between these 2 state, so once can't affect the other.

[mcovington]

No further problems.  I disabled Windows indexing of the folder in which the NEF files are written.  Also, I recommend setting the properties of that folder to optimize for "General items" rather than "Pictures."  That apparently turns off some kind of scanning of the NEF files.

Windows updates in the meantime may even have done something to alleviate the problem -- I don't know.  Windows is always changing.

 

[s3igell]

On 5/28/2022 at 2:58 PM, mcovington said:

Windows updates in the meantime may even have done something to alleviate the problem -- I don't know.  Windows is always changing.

If you're curious about the recent Windows Updates installed to your PC, simply open Settings / Update & Security / View Update History (4th item down the center).

[mcovington]

Yes; but they rarely or never reveal the effect of the update.

[mcovington]

I can't pronounce this problem dead because it happened again last night, and since I wasn't expecting it, I wasn't looking for causes.  BackgroundWorker is not enabled, and although file indexing is turned off, that might not stop all background processes from wanting to index the file.  Anyhow, it hasn't just disappeared...

And again, it's the 3rd exposure that gets lengthened.

2022-06-18 22:27:47  M 64_LIGHT_120s_22h27m21s72700871.NEF :    119.9s ISO   200  6016 x 4016  NIKON D5500
2022-06-18 22:30:25  M 64_LIGHT_120s_22h30m00s56400872.NEF :    119.8s ISO   200  6016 x 4016  NIKON D5500
2022-06-18 22:33:17  M 64_LIGHT_120s_22h32m51s81800873.NEF :    123.6s ISO   200  6016 x 4016  NIKON D5500 note slightly mismatched duration
2022-06-18 22:35:55  M 64_LIGHT_120s_22h35m26s36900874.NEF :    119.9s ISO   200  6016 x 4016  NIKON D5500
2022-06-18 22:38:35  M 64_LIGHT_120s_22h38m06s50100875.NEF :    119.8s ISO   200  6016 x 4016  NIKON D5500
2022-06-18 22:41:10  M 64_LIGHT_120s_22h40m41s38300876.NEF :    119.9s ISO   200  6016 x 4016  NIKON D5500
2022-06-18 22:43:48  M 64_LIGHT_120s_22h43m19s11000877.NEF :    119.8s ISO   200  6016 x 4016  NIKON D5500
2022-06-18 22:46:23  M 64_LIGHT_120s_22h45m54s08200878.NEF :    119.9s ISO   200  6016 x 4016  NIKON D5500
2022-06-18 22:48:59  M 64_LIGHT_120s_22h48m30s78700879.NEF :    119.9s ISO   200  6016 x 4016  NIKON D5500
2022-06-18 22:51:34  M 64_LIGHT_120s_22h51m05s95900880.NEF :    119.9s ISO   200  6016 x 4016  NIKON D5500
2022-06-18 22:54:17  M 64_LIGHT_120s_22h53m48s74200881.NEF :    119.8s ISO   200  6016 x 4016  NIKON D5500
2022-06-18 22:56:54  M 64_LIGHT_120s_22h56m25s47900882.NEF :    119.9s ISO   200  6016 x 4016  NIKON D5500
2022-06-18 22:59:29  M 64_LIGHT_120s_22h58m59s92100883.NEF :    119.8s ISO   200  6016 x 4016  NIKON D5500
2022-06-18 23:02:05  M 64_LIGHT_120s_23h01m36s90500884.NEF :    119.9s ISO   200  6016 x 4016  NIKON D5500
2022-06-18 23:04:41  M 64_LIGHT_120s_23h04m12s01500885.NEF :    119.9s ISO   200  6016 x 4016  NIKON D5500
2022-06-18 23:07:16  M 64_LIGHT_120s_23h06m47s03500886.NEF :      120s ISO   200  6016 x 4016  NIKON D5500

I will keep trying things.

[mcovington]

In one test with BackgroundWorker enabled, the problem is absent.  I don't know if it's cured or just intermittent.

I'd like to dig deeper, because it's hard for me to believe that file indexing or other background operations can really tie up a whole quad-core CPU badly enough to block BackyardNikon totally for several seconds.  (See next message...)

[mcovington]

Cue "Twilight Zone" music -- it's turning into a ghost story --

Looking at BackyardNikon's logs, the "longer" exposure is not any longer than the others!  (To within 1 second, taking the time from DEBUG: TAKE PICTURE to OnDeviceOnImageReady.)  

Both EXIFLOG (using EXIFTOOL) and PixInsight agree that according to the EXIF data, it is longer.  But I wonder if something freakish is happening -- perhaps Nikon's own firmware is putting the wrong exposure duration into the EXIF data in this specific situation.

What is the source of the exposure duration that is written into the EXIF field of the NEF file?  Does BackyardNikon construct that part of the NEF file, or does the camera construct it?  It is very strange that the camera would get it wrong, but stranger things have happened.

[admin]

The source of the EXIF data is the Camera firmware, the EXIF content is an integral part of the image download, not BYN.

[admin]

Thinking about this a bit more... since the log appears to show that the command was sent relatively on time, I wonder what else the camera is doing at that time that could possibly cause this? It's not busy downloading because BYN downloads the image data before sending the next take picture command.

Another thing to through in the mix, could the issue be caused by a delayed return of the start bulb capture command to the BYN application rather than a sluggish end of bulb command being issued/executed? In both cases, the return of the commands is controlled by Nikon, and BYN continues its execution only when the camera returns from a successful command (or an error is thrown - which is not the case here)

[s3igell]

Any chance that you have left the Lens set to AutoFocus??  Or the Camera set with WiFi Enabled??  Or any In-Camera Blending or other Processing??

These should cause issues to show up more frequently than just the 3rd Image in sequence, but when looking for the "odd"...

[mcovington]

Thanks for your input.  Next time, I might actually make audio recordings so I can time how long the shutter is open!  Either the exposures are indeed occasionally too long, or the EXIF data is false, and either way it seems to have to do with the camera.  I have not experienced it controlling the same camera with NINA (so far) or with intervalometers (ever).  

The camera is not set to autofocus or anything else unusual.  This camera has been dedicated to astronomy for a long time.