| // Copyright 2018 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 <fstream> |
| |
| #include <lib/async-loop/cpp/loop.h> |
| #include <lib/async/cpp/task.h> |
| #include <lib/fxl/logging.h> |
| #include <lib/zx/time.h> |
| #include <rapidjson/document.h> |
| #include <rapidjson/error/en.h> |
| #include <rapidjson/istreamwrapper.h> |
| #include <trace/event.h> |
| #include <trace/observer.h> |
| #include <zircon/status.h> |
| |
| #include "garnet/bin/trace/spec.h" |
| #include "garnet/bin/trace/tests/integration_test_utils.h" |
| |
| // The name of the trace events member in the json output file. |
| const char kTraceEventsMemberName[] = "traceEvents"; |
| |
| // The name of the category member in the json output file. |
| const char kCategoryMemberName[] = "cat"; |
| |
| // The name of the event name member in the json output file. |
| const char kEventNameMemberName[] = "name"; |
| |
| // Category for events we generate. |
| #define CATEGORY_NAME "trace:test" |
| |
| // Name to use in instant events. |
| #define INSTANT_EVENT_NAME "instant" |
| |
| // Size in bytes of the records |WriteTestRecords()| emits. |
| // We assume strings and thread references are not inlined. If they are that's |
| // ok. The point is this value is the minimum size of the record we're going to |
| // emit. If the record is larger then the trace will be larger, which is ok. |
| // If it's smaller we risk not stress-testing things enough. |
| // header-word(8) + ticks(8) + 3 arguments (= 3 * (8 + 8)) = 64 |
| constexpr size_t kRecordSize = 64; |
| |
| bool CreateProviderSynchronously( |
| async::Loop& loop, const char* name, |
| fbl::unique_ptr<trace::TraceProvider>* out_provider) { |
| async_dispatcher_t* dispatcher = loop.dispatcher(); |
| |
| fbl::unique_ptr<trace::TraceProvider> provider; |
| bool already_started; |
| if (!trace::TraceProvider::CreateSynchronously(dispatcher, name, &provider, |
| &already_started)) { |
| FXL_LOG(ERROR) << "Failed to create provider " << name; |
| return false; |
| } |
| |
| if (already_started) { |
| // At this point we're registered with trace-manager, and we know tracing |
| // has started. But we haven't received the Start() request yet, which |
| // contains the trace buffer (as a vmo) and other things. So wait for it. |
| if (!WaitForTracingToStart(loop, kStartTimeout)) { |
| FXL_LOG(ERROR) << "Provider " << name |
| << " failed waiting for tracing to start"; |
| return false; |
| } |
| } |
| |
| *out_provider = std::move(provider); |
| return true; |
| } |
| |
| void WriteTestEvents(size_t num_records) { |
| for (size_t i = 0; i < num_records; ++i) { |
| TRACE_INSTANT(CATEGORY_NAME, INSTANT_EVENT_NAME, TRACE_SCOPE_PROCESS, |
| "arg1", 1, "arg2", 2, "arg3", 3); |
| } |
| } |
| |
| bool VerifyTestEvents(const std::string& test_output_file, |
| size_t* out_num_events) { |
| // We don't know how many records got dropped, but we can count them, |
| // and verify they are what we expect. |
| std::ifstream in(test_output_file); |
| rapidjson::IStreamWrapper isw(in); |
| rapidjson::Document document; |
| |
| if (!document.ParseStream(isw).IsObject()) { |
| FXL_LOG(ERROR) << "Failed to parse JSON object from: " << test_output_file; |
| if (document.HasParseError()) { |
| FXL_LOG(ERROR) << "Parse error " |
| << GetParseError_En(document.GetParseError()) << " (" |
| << document.GetErrorOffset() << ")"; |
| } |
| return false; |
| } |
| |
| auto events_it = document.FindMember(kTraceEventsMemberName); |
| if (events_it == document.MemberEnd()) { |
| FXL_LOG(ERROR) << "Member not found: " << kTraceEventsMemberName; |
| return false; |
| } |
| const auto& value = events_it->value; |
| if (!value.IsArray()) { |
| FXL_LOG(ERROR) << kTraceEventsMemberName << " is not an array"; |
| return false; |
| } |
| |
| const auto& array = value.GetArray(); |
| for (size_t i = 0; i < array.Size(); ++i) { |
| if (!array[i].IsObject()) { |
| FXL_LOG(ERROR) << "Event " << i << " is not an object"; |
| return false; |
| } |
| |
| const auto& event = array[i]; |
| auto cat_it = event.FindMember(kCategoryMemberName); |
| if (cat_it == event.MemberEnd()) { |
| FXL_LOG(ERROR) << "Category not present in event"; |
| return false; |
| } |
| const auto& category_name = cat_it->value; |
| if (!category_name.IsString()) { |
| FXL_LOG(ERROR) << "Category name is not a string"; |
| return false; |
| } |
| if (strcmp(category_name.GetString(), CATEGORY_NAME) != 0) { |
| FXL_LOG(ERROR) << "Expected category not present in event, got: " |
| << category_name.GetString(); |
| return false; |
| } |
| |
| auto name_it = event.FindMember(kEventNameMemberName); |
| if (name_it == event.MemberEnd()) { |
| FXL_LOG(ERROR) << "Event name not present in event"; |
| return false; |
| } |
| const auto& event_name = name_it->value; |
| if (!event_name.IsString()) { |
| FXL_LOG(ERROR) << "Event name is not a string"; |
| return false; |
| } |
| if (strcmp(event_name.GetString(), INSTANT_EVENT_NAME) != 0) { |
| FXL_LOG(ERROR) << "Expected event not present in event, got: " |
| << event_name.GetString(); |
| return false; |
| } |
| } |
| |
| FXL_VLOG(1) << array.Size() << " trace events present"; |
| *out_num_events = array.Size(); |
| return true; |
| } |
| |
| void FillBuffer(size_t num_times, size_t buffer_size_in_mb) { |
| FXL_DCHECK(num_times && buffer_size_in_mb); |
| size_t buffer_size = buffer_size_in_mb * 1024 * 1024; |
| size_t num_iterations = buffer_size / kRecordSize; |
| |
| for (size_t i = 0; i < num_times; ++i) { |
| if (i > 0) { |
| // The buffer is roughly full at this point. |
| // Give TraceManager some time to catch up in streaming mode |
| // (but not too much time). |
| zx::nanosleep(zx::deadline_after(zx::sec(1))); |
| } |
| WriteTestEvents(num_iterations); |
| } |
| } |
| |
| static size_t GetMinimumNumberOfEvents(tracing::BufferingMode buffering_mode, |
| size_t buffer_size_in_mb) { |
| size_t buffer_size = buffer_size_in_mb * 1024 * 1024; |
| |
| // Being hyperaccurate here involves encoding a lot of internal knowledge |
| // about how records are stored. Things are also tricky because: |
| // - The physical buffer is split up into three pieces in streaming and |
| // circular modes (durable + 2 * rolling). Plus there's the header. |
| // - Events go into the rolling buffers, not the durable buffer, and we'd |
| // rather not encode knowlege of their different sizes here. We can be |
| // assured though that the durable buffer size is not greater than the |
| // rolling buffer sizes. |
| // - In circular mode it's possible one of the rolling buffers is empty. |
| // We just need a lower bound on the number of records that are present. |
| double percentage_buffer_filled; |
| switch (buffering_mode) { |
| case tracing::BufferingMode::kOneshot: |
| percentage_buffer_filled = 0.8; |
| break; |
| case tracing::BufferingMode::kCircular: |
| // One of the rolling buffers could be empty. |
| // If we conservatively assume durable,rolling buffers are all the same |
| // size this could be 0.333. Rounded down to 0.2 as a safe lower bound. |
| percentage_buffer_filled = 0.2; |
| break; |
| case tracing::BufferingMode::kStreaming: |
| // If we conservatively assume durable,rolling buffers are all the same |
| // size this could be 0.666. Rounded down to 0.5 as a safe lower bound. |
| percentage_buffer_filled = 0.5; |
| break; |
| default: |
| FXL_NOTREACHED(); |
| } |
| |
| return (buffer_size / kRecordSize) * percentage_buffer_filled; |
| } |
| |
| bool VerifyFullBuffer(const std::string& test_output_file, |
| tracing::BufferingMode buffering_mode, |
| size_t buffer_size_in_mb) { |
| size_t num_events; |
| if (!VerifyTestEvents(test_output_file, &num_events)) { |
| return false; |
| } |
| |
| size_t min_num_events = GetMinimumNumberOfEvents(buffering_mode, |
| buffer_size_in_mb); |
| if (num_events < min_num_events) { |
| FXL_LOG(ERROR) << "Insufficient number of events present, got " |
| << num_events << ", expected at least " << min_num_events; |
| return false; |
| } |
| |
| return true; |
| } |
| |
| bool WaitForTracingToStart(async::Loop& loop, zx::duration timeout) { |
| trace::TraceObserver trace_observer; |
| |
| bool started = false; |
| auto on_trace_state_changed = [&loop, &started]() { |
| if (trace_state() == TRACE_STARTED) { |
| started = true; |
| } |
| // Any state change is relevant to us. If we're not started then we must |
| // have transitioned from STOPPED to STARTED to at least STOPPING. |
| loop.Quit(); |
| }; |
| |
| trace_observer.Start(loop.dispatcher(), std::move(on_trace_state_changed)); |
| if (trace_state() == TRACE_STARTED) { |
| return true; |
| } |
| |
| async::TaskClosure timeout_task([&loop] { |
| FXL_LOG(ERROR) << "Timed out waiting for tracing to start"; |
| loop.Quit(); |
| }); |
| timeout_task.PostDelayed(loop.dispatcher(), timeout); |
| loop.Run(); |
| |
| return started; |
| } |