Home | History | Annotate | Download | only in trace_processor 
      1 /*
      2  * Copyright (C) 2018 The Android Open Source Project
      3  *
      4  * Licensed under the Apache License, Version 2.0 (the "License");
      5  * you may not use this file except in compliance with the License.
      6  * You may obtain a copy of the License at
      7  *
      8  *      http://www.apache.org/licenses/LICENSE-2.0
      9  *
     10  * Unless required by applicable law or agreed to in writing, software
     11  * distributed under the License is distributed on an "AS IS" BASIS,
     12  * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
     13  * See the License for the specific language governing permissions and
     14  * limitations under the License.
     15  */
     16 
     17 #include "src/trace_processor/proto_trace_tokenizer.h"
     18 
     19 #include <string>
     20 
     21 #include "perfetto/base/logging.h"
     22 #include "perfetto/base/utils.h"
     23 #include "perfetto/protozero/proto_decoder.h"
     24 #include "perfetto/protozero/proto_utils.h"
     25 #include "src/trace_processor/event_tracker.h"
     26 #include "src/trace_processor/process_tracker.h"
     27 #include "src/trace_processor/stats.h"
     28 #include "src/trace_processor/trace_blob_view.h"
     29 #include "src/trace_processor/trace_sorter.h"
     30 #include "src/trace_processor/trace_storage.h"
     31 
     32 #include "perfetto/trace/ftrace/ftrace_event.pbzero.h"
     33 #include "perfetto/trace/ftrace/ftrace_event_bundle.pbzero.h"
     34 #include "perfetto/trace/interned_data/interned_data.pbzero.h"
     35 #include "perfetto/trace/trace.pbzero.h"
     36 #include "perfetto/trace/track_event/task_execution.pbzero.h"
     37 #include "perfetto/trace/track_event/thread_descriptor.pbzero.h"
     38 #include "perfetto/trace/track_event/track_event.pbzero.h"
     39 
     40 namespace perfetto {
     41 namespace trace_processor {
     42 
     43 using protozero::ProtoDecoder;
     44 using protozero::proto_utils::MakeTagLengthDelimited;
     45 using protozero::proto_utils::MakeTagVarInt;
     46 using protozero::proto_utils::ParseVarInt;
     47 
     48 namespace {
     49 
     50 template <typename MessageType>
     51 void InternMessage(TraceProcessorContext* context,
     52                    ProtoIncrementalState::PacketSequenceState* state,
     53                    TraceBlobView message) {
     54   constexpr auto kIidFieldNumber = MessageType::kIidFieldNumber;
     55 
     56   uint32_t iid = 0;
     57   auto message_start = message.data();
     58   auto message_size = message.length();
     59   protozero::ProtoDecoder decoder(message_start, message_size);
     60 
     61   auto field = decoder.FindField(kIidFieldNumber);
     62   if (PERFETTO_UNLIKELY(!field)) {
     63     PERFETTO_ELOG("Interned message without interning_id");
     64     context->storage->IncrementStats(stats::interned_data_tokenizer_errors);
     65     return;
     66   }
     67   iid = field.as_uint32();
     68 
     69   auto res = state->GetInternedDataMap<MessageType>()->emplace(
     70       iid,
     71       ProtoIncrementalState::InternedDataView<MessageType>(std::move(message)));
     72   // If a message with this ID is already interned, its data should not have
     73   // changed (this is forbidden by the InternedData proto).
     74   // TODO(eseckler): This DCHECK assumes that the message is encoded the
     75   // same way whenever it is re-emitted.
     76   PERFETTO_DCHECK(res.second ||
     77                   (res.first->second.message.length() == message_size &&
     78                    memcmp(res.first->second.message.data(), message_start,
     79                           message_size) == 0));
     80 }
     81 
     82 }  // namespace
     83 
     84 // static
     85 TraceType ProtoTraceTokenizer::GuessProtoTraceType(const uint8_t* data,
     86                                                    size_t size) {
     87   // Scan at most the first 128MB for a track event packet.
     88   constexpr size_t kMaxScanSize = 128 * 1024 * 1024;
     89   protos::pbzero::Trace::Decoder decoder(data, std::min(size, kMaxScanSize));
     90   if (!decoder.has_packet())
     91     return TraceType::kUnknownTraceType;
     92   for (auto it = decoder.packet(); it; ++it) {
     93     ProtoDecoder packet_decoder(it->data(), it->size());
     94     if (PERFETTO_UNLIKELY(packet_decoder.FindField(
     95             protos::pbzero::TracePacket::kTrackEventFieldNumber))) {
     96       return TraceType::kProtoWithTrackEventsTraceType;
     97     }
     98   }
     99   return TraceType::kProtoTraceType;
    100 }
    101 
    102 ProtoTraceTokenizer::ProtoTraceTokenizer(TraceProcessorContext* ctx)
    103     : context_(ctx) {}
    104 ProtoTraceTokenizer::~ProtoTraceTokenizer() = default;
    105 
    106 bool ProtoTraceTokenizer::Parse(std::unique_ptr<uint8_t[]> owned_buf,
    107                                 size_t size) {
    108   uint8_t* data = &owned_buf[0];
    109   if (!partial_buf_.empty()) {
    110     // It takes ~5 bytes for a proto preamble + the varint size.
    111     const size_t kHeaderBytes = 5;
    112     if (PERFETTO_UNLIKELY(partial_buf_.size() < kHeaderBytes)) {
    113       size_t missing_len = std::min(kHeaderBytes - partial_buf_.size(), size);
    114       partial_buf_.insert(partial_buf_.end(), &data[0], &data[missing_len]);
    115       if (partial_buf_.size() < kHeaderBytes)
    116         return true;
    117       data += missing_len;
    118       size -= missing_len;
    119     }
    120 
    121     // At this point we have enough data in |partial_buf_| to read at least the
    122     // field header and know the size of the next TracePacket.
    123     constexpr uint8_t kTracePacketTag =
    124         MakeTagLengthDelimited(protos::pbzero::Trace::kPacketFieldNumber);
    125     const uint8_t* pos = &partial_buf_[0];
    126     uint8_t proto_field_tag = *pos;
    127     uint64_t field_size = 0;
    128     const uint8_t* next = ParseVarInt(++pos, &*partial_buf_.end(), &field_size);
    129     bool parse_failed = next == pos;
    130     pos = next;
    131     if (proto_field_tag != kTracePacketTag || field_size == 0 || parse_failed) {
    132       PERFETTO_ELOG("Failed parsing a TracePacket from the partial buffer");
    133       return false;  // Unrecoverable error, stop parsing.
    134     }
    135 
    136     // At this point we know how big the TracePacket is.
    137     size_t hdr_size = static_cast<size_t>(pos - &partial_buf_[0]);
    138     size_t size_incl_header = static_cast<size_t>(field_size + hdr_size);
    139     PERFETTO_DCHECK(size_incl_header > partial_buf_.size());
    140 
    141     // There is a good chance that between the |partial_buf_| and the new |data|
    142     // of the current call we have enough bytes to parse a TracePacket.
    143     if (partial_buf_.size() + size >= size_incl_header) {
    144       // Create a new buffer for the whole TracePacket and copy into that:
    145       // 1) The beginning of the TracePacket (including the proto header) from
    146       //    the partial buffer.
    147       // 2) The rest of the TracePacket from the current |data| buffer (note
    148       //    that we might have consumed already a few bytes form |data| earlier
    149       //    in this function, hence we need to keep |off| into account).
    150       std::unique_ptr<uint8_t[]> buf(new uint8_t[size_incl_header]);
    151       memcpy(&buf[0], partial_buf_.data(), partial_buf_.size());
    152       // |size_missing| is the number of bytes for the rest of the TracePacket
    153       // in |data|.
    154       size_t size_missing = size_incl_header - partial_buf_.size();
    155       memcpy(&buf[partial_buf_.size()], &data[0], size_missing);
    156       data += size_missing;
    157       size -= size_missing;
    158       partial_buf_.clear();
    159       uint8_t* buf_start = &buf[0];  // Note that buf is std::moved below.
    160       ParseInternal(std::move(buf), buf_start, size_incl_header);
    161     } else {
    162       partial_buf_.insert(partial_buf_.end(), data, &data[size]);
    163       return true;
    164     }
    165   }
    166   ParseInternal(std::move(owned_buf), data, size);
    167   return true;
    168 }
    169 
    170 void ProtoTraceTokenizer::ParseInternal(std::unique_ptr<uint8_t[]> owned_buf,
    171                                         uint8_t* data,
    172                                         size_t size) {
    173   PERFETTO_DCHECK(data >= &owned_buf[0]);
    174   const uint8_t* start = &owned_buf[0];
    175   const size_t data_off = static_cast<size_t>(data - start);
    176   TraceBlobView whole_buf(std::move(owned_buf), data_off, size);
    177 
    178   protos::pbzero::Trace::Decoder decoder(data, size);
    179   for (auto it = decoder.packet(); it; ++it) {
    180     size_t field_offset = whole_buf.offset_of(it->data());
    181     ParsePacket(whole_buf.slice(field_offset, it->size()));
    182   }
    183 
    184   const size_t bytes_left = decoder.bytes_left();
    185   if (bytes_left > 0) {
    186     PERFETTO_DCHECK(partial_buf_.empty());
    187     partial_buf_.insert(partial_buf_.end(), &data[decoder.read_offset()],
    188                         &data[decoder.read_offset() + bytes_left]);
    189   }
    190 }
    191 
    192 void ProtoTraceTokenizer::ParsePacket(TraceBlobView packet) {
    193   protos::pbzero::TracePacket::Decoder decoder(packet.data(), packet.length());
    194   PERFETTO_DCHECK(!decoder.bytes_left());
    195 
    196   auto timestamp = decoder.has_timestamp()
    197                        ? static_cast<int64_t>(decoder.timestamp())
    198                        : latest_timestamp_;
    199   latest_timestamp_ = std::max(timestamp, latest_timestamp_);
    200 
    201   if (decoder.incremental_state_cleared()) {
    202     HandleIncrementalStateCleared(decoder);
    203   } else if (decoder.previous_packet_dropped()) {
    204     HandlePreviousPacketDropped(decoder);
    205   }
    206 
    207   if (decoder.has_interned_data()) {
    208     auto field = decoder.interned_data();
    209     const size_t offset = packet.offset_of(field.data);
    210     ParseInternedData(decoder, packet.slice(offset, field.size));
    211   }
    212 
    213   if (decoder.has_ftrace_events()) {
    214     auto ftrace_field = decoder.ftrace_events();
    215     const size_t fld_off = packet.offset_of(ftrace_field.data);
    216     ParseFtraceBundle(packet.slice(fld_off, ftrace_field.size));
    217     return;
    218   }
    219 
    220   if (decoder.has_track_event()) {
    221     ParseTrackEventPacket(decoder, std::move(packet));
    222     return;
    223   }
    224 
    225   if (decoder.has_thread_descriptor()) {
    226     ParseThreadDescriptorPacket(decoder);
    227     return;
    228   }
    229 
    230   // Use parent data and length because we want to parse this again
    231   // later to get the exact type of the packet.
    232   context_->sorter->PushTracePacket(timestamp, std::move(packet));
    233 }
    234 
    235 void ProtoTraceTokenizer::HandleIncrementalStateCleared(
    236     const protos::pbzero::TracePacket::Decoder& packet_decoder) {
    237   if (PERFETTO_UNLIKELY(!packet_decoder.has_trusted_packet_sequence_id())) {
    238     PERFETTO_ELOG(
    239         "incremental_state_cleared without trusted_packet_sequence_id");
    240     context_->storage->IncrementStats(stats::interned_data_tokenizer_errors);
    241     return;
    242   }
    243   GetIncrementalStateForPacketSequence(
    244       packet_decoder.trusted_packet_sequence_id())
    245       ->OnIncrementalStateCleared();
    246 }
    247 
    248 void ProtoTraceTokenizer::HandlePreviousPacketDropped(
    249     const protos::pbzero::TracePacket::Decoder& packet_decoder) {
    250   if (PERFETTO_UNLIKELY(!packet_decoder.has_trusted_packet_sequence_id())) {
    251     PERFETTO_ELOG("previous_packet_dropped without trusted_packet_sequence_id");
    252     context_->storage->IncrementStats(stats::interned_data_tokenizer_errors);
    253     return;
    254   }
    255   GetIncrementalStateForPacketSequence(
    256       packet_decoder.trusted_packet_sequence_id())
    257       ->OnPacketLoss();
    258 }
    259 
    260 void ProtoTraceTokenizer::ParseInternedData(
    261     const protos::pbzero::TracePacket::Decoder& packet_decoder,
    262     TraceBlobView interned_data) {
    263   if (PERFETTO_UNLIKELY(!packet_decoder.has_trusted_packet_sequence_id())) {
    264     PERFETTO_ELOG("InternedData packet without trusted_packet_sequence_id");
    265     context_->storage->IncrementStats(stats::interned_data_tokenizer_errors);
    266     return;
    267   }
    268 
    269   auto* state = GetIncrementalStateForPacketSequence(
    270       packet_decoder.trusted_packet_sequence_id());
    271 
    272   protos::pbzero::InternedData::Decoder interned_data_decoder(
    273       interned_data.data(), interned_data.length());
    274 
    275   // Store references to interned data submessages into the sequence's state.
    276   for (auto it = interned_data_decoder.event_categories(); it; ++it) {
    277     size_t offset = interned_data.offset_of(it->data());
    278     InternMessage<protos::pbzero::EventCategory>(
    279         context_, state, interned_data.slice(offset, it->size()));
    280   }
    281 
    282   for (auto it = interned_data_decoder.legacy_event_names(); it; ++it) {
    283     size_t offset = interned_data.offset_of(it->data());
    284     InternMessage<protos::pbzero::LegacyEventName>(
    285         context_, state, interned_data.slice(offset, it->size()));
    286   }
    287 
    288   for (auto it = interned_data_decoder.debug_annotation_names(); it; ++it) {
    289     size_t offset = interned_data.offset_of(it->data());
    290     InternMessage<protos::pbzero::DebugAnnotationName>(
    291         context_, state, interned_data.slice(offset, it->size()));
    292   }
    293 
    294   for (auto it = interned_data_decoder.source_locations(); it; ++it) {
    295     size_t offset = interned_data.offset_of(it->data());
    296     InternMessage<protos::pbzero::SourceLocation>(
    297         context_, state, interned_data.slice(offset, it->size()));
    298   }
    299 }
    300 
    301 void ProtoTraceTokenizer::ParseThreadDescriptorPacket(
    302     const protos::pbzero::TracePacket::Decoder& packet_decoder) {
    303   if (PERFETTO_UNLIKELY(!packet_decoder.has_trusted_packet_sequence_id())) {
    304     PERFETTO_ELOG("ThreadDescriptor packet without trusted_packet_sequence_id");
    305     context_->storage->IncrementStats(stats::track_event_tokenizer_errors);
    306     return;
    307   }
    308 
    309   auto* state = GetIncrementalStateForPacketSequence(
    310       packet_decoder.trusted_packet_sequence_id());
    311 
    312   // TrackEvents will be ignored while incremental state is invalid. As a
    313   // consequence, we should also ignore any ThreadDescriptors received in this
    314   // state. Otherwise, any delta-encoded timestamps would be calculated
    315   // incorrectly once we move out of the packet loss state. Instead, wait until
    316   // the first subsequent descriptor after incremental state is cleared.
    317   if (!state->IsIncrementalStateValid()) {
    318     context_->storage->IncrementStats(
    319         stats::track_event_tokenizer_skipped_packets);
    320     return;
    321   }
    322 
    323   auto thread_descriptor_field = packet_decoder.thread_descriptor();
    324   protos::pbzero::ThreadDescriptor::Decoder thread_descriptor_decoder(
    325       thread_descriptor_field.data, thread_descriptor_field.size);
    326 
    327   state->SetThreadDescriptor(
    328       thread_descriptor_decoder.pid(), thread_descriptor_decoder.tid(),
    329       thread_descriptor_decoder.reference_timestamp_us() * 1000,
    330       thread_descriptor_decoder.reference_thread_time_us() * 1000);
    331   // TODO(eseckler): Handle other thread_descriptor fields (e.g. thread
    332   // name/type).
    333 }
    334 
    335 void ProtoTraceTokenizer::ParseTrackEventPacket(
    336     const protos::pbzero::TracePacket::Decoder& packet_decoder,
    337     TraceBlobView packet) {
    338   constexpr auto kTimestampDeltaUsFieldNumber =
    339       protos::pbzero::TrackEvent::kTimestampDeltaUsFieldNumber;
    340   constexpr auto kTimestampAbsoluteUsFieldNumber =
    341       protos::pbzero::TrackEvent::kTimestampAbsoluteUsFieldNumber;
    342   constexpr auto kThreadTimeDeltaUsFieldNumber =
    343       protos::pbzero::TrackEvent::kThreadTimeDeltaUsFieldNumber;
    344   constexpr auto kThreadTimeAbsoluteUsFieldNumber =
    345       protos::pbzero::TrackEvent::kThreadTimeAbsoluteUsFieldNumber;
    346 
    347   if (PERFETTO_UNLIKELY(!packet_decoder.has_trusted_packet_sequence_id())) {
    348     PERFETTO_ELOG("TrackEvent packet without trusted_packet_sequence_id");
    349     context_->storage->IncrementStats(stats::track_event_tokenizer_errors);
    350     return;
    351   }
    352 
    353   auto* state = GetIncrementalStateForPacketSequence(
    354       packet_decoder.trusted_packet_sequence_id());
    355 
    356   // TrackEvents can only be parsed correctly while incremental state for their
    357   // sequence is valid and after a ThreadDescriptor has been parsed.
    358   if (!state->IsTrackEventStateValid()) {
    359     context_->storage->IncrementStats(
    360         stats::track_event_tokenizer_skipped_packets);
    361     return;
    362   }
    363 
    364   auto field = packet_decoder.track_event();
    365   ProtoDecoder event_decoder(field.data, field.size);
    366 
    367   int64_t timestamp;
    368   int64_t thread_timestamp = 0;
    369 
    370   if (auto ts_delta_field =
    371           event_decoder.FindField(kTimestampDeltaUsFieldNumber)) {
    372     timestamp = state->IncrementAndGetTrackEventTimeNs(
    373         ts_delta_field.as_int64() * 1000);
    374   } else if (auto ts_absolute_field =
    375                  event_decoder.FindField(kTimestampAbsoluteUsFieldNumber)) {
    376     // One-off absolute timestamps don't affect delta computation.
    377     timestamp = ts_absolute_field.as_int64() * 1000;
    378   } else {
    379     PERFETTO_ELOG("TrackEvent without timestamp");
    380     context_->storage->IncrementStats(stats::track_event_tokenizer_errors);
    381     return;
    382   }
    383 
    384   if (auto tt_delta_field =
    385           event_decoder.FindField(kThreadTimeDeltaUsFieldNumber)) {
    386     thread_timestamp = state->IncrementAndGetTrackEventThreadTimeNs(
    387         tt_delta_field.as_int64() * 1000);
    388   } else if (auto tt_absolute_field =
    389                  event_decoder.FindField(kThreadTimeAbsoluteUsFieldNumber)) {
    390     // One-off absolute timestamps don't affect delta computation.
    391     thread_timestamp = tt_absolute_field.as_int64() * 1000;
    392   }
    393 
    394   context_->sorter->PushTrackEventPacket(timestamp, thread_timestamp, state,
    395                                          std::move(packet));
    396 }
    397 
    398 PERFETTO_ALWAYS_INLINE
    399 void ProtoTraceTokenizer::ParseFtraceBundle(TraceBlobView bundle) {
    400   protos::pbzero::FtraceEventBundle::Decoder decoder(bundle.data(),
    401                                                      bundle.length());
    402 
    403   if (PERFETTO_UNLIKELY(!decoder.has_cpu())) {
    404     PERFETTO_ELOG("CPU field not found in FtraceEventBundle");
    405     context_->storage->IncrementStats(stats::ftrace_bundle_tokenizer_errors);
    406     return;
    407   }
    408 
    409   uint32_t cpu = decoder.cpu();
    410   if (PERFETTO_UNLIKELY(cpu > base::kMaxCpus)) {
    411     PERFETTO_ELOG("CPU larger than kMaxCpus (%u > %zu)", cpu, base::kMaxCpus);
    412     return;
    413   }
    414 
    415   for (auto it = decoder.event(); it; ++it) {
    416     size_t off = bundle.offset_of(it->data());
    417     ParseFtraceEvent(cpu, bundle.slice(off, it->size()));
    418   }
    419   context_->sorter->FinalizeFtraceEventBatch(cpu);
    420 }
    421 
    422 PERFETTO_ALWAYS_INLINE
    423 void ProtoTraceTokenizer::ParseFtraceEvent(uint32_t cpu, TraceBlobView event) {
    424   constexpr auto kTimestampFieldNumber =
    425       protos::pbzero::FtraceEvent::kTimestampFieldNumber;
    426   const uint8_t* data = event.data();
    427   const size_t length = event.length();
    428   ProtoDecoder decoder(data, length);
    429   uint64_t raw_timestamp = 0;
    430   bool timestamp_found = false;
    431 
    432   // Speculate on the fact that the timestamp is often the 1st field of the
    433   // event.
    434   constexpr auto timestampFieldTag = MakeTagVarInt(kTimestampFieldNumber);
    435   if (PERFETTO_LIKELY(length > 10 && data[0] == timestampFieldTag)) {
    436     // Fastpath.
    437     const uint8_t* next = ParseVarInt(data + 1, data + 11, &raw_timestamp);
    438     timestamp_found = next != data + 1;
    439     decoder.Reset(next);
    440   } else {
    441     // Slowpath.
    442     if (auto ts_field = decoder.FindField(kTimestampFieldNumber)) {
    443       timestamp_found = true;
    444       raw_timestamp = ts_field.as_uint64();
    445     }
    446   }
    447 
    448   if (PERFETTO_UNLIKELY(!timestamp_found)) {
    449     PERFETTO_ELOG("Timestamp field not found in FtraceEvent");
    450     context_->storage->IncrementStats(stats::ftrace_bundle_tokenizer_errors);
    451     return;
    452   }
    453 
    454   int64_t timestamp = static_cast<int64_t>(raw_timestamp);
    455   latest_timestamp_ = std::max(timestamp, latest_timestamp_);
    456 
    457   // We don't need to parse this packet, just push it to be sorted with
    458   // the timestamp.
    459   context_->sorter->PushFtraceEvent(cpu, timestamp, std::move(event));
    460 }
    461 
    462 }  // namespace trace_processor
    463 }  // namespace perfetto
    464