Re: Where does the time go?

>>> On Wed, Mar 22, 2006 at 8:59 pm, in message
<27386(dot)1143082792(at)sss(dot)pgh(dot)pa(dot)us>,
Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
> "Kevin Grittner" <Kevin(dot)Grittner(at)wicourts(dot)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