diff --git a/deps/easy/src/io/easy_connection.c b/deps/easy/src/io/easy_connection.c index 9175e231a0..8cc2694bc3 100644 --- a/deps/easy/src/io/easy_connection.c +++ b/deps/easy/src/io/easy_connection.c @@ -61,8 +61,7 @@ static void easy_session_on_write_success(easy_session_t *s); static int easy_connection_send_rlmtr(easy_io_thread_t *ioth); #define CONN_DESTROY_LOG(msg) easy_error_log("easy_destroy_conn: %s %s", msg, easy_connection_str(c)) -#define EASY_CONNECTION_TIME_GUARD(name, c) EASY_TIME_GUARD("%s: %p", name, c) -#define SERVER_PROCESS(c, r) ({ EASY_STAT_TIME_GUARD((ev_server_process_count++, ev_server_process_time += cost), "server_process"); (c->handler->process(r)); }) +#define SERVER_PROCESS(c, r) ({ EASY_STAT_TIME_GUARD(ev_server_process_count, ev_server_process_time); (c->handler->process(r)); }) inline int64_t current_time() { struct timeval t; @@ -403,7 +402,7 @@ void easy_connection_wakeup_session(easy_connection_t *c, int err) easy_list_del(&r->request_list_node); // SERVER_PROCESS(c, r); { - EASY_STAT_TIME_GUARD((ev_server_process_count++, ev_server_process_time += cost), "server_process"); + EASY_STAT_TIME_GUARD(ev_server_process_count, ev_server_process_time); c->handler->process(r); } } @@ -1228,7 +1227,7 @@ void easy_connection_on_listen(struct ev_loop *loop, ev_timer *w, int revents) */ void easy_connection_on_wakeup(struct ev_loop *loop, ev_async *w, int revents) { - EASY_CONNECTION_TIME_GUARD("on_thread_wakeup", NULL); + EASY_TIME_GUARD(); easy_connection_t *c, *c2; easy_io_thread_t *ioth; easy_list_t conn_list; @@ -1550,7 +1549,7 @@ void easy_connection_on_readable(struct ev_loop *loop, ev_io *w, int revents) mod_stat_t **mod_stat __attribute__((cleanup(__mod_stat_cleanup))) = &easy_cur_mod_stat; *mod_stat = c->pool->mod_stat; - EASY_CONNECTION_TIME_GUARD("on_readable", c); + EASY_TIME_GUARD(); assert(c->fd == w->fd); // 防止请求过多 @@ -2008,7 +2007,7 @@ void easy_connection_on_writable(struct ev_loop *loop, ev_io *w, int revents) int ret; c = (easy_connection_t *)w->data; - EASY_CONNECTION_TIME_GUARD("on_writable", c); + EASY_TIME_GUARD(); assert(c->fd == w->fd); /* if not openssl, start negotiation here, or do negotiation in easy_ssl_client_handshake */ @@ -2048,7 +2047,7 @@ void easy_connection_on_writable(struct ev_loop *loop, ev_io *w, int revents) if (c->type == EASY_TYPE_CLIENT) { // connected. if (c->status == EASY_CONN_CONNECTING) { - EASY_CONNECTION_TIME_GUARD("on_connect", c); + EASY_TIME_GUARD(); c->status = EASY_CONN_OK; ev_io_start(c->loop, &c->read_watcher); ev_timer_set(&c->timeout_watcher, 0.0, 0.5); @@ -2120,7 +2119,7 @@ static void easy_connection_on_timeout_session(struct ev_loop *loop, ev_timer *w s = (easy_session_t *)w->data; c = s->c; - EASY_CONNECTION_TIME_GUARD("on_timeout_session", c); + EASY_TIME_GUARD(); if ((now != (int)ev_now(loop)) && (s->error == 0)) { easy_info_log("Session has timed out, session(%p), time(%fs), packet_id(%" PRIu64 ")," " pcode(%d), trace_id(" OB_TRACE_ID_FORMAT "), conn(%s).", @@ -2146,7 +2145,7 @@ static int easy_connection_update_ack_bytes_and_time(easy_connection_t* c, ev_ts int ret; int64_t qlen = 0; - EASY_CONNECTION_TIME_GUARD("check_send_queue", c); + EASY_TIME_GUARD(); ret = ioctl(c->fd, TIOCOUTQ, &qlen); if (0 != ret) { @@ -2257,7 +2256,7 @@ static void easy_connection_on_timeout_conn(struct ev_loop *loop, ev_timer *w, i int ev_timer_pending = ev_watch_pending; conn = (easy_connection_t *)w->data; - EASY_CONNECTION_TIME_GUARD("on_timeout_conn", conn); + EASY_TIME_GUARD(); if (conn->status == EASY_CONN_AUTO_CONN) { easy_connection_autoconn(conn); @@ -2574,7 +2573,7 @@ static int easy_connection_send_response(easy_list_t *request_list) easy_io_thread_t *ioth = EASY_IOTH_SELF, *dst_ioth; char dest_addr[32]; - EASY_TIME_GUARD("send_response: count=%ld", send_count); + EASY_TIME_GUARD(); // encode easy_list_for_each_entry_safe(r, rn, request_list, request_list_node) { @@ -2696,7 +2695,7 @@ int easy_connection_send_session_list(easy_list_t *list) easy_io_thread_t *ioth = EASY_IOTH_SELF; char dest_addr[32]; - EASY_TIME_GUARD("send_session_list: count=%ld", send_count); + EASY_TIME_GUARD(); // foreach encode easy_list_for_each_entry_safe(s, s1, list, session_list_node) { @@ -3263,7 +3262,7 @@ static int easy_connection_process_request(easy_connection_t *c, easy_list_t *li EASY_IOTH_SELF->rx_done_request_count++; { - EASY_STAT_TIME_GUARD((ev_server_process_count++, ev_server_process_time += cost), "server_process"); + EASY_STAT_TIME_GUARD(ev_server_process_count, ev_server_process_time); ret = (c->handler->process(r)); } if (ret == EASY_ABORT || ret == EASY_ASYNC || ret == EASY_ERROR) { diff --git a/deps/easy/src/io/easy_log.c b/deps/easy/src/io/easy_log.c index 9aa72fafda..466eefbe14 100644 --- a/deps/easy/src/io/easy_log.c +++ b/deps/easy/src/io/easy_log.c @@ -132,3 +132,47 @@ void __attribute__((constructor)) easy_log_start_() if (p) easy_log_level = (easy_log_level_t)atoi(p); } + +void __tg_cleanup(void *s) +{ + int64_t cost = get_us() - ((struct easy_time_guard_t *)s)->start; + if (cost > ev_loop_warn_threshold) { + easy_warn_log("easy cost too much time: %ldus, procedure: %s", cost, ((struct easy_time_guard_t *)s)->procedure); + } +} + +void __tg_stat_cleanup(void *s) +{ + int64_t cost = get_us() - ((struct easy_stat_time_guard_t *)s)->start; + int64_t *cnt = ((struct easy_stat_time_guard_t *)s)->cnt; + *cnt += 1; + int64_t *time = ((struct easy_stat_time_guard_t *)s)->time; + *time += cost; + if (cost > ev_loop_warn_threshold) { + easy_warn_log("easy cost too much time: %ldus, procedure: %s", cost, ((struct easy_stat_time_guard_t *)s)->procedure); + } +} + +void __tg_io_cleanup(void *s) +{ + int ret = 0; + int64_t cost = get_us() - ((struct easy_stat_time_guard_t *)s)->start; + double loadavg[3]; + int64_t *cnt = ((struct easy_stat_time_guard_t *)s)->cnt; + *cnt += 1; + int64_t *time = ((struct easy_stat_time_guard_t *)s)->time; + *time += cost; + if (cost > ev_loop_warn_threshold) { + ret = getloadavg(loadavg, 3); + if (ret == 3) { + easy_warn_log("easy cost too much time(%ldus). loadavg(%lf, %lf, %lf), procedure: %s", + cost, + loadavg[0], + loadavg[1], + loadavg[2], + ((struct easy_stat_time_guard_t *)s)->procedure); + } else { + easy_warn_log("easy cost too much time(%ldus), procedure: %s", cost, ((struct easy_stat_time_guard_t *)s)->procedure); + } + } +} \ No newline at end of file diff --git a/deps/easy/src/io/easy_log.h b/deps/easy/src/io/easy_log.h index 502eb2b12f..98096fe763 100644 --- a/deps/easy/src/io/easy_log.h +++ b/deps/easy/src/io/easy_log.h @@ -75,6 +75,9 @@ extern void easy_log_print_default(const char *message); int64_t get_us(); uint64_t easy_fnv_hash(const char *str); +void __tg_cleanup(void *s); +void __tg_stat_cleanup(void *s); +void __tg_io_cleanup(void *s); extern int64_t ev_loop_warn_threshold; extern __thread int64_t ev_malloc_count; @@ -90,51 +93,39 @@ extern __thread int64_t ev_server_process_time; extern __thread void *ev_watch_pending_addr; extern __thread int ev_watch_pending; +struct easy_stat_time_guard_t { + int64_t start; + int64_t *cnt; + int64_t *time; + const char *procedure; +}; -#ifndef __clang__ +struct easy_time_guard_t { + int64_t start; + const char *procedure; +}; -#define EASY_STAT_TIME_GUARD(stat, format, ...) \ - void __tg_cleanup(void* s) \ - { \ - int64_t cost = get_us() - *(int64_t*)s; \ - stat; \ - if (cost > ev_loop_warn_threshold) { \ - easy_warn_log("easy cost too much time: %ldus " format, cost, ##__VA_ARGS__); \ - } \ - } \ - int64_t _tg_s __attribute__((cleanup(__tg_cleanup))) = get_us(); +#define EASY_STAT_TIME_GUARD(_cnt, _time) \ + struct easy_stat_time_guard_t _tg_stat_time_guard __attribute__((cleanup(__tg_stat_cleanup))) = { \ + .start = get_us(), \ + .cnt = &(_cnt), \ + .time = &(_time), \ + .procedure = __FUNCTION__, \ + }; -#define EASY_SOCKET_IO_TIME_GUARD(stat, format, ...) \ - void __tg_cleanup(void* s) \ - { \ - int ret; \ - int64_t cost = get_us() - *(int64_t*)s; \ - double loadavg[3]; \ - stat; \ - if (cost > ev_loop_warn_threshold) { \ - ret = getloadavg(loadavg, 3); \ - if (ret == 3) { \ - easy_warn_log("easy cost too much time(%ldus). loadavg(%lf, %lf, %lf)" format, \ - cost, \ - loadavg[0], \ - loadavg[1], \ - loadavg[2], \ - ##__VA_ARGS__); \ - } else { \ - easy_warn_log("easy cost too much time(%ldus) " format, cost, ##__VA_ARGS__); \ - } \ - } \ - } \ - int64_t _tg_s __attribute__((cleanup(__tg_cleanup))) = get_us(); +#define EASY_TIME_GUARD() \ + struct easy_time_guard_t _tg_time_guard __attribute__((cleanup(__tg_cleanup))) = { \ + .start = get_us(), \ + .procedure = __FUNCTION__, \ + }; -#else - -#define EASY_STAT_TIME_GUARD(...) -#define EASY_SOCKET_IO_TIME_GUARD(...) - -#endif - -#define EASY_TIME_GUARD(format, ...) EASY_STAT_TIME_GUARD((void)0, format, ##__VA_ARGS__) +#define EASY_SOCKET_IO_TIME_GUARD(_cnt, _time) \ + struct easy_stat_time_guard_t _tg__io_time_guard __attribute__((cleanup(__tg_io_cleanup))) = { \ + .start = get_us(), \ + .cnt = &(_cnt), \ + .time = &(_time), \ + .procedure = __FUNCTION__, \ + }; EASY_CPP_END diff --git a/deps/easy/src/io/easy_message.c b/deps/easy/src/io/easy_message.c index 3812579a79..6c0b184c93 100644 --- a/deps/easy/src/io/easy_message.c +++ b/deps/easy/src/io/easy_message.c @@ -231,7 +231,7 @@ int easy_session_process_low_level(easy_session_t *s, int stop, int need_copy_re easy_buf_t *ebuf = NULL; easy_connection_t *conn; - EASY_STAT_TIME_GUARD((ev_client_cb_count++, ev_client_cb_time += cost), "session_process"); + EASY_STAT_TIME_GUARD(ev_client_cb_count, ev_client_cb_time); if (stop) { ev_timer_stop(s->c->loop, &s->timeout_watcher); easy_list_del(&s->session_list_node); diff --git a/deps/easy/src/io/easy_socket.c b/deps/easy/src/io/easy_socket.c index 1bce704ad2..da7bf4612c 100644 --- a/deps/easy/src/io/easy_socket.c +++ b/deps/easy/src/io/easy_socket.c @@ -196,8 +196,7 @@ char* easy_socket_err_reason(int error_no) ssize_t easy_socket_read(easy_connection_t *conn, char *buf, size_t size, int *pending) { ssize_t n; - EASY_SOCKET_IO_TIME_GUARD((ev_read_count++, ev_read_time += cost), - ", socket recv, fd(%d), conn(%p).", conn->fd, conn); + EASY_SOCKET_IO_TIME_GUARD(ev_read_count, ev_read_time); do { n = recv(conn->fd, buf, size, 0); @@ -237,8 +236,7 @@ ssize_t easy_socket_tcpwrite(easy_connection_t *conn, easy_list_t *l) ssize_t sended, size, wbyte, ret; int cnt, again; - EASY_SOCKET_IO_TIME_GUARD((ev_write_count++, ev_write_time += cost), - ", socket write, fd(%d), iov(%ld/%ld), conn(%p).", conn->fd, wbyte, cnt, conn); + EASY_SOCKET_IO_TIME_GUARD(ev_write_count, ev_write_time); wbyte = cnt = sended = again = 0; // foreach @@ -291,7 +289,7 @@ static ssize_t easy_socket_chain_writev(easy_connection_t *conn, easy_list_t *l, { int retry = 0; - EASY_STAT_TIME_GUARD((void)0, "write retry=%d iov=%ld/%d", retry, ret, cnt); + EASY_TIME_GUARD(); do { retry++; if (cnt == 1) { diff --git a/deps/easy/src/util/easy_pool.c b/deps/easy/src/util/easy_pool.c index 141bf3d48e..1165dd6358 100644 --- a/deps/easy/src/util/easy_pool.c +++ b/deps/easy/src/util/easy_pool.c @@ -82,7 +82,7 @@ void easy_pool_clear(easy_pool_t *pool) void easy_pool_destroy(easy_pool_t *pool) { - EASY_STAT_TIME_GUARD((ev_malloc_count++, ev_malloc_time += cost), "easy_pool_destroy"); + EASY_STAT_TIME_GUARD(ev_malloc_count, ev_malloc_time); easy_pool_clear(pool); assert(pool->ref == 0); #ifdef EASY_DEBUG_MAGIC @@ -93,7 +93,7 @@ void easy_pool_destroy(easy_pool_t *pool) void *easy_pool_alloc_ex(easy_pool_t *pool, uint32_t size, int align) { - EASY_STAT_TIME_GUARD((ev_malloc_count++, ev_malloc_time += cost), "easy_pool_alloc: size=%d", size); + EASY_STAT_TIME_GUARD(ev_malloc_count, ev_malloc_time); uint8_t *m; easy_pool_t *p; int dsize;