2 * Copyright (C) 1996-2018 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(const void *A
, const void *B
)
67 const xprof_stats_node
*ii
= *(static_cast<const xprof_stats_node
* const *>(A
));
68 const xprof_stats_node
*jj
= *(static_cast<const xprof_stats_node
* const *>(B
));
70 if (ii
->hist
.summ
< jj
->hist
.summ
)
73 if (ii
->hist
.summ
> jj
->hist
.summ
)
80 xprof_sorthist(TimersArray
* xprof_list
)
82 for (int i
= 0; i
< XPROF_LAST
; ++i
) {
83 sortlist
[i
] = xprof_list
[i
];
86 qsort(&sortlist
[XPROF_PROF_UNACCOUNTED
+1], XPROF_LAST
- XPROF_PROF_UNACCOUNTED
+1, sizeof(xprof_stats_node
*), xprof_comp
);
89 static double time_frame
;
92 xprof_show_item(StoreEntry
* sentry
, const char *name
, xprof_stats_data
* hist
)
94 storeAppendPrintf(sentry
,
95 "%s\t %" PRIu64
"\t %" PRIu64
"\t %" PRIu64
"\t %" PRIu64
"\t %" PRIu64
"\t %.2f\t %6.3f\t\n",
99 (hist
->best
!= XP_NOBEST
? hist
->best
: 0),
100 hist
->count
? hist
->summ
/ hist
->count
: 0,
102 hist
->count
/ time_frame
,
103 Math::doublePercent((double) hist
->summ
, (double) hist
->delta
));
107 xprof_summary_item(StoreEntry
* sentry
, char const *descr
, TimersArray
* list
)
110 xprof_stats_node
**hist
;
111 xprof_stats_data
*show
;
112 xprof_reset(&Totals
);
113 xprof_sorthist(list
);
116 show
= &hist
[0]->hist
;
118 if (!hist
[0]->hist
.delta
)
119 show
= &hist
[0]->accu
;
121 time_frame
= (double) show
->delta
/ (double) xprof_average_delta
;
123 storeAppendPrintf(sentry
, "\n%s:", descr
);
125 storeAppendPrintf(sentry
, " (Cumulated time: %" PRIu64
", %.2f sec)\n",
130 storeAppendPrintf(sentry
,
131 "Probe Name\t Events\t cumulated time \t best case \t average \t worst case\t Rate / sec \t %% in int\n");
133 for (i
= 0; i
< XPROF_LAST
; ++i
) {
137 show
= &hist
[i
]->hist
;
142 xprof_show_item(sentry
, hist
[i
]->name
, show
);
144 Totals
.count
+= show
->count
;
146 Totals
.summ
+= show
->summ
;
148 Totals
.best
+= (show
->best
!= XP_NOBEST
? show
->best
: 0);
150 Totals
.worst
+= show
->worst
;
152 Totals
.delta
= (show
->delta
> Totals
.delta
? show
->delta
: Totals
.delta
);
155 xprof_show_item(sentry
, "TOTALS", &Totals
);
159 xprof_average(TimersArray
** list
, int secs
)
162 TimersArray
*head
= xprof_Timers
;
166 int doavg
= (xprof_events
% secs
);
169 *list
= (TimersArray
*)xcalloc(XPROF_LAST
, sizeof(xprof_stats_node
));
175 for (i
= 0; i
< XPROF_LAST
; ++i
) {
176 hist
[i
]->name
= head
[i
]->name
;
177 hist
[i
]->accu
.summ
+= head
[i
]->accu
.summ
;
178 hist
[i
]->accu
.count
+= head
[i
]->accu
.count
; /* accumulate multisec */
180 if (!hist
[i
]->accu
.best
)
181 hist
[i
]->accu
.best
= head
[i
]->accu
.best
;
183 if (hist
[i
]->accu
.best
> head
[i
]->accu
.best
)
184 hist
[i
]->accu
.best
= head
[i
]->accu
.best
;
186 if (hist
[i
]->accu
.worst
< head
[i
]->accu
.worst
)
187 hist
[i
]->accu
.worst
= head
[i
]->accu
.worst
;
189 hist
[i
]->accu
.delta
+= xprof_delta
;
192 /* we have X seconds accumulated */
193 xprof_move(&hist
[i
]->accu
, &hist
[i
]->hist
);
194 xprof_reset(&hist
[i
]->accu
);
196 hist
[i
]->accu
.start
= now
;
199 /* reset 0sec counters */
201 keep
= head
[i
]->accu
.start
;
202 xprof_move(&head
[i
]->accu
, &head
[i
]->hist
);
203 xprof_reset(&head
[i
]->accu
);
204 hist
[i
]->accu
.delta
= 0;
205 head
[i
]->accu
.start
= keep
;
211 xprof_summary(StoreEntry
* sentry
)
213 hrtime_t now
= get_tick();
215 storeAppendPrintf(sentry
, "CPU Profiling Statistics:\n");
216 storeAppendPrintf(sentry
,
217 " (CPU times are in arbitrary units, most probably in CPU clock ticks)\n");
218 storeAppendPrintf(sentry
,
219 "Probe Name\t Event Count\t last Interval \t Avg Interval \t since squid start \t (since system boot) \n");
220 storeAppendPrintf(sentry
, "Total\t %lu\t %" PRIu64
" \t %" PRIu64
" \t %" PRIu64
" \t %" PRIu64
"\n",
221 (long unsigned) xprof_events
,
224 now
- xprof_verystart
,
227 xprof_summary_item(sentry
, "Last 1 sec averages", xprof_stats_avg1sec
);
228 xprof_summary_item(sentry
, "Last 5 sec averages", xprof_stats_avg5sec
);
229 xprof_summary_item(sentry
, "Last 30 sec averages", xprof_stats_avg30sec
);
230 xprof_summary_item(sentry
, "Last 1 min averages", xprof_stats_avg1min
);
231 xprof_summary_item(sentry
, "Last 5 min averages", xprof_stats_avg5min
);
232 xprof_summary_item(sentry
, "Last 30 min averages", xprof_stats_avg30min
);
233 xprof_summary_item(sentry
, "Last 1 hour averages", xprof_stats_avg1hour
);
234 xprof_summary_item(sentry
, "Last 5 hour averages", xprof_stats_avg5hour
);
235 xprof_summary_item(sentry
, "Last 24 hour averages", xprof_stats_avg24hour
);
239 xprof_chk_overhead(int samples
)
242 PROF_start(PROF_OVERHEAD
);
243 PROF_stop(PROF_OVERHEAD
);
248 xprofRegisterWithCacheManager(void)
250 Mgr::RegisterAction("cpu_profile", "CPU Profiling Stats", xprof_summary
, 0, 1);
254 // this gets colled once per event. This doesn't seem to make much sense,
263 xprof_delta
= xprof_verystart
= xprof_start_t
= now
;
267 xprofRegisterWithCacheManager(); //moved here so it's not double-init'ed
271 xprof_event(void *data
)
275 xprof_delta
= now
- xprof_start_t
;
279 if (!xprof_average_delta
)
280 xprof_average_delta
= xprof_delta
;
282 if (xprof_average_delta
> (xprof_delta
>> 1))
283 xprof_average_delta
= xprof_average_delta
- (xprof_average_delta
>> 8) + (xprof_delta
>> 8);
285 xprof_chk_overhead(2);
287 xprof_average(&xprof_stats_avg24hour
, 24 * 3600);
289 xprof_average(&xprof_stats_avg5hour
, 5 * 3600);
291 xprof_average(&xprof_stats_avg1hour
, 3600);
293 xprof_average(&xprof_stats_avg30min
, 1800);
295 xprof_average(&xprof_stats_avg5min
, 300);
297 xprof_average(&xprof_stats_avg1min
, 60);
299 xprof_average(&xprof_stats_avg30sec
, 30);
301 xprof_average(&xprof_stats_avg5sec
, 5);
303 xprof_average(&xprof_stats_avg1sec
, 1);
305 xprof_chk_overhead(30);
307 eventAdd("cpuProfiling", xprof_event
, NULL
, 1.0, 1);
310 #endif /* USE_XPROF_STATS */