1

I have a query (attached with query plan) that is run every 5-7 seconds from every device that is running our dashboard (typically, 500+ devices at peak time). This query, at the outset looks like it spends time in wait state IO:BufFileWrite.

From AWS Aurora Performance Insights dashboard, one can see that the query in question spends more time in IO: BUfFileWrite wait state (sky blue color in the graph)

Performance_Insights

Postgres Configuration / Details:

  1. AWS Aurora PostgreSQL 10.6
  2. R5.4X Large instance (128 GB RAM)
  3. work_mem = 80MB
  4. I use a hikari connection pool to manage the DB connections.

A week earlier, I started seeing many errors on my app server:

Failed to get database connection errors

and/or

java.sql.SQLTimeoutException: Timeout after 30000ms of waiting for a connection

A little debugging and with help of PGAdmin, saw that most of the connections were waiting on IO: BufFileWrite and hence realised that the default 4MB work_mem was not enough for the query.

PGAdmin stats

With the help of PgBadger, saw that the average temp file size was 70MB and hence updated the work_mem to 80 MB.

Temp_File_Pg_Badger

This definitely helped, I started seeing lesser DB connections issue, but it did not go away completely.

I used Postgres Visualize Analyzer and Explain Depesz to understand the query plan and saw that an index only scan has a Total Cost of 4984972.45 and Plan Rows 111195272. This table (students_points) actually has 100M+ rows and is ~15GB in size and is not partitioned.

I tried adding a partial index ( create index students_latest_point_idx ON students_points (student_id, evaluation_date desc) ), in the hope that the cost of the above scan would improve, but in vain.

I have run VACUUM ( FULL, ANALYZE, VERBOSE); and REINDEX on the tables involved, but no visible performance improvement.

I need help with the following

  1. What does the never executed part of the query plan mean? - I have checked the literature on the web, but no satisfactory explanation apart from Postgres engine thinks that it's not relevant / returned 0 rows.
  2. Should I look at/be worried at Total Cost of 4984972.45 and Plan Rows 111195272. from the query plan, even though it says never executed?
  3. What would lead to excessive time spent in the wait state BufFileWrite? From what I understand, when a sort/filter is being applied, temp files are used and this shows up as the BufFileWrite wait state. Monitoring_Postgres
  4. Where would you advise me to start with, to reduce the time spent by the query in the IO wait state of BufFileWrite? - I have tried, Vacuum, Reindex, adding new partial index - but didn't help.
  5. One thing on my mind is, instead of using the students_points table (which has 1 row, for every student, for every test, he takes every week, over 4 years) so it builds up fast, create a new table that will hold only the latest points for every student (hence only as many rows as there are students) and use that in the query.

Any help is appreciated. Thanks in advance. If you need any more information, I would be happy to provide.

The query and the plan

EXPLAIN (ANALYZE, COSTS, VERBOSE, BUFFERS, TIMING, SUMMARY) 
SELECT 
    SUM(CASE WHEN just_pass = 1 THEN 1 ELSE 0 END) point,
    SUM(CASE WHEN week_of_birthday = TRUE THEN 1 ELSE 0 END) birthday, 
    SUM(CASE WHEN fresh_grad = 1 THEN 1 ELSE 0 end) fresher, 
    SUM(CASE WHEN intervention_type::INT = 2 OR intervention_type::INT = 3 THEN 1 ELSE 0 END) attention 
FROM 
    (
        SELECT 
            checkins.student_id, intercepts.intervention_type ,max(evaluation_date), just_pass, 
            compute_week_of_birthday(student_birthdate, 4 , 'US/Central') as week_of_birthday, 
            CASE 
                WHEN student_enrolment_date NOTNULL AND student_enrolment_date >= '2017-01-29' AND student_enrolment_date < '2016-11-30' 
                THEN 1 ELSE 0 END AS fresh_grad 
            FROM 
            (
                SELECT 
                    student_id 
                FROM 
                    checkin_table 
                WHERE 
                    house_id = 9001 
                AND 
                    timestamp> '2019-06-11 01:00:40' AND timestamp<= '2019-06-11 01:00:50'
                GROUP BY 
                student_id
            ) 
            checkins 
        LEFT JOIN 
            students 
        ON 
            checkins.student_id = students.student_id 
        LEFT JOIN 
            students_points points 
        ON 
            checkins.student_id = points.student_id 
        LEFT JOIN 
            (
                select 
                    record_id, student_id, intervention_type, intervention_date
                FROM 
                    intervention_table 
                WHERE 
                    intervention_date 
                IN 
                    (
                        SELECT 
                            MAX(intervention_date) 
                        FROM 
                            intervention_table 
                        GROUP BY 
                            student_id
                    )
            ) AS intercepts 
        ON 
            checkins.student_id = intercepts.student_id 
        WHERE 
            date_part('year',age(student_birthdate)) >=18 
        AND 
            lower(registration_type_description) !~* '.*temporary.*' 
        GROUP BY 
            checkins.student_id, students.student_enrolment_date, student_birthdate, just_pass, intercepts.intervention_type
    ) AS result 
WHERE 
    max IN 
        (
            SELECT 
                evaluation_date 
            FROM 
                students_points 
            ORDER BY 
                evaluation_date DESC LIMIT 1
        ) 
        OR 
    max ISNULL;
                                                                                                                                                                                                                                                                                                                                                                                                                                                                      QUERY PLAN                                                                                                                                                                                                                                                                                                                                                                                                                                                                      
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=74433.83..74433.84 rows=1 width=32) (actual time=0.081..0.081 rows=1 loops=1)
   Output: sum(CASE WHEN (result.just_pass = 1) THEN 1 ELSE 0 END), sum(CASE WHEN result.week_of_birthday THEN 1 ELSE 0 END), sum(CASE WHEN (result.fresh_grad = 1) THEN 1 ELSE 0 END), sum(CASE WHEN (((result.intervention_type)::integer = 2) OR ((result.intervention_type)::integer = 3)) THEN 1 ELSE 0 END)
   Buffers: shared hit=20
   ->  Subquery Scan on result  (cost=74412.92..74432.98 rows=34 width=15) (actual time=0.079..0.079 rows=0 loops=1)
         Output: result.student_id, result.intervention_type, result.max, result.just_pass, result.week_of_birthday, result.fresh_grad, students.student_enrolment_date, students.student_birthdate
         Filter: ((hashed SubPlan 1) OR (result.max IS NULL))
         Buffers: shared hit=20
         ->  GroupAggregate  (cost=74412.31..74431.52 rows=68 width=35) (actual time=0.079..0.079 rows=0 loops=1)
               Output: checkin_table.student_id, intervention_table.intervention_type, max(points.evaluation_date), points.just_pass, compute_week_of_birthday(students.student_birthdate, 4, 'US/Central'::text), CASE WHEN ((students.student_enrolment_date IS NOT NULL) AND (students.student_enrolment_date >= '2017-01-29'::date) AND (students.student_enrolment_date < '2016-11-30'::date)) THEN 1 ELSE 0 END, students.student_enrolment_date, students.student_birthdate
               Group Key: checkin_table.student_id, students.student_enrolment_date, students.student_birthdate, points.just_pass, intervention_table.intervention_type
               Buffers: shared hit=20
               ->  Sort  (cost=74412.31..74412.48 rows=68 width=30) (actual time=0.078..0.078 rows=0 loops=1)
                     Output: checkin_table.student_id, intervention_table.intervention_type, points.just_pass, students.student_enrolment_date, students.student_birthdate, points.evaluation_date
                     Sort Key: checkin_table.student_id, students.student_enrolment_date, students.student_birthdate, points.just_pass, intervention_table.intervention_type
                     Sort Method: quicksort  Memory: 25kB
                     Buffers: shared hit=20
                     ->  Nested Loop Left Join  (cost=70384.64..74410.24 rows=68 width=30) (actual time=0.035..0.035 rows=0 loops=1)
                           Output: checkin_table.student_id, intervention_table.intervention_type, points.just_pass, students.student_enrolment_date, students.student_birthdate, points.evaluation_date
                           Buffers: shared hit=6
                           ->  Nested Loop Left Join  (cost=70384.08..74151.91 rows=1 width=22) (actual time=0.035..0.035 rows=0 loops=1)
                                 Output: checkin_table.student_id, intervention_table.intervention_type, students.student_birthdate, students.student_enrolment_date
                                 Buffers: shared hit=6
                                 ->  Nested Loop  (cost=8.90..25.46 rows=1 width=16) (actual time=0.034..0.034 rows=0 loops=1)
                                       Output: checkin_table.student_id, students.student_birthdate, students.student_enrolment_date
                                       Buffers: shared hit=6
                                       ->  Group  (cost=8.46..8.47 rows=2 width=8) (actual time=0.034..0.034 rows=0 loops=1)
                                             Output: checkin_table.student_id
                                             Group Key: checkin_table.student_id
                                             Buffers: shared hit=6
                                             ->  Sort  (cost=8.46..8.47 rows=2 width=8) (actual time=0.033..0.033 rows=0 loops=1)
                                                   Output: checkin_table.student_id
                                                   Sort Key: checkin_table.student_id
                                                   Sort Method: quicksort  Memory: 25kB
                                                   Buffers: shared hit=6
                                                   ->  Append  (cost=0.00..8.45 rows=2 width=8) (actual time=0.027..0.027 rows=0 loops=1)
                                                         Buffers: shared hit=6
                                                         ->  Seq Scan on public.checkin_table  (cost=0.00..0.00 rows=1 width=8) (actual time=0.002..0.002 rows=0 loops=1)
                                                               Output: checkin_table.student_id
                                                               Filter: ((checkin_table.checkin_time > '2019-06-11 01:00:40+00'::timestamp with time zone) AND (checkin_table.checkin_time <= '2019-06-11 01:00:50+00'::timestamp with time zone) AND (checkin_table.house_id = 9001))
                                                         ->  Index Scan using checkins_y2019_m6_house_id_timestamp_idx on public.checkins_y2019_m6  (cost=0.43..8.45 rows=1 width=8) (actual time=0.024..0.024 rows=0 loops=1)
                                                               Output: checkins_y2019_m6.student_id
                                                               Index Cond: ((checkins_y2019_m6.house_id = 9001) AND (checkins_y2019_m6.checkin_time > '2019-06-11 01:00:40+00'::timestamp with time zone) AND (checkins_y2019_m6.checkin_time <= '2019-06-11 01:00:50+00'::timestamp with time zone))
                                                               Buffers: shared hit=6
                                       ->  Index Scan using students_student_id_idx on public.students  (cost=0.43..8.47 rows=1 width=16) (never executed)
                                             Output: students.student_type, students.house_id, students.registration_id, students.registration_status, students.registration_type_status, students.total_non_core_subjects, students.registration_source, students.total_core_subjects, students.registration_type_description, students.non_access_flag, students.address_1, students.address_2, students.city, students.state, students.zipcode, students.registration_created_date, students.registration_activation_date, students.registration_cancellation_request_date, students.registration_termination_date, students.cancellation_reason, students.monthly_dues, students.student_id, students.student_type, students.student_status, students.student_first_name, students.student_last_name, students.email_address, students.student_enrolment_date, students.student_birthdate, students.student_gender, students.insert_time, students.update_time
                                             Index Cond: (students.student_id = checkin_table.student_id)
                                             Filter: ((lower((students.registration_type_description)::text) !~* '.*temporary.*'::text) AND (date_part('year'::text, age((CURRENT_DATE)::timestamp with time zone, (students.student_birthdate)::timestamp with time zone)) >= '18'::double precision))
                                 ->  Nested Loop  (cost=70375.18..74126.43 rows=2 width=14) (never executed)
                                       Output: intervention_table.intervention_type, intervention_table.student_id
                                       Join Filter: (intervention_table.intervention_date = (max(intervention_table_1.intervention_date)))
                                       ->  HashAggregate  (cost=70374.75..70376.75 rows=200 width=8) (never executed)
                                             Output: (max(intervention_table_1.intervention_date))
                                             Group Key: max(intervention_table_1.intervention_date)
                                             ->  HashAggregate  (cost=57759.88..63366.49 rows=560661 width=16) (never executed)
                                                   Output: max(intervention_table_1.intervention_date), intervention_table_1.student_id
                                                   Group Key: intervention_table_1.student_id
                                                   ->  Seq Scan on public.intervention_table intervention_table_1  (cost=0.00..46349.25 rows=2282125 width=16) (never executed)
                                                         Output: intervention_table_1.record_id, intervention_table_1.student_id, intervention_table_1.intervention_type, intervention_table_1.intervention_date, intervention_table_1.house_id, intervention_table_1.teacher_id, intervention_table_1.expiration_date, intervention_table_1.point_at_intervention
                                       ->  Index Scan using intervention_table_student_id_idx on public.intervention_table  (cost=0.43..18.70 rows=4 width=22) (never executed)
                                             Output: intervention_table.record_id, intervention_table.student_id, intervention_table.intervention_type, intervention_table.intervention_date, intervention_table.house_id, intervention_table.teacher_id, intervention_table.expiration_date, intervention_table.point_at_intervention
                                             Index Cond: (checkin_table.student_id = intervention_table.student_id)
                           ->  Index Scan using students_latest_points_idx on public.students_points points  (cost=0.57..257.65 rows=68 width=16) (never executed)
                                 Output: points.record_id, points.student_id, points.registration_id, points.house_id, points.evaluation_date, points.just_pass, points.five_star, points.star1, points.star2, points.star3, points.star4, points.updatedate
                                 Index Cond: (checkin_table.student_id = points.student_id)
         SubPlan 1
           ->  Limit  (cost=0.57..0.61 rows=1 width=4) (never executed)
                 Output: students_points.evaluation_date
                 ->  Index Only Scan Backward using students_points_evaluation_date_idx on public.students_points  (cost=0.57..4984972.45 rows=111195272 width=4) (never executed)
                       Output: students_points.evaluation_date
                       Heap Fetches: 0
 Planning time: 23.993 ms
 Execution time: 17.648 ms
(72 rows) 

PS: The names of the table and the attributes are replaced for privacy concerns. At the outset, it seems like I can partition the students_points table by year, but that is not an option that the team is open to for reasons I can't specify and it does not make sense to partition it based on the year, since most of our joins are on student_id and partitioning on student_id would lead to 1M+ partitions.

Edited to address Jjanes comment.

  1. checkin_table seems to be empty - checkin_table is a partitioned table. The query actually hits the partition - checkins_y2019_m6, which actually has data.
  2. What led you to think this query was the culprit? - When using PGBadger at the peak time, see that 30 out of the 40 DB connections are in the wait state. Looking at the queries of these connections, it's the same query described above - but with different combinations of house_id and checkin_time. Also, from the RDS insights, (image 1 above), if you look at the bottom portion of the screenshot, it has bar graphic, under the Load By Waits (AAS) and you can see that 2/3rds of the bar graph is light blue color (IOWait) and 1/3 is Green (CPU) and the corresponding query. Look at the attached pgbadger view (redacted the query details). This query is the most time consuming query. Redacted_PgBadger_Long_Running_Query
  3. pg_stat_statements - Yes I have had a look at it And this is the top query on total_time desc, which concurs with the PG Badger one. pg_stat_statements
  4. auto_explain looks doable. Just one question - would it hamper the performance in any way?
  5. Regarding IO Churn and slowest queries - I agree, but I am hitting dead ends and run out of ideas. I may be misinterpreting things, like you pointed out. I am not looking at all queries writing to temporary files, and that might be hogging the buffers, resulting in an IOWait here.
1

The value of "evaluation_date" is only needed to filter out rows from the GroupAggregate. Since that returns no rows, there is no need to execute the subplan that finds of the value of "evaluation_date".

You should not be worried about that cost. Even if that part of the query was executed, it would still be fast due to the LIMIT. The reported cost estimate for a node is under the assumption it runs to completion. Pro-rating that cost down is the job of the LIMIT node above it.

The table checkin_table seems to be empty. That is pretty odd, isn't it?

Whatever is causing your excessive BufFileWrite is not this query, or at least not the instance of the query you show--perhaps there are other occasions when it gets run with a non-empty checkin_table. What led you to think this query was the culprit? You mention several different tools, but you didn't say what in particular those tools showed you, other than the total cost estimate of a LIMITed index scan which you misinterpreted.

You can use pg_stat_statements to see what queries are slow on average or in total, and "log_min_duration_statement" or better yet auto_explain to see what specific executions are slow individually.

It is not necessarily the case that your slowest query is causing all of this IO churn, but anything causing that much IO churn needs to be at least kind of slow. So your best bet is to start with the slowest ones.

  • I have edited the question, answering your queries. Also, you made me think - "This query needs buffer for some use, and it's waiting for the buffer to be released. So there might be other queries hogging the buffer available". I am now investigating in this new direction. Will update what I find. Thanks – gvatreya Jun 20 at 6:54
  • Also, this has been a recurring issue and I realized I had asked a similar question in 2017 - dba.stackexchange.com/questions/165856/… Since then I have added Prometheus monitoring etc., Vacuuming etc., and the issue has come down but not fully resolved. – gvatreya Jun 20 at 7:10

Your Answer

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

Not the answer you're looking for? Browse other questions tagged or ask your own question.