Delay returns immediately

  • This site uses cookies. By continuing to use this site, you are agreeing to our use of cookies. Learn more.
Sep 27, 2009
8
0
#1
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
 

Attachments

rconn

Administrator
Staff member
May 14, 2008
10,210
86
#2
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.
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.
 
Sep 27, 2009
8
0
#3
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 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
---- 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
 
Sep 27, 2009
8
0
#6
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:
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
---- 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
 

rconn

Administrator
Staff member
May 14, 2008
10,210
86
#8
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/library/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.
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
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.
 
Sep 27, 2009
8
0
#10
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.
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
 

Attachments

Sep 27, 2009
8
0
#11
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
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
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
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".
 
#16
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.
 

rconn

Administrator
Staff member
May 14, 2008
10,210
86
#17
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.
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
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.
 
#20
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
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.