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

Discussion in 'Python' started by Paul Probert, Feb 23, 2006.

  1. Paul Probert

    Paul Probert Guest

    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
     
    Paul Probert, Feb 23, 2006
    #1
    1. Advertising

  2. 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
     
    Claudio Grondi, Feb 24, 2006
    #2
    1. Advertising

  3. Paul Probert

    Magnus Lycka Guest

    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.
     
    Magnus Lycka, Feb 24, 2006
    #3
  4. Paul Probert

    Peter Hansen Guest

    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
     
    Peter Hansen, Feb 24, 2006
    #4
  5. 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
     
    Claudio Grondi, Feb 24, 2006
    #5
  6. 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
     
    Scott David Daniels, Feb 24, 2006
    #6
  7. Paul Probert

    Bryan Olson Guest

    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
     
    Bryan Olson, Feb 24, 2006
    #7
  8. 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
     
    Claudio Grondi, Feb 25, 2006
    #8
  9. Paul Probert

    Tony Nelson Guest

    In article <dtqpkl$kbo$>,
    Claudio Grondi <> 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')
    >>> up.seek(0) ; up.read()


    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/>
     
    Tony Nelson, Feb 26, 2006
    #9
  10. Tony Nelson wrote:
    > In article <dtqpkl$kbo$>,
    > Claudio Grondi <> 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')
    > >>> up.seek(0) ; up.read()

    >
    > 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
     
    Claudio Grondi, Feb 26, 2006
    #10
  11. Paul Probert

    Magnus Lycka Guest

    Peter Hansen wrote:
    > 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 know Peter, quotations are typically used when you actually
    quote someone, not when you make your own interpretation of what
    they meant.

    If I write that it would surprise me if you are often hit by
    meteorites, would the quote then be "you'll probably get hit
    by meteorites"?
     
    Magnus Lycka, Feb 27, 2006
    #11
  12. Paul Probert

    Magnus Lycka Guest

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


    On Windows that it. At least on Linux and Solaris, time.clock() returns
    CPU time. If time.clock() returns significantly different values before
    and after time.sleep(1), there's something seriously broken in sleep on
    such platforms.

    Anyway, what is the perceived problem?
    A) That sleep takes too much time, or
    B) that time measurements don't work right?

    If A), the problem is solved if what really happens is clock-setting
    glitches.

    If B), I see two options:

    - Use some proper external and stable time source. (It should be
    fairly trivial to build a little socket server that returns
    timestamps from a single source if no other source is available.
    See http://www.python.org/doc/lib/socket-example.html )

    - If the clock-resetting is actually warranted because the system
    clocks lag so much, make sure this resetting is made more often,
    so that it never gets so much off track.

    Unless hardware is broken, or the clocks are changed so that they
    get more and more off track with time as the rest of us perceives
    it, there ought to be "negative sleeps" as well as sleeps much
    longer than 2 seconds. Of course, if you only look for longer sleeps
    than 2 secs, you won't see them.

    BTW, finding "negative sleeps" pretty much proves that it's the
    clocks, not actual delays, that cause problems...

    I guess a typical cause of clock setting problems is that one has
    two disagreeing time sources that both try to set the system times
    of the computers...
     
    Magnus Lycka, Feb 27, 2006
    #12
  13. Magnus Lycka wrote:
    > On Windows that it. At least on Linux and Solaris, time.clock() returns
    > CPU time. If time.clock() returns significantly different values before
    > and after time.sleep(1), there's something seriously broken in sleep on
    > such platforms.


    No!
    When process run the sleep, the operating system give other processes to
    run and it takes time (so called time slice) to get back to the
    original process.

    Recently I invoked Runtime.sleep() from Java on Centos 4.2 and it might
    take up to 1 sec(!) to come from the sleep no matter what you put as the
    sleep parameter.

    Basically each process runs for around 20ms and then the other process
    get priority. I'm not sure why those Codecs run OK when I watch DVD
    movie while running other Java application which use processor and hard
    disc quite intensivly, it seems that they got slices regulary, I'm not
    sure way.

    So, once more when you go to "sleep" other process get the slice so it
    could take more time then predicted to continue.

    --
    Mladen Adamovic
    http://home.blic.net/adamm
    http://www.shortopedia.com
    http://www.froola.com
     
    Mladen Adamovic, Feb 28, 2006
    #13
  14. Paul Probert

    Magnus Lycka Guest

    Mladen Adamovic wrote:
    > Magnus Lycka wrote:
    >
    >> On Windows that it. At least on Linux and Solaris, time.clock() returns
    >> CPU time. If time.clock() returns significantly different values before
    >> and after time.sleep(1), there's something seriously broken in sleep on
    >> such platforms.

    >
    > No!


    It seems I can't say anything in this thread without getting
    contradicted! :)

    I'm sorry if I wasn't clear in explaining the concept of CPU
    time in Unix (and other multi user operating systems). This is
    an entity that is registered per process. Roughly, the code below
    means that calling f(arg) used s CPU seconds *in* *this* *process*.

    c0 = time.clock()
    f(arg)
    s = time.clock() - c0

    If f is time.sleep, s should be 0, or at least very close to 0
    on systems such as Linux where time.clock() measures CPU time.
    Otherwise something is broken. (On Linux, where CPU time has a
    low resolution (100 ms?) I've never seen any other figure than
    0.0.) There will obviously be other processes using the CPU while
    this process is sleeping, but this process should use no CPU time.

    Wall time delays will obviously depend on the load of the machines
    in question. I rarely see > 1 ms on Linux boxes with a low load.
    With a higher load, or many users, I see delays of up to 10 ms or
    so now and then, but rarely more.

    I suspect that observations from Java might not be completely
    relevant for Python. I suspect the Java implementation might add
    additional delays.
     
    Magnus Lycka, Mar 1, 2006
    #14
    1. Advertising

Want to reply to this thread or ask your own question?

It takes just 2 minutes to sign up (and it's free!). Just click the sign up button to choose a username and then you can ask your own questions on the forum.
Similar Threads
  1. Roman Zhovtulya
    Replies:
    5
    Views:
    661
    marcus
    Nov 8, 2004
  2. Paul Probert
    Replies:
    9
    Views:
    357
    Roel Schroeven
    Feb 24, 2006
  3. Paul Probert
    Replies:
    1
    Views:
    352
    Magnus Lycka
    Mar 1, 2006
  4. Michael Tan
    Replies:
    32
    Views:
    1,030
    Ara.T.Howard
    Jul 21, 2005
  5. Jesse Schoch
    Replies:
    2
    Views:
    141
    Jesse Schoch
    Oct 2, 2003
Loading...

Share This Page