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 |