David's Astronomy Pages
|
Notes (S866) |
Notes Main |
Home Page |
Notes (S868) |
Main aims
Equipment & Software
Highlights
Summary Plots & Logs
Observing Plan | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Observing Result |
||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Dome & Scope Slewing Performance | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Slew/Centering Performance | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Guiding Performance | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Sky Conditions (Locate Frames) | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Night Sky Summary Plot Top axis: Sky Brightness at Zenith (in ADU/s) Lefthand axis: Local Time (hh LT). Righthand axis: Sun Altitude (degs) |
||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Pre-Session Weather Forecast (API data from darksky.net) |
||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Session Event Log | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Session Alerts | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Back to Top
Back to Top
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
This Web Page: | Notes - Session 867 (2021-03-05) |
Last Updated : | 2024-09-30 |
Site Owner : | David Richards |
Home Page : | David's Astronomy Web Site |