bob at bobcowdery
May 8, 2012, 8:42 AM
Post #13 of 15
(322 views)
Permalink
|
|
Re: Problem with time.time() standing still
[In reply to]
|
|
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
>
> TIME : 1336474857
> FTIME secs 1336474880.000000
> FTIME ms 0.601000
> FTIME secs+ms 1336474880.601000
> 0
> TIME : 1336474871
> FTIME secs 1336474880.000000
> FTIME ms 0.548000
> FTIME secs+ms 1336474880.548000
> 0
> 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.
>
> 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> wrote:
>>> | On 05/05/2012 23:05, Cameron Simpson wrote:
>>> |> On 05May2012 20:33, Bob Cowdery<bob [at] bobcowdery> 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
>>
>>
>>
>
--
http://mail.python.org/mailman/listinfo/python-list
|
