Print resource utilization

src/core/support/histogram.c

@@ -236,4 +236,4 @@ double gpr_histogram_sum_of_squares(gpr_histogram *h) {
 const gpr_uint32 *gpr_histogram_get_contents(gpr_histogram *h, size_t *size) {
   *size = h->num_buckets;
   return h->buckets;
-}
+}

test/cpp/qps/driver.cc

@@ -71,7 +71,7 @@ static vector<string> get_hosts(const string& name) {
   }
 }
 
-void RunScenario(const ClientConfig& initial_client_config, size_t num_clients,
+ScenarioResult RunScenario(const ClientConfig& initial_client_config, size_t num_clients,
                  const ServerConfig& server_config, size_t num_servers) {
   // ClientContext allocator (all are destroyed at scope exit)
   list<ClientContext> contexts;
@@ -172,7 +172,7 @@ void RunScenario(const ClientConfig& initial_client_config, size_t num_clients,
   gpr_sleep_until(gpr_time_add(start, gpr_time_from_seconds(15)));
 
   // Finish a run
-  Histogram latencies;
+  ScenarioResult result;
   gpr_log(GPR_INFO, "Finishing");
   for (auto& server : servers) {
     GPR_ASSERT(server.stream->Write(server_mark));
@@ -182,10 +182,14 @@ void RunScenario(const ClientConfig& initial_client_config, size_t num_clients,
   }
   for (auto& server : servers) {
     GPR_ASSERT(server.stream->Read(&server_status));
+    const auto& stats = server_status.stats();
+    result.server_resources.push_back(ResourceUsage{stats.time_elapsed(), stats.time_user(), stats.time_system()});
   }
   for (auto& client : clients) {
     GPR_ASSERT(client.stream->Read(&client_status));
-    latencies.MergeProto(client_status.stats().latencies());
+    const auto& stats = client_status.stats();
+    result.latencies.MergeProto(stats.latencies());
+    result.client_resources.push_back(ResourceUsage{stats.time_elapsed(), stats.time_user(), stats.time_system()});
   }
 
   for (auto& client : clients) {
@@ -196,10 +200,7 @@ void RunScenario(const ClientConfig& initial_client_config, size_t num_clients,
     GPR_ASSERT(server.stream->WritesDone());
     GPR_ASSERT(server.stream->Finish().IsOk());
   }
-
-  gpr_log(GPR_INFO, "Latencies (50/95/99/99.9%%-ile): %.1f/%.1f/%.1f/%.1f us",
-          latencies.Percentile(50) / 1e3, latencies.Percentile(95) / 1e3,
-          latencies.Percentile(99) / 1e3, latencies.Percentile(99.9) / 1e3);
-}
-}
+  return result;
 }
+}  // namespace testing
+}  // namespace grpc

test/cpp/qps/driver.h

@@ -34,15 +34,28 @@
 #ifndef TEST_QPS_DRIVER_H
 #define TEST_QPS_DRIVER_H
 
+#include "test/cpp/qps/histogram.h"
 #include "test/cpp/qps/qpstest.pb.h"
 
 namespace grpc {
 namespace testing {
-void RunScenario(const grpc::testing::ClientConfig& client_config,
+struct ResourceUsage {
+  double wall_time;
+  double user_time;
+  double system_time;
+};
+
+struct ScenarioResult {
+  Histogram latencies;
+  std::vector<ResourceUsage> client_resources;
+  std::vector<ResourceUsage> server_resources;
+};
+
+ScenarioResult RunScenario(const grpc::testing::ClientConfig& client_config,
                  size_t num_clients,
                  const grpc::testing::ServerConfig& server_config,
                  size_t num_servers);
-}
-}
+} // namespace testing
+} // namespace grpc
 
 #endif

test/cpp/qps/histogram.h

@@ -43,7 +43,10 @@ namespace testing {
 class Histogram {
  public:
   Histogram() : impl_(gpr_histogram_create(0.01, 60e9)) {}
-  ~Histogram() { gpr_histogram_destroy(impl_); }
+  ~Histogram() { if (impl_) gpr_histogram_destroy(impl_); }
+  Histogram(Histogram&& other) : impl_(other.impl_) {
+    other.impl_ = nullptr;
+  }
 
   void Merge(Histogram* h) { gpr_histogram_merge(impl_, h->impl_); }
   void Add(double value) { gpr_histogram_add(impl_, value); }

test/cpp/qps/qps_driver.cc

@@ -35,6 +35,7 @@
 #include <grpc/support/log.h>
 
 #include "test/cpp/qps/driver.h"
+#include "test/cpp/qps/stats.h"
 
 DEFINE_int32(num_clients, 1, "Number of client binaries");
 DEFINE_int32(num_servers, 1, "Number of server binaries");
@@ -57,6 +58,8 @@ using grpc::testing::ClientConfig;
 using grpc::testing::ServerConfig;
 using grpc::testing::ClientType;
 using grpc::testing::ServerType;
+using grpc::testing::ResourceUsage;
+using grpc::testing::sum;
 
 // In some distros, gflags is in the namespace google, and in some others,
 // in gflags. This hack is enabling us to find both.
@@ -87,9 +90,18 @@ int main(int argc, char **argv) {
   server_config.set_threads(FLAGS_server_threads);
   server_config.set_enable_ssl(FLAGS_enable_ssl);
 
-  RunScenario(client_config, FLAGS_num_clients, server_config,
+  auto result = RunScenario(client_config, FLAGS_num_clients, server_config,
               FLAGS_num_servers);
 
+  gpr_log(GPR_INFO, "Latencies (50/95/99/99.9%%-ile): %.1f/%.1f/%.1f/%.1f us",
+    result.latencies.Percentile(50) / 1000, result.latencies.Percentile(95) / 1000,
+    result.latencies.Percentile(99) / 1000, result.latencies.Percentile(99.9) / 1000);
+
+  gpr_log(GPR_INFO, "Server system time: %.2f%%", 100.0 * sum(result.server_resources, [](ResourceUsage u) { return u.system_time; }) / sum(result.server_resources, [](ResourceUsage u) { return u.wall_time; }));
+  gpr_log(GPR_INFO, "Server user time:   %.2f%%", 100.0 * sum(result.server_resources, [](ResourceUsage u) { return u.user_time; }) / sum(result.server_resources, [](ResourceUsage u) { return u.wall_time; }));
+  gpr_log(GPR_INFO, "Client system time: %.2f%%", 100.0 * sum(result.client_resources, [](ResourceUsage u) { return u.system_time; }) / sum(result.client_resources, [](ResourceUsage u) { return u.wall_time; }));
+  gpr_log(GPR_INFO, "Client user time:   %.2f%%", 100.0 * sum(result.client_resources, [](ResourceUsage u) { return u.user_time; }) / sum(result.client_resources, [](ResourceUsage u) { return u.wall_time; }));
+
   grpc_shutdown();
   return 0;
 }

test/cpp/qps/stats.h

@@ -0,0 +1,60 @@
+/*
+ *
+ * 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.
+ *
+ */
+
+#ifndef TEST_QPS_STATS_UTILS_H
+#define TEST_QPS_STATS_UTILS_H
+
+#include "test/cpp/qps/histogram.h"
+#include <string>
+
+namespace grpc {
+namespace testing {
+
+template <class T, class F>
+double sum(const T& container, F functor) {
+  double r = 0;
+  for (auto v : container) {
+  	r += functor(v);
+  }
+  return r;
+}
+
+template <class T, class F>
+double average(const T& container, F functor) {
+  return sum(container, functor) / container.size();
+}
+
+} // namespace testing
+} // namespace grpc
+
+#endif