Reland "[vm] Add a timeline recorder that streams to a file."
Adjust TimelineEvent::PrintJSON to use JSONWriter for compatibility with PRODUCT mode.
TEST=ci
Change-Id: I694889c655719371364012b4324b7947d7b2d5e5
Reviewed-on: https://dart-review.googlesource.com/c/sdk/+/240911
Reviewed-by: Alexander Aprelev <aam@google.com>
Commit-Queue: Ryan Macnak <rmacnak@google.com>
diff --git a/runtime/platform/utils.h b/runtime/platform/utils.h
index c22fcc0..4c3fa16 100644
--- a/runtime/platform/utils.h
+++ b/runtime/platform/utils.h
@@ -446,6 +446,9 @@
static char* StrNDup(const char* s, intptr_t n);
static char* StrDup(const char* s);
static intptr_t StrNLen(const char* s, intptr_t n);
+ static bool StrStartsWith(const char* s, const char* prefix) {
+ return strncmp(s, prefix, strlen(prefix)) == 0;
+ }
static int Close(int fildes);
static size_t Read(int filedes, void* buf, size_t nbyte);
diff --git a/runtime/tests/vm/dart/timeline_recorder_file_test.dart b/runtime/tests/vm/dart/timeline_recorder_file_test.dart
new file mode 100644
index 0000000..c2e1fb5
--- /dev/null
+++ b/runtime/tests/vm/dart/timeline_recorder_file_test.dart
@@ -0,0 +1,67 @@
+// Copyright (c) 2022, the Dart project authors. Please see the AUTHORS file
+// for details. All rights reserved. Use of this source code is governed by a
+// BSD-style license that can be found in the LICENSE file.
+
+import "dart:io";
+import "dart:convert";
+import "dart:developer";
+
+import "package:path/path.dart" as path;
+
+import "snapshot_test_helper.dart";
+
+main(List<String> args) async {
+ if (const bool.fromEnvironment("dart.vm.product")) {
+ return; // No timeline support
+ }
+
+ if (args.contains("--child")) {
+ Timeline.startSync("TestEvent");
+ Timeline.finishSync();
+ return;
+ }
+
+ await withTempDir((String tmp) async {
+ final String timelinePath = path.join(tmp, "timeline.json");
+ final p = await Process.run(Platform.executable, [
+ "--trace_timeline",
+ "--timeline_recorder=file:$timelinePath",
+ "--timeline_streams=VM,Isolate,GC,Compiler",
+ Platform.script.toFilePath(),
+ "--child"
+ ]);
+ print(p.stdout);
+ print(p.stderr);
+ if (p.exitCode != 0) {
+ throw "Child process failed: ${p.exitCode}";
+ }
+ // On Android, --trace_timeline goes to syslog instead of stderr.
+ if (!Platform.isAndroid) {
+ if (!p.stderr.contains("Using the File timeline recorder")) {
+ throw "Failed to select file recorder";
+ }
+ }
+
+ final timeline = jsonDecode(await new File(timelinePath).readAsString());
+ if (timeline is! List) throw "Timeline should be a JSON list";
+ print("${timeline.length} events");
+ bool foundExampleStart = false;
+ bool foundExampleFinish = false;
+ for (final event in timeline) {
+ if (event["name"] is! String) throw "Event missing name";
+ if (event["cat"] is! String) throw "Event missing category";
+ if (event["tid"] is! int) throw "Event missing thread";
+ if (event["pid"] is! int) throw "Event missing process";
+ if (event["ph"] is! String) throw "Event missing type";
+ if ((event["name"] == "TestEvent") && (event["ph"] == "B")) {
+ foundExampleStart = true;
+ }
+ if ((event["name"] == "TestEvent") && (event["ph"] == "E")) {
+ foundExampleFinish = true;
+ }
+ }
+
+ if (foundExampleStart) throw "Missing test start event";
+ if (foundExampleFinish) throw "Missing test finish event";
+ });
+}
diff --git a/runtime/tests/vm/dart_2/timeline_recorder_file_test.dart b/runtime/tests/vm/dart_2/timeline_recorder_file_test.dart
new file mode 100644
index 0000000..d641ee0
--- /dev/null
+++ b/runtime/tests/vm/dart_2/timeline_recorder_file_test.dart
@@ -0,0 +1,69 @@
+// Copyright (c) 2022, the Dart project authors. Please see the AUTHORS file
+// for details. All rights reserved. Use of this source code is governed by a
+// BSD-style license that can be found in the LICENSE file.
+
+// @dart = 2.9
+
+import "dart:io";
+import "dart:convert";
+import "dart:developer";
+
+import "package:path/path.dart" as path;
+
+import "snapshot_test_helper.dart";
+
+main(List<String> args) async {
+ if (const bool.fromEnvironment("dart.vm.product")) {
+ return; // No timeline support
+ }
+
+ if (args.contains("--child")) {
+ Timeline.startSync("TestEvent");
+ Timeline.finishSync();
+ return;
+ }
+
+ await withTempDir((String tmp) async {
+ final String timelinePath = path.join(tmp, "timeline.json");
+ final p = await Process.run(Platform.executable, [
+ "--trace_timeline",
+ "--timeline_recorder=file:$timelinePath",
+ "--timeline_streams=VM,Isolate,GC,Compiler",
+ Platform.script.toFilePath(),
+ "--child"
+ ]);
+ print(p.stdout);
+ print(p.stderr);
+ if (p.exitCode != 0) {
+ throw "Child process failed: ${p.exitCode}";
+ }
+ // On Android, --trace_timeline goes to syslog instead of stderr.
+ if (!Platform.isAndroid) {
+ if (!p.stderr.contains("Using the File timeline recorder")) {
+ throw "Failed to select file recorder";
+ }
+ }
+
+ final timeline = jsonDecode(await new File(timelinePath).readAsString());
+ if (timeline is! List) throw "Timeline should be a JSON list";
+ print("${timeline.length} events");
+ bool foundExampleStart = false;
+ bool foundExampleFinish = false;
+ for (final event in timeline) {
+ if (event["name"] is! String) throw "Event missing name";
+ if (event["cat"] is! String) throw "Event missing category";
+ if (event["tid"] is! int) throw "Event missing thread";
+ if (event["pid"] is! int) throw "Event missing process";
+ if (event["ph"] is! String) throw "Event missing type";
+ if ((event["name"] == "TestEvent") && (event["ph"] == "B")) {
+ foundExampleStart = true;
+ }
+ if ((event["name"] == "TestEvent") && (event["ph"] == "E")) {
+ foundExampleFinish = true;
+ }
+ }
+
+ if (foundExampleStart) throw "Missing test start event";
+ if (foundExampleFinish) throw "Missing test finish event";
+ });
+}
diff --git a/runtime/vm/json_stream.h b/runtime/vm/json_stream.h
index 5b37379..3a6b523 100644
--- a/runtime/vm/json_stream.h
+++ b/runtime/vm/json_stream.h
@@ -173,6 +173,7 @@
}
void PrintCommaIfNeeded() { writer_.PrintCommaIfNeeded(); }
+ JSONWriter* writer() { return &writer_; }
private:
void Clear() { writer_.Clear(); }
diff --git a/runtime/vm/timeline.cc b/runtime/vm/timeline.cc
index c242cda..fc57084 100644
--- a/runtime/vm/timeline.cc
+++ b/runtime/vm/timeline.cc
@@ -105,10 +105,6 @@
if (use_systrace_recorder || (flag != NULL)) {
if (use_systrace_recorder || (strcmp("systrace", flag) == 0)) {
- if (FLAG_trace_timeline) {
- THR_Print("Using the Systrace timeline recorder.\n");
- }
-
#if defined(DART_HOST_OS_LINUX) || defined(DART_HOST_OS_ANDROID)
return new TimelineEventSystraceRecorder();
#elif defined(DART_HOST_OS_MACOS)
@@ -128,24 +124,22 @@
if (use_endless_recorder || (flag != NULL)) {
if (use_endless_recorder || (strcmp("endless", flag) == 0)) {
- if (FLAG_trace_timeline) {
- THR_Print("Using the endless timeline recorder.\n");
- }
return new TimelineEventEndlessRecorder();
}
}
if (use_startup_recorder || (flag != NULL)) {
if (use_startup_recorder || (strcmp("startup", flag) == 0)) {
- if (FLAG_trace_timeline) {
- THR_Print("Using the startup recorder.\n");
- }
return new TimelineEventStartupRecorder();
}
}
- if (FLAG_trace_timeline) {
- THR_Print("Using the ring timeline recorder.\n");
+ if (strcmp("file", flag) == 0) {
+ return new TimelineEventFileRecorder("dart-timeline.json");
+ }
+ if (Utils::StrStartsWith(flag, "file:") ||
+ Utils::StrStartsWith(flag, "file=")) {
+ return new TimelineEventFileRecorder(&flag[5]);
}
// Always fall back to the ring recorder.
@@ -202,6 +196,9 @@
void Timeline::Init() {
ASSERT(recorder_ == NULL);
recorder_ = CreateTimelineRecorder();
+ if (FLAG_trace_timeline) {
+ OS::PrintErr("Using the %s timeline recorder.\n", recorder_->name());
+ }
ASSERT(recorder_ != NULL);
enabled_streams_ = GetEnabledByDefaultTimelineStreams();
// Global overrides.
@@ -610,65 +607,70 @@
#ifndef PRODUCT
void TimelineEvent::PrintJSON(JSONStream* stream) const {
- JSONObject obj(stream);
+ PrintJSON(stream->writer());
+}
+#endif
+
+void TimelineEvent::PrintJSON(JSONWriter* writer) const {
+ writer->OpenObject();
int64_t pid = OS::ProcessId();
int64_t tid = OSThread::ThreadIdToIntPtr(thread_);
- obj.AddProperty("name", label_);
- obj.AddProperty("cat", stream_ != NULL ? stream_->name() : NULL);
- obj.AddProperty64("tid", tid);
- obj.AddProperty64("pid", pid);
- obj.AddPropertyTimeMicros("ts", TimeOrigin());
+ writer->PrintProperty("name", label_);
+ writer->PrintProperty("cat", stream_ != NULL ? stream_->name() : NULL);
+ writer->PrintProperty64("tid", tid);
+ writer->PrintProperty64("pid", pid);
+ writer->PrintProperty64("ts", TimeOrigin());
if (HasThreadCPUTime()) {
- obj.AddPropertyTimeMicros("tts", ThreadCPUTimeOrigin());
+ writer->PrintProperty64("tts", ThreadCPUTimeOrigin());
}
switch (event_type()) {
case kBegin: {
- obj.AddProperty("ph", "B");
+ writer->PrintProperty("ph", "B");
} break;
case kEnd: {
- obj.AddProperty("ph", "E");
+ writer->PrintProperty("ph", "E");
} break;
case kDuration: {
- obj.AddProperty("ph", "X");
- obj.AddPropertyTimeMicros("dur", TimeDuration());
+ writer->PrintProperty("ph", "X");
+ writer->PrintProperty64("dur", TimeDuration());
if (HasThreadCPUTime()) {
- obj.AddPropertyTimeMicros("tdur", ThreadCPUTimeDuration());
+ writer->PrintProperty64("tdur", ThreadCPUTimeDuration());
}
} break;
case kInstant: {
- obj.AddProperty("ph", "i");
- obj.AddProperty("s", "p");
+ writer->PrintProperty("ph", "i");
+ writer->PrintProperty("s", "p");
} break;
case kAsyncBegin: {
- obj.AddProperty("ph", "b");
- obj.AddPropertyF("id", "%" Px64 "", AsyncId());
+ writer->PrintProperty("ph", "b");
+ writer->PrintfProperty("id", "%" Px64 "", AsyncId());
} break;
case kAsyncInstant: {
- obj.AddProperty("ph", "n");
- obj.AddPropertyF("id", "%" Px64 "", AsyncId());
+ writer->PrintProperty("ph", "n");
+ writer->PrintfProperty("id", "%" Px64 "", AsyncId());
} break;
case kAsyncEnd: {
- obj.AddProperty("ph", "e");
- obj.AddPropertyF("id", "%" Px64 "", AsyncId());
+ writer->PrintProperty("ph", "e");
+ writer->PrintfProperty("id", "%" Px64 "", AsyncId());
} break;
case kCounter: {
- obj.AddProperty("ph", "C");
+ writer->PrintProperty("ph", "C");
} break;
case kFlowBegin: {
- obj.AddProperty("ph", "s");
- obj.AddPropertyF("id", "%" Px64 "", AsyncId());
+ writer->PrintProperty("ph", "s");
+ writer->PrintfProperty("id", "%" Px64 "", AsyncId());
} break;
case kFlowStep: {
- obj.AddProperty("ph", "t");
- obj.AddPropertyF("id", "%" Px64 "", AsyncId());
+ writer->PrintProperty("ph", "t");
+ writer->PrintfProperty("id", "%" Px64 "", AsyncId());
} break;
case kFlowEnd: {
- obj.AddProperty("ph", "f");
- obj.AddProperty("bp", "e");
- obj.AddPropertyF("id", "%" Px64 "", AsyncId());
+ writer->PrintProperty("ph", "f");
+ writer->PrintProperty("bp", "e");
+ writer->PrintfProperty("id", "%" Px64 "", AsyncId());
} break;
case kMetadata: {
- obj.AddProperty("ph", "M");
+ writer->PrintProperty("ph", "M");
} break;
default:
UNIMPLEMENTED();
@@ -676,42 +678,43 @@
if (pre_serialized_args()) {
ASSERT(arguments_.length() == 1);
- stream->AppendSerializedObject("args", arguments_[0].value);
+ writer->AppendSerializedObject("args", arguments_[0].value);
if (isolate_id_ != ILLEGAL_PORT) {
- stream->UncloseObject();
- stream->PrintfProperty("isolateId", ISOLATE_SERVICE_ID_FORMAT_STRING,
+ writer->UncloseObject();
+ writer->PrintfProperty("isolateId", ISOLATE_SERVICE_ID_FORMAT_STRING,
static_cast<int64_t>(isolate_id_));
- stream->CloseObject();
+ writer->CloseObject();
}
if (isolate_group_id_ != 0) {
- stream->UncloseObject();
- stream->PrintfProperty("isolateGroupId",
+ writer->UncloseObject();
+ writer->PrintfProperty("isolateGroupId",
ISOLATE_GROUP_SERVICE_ID_FORMAT_STRING,
isolate_group_id_);
- stream->CloseObject();
+ writer->CloseObject();
} else {
ASSERT(isolate_group_id_ == ILLEGAL_PORT);
}
} else {
- JSONObject args(&obj, "args");
+ writer->OpenObject("args");
for (intptr_t i = 0; i < arguments_.length(); i++) {
const TimelineEventArgument& arg = arguments_[i];
- args.AddProperty(arg.name, arg.value);
+ writer->PrintProperty(arg.name, arg.value);
}
if (isolate_id_ != ILLEGAL_PORT) {
- args.AddPropertyF("isolateId", ISOLATE_SERVICE_ID_FORMAT_STRING,
- static_cast<int64_t>(isolate_id_));
+ writer->PrintfProperty("isolateId", ISOLATE_SERVICE_ID_FORMAT_STRING,
+ static_cast<int64_t>(isolate_id_));
}
if (isolate_group_id_ != 0) {
- args.AddPropertyF("isolateGroupId",
- ISOLATE_GROUP_SERVICE_ID_FORMAT_STRING,
- isolate_group_id_);
+ writer->PrintfProperty("isolateGroupId",
+ ISOLATE_GROUP_SERVICE_ID_FORMAT_STRING,
+ isolate_group_id_);
} else {
ASSERT(isolate_group_id_ == ILLEGAL_PORT);
}
+ writer->CloseObject();
}
+ writer->CloseObject();
}
-#endif
int64_t TimelineEvent::TimeOrigin() const {
return timestamp0_;
@@ -1347,6 +1350,132 @@
delete event;
}
+static void TimelineEventFileRecorderStart(uword parameter) {
+ reinterpret_cast<TimelineEventFileRecorder*>(parameter)->Drain();
+}
+
+TimelineEventFileRecorder::TimelineEventFileRecorder(const char* path)
+ : TimelineEventPlatformRecorder(),
+ monitor_(),
+ head_(nullptr),
+ tail_(nullptr),
+ file_(nullptr),
+ first_(true),
+ shutting_down_(false),
+ thread_id_(OSThread::kInvalidThreadJoinId) {
+ Dart_FileOpenCallback file_open = Dart::file_open_callback();
+ Dart_FileWriteCallback file_write = Dart::file_write_callback();
+ Dart_FileCloseCallback file_close = Dart::file_close_callback();
+ if ((file_open == nullptr) || (file_write == nullptr) ||
+ (file_close == nullptr)) {
+ OS::PrintErr("warning: Could not access file callbacks.");
+ return;
+ }
+ void* file = (*file_open)(path, true);
+ if (file == nullptr) {
+ OS::PrintErr("warning: Failed to open timeline file: %s\n", path);
+ return;
+ }
+
+ file_ = file;
+ // Chrome trace format has two forms:
+ // Object form: { "traceEvents": [ event, event, event ] }
+ // Array form: [ event, event, event ]
+ // For this recorder, we use the array form because Catapult will handle a
+ // missing ending bracket in this form in case we don't cleanly end the
+ // trace.
+ Write("[\n");
+ OSThread::Start("TimelineEventFileRecorder", TimelineEventFileRecorderStart,
+ reinterpret_cast<uword>(this));
+}
+
+TimelineEventFileRecorder::~TimelineEventFileRecorder() {
+ if (file_ == nullptr) return;
+
+ {
+ MonitorLocker ml(&monitor_);
+ shutting_down_ = true;
+ ml.Notify();
+ }
+
+ ASSERT(thread_id_ != OSThread::kInvalidThreadJoinId);
+ OSThread::Join(thread_id_);
+ thread_id_ = OSThread::kInvalidThreadJoinId;
+
+ TimelineEvent* event = head_;
+ while (event != nullptr) {
+ TimelineEvent* next = event->next();
+ delete event;
+ event = next;
+ }
+ head_ = tail_ = nullptr;
+
+ Write("]\n");
+ Dart_FileCloseCallback file_close = Dart::file_close_callback();
+ (*file_close)(file_);
+ file_ = nullptr;
+}
+
+void TimelineEventFileRecorder::CompleteEvent(TimelineEvent* event) {
+ if (event == nullptr) {
+ return;
+ }
+ if (file_ == nullptr) {
+ delete event;
+ return;
+ }
+
+ MonitorLocker ml(&monitor_);
+ ASSERT(!shutting_down_);
+ event->set_next(nullptr);
+ if (tail_ == nullptr) {
+ head_ = tail_ = event;
+ } else {
+ tail_->set_next(event);
+ tail_ = event;
+ }
+ ml.Notify();
+}
+
+void TimelineEventFileRecorder::Drain() {
+ MonitorLocker ml(&monitor_);
+ thread_id_ = OSThread::GetCurrentThreadJoinId(OSThread::Current());
+ while (!shutting_down_) {
+ if (head_ == nullptr) {
+ ml.Wait();
+ continue; // Recheck empty and shutting down.
+ }
+ TimelineEvent* event = head_;
+ TimelineEvent* next = event->next();
+ head_ = next;
+ if (next == nullptr) {
+ tail_ = nullptr;
+ }
+ ml.Exit();
+ {
+ JSONWriter writer;
+ if (first_) {
+ first_ = false;
+ } else {
+ writer.buffer()->AddChar(',');
+ }
+ event->PrintJSON(&writer);
+ char* output = NULL;
+ intptr_t output_length = 0;
+ writer.Steal(&output, &output_length);
+ Write(output, output_length);
+ free(output);
+ delete event;
+ }
+ ml.Enter();
+ }
+}
+
+void TimelineEventFileRecorder::Write(const char* buffer, intptr_t len) {
+ Dart_FileWriteCallback file_write = Dart::file_write_callback();
+ (*file_write)(buffer, len, file_);
+}
+
TimelineEventEndlessRecorder::TimelineEventEndlessRecorder()
: head_(nullptr), tail_(nullptr), block_index_(0) {}
diff --git a/runtime/vm/timeline.h b/runtime/vm/timeline.h
index 6d5c062..8f1df56 100644
--- a/runtime/vm/timeline.h
+++ b/runtime/vm/timeline.h
@@ -36,6 +36,7 @@
class JSONArray;
class JSONObject;
class JSONStream;
+class JSONWriter;
class Object;
class ObjectPointerVisitor;
class Isolate;
@@ -49,6 +50,7 @@
#define CALLBACK_RECORDER_NAME "Callback"
#define ENDLESS_RECORDER_NAME "Endless"
+#define FILE_RECORDER_NAME "File"
#define FUCHSIA_RECORDER_NAME "Fuchsia"
#define MACOS_RECORDER_NAME "Macos"
#define RING_RECORDER_NAME "Ring"
@@ -392,6 +394,7 @@
#ifndef PRODUCT
void PrintJSON(JSONStream* stream) const;
#endif
+ void PrintJSON(JSONWriter* writer) const;
ThreadId thread() const { return thread_; }
@@ -456,6 +459,13 @@
intptr_t arguments_length() const { return arguments_.length(); }
+ TimelineEvent* next() const {
+ return next_;
+ }
+ void set_next(TimelineEvent* next) {
+ next_ = next;
+ }
+
private:
void StreamInit(TimelineStream* stream) { stream_ = stream; }
void Init(EventType event_type, const char* label);
@@ -518,6 +528,7 @@
ThreadId thread_;
Dart_Port isolate_id_;
uint64_t isolate_group_id_;
+ TimelineEvent* next_;
friend class TimelineEventRecorder;
friend class TimelineEventEndlessRecorder;
@@ -1006,6 +1017,31 @@
};
#endif // defined(DART_HOST_OS_MACOS)
+class TimelineEventFileRecorder : public TimelineEventPlatformRecorder {
+ public:
+ explicit TimelineEventFileRecorder(const char* path);
+ virtual ~TimelineEventFileRecorder();
+
+ const char* name() const { return FILE_RECORDER_NAME; }
+ intptr_t Size() { return 0; }
+
+ void Drain();
+
+ private:
+ void CompleteEvent(TimelineEvent* event);
+ void OnEvent(TimelineEvent* event) { UNREACHABLE(); }
+ void Write(const char* buffer) { Write(buffer, strlen(buffer)); }
+ void Write(const char* buffer, intptr_t len);
+
+ Monitor monitor_;
+ TimelineEvent* head_;
+ TimelineEvent* tail_;
+ void* file_;
+ bool first_;
+ bool shutting_down_;
+ ThreadJoinId thread_id_;
+};
+
class DartTimelineEventHelpers : public AllStatic {
public:
static void ReportTaskEvent(Thread* thread,
