trace_processor: fix ordering of slices in trace storage
Slices are meant to be stored ordered by timestamp. However, because we
were waiting until the end event to push the slice to storage, each
stack would actually be stored in *reverse* timestamp order.
Fix this issue by pushing the slice to storage as soon as we see the
start event and then updating duration after the fact. This works
similarily to sched events.
Change-Id: If89ff8f4fde91917b090f1013efafd0f3d9d997d
diff --git a/src/trace_processor/slice_tracker.cc b/src/trace_processor/slice_tracker.cc
index 45e6c17..a2e9a8e 100644
--- a/src/trace_processor/slice_tracker.cc
+++ b/src/trace_processor/slice_tracker.cc
@@ -46,9 +46,8 @@
UniqueTid utid,
StringId cat,
StringId name) {
- auto& stack = threads_[utid];
- MaybeCloseStack(timestamp, stack);
- stack.emplace_back(Slice{cat, name, timestamp, 0});
+ MaybeCloseStack(timestamp, &threads_[utid]);
+ StartSlice(timestamp, 0, utid, cat, name);
}
void SliceTracker::Scoped(uint64_t timestamp,
@@ -56,12 +55,32 @@
StringId cat,
StringId name,
uint64_t duration) {
- auto& stack = threads_[utid];
- MaybeCloseStack(timestamp, stack);
- stack.emplace_back(Slice{cat, name, timestamp, timestamp + duration});
+ MaybeCloseStack(timestamp, &threads_[utid]);
+ StartSlice(timestamp, duration, utid, cat, name);
CompleteSlice(utid);
}
+void SliceTracker::StartSlice(uint64_t timestamp,
+ uint64_t duration,
+ UniqueTid utid,
+ StringId cat,
+ StringId name) {
+ auto* stack = &threads_[utid];
+ auto* slices = context_->storage->mutable_nestable_slices();
+
+ const uint8_t depth = static_cast<uint8_t>(stack->size());
+ if (depth >= std::numeric_limits<uint8_t>::max()) {
+ PERFETTO_DFATAL("Slices with too large depth found.");
+ return;
+ }
+ uint64_t parent_stack_id = depth == 0 ? 0 : slices->stack_ids().back();
+ size_t slice_idx = slices->AddSlice(timestamp, duration, utid, cat, name,
+ depth, 0, parent_stack_id);
+ stack->emplace_back(slice_idx);
+
+ slices->set_stack_id(slice_idx, GetStackHash(*stack));
+}
+
void SliceTracker::EndAndroid(uint64_t timestamp,
uint32_t ftrace_tid,
uint32_t atrace_tid) {
@@ -81,82 +100,69 @@
UniqueTid utid,
StringId cat,
StringId name) {
- auto& stack = threads_[utid];
- MaybeCloseStack(timestamp, stack);
- if (stack.empty()) {
+ MaybeCloseStack(timestamp, &threads_[utid]);
+
+ const auto& stack = threads_[utid];
+ if (stack.empty())
return;
- }
- PERFETTO_CHECK(cat == 0 || stack.back().cat_id == cat);
- PERFETTO_CHECK(name == 0 || stack.back().name_id == name);
+ auto* slices = context_->storage->mutable_nestable_slices();
+ size_t slice_idx = stack.back();
- Slice& slice = stack.back();
- slice.end_ts = timestamp;
+ PERFETTO_CHECK(cat == 0 || slices->cats()[slice_idx] == cat);
+ PERFETTO_CHECK(name == 0 || slices->names()[slice_idx] == name);
+
+ slices->set_duration(slice_idx, timestamp - slices->start_ns()[slice_idx]);
CompleteSlice(utid);
// TODO(primiano): auto-close B slices left open at the end.
}
void SliceTracker::CompleteSlice(UniqueTid utid) {
- auto& stack = threads_[utid];
- if (stack.size() >= std::numeric_limits<uint8_t>::max()) {
- stack.pop_back();
- return;
- }
- const uint8_t depth = static_cast<uint8_t>(stack.size()) - 1;
-
- uint64_t parent_stack_id, stack_id;
- std::tie(parent_stack_id, stack_id) = GetStackHashes(stack);
-
- Slice& slice = stack.back();
- auto* slices = context_->storage->mutable_nestable_slices();
- slices->AddSlice(slice.start_ts, slice.end_ts - slice.start_ts, utid,
- slice.cat_id, slice.name_id, depth, stack_id,
- parent_stack_id);
-
- stack.pop_back();
+ threads_[utid].pop_back();
}
-void SliceTracker::MaybeCloseStack(uint64_t ts, SlicesStack& stack) {
+void SliceTracker::MaybeCloseStack(uint64_t ts, SlicesStack* stack) {
+ const auto& slices = context_->storage->nestable_slices();
bool check_only = false;
- for (int i = static_cast<int>(stack.size()) - 1; i >= 0; i--) {
- const Slice& slice = stack[size_t(i)];
- if (slice.end_ts == 0) {
+ for (int i = static_cast<int>(stack->size()) - 1; i >= 0; i--) {
+ size_t slice_idx = (*stack)[static_cast<size_t>(i)];
+
+ uint64_t start_ts = slices.start_ns()[slice_idx];
+ uint64_t dur = slices.durations()[slice_idx];
+ uint64_t end_ts = start_ts + dur;
+ if (dur == 0) {
check_only = true;
}
if (check_only) {
- PERFETTO_DCHECK(ts >= slice.start_ts);
- PERFETTO_DCHECK(slice.end_ts == 0 || ts <= slice.end_ts);
+ PERFETTO_DCHECK(ts >= start_ts);
+ PERFETTO_DCHECK(dur == 0 || ts <= end_ts);
continue;
}
- if (slice.end_ts <= ts) {
- stack.pop_back();
+ if (end_ts <= ts) {
+ stack->pop_back();
}
}
}
-// Returns <parent_stack_id, stack_id>, where
-// |parent_stack_id| == hash(stack_id - last slice).
-std::tuple<uint64_t, uint64_t> SliceTracker::GetStackHashes(
- const SlicesStack& stack) {
+uint64_t SliceTracker::GetStackHash(const SlicesStack& stack) {
PERFETTO_DCHECK(!stack.empty());
+
+ const auto& slices = context_->storage->nestable_slices();
+
std::string s;
s.reserve(stack.size() * sizeof(uint64_t) * 2);
- constexpr uint64_t kMask = uint64_t(-1) >> 1;
- uint64_t parent_stack_id = 0;
for (size_t i = 0; i < stack.size(); i++) {
- if (i == stack.size() - 1)
- parent_stack_id = i > 0 ? (std::hash<std::string>{}(s)) & kMask : 0;
- const Slice& slice = stack[i];
- s.append(reinterpret_cast<const char*>(&slice.cat_id),
- sizeof(slice.cat_id));
- s.append(reinterpret_cast<const char*>(&slice.name_id),
- sizeof(slice.name_id));
+ size_t slice_idx = stack[i];
+ s.append(reinterpret_cast<const char*>(&slices.cats()[slice_idx]),
+ sizeof(slices.cats()[slice_idx]));
+ s.append(reinterpret_cast<const char*>(&slices.names()[slice_idx]),
+ sizeof(slices.names()[slice_idx]));
}
- uint64_t stack_id = (std::hash<std::string>{}(s)) & kMask;
- return std::make_tuple(parent_stack_id, stack_id);
+ constexpr uint64_t kMask = uint64_t(-1) >> 1;
+ return (std::hash<std::string>{}(s)) & kMask;
}
} // namespace trace_processor
diff --git a/src/trace_processor/slice_tracker.h b/src/trace_processor/slice_tracker.h
index 1c08d6b..cfed40c 100644
--- a/src/trace_processor/slice_tracker.h
+++ b/src/trace_processor/slice_tracker.h
@@ -53,19 +53,18 @@
StringId opt_name = {});
private:
- struct Slice {
- StringId cat_id;
- StringId name_id;
- uint64_t start_ts;
- uint64_t end_ts; // Only for complete events (scoped TRACE_EVENT macros).
- };
- using SlicesStack = std::vector<Slice>;
+ using SlicesStack = std::vector<size_t>;
- static inline void MaybeCloseStack(uint64_t end_ts, SlicesStack&);
- static inline std::tuple<uint64_t, uint64_t> GetStackHashes(
- const SlicesStack&);
+ void StartSlice(uint64_t timestamp,
+ uint64_t duration,
+ UniqueTid utid,
+ StringId cat,
+ StringId name);
void CompleteSlice(UniqueTid tid);
+ void MaybeCloseStack(uint64_t end_ts, SlicesStack*);
+ uint64_t GetStackHash(const SlicesStack&);
+
TraceProcessorContext* const context_;
std::unordered_map<UniqueTid, SlicesStack> threads_;
std::unordered_map<uint32_t, uint32_t> ftrace_to_atrace_pid_;
diff --git a/src/trace_processor/slice_tracker_unittest.cc b/src/trace_processor/slice_tracker_unittest.cc
index 8eb72b9..bd5ca2e 100644
--- a/src/trace_processor/slice_tracker_unittest.cc
+++ b/src/trace_processor/slice_tracker_unittest.cc
@@ -83,23 +83,24 @@
EXPECT_EQ(slices.slice_count(), 2);
- EXPECT_EQ(slices.start_ns()[0], 3);
- EXPECT_EQ(slices.durations()[0], 2);
- EXPECT_EQ(slices.cats()[0], 0);
- EXPECT_EQ(slices.names()[0], 2);
- EXPECT_EQ(slices.utids()[0], 42);
- EXPECT_EQ(slices.depths()[0], 1);
+ size_t idx = 0;
+ EXPECT_EQ(slices.start_ns()[idx], 2);
+ EXPECT_EQ(slices.durations()[idx], 8);
+ EXPECT_EQ(slices.cats()[idx], 0);
+ EXPECT_EQ(slices.names()[idx], 1);
+ EXPECT_EQ(slices.utids()[idx], 42);
+ EXPECT_EQ(slices.depths()[idx++], 0);
- EXPECT_EQ(slices.start_ns()[1], 2);
- EXPECT_EQ(slices.durations()[1], 8);
- EXPECT_EQ(slices.cats()[1], 0);
- EXPECT_EQ(slices.names()[1], 1);
- EXPECT_EQ(slices.utids()[1], 42);
- EXPECT_EQ(slices.depths()[1], 0);
+ EXPECT_EQ(slices.start_ns()[idx], 3);
+ EXPECT_EQ(slices.durations()[idx], 2);
+ EXPECT_EQ(slices.cats()[idx], 0);
+ EXPECT_EQ(slices.names()[idx], 2);
+ EXPECT_EQ(slices.utids()[idx], 42);
+ EXPECT_EQ(slices.depths()[idx], 1);
- EXPECT_EQ(slices.parent_stack_ids()[1], 0);
- EXPECT_EQ(slices.stack_ids()[1], slices.parent_stack_ids()[0]);
- EXPECT_NE(slices.stack_ids()[0], 0);
+ EXPECT_EQ(slices.parent_stack_ids()[0], 0);
+ EXPECT_EQ(slices.stack_ids()[0], slices.parent_stack_ids()[1]);
+ EXPECT_NE(slices.stack_ids()[1], 0);
}
TEST(SliceTrackerTest, Scoped) {
@@ -115,7 +116,7 @@
auto slices = ToSliceInfo(context.storage->nestable_slices());
EXPECT_THAT(slices,
- ElementsAre(SliceInfo{2, 6}, SliceInfo{1, 8}, SliceInfo{0, 10}));
+ ElementsAre(SliceInfo{0, 10}, SliceInfo{1, 8}, SliceInfo{2, 6}));
}
} // namespace
diff --git a/src/trace_processor/trace_storage.h b/src/trace_processor/trace_storage.h
index 57de9ed..b42b539 100644
--- a/src/trace_processor/trace_storage.h
+++ b/src/trace_processor/trace_storage.h
@@ -124,14 +124,14 @@
class NestableSlices {
public:
- inline void AddSlice(uint64_t start_ns,
- uint64_t duration_ns,
- UniqueTid utid,
- StringId cat,
- StringId name,
- uint8_t depth,
- uint64_t stack_id,
- uint64_t parent_stack_id) {
+ inline size_t AddSlice(uint64_t start_ns,
+ uint64_t duration_ns,
+ UniqueTid utid,
+ StringId cat,
+ StringId name,
+ uint8_t depth,
+ uint64_t stack_id,
+ uint64_t parent_stack_id) {
start_ns_.emplace_back(start_ns);
durations_.emplace_back(duration_ns);
utids_.emplace_back(utid);
@@ -140,6 +140,15 @@
depths_.emplace_back(depth);
stack_ids_.emplace_back(stack_id);
parent_stack_ids_.emplace_back(parent_stack_id);
+ return slice_count() - 1;
+ }
+
+ void set_duration(size_t index, uint64_t duration_ns) {
+ durations_[index] = duration_ns;
+ }
+
+ void set_stack_id(size_t index, uint64_t stack_id) {
+ stack_ids_[index] = stack_id;
}
size_t slice_count() const { return start_ns_.size(); }
