Thread: Call stacks and RAISE INFO
All, I'm noticing some inconsistent and (I believe) undesirable behavior on RAISE INFO. If you call a function, and it posts progress reports using RAISE INFO, then you get the INFO statements plain back to the client. However, if that function calls another function, then you also get a three-line CONTEXT message ... and if the functions are recursively called, the CONTEXT message will emit 3 lines for every level of the call stack. This seems like reasonable behavior for RAISE EXCEPTION but not RAISE INFO. It pretty much makes INFO notices useless as end-user feedback if you have functions calling other functions because of the amount of garbage on the screen. Is this a bug? -- Josh Berkus PostgreSQL Experts Inc. http://pgexperts.com
Excerpts from Josh Berkus's message of vie oct 14 13:52:32 -0300 2011: > All, > > I'm noticing some inconsistent and (I believe) undesirable behavior on > RAISE INFO. > > If you call a function, and it posts progress reports using RAISE INFO, > then you get the INFO statements plain back to the client. However, if > that function calls another function, then you also get a three-line > CONTEXT message ... and if the functions are recursively called, the > CONTEXT message will emit 3 lines for every level of the call stack. > > This seems like reasonable behavior for RAISE EXCEPTION but not RAISE > INFO. It pretty much makes INFO notices useless as end-user feedback if > you have functions calling other functions because of the amount of > garbage on the screen. Is this a bug? Maybe set the verbosity to a lower level in the function? I dunno if plpgsql lets you do that though. We have a GUC that controls the server log verbosity, and psql can do it too; but plpgsql is sort of in between. -- Álvaro Herrera <alvherre@commandprompt.com> The PostgreSQL Company - Command Prompt, Inc. PostgreSQL Replication, Consulting, Custom Development, 24x7 support
> Maybe set the verbosity to a lower level in the function? I dunno if > plpgsql lets you do that though. We have a GUC that controls the server > log verbosity, and psql can do it too; but plpgsql is sort of in > between. The problem is that there is no level of verbosity which will supress the CONTEXT messages and not supress the INFO messages as well. Not that I've found, anyway. -- Josh Berkus PostgreSQL Experts Inc. http://pgexperts.com
Excerpts from Josh Berkus's message of vie oct 14 14:16:43 -0300 2011: > > > Maybe set the verbosity to a lower level in the function? I dunno if > > plpgsql lets you do that though. We have a GUC that controls the server > > log verbosity, and psql can do it too; but plpgsql is sort of in > > between. > > The problem is that there is no level of verbosity which will supress > the CONTEXT messages and not supress the INFO messages as well. Not > that I've found, anyway. I meant verbosity, not error level. This quick test shows what I meant -- but it doesn't work; the server log is altered as I expected (and does not include the context lines), but not plpgsql's: alvherre=# create function f() returns void language plpgsql as $$ begin raise info 'hello'; end $$; CREATE FUNCTION alvherre=# select f(); INFO: hellof --- (1 fila) alvherre=# create function g() returns void language plpgsql as $$ begin perform f(); end $$; CREATE FUNCTION alvherre=# select g(); INFO: hello CONTEXTO: SQL statement "SELECT f()" función PL/pgSQL «g» en la línea 1 en PERFORMg --- (1 fila) alvherre=# alter function g() set log_error_verbosity to 'terse'; ALTER FUNCTION alvherre=# select g(); INFO: hello CONTEXTO: SQL statement "SELECT f()" función PL/pgSQL «g» en la línea 1 en PERFORMg --- (1 fila) alvherre=# alter function f() set log_error_verbosity to 'terse'; ALTER FUNCTION alvherre=# select g(); INFO: hello CONTEXTO: SQL statement "SELECT f()" función PL/pgSQL «g» en la línea 1 en PERFORMg --- (1 fila) -- Álvaro Herrera <alvherre@commandprompt.com> The PostgreSQL Company - Command Prompt, Inc. PostgreSQL Replication, Consulting, Custom Development, 24x7 support
> I meant verbosity, not error level. This quick test shows what I meant > -- but it doesn't work; the server log is altered as I expected (and does not > include the context lines), but not plpgsql's: Yeah, what we'd need is a client_error_verbosity setting. -- Josh Berkus PostgreSQL Experts Inc. http://pgexperts.com
On Oct14, 2011, at 19:27 , Josh Berkus wrote: >> I meant verbosity, not error level. This quick test shows what I meant >> -- but it doesn't work; the server log is altered as I expected (and does not >> include the context lines), but not plpgsql's: > > Yeah, what we'd need is a client_error_verbosity setting. We do transmit the individual parts of a NOTICE separately, so I'd say suppressing some of them is the client's job. So, instead of a GUC I'd say we'd need a psql setting ERROR_VERBOSITY. best regards, Florian Pflug
Excerpts from Florian Pflug's message of vie oct 14 14:41:11 -0300 2011: > > On Oct14, 2011, at 19:27 , Josh Berkus wrote: > >> I meant verbosity, not error level. This quick test shows what I meant > >> -- but it doesn't work; the server log is altered as I expected (and does not > >> include the context lines), but not plpgsql's: > > > > Yeah, what we'd need is a client_error_verbosity setting. > > We do transmit the individual parts of a NOTICE separately, so I'd say > suppressing some of them is the client's job. So, instead of a GUC I'd say > we'd need a psql setting ERROR_VERBOSITY. Well, we do have a psql setting as well (\set VERBOSITY). But is Josh using psql? -- Álvaro Herrera <alvherre@commandprompt.com> The PostgreSQL Company - Command Prompt, Inc. PostgreSQL Replication, Consulting, Custom Development, 24x7 support
>> We do transmit the individual parts of a NOTICE separately, so I'd say >> suppressing some of them is the client's job. So, instead of a GUC I'd say >> we'd need a psql setting ERROR_VERBOSITY. > > Well, we do have a psql setting as well (\set VERBOSITY). But is Josh > using psql? Not in this instance, no. In any case, this doesn't address the inconsistency of supressing CONTEXT for the first level of the call stack with RAISE INFO but not for the others. (RAISE EXCEPTION shows CONTEXT for all levels of the call stack). -- Josh Berkus PostgreSQL Experts Inc. http://pgexperts.com
Josh Berkus <josh@agliodbs.com> writes: >> I meant verbosity, not error level. This quick test shows what I meant >> -- but it doesn't work; the server log is altered as I expected (and does not >> include the context lines), but not plpgsql's: > Yeah, what we'd need is a client_error_verbosity setting. It seems to me that a client-side facility would be unlikely to do the right things, because it has not got enough information to know which messages came from plpgsql RAISE commands. Moreover, it's not apparent that a one-size-fits-all approach is suitable anyhow: it may be that some RAISEs don't need context traceback while others could use it. Now that we have syntax for adding miscellaneous options to RAISE statements, what I suggest we consider is a RAISE option that suppresses all context lines for the message, perhaps RAISE NOTICE 'fee, fi, fo, fum' USING context = false; regards, tom lane
Josh Berkus <josh@agliodbs.com> writes: > In any case, this doesn't address the inconsistency of supressing > CONTEXT for the first level of the call stack with RAISE INFO but not > for the others. (RAISE EXCEPTION shows CONTEXT for all levels of the > call stack). Oh? I don't see that. AFAICT the behavior is not dependent on the error severity level. RAISE just automatically suppresses the context line from the current plpgsql function. Not sure if we need to make that part of the behavior configurable or not. regards, tom lane
> Now that we have syntax for adding miscellaneous options to RAISE > statements, what I suggest we consider is a RAISE option that suppresses > all context lines for the message, perhaps > > RAISE NOTICE 'fee, fi, fo, fum' USING context = false; Yeah, that would do it. Pavel? ;-) -- Josh Berkus PostgreSQL Experts Inc. http://pgexperts.com
On Oct14, 2011, at 20:00 , Josh Berkus wrote: >>> We do transmit the individual parts of a NOTICE separately, so I'd say >>> suppressing some of them is the client's job. So, instead of a GUC I'd say >>> we'd need a psql setting ERROR_VERBOSITY. >> >> Well, we do have a psql setting as well (\set VERBOSITY). But is Josh >> using psql? Yeah, I meant that we could split that into two settings, one for level >= ERROR and one for level < ERROR. It'd certainly be nice to be able to report progress messages from functions without seeing all the CONTEXT and STATEMENT noise when running them via psql, yet still get that information if an actual error occurs. > Not in this instance, no. But I still believe this is something that should be done client-side. best regards, Florian Pflug
On Oct14, 2011, at 23:51 , Tom Lane wrote: > Josh Berkus <josh@agliodbs.com> writes: >>> I meant verbosity, not error level. This quick test shows what I meant >>> -- but it doesn't work; the server log is altered as I expected (and does not >>> include the context lines), but not plpgsql's: > >> Yeah, what we'd need is a client_error_verbosity setting. > > It seems to me that a client-side facility would be unlikely to do the > right things, because it has not got enough information to know which > messages came from plpgsql RAISE commands. Moreover, it's not apparent > that a one-size-fits-all approach is suitable anyhow: it may be that > some RAISEs don't need context traceback while others could use it. Hm, I think you'd usually want to adjust the verbosity of log messages when you *run* code, not when you *write* it. That's the raison d'etre for having logging infrastructure and verbosity settings, after all. When I'm running a function from psql interactively, I probably want to suppress CONTEXT and maybe STATEMENT lines for NOTICEs - presumably the message itself tells me everything I need to know. When I'm running the same function in a setting where there messages go to a log file, I probably want to include as much context information as necessary in order to be able to debug possible problems post-mortem. Having said that, having the option to not emit CONTEXT lines in the first place wouldn't hurt of course. best regards, Florian Pflug
Florian Pflug <fgp@phlo.org> writes: > On Oct14, 2011, at 23:51 , Tom Lane wrote: >> It seems to me that a client-side facility would be unlikely to do the >> right things, because it has not got enough information to know which >> messages came from plpgsql RAISE commands. Moreover, it's not apparent >> that a one-size-fits-all approach is suitable anyhow: it may be that >> some RAISEs don't need context traceback while others could use it. > Hm, I think you'd usually want to adjust the verbosity of log messages > when you *run* code, not when you *write* it. That's the raison d'etre > for having logging infrastructure and verbosity settings, after all. No, I don't think so. The use-case for this sort of thing seems to me to be messages that are directed to the user or DBA, and don't want to be decorated with a lot of information about where they came from. That determination is usually pretty clear when you write the code. Moreover, if we don't attach the specification to particular RAISE commands, it's going to be "all or nothing", which is most definitely not the right thing. Having said that, if we allow "USING context = boolean_expression", it'd be possible for the plpgsql coder to make the behavior run-time adjustable if he wanted. regards, tom lane
Hello 2011/10/15 Josh Berkus <josh@agliodbs.com>: > >> Now that we have syntax for adding miscellaneous options to RAISE >> statements, what I suggest we consider is a RAISE option that suppresses >> all context lines for the message, perhaps >> >> RAISE NOTICE 'fee, fi, fo, fum' USING context = false; > > Yeah, that would do it. Pavel? ;-) > I have no problem with this. A context can be false for info and true for other in default. Please, use a different identifier than "context", that can be use for reading context in future - maybe "attach_context" or some similar. Just note, when we are in this topis. I got a experience so debugging functions that contains a pattern BEGIN .. do some .. that can raise exception ... EXCEPT WHEN OTHERS .. .. do some else RAISE ... ; END IF is little bit difficult, because we lost a context information about original exception Regards Pavel > -- > Josh Berkus > PostgreSQL Experts Inc. > http://pgexperts.com > > -- > Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) > To make changes to your subscription: > http://www.postgresql.org/mailpref/pgsql-hackers >
On Sat, Oct 15, 2011 at 12:24 AM, Pavel Stehule <pavel.stehule@gmail.com> wrote: > I have no problem with this. A context can be false for info and true > for other in default. Please, use a different identifier than > "context", that can be use for reading context in future - maybe > "attach_context" or some similar. error_context? -- Robert Haas EnterpriseDB: http://www.enterprisedb.com The Enterprise PostgreSQL Company
2011/10/15 Robert Haas <robertmhaas@gmail.com>: > On Sat, Oct 15, 2011 at 12:24 AM, Pavel Stehule <pavel.stehule@gmail.com> wrote: >> I have no problem with this. A context can be false for info and true >> for other in default. Please, use a different identifier than >> "context", that can be use for reading context in future - maybe >> "attach_context" or some similar. > > error_context? what about show_context, hide_context, hold_context, use_context ?? > > -- > Robert Haas > EnterpriseDB: http://www.enterprisedb.com > The Enterprise PostgreSQL Company >
Pavel Stehule <pavel.stehule@gmail.com> writes: > 2011/10/15 Robert Haas <robertmhaas@gmail.com>: >> On Sat, Oct 15, 2011 at 12:24 AM, Pavel Stehule <pavel.stehule@gmail.com> wrote: >>> I have no problem with this. A context can be false for info and true >>> for other in default. Please, use a different identifier than >>> "context", that can be use for reading context in future - maybe >>> "attach_context" or some similar. >> error_context? > what about show_context, hide_context, hold_context, use_context ?? I still think it should be CONTEXT, period. All the other options to RAISE are named directly after the message lines they control; why should this one be different? regards, tom lane
2011/10/15 Tom Lane <tgl@sss.pgh.pa.us>: > Pavel Stehule <pavel.stehule@gmail.com> writes: >> 2011/10/15 Robert Haas <robertmhaas@gmail.com>: >>> On Sat, Oct 15, 2011 at 12:24 AM, Pavel Stehule <pavel.stehule@gmail.com> wrote: >>>> I have no problem with this. A context can be false for info and true >>>> for other in default. Please, use a different identifier than >>>> "context", that can be use for reading context in future - maybe >>>> "attach_context" or some similar. > >>> error_context? > >> what about show_context, hide_context, hold_context, use_context ?? > > I still think it should be CONTEXT, period. All the other options to > RAISE are named directly after the message lines they control; why > should this one be different? I had a idea to set CONTEXT from RAISE statement - for forwarding data from handled exception some like BEGIN ... EXCEPTION WHEN ... GET DIAGNOSTICS _context = PG_EXCEPTION_CONTEXT; REISE USING context = _context; END; Regards Pavel Stehule > > regards, tom lane >
> No, I don't think so. The use-case for this sort of thing seems to me > to be messages that are directed to the user or DBA, and don't want to > be decorated with a lot of information about where they came from. > That determination is usually pretty clear when you write the code. For my case, I agree with Tom. For example, in my recent debugging session, I was debugging a recursive function ... one which calls itself, up to 6 levels deep. For that function, I want to turn context off because there's so much it becomes unreadable, and instead I put a nesting counter in the INFO. I don't want to turn of context for other functions universally -- even in the same ETL session -- because I want to know what called them, since some of them can be called on multiple paths. -- Josh Berkus PostgreSQL Experts Inc. http://pgexperts.com