add diagnose info for easy when use clang to compile

This commit is contained in:
obdev
2023-01-12 04:15:50 +00:00
committed by ob-robot
parent 7705a1f276
commit d6d16b62f1
6 changed files with 94 additions and 62 deletions

View File

@ -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) {

View File

@ -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);
}
}
}

View File

@ -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

View File

@ -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);

View File

@ -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) {

View File

@ -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;