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

• Add additional trace statements to ObservatoryMonitoring Loop. Add additional trace statements to capture information about the time taken to run each cycle of the observatory Monitoring code (written to (debug).dat file ) and the particular tasks and time times taken for any individual part of the observatory monitoring loop where a particular task has taken > 500ms.  
  (This will provide definitive information to narrow down the problem area to a specific object or specific group of tasks)
  
   
• Work on the interim hypothesis that issue relates to the Focuser1 object.
  ( alternate but less likely hypothesis is that issue relates to the Camera1 object (CCDSoft.Camera))
  
   

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

• Any Operations that move the focuser (whether manually initiated or automated) to set a flag to say that scope is moving . This would be a flag which can be checked before committing Obs.Monitoring to reading Focuser properties with the potential for causing the execution to hand-up until the Focuser Move is completed.
  
   
• Network Checks to be conducted via a separate thread in order to isolate Obs.Monitoring from network delays.
  
   
• Add extra trace statements that record time taken by Obs.Monitor's Focuser1 tasks
  

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

Session S868 (2021-03-11) showed that the CCD and Foc1 Fields sections of Obs.Monitor experience occasional hangups of 1 - 3s. The Hangs-ups typically come when Focuser1 section is also taking 500-600ms.   Hang-ups of CCD and Foc1 Fields also seem to came at the same time.    Hangups are only present when session is running / and images are being taken.  No hangups of CCD & Foc1 Fields sections occured when the session was suspended between 23:24 and 03:29.   UpdateFoc1Fields() routine accesses  Camera.FilterIndexZeroBased twice each time it's called,  so the association between hang-ups of the Foc1 Fields and CCD Sections is explainable.   Examining timings shows that CCD object becomes locked/unaccessible when it is downloading an image.     This time is predictable based on when Camera.TakeImage is called and the delay and exposure time used.   These hang-ups could potentially be fixed by using asynchronous camera ops but this requires very careful implementation, therefore the issue will be fixed in the shorterm by using a flag and time point  (bCamera1TakingImage and Camera1ExpectedStartDownloadTime )  to indicate when the Camera is / isn't available.