• Home
  • Line#
  • Scopes#
  • Navigate#
  • Raw
  • Download
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 <limits>
18 
19 #include <stdint.h>
20 
21 #include "src/trace_processor/importers/common/process_tracker.h"
22 #include "src/trace_processor/importers/common/slice_tracker.h"
23 #include "src/trace_processor/importers/common/slice_translation_table.h"
24 #include "src/trace_processor/importers/common/track_tracker.h"
25 #include "src/trace_processor/storage/trace_storage.h"
26 #include "src/trace_processor/types/trace_processor_context.h"
27 
28 namespace perfetto {
29 namespace trace_processor {
30 
SliceTracker(TraceProcessorContext * context)31 SliceTracker::SliceTracker(TraceProcessorContext* context)
32     : legacy_unnestable_begin_count_string_id_(
33           context->storage->InternString("legacy_unnestable_begin_count")),
34       legacy_unnestable_last_begin_ts_string_id_(
35           context->storage->InternString("legacy_unnestable_last_begin_ts")),
36       context_(context) {}
37 
38 SliceTracker::~SliceTracker() = default;
39 
Begin(int64_t timestamp,TrackId track_id,StringId category,StringId raw_name,SetArgsCallback args_callback)40 base::Optional<SliceId> SliceTracker::Begin(int64_t timestamp,
41                                             TrackId track_id,
42                                             StringId category,
43                                             StringId raw_name,
44                                             SetArgsCallback args_callback) {
45   const StringId name =
46       context_->slice_translation_table->TranslateName(raw_name);
47   tables::SliceTable::Row row(timestamp, kPendingDuration, track_id, category,
48                               name);
49   return StartSlice(timestamp, track_id, args_callback, [this, &row]() {
50     return context_->storage->mutable_slice_table()->Insert(row).id;
51   });
52 }
53 
BeginLegacyUnnestable(tables::SliceTable::Row row,SetArgsCallback args_callback)54 void SliceTracker::BeginLegacyUnnestable(tables::SliceTable::Row row,
55                                          SetArgsCallback args_callback) {
56   if (row.name) {
57     row.name = context_->slice_translation_table->TranslateName(*row.name);
58   }
59 
60   // Ensure that the duration is pending for this row.
61   // TODO(lalitm): change this to eventually use null instead of -1.
62   row.dur = kPendingDuration;
63 
64   // Double check that if we've seen this track in the past, it was also
65   // marked as unnestable then.
66 #if PERFETTO_DCHECK_IS_ON()
67   auto* it = stacks_.Find(row.track_id);
68   PERFETTO_DCHECK(!it || it->is_legacy_unnestable);
69 #endif
70 
71   // Ensure that StartSlice knows that this track is unnestable.
72   stacks_[row.track_id].is_legacy_unnestable = true;
73 
74   StartSlice(row.ts, row.track_id, args_callback, [this, &row]() {
75     return context_->storage->mutable_slice_table()->Insert(row).id;
76   });
77 }
78 
Scoped(int64_t timestamp,TrackId track_id,StringId category,StringId raw_name,int64_t duration,SetArgsCallback args_callback)79 base::Optional<SliceId> SliceTracker::Scoped(int64_t timestamp,
80                                              TrackId track_id,
81                                              StringId category,
82                                              StringId raw_name,
83                                              int64_t duration,
84                                              SetArgsCallback args_callback) {
85   PERFETTO_DCHECK(duration >= 0);
86 
87   const StringId name =
88       context_->slice_translation_table->TranslateName(raw_name);
89   tables::SliceTable::Row row(timestamp, duration, track_id, category, name);
90   return StartSlice(timestamp, track_id, args_callback, [this, &row]() {
91     return context_->storage->mutable_slice_table()->Insert(row).id;
92   });
93 }
94 
End(int64_t timestamp,TrackId track_id,StringId category,StringId raw_name,SetArgsCallback args_callback)95 base::Optional<SliceId> SliceTracker::End(int64_t timestamp,
96                                           TrackId track_id,
97                                           StringId category,
98                                           StringId raw_name,
99                                           SetArgsCallback args_callback) {
100   const StringId name =
101       context_->slice_translation_table->TranslateName(raw_name);
102   auto finder = [this, category, name](const SlicesStack& stack) {
103     return MatchingIncompleteSliceIndex(stack, name, category);
104   };
105   return CompleteSlice(timestamp, track_id, args_callback, finder);
106 }
107 
AddArgs(TrackId track_id,StringId category,StringId name,SetArgsCallback args_callback)108 base::Optional<uint32_t> SliceTracker::AddArgs(TrackId track_id,
109                                                StringId category,
110                                                StringId name,
111                                                SetArgsCallback args_callback) {
112   auto* it = stacks_.Find(track_id);
113   if (!it)
114     return base::nullopt;
115 
116   auto& stack = it->slice_stack;
117   if (stack.empty())
118     return base::nullopt;
119 
120   auto* slices = context_->storage->mutable_slice_table();
121   base::Optional<uint32_t> stack_idx =
122       MatchingIncompleteSliceIndex(stack, name, category);
123   if (!stack_idx.has_value())
124     return base::nullopt;
125   uint32_t slice_idx = stack[*stack_idx].row;
126   PERFETTO_DCHECK(slices->dur()[slice_idx] == kPendingDuration);
127   // Add args to current pending slice.
128   ArgsTracker* tracker = &stack[*stack_idx].args_tracker;
129   auto bound_inserter = tracker->AddArgsTo(slices->id()[slice_idx]);
130   args_callback(&bound_inserter);
131   return slice_idx;
132 }
133 
StartSlice(int64_t timestamp,TrackId track_id,SetArgsCallback args_callback,std::function<SliceId ()> inserter)134 base::Optional<SliceId> SliceTracker::StartSlice(
135     int64_t timestamp,
136     TrackId track_id,
137     SetArgsCallback args_callback,
138     std::function<SliceId()> inserter) {
139   // At this stage all events should be globally timestamp ordered.
140   if (timestamp < prev_timestamp_) {
141     context_->storage->IncrementStats(stats::slice_out_of_order);
142     return base::nullopt;
143   }
144   prev_timestamp_ = timestamp;
145 
146   auto* track_info = &stacks_[track_id];
147   auto* stack = &track_info->slice_stack;
148 
149   if (track_info->is_legacy_unnestable) {
150     PERFETTO_DCHECK(stack->size() <= 1);
151 
152     track_info->legacy_unnestable_begin_count++;
153     track_info->legacy_unnestable_last_begin_ts = timestamp;
154 
155     // If this is an unnestable track, don't start a new slice if one already
156     // exists.
157     if (!stack->empty()) {
158       return base::nullopt;
159     }
160   }
161 
162   auto* slices = context_->storage->mutable_slice_table();
163   MaybeCloseStack(timestamp, stack, track_id);
164 
165   const uint8_t depth = static_cast<uint8_t>(stack->size());
166   int64_t parent_stack_id =
167       depth == 0 ? 0 : slices->stack_id()[stack->back().row];
168   base::Optional<tables::SliceTable::Id> parent_id =
169       depth == 0 ? base::nullopt
170                  : base::make_optional(slices->id()[stack->back().row]);
171 
172   SliceId id = inserter();
173   uint32_t slice_idx = *slices->id().IndexOf(id);
174   if (depth >= std::numeric_limits<uint8_t>::max()) {
175     auto last_slice_name = slices->name().GetString(stack->back().row);
176     auto current_slice_name = slices->name().GetString(slice_idx);
177     PERFETTO_DLOG("Last slice: %s", last_slice_name.c_str());
178     PERFETTO_DLOG("Current slice: %s", current_slice_name.c_str());
179     PERFETTO_DFATAL("Slices with too large depth found.");
180     return base::nullopt;
181   }
182   StackPush(track_id, slice_idx);
183 
184   // Post fill all the relevant columns. All the other columns should have
185   // been filled by the inserter.
186   slices->mutable_depth()->Set(slice_idx, depth);
187   slices->mutable_parent_stack_id()->Set(slice_idx, parent_stack_id);
188   slices->mutable_stack_id()->Set(slice_idx, GetStackHash(*stack));
189   if (parent_id)
190     slices->mutable_parent_id()->Set(slice_idx, *parent_id);
191 
192   if (args_callback) {
193     ArgsTracker* tracker = &stack->back().args_tracker;
194     auto bound_inserter = tracker->AddArgsTo(id);
195     args_callback(&bound_inserter);
196   }
197   return id;
198 }
199 
CompleteSlice(int64_t timestamp,TrackId track_id,SetArgsCallback args_callback,std::function<base::Optional<uint32_t> (const SlicesStack &)> finder)200 base::Optional<SliceId> SliceTracker::CompleteSlice(
201     int64_t timestamp,
202     TrackId track_id,
203     SetArgsCallback args_callback,
204     std::function<base::Optional<uint32_t>(const SlicesStack&)> finder) {
205   // At this stage all events should be globally timestamp ordered.
206   if (timestamp < prev_timestamp_) {
207     context_->storage->IncrementStats(stats::slice_out_of_order);
208     return base::nullopt;
209   }
210   prev_timestamp_ = timestamp;
211 
212   auto it = stacks_.Find(track_id);
213   if (!it)
214     return base::nullopt;
215 
216   TrackInfo& track_info = *it;
217   SlicesStack& stack = track_info.slice_stack;
218   MaybeCloseStack(timestamp, &stack, track_id);
219   if (stack.empty())
220     return base::nullopt;
221 
222   auto* slices = context_->storage->mutable_slice_table();
223   base::Optional<uint32_t> stack_idx = finder(stack);
224 
225   // If we are trying to close slices that are not open on the stack (e.g.,
226   // slices that began before tracing started), bail out.
227   if (!stack_idx)
228     return base::nullopt;
229 
230   const auto& slice_info = stack[stack_idx.value()];
231   uint32_t slice_idx = slice_info.row;
232   PERFETTO_DCHECK(slices->dur()[slice_idx] == kPendingDuration);
233   slices->mutable_dur()->Set(slice_idx, timestamp - slices->ts()[slice_idx]);
234 
235   ArgsTracker* tracker = &stack[stack_idx.value()].args_tracker;
236   if (args_callback) {
237     auto bound_inserter = tracker->AddArgsTo(slices->id()[slice_idx]);
238     args_callback(&bound_inserter);
239   }
240 
241   // Add the legacy unnestable args if they exist.
242   if (track_info.is_legacy_unnestable) {
243     auto bound_inserter = tracker->AddArgsTo(slices->id()[slice_idx]);
244     bound_inserter.AddArg(
245         legacy_unnestable_begin_count_string_id_,
246         Variadic::Integer(track_info.legacy_unnestable_begin_count));
247     bound_inserter.AddArg(
248         legacy_unnestable_last_begin_ts_string_id_,
249         Variadic::Integer(track_info.legacy_unnestable_last_begin_ts));
250   }
251 
252   // If this slice is the top slice on the stack, pop it off.
253   if (*stack_idx == stack.size() - 1)
254     stack.pop_back();
255   return slices->id()[slice_idx];
256 }
257 
258 // Returns the first incomplete slice in the stack with matching name and
259 // category. We assume null category/name matches everything. Returns
260 // nullopt if no matching slice is found.
MatchingIncompleteSliceIndex(const SlicesStack & stack,StringId name,StringId category)261 base::Optional<uint32_t> SliceTracker::MatchingIncompleteSliceIndex(
262     const SlicesStack& stack,
263     StringId name,
264     StringId category) {
265   auto* slices = context_->storage->mutable_slice_table();
266   for (int i = static_cast<int>(stack.size()) - 1; i >= 0; i--) {
267     uint32_t slice_idx = stack[static_cast<size_t>(i)].row;
268     if (slices->dur()[slice_idx] != kPendingDuration)
269       continue;
270     base::Optional<StringId> other_category = slices->category()[slice_idx];
271     if (!category.is_null() && (!other_category || other_category->is_null() ||
272                                 category != other_category)) {
273       continue;
274     }
275     base::Optional<StringId> other_name = slices->name()[slice_idx];
276     if (!name.is_null() && other_name && !other_name->is_null() &&
277         name != other_name) {
278       continue;
279     }
280     return static_cast<uint32_t>(i);
281   }
282   return base::nullopt;
283 }
284 
FlushPendingSlices()285 void SliceTracker::FlushPendingSlices() {
286   // Clear the remaining stack entries. This ensures that any pending args are
287   // written to the storage. We don't close any slices with kPendingDuration so
288   // that the UI can still distinguish such "incomplete" slices.
289   //
290   // TODO(eseckler): Reconsider whether we want to close pending slices by
291   // setting their duration to |trace_end - event_start|. Might still want some
292   // additional way of flagging these events as "incomplete" to the UI.
293   stacks_.Clear();
294 }
295 
SetOnSliceBeginCallback(OnSliceBeginCallback callback)296 void SliceTracker::SetOnSliceBeginCallback(OnSliceBeginCallback callback) {
297   on_slice_begin_callback_ = callback;
298 }
299 
GetTopmostSliceOnTrack(TrackId track_id) const300 base::Optional<SliceId> SliceTracker::GetTopmostSliceOnTrack(
301     TrackId track_id) const {
302   const auto* iter = stacks_.Find(track_id);
303   if (!iter)
304     return base::nullopt;
305   const auto& stack = iter->slice_stack;
306   if (stack.empty())
307     return base::nullopt;
308   uint32_t slice_idx = stack.back().row;
309   return context_->storage->slice_table().id()[slice_idx];
310 }
311 
MaybeCloseStack(int64_t ts,SlicesStack * stack,TrackId track_id)312 void SliceTracker::MaybeCloseStack(int64_t ts,
313                                    SlicesStack* stack,
314                                    TrackId track_id) {
315   auto* slices = context_->storage->mutable_slice_table();
316   bool incomplete_descendent = false;
317   for (int i = static_cast<int>(stack->size()) - 1; i >= 0; i--) {
318     uint32_t slice_idx = (*stack)[static_cast<size_t>(i)].row;
319 
320     int64_t start_ts = slices->ts()[slice_idx];
321     int64_t dur = slices->dur()[slice_idx];
322     int64_t end_ts = start_ts + dur;
323     if (dur == kPendingDuration) {
324       incomplete_descendent = true;
325       continue;
326     }
327 
328     if (incomplete_descendent) {
329       PERFETTO_DCHECK(ts >= start_ts);
330 
331       // Only process slices if the ts is past the end of the slice.
332       if (ts <= end_ts)
333         continue;
334 
335       // This usually happens because we have two slices that are partially
336       // overlapping.
337       // [  slice  1    ]
338       //          [     slice 2     ]
339       // This is invalid in chrome and should be fixed. Duration events should
340       // either be nested or disjoint, never partially intersecting.
341       PERFETTO_DLOG(
342           "Incorrect ordering of begin/end slice events around timestamp "
343           "%" PRId64,
344           ts);
345       context_->storage->IncrementStats(stats::misplaced_end_event);
346 
347       // Every slice below this one should have a pending duration. Update
348       // of them to have the end ts of the current slice and pop them
349       // all off.
350       for (int j = static_cast<int>(stack->size()) - 1; j > i; --j) {
351         uint32_t child_idx = (*stack)[static_cast<size_t>(j)].row;
352         PERFETTO_DCHECK(slices->dur()[child_idx] == kPendingDuration);
353         slices->mutable_dur()->Set(child_idx, end_ts - slices->ts()[child_idx]);
354         StackPop(track_id);
355       }
356 
357       // Also pop the current row itself and reset the incomplete flag.
358       StackPop(track_id);
359       incomplete_descendent = false;
360 
361       continue;
362     }
363 
364     if (end_ts <= ts) {
365       StackPop(track_id);
366     }
367   }
368 }
369 
GetStackHash(const SlicesStack & stack)370 int64_t SliceTracker::GetStackHash(const SlicesStack& stack) {
371   PERFETTO_DCHECK(!stack.empty());
372 
373   const auto& slices = context_->storage->slice_table();
374 
375   base::Hash hash;
376   for (size_t i = 0; i < stack.size(); i++) {
377     uint32_t slice_idx = stack[i].row;
378     hash.Update(slices.category()[slice_idx].value_or(kNullStringId).raw_id());
379     hash.Update(slices.name()[slice_idx].value_or(kNullStringId).raw_id());
380   }
381 
382   // For clients which don't have an integer type (i.e. Javascript), returning
383   // hashes which have the top 11 bits set leads to numbers which are
384   // unrepresenatble. This means that clients cannot filter using this number as
385   // it will be meaningless when passed back to us. For this reason, make sure
386   // that the hash is always less than 2^53 - 1.
387   constexpr uint64_t kSafeBitmask = (1ull << 53) - 1;
388   return static_cast<int64_t>(hash.digest() & kSafeBitmask);
389 }
390 
StackPop(TrackId track_id)391 void SliceTracker::StackPop(TrackId track_id) {
392   stacks_[track_id].slice_stack.pop_back();
393 }
394 
StackPush(TrackId track_id,uint32_t slice_idx)395 void SliceTracker::StackPush(TrackId track_id, uint32_t slice_idx) {
396   stacks_[track_id].slice_stack.push_back(
397       SliceInfo{slice_idx, ArgsTracker(context_)});
398 
399   const auto& slices = context_->storage->slice_table();
400   if (on_slice_begin_callback_) {
401     on_slice_begin_callback_(track_id, slices.id()[slice_idx]);
402   }
403 }
404 
405 }  // namespace trace_processor
406 }  // namespace perfetto
407