Wraparound problems with time.clock() on Linux

[Fernando Perez]

Hi all,

I wrote the following simple code to take some timing information along the
way as some very cpu-intensive code executes:

#cut-----------------------------------------------------------------------

import time

class Timer:
    """Stopwatch-like class to take timings during code execution.

    It is not meant to be an ultra-accurate tool, since it doesn't calibrate
    its own overhead.  But it will work well for timing reasonably
    long-running codes."""

    def __init__(self):
        """Return a new timer."""
        self.clock = time.clock
        self.start = self.clock()
        self.times = [self.start]
        self.splits = [0]
        self.tagged_splits = []

    def split(self,tag=None):
        """Take a split time reading."""
        self.times.append(self.clock())
        self.splits.append(self.times[-1]-self.times[-2])
        if tag:
            self.tagged_splits.append((tag,self.splits[-1]))

    def split_print(self,tag=None):
        """Take a split and print it."""

        self.split(tag)
        if tag is None:
            print "Last split timing: %s CPU seconds." % self.splits[-1]
        else:
            print "Split timing for <%s>: %s CPU seconds." % \
(tag,self.splits[-1])

    def print_tagged_splits(self):
        """Print a formatted table of all tagged splits."""
        print 'Summary of tagged splits (in CPU seconds)'
        print '-----------------------------------------'
        for tsplit in self.tagged_splits:
            print '%s: %s s' % tsplit
            
    def last_split(self):
        """Return the last split."""

        return self.splits[-1]

    def total(self):
        """Return total time elapsed since timer's creation."""
        return self.clock() - self.start

#/cut----------------------------------------------------------------------

The problem I am having is that in certain long runs, I get negative values
for the total() function.  I was wondering if there are wraparound issues I
should be aware of.  Here is an example of the output from two different
runs of my code:

This one was ok:
    CPU total: 831.26 s
    Splits   :
        build rho -> 683.73 s
        build sep Coul -> 0.24 s
        apply sep Coul -> 119.92 s
        build mra Coul -> 0.02 s
        apply mra Coul -> 19.21 s
        build plot arrays -> 8.11 s
        saving plots to disk -> 0.03 s

This one, on the other hand, generated negative times.  I know (from
timestamps on files made by the code as it ran), that the code took about
50 minutes of wall time to actually execute.  Since time.clock() is
supposed to return floats, I wasn't expecting wraparound problems.


    CPU total: -1418.007296 s
    Splits   :
        build rho -> -2211.787296 s
        build sep Coul -> 0.03 s
        apply sep Coul -> 683.05 s
        build mra Coul -> 0.18 s
        apply mra Coul -> 100.78 s
        build plot arrays -> 9.7 s
        saving plots to disk -> 0.0400000000001 s


Any ideas?  For reference, this is running on a RedHat 8.0 Intel box.

Thanks for any input.

cheers,

f.