felixge / felixge/flame-explain
Incorrect total time for parallel append plan
- 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.

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