Problem with time.time() standing still

[Bob Cowdery]

Hopefully somebody can add the last piece of this puzzle. My code didn't 
work because I did make a silly mistake. The number of seconds since 
EPOC is a large number but it also needs a high precision. Attempting to 
put this value into a 32 bit float corrupts the least significant part 
because 24 bits  cannot hold that precision. Now Python floats are C 
doubles and the calculation in timemodule.c is in doubles right back to 
Python. Normally this retains the precision. For some inexplicable 
reason when I make certain calls into this vendors SDK, ftime()  is 
getting precision problems and appears to be frozen as a result.

C, only supporting early binding cannot change the function referenced 
at runtime so how the devil is it managing to do this.

On 08/05/2012 12:17, Bob Cowdery wrote:
> 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
>>
>>
>>
>