diff --git a/examples/tracing_example/main.cc b/examples/tracing_example/main.cc index c92667e..1d8e0d7 100644 --- a/examples/tracing_example/main.cc +++ b/examples/tracing_example/main.cc @@ -16,8 +16,19 @@ void WasteTime(std::chrono::microseconds duration) { class ExampleRTThread : public CyclicThread { int64_t loop_counter_ = 0; + static cactus_rt::CyclicThreadConfig CreateThreadConfig() { + cactus_rt::CyclicThreadConfig thread_config; + thread_config.period_ns = 1'000'000; + thread_config.cpu_affinity = std::vector{2}; + thread_config.SetFifoScheduler(80); + + // thread_config.tracer_config.trace_sleep = true; + thread_config.tracer_config.trace_wakeup_latency = true; + return thread_config; + } + public: - ExampleRTThread(const char* name, cactus_rt::CyclicThreadConfig config) : CyclicThread(name, config) {} + ExampleRTThread() : CyclicThread("ExampleRTThread", CreateThreadConfig()) {} int64_t GetLoopCounter() const { return loop_counter_; @@ -60,21 +71,38 @@ class ExampleRTThread : public CyclicThread { } }; -int main() { - cactus_rt::CyclicThreadConfig thread_config; - thread_config.period_ns = 1'000'000; - thread_config.cpu_affinity = std::vector{2}; - thread_config.SetFifoScheduler(80); +class SecondRTThread : public CyclicThread { + static cactus_rt::CyclicThreadConfig CreateThreadConfig() { + cactus_rt::CyclicThreadConfig thread_config; + thread_config.period_ns = 3'000'000; + thread_config.cpu_affinity = {1}; + thread_config.SetFifoScheduler(60); - // thread_config.tracer_config.trace_sleep = true; - thread_config.tracer_config.trace_wakeup_latency = true; + // thread_config.tracer_config.trace_sleep = true; + thread_config.tracer_config.trace_wakeup_latency = true; + return thread_config; + } + public: + SecondRTThread() : CyclicThread("SecondRTThread", CreateThreadConfig()) {} + + protected: + bool Loop(int64_t /*now*/) noexcept final { + const auto span = Tracer().WithSpan("Sense"); + WasteTime(std::chrono::microseconds(2000)); + return false; + } +}; + +int main() { cactus_rt::AppConfig app_config; - app_config.tracer_config.trace_aggregator_cpu_affinity = {1}; + app_config.tracer_config.trace_aggregator_cpu_affinity = {0}; // doesn't work yet - auto thread = std::make_shared("ExampleRTThread", thread_config); + auto thread1 = std::make_shared(); + auto thread2 = std::make_shared(); App app("TracingExampleApp", app_config); - app.RegisterThread(thread); + app.RegisterThread(thread1); + app.RegisterThread(thread2); std::cout << "Testing RT loop for 15 seconds with two trace sessions.\n"; @@ -97,6 +125,6 @@ int main() { app.Join(); // Don't need to stop the trace session as the app destructor will take care of it. - std::cout << "Number of loops executed: " << thread->GetLoopCounter() << "\n"; + std::cout << "Number of loops executed: " << thread1->GetLoopCounter() << "\n"; return 0; } diff --git a/include/cactus_rt/app.h b/include/cactus_rt/app.h index 5aedf7a..5b47f4b 100644 --- a/include/cactus_rt/app.h +++ b/include/cactus_rt/app.h @@ -43,7 +43,7 @@ class App { // TODO: investigate into a weak pointer. std::list> thread_tracers_; std::unique_ptr trace_aggregator_ = nullptr; - std::mutex tracer_mutex_; + std::mutex aggregator_mutex_; void SetDefaultLogFormat(quill::Config& cfg) { // Create a handler of stdout @@ -113,15 +113,14 @@ class App { /** * @brief Starts a new tracing session for the process. Will not start a new * tracing session if an existing tracing session is in progress. This - * function is not real-time safe. This will not register any output sinks. - * Use App::RegisterTraceSink() to register custom sinks. + * function is not real-time safe. */ - bool StartTraceSession() noexcept; + bool StartTraceSession(std::shared_ptr sink) noexcept; /** * @brief Register a custom trace sink after starting the trace session */ - void RegisterTraceSink(std::shared_ptr sink) noexcept; + void RegisterTraceSink(std::shared_ptr sink) noexcept; /** * @brief Stops the tracing session for the process. Will be no-op if tracing @@ -159,7 +158,7 @@ class App { */ void DeregisterThreadTracer(const std::shared_ptr& thread_tracer) noexcept; - void CreateAndStartTraceAggregator() noexcept; + void CreateAndStartTraceAggregator(std::shared_ptr sink) noexcept; void StopTraceAggregator() noexcept; }; diff --git a/include/cactus_rt/tracing/thread_tracer.h b/include/cactus_rt/tracing/thread_tracer.h index b0a6353..c5e3615 100644 --- a/include/cactus_rt/tracing/thread_tracer.h +++ b/include/cactus_rt/tracing/thread_tracer.h @@ -12,6 +12,7 @@ #include "../experimental/lockless/atomic_message.h" #include "track_event_internal.h" +#include "utils/string_interner.h" namespace cactus_rt::tracing { struct EventCountData { @@ -35,6 +36,13 @@ class ThreadTracer { moodycamel::ReaderWriterQueue queue_; + // The event name interning must be done per thread (per sequence). Thus it is + // stored here. However, this class must NEVER call functions here (other + // than maybe .Size), as the memory allocation can occur. This variable is + // designed to be used by TraceAggregator on the non-real-time path. + utils::StringInterner event_name_interner_; + utils::StringInterner event_category_interner_; + std::string name_; uint64_t track_uuid_; diff --git a/include/cactus_rt/tracing/trace_aggregator.h b/include/cactus_rt/tracing/trace_aggregator.h index f173512..4e18dcb 100644 --- a/include/cactus_rt/tracing/trace_aggregator.h +++ b/include/cactus_rt/tracing/trace_aggregator.h @@ -132,9 +132,35 @@ class TraceAggregator { size_t TryDequeueOnceFromAllTracers(Trace& trace) noexcept; void WriteTrace(const Trace& trace) noexcept; + /** + * Creates the initial process descriptor packet + */ Trace CreateProcessDescriptorPacket() const; + + /** + * Creates a thread descriptor packet given a thread tracer. + * + * Must be called while a lock is held. + */ Trace CreateThreadDescriptorPacket(const ThreadTracer& thread_tracer) const; - void AddTrackEventPacketToTrace(Trace& trace, const ThreadTracer& thread_tracer, const TrackEventInternal& track_event_internal); + + /** + * Adds the track event packet to an existing trace. + * + * Must be called while a lock is held. + */ + void AddTrackEventPacketToTrace(Trace& trace, ThreadTracer& thread_tracer, const TrackEventInternal& track_event_internal); + + /** + * Create the initial interned data packet if a new sink joins. + * + * Must be called while a lock is held. + * + * @param initial_timestamp The initial timestamp of the track, must be before + * all other packets about to be written. Commonly this should be the + * timestamp of the sticky packets. + */ + std::optional CreateInitialInternedDataPacket() const; }; } // namespace cactus_rt::tracing diff --git a/include/cactus_rt/tracing/utils/string_interner.h b/include/cactus_rt/tracing/utils/string_interner.h index 72a90ae..fdce576 100644 --- a/include/cactus_rt/tracing/utils/string_interner.h +++ b/include/cactus_rt/tracing/utils/string_interner.h @@ -43,6 +43,10 @@ class StringInterner { size_t Size() const { return strings_.size(); }; + + const std::unordered_map& Ids() const { + return ids_; + } }; } // namespace cactus_rt::tracing::utils diff --git a/src/cactus_rt/app.cc b/src/cactus_rt/app.cc index cb9d914..794630e 100644 --- a/src/cactus_rt/app.cc +++ b/src/cactus_rt/app.cc @@ -65,30 +65,29 @@ bool App::StartTraceSession(const char* output_filename) noexcept { return false; } - CreateAndStartTraceAggregator(); - trace_aggregator_->RegisterSink(std::make_unique(output_filename)); + CreateAndStartTraceAggregator(std::make_shared(output_filename)); cactus_rt::tracing::EnableTracing(); return true; } -bool App::StartTraceSession() noexcept { +bool App::StartTraceSession(std::shared_ptr sink) noexcept { if (cactus_rt::tracing::IsTracingEnabled()) { return false; } - CreateAndStartTraceAggregator(); + CreateAndStartTraceAggregator(sink); cactus_rt::tracing::EnableTracing(); return true; } -void App::RegisterTraceSink(std::shared_ptr sink) noexcept { - if (trace_aggregator_ == nullptr) { - return; - } +void App::RegisterTraceSink(std::shared_ptr sink) noexcept { + const std::scoped_lock lock(aggregator_mutex_); - trace_aggregator_->RegisterSink(sink); + if (trace_aggregator_ != nullptr) { + trace_aggregator_->RegisterSink(sink); + } } bool App::StopTraceSession() noexcept { @@ -103,7 +102,7 @@ bool App::StopTraceSession() noexcept { } void App::RegisterThreadTracer(std::shared_ptr thread_tracer) noexcept { - const std::scoped_lock lock(tracer_mutex_); + const std::scoped_lock lock(aggregator_mutex_); thread_tracers_.push_back(thread_tracer); @@ -113,7 +112,7 @@ void App::RegisterThreadTracer(std::shared_ptr thread_tra } void App::DeregisterThreadTracer(const std::shared_ptr& thread_tracer) noexcept { - const std::scoped_lock lock(tracer_mutex_); + const std::scoped_lock lock(aggregator_mutex_); thread_tracers_.remove_if([thread_tracer](const std::shared_ptr& t) { return t == thread_tracer; @@ -190,8 +189,8 @@ void App::StartQuill() { quill::start(); } -void App::CreateAndStartTraceAggregator() noexcept { - const std::scoped_lock lock(tracer_mutex_); +void App::CreateAndStartTraceAggregator(std::shared_ptr sink) noexcept { + const std::scoped_lock lock(aggregator_mutex_); if (trace_aggregator_ != nullptr) { // TODO: error here @@ -203,11 +202,15 @@ void App::CreateAndStartTraceAggregator() noexcept { trace_aggregator_->RegisterThreadTracer(tracer); } + if (sink != nullptr) { + trace_aggregator_->RegisterSink(sink); + } + trace_aggregator_->Start(); } void App::StopTraceAggregator() noexcept { - const std::scoped_lock lock(tracer_mutex_); + const std::scoped_lock lock(aggregator_mutex_); if (trace_aggregator_ == nullptr) { // TODO: error here diff --git a/src/cactus_rt/tracing/trace_aggregator.cc b/src/cactus_rt/tracing/trace_aggregator.cc index 883b232..28c9d54 100644 --- a/src/cactus_rt/tracing/trace_aggregator.cc +++ b/src/cactus_rt/tracing/trace_aggregator.cc @@ -14,12 +14,18 @@ using cactus_tracing::vendor::perfetto::protos::ProcessDescriptor; using cactus_tracing::vendor::perfetto::protos::ThreadDescriptor; using cactus_tracing::vendor::perfetto::protos::Trace; +using cactus_tracing::vendor::perfetto::protos::TracePacket; using cactus_tracing::vendor::perfetto::protos::TracePacket_SequenceFlags_SEQ_INCREMENTAL_STATE_CLEARED; +using cactus_tracing::vendor::perfetto::protos::TracePacket_SequenceFlags_SEQ_NEEDS_INCREMENTAL_STATE; using cactus_tracing::vendor::perfetto::protos::TrackDescriptor; using cactus_tracing::vendor::perfetto::protos::TrackEvent; using namespace std::chrono_literals; +namespace { +constexpr size_t kMaxInternedStrings = 10000; +} + namespace cactus_rt::tracing { TraceAggregator::TraceAggregator(std::string process_name, std::vector cpu_affinity) : process_name_(process_name), @@ -41,6 +47,12 @@ void TraceAggregator::RegisterSink(std::shared_ptr sink) { sink->Write(trace); } + auto interned_data_trace = CreateInitialInternedDataPacket(); + if (interned_data_trace) { + // TODO: deal with errors + sink->Write(*interned_data_trace); + } + sinks_.push_back(sink); } @@ -248,37 +260,154 @@ Trace TraceAggregator::CreateThreadDescriptorPacket(const ThreadTracer& thread_t void TraceAggregator::AddTrackEventPacketToTrace( Trace& trace, - const ThreadTracer& thread_tracer, + ThreadTracer& thread_tracer, const TrackEventInternal& track_event_internal ) { // NOLINTBEGIN(clang-analyzer-cplusplus.NewDeleteLeaks) + uint32_t sequence_flags = 0; + InternedData* interned_data = nullptr; + + // Create trace packet auto* packet = trace.add_packet(); packet->set_timestamp(track_event_internal.timestamp); + // Create track event auto* track_event = new TrackEvent(); track_event->set_track_uuid(thread_tracer.track_uuid_); track_event->set_type(track_event_internal.type); + // Deal with the event name if (track_event_internal.name != nullptr) { - track_event->set_name(track_event_internal.name); + if (thread_tracer.event_name_interner_.Size() < kMaxInternedStrings) { + auto [new_event_name, event_name_iid] = thread_tracer.event_name_interner_.GetId(track_event_internal.name); + + // If this is a never-seen-before event name, we need to emit the interned data into the data stream. + if (new_event_name) { + if (interned_data == nullptr) { + interned_data = new InternedData(); + } + + auto* event_name = interned_data->add_event_names(); + event_name->set_iid(event_name_iid); + event_name->set_name(track_event_internal.name); + } + + // Finally set the name_iid + track_event->set_name_iid(event_name_iid); + sequence_flags |= TracePacket_SequenceFlags_SEQ_NEEDS_INCREMENTAL_STATE; + } else { + LOG_WARNING_LIMIT( + std::chrono::milliseconds(5000), + Logger(), + "number of unique event names emitted in tracing is exceeding {} for thread {}, string interning is disabled. trace files may be excessively large", + kMaxInternedStrings, + thread_tracer.name_ + ); + track_event->set_name(track_event_internal.name); + } } - + // Deal with the event category. Code is slightly duplicated, which is fine + // for readability as we only have name and category to intern. // TODO: support multiple categories later? if (track_event_internal.category != nullptr) { - track_event->add_categories(track_event_internal.category); + if (thread_tracer.event_category_interner_.Size() < kMaxInternedStrings) { + auto [new_category, category_iid] = thread_tracer.event_category_interner_.GetId(track_event_internal.category); + + // If this is a never-seen-before event category, we need to emit the interned data into the data stream. + if (new_category) { + if (interned_data == nullptr) { + interned_data = new InternedData(); + } + + auto* category = interned_data->add_event_categories(); + category->set_iid(category_iid); + category->set_name(track_event_internal.category); + } + + // Finally set the category + track_event->add_category_iids(category_iid); + sequence_flags |= TracePacket_SequenceFlags_SEQ_NEEDS_INCREMENTAL_STATE; + } else { + LOG_WARNING_LIMIT( + std::chrono::milliseconds(5000), + Logger(), + "number of unique event category emitted in tracing is exceeding {} for thread {}, string interning is disabled. trace files may be excessively large", + kMaxInternedStrings, + thread_tracer.name_ + ); + track_event->add_categories(track_event_internal.category); + } } + // Set the track event into the packet and setup packet sequence id packet->set_allocated_track_event(track_event); packet->set_trusted_packet_sequence_id(thread_tracer.trusted_packet_sequence_id_); + // Deal with "first packet" if (sequences_with_first_packet_emitted_.count(thread_tracer.trusted_packet_sequence_id_) == 0) { sequences_with_first_packet_emitted_.insert(thread_tracer.trusted_packet_sequence_id_); packet->set_first_packet_on_sequence(true); packet->set_previous_packet_dropped(true); - packet->set_sequence_flags(TracePacket_SequenceFlags_SEQ_INCREMENTAL_STATE_CLEARED); // TODO: may need to OR this with SEQ_NEEDS_INCREMENTAL_STATE if above needs it. + sequence_flags |= TracePacket_SequenceFlags_SEQ_INCREMENTAL_STATE_CLEARED; + } + + // If interned data exists, add it to the packet + if (interned_data != nullptr) { + packet->set_allocated_interned_data(interned_data); + } + + // Write the sequence flag is needed + if (sequence_flags != 0) { + packet->set_sequence_flags(sequence_flags); } // NOLINTEND(clang-analyzer-cplusplus.NewDeleteLeaks) } +std::optional TraceAggregator::CreateInitialInternedDataPacket() const { + Trace trace; + + bool wrote_interned_data = false; + + for (const auto& tracer : this->tracers_) { + InternedData* interned_data = nullptr; + for (const auto& [name, name_iid] : tracer->event_name_interner_.Ids()) { + if (interned_data == nullptr) { + interned_data = new InternedData(); + } + + auto* event_name = interned_data->add_event_names(); + event_name->set_name(name.data()); + event_name->set_iid(name_iid); + } + + for (const auto& [category, category_iid] : tracer->event_category_interner_.Ids()) { + if (interned_data == nullptr) { + interned_data = new InternedData(); + } + + auto* event_category = interned_data->add_event_categories(); + event_category->set_name(category.data()); + event_category->set_iid(category_iid); + } + + if (interned_data != nullptr) { + wrote_interned_data = true; + TracePacket* packet = trace.add_packet(); + + // TODO: is it okay to not have a timestamp? + // packet->set_timestamp(initial_timestamp); + + packet->set_allocated_interned_data(interned_data); + packet->set_trusted_packet_sequence_id(tracer->trusted_packet_sequence_id_); + } + } + + if (wrote_interned_data) { + return trace; + } + + return std::nullopt; +} + } // namespace cactus_rt::tracing diff --git a/tests/CMakeLists.txt b/tests/CMakeLists.txt index fc47cc9..3bc16dc 100644 --- a/tests/CMakeLists.txt +++ b/tests/CMakeLists.txt @@ -46,9 +46,15 @@ find_package(benchmark REQUIRED) add_executable(cactus_rt_tracing_benchmark tracing/tracing_benchmark.cc - tracing/string_interner_benchmark.cc ) +if (ENABLE_TRACING) + target_sources(cactus_rt_tracing_benchmark + PRIVATE + tracing/string_interner_benchmark.cc + ) +endif() + target_link_libraries(cactus_rt_tracing_benchmark PRIVATE cactus_rt diff --git a/tests/tracing/helpers/assert_helpers.cc b/tests/tracing/helpers/assert_helpers.cc index d825eed..7df1063 100644 --- a/tests/tracing/helpers/assert_helpers.cc +++ b/tests/tracing/helpers/assert_helpers.cc @@ -3,6 +3,8 @@ #include #include +#include + std::string ProtoToJson(const google::protobuf::Message& proto) { std::string json; google::protobuf::util::MessageToJsonString(proto, &json); @@ -44,8 +46,6 @@ void AssertIsThreadTrackDescriptor(const TracePacket& packet, const char* thread void AssertIsTrackEventSliceBegin( const TracePacket& packet, - const char* event_name, - const char* category, uint64_t thread_track_uuid, uint32_t trusted_packet_sequence_id ) { @@ -54,15 +54,6 @@ void AssertIsTrackEventSliceBegin( const auto& track_event = packet.track_event(); ASSERT_TRUE(track_event.has_type()); ASSERT_EQ(track_event.type(), TrackEvent_Type_TYPE_SLICE_BEGIN); - ASSERT_TRUE(track_event.has_name()); - ASSERT_EQ(track_event.name(), event_name); - - if (category == nullptr) { - ASSERT_EQ(track_event.categories_size(), 0); - } else { - ASSERT_EQ(track_event.categories_size(), 1); - ASSERT_EQ(track_event.categories(0), category); - } ASSERT_EQ(track_event.track_uuid(), thread_track_uuid); @@ -74,6 +65,66 @@ void AssertIsTrackEventSliceBegin( } } +void AssertTrackEventHasIid( + const TracePacket& packet, + uint64_t event_name_iid, + uint64_t category_iid +) { + const auto& track_event = packet.track_event(); + ASSERT_FALSE(track_event.has_name()); + ASSERT_TRUE(track_event.has_name_iid()); + ASSERT_EQ(track_event.name_iid(), event_name_iid); + + ASSERT_EQ(track_event.categories_size(), 0); + if (category_iid == 0) { + ASSERT_EQ(track_event.category_iids_size(), 0); + } else { + ASSERT_EQ(track_event.category_iids_size(), 1); + ASSERT_EQ(track_event.category_iids(0), category_iid); + } +} + +void AssertTrackEventHasNoInternedData(const TracePacket& packet) { + ASSERT_FALSE(packet.has_interned_data()); +} + +std::unordered_map GetInternedEventNames(const TracePacket& packet) { + std::unordered_map event_names; + + if (!packet.has_interned_data()) { + return event_names; + } + + const auto& interned_data = packet.interned_data(); + + for (int i = 0; i < interned_data.event_names_size(); i++) { + const auto& event_name = interned_data.event_names(i); + if (event_name.has_name() && event_name.has_iid()) { + event_names.emplace(event_name.name(), event_name.iid()); + } + } + + return event_names; +} + +std::unordered_map GetInternedEventCategories(const TracePacket& packet) { + std::unordered_map categories; + + if (!packet.has_interned_data()) { + return categories; + } + + const auto& interned_data = packet.interned_data(); + for (int i = 0; i < interned_data.event_categories_size(); i++) { + const auto& category = interned_data.event_categories(i); + if (category.has_name() && category.has_iid()) { + categories.emplace(category.name(), category.iid()); + } + } + + return categories; +} + void AssertIsTrackEventSliceEnd(const TracePacket& packet, uint64_t thread_track_uuid, uint32_t trusted_packet_sequence_id) { ASSERT_TRUE(packet.has_track_event()); const auto& track_event = packet.track_event(); @@ -88,8 +139,6 @@ void AssertIsTrackEventSliceEnd(const TracePacket& packet, uint64_t thread_track void AssertIsTrackEventInstant( const TracePacket& packet, - const char* event_name, - const char* category, uint64_t thread_track_uuid, uint32_t trusted_packet_sequence_id ) { @@ -98,15 +147,6 @@ void AssertIsTrackEventInstant( const auto& track_event = packet.track_event(); ASSERT_TRUE(track_event.has_type()); ASSERT_EQ(track_event.type(), TrackEvent_Type_TYPE_INSTANT); - ASSERT_TRUE(track_event.has_name()); - ASSERT_EQ(track_event.name(), event_name); - - if (category == nullptr) { - ASSERT_EQ(track_event.categories_size(), 0); - } else { - ASSERT_EQ(track_event.categories_size(), 1); - ASSERT_EQ(track_event.categories(0), category); - } ASSERT_EQ(track_event.track_uuid(), thread_track_uuid); diff --git a/tests/tracing/helpers/assert_helpers.h b/tests/tracing/helpers/assert_helpers.h index c494ebc..033c27a 100644 --- a/tests/tracing/helpers/assert_helpers.h +++ b/tests/tracing/helpers/assert_helpers.h @@ -23,19 +23,27 @@ void AssertIsThreadTrackDescriptor(const TracePacket& packet, const char* thread void AssertIsTrackEventSliceBegin( const TracePacket& packet, - const char* event_name, - const char* category, uint64_t thread_track_uuid, // If 0, this assertion will only check if the id is >0. Otherwise it will do an equality check uint32_t trusted_packet_sequence_id = 0 ); +void AssertTrackEventHasIid( + const TracePacket& packet, + uint64_t event_name_iid, + uint64_t category_iid +); + +void AssertTrackEventHasNoInternedData(const TracePacket& packet); + +std::unordered_map GetInternedEventNames(const TracePacket& packet); + +std::unordered_map GetInternedEventCategories(const TracePacket& packet); + void AssertIsTrackEventSliceEnd(const TracePacket& packet, uint64_t thread_track_uuid, uint32_t trusted_packet_sequence_id); void AssertIsTrackEventInstant( const TracePacket& packet, - const char* event_name, - const char* category, uint64_t thread_track_uuid, uint32_t trusted_packet_sequence_id = 0 ); diff --git a/tests/tracing/multi_threaded_test.cc b/tests/tracing/multi_threaded_test.cc index 485d196..9fcf468 100644 --- a/tests/tracing/multi_threaded_test.cc +++ b/tests/tracing/multi_threaded_test.cc @@ -38,8 +38,7 @@ class MultiThreadTracingTest : public ::testing::Test { protected: void SetUp() override { - app_.StartTraceSession(); - app_.RegisterTraceSink(sink_); // TODO: make this registerable before the trace session starts. + app_.StartTraceSession(sink_); } void TearDown() override { @@ -87,19 +86,51 @@ TEST_F(MultiThreadTracingTest, TraceFromMultipleThreads) { AssertIsThreadTrackDescriptor(*regular_thread_traces[0], kRegularThreadName, process_track_uuid); const auto regular_thread_track_uuid = regular_thread_traces[0]->track_descriptor().uuid(); - AssertIsTrackEventInstant(*regular_thread_traces[1], "Event1", nullptr, regular_thread_track_uuid); + AssertIsTrackEventInstant(*regular_thread_traces[1], regular_thread_track_uuid); + + auto event_names = GetInternedEventNames(*regular_thread_traces[1]); + ASSERT_EQ(event_names.size(), 1); + + const auto event1_iid = event_names.at("Event1"); + ASSERT_GT(event1_iid, 0); + + AssertTrackEventHasIid(*regular_thread_traces[1], event1_iid, 0); + + const auto regular_thread_sequence_id = regular_thread_traces[1]->trusted_packet_sequence_id(); AssertIsThreadTrackDescriptor(*cyclic_thread_traces[0], kCyclicThreadName, process_track_uuid); const auto cyclic_thread_track_uuid = cyclic_thread_traces[0]->track_descriptor().uuid(); - AssertIsTrackEventSliceBegin(*cyclic_thread_traces[1], "Loop", "cactusrt", cyclic_thread_track_uuid); + AssertIsTrackEventSliceBegin(*cyclic_thread_traces[1], cyclic_thread_track_uuid); + + event_names = GetInternedEventNames(*cyclic_thread_traces[1]); + ASSERT_EQ(event_names.size(), 1); + + const auto loop_iid = event_names.at("Loop"); + ASSERT_GT(loop_iid, 0); + + auto event_categories = GetInternedEventCategories(*cyclic_thread_traces[1]); + ASSERT_EQ(event_categories.size(), 1); + + const auto cactusrt_category_iid = event_categories.at("cactusrt"); + ASSERT_GT(cactusrt_category_iid, 0); + + AssertTrackEventHasIid(*cyclic_thread_traces[1], loop_iid, cactusrt_category_iid); + auto sequence_id = cyclic_thread_traces[1]->trusted_packet_sequence_id(); + ASSERT_NE(regular_thread_sequence_id, sequence_id); for (size_t i = 0; i < 20; i++) { auto begin_idx = 1 + (i * 2); auto end_idx = 1 + (i * 2) + 1; - AssertIsTrackEventSliceBegin(*cyclic_thread_traces[begin_idx], "Loop", "cactusrt", cyclic_thread_track_uuid, sequence_id); + AssertIsTrackEventSliceBegin(*cyclic_thread_traces[begin_idx], cyclic_thread_track_uuid, sequence_id); + if (i != 0) { + // The first packet will have interned data and we checked it already with the previous block + AssertTrackEventHasNoInternedData(*cyclic_thread_traces[begin_idx]); + } + + AssertTrackEventHasIid(*cyclic_thread_traces[begin_idx], loop_iid, cactusrt_category_iid); AssertIsTrackEventSliceEnd(*cyclic_thread_traces[end_idx], cyclic_thread_track_uuid, sequence_id); } } @@ -124,14 +155,35 @@ TEST_F(MultiThreadTracingTest, CyclicThreadTracesLoop) { AssertIsThreadTrackDescriptor(*packets[1], kCyclicThreadName, process_track_uuid); const auto thread_track_uuid = packets[1]->track_descriptor().uuid(); - AssertIsTrackEventSliceBegin(*packets[2], "Loop", "cactusrt", thread_track_uuid); + AssertIsTrackEventSliceBegin(*packets[2], thread_track_uuid); + + auto event_names = GetInternedEventNames(*packets[2]); + ASSERT_EQ(event_names.size(), 1); + + const auto loop_iid = event_names.at("Loop"); + ASSERT_GT(loop_iid, 0); + + auto event_categories = GetInternedEventCategories(*packets[2]); + ASSERT_EQ(event_categories.size(), 1); + + const auto cactusrt_category_iid = event_categories.at("cactusrt"); + ASSERT_GT(cactusrt_category_iid, 0); + + AssertTrackEventHasIid(*packets[2], loop_iid, cactusrt_category_iid); + auto sequence_id = packets[2]->trusted_packet_sequence_id(); for (size_t i = 0; i < 20; i++) { auto begin_idx = 2 + (i * 2); auto end_idx = 2 + (i * 2) + 1; - AssertIsTrackEventSliceBegin(*packets[begin_idx], "Loop", "cactusrt", thread_track_uuid, sequence_id); + AssertIsTrackEventSliceBegin(*packets[begin_idx], thread_track_uuid); + if (i != 0) { + // The first packet will have interned data and we checked it already with the previous block + AssertTrackEventHasNoInternedData(*packets[begin_idx]); + } + + AssertTrackEventHasIid(*packets[begin_idx], loop_iid, cactusrt_category_iid); AssertIsTrackEventSliceEnd(*packets[end_idx], thread_track_uuid, sequence_id); } } @@ -167,14 +219,36 @@ TEST_F(MultiThreadTracingTest, CyclicThreadTracesSleepAndDoesNotTraceLoopIfConfi AssertIsThreadTrackDescriptor(*packets[1], thread_name, process_track_uuid); const auto thread_track_uuid = packets[1]->track_descriptor().uuid(); - AssertIsTrackEventSliceBegin(*packets[2], "Sleep", "cactusrt", thread_track_uuid); + AssertIsTrackEventSliceBegin(*packets[2], thread_track_uuid); + + auto event_names = GetInternedEventNames(*packets[2]); + ASSERT_EQ(event_names.size(), 1); + + const auto sleep_iid = event_names.at("Sleep"); + ASSERT_GT(sleep_iid, 0); + + auto event_categories = GetInternedEventCategories(*packets[2]); + ASSERT_EQ(event_categories.size(), 1); + + const auto cactusrt_category_iid = event_categories.at("cactusrt"); + ASSERT_GT(cactusrt_category_iid, 0); + + AssertTrackEventHasIid(*packets[2], sleep_iid, cactusrt_category_iid); + auto sequence_id = packets[2]->trusted_packet_sequence_id(); for (size_t i = 0; i < 19; i++) { auto begin_idx = 2 + (i * 2); auto end_idx = 2 + (i * 2) + 1; - AssertIsTrackEventSliceBegin(*packets[begin_idx], "Sleep", "cactusrt", thread_track_uuid, sequence_id); + AssertIsTrackEventSliceBegin(*packets[begin_idx], thread_track_uuid, sequence_id); + if (i != 0) { + // The first packet will have interned data and we checked it already with the previous block + AssertTrackEventHasNoInternedData(*packets[begin_idx]); + } + + AssertTrackEventHasIid(*packets[begin_idx], sleep_iid, cactusrt_category_iid); + AssertIsTrackEventSliceEnd(*packets[end_idx], thread_track_uuid, sequence_id); // 100 Hz = 10ms loop. @@ -220,7 +294,21 @@ TEST_F(MultiThreadTracingTest, CyclicThreadTracesLoopOverrun) { AssertIsThreadTrackDescriptor(*packets[1], thread_name, process_track_uuid); const auto thread_track_uuid = packets[1]->track_descriptor().uuid(); - AssertIsTrackEventInstant(*packets[2], "LoopOverrun", "cactusrt", thread_track_uuid); + AssertIsTrackEventInstant(*packets[2], thread_track_uuid); + + auto event_names = GetInternedEventNames(*packets[2]); + ASSERT_EQ(event_names.size(), 1); + + const auto name_iid = event_names.at("LoopOverrun"); + ASSERT_GT(name_iid, 0); + + auto event_categories = GetInternedEventCategories(*packets[2]); + ASSERT_EQ(event_categories.size(), 1); + + const auto cactusrt_category_iid = event_categories.at("cactusrt"); + ASSERT_GT(cactusrt_category_iid, 0); + + AssertTrackEventHasIid(*packets[2], name_iid, cactusrt_category_iid); } } // namespace cactus_rt diff --git a/tests/tracing/single_threaded_test.cc b/tests/tracing/single_threaded_test.cc index 01f0650..2134985 100644 --- a/tests/tracing/single_threaded_test.cc +++ b/tests/tracing/single_threaded_test.cc @@ -35,10 +35,7 @@ class SingleThreadTracingTest : public ::testing::Test { protected: void SetUp() override { app_.RegisterThread(regular_thread_); - app_.StartTraceSession(); // TODO: make each test manually start the trace session! - - app_.RegisterTraceSink(sink_); - + app_.StartTraceSession(sink_); // TODO: make each test manually start the trace session! app_.Start(); } @@ -72,9 +69,23 @@ TEST_F(SingleThreadTracingTest, WithSpan) { auto thread_track_uuid = packets[1]->track_descriptor().uuid(); // Third packet is the slice begin - AssertIsTrackEventSliceBegin(*packets[2], "TestEvent", "category", thread_track_uuid); + AssertIsTrackEventSliceBegin(*packets[2], thread_track_uuid); auto sequence_id = packets[2]->trusted_packet_sequence_id(); + const auto event_names = GetInternedEventNames(*packets[2]); + ASSERT_EQ(event_names.size(), 1); + + const auto event_name_iid = event_names.at("TestEvent"); + ASSERT_GT(event_name_iid, 0); + + const auto event_categories = GetInternedEventCategories(*packets[2]); + ASSERT_EQ(event_categories.size(), 1); + + const auto category_iid = event_categories.at("category"); + ASSERT_GT(category_iid, 0); + + AssertTrackEventHasIid(*packets[2], event_name_iid, category_iid); + // Fourth packet is slice end AssertIsTrackEventSliceEnd(*packets[3], thread_track_uuid, sequence_id); @@ -117,23 +128,94 @@ TEST_F(SingleThreadTracingTest, WithSpanNested) { AssertIsThreadTrackDescriptor(*packets[1], kRegularThreadName, process_track_uuid); auto thread_track_uuid = packets[1]->track_descriptor().uuid(); - AssertIsTrackEventSliceBegin(*packets[2], "OuterEvent", "outer", thread_track_uuid); + // First OuterEvent, outer packet + AssertIsTrackEventSliceBegin(*packets[2], thread_track_uuid); auto sequence_id = packets[2]->trusted_packet_sequence_id(); - AssertIsTrackEventSliceBegin(*packets[3], "InnerEvent1", "inner", thread_track_uuid, sequence_id); + auto event_names = GetInternedEventNames(*packets[2]); + ASSERT_EQ(event_names.size(), 1); + + const auto outer_event_iid = event_names.at("OuterEvent"); + ASSERT_GT(outer_event_iid, 0); + + auto event_categories = GetInternedEventCategories(*packets[2]); + ASSERT_EQ(event_categories.size(), 1); + + const auto outer_category_iid = event_categories.at("outer"); + ASSERT_GT(outer_category_iid, 0); + + AssertTrackEventHasIid(*packets[2], outer_event_iid, outer_category_iid); + + // First InnerEvent1, inner packet + AssertIsTrackEventSliceBegin(*packets[3], thread_track_uuid, sequence_id); + event_names = GetInternedEventNames(*packets[3]); + ASSERT_EQ(event_names.size(), 1); + + const auto inner_event1_iid = event_names.at("InnerEvent1"); + ASSERT_GT(inner_event1_iid, 0); + ASSERT_NE(inner_event1_iid, outer_event_iid); + + event_categories = GetInternedEventCategories(*packets[3]); + ASSERT_EQ(event_categories.size(), 1); + + const auto inner_category_iid = event_categories.at("inner"); + ASSERT_GT(inner_category_iid, 0); + ASSERT_NE(inner_category_iid, outer_category_iid); + + AssertTrackEventHasIid(*packets[3], inner_event1_iid, inner_category_iid); + + AssertIsTrackEventSliceBegin(*packets[4], thread_track_uuid, sequence_id); + event_names = GetInternedEventNames(*packets[4]); + ASSERT_EQ(event_names.size(), 1); + + // First InnerInnerEvent1, inner packet + const auto inner_inner_event1_iid = event_names.at("InnerInnerEvent1"); + ASSERT_GT(inner_inner_event1_iid, 0); + ASSERT_NE(inner_inner_event1_iid, inner_event1_iid); + ASSERT_NE(inner_inner_event1_iid, outer_event_iid); + + event_categories = GetInternedEventCategories(*packets[4]); + ASSERT_EQ(event_categories.size(), 0); + + AssertTrackEventHasIid(*packets[4], inner_inner_event1_iid, inner_category_iid); - AssertIsTrackEventSliceBegin(*packets[4], "InnerInnerEvent1", "inner", thread_track_uuid, sequence_id); AssertIsTrackEventSliceEnd(*packets[5], thread_track_uuid, sequence_id); AssertTrackEventDuration(*packets[4], *packets[5], 1000000, 10000000); - AssertIsTrackEventSliceBegin(*packets[6], "InnerInnerEvent2", "inner", thread_track_uuid, sequence_id); + // First InnerInnerEvent2, inner packet + AssertIsTrackEventSliceBegin(*packets[6], thread_track_uuid, sequence_id); + event_names = GetInternedEventNames(*packets[6]); + ASSERT_EQ(event_names.size(), 1); + + const auto inner_inner_event2_iid = event_names.at("InnerInnerEvent2"); + ASSERT_GT(inner_inner_event2_iid, 0); + ASSERT_NE(inner_inner_event2_iid, inner_inner_event1_iid); + ASSERT_NE(inner_inner_event2_iid, inner_event1_iid); + ASSERT_NE(inner_inner_event2_iid, outer_event_iid); + + AssertTrackEventHasIid(*packets[6], inner_inner_event2_iid, inner_category_iid); + AssertIsTrackEventSliceEnd(*packets[7], thread_track_uuid, sequence_id); AssertTrackEventDuration(*packets[6], *packets[7], 1000000, 10000000); AssertIsTrackEventSliceEnd(*packets[8], thread_track_uuid, sequence_id); AssertTrackEventDuration(*packets[3], *packets[8], 2000000, 20000000); - AssertIsTrackEventSliceBegin(*packets[9], "InnerEvent2", "inner", thread_track_uuid, sequence_id); + // First InnerEvent2, inner packet + AssertIsTrackEventSliceBegin(*packets[9], thread_track_uuid, sequence_id); + + event_names = GetInternedEventNames(*packets[9]); + ASSERT_EQ(event_names.size(), 1); + + const auto inner_event2_iid = event_names.at("InnerEvent2"); + ASSERT_GT(inner_event2_iid, 0); + ASSERT_NE(inner_event2_iid, inner_inner_event2_iid); + ASSERT_NE(inner_event2_iid, inner_inner_event1_iid); + ASSERT_NE(inner_event2_iid, inner_event1_iid); + ASSERT_NE(inner_event2_iid, outer_event_iid); + + AssertTrackEventHasIid(*packets[9], inner_event2_iid, inner_category_iid); + AssertIsTrackEventSliceEnd(*packets[10], thread_track_uuid, sequence_id); AssertTrackEventDuration(*packets[9], *packets[10], 2000000, 20000000); @@ -158,7 +240,21 @@ TEST_F(SingleThreadTracingTest, InstantEvent) { AssertIsThreadTrackDescriptor(*packets[1], kRegularThreadName, process_track_uuid); auto thread_track_uuid = packets[1]->track_descriptor().uuid(); - AssertIsTrackEventInstant(*packets[2], "MyCoolEvent", "instant", thread_track_uuid); + AssertIsTrackEventInstant(*packets[2], thread_track_uuid); + + const auto event_names = GetInternedEventNames(*packets[2]); + ASSERT_EQ(event_names.size(), 1); + + const auto event_name_iid = event_names.at("MyCoolEvent"); + ASSERT_GT(event_name_iid, 0); + + const auto event_categories = GetInternedEventCategories(*packets[2]); + ASSERT_EQ(event_categories.size(), 1); + + const auto category_iid = event_categories.at("instant"); + ASSERT_GT(category_iid, 0); + + AssertTrackEventHasIid(*packets[2], event_name_iid, category_iid); } TEST_F(SingleThreadTracingTest, StopTracingAndNoEventsAreRecorded) { @@ -187,17 +283,15 @@ TEST_F(SingleThreadTracingTest, RestartTracingStartsNewSession) { auto packets = GetPacketsFromTraces(traces); ASSERT_EQ(packets.size(), 4); + auto event1_thread_sequence_id1 = packets[2]->trusted_packet_sequence_id(); + regular_thread_->RunOneIteration([](MockRegularThread* self) { auto span = self->TracerForTest().WithSpan("Event2"); WasteTime(std::chrono::microseconds(1000)); }); - // In normal API usage, we always have to re-register sinks after starting a - // trace session, which may not be ideal?? Alternatively could use the short - // hand API to log directly to file... - app_.StartTraceSession(); - sink_->Clear(); // clear the sink so we have a fresh start when restarting trace - app_.RegisterTraceSink(sink_); // TODO: make it so that sinks are cached???? Doesn't make sense tho. + sink_->Clear(); // clear the sink so we have a fresh start when restarting trace + app_.StartTraceSession(sink_); regular_thread_->RunOneIteration([](MockRegularThread* self) { auto span = self->TracerForTest().WithSpan("Event3"); @@ -208,7 +302,7 @@ TEST_F(SingleThreadTracingTest, RestartTracingStartsNewSession) { auto traces2 = sink_->LoggedTraces(); auto packets2 = GetPacketsFromTraces(traces2); - ASSERT_EQ(packets2.size(), 4); + ASSERT_EQ(packets2.size(), 5); AssertIsProcessTrackDescriptor(*packets2[0], kAppName); const auto process_track_uuid = packets2[0]->track_descriptor().uuid(); @@ -216,13 +310,36 @@ TEST_F(SingleThreadTracingTest, RestartTracingStartsNewSession) { AssertIsThreadTrackDescriptor(*packets2[1], kRegularThreadName, process_track_uuid); auto thread_track_uuid = packets2[1]->track_descriptor().uuid(); + std::cout << "packets2: " << packets2[2]->ShortDebugString() << "\n"; + + // Event1 is emitted as interned data because that thread is still active and the event name got interned previously. + auto event_names = GetInternedEventNames(*packets2[2]); + ASSERT_EQ(event_names.size(), 1); + + auto event1_name_iid = event_names.at("Event1"); + ASSERT_GT(event1_name_iid, 0); + + auto event1_thread_sequence_id2 = packets2[2]->trusted_packet_sequence_id(); + + ASSERT_EQ(event1_thread_sequence_id1, event1_thread_sequence_id2); + // Note Event2 is lost as designed - AssertIsTrackEventSliceBegin(*packets2[2], "Event3", nullptr, thread_track_uuid); - auto sequence_id = packets2[2]->trusted_packet_sequence_id(); + AssertIsTrackEventSliceBegin(*packets2[3], thread_track_uuid); + auto sequence_id = packets2[3]->trusted_packet_sequence_id(); + + ASSERT_EQ(sequence_id, event1_thread_sequence_id2); + + event_names = GetInternedEventNames(*packets2[3]); + ASSERT_EQ(event_names.size(), 1); + + const auto event3_name_iid = event_names.at("Event3"); + ASSERT_GT(event3_name_iid, 0); - AssertIsTrackEventSliceEnd(*packets2[3], thread_track_uuid, sequence_id); + AssertTrackEventHasIid(*packets2[3], event3_name_iid, 0); - AssertTrackEventDuration(*packets2[2], *packets2[3], 1000000, 10000000); + AssertIsTrackEventSliceEnd(*packets2[4], thread_track_uuid, sequence_id); + + AssertTrackEventDuration(*packets2[3], *packets2[4], 1000000, 10000000); } TEST_F(SingleThreadTracingTest, DynamicallyAddingSinkWillWork) { @@ -249,7 +366,7 @@ TEST_F(SingleThreadTracingTest, DynamicallyAddingSinkWillWork) { auto traces2 = sink2->LoggedTraces(); auto packets2 = GetPacketsFromTraces(traces2); - ASSERT_EQ(packets2.size(), 3); + ASSERT_EQ(packets2.size(), 4); AssertIsProcessTrackDescriptor(*packets2[0], kAppName); const auto process_track_uuid = packets2[0]->track_descriptor().uuid(); @@ -257,7 +374,24 @@ TEST_F(SingleThreadTracingTest, DynamicallyAddingSinkWillWork) { AssertIsThreadTrackDescriptor(*packets2[1], kRegularThreadName, process_track_uuid); auto thread_track_uuid = packets2[1]->track_descriptor().uuid(); - AssertIsTrackEventInstant(*packets2[2], "Event2", nullptr, thread_track_uuid); + auto event_names = GetInternedEventNames(*packets2[2]); + ASSERT_EQ(event_names.size(), 1); + + const auto event1_name_iid = event_names.at("Event1"); + ASSERT_GT(event1_name_iid, 0); + + auto sequence_id = packets2[2]->trusted_packet_sequence_id(); + + AssertIsTrackEventInstant(*packets2[3], thread_track_uuid, sequence_id); + + event_names = GetInternedEventNames(*packets2[3]); + ASSERT_EQ(event_names.size(), 1); + + const auto event2_name_iid = event_names.at("Event2"); + ASSERT_GT(event2_name_iid, 0); + ASSERT_NE(event2_name_iid, event1_name_iid); + + AssertTrackEventHasIid(*packets2[3], event2_name_iid, 0); auto traces = sink_->LoggedTraces(); auto packets = GetPacketsFromTraces(traces); diff --git a/tests/tracing/string_interner_benchmark.cc b/tests/tracing/string_interner_benchmark.cc index c7c8e98..2300138 100644 --- a/tests/tracing/string_interner_benchmark.cc +++ b/tests/tracing/string_interner_benchmark.cc @@ -2,7 +2,8 @@ #include namespace { - +// The for (auto _ : state) triggers the following rule... +// NOLINTBEGIN(clang-analyzer-deadcode.DeadStores) using cactus_rt::tracing::utils::StringInterner; StringInterner SetupInterner() { @@ -40,4 +41,5 @@ void BM_StringInternerStdLongString(benchmark::State& state) { } } BENCHMARK(BM_StringInternerStdLongString); +// NOLINTEND(clang-analyzer-deadcode.DeadStores) } // namespace diff --git a/tests/tracing/string_interner_test.cc b/tests/tracing/string_interner_test.cc index 1be87fd..dae5a8d 100644 --- a/tests/tracing/string_interner_test.cc +++ b/tests/tracing/string_interner_test.cc @@ -6,8 +6,6 @@ #include #include -using cactus_rt::tracing::utils::StringInterner; - namespace cactus_rt::tracing::utils { TEST(StringInternerTest, BasicAssertions) {