Trigger times sometimes off by 1 second

[shallmann]

The current way the trigger time is constructed is insufficient!

The sub-second part is determined from the counter values (sysclk) of a ~100 MHz oscillator stored upon trigger and the last two PPS pulses. There is a long-standing issue which might be solvable in firmware, and an approximate solution which can be applied in mattak here: #3

Now here is another issue:

The second part is determined from the readout time (minus one if the subsecond part of the trigger time > subsecond part of the readout time) here:

mattak/src/Header.cc

Line 36 in 0143ee2

if (1e-9 * head->readout_time_nsecs < this->trigger_time) this->trigger_time += head->readout_time_secs-1;

. The simple "minus 1" by comparing the two is insufficient, due to time passing between trigger and readout.

Here is a demonstration, trigger times inconsistent with the events before/after are marked in red:

[shallmann]

for completeness... this is the current time difference between readout and trigger times stored for the same run

[cozzyd]

I think the problem is that the code might assume that readout_time is always larger than trigger time, but due to the clock drift, even with NTP, the CPU clock may fluctuate enough that even with the time it takes to readout, the readout time appears "before" the trigger time.

[barawn]

@cozzyd BTW you can't trust that it's always going to be 100M. It's sysclk - it's always going to be 1/32nd the sampling frequency. So if you slow the sampling freq sysclk slows.

Really I feel like when a run is reprocessed the timing should just be rebuilt based on the extracted sysclks and sanity checks. The sysclk counter itself is free running, so really the PPS values are just there to help figure out the overall time. If you fed everything into a simple digital filter it'd be easy to deal with weird glitches and such.

[cozzyd]

yes, we don't trust it's 100 M, we use sysclk_last_pps - sysclk_last_last_pps (which is off by a second, but close enough). Yes we should probably filter that distribution for post-processing.

For this particular problem, the right thing to do is probably just find the overall offset between pps_count and readout_time over the run.

[shallmann]

Ok, this is mainly to document findings, and discuss how to proceed.

1. depending on the offset between trigger and readout clock the current fractions where the trigger time stored is 1 second early ranges from close to 0 to close to 1 in a run ... I.e. globally a sizable fraction O(up to ~50%) of the trigger times currently stored are off

2. I tried 2 quick hacky offline fixes

• Fix 1: simply subtract -1 second from the currently stored trigger times if it is off from the readout time by >0.8 seconds
• Fix 2: use the pps_num and the readout times to determine the second part at pps_num==0 and use that

Although both of them make things better, none of them is perfect. I will attach some examples for demonstration below.

[shallmann]

• Case where it works:

• Case where fix 1 does not work but fix 2 does, because single events (I checked this happens right at the beginning of runs) are read out much after the trigger
  

• Cases where the readout distribution is much delayed
  
  

... this is the problematic case... unless the hardware reads out 20 secs (!) after the trigger, it looks like pps clicks are missed. These cases would need some further investigation, but it might be in that case that the sub-second part is also wrong since we divide by (pps_last - pps_last_last) ... These runs will be hard to fix correctly (and involves checking the sub-second part is done correctly judging by the pps_last/last_last difference if the difference is too large for only 1 pps difference)

[shallmann]

Just for demonstration, a second case of the "much delayed" distribution... which actually looks like the readout could be in fact delayed by few seconds here

And this run definitely looks like PPSes are missed:

[cozzyd]

It should never take so long to read out an event, unless somehow the CPU is swamped doing something different for a very long time? (running out of memory or something and waiting for the oom_killer to do something? but that "shouldn't" happen...I've never seen evidence that the oom_killer is doing anything).

In station 24, run 1132, I don't see any evidence of a missed pps in sysclk_last_pps - sysclk_last_last_pps, but I suppose it could happen in a second where there is no event in the next second.

But this is strange:

And this indicates we are certainly jumping seconds at some point:

[cozzyd]

also no obvious missed PPS problem here either (and in fact you can see the CPU clock jitter in here pretty well)

[cozzyd]

(well it's not really the CPU clock jitter only, also has to do with when the thread servicing the force triggers is scheduled... basically a force trigger is sent if that thread notices it's been longer than X time since the last one, it's not real time at all, a better way to see the clock jitter would be to look at the readout_time of a calpulser run).

[barawn]

There are also the status flags in the header that I'm not ever sure you check, but you'd be seeing weirdness in the event numbers if something happened there, though.

The roll flags will technically be more accurate than the check to see if the new clock is less than the last clock, but that would only matter if events are separated by a narrow time range - technically I guess I should just capture the entire 48-bit counter and compare that...

ooh I actually just realized I can do that for free if I'm clever, now I might need to write another module that does that

[cozzyd]

Do you have some debouncing on sysclk_last_pps / sysclk_last_last_pps that isn't applied to the pps_num?

[barawn]

No, they're all driven off of the same signal, which is why this doesn't make any sense.

[cozzyd]

Something funky is going on at the end of this run:

[cozzyd]

it's as if pps_num is jumping by several at a time, but somehow not detected by sysclk_last_pps - syclk_last_last_pps (which you'd expect to be very small sometimes if jumping quickly). Ok, we could miss a few since we don't have an event every second but, we shouldn't miss them all?