Havard.Eidnes@runit.sintef.no writes:
> Hi,
> 
> I've found at least one explanation to why the ru_utime time
> returned by getrusage() isn't monotonically increasing.
> 
> The basic problem is that the implementation of getrusage() pretends
> to have more resolution in the resource accounting than what is
> actually the case...
> 
> The process accounting is done in 'ticks', and each tick is counted
> as either "user time", "system time" or "interrupt time" (the latter
> is always zero on at least NetBSD/i386 and NetBSD/hp300).
> 
> calcru() inside /sys/kern/kern_resource.c shows what is going on.
> It sums up how much time this process has used, sums up the ticks,
> and distributes the total time over the ticks.  Thus, if you get a
> clock tick accounted to system time and at the same time not one to
> user time and the total time consumed hasn't changed much, the user
> time proportion can decrease.

Ahh.. Yup, I believe that's correct. 
Allow me to attempt to do a little of the math (which I probably shouldn't be 
doing thisafternoon, as my brain is already mush, but here goes anyways...)
For those who care to follow along, and/or make sure I'm not completely off 
track, the relevant code is calcru() in /src/sys/kern/kern_resource.c.
Apologies for the length of this post, but I'm hoping this analysis will be 
useful... 

Say we are at the *end* of the current timeslice, but the tick counters and 
such have *NOT* been updated:

  st=80
  ut=20
  it=0
  tot=100
  rtime.tv_sec=1
  rtime.tv_usec=0

(I hope that's right... 100 ticks total, at 100 ticks/second is 1 second)
At this point (the end of the quantum), the number of usecs run should be 
equal to (at most) 1/100 of a second, so that's 10000 usecs.

 Thus we get:

 sec = rtime.tv_sec + (tv.tv_sec - runtime.tv_sec) = 1 + 0 = 1
 usec = rtime.tv_usec + (tv.tv_usec - runtime.tv_usec) = 0 + 10000 = 10000
 u = sec * 1000000 + usec = 1 * 1000000 + 10000 = 1010000
 st = (u * st) / tot = (1010000 * 80) / 100 = 808000
 ut = (u * ut) / tot = (1010000 * 20) / 100 = 202000

and hence:
 sp->tv_sec = 0
 sp->tv_usec = 808000
 up->tv_sec = 0
 up->tv_usec = 202000

So that's at the *end* of the quantum, and *before* the tick counters have 
been updated.  
Now consider that the quantum is done, and we update one of the tick counters 
(lets say it was p_sticks that was updated, for sake of argument) and the 
amount of accumulated running time.  Our updated values are now:

  st=81
  ut=20
  it=0
  tot=101
  rtime.tv_sec=1
  rtime.tv_usec=10000  

At the very beginning of this quantum, we have:
(Note that both (tv.tv_sec - runtime.tv_sec) and (tv.tv_usec - 
runtime.tv_usec) are 0 -- might not be very likely, but it's worst-case...)

 sec = rtime.tv_sec + (tv.tv_sec - runtime.tv_sec) = 1 + 0 = 1
 usec = rtime.tv_usec +  = 10000 + 0 = 10000

 u = sec * 1000000 + usec = 1 * 1000000 + 10000 = 1010000
 st = (u * st) / tot = (1010000 * 81) / 101 = 810000
 ut = (u * ut) / tot = (1010000 * 20) / 101 = 200000

Woah!!! what's this?? Our "ut" value is now 200000, which is 2000 usec
*LOWER* than what it was before...  Thus our user resource usage time appears 
to have actually decreased...  

Thus unless I'm very much wrong somewhere above it would appear quite possible 
to end up with the "erratic" usage times that I've been seeing...

I'm not sure if/how this can be fixed, except perhaps by adjusting "st" or 
"ut" to the appropriate value once the time used (tv.tv_usec - 
runtime.tv_usec) is greater than 1/2 of the time it takes to complete the 
quantum (or get to the next "tick").  "better" still would be to weight the 
values of "st" or "ut" as to how far through the quantum the measurement is 
being taken.  All of this just gets plain ugly though...

> For a while I thought that the sum of the system time and the user
> time would monotonically increase, but that appears not to be the
> case either, at least on NetBSD/hp300. 

Now that's *really* curious... Even with my math above I'd expect the sum of 
the two to be the same... That certainly does point to "something else" 
contributing to the problem...

> I tweaked your original
> program and ran it for a while, and suddenly it printed:
> 
> 0 + 303763
> 0 + 305256
> 0 + 306344
> 0 + 297427
> Decreasing time: 0 + 306344 vs 0 + 297427
> 0 + 299611
> 0 + 300696
> 0 + 301752
> 
> The tweaked program can be found below.

Hmm.. I've run that program a number of times, and have been unable 
to get this behaviour... (I suspect it's something to do with the nature 
of the "bug"(s)...)

> Strange...  I wonder: can it be that microtime() and thus
> gettimeofday() isn't always monotonically increasing? (...)  Yep,
> that appears to be the problem.  It appears that NetBSD/hp300's
> microtime is slightly broken, I get lots of these from my test
> program which I've included below when I run it on one of our
> hp433's:
> 
> Whoa! Decreasing time: 880054445 + 499972 vs 880054445 + 490000
> Whoa! Decreasing time: 880054445 + 529972 vs 880054445 + 520000
> Whoa! Decreasing time: 880054446 + 149972 vs 880054446 + 140000
> Whoa! Decreasing time: 880054447 + 779972 vs 880054447 + 770000
> Whoa! Decreasing time: 880054448 + 279972 vs 880054448 + 270000
> Whoa! Decreasing time: 880054448 + 299972 vs 880054448 + 290000

I see much the same thing on our hp300's.. 

> Oh, well, more work for our beloved portmaster, I think... (Yes,
> I've UTSL'ed /sys/arch/hp300/hp300/clock.c, but the source isn't
> quite with me today, I think...  ;-)

:-) I havn't made it out of calcru() yet... microtime() may be this 
evenings project, if I get some other stuff taken care of first...

> Anyway, this latter problem with gettimeofday() returning non-
> monotonically increasing values doesn't appear to exist on either of
> NetBSD/sparc, NetBSD/i386, NetBSD/pmax(1.2) or NetBSD/vax.

Later...

Greg Oster

oster@cs.usask.ca
Department of Computer Science
University of Saskatchewan, Saskatoon, Saskatchewan, CANADA