On Mon, Aug 15, 2016 at 12:34 PM zh1029 <zh1029@xxxxxxxx> 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@xxxxxxxxxxxxxx)
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
