ClockSync.lf test seems to silently fail

[hokeun]

Description:

It looks like there is a problem with clock synchronization in federated LF. While @Jakio815 was running federated LF programs on distributed computers (Raspberry PI), he found that clock sync did not work, and it did not work on release 0.7.0 either, showing a very high ( 1-100 ms) clock synchronization error when he measured the lag (physical time - logical time) for the very simple federated examples.

Code version:

• lingua-franca: master branch
• reactor-c: 329528f0

  Platform

• M1 Macbook pro

  Test

• test/C/src/federated/ClockSync.lf

  Error log

✗ test/C/bin/ClockSync
Federate ClockSync in Federation ID 'cf57679640238ba198c0a561dee6a7f56a84777cc3ecd371'
#### Launching the runtime infrastructure (RTI).
#### Launching the federate federate__fed1.
#### Launching the federate federate__fed2.
#### Bringing the RTI back to foreground so it can receive Control-C.
RTI -i ${FEDERATION_ID} -n 2 -c on period 5000000 exchanges-per-interval 10 \
Federation ID for executable /Users/hokeunkim/Development/lingua-franca/test/C/fed-gen/ClockSync/bin/federate__fed1: cf57679640238ba198c0a561dee6a7f56a84777cc3ecd371
---- System clock resolution: 1000 nsec
---- Start execution at time Tue May  7 09:41:24 2024
---- plus 757999000 nanoseconds
Fed 0 (fed1): Connected to RTI at localhost:15045.
Fed 0 (fed1): Environment 0: ---- Intializing start tag
Federation ID for executable /Users/hokeunkim/Development/lingua-franca/test/C/fed-gen/ClockSync/bin/federate__fed2: cf57679640238ba198c0a561dee6a7f56a84777cc3ecd371
---- System clock resolution: 1000 nsec
---- Start execution at time Tue May  7 09:41:24 2024
---- plus 990169000 nanoseconds
Fed 1 (fed2): Connected to RTI at localhost:15045.
Fed 1 (fed2): Environment 0: ---- Intializing start tag
Fed 1 (fed2): Starting timestamp is: 1715042489996164001.
Fed 0 (fed1): Starting timestamp is: 1715042489996164001.
Fed 1 (fed2): Environment 0: ---- Spawning 2 workers.
Fed 1 (fed2): Clock sync error at startup is -3300 ns.
Fed 1 (fed2): Received 42.
Fed 0 (fed1): Environment 0: ---- Spawning 2 workers.
Fed 0 (fed1): Clock sync error at startup is -3900 ns.
Fed 0 (fed1): Received 42.
Fed 1 (fed2): Received 42.
Fed 0 (fed1): Received 42.
Fed 1 (fed2): Received 42.
Fed 0 (fed1): Received 42.
Fed 1 (fed2): Received 42.
Fed 0 (fed1): Received 42.
Fed 1 (fed2): Received 42.
Fed 0 (fed1): Received 42.
Fed 1 (fed2): Received 42.
Fed 0 (fed1): Received 42.
Fed 0 (fed1): Received 42.
Fed 1 (fed2): Received 42.
Fed 1 (fed2): Clock sync error at shutdown is -13284 ns.
Fed 0 (fed1): Clock sync error at shutdown is -54469 ns.
Fed 1 (fed2): Connection to the RTI closed with an EOF.
---- Elapsed logical time (in nsec): 10,000,000,000
---- Elapsed physical time (in nsec): 10,005,290,715
Fed 0 (fed1): Connection to the RTI closed with an EOF.
---- Elapsed logical time (in nsec): 10,000,000,000
---- Elapsed physical time (in nsec): 10,007,841,530
ERROR: Clock sync failed with federate 1. Not connected.
RTI has exited. Wait for federates to exit.
All done.

[hokeun]

This maybe related to https://github.com/lf-lang/reactor-c/issues/332. However, now, it looks like the same problem occurs on other platforms, not just Mac.

[lhstrh]

Can you confirm whether clock sync is actually happening or not? And if not, why not? With that information if would be easier to come up with a fix.

[hokeun]

Can you confirm whether clock sync is actually happening or not? And if not, why not? With that information if would be easier to come up with a fix.

I think the clock sync is happening. Here is part of the log for the same test with a debug option on for both RTI and federates:

DEBUG: RTI sending T1 message to initiate clock sync round.
DEBUG: Clock sync: RTI sending UDP message type 19.
DEBUG: Clock sync: RTI sent PHYSICAL_TIME_SYNC_MESSAGE with timestamp 1715043670851987000 to federate 1.
DEBUG: Clock sync: RTI received T3 message from federate 1.
DEBUG: Clock sync: RTI sending UDP message type 21.
DEBUG: Clock sync: RTI sent PHYSICAL_TIME_SYNC_MESSAGE with timestamp 1715043670852119000 to federate 1.
DEBUG: Clock sync: RTI sending UDP message type 22.
DEBUG: Clock sync: RTI sent PHYSICAL_TIME_SYNC_MESSAGE with timestamp 1715043670852153000 to federate 1.
DEBUG: RTI sending T1 message to initiate clock sync round.
DEBUG: Clock sync: RTI sending UDP message type 19.
DEBUG: Clock sync: RTI sent PHYSICAL_TIME_SYNC_MESSAGE with timestamp 1715043670858257000 to federate 0.
DEBUG: Clock sync: RTI received T3 message from federate 0.
DEBUG: Clock sync: RTI sending UDP message type 21.
DEBUG: Clock sync: RTI sent PHYSICAL_TIME_SYNC_MESSAGE with timestamp 1715043670858476000 to federate 0.
DEBUG: Clock sync: RTI sending UDP message type 22.
DEBUG: Clock sync: RTI sent PHYSICAL_TIME_SYNC_MESSAGE with timestamp 1715043670858507000 to federate 0.
DEBUG: RTI sending T1 message to initiate clock sync round.
DEBUG: Clock sync: RTI sending UDP message type 19.
DEBUG: Clock sync: RTI sent PHYSICAL_TIME_SYNC_MESSAGE with timestamp 1715043670858530000 to federate 1.
DEBUG: Clock sync: RTI received T3 message from federate 1.
DEBUG: Clock sync: RTI sending UDP message type 21.
DEBUG: Clock sync: RTI sent PHYSICAL_TIME_SYNC_MESSAGE with timestamp 1715043670858665000 to federate 1.
DEBUG: Clock sync: RTI sending UDP message type 22.
DEBUG: Clock sync: RTI sent PHYSICAL_TIME_SYNC_MESSAGE with timestamp 1715043670858691000 to federate 1.
Fed 1 (fed2): Clock sync error at shutdown is -17011 ns.
Fed 0 (fed1): Clock sync error at shutdown is -49033 ns.
DEBUG: RTI sending T1 message to initiate clock sync round.
DEBUG: Clock sync: RTI sending UDP message type 19.
DEBUG: Clock sync: RTI sent PHYSICAL_TIME_SYNC_MESSAGE with timestamp 1715043670864985000 to federate 0.
DEBUG: RTI: Received message type 4 from federate 1.
DEBUG: RTI: Received message type 4 from federate 0.
RTI: Federate 1 has resigned.
Fed 1 (fed2): Connection to the RTI closed with an EOF.
---- Elapsed logical time (in nsec): 10,000,000,000
---- Elapsed physical time (in nsec): 10,005,464,988
DEBUG: Clock sync: RTI received T3 message from federate 0.
RTI: Federate 0 has resigned.
Fed 0 (fed1): Connection to the RTI closed with an EOF.
---- Elapsed logical time (in nsec): 10,000,000,000
---- Elapsed physical time (in nsec): 10,006,303,966
WARNING: Clock sync: RTI failed to send physical time to federate 0. Socket not connected.

WARNING: Clock sync: RTI failed to send physical time to federate 0. Socket not connected.

ERROR: Clock sync failed with federate 1. Not connected.
RTI: Federate 0 thread exited.
RTI: Waiting for thread handling federate 1.
RTI: Federate 1 thread exited.
LOG: On shut down TCP socket, received reply: Socket is not connected
LOG: On shut down UDP socket, received reply: Socket is not connected
RTI is exiting.
RTI has exited. Wait for federates to exit.
All done.

[lhstrh]

Interesting. Perhaps @edwardalee or @erlingrj know more?

[erlingrj]

Its the RTI which throws the error. Are you sure RTI is also from v0.7?

[hokeun]

Its the RTI which throws the error. Are you sure RTI is also from v0.7?

I think so. I used the master branch of lingua-franca, and installed the RTI using the reactor-c version attached to the current master branch.

• lingua-franca: master branch
• reactor-c: 329528f0

[erlingrj]

OK. It looks as if the RTI believes that the initial clock sync has not completed, while the federates does. Before debugging this issue I would like to know if Edward has any clue, I know that they recently fixed clock sync after seeing that it did not work on RPIs.

In any case, I would recommend to just use NTP or PTP to synchronize the RPis and disable clock sync. It is not that hard to setup your own local NTP server on either your desktop, or on one of the RPis, and point the other NTP clients to it. It is also an educational experience as NTP is a very important piece of the internet

[edwardalee]

I suspect the error message is occurring because the clock-sync thread is trying to communicate after the other side has shut down.

[erlingrj]

OK, so then it is not a bug. Then I guess we need to know more about the clock-sync error that was measured. Can you explain the experiment in more detail. How did you actually measure clock sync precision based on lag? What kind of network was used?

[edwardalee]

@fra-p has been tracking problems with clock sync using two RP5s. He is running a simple federated program where each federate drives a GPIO pin in a reaction triggered by a timer. He uses a logic analyzer to measure the time between transitions on the pins. He first identified an error where clock sync was not being done when clock sync option was "init". This was fixed in PR 414 in reactor-c. However, there are still mysterious problems. Most weirdly, he sees that when clock sync is set to "init", then after the initial clock sync phase, the clocks drift by more than their natural drift. This is inexplicable and it only occurs if the clocks are initially significantly out-of-phase.

[erlingrj]

That is strange, is the clocks drifting faster than if we had just clock-sync: off? Is ntps/chronyd running in the background? It might be bug with the addition/subtraction of the clock-sync offsets also. Not unthinkable that it is related to 32bit vs 64bit OS also

[fra-p]

Hi Erling! During the experiments I don't have any clock synchronization services running in the background. I've got some plots to show about this issue that might give you a hint on where the problem is.

This is the behaviour over time of the offset between the two signals when clock-sync: off: To obtain this, I ran the PTP clock synchronization, I disabled it and then ran the LF program.

This is the behaviour of the offset when clock-sync: init but when the initial offset is small (e.g., right after PTP clock sync, as in the former experiment): And this is interesting already, because I would have expected the same drift as with clock-sync: off.

Then I shut the RPis down and turned them on again, so that their clocks were off by 1.8s, and then ran the LF program with clock-sync: init: The error between the two signals increases linearly. It's interesting to see that I repeated the same experiment today with the clocks initially off by about 24s and this is the behaviour I got: Because of the 24s initial offset, the two LF programs waited 24s before starting, and the error at startup looks comparable to the error of the 1.8s initial offset case at time 25s. Edward suggested that it might be a problem with the wait_until function, I'm currently on that to be sure the offset variable is managed correctly. I'm compiling with lfc-dev on the latest commit of the main branch, and I reinstalled the RTI to be sure I've got the latest version. Also, I should be running a 64-bit OS on both the RPis:

[Jakio815]

The problem that I got was when I used two Raspeberry Pis. One federate just sends an integer using lf_set(), when a timer is triggered, and the other just receives it, and prints the lag instant_t lag = lf_time_physical() - lf_time_logical();.

 target C {
  // logging: DEBUG,
  // comm-type: SST,
  // tracing: true,
  timeout: 50 sec
}

reactor Source {
  output out: int
  timer t(0, 500msec)

  reaction(t) -> out {=
    lf_set(out, 47);
  =}
}

reactor Destination {
  input in: int
  state count: int = 0
  state avg_lag: instant_t = 0
  state max_lag: instant_t = 0
  state min_lag: instant_t = 1000000000 //1sec
  state total_lag: instant_t = 0

  reaction(in) {=
    instant_t lag = lf_time_physical() - lf_time_logical();
    char time_buffer[LF_TIME_BUFFER_LENGTH];
    lf_readable_time(time_buffer, lag);
    lf_print("Received %d. Logical time is behind physical time by %s nsec.", in->value, time_buffer);
    if (self->max_lag < lag){
      self->max_lag = lag;
    }
    if (self->min_lag > lag){
      self->min_lag = lag;
    }
    self->count ++;
    self->total_lag += lag;
  =}
  reaction(shutdown) {=
    self->avg_lag = self->total_lag / self->count;
    FILE* fp;
    fp = fopen("eval.csv", "a");
    if(fp == NULL) {
      lf_print("Couldn't open the file.");
    } else {
      fprintf(fp, "%ld,", self->avg_lag);
      fprintf(fp, "%ld,", self->max_lag);
      fprintf(fp, "%ld\n", self->min_lag);
      fprintf(fp, "\n");
    }
    lf_print("Avg: %ld, Max: %ld, Min: %ld", self->avg_lag, self->max_lag, self->min_lag);
    fclose(fp);
  =}

}

federated reactor at localhost{
  s = new Source()       // Reactor s is in federate Source
  d = new Destination()  // Reactor d is in federate Destination
  s.out -> d.in          // This version preserves the timestamp.
}

What I found out that the time differs depending on what RPI was the Destination printing the time.

On v0.6.0, it shows a proper lag between 7~10 milliseconds, on both sides.

On v0.7.0 it shows an unstable lag. When RPI 1 was the Destination, it showed a lag under 1 milliseconds, and when RPI 2 was the Destination, it showed a around 100 milliseconds.

I think the initial clock-synchronization using TCP is not working properly.

I also had the same problem when one device was the RPI, and the other was a Windows Machine running WSL Ubuntu 20.04.

[edwardalee]

I suggest being careful with terminology: "drift" is the rate of change of clock synchronization error. "Offset" is the clock synchronization error. Above, for example, "24 second drift" should be "24 second initial offset." Technically, drift is unitless, but it's more useful to see it as having units of seconds per second.

[erlingrj]

@fra-p Thanks for sharing those plots! I have some questions to understand it better.

This is the behaviour over time of the drift between the two signals when clock-sync: off. To obtain this, I ran the PTP clock synchronization, I disabled it and then ran the LF program.

In this plot it seems you have a drift of around 33PPB (roughly from a 2us offset to 2.5us offset between 5s and 25s) This is remarkably little and must be because PTP has very accurately estimated the drift. I think, if you stop ptpd, CLOCK_REALTIME will just continue with the last drift corrections.

I cannot find info on the crystal oscillator on the RPi5, but read something about 100PPM on a previous version.

This is the behaviour of the drift when clock-sync: init but when the drift is small (e.g., right after PTP clock sync, as in the former experiment). And this is interesting already, because I would have expected the same drift as with clock-sync: off.

Yes, we would expect the same behavior more-or-less. But could this not be explained by PTP this time having estimated an even more accurate relative drift between the two oscillators, before you turned it off?

Then I shut the RPis down and turned them on again, so that their clocks were off by 1.8s, and then ran the LF program with clock-sync: init: The error between the two signals increases linearly. It's interesting to see that I repeated the same experiment today with the clocks off by about 24s and this is the behaviour I got:

In this plot we are seeing a drift of ~2PPM (last time was per billion), this is also very small actually. But the big question here is this: Was ptpd/ntpd/chronyd running at all after your reboot? Because if they were not, then I would expect this kind of drift.

Because of the 24s-drift, the two LF programs waited 24s before starting, and the error at startup looks comparable to the error of the 1.8s-drift case at time 25s.

Hm, is this the correct behavior? Should not the initial clock sync make the clocks appear equal, the one hosting the RTI should be the master and the other should get an offset that it will apply to all readings of the clock? This seems like a bug to me. But the other plots seems like within expected behavior?

Edward suggested that it might be a problem with the wait_until function, I'm currently on that to be sure the offset is managed correctly. I'm compiling with lfc-dev on the latest commit of the main branch, and I reinstalled the RTI to be sure I've got the latest version.

Great. FYI, there is critical logic that every time you read with lf_time_physical() the estimated clock offset is applied, such that physical times are not necessarily equal to the system time. This offset must be removed before trying to sleep since those functions, pthread_cond_timedwait sleeps relative the system time.

[erlingrj]

@Jakio815

In the program you share, there is no clock-sync target properties set. Can you explain what they were for the different experiments. Also where is the RTI located? When you switch where each federate is running, do you also switch where the RTI is running?

On v0.7.0 it shows an unstable lag. When RPI 1 was the Destination, it showed a lag under 1 milliseconds, and when RPI 2 was the Destination, it showed a around 100 milliseconds.

This certainly looks like a clock sync error. It looks to me that RTI is always located at one of the RPIs and that the LF physical clocks (which in these cases are distinct from system clocks btw, LF physical clock = system_time + clock_sync_offset) are off around 100 msec. If RPI2 has a LF clock that reads 100 msec greater than RPI1, then this would be the behavior.

It might be good for you to compare notes with @fra-p since he apparently has the initial clock sync working on the RPis.

Lastly, I think we need to build a testbed for evaluating the real-time performance which can run as part of the CI. Would be a great project for a PhD student :D

[edwardalee]

Note that if you are not running in an up-to-date master/main, then you won't have my bug fix that resulted in clock-sync being off by default rather than init by default.

[Jakio815]

@erlingrj The RTI was working on a workstation, and federates on a separate RPIs.

@edwardalee I didn't understand. ASAIK, the RTI and federates do initial clock sync as default, even with the 'RTI -c init' and 'clock-sync: init'.

You mean that on the latest version(v0.7.0) clock sync is off as default?

[edwardalee]

Hmm, it looks to me like my PR was merged into main two weeks ago, so it should be in 0.7.0, though I'm not sure. However, on re-examining that PR, it seems that initial clock synchronization will only be done if _LF_CLOCK_SYNC_INITIAL is defined, and I don't see anywhere in the code where this gets defined. In fact, I don't see how the current scheme can possibly work. Clock sync will occur only if one of _LF_CLOCK_SYNC_INITIAL or _LF_CLOCK_SYNC_ON is set, but neither of these is set by default. The usual way to set a default would be to have something like this in a header file:

#ifndef _LF_CLOCK_SYNC_INITIAL
#define _LF_CLOCK_SYNC_INITIAL
#endif

but this won't work because then it will be impossible to turn clock synchronization off. @erlingrj : Suggestions? It looks to me like clock synchronization is still off by default and only will be turned on if you explicitly turn it on by setting either _LF_CLOCK_SYNC_INITIAL or _LF_CLOCK_SYNC_ON.

[edwardalee]

As a workaround while we fix this, you should be able to turn on clock synchronization with the target parameter:

  clock-sync: on,  // Turn on runtime clock synchronization.

or

  clock-sync: init,  // Turn on runtime clock synchronization at initialization only.

[fra-p]

@edwardalee I'm sorry for my incorrect use of the terminology. I edited the original comment with the (hopefully) correct terms, thank you!

@erlingrj thanks for your comments! This is how I ran the first two experiments (clock-sync: off and clock-sync: init): first I synchronized the clocks with PTP, then I stopped the clock synchronization and ran the two experiments (first clock-sync: init and then clock-sync: off). So, the two cases were using the same drift correction computed by PTP. I also have more runs of the clock-sync: init experiments with the same PTP correction (i.e., executed one after the other without restarting PTP or rebooting the Pis), which show behaviours that I find hard to explain:

For the experiment with clock-sync: init with the 24s initial offset, I didn't restart PTP (or any clock sync daemons) after reboot. So, you are saying that the reboot reset the drift correction that was computed by PTP. This then would explain the behaviour.

I cannot tell if in the experiment with clock-sync: init and the initial offset of 1.8s there was an initial wait time before seeing the LF program run on the two boards (the initial offset was too small). But I'm sure that I saw it with the 24s initial offset.

I also noticed that I get the same linear error behaviour with clock-sync: on (as with clock-sync: init), probably the LF clock synchronization is not happening. I see that the UDP thread receives packets from the RTI but for some reason they are not processed. Currently investigating the cause...

[fra-p]

Update: I managed to get the LF clock-sync: on working. Looking at the code of the RTI, the RTI needs to be executed with the option -c on to enable the clock synchronization algorithm. I see that there is also the possibility to enable the synchronization of the start time only with -c init and I wonder if it really needs to be enabled? (maybe @erlingrj?) Because clock-sync: init is already working without specifying the command line option when starting the RTI.

[Jakio815]

@edwardalee

Hmm, it looks to me like https://github.com/lf-lang/reactor-c/pull/414 was merged into main two weeks ago, so it should be in 0.7.0, though I'm not sure. However, on re-examining that PR, it seems that initial clock synchronization will only be done if _LF_CLOCK_SYNC_INITIAL is defined, and I don't see anywhere in the code where this gets defined. In fact, I don't see how the current scheme can possibly work. Clock sync will occur only if one of _LF_CLOCK_SYNC_INITIAL or _LF_CLOCK_SYNC_ON is set, but neither of these is set by default. The usual way to set a default would be to have something like this in a header file:

I had a look at the code. The clock-sync option setting implementations are different in the federate and RTI.

Federate (Use compiler definitions)

The _LF_CLOCK_SYNC_INITIAL and _LF_CLOCK_SYNC_ON are only for federates. You can find out that these definitions are not used in rti_remote.c. It is only in clock.c and clock-sync.c and the functions where they are used, are only used for federates (e.g. setup_clock_synchronization_with_rti()). The initial mode is defined in here.

  public ClockSyncMode initialValue() {
    return ClockSyncMode.INIT;
  }

RTI (Use variables)

RTI has a variable rti_remote->clock_sync_global_status, that can be controlled by the -c option. The default status of the RTI is the init mode. It is set up in rti_remote.c's initialize_RTI() function's rti_remote->clock_sync_global_status = clock_sync_init; line. Of course it can be changed by the -c option, and that is in process_clock_sync_args().

After a federate connect()s to the RTI, the federate sends a couple of things, and then the RTI enters receive_udp_message_and_set_up_clock_sync(). Whatever the clock-sync option is, the federate sends a port number. The RTI receives this message. This is because the RTI does not have any information about the federate's clock-sync mode .

Now the RTI decides the clock-sync mode for the federate depending on this port number. https://github.com/lf-lang/reactor-c/blob/0a4272234b0e7109271e4797338f099facb8e48d/core/federated/RTI/rti_remote.c#L1415

If the federate sends a port number UINT16_MAX then it means the clock-sync is off. https://github.com/lf-lang/reactor-c/blob/0a4272234b0e7109271e4797338f099facb8e48d/core/federated/clock-sync.c#L164

If the federate sends a port number 0 then it means the clock-sync is init. https://github.com/lf-lang/reactor-c/blob/0a4272234b0e7109271e4797338f099facb8e48d/core/federated/clock-sync.c#L205

If the federate sends anything else, it means the clock-sync is on.

The logic how the RTI works, is that if the port number is not UINT16_MAX it does the initial clock-sync in TCP. Then, if if (rti_remote->clock_sync_global_status >= clock_sync_on) { this passes, it sets up the received port number, and other UDP information. The actual UDP clock-sync is done in clock_synchronization_thread()

So these are some points interesting.

• If the RTI is -c init and federates are clock-sync: on, the clock-sync after the initial will not work.
• If the RTI is -c on and federates are clock-sync: init it will only do the default initial clock-sync.
• If the RTI is -c on and one federate is clock-sync: init, and another is clock-sync: on, one will do only the initial, and the other will do the runtime clock-sync using UDP. (However, this needs to be verified. The code just looks like this.)

[edwardalee]

This is another reason we should be code generating the RTI together with the federates. Currently, getting the clock sync parameters to match relies on the launch script being run. If you run the RTI and federates manually, you have to start the RTI to match the compiled federates.

[edwardalee]

Also, it looks like my clock sync fixes have not been merged and are not in 0.7.0, so I don't think clock sync init will work in 0.7.0 unless it is explicitly specified in the target properties.

[lhstrh]

Also, it looks like my clock sync fixes have not been merged and are not in 0.7.0, so I don't think clock sync init will work in 0.7.0 unless it is explicitly specified in the target properties.

Where are those changes then?

[edwardalee]

The clock sync fixes are here: https://github.com/lf-lang/reactor-c/pull/425 This was stalled due to issues somewhat peripheral to the PR, but it got merged 12 hours ago. I'm not sure it made it into 0.7.1.

[lhstrh]

The clock sync fixes are here: lf-lang/reactor-c#425 This was stalled due to issues somewhat peripheral to the PR, but it got merged 12 hours ago. I'm not sure it made it into 0.7.1.

It wasn't, because the submodule apparently wasn't updated... Happy to release another patch soon.

[lhstrh]

@edwardalee and @hokeun, can this issue be closed?

[hokeun]

@edwardalee and @hokeun, can this issue be closed?

Yes, I think this can be closed now.