Pings become synchronized after a while

[patrakov]

The code initially tries to "Space out pings by ping interval / number of reflectors". However, this spacing-out does not persist. After the night, the pings became almost 100% synchronized, thus losing the temporal resolution:

1649738354.339253 1      3      0   1   [1649738354.247817] 9.9.9.9         8421   29457  38400  8951   0 idle           idle           556    163    -64    -96    1.2    -12.5 
1649738354.422146 1      3      0   1   [1649738354.258872] 1.1.1.1         8422   57339  57600  261    0 idle           idle           556    163    -64    -96    1.2    -12.5 
1649738354.506180 1      3      0   1   [1649738354.264873] 8.8.4.4         8421   53699  55700  2003   0 idle           idle           556    163    -64    -96    2.2    -12.5 
1649738354.589174 1      3      0   1   [1649738354.275154] 8.8.8.8         8421   60394  65800  5411   0 idle           idle           556    163    -64    -96    2.2    -12.5 
1649738358.336279 110    12     19  7   [1649738358.248908] 9.9.9.9         8422   29463  35600  6143   0 low            idle           544    166    -64    -98    2.2    -14.5 
1649738358.437099 110    12     20  7   [1649738358.263852] 1.1.1.1         8423   57340  58700  1361   0 low            idle           544    166    -64    -98    2.2    -14.5 
1649738358.519066 110    12     20  7   [1649738358.273839] 8.8.8.8         8422   60394  60700  306    0 low            idle           544    166    -64    -98    0.2    -14.5 
1649738358.601200 110    12     20  7   [1649738358.276845] 8.8.4.4         8422   53708  63400  9701   0 low            idle           544    166    -64    -98    0.2    -14.5 
1649738362.349216 4      3      0   1   [1649738362.258866] 9.9.9.9         8423   29474  41400  11937  0 idle           idle           544    166    -65    -98    2.2    -12.5 
1649738362.431115 4      3      0   1   [1649738362.267916] 1.1.1.1         8424   57341  58800  1460   0 idle           idle           544    166    -65    -98    2.2    -12.5 
1649738362.514163 4      3      0   1   [1649738362.278377] 8.8.8.8         8423   60394  61200  806    0 idle           idle           544    166    -65    -97    0.2    -12.5 
1649738362.595243 4      3      0   1   [1649738362.276988] 8.8.4.4         8423   53713  59600  5892   0 idle           idle           544    166    -65    -97    0.2    -12.5 
1649738366.357298 12     16     2   9   [1649738366.259868] 9.9.9.9         8424   29482  38400  8926   0 idle           idle           533    169    -64    -97    3.2    -13.5 
1649738366.459498 12     16     2   9   [1649738366.271022] 1.1.1.1         8425   57341  57900  559    0 idle           idle           533    169    -64    -97    3.2    -13.5 
1649738366.541186 12     16     2   9   [1649738366.285891] 8.8.8.8         8424   60398  64600  4206   0 idle           idle           533    169    -63    -98    2.2    -14.5 
1649738366.625145 12     16     2   9   [1649738366.288897] 8.8.4.4         8424   53726  67300  13587  0 idle           idle           533    169    -63    -98    2.2    -14.5 
1649738370.351141 159    110    29  65  [1649738370.260978] 9.9.9.9         8425   29488  35600  6118   0 medium         medium         533    169    -61    -94    4.2    -13.5 
1649738370.436131 159    110    29  65  [1649738370.275232] 1.1.1.1         8426   57341  58100  759    0 medium         medium         533    169    -61    -94    4.2    -13.5 
1649738370.521240 159    110    29  65  [1649738370.285985] 8.8.8.8         8425   60398  60800  402    0 medium         medium         533    169    -62    -95    0.2    -12.5 
1649738370.603143 159    110    29  65  [1649738370.290986] 8.8.4.4         8425   53737  65500  11774  0 medium         medium         533    169    -62    -95    0.2    -12.5 
1649738374.361174 291    31     54  18  [1649738374.268897] 9.9.9.9         8426   29497  39400  9912   0 medium         idle           533    172    -63    -96    4.2    -13.5 
1649738374.453875 291    31     54  18  [1649738374.281093] 1.1.1.1         8427   57341  57900  559    0 medium         idle           533    172    -63    -96    4.2    -13.5 
1649738374.537167 291    31     54  18  [1649738374.287952] 8.8.4.4         8426   53741  58600  4863   0 medium         idle           533    172    -64    -97    4.2    -13.5 
1649738374.619121 291    31     54  18  [1649738374.290958] 8.8.8.8         8426   60399  61800  1402   0 medium         idle           533    172    -64    -97    4.2    -13.5 

(The last four columns are signal strength measurements due to a local modification, please ignore, actually only the timestamps in the first column are relevant).

The suspected cause is that the ping processes were put to sleep, and there is nothing that restores the spacing-out when sending SIGCONT.

[lynxthecat]

Fantastic spot! Endeavouring to keep the spacing is indeed important and that they become synchronised is hugely detrimental for the reason that you state: we lose granularity.

I thought sending 'kill -STOP' and 'kill -CONT' would be fine because I imagined it being exactly like pausing and resuming the processes that had already been started in a staggered manner. But hopefully I am mistaken because the fix then would be easy - just stagger the 'kill -CONT' commands in the same way as the ping commands were staggered.

The latter would have the added benefit of resetting the staggering, which would have always tended to drift somewhat anyway.

So I'll try this and let's see if it fixes this issue.

[lynxthecat]

@moeller0 I am intrigued and a little stumped by how to tackle this one.

I tested by setting:

reflector_ping_interval_s=4 # (seconds, e.g. 0.2s or 2s)
sustained_idle_sleep_thr_s=6  # time threshold to put pingers to sleep on sustained dl/ul achieved rate < idle_thr (seconds)

with my usual four reflectors, and having the pingers get repeatedly put to sleep and woken up as per:

https://github.com/lynxthecat/CAKE-autorate/blob/main/CAKE-autorate.sh#L347

However I see the 1s spacing nicely retained:

ping_sync.txt

so it seems the solution to @patrakov's observation that with time his ping responses become synchronized is not as simple as I had imagined/hoped, i.e. by repeating this:

https://github.com/lynxthecat/CAKE-autorate/blob/main/CAKE-autorate.sh#L230

for the 'kill -CONT' calls.

Admittedly this is a benefit of 'fping', namely that 'fping' facilitates improved control over the spacing between pings because it pings in round robin and so the spacing is guaranteed to remain.

And yet use of 'fping' reduces our flexibility in controlling individual ping streams (e.g. we have to shut the whole fping process down just to remove one reflector, whereas with iputils-ping we can just shut down the one naughty stream).

So it would be nice if we could improve the separation somehow.

Any ideas? Now I know that just staggering the start-time of the calls is not guaranteed to ensure long term spacing, but I thought random jitter would be fine. So perhaps there is an easy fix here to help ameliorate things. Also, a more drastic solution would be to periodically look at the response timestamps and stop and start individual ping streams to forcibly restore spacing.

@patrakov since you are interested in physics, how about:

https://www.youtube.com/watch?v=T58lGKREubo

[moeller0]

Any ideas?

Yes, pass in interval and start_timestamp_ms, and delay the initial start of the ping command such that the time is just larger than start_timestamp_ms + integer*(interval) (this might require a busy wait at start up so ping is started as close to its "slot" as reasonably possible).
AND also only run pings for say 1000 samples, after which they are restarted again with waiting for the time slot. That should help with redistributing the pings over time and keep it that way, in spite of each ping process being independent and not all that precise. The number 100o obviously is just a first guess... The point is, this is still a heuristic that needs to be "good enough" so no need for absolute perfection here... you could probably figure out a suitable replacement for my 1000 by looking at a few traces to see how long it takes for the pings synchronize... and then pick a smaller number...

[lynxthecat]

Makes sense to me. One challenge is how to address retention of the background process id. Right now I retain the ping pid:

https://github.com/lynxthecat/CAKE-autorate/blob/97bba64a129b433bc2c75d501a0ed4d5d20be47f/CAKE-autorate.sh#L150

We kill that and that effectively kills the background monitor_reflector_path process.

But now if the monitor_reflector_path process restarts pings then I think we ideally just want pid for the monitor_reflector_path process that we can kill, which in turn will kill the ping. I don't entirely understand the 'exec' call. Would running ping with 'exec' inside the function mean that killing the pid for the function will kill the function and ping?

[moeller0]

Makes sense to me. One challenge is how to address retention of the background process id. Right now I retain the ping pid:

https://github.com/lynxthecat/CAKE-autorate/blob/97bba64a129b433bc2c75d501a0ed4d5d20be47f/CAKE-autorate.sh#L150

We kill that and that effectively kills the background monitor_reflector_path process.

But now if the monitor_reflector_path process restarts pings then I think we ideally just want pid for the monitor_reflector_path process that we can kill, which in turn will kill the ping. I don't entirely understand the 'exec' call. Would running ping with 'exec' inside the function mean that killing the pid for the function will kill the function and ping?

One option is to move this into its own file again, so the background PID then addresses the bash script, which can handle the stopping/restarting of the ping binary on its own, no? Similar to what you propose... I guess it is a matter of taste, but moving the monitor_reflector_path into its own set of files/scripts seems helpful to clean things up a bit, given that you will be adding more code to this function making the main script harder to read?

[patrakov]

For the record, I was able to reproduce the effect on my Arch Linux laptop.

In one terminal, run this:

ping -D -v -n -i 2 8.8.8.8 & sleep 1 ; ping -D -v -n -i 2 8.8.4.4 & wait

In the other terminal, run this:

killall -STOP ping ; sleep 15 ; killall -CONT ping

Result: grouped timestamps:

[1] 37742
PING 8.8.8.8 (8.8.8.8) 56(84) bytes of data.
[1649759289.592850] 64 bytes from 8.8.8.8: icmp_seq=1 ttl=119 time=93.2 ms
[2] 37745
PING 8.8.4.4 (8.8.4.4) 56(84) bytes of data.
[1649759290.612805] 64 bytes from 8.8.4.4: icmp_seq=1 ttl=119 time=110 ms
[1649759291.595966] 64 bytes from 8.8.8.8: icmp_seq=2 ttl=119 time=93.5 ms
[1649759292.602523] 64 bytes from 8.8.4.4: icmp_seq=2 ttl=119 time=98.5 ms
[1649759293.603134] 64 bytes from 8.8.8.8: icmp_seq=3 ttl=119 time=97.7 ms
[1649759294.602087] 64 bytes from 8.8.4.4: icmp_seq=3 ttl=119 time=95.4 ms
[1649759295.602899] 64 bytes from 8.8.8.8: icmp_seq=4 ttl=119 time=94.6 ms
[1649759296.596659] 64 bytes from 8.8.4.4: icmp_seq=4 ttl=119 time=88.5 ms
[1649759297.613447] 64 bytes from 8.8.8.8: icmp_seq=5 ttl=119 time=102 ms

[1]+  Stopped                 ping -D -v -n -i 2 8.8.8.8
bash: wait: warning: job 1[37742] stopped
bash: wait: warning: job 2[37745] stopped

[2]+  Stopped                 ping -D -v -n -i 2 8.8.4.4
[aep@hp-laptop ~]$ [1649759312.891879] 64 bytes from 8.8.8.8: icmp_seq=6 ttl=119 time=96.3 ms
[1649759312.895497] 64 bytes from 8.8.4.4: icmp_seq=5 ttl=119 time=100 ms
[1649759314.895126] 64 bytes from 8.8.8.8: icmp_seq=7 ttl=119 time=96.9 ms
[1649759314.896651] 64 bytes from 8.8.4.4: icmp_seq=6 ttl=119 time=98.6 ms
[1649759316.902985] 64 bytes from 8.8.8.8: icmp_seq=8 ttl=119 time=103 ms
[1649759316.907366] 64 bytes from 8.8.4.4: icmp_seq=7 ttl=119 time=107 ms

[lynxthecat]

Hmm, interesting. Here is what I see from my RT3200:

root@OpenWrt:~# ping -D -v -n -i 2 8.8.8.8 & sleep 1 ; ping -D -v -n -i 2 8.8.4.4 & wait
PING 8.8.8.8 (8.8.8.8) 56(84) bytes of data.
[1649761995.527296] 64 bytes from 8.8.8.8: icmp_seq=1 ttl=114 time=56.6 ms
PING 8.8.4.4 (8.8.4.4) 56(84) bytes of data.
[1649761996.518335] 64 bytes from 8.8.4.4: icmp_seq=1 ttl=114 time=44.0 ms
[1649761997.519758] 64 bytes from 8.8.8.8: icmp_seq=2 ttl=114 time=45.8 ms
[1649761998.529602] 64 bytes from 8.8.4.4: icmp_seq=2 ttl=114 time=52.3 ms
[1649761999.519421] 64 bytes from 8.8.8.8: icmp_seq=3 ttl=114 time=44.7 ms
[1649762000.528385] 64 bytes from 8.8.4.4: icmp_seq=3 ttl=114 time=48.5 ms
[1649762001.520522] 64 bytes from 8.8.8.8: icmp_seq=4 ttl=114 time=42.8 ms
[1649762002.519512] 64 bytes from 8.8.4.4: icmp_seq=4 ttl=114 time=36.9 ms
[1649762003.519566] 64 bytes from 8.8.8.8: icmp_seq=5 ttl=114 time=39.6 ms
[1649762004.529443] 64 bytes from 8.8.4.4: icmp_seq=5 ttl=114 time=44.8 ms
[1649762005.529398] 64 bytes from 8.8.8.8: icmp_seq=6 ttl=114 time=45.0 ms
[1649762006.539454] 64 bytes from 8.8.4.4: icmp_seq=6 ttl=114 time=52.7 ms
[1649762007.529282] 64 bytes from 8.8.8.8: icmp_seq=7 ttl=114 time=42.6 ms
[1649762008.539210] 64 bytes from 8.8.4.4: icmp_seq=7 ttl=114 time=49.5 ms
[1649762009.539393] 64 bytes from 8.8.8.8: icmp_seq=8 ttl=114 time=49.8 ms
[1649762010.538313] 64 bytes from 8.8.4.4: icmp_seq=8 ttl=114 time=45.9 ms
[1649762011.541687] 64 bytes from 8.8.8.8: icmp_seq=9 ttl=114 time=50.0 ms
[2]+  Stopped (signal)           ping -D -v -n -i 2 8.8.4.4
[1]-  Stopped (signal)           ping -D -v -n -i 2 8.8.8.8
root@OpenWrt:~# [1649762017.559402] 64 bytes from 8.8.4.4: icmp_seq=9 ttl=114 time=53.2 ms
[1649762018.559398] 64 bytes from 8.8.8.8: icmp_seq=10 ttl=114 time=52.8 ms
[1649762019.556848] 64 bytes from 8.8.4.4: icmp_seq=10 ttl=114 time=48.2 ms
[1649762020.557457] 64 bytes from 8.8.8.8: icmp_seq=11 ttl=114 time=48.8 ms
[1649762021.557382] 64 bytes from 8.8.4.4: icmp_seq=11 ttl=114 time=47.4 ms
[1649762022.560341] 64 bytes from 8.8.8.8: icmp_seq=12 ttl=114 time=50.3 ms
[1649762023.559345] 64 bytes from 8.8.4.4: icmp_seq=12 ttl=114 time=46.7 ms
[1649762024.559441] 64 bytes from 8.8.8.8: icmp_seq=13 ttl=114 time=46.8 ms
[1649762025.558389] 64 bytes from 8.8.4.4: icmp_seq=13 ttl=114 time=43.9 ms

In any case, if 'kill -STOP' and 'kill -CONT' is sometimes resulting in synchronization we would need to either have a mechanism to periodically enforce separation along the lines @moeller0 suggests above, or actually kill the ping processes on sleep and restart them in the same way they were originally started on sleep.

That is, just fully kill upon sleep and re-initiate again as in:

# Initiate pingers
for reflector in "${reflectors[@]}"
do
	t_start_us=${EPOCHREALTIME/./}
	monitor_reflector_path $reflector ${rtt_baseline[$reflector]}&
	t_end_us=${EPOCHREALTIME/./}
	# Space out pings by ping interval / number of reflectors
	sleep_remaining_tick_time $t_start_us $t_end_us $(( $reflector_ping_interval_us / $no_reflectors ))
done

The latter option is perhaps simpler? Albeit one issue is the resumption of the main processing loop since then that will be delayed somewhat until all the pingers are back up. So I'm not sure I like this so much either.

A hybrid would be to move the sleep to inside the monitor_reflector_path function so that we make the calls and then resume the main loop read ASAP. Perhaps this is the best fix for now?

[moeller0]

The latter option is perhaps simpler?

That will probably also kill the old baseline state, no? So after the ping sleep things will start with having to learn a new baseline. Which after a long sleep, might actually be the right thing to do anyway, no?

[lynxthecat]

Crap didn't think about that. If we wait to obtain the baseline updates as well that will mean introducing a little delay. But during this time the bandwidth will remain set to minimum so perhaps that is OK?

# Get initial rtt_baselines for each reflector
for reflector in "${reflectors[@]}"
do
	[[ $(ping -q -c 10 -i 0.1 $reflector | tail -1) =~ ([0-9.]+)/ ]] && printf -v rtt_baseline[$reflector] %.0f\\n "${BASH_REMATCH[1]}e3" || rtt_baseline[$reflector]=0
done

# Initiate pingers
for reflector in "${reflectors[@]}"
do
	t_start_us=${EPOCHREALTIME/./}
	monitor_reflector_path $reflector ${rtt_baseline[$reflector]}&
	t_end_us=${EPOCHREALTIME/./}
	# Space out pings by ping interval / number of reflectors
	sleep_remaining_tick_time $t_start_us $t_end_us $(( $reflector_ping_interval_us / $no_reflectors ))
done

As you can see the baseline capture is fixed at -c 10 -i 0.1 <-- these should be set based on other parameters? How many responses / over what period do we need for decent baseline?

[moeller0]

So what I would do instead is in the monitor_reflector scripts/function:

1. add a variable reflector_is_working=0
2. add a counter for consecutive good and bad samples (judged by a timeout criterion most likely)
   sample_counter

 if [  "${reflector_is_working}" -eq "0"  -a  "${sample_counter}" -gt "10" ] ;
then
         # actually write data to the FIFO,
fi

if [  "${reflector_is_working}" -eq "0"  -a  "${sample_counter}" -lt "-10" ] ;
then
        reflector_is_working=1
         # actually write data to the FIFO that signal the reflector is bad and should be replaced, potentially via a negative $sample_counter
fi

If a reflector is flapping between <10 good and bad samples it should be rejected as well, so maybe add a timeout if after 20 intervals reflector_is_working is still 0, or similar.

This is just shellish pseudo code that is probably broken... ;) but you get the idea, do not put that into the main script but simply do not

[moeller0]

How many responses / over what period do we need for decent baseline?

The more the better, but if we are sure about the link not being permanently congested even a single sample is fine, as the code updates the baseline on every sample with a strong bias towards smaller samples, so the should converge on the true baseline quickly, as long as we do not restart under massive prolonged congestion. But I think the ping wakeup happens at a really lowish achieved throughput so there is little risk of the problematic situation happening. And since this is a heuristic it might be "good enough" already...

[lynxthecat]

I really like your proposal above. Very elegant. It deals with baseline priming and wonky reflector management at the same time.

What should the counter max out at? 20?

[moeller0]

What should the counter max out at? 20?

The counter, IMHO should really count consecutive good or bad samples (by whichever criterion) with resetting to zero when switching between good and bad or bad and good. There is no real need to max it out, as long as we avoid wrap-around where positive numbers become negative, but there is also limited value in keeping large counts here... so for the implementation maybe ceil the counter at 106060*24 = 864000 the maximal number of 10Hz samples in a day?

Or are you asking about the timeout? I think 2 times the number of samples you want to aggregate into the initial baseline and to check whether the reflector is not obviously buggy (10 in the pseudocode above)... Or you could argue that start-up should not be delayed for more than X seconds and use that as timeout (just make sure that X is larger than the time required for the Y good samples ;) )

[lynxthecat]

But I thought the idea is that we increment the counter on good sample, and decrement on bad, and if a sufficient number of bad, then the reflector is silenced until it becomes good by 10 good samples again. If we allow the counter to go up really high, e.g. to 10,000 or more then doesn't that mean we will need at least 10,000 bad samples to classify reflector as bad?