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

[kwatch at gmail.com]

Thank you, aspineux and Douglas.

Douglas's analysis is especially great.
I changed HZ to CLK_TCK in Python-2.5/Modules/posixmodule.c and
got the proper result!

  ====================
  $ time /usr/local/python2.5/bin/python ostimetest.rb
  n=35, v=14930352
  utime=12.42, stime=0.04

  real    0m13.621s
  user    0m12.438s
  sys     0m0.063s
  ====================

Great job, Douglas.

--
regards,
kwatch


s... at signature.invalid (Douglas Wells) wrote:
> [various posting problems corrected and response interspersed in
> previous post for purposes of coherent response]
>
> In article <1170446796.156141.201... at v33g2000cwv.googlegroups.com>,
>
>
>
> "aspineux" <aspin... 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-                     .