1 /*
2 * httperf -- a tool for measuring web server performance
3 * Copyright 2000-2007 Hewlett-Packard Company
4 *
5 * This file is part of httperf, a web server performance measurment tool.
6 *
7 * This program is free software; you can redistribute it and/or modify it
8 * under the terms of the GNU General Public License as published by the Free
9 * Software Foundation; either version 2 of the License, or (at your option)
10 * any later version.
11 *
12 * In addition, as a special exception, the copyright holders give permission
13 * to link the code of this work with the OpenSSL project's "OpenSSL" library
14 * (or with modified versions of it that use the same license as the "OpenSSL"
15 * library), and distribute linked combinations including the two. You must
16 * obey the GNU General Public License in all respects for all of the code
17 * used other than "OpenSSL". If you modify this file, you may extend this
18 * exception to your version of the file, but you are not obligated to do so.
19 * If you do not wish to do so, delete this exception statement from your
20 * version.
21 *
22 * This program is distributed in the hope that it will be useful, but WITHOUT
23 * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
24 * FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License for
25 * more details.
26 *
27 * You should have received a copy of the GNU General Public License along
28 * with this program; if not, write to the Free Software Foundation, Inc., 51
29 * Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA
30 */
31
32 /*
33 * Basic statistics collector.
34 */
35
36 #include "config.h"
37
38 #include <assert.h>
39 #include <errno.h>
40 #include <float.h>
41 #include <stdio.h>
42
43 #include <generic_types.h>
44 #include <sys/resource.h>
45
46 #include <object.h>
47 #include <timer.h>
48 #include <httperf.h>
49 #include <call.h>
50 #include <conn.h>
51 #include <localevent.h>
52 #include <stats.h>
53
54 /*
55 * Increase this if it does not cover at least 50% of all response times.
56 */
57 #define MAX_LIFETIME 100.0 /* max. conn. lifetime in seconds */
58 #define BIN_WIDTH 1e-3
59 #define NUM_BINS ((u_int) (MAX_LIFETIME / BIN_WIDTH))
60
61 static struct {
62 u_long num_conns_issued; /* total # of connections * issued */
63 u_long num_replies[6]; /* completion count per status class */
64 u_long num_200; /* total # of 200 responses */
65 u_long num_302; /* total # of 302 responses */
66 u_long num_client_timeouts; /* # of client timeouts */
67 u_long num_sock_fdunavail; /* # of times out of *
68 * filedescriptors */
69 u_long num_sock_ftabfull; /* # of times file table was full */
70 u_long num_sock_refused; /* # of ECONNREFUSED */
71 u_long num_sock_reset; /* # of ECONNRESET */
72 u_long num_sock_timeouts; /* # of ETIMEDOUT */
73 u_long num_sock_addrunavail; /* # of EADDRNOTAVAIL */
74 u_long num_other_errors; /* # of other errors */
75 u_long max_conns; /* max # of concurrent connections */
76
77 u_long num_lifetimes;
78 Time conn_lifetime_sum; /* sum of connection lifetimes */
79 Time conn_lifetime_sum2; /* sum of connection lifetimes
80 * squared */
81 Time conn_lifetime_min; /* minimum connection lifetime */
82 Time conn_lifetime_max; /* maximum connection lifetime */
83
84 u_long num_reply_rates;
85 Time reply_rate_sum;
86 Time reply_rate_sum2;
87 Time reply_rate_min;
88 Time reply_rate_max;
89
90 u_long num_connects; /* # of completed connect()s */
91 Time conn_connect_sum; /* sum of connect times */
92
93 u_long num_responses;
94 Time call_response_sum; /* sum of response times */
95
96 Time call_xfer_sum; /* sum of response times */
97
98 u_long num_sent; /* # of requests sent */
99 size_t req_bytes_sent;
100
101 u_long num_received; /* # of replies received */
102 u_wide hdr_bytes_received; /* sum of all header bytes */
103 u_wide reply_bytes_received; /* sum of all data bytes */
104 u_wide footer_bytes_received; /* sum of all footer bytes */
105
106 u_int conn_lifetime_hist[NUM_BINS]; /* histogram of
107 * connection lifetimes */
108 } basic;
109
110 static u_long num_active_conns;
111 static u_long num_replies; /* # of replies received in this interval */
112
113 static void
perf_sample(Event_Type et,Object * obj,Any_Type reg_arg,Any_Type call_arg)114 perf_sample(Event_Type et, Object * obj, Any_Type reg_arg, Any_Type call_arg)
115 {
116 Time weight = call_arg.d;
117 double rate;
118
119 assert(et == EV_PERF_SAMPLE);
120
121 rate = weight * num_replies;
122
123 if (verbose)
124 printf("reply-rate = %-8.1f\n", rate);
125
126 basic.reply_rate_sum += rate;
127 basic.reply_rate_sum2 += SQUARE(rate);
128 if (rate < basic.reply_rate_min)
129 basic.reply_rate_min = rate;
130 if (rate > basic.reply_rate_max)
131 basic.reply_rate_max = rate;
132 ++basic.num_reply_rates;
133
134 /*
135 * prepare for next sample interval:
136 */
137 num_replies = 0;
138 }
139
140 static void
conn_timeout(Event_Type et,Object * obj,Any_Type reg_arg,Any_Type call_arg)141 conn_timeout(Event_Type et, Object * obj, Any_Type reg_arg, Any_Type call_arg)
142 {
143 assert(et == EV_CONN_TIMEOUT);
144
145 ++basic.num_client_timeouts;
146 }
147
148 static void
conn_fail(Event_Type et,Object * obj,Any_Type reg_arg,Any_Type call_arg)149 conn_fail(Event_Type et, Object * obj, Any_Type reg_arg, Any_Type call_arg)
150 {
151 static int first_time = 1;
152 int err = call_arg.i;
153
154 assert(et == EV_CONN_FAILED);
155
156 switch (err) {
157 #ifdef __linux__
158 case EINVAL: /* Linux has a strange way of saying "out of
159 * * fds"... */
160 #endif
161 case EMFILE:
162 ++basic.num_sock_fdunavail;
163 break;
164 case ENFILE:
165 ++basic.num_sock_ftabfull;
166 break;
167 case ECONNREFUSED:
168 ++basic.num_sock_refused;
169 break;
170 case ETIMEDOUT:
171 ++basic.num_sock_timeouts;
172 break;
173
174 case EPIPE:
175 case ECONNRESET:
176 ++basic.num_sock_reset;
177 break;
178
179 default:
180 if (first_time) {
181 first_time = 0;
182 fprintf(stderr,
183 "%s: connection failed with unexpected error %d\n",
184 prog_name, errno);
185 }
186 ++basic.num_other_errors;
187 break;
188 }
189 }
190
191 static void
conn_created(Event_Type et,Object * obj,Any_Type reg_arg,Any_Type c_arg)192 conn_created(Event_Type et, Object * obj, Any_Type reg_arg, Any_Type c_arg)
193 {
194 ++num_active_conns;
195 if (num_active_conns > basic.max_conns)
196 basic.max_conns = num_active_conns;
197 }
198
199 static void
conn_connecting(Event_Type et,Object * obj,Any_Type reg_arg,Any_Type c_arg)200 conn_connecting(Event_Type et, Object * obj, Any_Type reg_arg, Any_Type c_arg)
201 {
202 Conn *s = (Conn *) obj;
203
204 assert(et == EV_CONN_CONNECTING && object_is_conn(s));
205
206 s->basic.time_connect_start = timer_now();
207 ++basic.num_conns_issued;
208 }
209
210 static void
conn_connected(Event_Type et,Object * obj,Any_Type reg_arg,Any_Type call_arg)211 conn_connected(Event_Type et, Object * obj, Any_Type reg_arg,
212 Any_Type call_arg)
213 {
214 Conn *s = (Conn *) obj;
215
216 assert(et == EV_CONN_CONNECTED && object_is_conn(s));
217 basic.conn_connect_sum += timer_now() - s->basic.time_connect_start;
218 ++basic.num_connects;
219 }
220
221 static void
conn_destroyed(Event_Type et,Object * obj,Any_Type reg_arg,Any_Type c_arg)222 conn_destroyed(Event_Type et, Object * obj, Any_Type reg_arg, Any_Type c_arg)
223 {
224 Conn *s = (Conn *) obj;
225 Time lifetime;
226 u_int bin;
227
228 assert(et == EV_CONN_DESTROYED && object_is_conn(s)
229 && num_active_conns > 0);
230
231 if (s->basic.num_calls_completed > 0) {
232 lifetime = timer_now() - s->basic.time_connect_start;
233 basic.conn_lifetime_sum += lifetime;
234 basic.conn_lifetime_sum2 += SQUARE(lifetime);
235 if (lifetime < basic.conn_lifetime_min)
236 basic.conn_lifetime_min = lifetime;
237 if (lifetime > basic.conn_lifetime_max)
238 basic.conn_lifetime_max = lifetime;
239 ++basic.num_lifetimes;
240
241 bin = lifetime * NUM_BINS / MAX_LIFETIME;
242 if (bin >= NUM_BINS)
243 bin = NUM_BINS;
244 ++basic.conn_lifetime_hist[bin];
245 }
246 --num_active_conns;
247 }
248
249 static void
send_start(Event_Type et,Object * obj,Any_Type reg_arg,Any_Type call_arg)250 send_start(Event_Type et, Object * obj, Any_Type reg_arg, Any_Type call_arg)
251 {
252 Call *c = (Call *) obj;
253
254 assert(et == EV_CALL_SEND_START && object_is_call(c));
255
256 c->basic.time_send_start = timer_now();
257 }
258
259 static void
send_stop(Event_Type et,Object * obj,Any_Type reg_arg,Any_Type call_arg)260 send_stop(Event_Type et, Object * obj, Any_Type reg_arg, Any_Type call_arg)
261 {
262 Call *c = (Call *) obj;
263
264 assert(et == EV_CALL_SEND_STOP && object_is_call(c));
265
266 basic.req_bytes_sent += c->req.size;
267 ++basic.num_sent;
268 }
269
270 static void
recv_start(Event_Type et,Object * obj,Any_Type reg_arg,Any_Type call_arg)271 recv_start(Event_Type et, Object * obj, Any_Type reg_arg, Any_Type call_arg)
272 {
273 Call *c = (Call *) obj;
274 Time now;
275
276 assert(et == EV_CALL_RECV_START && object_is_call(c));
277
278 now = timer_now();
279
280 basic.call_response_sum += now - c->basic.time_send_start;
281 c->basic.time_recv_start = now;
282 ++basic.num_responses;
283
284 if (periodic_stats) {
285 if (c->reply.status == 200)
286 ++basic.num_200;
287
288 if (c->reply.status == 302)
289 ++basic.num_302;
290 }
291 }
292
293 static void
recv_stop(Event_Type et,Object * obj,Any_Type reg_arg,Any_Type call_arg)294 recv_stop(Event_Type et, Object * obj, Any_Type reg_arg, Any_Type call_arg)
295 {
296 Call *c = (Call *) obj;
297 int index;
298
299 assert(et == EV_CALL_RECV_STOP && object_is_call(c));
300 assert(c->basic.time_recv_start > 0);
301
302 basic.call_xfer_sum += timer_now() - c->basic.time_recv_start;
303
304 basic.hdr_bytes_received += c->reply.header_bytes;
305 basic.reply_bytes_received += c->reply.content_bytes;
306 basic.footer_bytes_received += c->reply.footer_bytes;
307
308 index = (c->reply.status / 100);
309 assert((unsigned) index < NELEMS(basic.num_replies));
310 ++basic.num_replies[index];
311 ++num_replies;
312
313 ++c->conn->basic.num_calls_completed;
314 }
315
316 static void
one_second_timer(struct Timer * t,Any_Type arg)317 one_second_timer(struct Timer *t, Any_Type arg)
318 {
319 static u_long prev200 = 0;
320 static u_long prev302 = 0;
321
322 printf("[%.6f s] 200=%lu, 302=%lu\n",
323 timer_now() - test_time_start,
324 basic.num_200 - prev200,
325 basic.num_302 - prev302);
326
327 prev200 = basic.num_200;
328 prev302 = basic.num_302;
329
330 timer_schedule(one_second_timer, arg, 1);
331 }
332
333 static void
init(void)334 init(void)
335 {
336 Any_Type arg;
337
338 basic.conn_lifetime_min = DBL_MAX;
339 basic.reply_rate_min = DBL_MAX;
340
341 arg.l = 0;
342 event_register_handler(EV_PERF_SAMPLE, perf_sample, arg);
343 event_register_handler(EV_CONN_FAILED, conn_fail, arg);
344 event_register_handler(EV_CONN_TIMEOUT, conn_timeout, arg);
345 event_register_handler(EV_CONN_NEW, conn_created, arg);
346 event_register_handler(EV_CONN_CONNECTING, conn_connecting, arg);
347 event_register_handler(EV_CONN_CONNECTED, conn_connected, arg);
348 event_register_handler(EV_CONN_DESTROYED, conn_destroyed, arg);
349 event_register_handler(EV_CALL_SEND_START, send_start, arg);
350 event_register_handler(EV_CALL_SEND_STOP, send_stop, arg);
351 event_register_handler(EV_CALL_RECV_START, recv_start, arg);
352 event_register_handler(EV_CALL_RECV_STOP, recv_stop, arg);
353
354 if (periodic_stats)
355 timer_schedule(one_second_timer, arg, 1);
356 }
357
358 static void
dump(void)359 dump(void)
360 {
361 Time conn_period = 0.0, call_period = 0.0;
362 Time conn_time = 0.0, resp_time = 0.0, xfer_time = 0.0;
363 Time call_size = 0.0, hdr_size = 0.0, reply_size =
364 0.0, footer_size = 0.0;
365 Time lifetime_avg = 0.0, lifetime_stddev =
366 0.0, lifetime_median = 0.0;
367 double reply_rate_avg = 0.0, reply_rate_stddev = 0.0;
368 int i;
369 u_long total_replies = 0;
370 Time delta, user, sys;
371 u_wide total_size;
372 Time time;
373 u_int n;
374
375 for (i = 1; i < NELEMS(basic.num_replies); ++i)
376 total_replies += basic.num_replies[i];
377
378 delta = test_time_stop - test_time_start;
379
380 if (verbose > 1) {
381 printf("\nConnection lifetime histogram (time in ms):\n");
382 for (i = 0; i < NUM_BINS; ++i)
383 if (basic.conn_lifetime_hist[i]) {
384 if (i > 0 && basic.conn_lifetime_hist[i - 1] == 0)
385 printf("%14c\n", ':');
386 time = (i + 0.5) * BIN_WIDTH;
387 printf("%16.1f %u\n", 1e3 * time,
388 basic.conn_lifetime_hist[i]);
389 }
390 }
391
392 printf("\nTotal: connections %lu requests %lu replies %lu "
393 "test-duration %.3f s\n",
394 basic.num_conns_issued, basic.num_sent, total_replies, delta);
395
396 putchar('\n');
397
398 if (basic.num_conns_issued)
399 conn_period = delta / basic.num_conns_issued;
400 printf("Connection rate: %.1f conn/s (%.1f ms/conn, "
401 "<=%lu concurrent connections)\n",
402 basic.num_conns_issued / delta, 1e3 * conn_period,
403 basic.max_conns);
404
405 if (basic.num_lifetimes > 0) {
406 lifetime_avg = (basic.conn_lifetime_sum / basic.num_lifetimes);
407 if (basic.num_lifetimes > 1)
408 lifetime_stddev = STDDEV(basic.conn_lifetime_sum,
409 basic.conn_lifetime_sum2,
410 basic.num_lifetimes);
411 n = 0;
412 for (i = 0; i < NUM_BINS; ++i) {
413 n += basic.conn_lifetime_hist[i];
414 if (n >= 0.5 * basic.num_lifetimes) {
415 lifetime_median = (i + 0.5) * BIN_WIDTH;
416 break;
417 }
418 }
419 }
420 printf("Connection time [ms]: min %.1f avg %.1f max %.1f median %.1f "
421 "stddev %.1f\n",
422 basic.num_lifetimes > 0 ? 1e3 * basic.conn_lifetime_min : 0.0,
423 1e3 * lifetime_avg,
424 1e3 * basic.conn_lifetime_max, 1e3 * lifetime_median,
425 1e3 * lifetime_stddev);
426 if (basic.num_connects > 0)
427 conn_time = basic.conn_connect_sum / basic.num_connects;
428 printf("Connection time [ms]: connect %.1f\n", 1e3 * conn_time);
429 printf("Connection length [replies/conn]: %.3f\n",
430 basic.num_lifetimes > 0
431 ? total_replies / (double) basic.num_lifetimes : 0.0);
432 putchar('\n');
433
434 if (basic.num_sent > 0)
435 call_period = delta / basic.num_sent;
436 printf("Request rate: %.1f req/s (%.1f ms/req)\n",
437 basic.num_sent / delta, 1e3 * call_period);
438
439 if (basic.num_sent)
440 call_size = basic.req_bytes_sent / basic.num_sent;
441 printf("Request size [B]: %.1f\n", call_size);
442
443 putchar('\n');
444
445 if (basic.num_reply_rates > 0) {
446 reply_rate_avg = (basic.reply_rate_sum / basic.num_reply_rates);
447 if (basic.num_reply_rates > 1)
448 reply_rate_stddev = STDDEV(basic.reply_rate_sum,
449 basic.reply_rate_sum2,
450 basic.num_reply_rates);
451 }
452 printf
453 ("Reply rate [replies/s]: min %.1f avg %.1f max %.1f stddev %.1f "
454 "(%lu samples)\n",
455 basic.num_reply_rates > 0 ? basic.reply_rate_min : 0.0,
456 reply_rate_avg, basic.reply_rate_max, reply_rate_stddev,
457 basic.num_reply_rates);
458
459 if (basic.num_responses > 0)
460 resp_time = basic.call_response_sum / basic.num_responses;
461 if (total_replies > 0)
462 xfer_time = basic.call_xfer_sum / total_replies;
463 printf("Reply time [ms]: response %.1f transfer %.1f\n",
464 1e3 * resp_time, 1e3 * xfer_time);
465
466 if (total_replies) {
467 hdr_size = basic.hdr_bytes_received / total_replies;
468 reply_size = basic.reply_bytes_received / total_replies;
469 footer_size = basic.footer_bytes_received / total_replies;
470 }
471 printf("Reply size [B]: header %.1f content %.1f footer %.1f "
472 "(total %.1f)\n", hdr_size, reply_size, footer_size,
473 hdr_size + reply_size + footer_size);
474
475 printf("Reply status: 1xx=%lu 2xx=%lu 3xx=%lu 4xx=%lu 5xx=%lu\n",
476 basic.num_replies[1], basic.num_replies[2],
477 basic.num_replies[3], basic.num_replies[4], basic.num_replies[5]);
478
479 putchar('\n');
480
481 if (periodic_stats) {
482 printf("Periodic stats: 200=%lu 302=%lu\n", basic.num_200, basic.num_302);
483 putchar('\n');
484 }
485
486 user = (TV_TO_SEC(test_rusage_stop.ru_utime)
487 - TV_TO_SEC(test_rusage_start.ru_utime));
488 sys = (TV_TO_SEC(test_rusage_stop.ru_stime)
489 - TV_TO_SEC(test_rusage_start.ru_stime));
490 printf
491 ("CPU time [s]: user %.2f system %.2f (user %.1f%% system %.1f%% "
492 "total %.1f%%)\n", user, sys, 100.0 * user / delta,
493 100.0 * sys / delta, 100.0 * (user + sys) / delta);
494
495 total_size = (basic.req_bytes_sent
496 + basic.hdr_bytes_received + basic.reply_bytes_received);
497 printf("Net I/O: %.1f KB/s (%.1f*10^6 bps)\n",
498 total_size / delta / 1024.0, 8e-6 * total_size / delta);
499
500 putchar('\n');
501
502 printf("Errors: total %lu client-timo %lu socket-timo %lu "
503 "connrefused %lu connreset %lu\n"
504 "Errors: fd-unavail %lu addrunavail %lu ftab-full %lu other %lu\n",
505 (basic.num_client_timeouts + basic.num_sock_timeouts
506 + basic.num_sock_fdunavail + basic.num_sock_ftabfull
507 + basic.num_sock_refused + basic.num_sock_reset
508 + basic.num_sock_addrunavail + basic.num_other_errors),
509 basic.num_client_timeouts, basic.num_sock_timeouts,
510 basic.num_sock_refused, basic.num_sock_reset,
511 basic.num_sock_fdunavail, basic.num_sock_addrunavail,
512 basic.num_sock_ftabfull, basic.num_other_errors);
513 }
514
515 Stat_Collector stats_basic = {
516 "Basic statistics",
517 init,
518 no_op,
519 no_op,
520 dump
521 };
522