result of os.times() is different with 'time' command

[Douglas Wells]

[various posting problems corrected and response interspersed in
previous post for purposes of coherent response]

In article <1170446796.156141.201960 at v33g2000cwv.googlegroups.com>,
"aspineux" <aspineux at gmail.com> writes:
> On 2 Feb, 19:30, kwa... at gmail.com wrote:
> > Hi,
> >
> > I have a question about os.times().
> > os.times() returns a tuple containing user time and system time,
> > but it is not matched to the result of 'time' command.
> > For example, os.times() reports that user time is 39.85 sec,
> > but 'time' command reports that user time is 28.55sec.
> > (machine: Python2.5, MacOS X 10.4 Tiger, MacBook 1.83GHz intel core
> > duo)
> >
> >   [ source elided ]
> 
> I dont see anything wrong !
> Did you try to measure time with your watch ?
> Did you try a simple python test.py without the time command ?
> Maybe python is 'disturbed' by the intel core
> 
> can you try this ?
> 
> # strace python test.py  2>&1 | grep time
> times({tms_utime=1, tms_stime=1, tms_cutime=0, tms_cstime=0}) =
> 430217777
> times({tms_utime=2238, tms_stime=2, tms_cutime=0, tms_cstime=0})  = 430220049
> write(1, "n=35, v=14930352\nutime=22.37, st"..., 41n=35, v=14930 52
> utime=22.37, stime=0.01

Note that this likely won't work.  First, strace is not native to
OS X; ktrace is the analogous native command.  Second, OS X almost
certainly implements the times system call in terms of getrusage.

> >   Result:
> >   ====================
> >   $ python -V
> >   Python 2.5
> >   $ time python ostimetest.py
> >   n=35, v=14930352
> >   utime=39.85, stime=0.216666666667
> >   real    0m28.554suser    0m23.938ssys     0m0.177s
> >   ====================
> >
> > This shows that os.times() reports that user time is 39.85sec,
> > but time command shows that user time is 23.938sec.
> > Why os.times() reports wrong result? Do I have any mistake?
> >
> > --
> > kwatch

Yes, I can reproduce this on my FreeBSD system.  No, I do not believe
that you have made a mistake.  Yes, I believe that you have uncovered
a bug in the Python os/posix modules.

Here's my analysis (although I should note that I've not looked
at the source of Python previously).  I'm looking at Python 2.4.3,
but this looks like a long existing bug:

The following code exists in the source code module
Modules/posixmodule.c @ posix_times:
        struct tms t;
        clock_t c;
        [ ... ]
        c = times(&t);
                [ ... ]
        return Py_BuildValue("ddddd",
                             (double)t.tms_utime / HZ,
                             (double)t.tms_stime / HZ,
                             (double)t.tms_cutime / HZ,
                             (double)t.tms_cstime / HZ,
                             (double)c / HZ);
This is incorrect.  It should not be dividing by HZ, but by the
result of the dynamic value 'sysconf (_SC_CLK_TCK)'.  Even if
it were to use a compile time value, the proper value would be
CLK_TCK, not HZ.

So here's what's happening.  Neither my FreeBSD nor the OP's Mac
defines HZ as a compile time variable, but the same source module
also contains the following code:
        #ifndef HZ
        #define HZ 60 /* Universal constant :-) */
        #endif /* HZ */
So, the Python posix module is using 60 instead of the proper
value, which happens to be 128 on my FreeBSD, and 100 on the OP's
OS X(*).  (BTW, this sort of historic code is exactly why POSIX
no longer defines HZ.)

In support of this, I note that the following ratios exist:
  user time from os.times / user time from time command
                    39.85 / 23.938 => 1.665
                      CLK_TCK / HZ
                          100 / 60 => 1.667
which are in reasonably close agreement!

 - dmw

[*] I've actually only looked at OS X for the PPC platform, not
for the User's Intel platform, but I'm fairly certain that the
CLK_TCK value is the same on both.

-- 
.   Douglas Wells             .  Connection Technologies      .
.   Internet:  -sp9804- -at - contek.com-                     .