G1: Assert message is being constructed even with asserts disabled?

[Vitaly Davidovich]

Maybe instead turn err_msg into a macro (e.g. ERR_MSG) that expands to NULL
if assertions are disabled?

Sent from my phone
On Sep 11, 2013 5:16 PM, "Stefan Karlsson" <stefan.karlsson at oracle.com>
wrote:

>  On 9/11/13 10:46 PM, Aleksey Shipilev wrote:
>
> (please disregard the previous message, if any, sent from un-subscribed
> email address)
>
> Hi there,
>
> I did not believe my eyes at first. Please look at this and tell me I am
> not imagining things because of too much green tea. I can submit the bug
> after somebody else confirms.
>
> There is some workload which runs significantly slower with G1 than with
> Parallel GC. So, I profile this application, and what I see?
>
>
>     |    |  +-  131.100   (60%)    ConcurrentG1RefineThread::run()
>    |    |  |  +-  131.020   (60%)    DirtyCardQueueSet::apply_closure_to_completed_buffer(int, int, bool)
>    |    |  |  |  +-  130.870   (60%)    DirtyCardQueueSet::apply_closure_to_completed_buffer_helper(CardTableEntryClosure*, int, BufferNode*)
>    |    |  |  |  |  +-  128.650   (59%)    RefineCardTableEntryClosure::do_card_ptr(signed char*, int)
>    |    |  |  |  |  |  +-  127.290   (59%)    G1RemSet::refine_card(signed char*, int, bool)
>    |    |  |  |  |  |    +-  61.260   (28%)    G1HotCardCache::insert(signed char*)
>    |    |  |  |  |  |    |  +-  59.650   (27%)    G1CardCounts::add_card_count(signed char*)
>    |    |  |  |  |  |    |  |  +-  57.340   (26%)    G1CardCounts::ptr_2_card_num(const signed char*)
>    |    |  |  |  |  |    |  |    +-  56.420   (26%)    FormatBuffer<256>::FormatBuffer(const char*, ...)
>    |    |  |  |  |  |    |  |      +-  54.240   (25%)    vsnprintf
>    |    |  |  |  |  |    |  |      |  +-  44.350   (20%)    vfprintf
>    |    |  |  |  |  |    |  |      |  |  +-  8.950   (4%)    _IO_default_xsputn
>    |    |  |  |  |  |    |  |      |  |  |  +-  1.660   (1%)    <static>@0x8b5f4 (<libc-2.15.so>)
>    |    |  |  |  |  |    |  |      |  |  +-  5.160   (2%)    _IO_padn
>    |    |  |  |  |  |    |  |      |  |  +-  4.470   (2%)    <static>@0x4872c (<libc-2.15.so>)
>    |    |  |  |  |  |    |  |      |  |  +-  4.110   (2%)    free
>    |    |  |  |  |  |    |  |      |  |  +-  1.780   (1%)    strchrnul
>    |    |  |  |  |  |    |  |      |  +-  3.450   (2%)    <static>@0x7c3f7 (<libc-2.15.so>)
>    |    |  |  |  |  |    |  |      |  +-  2.870   (1%)    <static>@0x7d270 (<libc-2.15.so>)
>    |    |  |  |  |  |    |  |      |  +-  1.200   (1%)    strchrnul
>    |    |  |  |  |  |    |  |      +-  0.290   (0%)    jio_vsnprintf
>
>
>
> Say what? FormatBuffer? In GC refinement thread (which supposedly drains
> card marks)? In ptr_2_card_num() converter method?
>
> Looking deeper:
>
>   typedef FormatBuffer<> err_msg;
> ...
>   void check_card_num(size_t card_num) {
>     assert(card_num >= 0 && card_num < _committed_max_card_num,
>             err_msg("card num out of range: "SIZE_FORMAT, card_num));
>   }
> ...
>   size_t ptr_2_card_num(const jbyte* card_ptr) {
>     assert(card_ptr >= _ct_bot,
>            err_msg("Inavalied card pointer: "
>                    "card_ptr: " PTR_FORMAT ", "
>                     "_ct_bot: " PTR_FORMAT,
>                     card_ptr, _ct_bot));
>      size_t card_num = pointer_delta(card_ptr, _ct_bot, sizeof(jbyte));
>      check_card_num(card_num,
>                    err_msg("card pointer out of range: " PTR_FORMAT,
> card_ptr));
>      return card_num;
>    }
>
> Well, d'uh! Even though the asserts are erased in the product build,
> err_msg argument for check_card_num() call is still there, thrashing
> out. So, I do this quick and safe change:
>   http://cr.openjdk.java.net/~shade/scratch/g1-cardmark-wtf/webrev/
>
> Also, I churn down the workload into the essential one, trashing the heap:http://cr.openjdk.java.net/~shade/scratch/g1-cardmark-wtf/test/src/main/java/org/sample/MyBenchmark.java
>
> Running with latest hsx/hotspot-gc on my 1x2x2 i5 laptop, Linux x86_64,
> with "{baseline,patched}/bin/java -XX:+UseG1GC -jar microbenchmarks.jar
> -t 4 -f 5", which means four threads, five forked JVM runs, I got:
>
>   baseline:  125.3 +- 4.9 ns/op
>    patched:   85.8 +- 3.5 ns/op
>
> ...which means 1.47x improvement!
>
>
> Wow! Nice finding.
>
> Would it be possible to keep the assert message by turning
> check_card_num() into a #define instead? I don't know if that matters or
> not, though.
>
> Will you create a bug report?
>
> thanks,
> StefanK
>
>
>
> -Aleksey.
>
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://mail.openjdk.org/pipermail/hotspot-gc-dev/attachments/20130911/a61c131e/attachment.htm>