ART: Fix streaming tracing issues

Fix a lock ordering issue in streaming-mode tracing.

Fix a moving-GC issue in streaming-mode tracing. DexCache
objects are not good keys for a map.

Expose streaming mode for testing in run-tests.

Bug: 21760614
Change-Id: Idcd0575684ee3cc0cec3f81b4fdd0d5988c11e8c

6 files changed, 61 insertions, 23 deletions

diff --git a/build/Android.common_test.mk b/build/Android.common_test.mk
index f3e1cc3272..45b649047f 100644
--- a/build/Android.common_test.mk
+++ b/build/Android.common_test.mk
@@ -61,6 +61,9 @@ ART_TEST_PIC_TEST ?= $(ART_TEST_FULL)
 # Do you want tracing tests run?
 ART_TEST_TRACE ?= $(ART_TEST_FULL)
 
+# Do you want tracing tests (streaming mode) run?
+ART_TEST_TRACE_STREAM ?= $(ART_TEST_FULL)
+
 # Do you want tests with GC verification enabled run?
 ART_TEST_GC_VERIFY ?= $(ART_TEST_FULL)
 
diff --git a/runtime/base/mutex.h b/runtime/base/mutex.h
index aa91ca161d..678d55bddd 100644
--- a/runtime/base/mutex.h
+++ b/runtime/base/mutex.h
@@ -80,6 +80,8 @@ enum LockLevel {
   kMarkSweepMarkStackLock,
   kInternTableLock,
   kOatFileSecondaryLookupLock,
+  kTracingUniqueMethodsLock,
+  kTracingStreamingLock,
   kDefaultMutexLevel,
   kMarkSweepLargeObjectLock,
   kPinTableLock,
diff --git a/runtime/trace.cc b/runtime/trace.cc
index 5a43b567aa..487baedba4 100644
--- a/runtime/trace.cc
+++ b/runtime/trace.cc
@@ -427,7 +427,7 @@ void Trace::StopTracing(bool finish_tracing, bool flush_file) {
       // Do not try to erase, so flush and close explicitly.
       if (flush_file) {
         if (the_trace->trace_file_->Flush() != 0) {
-          PLOG(ERROR) << "Could not flush trace file.";
+          PLOG(WARNING) << "Could not flush trace file.";
         }
       } else {
         the_trace->trace_file_->MarkUnchecked();  // Do not trigger guard.
@@ -581,7 +581,7 @@ Trace::Trace(File* trace_file, const char* trace_name, size_t buffer_size, int f
       buffer_size_(std::max(kMinBufSize, buffer_size)),
       start_time_(MicroTime()), clock_overhead_ns_(GetClockOverheadNanoSeconds()), cur_offset_(0),
       overflow_(false), interval_us_(0), streaming_lock_(nullptr),
-      unique_methods_lock_(new Mutex("unique methods lock")) {
+      unique_methods_lock_(new Mutex("unique methods lock", kTracingUniqueMethodsLock)) {
   uint16_t trace_version = GetTraceVersion(clock_source_);
   if (output_mode == TraceOutputMode::kStreaming) {
     trace_version |= 0xF0U;
@@ -603,13 +603,14 @@ Trace::Trace(File* trace_file, const char* trace_name, size_t buffer_size, int f
 
   if (output_mode == TraceOutputMode::kStreaming) {
     streaming_file_name_ = trace_name;
-    streaming_lock_ = new Mutex("tracing lock");
+    streaming_lock_ = new Mutex("tracing lock", LockLevel::kTracingStreamingLock);
     seen_threads_.reset(new ThreadIDBitSet());
   }
 }
 
 Trace::~Trace() {
   delete streaming_lock_;
+  delete unique_methods_lock_;
 }
 
 static uint64_t ReadBytes(uint8_t* buf, size_t bytes) {
@@ -634,13 +635,15 @@ void Trace::DumpBuf(uint8_t* buf, size_t buf_size, TraceClockSource clock_source
 }
 
 static void GetVisitedMethodsFromBitSets(
-    const std::map<mirror::DexCache*, DexIndexBitSet*>& seen_methods,
+    const std::map<const DexFile*, DexIndexBitSet*>& seen_methods,
     std::set<ArtMethod*>* visited_methods) SHARED_LOCKS_REQUIRED(Locks::mutator_lock_) {
+  ClassLinker* class_linker = Runtime::Current()->GetClassLinker();
   for (auto& e : seen_methods) {
     DexIndexBitSet* bit_set = e.second;
+    mirror::DexCache* dex_cache = class_linker->FindDexCache(*e.first);
     for (uint32_t i = 0; i < bit_set->size(); ++i) {
       if ((*bit_set)[i]) {
-        visited_methods->insert(e.first->GetResolvedMethod(i, sizeof(void*)));
+        visited_methods->insert(dex_cache->GetResolvedMethod(i, sizeof(void*)));
       }
     }
   }
@@ -819,15 +822,16 @@ void Trace::ReadClocks(Thread* thread, uint32_t* thread_clock_diff, uint32_t* wa
 
 bool Trace::RegisterMethod(ArtMethod* method) {
   mirror::DexCache* dex_cache = method->GetDexCache();
+  const DexFile* dex_file = dex_cache->GetDexFile();
   auto* resolved_method = dex_cache->GetResolvedMethod(method->GetDexMethodIndex(), sizeof(void*));
   if (resolved_method != method) {
     DCHECK(resolved_method == nullptr);
     dex_cache->SetResolvedMethod(method->GetDexMethodIndex(), method, sizeof(void*));
   }
-  if (seen_methods_.find(dex_cache) == seen_methods_.end()) {
-    seen_methods_.insert(std::make_pair(dex_cache, new DexIndexBitSet()));
+  if (seen_methods_.find(dex_file) == seen_methods_.end()) {
+    seen_methods_.insert(std::make_pair(dex_file, new DexIndexBitSet()));
   }
-  DexIndexBitSet* bit_set = seen_methods_.find(dex_cache)->second;
+  DexIndexBitSet* bit_set = seen_methods_.find(dex_file)->second;
   if (!(*bit_set)[method->GetDexMethodIndex()]) {
     bit_set->set(method->GetDexMethodIndex());
     return true;
diff --git a/runtime/trace.h b/runtime/trace.h
index 7bc495a237..69e6acc899 100644
--- a/runtime/trace.h
+++ b/runtime/trace.h
@@ -35,12 +35,9 @@
 
 namespace art {
 
-namespace mirror {
-  class DexCache;
-}  // namespace mirror
-
 class ArtField;
 class ArtMethod;
+class DexFile;
 class Thread;
 
 using DexIndexBitSet = std::bitset<65536>;
@@ -126,15 +123,18 @@ class Trace FINAL : public instrumentation::InstrumentationListener {
 
   // Stop tracing. This will finish the trace and write it to file/send it via DDMS.
   static void Stop()
-        LOCKS_EXCLUDED(Locks::mutator_lock_,
-                       Locks::thread_list_lock_,
-                       Locks::trace_lock_);
+      LOCKS_EXCLUDED(Locks::mutator_lock_,
+                     Locks::thread_list_lock_,
+                     Locks::trace_lock_);
   // Abort tracing. This will just stop tracing and *not* write/send the collected data.
   static void Abort()
       LOCKS_EXCLUDED(Locks::mutator_lock_,
                      Locks::thread_list_lock_,
                      Locks::trace_lock_);
-  static void Shutdown() LOCKS_EXCLUDED(Locks::trace_lock_);
+  static void Shutdown()
+      LOCKS_EXCLUDED(Locks::mutator_lock_,
+                     Locks::thread_list_lock_,
+                     Locks::trace_lock_);
   static TracingMode GetMethodTracingMode() LOCKS_EXCLUDED(Locks::trace_lock_);
 
   bool UseWallClock();
@@ -188,7 +188,10 @@ class Trace FINAL : public instrumentation::InstrumentationListener {
   // The sampling interval in microseconds is passed as an argument.
   static void* RunSamplingThread(void* arg) LOCKS_EXCLUDED(Locks::trace_lock_);
 
-  static void StopTracing(bool finish_tracing, bool flush_file);
+  static void StopTracing(bool finish_tracing, bool flush_file)
+      LOCKS_EXCLUDED(Locks::mutator_lock_,
+                     Locks::thread_list_lock_,
+                     Locks::trace_lock_);
   void FinishTracing() SHARED_LOCKS_REQUIRED(Locks::mutator_lock_);
 
   void ReadClocks(Thread* thread, uint32_t* thread_clock_diff, uint32_t* wall_clock_diff);
@@ -279,12 +282,12 @@ class Trace FINAL : public instrumentation::InstrumentationListener {
   // Streaming mode data.
   std::string streaming_file_name_;
   Mutex* streaming_lock_;
-  std::map<mirror::DexCache*, DexIndexBitSet*> seen_methods_;
+  std::map<const DexFile*, DexIndexBitSet*> seen_methods_;
   std::unique_ptr<ThreadIDBitSet> seen_threads_;
 
   // Bijective map from ArtMethod* to index.
   // Map from ArtMethod* to index in unique_methods_;
-  Mutex* unique_methods_lock_ DEFAULT_MUTEX_ACQUIRED_AFTER;
+  Mutex* unique_methods_lock_ ACQUIRED_AFTER(streaming_lock_);
   std::unordered_map<ArtMethod*, uint32_t> art_method_id_map_ GUARDED_BY(unique_methods_lock_);
   std::vector<ArtMethod*> unique_methods_ GUARDED_BY(unique_methods_lock_);
 
diff --git a/test/Android.run-test.mk b/test/Android.run-test.mk
index 5eda539e7d..8c62ed7523 100644
--- a/test/Android.run-test.mk
+++ b/test/Android.run-test.mk
@@ -101,6 +101,9 @@ TRACE_TYPES := ntrace
 ifeq ($(ART_TEST_TRACE),true)
   TRACE_TYPES += trace
 endif
+ifeq ($(ART_TEST_TRACE_STREAM),true)
+  TRACE_TYPES += stream
+endif
 GC_TYPES := cms
 ifeq ($(ART_TEST_GC_STRESS),true)
   GC_TYPES += gcstress
@@ -310,9 +313,9 @@ TEST_ART_BROKEN_TRACING_RUN_TESTS := \
   137-cfi \
   802-deoptimization
 
-ifneq (,$(filter trace,$(TRACE_TYPES)))
+ifneq (,$(filter trace stream,$(TRACE_TYPES)))
   ART_TEST_KNOWN_BROKEN += $(call all-run-test-names,$(TARGET_TYPES),$(RUN_TYPES),$(PREBUILD_TYPES), \
-      $(COMPILER_TYPES),$(RELOCATE_TYPES),trace,$(GC_TYPES),$(JNI_TYPES),$(IMAGE_TYPES), \
+      $(COMPILER_TYPES),$(RELOCATE_TYPES),trace stream,$(GC_TYPES),$(JNI_TYPES),$(IMAGE_TYPES), \
       $(PICTEST_TYPES),$(DEBUGGABLE_TYPES), $(TEST_ART_BROKEN_TRACING_RUN_TESTS),$(ALL_ADDRESS_SIZES))
 endif
 
@@ -661,7 +664,13 @@ define define-test-art-run-test
     ifeq ($(6),ntrace)
       test_groups += ART_RUN_TEST_$$(uc_host_or_target)_NO_TRACE_RULES
     else
-      $$(error found $(6) expected $(TRACE_TYPES))
+      ifeq ($(6),stream)
+        # Group streaming under normal tracing rules.
+        test_groups += ART_RUN_TEST_$$(uc_host_or_target)_TRACE_RULES
+        run_test_options += --trace --stream
+      else
+        $$(error found $(6) expected $(TRACE_TYPES))
+      endif
     endif
   endif
   ifeq ($(7),gcverify)
diff --git a/test/run-test b/test/run-test
index dc60edabd8..3f17861a22 100755
--- a/test/run-test
+++ b/test/run-test
@@ -92,6 +92,7 @@ usage="no"
 build_only="no"
 suffix64=""
 trace="false"
+trace_stream="false"
 basic_verify="false"
 gc_verify="false"
 gc_stress="false"
@@ -267,6 +268,9 @@ while true; do
     elif [ "x$1" = "x--trace" ]; then
         trace="true"
         shift
+    elif [ "x$1" = "x--stream" ]; then
+        trace_stream="true"
+        shift
     elif [ "x$1" = "x--always-clean" ]; then
         always_clean="yes"
         shift
@@ -303,7 +307,19 @@ if [ "$gc_stress" = "true" ]; then
   run_args="${run_args} --runtime-option -Xgc:SS --runtime-option -Xms2m --runtime-option -Xmx2m"
 fi
 if [ "$trace" = "true" ]; then
-    run_args="${run_args} --runtime-option -Xmethod-trace --runtime-option -Xmethod-trace-file:${DEX_LOCATION}/trace.bin --runtime-option -Xmethod-trace-file-size:2000000"
+    run_args="${run_args} --runtime-option -Xmethod-trace --runtime-option -Xmethod-trace-file-size:2000000"
+    if [ "$trace_stream" = "true" ]; then
+        # Streaming mode uses the file size as the buffer size. So output gets really large. Drop
+        # the ability to analyze the file and just write to /dev/null.
+        run_args="${run_args} --runtime-option -Xmethod-trace-file:/dev/null"
+        # Enable streaming mode.
+        run_args="${run_args} --runtime-option -Xmethod-trace-stream"
+    else
+        run_args="${run_args} --runtime-option -Xmethod-trace-file:${DEX_LOCATION}/trace.bin"
+    fi
+elif [ "$trace_stream" = "true" ]; then
+    echo "Cannot use --stream without --trace."
+    exit 1
 fi
 
 # Most interesting target architecture variables are Makefile variables, not environment variables.
@@ -469,6 +485,7 @@ if [ "$usage" = "yes" ]; then
              "files."
         echo "    --64                  Run the test in 64-bit mode"
         echo "    --trace               Run with method tracing"
+        echo "    --stream              Run method tracing in streaming mode (requires --trace)"
         echo "    --gcstress            Run with gc stress testing"
         echo "    --gcverify            Run with gc verification"
         echo "    --always-clean        Delete the test files even if the test fails."