• Home
  • Line#
  • Scopes#
  • Navigate#
  • Raw
  • Download
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