misc/72498: Libc timestamp code on jailed SMP machine generates
incorrect results
Justin Clift
jc at telstra.net
Sun Oct 10 19:10:10 PDT 2004
>Number: 72498
>Category: misc
>Synopsis: Libc timestamp code on jailed SMP machine generates incorrect results
>Confidential: no
>Severity: non-critical
>Priority: medium
>Responsible: freebsd-bugs
>State: open
>Quarter:
>Keywords:
>Date-Required:
>Class: sw-bug
>Submitter-Id: current-users
>Arrival-Date: Mon Oct 11 02:10:09 GMT 2004
>Closed-Date:
>Last-Modified:
>Originator: Justin Clift
>Release: 4.10
>Organization:
Telstra Corporation Ltd.
>Environment:
FreeBSD was-dev.telstra.net 4.10-RELEASE FreeBSD 4.10-RELEASE #0: Fri Jun 25 14:23:42 EST 2004 root at verdelho.telstra.net:/usr/src/sys/compile/1GB_SHARED_V3 i386
>Description:
We're using PostgreSQL 7.4.5 in an SMP jailed environment on FreeBSD 4.10.
Inside this jail PostgreSQL is configured to output timestamp information in it's log file entries. There appears to be a bug in the timestamp generation code, as for hours above 9 oclock (10am and onwards) the timestamp's being generated are occasionally incorrect:
59755:2004-10-07 09:55:38 [92989] LOG: duration: 5.296 ms
59771:2004-10-07 09:55:38 [92990] LOG: duration: 9.781 ms
59785:2004-10-07 09:55:38 [92990] LOG: duration: 5.032 ms
59801:2004-10-07 10:00:38 [93240] LOG: duration: 7.601 ms
59817:2004-10-07 10:00:38 [93241] LOG: duration: 10.033 ms
59833:2004-10-07 10:00:38 [93242] LOG: duration: 9.720 ms
59849:2004-10-07 10:05:38 [93377] LOG: duration: 2.322 ms
59863:2004-10-07 10:05:38 [93377] LOG: duration: 6.327 ms
59877:2004-10-07 10:05:38 [93377] LOG: duration: 2.873 ms
59893:2004-10-07 10:05:38 [93378] LOG: duration: 10.078 ms
59907:2004-10-07 10:05:38 [93378] LOG: duration: 5.293 ms
59923:2004-10-07 10:05:38 [93379] LOG: duration: 9.859 ms
59937:2004-10-07 10:05:38 [93379] LOG: duration: 4.995 ms
59953:2004-10-07 10:10:38 [93515] LOG: duration: 7.621 ms
59969:2004-10-07 10:10:38 [93516] LOG: duration: 10.130 ms
59985:2004-10-07 10:10:38 [93517] LOG: duration: 9.791 ms
60001:2004-10-07 10:15:23 [93665] LOG: duration: 1.031 ms
60015:2004-10-07 10:15:23 [93665] LOG: duration: 0.185 ms
60029:2004-10-07 10:15:23 [93665] LOG: duration: 3.982 ms
60329:2004-10-07 10:15:23 [93665] LOG: duration: 4.466 ms
60343:2004-10-07 10:15:23 [93665] LOG: duration: 20.072 ms
60357:2004-10-07 10:15:27 [93665] LOG: duration: 0.246 ms
60371:2004-10-07 10:15:27 [93665] LOG: duration: 0.090 ms
60385:2004-10-07 10:15:27 [93665] LOG: duration: 0.656 ms
60401:2004-10-07 10:15:28 [93666] LOG: duration: 0.714 ms
60415:2004-10-07 00:15:28 [93666] LOG: duration: 0.491 ms
60429:2004-10-07 00:15:28 [93666] LOG: duration: 0.267 ms
60443:2004-10-07 00:15:28 [93666] LOG: duration: 18.796 ms
60743:2004-10-07 10:15:28 [93665] LOG: duration: 3.285 ms
60757:2004-10-07 10:15:28 [93665] LOG: duration: 15.618 ms
60771:2004-10-07 10:15:30 [93665] LOG: duration: 0.248 ms
60785:2004-10-07 10:15:30 [93665] LOG: duration: 0.089 ms
60799:2004-10-07 10:15:30 [93665] LOG: duration: 0.626 ms
60815:2004-10-07 10:15:30 [93667] LOG: duration: 0.687 ms
60829:2004-10-07 10:15:30 [93667] LOG: duration: 0.107 ms
60843:2004-10-07 00:15:30 [93667] LOG: duration: 0.304 ms
60857:2004-10-07 00:15:30 [93667] LOG: duration: 0.131 ms
60871:2004-10-07 00:15:30 [93667] LOG: duration: 314.000 ms
61171:2004-10-07 10:15:30 [93665] LOG: duration: 3.121 ms
61185:2004-10-07 10:15:31 [93665] LOG: duration: 243.182 ms
61199:2004-10-07 00:15:31 [93667] LOG: duration: 0.492 ms
61213:2004-10-07 10:15:34 [93665] LOG: duration: 0.317 ms
61227:2004-10-07 10:15:34 [93665] LOG: duration: 0.161 ms
61241:2004-10-07 10:15:34 [93665] LOG: duration: 0.986 ms
61255:2004-10-07 00:15:34 [93667] LOG: duration: 0.275 ms
61269:2004-10-07 00:15:34 [93667] LOG: duration: 0.130 ms
Notice the hour column near the end of this listing should have been 10:xx:xx, but sometimes is 00:xx:xx. This also happens for 11->01 too. It may also happen for others (12->02, 13->03, etc).
Initially I assumed the bug was in PostgreSQL's code and submitted a bug report to them, however they have indicated that's not likely.
This is the response email from the PostgreSQL bug team, in case it's useful:
***********
Justin Clift <jc at telstra.net> writes:
>How-To-Repeat:
Install PostgreSQL 7.4.5 from ports, and configure it (in its postgresql.conf file) to output SQL statements and their duration to stdout.
Pipe stdout to a file, then begin processing SQL statements (it doesn't matter what they do).
Looking in the logfiles with:
$ grep duration postgresql.log
will extract the lines with duration timestamps.
>From 10am onwards, the timestamps will occasionally be incorrect. Sometimes for several entries in a run before going back to normal. It happens often enough so you probably won't have to wait long for it to show up.
>Fix:
Not known.
>Release-Note:
>Audit-Trail:
>Unformatted:
>> Running PG 7.4.5 on FreeBSD 4.10, we've found what looks to be buggy
>> output from the timestamp code used to generate logfile entries.
The code involved is
curtime = time(NULL);
strftime(buf, sizeof(buf),
"%Y-%m-%d %H:%M:%S ",
localtime(&curtime));
so this bug report ought to go to the FreeBSD libc folk.
I believe there are known problems with BSD kernels sometimes returning
wrong clock readings on SMP machines, so that might be a place to look too.
regards, tom lane
***********
The hardware is a HP Proliant DL380, dual 3.04 Ghz Xeon processor, 3GB RAM, SCSI drives.
More information about the freebsd-bugs
mailing list