我是性能诊断和优化的新手 . 有一个基于Spring的Web应用程序，它使用由PostgreSQL支持的hibernate EhCache HikariCP . 我正在运行SpringJUnit4ClassRunner测试和 JProfiler 作为测量和优化单个hibernate查询的主要工具 . 目标是发现并修复映射/获取导致查询执行时间过长的反模式 .
给定方案测试EhCache利用率和查询执行时间 . 据我所知，JDBC Hot Sports显示：
- 每个选择500个
Address实体的六个查询运行所有时间的5％ .
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 ?
和
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=?
City实体被检索了2,910次（部分来自EhCache？）
3,657毫秒 - 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加入dvdrental.PUBLIC.country country1_ ON city0_.country_id = country1_.country_id WHERE city0_.city_id =？
Store为什么不是国家？正在检索3,000次 . （部分来自EhCache？）
5,660毫秒 - 3,000 evt . SELECT store0_.store_id AS store_id1_12_13_，/ 更多字段 / 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 . 付款payment5_ ON staff1_.staff_id = payment5_.staff_id左外连接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 dvdrenta l.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加入dvdrental.PUBLIC.staff staff13_ ON rental8_.staff_id = staff13_.staff_id WHERE store0_.address_id =？
Console:
JProfiler> Protocol version 50
JProfiler> Using JVMTI
JProfiler> JVMTI version 1.1 detected.
JProfiler> 64-bit library
JProfiler> Instrumenting native methods.
JProfiler> Can retransform classes.
JProfiler> Can retransform any class.
JProfiler> Native library initialized
JProfiler> VM initialized
JProfiler> Waiting for a connection from the JProfiler GUI ...
JProfiler> Using dynamic instrumentation
JProfiler> Time measurement: elapsed time
JProfiler> 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 <clinit>
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 <clinit>
INFO: HCANN000001: Hibernate Commons Annotations {4.0.5.Final}
[timestamp] org.hibernate.dialect.Dialect <init>
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 <init>
INFO: HHH000397: Using ASTQueryTranslatorFactory
[timestamp] org.hibernate.cfg.SettingsFactory buildSettings
WARN: Unrecognized value for "hibernate.hbm2ddl.auto": none
[timestamp] org.hibernate.cache.spi.UpdateTimestampsCache <init>
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 <init>
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 <clinit>
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 <init>
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 <init>
INFO: HHH000397: Using ASTQueryTranslatorFactory
[timestamp] org.hibernate.cfg.SettingsFactory buildSettings
WARN: Unrecognized value for "hibernate.hbm2ddl.auto": none
[timestamp] org.hibernate.cache.spi.UpdateTimestampsCache <init>
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 <init>
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 <init>
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> Keeping VM alive until frontend disconnects.
Test
@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<Address> 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 < 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<Address> addressrFromCache = anotherQuery.list();
sessionNew.flush();
TestTransaction.flagForCommit();
TestTransaction.end();
sessionNew.clear();
sessionNew.close();
end = System.currentTimeMillis();
logger.error("Transaction #" + i + " took " + (end - start) + " ms");
}
}
}
关于我的优化方法可以改进什么？是否有任何明显的问题会降低查询执行速度？是否有改进查询的空间？
