felixge / felixge/flame-explain

Incorrect total time for parallel append plan

Open
#15 0 comments 0 reactions 0 assignees View on GitHub
🐞bug
Dominant language
TypeScript
Stars
55
Forks
5
PR merge metrics
No merged PRs in 30d

Description

In the plan below the index scan on repo is looped over 200k times, but it doesn't get taken into account into the total time calculation.

Screenshot 2020-10-11 at 15 32 15

```json
[
{
"Plan": {
"Node Type": "Unique",
"Parallel Aware": false,
"Startup Cost": 493708.62,
"Total Cost": 495830.95,
"Plan Rows": 424465,
"Plan Width": 39,
"Actual Startup Time": 401.436,
"Actual Total Time": 459.491,
"Actual Rows": 206400,
"Actual Loops": 1,
"Output": ["repo.id", "repo.name"],
"Shared Hit Blocks": 826581,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 1248,
"Temp Written Blocks": 1253,
"Plans": [
{
"Node Type": "Sort",
"Parent Relationship": "Outer",
"Parallel Aware": false,
"Startup Cost": 493708.62,
"Total Cost": 494769.79,
"Plan Rows": 424465,
"Plan Width": 39,
"Actual Startup Time": 401.434,
"Actual Total Time": 424.931,
"Actual Rows": 206400,
"Actual Loops": 1,
"Output": ["repo.id", "repo.name"],
"Sort Key": ["repo.id"],
"Sort Method": "external merge",
"Sort Space Used": 9984,
"Sort Space Type": "Disk",
"Shared Hit Blocks": 826581,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 1248,
"Temp Written Blocks": 1253,
"Plans": [
{
"Node Type": "Gather",
"Parent Relationship": "Outer",
"Parallel Aware": false,
"Startup Cost": 1000.43,
"Total Cost": 447231.30,
"Plan Rows": 424465,
"Plan Width": 39,
"Actual Startup Time": 0.402,
"Actual Total Time": 308.246,
"Actual Rows": 206400,
"Actual Loops": 1,
"Output": ["repo.id", "repo.name"],
"Workers Planned": 2,
"Workers Launched": 2,
"Single Copy": false,
"Shared Hit Blocks": 826581,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"Plans": [
{
"Node Type": "Nested Loop",
"Parent Relationship": "Outer",
"Parallel Aware": false,
"Join Type": "Inner",
"Startup Cost": 0.43,
"Total Cost": 403784.80,
"Plan Rows": 176860,
"Plan Width": 39,
"Actual Startup Time": 0.079,
"Actual Total Time": 308.420,
"Actual Rows": 68800,
"Actual Loops": 3,
"Output": ["repo.id", "repo.name"],
"Inner Unique": true,
"Shared Hit Blocks": 826581,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"Workers": [
{
"Worker Number": 0,
"Actual Startup Time": 0.077,
"Actual Total Time": 332.087,
"Actual Rows": 68021,
"Actual Loops": 1,
"Shared Hit Blocks": 272406,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0
},
{
"Worker Number": 1,
"Actual Startup Time": 0.121,
"Actual Total Time": 330.452,
"Actual Rows": 67647,
"Actual Loops": 1,
"Shared Hit Blocks": 270910,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0
}
],
"Plans": [
{
"Node Type": "Append",
"Parent Relationship": "Outer",
"Parallel Aware": true,
"Startup Cost": 0.00,
"Total Cost": 60183.72,
"Plan Rows": 304141,
"Plan Width": 4,
"Actual Startup Time": 0.034,
"Actual Total Time": 13.134,
"Actual Rows": 68805,
"Actual Loops": 3,
"Shared Hit Blocks": 915,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"Workers": [
{
"Worker Number": 0,
"Actual Startup Time": 0.026,
"Actual Total Time": 13.295,
"Actual Rows": 68026,
"Actual Loops": 1,
"Shared Hit Blocks": 301,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0
},
{
"Worker Number": 1,
"Actual Startup Time": 0.067,
"Actual Total Time": 13.102,
"Actual Rows": 67652,
"Actual Loops": 1,
"Shared Hit Blocks": 301,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0
}
],
"Subplans Removed": 0,
"Plans": [
{
"Node Type": "Nested Loop",
"Parent Relationship": "Member",
"Parallel Aware": false,
"Join Type": "Inner",
"Startup Cost": 0.43,
"Total Cost": 54989.76,
"Plan Rows": 218144,
"Plan Width": 4,
"Actual Startup Time": 0.042,
"Actual Total Time": 0.043,
"Actual Rows": 0,
"Actual Loops": 1,
"Output": ["esr.repo_id"],
"Inner Unique": false,
"Shared Hit Blocks": 1,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"Workers": [
{
"Worker Number": 1,
"Actual Startup Time": 0.042,
"Actual Total Time": 0.043,
"Actual Rows": 0,
"Actual Loops": 1,
"Shared Hit Blocks": 1,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0
}
],
"Plans": [
{
"Node Type": "Seq Scan",
"Parent Relationship": "Outer",
"Parallel Aware": false,
"Relation Name": "external_services",
"Schema": "public",
"Alias": "es",
"Startup Cost": 0.00,
"Total Cost": 1.17,
"Plan Rows": 1,
"Plan Width": 8,
"Actual Startup Time": 0.042,
"Actual Total Time": 0.042,
"Actual Rows": 0,
"Actual Loops": 1,
"Output": ["es.id", "es.kind", "es.display_name", "es.config", "es.created_at", "es.updated_at", "es.deleted_at", "es.last_sync_at", "es.next_sync_at", "es.namespace_user_id"],
"Filter": "((es.namespace_user_id IS NOT NULL) AND (es.deleted_at IS NULL))",
"Rows Removed by Filter": 19,
"Shared Hit Blocks": 1,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"Workers": [
{
"Worker Number": 1,
"Actual Startup Time": 0.042,
"Actual Total Time": 0.042,
"Actual Rows": 0,
"Actual Loops": 1,
"Shared Hit Blocks": 1,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0
}
]
},
{
"Node Type": "Index Scan",
"Parent Relationship": "Inner",
"Parallel Aware": false,
"Scan Direction": "Forward",
"Index Name": "external_service_repos_external_service_id",
"Relation Name": "external_service_repos",
"Schema": "public",
"Alias": "esr",
"Startup Cost": 0.43,
"Total Cost": 45717.49,
"Plan Rows": 927110,
"Plan Width": 12,
"Actual Startup Time": 0.000,
"Actual Total Time": 0.000,
"Actual Rows": 0,
"Actual Loops": 0,
"Output": ["esr.external_service_id", "esr.repo_id", "esr.clone_url"],
"Index Cond": "(esr.external_service_id = es.id)",
"Rows Removed by Index Recheck": 0,
"Shared Hit Blocks": 0,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0
}
]
},
{
"Node Type": "Seq Scan",
"Parent Relationship": "Member",
"Parallel Aware": true,
"Relation Name": "default_repos",
"Schema": "public",
"Alias": "default_repos",
"Startup Cost": 0.00,
"Total Cost": 2128.07,
"Plan Rows": 121407,
"Plan Width": 4,
"Actual Startup Time": 0.019,
"Actual Total Time": 7.100,
"Actual Rows": 68805,
"Actual Loops": 3,
"Output": ["default_repos.repo_id"],
"Shared Hit Blocks": 914,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"Workers": [
{
"Worker Number": 0,
"Actual Startup Time": 0.025,
"Actual Total Time": 7.332,
"Actual Rows": 68026,
"Actual Loops": 1,
"Shared Hit Blocks": 301,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0
},
{
"Worker Number": 1,
"Actual Startup Time": 0.023,
"Actual Total Time": 7.169,
"Actual Rows": 67652,
"Actual Loops": 1,
"Shared Hit Blocks": 300,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0
}
]
}
]
},
{
"Node Type": "Index Scan",
"Parent Relationship": "Inner",
"Parallel Aware": false,
"Scan Direction": "Forward",
"Index Name": "repo_pkey",
"Relation Name": "repo",
"Schema": "public",
"Alias": "repo",
"Startup Cost": 0.43,
"Total Cost": 1.13,
"Plan Rows": 1,
"Plan Width": 39,
"Actual Startup Time": 0.004,
"Actual Total Time": 0.004,
"Actual Rows": 1,
"Actual Loops": 206416,
"Output": ["repo.name", "repo.description", "repo.language", "repo.fork", "repo.created_at", "repo.updated_at", "repo.id", "repo.external_id", "repo.external_service_type", "repo.external_service_id", "repo.archived", "repo.uri", "repo.deleted_at", "repo.metadata", "repo.private", "repo.cloned"],
"Index Cond": "(repo.id = esr.repo_id)",
"Rows Removed by Index Recheck": 0,
"Filter": "(repo.deleted_at IS NULL)",
"Rows Removed by Filter": 0,
"Shared Hit Blocks": 825666,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"Workers": [
{
"Worker Number": 0,
"Actual Startup Time": 0.004,
"Actual Total Time": 0.004,
"Actual Rows": 1,
"Actual Loops": 68026,
"Shared Hit Blocks": 272105,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0
},
{
"Worker Number": 1,
"Actual Startup Time": 0.004,
"Actual Total Time": 0.004,
"Actual Rows": 1,
"Actual Loops": 67652,
"Shared Hit Blocks": 270609,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0
}
]
}
]
}
]
}
]
}
]
},
"Planning Time": 0.294,
"Triggers": [
],
"Execution Time": 472.892
}
]
```

```
EXPLAIN (ANALYZE, FORMAT JSON, VERBOSE, BUFFERS)
SELECT DISTINCT ON(repo.id) repo.id, repo.name
FROM repo
JOIN LATERAL (
SELECT esr.repo_id
FROM external_service_repos esr
JOIN external_services es ON es.id = esr.external_service_id
WHERE
es.namespace_user_id IS NOT NULL AND
es.deleted_at IS NULL
UNION ALL
SELECT repo_id
FROM default_repos
) repo_ids ON repo.id = repo_ids.repo_id
WHERE
repo.deleted_at IS NULL;
```

Contributor guide

Open the contributing guide

Research direction

Start by examining how the visualizer calculates total time for the supplied PostgreSQL EXPLAIN ANALYZE plan, focusing on the parallel Append, nested loop, and the repo index scan's Actual Loops value. Done means the repeated scan contributes correctly to the displayed total time for this plan.

Written by the indexing model from the issue text.

Assessment

Tech stack
postgresql, typescript
Domain
data-visualization, databases
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Mostly clear
Newbie friendliness
35/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.