Login | Register For Free | Help
Search for: (Advanced)

Mailing List Archive: Python: Python

Problem with time.time() standing still

 

 

Python python RSS feed   Index | Next | Previous | View Threaded


bob at bobcowdery

May 5, 2012, 12:33 PM

Post #1 of 15 (635 views)
Permalink
Problem with time.time() standing still

Hi all,

I've been a long time user of Python and written many extensions but
this problem has me stumped.

I've written a straight forward extension that wraps a vendors SDK for a
video capture card. All works well except that in the Python thread on
which I call the extension, after certain calls that I believe are using
DirectShow, time stands still. The thread returns fine as the extension
does its stuff in its own threads. In all other respects the Python
thread seems unaffected but 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. 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. If I call from the main
thread then the main thread is affected. The calling program I've used
to test this is just a few lines long.

I believe the time function is a thin wrapper over the 'C' runtime so
its very odd that time only stands still on the Python side but not on
the 'C' side. As time is built in I've not looked at the code as its not
in the distribution. Don't know if it would help to do that.

This also can affect the time.sleep() function making it return
immediately but that only seems to happen in my full application.

Any ideas would be very greatly received.

Bob
--
http://mail.python.org/mailman/listinfo/python-list


danyellawson at gmail

May 5, 2012, 1:17 PM

Post #2 of 15 (623 views)
Permalink
Re: Problem with time.time() standing still [In reply to]

Add a time.sleep(0) call to all your loops. Multithreading in Python
is a cooperative cross platform threading simulation if you have tight
loops Python won't task switch until you make a system call.
Potentially preventing internal library variables from being updated.

Your five minute interval may be almost exactly how long it takes to
process a flooded queue in a tight loop in your program and it may be
why it continues to happen as the queue waits to fill again while
processing happens.

You can simulate the progression of time by overriding the time.time
function by simply setting it to a function that just increments a
module level or function property variable. You can also override the
time.time function to return the posix time function's value to maybe
get around whatever optimization is happening in the time.time
function to pass back the same value.

If you post your sample code that exhibits the same behavior it may be
obvious to someone on the list as to what is the problem.



On Sat, May 5, 2012 at 3:33 PM, Bob Cowdery <bob [at] bobcowdery> wrote:
> Hi all,
>
> I've been a long time user of Python and written many extensions but
> this problem has me stumped.
>
> I've written a straight forward extension that wraps a vendors SDK for a
> video capture card. All works well except that in the Python thread on
> which I call the extension, after certain calls that I believe are using
> DirectShow,  time stands still. The thread returns fine as the extension
> does its stuff in its own threads. In all other respects the Python
> thread seems unaffected but 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. 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. If I call from the main
> thread then the main thread is affected. The calling program I've used
> to test this is just a few lines long.
>
> I believe the time function is a thin wrapper over the 'C' runtime so
> its very odd that time only stands still on the Python side but not on
> the 'C' side. As time is built in I've not looked at the code as its not
> in the distribution. Don't know if it would help to do that.
>
> This also can affect the time.sleep() function making it return
> immediately but that only seems to happen in my full application.
>
> Any ideas would be very greatly received.
>
> Bob
> --
> http://mail.python.org/mailman/listinfo/python-list
--
http://mail.python.org/mailman/listinfo/python-list


bob at bobcowdery

May 5, 2012, 1:51 PM

Post #3 of 15 (633 views)
Permalink
Re: Problem with time.time() standing still [In reply to]

Thanks Daniel, that's interesting. Unfortunately there is no sensible
code I can post because this only happens when I make a specific call
into the vendors SDK. I can exercise my own code in the extension
without a problem. The python test calling code is doing practically
nothing. I make 3 calls to the extension to set things going and then
loop every 5 seconds and print the time. I know Pythons own threading
model is cooperative because of the GIL and therefore one thread can hog
the show but I've never had issues with threads running in a C extension
messing up a Python thread. I really need to understand what mechanism
is at play here rather than work around it.

Bob

The time.clock() function does increment correctly. CPU is around 30%
On 05/05/2012 21:17, Danyel Lawson wrote:
> Add a time.sleep(0) call to all your loops. Multithreading in Python
> is a cooperative cross platform threading simulation if you have tight
> loops Python won't task switch until you make a system call.
> Potentially preventing internal library variables from being updated.
>
> Your five minute interval may be almost exactly how long it takes to
> process a flooded queue in a tight loop in your program and it may be
> why it continues to happen as the queue waits to fill again while
> processing happens.
>
> You can simulate the progression of time by overriding the time.time
> function by simply setting it to a function that just increments a
> module level or function property variable. You can also override the
> time.time function to return the posix time function's value to maybe
> get around whatever optimization is happening in the time.time
> function to pass back the same value.
>
> If you post your sample code that exhibits the same behavior it may be
> obvious to someone on the list as to what is the problem.
>
>
>
> On Sat, May 5, 2012 at 3:33 PM, Bob Cowdery <bob [at] bobcowdery> wrote:
>> Hi all,
>>
>> I've been a long time user of Python and written many extensions but
>> this problem has me stumped.
>>
>> I've written a straight forward extension that wraps a vendors SDK for a
>> video capture card. All works well except that in the Python thread on
>> which I call the extension, after certain calls that I believe are using
>> DirectShow, time stands still. The thread returns fine as the extension
>> does its stuff in its own threads. In all other respects the Python
>> thread seems unaffected but 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. 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. If I call from the main
>> thread then the main thread is affected. The calling program I've used
>> to test this is just a few lines long.
>>
>> I believe the time function is a thin wrapper over the 'C' runtime so
>> its very odd that time only stands still on the Python side but not on
>> the 'C' side. As time is built in I've not looked at the code as its not
>> in the distribution. Don't know if it would help to do that.
>>
>> This also can affect the time.sleep() function making it return
>> immediately but that only seems to happen in my full application.
>>
>> Any ideas would be very greatly received.
>>
>> Bob
>> --
>> http://mail.python.org/mailman/listinfo/python-list

--
http://mail.python.org/mailman/listinfo/python-list


cs at zip

May 5, 2012, 3:05 PM

Post #4 of 15 (619 views)
Permalink
Re: Problem with time.time() standing still [In reply to]

On 05May2012 20:33, Bob Cowdery <bob [at] bobcowdery> wrote:
| I've written a straight forward extension that wraps a vendors SDK for a
| video capture card. All works well except that in the Python thread on
| which I call the extension, after certain calls that I believe are using
| DirectShow, time stands still. The thread returns fine as the extension
| does its stuff in its own threads. In all other respects the Python
| thread seems unaffected but 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.)

| 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?

Cheers,
--
Cameron Simpson <cs [at] zip> DoD#743
http://www.cskk.ezoshosting.com/cs/

A slipping sear could let your M203 grenade launcher fire when you least
expect it. That would make you quite unpopular in what's left of your unit.
- page 9 of the August 1993 issue of PS magazine, the US Army's
preventive maintenance magazine
--
http://mail.python.org/mailman/listinfo/python-list


rosuav at gmail

May 5, 2012, 4:11 PM

Post #5 of 15 (620 views)
Permalink
Re: Problem with time.time() standing still [In reply to]

On Sun, May 6, 2012 at 6:51 AM, Bob Cowdery <bob [at] bobcowdery> wrote:
> The time.clock() function does increment correctly. CPU is around 30%

30% of how many cores? If that's a quad-core processor, that could
indicate one core completely pegged plus a little usage elsewhere.

ChrisA
--
http://mail.python.org/mailman/listinfo/python-list


bob at bobcowdery

May 6, 2012, 1:18 AM

Post #6 of 15 (615 views)
Permalink
Re: Problem with time.time() standing still [In reply to]

On 05/05/2012 23:05, Cameron Simpson wrote:
> On 05May2012 20:33, Bob Cowdery <bob [at] bobcowdery> wrote:
> | I've written a straight forward extension that wraps a vendors SDK for a
> | video capture card. All works well except that in the Python thread on
> | which I call the extension, after certain calls that I believe are using
> | DirectShow, time stands still. The thread returns fine as the extension
> | does its stuff in its own threads. In all other respects the Python
> | thread seems unaffected but 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. I also tried datetime and that had
the same behaviour.
>
> | 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. The video
SDK is Windows only. 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. 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. I'd dearly
love to know what's going on here. I thought about extracting the time
module, building it, calling it something else and seeing if it behaves
the same. All time consuming unfortunately when I have a deadline.
>
> Cheers,

--
http://mail.python.org/mailman/listinfo/python-list


bob at bobcowdery

May 6, 2012, 1:20 AM

Post #7 of 15 (618 views)
Permalink
Re: Problem with time.time() standing still [In reply to]

On 06/05/2012 00:11, Chris Angelico wrote:
> On Sun, May 6, 2012 at 6:51 AM, Bob Cowdery <bob [at] bobcowdery> wrote:
>> The time.clock() function does increment correctly. CPU is around 30%
> 30% of how many cores? If that's a quad-core processor, that could
> indicate one core completely pegged plus a little usage elsewhere.
It is a quad core but no CPU is pegged as there are a number of threads
running in C. It's reasonably well spread.
>
> ChrisA

--
http://mail.python.org/mailman/listinfo/python-list


rosuav at gmail

May 6, 2012, 1:24 AM

Post #8 of 15 (616 views)
Permalink
Re: Problem with time.time() standing still [In reply to]

On Sun, May 6, 2012 at 6:18 PM, Bob Cowdery <bob [at] bobcowdery> wrote:
> On 05/05/2012 23:05, Cameron Simpson wrote:
>> 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. I also tried datetime and that had
> the same behaviour.

In Python, names are nothing special, so you could do something like:

time.time = lambda: 142857

which means that time.time() will forever return that constant.

Take a snapshot of time.time early in your code somewhere, and try
using that instead, just in case. It's a long shot but might save you
some insanity!

ChrisA
--
http://mail.python.org/mailman/listinfo/python-list


cs at zip

May 6, 2012, 1:49 AM

Post #9 of 15 (617 views)
Permalink
Re: Problem with time.time() standing still [In reply to]

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).

| > | 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.

| [...] 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 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.
--
Cameron Simpson <cs [at] zip> DoD#743
http://www.cskk.ezoshosting.com/cs/

As you can see, unraveling even a small part of 'sendmail' can introduce more
complexity than answers. - Brian Costales, _sendmail_
--
http://mail.python.org/mailman/listinfo/python-list


bob at bobcowdery

May 6, 2012, 2:09 AM

Post #10 of 15 (615 views)
Permalink
Re: Problem with time.time() standing still [In reply to]

On 06/05/2012 09:24, Chris Angelico wrote:
> On Sun, May 6, 2012 at 6:18 PM, Bob Cowdery <bob [at] bobcowdery> wrote:
>> On 05/05/2012 23:05, Cameron Simpson wrote:
>>> 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. I also tried datetime and that had
>> the same behaviour.
> In Python, names are nothing special, so you could do something like:
>
> time.time = lambda: 142857
>
> which means that time.time() will forever return that constant.
>
> Take a snapshot of time.time early in your code somewhere, and try
> using that instead, just in case. It's a long shot but might save you
> some insanity!
Thanks. I will try that. Away now until Monday when the battle will resume.

Bob
> ChrisA

--
http://mail.python.org/mailman/listinfo/python-list


bob at bobcowdery

May 6, 2012, 2:19 AM

Post #11 of 15 (617 views)
Permalink
Re: Problem with time.time() standing still [In reply to]

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


bob at bobcowdery

May 8, 2012, 4:17 AM

Post #12 of 15 (605 views)
Permalink
Re: Problem with time.time() standing still [In reply to]

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> 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


bob at bobcowdery

May 8, 2012, 8:42 AM

Post #13 of 15 (602 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


roel at roelschroeven

May 10, 2012, 10:06 AM

Post #14 of 15 (589 views)
Permalink
Re: Problem with time.time() standing still [In reply to]

Hi Bob,

This reminds of a problem we had at work some years ago. I've followed
the thread from the beginning, but I hadn't a clue about what could
possibly cause the problem until you said:

Bob Cowdery schreef:
> 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.

Our problem turned out to be caused by a loss of precision in an
application of ours, caused by Direct3D. The solution for us was to
include the flag D3DCREATE_FPU_PRESERVE in CreateDevice(). The
documentation seems to imply that the lower precision only has effect in
the Direct3D code, but in reality it lowers precision in the rest of the
code too (the whole process or the whole thread, I'm not sure).

In your case it seems harder to solve: as far as I understand, the
trigger is somewhere in the vendors SDK, which you have no control over.
I'm afraid I don't know what you can do about that.

Best regards,
Roel

--
"The reasonable man adapts himself to the world. The unreasonable
man persists in trying to adapt the world to himself. Therefore,
all progress depends on the unreasonable man."
-- George Bernard Shaw

roel [at] roelschroeven
http://roelschroeven.net

--
http://mail.python.org/mailman/listinfo/python-list


bob at bobcowdery

May 10, 2012, 3:10 PM

Post #15 of 15 (586 views)
Permalink
Re: Problem with time.time() standing still [In reply to]

Hi Roel

"Our problem turned out to be caused by a loss of precision in an
application of ours, caused by Direct3D. The solution for us was to
include the flag D3DCREATE_FPU_PRESERVE in CreateDevice(). The
documentation seems to imply that the lower precision only has effect in
the Direct3D code, but in reality it lowers precision in the rest of the
code too (the whole process or the whole thread, I'm not sure). "

That is spot on and very likely the cause. Thanks very much for
responding. I do have some control over the vendor and have passed that
information on to them. Hopefully they will investigate and fix the problem.

Bob
--
http://mail.python.org/mailman/listinfo/python-list

Python python RSS feed   Index | Next | Previous | View Threaded
 
 


Interested in having your list archived? Contact Gossamer Threads
 
  Web Applications & Managed Hosting Powered by Gossamer Threads Inc.