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

[Sam Gilson]

Thank you for the response! I don't think I did a great job asking an actual question in my last email, so let me clarify.

What I am currently trying to understand is what the differences between how  and when the different timestamps for each service are logged. The confusion comes from the fact that ExecMainStartTimestamp, according to the name, should be the timestamp for when the Main of my service gets run, but that doesn't seem to be the case. Our service emits its own timestamp when the main is run, but ExecMainStartTimestamp doesn't reflect that timestamp like it should.

My hypothesis is that is that our service loops for a long time (30 min usually) while waiting for a new DHCP lease to come in, and once that is completed, a time sync w/NTP occurs which causes the ExecMainStartTimestamp to be rewritten. Why I think this is the case is that InactiveExitTimestamp and ExecMainStartTimestamp are always off by the time spent in our loop (i.e InactiveTimestamp = X, loop takes 30 min, ExecMainStartTimestamp = X + 30). The same problem also occurs with the ActiveStartTimestamp. However, I might be completely incorrect about my hypothesis and that's why I am asking here.

Any help would be appreciated!

Best Regards,
Sam Gilson

-----Original Message-----
From: Lennart Poettering <lennart at poettering.net> 
Sent: Wednesday, July 3, 2019 2:30 AM
To: Sam Gilson <t-sagils at microsoft.com>
Cc: systemd-devel at lists.freedesktop.org
Subject: Re: [systemd-devel] Logged timestamps for service do not report correct times

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