Hi all,

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.

After turning on the postgresql.conf settings to capture queries and
their execution times, this is the output from a "grep -n duration" on
the output.

Looking at the "hours" column it all looks fine until we get to 10 am.
From there onwards (into 11am too) occasionally the hours column is
wrong. 10 is occasionally given as 00, and 11 is occasionally given as 1.

***********

59697:2004-10-07 09:55:38 [92988] LOG: duration: 2.358 ms
59711:2004-10-07 09:55:38 [92988] LOG: duration: 6.365 ms
59725:2004-10-07 09:55:38 [92988] LOG: duration: 2.938 ms
59741:2004-10-07 09:55:38 [92989] LOG: duration: 10.088 ms
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

***********

and

***********

81738:2004-10-07 10:45:39 [94489] LOG: duration: 5.043 ms
81754:2004-10-07 10:50:39 [94595] LOG: duration: 7.682 ms
81770:2004-10-07 10:50:39 [94596] LOG: duration: 10.083 ms
81786:2004-10-07 10:50:39 [94597] LOG: duration: 9.811 ms
81837:2004-10-07 10:52:40 [63625] LOG: duration: 899.978 ms
81888:2004-10-07 10:54:16 [63625] LOG: duration: 15405.853 ms
81904:2004-10-07 10:55:39 [94736] LOG: duration: 2.340 ms
81918:2004-10-07 10:55:39 [94736] LOG: duration: 6.294 ms
81932:2004-10-07 10:55:39 [94736] LOG: duration: 2.879 ms
81948:2004-10-07 10:55:39 [94737] LOG: duration: 10.113 ms
81962:2004-10-07 10:55:39 [94737] LOG: duration: 5.310 ms
81978:2004-10-07 10:55:39 [94738] LOG: duration: 9.764 ms
81992:2004-10-07 10:55:39 [94738] LOG: duration: 5.013 ms
82008:2004-10-07 11:00:39 [94994] LOG: duration: 7.681 ms
82024:2004-10-07 11:00:39 [94995] LOG: duration: 10.157 ms
82040:2004-10-07 11:00:39 [94996] LOG: duration: 9.821 ms
82054:2004-10-07 11:01:44 [94128] LOG: duration: 0.245 ms
82068:2004-10-07 11:01:44 [94128] LOG: duration: 0.089 ms
82082:2004-10-07 11:01:44 [94128] LOG: duration: 0.957 ms
82096:2004-10-07 01:01:44 [94129] LOG: duration: 0.286 ms
82110:2004-10-07 01:01:44 [94129] LOG: duration: 0.091 ms
82124:2004-10-07 01:01:44 [94129] LOG: duration: 0.101 ms
82138:2004-10-07 01:01:44 [94129] LOG: duration: 0.086 ms
82152:2004-10-07 01:01:44 [94129] LOG: duration: 279.595 ms
82452:2004-10-07 11:01:44 [94128] LOG: duration: 3.664 ms
82466:2004-10-07 11:01:44 [94128] LOG: duration: 23.599 ms

***********

This snippet of the output is rather cut down, as the verbose version
caused my last email to bounce for being too large.

Regards and best wishes,

Justin Clift



---------------------------(end of broadcast)---------------------------
TIP 3: if posting/reading through Usenet, please send an appropriate
subscribe-nomail command to majordomo (AT) postgresql (DOT) org so that your
message can get through to the mailing list cleanly

Justin Clift <jc (AT) telstra (DOT) net> writes:
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

---------------------------(end of broadcast)---------------------------
TIP 7: don't forget to increase your free space map settings