RFR(S): 8005885: enhance PrintCodeCache to print more data

[Vladimir Kozlov]

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.

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

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.