いろいろベンチ(8)

benchmark

＃とりあえず，これで一区切りにしよう．


Hibernateのテストをプロファイリングしてみました．使ったプロファイラはYourKit Java Profiler．

まずは，バッチタイプのプロファイリング結果．SELECT回数が102回なのは，後続のUPDATE，DELETEの元ネタを渡すために再度SELECTしているため．

NameTime(ms)Count
TestHibernate.selectAllCats()40,843102
└net.sf.hibernate.impl.SessionImpl.find()40,843102
　└net.sf.hibernate.impl.SessionImpl.find()40,843102
　　├net.sf.hibernate.impl.SessionImpl.find()40,828102
　　｜├net.sf.hibernate.hql.QueryTranslator.list()35,171102
　　｜｜└net.sf.hibernate.loader.Loader.list()35,171102
　　｜｜　└net.sf.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections()35,171102
　　｜｜　　└net.sf.hibernate.loader.Loader.doQuery()35,171102
　　｜｜　　　├com.p6spy.engine.logging.P6LogResultSet.next()20,64010,302
　　｜｜　　　├net.sf.hibernate.loader.Loader.getKeyFromResultSet()7,31210,200
　　｜｜　　　├net.sf.hibernate.loader.Loader.getRow()3,54610,200
　　｜｜　　　├net.sf.hibernate.loader.Loader.getResultSet()2,562102
　　｜｜　　　├net.sf.hibernate.loader.Loader.prepareQueryStatement()218102
　　｜｜　　　├net.sf.hibernate.impl.BatcherImpl.closeQueryStatement()187102
　　｜｜　　　├net.sf.hibernate.impl.SessionImpl.initializeEntity()156300
　　｜｜　　　├net.sf.hibernate.hql.QueryTranslator.getResultColumnOrRow()7810,200
　　｜｜　　　├net.sf.hibernate.impl.SessionImpl.proxyFor()6210,200
　　｜｜　　　├net.sf.hibernate.hql.QueryTranslator.getSQLString()46102
　　｜｜　　　├java.util.ArrayList.add()3110,200
　　｜｜　　　├java.lang.StringBuffer.append()15204
　　｜｜　　　└java.util.ArrayList.<init>()15204
　　｜└net.sf.hibernate.impl.SessionImpl.getQueries()5,640102
　　└java.lang.ClassLoader.loadClassInternal()151
TestHibernate.endTransaction()2,4534
├net.sf.hibernate.transaction.JDBCTransaction.commit()2,4534
｜├net.sf.hibernate.impl.SessionImpl.flush()2,4064
｜├net.sf.hibernate.impl.SessionImpl.afterTransactionCompletion()154
｜└com.p6spy.engine.logging.P6LogConnection.commit()154
└net.sf.hibernate.impl.SessionImpl.close()154
TestHibernate.beginTransaction()4214
├net.sf.hibernate.impl.SessionFactoryImpl.openSession()4064
｜└net.sf.hibernate.impl.SessionFactoryImpl.openSession()4064
｜　├net.sf.hibernate.impl.SessionFactoryImpl.openSession()3904
｜　└net.sf.ehcache.hibernate.Provider.nextTimestamp()154
└net.sf.hibernate.impl.SessionImpl.beginTransaction()154
TestHibernate.createCats()281100
└net.sf.hibernate.impl.SessionImpl.save()281100
　├net.sf.hibernate.impl.SessionImpl.saveWithGeneratedIdentifier()250100
　｜├net.sf.hibernate.impl.SessionImpl.doSave()203100
　｜└net.sf.hibernate.id.UUIDHexGenerator.generate()46100
　├net.sf.hibernate.impl.SessionImpl.getEntity()15100
　└net.sf.hibernate.impl.SessionImpl.unproxy()15100
TestHibernate.deleteCats()781
└net.sf.hibernate.impl.SessionImpl.delete()62100
　└net.sf.hibernate.impl.SessionImpl.doDelete()62100
　　├net.sf.hibernate.impl.MessageHelper.infoString()31100
　　├java.lang.ClassLoader.loadClassInternal()151
　　└java.util.HashSet.add()15100
TestHibernate.updateCats()151
└net.sf.hibernate.impl.SessionImpl.update()15100
　└org.apache.commons.logging.impl.Log4JLogger.trace()15100
SELECTに比べると，他の処理はゴミ同然．って，このプロファイラが計測する時間はCPU時間か？
＃UPDATEが15[msec]って，あんた...


続いて，ショートトランザクションタイプ（コネクション毎回取得）の結果．基本的にバッチと同じだったんで，一番違いがあったSELECTんとこだけ．

NameTime(ms)Count
TestHibernate.selectAllCats()75,828100
└net.sf.hibernate.impl.SessionImpl.find()75,828100
　└net.sf.hibernate.impl.SessionImpl.find()75,828100
　　├net.sf.hibernate.impl.SessionImpl.find()75,828100
　　｜├net.sf.hibernate.hql.QueryTranslator.list()75,281100
　　｜｜└net.sf.hibernate.loader.Loader.list()75,281100
　　｜｜　└net.sf.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections()75,281100
　　｜｜　　└net.sf.hibernate.loader.Loader.doQuery()75,281100
　　｜｜　　　├*net.sf.hibernate.loader.Loader.getRow()34,73410,000
　　｜｜　　　├com.p6spy.engine.logging.P6LogResultSet.next()23,65610,100
　　｜｜　　　├net.sf.hibernate.loader.Loader.getKeyFromResultSet()6,98410,000
　　｜｜　　　├*net.sf.hibernate.impl.SessionImpl.initializeEntity()6,53110,000
　　｜｜　　　├net.sf.hibernate.loader.Loader.getResultSet()2,500100
　　｜｜　　　├net.sf.hibernate.loader.Loader.prepareQueryStatement()140100
　　｜｜　　　├net.sf.hibernate.hql.QueryTranslator.getResultColumnOrRow()12510,000
　　｜｜　　　├net.sf.hibernate.impl.BatcherImpl.closeQueryStatement()78100
　　｜｜　　　├java.util.ArrayList.add()7810,000
　　｜｜　　　├java.util.ArrayList.get()1510,000
　　｜｜　　　├org.apche.commons.logging.impl.Log4JLogger.isTraceEnabled()15300
　　｜｜　　　├net.sf.hibernate.hql.QueryTranslator.getSQLString()15100
　　｜｜　　　└java.util.ArrayList.<init>()15200
　　｜├*net.sf.hibernate.impl.SessionImpl.getQueries()515100
　　｜└java.lang.StringBuffer.toString()15100
　　└java.lang.ClassLoader.loadClassInternal()151
大枠同じなんだけど，実はびみょ〜〜〜に違う． Nameの最初んとこに「*」があるのが，バッチタイプと明らかに違う部分． Loader.getRow()やSessionImpl.initializeEntity()なんて，バッチタイプと桁違いに遅い．が，そのまた反対で，SessionImpl.getQueries()は，バッチタイプの方が桁違いに遅かったりもする． Loader.getRow()の違いは，以下の通り．Loader.getRow()入ってからの内部メソッドの呼び出し回数が桁違いになってました． やっぱ，これはキャッシュに関係するのかな？
Namebatch(ms/count)short(ms/count)
net.sf.hibernate.loader.Loader.getRow()3,546/10,20034,734/10,000
└net.sf.hibernate.loader.Loader.instanceNotYetLoaded()1,093/30032,203/10,000
　├net.sf.hibernate.loader.Loader.loadFromResultSet()1,015/30030,703/10,000
　｜├net.sf.hibernate.loader.Loader.hydrate()828/30025,375/10,000
　｜├net.sf.hibernate.impl.SessionImpl.postHydrate()62/3001,031/10,000
　｜├net.sf.hibernate.impl.SessionImpl.addUninitializedEntity()46/3001,578/10,000
　｜├net.sf.hibernate.impl.SessionImpl.getPersister()15/300140/10,000
　｜├org.apache.commons.logging.impl.Log4JLogger.trace()15/300625/10,000
　｜└java.lang.StringBuffer.append()15/300531/10,000
　└net.sf.hibernate.impl.SessionImpl.instantiate()46/3001,046/10,000
(おまけ) バッチタイプで，Session.find()ではなく，Session.iterate()にしたときのトレース結果．
NameTime(ms)Count
TestHibernate.selectAllCats()47,781102
├net.sf.hibernate.impl.IteratorImpl.next()40,00010,200
｜├net.sf.hibernate.impl.IteratorImpl.postNext()39,34310,200
｜｜├net.sf.hibernate.type.EntityType.nullSafeGet()24,70310,098
｜｜｜├net.sf.hibernate.type.EntityType.resolveIdentifier()16,75010,098
｜｜｜｜└net.sf.hibernate.type.ManyToOneType.resolveIdentifier()16,68710,098
｜｜｜｜　└net.sf.hibernate.impl.SessionImpl.internalLoad()16,67110,098
｜｜｜｜　　├net.sf.hibernate.impl.SessionImpl.doLoadByClass()16,50010,098
｜｜｜｜　　└net.sf.hibernate.UnresolvableObjectException.throwIfNull()4610,098
｜｜｜└net.sf.hibernate.type.ManyToOneType.hydrate()7,89010,098
｜｜├com.p6spy.engine.logging.P6LogResultSet.next()13,85910,200
｜｜├org.apache.commons.logging.impl.Log4JLogger.debug()46810,200
｜｜└net.sf.hibernate.impl.IteratorImpl.close()109102
｜└org.apache.commons.logging.impl.Log4JLogger.debug()62510,200
├net.sf.hibernate.impl.QueryImpl.iterate()7,593102
├net.sf.hibernate.impl.SessionImpl.createQuery()78102
└java.util.ArrayList.add()4610,200
ps. YourKit．結構，悪くないなぁ．