Packets dropped with multithreaded TrackEvent, no buffer overwrite

[kamrann]

I'm using perfetto for the first time so apologies if I'm just misunderstanding intended usage, but I've been digging into things for two days and can't understand why my traces are getting corrupted. I'm using the C++ SDK and doing nothing other than the default TRACE_EVENT[_BEGIN/END] datasource instrumentation. So far, I haven't seen a problem running single threaded, but when I run tasks in parallel on a large enough workload, I almost always end up with dropped packets which render the result useless.

Here is the relevant data, so far as I understand, from my investigation:

1. I see various mixtures of the following data loss warnings: traced_buf_trace_writer_packet_loss, traced_buf_sequence_packet_loss and traced_buf_incremental_sequences_dropped. Maybe just one, maybe two or all three. Yet whenever there are any such loss events, the timeline shows up malformed, with some events being marked as incomplete.
2. Sometimes the timeline length seems as it should be, with the incomplete slices just extending to the end and being far longer than they should be. Other times the incomplete slices just cut short and the trace timeline is much shorter than it should be.
3. Often I see traced_flushes_succeeded being one less than traced_flushes_requested, but this appears to have no relation to whether or not the results are malformed.
4. When it is malformed, traced_buf_bytes_read is slightly smaller than traced_buf_bytes_written.
5. To give an idea of my data volume, the traces I've been doing have been around 2-3 minutes, generating trace files of around half a gigabyte.
6. Slice nesting depth reaches around 100.
7. I ran traceconv text as suggested in another issue, and found some packets like the following:

packet {
  previous_packet_dropped: true
  timestamp: 85501
  sequence_flags: 2
  track_event {
    type: TYPE_SLICE_END
  }
  trusted_uid: 0
  trusted_packet_sequence_id: 3
  trusted_pid: 0
}

To give a bit more info on my setup. I trigger a single tracing session, which

• calls perfetto::Tracing::NewTrace(perfetto::kInProcessBackend)
• calls Setup() (passing a file) and then StartBlocking
• the main thread then spawns N workers (std::jthread), all of which along with the main thread run the same code which can emit events
• the main thread will join with all the worker threads, which are then destroyed
• only then will the main thread call FlushBlocking (unsure if needed) before StopBlocking and then closing the file

Results are unpredictable, but so far I've seen packet loss for N >= 1, but not for N == 0.

I've experimented with various config values based on suggestions in the docs and elsewhere:

• I've bumped up the buffer size (add_buffers()->set_size_kb()) to 1GB, which from the stats is more than is being written throughout the whole trace, so there is no overflow happening there.
• Tried increasing shmem_size_hint_kb and shmem_page_size_hint_kb to various degrees.
• Experimented with file_write_period and flush_period.
• Also tried to use BufferExhaustedPolicy::kStall as noted somewhere.

Am I right in thinking that under these conditions, there's really no reason I should be seeing packet loss like this? Any suggestions as to what the cause could be, or ways to debug, would be much appreciated.

Stats from one malformed trace:

clock_sync_cache_miss | 77 | info (analysis)
guess_trace_type_duration_ns | 110163100 | info (analysis)
packet_skipped_seq_needs_incremental_state_invalid | 9715362 | info (analysis)
parse_trace_duration_ns | 7912450300 | info (analysis)
traced_buf_buffer_size[0] | 1073741824 | info (trace)
traced_buf_bytes_read[0] | 363528192 | info (trace)
traced_buf_bytes_written[0] | 363560960 | info (trace)
traced_buf_chunks_read[0] | 11094 | info (trace)
traced_buf_chunks_rewritten[0] | 35 | info (trace)
traced_buf_chunks_written[0] | 11095 | info (trace)
traced_buf_patches_succeeded[0] | 354 | info (trace)
traced_buf_readaheads_failed[0] | 25 | info (trace)
traced_buf_readaheads_succeeded[0] | 234 | info (trace)
traced_buf_sequence_packet_loss[0] | 14 | data_loss (analysis)
traced_chunks_discarded | 19 | info (trace)
traced_data_sources_registered | 1 | info (trace)
traced_data_sources_seen | 20 | info (trace)
traced_flushes_requested | 15 | info (trace)
traced_flushes_succeeded | 15 | info (trace)
traced_producers_connected | 1 | info (trace)
traced_producers_seen | 1 | info (trace)
traced_total_buffers | 1 | info (trace)
traced_tracing_sessions | 1 | info (trace)

[primiano]

can you share the full trace config used for recording?

The thing that makes more a differnce if whether you are using periodic file writing (write_into_file) or pure ring buffer.
If the former, there are some known issues with the V1 TraceBuffer

The first step I'd do is: if you are using write_into_file, what happens if you remove that, and use a pure-ring buffer? do the problems go away? if yes, that rules out 90% of the other potential problems

[kamrann]

Really appreciate the quick response. And you were right, that seems to have fixed it.
The config from my last problematic trace was:

buffers {
  size_kb: 1048576
}
data_sources {
  config {
    name: "track_event"
    buffer_exhausted_policy: BUFFER_EXHAUSTED_STALL_THEN_ABORT
    track_event_config {
      disabled_categories: "*"
      enabled_categories: "kparse.rule"
      enabled_categories: "kdeps"
      enabled_categories: "dl.compilation"
      enabled_categories: "dl.evaluation"
    }
  }
}
write_into_file: true
file_write_period_ms: 25
flush_period_ms: 50

though various values for some of those settings all had the same result. But indeed turning off write_into_file (and using ReadTraceBlocking after StopBlocking) seems to fix it; I've tried 3 multithreaded runs and they all succeeded.

buffers {
  size_kb: 1048576
}
data_sources {
  config {
    name: "track_event"
    track_event_config {
      disabled_categories: "*"
      enabled_categories: "kparse.rule"
      enabled_categories: "kdeps"
      enabled_categories: "dl.compilation"
      enabled_categories: "dl.evaluation"
    }
  }
}
flush_period_ms: 500

So if I handle this manually, is buffer_exhausted_policy still relevant? Is the idea that I just set up a callback or dedicated thread to call ReadTrace frequently enough to avoid the buffer filling up?

If there's anything you'd like me to do to get more info about whatever the problem is with write_into_file please let me know. Otherwise, thanks and feel free to close.

[primiano]

So if I handle this manually, is buffer_exhausted_policy still relevant?

No I don't that was the problem

Is the idea that I just set up a callback or dedicated thread to call ReadTrace frequently enough to avoid the buffer filling up?

Unfortunately that would create the same problem that write_into_file has.
The only solution is wait that we switch to TraceBufferV2, as that will sovle this long-standing issue.

We are in the process of evaluating it (it -> switching to TRACE_BUFFER_V2). right now is behind an experimental flag.
Once we hash out all the details it will become the new default.

Unfortunately I don't have a good solution until then

the only other thing you can try is to use perfetto --clone and create snapshots of the ring buffer.
However be aware that doing so will give you trace files that can contain duplicate events: i.e. events in the N-th snapshot can contains some late events present also in the N-1 (or even N-2) snapshot. So you can't just "stitch together" the snapshots.

[kamrann]

Ok understood. Right now I'm just using this for analysing behaviour during development, not production, so I'll look into the experimental flag, or otherwise even if I have to just use a huge buffer with a single readback it's not a major problem. I just need a way to make it reasonably reliable, as the nature of my trace is such that any dropped packet is liable to make it unusable.

Thanks again for your help!

[LalitMaganti]

To update on this issue, we're working through the edge cases around the new TraceBuffer v2 implementation - #5323 was the latest fix which went in today.

There's another edge case which @sashwinbalaji will look into fixing next week. I believe once that lands, we've addressed all the issues we've found so far. We'll stress test internally in Google and then, if everything goes well, we'll make this the default, ideally before Perfetto v55.