unexpected lock waits (was Re: Do not understand why this happens)

I don't know the answer to your question. Please keep mailing list
conversations on the list, otherwise you won't get the benefit of
someone else who may know the answer.

I do wonder what else is happening in the transaction that you're
calling NOTIFY within; and that some other statement could be causing
the lock wait.

On Fri, 15 Mar 2013 10:53:56 +0400 Aln Kapa <alnkapa(at)gmail(dot)com> wrote:

> I realized that my explanation of the problem is not accurate. I do
> not understand what is happening and why process is waiting for
> AccessExclusiveLock.
> More logs:
> --
> 682058674-2013-03-14 16:41:48 MSK web(at)web 8025 LOG: process 8025
> still waiting for AccessExclusiveLock on object 0 of class 1262 of
> database 0 after 3000.114 ms
> 682058826:2013-03-14 16:41:48 MSK web(at)web 8025 STATEMENT: NOTIFY test71, ''
> 682058893-2013-03-14 16:41:48 MSK web(at)web 15984 LOG: duration:
> 4017.622 ms statement: COMMIT
> --
> 682059265-2013-03-14 16:41:48 MSK web(at)web 8025 LOG: process 8025
> acquired AccessExclusiveLock on object 0 of class 1262 of database 0
> after 3228.124 ms
> 682059408:2013-03-14 16:41:48 MSK web(at)web 8025 STATEMENT: NOTIFY test71, ''
> 682059475-2013-03-14 16:41:48 MSK web(at)web 8025 LOG: duration:
> 3228.257 ms statement: NOTIFY test71, ''
> --
> 816903276-2013-03-15 09:18:04 MSK web(at)web 11373 LOG: process 11373
> still waiting for AccessExclusiveLock on object 0 of class 1262 of
> database 0 after 3000.129 ms
> 816903430:2013-03-15 09:18:04 MSK web(at)web 11373 STATEMENT: NOTIFY test102, ''
> 816903499-2013-03-15 09:18:05 MSK web(at)web 15984 LOG: duration:
> 7075.972 ms statement: COMMIT
> --
> 816903867-2013-03-15 09:18:05 MSK web(at)web 11373 LOG: process 11373
> acquired AccessExclusiveLock on object 0 of class 1262 of database 0
> after 3747.147 ms
> 816904012:2013-03-15 09:18:05 MSK web(at)web 11373 STATEMENT: NOTIFY test102, ''
> 816904081-2013-03-15 09:18:05 MSK web(at)web 11373 LOG: duration:
> 3747.254 ms statement: NOTIFY test102, ''
> --
> 817081702-2013-03-15 09:19:25 MSK web(at)web 11491 LOG: process 11491
> still waiting for AccessExclusiveLock on object 0 of class 1262 of
> database 0 after 3000.117 ms
> 817081856:2013-03-15 09:19:25 MSK web(at)web 11491 STATEMENT: NOTIFY test87, ''
> 817081924-2013-03-15 09:19:25 MSK web(at)web 15984 LOG: duration:
> 4004.117 ms statement: COMMIT
> 817082009-2013-03-15 09:19:25 MSK web(at)web 11491 LOG: process 11491
> acquired AccessExclusiveLock on object 0 of class 1262 of database 0
> after 3141.744 ms
> 817082154:2013-03-15 09:19:25 MSK web(at)web 11491 STATEMENT: NOTIFY test87, ''
> 817082222-2013-03-15 09:19:25 MSK web(at)web 11491 LOG: duration:
> 3164.606 ms statement: NOTIFY test87, ''
> --
> 818804853-2013-03-15 09:38:02 MSK OhGha5ya(at)rzdvo 11759 LOG: process
> 11759 still waiting for AccessExclusiveLock on object 0 of class 1262
> of database 0 after 3000.111 ms
> 818805014:2013-03-15 09:38:02 MSK OhGha5ya(at)rzdvo 11759 STATEMENT:
> NOTIFY test, ''
> 818805087-2013-03-15 09:38:02 MSK web(at)web 15984 WARNING:
> key:union_transport_stat_web75
> --
> 818831490-2013-03-15 09:38:03 MSK OhGha5ya(at)rzdvo 11759 LOG: process
> 11759 acquired AccessExclusiveLock on object 0 of class 1262 of
> database 0 after 3960.587 ms
> 818831642:2013-03-15 09:38:03 MSK OhGha5ya(at)rzdvo 11759 STATEMENT:
> NOTIFY test, ''
> 818831715-2013-03-15 09:38:03 MSK OhGha5ya(at)rzdvo 11759 LOG: duration:
> 3990.403 ms statement: NOTIFY test, ''
> --
> 820776461-2013-03-15 09:50:59 MSK web(at)web 11630 LOG: process 11630
> still waiting for AccessExclusiveLock on object 0 of class 1262 of
> database 0 after 3000.120 ms
> 820776615:2013-03-15 09:50:59 MSK web(at)web 11630 STATEMENT: NOTIFY test71, ''
> 820776683-2013-03-15 09:50:59 MSK ukraine(at)ukraine 8168 LOG: process
> 8168 still waiting for AccessExclusiveLock on object 0 of class 1262
> of database 0 after 3000.118 ms
> --
> 820777290-2013-03-15 09:51:03 MSK web(at)web 11630 LOG: process 11630
> acquired AccessExclusiveLock on object 0 of class 1262 of database 0
> after 6374.424 ms
> 820777435:2013-03-15 09:51:03 MSK web(at)web 11630 STATEMENT: NOTIFY test71, ''
> 820777503-2013-03-15 09:51:03 MSK web(at)web 11630 LOG: duration:
> 6374.557 ms statement: NOTIFY test71, ''
> --
> 821538779-2013-03-15 09:57:00 MSK OhGha5ya(at)rzdvo 14501 LOG: process
> 14501 still waiting for AccessExclusiveLock on object 0 of class 1262
> of database 0 after 3000.096 ms
> 821538940:2013-03-15 09:57:00 MSK OhGha5ya(at)rzdvo 14501 STATEMENT:
> NOTIFY test, ''
> 821539013-2013-03-15 09:57:00 MSK web(at)web 7995 LOG: process 7995
> still waiting for AccessExclusiveLock on object 0 of class 1262 of
> database 0 after 3000.111 ms
> --
> 821539305-2013-03-15 09:57:01 MSK OhGha5ya(at)rzdvo 14501 LOG: process
> 14501 acquired AccessExclusiveLock on object 0 of class 1262 of
> database 0 after 4007.728 ms
> 821539457:2013-03-15 09:57:01 MSK OhGha5ya(at)rzdvo 14501 STATEMENT:
> NOTIFY test, ''
> 821539530-2013-03-15 09:57:01 MSK OhGha5ya(at)rzdvo 14501 LOG: duration:
> 4007.905 ms statement: NOTIFY test, ''
> --
> 822220899-2013-03-15 10:00:54 MSK OhGha5ya(at)rzdvo 10849 LOG: process
> 10849 still waiting for AccessExclusiveLock on object 0 of class 1262
> of database 0 after 3000.138 ms
> 822221060:2013-03-15 10:00:54 MSK OhGha5ya(at)rzdvo 10849 STATEMENT:
> NOTIFY test138, ''
> 822221136-2013-03-15 10:00:54 MSK web(at)web 7987 LOG: duration:
> 4011.984 ms statement: COMMIT
> 822221220-2013-03-15 10:00:54 MSK OhGha5ya(at)rzdvo 10849 LOG: process
> 10849 acquired AccessExclusiveLock on object 0 of class 1262 of
> database 0 after 3100.606 ms
> 822221372:2013-03-15 10:00:54 MSK OhGha5ya(at)rzdvo 10849 STATEMENT:
> NOTIFY test138, ''
> 822221448-2013-03-15 10:00:54 MSK OhGha5ya(at)rzdvo 10849 LOG: duration:
> 3100.799 ms statement: NOTIFY test138, ''
> --
> 825472959-2013-03-15 10:28:16 MSK OhGha5ya(at)rzdvo 5616 LOG: process
> 5616 still waiting for AccessExclusiveLock on object 0 of class 1262
> of database 0 after 3000.112 ms
> 825473118:2013-03-15 10:28:16 MSK OhGha5ya(at)rzdvo 5616 STATEMENT:
> NOTIFY test, ''
> 825473190-2013-03-15 10:28:17 MSK web(at)web 15984 LOG: duration:
> 4019.454 ms statement: COMMIT
> 825473275-2013-03-15 10:28:17 MSK OhGha5ya(at)rzdvo 5616 LOG: process
> 5616 acquired AccessExclusiveLock on object 0 of class 1262 of
> database 0 after 3909.825 ms
> 825473425:2013-03-15 10:28:17 MSK OhGha5ya(at)rzdvo 5616 STATEMENT:
> NOTIFY test, ''
> 825473497-2013-03-15 10:28:17 MSK OhGha5ya(at)rzdvo 5616 LOG: duration:
> 3909.937 ms statement: NOTIFY test, ''
>
>
> 2013/3/14 Bill Moran <wmoran(at)potentialtech(dot)com>:
> > On Thu, 14 Mar 2013 15:24:45 +0400 Aln Kapa <alnkapa(at)gmail(dot)com> wrote:
> >>
> >> I connect to the database using the PGDAC, and then send a NOTIFY to
> >> myself every minute. In this case, the logs get that.
> >>
> >> 2013-03-10 10:34:36 19797 LOG: process 19797 still waiting for
> >> AccessExclusiveLock on object 0 of class 1262 of database 0 after
> >> 3000.100 ms
> >> 2013-03-10 10:34:36 19797 STATEMENT: NOTIFY test105, ''
> >> 2013-03-10 10:34:37 19797 LOG: process 19797 acquired
> >> AccessExclusiveLock on object 0 of class 1262 of database 0 after
> >> 3315.206 ms
> >> 2013-03-10 10:34:37 19797 STATEMENT: NOTIFY test105, ''
> >> 2013-03-10 10:34:37 19797 LOG: duration: 3315.322 ms statement:
> >> NOTIFY test105, ''
> >> 2013-03-10 14:27:43 19797 LOG: could not receive data from client:
> >> Connection reset by peer
> >> 2013-03-10 14:27:43 19797 LOG: unexpected EOF on client connection
> >>
> >> Tell me what's the problem?
> >
> > Are the last two lines your perceived problem? Is the NOTIFY working?
> >
> > There's really not enough information here to actually understand
> > what you're asking. Based on the log information, it looks like
> > a client program issues a notify, then drops the connection. Could
> > be because in intervening network control device times out the TCP
> > state, or could be because the client drops the conneciton, or
> > because the client crashed, or is poorly implementd in that it looses
> > its TCP socket.
> >
> > In any event, the 4 hour lag between the NOTIFY and the conneciton drop
> > during which nothing happens seems to indicate that the two events
> > are probably not related.
> >
> > Is any of that helpful? I feel like I don't understand your question
> > and suspect that you didn't receive an answer to your first post
> > because most people didn't understand it. If my comments don't
> > address your question, perhaps try describing it differently.
> >
> > --
> > Bill Moran <wmoran(at)potentialtech(dot)com>

--
Bill Moran <wmoran(at)potentialtech(dot)com>