Trace CHA optimizations (where, when, why)

runtime/vm/object.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/object.h"
 
 #include "include/dart_api.h"
 #include "platform/assert.h"
 #include "vm/assembler.h"
 #include "vm/cpu.h"
@@ skipping 44 matching lines @@
     "Huge method cutoff in tokens: Disables optimizations for huge methods.");
 DEFINE_FLAG(bool, overlap_type_arguments, true,
     "When possible, partially or fully overlap the type arguments of a type "
     "with the type arguments of its super type.");
 DEFINE_FLAG(bool, show_internal_names, false,
     "Show names of internal classes (e.g. \"OneByteString\") in error messages "
     "instead of showing the corresponding interface names (e.g. \"String\")");
 DEFINE_FLAG(bool, throw_on_javascript_int_overflow, false,
     "Throw an exception when the result of an integer calculation will not "
     "fit into a javascript integer.");
+DEFINE_FLAG(bool, trace_cha, false, "Trace CHA operations");
 DEFINE_FLAG(bool, use_field_guards, true, "Guard field cids.");
 DEFINE_FLAG(bool, use_lib_cache, true, "Use library name cache");
 DEFINE_FLAG(bool, trace_field_guards, false, "Trace changes in field's cids.");
 
 DECLARE_FLAG(charp, coverage_dir);
 DECLARE_FLAG(bool, load_deferred_eagerly);
 DECLARE_FLAG(bool, show_invisible_frames);
 DECLARE_FLAG(bool, trace_compiler);
 DECLARE_FLAG(bool, trace_deoptimization);
 DECLARE_FLAG(bool, trace_deoptimization_verbose);
@@ skipping 1527 matching lines @@
                                            Context::New(0, Heap::kOld));
   object_store->set_empty_context(context);
 
 #endif  // defined(DART_NO_SNAPSHOT).
 
   return Error::null();
 }
 
 
 void Object::Print() const {
-  OS::Print("%s\n", ToCString());
+  ISL_Print("%s\n", ToCString());
 }
 
 
 static void AddNameProperties(JSONObject* jsobj,
                               const String& name,
                               const String& vm_name) {
   jsobj->AddProperty("name", name.ToCString());
   if (!name.Equals(vm_name)) {
     jsobj->AddProperty("_vmName", vm_name.ToCString());
   }
@@ skipping 1085 matching lines @@
   }
 
   virtual void UpdateArrayTo(const Array& value) {
     // TODO(fschneider): Fails for classes in the VM isolate.
     cls_.set_cha_codes(value);
   }
 
   virtual void ReportDeoptimization(const Code& code) {
     if (FLAG_trace_deoptimization || FLAG_trace_deoptimization_verbose) {
       Function& function = Function::Handle(code.function());
-      OS::PrintErr("Deoptimizing %s because CHA optimized (%s).\n",
+      ISL_Print("Deoptimizing %s because CHA optimized (%s).\n",
           function.ToFullyQualifiedCString(),
           cls_.ToCString());
     }
   }
 
   virtual void ReportSwitchingCode(const Code& code) {
     if (FLAG_trace_deoptimization || FLAG_trace_deoptimization_verbose) {
       Function& function = Function::Handle(code.function());
-      OS::PrintErr("Switching %s to unoptimized code because CHA invalid"
-                   " (%s)\n",
-                   function.ToFullyQualifiedCString(),
-                   cls_.ToCString());
+      ISL_Print("Switching %s to unoptimized code because CHA invalid"
+                " (%s)\n",
+                function.ToFullyQualifiedCString(),
+                cls_.ToCString());
     }
   }
 
  private:
   const Class& cls_;
   DISALLOW_COPY_AND_ASSIGN(CHACodeArray);
 };
 
 
 void Class::RegisterCHACode(const Code& code) {
+  if (FLAG_trace_cha) {
+    ISL_Print("RegisterCHACode %s class %s\n",
+        Function::Handle(code.function()).ToQualifiedCString(), ToCString());
+  }
   ASSERT(code.is_optimized());
   CHACodeArray a(*this);
   a.Register(code);
 }
 
 
 void Class::DisableCHAOptimizedCode() {
   CHACodeArray a(*this);
   a.DisableCode();
 }
@@ skipping 2461 matching lines @@
 
 
 void Function::SwitchToUnoptimizedCode() const {
   ASSERT(HasOptimizedCode());
   Thread* thread = Thread::Current();
   Isolate* isolate = thread->isolate();
   Zone* zone = thread->zone();
   const Code& current_code = Code::Handle(zone, CurrentCode());
 
   if (FLAG_trace_deoptimization_verbose) {
-    OS::Print("Disabling optimized code: '%s' entry: %#" Px "\n",
+    ISL_Print("Disabling optimized code: '%s' entry: %#" Px "\n",
       ToFullyQualifiedCString(),
       current_code.EntryPoint());
   }
   // Patch entry of the optimized code.
   CodePatcher::PatchEntry(current_code);
   const Error& error = Error::Handle(zone,
       Compiler::EnsureUnoptimizedCode(thread, *this));
   if (!error.IsNull()) {
     Exceptions::PropagateError(error);
   }
@@ skipping 1657 matching lines @@
 
 
 bool Function::CheckSourceFingerprint(const char* prefix, int32_t fp) const {
   if (SourceFingerprint() != fp) {
     const bool recalculatingFingerprints = false;
     if (recalculatingFingerprints) {
       // This output can be copied into a file, then used with sed
       // to replace the old values.
       // sed -i .bak -f /tmp/newkeys runtime/vm/method_recognizer.h
       // sed -i .bak -f /tmp/newkeys runtime/vm/flow_graph_builder.h
-      OS::Print("s/V(%s, %d)/V(%s, %d)/\n",
+      ISL_Print("s/V(%s, %d)/V(%s, %d)/\n",
                 prefix, fp, prefix, SourceFingerprint());
     } else {
-      OS::Print("FP mismatch while recognizing method %s:"
+      ISL_Print("FP mismatch while recognizing method %s:"
                 " expecting %d found %d\n",
                 ToFullyQualifiedCString(),
                 fp,
                 SourceFingerprint());
       return false;
     }
   }
   return true;
 }
 
@@ skipping 580 matching lines @@
       : WeakCodeReferences(Array::Handle(field.dependent_code())),
                            field_(field) {}
 
   virtual void UpdateArrayTo(const Array& value) {
     field_.set_dependent_code(value);
   }
 
   virtual void ReportDeoptimization(const Code& code) {
     if (FLAG_trace_deoptimization || FLAG_trace_deoptimization_verbose) {
       Function& function = Function::Handle(code.function());
-          OS::PrintErr("Deoptimizing %s because guard on field %s failed.\n",
-          function.ToFullyQualifiedCString(),
-          field_.ToCString());
+      ISL_Print("Deoptimizing %s because guard on field %s failed.\n",
+                function.ToFullyQualifiedCString(), field_.ToCString());
     }
   }
 
   virtual void ReportSwitchingCode(const Code& code) {
     if (FLAG_trace_deoptimization || FLAG_trace_deoptimization_verbose) {
       Function& function = Function::Handle(code.function());
-      OS::PrintErr("Switching %s to unoptimized code because guard"
-                   " on field %s was violated.\n",
-                   function.ToFullyQualifiedCString(),
-                   field_.ToCString());
+      ISL_Print("Switching %s to unoptimized code because guard"
+                " on field %s was violated.\n",
+                function.ToFullyQualifiedCString(),
+                field_.ToCString());
     }
   }
 
  private:
   const Field& field_;
   DISALLOW_COPY_AND_ASSIGN(FieldDependentArray);
 };
 
 
 void Field::RegisterDependentCode(const Code& code) const {
@@ skipping 144 matching lines @@
     // Start tracking length if needed.
     ASSERT((guarded_list_length() == Field::kUnknownFixedLength) ||
            (guarded_list_length() == Field::kNoFixedLength));
     if (needs_length_check()) {
       ASSERT(guarded_list_length() == Field::kUnknownFixedLength);
       set_guarded_list_length(GetListLength(value));
       InitializeGuardedListLengthInObjectOffset();
     }
 
     if (FLAG_trace_field_guards) {
-      OS::Print("    => %s\n", GuardedPropertiesAsCString());
+      ISL_Print("    => %s\n", GuardedPropertiesAsCString());
     }
 
     return false;
   }
 
   if ((cid == guarded_cid()) || ((cid == kNullCid) && is_nullable())) {
     // Class id of the assigned value matches expected class id and nullability.
 
     // If we are tracking length check if it has matches.
     if (needs_length_check() &&
@@ skipping 34 matching lines @@
   return true;
 }
 
 
 void Field::RecordStore(const Object& value) const {
   if (!FLAG_use_field_guards) {
     return;
   }
 
   if (FLAG_trace_field_guards) {
-    OS::Print("Store %s %s <- %s\n",
+    ISL_Print("Store %s %s <- %s\n",
               ToCString(),
               GuardedPropertiesAsCString(),
               value.ToCString());
   }
 
   if (UpdateGuardedCidAndLength(value)) {
     if (FLAG_trace_field_guards) {
-      OS::Print("    => %s\n", GuardedPropertiesAsCString());
+      ISL_Print("    => %s\n", GuardedPropertiesAsCString());
     }
 
     DeoptimizeDependentCode();
   }
 }
 
 
 void LiteralToken::set_literal(const String& literal) const {
   StorePointer(&raw_ptr()->literal_, literal.raw());
 }
@@ skipping 2693 matching lines @@
   virtual void ReportDeoptimization(const Code& code) {
     // This gets called when the code object is on the stack
     // while nuking code that depends on a prefix. We don't expect
     // this to happen, so make sure we die loudly if we find
     // ourselves here.
     UNIMPLEMENTED();
   }
 
   virtual void ReportSwitchingCode(const Code& code) {
     if (FLAG_trace_deoptimization || FLAG_trace_deoptimization_verbose) {
-      OS::PrintErr("Prefix '%s': disabling %s code for %s function '%s'\n",
-        String::Handle(prefix_.name()).ToCString(),
-        code.is_optimized() ? "optimized" : "unoptimized",
-        CodePatcher::IsEntryPatched(code) ? "patched" : "unpatched",
-        Function::Handle(code.function()).ToCString());
+      ISL_Print("Prefix '%s': disabling %s code for %s function '%s'\n",
+          String::Handle(prefix_.name()).ToCString(),
+          code.is_optimized() ? "optimized" : "unoptimized",
+          CodePatcher::IsEntryPatched(code) ? "patched" : "unpatched",
+          Function::Handle(code.function()).ToCString());
     }
   }
 
  private:
   const LibraryPrefix& prefix_;
   DISALLOW_COPY_AND_ASSIGN(PrefixDependentArray);
 };
 
 
 void LibraryPrefix::RegisterDependentCode(const Code& code) const {
@@ skipping 2964 matching lines @@
     const char* parent_str = parent_ctx.ToCString();
     return zone->PrintToString(
         "Context@%p num_variables:% " Pd " parent:{ %s }",
         this->raw(), num_variables(), parent_str);
   }
 }
 
 
 static void IndentN(int count) {
   for (int i = 0; i < count; i++) {
-    OS::PrintErr(" ");
+    ISL_Print(" ");
   }
 }
 
 
 void Context::Dump(int indent) const {
   if (IsNull()) {
     IndentN(indent);
-    OS::PrintErr("Context@null\n");
+    ISL_Print("Context@null\n");
     return;
   }
 
   IndentN(indent);
-  OS::PrintErr("Context@%p vars(%" Pd ") {\n", this->raw(), num_variables());
+  ISL_Print("Context@%p vars(%" Pd ") {\n", this->raw(), num_variables());
   Object& obj = Object::Handle();
   for (intptr_t i = 0; i < num_variables(); i++) {
     IndentN(indent + 2);
     obj = At(i);
-    OS::PrintErr("[%" Pd "] = %s\n", i, obj.ToCString());
+    ISL_Print("[%" Pd "] = %s\n", i, obj.ToCString());
   }
 
   const Context& parent_ctx = Context::Handle(parent());
   if (!parent_ctx.IsNull()) {
     parent_ctx.Dump(indent + 2);
   }
   IndentN(indent);
-  OS::PrintErr("}\n");
+  ISL_Print("}\n");
 }
 
 
 void Context::PrintJSONImpl(JSONStream* stream, bool ref) const {
   JSONObject jsobj(stream);
   // TODO(turnidge): Should the user level type for Context be Context
   // or Object?
   AddCommonObjectProperties(&jsobj, "Context", ref);
   jsobj.AddServiceId(*this);
 
@@ skipping 7880 matching lines @@
   return tag_label.ToCString();
 }
 
 
 void UserTag::PrintJSONImpl(JSONStream* stream, bool ref) const {
   Instance::PrintJSONImpl(stream, ref);
 }
 
 
 }  // namespace dart