Possible N+1 query problem when fetching job status.

Expected behavior

We should see only periodic queries against the WebAPI DB for job execution status.

Actual behavior

When logging is enabled, we see a constant barrage of SELECT JOB_EXECUTION_ID, KEY_NAME, TYPE_CD.... in logs.

Steps to reproduce behavior

Set up a maven profile that will enabled hibernate and jdbc debugging like so:

    <profile>
      <id>jdbc-debug</id>
      <properties>
        <logging.level.root>info</logging.level.root>
        <logging.level.org.springframework.orm>debug</logging.level.org.springframework.orm>
        <logging.level.org.springframework.jdbc>debug</logging.level.org.springframework.jdbc>
        <logging.level.org.hibernate.SQL>debug</logging.level.org.hibernate.SQL>
        <logging.level.org.springframework.jdbc.core.JdbcTemplate>debug</logging.level.org.springframework.jdbc.core.JdbcTemplate>
        <spring.jpa.show-sql>true</spring.jpa.show-sql>
      </properties>	
    </profile>

Make sure this profile is active, and you recompile your WAR. Then launch the app.
You will see this flooding the console:

2023-02-21 12:16:02.252 DEBUG http-nio-8080-exec-10 org.springframework.jdbc.core.JdbcTemplate - [] - Executing prepared SQL statement [SELECT JOB_EXECUTION_ID, KEY_NAME, TYPE_CD, STRING_VAL, DATE_VAL, LONG_VAL, DOUBLE_VAL, IDENTIFYING from webapi.BATCH_JOB_EXECUTION_PARAMS where JOB_EXECUTION_ID = ?]
2023-02-21 12:16:02.282 DEBUG http-nio-8080-exec-4 org.springframework.jdbc.core.JdbcTemplate - [] - Executing prepared SQL query
2023-02-21 12:16:02.282 DEBUG http-nio-8080-exec-4 org.springframework.jdbc.core.JdbcTemplate - [] - Executing prepared SQL statement [SELECT JOB_EXECUTION_ID, KEY_NAME, TYPE_CD, STRING_VAL, DATE_VAL, LONG_VAL, DOUBLE_VAL, IDENTIFYING from webapi.BATCH_JOB_EXECUTION_PARAMS where JOB_EXECUTION_ID = ?]
2023-02-21 12:16:02.321 DEBUG http-nio-8080-exec-10 org.springframework.jdbc.core.JdbcTemplate - [] - Executing prepared SQL query
2023-02-21 12:16:02.321 DEBUG http-nio-8080-exec-10 org.springframework.jdbc.core.JdbcTemplate - [] - Executing prepared SQL statement [SELECT JOB_EXECUTION_ID, KEY_NAME, TYPE_CD, STRING_VAL, DATE_VAL, LONG_VAL, DOUBLE_VAL, IDENTIFYING from webapi.BATCH_JOB_EXECUTION_PARAMS where JOB_EXECUTION_ID = ?]
2023-02-21 12:16:02.326 DEBUG http-nio-8080-exec-4 org.springframework.jdbc.core.JdbcTemplate - [] - Executing prepared SQL query
2023-02-21 12:16:02.326 DEBUG http-nio-8080-exec-4 org.springframework.jdbc.core.JdbcTemplate - [] - Executing prepared SQL statement [SELECT JOB_EXECUTION_ID, KEY_NAME, TYPE_CD, STRING_VAL, DATE_VAL, LONG_VAL, DOUBLE_VAL, IDENTIFYING from webapi.BATCH_JOB_EXECUTION_PARAMS where JOB_EXECUTION_ID = ?]
2023-02-21 12:16:02.364 DEBUG http-nio-8080-exec-10 org.springframework.jdbc.core.JdbcTemplate - [] - Executing prepared SQL query
2023-02-21 12:16:02.364 DEBUG http-nio-8080-exec-10 org.springframework.jdbc.core.JdbcTemplate - [] - Executing prepared SQL statement [SELECT JOB_EXECUTION_ID, KEY_NAME, TYPE_CD, STRING_VAL, DATE_VAL, LONG_VAL, DOUBLE_VAL, IDENTIFYING from webapi.BATCH_JOB_EXECUTION_PARAMS where JOB_EXECUTION_ID = ?]
2023-02-21 12:16:02.366 DEBUG http-nio-8080-exec-4 org.springframework.jdbc.core.JdbcTemplate - [] - Executing prepared SQL query
2023-02-21 12:16:02.366 DEBUG http-nio-8080-exec-4 org.springframework.jdbc.core.JdbcTemplate - [] - Executing prepared SQL statement [SELECT JOB_EXECUTION_ID, KEY_NAME, TYPE_CD, STRING_VAL, DATE_VAL, LONG_VAL, DOUBLE_VAL, IDENTIFYING from webapi.BATCH_JOB_EXECUTION_PARAMS where JOB_EXECUTION_ID = ?]
2023-02-21 12:16:02.399 DEBUG http-nio-8080-exec-4 org.springframework.jdbc.core.JdbcTemplate - [] - Executing prepared SQL query
2023-02-21 12:16:02.399 DEBUG http-nio-8080-exec-4 org.springframework.jdbc.core.JdbcTemplate - [] - Executing prepared SQL statement [SELECT JOB_EXECUTION_ID, KEY_NAME, TYPE_CD, STRING_VAL, DATE_VAL, LONG_VAL, DOUBLE_VAL, IDENTIFYING from webapi.BATCH_JOB_EXECUTION_PARAMS where JOB_EXECUTION_ID = ?]
2023-02-21 12:16:02.400 DEBUG taskExecutor-1 org.springframework.orm.jpa.JpaTransactionManager - [] - Exposing JPA transaction as JDBC transaction [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@242ceea6]
2023-02-21 12:16:02.400 DEBUG http-nio-8080-exec-10 org.springframework.jdbc.core.JdbcTemplate - [] - Executing prepared SQL query
2023-02-21 12:16:02.400 DEBUG http-nio-8080-exec-10 org.springframework.jdbc.core.JdbcTemplate - [] - Executing prepared SQL statement [SELECT JOB_EXECUTION_ID, KEY_NAME, TYPE_CD, STRING_VAL, DATE_VAL, LONG_VAL, DOUBLE_VAL, IDENTIFYING from webapi.BATCH_JOB_EXECUTION_PARAMS where JOB_EXECUTION_ID = ?]

2023-02-21 12:16:02.436 DEBUG http-nio-8080-exec-4 org.springframework.jdbc.core.JdbcTemplate - [] - Executing prepared SQL statement [SELECT JOB_EXECUTION_ID, KEY_NAME, TYPE_CD, STRING_VAL, DATE_VAL, LONG_VAL, DOUBLE_VAL, IDENTIFYING from webapi.BATCH_JOB_EXECUTION_PARAMS where JOB_EXECUTION_ID = ?]
2023-02-21 12:16:02.437 DEBUG http-nio-8080-exec-10 org.springframework.jdbc.core.JdbcTemplate - [] - Executing prepared SQL query
2023-02-21 12:16:02.437 DEBUG http-nio-8080-exec-10 org.springframework.jdbc.core.JdbcTemplate - [] - Executing prepared SQL statement [SELECT JOB_EXECUTION_ID, KEY_NAME, TYPE_CD, STRING_VAL, DATE_VAL, LONG_VAL, DOUBLE_VAL, IDENTIFYING from webapi.BATCH_JOB_EXECUTION_PARAMS where JOB_EXECUTION_ID = ?]

One specific line that I saw:

2023-02-21 12:24:23.976 DEBUG http-nio-8080-exec-10 org.springframework.jdbc.core.JdbcTemplate - [] - Executing SQL query [SELECT JOB_EXECUTION_ID FROM webapi.BATCH_JOB_EXECUTION E, webapi.BATCH_JOB_INSTANCE I WHERE E.JOB_INSTANCE_ID=I.JOB_INSTANCE_ID ORDER BY JOB_EXECUTION_ID DESC LIMIT 1 OFFSET 16599]

The LIMIT 1 OFFSET 16599 is odd here as well. Why would we select 1 job after the 16599th?

Note the individual queries looking for JOB_EXECUTIONID = ?. The issue is: why is it querying for specific job executions when the only thing happening is getting a list of job statuses (presumably)?

You will need to have many jobs in your spring-batch tables: we have over 30,000 jobs.

Start at the job-status listing path that uses Spring Batch and JdbcTemplate, and reproduce with the jdbc-debug Maven profile against tables containing more than 30,000 jobs. Trace the repeated BATCH_JOB_EXECUTION_PARAMS queries and the LIMIT 1 OFFSET query. Done means the status listing no longer produces the reported query barrage and its query behavior is explained or corrected.