[systemd-devel] Plot time data anomalies

[Joshua Zivkovic]

On Wed, 2023-01-11 at 13:54 +0100, Lennart Poettering wrote:
> On Mi, 11.01.23 13:31, Lennart Poettering (lennart at poettering.net)
> wrote:
> 
> > On Mi, 11.01.23 11:53, Joshua Zivkovic
> > (joshua.zivkovic at codethink.co.uk) wrote:
> > 
> > > Hello,
> > > 
> > > I've been working on adding JSON and table output to `systemd-
> > > analyze
> > > plot`, to allow programmatic access to the data presented in the
> > > SVG
> > > produced by `systemd-analyze plot`. Whilst using this data I have
> > > noticed some irregularities in the initialisation times
> > > associated with
> > > a variety of units. It seems as though these units are being
> > > activated,
> > > deactivated and then reactivated because they have recorded
> > > deactivation times that are before the recorded activation time.
> > > 
> > > Looking at some of these units, they don't use the `Restart=`
> > > configuration so it's unusual that they are seemingly being
> > > restarted.
> > > 
> > > These irregularities are dealt with by forcing the values to some
> > > other
> > > recorded value of that unit through a series of conditions in the
> > > SVG
> > > production code.
> > > 
> > > I'm interested in whether this means that the times for unit
> > > initialisation, presented by `plot`, aren't entirely accurate and
> > > if
> > > there is anything that can be done about this.
> > 
> > You should read them with a grain of salt. And you should only run
> > the
> > tool shortly after booting (i.e. where there's a reasonably chance
> > no
> > service has been restarted yet). If you do it later then the data
> > is
> > going to be garbage because of the discrepancy between what we
> > actually track (startup time of most recent invocation) to what
> > people
> > might expect (startup time of first invocation).
> > 
> > Also note that services that are not referenced by anything (and
> > didn't fail) might have been unloaded (i.e. "GC'ed"), which means
> > their startup timing info is released and won't show up in the
> > displayed data either.
> 
> I added some explanatory docs for this now, in this PR:
> 
> https://github.com/systemd/systemd/pull/26019
> 
As a comment points out, what happens if a unit gets stopped and
started during boot? This is what I noticed in the time data, some
units are being stopped and started again during boot, not afterwards.

I see the obvious implications of recording multiple activation and
deactivation times for a unit during boot, but this would be useful for
debugging.