2 * Copyright (C) 1996-2015 The Squid Software Foundation and contributors
4 * Squid software is distributed under GPLv2+ license and includes
5 * contributions from numerous individuals and organizations.
6 * Please see the COPYING and CONTRIBUTORS files for details.
9 /* DEBUG: section 81 CPU Profiling Routines */
16 #include "mgr/Registration.h"
17 #include "profiler/Profiler.h"
18 #include "SquidMath.h"
23 #define MAX_SORTLIST 200
25 static hrtime_t xprof_delta
= 0;
26 static hrtime_t xprof_start_t
= 0;
27 static hrtime_t xprof_verystart
= 0;
28 static hrtime_t xprof_average_delta
= 0;
29 static int xprof_events
= 0;
30 static int xprof_inited
= 0;
31 static xprof_stats_data Totals
;
33 static TimersArray
*xprof_stats_avg1sec
= NULL
;
34 static TimersArray
*xprof_stats_avg5sec
= NULL
;
35 static TimersArray
*xprof_stats_avg30sec
= NULL
;
36 static TimersArray
*xprof_stats_avg1min
= NULL
;
37 static TimersArray
*xprof_stats_avg5min
= NULL
;
38 static TimersArray
*xprof_stats_avg30min
= NULL
;
39 static TimersArray
*xprof_stats_avg1hour
= NULL
;
40 static TimersArray
*xprof_stats_avg5hour
= NULL
;
41 static TimersArray
*xprof_stats_avg24hour
= NULL
;
43 static xprof_stats_node
*sortlist
[XPROF_LAST
+ 2];
44 static void xprof_summary(StoreEntry
* sentry
);
47 xprof_reset(xprof_stats_data
* head
)
52 head
->best
= XP_NOBEST
;
59 xprof_move(xprof_stats_data
* head
, xprof_stats_data
* hist
)
61 memcpy(hist
, head
, sizeof(xprof_stats_data
));
65 xprof_comp(xprof_stats_node
** ii
, xprof_stats_node
** jj
)
67 if ((*ii
)->hist
.summ
< (*jj
)->hist
.summ
)
70 if ((*ii
)->hist
.summ
> (*jj
)->hist
.summ
)
77 xprof_sorthist(TimersArray
* xprof_list
)
79 for (int i
= 0; i
< XPROF_LAST
; ++i
) {
80 sortlist
[i
] = xprof_list
[i
];
83 qsort(&sortlist
[XPROF_PROF_UNACCOUNTED
+1], XPROF_LAST
- XPROF_PROF_UNACCOUNTED
+1, sizeof(xprof_stats_node
*), (QS
*) xprof_comp
);
86 static double time_frame
;
89 xprof_show_item(StoreEntry
* sentry
, const char *name
, xprof_stats_data
* hist
)
91 storeAppendPrintf(sentry
,
92 "%s\t %" PRIu64
"\t %" PRIu64
"\t %" PRIu64
"\t %" PRIu64
"\t %" PRIu64
"\t %.2f\t %6.3f\t\n",
96 (hist
->best
!= XP_NOBEST
? hist
->best
: 0),
97 hist
->count
? hist
->summ
/ hist
->count
: 0,
99 hist
->count
/ time_frame
,
100 Math::doublePercent((double) hist
->summ
, (double) hist
->delta
));
104 xprof_summary_item(StoreEntry
* sentry
, char const *descr
, TimersArray
* list
)
107 xprof_stats_node
**hist
;
108 xprof_stats_data
*show
;
109 xprof_reset(&Totals
);
110 xprof_sorthist(list
);
113 show
= &hist
[0]->hist
;
115 if (!hist
[0]->hist
.delta
)
116 show
= &hist
[0]->accu
;
118 time_frame
= (double) show
->delta
/ (double) xprof_average_delta
;
120 storeAppendPrintf(sentry
, "\n%s:", descr
);
122 storeAppendPrintf(sentry
, " (Cumulated time: %" PRIu64
", %.2f sec)\n",
127 storeAppendPrintf(sentry
,
128 "Probe Name\t Events\t cumulated time \t best case \t average \t worst case\t Rate / sec \t %% in int\n");
130 for (i
= 0; i
< XPROF_LAST
; ++i
) {
134 show
= &hist
[i
]->hist
;
139 xprof_show_item(sentry
, hist
[i
]->name
, show
);
141 Totals
.count
+= show
->count
;
143 Totals
.summ
+= show
->summ
;
145 Totals
.best
+= (show
->best
!= XP_NOBEST
? show
->best
: 0);
147 Totals
.worst
+= show
->worst
;
149 Totals
.delta
= (show
->delta
> Totals
.delta
? show
->delta
: Totals
.delta
);
152 xprof_show_item(sentry
, "TOTALS", &Totals
);
156 xprof_average(TimersArray
** list
, int secs
)
159 TimersArray
*head
= xprof_Timers
;
163 int doavg
= (xprof_events
% secs
);
166 *list
= (TimersArray
*)xcalloc(XPROF_LAST
, sizeof(xprof_stats_node
));
172 for (i
= 0; i
< XPROF_LAST
; ++i
) {
173 hist
[i
]->name
= head
[i
]->name
;
174 hist
[i
]->accu
.summ
+= head
[i
]->accu
.summ
;
175 hist
[i
]->accu
.count
+= head
[i
]->accu
.count
; /* accumulate multisec */
177 if (!hist
[i
]->accu
.best
)
178 hist
[i
]->accu
.best
= head
[i
]->accu
.best
;
180 if (hist
[i
]->accu
.best
> head
[i
]->accu
.best
)
181 hist
[i
]->accu
.best
= head
[i
]->accu
.best
;
183 if (hist
[i
]->accu
.worst
< head
[i
]->accu
.worst
)
184 hist
[i
]->accu
.worst
= head
[i
]->accu
.worst
;
186 hist
[i
]->accu
.delta
+= xprof_delta
;
189 /* we have X seconds accumulated */
190 xprof_move(&hist
[i
]->accu
, &hist
[i
]->hist
);
191 xprof_reset(&hist
[i
]->accu
);
193 hist
[i
]->accu
.start
= now
;
196 /* reset 0sec counters */
198 keep
= head
[i
]->accu
.start
;
199 xprof_move(&head
[i
]->accu
, &head
[i
]->hist
);
200 xprof_reset(&head
[i
]->accu
);
201 hist
[i
]->accu
.delta
= 0;
202 head
[i
]->accu
.start
= keep
;
208 xprof_summary(StoreEntry
* sentry
)
210 hrtime_t now
= get_tick();
212 storeAppendPrintf(sentry
, "CPU Profiling Statistics:\n");
213 storeAppendPrintf(sentry
,
214 " (CPU times are in arbitrary units, most probably in CPU clock ticks)\n");
215 storeAppendPrintf(sentry
,
216 "Probe Name\t Event Count\t last Interval \t Avg Interval \t since squid start \t (since system boot) \n");
217 storeAppendPrintf(sentry
, "Total\t %lu\t %" PRIu64
" \t %" PRIu64
" \t %" PRIu64
" \t %" PRIu64
"\n",
218 (long unsigned) xprof_events
,
221 now
- xprof_verystart
,
224 xprof_summary_item(sentry
, "Last 1 sec averages", xprof_stats_avg1sec
);
225 xprof_summary_item(sentry
, "Last 5 sec averages", xprof_stats_avg5sec
);
226 xprof_summary_item(sentry
, "Last 30 sec averages", xprof_stats_avg30sec
);
227 xprof_summary_item(sentry
, "Last 1 min averages", xprof_stats_avg1min
);
228 xprof_summary_item(sentry
, "Last 5 min averages", xprof_stats_avg5min
);
229 xprof_summary_item(sentry
, "Last 30 min averages", xprof_stats_avg30min
);
230 xprof_summary_item(sentry
, "Last 1 hour averages", xprof_stats_avg1hour
);
231 xprof_summary_item(sentry
, "Last 5 hour averages", xprof_stats_avg5hour
);
232 xprof_summary_item(sentry
, "Last 24 hour averages", xprof_stats_avg24hour
);
236 xprof_chk_overhead(int samples
)
239 PROF_start(PROF_OVERHEAD
);
240 PROF_stop(PROF_OVERHEAD
);
245 xprofRegisterWithCacheManager(void)
247 Mgr::RegisterAction("cpu_profile", "CPU Profiling Stats", xprof_summary
, 0, 1);
251 // this gets colled once per event. This doesn't seem to make much sense,
260 xprof_delta
= xprof_verystart
= xprof_start_t
= now
;
264 xprofRegisterWithCacheManager(); //moved here so it's not double-init'ed
268 xprof_event(void *data
)
272 xprof_delta
= now
- xprof_start_t
;
276 if (!xprof_average_delta
)
277 xprof_average_delta
= xprof_delta
;
279 if (xprof_average_delta
> (xprof_delta
>> 1))
280 xprof_average_delta
= xprof_average_delta
- (xprof_average_delta
>> 8) + (xprof_delta
>> 8);
282 xprof_chk_overhead(2);
284 xprof_average(&xprof_stats_avg24hour
, 24 * 3600);
286 xprof_average(&xprof_stats_avg5hour
, 5 * 3600);
288 xprof_average(&xprof_stats_avg1hour
, 3600);
290 xprof_average(&xprof_stats_avg30min
, 1800);
292 xprof_average(&xprof_stats_avg5min
, 300);
294 xprof_average(&xprof_stats_avg1min
, 60);
296 xprof_average(&xprof_stats_avg30sec
, 30);
298 xprof_average(&xprof_stats_avg5sec
, 5);
300 xprof_average(&xprof_stats_avg1sec
, 1);
302 xprof_chk_overhead(30);
304 eventAdd("cpuProfiling", xprof_event
, NULL
, 1.0, 1);
307 #endif /* USE_XPROF_STATS */