[systemd-devel] Logged timestamps for service do not report correct times

[Lennart Poettering]

On Mi, 26.06.19 16:30, Sam Gilson (t-sagils at microsoft.com) wrote:

> Hey everyone, I've got a quick question about how the timestamps
> that are gathered by systemctl are emitted by systemd. My
> organization has a service that runs fairly early in boot (timestamp
> X ), it has DHCP to an internal network (no Internet)and stays in a
> polling loop for about 30 minutes. At some point later it finishes
> polling and obtain a new DHCP lease and at this time it has access
> to the Internet (X+30min). Once the service finished we queried the
> following monotonic timestamps: InactiveExitTimestampMonotonic,
> ActiveEnterTimestampMonotonic, ExecMainStartTimestampMonotonic. The
> InactiveExit timestamp indicates the unit was started around
> Timestamp X, which is as expected. However, ActiveEnter and
> ExecMainStart seems to put it at X + 30min, despite the unit already
> started ways back at X + x (we know because this service emits its
> own log when it starts up). We are trying to figure out how each of
> these timestamps are logged, as when we disable the internal DHCP
> loop, all these timestamps have very similar values. This indicates
> to me that our DHCP loop apparently runs between when InactiveExit
> and ActiveEnter are logged, which accounts for that extra 30 minutes
> added to the ActiveEnterTimestamp. The problem that we have is that
> we need the ActiveEnterTimestampMonotonic to be reported accurately
> when the internal DHCP loop runs.

I am not sure I grok the question fully, but do note that services can
be restarted, at which time the InactiveExitTimestampMonotonic field
is of course reset. i.e. if you issue "systemctl show" after boot
completed you'll just see the data of the most recent instance
started.

The clock is directly in Linux' CLOCK_MONOTONIC timestamp, which
should be fully monotonic on each boot, and will pause when the system
is suspended.

Note that the journal always logs the boot ID (which is a uuid the
kernel assigns to each boot iteration) along with the monotonic clock
value. When the boot id changes you cannot really compare the
monotonic timestamps anymore, of course.

Lennart

--
Lennart Poettering, Berlin