In summary, Postgres prefers doing the equivalent of a [datetime index seqscan]+[filter (using the heavy function)] instead of using the index when using = to find what I like. When simply replacing = with ~~, it starts using a bitmapAnd on datetime+indexed field which is thousands of time quicker.
I tried:
- setting the cost of seqscan up, enable_seqscan=off, effective_cache_size=<size of indices> without any effect.
- changing the cost of the execution of the function to 1000, but it also affects the index lookups cost even if it doesn't execute the function when using the index.
- raising the parallel_setup_cost to 10000 to make the explain understand the minimum cost of setting up parallel index scan is above 5000 which is the minimum cost of the bitmapAnd index scan.
- run analyze on the table.
It seems the planner doesn't take into accounts how many records it'll have to filter thru the costly function even if the planner knows how many records it'll have to filter. And I can confirm that using the index instead of filtering with the function result in order of magnitudes less processing time.
Any idea how to convince Postgres it is a bad idea to execute that function?
The table is quite simple:
fluentbit=# \d logs_nginx_p2022w07
Table "public.logs_nginx_p2022w07"
Column | Type | Collation | Nullable | Default
--------------------+--------------------------+-----------+----------+---------
dt | timestamp with time zone | | not null |
logs_meta_id | integer | | not null |
log | text | | |
http_authorization | jsonb | | |
log_format | logs_nginx_format | | not null |
Partition of: logs_nginx FOR VALUES FROM ('2022-02-14 00:00:00-05') TO ('2022-02-21 00:00:00-05')
Indexes:
"logs_nginx_p2022w07_dest_service_idx" btree (((logs_nginx_extract_fields(log_format, log)).dest_service) COLLATE "C") WITH (fillfactor='100')
"logs_nginx_p2022w07_dt_logs_meta_id_idx" btree (dt, logs_meta_id)
"logs_nginx_p2022w07_logs_nginx_get_remote_ip_idx" btree (logs_nginx_get_remote_ip(log))
"logs_nginx_p2022w07_remote_user_idx" btree (logs_nginx_get_remote_user(http_authorization)) WHERE http_authorization IS NOT NULL
Foreign-key constraints:
TABLE "logs_nginx" CONSTRAINT "logs_nginx_logs_meta_id_fk" FOREIGN KEY (logs_meta_id) REFERENCES logs_meta(id)
The function logs_nginx_extract_fields
does a CASE, a couple regexes and returns 10 values and is quite heavy on the CPU.
Here are the EXPLAIN ANALYZE for both =
and ~~
.
Using Equality operator:
fluentbit=# explain analyze select dt,log from logs_nginx where dt between '2022-02-15 13:00:00-05' and '2022-02-15 14:00:00-05' and ((logs_nginx_extract_fields(log_format, log)).dest_service = 'customerportal-webapi') limit 1000;
QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Limit (cost=1000.57..577572.04 rows=49 width=517) (actual time=44379.393..44379.453 rows=0 loops=1)
-> Gather (cost=1000.57..577572.04 rows=49 width=517) (actual time=44328.092..44328.151 rows=0 loops=1)
Workers Planned: 2
Workers Launched: 0
-> Parallel Index Scan using logs_nginx_p2022w07_dt_logs_meta_id_idx on logs_nginx_p2022w07 logs_nginx (cost=0.56..576567.14 rows=20 width=517) (actual time=44327.829..44327.829 rows=0 loops=1)
Index Cond: ((dt >= '2022-02-15 13:00:00-05'::timestamp with time zone) AND (dt <= '2022-02-15 14:00:00-05'::timestamp with time zone))
Filter: ((logs_nginx_extract_fields(log_format, log)).dest_service = 'customerportal-webapi'::text)
Rows Removed by Filter: 299642
Planning Time: 0.162 ms
JIT:
Functions: 7
Options: Inlining true, Optimization true, Expressions true, Deforming true
Timing: Generation 1.122 ms, Inlining 10.860 ms, Optimization 26.515 ms, Emission 13.784 ms, Total 52.279 ms
Execution Time: 44380.632 ms
Using LIKE operator:
fluentbit=# explain analyze select dt,log from logs_nginx where dt between '2022-02-15 13:00:00-05' and '2022-02-15 14:00:00-05' and ((logs_nginx_extract_fields(log_format, log)).dest_service ~~ 'customerportal-webapi') limit 1000;
QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------------------------------------------
Limit (cost=5323.55..5496.48 rows=49 width=517) (actual time=0.023..0.025 rows=0 loops=1)
-> Bitmap Heap Scan on logs_nginx_p2022w07 logs_nginx (cost=5323.55..5496.48 rows=49 width=517) (actual time=0.022..0.023 rows=0 loops=1)
Recheck Cond: ((dt >= '2022-02-15 13:00:00-05'::timestamp with time zone) AND (dt <= '2022-02-15 14:00:00-05'::timestamp with time zone))
Filter: ((logs_nginx_extract_fields(log_format, log)).dest_service ~~ 'customerportal-webapi'::text)
-> BitmapAnd (cost=5323.55..5323.55 rows=49 width=0) (actual time=0.020..0.021 rows=0 loops=1)
-> Bitmap Index Scan on logs_nginx_p2022w07_dest_service_idx (cost=0.00..54.85 rows=6438 width=0) (actual time=0.019..0.020 rows=0 loops=1)
Index Cond: ((logs_nginx_extract_fields(log_format, log)).dest_service = 'customerportal-webapi'::text)
-> Bitmap Index Scan on logs_nginx_p2022w07_dt_logs_meta_id_idx (cost=0.00..5268.43 rows=352886 width=0) (never executed)
Index Cond: ((dt >= '2022-02-15 13:00:00-05'::timestamp with time zone) AND (dt <= '2022-02-15 14:00:00-05'::timestamp with time zone))
Planning Time: 0.277 ms
Execution Time: 0.066 ms