1. This site uses cookies. By continuing to use this site, you are agreeing to our use of cookies. Learn More.

Delay returns immediately

Discussion in 'Support' started by Ninja, Feb 28, 2011.

  1. Ninja

    Joined:
    Sep 27, 2009
    Messages:
    8
    Likes Received:
    0
    Hi,

    I have found this problem in v12 and some older version.

    I use TC, TCC/LE to run batch to repeat jobs every day. I use DELAY to sleep for a bit less than 24 hr without problem. However, when the script keeps on running, "DELAY" may return immediate for some large value. Even I logoff and then login again, the problem still exist but fixed only after reboot.

    I am not sure if it is Windows' problem or TCC's, so I would like to ask if any ways to help troubleshoot. I attached the screen cap for reference.

    Thanks a lot.

    Ninja
     

    Attached Files:

  2. rconn

    rconn Administrator
    Staff Member

    Joined:
    May 14, 2008
    Messages:
    10,091
    Likes Received:
    85
    I cannot reproduce the problem here (tried on four machines and three different versions of Windows).

    This has to be a Windows issue (perhaps unique to your system?), as DELAY is simply calling a Windows API for the wait.
     
  3. Ninja

    Joined:
    Sep 27, 2009
    Messages:
    8
    Likes Received:
    0
    I agree with you and I think it simply call Sleep or WaitForSingleObject API. I wrote a tiny C++ program to execute Sleep and WaitForSingleObject but seems ok. Could you tell me which function "DELAY" used, so I can perform more test.

    Below is my tiny program for your reference:
    int _tmain(int argc, _TCHAR* argv[])
    {
    if (3 != argc)
    {
    printf(
    "usage: [S|W] time\n");
    return 1;
    }
    DWORD delay;
    bool doSleep;
    if ('s' == argv[1][0] || 'S' == argv[1][0])
    {
    doSleep =
    true;
    }
    else if ('w' == argv[1][0] || 'W' == argv[1][0])
    {
    doSleep =
    false;
    }
    else
    {
    printf(
    "Invalid option\n");
    return 1;
    }
    if (1 != _stscanf( argv[2], _T("%u"), & delay))
    {
    printf(
    "Invalid time\n");
    return 1;
    }
    delay *= 1000;
    SYSTEMTIME curTime;
    HANDLE hEvent;
    DWORD hr;
    hEvent = CreateEvent(NULL, FALSE, FALSE, NULL);
    if (doSleep)
    {
    GetLocalTime(&curTime);
    printf(
    "%04d-%02d-%02d %02d:%02d:%02d.%03d Sleep Started\n",
    curTime.wYear,
    curTime.wMonth,
    curTime.wDay,
    curTime.wHour,
    curTime.wMinute,
    curTime.wSecond,
    curTime.wMilliseconds);
    Sleep(delay);
    GetLocalTime(&curTime);
    printf(
    "%04d-%02d-%02d %02d:%02d:%02d.%03d Sleep returned\n",
    curTime.wYear,
    curTime.wMonth,
    curTime.wDay,
    curTime.wHour,
    curTime.wMinute,
    curTime.wSecond,
    curTime.wMilliseconds);
    }
    else
    {
    GetLocalTime(&curTime);
    printf(
    "%04d-%02d-%02d %02d:%02d:%02d.%03d WaitForSingleObject Started\n",
    curTime.wYear,
    curTime.wMonth,
    curTime.wDay,
    curTime.wHour,
    curTime.wMinute,
    curTime.wSecond,
    curTime.wMilliseconds);
    hr = WaitForSingleObject(hEvent, delay);
    GetLocalTime(&curTime);
    printf(
    "%04d-%02d-%02d %02d:%02d:%02d.%03d WaitForSingleObject returned %08X\n",
    curTime.wYear,
    curTime.wMonth,
    curTime.wDay,
    curTime.wHour,
    curTime.wMinute,
    curTime.wSecond,
    curTime.wMilliseconds,
    hr);
    }
    return 0;
    }
     
  4. Steve Fabian

    Joined:
    May 20, 2008
    Messages:
    3,520
    Likes Received:
    4
    ---- Original Message ----
    From: rconn
    | Originally Posted by Ninja
    ...
    || "DELAY" may return immediate for some large value.
    ...
    |
    | I cannot reproduce the problem here (tried on four machines and three
    | different versions of Windows).
    |
    | This has to be a Windows issue (perhaps unique to your system?), as
    | DELAY is simply calling a Windows API for the wait.

    I, too, observed something akin to the OP. In a batch file which starts a game a loop containing only DELAY /M 100 runs until a specific new window is detected; at that time a DELAY 5 is supposed to occur to permit the player to decide either to resume the game or to quit it. On many occasions this 5s delay does not occur. Due to its lack of importance I never investigated whether or not a mistake in my batch file is the cause, but the observation does go back to at least TCC v10, always in the WinXP SP3 environment.
    --
    Steve
     
  5. rconn

    rconn Administrator
    Staff Member

    Joined:
    May 14, 2008
    Messages:
    10,091
    Likes Received:
    85
    It calls GetTickCount in a loop (so that it can break on a keystroke), goes to sleep for a millisecond, then loops back.
     
  6. Ninja

    Joined:
    Sep 27, 2009
    Messages:
    8
    Likes Received:
    0
    I think it is the cause of the problem. GetTickCount on the machines returns:
    Tick Count is: 4290913766 (FFC225E6)

    According to Windows Doc:
    ms724408(VS.85).aspx

    The elapsed time is stored as a DWORD value. Therefore, the time will wrap around to zero if the system is run continuously for 49.7 days. To avoid this problem, use GetTickCount64. Otherwise, check for an overflow condition when comparing times.


    Thus, I think this is a bug in TCC.

    Ninja
     
  7. Steve Fabian

    Joined:
    May 20, 2008
    Messages:
    3,520
    Likes Received:
    4
    ---- Original Message ----
    From: Ninja
    To: ESFabian@zenge.org
    Sent: Monday, 2011. February 28. 22:53
    Subject: RE: [Support-t-2637] Re: Delay returns immediately

    | Quote:
    | Originally Posted by rconn
    | It calls GetTickCount in a loop (so that it can break on a
    | keystroke), goes to sleep for a millisecond, then loops back.
    |
    | I think it is the cause of the problem. GetTickCount on the machines
    | returns:
    | Tick Count is: 4290913766 (FFC225E6)
    |
    | According to Windows Doc:
    | http://msdn.microsoft.com/en-us/libr...08(VS.85).aspx
    |
    | The elapsed time is stored as a DWORD value. Therefore, the time will
    | wrap around to zero if the system is run continuously for 49.7 days.
    | To avoid this problem, use GetTickCount64. Otherwise, check for an
    | overflow condition when comparing times.
    |
    |
    | Thus, I think this is a bug in TCC.

    Firstly, Rex did not mention loop details, which may indeed include the overflow check. Regardless, this issue would only occur once each 49.7 days on a system that is never restarted, so certainly would not cause my problem (several times each day).
    --
    Steve
     
  8. rconn

    rconn Administrator
    Staff Member

    Joined:
    May 14, 2008
    Messages:
    10,091
    Likes Received:
    85
    I'm aware of the limitation in GetTickCount, and TCC takes this into account when calculating the time to wait.

    And I can't use GetTickCount64, because a lot of users (like you!) are running an ancient version of Windows that doesn't include that API.
     
  9. vefatica

    Joined:
    May 20, 2008
    Messages:
    8,129
    Likes Received:
    33
    On Mon, 28 Feb 2011 22:53:50 -0500, Ninja <> wrote:

    |I think it is the cause of the problem. GetTickCount on the machines returns:
    |Tick Count is: 4290913766 (FFC225E6)

    Always? (!!!!!) A half a second after you saw that, it should be 0.
     
  10. Ninja

    Joined:
    Sep 27, 2009
    Messages:
    8
    Likes Received:
    0
    I further perform a test to verify the overflow issue. Below is the screen output. (screen cap attached) "GetTickCount.exe" is a simple program which print out the tick count.

    [C:\tmp]GetTickCount.exe > a.txt & type a.txt & for %x in (@a.txt) (set delayMs=
    %@eval[4294967295 + 1000 - %@word[3,%x]] & echo To be delay %delayMs ms & echo %
    _isodate %_time & delay /m %delayMs & echo %_isodate %_time)
    Tick Count is: 4293321907 (FFE6E4B3)
    To be delay 1646388 ms
    2011-03-01 12:41:22
    2011-03-01 12:41:22
     

    Attached Files:

  11. Ninja

    Joined:
    Sep 27, 2009
    Messages:
    8
    Likes Received:
    0
    I suspect there is bug when special data encountered. I would suggest try debug by filling the specified data.

    Hopes to hear from you soon.

    Best Regards,
    Ninja
     
  12. vefatica

    Joined:
    May 20, 2008
    Messages:
    8,129
    Likes Received:
    33
    Ninja seems to be right. If the due-time of a DELAY /M is after the rollover,
    it finishes immediately.

    Code:
    v:\> echo %_time & delay /m %@eval[0xffffffff - %_winticks + 1] & echo
    %_time
    22:34:28
    22:34:28
     
  13. vefatica

    Joined:
    May 20, 2008
    Messages:
    8,129
    Likes Received:
    33
    DELAY (without /M) seems to suffer similarly:

    Code:
    v:\> set /a delay=%@eval[0xffffffff \ 1000 - %_winticks \ 1000 + 1]
    2468596
    
    v:\> echo %_time & delay %delay & echo %_time
    22:54:13
    22:54:13
    The help says the delay may be up to about a billion seconds.

    How about Create/SetWaitableTimer() and loop (in little bits) around WaitForSingleObject(). That might also work nicely for my proposed "DELAY /U(ntil) DATETIME".
     
  14. vefatica

    Joined:
    May 20, 2008
    Messages:
    8,129
    Likes Received:
    33
    Are you going to fix DELAY or amend the help to say how it really works?
     
  15. rconn

    rconn Administrator
    Staff Member

    Joined:
    May 14, 2008
    Messages:
    10,091
    Likes Received:
    85
    Are you having a problem with DELAY in 12.10.56? I cannot reproduce any
    wrapping problem here.
     
  16. vefatica

    Joined:
    May 20, 2008
    Messages:
    8,129
    Likes Received:
    33
    On Tue, 22 Mar 2011 21:25:27 -0400, rconn <> wrote:

    |---Quote---
    |> Are you going to fix DELAY or amend the help to say how it
    |> really works?
    |---End Quote---
    |Are you having a problem with DELAY in 12.10.56? I cannot reproduce any
    |wrapping problem here.

    Yes.

    Code:
    v:\> set /a delay=%@eval[0xffffffff \ 1000 + 5] & delay %delay
    4294972
    
    v:\> set /a delay=%@eval[0xffffffff \ 1000 - 5] & delay %delay
    4294962
    The first above gives a 5 second delay. The second returns immediately.
    Everything seems to happen modulo the maximum tick count.
     
  17. rconn

    rconn Administrator
    Staff Member

    Joined:
    May 14, 2008
    Messages:
    10,091
    Likes Received:
    85
    Let me rephrase that:

    Do you have any wrapping problems that don't require passing a crazy value to DELAY?

    What you're reporting now is unrelated to the OP question. Your (meaninglessly large) value is always wrapping, and can never match a time difference, so it's immediately rejected by DELAY as an invalid value.
     
  18. vefatica

    Joined:
    May 20, 2008
    Messages:
    8,129
    Likes Received:
    33
    On Wed, 23 Mar 2011 15:33:29 -0400, rconn <> wrote:

    |Do you have any wrapping problems that don't require passing a crazy value to DELAY?
    |
    |What you're reporting now is unrelated to the OP question. Your (meaninglessly large) value is always wrapping, and can never match a time difference, so it's immediately rejected by DELAY as an invalid value.

    The help says something abouit a billion seconds, and 34 years.

    The truth is, if you give a time that expires before the tick count rolls over,
    it works properly. If the specified time is longer than that but less than the
    tick count's period, DELAY returns immediately. And if the specified time is
    longer than the tick count's peroid the delay winds up being the specified
    amount **MODULO** MAX_TICK_COUNT. I believe that was precisely the OP's
    problem.

    In any event, it doesn't come close to what the help says.
     
  19. rconn

    rconn Administrator
    Staff Member

    Joined:
    May 14, 2008
    Messages:
    10,091
    Likes Received:
    85
    Let me rephrase that again:

    Do you have a REAL problem with this, or are you arguing for a useless hypothetical case when passing values to DELAY that you would never actually pass?

    As I said before, DELAY is rejecting the value; it's not wrapping around.
     
  20. vefatica

    Joined:
    May 20, 2008
    Messages:
    8,129
    Likes Received:
    33
    On Wed, 23 Mar 2011 16:02:55 -0400, rconn <> wrote:

    |Let me rephrase that again:
    |
    |Do you have a REAL problem with this, or are you arguing for a useless hypothetical case when passing values to DELAY that you would never actually pass?
    |
    |As I said before, DELAY is rejecting the value; it's not wrapping around.

    I'm sorry; I'm thick.

    Why is it delaying 5 seconds when I say

    Code:
    DELAY %@EVAL[0xFFFFFFFF \ 1000 + 5]
    That's only 4294972, well under a billion and much less than 34 years. It
    doesn't seem to be rejecting the value.

    And the possibility exists, though it's small, that someone will really
    ask for a (reasonble) delay that will fail if it spans a tick count roll-over.

    Right now, on lucky (at work),

    Code:
    v:\> uptime
    
    Uptime: 47 days 10 hours 52 minutes 31 seconds
    Boot:   2011-02-04,06:17:35
    If I ask for a 63 hour delay (reasonable?), it fails.

    Shall I wait until 1 minute before the tick count rolls over and ask for a
    2-minute (reasonable?) delay? ... bet it will fail.

    I don't care if you fix it or not, but at least let the help say how it works.
     
  21. JohnQSmith

    Joined:
    Jan 19, 2011
    Messages:
    559
    Likes Received:
    7
    Actually, it fails at a MUCH LOWER value than 34 years. It changes from succeeding at 0x7fffffff milliseconds (~2147483 seconds) to failing at 0x80000000 milliseconds (~2147484 seconds), which is just over 596 and a half days (less than 2 years).
    Code:
    [C:\test] set /a delay=%@eval[0x7fffffff] & delay /m %delay
    2147483647
    ^C
    [C:\test] set /a delay=%@eval[0x80000000] & delay /m %delay
    2147483648
    
    [C:\test]
    
    Looks to me like the code is using a 32 bit signed integer and is being rejected when it overflows into a negative number.
     

Share This Page