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