From owner-freebsd-bugs@FreeBSD.ORG Mon Oct 11 02:10:10 2004 Return-Path: Delivered-To: freebsd-bugs@hub.freebsd.org Received: from mx1.FreeBSD.org (mx1.freebsd.org [216.136.204.125]) by hub.freebsd.org (Postfix) with ESMTP id 1F55F16A4CE for ; Mon, 11 Oct 2004 02:10:10 +0000 (GMT) Received: from freefall.freebsd.org (freefall.freebsd.org [216.136.204.21]) by mx1.FreeBSD.org (Postfix) with ESMTP id EE61C43D55 for ; Mon, 11 Oct 2004 02:10:09 +0000 (GMT) (envelope-from gnats@FreeBSD.org) Received: from freefall.freebsd.org (gnats@localhost [127.0.0.1]) by freefall.freebsd.org (8.12.11/8.12.11) with ESMTP id i9B2A9oe093197 for ; Mon, 11 Oct 2004 02:10:09 GMT (envelope-from gnats@freefall.freebsd.org) Received: (from gnats@localhost) by freefall.freebsd.org (8.12.11/8.12.11/Submit) id i9B2A9gg093196; Mon, 11 Oct 2004 02:10:09 GMT (envelope-from gnats) Resent-Date: Mon, 11 Oct 2004 02:10:09 GMT Resent-Message-Id: <200410110210.i9B2A9gg093196@freefall.freebsd.org> Resent-From: FreeBSD-gnats-submit@FreeBSD.org (GNATS Filer) Resent-To: freebsd-bugs@FreeBSD.org Resent-Reply-To: FreeBSD-gnats-submit@FreeBSD.org, Justin Clift Received: from mx1.FreeBSD.org (mx1.freebsd.org [216.136.204.125]) by hub.freebsd.org (Postfix) with ESMTP id BC0B516A4CE for ; Mon, 11 Oct 2004 02:02:08 +0000 (GMT) Received: from www.freebsd.org (www.freebsd.org [216.136.204.117]) by mx1.FreeBSD.org (Postfix) with ESMTP id 9DCA243D2D for ; Mon, 11 Oct 2004 02:02:08 +0000 (GMT) (envelope-from nobody@FreeBSD.org) Received: from www.freebsd.org (localhost [127.0.0.1]) by www.freebsd.org (8.12.11/8.12.11) with ESMTP id i9B228BI060292 for ; Mon, 11 Oct 2004 02:02:08 GMT (envelope-from nobody@www.freebsd.org) Received: (from nobody@localhost) by www.freebsd.org (8.12.11/8.12.11/Submit) id i9B228Ye060291; Mon, 11 Oct 2004 02:02:08 GMT (envelope-from nobody) Message-Id: <200410110202.i9B228Ye060291@www.freebsd.org> Date: Mon, 11 Oct 2004 02:02:08 GMT From: Justin Clift To: freebsd-gnats-submit@FreeBSD.org X-Send-Pr-Version: www-2.3 Subject: misc/72498: Libc timestamp code on jailed SMP machine generates incorrect results X-BeenThere: freebsd-bugs@freebsd.org X-Mailman-Version: 2.1.1 Precedence: list List-Id: Bug reports List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Mon, 11 Oct 2004 02:10:10 -0000 >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 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.