Обсуждение: errbacktrace

New thread continuing from
<https://www.postgresql.org/message-id/d4903af2-e7b7-b551-71f8-3e4a6bdc2e73@2ndquadrant.com>.

Here is a extended version of Álvaro's patch that adds an errbacktrace()
function.  You can do two things with this:

- Manually attach it to an ereport() call site that you want to debug.

- Set a configuration parameter like backtrace_function = 'int8in' to
debug ereport()/elog() calls in a specific function.

There was also mention of settings that would automatically produce
backtraces for PANICs etc.  Those could surely be added if there is
enough interest.

For the implementation, I support both backtrace() provided by the OS as
well as using libunwind.  The former seems to be supported by a number
of platforms, including glibc, macOS, and FreeBSD, so maybe we don't
need the libunwind suport.  I haven't found any difference in quality in
the backtraces between the two approaches, but surely that is highly
dependent on the exact configuration.

I would welcome testing in all direction with this, to see how well it
works in different circumstances.

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

On 2019-Jun-25, Peter Eisentraut wrote:

> Here is a extended version of Álvaro's patch that adds an errbacktrace()
> function.

Great stuff, thanks for working on it.

> You can do two things with this:
> 
> - Manually attach it to an ereport() call site that you want to debug.
> 
> - Set a configuration parameter like backtrace_function = 'int8in' to
> debug ereport()/elog() calls in a specific function.

WFM.  I tried specifying int4in -- didn't work.  Turns out the errors
are inside another function which is what I have to put in
backtrace_function:

$ PGOPTIONS="-c backtrace_function=pg_strtoint32" psql

alvherre=# select int 'foobar';

2019-06-25 10:03:51.034 -04 [11711] ERROR:  invalid input syntax for type integer: "foobar" at character 12
2019-06-25 10:03:51.034 -04 [11711] BACKTRACE:  postgres: alvherre alvherre [local] SELECT(pg_strtoint32+0xef)
[0x55862737bdaf]
    postgres: alvherre alvherre [local] SELECT(int4in+0xd) [0x558627336d7d]
    postgres: alvherre alvherre [local] SELECT(InputFunctionCall+0x7b) [0x55862740b10b]
    postgres: alvherre alvherre [local] SELECT(OidInputFunctionCall+0x48) [0x55862740b378]
    postgres: alvherre alvherre [local] SELECT(coerce_type+0x297) [0x5586270b2f67]
    postgres: alvherre alvherre [local] SELECT(coerce_to_target_type+0x9d) [0x5586270b37ad]
    postgres: alvherre alvherre [local] SELECT(+0x1ed3d8) [0x5586270b83d8]
    postgres: alvherre alvherre [local] SELECT(transformExpr+0x18) [0x5586270bbcc8]
    postgres: alvherre alvherre [local] SELECT(transformTargetEntry+0xb2) [0x5586270c81c2]
    postgres: alvherre alvherre [local] SELECT(transformTargetList+0x58) [0x5586270c9808]
    postgres: alvherre alvherre [local] SELECT(transformStmt+0x9d1) [0x55862708caf1]
    postgres: alvherre alvherre [local] SELECT(parse_analyze+0x57) [0x55862708f177]
    postgres: alvherre alvherre [local] SELECT(pg_analyze_and_rewrite+0x12) [0x5586272d2f02]
    postgres: alvherre alvherre [local] SELECT(+0x4085ca) [0x5586272d35ca]
    postgres: alvherre alvherre [local] SELECT(PostgresMain+0x1a37) [0x5586272d52b7]
    postgres: alvherre alvherre [local] SELECT(+0xbf635) [0x558626f8a635]
    postgres: alvherre alvherre [local] SELECT(PostmasterMain+0xf3e) [0x55862724e27e]
    postgres: alvherre alvherre [local] SELECT(main+0x723) [0x558626f8c603]
    /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xe7) [0x7f99d1931b97]
    postgres: alvherre alvherre [local] SELECT(_start+0x2a) [0x558626f8c6ca]

Didn't think too much about the libunwind format string (or even try to
compile it.)

Despite possible shortcomings in the produced backtraces, this is a
*much* more convenient interface than requesting users to attach gdb,
set breakpoint on errfinish, hey why does my SQL not run, "oh you forgot
'cont' in gdb", etc.

> There was also mention of settings that would automatically produce
> backtraces for PANICs etc.  Those could surely be added if there is
> enough interest.

Let's have the basics first, we can add niceties afterwards.  (IMO yes,
we should have backtraces in PANICs and assertion failures).

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

On Tue, Jun 25, 2019 at 11:08 PM Peter Eisentraut
<peter.eisentraut@2ndquadrant.com> wrote:
> For the implementation, I support both backtrace() provided by the OS as
> well as using libunwind.  The former seems to be supported by a number
> of platforms, including glibc, macOS, and FreeBSD, so maybe we don't
> need the libunwind suport.  I haven't found any difference in quality in
> the backtraces between the two approaches, but surely that is highly
> dependent on the exact configuration.
>
> I would welcome testing in all direction with this, to see how well it
> works in different circumstances.

I like it.

Works out of the box on my macOS machine, but for FreeBSD I had to add
-lexecinfo to LIBS.

-- 
Thomas Munro
https://enterprisedb.com

> On Sat, Jun 29, 2019 at 7:41 AM Jaime Casanova <jaime.casanova@2ndquadrant.com> wrote:
>
> This is certainly a very useful thing. Sadly, it doesn't seem to compile when
> trying to use libunwind.

Yeah, the same for me. To make it works I've restricted libunwind to local
unwinding only:

    #ifdef USE_LIBUNWIND
    #define UNW_LOCAL_ONLY
    #include <libunwind.h>
    #endif

And result looks pretty nice:

2019-07-08 17:24:08.406 CEST [31828] ERROR:  invalid input syntax for
type integer: "foobar" at character 12
2019-07-08 17:24:08.406 CEST [31828] BACKTRACE:  #0
pg_strtoint32+0x1d1 [0x000055fa389bcbbe]
        #1  int4in+0xd [0x000055fa38976d7b]
        #2  InputFunctionCall+0x6f [0x000055fa38a488e9]
        #3  OidInputFunctionCall+0x44 [0x000055fa38a48b0d]
        #4  stringTypeDatum+0x33 [0x000055fa386e222e]
        #5  coerce_type+0x26d [0x000055fa386ca14d]
        #6  coerce_to_target_type+0x79 [0x000055fa386c9494]
        #7  transformTypeCast+0xaa [0x000055fa386d0042]
        #8  transformExprRecurse+0x22f [0x000055fa386cf650]
        #9  transformExpr+0x1a [0x000055fa386cf30a]
        #10 transformTargetEntry+0x79 [0x000055fa386e1131]
        #11 transformTargetList+0x86 [0x000055fa386e11ce]
        #12 transformSelectStmt+0xa1 [0x000055fa386a29c9]
        #13 transformStmt+0x9d [0x000055fa386a345a]
        #14 transformOptionalSelectInto+0x94 [0x000055fa386a3f49]
        #15 transformTopLevelStmt+0x15 [0x000055fa386a3f88]
        #16 parse_analyze+0x4e [0x000055fa386a3fef]
        #17 pg_analyze_and_rewrite+0x3e [0x000055fa3890cfa5]
        #18 exec_simple_query+0x35b [0x000055fa3890d5b5]
        #19 PostgresMain+0x91f [0x000055fa3890f7a8]
        #20 BackendRun+0x1ac [0x000055fa3887ed17]
        #21 BackendStartup+0x15c [0x000055fa38881ea1]
        #22 ServerLoop+0x1e6 [0x000055fa388821bb]
        #23 PostmasterMain+0x1101 [0x000055fa388835a1]
        #24 main+0x21a [0x000055fa387db1a9]
        #25 __libc_start_main+0xe7 [0x00007f3d1a607fa7]
        #26 _start+0x2a [0x000055fa3858e4ea]

On 2019-Jul-08, Dmitry Dolgov wrote:

> > On Sat, Jun 29, 2019 at 7:41 AM Jaime Casanova <jaime.casanova@2ndquadrant.com> wrote:
> >
> > This is certainly a very useful thing. Sadly, it doesn't seem to compile when
> > trying to use libunwind.
> 
> Yeah, the same for me. To make it works I've restricted libunwind to local
> unwinding only:
> 
>     #ifdef USE_LIBUNWIND
>     #define UNW_LOCAL_ONLY
>     #include <libunwind.h>
>     #endif

Ah, yes.  unwind's manpage says:

  Normally, libunwind supports both local and remote unwinding (the latter will
  be explained in the next section). However, if you tell libunwind that your
  program only needs local unwinding, then a special implementation can be
  selected which may run much faster than the generic implementation which
  supports both kinds of unwinding. To select this optimized version, simply
  define the macro UNW_LOCAL_ONLY before including the headerfile <libunwind.h>.

so I agree with unconditionally defining that symbol.

Nitpicking dept: I think in these tests:

+   if (!edata->backtrace &&
+       edata->funcname &&
+       backtrace_function[0] &&
+       strcmp(backtrace_function, edata->funcname) == 0)
+       set_backtrace(edata, 2);

we should test for backtrace_function[0] before edata->funcname, since
it seems more likely to be unset.

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

After further research I'm thinking about dropping the libunwind
support.  The backtrace()/backtrace_symbols() API is more widely
available: darwin, freebsd, linux, netbsd, openbsd (via port), solaris,
and of course it's built-in, whereas libunwind is only available for
linux, freebsd, hpux, solaris, and requires an external dependency.

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

On 2019-07-09 11:43, Peter Eisentraut wrote:
> After further research I'm thinking about dropping the libunwind
> support.  The backtrace()/backtrace_symbols() API is more widely
> available: darwin, freebsd, linux, netbsd, openbsd (via port), solaris,
> and of course it's built-in, whereas libunwind is only available for
> linux, freebsd, hpux, solaris, and requires an external dependency.

Here is an updated patch without the libunwind support, some minor
cleanups, documentation, and automatic back traces from assertion failures.

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

On 2019-Jul-22, Peter Eisentraut wrote:

> On 2019-07-09 11:43, Peter Eisentraut wrote:
> > After further research I'm thinking about dropping the libunwind
> > support.  The backtrace()/backtrace_symbols() API is more widely
> > available: darwin, freebsd, linux, netbsd, openbsd (via port), solaris,
> > and of course it's built-in, whereas libunwind is only available for
> > linux, freebsd, hpux, solaris, and requires an external dependency.
> 
> Here is an updated patch without the libunwind support, some minor
> cleanups, documentation, and automatic back traces from assertion failures.

The only possibly complaint I see is that the backtrace support in
ExceptionalCondition does not work for Windows eventlog/console ... but
that seems moot since Windows does not have backtrace support anyway.

+1 to get this patch in at this stage; we can further refine (esp. add
Windows support) later, if need be.

https://stackoverflow.com/questions/26398064/counterpart-to-glibcs-backtrace-and-backtrace-symbols-on-windows

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

Peter Eisentraut <peter.eisentraut@2ndquadrant.com> writes:
> Here is an updated patch without the libunwind support, some minor
> cleanups, documentation, and automatic back traces from assertion failures.

Just noticing that ExceptionalCondition has an "fflush(stderr);"
in front of what you added --- perhaps you should also add one
after the backtrace_symbols_fd call?  It's not clear to me that
that function guarantees to fflush, nor do I want to assume that
abort() does.

            regards, tom lane

I wrote:
> Just noticing that ExceptionalCondition has an "fflush(stderr);"
> in front of what you added --- perhaps you should also add one
> after the backtrace_symbols_fd call?  It's not clear to me that
> that function guarantees to fflush, nor do I want to assume that
> abort() does.

Oh, wait, it's writing to fileno(stderr) so it couldn't be
buffering anything.  Disregard ...

            regards, tom lane

On Tue, Jul 23, 2019 at 6:19 AM Peter Eisentraut
<peter.eisentraut@2ndquadrant.com> wrote:
> On 2019-07-09 11:43, Peter Eisentraut wrote:
> > After further research I'm thinking about dropping the libunwind
> > support.  The backtrace()/backtrace_symbols() API is more widely
> > available: darwin, freebsd, linux, netbsd, openbsd (via port), solaris,
> > and of course it's built-in, whereas libunwind is only available for
> > linux, freebsd, hpux, solaris, and requires an external dependency.
>
> Here is an updated patch without the libunwind support, some minor
> cleanups, documentation, and automatic back traces from assertion failures.

Now works out of the box on FreeBSD.  The assertion thing is a nice touch.

I wonder if it'd make sense to have a log_min_backtrace GUC that you
could set to error/fatal/panicwhatever (perhaps in a later patch).

-- 
Thomas Munro
https://enterprisedb.com

On 2019-08-12 13:19, Pavel Stehule wrote:
> If I understand well, backtrace is displayed only when edata->funcname
> is same like backtrace_function GUC. Isn't it too strong limit?
> 
> For example, I want to see backtrace for all PANIC level errors on
> production, and I would not to limit the source function?

We can add additional ways to invoke this once we have the basic
functionality in.

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

On 2019-07-22 20:19, Peter Eisentraut wrote:
> On 2019-07-09 11:43, Peter Eisentraut wrote:
>> After further research I'm thinking about dropping the libunwind
>> support.  The backtrace()/backtrace_symbols() API is more widely
>> available: darwin, freebsd, linux, netbsd, openbsd (via port), solaris,
>> and of course it's built-in, whereas libunwind is only available for
>> linux, freebsd, hpux, solaris, and requires an external dependency.
> 
> Here is an updated patch without the libunwind support, some minor
> cleanups, documentation, and automatic back traces from assertion failures.

Another updated version.

I have changed the configuration setting to backtrace_functions plural,
so that you can debug more than one location at once.  I had originally
wanted to do that but using existing functions like
SplitIdentifierString() resulted in lots of complications with error
handling (inside error handling!).  So here I just hand-coded the list
splitting.  Seems simple enough.

I think this patch is now good to go from my perspective.

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

On 2019-Aug-13, Peter Eisentraut wrote:

> I have changed the configuration setting to backtrace_functions plural,
> so that you can debug more than one location at once.  I had originally
> wanted to do that but using existing functions like
> SplitIdentifierString() resulted in lots of complications with error
> handling (inside error handling!).  So here I just hand-coded the list
> splitting.  Seems simple enough.

Hmm ... but is that the natural way to write this?  I would have thought
you'd split the list at config-read time (the assign hook for the GUC)
and turn it into a List of simple strings.  Then you don't have to
loop strtok() on each errfinish().

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

Peter Eisentraut <peter.eisentraut@2ndquadrant.com> writes:
> I have changed the configuration setting to backtrace_functions plural,
> so that you can debug more than one location at once.  I had originally
> wanted to do that but using existing functions like
> SplitIdentifierString() resulted in lots of complications with error
> handling (inside error handling!).  So here I just hand-coded the list
> splitting.  Seems simple enough.

I think it's a pretty bad idea for anything invocable from elog to
trample on the process-wide strtok() state.  Even if there's no
conflict today, there will be one eventually, unless you are going
to adopt the position that nobody else is allowed to use strtok().

            regards, tom lane

On 2019-08-13 15:24, Alvaro Herrera wrote:
> On 2019-Aug-13, Peter Eisentraut wrote:
> 
>> I have changed the configuration setting to backtrace_functions plural,
>> so that you can debug more than one location at once.  I had originally
>> wanted to do that but using existing functions like
>> SplitIdentifierString() resulted in lots of complications with error
>> handling (inside error handling!).  So here I just hand-coded the list
>> splitting.  Seems simple enough.
> 
> Hmm ... but is that the natural way to write this?  I would have thought
> you'd split the list at config-read time (the assign hook for the GUC)
> and turn it into a List of simple strings.  Then you don't have to
> loop strtok() on each errfinish().

The memory management of that seems too complicated.  The "extra"
mechanism of the check/assign hooks only supports one level of malloc.
Using a List seems impossible.  I don't know if you can safely do a
malloc-ed array of malloc-ed strings either.

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

On 2019-Aug-20, Peter Eisentraut wrote:

> The memory management of that seems too complicated.  The "extra"
> mechanism of the check/assign hooks only supports one level of malloc.
> Using a List seems impossible.  I don't know if you can safely do a
> malloc-ed array of malloc-ed strings either.

Here's an idea -- have the check/assign hooks create a different
representation, which is a single guc_malloc'ed chunk that is made up of
every function name listed in the GUC, separated by \0.  That can be
scanned at error time comparing the function name with each piece.

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

On 2019-Sep-13, Alvaro Herrera wrote:

> On 2019-Aug-20, Peter Eisentraut wrote:
> 
> > The memory management of that seems too complicated.  The "extra"
> > mechanism of the check/assign hooks only supports one level of malloc.
> > Using a List seems impossible.  I don't know if you can safely do a
> > malloc-ed array of malloc-ed strings either.
> 
> Here's an idea -- have the check/assign hooks create a different
> representation, which is a single guc_malloc'ed chunk that is made up of
> every function name listed in the GUC, separated by \0.  That can be
> scanned at error time comparing the function name with each piece.

Peter, would you like me to clean this up for commit, or do you prefer
to keep authorship and get it done yourself?

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

On 2019-09-27 17:50, Alvaro Herrera wrote:
> On 2019-Sep-13, Alvaro Herrera wrote:
> 
>> On 2019-Aug-20, Peter Eisentraut wrote:
>>
>>> The memory management of that seems too complicated.  The "extra"
>>> mechanism of the check/assign hooks only supports one level of malloc.
>>> Using a List seems impossible.  I don't know if you can safely do a
>>> malloc-ed array of malloc-ed strings either.
>>
>> Here's an idea -- have the check/assign hooks create a different
>> representation, which is a single guc_malloc'ed chunk that is made up of
>> every function name listed in the GUC, separated by \0.  That can be
>> scanned at error time comparing the function name with each piece.
> 
> Peter, would you like me to clean this up for commit, or do you prefer
> to keep authorship and get it done yourself?

If you want to finish it using the idea from your previous message,
please feel free.  I won't get to it this week.

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

On 2019-09-30 20:16, Peter Eisentraut wrote:
> On 2019-09-27 17:50, Alvaro Herrera wrote:
>> On 2019-Sep-13, Alvaro Herrera wrote:
>>
>>> On 2019-Aug-20, Peter Eisentraut wrote:
>>>
>>>> The memory management of that seems too complicated.  The "extra"
>>>> mechanism of the check/assign hooks only supports one level of malloc.
>>>> Using a List seems impossible.  I don't know if you can safely do a
>>>> malloc-ed array of malloc-ed strings either.
>>>
>>> Here's an idea -- have the check/assign hooks create a different
>>> representation, which is a single guc_malloc'ed chunk that is made up of
>>> every function name listed in the GUC, separated by \0.  That can be
>>> scanned at error time comparing the function name with each piece.
>>
>> Peter, would you like me to clean this up for commit, or do you prefer
>> to keep authorship and get it done yourself?
> 
> If you want to finish it using the idea from your previous message,
> please feel free.  I won't get to it this week.

I hadn't realized that you had already attached a patch that implements
your idea.  It looks good to me.  Maybe a small comment near
check_backtrace_functions() why we're not using a regular list.  Other
than that, please go ahead with this.

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

On 2019-Oct-26, Peter Eisentraut wrote:

> I hadn't realized that you had already attached a patch that implements
> your idea.  It looks good to me.  Maybe a small comment near
> check_backtrace_functions() why we're not using a regular list.  Other
> than that, please go ahead with this.

Thanks, I added that comment and others, and pushed.  Let's see what
happens now ...

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

Alvaro Herrera <alvherre@2ndquadrant.com> writes:
> On 2019-Oct-26, Peter Eisentraut wrote:
>> I hadn't realized that you had already attached a patch that implements
>> your idea.  It looks good to me.  Maybe a small comment near
>> check_backtrace_functions() why we're not using a regular list.  Other
>> than that, please go ahead with this.

> Thanks, I added that comment and others, and pushed.  Let's see what
> happens now ...

I had occasion to try to use errbacktrace() just now, and it blew up
on me.  Investigation finds this:

int
errbacktrace(void)
{
    ErrorData   *edata = &errordata[errordata_stack_depth];
    MemoryContext oldcontext;

    Assert(false);


I suppose that's a debugging leftover that shouldn't have been committed?
It did what I wanted after I took out the Assert.

            regards, tom lane

On 2019-Nov-23, Tom Lane wrote:

> I had occasion to try to use errbacktrace() just now, and it blew up
> on me.  Investigation finds this:
> 
> int
> errbacktrace(void)
> {
>     ErrorData   *edata = &errordata[errordata_stack_depth];
>     MemoryContext oldcontext;
> 
>     Assert(false);
> 
> 
> I suppose that's a debugging leftover that shouldn't have been committed?
> It did what I wanted after I took out the Assert.

Uhh ... facepalm.  Yes, that's not intended.  I don't remember why would
I want to put that there.

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