diff --git a/src/core/lib/surface/completion_queue.c b/src/core/lib/surface/completion_queue.c index 52f2df0c6ce1ff978f57109a901db295a660d054..b0a4b1fbccae17ffc32effb29cbe2603b456d7e1 100644 --- a/src/core/lib/surface/completion_queue.c +++ b/src/core/lib/surface/completion_queue.c @@ -262,6 +262,7 @@ typedef struct cq_data { int is_server_cq; int num_pluckers; + int num_polls; plucker pluckers[GRPC_MAX_COMPLETION_QUEUE_PLUCKERS]; grpc_closure pollset_shutdown_done; @@ -425,6 +426,7 @@ grpc_completion_queue *grpc_completion_queue_create_internal( cqd->shutdown_called = 0; cqd->is_server_cq = 0; cqd->num_pluckers = 0; + cqd->num_polls = 0; gpr_atm_no_barrier_store(&cqd->things_queued_ever, 0); #ifndef NDEBUG cqd->outstanding_tag_count = 0; @@ -442,6 +444,14 @@ grpc_cq_completion_type grpc_get_cq_completion_type(grpc_completion_queue *cc) { return cc->vtable->cq_completion_type; } +int grpc_get_cq_poll_num(grpc_completion_queue *cc) { + int cur_num_polls; + gpr_mu_lock(cc->data.mu); + cur_num_polls = cc->data.num_polls; + gpr_mu_unlock(cc->data.mu); + return cur_num_polls; +} + #ifdef GRPC_CQ_REF_COUNT_DEBUG void grpc_cq_internal_ref(grpc_completion_queue *cc, const char *reason, const char *file, int line) { @@ -830,6 +840,7 @@ static grpc_event cq_next(grpc_completion_queue *cc, gpr_timespec deadline, /* The main polling work happens in grpc_pollset_work */ gpr_mu_lock(cqd->mu); + cqd->num_polls++; grpc_error *err = cc->poller_vtable->work(&exec_ctx, POLLSET_FROM_CQ(cc), NULL, now, iteration_deadline); gpr_mu_unlock(cqd->mu); @@ -1015,6 +1026,7 @@ static grpc_event cq_pluck(grpc_completion_queue *cc, void *tag, break; } + cqd->num_polls++; grpc_error *err = cc->poller_vtable->work(&exec_ctx, POLLSET_FROM_CQ(cc), &worker, now, deadline); if (err != GRPC_ERROR_NONE) { diff --git a/src/core/lib/surface/completion_queue.h b/src/core/lib/surface/completion_queue.h index f8beebf943195cf10952d967a4627593334c5d46..7963ea75e77c837ad74a74126928cd70c9ced8df 100644 --- a/src/core/lib/surface/completion_queue.h +++ b/src/core/lib/surface/completion_queue.h @@ -49,6 +49,10 @@ extern grpc_tracer_flag grpc_trace_operation_failures; extern grpc_tracer_flag grpc_trace_pending_tags; #endif +#ifdef __cplusplus +extern "C" { +#endif + typedef struct grpc_cq_completion { gpr_mpscq_node node; @@ -103,7 +107,13 @@ bool grpc_cq_can_listen(grpc_completion_queue *cc); grpc_cq_completion_type grpc_get_cq_completion_type(grpc_completion_queue *cc); +int grpc_get_cq_poll_num(grpc_completion_queue *cc); + grpc_completion_queue *grpc_completion_queue_create_internal( grpc_cq_completion_type completion_type, grpc_cq_polling_type polling_type); +#ifdef __cplusplus +} +#endif + #endif /* GRPC_CORE_LIB_SURFACE_COMPLETION_QUEUE_H */ diff --git a/src/proto/grpc/testing/control.proto b/src/proto/grpc/testing/control.proto index 02b156d0cd2591125b720602c43480d227e23157..1f4569e2780aeaaf8d8985cdeabcb2fb15c0062e 100644 --- a/src/proto/grpc/testing/control.proto +++ b/src/proto/grpc/testing/control.proto @@ -244,6 +244,10 @@ message ScenarioResultSummary // Number of requests that succeeded/failed double successful_requests_per_second = 13; double failed_requests_per_second = 14; + + // Number of polls called inside completion queue per request + double client_polls_per_request = 15; + double server_polls_per_request = 16; } // Results of a single benchmark scenario. diff --git a/src/proto/grpc/testing/stats.proto b/src/proto/grpc/testing/stats.proto index 80014161a1763226db279c8e07c2f1069c8ef4d9..e236cf159b3e6773b94e4c84d5feeaa7ae66f515 100644 --- a/src/proto/grpc/testing/stats.proto +++ b/src/proto/grpc/testing/stats.proto @@ -47,6 +47,9 @@ message ServerStats { // change in idle time of the server (data from proc/stat) uint64 idle_cpu_time = 5; + + // Number of polls called inside completion queue + uint64 cq_poll_count = 6; } // Histogram params based on grpc/support/histogram.c @@ -81,4 +84,7 @@ message ClientStats { // Number of failed requests (one row per status code seen) repeated RequestResultCount request_results = 5; + + // Number of polls called inside completion queue + uint64 cq_poll_count = 6; } diff --git a/test/cpp/microbenchmarks/fullstack_fixtures.h b/test/cpp/microbenchmarks/fullstack_fixtures.h index 98aca1c34652bcf43b143405b2f5e62e7fd52e0b..aa71c2ae3f9e5c167450b57915d382ad76d9e226 100644 --- a/test/cpp/microbenchmarks/fullstack_fixtures.h +++ b/test/cpp/microbenchmarks/fullstack_fixtures.h @@ -100,6 +100,12 @@ class FullstackFixture : public BaseFixture { } } + void AddToLabel(std::ostream& out, benchmark::State& state) { + BaseFixture::AddToLabel(out, state); + out << " polls/iter:" + << (double)grpc_get_cq_poll_num(this->cq()->cq()) / state.iterations(); + } + ServerCompletionQueue* cq() { return cq_.get(); } std::shared_ptr<Channel> channel() { return channel_; } @@ -212,6 +218,12 @@ class EndpointPairFixture : public BaseFixture { } } + void AddToLabel(std::ostream& out, benchmark::State& state) { + BaseFixture::AddToLabel(out, state); + out << " polls/iter:" + << (double)grpc_get_cq_poll_num(this->cq()->cq()) / state.iterations(); + } + ServerCompletionQueue* cq() { return cq_.get(); } std::shared_ptr<Channel> channel() { return channel_; } @@ -245,7 +257,7 @@ class InProcessCHTTP2 : public EndpointPairFixture { void AddToLabel(std::ostream& out, benchmark::State& state) { EndpointPairFixture::AddToLabel(out, state); out << " writes/iter:" - << ((double)stats_.num_writes / (double)state.iterations()); + << (double)stats_.num_writes / (double)state.iterations(); } private: diff --git a/test/cpp/qps/client.h b/test/cpp/qps/client.h index c3197eb6221c1396e41e025e6e808f8c92c570c5..5ae6b54f89da9c108e5da2a611e4b3fc438834b9 100644 --- a/test/cpp/qps/client.h +++ b/test/cpp/qps/client.h @@ -46,6 +46,7 @@ #include <grpc/support/log.h> #include <grpc/support/time.h> +#include "src/core/lib/surface/completion_queue.h" #include "src/proto/grpc/testing/payloads.pb.h" #include "src/proto/grpc/testing/services.grpc.pb.h" @@ -150,7 +151,8 @@ class Client { Client() : timer_(new UsageTimer), interarrival_timer_(), - started_requests_(false) { + started_requests_(false), + last_reset_poll_count_(0) { gpr_event_init(&start_requests_); } virtual ~Client() {} @@ -162,6 +164,8 @@ class Client { MaybeStartRequests(); + int cur_poll_count = GetPollCount(); + int poll_count = cur_poll_count - last_reset_poll_count_; if (reset) { std::vector<Histogram> to_merge(threads_.size()); std::vector<StatusHistogram> to_merge_status(threads_.size()); @@ -176,6 +180,7 @@ class Client { MergeStatusHistogram(to_merge_status[i], &statuses); } timer_result = timer->Mark(); + last_reset_poll_count_ = cur_poll_count; } else { // merge snapshots of each thread histogram for (size_t i = 0; i < threads_.size(); i++) { @@ -195,6 +200,7 @@ class Client { stats.set_time_elapsed(timer_result.wall); stats.set_time_system(timer_result.system); stats.set_time_user(timer_result.user); + stats.set_cq_poll_count(poll_count); return stats; } @@ -209,6 +215,11 @@ class Client { } } + virtual int GetPollCount() { + // For sync client. + return 0; + } + protected: bool closed_loop_; gpr_atm thread_pool_done_; @@ -351,6 +362,8 @@ class Client { gpr_event start_requests_; bool started_requests_; + int last_reset_poll_count_; + void MaybeStartRequests() { if (!started_requests_) { started_requests_ = true; diff --git a/test/cpp/qps/client_async.cc b/test/cpp/qps/client_async.cc index 82c3356f021cb06bc11720a466621b5f16797c88..6b8f736813319f3d29eba254517dae44ecc1548b 100644 --- a/test/cpp/qps/client_async.cc +++ b/test/cpp/qps/client_async.cc @@ -205,6 +205,14 @@ class AsyncClient : public ClientImpl<StubType, RequestType> { } } + int GetPollCount() override { + int count = 0; + for (auto cq = cli_cqs_.begin(); cq != cli_cqs_.end(); cq++) { + count += grpc_get_cq_poll_num((*cq)->cq()); + } + return count; + } + protected: const int num_async_threads_; diff --git a/test/cpp/qps/driver.cc b/test/cpp/qps/driver.cc index 74fe3662c1ca2c2029cd8689872f7961849188e8..ace50288764c624d592f757089d6fdbb87686d03 100644 --- a/test/cpp/qps/driver.cc +++ b/test/cpp/qps/driver.cc @@ -112,6 +112,8 @@ static deque<string> get_workers(const string& env_name) { static double WallTime(ClientStats s) { return s.time_elapsed(); } static double SystemTime(ClientStats s) { return s.time_system(); } static double UserTime(ClientStats s) { return s.time_user(); } +static double CliPollCount(ClientStats s) { return s.cq_poll_count(); } +static double SvrPollCount(ServerStats s) { return s.cq_poll_count(); } static double ServerWallTime(ServerStats s) { return s.time_elapsed(); } static double ServerSystemTime(ServerStats s) { return s.time_system(); } static double ServerUserTime(ServerStats s) { return s.time_user(); } @@ -180,6 +182,11 @@ static void postprocess_scenario_result(ScenarioResult* result) { result->mutable_summary()->set_failed_requests_per_second(failures / time_estimate); } + + result->mutable_summary()->set_client_polls_per_request( + sum(result->client_stats(), CliPollCount) / histogram.Count()); + result->mutable_summary()->set_server_polls_per_request( + sum(result->server_stats(), SvrPollCount) / histogram.Count()); } std::unique_ptr<ScenarioResult> RunScenario( diff --git a/test/cpp/qps/qps_json_driver.cc b/test/cpp/qps/qps_json_driver.cc index a9061374748a479dac074c4995504bab58693daf..f00f771ea02ca42b752e8421f3f07222a5d12dd5 100644 --- a/test/cpp/qps/qps_json_driver.cc +++ b/test/cpp/qps/qps_json_driver.cc @@ -94,6 +94,7 @@ static std::unique_ptr<ScenarioResult> RunAndReport(const Scenario& scenario, GetReporter()->ReportLatency(*result); GetReporter()->ReportTimes(*result); GetReporter()->ReportCpuUsage(*result); + GetReporter()->ReportPollCount(*result); for (int i = 0; *success && i < result->client_success_size(); i++) { *success = result->client_success(i); diff --git a/test/cpp/qps/report.cc b/test/cpp/qps/report.cc index a9130bf5d425b3dd8970eff3874a3647b6d25439..8bb4c9a3a50a63c86e591eb6fa743f334c5d42d0 100644 --- a/test/cpp/qps/report.cc +++ b/test/cpp/qps/report.cc @@ -80,6 +80,12 @@ void CompositeReporter::ReportCpuUsage(const ScenarioResult& result) { } } +void CompositeReporter::ReportPollCount(const ScenarioResult& result) { + for (size_t i = 0; i < reporters_.size(); ++i) { + reporters_[i]->ReportPollCount(result); + } +} + void GprLogReporter::ReportQPS(const ScenarioResult& result) { gpr_log(GPR_INFO, "QPS: %.1f", result.summary().qps()); if (result.summary().failed_requests_per_second() > 0) { @@ -121,6 +127,13 @@ void GprLogReporter::ReportCpuUsage(const ScenarioResult& result) { result.summary().server_cpu_usage()); } +void GprLogReporter::ReportPollCount(const ScenarioResult& result) { + gpr_log(GPR_INFO, "Client Polls per Request: %.2f", + result.summary().client_polls_per_request()); + gpr_log(GPR_INFO, "Server Polls per Request: %.2f", + result.summary().server_polls_per_request()); +} + void JsonReporter::ReportQPS(const ScenarioResult& result) { grpc::string json_string = SerializeJson(result, "type.googleapis.com/grpc.testing.ScenarioResult"); @@ -145,6 +158,10 @@ void JsonReporter::ReportCpuUsage(const ScenarioResult& result) { // NOP - all reporting is handled by ReportQPS. } +void JsonReporter::ReportPollCount(const ScenarioResult& result) { + // NOP - all reporting is handled by ReportQPS. +} + void RpcReporter::ReportQPS(const ScenarioResult& result) { grpc::ClientContext context; grpc::Status status; @@ -177,5 +194,9 @@ void RpcReporter::ReportCpuUsage(const ScenarioResult& result) { // NOP - all reporting is handled by ReportQPS. } +void RpcReporter::ReportPollCount(const ScenarioResult& result) { + // NOP - all reporting is handled by ReportQPS. +} + } // namespace testing } // namespace grpc diff --git a/test/cpp/qps/report.h b/test/cpp/qps/report.h index 1749be98c6f9ce95b9d97e664340e85d004c40e0..621fa7cb007c96b782537215a552c07401c7da03 100644 --- a/test/cpp/qps/report.h +++ b/test/cpp/qps/report.h @@ -76,6 +76,9 @@ class Reporter { /** Reports server cpu usage. */ virtual void ReportCpuUsage(const ScenarioResult& result) = 0; + /** Reports client and server poll usage inside completion queue. */ + virtual void ReportPollCount(const ScenarioResult& result) = 0; + private: const string name_; }; @@ -93,6 +96,7 @@ class CompositeReporter : public Reporter { void ReportLatency(const ScenarioResult& result) override; void ReportTimes(const ScenarioResult& result) override; void ReportCpuUsage(const ScenarioResult& result) override; + void ReportPollCount(const ScenarioResult& result) override; private: std::vector<std::unique_ptr<Reporter> > reporters_; @@ -109,6 +113,7 @@ class GprLogReporter : public Reporter { void ReportLatency(const ScenarioResult& result) override; void ReportTimes(const ScenarioResult& result) override; void ReportCpuUsage(const ScenarioResult& result) override; + void ReportPollCount(const ScenarioResult& result) override; }; /** Dumps the report to a JSON file. */ @@ -123,6 +128,7 @@ class JsonReporter : public Reporter { void ReportLatency(const ScenarioResult& result) override; void ReportTimes(const ScenarioResult& result) override; void ReportCpuUsage(const ScenarioResult& result) override; + void ReportPollCount(const ScenarioResult& result) override; const string report_file_; }; @@ -138,6 +144,7 @@ class RpcReporter : public Reporter { void ReportLatency(const ScenarioResult& result) override; void ReportTimes(const ScenarioResult& result) override; void ReportCpuUsage(const ScenarioResult& result) override; + void ReportPollCount(const ScenarioResult& result) override; std::unique_ptr<ReportQpsScenarioService::Stub> stub_; }; diff --git a/test/cpp/qps/server.h b/test/cpp/qps/server.h index 8fbf37a0957869868fec4b68c75c0823f21e1b39..a03dd1a695b07b6b7b7927b1d2c335d1997b11f8 100644 --- a/test/cpp/qps/server.h +++ b/test/cpp/qps/server.h @@ -38,6 +38,7 @@ #include <grpc/support/cpu.h> #include <vector> +#include "src/core/lib/surface/completion_queue.h" #include "src/proto/grpc/testing/control.pb.h" #include "src/proto/grpc/testing/messages.pb.h" #include "test/core/end2end/data/ssl_test_data.h" @@ -49,7 +50,8 @@ namespace testing { class Server { public: - explicit Server(const ServerConfig& config) : timer_(new UsageTimer) { + explicit Server(const ServerConfig& config) + : timer_(new UsageTimer), last_reset_poll_count_(0) { cores_ = gpr_cpu_num_cores(); if (config.port()) { port_ = config.port(); @@ -62,10 +64,13 @@ class Server { ServerStats Mark(bool reset) { UsageTimer::Result timer_result; + int cur_poll_count = GetPollCount(); + int poll_count = cur_poll_count - last_reset_poll_count_; if (reset) { std::unique_ptr<UsageTimer> timer(new UsageTimer); timer.swap(timer_); timer_result = timer->Mark(); + last_reset_poll_count_ = cur_poll_count; } else { timer_result = timer_->Mark(); } @@ -76,6 +81,7 @@ class Server { stats.set_time_user(timer_result.user); stats.set_total_cpu_time(timer_result.total_cpu_time); stats.set_idle_cpu_time(timer_result.idle_cpu_time); + stats.set_cq_poll_count(poll_count); return stats; } @@ -106,10 +112,16 @@ class Server { } } + virtual int GetPollCount() { + // For sync server. + return 0; + } + private: int port_; int cores_; std::unique_ptr<UsageTimer> timer_; + int last_reset_poll_count_; }; std::unique_ptr<Server> CreateSynchronousServer(const ServerConfig& config); diff --git a/test/cpp/qps/server_async.cc b/test/cpp/qps/server_async.cc index 84f1579c2f91228afbb990f6ec1d3590387ed285..3403ffd326688427ad77039df9c2692de5d02ec4 100644 --- a/test/cpp/qps/server_async.cc +++ b/test/cpp/qps/server_async.cc @@ -186,6 +186,14 @@ class AsyncQpsServerTest final : public grpc::testing::Server { shutdown_thread.join(); } + int GetPollCount() override { + int count = 0; + for (auto cq = srv_cqs_.begin(); cq != srv_cqs_.end(); cq++) { + count += grpc_get_cq_poll_num((*cq)->cq()); + } + return count; + } + private: void ShutdownThreadFunc() { // TODO (vpai): Remove this deadline and allow Shutdown to finish properly