| OLD | NEW |
| (Empty) |
| 1 // Copyright (c) 2010 The Chromium Authors. All rights reserved. | |
| 2 // Use of this source code is governed by a BSD-style license that can be | |
| 3 // found in the LICENSE file. | |
| 4 | |
| 5 // Helper program to analyze the time that Chrome's renderers spend in system | |
| 6 // calls. Start Chrome like this: | |
| 7 // | |
| 8 // SECCOMP_SANDBOX_DEBUGGING=1 chrome --enable-seccomp-sandbox 2>&1 | timestats | |
| 9 // | |
| 10 // The program prints CPU time (0-100%) spent within system calls. This gives | |
| 11 // a general idea of where it is worthwhile to spend effort optimizing Chrome. | |
| 12 // | |
| 13 // Caveats: | |
| 14 // - there currently is no way to estimate what the overhead is for running | |
| 15 // inside of the sandbox vs. running without a sandbox. | |
| 16 // - we currently use a very simple heuristic to decide whether a system call | |
| 17 // is blocking or not. Blocking system calls should not be included in the | |
| 18 // computations. But it is quite possible for the numbers to be somewhat | |
| 19 // wrong, because the heuristic failed. | |
| 20 // - in order to collect this data, we have to turn on sandbox debugging. | |
| 21 // There is a measurable performance penalty to doing so. Production numbers | |
| 22 // are strictly better than the numbers reported by this tool. | |
| 23 #include <set> | |
| 24 #include <vector> | |
| 25 | |
| 26 #include <stdio.h> | |
| 27 #include <stdlib.h> | |
| 28 #include <string.h> | |
| 29 #include <sys/time.h> | |
| 30 #include <time.h> | |
| 31 | |
| 32 static const int kAvgWindowSizeMs = 500; | |
| 33 static const int kPeakWindowSizeMs = 2*1000; | |
| 34 | |
| 35 // Class containing information on a single system call. Most notably, it | |
| 36 // contains the time when the system call happened, and the time that it | |
| 37 // took to complete. | |
| 38 class Datum { | |
| 39 friend class Data; | |
| 40 public: | |
| 41 Datum(const char* name, double ms) | |
| 42 : name_(name), | |
| 43 ms_(ms) { | |
| 44 struct timeval tv; | |
| 45 gettimeofday(&tv, NULL); | |
| 46 timestamp_ = tv.tv_sec*1000.0 + tv.tv_usec/1000.0; | |
| 47 } | |
| 48 virtual ~Datum() { } | |
| 49 | |
| 50 double operator-(const Datum& b) { | |
| 51 return timestamp_ - b.timestamp_; | |
| 52 } | |
| 53 | |
| 54 protected: | |
| 55 const char* name_; | |
| 56 double ms_; | |
| 57 double timestamp_; | |
| 58 }; | |
| 59 | |
| 60 // Class containing data on the most recent system calls. It maintains | |
| 61 // sliding averages for total CPU time used, and it also maintains a peak | |
| 62 // CPU usage. The peak usage is usually updated slower than the average | |
| 63 // usage, as that makes it easier to inspect visually. | |
| 64 class Data { | |
| 65 public: | |
| 66 Data() { } | |
| 67 virtual ~Data() { } | |
| 68 | |
| 69 void addData(const char* name, double ms) { | |
| 70 average_.push_back(Datum(name, ms)); | |
| 71 peak_.push_back(Datum(name, ms)); | |
| 72 | |
| 73 // Prune entries outside of the window | |
| 74 std::vector<Datum>::iterator iter; | |
| 75 for (iter = average_.begin(); | |
| 76 *average_.rbegin() - *iter > kAvgWindowSizeMs; | |
| 77 ++iter) { | |
| 78 } | |
| 79 average_.erase(average_.begin(), iter); | |
| 80 | |
| 81 for (iter = peak_.begin(); | |
| 82 *peak_.rbegin() - *iter > kPeakWindowSizeMs; | |
| 83 ++iter){ | |
| 84 } | |
| 85 peak_.erase(peak_.begin(), iter); | |
| 86 | |
| 87 // Add the total usage of all system calls inside of the window | |
| 88 double total = 0; | |
| 89 for (iter = average_.begin(); iter != average_.end(); ++iter) { | |
| 90 total += iter->ms_; | |
| 91 } | |
| 92 | |
| 93 // Compute the peak CPU usage during the last window | |
| 94 double peak = 0; | |
| 95 double max = 0; | |
| 96 std::vector<Datum>::iterator tail = peak_.begin(); | |
| 97 for (iter = tail; iter != peak_.end(); ++iter) { | |
| 98 while (*iter - *tail > kAvgWindowSizeMs) { | |
| 99 peak -= tail->ms_; | |
| 100 ++tail; | |
| 101 } | |
| 102 peak += iter->ms_; | |
| 103 if (peak > max) { | |
| 104 max = peak; | |
| 105 } | |
| 106 } | |
| 107 | |
| 108 // Print the average CPU usage in the last window | |
| 109 char buf[80]; | |
| 110 total *= 100.0/kAvgWindowSizeMs; | |
| 111 max *= 100.0/kAvgWindowSizeMs; | |
| 112 sprintf(buf, "%6.2f%% (peak=%6.2f%%) ", total, max); | |
| 113 | |
| 114 // Animate the actual usage, displaying both average and peak values | |
| 115 int len = strlen(buf); | |
| 116 int space = sizeof(buf) - len - 1; | |
| 117 int mark = (total * space + 50)/100; | |
| 118 int bar = (max * space + 50)/100; | |
| 119 for (int i = 0; i < mark; ++i) { | |
| 120 buf[len++] = '*'; | |
| 121 } | |
| 122 if (mark == bar) { | |
| 123 if (bar) { | |
| 124 len--; | |
| 125 } | |
| 126 } else { | |
| 127 for (int i = 0; i < bar - mark - 1; ++i) { | |
| 128 buf[len++] = ' '; | |
| 129 } | |
| 130 } | |
| 131 buf[len++] = '|'; | |
| 132 while (len < static_cast<int>(sizeof(buf))) { | |
| 133 buf[len++] = ' '; | |
| 134 } | |
| 135 strcpy(buf + len, "\r"); | |
| 136 fwrite(buf, len + 1, 1, stdout); | |
| 137 fflush(stdout); | |
| 138 } | |
| 139 | |
| 140 private: | |
| 141 std::vector<Datum> average_; | |
| 142 std::vector<Datum> peak_; | |
| 143 }; | |
| 144 static Data data; | |
| 145 | |
| 146 | |
| 147 int main(int argc, char *argv[]) { | |
| 148 char buf[80]; | |
| 149 bool expensive = false; | |
| 150 while (fgets(buf, sizeof(buf), stdin)) { | |
| 151 // Allow longer delays for expensive system calls | |
| 152 if (strstr(buf, "This is an expensive system call")) { | |
| 153 expensive = true; | |
| 154 continue; | |
| 155 } | |
| 156 | |
| 157 // Parse the string and extract the elapsed time | |
| 158 const char elapsed[] = "Elapsed time: "; | |
| 159 char* ms_string = strstr(buf, elapsed); | |
| 160 char* endptr; | |
| 161 double ms; | |
| 162 char* colon = strchr(buf, ':'); | |
| 163 | |
| 164 // If this string doesn't match, then it must be some other type of | |
| 165 // message. Just ignore it. | |
| 166 // It is quite likely that we will regularly encounter debug messages | |
| 167 // that either should be parsed by a completely different tool, or | |
| 168 // messages that were intended for humans to read. | |
| 169 if (!ms_string || | |
| 170 ((ms = strtod(ms_string + sizeof(elapsed) - 1, &endptr)), | |
| 171 endptr == ms_string) || | |
| 172 !colon) { | |
| 173 continue; | |
| 174 } | |
| 175 | |
| 176 // Filter out system calls that were probably just blocking | |
| 177 // TODO(markus): automatically compute the cut-off for blocking calls | |
| 178 if (!expensive && ms > 0.05) { | |
| 179 continue; | |
| 180 } | |
| 181 expensive = false; | |
| 182 | |
| 183 // Extract the name of the system call | |
| 184 *colon = '\000'; | |
| 185 | |
| 186 // Add the data point and update the display | |
| 187 data.addData(buf, ms); | |
| 188 } | |
| 189 puts(""); | |
| 190 return 0; | |
| 191 } | |
| OLD | NEW |