Re: [HACKERS] More logging for autovacuum
On Sat, Jul 4, 2015 at 2:30 PM, Amit Kapila amit.kapil...@gmail.com wrote: On Thu, Jul 2, 2015 at 4:41 AM, Gurjeet Singh gurj...@singh.im wrote: On Fri, Aug 17, 2007 at 3:14 PM, Alvaro Herrera alvhe...@commandprompt.com wrote: Gregory Stark wrote: I'm having trouble following what's going on with autovacuum and I'm finding the existing logging insufficient. In particular that it's only logging vacuum runs *after* the vacuum finishes makes it hard to see what vacuums are running at any given time. Also, I want to see what is making autovacuum decide to forgo vacuuming a table and the log with that information is at DEBUG2. So did this idea go anywhere? Assuming the thread stopped here, I'd like to rekindle the proposal. log_min_messages acts as a single gate for everything headed for the server logs; controls for per-background process logging do not exist. If one wants to see DEBUG/INFO messages for just the Autovacuum (or checkpointer, bgwriter, etc.), they have to set log_min_messages to that level, but the result would be a lot of clutter from other processes to grovel through, to see the messages of interest. I think that will be quite helpful. During the patch development of parallel sequential scan, it was quite helpful to see the LOG messages of bgworkers, however one of the recent commits (91118f1a) have changed those to DEBUG1, now if I have to enable all DEBUG1 messages, then what I need will be difficult to find in all the log messages. Having control of separate logging for background tasks will serve such a purpose. The facilities don't yet exist, but it'd be nice if such parameters when unset (ie NULL) pick up the value of log_min_messages. So by default, the users will get the same behaviour as today, but can choose to tweak per background-process logging when needed. Will this proposal allow user to see all the messages by all the background workers or will it be per background task. Example in some cases user might want to see the messages by all bgworkers and in some cases one might want to see just messages by AutoVacuum and it's workers. I think here designing User Interface is an important work if others also agree that such an option is useful, could you please elaborate your proposal? +1 I sometime want to set log_min_messages per process, especially when less than DEBUG level log is needed. It's not easy to set log level to particular process from immediately after beginning of launch today. Regards, -- Sawada Masahiko -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] More logging for autovacuum
On Sat, Jul 4, 2015 at 2:30 PM, Amit Kapila amit.kapil...@gmail.com wrote: On Thu, Jul 2, 2015 at 4:41 AM, Gurjeet Singh gurj...@singh.im wrote: On Fri, Aug 17, 2007 at 3:14 PM, Alvaro Herrera alvhe...@commandprompt.com wrote: Gregory Stark wrote: I'm having trouble following what's going on with autovacuum and I'm finding the existing logging insufficient. In particular that it's only logging vacuum runs *after* the vacuum finishes makes it hard to see what vacuums are running at any given time. Also, I want to see what is making autovacuum decide to forgo vacuuming a table and the log with that information is at DEBUG2. So did this idea go anywhere? Assuming the thread stopped here, I'd like to rekindle the proposal. log_min_messages acts as a single gate for everything headed for the server logs; controls for per-background process logging do not exist. If one wants to see DEBUG/INFO messages for just the Autovacuum (or checkpointer, bgwriter, etc.), they have to set log_min_messages to that level, but the result would be a lot of clutter from other processes to grovel through, to see the messages of interest. I think that will be quite helpful. During the patch development of parallel sequential scan, it was quite helpful to see the LOG messages of bgworkers, however one of the recent commits (91118f1a) have changed those to DEBUG1, now if I have to enable all DEBUG1 messages, then what I need will be difficult to find in all the log messages. Having control of separate logging for background tasks will serve such a purpose. +1 I sometime want to set log_min_messages per process, especially when less than DEBUG level log is needed. It's not easy to set log level to particular process from immediately after beginning of launch today. Regards, -- Sawada Masahiko -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] More logging for autovacuum
On Tue, Jul 7, 2015 at 11:20 AM, Sawada Masahiko sawada.m...@gmail.com wrote: On Sat, Jul 4, 2015 at 2:30 PM, Amit Kapila amit.kapil...@gmail.com wrote: On Thu, Jul 2, 2015 at 4:41 AM, Gurjeet Singh gurj...@singh.im wrote: log_min_messages acts as a single gate for everything headed for the server logs; controls for per-background process logging do not exist. If one wants to see DEBUG/INFO messages for just the Autovacuum (or checkpointer, bgwriter, etc.), they have to set log_min_messages to that level, but the result would be a lot of clutter from other processes to grovel through, to see the messages of interest. I think that will be quite helpful. During the patch development of parallel sequential scan, it was quite helpful to see the LOG messages of bgworkers, however one of the recent commits (91118f1a) have changed those to DEBUG1, now if I have to enable all DEBUG1 messages, then what I need will be difficult to find in all the log messages. Having control of separate logging for background tasks will serve such a purpose. The facilities don't yet exist, but it'd be nice if such parameters when unset (ie NULL) pick up the value of log_min_messages. So by default, the users will get the same behaviour as today, but can choose to tweak per background-process logging when needed. Will this proposal allow user to see all the messages by all the background workers or will it be per background task. Example in some cases user might want to see the messages by all bgworkers and in some cases one might want to see just messages by AutoVacuum and it's workers. I want the logging to be controlled per background process, so that user can pick and choose how much detail they want from each process. In absence of such a setting for a background process, the global log_min_messages should control the logging. I think here designing User Interface is an important work if others also agree that such an option is useful, could you please elaborate your proposal? +1 I would like this feature to be as simple as the current log_min_messages; currently a superuser can do ALTER USER X SET log_min_messages = Y, and control logging for specific users or databases or a combination of those. In the same vein, setting autovacuum.log_min_messages in postgresql.conf, or a corresponding ALTER SYSTEM should be enough to use a different setting of log_min_messages inside autovacuum launcher and its worker processes. I am using autovacuum process as an example, but the same is applicable to other background processes as well. E.g. checkpointer.log_min_messages. As for the implementation details, upon startup and after every reload, the autovacuum launcher process will look for autovacuum.log_min_messages being defined; if yes, it'd set the global variable log_min_messages in code to that value, and if not defined in any of the conf files, the global variable in code would be assigned whatever is assigned to the GUC param log_min_messages. DefineCustomXXVariable() seems incapable of supporting this behaviour, so we might have to invent a new one. This will allow us to keep the current behaviour as default when autovacuum.log_min_messages is not defined, and provide finer control over autovacuum's logging by defining this variable, when needed. Same goes for Checkpointer, BGWriter, WALWriter, and BGWorkers. BTW, the facility we invent needn't be limited to log_min_messages, but it's just what we need now. Best regards, -- Gurjeet Singh http://gurjeet.singh.im/
Re: [HACKERS] More logging for autovacuum
On Thu, Jul 2, 2015 at 4:41 AM, Gurjeet Singh gurj...@singh.im wrote: On Fri, Aug 17, 2007 at 3:14 PM, Alvaro Herrera alvhe...@commandprompt.com wrote: Gregory Stark wrote: I'm having trouble following what's going on with autovacuum and I'm finding the existing logging insufficient. In particular that it's only logging vacuum runs *after* the vacuum finishes makes it hard to see what vacuums are running at any given time. Also, I want to see what is making autovacuum decide to forgo vacuuming a table and the log with that information is at DEBUG2. So did this idea go anywhere? Assuming the thread stopped here, I'd like to rekindle the proposal. log_min_messages acts as a single gate for everything headed for the server logs; controls for per-background process logging do not exist. If one wants to see DEBUG/INFO messages for just the Autovacuum (or checkpointer, bgwriter, etc.), they have to set log_min_messages to that level, but the result would be a lot of clutter from other processes to grovel through, to see the messages of interest. I think that will be quite helpful. During the patch development of parallel sequential scan, it was quite helpful to see the LOG messages of bgworkers, however one of the recent commits (91118f1a) have changed those to DEBUG1, now if I have to enable all DEBUG1 messages, then what I need will be difficult to find in all the log messages. Having control of separate logging for background tasks will serve such a purpose. The facilities don't yet exist, but it'd be nice if such parameters when unset (ie NULL) pick up the value of log_min_messages. So by default, the users will get the same behaviour as today, but can choose to tweak per background-process logging when needed. Will this proposal allow user to see all the messages by all the background workers or will it be per background task. Example in some cases user might want to see the messages by all bgworkers and in some cases one might want to see just messages by AutoVacuum and it's workers. I think here designing User Interface is an important work if others also agree that such an option is useful, could you please elaborate your proposal? With Regards, Amit Kapila. EnterpriseDB: http://www.enterprisedb.com
Re: [HACKERS] More logging for autovacuum
On Fri, Aug 17, 2007 at 3:14 PM, Alvaro Herrera alvhe...@commandprompt.com wrote: Gregory Stark wrote: I'm having trouble following what's going on with autovacuum and I'm finding the existing logging insufficient. In particular that it's only logging vacuum runs *after* the vacuum finishes makes it hard to see what vacuums are running at any given time. Also, I want to see what is making autovacuum decide to forgo vacuuming a table and the log with that information is at DEBUG2. So did this idea go anywhere? Assuming the thread stopped here, I'd like to rekindle the proposal. log_min_messages acts as a single gate for everything headed for the server logs; controls for per-background process logging do not exist. If one wants to see DEBUG/INFO messages for just the Autovacuum (or checkpointer, bgwriter, etc.), they have to set log_min_messages to that level, but the result would be a lot of clutter from other processes to grovel through, to see the messages of interest. The facilities don't yet exist, but it'd be nice if such parameters when unset (ie NULL) pick up the value of log_min_messages. So by default, the users will get the same behaviour as today, but can choose to tweak per background-process logging when needed. Absent such a feature, one hack is to set the desired log_min_messages value in conf file and send SIGHUP to just the process of interest and revert the conf file back; but it's a hack. Best regards, -- Gurjeet Singh http://gurjeet.singh.im/
Re: [HACKERS] More logging for autovacuum
Gregory Stark wrote: I'm having trouble following what's going on with autovacuum and I'm finding the existing logging insufficient. In particular that it's only logging vacuum runs *after* the vacuum finishes makes it hard to see what vacuums are running at any given time. Also, I want to see what is making autovacuum decide to forgo vacuuming a table and the log with that information is at DEBUG2. So did this idea go anywhere? -- Alvaro Herrera Developer, http://www.PostgreSQL.org/ Officer Krupke, what are we to do? Gee, officer Krupke, Krup you! (West Side Story, Gee, Officer Krupke) ---(end of broadcast)--- TIP 5: don't forget to increase your free space map settings
[HACKERS] More logging for autovacuum
I'm having trouble following what's going on with autovacuum and I'm finding the existing logging insufficient. In particular that it's only logging vacuum runs *after* the vacuum finishes makes it hard to see what vacuums are running at any given time. Also, I want to see what is making autovacuum decide to forgo vacuuming a table and the log with that information is at DEBUG2. So I would like to suggest adding two options: log_autovacuum_jobs - output every time a vacuum or analyze *starts* log_autovacuum_level - set the log level for the autovacuum process I would also suggest raising the level of the DEBUG2 message indicating why tables were chosen or not. At least to DEBUG1 if not to INFO. Am I missing anything? Are there ways to get this info already that I'm missing? I imagine it would be pretty simple to add these and I'll be happy to do it and send the patch to -patches assuming others (Alvaro? :) agree. -- Gregory Stark EnterpriseDB http://www.enterprisedb.com ---(end of broadcast)--- TIP 1: if posting/reading through Usenet, please send an appropriate subscribe-nomail command to [EMAIL PROTECTED] so that your message can get through to the mailing list cleanly
Re: [HACKERS] More logging for autovacuum
Gregory Stark [EMAIL PROTECTED] writes: I would also suggest raising the level of the DEBUG2 message indicating why tables were chosen or not. At least to DEBUG1 if not to INFO. It's not acceptable for autovacuum to be cluttering the log by default. regards, tom lane ---(end of broadcast)--- TIP 1: if posting/reading through Usenet, please send an appropriate subscribe-nomail command to [EMAIL PROTECTED] so that your message can get through to the mailing list cleanly
Re: [HACKERS] More logging for autovacuum
Gregory Stark wrote: I'm having trouble following what's going on with autovacuum and I'm finding the existing logging insufficient. In particular that it's only logging vacuum runs *after* the vacuum finishes makes it hard to see what vacuums are running at any given time. Also, I want to see what is making autovacuum decide to forgo vacuuming a table and the log with that information is at DEBUG2. So I would like to suggest adding two options: log_autovacuum_jobs - output every time a vacuum or analyze *starts* log_autovacuum_level - set the log level for the autovacuum process I would also suggest raising the level of the DEBUG2 message indicating why tables were chosen or not. At least to DEBUG1 if not to INFO. Am I missing anything? Are there ways to get this info already that I'm missing? I imagine it would be pretty simple to add these and I'll be happy to do it and send the patch to -patches assuming others (Alvaro? :) agree. I think this sounds good. There was talk a while ago about need a special log level setting just for autovacuum, but nobody did the leg work. ---(end of broadcast)--- TIP 1: if posting/reading through Usenet, please send an appropriate subscribe-nomail command to [EMAIL PROTECTED] so that your message can get through to the mailing list cleanly
Re: [HACKERS] More logging for autovacuum
Le mardi 07 août 2007, Tom Lane a écrit : Gregory Stark [EMAIL PROTECTED] writes: log_autovacuum_jobs - output every time a vacuum or analyze *starts* [...] I would also suggest raising the level of the DEBUG2 message indicating why tables were chosen or not. At least to DEBUG1 if not to INFO. It's not acceptable for autovacuum to be cluttering the log by default. If I understand correctly what is proposed, the log_autovacuum_jobs option would allow the user to choose whether or not he wants its log cluttered by autovacuum. I know I'd choose to clutter them, and would prefer not having to choose a DEBUG loglevel to have autovacuum logs... Regards, -- dim signature.asc Description: This is a digitally signed message part.
Re: [HACKERS] More logging for autovacuum
Tom Lane [EMAIL PROTECTED] writes: Gregory Stark [EMAIL PROTECTED] writes: I would also suggest raising the level of the DEBUG2 message indicating why tables were chosen or not. At least to DEBUG1 if not to INFO. It's not acceptable for autovacuum to be cluttering the log by default. Well log_min_messages is NOTICE by default so neither INFO nor DEBUG1 would actually clutter the logs by default, but it sounds like you would prefer at most DEBUG1? -- Gregory Stark EnterpriseDB http://www.enterprisedb.com ---(end of broadcast)--- TIP 3: Have you checked our extensive FAQ? http://www.postgresql.org/docs/faq
Re: [HACKERS] More logging for autovacuum
-BEGIN PGP SIGNED MESSAGE- Hash: SHA1 Dimitri Fontaine wrote: Le mardi 07 août 2007, Tom Lane a écrit : Gregory Stark [EMAIL PROTECTED] writes: log_autovacuum_jobs - output every time a vacuum or analyze *starts* [...] I would also suggest raising the level of the DEBUG2 message indicating why tables were chosen or not. At least to DEBUG1 if not to INFO. It's not acceptable for autovacuum to be cluttering the log by default. If I understand correctly what is proposed, the log_autovacuum_jobs option would allow the user to choose whether or not he wants its log cluttered by autovacuum. I know I'd choose to clutter them, and would prefer not having to choose a DEBUG loglevel to have autovacuum logs... With 8.3 having autovacuum on by default, we really should be logging at a mininum: autovacuum start autovacuum working (what am I working on but not what I am doing, meaning we don't need tuple information etc..) autovacuum stop Yes, by default or at least at no level higher than INFO. Sincerely, Joshua D. Drake Regards, - -- === The PostgreSQL Company: Command Prompt, Inc. === Sales/Support: +1.503.667.4564 || 24x7/Emergency: +1.800.492.2240 Providing the most comprehensive PostgreSQL solutions since 1997 http://www.commandprompt.com/ Donate to the PostgreSQL Project: http://www.postgresql.org/about/donate PostgreSQL Replication: http://www.commandprompt.com/products/ -BEGIN PGP SIGNATURE- Version: GnuPG v1.4.6 (GNU/Linux) Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org iD8DBQFGuJJIATb/zqfZUUQRApl7AJoCq85I0drgIUg1BEn/2ngrSKCQTwCgoIik ZmLO2N/2nQLNdNJeKUwhQEo= =nLKN -END PGP SIGNATURE- ---(end of broadcast)--- TIP 5: don't forget to increase your free space map settings
Re: [HACKERS] More logging for autovacuum
Joshua D. Drake [EMAIL PROTECTED] writes: With 8.3 having autovacuum on by default, we really should be logging at a mininum: autovacuum start autovacuum working (what am I working on but not what I am doing, meaning we don't need tuple information etc..) autovacuum stop Yes, by default or at least at no level higher than INFO. No, NOT by default. Our users have made it perfectly clear that they don't want the logs cluttered with high-volume information about non-error normal workings of the system. Every time we have caused the system to emit such data by default, the log level of the messages in question has gotten dialed down in a later release. I don't object to what Greg suggests as an option. If we try to make it the default behavior, we will find ourselves changing that. As far as the debug/info/etc discussion goes: if there is a GUC variable controlling it, just make the elevel be LOG. regards, tom lane ---(end of broadcast)--- TIP 3: Have you checked our extensive FAQ? http://www.postgresql.org/docs/faq
Re: [HACKERS] More logging for autovacuum
Tom Lane wrote: Yes, by default or at least at no level higher than INFO. No, NOT by default. Our users have made it perfectly clear that they don't want the logs cluttered with high-volume information about non-error normal workings of the system. Every time we have caused the system to emit such data by default, the log level of the messages in question has gotten dialed down in a later release. But INFO is not shown by default. In fact, just about the only useful thing that emits INFO messages is VACUUM VERBOSE, so there is a fair precedent for equating the INFO level with lots of chatter about VACUUM. I like to set log_min_messages to INFO (and run vacuum verbosely) while a system is stabilizing, so adding autovacuum information there would come in handy. -- Peter Eisentraut http://developer.postgresql.org/~petere/ ---(end of broadcast)--- TIP 5: don't forget to increase your free space map settings
Re: [HACKERS] More logging for autovacuum
Peter Eisentraut [EMAIL PROTECTED] writes: But INFO is not shown by default. INFO is mostly a hack to try to emulate VACUUM VERBOSE's ancient behavior before we redesigned the elog levels. It's intended for controlling messages that should go to a client because the client asked for them, and usually should NOT go to the log. I think it's 100% inappropriate to use it for messages from a background process that has no client. regards, tom lane ---(end of broadcast)--- TIP 5: don't forget to increase your free space map settings
Re: [HACKERS] More logging for autovacuum
On 8/7/07, Tom Lane [EMAIL PROTECTED] wrote: Peter Eisentraut [EMAIL PROTECTED] writes: But INFO is not shown by default. INFO is mostly a hack to try to emulate VACUUM VERBOSE's ancient behavior before we redesigned the elog levels. It's intended for controlling messages that should go to a client because the client asked for them, and usually should NOT go to the log. I think it's 100% inappropriate to use it for messages from a background process that has no client. Traditional log-level semantics aren't very rich. I think that's the real source of this problem: How do I get the info I need to tune auto-vacuum without swamping my system with log IO. While the following isn't production ready, it seems to have some really good ideas. http://log4c.sourceforge.net/ log4c is inspired by log4j, which seems to have become the defacto standard tool for logging in the enterprise java world. Andrew
Re: [HACKERS] More logging for autovacuum
On Tue, Aug 07, 2007 at 11:59:03AM -0700, Andrew Hammond wrote: On 8/7/07, Tom Lane [EMAIL PROTECTED] wrote: Peter Eisentraut [EMAIL PROTECTED] writes: But INFO is not shown by default. INFO is mostly a hack to try to emulate VACUUM VERBOSE's ancient behavior before we redesigned the elog levels. It's intended for controlling messages that should go to a client because the client asked for them, and usually should NOT go to the log. I think it's 100% inappropriate to use it for messages from a background process that has no client. Traditional log-level semantics aren't very rich. I think that's the real source of this problem: How do I get the info I need to tune auto-vacuum without swamping my system with log IO. While the following isn't production ready, it seems to have some really good ideas. Is logging really the answer for that? ISTM it'd be better to provide statistics info so that you could monitor autovacuum activity with things like cricket, SNMP, etc. -- Decibel!, aka Jim Nasby[EMAIL PROTECTED] EnterpriseDB http://enterprisedb.com 512.569.9461 (cell) pgpQAGIJLuS1i.pgp Description: PGP signature
Re: [HACKERS] More logging for autovacuum
-BEGIN PGP SIGNED MESSAGE- Hash: SHA1 Decibel! wrote: On Tue, Aug 07, 2007 at 11:59:03AM -0700, Andrew Hammond wrote: On 8/7/07, Tom Lane [EMAIL PROTECTED] wrote: Peter Eisentraut [EMAIL PROTECTED] writes: But INFO is not shown by default. INFO is mostly a hack to try to emulate VACUUM VERBOSE's ancient behavior before we redesigned the elog levels. It's intended for controlling messages that should go to a client because the client asked for them, and usually should NOT go to the log. I think it's 100% inappropriate to use it for messages from a background process that has no client. Traditional log-level semantics aren't very rich. I think that's the real source of this problem: How do I get the info I need to tune auto-vacuum without swamping my system with log IO. While the following isn't production ready, it seems to have some really good ideas. Is logging really the answer for that? ISTM it'd be better to provide statistics info so that you could monitor autovacuum activity with things like cricket, SNMP, etc. Well that would certainly be useful too. Joshua D. Drake - -- === The PostgreSQL Company: Command Prompt, Inc. === Sales/Support: +1.503.667.4564 || 24x7/Emergency: +1.800.492.2240 Providing the most comprehensive PostgreSQL solutions since 1997 http://www.commandprompt.com/ Donate to the PostgreSQL Project: http://www.postgresql.org/about/donate PostgreSQL Replication: http://www.commandprompt.com/products/ -BEGIN PGP SIGNATURE- Version: GnuPG v1.4.6 (GNU/Linux) Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org iD8DBQFGuOZBATb/zqfZUUQRAmy6AKCohv/RtFmPCA+zmmpkwR1qCX3XugCgg/rE lq3wxodgiWNe0d1wmw1ragc= =X6W3 -END PGP SIGNATURE- ---(end of broadcast)--- TIP 4: Have you searched our list archives? http://archives.postgresql.org
Re: [HACKERS] More logging for autovacuum
On Tue, 7 Aug 2007, Decibel! wrote: Is logging really the answer for that? ISTM it'd be better to provide statistics info so that you could monitor autovacuum activity with things like cricket, SNMP, etc. There are two sides to this. One is that it's difficult to right now to tell when your performance is being whacked because autovacuum is doing something. The original version of the checkpoint + other slowdowns logging patch I submitted included a line of extra detail there so I could watch the entry/exit to every autovaccum section if the log level was cranked up to DEBUG2, motivated by the same reasons Greg Stark mentioned. When you get into a situation where things are inexplicably slow, it's nice to do a tail on the logs and be able to figure out oh, it's busy vacuuming X right now, no wonder. Just logging when you're going through that is good enough to let you line up the timestamps with other system activity measurements, and while difficult you can tune based just on that. And having that information easily available in the logs lets almost any level of user watch what's going on. Actually tuning that behavior out of the system altogether is easier done by collecting statistics, in a similar fashion to how pg_stat_bgwriter lets you track checkpoints now, but that being helpful presumes a level of monitoring sophistication that typical new installations (who need this kind of help the most) don't have. Also, given the way that the stats are often updated after the work was done, that implementation may not solve the why am I slow right now? side of the problem effectively. I think both types of instrumentation are ultimately needed, but if you were only picking one I think the log entries would be the better one to start with. -- * Greg Smith [EMAIL PROTECTED] http://www.gregsmith.com Baltimore, MD ---(end of broadcast)--- TIP 6: explain analyze is your friend
