about explain analyze

Teodor Sigaev <teodor@sigaev.ru> writes:

Explain analyze takes 3 times more time for execution. Why?

Measurement overhead. It would seem your platform has a particularly
slow version of gettimeofday() though ... I've never noticed such a
large discrepancy myself.

regards, tom lane

On Fri, 28 Nov 2003, Tom Lane wrote:

Teodor Sigaev <teodor@sigaev.ru> writes:

Explain analyze takes 3 times more time for execution. Why?

Measurement overhead. It would seem your platform has a particularly
slow version of gettimeofday() though ... I've never noticed such a
large discrepancy myself.

Actually, I'm noticing similar "problems" with v7.4 ... "EXPLAIN ANALYZE"
seems to be showing some *very* high ms for execution time, but if you run
the actual query, it doesn't seem to take even 1/10th the time reported
...

This is on a FreeBSD 4.x box ...

----
Marc G. Fournier Hub.Org Networking Services (http://www.hub.org)
Email: scrappy@hub.org Yahoo!: yscrappy ICQ: 7615664

"Marc G. Fournier" <scrappy@postgresql.org> writes:

Actually, I'm noticing similar "problems" with v7.4 ... "EXPLAIN ANALYZE"
seems to be showing some *very* high ms for execution time, but if you run
the actual query, it doesn't seem to take even 1/10th the time reported
...

Example? I don't see anything out of line here.

regards, tom lane

On Fri, 28 Nov 2003, Tom Lane wrote:

"Marc G. Fournier" <scrappy@postgresql.org> writes:

Actually, I'm noticing similar "problems" with v7.4 ... "EXPLAIN ANALYZE"
seems to be showing some *very* high ms for execution time, but if you run
the actual query, it doesn't seem to take even 1/10th the time reported
...

Example? I don't see anything out of line here.

pgsql74# /usr/local/pgsql/bin/psql -U pgsql -c "SELECT count(rec_id) FROM url" 186_archives
count
--------
209872
(1 row)

pgsql74# /usr/local/pgsql/bin/psql -U pgsql -c "EXPLAIN ANALYZE SELECT max(rec_id) FROM url" 186_archives
QUERY PLAN
--------------------------------------------------------------------------------------------------------------------
Aggregate (cost=11177.19..11177.19 rows=1 width=4) (actual time=2400.579..2400.585 rows=1 loops=1)
-> Seq Scan on url (cost=0.00..10741.55 rows=174255 width=4) (actual time=0.056..1387.803 rows=209872 loops=1)
Total runtime: 2407.095 ms
(3 rows)

pgsql74# time /usr/local/pgsql/bin/psql -U pgsql -c "SELECT max(rec_id) FROM url" 186_archives
max
--------
690582
(1 row)

0.000u 0.004s 0:00.32 0.0% 0+0k 0+0io 0pf+0w

----
Marc G. Fournier Hub.Org Networking Services (http://www.hub.org)
Email: scrappy@hub.org Yahoo!: yscrappy ICQ: 7615664

How many times is gettimeofday called?
wow=# explain analyze select 1;
QUERY PLAN

------------------------------------------------------------------------------------
Result (cost=0.00..0.01 rows=1 width=0) (actual time=0.008..0.010 rows=1 loops=1)
Total runtime: 0.047 ms
(2 rows)

Several thousands?

Tom Lane wrote:

Teodor Sigaev <teodor@sigaev.ru> writes:

Explain analyze takes 3 times more time for execution. Why?

Measurement overhead. It would seem your platform has a particularly
slow version of gettimeofday() though ... I've never noticed such a
large discrepancy myself.

regards, tom lane

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

--
Teodor Sigaev E-mail: teodor@sigaev.ru

Teodor Sigaev <teodor@sigaev.ru> writes:

How many times is gettimeofday called?

Twice per plan node visit, if you are doing EXPLAIN ANALYZE. (The
number of "visits" is one more than the number of rows returned.)

regards, tom lane

... if its just me mis-reading the numbers, let me
know ... it just "feels" off

Here's what I see:

time psql -c "explain analyze SELECT count(rec_id) FROM url" 186_archives

QUERY PLAN
--------------------------------------------------------------------------------------------------------------------
Aggregate (cost=11177.19..11177.19 rows=1 width=4) (actual time=3539.180..3539.184 rows=1 loops=1)
-> Seq Scan on url (cost=0.00..10741.55 rows=174255 width=4) (actual time=0.111..2292.234 rows=215552 loops=1)
Total runtime: 3539.922 ms
(3 rows)

0.006u 0.000s 0:03.57 0.0% 0+0k 0+0io 0pf+0w

So there doesn't seem to be any discrepancy between what EXPLAIN says
and what time(1) says. It is true that the overhead of EXPLAIN ANALYZE
looks a bit high:

time psql -c "SELECT count(rec_id) FROM url" 186_archives

count
--------
215169
(1 row)

0.000u 0.004s 0:00.77 0.0% 0+0k 0+0io 0pf+0w

If I'm doing the arithmetic correctly this makes the measurement
overhead about 13 microseconds per row. Presumably that's almost
entirely spent on the two gettimeofday() calls, so they are costing
upwards of 6 microseconds apiece, which seems like a lot for a modern
processor. Might be worth griping to the BSD kernel folk...

Still though I think we could be proud that we've gotten the price of
a seqscan down to the point where a couple of gettimeofday() calls per
row are dominating the runtime.

regards, tom lane

did you happen to take a look at the other set of queries I sent you, that
were showing 39k and 41k explain results? do they show pretty much the
same 'lag' in gettimeofday()?

On Fri, 28 Nov 2003, Tom Lane wrote:

... if its just me mis-reading the numbers, let me
know ... it just "feels" off

Here's what I see:

time psql -c "explain analyze SELECT count(rec_id) FROM url" 186_archives

QUERY PLAN
--------------------------------------------------------------------------------------------------------------------
Aggregate (cost=11177.19..11177.19 rows=1 width=4) (actual time=3539.180..3539.184 rows=1 loops=1)
-> Seq Scan on url (cost=0.00..10741.55 rows=174255 width=4) (actual time=0.111..2292.234 rows=215552 loops=1)
Total runtime: 3539.922 ms
(3 rows)

0.006u 0.000s 0:03.57 0.0% 0+0k 0+0io 0pf+0w

So there doesn't seem to be any discrepancy between what EXPLAIN says
and what time(1) says. It is true that the overhead of EXPLAIN ANALYZE
looks a bit high:

time psql -c "SELECT count(rec_id) FROM url" 186_archives

count
--------
215169
(1 row)

0.000u 0.004s 0:00.77 0.0% 0+0k 0+0io 0pf+0w

If I'm doing the arithmetic correctly this makes the measurement
overhead about 13 microseconds per row. Presumably that's almost
entirely spent on the two gettimeofday() calls, so they are costing
upwards of 6 microseconds apiece, which seems like a lot for a modern
processor. Might be worth griping to the BSD kernel folk...

Still though I think we could be proud that we've gotten the price of
a seqscan down to the point where a couple of gettimeofday() calls per
row are dominating the runtime.

regards, tom lane

----
Marc G. Fournier Hub.Org Networking Services (http://www.hub.org)
Email: scrappy@hub.org Yahoo!: yscrappy ICQ: 7615664

"Marc G. Fournier" <scrappy@postgresql.org> writes:

did you happen to take a look at the other set of queries I sent you, that
were showing 39k and 41k explain results?

You mean this one?

time psql -c "explain analyze select max(intag) from ndict3" 186_archives

QUERY PLAN
----------------------------------------------------------------------------------------------------------------------------
Aggregate (cost=40168.96..40168.96 rows=1 width=4) (actual time=48953.823..48953.827 rows=1 loops=1)
-> Seq Scan on ndict3 (cost=0.00..34560.57 rows=2243357 width=4) (actual time=4.903..-666785.605 rows=3516680 loops=1)
Total runtime: 48982.514 ms
(3 rows)

0.000u 0.005s 0:49.06 0.0% 0+0k 0+0io 0pf+0w

time psql -c "select max(intag) from ndict3" 186_archives

max
------------
2147418368
(1 row)

0.000u 0.005s 0:03.06 0.0% 0+0k 0+0io 0pf+0w

This looks like 46 seconds of overhead for 3516680 rows, or still right
about 13 microseconds per row, so that's consistent. The negative
"actual time" measurement for the Seq Scan row seems pretty broken
though :-(.

Now that I recall, didn't you complain of something similar with a beta?

regards, tom lane

Tom, I am afraid that I don't understand. My first example:
wow=# explain analyze select max(click.accesses) from click;
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------
Aggregate (cost=1103.70..1103.70 rows=1 width=8) (actual
time=289.391..289.393 rows=1 loops=1)
-> Seq Scan on click (cost=0.00..971.36 rows=52936 width=8) (actual
time=0.013..133.943 rows=52936 loops=1)
Total runtime: 289.498 ms
(3 rows)

Time: 290,695 ms

select max() returns only one row... If you mean rows in Seq Scan than
gettimeofday was called (52936+1)*2. Huge value :(

Tom Lane wrote:

Teodor Sigaev <teodor@sigaev.ru> writes:

How many times is gettimeofday called?

Twice per plan node visit, if you are doing EXPLAIN ANALYZE. (The
number of "visits" is one more than the number of rows returned.)

regards, tom lane

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

--
Teodor Sigaev E-mail: teodor@sigaev.ru

On Fri, 28 Nov 2003, Tom Lane wrote:

"Marc G. Fournier" <scrappy@postgresql.org> writes:

did you happen to take a look at the other set of queries I sent you, that
were showing 39k and 41k explain results?

You mean this one?

Yup ...

time psql -c "explain analyze select max(intag) from ndict3" 186_archives

QUERY PLAN
----------------------------------------------------------------------------------------------------------------------------
Aggregate (cost=40168.96..40168.96 rows=1 width=4) (actual time=48953.823..48953.827 rows=1 loops=1)
-> Seq Scan on ndict3 (cost=0.00..34560.57 rows=2243357 width=4) (actual time=4.903..-666785.605 rows=3516680 loops=1)
Total runtime: 48982.514 ms
(3 rows)

0.000u 0.005s 0:49.06 0.0% 0+0k 0+0io 0pf+0w

time psql -c "select max(intag) from ndict3" 186_archives

max
------------
2147418368
(1 row)

0.000u 0.005s 0:03.06 0.0% 0+0k 0+0io 0pf+0w

This looks like 46 seconds of overhead for 3516680 rows, or still right
about 13 microseconds per row, so that's consistent. The negative
"actual time" measurement for the Seq Scan row seems pretty broken
though :-(.

Now that I recall, didn't you complain of something similar with a beta?

Yup ... and I bet its not reproducible yet again, is it? :) That would
make for twice though, with v7.4, that I've come up with - results :)

----
Marc G. Fournier Hub.Org Networking Services (http://www.hub.org)
Email: scrappy@hub.org Yahoo!: yscrappy ICQ: 7615664

Teodor Sigaev <teodor@sigaev.ru> writes:

Tom, I am afraid that I don't understand. My first example:
wow=# explain analyze select max(click.accesses) from click;
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------
Aggregate (cost=1103.70..1103.70 rows=1 width=8) (actual
time=289.391..289.393 rows=1 loops=1)
-> Seq Scan on click (cost=0.00..971.36 rows=52936 width=8) (actual
time=0.013..133.943 rows=52936 loops=1)
Total runtime: 289.498 ms
(3 rows)

Time: 290,695 ms

select max() returns only one row... If you mean rows in Seq Scan than
gettimeofday was called (52936+1)*2. Huge value :(

Right, that many times at the Seq Scan plan node, and (1+1)*2 more times
at the Aggregate node.

regards, tom lane

"Marc G. Fournier" <scrappy@postgresql.org> writes:

On Fri, 28 Nov 2003, Tom Lane wrote:

Now that I recall, didn't you complain of something similar with a beta?

Yup ... and I bet its not reproducible yet again, is it? :) That would
make for twice though, with v7.4, that I've come up with - results :)

Well, it's not reproducibly negative, but it seems reproducibly wrong:

Aggregate (cost=40168.96..40168.96 rows=1 width=4) (actual time=49641.603..49641.611 rows=1 loops=1)
-> Seq Scan on ndict3 (cost=0.00..34560.57 rows=2243357 width=4) (actual time=34.854..724754.474 rows=3570252 loops=1)
Total runtime: 49688.524 ms

Aggregate (cost=40168.96..40168.96 rows=1 width=4) (actual time=36625.013..36625.018 rows=1 loops=1)
-> Seq Scan on ndict3 (cost=0.00..34560.57 rows=2243357 width=4) (actual time=0.128..-676113.173 rows=3572298 loops=1)
Total runtime: 36625.779 ms

Aggregate (cost=40168.96..40168.96 rows=1 width=4) (actual time=41380.881..41380.885 rows=1 loops=1)
-> Seq Scan on ndict3 (cost=0.00..34560.57 rows=2243357 width=4) (actual time=0.091..718200.092 rows=3575264 loops=1)
Total runtime: 41381.504 ms
(3 rows)

I'm wondering if there's an actual bug in gettimeofday() in this
platform, such that once in a while it returns a value that's off
a minute or so ...

regards, tom lane

None that I've heard of ... Sean?

Tom, any way of writing a quite test C program for this? Something to
'simulate' the same thing, but without having to build the whole
postmaster?

On Fri, 28 Nov 2003, Tom Lane wrote:

"Marc G. Fournier" <scrappy@postgresql.org> writes:

On Fri, 28 Nov 2003, Tom Lane wrote:

Now that I recall, didn't you complain of something similar with a beta?

Yup ... and I bet its not reproducible yet again, is it? :) That would
make for twice though, with v7.4, that I've come up with - results :)

Well, it's not reproducibly negative, but it seems reproducibly wrong:

Aggregate (cost=40168.96..40168.96 rows=1 width=4) (actual time=49641.603..49641.611 rows=1 loops=1)
-> Seq Scan on ndict3 (cost=0.00..34560.57 rows=2243357 width=4) (actual time=34.854..724754.474 rows=3570252 loops=1)
Total runtime: 49688.524 ms

Aggregate (cost=40168.96..40168.96 rows=1 width=4) (actual time=36625.013..36625.018 rows=1 loops=1)
-> Seq Scan on ndict3 (cost=0.00..34560.57 rows=2243357 width=4) (actual time=0.128..-676113.173 rows=3572298 loops=1)
Total runtime: 36625.779 ms

Aggregate (cost=40168.96..40168.96 rows=1 width=4) (actual time=41380.881..41380.885 rows=1 loops=1)
-> Seq Scan on ndict3 (cost=0.00..34560.57 rows=2243357 width=4) (actual time=0.091..718200.092 rows=3575264 loops=1)
Total runtime: 41381.504 ms
(3 rows)

I'm wondering if there's an actual bug in gettimeofday() in this
platform, such that once in a while it returns a value that's off
a minute or so ...

regards, tom lane

----
Marc G. Fournier Hub.Org Networking Services (http://www.hub.org)
Email: scrappy@hub.org Yahoo!: yscrappy ICQ: 7615664

I said:

I'm wondering if there's an actual bug in gettimeofday() in this
platform, such that once in a while it returns a value that's off
a minute or so ...

Whoa. Try the following test program. Then send it in to your friendly
local BSD hackers ....

uname -a

FreeBSD pgsql74.hub.org 4.9-PRERELEASE FreeBSD 4.9-PRERELEASE #3: Sat Sep 20 14:16:48 ADT 2003 root@neptune.hub.org:/usr/obj/usr/src/sys/kernel i386

./a.out

out of order tv_sec: 1070050646 939970, prev 1070051342 516165
out of order tv_sec: 1070051342 789127, prev 1070050646 939970
out of order tv_usec: 1070051342 789127, prev 1070050646 939970
out of order tv_sec: 1070050654 690255, prev 1070051350 216448
out of order tv_sec: 1070051350 402412, prev 1070050654 690255
out of order tv_usec: 1070051350 402412, prev 1070050654 690255
out of order tv_sec: 1070050672 990359, prev 1070051368 416546
out of order tv_sec: 1070051368 501648, prev 1070050672 990359
out of order tv_usec: 1070051368 501648, prev 1070050672 990359
out of order tv_sec: 1070050672 990363, prev 1070051368 516557
out of order tv_sec: 1070051368 700227, prev 1070050672 990363
out of order tv_usec: 1070051368 700227, prev 1070050672 990363
out of order tv_sec: 1070050675 740524, prev 1070051371 216718
out of order tv_sec: 1070051371 346521, prev 1070050675 740524
out of order tv_usec: 1070051371 346521, prev 1070050675 740524
out of order tv_sec: 1070050676 440415, prev 1070051371 916605
out of order tv_usec: 1070050676 440415, prev 1070051371 916605
out of order tv_sec: 1070051372 238348, prev 1070050676 440415
out of order tv_usec: 1070051372 238348, prev 1070050676 440415
^C

regards, tom lane

#include <stdio.h>
#include <sys/time.h>

int
main()
{
struct timeval prevtime;
struct timeval curtime;

gettimeofday(&prevtime, NULL);

for (;;)
{
gettimeofday(&curtime, NULL);

if (curtime.tv_usec < 0 || curtime.tv_usec >= 1000000)
fprintf(stderr, "bogus tv_usec: %ld %ld, prev %ld %ld\n",
(long int) curtime.tv_sec,
(long int) curtime.tv_usec,
(long int) prevtime.tv_sec,
(long int) prevtime.tv_usec);

if (curtime.tv_sec < prevtime.tv_sec ||
curtime.tv_sec > prevtime.tv_sec + 1)
fprintf(stderr, "out of order tv_sec: %ld %ld, prev %ld %ld\n",
(long int) curtime.tv_sec,
(long int) curtime.tv_usec,
(long int) prevtime.tv_sec,
(long int) prevtime.tv_usec);

if (curtime.tv_usec < prevtime.tv_usec &&
curtime.tv_sec != prevtime.tv_sec + 1)
fprintf(stderr, "out of order tv_usec: %ld %ld, prev %ld %ld\n",
(long int) curtime.tv_sec,
(long int) curtime.tv_usec,
(long int) prevtime.tv_sec,
(long int) prevtime.tv_usec);

prevtime = curtime;
}

return 0;
}

On November 28, 2003 12:33 pm, Tom Lane wrote:

I said:

I'm wondering if there's an actual bug in gettimeofday() in this
platform, such that once in a while it returns a value that's off
a minute or so ...

Whoa. Try the following test program. Then send it in to your friendly
local BSD hackers ....

uname -a

FreeBSD pgsql74.hub.org 4.9-PRERELEASE FreeBSD 4.9-PRERELEASE #3: Sat Sep
20 14:16:48 ADT 2003 root@neptune.hub.org:/usr/obj/usr/src/sys/kernel
i386

./a.out

out of order tv_sec: 1070050646 939970, prev 1070051342 516165
out of order tv_sec: 1070051342 789127, prev 1070050646 939970
out of order tv_usec: 1070051342 789127, prev 1070050646 939970
out of order tv_sec: 1070050654 690255, prev 1070051350 216448
out of order tv_sec: 1070051350 402412, prev 1070050654 690255
out of order tv_usec: 1070051350 402412, prev 1070050654 690255
out of order tv_sec: 1070050672 990359, prev 1070051368 416546
out of order tv_sec: 1070051368 501648, prev 1070050672 990359
out of order tv_usec: 1070051368 501648, prev 1070050672 990359
out of order tv_sec: 1070050672 990363, prev 1070051368 516557
out of order tv_sec: 1070051368 700227, prev 1070050672 990363
out of order tv_usec: 1070051368 700227, prev 1070050672 990363
out of order tv_sec: 1070050675 740524, prev 1070051371 216718
out of order tv_sec: 1070051371 346521, prev 1070050675 740524
out of order tv_usec: 1070051371 346521, prev 1070050675 740524
out of order tv_sec: 1070050676 440415, prev 1070051371 916605
out of order tv_usec: 1070050676 440415, prev 1070051371 916605
out of order tv_sec: 1070051372 238348, prev 1070050676 440415
out of order tv_usec: 1070051372 238348, prev 1070050676 440415
^C

I've been running this code on a pair of FreeBSD (i386) boxen, for some time
now, one of which is a 4.8-STABLE, the other is a 5.2-BETA.

In 10 minutes of execution the 4.8 box has only shown the following:

out of order tv_sec: 1070063393 115226, prev 1070063391 381087
out of order tv_usec: 1070063393 115226, prev 1070063391 381087

the 5.2 box, hasn't outputed anything. I'm goignt o run this test on some
other boxen I have and see what/ifany results are happening.

regards, tom lane

#include <stdio.h>
#include <sys/time.h>

int
main()
{
struct timeval prevtime;
struct timeval curtime;

gettimeofday(&prevtime, NULL);

for (;;)
{
gettimeofday(&curtime, NULL);

if (curtime.tv_usec < 0 || curtime.tv_usec >= 1000000)
fprintf(stderr, "bogus tv_usec: %ld %ld, prev %ld %ld\n",
(long int) curtime.tv_sec,
(long int) curtime.tv_usec,
(long int) prevtime.tv_sec,
(long int) prevtime.tv_usec);

if (curtime.tv_sec < prevtime.tv_sec ||
curtime.tv_sec > prevtime.tv_sec + 1)
fprintf(stderr, "out of order tv_sec: %ld %ld, prev %ld %ld\n",
(long int) curtime.tv_sec,
(long int) curtime.tv_usec,
(long int) prevtime.tv_sec,
(long int) prevtime.tv_usec);

if (curtime.tv_usec < prevtime.tv_usec &&
curtime.tv_sec != prevtime.tv_sec + 1)
fprintf(stderr, "out of order tv_usec: %ld %ld, prev %ld %ld\n",
(long int) curtime.tv_sec,
(long int) curtime.tv_usec,
(long int) prevtime.tv_sec,
(long int) prevtime.tv_usec);

prevtime = curtime;
}

return 0;
}

---------------------------(end of broadcast)---------------------------
TIP 8: explain analyze is your friend

--
Darcy Buskermolen
Wavefire Technologies Corp.
ph: 250.717.0200
fx: 250.763.1759
http://www.wavefire.com

Darcy Buskermolen <darcy@wavefire.com> writes:

On November 28, 2003 12:33 pm, Tom Lane wrote:

Whoa. Try the following test program. Then send it in to your friendly
local BSD hackers ....

I've been running this code on a pair of FreeBSD (i386) boxen, for some time
now, one of which is a 4.8-STABLE, the other is a 5.2-BETA.

Could it be a hardware problem on Marc's box? Or specific to some other
aspect of that installation (Marc, is pgsql74.hub.org multi-CPU, for
example?)

The failure is definitely quite repeatable on pgsql74.hub.org. I don't
see it on svr1.postgresql.org, though, which seems to be running almost
the same kernel.

regards, tom lane

I said:

The failure is definitely quite repeatable on pgsql74.hub.org. I don't
see it on svr1.postgresql.org, though, which seems to be running almost
the same kernel.

After looking more closely, I take that back: svr1 is failing too,
though not as often:

uname -a

FreeBSD svr1.postgresql.org 4.9-PRERELEASE FreeBSD 4.9-PRERELEASE #4: Sat Sep 20 14:41:58 ADT 2003 root@jupiter.hub.org:/usr/obj/usr/src/sys/kernel i386

./a.out

out of order tv_sec: 1070064182 410497, prev 1070064877 836691 <-----------
out of order tv_usec: 1070064182 410497, prev 1070064877 836691
out of order tv_sec: 1070064877 920579, prev 1070064182 410497
out of order tv_sec: 1070064901 126624, prev 1070064899 897160
out of order tv_usec: 1070064901 126624, prev 1070064899 897160
out of order tv_sec: 1070064907 306286, prev 1070064905 481423
out of order tv_usec: 1070064907 306286, prev 1070064905 481423
out of order tv_sec: 1070064218 861047, prev 1070064914 337241 <-----------
out of order tv_sec: 1070064914 570717, prev 1070064218 861047
out of order tv_usec: 1070064914 570717, prev 1070064218 861047
out of order tv_sec: 1070064241 411391, prev 1070064936 837585 <-----------
out of order tv_usec: 1070064241 411391, prev 1070064936 837585
out of order tv_sec: 1070064937 497925, prev 1070064241 411391
out of order tv_sec: 1070064251 811548, prev 1070064947 337739 <-----------
out of order tv_sec: 1070064947 508364, prev 1070064251 811548
out of order tv_usec: 1070064947 508364, prev 1070064251 811548

Maybe it's a 4.9-PRERELEASE bug?

regards, tom lane

On November 28, 2003 12:33 pm, Tom Lane wrote:

I said:

I'm wondering if there's an actual bug in gettimeofday() in this
platform, such that once in a while it returns a value that's off
a minute or so ...

Whoa. Try the following test program. Then send it in to your friendly
local BSD hackers ....

uname -a

FreeBSD pgsql74.hub.org 4.9-PRERELEASE FreeBSD 4.9-PRERELEASE #3: Sat Sep
20 14:16:48 ADT 2003 root@neptune.hub.org:/usr/obj/usr/src/sys/kernel
i386

./a.out

----8<------ snip
Further to my last email, after 30 minutes of running I was able to get
simular behavior off the 5.2 test system.

--
Darcy Buskermolen
Wavefire Technologies Corp.
ph: 250.717.0200
fx: 250.763.1759
http://www.wavefire.com