Details
-
Task
-
Status: Closed
-
Major
-
Resolution: Fixed
-
None
-
None
-
None
-
New
Description
It is kind of a hassle to profile slow tests to fix the bottlenecks
The idea here is to make it dead easy to profile (just) the tests, capturing samples at a very low granularity, reducing noise as much as possible (e.g. not profiling entire gradle build or anything) and print a simple report for quick iterating.
Here's a prototype of what I hacked together:
All of lucene core: ./gradlew -p lucene/core test -Dtests.profile=true
... PROFILE SUMMARY from 122464 samples tests.profile.count=10 tests.profile.stacksize=1 tests.profile.linenumbers=false PERCENT SAMPLES STACK 2.59% 3170 org.apache.lucene.util.compress.LZ4$HighCompressionHashTable#assertReset() 2.26% 2762 java.util.Arrays#fill() 1.59% 1953 com.carrotsearch.randomizedtesting.RandomizedContext#context() 1.24% 1523 java.util.Random#nextInt() 1.19% 1456 java.lang.StringUTF16#compress() 1.08% 1319 java.lang.StringLatin1#inflate() 1.00% 1228 java.lang.Integer#getChars() 0.99% 1214 java.util.Arrays#compareUnsigned() 0.96% 1179 java.util.zip.Inflater#inflateBytesBytes() 0.91% 1114 java.util.concurrent.atomic.AtomicLong#compareAndSet() BUILD SUCCESSFUL in 3m 59s
If you look at this LZ4 assertReset method, you can see its indeed way too expensive, checking 64K items every time.
To dig deeper into potential problems you can pass additional parameters (all of them used here for demonstration):
./gradlew -p solr/core test --tests TestLRUStatsCache -Dtests.profile=true -Dtests.profile.count=8 -Dtests.profile.stacksize=20 -Dtests.profile.linenumbers=true
This clearly finds SOLR-14223 (expensive RSA key generation in CryptoKeys) ...
... PROFILE SUMMARY from 21355 samples tests.profile.count=8 tests.profile.stacksize=20 tests.profile.linenumbers=true PERCENT SAMPLES STACK 26.30% 5617 sun.nio.ch.EPoll#wait():(Native code) at sun.nio.ch.EPollSelectorImpl#doSelect():120 at sun.nio.ch.SelectorImpl#lockAndDoSelect():124 at sun.nio.ch.SelectorImpl#select():141 at org.eclipse.jetty.io.ManagedSelector$SelectorProducer#select():472 at org.eclipse.jetty.io.ManagedSelector$SelectorProducer#produce():409 at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill#produceTask():360 at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill#doProduce():184 at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill#tryProduce():171 at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill#produce():135 at org.eclipse.jetty.io.ManagedSelector$$Lambda$235.1914126144#run():(Interpreted code) at org.eclipse.jetty.util.thread.QueuedThreadPool#runJob():806 at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner#run():938 at java.lang.Thread#run():830 16.19% 3458 sun.nio.ch.EPoll#wait():(Native code) at sun.nio.ch.EPollSelectorImpl#doSelect():120 at sun.nio.ch.SelectorImpl#lockAndDoSelect():124 at sun.nio.ch.SelectorImpl#select():141 at org.eclipse.jetty.io.ManagedSelector$SelectorProducer#select():472 at org.eclipse.jetty.io.ManagedSelector$SelectorProducer#produce():409 at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill#produceTask():360 at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill#doProduce():184 at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill#tryProduce():171 at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill#produce():135 at org.eclipse.jetty.io.ManagedSelector$$Lambda$235.1914126144#run():(Interpreted code) at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor#lambda$execute$0():210 at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor$$Lambda$270.1779693615#run():(Interpreted code) at java.util.concurrent.ThreadPoolExecutor#runWorker():1128 at java.util.concurrent.ThreadPoolExecutor$Worker#run():628 at java.lang.Thread#run():830 13.15% 2808 sun.nio.ch.Net#accept():(Native code) at sun.nio.ch.ServerSocketChannelImpl#accept():276 at org.eclipse.jetty.server.ServerConnector#accept():385 at org.eclipse.jetty.server.AbstractConnector$Acceptor#run():701 at org.eclipse.jetty.util.thread.QueuedThreadPool#runJob():806 at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner#run():938 at java.lang.Thread#run():830 2.95% 630 java.math.BigInteger#implMulAdd():3191 at java.math.BigInteger#mulAdd():3161 at java.math.BigInteger#montReduce():3110 at java.math.BigInteger#implMontgomerySquare():2857 at java.math.BigInteger#montgomerySquare():2813 at java.math.BigInteger#oddModPow():3083 at java.math.BigInteger#modPow():2744 at java.math.BigInteger#passesMillerRabin():1103 at java.math.BigInteger#primeToCertainty():959 at java.math.BitSieve#retrieve():203 at java.math.BigInteger#largePrime():828 at java.math.BigInteger#probablePrime():766 at sun.security.rsa.RSAKeyPairGenerator#generateKeyPair():140 at java.security.KeyPairGenerator$Delegate#generateKeyPair():728 at java.security.KeyPairGenerator#genKeyPair():495 at org.apache.solr.util.CryptoKeys$RSAKeyPair#<init>():342 at org.apache.solr.security.PublicKeyHandler#<init>():27 at org.apache.solr.core.CoreContainer#<init>():336 at org.apache.solr.core.CoreContainer#<init>():326 at org.apache.solr.servlet.SolrDispatchFilter#createCoreContainer():261 2.74% 586 java.math.BigInteger#implMulAdd():3194 at java.math.BigInteger#mulAdd():3161 at java.math.BigInteger#montReduce():3110 at java.math.BigInteger#implMontgomerySquare():2857 at java.math.BigInteger#montgomerySquare():2813 at java.math.BigInteger#oddModPow():3083 at java.math.BigInteger#modPow():2744 at java.math.BigInteger#passesMillerRabin():1103 at java.math.BigInteger#primeToCertainty():959 at java.math.BitSieve#retrieve():203 at java.math.BigInteger#largePrime():828 at java.math.BigInteger#probablePrime():766 at sun.security.rsa.RSAKeyPairGenerator#generateKeyPair():140 at java.security.KeyPairGenerator$Delegate#generateKeyPair():728 at java.security.KeyPairGenerator#genKeyPair():495 at org.apache.solr.util.CryptoKeys$RSAKeyPair#<init>():342 at org.apache.solr.security.PublicKeyHandler#<init>():27 at org.apache.solr.core.CoreContainer#<init>():336 at org.apache.solr.core.CoreContainer#<init>():326 at org.apache.solr.servlet.SolrDispatchFilter#createCoreContainer():261 2.21% 472 java.math.BigInteger#implMulAdd():3191 at java.math.BigInteger#mulAdd():3161 at java.math.BigInteger#montReduce():3110 at java.math.BigInteger#implMontgomerySquare():2857 at java.math.BigInteger#montgomerySquare():2813 at java.math.BigInteger#oddModPow():3083 at java.math.BigInteger#modPow():2744 at java.math.BigInteger#passesMillerRabin():1103 at java.math.BigInteger#primeToCertainty():959 at java.math.BitSieve#retrieve():203 at java.math.BigInteger#largePrime():828 at java.math.BigInteger#probablePrime():766 at sun.security.rsa.RSAKeyPairGenerator#generateKeyPair():137 at java.security.KeyPairGenerator$Delegate#generateKeyPair():728 at java.security.KeyPairGenerator#genKeyPair():495 at org.apache.solr.util.CryptoKeys$RSAKeyPair#<init>():342 at org.apache.solr.security.PublicKeyHandler#<init>():27 at org.apache.solr.core.CoreContainer#<init>():336 at org.apache.solr.core.CoreContainer#<init>():326 at org.apache.solr.servlet.SolrDispatchFilter#createCoreContainer():261 1.93% 412 java.math.BigInteger#implMulAdd():3194 at java.math.BigInteger#mulAdd():3161 at java.math.BigInteger#montReduce():3110 at java.math.BigInteger#implMontgomerySquare():2857 at java.math.BigInteger#montgomerySquare():2813 at java.math.BigInteger#oddModPow():3083 at java.math.BigInteger#modPow():2744 at java.math.BigInteger#passesMillerRabin():1103 at java.math.BigInteger#primeToCertainty():959 at java.math.BitSieve#retrieve():203 at java.math.BigInteger#largePrime():828 at java.math.BigInteger#probablePrime():766 at sun.security.rsa.RSAKeyPairGenerator#generateKeyPair():137 at java.security.KeyPairGenerator$Delegate#generateKeyPair():728 at java.security.KeyPairGenerator#genKeyPair():495 at org.apache.solr.util.CryptoKeys$RSAKeyPair#<init>():342 at org.apache.solr.security.PublicKeyHandler#<init>():27 at org.apache.solr.core.CoreContainer#<init>():336 at org.apache.solr.core.CoreContainer#<init>():326 at org.apache.solr.servlet.SolrDispatchFilter#createCoreContainer():261 1.40% 299 java.math.BigInteger#implMulAdd():3194 at java.math.BigInteger#mulAdd():3161 at java.math.BigInteger#implSquareToLen():2185 at java.math.BigInteger#squareToLen():2105 at java.math.BigInteger#implMontgomerySquare():2856 at java.math.BigInteger#montgomerySquare():2813 at java.math.BigInteger#oddModPow():3083 at java.math.BigInteger#modPow():2744 at java.math.BigInteger#passesMillerRabin():1103 at java.math.BigInteger#primeToCertainty():959 at java.math.BitSieve#retrieve():203 at java.math.BigInteger#largePrime():828 at java.math.BigInteger#probablePrime():766 at sun.security.rsa.RSAKeyPairGenerator#generateKeyPair():140 at java.security.KeyPairGenerator$Delegate#generateKeyPair():728 at java.security.KeyPairGenerator#genKeyPair():495 at org.apache.solr.util.CryptoKeys$RSAKeyPair#<init>():342 at org.apache.solr.security.PublicKeyHandler#<init>():27 at org.apache.solr.core.CoreContainer#<init>():336 at org.apache.solr.core.CoreContainer#<init>():326 BUILD SUCCESSFUL in 39s