Release 2.2.0 preperation

mdavidsaver commented 7 years ago

Let's try something different this time...

The next release includes some incompatible changes to the set of records for the EVG sequencer (included opis updated). This is part of a re-write so that the same code can be used with the sequencer found on newer 300 EVRs. There are also some substantial changes to the timestamp handling for similar reasons (300 EVRs can send software events).

I'd like to request, or give an opportunity, for testing by @aderbenev and/or @mark0n. Specifically, I'd like to get test results for:

Timestamping with an external time source (GPS). I'd like to know that the seconds value isn't off by one (or more). A few runs of "generalTimeReport 2" on a sync'd system should be sufficient.
Confirmation that the new sequencer code has no regressions in existing installations, particularly frib 100Hz.
Confirmation that RTEMS/mvme3100 still works. I do build tests, but it would be good to confirm that it runs.

The changelog in documentation/mainpage.h and the evr manual documentation/evr-usage.lyx have been updated to describe changes.

aderbenev commented 7 years ago

I'll give it a go on test setup next week. Alas, that setup lacks the external time source and 1 PPS is provided to EVG from EVR, but I suppose it is still sufficient to reveal any crude discrepancy. For sequencers, I learned that sometimes glitches are too intricate to be observed on anything less than live machine - but I can ensure that events arrive in certain relation at least.

aderbenev commented 7 years ago

I tried the new version in our test setup. Assume configuration where EVG runs on default FracSyn frequency which is divided to ~1 Hz and used to generate event 125. EVR produces a pulse based on that event which is fed to EVG as 1 PPS input:

timing_300_test_config

EVR requested frequency is set to 124.930 because of 1 Hz being not really 1 Hz so event 125 arrives too late and it invalidates the EVR time. This could be amended by decreasing Mxc divider as well.

Observed results are:

timing_300_test_result

Time-I.TSE is set to 0. Timestamps of PV values correspond to whatever is reported by generalTimeReport, but Time-I value is 1 second behind its timestamp and Timestamp-RB is 2 seconds ahead its timestamp, so there is 3 seconds total difference between those PV values (while PV timestamps match closely). Also, time error counter is increasing at ~1 Hz rate.

A bunch of reports:

timing_300_test_gtr

Also, a large discrepancy between EVR/OS and NTP clocks is because I adjusted the Mxc divider for faster event generation to see if there is any time value drifts. As mentioned, I cannot sync the timestamp with NTP source.

mark0n commented 7 years ago

I will look into this next week.

mdavidsaver commented 6 years ago

EVR requested frequency is set to 124.930 because of 1 Hz being not really 1 Hz so event 125 arrives too late and it invalidates the EVR time. This could be amended by decreasing Mxc divider as well.

Decreasing the divider is the recommended way to accomplish this. As you see, the PLL still locks with ~15KHz difference, but smaller is preferable. As I recall, the max difference is something like 20-25 KHz.

Time-I.TSE is set to 0. Timestamps of PV values correspond to whatever is reported by generalTimeReport, but Time-I value is 1 second behind its timestamp

Do you change this? Time-I.TSE should default to -2. I also fixed a long standing bug in this area (62d01c2f9fe2f8c31fc04ed5892ca3042eb544f6) where the event code being used was 0 (system time) instead of 125 reception time as I had intended. With this change, the timestamp used for Time-I should be reception of 125, which is immediately before the reset (aka. nanoseconds=999999999). With truncation by strftime() this shows as 1 second behind. (suggestions on how to clarify this would be appreciated)

Timestamp-RB is 2 seconds ahead

The value being shown is the seconds value which will be sent after the next reset. It won't be used until the following reset (the next next reset). So it should be ahead by 2. (again, suggestions to enhance clarify appreciated)

This can be understood by looking at https://github.com/epics-modules/mrfioc2/blob/master/mrmShared/src/mrmtimesrc.cpp#L175 which is essentially

bool valid = epicsTimeOK == generalTimeGetExceptPriority(&ts, 0, ER_PROVIDER_PRIORITY);
...
        if(ok && valid && impl->resync)  {
            impl->next = ts.secPastEpoch+POSIX_TIME_AT_EPICS_EPOCH+1;
            impl->resync = false;
        }
...
       impl->next++;

So when re-sync is requested, the result is next=now+2

mdavidsaver commented 6 years ago

To summarize. The results @aderbenev provides are what I would expect.

wrt. Time-I, the format string is presently hard-coded in evrApp/src/devEvrStringIO.cpp and doesn't include the fractional part of the seconds. This was an arbitrary decision on my part to keep the string shorter. This could be changed to add ".%f" to show some of the fractional part, or to use the fractional part to round up the seconds value.

aderbenev commented 6 years ago

I did change the TSE field so that timestamps of my monitors match for visual convenience. Given that it should not change when the record is being processed, I figured it won't alter results.

With truncation by strftime() this shows as 1 second behind.

It does show one second behind in my case; yet with .TSE=-2 seconds values match, e.g.

TST{evr:wiener}Time-I          2017-09-25 10:30:41.999920 Mon, 25 Sep 2017 10:30:41 -0400

So, effectively EVR time PV shows seconds value which arrived in previous cycle (not the one which is used to timestamp stuff in the current cycle), and EVG time PV shows seconds value which is to be sent in next-next cycle. By common sense, I'd expect instead:

EVR to report last seconds value it received (and which is used to timestamp stuff)
EVG to report last seconds value it sent
Those values to match

Not like system users are concerned with that much as long as timestamping itself works, but those subtleties then deserve a mention in some documentation section perhaps.

Decreasing the divider is the recommended way to accomplish this.

Is that a viable option for the live machine where the RF frequency divider is derived from all applicable constraints? I always saw it to be pretty much fixed.

mdavidsaver commented 6 years ago

EVR to report last seconds value it received (and which is used to timestamp stuff) EVG to report last seconds value it sent Those values to match

This is a bit contradictory as there is the 1 second gap between when the EVG shifts out a timestamp to when an EVR starting using it. I take your meaning though.

However, I'm going to go ahead with a release because, as you note, this isn't really a user visible confusion.

Decreasing the divider is the recommended way to accomplish this.

Is that a viable option for the live machine where the RF frequency divider is derived from all applicable constraints? I always saw it to be pretty much fixed.

Firstly, a live machine would have a GPS receiver for the 1Hz. Second, I'm referring to the divider between RF and ~1Hz in the EVG, which can be chosen arbitrarily wrt. the RF freq.

mdavidsaver commented 6 years ago

Released

http://www.aps.anl.gov/epics/tech-talk/2017/msg01593.php

epics-modules / mrfioc2

Release 2.2.0 preperation #13