Date: Mon, 11 Oct 2004 02:02:08 GMT From: Justin Clift <jc@telstra.net> To: freebsd-gnats-submit@FreeBSD.org Subject: misc/72498: Libc timestamp code on jailed SMP machine generates incorrect results Message-ID: <200410110202.i9B228Ye060291@www.freebsd.org> Resent-Message-ID: <200410110210.i9B2A9gg093196@freefall.freebsd.org>
next in thread | raw e-mail | index | archive | help
>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@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@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.
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?200410110202.i9B228Ye060291>