Fix printing of the function that cannot be optimized.

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/bigint_operations.h"
 #include "vm/code_patcher.h"
@@ skipping 44 matching lines @@
     "Maximum number of subtype cache entries (number of checks cached).");
 
 
 DEFINE_RUNTIME_ENTRY(TraceFunctionEntry, 1) {
   ASSERT(arguments.ArgCount() ==
       kTraceFunctionEntryRuntimeEntry.argument_count());
   const Function& function = Function::CheckedHandle(arguments.ArgAt(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",
+  OS::PrintErr("> Entering '%s.%s'\n",
       class_name.ToCString(), function_name.ToCString());
 }
 
 
 DEFINE_RUNTIME_ENTRY(TraceFunctionExit, 1) {
   ASSERT(arguments.ArgCount() ==
       kTraceFunctionExitRuntimeEntry.argument_count());
   const Function& function = Function::CheckedHandle(arguments.ArgAt(0));
   const String& function_name = String::Handle(function.name());
   const String& class_name =
       String::Handle(Class::Handle(function.Owner()).Name());
-  OS::Print("< Exiting '%s.%s'\n",
+  OS::PrintErr("< Exiting '%s.%s'\n",
       class_name.ToCString(), function_name.ToCString());
 }
 
 
 // Allocation of a fixed length array of given element type.
 // This runtime entry is never called for allocating a List of a generic type,
 // because a prior run time call instantiates the element type if necessary.
 // Arg0: array length.
 // Arg1: array type arguments, i.e. vector of 1 type, the element type.
 // Return value: newly allocated array of length arg0.
@@ skipping 268 matching lines @@
     const AbstractType& type,
     const AbstractTypeArguments& instantiator_type_arguments,
     const Bool& result) {
   DartFrameIterator iterator;
   StackFrame* caller_frame = iterator.NextFrame();
   ASSERT(caller_frame != NULL);
 
   const Type& instance_type = Type::Handle(instance.GetType());
   ASSERT(instance_type.IsInstantiated());
   if (type.IsInstantiated()) {
-    OS::Print("%s: '%s' %"Pd" %s '%s' %"Pd" (pc: %#"Px").\n",
-              message,
-              String::Handle(instance_type.Name()).ToCString(),
-              Class::Handle(instance_type.type_class()).id(),
-              (result.raw() == Bool::True().raw()) ? "is" : "is !",
-              String::Handle(type.Name()).ToCString(),
-              Class::Handle(type.type_class()).id(),
-              caller_frame->pc());
+    OS::PrintErr("%s: '%s' %"Pd" %s '%s' %"Pd" (pc: %#"Px").\n",
+                 message,
+                 String::Handle(instance_type.Name()).ToCString(),
+                 Class::Handle(instance_type.type_class()).id(),
+                 (result.raw() == Bool::True().raw()) ? "is" : "is !",
+                 String::Handle(type.Name()).ToCString(),
+                 Class::Handle(type.type_class()).id(),
+                 caller_frame->pc());
   } else {
     // Instantiate type before printing.
     const AbstractType& instantiated_type =
         AbstractType::Handle(type.InstantiateFrom(instantiator_type_arguments));
-    OS::Print("%s: '%s' %s '%s' instantiated from '%s' (pc: %#"Px").\n",
-              message,
-              String::Handle(instance_type.Name()).ToCString(),
-              (result.raw() == Bool::True().raw()) ? "is" : "is !",
-              String::Handle(instantiated_type.Name()).ToCString(),
-              String::Handle(type.Name()).ToCString(),
-              caller_frame->pc());
+    OS::PrintErr("%s: '%s' %s '%s' instantiated from '%s' (pc: %#"Px").\n",
+                 message,
+                 String::Handle(instance_type.Name()).ToCString(),
+                 (result.raw() == Bool::True().raw()) ? "is" : "is !",
+                 String::Handle(instantiated_type.Name()).ToCString(),
+                 String::Handle(type.Name()).ToCString(),
+                 caller_frame->pc());
   }
   const Function& function = Function::Handle(
       caller_frame->LookupDartFunction());
-  OS::Print(" -> Function %s\n", function.ToFullyQualifiedCString());
+  OS::PrintErr(" -> Function %s\n", function.ToFullyQualifiedCString());
 }
 
 
 // Converts InstantiatedTypeArguments to TypeArguments and stores it
 // into the instance. The assembly code can handle only type arguments of
 // class TypeArguments. Because of the overhead, do it only when needed.
 // Return true if type arguments have been replaced, false otherwise.
 static bool OptimizeTypeArguments(const Instance& instance) {
   const Class& type_class = Class::ZoneHandle(instance.clazz());
   if (!type_class.HasTypeArguments()) {
@@ skipping 86 matching lines @@
         i,
         &last_instance_class_id,
         &last_instance_type_arguments,
         &last_instantiator_type_arguments,
         &last_result);
     if ((last_instance_class_id == instance_class.id()) &&
         (last_instance_type_arguments.raw() == instance_type_arguments.raw()) &&
         (last_instantiator_type_arguments.raw() ==
          instantiator_type_arguments.raw())) {
       if (FLAG_trace_type_checks) {
-        OS::Print("%"Pd" ", i);
+        OS::PrintErr("%"Pd" ", i);
         if (type_arguments_replaced) {
           PrintTypeCheck("Duplicate cache entry (canonical.)", instance, type,
               instantiator_type_arguments, result);
         } else {
           PrintTypeCheck("WARNING Duplicate cache entry", instance, type,
               instantiator_type_arguments, result);
         }
       }
       // Can occur if we have canonicalized arguments.
       // TODO(srdjan): Investigate why this assert can fail.
       // ASSERT(type_arguments_replaced);
       return;
     }
   }
   if (!instantiator_type_arguments.IsInstantiatedTypeArguments()) {
     new_cache.AddCheck(instance_class.id(),
                        instance_type_arguments,
                        instantiator_type_arguments,
                        result);
   }
   if (FLAG_trace_type_checks) {
     AbstractType& test_type = AbstractType::Handle(type.raw());
     if (!test_type.IsInstantiated()) {
       test_type = type.InstantiateFrom(instantiator_type_arguments);
     }
-    OS::Print("  Updated test cache %p ix: %"Pd" with (%"Pd", %p, %p, %s)\n"
+    OS::PrintErr("  Updated test cache %p ix: %"Pd" with (%"Pd", %p, %p, %s)\n"
         "    [%p %s %"Pd", %p %s]\n"
         "    [%p %s %"Pd", %p %s] %s\n",
         new_cache.raw(),
         len,
         instance_class.id(),
 
         instance_type_arguments.raw(),
         instantiator_type_arguments.raw(),
         result.ToCString(),
 
@@ skipping 227 matching lines @@
     }
   }
   const Code& target_code = Code::Handle(target_function.CurrentCode());
   // Before patching verify that we are not repeatedly patching to the same
   // target.
   ASSERT(target_code.EntryPoint() !=
          CodePatcher::GetStaticCallTargetAt(caller_frame->pc()));
   CodePatcher::PatchStaticCallAt(caller_frame->pc(), target_code.EntryPoint());
   caller_code.SetStaticCallTargetCodeAt(caller_frame->pc(), target_code);
   if (FLAG_trace_patching) {
-    OS::Print("PatchStaticCall: patching from %#"Px" to '%s' %#"Px"\n",
+    OS::PrintErr("PatchStaticCall: patching from %#"Px" to '%s' %#"Px"\n",
         caller_frame->pc(),
         target_function.ToFullyQualifiedCString(),
         target_code.EntryPoint());
   }
   arguments.SetReturn(target_code);
 }
 
 
 // Resolves and compiles the target function of an instance call, updates
 // function cache of the receiver's class and returns the compiled code or null.
@@ skipping 87 matching lines @@
     const Array& arg_descriptor_array) {
   const Instance& receiver = *args[0];
   const Code& target_code =
       Code::Handle(ResolveCompileInstanceCallTarget(receiver,
                                                     ic_data,
                                                     arg_descriptor_array));
   if (target_code.IsNull()) {
     // Let the megamorphic stub handle special cases: NoSuchMethod,
     // closure calls.
     if (FLAG_trace_ic) {
-      OS::Print("InlineCacheMissHandler NULL code for receiver: %s\n",
+      OS::PrintErr("InlineCacheMissHandler NULL code for receiver: %s\n",
           receiver.ToCString());
     }
     return Function::null();
   }
   const Function& target_function =
       Function::Handle(target_code.function());
   ASSERT(!target_function.IsNull());
   if (args.length() == 1) {
     ic_data.AddReceiverCheck(Class::Handle(args[0]->clazz()).id(),
                              target_function);
   } else {
     GrowableArray<intptr_t> class_ids(args.length());
     ASSERT(ic_data.num_args_tested() == args.length());
     for (intptr_t i = 0; i < args.length(); i++) {
       class_ids.Add(Class::Handle(args[i]->clazz()).id());
     }
     ic_data.AddCheck(class_ids, target_function);
   }
   if (FLAG_trace_ic_miss_in_optimized || FLAG_trace_ic) {
     DartFrameIterator iterator;
     StackFrame* caller_frame = iterator.NextFrame();
     ASSERT(caller_frame != NULL);
     if (FLAG_trace_ic_miss_in_optimized) {
       const Code& caller = Code::Handle(Code::LookupCode(caller_frame->pc()));
       if (caller.is_optimized()) {
-        OS::Print("IC miss in optimized code; call %s -> %s\n",
+        OS::PrintErr("IC miss in optimized code; call %s -> %s\n",
             Function::Handle(caller.function()).ToCString(),
             target_function.ToCString());
       }
     }
     if (FLAG_trace_ic) {
-      OS::Print("InlineCacheMissHandler %d call at %#"Px"' "
-                "adding <%s> id:%"Pd" -> <%s>\n",
+      OS::PrintErr("InlineCacheMissHandler %d call at %#"Px"' "
+                   "adding <%s> id:%"Pd" -> <%s>\n",
           args.length(),
           caller_frame->pc(),
           Class::Handle(receiver.clazz()).ToCString(),
           Class::Handle(receiver.clazz()).id(),
           target_function.ToCString());
     }
   }
   return target_function.raw();
 }
 
@@ skipping 87 matching lines @@
   const String& name = String::Handle(ic_data.target_name());
   const MegamorphicCache& cache = MegamorphicCache::Handle(
       isolate->megamorphic_cache_table()->Lookup(name, descriptor));
   Class& cls = Class::Handle(receiver.clazz());
   // For lookups treat null as an instance of class Object.
   if (cls.IsNullClass()) {
     cls = isolate->object_store()->object_class();
   }
   ASSERT(!cls.IsNull());
   if (FLAG_trace_ic || FLAG_trace_ic_miss_in_optimized) {
-    OS::Print("Megamorphic IC miss, class=%s, function=%s\n",
-              cls.ToCString(), name.ToCString());
+    OS::PrintErr("Megamorphic IC miss, class=%s, function=%s\n",
+                 cls.ToCString(), name.ToCString());
   }
 
   intptr_t arg_count =
       Smi::Cast(Object::Handle(descriptor.At(0))).Value();
   intptr_t named_arg_count =
       arg_count - Smi::Cast(Object::Handle(descriptor.At(1))).Value();
   const Function& target = Function::Handle(
       Resolver::ResolveDynamicForReceiverClass(cls,
                                                name,
                                                arg_count,
@@ skipping 268 matching lines @@
   }
 }
 
 
 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 @ %#"Px"\n",
+  OS::PrintErr("Failed: '%s' %s @ %#"Px"\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",
+    OS::PrintErr("  -> caller: %s (%s)\n",
         caller_function.ToFullyQualifiedCString(),
         code.is_optimized() ? "optimized" : "unoptimized");
   }
 }
 
 
 DEFINE_RUNTIME_ENTRY(TraceICCall, 2) {
   ASSERT(arguments.ArgCount() ==
          kTraceICCallRuntimeEntry.argument_count());
   const ICData& ic_data = ICData::CheckedHandle(arguments.ArgAt(0));
   const Function& function = Function::CheckedHandle(arguments.ArgAt(1));
   DartFrameIterator iterator;
   StackFrame* frame = iterator.NextFrame();
   ASSERT(frame != NULL);
-  OS::Print("IC call @%#"Px": ICData: %p cnt:%"Pd" nchecks: %"Pd" %s %s\n",
+  OS::PrintErr("IC call @%#"Px": ICData: %p cnt:%"Pd" nchecks: %"Pd" %s %s\n",
       frame->pc(),
       ic_data.raw(),
       function.usage_counter(),
       ic_data.NumberOfChecks(),
       ic_data.is_closure_call() ? "closure" : "",
       function.ToFullyQualifiedCString());
 }
 
 
 // This is called from function that needs to be optimized.
@@ skipping 35 matching lines @@
     if (!error.IsNull()) {
       Exceptions::PropagateError(error);
     }
     const Code& optimized_code = Code::Handle(function.CurrentCode());
     ASSERT(!optimized_code.IsNull());
     // Set usage counter for reoptimization.
     function.set_usage_counter(
         function.usage_counter() - FLAG_reoptimization_counter_threshold);
   } else {
     if (FLAG_trace_failed_optimization_attempts) {
-      PrintCaller("Not Optimizable");
+      OS::PrintErr("Not Optimizable: %s\n", function.ToFullyQualifiedCString());
     }
     // TODO(5442338): Abort as this should not happen.
     function.set_usage_counter(kLowInvocationCount);
   }
   arguments.SetReturn(Code::Handle(function.CurrentCode()));
 }
 
 
 // The caller must be a static call in a Dart frame, or an entry frame.
 // Patch static call to point to valid code's entry point.
@@ skipping 13 matching lines @@
     UNREACHABLE();
   }
   ASSERT(frame->IsDartFrame());
   const Code& caller_code = Code::Handle(frame->LookupDartCode());
   const Function& target_function = Function::Handle(
       caller_code.GetStaticCallTargetFunctionAt(frame->pc()));
   const Code& target_code = Code::Handle(target_function.CurrentCode());
   CodePatcher::PatchStaticCallAt(frame->pc(), target_code.EntryPoint());
   caller_code.SetStaticCallTargetCodeAt(frame->pc(), target_code);
   if (FLAG_trace_patching) {
-    OS::Print("FixCallersTarget: patching from %#"Px" to '%s' %#"Px"\n",
+    OS::PrintErr("FixCallersTarget: patching from %#"Px" to '%s' %#"Px"\n",
         frame->pc(),
         Function::Handle(target_code.function()).ToFullyQualifiedCString(),
         target_code.EntryPoint());
   }
   arguments.SetReturn(target_code);
 }
 
 
 const char* DeoptReasonToText(intptr_t deopt_id) {
   switch (deopt_id) {
@@ skipping 170 matching lines @@
 
   DeoptInfo& deopt_info = DeoptInfo::Handle();
   DeoptReasonId deopt_reason = kDeoptUnknown;
   GetDeoptInfoAtPc(optimized_code, caller_frame->pc(), &deopt_info,
                    &deopt_reason);
   ASSERT(!deopt_info.IsNull());
 
   CopyFrame(optimized_code, *caller_frame);
   if (FLAG_trace_deoptimization) {
     Function& function = Function::Handle(optimized_code.function());
-    OS::Print("Deoptimizing (reason %d '%s') at pc %#"Px" '%s' (count %d)\n",
+    OS::PrintErr("Deoptimizing (reason %d '%s') at pc %#"Px" '%s' (count %d)\n",
         deopt_reason,
         DeoptReasonToText(deopt_reason),
         caller_frame->pc(),
         function.ToFullyQualifiedCString(),
         function.deoptimization_counter());
   }
 
   // Compute the stack size of the unoptimized frame.  For functions with
   // optional arguments the deoptimization info does not describe the
   // incoming arguments.
@@ skipping 31 matching lines @@
   DeoptimizationContext deopt_context(start,
                                       to_frame_size,
                                       Array::Handle(code.object_table()),
                                       num_args,
                                       deopt_reason);
   for (intptr_t to_index = len - 1; to_index >= 0; to_index--) {
     deopt_instructions[to_index]->Execute(&deopt_context, to_index);
   }
   if (FLAG_trace_deoptimization_verbose) {
     for (intptr_t i = 0; i < len; i++) {
-      OS::Print("*%"Pd". [%p] %#014"Px" [%s]\n",
+      OS::PrintErr("*%"Pd". [%p] %#014"Px" [%s]\n",
           i,
           &start[i],
           start[i],
           deopt_instructions[i]->ToCString());
     }
   }
   return deopt_context.GetCallerFp();
 }
 
 
@@ skipping 45 matching lines @@
   DeferredDouble* deferred_double = Isolate::Current()->DetachDeferredDoubles();
 
   while (deferred_double != NULL) {
     DeferredDouble* current = deferred_double;
     deferred_double = deferred_double->next();
 
     RawDouble** slot = current->slot();
     *slot = Double::New(current->value());
 
     if (FLAG_trace_deoptimization_verbose) {
-      OS::Print("materializing double at %"Px": %g\n",
+      OS::PrintErr("materializing double at %"Px": %g\n",
                 reinterpret_cast<uword>(current->slot()),
                 current->value());
     }
 
     delete current;
   }
 
   DeferredMint* deferred_mint = Isolate::Current()->DetachDeferredMints();
 
   while (deferred_mint != NULL) {
     DeferredMint* current = deferred_mint;
     deferred_mint = deferred_mint->next();
 
     RawMint** slot = current->slot();
     ASSERT(!Smi::IsValid64(current->value()));
     *slot = Mint::New(current->value());
 
     if (FLAG_trace_deoptimization_verbose) {
-      OS::Print("materializing mint at %"Px": %"Pd64"\n",
+      OS::PrintErr("materializing mint at %"Px": %"Pd64"\n",
                 reinterpret_cast<uword>(current->slot()),
                 current->value());
     }
 
     delete current;
   }
   // Since this is the only step where GC can occur during deoptimization,
   // use it to report the source line where deoptimization occured.
   if (FLAG_trace_deoptimization) {
     DartFrameIterator iterator;
     StackFrame* top_frame = iterator.NextFrame();
     ASSERT(top_frame != NULL);
     const Code& code = Code::Handle(top_frame->LookupDartCode());
     const Function& top_function = Function::Handle(code.function());
     const Script& script = Script::Handle(top_function.script());
     const intptr_t token_pos = code.GetTokenIndexOfPC(top_frame->pc());
     intptr_t line, column;
     script.GetTokenLocation(token_pos, &line, &column);
     String& line_string = String::Handle(script.GetLine(line));
-    OS::Print("  Function: %s\n", top_function.ToFullyQualifiedCString());
-    OS::Print("  Line %"Pd": '%s'\n", line, line_string.ToCString());
+    OS::PrintErr("  Function: %s\n", top_function.ToFullyQualifiedCString());
+    OS::PrintErr("  Line %"Pd": '%s'\n", line, line_string.ToCString());
   }
 }
 
 
 DEFINE_LEAF_RUNTIME_ENTRY(intptr_t,
                           BigintCompare,
                           RawBigint* left,
                           RawBigint* right) {
   Isolate* isolate = Isolate::Current();
   StackZone zone(isolate);
@@ skipping 14 matching lines @@
     return;
   }
   HeapTrace* heap_trace = Isolate::Current()->heap()->trace();
   heap_trace->TraceStoreIntoObject(RawObject::ToAddr(object),
                                    field_addr,
                                    RawObject::ToAddr(value));
 }
 END_LEAF_RUNTIME_ENTRY
 
 }  // namespace dart