diff --git a/.clang-format b/.clang-format index 49d114d..98dd12d 100644 --- a/.clang-format +++ b/.clang-format @@ -1,5 +1,6 @@ --- Language: Cpp +Standard: c++17 BasedOnStyle: Google IndentWidth: 2 ColumnLimit: 0 @@ -7,4 +8,3 @@ PointerAlignment: Left AlignConsecutiveDeclarations: true ContinuationIndentWidth: 2 AlignAfterOpenBracket: BlockIndent - diff --git a/.clang-tidy b/.clang-tidy index 8fa807d..e3953db 100644 --- a/.clang-tidy +++ b/.clang-tidy @@ -11,6 +11,7 @@ cert-*, -bugprone-implicit-widening-of-multiplication-result, -bugprone-narrowing-conversions, -clang-diagnostic-unused-parameter, +-misc-include-cleaner, -misc-non-private-member-variables-in-classes, -modernize-pass-by-value, -modernize-use-nodiscard, @@ -19,7 +20,8 @@ cert-*, -readability-function-cognitive-complexity, -readability-identifier-length, -readability-isolate-declaration, --readability-magic-numbers' +-readability-magic-numbers, +-readability-redundant-inline-specifier' # TODO: Re-enable bugprone-exception-escape when no longer throwing # https://github.com/isocpp/CppCoreGuidelines/issues/1589 WarningsAsErrors: '*' diff --git a/CMakeLists.txt b/CMakeLists.txt index cdcf6a9..795f9c3 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -135,10 +135,11 @@ target_compile_definitions(cactus_rt PUBLIC QUILL_USE_BOUNDED_QUEUE) if (ENABLE_TRACING) target_sources(cactus_rt PRIVATE - src/cactus_rt/tracing/tracing_enabled.cc src/cactus_rt/tracing/sink.cc src/cactus_rt/tracing/thread_tracer.cc src/cactus_rt/tracing/trace_aggregator.cc + src/cactus_rt/tracing/tracing_enabled.cc + src/cactus_rt/tracing/utils/string_interner.cc ) target_link_libraries(cactus_rt diff --git a/Makefile b/Makefile index 5e3e418..3336393 100644 --- a/Makefile +++ b/Makefile @@ -24,11 +24,16 @@ test-debug: build-test-debug test: test-debug -benchmark: build-test-debug - build/test/tests/cactus_rt_tracing_benchmark +build-test-release: + cmake -Bbuild/benchmark -DCMAKE_BUILD_TYPE=RelWithDebInfo -DENABLE_EXAMPLES=OFF -DBUILD_TESTING=ON -DENABLE_CLANG_TIDY=$(ENABLE_CLANG_TIDY) -DENABLE_TRACING=$(ENABLE_TRACING) + cmake --build build/benchmark -j $$(nproc) + +benchmark: build-test-release + build/benchmark/tests/cactus_rt_tracing_benchmark clean: test ! -d build/test || cmake --build build/test --target clean + test ! -d build/benchmark || cmake --build build/benchmark --target clean test ! -d build/debug || cmake --build build/debug --target clean test ! -d build/release || cmake --build build/release --target clean diff --git a/docker/scripts/01-build.sh b/docker/scripts/01-build.sh index 3004153..beb74c4 100755 --- a/docker/scripts/01-build.sh +++ b/docker/scripts/01-build.sh @@ -6,5 +6,6 @@ cmake -B${CACTUS_RT_BUILD_DIR} \ -DENABLE_CLANG_TIDY=ON \ -DBUILD_DOCS=ON \ -DBUILD_TESTING=ON \ - -DENABLE_TRACING=${ENABLE_TRACING:-ON} + -DENABLE_TRACING=${ENABLE_TRACING:-ON} \ + -DCMAKE_BUILD_TYPE=RelWithDebInfo cmake --build ${CACTUS_RT_BUILD_DIR} -j $(nproc) diff --git a/docs/tracing.md b/docs/tracing.md index f9fb562..78f55a6 100644 --- a/docs/tracing.md +++ b/docs/tracing.md @@ -235,7 +235,57 @@ TODO... ### Performance and limitations -TODO... +#### Too much data causing buffer overflow and trace data drops + +#### String interning + +Perfetto allows event names and event categories to be interned by assigning +each unique string with an id and emitting the id rather than the string to save +space in the output trace files. This feature is implemented via the +`interned_data`, `name_iid`, and `category_iids` fields. A few details worth +noting: + +1. Perfetto uses `trusted_packet_sequence_id` to identify a single sequence. A + single sequence must have monotonically increasing timestamps for its + packets. Both Perfetto upstream and cactus-rt's implementation of the tracer + gives a sequence id per thread. In cactus-rt, this is especially important + as when we pop the data from the queue originating from multiple threads. +2. The `iid`s on their own are not sufficient to identify the string being + interned as it is not "globally" unique. It is only unique per sequence + (i.e. thus `(trusted_packet_sequence_id, iid)` is sufficient to identify an + interned string). This, along with (1), implies we have to intern strings on + a per-thread interner. + +### Other notes + +#### Perfetto SDK (upstream) can grab a lock when buffer is full + +- It seems that trace events are emitted via the `TRACE_EVENT` macro, which starts [here with `TRACE_EVENT_BEGIN`](https://github.com/google/perfetto/blob/v43.2/include/perfetto/tracing/track_event.h#L354). +- This then calls [`PERFETTO_INTERNAL_TRACK_EVENT_WITH_METHOD`](https://github.com/google/perfetto/blob/v43.2/include/perfetto/tracing/internal/track_event_macros.h#L115). + - This also calls `perfetto_track_event::internal::isDynamicCategory` +- This calls [`perfetto_track_event::TrackEvent::TraceForCategory`](https://github.com/google/perfetto/blob/v43.2/include/perfetto/tracing/internal/track_event_data_source.h#L376), which eventually calls: + - [`WriteTrackEventImpl`](https://github.com/google/perfetto/blob/v43.2/include/perfetto/tracing/internal/track_event_data_source.h#L874) which creates the protobuf packet via protozero. + - This [calls](https://github.com/google/perfetto/blob/v43.2/include/perfetto/tracing/internal/track_event_data_source.h#L901) [`TrackEventInternal::WriteEvent`](https://github.com/google/perfetto/blob/v43.2/src/tracing/internal/track_event_internal.cc#L528) + - which [calls](https://github.com/google/perfetto/blob/v43.2/src/tracing/internal/track_event_internal.cc#L537) [`NewTracePacket`](https://github.com/google/perfetto/blob/v43.2/src/tracing/internal/track_event_internal.cc#L470) + - which [calls](https://github.com/google/perfetto/blob/v43.2/src/tracing/internal/track_event_internal.cc#L479) [`TraceWriterBase::NewTracePacket`](https://github.com/google/perfetto/blob/v43.2/include/perfetto/tracing/trace_writer_base.h#L41-L61), **which might be [`TraceWriterImpl::NewTracePacket`](https://github.com/google/perfetto/blob/v43.2/src/tracing/core/trace_writer_impl.cc#L119).** + +From the other side: + +- `SharedMemoryArbiterImpl::GetNewChunk` grabs [a lock](https://github.com/google/perfetto/blob/v43.2/src/tracing/core/shared_memory_arbiter_impl.cc#L106-L110) + - [called from](https://github.com/google/perfetto/blob/v43.2/src/tracing/core/trace_writer_impl.cc#L242) `TraceWriterImpl::GetNewBuffer`. + - **This is called from [`TraceWriterImpl::NewTracePacket`](https://github.com/google/perfetto/blob/v43.2/src/tracing/core/trace_writer_impl.cc#L151).** This is called if the chunk is too full for the data. + +This means that there is a small chance that a lock can be taken, and an even smaller chance that a priority inversion could take place. This means it is not suitable for hard real-time applications and a custom tracing library must be written. + +#### Perfetto SDK string interning + +- `WriteTrackEventImpl` [calls](https://github.com/google/perfetto/blob/v43.2/include/perfetto/tracing/internal/track_event_data_source.h#L907) `TrackEventInternal::WriteEventName` which calls [`InternedEventName::Get`](https://github.com/google/perfetto/blob/v43.2/src/tracing/internal/track_event_internal.cc#L506), and which is implemented in [here](https://github.com/google/perfetto/blob/v43.2/include/perfetto/tracing/track_event_interned_data_index.h#L183). + - In here there's memory allocation due to [`LookupAndInsert`](https://github.com/google/perfetto/blob/v43.2/include/perfetto/tracing/track_event_interned_data_index.h#L99-L144) (called from [here](https://github.com/google/perfetto/blob/v43.2/include/perfetto/tracing/track_event_interned_data_index.h#L189)) using a `std::map`. + - Also `GetOrCreateIndex` [calls `new`](https://github.com/google/perfetto/blob/v43.2/include/perfetto/tracing/track_event_interned_data_index.h#L243). Likely this means another allocation potential on the hot path. + +This means Perfetto uses memory allocation on the hot path, which is not acceptable for cactus-rt due to real-time constraints. + +#### Perfetto SDK data dropping counter Advanced tuning and use cases ----------------------------- 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/examples/tracing_protos_example/synthetic_events.cc b/examples/tracing_protos_example/synthetic_events.cc index e2d22cf..7227b09 100644 --- a/examples/tracing_protos_example/synthetic_events.cc +++ b/examples/tracing_protos_example/synthetic_events.cc @@ -5,9 +5,12 @@ #include "trace.pb.h" +using cactus_tracing::vendor::perfetto::protos::InternedData; 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_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 cactus_tracing::vendor::perfetto::protos::TrackEvent_Type_TYPE_INSTANT; @@ -69,13 +72,22 @@ int main() { auto* packet3 = trace3.add_packet(); packet3->set_timestamp(200); + auto* interned_data1 = new InternedData(); + auto* event_name = interned_data1->add_event_names(); + event_name->set_iid(1); + event_name->set_name("My special parent"); + packet3->set_allocated_interned_data(interned_data1); + auto* track_event1 = new TrackEvent(); track_event1->set_type(TrackEvent_Type_TYPE_SLICE_BEGIN); track_event1->set_track_uuid(thread_uuid); - track_event1->set_name("My special parent"); + track_event1->set_name_iid(1); packet3->set_allocated_track_event(track_event1); packet3->set_trusted_packet_sequence_id(trusted_packet_sequence_id); + packet3->set_previous_packet_dropped(true); + packet3->set_first_packet_on_sequence(true); + packet3->set_sequence_flags(TracePacket_SequenceFlags_SEQ_INCREMENTAL_STATE_CLEARED | TracePacket_SequenceFlags_SEQ_NEEDS_INCREMENTAL_STATE); Trace trace4; auto* packet4 = trace4.add_packet(); @@ -123,19 +135,44 @@ int main() { packet7->set_trusted_packet_sequence_id(trusted_packet_sequence_id); - // Packets complete, write it into a file! + Trace trace8; + auto* packet8 = trace8.add_packet(); + packet8->set_timestamp(350); + + auto* track_event8 = new TrackEvent(); + track_event8->set_type(TrackEvent_Type_TYPE_SLICE_BEGIN); + track_event8->set_track_uuid(thread_uuid); + track_event8->set_name_iid(1); + packet8->set_allocated_track_event(track_event8); + packet8->set_sequence_flags(TracePacket_SequenceFlags_SEQ_NEEDS_INCREMENTAL_STATE); + + packet8->set_trusted_packet_sequence_id(trusted_packet_sequence_id); + + Trace trace9; + auto* packet9 = trace9.add_packet(); + packet9->set_timestamp(500); + + auto* track_event9 = new TrackEvent(); + track_event9->set_type(TrackEvent_Type_TYPE_SLICE_END); + track_event9->set_track_uuid(thread_uuid); + packet9->set_allocated_track_event(track_event9); + + packet9->set_trusted_packet_sequence_id(trusted_packet_sequence_id); { std::fstream output("build/direct_proto_serialization.perfetto-trace", std::ios::out | std::ios::trunc | std::ios::binary); - const std::array traces{ + const std::array traces{ &trace1, &trace2, &trace3, &trace4, &trace5, &trace6, - &trace7}; + &trace7, + &trace8, + &trace9, + }; for (const auto* trace : traces) { trace->SerializeToOstream(&output); 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/config.h b/include/cactus_rt/config.h index 2739326..075e69e 100644 --- a/include/cactus_rt/config.h +++ b/include/cactus_rt/config.h @@ -105,7 +105,7 @@ struct ThreadTracerConfig { */ struct ThreadConfig { // A vector of CPUs this thread should run on. If empty, no CPU restrictions are set. - std::vector cpu_affinity = {}; + std::vector cpu_affinity; // The size of the stack for this thread. Defaults to 8MB. size_t stack_size = 8 * 1024 * 1024; 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 6b0d1b1..4e18dcb 100644 --- a/include/cactus_rt/tracing/trace_aggregator.h +++ b/include/cactus_rt/tracing/trace_aggregator.h @@ -12,14 +12,18 @@ #include #include #include +#include +#include #include "sink.h" #include "thread_tracer.h" +#include "utils/string_interner.h" namespace cactus_rt::tracing { class TraceAggregator { using Trace = cactus_tracing::vendor::perfetto::protos::Trace; + using InternedData = cactus_tracing::vendor::perfetto::protos::InternedData; std::string process_name_; std::vector cpu_affinity_; @@ -33,14 +37,14 @@ class TraceAggregator { std::mutex mutex_; // A list of sinks the output should be written to. - std::list > sinks_; + std::list> sinks_; // This is a list of all known thread tracers. The background processing // thread will loop through this and pop all data from the queues. // Tracer is a friend class of ThreadTracer and thus can access all private // variables. These two structs are supposed to be tightly coupled so this is // no problem. - std::list > tracers_; + std::list> tracers_; // This is a vector of sticky trace packets that should always be emitted // when a new sink connects to the tracer. When a new sink connects to the @@ -53,6 +57,27 @@ class TraceAggregator { // The list of packets only grow here (although shouldn't grow that much). std::list sticky_trace_packets_; + // These are the interners for the event name and event categories to save + // space on the output. + utils::StringInterner event_name_interner_; + utils::StringInterner event_category_interner_; + + // This is a map of trusted_sequence_id to InternedData. + // + // The InternedData is allocated directly here and kept for the duration of + // the program. This is necessary in case we detect a packet loss, and we + // would like to re-emit the interned data for that sequence so it can + // continue. + // + // TODO: cap the amount of interned data to a maximum amount. + std::unordered_map> sequence_interned_data_; + + // This is a set of sequence ids where the first packet has already been emitted. + // If a sequence is not in here, the first packet emitted with have + // first_packet_on_sequence = true, previous_packet_dropped = true, and + // sequence_flags = SEQ_INCREMENTAL_STATE_CLEARED + std::unordered_set sequences_with_first_packet_emitted_; + public: explicit TraceAggregator(std::string name, std::vector cpu_affinity = {}); @@ -107,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) const; + + /** + * 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 new file mode 100644 index 0000000..fdce576 --- /dev/null +++ b/include/cactus_rt/tracing/utils/string_interner.h @@ -0,0 +1,53 @@ +#ifndef CACTUS_TRACING_STRING_INTERNER_H_ +#define CACTUS_TRACING_STRING_INTERNER_H_ + +#include +#include +#include +#include +#include + +namespace cactus_rt::tracing::utils { + +/** + * @private + * + * This class interns strings to become ids so the ids can be written to the + * trace file to save space. + * + * It is designed to convert the same string content to uint64_t. A string could + * be a const char*, std::string_view or std::string. If const char* is used, + * the string content is copied and stored in this class the first time to + * ensure it is not deleted during the lifetime of this class. + * + * This class is NOT thread-safe. + * + * TODO: is having a list of strings as references manually necessary? Can we + * not simply have std::string as the map key. When looking up values, does C++ + * convert const char* to string view which has a hash code and thus should find + * the string?... Why is C++ so confusing for simple stuff? It looks like this + * feature only exist in C++20 and above? Heterogenous lookup: + * http://wg21.link/P0919r0. + * + * So for now we are stuck with this. + */ +class StringInterner { + uint64_t current_id_ = 0; + std::unordered_map ids_; + std::list strings_; + + public: + std::pair GetId(const std::string_view& s); + std::pair GetId(const char* s); + + size_t Size() const { + return strings_.size(); + }; + + const std::unordered_map& Ids() const { + return ids_; + } +}; +} // namespace cactus_rt::tracing::utils + +#endif diff --git a/protos/CMakeLists.txt b/protos/CMakeLists.txt index 1c43e28..09d70f7 100644 --- a/protos/CMakeLists.txt +++ b/protos/CMakeLists.txt @@ -13,6 +13,7 @@ protobuf_generate_cpp( process_descriptor.proto counter_descriptor.proto track_event.proto + interned_data.proto source_location.proto ) diff --git a/protos/counter_descriptor.proto b/protos/counter_descriptor.proto index 126b30f..1d2d94f 100644 --- a/protos/counter_descriptor.proto +++ b/protos/counter_descriptor.proto @@ -16,7 +16,9 @@ syntax = "proto2"; -// Adapted from https://github.com/google/perfetto/blob/v36.1/protos/perfetto/trace/track_event/counter_descriptor.proto +// Adapted from https://github.com/google/perfetto/blob/v43.2/protos/perfetto/trace/track_event/counter_descriptor.proto +// +// No changes are made other than the package name. package cactus_tracing.vendor.perfetto.protos; diff --git a/protos/interned_data.proto b/protos/interned_data.proto new file mode 100644 index 0000000..ed3b78d --- /dev/null +++ b/protos/interned_data.proto @@ -0,0 +1,68 @@ +/* + * Copyright (C) 2019 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +syntax = "proto2"; + +import "source_location.proto"; +import "track_event.proto"; + +// Adapted from https://github.com/google/perfetto/blob/v43.2/protos/perfetto/trace/interned_data/interned_data.proto +// +// 1. Kept only event_names, event_categories, and source_locations + +package cactus_tracing.vendor.perfetto.protos; + +// ------------------------------ DATA INTERNING: ------------------------------ +// Interning indexes are built up gradually by adding the entries contained in +// each TracePacket of the same packet sequence (packets emitted by the same +// producer and TraceWriter, see |trusted_packet_sequence_id|). Thus, packets +// can only refer to interned data from other packets in the same sequence. +// +// The writer will emit new entries when it encounters new internable values +// that aren't yet in the index. Data in current and subsequent TracePackets can +// then refer to the entry by its position (interning ID, abbreviated "iid") in +// its index. An interning ID with value 0 is considered invalid (not set). +// +// Because of the incremental build-up, the interning index will miss data when +// TracePackets are lost, e.g. because a chunk was overridden in the central +// ring buffer. To avoid invalidation of the whole trace in such a case, the +// index is periodically reset (see SEQ_INCREMENTAL_STATE_CLEARED). +// When packet loss occurs, the reader will only lose interning data up to the +// next reset. +// ----------------------------------------------------------------------------- + +// Message that contains new entries for the interning indices of a packet +// sequence. +// +// The writer will usually emit new entries in the same TracePacket that first +// refers to them (since the last reset of interning state). They may also be +// emitted proactively in advance of referring to them in later packets. +// +// Next reserved id: 8 (up to 15). +// Next id: 36. +message InternedData { + // TODO(eseckler): Replace iid fields inside interned messages with + // map type fields in InternedData. + + // Each field's message type needs to specify an |iid| field, which is the ID + // of the entry in the field's interning index. Each field constructs its own + // index, thus interning IDs are scoped to the tracing session and field + // (usually as a counter for efficient var-int encoding), and optionally to + // the incremental state generation of the packet sequence. + repeated EventCategory event_categories = 1; + repeated EventName event_names = 2; + repeated SourceLocation source_locations = 4; +} diff --git a/protos/process_descriptor.proto b/protos/process_descriptor.proto index 73abfca..fe7fcf7 100644 --- a/protos/process_descriptor.proto +++ b/protos/process_descriptor.proto @@ -16,7 +16,9 @@ syntax = "proto2"; -// Adapted from https://github.com/google/perfetto/blob/v36.1/protos/perfetto/trace/track_event/process_descriptor.proto +// Adapted from https://github.com/google/perfetto/blob/v43.2/protos/perfetto/trace/track_event/process_descriptor.proto +// +// 1. Only the non-deprecated fields. package cactus_tracing.vendor.perfetto.protos; diff --git a/protos/source_location.proto b/protos/source_location.proto index 0ec4f97..14802c6 100644 --- a/protos/source_location.proto +++ b/protos/source_location.proto @@ -14,12 +14,26 @@ * limitations under the License. */ -// Adapted from https://github.com/google/perfetto/blob/v36.1/protos/perfetto/trace/track_event/source_location.proto +// Adapted from https://github.com/google/perfetto/blob/v43.2/protos/perfetto/trace/track_event/source_location.proto syntax = "proto2"; package cactus_tracing.vendor.perfetto.protos; +// -------------------- +// Interned data types: +// -------------------- + +// A source location, represented as a native symbol. +// This is similar to `message Frame` from +// protos/perfetto/trace/profiling/profile_common.proto, but for abitrary +// source code locations (for example in track event args), not stack frames. +message UnsymbolizedSourceLocation { + optional uint64 iid = 1; + optional uint64 mapping_id = 2; + optional uint64 rel_pc = 3; +} + message SourceLocation { optional uint64 iid = 1; optional string file_name = 2; diff --git a/protos/thread_descriptor.proto b/protos/thread_descriptor.proto index ec26426..bfd1180 100644 --- a/protos/thread_descriptor.proto +++ b/protos/thread_descriptor.proto @@ -14,13 +14,14 @@ * limitations under the License. */ -// Adapted from https://github.com/google/perfetto/blob/v36.1/protos/perfetto/trace/track_event/thread_descriptor.proto +// Adapted from https://github.com/google/perfetto/blob/v43.2/protos/perfetto/trace/track_event/thread_descriptor.proto +// +// 1. Only the three fields that describes the thread is kept as all other fields are deprecated. syntax = "proto2"; package cactus_tracing.vendor.perfetto.protos; - // Describes a thread's attributes. Emitted as part of a TrackDescriptor, // usually by the thread's trace writer. // diff --git a/protos/trace.proto b/protos/trace.proto index 21070ad..4963b72 100644 --- a/protos/trace.proto +++ b/protos/trace.proto @@ -14,7 +14,9 @@ * limitations under the License. */ -// Adapted from https://github.com/google/perfetto/blob/v36.1/protos/perfetto/trace/trace.proto +// Adapted from https://github.com/google/perfetto/blob/v43.2/protos/perfetto/trace/trace.proto +// +// No changes are made other than the package name. syntax = "proto2"; diff --git a/protos/trace_packet.proto b/protos/trace_packet.proto index 3297ab4..19dee5a 100644 --- a/protos/trace_packet.proto +++ b/protos/trace_packet.proto @@ -14,17 +14,15 @@ * limitations under the License. */ -// Adapter from https://github.com/google/perfetto/blob/v36.1/protos/perfetto/trace/trace_packet.proto +// Adapter from https://github.com/google/perfetto/blob/v43.2/protos/perfetto/trace/trace_packet.proto // -// TODO: consider adding in the following fields; -// -// - sequence_flags, trace_packet_defaults, previous_packet_dropped, first_packet_on_sequence -// - interned_data https://github.com/google/perfetto/issues/526 +// 1. Only the necessary fields are copied. Unnecessary fields are removed. syntax = "proto2"; import "track_event.proto"; import "track_descriptor.proto"; +import "interned_data.proto"; package cactus_tracing.vendor.perfetto.protos; @@ -56,6 +54,7 @@ message TracePacket { // The clock domain definition in ClockSnapshot can also override: // - The unit (default: 1ns). // - The absolute vs delta encoding (default: absolute timestamp). + // INCLUSION REASON: event timestamp optional uint64 timestamp = 8; // Specifies the ID of the clock used for the TracePacket |timestamp|. Can be @@ -63,12 +62,16 @@ message TracePacket { // producer-defined clock id. // If unspecified and if no default per-sequence value has been provided via // TracePacketDefaults, it defaults to BuiltinClocks::BOOTTIME. + // INCLUSION REASON: event timestamp optional uint32 timestamp_clock_id = 58; + // INCLUSION REASON: trace data oneof data { + // INCLUSION REASON: track event is the span information TrackEvent track_event = 11; // Only used by TrackEvent. + // INCLUSION REASON: this describes the track TrackDescriptor track_descriptor = 60; // This field is emitted at periodic intervals (~10s) and @@ -84,7 +87,73 @@ message TracePacket { // Uniquely identifies a producer + writer pair within the tracing session. A // value of zero denotes an invalid ID. Keep in sync with // TrustedPacket.trusted_packet_sequence_id. + // INCLUSION REASON: required field for the sequences oneof optional_trusted_packet_sequence_id { uint32 trusted_packet_sequence_id = 10; } + + // Incrementally emitted interned data, valid only on the packet's sequence + // (packets with the same |trusted_packet_sequence_id|). The writer will + // usually emit new interned data in the same TracePacket that first refers to + // it (since the last reset of interning state). It may also be emitted + // proactively in advance of referring to them in later packets. + // INCLUSION REASON: for interning string and other data. + optional InternedData interned_data = 12; + + enum SequenceFlags { + SEQ_UNSPECIFIED = 0; + + // Set by the writer to indicate that it will re-emit any incremental data + // for the packet's sequence before referring to it again. This includes + // interned data as well as periodically emitted data like + // Process/ThreadDescriptors. This flag only affects the current packet + // sequence (see |trusted_packet_sequence_id|). + // + // When set, this TracePacket and subsequent TracePackets on the same + // sequence will not refer to any incremental data emitted before this + // TracePacket. For example, previously emitted interned data will be + // re-emitted if it is referred to again. + // + // When the reader detects packet loss (|previous_packet_dropped|), it needs + // to skip packets in the sequence until the next one with this flag set, to + // ensure intact incremental data. + SEQ_INCREMENTAL_STATE_CLEARED = 1; + + // This packet requires incremental state, such as TracePacketDefaults or + // InternedData, to be parsed correctly. The trace reader should skip this + // packet if incremental state is not valid on this sequence, i.e. if no + // packet with the SEQ_INCREMENTAL_STATE_CLEARED flag has been seen on the + // current |trusted_packet_sequence_id|. + SEQ_NEEDS_INCREMENTAL_STATE = 2; + }; + // INCLUSION REASON: This is required for interned data. Also the flags are supposed to be binary OR'ed + optional uint32 sequence_flags = 13; + + // Flag set by the service if, for the current packet sequence (see + // |trusted_packet_sequence_id|), either: + // * this is the first packet, or + // * one or multiple packets were dropped since the last packet that the + // consumer read from the sequence. This can happen if chunks in the trace + // buffer are overridden before the consumer could read them when the trace + // is configured in ring buffer mode. + // + // When packet loss occurs, incrementally emitted data (including interned + // data) on the sequence should be considered invalid up until the next packet + // with SEQ_INCREMENTAL_STATE_CLEARED set. + optional bool previous_packet_dropped = 42; + + // Flag set by a producer (starting from SDK v29) if, for the current packet + // sequence (see |trusted_packet_sequence_id|), this is the first packet. + // + // This flag can be used for distinguishing the two situations when + // processing the trace: + // 1. There are no prior events for the sequence because of data loss, e.g. + // due to ring buffer wrapping. + // 2. There are no prior events for the sequence because it didn't start + // before this packet (= there's definitely no preceding data loss). + // + // Given that older SDK versions do not support this flag, this flag not + // being present for a particular sequence does not necessarily imply data + // loss. + optional bool first_packet_on_sequence = 87; } diff --git a/protos/track_descriptor.proto b/protos/track_descriptor.proto index 6b6e71c..027ace3 100644 --- a/protos/track_descriptor.proto +++ b/protos/track_descriptor.proto @@ -14,7 +14,9 @@ * limitations under the License. */ -// Adapted from https://github.com/google/perfetto/blob/v36.1/protos/perfetto/trace/track_event/track_descriptor.proto +// Adapted from https://github.com/google/perfetto/blob/v43.2/protos/perfetto/trace/track_event/track_descriptor.proto +// +// 1. Removed chrome_process and chrome_thread syntax = "proto2"; @@ -82,4 +84,11 @@ message TrackDescriptor { // TYPE_COUNTER TrackEvents (and values provided via TrackEvent's // |extra_counter_values|). optional CounterDescriptor counter = 8; + + // If true, forces Trace Processor to use separate tracks for track events + // and system events for the same thread. + // Track events timestamps in Chrome have microsecond resolution, while + // system events use nanoseconds. It results in broken event nesting when + // track events and system events share a track. + optional bool disallow_merging_with_system_tracks = 9; } diff --git a/protos/track_event.proto b/protos/track_event.proto index f07b128..6e560c1 100644 --- a/protos/track_event.proto +++ b/protos/track_event.proto @@ -14,9 +14,9 @@ * limitations under the License. */ -// Adapted from https://github.com/google/perfetto/blob/v36.1/protos/perfetto/trace/track_event/track_event.proto +// Adapted from https://github.com/google/perfetto/blob/v43.2/protos/perfetto/trace/track_event/track_event.proto // -// TODO: add interned data of EventCategory and EventName +// 1. Only the required fields are imported. Rest are removed. syntax = "proto2"; @@ -86,7 +86,7 @@ package cactus_tracing.vendor.perfetto.protos; // their default track association) can be emitted as part of a // TrackEventDefaults message. // -// Next reserved id: 13 (up to 15). Next id: 50. +// Next reserved id: 13 (up to 15). Next id: 51. message TrackEvent { // Names of categories of the event. In the client library, categories are a // way to turn groups of individual events on or off. @@ -213,3 +213,17 @@ message TrackEvent { uint64 source_location_iid = 34; } } + +// -------------------- +// Interned data types: +// -------------------- + +message EventCategory { + optional uint64 iid = 1; + optional string name = 2; +} + +message EventName { + optional uint64 iid = 1; + optional string name = 2; +} 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/cyclic_thread.cc b/src/cactus_rt/cyclic_thread.cc index d560e94..3c0366e 100644 --- a/src/cactus_rt/cyclic_thread.cc +++ b/src/cactus_rt/cyclic_thread.cc @@ -25,7 +25,7 @@ void CyclicThread::Run() noexcept { Tracer().StartSpan("Loop", "cactusrt", loop_start); } - bool should_stop = Loop(loop_start - Thread::StartMonotonicTimeNs()); + const bool should_stop = Loop(loop_start - Thread::StartMonotonicTimeNs()); loop_end = NowNs(); diff --git a/src/cactus_rt/tracing/trace_aggregator.cc b/src/cactus_rt/tracing/trace_aggregator.cc index cda2d44..28c9d54 100644 --- a/src/cactus_rt/tracing/trace_aggregator.cc +++ b/src/cactus_rt/tracing/trace_aggregator.cc @@ -11,14 +11,21 @@ #include #include -using Trace = cactus_tracing::vendor::perfetto::protos::Trace; -using TrackDescriptor = cactus_tracing::vendor::perfetto::protos::TrackDescriptor; -using ThreadDescriptor = cactus_tracing::vendor::perfetto::protos::ThreadDescriptor; -using ProcessDescriptor = cactus_tracing::vendor::perfetto::protos::ProcessDescriptor; -using TrackEvent = cactus_tracing::vendor::perfetto::protos::TrackEvent; +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), @@ -40,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); } @@ -103,12 +116,10 @@ void TraceAggregator::Run() { Trace trace; auto num_events = TryDequeueOnceFromAllTracers(trace); - // TODO: what we should do here is: - // 1. While the dequeue is happening, we should check each tracer for errors/full queue problems. - // 2. Instead of writing the trace directly, we should put it into a bigger - // memory queue (bigger than the tracer queue), which would be written out - // in another thread. That should reduce the bottlenecks for this loop as - // otherwise this loop would be blocked by the writer. + // TODO: Instead of writing the trace directly, we should put it into a + // bigger memory queue (bigger than the tracer queue), which would be + // written out in another thread. That should reduce the bottlenecks for + // this loop as otherwise this loop would be blocked by the writer. if (num_events > 0) { WriteTrace(trace); @@ -182,6 +193,9 @@ size_t TraceAggregator::TryDequeueOnceFromAllTracers(Trace& trace) noexcept { continue; } + // TODO: While the dequeue is happening, we should check each tracer for + // errors/full queue problems. + num_events++; AddTrackEventPacketToTrace(trace, *tracer, event); } @@ -246,29 +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 -) const { +) { // 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); + 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/src/cactus_rt/tracing/utils/string_interner.cc b/src/cactus_rt/tracing/utils/string_interner.cc new file mode 100644 index 0000000..7411bf1 --- /dev/null +++ b/src/cactus_rt/tracing/utils/string_interner.cc @@ -0,0 +1,19 @@ +#include "cactus_rt/tracing/utils/string_interner.h" + +namespace cactus_rt::tracing::utils { +std::pair StringInterner::GetId(const std::string_view& s) { + if (auto it = ids_.find(s); it != ids_.end()) { + return std::make_pair(false, it->second); + } + + const auto& copied_str = strings_.emplace_back(s); + const auto id = ++current_id_; + ids_.emplace(copied_str, id); + + return std::make_pair(true, id); +} + +std::pair StringInterner::GetId(const char* s) { + return GetId(std::string_view{s}); +} +} // namespace cactus_rt::tracing::utils diff --git a/tests/CMakeLists.txt b/tests/CMakeLists.txt index 8cfc157..3bc16dc 100644 --- a/tests/CMakeLists.txt +++ b/tests/CMakeLists.txt @@ -21,6 +21,7 @@ if(ENABLE_TRACING) add_executable(cactus_rt_tracing_tests tracing/single_threaded_test.cc + tracing/string_interner_test.cc tracing/multi_threaded_test.cc tracing/helpers/assert_helpers.cc @@ -47,6 +48,13 @@ add_executable(cactus_rt_tracing_benchmark tracing/tracing_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 new file mode 100644 index 0000000..2300138 --- /dev/null +++ b/tests/tracing/string_interner_benchmark.cc @@ -0,0 +1,45 @@ +#include +#include + +namespace { +// The for (auto _ : state) triggers the following rule... +// NOLINTBEGIN(clang-analyzer-deadcode.DeadStores) +using cactus_rt::tracing::utils::StringInterner; + +StringInterner SetupInterner() { + StringInterner interner; + interner.GetId("hello1"); + interner.GetId("hello2"); + interner.GetId("hello3"); + interner.GetId("hello4"); + interner.GetId("hello5"); + interner.GetId("hello6"); + interner.GetId("hello7"); + interner.GetId("hello8"); + interner.GetId("hello9"); + return interner; +} + +void BM_StringInternerConstCharArr(benchmark::State& state) { + auto interner = SetupInterner(); + + for (auto _ : state) { + interner.GetId("hello1"); + } +} +BENCHMARK(BM_StringInternerConstCharArr); + +void BM_StringInternerStdLongString(benchmark::State& state) { + auto interner = SetupInterner(); + std::string s; + for (int i = 0; i < 500; i++) { + s.append("hello "); + } + + for (auto _ : state) { + interner.GetId(s); + } +} +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 new file mode 100644 index 0000000..dae5a8d --- /dev/null +++ b/tests/tracing/string_interner_test.cc @@ -0,0 +1,121 @@ +#include "cactus_rt/tracing/utils/string_interner.h" + +#include + +#include +#include +#include + +namespace cactus_rt::tracing::utils { + +TEST(StringInternerTest, BasicAssertions) { + StringInterner interner; + + const char* const_char_arr = "hello"; + char char_arr[sizeof(const_char_arr)]; // NOLINT(modernize-avoid-c-arrays,bugprone-sizeof-expression) + strncpy(char_arr, const_char_arr, sizeof(char_arr)); + + const std::string_view sv{const_char_arr}; + const std::string str{const_char_arr}; + + const auto [new1, id1] = interner.GetId("hello"); + const auto [new2, id2] = interner.GetId(const_char_arr); + const auto [new3, id3] = interner.GetId(char_arr); + const auto [new4, id4] = interner.GetId(sv); + const auto [new5, id5] = interner.GetId(str); + + EXPECT_NE(const_char_arr, char_arr); // Just a sanity check... + + // Everything should have the same id + EXPECT_EQ(id1, id2); + EXPECT_EQ(id1, id3); + EXPECT_EQ(id1, id4); + EXPECT_EQ(id1, id5); + + // Only one of them should be inserting. + EXPECT_TRUE(new1); + EXPECT_FALSE(new2); + EXPECT_FALSE(new3); + EXPECT_FALSE(new4); + EXPECT_FALSE(new5); + + // We expect the size of the strings memoized to be 1. + EXPECT_EQ(interner.Size(), 1); +} + +TEST(StringInternerTest, ManyStrings) { + StringInterner interner; + + const auto [new1, id1] = interner.GetId("hello1"); + const auto [new2, id2] = interner.GetId("hello2"); + const auto [new3, id3] = interner.GetId("hello3"); + const auto [new4, id4] = interner.GetId("hello4"); + const auto [new5, id5] = interner.GetId("hello5"); + const auto [new6, id6] = interner.GetId("hello6"); + const auto [new7, id7] = interner.GetId("hello7"); + const auto [new8, id8] = interner.GetId("hello8"); + const auto [new9, id9] = interner.GetId("hello9"); + + const std::unordered_set s{id1, id2, id3, id4, id5, id6, id7, id8, id9}; + + EXPECT_EQ(s.size(), 9); + EXPECT_EQ(interner.Size(), 9); + + for (const auto id : s) { + EXPECT_NE(id, 0); + } + + EXPECT_TRUE(new1); + EXPECT_TRUE(new2); + EXPECT_TRUE(new3); + EXPECT_TRUE(new4); + EXPECT_TRUE(new5); + EXPECT_TRUE(new6); + EXPECT_TRUE(new7); + EXPECT_TRUE(new8); + EXPECT_TRUE(new9); + + const std::string str{"hello1"}; + const auto [new10, id10] = interner.GetId(str.data()); + EXPECT_EQ(id1, id10); + EXPECT_FALSE(new10); + EXPECT_EQ(interner.Size(), 9); +} + +TEST(StringInternerTest, OutOfScope) { + StringInterner interner; + + uint64_t id1 = 0; + bool new1 = false; + uint64_t id2 = 0; + bool new2 = true; // intentionally wrong answer to ensure the expect is working + + { + std::string s{"hello1"}; + const auto [n, i] = interner.GetId(s.data()); + new1 = n; + id1 = i; + s.replace(1, 1, "g"); + } + + { + char c[8]; // NOLINT(modernize-avoid-c-arrays) + strncpy(c, "hello1", sizeof(c)); + const auto [n, i] = interner.GetId(c); + new2 = n; + id2 = i; + c[1] = 'g'; + } + + const auto [new3, id3] = interner.GetId("hello1"); + EXPECT_EQ(id1, id2); + EXPECT_EQ(id1, id3); + + EXPECT_TRUE(new1); + EXPECT_FALSE(new2); + EXPECT_FALSE(new3); + + EXPECT_EQ(interner.Size(), 1); +} + +} // namespace cactus_rt::tracing::utils