/src/h2o/lib/handler/status/durations.c

Source (jump to first uncovered line)
/*
 * Copyright (c) 2016 Fastly
 *
 * Permission is hereby granted, free of charge, to any person obtaining a copy
 * of this software and associated documentation files (the "Software"), to
 * deal in the Software without restriction, including without limitation the
 * rights to use, copy, modify, merge, publish, distribute, sublicense, and/or
 * sell copies of the Software, and to permit persons to whom the Software is
 * furnished to do so, subject to the following conditions:
 *
 * The above copyright notice and this permission notice shall be included in
 * all copies or substantial portions of the Software.
 *
 * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
 * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
 * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
 * AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
 * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING
 * FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS
 * IN THE SOFTWARE.
 */

#include "h2o.h"
#include "gkc.h"
#include <inttypes.h>
#include <pthread.h>

#define GK_EPSILON 0.01

struct st_duration_stats_t {
    struct gkc_summary *connect_time;
    struct gkc_summary *header_time;
    struct gkc_summary *body_time;
    struct gkc_summary *request_total_time;
    struct gkc_summary *process_time;
    struct gkc_summary *response_time;
    struct gkc_summary *total_time;

    /**
     * average event loop latency per worker thread
     */
    H2O_VECTOR(uint64_t) evloop_latency_nanosec;
};

struct st_duration_agg_stats_t {
    struct st_duration_stats_t stats;
    pthread_mutex_t mutex;
};

static h2o_logger_t *durations_logger;
static void durations_status_per_thread(void *priv, h2o_context_t *ctx)
{
    struct st_duration_agg_stats_t *agg_stats = priv;
    if (durations_logger) {
        struct st_duration_stats_t *ctx_stats = h2o_context_get_logger_context(ctx, durations_logger);
        pthread_mutex_lock(&agg_stats->mutex);
#define ADD_DURATION(x)                                                                                                            \
    do {                                                                                                                           \
        struct gkc_summary *tmp;                                                                                                   \
        tmp = gkc_combine(agg_stats->stats.x, ctx_stats->x);                                                                       \
        gkc_summary_free(agg_stats->stats.x);                                                                                      \
        agg_stats->stats.x = tmp;                                                                                                  \
    } while (0)
        ADD_DURATION(connect_time);
        ADD_DURATION(header_time);
        ADD_DURATION(body_time);
        ADD_DURATION(request_total_time);
        ADD_DURATION(process_time);
        ADD_DURATION(response_time);
        ADD_DURATION(total_time);
#undef ADD_DURATION

#if !H2O_USE_LIBUV
        h2o_vector_reserve(NULL, &agg_stats->stats.evloop_latency_nanosec, agg_stats->stats.evloop_latency_nanosec.size + 1);
        agg_stats->stats.evloop_latency_nanosec.entries[agg_stats->stats.evloop_latency_nanosec.size] =
            h2o_evloop_get_execution_time_nanosec(ctx->loop);
        agg_stats->stats.evloop_latency_nanosec.size++;
#endif
        pthread_mutex_unlock(&agg_stats->mutex);
    }
}

static void duration_stats_init(struct st_duration_stats_t *stats)
{
    stats->connect_time = gkc_summary_alloc(GK_EPSILON);
    stats->header_time = gkc_summary_alloc(GK_EPSILON);
    stats->body_time = gkc_summary_alloc(GK_EPSILON);
    stats->request_total_time = gkc_summary_alloc(GK_EPSILON);
    stats->process_time = gkc_summary_alloc(GK_EPSILON);
    stats->response_time = gkc_summary_alloc(GK_EPSILON);
    stats->total_time = gkc_summary_alloc(GK_EPSILON);
    memset(&stats->evloop_latency_nanosec, 0, sizeof(stats->evloop_latency_nanosec));
}

static void *durations_status_init(void)
{
    struct st_duration_agg_stats_t *agg_stats;

    agg_stats = h2o_mem_alloc(sizeof(*agg_stats));

    duration_stats_init(&agg_stats->stats);
    pthread_mutex_init(&agg_stats->mutex, NULL);

    return agg_stats;
}

static void duration_stats_free(struct st_duration_stats_t *stats)
{
    gkc_summary_free(stats->connect_time);
    gkc_summary_free(stats->header_time);
    gkc_summary_free(stats->body_time);
    gkc_summary_free(stats->request_total_time);
    gkc_summary_free(stats->process_time);
    gkc_summary_free(stats->response_time);
    gkc_summary_free(stats->total_time);
    free(stats->evloop_latency_nanosec.entries);
}

static h2o_iovec_t durations_status_final(void *priv, h2o_globalconf_t *gconf, h2o_req_t *req)
{
    struct st_duration_agg_stats_t *agg_stats = priv;
    h2o_iovec_t ret;

#define BUFSIZE 16384
#define DURATION_FMT(x)                                                                                                            \
    " \"" x "-0\": %lu,\n"                                                                                                         \
    " \"" x "-25\": %lu,\n"                                                                                                        \
    " \"" x "-50\": %lu,\n"                                                                                                        \
    " \"" x "-75\": %lu,\n"                                                                                                        \
    " \"" x "-99\": %lu\n"
#define DURATION_VALS(x)                                                                                                           \
    gkc_query(agg_stats->stats.x, 0), gkc_query(agg_stats->stats.x, 0.25), gkc_query(agg_stats->stats.x, 0.5),                     \
        gkc_query(agg_stats->stats.x, 0.75), gkc_query(agg_stats->stats.x, 0.99)

    ret.base = h2o_mem_alloc_pool(&req->pool, char, BUFSIZE);
    ret.len = snprintf(
        ret.base, BUFSIZE,
        ",\n" DURATION_FMT("connect-time") "," DURATION_FMT("header-time") "," DURATION_FMT("body-time") "," DURATION_FMT(
            "request-total-time") "," DURATION_FMT("process-time") "," DURATION_FMT("response-time") "," DURATION_FMT("duration"),
        DURATION_VALS(connect_time), DURATION_VALS(header_time), DURATION_VALS(body_time), DURATION_VALS(request_total_time),
        DURATION_VALS(process_time), DURATION_VALS(response_time), DURATION_VALS(total_time));
#undef DURATION_FMT
#undef DURATION_VALS
    char *delim = "";
    ret.len += sprintf(ret.base + ret.len, ",\n\"evloop-latency-nanosec\": [");
    size_t i;
    for (i = 0; i < agg_stats->stats.evloop_latency_nanosec.size; i++) {
        size_t len = snprintf(NULL, 0, "%s%" PRIu64, delim, agg_stats->stats.evloop_latency_nanosec.entries[i]);
        /* require that there's enough space for the closing "]\0" */
        if (ret.len + len + 1 >= BUFSIZE)
            break;
        ret.len += snprintf(ret.base + ret.len, BUFSIZE - ret.len, "%s%" PRIu64, delim,
                            agg_stats->stats.evloop_latency_nanosec.entries[i]);
        delim = ",";
    }
    ret.len += snprintf(ret.base + ret.len, BUFSIZE - ret.len, "]");
#undef BUFSIZE
    duration_stats_free(&agg_stats->stats);
    pthread_mutex_destroy(&agg_stats->mutex);

    free(agg_stats);
    return ret;
}

static void stat_access(h2o_logger_t *_self, h2o_req_t *req)
{
    struct st_duration_stats_t *ctx_stats = h2o_context_get_logger_context(req->conn->ctx, _self);
#define ADD_OBSERVATION(x, from, until)                                                                                            \
    do {                                                                                                                           \
        int64_t dur;                                                                                                               \
        if (h2o_time_compute_##x(req, &dur)) {                                                                                     \
            gkc_insert_value(ctx_stats->x, dur);                                                                                   \
        }                                                                                                                          \
    } while (0)

    ADD_OBSERVATION(connect_time, &req->conn->connected_at, &req->timestamps.request_begin_at);
    ADD_OBSERVATION(header_time, &req->timestamps.request_begin_at,
                    h2o_timeval_is_null(&req->timestamps.request_body_begin_at) ? &req->processed_at.at
                                                                                : &req->timestamps.request_body_begin_at);
    ADD_OBSERVATION(body_time,
                    h2o_timeval_is_null(&req->timestamps.request_body_begin_at) ? &req->processed_at.at
                                                                                : &req->timestamps.request_body_begin_at,
                    &req->processed_at.at);
    ADD_OBSERVATION(request_total_time, &req->timestamps.request_begin_at, &req->processed_at.at);
    ADD_OBSERVATION(process_time, &req->processed_at.at, &req->timestamps.response_start_at);
    ADD_OBSERVATION(response_time, &req->timestamps.response_start_at, &req->timestamps.response_end_at);
    ADD_OBSERVATION(total_time, &req->timestamps.request_begin_at, &req->timestamps.response_end_at);
#undef ADD_OBSERVATION
}

static void on_context_init(struct st_h2o_logger_t *self, h2o_context_t *ctx)
{
    struct st_duration_stats_t *duration_stats = h2o_mem_alloc(sizeof(struct st_duration_stats_t));
    duration_stats_init(duration_stats);
    h2o_context_set_logger_context(ctx, self, duration_stats);
}

static void on_context_dispose(struct st_h2o_logger_t *self, h2o_context_t *ctx)
{
    struct st_duration_stats_t *duration_stats;
    duration_stats = h2o_context_get_logger_context(ctx, self);
    duration_stats_free(duration_stats);
}

void h2o_duration_stats_register(h2o_globalconf_t *conf)
{
    int i, k;
    h2o_logger_t *logger;
    h2o_hostconf_t *hconf;

    durations_logger = logger = h2o_mem_alloc(sizeof(*logger));
    memset(logger, 0, sizeof(*logger));
    logger->_config_slot = conf->_num_config_slots++;
    logger->log_access = stat_access;
    logger->on_context_init = on_context_init;
    logger->on_context_dispose = on_context_dispose;

    for (k = 0; conf->hosts[k]; k++) {
        hconf = conf->hosts[k];
        for (i = 0; i < hconf->paths.size; i++) {
            int j;
            for (j = 0; j < hconf->paths.entries[i]->handlers.size; j++) {
                h2o_pathconf_t *pathconf = hconf->paths.entries[i];
                h2o_vector_reserve(NULL, &pathconf->_loggers, pathconf->_loggers.size + 1);
                pathconf->_loggers.entries[pathconf->_loggers.size++] = (void *)logger;
            }
        }
    }
}

h2o_status_handler_t h2o_durations_status_handler = {
    {H2O_STRLIT("durations")}, durations_status_final, durations_status_init, durations_status_per_thread};

Coverage Report

Created: 2025-07-18 06:42

Line	Count	Source (jump to first uncovered line)
1		/*
2		* Copyright (c) 2016 Fastly
3		*
4		* Permission is hereby granted, free of charge, to any person obtaining a copy
5		* of this software and associated documentation files (the "Software"), to
6		* deal in the Software without restriction, including without limitation the
7		* rights to use, copy, modify, merge, publish, distribute, sublicense, and/or
8		* sell copies of the Software, and to permit persons to whom the Software is
9		* furnished to do so, subject to the following conditions:
10		*
11		* The above copyright notice and this permission notice shall be included in
12		* all copies or substantial portions of the Software.
13		*
14		* THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
15		* IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
16		* FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
17		* AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
18		* LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING
19		* FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS
20		* IN THE SOFTWARE.
21		*/
22
23		#include "h2o.h"
24		#include "gkc.h"
25		#include <inttypes.h>
26		#include <pthread.h>
27
28	0	#define GK_EPSILON 0.01
29
30		struct st_duration_stats_t {
31		struct gkc_summary *connect_time;
32		struct gkc_summary *header_time;
33		struct gkc_summary *body_time;
34		struct gkc_summary *request_total_time;
35		struct gkc_summary *process_time;
36		struct gkc_summary *response_time;
37		struct gkc_summary *total_time;
38
39		/**
40		* average event loop latency per worker thread
41		*/
42		H2O_VECTOR(uint64_t) evloop_latency_nanosec;
43		};
44
45		struct st_duration_agg_stats_t {
46		struct st_duration_stats_t stats;
47		pthread_mutex_t mutex;
48		};
49
50		static h2o_logger_t *durations_logger;
51		static void durations_status_per_thread(void priv, h2o_context_t ctx)
52	0	{
53	0	struct st_duration_agg_stats_t *agg_stats = priv;
54	0	if (durations_logger) {
55	0	struct st_duration_stats_t *ctx_stats = h2o_context_get_logger_context(ctx, durations_logger);
56	0	pthread_mutex_lock(&agg_stats->mutex);
57	0	#define ADD_DURATION(x) \
58	0	do { \
59	0	struct gkc_summary *tmp; \
60	0	tmp = gkc_combine(agg_stats->stats.x, ctx_stats->x); \
61	0	gkc_summary_free(agg_stats->stats.x); \
62	0	agg_stats->stats.x = tmp; \
63	0	} while (0)
64	0	ADD_DURATION(connect_time);
65	0	ADD_DURATION(header_time);
66	0	ADD_DURATION(body_time);
67	0	ADD_DURATION(request_total_time);
68	0	ADD_DURATION(process_time);
69	0	ADD_DURATION(response_time);
70	0	ADD_DURATION(total_time);
71	0	#undef ADD_DURATION
72
73	0	#if !H2O_USE_LIBUV
74	0	h2o_vector_reserve(NULL, &agg_stats->stats.evloop_latency_nanosec, agg_stats->stats.evloop_latency_nanosec.size + 1);
75	0	agg_stats->stats.evloop_latency_nanosec.entries[agg_stats->stats.evloop_latency_nanosec.size] =
76	0	h2o_evloop_get_execution_time_nanosec(ctx->loop);
77	0	agg_stats->stats.evloop_latency_nanosec.size++;
78	0	#endif
79	0	pthread_mutex_unlock(&agg_stats->mutex);
80	0	}
81	0	}
82
83		static void duration_stats_init(struct st_duration_stats_t *stats)
84	0	{
85	0	stats->connect_time = gkc_summary_alloc(GK_EPSILON);
86	0	stats->header_time = gkc_summary_alloc(GK_EPSILON);
87	0	stats->body_time = gkc_summary_alloc(GK_EPSILON);
88	0	stats->request_total_time = gkc_summary_alloc(GK_EPSILON);
89	0	stats->process_time = gkc_summary_alloc(GK_EPSILON);
90	0	stats->response_time = gkc_summary_alloc(GK_EPSILON);
91	0	stats->total_time = gkc_summary_alloc(GK_EPSILON);
92	0	memset(&stats->evloop_latency_nanosec, 0, sizeof(stats->evloop_latency_nanosec));
93	0	}
94
95		static void *durations_status_init(void)
96	0	{
97	0	struct st_duration_agg_stats_t *agg_stats;
98
99	0	agg_stats = h2o_mem_alloc(sizeof(*agg_stats));
100
101	0	duration_stats_init(&agg_stats->stats);
102	0	pthread_mutex_init(&agg_stats->mutex, NULL);
103
104	0	return agg_stats;
105	0	}
106
107		static void duration_stats_free(struct st_duration_stats_t *stats)
108	0	{
109	0	gkc_summary_free(stats->connect_time);
110	0	gkc_summary_free(stats->header_time);
111	0	gkc_summary_free(stats->body_time);
112	0	gkc_summary_free(stats->request_total_time);
113	0	gkc_summary_free(stats->process_time);
114	0	gkc_summary_free(stats->response_time);
115	0	gkc_summary_free(stats->total_time);
116	0	free(stats->evloop_latency_nanosec.entries);
117	0	}
118
119		static h2o_iovec_t durations_status_final(void priv, h2o_globalconf_t gconf, h2o_req_t *req)
120	0	{
121	0	struct st_duration_agg_stats_t *agg_stats = priv;
122	0	h2o_iovec_t ret;
123
124	0	#define BUFSIZE 16384
125	0	#define DURATION_FMT(x) \
126	0	" \"" x "-0\": %lu,\n" \
127	0	" \"" x "-25\": %lu,\n" \
128	0	" \"" x "-50\": %lu,\n" \
129	0	" \"" x "-75\": %lu,\n" \
130	0	" \"" x "-99\": %lu\n"
131	0	#define DURATION_VALS(x) \
132	0	gkc_query(agg_stats->stats.x, 0), gkc_query(agg_stats->stats.x, 0.25), gkc_query(agg_stats->stats.x, 0.5), \
133	0	gkc_query(agg_stats->stats.x, 0.75), gkc_query(agg_stats->stats.x, 0.99)
134
135	0	ret.base = h2o_mem_alloc_pool(&req->pool, char, BUFSIZE);
136	0	ret.len = snprintf(
137	0	ret.base, BUFSIZE,
138	0	",\n" DURATION_FMT("connect-time") "," DURATION_FMT("header-time") "," DURATION_FMT("body-time") "," DURATION_FMT(
139	0	"request-total-time") "," DURATION_FMT("process-time") "," DURATION_FMT("response-time") "," DURATION_FMT("duration"),
140	0	DURATION_VALS(connect_time), DURATION_VALS(header_time), DURATION_VALS(body_time), DURATION_VALS(request_total_time),
141	0	DURATION_VALS(process_time), DURATION_VALS(response_time), DURATION_VALS(total_time));
142	0	#undef DURATION_FMT
143	0	#undef DURATION_VALS
144	0	char *delim = "";
145	0	ret.len += sprintf(ret.base + ret.len, ",\n\"evloop-latency-nanosec\": [");
146	0	size_t i;
147	0	for (i = 0; i < agg_stats->stats.evloop_latency_nanosec.size; i++) {
148	0	size_t len = snprintf(NULL, 0, "%s%" PRIu64, delim, agg_stats->stats.evloop_latency_nanosec.entries[i]);
149		/* require that there's enough space for the closing "]\0" */
150	0	if (ret.len + len + 1 >= BUFSIZE)
151	0	break;
152	0	ret.len += snprintf(ret.base + ret.len, BUFSIZE - ret.len, "%s%" PRIu64, delim,
153	0	agg_stats->stats.evloop_latency_nanosec.entries[i]);
154	0	delim = ",";
155	0	}
156	0	ret.len += snprintf(ret.base + ret.len, BUFSIZE - ret.len, "]");
157	0	#undef BUFSIZE
158	0	duration_stats_free(&agg_stats->stats);
159	0	pthread_mutex_destroy(&agg_stats->mutex);
160
161	0	free(agg_stats);
162	0	return ret;
163	0	}
164
165		static void stat_access(h2o_logger_t _self, h2o_req_t req)
166	0	{
167	0	struct st_duration_stats_t *ctx_stats = h2o_context_get_logger_context(req->conn->ctx, _self);
168	0	#define ADD_OBSERVATION(x, from, until) \
169	0	do { \
170	0	int64_t dur; \
171	0	if (h2o_time_compute_##x(req, &dur)) { \
172	0	gkc_insert_value(ctx_stats->x, dur); \
173	0	} \
174	0	} while (0)
175
176	0	ADD_OBSERVATION(connect_time, &req->conn->connected_at, &req->timestamps.request_begin_at);
177	0	ADD_OBSERVATION(header_time, &req->timestamps.request_begin_at,
178	0	h2o_timeval_is_null(&req->timestamps.request_body_begin_at) ? &req->processed_at.at
179	0	: &req->timestamps.request_body_begin_at);
180	0	ADD_OBSERVATION(body_time,
181	0	h2o_timeval_is_null(&req->timestamps.request_body_begin_at) ? &req->processed_at.at
182	0	: &req->timestamps.request_body_begin_at,
183	0	&req->processed_at.at);
184	0	ADD_OBSERVATION(request_total_time, &req->timestamps.request_begin_at, &req->processed_at.at);
185	0	ADD_OBSERVATION(process_time, &req->processed_at.at, &req->timestamps.response_start_at);
186	0	ADD_OBSERVATION(response_time, &req->timestamps.response_start_at, &req->timestamps.response_end_at);
187	0	ADD_OBSERVATION(total_time, &req->timestamps.request_begin_at, &req->timestamps.response_end_at);
188	0	#undef ADD_OBSERVATION
189	0	}
190
191		static void on_context_init(struct st_h2o_logger_t self, h2o_context_t ctx)
192	0	{
193	0	struct st_duration_stats_t *duration_stats = h2o_mem_alloc(sizeof(struct st_duration_stats_t));
194	0	duration_stats_init(duration_stats);
195	0	h2o_context_set_logger_context(ctx, self, duration_stats);
196	0	}
197
198		static void on_context_dispose(struct st_h2o_logger_t self, h2o_context_t ctx)
199	0	{
200	0	struct st_duration_stats_t *duration_stats;
201	0	duration_stats = h2o_context_get_logger_context(ctx, self);
202	0	duration_stats_free(duration_stats);
203	0	}
204
205		void h2o_duration_stats_register(h2o_globalconf_t *conf)
206	0	{
207	0	int i, k;
208	0	h2o_logger_t *logger;
209	0	h2o_hostconf_t *hconf;
210
211	0	durations_logger = logger = h2o_mem_alloc(sizeof(*logger));
212	0	memset(logger, 0, sizeof(*logger));
213	0	logger->_config_slot = conf->_num_config_slots++;
214	0	logger->log_access = stat_access;
215	0	logger->on_context_init = on_context_init;
216	0	logger->on_context_dispose = on_context_dispose;
217
218	0	for (k = 0; conf->hosts[k]; k++) {
219	0	hconf = conf->hosts[k];
220	0	for (i = 0; i < hconf->paths.size; i++) {
221	0	int j;
222	0	for (j = 0; j < hconf->paths.entries[i]->handlers.size; j++) {
223	0	h2o_pathconf_t *pathconf = hconf->paths.entries[i];
224	0	h2o_vector_reserve(NULL, &pathconf->_loggers, pathconf->_loggers.size + 1);
225	0	pathconf->_loggers.entries[pathconf->_loggers.size++] = (void *)logger;
226	0	}
227	0	}
228	0	}
229	0	}
230
231		h2o_status_handler_t h2o_durations_status_handler = {
232		{H2O_STRLIT("durations")}, durations_status_final, durations_status_init, durations_status_per_thread};