Thread: RowExclusiveLock timeout while autovacuum

RowExclusiveLock timeout while autovacuum

From

zh1029

Date:

15 August 2016, 07:33:35

Hi,
  We are using PostgreSQL 9.3.11. We are observing DB update failed due to
lock timeout. failure because waiting for RowExclusiveLock.  Autovacuum uses
plain vacuum which uses ShareUpdateExclusiveLock. right?
But from Postgres Manual chapter 13.3. Explicit Locking. both Locks has no
conflict. So in which situation conflict lock happened. Does autovacuum use
other lock than ShareUpdateExclusiveLock in certain situation?

Aug 10 15:03:16 DB-1 postgres[3314]: [5-1] DEBUG:  sending cancel to
blocking autovacuum PID 25047
Aug 10 15:03:16 DB-1 postgres[3314]: [5-2] DETAIL:  Process 3314 waits for
RowExclusiveLock on relation 19386 of database 18363.
Aug 10 15:03:16 DB-1 postgres[3314]: [5-3] CONTEXT:  SQL statement "insert
into ActiveRadiusSessionTrafficVM7(AccountSessionId)
values(NEW.AccountSessionId)"
Aug 10 15:03:16 DB-1 postgres[3314]: [5-4]         PL/pgSQL function
activesessiontriggerfunction() line 22 at SQL statement
Aug 10 15:03:16 DB-1 postgres[3314]: [5-5] STATEMENT:  INSERT INTO

ActiveRadiussession(AccountSessionId,StationMAC,StationIP,StationIPV6,ApMAC,SSID,Username,WlanMAC,ChargeableUserIdentity,NASIPAddress,SessionStartTime,Port,
ZoneWlanInfo, AppVMInstanceIP)
values($1,$2,$3,$4,$5,$6,$7,$8,$9,$10,$11,$12,$13,$14)
Aug 10 15:03:16 DB-1 postgres[3314]: [6-1] LOG:  process 3314 still waiting
for RowExclusiveLock on relation 19386 of database 18363 after 1000.186 ms
Aug 10 15:03:16 DB-1 postgres[3314]: [6-2] CONTEXT:  SQL statement "insert
into ActiveRadiusSessionTrafficVM7(AccountSessionId)
values(NEW.AccountSessionId)"
Aug 10 15:03:16 DB-1 postgres[3314]: [6-3]         PL/pgSQL function
activesessiontriggerfunction() line 22 at SQL statement
Aug 10 15:03:16 DB-1 postgres[3314]: [6-4] STATEMENT:  INSERT INTO

ActiveRadiussession(AccountSessionId,StationMAC,StationIP,StationIPV6,ApMAC,SSID,Username,WlanMAC,ChargeableUserIdentity,NASIPAddress,SessionStartTime,Port,
ZoneWlanInfo, AppVMInstanceIP)
values($1,$2,$3,$4,$5,$6,$7,$8,$9,$10,$11,$12,$13,$14)
Aug 10 15:03:16 DB-1 postgres[3314]: [7-1] LOG:  process 3314 acquired
RowExclusiveLock on relation 19386 of database 18363 after 1686.768 ms
Aug 10 15:03:16 DB-1 postgres[3314]: [7-2] CONTEXT:  SQL statement "insert
into ActiveRadiusSessionTrafficVM7(AccountSessionId)
values(NEW.AccountSessionId)"
Aug 10 15:03:16 DB-1 postgres[3314]: [7-3]         PL/pgSQL function
activesessiontriggerfunction() line 22 at SQL statement
Aug 10 15:03:16 DB-1 postgres[3314]: [7-4] STATEMENT:  INSERT INTO

ActiveRadiussession(AccountSessionId,StationMAC,StationIP,StationIPV6,ApMAC,SSID,Username,WlanMAC,ChargeableUserIdentity,NASIPAddress,SessionStartTime,Port,
ZoneWlanInfo, AppVMInstanceIP)
values($1,$2,$3,$4,$5,$6,$7,$8,$9,$10,$11,$12,$13,$14)
Aug 10 15:14:52 DB-1 postgres[3314]: [8-1] LOG:  process 3314 still waiting
for ExclusiveLock on extension of relation 19308 of database 18363 after
1000.061 ms
Aug 10 15:14:52 DB-1 postgres[3314]: [8-2] STATEMENT:  INSERT INTO

ActiveRadiussession(AccountSessionId,StationMAC,StationIP,StationIPV6,ApMAC,SSID,Username,WlanMAC,ChargeableUserIdentity,NASIPAddress,SessionStartTime,Port,
ZoneWlanInfo, AppVMInstanceIP)
values($1,$2,$3,$4,$5,$6,$7,$8,$9,$10,$11,$12,$13,$14)
Aug 10 15:14:52 DB-1 postgres[3314]: [9-1] LOG:  process 3314 acquired
ExclusiveLock on extension of relation 19308 of database 18363 after
1550.529 ms
Aug 10 15:14:52 DB-1 postgres[3314]: [9-2] STATEMENT:  INSERT INTO

ActiveRadiussession(AccountSessionId,StationMAC,StationIP,StationIPV6,ApMAC,SSID,Username,WlanMAC,ChargeableUserIdentity,NASIPAddress,SessionStartTime,Port,
ZoneWlanInfo, AppVMInstanceIP)
values($1,$2,$3,$4,$5,$6,$7,$8,$9,$10,$11,$12,$13,$14)
Aug 10 15:26:16 DB-1 postgres[3314]: [10-1] DEBUG:  sending cancel to
blocking autovacuum PID 26527
Aug 10 15:26:16 DB-1 postgres[3314]: [10-2] DETAIL:  Process 3314 waits for
RowExclusiveLock on relation 19386 of database 18363.
Aug 10 15:26:16 DB-1 postgres[3314]: [10-3] CONTEXT:  SQL statement "insert
into ActiveRadiusSessionTrafficVM7(AccountSessionId)
values(NEW.AccountSessionId)"
Aug 10 15:26:16 DB-1 postgres[3314]: [10-4]         PL/pgSQL function
activesessiontriggerfunction() line 22 at SQL statement
Aug 10 15:26:16 DB-1 postgres[3314]: [10-5] STATEMENT:  INSERT INTO

ActiveRadiussession(AccountSessionId,StationMAC,StationIP,StationIPV6,ApMAC,SSID,Username,WlanMAC,ChargeableUserIdentity,NASIPAddress,SessionStartTime,Port,
ZoneWlanInfo, AppVMInstanceIP)
values($1,$2,$3,$4,$5,$6,$7,$8,$9,$10,$11,$12,$13,$14)
Aug 10 15:26:16 DB-1 postgres[3314]: [11-1] LOG:  process 3314 still waiting
for RowExclusiveLock on relation 19386 of database 18363 after 1000.115 ms
Aug 10 15:26:16 DB-1 postgres[3314]: [11-2] CONTEXT:  SQL statement "insert
into ActiveRadiusSessionTrafficVM7(AccountSessionId)
values(NEW.AccountSessionId)"
Aug 10 15:26:16 DB-1 postgres[3314]: [11-3]         PL/pgSQL function
activesessiontriggerfunction() line 22 at SQL statement
Aug 10 15:26:16 DB-1 postgres[3314]: [11-4] STATEMENT:  INSERT INTO

ActiveRadiussession(AccountSessionId,StationMAC,StationIP,StationIPV6,ApMAC,SSID,Username,WlanMAC,ChargeableUserIdentity,NASIPAddress,SessionStartTime,Port,
ZoneWlanInfo, AppVMInstanceIP)
values($1,$2,$3,$4,$5,$6,$7,$8,$9,$10,$11,$12,$13,$14)
Aug 10 15:26:25 DB-1 postgres[3314]: [12-1] err-1:  canceling statement due
to lock timeout
Aug 10 15:26:25 DB-1 postgres[3314]: [12-2] CONTEXT:  SQL statement "insert
into ActiveRadiusSessionTrafficVM7(AccountSessionId)
values(NEW.AccountSessionId)"
Aug 10 15:26:25 DB-1 postgres[3314]: [12-3]         PL/pgSQL function
activesessiontriggerfunction() line 22 at SQL statement
Aug 10 15:26:25 DB-1 postgres[3314]: [12-4] STATEMENT:  INSERT INTO

ActiveRadiussession(AccountSessionId,StationMAC,StationIP,StationIPV6,ApMAC,SSID,Username,WlanMAC,ChargeableUserIdentity,NASIPAddress,SessionStartTime,Port,
ZoneWlanInfo, AppVMInstanceIP)
values($1,$2,$3,$4,$5,$6,$7,$8,$9,$10,$11,$12,$13,$14)
Aug 10 15:26:26 DB-1 postgres[3314]: [13-1] DEBUG:  sending cancel to
blocking autovacuum PID 26527
Aug 10 15:26:26 DB-1 postgres[3314]: [13-2] DETAIL:  Process 3314 waits for
RowExclusiveLock on relation 19386 of database 18363.
Aug 10 15:26:26 DB-1 postgres[3314]: [13-3] CONTEXT:  SQL statement "insert
into ActiveRadiusSessionTrafficVM7(AccountSessionId)
values(NEW.AccountSessionId)"
Aug 10 15:26:26 DB-1 postgres[3314]: [13-4]         PL/pgSQL function
activesessiontriggerfunction() line 22 at SQL statement
Aug 10 15:26:26 DB-1 postgres[3314]: [13-5] STATEMENT:  INSERT INTO

ActiveRadiussession(AccountSessionId,StationMAC,StationIP,StationIPV6,ApMAC,SSID,Username,WlanMAC,ChargeableUserIdentity,NASIPAddress,SessionStartTime,Port,
ZoneWlanInfo, AppVMInstanceIP)
values($1,$2,$3,$4,$5,$6,$7,$8,$9,$10,$11,$12,$13,$14)
Aug 10 15:26:26 DB-1 postgres[3314]: [14-1] LOG:  process 3314 still waiting
for RowExclusiveLock on relation 19386 of database 18363 after 1000.218 ms
Aug 10 15:26:26 DB-1 postgres[3314]: [14-2] CONTEXT:  SQL statement "insert
into ActiveRadiusSessionTrafficVM7(AccountSessionId)
values(NEW.AccountSessionId)"
Aug 10 15:26:26 DB-1 postgres[3314]: [14-3]         PL/pgSQL function
activesessiontriggerfunction() line 22 at SQL statement
Aug 10 15:26:26 DB-1 postgres[3314]: [14-4] STATEMENT:  INSERT INTO

ActiveRadiussession(AccountSessionId,StationMAC,StationIP,StationIPV6,ApMAC,SSID,Username,WlanMAC,ChargeableUserIdentity,NASIPAddress,SessionStartTime,Port,
ZoneWlanInfo, AppVMInstanceIP)
values($1,$2,$3,$4,$5,$6,$7,$8,$9,$10,$11,$12,$13,$14)
Aug 10 15:26:28 DB-1 postgres[3314]: [15-1] LOG:  process 3314 acquired
RowExclusiveLock on relation 19386 of database 18363 after 3016.602 ms
Aug 10 15:26:28 DB-1 postgres[3314]: [15-2] CONTEXT:  SQL statement "insert
into ActiveRadiusSessionTrafficVM7(AccountSessionId)
values(NEW.AccountSessionId)"
Aug 10 15:26:28 DB-1 postgres[3314]: [15-3]         PL/pgSQL function
activesessiontriggerfunction() line 22 at SQL statement
Aug 10 15:26:28 DB-1 postgres[3314]: [15-4] STATEMENT:  INSERT INTO

ActiveRadiussession(AccountSessionId,StationMAC,StationIP,StationIPV6,ApMAC,SSID,Username,WlanMAC,ChargeableUserIdentity,NASIPAddress,SessionStartTime,Port,
ZoneWlanInfo, AppVMInstanceIP)
values($1,$2,$3,$4,$5,$6,$7,$8,$9,$10,$11,$12,$13,$14)
Aug 10 15:28:36 DB-1 postgres[3314]: [16-1] LOG:  process 3314 still waiting
for ExclusiveLock on extension of relation 19308 of database 18363 after
1000.065 ms
Aug 10 15:28:36 DB-1 postgres[3314]: [16-2] STATEMENT:  INSERT INTO

ActiveRadiussession(AccountSessionId,StationMAC,StationIP,StationIPV6,ApMAC,SSID,Username,WlanMAC,ChargeableUserIdentity,NASIPAddress,SessionStartTime,Port,
ZoneWlanInfo, AppVMInstanceIP)
values($1,$2,$3,$4,$5,$6,$7,$8,$9,$10,$11,$12,$13,$14)
Aug 10 15:28:39 DB-1 postgres[3314]: [17-1] LOG:  process 3314 acquired
ExclusiveLock on extension of relation 19308 of database 18363 after
3212.061 ms
Aug 10 15:28:39 DB-1 postgres[3314]: [17-2] STATEMENT:  INSERT INTO

ActiveRadiussession(AccountSessionId,StationMAC,StationIP,StationIPV6,ApMAC,SSID,Username,WlanMAC,ChargeableUserIdentity,NASIPAddress,SessionStartTime,Port,
ZoneWlanInfo, AppVMInstanceIP)
values($1,$2,$3,$4,$5,$6,$7,$8,$9,$10,$11,$12,$13,$14)




--
View this message in context: http://postgresql.nabble.com/RowExclusiveLock-timeout-while-autovacuum-tp5916437.html
Sent from the PostgreSQL - general mailing list archive at Nabble.com.

Re: RowExclusiveLock timeout while autovacuum

From

Sameer Kumar

Date:

15 August 2016, 07:51:50

On Mon, Aug 15, 2016 at 12:34 PM zh1029 <zh1029@sina.com> wrote:

Hi,
We are using PostgreSQL 9.3.11. We are observing DB update failed due to
lock timeout. failure because waiting for RowExclusiveLock. Autovacuum uses
plain vacuum which uses ShareUpdateExclusiveLock. right?

This I learnt recently, if autovacuum (or for that matter a normal vacuum) identifies that it needs to perform page truncation (release the empty space or relinquish a complete page back to OS), it would acquire an Exclusive Lock. I am not very sure if that is a page level lock or a row level lock (my guess is page level), but it would cause conflict with read/write queries on the master and would wait for the lock. On standby this might cause cancellation of queries.

You can simulate this easily with pgbench-

1. Setup a database with scale 1000

2. Create your custom script for pgbench to perform inserts

3. Fire pgbench

4. While pgbench is running the inserts script with multiple clients, you delete rows from the table where insert is happening. Make sure that deletes are with range filter large enough to release a few pages (e.g. where id between 1 and 5000)

Perhaps you might need to -

1. Look into why autovacuum is trying to perform page truncation to often. In my case I discovered it was a batch-job which would delete almost all rows and reinsert them, hence creating a huge chunk of free space for vacuum to relinquish

2. Make sure that the other operations on the database should perform faster. You may have some scope to tune the PL/pgSQL code or create some indexes or tune the insert itself

But from Postgres Manual chapter 13.3. Explicit Locking. both Locks has no
conflict. So in which situation conflict lock happened. Does autovacuum use
other lock than ShareUpdateExclusiveLock in certain situation?

Aug 10 15:03:16 DB-1 postgres[3314]: [5-1] DEBUG: sending cancel to
blocking autovacuum PID 25047
Aug 10 15:03:16 DB-1 postgres[3314]: [5-2] DETAIL: Process 3314 waits for
RowExclusiveLock on relation 19386 of database 18363.
Aug 10 15:03:16 DB-1 postgres[3314]: [5-3] CONTEXT: SQL statement "insert
into ActiveRadiusSessionTrafficVM7(AccountSessionId)
values(NEW.AccountSessionId)"
Aug 10 15:03:16 DB-1 postgres[3314]: [5-4] PL/pgSQL function
activesessiontriggerfunction() line 22 at SQL statement
Aug 10 15:03:16 DB-1 postgres[3314]: [5-5] STATEMENT: INSERT INTO
ActiveRadiussession(AccountSessionId,StationMAC,StationIP,StationIPV6,ApMAC,SSID,Username,WlanMAC,ChargeableUserIdentity,NASIPAddress,SessionStartTime,Port,
ZoneWlanInfo, AppVMInstanceIP)
values($1,$2,$3,$4,$5,$6,$7,$8,$9,$10,$11,$12,$13,$14)
Aug 10 15:03:16 DB-1 postgres[3314]: [6-1] LOG: process 3314 still waiting
for RowExclusiveLock on relation 19386 of database 18363 after 1000.186 ms
Aug 10 15:03:16 DB-1 postgres[3314]: [6-2] CONTEXT: SQL statement "insert
into ActiveRadiusSessionTrafficVM7(AccountSessionId)
values(NEW.AccountSessionId)"
Aug 10 15:03:16 DB-1 postgres[3314]: [6-3] PL/pgSQL function
activesessiontriggerfunction() line 22 at SQL statement
Aug 10 15:03:16 DB-1 postgres[3314]: [6-4] STATEMENT: INSERT INTO
ActiveRadiussession(AccountSessionId,StationMAC,StationIP,StationIPV6,ApMAC,SSID,Username,WlanMAC,ChargeableUserIdentity,NASIPAddress,SessionStartTime,Port,
ZoneWlanInfo, AppVMInstanceIP)
values($1,$2,$3,$4,$5,$6,$7,$8,$9,$10,$11,$12,$13,$14)
Aug 10 15:03:16 DB-1 postgres[3314]: [7-1] LOG: process 3314 acquired
RowExclusiveLock on relation 19386 of database 18363 after 1686.768 ms
Aug 10 15:03:16 DB-1 postgres[3314]: [7-2] CONTEXT: SQL statement "insert
into ActiveRadiusSessionTrafficVM7(AccountSessionId)
values(NEW.AccountSessionId)"
Aug 10 15:03:16 DB-1 postgres[3314]: [7-3] PL/pgSQL function
activesessiontriggerfunction() line 22 at SQL statement
Aug 10 15:03:16 DB-1 postgres[3314]: [7-4] STATEMENT: INSERT INTO
ActiveRadiussession(AccountSessionId,StationMAC,StationIP,StationIPV6,ApMAC,SSID,Username,WlanMAC,ChargeableUserIdentity,NASIPAddress,SessionStartTime,Port,
ZoneWlanInfo, AppVMInstanceIP)
values($1,$2,$3,$4,$5,$6,$7,$8,$9,$10,$11,$12,$13,$14)
Aug 10 15:14:52 DB-1 postgres[3314]: [8-1] LOG: process 3314 still waiting
for ExclusiveLock on extension of relation 19308 of database 18363 after
1000.061 ms
Aug 10 15:14:52 DB-1 postgres[3314]: [8-2] STATEMENT: INSERT INTO
ActiveRadiussession(AccountSessionId,StationMAC,StationIP,StationIPV6,ApMAC,SSID,Username,WlanMAC,ChargeableUserIdentity,NASIPAddress,SessionStartTime,Port,
ZoneWlanInfo, AppVMInstanceIP)
values($1,$2,$3,$4,$5,$6,$7,$8,$9,$10,$11,$12,$13,$14)
Aug 10 15:14:52 DB-1 postgres[3314]: [9-1] LOG: process 3314 acquired
ExclusiveLock on extension of relation 19308 of database 18363 after
1550.529 ms
Aug 10 15:14:52 DB-1 postgres[3314]: [9-2] STATEMENT: INSERT INTO
ActiveRadiussession(AccountSessionId,StationMAC,StationIP,StationIPV6,ApMAC,SSID,Username,WlanMAC,ChargeableUserIdentity,NASIPAddress,SessionStartTime,Port,
ZoneWlanInfo, AppVMInstanceIP)
values($1,$2,$3,$4,$5,$6,$7,$8,$9,$10,$11,$12,$13,$14)
Aug 10 15:26:16 DB-1 postgres[3314]: [10-1] DEBUG: sending cancel to
blocking autovacuum PID 26527
Aug 10 15:26:16 DB-1 postgres[3314]: [10-2] DETAIL: Process 3314 waits for
RowExclusiveLock on relation 19386 of database 18363.
Aug 10 15:26:16 DB-1 postgres[3314]: [10-3] CONTEXT: SQL statement "insert
into ActiveRadiusSessionTrafficVM7(AccountSessionId)
values(NEW.AccountSessionId)"
Aug 10 15:26:16 DB-1 postgres[3314]: [10-4] PL/pgSQL function
activesessiontriggerfunction() line 22 at SQL statement
Aug 10 15:26:16 DB-1 postgres[3314]: [10-5] STATEMENT: INSERT INTO
ActiveRadiussession(AccountSessionId,StationMAC,StationIP,StationIPV6,ApMAC,SSID,Username,WlanMAC,ChargeableUserIdentity,NASIPAddress,SessionStartTime,Port,
ZoneWlanInfo, AppVMInstanceIP)
values($1,$2,$3,$4,$5,$6,$7,$8,$9,$10,$11,$12,$13,$14)
Aug 10 15:26:16 DB-1 postgres[3314]: [11-1] LOG: process 3314 still waiting
for RowExclusiveLock on relation 19386 of database 18363 after 1000.115 ms
Aug 10 15:26:16 DB-1 postgres[3314]: [11-2] CONTEXT: SQL statement "insert
into ActiveRadiusSessionTrafficVM7(AccountSessionId)
values(NEW.AccountSessionId)"
Aug 10 15:26:16 DB-1 postgres[3314]: [11-3] PL/pgSQL function
activesessiontriggerfunction() line 22 at SQL statement
Aug 10 15:26:16 DB-1 postgres[3314]: [11-4] STATEMENT: INSERT INTO
ActiveRadiussession(AccountSessionId,StationMAC,StationIP,StationIPV6,ApMAC,SSID,Username,WlanMAC,ChargeableUserIdentity,NASIPAddress,SessionStartTime,Port,
ZoneWlanInfo, AppVMInstanceIP)
values($1,$2,$3,$4,$5,$6,$7,$8,$9,$10,$11,$12,$13,$14)
Aug 10 15:26:25 DB-1 postgres[3314]: [12-1] err-1: canceling statement due
to lock timeout
Aug 10 15:26:25 DB-1 postgres[3314]: [12-2] CONTEXT: SQL statement "insert
into ActiveRadiusSessionTrafficVM7(AccountSessionId)
values(NEW.AccountSessionId)"
Aug 10 15:26:25 DB-1 postgres[3314]: [12-3] PL/pgSQL function
activesessiontriggerfunction() line 22 at SQL statement
Aug 10 15:26:25 DB-1 postgres[3314]: [12-4] STATEMENT: INSERT INTO
ActiveRadiussession(AccountSessionId,StationMAC,StationIP,StationIPV6,ApMAC,SSID,Username,WlanMAC,ChargeableUserIdentity,NASIPAddress,SessionStartTime,Port,
ZoneWlanInfo, AppVMInstanceIP)
values($1,$2,$3,$4,$5,$6,$7,$8,$9,$10,$11,$12,$13,$14)
Aug 10 15:26:26 DB-1 postgres[3314]: [13-1] DEBUG: sending cancel to
blocking autovacuum PID 26527
Aug 10 15:26:26 DB-1 postgres[3314]: [13-2] DETAIL: Process 3314 waits for
RowExclusiveLock on relation 19386 of database 18363.
Aug 10 15:26:26 DB-1 postgres[3314]: [13-3] CONTEXT: SQL statement "insert
into ActiveRadiusSessionTrafficVM7(AccountSessionId)
values(NEW.AccountSessionId)"
Aug 10 15:26:26 DB-1 postgres[3314]: [13-4] PL/pgSQL function
activesessiontriggerfunction() line 22 at SQL statement
Aug 10 15:26:26 DB-1 postgres[3314]: [13-5] STATEMENT: INSERT INTO
ActiveRadiussession(AccountSessionId,StationMAC,StationIP,StationIPV6,ApMAC,SSID,Username,WlanMAC,ChargeableUserIdentity,NASIPAddress,SessionStartTime,Port,
ZoneWlanInfo, AppVMInstanceIP)
values($1,$2,$3,$4,$5,$6,$7,$8,$9,$10,$11,$12,$13,$14)
Aug 10 15:26:26 DB-1 postgres[3314]: [14-1] LOG: process 3314 still waiting
for RowExclusiveLock on relation 19386 of database 18363 after 1000.218 ms
Aug 10 15:26:26 DB-1 postgres[3314]: [14-2] CONTEXT: SQL statement "insert
into ActiveRadiusSessionTrafficVM7(AccountSessionId)
values(NEW.AccountSessionId)"
Aug 10 15:26:26 DB-1 postgres[3314]: [14-3] PL/pgSQL function
activesessiontriggerfunction() line 22 at SQL statement
Aug 10 15:26:26 DB-1 postgres[3314]: [14-4] STATEMENT: INSERT INTO
ActiveRadiussession(AccountSessionId,StationMAC,StationIP,StationIPV6,ApMAC,SSID,Username,WlanMAC,ChargeableUserIdentity,NASIPAddress,SessionStartTime,Port,
ZoneWlanInfo, AppVMInstanceIP)
values($1,$2,$3,$4,$5,$6,$7,$8,$9,$10,$11,$12,$13,$14)
Aug 10 15:26:28 DB-1 postgres[3314]: [15-1] LOG: process 3314 acquired
RowExclusiveLock on relation 19386 of database 18363 after 3016.602 ms
Aug 10 15:26:28 DB-1 postgres[3314]: [15-2] CONTEXT: SQL statement "insert
into ActiveRadiusSessionTrafficVM7(AccountSessionId)
values(NEW.AccountSessionId)"
Aug 10 15:26:28 DB-1 postgres[3314]: [15-3] PL/pgSQL function
activesessiontriggerfunction() line 22 at SQL statement
Aug 10 15:26:28 DB-1 postgres[3314]: [15-4] STATEMENT: INSERT INTO
ActiveRadiussession(AccountSessionId,StationMAC,StationIP,StationIPV6,ApMAC,SSID,Username,WlanMAC,ChargeableUserIdentity,NASIPAddress,SessionStartTime,Port,
ZoneWlanInfo, AppVMInstanceIP)
values($1,$2,$3,$4,$5,$6,$7,$8,$9,$10,$11,$12,$13,$14)
Aug 10 15:28:36 DB-1 postgres[3314]: [16-1] LOG: process 3314 still waiting
for ExclusiveLock on extension of relation 19308 of database 18363 after
1000.065 ms
Aug 10 15:28:36 DB-1 postgres[3314]: [16-2] STATEMENT: INSERT INTO
ActiveRadiussession(AccountSessionId,StationMAC,StationIP,StationIPV6,ApMAC,SSID,Username,WlanMAC,ChargeableUserIdentity,NASIPAddress,SessionStartTime,Port,
ZoneWlanInfo, AppVMInstanceIP)
values($1,$2,$3,$4,$5,$6,$7,$8,$9,$10,$11,$12,$13,$14)
Aug 10 15:28:39 DB-1 postgres[3314]: [17-1] LOG: process 3314 acquired
ExclusiveLock on extension of relation 19308 of database 18363 after
3212.061 ms
Aug 10 15:28:39 DB-1 postgres[3314]: [17-2] STATEMENT: INSERT INTO
ActiveRadiussession(AccountSessionId,StationMAC,StationIP,StationIPV6,ApMAC,SSID,Username,WlanMAC,ChargeableUserIdentity,NASIPAddress,SessionStartTime,Port,
ZoneWlanInfo, AppVMInstanceIP)
values($1,$2,$3,$4,$5,$6,$7,$8,$9,$10,$11,$12,$13,$14)

--
View this message in context: http://postgresql.nabble.com/RowExclusiveLock-timeout-while-autovacuum-tp5916437.html
Sent from the PostgreSQL - general mailing list archive at Nabble.com.

--
Sent via pgsql-general mailing list (pgsql-general@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general

Best Regards

Sameer Kumar | DB Solution Architect

ASHNIK PTE. LTD.

101 Cecil Street, #11-11 Tong Eng Building, Singapore 069 533

T: +65 6438 3504 | M: +65 8110 0350 | www.ashnik.com

Re: RowExclusiveLock timeout while autovacuum

From

Jeff Janes

Date:

15 August 2016, 20:21:02

On Sun, Aug 14, 2016 at 9:33 PM, zh1029 <zh1029@sina.com> wrote:
> Hi,
>   We are using PostgreSQL 9.3.11. We are observing DB update failed due to
> lock timeout. failure because waiting for RowExclusiveLock.  Autovacuum uses
> plain vacuum which uses ShareUpdateExclusiveLock. right?
> But from Postgres Manual chapter 13.3. Explicit Locking. both Locks has no
> conflict. So in which situation conflict lock happened. Does autovacuum use
> other lock than ShareUpdateExclusiveLock in certain situation?
>
> Aug 10 15:03:16 DB-1 postgres[3314]: [5-1] DEBUG:  sending cancel to
> blocking autovacuum PID 25047

What is your log_line_prefix?  I am not familiar with the '[5-1]'
thing.  I assume %l is the final part, but what is the first first
part?  Also, including the milliseconds in the timestamps can help a
lot (%m rather than %t), because a 200ms gap between log messages can
lead to much different interpretation than a 2ms gap.  And is 3314 the
port you are running on, or is it the pid of the process?  Is DEBUG
set globally or locally?

Why don't we ever see 25047 responding to the cancellation?

Anyway, ShareUpdateExclusiveLock and RowExclusiveLock do not directly
interfere with each other.  If you have a chain of processes blocking
each other, it is possible that one blocks the other indirectly.  Your
log file seems incomplete, so it is hard to say what is going on.
Does your app use any explicit table locks?

Cheers,

Jeff