My H2/C3PO/Hibernate setup does not seem to preserving prepared statements?

Viewed 191

I am finding my database is the bottleneck in my application, as part of this it looks like Prepared statements are not being reused.

For example here method I use

public static CoverImage findCoverImageBySource(Session session, String src)
{
    try
    {
        Query q = session.createQuery("from CoverImage t1 where t1.source=:source");
        q.setParameter("source", src, StandardBasicTypes.STRING);
        CoverImage result = (CoverImage)q.setMaxResults(1).uniqueResult();
        return result;
    }
    catch (Exception ex)
    {
        MainWindow.logger.log(Level.SEVERE, ex.getMessage(), ex);
    }
    return null;
}

But using Yourkit profiler it says

com.mchange.v2.c3po.impl.NewProxyPreparedStatemtn.executeQuery() Count 511 com.mchnage.v2.c3po.impl.NewProxyConnection.prepareStatement() Count 511

and I assume that the count for prepareStatement() call should be lower, ais it is looks like we create a new prepared statment every time instead of reusing.

https://docs.oracle.com/javase/7/docs/api/java/sql/Connection.html

enter image description here

I am using C3po connecting poolng wehich complicates things a little, but as I understand it I have it configured correctly

public static Configuration getInitializedConfiguration() { //See https://www.mchange.com/projects/c3p0/#hibernate-specific Configuration config = new Configuration();

config.setProperty(Environment.DRIVER,"org.h2.Driver");
config.setProperty(Environment.URL,"jdbc:h2:"+Db.DBFOLDER+"/"+Db.DBNAME+";FILE_LOCK=SOCKET;MVCC=TRUE;DB_CLOSE_ON_EXIT=FALSE;CACHE_SIZE=50000");
config.setProperty(Environment.DIALECT,"org.hibernate.dialect.H2Dialect");
System.setProperty("h2.bindAddress", InetAddress.getLoopbackAddress().getHostAddress());
config.setProperty("hibernate.connection.username","jaikoz");
config.setProperty("hibernate.connection.password","jaikoz");
config.setProperty("hibernate.c3p0.numHelperThreads","10");
config.setProperty("hibernate.c3p0.min_size","1");
//Consider that if we have lots of busy threads waiting on next stages could we possibly have alot of active
//connections.
config.setProperty("hibernate.c3p0.max_size","200");
config.setProperty("hibernate.c3p0.max_statements","5000");
config.setProperty("hibernate.c3p0.timeout","2000");
config.setProperty("hibernate.c3p0.maxStatementsPerConnection","50");
config.setProperty("hibernate.c3p0.idle_test_period","3000");
config.setProperty("hibernate.c3p0.acquireRetryAttempts","10");
//Cancel any connection that is more than 30 minutes old.
//config.setProperty("hibernate.c3p0.unreturnedConnectionTimeout","3000");
//config.setProperty("hibernate.show_sql","true");
//config.setProperty("org.hibernate.envers.audit_strategy", "org.hibernate.envers.strategy.ValidityAuditStrategy");
//config.setProperty("hibernate.format_sql","true");

config.setProperty("hibernate.generate_statistics","true");
//config.setProperty("hibernate.cache.region.factory_class", "org.hibernate.cache.ehcache.SingletonEhCacheRegionFactory");
//config.setProperty("hibernate.cache.use_second_level_cache", "true");
//config.setProperty("hibernate.cache.use_query_cache", "true");
addEntitiesToConfig(config);
return config;

}

Using H2 1.3.172, Hibernate 4.3.11 and the corresponding c3po for that hibernate version

With reproducible test case we have

HibernateStats

  • HibernateStatistics.getQueryExecutionCount() 28
  • HibernateStatistics.getEntityInsertCount() 119
  • HibernateStatistics.getEntityUpdateCount() 39
  • HibernateStatistics.getPrepareStatementCount() 189

Profiler, method counts

  • GooGooStaementCache.aquireStatement() 35
  • GooGooStaementCache.checkInStatement() 189
  • GooGooStaementCache.checkOutStatement() 189
  • NewProxyPreparedStatement.init() 189

I don't know what I shoud be counting as creation of prepared statement rather than reusing an existing prepared statement ?

I also tried enabling c3p0 logging by adding a c3p0 logger ands making it use same log file in my LogProperties but had no effect.

            String logFileName = Platform.getPlatformLogFolderInLogfileFormat() + "songkong_debug%u-%g.log";
            FileHandler fe = new FileHandler(logFileName, LOG_SIZE_IN_BYTES, 10, true);
            fe.setEncoding(StandardCharsets.UTF_8.name());
            fe.setFormatter(new com.jthink.songkong.logging.LogFormatter());
            fe.setLevel(Level.FINEST);

            MainWindow.logger.addHandler(fe);

            Logger c3p0Logger = Logger.getLogger("com.mchange.v2.c3p0");
            c3p0Logger.setLevel(Level.FINEST);
            c3p0Logger.addHandler(fe);
1 Answers

Now that I have eventually got c3p0Based logging working and I can confirm the suggestion of @Stevewaldman is correct.

If you enable

public static  Logger  c3p0ConnectionLogger = Logger.getLogger("com.mchange.v2.c3p0.stmt");
c3p0ConnectionLogger.setLevel(Level.FINEST);
c3p0ConnectionLogger.setUseParentHandlers(false);

Then you get log output of the form

24/08/2019 10.20.12:BST:FINEST: com.mchange.v2.c3p0.stmt.DoubleMaxStatementCache ----> CACHE HIT
24/08/2019 10.20.12:BST:FINEST: checkoutStatement: com.mchange.v2.c3p0.stmt.DoubleMaxStatementCache stats -- total size: 347; checked out: 1; num connections: 13; num keys: 347
24/08/2019 10.20.12:BST:FINEST: checkinStatement(): com.mchange.v2.c3p0.stmt.DoubleMaxStatementCache stats -- total size: 347; checked out: 0; num connections: 13; num keys: 347

making it clear when you get a cache hit. When there is no cache hit yo dont get the first line, but get the other two lines.

This is using C3p0 9.2.1

Related