// Copyright 2015 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 "sky/shell/tracing_controller.h" #include "base/files/file_util.h" #include "base/logging.h" #include "base/macros.h" #include "base/trace_event/trace_config.h" #include "base/trace_event/trace_event.h" #include "dart/runtime/include/dart_tools_api.h" #include "sky/shell/shell.h" #include #include namespace sky { namespace shell { const char kBaseTraceStart[] = "{\"traceEvents\":["; const char kBaseTraceEnd[] = "]}"; const char kObservatoryMethodStartTracing[] = "flutter_startTracing"; const char kObservatoryMethodStopTracing[] = "flutter_stopTracing"; const char kObservatoryResultOk[] = "{\"success\" : true}"; const char kObservatoryResultFail[] = "{\"success\" : false}"; static const char* ObservatoryInvoke(const char* method, const char** param_keys, const char** param_values, intptr_t num_params, void* user_data) { if (user_data == nullptr) { // During the destruction of the tracing controller, the user data is // cleared. Make sure that observatory requests to service calls are not // attempted after tracing controller destruction. return strdup(kObservatoryResultFail); } auto tracing_controller = reinterpret_cast(user_data); if (strncmp(method, kObservatoryMethodStartTracing, sizeof(kObservatoryMethodStartTracing)) == 0) { if (!tracing_controller->tracing_active()) { tracing_controller->StartTracing(); return strdup(kObservatoryResultOk); } } if (strncmp(method, kObservatoryMethodStopTracing, sizeof(kObservatoryMethodStopTracing)) == 0) { if (tracing_controller->tracing_active()) { // Flushing the trace log requires an active message loop. However, // observatory callbacks are made on a dart worker thread. We setup a // message loop manually and tell the flush completion handler to // terminate the loop when done base::MessageLoop worker_thread_loop; base::FilePath temp_dir; bool temp_access = base::GetTempDir(&temp_dir); DCHECK(temp_access) << "Must be able to access the temp directory"; base::FilePath path = tracing_controller->TracePathForCurrentTime(temp_dir); tracing_controller->StopTracing(path, true); // Run the loop till the flush callback terminates the activation worker_thread_loop.Run(); base::File file( path, base::File::Flags::FLAG_OPEN | base::File::Flags::FLAG_READ); int64 length = file.GetLength(); if (length == 0) { base::DeleteFile(path, false); return strdup(kObservatoryResultFail); } char* data = reinterpret_cast(malloc(length)); int length_read = file.Read(0, data, length); DCHECK(length == length_read); base::DeleteFile(path, false); return data; } } return strdup(kObservatoryResultFail); } TracingController::TracingController() : picture_tracing_enabled_(false), terminate_loop_on_write_(false), dart_initialized_(false), tracing_active_(false), weak_factory_(this) { ManageObservatoryCallbacks(true); } TracingController::~TracingController() { ManageObservatoryCallbacks(false); } void TracingController::SetDartInitialized() { DCHECK(!dart_initialized_); dart_initialized_ = true; // In case early lifecycle is being traced, base tracing has already begun // but we have just been notified of initialization of the Dart VM. Start // collecting traces in Dart. if (tracing_active_) { StartDartTracing(); } } void TracingController::ManageObservatoryCallbacks(bool add) { void* baton = add ? this : nullptr; Dart_RegisterRootServiceRequestCallback(kObservatoryMethodStartTracing, &ObservatoryInvoke, baton); Dart_RegisterRootServiceRequestCallback(kObservatoryMethodStopTracing, &ObservatoryInvoke, baton); } void TracingController::StartTracing() { DCHECK(!tracing_active_); LOG(INFO) << "Starting trace"; tracing_active_ = true; StartDartTracing(); StartBaseTracing(); } void TracingController::StopTracing(const base::FilePath& path, bool terminate_loop_when_done) { base::MessageLoop::current()->PostTask( FROM_HERE, base::Bind(&TracingController::StopTracingAsync, weak_factory_.GetWeakPtr(), path, terminate_loop_when_done)); } void TracingController::StopTracingAsync(const base::FilePath& path, bool terminate_loop_when_done) { if (terminate_loop_on_write_) { DLOG(INFO) << "Observatory is attempting to capture a trace."; return; } terminate_loop_on_write_ = terminate_loop_when_done; LOG(INFO) << "Saving trace to " << path.LossyDisplayName(); trace_file_ = std::unique_ptr(new base::File( path, base::File::FLAG_CREATE_ALWAYS | base::File::FLAG_WRITE)); base::SetPosixFilePermissions(path, base::FILE_PERMISSION_MASK); StopBaseTracing(); } void TracingController::StartDartTracing() { if (!dart_initialized_) { return; } Dart_GlobalTimelineSetRecordedStreams(~0); } static void TracingController_DartStreamConsumer( Dart_StreamConsumer_State state, const char* stream_name, uint8_t* buffer, intptr_t buffer_length, base::File* traceFile) { if (state == Dart_StreamConsumer_kData) { // Trim trailing null characters. if (buffer[buffer_length - 1] == 0) --buffer_length; if (buffer_length) { if (traceFile != nullptr) { traceFile->WriteAtCurrentPos(reinterpret_cast(buffer), buffer_length); } } } } void TracingController::StopDartTracing() { if (!dart_initialized_) { // This is checking for the highly unlikely case where the user starts and // stops tracing before the dart VM is initialized. FinalizeTraceFile(); return; } if (trace_file_){ trace_file_->WriteAtCurrentPos(",", 1); } Dart_GlobalTimelineSetRecordedStreams(DART_TIMELINE_STREAM_DISABLE); auto callback = reinterpret_cast( &TracingController_DartStreamConsumer); Dart_GlobalTimelineGetTrace(callback, trace_file_.get()); FinalizeTraceFile(); } void TracingController::StartBaseTracing() { base::trace_event::TraceLog::GetInstance()->SetEnabled( base::trace_event::TraceConfig("*", base::trace_event::RECORD_UNTIL_FULL), base::trace_event::TraceLog::RECORDING_MODE); } void TracingController::StopBaseTracing() { base::trace_event::TraceLog* log = base::trace_event::TraceLog::GetInstance(); log->SetDisabled(); if (trace_file_) { trace_file_->WriteAtCurrentPos(kBaseTraceStart, sizeof(kBaseTraceStart) - 1); } log->Flush(base::Bind(&TracingController::OnBaseTraceChunk, weak_factory_.GetWeakPtr())); } void TracingController::FinalizeTraceFile() { if (trace_file_) { trace_file_->WriteAtCurrentPos(kBaseTraceEnd, sizeof(kBaseTraceEnd) - 1); trace_file_ = nullptr; } if (terminate_loop_on_write_) { base::MessageLoop::current()->Quit(); terminate_loop_on_write_ = false; } tracing_active_ = false; LOG(INFO) << "Trace complete"; } void TracingController::OnBaseTraceChunk( const scoped_refptr& chunk, bool has_more_events) { if (trace_file_) { std::string& str = chunk->data(); trace_file_->WriteAtCurrentPos(str.data(), str.size()); if (has_more_events) trace_file_->WriteAtCurrentPos(",", 1); } if (!has_more_events) { StopDartTracing(); } } base::FilePath TracingController::TracePathWithExtension( base::FilePath dir, std::string extension) const { base::Time::Exploded exploded; base::Time now = base::Time::Now(); now.LocalExplode(&exploded); std::stringstream stream; // Example: trace_2015-10-08_at_11.38.25.121_.extension stream << "trace_" << exploded.year << "-" << exploded.month << "-" << exploded.day_of_month << "_at_" << exploded.hour << "." << exploded.minute << "." << exploded.second << "." << exploded.millisecond << "." << extension; return dir.Append(stream.str()); } base::FilePath TracingController::PictureTracingPathForCurrentTime() const { return PictureTracingPathForCurrentTime(traces_base_path_); } base::FilePath TracingController::PictureTracingPathForCurrentTime( base::FilePath dir) const { return TracePathWithExtension(dir, "skp"); } base::FilePath TracingController::TracePathForCurrentTime( base::FilePath dir) const { return TracePathWithExtension(dir, "json"); } } // namespace shell } // namespace sky