Skip to content
This repository has been archived by the owner on Nov 3, 2021. It is now read-only.

Output of last points in continuous scan often comes too late #1651

Open
johanfforsberg opened this issue Jul 9, 2021 · 5 comments · May be fixed by #1668
Open

Output of last points in continuous scan often comes too late #1651

johanfforsberg opened this issue Jul 9, 2021 · 5 comments · May be fixed by #1668

Comments

@johanfforsberg
Copy link

Sometimes (~50% of times) the last point (and sometimes even the two last points) of the scan are output after some other output that is clearly about the end of the scan. E.g. the "Correcting overshoot..." message, see example output below.

This is confusing and also prevents adding more helpful output at the end (see #692) as it would be interleaved with the points table in confusing ways.

Here is an example (with "debug on"), note that point 10 is printed after "All data events are processed". Seems like there is some timing, or maybe buffer flushing problem going on?

Scan #34 started at Fri Jul  9 08:14:16 2021. It will take at least 0:00:00
_go_through_waypoints() entering...
Motor positions and relative timestamp (dt) columns contains theoretical values
Waypoint iteration...
Motor: mot10
AccTime: 2.000000
DecTime: 2.000000
Moving to start position: [-5.0]
Motor: mot10
start_user: 0.000000; end_user: 11.000000; start: -5.000000; end: 16.000000; ds: 21.000000
Starting measurement group
Moving to waypoint position: [16.0]
 #Pt No    mot10      ct09      ct10      ct11      ct12       dt   
   0         0        0.1       0.2       0.3       0.4        2    
   1         1        nan       nan       nan       nan       2.2   
   2         2        0.1       0.2       0.3       0.4       2.4   
   3         3        nan       nan       nan       nan       2.6   
   4         4        0.1       0.2       0.3       0.4       2.8   
   5         5        0.1       0.2       0.3       0.4        3    
   6         6        nan       nan       nan       nan       3.2   
   7         7        0.1       0.2       0.3       0.4       3.4   
   8         8        nan       nan       nan       nan       3.6   
   9         9        0.1       0.2       0.3       0.4       3.8   
on_waypoints_end() entering...
Correcting overshoot...
Waiting for data events to be processed
All data events are processed
   10        10       nan       nan       nan       nan        4    
Scan #34 ended at Fri Jul  9 08:14:29 2021, taking 0:00:13.327555. Dead time 100.0% (motion dead time 100.0%)
[ END ] runMacro Macro 'ascanct(mot10, 0.0, 10.0, 10, 0.1, 0.1) -> e2bf04f0-e07c-11eb-8460-fc4482b81901'

Job ended (stopped=False, aborted=False)
@johanfforsberg johanfforsberg mentioned this issue Jul 9, 2021
Merged
@reszelaz reszelaz linked a pull request Jul 27, 2021 that will close this issue
Open
2 tasks
@reszelaz
Copy link
Collaborator

Thanks for the report @johanfforsberg!
In #1668 I already addressed the problem of messages like:

on_waypoints_end() entering...
Waiting for data events to be processed
All data events are processed

Regarding the message:

Correcting overshoot...

it was done like this on purpose. Since the scan data events are queued and processed by a worker thread we wanted to go ahead with the overshoot correction as soon as possible (when the measurement is done).
I see two options:

  1. We change the order and first wait for all the data to be processed and then we perform the overshoot correction (not optimal)
  2. We change the log level of the message "Correcting overshoot..." to debug - then it could be interleaved with the scan records output only if the macro is run in the debug mode.

Or maybe you have some better solution?

Many thanks!

@johanfforsberg
Copy link
Author

Sorry for forgetting about this ticket!

I think option 2 is fine, unless you think the "overshoot" message is important enough to interrupt the table. In that case it's OK with me to keep it as it is. I'm not sure if it's something the general user needs to know. I feel that interrupting the table output should only be done if something "exceptional" happens.

@reszelaz
Copy link
Collaborator

Thanks @johanfforsberg for sharing your opinion. Now, 3rd option comes to my mind, what we could do is to maintain the info log level but delay its print until all the data events are processed and the overshoot correction is done. Message of course would need to be rephrased to "Overshoot correction was done" instead of "Correcting overshoot...". This way it will not interrupt the table output. And it still may be interesting to see, especially since the overshoot correction became optional recently.

@johanfforsberg
Copy link
Author

That sould like the best solution to me. The user is not really able to act on the message during the scan anyway, being informed at the end should be just as useful.

Sometimes it's good to let some time pass before acting; the best ideas are sometimes a bit slower :)

@reszelaz
Copy link
Collaborator

That sould like the best solution to me.

Done in ead90c2.

Sometimes it's good to let some time pass before acting; the best ideas are sometimes a bit slower :)

Yes, it happens to me all the time.. :)

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Advance output of last points in continuous scan reszelaz/sardana
2 participants
@johanfforsberg @reszelaz