From 74c0224e672468ff1a55f150513ebd70045dcc68 Mon Sep 17 00:00:00 2001 From: Vijay Pai Date: Wed, 15 Apr 2015 00:44:35 -0700 Subject: [PATCH 1/7] Change int sequence number to a void* for more generality --- src/core/profiling/timers.c | 6 +++--- src/core/profiling/timers.h | 9 +++++---- 2 files changed, 8 insertions(+), 7 deletions(-) diff --git a/src/core/profiling/timers.c b/src/core/profiling/timers.c index 478397d1bfc..e8743aa990f 100644 --- a/src/core/profiling/timers.c +++ b/src/core/profiling/timers.c @@ -45,7 +45,7 @@ typedef struct grpc_timer_entry { grpc_precise_clock tm; const char* tag; - int seq; + void* seq; const char* file; int line; } grpc_timer_entry; @@ -85,7 +85,7 @@ static void log_report_locked(grpc_timers_log* log) { grpc_timer_entry* entry = &(log->log[i]); fprintf(fp, "GRPC_LAT_PROF "); grpc_precise_clock_print(&entry->tm, fp); - fprintf(fp, " %s#%d,%s:%d\n", entry->tag, entry->seq, entry->file, + fprintf(fp, " %s %p %s %d\n", entry->tag, entry->seq, entry->file, entry->line); } @@ -104,7 +104,7 @@ void grpc_timers_log_destroy(grpc_timers_log* log) { gpr_free(log); } -void grpc_timers_log_add(grpc_timers_log* log, const char* tag, int seq, +void grpc_timers_log_add(grpc_timers_log* log, const char* tag, void* seq, const char* file, int line) { grpc_timer_entry* entry; diff --git a/src/core/profiling/timers.h b/src/core/profiling/timers.h index ef4cad112ae..3cb6feaa855 100644 --- a/src/core/profiling/timers.h +++ b/src/core/profiling/timers.h @@ -44,15 +44,16 @@ extern "C" { typedef struct grpc_timers_log grpc_timers_log; -grpc_timers_log *grpc_timers_log_create(int capacity_limit, FILE *dump); -void grpc_timers_log_add(grpc_timers_log *, const char *tag, int seq, - const char *file, int line); +grpc_timers_log* grpc_timers_log_create(int capacity_limit, FILE* dump); +void grpc_timers_log_add(grpc_timers_log*, const char* tag, void* seq, + const char* file, int line); void grpc_timers_log_destroy(grpc_timers_log *); extern grpc_timers_log *grpc_timers_log_global; #define GRPC_TIMER_MARK(x, s) \ - grpc_timers_log_add(grpc_timers_log_global, #x, s, __FILE__, __LINE__) + grpc_timers_log_add(grpc_timers_log_global, #x, ((void *)(gpr_intptr)(s)), \ + __FILE__, __LINE__) #else /* !GRPC_LATENCY_PROFILER */ #define GRPC_TIMER_MARK(x, s) \ From 0fb96e8b5e32a8f8c7bc364ff8bc37df61a6e315 Mon Sep 17 00:00:00 2001 From: Vijay Pai Date: Wed, 15 Apr 2015 00:47:05 -0700 Subject: [PATCH 2/7] Rename seq to id so that it's clear it can be any generic ID --- src/core/profiling/timers.c | 8 ++++---- src/core/profiling/timers.h | 2 +- 2 files changed, 5 insertions(+), 5 deletions(-) diff --git a/src/core/profiling/timers.c b/src/core/profiling/timers.c index e8743aa990f..7cc79bd22bc 100644 --- a/src/core/profiling/timers.c +++ b/src/core/profiling/timers.c @@ -45,7 +45,7 @@ typedef struct grpc_timer_entry { grpc_precise_clock tm; const char* tag; - void* seq; + void* id; const char* file; int line; } grpc_timer_entry; @@ -85,7 +85,7 @@ static void log_report_locked(grpc_timers_log* log) { grpc_timer_entry* entry = &(log->log[i]); fprintf(fp, "GRPC_LAT_PROF "); grpc_precise_clock_print(&entry->tm, fp); - fprintf(fp, " %s %p %s %d\n", entry->tag, entry->seq, entry->file, + fprintf(fp, " %s %p %s %d\n", entry->tag, entry->id, entry->file, entry->line); } @@ -104,7 +104,7 @@ void grpc_timers_log_destroy(grpc_timers_log* log) { gpr_free(log); } -void grpc_timers_log_add(grpc_timers_log* log, const char* tag, void* seq, +void grpc_timers_log_add(grpc_timers_log* log, const char* tag, void* id, const char* file, int line) { grpc_timer_entry* entry; @@ -118,7 +118,7 @@ void grpc_timers_log_add(grpc_timers_log* log, const char* tag, void* seq, grpc_precise_clock_now(&entry->tm); entry->tag = tag; - entry->seq = seq; + entry->id = id; entry->file = file; entry->line = line; diff --git a/src/core/profiling/timers.h b/src/core/profiling/timers.h index 3cb6feaa855..1a6b9ffac90 100644 --- a/src/core/profiling/timers.h +++ b/src/core/profiling/timers.h @@ -45,7 +45,7 @@ extern "C" { typedef struct grpc_timers_log grpc_timers_log; grpc_timers_log* grpc_timers_log_create(int capacity_limit, FILE* dump); -void grpc_timers_log_add(grpc_timers_log*, const char* tag, void* seq, +void grpc_timers_log_add(grpc_timers_log*, const char* tag, void* id, const char* file, int line); void grpc_timers_log_destroy(grpc_timers_log *); From 9ffbd0ca4dde4c93b81e3178186653ba2cf475d9 Mon Sep 17 00:00:00 2001 From: Vijay Pai Date: Wed, 15 Apr 2015 01:02:50 -0700 Subject: [PATCH 3/7] Mark proto ser/deser on server side --- src/cpp/server/async_server_context.cc | 4 ++++ src/cpp/server/server.cc | 5 +++++ 2 files changed, 9 insertions(+) diff --git a/src/cpp/server/async_server_context.cc b/src/cpp/server/async_server_context.cc index 628822a3387..0162ddc97db 100644 --- a/src/cpp/server/async_server_context.cc +++ b/src/cpp/server/async_server_context.cc @@ -68,9 +68,11 @@ bool AsyncServerContext::StartRead(grpc::protobuf::Message* request) { bool AsyncServerContext::StartWrite(const grpc::protobuf::Message& response, int flags) { grpc_byte_buffer* buffer = nullptr; + GRPC_TIMER_MARK(SER_PROTO_BEGIN, call_->call()); if (!SerializeProto(response, &buffer)) { return false; } + GRPC_TIMER_MARK(SER_PROTO_END, call_->call()); grpc_call_error err = grpc_call_start_write_old(call_, buffer, this, flags); grpc_byte_buffer_destroy(buffer); return err == GRPC_CALL_OK; @@ -87,7 +89,9 @@ bool AsyncServerContext::StartWriteStatus(const Status& status) { bool AsyncServerContext::ParseRead(grpc_byte_buffer* read_buffer) { GPR_ASSERT(request_); + GRPC_TIMER_MARK(DESER_PROTO_BEGIN, call_->call()); bool success = DeserializeProto(read_buffer, request_); + GRPC_TIMER_MARK(DESER_PROTO_BEGIN, call_->call()); request_ = nullptr; return success; } diff --git a/src/cpp/server/server.cc b/src/cpp/server/server.cc index 046133c5eb1..b3cd1fdd74b 100644 --- a/src/cpp/server/server.cc +++ b/src/cpp/server/server.cc @@ -46,6 +46,7 @@ #include #include +#include "src/core/profiling/timers.h" #include "src/cpp/proto/proto_utils.h" #include "src/cpp/util/time.h" @@ -123,10 +124,12 @@ class Server::SyncRequest GRPC_FINAL : public CompletionQueueTag { std::unique_ptr req; std::unique_ptr res; if (has_request_payload_) { + GRPC_TIMER_MARK(DESER_PROTO_BEGIN, call_.call()); req.reset(method_->AllocateRequestProto()); if (!DeserializeProto(request_payload_, req.get())) { abort(); // for now } + GRPC_TIMER_MARK(DESER_PROTO_END, call_.call()); } if (has_response_payload_) { res.reset(method_->AllocateResponseProto()); @@ -340,7 +343,9 @@ class Server::AsyncRequest GRPC_FINAL : public CompletionQueueTag { bool orig_status = *status; if (*status && request_) { if (payload_) { + GRPC_TIMER_MARK(DESER_PROTO_BEGIN, call_); *status = DeserializeProto(payload_, request_); + GRPC_TIMER_MARK(DESER_PROTO_END, call_); } else { *status = false; } From fad38ba4302aa3fa0d3b098e1fad8e09fc494b27 Mon Sep 17 00:00:00 2001 From: Vijay Pai Date: Wed, 15 Apr 2015 01:06:58 -0700 Subject: [PATCH 4/7] Add client-side marks for proto processing. Need to go in and fill in tag later --- src/cpp/common/call.cc | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/src/cpp/common/call.cc b/src/cpp/common/call.cc index e75e77e0b53..9878133331d 100644 --- a/src/cpp/common/call.cc +++ b/src/cpp/common/call.cc @@ -38,6 +38,7 @@ #include #include +#include "src/core/profiling/timers.h" #include "src/cpp/proto/proto_utils.h" namespace grpc { @@ -231,11 +232,13 @@ void CallOpBuffer::FillOps(grpc_op* ops, size_t* nops) { } if (send_message_ || send_message_buffer_) { if (send_message_) { + GRPC_TIMER_MARK(SER_PROTO_BEGIN, 0); bool success = SerializeProto(*send_message_, &send_buf_); if (!success) { abort(); // TODO handle parse failure } + GRPC_TIMER_MARK(SER_PROTO_END, 0); } else { send_buf_ = send_message_buffer_->buffer(); } @@ -307,8 +310,10 @@ bool CallOpBuffer::FinalizeResult(void** tag, bool* status) { if (recv_buf_) { got_message = *status; if (recv_message_) { + GRPC_TIMER_MARK(DESER_PROTO_BEGIN, 0); *status = *status && DeserializeProto(recv_buf_, recv_message_); grpc_byte_buffer_destroy(recv_buf_); + GRPC_TIMER_MARK(DESER_PROTO_END, 0); } else { recv_message_buffer_->set_buffer(recv_buf_); } From 0163460bd602ad77f15caa7a9efff23491efa934 Mon Sep 17 00:00:00 2001 From: Vijay Pai Date: Wed, 15 Apr 2015 02:09:52 -0700 Subject: [PATCH 5/7] Mark creation of call, performing ops on channel --- src/cpp/client/channel.cc | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/src/cpp/client/channel.cc b/src/cpp/client/channel.cc index 5380d3a232c..72123abbc8d 100644 --- a/src/cpp/client/channel.cc +++ b/src/cpp/client/channel.cc @@ -41,6 +41,7 @@ #include #include +#include "src/core/profiling/timers.h" #include "src/cpp/proto/proto_utils.h" #include #include @@ -65,6 +66,7 @@ Call Channel::CreateCall(const RpcMethod& method, ClientContext* context, ? target_.c_str() : context->authority().c_str(), context->RawDeadline()); + GRPC_TIMER_MARK(CALL_CREATED,c_call); context->set_call(c_call); return Call(c_call, this, cq); } @@ -73,9 +75,11 @@ void Channel::PerformOpsOnCall(CallOpBuffer* buf, Call* call) { static const size_t MAX_OPS = 8; size_t nops = MAX_OPS; grpc_op ops[MAX_OPS]; + GRPC_TIMER_MARK(PERFORM_OPS_BEGIN, call->call()); buf->FillOps(ops, &nops); GPR_ASSERT(GRPC_CALL_OK == grpc_call_start_batch(call->call(), ops, nops, buf)); + GRPC_TIMER_MARK(PERFORM_OPS_END, call->call()); } } // namespace grpc From 68e4515c8d6ec2796a869e31de7a81071d550662 Mon Sep 17 00:00:00 2001 From: Vijay Pai Date: Wed, 15 Apr 2015 02:10:17 -0700 Subject: [PATCH 6/7] Mark activation for read, write, and time spent in system calls --- src/core/iomgr/tcp_posix.c | 11 +++++++++++ 1 file changed, 11 insertions(+) diff --git a/src/core/iomgr/tcp_posix.c b/src/core/iomgr/tcp_posix.c index 597a2a62d37..20df6d1b016 100644 --- a/src/core/iomgr/tcp_posix.c +++ b/src/core/iomgr/tcp_posix.c @@ -46,6 +46,7 @@ #include "src/core/support/string.h" #include "src/core/debug/trace.h" +#include "src/core/profiling/timers.h" #include #include #include @@ -326,6 +327,7 @@ static void grpc_tcp_handle_read(void *arg /* grpc_tcp */, int success) { gpr_slice *final_slices; size_t final_nslices; + GRPC_TIMER_MARK(HANDLE_READ_BEGIN, 0); slice_state_init(&read_state, static_read_slices, INLINE_SLICE_BUFFER_SIZE, 0); @@ -348,9 +350,11 @@ static void grpc_tcp_handle_read(void *arg /* grpc_tcp */, int success) { msg.msg_controllen = 0; msg.msg_flags = 0; + GRPC_TIMER_MARK(RECVMSG_BEGIN, 0); do { read_bytes = recvmsg(tcp->fd, &msg, 0); } while (read_bytes < 0 && errno == EINTR); + GRPC_TIMER_MARK(RECVMSG_END, 0); if (read_bytes < allocated_bytes) { /* TODO(klempner): Consider a second read first, in hopes of getting a @@ -402,6 +406,7 @@ static void grpc_tcp_handle_read(void *arg /* grpc_tcp */, int success) { ++iov_size; } } + GRPC_TIMER_MARK(HANDLE_READ_BEGIN, 0); } static void grpc_tcp_notify_on_read(grpc_endpoint *ep, grpc_endpoint_read_cb cb, @@ -433,10 +438,12 @@ static grpc_endpoint_write_status grpc_tcp_flush(grpc_tcp *tcp) { msg.msg_controllen = 0; msg.msg_flags = 0; + GRPC_TIMER_MARK(SENDMSG_BEGIN, 0); do { /* TODO(klempner): Cork if this is a partial write */ sent_length = sendmsg(tcp->fd, &msg, 0); } while (sent_length < 0 && errno == EINTR); + GRPC_TIMER_MARK(SENDMSG_END, 0); if (sent_length < 0) { if (errno == EAGAIN) { @@ -472,6 +479,7 @@ static void grpc_tcp_handle_write(void *arg /* grpc_tcp */, int success) { return; } + GRPC_TIMER_MARK(CB_WRITE_BEGIN, 0); write_status = grpc_tcp_flush(tcp); if (write_status == GRPC_ENDPOINT_WRITE_PENDING) { grpc_fd_notify_on_write(tcp->em_fd, &tcp->write_closure); @@ -487,6 +495,7 @@ static void grpc_tcp_handle_write(void *arg /* grpc_tcp */, int success) { cb(tcp->write_user_data, cb_status); grpc_tcp_unref(tcp); } + GRPC_TIMER_MARK(CB_WRITE_END, 0); } static grpc_endpoint_write_status grpc_tcp_write(grpc_endpoint *ep, @@ -509,6 +518,7 @@ static grpc_endpoint_write_status grpc_tcp_write(grpc_endpoint *ep, } } + GRPC_TIMER_MARK(WRITE_BEGIN, 0); GPR_ASSERT(tcp->write_cb == NULL); slice_state_init(&tcp->write_state, slices, nslices, nslices); @@ -522,6 +532,7 @@ static grpc_endpoint_write_status grpc_tcp_write(grpc_endpoint *ep, grpc_fd_notify_on_write(tcp->em_fd, &tcp->write_closure); } + GRPC_TIMER_MARK(WRITE_END, 0); return status; } From 7b3aba5e27955e2ded5679b2dda18c8eb4229f25 Mon Sep 17 00:00:00 2001 From: Vijay Pai Date: Wed, 15 Apr 2015 10:48:31 -0700 Subject: [PATCH 7/7] Fix some name choices --- src/core/iomgr/tcp_posix.c | 2 +- src/cpp/server/async_server_context.cc | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/src/core/iomgr/tcp_posix.c b/src/core/iomgr/tcp_posix.c index 20df6d1b016..86721e9c955 100644 --- a/src/core/iomgr/tcp_posix.c +++ b/src/core/iomgr/tcp_posix.c @@ -406,7 +406,7 @@ static void grpc_tcp_handle_read(void *arg /* grpc_tcp */, int success) { ++iov_size; } } - GRPC_TIMER_MARK(HANDLE_READ_BEGIN, 0); + GRPC_TIMER_MARK(HANDLE_READ_END, 0); } static void grpc_tcp_notify_on_read(grpc_endpoint *ep, grpc_endpoint_read_cb cb, diff --git a/src/cpp/server/async_server_context.cc b/src/cpp/server/async_server_context.cc index 0162ddc97db..e1f29452a44 100644 --- a/src/cpp/server/async_server_context.cc +++ b/src/cpp/server/async_server_context.cc @@ -91,7 +91,7 @@ bool AsyncServerContext::ParseRead(grpc_byte_buffer* read_buffer) { GPR_ASSERT(request_); GRPC_TIMER_MARK(DESER_PROTO_BEGIN, call_->call()); bool success = DeserializeProto(read_buffer, request_); - GRPC_TIMER_MARK(DESER_PROTO_BEGIN, call_->call()); + GRPC_TIMER_MARK(DESER_PROTO_END, call_->call()); request_ = nullptr; return success; }