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
diff --git a/tools/jvmti-agents/ti-alloc-sample/README.md b/tools/jvmti-agents/ti-alloc-sample/README.md
index e4f3793..0da090a 100644
--- a/tools/jvmti-agents/ti-alloc-sample/README.md
+++ b/tools/jvmti-agents/ti-alloc-sample/README.md
@@ -30,51 +30,38 @@
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.
-
+Lines starting with a + are key, value pairs. So, for instance, key 2 stands for
```
- #1(nativeReadString(J)Ljava/lang/String;)
+run()V
```
+.
-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
-
-```
- #1
-```
-
-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 0000000..8f1dccf
--- /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 f156421..75110c6 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 @@
}
}
-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 @@
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 @@
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 @@
&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 @@
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(¤tly_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 @@
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 @@
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 @@
string_table = new UniqueStringTable();
- stream = new LockedStream(output_file_path);
-
return JNI_OK;
}