Velocity Reviews > Re: time.sleep(1) sometimes runs for 200 seconds under windows

# Re: time.sleep(1) sometimes runs for 200 seconds under windows

Paul Probert
Guest
Posts: n/a

 02-23-2006
Peter Hansen wrote:

>Are you saying that you believe the time.sleep(1) call is actually
>blocking for 200 seconds? Or just that your loop (and we can only guess
>what it looks like) is the one taking that long?
>
>If the former, try something like putting "print 'before'" and "print
>'after'" before and after the sleep, and observe what happens when you
>run the program. I'm fairly confident in saying there's no chance
>you'll see the "before" sit for 200s before you see the "after" and that
>your problem lies elsewhere, not with time.sleep(1).
>
>
>-Peter
>
>
>

Yes, I'm doing this:
.....
oldtime=time.time()
time.sleep(1)
newtime=time.time()
dt=newtime-oldtime
if dt > 2:
print 'dt=',dt,' time=',time.strftime('%Y_%m_%d_%Hh_%Mm_%Ss')
Its happening roughly 4 times a day total on our 20 machines, ie about
once every 5 days on a given machine.

Paul Probert
University of Wisconsin

Claudio Grondi
Guest
Posts: n/a

 02-24-2006
Paul Probert wrote:
> Peter Hansen wrote:
>
>> Are you saying that you believe the time.sleep(1) call is actually
>> blocking for 200 seconds? Or just that your loop (and we can only
>> guess what it looks like) is the one taking that long?
>>
>> If the former, try something like putting "print 'before'" and "print
>> 'after'" before and after the sleep, and observe what happens when you
>> run the program. I'm fairly confident in saying there's no chance
>> you'll see the "before" sit for 200s before you see the "after" and
>> that your problem lies elsewhere, not with time.sleep(1).
>>
>> If the latter, um, obviously we can't help without more info.
>>
>> -Peter
>>
>>
>>

> Yes, I'm doing this:
> .....
> oldtime=time.time()
> time.sleep(1)
> newtime=time.time()
> dt=newtime-oldtime
> if dt > 2:
> print 'dt=',dt,' time=',time.strftime('%Y_%m_%d_%Hh_%Mm_%Ss')
> Its happening roughly 4 times a day total on our 20 machines, ie about
> once every 5 days on a given machine.
>
> Paul Probert
> University of Wisconsin
>

With such rare occurrence it is very hard to tell what is going on.
Usually I put such strange things on a list of curiosities I don't want
to know the reason of, because it is in my eyes not worth the effort.
Maybe it is even a common problem not yet detected by me, because I have
never run this kind of tests for such a long time.
Starting today, I can tell you statistically not earlier than in one
week, if I have the same problem on my machines (currently I am running
only one or two at the same time).

In between let's try to use some logic:
If the machine and the operating system are not the cause, what have all
these machines in common?
1. The software they are running (kind of not often triggered bug)
2. The network cards used (bug in hardware or drivers)
3. Another piece of hardware common to all the machines
3. The harddisks (recalibration)
4. The network router/switch and/or the server.

Claudio

Magnus Lycka
Guest
Posts: n/a

 02-24-2006
Paul Probert wrote:
> Yes, I'm doing this:
> .....
> oldtime=time.time()
> time.sleep(1)
> newtime=time.time()
> dt=newtime-oldtime
> if dt > 2:
> print 'dt=',dt,' time=',time.strftime('%Y_%m_%d_%Hh_%Mm_%Ss')
> Its happening roughly 4 times a day total on our 20 machines, ie about
> once every 5 days on a given machine.

So, it happens roughly one time out of 400 000 sleeps?

With an operating system such as Windows, this is
probably something you can expect to happen, although
I'm surprised if such long lag times as 200 s are typical.

If you need real time characteristics, you should
probably use a real time operating system, not Windows.

The operating system can schedule jobs as it likes,
and your sleep is obviously just the right time to hand
off the CPU to some other process.

Of course, if something takes 200 seconds, it's typically
because some process is waiting for IO, and if it's waiting
for IO, the CPU should be used by other processes, such as
yours.

Perhaps you can use the event log or some performance
measurement tools to check if something else on the system
happens to coincide with your long delays.

Peter Hansen
Guest
Posts: n/a

 02-24-2006
Magnus Lycka wrote:
> With an operating system such as Windows, this is
> probably something you can expect to happen, although
> I'm surprised if such long lag times as 200 s are typical.

No way. I mean, I'm the biggest critic of Windows operating systems
when used in realtime environments (at least with my customers), but
there's no way you should "probably expect a 200s delay to happen".

(You can't guarantee it won't, but seeing it on a regular basis is
sending a clear message that something *else* is going on. Dennis'
guess seems a good one.)

> If you need real time characteristics, you should
> probably use a real time operating system, not Windows.

Quite true. I doubt the OP needs that though.

-Peter

Claudio Grondi
Guest
Posts: n/a

 02-24-2006
Claudio Grondi wrote:
> Paul Probert wrote:
>
>> Peter Hansen wrote:
>>
>>> Are you saying that you believe the time.sleep(1) call is actually
>>> blocking for 200 seconds?

> With such rare occurrence it is very hard to tell what is going on.
> Usually I put such strange things on a list of curiosities I don't want
> to know the reason of, because it is in my eyes not worth the effort.
> Maybe it is even a common problem not yet detected by me, because I have
> never run this kind of tests for such a long time.
> Starting today, I can tell you statistically not earlier than in one
> week, if I have the same problem on my machines (currently I am running
> only one or two at the same time).

Here the intermediate results on my Windows XP machine connected to the
Internet via very fast digital phone line connection (network
card/digital-converter box/phone-line):

dt= 1.125 time= 2006_02_24_11h_36m_15s
dt= 9.20200014114 time= 2006_02_24_12h_46m_49s
dt= 1.18799996376 time= 2006_02_24_14h_43m_32s

The code used:
"""
import time
while True:
oldtime=time.time()
time.sleep(1.0)
newtime=time.time()
dt=newtime-oldtime
if dt > 1.1:
print 'dt=',dt,' time=',time.strftime('%Y_%m_%d_%Hh_%Mm_%Ss')
"""
running in a command line console parallel to usual daily business on
the computer.

The yesterday night run (5 hours) gave max. 1.125 sec., so I am
surprized to see the 9 seconds already after only two hours today.

Claudio

Scott David Daniels
Guest
Posts: n/a

 02-24-2006
Paul Probert wrote:
> Yes, I'm doing this:
> .....
> oldtime=time.time()
> time.sleep(1)
> newtime=time.time()
> dt=newtime-oldtime
> if dt > 2:
> print 'dt=',dt,' time=',time.strftime('%Y_%m_%d_%Hh_%Mm_%Ss')
> Its happening roughly 4 times a day total on our 20 machines, ie about
> once every 5 days on a given machine.

Well, you have a guess about the time updates that may well tell you
all. Because of that guess, you might want to try:

oldtime = time.time()
time.sleep(1)
newtime = time.time()
delta = newtime - oldtime
if not .5 < delta < 2:
print 'delta=%s, from=%s, time=%s' % (
delta, time.strftime('%Y_%m_%d_%Hh_%Mm_%Ss',
time.gmtime(oldtime)),
time.strftime('%Y_%m_%d_%Hh_%Mm_%Ss',
time.gmtime(newtime)))

to see if you get time running backwards as well.

--Scott David Daniels
http://www.velocityreviews.com/forums/(E-Mail Removed)

Bryan Olson
Guest
Posts: n/a

 02-24-2006
Paul Probert wrote:
[...]
> Its happening roughly 4 times a day total on our 20 machines, ie about
> once every 5 days on a given machine.

Do they all have similar anti-virus programs? Some of those can
freeze out other tasks from time to time. Just one more candidate.

--
--Bryan

Claudio Grondi
Guest
Posts: n/a

 02-25-2006
Claudio Grondi wrote:
> Claudio Grondi wrote:
>
>> Paul Probert wrote:
>>
>>> Peter Hansen wrote:
>>>
>>>> Are you saying that you believe the time.sleep(1) call is actually
>>>> blocking for 200 seconds?

>>
>> With such rare occurrence it is very hard to tell what is going on.
>> Usually I put such strange things on a list of curiosities I don't
>> want to know the reason of, because it is in my eyes not worth the
>> effort. Maybe it is even a common problem not yet detected by me,
>> because I have never run this kind of tests for such a long time.
>> Starting today, I can tell you statistically not earlier than in one
>> week, if I have the same problem on my machines (currently I am
>> running only one or two at the same time).

>
>
> Here the intermediate results on my Windows XP machine connected to the
> Internet via very fast digital phone line connection (network
> card/digital-converter box/phone-line):
>
> dt= 1.125 time= 2006_02_24_11h_36m_15s
> dt= 9.20200014114 time= 2006_02_24_12h_46m_49s
> dt= 1.18799996376 time= 2006_02_24_14h_43m_32s
>
> The code used:
> """
> import time
> while True:
> oldtime=time.time()
> time.sleep(1.0)
> newtime=time.time()
> dt=newtime-oldtime
> if dt > 1.1:
> print 'dt=',dt,' time=',time.strftime('%Y_%m_%d_%Hh_%Mm_%Ss')
> """
> running in a command line console parallel to usual daily business on
> the computer.
>
> The yesterday night run (5 hours) gave max. 1.125 sec., so I am
> surprized to see the 9 seconds already after only two hours today.
>
> Claudio

The 9.2 seconds difference was also because of time synchronization
Windows XP does using time.windows.com server - it reported to be done
last time 2006-02-24 at 12:46 o'clock i.e. exactly at the same time
where the 9.2 delay occurred.

Claudio

Tony Nelson
Guest
Posts: n/a

 02-26-2006
In article <dtqpkl\$kbo\$(E-Mail Removed)>,
Claudio Grondi <(E-Mail Removed)> wrote:

> Claudio Grondi wrote:
> > Claudio Grondi wrote:
> >
> >> Paul Probert wrote:
> >>
> >>> Peter Hansen wrote:
> >>>
> >>>> Are you saying that you believe the time.sleep(1) call is actually
> >>>> blocking for 200 seconds?
> >>
> >> With such rare occurrence it is very hard to tell what is going on.
> >> Usually I put such strange things on a list of curiosities I don't
> >> want to know the reason of, because it is in my eyes not worth the
> >> effort. Maybe it is even a common problem not yet detected by me,
> >> because I have never run this kind of tests for such a long time.
> >> Starting today, I can tell you statistically not earlier than in one
> >> week, if I have the same problem on my machines (currently I am
> >> running only one or two at the same time).

> >
> >
> > Here the intermediate results on my Windows XP machine connected to the
> > Internet via very fast digital phone line connection (network
> > card/digital-converter box/phone-line):
> >
> > dt= 1.125 time= 2006_02_24_11h_36m_15s
> > dt= 9.20200014114 time= 2006_02_24_12h_46m_49s
> > dt= 1.18799996376 time= 2006_02_24_14h_43m_32s
> >
> > The code used:
> > """
> > import time
> > while True:
> > oldtime=time.time()
> > time.sleep(1.0)
> > newtime=time.time()
> > dt=newtime-oldtime
> > if dt > 1.1:
> > print 'dt=',dt,' time=',time.strftime('%Y_%m_%d_%Hh_%Mm_%Ss')
> > """
> > running in a command line console parallel to usual daily business on
> > the computer.
> >
> > The yesterday night run (5 hours) gave max. 1.125 sec., so I am
> > surprized to see the 9 seconds already after only two hours today.
> >
> > Claudio

>
> The 9.2 seconds difference was also because of time synchronization
> Windows XP does using time.windows.com server - it reported to be done
> last time 2006-02-24 at 12:46 o'clock i.e. exactly at the same time
> where the 9.2 delay occurred.

ISTM that using time-of-day is the wrong thing for measuring elapsed
time, but I don't find anything in the time module that would be better.
/proc/uptime looks like it would work on linux, in a roundabout way:

>>> up = open('/proc/uptime')

will print uptime and idle time, but on linux only. At least it seems
to be fast enough for the purpose at hand (about 18 microseconds on my
old box, according to timeit).

Is there a better timer available in python? I see that timeit module
uses time.time() (or time.clock() on MSWindows), so I am not hopeful.
__________________________________________________ ______________________
TonyN.:' *firstname*nlsnews@georgea*lastname*.com
' <http://www.georgeanelson.com/>

Claudio Grondi
Guest
Posts: n/a

 02-26-2006
Tony Nelson wrote:
> In article <dtqpkl\$kbo\$(E-Mail Removed)>,
> Claudio Grondi <(E-Mail Removed)> wrote:
>
>
>>Claudio Grondi wrote:
>>
>>>Claudio Grondi wrote:
>>>
>>>
>>>>Paul Probert wrote:
>>>>
>>>>
>>>>>Peter Hansen wrote:
>>>>>
>>>>>
>>>>>>Are you saying that you believe the time.sleep(1) call is actually
>>>>>>blocking for 200 seconds?
>>>>
>>>>With such rare occurrence it is very hard to tell what is going on.
>>>>Usually I put such strange things on a list of curiosities I don't
>>>>want to know the reason of, because it is in my eyes not worth the
>>>>effort. Maybe it is even a common problem not yet detected by me,
>>>>because I have never run this kind of tests for such a long time.
>>>>Starting today, I can tell you statistically not earlier than in one
>>>>week, if I have the same problem on my machines (currently I am
>>>>running only one or two at the same time).
>>>
>>>
>>>Here the intermediate results on my Windows XP machine connected to the
>>>Internet via very fast digital phone line connection (network
>>>card/digital-converter box/phone-line):
>>>
>>>dt= 1.125 time= 2006_02_24_11h_36m_15s
>>>dt= 9.20200014114 time= 2006_02_24_12h_46m_49s
>>>dt= 1.18799996376 time= 2006_02_24_14h_43m_32s
>>>
>>>The code used:
>>>"""
>>>import time
>>>while True:
>>> oldtime=time.time()
>>> time.sleep(1.0)
>>> newtime=time.time()
>>> dt=newtime-oldtime
>>> if dt > 1.1:
>>> print 'dt=',dt,' time=',time.strftime('%Y_%m_%d_%Hh_%Mm_%Ss')
>>>"""
>>>running in a command line console parallel to usual daily business on
>>>the computer.
>>>
>>>The yesterday night run (5 hours) gave max. 1.125 sec., so I am
>>>surprized to see the 9 seconds already after only two hours today.
>>>
>>>Claudio

>>
>>The 9.2 seconds difference was also because of time synchronization
>>Windows XP does using time.windows.com server - it reported to be done
>>last time 2006-02-24 at 12:46 o'clock i.e. exactly at the same time
>>where the 9.2 delay occurred.

>
>
> ISTM that using time-of-day is the wrong thing for measuring elapsed
> time, but I don't find anything in the time module that would be better.
> /proc/uptime looks like it would work on linux, in a roundabout way:
>
> >>> up = open('/proc/uptime')

>
> will print uptime and idle time, but on linux only. At least it seems
> to be fast enough for the purpose at hand (about 18 microseconds on my
> old box, according to timeit).
>
> Is there a better timer available in python? I see that timeit module
> uses time.time() (or time.clock() on MSWindows), so I am not hopeful.

I mean, that using time.clock() solves the problem, because the output
of the following code:

"""
import time
while True:
old_Time = time.time()
oldClock = time.clock()
time.sleep(1.0)
new_Time = time.time()
newClock = time.clock()
dt=new_Time-old_Time
if( dt < 0.9 or dt > 1.1 ):
print 'new_Time-old_Time =', dt,'
time=',time.strftime('%Y_%m_%d_%Hh_%Mm_%Ss')
print 'newClock-oldClock =', newClock-oldClock
"""

was:

new_Time-old_Time = 177.921999931 time= 2006_02_26_20h_46m_01s
newClock-oldClock = 0.999994692063
new_Time-old_Time = -124.171999931 time= 2006_02_26_20h_44m_19s
newClock-oldClock = 1.00000502857
new_Time-old_Time = 53.3339998722 time= 2006_02_26_20h_45m_42s
newClock-oldClock = 1.00001313016
new_Time-old_Time = 0.634000062943 time= 2006_02_26_20h_45m_48s
newClock-oldClock = 1.00000195556

where I have manipulated the system clock manually to trigger the output.

Claudio