]>
Commit | Line | Data |
---|---|---|
88bfe092 | 1 | |
2 | /* | |
262a0e14 | 3 | * $Id$ |
88bfe092 | 4 | * |
507d0a78 | 5 | * DEBUG: section 81 CPU Profiling Routines |
88bfe092 | 6 | * AUTHOR: Andres Kroonmaa |
7 | * | |
8 | * SQUID Internet Object Cache http://squid.nlanr.net/Squid/ | |
9 | * ---------------------------------------------------------- | |
10 | * | |
11 | * Squid is the result of efforts by numerous individuals from the | |
12 | * Internet community. Development is led by Duane Wessels of the | |
13 | * National Laboratory for Applied Network Research and funded by the | |
14 | * National Science Foundation. Squid is Copyrighted (C) 1998 by | |
15 | * the Regents of the University of California. Please see the | |
16 | * COPYRIGHT file for full details. Squid incorporates software | |
17 | * developed and/or copyrighted by other sources. Please see the | |
18 | * CREDITS file for full details. | |
19 | * | |
20 | * This program is free software; you can redistribute it and/or modify | |
21 | * it under the terms of the GNU General Public License as published by | |
22 | * the Free Software Foundation; either version 2 of the License, or | |
23 | * (at your option) any later version. | |
26ac0430 | 24 | * |
88bfe092 | 25 | * This program is distributed in the hope that it will be useful, |
26 | * but WITHOUT ANY WARRANTY; without even the implied warranty of | |
27 | * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the | |
28 | * GNU General Public License for more details. | |
26ac0430 | 29 | * |
88bfe092 | 30 | * You should have received a copy of the GNU General Public License |
31 | * along with this program; if not, write to the Free Software | |
32 | * Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA 02111, USA. | |
33 | * | |
34 | */ | |
35 | ||
36 | #include "squid.h" | |
37 | ||
32d002cb | 38 | #if USE_XPROF_STATS |
a98bcbee AJ |
39 | |
40 | #include "CacheManager.h" | |
41 | #include "event.h" | |
42 | #include "SquidMath.h" | |
e6ccf245 | 43 | #include "Store.h" |
88bfe092 | 44 | |
45 | /* Private stuff */ | |
46 | ||
47 | #define MAX_SORTLIST 200 | |
48 | ||
49 | static hrtime_t xprof_delta = 0; | |
50 | static hrtime_t xprof_start_t = 0; | |
51 | static hrtime_t xprof_verystart = 0; | |
52 | static hrtime_t xprof_average_delta = 0; | |
53 | static int xprof_events = 0; | |
54 | static int xprof_inited = 0; | |
55 | static xprof_stats_data Totals; | |
56 | ||
57 | static TimersArray *xprof_stats_avg1sec = NULL; | |
58 | static TimersArray *xprof_stats_avg5sec = NULL; | |
59 | static TimersArray *xprof_stats_avg30sec = NULL; | |
60 | static TimersArray *xprof_stats_avg1min = NULL; | |
61 | static TimersArray *xprof_stats_avg5min = NULL; | |
62 | static TimersArray *xprof_stats_avg30min = NULL; | |
63 | static TimersArray *xprof_stats_avg1hour = NULL; | |
64 | static TimersArray *xprof_stats_avg5hour = NULL; | |
65 | static TimersArray *xprof_stats_avg24hour = NULL; | |
66 | ||
67 | static xprof_stats_node *sortlist[XPROF_LAST + 2]; | |
43ae1d95 | 68 | static void xprof_summary(StoreEntry * sentry); |
88bfe092 | 69 | |
70 | static void | |
71 | xprof_reset(xprof_stats_data * head) | |
72 | { | |
73 | head->summ = 0; | |
74 | head->count = 0; | |
75 | head->delta = 0; | |
76 | head->best = XP_NOBEST; | |
77 | head->worst = 0; | |
78 | head->start = 0; | |
79 | head->stop = 0; | |
80 | } | |
81 | ||
82 | static void | |
83 | xprof_move(xprof_stats_data * head, xprof_stats_data * hist) | |
84 | { | |
85 | memcpy(hist, head, sizeof(xprof_stats_data)); | |
86 | } | |
87 | ||
88 | static int | |
89 | xprof_comp(xprof_stats_node ** ii, xprof_stats_node ** jj) | |
90 | { | |
91 | if ((*ii)->hist.summ < (*jj)->hist.summ) | |
62e76326 | 92 | return (1); |
93 | ||
88bfe092 | 94 | if ((*ii)->hist.summ > (*jj)->hist.summ) |
62e76326 | 95 | return (-1); |
88bfe092 | 96 | |
97 | return (0); | |
98 | } | |
99 | ||
100 | static void | |
101 | xprof_sorthist(TimersArray * xprof_list) | |
102 | { | |
103 | int i; | |
104 | ||
105 | for (i = 0; i < XPROF_LAST; i++) { | |
62e76326 | 106 | sortlist[i] = xprof_list[i]; |
88bfe092 | 107 | } |
62e76326 | 108 | |
88bfe092 | 109 | qsort(&sortlist[XPROF_hash_lookup], XPROF_LAST - XPROF_hash_lookup, sizeof(xprof_stats_node *), (QS *) xprof_comp); |
110 | } | |
111 | ||
112 | static double time_frame; | |
113 | ||
114 | static void | |
115 | xprof_show_item(StoreEntry * sentry, const char *name, xprof_stats_data * hist) | |
116 | { | |
117 | storeAppendPrintf(sentry, | |
e2b35d08 | 118 | "%s\t %" PRIu64 "\t %" PRIu64 "\t %" PRIu64 "\t %" PRIu64 "\t %" PRIu64 "\t %.2f\t %6.3f\t\n", |
62e76326 | 119 | name, |
120 | hist->count, | |
121 | hist->summ, | |
122 | (hist->best != XP_NOBEST ? hist->best : 0), | |
123 | hist->count ? hist->summ / hist->count : 0, | |
124 | hist->worst, | |
125 | hist->count / time_frame, | |
a98bcbee | 126 | Math::doublePercent((double) hist->summ, (double) hist->delta)); |
88bfe092 | 127 | } |
128 | ||
129 | static void | |
43ae1d95 | 130 | xprof_summary_item(StoreEntry * sentry, char const *descr, TimersArray * list) |
88bfe092 | 131 | { |
132 | int i; | |
133 | xprof_stats_node **hist; | |
134 | xprof_stats_data *show; | |
135 | xprof_reset(&Totals); | |
136 | xprof_sorthist(list); | |
137 | hist = &sortlist[0]; | |
138 | ||
139 | show = &hist[0]->hist; | |
62e76326 | 140 | |
88bfe092 | 141 | if (!hist[0]->hist.delta) |
62e76326 | 142 | show = &hist[0]->accu; |
88bfe092 | 143 | |
144 | time_frame = (double) show->delta / (double) xprof_average_delta; | |
145 | ||
146 | storeAppendPrintf(sentry, "\n%s:", descr); | |
62e76326 | 147 | |
e2b35d08 | 148 | storeAppendPrintf(sentry, " (Cumulated time: %" PRIu64 ", %.2f sec)\n", |
62e76326 | 149 | show->delta, |
150 | time_frame | |
151 | ); | |
152 | ||
88bfe092 | 153 | storeAppendPrintf(sentry, |
62e76326 | 154 | "Probe Name\t Events\t cumulated time \t best case \t average \t worst case\t Rate / sec \t %% in int\n"); |
88bfe092 | 155 | |
156 | for (i = 0; i < XPROF_LAST; i++) { | |
62e76326 | 157 | if (!hist[i]->name) |
158 | continue; | |
159 | ||
160 | show = &hist[i]->hist; | |
161 | ||
162 | if (!show->count) | |
163 | continue; | |
164 | ||
165 | xprof_show_item(sentry, hist[i]->name, show); | |
166 | ||
167 | Totals.count += show->count; | |
168 | ||
169 | Totals.summ += show->summ; | |
170 | ||
171 | Totals.best += (show->best != XP_NOBEST ? show->best : 0); | |
172 | ||
173 | Totals.worst += show->worst; | |
174 | ||
175 | Totals.delta = (show->delta > Totals.delta ? show->delta : Totals.delta); | |
88bfe092 | 176 | } |
62e76326 | 177 | |
88bfe092 | 178 | xprof_show_item(sentry, "TOTALS", &Totals); |
179 | } | |
180 | ||
181 | static void | |
182 | xprof_average(TimersArray ** list, int secs) | |
183 | { | |
184 | int i; | |
185 | TimersArray *head = xprof_Timers; | |
186 | TimersArray *hist; | |
187 | hrtime_t now; | |
188 | hrtime_t keep; | |
189 | int doavg = (xprof_events % secs); | |
190 | ||
191 | if (!*list) | |
62e76326 | 192 | *list = (TimersArray *)xcalloc(XPROF_LAST, sizeof(xprof_stats_node)); |
88bfe092 | 193 | |
194 | hist = *list; | |
62e76326 | 195 | |
88bfe092 | 196 | now = get_tick(); |
197 | ||
198 | for (i = 0; i < XPROF_LAST; i++) { | |
62e76326 | 199 | hist[i]->name = head[i]->name; |
200 | hist[i]->accu.summ += head[i]->accu.summ; | |
201 | hist[i]->accu.count += head[i]->accu.count; /* accumulate multisec */ | |
202 | ||
203 | if (!hist[i]->accu.best) | |
204 | hist[i]->accu.best = head[i]->accu.best; | |
205 | ||
206 | if (hist[i]->accu.best > head[i]->accu.best) | |
207 | hist[i]->accu.best = head[i]->accu.best; | |
208 | ||
209 | if (hist[i]->accu.worst < head[i]->accu.worst) | |
210 | hist[i]->accu.worst = head[i]->accu.worst; | |
211 | ||
212 | hist[i]->accu.delta += xprof_delta; | |
213 | ||
214 | if (!doavg) { | |
215 | /* we have X seconds accumulated */ | |
216 | xprof_move(&hist[i]->accu, &hist[i]->hist); | |
217 | xprof_reset(&hist[i]->accu); | |
218 | ||
219 | hist[i]->accu.start = now; | |
220 | } | |
221 | ||
222 | /* reset 0sec counters */ | |
223 | if (secs == 1) { | |
224 | keep = head[i]->accu.start; | |
225 | xprof_move(&head[i]->accu, &head[i]->hist); | |
226 | xprof_reset(&head[i]->accu); | |
227 | hist[i]->accu.delta = 0; | |
228 | head[i]->accu.start = keep; | |
229 | } | |
88bfe092 | 230 | } |
231 | } | |
232 | ||
233 | void | |
234 | xprof_summary(StoreEntry * sentry) | |
235 | { | |
236 | hrtime_t now = get_tick(); | |
237 | ||
238 | storeAppendPrintf(sentry, "CPU Profiling Statistics:\n"); | |
239 | storeAppendPrintf(sentry, | |
62e76326 | 240 | " (CPU times are in arbitrary units, most probably in CPU clock ticks)\n"); |
88bfe092 | 241 | storeAppendPrintf(sentry, |
62e76326 | 242 | "Probe Name\t Event Count\t last Interval \t Avg Interval \t since squid start \t (since system boot) \n"); |
e2b35d08 | 243 | storeAppendPrintf(sentry, "Total\t %lu\t %" PRIu64 " \t %" PRIu64 " \t %" PRIu64 " \t %" PRIu64 "\n", |
62e76326 | 244 | (long unsigned) xprof_events, |
245 | xprof_delta, | |
246 | xprof_average_delta, | |
247 | now - xprof_verystart, | |
248 | now); | |
88bfe092 | 249 | |
250 | xprof_summary_item(sentry, "Last 1 sec averages", xprof_stats_avg1sec); | |
251 | xprof_summary_item(sentry, "Last 5 sec averages", xprof_stats_avg5sec); | |
252 | xprof_summary_item(sentry, "Last 30 sec averages", xprof_stats_avg30sec); | |
253 | xprof_summary_item(sentry, "Last 1 min averages", xprof_stats_avg1min); | |
254 | xprof_summary_item(sentry, "Last 5 min averages", xprof_stats_avg5min); | |
255 | xprof_summary_item(sentry, "Last 30 min averages", xprof_stats_avg30min); | |
256 | xprof_summary_item(sentry, "Last 1 hour averages", xprof_stats_avg1hour); | |
257 | xprof_summary_item(sentry, "Last 5 hour averages", xprof_stats_avg5hour); | |
258 | xprof_summary_item(sentry, "Last 24 hour averages", xprof_stats_avg24hour); | |
259 | } | |
260 | ||
261 | static inline void | |
262 | xprof_chk_overhead(int samples) | |
263 | { | |
264 | while (samples--) { | |
62e76326 | 265 | PROF_start(PROF_OVERHEAD); |
266 | PROF_stop(PROF_OVERHEAD); | |
88bfe092 | 267 | } |
268 | } | |
269 | ||
6b7d87bb FC |
270 | static void |
271 | xprofRegisterWithCacheManager(void) | |
272 | { | |
273 | CacheManager::GetInstance()-> | |
26ac0430 | 274 | registerAction("cpu_profile", "CPU Profiling Stats", xprof_summary, 0, 1); |
6b7d87bb FC |
275 | } |
276 | ||
26ac0430 | 277 | // FIXME: |
6852be71 FC |
278 | // this gets colled once per event. This doesn't seem to make much sense, |
279 | // does it? | |
88bfe092 | 280 | static hrtime_t now; |
281 | static void | |
282 | xprof_Init(void) | |
283 | { | |
284 | if (xprof_inited) | |
62e76326 | 285 | return; |
88bfe092 | 286 | |
287 | xprof_delta = xprof_verystart = xprof_start_t = now; | |
288 | ||
289 | xprof_inited = 1; | |
6852be71 FC |
290 | |
291 | xprofRegisterWithCacheManager(); //moved here so it's not double-init'ed | |
62ee09ca | 292 | } |
62e76326 | 293 | |
88bfe092 | 294 | void |
295 | xprof_event(void *data) | |
296 | { | |
297 | now = get_tick(); | |
298 | xprof_Init(); | |
299 | xprof_delta = now - xprof_start_t; | |
300 | xprof_start_t = now; | |
301 | xprof_events++; | |
302 | ||
303 | if (!xprof_average_delta) | |
62e76326 | 304 | xprof_average_delta = xprof_delta; |
305 | ||
88bfe092 | 306 | if (xprof_average_delta > (xprof_delta >> 1)) |
62e76326 | 307 | xprof_average_delta = xprof_average_delta - (xprof_average_delta >> 8) + (xprof_delta >> 8); |
88bfe092 | 308 | |
88bfe092 | 309 | xprof_chk_overhead(2); |
62e76326 | 310 | |
88bfe092 | 311 | xprof_average(&xprof_stats_avg24hour, 24 * 3600); |
62e76326 | 312 | |
88bfe092 | 313 | xprof_average(&xprof_stats_avg5hour, 5 * 3600); |
62e76326 | 314 | |
88bfe092 | 315 | xprof_average(&xprof_stats_avg1hour, 3600); |
62e76326 | 316 | |
88bfe092 | 317 | xprof_average(&xprof_stats_avg30min, 1800); |
62e76326 | 318 | |
88bfe092 | 319 | xprof_average(&xprof_stats_avg5min, 300); |
62e76326 | 320 | |
88bfe092 | 321 | xprof_average(&xprof_stats_avg1min, 60); |
62e76326 | 322 | |
88bfe092 | 323 | xprof_average(&xprof_stats_avg30sec, 30); |
62e76326 | 324 | |
88bfe092 | 325 | xprof_average(&xprof_stats_avg5sec, 5); |
62e76326 | 326 | |
88bfe092 | 327 | xprof_average(&xprof_stats_avg1sec, 1); |
62e76326 | 328 | |
88bfe092 | 329 | xprof_chk_overhead(30); |
62e76326 | 330 | |
88bfe092 | 331 | eventAdd("cpuProfiling", xprof_event, NULL, 1.0, 1); |
332 | } | |
333 | ||
334 | #endif /* USE_XPROF_STATS */ |