1 /*
2  * Copyright (C) 2016 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 "guest/hals/hwcomposer/common/stats_keeper.h"
18 
19 #include <inttypes.h>
20 #include <stdint.h>
21 #include <stdio.h>
22 #include <stdlib.h>
23 
24 #include <algorithm>
25 #include <mutex>
26 #include <utility>
27 #include <vector>
28 
29 #include <log/log.h>
30 
31 #include "guest/hals/hwcomposer/common/geometry_utils.h"
32 
33 using cuttlefish::time::Microseconds;
34 using cuttlefish::time::MonotonicTimePoint;
35 using cuttlefish::time::Nanoseconds;
36 using cuttlefish::time::Seconds;
37 using cuttlefish::time::TimeDifference;
38 
39 namespace cuttlefish {
40 
41 namespace {
42 
43 // These functions assume that there is at least one suitable element inside
44 // the multiset.
45 template <class T>
MultisetDeleteOne(std::multiset<T> * mset,const T & key)46 void MultisetDeleteOne(std::multiset<T>* mset, const T& key) {
47   mset->erase(mset->find(key));
48 }
49 template <class T>
MultisetMin(const std::multiset<T> & mset)50 const T& MultisetMin(const std::multiset<T>& mset) {
51   return *mset.begin();
52 }
53 template <class T>
MultisetMax(const std::multiset<T> & mset)54 const T& MultisetMax(const std::multiset<T>& mset) {
55   return *mset.rbegin();
56 }
57 
TimeDifferenceToTimeSpec(const TimeDifference & td,timespec * ts)58 void TimeDifferenceToTimeSpec(const TimeDifference& td, timespec* ts) {
59   ts->tv_sec = td.seconds();
60   ts->tv_nsec = td.subseconds_in_ns();
61 }
62 
63 }  // namespace
64 
GetLastCompositionStats(CompositionStats * stats_p)65 void StatsKeeper::GetLastCompositionStats(CompositionStats* stats_p) {
66   if (stats_p) {
67     TimeDifferenceToTimeSpec(last_composition_stats_.prepare_start.SinceEpoch(),
68                              &stats_p->prepare_start);
69     TimeDifferenceToTimeSpec(last_composition_stats_.prepare_end.SinceEpoch(),
70                              &stats_p->prepare_end);
71     TimeDifferenceToTimeSpec(last_composition_stats_.set_start.SinceEpoch(),
72                              &stats_p->set_start);
73     TimeDifferenceToTimeSpec(last_composition_stats_.set_end.SinceEpoch(),
74                              &stats_p->set_end);
75     TimeDifferenceToTimeSpec(last_composition_stats_.last_vsync.SinceEpoch(),
76                              &stats_p->last_vsync);
77 
78     stats_p->num_prepare_calls = last_composition_stats_.num_prepare_calls;
79     stats_p->num_layers = last_composition_stats_.num_layers;
80     stats_p->num_hwcomposited_layers = last_composition_stats_.num_hwc_layers;
81   }
82 }
83 
StatsKeeper(TimeDifference timespan,int64_t vsync_base,int32_t vsync_period)84 StatsKeeper::StatsKeeper(TimeDifference timespan, int64_t vsync_base,
85                          int32_t vsync_period)
86     : period_length_(timespan, 1),
87       vsync_base_(vsync_base),
88       vsync_period_(vsync_period),
89       num_layers_(0),
90       num_hwcomposited_layers_(0),
91       num_prepare_calls_(0),
92       num_set_calls_(0),
93       prepare_call_total_time_(0),
94       set_call_total_time_(0),
95       total_layers_area(0),
96       total_invisible_area(0) {
97   last_composition_stats_.num_prepare_calls = 0;
98 }
99 
~StatsKeeper()100 StatsKeeper::~StatsKeeper() {}
101 
RecordPrepareStart(int num_layers)102 void StatsKeeper::RecordPrepareStart(int num_layers) {
103   last_composition_stats_.num_layers = num_layers;
104   last_composition_stats_.num_prepare_calls++;
105   num_prepare_calls_++;
106   last_composition_stats_.prepare_start = MonotonicTimePoint::Now();
107   // Calculate the (expected) time of last VSYNC event. We can only make a guess
108   // about it because the vsync thread could run late or surfaceflinger could
109   // run late and call prepare from a previous vsync cycle.
110   int64_t last_vsync =
111       Nanoseconds(last_composition_stats_.set_start.SinceEpoch()).count();
112   last_vsync -= (last_vsync - vsync_base_) % vsync_period_;
113   last_composition_stats_.last_vsync =
114       MonotonicTimePoint() + Nanoseconds(last_vsync);
115 }
116 
RecordPrepareEnd(int num_hwcomposited_layers)117 void StatsKeeper::RecordPrepareEnd(int num_hwcomposited_layers) {
118   last_composition_stats_.prepare_end = MonotonicTimePoint::Now();
119   last_composition_stats_.num_hwc_layers = num_hwcomposited_layers;
120 }
121 
RecordSetStart()122 void StatsKeeper::RecordSetStart() {
123   last_composition_stats_.set_start = MonotonicTimePoint::Now();
124 }
125 
RecordSetEnd()126 void StatsKeeper::RecordSetEnd() {
127   last_composition_stats_.set_end = MonotonicTimePoint::Now();
128   std::lock_guard lock(mutex_);
129   num_set_calls_++;
130   while (!raw_composition_data_.empty() &&
131          period_length_ < last_composition_stats_.set_end -
132                               raw_composition_data_.front().time_point()) {
133     const CompositionData& front = raw_composition_data_.front();
134 
135     num_prepare_calls_ -= front.num_prepare_calls();
136     --num_set_calls_;
137     num_layers_ -= front.num_layers();
138     num_hwcomposited_layers_ -= front.num_hwcomposited_layers();
139     prepare_call_total_time_ =
140         Nanoseconds(prepare_call_total_time_ - front.prepare_time());
141     set_call_total_time_ =
142         Nanoseconds(set_call_total_time_ - front.set_calls_time());
143 
144     MultisetDeleteOne(&prepare_calls_per_set_calls_, front.num_prepare_calls());
145     MultisetDeleteOne(&layers_per_compositions_, front.num_layers());
146     MultisetDeleteOne(&prepare_call_times_, front.prepare_time());
147     MultisetDeleteOne(&set_call_times_, front.set_calls_time());
148     if (front.num_hwcomposited_layers() != 0) {
149       MultisetDeleteOne(
150           &set_call_times_per_hwcomposited_layer_ns_,
151           front.set_calls_time().count() / front.num_hwcomposited_layers());
152     }
153 
154     raw_composition_data_.pop_front();
155   }
156   Nanoseconds last_prepare_call_time_(last_composition_stats_.prepare_end -
157                                       last_composition_stats_.prepare_start);
158   Nanoseconds last_set_call_total_time_(last_composition_stats_.set_end -
159                                         last_composition_stats_.set_start);
160   raw_composition_data_.push_back(
161       CompositionData(last_composition_stats_.set_end,
162                       last_composition_stats_.num_prepare_calls,
163                       last_composition_stats_.num_layers,
164                       last_composition_stats_.num_hwc_layers,
165                       last_prepare_call_time_, last_set_call_total_time_));
166 
167   // There may be several calls to prepare before a call to set, but the only
168   // valid call is the last one, so we need to compute these here:
169   num_layers_ += last_composition_stats_.num_layers;
170   num_hwcomposited_layers_ += last_composition_stats_.num_hwc_layers;
171   prepare_call_total_time_ =
172       Nanoseconds(prepare_call_total_time_ + last_prepare_call_time_);
173   set_call_total_time_ =
174       Nanoseconds(set_call_total_time_ + last_set_call_total_time_);
175   prepare_calls_per_set_calls_.insert(
176       last_composition_stats_.num_prepare_calls);
177   layers_per_compositions_.insert(last_composition_stats_.num_layers);
178   prepare_call_times_.insert(last_prepare_call_time_);
179   set_call_times_.insert(last_set_call_total_time_);
180   if (last_composition_stats_.num_hwc_layers != 0) {
181     set_call_times_per_hwcomposited_layer_ns_.insert(
182         last_set_call_total_time_.count() /
183         last_composition_stats_.num_hwc_layers);
184   }
185 
186   // Reset the counter
187   last_composition_stats_.num_prepare_calls = 0;
188 }
189 
SynchronizedDump(char * buffer,int buffer_size) const190 void StatsKeeper::SynchronizedDump(char* buffer, int buffer_size) const {
191   std::lock_guard lock(mutex_);
192   int chars_written = 0;
193 // Make sure there is enough space to write the next line
194 #define bprintf(...)                                                           \
195   (chars_written += (chars_written < buffer_size)                              \
196                         ? (snprintf(&buffer[chars_written],                    \
197                                     buffer_size - chars_written, __VA_ARGS__)) \
198                         : 0)
199 
200   bprintf("HWComposer stats from the %" PRId64
201           " seconds just before the last call to "
202           "set() (which happended %" PRId64 " seconds ago):\n",
203           Seconds(period_length_).count(),
204           Seconds(MonotonicTimePoint::Now() - last_composition_stats_.set_end)
205               .count());
206   bprintf("  Layer count: %d\n", num_layers_);
207 
208   if (num_layers_ == 0 || num_prepare_calls_ == 0 || num_set_calls_ == 0) {
209     return;
210   }
211 
212   bprintf("  Layers composited by hwcomposer: %d (%d%%)\n",
213           num_hwcomposited_layers_,
214           100 * num_hwcomposited_layers_ / num_layers_);
215   bprintf("  Number of calls to prepare(): %d\n", num_prepare_calls_);
216   bprintf("  Number of calls to set(): %d\n", num_set_calls_);
217   if (num_set_calls_ > 0) {
218     bprintf(
219         "  Maximum number of calls to prepare() before a single call to set(): "
220         "%d\n",
221         MultisetMax(prepare_calls_per_set_calls_));
222   }
223   bprintf("  Time spent on prepare() (in microseconds):\n    max: %" PRId64
224           "\n    "
225           "average: %" PRId64 "\n    min: %" PRId64 "\n    total: %" PRId64
226           "\n",
227           Microseconds(MultisetMax(prepare_call_times_)).count(),
228           Microseconds(prepare_call_total_time_).count() / num_prepare_calls_,
229           Microseconds(MultisetMin(prepare_call_times_)).count(),
230           Microseconds(prepare_call_total_time_).count());
231   bprintf("  Time spent on set() (in microseconds):\n    max: %" PRId64
232           "\n    average: "
233           "%" PRId64 "\n    min: %" PRId64 "\n    total: %" PRId64 "\n",
234           Microseconds(MultisetMax(set_call_times_)).count(),
235           Microseconds(set_call_total_time_).count() / num_set_calls_,
236           Microseconds(MultisetMin(set_call_times_)).count(),
237           Microseconds(set_call_total_time_).count());
238   if (num_hwcomposited_layers_ > 0) {
239     bprintf(
240         "  Per layer compostition time:\n    max: %" PRId64
241         "\n    average: %" PRId64
242         "\n    "
243         "min: %" PRId64 "\n",
244         Microseconds(MultisetMax(set_call_times_per_hwcomposited_layer_ns_))
245             .count(),
246         Microseconds(set_call_total_time_).count() / num_hwcomposited_layers_,
247         Microseconds(MultisetMin(set_call_times_per_hwcomposited_layer_ns_))
248             .count());
249   }
250   bprintf("Statistics from last 100 compositions:\n");
251   bprintf("  Total area: %" PRId64 " square pixels\n", total_layers_area);
252   if (total_layers_area != 0) {
253     bprintf(
254         "  Total invisible area: %" PRId64 " square pixels, %" PRId64 "%%\n",
255         total_invisible_area, 100 * total_invisible_area / total_layers_area);
256   }
257 #undef bprintf
258 }
259 
260 }  // namespace cuttlefish
261