tradeoffs, bad science, and polar bears: the world of java optimisation

Welcome to the Java optimisation jungle. Why can’t we “just make it go faster”? It turns out, in most cases, we need to first work out “faster for whom?” and “why do we want to go faster?” and “what even *is* faster?” This talk introduces the basic principles of optimisation, before bouncing through the pitfalls of optimisation; why the exact same techniques which make Quarkus rocket-fast used to be a terrible idea fifteen years ago, why fast benchmarks make for slow programs, and why even though it can be easy to get wrong, optimisation really really matters. Along the way we’ll talk about measuring things, bad advice, garbage collection, and climate change.

Transcript

1. Holly Cummins IBM @holly_cummins tradeoffs, bad science, and polar bears: the world of java optimisation
2. #Quarkus @holly_cummins why optimise?
3. #Quarkus @holly_cummins why optimise?
4. #Quarkus @holly_cummins why optimise? 0.5s extra search page time
5. #Quarkus @holly_cummins why optimise? 0.5s extra search page time 20% drop in traf fi c
6. #Quarkus @holly_cummins why optimise? 0.5s extra search page time 20% drop in traf fi c 100 ms latency on page load
7. #Quarkus @holly_cummins why optimise? 0.5s extra search page time 20% drop in traf fi c 100 ms latency on page load 7% lower conversion rate
8. #Quarkus @holly_cummins why optimise? 0.5s extra search page time 20% drop in traf fi c 100 ms latency on page load 7% lower conversion rate
9. #Quarkus @holly_cummins why optimise? 0.5s extra search page time 20% drop in traf fi c 10 ms delay in trading platform 100 ms latency on page load 7% lower conversion rate
10. #Quarkus @holly_cummins why optimise? 0.5s extra search page time 20% drop in traf fi c 10 ms delay in trading platform 10% drop in revenue 100 ms latency on page load 7% lower conversion rate
11. #Quarkus @holly_cummins what is optimising?
12. #Quarkus @holly_cummins for whom? when? doing what? “make it go faster”
13. #Quarkus @holly_cummins design thinking
14. #Quarkus @holly_cummins
15. #Quarkus @holly_cummins performance can be:
16. #Quarkus @holly_cummins performance can be: throughput
17. #Quarkus @holly_cummins performance can be: throughput transactions per second
18. #Quarkus @holly_cummins performance can be: throughput latency transactions per second
19. #Quarkus @holly_cummins performance can be: throughput latency transactions per second start-up time
20. #Quarkus @holly_cummins performance can be: throughput latency transactions per second response time start-up time
21. #Quarkus @holly_cummins performance can be: throughput latency transactions per second response time start-up time ramp-up time
22. #Quarkus @holly_cummins performance can be: throughput latency capacity transactions per second response time start-up time ramp-up time
23. #Quarkus @holly_cummins performance can be: throughput latency capacity transactions per second response time start-up time footprint ramp-up time
24. #Quarkus @holly_cummins performance can be: throughput latency capacity transactions per second response time start-up time CPU usage footprint ramp-up time
25. #Quarkus @holly_cummins performance can be: throughput latency capacity utilisation transactions per second response time start-up time CPU usage footprint ramp-up time
26. #Quarkus @holly_cummins performance can be: throughput latency capacity utilisation … transactions per second response time start-up time CPU usage footprint ramp-up time
27. #Quarkus @holly_cummins Never underestimate the bandwidth [throughput] of a station wagon full of tapes hurtling down the highway. –Andrew Tanenbaum, 1981
28. #Quarkus @holly_cummins Never underestimate the bandwidth [throughput] of a station wagon full of tapes hurtling down the highway. –Andrew Tanenbaum, 1981 but the latency is terrible …
29. @holly_cummins requirements change
30. @holly_cummins
31. @holly_cummins
32. @holly_cummins
33. @holly_cummins
34. @holly_cummins I am not designed for this.
35. @holly_cummins the world changes
36. #Quarkus @holly_cummins
37. #Quarkus @holly_cummins -Xmx == $
38. #Quarkus @holly_cummins -Xmx == $ footprint
39. #Quarkus @holly_cummins
40. #Quarkus @holly_cummins which performs better?
41. #Quarkus @holly_cummins quarkus trading-off fl exibility against startup speed and footprint
42. #Quarkus @holly_cummins quarkus trading-off fl exibility against startup speed and footprint uhh … are you supposed to shut down applications after using them?
43. #Quarkus @holly_cummins 30% of VMs are zombies (antithesisgroup.com) behaviour at idle
44. #Quarkus @holly_cummins how to optimise?
45. #Quarkus @holly_cummins find the bottleneck. fi x it.
46. #IBM @holly_cummins intuition pitfall 1
47. #Quarkus @holly_cummins this is not the place for ideas
48. #Quarkus @holly_cummins measure, don’t guess.
49. #Quarkus @holly_cummins measure the right thing
50. #Quarkus @holly_cummins measure the right thing what do your users care about?
51. #IBM @holly_cummins numbers pitfall 2
52. #Quarkus @holly_cummins
53. #Quarkus @holly_cummins leading indicators
54. #Quarkus @holly_cummins leading indicators lagging indicators
55. #Quarkus @holly_cummins leading indicators we care about them lagging indicators
56. #Quarkus @holly_cummins leading indicators we care about them easy to measure lagging indicators
57. #Quarkus @holly_cummins leading indicators we care about them easy to measure hard to change lagging indicators
58. #Quarkus @holly_cummins leading indicators we care about them easy to measure hard to change lagging indicators easy to change
59. #Quarkus @holly_cummins leading indicators we care about them easy to measure hard to change lagging indicators predictive of a thing we care about easy to change
60. #Quarkus @holly_cummins leading indicators we care about them easy to measure hard to change lagging indicators predictive of a thing we care about hard to identify easy to change
61. #Quarkus @holly_cummins leading indicators we care about them easy to measure hard to change lagging indicators predictive of a thing we care about hard to identify easy to change
62. #Quarkus @holly_cummins caution: performance experiments for entertainment purposes only. do not try these at home.
63. #Quarkus @holly_cummins 2007
64. #Quarkus @holly_cummins bad-ish advice: “reduce time spent in garbage collection”
65. #Quarkus @holly_cummins bad-ish advice: “reduce time spent in garbage collection” actually, garbage collection can make your application go faster
66. #Quarkus @holly_cummins 2007
67. #Quarkus @holly_cummins 2007
68. #Quarkus @holly_cummins 2021
69. #Quarkus @holly_cummins 2021
70. #Quarkus @holly_cummins -verbose:gc -Xverbosegclog:gclog.xml -Xcompactgc
71. #Quarkus @holly_cummins -verbose:gc -Xverbosegclog:gclog.xml -Xgcpolicy:optthruput -Xcompactgc
72. #Quarkus @holly_cummins -verbose:gc -Xverbosegclog:gclog.xml -Xgcpolicy:optthruput -Xmx110m -Xms110m -Xnocompactgc
73. #Quarkus @holly_cummins -verbose:gc -Xverbosegclog:gclog.xml -Xgcpolicy:optthruput -Xmx160m -Xms160m -Xnocompactgc
74. #Quarkus @holly_cummins -verbose:gc -Xverbosegclog:gclog.xml -Xgcpolicy:optthruput -Xmx300m -Xms300m -Xcompactgc why does the performance stay exactly the same no matter what gc settings I choose?
75. #Quarkus @holly_cummins by the way, this is cheating. (remember the ‘bad science’?)
76. #Quarkus @holly_cummins -verbose:gc -Xverbosegclog:gclog.xml -Xgcpolicy:optthruput
77. #Quarkus @holly_cummins -verbose:gc -Xverbosegclog:gclog.xml -Xgcpolicy:optthruput tool: GCMV
78. #Quarkus @holly_cummins -verbose:gc -Xverbosegclog:gclog.xml -Xgcpolicy:optthruput total GC time: 21.6s tool: GCMV
79. #Quarkus @holly_cummins -verbose:gc -Xverbosegclog:gclog.xml -Xgcpolicy:optthruput total GC time: 21.6s 4.1% of time in GC pause tool: GCMV
80. #Quarkus @holly_cummins -verbose:gc -Xverbosegclog:gclog.xml -Xgcpolicy:optthruput total GC time: 21.6s 4.1% of time in GC pause total GC time: 12.0s tool: GCMV
81. #Quarkus @holly_cummins -verbose:gc -Xverbosegclog:gclog.xml -Xgcpolicy:optthruput total GC time: 21.6s 4.1% of time in GC pause total GC time: 12.0s 3.6% of time in GC pause tool: GCMV
82. #Quarkus @holly_cummins -verbose:gc -Xverbosegclog:gclog.xml -Xgcpolicy:optthruput total GC time: 21.6s 4.1% of time in GC pause 23.9 GB garbage collected total GC time: 12.0s 3.6% of time in GC pause 13.0 GB garbage collected tool: GCMV
83. #Quarkus @holly_cummins -verbose:gc -Xverbosegclog:gclog.xml -Xgcpolicy:optthruput total GC time: 21.6s 4.1% of time in GC pause 23.9 GB garbage collected 493 transactions/s total GC time: 12.0s 3.6% of time in GC pause 13.0 GB garbage collected 260 transactions/s tool: GCMV
84. #Quarkus @holly_cummins -verbose:gc -Xverbosegclog:gclog.xml -Xgcpolicy:optthruput total GC time: 21.6s 4.1% of time in GC pause 23.9 GB garbage collected 493 transactions/s total GC time: 12.0s 3.6% of time in GC pause 13.0 GB garbage collected 260 transactions/s tool: GCMV
85. #Quarkus @holly_cummins -verbose:gc -Xverbosegclog:gclog.xml -Xgcpolicy:optthruput total GC time: 21.6s 4.1% of time in GC pause 23.9 GB garbage collected 493 transactions/s total GC time: 12.0s 3.6% of time in GC pause 13.0 GB garbage collected 260 transactions/s tool: GCMV
86. #Quarkus @holly_cummins total GC time: 21.6s 4.1% of time in GC pause 23.9 GB garbage collected 493 transactions/s total GC time: 12.0s 3.6% of time in GC pause 13.0 GB garbage collected 260 transactions/s
87. #Quarkus @holly_cummins total GC time: 21.6s 4.1% of time in GC pause 23.9 GB garbage collected 493 transactions/s total GC time: 12.0s 3.6% of time in GC pause 13.0 GB garbage collected 260 transactions/s
88. #Quarkus @holly_cummins total GC time: 21.6s 4.1% of time in GC pause 23.9 GB garbage collected 493 transactions/s total GC time: 12.0s 3.6% of time in GC pause 13.0 GB garbage collected 260 transactions/s leading indicator
89. #Quarkus @holly_cummins total GC time: 21.6s 4.1% of time in GC pause 23.9 GB garbage collected 493 transactions/s total GC time: 12.0s 3.6% of time in GC pause 13.0 GB garbage collected 260 transactions/s leading indicator
90. #Quarkus @holly_cummins total GC time: 21.6s 4.1% of time in GC pause 23.9 GB garbage collected 493 transactions/s total GC time: 12.0s 3.6% of time in GC pause 13.0 GB garbage collected 260 transactions/s leading indicator lagging indicator
91. #Quarkus @holly_cummins total GC time: 21.6s 4.1% of time in GC pause 23.9 GB garbage collected 493 transactions/s total GC time: 12.0s 3.6% of time in GC pause 13.0 GB garbage collected 260 transactions/s leading indicator lagging indicator ?
92. #Quarkus @holly_cummins total GC time: 21.6s 4.1% of time in GC pause 23.9 GB garbage collected 493 transactions/s total GC time: 12.0s 3.6% of time in GC pause 13.0 GB garbage collected 260 transactions/s leading indicator lagging indicator ? ?
93. #Quarkus @holly_cummins so wait, what changed to make the app faster? running jmeter on the same machine as the app gives a big speedup!
94. #Quarkus @holly_cummins “Any improvements made anywhere besides the bottleneck are an illusion.” – Gene Kim
95. #Quarkus @holly_cummins time kills all performance advice (even mine)
96. #Quarkus @holly_cummins the takeaways: gc can improve performance by rearranging the heap find the bottleneck validate advice independently
97. #IBM @holly_cummins advice pitfall 3
98. #Quarkus @holly_cummins I read it on the internet!
99. #IBM @holly_cummins noooooo! “make one big method because method dispatching is slow”
100. #IBM @holly_cummins noooooo! “re-use your objects to help the garbage collector”
101. #IBM @holly_cummins noooooo! “to tune your JVM, use this command-line:” -server -Xms1g -Xmx1g -XX:PermSize=1g -XX:MaxPermSize=256m -Xmn256m -Xss64k -XX:SurvivorRatio=30 -XX:+UseConcMarkSweepGC -XX: +CMSParallelRemarkEnabled -XX:+UseCMSInitiatingOccupancyOnly -XX:CMSInitiatingOccupancyFraction=10 -XX:+ScavengeBeforeFullGC -XX: +CMSScavengeBeforeRemark -XX:+PrintGCDateStamps -verbose:gc -XX: +PrintGCDetails -Dsun.net.inetaddr.ttl=5 -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=`date`.hprof -Dcom.sun.management.jmxremote.port=5616 -Dcom.sun.management.jmxremote.authenticate=false -Dcom.sun.management.jmxremote.ssl=false -server -Xms2g -Xmx2g -XX:MaxPermSize=256m -XX:NewRatio=1 -XX:+UseConcMarkSweepGC
102. #IBM @holly_cummins noooooo! use StringBuilder, never concatenate strings with +=
103. #IBM @holly_cummins noooooo! use StringBuilder, never concatenate strings with += wait, what? yes, right?
104. #Quarkus @holly_cummins 2 things ruin advice: • context • time
105. #IBM @holly_cummins micro-optimisation pitfall 4
106. #Quarkus @holly_cummins
107. #Quarkus @holly_cummins static string beSlow() { string result = ""; for (int i = 0; i < 314159; i++) { result += getStringData(i); } return result; }
108. #Quarkus @holly_cummins @Override public String toString() { String ret = "\n\tMarket Summary at: " + getSummaryDate() + "\n\t\t TSIA:" + getTSIA() + "\n\t\t openTSIA:" + getOpenTSIA() + "\n\t\t gain:" + getGainPercent() + "\n\t\t volume:" + getVolume(); if ((getTopGainers() == null) || (getTopLosers() == null)) { return ret; } ret += "\n\t\t Current Top Gainers:"; Iterator<QuoteDataBean> it = getTopGainers().iterator(); while (it.hasNext()) { QuoteDataBean quoteData = it.next(); ret += ("\n\t\t\t" + quoteData.toString()); } ret += "\n\t\t Current Top Losers:"; it = getTopLosers().iterator(); while (it.hasNext()) { QuoteDataBean quoteData = it.next(); ret += ("\n\t\t\t" + quoteData.toString()); } return ret; }
109. #Quarkus @holly_cummins @Override public String toString() { String ret = "\n\tMarket Summary at: " + getSummaryDate() + "\n\t\t TSIA:" + getTSIA() + "\n\t\t openTSIA:" + getOpenTSIA() + "\n\t\t gain:" + getGainPercent() + "\n\t\t volume:" + getVolume(); if ((getTopGainers() == null) || (getTopLosers() == null)) { return ret; } ret += "\n\t\t Current Top Gainers:"; Iterator<QuoteDataBean> it = getTopGainers().iterator(); while (it.hasNext()) { QuoteDataBean quoteData = it.next(); ret += ("\n\t\t\t" + quoteData.toString()); } ret += "\n\t\t Current Top Losers:"; it = getTopLosers().iterator(); while (it.hasNext()) { QuoteDataBean quoteData = it.next(); ret += ("\n\t\t\t" + quoteData.toString()); } return ret; }
110. #Quarkus @holly_cummins @Override public String toString() { String ret = "\n\tMarket Summary at: " + getSummaryDate() + "\n\t\t TSIA:" + getTSIA() + "\n\t\t openTSIA:" + getOpenTSIA() + "\n\t\t gain:" + getGainPercent() + "\n\t\t volume:" + getVolume(); if ((getTopGainers() == null) || (getTopLosers() == null)) { return ret; } ret += "\n\t\t Current Top Gainers:"; Iterator<QuoteDataBean> it = getTopGainers().iterator(); while (it.hasNext()) { QuoteDataBean quoteData = it.next(); ret += ("\n\t\t\t" + quoteData.toString()); } ret += "\n\t\t Current Top Losers:"; it = getTopLosers().iterator(); while (it.hasNext()) { QuoteDataBean quoteData = it.next(); ret += ("\n\t\t\t" + quoteData.toString()); } return ret; }
111. #Quarkus @holly_cummins @Override public String toString() { String ret = "\n\tMarket Summary at: " + getSummaryDate() + "\n\t\t TSIA:" + getTSIA() + "\n\t\t openTSIA:" + getOpenTSIA() + "\n\t\t gain:" + getGainPercent() + "\n\t\t volume:" + getVolume(); if ((getTopGainers() == null) || (getTopLosers() == null)) { return ret; } ret += "\n\t\t Current Top Gainers:"; Iterator<QuoteDataBean> it = getTopGainers().iterator(); while (it.hasNext()) { QuoteDataBean quoteData = it.next(); ret += ("\n\t\t\t" + quoteData.toString()); } ret += "\n\t\t Current Top Losers:"; it = getTopLosers().iterator(); while (it.hasNext()) { QuoteDataBean quoteData = it.next(); ret += ("\n\t\t\t" + quoteData.toString()); } return ret; } this never gets called
112. #Quarkus @holly_cummins let’s make travel energy-efficient?
113. #Quarkus @holly_cummins every little helps?
114. #Quarkus @holly_cummins every little helps? every optimisation is another optimisation you aren’t doing
115. #Quarkus @holly_cummins our platforms help
116. #Quarkus @holly_cummins static string beSlow() { string result = ""; for (int i = 0; i < 314159; i++) { result += getStringData(i); } return result; }
117. #Quarkus @holly_cummins static string beSlow() { string result = “"; result += getStringData(1); result += getStringData(2); result += getStringData(3); return result; }
118. #Quarkus @holly_cummins static string beSlow() { string result = “"; result += getStringData(1); result += getStringData(2); result += getStringData(3); return result; } this is fine
119. #Quarkus @holly_cummins the JVM writers have far more time for optimising than you do clean, typical, code runs best
120. #Quarkus @holly_cummins ok, but how to optimise?
121. #Quarkus @holly_cummins tools
122. #Quarkus @holly_cummins “What you can optimize is limited to what you can observe.” -Susie Xia, Netflix
123. #Quarkus @holly_cummins observability
124. #Quarkus @holly_cummins method profiler GC analysis heap analysis APM distributed tracing * not free this is an incomplete list, because there are a lot of tools out there, and many cost money
125. #Quarkus @holly_cummins method profiler GC analysis heap analysis APM distributed tracing VisualVM * not free this is an incomplete list, because there are a lot of tools out there, and many cost money
126. #Quarkus @holly_cummins method profiler GC analysis heap analysis APM distributed tracing Mission Control VisualVM * not free this is an incomplete list, because there are a lot of tools out there, and many cost money
127. #Quarkus @holly_cummins method profiler GC analysis heap analysis APM distributed tracing Mission Control VisualVM * not free this is an incomplete list, because there are a lot of tools out there, and many cost money IBM Health Center (for OpenJ9)
128. #Quarkus @holly_cummins method profiler GC analysis heap analysis APM distributed tracing Mission Control fl ame graphs VisualVM * not free this is an incomplete list, because there are a lot of tools out there, and many cost money IBM Health Center (for OpenJ9)
129. #Quarkus @holly_cummins method profiler GC analysis heap analysis APM distributed tracing Mission Control fl ame graphs GCMV VisualVM * not free this is an incomplete list, because there are a lot of tools out there, and many cost money IBM Health Center (for OpenJ9)
130. #Quarkus @holly_cummins method profiler GC analysis heap analysis APM distributed tracing Mission Control fl ame graphs GCMV VisualVM Eclipse MAT * not free this is an incomplete list, because there are a lot of tools out there, and many cost money IBM Health Center (for OpenJ9)
131. #Quarkus @holly_cummins method profiler GC analysis heap analysis APM distributed tracing Mission Control fl ame graphs GCMV VisualVM Eclipse MAT * not free this is an incomplete list, because there are a lot of tools out there, and many cost money GlowRoot IBM Health Center (for OpenJ9)
132. #Quarkus @holly_cummins method profiler GC analysis heap analysis APM distributed tracing Mission Control fl ame graphs GCMV New Relic* VisualVM Eclipse MAT * not free this is an incomplete list, because there are a lot of tools out there, and many cost money GlowRoot IBM Health Center (for OpenJ9)
133. #Quarkus @holly_cummins method profiler GC analysis heap analysis APM distributed tracing Mission Control fl ame graphs GCMV New Relic* AppDynamics* VisualVM Eclipse MAT * not free this is an incomplete list, because there are a lot of tools out there, and many cost money GlowRoot IBM Health Center (for OpenJ9)
134. #Quarkus @holly_cummins method profiler GC analysis heap analysis APM distributed tracing Mission Control fl ame graphs GCMV New Relic* AppDynamics* VisualVM Dynatrace* Eclipse MAT * not free this is an incomplete list, because there are a lot of tools out there, and many cost money GlowRoot IBM Health Center (for OpenJ9)
135. #Quarkus @holly_cummins method profiler GC analysis heap analysis APM distributed tracing Mission Control fl ame graphs GCMV New Relic* AppDynamics* Zipkin VisualVM Dynatrace* Eclipse MAT * not free this is an incomplete list, because there are a lot of tools out there, and many cost money GlowRoot IBM Health Center (for OpenJ9)
136. #Quarkus @holly_cummins method profiler GC analysis heap analysis APM distributed tracing Mission Control fl ame graphs GCMV New Relic* AppDynamics* Jaeger Zipkin VisualVM Dynatrace* Eclipse MAT * not free this is an incomplete list, because there are a lot of tools out there, and many cost money GlowRoot IBM Health Center (for OpenJ9)
137. #Quarkus @holly_cummins Net fl ix microservice architecture optimising a micro-service: is that micro-optimising?
138. @holly_cummins you may need to know the whole system context to know what to optimise
139. #Quarkus @holly_cummins “Nines don’t matter if your users aren’t happy.” – Charity Majors
140. #Quarkus @holly_cummins don’t forget the edges queueing theory helps us understand where the disasters happen
141. #Quarkus @holly_cummins “When it comes to IT performance, amateurs look at averages. Professionals look at distributions.” – Avishai Ish-Shalom
142. #Quarkus @holly_cummins slow performance can turn into big cloud bills make cloud costs visible to engineers
143. #Quarkus @holly_cummins ok, but you promised bears
144. #Quarkus @holly_cummins if you leave the TV on when you’re not using it, you’re a polar bear murderer
145. #Quarkus @holly_cummins there is a moral imperative to avoid waste
146. #Quarkus @holly_cummins there is a moral imperative to avoid waste electricity hardware
147. #Quarkus @holly_cummins data centres use 1-2% of the world’s electricity
148. #Quarkus @holly_cummins fewer devices longer lifetime
149. #Quarkus @holly_cummins fewer devices longer lifetime higher ef fi ciency
150. #Quarkus @holly_cummins fewer devices longer lifetime higher ef fi ciency lower footprint
151. #Quarkus @holly_cummins fewer devices longer lifetime higher ef fi ciency lower footprint more multitenancy
152. #Quarkus @holly_cummins fewer devices longer lifetime higher ef fi ciency lower footprint more multitenancy optimise for longevity
153. #Quarkus @holly_cummins fewer devices longer lifetime higher ef fi ciency lower footprint more multitenancy optimise for longevity the end of planned obsolescence?
154. #Quarkus @holly_cummins sooo … you can optimise, and it can be fun measure, don’t guess only optimise what matters now for questions!