Re: That EXPLAIN ANALYZE patch still needs work

On Thu, Jun 08, 2006 at 04:58:07PM -0400, Tom Lane wrote:
> Simon Riggs <simon(at)2ndquadrant(dot)com> writes:
> > So the timing is clearly responsible for the additional time I'm
> > personally experiencing and very likely to be that for others also.
>
> Well, that's certainly unsurprising, but the question is why it's such
> a large overhead for you when it's not on other apparently-similar kit.
>
> If anyone else is still following this discussion, could you try the
> test case Simon gave a bit earlier (select count(*) from 100000-row
> table, check \timing with and without explain analyze)? If we could get
> a clearer picture of which platforms show the problem and which don't,
> maybe we could make some progress.
>
> (BTW, I just tried it on my Apple Powerbook G4, and got results in line
> with what I get elsewhere. So I've now tried it on three very different
> CPU types and OSes, and not duplicated Simon's problem on any of them.)

CPU: AMD Athlon(tm) 64 Processor 3500+ (2210.20-MHz K8-class CPU)
8.1.3 on amd64-portbld-freebsd6.0 25ms 353ms

CPU: AMD Opteron(tm) Processor 244 (1792.50-MHz K8-class CPU) (dual CPU)
8.1.4 on amd64-portbld-freebsd6.0 31ms 295ms

Powerbook G4 1.33GHz
8.1.4 on powerpc-apple-darwin8.6.0 5.1s 5.8s*

The powerbook tests were not very repeatable at 100,000 rows, so I
bumped up to 1M. The results still aren't very repeatable...
decibel=# select count(*) from i;
count
---------
1000000
(1 row)

Time: 4914.604 ms
decibel=# select count(*) from i;
count
---------
1000000
(1 row)

Time: 5186.516 ms
decibel=# select count(*) from i;
count
---------
1000000
(1 row)

Time: 5174.418 ms
decibel=# explain analyze select count(*) from i;
QUERY PLAN
-------------------------------------------------------------------------------------------------------------------
Aggregate (cost=16905.05..16905.06 rows=1 width=0) (actual time=5729.623..5729.624 rows=1 loops=1)
-> Seq Scan on i (cost=0.00..14405.24 rows=999924 width=0) (actual time=0.155..4039.317 rows=1000000 loops=1)
Total runtime: 5729.907 ms
(3 rows)

Time: 5732.076 ms
decibel=# explain analyze select count(*) from i;
QUERY PLAN
-------------------------------------------------------------------------------------------------------------------
Aggregate (cost=16905.05..16905.06 rows=1 width=0) (actual time=5916.025..5916.026 rows=1 loops=1)
-> Seq Scan on i (cost=0.00..14405.24 rows=999924 width=0) (actual time=0.157..4246.123 rows=1000000 loops=1)
Total runtime: 5916.261 ms
(3 rows)

Time: 5922.542 ms
decibel=# explain analyze select count(*) from i;
QUERY PLAN
-------------------------------------------------------------------------------------------------------------------
Aggregate (cost=16905.05..16905.06 rows=1 width=0) (actual time=5800.788..5800.789 rows=1 loops=1)
-> Seq Scan on i (cost=0.00..14405.24 rows=999924 width=0) (actual time=0.152..4126.781 rows=1000000 loops=1)
Total runtime: 5801.026 ms
(3 rows)

Time: 5803.070 ms
decibel=# explain analyze select count(*) from i;
QUERY PLAN
-------------------------------------------------------------------------------------------------------------------
Aggregate (cost=16905.05..16905.06 rows=1 width=0) (actual time=5994.285..5994.286 rows=1 loops=1)
-> Seq Scan on i (cost=0.00..14405.24 rows=999924 width=0) (actual time=0.156..4341.463 rows=1000000 loops=1)
Total runtime: 5994.520 ms
(3 rows)

Time: 5996.577 ms
--
Jim C. Nasby, Sr. Engineering Consultant jnasby(at)pervasive(dot)com
Pervasive Software http://pervasive.com work: 512-231-6117
vcard: http://jim.nasby.net/pervasive.vcf cell: 512-569-9461