Postgres 10.6: Why is a particular partition's index not being used?

Question

I'm truly stumped as to what's causing this issue and hoping for some guidance.

Firstly, this is in our STAGE environment and we partition this table based on the createdTime every month. I have triple checked the partitions and INDEXes on each and everything is Identical for every month. Also, our PRODUCTION database table I have run an EXPLAIN ANALYZE on the following query:

explain analyze select * from ubdrecord
where jsonb_extract_path_text("metadata",'deliveryNoteInfo','deliveryNoteNumber') =  '3535359152';

This results in the following result:

Append  (cost=0.43..23499.50 rows=21693 width=3503) (actual time=10.682..11.823 rows=7 loops=1)
  ->  Index Scan using p_01_2019_deliverynotenumberindex on ubdrecord_partition_01_2019  (cost=0.43..53.50 rows=47 width=765) (actual time=0.743..0.744 rows=0 loops=1)
        Index Cond: (jsonb_extract_path_text(metadata, VARIADIC '{deliveryNoteInfo,deliveryNoteNumber}'::text[]) = '3535359152'::text)
  ->  Index Scan using p_02_2019_deliverynotenumberindex on ubdrecord_partition_02_2019  (cost=0.43..34.23 rows=30 width=808) (actual time=0.892..0.893 rows=0 loops=1)
        Index Cond: (jsonb_extract_path_text(metadata, VARIADIC '{deliveryNoteInfo,deliveryNoteNumber}'::text[]) = '3535359152'::text)
  ->  Index Scan using p_03_2019_deliverynotenumberindex on ubdrecord_partition_03_2019  (cost=0.43..31.81 rows=28 width=800) (actual time=0.682..0.682 rows=0 loops=1)
        Index Cond: (jsonb_extract_path_text(metadata, VARIADIC '{deliveryNoteInfo,deliveryNoteNumber}'::text[]) = '3535359152'::text)
  ->  Index Scan using p_04_2019_deliverynotenumberindex on ubdrecord_partition_04_2019  (cost=0.43..37.17 rows=32 width=822) (actual time=0.904..0.904 rows=0 loops=1)
        Index Cond: (jsonb_extract_path_text(metadata, VARIADIC '{deliveryNoteInfo,deliveryNoteNumber}'::text[]) = '3535359152'::text)
  ->  Index Scan using p_05_2019_deliverynotenumberindex on ubdrecord_partition_05_2019  (cost=0.43..37.12 rows=33 width=827) (actual time=0.821..0.821 rows=0 loops=1)
        Index Cond: (jsonb_extract_path_text(metadata, VARIADIC '{deliveryNoteInfo,deliveryNoteNumber}'::text[]) = '3535359152'::text)
  ->  Index Scan using p_06_2019_deliverynotenumberindex on ubdrecord_partition_06_2019  (cost=0.43..50.06 rows=44 width=821) (actual time=0.720..0.720 rows=0 loops=1)
        Index Cond: (jsonb_extract_path_text(metadata, VARIADIC '{deliveryNoteInfo,deliveryNoteNumber}'::text[]) = '3535359152'::text)
  ->  Index Scan using p_07_2019_deliverynotenumberindex on ubdrecord_partition_07_2019  (cost=0.43..45.29 rows=40 width=816) (actual time=0.773..0.774 rows=0 loops=1)
        Index Cond: (jsonb_extract_path_text(metadata, VARIADIC '{deliveryNoteInfo,deliveryNoteNumber}'::text[]) = '3535359152'::text)
  ->  Index Scan using p_08_2019_deliverynotenumberindex on ubdrecord_partition_08_2019  (cost=0.43..37.82 rows=33 width=799) (actual time=0.950..0.950 rows=0 loops=1)
        Index Cond: (jsonb_extract_path_text(metadata, VARIADIC '{deliveryNoteInfo,deliveryNoteNumber}'::text[]) = '3535359152'::text)
  ->  Index Scan using p_09_2019_deliverynotenumberindex on ubdrecord_partition_09_2019  (cost=0.43..42.18 rows=37 width=843) (actual time=1.111..1.111 rows=0 loops=1)
        Index Cond: (jsonb_extract_path_text(metadata, VARIADIC '{deliveryNoteInfo,deliveryNoteNumber}'::text[]) = '3535359152'::text)
  ->  Index Scan using p_10_2019_deliverynotenumberindex on ubdrecord_partition_10_2019  (cost=0.43..44.22 rows=39 width=815) (actual time=0.765..0.765 rows=0 loops=1)
        Index Cond: (jsonb_extract_path_text(metadata, VARIADIC '{deliveryNoteInfo,deliveryNoteNumber}'::text[]) = '3535359152'::text)
  ->  Index Scan using p_11_2019_deliverynotenumberindex on ubdrecord_partition_11_2019  (cost=0.43..55.72 rows=49 width=738) (actual time=1.141..1.141 rows=0 loops=1)
        Index Cond: (jsonb_extract_path_text(metadata, VARIADIC '{deliveryNoteInfo,deliveryNoteNumber}'::text[]) = '3535359152'::text)
  ->  Index Scan using p_12_2019_deliverynotenumberindex on ubdrecord_partition_12_2019  (cost=0.43..37.24 rows=32 width=833) (actual time=0.720..0.720 rows=0 loops=1)
        Index Cond: (jsonb_extract_path_text(metadata, VARIADIC '{deliveryNoteInfo,deliveryNoteNumber}'::text[]) = '3535359152'::text)
  ->  Index Scan using p_01_2020_deliverynotenumberindex on ubdrecord_partition_01_2020  (cost=0.43..41.19 rows=36 width=814) (actual time=0.027..0.027 rows=0 loops=1)
        Index Cond: (jsonb_extract_path_text(metadata, VARIADIC '{deliveryNoteInfo,deliveryNoteNumber}'::text[]) = '3535359152'::text)
  ->  Index Scan using p_02_2020_deliverynotenumberindex on ubdrecord_partition_02_2020  (cost=0.43..39.26 rows=34 width=848) (actual time=0.027..0.027 rows=0 loops=1)
        Index Cond: (jsonb_extract_path_text(metadata, VARIADIC '{deliveryNoteInfo,deliveryNoteNumber}'::text[]) = '3535359152'::text)
  ->  Index Scan using p_03_2020_deliverynotenumberindex on ubdrecord_partition_03_2020  (cost=0.43..45.85 rows=40 width=856) (actual time=0.026..0.027 rows=0 loops=1)
        Index Cond: (jsonb_extract_path_text(metadata, VARIADIC '{deliveryNoteInfo,deliveryNoteNumber}'::text[]) = '3535359152'::text)
  ->  Index Scan using p_04_2020_deliverynotenumberindex on ubdrecord_partition_04_2020  (cost=0.43..3.77 rows=2 width=811) (actual time=0.025..0.026 rows=0 loops=1)
        Index Cond: (jsonb_extract_path_text(metadata, VARIADIC '{deliveryNoteInfo,deliveryNoteNumber}'::text[]) = '3535359152'::text)
  ->  Bitmap Heap Scan on ubdrecord_partition_05_2020  (cost=241.19..22846.59 rows=21130 width=3575) (actual time=0.349..1.451 rows=7 loops=1)
        Recheck Cond: (jsonb_extract_path_text(metadata, VARIADIC '{deliveryNoteInfo,deliveryNoteNumber}'::text[]) = '3535359152'::text)
        Heap Blocks: exact=7
        ->  Bitmap Index Scan on p_05_2020_deliverynotenumberindex  (cost=0.00..235.91 rows=21130 width=0) (actual time=0.338..0.338 rows=7 loops=1)
              Index Cond: (jsonb_extract_path_text(metadata, VARIADIC '{deliveryNoteInfo,deliveryNoteNumber}'::text[]) = '3535359152'::text)
  ->  Index Scan using p_06_2020_deliverynotenumberindex on ubdrecord_partition_06_2020  (cost=0.14..2.36 rows=1 width=3575) (actual time=0.006..0.006 rows=0 loops=1)
        Index Cond: (jsonb_extract_path_text(metadata, VARIADIC '{deliveryNoteInfo,deliveryNoteNumber}'::text[]) = '3535359152'::text)
  ->  Index Scan using p_07_2020_deliverynotenumberindex on ubdrecord_partition_07_2020  (cost=0.14..2.36 rows=1 width=3575) (actual time=0.005..0.005 rows=0 loops=1)
        Index Cond: (jsonb_extract_path_text(metadata, VARIADIC '{deliveryNoteInfo,deliveryNoteNumber}'::text[]) = '3535359152'::text)
  ->  Index Scan using p_08_2020_deliverynotenumberindex on ubdrecord_partition_08_2020  (cost=0.14..2.36 rows=1 width=3575) (actual time=0.004..0.005 rows=0 loops=1)
        Index Cond: (jsonb_extract_path_text(metadata, VARIADIC '{deliveryNoteInfo,deliveryNoteNumber}'::text[]) = '3535359152'::text)
  ->  Index Scan using p_09_2020_deliverynotenumberindex on ubdrecord_partition_09_2020  (cost=0.14..2.36 rows=1 width=3575) (actual time=0.004..0.004 rows=0 loops=1)
        Index Cond: (jsonb_extract_path_text(metadata, VARIADIC '{deliveryNoteInfo,deliveryNoteNumber}'::text[]) = '3535359152'::text)
  ->  Index Scan using p_10_2020_deliverynotenumberindex on ubdrecord_partition_10_2020  (cost=0.14..2.36 rows=1 width=3575) (actual time=0.004..0.004 rows=0 loops=1)
        Index Cond: (jsonb_extract_path_text(metadata, VARIADIC '{deliveryNoteInfo,deliveryNoteNumber}'::text[]) = '3535359152'::text)
  ->  Index Scan using p_11_2020_deliverynotenumberindex on ubdrecord_partition_11_2020  (cost=0.14..2.36 rows=1 width=3575) (actual time=0.006..0.006 rows=0 loops=1)
        Index Cond: (jsonb_extract_path_text(metadata, VARIADIC '{deliveryNoteInfo,deliveryNoteNumber}'::text[]) = '3535359152'::text)
  ->  Index Scan using p_12_2020_deliverynotenumberindex on ubdrecord_partition_12_2020  (cost=0.14..2.36 rows=1 width=3575) (actual time=0.004..0.005 rows=0 loops=1)
        Index Cond: (jsonb_extract_path_text(metadata, VARIADIC '{deliveryNoteInfo,deliveryNoteNumber}'::text[]) = '3535359152'::text)
Planning time: 192.498 ms
Execution time: 11.997 ms

As you can see, the current month is not getting scanned like all the other months. There are two things distinctive about that month which is:

1) This is the current month we're in (hence getting a lot of writes to that table) and

2) This is the month that actually contains some results.

The reason I haven't explored these particular distinctions is because our Production environment is scanning the index perfectly fine for this month. I should point out the data in each environment and read/write patterns is also very similar. We've verified the partitions and indexes in both environments are identifical in their specific configuration but curious as to what other broader database parameter settings may be the cause of this discrepancy. Any insight would be greatly appreciated and I can provide any additional information you need, just ask.

UPDATE: The reason this is a problem for us is that the actual query we're running uses other where clause parameters (which are also indexed, although for this particular case far less efficient). It's not possible for us to remove the other indexes and again, in Production, the proper index is used and the query returns quickly. However in STG, failure to use the proper index results in the query not coming back for several minutes. I guess the follow up question would be how do we FORCE a query plan to use a specific index (if it's too difficult to determine exactly WHY it's not using it)? I hope I've been successful in explaining. Again, the DATA between the two environments are nearly identical.

Answer 1

Very likely your table statistics are outdated.

Try the following:

ANALYZE ubdrecord_partition_05_2020;

If that improves the estimate, you can reduce autovacuum_analyze_scale_factor for the partitions to have PostgreSQL calculate the statistics more often.

Answer 2

So, this isn't, from what I can tell, an issue; the planner is behaving in a perfectly sane way, and the query is executing plenty quickly. And, to be clear, it is using the index for the current month, it's just using a different plan, a Bitmap Index Scan feeding into a Bitmap Heap Scan instead of a single-level Index Scan.

The reason you're seeing this - a different plan for only the partition that has results - is because you have an expression index on jsonb_extract_path_text("metadata", 'deliveryNoteInfo', 'deliveryNoteNumber'). The database collects statistics for every expression index in addition to every column, and so is able to tell from these statistics that the partitions other than the current one are likely to have very few results (rows=47, rows=30 etc, for the early months), and given that, it uses an index scan node for those partitions. For the current month, the statistics indicate that there should be be ~21130 rows, and so it uses a bitmap index scan instead, which is much faster when many rows are expected to be matched. Only 7 end up being found, but if other IDs could have had many

There's several parts of the statistics that could be in play. If you want to dive in, pg_stats is where to look. Let's do away with the parts that are probably irrelevant to this situation first. The statistics data that's least likely to be involved here is most_common_vals; unless this ID is one of the most common jsonb_extract_path_text("metadata", 'deliveryNoteInfo', 'deliveryNoteNumber') values in the table in the table (I assume not given there's only 7), it's unlikely to appear in this list. 2nd, n_distinct, is also probably unlikely to be what's causing this, as I assume the cardinality of unique deliveryNoteNumbers from month-to-month doesn't change much.

histogram_bounds, though, could absolutely cause the planner to think that other months don't have deliveryNoteNumbers that are likely to match, especially if deliveryNoteNumber is correlated with time in any way (either monotonically increasing or derived from a timestamp will do this) - and this is my guess as to why you're seeing this plan. Using the histogram bounds, the planner would see that january's deliveryNoteNumbers tend to range from (I'm making these up) 3532000000 to 3533000000, February the next chunk, and so on. It doesn't know this for sure (the statistics are not guaranteed to be correct; stats collection is skipped in various situations) and so it has to check the partition anyway, but for planning purposes, it would be able to predict that there would be few results, and so it goes for the index scan. If indeed all of the other months' deliveryNoteNumbers fall below the one in the query, it's a very quick check of each partition's index. For the current month, the histogram would overlap the deliveryNoteNumber in the query, and the planner would assume many more rows would be found.

Here's a blog post from 2ndQuadrant that, towards the end, goes into how an expression index results in better plans.