Re: What to do about "WARNING: negative runtime; monotonic clock has gone backwards"

[Brad Spencer <brad%anduin.eldar.org@localhost>]

Taylor R Campbell <riastradh%NetBSD.org@localhost> writes:

>> Date: Thu, 20 Jul 2023 21:50:26 -0400
>> From: Brad Spencer <brad%samwise.nat.eldar.org@localhost>
>> 
>> With a DOMU kernel compiled with KDTRACE_HOOKS I get the following with
>> either of those dtrace probes on the DOMU:
>> 
>> dtrace -n 'sdt:xen:clock:, sdt:xen:hardclock:, sdt:xen:timecounter: { printf("%d %d %d %d %d %d %d", arg0, arg1, arg2, arg3, arg4, arg5, arg6, arg7) }'
>> dtrace: invalid probe specifier sdt:xen:clock:, sdt:xen:hardclock:, sdt:xen:timecounter: { printf("%d %d %d %d %d %d %d", arg0, arg1, arg2, arg3, arg4, arg5, arg6, arg7) }: "/usr/lib/dtrace/psinfo.d", line 46: syntax error near "u_int"
>
> Can you please file a PR about that, and pass `-x nolibs' to dtrace in
> the mean time?
>
> dtrace -x nolibs -n 'sdt:xen:clock:...'

[trying again... the attachments were apparently too large]

Some initial results...


I set up a -current DOMU running in normal PV mode.  The userland is
9.x and the kernel is a custom build adding KDTRACE_HOOKS but is
otherwise XEN3_DOMU.

I used this probe:

dtrace -x nolibs -n 'sdt:xen:clock:, sdt:xen:hardclock:, sdt:xen:timecounter: { printf("%d %d %d %d %d %d %d %d", arg0, arg1, arg2, arg3, arg4, arg5, arg6, arg7) }'

Note that the initial probe I was presented with either was missing a %d
or had too many arguments.  The above balances out the %d and argument
in what I suspect should be the proper way.

This first result is:

http://anduin.eldar.org/~brad/dtrace_neg/d2_idle.out

This is the above dtrace probe running on the system when it is mostly
idle.

The second result is:

http://anduin.eldar.org/~brad/dtrace_neg/d2_working.out

This is the dtrace probe running when the system was made to be busy
doing three world builds of the NetBSD tree.  Each build was allowed to
use 2 processors.  If you look at the xentop output on the DOM0 it will
be noted that the guest is almost always 199% or 200% busy as was
intended.  The system was rebooted and the artifact area for the builds
cleared out before this run.

There is a third result that was generated to get the dtrace working.
The system was busy doing builds at the time, but probably had been
doing that longer than the "working" result mention above.  This initial
result caught some hardclock miss events that I have not seen again
(although apparently vmstat -e did).  This result has only 6 of the 7
arguments in it as I was trying to work out what was wrong with the
probe.

http://anduin.eldar.org/~brad/dtrace_neg/d2_initial.out


At no time, so far, has the system reported the 'WARNING: negative
runtime...' message.  With a 9.x kernel, I can usual get though a small
number of builds and when the system is idle after that, the message is
generated.



-- 
Brad Spencer - brad%anduin.eldar.org@localhost - KC8VKS - http://anduin.eldar.org