57
votes

I want to log how long something takes in real walltime. Currently I'm doing this:

startTime = time.time()
someSQLOrSomething()
print "That took %.3f seconds" % (time.time() - startTime)

But that will fail (produce incorrect results) if the time is adjusted while the SQL query (or whatever it is) is running.

I don't want to just benchmark it. I want to log it in a live application in order to see trends on a live system.

I want something like clock_gettime(CLOCK_MONOTONIC,...), but in Python. And preferably without having to write a C module that calls clock_gettime().

5
Well I don't really know how often it's actually adjusted. I run NTP. But with a mononotic clock I won't have to run into stuff like the Oracle RAC bug where it rebooted the system if the time was set backwards. Besides small NTP adjustments there are leap seconds that can go back and forward. - Thomas
S.Lott: incorrect. "A leap second is a positive or negative one-second adjustment [...]". It's trivial to look up. It's the first sentence on the "Leap second" article on Wikipedia. So when a leap second is added, NTP will readjust you system time backwards (because your system is fast. It didn't count 23:59:60), meaning a time.time()-based measurment can be negative. Trust me, many Oracle servers rebooted due to the bug I mentioned above last newyears. And I just used Oracle as an example where some programs can't handle time readjustments. - Thomas
I don't know why (unpatched) Oracle 10 does that. It just does, and Oracle (the company) confirms it. - Thomas
Just wanted to add a comment here of a use case that we encountered. Within our setup that consists of a number of vmware systems, we have noticed that time "adjustments" do happen regularly enough in the guest vms, especially with the host's load avg. is high. This results in things like supervisord that appear to depend on time.time() crashing resulting in orphaning the processes that it started. We've ^fixed^ this issue by applying the patch - github.com/Supervisor/supervisor/pull/468 - lonetwin
@Thomas: In theory, there could be negative leap seconds. In practice, all leap seconds are positive. See The leap second: its history and possible future. - jfs

5 Answers

82
votes

That function is simple enough that you can use ctypes to access it:

#!/usr/bin/env python

__all__ = ["monotonic_time"]

import ctypes, os

CLOCK_MONOTONIC_RAW = 4 # see <linux/time.h>

class timespec(ctypes.Structure):
    _fields_ = [
        ('tv_sec', ctypes.c_long),
        ('tv_nsec', ctypes.c_long)
    ]

librt = ctypes.CDLL('librt.so.1', use_errno=True)
clock_gettime = librt.clock_gettime
clock_gettime.argtypes = [ctypes.c_int, ctypes.POINTER(timespec)]

def monotonic_time():
    t = timespec()
    if clock_gettime(CLOCK_MONOTONIC_RAW , ctypes.pointer(t)) != 0:
        errno_ = ctypes.get_errno()
        raise OSError(errno_, os.strerror(errno_))
    return t.tv_sec + t.tv_nsec * 1e-9

if __name__ == "__main__":
    print monotonic_time()
43
votes

Now, in Python 3.3 you would use time.monotonic.

9
votes

As pointed out in this question, avoiding NTP readjustments on Linux requires CLOCK_MONOTONIC_RAW. That's defined as 4 on Linux (since 2.6.28).

Portably getting the correct constant #defined in a C header from Python is tricky; there is h2py, but that doesn't really help you get the value at runtime.

4
votes

Here's how I get monotonic time in Python 2.7:

Install the monotonic package:

pip install monotonic

Then in Python:

import monotonic; mtime = monotonic.time.time #now mtime() can be used in place of time.time()
t0 = mtime()
#...do something
elapsed = mtime()-t0 #gives correct elapsed time, even if system clock changed.

EDIT: check that the above works on your target OS before trusting it. The monotonic library seems to handle clock changes in some OSes and not others.

0
votes

time.monotonic() might be useful:

Return the value (in fractional seconds) of a monotonic clock, i.e. a clock that cannot go backwards. The clock is not affected by system clock updates. The reference point of the returned value is undefined, so that only the difference between the results of consecutive calls is valid.