About, Disclaimers, Contacts
"JVM Anatomy Quarks" is the on-going mini-post series, where every post is describing some elementary piece of knowledge about JVM. The name underlines the fact that the single post cannot be taken in isolation, and most pieces described here are going to readily interact with each other.
The post should take about 5-10 minutes to read. As such, it goes deep for only a single topic, a single test, a single benchmark, a single observation. The evidence and discussion here might be anecdotal, not actually reviewed for errors, consistency, writing 'tyle, syntaxtic and semantically errors, duplicates, or also consistency. Use and/or trust this at your own risk.
Aleksey Shipilëv, JVM/Performance Geek
Shout out at Twitter: @shipilev; Questions, comments, suggestions: aleksey@shipilev.net
Question
What is so expensive about creating new objects? What defines the object instantiation performance?
Theory
If you look closely at object instantiation paths on larger objects, you will inevitably wonder how the different parts scale, and what is the actual bottleneck in real world cases. We have seen that TLAB allocation seems very efficient, and that system initialization can be coalesced with user initialization. But in the end, we still have to do writes to memory — can we tell how much it costs?
Experiment
One primitive that can tell us the initialization part of story is plain old Java array. It needs to be initialized too, and its length is variable, which lets us see what is going on at different sizes. With that in mind, let us construct this benchmark:
import org.openjdk.jmh.annotations.*;
@Warmup(iterations = 5, time = 1, timeUnit = TimeUnit.SECONDS)
@Measurement(iterations = 5, time = 1, timeUnit = TimeUnit.SECONDS)
@Fork(value = 3)
@BenchmarkMode(Mode.AverageTime)
@OutputTimeUnit(TimeUnit.NANOSECONDS)
@State(Scope.Benchmark)
public class UA {
@Param({"1", "10", "100", "1000", "10000", "100000"})
int size;
@Benchmark
public byte[] java() {
return new byte[size];
}
}It makes sense to run with the latest JDK 9 EA (the follow up test below requires it), with -XX:+UseParallelOldGC to minimize GC overhead, and -Xmx20g -Xms20g -Xmn18g to keep most of the heap for these new allocations. Without further delay, this is what you will get on a good development desktop (like mine i7-4790K, 4.0 GHz, Linux x86_64), when all 8 hardware threads are busy:
Benchmark (size) Mode Cnt Score Error Units
# Time to allocate
UA.java 1 avgt 15 20.307 ± 4.532 ns/op
UA.java 10 avgt 15 26.657 ± 6.072 ns/op
UA.java 100 avgt 15 106.632 ± 34.742 ns/op
UA.java 1000 avgt 15 681.176 ± 124.980 ns/op
UA.java 10000 avgt 15 4576.433 ± 909.956 ns/op
UA.java 100000 avgt 15 44881.095 ± 13765.440 ns/op
# Allocation rate
UA.java:·gc.alloc.rate 1 avgt 15 6228.153 ± 1059.385 MB/sec
UA.java:·gc.alloc.rate 10 avgt 15 6335.809 ± 986.395 MB/sec
UA.java:·gc.alloc.rate 100 avgt 15 6126.333 ± 1354.964 MB/sec
UA.java:·gc.alloc.rate 1000 avgt 15 7772.263 ± 1263.453 MB/sec
UA.java:·gc.alloc.rate 10000 avgt 15 11518.422 ± 2155.516 MB/sec
UA.java:·gc.alloc.rate 100000 avgt 15 12039.594 ± 2724.242 MB/secOne can see that the allocation takes around 20 ns (single-threaded is much lower, but this average is skewed by hyper-threads), which goes gradually up to 40 us for 100K array. If you look at the allocation rate, then you will see it saturates at around 12 GB/sec. These experiments form the basis for other performance tests, by the way: it is important to understand the order of memory bandwidth / allocation rate you can pull off on a particular machine.
Can we see what code dominates the execution time? Of course we can, again, with JMH’s -prof perfasm. For -p size=100000, it will print out the hottest code like this:
0x00007f1f094f650b: movq $0x1,(%rdx) ; store mark word
0.00% 0x00007f1f094f6512: prefetchnta 0xc0(%r9)
0.64% 0x00007f1f094f651a: movl $0xf80000f5,0x8(%rdx) ; store klass word
0.02% 0x00007f1f094f6521: mov %r11d,0xc(%rdx) ; store array length
0x00007f1f094f6525: prefetchnta 0x100(%r9)
0.05% 0x00007f1f094f652d: prefetchnta 0x140(%r9)
0.07% 0x00007f1f094f6535: prefetchnta 0x180(%r9)
0.09% 0x00007f1f094f653d: shr $0x3,%rcx
0.00% 0x00007f1f094f6541: add $0xfffffffffffffffe,%rcx
0x00007f1f094f6545: xor %rax,%rax
0x00007f1f094f6548: cmp $0x8,%rcx
╭ 0x00007f1f094f654c: jg 0x00007f1f094f655e ; large enough? jump
│ 0x00007f1f094f654e: dec %rcx
│╭ 0x00007f1f094f6551: js 0x00007f1f094f6565 ; zero length? jump
││↗ 0x00007f1f094f6553: mov %rax,(%rdi,%rcx,8) ; small loop init
│││ 0x00007f1f094f6557: dec %rcx
││╰ 0x00007f1f094f655a: jge 0x00007f1f094f6553
││ ╭ 0x00007f1f094f655c: jmp 0x00007f1f094f6565
↘│ │ 0x00007f1f094f655e: shl $0x3,%rcx
89.12% │ │ 0x00007f1f094f6562: rep rex.W stos %al,%es:(%rdi) ; large loop init
0.20% ↘ ↘ 0x00007f1f094f6565: mov %r8,(%rsp)You may find this code shape familiar from "TLAB Allocation" and "New Object Stages" issues in the series. What is interesting here, is that we have to initialize much larger chunk of array data. For this reason, we see the inlined rep stos sequence on x86 — which repeatedly stores the given number of given byte — and seems most effective on recent x86-s. One can spy with a little eye that there is also an initializing loop for small arrays (smaller or equal of 8 elements) — rep stos has upfront startup costs, so smaller loop is beneficial there.
This example shows that for large objects/arrays initialization costs would dominate the performance. If objects/arrays are small, then writes of metadata (headers, array lengths) would dominate. Small array case would not be significantly different from small object case.
Can we guesstimate what would the performance be, if we somehow avoid initialization? The compilers are routinely coalesce system and user initialization, but can we get no initialization at all? Granted, it would serve no practical purpose to have uninitialized object, because we will still fill it with user data later — but synthetic tests are fun, am I right?
Turns out, there is an Unsafe method that allocates uninitialized arrays, so we may use it to see the benefits. Unsafe is not Java, it does not play by Java rules, and it sometimes even defies the JVM rules. It is not the API for the public use, and it is there for internal JDK use and JDK-VM interoperability. You can’t have it, it is not guaranteed to work for you, and it can go away, crash and burn without telling you.
Still, we can use it in synthetics, like this:
import jdk.internal.misc.Unsafe;
import org.openjdk.jmh.annotations.*;
@Warmup(iterations = 5, time = 1, timeUnit = TimeUnit.SECONDS)
@Measurement(iterations = 5, time = 1, timeUnit = TimeUnit.SECONDS)
@Fork(value = 3)
@BenchmarkMode(Mode.AverageTime)
@OutputTimeUnit(TimeUnit.NANOSECONDS)
@State(Scope.Benchmark)
public class UA {
static Unsafe U;
static {
try {
Field field = Unsafe.class.getDeclaredField("theUnsafe");
field.setAccessible(true);
U = (Unsafe) field.get(null);
} catch (Exception e) {
throw new IllegalStateException(e);
}
}
@Param({"1", "10", "100", "1000", "10000", "100000"})
int size;
@Benchmark
public byte[] unsafe() {
return (byte[]) U.allocateUninitializedArray(byte.class, size);
}
}Why don’t we run it? Okay:
Benchmark (size) Mode Cnt Score Error Units
UA.unsafe 1 avgt 15 19.766 ± 4.002 ns/op
UA.unsafe 10 avgt 15 27.486 ± 7.005 ns/op
UA.unsafe 100 avgt 15 80.040 ± 15.754 ns/op
UA.unsafe 1000 avgt 15 156.041 ± 0.552 ns/op
UA.unsafe 10000 avgt 15 162.384 ± 1.448 ns/op
UA.unsafe 100000 avgt 15 309.769 ± 2.819 ns/op
UA.unsafe:·gc.alloc.rate 1 avgt 15 6359.987 ± 928.472 MB/sec
UA.unsafe:·gc.alloc.rate 10 avgt 15 6193.103 ± 1160.353 MB/sec
UA.unsafe:·gc.alloc.rate 100 avgt 15 7855.147 ± 1313.314 MB/sec
UA.unsafe:·gc.alloc.rate 1000 avgt 15 33171.384 ± 153.645 MB/sec
UA.unsafe:·gc.alloc.rate 10000 avgt 15 315740.299 ± 3678.459 MB/sec
UA.unsafe:·gc.alloc.rate 100000 avgt 15 1650860.763 ± 14498.920 MB/secHoly crap! 100K arrays are allocated with 1.6 terabytes per second rate. Can we see where we spend time now?
0x00007f65fd722c74: prefetchnta 0xc0(%r11)
66.06% 0x00007f65fd722c7c: movq $0x1,(%rax) ; store mark word
0.40% 0x00007f65fd722c83: prefetchnta 0x100(%r11)
4.43% 0x00007f65fd722c8b: movl $0xf80000f5,0x8(%rax) ; store class word
0.01% 0x00007f65fd722c92: mov %edx,0xc(%rax) ; store array length
0x00007f65fd722c95: prefetchnta 0x140(%r11)
5.18% 0x00007f65fd722c9d: prefetchnta 0x180(%r11)
4.99% 0x00007f65fd722ca5: mov %r8,0x40(%rsp)
0x00007f65fd722caa: mov %rax,%rdxOh yeah, touching the memory to push the metadata out. The cycles accounting is skewed towards the prefetches, because they are now paying the most of the cost for pre-accessing memory for upcoming writes.
One might wonder what toll that exerts on GC, and the answer is: not that much! The objects are almost all dead, and so any mark-(copy|sweep|compact) GC would breeze through the workload like this. When objects start surviving at TB/sec rate, the picture gets interesting. Some GC guys I know call these things "impossible workloads" — because they both impossible in reality, and impossible to deal with. Try to drink from a firehose to learn this in practice.
Anyhow, we can see that with pure allocations, GCs are surviving fine. With the same workload, we can see what are the apparent application pauses, by using JMH’s -prof pauses profiler. It runs a high-priority thread and records the perceived pauses:
Benchmark (size) Mode Cnt Score Error Units
UA.unsafe 100000 avgt 5 315.732 ± 5.133 ns/op
UA.unsafe:·pauses 100000 avgt 84 537.018 ms
UA.unsafe:·pauses.avg 100000 avgt 6.393 ms
UA.unsafe:·pauses.count 100000 avgt 84.000 #
UA.unsafe:·pauses.p0.00 100000 avgt 2.560 ms
UA.unsafe:·pauses.p0.50 100000 avgt 6.148 ms
UA.unsafe:·pauses.p0.90 100000 avgt 9.642 ms
UA.unsafe:·pauses.p0.95 100000 avgt 9.802 ms
UA.unsafe:·pauses.p0.99 100000 avgt 14.418 ms
UA.unsafe:·pauses.p0.999 100000 avgt 14.418 ms
UA.unsafe:·pauses.p0.9999 100000 avgt 14.418 ms
UA.unsafe:·pauses.p1.00 100000 avgt 14.418 msSo, it had detected around 84 pauses, the longest is 14 ms, while the average is about 6 ms. Profilers like these are inherently imprecise, because they contend on CPUs with workload threads, they get into the mercy of OS scheduler, etc.
In many cases, it is better to enable the JVM to tell when it stops the application threads. This can be done with JMH’s -prof safepoints profiler, which records the "safe point", "stop the world" events when all application threads are stopped, and VM does its work. GC pauses are naturally the subset of safepoint events.
Benchmark (size) Mode Cnt Score Error Units
UA.unsafe 100000 avgt 5 328.247 ± 34.450 ns/op
UA.unsafe:·safepoints.interval 100000 avgt 5043.000 ms
UA.unsafe:·safepoints.pause 100000 avgt 639 617.796 ms
UA.unsafe:·safepoints.pause.avg 100000 avgt 0.967 ms
UA.unsafe:·safepoints.pause.count 100000 avgt 639.000 #
UA.unsafe:·safepoints.pause.p0.00 100000 avgt 0.433 ms
UA.unsafe:·safepoints.pause.p0.50 100000 avgt 0.627 ms
UA.unsafe:·safepoints.pause.p0.90 100000 avgt 2.150 ms
UA.unsafe:·safepoints.pause.p0.95 100000 avgt 2.241 ms
UA.unsafe:·safepoints.pause.p0.99 100000 avgt 2.979 ms
UA.unsafe:·safepoints.pause.p0.999 100000 avgt 12.599 ms
UA.unsafe:·safepoints.pause.p0.9999 100000 avgt 12.599 ms
UA.unsafe:·safepoints.pause.p1.00 100000 avgt 12.599 msSee, this profiler records 639 safepoints, with average time of less than 1 ms, and the largest time of 12 ms. Not bad, taking into account 1.6 TB/sec allocation rate!
Observations
The initialization costs are the significant part of object/array instantiation. With TLAB allocation, the object/array creation speed is largely dominated by either metadata writes (for smaller things), or the content initialization (for larger things). The allocation rate alone is not always a good predictor of performance, as you can manage huge allocation rates if you runtime pulls weird tricks on you.