Thread: AssertLog instead of Assert in some places
Hi All,
PostgreSQL code uses Assert() as a way to
1. document the assumption or conditions which must be true at a given
place in code
2. make sure that some bug elsewhere does not break these assumptions or rules
3. conditions which can not be (easily) induced by user actions
E.g. following conditions in adjust_appendrel_attrs()
/* If there's nothing to adjust, don't call this function. */
Assert(nappinfos >= 1 && appinfos != NULL);
/* Should never be translating a Query tree. */
Assert(node == NULL || !IsA(node, Query));
These conditions do not make it to non-assert builds and thus do not
make it to the production binary. That saves some CPU cycles.
When an Assert fails, and it fails quite a lot for developers, the
Postgres backend that caused the Assert is Aborted, restarting the
server. So a developer testing code that caused the Assert has to
start a psql again, run any session setup before running the faulting
query, gdb needs to be reattached to the new backend process. That's
some waste of time and frustration, esp. when the Assert does not
damage the backend itself e.g. by corrupting memory.
Most of the Asserts are recoverable by rolling back the transaction
without crashing the backend. So an elog(ERROR, ) is enough. But just
by themselves elogs are compiled into non-debug binary and the
condition check can waste CPU cycles esp. conditions are mostly true
like the ones we use in Assert.
Attached patch combines Assert and elog(ERROR, ) so that when an
Assert is triggered in assert-enabled binary, it will throw an error
while keeping the backend intact. Thus it does not affect gdb session
or psql session. These elogs do not make their way to non-assert
binary so do not make it to production like Assert.
I have been using AssertLog for my work for some time. It is quite
convenient. With AssertLog I get
```
#explain (summary on) select * from a, b, c where a.c1 = b.c1 and b.c1
= c.c1 and a.c2 < b.c2 and a.c3 + b.c3 < c.c3;
ERROR: failed Assert("equal(child_rinfo, adjust_appendrel_attrs(root,
(Node *) rinfo, nappinfos, appinfos))"), File: "relnode.c", Line: 997,
PID: 568088
```
instead of
```
#explain (summary on) select * from a, b, c where a.c1 = b.c1 and b.c1
= c.c1 and a.c2 < b.c2 and a.c3 + b.c3 < c.c3;
server closed the connection unexpectedly
This probably means the server terminated abnormally
before or while processing the request.
The connection to the server was lost. Attempting reset: Failed.
The connection to the server was lost. Attempting reset: Failed.
@!#\q
```
If there is an interest in accepting the patch, I will add it to the
commitfest and work on it further.
--
Best Wishes,
Ashutosh Bapat
Attachment
Hi, On 2023-08-11 17:59:37 +0530, Ashutosh Bapat wrote: > Most of the Asserts are recoverable by rolling back the transaction > without crashing the backend. So an elog(ERROR, ) is enough. But just > by themselves elogs are compiled into non-debug binary and the > condition check can waste CPU cycles esp. conditions are mostly true > like the ones we use in Assert. > > Attached patch combines Assert and elog(ERROR, ) so that when an > Assert is triggered in assert-enabled binary, it will throw an error > while keeping the backend intact. Thus it does not affect gdb session > or psql session. These elogs do not make their way to non-assert > binary so do not make it to production like Assert. I am quite strongly against this. This will lead to assertions being hit in tests without that being noticed, e.g. because they happen in a background process that just restarts. Greetings, Andres Freund
On Fri, Aug 11, 2023 at 10:57 AM Andres Freund <andres@anarazel.de> wrote: > I am quite strongly against this. This will lead to assertions being hit in > tests without that being noticed, e.g. because they happen in a background > process that just restarts. Couldn't you say the same thing about defensive "can't happen" ERRORs? They are essentially a form of assertion that isn't limited to assert-enabled builds. I have sometimes thought that it would be handy if there was a variant of "can't happen" ERRORs that took on the structure of an assertion. (This is quite different to what Ashutosh has proposed, though, since it would still look like a conventional assertion failure on assert-enabled builds.) -- Peter Geoghegan
Hi, On 2023-08-11 11:14:34 -0700, Peter Geoghegan wrote: > On Fri, Aug 11, 2023 at 10:57 AM Andres Freund <andres@anarazel.de> wrote: > > I am quite strongly against this. This will lead to assertions being hit in > > tests without that being noticed, e.g. because they happen in a background > > process that just restarts. > > Couldn't you say the same thing about defensive "can't happen" ERRORs? > They are essentially a form of assertion that isn't limited to > assert-enabled builds. Yes. A lot of them I hate them with the passion of a thousand suns ;). "Oh, our transaction state machinery is confused. Yes, let's just continue going through the same machinery again, that'll resolve it.". Even worse are the ones that are just WARNINGS. Like "Oh, something wrote beyond the length of allocated memory, that's something to issue a WARNING about and happily continue". There've been people arguing in the past that it's good for robustness to do stuff like that. I think it's exactly the opposite. Now, don't get me wrong, there are plenty cases where a "this shouldn't happen" elog(ERROR) is appropriate... > I have sometimes thought that it would be handy if there was a variant > of "can't happen" ERRORs that took on the structure of an assertion. What are you imagining? Basically something that generates an elog(ERROR) with the stringified expression as part of the error message? Greetings, Andres Freund
On Fri, Aug 11, 2023 at 11:23 AM Andres Freund <andres@anarazel.de> wrote: > > Couldn't you say the same thing about defensive "can't happen" ERRORs? > > They are essentially a form of assertion that isn't limited to > > assert-enabled builds. > > Yes. A lot of them I hate them with the passion of a thousand suns ;). "Oh, > our transaction state machinery is confused. Yes, let's just continue going > through the same machinery again, that'll resolve it.". I am not unsympathetic to Ashutosh's point about conventional ERRORs being easier to deal with when debugging your own code, during initial development work. But that seems like a problem with the tooling in other areas. For example, dealing with core dumps left behind by the regression tests can be annoying. Don't you also hate it when there's a regression.diffs that just shows 20k lines of subtractions? Perhaps you don't -- perhaps your custom setup makes it quick and easy to get relevant information about what actually went wrong. But it seems like that sort of thing could be easier to deal with by default, without using custom shell scripts or anything -- particularly for those of us that haven't been Postgres hackers for eons. > There've been people arguing in the past that it's good for robustness to do > stuff like that. I think it's exactly the opposite. > > Now, don't get me wrong, there are plenty cases where a "this shouldn't > happen" elog(ERROR) is appropriate... Right. They're not bad -- they just need to be backed up by some kind of reasoning, which will be particular to each case. The default approach should be to crash whenever any invariants are violated, because all bets are off at that point. > What are you imagining? Basically something that generates an elog(ERROR) with > the stringified expression as part of the error message? I'd probably start with a new elevel, that implied an assertion failure in assert-enabled builds but otherwise acted just like ERROR. I remember multiple cases where I added an "Assert(false)" right after a "can't happen" error, which isn't a great approach. It might also be useful to offer something along the lines you've described, which I was sort of thinking of myself. But now that I've thought about it a little more, I think that such an approach might end up being overused. If you're going to add what amounts to a "can't happen" ERROR then you should really be obligated to write a halfway reasonable error message. As I said, you should have to own the fact that you think it's better to not just crash for this one particular callsite, based on some fairly specific chain of reasoning. Ideally it'll be backed up by practical experience/user reports. -- Peter Geoghegan
Hi, On 2023-08-11 11:56:27 -0700, Peter Geoghegan wrote: > On Fri, Aug 11, 2023 at 11:23 AM Andres Freund <andres@anarazel.de> wrote: > > > Couldn't you say the same thing about defensive "can't happen" ERRORs? > > > They are essentially a form of assertion that isn't limited to > > > assert-enabled builds. > > > > Yes. A lot of them I hate them with the passion of a thousand suns ;). "Oh, > > our transaction state machinery is confused. Yes, let's just continue going > > through the same machinery again, that'll resolve it.". > > I am not unsympathetic to Ashutosh's point about conventional ERRORs > being easier to deal with when debugging your own code, during initial > development work. Oh, I am as well - I just don't think it's a good idea to introduce "log + error" assertions to core postgres, because it seems very likely that they'll end up getting used a lot. > But that seems like a problem with the tooling in other areas. Agreed. > For example, dealing with core dumps left behind by the regression > tests can be annoying. Hm. I don't have a significant problem with that. But I can see it being problematic. Unfortunately, short of preventing core dumps from happening, I don't think we really can do much about that - whatever is running the tests shouldn't have privileges to change system wide settings about where core dumps end up etc. > Don't you also hate it when there's a regression.diffs that just shows 20k > lines of subtractions? Perhaps you don't -- perhaps your custom setup makes > it quick and easy to get relevant information about what actually went > wrong. I do really hate that. At the very least we should switch to using restart-after-crash by default, and not start new tests once the server has crashed and do a waitpid(postmaster, WNOHANG) after each failing test, to see if the reason the test failed is that the backend died. > But it seems like that sort of thing could be easier to deal with by > default, without using custom shell scripts or anything -- particularly for > those of us that haven't been Postgres hackers for eons. Yes, wholeheartedly agreed. Greetings, Andres Freund
On Fri, Aug 11, 2023 at 12:26 PM Andres Freund <andres@anarazel.de> wrote: > > For example, dealing with core dumps left behind by the regression > > tests can be annoying. > > Hm. I don't have a significant problem with that. But I can see it being > problematic. Unfortunately, short of preventing core dumps from happening, > I don't think we really can do much about that - whatever is running the tests > shouldn't have privileges to change system wide settings about where core > dumps end up etc. I was unclear. I wasn't talking about managing core dumps. I was talking about using core dumps to get a simple backtrace, that just gives me some very basic information. I probably shouldn't have even mentioned core dumps, because what I'm really concerned about is the workflow around getting very basic information about assertion failures. Not around core dumps per se. The inconsistent approach needed to get a simple, useful backtrace for assertion failures (along with other basic information associated with the failure) is a real problem. Particularly when running the tests. Most individual assertion failures that I see are for code that I'm practically editing in real time. So shaving cycles here really matters. For one thing the symbol mangling that we have around the built-in backtraces makes them significantly less useful. I really hope that your libbacktrace patch gets committed soon, since that looks like it would be a nice quality of life improvement, all on its own. It would also be great if the tests spit out information about assertion failures that was reasonably complete (backtrace without any mangling, query text included, other basic context), reliably and uniformly -- it shouldn't matter if it's from TAP or pg_regress test SQL scripts. Which kind of test happened to be involved is usually not interesting to me here (even the query text won't usually be interesting), so being forced to think about it slows me down quite a lot. > > Don't you also hate it when there's a regression.diffs that just shows 20k > > lines of subtractions? Perhaps you don't -- perhaps your custom setup makes > > it quick and easy to get relevant information about what actually went > > wrong. > > I do really hate that. At the very least we should switch to using > restart-after-crash by default, and not start new tests once the server has > crashed and do a waitpid(postmaster, WNOHANG) after each failing test, to see > if the reason the test failed is that the backend died. +1 -- Peter Geoghegan
Hi, On 2023-08-11 13:19:34 -0700, Peter Geoghegan wrote: > On Fri, Aug 11, 2023 at 12:26 PM Andres Freund <andres@anarazel.de> wrote: > > > For example, dealing with core dumps left behind by the regression > > > tests can be annoying. > > > > Hm. I don't have a significant problem with that. But I can see it being > > problematic. Unfortunately, short of preventing core dumps from happening, > > I don't think we really can do much about that - whatever is running the tests > > shouldn't have privileges to change system wide settings about where core > > dumps end up etc. > > I was unclear. I wasn't talking about managing core dumps. I was > talking about using core dumps to get a simple backtrace, that just > gives me some very basic information. I probably shouldn't have even > mentioned core dumps, because what I'm really concerned about is the > workflow around getting very basic information about assertion > failures. Not around core dumps per se. > > The inconsistent approach needed to get a simple, useful backtrace for > assertion failures (along with other basic information associated with > the failure) is a real problem. Particularly when running the tests. > Most individual assertion failures that I see are for code that I'm > practically editing in real time. So shaving cycles here really > matters. Ah, yes. Agreed, obviously. > For one thing the symbol mangling that we have around the built-in > backtraces makes them significantly less useful. I really hope that > your libbacktrace patch gets committed soon, since that looks like it > would be a nice quality of life improvement, all on its own. I've been hacking a further on it: https://github.com/anarazel/postgres/tree/backtrace Haven't yet posted a new version. Doing it properly for fronted tools has some dependencies on threading stuff. I'm hoping Thomas' patch for that will go in. Now it also intercepts segfaults and prints backtraces for them, if that's possible (it requires libbacktrace to be async signal safe, which it isn't on all platforms). Where supported, a crash (distinguishing from assertion failures) will now report something like: process with pid: 2900527 received signal: SIGSEGV, si_code: 1, si_addr: 0xdeadbeef [0x5628ec45212f] pg_fatalsig_handler+0x20f: ../../../../home/andres/src/postgresql/src/common/pg_backtrace.c:615 [0x7fc4b743650f] [unknown] [0x5628ec14897c] check_root+0x19c (inlined): ../../../../home/andres/src/postgresql/src/backend/main/main.c:393 [0x5628ec14897c] main+0x19c: ../../../../home/andres/src/postgresql/src/backend/main/main.c:183 after I added *(volatile int*)0xdeadbeef = 1; to check_root(). For signals sent by users, it'd show the pid of the process sending the signal on most OSs. I really would like some generalized infrastructure for that, so that we can report for things like query cancellations. As the patch stands, the only OS that doesn't yet have useful "backtrace on crash" support with that is windows, as libbacktrace unfortunately isn't signal safe on windows. But it'd still provide useful backtraces on Assert()s. I haven't yet figured out whether/when it's required to be signal safe on windows though - crashes are intercepted by SetUnhandledExceptionFilter() - I don't understand the precise constraints of that. Plenty people seem to generate backtraces on crashes on windows using that, without concerns for signal safety like things. Currently Macos CI doesn't use libbacktrace, but as it turns out backtrace_symbols() on windows is a heck of a lot better than on glibc platforms. CI for windows with visual studio doesn't have libbacktrace installed yet (and has the aforementioned signal safety issue), I think it's installed for windows w/ mingw. > It would also be great if the tests spit out information about > assertion failures that was reasonably complete (backtrace without any > mangling, query text included, other basic context), reliably and > uniformly -- it shouldn't matter if it's from TAP or pg_regress test > SQL scripts. Hm. What other basic context are you thinking of? Pid is obvious. I guess backend type could be useful too, but normally be inferred from the stack trace pretty easily. Application name could be useful to know which test caused the crash. I'm a bit wary about trying to print things like query text - what if that string points to memory not terminated by a \0? I guess we could use an approach similar to pgstat_get_crashed_backend_activity(). One issue with reporting crashes from signal handlers is that the obvious way to make that signal safe (lots of small writes) leads to the potential for interspersed lines. It's probably worth having a statically sized buffer that will commonly be large enough to print a whole backtrace. When too small, it should include the pid at the start of every "chunk". > Which kind of test happened to be involved is usually not interesting to me > here (even the query text won't usually be interesting), so being forced to > think about it slows me down quite a lot. Interesting - I quite often end up spending time trying to dig out which query from what sql file triggered a crash, so I can try to trigger it in isolation. I often wished the server knew the source line associated with the query. Enough that I pondered ways to have psql transport that knowledge to the the server. Greetings, Andres Freund
On Fri, Aug 11, 2023 at 2:04 PM Andres Freund <andres@anarazel.de> wrote: > Where supported, a crash (distinguishing from assertion failures) will now > report something like: > > process with pid: 2900527 received signal: SIGSEGV, si_code: 1, si_addr: 0xdeadbeef > [0x5628ec45212f] pg_fatalsig_handler+0x20f: ../../../../home/andres/src/postgresql/src/common/pg_backtrace.c:615 > [0x7fc4b743650f] [unknown] > [0x5628ec14897c] check_root+0x19c (inlined): ../../../../home/andres/src/postgresql/src/backend/main/main.c:393 > [0x5628ec14897c] main+0x19c: ../../../../home/andres/src/postgresql/src/backend/main/main.c:183 > > after I added > *(volatile int*)0xdeadbeef = 1; > to check_root(). It'll be like living in the future! > For signals sent by users, it'd show the pid of the process sending the signal > on most OSs. I really would like some generalized infrastructure for that, so > that we can report for things like query cancellations. That sounds great. > > It would also be great if the tests spit out information about > > assertion failures that was reasonably complete (backtrace without any > > mangling, query text included, other basic context), reliably and > > uniformly -- it shouldn't matter if it's from TAP or pg_regress test > > SQL scripts. > > Hm. What other basic context are you thinking of? Pid is obvious. I guess > backend type could be useful too, but normally be inferred from the stack > trace pretty easily. Application name could be useful to know which test > caused the crash. > > I'm a bit wary about trying to print things like query text - what if that > string points to memory not terminated by a \0? I guess we could use an > approach similar to pgstat_get_crashed_backend_activity(). I agree that being less verbose by default is good. On second thought even query text isn't all that important. > One issue with reporting crashes from signal handlers is that the obvious way > to make that signal safe (lots of small writes) leads to the potential for > interspersed lines. It's probably worth having a statically sized buffer that > will commonly be large enough to print a whole backtrace. When too small, it > should include the pid at the start of every "chunk". Good idea. > > Which kind of test happened to be involved is usually not interesting to me > > here (even the query text won't usually be interesting), so being forced to > > think about it slows me down quite a lot. > > Interesting - I quite often end up spending time trying to dig out which query > from what sql file triggered a crash, so I can try to trigger it in > isolation. I often wished the server knew the source line associated with the > query. Enough that I pondered ways to have psql transport that knowledge to the > the server. I actually do plenty of that too. My overall point was this: there is likely some kind of pareto principle here. That should guide the sorts of scenarios we optimize for. If you actually benchmarked where I spent time while writing code, minute to minute, I bet it would show that most of the individual debug-compile cycles were triggered by issues that had a fairly simple and immediate cause. Cases where I improve one small thing, and then rerun the tests, which show an assertion failure in nearby code. As soon as I see very basic details I immediately think "duh, of course" in these cases, at which point I'll come up with a likely-good fix in seconds. And then I'll rinse and repeat. My fix might just work (at least to the extent that all tests now pass), but it also might lead to another assertion failure of the same general nature. There are also lots of cases where I really do have to think about recreating the details from the test in order to truly understand what's going on, of course. But there are still way way more individual "duh, of course" assertion failures in practice. Those are where productivity wins are still possible, because the bottleneck isn't just that I have an incomplete mental model that I need to work to expand. Perhaps my experiences here aren't universal. But it seems like they might be roughly the same as everybody else that works on Postgres? Assuming that they are, then the information that is output should be optimized for the "duh, of course" scenarios. Not to an absurd degree, mind you. But the output shouldn't be too verbose. Ideally there'd be a still fairly straightforward way of getting extra information, for the cases where debugging is likely to take a few minutes, and require real focus. The extra work in those other cases is relatively insignificant, because the "startup costs" are relatively large -- a little extra indirection (though only a little) can't hurt too much. -- Peter Geoghegan
On Fri, Aug 11, 2023 at 11:27 PM Andres Freund <andres@anarazel.de> wrote: > > > > Attached patch combines Assert and elog(ERROR, ) so that when an > > Assert is triggered in assert-enabled binary, it will throw an error > > while keeping the backend intact. Thus it does not affect gdb session > > or psql session. These elogs do not make their way to non-assert > > binary so do not make it to production like Assert. > > I am quite strongly against this. This will lead to assertions being hit in > tests without that being noticed, e.g. because they happen in a background > process that just restarts. Fair point. Our regression doesn't check server error logs for unwanted errors. How about restricting it to only client backends? I don't know how to identify those from others but there must be a way. -- Best Wishes, Ashutosh Bapat
On Sat, Aug 12, 2023 at 12:56 AM Andres Freund <andres@anarazel.de> wrote: > On 2023-08-11 11:56:27 -0700, Peter Geoghegan wrote: > > On Fri, Aug 11, 2023 at 11:23 AM Andres Freund <andres@anarazel.de> wrote: > > > > Couldn't you say the same thing about defensive "can't happen" ERRORs? > > > > They are essentially a form of assertion that isn't limited to > > > > assert-enabled builds. > > > > > > Yes. A lot of them I hate them with the passion of a thousand suns ;). "Oh, > > > our transaction state machinery is confused. Yes, let's just continue going > > > through the same machinery again, that'll resolve it.". > > > > I am not unsympathetic to Ashutosh's point about conventional ERRORs > > being easier to deal with when debugging your own code, during initial > > development work. > > Oh, I am as well - I just don't think it's a good idea to introduce "log + error" > assertions to core postgres, because it seems very likely that they'll end up > getting used a lot. > > I am open to ideas which allow the same backend to recover after meeting an easily recoverable but "can't happen" condition rather than losing that backend and starting all over with a new backend. Not all Assert'ed conditions are recoverable so a blanket GUC or compile time option won't help. Those might make things worse. We need two separate incantations for non-recoverable and recoverable Asserts respectively. I like Peter's idea of having a new elevel, however it still requires adding conditional USE_ASSERT, an if testing the condition and then writing an error message. AssertLog() in the patch uses just a few more letters. It won't help to expand the scope of the problem since that will reduce the chances of getting anything done. -- Best Wishes, Ashutosh Bapat