1

I return a query which is taking Avg of 170 seconds to execute. I went through the PSQL documentation, they mentioned that if we increase work_mem the performance will increase. I increased the work_mem to 1000 MB even the performance is not improved.

Note: I indexed all the field which are the part of the query.

Below I am pasting the records present in the DB, query execution plan, query, result.

  • The number of records present in the DB:
event_logs=> select count(*) from events;
  count   
----------
 18706734
(1 row)
  • Query:
select raw->'request_payload'->'source'->0 as file, 
       count(raw->'request_payload'->>'status') as count, 
       raw->'request_payload'->>'status' as status 
from events 
where client = 'NTT' 
  and to_char(datetime, 'YYYY-MM-DD') = '2019-10-31' 
  and event_name = 'wbs_indexing' 
group by raw->'request_payload'->'source'->0, 
         raw->'request_payload'->>'status';
  • Result:
 file                   | count  | status  
-----------------------------+--------+--
 "xyz.csv"              |  91878 | failure
 "abc.csv"              |  91816 | failure
 "efg.csv"              | 398196 | failure
(3 rows)
  • Default work_mem(4 MB) query execution plan:
event_logs=> SHOW work_mem;
 work_mem 
----------
 4MB
(1 row)

event_logs=> explain analyze select raw->'request_payload'->'source'->0 as file, count(raw->'request_payload'->>'status') as count,  raw->'request_payload'->>'status' as status from events where to_char(datetime, 'YYYY-MM-DD') = '2019-10-31' and client = 'NTT'  and event_name = 'wbs_indexing' group by raw->'request_payload'->'source'->0, raw->'request_payload'->>'status';
                                                                             QUERY PLAN                                                       

----------------------------------------------------------------------------------------------------------------------------------------------
-----------------------
 Finalize GroupAggregate  (cost=3256017.54..3267087.56 rows=78474 width=72) (actual time=172547.598..172965.581 rows=3 loops=1)
   Group Key: ((((raw -> 'request_payload'::text) -> 'source'::text) -> 0)), (((raw -> 'request_payload'::text) ->> 'status'::text))
   ->  Gather Merge  (cost=3256017.54..3264829.34 rows=65674 width=72) (actual time=172295.204..172965.630 rows=9 loops=1)
         Workers Planned: 2
         Workers Launched: 2
         ->  Partial GroupAggregate  (cost=3255017.52..3256248.91 rows=32837 width=72) (actual time=172258.342..172737.534 rows=3 loops=3)
               Group Key: ((((raw -> 'request_payload'::text) -> 'source'::text) -> 0)), (((raw -> 'request_payload'::text) ->> 'status'::text))
               ->  Sort  (cost=3255017.52..3255099.61 rows=32837 width=533) (actual time=171794.584..172639.670 rows=193963 loops=3)
                     Sort Key: ((((raw -> 'request_payload'::text) -> 'source'::text) -> 0)), (((raw -> 'request_payload'::text) ->> 'status'::text))
                     Sort Method: external merge  Disk: 131856kB
                     ->  Parallel Seq Scan on events  (cost=0.00..3244696.75 rows=32837 width=533) (actual time=98846.155..169311.063 rows=193963 loops=3)
                           Filter: ((client = 'NTT'::text) AND (event_name = 'wbs_indexing'::text) AND (to_char(datetime, 'YYYY-MM-DD'::text) = '2019-10-31'::text))
                           Rows Removed by Filter: 6041677
 Planning time: 0.953 ms
 Execution time: 172983.273 ms
(15 rows)
  • Increased work_mem(1000 MB) query execution plan:
event_logs=> SHOW work_mem;
 work_mem 
----------
 1000MB
(1 row)

event_logs=> explain analyze select raw->'request_payload'->'source'->0 as file, count(raw->'request_payload'->>'status') as count,  raw->'request_payload'->>'status' as status from events where to_char(datetime, 'YYYY-MM-DD') = '2019-10-31' and client = 'NTT'  and event_name = 'wbs_indexing' group by raw->'request_payload'->'source'->0, raw->'request_payload'->>'status';
                                                                            QUERY PLAN                                                                              
---------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Finalize GroupAggregate  (cost=3248160.04..3259230.06 rows=78474 width=72) (actual time=167979.419..168189.228 rows=3 loops=1)
   Group Key: ((((raw -> 'request_payload'::text) -> 'source'::text) -> 0)), (((raw -> 'request_payload'::text) ->> 'status'::text))
   ->  Gather Merge  (cost=3248160.04..3256971.84 rows=65674 width=72) (actual time=167949.951..168189.282 rows=9 loops=1)
         Workers Planned: 2
         Workers Launched: 2
         ->  Partial GroupAggregate  (cost=3247160.02..3248391.41 rows=32837 width=72) (actual time=167945.607..168083.707 rows=3 loops=3)
               Group Key: ((((raw -> 'request_payload'::text) -> 'source'::text) -> 0)), (((raw -> 'request_payload'::text) ->> 'status'::text))
               ->  Sort  (cost=3247160.02..3247242.11 rows=32837 width=533) (actual time=167917.891..167975.549 rows=193963 loops=3)
                     Sort Key: ((((raw -> 'request_payload'::text) -> 'source'::text) -> 0)), (((raw -> 'request_payload'::text) ->> 'status'::text))
                     Sort Method: quicksort  Memory: 191822kB
                     ->  Parallel Seq Scan on events  (cost=0.00..3244696.75 rows=32837 width=533) (actual time=98849.936..167570.669 rows=193963 loops=3)
                           Filter: ((client = 'NTT'::text) AND (event_name = 'wbs_indexing'::text) AND (to_char(datetime, 'YYYY-MM-DD'::text) = '2019-10-31'::text))
                           Rows Removed by Filter: 6041677
 Planning time: 0.238 ms
 Execution time: 168199.046 ms
(15 rows)
  • Can someone help me to improve the performance of this query?
chatrapathi
  • 107
  • 8
  • The increase in `work_mem` got you off the sort-on-disk, but the seqscan is still taking up the most time. Have you created an index on the `events` table for columns `(client, event_name, to_char(datetime, 'YYYY-MM-DD'::text))`? – richyen Nov 06 '19 at 17:34
  • Yes, I indexed all the column names which are part of the query. – chatrapathi Nov 07 '19 at 06:33

2 Answers2

3

Increasing the work_mem did seem to make the sort about 8 times faster: (172639.670 - 169311.063) / (167975.549 - 167570.669) . But since the sort only took up a small fraction of the overall execution time, making it even 1000 times faster can't make things much better overall. It is the seq scan which is taking up the time.

Much of the time in the seq scan is probably spend on IO. You can see by running EXPLAIN (ANALYZE, BUFFERS) after turning track_io_timing on.

Also, parallelizing a seq scan is often not very helpful, as the IO system is usually able to deliver its full capacity to a single reader, due to the magic of readahead. And sometimes parallel readers can even step on each others toes, making the whole performance worse. You can disable parallelization with set max_parallel_workers_per_gather TO 0; This might make things faster, and if it doesn't it will at least make the EXPLAIN plan easier to understand.

You are fetching over 3% of the table: 193963 / (193963 + 6041677). Indexes might not be very helpful when you are fetching so much of it. If they are to be, you would want a combined index, not individual ones. So you would want an index on (client, event_name, date(datetime)). Then you would also need to change the query to use date(datetime) rather than to_char(datetime, 'YYYY-MM-DD'). You need to make this change because to_char is not immutable, and so can't be indexed.

jjanes
  • 37,812
  • 5
  • 27
  • 34
0

The issue got resolved by modifying the query. Here the issue with the to_char method. It is converting the date object to string date on each and every record in the table to match with the given string date. So I update the query like extracting the records between the given date and next day date. Now am getting the response within 500 ms.

chatrapathi
  • 107
  • 8