diff --git a/core/general-client/src/brpc_client.cpp b/core/general-client/src/brpc_client.cpp index ad459604f3866b6aa1088e22de599071ebbae665..435f9cbba5f957547f69189996974a07deb3b098 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 b8e8630b801f0777224d8c11c23578bc7049989c..a9e8e75975d0e6b56e9a0b6c2dfd0898a018c3ae 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 f17166a75b5dd335c1fa7ff7258c51326961feea..b4ab1afc2f34c947745a9b33a941d317083ee372 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