Change agent text encoding

Change the text encoding to be easier to parse off-line.  Also fixes the
per-thread sampling bias Hans pointed out yesterday.  Adds the python
script I use to uncompress the text encoding.

Bug: none
Test: attach the agent; run the startop test; uncompress; make flame graph; view
Change-Id: I4a882642e659d8512a02d4980c82fb52470ac7f9

3 files changed, 190 insertions, 115 deletions

diff --git a/tools/jvmti-agents/ti-alloc-sample/README.md b/tools/jvmti-agents/ti-alloc-sample/README.md
index e4f37931c3..0da090af12 100644
--- a/tools/jvmti-agents/ti-alloc-sample/README.md
+++ b/tools/jvmti-agents/ti-alloc-sample/README.md
@@ -30,51 +30,38 @@ The resulting file is a sequence of object allocations, with a limited form of
 text compression.  For example a single stack frame might look like:
 
 ```
-#20(VMObjectAlloc(#0(jthread[main], jclass[Ljava/lang/String; file: String.java], size[56, hex: 0x38
-> ]))
-    #1(nativeReadString(J)Ljava/lang/String;)
-    #2(readString(Landroid/os/Parcel;)Ljava/lang/String;)
-    #3(readString()Ljava/lang/String;)
-    #4(readParcelableCreator(Ljava/lang/ClassLoader;)Landroid/os/Parcelable$Creator;)
-    #5(readParcelable(Ljava/lang/ClassLoader;)Landroid/os/Parcelable;)
-    #6(readFromParcel(Landroid/os/Parcel;)V)
-    #7(<init>(Landroid/os/Parcel;)V)
-    #8(<init>(Landroid/os/Parcel;Landroid/view/DisplayInfo$1;)V)
-    #9(createFromParcel(Landroid/os/Parcel;)Landroid/view/DisplayInfo;)
-    #10(createFromParcel(Landroid/os/Parcel;)Ljava/lang/Object;)
-    #11(getDisplayInfo(I)Landroid/view/DisplayInfo;)
-    #11
-    #12(updateDisplayInfoLocked()V)
-    #13(getState()I)
-    #14(onDisplayChanged(I)V)
-    #15(handleMessage(Landroid/os/Message;)V)
-    #16(dispatchMessage(Landroid/os/Message;)V)
-    #17(loop()V)
-    #18(main([Ljava/lang/String;)V)
-    #19(invoke(Ljava/lang/Object;[Ljava/lang/Object;)Ljava/lang/Object;))
++0,jthread[main], jclass[[I file: <UNKNOWN_FILE>], size[24, hex: 0x18]
++1,main([Ljava/lang/String;)V
++2,run()V
++3,invoke(Ljava/lang/Object;[Ljava/lang/Object;)Ljava/lang/Object;
++4,loop()V
++5,dispatchMessage(Landroid/os/Message;)V
++6,handleMessage(Landroid/os/Message;)V
++7,onDisplayChanged(I)V
++8,getState()I
++9,updateDisplayInfoLocked()V
++10,getDisplayInfo(I)Landroid/view/DisplayInfo;
++11,createFromParcel(Landroid/os/Parcel;)Ljava/lang/Object;
++12,createFromParcel(Landroid/os/Parcel;)Landroid/view/DisplayInfo;
++13,<init>(Landroid/os/Parcel;Landroid/view/DisplayInfo$1;)V
++14,<init>(Landroid/os/Parcel;)V
++15,readFromParcel(Landroid/os/Parcel;)V
+=16,0;1;2;3;1;4;5;6;7;8;9;10;10;11;12;13;14;15
+16
 ```
 
-The first line tells what thread the allocation occurred on, what type is
-allocated, and what size the allocation was.  The remaining lines are the call
-stack, starting with the function in which the allocation occured.  The depth
-limit is 20 frames.
-
-String compression is rudimentary.
-
-```
-    #1(nativeReadString(J)Ljava/lang/String;)
-```
-
-Indicates that the string inside the parenthesis is the first entry in a string
-table.  Later occurences in the printout of that string will print as
-
+Lines starting with a + are key, value pairs.  So, for instance, key 2 stands for
 ```
-    #1
+run()V
 ```
-
-Stack frame entries are compressed by this method, as are entire allocation
-records.
-
+.
+
+The line starting with 0 is the thread, type, and size (TTS) of an allocation.  The
+remaining lines starting with + are stack frames (SFs), containing function signatures.
+Lines starting with = are stack traces (STs), and are again key, value pairs.  In the
+example above, an ST called 16 is the TTS plus sequence of SFs.  Any line not starting
+with + or = is a sample.  It is a reference to an ST.  Hence repeated samples are
+represented as just numbers.
 
 #### ART
 >    `art -Xplugin:$ANDROID_HOST_OUT/lib64/libopenjdkjvmti.so '-agentpath:libtiallocsample.so=100' -cp tmp/java/helloworld.dex -Xint helloworld`
diff --git a/tools/jvmti-agents/ti-alloc-sample/mkflame.py b/tools/jvmti-agents/ti-alloc-sample/mkflame.py
new file mode 100755
index 0000000000..8f1dccfd99
--- /dev/null
+++ b/tools/jvmti-agents/ti-alloc-sample/mkflame.py
@@ -0,0 +1,90 @@
+#!/usr/bin/python3
+#
+# Copyright 2019, The Android Open Source Project
+#
+# Licensed under the Apache License, Version 2.0 (the "License");
+# you may not use this file except in compliance with the License.
+# You may obtain a copy of the License at
+#
+#     http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+
+"""
+Usage: mkflame.py <jvmti_trace_file>
+"""
+
+import sys
+
+table = {}
+
+def add_definition_to_table(line):
+  """
+  Adds line to the list of definitions in table.
+  """
+  comma_pos = line.find(",")
+  index = int(line[1:comma_pos])
+  definition = line[comma_pos+1:]
+  if line[0:1] == "=":
+    # Skip the type/size prefix for flame graphs.
+    semi_pos = definition.find(";")
+    definition = definition[semi_pos + 1:]
+    # Expand stack frame definitions to be a semicolon-separated list of stack
+    # frame methods.
+    expanded_definition = ""
+    while definition != "":
+      semi_pos = definition.find(";")
+      if semi_pos == -1:
+        method_index = int(definition)
+        definition = ""
+      else:
+        method_index = int(definition[:semi_pos])
+        definition = definition[semi_pos + 1:]
+      # Replace semicolons by colons in the method entry signatures.
+      method = lookup_definition(method_index).replace(";", ":")
+      expanded_definition += ";" + method
+    definition = expanded_definition
+  table[index] = definition
+
+def lookup_definition(index):
+  """
+  Returns the definition for "index" from table.
+  """
+  return table[index]
+
+traces = {}
+def record_stack_trace(string):
+  """
+  Remembers one stack trace index in the list of stack traces we have seen.
+  Remembering a stack trace increments a count associated with the trace.
+  """
+  index = int(string)
+  if index in traces:
+    count = traces[index]
+    traces[index] = count + 1
+  else:
+    traces[index] = 1
+
+def main(argv):
+  filename = argv[1]
+  pagefile = open(filename, "r")
+  current_allocation_trace = ""
+  for line in pagefile:
+    args = line.split()
+    line = line.rstrip("\n")
+    if line[0:1] == "=" or line[0:1] == "+":
+      # definition.
+      add_definition_to_table(line)
+    else:
+      # stack trace.
+      record_stack_trace(line)
+  # Dump all the traces, with count.
+  for k, v in traces.items():
+    print(lookup_definition(k) + " " + str(v))
+
+if __name__ == '__main__':
+  sys.exit(main(sys.argv))
diff --git a/tools/jvmti-agents/ti-alloc-sample/ti_alloc_sample.cc b/tools/jvmti-agents/ti-alloc-sample/ti_alloc_sample.cc
index f156421c01..75110c665e 100644
--- a/tools/jvmti-agents/ti-alloc-sample/ti_alloc_sample.cc
+++ b/tools/jvmti-agents/ti-alloc-sample/ti_alloc_sample.cc
@@ -231,26 +231,6 @@ std::ostream& operator<<(std::ostream &os, ScopedClassInfo const& c) {
   }
 }
 
-class UniqueStringTable {
- public:
-  UniqueStringTable() = default;
-  ~UniqueStringTable() = default;
-  std::string Intern(const std::string& key) {
-    if (map_.find(key) != map_.end()) {
-      return std::string("#") + std::to_string(map_[key]);
-    } else {
-      map_[key] = next_index_;
-      ++next_index_;
-      return std::string("#") + std::to_string(map_[key]) + "(" + key + ")";
-    }
-  }
- private:
-  int32_t next_index_;
-  std::map<std::string, int32_t> map_;
-};
-
-static UniqueStringTable* string_table = nullptr;
-
 class LockedStream {
  public:
   explicit LockedStream(const std::string& filepath) {
@@ -272,19 +252,26 @@ class LockedStream {
 
 static LockedStream* stream = nullptr;
 
-// An RAII class to turn a boolean flag on/off.
-class ScopedFlag {
+class UniqueStringTable {
  public:
-  explicit ScopedFlag(bool* flag) : flag_(flag) {
-    *flag_ = true;
-  }
-  ~ScopedFlag() {
-    *flag_ = false;
+  UniqueStringTable() = default;
+  ~UniqueStringTable() = default;
+  std::string Intern(const std::string& header, const std::string& key) {
+    if (map_.find(key) == map_.end()) {
+      map_[key] = next_index_;
+      // Emit definition line.  E.g., =123,string
+      stream->Write(header + std::to_string(next_index_) + "," + key + "\n");
+      ++next_index_;
+    }
+    return std::to_string(map_[key]);
   }
  private:
-  bool* flag_;
+  int32_t next_index_;
+  std::map<std::string, int32_t> map_;
 };
 
+static UniqueStringTable* string_table = nullptr;
+
 // Formatter for the thread, type, and size of an allocation.
 static std::string formatAllocation(jvmtiEnv* jvmti,
                                     JNIEnv* jni,
@@ -301,7 +288,7 @@ static std::string formatAllocation(jvmtiEnv* jvmti,
     allocation << ", jclass[TYPE UNKNOWN]";
   }
   allocation << ", size[" << size.val << ", hex: 0x" << std::hex << size.val << "]";
-  return string_table->Intern(allocation.str());
+  return string_table->Intern("+", allocation.str());
 }
 
 // Formatter for a method entry on a call stack.
@@ -313,18 +300,16 @@ static std::string formatMethod(jvmtiEnv* jvmti, jmethodID method_id) {
                                         &method_name,
                                         &method_signature,
                                         &generic_pointer);
+  std::string method = "METHODERROR";
   if (err == JVMTI_ERROR_NONE) {
-    std::string method;
     method = ((method_name == nullptr) ? "UNKNOWN" : method_name);
     method += ((method_signature == nullptr) ? "(UNKNOWN)" : method_signature);
-    return string_table->Intern(method);
-  } else {
-    return "METHODERROR";
   }
+  return string_table->Intern("+", method);
 }
 
-static int sampling_rate = 10;
-static int stack_depth_limit = 50;
+static int sampling_rate;
+static int stack_depth_limit;
 
 static void JNICALL logVMObjectAlloc(jvmtiEnv* jvmti,
                                      JNIEnv* jni,
@@ -332,32 +317,23 @@ static void JNICALL logVMObjectAlloc(jvmtiEnv* jvmti,
                                      jobject obj ATTRIBUTE_UNUSED,
                                      jclass klass,
                                      jlong size) {
-  // Prevent recursive allocation tracking, and the stack overflow it causes.
-  static thread_local bool currently_logging;
-  if (currently_logging) {
+  // Sample only once out of sampling_rate tries, and prevent recursive allocation tracking,
+  static thread_local int sample_countdown = sampling_rate;
+  --sample_countdown;
+  if (sample_countdown != 0) {
     return;
   }
-  ScopedFlag sf(&currently_logging);
 
-  // Guard accesses to log skip count, string table, etc.
+  // Guard accesses to string table and emission.
   static std::mutex mutex;
   std::lock_guard<std::mutex> lg(mutex);
 
-  // Only process every nth log call.
-  static int logs_skipped = 0;
-  if (logs_skipped < sampling_rate) {
-    logs_skipped++;
-    return;
-  } else {
-    logs_skipped = 0;
-  }
-
   std::string record =
-      "VMObjectAlloc(" + formatAllocation(jvmti,
-                                          jni,
-                                          jthreadContainer{.thread = thread},
-                                          klass,
-                                          jlongContainer{.val = size}) + ")";
+      formatAllocation(jvmti,
+                       jni,
+                       jthreadContainer{.thread = thread},
+                       klass,
+                       jlongContainer{.val = size});
 
   std::unique_ptr<jvmtiFrameInfo[]> stack_frames(new jvmtiFrameInfo[stack_depth_limit]);
   jint stack_depth;
@@ -367,11 +343,15 @@ static void JNICALL logVMObjectAlloc(jvmtiEnv* jvmti,
                                         stack_frames.get(),
                                         &stack_depth);
   if (err == JVMTI_ERROR_NONE) {
-    for (int i = 0; i < stack_depth; ++i) {
-      record += "\n    " + formatMethod(jvmti, stack_frames[i].method);
+    // Emit stack frames in order from deepest in the stack to most recent.
+    // This simplifies post-collection processing.
+    for (int i = stack_depth - 1; i >= 0; --i) {
+      record += ";" + formatMethod(jvmti, stack_frames[i].method);
     }
   }
-  stream->Write(string_table->Intern(record) + "\n");
+  stream->Write(string_table->Intern("=", record) + "\n");
+
+  sample_countdown = sampling_rate;
 }
 
 static jvmtiEventCallbacks kLogCallbacks {
@@ -398,26 +378,46 @@ static jvmtiError SetupCapabilities(jvmtiEnv* jvmti) {
   return jvmti->AddCapabilities(&caps);
 }
 
+static bool ProcessOptions(std::string options) {
+  std::string output_file_path;
+  if (options.empty()) {
+    static constexpr int kDefaultSamplingRate = 10;
+    static constexpr int kDefaultStackDepthLimit = 50;
+    static constexpr const char* kDefaultOutputFilePath = "/data/local/tmp/logstream.txt";
+
+    sampling_rate = kDefaultSamplingRate;
+    stack_depth_limit = kDefaultStackDepthLimit;
+    output_file_path = kDefaultOutputFilePath;
+  } else {
+    // options string should contain "sampling_rate,stack_depth_limit,output_file_path".
+    size_t comma_pos = options.find(',');
+    if (comma_pos == std::string::npos) {
+      return false;
+    }
+    sampling_rate = std::stoi(options.substr(0, comma_pos));
+    options = options.substr(comma_pos + 1);
+    comma_pos = options.find(',');
+    if (comma_pos == std::string::npos) {
+      return false;
+    }
+    stack_depth_limit = std::stoi(options.substr(0, comma_pos));
+    output_file_path = options.substr(comma_pos + 1);
+  }
+  LOG(INFO) << "Starting allocation tracing: sampling_rate=" << sampling_rate
+            << ", stack_depth_limit=" << stack_depth_limit
+            << ", output_file_path=" << output_file_path;
+  stream = new LockedStream(output_file_path);
+
+  return true;
+}
+
 static jint AgentStart(JavaVM* vm,
                        char* options,
                        void* reserved ATTRIBUTE_UNUSED) {
-  // options string should contain "sampling_rate,stack_depth_limit,output_file_path".
-  std::string args(options);
-  size_t comma_pos = args.find(',');
-  if (comma_pos == std::string::npos) {
+  // Handle the sampling rate, depth limit, and output path, if set.
+  if (!ProcessOptions(options)) {
     return JNI_ERR;
   }
-  sampling_rate = std::stoi(args.substr(0, comma_pos));
-  args = args.substr(comma_pos + 1);
-  comma_pos = args.find(',');
-  if (comma_pos == std::string::npos) {
-    return JNI_ERR;
-  }
-  stack_depth_limit = std::stoi(args.substr(0, comma_pos));
-  std::string output_file_path = args.substr(comma_pos + 1);
-
-  LOG(INFO) << "Starting allocation tracing: sampling_rate=" << sampling_rate
-            << ", stack_depth_limit=" << stack_depth_limit;
 
   // Create the environment.
   jvmtiEnv* jvmti = nullptr;
@@ -448,8 +448,6 @@ static jint AgentStart(JavaVM* vm,
 
   string_table = new UniqueStringTable();
 
-  stream = new LockedStream(output_file_path);
-
   return JNI_OK;
 }