arc: enable Android tracing in verified-boot mode

chrome/browser/chromeos/arc/trace/arc_trace_reader.cc

+// Copyright 2017 The Chromium Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
+
+#include "chrome/browser/chromeos/arc/trace/arc_trace_reader.h"
+
+#include <errno.h>
+#include <string.h>
+#include <sys/select.h>
+
+#include <memory>
+#include <sstream>
+#include <utility>
+#include <vector>
+
+#include "base/json/json_writer.h"
+#include "base/logging.h"
+#include "base/strings/string_number_conversions.h"
+#include "base/strings/string_split.h"
+#include "base/values.h"
+#include "content/public/browser/browser_thread.h"
+
+namespace arc {
+
+namespace {
+
+#define ARC_TRACE_MESSAGE_LENGTH (1024 + 512)

[Luis Héctor Chávez, 2017/02/10 17:43:54]

constexpr size_t kArcTraceMessageLength = 1024 + 512;

[Earl Ou, 2017/03/22 11:38:26]

Done in Android side.

+
+// Maximum data to be stored in the buffer.
+constexpr int kTraceBufferByteSize = 16 * 1024 * 1024;  // 16MB
+
+}  // namespace
+
+ArcTraceReader::ArcTraceReader()
+    : is_recording_(false), input_fd_(-1), recording_thread_(nullptr) {}

[Luis Héctor Chávez, 2017/02/10 17:43:55]

these three can be set in the .h, that way you can have ArcTraceReader() =
default;

also, the convention is to not explicitly initialize unique_ptrs with nullptr.

[Earl Ou, 2017/03/22 11:38:26]

Done in Android side.

+
+void ArcTraceReader::Run() {
+  if (input_fd_.get() == -1) {
+    LOG(WARNING) << "No input FD is set before starting recording.";
+    return;
+  }
+
+  int ret;
+  fd_set fds;
+  timeval tv;
+  char buf[ARC_TRACE_MESSAGE_LENGTH];
+
+  while (is_recording_) {
+    FD_ZERO(&fds);
+    FD_SET(input_fd_.get(), &fds);
+
+    // Wait up to 1 second.
+    tv.tv_sec = 1;
+    tv.tv_usec = 0;
+
+    ret = TEMP_FAILURE_RETRY(
+        select(input_fd_.get() + 1, &fds, nullptr, nullptr, &tv));
+    if (ret < 0) {
+      LOG(ERROR) << "Unexpected error while recording ARC trace: "
+                 << strerror(errno);
+      break;
+    }
+    if (!ret)  // No data available.
+      continue;
+
+    ret = TEMP_FAILURE_RETRY(read(input_fd_.get(), buf, sizeof(buf) - 1));

[Luis Héctor Chávez, 2017/02/10 23:16:51]

in any case, you should try to limit the amount of raw UNIX calls. Try to use
the very nice classes in base/ :)

[Earl Ou, 2017/03/22 11:38:26]

This is moved to the Android side.

+    if (ret < 0) {
+      LOG(ERROR) << "Unexpected error while reading ARC trace: "
+                 << strerror(errno);
+      break;
+    }
+    if (ret == 0) {  // EOF
+      LOG(WARNING) << "EOF while recording ARC trace.";
+      break;
+    }
+    buf[ret] = 0;  // Make sure the string is null terminated.
+    ParseAndSaveData(buf);
+  }
+}
+
+void ArcTraceReader::SetInputFD(base::ScopedFD fd) {
+  input_fd_ = std::move(fd);
+}
+
+void ArcTraceReader::StartRecord() {
+  DCHECK_CURRENTLY_ON(content::BrowserThread::UI);
+
+  if (is_recording_) {
+    LOG(WARNING) << "ARC trace reader already started.";
+    return;
+  }
+  is_recording_ = true;
+  current_data_size_ = 0;
+  trace_buffer_ = std::queue<std::string>();  // clean the queue.
+
+  recording_thread_.reset(

[Luis Héctor Chávez, 2017/02/10 17:43:54]

How about using base::FileDescriptorWatcher::WatchReadable()[1] instead? That'll
remove all the select() code and make everything simpler.

https://cs.chromium.org/chromium/src/base/files/file_descriptor_watcher_posix...

[Luis Héctor Chávez, 2017/02/10 23:16:51]

You can also use something similar to
https://cs.chromium.org/chromium/src/chromeos/dbus/pipe_reader.h, which seems to
be a bit simpler to use. in any case, you should try to use the browser's
blocking pool (probably passed in as a class parameter if you end up moving it
to components/arc)

[Earl Ou, 2017/03/22 11:38:26]

Done in arc_tracing_agent.cc

+      new base::DelegateSimpleThread(this, "ArcTraceReader"));
+  recording_thread_->Start();
+}
+
+void ArcTraceReader::StopRecord(const StopTracingCallback& callback) {
+  DCHECK_CURRENTLY_ON(content::BrowserThread::UI);
+
+  if (!is_recording_) {
+    LOG(WARNING) << "ARC trace reader was not started.";
+    callback.Run("");
+    return;
+  }
+  is_recording_ = false;
+  recording_thread_->Join();
+  recording_thread_.reset(nullptr);

[Luis Héctor Chávez, 2017/02/10 17:43:54]

nit: recording_thread_.reset();

[Earl Ou, 2017/03/22 11:38:26]

No reading thread now as suggested.

+
+  // TODO(shunshingou): run the following in a separated thread to avoid long

[Luis Héctor Chávez, 2017/02/10 17:43:55]

This must be done in this CL, unfortunately. Worst case scenario, you can just
close the pipe in this end and make sure you block SIGPIPE on the other end.

Btw, by using the WatchReadable() and by streaming events as they come, you
won't need to join a thread at all!

[Luis Héctor Chávez, 2017/02/10 17:48:03]

D'Oh, this is a socket, not a pipe. Ignore the SIGPIPE part.

[Earl Ou, 2017/02/16 09:56:45]

The comment here is for the processing of stringstream below. It may takes some
time to pop the buffer and generate the report if the buffer is pretty large.
(but in currently size (16MB) it's usually quite fast)

For the above join(), the worst case take about 1s (blocked by select()), but
it's true that I should use WatchReadable or other tools under base/ to avoid
many system calls here.

[Earl Ou, 2017/03/22 11:38:26]

Now this is running in IO thread with WatchReadable.

+  // processing in UI thread.
+  std::stringstream ss;
+  bool is_first = true;
+  while (!trace_buffer_.empty()) {
+    if (!is_first)
+      ss << ",";
+    is_first = false;
+    ss << trace_buffer_.front();
+    trace_buffer_.pop();
+  }
+  callback.Run(ss.str());
+}
+
+void ArcTraceReader::WriteTraceEvent(char ph,
+                                     int pid,
+                                     int tid,
+                                     uint64_t ts,
+                                     uint64_t tts,
+                                     const std::string* name,
+                                     const int* count,
+                                     const int* id) {
+  base::DictionaryValue event;
+  event.SetString("cat", "android");
+  event.SetString("ph", std::string(1, ph));
+  event.SetInteger("pid", pid);
+  event.SetInteger("tid", tid);
+  event.SetDouble("ts", ts);
+  event.SetDouble("tts", tts);
+  if (name)
+    event.SetString("name", *name);
+
+  if (count)
+    event.SetInteger("args.count", *count);
+
+  if (id)
+    event.SetInteger("id", *id);
+
+  std::string json;
+  if (!base::JSONWriter::Write(event, &json)) {
+    // Bad data, shouldn't happen as the data is prepared by ourself.

[Luis Héctor Chávez, 2017/02/10 17:43:54]

nit: ourselves.

[Earl Ou, 2017/03/22 11:38:26]

Done on the Android side.

+    // Skip and return.
+    return;
+  }
+
+  current_data_size_ += json.size();

[Luis Héctor Chávez, 2017/02/10 17:43:54]

Why do you still need this? Why can't you just send it to the tracing processor
and let it deal with buffers? Doing it this way will effectively double the
amount of memory needed.

[Luis Héctor Chávez, 2017/02/10 23:16:51]

Ignore the above comment, since it's the way the API is designed. I should have
read the code for TracingAgent instead of relying on my (flawed) understanding
of what the trace does just based on the UI. Apologies for any confusion.

Having said that, can you please try to use
https://cs.chromium.org/chromium/src/base/trace_event/trace_buffer.h instead of
rolling your own ring buffer?

[Earl Ou, 2017/02/16 09:56:45]

trace_buffer seems to be designed for Chrome tracing itself (used by TraceLog),
not for TracingAgent. For example, it has chunk design that is not really useful
in our case. Other TracingAgent, e.g. etw_tracing_agent_win,
power_tracing_agent, also maintain their own buffer. (Although they do not use
ring buffer)

[Earl Ou, 2017/03/22 11:38:26]

I'm using TraceBuffer in the new patch now.

+  trace_buffer_.emplace(std::move(json));
+
+  while (current_data_size_ > kTraceBufferByteSize) {
+    current_data_size_ -= trace_buffer_.front().size();
+    trace_buffer_.pop();
+  }
+}
+
+void ArcTraceReader::ParseAndSaveData(std::string data) {

[Luis Héctor Chávez, 2017/02/10 17:43:54]

This might fail since |data| might contain multiple lines if you're not reading
fast enough. Even worse, you might end up with one line plus a chunk of a second
line, and the next entry will be read incorrectly.

You'll need to add some buffering to ensure that you're reading this line by
line.

[Earl Ou, 2017/02/16 09:56:46]

The data would only have one trace event since we're using SEQPACKET socket.

+  const std::vector<std::string> tokens =
+      base::SplitString(data, "|", base::KEEP_WHITESPACE, base::SPLIT_WANT_ALL);
+
+  // ph|pid|tid|ts|tts
+  if (tokens.size() < 5 || tokens[0].size() != 1)  // bad data, skip.
+    return;
+
+  char ph = tokens[0][0];
+  int pid, tid;
+  uint64_t ts, tts;
+
+  if (!base::StringToInt(tokens[1], &pid) ||
+      !base::StringToInt(tokens[2], &tid) ||
+      !base::StringToUint64(tokens[3], &ts) ||
+      !base::StringToUint64(tokens[4], &tts)) {
+    return;  // bad data, skip.
+  }
+
+  switch (ph) {
+    case 'B':
+      // B|pid|tid|ts|tts|name
+      if (tokens.size() != 6)
+        return;  // bad data, skip.
+      WriteTraceEvent(ph, pid, tid, ts, tts, &tokens[5]);
+      break;
+    case 'E':
+      // E|pid|tid|ts|tts
+      WriteTraceEvent(ph, pid, tid, ts, tts);
+      break;
+    case 'F':
+    case 'S':
+      // F|pid|tid|ts|tts|name|value
+      int id;
+      if (tokens.size() != 7 || !base::StringToInt(tokens[6], &id))
+        return;  // bad data, skip.
+      WriteTraceEvent(ph, pid, tid, ts, tts, &tokens[5], nullptr, &id);
+      break;
+    case 'C':
+      // C|pid|tid|ts|tts|name|value
+      int count;
+      if (tokens.size() != 7 || !base::StringToInt(tokens[6], &count))
+        return;  // bad data, skip.
+      WriteTraceEvent(ph, pid, tid, ts, tts, &tokens[5], &count);
+      break;
+  }
+}
+
+}  // namespace arc