diff options
Diffstat (limited to 'src/core')
27 files changed, 382 insertions, 231 deletions
diff --git a/src/core/channel/client_channel.c b/src/core/channel/client_channel.c index ce8af96054..9f85557ea1 100644 --- a/src/core/channel/client_channel.c +++ b/src/core/channel/client_channel.c @@ -36,16 +36,18 @@ #include <stdio.h> #include <string.h> +#include <grpc/support/alloc.h> +#include <grpc/support/log.h> +#include <grpc/support/sync.h> +#include <grpc/support/useful.h> + #include "src/core/channel/channel_args.h" #include "src/core/channel/connected_channel.h" -#include "src/core/surface/channel.h" #include "src/core/iomgr/iomgr.h" +#include "src/core/profiling/timers.h" #include "src/core/support/string.h" +#include "src/core/surface/channel.h" #include "src/core/transport/connectivity_state.h" -#include <grpc/support/alloc.h> -#include <grpc/support/log.h> -#include <grpc/support/sync.h> -#include <grpc/support/useful.h> /* Client channel implementation */ @@ -242,6 +244,8 @@ static void picked_target(grpc_exec_ctx *exec_ctx, void *arg, grpc_pollset *pollset; grpc_subchannel_call_create_status call_creation_status; + GPR_TIMER_BEGIN("picked_target", 0); + if (calld->picked_channel == NULL) { /* treat this like a cancellation */ calld->waiting_op.cancel_with_status = GRPC_STATUS_UNAVAILABLE; @@ -266,6 +270,8 @@ static void picked_target(grpc_exec_ctx *exec_ctx, void *arg, } } } + + GPR_TIMER_END("picked_target", 0); } static grpc_closure *merge_into_waiting_op(grpc_call_element *elem, @@ -326,6 +332,7 @@ static void perform_transport_stream_op(grpc_exec_ctx *exec_ctx, grpc_subchannel_call *subchannel_call; grpc_lb_policy *lb_policy; grpc_transport_stream_op op2; + GPR_TIMER_BEGIN("perform_transport_stream_op", 0); GPR_ASSERT(elem->filter == &grpc_client_channel_filter); GRPC_CALL_LOG_OP(GPR_INFO, elem, op); @@ -437,6 +444,8 @@ static void perform_transport_stream_op(grpc_exec_ctx *exec_ctx, } break; } + + GPR_TIMER_END("perform_transport_stream_op", 0); } static void cc_start_transport_stream_op(grpc_exec_ctx *exec_ctx, diff --git a/src/core/channel/compress_filter.c b/src/core/channel/compress_filter.c index c32f150715..20b5084044 100644 --- a/src/core/channel/compress_filter.c +++ b/src/core/channel/compress_filter.c @@ -41,6 +41,7 @@ #include "src/core/channel/compress_filter.h" #include "src/core/channel/channel_args.h" +#include "src/core/profiling/timers.h" #include "src/core/compression/message_compress.h" #include "src/core/support/string.h" @@ -271,10 +272,14 @@ static void process_send_ops(grpc_call_element *elem, static void compress_start_transport_stream_op(grpc_exec_ctx *exec_ctx, grpc_call_element *elem, grpc_transport_stream_op *op) { + GPR_TIMER_BEGIN("compress_start_transport_stream_op", 0); + if (op->send_ops && op->send_ops->nops > 0) { process_send_ops(elem, op->send_ops); } + GPR_TIMER_END("compress_start_transport_stream_op", 0); + /* pass control down the stack */ grpc_call_next_op(exec_ctx, elem, op); } diff --git a/src/core/channel/connected_channel.c b/src/core/channel/connected_channel.c index f9fc280259..6d4d7be632 100644 --- a/src/core/channel/connected_channel.c +++ b/src/core/channel/connected_channel.c @@ -39,6 +39,7 @@ #include "src/core/support/string.h" #include "src/core/transport/transport.h" +#include "src/core/profiling/timers.h" #include <grpc/byte_buffer.h> #include <grpc/support/alloc.h> #include <grpc/support/log.h> diff --git a/src/core/channel/http_client_filter.c b/src/core/channel/http_client_filter.c index d67dc37ad2..f78a5cc315 100644 --- a/src/core/channel/http_client_filter.c +++ b/src/core/channel/http_client_filter.c @@ -36,6 +36,7 @@ #include <grpc/support/log.h> #include <grpc/support/string_util.h> #include "src/core/support/string.h" +#include "src/core/profiling/timers.h" typedef struct call_data { grpc_linked_mdelem method; @@ -162,8 +163,10 @@ static void hc_mutate_op(grpc_call_element *elem, static void hc_start_transport_op(grpc_exec_ctx *exec_ctx, grpc_call_element *elem, grpc_transport_stream_op *op) { + GPR_TIMER_BEGIN("hc_start_transport_op", 0); GRPC_CALL_LOG_OP(GPR_INFO, elem, op); hc_mutate_op(elem, op); + GPR_TIMER_END("hc_start_transport_op", 0); grpc_call_next_op(exec_ctx, elem, op); } diff --git a/src/core/channel/http_server_filter.c b/src/core/channel/http_server_filter.c index 5e6d684a52..99e5066a4e 100644 --- a/src/core/channel/http_server_filter.c +++ b/src/core/channel/http_server_filter.c @@ -36,6 +36,7 @@ #include <string.h> #include <grpc/support/alloc.h> #include <grpc/support/log.h> +#include "src/core/profiling/timers.h" typedef struct call_data { gpr_uint8 got_initial_metadata; @@ -230,8 +231,10 @@ static void hs_start_transport_op(grpc_exec_ctx *exec_ctx, grpc_call_element *elem, grpc_transport_stream_op *op) { GRPC_CALL_LOG_OP(GPR_INFO, elem, op); + GPR_TIMER_BEGIN("hs_start_transport_op", 0); hs_mutate_op(elem, op); grpc_call_next_op(exec_ctx, elem, op); + GPR_TIMER_END("hs_start_transport_op", 0); } /* Constructor for call_data */ diff --git a/src/core/client_config/lb_policies/pick_first.c b/src/core/client_config/lb_policies/pick_first.c index 4b3aaab09c..e5bf0680ff 100644 --- a/src/core/client_config/lb_policies/pick_first.c +++ b/src/core/client_config/lb_policies/pick_first.c @@ -175,7 +175,7 @@ void pf_pick(grpc_exec_ctx *exec_ctx, grpc_lb_policy *pol, } } -static void destroy_subchannels(grpc_exec_ctx *exec_ctx, void *arg, +static void destroy_subchannels(grpc_exec_ctx *exec_ctx, void *arg, int iomgr_success) { pick_first_lb_policy *p = arg; size_t i; @@ -235,7 +235,8 @@ static void pf_connectivity_changed(grpc_exec_ctx *exec_ctx, void *arg, GRPC_SUBCHANNEL_REF(p->selected, "picked_first"); /* drop the pick list: we are connected now */ GRPC_LB_POLICY_REF(&p->base, "destroy_subchannels"); - grpc_exec_ctx_enqueue(exec_ctx, grpc_closure_create(destroy_subchannels, p), 1); + grpc_exec_ctx_enqueue(exec_ctx, + grpc_closure_create(destroy_subchannels, p), 1); /* update any calls that were waiting for a pick */ while ((pp = p->pending_picks)) { p->pending_picks = pp->next; diff --git a/src/core/iomgr/exec_ctx.c b/src/core/iomgr/exec_ctx.c index f2914d376e..410b34c521 100644 --- a/src/core/iomgr/exec_ctx.c +++ b/src/core/iomgr/exec_ctx.c @@ -35,18 +35,24 @@ #include <grpc/support/log.h> +#include "src/core/profiling/timers.h" + int grpc_exec_ctx_flush(grpc_exec_ctx *exec_ctx) { int did_something = 0; + GPR_TIMER_BEGIN("grpc_exec_ctx_flush", 0); while (!grpc_closure_list_empty(exec_ctx->closure_list)) { grpc_closure *c = exec_ctx->closure_list.head; exec_ctx->closure_list.head = exec_ctx->closure_list.tail = NULL; while (c != NULL) { grpc_closure *next = c->next; - did_something = 1; + did_something++; + GPR_TIMER_BEGIN("grpc_exec_ctx_flush.cb", 0); c->cb(exec_ctx, c->cb_arg, c->success); + GPR_TIMER_END("grpc_exec_ctx_flush.cb", 0); c = next; } } + GPR_TIMER_END("grpc_exec_ctx_flush", 0); return did_something; } diff --git a/src/core/iomgr/pollset_multipoller_with_epoll.c b/src/core/iomgr/pollset_multipoller_with_epoll.c index ba9ba73f9d..2aafd21dfb 100644 --- a/src/core/iomgr/pollset_multipoller_with_epoll.c +++ b/src/core/iomgr/pollset_multipoller_with_epoll.c @@ -41,10 +41,11 @@ #include <sys/epoll.h> #include <unistd.h> -#include "src/core/iomgr/fd_posix.h" -#include "src/core/support/block_annotate.h" #include <grpc/support/alloc.h> #include <grpc/support/log.h> +#include "src/core/iomgr/fd_posix.h" +#include "src/core/support/block_annotate.h" +#include "src/core/profiling/timers.h" typedef struct wakeup_fd_hdl { grpc_wakeup_fd wakeup_fd; @@ -182,9 +183,11 @@ static void multipoll_with_epoll_pollset_maybe_work_and_unlock( /* TODO(vpai): Consider first doing a 0 timeout poll here to avoid even going into the blocking annotation if possible */ + GPR_TIMER_BEGIN("poll", 0); GRPC_SCHEDULING_START_BLOCKING_REGION; poll_rv = grpc_poll_function(pfds, 2, timeout_ms); GRPC_SCHEDULING_END_BLOCKING_REGION; + GPR_TIMER_END("poll", 0); if (poll_rv < 0) { if (errno != EINTR) { diff --git a/src/core/iomgr/pollset_posix.c b/src/core/iomgr/pollset_posix.c index d4362bb53a..c4e1987491 100644 --- a/src/core/iomgr/pollset_posix.c +++ b/src/core/iomgr/pollset_posix.c @@ -101,9 +101,12 @@ static void push_front_worker(grpc_pollset *p, grpc_pollset_worker *worker) { void grpc_pollset_kick_ext(grpc_pollset *p, grpc_pollset_worker *specific_worker, gpr_uint32 flags) { + GPR_TIMER_BEGIN("grpc_pollset_kick_ext", 0); + /* pollset->mu already held */ if (specific_worker != NULL) { if (specific_worker == GRPC_POLLSET_KICK_BROADCAST) { + GPR_TIMER_BEGIN("grpc_pollset_kick_ext.broadcast", 0); GPR_ASSERT((flags & GRPC_POLLSET_REEVALUATE_POLLING_ON_WAKEUP) == 0); for (specific_worker = p->root_worker.next; specific_worker != &p->root_worker; @@ -111,44 +114,50 @@ void grpc_pollset_kick_ext(grpc_pollset *p, grpc_wakeup_fd_wakeup(&specific_worker->wakeup_fd); } p->kicked_without_pollers = 1; - return; + GPR_TIMER_END("grpc_pollset_kick_ext.broadcast", 0); } else if (gpr_tls_get(&g_current_thread_worker) != (gpr_intptr)specific_worker) { + GPR_TIMER_MARK("different_thread_worker", 0); if ((flags & GRPC_POLLSET_REEVALUATE_POLLING_ON_WAKEUP) != 0) { specific_worker->reevaluate_polling_on_wakeup = 1; } grpc_wakeup_fd_wakeup(&specific_worker->wakeup_fd); - return; } else if ((flags & GRPC_POLLSET_CAN_KICK_SELF) != 0) { + GPR_TIMER_MARK("kick_yoself", 0); if ((flags & GRPC_POLLSET_REEVALUATE_POLLING_ON_WAKEUP) != 0) { specific_worker->reevaluate_polling_on_wakeup = 1; } grpc_wakeup_fd_wakeup(&specific_worker->wakeup_fd); - return; } } else if (gpr_tls_get(&g_current_thread_poller) != (gpr_intptr)p) { GPR_ASSERT((flags & GRPC_POLLSET_REEVALUATE_POLLING_ON_WAKEUP) == 0); + GPR_TIMER_MARK("kick_anonymous", 0); specific_worker = pop_front_worker(p); if (specific_worker != NULL) { if (gpr_tls_get(&g_current_thread_worker) == (gpr_intptr)specific_worker) { + GPR_TIMER_MARK("kick_anonymous_not_self", 0); push_back_worker(p, specific_worker); specific_worker = pop_front_worker(p); if ((flags & GRPC_POLLSET_CAN_KICK_SELF) == 0 && gpr_tls_get(&g_current_thread_worker) == (gpr_intptr)specific_worker) { push_back_worker(p, specific_worker); - return; + specific_worker = NULL; } } - push_back_worker(p, specific_worker); - grpc_wakeup_fd_wakeup(&specific_worker->wakeup_fd); - return; + if (specific_worker != NULL) { + GPR_TIMER_MARK("finally_kick", 0); + push_back_worker(p, specific_worker); + grpc_wakeup_fd_wakeup(&specific_worker->wakeup_fd); + } } else { + GPR_TIMER_MARK("kicked_no_pollers", 0); p->kicked_without_pollers = 1; - return; } } + + GPR_TIMER_END("grpc_pollset_kick_ext", 0); } void grpc_pollset_kick(grpc_pollset *p, grpc_pollset_worker *specific_worker) { @@ -229,6 +238,7 @@ void grpc_pollset_work(grpc_exec_ctx *exec_ctx, grpc_pollset *pollset, int locked = 1; int queued_work = 0; int keep_polling = 0; + GPR_TIMER_BEGIN("grpc_pollset_work", 0); /* this must happen before we (potentially) drop pollset->mu */ worker->next = worker->prev = NULL; worker->reevaluate_polling_on_wakeup = 0; @@ -273,8 +283,10 @@ void grpc_pollset_work(grpc_exec_ctx *exec_ctx, grpc_pollset *pollset, } gpr_tls_set(&g_current_thread_poller, (gpr_intptr)pollset); gpr_tls_set(&g_current_thread_worker, (gpr_intptr)worker); + GPR_TIMER_BEGIN("maybe_work_and_unlock", 0); pollset->vtable->maybe_work_and_unlock(exec_ctx, pollset, worker, deadline, now); + GPR_TIMER_END("maybe_work_and_unlock", 0); locked = 0; gpr_tls_set(&g_current_thread_poller, 0); gpr_tls_set(&g_current_thread_worker, 0); @@ -329,6 +341,7 @@ void grpc_pollset_work(grpc_exec_ctx *exec_ctx, grpc_pollset *pollset, gpr_mu_lock(&pollset->mu); } } + GPR_TIMER_END("grpc_pollset_work", 0); } void grpc_pollset_shutdown(grpc_exec_ctx *exec_ctx, grpc_pollset *pollset, @@ -563,10 +576,11 @@ static void basic_pollset_maybe_work_and_unlock(grpc_exec_ctx *exec_ctx, even going into the blocking annotation if possible */ /* poll fd count (argument 2) is shortened by one if we have no events to poll on - such that it only includes the kicker */ + GPR_TIMER_BEGIN("poll", 0); GRPC_SCHEDULING_START_BLOCKING_REGION; r = grpc_poll_function(pfd, nfds, timeout); GRPC_SCHEDULING_END_BLOCKING_REGION; - GRPC_TIMER_MARK(GRPC_PTAG_POLL_FINISHED, r); + GPR_TIMER_END("poll", 0); if (r < 0) { gpr_log(GPR_ERROR, "poll() failed: %s", strerror(errno)); diff --git a/src/core/iomgr/tcp_posix.c b/src/core/iomgr/tcp_posix.c index 4a57037a72..915553d509 100644 --- a/src/core/iomgr/tcp_posix.c +++ b/src/core/iomgr/tcp_posix.c @@ -180,7 +180,7 @@ static void tcp_continue_read(grpc_exec_ctx *exec_ctx, grpc_tcp *tcp) { GPR_ASSERT(!tcp->finished_edge); GPR_ASSERT(tcp->iov_size <= MAX_READ_IOVEC); GPR_ASSERT(tcp->incoming_buffer->count <= MAX_READ_IOVEC); - GRPC_TIMER_BEGIN(GRPC_PTAG_HANDLE_READ, 0); + GPR_TIMER_BEGIN("tcp_continue_read", 0); while (tcp->incoming_buffer->count < (size_t)tcp->iov_size) { gpr_slice_buffer_add_indexed(tcp->incoming_buffer, @@ -199,11 +199,11 @@ static void tcp_continue_read(grpc_exec_ctx *exec_ctx, grpc_tcp *tcp) { msg.msg_controllen = 0; msg.msg_flags = 0; - GRPC_TIMER_BEGIN(GRPC_PTAG_RECVMSG, 0); + GPR_TIMER_BEGIN("recvmsg", 1); do { read_bytes = recvmsg(tcp->fd, &msg, 0); } while (read_bytes < 0 && errno == EINTR); - GRPC_TIMER_END(GRPC_PTAG_RECVMSG, 0); + GPR_TIMER_END("recvmsg", 0); if (read_bytes < 0) { /* NB: After calling call_read_cb a parallel call of the read handler may @@ -240,7 +240,7 @@ static void tcp_continue_read(grpc_exec_ctx *exec_ctx, grpc_tcp *tcp) { TCP_UNREF(exec_ctx, tcp, "read"); } - GRPC_TIMER_END(GRPC_PTAG_HANDLE_READ, 0); + GPR_TIMER_END("tcp_continue_read", 0); } static void tcp_handle_read(grpc_exec_ctx *exec_ctx, void *arg /* grpc_tcp */, @@ -316,12 +316,12 @@ static flush_result tcp_flush(grpc_tcp *tcp) { msg.msg_controllen = 0; msg.msg_flags = 0; - GRPC_TIMER_BEGIN(GRPC_PTAG_SENDMSG, 0); + GPR_TIMER_BEGIN("sendmsg", 1); do { /* TODO(klempner): Cork if this is a partial write */ sent_length = sendmsg(tcp->fd, &msg, SENDMSG_FLAGS); } while (sent_length < 0 && errno == EINTR); - GRPC_TIMER_END(GRPC_PTAG_SENDMSG, 0); + GPR_TIMER_END("sendmsg", 0); if (sent_length < 0) { if (errno == EAGAIN) { @@ -370,17 +370,17 @@ static void tcp_handle_write(grpc_exec_ctx *exec_ctx, void *arg /* grpc_tcp */, return; } - GRPC_TIMER_BEGIN(GRPC_PTAG_TCP_CB_WRITE, 0); status = tcp_flush(tcp); if (status == FLUSH_PENDING) { grpc_fd_notify_on_write(exec_ctx, tcp->em_fd, &tcp->write_closure); } else { cb = tcp->write_cb; tcp->write_cb = NULL; + GPR_TIMER_BEGIN("tcp_handle_write.cb", 0); cb->cb(exec_ctx, cb->cb_arg, status == FLUSH_DONE); + GPR_TIMER_END("tcp_handle_write.cb", 0); TCP_UNREF(exec_ctx, tcp, "write"); } - GRPC_TIMER_END(GRPC_PTAG_TCP_CB_WRITE, 0); } static void tcp_write(grpc_exec_ctx *exec_ctx, grpc_endpoint *ep, @@ -399,11 +399,11 @@ static void tcp_write(grpc_exec_ctx *exec_ctx, grpc_endpoint *ep, } } - GRPC_TIMER_BEGIN(GRPC_PTAG_TCP_WRITE, 0); + GPR_TIMER_BEGIN("tcp_write", 0); GPR_ASSERT(tcp->write_cb == NULL); if (buf->length == 0) { - GRPC_TIMER_END(GRPC_PTAG_TCP_WRITE, 0); + GPR_TIMER_END("tcp_write", 0); grpc_exec_ctx_enqueue(exec_ctx, cb, 1); return; } @@ -420,7 +420,7 @@ static void tcp_write(grpc_exec_ctx *exec_ctx, grpc_endpoint *ep, grpc_exec_ctx_enqueue(exec_ctx, cb, status == FLUSH_DONE); } - GRPC_TIMER_END(GRPC_PTAG_TCP_WRITE, 0); + GPR_TIMER_END("tcp_write", 0); } static void tcp_add_to_pollset(grpc_exec_ctx *exec_ctx, grpc_endpoint *ep, diff --git a/src/core/iomgr/wakeup_fd_eventfd.c b/src/core/iomgr/wakeup_fd_eventfd.c index 48eb1afb3d..f67379e4fc 100644 --- a/src/core/iomgr/wakeup_fd_eventfd.c +++ b/src/core/iomgr/wakeup_fd_eventfd.c @@ -39,9 +39,11 @@ #include <sys/eventfd.h> #include <unistd.h> -#include "src/core/iomgr/wakeup_fd_posix.h" #include <grpc/support/log.h> +#include "src/core/iomgr/wakeup_fd_posix.h" +#include "src/core/profiling/timers.h" + static void eventfd_create(grpc_wakeup_fd* fd_info) { int efd = eventfd(0, EFD_NONBLOCK | EFD_CLOEXEC); /* TODO(klempner): Handle failure more gracefully */ @@ -60,9 +62,11 @@ static void eventfd_consume(grpc_wakeup_fd* fd_info) { static void eventfd_wakeup(grpc_wakeup_fd* fd_info) { int err; + GPR_TIMER_BEGIN("eventfd_wakeup", 0); do { err = eventfd_write(fd_info->read_fd, 1); } while (err < 0 && errno == EINTR); + GPR_TIMER_END("eventfd_wakeup", 0); } static void eventfd_destroy(grpc_wakeup_fd* fd_info) { diff --git a/src/core/profiling/basic_timers.c b/src/core/profiling/basic_timers.c index 2f6c88daac..b49cdd07b3 100644 --- a/src/core/profiling/basic_timers.c +++ b/src/core/profiling/basic_timers.c @@ -44,98 +44,91 @@ #include <grpc/support/thd.h> #include <stdio.h> -typedef enum { - BEGIN = '{', - END = '}', - MARK = '.', - IMPORTANT = '!' -} marker_type; - -typedef struct grpc_timer_entry { +typedef enum { BEGIN = '{', END = '}', MARK = '.' } marker_type; + +typedef struct gpr_timer_entry { gpr_timespec tm; - int tag; const char *tagstr; - marker_type type; - void *id; const char *file; int line; -} grpc_timer_entry; + char type; + gpr_uint8 important; +} gpr_timer_entry; + +#define MAX_COUNT (1024 * 1024 / sizeof(gpr_timer_entry)) -#define MAX_COUNT (1024 * 1024 / sizeof(grpc_timer_entry)) +static __thread gpr_timer_entry g_log[MAX_COUNT]; +static __thread int g_count; +static gpr_once g_once_init = GPR_ONCE_INIT; +static FILE *output_file; -static __thread grpc_timer_entry log[MAX_COUNT]; -static __thread int count; +static void close_output() { fclose(output_file); } + +static void init_output() { + output_file = fopen("latency_trace.txt", "w"); + GPR_ASSERT(output_file); + atexit(close_output); +} static void log_report() { int i; - for (i = 0; i < count; i++) { - grpc_timer_entry *entry = &(log[i]); - printf("GRPC_LAT_PROF %ld.%09d %p %c %d(%s) %p %s %d\n", entry->tm.tv_sec, - entry->tm.tv_nsec, (void *)(gpr_intptr)gpr_thd_currentid(), - entry->type, entry->tag, entry->tagstr, entry->id, entry->file, - entry->line); + gpr_once_init(&g_once_init, init_output); + for (i = 0; i < g_count; i++) { + gpr_timer_entry *entry = &(g_log[i]); + fprintf(output_file, + "{\"t\": %ld.%09d, \"thd\": \"%p\", \"type\": \"%c\", \"tag\": " + "\"%s\", \"file\": \"%s\", \"line\": %d, \"imp\": %d}\n", + entry->tm.tv_sec, entry->tm.tv_nsec, + (void *)(gpr_intptr)gpr_thd_currentid(), entry->type, entry->tagstr, + entry->file, entry->line, entry->important); } /* Now clear out the log */ - count = 0; + g_count = 0; } -static void grpc_timers_log_add(int tag, const char *tagstr, marker_type type, - void *id, const char *file, int line) { - grpc_timer_entry *entry; +static void gpr_timers_log_add(const char *tagstr, marker_type type, + int important, const char *file, int line) { + gpr_timer_entry *entry; /* TODO (vpai) : Improve concurrency */ - if (count == MAX_COUNT) { + if (g_count == MAX_COUNT) { log_report(); } - entry = &log[count++]; + entry = &g_log[g_count++]; entry->tm = gpr_now(GPR_CLOCK_PRECISE); - entry->tag = tag; entry->tagstr = tagstr; entry->type = type; - entry->id = id; entry->file = file; entry->line = line; + entry->important = important != 0; } /* Latency profiler API implementation. */ -void grpc_timer_add_mark(int tag, const char *tagstr, void *id, - const char *file, int line) { - if (tag < GRPC_PTAG_IGNORE_THRESHOLD) { - grpc_timers_log_add(tag, tagstr, MARK, id, file, line); - } +void gpr_timer_add_mark(const char *tagstr, int important, const char *file, + int line) { + gpr_timers_log_add(tagstr, MARK, important, file, line); } -void grpc_timer_add_important_mark(int tag, const char *tagstr, void *id, - const char *file, int line) { - if (tag < GRPC_PTAG_IGNORE_THRESHOLD) { - grpc_timers_log_add(tag, tagstr, IMPORTANT, id, file, line); - } +void gpr_timer_begin(const char *tagstr, int important, const char *file, + int line) { + gpr_timers_log_add(tagstr, BEGIN, important, file, line); } -void grpc_timer_begin(int tag, const char *tagstr, void *id, const char *file, - int line) { - if (tag < GRPC_PTAG_IGNORE_THRESHOLD) { - grpc_timers_log_add(tag, tagstr, BEGIN, id, file, line); - } -} - -void grpc_timer_end(int tag, const char *tagstr, void *id, const char *file, - int line) { - if (tag < GRPC_PTAG_IGNORE_THRESHOLD) { - grpc_timers_log_add(tag, tagstr, END, id, file, line); - } +void gpr_timer_end(const char *tagstr, int important, const char *file, + int line) { + gpr_timers_log_add(tagstr, END, important, file, line); } /* Basic profiler specific API functions. */ -void grpc_timers_global_init(void) {} +void gpr_timers_global_init(void) {} -void grpc_timers_global_destroy(void) {} +void gpr_timers_global_destroy(void) {} #else /* !GRPC_BASIC_PROFILER */ -void grpc_timers_global_init(void) {} +void gpr_timers_global_init(void) {} -void grpc_timers_global_destroy(void) {} +void gpr_timers_global_destroy(void) {} #endif /* GRPC_BASIC_PROFILER */ diff --git a/src/core/profiling/stap_timers.c b/src/core/profiling/stap_timers.c index 6868a674a9..efcd1af4a1 100644 --- a/src/core/profiling/stap_timers.c +++ b/src/core/profiling/stap_timers.c @@ -42,23 +42,23 @@ #include "src/core/profiling/stap_probes.h" /* Latency profiler API implementation. */ -void grpc_timer_add_mark(int tag, const char *tagstr, void *id, - const char *file, int line) { +void gpr_timer_add_mark(int tag, const char *tagstr, void *id, const char *file, + int line) { _STAP_ADD_MARK(tag); } -void grpc_timer_add_important_mark(int tag, const char *tagstr, void *id, - const char *file, int line) { +void gpr_timer_add_important_mark(int tag, const char *tagstr, void *id, + const char *file, int line) { _STAP_ADD_IMPORTANT_MARK(tag); } -void grpc_timer_begin(int tag, const char *tagstr, void *id, const char *file, - int line) { +void gpr_timer_begin(int tag, const char *tagstr, void *id, const char *file, + int line) { _STAP_TIMING_NS_BEGIN(tag); } -void grpc_timer_end(int tag, const char *tagstr, void *id, const char *file, - int line) { +void gpr_timer_end(int tag, const char *tagstr, void *id, const char *file, + int line) { _STAP_TIMING_NS_END(tag); } diff --git a/src/core/profiling/timers.h b/src/core/profiling/timers.h index a70520408c..0d112e7248 100644 --- a/src/core/profiling/timers.h +++ b/src/core/profiling/timers.h @@ -38,65 +38,28 @@ extern "C" { #endif -void grpc_timers_global_init(void); -void grpc_timers_global_destroy(void); - -void grpc_timer_add_mark(int tag, const char *tagstr, void *id, - const char *file, int line); -void grpc_timer_add_important_mark(int tag, const char *tagstr, void *id, - const char *file, int line); -void grpc_timer_begin(int tag, const char *tagstr, void *id, const char *file, - int line); -void grpc_timer_end(int tag, const char *tagstr, void *id, const char *file, - int line); - -enum grpc_profiling_tags { - /* Any GRPC_PTAG_* >= than the threshold won't generate any profiling mark. */ - GRPC_PTAG_IGNORE_THRESHOLD = 1000000, - - /* Re. Protos. */ - GRPC_PTAG_PROTO_SERIALIZE = 100 + GRPC_PTAG_IGNORE_THRESHOLD, - GRPC_PTAG_PROTO_DESERIALIZE = 101 + GRPC_PTAG_IGNORE_THRESHOLD, - - /* Re. sockets. */ - GRPC_PTAG_HANDLE_READ = 200 + GRPC_PTAG_IGNORE_THRESHOLD, - GRPC_PTAG_SENDMSG = 201 + GRPC_PTAG_IGNORE_THRESHOLD, - GRPC_PTAG_RECVMSG = 202 + GRPC_PTAG_IGNORE_THRESHOLD, - GRPC_PTAG_POLL_FINISHED = 203 + GRPC_PTAG_IGNORE_THRESHOLD, - GRPC_PTAG_TCP_CB_WRITE = 204 + GRPC_PTAG_IGNORE_THRESHOLD, - GRPC_PTAG_TCP_WRITE = 205 + GRPC_PTAG_IGNORE_THRESHOLD, - GRPC_PTAG_CALL_ON_DONE_RECV = 206 + GRPC_PTAG_IGNORE_THRESHOLD, - - /* C++ */ - GRPC_PTAG_CPP_CALL_CREATED = 300 + GRPC_PTAG_IGNORE_THRESHOLD, - GRPC_PTAG_CPP_PERFORM_OPS = 301 + GRPC_PTAG_IGNORE_THRESHOLD, - - /* Transports */ - GRPC_PTAG_HTTP2_UNLOCK = 401 + GRPC_PTAG_IGNORE_THRESHOLD, - GRPC_PTAG_HTTP2_UNLOCK_CLEANUP = 402 + GRPC_PTAG_IGNORE_THRESHOLD, - - /* > 1024 Unassigned reserved. For any miscellaneous use. - * Use addition to generate tags from this base or take advantage of the 10 - * zero'd bits for OR-ing. */ - GRPC_PTAG_OTHER_BASE = 1024 -}; +void gpr_timers_global_init(void); +void gpr_timers_global_destroy(void); + +void gpr_timer_add_mark(const char *tagstr, int important, const char *file, + int line); +void gpr_timer_begin(const char *tagstr, int important, const char *file, + int line); +void gpr_timer_end(const char *tagstr, int important, const char *file, + int line); #if !(defined(GRPC_STAP_PROFILER) + defined(GRPC_BASIC_PROFILER)) /* No profiling. No-op all the things. */ -#define GRPC_TIMER_MARK(tag, id) \ - do { \ - } while (0) - -#define GRPC_TIMER_IMPORTANT_MARK(tag, id) \ - do { \ +#define GPR_TIMER_MARK(tag, important) \ + do { \ } while (0) -#define GRPC_TIMER_BEGIN(tag, id) \ - do { \ +#define GPR_TIMER_BEGIN(tag, important) \ + do { \ } while (0) -#define GRPC_TIMER_END(tag, id) \ - do { \ +#define GPR_TIMER_END(tag, important) \ + do { \ } while (0) #else /* at least one profiler requested... */ @@ -106,28 +69,14 @@ enum grpc_profiling_tags { #endif /* Generic profiling interface. */ -#define GRPC_TIMER_MARK(tag, id) \ - if (tag < GRPC_PTAG_IGNORE_THRESHOLD) { \ - grpc_timer_add_mark(tag, #tag, ((void *)(gpr_intptr)(id)), __FILE__, \ - __LINE__); \ - } - -#define GRPC_TIMER_IMPORTANT_MARK(tag, id) \ - if (tag < GRPC_PTAG_IGNORE_THRESHOLD) { \ - grpc_timer_add_important_mark(tag, #tag, ((void *)(gpr_intptr)(id)), \ - __FILE__, __LINE__); \ - } +#define GPR_TIMER_MARK(tag, important) \ + gpr_timer_add_mark(tag, important, __FILE__, __LINE__); -#define GRPC_TIMER_BEGIN(tag, id) \ - if (tag < GRPC_PTAG_IGNORE_THRESHOLD) { \ - grpc_timer_begin(tag, #tag, ((void *)(gpr_intptr)(id)), __FILE__, \ - __LINE__); \ - } +#define GPR_TIMER_BEGIN(tag, important) \ + gpr_timer_begin(tag, important, __FILE__, __LINE__); -#define GRPC_TIMER_END(tag, id) \ - if (tag < GRPC_PTAG_IGNORE_THRESHOLD) { \ - grpc_timer_end(tag, #tag, ((void *)(gpr_intptr)(id)), __FILE__, __LINE__); \ - } +#define GPR_TIMER_END(tag, important) \ + gpr_timer_end(tag, important, __FILE__, __LINE__); #ifdef GRPC_STAP_PROFILER /* Empty placeholder for now. */ @@ -141,6 +90,28 @@ enum grpc_profiling_tags { #ifdef __cplusplus } + +#if (defined(GRPC_STAP_PROFILER) + defined(GRPC_BASIC_PROFILER)) +namespace grpc { +class ProfileScope { + public: + ProfileScope(const char *desc, bool important) : desc_(desc) { + GPR_TIMER_BEGIN(desc_, important ? 1 : 0); + } + ~ProfileScope() { GPR_TIMER_END(desc_, 0); } + + private: + const char *const desc_; +}; +} + +#define GPR_TIMER_SCOPE(tag, important) \ + ::grpc::ProfileScope _profile_scope_##__LINE__((tag), (important)) +#else +#define GPR_TIMER_SCOPE(tag, important) \ + do { \ + } while (false) +#endif #endif #endif /* GRPC_CORE_PROFILING_TIMERS_H */ diff --git a/src/core/support/alloc.c b/src/core/support/alloc.c index d2ed82e771..bfcb77956b 100644 --- a/src/core/support/alloc.c +++ b/src/core/support/alloc.c @@ -35,22 +35,32 @@ #include <stdlib.h> #include <grpc/support/port_platform.h> +#include "src/core/profiling/timers.h" void *gpr_malloc(size_t size) { - void *p = malloc(size); + void *p; + GPR_TIMER_BEGIN("gpr_malloc", 0); + p = malloc(size); if (!p) { abort(); } + GPR_TIMER_END("gpr_malloc", 0); return p; } -void gpr_free(void *p) { free(p); } +void gpr_free(void *p) { + GPR_TIMER_BEGIN("gpr_free", 0); + free(p); + GPR_TIMER_END("gpr_free", 0); +} void *gpr_realloc(void *p, size_t size) { + GPR_TIMER_BEGIN("gpr_realloc", 0); p = realloc(p, size); if (!p) { abort(); } + GPR_TIMER_END("gpr_realloc", 0); return p; } diff --git a/src/core/support/sync_posix.c b/src/core/support/sync_posix.c index 91c30989ce..39c96feb13 100644 --- a/src/core/support/sync_posix.c +++ b/src/core/support/sync_posix.c @@ -40,14 +40,23 @@ #include <grpc/support/log.h> #include <grpc/support/sync.h> #include <grpc/support/time.h> +#include "src/core/profiling/timers.h" void gpr_mu_init(gpr_mu* mu) { GPR_ASSERT(pthread_mutex_init(mu, NULL) == 0); } void gpr_mu_destroy(gpr_mu* mu) { GPR_ASSERT(pthread_mutex_destroy(mu) == 0); } -void gpr_mu_lock(gpr_mu* mu) { GPR_ASSERT(pthread_mutex_lock(mu) == 0); } +void gpr_mu_lock(gpr_mu* mu) { + GPR_TIMER_BEGIN("gpr_mu_lock", 0); + GPR_ASSERT(pthread_mutex_lock(mu) == 0); + GPR_TIMER_END("gpr_mu_lock", 0); +} -void gpr_mu_unlock(gpr_mu* mu) { GPR_ASSERT(pthread_mutex_unlock(mu) == 0); } +void gpr_mu_unlock(gpr_mu* mu) { + GPR_TIMER_BEGIN("gpr_mu_unlock", 0); + GPR_ASSERT(pthread_mutex_unlock(mu) == 0); + GPR_TIMER_END("gpr_mu_unlock", 0); +} int gpr_mu_trylock(gpr_mu* mu) { int err = pthread_mutex_trylock(mu); diff --git a/src/core/support/time_posix.c b/src/core/support/time_posix.c index 78f2c2bb77..02cfca8555 100644 --- a/src/core/support/time_posix.c +++ b/src/core/support/time_posix.c @@ -63,7 +63,7 @@ static gpr_timespec gpr_from_timespec(struct timespec ts, /** maps gpr_clock_type --> clockid_t for clock_gettime */ static clockid_t clockid_for_gpr_clock[] = {CLOCK_MONOTONIC, CLOCK_REALTIME}; -void gpr_time_init(void) {} +void gpr_time_init(void) { gpr_precise_clock_init(); } gpr_timespec gpr_now(gpr_clock_type clock_type) { struct timespec now; @@ -89,6 +89,7 @@ static uint64_t g_time_start; void gpr_time_init(void) { mach_timebase_info_data_t tb = {0, 1}; + gpr_precise_clock_init(); mach_timebase_info(&tb); g_time_scale = tb.numer; g_time_scale /= tb.denom; diff --git a/src/core/support/time_precise.c b/src/core/support/time_precise.c new file mode 100644 index 0000000000..b37517e639 --- /dev/null +++ b/src/core/support/time_precise.c @@ -0,0 +1,89 @@ +/* + * + * Copyright 2015, Google Inc. + * All rights reserved. + * + * Redistribution and use in source and binary forms, with or without + * modification, are permitted provided that the following conditions are + * met: + * + * * Redistributions of source code must retain the above copyright + * notice, this list of conditions and the following disclaimer. + * * Redistributions in binary form must reproduce the above + * copyright notice, this list of conditions and the following disclaimer + * in the documentation and/or other materials provided with the + * distribution. + * * Neither the name of Google Inc. nor the names of its + * contributors may be used to endorse or promote products derived from + * this software without specific prior written permission. + * + * THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS + * "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT + * LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR + * A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT + * OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, + * SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT + * LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, + * DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY + * THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT + * (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE + * OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE. + * + */ + +#include <grpc/support/log.h> +#include <grpc/support/time.h> +#include <stdio.h> + +#ifdef GRPC_TIMERS_RDTSC +#if defined(__i386__) +static void gpr_get_cycle_counter(long long int *clk) { + long long int ret; + __asm__ volatile("rdtsc" : "=A"(ret)); + *clk = ret; +} + +// ---------------------------------------------------------------- +#elif defined(__x86_64__) || defined(__amd64__) +static void gpr_get_cycle_counter(long long int *clk) { + unsigned long long low, high; + __asm__ volatile("rdtsc" : "=a"(low), "=d"(high)); + *clk = (long long)(high << 32) | (long long)low; +} +#endif + +static double cycles_per_second = 0; +static long long int start_cycle; +void gpr_precise_clock_init(void) { + time_t start; + long long end_cycle; + gpr_log(GPR_DEBUG, "Calibrating timers"); + start = time(NULL); + while (time(NULL) == start) + ; + gpr_get_cycle_counter(&start_cycle); + while (time(NULL) <= start + 10) + ; + gpr_get_cycle_counter(&end_cycle); + cycles_per_second = (double)(end_cycle - start_cycle) / 10.0; + gpr_log(GPR_DEBUG, "... cycles_per_second = %f\n", cycles_per_second); +} + +void gpr_precise_clock_now(gpr_timespec *clk) { + long long int counter; + double secs; + gpr_get_cycle_counter(&counter); + secs = (double)(counter - start_cycle) / cycles_per_second; + clk->clock_type = GPR_CLOCK_PRECISE; + clk->tv_sec = (time_t)secs; + clk->tv_nsec = (int)(1e9 * (secs - (double)clk->tv_sec)); +} + +#else /* GRPC_TIMERS_RDTSC */ +void gpr_precise_clock_init(void) {} + +void gpr_precise_clock_now(gpr_timespec *clk) { + *clk = gpr_now(GPR_CLOCK_REALTIME); + clk->clock_type = GPR_CLOCK_PRECISE; +} +#endif /* GRPC_TIMERS_RDTSC */ diff --git a/src/core/support/time_precise.h b/src/core/support/time_precise.h index cd201faab9..80c5000123 100644 --- a/src/core/support/time_precise.h +++ b/src/core/support/time_precise.h @@ -34,60 +34,9 @@ #ifndef GRPC_CORE_SUPPORT_TIME_PRECISE_H_ #define GRPC_CORE_SUPPORT_TIME_PRECISE_H_ -#include <grpc/support/sync.h> #include <grpc/support/time.h> -#include <stdio.h> -#ifdef GRPC_TIMERS_RDTSC -#if defined(__i386__) -static void gpr_get_cycle_counter(long long int *clk) { - long long int ret; - __asm__ volatile("rdtsc" : "=A"(ret)); - *clk = ret; -} - -// ---------------------------------------------------------------- -#elif defined(__x86_64__) || defined(__amd64__) -static void gpr_get_cycle_counter(long long int *clk) { - unsigned long long low, high; - __asm__ volatile("rdtsc" : "=a"(low), "=d"(high)); - *clk = (high << 32) | low; -} -#endif - -static gpr_once precise_clock_init = GPR_ONCE_INIT; -static long long cycles_per_second = 0; -static void gpr_precise_clock_init() { - time_t start = time(NULL); - gpr_precise_clock start_cycle; - gpr_precise_clock end_cycle; - while (time(NULL) == start) - ; - gpr_get_cycle_counter(&start_cycle); - while (time(NULL) == start + 1) - ; - gpr_get_cycle_counter(&end_cycle); - cycles_per_second = end_cycle - start_cycle; -} - -static double grpc_precise_clock_scaling_factor() { - gpr_once_init(&precise_clock_init, grpc_precise_clock_init); - return 1e6 / cycles_per_second; -} - -static void gpr_precise_clock_now(gpr_timespec *clk) { - long long int counter; - gpr_get_cycle_counter(&counter); - clk->clock = GPR_CLOCK_REALTIME; - clk->tv_sec = counter / cycles_per_second; - clk->tv_nsec = counter % cycles_per_second; -} - -#else /* GRPC_TIMERS_RDTSC */ -static void gpr_precise_clock_now(gpr_timespec *clk) { - *clk = gpr_now(GPR_CLOCK_REALTIME); - clk->clock_type = GPR_CLOCK_PRECISE; -} -#endif /* GRPC_TIMERS_RDTSC */ +void gpr_precise_clock_init(void); +void gpr_precise_clock_now(gpr_timespec *clk); #endif /* GRPC_CORE_SUPPORT_TIME_PRECISE_ */ diff --git a/src/core/surface/call.c b/src/core/surface/call.c index c963d64ecb..1f8ffd88c1 100644 --- a/src/core/surface/call.c +++ b/src/core/surface/call.c @@ -306,8 +306,9 @@ grpc_call *grpc_call_create(grpc_channel *channel, grpc_call *parent_call, grpc_transport_stream_op *initial_op_ptr = NULL; grpc_channel_stack *channel_stack = grpc_channel_get_channel_stack(channel); grpc_exec_ctx exec_ctx = GRPC_EXEC_CTX_INIT; - grpc_call *call = - gpr_malloc(sizeof(grpc_call) + channel_stack->call_stack_size); + grpc_call *call; + GPR_TIMER_BEGIN("grpc_call_create", 0); + call = gpr_malloc(sizeof(grpc_call) + channel_stack->call_stack_size); memset(call, 0, sizeof(grpc_call)); gpr_mu_init(&call->mu); gpr_mu_init(&call->completion_mu); @@ -401,6 +402,7 @@ grpc_call *grpc_call_create(grpc_channel *channel, grpc_call *parent_call, set_deadline_alarm(&exec_ctx, call, send_deadline); } grpc_exec_ctx_finish(&exec_ctx); + GPR_TIMER_END("grpc_call_create", 0); return call; } @@ -461,6 +463,7 @@ void grpc_call_internal_ref(grpc_call *c) { static void destroy_call(grpc_exec_ctx *exec_ctx, grpc_call *call) { size_t i; grpc_call *c = call; + GPR_TIMER_BEGIN("destroy_call", 0); grpc_call_stack_destroy(exec_ctx, CALL_STACK_FROM_CALL(c)); GRPC_CHANNEL_INTERNAL_UNREF(exec_ctx, c->channel, "call"); gpr_mu_destroy(&c->mu); @@ -493,6 +496,7 @@ static void destroy_call(grpc_exec_ctx *exec_ctx, grpc_call *call) { GRPC_CQ_INTERNAL_UNREF(c->cq, "bind"); } gpr_free(c); + GPR_TIMER_END("destroy_call", 0); } #ifdef GRPC_CALL_REF_COUNT_DEBUG @@ -624,6 +628,8 @@ static void unlock(grpc_exec_ctx *exec_ctx, grpc_call *call) { const size_t MAX_RECV_PEEK_AHEAD = 65536; size_t buffered_bytes; + GPR_TIMER_BEGIN("unlock", 0); + memset(&op, 0, sizeof(op)); op.cancel_with_status = call->cancel_with_status; @@ -694,6 +700,8 @@ static void unlock(grpc_exec_ctx *exec_ctx, grpc_call *call) { unlock(exec_ctx, call); GRPC_CALL_INTERNAL_UNREF(exec_ctx, call, "completing"); } + + GPR_TIMER_END("unlock", 0); } static void get_final_status(grpc_call *call, grpc_ioreq_data out) { @@ -843,6 +851,7 @@ static void early_out_write_ops(grpc_call *call) { static void call_on_done_send(grpc_exec_ctx *exec_ctx, void *pc, int success) { grpc_call *call = pc; + GPR_TIMER_BEGIN("call_on_done_send", 0); lock(call); if (call->last_send_contains & (1 << GRPC_IOREQ_SEND_INITIAL_METADATA)) { finish_ioreq_op(call, GRPC_IOREQ_SEND_INITIAL_METADATA, success); @@ -866,9 +875,11 @@ static void call_on_done_send(grpc_exec_ctx *exec_ctx, void *pc, int success) { call->sending = 0; unlock(exec_ctx, call); GRPC_CALL_INTERNAL_UNREF(exec_ctx, call, "sending"); + GPR_TIMER_END("call_on_done_send", 0); } static void finish_message(grpc_call *call) { + GPR_TIMER_BEGIN("finish_message", 0); if (call->error_status_set == 0) { /* TODO(ctiller): this could be a lot faster if coded directly */ grpc_byte_buffer *byte_buffer; @@ -888,6 +899,7 @@ static void finish_message(grpc_call *call) { gpr_slice_buffer_reset_and_unref(&call->incoming_message); GPR_ASSERT(call->incoming_message.count == 0); call->reading_message = 0; + GPR_TIMER_END("finish_message", 0); } static int begin_message(grpc_call *call, grpc_begin_message msg) { @@ -977,7 +989,7 @@ static void call_on_done_recv(grpc_exec_ctx *exec_ctx, void *pc, int success) { grpc_call *child_call; grpc_call *next_child_call; size_t i; - GRPC_TIMER_BEGIN(GRPC_PTAG_CALL_ON_DONE_RECV, 0); + GPR_TIMER_BEGIN("call_on_done_recv", 0); lock(call); call->receiving = 0; if (success) { @@ -987,13 +999,19 @@ static void call_on_done_recv(grpc_exec_ctx *exec_ctx, void *pc, int success) { case GRPC_NO_OP: break; case GRPC_OP_METADATA: + GPR_TIMER_BEGIN("recv_metadata", 0); recv_metadata(exec_ctx, call, &op->data.metadata); + GPR_TIMER_END("recv_metadata", 0); break; case GRPC_OP_BEGIN_MESSAGE: + GPR_TIMER_BEGIN("begin_message", 0); success = begin_message(call, op->data.begin_message); + GPR_TIMER_END("begin_message", 0); break; case GRPC_OP_SLICE: + GPR_TIMER_BEGIN("add_slice_to_message", 0); success = add_slice_to_message(call, op->data.slice); + GPR_TIMER_END("add_slice_to_message", 0); break; } } @@ -1039,7 +1057,7 @@ static void call_on_done_recv(grpc_exec_ctx *exec_ctx, void *pc, int success) { unlock(exec_ctx, call); GRPC_CALL_INTERNAL_UNREF(exec_ctx, call, "receiving"); - GRPC_TIMER_END(GRPC_PTAG_CALL_ON_DONE_RECV, 0); + GPR_TIMER_END("call_on_done_recv", 0); } static int prepare_application_metadata(grpc_call *call, size_t count, @@ -1517,16 +1535,25 @@ static void recv_metadata(grpc_exec_ctx *exec_ctx, grpc_call *call, grpc_mdelem *mdel = l->md; grpc_mdstr *key = mdel->key; if (key == grpc_channel_get_status_string(call->channel)) { + GPR_TIMER_BEGIN("status", 0); set_status_code(call, STATUS_FROM_WIRE, decode_status(mdel)); + GPR_TIMER_END("status", 0); } else if (key == grpc_channel_get_message_string(call->channel)) { + GPR_TIMER_BEGIN("status-details", 0); set_status_details(call, STATUS_FROM_WIRE, GRPC_MDSTR_REF(mdel->value)); + GPR_TIMER_END("status-details", 0); } else if (key == grpc_channel_get_compression_algorithm_string(call->channel)) { + GPR_TIMER_BEGIN("compression_algorithm", 0); set_compression_algorithm(call, decode_compression(mdel)); + GPR_TIMER_END("compression_algorithm", 0); } else if (key == grpc_channel_get_encodings_accepted_by_peer_string( call->channel)) { + GPR_TIMER_BEGIN("encodings_accepted_by_peer", 0); set_encodings_accepted_by_peer(call, mdel->value->slice); + GPR_TIMER_END("encodings_accepted_by_peer", 0); } else { + GPR_TIMER_BEGIN("report_up", 0); dest = &call->buffered_metadata[is_trailing]; if (dest->count == dest->capacity) { dest->capacity = GPR_MAX(dest->capacity + 8, dest->capacity * 2); @@ -1547,12 +1574,15 @@ static void recv_metadata(grpc_exec_ctx *exec_ctx, grpc_call *call, } call->owned_metadata[call->owned_metadata_count++] = mdel; l->md = NULL; + GPR_TIMER_END("report_up", 0); } } if (gpr_time_cmp(md->deadline, gpr_inf_future(md->deadline.clock_type)) != 0 && !call->is_client) { + GPR_TIMER_BEGIN("set_deadline_alarm", 0); set_deadline_alarm(exec_ctx, call, md->deadline); + GPR_TIMER_END("set_deadline_alarm", 0); } if (!is_trailing) { call->read_state = READ_STATE_GOT_INITIAL_METADATA; @@ -1615,6 +1645,8 @@ grpc_call_error grpc_call_start_batch(grpc_call *call, const grpc_op *ops, grpc_call_error error; grpc_exec_ctx exec_ctx = GRPC_EXEC_CTX_INIT; + GPR_TIMER_BEGIN("grpc_call_start_batch", 0); + GRPC_API_TRACE( "grpc_call_start_batch(call=%p, ops=%p, nops=%lu, tag=%p, reserved=%p)", 5, (call, ops, (unsigned long)nops, tag, reserved)); @@ -1852,6 +1884,7 @@ grpc_call_error grpc_call_start_batch(grpc_call *call, const grpc_op *ops, finish_func, tag); done: grpc_exec_ctx_finish(&exec_ctx); + GPR_TIMER_END("grpc_call_start_batch", 0); return error; } diff --git a/src/core/surface/completion_queue.c b/src/core/surface/completion_queue.c index c435c48d01..aa90b3f7f5 100644 --- a/src/core/surface/completion_queue.c +++ b/src/core/surface/completion_queue.c @@ -43,6 +43,7 @@ #include "src/core/surface/call.h" #include "src/core/surface/event_string.h" #include "src/core/surface/surface_trace.h" +#include "src/core/profiling/timers.h" #include <grpc/support/alloc.h> #include <grpc/support/atm.h> #include <grpc/support/log.h> @@ -154,6 +155,8 @@ void grpc_cq_end_op(grpc_exec_ctx *exec_ctx, grpc_completion_queue *cc, int i; grpc_pollset_worker *pluck_worker; + GPR_TIMER_BEGIN("grpc_cq_end_op", 0); + storage->tag = tag; storage->done = done; storage->done_arg = done_arg; @@ -185,6 +188,8 @@ void grpc_cq_end_op(grpc_exec_ctx *exec_ctx, grpc_completion_queue *cc, gpr_mu_unlock(GRPC_POLLSET_MU(&cc->pollset)); grpc_pollset_shutdown(exec_ctx, &cc->pollset, &cc->pollset_destroy_done); } + + GPR_TIMER_END("grpc_cq_end_op", 0); } grpc_event grpc_completion_queue_next(grpc_completion_queue *cc, @@ -195,6 +200,8 @@ grpc_event grpc_completion_queue_next(grpc_completion_queue *cc, gpr_timespec now; grpc_exec_ctx exec_ctx = GRPC_EXEC_CTX_INIT; + GPR_TIMER_BEGIN("grpc_completion_queue_next", 0); + GRPC_API_TRACE( "grpc_completion_queue_next(" "cc=%p, " @@ -241,6 +248,9 @@ grpc_event grpc_completion_queue_next(grpc_completion_queue *cc, GRPC_SURFACE_TRACE_RETURNED_EVENT(cc, &ret); GRPC_CQ_INTERNAL_UNREF(cc, "next"); grpc_exec_ctx_finish(&exec_ctx); + + GPR_TIMER_END("grpc_completion_queue_next", 0); + return ret; } @@ -278,6 +288,8 @@ grpc_event grpc_completion_queue_pluck(grpc_completion_queue *cc, void *tag, int first_loop = 1; grpc_exec_ctx exec_ctx = GRPC_EXEC_CTX_INIT; + GPR_TIMER_BEGIN("grpc_completion_queue_pluck", 0); + GRPC_API_TRACE( "grpc_completion_queue_pluck(" "cc=%p, tag=%p, " @@ -343,6 +355,9 @@ done: GRPC_SURFACE_TRACE_RETURNED_EVENT(cc, &ret); GRPC_CQ_INTERNAL_UNREF(cc, "pluck"); grpc_exec_ctx_finish(&exec_ctx); + + GPR_TIMER_END("grpc_completion_queue_pluck", 0); + return ret; } diff --git a/src/core/surface/init.c b/src/core/surface/init.c index 95011cab17..715c90a5e1 100644 --- a/src/core/surface/init.c +++ b/src/core/surface/init.c @@ -115,7 +115,7 @@ void grpc_init(void) { gpr_log(GPR_ERROR, "Could not initialize census."); } } - grpc_timers_global_init(); + gpr_timers_global_init(); for (i = 0; i < g_number_of_plugins; i++) { if (g_all_of_the_plugins[i].init != NULL) { g_all_of_the_plugins[i].init(); @@ -133,7 +133,7 @@ void grpc_shutdown(void) { if (--g_initializations == 0) { grpc_iomgr_shutdown(); census_shutdown(); - grpc_timers_global_destroy(); + gpr_timers_global_destroy(); grpc_tracer_shutdown(); grpc_resolver_registry_shutdown(); for (i = 0; i < g_number_of_plugins; i++) { diff --git a/src/core/transport/chttp2/parsing.c b/src/core/transport/chttp2/parsing.c index a0977ccaf6..5d4d8e70c4 100644 --- a/src/core/transport/chttp2/parsing.c +++ b/src/core/transport/chttp2/parsing.c @@ -35,6 +35,7 @@ #include <string.h> +#include "src/core/profiling/timers.h" #include "src/core/transport/chttp2/http2_errors.h" #include "src/core/transport/chttp2/status_conversion.h" #include "src/core/transport/chttp2/timeout_encoding.h" @@ -68,6 +69,8 @@ void grpc_chttp2_prepare_to_read( grpc_chttp2_stream_global *stream_global; grpc_chttp2_stream_parsing *stream_parsing; + GPR_TIMER_BEGIN("grpc_chttp2_prepare_to_read", 0); + transport_parsing->next_stream_id = transport_global->next_stream_id; /* update the parsing view of incoming window */ @@ -89,6 +92,8 @@ void grpc_chttp2_prepare_to_read( stream_parsing->incoming_window = stream_global->incoming_window; } } + + GPR_TIMER_END("grpc_chttp2_prepare_to_read", 0); } void grpc_chttp2_publish_reads( diff --git a/src/core/transport/chttp2/writing.c b/src/core/transport/chttp2/writing.c index d1c9da6df0..69ad8854ba 100644 --- a/src/core/transport/chttp2/writing.c +++ b/src/core/transport/chttp2/writing.c @@ -37,6 +37,7 @@ #include <grpc/support/log.h> +#include "src/core/profiling/timers.h" #include "src/core/transport/chttp2/http2_errors.h" static void finalize_outbuf(grpc_chttp2_transport_writing *transport_writing); @@ -180,6 +181,8 @@ void grpc_chttp2_perform_writes( static void finalize_outbuf(grpc_chttp2_transport_writing *transport_writing) { grpc_chttp2_stream_writing *stream_writing; + GPR_TIMER_BEGIN("finalize_outbuf", 0); + while ( grpc_chttp2_list_pop_writing_stream(transport_writing, &stream_writing)) { if (stream_writing->sopb.nops > 0 || @@ -208,6 +211,8 @@ static void finalize_outbuf(grpc_chttp2_transport_writing *transport_writing) { } grpc_chttp2_list_add_written_stream(transport_writing, stream_writing); } + + GPR_TIMER_END("finalize_outbuf", 0); } void grpc_chttp2_cleanup_writing( diff --git a/src/core/transport/chttp2_transport.c b/src/core/transport/chttp2_transport.c index de74379546..effc3c4b3b 100644 --- a/src/core/transport/chttp2_transport.c +++ b/src/core/transport/chttp2_transport.c @@ -510,6 +510,7 @@ grpc_chttp2_stream_parsing *grpc_chttp2_parsing_accept_stream( static void lock(grpc_chttp2_transport *t) { gpr_mu_lock(&t->mu); } static void unlock(grpc_exec_ctx *exec_ctx, grpc_chttp2_transport *t) { + GPR_TIMER_BEGIN("unlock", 0); unlock_check_read_write_state(exec_ctx, t); if (!t->writing_active && !t->closed && grpc_chttp2_unlocking_check_writes(&t->global, &t->writing)) { @@ -520,6 +521,7 @@ static void unlock(grpc_exec_ctx *exec_ctx, grpc_chttp2_transport *t) { } gpr_mu_unlock(&t->mu); + GPR_TIMER_END("unlock", 0); } /* @@ -546,6 +548,8 @@ void grpc_chttp2_terminate_writing(grpc_exec_ctx *exec_ctx, grpc_chttp2_transport_writing *transport_writing = transport_writing_ptr; grpc_chttp2_transport *t = TRANSPORT_FROM_WRITING(transport_writing); + GPR_TIMER_BEGIN("grpc_chttp2_terminate_writing", 0); + lock(t); allow_endpoint_shutdown_locked(exec_ctx, t); @@ -567,12 +571,16 @@ void grpc_chttp2_terminate_writing(grpc_exec_ctx *exec_ctx, unlock(exec_ctx, t); UNREF_TRANSPORT(exec_ctx, t, "writing"); + + GPR_TIMER_END("grpc_chttp2_terminate_writing", 0); } static void writing_action(grpc_exec_ctx *exec_ctx, void *gt, int iomgr_success_ignored) { grpc_chttp2_transport *t = gt; + GPR_TIMER_BEGIN("writing_action", 0); grpc_chttp2_perform_writes(exec_ctx, &t->writing, t->ep); + GPR_TIMER_END("writing_action", 0); } void grpc_chttp2_add_incoming_goaway( @@ -642,6 +650,7 @@ static void maybe_start_some_streams( static void perform_stream_op_locked( grpc_exec_ctx *exec_ctx, grpc_chttp2_transport_global *transport_global, grpc_chttp2_stream_global *stream_global, grpc_transport_stream_op *op) { + GPR_TIMER_BEGIN("perform_stream_op_locked", 0); if (op->cancel_with_status != GRPC_STATUS_OK) { cancel_from_api(transport_global, stream_global, op->cancel_with_status); } @@ -713,6 +722,7 @@ static void perform_stream_op_locked( } grpc_exec_ctx_enqueue(exec_ctx, op->on_consumed, 1); + GPR_TIMER_END("perform_stream_op_locked", 0); } static void perform_stream_op(grpc_exec_ctx *exec_ctx, grpc_transport *gt, @@ -1103,6 +1113,8 @@ static void recv_data(grpc_exec_ctx *exec_ctx, void *tp, int success) { int keep_reading = 0; grpc_chttp2_transport *t = tp; + GPR_TIMER_BEGIN("recv_data", 0); + lock(t); i = 0; GPR_ASSERT(!t->parsing_active); @@ -1113,11 +1125,13 @@ static void recv_data(grpc_exec_ctx *exec_ctx, void *tp, int success) { &t->parsing_stream_map); grpc_chttp2_prepare_to_read(&t->global, &t->parsing); gpr_mu_unlock(&t->mu); + GPR_TIMER_BEGIN("recv_data.parse", 0); for (; i < t->read_buffer.count && grpc_chttp2_perform_read(exec_ctx, &t->parsing, t->read_buffer.slices[i]); i++) ; + GPR_TIMER_END("recv_data.parse", 0); gpr_mu_lock(&t->mu); if (i != t->read_buffer.count) { drop_connection(exec_ctx, t); @@ -1154,6 +1168,8 @@ static void recv_data(grpc_exec_ctx *exec_ctx, void *tp, int success) { } else { UNREF_TRANSPORT(exec_ctx, t, "recv_data"); } + + GPR_TIMER_END("recv_data", 0); } /* diff --git a/src/core/transport/stream_op.c b/src/core/transport/stream_op.c index 1cb2bd7c59..6493e77bc5 100644 --- a/src/core/transport/stream_op.c +++ b/src/core/transport/stream_op.c @@ -38,6 +38,8 @@ #include <grpc/support/alloc.h> #include <grpc/support/log.h> +#include "src/core/profiling/timers.h" + /* Exponential growth function: Given x, return a larger x. Currently we grow by 1.5 times upon reallocation. */ #define GROW(x) (3 * (x) / 2) @@ -300,6 +302,8 @@ void grpc_metadata_batch_filter(grpc_metadata_batch *batch, grpc_linked_mdelem *l; grpc_linked_mdelem *next; + GPR_TIMER_BEGIN("grpc_metadata_batch_filter", 0); + assert_valid_list(&batch->list); assert_valid_list(&batch->garbage); for (l = batch->list.head; l; l = next) { @@ -328,4 +332,6 @@ void grpc_metadata_batch_filter(grpc_metadata_batch *batch, } assert_valid_list(&batch->list); assert_valid_list(&batch->garbage); + + GPR_TIMER_END("grpc_metadata_batch_filter", 0); } diff --git a/src/core/tsi/fake_transport_security.c b/src/core/tsi/fake_transport_security.c index a40268a7f0..99e28ab63b 100644 --- a/src/core/tsi/fake_transport_security.c +++ b/src/core/tsi/fake_transport_security.c @@ -121,7 +121,7 @@ static void store32_little_endian(gpr_uint32 value, unsigned char *buf) { buf[3] = (unsigned char)((value >> 24) & 0xFF); buf[2] = (unsigned char)((value >> 16) & 0xFF); buf[1] = (unsigned char)((value >> 8) & 0xFF); - buf[0] = (unsigned char)((value) & 0xFF); + buf[0] = (unsigned char)((value)&0xFF); } static void tsi_fake_frame_reset(tsi_fake_frame *frame, int needs_draining) { |