From 8910ac6a363173b037a209debdc2b4528e9309f6 Mon Sep 17 00:00:00 2001 From: Craig Tiller <ctiller@google.com> Date: Thu, 8 Oct 2015 16:49:15 -0700 Subject: [PATCH] more markers --- src/core/channel/client_channel.c | 16 +++++++++++----- src/core/iomgr/exec_ctx.c | 4 +++- src/core/profiling/timers.h | 16 ++++++++++++++-- src/core/support/alloc.c | 14 ++++++++++++-- src/core/support/sync_posix.c | 13 +++++++++++-- src/core/surface/call.c | 2 ++ src/core/transport/chttp2_transport.c | 6 ++++++ 7 files changed, 59 insertions(+), 12 deletions(-) diff --git a/src/core/channel/client_channel.c b/src/core/channel/client_channel.c index 8e7cb27cfd..b3e10b0237 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 */ @@ -235,6 +237,8 @@ static void picked_target(grpc_exec_ctx *exec_ctx, void *arg, call_data *calld = arg; grpc_pollset *pollset; + GRPC_TIMER_BEGIN(GRPC_PTAG_CHANNEL_PICKED_TARGET, 0); + if (calld->picked_channel == NULL) { /* treat this like a cancellation */ calld->waiting_op.cancel_with_status = GRPC_STATUS_UNAVAILABLE; @@ -255,6 +259,8 @@ static void picked_target(grpc_exec_ctx *exec_ctx, void *arg, &calld->async_setup_task); } } + + GRPC_TIMER_END(GRPC_PTAG_CHANNEL_PICKED_TARGET, 0); } static grpc_closure *merge_into_waiting_op(grpc_call_element *elem, diff --git a/src/core/iomgr/exec_ctx.c b/src/core/iomgr/exec_ctx.c index 10786b44c2..7e40c55172 100644 --- a/src/core/iomgr/exec_ctx.c +++ b/src/core/iomgr/exec_ctx.c @@ -45,8 +45,10 @@ int grpc_exec_ctx_flush(grpc_exec_ctx *exec_ctx) { exec_ctx->closure_list.head = exec_ctx->closure_list.tail = NULL; while (c != NULL) { grpc_closure *next = c->next; - did_something = 1; + did_something++; + GRPC_TIMER_BEGIN(GRPC_PTAG_EXEC_CTX_STEP, 0); c->cb(exec_ctx, c->cb_arg, c->success); + GRPC_TIMER_END(GRPC_PTAG_EXEC_CTX_STEP, 0); c = next; } } diff --git a/src/core/profiling/timers.h b/src/core/profiling/timers.h index 326c1997c3..8305dac2cf 100644 --- a/src/core/profiling/timers.h +++ b/src/core/profiling/timers.h @@ -65,6 +65,12 @@ enum grpc_profiling_tags { GRPC_PTAG_TCP_WRITE = 205 + GRPC_PTAG_IGNORE_THRESHOLD, GRPC_PTAG_BECOME_READABLE = 207, + GRPC_PTAG_MUTEX_LOCK = 250, + GRPC_PTAG_MUTEX_UNLOCK = 254, + GRPC_PTAG_MALLOC = 251, + GRPC_PTAG_REALLOC = 252, + GRPC_PTAG_FREE = 253, + /* C++ */ GRPC_PTAG_CPP_CALL_CREATED = 300 + GRPC_PTAG_IGNORE_THRESHOLD, GRPC_PTAG_CPP_PERFORM_OPS = 301 + GRPC_PTAG_IGNORE_THRESHOLD, @@ -74,19 +80,25 @@ enum grpc_profiling_tags { /* Transports */ GRPC_PTAG_HTTP2_RECV_DATA = 400, - GRPC_PTAG_HTTP2_UNLOCK = 401 + GRPC_PTAG_IGNORE_THRESHOLD, - GRPC_PTAG_HTTP2_UNLOCK_CLEANUP = 402 + GRPC_PTAG_IGNORE_THRESHOLD, + GRPC_PTAG_HTTP2_UNLOCK = 401, + GRPC_PTAG_HTTP2_WRITING_ACTION = 402, + GRPC_PTAG_HTTP2_TERMINATE_WRITING = 403, /* Completion queue */ GRPC_PTAG_CQ_NEXT = 501, GRPC_PTAG_CQ_PLUCK = 502, GRPC_PTAG_POLLSET_WORK = 503, GRPC_PTAG_EXEC_CTX_FLUSH = 504, + GRPC_PTAG_EXEC_CTX_STEP = 505, /* Surface */ GRPC_PTAG_CALL_START_BATCH = 600, GRPC_PTAG_CALL_ON_DONE_RECV = 601, GRPC_PTAG_CALL_UNLOCK = 602, + GRPC_PTAG_CALL_ON_DONE_SEND = 602, + + /* Channel */ + GRPC_PTAG_CHANNEL_PICKED_TARGET = 700, /* > 1024 Unassigned reserved. For any miscellaneous use. * Use addition to generate tags from this base or take advantage of the 10 diff --git a/src/core/support/alloc.c b/src/core/support/alloc.c index d2ed82e771..5e17daafe2 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; + GRPC_TIMER_BEGIN(GRPC_PTAG_MALLOC, 0); + p = malloc(size); if (!p) { abort(); } + GRPC_TIMER_END(GRPC_PTAG_MALLOC, 0); return p; } -void gpr_free(void *p) { free(p); } +void gpr_free(void *p) { + GRPC_TIMER_BEGIN(GRPC_PTAG_FREE, 0); + free(p); + GRPC_TIMER_END(GRPC_PTAG_FREE, 0); +} void *gpr_realloc(void *p, size_t size) { + GRPC_TIMER_BEGIN(GRPC_PTAG_REALLOC, 0); p = realloc(p, size); if (!p) { abort(); } + GRPC_TIMER_END(GRPC_PTAG_REALLOC, 0); return p; } diff --git a/src/core/support/sync_posix.c b/src/core/support/sync_posix.c index 91c30989ce..25a580c289 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) { + GRPC_TIMER_BEGIN(GRPC_PTAG_MUTEX_LOCK, 0); + GPR_ASSERT(pthread_mutex_lock(mu) == 0); + GRPC_TIMER_END(GRPC_PTAG_MUTEX_LOCK, 0); +} -void gpr_mu_unlock(gpr_mu* mu) { GPR_ASSERT(pthread_mutex_unlock(mu) == 0); } +void gpr_mu_unlock(gpr_mu* mu) { + GRPC_TIMER_BEGIN(GRPC_PTAG_MUTEX_UNLOCK, 0); + GPR_ASSERT(pthread_mutex_unlock(mu) == 0); + GRPC_TIMER_END(GRPC_PTAG_MUTEX_UNLOCK, 0); +} int gpr_mu_trylock(gpr_mu* mu) { int err = pthread_mutex_trylock(mu); diff --git a/src/core/surface/call.c b/src/core/surface/call.c index 6747c8af56..9e2182952b 100644 --- a/src/core/surface/call.c +++ b/src/core/surface/call.c @@ -836,6 +836,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; + GRPC_TIMER_BEGIN(GRPC_PTAG_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); @@ -859,6 +860,7 @@ 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"); + GRPC_TIMER_END(GRPC_PTAG_CALL_ON_DONE_SEND, 0); } static void finish_message(grpc_call *call) { diff --git a/src/core/transport/chttp2_transport.c b/src/core/transport/chttp2_transport.c index b4508b42bc..0a1b3a8176 100644 --- a/src/core/transport/chttp2_transport.c +++ b/src/core/transport/chttp2_transport.c @@ -546,6 +546,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); + GRPC_TIMER_BEGIN(GRPC_PTAG_HTTP2_TERMINATE_WRITING, 0); + lock(t); allow_endpoint_shutdown_locked(exec_ctx, t); @@ -567,12 +569,16 @@ void grpc_chttp2_terminate_writing(grpc_exec_ctx *exec_ctx, unlock(exec_ctx, t); UNREF_TRANSPORT(exec_ctx, t, "writing"); + + GRPC_TIMER_END(GRPC_PTAG_HTTP2_TERMINATE_WRITING, 0); } static void writing_action(grpc_exec_ctx *exec_ctx, void *gt, int iomgr_success_ignored) { grpc_chttp2_transport *t = gt; + GRPC_TIMER_BEGIN(GRPC_PTAG_HTTP2_WRITING_ACTION, 0); grpc_chttp2_perform_writes(exec_ctx, &t->writing, t->ep); + GRPC_TIMER_END(GRPC_PTAG_HTTP2_WRITING_ACTION, 0); } void grpc_chttp2_add_incoming_goaway( -- GitLab