I have some odd results from timing two versions of an update query, and
was hoping to get a better handle on how to interpret this. The query
does an update of one table. One version does three NOT IN tests
against three related tables. The other version does the logically
equivalent NOT EXISTS tests. Here are the timings:

(a) NOT IN EXPLAIN ANALYZE reports: 150 ms.

(b) Difference between SELECT CURRENT_TIMESTAMP values before and
after the NOT IN EXPLAIN ANALYZE: 171 ms.

(c) Difference between SELECT CURRENT_TIMESTAMP values before and
after NOT IN query without EXPLAIN ANALYZE: 140 ms.

(d) NOT EXISTS EXPLAIN ANALYZE reports: 9 ms.

(e) Difference between SELECT CURRENT_TIMESTAMP values before and
after the NOT EXISTS EXPLAIN ANALYZE: 62 ms.

(f) Difference between SELECT CURRENT_TIMESTAMP values before and
after NOT EXISTS query without EXPLAIN ANALYZE: 62 ms.

I repeated these tests many times. After each test I updated the table
back to its original state and ran CLUSTER and VACUUM ANALYZE, then
allowed a minute of settling time. The timings are remarkably
consistent from one try to the next with an occasional outlier on the
high side.

It seems to me that these results indicate that EXPLAIN ANALYZE
distorts the plan for the IN query (b - c = 31 ms), but not the plan for
the EXISTS query (e == f). The time to bracket the UPDATE with the
SELECT CURRENT_TIMESTAMP queries can't exceed 21 ms (b - a). That seems
like a long time, though, so I suspect that some of that time is going
to the same place that most of the 53 ms (e - d) goes on the NOT EXISTS
query. Where would that be? Parse and plan phases? Is there a way to
pin that down better?

I was planning on posting the queries with plans and timings to
illustrate a costing issue, but when I saw these timings I figured I'd
ask about this first. It raises what seems like a more fundamental
question, which would have an impact on collecting all of the
interesting information. If execution time is 9 ms, but there is
something else adding several times that, perhaps that something else is
interesting in itself.

Thanks for any info.

-Kevin


---------------------------(end of broadcast)---------------------------
TIP 9: In versions below 8.0, the planner will ignore your desire to
choose an index scan if your joining column's datatypes do not
match

"Kevin Grittner" <Kevin.Grittner@wicourts.gov> writes:
> I have some odd results from timing two versions of an update query, and
> was hoping to get a better handle on how to interpret this.

You didn't show us the explain analyze results, but I'm betting that a
big part of your issue is that the EXPLAIN ANALYZE instrumentation
overhead is (1) significant and (2) different for the two query plans.
The instrumentation overhead should be about the same for any one plan
node execution, but the two plans could involve very different numbers
of plan node executions ...

regards, tom lane

---------------------------(end of broadcast)---------------------------
TIP 3: Have you checked our extensive FAQ?

http://www.postgresql.org/docs/faq

>>> On Wed, Mar 22, 2006 at 8:59 pm, in message
<27386.1143082792@sss.pgh.pa.us>,
Tom Lane <tgl@sss.pgh.pa.us> wrote:
> "Kevin Grittner" <Kevin.Grittner@wicourts.gov> writes:
> You didn't show us the explain analyze results,

The below is cut & paste directly from a psql run without editing.


bigbird=> UPDATE "User" SET "isActive" = TRUE WHERE "countyNo" = 13 and
"isActive" = FALSE;
UPDATE 0
bigbird=> cluster "User";
CLUSTER
bigbird=> vacuum analyze "User";
VACUUM
bigbird=> select current_timestamp;
now
----------------------------
2006-03-22 16:30:55.875-06
(1 row)

bigbird=> explain analyze
bigbird-> UPDATE "User"
bigbird-> SET "isActive" = FALSE
bigbird-> WHERE "countyNo" = 13
bigbird-> AND ("userId", "countyNo") NOT IN (SELECT "userId",
"countyNo" FROM "UserAuthority")
bigbird-> AND ("userId", "countyNo") NOT IN (SELECT "userId",
"countyNo" FROM "UserDivision")
bigbird-> AND ("userId", "countyNo") NOT IN (SELECT "userId",
"countyNo" FROM "UserCtofcAuthority");
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------
Index Scan using "User_pkey" on "User" (cost=2365.43..2499.34 rows=44
width=126) (actual time=145.968..147.061 rows=153 loops=1)
Index Cond: (("countyNo")::smallint = 13)
Filter: ((NOT (hashed subplan)) AND (NOT (hashed subplan)) AND (NOT
(hashed subplan)))
SubPlan
-> Seq Scan on "UserCtofcAuthority" (cost=0.00..332.65
rows=15565 width=14) (actual time=0.003..10.105 rows=15565 loops=1)
-> Seq Scan on "UserDivision" (cost=0.00..326.65 rows=15765
width=14) (actual time=0.003..10.409 rows=15764 loops=1)
-> Seq Scan on "UserAuthority" (cost=0.00..1451.24 rows=70624
width=14) (actual time=0.007..45.823 rows=70626 loops=1)
Total runtime: 150.340 ms
(8 rows)

bigbird=> select current_timestamp;
now
----------------------------
2006-03-22 16:30:56.046-06
(1 row)

bigbird=> UPDATE "User" SET "isActive" = TRUE WHERE "countyNo" = 13 and
"isActive" = FALSE;
UPDATE 153
bigbird=> cluster "User";
CLUSTER
bigbird=> vacuum analyze "User";
VACUUM
bigbird=> select current_timestamp;
now
----------------------------
2006-03-22 16:30:56.203-06
(1 row)

bigbird=> UPDATE "User"
bigbird-> SET "isActive" = FALSE
bigbird-> WHERE "countyNo" = 13
bigbird-> AND ("userId", "countyNo") NOT IN (SELECT "userId",
"countyNo" FROM "UserAuthority")
bigbird-> AND ("userId", "countyNo") NOT IN (SELECT "userId",
"countyNo" FROM "UserDivision")
bigbird-> AND ("userId", "countyNo") NOT IN (SELECT "userId",
"countyNo" FROM "UserCtofcAuthority");
UPDATE 153
bigbird=> select current_timestamp;
now
----------------------------
2006-03-22 16:30:56.343-06
(1 row)

bigbird=> UPDATE "User" SET "isActive" = TRUE WHERE "countyNo" = 13 and
"isActive" = FALSE;
UPDATE 153
bigbird=> cluster "User";
CLUSTER
bigbird=> vacuum analyze "User";
VACUUM
bigbird=> select current_timestamp;
now
----------------------------
2006-03-22 16:30:56.484-06
(1 row)

bigbird=> explain analyze
bigbird-> UPDATE "User"
bigbird-> SET "isActive" = FALSE
bigbird-> WHERE "countyNo" = 13
bigbird-> AND NOT EXISTS (SELECT * FROM "UserAuthority" a where
a."countyNo" = "User"."countyNo" and a."userId" = "User"."userId")
bigbird-> AND NOT EXISTS (SELECT * FROM "UserDivision" b where
b."countyNo" = "User"."countyNo" and b."userId" = "User"."userId")
bigbird-> AND NOT EXISTS (SELECT * FROM "UserCtofcAuthority" c
where c."countyNo" = "User"."countyNo" and c."userId" =
"User"."userId");

QUERY PLAN

-------------------------------------------------------------------------------------------------------------------------------------------------------------
Index Scan using "User_pkey" on "User" (cost=0.00..3650.67 rows=42
width=111) (actual time=0.057..5.722 rows=153 loops=1)
Index Cond: (("countyNo")::smallint = 13)
Filter: ((NOT (subplan)) AND (NOT (subplan)) AND (NOT (subplan)))
SubPlan
-> Index Scan using "UserCtofcAuthority_pkey" on
"UserCtofcAuthority" c (cost=0.00..3.48 rows=1 width=50) (actual
time=0.004..0.004 rows=0 loops=153)
Index Cond: ((("countyNo")::smallint = ($0)::smallint) AND
(("userId")::bpchar = ($1)::bpchar))
-> Index Scan using "UserDivision_pkey" on "UserDivision" b
(cost=0.00..3.53 rows=1 width=42) (actual time=0.006..0.006 rows=0
loops=156)
Index Cond: ((("countyNo")::smallint = ($0)::smallint) AND
(("userId")::bpchar = ($1)::bpchar))
-> Index Scan using "UserAuthority_pkey" on "UserAuthority" a
(cost=0.00..3.60 rows=1 width=42) (actual time=0.007..0.007 rows=1
loops=341)
Index Cond: ((("countyNo")::smallint = ($0)::smallint) AND
(("userId")::bpchar = ($1)::bpchar))
Total runtime: 9.136 ms
(11 rows)

bigbird=> select current_timestamp;
now
----------------------------
2006-03-22 16:30:56.546-06
(1 row)

bigbird=> UPDATE "User" SET "isActive" = TRUE WHERE "countyNo" = 13 and
"isActive" = FALSE;
UPDATE 153
bigbird=> cluster "User";
CLUSTER
bigbird=> vacuum analyze "User";
VACUUM
bigbird=> select current_timestamp;
now
----------------------------
2006-03-22 16:30:56.703-06
(1 row)

bigbird=> UPDATE "User"
bigbird-> SET "isActive" = FALSE
bigbird-> WHERE "countyNo" = 13
bigbird-> AND NOT EXISTS (SELECT * FROM "UserAuthority" a where
a."countyNo" = "User"."countyNo" and a."userId" = "User"."userId")
bigbird-> AND NOT EXISTS (SELECT * FROM "UserDivision" b where
b."countyNo" = "User"."countyNo" and b."userId" = "User"."userId")
bigbird-> AND NOT EXISTS (SELECT * FROM "UserCtofcAuthority" c
where c."countyNo" = "User"."countyNo" and c."userId" =
"User"."userId");
UPDATE 153
bigbird=> select current_timestamp;
now
----------------------------
2006-03-22 16:30:56.765-06
(1 row)


> I'm betting that a
> big part of your issue is that the EXPLAIN ANALYZE instrumentation
> overhead is (1) significant and (2) different for the two query
plans.

The run time of the NOT IN query, as measured by elapsed time between
SELECT CURRENT_TIMESTAMP executions, increased by 31 ms. The run time
of the NOT EXISTS did not increase measurably. I factored out the
EXPLAIN ANALYZE time in my original post for this topic. My question
was about where the REST of the time goes.

On this topic, I'm interested in the difference between the time
reported by the EXPLAIN ANALYZE and the elapsed time to run the query.
I've run a series of tests to determine what the minimum time is for a
query bracketed by SELECT CURRENT_TIMESTAMP statements for this
environment, and it is 12 ms (on average -- the time increments 15 ms to
16 ms at a time, which helps explain the odd consistency of the
timings). That leaves an unaccounted difference between the time
reported by EXPLAIN ANALYZE and the timestamp elapsed time of (on
average) 9 ms for the NOT IN form of the query, and 41 ms for the NOT
EXISTS for of the query. (In the run shown above, it's higher.) I'm
guessing that this is the time spent in parsing and planning the query.
Since for one query it is many times the actual run time reported by
EXPLAIN ANALYZE, it has piqued my interest. It's also interesting that
this time would be so much higher for one query than the other.

What is the best way to see where this time is going? (Or, if it is
obvious to those more familiar with the internals, please share.)

-Kevin


---------------------------(end of broadcast)---------------------------
TIP 4: Have you searched our list archives?

http://archives.postgresql.org

>>> On Thu, Mar 23, 2006 at 11:27 am, in message
<10223.1143134839@sss.pgh.pa.us>,
Tom Lane <tgl@sss.pgh.pa.us> wrote:
>> The run time of the NOT IN query, as measured by elapsed time
between
>> SELECT CURRENT_TIMESTAMP executions, increased by 31 ms.
>
> Works out to about 30 microsec per node execution, which seems a bit
> high for modern machines ... and the coarse quantization of the
> CURRENT_TIMESTAMP results is odd too. What platform is this on
exactly?

This is a smaller machine with a copy of the full production database.
A single 3.6 GHz Xeon with 4 GB RAM running Windows Server 2003. It was
being used to test update scripts before applying them to the production
machines. I stumbled across a costing issue I thought worth posting,
and in the course of gathering data noticed this time difference I
didn't understand.

>> What is the best way to see where this time is going?
>
> Profiling with gprof or some such tool might be educational.

Our builds are all done with --enable-debug, but this machine doesn't
even have msys installed. I'll try to put together some way to profile
it on this machine or some other. (It might be easier to move it to a
Linux machine and confirm the problem there, then profile.)

Thanks,

-Kevin



---------------------------(end of broadcast)---------------------------
TIP 9: In versions below 8.0, the planner will ignore your desire to
choose an index scan if your joining column's datatypes do not
match

>>> On Thu, Mar 23, 2006 at 11:27 am, in message
<10223.1143134839@sss.pgh.pa.us>,
Tom Lane <tgl@sss.pgh.pa.us> wrote:
> Profiling with gprof or some such tool might be educational.

I've never used gprof before, and from a quick scan of the info, it
appears that I need to compile and link a special version of the
software to generate the file that gprof needs. Is this correct? Does
it work on a Windows build, or will I need to use Linux? Any tips?

Thanks, all.

-Kevin


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

On Thu, Mar 23, 2006 at 12:29:27PM -0600, Kevin Grittner wrote:
> > Works out to about 30 microsec per node execution, which seems a
> > bit high for modern machines ... and the coarse quantization of the
> > CURRENT_TIMESTAMP results is odd too. What platform is this on
> > exactly?
>
> This is a smaller machine with a copy of the full production database.
> A single 3.6 GHz Xeon with 4 GB RAM running Windows Server 2003. It was
> being used to test update scripts before applying them to the production
> machines. I stumbled across a costing issue I thought worth posting,
> and in the course of gathering data noticed this time difference I
> didn't understand.

This may be the cause of the problem (windows). On UNIX platforms the
gettimeofday() call is used to calculate the timings in both cases. On
Windows the EXPLAIN ANALYZE measures time in a different way using the
CPU counters. It uses the interface but it will run into issues if the
CPU speed is not properly calculated or there is drift between the
different CPUs.

Here's one person who claims that the performance counter frequency is
often wrong:

http://archives.postgresql.org/pgsql...3/msg00063.php

It's also been pointed out before that the code actually divides by the
wrong number (it uses GetTimerFrequency() rather than
QueryPerformenceFrequency()). If you can find the values of these two
functions on your machine, see how it compares to your actual clock
speed.

Have a nice day,
--
Martijn van Oosterhout <kleptog@svana.org> http://svana.org/kleptog/
> Patent. n. Genius is 5% inspiration and 95% perspiration. A patent is a
> tool for doing 5% of the work and then sitting around waiting for someone
> else to do the other 95% so you can sue them.

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.1 (GNU/Linux)

iD8DBQFEIvs4IB7bNG8LQkwRAuR1AJ9N4A4e229FR1c4zdZ7xI gEh9j2SwCePp/h
ngaqMknStpgOECrEgyPzOLU=
=SFIo
-----END PGP SIGNATURE-----

"Kevin Grittner" <Kevin.Grittner@wicourts.gov> writes:
> I've never used gprof before, and from a quick scan of the info, it
> appears that I need to compile and link a special version of the
> software to generate the file that gprof needs. Is this correct? Does
> it work on a Windows build, or will I need to use Linux? Any tips?

I dunno anything about profiling on Windows. If you don't mind moving
the test case to Linux it's pretty easy:

./configure --enable-debug --whatever-other-options
make PROFILE="-pg -DLINUX_PROFILE"
install postgres executable

(On non-Linux Unixen you can omit that -D flag, but otherwise the recipe
is the same.)

Run the test case (you'll want a test script that does the same thing over
and over, enough times to build up a decent set of statistics; I like to
have about a minute's worth of accumulated CPU time in a profile run).
Exit the session --- the gmon.out file will only be dumped at backend
process exit. Then do

gprof /path/to/postgres-executable $PGDATA/gmon.out >outfile

BTW, in 8.1 you want to be sure to do this with autovacuum off, else
exit of the autovacuum process might clobber the gmon.out file before
you can run gprof.

regards, tom lane

---------------------------(end of broadcast)---------------------------
TIP 3: Have you checked our extensive FAQ?

http://www.postgresql.org/docs/faq

On Wed, 2006-03-22 at 21:59 -0500, Tom Lane wrote:

> I'm betting that a
> big part of your issue is that the EXPLAIN ANALYZE instrumentation
> overhead is (1) significant

I would like to implement an additional mode for EXPLAIN ANALYZE that
does no timing instrumentation at all. Most of the time just looking for
differences between estimated and actual row counts is all you need.

For long queries, the additional time can make the execution infeasible,
yet frequently they are the ones you want to see the output for.

EXPLAIN ANALYZE NOTIMING sounds a little dry, any ideas?

Best Regards, Simon Riggs


---------------------------(end of broadcast)---------------------------
TIP 2: Don't 'kill -9' the postmaster

Simon Riggs <simon@2ndquadrant.com> writes:
> I would like to implement an additional mode for EXPLAIN ANALYZE that
> does no timing instrumentation at all. Most of the time just looking for
> differences between estimated and actual row counts is all you need.

I don't really agree with that premise ... without timings, you cannot
for instance tell if the planner has over/underestimated the cost of an
index fetch.

regards, tom lane

---------------------------(end of broadcast)---------------------------
TIP 2: Don't 'kill -9' the postmaster

On Sat, Mar 25, 2006 at 10:00:51AM -0500, Tom Lane wrote:
> Simon Riggs <simon@2ndquadrant.com> writes:
> > I would like to implement an additional mode for EXPLAIN ANALYZE that
> > does no timing instrumentation at all. Most of the time just looking for
> > differences between estimated and actual row counts is all you need.
>
> I don't really agree with that premise ... without timings, you cannot
> for instance tell if the planner has over/underestimated the cost of an
> index fetch.

I agree. However, if it's the overhead of calling gettimeofday() that
slows everything down, perhaps we should tackle that end. For example,
have a sampling mode that only times say 5% of the executed nodes.

EXPLAIN ANALYZE SAMPLE blah;

And then in InstrStart have a quick test that skips the gettimeofday
for this interation sometimes. You'd probably need some heuristics
because you always want to catch the first iteration but after the
10,000th tuple in an indexscan, you're probably not going to learn
anything new.

You could do a non-random sampling fairly easily:

if( ntuples < 16 )
yes
else if( ntuples < 16*16 && (ntuples%16) == 0)
yes
else if( ntuples < 16*16*16 && ntuples%(16*16) == 0)
yes
else
etc etc etc

This mean that the more often a node is executed, the less often you
actually time it. Note, we store ntuples as a doulbe so the mod
operation won't work...

How does this sound?
--
Martijn van Oosterhout <kleptog@svana.org> http://svana.org/kleptog/
> Patent. n. Genius is 5% inspiration and 95% perspiration. A patent is a
> tool for doing 5% of the work and then sitting around waiting for someone
> else to do the other 95% so you can sue them.

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.1 (GNU/Linux)

iD8DBQFEJWCVIB7bNG8LQkwRAoUPAJ95Gzlxj9tm0J9qI3sQxq DUyZ1L1ACePFq3
/FN0ttGyAS0UHy7XMvGQts8=
=xzPU
-----END PGP SIGNATURE-----