[jira] [Updated] (LUCENE-9185) add "tests.profile" to gradle build to aid fixing slow tests
[
https://issues.apache.org/jira/browse/LUCENE-9185?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Robert Muir updated LUCENE-9185:
Attachment: LUCENE-9185.patch
> 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
>Priority: Major
> Attachments: LUCENE-9185.patch, LUCENE-9185.patch, 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% 2762java.util.Arrays#fill()
> 1.59% 1953com.carrotsearch.randomizedtesting.RandomizedContext#context()
> 1.24% 1523java.util.Random#nextInt()
> 1.19% 1456java.lang.StringUTF16#compress()
> 1.08% 1319java.lang.StringLatin1#inflate()
> 1.00% 1228java.lang.Integer#getChars()
> 0.99% 1214java.util.Arrays#compareUnsigned()
> 0.96% 1179java.util.zip.Inflater#inflateBytesBytes()
> 0.91% 1114java.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% 5617sun.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% 3458sun.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$MDCAwareThreadPoolExe
[jira] [Updated] (LUCENE-9185) add "tests.profile" to gradle build to aid fixing slow tests
[
https://issues.apache.org/jira/browse/LUCENE-9185?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Robert Muir updated LUCENE-9185:
Attachment: LUCENE-9185.patch
> 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
>Priority: Major
> Attachments: LUCENE-9185.patch, 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% 2762java.util.Arrays#fill()
> 1.59% 1953com.carrotsearch.randomizedtesting.RandomizedContext#context()
> 1.24% 1523java.util.Random#nextInt()
> 1.19% 1456java.lang.StringUTF16#compress()
> 1.08% 1319java.lang.StringLatin1#inflate()
> 1.00% 1228java.lang.Integer#getChars()
> 0.99% 1214java.util.Arrays#compareUnsigned()
> 0.96% 1179java.util.zip.Inflater#inflateBytesBytes()
> 0.91% 1114java.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% 5617sun.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% 3458sun.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$execut
[jira] [Updated] (LUCENE-9185) add "tests.profile" to gradle build to aid fixing slow tests
[
https://issues.apache.org/jira/browse/LUCENE-9185?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Robert Muir updated LUCENE-9185:
Attachment: LUCENE-9185.patch
> 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
>Priority: Major
> 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% 2762java.util.Arrays#fill()
> 1.59% 1953com.carrotsearch.randomizedtesting.RandomizedContext#context()
> 1.24% 1523java.util.Random#nextInt()
> 1.19% 1456java.lang.StringUTF16#compress()
> 1.08% 1319java.lang.StringLatin1#inflate()
> 1.00% 1228java.lang.Integer#getChars()
> 0.99% 1214java.util.Arrays#compareUnsigned()
> 0.96% 1179java.util.zip.Inflater#inflateBytesBytes()
> 0.91% 1114java.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% 5617sun.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% 3458sun.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
>
