Horton

Thread

  1. ToDo: log plans of cancelled queries

    Pavel Stehule <pavel.stehule@gmail.com> — 2013-01-11T12:42:44Z

    Hello

We use successfully use auto_explain. We miss support cancelled
queries - we need same info for queries, that we cancel after x
minutes.

Subtask of this feature can be dumping currently executed query with
plan and with complete query string to log after receiving some signal
- maybe SIGTRAP.

What do you thinking about this feature?

Regards

Pavel Stehule

  2. Re: ToDo: log plans of cancelled queries

    Tom Lane <tgl@sss.pgh.pa.us> — 2013-01-11T15:31:24Z

    Pavel Stehule <pavel.stehule@gmail.com> writes:
> What do you thinking about this feature?

The idea of expecting an add-on module to execute operations in an
already-failed transaction seems pretty dubious to me.  I also think
it's not a great idea to add partial executions into a query's stats.
For instance, suppose query X has been done 3 times and took a minute
each time.  The fourth time, the user cancels it after one second.
If we now report that the query's average execution time is 45 seconds
or so, that seems pretty misleading to me.

			regards, tom lane

  3. Re: ToDo: log plans of cancelled queries

    Pavel Stehule <pavel.stehule@gmail.com> — 2013-01-11T15:42:03Z

    2013/1/11 Tom Lane <tgl@sss.pgh.pa.us>:
> Pavel Stehule <pavel.stehule@gmail.com> writes:
>> What do you thinking about this feature?
>
> The idea of expecting an add-on module to execute operations in an
> already-failed transaction seems pretty dubious to me.  I also think
> it's not a great idea to add partial executions into a query's stats.
> For instance, suppose query X has been done 3 times and took a minute
> each time.  The fourth time, the user cancels it after one second.
> If we now report that the query's average execution time is 45 seconds
> or so, that seems pretty misleading to me.

I don't propose logging query time for cancelled queries - although we
have path that do it - but it is our specific issue.

My propose is proposed for different dimensions and purpose - for
example - we have a limit 20 minutes for almost all queries, and after
this limit we killing queries. But we have to know little bit more
about these bad queries - and we hope, so execution plan can give this
additional info. We have same motivation like people who use
auto_explain for slow query - but we can't to wait to query complete.

Regards

Pavel

>
>                         regards, tom lane

  4. Re: ToDo: log plans of cancelled queries

    Stephen Frost <sfrost@snowman.net> — 2013-01-11T15:47:48Z

    * Pavel Stehule (pavel.stehule@gmail.com) wrote:
> My propose is proposed for different dimensions and purpose - for
> example - we have a limit 20 minutes for almost all queries, and after
> this limit we killing queries. But we have to know little bit more
> about these bad queries - and we hope, so execution plan can give this
> additional info. We have same motivation like people who use
> auto_explain for slow query - but we can't to wait to query complete.

Why not an option to auto_explain (or whatever) to log an execution plan
right before actually executing it?  If that was something which could
be set with a GUC or similar, you could just do that before running
whatever queries you're interested in capturing the plans for.

	Thanks,

		Stephen

  5. Re: ToDo: log plans of cancelled queries

    Tom Lane <tgl@sss.pgh.pa.us> — 2013-01-11T15:48:14Z

    Pavel Stehule <pavel.stehule@gmail.com> writes:
> My propose is proposed for different dimensions and purpose - for
> example - we have a limit 20 minutes for almost all queries, and after
> this limit we killing queries. But we have to know little bit more
> about these bad queries - and we hope, so execution plan can give this
> additional info. We have same motivation like people who use
> auto_explain for slow query - but we can't to wait to query complete.

Oh, sorry, not enough caffeine yet --- somehow I was thinking about
pg_stat_statements not auto_explain.

However, auto_explain is even worse on the other problem.  You flat out
cannot do catalog lookups in a failed transaction, but there's no way to
print a decompiled plan without such lookups.  So it won't work.  (It
would also be appropriate to be suspicious of whether the executor's
plan state tree is even fully set up at the time the error is thrown...)

			regards, tom lane

  6. Re: ToDo: log plans of cancelled queries

    Pavel Stehule <pavel.stehule@gmail.com> — 2013-01-11T15:51:32Z

    2013/1/11 Stephen Frost <sfrost@snowman.net>:
> * Pavel Stehule (pavel.stehule@gmail.com) wrote:
>> My propose is proposed for different dimensions and purpose - for
>> example - we have a limit 20 minutes for almost all queries, and after
>> this limit we killing queries. But we have to know little bit more
>> about these bad queries - and we hope, so execution plan can give this
>> additional info. We have same motivation like people who use
>> auto_explain for slow query - but we can't to wait to query complete.
>
> Why not an option to auto_explain (or whatever) to log an execution plan
> right before actually executing it?  If that was something which could
> be set with a GUC or similar, you could just do that before running
> whatever queries you're interested in capturing the plans for.

for our OLAP usage it is probably possible, but it can be slow for OLTP usage..

Regards

Pavel

>
>         Thanks,
>
>                 Stephen

  7. Re: ToDo: log plans of cancelled queries

    Alvaro Herrera <alvherre@2ndquadrant.com> — 2013-01-11T15:54:15Z

    Tom Lane escribió:
> Pavel Stehule <pavel.stehule@gmail.com> writes:
> > My propose is proposed for different dimensions and purpose - for
> > example - we have a limit 20 minutes for almost all queries, and after
> > this limit we killing queries. But we have to know little bit more
> > about these bad queries - and we hope, so execution plan can give this
> > additional info. We have same motivation like people who use
> > auto_explain for slow query - but we can't to wait to query complete.
> 
> Oh, sorry, not enough caffeine yet --- somehow I was thinking about
> pg_stat_statements not auto_explain.
> 
> However, auto_explain is even worse on the other problem.  You flat out
> cannot do catalog lookups in a failed transaction, but there's no way to
> print a decompiled plan without such lookups.  So it won't work.  (It
> would also be appropriate to be suspicious of whether the executor's
> plan state tree is even fully set up at the time the error is thrown...)

Maybe it'd work to save the query source text and parameter values
somewhere and log an explain in a different session.

-- 
Álvaro Herrera                http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services

  8. Re: ToDo: log plans of cancelled queries

    Pavel Stehule <pavel.stehule@gmail.com> — 2013-01-11T16:05:41Z

    2013/1/11 Tom Lane <tgl@sss.pgh.pa.us>:
> Pavel Stehule <pavel.stehule@gmail.com> writes:
>> My propose is proposed for different dimensions and purpose - for
>> example - we have a limit 20 minutes for almost all queries, and after
>> this limit we killing queries. But we have to know little bit more
>> about these bad queries - and we hope, so execution plan can give this
>> additional info. We have same motivation like people who use
>> auto_explain for slow query - but we can't to wait to query complete.
>
> Oh, sorry, not enough caffeine yet --- somehow I was thinking about
> pg_stat_statements not auto_explain.
>
> However, auto_explain is even worse on the other problem.  You flat out
> cannot do catalog lookups in a failed transaction, but there's no way to
> print a decompiled plan without such lookups.  So it won't work.  (It
> would also be appropriate to be suspicious of whether the executor's
> plan state tree is even fully set up at the time the error is thrown...)

yes, it is - I have a few ideas

1) using signal handler - we don't use a SIGTRAP - so we can use
SIGTRAP (for example) - and inside signal handler we can ensure dump
of plan. It has one advantage - we can take a plan - and maybe more
without query cancelling - somebody can have significantly higher
limit then we, but he would to know a plan.

2) creating some hook for some operations called before query is
really cancelled - this can be called before exception is raised, so
we can materialise plan without problem in this moment. This hook can
be used for auto_explain, because we don't would to print plans for
queries that was faster cancelled than auto_explain limit is it. Maybe
this hook can be called before raising more kinds of exceptions -
across temp file limits. We are not interested on queries that was
finished different errors - because these errors coming quickly
usually.

From my perspective some possible integration with auto_explain can be
nice, I would not to set limits on more places.

Regards

Pavel


>
>                         regards, tom lane

  9. Re: ToDo: log plans of cancelled queries

    Simon Riggs <simon@2ndquadrant.com> — 2013-01-11T16:10:07Z

    On 11 January 2013 15:54, Alvaro Herrera <alvherre@2ndquadrant.com> wrote:
> Tom Lane escribió:
>> Pavel Stehule <pavel.stehule@gmail.com> writes:
>> > My propose is proposed for different dimensions and purpose - for
>> > example - we have a limit 20 minutes for almost all queries, and after
>> > this limit we killing queries. But we have to know little bit more
>> > about these bad queries - and we hope, so execution plan can give this
>> > additional info. We have same motivation like people who use
>> > auto_explain for slow query - but we can't to wait to query complete.
>>
>> Oh, sorry, not enough caffeine yet --- somehow I was thinking about
>> pg_stat_statements not auto_explain.
>>
>> However, auto_explain is even worse on the other problem.  You flat out
>> cannot do catalog lookups in a failed transaction, but there's no way to
>> print a decompiled plan without such lookups.  So it won't work.  (It
>> would also be appropriate to be suspicious of whether the executor's
>> plan state tree is even fully set up at the time the error is thrown...)
>
> Maybe it'd work to save the query source text and parameter values
> somewhere and log an explain in a different session.

I think this would be an important feature.

But then I also want to be able to kill a query without it doing 50
pushups and a backflip before it dies, since that will inevitably go
wrong.

Perhaps we can have a new signal that means "exit gracefully, with
info if requested". That way we can keep "kill" to mean "kill".

An even better feature would be to be able to send a signal to a
running query to log its currently executing plan. That way you can
ask "Why so slow?" before deciding to kill it. That way we don't need
to overload the kill signal at all. That's the most useful part of a
"progress indicator" tool without the complexity.

-- 
 Simon Riggs                   http://www.2ndQuadrant.com/
 PostgreSQL Development, 24x7 Support, Training & Services

  10. Re: ToDo: log plans of cancelled queries

    Tom Lane <tgl@sss.pgh.pa.us> — 2013-01-11T16:11:11Z

    Alvaro Herrera <alvherre@2ndquadrant.com> writes:
> Tom Lane escribi:
>> However, auto_explain is even worse on the other problem.  You flat out
>> cannot do catalog lookups in a failed transaction, but there's no way to
>> print a decompiled plan without such lookups.  So it won't work.  (It
>> would also be appropriate to be suspicious of whether the executor's
>> plan state tree is even fully set up at the time the error is thrown...)

> Maybe it'd work to save the query source text and parameter values
> somewhere and log an explain in a different session.

There wouldn't be a lot of certainty that you got the same plan.

AFAICS the only thing you could do is what Stephen suggested: run
EXPLAIN *before* starting the query.  You could stash the text somewhere
and only print it on failure, which would prevent useless log bloat.
But it'd still be awfully expensive.

			regards, tom lane

  11. Re: ToDo: log plans of cancelled queries

    Stephen Frost <sfrost@snowman.net> — 2013-01-11T16:15:13Z

    * Pavel Stehule (pavel.stehule@gmail.com) wrote:
> 2013/1/11 Stephen Frost <sfrost@snowman.net>:
> > Why not an option to auto_explain (or whatever) to log an execution plan
> > right before actually executing it?  If that was something which could
> > be set with a GUC or similar, you could just do that before running
> > whatever queries you're interested in capturing the plans for.
> 
> for our OLAP usage it is probably possible, but it can be slow for OLTP usage..

If it was a GUC, you could turn it on/off at appropriate places in the
OLTP scenario.

	Thanks,

		Stephen

  12. Re: ToDo: log plans of cancelled queries

    Tom Lane <tgl@sss.pgh.pa.us> — 2013-01-11T16:20:23Z

    Simon Riggs <simon@2ndQuadrant.com> writes:
> An even better feature would be to be able to send a signal to a
> running query to log its currently executing plan. That way you can
> ask "Why so slow?" before deciding to kill it.

That could conceivably work.  At least it wouldn't require running
EXPLAIN in a failed transaction.

			regards, tom lane

  13. Re: ToDo: log plans of cancelled queries

    Pavel Stehule <pavel.stehule@gmail.com> — 2013-01-11T16:20:39Z

    2013/1/11 Stephen Frost <sfrost@snowman.net>:
> * Pavel Stehule (pavel.stehule@gmail.com) wrote:
>> 2013/1/11 Stephen Frost <sfrost@snowman.net>:
>> > Why not an option to auto_explain (or whatever) to log an execution plan
>> > right before actually executing it?  If that was something which could
>> > be set with a GUC or similar, you could just do that before running
>> > whatever queries you're interested in capturing the plans for.
>>
>> for our OLAP usage it is probably possible, but it can be slow for OLTP usage..
>
> If it was a GUC, you could turn it on/off at appropriate places in the
> OLTP scenario.

yes, it is possible solution

Pavel

>
>         Thanks,
>
>                 Stephen

  14. Re: ToDo: log plans of cancelled queries

    Pavel Stehule <pavel.stehule@gmail.com> — 2013-01-11T16:24:11Z

    2013/1/11 Stephen Frost <sfrost@snowman.net>:
> * Pavel Stehule (pavel.stehule@gmail.com) wrote:
>> 2013/1/11 Stephen Frost <sfrost@snowman.net>:
>> > Why not an option to auto_explain (or whatever) to log an execution plan
>> > right before actually executing it?  If that was something which could
>> > be set with a GUC or similar, you could just do that before running
>> > whatever queries you're interested in capturing the plans for.
>>
>> for our OLAP usage it is probably possible, but it can be slow for OLTP usage..
>
> If it was a GUC, you could turn it on/off at appropriate places in the
> OLTP scenario.

but still - if this is a auto_explain feature - then we need to return
execution to auto_explain after cancelled query - and it is probably
impossible now

Regards

Pavel

>
>         Thanks,
>
>                 Stephen

  15. Re: ToDo: log plans of cancelled queries

    Stephen Frost <sfrost@snowman.net> — 2013-01-11T16:28:01Z

    * Tom Lane (tgl@sss.pgh.pa.us) wrote:
> Simon Riggs <simon@2ndQuadrant.com> writes:
> > An even better feature would be to be able to send a signal to a
> > running query to log its currently executing plan. That way you can
> > ask "Why so slow?" before deciding to kill it.
> 
> That could conceivably work.  At least it wouldn't require running
> EXPLAIN in a failed transaction.

I like this idea, in general, also.  Taking that to the next level would
be figuring out how you can do the same kind of thing through an
interactive psql session where the user running the query doesn't need
access to the database server or PG log files...

We can send a 'cancel query', how about a 'report on query' which
returns the plan and perhaps whatever other stats are easily available?

	Thanks,

		Stephen

  16. Re: ToDo: log plans of cancelled queries

    Pavel Stehule <pavel.stehule@gmail.com> — 2013-01-11T16:31:59Z

    2013/1/11 Stephen Frost <sfrost@snowman.net>:
> * Tom Lane (tgl@sss.pgh.pa.us) wrote:
>> Simon Riggs <simon@2ndQuadrant.com> writes:
>> > An even better feature would be to be able to send a signal to a
>> > running query to log its currently executing plan. That way you can
>> > ask "Why so slow?" before deciding to kill it.
>>
>> That could conceivably work.  At least it wouldn't require running
>> EXPLAIN in a failed transaction.
>
> I like this idea, in general, also.  Taking that to the next level would
> be figuring out how you can do the same kind of thing through an
> interactive psql session where the user running the query doesn't need
> access to the database server or PG log files...
>

this is simple - it can be printed via elog(WARNING, ...) to original console

> We can send a 'cancel query', how about a 'report on query' which
> returns the plan and perhaps whatever other stats are easily available?

there is only one question - that POSIX signal we can use?

Pavel

>
>         Thanks,
>
>                 Stephen

  17. Re: ToDo: log plans of cancelled queries

    Pavel Stehule <pavel.stehule@gmail.com> — 2013-01-11T16:34:01Z

    2013/1/11 Pavel Stehule <pavel.stehule@gmail.com>:
> 2013/1/11 Stephen Frost <sfrost@snowman.net>:
>> * Tom Lane (tgl@sss.pgh.pa.us) wrote:
>>> Simon Riggs <simon@2ndQuadrant.com> writes:
>>> > An even better feature would be to be able to send a signal to a
>>> > running query to log its currently executing plan. That way you can
>>> > ask "Why so slow?" before deciding to kill it.
>>>
>>> That could conceivably work.  At least it wouldn't require running
>>> EXPLAIN in a failed transaction.
>>
>> I like this idea, in general, also.  Taking that to the next level would
>> be figuring out how you can do the same kind of thing through an
>> interactive psql session where the user running the query doesn't need
>> access to the database server or PG log files...
>>
>
> this is simple - it can be printed via elog(WARNING, ...) to original console

theoretically we can show current state via EXPLAIN ANALYSE result

>
>> We can send a 'cancel query', how about a 'report on query' which
>> returns the plan and perhaps whatever other stats are easily available?
>
> there is only one question - that POSIX signal we can use?
>
> Pavel
>
>>
>>         Thanks,
>>
>>                 Stephen

  18. Re: ToDo: log plans of cancelled queries

    Stephen Frost <sfrost@snowman.net> — 2013-01-11T16:41:24Z

    * Pavel Stehule (pavel.stehule@gmail.com) wrote:
> 2013/1/11 Stephen Frost <sfrost@snowman.net>:
> > We can send a 'cancel query', how about a 'report on query' which
> > returns the plan and perhaps whatever other stats are easily available?
> 
> there is only one question - that POSIX signal we can use?

This would be a new protocol message, psql doesn't ever send any actual
process signals to the backend processes...

Or at least, that's how I was thinking it would be implemented, in an
ideal world.  It's possible we could have some backend helper function
which a user could call on another connection to send a signal to the
first, after figuring out the pid, blah, blah.

Of course, I haven't gone and looked at how cancel query really works
under the hood, so I have no idea if this is at all possible. :)

	Thanks,

		Stephen

  19. Re: ToDo: log plans of cancelled queries

    Simon Riggs <simon@2ndquadrant.com> — 2013-01-11T16:52:33Z

    On 11 January 2013 16:31, Pavel Stehule <pavel.stehule@gmail.com> wrote:
> 2013/1/11 Stephen Frost <sfrost@snowman.net>:
>> * Tom Lane (tgl@sss.pgh.pa.us) wrote:
>>> Simon Riggs <simon@2ndQuadrant.com> writes:
>>> > An even better feature would be to be able to send a signal to a
>>> > running query to log its currently executing plan. That way you can
>>> > ask "Why so slow?" before deciding to kill it.
>>>
>>> That could conceivably work.  At least it wouldn't require running
>>> EXPLAIN in a failed transaction.
>>
>> I like this idea, in general, also.  Taking that to the next level would
>> be figuring out how you can do the same kind of thing through an
>> interactive psql session where the user running the query doesn't need
>> access to the database server or PG log files...
>>
>
> this is simple - it can be printed via elog(WARNING, ...) to original console
>
>> We can send a 'cancel query', how about a 'report on query' which
>> returns the plan and perhaps whatever other stats are easily available?
>
> there is only one question - that POSIX signal we can use?

We already overload the signals, so its just a new type for the signal
handler to cope with.

See procsignal_sigusr1_handler()

If we do it this way we can have time-based explain logging, so log
anything that hits 60 minutes etc..

Stephen's idea of an additional protocol message to support this is
fine, but I wouldn't want to limit this capability so it can only be
invoked from the client. I'd like a sysadmin be able to enquire about
other sessions.

-- 
 Simon Riggs                   http://www.2ndQuadrant.com/
 PostgreSQL Development, 24x7 Support, Training & Services

  20. Re: ToDo: log plans of cancelled queries

    Simon Riggs <simon@2ndquadrant.com> — 2013-01-11T20:50:57Z

    On 11 January 2013 16:52, Simon Riggs <simon@2ndquadrant.com> wrote:

> We already overload the signals, so its just a new type for the signal
> handler to cope with.
>
> See procsignal_sigusr1_handler()

I roughed up something to help you here... this is like 50% of a patch.

pg_explain_backend() calls a SIGUSR1 variant which then allows a call
to RunDynamicExplain() during any call to CHECK_FOR_INTERRUPTS()

That only works when something in the executor has called
SetDynamicExplain(), which later needs to be Unset...

So that's all you need to invoke a dynamic EXPLAIN via a sysadmin
function. All you need to do is generate an EXPLAIN and dump it
somewhere useful, like the server log. Over to you Pavel. There's a
patch somewhere by Greg Stark that generated a plan from a running
server for progress bar stuff, but that was like 5 years ago nearly.
But the explain invocation stuff from that might be useful as a guide.

-- 
 Simon Riggs                   http://www.2ndQuadrant.com/
 PostgreSQL Development, 24x7 Support, Training & Services

  21. Re: ToDo: log plans of cancelled queries

    Dimitri Fontaine <dimitri@2ndquadrant.fr> — 2013-01-13T15:44:51Z

    Pavel Stehule <pavel.stehule@gmail.com> writes:
> My propose is proposed for different dimensions and purpose - for
> example - we have a limit 20 minutes for almost all queries, and after
> this limit we killing queries. But we have to know little bit more
> about these bad queries - and we hope, so execution plan can give this
> additional info. We have same motivation like people who use
> auto_explain for slow query - but we can't to wait to query complete.

Set auto_explain.log_min_duration to 19 mins or maybe 17 and be done?

Regards,
-- 
Dimitri Fontaine
http://2ndQuadrant.fr     PostgreSQL : Expertise, Formation et Support

  22. Re: ToDo: log plans of cancelled queries

    Pavel Stehule <pavel.stehule@gmail.com> — 2013-01-13T17:28:58Z

    2013/1/13 Dimitri Fontaine <dimitri@2ndquadrant.fr>:
> Pavel Stehule <pavel.stehule@gmail.com> writes:
>> My propose is proposed for different dimensions and purpose - for
>> example - we have a limit 20 minutes for almost all queries, and after
>> this limit we killing queries. But we have to know little bit more
>> about these bad queries - and we hope, so execution plan can give this
>> additional info. We have same motivation like people who use
>> auto_explain for slow query - but we can't to wait to query complete.
>
> Set auto_explain.log_min_duration to 19 mins or maybe 17 and be done?

We have limit 5 sec - but we have to kill queries after 20 minutes -
and we have no plan for these queries.

Regards

Pavel


>
> Regards,
> --
> Dimitri Fontaine
> http://2ndQuadrant.fr     PostgreSQL : Expertise, Formation et Support

  23. Re: ToDo: log plans of cancelled queries

    Tom Lane <tgl@sss.pgh.pa.us> — 2013-01-13T17:32:58Z

    Dimitri Fontaine <dimitri@2ndQuadrant.fr> writes:
> Pavel Stehule <pavel.stehule@gmail.com> writes:
>> My propose is proposed for different dimensions and purpose - for
>> example - we have a limit 20 minutes for almost all queries, and after
>> this limit we killing queries. But we have to know little bit more
>> about these bad queries - and we hope, so execution plan can give this
>> additional info. We have same motivation like people who use
>> auto_explain for slow query - but we can't to wait to query complete.

> Set auto_explain.log_min_duration to 19 mins or maybe 17 and be done?

That would only help if he were willing to wait for the long-running
command to be done (instead of canceling it).  It's not hard to think
of commands that will still be running after the heat death of the
universe.

			regards, tom lane

  24. Re: ToDo: log plans of cancelled queries

    Dimitri Fontaine <dimitri@2ndquadrant.fr> — 2013-01-13T20:32:45Z

    Tom Lane <tgl@sss.pgh.pa.us> writes:
>> Set auto_explain.log_min_duration to 19 mins or maybe 17 and be done?
>
> That would only help if he were willing to wait for the long-running
> command to be done (instead of canceling it).  It's not hard to think
> of commands that will still be running after the heat death of the
> universe.

Oh. Brain fart from me. Sorry.

-- 
Dimitri Fontaine
http://2ndQuadrant.fr     PostgreSQL : Expertise, Formation et Support