I have an odd problem where Hibernate is running more queries than I've asked for, and can't see the need for.
Here is my controller:
@Autowired UserService users;
@RequestMapping("/test")
@ResponseBody
public String test() {
User user = users.findUser(1L);
return "Found user: "+user.getEmail();
}
Here is the UserService:
@Component
public class UserService {
@javax.persistence.PersistenceUnit private EntityManagerFactory emf;
private JpaTemplate getJpaTemplate() {
return new JpaTemplate(emf);
}
public User findUser(long id) {
long start = System.currentTimeMillis();
JpaTemplate jpaTemplate = getJpaTemplate();
User user = jpaTemplate.find(User.class, id);
System.out.println(System.currentTimeMillis() - start);
return user;
}
}
The call to findUser() takes about 140ms... Rather baffling. The database performs just fine for other queries, including this one in some handlers (I suspect when it is not the first query run).
JProfiler suggests that every time it is called, four queries are sent to the database (not necessarily in this order):
1) [5ms] select user... (the actual query) 2) [7ms] SHOW COLLATION 3) [14ms] /* mysql-connector-java-5.1.7 ( Revision: ${svn.Revision} ) */SELECT @@session.auto_increment_increment 4) [70ms] /* mysql-connector-java-5.1.7 ( Revision: ${svn.Revision} ) */SHOW VARIABLES WHERE Variable_name ='language' OR Variable_name = 'net_write_timeout' OR Variable_name = 'interactive_timeout' OR Variable_name = 'wait_timeout' OR Variable_name = 'character_set_client' OR Variable_name = 'character_set_connection' OR Variable_name = 'character_set' OR Variable_name = 'character_set_server' OR Variable_name = 'tx_isolation' OR Variable_name = 'transaction_isolation' OR Variable_name = 'character_set_results' OR Variable_name = 'timezone' OR Variable_name = 'time_zone' OR Variable_name = 'system_time_zone' OR Variable_name = 'lower_case_table_names' OR Variable_name = 'max_allowed_packet' OR Variable_name = 'net_buffer_length' OR Variable_name = 'sql_mode' OR Variable_name = 'query_cache_type' OR Variable_name = 'query_cache_size' OR Variable_name = 'init_connect'
Its clear that the actual query takes no time at all, and most of the time is spend in that fourth one. What can I do about this? It doesn't show up in the hibernate log output, only the first, actual query does. Incidentally, all the time is spent after the call to getJpaTemplate() - i.e actually in the jpa.find() method.
Any ideas?
UPDATE: I've worked out that it is hibernate doing some sort of initial connection to the database multiple times, since somebody else posted the same set of queries (http://ondra.zizka.cz/stranky/programovani/java/hibernate_netbeans_howto_tutorial.texy). Why would hibernate make its initial connection repeatedly, isn't it using a connection pool - how can I check?
I've solved it. I had a non-pooled datasource:
From the Javadoc at: http://static.springsource.org/spring/docs/2.0.x/api/org/springframework/jdbc/datasource/DriverManagerDataSource.html
So I've now replaced this with:
I had to throw in c3p0-0.9.1.2.jar too, since it uses that connection pool.