0

I have a query which runs in about 6ms in DBeaver and I used the general log to extract the query that is being passed in which is the same database that my Tomcat server is connected to

select min(organizati0_.Downloaded) as col_0_0_ from oss_collection_history organizati0_ 
where organizati0_.AccountingSystem='SomeSystem' 
and (organizati0_.Org in ('ID1' , 'ID2', ..., 'ID10' ))

On a JUnit test running Spring Data JPA against a Dockerized copy of the database, the query also runs quite fast 60ms, but on Tomcat it takes upwards of 8-10 seconds.

So not exactly sure what's going on.

I just do this to profile the function call using the same parameters.

var start = System.currentTimeMillis();
consolidatedDownloadSvc.getAvailableYearsOfDownloadedForAccountingSystem(...);
System.out.println(System.currentTimeMillis() - start);

It does not appear on slowlog even if I set global log_queries_not_using_indexes = 'ON'; so that would indicate to me that the query is indexed.

So I was wondering if there's some sort of log that will show me any extra things I may be missing in Spring-Data and Hibernate.

Archimedes Trajano
  • 35,625
  • 19
  • 175
  • 265
  • Are you comparing performance against a local DB running in Docker vs. a remote DB or what's the slower environment exactly? – Mick Mnemonic Dec 28 '21 at 22:33
  • In Tomcat it's significantly slower compared to JUnit. I don't mind if it is a factor of 10 compared to JUnit in Docker, because factor of 10 is still under a second. i.e. 600ms. 6 ms for MySQL client over JDBC, 60ms in a test container docker and 8000ms with Tomcat. – Archimedes Trajano Dec 29 '21 at 02:20

1 Answers1

1

Apart from what @Panagiotis suggested it will also be helpful to enable below stats to understand in what phase is hibernate spending more time.

spring.jpa.properties.hibernate.generate_statistics=true
logging.level.org.hibernate.stat=DEBUG

You would see something like below in your logs

2021-12-29 10:54:52.408  INFO 31972 - – [           main] i.StatisticalLoggingSessionEventListener : Session Metrics {
    5070899 nanoseconds spent acquiring 1 JDBC connections;
    0 nanoseconds spent releasing 0 JDBC connections;
    4359903 nanoseconds spent preparing 20 JDBC statements;
    76117198 nanoseconds spent executing 20 JDBC statements;
    0 nanoseconds spent executing 0 JDBC batches;
    132026893 nanoseconds spent performing 40 L2C puts;
    0 nanoseconds spent performing 0 L2C hits;
    838900 nanoseconds spent performing 19 L2C misses;
    0 nanoseconds spent executing 0 flushes (flushing a total of 0 entities and 0 collections);
    16900 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}
Shailendra
  • 8,874
  • 2
  • 28
  • 37
  • This probably would've been useful a few minutes ago. :) I'll check it out, but after trying out a few things it appears that there's some "lingering information" when running in tomcat. Namely the access control which used hibernate caused some data to be left in memory (since I know I don't plan to use it I just did an entityManager.clear and it made things run MUCH faster) – Archimedes Trajano Dec 29 '21 at 09:12