Problem with time.time() standing still

[Bob Cowdery]

Can anyone make sense of this.

I've looked over the Python timemodule.c again and it uses one of 
gettimeofday(), ftime() or time(). The gettimeofday() is not available 
on Windows so its going to use ftime() or time(). As time() only has a 
resolution of 1 second and returns a long and I know Python time.time() 
has a ms resolution it must be using ftime().

After going round the houses - a lot. I've made a trivially simple 
extension that goes wrong. I can only think I must be doing something 
incredibly stupid. Perhaps someone can put me out of my misery.

In the full app what happens is that it reports the correct time as 
given by time() by gets the ms from somewhere also. When it goes wrong 
it reports the same time as ftime().

Bob

 >>> import mytime
 >>> mytime.doTime()
TIME : 1336474857
FTIME secs 1336474880.000000
FTIME ms 0.601000
FTIME secs+ms 1336474880.601000
0
 >>> mytime.doTime()
TIME : 1336474871
FTIME secs 1336474880.000000
FTIME ms 0.548000
FTIME secs+ms 1336474880.548000
0
 >>> mytime.doTime()
TIME : 1336474897
FTIME secs 1336474880.000000
FTIME ms 0.007000
FTIME secs+ms 1336474880.007000
0

The extension just prints out the time as got from time() and ftime(). 
For a start the two do not agree on what the time is. Secondly ftime() 
stops incrementing while the python session is running. If I start a new 
session it will have incremented.

 >>> import mytime
 >>> mytime.doTime()
TIME : 1336475029
FTIME secs 1336475008.000000
FTIME ms 0.265000
FTIME secs+ms 1336475008.265000
0

Code and build file
================

#include "Python.h"
#include <sys/types.h>
#include <stdio.h>
#include <time.h>
#include <sys/timeb.h>

static struct timeb t;
static float secs = 0.0;
static float ms = 0.0;
static float both = 0.0;

static PyObject *doTime(
                 PyObject *self,
                 PyObject *args) {
         time_t seconds;
     seconds = time (NULL);
     printf ("TIME : %ld\n", seconds);
         ftime(&t);
         secs = (float)t.time;
         ms = (float)((float)t.millitm * 0.001);
         printf("FTIME secs+ms %f\n",  secs + ms);

     return PyInt_FromLong((long)0);
}

static PyMethodDef pyInst_Methods[] = {

         {"doTime",
             doTime,
             METH_VARARGS},
         {NULL, NULL, 0, NULL}
};

#ifndef PyMODINIT_FUNC
#define PyMODINIT_FUNC void
#endif /* PyMODINIT_FUNC */

PyMODINIT_FUNC initmytime(void)
{
     PyObject *module;
     module = Py_InitModule3("mytime", pyInst_Methods,"Time module");
     if (!module) return;
}

Build file
========
import os
from distutils.core import setup
from distutils.extension import Extension

if os.path.exists('C:\\Program Files (x86)'):
     # 64 bit
     ProgramFiles = 'Program Files (x86)'
else:
     # 32 bit
     ProgramFiles = 'Program Files'

setup(
     name='Time Test',
     author='Bob Cowdery',
     ext_modules = [
         Extension('mytime',
                     ['pytime.cpp'],
                     include_dirs = ['C:\\' + ProgramFiles + 
'\\Microsoft SDKs\\Windows\\v7.0A\\Include', 'C:\\Python26\\include'],
                     #define_macros = [("_AFXDLL", None)],
                     library_dirs = ['C:\\' + ProgramFiles + 
'\\Microsoft SDKs\\Windows\\v7.0A\\Lib', 'C:\\Python26\\libs'],
                     libraries = ['User32', 'Gdi32', 'python26', 
'odbc32', 'odbccp32']
         )
     ]
)

On 06/05/2012 10:19, Bob Cowdery wrote:
> On 06/05/2012 09:49, Cameron Simpson wrote:
>> On 06May2012 09:18, Bob Cowdery<bob at bobcowdery.plus.com>  wrote:
>> | On 05/05/2012 23:05, Cameron Simpson wrote:
>> |>  On 05May2012 20:33, Bob Cowdery<bob at bobcowdery.plus.com>  wrote:
>> |>  | [...] calls to time.time() always return the same
>> |>  | time which is usually several seconds in the past or future and always
>> |>  | has no fractional part.
>> |>
>> |>  Thought #1: you are calling time.time() and haven't unfortunately
>> |>  renamed it? (I doubt this scenario, though the lack of fractional part
>> |>  is interesting.)
>> |
>> | Not sure what you mean by renamed it.
>>
>> Like this:
>>
>>    from time import time
>>    [...]
>>    time = some_unfortunate_other_function
>>    [...]
>>    now = time()  # calls wrong function
>>
>> It seems unlikely, but possible.
>>
>> | I also tried datetime and that had
>> | the same behaviour.
>>
>> Makes my suggestion even less likely unless the time module itself gets
>> monkeypatched (i.e. "time.time = bad_function" somewhere).
> I don't think the function is subverted unless there is some way inside
> the vendor SDK or even DirectShow (the SDK uses this as a COM object)
> which can somehow hijack it. It does catch up every few minutes so there
> has to be a clue there.
>> |>  | If I leave it long enough time will suddently
>> |>  | jump forward after a few minutes, then again after a few minutes more.
>> |>  |
>> |>  | I've never encountered this behaviour before and can't understand what
>> |>  | on earth is going on. If I call the 'C' time() function just the other
>> |>  | side of my call to the extension the time is ticking along fine. It's
>> |>  | just the one Python thread that is affected.
>> |>  [...]
>> |>
>> |>  Thought #2: On a UNIX system I'd be running the process under strace (or
>> |>  dtrace or ktrace depending on flavour) to see what actual OS system calls are
>> |>  being made during this behaviour. Is this feasible for you?
>> |
>> | I'm on Windows for this particular part of the application.
>>
>> I'd guessed so. I've no Windows programming background; I was wondering
>> if there was something like this you had to hand on windows.
> Maybe, but not that I know of.
>> | [...] But debugging into this is probably the only way. I
>> | looked at the built-in time module. As far as I can tell it just calls
>> | the underlying C time() function as an extension. This is more
>> | mystifying as that is pretty much what I'm doing by checking the time in
>> | my own extension module where it ticks along fine.
>>
>> Hmm. A C extension I presume? How about writing a little pure Python
>> thread to call time.time(), and spin it off parallel to the rest of the
>> app; does it also get bad time.time() behaviour?
> I've tried that. It's only the Python thread (or Python main thread)
> that calls the extension that behaves like this. Other Python threads
> tick along fine with the correct time including a fractional part.
>> | I have another
>> | scenario using a different part of their SDK where the time does still
>> | tick but the fractional part is frozen, not 0 but frozen.
>>
>> Curiouser and curiouser.
> Indeed. Away now but battle will resume on Tuesday.
>
> Bob
>
>
>