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