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
Sent: Wednesday, July 3, 2019 2:30 AM
To: Sam Gilson
Cc: systemd-devel@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-sag...@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
___
systemd-devel mailing list
systemd-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/systemd-devel
