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 <log/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
