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

[kwatch]

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)

file: ostimetest.py
--------------------
import os

## benchmark function
def f(x):
if x <= 1:
return 1
else:
return f(x-1) + f(x-2)

## do benchmark
n = 35
t1 = os.times() # start time
v = f(n) # end time
print "n=%d, v=%d" % (n, v)
t2 = os.times()

## print result
utime = t2[0] - t1[0] # user time
stime = t2[1] - t1[1] # system time
print "utime=%s, stime=%s" % (utime, stime)
--------------------

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?

 

[aspineux]

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

Here my result on a linux dual AMD, python 2.4.3

# time python test.py
n=35, v=14930352
utime=22.54, stime=0.02

real 0m22.755s
user 0m22.564s
sys 0m0.022s

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=14930352
utime=22.37, stime=0.01

now you can compare what your system replied and what python
returned !

 

[Douglas Wells]

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

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.

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.

 

[aspineux]

Your analysis looks great, maybe the good arguments to report a bug ?

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

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.



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.

 

[kwatch]

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

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

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.



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.