Thread: Logging Lock Waits
Right now, I need a way to log the lock wait times for certain queries, to see if they are acceptable. DTrace is not available. I'm dealing with a problem that is either a standard lock wait involving RI trigger locking, or a weirder problem involving lock starvation as a result of soft deadlock queue re-arrangement. I doubt its the latter but neither situation can be straightforwardly enabled to diagnose the situation. Sometime earlier, I proposed log_min_lockwait. A frequent case is where the lockwait is so long that the statement effectively never completes, so the statement duration doesn't appear in the log. That can cause further diagnosis problems. Ideally, I'd like to know both 1. there is a lock wait and it is happening now 2. there was a lock wait and it was THIS bad For 1, I need to log something while the lock wait is happening, not just when it ends - it might not end successfully. For 2 we can log it during or afterwards, not a problem. I'm thinking to write an INFO message, so that people can choose to log this and/or the SQL statement if they choose. e.g. INFO: lock wait time of XXX secs has been exceeded Comments? -- Simon Riggs EnterpriseDB http://www.enterprisedb.com
"Simon Riggs" <simon@2ndquadrant.com> writes:
> I'm thinking to write an INFO message, so that people can choose to log
> this and/or the SQL statement if they choose.
> e.g. INFO: lock wait time of XXX secs has been exceeded
The available timer resources are already overloaded; adding an
independent timeout for this will complicate the code more than seems
justified. Perhaps you could add a LOG message whenever the
deadlock-check code runs (and doesn't detect an error, so is about to go
back to sleep). This would take almost no effort, and the granularity
could still be adjusted via the deadlock check timeout.
regards, tom lane
On Jan 30, 2007, at 6:32 PM, Tom Lane wrote: > "Simon Riggs" <simon@2ndquadrant.com> writes: >> I'm thinking to write an INFO message, so that people can choose >> to log >> this and/or the SQL statement if they choose. >> e.g. INFO: lock wait time of XXX secs has been exceeded > > The available timer resources are already overloaded; adding an > independent timeout for this will complicate the code more than seems > justified. Perhaps you could add a LOG message whenever the > deadlock-check code runs (and doesn't detect an error, so is about > to go > back to sleep). This would take almost no effort, and the granularity > could still be adjusted via the deadlock check timeout. Sybase collected performance information for a server by periodically checking the status of all backend processes (ie: waiting on a user lock, waiting on IO, internal lock, etc) and keeping counters. Having that information available was useful for debugging performance issues (unfortunately I can't provide any specific examples since it was years ago I played with it). I'm thinking backends could set flags in shared memory to indicate what they're doing and a process could poll that every X milliseconds and keep stats on what's going on. But maybe that's more along the lines of the rewrite of the stats system that's been talked about... -- Jim Nasby jim@nasby.net EnterpriseDB http://enterprisedb.com 512.569.9461 (cell)