ProfStats.cc
Go to the documentation of this file.
1 /*
2  * Copyright (C) 1996-2017 The Squid Software Foundation and contributors
3  *
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.
7  */
8 
9 /* DEBUG: section 81 CPU Profiling Routines */
10 
11 #include "squid.h"
12 
13 #if USE_XPROF_STATS
14 
15 #include "event.h"
16 #include "mgr/Registration.h"
17 #include "profiler/Profiler.h"
18 #include "SquidMath.h"
19 #include "Store.h"
20 
21 /* Private stuff */
22 
23 #define MAX_SORTLIST 200
24 
25 static hrtime_t xprof_delta = 0;
29 static int xprof_events = 0;
30 static int xprof_inited = 0;
32 
42 
43 static xprof_stats_node *sortlist[XPROF_LAST + 2];
44 static void xprof_summary(StoreEntry * sentry);
45 
46 static void
48 {
49  head->summ = 0;
50  head->count = 0;
51  head->delta = 0;
52  head->best = XP_NOBEST;
53  head->worst = 0;
54  head->start = 0;
55  head->stop = 0;
56 }
57 
58 static void
60 {
61  memcpy(hist, head, sizeof(xprof_stats_data));
62 }
63 
64 static int
65 xprof_comp(const void *A, const void *B)
66 {
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));
69 
70  if (ii->hist.summ < jj->hist.summ)
71  return (1);
72 
73  if (ii->hist.summ > jj->hist.summ)
74  return (-1);
75 
76  return (0);
77 }
78 
79 static void
81 {
82  for (int i = 0; i < XPROF_LAST; ++i) {
83  sortlist[i] = xprof_list[i];
84  }
85 
86  qsort(&sortlist[XPROF_PROF_UNACCOUNTED+1], XPROF_LAST - XPROF_PROF_UNACCOUNTED+1, sizeof(xprof_stats_node *), xprof_comp);
87 }
88 
89 static double time_frame;
90 
91 static void
92 xprof_show_item(StoreEntry * sentry, const char *name, xprof_stats_data * hist)
93 {
94  storeAppendPrintf(sentry,
95  "%s\t %" PRIu64 "\t %" PRIu64 "\t %" PRIu64 "\t %" PRIu64 "\t %" PRIu64 "\t %.2f\t %6.3f\t\n",
96  name,
97  hist->count,
98  hist->summ,
99  (hist->best != XP_NOBEST ? hist->best : 0),
100  hist->count ? hist->summ / hist->count : 0,
101  hist->worst,
102  hist->count / time_frame,
103  Math::doublePercent((double) hist->summ, (double) hist->delta));
104 }
105 
106 static void
107 xprof_summary_item(StoreEntry * sentry, char const *descr, TimersArray * list)
108 {
109  int i;
110  xprof_stats_node **hist;
111  xprof_stats_data *show;
112  xprof_reset(&Totals);
113  xprof_sorthist(list);
114  hist = &sortlist[0];
115 
116  show = &hist[0]->hist;
117 
118  if (!hist[0]->hist.delta)
119  show = &hist[0]->accu;
120 
121  time_frame = (double) show->delta / (double) xprof_average_delta;
122 
123  storeAppendPrintf(sentry, "\n%s:", descr);
124 
125  storeAppendPrintf(sentry, " (Cumulated time: %" PRIu64 ", %.2f sec)\n",
126  show->delta,
127  time_frame
128  );
129 
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");
132 
133  for (i = 0; i < XPROF_LAST; ++i) {
134  if (!hist[i]->name)
135  continue;
136 
137  show = &hist[i]->hist;
138 
139  if (!show->count)
140  continue;
141 
142  xprof_show_item(sentry, hist[i]->name, show);
143 
144  Totals.count += show->count;
145 
146  Totals.summ += show->summ;
147 
148  Totals.best += (show->best != XP_NOBEST ? show->best : 0);
149 
150  Totals.worst += show->worst;
151 
152  Totals.delta = (show->delta > Totals.delta ? show->delta : Totals.delta);
153  }
154 
155  xprof_show_item(sentry, "TOTALS", &Totals);
156 }
157 
158 static void
159 xprof_average(TimersArray ** list, int secs)
160 {
161  int i;
163  TimersArray *hist;
164  hrtime_t now;
165  hrtime_t keep;
166  int doavg = (xprof_events % secs);
167 
168  if (!*list)
169  *list = (TimersArray *)xcalloc(XPROF_LAST, sizeof(xprof_stats_node));
170 
171  hist = *list;
172 
173  now = get_tick();
174 
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 */
179 
180  if (!hist[i]->accu.best)
181  hist[i]->accu.best = head[i]->accu.best;
182 
183  if (hist[i]->accu.best > head[i]->accu.best)
184  hist[i]->accu.best = head[i]->accu.best;
185 
186  if (hist[i]->accu.worst < head[i]->accu.worst)
187  hist[i]->accu.worst = head[i]->accu.worst;
188 
189  hist[i]->accu.delta += xprof_delta;
190 
191  if (!doavg) {
192  /* we have X seconds accumulated */
193  xprof_move(&hist[i]->accu, &hist[i]->hist);
194  xprof_reset(&hist[i]->accu);
195 
196  hist[i]->accu.start = now;
197  }
198 
199  /* reset 0sec counters */
200  if (secs == 1) {
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;
206  }
207  }
208 }
209 
210 void
212 {
213  hrtime_t now = get_tick();
214 
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,
222  xprof_delta,
224  now - xprof_verystart,
225  now);
226 
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);
236 }
237 
238 static inline void
239 xprof_chk_overhead(int samples)
240 {
241  while (samples--) {
242  PROF_start(PROF_OVERHEAD);
243  PROF_stop(PROF_OVERHEAD);
244  }
245 }
246 
247 static void
249 {
250  Mgr::RegisterAction("cpu_profile", "CPU Profiling Stats", xprof_summary, 0, 1);
251 }
252 
253 // FIXME:
254 // this gets colled once per event. This doesn't seem to make much sense,
255 // does it?
256 static hrtime_t now;
257 static void
259 {
260  if (xprof_inited)
261  return;
262 
264 
265  xprof_inited = 1;
266 
267  xprofRegisterWithCacheManager(); //moved here so it's not double-init'ed
268 }
269 
270 void
272 {
273  now = get_tick();
274  xprof_Init();
276  xprof_start_t = now;
277  ++xprof_events;
278 
279  if (!xprof_average_delta)
281 
282  if (xprof_average_delta > (xprof_delta >> 1))
284 
286 
288 
290 
292 
294 
296 
298 
300 
302 
304 
305  xprof_chk_overhead(30);
306 
307  eventAdd("cpuProfiling", xprof_event, NULL, 1.0, 1);
308 }
309 
310 #endif /* USE_XPROF_STATS */
311 
static void xprof_sorthist(TimersArray *xprof_list)
Definition: ProfStats.cc:80
static void xprof_reset(xprof_stats_data *head)
Definition: ProfStats.cc:47
static TimersArray * xprof_stats_avg5sec
Definition: ProfStats.cc:34
static hrtime_t xprof_average_delta
Definition: ProfStats.cc:28
static uint32 B
Definition: md4.c:43
static void xprof_show_item(StoreEntry *sentry, const char *name, xprof_stats_data *hist)
Definition: ProfStats.cc:92
#define xcalloc
Definition: membanger.c:57
void xprof_event(void *data)
Definition: ProfStats.cc:271
static void xprof_chk_overhead(int samples)
Definition: ProfStats.cc:239
xprof_stats_node TimersArray[1]
Definition: Profiler.h:52
int i
Definition: membanger.c:49
static void xprof_Init(void)
Definition: ProfStats.cc:258
static xprof_stats_data Totals
Definition: ProfStats.cc:31
static TimersArray * xprof_stats_avg24hour
Definition: ProfStats.cc:41
hrtime_t count
Definition: Profiler.h:41
static int xprof_comp(const void *A, const void *B)
Definition: ProfStats.cc:65
static hrtime_t xprof_start_t
Definition: ProfStats.cc:26
static hrtime_t xprof_delta
Definition: ProfStats.cc:25
static void xprof_summary(StoreEntry *sentry)
Definition: ProfStats.cc:211
hrtime_t delta
Definition: Profiler.h:38
static TimersArray * xprof_stats_avg1min
Definition: ProfStats.cc:36
hrtime_t worst
Definition: Profiler.h:40
static void xprof_summary_item(StoreEntry *sentry, char const *descr, TimersArray *list)
Definition: ProfStats.cc:107
xprof_stats_data hist
Definition: Profiler.h:49
static TimersArray * xprof_stats_avg5hour
Definition: ProfStats.cc:40
double doublePercent(const double, const double)
Definition: SquidMath.cc:25
void const char HLPCB void * data
Definition: stub_helper.cc:16
static double time_frame
Definition: ProfStats.cc:89
hrtime_t best
Definition: Profiler.h:39
static TimersArray * xprof_stats_avg1sec
Definition: ProfStats.cc:33
void RegisterAction(char const *action, char const *desc, OBJH *handler, int pw_req_flag, int atomic)
Definition: Registration.cc:16
static TimersArray * xprof_stats_avg30min
Definition: ProfStats.cc:38
static TimersArray * xprof_stats_avg5min
Definition: ProfStats.cc:37
hrtime_t start
Definition: Profiler.h:36
xprof_stats_data accu
Definition: Profiler.h:48
TimersArray * xprof_Timers
Definition: Profiler.cc:108
static uint32 A
Definition: md4.c:43
static hrtime_t xprof_verystart
Definition: ProfStats.cc:27
void eventAdd(const char *name, EVH *func, void *arg, double when, int weight, bool cbdata)
Definition: event.cc:109
#define PRIu64
Definition: types.h:120
int64_t summ
Definition: Profiler.h:43
static TimersArray * xprof_stats_avg30sec
Definition: ProfStats.cc:35
#define PROF_start(probename)
Definition: Profiler.h:62
hrtime_t stop
Definition: Profiler.h:37
static void xprofRegisterWithCacheManager(void)
Definition: ProfStats.cc:248
static void xprof_move(xprof_stats_data *head, xprof_stats_data *hist)
Definition: ProfStats.cc:59
static int xprof_events
Definition: ProfStats.cc:29
#define PROF_stop(probename)
Definition: Profiler.h:63
static TimersArray * xprof_stats_avg1hour
Definition: ProfStats.cc:39
static hrtime_t now
Definition: ProfStats.cc:256
int64_t hrtime_t
Definition: get_tick.h:19
void storeAppendPrintf(StoreEntry *e, const char *fmt,...)
Definition: store.cc:904
static void xprof_average(TimersArray **list, int secs)
Definition: ProfStats.cc:159
squidaio_request_t * head
Definition: aiops.cc:127
#define NULL
Definition: types.h:166
#define XP_NOBEST
Definition: Profiler.h:29
static int xprof_inited
Definition: ProfStats.cc:30

 

Introduction

Documentation

Support

Miscellaneous

Web Site Translations

Mirrors