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

All we need is an easy explanation of the problem, so here it is.

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 (<200ms vs. >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.

How to solve :

I know you bored from this bug, So we are here to help you! Take a deep breath and look at the explanation of your problem. We have many solutions to this problem, But we recommend you to use the first method because it is tested & true method that will 100% work for you.

Method 1

After the helpful comments and more research it seems that JIT should be turned off as in case of my workload decreases performance. The added time is due to the compile/optimize cycle and is added to each execution as the compilation results can’t be cached. This applies to PostgreSQL 12/13/14.

Note: Use and implement method 1 because this method fully tested our system.
Thank you 🙂

All methods was sourced from stackoverflow.com or stackexchange.com, is licensed under cc by-sa 2.5, cc by-sa 3.0 and cc by-sa 4.0

Leave a Reply