1

I have a simple table which stores metadata about users in an hstore column. This table has ~1.1M rows.

                            Table "public.stitcher_participant"
   Column   |           Type           |                             Modifiers
------------+--------------------------+-------------------------------------------------------------------
 id         | integer                  | not null default nextval('stitcher_participant_id_seq'::regclass)
 sample_id  | character varying(255)   | not null
 created    | timestamp with time zone | not null
 hs_data    | hstore                   |
Indexes:
    "stitcher_participant_pkey" PRIMARY KEY, btree (id)
    "ix_participant_created" btree (created)
    "ix_participant_hs_mp_birth_year" btree (((hs_data -> 'mp_birth_year'::text)::numeric), id) WHERE (hs_data -> 'mp_birth_year'::text) ~ '^(?=.+)(?:[1-9]\d*|0)?(?:\.\d+)?$'::text
    "ix_participant_hs_object" gin (hs_data)
    "stitcher_participant_sample_id_idx" btree (sample_id)

Options: autovacuum_vacuum_threshold=50, autovacuum_enabled=true, autovacuum_vacuum_scale_factor=0.0001, autovacuum_analyze_scale_factor=0.0005

I also have the statistics_target for hs_data set at 2000:

SELECT attrelid, attstattarget, attname
FROM   pg_attribute
WHERE  attrelid = 'public.stitcher_participant'::regclass
  AND  attname = 'hs_data';

produces:

attrelid    attstattarget    attname
16640       2000             hs_data

When these users are active they may produce 25 to 100 UPDATEs to the hs_data in their respective row over a period of 20 min or so.

In periods of somewhat higher activity (1000+ UPDATEs/minute) I noticed some of our reporting pages were timing out. One of the queries responsible was this one (generated by an ORM though I tried to format it nicely):

SELECT
    (trim(hs_data->'xxxxx_q01 - sueno')) AS "hscol", 
    COUNT(stitcher_participant.hs_data->'xxxxx_q01 - sueno') AS "hscol_count" 
FROM 
    "stitcher_participant" 
WHERE 
    (     
         (hs_data @> hstore('xxxxx_qx1', 'yes')) 
      OR (hs_data @> hstore('xxxxx_qx2', 'yes'))
      OR (hs_data @> hstore('xxxxx_qx3', 'yes'))
      OR (hs_data @> hstore('xxxxx_qx4', 'yes'))
    ) 
    AND (hs_data @> hstore('source', 'somesource'))
GROUP BY 
    (trim(hs_data->'xxxxx_q01 - sueno'))

Normally this query runs in ~50ms, but during this period of activity it got much slower. Turns out it was using a much worse query plan than it does normally.

note: hs_data @> hstore('source', 'somesource') matches ~530k users, but each of the xxxxx_qxN conditions matches under a hundred.

Here are the query plans captured with explain (analyze, verbose, buffers, costs)

Good query plan (30ms):

HashAggregate  (cost=962.02..962.04 rows=5 width=417) (actual time=31.885..31.885 rows=2 loops=1)
  Output: (btrim((hs_data -> 'xxxxx_q01 - sueno'::text))), count((hs_data -> 'xxxxx_q01 - sueno'::text))
  Group Key: btrim((stitcher_participant.hs_data -> 'xxxxx_q01 - sueno'::text))
  Buffers: shared hit=12470
  ->  Bitmap Heap Scan on public.stitcher_participant  (cost=952.01..962.01 rows=5 width=417) (actual time=5.789..27.076 rows=462 loops=1)
        Output: btrim((hs_data -> 'xxxxx_q01 - sueno'::text)), hs_data
        Recheck Cond: (((stitcher_participant.hs_data @> '"xxxxx_qx1"=>"yes"'::hstore) AND (stitcher_participant.hs_data @> '"source"=>"somesource"'::hstore)) OR ((stitcher_participant.hs_data @> '"xxxxx_qx2"=>"yes"'::hstore) AND (stitcher_participant.hs_data @> '"source"=>"somesource"'::hstore)) OR ((stitcher_participant.hs_data @> '"xxxxx_qx3"=>"yes"'::hstore) AND (stitcher_participant.hs_data @> '"source"=>"somesource"'::hstore)) OR ((stitcher_participant.hs_data @> '"xxxxx_qx4"=>"yes"'::hstore) AND (stitcher_participant.hs_data @> '"source"=>"somesource"'::hstore)))
        Heap Blocks: exact=210
        Buffers: shared hit=10355
        ->  BitmapOr  (cost=952.01..952.01 rows=5 width=0) (actual time=5.631..5.631 rows=0 loops=1)
              Buffers: shared hit=571
              ->  Bitmap Index Scan on ix_participant_hs_object  (cost=0.00..238.00 rows=1 width=0) (actual time=1.582..1.582 rows=105 loops=1)
                    Index Cond: ((stitcher_participant.hs_data @> '"xxxxx_qx1"=>"yes"'::hstore) AND (stitcher_participant.hs_data @> '"source"=>"somesource"'::hstore))
                    Buffers: shared hit=136
              ->  Bitmap Index Scan on ix_participant_hs_object  (cost=0.00..238.00 rows=1 width=0) (actual time=1.314..1.314 rows=123 loops=1)
                    Index Cond: ((stitcher_participant.hs_data @> '"xxxxx_qx2"=>"yes"'::hstore) AND (stitcher_participant.hs_data @> '"source"=>"somesource"'::hstore))
                    Buffers: shared hit=143
              ->  Bitmap Index Scan on ix_participant_hs_object  (cost=0.00..238.00 rows=1 width=0) (actual time=1.341..1.341 rows=119 loops=1)
                    Index Cond: ((stitcher_participant.hs_data @> '"xxxxx_qx3"=>"yes"'::hstore) AND (stitcher_participant.hs_data @> '"source"=>"somesource"'::hstore))
                    Buffers: shared hit=149
              ->  Bitmap Index Scan on ix_participant_hs_object  (cost=0.00..238.00 rows=1 width=0) (actual time=1.393..1.393 rows=115 loops=1)
                    Index Cond: ((stitcher_participant.hs_data @> '"xxxxx_qx4"=>"yes"'::hstore) AND (stitcher_participant.hs_data @> '"source"=>"somesource"'::hstore))
                    Buffers: shared hit=143
Planning time: 0.733 ms
Execution time: 31.942 ms

Bad query plan (115 sec):

HashAggregate  (cost=3576.93..3576.95 rows=5 width=416) (actual time=114796.851..114796.852 rows=2 loops=1)
  Output: (btrim((hs_data -> 'xxxxx_q01 - sueno'::text))), count((hs_data -> 'xxxxx_q01 - sueno'::text))
  Group Key: btrim((stitcher_participant.hs_data -> 'xxxxx_q01 - sueno'::text))
  Buffers: shared hit=5246897
  ->  Bitmap Heap Scan on public.stitcher_participant  (cost=1389.71..3576.92 rows=5 width=416) (actual time=2036.657..114782.884 rows=462 loops=1)
        Output: btrim((hs_data -> 'xxxxx_q01 - sueno'::text)), hs_data
        Recheck Cond: (stitcher_participant.hs_data @> '"source"=>"somesource"'::hstore)
        Filter: ((stitcher_participant.hs_data @> '"xxxxx_qx1"=>"yes"'::hstore) OR (stitcher_participant.hs_data @> '"xxxxx_qx2"=>"yes"'::hstore) OR (stitcher_participant.hs_data @> '"xxxxx_qx3"=>"yes"'::hstore) OR (stitcher_participant.hs_data @> '"xxxxx_qx4"=>"yes"'::hstore))
        Rows Removed by Filter: 524556
        Heap Blocks: exact=104637
        Buffers: shared hit=5244782
        ->  Bitmap Index Scan on ix_participant_hs_object  (cost=0.00..1389.71 rows=1141 width=0) (actual time=935.297..935.297 rows=525849 loops=1)
              Index Cond: (stitcher_participant.hs_data @> '"source"=>"somesource"'::hstore)
              Buffers: shared hit=1157
Planning time: 0.358 ms
Execution time: 114798.054 ms

I suspected that analyze was running frequently (more on this in a sec) and possibly causing the issue so I reigned in the autovacuum_analyze_scale_factor from it's previous value, 0.00001 to the current 0.0005 that you see now in the table description.

This problem of our reporting pages timing out during periods of elevated activity has happened several times, though this is the first solid lead I've found.

There hasn't been another period of elevated activity, nor any reporting timeouts since the last incident when I captured these query plans. I also haven't been able to reproduce this on my local machine.

Is it possible that autovacuum analyze running very frequently (I saw the pg_stat_user_tables.last_autoanalyze value updating every few minutes during the incident) was the cause of the bad query plan?

  • 1
    This is a very good question. I wouldn't blame autoanalyze for this happening, rather the underlying statistics settings. If the statistics (auto)analyze collects from the table leads to so bad plans (check the huge mismatch of the estimated and actual row numbers in the bottom node of the bad plan), one can play around with statistics settings. I am currently not in a position to check how this could work for an hstore, but usually raising statistics_target to a higher value helps. See tech.zalando.com/blog/… for an example. – dezso Apr 22 '16 at 21:32
  • I have the statistics_target for the hs_data column set to 2000 – Jiaaro Apr 23 '16 at 0:34
  • @dezso I suppose it depends largely on how statistics work for hstore - regardless of having a high statistics_target. I've had a hard time understanding the specifics about that though – Jiaaro Apr 23 '16 at 0:54

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Browse other questions tagged or ask your own question.