Deoptimization taking up most CPU cycles

[Chris Newland]

fyi A very similar problem was reported on hotspot-compiler-dev this week:
http://mail.openjdk.java.net/pipermail/hotspot-compiler-dev/2016-June/023278.html

In response to that thread I've just pushed some code in JITWatch for
visualising sweeps and the point at which compilation gets disabled [1].
Hope that's useful.

Cheers,

Chris

[1] https://github.com/AdoptOpenJDK/jitwatch

On Mon, June 6, 2016 18:34, Aleksey Shipilev wrote:
> On 06/06/2016 07:58 PM, Haozhun Jin wrote:
>
>> $34746 = 0x7f7a7cc67bf0 "Uncommon trap: reason=%s action=%s pc=0x%016lx
>>  method=%s @ %d" $34747 = 0x7f7a7cc67905 "unstable_if"
>> $34748 = 0x7f7a7cc4d0ba "none"
>> $34749 = 0x7f7a14f422c0
>> "com_facebook_presto_$gen_PageProcessor_440742.filter(Lcom/facebook/pres
>> to/spi/ConnectorSession;Lcom/facebook/presto/spi/block/Block;Lcom/faceb
>> ook/presto/spi/block/Block;Lcom/facebook/presto/spi/block/"... $34750 =
>> 450
>>
>
> Looking at HotSpot source code, action="None" seems to mean:
>
>
> enum DeoptAction { Action_none,  // just interpret, do not invalidate
> nmethod
>
> ...which probably means you end up calling cold branch via trap to
> interpreter always, and die trashing compiled->trap->interpreter
> transitions.
>
> I see the we emit with Action_reinterpret for Reason_unstable_if:
>
>
> void Parse::adjust_map_after_if(...) { ...
> if (path_is_suitable_for_uncommon_trap(prob)) { repush_if_args();
> uncommon_trap(Deoptimization::Reason_unstable_if,
> Deoptimization::Action_reinterpret,
> NULL,
> (is_fallthrough ? "taken always" : "taken never"));
> return; }
>
>
> ...but in the downcall:
>
>
> void GraphKit::uncommon_trap(...) { ...
> case Deoptimization::Action_reinterpret: // Temporary fix for 6529811 to
> allow virtual calls to be sure they // get the chance to go from
> mono->bi->mega if (!keep_exact_action &&
> Deoptimization::trap_request_index(trap_request) < 0 &&
> too_many_recompiles(reason)) { // This BCI is causing too many
> recompilations. if (C->log() != NULL) { C->log()->elem("observe
> that='trap_action_change' reason='%s' from='%s' to='none'",
> Deoptimization::trap_reason_name(reason),
> Deoptimization::trap_action_name(action));
> }
> action = Deoptimization::Action_none; trap_request =
> Deoptimization::make_trap_request(reason, action);
>
>
> The comment leads to:
> https://bugs.openjdk.java.net/browse/JDK-6529811
>
>
> ...which manifestation looks suspiciously like the issue you are
> describing. For one, I wonder why do we overwrite with Action_none, while
> safer alternative would be deoptimize hard on too many recompiles and run
> in interpreter with Action_make_not_compilable.
>
>
>> * Are there any options we can turn on next time we start the process
>> that could help troubleshoot this when it happens again?
>
> I would guess -XX:+LogCompilation -XX:LogFile=somewhere.log would be
> nice to have to better diagnose cases like these. But if you are under the
> uncommon_trap storm, that file can get rather large.
>
> Thanks,
> -Aleksey
>
>
>