From 57247c9f29b13c4e24f256f859d2748edab03b08 Mon Sep 17 00:00:00 2001 From: shijing xian Date: Fri, 3 Apr 2026 14:07:37 -0700 Subject: [PATCH 1/2] Implement Chromium tracing in SDK and some benchmark code under tests --- .gitignore | 1 + CMakeLists.txt | 7 + include/livekit/livekit.h | 1 + include/livekit/tracing.h | 56 ++ src/room.cpp | 3 + src/tests/CMakeLists.txt | 90 ++ src/tests/benchmark/benchmark_utils.cpp | 473 ++++++++++ src/tests/benchmark/benchmark_utils.h | 373 ++++++++ src/tests/common/test_common.h | 137 ++- src/tests/stress/test_latency_measurement.cpp | 135 +-- src/tests/stress/test_rpc_stress.cpp | 57 +- src/tests/unit/test_tracing.cpp | 551 +++++++++++ src/trace/event_tracer.cpp | 446 +++++++++ src/trace/event_tracer.h | 92 ++ src/trace/event_tracer_internal.h | 61 ++ src/trace/trace_event.h | 862 ++++++++++++++++++ src/trace/tracing.cpp | 31 + 17 files changed, 3313 insertions(+), 63 deletions(-) create mode 100644 include/livekit/tracing.h create mode 100644 src/tests/benchmark/benchmark_utils.cpp create mode 100644 src/tests/benchmark/benchmark_utils.h create mode 100644 src/tests/unit/test_tracing.cpp create mode 100644 src/trace/event_tracer.cpp create mode 100644 src/trace/event_tracer.h create mode 100644 src/trace/event_tracer_internal.h create mode 100644 src/trace/trace_event.h create mode 100644 src/trace/tracing.cpp diff --git a/.gitignore b/.gitignore index 6c8853a7..0e84b8f7 100644 --- a/.gitignore +++ b/.gitignore @@ -31,3 +31,4 @@ lib/ *.exe livekit.log web/ +*trace.json diff --git a/CMakeLists.txt b/CMakeLists.txt index 3af32d2c..8ae28aa9 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -359,6 +359,12 @@ add_library(livekit SHARED src/remote_video_track.cpp src/video_utils.cpp src/video_utils.h + # Tracing support (Chrome trace format) + src/trace/event_tracer.cpp + src/trace/event_tracer.h + src/trace/event_tracer_internal.h + src/trace/trace_event.h + src/trace/tracing.cpp ) if(WIN32) set_target_properties(livekit PROPERTIES WINDOWS_EXPORT_ALL_SYMBOLS ON) @@ -373,6 +379,7 @@ target_include_directories(livekit $ PRIVATE ${LIVEKIT_ROOT_DIR}/src + ${LIVEKIT_ROOT_DIR}/src/trace ${RUST_ROOT}/livekit-ffi/include ${PROTO_BINARY_DIR} ) diff --git a/include/livekit/livekit.h b/include/livekit/livekit.h index 7d055725..cda1baa7 100644 --- a/include/livekit/livekit.h +++ b/include/livekit/livekit.h @@ -34,6 +34,7 @@ #include "room.h" #include "room_delegate.h" #include "room_event_types.h" +#include "tracing.h" #include "track_publication.h" #include "video_frame.h" #include "video_source.h" diff --git a/include/livekit/tracing.h b/include/livekit/tracing.h new file mode 100644 index 00000000..d26e5e6f --- /dev/null +++ b/include/livekit/tracing.h @@ -0,0 +1,56 @@ +/* + * Copyright 2024 LiveKit + * + * 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. + */ + +#pragma once + +#include +#include + +namespace livekit { + +/** + * Start tracing and write events to a file. + * + * Events are written to the file asynchronously by a background thread. + * The file is written in Chrome trace format (JSON), viewable in: + * - Chrome: chrome://tracing + * - Perfetto: https://ui.perfetto.dev + * + * @param trace_file_path Path to the output trace file (e.g., "trace.json") + * @param categories Categories to enable (empty = all categories). + * Supports wildcards: "livekit.*" matches all livekit + * categories. + * @return true if tracing was started, false if already running or file error + */ +bool startTracing(const std::string &trace_file_path, + const std::vector &categories = {}); + +/** + * Stop tracing and flush remaining events to file. + * + * This blocks until all pending events are written and the file is closed. + * After stopping, the trace file is complete and ready for analysis. + */ +void stopTracing(); + +/** + * Check if tracing is currently active. + * + * @return true if tracing is running + */ +bool isTracingEnabled(); + +} // namespace livekit diff --git a/src/room.cpp b/src/room.cpp index 0ee28ba7..3228041b 100644 --- a/src/room.cpp +++ b/src/room.cpp @@ -36,6 +36,7 @@ #include "livekit_ffi.h" #include "room.pb.h" #include "room_proto_converter.h" +#include "trace/trace_event.h" #include "track.pb.h" #include "track_proto_converter.h" #include @@ -107,6 +108,8 @@ void Room::setDelegate(RoomDelegate *delegate) { bool Room::Connect(const std::string &url, const std::string &token, const RoomOptions &options) { + TRACE_EVENT0("livekit", "Room::Connect"); + { std::lock_guard g(lock_); if (connection_state_ != ConnectionState::Disconnected) { diff --git a/src/tests/CMakeLists.txt b/src/tests/CMakeLists.txt index 1b9695eb..c58d1c61 100644 --- a/src/tests/CMakeLists.txt +++ b/src/tests/CMakeLists.txt @@ -24,6 +24,86 @@ FetchContent_MakeAvailable(googletest) enable_testing() include(GoogleTest) +# ============================================================================ +# Benchmark Utilities (shared by all test types) +# ============================================================================ + +set(BENCHMARK_UTILS_SOURCES + "${CMAKE_CURRENT_SOURCE_DIR}/benchmark/benchmark_utils.cpp" + "${CMAKE_CURRENT_SOURCE_DIR}/benchmark/benchmark_utils.h" +) + +# ============================================================================ +# Unit Tests +# ============================================================================ + +# Collect all unit test sources +file(GLOB UNIT_TEST_SOURCES + "${CMAKE_CURRENT_SOURCE_DIR}/unit/*.cpp" +) + +if(UNIT_TEST_SOURCES) + add_executable(livekit_unit_tests + ${UNIT_TEST_SOURCES} + ${BENCHMARK_UTILS_SOURCES} + ) + + target_link_libraries(livekit_unit_tests + PRIVATE + livekit + GTest::gtest_main + GTest::gmock + ) + + target_include_directories(livekit_unit_tests + PRIVATE + ${LIVEKIT_ROOT_DIR}/include + ${LIVEKIT_ROOT_DIR}/src + ${LIVEKIT_ROOT_DIR}/src/trace + ${CMAKE_CURRENT_SOURCE_DIR}/benchmark + ) + + # Copy shared libraries to test executable directory + if(WIN32) + add_custom_command(TARGET livekit_unit_tests POST_BUILD + COMMAND ${CMAKE_COMMAND} -E copy_if_different + $ + $ + COMMAND ${CMAKE_COMMAND} -E copy_if_different + "$/livekit_ffi.dll" + $ + COMMENT "Copying DLLs to unit test directory" + ) + elseif(APPLE) + add_custom_command(TARGET livekit_unit_tests POST_BUILD + COMMAND ${CMAKE_COMMAND} -E copy_if_different + $ + $ + COMMAND ${CMAKE_COMMAND} -E copy_if_different + "$/liblivekit_ffi.dylib" + $ + COMMENT "Copying dylibs to unit test directory" + ) + else() + add_custom_command(TARGET livekit_unit_tests POST_BUILD + COMMAND ${CMAKE_COMMAND} -E copy_if_different + $ + $ + COMMAND ${CMAKE_COMMAND} -E copy_if_different + "$/liblivekit_ffi.so" + $ + COMMENT "Copying shared libraries to unit test directory" + ) + endif() + + # Register tests with CTest + gtest_discover_tests(livekit_unit_tests + WORKING_DIRECTORY ${CMAKE_RUNTIME_OUTPUT_DIRECTORY} + PROPERTIES + LABELS "unit" + ) +endif() + # ============================================================================ # Integration Tests # ============================================================================ @@ -36,6 +116,7 @@ file(GLOB INTEGRATION_TEST_SOURCES if(INTEGRATION_TEST_SOURCES) add_executable(livekit_integration_tests ${INTEGRATION_TEST_SOURCES} + ${BENCHMARK_UTILS_SOURCES} ) target_link_libraries(livekit_integration_tests @@ -49,6 +130,8 @@ if(INTEGRATION_TEST_SOURCES) PRIVATE ${LIVEKIT_ROOT_DIR}/include ${LIVEKIT_ROOT_DIR}/src + ${LIVEKIT_ROOT_DIR}/src/trace + ${CMAKE_CURRENT_SOURCE_DIR}/benchmark ${LIVEKIT_BINARY_DIR}/generated ${Protobuf_INCLUDE_DIRS} ) @@ -121,6 +204,7 @@ file(GLOB STRESS_TEST_SOURCES if(STRESS_TEST_SOURCES) add_executable(livekit_stress_tests ${STRESS_TEST_SOURCES} + ${BENCHMARK_UTILS_SOURCES} ) target_link_libraries(livekit_stress_tests @@ -134,6 +218,8 @@ if(STRESS_TEST_SOURCES) PRIVATE ${LIVEKIT_ROOT_DIR}/include ${LIVEKIT_ROOT_DIR}/src + ${LIVEKIT_ROOT_DIR}/src/trace + ${CMAKE_CURRENT_SOURCE_DIR}/benchmark ) # Copy shared libraries to test executable directory @@ -188,6 +274,10 @@ add_custom_target(run_all_tests COMMENT "Running all tests" ) +if(TARGET livekit_unit_tests) + add_dependencies(run_all_tests livekit_unit_tests) +endif() + if(TARGET livekit_integration_tests) add_dependencies(run_all_tests livekit_integration_tests) endif() diff --git a/src/tests/benchmark/benchmark_utils.cpp b/src/tests/benchmark/benchmark_utils.cpp new file mode 100644 index 00000000..eb18f927 --- /dev/null +++ b/src/tests/benchmark/benchmark_utils.cpp @@ -0,0 +1,473 @@ +/* + * Copyright 2024 LiveKit + * + * 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. + */ + +#include "benchmark_utils.h" + +#include +#include +#include +#include +#include +#include +#include +#include + +namespace livekit { +namespace test { +namespace benchmark { + +namespace { + +// Simple JSON parser for trace files +// Note: This is a minimal parser for Chrome trace format, not a general JSON +// parser + +std::string readFile(const std::string &path) { + std::ifstream file(path); + if (!file.is_open()) { + return ""; + } + std::stringstream buffer; + buffer << file.rdbuf(); + return buffer.str(); +} + +// Skip whitespace +void skipWhitespace(const std::string &json, size_t &pos) { + while (pos < json.size() && std::isspace(json[pos])) { + pos++; + } +} + +// Parse a JSON string (assumes pos is at opening quote) +std::string parseString(const std::string &json, size_t &pos) { + if (pos >= json.size() || json[pos] != '"') { + return ""; + } + pos++; // skip opening quote + + std::string result; + while (pos < json.size() && json[pos] != '"') { + if (json[pos] == '\\' && pos + 1 < json.size()) { + pos++; + switch (json[pos]) { + case '"': + result += '"'; + break; + case '\\': + result += '\\'; + break; + case 'n': + result += '\n'; + break; + case 't': + result += '\t'; + break; + case 'r': + result += '\r'; + break; + default: + result += json[pos]; + break; + } + } else { + result += json[pos]; + } + pos++; + } + if (pos < json.size()) { + pos++; // skip closing quote + } + return result; +} + +// Parse a JSON number +double parseNumber(const std::string &json, size_t &pos) { + size_t start = pos; + if (pos < json.size() && (json[pos] == '-' || json[pos] == '+')) { + pos++; + } + while (pos < json.size() && + (std::isdigit(json[pos]) || json[pos] == '.' || json[pos] == 'e' || + json[pos] == 'E' || json[pos] == '-' || json[pos] == '+')) { + pos++; + } + if (pos == start) { + return 0.0; + } + try { + return std::stod(json.substr(start, pos - start)); + } catch (...) { + return 0.0; + } +} + +// Parse a trace event object +TraceEvent parseTraceEvent(const std::string &json, size_t &pos) { + TraceEvent event; + + skipWhitespace(json, pos); + if (pos >= json.size() || json[pos] != '{') { + return event; + } + pos++; // skip '{' + + while (pos < json.size()) { + skipWhitespace(json, pos); + if (json[pos] == '}') { + pos++; + break; + } + if (json[pos] == ',') { + pos++; + continue; + } + + // Parse key + std::string key = parseString(json, pos); + skipWhitespace(json, pos); + if (pos < json.size() && json[pos] == ':') { + pos++; + } + skipWhitespace(json, pos); + + // Parse value based on key + if (key == "ph") { + std::string phase = parseString(json, pos); + if (!phase.empty()) { + event.phase = phase[0]; + } + } else if (key == "cat") { + event.category = parseString(json, pos); + } else if (key == "name") { + event.name = parseString(json, pos); + } else if (key == "ts") { + event.timestamp_us = static_cast(parseNumber(json, pos)); + } else if (key == "pid") { + event.pid = static_cast(parseNumber(json, pos)); + } else if (key == "tid") { + event.tid = static_cast(parseNumber(json, pos)); + } else if (key == "id") { + // ID can be a string like "0x1" or a number + if (json[pos] == '"') { + std::string id_str = parseString(json, pos); + try { + if (id_str.size() > 2 && id_str.substr(0, 2) == "0x") { + event.id = std::stoull(id_str.substr(2), nullptr, 16); + } else { + event.id = std::stoull(id_str); + } + } catch (...) { + event.id = 0; + } + } else { + event.id = static_cast(parseNumber(json, pos)); + } + } else if (key == "args") { + // Parse args object + skipWhitespace(json, pos); + if (pos < json.size() && json[pos] == '{') { + pos++; + while (pos < json.size()) { + skipWhitespace(json, pos); + if (json[pos] == '}') { + pos++; + break; + } + if (json[pos] == ',') { + pos++; + continue; + } + + std::string arg_key = parseString(json, pos); + skipWhitespace(json, pos); + if (pos < json.size() && json[pos] == ':') { + pos++; + } + skipWhitespace(json, pos); + + // Determine value type + if (json[pos] == '"') { + event.string_args[arg_key] = parseString(json, pos); + } else if (json[pos] == '-' || json[pos] == '+' || + std::isdigit(json[pos])) { + event.double_args[arg_key] = parseNumber(json, pos); + } else { + // Skip unknown value types (booleans, nulls, nested objects) + int depth = 0; + while (pos < json.size()) { + if (json[pos] == '{' || json[pos] == '[') + depth++; + else if (json[pos] == '}' || json[pos] == ']') { + if (depth == 0) + break; + depth--; + } else if (json[pos] == ',' && depth == 0) + break; + pos++; + } + } + } + } + } else { + // Skip unknown fields + if (pos < json.size() && json[pos] == '"') { + parseString(json, pos); + } else if (pos < json.size() && (json[pos] == '{' || json[pos] == '[')) { + int depth = 1; + pos++; + while (pos < json.size() && depth > 0) { + if (json[pos] == '{' || json[pos] == '[') + depth++; + else if (json[pos] == '}' || json[pos] == ']') + depth--; + pos++; + } + } else if (pos < json.size() && (json[pos] == '-' || json[pos] == '+' || + std::isdigit(json[pos]))) { + parseNumber(json, pos); + } else { + // Skip boolean/null + while (pos < json.size() && json[pos] != ',' && json[pos] != '}') { + pos++; + } + } + } + } + + return event; +} + +// Calculate percentile from sorted values +double percentile(const std::vector &sorted, double p) { + if (sorted.empty()) + return 0.0; + size_t idx = static_cast(sorted.size() * p / 100.0); + if (idx >= sorted.size()) + idx = sorted.size() - 1; + return sorted[idx]; +} + +} // namespace + +std::vector loadTraceFile(const std::string &trace_file_path) { + std::vector events; + + std::string json = readFile(trace_file_path); + if (json.empty()) { + return events; + } + + // Find traceEvents array + size_t pos = json.find("\"traceEvents\""); + if (pos == std::string::npos) { + return events; + } + + // Skip to array start + pos = json.find('[', pos); + if (pos == std::string::npos) { + return events; + } + pos++; // skip '[' + + // Parse events + while (pos < json.size()) { + skipWhitespace(json, pos); + if (pos >= json.size() || json[pos] == ']') { + break; + } + if (json[pos] == ',') { + pos++; + continue; + } + + TraceEvent event = parseTraceEvent(json, pos); + if (!event.name.empty()) { + events.push_back(event); + } + } + + return events; +} + +std::vector calculateDurations(const std::vector &events, + const std::string &name) { + std::vector durations; + + // For scoped events (B/E): track by thread ID + std::unordered_map scoped_begin_times; + + // For async events (S/F): track by event ID + std::unordered_map async_begin_times; + + for (const auto &event : events) { + if (event.name != name) { + continue; + } + + if (event.phase == 'B') { + // Scoped begin - track by thread ID + scoped_begin_times[event.tid] = event.timestamp_us; + } else if (event.phase == 'E') { + // Scoped end - match by thread ID + auto it = scoped_begin_times.find(event.tid); + if (it != scoped_begin_times.end()) { + double duration_ms = + static_cast(event.timestamp_us - it->second) / 1000.0; + durations.push_back(duration_ms); + scoped_begin_times.erase(it); + } + } else if (event.phase == 'S') { + // Async start - track by event ID + async_begin_times[event.id] = event.timestamp_us; + } else if (event.phase == 'F') { + // Async finish - match by event ID + auto it = async_begin_times.find(event.id); + if (it != async_begin_times.end()) { + double duration_ms = + static_cast(event.timestamp_us - it->second) / 1000.0; + durations.push_back(duration_ms); + async_begin_times.erase(it); + } + } + } + + return durations; +} + +BenchmarkStats calculateStats(const std::string &name, + const std::vector &durations) { + BenchmarkStats stats; + stats.name = name; + stats.count = durations.size(); + + if (durations.empty()) { + return stats; + } + + std::vector sorted = durations; + std::sort(sorted.begin(), sorted.end()); + + stats.min_ms = sorted.front(); + stats.max_ms = sorted.back(); + + double sum = std::accumulate(sorted.begin(), sorted.end(), 0.0); + stats.avg_ms = sum / sorted.size(); + + stats.p50_ms = percentile(sorted, 50); + stats.p95_ms = percentile(sorted, 95); + stats.p99_ms = percentile(sorted, 99); + + return stats; +} + +BenchmarkStats analyzeTraceFile(const std::string &trace_file_path, + const std::string &event_name) { + auto events = loadTraceFile(trace_file_path); + auto durations = calculateDurations(events, event_name); + return calculateStats(event_name, durations); +} + +std::map +analyzeTraceFile(const std::string &trace_file_path, + const std::vector &event_names) { + std::map results; + + auto events = loadTraceFile(trace_file_path); + + for (const auto &name : event_names) { + auto durations = calculateDurations(events, name); + results[name] = calculateStats(name, durations); + } + + return results; +} + +void printStats(const BenchmarkStats &stats) { + std::cout << "\n========================================" << std::endl; + std::cout << " " << stats.name << std::endl; + std::cout << "========================================" << std::endl; + + if (stats.count == 0) { + std::cout << "No measurements collected" << std::endl; + return; + } + + std::cout << std::fixed << std::setprecision(2); + std::cout << "Samples: " << stats.count << std::endl; + std::cout << "Min: " << stats.min_ms << " ms" << std::endl; + std::cout << "Avg: " << stats.avg_ms << " ms" << std::endl; + std::cout << "P50: " << stats.p50_ms << " ms" << std::endl; + std::cout << "P95: " << stats.p95_ms << " ms" << std::endl; + std::cout << "P99: " << stats.p99_ms << " ms" << std::endl; + std::cout << "Max: " << stats.max_ms << " ms" << std::endl; + std::cout << "========================================\n" << std::endl; +} + +void printComparisonTable(const std::vector &results) { + if (results.empty()) { + return; + } + + // Find max name length for formatting + size_t max_name_len = 10; + for (const auto &stats : results) { + max_name_len = std::max(max_name_len, stats.name.size()); + } + + // Print header + std::cout << "\n" + << std::left << std::setw(max_name_len + 2) << "Metric" + << std::right << std::setw(8) << "Count" << std::setw(10) << "Min" + << std::setw(10) << "Avg" << std::setw(10) << "P50" << std::setw(10) + << "P95" << std::setw(10) << "P99" << std::setw(10) << "Max" + << std::endl; + + std::cout << std::string(max_name_len + 2 + 68, '-') << std::endl; + + // Print rows + std::cout << std::fixed << std::setprecision(1); + for (const auto &stats : results) { + std::cout << std::left << std::setw(max_name_len + 2) << stats.name + << std::right << std::setw(8) << stats.count << std::setw(10) + << stats.min_ms << std::setw(10) << stats.avg_ms << std::setw(10) + << stats.p50_ms << std::setw(10) << stats.p95_ms << std::setw(10) + << stats.p99_ms << std::setw(10) << stats.max_ms << std::endl; + } + std::cout << std::endl; +} + +std::string exportToCsv(const std::vector &results) { + std::ostringstream csv; + + // Header + csv << "Metric,Count,Min_ms,Avg_ms,P50_ms,P95_ms,P99_ms,Max_ms\n"; + + // Data rows + csv << std::fixed << std::setprecision(3); + for (const auto &stats : results) { + csv << stats.name << "," << stats.count << "," << stats.min_ms << "," + << stats.avg_ms << "," << stats.p50_ms << "," << stats.p95_ms << "," + << stats.p99_ms << "," << stats.max_ms << "\n"; + } + + return csv.str(); +} + +} // namespace benchmark +} // namespace test +} // namespace livekit diff --git a/src/tests/benchmark/benchmark_utils.h b/src/tests/benchmark/benchmark_utils.h new file mode 100644 index 00000000..4eb139f4 --- /dev/null +++ b/src/tests/benchmark/benchmark_utils.h @@ -0,0 +1,373 @@ +/* + * Copyright 2024 LiveKit + * + * 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. + */ + +#pragma once + +#include + +#include +#include +#include +#include +#include +#include +#include +#include +#include + +namespace livekit { +namespace test { +namespace benchmark { + +// ============================================================================= +// Trace Categories (for documentation/organization) +// ============================================================================= + +constexpr const char *kCategoryConnect = "livekit.benchmark.connect"; +constexpr const char *kCategoryRpc = "livekit.benchmark.rpc"; +constexpr const char *kCategoryAudio = "livekit.benchmark.audio"; +constexpr const char *kCategoryDataChannel = "livekit.benchmark.datachannel"; + +// ============================================================================= +// Trace Event Structure (for parsing trace files) +// ============================================================================= + +/** + * Represents a single trace event parsed from a trace file. + */ +struct TraceEvent { + char phase = 0; // 'B' = begin, 'E' = end, 'S' = async start, 'F' = async + // finish, 'I' = instant + std::string category; // Event category + std::string name; // Event name + uint64_t id = 0; // Event ID (for async event pairing) + uint64_t timestamp_us = 0; // Timestamp in microseconds + uint32_t pid = 0; // Process ID + uint32_t tid = 0; // Thread ID + + // Arguments (optional) + std::map double_args; + std::map string_args; +}; + +// ============================================================================= +// Benchmark Statistics +// ============================================================================= + +/** + * Statistics calculated from trace event durations. + */ +struct BenchmarkStats { + std::string name; + size_t count = 0; + double min_ms = 0.0; + double max_ms = 0.0; + double avg_ms = 0.0; + double p50_ms = 0.0; + double p95_ms = 0.0; + double p99_ms = 0.0; +}; + +// ============================================================================= +// Trace File Analysis +// ============================================================================= + +/** + * Load and parse a trace file in Chrome trace format. + * + * @param trace_file_path Path to the trace JSON file + * @return Vector of parsed trace events, empty if file cannot be read + */ +std::vector loadTraceFile(const std::string &trace_file_path); + +/** + * Calculate durations for paired begin/end or async start/finish events. + * + * Pairs events by: + * - 'B'/'E' (scoped events): matched by name and thread ID + * - 'S'/'F' (async events): matched by name and event ID + * + * @param events Vector of trace events + * @param name Event name to match (category is ignored, matches by name only) + * @return Vector of durations in milliseconds + */ +std::vector calculateDurations(const std::vector &events, + const std::string &name); + +/** + * Calculate statistics from duration measurements. + * + * @param name Name for the statistics (for display) + * @param durations Vector of duration measurements in milliseconds + * @return Calculated statistics + */ +BenchmarkStats calculateStats(const std::string &name, + const std::vector &durations); + +/** + * Analyze a trace file and calculate statistics for a specific event. + * + * This is a convenience function that combines loadTraceFile(), + * calculateDurations(), and calculateStats(). + * + * @param trace_file_path Path to the trace JSON file + * @param event_name Event name to analyze + * @return Statistics for the event, or empty stats if not found + */ +BenchmarkStats analyzeTraceFile(const std::string &trace_file_path, + const std::string &event_name); + +/** + * Analyze a trace file and calculate statistics for multiple events. + * + * @param trace_file_path Path to the trace JSON file + * @param event_names List of event names to analyze + * @return Map of event name to statistics + */ +std::map +analyzeTraceFile(const std::string &trace_file_path, + const std::vector &event_names); + +// ============================================================================= +// Output Functions +// ============================================================================= + +/** + * Print benchmark statistics to stdout. + * + * @param stats Statistics to print + */ +void printStats(const BenchmarkStats &stats); + +/** + * Print a comparison table of multiple benchmark results. + * + * @param results Vector of benchmark statistics to compare + */ +void printComparisonTable(const std::vector &results); + +/** + * Export benchmark results to CSV format. + * + * @param results Vector of benchmark statistics + * @return CSV formatted string + */ +std::string exportToCsv(const std::vector &results); + +// ============================================================================= +// Benchmark Session (wraps tracing lifecycle) +// ============================================================================= + +/** + * Manages a benchmark session with automatic tracing. + * + * Usage: + * BenchmarkSession session("MyBenchmark", {"livekit.*"}); + * session.start("my_trace.json"); + * // ... run benchmark ... + * session.stop(); + */ +class BenchmarkSession { +public: + BenchmarkSession(const std::string &name, + const std::vector &categories = {}) + : name_(name), categories_(categories) { + if (categories_.empty()) { + categories_ = {"livekit", "livekit.*"}; + } + } + + ~BenchmarkSession() { + if (running_) { + stop(); + } + } + + void start(const std::string &trace_filename = "") { + if (running_) + return; + trace_filename_ = + trace_filename.empty() ? (name_ + "_trace.json") : trace_filename; + livekit::startTracing(trace_filename_, categories_); + running_ = true; + std::cout << "\n=== Benchmark Session Started: " << name_ + << " ===" << std::endl; + } + + void stop() { + if (!running_) + return; + livekit::stopTracing(); + running_ = false; + std::cout << "=== Benchmark Session Stopped: " << name_ + << " ===" << std::endl; + std::cout << "Trace saved to: " << trace_filename_ << std::endl; + std::cout << "View in Chrome: chrome://tracing or https://ui.perfetto.dev" + << std::endl; + } + + bool isRunning() const { return running_; } + const std::string &name() const { return name_; } + const std::string &traceFilename() const { return trace_filename_; } + +private: + std::string name_; + std::string trace_filename_; + std::vector categories_; + bool running_ = false; +}; + +// ============================================================================= +// Stress Test Statistics (in-memory, no tracing dependency) +// ============================================================================= + +/** + * Thread-safe statistics collector for stress tests. + * Tracks success/failure counts, latencies, and error breakdown. + */ +class TracedStressStats { +public: + TracedStressStats(const std::string &name, + const char *category = kCategoryRpc) + : name_(name), category_(category) {} + + void recordCall(bool success, double latency_ms, size_t payload_size = 0) { + std::lock_guard lock(mutex_); + total_calls_++; + if (success) { + successful_calls_++; + latencies_.push_back(latency_ms); + total_bytes_ += payload_size; + } else { + failed_calls_++; + } + } + + void recordError(const std::string &error_type) { + std::lock_guard lock(mutex_); + error_counts_[error_type]++; + } + + BenchmarkStats getLatencyStats() const { + std::lock_guard lock(mutex_); + return calculateStats(name_ + " Latency", latencies_); + } + + int totalCalls() const { + std::lock_guard lock(mutex_); + return total_calls_; + } + + int successfulCalls() const { + std::lock_guard lock(mutex_); + return successful_calls_; + } + + int failedCalls() const { + std::lock_guard lock(mutex_); + return failed_calls_; + } + + size_t totalBytes() const { + std::lock_guard lock(mutex_); + return total_bytes_; + } + + double successRate() const { + std::lock_guard lock(mutex_); + return total_calls_ > 0 ? (100.0 * successful_calls_ / total_calls_) : 0.0; + } + + std::map errorCounts() const { + std::lock_guard lock(mutex_); + return error_counts_; + } + + void printStats() const { + std::lock_guard lock(mutex_); + + std::cout << "\n========================================" << std::endl; + std::cout << " " << name_ << std::endl; + std::cout << "========================================" << std::endl; + std::cout << "Total calls: " << total_calls_ << std::endl; + std::cout << "Successful: " << successful_calls_ << std::endl; + std::cout << "Failed: " << failed_calls_ << std::endl; + std::cout << "Success rate: " << std::fixed << std::setprecision(2) + << (total_calls_ > 0 ? (100.0 * successful_calls_ / total_calls_) + : 0.0) + << "%" << std::endl; + std::cout << "Total bytes: " << total_bytes_ << " (" + << (total_bytes_ / (1024.0 * 1024.0)) << " MB)" << std::endl; + + if (!latencies_.empty()) { + std::vector sorted = latencies_; + std::sort(sorted.begin(), sorted.end()); + + double sum = std::accumulate(sorted.begin(), sorted.end(), 0.0); + double avg = sum / sorted.size(); + + auto percentile = [&sorted](double p) { + size_t idx = static_cast(sorted.size() * p / 100.0); + if (idx >= sorted.size()) + idx = sorted.size() - 1; + return sorted[idx]; + }; + + std::cout << "\nLatency (ms):" << std::endl; + std::cout << " Min: " << sorted.front() << std::endl; + std::cout << " Avg: " << avg << std::endl; + std::cout << " P50: " << percentile(50) << std::endl; + std::cout << " P95: " << percentile(95) << std::endl; + std::cout << " P99: " << percentile(99) << std::endl; + std::cout << " Max: " << sorted.back() << std::endl; + } + + if (!error_counts_.empty()) { + std::cout << "\nError breakdown:" << std::endl; + for (const auto &pair : error_counts_) { + std::cout << " " << pair.first << ": " << pair.second << std::endl; + } + } + + std::cout << "========================================\n" << std::endl; + } + + void clear() { + std::lock_guard lock(mutex_); + total_calls_ = 0; + successful_calls_ = 0; + failed_calls_ = 0; + total_bytes_ = 0; + latencies_.clear(); + error_counts_.clear(); + } + +private: + std::string name_; + const char *category_; + mutable std::mutex mutex_; + + int total_calls_ = 0; + int successful_calls_ = 0; + int failed_calls_ = 0; + size_t total_bytes_ = 0; + std::vector latencies_; + std::map error_counts_; +}; + +} // namespace benchmark +} // namespace test +} // namespace livekit diff --git a/src/tests/common/test_common.h b/src/tests/common/test_common.h index 3133adc9..d909c995 100644 --- a/src/tests/common/test_common.h +++ b/src/tests/common/test_common.h @@ -25,6 +25,7 @@ #include #include #include +#include #include #include #include @@ -34,11 +35,21 @@ #include #include +// Include benchmark utilities for trace file analysis +#include "../benchmark/benchmark_utils.h" + namespace livekit { namespace test { using namespace std::chrono_literals; +// ============================================================================= +// Tracing Configuration +// ============================================================================= + +// Set to 0 to disable tracing in tests, 1 to enable +#define LIVEKIT_TEST_ENABLE_TRACING 1 + // ============================================================================= // Common Constants // ============================================================================= @@ -413,16 +424,88 @@ class StressTestStats { // ============================================================================= /** - * Base test fixture that handles SDK initialization and configuration loading. + * Base test fixture that handles SDK initialization, configuration loading, + * and automatic tracing. + * + * ## Tracing Overview + * + * Tracing uses Chrome's trace event format to capture timing information. + * When enabled, the test automatically: + * 1. Generates a trace filename from test name in SetUp() + * 2. Starts tracing with a background writer thread + * 3. In TearDown(), stops tracing (flushes to file) and analyzes results + * + * ## Trace Event Types + * + * The SDK uses two types of trace events: + * + * 1. Scoped events (TRACE_EVENT0): Automatically record begin/end within a + * scope. Used for synchronous operations like Room::Connect(). + * - Phase 'B' = begin, Phase 'E' = end + * - Events are matched by thread ID + * + * 2. Async events (TRACE_EVENT_ASYNC_BEGIN/END): For operations that span + * threads or have explicit start/end points. + * - Phase 'S' = async start, Phase 'F' = async finish + * - Events are matched by a unique ID + * + * ## Output Files + * + * Trace files are saved as: __trace.json + * These can be viewed in: + * - Chrome: chrome://tracing + * - Perfetto: https://ui.perfetto.dev + * + * ## Enabling/Disabling Tracing + * + * Tracing is controlled by LIVEKIT_TEST_ENABLE_TRACING macro at the top of + * this file. Set to 0 to disable, 1 to enable. + * + * ## Default Events Analyzed + * + * The following events are automatically analyzed if present: + * - Room::Connect - Time to establish room connection + * - FfiClient::initialize - SDK initialization time + * + * Tests can add custom events to analyze via addTraceEventToAnalyze(). */ class LiveKitTestBase : public ::testing::Test { protected: void SetUp() override { livekit::initialize(livekit::LogLevel::Info, livekit::LogSink::kConsole); config_ = TestConfig::fromEnv(); + + // Tracing is controlled by compile-time macro LIVEKIT_TEST_ENABLE_TRACING + tracing_enabled_ = LIVEKIT_TEST_ENABLE_TRACING; + + if (tracing_enabled_) { + // Generate trace filename from test name: TestSuite_TestName_trace.json + const ::testing::TestInfo *test_info = + ::testing::UnitTest::GetInstance()->current_test_info(); + trace_filename_ = std::string(test_info->test_suite_name()) + "_" + + std::string(test_info->name()) + "_trace.json"; + + // Start tracing with background file writer + // Events are written to file asynchronously, so memory usage is bounded + livekit::startTracing(trace_filename_, {"livekit", "livekit.*"}); + } } - void TearDown() override { livekit::shutdown(); } + void TearDown() override { + if (tracing_enabled_) { + // Stop tracing - this flushes all pending events to the file + livekit::stopTracing(); + + std::cout << "\nTrace saved to: " << trace_filename_ << std::endl; + std::cout << "View in Chrome: chrome://tracing or https://ui.perfetto.dev" + << std::endl; + + // Analyze the trace file and print statistics + analyzeTraceFile(); + } + + livekit::shutdown(); + } /// Skip the test if the required environment variables are not set void skipIfNotConfigured() { @@ -432,7 +515,57 @@ class LiveKitTestBase : public ::testing::Test { } } + /** + * Register a custom trace event to analyze in TearDown(). + * + * In addition to the default events (Room::Connect, FfiClient::initialize), + * tests can register their own events to get statistics printed. + * + * Example: + * addTraceEventToAnalyze("audio_latency"); + * + * @param name The event name to analyze (e.g., "audio_latency") + */ + void addTraceEventToAnalyze(const std::string &name) { + custom_trace_events_.push_back(name); + } + TestConfig config_; + bool tracing_enabled_ = false; + std::string trace_filename_; + +private: + /** + * Analyze the trace file and print statistics. + * + * Loads the saved trace file, calculates durations for paired events, + * and prints statistics for default SDK events plus any custom events. + */ + void analyzeTraceFile() { + // Build list of events to analyze + std::vector events_to_analyze = {"Room::Connect", + "FfiClient::initialize"}; + + // Add custom events + for (const auto &name : custom_trace_events_) { + events_to_analyze.push_back(name); + } + + // Analyze the trace file + auto results = + benchmark::analyzeTraceFile(trace_filename_, events_to_analyze); + + // Print statistics for events that have data + std::cout << "\n=== Trace Statistics ===" << std::endl; + for (const auto &[name, stats] : results) { + if (stats.count > 0) { + benchmark::printStats(stats); + } + } + } + + /// Custom trace event names to analyze, in addition to defaults + std::vector custom_trace_events_; }; } // namespace test diff --git a/src/tests/stress/test_latency_measurement.cpp b/src/tests/stress/test_latency_measurement.cpp index e93d2102..ed2fd131 100644 --- a/src/tests/stress/test_latency_measurement.cpp +++ b/src/tests/stress/test_latency_measurement.cpp @@ -14,12 +14,16 @@ * limitations under the License. */ +#include "../benchmark/benchmark_utils.h" #include "../common/test_common.h" +#include "trace/trace_event.h" #include #include #include #include +using namespace livekit::test::benchmark; + namespace livekit { namespace test { @@ -279,24 +283,24 @@ TEST_F(LatencyMeasurementTest, ConnectionTime) { std::cout << "\n=== Connection Time Measurement Test ===" << std::endl; std::cout << "Iterations: " << config_.test_iterations << std::endl; - LatencyStats stats; RoomOptions options; options.auto_subscribe = true; + int successful_connections = 0; for (int i = 0; i < config_.test_iterations; ++i) { auto room = std::make_unique(); auto start = std::chrono::high_resolution_clock::now(); + // Room::Connect() has built-in TRACE_EVENT0 for automatic timing bool connected = room->Connect(config_.url, config_.caller_token, options); auto end = std::chrono::high_resolution_clock::now(); if (connected) { + successful_connections++; double latency_ms = std::chrono::duration(end - start).count(); - stats.addMeasurement(latency_ms); std::cout << " Iteration " << (i + 1) << ": " << std::fixed << std::setprecision(2) << latency_ms << " ms" << std::endl; - } else { std::cout << " Iteration " << (i + 1) << ": FAILED to connect" << std::endl; @@ -306,9 +310,11 @@ TEST_F(LatencyMeasurementTest, ConnectionTime) { std::this_thread::sleep_for(500ms); } - stats.printStats("Connection Time Statistics"); + // Tracing is automatically handled by LiveKitTestBase + // Stats for Room::Connect will be printed in TearDown() - EXPECT_GT(stats.count(), 0) << "At least one connection should succeed"; + EXPECT_GT(successful_connections, 0) + << "At least one connection should succeed"; } // ============================================================================= @@ -364,6 +370,9 @@ TEST_F(LatencyMeasurementTest, AudioLatency) { std::cout << "Using energy detection to measure audio round-trip latency" << std::endl; + // Register custom trace events to analyze at test end + addTraceEventToAnalyze("audio_latency"); + // Create receiver room with delegate auto receiver_room = std::make_unique(); AudioLatencyDelegate receiver_delegate; @@ -393,7 +402,6 @@ TEST_F(LatencyMeasurementTest, AudioLatency) { << "Sender not visible to receiver"; // Create audio source in real-time mode (queue_size_ms = 0) - // We'll pace the frames ourselves to match real-time delivery auto audio_source = std::make_shared(kAudioSampleRate, kAudioChannels, 0); auto audio_track = @@ -420,12 +428,12 @@ TEST_F(LatencyMeasurementTest, AudioLatency) { auto audio_stream = AudioStream::fromTrack(subscribed_track, stream_options); ASSERT_NE(audio_stream, nullptr) << "Failed to create audio stream"; - // Statistics for latency measurements - LatencyStats stats; std::atomic running{true}; std::atomic last_high_energy_send_time_us{0}; std::atomic waiting_for_echo{false}; std::atomic missed_pulses{0}; + std::atomic successful_measurements{0}; + std::atomic current_pulse_id{0}; // Timeout for waiting for echo (2 seconds) constexpr uint64_t kEchoTimeoutUs = 2000000; @@ -446,7 +454,11 @@ TEST_F(LatencyMeasurementTest, AudioLatency) { if (send_time_us > 0) { double latency_ms = (receive_time_us - send_time_us) / 1000.0; if (latency_ms > 0 && latency_ms < 5000) { // Sanity check - stats.addMeasurement(latency_ms); + // End the async trace span + TRACE_EVENT_ASYNC_END1(kCategoryAudio, "audio_latency", + current_pulse_id.load(), "latency_ms", + latency_ms); + successful_measurements++; std::cout << " Audio latency: " << std::fixed << std::setprecision(2) << latency_ms << " ms" << " (energy: " << std::setprecision(3) << energy << ")" @@ -459,24 +471,19 @@ TEST_F(LatencyMeasurementTest, AudioLatency) { }); // Sender thread: send audio frames in real-time (10ms audio every 10ms) - // Hijack periodic frames with high energy for latency measurement std::thread sender_thread([&]() { int frame_count = 0; - const int frames_between_pulses = - 100; // Send pulse every 100 frames (~1 second) + const int frames_between_pulses = 100; // ~1 second between pulses const int total_pulses = 10; int pulses_sent = 0; uint64_t pulse_send_time = 0; - int high_energy_frames_remaining = - 0; // Counter for consecutive high-energy frames + int high_energy_frames_remaining = 0; - // Use steady timing to maintain real-time pace auto next_frame_time = std::chrono::steady_clock::now(); const auto frame_duration = std::chrono::milliseconds(kAudioFrameDurationMs); while (running.load() && pulses_sent < total_pulses) { - // Wait until it's time to send the next frame (real-time pacing) std::this_thread::sleep_until(next_frame_time); next_frame_time += frame_duration; @@ -498,16 +505,14 @@ TEST_F(LatencyMeasurementTest, AudioLatency) { } } - // Continue sending high-energy frames if we're in the middle of a pulse if (high_energy_frames_remaining > 0) { frame_data = generateHighEnergyFrame(kSamplesPerFrame); high_energy_frames_remaining--; } else if (frame_count % frames_between_pulses == 0 && !waiting_for_echo.load()) { - // Start a new pulse - send multiple consecutive high-energy frames + // Start a new pulse frame_data = generateHighEnergyFrame(kSamplesPerFrame); - high_energy_frames_remaining = - kHighEnergyFramesPerPulse - 1; // -1 because we're sending one now + high_energy_frames_remaining = kHighEnergyFramesPerPulse - 1; pulse_send_time = std::chrono::duration_cast( @@ -517,10 +522,14 @@ TEST_F(LatencyMeasurementTest, AudioLatency) { waiting_for_echo.store(true); pulses_sent++; + // Begin async trace span + current_pulse_id.store(static_cast(pulses_sent)); + TRACE_EVENT_ASYNC_BEGIN1(kCategoryAudio, "audio_latency", + current_pulse_id.load(), "pulse", pulses_sent); + std::cout << "Sent pulse " << pulses_sent << "/" << total_pulses << " (" << kHighEnergyFramesPerPulse << " frames)" << std::endl; } else { - // Send silence (but still real audio frames for proper timing) frame_data = generateSilentFrame(kSamplesPerFrame); } @@ -536,7 +545,6 @@ TEST_F(LatencyMeasurementTest, AudioLatency) { frame_count++; } - // Wait a bit for last echo to arrive std::this_thread::sleep_for(2s); running.store(false); }); @@ -546,20 +554,18 @@ TEST_F(LatencyMeasurementTest, AudioLatency) { audio_stream->close(); receiver_thread.join(); - stats.printStats("Audio Latency Statistics"); - if (missed_pulses > 0) { std::cout << "Missed pulses (timeout): " << missed_pulses << std::endl; } // Clean up - ASSERT_NE(audio_track, nullptr) << "Audio track is null"; - ASSERT_NE(audio_track->publication(), nullptr) - << "Audio track publication is null"; sender_room->localParticipant()->unpublishTrack( audio_track->publication()->sid()); - EXPECT_GT(stats.count(), 0) + // Tracing is automatically handled by LiveKitTestBase + // Stats for audio_latency will be printed in TearDown() + + EXPECT_GT(successful_measurements.load(), 0) << "At least one audio latency measurement should be recorded"; } @@ -570,6 +576,11 @@ TEST_F(LatencyMeasurementTest, FullDeplexAudioLatency) { std::cout << "Measuring A->B, B->A, and A->B->A using audio ping-pong" << std::endl; + // Register custom trace events to analyze at test end + addTraceEventToAnalyze("A_to_B"); + addTraceEventToAnalyze("B_to_A"); + addTraceEventToAnalyze("round_trip"); + auto room_a = std::make_unique(); // caller auto room_b = std::make_unique(); // receiver AudioLatencyDelegate delegate_a; @@ -624,9 +635,6 @@ TEST_F(LatencyMeasurementTest, FullDeplexAudioLatency) { ASSERT_NE(stream_b_recv_a, nullptr); ASSERT_NE(stream_a_recv_b, nullptr); - LatencyStats a_to_b_stats; - LatencyStats b_to_a_stats; - LatencyStats round_trip_stats; std::atomic running{true}; std::atomic active_pulse_id{0}; std::atomic a_send_us{0}; @@ -637,15 +645,19 @@ TEST_F(LatencyMeasurementTest, FullDeplexAudioLatency) { std::atomic waiting_for_response{false}; std::atomic pre_pulse_silence_frames_remaining{200}; std::atomic timeouts{0}; + std::atomic a_to_b_count{0}; + std::atomic b_to_a_count{0}; + std::atomic round_trip_count{0}; constexpr int kTotalPulses = 100; constexpr int kPrePulseSilenceFrames = 50; // 500ms at 10ms/frame constexpr uint64_t kPulseTimeoutUs = 8000000; // 8 seconds constexpr int kBMaxResponseFrames = 50; // 500ms at 10ms/frame - constexpr double kMinValidOneWayMs = 100.0; // filter stale/impossible matches - constexpr double kMinValidBToAMs = 100.0; // filter stale/impossible matches + constexpr double kMinValidOneWayMs = + 10.0; // Filter impossible matches (< 10ms) + constexpr double kMinValidBToAMs = 10.0; // Filter impossible matches (< 10ms) - // B receives A pulses and sends response frames only when responding. + // B receives A pulses and sends response frames std::thread b_receiver_thread([&]() { AudioFrameEvent event; while (running.load() && stream_b_recv_a->read(event)) { @@ -673,9 +685,20 @@ TEST_F(LatencyMeasurementTest, FullDeplexAudioLatency) { b_detect_us.store(detect_us); b_responded_pulse_id.store(pulse_id); - a_to_b_stats.addMeasurement(a_to_b_ms); + + // End the A->B trace span + TRACE_EVENT_ASYNC_END1(kCategoryAudio, "A_to_B", + static_cast(pulse_id), "latency_ms", + a_to_b_ms); + a_to_b_count++; std::cout << " A->B latency: " << std::fixed << std::setprecision(2) << a_to_b_ms << " ms" << std::endl; + + // Begin B->A trace span + TRACE_EVENT_ASYNC_BEGIN1(kCategoryAudio, "B_to_A", + static_cast(pulse_id), "pulse", + pulse_id); + for (int i = 0; i < kBMaxResponseFrames; ++i) { std::vector pulse = generateHighEnergyFrame(kSamplesPerFrame); AudioFrame response_frame(std::move(pulse), kAudioSampleRate, @@ -693,7 +716,6 @@ TEST_F(LatencyMeasurementTest, FullDeplexAudioLatency) { << std::endl; break; } - // Prevent stale overlap into subsequent pulses. if (!waiting_for_response.load()) { break; } @@ -702,7 +724,7 @@ TEST_F(LatencyMeasurementTest, FullDeplexAudioLatency) { } }); - // A receives B responses and computes B->A and A->B->A. + // A receives B responses and computes B->A and A->B->A std::thread a_receiver_thread([&]() { AudioFrameEvent event; while (running.load() && stream_a_recv_b->read(event)) { @@ -724,8 +746,6 @@ TEST_F(LatencyMeasurementTest, FullDeplexAudioLatency) { uint64_t send_from_b_us = b_send_us.load(); int responded_pulse_id = b_responded_pulse_id.load(); - // Only accept a return pulse after B has actually started responding to - // this same pulse id. This filters stale overlap from previous responses. if (responded_pulse_id != pulse_id || send_from_b_us == 0 || receive_us < send_from_b_us) { continue; @@ -734,7 +754,10 @@ TEST_F(LatencyMeasurementTest, FullDeplexAudioLatency) { double b_to_a_ms = (receive_us - send_from_b_us) / 1000.0; if (b_to_a_ms >= kMinValidBToAMs && b_to_a_ms < 5000) { - b_to_a_stats.addMeasurement(b_to_a_ms); + TRACE_EVENT_ASYNC_END1(kCategoryAudio, "B_to_A", + static_cast(pulse_id), "latency_ms", + b_to_a_ms); + b_to_a_count++; std::cout << " B->A latency: " << std::fixed << std::setprecision(2) << b_to_a_ms << " ms" << std::endl; } @@ -742,7 +765,10 @@ TEST_F(LatencyMeasurementTest, FullDeplexAudioLatency) { if (send_from_a_us > 0) { double rtt_ms = (receive_us - send_from_a_us) / 1000.0; if (rtt_ms > 0 && rtt_ms < 10000) { - round_trip_stats.addMeasurement(rtt_ms); + TRACE_EVENT_ASYNC_END1(kCategoryAudio, "round_trip", + static_cast(pulse_id), "latency_ms", + rtt_ms); + round_trip_count++; std::cout << " A->B->A latency: " << std::fixed << std::setprecision(2) << rtt_ms << " ms" << std::endl; } @@ -754,7 +780,7 @@ TEST_F(LatencyMeasurementTest, FullDeplexAudioLatency) { } }); - // A sends ping pulses and waits for B's response. + // A sends ping pulses std::thread a_sender_thread([&]() { auto next_frame_time = std::chrono::steady_clock::now(); const auto frame_duration = @@ -784,7 +810,6 @@ TEST_F(LatencyMeasurementTest, FullDeplexAudioLatency) { std::vector frame_data; if (waiting_for_response.load()) { - // Keep transmitting pulse frames until B responds or timeout. frame_data = generateHighEnergyFrame(kSamplesPerFrame); } else if (!waiting_for_response.load() && pulses_sent < kTotalPulses) { int remaining_silence = pre_pulse_silence_frames_remaining.load(); @@ -806,6 +831,14 @@ TEST_F(LatencyMeasurementTest, FullDeplexAudioLatency) { a_send_us.store(pulse_start_us); waiting_for_response.store(true); + // Begin trace spans for A->B and round-trip + TRACE_EVENT_ASYNC_BEGIN1(kCategoryAudio, "A_to_B", + static_cast(pulse_id), "pulse", + pulse_id); + TRACE_EVENT_ASYNC_BEGIN1(kCategoryAudio, "round_trip", + static_cast(pulse_id), "pulse", + pulse_id); + frame_data = generateHighEnergyFrame(kSamplesPerFrame); std::cout << "Sent ping pulse " << pulse_id << "/" << kTotalPulses @@ -834,21 +867,21 @@ TEST_F(LatencyMeasurementTest, FullDeplexAudioLatency) { a_receiver_thread.join(); b_receiver_thread.join(); - round_trip_stats.printStats("Full Duplex Latency (A->B->A) Statistics"); - a_to_b_stats.printStats("One-way Latency (A->B) Statistics"); - b_to_a_stats.printStats("One-way Latency (B->A) Statistics"); if (timeouts > 0) { std::cout << "Response timeouts: " << timeouts << std::endl; } - room_a->localParticipant()->unpublishTrack(track_a->sid()); - room_b->localParticipant()->unpublishTrack(track_b->sid()); + room_a->localParticipant()->unpublishTrack(track_a->publication()->sid()); + room_b->localParticipant()->unpublishTrack(track_b->publication()->sid()); + + // Tracing is automatically handled by LiveKitTestBase + // Stats for A_to_B, B_to_A, round_trip will be printed in TearDown() - EXPECT_GT(round_trip_stats.count(), 0) + EXPECT_GT(round_trip_count.load(), 0) << "At least one round-trip latency measurement should be recorded"; - EXPECT_GT(a_to_b_stats.count(), 0) + EXPECT_GT(a_to_b_count.load(), 0) << "At least one A->B latency measurement should be recorded"; - EXPECT_GT(b_to_a_stats.count(), 0) + EXPECT_GT(b_to_a_count.load(), 0) << "At least one B->A latency measurement should be recorded"; } diff --git a/src/tests/stress/test_rpc_stress.cpp b/src/tests/stress/test_rpc_stress.cpp index 4e25a7b8..8b962be1 100644 --- a/src/tests/stress/test_rpc_stress.cpp +++ b/src/tests/stress/test_rpc_stress.cpp @@ -14,11 +14,14 @@ * limitations under the License. */ +#include "../benchmark/benchmark_utils.h" #include "../common/test_common.h" #include #include #include +using namespace livekit::test::benchmark; + namespace livekit { namespace test { @@ -200,7 +203,11 @@ TEST_F(RpcStressTest, MaxPayloadStress) { std::cout << "Both rooms connected. Starting stress test..." << std::endl; - StressTestStats stats; + // Start benchmark session with tracing + BenchmarkSession session("MaxPayloadStress", {kCategoryRpc}); + session.start("rpc_max_payload_stress_trace.json"); + + TracedStressStats stats("Max Payload RPC", kCategoryRpc); std::atomic running{true}; auto start_time = std::chrono::steady_clock::now(); @@ -320,7 +327,10 @@ TEST_F(RpcStressTest, MaxPayloadStress) { } progress_thread.join(); - stats.printStats("RPC Max Payload Stress Test"); + session.stop(); + + // Print trace-based statistics + stats.printStats(); // Verify results EXPECT_GT(stats.successfulCalls(), 0) << "No successful calls"; @@ -394,7 +404,11 @@ TEST_F(RpcStressTest, SmallPayloadStress) { std::cout << "Both rooms connected. Starting stress test..." << std::endl; - StressTestStats stats; + // Start benchmark session with tracing + BenchmarkSession session("SmallPayloadStress", {kCategoryRpc}); + session.start("rpc_small_payload_stress_trace.json"); + + TracedStressStats stats("Small Payload RPC", kCategoryRpc); std::atomic running{true}; auto start_time = std::chrono::steady_clock::now(); @@ -506,7 +520,10 @@ TEST_F(RpcStressTest, SmallPayloadStress) { } progress_thread.join(); - stats.printStats("RPC Small Payload Stress Test"); + session.stop(); + + // Print trace-based statistics + stats.printStats(); // Verify results EXPECT_GT(stats.successfulCalls(), 0) << "No successful calls"; @@ -573,8 +590,12 @@ TEST_F(RpcStressTest, BidirectionalRpcStress) { return data.payload; }); - StressTestStats stats_a_to_b; - StressTestStats stats_b_to_a; + // Start benchmark session with tracing + BenchmarkSession session("BidirectionalRpcStress", {kCategoryRpc}); + session.start("rpc_bidirectional_stress_trace.json"); + + TracedStressStats stats_a_to_b("A->B RPC", kCategoryRpc); + TracedStressStats stats_b_to_a("B->A RPC", kCategoryRpc); std::atomic running{true}; auto start_time = std::chrono::steady_clock::now(); @@ -715,11 +736,20 @@ TEST_F(RpcStressTest, BidirectionalRpcStress) { thread_b_to_a.join(); progress_thread.join(); + session.stop(); + + // Print trace-based statistics std::cout << "\n=== A -> B Statistics ===" << std::endl; - stats_a_to_b.printStats("A -> B"); + stats_a_to_b.printStats(); std::cout << "\n=== B -> A Statistics ===" << std::endl; - stats_b_to_a.printStats("B -> A"); + stats_b_to_a.printStats(); + + // Print comparison table + std::vector all_stats = {stats_a_to_b.getLatencyStats(), + stats_b_to_a.getLatencyStats()}; + std::cout << "\n=== Comparison Table ===" << std::endl; + printComparisonTable(all_stats); EXPECT_GT(stats_a_to_b.successfulCalls(), 0); EXPECT_GT(stats_b_to_a.successfulCalls(), 0); @@ -769,7 +799,11 @@ TEST_F(RpcStressTest, HighThroughputBurst) { waitForParticipant(caller_room.get(), receiver_identity, 10s); ASSERT_TRUE(receiver_visible) << "Receiver not visible to caller"; - StressTestStats stats; + // Start benchmark session with tracing + BenchmarkSession session("HighThroughputBurst", {kCategoryRpc}); + session.start("rpc_high_throughput_burst_trace.json"); + + TracedStressStats stats("High Throughput Burst", kCategoryRpc); std::atomic running{true}; auto start_time = std::chrono::steady_clock::now(); @@ -866,7 +900,10 @@ TEST_F(RpcStressTest, HighThroughputBurst) { } progress_thread.join(); - stats.printStats("High Throughput Burst Test"); + session.stop(); + + // Print trace-based statistics + stats.printStats(); auto total_time = std::chrono::duration_cast( std::chrono::steady_clock::now() - start_time) diff --git a/src/tests/unit/test_tracing.cpp b/src/tests/unit/test_tracing.cpp new file mode 100644 index 00000000..979d39e4 --- /dev/null +++ b/src/tests/unit/test_tracing.cpp @@ -0,0 +1,551 @@ +/* + * Copyright 2024 LiveKit + * + * 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. + */ + +#include + +#include "benchmark_utils.h" +#include "event_tracer.h" +#include + +#include +#include +#include +#include +#include +#include + +namespace livekit { +namespace test { +namespace { + +// Helper to generate unique temp file paths +std::string GetTempTracePath(const std::string &test_name) { + auto now = std::chrono::steady_clock::now(); + auto ns = std::chrono::duration_cast( + now.time_since_epoch()) + .count(); + return "/tmp/livekit_test_trace_" + test_name + "_" + std::to_string(ns) + + ".json"; +} + +// Helper to read file contents +std::string ReadFileContents(const std::string &path) { + std::ifstream file(path); + if (!file.is_open()) { + return ""; + } + std::stringstream buffer; + buffer << file.rdbuf(); + return buffer.str(); +} + +// Helper to cleanup trace files +void CleanupTraceFile(const std::string &path) { std::remove(path.c_str()); } + +// ============================================================================= +// Basic Lifecycle Tests +// ============================================================================= + +TEST(TracingTest, StartAndStopTracing) { + std::string trace_path = GetTempTracePath("start_stop"); + + // Initially tracing should be disabled + EXPECT_FALSE(isTracingEnabled()); + + // Start tracing + bool started = startTracing(trace_path); + EXPECT_TRUE(started); + EXPECT_TRUE(isTracingEnabled()); + + // Stop tracing + stopTracing(); + EXPECT_FALSE(isTracingEnabled()); + + // Verify file was created + std::string contents = ReadFileContents(trace_path); + EXPECT_FALSE(contents.empty()); + + // Verify file has valid JSON structure + EXPECT_NE(contents.find("{\"traceEvents\":["), std::string::npos); + EXPECT_NE(contents.find("],\"displayTimeUnit\":\"ms\"}"), std::string::npos); + + CleanupTraceFile(trace_path); +} + +TEST(TracingTest, DoubleStartReturnsFalse) { + std::string trace_path = GetTempTracePath("double_start"); + + bool first_start = startTracing(trace_path); + EXPECT_TRUE(first_start); + + // Second start should fail + bool second_start = startTracing(trace_path); + EXPECT_FALSE(second_start); + + stopTracing(); + CleanupTraceFile(trace_path); +} + +TEST(TracingTest, StopWithoutStartIsSafe) { + // Should not crash + stopTracing(); + EXPECT_FALSE(isTracingEnabled()); +} + +TEST(TracingTest, InvalidPathReturnsFalse) { + // Try to start with an invalid path + bool started = startTracing("/nonexistent/directory/trace.json"); + EXPECT_FALSE(started); + EXPECT_FALSE(isTracingEnabled()); +} + +// ============================================================================= +// Event Writing Tests +// ============================================================================= + +TEST(TracingTest, EventsAreWrittenToFile) { + std::string trace_path = GetTempTracePath("events_written"); + + startTracing(trace_path); + + // Add some trace events using the internal API + const unsigned char *category = + trace::EventTracer::GetCategoryEnabled("test.category"); + EXPECT_TRUE(*category != 0); // Category should be enabled + + // Add a begin/end event pair + trace::EventTracer::AddTraceEvent('B', // phase: begin + category, // category_enabled + "test_event", // name + 0, // id + 0, // num_args + nullptr, // arg_names + nullptr, // arg_types + nullptr, // arg_values + 0 // flags + ); + + // Small delay to ensure timestamp difference + std::this_thread::sleep_for(std::chrono::milliseconds(1)); + + trace::EventTracer::AddTraceEvent('E', // phase: end + category, // category_enabled + "test_event", // name + 0, // id + 0, // num_args + nullptr, // arg_names + nullptr, // arg_types + nullptr, // arg_values + 0 // flags + ); + + stopTracing(); + + // Verify events are in the file + std::string contents = ReadFileContents(trace_path); + EXPECT_NE(contents.find("\"name\":\"test_event\""), std::string::npos); + EXPECT_NE(contents.find("\"ph\":\"B\""), std::string::npos); + EXPECT_NE(contents.find("\"ph\":\"E\""), std::string::npos); + + CleanupTraceFile(trace_path); +} + +TEST(TracingTest, AsyncEventsAreWrittenCorrectly) { + std::string trace_path = GetTempTracePath("async_events"); + + startTracing(trace_path); + + const unsigned char *category = + trace::EventTracer::GetCategoryEnabled("test.async"); + + // Add async start event + trace::EventTracer::AddTraceEvent('S', // phase: async start + category, "async_operation", + 12345, // id for pairing + 0, nullptr, nullptr, nullptr, 0); + + std::this_thread::sleep_for(std::chrono::milliseconds(5)); + + // Add async finish event + trace::EventTracer::AddTraceEvent('F', // phase: async finish + category, "async_operation", + 12345, // same id + 0, nullptr, nullptr, nullptr, 0); + + stopTracing(); + + // Verify events + std::string contents = ReadFileContents(trace_path); + EXPECT_NE(contents.find("\"name\":\"async_operation\""), std::string::npos); + EXPECT_NE(contents.find("\"ph\":\"S\""), std::string::npos); + EXPECT_NE(contents.find("\"ph\":\"F\""), std::string::npos); + EXPECT_NE(contents.find("\"id\":\"0x3039\""), + std::string::npos); // 12345 in hex + + CleanupTraceFile(trace_path); +} + +TEST(TracingTest, EventsWithArguments) { + std::string trace_path = GetTempTracePath("events_with_args"); + + startTracing(trace_path); + + const unsigned char *category = + trace::EventTracer::GetCategoryEnabled("test.args"); + + // Add event with integer argument + const char *arg_names[] = {"count"}; + unsigned char arg_types[] = {2}; // TRACE_VALUE_TYPE_UINT = 2 + unsigned long long arg_values[] = {42}; + + trace::EventTracer::AddTraceEvent('I', // instant event + category, "event_with_args", 0, + 1, // num_args + arg_names, arg_types, arg_values, 0); + + stopTracing(); + + std::string contents = ReadFileContents(trace_path); + EXPECT_NE(contents.find("\"name\":\"event_with_args\""), std::string::npos); + EXPECT_NE(contents.find("\"count\":42"), std::string::npos); + + CleanupTraceFile(trace_path); +} + +// ============================================================================= +// Category Filtering Tests +// ============================================================================= + +TEST(TracingTest, CategoryFilteringEnablesSpecificCategory) { + std::string trace_path = GetTempTracePath("category_filter"); + + // Start with specific category enabled + startTracing(trace_path, {"enabled.category"}); + + const unsigned char *enabled_cat = + trace::EventTracer::GetCategoryEnabled("enabled.category"); + const unsigned char *disabled_cat = + trace::EventTracer::GetCategoryEnabled("disabled.category"); + + EXPECT_TRUE(*enabled_cat != 0); + EXPECT_TRUE(*disabled_cat == 0); + + stopTracing(); + CleanupTraceFile(trace_path); +} + +TEST(TracingTest, CategoryWildcardMatching) { + std::string trace_path = GetTempTracePath("wildcard_filter"); + + // Start with wildcard category + startTracing(trace_path, {"livekit.*"}); + + const unsigned char *match1 = + trace::EventTracer::GetCategoryEnabled("livekit.connect"); + const unsigned char *match2 = + trace::EventTracer::GetCategoryEnabled("livekit.rpc"); + const unsigned char *no_match = + trace::EventTracer::GetCategoryEnabled("other.category"); + + EXPECT_TRUE(*match1 != 0); + EXPECT_TRUE(*match2 != 0); + EXPECT_TRUE(*no_match == 0); + + stopTracing(); + CleanupTraceFile(trace_path); +} + +TEST(TracingTest, EmptyCategoriesEnablesAll) { + std::string trace_path = GetTempTracePath("all_categories"); + + // Start with empty categories (all enabled) + startTracing(trace_path, {}); + + const unsigned char *cat1 = + trace::EventTracer::GetCategoryEnabled("any.category"); + const unsigned char *cat2 = + trace::EventTracer::GetCategoryEnabled("another.category"); + + EXPECT_TRUE(*cat1 != 0); + EXPECT_TRUE(*cat2 != 0); + + stopTracing(); + CleanupTraceFile(trace_path); +} + +// ============================================================================= +// Trace File Analysis Tests (using benchmark_utils) +// ============================================================================= + +TEST(TracingTest, TraceFileCanBeParsed) { + std::string trace_path = GetTempTracePath("parse_test"); + + startTracing(trace_path); + + const unsigned char *category = + trace::EventTracer::GetCategoryEnabled("test"); + + // Add multiple events + for (int i = 0; i < 5; ++i) { + trace::EventTracer::AddTraceEvent('B', category, "parse_event", 0, 0, + nullptr, nullptr, nullptr, 0); + std::this_thread::sleep_for(std::chrono::milliseconds(1)); + trace::EventTracer::AddTraceEvent('E', category, "parse_event", 0, 0, + nullptr, nullptr, nullptr, 0); + } + + stopTracing(); + + // Use benchmark_utils to parse the trace file + auto events = benchmark::loadTraceFile(trace_path); + EXPECT_FALSE(events.empty()); + + // Count begin/end events for our test event + int begin_count = 0; + int end_count = 0; + for (const auto &event : events) { + if (event.name == "parse_event") { + if (event.phase == 'B') + begin_count++; + if (event.phase == 'E') + end_count++; + } + } + + EXPECT_EQ(begin_count, 5); + EXPECT_EQ(end_count, 5); + + CleanupTraceFile(trace_path); +} + +TEST(TracingTest, DurationCalculationWorks) { + std::string trace_path = GetTempTracePath("duration_test"); + + startTracing(trace_path); + + const unsigned char *category = + trace::EventTracer::GetCategoryEnabled("test"); + + // Add events with known delay + for (int i = 0; i < 3; ++i) { + trace::EventTracer::AddTraceEvent('B', category, "timed_event", 0, 0, + nullptr, nullptr, nullptr, 0); + std::this_thread::sleep_for(std::chrono::milliseconds(10)); + trace::EventTracer::AddTraceEvent('E', category, "timed_event", 0, 0, + nullptr, nullptr, nullptr, 0); + } + + stopTracing(); + + // Calculate durations + auto events = benchmark::loadTraceFile(trace_path); + auto durations = benchmark::calculateDurations(events, "timed_event"); + + EXPECT_EQ(durations.size(), 3); + + // Each duration should be at least 10ms (we slept for 10ms) + for (double duration : durations) { + EXPECT_GE(duration, 9.0); // Allow small timing variance + } + + CleanupTraceFile(trace_path); +} + +TEST(TracingTest, AsyncDurationCalculationWorks) { + std::string trace_path = GetTempTracePath("async_duration_test"); + + startTracing(trace_path); + + const unsigned char *category = + trace::EventTracer::GetCategoryEnabled("test"); + + // Add async events with known IDs + trace::EventTracer::AddTraceEvent('S', category, "async_op", 100, 0, nullptr, + nullptr, nullptr, 0); + trace::EventTracer::AddTraceEvent('S', category, "async_op", 200, 0, nullptr, + nullptr, nullptr, 0); + + std::this_thread::sleep_for(std::chrono::milliseconds(15)); + + trace::EventTracer::AddTraceEvent('F', category, "async_op", 100, 0, nullptr, + nullptr, nullptr, 0); + + std::this_thread::sleep_for(std::chrono::milliseconds(10)); + + trace::EventTracer::AddTraceEvent('F', category, "async_op", 200, 0, nullptr, + nullptr, nullptr, 0); + + stopTracing(); + + auto events = benchmark::loadTraceFile(trace_path); + auto durations = benchmark::calculateDurations(events, "async_op"); + + EXPECT_EQ(durations.size(), 2); + + CleanupTraceFile(trace_path); +} + +TEST(TracingTest, StatisticsCalculation) { + std::string trace_path = GetTempTracePath("stats_test"); + + startTracing(trace_path); + + const unsigned char *category = + trace::EventTracer::GetCategoryEnabled("test"); + + // Add 10 events + for (int i = 0; i < 10; ++i) { + trace::EventTracer::AddTraceEvent('B', category, "stats_event", 0, 0, + nullptr, nullptr, nullptr, 0); + std::this_thread::sleep_for(std::chrono::milliseconds(5)); + trace::EventTracer::AddTraceEvent('E', category, "stats_event", 0, 0, + nullptr, nullptr, nullptr, 0); + } + + stopTracing(); + + // Calculate statistics + auto stats = benchmark::analyzeTraceFile(trace_path, "stats_event"); + + EXPECT_EQ(stats.count, 10); + EXPECT_GT(stats.min_ms, 0.0); + EXPECT_GE(stats.max_ms, stats.min_ms); + EXPECT_GE(stats.avg_ms, stats.min_ms); + EXPECT_LE(stats.avg_ms, stats.max_ms); + + CleanupTraceFile(trace_path); +} + +// ============================================================================= +// Multiple Sessions Test +// ============================================================================= + +TEST(TracingTest, MultipleTracingSessions) { + std::string trace_path1 = GetTempTracePath("session1"); + std::string trace_path2 = GetTempTracePath("session2"); + + // First session + startTracing(trace_path1); + const unsigned char *cat = trace::EventTracer::GetCategoryEnabled("test"); + trace::EventTracer::AddTraceEvent('B', cat, "session1_event", 0, 0, nullptr, + nullptr, nullptr, 0); + trace::EventTracer::AddTraceEvent('E', cat, "session1_event", 0, 0, nullptr, + nullptr, nullptr, 0); + stopTracing(); + + // Second session + startTracing(trace_path2); + cat = trace::EventTracer::GetCategoryEnabled("test"); + trace::EventTracer::AddTraceEvent('B', cat, "session2_event", 0, 0, nullptr, + nullptr, nullptr, 0); + trace::EventTracer::AddTraceEvent('E', cat, "session2_event", 0, 0, nullptr, + nullptr, nullptr, 0); + stopTracing(); + + // Verify first file contains session1 event only + std::string contents1 = ReadFileContents(trace_path1); + EXPECT_NE(contents1.find("session1_event"), std::string::npos); + EXPECT_EQ(contents1.find("session2_event"), std::string::npos); + + // Verify second file contains session2 event only + std::string contents2 = ReadFileContents(trace_path2); + EXPECT_NE(contents2.find("session2_event"), std::string::npos); + EXPECT_EQ(contents2.find("session1_event"), std::string::npos); + + CleanupTraceFile(trace_path1); + CleanupTraceFile(trace_path2); +} + +// ============================================================================= +// Thread Safety Tests +// ============================================================================= + +TEST(TracingTest, ConcurrentEventWriting) { + std::string trace_path = GetTempTracePath("concurrent_test"); + + startTracing(trace_path); + + const int num_threads = 4; + const int events_per_thread = 100; + std::vector threads; + + for (int t = 0; t < num_threads; ++t) { + threads.emplace_back([t, events_per_thread]() { + const unsigned char *cat = + trace::EventTracer::GetCategoryEnabled("test.concurrent"); + std::string event_name = "thread_" + std::to_string(t) + "_event"; + + for (int i = 0; i < events_per_thread; ++i) { + trace::EventTracer::AddTraceEvent('B', cat, event_name.c_str(), 0, 0, + nullptr, nullptr, nullptr, 0); + trace::EventTracer::AddTraceEvent('E', cat, event_name.c_str(), 0, 0, + nullptr, nullptr, nullptr, 0); + } + }); + } + + for (auto &t : threads) { + t.join(); + } + + stopTracing(); + + // Parse and count events + auto events = benchmark::loadTraceFile(trace_path); + + // Each thread should have written events_per_thread * 2 events (begin + end) + int total_begin = 0; + int total_end = 0; + for (const auto &event : events) { + if (event.phase == 'B') + total_begin++; + if (event.phase == 'E') + total_end++; + } + + // Should have all events written + EXPECT_EQ(total_begin, num_threads * events_per_thread); + EXPECT_EQ(total_end, num_threads * events_per_thread); + + CleanupTraceFile(trace_path); +} + +// ============================================================================= +// Events Not Written When Tracing Disabled +// ============================================================================= + +TEST(TracingTest, EventsIgnoredWhenTracingDisabled) { + // Ensure tracing is stopped + stopTracing(); + EXPECT_FALSE(isTracingEnabled()); + + // Get category - should return disabled + const unsigned char *cat = trace::EventTracer::GetCategoryEnabled("test"); + EXPECT_EQ(*cat, 0); + + // Adding events should be safe (no crash) + trace::EventTracer::AddTraceEvent('B', cat, "ignored_event", 0, 0, nullptr, + nullptr, nullptr, 0); + trace::EventTracer::AddTraceEvent('E', cat, "ignored_event", 0, 0, nullptr, + nullptr, nullptr, 0); + + // Still disabled + EXPECT_FALSE(isTracingEnabled()); +} + +} // namespace +} // namespace test +} // namespace livekit diff --git a/src/trace/event_tracer.cpp b/src/trace/event_tracer.cpp new file mode 100644 index 00000000..6f55596c --- /dev/null +++ b/src/trace/event_tracer.cpp @@ -0,0 +1,446 @@ +/* + * Copyright 2024 LiveKit + * + * 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. + */ + +#include "event_tracer.h" +#include "event_tracer_internal.h" + +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include + +#ifdef _WIN32 +#include +#include +#else +#include +#include +#endif + +namespace livekit { +namespace trace { + +namespace { + +// Get current process ID +uint32_t GetCurrentProcessId() { +#ifdef _WIN32 + return static_cast(::GetCurrentProcessId()); +#else + return static_cast(getpid()); +#endif +} + +// Get current thread ID +uint32_t GetCurrentThreadId() { +#ifdef _WIN32 + return static_cast(::GetCurrentThreadId()); +#elif defined(__APPLE__) + uint64_t tid; + pthread_threadid_np(nullptr, &tid); + return static_cast(tid); +#else + return static_cast(pthread_self()); +#endif +} + +// Get timestamp in microseconds +uint64_t GetTimestampMicros() { + auto now = std::chrono::steady_clock::now(); + auto duration = now.time_since_epoch(); + return std::chrono::duration_cast(duration) + .count(); +} + +// Internal trace event structure +struct TraceEventData { + char phase; + std::string category; + std::string name; + uint64_t id; + uint64_t timestamp_us; + uint32_t pid; + uint32_t tid; + unsigned char flags; + int num_args; + std::string arg_names[2]; + unsigned char arg_types[2]; + uint64_t arg_values[2]; + std::string arg_string_values[2]; +}; + +// Escape a string for JSON +std::string JsonEscape(const std::string &s) { + std::ostringstream oss; + for (char c : s) { + switch (c) { + case '"': + oss << "\\\""; + break; + case '\\': + oss << "\\\\"; + break; + case '\b': + oss << "\\b"; + break; + case '\f': + oss << "\\f"; + break; + case '\n': + oss << "\\n"; + break; + case '\r': + oss << "\\r"; + break; + case '\t': + oss << "\\t"; + break; + default: + if ('\x00' <= c && c <= '\x1f') { + oss << "\\u" << std::hex << std::setw(4) << std::setfill('0') + << static_cast(c); + } else { + oss << c; + } + } + } + return oss.str(); +} + +// Convert argument value to JSON based on type +std::string ArgValueToJson(unsigned char type, uint64_t value, + const std::string &string_value) { + constexpr unsigned char TRACE_VALUE_TYPE_BOOL = 1; + constexpr unsigned char TRACE_VALUE_TYPE_UINT = 2; + constexpr unsigned char TRACE_VALUE_TYPE_INT = 3; + constexpr unsigned char TRACE_VALUE_TYPE_DOUBLE = 4; + constexpr unsigned char TRACE_VALUE_TYPE_POINTER = 5; + constexpr unsigned char TRACE_VALUE_TYPE_STRING = 6; + constexpr unsigned char TRACE_VALUE_TYPE_COPY_STRING = 7; + + std::ostringstream oss; + switch (type) { + case TRACE_VALUE_TYPE_BOOL: + oss << (value ? "true" : "false"); + break; + case TRACE_VALUE_TYPE_UINT: + oss << value; + break; + case TRACE_VALUE_TYPE_INT: + oss << static_cast(value); + break; + case TRACE_VALUE_TYPE_DOUBLE: { + union { + uint64_t u; + double d; + } converter; + converter.u = value; + oss << std::setprecision(17) << converter.d; + break; + } + case TRACE_VALUE_TYPE_POINTER: + oss << "\"0x" << std::hex << value << "\""; + break; + case TRACE_VALUE_TYPE_STRING: + case TRACE_VALUE_TYPE_COPY_STRING: + oss << "\"" << JsonEscape(string_value) << "\""; + break; + default: + oss << value; + break; + } + return oss.str(); +} + +// Format a single event as JSON +std::string FormatEventJson(const TraceEventData &event, uint64_t start_time) { + std::ostringstream oss; + oss << "{"; + oss << "\"ph\":\"" << event.phase << "\","; + oss << "\"cat\":\"" << JsonEscape(event.category) << "\","; + oss << "\"name\":\"" << JsonEscape(event.name) << "\","; + oss << "\"ts\":" << (event.timestamp_us - start_time) << ","; + oss << "\"pid\":" << event.pid << ","; + oss << "\"tid\":" << event.tid; + + if (event.id != 0) { + oss << ",\"id\":\"0x" << std::hex << event.id << std::dec << "\""; + } + + if (event.num_args > 0) { + oss << ",\"args\":{"; + for (int i = 0; i < event.num_args && i < 2; ++i) { + if (i > 0) + oss << ","; + oss << "\"" << JsonEscape(event.arg_names[i]) << "\":"; + oss << ArgValueToJson(event.arg_types[i], event.arg_values[i], + event.arg_string_values[i]); + } + oss << "}"; + } + + oss << "}"; + return oss.str(); +} + +// Global state +std::mutex g_mutex; +std::condition_variable g_cv; +std::queue g_event_queue; +std::unordered_set g_enabled_categories; +std::atomic g_tracing_enabled{false}; +std::atomic g_shutdown_requested{false}; +std::thread g_writer_thread; +std::ofstream g_trace_file; +uint64_t g_start_time = 0; +bool g_first_event = true; + +// Custom tracer callbacks +GetCategoryEnabledPtr g_custom_get_category_enabled = nullptr; +AddTraceEventPtr g_custom_add_trace_event = nullptr; + +// Static enabled/disabled bytes for category state +static unsigned char g_enabled_byte = 1; +static unsigned char g_disabled_byte = 0; + +// Background writer thread function +void WriterThreadFunc() { + std::vector batch; + batch.reserve(100); + + while (true) { + // Wait for events or shutdown + { + std::unique_lock lock(g_mutex); + g_cv.wait(lock, [] { + return !g_event_queue.empty() || g_shutdown_requested.load(); + }); + + // Drain the queue into a local batch + while (!g_event_queue.empty()) { + batch.push_back(std::move(g_event_queue.front())); + g_event_queue.pop(); + } + } + + // Write batch to file (outside the lock) + for (const auto &event : batch) { + if (g_trace_file.is_open()) { + if (!g_first_event) { + g_trace_file << ","; + } + g_first_event = false; + g_trace_file << FormatEventJson(event, g_start_time); + } + } + batch.clear(); + + // Exit if shutdown requested and queue is empty + if (g_shutdown_requested.load()) { + std::lock_guard lock(g_mutex); + if (g_event_queue.empty()) { + break; + } + } + } +} + +} // namespace + +void SetupEventTracer(GetCategoryEnabledPtr get_category_enabled_ptr, + AddTraceEventPtr add_trace_event_ptr) { + std::lock_guard lock(g_mutex); + g_custom_get_category_enabled = get_category_enabled_ptr; + g_custom_add_trace_event = add_trace_event_ptr; +} + +const unsigned char *EventTracer::GetCategoryEnabled(const char *name) { + // If custom tracer is set, use it + if (g_custom_get_category_enabled) { + return g_custom_get_category_enabled(name); + } + + // Fast path: tracing disabled + if (!g_tracing_enabled.load(std::memory_order_relaxed)) { + return &g_disabled_byte; + } + + // Check if category is enabled + std::lock_guard lock(g_mutex); + + // Empty enabled set means all categories are enabled + if (g_enabled_categories.empty()) { + return &g_enabled_byte; + } + + // Check if this specific category is enabled + std::string category_name(name); + if (g_enabled_categories.count(category_name) > 0) { + return &g_enabled_byte; + } + + // Check for wildcard matches (e.g., "livekit.*" matches "livekit.connect") + for (const auto &pattern : g_enabled_categories) { + if (pattern.back() == '*') { + std::string prefix = pattern.substr(0, pattern.size() - 1); + if (category_name.compare(0, prefix.size(), prefix) == 0) { + return &g_enabled_byte; + } + } + } + + return &g_disabled_byte; +} + +void EventTracer::AddTraceEvent(char phase, + const unsigned char *category_enabled, + const char *name, unsigned long long id, + int num_args, const char **arg_names, + const unsigned char *arg_types, + const unsigned long long *arg_values, + unsigned char flags) { + // If custom tracer is set, use it + if (g_custom_add_trace_event) { + g_custom_add_trace_event(phase, category_enabled, name, id, num_args, + arg_names, arg_types, arg_values, flags); + return; + } + + // Skip if tracing disabled + if (!g_tracing_enabled.load(std::memory_order_relaxed)) { + return; + } + + // Build the event + TraceEventData event; + event.phase = phase; + event.name = name ? name : ""; + event.id = static_cast(id); + event.timestamp_us = GetTimestampMicros(); + event.pid = GetCurrentProcessId(); + event.tid = GetCurrentThreadId(); + event.flags = flags; + event.num_args = num_args; + + // Copy arguments + for (int i = 0; i < num_args && i < 2; ++i) { + if (arg_names && arg_names[i]) { + event.arg_names[i] = arg_names[i]; + } + if (arg_types) { + event.arg_types[i] = arg_types[i]; + } + if (arg_values) { + event.arg_values[i] = arg_values[i]; + + // Handle string arguments + if (arg_types && (arg_types[i] == 6 || arg_types[i] == 7)) { + const char *str_val = reinterpret_cast(arg_values[i]); + if (str_val) { + event.arg_string_values[i] = str_val; + } + } + } + } + + // Queue the event for the writer thread + { + std::lock_guard lock(g_mutex); + g_event_queue.push(std::move(event)); + } + g_cv.notify_one(); +} + +namespace internal { + +bool StartTracing(const std::string &file_path, + const std::vector &categories) { + std::lock_guard lock(g_mutex); + + // Don't start if already running + if (g_tracing_enabled.load()) { + return false; + } + + // Open the trace file + g_trace_file.open(file_path, std::ios::out | std::ios::trunc); + if (!g_trace_file.is_open()) { + return false; + } + + // Write JSON header + g_trace_file << "{\"traceEvents\":["; + g_first_event = true; + + // Set start time + g_start_time = GetTimestampMicros(); + + // Set enabled categories + g_enabled_categories.clear(); + for (const auto &cat : categories) { + g_enabled_categories.insert(cat); + } + + // Reset shutdown flag and start writer thread + g_shutdown_requested.store(false); + g_writer_thread = std::thread(WriterThreadFunc); + + // Enable tracing (must be last to ensure everything is ready) + g_tracing_enabled.store(true, std::memory_order_release); + + return true; +} + +void StopTracing() { + // Disable tracing first to stop new events + g_tracing_enabled.store(false, std::memory_order_release); + + // Signal writer thread to shut down + g_shutdown_requested.store(true); + g_cv.notify_one(); + + // Wait for writer thread to finish + if (g_writer_thread.joinable()) { + g_writer_thread.join(); + } + + // Close the file with JSON footer + std::lock_guard lock(g_mutex); + if (g_trace_file.is_open()) { + g_trace_file << "],\"displayTimeUnit\":\"ms\"}"; + g_trace_file.close(); + } + + // Clear state + g_enabled_categories.clear(); +} + +bool IsTracingEnabled() { + return g_tracing_enabled.load(std::memory_order_acquire); +} + +} // namespace internal + +} // namespace trace +} // namespace livekit diff --git a/src/trace/event_tracer.h b/src/trace/event_tracer.h new file mode 100644 index 00000000..c4225127 --- /dev/null +++ b/src/trace/event_tracer.h @@ -0,0 +1,92 @@ +/* + * Copyright 2024 LiveKit + * + * 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. + * + * Based on WebRTC's event_tracer.h: + * Copyright (c) 2012 The WebRTC project authors. All Rights Reserved. + * Use of this source code is governed by a BSD-style license. + */ + +// This file defines the interface for event tracing in LiveKit SDK. +// +// Event log handlers are set through SetupEventTracer(). User of this API will +// provide two function pointers to handle event tracing calls. +// +// * GetCategoryEnabledPtr +// Event tracing system calls this function to determine if a particular +// event category is enabled. +// +// * AddTraceEventPtr +// Adds a tracing event. It is the user's responsibility to log the data +// provided. +// +// Parameters for the above two functions are described in trace_event.h. + +#ifndef LIVEKIT_TRACE_EVENT_TRACER_H_ +#define LIVEKIT_TRACE_EVENT_TRACER_H_ + +// Platform-specific DLL export macro +#if defined(_WIN32) +#if defined(LIVEKIT_BUILDING_SDK) +#define LIVEKIT_EXPORT __declspec(dllexport) +#else +#define LIVEKIT_EXPORT __declspec(dllimport) +#endif +#else +#define LIVEKIT_EXPORT __attribute__((visibility("default"))) +#endif + +namespace livekit { +namespace trace { + +typedef const unsigned char *(*GetCategoryEnabledPtr)(const char *name); +typedef void (*AddTraceEventPtr)(char phase, + const unsigned char *category_enabled, + const char *name, unsigned long long id, + int num_args, const char **arg_names, + const unsigned char *arg_types, + const unsigned long long *arg_values, + unsigned char flags); + +// User of LiveKit SDK can call this method to setup custom event tracing. +// +// This method must be called before any tracing begins. Functions +// provided should be thread-safe. +LIVEKIT_EXPORT void +SetupEventTracer(GetCategoryEnabledPtr get_category_enabled_ptr, + AddTraceEventPtr add_trace_event_ptr); + +// This class defines interface for the event tracing system to call +// internally. Do not call these methods directly. +class EventTracer { +public: + static const unsigned char *GetCategoryEnabled(const char *name); + + static void AddTraceEvent(char phase, const unsigned char *category_enabled, + const char *name, unsigned long long id, + int num_args, const char **arg_names, + const unsigned char *arg_types, + const unsigned long long *arg_values, + unsigned char flags); +}; + +} // namespace trace +} // namespace livekit + +// Compatibility aliases for trace_event.h macros (which use webrtc:: namespace) +namespace webrtc { +using namespace livekit::trace; +} // namespace webrtc + +#endif // LIVEKIT_TRACE_EVENT_TRACER_H_ diff --git a/src/trace/event_tracer_internal.h b/src/trace/event_tracer_internal.h new file mode 100644 index 00000000..4d2ad119 --- /dev/null +++ b/src/trace/event_tracer_internal.h @@ -0,0 +1,61 @@ +/* + * Copyright 2024 LiveKit + * + * 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. + */ + +#ifndef LIVEKIT_TRACE_EVENT_TRACER_INTERNAL_H_ +#define LIVEKIT_TRACE_EVENT_TRACER_INTERNAL_H_ + +#include +#include +#include + +namespace livekit { +namespace trace { +namespace internal { + +/** + * Start tracing and write events to the specified file. + * + * Opens the file, starts a background writer thread, and enables tracing. + * Events are queued and written asynchronously to minimize latency impact. + * + * @param file_path Path to the output trace file + * @param categories Categories to enable (empty = all) + * @return true if tracing started successfully, false if already running or + * file error + */ +bool StartTracing(const std::string &file_path, + const std::vector &categories); + +/** + * Stop tracing and flush all pending events. + * + * Disables tracing, waits for the background thread to write all queued events, + * finalizes the JSON output, and closes the file. + */ +void StopTracing(); + +/** + * Check if tracing is currently enabled. + * + * @return true if tracing is active + */ +bool IsTracingEnabled(); + +} // namespace internal +} // namespace trace +} // namespace livekit + +#endif // LIVEKIT_TRACE_EVENT_TRACER_INTERNAL_H_ diff --git a/src/trace/trace_event.h b/src/trace/trace_event.h new file mode 100644 index 00000000..05d6edfa --- /dev/null +++ b/src/trace/trace_event.h @@ -0,0 +1,862 @@ +/* + * Copyright 2024 LiveKit + * + * 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. + * + * Based on Chromium's trace_event.h: + * Copyright (c) 2012 The Chromium Authors. All rights reserved. + * Use of this source code is governed by a BSD-style license. + */ + +#ifndef LIVEKIT_TRACE_TRACE_EVENT_H_ +#define LIVEKIT_TRACE_TRACE_EVENT_H_ + +#include "event_tracer.h" +#include +#include +#if defined(TRACE_EVENT0) +#error "Another copy of trace_event.h has already been included." +#endif +// Extracted from Chromium's src/base/debug/trace_event.h. +// This header is designed to give you trace_event macros without specifying +// how the events actually get collected and stored. If you need to expose trace +// event to some other universe, you can copy-and-paste this file, +// implement the TRACE_EVENT_API macros, and do any other necessary fixup for +// the target platform. The end result is that multiple libraries can funnel +// events through to a shared trace event collector. +// Trace events are for tracking application performance and resource usage. +// Macros are provided to track: +// Begin and end of function calls +// Counters +// +// Events are issued against categories. Whereas LOG's +// categories are statically defined, TRACE categories are created +// implicitly with a string. For example: +// TRACE_EVENT_INSTANT0("MY_SUBSYSTEM", "SomeImportantEvent") +// +// Events can be INSTANT, or can be pairs of BEGIN and END in the same scope: +// TRACE_EVENT_BEGIN0("MY_SUBSYSTEM", "SomethingCostly") +// doSomethingCostly() +// TRACE_EVENT_END0("MY_SUBSYSTEM", "SomethingCostly") +// Note: our tools can't always determine the correct BEGIN/END pairs unless +// these are used in the same scope. Use ASYNC_BEGIN/ASYNC_END macros if you +// need them to be in separate scopes. +// +// A common use case is to trace entire function scopes. This +// issues a trace BEGIN and END automatically: +// void doSomethingCostly() { +// TRACE_EVENT0("MY_SUBSYSTEM", "doSomethingCostly"); +// ... +// } +// +// Additional parameters can be associated with an event: +// void doSomethingCostly2(int howMuch) { +// TRACE_EVENT1("MY_SUBSYSTEM", "doSomethingCostly", +// "howMuch", howMuch); +// ... +// } +// +// The trace system will automatically add to this information the +// current process id, thread id, and a timestamp in microseconds. +// +// To trace an asynchronous procedure such as an IPC send/receive, use +// ASYNC_BEGIN and ASYNC_END: +// [single threaded sender code] +// static int send_count = 0; +// ++send_count; +// TRACE_EVENT_ASYNC_BEGIN0("ipc", "message", send_count); +// Send(new MyMessage(send_count)); +// [receive code] +// void OnMyMessage(send_count) { +// TRACE_EVENT_ASYNC_END0("ipc", "message", send_count); +// } +// The third parameter is a unique ID to match ASYNC_BEGIN/ASYNC_END pairs. +// ASYNC_BEGIN and ASYNC_END can occur on any thread of any traced process. +// Pointers can be used for the ID parameter, and they will be mangled +// internally so that the same pointer on two different processes will not +// match. For example: +// class MyTracedClass { +// public: +// MyTracedClass() { +// TRACE_EVENT_ASYNC_BEGIN0("category", "MyTracedClass", this); +// } +// ~MyTracedClass() { +// TRACE_EVENT_ASYNC_END0("category", "MyTracedClass", this); +// } +// } +// +// Trace event also supports counters, which is a way to track a quantity +// as it varies over time. Counters are created with the following macro: +// TRACE_COUNTER1("MY_SUBSYSTEM", "myCounter", g_myCounterValue); +// +// Counters are process-specific. The macro itself can be issued from any +// thread, however. +// +// Sometimes, you want to track two counters at once. You can do this with two +// counter macros: +// TRACE_COUNTER1("MY_SUBSYSTEM", "myCounter0", g_myCounterValue[0]); +// TRACE_COUNTER1("MY_SUBSYSTEM", "myCounter1", g_myCounterValue[1]); +// Or you can do it with a combined macro: +// TRACE_COUNTER2("MY_SUBSYSTEM", "myCounter", +// "bytesPinned", g_myCounterValue[0], +// "bytesAllocated", g_myCounterValue[1]); +// This indicates to the tracing UI that these counters should be displayed +// in a single graph, as a summed area chart. +// +// Since counters are in a global namespace, you may want to disembiguate with a +// unique ID, by using the TRACE_COUNTER_ID* variations. +// +// By default, trace collection is compiled in, but turned off at runtime. +// Collecting trace data is the responsibility of the embedding +// application. In Chrome's case, navigating to about:tracing will turn on +// tracing and display data collected across all active processes. +// +// +// Memory scoping note: +// Tracing copies the pointers, not the string content, of the strings passed +// in for category, name, and arg_names. Thus, the following code will +// cause problems: +// char* str = strdup("impprtantName"); +// TRACE_EVENT_INSTANT0("SUBSYSTEM", str); // BAD! +// free(str); // Trace system now has dangling pointer +// +// To avoid this issue with the |name| and |arg_name| parameters, use the +// TRACE_EVENT_COPY_XXX overloads of the macros at additional runtime overhead. +// Notes: The category must always be in a long-lived char* (i.e. static const). +// The |arg_values|, when used, are always deep copied with the _COPY +// macros. +// +// When are string argument values copied: +// const char* arg_values are only referenced by default: +// TRACE_EVENT1("category", "name", +// "arg1", "literal string is only referenced"); +// Use TRACE_STR_COPY to force copying of a const char*: +// TRACE_EVENT1("category", "name", +// "arg1", TRACE_STR_COPY("string will be copied")); +// std::string arg_values are always copied: +// TRACE_EVENT1("category", "name", +// "arg1", std::string("string will be copied")); +// +// +// Thread Safety: +// Thread safety is provided by methods defined in event_tracer.h. See the file +// for details. +// By default, const char* argument values are assumed to have long-lived scope +// and will not be copied. Use this macro to force a const char* to be copied. +#define TRACE_STR_COPY(str) \ + webrtc::trace_event_internal::TraceStringWithCopy(str) +// By default, uint64 ID argument values are not mangled with the Process ID in +// TRACE_EVENT_ASYNC macros. Use this macro to force Process ID mangling. +#define TRACE_ID_MANGLE(id) \ + webrtc::trace_event_internal::TraceID::ForceMangle(id) +// Records a pair of begin and end events called "name" for the current +// scope, with 0, 1 or 2 associated arguments. If the category is not +// enabled, then this does nothing. +// - category and name strings must have application lifetime (statics or +// literals). They may not include " chars. +#define TRACE_EVENT0(category, name) \ + INTERNAL_TRACE_EVENT_ADD_SCOPED(category, name) +#define TRACE_EVENT1(category, name, arg1_name, arg1_val) \ + INTERNAL_TRACE_EVENT_ADD_SCOPED(category, name, arg1_name, arg1_val) +#define TRACE_EVENT2(category, name, arg1_name, arg1_val, arg2_name, arg2_val) \ + INTERNAL_TRACE_EVENT_ADD_SCOPED(category, name, arg1_name, arg1_val, \ + arg2_name, arg2_val) +// Same as TRACE_EVENT except that they are not included in official builds. +#ifdef OFFICIAL_BUILD +#define UNSHIPPED_TRACE_EVENT0(category, name) (void)0 +#define UNSHIPPED_TRACE_EVENT1(category, name, arg1_name, arg1_val) (void)0 +#define UNSHIPPED_TRACE_EVENT2(category, name, arg1_name, arg1_val, arg2_name, \ + arg2_val) \ + (void)0 +#define UNSHIPPED_TRACE_EVENT_INSTANT0(category, name) (void)0 +#define UNSHIPPED_TRACE_EVENT_INSTANT1(category, name, arg1_name, arg1_val) \ + (void)0 +#define UNSHIPPED_TRACE_EVENT_INSTANT2(category, name, arg1_name, arg1_val, \ + arg2_name, arg2_val) \ + (void)0 +#else +#define UNSHIPPED_TRACE_EVENT0(category, name) TRACE_EVENT0(category, name) +#define UNSHIPPED_TRACE_EVENT1(category, name, arg1_name, arg1_val) \ + TRACE_EVENT1(category, name, arg1_name, arg1_val) +#define UNSHIPPED_TRACE_EVENT2(category, name, arg1_name, arg1_val, arg2_name, \ + arg2_val) \ + TRACE_EVENT2(category, name, arg1_name, arg1_val, arg2_name, arg2_val) +#define UNSHIPPED_TRACE_EVENT_INSTANT0(category, name) \ + TRACE_EVENT_INSTANT0(category, name) +#define UNSHIPPED_TRACE_EVENT_INSTANT1(category, name, arg1_name, arg1_val) \ + TRACE_EVENT_INSTANT1(category, name, arg1_name, arg1_val) +#define UNSHIPPED_TRACE_EVENT_INSTANT2(category, name, arg1_name, arg1_val, \ + arg2_name, arg2_val) \ + TRACE_EVENT_INSTANT2(category, name, arg1_name, arg1_val, arg2_name, arg2_val) +#endif +// Records a single event called "name" immediately, with 0, 1 or 2 +// associated arguments. If the category is not enabled, then this +// does nothing. +// - category and name strings must have application lifetime (statics or +// literals). They may not include " chars. +#define TRACE_EVENT_INSTANT0(category, name) \ + INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_INSTANT, category, name, \ + TRACE_EVENT_FLAG_NONE) +#define TRACE_EVENT_INSTANT1(category, name, arg1_name, arg1_val) \ + INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_INSTANT, category, name, \ + TRACE_EVENT_FLAG_NONE, arg1_name, arg1_val) +#define TRACE_EVENT_INSTANT2(category, name, arg1_name, arg1_val, arg2_name, \ + arg2_val) \ + INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_INSTANT, category, name, \ + TRACE_EVENT_FLAG_NONE, arg1_name, arg1_val, \ + arg2_name, arg2_val) +#define TRACE_EVENT_COPY_INSTANT0(category, name) \ + INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_INSTANT, category, name, \ + TRACE_EVENT_FLAG_COPY) +#define TRACE_EVENT_COPY_INSTANT1(category, name, arg1_name, arg1_val) \ + INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_INSTANT, category, name, \ + TRACE_EVENT_FLAG_COPY, arg1_name, arg1_val) +#define TRACE_EVENT_COPY_INSTANT2(category, name, arg1_name, arg1_val, \ + arg2_name, arg2_val) \ + INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_INSTANT, category, name, \ + TRACE_EVENT_FLAG_COPY, arg1_name, arg1_val, \ + arg2_name, arg2_val) +// Records a single BEGIN event called "name" immediately, with 0, 1 or 2 +// associated arguments. If the category is not enabled, then this +// does nothing. +// - category and name strings must have application lifetime (statics or +// literals). They may not include " chars. +#define TRACE_EVENT_BEGIN0(category, name) \ + INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_BEGIN, category, name, \ + TRACE_EVENT_FLAG_NONE) +#define TRACE_EVENT_BEGIN1(category, name, arg1_name, arg1_val) \ + INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_BEGIN, category, name, \ + TRACE_EVENT_FLAG_NONE, arg1_name, arg1_val) +#define TRACE_EVENT_BEGIN2(category, name, arg1_name, arg1_val, arg2_name, \ + arg2_val) \ + INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_BEGIN, category, name, \ + TRACE_EVENT_FLAG_NONE, arg1_name, arg1_val, \ + arg2_name, arg2_val) +#define TRACE_EVENT_COPY_BEGIN0(category, name) \ + INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_BEGIN, category, name, \ + TRACE_EVENT_FLAG_COPY) +#define TRACE_EVENT_COPY_BEGIN1(category, name, arg1_name, arg1_val) \ + INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_BEGIN, category, name, \ + TRACE_EVENT_FLAG_COPY, arg1_name, arg1_val) +#define TRACE_EVENT_COPY_BEGIN2(category, name, arg1_name, arg1_val, \ + arg2_name, arg2_val) \ + INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_BEGIN, category, name, \ + TRACE_EVENT_FLAG_COPY, arg1_name, arg1_val, \ + arg2_name, arg2_val) +// Records a single END event for "name" immediately. If the category +// is not enabled, then this does nothing. +// - category and name strings must have application lifetime (statics or +// literals). They may not include " chars. +#define TRACE_EVENT_END0(category, name) \ + INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_END, category, name, \ + TRACE_EVENT_FLAG_NONE) +#define TRACE_EVENT_END1(category, name, arg1_name, arg1_val) \ + INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_END, category, name, \ + TRACE_EVENT_FLAG_NONE, arg1_name, arg1_val) +#define TRACE_EVENT_END2(category, name, arg1_name, arg1_val, arg2_name, \ + arg2_val) \ + INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_END, category, name, \ + TRACE_EVENT_FLAG_NONE, arg1_name, arg1_val, \ + arg2_name, arg2_val) +#define TRACE_EVENT_COPY_END0(category, name) \ + INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_END, category, name, \ + TRACE_EVENT_FLAG_COPY) +#define TRACE_EVENT_COPY_END1(category, name, arg1_name, arg1_val) \ + INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_END, category, name, \ + TRACE_EVENT_FLAG_COPY, arg1_name, arg1_val) +#define TRACE_EVENT_COPY_END2(category, name, arg1_name, arg1_val, arg2_name, \ + arg2_val) \ + INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_END, category, name, \ + TRACE_EVENT_FLAG_COPY, arg1_name, arg1_val, \ + arg2_name, arg2_val) +// Records the value of a counter called "name" immediately. Value +// must be representable as a 32 bit integer. +// - category and name strings must have application lifetime (statics or +// literals). They may not include " chars. +#define TRACE_COUNTER1(category, name, value) \ + INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_COUNTER, category, name, \ + TRACE_EVENT_FLAG_NONE, "value", \ + static_cast(value)) +#define TRACE_COPY_COUNTER1(category, name, value) \ + INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_COUNTER, category, name, \ + TRACE_EVENT_FLAG_COPY, "value", \ + static_cast(value)) +// Records the values of a multi-parted counter called "name" immediately. +// The UI will treat value1 and value2 as parts of a whole, displaying their +// values as a stacked-bar chart. +// - category and name strings must have application lifetime (statics or +// literals). They may not include " chars. +#define TRACE_COUNTER2(category, name, value1_name, value1_val, value2_name, \ + value2_val) \ + INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_COUNTER, category, name, \ + TRACE_EVENT_FLAG_NONE, value1_name, \ + static_cast(value1_val), value2_name, \ + static_cast(value2_val)) +#define TRACE_COPY_COUNTER2(category, name, value1_name, value1_val, \ + value2_name, value2_val) \ + INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_COUNTER, category, name, \ + TRACE_EVENT_FLAG_COPY, value1_name, \ + static_cast(value1_val), value2_name, \ + static_cast(value2_val)) +// Records the value of a counter called "name" immediately. Value +// must be representable as a 32 bit integer. +// - category and name strings must have application lifetime (statics or +// literals). They may not include " chars. +// - |id| is used to disambiguate counters with the same name. It must either +// be a pointer or an integer value up to 64 bits. If it's a pointer, the bits +// will be xored with a hash of the process ID so that the same pointer on +// two different processes will not collide. +#define TRACE_COUNTER_ID1(category, name, id, value) \ + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_COUNTER, category, name, \ + id, TRACE_EVENT_FLAG_NONE, "value", \ + static_cast(value)) +#define TRACE_COPY_COUNTER_ID1(category, name, id, value) \ + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_COUNTER, category, name, \ + id, TRACE_EVENT_FLAG_COPY, "value", \ + static_cast(value)) +// Records the values of a multi-parted counter called "name" immediately. +// The UI will treat value1 and value2 as parts of a whole, displaying their +// values as a stacked-bar chart. +// - category and name strings must have application lifetime (statics or +// literals). They may not include " chars. +// - |id| is used to disambiguate counters with the same name. It must either +// be a pointer or an integer value up to 64 bits. If it's a pointer, the bits +// will be xored with a hash of the process ID so that the same pointer on +// two different processes will not collide. +#define TRACE_COUNTER_ID2(category, name, id, value1_name, value1_val, \ + value2_name, value2_val) \ + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_COUNTER, category, name, \ + id, TRACE_EVENT_FLAG_NONE, value1_name, \ + static_cast(value1_val), value2_name, \ + static_cast(value2_val)) +#define TRACE_COPY_COUNTER_ID2(category, name, id, value1_name, value1_val, \ + value2_name, value2_val) \ + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_COUNTER, category, name, \ + id, TRACE_EVENT_FLAG_COPY, value1_name, \ + static_cast(value1_val), value2_name, \ + static_cast(value2_val)) +// Records a single ASYNC_BEGIN event called "name" immediately, with 0, 1 or 2 +// associated arguments. If the category is not enabled, then this +// does nothing. +// - category and name strings must have application lifetime (statics or +// literals). They may not include " chars. +// - |id| is used to match the ASYNC_BEGIN event with the ASYNC_END event. ASYNC +// events are considered to match if their category, name and id values all +// match. |id| must either be a pointer or an integer value up to 64 bits. If +// it's a pointer, the bits will be xored with a hash of the process ID so +// that the same pointer on two different processes will not collide. +// An asynchronous operation can consist of multiple phases. The first phase is +// defined by the ASYNC_BEGIN calls. Additional phases can be defined using the +// ASYNC_STEP macros. When the operation completes, call ASYNC_END. +// An ASYNC trace typically occur on a single thread (if not, they will only be +// drawn on the thread defined in the ASYNC_BEGIN event), but all events in that +// operation must use the same |name| and |id|. Each event can have its own +// args. +#define TRACE_EVENT_ASYNC_BEGIN0(category, name, id) \ + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_ASYNC_BEGIN, category, \ + name, id, TRACE_EVENT_FLAG_NONE) +#define TRACE_EVENT_ASYNC_BEGIN1(category, name, id, arg1_name, arg1_val) \ + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_ASYNC_BEGIN, category, \ + name, id, TRACE_EVENT_FLAG_NONE, arg1_name, \ + arg1_val) +#define TRACE_EVENT_ASYNC_BEGIN2(category, name, id, arg1_name, arg1_val, \ + arg2_name, arg2_val) \ + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_ASYNC_BEGIN, category, \ + name, id, TRACE_EVENT_FLAG_NONE, arg1_name, \ + arg1_val, arg2_name, arg2_val) +#define TRACE_EVENT_COPY_ASYNC_BEGIN0(category, name, id) \ + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_ASYNC_BEGIN, category, \ + name, id, TRACE_EVENT_FLAG_COPY) +#define TRACE_EVENT_COPY_ASYNC_BEGIN1(category, name, id, arg1_name, arg1_val) \ + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_ASYNC_BEGIN, category, \ + name, id, TRACE_EVENT_FLAG_COPY, arg1_name, \ + arg1_val) +#define TRACE_EVENT_COPY_ASYNC_BEGIN2(category, name, id, arg1_name, arg1_val, \ + arg2_name, arg2_val) \ + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_ASYNC_BEGIN, category, \ + name, id, TRACE_EVENT_FLAG_COPY, arg1_name, \ + arg1_val, arg2_name, arg2_val) +// Records a single ASYNC_STEP event for |step| immediately. If the category +// is not enabled, then this does nothing. The |name| and |id| must match the +// ASYNC_BEGIN event above. The |step| param identifies this step within the +// async event. This should be called at the beginning of the next phase of an +// asynchronous operation. +#define TRACE_EVENT_ASYNC_STEP0(category, name, id, step) \ + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_ASYNC_STEP, category, \ + name, id, TRACE_EVENT_FLAG_NONE, "step", \ + step) +#define TRACE_EVENT_ASYNC_STEP1(category, name, id, step, arg1_name, arg1_val) \ + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_ASYNC_STEP, category, \ + name, id, TRACE_EVENT_FLAG_NONE, "step", \ + step, arg1_name, arg1_val) +#define TRACE_EVENT_COPY_ASYNC_STEP0(category, name, id, step) \ + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_ASYNC_STEP, category, \ + name, id, TRACE_EVENT_FLAG_COPY, "step", \ + step) +#define TRACE_EVENT_COPY_ASYNC_STEP1(category, name, id, step, arg1_name, \ + arg1_val) \ + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_ASYNC_STEP, category, \ + name, id, TRACE_EVENT_FLAG_COPY, "step", \ + step, arg1_name, arg1_val) +// Records a single ASYNC_END event for "name" immediately. If the category +// is not enabled, then this does nothing. +#define TRACE_EVENT_ASYNC_END0(category, name, id) \ + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_ASYNC_END, category, \ + name, id, TRACE_EVENT_FLAG_NONE) +#define TRACE_EVENT_ASYNC_END1(category, name, id, arg1_name, arg1_val) \ + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_ASYNC_END, category, \ + name, id, TRACE_EVENT_FLAG_NONE, arg1_name, \ + arg1_val) +#define TRACE_EVENT_ASYNC_END2(category, name, id, arg1_name, arg1_val, \ + arg2_name, arg2_val) \ + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_ASYNC_END, category, \ + name, id, TRACE_EVENT_FLAG_NONE, arg1_name, \ + arg1_val, arg2_name, arg2_val) +#define TRACE_EVENT_COPY_ASYNC_END0(category, name, id) \ + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_ASYNC_END, category, \ + name, id, TRACE_EVENT_FLAG_COPY) +#define TRACE_EVENT_COPY_ASYNC_END1(category, name, id, arg1_name, arg1_val) \ + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_ASYNC_END, category, \ + name, id, TRACE_EVENT_FLAG_COPY, arg1_name, \ + arg1_val) +#define TRACE_EVENT_COPY_ASYNC_END2(category, name, id, arg1_name, arg1_val, \ + arg2_name, arg2_val) \ + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_ASYNC_END, category, \ + name, id, TRACE_EVENT_FLAG_COPY, arg1_name, \ + arg1_val, arg2_name, arg2_val) +// Records a single FLOW_BEGIN event called "name" immediately, with 0, 1 or 2 +// associated arguments. If the category is not enabled, then this +// does nothing. +// - category and name strings must have application lifetime (statics or +// literals). They may not include " chars. +// - |id| is used to match the FLOW_BEGIN event with the FLOW_END event. FLOW +// events are considered to match if their category, name and id values all +// match. |id| must either be a pointer or an integer value up to 64 bits. If +// it's a pointer, the bits will be xored with a hash of the process ID so +// that the same pointer on two different processes will not collide. +// FLOW events are different from ASYNC events in how they are drawn by the +// tracing UI. A FLOW defines asynchronous data flow, such as posting a task +// (FLOW_BEGIN) and later executing that task (FLOW_END). Expect FLOWs to be +// drawn as lines or arrows from FLOW_BEGIN scopes to FLOW_END scopes. Similar +// to ASYNC, a FLOW can consist of multiple phases. The first phase is defined +// by the FLOW_BEGIN calls. Additional phases can be defined using the FLOW_STEP +// macros. When the operation completes, call FLOW_END. An async operation can +// span threads and processes, but all events in that operation must use the +// same |name| and |id|. Each event can have its own args. +#define TRACE_EVENT_FLOW_BEGIN0(category, name, id) \ + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_FLOW_BEGIN, category, \ + name, id, TRACE_EVENT_FLAG_NONE) +#define TRACE_EVENT_FLOW_BEGIN1(category, name, id, arg1_name, arg1_val) \ + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_FLOW_BEGIN, category, \ + name, id, TRACE_EVENT_FLAG_NONE, arg1_name, \ + arg1_val) +#define TRACE_EVENT_FLOW_BEGIN2(category, name, id, arg1_name, arg1_val, \ + arg2_name, arg2_val) \ + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_FLOW_BEGIN, category, \ + name, id, TRACE_EVENT_FLAG_NONE, arg1_name, \ + arg1_val, arg2_name, arg2_val) +#define TRACE_EVENT_COPY_FLOW_BEGIN0(category, name, id) \ + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_FLOW_BEGIN, category, \ + name, id, TRACE_EVENT_FLAG_COPY) +#define TRACE_EVENT_COPY_FLOW_BEGIN1(category, name, id, arg1_name, arg1_val) \ + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_FLOW_BEGIN, category, \ + name, id, TRACE_EVENT_FLAG_COPY, arg1_name, \ + arg1_val) +#define TRACE_EVENT_COPY_FLOW_BEGIN2(category, name, id, arg1_name, arg1_val, \ + arg2_name, arg2_val) \ + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_FLOW_BEGIN, category, \ + name, id, TRACE_EVENT_FLAG_COPY, arg1_name, \ + arg1_val, arg2_name, arg2_val) +// Records a single FLOW_STEP event for |step| immediately. If the category +// is not enabled, then this does nothing. The |name| and |id| must match the +// FLOW_BEGIN event above. The |step| param identifies this step within the +// async event. This should be called at the beginning of the next phase of an +// asynchronous operation. +#define TRACE_EVENT_FLOW_STEP0(category, name, id, step) \ + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_FLOW_STEP, category, \ + name, id, TRACE_EVENT_FLAG_NONE, "step", \ + step) +#define TRACE_EVENT_FLOW_STEP1(category, name, id, step, arg1_name, arg1_val) \ + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_FLOW_STEP, category, \ + name, id, TRACE_EVENT_FLAG_NONE, "step", \ + step, arg1_name, arg1_val) +#define TRACE_EVENT_COPY_FLOW_STEP0(category, name, id, step) \ + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_FLOW_STEP, category, \ + name, id, TRACE_EVENT_FLAG_COPY, "step", \ + step) +#define TRACE_EVENT_COPY_FLOW_STEP1(category, name, id, step, arg1_name, \ + arg1_val) \ + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_FLOW_STEP, category, \ + name, id, TRACE_EVENT_FLAG_COPY, "step", \ + step, arg1_name, arg1_val) +// Records a single FLOW_END event for "name" immediately. If the category +// is not enabled, then this does nothing. +#define TRACE_EVENT_FLOW_END0(category, name, id) \ + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_FLOW_END, category, name, \ + id, TRACE_EVENT_FLAG_NONE) +#define TRACE_EVENT_FLOW_END1(category, name, id, arg1_name, arg1_val) \ + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_FLOW_END, category, name, \ + id, TRACE_EVENT_FLAG_NONE, arg1_name, \ + arg1_val) +#define TRACE_EVENT_FLOW_END2(category, name, id, arg1_name, arg1_val, \ + arg2_name, arg2_val) \ + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_FLOW_END, category, name, \ + id, TRACE_EVENT_FLAG_NONE, arg1_name, \ + arg1_val, arg2_name, arg2_val) +#define TRACE_EVENT_COPY_FLOW_END0(category, name, id) \ + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_FLOW_END, category, name, \ + id, TRACE_EVENT_FLAG_COPY) +#define TRACE_EVENT_COPY_FLOW_END1(category, name, id, arg1_name, arg1_val) \ + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_FLOW_END, category, name, \ + id, TRACE_EVENT_FLAG_COPY, arg1_name, \ + arg1_val) +#define TRACE_EVENT_COPY_FLOW_END2(category, name, id, arg1_name, arg1_val, \ + arg2_name, arg2_val) \ + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_FLOW_END, category, name, \ + id, TRACE_EVENT_FLAG_COPY, arg1_name, \ + arg1_val, arg2_name, arg2_val) +//////////////////////////////////////////////////////////////////////////////// +// Implementation specific tracing API definitions. +// Get a pointer to the enabled state of the given trace category. Only +// long-lived literal strings should be given as the category name. The returned +// pointer can be held permanently in a local static for example. If the +// unsigned char is non-zero, tracing is enabled. If tracing is enabled, +// TRACE_EVENT_API_ADD_TRACE_EVENT can be called. It's OK if tracing is disabled +// between the load of the tracing state and the call to +// TRACE_EVENT_API_ADD_TRACE_EVENT, because this flag only provides an early out +// for best performance when tracing is disabled. +// const unsigned char* +// TRACE_EVENT_API_GET_CATEGORY_ENABLED(const char* category_name) +#define TRACE_EVENT_API_GET_CATEGORY_ENABLED \ + webrtc::EventTracer::GetCategoryEnabled +// Add a trace event to the platform tracing system. +// void TRACE_EVENT_API_ADD_TRACE_EVENT( +// char phase, +// const unsigned char* category_enabled, +// const char* name, +// unsigned long long id, +// int num_args, +// const char** arg_names, +// const unsigned char* arg_types, +// const unsigned long long* arg_values, +// unsigned char flags) +#define TRACE_EVENT_API_ADD_TRACE_EVENT webrtc::EventTracer::AddTraceEvent +//////////////////////////////////////////////////////////////////////////////// +// Implementation detail: trace event macros create temporary variables +// to keep instrumentation overhead low. These macros give each temporary +// variable a unique name based on the line number to prevent name collissions. +#define INTERNAL_TRACE_EVENT_UID3(a, b) trace_event_unique_##a##b +#define INTERNAL_TRACE_EVENT_UID2(a, b) INTERNAL_TRACE_EVENT_UID3(a, b) +#define INTERNAL_TRACE_EVENT_UID(name_prefix) \ + INTERNAL_TRACE_EVENT_UID2(name_prefix, __LINE__) +// Implementation detail: internal macro to create static category. +#define INTERNAL_TRACE_EVENT_GET_CATEGORY_INFO(category) \ + static const unsigned char *INTERNAL_TRACE_EVENT_UID(catstatic) = 0; \ + if (!INTERNAL_TRACE_EVENT_UID(catstatic)) { \ + INTERNAL_TRACE_EVENT_UID(catstatic) = \ + TRACE_EVENT_API_GET_CATEGORY_ENABLED(category); \ + } +// Implementation detail: internal macro to create static category and add +// event if the category is enabled. +#define INTERNAL_TRACE_EVENT_ADD(phase, category, name, flags, ...) \ + do { \ + INTERNAL_TRACE_EVENT_GET_CATEGORY_INFO(category); \ + if (*INTERNAL_TRACE_EVENT_UID(catstatic)) { \ + webrtc::trace_event_internal::AddTraceEvent( \ + phase, INTERNAL_TRACE_EVENT_UID(catstatic), name, \ + webrtc::trace_event_internal::kNoEventId, flags, ##__VA_ARGS__); \ + } \ + } while (0) +// Implementation detail: internal macro to create static category and add begin +// event if the category is enabled. Also adds the end event when the scope +// ends. +#define INTERNAL_TRACE_EVENT_ADD_SCOPED(category, name, ...) \ + INTERNAL_TRACE_EVENT_GET_CATEGORY_INFO(category); \ + webrtc::trace_event_internal::TraceEndOnScopeClose INTERNAL_TRACE_EVENT_UID( \ + profileScope); \ + if (*INTERNAL_TRACE_EVENT_UID(catstatic)) { \ + webrtc::trace_event_internal::AddTraceEvent( \ + TRACE_EVENT_PHASE_BEGIN, INTERNAL_TRACE_EVENT_UID(catstatic), name, \ + webrtc::trace_event_internal::kNoEventId, TRACE_EVENT_FLAG_NONE, \ + ##__VA_ARGS__); \ + INTERNAL_TRACE_EVENT_UID(profileScope) \ + .Initialize(INTERNAL_TRACE_EVENT_UID(catstatic), name); \ + } +// Implementation detail: internal macro to create static category and add +// event if the category is enabled. +#define INTERNAL_TRACE_EVENT_ADD_WITH_ID(phase, category, name, id, flags, \ + ...) \ + do { \ + INTERNAL_TRACE_EVENT_GET_CATEGORY_INFO(category); \ + if (*INTERNAL_TRACE_EVENT_UID(catstatic)) { \ + unsigned char trace_event_flags = flags | TRACE_EVENT_FLAG_HAS_ID; \ + webrtc::trace_event_internal::TraceID trace_event_trace_id( \ + id, &trace_event_flags); \ + webrtc::trace_event_internal::AddTraceEvent( \ + phase, INTERNAL_TRACE_EVENT_UID(catstatic), name, \ + trace_event_trace_id.data(), trace_event_flags, ##__VA_ARGS__); \ + } \ + } while (0) +// Notes regarding the following definitions: +// New values can be added and propagated to third party libraries, but existing +// definitions must never be changed, because third party libraries may use old +// definitions. +// Phase indicates the nature of an event entry. E.g. part of a begin/end pair. +#define TRACE_EVENT_PHASE_BEGIN ('B') +#define TRACE_EVENT_PHASE_END ('E') +#define TRACE_EVENT_PHASE_INSTANT ('I') +#define TRACE_EVENT_PHASE_ASYNC_BEGIN ('S') +#define TRACE_EVENT_PHASE_ASYNC_STEP ('T') +#define TRACE_EVENT_PHASE_ASYNC_END ('F') +#define TRACE_EVENT_PHASE_FLOW_BEGIN ('s') +#define TRACE_EVENT_PHASE_FLOW_STEP ('t') +#define TRACE_EVENT_PHASE_FLOW_END ('f') +#define TRACE_EVENT_PHASE_METADATA ('M') +#define TRACE_EVENT_PHASE_COUNTER ('C') +// Flags for changing the behavior of TRACE_EVENT_API_ADD_TRACE_EVENT. +#define TRACE_EVENT_FLAG_NONE (static_cast(0)) +#define TRACE_EVENT_FLAG_COPY (static_cast(1 << 0)) +#define TRACE_EVENT_FLAG_HAS_ID (static_cast(1 << 1)) +#define TRACE_EVENT_FLAG_MANGLE_ID (static_cast(1 << 2)) +// Type values for identifying types in the TraceValue union. +#define TRACE_VALUE_TYPE_BOOL (static_cast(1)) +#define TRACE_VALUE_TYPE_UINT (static_cast(2)) +#define TRACE_VALUE_TYPE_INT (static_cast(3)) +#define TRACE_VALUE_TYPE_DOUBLE (static_cast(4)) +#define TRACE_VALUE_TYPE_POINTER (static_cast(5)) +#define TRACE_VALUE_TYPE_STRING (static_cast(6)) +#define TRACE_VALUE_TYPE_COPY_STRING (static_cast(7)) +namespace webrtc { +namespace trace_event_internal { +// Specify these values when the corresponding argument of AddTraceEvent is not +// used. +const int kZeroNumArgs = 0; +const unsigned long long kNoEventId = 0; +// TraceID encapsulates an ID that can either be an integer or pointer. Pointers +// are mangled with the Process ID so that they are unlikely to collide when the +// same pointer is used on different processes. +class TraceID { +public: + class ForceMangle { + public: + explicit ForceMangle(unsigned long long id) : data_(id) {} + explicit ForceMangle(unsigned long id) : data_(id) {} + explicit ForceMangle(unsigned int id) : data_(id) {} + explicit ForceMangle(unsigned short id) : data_(id) {} + explicit ForceMangle(unsigned char id) : data_(id) {} + explicit ForceMangle(long long id) + : data_(static_cast(id)) {} + explicit ForceMangle(long id) + : data_(static_cast(id)) {} + explicit ForceMangle(int id) : data_(static_cast(id)) {} + explicit ForceMangle(short id) + : data_(static_cast(id)) {} + explicit ForceMangle(signed char id) + : data_(static_cast(id)) {} + unsigned long long data() const { return data_; } + + private: + unsigned long long data_; + }; + explicit TraceID(const void *id, unsigned char *flags) + : data_(static_cast( + reinterpret_cast(id))) { + *flags |= TRACE_EVENT_FLAG_MANGLE_ID; + } + explicit TraceID(ForceMangle id, unsigned char *flags) : data_(id.data()) { + *flags |= TRACE_EVENT_FLAG_MANGLE_ID; + } + explicit TraceID(unsigned long long id, unsigned char *flags) : data_(id) { + (void)flags; + } + explicit TraceID(unsigned long id, unsigned char *flags) : data_(id) { + (void)flags; + } + explicit TraceID(unsigned int id, unsigned char *flags) : data_(id) { + (void)flags; + } + explicit TraceID(unsigned short id, unsigned char *flags) : data_(id) { + (void)flags; + } + explicit TraceID(unsigned char id, unsigned char *flags) : data_(id) { + (void)flags; + } + explicit TraceID(long long id, unsigned char *flags) + : data_(static_cast(id)) { + (void)flags; + } + explicit TraceID(long id, unsigned char *flags) + : data_(static_cast(id)) { + (void)flags; + } + explicit TraceID(int id, unsigned char *flags) + : data_(static_cast(id)) { + (void)flags; + } + explicit TraceID(short id, unsigned char *flags) + : data_(static_cast(id)) { + (void)flags; + } + explicit TraceID(signed char id, unsigned char *flags) + : data_(static_cast(id)) { + (void)flags; + } + unsigned long long data() const { return data_; } + +private: + unsigned long long data_; +}; +// Simple union to store various types as unsigned long long. +union TraceValueUnion { + bool as_bool; + unsigned long long as_uint; + long long as_int; + double as_double; + const void *as_pointer; + const char *as_string; +}; +// Simple container for const char* that should be copied instead of retained. +class TraceStringWithCopy { +public: + explicit TraceStringWithCopy(const char *str) : str_(str) {} + operator const char *() const { return str_; } + +private: + const char *str_; +}; +// Define SetTraceValue for each allowed type. It stores the type and +// value in the return arguments. This allows this API to avoid declaring any +// structures so that it is portable to third_party libraries. +#define INTERNAL_DECLARE_SET_TRACE_VALUE(actual_type, union_member, \ + value_type_id) \ + static inline void SetTraceValue(actual_type arg, unsigned char *type, \ + unsigned long long *value) { \ + TraceValueUnion type_value; \ + type_value.union_member = arg; \ + *type = value_type_id; \ + *value = type_value.as_uint; \ + } +// Simpler form for int types that can be safely casted. +#define INTERNAL_DECLARE_SET_TRACE_VALUE_INT(actual_type, value_type_id) \ + static inline void SetTraceValue(actual_type arg, unsigned char *type, \ + unsigned long long *value) { \ + *type = value_type_id; \ + *value = static_cast(arg); \ + } +INTERNAL_DECLARE_SET_TRACE_VALUE_INT(unsigned long long, TRACE_VALUE_TYPE_UINT) +INTERNAL_DECLARE_SET_TRACE_VALUE_INT(unsigned long, TRACE_VALUE_TYPE_UINT) +INTERNAL_DECLARE_SET_TRACE_VALUE_INT(unsigned int, TRACE_VALUE_TYPE_UINT) +INTERNAL_DECLARE_SET_TRACE_VALUE_INT(unsigned short, TRACE_VALUE_TYPE_UINT) +INTERNAL_DECLARE_SET_TRACE_VALUE_INT(unsigned char, TRACE_VALUE_TYPE_UINT) +INTERNAL_DECLARE_SET_TRACE_VALUE_INT(long long, TRACE_VALUE_TYPE_INT) +INTERNAL_DECLARE_SET_TRACE_VALUE_INT(long, TRACE_VALUE_TYPE_INT) +INTERNAL_DECLARE_SET_TRACE_VALUE_INT(int, TRACE_VALUE_TYPE_INT) +INTERNAL_DECLARE_SET_TRACE_VALUE_INT(short, TRACE_VALUE_TYPE_INT) +INTERNAL_DECLARE_SET_TRACE_VALUE_INT(signed char, TRACE_VALUE_TYPE_INT) +INTERNAL_DECLARE_SET_TRACE_VALUE(bool, as_bool, TRACE_VALUE_TYPE_BOOL) +INTERNAL_DECLARE_SET_TRACE_VALUE(double, as_double, TRACE_VALUE_TYPE_DOUBLE) +INTERNAL_DECLARE_SET_TRACE_VALUE(const void *, as_pointer, + TRACE_VALUE_TYPE_POINTER) +INTERNAL_DECLARE_SET_TRACE_VALUE(const char *, as_string, + TRACE_VALUE_TYPE_STRING) +INTERNAL_DECLARE_SET_TRACE_VALUE(const TraceStringWithCopy &, as_string, + TRACE_VALUE_TYPE_COPY_STRING) +#undef INTERNAL_DECLARE_SET_TRACE_VALUE +#undef INTERNAL_DECLARE_SET_TRACE_VALUE_INT +// std::string version of SetTraceValue so that trace arguments can be strings. +static inline void SetTraceValue(const std::string &arg, unsigned char *type, + unsigned long long *value) { + TraceValueUnion type_value; + type_value.as_string = arg.c_str(); + *type = TRACE_VALUE_TYPE_COPY_STRING; + *value = type_value.as_uint; +} +// These AddTraceEvent template functions are defined here instead of in the +// macro, because the arg_values could be temporary objects, such as +// std::string. In order to store pointers to the internal c_str and pass +// through to the tracing API, the arg_values must live throughout +// these procedures. +static inline void AddTraceEvent(char phase, + const unsigned char *category_enabled, + const char *name, unsigned long long id, + unsigned char flags) { + TRACE_EVENT_API_ADD_TRACE_EVENT(phase, category_enabled, name, id, + kZeroNumArgs, NULL, NULL, NULL, flags); +} +template +static inline void +AddTraceEvent(char phase, const unsigned char *category_enabled, + const char *name, unsigned long long id, unsigned char flags, + const char *arg1_name, const ARG1_TYPE &arg1_val) { + const int num_args = 1; + unsigned char arg_types[1]; + unsigned long long arg_values[1]; + SetTraceValue(arg1_val, &arg_types[0], &arg_values[0]); + TRACE_EVENT_API_ADD_TRACE_EVENT(phase, category_enabled, name, id, num_args, + &arg1_name, arg_types, arg_values, flags); +} +template +static inline void +AddTraceEvent(char phase, const unsigned char *category_enabled, + const char *name, unsigned long long id, unsigned char flags, + const char *arg1_name, const ARG1_TYPE &arg1_val, + const char *arg2_name, const ARG2_TYPE &arg2_val) { + const int num_args = 2; + const char *arg_names[2] = {arg1_name, arg2_name}; + unsigned char arg_types[2]; + unsigned long long arg_values[2]; + SetTraceValue(arg1_val, &arg_types[0], &arg_values[0]); + SetTraceValue(arg2_val, &arg_types[1], &arg_values[1]); + TRACE_EVENT_API_ADD_TRACE_EVENT(phase, category_enabled, name, id, num_args, + arg_names, arg_types, arg_values, flags); +} +// Used by TRACE_EVENTx macro. Do not use directly. +class TraceEndOnScopeClose { +public: + // Note: members of data_ intentionally left uninitialized. See Initialize. + TraceEndOnScopeClose() : p_data_(NULL) {} + ~TraceEndOnScopeClose() { + if (p_data_) + AddEventIfEnabled(); + } + void Initialize(const unsigned char *category_enabled, const char *name) { + data_.category_enabled = category_enabled; + data_.name = name; + p_data_ = &data_; + } + +private: + // Add the end event if the category is still enabled. + void AddEventIfEnabled() { + // Only called when p_data_ is non-null. + if (*p_data_->category_enabled) { + TRACE_EVENT_API_ADD_TRACE_EVENT( + TRACE_EVENT_PHASE_END, p_data_->category_enabled, p_data_->name, + kNoEventId, kZeroNumArgs, NULL, NULL, NULL, TRACE_EVENT_FLAG_NONE); + } + } + // This Data struct workaround is to avoid initializing all the members + // in Data during construction of this object, since this object is always + // constructed, even when tracing is disabled. If the members of Data were + // members of this class instead, compiler warnings occur about potential + // uninitialized accesses. + struct Data { + const unsigned char *category_enabled; + const char *name; + }; + Data *p_data_; + Data data_; +}; +} // namespace trace_event_internal +} // namespace webrtc +#endif // LIVEKIT_TRACE_TRACE_EVENT_H_ diff --git a/src/trace/tracing.cpp b/src/trace/tracing.cpp new file mode 100644 index 00000000..f1689695 --- /dev/null +++ b/src/trace/tracing.cpp @@ -0,0 +1,31 @@ +/* + * Copyright 2024 LiveKit + * + * 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. + */ + +#include "livekit/tracing.h" +#include "trace/event_tracer_internal.h" + +namespace livekit { + +bool startTracing(const std::string &trace_file_path, + const std::vector &categories) { + return trace::internal::StartTracing(trace_file_path, categories); +} + +void stopTracing() { trace::internal::StopTracing(); } + +bool isTracingEnabled() { return trace::internal::IsTracingEnabled(); } + +} // namespace livekit From d9f591bb45a643de74bcb5848d99cd2c1b1c4b05 Mon Sep 17 00:00:00 2001 From: shijing xian Date: Wed, 8 Apr 2026 17:44:44 -0700 Subject: [PATCH 2/2] fix the license year --- src/tests/benchmark/benchmark_utils.cpp | 2 +- src/tests/benchmark/benchmark_utils.h | 2 +- src/tests/unit/test_tracing.cpp | 2 +- src/trace/event_tracer.cpp | 2 +- src/trace/event_tracer.h | 2 +- src/trace/event_tracer_internal.h | 2 +- src/trace/trace_event.h | 2 +- src/trace/tracing.cpp | 2 +- 8 files changed, 8 insertions(+), 8 deletions(-) diff --git a/src/tests/benchmark/benchmark_utils.cpp b/src/tests/benchmark/benchmark_utils.cpp index eb18f927..b5340ef8 100644 --- a/src/tests/benchmark/benchmark_utils.cpp +++ b/src/tests/benchmark/benchmark_utils.cpp @@ -1,5 +1,5 @@ /* - * Copyright 2024 LiveKit + * Copyright 2026 LiveKit * * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. diff --git a/src/tests/benchmark/benchmark_utils.h b/src/tests/benchmark/benchmark_utils.h index 4eb139f4..f12328bb 100644 --- a/src/tests/benchmark/benchmark_utils.h +++ b/src/tests/benchmark/benchmark_utils.h @@ -1,5 +1,5 @@ /* - * Copyright 2024 LiveKit + * Copyright 2026 LiveKit * * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. diff --git a/src/tests/unit/test_tracing.cpp b/src/tests/unit/test_tracing.cpp index 979d39e4..4439baaf 100644 --- a/src/tests/unit/test_tracing.cpp +++ b/src/tests/unit/test_tracing.cpp @@ -1,5 +1,5 @@ /* - * Copyright 2024 LiveKit + * Copyright 2026 LiveKit * * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. diff --git a/src/trace/event_tracer.cpp b/src/trace/event_tracer.cpp index 6f55596c..05c7ad8a 100644 --- a/src/trace/event_tracer.cpp +++ b/src/trace/event_tracer.cpp @@ -1,5 +1,5 @@ /* - * Copyright 2024 LiveKit + * Copyright 2026 LiveKit * * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. diff --git a/src/trace/event_tracer.h b/src/trace/event_tracer.h index c4225127..0b7aae28 100644 --- a/src/trace/event_tracer.h +++ b/src/trace/event_tracer.h @@ -1,5 +1,5 @@ /* - * Copyright 2024 LiveKit + * Copyright 2026 LiveKit * * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. diff --git a/src/trace/event_tracer_internal.h b/src/trace/event_tracer_internal.h index 4d2ad119..01884b85 100644 --- a/src/trace/event_tracer_internal.h +++ b/src/trace/event_tracer_internal.h @@ -1,5 +1,5 @@ /* - * Copyright 2024 LiveKit + * Copyright 2026 LiveKit * * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. diff --git a/src/trace/trace_event.h b/src/trace/trace_event.h index 05d6edfa..9efda258 100644 --- a/src/trace/trace_event.h +++ b/src/trace/trace_event.h @@ -1,5 +1,5 @@ /* - * Copyright 2024 LiveKit + * Copyright 2026 LiveKit * * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. diff --git a/src/trace/tracing.cpp b/src/trace/tracing.cpp index f1689695..a753e2bf 100644 --- a/src/trace/tracing.cpp +++ b/src/trace/tracing.cpp @@ -1,5 +1,5 @@ /* - * Copyright 2024 LiveKit + * Copyright 2026 LiveKit * * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License.