Need help understanding Postgresql query execution

Question

I have a generated query from an ORM that selects data from a nested join on a junction table.
When executing it looks like it performs a full table scan on a table with >55 million records resulting in a slow execution time.
My expectation was that it would perform the filtering first then lookup by index for the join.

Here is the query: (additional columns have been removed for brevity)

SELECT
   e."SnapshotId" 
FROM
   "EFACSnapshot" AS e 
   LEFT JOIN
      (
         SELECT
            e0."SnapshotId" 
         FROM
            "EFACSnapshotVector3" AS e0 
            INNER JOIN
               "Vector3" AS v3 
               ON e0."Vector3Id" = v3."Vector3Id" 
      )
      AS t 
      ON e."SnapshotId" = t."SnapshotId" 
WHERE
   e."ClientId" = 386707

Query Plan

[
  {
    "Plan": {
      "Node Type": "Hash Join",
      "Join Type": "Right",
      "Startup Cost": 1814295.06,
      "Total Cost": 2160533.66,
      "Plan Rows": 6020,
      "Plan Width": 4,
      "Actual Startup Time": 97144.904,
      "Actual Total Time": 111542.936,
      "Actual Rows": 155,
      "Actual Loops": 1,
      "Output": [
        "e.\"SnapshotId\""
      ],
      "Hash Cond": "(e0.\"SnapshotId\" = e.\"SnapshotId\")",
      "Shared Hit Blocks": 2,
      "Shared Read Blocks": 358552,
      "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": 163599,
      "Temp Written Blocks": 163473,
      "Plans": [
        {
          "Node Type": "Hash Join",
          "Parent Relationship": "Outer",
          "Join Type": "Inner",
          "Startup Cost": 1811166.81,
          "Total Cost": 2152829.01,
          "Plan Rows": 1204320,
          "Plan Width": 4,
          "Actual Startup Time": 94371.544,
          "Actual Total Time": 110790.36,
          "Actual Rows": 1204320,
          "Actual Loops": 1,
          "Output": [
            "e0.\"SnapshotId\""
          ],
          "Hash Cond": "(e0.\"Vector3Id\" = v3.\"Vector3Id\")",
          "Shared Hit Blocks": 2,
          "Shared Read Blocks": 358548,
          "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": 163599,
          "Temp Written Blocks": 163473,
          "Plans": [
            {
              "Node Type": "Seq Scan",
              "Parent Relationship": "Outer",
              "Relation Name": "EFACSnapshotVector3",
              "Schema": "public",
              "Alias": "e0",
              "Startup Cost": 0,
              "Total Cost": 18553.2,
              "Plan Rows": 1204320,
              "Plan Width": 8,
              "Actual Startup Time": 0.007,
              "Actual Total Time": 1936.546,
              "Actual Rows": 1204320,
              "Actual Loops": 1,
              "Output": [
                "e0.\"Vector3Id\"",
                "e0.\"SnapshotId\""
              ],
              "Shared Hit Blocks": 1,
              "Shared Read Blocks": 6509,
              "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": "Hash",
              "Parent Relationship": "Inner",
              "Startup Cost": 904608.36,
              "Total Cost": 904608.36,
              "Plan Rows": 55256836,
              "Plan Width": 4,
              "Actual Startup Time": 94369.276,
              "Actual Total Time": 94369.276,
              "Actual Rows": 55256837,
              "Actual Loops": 1,
              "Output": [
                "v3.\"Vector3Id\""
              ],
              "Hash Buckets": 262144,
              "Hash Batches": 64,
              "Original Hash Batches": 64,
              "Peak Memory Usage": 30422,
              "Shared Hit Blocks": 1,
              "Shared Read Blocks": 352039,
              "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": 159326,
              "Plans": [
                {
                  "Node Type": "Seq Scan",
                  "Parent Relationship": "Outer",
                  "Relation Name": "Vector3",
                  "Schema": "public",
                  "Alias": "v3",
                  "Startup Cost": 0,
                  "Total Cost": 904608.36,
                  "Plan Rows": 55256836,
                  "Plan Width": 4,
                  "Actual Startup Time": 0.012,
                  "Actual Total Time": 50954.107,
                  "Actual Rows": 55256837,
                  "Actual Loops": 1,
                  "Output": [
                    "v3.\"Vector3Id\""
                  ],
                  "Shared Hit Blocks": 1,
                  "Shared Read Blocks": 352039,
                  "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": "Hash",
          "Parent Relationship": "Inner",
          "Startup Cost": 3112.53,
          "Total Cost": 3112.53,
          "Plan Rows": 1257,
          "Plan Width": 4,
          "Actual Startup Time": 3.052,
          "Actual Total Time": 3.052,
          "Actual Rows": 31,
          "Actual Loops": 1,
          "Output": [
            "e.\"SnapshotId\""
          ],
          "Hash Buckets": 1024,
          "Hash Batches": 1,
          "Original Hash Batches": 1,
          "Peak Memory Usage": 2,
          "Shared Hit Blocks": 0,
          "Shared Read Blocks": 4,
          "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": "Bitmap Heap Scan",
              "Parent Relationship": "Outer",
              "Relation Name": "EFACSnapshot",
              "Schema": "public",
              "Alias": "e",
              "Startup Cost": 26.02,
              "Total Cost": 3112.53,
              "Plan Rows": 1257,
              "Plan Width": 4,
              "Actual Startup Time": 3.008,
              "Actual Total Time": 3.026,
              "Actual Rows": 31,
              "Actual Loops": 1,
              "Output": [
                "e.\"SnapshotId\""
              ],
              "Recheck Cond": "(e.\"ClientId\" = 386707)",
              "Rows Removed by Index Recheck": 0,
              "Shared Hit Blocks": 0,
              "Shared Read Blocks": 4,
              "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": "Bitmap Index Scan",
                  "Parent Relationship": "Outer",
                  "Index Name": "\"IX_EFACSnapshot_ClientId\"",
                  "Startup Cost": 0,
                  "Total Cost": 25.71,
                  "Plan Rows": 1257,
                  "Plan Width": 0,
                  "Actual Startup Time": 2.593,
                  "Actual Total Time": 2.593,
                  "Actual Rows": 31,
                  "Actual Loops": 1,
                  "Index Cond": "(e.\"ClientId\" = 386707)",
                  "Shared Hit Blocks": 0,
                  "Shared Read Blocks": 3,
                  "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
                }
              ]
            }
          ]
        }
      ]
    },
    "Triggers": [],
    "Total Runtime": 111549.609
  }
]

All referenced columns appear to have the correct foreign key and indexing setup.

Could someone explain why a full table scan is being performed and how I can adjust the query to prevent that?

Thanks!

can you update your query plan by the full explain analyze result : EXPLAIN (ANALYZE, COSTS, VERBOSE, BUFFERS, FORMAT JSON) — eshirvana
– eshirvana, Commented Nov 30, 2020 at 17:45
Sure thing. I thought the verbose included all of those by default — RaidMax
– RaidMax, Commented Nov 30, 2020 at 18:10

jjanes · Accepted Answer · 2020-11-30 18:55:47Z

1

JSON format is not very readable by humans, you would probably be better off with text format (the default) for your plan.

  "Plan Rows": 1257,
  "Actual Rows": 31,

So e."ClientId" = 386707 yields 40 times fewer rows than it thought it would. Which means it thinks the nested loop would be about 40 times more expensive than it actually is. It is not surprising the planner makes the wrong choice (well, assuming it is the wrong choice, we don't actually know that).

Why is that stat off by so much? Are your stats way out of date? Do a VACUUM ANALYZE on "EFACSnapshot" and see if things look better after that. If nothing changes, then I'd want to see the data select * from pg_stats where relname='EFACSnapshot' and attname='ClientId', as well as knowing the PostgreSQL version and the setting of default_statistics_target

answered Nov 30, 2020 at 18:55

jjanes

45k5 gold badges39 silver badges48 bronze badges

Sign up to request clarification or add additional context in comments.

1 Comment

RaidMax Over a year ago

Looks like VACUUM did the trick. After running it on all tables involved in the query, execution time was reduced to 300ms. Not sure what caused it to get out of date in the first place, but thanks for the insight!

Collectives™ on Stack Overflow

Need help understanding Postgresql query execution

1 Answer 1

1 Comment

Your Answer

Hot Network Questions

Collectives™ on Stack Overflow

1 Answer 1

1 Comment

Your Answer

Sign up or log in

Post as a guest

Related