Where does the time go?

From: "Kevin Grittner" <Kevin(dot)Grittner(at)wicourts(dot)gov>
To: <pgsql-hackers(at)postgresql(dot)org>
Subject: Where does the time go?
Date: 2006-03-23 00:09:09
Message-ID: 442192C5.EE98.0025.0@wicourts.gov
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-hackers pgsql-patches

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

Responses

Browse pgsql-hackers by date

  From Date Subject
Next Message Trent Shipley 2006-03-23 00:39:12 Re: Modular Type Libraries: was A real currency type
Previous Message Jim Buttafuoco 2006-03-23 00:03:56 create type error message

Browse pgsql-patches by date

  From Date Subject
Next Message Tom Lane 2006-03-23 02:59:52 Re: Where does the time go?
Previous Message Kris Jurka 2006-03-22 19:37:28 Re: WAL logging of SELECT ... INTO command