Boot time, wall time, arrival time: one incident, three clocks

The first question in any incident review is what failed first. In INC-0142, obstacle data into PX4 stopped on a quad’s return leg, and the companion’s kernel killed the process that sent it. On one merged timeline the two events sit 39 ms apart, and the logs cannot say which came first.

INC-0142 is an example from the Foxborne example dataset, not a field report. Its logs keep three kinds of time: boot time, wall time and arrival time. Each needs an anchor to reach UTC, and every anchor comes with an error you can write down.

Write the errors down, and the ordering question gets a precise answer. Two events on different clocks have a supported order only when they sit farther apart than their bounds combined.

Boot time: the flight log

Every logged topic in a ULog must carry a timestamp field: a uint64_t in microseconds.¹ In PX4’s messages that field is time since system start, as the sensor_gps definition states.² The last obstacle_distance sample before the stall reads 1,132,793,000 µs, which is 1,132.793 s after boot and says nothing about when boot happened.

The anchor is sensor_gps. Each message carries both clocks: the boot timestamp, and time_utc_usec, the UTC time from the GPS module.² A third field places that UTC time on the boot clock:³

uint64 timestamp		# time since system start (microseconds)
...
int32 timestamp_time_relative	# timestamp + timestamp_time_relative = Time of the UTC timestamp since system start, (microseconds)
uint64 time_utc_usec		# Timestamp (microseconds, UTC), this is the timestamp which comes from the gps module. It might be unavailable right after cold start, indicated by a value of 0

So each fix is a pair of readings of one instant: timestamp + timestamp_time_relative on the boot clock, and time_utc_usec in UTC. Drop the zeros the comment warns about. In the example, 1,081 fixes put the flight controller’s boot at 14:13:11.286, so the sample lands at 14:13:11.286 + 1,132.793 s = 14:32:04.079.

Their difference is the offset from boot to UTC. Its spread across the flight’s fixes is a direct check on the bound you claim. The log’s time_ref_utc entry is no substitute: the format defines it as a UTC time offset in seconds, with -3600 as its example.¹

The anchor is not exact: PX4’s documentation says GPS time sent over serial carries “latency and jitter from serial communication”.⁴ A PPS signal captured by a hardware timer does much better.⁴ The example dataset carries ±40 ms on its flight logs.

Wall time: the companion journal

systemd’s journal stamps each entry with __REALTIME_TIMESTAMP: the wall clock at the point the journal received the entry, in microseconds since the epoch.⁵ The man page adds that it is “usually a bit later” than _SOURCE_REALTIME_TIMESTAMP, the earliest trusted timestamp of the message.⁵ This is the kill, from the example’s journal export:

{
  "__REALTIME_TIMESTAMP": "1790260324118000",
  "__MONOTONIC_TIMESTAMP": "1152904000",
  "_BOOT_ID": "9b2e4c1d0f8a4e57b3c2a1d9e8f7c6b5",
  "_HOSTNAME": "uas04-orin",
  ...
  "MESSAGE": "Out of memory: Killed process 2213 (perception_node) total-vm:11873248kB, anon-rss:6823516kB, file-rss:10240kB, shmem-rss:0kB, UID:1001 pgtables:14720kB oom_score_adj:0"
}

1790260324118000 µs after the epoch is 14:32:04.118 UTC. The same entry carries __MONOTONIC_TIMESTAMP, 1,152.904 s on the companion’s monotonic clock, which the man page says to combine with _BOOT_ID.⁵ On the flight controller’s clock, the same instant is boot + 1,132.832 s.

Wall time is only as good as the clock under it, and on the companion chrony disciplines that clock. chronyc tracking displays the clock’s performance, and its Leap status reads Normal, Insert second, Delete second or Not synchronised.⁶ If it reads Not synchronised, the journal has no anchor and belongs on its own clock.

System time     : 0.000006523 seconds slow of NTP time
...
Root delay      : 0.013639022 seconds
Root dispersion : 0.001100737 seconds
...
Leap status     : Normal

The same manual gives an absolute bound on the clock error, assuming the stratum-1 computer at the top of the chain is correct:⁶

clock_error <= |system_time_offset| + root_dispersion + (0.5 * root_delay)

On the manual’s example output, that is 0.0000065 + 0.0011007 + 0.5 × 0.0136390 s, about 7.9 ms.⁶ In INC-0142, chrony was synchronized with an offset of −1.8 ms, and the dataset carries ±6 ms on the journal.

Arrival time: the ground receive log

The receiver at range control stamps each MAVLink message when it arrives, on a clock kept by NTP. In the example that clock is good to ±15 ms, but only for arrival. Departure is earlier by the link latency, which on this run was 96 ms at the median and 412 ms at the 95th percentile.

Each record says what arrived, from which system, and when it arrived. This is the last heartbeat from UAS-04 before the gap:

{
  "recv_utc": "2026-09-24T14:32:03.912Z",
  "mono_ns": 12805145901122,
  "link": "mesh0",
  "sysid": 4,
  "compid": 1,
  "msgid": 0,
  "msg": "HEARTBEAT",
  "seq": 204,
  "len": 9
}

It arrived at 14:32:03.912. Allow 412 ms of latency and 15 ms of clock error, and it left the vehicle between 14:32:03.485 and its arrival. The bracket is lopsided, because latency only ever moves departure earlier.

When the order is unknown

Put two events from different sources on one axis, and give each its source’s bound. They have a supported order only when they sit farther apart than the two bounds added together. Closer than that, either could have come first.

The stall and the kill fail that test. They are 39 ms apart, and their combined bound is 40 + 6 = 46 ms. The flight log sample could be as late as 04.119 and the kill as early as 04.112, so for 7 ms either order fits.

The order matters. If the stream stalled first, something stopped it while perception_node was still alive; if the kill came first, the kill explains the stall. The example’s report takes neither side: “Their order is not claimed.”

The same test puts other pairs in order. mavlink-router.service stopped at 14:32:04.152 on the journal, and the next heartbeat was due at range control at 14:32:04.912. That is 760 ms apart against a bound of 6 + 15 + 412 = 433 ms, so the order holds.

Carry the bound with every event

None of this needs new sensors. It needs every event stored with its clock, its anchor and its bound, instead of a bare UTC time.

1. Anchor the flight log from sensor_gps. Drop fixes where time_utc_usec is 0. With no fix at all, the log has boot time only.
2. Record chronyc tracking on the companion. Capture it before and after each run. If Leap status reads Not synchronised, keep the journal on its own clock.
3. Treat receive times as arrival. Carry latency as a one-sided term, from a percentile you measured on that link.
4. Compare before you write “then”. If two events sit inside their combined bound, the report says “order unknown”.

This is how Foxborne aligns sources: each gets a clock, an anchor and an error bound. A source that cannot be anchored stays on its own clock, and the timeline shows exactly where the evidence stops.