Re: Allow auto_explain to log plans before queries are executed

On Thu, 27 Feb 2020 14:14:41 +0900 (JST)
Kyotaro Horiguchi <horikyota.ntt@gmail.com> wrote:

> Hello.
> 
> At Thu, 27 Feb 2020 10:18:16 +0900, Yugo NAGATA <nagata@sraoss.co.jp> wrote in 
> > On Wed, 26 Feb 2020 18:51:21 +0100
> > Julien Rouhaud <rjuju123@gmail.com> wrote:
> > 
> > > On Thu, Feb 27, 2020 at 02:35:18AM +0900, Yugo NAGATA wrote:
> > > > Hi,
> > > >
> > > > Attached is a patch for allowing auto_explain to log plans before
> > > > queries are executed.
> > > >
> > > > Currently, auto_explain logs plans only after query executions,
> > > > so if a query gets stuck its plan could not be logged. If we can
> > > > know plans of stuck queries, we may get some hints to resolve the
> > > > stuck. This is useful when you are testing and debugging your
> > > > application whose queries get stuck in some situations.
> > > 
> > > Indeed that could be useful.
> >
> > > > This patch adds  new option log_before_query to auto_explain.
> > > 
> > > Maybe "log_before_execution" would be better?
> > 
> > Thanks!  This seems better also to me.
> > 
> > > 
> > > > Setting auto_explain.log_before_query option logs all plans before
> > > > queries are executed regardless of auto_explain.log_min_duration
> > > > unless this is set -1 to disable logging.  If log_before_query is
> > > > enabled, only duration time is logged after query execution as in
> > > > the case of when both log_statement and log_min_duration_statement
> > > > are enabled.
> > > 
> > > I'm not sure about this behavior.  The final explain plan is needed at least if
> > > log_analyze, log_buffers or log_timing are enabled.
> > 
> > In the current patch, log_before_query (will be log_before_execution)
> > has no effect if log_analyze is enabled in order to avoid to log the
> > same plans twice.  Instead, is it better to log the plan always twice,
> > before and after the execution, if  log_before_query is enabled
> > regardless of log_min_duration or log_analyze?
> 
> Honestly, I don't think showing plans for all queries is useful
> behavior.
> 
> If you allow the stuck query to be canceled, showing plan in
> PG_FINALLY() block in explain_ExecutorRun would work, which look like
> this.
> 
> explain_ExecutorRun()
> {
>   ...
>   PG_TRY();
>   {
>       ...
>       else
>          starndard_ExecutorRun();
>       nesting_level--;
>   }
>   PG_CATCH();
>   {
>       nesting_level--;
> 
>       if (auto_explain_log_failed_plan &&
>        <maybe the time elapsed from start exceeds min_duration>)
>       {
>           'show the plan'
>       }
>    }
> }

That makes sense. The initial purpose is to log plans of stuck queries
not of all queries, so your suggestion, doing it only when the query
fails, is reasonable.  I'll consider it little more.

Regards,
Yugo Nagata


-- 
Yugo NAGATA <nagata@sraoss.co.jp>