Postgres 10 Query waits on IO: BufFileWrite causing failure to get new database connections

Question

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)

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.

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

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.
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.
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.

Edited to add solution:

The backend team re-wrote the sql query and the performance improved. This brought down the query execution time to milliseconds.

Answer 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.

Answer 2

I made tables and queries from your situation. Even though they are not the same as yours, it will be helpful to solve the issue.

create table students
(student_id integer,
 student_name varchar(100));

create table student_point
(student_id integer,
 exam_seq   integer,
 points     integer
);
create index idx_student_point_02 on student_point(exam_seq,student_id);

create table check_in_table
( check_dt timestamp,
  house_no integer,
  student_id integer
);
create index idx_check_in_table_01 on check_in_table(house_no,check_dt);

create table intervention_table
(student_id integer,
 intervention_date timestamp,
 intervention_type varchar(1));
 
create index idx_test on intervention_table(student_id,intervention_date, intervention_type);

-- insert sample data
insert into students
with ch as 
(
    select chr(i+96) as c from generate_series(1,25) i
)
select row_number() over() as student_id, 
       c1||c2||c3 as student_name
from 
(select c c1 from ch) a,
(select c c2 from ch) b,
(select c c3 from ch) c,
(select i from generate_series(1,50) i) d;
commit;

insert into student_point
select student_id, row_number() over(partition by student_id) as exam_seq, trunc(random() * 100+1) as points
from students, ( select i from generate_series(1,5) i) j;
commit;

--For invention_table data, I lost sql scripts. sorry :(

--10 second delay
select pg_sleep(10);

--the numbers below are just random : I just want to show numbers in no order.  I executed these insert queries repeatedly.
insert into check_in_table 
select now() as check_dt, trunc(random() * 10+1) as room_no, student_id 
from students
where student_id between ( select trunc(random()*5733) as student_id ) and ( select trunc(random()*23467) as student_id )
limit 32231;
commit;

select pg_sleep(10);

insert into check_in_table 
select now() as check_dt, trunc(random() * 10+1) as room_no, student_id 
from students
where student_id between ( select trunc(random()*15801) as student_id ) and ( select trunc(random()*35154) as student_id )
limit 14332;
commit;

select pg_sleep(10);

insert into check_in_table 
select now() as check_dt, trunc(random() * 10+1) as room_no, student_id 
from students
where student_id between ( select trunc(random()*98752) as student_id ) and ( select trunc(random()*112506) as student_id )
limit 24233;
commit;

select pg_sleep(10);

insert into check_in_table 
select now() as check_dt, trunc(random() * 10+1) as room_no, student_id 
from students
where student_id between ( select trunc(random()*551500) as student_id ) and ( select trunc(random()*570000) as student_id )
limit 14391;
commit;

--query before tuning : really slow and causing a heavy cpu load & buffwrite for a long time 
SELECT SUM(points) points
      ,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(exam_seq), sum(sp.points) as points
            FROM 
            (
                SELECT 
                    student_id 
                FROM 
                    check_in_table 
                WHERE 
                  house_no = 1
                AND 
                    check_dt> '2020-07-08 12:44:47' AND check_dt<= '2020-07-08 12:44:57'
                GROUP BY student_id
            ) 
            checkins 
        LEFT JOIN 
            students 
        ON 
            checkins.student_id = students.student_id 
        LEFT JOIN 
            student_point sp
        ON 
            checkins.student_id = sp.student_id 
        LEFT JOIN 
            (
                select record_id, student_id, intervention_type, intervention_date
                FROM intervention_table i1
                WHERE (student_id, intervention_date) in 
                     (
                        SELECT student_id, MAX(intervention_date) 
                        FROM intervention_table 
                        GROUP BY student_id
                     )   
            ) AS intercepts 
        ON 
            checkins.student_id = intercepts.student_id 
        GROUP BY 
            checkins.student_id, intercepts.intervention_type
    ) AS result 
WHERE 
    max IN 
        (
            SELECT 
                exam_seq 
            FROM 
                student_point 
            ORDER BY 
                exam_seq DESC LIMIT 1
        ) 
        OR 
    max ISNULL;


--query after tuning
with checkins as
(   
    SELECT student_id 
    FROM 
        check_in_table 
    WHERE 
      house_no = 1
    AND 
        check_dt> '2020-07-08 12:44:47' AND check_dt<= '2020-07-08 12:44:57'
    GROUP BY student_id
)
SELECT SUM(points) points
      ,SUM(CASE WHEN intervention_type::INT = 2 OR intervention_type::INT = 3 THEN 1 ELSE 0 END) attention 
FROM 
    (
        SELECT /*+ Leading(checkins students) */
            checkins.student_id, intercepts.intervention_type ,max(exam_seq), sum(sp.points) as points
        FROM checkins 
        LEFT JOIN 
            students 
        ON 
            checkins.student_id = students.student_id 
        LEFT JOIN 
            student_point sp
        ON 
            checkins.student_id = sp.student_id 
        LEFT JOIN 
            (
                select record_id, student_id, intervention_type, intervention_date
                FROM intervention_table i1
                WHERE (student_id,intervention_date) in 
                     (
                        SELECT  i2.student_id, MAX(intervention_date) 
                        FROM intervention_table i2
                            ,checkins           c
                        WHERE i2.student_id = c.student_id
                        GROUP BY i2.student_id
                     )   
            ) AS intercepts 
        ON 
            checkins.student_id = intercepts.student_id 
        GROUP BY 
            checkins.student_id, intercepts.intervention_type
    ) AS result 
WHERE 
    max IN 
        (
            SELECT 
                exam_seq 
            FROM 
                student_point 
            ORDER BY 
                exam_seq DESC LIMIT 1
        ) 
        OR 
    max ISNULL;

Answer 3

I think it may be the main problem of query, because there is no condition with sutdent_id from student tables when selecting data from intervention_table: I mean IN ( SELECT MAX.... ) <-- In this query block, external condition student_id can't come in and join: To get lastest intervention_date, seq scan is operated. Besides, in explain plan, this table has 2,282,125 rows. BuffileWrite is inevitable! (I'll upload the test case based on your situations later.)

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
                    );

In the explain plan, there are 560,000 rows from intervention table
  ->  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
 

I suggest window functions for intervention_table and join check in table before group by operation.

select *
from (
select student_id,.., rownumber() over (partition by student_id order by internvention_date desc) as rn 
from check_in_table left join intervention_table on student_id=..student_id..
) where rn=1