Skip to content

Commit

Permalink
Some notes on perfetto's behavior upstream
Browse files Browse the repository at this point in the history
  • Loading branch information
@shuhaowu
shuhaowu committed Mar 17, 2024
1 parent 651aa06 commit 42c7722
Show file tree
Hide file tree
Showing 2 changed files with 72 additions and 50 deletions.
50 changes: 49 additions & 1 deletion docs/tracing.md
View file
Original file line number Diff line number Diff line change
Expand Up @@ -237,7 +237,55 @@ TODO...

#### Too much data causing buffer overflow and trace data drops

See https://github.com/google/perfetto/issues/575#issuecomment-1699253191
#### String interning

Perfetto allows event names and event categories to be interned by assigning
each unique string with an id and emitting the id rather than the string to save
space in the output trace files. This feature is implemented via the
`interned_data`, `name_iid`, and `category_iids` fields. A few details worth
noting:

1. Perfetto uses `trusted_packet_sequence_id` to identify a single sequence. A
single sequence must have monotonically increasing timestamps for its
packets. Both Perfetto upstream and cactus-rt's implementation of the tracer
gives a sequence id per thread. In cactus-rt, this is especially important
as when we pop the data from the queue originating from multiple threads.
2. The `iid`s on their own are not sufficient to identify the string being
interned as it is not "globally" unique. It is only unique per sequence
(i.e. thus `(trusted_packet_sequence_id, iid)` is sufficient to identify an
interned string). This, along with (1), implies we have to intern strings on
a per-thread interner.

### Other notes

#### Perfetto SDK (upstream) can grab a lock when buffer is full

- It seems that trace events are emitted via the `TRACE_EVENT` macro, which starts [here with `TRACE_EVENT_BEGIN`](https://github.com/google/perfetto/blob/v43.2/include/perfetto/tracing/track_event.h#L354).
- This then calls [`PERFETTO_INTERNAL_TRACK_EVENT_WITH_METHOD`](https://github.com/google/perfetto/blob/v43.2/include/perfetto/tracing/internal/track_event_macros.h#L115).
- This also calls `perfetto_track_event::internal::isDynamicCategory`
- This calls [`perfetto_track_event::TrackEvent::TraceForCategory`](https://github.com/google/perfetto/blob/v43.2/include/perfetto/tracing/internal/track_event_data_source.h#L376), which eventually calls:
- [`WriteTrackEventImpl`](https://github.com/google/perfetto/blob/v43.2/include/perfetto/tracing/internal/track_event_data_source.h#L874) which creates the protobuf packet via protozero.
- This [calls](https://github.com/google/perfetto/blob/v43.2/include/perfetto/tracing/internal/track_event_data_source.h#L901) [`TrackEventInternal::WriteEvent`](https://github.com/google/perfetto/blob/v43.2/src/tracing/internal/track_event_internal.cc#L528)
- which [calls](https://github.com/google/perfetto/blob/v43.2/src/tracing/internal/track_event_internal.cc#L537) [`NewTracePacket`](https://github.com/google/perfetto/blob/v43.2/src/tracing/internal/track_event_internal.cc#L470)
- which [calls](https://github.com/google/perfetto/blob/v43.2/src/tracing/internal/track_event_internal.cc#L479) [`TraceWriterBase::NewTracePacket`](https://github.com/google/perfetto/blob/v43.2/include/perfetto/tracing/trace_writer_base.h#L41-L61), **which might be [`TraceWriterImpl::NewTracePacket`](https://github.com/google/perfetto/blob/v43.2/src/tracing/core/trace_writer_impl.cc#L119).**

From the other side:

- `SharedMemoryArbiterImpl::GetNewChunk` grabs [a lock](https://github.com/google/perfetto/blob/v43.2/src/tracing/core/shared_memory_arbiter_impl.cc#L106-L110)
- [called from](https://github.com/google/perfetto/blob/v43.2/src/tracing/core/trace_writer_impl.cc#L242) `TraceWriterImpl::GetNewBuffer`.
- **This is called from [`TraceWriterImpl::NewTracePacket`](https://github.com/google/perfetto/blob/v43.2/src/tracing/core/trace_writer_impl.cc#L151).** This is called if the chunk is too full for the data.

This means that there is a small chance that a lock can be taken, and an even smaller chance that a priority inversion could take place. This means it is not suitable for hard real-time applications and a custom tracing library must be written.

#### Perfetto SDK string interning

- `WriteTrackEventImpl` [calls](https://github.com/google/perfetto/blob/v43.2/include/perfetto/tracing/internal/track_event_data_source.h#L907) `TrackEventInternal::WriteEventName` which calls [`InternedEventName::Get`](https://github.com/google/perfetto/blob/v43.2/src/tracing/internal/track_event_internal.cc#L506), and which is implemented in [here](https://github.com/google/perfetto/blob/v43.2/include/perfetto/tracing/track_event_interned_data_index.h#L183).
- In here there's memory allocation due to [`LookupAndInsert`](https://github.com/google/perfetto/blob/v43.2/include/perfetto/tracing/track_event_interned_data_index.h#L99-L144) (called from [here](https://github.com/google/perfetto/blob/v43.2/include/perfetto/tracing/track_event_interned_data_index.h#L189)) using a `std::map`.
- Also `GetOrCreateIndex` [calls `new`](https://github.com/google/perfetto/blob/v43.2/include/perfetto/tracing/track_event_interned_data_index.h#L243). Likely this means another allocation potential on the hot path.

This means Perfetto uses memory allocation on the hot path, which is not acceptable for cactus-rt due to real-time constraints.

#### Perfetto SDK data dropping counter

Advanced tuning and use cases
-----------------------------
Expand Down
72 changes: 23 additions & 49 deletions examples/tracing_protos_example/synthetic_events.cc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -5,10 +5,12 @@

#include "trace.pb.h"

using cactus_tracing::vendor::perfetto::protos::InternedData;
using cactus_tracing::vendor::perfetto::protos::ProcessDescriptor;
using cactus_tracing::vendor::perfetto::protos::ThreadDescriptor;
using cactus_tracing::vendor::perfetto::protos::Trace;
using cactus_tracing::vendor::perfetto::protos::TracePacket_SequenceFlags_SEQ_INCREMENTAL_STATE_CLEARED;
using cactus_tracing::vendor::perfetto::protos::TracePacket_SequenceFlags_SEQ_NEEDS_INCREMENTAL_STATE;
using cactus_tracing::vendor::perfetto::protos::TrackDescriptor;
using cactus_tracing::vendor::perfetto::protos::TrackEvent;
using cactus_tracing::vendor::perfetto::protos::TrackEvent_Type_TYPE_INSTANT;
Expand Down Expand Up @@ -70,16 +72,22 @@ int main() {
auto* packet3 = trace3.add_packet();
packet3->set_timestamp(200);

auto* interned_data1 = new InternedData();
auto* event_name = interned_data1->add_event_names();
event_name->set_iid(1);
event_name->set_name("My special parent");
packet3->set_allocated_interned_data(interned_data1);

auto* track_event1 = new TrackEvent();
track_event1->set_type(TrackEvent_Type_TYPE_SLICE_BEGIN);
track_event1->set_track_uuid(thread_uuid);
track_event1->set_name("My special parent");
track_event1->set_name_iid(1);
packet3->set_allocated_track_event(track_event1);

packet3->set_trusted_packet_sequence_id(trusted_packet_sequence_id);
packet3->set_previous_packet_dropped(true);
packet3->set_first_packet_on_sequence(true);
packet3->set_sequence_flags(TracePacket_SequenceFlags_SEQ_INCREMENTAL_STATE_CLEARED);
packet3->set_sequence_flags(TracePacket_SequenceFlags_SEQ_INCREMENTAL_STATE_CLEARED | TracePacket_SequenceFlags_SEQ_NEEDS_INCREMENTAL_STATE);

Trace trace4;
auto* packet4 = trace4.add_packet();
Expand Down Expand Up @@ -127,66 +135,34 @@ int main() {

packet7->set_trusted_packet_sequence_id(trusted_packet_sequence_id);

// Packets complete, write it into a file!

// Now let's simulate a corruption in the middle of another slide. The idea is:
// 1. There is supposed to be three trace packets between 330 - 430 and 450 - 1000, 1050 - 2000
// 2. The slice begin at 330 got emitted, the slice end at 430 is lost, the slice begin at 450 is lost.
// 3. We detect packet loss occurred, and hence emit a packet loss marker
// 4. Then we emit the slice end at 1000? Could also try emitting 1050.
Trace trace8;
auto* packet8 = trace8.add_packet();
packet8->set_timestamp(330);
packet8->set_timestamp(350);

auto* track_event8 = new TrackEvent();
track_event8->set_type(TrackEvent_Type_TYPE_SLICE_BEGIN);
track_event8->set_track_uuid(thread_uuid);
track_event8->set_name("before packet loss");
track_event8->set_name_iid(1);
packet8->set_allocated_track_event(track_event8);
packet8->set_sequence_flags(TracePacket_SequenceFlags_SEQ_NEEDS_INCREMENTAL_STATE);

packet8->set_trusted_packet_sequence_id(trusted_packet_sequence_id);

Trace trace10;
auto* packet10 = trace10.add_packet();
packet10->set_timestamp(1000);

auto* track_event10 = new TrackEvent();
track_event10->set_type(TrackEvent_Type_TYPE_SLICE_END);
track_event10->set_track_uuid(thread_uuid);
packet10->set_allocated_track_event(track_event10);

packet10->set_trusted_packet_sequence_id(trusted_packet_sequence_id);
packet10->set_first_packet_on_sequence(true);
packet10->set_previous_packet_dropped(true);
packet10->set_sequence_flags(TracePacket_SequenceFlags_SEQ_INCREMENTAL_STATE_CLEARED);

Trace trace11;
auto* packet11 = trace11.add_packet();
packet11->set_timestamp(1050);

auto* track_event11 = new TrackEvent();
track_event11->set_type(TrackEvent_Type_TYPE_SLICE_BEGIN);
track_event11->set_track_uuid(thread_uuid);
track_event11->set_name("After packet loss");
packet11->set_allocated_track_event(track_event11);

packet11->set_trusted_packet_sequence_id(trusted_packet_sequence_id);

Trace trace12;
auto* packet12 = trace12.add_packet();
packet12->set_timestamp(2000);
Trace trace9;
auto* packet9 = trace9.add_packet();
packet9->set_timestamp(500);

auto* track_event12 = new TrackEvent();
track_event12->set_type(TrackEvent_Type_TYPE_SLICE_END);
track_event12->set_track_uuid(thread_uuid);
packet12->set_allocated_track_event(track_event12);
auto* track_event9 = new TrackEvent();
track_event9->set_type(TrackEvent_Type_TYPE_SLICE_END);
track_event9->set_track_uuid(thread_uuid);
packet9->set_allocated_track_event(track_event9);

packet12->set_trusted_packet_sequence_id(trusted_packet_sequence_id);
packet9->set_trusted_packet_sequence_id(trusted_packet_sequence_id);

{
std::fstream output("build/direct_proto_serialization.perfetto-trace", std::ios::out | std::ios::trunc | std::ios::binary);

const std::array<Trace*, 11> traces{
const std::array<Trace*, 9> traces{
&trace1,
&trace2,
&trace3,
Expand All @@ -195,9 +171,7 @@ int main() {
&trace6,
&trace7,
&trace8,
&trace10,
&trace11,
&trace12,
&trace9,
};

for (const auto* trace : traces) {
Expand Down

0 comments on commit 42c7722

Please sign in to comment.