tracing: Add support for track event timestamps using custom clocks
Make it possible to write track events using custom timestamps together
with a custom reference clock. For example:
TRACE_EVENT_BEGIN("cat", "Name",
perfetto::TraceTimestamp{
perfetto::protos::BuiltinClock::BUILTIN_CLOCK_MONOTONIC,
timestamp_ns});
You can also use a completely custom clock id, but will also need
to manually emit a clock snapshot mapping that clock to the builtin
ones.
Change-Id: I2635eef84dc62368e6e529f43ac5ad9e751c601adiff --git a/CHANGELOG b/CHANGELOG
index 79050a5..67b6c6b 100644
--- a/CHANGELOG
+++ b/CHANGELOG
@@ -6,7 +6,7 @@
UI:
*
SDK:
- *
+ * Added support for writing track events using custom clock timestamps.
v16.0 - 2021-06-01:
diff --git a/include/perfetto/tracing/internal/track_event_data_source.h b/include/perfetto/tracing/internal/track_event_data_source.h
index 12a5a85..9229153 100644
--- a/include/perfetto/tracing/internal/track_event_data_source.h
+++ b/include/perfetto/tracing/internal/track_event_data_source.h
@@ -35,11 +35,6 @@
namespace perfetto {
-struct TraceTimestamp {
- protos::pbzero::BuiltinClock clock_id;
- uint64_t nanoseconds;
-};
-
// This template provides a way to convert an abstract timestamp into the trace
// clock timebase in nanoseconds. By specialising this template and defining
// static ConvertTimestampToTraceTimeNs function in it the user can register
@@ -60,6 +55,15 @@
}
};
+// A pass-through implementation for the trace timestamp structure.
+template <>
+struct TraceTimestampTraits<TraceTimestamp> {
+ static inline TraceTimestamp ConvertTimestampToTraceTimeNs(
+ const TraceTimestamp& timestamp) {
+ return timestamp;
+ }
+};
+
namespace internal {
namespace {
@@ -440,19 +444,16 @@
return;
}
- // TODO(skyostil): Support additional clock ids.
TraceTimestamp trace_timestamp = ::perfetto::TraceTimestampTraits<
TimestampType>::ConvertTimestampToTraceTimeNs(timestamp);
- PERFETTO_DCHECK(trace_timestamp.clock_id ==
- TrackEventInternal::GetClockId());
// Make sure incremental state is valid.
TraceWriterBase* trace_writer = ctx.tls_inst_->trace_writer.get();
TrackEventIncrementalState* incr_state = ctx.GetIncrementalState();
if (incr_state->was_cleared) {
incr_state->was_cleared = false;
- TrackEventInternal::ResetIncrementalState(
- trace_writer, trace_timestamp.nanoseconds);
+ TrackEventInternal::ResetIncrementalState(trace_writer,
+ trace_timestamp);
}
// Write the track descriptor before any event on the track.
@@ -465,7 +466,7 @@
{
auto event_ctx = TrackEventInternal::WriteEvent(
trace_writer, incr_state, static_category, event_name, type,
- trace_timestamp.nanoseconds);
+ trace_timestamp);
// Write dynamic categories (except for events that don't require
// categories). For counter events, the counter name (and optional
// category) is stored as part of the track descriptor instead being
diff --git a/include/perfetto/tracing/internal/track_event_internal.h b/include/perfetto/tracing/internal/track_event_internal.h
index d293039..afd874c 100644
--- a/include/perfetto/tracing/internal/track_event_internal.h
+++ b/include/perfetto/tracing/internal/track_event_internal.h
@@ -32,6 +32,13 @@
#include <unordered_map>
namespace perfetto {
+
+// Represents a point in time for the clock specified by |clock_id|.
+struct TraceTimestamp {
+ protos::pbzero::BuiltinClock clock_id;
+ uint64_t nanoseconds;
+};
+
class EventContext;
class TrackEventSessionObserver;
struct Category;
@@ -139,9 +146,9 @@
const Category* category,
const char* name,
perfetto::protos::pbzero::TrackEvent::Type,
- uint64_t timestamp = GetTimeNs());
+ TraceTimestamp timestamp = {GetClockId(), GetTimeNs()});
- static void ResetIncrementalState(TraceWriterBase*, uint64_t timestamp);
+ static void ResetIncrementalState(TraceWriterBase*, TraceTimestamp);
template <typename T>
static void AddDebugAnnotation(perfetto::EventContext* event_ctx,
@@ -171,7 +178,7 @@
static void WriteTrackDescriptor(const TrackType& track,
TraceWriterBase* trace_writer) {
TrackRegistry::Get()->SerializeTrack(
- track, NewTracePacket(trace_writer, GetTimeNs()));
+ track, NewTracePacket(trace_writer, {GetClockId(), GetTimeNs()}));
}
// Get the current time in nanoseconds in the trace clock timebase.
@@ -195,7 +202,7 @@
private:
static protozero::MessageHandle<protos::pbzero::TracePacket> NewTracePacket(
TraceWriterBase*,
- uint64_t timestamp,
+ TraceTimestamp,
uint32_t seq_flags =
protos::pbzero::TracePacket::SEQ_NEEDS_INCREMENTAL_STATE);
static protos::pbzero::DebugAnnotation* AddDebugAnnotation(
diff --git a/src/tracing/internal/track_event_internal.cc b/src/tracing/internal/track_event_internal.cc
index 736c312..5e4a154 100644
--- a/src/tracing/internal/track_event_internal.cc
+++ b/src/tracing/internal/track_event_internal.cc
@@ -309,7 +309,7 @@
// static
void TrackEventInternal::ResetIncrementalState(TraceWriterBase* trace_writer,
- uint64_t timestamp) {
+ TraceTimestamp timestamp) {
auto default_track = ThreadTrack::Current();
{
// Mark any incremental state before this point invalid. Also set up
@@ -337,14 +337,18 @@
// static
protozero::MessageHandle<protos::pbzero::TracePacket>
TrackEventInternal::NewTracePacket(TraceWriterBase* trace_writer,
- uint64_t timestamp,
+ TraceTimestamp timestamp,
uint32_t seq_flags) {
auto packet = trace_writer->NewTracePacket();
- packet->set_timestamp(timestamp);
- // TODO(skyostil): Stop emitting this for every event once the trace
- // processor understands trace packet defaults.
- if (GetClockId() != protos::pbzero::BUILTIN_CLOCK_BOOTTIME)
+ packet->set_timestamp(timestamp.nanoseconds);
+ if (timestamp.clock_id != GetClockId()) {
+ packet->set_timestamp_clock_id(static_cast<uint32_t>(timestamp.clock_id));
+ } else if (GetClockId() != protos::pbzero::BUILTIN_CLOCK_BOOTTIME) {
+ // TODO(skyostil): Stop emitting the clock id for the default trace clock
+ // for every event once the trace processor understands trace packet
+ // defaults.
packet->set_timestamp_clock_id(GetClockId());
+ }
packet->set_sequence_flags(seq_flags);
return packet;
}
@@ -356,7 +360,7 @@
const Category* category,
const char* name,
perfetto::protos::pbzero::TrackEvent::Type type,
- uint64_t timestamp) {
+ TraceTimestamp timestamp) {
PERFETTO_DCHECK(g_main_thread);
PERFETTO_DCHECK(!incr_state->was_cleared);
diff --git a/src/tracing/test/api_integrationtest.cc b/src/tracing/test/api_integrationtest.cc
index 061e2fe..ed08a17 100644
--- a/src/tracing/test/api_integrationtest.cc
+++ b/src/tracing/test/api_integrationtest.cc
@@ -1473,6 +1473,65 @@
perfetto::TrackEvent::EraseTrackDescriptor(track);
}
+TEST_P(PerfettoApiTest, TrackEventCustomTimestampClock) {
+ // Create a new trace session.
+ auto* tracing_session = NewTraceWithCategories({"foo"});
+ tracing_session->get()->StartBlocking();
+
+ const perfetto::protos::pbzero::BuiltinClock kMyClockId =
+ static_cast<perfetto::protos::pbzero::BuiltinClock>(700);
+ const uint64_t kTimestamp = 12345678;
+
+ // First emit a clock snapshot that maps our custom clock to regular trace
+ // time. Note that the clock snapshot should come before any events
+ // referencing that clock.
+ perfetto::TrackEvent::Trace([](perfetto::TrackEvent::TraceContext ctx) {
+ auto packet = ctx.NewTracePacket();
+ packet->set_timestamp_clock_id(perfetto::TrackEvent::GetTraceClockId());
+ packet->set_timestamp(perfetto::TrackEvent::GetTraceTimeNs());
+ auto* clock_snapshot = packet->set_clock_snapshot();
+ // First set the reference clock, i.e., the default trace clock in this
+ // case.
+ auto* clock = clock_snapshot->add_clocks();
+ clock->set_clock_id(perfetto::TrackEvent::GetTraceClockId());
+ clock->set_timestamp(perfetto::TrackEvent::GetTraceTimeNs());
+ // Then set the value of our reference clock at the same point in time. We
+ // pretend our clock is one second behind trace time.
+ clock = clock_snapshot->add_clocks();
+ clock->set_clock_id(kMyClockId);
+ clock->set_timestamp(kTimestamp + 1000000000ull);
+ });
+
+ // Next emit a trace event with a custom timestamp and a custom clock.
+ TRACE_EVENT_INSTANT("foo", "EventWithCustomTime",
+ perfetto::TraceTimestamp{kMyClockId, kTimestamp});
+ TRACE_EVENT_INSTANT("foo", "EventWithNormalTime");
+
+ perfetto::TrackEvent::Flush();
+ tracing_session->get()->StopBlocking();
+
+ std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
+ perfetto::protos::gen::Trace trace;
+ ASSERT_TRUE(trace.ParseFromArray(raw_trace.data(), raw_trace.size()));
+
+ // Check that both the clock id and the timestamp got written together with
+ // the packet. Note that we don't check the actual clock sync behavior here
+ // since that happens in the Trace Processor instead.
+ bool found_clock_snapshot = false;
+ bool found_event = false;
+ for (const auto& packet : trace.packet()) {
+ if (packet.has_clock_snapshot())
+ found_clock_snapshot = true;
+ if (!packet.has_track_event() || packet.timestamp() != kTimestamp)
+ continue;
+ found_event = true;
+ EXPECT_EQ(static_cast<uint32_t>(kMyClockId), packet.timestamp_clock_id());
+ EXPECT_EQ(kTimestamp, packet.timestamp());
+ }
+ EXPECT_TRUE(found_clock_snapshot);
+ EXPECT_TRUE(found_event);
+}
+
TEST_P(PerfettoApiTest, LegacyEventWithThreadOverride) {
// Create a new trace session.
auto* tracing_session = NewTraceWithCategories({"cat"});
