Hello!
From time to time when investigating different locking issues using
postgres log i have thought that "process x is still waiting for"
message could be more informative, for example at the moment it is quite
painful to find out which session was actually holding that particular lock.
I would like to add detail part for this message to show information
about the lock holder and also show what the lock holder is actually
doing (yes, i know that i could get the lock holder's statement from the
log, but this not the same, maybe lock holder was idle in transaction).
So, i wrote a small patch, but i am not sure that this is the
best/correct way to do it.
Maybe someone can take a look at my patch and give some feedback.
Even if this idea won't reach to upstream, i would still like to get
feedback.
About patch:
Patch is tested against 9.2.4.
I was not sure that i should check if the lock holder's proclock was
found (as lock holder's proclock should be always there), check is there
to be on the safe side, but maybe it's unnecessary.
If it's not needed then fallback to old behavior (logging without
detail) is not needed as well.
And yes, i know that the lock holding time is not actually correct and
it actually shows milliseconds since transaction start.
Regards,
Tarvi Pillessaar
diff --git a/src/backend/storage/lmgr/proc.c b/src/backend/storage/lmgr/proc.c
index 3bfdd23..4dc7b37 100644
--- a/src/backend/storage/lmgr/proc.c
+++ b/src/backend/storage/lmgr/proc.c
@@ -49,6 +49,7 @@
#include "storage/procsignal.h"
#include "storage/spin.h"
#include "utils/timestamp.h"
+#include "pgstat.h"
/* GUC variables */
@@ -1198,9 +1199,66 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable)
}
if (myWaitStatus == STATUS_WAITING)
- ereport(LOG,
- (errmsg("process %d still waiting for %s on %s after %ld.%03d ms",
- MyProcPid, modename, buf.data, msecs, usecs)));
+ {
+ PROCLOCK *proclock2;
+ PGPROC *proc2;
+ PgBackendStatus *be;
+ bool found = false;
+
+ /* find lock holder */
+ proclock2 = (PROCLOCK *) SHMQueueNext(&(lock->procLocks), &(lock->procLocks),
+ offsetof(PROCLOCK, lockLink));
+ while (proclock2)
+ {
+ if (lockMethodTable->conflictTab[lockmode] & proclock2->holdMask)
+ break;
+
+ proclock2 = (PROCLOCK *) SHMQueueNext(&(lock->procLocks), &proclock2->lockLink,
+ offsetof(PROCLOCK, lockLink));
+ }
+
+ if (proclock2)
+ {
+ proc2 = proclock2->tag.myProc;
+
+ /* get lock holder's beentry */
+ int numbackends = pgstat_fetch_stat_numbackends();
+ for (i = 1; i <= numbackends; i++)
+ {
+ be = pgstat_fetch_stat_beentry(i);
+ if (be)
+ {
+ if (be->st_procpid == proc2->pid)
+ {
+ found = true;
+ break;
+ }
+ }
+ }
+ }
+
+ if (found)
+ {
+ long secs2;
+ int usecs2;
+ long msecs2;
+
+ /* calculate lock holder's tx duration */
+ TimestampDifference(be->st_xact_start_timestamp, GetCurrentTimestamp(), &secs2, &usecs2);
+ msecs2 = secs2 * 1000 + usecs2 / 1000;
+ usecs2 = usecs2 % 1000;
+
+ ereport(LOG,
+ (errmsg("process %d still waiting for %s on %s after %ld.%03d ms",
+ MyProcPid, modename, buf.data, msecs, usecs),
+ errdetail_log("process %d is holding lock for %ld.%03d ms, activity: %s",
+ proc2->pid, msecs2, usecs2, be->st_activity)));
+ }
+ else
+ ereport(LOG,
+ (errmsg("process %d still waiting for %s on %s after %ld.%03d ms",
+ MyProcPid, modename, buf.data, msecs, usecs)));
+ }
else if (myWaitStatus == STATUS_OK)
ereport(LOG,
(errmsg("process %d acquired %s on %s after %ld.%03d ms",
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
