Sample Header Ad - 728x90

Postgres 13/14 JIT execution increase execution time of query considerably

4 votes
1 answer
1946 views
I have a complex DB query that I run on different systems with identical specs, but different OS (CentOS7 vs. Debian 11). The Postgres version is 13.7, but I also tried with 14.4. I get vastly different execution times for the query on both systems (9s). CentOS (removed all never executed blocks for brevity):
[
  {
    "Plan": {
      "Node Type": "Nested Loop",
      "Parallel Aware": false,
      "Join Type": "Inner",
      "Startup Cost": 34432047.36,
      "Total Cost": 34432049.49,
      "Plan Rows": 1,
      "Plan Width": 32,
      "Actual Startup Time": 0.012,
      "Actual Total Time": 0.034,
      "Actual Rows": 0,
      "Actual Loops": 1,
      "Output": [...],
      "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,
      "Plans": [
        {
          "Node Type": "Nested Loop",
          "Parent Relationship": "Outer",
          "Parallel Aware": false,
          "Join Type": "Left",
          "Startup Cost": 92.30,
          "Total Cost": 94.39,
          "Plan Rows": 1,
          "Plan Width": 88,
          "Actual Startup Time": 0.012,
          "Actual Total Time": 0.027,
          "Actual Rows": 0,
          "Actual Loops": 1,
          "Output": [...],
          "Inner Unique": false,
          "Join Filter": "(acg.id = \"activityConflictGroup\".id)",
          "Rows Removed by Join Filter": 0,
          "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": "activity_conflict_group",
              "Schema": "production",
              "Alias": "activityConflictGroup",
              "Startup Cost": 0.00,
              "Total Cost": 1.01,
              "Plan Rows": 1,
              "Plan Width": 56,
              "Actual Startup Time": 0.012,
              "Actual Total Time": 0.012,
              "Actual Rows": 0,
              "Actual Loops": 1,
              "Output": [...],
              "Filter": "(\"activityConflictGroup\".state = 'ACTIVE'::text)",
              "Rows Removed by Filter": 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
               ...
    "Planning": {
      "Shared Hit Blocks": 4428,
      "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": 60.923,
    "Triggers": [
    ],
    "Execution Time": 2.081
  }
]
Debian (removed all never executed blocks for brevity):
[
  {
    "Plan": {
      "Node Type": "Nested Loop",
      "Parallel Aware": false,
      "Join Type": "Inner",
      "Startup Cost": 13844811.29,
      "Total Cost": 13844814.63,
      "Plan Rows": 1,
      "Plan Width": 32,
      "Actual Startup Time": 9462.994,
      "Actual Total Time": 9463.419,
      "Actual Rows": 0,
      "Actual Loops": 1,
      "Output": [...],
      "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,
      "Plans": [
        {
          "Node Type": "Nested Loop",
          "Parent Relationship": "Outer",
          "Parallel Aware": false,
          "Join Type": "Left",
          "Startup Cost": 268.43,
          "Total Cost": 271.73,
          "Plan Rows": 1,
          "Plan Width": 72,
          "Actual Startup Time": 9462.992,
          "Actual Total Time": 9463.058,
          "Actual Rows": 0,
          "Actual Loops": 1,
          "Output": [...],
          "Inner Unique": false,
          "Join Filter": "(acg.id = \"activityConflictGroup\".id)",
          "Rows Removed by Join Filter": 0,
          "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": "activity_conflict_group",
              "Schema": "production",
              "Alias": "activityConflictGroup",
              "Startup Cost": 0.00,
              "Total Cost": 1.01,
              "Plan Rows": 1,
              "Plan Width": 40,
              "Actual Startup Time": 9462.990,
              "Actual Total Time": 9462.991,
              "Actual Rows": 0,
              "Actual Loops": 1,
              "Output": [...],
              "Filter": "(\"activityConflictGroup\".state = 'ACTIVE'::text)",
              "Rows Removed by Filter": 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
            },
            ...
    "Planning": {
      "Shared Hit Blocks": 5017,
      "Shared Read Blocks": 199,
      "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": 136.644,
    "Triggers": [
    ],
    "JIT": {
      "Functions": 1359,
      "Options": {
        "Inlining": true,
        "Optimization": true,
        "Expressions": true,
        "Deforming": true
      },
      "Timing": {
        "Generation": 129.432,
        "Inlining": 61.619,
        "Optimization": 5772.102,
        "Emission": 3625.487,
        "Total": 9588.641
      }
    },
    "Execution Time": 9635.694
  }
]
The main difference I see is that the Debian query is using JIT compilation. Both systems use the standard PG 13.7 settings and so conf key jit is set to on. However, SELECT pg_jit_available(); show that JIT is only available on the Debian system. It took me a while to find this out. The plan shows that JIT is adding roughly 9.5s to the whole query time. My "workaround" is to turn off JIT for the server. This really confuses me. Is this a number I have to expect or is the JIT setup on Debian messed up? Maybe I'm looking at an edge case here, because the query is very complex on paper, but turns out to be very simple because of the data in the DB. So my question is, if this is an expected behaviour and what to do about it to get it faster. My workaround of turning JIT off seems to be not optimal.
Asked by spa (223 rep)
Jul 21, 2022, 02:40 PM
Last activity: Jul 26, 2022, 09:20 AM