[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

misc/72498: Libc timestamp code on jailed SMP machine generates incorrect results



>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_(_dot_)_telstra_(_dot_)_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_(_dot_)_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.