Robert Muir created LUCENE-9185:
-----------------------------------
Summary: add "tests.profile" to gradle build to aid fixing slow
tests
Key: LUCENE-9185
URL: https://issues.apache.org/jira/browse/LUCENE-9185
Project: Lucene - Core
Issue Type: Task
Reporter: Robert Muir
Attachments: LUCENE-9185.patch
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}}
{noformat}
...
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
{noformat}
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) ...
{noformat}
...
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
{noformat}
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
---------------------------------------------------------------------
To unsubscribe, e-mail: issues-unsubscr...@lucene.apache.org
For additional commands, e-mail: issues-h...@lucene.apache.org
