Обсуждение: EXPLAIN (no ANALYZE) taking an hour for INSERT FROM SELECT

>What could cause this? Note that there is no ANALYZE.

Can you capture pstack and/or perf report while explain hangs?
I think it should shed light on the activity of PostgreSQL.

Vladimir

Hi,

On 5.3.2015 16:01, Gunnlaugur Thor Briem wrote:
> Hi, thanks for your follow-up questions.
>
> - postgres version is 9.1.13
> - the number of rows (in this latest instance) is 28,474,842
> - I've clustered and vacuum-full-ed and analyzed this table frequently,
> attempting to troubleshoot this. (Running vacuum full on the whole
> catalog seems a little excessive, and unlikely to help.)
> - no other processes are likely to be interfering; nothing other than
> PostgreSQL runs on this machine (except for normal OS processes and New
> Relic server monitoring service); concurrent activity in PostgreSQL is
> low-level and unrelated, and this effect is observed systematically
> whenever this kind of operation is performed on this table
> - no override for this table; the system default_statistics_target is
> 100 (the default)
> - yes, an ANALYZE is performed on the temp table after the COPY and
> before the INSERT
> - no index on the temp table (but I'm scanning the whole thing anyway).
> There are indexes on f_foo as detailed in my original post, and I expect
> the PK to make the WHERE NOT EXISTS filtering efficient (as it filters
> on exactly all columns of the PK) ... but even if it didn't, I would
> expect that to only slow down the actual insert execution, not the EXPLAIN.

The only thing I can think of is some sort of memory exhaustion,
resulting in swapping out large amounts of memory. That'd explain the
I/O load. Can you run something like vmstat to see if this really is swap?

The fact that plain INSERT does not do that contradicts that, as it
should be able to plan either both queries (plain and EXPLAIN), or none
of them.

Can you prepare a self-contained test case? I.e. a script that
demonstrates the issue? I tried to reproduce the issue using the
information provided so far, but unsuccessfully :-(

Even if you could reproduce the problem on another machine (because of
keeping the data internal) on a server with debug symbols and see where
most of the time is spent (e.g. using 'perf top'), that'd be useful.

regards

--
Tomas Vondra                http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Tomas Vondra <tomas.vondra@2ndquadrant.com> writes:
> On 5.3.2015 16:01, Gunnlaugur Thor Briem wrote:
>> - postgres version is 9.1.13

> The only thing I can think of is some sort of memory exhaustion,
> resulting in swapping out large amounts of memory.

I'm wondering about the issue addressed by commit fccebe421 ("Use
SnapshotDirty rather than an active snapshot to probe index endpoints").
Now, that was allegedly fixed in 9.1.13 ... but if the OP were confused
and this server were running, say, 9.1.12, that could be a viable
explanation.  Another possibly viable explanation for seeing the issue
in 9.1.13 would be if I fat-fingered the back-patch somehow :-(.

In any case, I concur with your advice:

> Even if you could reproduce the problem on another machine (because of
> keeping the data internal) on a server with debug symbols and see where
> most of the time is spent (e.g. using 'perf top'), that'd be useful.

Without some more-precise idea of where the time is going, we're really
just guessing as to the cause.

            regards, tom lane

On 6.3.2015 01:44, Tom Lane wrote:
> Tomas Vondra <tomas.vondra@2ndquadrant.com> writes:
>> On 5.3.2015 16:01, Gunnlaugur Thor Briem wrote:
>>> - postgres version is 9.1.13
>
>> The only thing I can think of is some sort of memory exhaustion,
>> resulting in swapping out large amounts of memory.
>
> I'm wondering about the issue addressed by commit fccebe421 ("Use
> SnapshotDirty rather than an active snapshot to probe index
> endpoints"). Now, that was allegedly fixed in 9.1.13 ... but if the
> OP were confused and this server were running, say, 9.1.12, that
> could be a viable explanation. Another possibly viable explanation
> for seeing the issue in 9.1.13 would be if I fat-fingered the
> back-patch somehow :-(.

How would fccebe421 explain the large amount of random writes (~4MB/s
for more than an hour), reported in the initial post? And why would that
only affect the EXPLAIN and not the bare query?

I guess there might be two sessions, one keeping uncommitted changes
(thus invisible tuples), and the other one doing the explain. And the
actual query might be executed after the first session does a commit.

But the random writes don't really match in this scenario ...


regards

--
Tomas Vondra                http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Tomas Vondra <tomas.vondra@2ndquadrant.com> writes:
> On 6.3.2015 01:44, Tom Lane wrote:
>> I'm wondering about the issue addressed by commit fccebe421 ("Use
>> SnapshotDirty rather than an active snapshot to probe index
>> endpoints").

> How would fccebe421 explain the large amount of random writes (~4MB/s
> for more than an hour), reported in the initial post? And why would that
> only affect the EXPLAIN and not the bare query?

Hard to say.  There's probably additional factors involved, and this
may ultimately turn out to be unrelated.  But it seemed like it might
be an issue, particularly since the plan had a mergejoin with lots of
clauses ...

            regards, tom lane

Tomas Vondra <tomas.vondra@2ndquadrant.com> wrote:
> On 6.3.2015 01:44, Tom Lane wrote:
>> Tomas Vondra <tomas.vondra@2ndquadrant.com> writes:
>>> On 5.3.2015 16:01, Gunnlaugur Thor Briem wrote:
>>>> - postgres version is 9.1.13
>>>
>>> The only thing I can think of is some sort of memory exhaustion,
>>> resulting in swapping out large amounts of memory.
>>
>> I'm wondering about the issue addressed by commit fccebe421 ("Use
>> SnapshotDirty rather than an active snapshot to probe index
>> endpoints"). Now, that was allegedly fixed in 9.1.13 ... but if the
>> OP were confused and this server were running, say, 9.1.12, that
>> could be a viable explanation. Another possibly viable explanation
>> for seeing the issue in 9.1.13 would be if I fat-fingered the
>> back-patch somehow :-(.
>
> How would fccebe421 explain the large amount of random writes (~4MB/s
> for more than an hour), reported in the initial post? And why would that
> only affect the EXPLAIN and not the bare query?
>
> I guess there might be two sessions, one keeping uncommitted changes
> (thus invisible tuples), and the other one doing the explain. And the
> actual query might be executed after the first session does a commit.
>
> But the random writes don't really match in this scenario ...

Sure they do -- both the index and heap pages may be rewritten with
hints that the rows are dead.  In this email:

http://www.postgresql.org/message-id/19685.1384307200@sss.pgh.pa.us

... Tom said:

| The other thing we might consider doing is using SnapshotAny, which
| would amount to just taking the extremal index entry at face value.
| This would be cheap all right (in fact, we might later be able to optimize
| it to not even visit the heap).  However, I don't like the implications
| for the accuracy of the approximation.  It seems quite likely that an
| erroneous transaction could insert a wildly out-of-range index entry
| and then roll back --- or even if it committed, somebody might soon come
| along and clean up the bogus entry in a separate transaction.  If we use
| SnapshotAny then we'd believe that bogus entry until it got vacuumed, not
| just till it got deleted.  This is a fairly scary proposition, because
| the wackier that extremal value is, the more impact it will have on the
| selectivity estimates.
|
| If it's demonstrated that SnapshotDirty doesn't reduce the estimation
| costs enough to solve the performance problem the complainants are facing,
| I'd be willing to consider using SnapshotAny here.  But I don't want to
| take that step until it's proven that the more conservative approach
| doesn't solve the performance problem.

I wonder whether this isn't an example of a case where SnapshotAny
would do better.  I have definitely seen cases where BIND time on a
bloated database has exceeded all other PostgreSQL time combined --
in this planner probe of the index.  I haven't seen two hours on a
single EXPLAIN, but I have seen it be several times the execution
time.

Regarding the concerns about the accuracy of the estimate and the
effects on the planner that an incorrect selectivity estimate could
have -- clearly scanning a large number of index tuples and chasing
them to the heap just to find that the tuples are not visible is
about as expensive as if they were visible *for the index scan step
itself*.  I wonder whether there would be any way to allow the
index scan cost to be based on the work it has to do while somehow
generating a reasonable number for the rows it will find to be
visible, so that estimation of other nodes can be based on that.

--
Kevin Grittner
EDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

Kevin Grittner <kgrittn@ymail.com> writes:
> Tomas Vondra <tomas.vondra@2ndquadrant.com> wrote:
>> How would fccebe421 explain the large amount of random writes (~4MB/s
>> for more than an hour), reported in the initial post? And why would that
>> only affect the EXPLAIN and not the bare query?
>> But the random writes don't really match in this scenario ...

> Sure they do -- both the index and heap pages may be rewritten with
> hints that the rows are dead.

Hm ... yeah, this idea could match the symptoms: if the database has built
up a large debt of dead-but-unhinted rows, then the first pass through the
index would cause a write storm but the next would not, which would
explain why doing EXPLAIN immediately followed by the real query would put
all the hint-update burden on the EXPLAIN even though the planning phase
of the real query would inspect the same index entries.

But if that's the situation, those hint-updating writes would get done
sooner or later --- probably sooner, by actual execution of the query
itself.  So I'm not convinced that moving to SnapshotAny would fix
anything much, only change where the problem manifests.

Also, it's less than clear why only this particular query is showing
any stress.  Dead rows should be a hazard for anything, especially if
there are enough of them to require hours to re-hint.  And why wouldn't
autovacuum get to them first?

            regards, tom lane

On 7.3.2015 03:26, Jeff Janes wrote:
> On Fri, Mar 6, 2015 at 5:38 PM, Tom Lane <tgl@sss.pgh.pa.us
> <mailto:tgl@sss.pgh.pa.us>> wrote:
>
> But the actual query is using a seq scan, and so it would hint the
> table in efficient sequential order, rather than hinting the table
> haphazardly in index order like probing the endpoint does.

I think this has nothing to do with the plan itself, but with the
estimation in optimizer - that looks up the range from the index in some
cases, and that may generate random I/O to the table.

>
>> Also, it's less than clear why only this particular query is
>> showing any stress. Dead rows should be a hazard for anything,
>> especially if there are enough of them to require hours to re-hint.
>> And why wouldn't autovacuum get to them first?
>
>
> Say the timing of this query is such that 10% of the parent turns
> over between invocations of this query, and that this 10% is all at
> the end of some index but random over the table heap. If autovac
> kicks in at 20% turn over, then half the time autovac does get to
> them first, and half the time it doesn't. It would be interesting to
> know if this query is bad every time it is planner, or just
> sometimes.

Yeah, this might be the reason. Another possibility is that this is part
of some large batch, and autovacuum simply did not have change to do the
work.

regards

--
Tomas Vondra                http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Gunnlaugur Thor Briem <gunnlaugur@gmail.com> writes:
> Yes, I think that's it: I've just realized that immediately prior to the
> INSERT, in the same transaction, an unfiltered DELETE has been issued; i.e.
> the whole table is being rewritten. Then the INSERT is issued ... with a
> WHERE clause on non-existence in the (now empty) table.

> In that case of course the WHERE clause is unnecessary, as it will always
> evaluate as true (and we've locked the whole table for writes). Looks like
> it is a lot worse than unnecessary, though, if it triggers this performance
> snafu in EXPLAIN INSERT.

Ah-hah.  So what's happening is that the planner is doing an indexscan
over the entire table of now-dead rows, looking vainly for an undeleted
maximal row.  Ouch.

I wonder how hard it would be to make the indexscan give up after hitting
N consecutive dead rows, for some suitable N, maybe ~1000.  From the
planner's viewpoint it'd be easy enough to fall back to using whatever
it had in the histogram after all.  But that's all happening down inside
index_getnext, and I'm hesitant to stick some kind of wart into that
machinery for this purpose.

            regards, tom lane

On 11.3.2015 18:30, Jeff Janes wrote:
> On Sat, Mar 7, 2015 at 7:44 AM, Tomas Vondra
> <tomas.vondra@2ndquadrant.com <mailto:tomas.vondra@2ndquadrant.com>> wrote:
>
>     On 7.3.2015 03:26, Jeff Janes wrote:
>     > On Fri, Mar 6, 2015 at 5:38 PM, Tom Lane <tgl@sss.pgh.pa.us <mailto:tgl@sss.pgh.pa.us>
>     > <mailto:tgl@sss.pgh.pa.us <mailto:tgl@sss.pgh.pa.us>>> wrote:
>     >
>     > But the actual query is using a seq scan, and so it would hint the
>     > table in efficient sequential order, rather than hinting the table
>     > haphazardly in index order like probing the endpoint does.
>
>     I think this has nothing to do with the plan itself, but with the
>     estimation in optimizer - that looks up the range from the index in some
>     cases, and that may generate random I/O to the table.
>
>
> Right.  Tom was saying that the work needs to be done anyway, but it is
> just that some ways of doing the work are far more efficient than
> others.  It just happens that the executed plan in this case would do it
> more efficiently, (but in general you aren't going to get any less
> efficient than having the planner do it in index order).

Oh! Now I see what you meant. I parsed is as if you're suggesting that
the theory does not match the symptoms because the plan contains
sequential scan yet there's a lot of random I/O. But now I see that's
not what you claimed, so sorry for the noise.



--
Tomas Vondra                http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

On 3/11/15 11:15 AM, Tom Lane wrote:
> Gunnlaugur Thor Briem <gunnlaugur@gmail.com> writes:
>> Yes, I think that's it: I've just realized that immediately prior to the
>> INSERT, in the same transaction, an unfiltered DELETE has been issued; i.e.
>> the whole table is being rewritten. Then the INSERT is issued ... with a
>> WHERE clause on non-existence in the (now empty) table.
>
>> In that case of course the WHERE clause is unnecessary, as it will always
>> evaluate as true (and we've locked the whole table for writes). Looks like
>> it is a lot worse than unnecessary, though, if it triggers this performance
>> snafu in EXPLAIN INSERT.
>
> Ah-hah.  So what's happening is that the planner is doing an indexscan
> over the entire table of now-dead rows, looking vainly for an undeleted
> maximal row.  Ouch.
>
> I wonder how hard it would be to make the indexscan give up after hitting
> N consecutive dead rows, for some suitable N, maybe ~1000.  From the
> planner's viewpoint it'd be easy enough to fall back to using whatever
> it had in the histogram after all.  But that's all happening down inside
> index_getnext, and I'm hesitant to stick some kind of wart into that
> machinery for this purpose.

ISTM what we really want here is a time-based behavior, not number of
rows. Given that, could we do the index probe in a subtransaction, set
an alarm for X ms, and simply abort the subtransaction if the alarm fires?
--
Jim Nasby, Data Architect, Blue Treble Consulting
Data in Trouble? Get it in Treble! http://BlueTreble.com

On 3/11/15 10:54 AM, Gunnlaugur Thor Briem wrote:
> (Even better, just make the new table not temporary, and have it replace
> the former table altogether. But that's for later; requires some broader
> changes in our application.)

The other thing you should consider is using TRUNCATE instead of an
un-filtered DELETE. It will both be much faster to perform and won't
leave any dead rows behind.
--
Jim Nasby, Data Architect, Blue Treble Consulting
Data in Trouble? Get it in Treble! http://BlueTreble.com