Re: Allow auto_explain to log plans before queries are executed - Mailing list pgsql-hackers

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'
      }
   }
}

regards.

--
Kyotaro Horiguchi
NTT Open Source Software Center