|
8 | 8 | * |
9 | 9 | * |
10 | 10 | * IDENTIFICATION |
11 | | - * $PostgreSQL: pgsql/src/backend/storage/lmgr/proc.c,v 1.191 2007/07/16 21:09:50 tgl Exp $ |
| 11 | + * $PostgreSQL: pgsql/src/backend/storage/lmgr/proc.c,v 1.192 2007/08/28 03:23:44 tgl Exp $ |
12 | 12 | * |
13 | 13 | *------------------------------------------------------------------------- |
14 | 14 | */ |
@@ -727,6 +727,7 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable) |
727 | 727 | PROC_QUEUE*waitQueue=&(lock->waitProcs); |
728 | 728 | LOCKMASKmyHeldLocks=MyProc->heldLocks; |
729 | 729 | boolearly_deadlock= false; |
| 730 | +intmyWaitStatus; |
730 | 731 | PGPROC*proc; |
731 | 732 | inti; |
732 | 733 |
|
@@ -878,61 +879,86 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable) |
878 | 879 | { |
879 | 880 | PGSemaphoreLock(&MyProc->sem, true); |
880 | 881 |
|
| 882 | +/* |
| 883 | + * waitStatus could change from STATUS_WAITING to something else |
| 884 | + * asynchronously. Read it just once per loop to prevent surprising |
| 885 | + * behavior (such as missing log messages). |
| 886 | + */ |
| 887 | +myWaitStatus=MyProc->waitStatus; |
| 888 | + |
881 | 889 | /* |
882 | 890 | * If awoken after the deadlock check interrupt has run, and |
883 | 891 | * log_lock_waits is on, then report about the wait. |
884 | 892 | */ |
885 | | -if (log_lock_waits) |
| 893 | +if (log_lock_waits&&deadlock_state!=DS_NOT_YET_CHECKED) |
886 | 894 | { |
887 | | -switch (deadlock_state) |
| 895 | +StringInfoDatabuf; |
| 896 | +constchar*modename; |
| 897 | +longsecs; |
| 898 | +intusecs; |
| 899 | +longmsecs; |
| 900 | + |
| 901 | +initStringInfo(&buf); |
| 902 | +DescribeLockTag(&buf,&locallock->tag.lock); |
| 903 | +modename=GetLockmodeName(locallock->tag.lock.locktag_lockmethodid, |
| 904 | +lockmode); |
| 905 | +TimestampDifference(timeout_start_time,GetCurrentTimestamp(), |
| 906 | +&secs,&usecs); |
| 907 | +msecs=secs*1000+usecs /1000; |
| 908 | +usecs=usecs %1000; |
| 909 | + |
| 910 | +if (deadlock_state==DS_SOFT_DEADLOCK) |
| 911 | +ereport(LOG, |
| 912 | +(errmsg("process %d avoided deadlock for %s on %s by rearranging queue order after %ld.%03d ms", |
| 913 | +MyProcPid,modename,buf.data,msecs,usecs))); |
| 914 | +elseif (deadlock_state==DS_HARD_DEADLOCK) |
888 | 915 | { |
889 | | -caseDS_NOT_YET_CHECKED: |
890 | | -/* Lock granted, or spurious wakeup as described above */ |
891 | | -break; |
892 | | -caseDS_NO_DEADLOCK: |
893 | | -caseDS_SOFT_DEADLOCK: |
894 | | -{ |
895 | | -StringInfoDatabuf; |
896 | | -constchar*modename; |
897 | | -longsecs; |
898 | | -intusecs; |
899 | | -longmsecs; |
900 | | - |
901 | | -initStringInfo(&buf); |
902 | | -DescribeLockTag(&buf,&locallock->tag.lock); |
903 | | -modename=GetLockmodeName(locallock->tag.lock.locktag_lockmethodid, |
904 | | -lockmode); |
905 | | -TimestampDifference(timeout_start_time, |
906 | | -GetCurrentTimestamp(), |
907 | | -&secs,&usecs); |
908 | | -msecs=secs*1000+usecs /1000; |
909 | | -usecs=usecs %1000; |
910 | | - |
911 | | -if (deadlock_state==DS_SOFT_DEADLOCK) |
912 | | -ereport(LOG, |
913 | | -(errmsg("deadlock for %s on %s avoided by rearranging queue order after %ld.%03d ms", |
914 | | -modename,buf.data, |
915 | | -msecs,usecs))); |
916 | | -elseif (MyProc->waitStatus==STATUS_WAITING) |
917 | | -ereport(LOG, |
918 | | -(errmsg("process %d still waiting for %s on %s after %ld.%03d ms", |
919 | | -MyProcPid,modename,buf.data, |
920 | | -msecs,usecs))); |
921 | | -elseif (MyProc->waitStatus==STATUS_OK) |
922 | | -ereport(LOG, |
923 | | -(errmsg("process %d acquired %s on %s after %ld.%03d ms", |
924 | | -MyProcPid,modename,buf.data, |
925 | | -msecs,usecs))); |
926 | | -/* ERROR will be reported later, so no message here */ |
927 | | -pfree(buf.data); |
928 | | -break; |
929 | | -} |
930 | | -caseDS_HARD_DEADLOCK: |
931 | | -/* ERROR will be reported later, so no message here */ |
932 | | -break; |
| 916 | +/* |
| 917 | + * This message is a bit redundant with the error that will |
| 918 | + * be reported subsequently, but in some cases the error |
| 919 | + * report might not make it to the log (eg, if it's caught by |
| 920 | + * an exception handler), and we want to ensure all long-wait |
| 921 | + * events get logged. |
| 922 | + */ |
| 923 | +ereport(LOG, |
| 924 | +(errmsg("process %d detected deadlock while waiting for %s on %s after %ld.%03d ms", |
| 925 | +MyProcPid,modename,buf.data,msecs,usecs))); |
933 | 926 | } |
| 927 | + |
| 928 | +if (myWaitStatus==STATUS_WAITING) |
| 929 | +ereport(LOG, |
| 930 | +(errmsg("process %d still waiting for %s on %s after %ld.%03d ms", |
| 931 | +MyProcPid,modename,buf.data,msecs,usecs))); |
| 932 | +elseif (myWaitStatus==STATUS_OK) |
| 933 | +ereport(LOG, |
| 934 | +(errmsg("process %d acquired %s on %s after %ld.%03d ms", |
| 935 | +MyProcPid,modename,buf.data,msecs,usecs))); |
| 936 | +else |
| 937 | +{ |
| 938 | +Assert(myWaitStatus==STATUS_ERROR); |
| 939 | +/* |
| 940 | + * Currently, the deadlock checker always kicks its own |
| 941 | + * process, which means that we'll only see STATUS_ERROR |
| 942 | + * when deadlock_state == DS_HARD_DEADLOCK, and there's no |
| 943 | + * need to print redundant messages. But for completeness |
| 944 | + * and future-proofing, print a message if it looks like |
| 945 | + * someone else kicked us off the lock. |
| 946 | + */ |
| 947 | +if (deadlock_state!=DS_HARD_DEADLOCK) |
| 948 | +ereport(LOG, |
| 949 | +(errmsg("process %d failed to acquire %s on %s after %ld.%03d ms", |
| 950 | +MyProcPid,modename,buf.data,msecs,usecs))); |
| 951 | +} |
| 952 | + |
| 953 | +/* |
| 954 | + * At this point we might still need to wait for the lock. |
| 955 | + * Reset state so we don't print the above messages again. |
| 956 | + */ |
| 957 | +deadlock_state=DS_NO_DEADLOCK; |
| 958 | + |
| 959 | +pfree(buf.data); |
934 | 960 | } |
935 | | -}while (MyProc->waitStatus==STATUS_WAITING); |
| 961 | +}while (myWaitStatus==STATUS_WAITING); |
936 | 962 |
|
937 | 963 | /* |
938 | 964 | * Disable the timer, if it's still running |
|