Very expensive update to update a single row - Mailing list pgsql-performance

Postgres RDS running in AWS.  PostgreSQL 16.8 on aarch64-unknown-linux-gnu, compiled by gcc (GCC) 7.3.1 20180712 (Red Hat 7.3.1-17), 64-bit

Table definition

Table: request

      Column      |            Type             | Collation | Nullable |    Default

------------------+-----------------------------+-----------+----------+----------------

objectid         | character(36)               |           | not null |

data             | jsonb                       |           | not null | '{}'::jsonb

clientid         | character(3)                |           | not null |

active           | integer                     |           | not null |

productid        | integer                     |           | not null |

checkoutbyuid    | character(100)              |           |          |

checkoutdatetime | timestamp without time zone |           |          |

metadata         | jsonb                       |           | not null | '{}'::jsonb

search_vector    | tsvector                    |           |          |

requeststate     | text                        |           | not null | 'Active'::text

Indexes:

    "requestkey" PRIMARY KEY, btree (objectid, productid)

    "idx_request_gin_data" gin (data)

    "idx_request_gin_data_i" gin ((data -> 'i'::text))

    "idx_request_gin_data_r" gin ((data -> 'r'::text))

    "idx_request_gin_data_t" gin ((data -> 't'::text))

    "idx_request_gin_meta_identifiers" gin ((metadata -> 'identifiers'::text))

    "idx_request_gin_metadata" gin (metadata)

    "idx_request_meta_identifiers" btree ((metadata ->> 'identifiers'::text))

Check constraints:

    "require_jsonb_data" CHECK (jsonb_typeof(data) = 'object'::text)

    "require_jsonb_metadata" CHECK (jsonb_typeof(metadata) = 'object'::text)

Disabled user triggers:

    audit_trigger_row AFTER INSERT OR DELETE OR UPDATE ON request FOR EACH ROW EXECUTE FUNCTION audit.audit_event_processor('true')

    audit_trigger_stm AFTER TRUNCATE ON request FOR EACH STATEMENT EXECUTE FUNCTION audit.audit_event_processor('true'

Lots of gin indexes...

Note the 2 triggers are disabled.

Size of the table, indexes, toast:

table_name      request

row_estimate    227,771      

total_bytes     12,952,428,544 

index_bytes     6,088,523,776 

toast_bytes     6,614,458,368

table_bytes     249,446,400

total            12 GB

index            5806 MB

toast            6308 MB

table           238 MB

We are updating some sample rows.  Here are the sizes of the 2 JSONB columns for these sample rows:

select objectid, pg_column_size(data) data, pg_column_size(metadata) metadata,  clientid

  from request r

 order by  pg_column_size(data)  desc

 limit 4;

objectid                                         data      metadata   clientid

f9077561-4b40-41f8-8a52-3a2b83014982             22172347   842           VHW        <---- update #1 below

0103fe5d-7407-45b6-8966-32a8e4f6b67c             17814078   866           OV9        <---- update #2 below

6009dbfc-8375-48b3-bbf6-921d48aad308             15971425   879           VHW

3a0201bc-23f0-b648-8408-c21f81f6b974             14690119   785           VHU        <---- update #3 below

*** Update the top row above which is the largest for the DATA JSONB column:

explain(analyze, buffers)

UPDATE request

SET

     checkOutByUID = 'shivatest',

     CheckOutDateTime = '2022-01-10T16:24:10.2900556Z'

WHERE

     objectid = 'f9077561-4b40-41f8-8a52-3a2b83014982';

Update on request  (cost=0.42..8.44 rows=0 width=0) (actual time=74.678..74.679 rows=0 loops=1)

  Buffers: shared hit=2818 read=1 dirtied=1

  I/O Timings: shared read=0.835

  ->  Index Scan using requestkey on request  (cost=0.42..8.44 rows=1 width=418) (actual time=0.875..0.878 rows=1 loops=1)

        Index Cond: (objectid = 'f9077561-4b40-41f8-8a52-3a2b83014982'::bpchar)

        Buffers: shared hit=3 read=1

        I/O Timings: shared read=0.835

Planning Time: 0.093 ms

Execution Time: 74.707 ms

*** 2818 shared block hits, 1 read, 1 dirtied.  Excellent.

*** Update the next largest row

explain(analyze, buffers) UPDATE request

SET

     checkOutByUID = 'shivatest',

     CheckOutDateTime = '2022-01-10T16:24:10.2900556Z'

WHERE

     objectid = '0103fe5d-7407-45b6-8966-32a8e4f6b67c';

Update on request  (cost=0.42..8.44 rows=0 width=0) (actual time=34663.039..34663.040 rows=0 loops=1)

  Buffers: shared hit=10787339 read=79854 dirtied=90531

  I/O Timings: shared read=5083.198

  ->  Index Scan using requestkey on request  (cost=0.42..8.44 rows=1 width=418) (actual time=0.908..0.912 rows=1 loops=1)

        Index Cond: (objectid = '0103fe5d-7407-45b6-8966-32a8e4f6b67c'::bpchar)

        Buffers: shared hit=3 read=1

        I/O Timings: shared read=0.868

Planning Time: 0.095 ms

Execution Time: 34663.071 ms

Wow-  10 million shared block reads...  90k dirtied...  update it again:  Same deal with shared blocks at 10M.  Dirtied came down but shared blocks is still extremely high.

Update on request  (cost=0.42..8.44 rows=0 width=0) (actual time=27683.165..27683.166 rows=0 loops=1)

  Buffers: shared hit=10846051 read=145 dirtied=1189

  I/O Timings: shared read=73.607

  ->  Index Scan using requestkey on request  (cost=0.42..8.44 rows=1 width=418) (actual time=0.021..0.033 rows=1 loops=1)

        Index Cond: (objectid = '0103fe5d-7407-45b6-8966-32a8e4f6b67c'::bpchar)

        Buffers: shared hit=6

Planning Time: 0.095 ms

Execution Time: 27683.197 ms

*** Update the 4th largest row:

explain(analyze, buffers) UPDATE request

SET

     checkOutByUID = 'shivatest',

     CheckOutDateTime = '2022-01-10T16:24:10.2900556Z'

WHERE

     objectid = '3a0201bc-23f0-b648-8408-c21f81f6b974';

Update on request  (cost=0.42..8.44 rows=0 width=0) (actual time=18179.058..18179.059 rows=0 loops=1)

  Buffers: shared hit=2138731 read=37045 dirtied=50800

  I/O Timings: shared read=6030.123

  ->  Index Scan using requestkey on request  (cost=0.42..8.44 rows=1 width=418) (actual time=0.864..0.868 rows=1 loops=1)

        Index Cond: (objectid = '3a0201bc-23f0-b648-8408-c21f81f6b974'::bpchar)

        Buffers: shared hit=3 read=1

        I/O Timings: shared read=0.825

Planning Time: 0.085 ms

Execution Time: 18179.090 ms

And run it a second time:

Update on request  (cost=0.42..8.44 rows=0 width=0) (actual time=10553.022..10553.023 rows=0 loops=1)

  Buffers: shared hit=2159422 dirtied=17

  ->  Index Scan using requestkey on request  (cost=0.42..8.44 rows=1 width=418) (actual time=0.022..0.032 rows=1 loops=1)

        Index Cond: (objectid = '3a0201bc-23f0-b648-8408-c21f81f6b974'::bpchar)

        Buffers: shared hit=6

Planning Time: 0.093 ms

Execution Time: 10553.056 ms

2.1 million shared block reads, the first update did 50k dirtied...

At 2.1 million shared block reads with an 8k block size that is 16 GB of data read in memory.  At 10 million that is 76 GB of data read in memory.  The entire table, indexes, toast is only 12 GB so what is this reading through when it does 2 or 10 million shared block hits?  The amount of work for the first update which did 2818 shared block reads is what I'd expect but I have no clue how to determine what this is doing when it's going through millions of blocks in memory.

Any insight would be much appreciated.

Regards

Steve