Thread: Override compile time log levels of specific messages/modules
While reviewing Jeff's notice_lock_waits patch, I came across his comment about having a general facility for promoting selected LOG messages. So I thought I should post it here, even though the patch is probably far from being accepted in Postgres.
I recently wrote a patch for Postgres-XL to do exactly this and I found it very useful, especially while debugging race conditions and problems with ongoing sessions. I'm attaching a patch rebased on PG-master. It works, but TBH I don't think it's anywhere close for being acceptable in PG. But I hope this is good enough to show how this can be done with minimal changes and spark ideas.
The patch uses some preprocessing and scripting magic to assign distinct identifiers to each module (a subdir in the source code), to each file and to each elog message. It then provides a set of functions by which an user can increase/decrease/set log levels for either individual messages or all messages within a source file or source module. The log levels can be changed only for specific backends or all current or future backends. If you configure with --enable-genmsgids switch, a MSGMODULES and MSGIDS file is created in $srcdir, which can later be used to know ids assigned to various modules/messages.
Now there are several problems with the patch:
- I don't know if it will work for anything other than clang and gcc (I've tested those two, but only specific versions)
- The shared memory representation for msgs is not at all optimal and with a large value of max_connections, it can quickly go out of control. But I believe we can find a better representation without losing runtime performance.
- The APIs themselves can be significantly improved.
- MSGMODULES and MSGIDS should probably be some sort of a view that user can readily access without requiring access to the environment where it was built.
- Right now it only supports changing levels for DEBUG[1-5] and LOG messages. But that could be easily extended to cover INFO or NOTICE.
- The patch should probably have many more comments
- Finally, I don't know if better and more elegant ways exist to automatically assigning module/file/msgids. I couldn't think of any without making excessive changes to all source files and hence did what I did. That does not mean better ways don't exists.
Thanks,
Pavan
Pavan Deolasee http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services
PostgreSQL Development, 24x7 Support, Training & Services
Attachment
<p dir="ltr"><p dir="ltr">On 6 Sep. 2016 17:28, "Pavan Deolasee" <<a href="mailto:pavan.deolasee@gmail.com">pavan.deolasee@gmail.com</a>>wrote:<br /> ><p dir="ltr">><br /> > Thepatch uses some preprocessing and scripting magic to assign distinct identifiers to each module (a subdir in the sourcecode), to each file and to each elog message. It then provides a set of functions by which an user can increase/decrease/setlog levels for either individual messages or all messages within a source file or source module. Thelog levels can be changed only for specific backends or all current or future backends. If you configure with --enable-genmsgidsswitch, a MSGMODULES and MSGIDS file is created in $srcdir, which can later be used to know ids assignedto various modules/messages.<p dir="ltr">I think it's worth looking at how Java handles logging. We can't achievean exact parallel in C as we don't really have a class hierarchy ... but we do have subsystems roughly grouped byfile and directory structure.<p dir="ltr">Being able to promote/demote these or selective lower the log level thresholdon a directory, file, function and line level would be exceedingly handy. Pretty much all of that can be magic'dup from macro output so hopefully no postprocessing should be needed. (Though only gcc has _FUNC_ or _FUNCTION_ Ithink so we'd have selective support there.)<br />
On Tue, Sep 6, 2016 at 3:06 PM, Craig Ringer <craig.ringer@2ndquadrant.com> wrote:
Well, __FUNCTION__ expands to function name and lookup based on string identifiers will always be costly, especially if you want to sprinkle the code with lot many debug messages. Same with __FILE__. I believe we need an unique integer constant to make it a fast, O(1) lookup. I couldn't find any other method to do that when I wrote the facility and hence did what I did.
I think it's worth looking at how Java handles logging. We can't achieve an exact parallel in C as we don't really have a class hierarchy ... but we do have subsystems roughly grouped by file and directory structure.
Sure. In some large, popular enterprise softwares I've worked with many years ago, we used to define modules within each source file and then manually assign distinct integer IDs to each message and then provide various utilities to turn on/off specific messages or range of messages within a module.
Being able to promote/demote these or selective lower the log level threshold on a directory, file, function and line level would be exceedingly handy. Pretty much all of that can be magic'd up from macro output so hopefully no postprocessing should be needed. (Though only gcc has _FUNC_ or _FUNCTION_ I think so we'd have selective support there.)
Thanks,
Pavan
-- Pavan Deolasee http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services
PostgreSQL Development, 24x7 Support, Training & Services
<p dir="ltr">On 6 Sep. 2016 17:57, "Pavan Deolasee" <<a href="mailto:pavan.deolasee@gmail.com">pavan.deolasee@gmail.com</a>>wrote:<br /> ><br /> ><br /> ><br /> >On Tue, Sep 6, 2016 at 3:06 PM, Craig Ringer <<a href="mailto:craig.ringer@2ndquadrant.com">craig.ringer@2ndquadrant.com</a>>wrote:<br /> >><br /> >><br />>> I think it's worth looking at how Java handles logging. We can't achieve an exact parallel in C as we don't reallyhave a class hierarchy ... but we do have subsystems roughly grouped by file and directory structure.<br /> ><br/> > Sure. In some large, popular enterprise softwares I've worked with many years ago, we used to define moduleswithin each source file and then manually assign distinct integer IDs to each message and then provide various utilitiesto turn on/off specific messages or range of messages within a module.<p dir="ltr">Yeah, there same has been discussedfor Pg many times and firmly shot down each time. I certainly see the argument against making specific elog callspart of a sort of api people might expect to be stable ish. That's what we have ERRCODE / SQLSTATE for right? Concernsabout backpatch pain were also raised. Probably more. I'm not especially for or against it myself, just saying thatbased on past discussion such a proposal isn't likely to fly.<p dir="ltr">I think something automatic that we clearlydefine as unstable and not to be relied upon would be preferable. Plus we already have much of the infrastructurein elog.c as used by errcontext etc.<p dir="ltr">> Well, __FUNCTION__ expands to function name and lookupbased on string identifiers will always be costly, especially if you want to sprinkle the code with lot many debugmessages. Same with __FILE__. I believe we need an unique integer constant to make it a fast, O(1) lookup. I couldn'tfind any other method to do that when I wrote the facility and hence did what I did.<p dir="ltr">Yeah. High performancelogging and filtering isnt easy. Looking at existing C logging libraries with dynamic filtering might be informative.Though I can't imagine there being agreement to adopt one, this must be a reasonably solved problem...<p dir="ltr">><br/> > Thanks,<br /> > Pavan<br /> > -- <br /> > Pavan Deolasee <a href="http://www.2ndQuadrant.com/">http://www.2ndQuadrant.com/</a><br /> > PostgreSQL Development, 24x7 Support, Training& Services<br />
On 9/6/16 5:18 AM, Craig Ringer wrote: > I think something automatic that we clearly define as unstable and not > to be relied upon would be preferable. Plus we already have much of the > infrastructure in elog.c as used by errcontext etc. Actually, I wish this was a straight-up logging level feature, because I need it all the time when debugging complicated user-level code. Specifically, I wish there was a GUC that would alter (client|log)_min_messages upon entering a specific function, either for just that function or for anything that function subsequently called. Bonus points if you could also specify a regex that the message text had to match. I realize that code-wise that's completely incompatible with what you're discussing here, but I think the same API could be used (maybe as a different GUC). -- Jim Nasby, Data Architect, Blue Treble Consulting, Austin TX Experts in Analytics, Data Architecture and PostgreSQL Data in Trouble? Get it in Treble! http://BlueTreble.com 855-TREBLE2 (855-873-2532) mobile: 512-569-9461
<p dir="ltr"><p dir="ltr">On 11 Sep. 2016 11:31, "Jim Nasby" <<a href="mailto:Jim.Nasby@bluetreble.com">Jim.Nasby@bluetreble.com</a>>wrote:<p dir="ltr">> Actually, I wish this wasa straight-up logging level feature, because I need it all the time when debugging complicated user-level code. Specifically,I wish there was a GUC that would alter (client|log)_min_messages upon entering a specific function, eitherfor just that function or for anything that function subsequently called.<p dir="ltr">We have that or close to it,but it's restricted for security. IIRC you can't SET log_min_messages as non superuser including as part of CREATE FUNCTION... SET. Presumably because lowering it would let the user hide activity admins expect to be recorded. Raising itwould let them possibly DoS via log spam - though that argument is rather undermined by the ability to write plpgsql thatdoes RAISE in a tight loop.<p dir="ltr">I'd like to be able to let users make logging more detailed but not less, sothey can only SET it to something equal to or more detailed to what their session has art the start. Should actually bepretty trivial to implement too.<p dir="ltr">You can then SET at session level, function level, SET LOCAL, etc. If youwant to control it dynamically via GUC you add calls to your functions to check a custom user GUC and SET log level accordingly.Using whatever logic you like.<br /><br /><p dir="ltr">> Bonus points if you could also specify a regex thatthe message text had to match.<br /> ><p dir="ltr">An errfinish() hook would be nice for that.