Re: elog/ereport VS misleading backtrace_function function address
On Tue, May 14, 2024 at 6:13 AM Jakub Wartak wrote: > OK I'll try to explain using assembly, but I'm not an expert on this. > Let's go to the 1st post, assume we run with backtrace_function set: I feel like this explanation doesn't really explain very much. I mean, the question is not "how is it that adding a nop instruction fixes anything?" but "is adding a nop instruction a principled way of fixing things, and if so, for what reason?". And as far as I can see, you haven't answered that question anywhere. Unless we really understand why the results are better with that nop instruction added, we can't possibly have any confidence that this is anything other than random good fortune, which isn't a sufficiently good reason to make a change. And, while I'm no expert on this, I suspect that it is mostly just random good fortune -- the fact that inserting a volatile variable declaration here solved the problem seems like something that could easily fail to work out on another platform or compiler or compiler version. I also think it's the wrong idea on principle to insert junk declarations into our code to try to get good backtraces. I think the right answer here is probably what Alvaro said, namely, that people have to have the debug symbols installed if they want to get backtraces. Tom is probably correct when he says that there's nothing we can do to ensure that users end up with debug symbols in all cases, but that doesn't mean it's the wrong solution. It's at least understandable why it works. -- Robert Haas EDB: http://www.enterprisedb.com
Re: elog/ereport VS misleading backtrace_function function address
Alvaro Herrera writes: > On 2024-May-14, Jakub Wartak wrote: >> Reality is apparently mixed,at least from what I have checked : >> - all RHEL 7.x/8.x (PGDG and our forks) do NOT come with >> --enable-debug according to pg_config. > Ooh, yeah, that's true according to > https://git.postgresql.org/gitweb/?p=pgrpms.git;a=blob;f=rpm/redhat/main/non-common/postgresql-16/main/postgresql-16.spec;h=ab2f6edc903f083e04b8f7a1d3bad8e1b7018791;hb=1a8b9fa7019d3f73322ca873b62dc0b33e73ed1d > 507 %if %beta > 508 --enable-debug \ > 509 --enable-cassert \ > 510 %endif > Maybe a better approach for this whole thing is to change the specs so > that --enable-debug is always given, not just for %beta. My recollection from my time at Red Hat is that their standard policy is to build everything with debug symbols all the time; so this is violating that policy, and we should change it just on those grounds. However, I'm not sure how much the change will help Joe Average User with respect to the thread topic. RH actually has infrastructure that splits the debug symbol tables out into separate "debuginfo" RPMs, which you have to install manually if you want to debug a particular package. This is good for disk space consumption, but it means that most users are still only going to see the same backtrace they see currently. I don't know how much of that applies to, eg, Debian. regards, tom lane
Re: elog/ereport VS misleading backtrace_function function address
On 2024-May-14, Jakub Wartak wrote: > On Sun, May 12, 2024 at 10:33 PM Peter Eisentraut > wrote: > > Don't production builds use debug > > symbols nowadays as well? > > Reality is apparently mixed,at least from what I have checked : > - all RHEL 7.x/8.x (PGDG and our forks) do NOT come with > --enable-debug according to pg_config. Ooh, yeah, that's true according to https://git.postgresql.org/gitweb/?p=pgrpms.git;a=blob;f=rpm/redhat/main/non-common/postgresql-16/main/postgresql-16.spec;h=ab2f6edc903f083e04b8f7a1d3bad8e1b7018791;hb=1a8b9fa7019d3f73322ca873b62dc0b33e73ed1d 507 %if %beta 508 --enable-debug \ 509 --enable-cassert \ 510 %endif Maybe a better approach for this whole thing is to change the specs so that --enable-debug is always given, not just for %beta. -- Álvaro Herrera 48°01'N 7°57'E — https://www.EnterpriseDB.com/
Re: elog/ereport VS misleading backtrace_function function address
Hi Peter! On Sun, May 12, 2024 at 10:33 PM Peter Eisentraut wrote: > > On 07.05.24 09:43, Jakub Wartak wrote: > > NOTE: in case one will be testing this: one cannot ./configure with > > --enable-debug as it prevents the compiler optimizations that actually > > end up with the ".cold" branch optimizations that cause backtrace() to > > return the wrong address. > > Is that configuration useful? If you're interested in backtraces, > wouldn't you also want debug symbols? The use case here is that backtrace_functions is unreliable when we ask customers on production builds to use it (so it's useful not just for local tests) > Don't production builds use debug > symbols nowadays as well? Reality is apparently mixed,at least from what I have checked : - all RHEL 7.x/8.x (PGDG and our forks) do NOT come with --enable-debug according to pg_config. - on Debian 11/12 PGDG does come with --enable-debug > >> I recall speculating about whether we could somehow invoke gdb > >> to get a more comprehensive and accurate backtrace, but I don't > >> really have a concrete idea how that could be made to work. > > Oh no, I'm more about micro-fix rather than doing some bigger > > revolution. The patch simply adds this one instruction in macro, so > > that now backtrace_functions behaves better: > > > > 0x00773d28 <+105>: call 0x79243f > > 0x00773d2d <+110>: movzbl -0x12(%rbp),%eax << this ends > > up being added by the patch > > 0x00773d31 <+114>: call 0xdc1a0 > > > > I'll put that as for PG18 in CF, but maybe it could be backpatched too > > - no hard opinion on that (I don't see how that ERROR/FATAL path could > > cause any performance regressions) > > I'm missing a principled explanation of what this does. I just see that > it sprinkles some no-op code to make this particular thing work a bit > differently, but this might just behave differently with the next > compiler next year. I'd like to see a bit more of an abstract > explanation of what is happening here. OK I'll try to explain using assembly, but I'm not an expert on this. Let's go to the 1st post, assume we run with backtrace_function set: get_collation_isdeterministic() 0x5c7680 to 0x5c76c1: might jump(!) to 0x14c686 note the two completely different address ranges (hot and separate cold) it's because of 913ec71d682 that added the cold branches optimization via pg_attribute_cold to errstart_cold Dump of assembler code for function get_collation_isdeterministic: Address range 0x5c7680 to 0x5c76c1: 0x005c7680 <+0>: push %rbp [..] 0x005c7694 <+20>:call 0x5d63b0 0x005c7699 <+25>:test %rax,%rax 0x005c769c <+28>:je 0x14c686 [..] 0x005c76b3 <+51>:call 0x5d6430 0x005c76b8 <+56>:mov%r12d,%eax 0x005c76bb <+59>:mov-0x8(%rbp),%r12 0x005c76bf <+63>:leave 0x005c76c0 <+64>:ret Address range 0x14c686 to 0x14c6bb: // note here that the last instruction is 0x14c6b6 not 0x14c6bb(!) // note this cold path also has no frame pointer setup 0x0014c686 <-4698106>: xor%esi,%esi 0x0014c688 <-4698104>: mov$0x15,%edi 0x0014c68d <-4698099>: call 0x14ec86 0x0014c692 <-4698094>: mov%r12d,%esi 0x0014c695 <-4698091>: lea0x5028dc(%rip),%rdi # 0x64ef78 0x0014c69c <-4698084>: xor%eax,%eax 0x0014c69e <-4698082>: call 0x5df320 0x0014c6a3 <-4698077>: lea0x6311a6(%rip),%rdx # 0x77d850 <__func__.34> 0x0014c6aa <-4698070>: mov$0x440,%esi 0x0014c6af <-4698065>: lea0x630c8a(%rip),%rdi # 0x77d340 0x0014c6b6 <-4698058>: call 0x5df100 End of assembler dump. so it's get_collation_isdeterministic() -> get_collation_isdeterministic.cold() [but not real function -> no proper fp/stack?] -> .. -> errfinish() -> set_backtrace() // just builds and appends string using backtrace()/backtrace_functions()/backtrace_symbol_list(). prints/logs, finishes It seems that the thing is that the limited GNU libc backtrace_symbol_list() won't resolve the 0x14c6b6..0x14c6bb to the "get_collation_isdeterministic[.cold]" symbol name and it will just simply put 0x14c6bb in that the text asm. It's wrong and it is confusing: 2024-03-27 14:39:13.065 CET [12899] postgres(at)test1 ERROR: cache lookup failed for collation 0 2024-03-27 14:39:13.065 CET [12899] postgres(at)test1 BACKTRACE: postgres: 16/main: postgres test1 [local] DELETE(+0x14c6bb) [0x5565c5a9c6bb] postgres: 16/main: postgres test1 [local] DELETE(RI_FKey_cascade_del+0x323) [0x5565c5ec0973] [..] if you now take addr2line for 0x14c6bb it will
Re: elog/ereport VS misleading backtrace_function function address
On 07.05.24 09:43, Jakub Wartak wrote: NOTE: in case one will be testing this: one cannot ./configure with --enable-debug as it prevents the compiler optimizations that actually end up with the ".cold" branch optimizations that cause backtrace() to return the wrong address. Is that configuration useful? If you're interested in backtraces, wouldn't you also want debug symbols? Don't production builds use debug symbols nowadays as well? I recall speculating about whether we could somehow invoke gdb to get a more comprehensive and accurate backtrace, but I don't really have a concrete idea how that could be made to work. Oh no, I'm more about micro-fix rather than doing some bigger revolution. The patch simply adds this one instruction in macro, so that now backtrace_functions behaves better: 0x00773d28 <+105>: call 0x79243f 0x00773d2d <+110>: movzbl -0x12(%rbp),%eax << this ends up being added by the patch 0x00773d31 <+114>: call 0xdc1a0 I'll put that as for PG18 in CF, but maybe it could be backpatched too - no hard opinion on that (I don't see how that ERROR/FATAL path could cause any performance regressions) I'm missing a principled explanation of what this does. I just see that it sprinkles some no-op code to make this particular thing work a bit differently, but this might just behave differently with the next compiler next year. I'd like to see a bit more of an abstract explanation of what is happening here.
Re: elog/ereport VS misleading backtrace_function function address
Hi Tom and -hackers! On Thu, Mar 28, 2024 at 7:36 PM Tom Lane wrote: > > Jakub Wartak writes: > > While chasing some other bug I've learned that backtrace_functions > > might be misleading with top elog/ereport() address. > > That was understood from the beginning: this type of backtrace is > inherently pretty imprecise, and I doubt there is much that can > be done to make it better. IIRC the fundamental problem is it only > looks at global symbols, so static functions inherently defeat it. > It was argued that this is better than nothing, which is true, but > you have to take the info with a mountain of salt. OK, point taken, thanks for describing the limitations, still I find backtrace_functions often the best thing we have primarily due its simplicity and ease of use (for customers). I found out simplest portable way to generate NOP (or any other instruction that makes the problem go away): with the reproducer, psql returns: psql:ri-collation-bug-example.sql:48: error: ERROR: XX000: cache lookup failed for collation 0 LOCATION: get_collation_isdeterministic, lsyscache.c:1062 logfile without patch: 2024-05-07 09:05:43.043 CEST [44720] ERROR: cache lookup failed for collation 0 2024-05-07 09:05:43.043 CEST [44720] BACKTRACE: postgres: postgres postgres [local] DELETE(+0x155883) [0x55ce5a86a883] postgres: postgres postgres [local] DELETE(RI_FKey_cascade_del+0x2b0) [0x55ce5ac6dfd0] postgres: postgres postgres [local] DELETE(+0x2d488b) [0x55ce5a9e988b] [..] $ addr2line -e /usr/pgsql18/bin/postgres -a -f 0x155883 0x00155883 get_constraint_type.cold << so it's wrong as the real function should be get_collation_isdeterministic logfile with attached patch: 2024-05-07 09:11:06.596 CEST [51185] ERROR: cache lookup failed for collation 0 2024-05-07 09:11:06.596 CEST [51185] BACKTRACE: postgres: postgres postgres [local] DELETE(+0x168bf0) [0x560e1cdfabf0] postgres: postgres postgres [local] DELETE(RI_FKey_cascade_del+0x2b0) [0x560e1d200c00] postgres: postgres postgres [local] DELETE(+0x2e90fb) [0x560e1cf7b0fb] [..] $ addr2line -e /usr/pgsql18/bin/postgres -a -f 0x168bf0 0x00168bf0 get_collation_isdeterministic.cold <<< It's ok with the patch NOTE: in case one will be testing this: one cannot ./configure with --enable-debug as it prevents the compiler optimizations that actually end up with the ".cold" branch optimizations that cause backtrace() to return the wrong address. > I recall speculating about whether we could somehow invoke gdb > to get a more comprehensive and accurate backtrace, but I don't > really have a concrete idea how that could be made to work. Oh no, I'm more about micro-fix rather than doing some bigger revolution. The patch simply adds this one instruction in macro, so that now backtrace_functions behaves better: 0x00773d28 <+105>: call 0x79243f 0x00773d2d <+110>: movzbl -0x12(%rbp),%eax << this ends up being added by the patch 0x00773d31 <+114>: call 0xdc1a0 I'll put that as for PG18 in CF, but maybe it could be backpatched too - no hard opinion on that (I don't see how that ERROR/FATAL path could cause any performance regressions) -J. v1-0001-Tweak-ereport-so-that-it-generates-proper-address.patch Description: Binary data
Re: elog/ereport VS misleading backtrace_function function address
Jakub Wartak writes: > While chasing some other bug I've learned that backtrace_functions > might be misleading with top elog/ereport() address. That was understood from the beginning: this type of backtrace is inherently pretty imprecise, and I doubt there is much that can be done to make it better. IIRC the fundamental problem is it only looks at global symbols, so static functions inherently defeat it. It was argued that this is better than nothing, which is true, but you have to take the info with a mountain of salt. I recall speculating about whether we could somehow invoke gdb to get a more comprehensive and accurate backtrace, but I don't really have a concrete idea how that could be made to work. regards, tom lane
elog/ereport VS misleading backtrace_function function address
Hi -hackers,
While chasing some other bug I've learned that backtrace_functions
might be misleading with top elog/ereport() address.
Reproducer:
# using Tom's reproducer on master:
wget
https://www.postgresql.org/message-id/attachment/112394/ri-collation-bug-example.sql
echo '' >> ri-collation-bug-example.sql
echo '\errverbose' >> ri-collation-bug-example.sql
-- based on grepping the source code locations many others could go in here:
psql -p 5437 -c "alter system set backtrace_functions =
'RI_FKey_cascade_del,get_collation_isdeterministic';"
psql -p 5437 -c "select pg_reload_conf();"
dropdb -p 5437 test1 ; createdb -p 5437 test1 ; psql -p 5437 -d test1
-f ri-collation-bug-example.sql
gives (note "get_collation_isdeterministic"):
psql:ri-collation-bug-example.sql:42: ERROR: cache lookup failed
for collation 0
psql:ri-collation-bug-example.sql:44: error: ERROR: XX000: cache
lookup failed for collation 0
LOCATION: get_collation_isdeterministic, lsyscache.c:1088
and in log note the 0x14c6bb:
2024-03-27 14:39:13.065 CET [12899] postgres@test1 ERROR: cache
lookup failed for collation 0
2024-03-27 14:39:13.065 CET [12899] postgres@test1 BACKTRACE:
postgres: 16/main: postgres test1 [local] DELETE(+0x14c6bb)
[0x5565c5a9c6bb]
postgres: 16/main: postgres test1 [local]
DELETE(RI_FKey_cascade_del+0x323) [0x5565c5ec0973]
postgres: 16/main: postgres test1 [local] DELETE(+0x2d401f)
[0x5565c5c2401f]
postgres: 16/main: postgres test1 [local] DELETE(+0x2d5a04)
[0x5565c5c25a04]
postgres: 16/main: postgres test1 [local]
DELETE(AfterTriggerEndQuery+0x78) [0x5565c5c2a918]
[..]
2024-03-27 14:39:13.065 CET [12899] postgres@test1 STATEMENT: delete
from revisions where id='5c617ce7-688d-4bea-9d66-c0f0ebc635da';
based on \errverbose it is OK (error matches the code, thanks to
Alvaro for this hint):
9 bool
8 get_collation_isdeterministic(Oid colloid)
7 {
6 │ HeapTuple> tp;
5 │ Form_pg_collation colltup;
4 │ bool> > result;
3 │
2 │ tp = SearchSysCache1(COLLOID, ObjectIdGetDatum(colloid));
1 │ if (!HeapTupleIsValid(tp))
1088 │ │ elog(ERROR, "cache lookup failed for collation %u", colloid);
[..]
but based on backtrace address 0x14c6bb (!) and it resolves
differently which seems to be highly misleading (note the
"get_language_name.cold"):
$ addr2line -e /usr/lib/postgresql/16/bin/postgres -a -f 0x14c6bb
0x0014c6bb
get_language_name.cold
./build/src/backend/utils/cache/./build/../src/backend/utils/cache/lsyscache.c:1181
When i disassemble the get_collation_isdeterministic() (and I know the
name from \errverbose):
Dump of assembler code for function get_collation_isdeterministic:
Address range 0x5c7680 to 0x5c76c1:
0x005c7680 <+0>: push %rbp
[..]
0x005c7694 <+20>:call 0x5d63b0
0x005c7699 <+25>:test %rax,%rax
0x005c769c <+28>:je 0x14c686
0x005c76a2 <+34>:mov%rax,%rdi
[..]
0x005c76bf <+63>:leave
0x005c76c0 <+64>:ret
Address range 0x14c686 to 0x14c6bb:
0x0014c686 <-4698106>: xor%esi,%esi
0x0014c688 <-4698104>: mov$0x15,%edi
0x0014c68d <-4698099>: call 0x14ec86
0x0014c692 <-4698094>: mov%r12d,%esi
0x0014c695 <-4698091>: lea0x5028dc(%rip),%rdi
# 0x64ef78
0x0014c69c <-4698084>: xor%eax,%eax
0x0014c69e <-4698082>: call 0x5df320
0x0014c6a3 <-4698077>: lea0x6311a6(%rip),%rdx
# 0x77d850 <__func__.34>
0x0014c6aa <-4698070>: mov$0x440,%esi
0x0014c6af <-4698065>: lea0x630c8a(%rip),%rdi
# 0x77d340
0x0014c6b6 <-4698058>: call 0x5df100
<< NOTE the exact 0x14c6bb is even missing here(!)
notice the interesting thing here: according to GDB
get_collation_isdeterministic() is @ 0x5c7680 + jump to 0x14c686
till 0x14c6bb (but without it)
without any stack setup for that .cold. But backtrace() just captured
the elog/ereport (cold) at the end of 0x14c6bb instead, so if I take
that exact address from backtrace_functions output as it is
("DELETE(+0x14c6bb)"), it also shows WRONG function (just like
addr2line):
(gdb) disassemble 0x14c6bb
Dump of assembler code for function get_language_name:
Address range 0x5c7780 to 0x5c77ee:
[..]
0x005c77ed <+109>: ret
Address range 0x14c6bb to 0x14c6f0:
0x0014c6bb <-4698309>: xor%esi,%esi
[..]
0x0014c6eb <-4698261>: call 0x5df100
End of assembler dump.
so this is wrong (as are failing in "get_collation_isdeterministic"
not in "get_language_name").
I was very confused at the beginning with the main question being: why
are we compiling elog/ereport() so that it is incompatible with
backtrace? When looking for it I've found two threads [1] by David
that were
