RFR(S): 8005885: enhance PrintCodeCache to print more data
Albert Noll
albert.noll at oracle.com
Mon Aug 26 23:45:18 PDT 2013
Hi,
Chris P., Vladimir, and Christian T., thanks for looking at the code.
One note: We currently have a lot of -XX flags to provide information
about the code
cache (PrintCodeCache, PrintCodeCacheDetails, +Verbose,
PrintCodecacheOnCompilation,
and PrintCodeCacheAllocation.
We could combine these flags (or at least some of them) into one Integer
flag that gives the
level of detail that is printed. For example, we could make
-XX:PrintCodeCache=int
where: (this suggestion is not contained in the current patch)
int==0 -> no debug output
int==1 -> same debug output is PrintCodeCache
int==2 -> same debug output as PrintCodeCodeCacheDetails
int==3 -> same debug output as with int==1 and int==2 + Verbose
int==4 -> same debug output as with int==3 + PrintCodeCacheOnCompilation
int==5-> same debug output as with int==4 + PrintCodeCacheAllocation
Having levels of detail that can be specified via a variable seems
intuitive to
me. Please let me know what you think.
Here is the new webrev:
http://cr.openjdk.java.net/~anoll/8005885/webrev.01/
<http://cr.openjdk.java.net/%7Eanoll/8005885/webrev.01/>
I modified the patch so that the output is less verbose. Here are samples of
the output:
java -XX:+PrintCodeCache ...
CodeCache: size=245760kB used=8862kB max_used=9120kB free=236897kB
Interpreter=799kB live_nmethods=1565(6894kB) dead_nmethods=34(196kB)
stubs=77(1518kB) adapters=212(159kB)
bounds [0x00007f1195000000, 0x00007f1195900000, 0x00007f11a4000000]
compilation: enabled
java -XX:+PrintCodeCache -XX:+PrintCodeCacheDetails
CodeCache: size=245760kB used=9110kB max_used=9126kB free=236649kB
Interpreter=799kB live_nmethods=1607(7267kB) dead_nmethods=11(71kB)
stubs=77(1515kB) adapters=212(159kB)
bounds [0x00007f81cbb7c000, 0x00007f81cc47c000, 0x00007f81dab7c000]
compilation: enabled
Code cache entries: (total of #1907)
nmethods: #1618 7338kB
Java: #1576 7295kB
Tier 1: #236 213kB
Tier 2: #792 3280kB
Tier 3: #358 2349kB
Tier 4: #190 1451kB
Native: #42 43kB
runtime-stubs: #59 44kB
adapters: #212 159kB
buffer blobs: #12 1467kB
deopt-stubs: #1 1kB
uncommon-traps: #1 0kB
others: #4 2kB
nmethod state distribution
in-use: #1562 6596kB
not-entrant: #45 670kB
zombie: #11 71kB
unloaded: #0 0kB
java -XX:+PrintCodeCache -XX:+PrintCodeCacheDetails -XX:+Verbose
CodeCache: size=245760kB used=8907kB max_used=8995kB free=236852kB
Interpreter=799kB live_nmethods=1584(6973kB) dead_nmethods=29(164kB)
stubs=78(1517kB) adapters=212(159kB)
bounds [0x00007f4c4bda8000, 0x00007f4c4c688000, 0x00007f4c5ada8000]
compilation: enabled
Code cache entries: (total of #1903)
nmethods: #1613 7137kB
Java: #1572 7095kB
Tier 1: #245 221kB
Tier 2: #792 3261kB
Tier 3: #343 2238kB
Tier 4: #192 1373kB
Native: #41 42kB
runtime-stubs: #59 44kB
adapters: #212 159kB
buffer blobs: #13 1469kB
deopt-stubs: #1 1kB
uncommon-traps: #1 0kB
others: #4 2kB
nmethod state distribution
in-use: #1537 6447kB
not-entrant: #47 526kB
zombie: #29 164kB
unloaded: #0 0kB
nmethod size distribution (non-zombie java)
0 - 512 bytes 556
512 - 1024 bytes 318
1024 - 1536 bytes 156
1536 - 2048 bytes 109
2048 - 2560 bytes 87
2560 - 3072 bytes 56
3072 - 3584 bytes 40
3584 - 4096 bytes 32
4096 - 4608 bytes 28
4608 - 5120 bytes 31
5120 - 5632 bytes 10
5632 - 6144 bytes 12
6144 - 6656 bytes 8
6656 - 7168 bytes 11
7168 - 7680 bytes 12
7680 - 8192 bytes 14
8192 - 8704 bytes 2
8704 - 9216 bytes 7
9216 - 9728 bytes 6
9728 - 10240 bytes 4
10240 - 10752 bytes 5
10752 - 11264 bytes 7
11264 - 11776 bytes 1
11776 - 12288 bytes 2
12288 - 12800 bytes 1
12800 - 13312 bytes 3
13312 - 13824 bytes 2
13824 - 14336 bytes 3
14336 - 14848 bytes 2
14848 - 15360 bytes 6
15360 - 15872 bytes 5
15872 - 16384 bytes 1
16896 - 17408 bytes 1
17408 - 17920 bytes 1
17920 - 18432 bytes 3
18432 - 18944 bytes 2
18944 - 19456 bytes 2
19968 - 20480 bytes 2
22016 - 22528 bytes 3
22528 - 23040 bytes 1
23552 - 24064 bytes 2
25088 - 25600 bytes 1
25600 - 26112 bytes 2
26112 - 26624 bytes 1
27136 - 27648 bytes 1
27648 - 28160 bytes 1
28672 - 29184 bytes 1
30208 - 30720 bytes 1
31744 - 32256 bytes 1
35328 - 35840 bytes 1
35840 - 36352 bytes 1
36864 - 37376 bytes 1
37376 - 37888 bytes 1
41472 - 41984 bytes 1
43520 - 44032 bytes 1
47104 - 47616 bytes 1
49664 - 50176 bytes 1
58368 - 58880 bytes 1
nmethod dependency checking time 0.205156
java -XX:+PrintCodeCacheOnCompilation
CodeCache: size=245760kB used=1610kB max_used=1610kB free=244149kB
java -XX:PrintCodeCacheAllocation:
CodeCache allocation: addr: 0x00007f7ed1190850, size: 1984B
Best,
Albert
On 23.08.2013 21:24, Christian Thalinger wrote:
> On Aug 23, 2013, at 11:34 AM, Vladimir Kozlov <vladimir.kozlov at oracle.com> wrote:
>
>> Albert,
>>
>> I think you are missing constant section from nmethods or something else because % are not add up to 100%. Can you also try on SPARC?
>>
>> #500 Java methods = 1119K (hdr 12%, loc 4%, code 38%, stub 2%, [oops 0%, data 1%, pcs 24%])
>>
>> Use Kb when you show size.
> Actually, kB (http://en.wikipedia.org/wiki/Kilobyte).
>
>> I agree with Chris P. that output is too verbose for product *by default* - I thinks we don't need splitting per tiers and detail section sizes information. Note, this will be put into hs_err files. I don't see how this additional information will help to debug problems.
>>
>> I think by default PrintCodeCache should should sligthly verbose current output: add sizes, split live/dead nmethods, add interpreter and stubs instead of blobs and may be something else:
>>
>> CodeCache: size=49152Kb used=1729Kb max_used=1782Kb free=47422Kb
>> bounds [0x00007fbc13fb1000, 0x00007fbc14221000, 0x00007fbc16fb1000]
>> interpreter=199Kb stubs=302(400Kb) live_nmethods=510(1119Kb) dead_nmethods=2(85Kb) adapters=254(116Kb)
>> compilation: enabled
>>
>>
>> It could be important when you are working on codecache improvement or want to see how it is used. And, yes it would be nice to get detailed info in product VM also. Unfortunately Verbose flag is not product and in some places it guards code which we don't want in product VM so we can't make it product.
>>
>> Maybe you can convert PrintCodeCache2 to 'diagnostic' flag and use it for detailed information (it already does additional printing). But add new develop flag to replace it in print_trace():
>>
>> void CodeCache::print_trace(const char* event, CodeBlob* cb, int size) {
>> if (PrintCodeCache2) { // Need to add a new flag
> I agree with Vladimir. Can you also rename PrintCodeCache2 to PrintCodeCacheDetails?
>
> -- Chris
>
>> Thanks,
>> Vladimir
>>
>> On 8/23/13 6:31 AM, Albert Noll wrote:
>>> Hi,
>>>
>>> could I get reviews for the following patch?
>>>
>>> jbs: https://bugs.openjdk.java.net/browse/JDK-8005885
>>> webrev: http://cr.openjdk.java.net/~anoll/8005885/webrev.00/
>>> <http://cr.openjdk.java.net/%7Eanoll/8005885/webrev.00/>
>>>
>>> Many thanks in advance,
>>> Albert
>>>
>>> Problem: Currently we only print:
>>>
>>> CodeCache:
>>> nmethod dependency checking time 0.037552
>>> #944 live = 3681K (hdr 4%, loc 2%, code 74%, stub 1%, [oops 0%, data
>>> 0%, pcs 5%])
>>> #92 dead = 247K (hdr 7%, loc 6%, code 46%, stub 3%, [oops 0%, data 0%,
>>> pcs 12%])
>>>
>>> It would be helpful to have more detailed information about the code cache.
>>>
>>> Solution: add more detailed information about the content of the code
>>> cache when
>>> exiting the VM.
>>>
>>>
>>> See sample outputs:
>>> java -XX:-TieredCompilation -XX:+PrintCodeCache -jar
>>> dacapo-9.12-bach.jar fop
>>> ===== DaCapo 9.12 fop starting =====
>>> ===== DaCapo 9.12 fop PASSED in 7676 msec =====
>>> CodeCache: size=49152Kb used=1729Kb max_used=1782Kb free=47422Kb
>>> bounds [0x00007fbc13fb1000, 0x00007fbc14221000, 0x00007fbc16fb1000]
>>> total_blobs=814 nmethods=512 adapters=254
>>> compilation: enabled
>>>
>>> Interpreter: total=199k, used=124k
>>>
>>> Total number of live methods: 510
>>> Tier 1:
>>> #0 Java methods
>>> #0 OSR methods
>>> Tier 2:
>>> #0 Java methods
>>> #0 OSR methods
>>> Tier 3:
>>> #0 Java methods
>>> #0 OSR methods
>>> Tier 4:
>>> #500 Java methods = 1119K (hdr 12%, loc 4%, code 38%, stub 2%, [oops
>>> 0%, data 1%, pcs 24%])
>>> #5 OSR methods = 37K (hdr 3%, loc 3%, code 41%, stub 2%, [oops 0%,
>>> data 1%, pcs 30%])
>>> Native methods:
>>> #5 Native methods = 4K (hdr 31%, loc 10%, code 55%, stub 0%, [oops
>>> 0%, data 0%, pcs 0%])
>>>
>>> Total number of dead methods: 2
>>> Tier 1:
>>> #0 Java methods
>>> #0 OSR methods
>>> Tier 2:
>>> #0 Java methods
>>> #0 OSR methods
>>> Tier 3:
>>> #0 Java methods
>>> #0 OSR methods
>>> Tier 4:
>>> #1 Java methods = 67K (hdr 0%, loc 3%, code 41%, stub 0%, [oops 0%,
>>> data 0%, pcs 40%])
>>> #1 OSR methods = 18K (hdr 1%, loc 4%, code 39%, stub 2%, [oops 0%,
>>> data 1%, pcs 31%])
>>> Native methods:
>>> #0 Native methods
>>>
>>> Total number of stubs: 302
>>> #23 runtime = 5K (hdr 25%, loc 1%, code 67%, stub 0%, [oops 0%, data
>>> 0%, pcs 0%])
>>> #1 deoptimization = 1K (hdr 7%, loc 0%, code 89%, stub 0%, [oops 0%,
>>> data 0%, pcs 0%])
>>> #1 uncommon trap = 0K (hdr 13%, loc 1%, code 83%, stub 0%, [oops 0%,
>>> data 0%, pcs 0%])
>>> #1 exception = 0K (hdr 27%, loc 3%, code 65%, stub 0%, [oops 0%,
>>> data 0%, pcs 0%])
>>> #3 safepoint = 1K (hdr 10%, loc 1%, code 86%, stub 0%, [oops 0%,
>>> data 0%, pcs 0%])
>>> #254 C2I/I2C adapter = 116K (hdr 13%, loc 1%, code 82%, stub 0%,
>>> [oops 0%, data 0%, pcs 0%])
>>> #0 method handles adapter
>>> #19 other = 308K (hdr 0%, loc 0%, code 99%, stub 0%, [oops 0%, data
>>> 0%, pcs 0%])
>>>
>>>
>>> java -XX:+TieredCompilation -XX:+PrintCodeCache -jar
>>> dacapo-9.12-bach.jar fop
>>> ===== DaCapo 9.12 fop starting =====
>>> ===== DaCapo 9.12 fop PASSED in 4850 msec =====
>>> CodeCache: size=245760Kb used=7355Kb max_used=7370Kb free=238404Kb
>>> bounds [0x00007f49fd000000, 0x00007f49fd740000, 0x00007f4a0c000000]
>>> total_blobs=2578 nmethods=2240 adapters=254
>>> compilation: enabled
>>>
>>> Interpreter: total=199k, used=123k
>>>
>>> Total number of live methods: 2205
>>> Tier 1:
>>> #466 Java methods = 333K (hdr 39%, loc 5%, code 25%, stub 19%, [oops
>>> 0%, data 0%, pcs 1%])
>>> #0 OSR methods
>>> Tier 2:
>>> #429 Java methods = 1047K (hdr 11%, loc 5%, code 40%, stub 8%, [oops
>>> 0%, data 1%, pcs 18%])
>>> #0 OSR methods
>>> Tier 3:
>>> #1069 Java methods = 3817K (hdr 7%, loc 4%, code 53%, stub 5%, [oops
>>> 0%, data 0%, pcs 17%])
>>> #5 OSR methods = 92K (hdr 1%, loc 4%, code 57%, stub 2%, [oops 0%,
>>> data 0%, pcs 23%])
>>> Tier 4:
>>> #190 Java methods = 648K (hdr 8%, loc 3%, code 43%, stub 1%, [oops
>>> 0%, data 1%, pcs 26%])
>>> #3 OSR methods = 15K (hdr 5%, loc 3%, code 47%, stub 1%, [oops 0%,
>>> data 0%, pcs 28%])
>>> Native methods:
>>> #43 Native methods = 37K (hdr 31%, loc 10%, code 55%, stub 0%, [oops
>>> 0%, data 0%, pcs 0%])
>>>
>>> Total number of dead methods: 35
>>> Tier 1:
>>> #0 Java methods
>>> #0 OSR methods
>>> Tier 2:
>>> #3 Java methods = 22K (hdr 3%, loc 5%, code 40%, stub 6%, [oops 0%,
>>> data 1%, pcs 27%])
>>> #0 OSR methods
>>> Tier 3:
>>> #31 Java methods = 193K (hdr 4%, loc 4%, code 54%, stub 3%, [oops
>>> 0%, data 0%, pcs 21%])
>>> #1 OSR methods = 2K (hdr 11%, loc 5%, code 52%, stub 7%, [oops 0%,
>>> data 0%, pcs 7%])
>>> Tier 4:
>>> #0 Java methods
>>> #0 OSR methods
>>> Native methods:
>>> #0 Native methods
>>>
>>> Total number of stubs: 338
>>> #57 runtime = 24K (hdr 14%, loc 3%, code 79%, stub 0%, [oops 0%,
>>> data 0%, pcs 0%])
>>> #1 deoptimization = 1K (hdr 7%, loc 0%, code 89%, stub 0%, [oops 0%,
>>> data 0%, pcs 0%])
>>> #1 uncommon trap = 0K (hdr 13%, loc 1%, code 83%, stub 0%, [oops 0%,
>>> data 0%, pcs 0%])
>>> #1 exception = 0K (hdr 27%, loc 3%, code 65%, stub 0%, [oops 0%,
>>> data 0%, pcs 0%])
>>> #3 safepoint = 1K (hdr 10%, loc 1%, code 86%, stub 0%, [oops 0%,
>>> data 0%, pcs 0%])
>>> #254 C2I/I2C adapter = 116K (hdr 13%, loc 1%, code 82%, stub 0%,
>>> [oops 0%, data 0%, pcs 0%])
>>> #0 method handles adapter
>>> #21 other = 871K (hdr 0%, loc 0%, code 99%, stub 0%, [oops 0%, data
>>> 0%, pcs 0%])
>>>
>>>
>>> Please let me know if you think more/less/different data should be printed.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://mail.openjdk.java.net/pipermail/hotspot-compiler-dev/attachments/20130827/79c4fd60/attachment-0001.html
More information about the hotspot-compiler-dev
mailing list