title: How to optimize hibernate queries?
body: <p>I am new to performance diagnostics and optimization. There is Spring based web app that uses hibernate + EhCache + HikariCP that backed by PostgreSQL. I am running SpringJUnit4ClassRunner tests together with 
  <code>JProfiler</code> as the main tool for measuring and optimizing individual hibernate queries. The goal is to spot and fix mapping / fetching anti-patterns that lead to excessive query execution times.<br>
  The given scenario tests EhCache utilization and query execution times. As I understand the JDBC Hot Sports shows:</p>
  
  <ol>
  <li><p>Six queries that each select 500 <code>Address</code> entities runs 5% of all time.</p>
  
  <pre><code>106 ms - 1 evt. 
  SELECT address0_.address_id  AS address_1_1_, 
         address0_.address     AS address2_1_, 
         address0_.address2    AS address3_1_, 
         address0_.city_id     AS city_id8_1_, 
         address0_.district    AS district4_1_, 
         address0_.last_update AS last_upd5_1_, 
         address0_.phone       AS phone6_1_, 
         address0_.postal_code AS postal_c7_1_ 
  FROM   dvdrental.PUBLIC.address address0_ limit ?
  </code></pre>
  
  <p>and</p>
  
  <pre><code>30,161 micros - 6 evt. 
  SELECT     city0_.city_id        AS city_id1_3_0_, 
             city0_.city           AS city2_3_0_, 
             city0_.country_id     AS country_4_3_0_, 
             city0_.last_update    AS last_upd3_3_0_, 
             country1_.country_id  AS country_1_4_1_, 
             country1_.country     AS country2_4_1_, 
             country1_.last_update AS last_upd3_4_1_ 
  FROM       dvdrental.PUBLIC.city city0_ 
  inner join dvdrental.PUBLIC.country country1_ 
  ON         city0_.country_id=country1_.country_id 
  WHERE      city0_.city_id=?
  </code></pre></li>
  <li><p>The <code>City</code> entity is being retrieved 2,910 times (partially from EhCache?)</p></li>
  </ol>
  
  <p>3,657 ms - 2,910 evt. 
      SELECT     city0_.city_id        AS city_id1_3_0_, 
                 city0_.city           AS city2_3_0_, 
                 city0_.country_id     AS country_4_3_0_, 
                 city0_.last_update    AS last_upd3_3_0_, 
                 country1_.country_id  AS country_1_4_1_, 
                 country1_.country     AS country2_4_1_, 
                 country1_.last_update AS last_upd3_4_1_ 
      FROM       dvdrental.PUBLIC.city city0_ 
      inner join dvdrental.PUBLIC.country country1_ 
      ON         city0_.country_id=country1_.country_id 
      WHERE      city0_.city_id=?</p>
  
  <ol start="3">
  <li><p>The <code>Store</code> why not country??? is being retrieved 3,000 times. (partially from EhCache?)</p>
  
  <p>5,660 ms - 3,000 evt. 
  SELECT          store0_.store_id          AS store_id1_12_13_, 
                  /* many more fields */
                  staff13_.username         AS usernam10_11_12_ 
  FROM            dvdrental.PUBLIC.store store0_ 
  inner join      dvdrental.PUBLIC.staff staff1_ 
  ON              store0_.manager_staff_id=staff1_.staff_id 
  left outer join dvdrental.PUBLIC.address address2_ 
  ON              staff1_.address_id=address2_.address_id 
  left outer join dvdrental.PUBLIC.city city3_ 
  ON              address2_.city_id=city3_.city_id 
  left outer join dvdrental.PUBLIC.country country4_ 
  ON              city3_.country_id=country4_.country_id 
  left outer join dvdrental.PUBLIC.payment payment5_ 
  ON              staff1_.staff_id=payment5_.staff_id 
  left outer join dvdrental.PUBLIC.customer customer6_ 
  ON              payment5_.customer_id=customer6_.customer_id 
  left outer join dvdrental.PUBLIC.address address7_ 
  ON              customer6_.address_id=address7_.address_id 
  left outer join dvdrental.PUBLIC.rental rental8_ 
  ON              payment5_.rental_id=rental8_.rental_id 
  left outer join dvdrental.PUBLIC.customer customer9_ 
  ON              rental8_.customer_id=customer9_.customer_id 
  left outer join dvdrental.PUBLIC.inventory inventory10_ 
  ON              rental8_.inventory_id=inventory10_.inventory_id 
  left outer join dvdrental.PUBLIC.film film11_ 
  ON              inventory10_.film_id=film11_.film_id 
  left outer join dvdrental.PUBLIC.LANGUAGE language12_ 
  ON              film11_.language_id=language12_.language_id 
  left outer join dvdrental.PUBLIC.staff staff13_ 
  ON              rental8_.staff_id=staff13_.staff_id 
  WHERE           store0_.address_id=?</p></li>
  </ol>
  
  <p><strong>Console:</strong></p>
  
  <pre><code>JProfiler&gt; Protocol version 50
  JProfiler&gt; Using JVMTI
  JProfiler&gt; JVMTI version 1.1 detected.
  JProfiler&gt; 64-bit library
  JProfiler&gt; Instrumenting native methods.
  JProfiler&gt; Can retransform classes.
  JProfiler&gt; Can retransform any class.
  JProfiler&gt; Native library initialized
  JProfiler&gt; VM initialized
  JProfiler&gt; Waiting for a connection from the JProfiler GUI ...
  JProfiler&gt; Using dynamic instrumentation
  JProfiler&gt; Time measurement: elapsed time
  JProfiler&gt; CPU profiling enabled
  [timestamp] org.hibernate.jpa.internal.util.LogHelper logPersistenceUnitInformation
  INFO: HHH000204: Processing PersistenceUnitInfo [
      name: default
      ...]
  [timestamp] org.hibernate.Version logVersion
  INFO: HHH000412: Hibernate Core {4.3.11.Final}
  [timestamp] org.hibernate.cfg.Environment &lt;clinit&gt;
  INFO: HHH000206: hibernate.properties not found
  [timestamp] org.hibernate.cfg.Environment buildBytecodeProvider
  INFO: HHH000021: Bytecode provider name : javassist
  [timestamp] org.hibernate.annotations.common.reflection.java.JavaReflectionManager &lt;clinit&gt;
  INFO: HCANN000001: Hibernate Commons Annotations {4.0.5.Final}
  [timestamp] org.hibernate.dialect.Dialect &lt;init&gt;
  INFO: HHH000400: Using dialect: org.hibernate.dialect.PostgreSQLDialect
  [timestamp] org.hibernate.engine.jdbc.internal.LobCreatorBuilder useContextualLobCreation
  INFO: HHH000424: Disabling contextual LOB creation as createClob() method threw error : java.lang.reflect.InvocationTargetException
  [timestamp] org.hibernate.hql.internal.ast.ASTQueryTranslatorFactory &lt;init&gt;
  INFO: HHH000397: Using ASTQueryTranslatorFactory
  [timestamp] org.hibernate.cfg.SettingsFactory buildSettings
  WARN: Unrecognized value for "hibernate.hbm2ddl.auto": none
  [timestamp] org.hibernate.cache.spi.UpdateTimestampsCache &lt;init&gt;
  INFO: HHH000250: Starting update timestamps cache at region: org.hibernate.cache.spi.UpdateTimestampsCache
  [timestamp] org.hibernate.cache.ehcache.AbstractEhcacheRegionFactory getCache
  WARN: HHH020003: Could not find a specific ehcache configuration for cache named [org.hibernate.cache.spi.UpdateTimestampsCache]; using defaults.
  [timestamp] org.hibernate.cache.internal.StandardQueryCache &lt;init&gt;
  INFO: HHH000248: Starting query cache at region: org.hibernate.cache.internal.StandardQueryCache
  [timestamp] org.hibernate.cache.ehcache.AbstractEhcacheRegionFactory getCache
  WARN: HHH020003: Could not find a specific ehcache configuration for cache named [org.hibernate.cache.internal.StandardQueryCache]; using defaults.
  [timestamp] org.hibernate.validator.internal.util.Version &lt;clinit&gt;
  INFO: HV000001: Hibernate Validator 5.2.2.Final
  [timestamp] org.hibernate.cache.ehcache.AbstractEhcacheRegionFactory getCache
  WARN: HHH020003: Could not find a specific ehcache configuration for cache named [com.hibernate.query.performance.persistence.model.Address]; using defaults.
  [timestamp] org.hibernate.cache.ehcache.AbstractEhcacheRegionFactory getCache
  WARN: HHH020003: Could not find a specific ehcache configuration for cache named [customer]; using defaults.
  [timestamp] org.hibernate.cache.ehcache.AbstractEhcacheRegionFactory getCache
  WARN: HHH020003: Could not find a specific ehcache configuration for cache named [staff]; using defaults.
  [timestamp] org.hibernate.cache.ehcache.AbstractEhcacheRegionFactory getCache
  WARN: HHH020003: Could not find a specific ehcache configuration for cache named [language]; using defaults.
  [timestamp] org.hibernate.dialect.Dialect &lt;init&gt;
  INFO: HHH000400: Using dialect: org.hibernate.dialect.PostgreSQLDialect
  [timestamp] org.hibernate.engine.jdbc.internal.LobCreatorBuilder useContextualLobCreation
  INFO: HHH000424: Disabling contextual LOB creation as createClob() method threw error : java.lang.reflect.InvocationTargetException
  [timestamp] org.hibernate.engine.transaction.internal.TransactionFactoryInitiator initiateService
  INFO: HHH000399: Using default transaction strategy (direct JDBC transactions)
  [timestamp] org.hibernate.hql.internal.ast.ASTQueryTranslatorFactory &lt;init&gt;
  INFO: HHH000397: Using ASTQueryTranslatorFactory
  [timestamp] org.hibernate.cfg.SettingsFactory buildSettings
  WARN: Unrecognized value for "hibernate.hbm2ddl.auto": none
  [timestamp] org.hibernate.cache.spi.UpdateTimestampsCache &lt;init&gt;
  INFO: HHH000250: Starting update timestamps cache at region: org.hibernate.cache.spi.UpdateTimestampsCache
  [timestamp] org.hibernate.cache.ehcache.AbstractEhcacheRegionFactory getCache
  WARN: HHH020003: Could not find a specific ehcache configuration for cache named [org.hibernate.cache.spi.UpdateTimestampsCache]; using defaults.
  [timestamp] org.hibernate.cache.internal.StandardQueryCache &lt;init&gt;
  INFO: HHH000248: Starting query cache at region: org.hibernate.cache.internal.StandardQueryCache
  [timestamp] org.hibernate.cache.ehcache.AbstractEhcacheRegionFactory getCache
  WARN: HHH020003: Could not find a specific ehcache configuration for cache named [org.hibernate.cache.internal.StandardQueryCache]; using defaults.
  [timestamp] org.hibernate.cache.ehcache.AbstractEhcacheRegionFactory getCache
  WARN: HHH020003: Could not find a specific ehcache configuration for cache named [com.hibernate.query.performance.persistence.model.Address]; using defaults.
  [timestamp] org.hibernate.cache.ehcache.AbstractEhcacheRegionFactory getCache
  WARN: HHH020003: Could not find a specific ehcache configuration for cache named [customer]; using defaults.
  [timestamp] org.hibernate.cache.ehcache.AbstractEhcacheRegionFactory getCache
  WARN: HHH020003: Could not find a specific ehcache configuration for cache named [staff]; using defaults.
  [timestamp] org.hibernate.cache.ehcache.AbstractEhcacheRegionFactory getCache
  WARN: HHH020003: Could not find a specific ehcache configuration for cache named [language]; using defaults.
  [timestamp][main] ERROR - Starting QueryTimeWithEHCacheTest
  
  [timestamp] org.hibernate.cache.internal.StandardQueryCache &lt;init&gt;
  INFO: HHH000248: Starting query cache at region: address
  [timestamp] org.hibernate.cache.ehcache.AbstractEhcacheRegionFactory getCache
  WARN: HHH020003: Could not find a specific ehcache configuration for cache named [address]; using defaults.
  [timestamp] org.hibernate.engine.internal.StatisticalLoggingSessionEventListener end
  INFO: Session Metrics {
      30693123 nanoseconds spent acquiring 1 JDBC connections;
      0 nanoseconds spent releasing 0 JDBC connections;
      0 nanoseconds spent preparing 0 JDBC statements;
      0 nanoseconds spent executing 0 JDBC statements;
      0 nanoseconds spent executing 0 JDBC batches;
      0 nanoseconds spent performing 0 L2C puts;
      0 nanoseconds spent performing 0 L2C hits;
      0 nanoseconds spent performing 0 L2C misses;
      0 nanoseconds spent executing 0 flushes (flushing a total of 0 entities and 0 collections);
      0 nanoseconds spent executing 0 partial-flushes (flushing a total of 0 entities and 0 collections)
  }
  [timestamp][main] ERROR - Transaction #init took 4078 ms
  
  [timestamp] org.hibernate.engine.internal.StatisticalLoggingSessionEventListener end
  INFO: Session Metrics {
      26051941 nanoseconds spent acquiring 1 JDBC connections;
      0 nanoseconds spent releasing 0 JDBC connections;
      215664108 nanoseconds spent preparing 987 JDBC statements;
      2115057343 nanoseconds spent executing 987 JDBC statements;
      0 nanoseconds spent executing 0 JDBC batches;
      51375385 nanoseconds spent performing 501 L2C puts;
      0 nanoseconds spent performing 0 L2C hits;
      91260 nanoseconds spent performing 1 L2C misses;
      86065349 nanoseconds spent executing 1 flushes (flushing a total of 1093 entities and 1093 collections);
      0 nanoseconds spent executing 0 partial-flushes (flushing a total of 0 entities and 0 collections)
  }
  [timestamp] org.hibernate.engine.internal.StatisticalLoggingSessionEventListener end
  [timestamp][main] ERROR - Transaction #0 took 2469 ms
  
  INFO: Session Metrics {
      24727694 nanoseconds spent acquiring 1 JDBC connections;
      0 nanoseconds spent releasing 0 JDBC connections;
      0 nanoseconds spent preparing 0 JDBC statements;
      0 nanoseconds spent executing 0 JDBC statements;
      0 nanoseconds spent executing 0 JDBC batches;
      0 nanoseconds spent performing 0 L2C puts;
      0 nanoseconds spent performing 0 L2C hits;
      0 nanoseconds spent performing 0 L2C misses;
      0 nanoseconds spent executing 0 flushes (flushing a total of 0 entities and 0 collections);
      0 nanoseconds spent executing 0 partial-flushes (flushing a total of 0 entities and 0 collections)
  }
  [timestamp] org.hibernate.engine.internal.StatisticalLoggingSessionEventListener end
  INFO: Session Metrics {
      23262410 nanoseconds spent acquiring 1 JDBC connections;
      0 nanoseconds spent releasing 0 JDBC connections;
      157571091 nanoseconds spent preparing 986 JDBC statements;
      1545907919 nanoseconds spent executing 986 JDBC statements;
      0 nanoseconds spent executing 0 JDBC batches;
      0 nanoseconds spent performing 0 L2C puts;
      13736681 nanoseconds spent performing 501 L2C hits;
      10272 nanoseconds spent performing 1 L2C misses;
      34459640 nanoseconds spent executing 1 flushes (flushing a total of 1093 entities and 1093 collections);
      0 nanoseconds spent executing 0 partial-flushes (flushing a total of 0 entities and 0 collections)
  }
  [timestamp] org.hibernate.engine.internal.StatisticalLoggingSessionEventListener end
  INFO: Session Metrics {
      25324237 nanoseconds spent acquiring 1 JDBC connections;
      0 nanoseconds spent releasing 0 JDBC connections;
      0 nanoseconds spent preparing 0 JDBC statements;
      0 nanoseconds spent executing 0 JDBC statements;
      0 nanoseconds spent executing 0 JDBC batches;
      0 nanoseconds spent performing 0 L2C puts;
      0 nanoseconds spent performing 0 L2C hits;
      0 nanoseconds spent performing 0 L2C misses;
      0 nanoseconds spent executing 0 flushes (flushing a total of 0 entities and 0 collections);
      0 nanoseconds spent executing 0 partial-flushes (flushing a total of 0 entities and 0 collections)
  }
  [timestamp] org.hibernate.engine.internal.StatisticalLoggingSessionEventListener end
  INFO: Session Metrics {
      24041077 nanoseconds spent acquiring 1 JDBC connections;
      0 nanoseconds spent releasing 0 JDBC connections;
      155411292 nanoseconds spent preparing 986 JDBC statements;
      1739510225 nanoseconds spent executing 986 JDBC statements;
      0 nanoseconds spent executing 0 JDBC batches;
      0 nanoseconds spent performing 0 L2C puts;
      5709031 nanoseconds spent performing 501 L2C hits;
      11852 nanoseconds spent performing 1 L2C misses;
      27861718 nanoseconds spent executing 1 flushes (flushing a total of 1093 entities and 1093 collections);
      0 nanoseconds spent executing 0 partial-flushes (flushing a total of 0 entities and 0 collections)
  }
  [timestamp][main] ERROR - Transaction #1 took 2610 ms
  
  [timestamp] org.hibernate.engine.internal.StatisticalLoggingSessionEventListener end
  INFO: Session Metrics {
      23408584 nanoseconds spent acquiring 1 JDBC connections;
      0 nanoseconds spent releasing 0 JDBC connections;
      0 nanoseconds spent preparing 0 JDBC statements;
      0 nanoseconds spent executing 0 JDBC statements;
      0 nanoseconds spent executing 0 JDBC batches;
      0 nanoseconds spent performing 0 L2C puts;
      0 nanoseconds spent performing 0 L2C hits;
      0 nanoseconds spent performing 0 L2C misses;
      0 nanoseconds spent executing 0 flushes (flushing a total of 0 entities and 0 collections);
      0 nanoseconds spent executing 0 partial-flushes (flushing a total of 0 entities and 0 collections)
  }
  [timestamp][main] ERROR - Transaction #2 took 2288 ms
  
  [timestamp] org.hibernate.engine.internal.StatisticalLoggingSessionEventListener end
  INFO: Session Metrics {
      23451250 nanoseconds spent acquiring 1 JDBC connections;
      0 nanoseconds spent releasing 0 JDBC connections;
      145723202 nanoseconds spent preparing 986 JDBC statements;
      1464820331 nanoseconds spent executing 986 JDBC statements;
      0 nanoseconds spent executing 0 JDBC batches;
      0 nanoseconds spent performing 0 L2C puts;
      5532445 nanoseconds spent performing 501 L2C hits;
      3160 nanoseconds spent performing 1 L2C misses;
      31112679 nanoseconds spent executing 1 flushes (flushing a total of 1093 entities and 1093 collections);
      0 nanoseconds spent executing 0 partial-flushes (flushing a total of 0 entities and 0 collections)
  }
  [timestamp] org.hibernate.engine.internal.StatisticalLoggingSessionEventListener end
  INFO: Session Metrics {
      26841273 nanoseconds spent acquiring 1 JDBC connections;
      0 nanoseconds spent releasing 0 JDBC connections;
      0 nanoseconds spent preparing 0 JDBC statements;
      0 nanoseconds spent executing 0 JDBC statements;
      0 nanoseconds spent executing 0 JDBC batches;
      0 nanoseconds spent performing 0 L2C puts;
      0 nanoseconds spent performing 0 L2C hits;
      0 nanoseconds spent performing 0 L2C misses;
      0 nanoseconds spent executing 0 flushes (flushing a total of 0 entities and 0 collections);
      0 nanoseconds spent executing 0 partial-flushes (flushing a total of 0 entities and 0 collections)
  }
  [timestamp] org.hibernate.engine.internal.StatisticalLoggingSessionEventListener end
  INFO: Session Metrics {
      25004237 nanoseconds spent acquiring 1 JDBC connections;
      0 nanoseconds spent releasing 0 JDBC connections;
      159031639 nanoseconds spent preparing 986 JDBC statements;
      1539390609 nanoseconds spent executing 986 JDBC statements;
      0 nanoseconds spent executing 0 JDBC batches;
      0 nanoseconds spent performing 0 L2C puts;
      5428922 nanoseconds spent performing 501 L2C hits;
      3161 nanoseconds spent performing 1 L2C misses;
      37890751 nanoseconds spent executing 1 flushes (flushing a total of 1093 entities and 1093 collections);
      0 nanoseconds spent executing 0 partial-flushes (flushing a total of 0 entities and 0 collections)
  }
  [timestamp][main] ERROR - Transaction #3 took 2428 ms
  
  [timestamp] org.hibernate.engine.internal.StatisticalLoggingSessionEventListener end
  INFO: Session Metrics {
      24766806 nanoseconds spent acquiring 1 JDBC connections;
      0 nanoseconds spent releasing 0 JDBC connections;
      0 nanoseconds spent preparing 0 JDBC statements;
      0 nanoseconds spent executing 0 JDBC statements;
      0 nanoseconds spent executing 0 JDBC batches;
      0 nanoseconds spent performing 0 L2C puts;
      0 nanoseconds spent performing 0 L2C hits;
      0 nanoseconds spent performing 0 L2C misses;
      0 nanoseconds spent executing 0 flushes (flushing a total of 0 entities and 0 collections);
      0 nanoseconds spent executing 0 partial-flushes (flushing a total of 0 entities and 0 collections)
  }
  [timestamp] org.hibernate.engine.internal.StatisticalLoggingSessionEventListener end
  INFO: Session Metrics {
      26597126 nanoseconds spent acquiring 1 JDBC connections;
      0 nanoseconds spent releasing 0 JDBC connections;
      156316396 nanoseconds spent preparing 986 JDBC statements;
      1703458093 nanoseconds spent executing 986 JDBC statements;
      0 nanoseconds spent executing 0 JDBC batches;
      0 nanoseconds spent performing 0 L2C puts;
      4467764 nanoseconds spent performing 501 L2C hits;
      2765 nanoseconds spent performing 1 L2C misses;
      29417865 nanoseconds spent executing 1 flushes (flushing a total of 1093 entities and 1093 collections);
      0 nanoseconds spent executing 0 partial-flushes (flushing a total of 0 entities and 0 collections)
  }
  [timestamp][main] ERROR - Transaction #4 took 2543 ms
  
  JProfiler&gt; Keeping VM alive until frontend disconnects.
  </code></pre>
  
  <p><strong>Test</strong></p>
  
  <pre><code>@RunWith(SpringJUnit4ClassRunner.class)
  @ContextConfiguration(classes = {ApplicationTestConfig.class, CachingConfig.class }, loader = AnnotationConfigContextLoader.class)
  @Transactional(transactionManager = "hibernateTransactionManager")
  public class QueryTimeWithEHCacheTest extends AbstractTransactionalJUnit4SpringContextTests {
  
      private static final org.apache.logging.log4j.Logger logger = LogManager.getRootLogger();
  
      @Autowired
      private SessionFactory sessionFactory;
  
      @Test
      public void testTransactionCaching(){
          logger.error("Starting QueryTimeWithEHCacheTest");
          long start = System.currentTimeMillis();
          Session session = sessionFactory.openSession();
          Query query = session.createQuery("from Address").setCacheable(true).setCacheRegion("address").setMaxResults(500);
  
          @SuppressWarnings("unchecked")
          List&lt;Address&gt; entities = query.list();
          session.flush();
          TestTransaction.flagForCommit();
          TestTransaction.end();
          session.clear();
          session.close();
          long end = System.currentTimeMillis();
          logger.error("Transaction #init took " + (end - start) + " ms");
  
          for (int i = 0; i &lt; 5; i++) {
              start = System.currentTimeMillis();
              TestTransaction.start();
              Session sessionNew =  sessionFactory.openSession();
              Query anotherQuery = sessionNew.createQuery("from Address").setMaxResults(500);
              anotherQuery.setCacheable(true).setCacheRegion("address");
              @SuppressWarnings("unchecked")
              List&lt;Address&gt; addressrFromCache = anotherQuery.list();
              sessionNew.flush();
              TestTransaction.flagForCommit();
              TestTransaction.end();
              sessionNew.clear();
              sessionNew.close();
              end = System.currentTimeMillis();
              logger.error("Transaction #" + i  + " took " + (end - start) + " ms");
          }
      }
  }
  </code></pre>
  
  <p>What can be improved regarding my optimization approach? Are there any obvious problems that slow down query execution? Is there a room for improving queries?</p>
  
  <p><a href="https://i.stack.imgur.com/g2V8i.png" rel="nofollow noreferrer"><img src="https://i.stack.imgur.com/g2V8i.png" alt="enter image description here"></a></p>