0

I'm working with postgres 13.9 on Amazon Aurora. In our production environment, we're running a query that is taking >15 seconds to run when the query is using a small LIMIT. For example when the query is being run with LIMIT 1, we see the following result

Limit  (cost=1.54..2608.50 rows=1 width=1100) (actual time=17945.422..17945.424 rows=1 loops=1)
  Output: tasks.id, tasks.name, tasks.description, tasks.priority, tasks.estimated_hours, tasks.sort_order, tasks.estimated_points, tasks.responsibility, tasks.sign_off_required, tasks.created_at, tasks.updated_at, tasks.milestone_id, tasks.status, tasks.sign_off_user_id, tasks.assignee_id, tasks.creator_id, tasks.start_on, tasks.due_on, tasks.project_id, tasks.template_id, tasks.actual_hours, tasks.deleted_at, tasks.assignment_email_sent_at, tasks.stuck_message, tasks.overdue_pm_reminder_sent_at, tasks.duration, tasks.dependency_type, tasks.dependency_id, tasks.last_activity_at, tasks.completed_at, tasks.overdue_watched_tasks_email_sent_at, tasks.task_type, tasks.must_start_on, tasks.must_start_on_required, tasks.must_start_on_email_sent_at, tasks.visibility, tasks.type, tasks.related_task_id, tasks.action_items_count, tasks.open_action_items_count, tasks.billable_hours, tasks.non_billable_hours, tasks.jira_sync, tasks.public_id, tasks.event_details, tasks.blueprint_task_id, tasks.task_group_id
  ->  Merge Semi Join  (cost=1.54..60650907.42 rows=23265 width=1100) (actual time=17945.420..17945.422 rows=1 loops=1)
        Output: tasks.id, tasks.name, tasks.description, tasks.priority, tasks.estimated_hours, tasks.sort_order, tasks.estimated_points, tasks.responsibility, tasks.sign_off_required, tasks.created_at, tasks.updated_at, tasks.milestone_id, tasks.status, tasks.sign_off_user_id, tasks.assignee_id, tasks.creator_id, tasks.start_on, tasks.due_on, tasks.project_id, tasks.template_id, tasks.actual_hours, tasks.deleted_at, tasks.assignment_email_sent_at, tasks.stuck_message, tasks.overdue_pm_reminder_sent_at, tasks.duration, tasks.dependency_type, tasks.dependency_id, tasks.last_activity_at, tasks.completed_at, tasks.overdue_watched_tasks_email_sent_at, tasks.task_type, tasks.must_start_on, tasks.must_start_on_required, tasks.must_start_on_email_sent_at, tasks.visibility, tasks.type, tasks.related_task_id, tasks.action_items_count, tasks.open_action_items_count, tasks.billable_hours, tasks.non_billable_hours, tasks.jira_sync, tasks.public_id, tasks.event_details, tasks.blueprint_task_id, tasks.task_group_id
        Merge Cond: (tasks.id = t0.id)
        ->  Index Scan using tasks_pkey on public.tasks  (cost=0.56..14315808.88 rows=11401481 width=1100) (actual time=0.054..4908.126 rows=2722000 loops=1)
              Output: tasks.id, tasks.name, tasks.description, tasks.priority, tasks.estimated_hours, tasks.sort_order, tasks.estimated_points, tasks.responsibility, tasks.sign_off_required, tasks.created_at, tasks.updated_at, tasks.milestone_id, tasks.status, tasks.sign_off_user_id, tasks.assignee_id, tasks.creator_id, tasks.start_on, tasks.due_on, tasks.project_id, tasks.template_id, tasks.actual_hours, tasks.deleted_at, tasks.assignment_email_sent_at, tasks.stuck_message, tasks.overdue_pm_reminder_sent_at, tasks.duration, tasks.dependency_type, tasks.dependency_id, tasks.last_activity_at, tasks.completed_at, tasks.overdue_watched_tasks_email_sent_at, tasks.task_type, tasks.must_start_on, tasks.must_start_on_required, tasks.must_start_on_email_sent_at, tasks.visibility, tasks.type, tasks.related_task_id, tasks.action_items_count, tasks.open_action_items_count, tasks.billable_hours, tasks.non_billable_hours, tasks.jira_sync, tasks.public_id, tasks.event_details, tasks.blueprint_task_id, tasks.task_group_id
              Filter: ((tasks.deleted_at IS NULL) AND (tasks.milestone_id IS NOT NULL))
              Rows Removed by Filter: 650237
        ->  Nested Loop  (cost=0.98..46306291.52 rows=28266 width=8) (actual time=12863.972..12863.973 rows=1 loops=1)
              Output: t0.id
              Inner Unique: true
              ->  Index Scan using tasks_pkey on public.tasks t0  (cost=0.56..14350439.73 rows=13852340 width=16) (actual time=0.010..4179.561 rows=3372237 loops=1)
                    Output: t0.project_id, t0.id
                    Index Cond: (t0.id IS NOT NULL)
              ->  Index Scan using projects_pkey on public.projects j0  (cost=0.42..2.31 rows=1 width=8) (actual time=0.002..0.002 rows=0 loops=3372237)
                    Output: j0.id
                    Index Cond: (j0.id = t0.project_id)
                    Filter: (j0.organization_id = 79403)
                    Rows Removed by Filter: 1
Planning Time: 0.914 ms
Execution Time: 17945.475 ms

The same query, being run with LIMIT 500, has the following explanation:

Limit  (cost=322268.59..322269.84 rows=500 width=1100) (actual time=1329.805..1330.032 rows=500 loops=1)
  Output: tasks.id, tasks.name, tasks.description, tasks.priority, tasks.estimated_hours, tasks.sort_order, tasks.estimated_points, tasks.responsibility, tasks.sign_off_required, tasks.created_at, tasks.updated_at, tasks.milestone_id, tasks.status, tasks.sign_off_user_id, tasks.assignee_id, tasks.creator_id, tasks.start_on, tasks.due_on, tasks.project_id, tasks.template_id, tasks.actual_hours, tasks.deleted_at, tasks.assignment_email_sent_at, tasks.stuck_message, tasks.overdue_pm_reminder_sent_at, tasks.duration, tasks.dependency_type, tasks.dependency_id, tasks.last_activity_at, tasks.completed_at, tasks.overdue_watched_tasks_email_sent_at, tasks.task_type, tasks.must_start_on, tasks.must_start_on_required, tasks.must_start_on_email_sent_at, tasks.visibility, tasks.type, tasks.related_task_id, tasks.action_items_count, tasks.open_action_items_count, tasks.billable_hours, tasks.non_billable_hours, tasks.jira_sync, tasks.public_id, tasks.event_details, tasks.blueprint_task_id, tasks.task_group_id
  ->  Sort  (cost=322268.59..322326.76 rows=23266 width=1100) (actual time=1329.803..1329.989 rows=500 loops=1)
        Output: tasks.id, tasks.name, tasks.description, tasks.priority, tasks.estimated_hours, tasks.sort_order, tasks.estimated_points, tasks.responsibility, tasks.sign_off_required, tasks.created_at, tasks.updated_at, tasks.milestone_id, tasks.status, tasks.sign_off_user_id, tasks.assignee_id, tasks.creator_id, tasks.start_on, tasks.due_on, tasks.project_id, tasks.template_id, tasks.actual_hours, tasks.deleted_at, tasks.assignment_email_sent_at, tasks.stuck_message, tasks.overdue_pm_reminder_sent_at, tasks.duration, tasks.dependency_type, tasks.dependency_id, tasks.last_activity_at, tasks.completed_at, tasks.overdue_watched_tasks_email_sent_at, tasks.task_type, tasks.must_start_on, tasks.must_start_on_required, tasks.must_start_on_email_sent_at, tasks.visibility, tasks.type, tasks.related_task_id, tasks.action_items_count, tasks.open_action_items_count, tasks.billable_hours, tasks.non_billable_hours, tasks.jira_sync, tasks.public_id, tasks.event_details, tasks.blueprint_task_id, tasks.task_group_id
        Sort Key: tasks.id
        Sort Method: top-N heapsort  Memory: 444kB
        ->  Nested Loop  (cost=218419.30..321109.27 rows=23266 width=1100) (actual time=563.649..1313.910 rows=20876 loops=1)
              Output: tasks.id, tasks.name, tasks.description, tasks.priority, tasks.estimated_hours, tasks.sort_order, tasks.estimated_points, tasks.responsibility, tasks.sign_off_required, tasks.created_at, tasks.updated_at, tasks.milestone_id, tasks.status, tasks.sign_off_user_id, tasks.assignee_id, tasks.creator_id, tasks.start_on, tasks.due_on, tasks.project_id, tasks.template_id, tasks.actual_hours, tasks.deleted_at, tasks.assignment_email_sent_at, tasks.stuck_message, tasks.overdue_pm_reminder_sent_at, tasks.duration, tasks.dependency_type, tasks.dependency_id, tasks.last_activity_at, tasks.completed_at, tasks.overdue_watched_tasks_email_sent_at, tasks.task_type, tasks.must_start_on, tasks.must_start_on_required, tasks.must_start_on_email_sent_at, tasks.visibility, tasks.type, tasks.related_task_id, tasks.action_items_count, tasks.open_action_items_count, tasks.billable_hours, tasks.non_billable_hours, tasks.jira_sync, tasks.public_id, tasks.event_details, tasks.blueprint_task_id, tasks.task_group_id
              Inner Unique: true
              ->  HashAggregate  (cost=218418.74..218701.41 rows=28267 width=8) (actual time=563.618..570.523 rows=21926 loops=1)
                    Output: t0.id
                    Group Key: t0.id
                    Batches: 1  Memory Usage: 2065kB
                    ->  Gather  (cost=1000.56..218348.08 rows=28267 width=8) (actual time=1.032..553.590 rows=21926 loops=1)
                          Output: t0.id
                          Workers Planned: 2
                          Workers Launched: 2
                          ->  Nested Loop  (cost=0.56..214521.38 rows=11778 width=8) (actual time=1.020..522.937 rows=7309 loops=3)
                                Output: t0.id
                                Worker 0:  actual time=2.356..510.679 rows=7819 loops=1
                                Worker 1:  actual time=0.063..537.921 rows=7849 loops=1
                                ->  Parallel Seq Scan on public.projects j0  (cost=0.00..53613.72 rows=417 width=8) (actual time=0.515..68.601 rows=220 loops=3)
                                      Output: j0.id
                                      Filter: (j0.organization_id = 79403)
                                      Rows Removed by Filter: 90977
                                      Worker 0:  actual time=0.885..109.155 rows=225 loops=1
                                      Worker 1:  actual time=0.034..37.727 rows=212 loops=1
                                ->  Index Scan using index_tasks_on_project_id on public.tasks t0  (cost=0.56..384.30 rows=157 width=16) (actual time=0.886..2.059 rows=33 loops=660)
                                      Output: t0.project_id, t0.id
                                      Index Cond: (t0.project_id = j0.id)
                                      Filter: (t0.id IS NOT NULL)
                                      Worker 0:  actual time=0.698..1.778 rows=35 loops=225
                                      Worker 1:  actual time=0.960..2.353 rows=37 loops=212
              ->  Index Scan using tasks_pkey on public.tasks  (cost=0.56..3.63 rows=1 width=1100) (actual time=0.033..0.033 rows=1 loops=21926)
                    Output: tasks.id, tasks.name, tasks.description, tasks.priority, tasks.estimated_hours, tasks.sort_order, tasks.estimated_points, tasks.responsibility, tasks.sign_off_required, tasks.created_at, tasks.updated_at, tasks.milestone_id, tasks.status, tasks.sign_off_user_id, tasks.assignee_id, tasks.creator_id, tasks.start_on, tasks.due_on, tasks.project_id, tasks.template_id, tasks.actual_hours, tasks.deleted_at, tasks.assignment_email_sent_at, tasks.stuck_message, tasks.overdue_pm_reminder_sent_at, tasks.duration, tasks.dependency_type, tasks.dependency_id, tasks.last_activity_at, tasks.completed_at, tasks.overdue_watched_tasks_email_sent_at, tasks.task_type, tasks.must_start_on, tasks.must_start_on_required, tasks.must_start_on_email_sent_at, tasks.visibility, tasks.type, tasks.related_task_id, tasks.action_items_count, tasks.open_action_items_count, tasks.billable_hours, tasks.non_billable_hours, tasks.jira_sync, tasks.public_id, tasks.event_details, tasks.blueprint_task_id, tasks.task_group_id
                    Index Cond: (tasks.id = t0.id)
                    Filter: ((tasks.deleted_at IS NULL) AND (tasks.milestone_id IS NOT NULL))
                    Rows Removed by Filter: 0
Planning Time: 0.872 ms
Execution Time: 1330.691 ms

Correct me if I'm wrong, but the culprit is the query planner for choosing such an inefficient query plan with a small LIMIT. Since the query planner uses the pg_statistics to make its execution plans, we believed our statistics to be invalid. In checking it out, we determined that running VACUUM(FULL, ANALYZE, VERBOSE) would be the best solution for us. If you use this command, be cautious. It can take a while and will lock the database tables temporarily. This updated the statistics, but the query planner is still choosing an incorrect execution plan.

I'd love to understand why the query planner is choosing such an inefficient plan and how this could be resolved.

Improve this question
0

1 Answer 1

Reset to default
2

The planner thinks that the rows it finds meeting the conditions will be randomly distributed along the tasks.id ordering. So by finding them already in order it thinks it can stop after the first row out of 23265, which mean it only needs to do about 1/23265 of the full amount of work. In reality it had to scan about 3372237/13852340, or 1/4, of the tasks table before finding the first match. So it is off by almost 6000 fold. This "random ordering" is simply an assumption. It is not driven by planner stats, so stats cannot help fix it.

Why do the first 1/4 of all tasks have no projects? Maybe they can get archived or something.

You can usually "fix" this sort of thing by changing the ORDER BY into something which can't be fulfilled by use of an index, like ORDER BY tasks.id+0

Improve this answer
2
  • I won't get into the business details, but it suffices to say that it makes sense that a quarter of the tasks don't have a project. I tested your fix and it did work. Thank you for that. Unfortunately, this doesn't address the root problem of the query planner. Do you have any insights on why the query planner is drawing inaccurate conclusions? Or do you have any advice on how to further investigate the issue?
    – kylejw2
    Commented Aug 14, 2023 at 16:53
  • 1
    The problem is not that 1/4 don't have projects, the problem is that that 1/4 are all at one end of the ORDER BY. As I said, it simply assumes the qualifying rows are randomly scattered long the ORDER dimension, it is not really an estimation, just an assumption. This pro-rating is implemented in adjust_limit_rows_costs, so you could comment out those call sites if you wanted.
    – jjanes
    Commented Aug 14, 2023 at 21:00

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

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