Deoptimization taking up most CPU cycles

[Aleksey Shipilev]

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/presto/spi/ConnectorSession;Lcom/facebook/presto/spi/block/Block;Lcom/facebook/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