Fix problem of excessive attempts to optimize, fix excessive deoptimizations for load/store indexed…

runtime/vm/code_generator.cc

 // Copyright (c) 2012, the Dart project authors.  Please see the AUTHORS file
 // for details. All rights reserved. Use of this source code is governed by a
 // BSD-style license that can be found in the LICENSE file.
 
 #include "vm/code_generator.h"
 
 #include "vm/assembler_macros.h"
 #include "vm/ast.h"
 #include "vm/code_patcher.h"
 #include "vm/compiler.h"
 #include "vm/dart_api_impl.h"
 #include "vm/dart_entry.h"
 #include "vm/debugger.h"
 #include "vm/exceptions.h"
 #include "vm/object_store.h"
 #include "vm/message.h"
 #include "vm/message_handler.h"
 #include "vm/resolver.h"
 #include "vm/runtime_entry.h"
 #include "vm/stack_frame.h"
 #include "vm/verifier.h"
 
 namespace dart {
 
-DEFINE_FLAG(bool, inline_cache, true, "enable inline caches");
+DEFINE_FLAG(bool, inline_cache, true, "Enable inline caches");
 DEFINE_FLAG(bool, trace_deopt, false, "Trace deoptimization");
-DEFINE_FLAG(bool, trace_ic, false, "trace IC handling");
+DEFINE_FLAG(bool, trace_ic, false, "Trace IC handling");
 DEFINE_FLAG(bool, trace_patching, false, "Trace patching of code.");
-DEFINE_FLAG(bool, trace_runtime_calls, false, "Trace runtime calls.");
+DEFINE_FLAG(bool, trace_runtime_calls, false, "Trace runtime calls");
 DEFINE_FLAG(int, optimization_counter_threshold, 2000,
-    "function's usage-counter value before it is optimized, -1 means never.");
+    "Function's usage-counter value before it is optimized, -1 means never");
 DECLARE_FLAG(bool, enable_type_checks);
 DECLARE_FLAG(bool, trace_type_checks);
 DECLARE_FLAG(bool, report_usage_count);
 DECLARE_FLAG(int, deoptimization_counter_threshold);
 DEFINE_FLAG(charp, optimization_filter, NULL, "Optimize only named function");
+DEFINE_FLAG(bool, trace_failed_optimization_attempts, false,
+    "Traces all failed optimization attempts");
 
 
 DEFINE_RUNTIME_ENTRY(TraceFunctionEntry, 1) {
   ASSERT(arguments.Count() == kTraceFunctionEntryRuntimeEntry.argument_count());
   const Function& function = Function::CheckedHandle(arguments.At(0));
   const String& function_name = String::Handle(function.name());
   const String& class_name =
       String::Handle(Class::Handle(function.owner()).Name());
   OS::Print("> Entering '%s.%s'\n",
       class_name.ToCString(), function_name.ToCString());
@@ skipping 1219 matching lines @@
         return;
       } else {
         // TODO(turnidge): Unwind the stack.
         UNIMPLEMENTED();
       }
     }
   }
 }
 
 
+static void PrintCaller(const char* msg) {
+  DartFrameIterator iterator;
+  StackFrame* top_frame = iterator.NextFrame();
+  ASSERT(top_frame != NULL);
+  const Function& top_function = Function::Handle(
+      top_frame->LookupDartFunction());
+  OS::Print("Failed: '%s' %s @ 0x%x\n",
+      msg, top_function.ToFullyQualifiedCString(), top_frame->pc());
+  StackFrame* caller_frame = iterator.NextFrame();
+  if (caller_frame != NULL) {
+    const Function& caller_function = Function::Handle(
+        caller_frame->LookupDartFunction());
+    const Code& code = Code::Handle(caller_frame->LookupDartCode());
+    OS::Print("  -> caller: %s (%s)\n",
+        caller_function.ToFullyQualifiedCString(),
+        code.is_optimized() ? "optimized" : "unoptimized");
+  }
+}
+
+
+
 // Only unoptimized code has invocation counter threshold checking.
 // Once the invocation counter threshold is reached any entry into the
 // unoptimized code is redirected to this function.
 DEFINE_RUNTIME_ENTRY(OptimizeInvokedFunction, 1) {
   const intptr_t kLowInvocationCount = -100000000;
   ASSERT(arguments.Count() ==
          kOptimizeInvokedFunctionRuntimeEntry.argument_count());
   const Function& function = Function::CheckedHandle(arguments.At(0));
   if (isolate->debugger()->IsActive()) {
     // We cannot set breakpoints in optimized code, so do not optimize
     // the function.
     function.set_usage_counter(0);
     return;
   }
   if (function.deoptimization_counter() >=
       FLAG_deoptimization_counter_threshold) {
+    if (FLAG_trace_failed_optimization_attempts) {
+      PrintCaller("Too Many Deoptimizations");
+    }
     // TODO(srdjan): Investigate excessive deoptimization.
     function.set_usage_counter(kLowInvocationCount);
     return;
   }
   if (function.HasOptimizedCode()) {
-    // The caller has been already optimized.
-    // TODO(srdjan): This is a significant slowdown, the caller is probably in
-    // a loop. Maybe test if the code has been optimized before calling.
-    // If this happens from optimized code, then it means that the optimized
-    // code needs to be reoptimized.
-    function.set_usage_counter(kLowInvocationCount);
+    // The caller has been already optimized, the caller is probably in
+    // a loop or in a recursive call chain.
+    // Leave the usage_counter at the limit so that the count test knows that
+    // method is optimized.
+    if (FLAG_trace_failed_optimization_attempts) {
+      PrintCaller("Has Optimized Code");
+    }
+    // TODO(srdjan): Enable reoptimizing optimized code, but most recognize
+    // that reoptimization was not already applied.
     return;
   }
   if ((FLAG_optimization_filter != NULL) &&
       (strncmp(function.ToFullyQualifiedCString(),
                FLAG_optimization_filter,
                strlen(FLAG_optimization_filter)) != 0)) {
     function.set_usage_counter(kLowInvocationCount);
     return;
   }
   if (function.is_optimizable()) {
+    // Compilation patches the entry of unoptimized code.
     ASSERT(!function.HasOptimizedCode());
-    const Code& unoptimized_code = Code::Handle(function.unoptimized_code());
-    // Compilation patches the entry of unoptimized code.
     const Error& error =
         Error::Handle(Compiler::CompileOptimizedFunction(function));
     if (!error.IsNull()) {
       Exceptions::PropagateError(error);
     }
     const Code& optimized_code = Code::Handle(function.CurrentCode());
     ASSERT(!optimized_code.IsNull());
-    ASSERT(!unoptimized_code.IsNull());
+    function.set_usage_counter(0);
   } else {
+    if (FLAG_trace_failed_optimization_attempts) {
+      PrintCaller("Not Optimizable");
+    }
     // TODO(5442338): Abort as this should not happen.
     function.set_usage_counter(kLowInvocationCount);
   }
 }
 
 
 // The caller must be a static call in a Dart frame, or an entry frame.
 // Patch static call to point to 'new_entry_point'.
 DEFINE_RUNTIME_ENTRY(FixCallersTarget, 1) {
   ASSERT(arguments.Count() == kFixCallersTargetRuntimeEntry.argument_count());
@@ skipping 203 matching lines @@
       }
     }
   }
   // The cache is null terminated, therefore the loop above should never
   // terminate by itself.
   UNREACHABLE();
   return Code::null();
 }
 
 }  // namespace dart