1 /*
2 * Copyright (C) 2019 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/common/clock_tracker.h"
18
19 #include <inttypes.h>
20
21 #include <algorithm>
22 #include <atomic>
23 #include <queue>
24
25 #include "perfetto/base/logging.h"
26 #include "perfetto/ext/base/hash.h"
27 #include "src/trace_processor/storage/trace_storage.h"
28 #include "src/trace_processor/types/trace_processor_context.h"
29
30 #include "protos/perfetto/common/builtin_clock.pbzero.h"
31 #include "protos/perfetto/trace/clock_snapshot.pbzero.h"
32
33 namespace perfetto {
34 namespace trace_processor {
35
36 using Clock = protos::pbzero::ClockSnapshot::Clock;
37
ClockTracker(TraceProcessorContext * ctx)38 ClockTracker::ClockTracker(TraceProcessorContext* ctx)
39 : context_(ctx),
40 trace_time_clock_id_(protos::pbzero::BUILTIN_CLOCK_BOOTTIME) {}
41
42 ClockTracker::~ClockTracker() = default;
43
AddSnapshot(const std::vector<ClockValue> & clocks)44 uint32_t ClockTracker::AddSnapshot(const std::vector<ClockValue>& clocks) {
45 const auto snapshot_id = cur_snapshot_id_++;
46
47 // Clear the cache
48 cache_.fill({});
49
50 // Compute the fingerprint of the snapshot by hashing all clock ids. This is
51 // used by the clock pathfinding logic.
52 base::Hash hasher;
53 for (const auto& clock : clocks)
54 hasher.Update(clock.clock_id);
55 const auto snapshot_hash = static_cast<SnapshotHash>(hasher.digest());
56
57 // Add a new entry in each clock's snapshot vector.
58 for (const auto& clock : clocks) {
59 ClockId clock_id = clock.clock_id;
60 ClockDomain& domain = clocks_[clock_id];
61 if (domain.snapshots.empty()) {
62 if (clock.is_incremental && !ClockIsSeqScoped(clock_id)) {
63 PERFETTO_ELOG("Clock sync error: the global clock with id=%" PRIu64
64 " cannot use incremental encoding; this is only "
65 "supported for sequence-scoped clocks.",
66 clock_id);
67 context_->storage->IncrementStats(stats::invalid_clock_snapshots);
68 return snapshot_id;
69 }
70 domain.unit_multiplier_ns = clock.unit_multiplier_ns;
71 domain.is_incremental = clock.is_incremental;
72 } else if (PERFETTO_UNLIKELY(
73 domain.unit_multiplier_ns != clock.unit_multiplier_ns ||
74 domain.is_incremental != clock.is_incremental)) {
75 PERFETTO_ELOG("Clock sync error: the clock domain with id=%" PRIu64
76 " (unit=%" PRIu64
77 ", incremental=%d), was previously registered with "
78 "different properties (unit=%" PRIu64 ", incremental=%d).",
79 clock_id, clock.unit_multiplier_ns, clock.is_incremental,
80 domain.unit_multiplier_ns, domain.is_incremental);
81 context_->storage->IncrementStats(stats::invalid_clock_snapshots);
82 return snapshot_id;
83 }
84 const int64_t timestamp_ns =
85 clock.absolute_timestamp * domain.unit_multiplier_ns;
86 domain.last_timestamp_ns = timestamp_ns;
87
88 ClockSnapshots& vect = domain.snapshots[snapshot_hash];
89 if (!vect.snapshot_ids.empty() &&
90 PERFETTO_UNLIKELY(vect.snapshot_ids.back() == snapshot_id)) {
91 PERFETTO_ELOG("Clock sync error: duplicate clock domain with id=%" PRIu64
92 " at snapshot %" PRIu32 ".",
93 clock_id, snapshot_id);
94 context_->storage->IncrementStats(stats::invalid_clock_snapshots);
95 return snapshot_id;
96 }
97
98 // Clock ids in the range [64, 128) are sequence-scoped and must be
99 // translated to global ids via SeqScopedClockIdToGlobal() before calling
100 // this function.
101 PERFETTO_DCHECK(!IsReservedSeqScopedClockId(clock_id));
102
103 // Snapshot IDs must be always monotonic.
104 PERFETTO_DCHECK(vect.snapshot_ids.empty() ||
105 vect.snapshot_ids.back() < snapshot_id);
106
107 if (!vect.timestamps_ns.empty() &&
108 timestamp_ns < vect.timestamps_ns.back()) {
109 // Clock is not monotonic.
110
111 if (clock_id == trace_time_clock_id_) {
112 // The trace clock cannot be non-monotonic.
113 PERFETTO_ELOG("Clock sync error: the trace clock (id=%" PRIu64
114 ") is not monotonic at snapshot %" PRIu32 ". %" PRId64
115 " not >= %" PRId64 ".",
116 clock_id, snapshot_id, timestamp_ns,
117 vect.timestamps_ns.back());
118 context_->storage->IncrementStats(stats::invalid_clock_snapshots);
119 return snapshot_id;
120 }
121
122 PERFETTO_DLOG("Detected non-monotonic clock with ID %" PRIu64, clock_id);
123
124 // For the other clocks the best thing we can do is mark it as
125 // non-monotonic and refuse to use it as a source clock in the resolution
126 // graph. We can still use it as a target clock, but not viceversa.
127 // The concrete example is the CLOCK_REALTIME going 1h backwards during
128 // daylight saving. We can still answer the question "what was the
129 // REALTIME timestamp when BOOTTIME was X?" but we can't answer the
130 // opposite question because there can be two valid BOOTTIME(s) for the
131 // same REALTIME instant because of the 1:many relationship.
132 non_monotonic_clocks_.insert(clock_id);
133
134 // Erase all edges from the graph that start from this clock (but keep the
135 // ones that end on this clock).
136 auto begin = graph_.lower_bound(ClockGraphEdge{clock_id, 0, 0});
137 auto end = graph_.lower_bound(ClockGraphEdge{clock_id + 1, 0, 0});
138 graph_.erase(begin, end);
139 }
140 vect.snapshot_ids.emplace_back(snapshot_id);
141 vect.timestamps_ns.emplace_back(timestamp_ns);
142 }
143
144 // Create graph edges for all the possible tuples of clocks in this snapshot.
145 // If the snapshot contains clock a, b, c, d create edges [ab, ac, ad, bc, bd,
146 // cd] and the symmetrical ones [ba, ca, da, bc, db, dc].
147 // This is to store the information: Clock A is syncable to Clock B via the
148 // snapshots of type (hash).
149 // Clocks that were previously marked as non-monotonic won't be added as
150 // valid sources.
151 for (auto it1 = clocks.begin(); it1 != clocks.end(); ++it1) {
152 auto it2 = it1;
153 ++it2;
154 for (; it2 != clocks.end(); ++it2) {
155 if (!non_monotonic_clocks_.count(it1->clock_id))
156 graph_.emplace(it1->clock_id, it2->clock_id, snapshot_hash);
157
158 if (!non_monotonic_clocks_.count(it2->clock_id))
159 graph_.emplace(it2->clock_id, it1->clock_id, snapshot_hash);
160 }
161 }
162 return snapshot_id;
163 }
164
165 // Finds the shortest clock resolution path in the graph that allows to
166 // translate a timestamp from |src| to |target| clocks.
167 // The return value looks like the following: "If you want to convert a
168 // timestamp from clock C1 to C2 you need to first convert C1 -> C3 using the
169 // snapshot hash A, then convert C3 -> C2 via snapshot hash B".
FindPath(ClockId src,ClockId target)170 ClockTracker::ClockPath ClockTracker::FindPath(ClockId src, ClockId target) {
171 // This is a classic breadth-first search. Each node in the queue holds also
172 // the full path to reach that node.
173 // We assume the graph is acyclic, if it isn't the ClockPath::kMaxLen will
174 // stop the search anyways.
175 PERFETTO_CHECK(src != target);
176 std::queue<ClockPath> queue;
177 queue.emplace(src);
178
179 while (!queue.empty()) {
180 ClockPath cur_path = queue.front();
181 queue.pop();
182
183 const ClockId cur_clock_id = cur_path.last;
184 if (cur_clock_id == target)
185 return cur_path;
186
187 if (cur_path.len >= ClockPath::kMaxLen)
188 continue;
189
190 // Expore all the adjacent clocks.
191 // The lower_bound() below returns an iterator to the first edge that starts
192 // on |cur_clock_id|. The edges are sorted by (src, target, hash).
193 for (auto it = std::lower_bound(graph_.begin(), graph_.end(),
194 ClockGraphEdge(cur_clock_id, 0, 0));
195 it != graph_.end() && std::get<0>(*it) == cur_clock_id; ++it) {
196 ClockId next_clock_id = std::get<1>(*it);
197 SnapshotHash hash = std::get<2>(*it);
198 queue.push(ClockPath(cur_path, next_clock_id, hash));
199 }
200 }
201 return ClockPath(); // invalid path.
202 }
203
ConvertSlowpath(ClockId src_clock_id,int64_t src_timestamp,ClockId target_clock_id)204 base::Optional<int64_t> ClockTracker::ConvertSlowpath(ClockId src_clock_id,
205 int64_t src_timestamp,
206 ClockId target_clock_id) {
207 PERFETTO_DCHECK(!IsReservedSeqScopedClockId(src_clock_id));
208 PERFETTO_DCHECK(!IsReservedSeqScopedClockId(target_clock_id));
209
210 context_->storage->IncrementStats(stats::clock_sync_cache_miss);
211
212 ClockPath path = FindPath(src_clock_id, target_clock_id);
213 if (!path.valid()) {
214 // Too many logs maybe emitted when path is invalid.
215 static std::atomic<uint32_t> dlog_count(0);
216 if (dlog_count++ < 10) {
217 PERFETTO_DLOG("No path from clock %" PRIu64 " to %" PRIu64
218 " at timestamp %" PRId64,
219 src_clock_id, target_clock_id, src_timestamp);
220 }
221 context_->storage->IncrementStats(stats::clock_sync_failure);
222 return base::nullopt;
223 }
224
225 // We can cache only single-path resolutions between two clocks.
226 // Caching multi-path resolutions is harder because the (src,target) tuple
227 // is not enough as a cache key: at any step the |ns| value can yield to a
228 // different choice of the next snapshot. Multi-path resolutions don't seem
229 // too frequent these days, so we focus only on caching the more frequent
230 // one-step resolutions (typically from any clock to the trace clock).
231 const bool cacheable = path.len == 1;
232 CachedClockPath cache_entry{};
233
234 // Iterate trough the path found and translate timestamps onto the new clock
235 // domain on each step, until the target domain is reached.
236 ClockDomain* src_domain = GetClock(src_clock_id);
237 int64_t ns = src_domain->ToNs(src_timestamp);
238 for (uint32_t i = 0; i < path.len; ++i) {
239 const ClockGraphEdge edge = path.at(i);
240 ClockDomain* cur_clock = GetClock(std::get<0>(edge));
241 ClockDomain* next_clock = GetClock(std::get<1>(edge));
242 const SnapshotHash hash = std::get<2>(edge);
243
244 // Find the closest timestamp within the snapshots of the source clock.
245 const ClockSnapshots& cur_snap = cur_clock->GetSnapshot(hash);
246 const auto& ts_vec = cur_snap.timestamps_ns;
247 auto it = std::upper_bound(ts_vec.begin(), ts_vec.end(), ns);
248 if (it != ts_vec.begin())
249 --it;
250
251 // Now lookup the snapshot id that matches the closest timestamp.
252 size_t index = static_cast<size_t>(std::distance(ts_vec.begin(), it));
253 PERFETTO_DCHECK(index < ts_vec.size());
254 PERFETTO_DCHECK(cur_snap.snapshot_ids.size() == ts_vec.size());
255 uint32_t snapshot_id = cur_snap.snapshot_ids[index];
256
257 // And use that to retrieve the corresponding time in the next clock domain.
258 // The snapshot id must exist in the target clock domain. If it doesn't
259 // either the hash logic or the pathfinding logic are bugged.
260 // This can also happen if the checks in AddSnapshot fail and we skip part
261 // of the snapshot.
262 const ClockSnapshots& next_snap = next_clock->GetSnapshot(hash);
263
264 // Using std::lower_bound because snapshot_ids is sorted, so we can do
265 // a binary search. std::find would do a linear scan.
266 auto next_it = std::lower_bound(next_snap.snapshot_ids.begin(),
267 next_snap.snapshot_ids.end(), snapshot_id);
268 if (next_it == next_snap.snapshot_ids.end() || *next_it != snapshot_id) {
269 PERFETTO_DFATAL("Snapshot does not exist in clock domain.");
270 continue;
271 }
272 size_t next_index = static_cast<size_t>(
273 std::distance(next_snap.snapshot_ids.begin(), next_it));
274 PERFETTO_DCHECK(next_index < next_snap.snapshot_ids.size());
275 int64_t next_timestamp_ns = next_snap.timestamps_ns[next_index];
276
277 // The translated timestamp is the relative delta of the source timestamp
278 // from the closest snapshot found (ns - *it), plus the timestamp in
279 // the new clock domain for the same snapshot id.
280 const int64_t adj = next_timestamp_ns - *it;
281 ns += adj;
282
283 // On the first iteration, keep track of the bounds for the cache entry.
284 // This will allow future Convert() calls to skip the pathfinder logic
285 // as long as the query stays within the bound.
286 if (cacheable) {
287 PERFETTO_DCHECK(i == 0);
288 const int64_t kInt64Min = std::numeric_limits<int64_t>::min();
289 const int64_t kInt64Max = std::numeric_limits<int64_t>::max();
290 cache_entry.min_ts_ns = it == ts_vec.begin() ? kInt64Min : *it;
291 auto ubound = it + 1;
292 cache_entry.max_ts_ns = ubound == ts_vec.end() ? kInt64Max : *ubound;
293 cache_entry.translation_ns = adj;
294 }
295
296 // The last clock in the path must be the target clock.
297 PERFETTO_DCHECK(i < path.len - 1 || std::get<1>(edge) == target_clock_id);
298 }
299
300 if (cacheable) {
301 cache_entry.src = src_clock_id;
302 cache_entry.src_domain = src_domain;
303 cache_entry.target = target_clock_id;
304 cache_[rnd_() % cache_.size()] = cache_entry;
305 }
306
307 return ns;
308 }
309
310 } // namespace trace_processor
311 } // namespace perfetto
312