1 /*
2  * Copyright (C) 2020 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/importers/proto/profile_module.h"
18 
19 #include "perfetto/base/logging.h"
20 #include "src/trace_processor/importers/common/clock_tracker.h"
21 #include "src/trace_processor/importers/common/event_tracker.h"
22 #include "src/trace_processor/importers/common/process_tracker.h"
23 #include "src/trace_processor/importers/proto/packet_sequence_state.h"
24 #include "src/trace_processor/importers/proto/perf_sample_tracker.h"
25 #include "src/trace_processor/importers/proto/profile_packet_utils.h"
26 #include "src/trace_processor/importers/proto/stack_profile_tracker.h"
27 #include "src/trace_processor/storage/trace_storage.h"
28 #include "src/trace_processor/tables/profiler_tables.h"
29 #include "src/trace_processor/timestamped_trace_piece.h"
30 #include "src/trace_processor/trace_sorter.h"
31 #include "src/trace_processor/types/trace_processor_context.h"
32 
33 #include "protos/perfetto/common/builtin_clock.pbzero.h"
34 #include "protos/perfetto/common/perf_events.pbzero.h"
35 #include "protos/perfetto/trace/profiling/profile_packet.pbzero.h"
36 
37 namespace perfetto {
38 namespace trace_processor {
39 
40 using perfetto::protos::pbzero::TracePacket;
41 using protozero::ConstBytes;
42 
ProfileModule(TraceProcessorContext * context)43 ProfileModule::ProfileModule(TraceProcessorContext* context)
44     : context_(context) {
45   RegisterForField(TracePacket::kStreamingProfilePacketFieldNumber, context);
46   RegisterForField(TracePacket::kPerfSampleFieldNumber, context);
47 }
48 
49 ProfileModule::~ProfileModule() = default;
50 
TokenizePacket(const TracePacket::Decoder & decoder,TraceBlobView * packet,int64_t,PacketSequenceState * state,uint32_t field_id)51 ModuleResult ProfileModule::TokenizePacket(const TracePacket::Decoder& decoder,
52                                            TraceBlobView* packet,
53                                            int64_t /*packet_timestamp*/,
54                                            PacketSequenceState* state,
55                                            uint32_t field_id) {
56   switch (field_id) {
57     case TracePacket::kStreamingProfilePacketFieldNumber:
58       return TokenizeStreamingProfilePacket(state, packet,
59                                             decoder.streaming_profile_packet());
60   }
61   return ModuleResult::Ignored();
62 }
63 
ParsePacket(const TracePacket::Decoder & decoder,const TimestampedTracePiece & ttp,uint32_t field_id)64 void ProfileModule::ParsePacket(const TracePacket::Decoder& decoder,
65                                 const TimestampedTracePiece& ttp,
66                                 uint32_t field_id) {
67   switch (field_id) {
68     case TracePacket::kStreamingProfilePacketFieldNumber:
69       PERFETTO_DCHECK(ttp.type == TimestampedTracePiece::Type::kTracePacket);
70       ParseStreamingProfilePacket(ttp.timestamp,
71                                   ttp.packet_data.sequence_state.get(),
72                                   decoder.streaming_profile_packet());
73       return;
74     case TracePacket::kPerfSampleFieldNumber:
75       PERFETTO_DCHECK(ttp.type == TimestampedTracePiece::Type::kTracePacket);
76       ParsePerfSample(ttp.timestamp, ttp.packet_data.sequence_state.get(),
77                       decoder);
78       return;
79   }
80 }
81 
TokenizeStreamingProfilePacket(PacketSequenceState * sequence_state,TraceBlobView * packet,ConstBytes streaming_profile_packet)82 ModuleResult ProfileModule::TokenizeStreamingProfilePacket(
83     PacketSequenceState* sequence_state,
84     TraceBlobView* packet,
85     ConstBytes streaming_profile_packet) {
86   protos::pbzero::StreamingProfilePacket::Decoder decoder(
87       streaming_profile_packet.data, streaming_profile_packet.size);
88 
89   // We have to resolve the reference timestamp of a StreamingProfilePacket
90   // during tokenization. If we did this during parsing instead, the
91   // tokenization of a subsequent ThreadDescriptor with a new reference
92   // timestamp would cause us to later calculate timestamps based on the wrong
93   // reference value during parsing. Since StreamingProfilePackets only need to
94   // be sorted correctly with respect to process/thread metadata events (so that
95   // pid/tid are resolved correctly during parsing), we forward the packet as a
96   // whole through the sorter, using the "root" timestamp of the packet, i.e.
97   // the current timestamp of the packet sequence.
98   auto packet_ts =
99       sequence_state->IncrementAndGetTrackEventTimeNs(/*delta_ns=*/0);
100   auto trace_ts = context_->clock_tracker->ToTraceTime(
101       protos::pbzero::BUILTIN_CLOCK_MONOTONIC, packet_ts);
102   if (trace_ts)
103     packet_ts = *trace_ts;
104 
105   // Increment the sequence's timestamp by all deltas.
106   for (auto timestamp_it = decoder.timestamp_delta_us(); timestamp_it;
107        ++timestamp_it) {
108     sequence_state->IncrementAndGetTrackEventTimeNs(*timestamp_it * 1000);
109   }
110 
111   context_->sorter->PushTracePacket(packet_ts, sequence_state,
112                                     std::move(*packet));
113   return ModuleResult::Handled();
114 }
115 
ParseStreamingProfilePacket(int64_t timestamp,PacketSequenceStateGeneration * sequence_state,ConstBytes streaming_profile_packet)116 void ProfileModule::ParseStreamingProfilePacket(
117     int64_t timestamp,
118     PacketSequenceStateGeneration* sequence_state,
119     ConstBytes streaming_profile_packet) {
120   protos::pbzero::StreamingProfilePacket::Decoder packet(
121       streaming_profile_packet.data, streaming_profile_packet.size);
122 
123   ProcessTracker* procs = context_->process_tracker.get();
124   TraceStorage* storage = context_->storage.get();
125   SequenceStackProfileTracker& sequence_stack_profile_tracker =
126       sequence_state->state()->sequence_stack_profile_tracker();
127   ProfilePacketInternLookup intern_lookup(sequence_state);
128 
129   uint32_t pid = static_cast<uint32_t>(sequence_state->state()->pid());
130   uint32_t tid = static_cast<uint32_t>(sequence_state->state()->tid());
131   UniqueTid utid = procs->UpdateThread(tid, pid);
132 
133   // Iterate through timestamps and callstacks simultaneously.
134   auto timestamp_it = packet.timestamp_delta_us();
135   for (auto callstack_it = packet.callstack_iid(); callstack_it;
136        ++callstack_it, ++timestamp_it) {
137     if (!timestamp_it) {
138       context_->storage->IncrementStats(stats::stackprofile_parser_error);
139       PERFETTO_ELOG(
140           "StreamingProfilePacket has less callstack IDs than timestamps!");
141       break;
142     }
143 
144     auto opt_cs_id = sequence_stack_profile_tracker.FindOrInsertCallstack(
145         *callstack_it, &intern_lookup);
146     if (!opt_cs_id) {
147       context_->storage->IncrementStats(stats::stackprofile_parser_error);
148       continue;
149     }
150 
151     // Resolve the delta timestamps based on the packet's root timestamp.
152     timestamp += *timestamp_it * 1000;
153 
154     tables::CpuProfileStackSampleTable::Row sample_row{
155         timestamp, *opt_cs_id, utid, packet.process_priority()};
156     storage->mutable_cpu_profile_stack_sample_table()->Insert(sample_row);
157   }
158 }
159 
ParsePerfSample(int64_t ts,PacketSequenceStateGeneration * sequence_state,const TracePacket::Decoder & decoder)160 void ProfileModule::ParsePerfSample(
161     int64_t ts,
162     PacketSequenceStateGeneration* sequence_state,
163     const TracePacket::Decoder& decoder) {
164   using PerfSample = protos::pbzero::PerfSample;
165   const auto& sample_raw = decoder.perf_sample();
166   PerfSample::Decoder sample(sample_raw.data, sample_raw.size);
167 
168   uint32_t seq_id = decoder.trusted_packet_sequence_id();
169   PerfSampleTracker::SamplingStreamInfo sampling_stream =
170       context_->perf_sample_tracker->GetSamplingStreamInfo(
171           seq_id, sample.cpu(), sequence_state->GetTracePacketDefaults());
172 
173   // Not a sample, but an indication of data loss in the ring buffer shared with
174   // the kernel.
175   if (sample.kernel_records_lost() > 0) {
176     PERFETTO_DCHECK(sample.pid() == 0);
177 
178     context_->storage->IncrementIndexedStats(
179         stats::perf_cpu_lost_records, static_cast<int>(sample.cpu()),
180         static_cast<int64_t>(sample.kernel_records_lost()));
181     return;
182   }
183 
184   // Sample that looked relevant for the tracing session, but had to be skipped.
185   // Either we failed to look up the procfs file descriptors necessary for
186   // remote stack unwinding (not unexpected in most cases), or the unwind queue
187   // was out of capacity (producer lost data on its own).
188   if (sample.has_sample_skipped_reason()) {
189     context_->storage->IncrementStats(stats::perf_samples_skipped);
190 
191     if (sample.sample_skipped_reason() ==
192         PerfSample::PROFILER_SKIP_UNWIND_ENQUEUE)
193       context_->storage->IncrementStats(stats::perf_samples_skipped_dataloss);
194 
195     return;
196   }
197 
198   // Not a sample, but an event from the producer.
199   // TODO(rsavitski): this stat is indexed by the session id, but the older
200   // stats (see above) aren't. The indexing is relevant if a trace contains more
201   // than one profiling data source. So the older stats should be changed to
202   // being indexed as well.
203   if (sample.has_producer_event()) {
204     PerfSample::ProducerEvent::Decoder producer_event(sample.producer_event());
205     if (producer_event.source_stop_reason() ==
206         PerfSample::ProducerEvent::PROFILER_STOP_GUARDRAIL) {
207       context_->storage->SetIndexedStats(
208           stats::perf_guardrail_stop_ts,
209           static_cast<int>(sampling_stream.perf_session_id), ts);
210     }
211     return;
212   }
213 
214   // Proper sample, populate the |perf_sample| table with everything except the
215   // recorded counter values, which go to |counter|.
216   context_->event_tracker->PushCounter(
217       ts, static_cast<double>(sample.timebase_count()),
218       sampling_stream.timebase_track_id);
219 
220   // TODO(rsavitski): empty callsite is not an error for counter-only samples.
221   // But consider identifying sequences which *should* have a callstack in every
222   // sample, as an invalid stack there is a bug.
223   SequenceStackProfileTracker& stack_tracker =
224       sequence_state->state()->sequence_stack_profile_tracker();
225   ProfilePacketInternLookup intern_lookup(sequence_state);
226   uint64_t callstack_iid = sample.callstack_iid();
227   base::Optional<CallsiteId> cs_id =
228       stack_tracker.FindOrInsertCallstack(callstack_iid, &intern_lookup);
229 
230   UniqueTid utid =
231       context_->process_tracker->UpdateThread(sample.tid(), sample.pid());
232 
233   using protos::pbzero::Profiling;
234   TraceStorage* storage = context_->storage.get();
235 
236   auto cpu_mode = static_cast<Profiling::CpuMode>(sample.cpu_mode());
237   StringPool::Id cpu_mode_id =
238       storage->InternString(ProfilePacketUtils::StringifyCpuMode(cpu_mode));
239 
240   base::Optional<StringPool::Id> unwind_error_id;
241   if (sample.has_unwind_error()) {
242     auto unwind_error =
243         static_cast<Profiling::StackUnwindError>(sample.unwind_error());
244     unwind_error_id = storage->InternString(
245         ProfilePacketUtils::StringifyStackUnwindError(unwind_error));
246   }
247   tables::PerfSampleTable::Row sample_row(ts, utid, sample.cpu(), cpu_mode_id,
248                                           cs_id, unwind_error_id,
249                                           sampling_stream.perf_session_id);
250   context_->storage->mutable_perf_sample_table()->Insert(sample_row);
251 }
252 
253 }  // namespace trace_processor
254 }  // namespace perfetto
255