Re: In DTrace, why does timestamp increase after a call to chill() but vtimestamp and walltimestamp do not?

On Wed, Nov 23, 2022 at 09:07:23AM -0500, Mark Johnston wrote:
> On Mon, Nov 21, 2022 at 06:19:16PM +0100, Mateusz Piotrowski wrote:
> > Hello all,
> > 
> > I'd like to understand why calling chill() in a DTrace action block increases the timestampvariable, but not vtimestamp and walltimestamp.
> > Here's an example showing timestamp increasing after a call to chill():
> 
> I think you found a bug in dtrace.  When a dtrace probe fires and
> actions attached to that probe are executed, the value of *timestamp is
> cached in a struct dtrace_mstate on the firing CPU's stack.  This means
> that in D, within a probe body, multiple accesses of *timestamp will
> return the same cached value.
> 
> As it turns out, the implementation of chill() will invalidate that
> cached value, but only for "timestamp", not for walltimestamp, which
> seems incorrect.  Below is an untested patch which should fix your
> example.

I tested this and found that it isn't sufficient.  Even if we re-read
the walltimestamp value, it is usually the same before and after a
chill().  The reason is that walltimestamp returns the last saved
timecounter value rather than querying the timecounter directly and so
is not very precise.  This cannot be changed without violating the
invariant that DIF execution cannot invoke code that is not part of
dtrace itself.  Otherwise, reading walltimestamp could cause a probe to
fire.

It is possible that a timer interrupt on a different CPU will update the
timehands during a chill() and so the probe will see different values
before and after, but whether or not this happen is up to chance.  So, I
think you examples behave as expected, even though the results are a bit
unintuitive.

> I think the behaviour of vtimestamp that you observe is expected.  From
> the description, "The counter does not include the time that is spent in
> DTrace predicates and actions", so I wouldn't expect it to advance while
> dtrace_probe() is running.  And indeed, it gets advanced once at the
> beginning of dtrace_probe().