[ART] Prepare streaming output of method tracing for developer use.
Changes include:
* Flush the buffer to file when tracing ends, so every record is
preserved.
* At the end of the streaming output, add what's the header when the
output mode is not strreaming (called 'trace summary' in code).
* A new special token (kOpTraceSummary) is added for this purpose.
* The summary used to be written to a .sec file, which has
permission issues with non-rooted devices.
* Update the streaming output converter (stream-trace-converter.py)
to handle the updated format. When the trace summary is present,
it is used to populate the output header, which provides more
complete info than existing implementation where some info is
inferred from the records.
The changes to trace.h/cc impact streaming output mode only.
The updated stream-trace-converter.py works with or without the
trace summary at the file end, so pulling the file in the middle
is still supported.
Bug: b/33300765
Test: m -j48 ART_TEST_TRACE=true ART_TEST_TRACE_STREAM=true test-art-host
I also tested manually: flashed a Nexus 6P, collected traces, and
parsed them in Studio.
Change-Id: I697d2ec09bed56033cfce9a8f27dc4710d8b0798
diff --git a/runtime/trace.cc b/runtime/trace.cc
index 9d9360e..2add955 100644
--- a/runtime/trace.cc
+++ b/runtime/trace.cc
@@ -54,6 +54,7 @@
static_cast<size_t>(kTraceMethodActionMask));
static constexpr uint8_t kOpNewMethod = 1U;
static constexpr uint8_t kOpNewThread = 2U;
+static constexpr uint8_t kOpTraceSummary = 3U;
class BuildStackTraceVisitor : public StackVisitor {
public:
@@ -700,20 +701,19 @@
std::string header(os.str());
if (trace_output_mode_ == TraceOutputMode::kStreaming) {
- File file(streaming_file_name_ + ".sec", O_CREAT | O_WRONLY, true);
- if (!file.IsOpened()) {
- LOG(WARNING) << "Could not open secondary trace file!";
- return;
- }
- if (!file.WriteFully(header.c_str(), header.length())) {
- file.Erase();
- std::string detail(StringPrintf("Trace data write failed: %s", strerror(errno)));
- PLOG(ERROR) << detail;
- ThrowRuntimeException("%s", detail.c_str());
- }
- if (file.FlushCloseOrErase() != 0) {
- PLOG(ERROR) << "Could not write secondary file";
- }
+ MutexLock mu(Thread::Current(), *streaming_lock_); // To serialize writing.
+ // Write a special token to mark the end of trace records and the start of
+ // trace summary.
+ uint8_t buf[7];
+ Append2LE(buf, 0);
+ buf[2] = kOpTraceSummary;
+ Append4LE(buf + 3, static_cast<uint32_t>(header.length()));
+ WriteToBuf(buf, sizeof(buf));
+ // Write the trace summary. The summary is identical to the file header when
+ // the output mode is not streaming (except for methods).
+ WriteToBuf(reinterpret_cast<const uint8_t*>(header.c_str()), header.length());
+ // Flush the buffer, which may include some trace records before the summary.
+ FlushBuf();
} else {
if (trace_file_.get() == nullptr) {
iovec iov[2];
@@ -894,6 +894,14 @@
memcpy(buf_.get() + old_offset, src, src_size);
}
+void Trace::FlushBuf() {
+ int32_t offset = cur_offset_.LoadRelaxed();
+ if (!trace_file_->WriteFully(buf_.get(), offset)) {
+ PLOG(WARNING) << "Failed flush the remaining data in streaming.";
+ }
+ cur_offset_.StoreRelease(0);
+}
+
void Trace::LogMethodTraceEvent(Thread* thread, ArtMethod* method,
instrumentation::Instrumentation::InstrumentationEvent event,
uint32_t thread_clock_diff, uint32_t wall_clock_diff) {
diff --git a/runtime/trace.h b/runtime/trace.h
index 824b150..485e9a1 100644
--- a/runtime/trace.h
+++ b/runtime/trace.h
@@ -202,7 +202,8 @@
// This causes the negative annotations to incorrectly have a false positive. TODO: Figure out
// how to annotate this.
NO_THREAD_SAFETY_ANALYSIS;
- void FinishTracing() REQUIRES_SHARED(Locks::mutator_lock_) REQUIRES(!*unique_methods_lock_);
+ void FinishTracing()
+ REQUIRES_SHARED(Locks::mutator_lock_) REQUIRES(!*unique_methods_lock_, !*streaming_lock_);
void ReadClocks(Thread* thread, uint32_t* thread_clock_diff, uint32_t* wall_clock_diff);
@@ -229,6 +230,9 @@
// annotation.
void WriteToBuf(const uint8_t* src, size_t src_size)
REQUIRES(streaming_lock_);
+ // Flush the main buffer to file. Used for streaming. Exposed here for lock annotation.
+ void FlushBuf()
+ REQUIRES(streaming_lock_);
uint32_t EncodeTraceMethod(ArtMethod* method) REQUIRES(!*unique_methods_lock_);
uint32_t EncodeTraceMethodAndAction(ArtMethod* method, TraceAction action)
diff --git a/tools/stream-trace-converter.py b/tools/stream-trace-converter.py
index 951b05b..7e341f2 100755
--- a/tools/stream-trace-converter.py
+++ b/tools/stream-trace-converter.py
@@ -124,12 +124,20 @@
self._threads.append('%d\t%s\n' % (tid, str))
print 'New thread: %d/%s' % (tid, str)
+ def ProcessTraceSummary(self, input):
+ summaryLength = ReadIntLE(input)
+ str = input.read(summaryLength)
+ self._summary = str
+ print 'Summary: \"%s\"' % str
+
def ProcessSpecial(self, input):
code = ord(input.read(1))
if code == 1:
self.ProcessMethod(input)
elif code == 2:
self.ProcessThread(input)
+ elif code == 3:
+ self.ProcessTraceSummary(input)
else:
raise MyException("Unknown special!")
@@ -147,9 +155,24 @@
print 'Buffer underrun, file was probably truncated. Results should still be usable.'
def Finalize(self, header):
- header.write('*threads\n')
- for t in self._threads:
- header.write(t)
+ # If the summary is present in the input file, use it as the header except
+ # for the methods section which is emtpy in the input file. If not present,
+ # apppend header with the threads that are recorded in the input stream.
+ if (self._summary):
+ # Erase the contents that's already written earlier by PrintHeader.
+ header.seek(0)
+ header.truncate()
+ # Copy the lines from the input summary to the output header until
+ # the methods section is seen.
+ for line in self._summary.splitlines(True):
+ if line == "*methods\n":
+ break
+ else:
+ header.write(line)
+ else:
+ header.write('*threads\n')
+ for t in self._threads:
+ header.write(t)
header.write('*methods\n')
for m in self._methods:
header.write(m)
@@ -166,6 +189,7 @@
self._methods = []
self._threads = []
+ self._summary = None
self.Process(input, body)
self.Finalize(header)
