David's Astronomy Pages
Notes - Session 867 (2021-03-05)

 
Bullet Session Aims & Highlights
 - Observing Result
 - Night Summary Plot
 - Session Event Log
 
Bullet Operational Issues
  - Critical Issues (0),  Major Issues (0),  Minor Issues (8),  Continuous Improvement (6)
Bullet Images from 2021-03-05 >>     [ Local Files >> ]
2021-03-08
Bullet Investigation - Hang-ups during Observatory Monitoring

Session Aims & Highlights (2021-03-05)

Main aims

  1. AstroMain.  Test AstroMain 3.38 for stability and presence/absence of UI lockups following major refactoring
  2. Targets. Acquire images of a selection of variable stars, nearby stars, comets & deep sky targets as allowed by conditions.

Equipment & Software

Highlights

Summary Plots & Logs

Observing Plan
Image
  
Observing Result
Image
   
Dome & Scope Slewing Performance
Image
  
Slew/Centering Performance
Image
  
Guiding Performance
Image
Image
  
Sky Conditions (Locate Frames)
Image
  
Night Sky Summary Plot
Top axis: Sky Brightness at Zenith (in ADU/s)
Lefthand axis: Local Time (hh LT). Righthand axis: Sun Altitude (degs)
Image   
  
Pre-Session Weather Forecast (API data from darksky.net)
Image
Image   
  
Session Event Log
Time     Event Detail
17:40:48 Session Monitoring AutoStart monitoring for Live Session opportunity starting between 18:42 & 04:54
18:42:33   AutoStart Waiting AutoStart waiting till earliest start time at 18:42
18:42:34   AutoStart Delayed Session delayed due to cloud
18:59:29 Session AutoStarting Session autostarting (18:59)
19:00:00 Session Created Live Session Created (2021-03-05 S00867, ImageSaveNum: 867001)
19:00:02   Scope Switched On Telescope Power has been switched on via UPB Powerbox.
19:01:59   Services Started Observatory Services started
19:02:07 Observatory (Auto) Observatory placed in Fully-Automated Mode
19:02:10 Session Pending Session pending (2021-03-05)
19:02:12 Session Initiating Session initiating (2021-03-05)
19:02:14   Plan Requested Observing Plan requested from AstroPlan (1.21)
19:03:15 AstroPlan Crashed AstroPlan crashed with fatal exception in new code for plotting Az/Alt after creating plan.
19:18:00 User Intervention User interventation to restart AstroPlan / rebuild Observing Plan
19:24:16   Plan Loaded Observing Plan loaded to queue (, Plan ID: 605)
19:24:33   Camera1 Connected SBIG Camera Connected (set point -25°C)
19:24:39   Telescope Connected Telescope Connected (TheSky6)
19:24:49 Session Equilibration Session ready for dome & camera equilibration
19:25:35   Dome Opened Dome opened (opening time 46s)
19:25:39   Equilibration Started Dome Equilibration started
19:30:31   Equilibration Ended Dome Equilibration ended (4.9 mins total)
19:30:33 Session Running Session running
19:30:35   Queue Started Observing Queue started (32 targets selected)
19:32:19       Focusing Started-Foc1 Foc1 Focusing Started (TCF-S)
19:35:13       Focusing Completed Foc1 AutoFocus Completed (Profile No 1)
19:37:11       Focusing Failed Foc1 focusing failed - failed QC check (Ambiguous)
19:37:16       Focusing Started-Foc2 Foc2 Focusing Started (Secondary Scope, using ShCap)
19:39:40       Focusing Completed Foc2 AutoFocus Completed (Profile No 2, wide)
19:41:33       Focusing Completed Foc2 AutoFocus Completed (Profile No 2)
19:41:49       Focusing Checked Foc2 Focusing Check Succeeded
19:42:30     Target Started (1/32) Target started (1/32, Nova Per 2020 (CV))
19:46:28       Focusing Started-Foc1 Foc1 Focusing Started (TCF-S)
19:48:59       Focusing Completed Foc1 AutoFocus Completed (Profile No 3)
19:50:29       Focusing Completed Foc1 AutoFocus Completed (Profile No 3)
19:59:03     Target Completed Target completed (1/32, Nova Per 2020 (CV))
19:59:05     Target Started (2/32) Target started (2/32, NGC 304 w/SN2021dnn)
20:02:44       Focusing Skipped Foc1 focusing skipped - star is too dim (TCF-S)
20:20:00     Target Completed Target completed (2/32, NGC 304 w/SN2021dnn)
20:20:02     Target Started (3/32) Target started (3/32, UGC 2505 w/SN2021bge)
20:24:53       Focusing Skipped Foc1 focusing skipped - star is too dim (TCF-S)
20:42:40     Target Completed Target completed (3/32, UGC 2505 w/SN2021bge)
20:42:42     Target Started (4/32) Target started (4/32, GCVS RR Tau)
20:45:11       Focusing Started-Foc1 Foc1 Focusing Started (TCF-S)
20:46:35       Focusing Completed Foc1 AutoFocus Completed (Profile No 4)
20:52:32     Target Completed Target completed (4/32, GCVS RR Tau)
20:52:34     Target Started (5/32) Target started (5/32, UGC 1436 w/SN2021nv)
20:56:26       Focusing Started-Foc1 Foc1 Focusing Started (TCF-S)
20:58:16       Focusing Completed Foc1 AutoFocus Completed (Profile No 5)
21:14:09     Target Completed Target completed (5/32, UGC 1436 w/SN2021nv)
21:14:33     Target Started (6/32) Target started (6/32, AT2021dbp (CV))
21:17:11       Focusing Started-Foc1 Foc1 Focusing Started (TCF-S)
21:18:49       Focusing Completed Foc1 AutoFocus Completed (Profile No 6)
21:24:24     Target Completed Target completed (6/32, AT2021dbp (CV))
21:26:24     Target Started (7/32) Target started (7/32, AT2021bkv (CV))
21:29:03       Focusing Started-Foc1 Foc1 Focusing Started (TCF-S)
21:31:00       Focusing Completed Foc1 AutoFocus Completed (Profile No 7)
21:37:05     Target Completed Target completed (7/32, AT2021bkv (CV))
21:38:16     Target Started (8/32) Target started (8/32, AT2021ckv)
21:41:30       Focusing Started-Foc1 Foc1 Focusing Started (TCF-S)
21:43:18       Focusing Completed Foc1 AutoFocus Completed (Profile No 8)
21:59:24     Target Completed Target completed (8/32, AT2021ckv)
22:00:08     Target Started (9/32) Target started (9/32, AT2021elr (CV))
22:02:52       Focusing Started-Foc1 Foc1 Focusing Started (TCF-S)
22:04:37       Focusing Completed Foc1 AutoFocus Completed (Profile No 9)
22:10:28     Target Completed Target completed (9/32, AT2021elr (CV))
22:12:00     Target Started (10/32) Target started (10/32, Scholz's Star)
22:15:47       Focusing Started-Foc1 Foc1 Focusing Started (TCF-S)
22:17:47       Focusing Completed Foc1 AutoFocus Completed (Profile No 10)
22:32:47     Target Completed Target completed (10/32, Scholz's Star)
22:37:44     Target Started (11/32) Target started (11/32, GCVS DX Cnc)
22:41:52       Focusing Started-Foc1 Foc1 Focusing Started (TCF-S)
22:43:41       Focusing Completed Foc1 AutoFocus Completed (Profile No 11)
22:48:04     Target Completed Target completed (11/32, GCVS DX Cnc)
22:48:06     Target Started (12/32) Target started (12/32, NGC 2903)
22:51:06       Focusing Started-Foc1 Foc1 Focusing Started (TCF-S)
22:53:20       Focusing Completed Foc1 AutoFocus Completed (Profile No 12)
23:10:22     Target Completed Target completed (12/32, NGC 2903)
23:10:24     Target Started (13/32) Target started (13/32, UGC 5267)
23:11:26   SoftSuspend Called Soft Suspend is called due to Deteriorating Conditions (too few stars)
23:16:02       Focusing Skipped Foc1 focusing skipped - unable to find a star (TCF-S)
23:23:27   SoftSuspend Cancelled Soft Suspend is cancelled due to Improved Conditions
23:26:08   SoftSuspend Called Soft Suspend is called due to Deteriorating Conditions (too few stars)
23:31:35     Target Completed Target completed (13/32, UGC 5267)
23:31:37   Queue Paused Queue paused for Session Suspension
23:31:40 Session Suspended Session suspended
23:32:28   Dome Closed Dome closed (closing time 50s)
23:42:50     Target Cancelled Target cancelled (14/32, GCVS CN Leo) due to cloud
00:02:32     Target Cancelled Target cancelled (15/32, UGCA 252) due to cloud
00:24:54     Target Cancelled Target cancelled (16/32, NGC 3962) due to cloud
00:47:16     Target Cancelled Target cancelled (17/32, NGC 4281) due to cloud
01:09:38     Target Cancelled Target cancelled (18/32, M58) due to cloud
01:32:00     Target Cancelled Target cancelled (19/32, UGCA 305) due to other condition
01:36:45 Session Resuming Session resuming
01:37:30   Dome Opened Dome opened (opening time 45s)
01:37:32 Session Running Session running
01:37:34     Target Started (20/32) Target started (20/32, UGCA 308)
01:37:36   Queue Resumed Observing Queue resumed
01:40:48       Focusing Started-Foc1 Foc1 Focusing Started (TCF-S)
01:42:46       Focusing Completed Foc1 AutoFocus Completed (Profile No 13)
01:58:51     Target Completed Target completed (20/32, UGCA 308)
01:58:53     Target Started (21/32) Target started (21/32, IC 992 w/SN2021dwg)
02:03:18       Focusing Skipped Foc1 focusing skipped - star is too dim (TCF-S)
02:20:21     Target Completed Target completed (21/32, IC 992 w/SN2021dwg)
02:20:23     Target Started (22/32) Target started (22/32, UGC 3502 w/AT2021cwc)
02:24:59       Focusing Started-Foc1 Foc1 Focusing Started (TCF-S)
02:27:10       Focusing Failed Foc1 focusing failed - failed QC check (Ambiguous)
02:43:21     Target Completed Target completed (22/32, UGC 3502 w/AT2021cwc)
02:43:23     Target Started (23/32) Target started (23/32, NGC 4227 w/SN2021biz)
02:47:10       Focusing Started-Foc1 Foc1 Focusing Started (TCF-S)
02:49:09       Focusing Failed Foc1 focusing failed - failed QC check (Ambiguous)
03:04:43     Target Completed Target completed (23/32, NGC 4227 w/SN2021biz)
03:04:46     Target Started (24/32) Target started (24/32, NGC 4631 w/AT2021biy)
03:09:45       Focusing Skipped Foc1 focusing skipped - star is too dim (TCF-S)
03:10:53   SoftSuspend Called Soft Suspend is called due to Deteriorating Conditions (too few stars)
03:26:55     Target Completed Target completed (24/32, NGC 4631 w/AT2021biy)
03:26:57   Queue Paused Queue paused for Session Suspension
03:27:00 Session Suspended Session suspended
03:27:50   Dome Closed Dome closed (closing time 50s)
03:43:42     Target Cancelled Target cancelled (25/32, AT2021dtd) due to cloud
03:56:00     Target Cancelled Target cancelled (26/32, GCVS BL Lac) due to cloud
04:16:22     Target Cancelled Target cancelled (27/32, SN 2021xn) due to cloud
04:28:40     Target Cancelled Target cancelled (28/32, KIC 8462852) due to cloud
04:30:36 Session Resuming Session resuming
04:31:21   Dome Opened Dome opened (opening time 45s)
04:31:23 Session Running Session running
04:31:25     Target Started (29/32) Target started (29/32, GCVS R CrB)
04:31:27   Queue Resumed Observing Queue resumed
04:34:25       Focusing Started-Foc1 Foc1 Focusing Started (TCF-S)
04:36:12       Focusing Completed Foc1 AutoFocus Completed (Profile No 16)
04:38:26   SoftSuspend Called Soft Suspend is called due to Deteriorating Conditions (too few stars)
04:39:09     Target Completed Target completed (29/32, GCVS R CrB)
04:39:11   Queue Paused Queue paused for Session Suspension
04:39:14 Session Suspended Session suspended
04:40:02   Dome Closed Dome closed (closing time 50s)
04:49:02     Target Cancelled Target cancelled (30/32, GCVS U Her) due to cloud
05:04:19 Session Resuming Session resuming
05:05:04   Dome Opened Dome opened (opening time 45s)
05:05:06 Session Running Session running
05:05:08   Queue Resumed Observing Queue resumed
05:05:10     Target Started (31/32) Target started (31/32, CGCG 056-009 w/SN2021apf)
05:14:52     Target Completed Target partially completed (31/32, CGCG 056-009 w/SN2021apf)
05:14:54     Target Started (32/32) Target started (32/32, HIP 87937)
05:17:50       Focusing Started-Foc1 Foc1 Focusing Started (TCF-S)
05:19:39       Focusing Completed Foc1 AutoFocus Completed (Profile No 17)
05:23:29     Target Completed Target completed (32/32, HIP 87937)
05:23:32   Queue Completed Job Queue completed
05:23:36 Session Closing Session closing
05:24:31   Dome Closed Dome closed (closing time 50s)
05:25:10   Dome Parked Dome parked (parking time 31s), Az: 90.0 deg
05:25:43   Telescope Parked Telescope parked (parking time 30s)
05:26:13   Telescope Switched Off Telescope Power has been switched off via UPB Switch.
05:27:03   Services Stopped Night Services stopped
05:27:05 Session Housekeeping Housekeeping Started (Cleanup FITS, Create Fits Summary, Transfer Files)
05:27:21 Session Finished Session Finished
 
Session Alerts
Time     Alert Detail
-- No Alerts                --                              
 

Back to Top


Operational Issues (2021-03-05 S867)

[ Prev | Next ]

Critical Issues

Major Issues

Minor Issues

Continuous Improvement

[ Prev | Next ]

Back to Top


2021-03-08


Investigation - Hang-ups during Observatory Monitoring

Issue: Observatory Monitoring Loop is occasionally being delayed by 4-13s, delaying refresh of data on ObsViewer and Console Form. 

Description: There were 23 cases during the session where the Obs.Monitor Loop was identified as Pending (taking > 4s) with one case identified as being frozen (taking >10s).  This has been a long standing issue,  but appears to be now disassociated from the UI Hang-Up issue.     These hangups are significant because the data displayed on ObsViewer and Console Form aren't getting refreshed at the design rate (every 2.5s).

Analysis
Since the original occurance of this issue the addition of trace statements in the code now identify when the observatory monitoring has taken an unexpectedly long time, and indirectly the time at which an unexpectedly long cycle began at. This information is sent to the session's log file.

Examining the 23 cases from session S867 indicates that the temporary hang points come at very specific points during execution of the Job Queue where the Obs.Monitor is requesting information where the Camera or Focuser is performing activity and can not immediately respond.

1 case came when Connecting Camera during session setup
8 cases came during Autofocusing
13 cases came directly after ' Camera.TakeImage / IamAlive: TakeImage'  log messages (but closely tied to preceeding 'SetFocus, Filter: 1 / FocusPosition xxxx' messages

During these times the Job Queue isn't sending messages to the Log File, it is doing something or waiting for something.   Occasional messages from Obs.Manager or other thread show the writing of messages to the log file is normal (ie the logfile is give a true representation of the activities of the Obs.Monitor and Job Queue).

Focuser1 / objFocuser
Suspicion falls upon the Focuser1 and the objFocuser (TCF-S) objects. 

SetFocAutoPosition()   calls    Focuser1.MoveToPosition_Async, which is the asynchronous version of MoveToPosition (it does this by starting a thread to move the focuser, the thread waits till focuser has reached the requested position or a timeout after 2 minutes)

AutoSetFocusPosition() calls Focuser1.MoveToPosition which is the synchronous version and waits until the focuser has reached the requested position (or reaches a timeout after 2 minutes).  

It is unclear if objFocuser1.Move itself is synchronous  or asynchronous. Trace statements has therefore been added to ascertain whether execution immediately returns from calling objFocuser1.Move (i.e. task is asynchronous)  or consumes some time (ie. task is synchronous).

Observatory Monitoring reads the following Focuser1 properties

Camera
Observatory Monitoring reads the following Camera properties
   .FilterIndexZeroBased,  .State,  .Status,  .Temperature,   .TemperatureSetPoint
Are any of these held up if Camera is taking an image ?

Conclusion
To early to drawn a firm conclusion regarding the precise cause of the issue, but analysis shows that the whilst the issue doesn't occur every time, the occurance of the issue isn't random, but clearly relates to the regular coincidental timing of the Obs.Monitor reading of certain objects and activity associated with those objects.

Action

Update 2021-03-08 pm

Tests on the Observatory Computer running against live hardware reveal that when the system is idling (with Dome/Focuser connected, but not the Scope) the time taken by ObservatoryMonitoring task varies between 80 and 950ms. The occasions were the time exceeds 600ms corresponds exactly with occasion were Focuser1 tasks take  550-650m to complete.       In one of two cases the time taken to complete tasks reaches some 1300-1500ms and occurs when the Network Checks  (pinging Router & AllSky/Weather Computer) exceed 500ms on top of the 550-650ms taken by Focuser1.

Tests involving commands to move the TCF-S Focuser (Foc1) show that objFocuser1.Move is clearly a synchronous operation.  On the particular movements made, execution was held up for a periods of 4.8s moving one direction and held up for  7.7s (backlash) + 2.7s moving the other direction.    Observatory Monitoring hung up during these activities, with Focuser1 section of the monitoring loop taking 3290ms,   4945ms and 3710ms.     This must be what is responsible for the hang-ups seen during live sessions.

At Start ObsViewer causes a single 5s hang-up of the Obs Monitoring Loop

Further Actions

Update 2021-03-09

The main issue has been resolved, the Obs.Monitoring loop is no longer held-up when Focuser1 is moving. 

A residual issue remains however.   The time taken by Obs.Monitor's Focuser1 tasks with the Focuser Idle / Stationary starts at around 16ms but then gradually increases to around 608-624ms, and which point it then drops down to 16ms before building again on a regular frequency of approximately 35s.  This possibly suggests some form of harmonic interaction with some other thread.     

One cycle is shown below. The first ms column is the total time for all Obs.Monitor tasks, whilst the second ms columns is the time for just Focuser1 tasks. As each loop of the Obs.Monitor is made the time taken to run the Focuser1 tasks increases. 

19:45:59.83 | ObsMonitorTime (ms) 78  16
19:46:02.33 | ObsMonitorTime (ms) 62  16
19:46:04.86 | ObsMonitorTime (ms) 78  16
19:46:07.38 | ObsMonitorTime (ms) 94  31
19:46:09.88 | ObsMonitorTime (ms) 78  16
19:46:12.44 | ObsMonitorTime (ms) 125 47
19:46:14.98 | ObsMonitorTime (ms) 156 94
19:46:17.55 | ObsMonitorTime (ms) 218 156
19:46:20.11 | ObsMonitorTime (ms) 265 203
19:46:22.73 | ObsMonitorTime (ms) 374 281
19:46:25.26 | ObsMonitorTime (ms) 390 328
19:46:27.80 | ObsMonitorTime (ms) 421 359
19:46:30.39 | ObsMonitorTime (ms) 499 437
19:46:32.95 | ObsMonitorTime (ms) 546 499
19:46:35.53 | ObsMonitorTime (ms) 608 562 Focuser1: 562,
19:46:38.11 | ObsMonitorTime (ms) 686 608 Focuser1: 608,

Obs.Manager Main Loop running every 5s accesses Focuser1.Port and Focuser1.PortWhenConnected properties but doesn't touch objFocuser1 object.     Turning off Obs.Manager doesn't change the 35s cycle behaviour.

The ObsWorker thread running every 2s calls GetSmartDewControl found to access Focuser1.PreciseTemperature and thereby objFocuser1.Temperature.
Modifying this rountine to access MonitorFoc1Temperature variable (set by the Observatory Monitoring Loop) should reduce the load on the objFocuser1 object, but surprisingly there is no change to the 35s cycle behaviour.

Changing the Obs.Monitor cycle time from a) 2.5s to 2.9s b) 2.5s to 1.5s or c) 2.5s to 2.2392  each give somewhat different Focuser1 cycle timing behaviour, but in each case there is still some form of repeating pattern with increasing time to perform Focuser1 tasks.

Is the behaviour

a) self induced interference pattern by the the Obs.Monitor loop itself.
b) an interference pattern produced by interaction with another thread calling Focuser1 object (however this can be somewhat elimated)
c) a pattern that is produced by interference with active thread time (the thread isn't continuously active but depends on time alloted by the Windows OS)

When TCF-S Focuser (objFocuser) service isn't running the remaining Obs.Monitor tasks typicially take 47ms or 61ms to run.  But a repeating pattern is evident so that every few cycles the tasks take 109 - 296ms to run.

Update 2021-03-11

Back to Top