Thread: BUG #2569: statement_timeout bug on Windows
The following bug has been logged online: Bug reference: 2569 Logged by: James Email address: im-james@hotmail.com PostgreSQL version: 8.1.4 Operating system: Windows 200 Pro SP4 Description: statement_timeout bug on Windows Details: I'm using the latest version of postgresql (8.1.4) for Windows and I have a problem with 'statement_timeout'. Normally statement_timeout should "Abort any statement that takes over the specified number of milliseconds". However on my pc, instead of milliseconds it is tenth of seconds. For example: statement_timeout=30 actually means 'wait 3 seconds and abort' instead of wait 30 milliseconds. I've tested this on the same version of postgresql on Linux and it works correctly, as stated on the docs. What do I do to find get this strange result? I do this. set statement_timeout=30 show statement_timeout VACUUM ANALYSE The last statement is aborted after 3 seconds. set statement_timeout=6 show statement_timeout VACUUM ANALYSE The last statement is aborted after 600 milliseconds. Is this a bug (as I think) or could it be a misconfiguration of my OS, or of postgresql?
I have a big "Oops" for this item. Seems in 8.0, we used the Win32 call SetWaitableTimer(), which takes its timeout in 100 nanosecond intervals. This was changed to use WaitForSingleObjectEx() in 8.1, but not properly. The 8.0 code works fine. The attached patch will fix the problem, and will be in 8.1.X. Sorry. This affects all Win32 setitimer() calls in the backend, but the bug is only related to micro-seconds, not full seconds. Because deadlock timer is 1000ms, I don't think that is effected, but the stat file writer timeout is 500ms, so that could be doing a 50sec timeout instead without this patch. --------------------------------------------------------------------------- James wrote: > > The following bug has been logged online: > > Bug reference: 2569 > Logged by: James > Email address: im-james@hotmail.com > PostgreSQL version: 8.1.4 > Operating system: Windows 200 Pro SP4 > Description: statement_timeout bug on Windows > Details: > > I'm using the latest version of postgresql (8.1.4) for Windows and I have a > problem with 'statement_timeout'. > > Normally statement_timeout should "Abort any statement that takes over the > specified number of milliseconds". However on my pc, instead of milliseconds > it is tenth of seconds. For example: statement_timeout=30 actually means > 'wait 3 seconds and abort' instead of wait 30 milliseconds. > > I've tested this on the same version of postgresql on Linux and it works > correctly, as stated on the docs. > > What do I do to find get this strange result? I do this. > > set statement_timeout=30 > show statement_timeout > VACUUM ANALYSE > > The last statement is aborted after 3 seconds. > > > set statement_timeout=6 > show statement_timeout > VACUUM ANALYSE > > The last statement is aborted after 600 milliseconds. > > > > Is this a bug (as I think) or could it be a misconfiguration of my OS, or of > postgresql? > > ---------------------------(end of broadcast)--------------------------- > TIP 3: Have you checked our extensive FAQ? > > http://www.postgresql.org/docs/faq -- Bruce Momjian bruce@momjian.us EnterpriseDB http://www.enterprisedb.com + If your life is a hard drive, Christ can be your backup. + Index: src/backend/port/win32/timer.c =================================================================== RCS file: /cvsroot/pgsql/src/backend/port/win32/timer.c,v retrieving revision 1.9 diff -c -c -r1.9 timer.c *** src/backend/port/win32/timer.c 9 Aug 2006 17:33:52 -0000 1.9 --- src/backend/port/win32/timer.c 9 Aug 2006 17:34:11 -0000 *************** *** 56,62 **** timerCommArea.value.it_value.tv_usec == 0) waittime = INFINITE; /* Cancel the interrupt */ else ! waittime = timerCommArea.value.it_value.tv_usec / 10 + timerCommArea.value.it_value.tv_sec * 1000; ResetEvent(timerCommArea.event); LeaveCriticalSection(&timerCommArea.crit_sec); } --- 56,63 ---- timerCommArea.value.it_value.tv_usec == 0) waittime = INFINITE; /* Cancel the interrupt */ else ! /* WaitForSingleObjectEx() uses milliseconds */ ! waittime = timerCommArea.value.it_value.tv_usec / 1000 + timerCommArea.value.it_value.tv_sec * 1000; ResetEvent(timerCommArea.event); LeaveCriticalSection(&timerCommArea.crit_sec); }
Bruce Momjian <bruce@momjian.us> writes:
! /* WaitForSingleObjectEx() uses milliseconds */
> ! waittime = timerCommArea.value.it_value.tv_usec / 1000 + timerCommArea.value.it_value.tv_sec *
1000;
Seems like this probably ought to round up not down:
waittime = (timerCommArea.value.it_value.tv_usec + 999) / 1000 + timerCommArea.value.it_value.tv_sec * 1000;
Otherwise, an attempt to wait for 100 usec would convert to waittime 0,
which seems like a bad thing. In general the semantics of timed waits
are always supposed to be "you wait at least this long".
regards, tom lane
Tom Lane wrote: > Bruce Momjian <bruce@momjian.us> writes: > ! /* WaitForSingleObjectEx() uses milliseconds */ > > ! waittime = timerCommArea.value.it_value.tv_usec / 1000 + timerCommArea.value.it_value.tv_sec * 1000; > > Seems like this probably ought to round up not down: > > waittime = (timerCommArea.value.it_value.tv_usec + 999) / 1000 + timerCommArea.value.it_value.tv_sec * 1000; > > Otherwise, an attempt to wait for 100 usec would convert to waittime 0, > which seems like a bad thing. In general the semantics of timed waits > are always supposed to be "you wait at least this long". I thought about that, but because statement_timeout is in millis, and not micros, we can't have a value that gets rounded down. I am thinking a cleaner solution is to check for secs and if that is 0 and microsecs < 1000, you set millis = 1. Patch attached and applied to head and 8.1.X. -- Bruce Momjian bruce@momjian.us EnterpriseDB http://www.enterprisedb.com + If your life is a hard drive, Christ can be your backup. + Index: src/backend/port/win32/timer.c =================================================================== RCS file: /cvsroot/pgsql/src/backend/port/win32/timer.c,v retrieving revision 1.10 diff -c -c -r1.10 timer.c *** src/backend/port/win32/timer.c 9 Aug 2006 17:47:03 -0000 1.10 --- src/backend/port/win32/timer.c 9 Aug 2006 20:39:16 -0000 *************** *** 56,63 **** --- 56,69 ---- timerCommArea.value.it_value.tv_usec == 0) waittime = INFINITE; /* Cancel the interrupt */ else + { + /* Minimum wait time is 1ms */ + if (timerCommArea.value.it_value.tv_sec == 0 && + timerCommArea.value.it_value.tv_usec < 1000) + timerCommArea.value.it_value.tv_usec = 1000; /* WaitForSingleObjectEx() uses milliseconds */ waittime = timerCommArea.value.it_value.tv_usec / 1000 + timerCommArea.value.it_value.tv_sec * 1000; + } ResetEvent(timerCommArea.event); LeaveCriticalSection(&timerCommArea.crit_sec); }
Bruce Momjian <bruce@momjian.us> writes:
> Tom Lane wrote:
>> Seems like this probably ought to round up not down:
> I thought about that, but because statement_timeout is in millis, and
> not micros, we can't have a value that gets rounded down. I am
> thinking a cleaner solution is to check for secs and if that is 0 and
> microsecs < 1000, you set millis = 1.
This is much uglier, probably slower, and fixes the problem only for
the zero case --- it is just as wrong to wait 1 msec when the caller
asked for 1.5 msec. And per your own observation, statement_timeout
is not the only source of the wait values, so this code must not
assume that the value is a multiple of 1msec.
Please do it the other way.
regards, tom lane
OK, done. --------------------------------------------------------------------------- Tom Lane wrote: > Bruce Momjian <bruce@momjian.us> writes: > > Tom Lane wrote: > >> Seems like this probably ought to round up not down: > > > I thought about that, but because statement_timeout is in millis, and > > not micros, we can't have a value that gets rounded down. I am > > thinking a cleaner solution is to check for secs and if that is 0 and > > microsecs < 1000, you set millis = 1. > > This is much uglier, probably slower, and fixes the problem only for > the zero case --- it is just as wrong to wait 1 msec when the caller > asked for 1.5 msec. And per your own observation, statement_timeout > is not the only source of the wait values, so this code must not > assume that the value is a multiple of 1msec. > > Please do it the other way. > > regards, tom lane > > ---------------------------(end of broadcast)--------------------------- > TIP 5: don't forget to increase your free space map settings -- Bruce Momjian bruce@momjian.us EnterpriseDB http://www.enterprisedb.com + If your life is a hard drive, Christ can be your backup. +