| // Copyright 2020 The Fuchsia 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 "tracing.h" |
| |
| #include <lib/fxt/fields.h> |
| #include <lib/syslog/cpp/macros.h> |
| #include <lib/zircon-internal/ktrace.h> |
| |
| #include <fstream> |
| |
| #include <trace-reader/reader.h> |
| |
| // Performs same action as zx_ktrace_read and does necessary checks. |
| void Tracing::ReadKernelBuffer(zx_handle_t handle, void* data_buf, uint32_t offset, size_t len, |
| size_t* bytes_read) { |
| const zx_status_t status = zx_ktrace_read(handle, data_buf, offset, len, bytes_read); |
| if (status != ZX_OK) { |
| FX_PLOGS(FATAL, status) << "zx_trace_read"; |
| } |
| } |
| |
| // Rewinds kernel trace buffer. |
| void Tracing::Rewind() { |
| const zx_status_t status = zx_ktrace_control(debug_resource_, KTRACE_ACTION_REWIND, 0, nullptr); |
| if (status != ZX_OK) { |
| FX_PLOGS(FATAL, status) << "zx_ktrace_control(_, KTRACE_ACTION_REWIND, _, _)"; |
| } |
| } |
| |
| // Starts kernel tracing. |
| void Tracing::Start(uint32_t group_mask) { |
| const zx_status_t status = |
| zx_ktrace_control(debug_resource_, KTRACE_ACTION_START, group_mask, nullptr); |
| if (status != ZX_OK) { |
| FX_PLOGS(FATAL, status) << "zx_ktrace_control(_, KTRACE_ACTION_START, _, _)"; |
| } |
| |
| running_ = true; |
| } |
| |
| // Stops kernel tracing. |
| void Tracing::Stop() { |
| const zx_status_t status = zx_ktrace_control(debug_resource_, KTRACE_ACTION_STOP, 0, nullptr); |
| if (status != ZX_OK) { |
| FX_PLOGS(FATAL, status) << "zx_ktrace_control(_, KTRACE_ACTION_STOP, _, _)"; |
| } |
| |
| running_ = false; |
| } |
| |
| size_t Tracing::ReadKernelRecords(trace::TraceReader::RecordConsumer consumer, |
| trace::TraceReader::ErrorHandler error_handler) { |
| trace::TraceReader reader(std::move(consumer), std::move(error_handler)); |
| size_t bytes_read = 0; |
| |
| uint8_t buffer[4096]; |
| size_t available_bytes = 0; |
| ReadKernelBuffer(debug_resource_, nullptr, 0, 0, &available_bytes); |
| |
| size_t bytes_processed = 0; |
| while (bytes_processed < available_bytes) { |
| ReadKernelBuffer(debug_resource_, buffer, static_cast<uint32_t>(bytes_processed), |
| sizeof(buffer), &bytes_read); |
| if (bytes_read < 8) { |
| break; |
| } |
| trace::Chunk chunk{reinterpret_cast<uint64_t*>(buffer), bytes_read / 8}; |
| reader.ReadRecords(chunk); |
| bytes_processed += bytes_read - (chunk.remaining_words() * 8); |
| } |
| |
| return bytes_processed; |
| } |
| |
| // Reads trace buffer and converts output into human-readable format. Stores in location defined by |
| // <filepath>. Will overwrite any existing files with same name. |
| bool Tracing::WriteHumanReadable(std::ostream& filepath) { |
| if (running_) { |
| FX_LOGS(WARNING) << "Tracing was running when human readable translation was started. Tracing " |
| "stopped."; |
| Stop(); |
| } |
| |
| if (!filepath) { |
| FX_LOGS(ERROR) << "Failed to open file."; |
| return false; |
| } |
| |
| size_t record_count = 0; |
| size_t error_count = 0; |
| |
| trace::TraceReader::RecordConsumer accumulate_records = [&record_count, |
| &filepath](trace::Record rec) { |
| filepath << rec.ToString() << "\n"; |
| record_count++; |
| }; |
| trace::TraceReader::ErrorHandler accumulate_errors = [&error_count](const fbl::String& error) { |
| FX_LOGS(ERROR) << error << "\n"; |
| error_count++; |
| }; |
| size_t bytes_read = |
| ReadKernelRecords(std::move(accumulate_records), std::move(accumulate_errors)); |
| |
| filepath << "\nTotal records read: " << std::dec << record_count |
| << "\nTotal bytes read: " << std::dec << bytes_read << "\n"; |
| |
| return error_count == 0; |
| } |
| |
| // Picks out traces pertaining to name in string_ref and populates stats on them. Returns false if |
| // name not found. |
| bool Tracing::PopulateDurationStats(std::string string_ref, |
| std::vector<DurationStats>* duration_stats, |
| std::map<uint64_t, QueuingStats>* queuing_stats) { |
| if (running_) { |
| FX_LOGS(WARNING) << "Tracing was running when duration stats were started. Tracing stopped."; |
| Stop(); |
| } |
| |
| size_t error_count = 0; |
| bool string_ref_found = false; |
| |
| trace::TraceReader::RecordConsumer accumulate_records = [duration_stats, queuing_stats, |
| &string_ref_found, |
| &string_ref](trace::Record record) { |
| auto name = record.GetName(); |
| if (name && *name == string_ref) { |
| string_ref_found = true; |
| // Match duration records for given string ref. |
| if (record.type() == trace::RecordType::kEvent) { |
| auto& event = record.GetEvent(); |
| if (event.type() == trace::EventType::kDurationComplete) { |
| std::vector<trace::Argument> args; |
| for (auto&& argument : event.arguments) { |
| args.emplace_back(std::move(argument)); |
| } |
| duration_stats->emplace_back(event.timestamp, event.data.GetDurationComplete().end_time, |
| event.data.GetDurationComplete().end_time - event.timestamp, |
| std::move(args)); |
| } else if (event.type() == trace::EventType::kDurationBegin) { |
| duration_stats->emplace_back(event.timestamp); |
| } else if (event.type() == trace::EventType::kDurationEnd) { |
| for (auto duration = duration_stats->rbegin(); duration != duration_stats->rend(); |
| duration++) { |
| if (duration->end_ts_ns == 0) { |
| duration->end_ts_ns = event.timestamp; |
| duration->wall_duration_ns = event.timestamp - duration->begin_ts_ns; |
| for (auto&& argument : event.arguments) { |
| duration->arguments.emplace_back(std::move(argument)); |
| } |
| break; |
| } |
| } |
| } else if (event.type() == trace::EventType::kFlowBegin) { |
| auto [it, inserted] = queuing_stats->emplace( |
| event.data.GetFlowBegin().id, |
| QueuingStats(event.timestamp, event.process_thread.thread_koid())); |
| if (!inserted) { |
| FX_LOGS(ERROR) << "Failed to insert flow event of id: " << event.data.GetFlowBegin().id |
| << ". Id already exists"; |
| } |
| } else if (event.type() == trace::EventType::kFlowEnd) { |
| auto flow_iter = queuing_stats->find(event.data.GetFlowEnd().id); |
| if (flow_iter == queuing_stats->end()) { |
| return; |
| } |
| flow_iter->second.end_ts_ns = event.timestamp; |
| flow_iter->second.queuing_time_ns = |
| flow_iter->second.end_ts_ns - flow_iter->second.begin_ts_ns; |
| } |
| } |
| } |
| }; |
| trace::TraceReader::ErrorHandler accumulate_errors = [&error_count](const fbl::String& error) { |
| FX_LOGS(ERROR) << error << "\n"; |
| error_count++; |
| }; |
| ReadKernelRecords(std::move(accumulate_records), std::move(accumulate_errors)); |
| return string_ref_found && error_count == 0; |
| } |