Re: [PATCHES] [HACKERS] Deadlock with pg_dump?
I have applied a modified version of this patch, attached. I trimmed down the description of log_lock_waits to be more concise, and moved the idea of using this to tune deadlock_timeout to the deadlock_timeout section of the manual. --- Simon Riggs wrote: On Mon, 2007-02-19 at 19:38 +, Simon Riggs wrote: On Tue, 2007-02-13 at 22:19 -0500, Bruce Momjian wrote: Simon Riggs wrote: On Thu, 2006-10-26 at 18:45 -0400, Tom Lane wrote: Chris Campbell [EMAIL PROTECTED] writes: Is there additional logging information I can turn on to get more details? I guess I need to see exactly what locks both processes hold, and what queries they were running when the deadlock occurred? Is that easily done, without turning on logging for *all* statements? log_min_error_statement = error would at least get you the statements reporting the deadlocks, though not what they're conflicting against. Yeh, we need a much better locking logger for performance analysis. We really need to dump the whole wait-for graph for deadlocks, since this might be more complex than just two statements involved. Deadlocks ought to be so infrequent that we can afford the log space to do this - plus if we did this it would likely lead to fewer deadlocks. For 8.3 I'd like to have a log_min_duration_lockwait (secs) parameter that would allow you to dump the wait-for graph for any data-level locks that wait too long, rather than just those that deadlock. Many applications experience heavy locking because of lack of holistic design. That will also show up the need for other utilities to act CONCURRENTLY, if possible. Old email, but I don't see how our current output is not good enough? test= lock a; ERROR: deadlock detected DETAIL: Process 6855 waits for AccessExclusiveLock on relation 16394 of database 16384; blocked by process 6795. Process 6795 waits for AccessExclusiveLock on relation 16396 of database 16384; blocked by process 6855. This detects deadlocks, but it doesn't detect lock waits. When I wrote that it was previous experience driving me. Recent client experience has highlighted the clear need for this. We had a lock wait of 50 hours because of an RI check; thats the kind of thing I'd like to show up in the logs somewhere. Lock wait detection can be used to show up synchronisation points that have been inadvertently designed into an application, so its a useful tool in investigating performance issues. I have a patch implementing the logging as agreed with Tom, will post to patches later tonight. Patch for discussion, includes doc entries at top of patch, so its fairly clear how it works. Output is an INFO message, to allow this to trigger log_min_error_statement when it generates a message, to allow us to see the SQL statement that is waiting. This allows it to generate a message prior to the statement completing, which is important because it may not ever complete, in some cases, so simply logging a list of pids won't always tell you what the SQL was that was waiting. Other approaches are possible... Comments? -- Simon Riggs EnterpriseDB http://www.enterprisedb.com [ Attachment, skipping... ] -- Bruce Momjian [EMAIL PROTECTED] http://momjian.us EnterpriseDB http://www.enterprisedb.com + If your life is a hard drive, Christ can be your backup. + Index: doc/src/sgml/config.sgml === RCS file: /cvsroot/pgsql/doc/src/sgml/config.sgml,v retrieving revision 1.113 diff -c -c -r1.113 config.sgml *** doc/src/sgml/config.sgml 2 Mar 2007 23:37:22 - 1.113 --- doc/src/sgml/config.sgml 3 Mar 2007 18:41:13 - *** *** 2946,2951 --- 2946,2966 /listitem /varlistentry + varlistentry id=guc-log-lock-waits xreflabel=log_lock_waits + termvarnamelog_lock_waits/varname (typeboolean/type)/term + indexterm +primaryvarnamelog_lock_waits/ configuration parameter/primary + /indexterm + listitem +para + Controls whether a log message is produced when a statement waits + longer than xref linkend=guc-deadlock-timeout to acquire a + lock. This is useful in determining if lock waits are causing + poor performance. The default is literaloff/. +/para + /listitem + /varlistentry + varlistentry id=guc-log-temp-files xreflabel=log_temp_files termvarnamelog_temp_files/varname (typeinteger/type)/term indexterm *** *** 3980,3996 This is the amount of time, in milliseconds, to wait on a lock before checking to see if there is a deadlock
Re: [PATCHES] [HACKERS] Deadlock with pg_dump?
Tom Lane wrote: Bruce Momjian [EMAIL PROTECTED] writes: What are *you* thinking? Yes, that patch has that line, but log_statement and log_min_duration_statement is going to trigger log_min_error_statement so you are going to get the statement printed twice. What's wrong with that? If a statement triggers two different log entries, and both are subject to being annotated with the statement text according to log_min_error_statement, I would expect them both to be annotated. Doing otherwise will probably break automated log analysis tools. Are people going to be happy that log_statement and log_min_duration_statement output the statement twice? test= SHOW log_min_error_statement; log_min_error_statement - error (1 row) test= SET log_statement = 'all'; SET test= SELECT 1; ?column? -- 1 (1 row) Server log has: LOG: statement: SELECT 1; STATEMENT: SELECT 1; -- Bruce Momjian [EMAIL PROTECTED] http://momjian.us EnterpriseDB http://www.enterprisedb.com + If your life is a hard drive, Christ can be your backup. + ---(end of broadcast)--- TIP 9: In versions below 8.0, the planner will ignore your desire to choose an index scan if your joining column's datatypes do not match
Re: [PATCHES] [HACKERS] Deadlock with pg_dump?
Bruce Momjian [EMAIL PROTECTED] writes: Are people going to be happy that log_statement and log_min_duration_statement output the statement twice? If those are the only cases you're worried about, a far simpler solution is to clear debug_query_string before instead of after emitting those log messages. regards, tom lane ---(end of broadcast)--- TIP 3: Have you checked our extensive FAQ? http://www.postgresql.org/docs/faq
Re: [PATCHES] [HACKERS] Deadlock with pg_dump?
Tom Lane wrote: Bruce Momjian [EMAIL PROTECTED] writes: Are people going to be happy that log_statement and log_min_duration_statement output the statement twice? If those are the only cases you're worried about, a far simpler solution is to clear debug_query_string before instead of after emitting those log messages. I am concerned about setting debug_query_string to NULL, calling ereport(), and then resetting it might cause problems because of cases where ereport might want to access debug_query_string for other uses, for cases where ereport doesn't return to the reset code (but I assume that is handled), and for cases like pgmonitor that would stop a backend, read debug_query_string, and disconnect. I can create a global variable to control this, but the new elog level seemed cleaner. -- Bruce Momjian [EMAIL PROTECTED] http://momjian.us EnterpriseDB http://www.enterprisedb.com + If your life is a hard drive, Christ can be your backup. + ---(end of broadcast)--- TIP 5: don't forget to increase your free space map settings
Re: [PATCHES] [HACKERS] Deadlock with pg_dump?
Tom Lane wrote: Bruce Momjian [EMAIL PROTECTED] writes: I can create a global variable to control this, but the new elog level seemed cleaner. What I don't like about the proposed patch is that it's nonorthogonal. I see no reason to suppose that LOG is the only possible elevel for which it might be interesting to suppress the STATEMENT: field. True. Perhaps the best thing would be to define an additional ereport auxiliary function, say errprintstmt(bool), that could set a flag in the current elog stack entry to control suppression of STATEMENT. This would mean you couldn't determine the behavior when using elog(), but that's not supposed to be used for user-facing messages anyway. One idea I had was to set the high-bit of elevel to control whether we want to suppress statement logging, but I think errprintstmt() might be best. I don't understand the ereport stack well enough to add this functionality, though. What should I look for? -- Bruce Momjian [EMAIL PROTECTED] http://momjian.us EnterpriseDB http://www.enterprisedb.com + If your life is a hard drive, Christ can be your backup. + ---(end of broadcast)--- TIP 7: You can help support the PostgreSQL project by donating at http://www.postgresql.org/about/donate
Re: [PATCHES] [HACKERS] Deadlock with pg_dump?
Bruce Momjian [EMAIL PROTECTED] writes: Tom Lane wrote: Perhaps the best thing would be to define an additional ereport auxiliary function, say errprintstmt(bool), that could set a flag in the current elog stack entry to control suppression of STATEMENT. This would mean you couldn't determine the behavior when using elog(), but that's not supposed to be used for user-facing messages anyway. One idea I had was to set the high-bit of elevel to control whether we want to suppress statement logging, but I think errprintstmt() might be best. I don't understand the ereport stack well enough to add this functionality, though. What should I look for? It wouldn't really be any different from errcode(), but if you want I'll do it. regards, tom lane ---(end of broadcast)--- TIP 7: You can help support the PostgreSQL project by donating at http://www.postgresql.org/about/donate
Re: [PATCHES] [HACKERS] Deadlock with pg_dump?
Tom Lane wrote: Bruce Momjian [EMAIL PROTECTED] writes: Tom Lane wrote: Perhaps the best thing would be to define an additional ereport auxiliary function, say errprintstmt(bool), that could set a flag in the current elog stack entry to control suppression of STATEMENT. This would mean you couldn't determine the behavior when using elog(), but that's not supposed to be used for user-facing messages anyway. One idea I had was to set the high-bit of elevel to control whether we want to suppress statement logging, but I think errprintstmt() might be best. I don't understand the ereport stack well enough to add this functionality, though. What should I look for? It wouldn't really be any different from errcode(), but if you want I'll do it. If you would just add the infrastructure I can add the LOG part. -- Bruce Momjian [EMAIL PROTECTED] http://momjian.us EnterpriseDB http://www.enterprisedb.com + If your life is a hard drive, Christ can be your backup. + ---(end of broadcast)--- TIP 9: In versions below 8.0, the planner will ignore your desire to choose an index scan if your joining column's datatypes do not match
Re: [PATCHES] [HACKERS] Deadlock with pg_dump?
Bruce Momjian [EMAIL PROTECTED] writes: Tom Lane wrote: It wouldn't really be any different from errcode(), but if you want I'll do it. If you would just add the infrastructure I can add the LOG part. OK, I applied a patch that covers the same territory as your patch of Wednesday evening. I didn't do anything about Simon's original patch --- I assume that needs some rework now. regards, tom lane ---(end of broadcast)--- TIP 4: Have you searched our list archives? http://archives.postgresql.org
Re: [PATCHES] [HACKERS] Deadlock with pg_dump?
Tom Lane wrote: Bruce Momjian [EMAIL PROTECTED] writes: Tom Lane wrote: It wouldn't really be any different from errcode(), but if you want I'll do it. If you would just add the infrastructure I can add the LOG part. OK, I applied a patch that covers the same territory as your patch of Wednesday evening. I didn't do anything about Simon's original patch --- I assume that needs some rework now. Thanks. I will rework Simon's. -- Bruce Momjian [EMAIL PROTECTED] http://momjian.us EnterpriseDB http://www.enterprisedb.com + If your life is a hard drive, Christ can be your backup. + ---(end of broadcast)--- TIP 9: In versions below 8.0, the planner will ignore your desire to choose an index scan if your joining column's datatypes do not match
Re: [PATCHES] [HACKERS] Deadlock with pg_dump?
I will rework this before application to use LOG level. Your patch has been added to the PostgreSQL unapplied patches list at: http://momjian.postgresql.org/cgi-bin/pgpatches It will be applied as soon as one of the PostgreSQL committers reviews and approves it. --- Simon Riggs wrote: On Mon, 2007-02-19 at 19:38 +, Simon Riggs wrote: On Tue, 2007-02-13 at 22:19 -0500, Bruce Momjian wrote: Simon Riggs wrote: On Thu, 2006-10-26 at 18:45 -0400, Tom Lane wrote: Chris Campbell [EMAIL PROTECTED] writes: Is there additional logging information I can turn on to get more details? I guess I need to see exactly what locks both processes hold, and what queries they were running when the deadlock occurred? Is that easily done, without turning on logging for *all* statements? log_min_error_statement = error would at least get you the statements reporting the deadlocks, though not what they're conflicting against. Yeh, we need a much better locking logger for performance analysis. We really need to dump the whole wait-for graph for deadlocks, since this might be more complex than just two statements involved. Deadlocks ought to be so infrequent that we can afford the log space to do this - plus if we did this it would likely lead to fewer deadlocks. For 8.3 I'd like to have a log_min_duration_lockwait (secs) parameter that would allow you to dump the wait-for graph for any data-level locks that wait too long, rather than just those that deadlock. Many applications experience heavy locking because of lack of holistic design. That will also show up the need for other utilities to act CONCURRENTLY, if possible. Old email, but I don't see how our current output is not good enough? test= lock a; ERROR: deadlock detected DETAIL: Process 6855 waits for AccessExclusiveLock on relation 16394 of database 16384; blocked by process 6795. Process 6795 waits for AccessExclusiveLock on relation 16396 of database 16384; blocked by process 6855. This detects deadlocks, but it doesn't detect lock waits. When I wrote that it was previous experience driving me. Recent client experience has highlighted the clear need for this. We had a lock wait of 50 hours because of an RI check; thats the kind of thing I'd like to show up in the logs somewhere. Lock wait detection can be used to show up synchronisation points that have been inadvertently designed into an application, so its a useful tool in investigating performance issues. I have a patch implementing the logging as agreed with Tom, will post to patches later tonight. Patch for discussion, includes doc entries at top of patch, so its fairly clear how it works. Output is an INFO message, to allow this to trigger log_min_error_statement when it generates a message, to allow us to see the SQL statement that is waiting. This allows it to generate a message prior to the statement completing, which is important because it may not ever complete, in some cases, so simply logging a list of pids won't always tell you what the SQL was that was waiting. Other approaches are possible... Comments? -- Simon Riggs EnterpriseDB http://www.enterprisedb.com [ Attachment, skipping... ] -- Bruce Momjian [EMAIL PROTECTED] http://momjian.us EnterpriseDB http://www.enterprisedb.com + If your life is a hard drive, Christ can be your backup. + ---(end of broadcast)--- TIP 5: don't forget to increase your free space map settings
Re: [PATCHES] [HACKERS] Deadlock with pg_dump?
Tom Lane wrote: Bruce Momjian [EMAIL PROTECTED] writes: I have coded up the following patch which places LOG just above ERROR in log_min_error_statement. LOG_NO_STATEMENT? What *are* you thinking? The kindest word I can find for this is baroque. What I had in mind was a one-line patch: if (edata-elevel = log_min_error_statement debug_query_string != NULL) becomes if (is_log_level_output(edata-elevel, log_min_error_statement) debug_query_string != NULL) What are *you* thinking? Yes, that patch has that line, but log_statement and log_min_duration_statement is going to trigger log_min_error_statement so you are going to get the statement printed twice. LOG_NO_STATEMENT fixes that. -- Bruce Momjian [EMAIL PROTECTED] http://momjian.us EnterpriseDB http://www.enterprisedb.com + If your life is a hard drive, Christ can be your backup. + ---(end of broadcast)--- TIP 2: Don't 'kill -9' the postmaster
Re: [PATCHES] [HACKERS] Deadlock with pg_dump?
Bruce Momjian [EMAIL PROTECTED] writes: What are *you* thinking? Yes, that patch has that line, but log_statement and log_min_duration_statement is going to trigger log_min_error_statement so you are going to get the statement printed twice. What's wrong with that? If a statement triggers two different log entries, and both are subject to being annotated with the statement text according to log_min_error_statement, I would expect them both to be annotated. Doing otherwise will probably break automated log analysis tools. 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: [PATCHES] [HACKERS] Deadlock with pg_dump?
Bruce Momjian [EMAIL PROTECTED] writes: I have coded up the following patch which places LOG just above ERROR in log_min_error_statement. LOG_NO_STATEMENT? What *are* you thinking? The kindest word I can find for this is baroque. What I had in mind was a one-line patch: if (edata-elevel = log_min_error_statement debug_query_string != NULL) becomes if (is_log_level_output(edata-elevel, log_min_error_statement) debug_query_string != NULL) 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: [PATCHES] [HACKERS] Deadlock with pg_dump?
I am a little concerned about a log_* setting that is INFO. I understand why you used INFO (for log_min_error_messages), but INFO is inconsistent with the log* prefix, and by default INFO doesn't appear in the log file. So, by default, the INFO is going to go to the user terminal, and not to the logfile. Ideas? --- Simon Riggs wrote: On Mon, 2007-02-19 at 19:38 +, Simon Riggs wrote: On Tue, 2007-02-13 at 22:19 -0500, Bruce Momjian wrote: Simon Riggs wrote: On Thu, 2006-10-26 at 18:45 -0400, Tom Lane wrote: Chris Campbell [EMAIL PROTECTED] writes: Is there additional logging information I can turn on to get more details? I guess I need to see exactly what locks both processes hold, and what queries they were running when the deadlock occurred? Is that easily done, without turning on logging for *all* statements? log_min_error_statement = error would at least get you the statements reporting the deadlocks, though not what they're conflicting against. Yeh, we need a much better locking logger for performance analysis. We really need to dump the whole wait-for graph for deadlocks, since this might be more complex than just two statements involved. Deadlocks ought to be so infrequent that we can afford the log space to do this - plus if we did this it would likely lead to fewer deadlocks. For 8.3 I'd like to have a log_min_duration_lockwait (secs) parameter that would allow you to dump the wait-for graph for any data-level locks that wait too long, rather than just those that deadlock. Many applications experience heavy locking because of lack of holistic design. That will also show up the need for other utilities to act CONCURRENTLY, if possible. Old email, but I don't see how our current output is not good enough? test= lock a; ERROR: deadlock detected DETAIL: Process 6855 waits for AccessExclusiveLock on relation 16394 of database 16384; blocked by process 6795. Process 6795 waits for AccessExclusiveLock on relation 16396 of database 16384; blocked by process 6855. This detects deadlocks, but it doesn't detect lock waits. When I wrote that it was previous experience driving me. Recent client experience has highlighted the clear need for this. We had a lock wait of 50 hours because of an RI check; thats the kind of thing I'd like to show up in the logs somewhere. Lock wait detection can be used to show up synchronisation points that have been inadvertently designed into an application, so its a useful tool in investigating performance issues. I have a patch implementing the logging as agreed with Tom, will post to patches later tonight. Patch for discussion, includes doc entries at top of patch, so its fairly clear how it works. Output is an INFO message, to allow this to trigger log_min_error_statement when it generates a message, to allow us to see the SQL statement that is waiting. This allows it to generate a message prior to the statement completing, which is important because it may not ever complete, in some cases, so simply logging a list of pids won't always tell you what the SQL was that was waiting. Other approaches are possible... Comments? -- Simon Riggs EnterpriseDB http://www.enterprisedb.com [ Attachment, skipping... ] -- Bruce Momjian [EMAIL PROTECTED] http://momjian.us EnterpriseDB http://www.enterprisedb.com + If your life is a hard drive, Christ can be your backup. + ---(end of broadcast)--- TIP 7: You can help support the PostgreSQL project by donating at http://www.postgresql.org/about/donate
Re: [PATCHES] [HACKERS] Deadlock with pg_dump?
On Mon, 2007-02-26 at 13:34 -0500, Bruce Momjian wrote: I am a little concerned about a log_* setting that is INFO. I understand why you used INFO (for log_min_error_messages), but INFO is inconsistent with the log* prefix, and by default INFO doesn't appear in the log file. Yeh, LOG would be most appropriate, but thats not possible. log_min_messages allows only DEBUG5, DEBUG4, DEBUG3, DEBUG2, DEBUG1, INFO, NOTICE and WARNING for non-error states. Possibly DEBUG1? -- Simon Riggs EnterpriseDB http://www.enterprisedb.com ---(end of broadcast)--- TIP 3: Have you checked our extensive FAQ? http://www.postgresql.org/docs/faq
Re: [PATCHES] [HACKERS] Deadlock with pg_dump?
Simon Riggs [EMAIL PROTECTED] writes: Yeh, LOG would be most appropriate, but thats not possible. You have not given any good reason for that. log_min_messages allows only DEBUG5, DEBUG4, DEBUG3, DEBUG2, DEBUG1, INFO, NOTICE and WARNING for non-error states. I don't think you understand quite how the log message priority works... regards, tom lane ---(end of broadcast)--- TIP 3: Have you checked our extensive FAQ? http://www.postgresql.org/docs/faq
Re: [PATCHES] [HACKERS] Deadlock with pg_dump?
On Mon, 2007-02-26 at 14:11 -0500, Tom Lane wrote: Simon Riggs [EMAIL PROTECTED] writes: Yeh, LOG would be most appropriate, but thats not possible. You have not given any good reason for that. The idea of the patch is that it generates a log message which then invokes log_min_error_statement so that the SQL statement is displayed. LOG is not on the list of options there, otherwise I would use it. The reason for behaving like this is so that a message is generated while the statement is still waiting, rather than at the end. As I mentioned in the submission, you may not like that behaviour; I'm in two minds myself, but I'm trying to get to the stage of having useful information come out of the server when we have long lock waits. -- Simon Riggs EnterpriseDB http://www.enterprisedb.com ---(end of broadcast)--- TIP 4: Have you searched our list archives? http://archives.postgresql.org
Re: [PATCHES] [HACKERS] Deadlock with pg_dump?
Simon Riggs [EMAIL PROTECTED] writes: The idea of the patch is that it generates a log message which then invokes log_min_error_statement so that the SQL statement is displayed. LOG is not on the list of options there, otherwise I would use it. As I said, you don't understand how the logging priority control works. LOG *is* the appropriate level for stuff intended to go to the server log. regards, tom lane ---(end of broadcast)--- TIP 4: Have you searched our list archives? http://archives.postgresql.org
Re: [PATCHES] [HACKERS] Deadlock with pg_dump?
On Mon, 2007-02-26 at 14:28 -0500, Tom Lane wrote: Simon Riggs [EMAIL PROTECTED] writes: The idea of the patch is that it generates a log message which then invokes log_min_error_statement so that the SQL statement is displayed. LOG is not on the list of options there, otherwise I would use it. As I said, you don't understand how the logging priority control works. LOG *is* the appropriate level for stuff intended to go to the server log. Please look at the definition of log_min_error_statement, so you understand where I'm coming from. -- Simon Riggs EnterpriseDB http://www.enterprisedb.com ---(end of broadcast)--- TIP 5: don't forget to increase your free space map settings
Re: [PATCHES] [HACKERS] Deadlock with pg_dump?
Simon Riggs [EMAIL PROTECTED] writes: On Mon, 2007-02-26 at 14:28 -0500, Tom Lane wrote: Simon Riggs [EMAIL PROTECTED] writes: The idea of the patch is that it generates a log message which then invokes log_min_error_statement so that the SQL statement is displayed. LOG is not on the list of options there, otherwise I would use it. As I said, you don't understand how the logging priority control works. LOG *is* the appropriate level for stuff intended to go to the server log. Please look at the definition of log_min_error_statement, so you understand where I'm coming from. I *have* read the definition of log_min_error_statement. (The SGML docs are wrong btw, as a quick look at the code shows that LOG is an accepted value.) The real issue here is that send_message_to_server_log just does if (edata-elevel = log_min_error_statement debug_query_string != NULL) to determine whether to log the statement, whereas arguably it should be using a test like is_log_level_output --- that is, the priority ordering for log_min_error_statement should be like log_min_messages not like client_min_messages. We've discussed that before in another thread, but it looks like nothing's been done yet. In any case, if you're unhappy with the code's choice of whether to emit the STATEMENT part of a log message, some changes here are what's indicated, not bizarre choices of elevel for individual messages. 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: [PATCHES] [HACKERS] Deadlock with pg_dump?
On Mon, 2007-02-26 at 14:52 -0500, Tom Lane wrote: Simon Riggs [EMAIL PROTECTED] writes: On Mon, 2007-02-26 at 14:28 -0500, Tom Lane wrote: Simon Riggs [EMAIL PROTECTED] writes: The idea of the patch is that it generates a log message which then invokes log_min_error_statement so that the SQL statement is displayed. LOG is not on the list of options there, otherwise I would use it. As I said, you don't understand how the logging priority control works. LOG *is* the appropriate level for stuff intended to go to the server log. Please look at the definition of log_min_error_statement, so you understand where I'm coming from. I *have* read the definition of log_min_error_statement. (The SGML docs are wrong btw, as a quick look at the code shows that LOG is an accepted value.) OK, I should have looked passed the manual. The real issue here is that send_message_to_server_log just does if (edata-elevel = log_min_error_statement debug_query_string != NULL) to determine whether to log the statement, whereas arguably it should be using a test like is_log_level_output --- that is, the priority ordering for log_min_error_statement should be like log_min_messages not like client_min_messages. We've discussed that before in another thread, but it looks like nothing's been done yet. Hopefully not with me? Don't remember that. In any case, if you're unhappy with the code's choice of whether to emit the STATEMENT part of a log message, some changes here are what's indicated, not bizarre choices of elevel for individual messages. Well, I would have chosen LOG if I thought it was available. I'll do some more to the patch. -- Simon Riggs EnterpriseDB http://www.enterprisedb.com ---(end of broadcast)--- TIP 3: Have you checked our extensive FAQ? http://www.postgresql.org/docs/faq
Re: [PATCHES] [HACKERS] Deadlock with pg_dump?
Simon Riggs wrote: On Mon, 2007-02-26 at 13:34 -0500, Bruce Momjian wrote: I am a little concerned about a log_* setting that is INFO. I understand why you used INFO (for log_min_error_messages), but INFO is inconsistent with the log* prefix, and by default INFO doesn't appear in the log file. Yeh, LOG would be most appropriate, but thats not possible. log_min_messages allows only DEBUG5, DEBUG4, DEBUG3, DEBUG2, DEBUG1, INFO, NOTICE and WARNING for non-error states. Possibly DEBUG1? This highlights a problem we have often had with LOG output where we also want the query. I think there are two possible approaches. First, we could add a new bitmap value like LOG_STATEMENT to ereport when we want the statement with the log line: ereport (LOG | LOG_STATEMENT, ...) (or a new LOG_WITH_STATEMENT log level) and a new GUC like log_include_statement that would control the output of statements for certain GUC parameters, and we document with GUC values it controls. A simpler idea would be to unconditionally include the query in the errdetail() of the actual LOG ereport. This is not the first GUC that has needed this. We had this issue with log_temp_files, which we just added, and the only suggested solution was to use log_statement = 'all'. Either of these ideas above would be useful for this as well. -- Bruce Momjian [EMAIL PROTECTED] http://momjian.us EnterpriseDB http://www.enterprisedb.com + If your life is a hard drive, Christ can be your backup. + ---(end of broadcast)--- TIP 9: In versions below 8.0, the planner will ignore your desire to choose an index scan if your joining column's datatypes do not match
Re: [PATCHES] [HACKERS] Deadlock with pg_dump?
Bruce Momjian [EMAIL PROTECTED] writes: This is not the first GUC that has needed this. Exactly. I think that we simply made a mistake in the initial implementation of log_min_error_statement: we failed to think about whether it should use client or server priority ordering, and the easy-to-code behavior was the wrong one. regards, tom lane ---(end of broadcast)--- TIP 7: You can help support the PostgreSQL project by donating at http://www.postgresql.org/about/donate
Re: [PATCHES] [HACKERS] Deadlock with pg_dump?
On Mon, 2007-02-19 at 19:38 +, Simon Riggs wrote: On Tue, 2007-02-13 at 22:19 -0500, Bruce Momjian wrote: Simon Riggs wrote: On Thu, 2006-10-26 at 18:45 -0400, Tom Lane wrote: Chris Campbell [EMAIL PROTECTED] writes: Is there additional logging information I can turn on to get more details? I guess I need to see exactly what locks both processes hold, and what queries they were running when the deadlock occurred? Is that easily done, without turning on logging for *all* statements? log_min_error_statement = error would at least get you the statements reporting the deadlocks, though not what they're conflicting against. Yeh, we need a much better locking logger for performance analysis. We really need to dump the whole wait-for graph for deadlocks, since this might be more complex than just two statements involved. Deadlocks ought to be so infrequent that we can afford the log space to do this - plus if we did this it would likely lead to fewer deadlocks. For 8.3 I'd like to have a log_min_duration_lockwait (secs) parameter that would allow you to dump the wait-for graph for any data-level locks that wait too long, rather than just those that deadlock. Many applications experience heavy locking because of lack of holistic design. That will also show up the need for other utilities to act CONCURRENTLY, if possible. Old email, but I don't see how our current output is not good enough? test= lock a; ERROR: deadlock detected DETAIL: Process 6855 waits for AccessExclusiveLock on relation 16394 of database 16384; blocked by process 6795. Process 6795 waits for AccessExclusiveLock on relation 16396 of database 16384; blocked by process 6855. This detects deadlocks, but it doesn't detect lock waits. When I wrote that it was previous experience driving me. Recent client experience has highlighted the clear need for this. We had a lock wait of 50 hours because of an RI check; thats the kind of thing I'd like to show up in the logs somewhere. Lock wait detection can be used to show up synchronisation points that have been inadvertently designed into an application, so its a useful tool in investigating performance issues. I have a patch implementing the logging as agreed with Tom, will post to patches later tonight. Patch for discussion, includes doc entries at top of patch, so its fairly clear how it works. Output is an INFO message, to allow this to trigger log_min_error_statement when it generates a message, to allow us to see the SQL statement that is waiting. This allows it to generate a message prior to the statement completing, which is important because it may not ever complete, in some cases, so simply logging a list of pids won't always tell you what the SQL was that was waiting. Other approaches are possible... Comments? -- Simon Riggs EnterpriseDB http://www.enterprisedb.com Index: doc/src/sgml/config.sgml === RCS file: /projects/cvsroot/pgsql/doc/src/sgml/config.sgml,v retrieving revision 1.108 diff -c -r1.108 config.sgml *** doc/src/sgml/config.sgml 1 Feb 2007 00:28:16 - 1.108 --- doc/src/sgml/config.sgml 6 Feb 2007 12:31:49 - *** *** 2936,2941 --- 2936,2965 /listitem /varlistentry + varlistentry id=guc-log-lock-waits xreflabel=log_lock_waits + termvarnamelog_lock_waits/varname (typeboolean/type)/term + indexterm +primaryvarnamelog_lock_waits/ configuration parameter/primary + /indexterm + listitem +para + Controls whether log messages are produced when a statement is forced + to wait when trying to acquire locks on database objects. The threshold + time is the value of the xref linkend=guc-deadlock-timeout parameter. + The log messages generated are intended for use during specific + investigations into application performance issues and subsequent tuning. + It is designed for use in conjunction with varnamelog_min_error_statement/. + Log messages indicating long lock waits might indicate problems with + applications accessing the database or possibly disconnection issues. + If no such problem exist it might indicate that varnamedeadlock_timeout/ + could be set higher. Log messages might also indicate that certain + deadlocks have been avoided. In those cases, decreasing the value of + varnamedeadlock_timeout/ might resolve lock wait situations faster, + thereby reducing contention. By default, this form of logging is literaloff/. +/para + /listitem + /varlistentry + /variablelist /sect2 /sect1 Index: src/backend/storage/lmgr/deadlock.c === RCS file: /projects/cvsroot/pgsql/src/backend/storage/lmgr/deadlock.c,v retrieving revision
