From b90d2f1371d540fa64f06323611c7ab556f88acd Mon Sep 17 00:00:00 2001
From: ShiningZhang <zhang_liang1991@126.com>
Date: Fri, 17 Sep 2021 20:01:49 +0800
Subject: [PATCH] add log of client cost

---
 core/general-client/src/brpc_client.cpp   | 34 ++++++++++++++++++++---
 core/general-client/src/general_model.cpp | 34 ++++++++++++++++++++---
 core/pdcodegen/src/pdcodegen.cpp          |  4 +++
 3 files changed, 64 insertions(+), 8 deletions(-)

diff --git a/core/general-client/src/brpc_client.cpp b/core/general-client/src/brpc_client.cpp
index ad459604..435f9cbb 100644
--- a/core/general-client/src/brpc_client.cpp
+++ b/core/general-client/src/brpc_client.cpp
@@ -119,10 +119,8 @@ int ServingBrpcClient::predict(const PredictorInputs& inputs,
   int64_t postprocess_start = 0;
   int64_t postprocess_end = 0;
 
-  if (FLAGS_profile_client) {
-    if (FLAGS_profile_server) {
-      req.set_profile_server(true);
-    }
+  if (FLAGS_profile_server) {
+    req.set_profile_server(true);
   }
 
   res.Clear();
@@ -164,6 +162,34 @@ int ServingBrpcClient::predict(const PredictorInputs& inputs,
   // release predictor
   _api.thrd_clear();
 
+  std::ostringstream oss;
+  oss << "[client]"
+      << "logid=" << log_id <<",";
+  if (FLAGS_profile_client) {
+    double pre_cost = (preprocess_end - preprocess_start) / 1000.0;
+    double infer_cost = (client_infer_end - client_infer_start) / 1000.0;
+    double post_cost = (postprocess_end - postprocess_start) / 1000.0;
+    oss << "client_pre_cost=" << pre_cost << "ms,"
+        << "client_infer_cost=" << infer_cost << "ms,"
+        << "client_post_cost=" << post_cost << "ms,";
+  }
+  double client_cost = (postprocess_end - preprocess_start) / 1000.0;
+  oss << "client_cost=" << client_cost << "ms,";
+
+  int op_num = res.profile_time_size() / 2;
+  if (FLAGS_profile_server) {
+    for (int i = 0; i < op_num - 1; ++i) {
+      double t = (res.profile_time(i * 2 + 1)
+                 - res.profile_time(i * 2)) / 1000.0;
+      oss << "op" << i << "=" << t << "ms,";
+    }
+  }
+  int i = op_num - 1;
+  double server_cost = (res.profile_time(i * 2 + 1)
+               - res.profile_time(i * 2)) / 1000.0;
+  oss << "server_cost=" << server_cost << "ms.";
+  LOG(INFO) << oss.str();
+
   return 0;
 }
 
diff --git a/core/general-client/src/general_model.cpp b/core/general-client/src/general_model.cpp
index b8e8630b..a9e8e759 100644
--- a/core/general-client/src/general_model.cpp
+++ b/core/general-client/src/general_model.cpp
@@ -329,10 +329,8 @@ int PredictorClient::numpy_predict(
   int64_t postprocess_start = 0;
   int64_t postprocess_end = 0;
 
-  if (FLAGS_profile_client) {
-    if (FLAGS_profile_server) {
-      req.set_profile_server(true);
-    }
+  if (FLAGS_profile_server) {
+    req.set_profile_server(true);
   }
 
   res.Clear();
@@ -428,6 +426,34 @@ int PredictorClient::numpy_predict(
   }
 
   _api.thrd_clear();
+
+  std::ostringstream oss;
+  oss << "[client]"
+      << "logid=" << log_id <<",";
+  if (FLAGS_profile_client) {
+    double pre_cost = (preprocess_end - preprocess_start) / 1000.0;
+    double infer_cost = (client_infer_end - client_infer_start) / 1000.0;
+    double post_cost = (postprocess_end - postprocess_start) / 1000.0;
+    oss << "client_pre_cost=" << pre_cost << "ms,"
+        << "client_infer_cost=" << infer_cost << "ms,"
+        << "client_post_cost=" << post_cost << "ms,";
+  }
+  double client_cost = (postprocess_end - preprocess_start) / 1000.0;
+  oss << "client_cost=" << client_cost << "ms,";
+
+  int op_num = res.profile_time_size() / 2;
+  if (FLAGS_profile_server) {
+    for (int i = 0; i < op_num - 1; ++i) {
+      double t = (res.profile_time(i * 2 + 1)
+                 - res.profile_time(i * 2)) / 1000.0;
+      oss << "op" << i << "=" << t << "ms,";
+    }
+  }
+  int i = op_num - 1;
+  double server_cost = (res.profile_time(i * 2 + 1)
+               - res.profile_time(i * 2)) / 1000.0;
+  oss << "server_cost=" << server_cost << "ms.";
+  LOG(INFO) << oss.str();
   return 0;
 }
 }  // namespace general_model
diff --git a/core/pdcodegen/src/pdcodegen.cpp b/core/pdcodegen/src/pdcodegen.cpp
index f17166a7..b4ab1afc 100644
--- a/core/pdcodegen/src/pdcodegen.cpp
+++ b/core/pdcodegen/src/pdcodegen.cpp
@@ -326,6 +326,8 @@ class PdsCodeGenerator : public CodeGenerator {
           inference_body += "  oss << \"cost=\" << total_time << \"ms.\";\n";
           inference_body += "  // flush notice log\n";
           inference_body += "  LOG(INFO) << oss.str();\n";
+          inference_body += "  response->add_profile_time(start);\n";
+          inference_body += "  response->add_profile_time(end);\n";
         } else {
           inference_body += "  // flush notice log\n";
           inference_body += "  LOG(INFO) << \"(logid=\" << log_id << \") tc=\[\" << (end - ";  // NOLINT
@@ -1091,6 +1093,8 @@ class PdsCodeGenerator : public CodeGenerator {
           inference_body += "  oss << \"cost=\" << total_time << \"ms.\";\n";
           inference_body += "  // flush notice log\n";
           inference_body += "  LOG(INFO) << oss.str();\n";
+          inference_body += "  response->add_profile_time(start);\n";
+          inference_body += "  response->add_profile_time(end);\n";
         } else {
           inference_body += "  // flush notice log\n";
           inference_body += "  LOG(INFO) << \"(logid=\" << log_id << \") tc=\[\" << (end - ";  // NOLINT
-- 
GitLab