Re: RowExclusiveLock timeout while autovacuum

On Mon, Aug 15, 2016 at 12:34 PM zh1029 <zh1029(at)sina(dot)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(at)postgresql(dot)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