Simplify adding annotations, annotate more things
diff --git a/src/core/channel/client_channel.c b/src/core/channel/client_channel.c
index b3e10b0..79c5658 100644
--- a/src/core/channel/client_channel.c
+++ b/src/core/channel/client_channel.c
@@ -237,7 +237,7 @@
call_data *calld = arg;
grpc_pollset *pollset;
- GRPC_TIMER_BEGIN(GRPC_PTAG_CHANNEL_PICKED_TARGET, 0);
+ GRPC_TIMER_BEGIN("picked_target", 0);
if (calld->picked_channel == NULL) {
/* treat this like a cancellation */
@@ -260,7 +260,7 @@
}
}
- GRPC_TIMER_END(GRPC_PTAG_CHANNEL_PICKED_TARGET, 0);
+ GRPC_TIMER_END("picked_target", 0);
}
static grpc_closure *merge_into_waiting_op(grpc_call_element *elem,
@@ -321,6 +321,7 @@
grpc_subchannel_call *subchannel_call;
grpc_lb_policy *lb_policy;
grpc_transport_stream_op op2;
+ GRPC_TIMER_BEGIN("perform_transport_stream_op", 0);
GPR_ASSERT(elem->filter == &grpc_client_channel_filter);
GRPC_CALL_LOG_OP(GPR_INFO, elem, op);
@@ -432,6 +433,8 @@
}
break;
}
+
+ GRPC_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 182fbf1..6c1ed29 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 compress_start_transport_stream_op(grpc_exec_ctx *exec_ctx,
grpc_call_element *elem,
grpc_transport_stream_op *op) {
+ GRPC_TIMER_BEGIN("compress_start_transport_stream_op", 0);
+
if (op->send_ops && op->send_ops->nops > 0) {
process_send_ops(elem, op->send_ops);
}
+ GRPC_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 f9fc280..6d4d7be 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 d67dc37..9a7f8c4 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_start_transport_op(grpc_exec_ctx *exec_ctx,
grpc_call_element *elem,
grpc_transport_stream_op *op) {
+ GRPC_TIMER_BEGIN("hc_start_transport_op", 0);
GRPC_CALL_LOG_OP(GPR_INFO, elem, op);
hc_mutate_op(elem, op);
+ GRPC_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 5e6d684..16a0c1d 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 @@
grpc_call_element *elem,
grpc_transport_stream_op *op) {
GRPC_CALL_LOG_OP(GPR_INFO, elem, op);
+ GRPC_TIMER_BEGIN("hs_start_transport_op", 0);
hs_mutate_op(elem, op);
grpc_call_next_op(exec_ctx, elem, op);
+ GRPC_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 4b3aaab..e5bf068 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 @@
}
}
-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 @@
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 7e40c55..1ad3988 100644
--- a/src/core/iomgr/exec_ctx.c
+++ b/src/core/iomgr/exec_ctx.c
@@ -39,20 +39,20 @@
int grpc_exec_ctx_flush(grpc_exec_ctx *exec_ctx) {
int did_something = 0;
- GRPC_TIMER_BEGIN(GRPC_PTAG_EXEC_CTX_FLUSH, 0);
+ GRPC_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++;
- GRPC_TIMER_BEGIN(GRPC_PTAG_EXEC_CTX_STEP, 0);
+ GRPC_TIMER_BEGIN("grpc_exec_ctx_flush.cb", 0);
c->cb(exec_ctx, c->cb_arg, c->success);
- GRPC_TIMER_END(GRPC_PTAG_EXEC_CTX_STEP, 0);
+ GRPC_TIMER_END("grpc_exec_ctx_flush.cb", 0);
c = next;
}
}
- GRPC_TIMER_END(GRPC_PTAG_EXEC_CTX_FLUSH, 0);
+ GRPC_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 1292d9c..e874391 100644
--- a/src/core/iomgr/pollset_multipoller_with_epoll.c
+++ b/src/core/iomgr/pollset_multipoller_with_epoll.c
@@ -183,11 +183,11 @@
/* TODO(vpai): Consider first doing a 0 timeout poll here to avoid
even going into the blocking annotation if possible */
- GRPC_TIMER_BEGIN(GRPC_PTAG_POLL, 0);
+ GRPC_TIMER_BEGIN("poll", 0);
GRPC_SCHEDULING_START_BLOCKING_REGION;
poll_rv = grpc_poll_function(pfds, 2, timeout_ms);
GRPC_SCHEDULING_END_BLOCKING_REGION;
- GRPC_TIMER_END(GRPC_PTAG_POLL, 0);
+ GRPC_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 0068b16..9fda8f8 100644
--- a/src/core/iomgr/pollset_posix.c
+++ b/src/core/iomgr/pollset_posix.c
@@ -229,7 +229,7 @@
int locked = 1;
int queued_work = 0;
int keep_polling = 0;
- GRPC_TIMER_BEGIN(GRPC_PTAG_POLLSET_WORK, 0);
+ GRPC_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;
@@ -274,10 +274,10 @@
}
gpr_tls_set(&g_current_thread_poller, (gpr_intptr)pollset);
gpr_tls_set(&g_current_thread_worker, (gpr_intptr)worker);
- GRPC_TIMER_BEGIN(GRPC_PTAG_POLLSET_WORK, 0);
+ GRPC_TIMER_BEGIN("maybe_work_and_unlock", 0);
pollset->vtable->maybe_work_and_unlock(exec_ctx, pollset, worker,
deadline, now);
- GRPC_TIMER_END(GRPC_PTAG_POLLSET_WORK, 0);
+ GRPC_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);
@@ -332,7 +332,7 @@
gpr_mu_lock(&pollset->mu);
}
}
- GRPC_TIMER_END(GRPC_PTAG_POLLSET_WORK, 0);
+ GRPC_TIMER_END("grpc_pollset_work", 0);
}
void grpc_pollset_shutdown(grpc_exec_ctx *exec_ctx, grpc_pollset *pollset,
@@ -567,11 +567,11 @@
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 */
- GRPC_TIMER_BEGIN(GRPC_PTAG_POLL, 0);
+ GRPC_TIMER_BEGIN("poll", 0);
GRPC_SCHEDULING_START_BLOCKING_REGION;
r = grpc_poll_function(pfd, nfds, timeout);
GRPC_SCHEDULING_END_BLOCKING_REGION;
- GRPC_TIMER_END(GRPC_PTAG_POLL, 0);
+ GRPC_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 540ebd6..9e3773b 100644
--- a/src/core/iomgr/tcp_posix.c
+++ b/src/core/iomgr/tcp_posix.c
@@ -180,7 +180,7 @@
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);
+ GRPC_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 @@
msg.msg_controllen = 0;
msg.msg_flags = 0;
- GRPC_TIMER_BEGIN(GRPC_PTAG_RECVMSG, 1);
+ GRPC_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);
+ GRPC_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 @@
TCP_UNREF(exec_ctx, tcp, "read");
}
- GRPC_TIMER_END(GRPC_PTAG_HANDLE_READ, 0);
+ GRPC_TIMER_END("tcp_continue_read", 0);
}
static void tcp_handle_read(grpc_exec_ctx *exec_ctx, void *arg /* grpc_tcp */,
@@ -316,12 +316,12 @@
msg.msg_controllen = 0;
msg.msg_flags = 0;
- GRPC_TIMER_BEGIN(GRPC_PTAG_SENDMSG, 1);
+ GRPC_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);
+ GRPC_TIMER_END("sendmsg", 0);
if (sent_length < 0) {
if (errno == EAGAIN) {
@@ -370,17 +370,17 @@
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;
+ GRPC_TIMER_BEGIN("tcp_handle_write.cb", 0);
cb->cb(exec_ctx, cb->cb_arg, status == FLUSH_DONE);
+ GRPC_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 @@
}
}
- GRPC_TIMER_BEGIN(GRPC_PTAG_TCP_WRITE, 0);
+ GRPC_TIMER_BEGIN("tcp_write", 0);
GPR_ASSERT(tcp->write_cb == NULL);
if (buf->length == 0) {
- GRPC_TIMER_END(GRPC_PTAG_TCP_WRITE, 0);
+ GRPC_TIMER_END("tcp_write", 0);
grpc_exec_ctx_enqueue(exec_ctx, cb, 1);
return;
}
@@ -420,7 +420,7 @@
grpc_exec_ctx_enqueue(exec_ctx, cb, status == FLUSH_DONE);
}
- GRPC_TIMER_END(GRPC_PTAG_TCP_WRITE, 0);
+ GRPC_TIMER_END("tcp_write", 0);
}
static void tcp_add_to_pollset(grpc_exec_ctx *exec_ctx, grpc_endpoint *ep,
diff --git a/src/core/profiling/basic_timers.c b/src/core/profiling/basic_timers.c
index 944ed5f..8a68277 100644
--- a/src/core/profiling/basic_timers.c
+++ b/src/core/profiling/basic_timers.c
@@ -44,11 +44,7 @@
#include <grpc/support/thd.h>
#include <stdio.h>
-typedef enum {
- BEGIN = '{',
- END = '}',
- MARK = '.'
-} marker_type;
+typedef enum { BEGIN = '{', END = '}', MARK = '.' } marker_type;
typedef struct grpc_timer_entry {
gpr_timespec tm;
@@ -91,7 +87,7 @@
g_count = 0;
}
-static void grpc_timers_log_add(int tag, const char *tagstr, marker_type type,
+static void grpc_timers_log_add(const char *tagstr, marker_type type,
int important, const char *file, int line) {
grpc_timer_entry *entry;
@@ -111,25 +107,19 @@
}
/* Latency profiler API implementation. */
-void grpc_timer_add_mark(int tag, const char *tagstr, int important,
- const char *file, int line) {
- if (tag < GRPC_PTAG_IGNORE_THRESHOLD) {
- grpc_timers_log_add(tag, tagstr, MARK, important, file, line);
- }
+void grpc_timer_add_mark(const char *tagstr, int important, const char *file,
+ int line) {
+ grpc_timers_log_add(tagstr, MARK, important, file, line);
}
-void grpc_timer_begin(int tag, const char *tagstr, int important, const char *file,
+void grpc_timer_begin(const char *tagstr, int important, const char *file,
int line) {
- if (tag < GRPC_PTAG_IGNORE_THRESHOLD) {
- grpc_timers_log_add(tag, tagstr, BEGIN, important, file, line);
- }
+ grpc_timers_log_add(tagstr, BEGIN, important, file, line);
}
-void grpc_timer_end(int tag, const char *tagstr, int important, const char *file,
+void grpc_timer_end(const char *tagstr, int important, const char *file,
int line) {
- if (tag < GRPC_PTAG_IGNORE_THRESHOLD) {
- grpc_timers_log_add(tag, tagstr, END, important, file, line);
- }
+ grpc_timers_log_add(tagstr, END, important, file, line);
}
/* Basic profiler specific API functions. */
diff --git a/src/core/profiling/timers.h b/src/core/profiling/timers.h
index 8305dac..94251fb 100644
--- a/src/core/profiling/timers.h
+++ b/src/core/profiling/timers.h
@@ -41,83 +41,25 @@
void grpc_timers_global_init(void);
void grpc_timers_global_destroy(void);
-void grpc_timer_add_mark(int tag, const char *tagstr, int important,
- const char *file, int line);
-void grpc_timer_begin(int tag, const char *tagstr, int important, const char *file,
+void grpc_timer_add_mark(const char *tagstr, int important, const char *file,
+ int line);
+void grpc_timer_begin(const char *tagstr, int important, const char *file,
int line);
-void grpc_timer_end(int tag, const char *tagstr, int important, const char *file,
+void grpc_timer_end(const char *tagstr, int important, 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_RECVMSG = 202,
- GRPC_PTAG_POLL = 203,
- GRPC_PTAG_TCP_CB_WRITE = 204 + GRPC_PTAG_IGNORE_THRESHOLD,
- 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,
- GRPC_PTAG_CLIENT_UNARY_CALL = 302,
- GRPC_PTAG_SERVER_CALL = 303,
- GRPC_PTAG_SERVER_CALLBACK = 304,
-
- /* Transports */
- GRPC_PTAG_HTTP2_RECV_DATA = 400,
- 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
- * zero'd bits for OR-ing. */
- GRPC_PTAG_OTHER_BASE = 1024
-};
-
#if !(defined(GRPC_STAP_PROFILER) + defined(GRPC_BASIC_PROFILER))
/* No profiling. No-op all the things. */
#define GRPC_TIMER_MARK(tag, important) \
- do { \
+ do { \
} while (0)
#define GRPC_TIMER_BEGIN(tag, important) \
- do { \
+ do { \
} while (0)
#define GRPC_TIMER_END(tag, important) \
- do { \
+ do { \
} while (0)
#else /* at least one profiler requested... */
@@ -127,22 +69,14 @@
#endif
/* Generic profiling interface. */
-#define GRPC_TIMER_MARK(tag, important) \
- if (tag < GRPC_PTAG_IGNORE_THRESHOLD) { \
- grpc_timer_add_mark(tag, #tag, important, __FILE__, \
- __LINE__); \
- }
+#define GRPC_TIMER_MARK(tag, important) \
+ grpc_timer_add_mark(tag, important, __FILE__, __LINE__);
-#define GRPC_TIMER_BEGIN(tag, important) \
- if (tag < GRPC_PTAG_IGNORE_THRESHOLD) { \
- grpc_timer_begin(tag, #tag, important, __FILE__, \
- __LINE__); \
- }
+#define GRPC_TIMER_BEGIN(tag, important) \
+ grpc_timer_begin(tag, important, __FILE__, __LINE__);
-#define GRPC_TIMER_END(tag, important) \
- if (tag < GRPC_PTAG_IGNORE_THRESHOLD) { \
- grpc_timer_end(tag, #tag, important, __FILE__, __LINE__); \
- }
+#define GRPC_TIMER_END(tag, important) \
+ grpc_timer_end(tag, important, __FILE__, __LINE__);
#ifdef GRPC_STAP_PROFILER
/* Empty placeholder for now. */
@@ -156,6 +90,22 @@
#ifdef __cplusplus
}
+
+namespace grpc {
+class ProfileScope {
+ public:
+ ProfileScope(const char *desc, bool important) : desc_(desc) {
+ GRPC_TIMER_BEGIN(desc_, important ? 1 : 0);
+ }
+ ~ProfileScope() { GRPC_TIMER_END(desc_, 0); }
+
+ private:
+ const char *const desc_;
+};
+}
+
+#define GRPC_TIMER_SCOPE(tag, important) \
+ ProfileScope _profile_scope_##__LINE__((tag), (important))
#endif
#endif /* GRPC_CORE_PROFILING_TIMERS_H */
diff --git a/src/core/support/alloc.c b/src/core/support/alloc.c
index 5e17daa..beb0e78 100644
--- a/src/core/support/alloc.c
+++ b/src/core/support/alloc.c
@@ -39,28 +39,28 @@
void *gpr_malloc(size_t size) {
void *p;
- GRPC_TIMER_BEGIN(GRPC_PTAG_MALLOC, 0);
+ GRPC_TIMER_BEGIN("gpr_malloc", 0);
p = malloc(size);
if (!p) {
abort();
}
- GRPC_TIMER_END(GRPC_PTAG_MALLOC, 0);
+ GRPC_TIMER_END("gpr_malloc", 0);
return p;
}
-void gpr_free(void *p) {
- GRPC_TIMER_BEGIN(GRPC_PTAG_FREE, 0);
- free(p);
- GRPC_TIMER_END(GRPC_PTAG_FREE, 0);
+void gpr_free(void *p) {
+ GRPC_TIMER_BEGIN("gpr_free", 0);
+ free(p);
+ GRPC_TIMER_END("gpr_free", 0);
}
void *gpr_realloc(void *p, size_t size) {
- GRPC_TIMER_BEGIN(GRPC_PTAG_REALLOC, 0);
+ GRPC_TIMER_BEGIN("gpr_realloc", 0);
p = realloc(p, size);
if (!p) {
abort();
}
- GRPC_TIMER_END(GRPC_PTAG_REALLOC, 0);
+ GRPC_TIMER_END("gpr_realloc", 0);
return p;
}
diff --git a/src/core/support/sync_posix.c b/src/core/support/sync_posix.c
index 25a580c..f356bec 100644
--- a/src/core/support/sync_posix.c
+++ b/src/core/support/sync_posix.c
@@ -46,16 +46,16 @@
void gpr_mu_destroy(gpr_mu* mu) { GPR_ASSERT(pthread_mutex_destroy(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_lock(gpr_mu* mu) {
+ GRPC_TIMER_BEGIN("gpr_mu_lock", 0);
+ GPR_ASSERT(pthread_mutex_lock(mu) == 0);
+ GRPC_TIMER_END("gpr_mu_lock", 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);
+void gpr_mu_unlock(gpr_mu* mu) {
+ GRPC_TIMER_BEGIN("gpr_mu_unlock", 0);
+ GPR_ASSERT(pthread_mutex_unlock(mu) == 0);
+ GRPC_TIMER_END("gpr_mu_unlock", 0);
}
int gpr_mu_trylock(gpr_mu* mu) {
diff --git a/src/core/surface/call.c b/src/core/surface/call.c
index 9e21829..73c5260 100644
--- a/src/core/surface/call.c
+++ b/src/core/surface/call.c
@@ -306,8 +306,9 @@
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;
+ GRPC_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 @@
set_deadline_alarm(&exec_ctx, call, send_deadline);
}
grpc_exec_ctx_finish(&exec_ctx);
+ GRPC_TIMER_END("grpc_call_create", 0);
return call;
}
@@ -462,6 +464,7 @@
static void destroy_call(grpc_exec_ctx *exec_ctx, grpc_call *call) {
size_t i;
grpc_call *c = call;
+ GRPC_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);
@@ -494,6 +497,7 @@
GRPC_CQ_INTERNAL_UNREF(c->cq, "bind");
}
gpr_free(c);
+ GRPC_TIMER_END("destroy_call", 0);
}
#ifdef GRPC_CALL_REF_COUNT_DEBUG
@@ -613,7 +617,7 @@
const size_t MAX_RECV_PEEK_AHEAD = 65536;
size_t buffered_bytes;
- GRPC_TIMER_BEGIN(GRPC_PTAG_CALL_UNLOCK, 0);
+ GRPC_TIMER_BEGIN("unlock", 0);
memset(&op, 0, sizeof(op));
@@ -686,7 +690,7 @@
GRPC_CALL_INTERNAL_UNREF(exec_ctx, call, "completing");
}
- GRPC_TIMER_END(GRPC_PTAG_CALL_UNLOCK, 0);
+ GRPC_TIMER_END("unlock", 0);
}
static void get_final_status(grpc_call *call, grpc_ioreq_data out) {
@@ -836,7 +840,7 @@
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);
+ GRPC_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);
@@ -860,10 +864,11 @@
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);
+ GRPC_TIMER_END("call_on_done_send", 0);
}
static void finish_message(grpc_call *call) {
+ GRPC_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;
@@ -883,6 +888,7 @@
gpr_slice_buffer_reset_and_unref(&call->incoming_message);
GPR_ASSERT(call->incoming_message.count == 0);
call->reading_message = 0;
+ GRPC_TIMER_END("finish_message", 0);
}
static int begin_message(grpc_call *call, grpc_begin_message msg) {
@@ -972,7 +978,7 @@
grpc_call *child_call;
grpc_call *next_child_call;
size_t i;
- GRPC_TIMER_BEGIN(GRPC_PTAG_CALL_ON_DONE_RECV, 0);
+ GRPC_TIMER_BEGIN("call_on_done_recv", 0);
lock(call);
call->receiving = 0;
if (success) {
@@ -982,13 +988,19 @@
case GRPC_NO_OP:
break;
case GRPC_OP_METADATA:
+ GRPC_TIMER_BEGIN("recv_metadata", 0);
recv_metadata(exec_ctx, call, &op->data.metadata);
+ GRPC_TIMER_END("recv_metadata", 0);
break;
case GRPC_OP_BEGIN_MESSAGE:
+ GRPC_TIMER_BEGIN("begin_message", 0);
success = begin_message(call, op->data.begin_message);
+ GRPC_TIMER_END("begin_message", 0);
break;
case GRPC_OP_SLICE:
+ GRPC_TIMER_BEGIN("add_slice_to_message", 0);
success = add_slice_to_message(call, op->data.slice);
+ GRPC_TIMER_END("add_slice_to_message", 0);
break;
}
}
@@ -1034,7 +1046,7 @@
unlock(exec_ctx, call);
GRPC_CALL_INTERNAL_UNREF(exec_ctx, call, "receiving");
- GRPC_TIMER_END(GRPC_PTAG_CALL_ON_DONE_RECV, 0);
+ GRPC_TIMER_END("call_on_done_recv", 0);
}
static int prepare_application_metadata(grpc_call *call, size_t count,
@@ -1512,16 +1524,25 @@
grpc_mdelem *mdel = l->md;
grpc_mdstr *key = mdel->key;
if (key == grpc_channel_get_status_string(call->channel)) {
+ GRPC_TIMER_BEGIN("status", 0);
set_status_code(call, STATUS_FROM_WIRE, decode_status(mdel));
+ GRPC_TIMER_END("status", 0);
} else if (key == grpc_channel_get_message_string(call->channel)) {
+ GRPC_TIMER_BEGIN("status-details", 0);
set_status_details(call, STATUS_FROM_WIRE, GRPC_MDSTR_REF(mdel->value));
+ GRPC_TIMER_END("status-details", 0);
} else if (key ==
grpc_channel_get_compression_algorithm_string(call->channel)) {
+ GRPC_TIMER_BEGIN("compression_algorithm", 0);
set_compression_algorithm(call, decode_compression(mdel));
+ GRPC_TIMER_END("compression_algorithm", 0);
} else if (key == grpc_channel_get_encodings_accepted_by_peer_string(
call->channel)) {
+ GRPC_TIMER_BEGIN("encodings_accepted_by_peer", 0);
set_encodings_accepted_by_peer(call, mdel->value->slice);
+ GRPC_TIMER_END("encodings_accepted_by_peer", 0);
} else {
+ GRPC_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);
@@ -1542,12 +1563,15 @@
}
call->owned_metadata[call->owned_metadata_count++] = mdel;
l->md = NULL;
+ GRPC_TIMER_END("report_up", 0);
}
}
if (gpr_time_cmp(md->deadline, gpr_inf_future(md->deadline.clock_type)) !=
0 &&
!call->is_client) {
+ GRPC_TIMER_BEGIN("set_deadline_alarm", 0);
set_deadline_alarm(exec_ctx, call, md->deadline);
+ GRPC_TIMER_END("set_deadline_alarm", 0);
}
if (!is_trailing) {
call->read_state = READ_STATE_GOT_INITIAL_METADATA;
@@ -1610,7 +1634,7 @@
grpc_call_error error;
grpc_exec_ctx exec_ctx = GRPC_EXEC_CTX_INIT;
- GRPC_TIMER_BEGIN(GRPC_PTAG_CALL_START_BATCH, 0);
+ GRPC_TIMER_BEGIN("grpc_call_start_batch", 0);
GRPC_API_TRACE(
"grpc_call_start_batch(call=%p, ops=%p, nops=%lu, tag=%p, reserved=%p)",
@@ -1849,7 +1873,7 @@
finish_func, tag);
done:
grpc_exec_ctx_finish(&exec_ctx);
- GRPC_TIMER_END(GRPC_PTAG_CALL_START_BATCH, 0);
+ GRPC_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 5ca8f83..695dfbd 100644
--- a/src/core/surface/completion_queue.c
+++ b/src/core/surface/completion_queue.c
@@ -185,7 +185,7 @@
gpr_timespec now;
grpc_exec_ctx exec_ctx = GRPC_EXEC_CTX_INIT;
- GRPC_TIMER_BEGIN(GRPC_PTAG_CQ_NEXT, 0);
+ GRPC_TIMER_BEGIN("grpc_completion_queue_next", 0);
GRPC_API_TRACE(
"grpc_completion_queue_next("
@@ -234,7 +234,7 @@
GRPC_CQ_INTERNAL_UNREF(cc, "next");
grpc_exec_ctx_finish(&exec_ctx);
- GRPC_TIMER_END(GRPC_PTAG_CQ_NEXT, 0);
+ GRPC_TIMER_END("grpc_completion_queue_next", 0);
return ret;
}
@@ -274,7 +274,7 @@
int first_loop = 1;
grpc_exec_ctx exec_ctx = GRPC_EXEC_CTX_INIT;
- GRPC_TIMER_BEGIN(GRPC_PTAG_CQ_PLUCK, 0);
+ GRPC_TIMER_BEGIN("grpc_completion_queue_pluck", 0);
GRPC_API_TRACE(
"grpc_completion_queue_pluck("
@@ -342,7 +342,7 @@
GRPC_CQ_INTERNAL_UNREF(cc, "pluck");
grpc_exec_ctx_finish(&exec_ctx);
- GRPC_TIMER_END(GRPC_PTAG_CQ_PLUCK, 0);
+ GRPC_TIMER_END("grpc_completion_queue_pluck", 0);
return ret;
}
diff --git a/src/core/transport/chttp2/parsing.c b/src/core/transport/chttp2/parsing.c
index f7a0a10..e71d4fc 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 @@
grpc_chttp2_stream_global *stream_global;
grpc_chttp2_stream_parsing *stream_parsing;
+ GRPC_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 @@
stream_parsing->incoming_window = stream_global->incoming_window;
}
}
+
+ GRPC_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 d1c9da6..4abe00b 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 @@
static void finalize_outbuf(grpc_chttp2_transport_writing *transport_writing) {
grpc_chttp2_stream_writing *stream_writing;
+ GRPC_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 @@
}
grpc_chttp2_list_add_written_stream(transport_writing, stream_writing);
}
+
+ GRPC_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 0a1b3a8..d39816b 100644
--- a/src/core/transport/chttp2_transport.c
+++ b/src/core/transport/chttp2_transport.c
@@ -510,6 +510,7 @@
static void lock(grpc_chttp2_transport *t) { gpr_mu_lock(&t->mu); }
static void unlock(grpc_exec_ctx *exec_ctx, grpc_chttp2_transport *t) {
+ GRPC_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 @@
}
gpr_mu_unlock(&t->mu);
+ GRPC_TIMER_END("unlock", 0);
}
/*
@@ -546,7 +548,7 @@
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);
+ GRPC_TIMER_BEGIN("grpc_chttp2_terminate_writing", 0);
lock(t);
@@ -569,16 +571,16 @@
unlock(exec_ctx, t);
UNREF_TRANSPORT(exec_ctx, t, "writing");
-
- GRPC_TIMER_END(GRPC_PTAG_HTTP2_TERMINATE_WRITING, 0);
+
+ GRPC_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;
- GRPC_TIMER_BEGIN(GRPC_PTAG_HTTP2_WRITING_ACTION, 0);
+ GRPC_TIMER_BEGIN("writing_action", 0);
grpc_chttp2_perform_writes(exec_ctx, &t->writing, t->ep);
- GRPC_TIMER_END(GRPC_PTAG_HTTP2_WRITING_ACTION, 0);
+ GRPC_TIMER_END("writing_action", 0);
}
void grpc_chttp2_add_incoming_goaway(
@@ -648,6 +650,7 @@
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) {
+ GRPC_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);
}
@@ -719,6 +722,7 @@
}
grpc_exec_ctx_enqueue(exec_ctx, op->on_consumed, 1);
+ GRPC_TIMER_END("perform_stream_op_locked", 0);
}
static void perform_stream_op(grpc_exec_ctx *exec_ctx, grpc_transport *gt,
@@ -1109,7 +1113,7 @@
int keep_reading = 0;
grpc_chttp2_transport *t = tp;
- GRPC_TIMER_BEGIN(GRPC_PTAG_HTTP2_RECV_DATA, 0);
+ GRPC_TIMER_BEGIN("recv_data", 0);
lock(t);
i = 0;
@@ -1121,11 +1125,13 @@
&t->parsing_stream_map);
grpc_chttp2_prepare_to_read(&t->global, &t->parsing);
gpr_mu_unlock(&t->mu);
+ GRPC_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++)
;
+ GRPC_TIMER_END("recv_data.parse", 0);
gpr_mu_lock(&t->mu);
if (i != t->read_buffer.count) {
drop_connection(exec_ctx, t);
@@ -1163,7 +1169,7 @@
UNREF_TRANSPORT(exec_ctx, t, "recv_data");
}
- GRPC_TIMER_END(GRPC_PTAG_HTTP2_RECV_DATA, 0);
+ GRPC_TIMER_END("recv_data", 0);
}
/*
diff --git a/src/core/transport/stream_op.c b/src/core/transport/stream_op.c
index 1cb2bd7..5c3c90b 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 @@
grpc_linked_mdelem *l;
grpc_linked_mdelem *next;
+ GRPC_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 @@
}
assert_valid_list(&batch->list);
assert_valid_list(&batch->garbage);
+
+ GRPC_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 a40268a..99e28ab 100644
--- a/src/core/tsi/fake_transport_security.c
+++ b/src/core/tsi/fake_transport_security.c
@@ -121,7 +121,7 @@
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) {
diff --git a/src/cpp/proto/proto_utils.cc b/src/cpp/proto/proto_utils.cc
index 4131fbe..a7b6fd2 100644
--- a/src/cpp/proto/proto_utils.cc
+++ b/src/cpp/proto/proto_utils.cc
@@ -42,6 +42,8 @@
#include <grpc/support/port_platform.h>
#include <grpc++/support/config.h>
+#include "src/core/profiling/timers.h"
+
const int kMaxBufferLength = 8192;
class GrpcBufferWriter GRPC_FINAL
@@ -158,6 +160,7 @@
Status SerializeProto(const grpc::protobuf::Message& msg,
grpc_byte_buffer** bp) {
+ GRPC_TIMER_SCOPE("SerializeProto", 0);
int byte_size = msg.ByteSize();
if (byte_size <= kMaxBufferLength) {
gpr_slice slice = gpr_slice_malloc(byte_size);
@@ -176,6 +179,7 @@
Status DeserializeProto(grpc_byte_buffer* buffer, grpc::protobuf::Message* msg,
int max_message_size) {
+ GRPC_TIMER_SCOPE("DeserializeProto", 0);
if (!buffer) {
return Status(StatusCode::INTERNAL, "No payload");
}
diff --git a/src/cpp/server/server.cc b/src/cpp/server/server.cc
index f271973..2cd1905 100644
--- a/src/cpp/server/server.cc
+++ b/src/cpp/server/server.cc
@@ -541,7 +541,7 @@
void Server::RunRpc() {
// Wait for one more incoming rpc.
bool ok;
- GRPC_TIMER_BEGIN(GRPC_PTAG_SERVER_CALL, 0);
+ GRPC_TIMER_SCOPE("Server::RunRpc", 0);
auto* mrd = SyncRequest::Wait(&cq_, &ok);
if (mrd) {
ScheduleCallback();
@@ -557,12 +557,10 @@
mrd->TeardownRequest();
}
}
- GRPC_TIMER_BEGIN(GRPC_PTAG_SERVER_CALLBACK, 0);
+ GRPC_TIMER_SCOPE("cd.Run()", 0);
cd.Run();
- GRPC_TIMER_END(GRPC_PTAG_SERVER_CALLBACK, 0);
}
}
- GRPC_TIMER_END(GRPC_PTAG_SERVER_CALL, 0);
{
grpc::unique_lock<grpc::mutex> lock(mu_);
diff --git a/test/cpp/qps/client_sync.cc b/test/cpp/qps/client_sync.cc
index 0523371..6adf92a 100644
--- a/test/cpp/qps/client_sync.cc
+++ b/test/cpp/qps/client_sync.cc
@@ -101,11 +101,10 @@
WaitToIssue(thread_idx);
auto* stub = channels_[thread_idx % channels_.size()].get_stub();
double start = Timer::Now();
+ GRPC_TIMER_SCOPE("SynchronousUnaryClient::ThreadFunc", 0);
grpc::ClientContext context;
- GRPC_TIMER_BEGIN(GRPC_PTAG_CLIENT_UNARY_CALL, 0);
grpc::Status s =
stub->UnaryCall(&context, request_, &responses_[thread_idx]);
- GRPC_TIMER_END(GRPC_PTAG_CLIENT_UNARY_CALL, 0);
histogram->Add((Timer::Now() - start) * 1e9);
return s.ok();
}
@@ -139,15 +138,13 @@
bool ThreadFunc(Histogram* histogram, size_t thread_idx) GRPC_OVERRIDE {
WaitToIssue(thread_idx);
+ GRPC_TIMER_SCOPE("SynchronousStreamingClient::ThreadFunc", 0);
double start = Timer::Now();
- GRPC_TIMER_BEGIN(GRPC_PTAG_CLIENT_UNARY_CALL, 0);
if (stream_[thread_idx]->Write(request_) &&
stream_[thread_idx]->Read(&responses_[thread_idx])) {
- GRPC_TIMER_END(GRPC_PTAG_CLIENT_UNARY_CALL, 0);
histogram->Add((Timer::Now() - start) * 1e9);
return true;
}
- GRPC_TIMER_END(GRPC_PTAG_CLIENT_UNARY_CALL, 0);
return false;
}
diff --git a/tools/profiling/latency_profile/profile_analyzer.py b/tools/profiling/latency_profile/profile_analyzer.py
index 175b185..6de2fe7 100755
--- a/tools/profiling/latency_profile/profile_analyzer.py
+++ b/tools/profiling/latency_profile/profile_analyzer.py
@@ -29,6 +29,8 @@
self.start_time = line['t']
self.end_time = None
self.important = line['imp']
+ self.filename = line['file']
+ self.fileline = line['line']
self.times = {}
@@ -48,7 +50,7 @@
def finish(self, line):
- assert line['tag'] == self.top_line.tag
+ assert line['tag'] == self.top_line.tag, 'expected %s, got %s' % (self.top_line.tag, line['tag'])
final_time_stamp = line['t']
assert self.top_line.end_time is None
self.top_line.end_time = final_time_stamp
@@ -187,6 +189,7 @@
FORMAT = [
('TAG', lambda line: '..'*line.indent + tidy_tag(line.tag)),
+ ('LOC', lambda line: '%s:%d' % (line.filename[line.filename.rfind('/')+1:], line.fileline)),
('FROM_STACK_START', time_format(TIME_FROM_STACK_START)),
('SELF', time_format(SELF_TIME)),
('TO_STACK_END', time_format(TIME_TO_STACK_END)),