From 5d55bce1f6790e37c4214566ecb82ffd8648c4e4 Mon Sep 17 00:00:00 2001 From: barriery Date: Fri, 7 Aug 2020 13:07:51 +0000 Subject: [PATCH] add logid into Op --- core/general-server/op/general_infer_helper.h | 5 +- core/general-server/op/general_infer_op.cpp | 14 +++-- core/general-server/op/general_reader_op.cpp | 52 +++++++++++-------- .../general-server/op/general_response_op.cpp | 37 +++++++------ 4 files changed, 65 insertions(+), 43 deletions(-) diff --git a/core/general-server/op/general_infer_helper.h b/core/general-server/op/general_infer_helper.h index 4fa19956..9b5a023b 100644 --- a/core/general-server/op/general_infer_helper.h +++ b/core/general-server/op/general_infer_helper.h @@ -35,6 +35,7 @@ struct GeneralBlob { std::vector tensor_vector; int64_t time_stamp[20]; int p_size = 0; + uint64_t _log_id = -1; // for logging int _batch_size; @@ -46,9 +47,11 @@ struct GeneralBlob { tensor_vector.clear(); } - int SetBatchSize(int batch_size) { _batch_size = batch_size; } + void SetBatchSize(int batch_size) { _batch_size = batch_size; } + void SetLogId(uint64_t log_id) { _log_id = log_id; } int GetBatchSize() const { return _batch_size; } + uint64_t GetLogId() const { return _log_id; } std::string ShortDebugString() const { return "Not implemented!"; } }; diff --git a/core/general-server/op/general_infer_op.cpp b/core/general-server/op/general_infer_op.cpp index a9ff2e72..1fe9e738 100644 --- a/core/general-server/op/general_infer_op.cpp +++ b/core/general-server/op/general_infer_op.cpp @@ -47,22 +47,25 @@ int GeneralInferOp::inference() { const std::string pre_name = pre_node_names[0]; const GeneralBlob *input_blob = get_depend_argument(pre_name); - VLOG(2) << "Get precedent op name: " << pre_name; + uint64_t log_id = input_blob->GetLogId(); + VLOG(2) << "(logid=" << log_id << ") Get precedent op name: " << pre_name; GeneralBlob *output_blob = mutable_data(); + output_blob->SetLogId(log_id); if (!input_blob) { - LOG(ERROR) << "Failed mutable depended argument, op:" << pre_name; + LOG(ERROR) << "(logid=" << log_id + << ") Failed mutable depended argument, op:" << pre_name; return -1; } const TensorVector *in = &input_blob->tensor_vector; TensorVector *out = &output_blob->tensor_vector; int batch_size = input_blob->GetBatchSize(); - VLOG(2) << "input batch size: " << batch_size; + VLOG(2) << "(logid=" << log_id << ") input batch size: " << batch_size; output_blob->SetBatchSize(batch_size); - VLOG(2) << "infer batch size: " << batch_size; + VLOG(2) << "(logid=" << log_id << ") infer batch size: " << batch_size; Timer timeline; int64_t start = timeline.TimeStampUS(); @@ -70,7 +73,8 @@ int GeneralInferOp::inference() { if (InferManager::instance().infer( engine_name().c_str(), in, out, batch_size)) { - LOG(ERROR) << "Failed do infer in fluid model: " << engine_name().c_str(); + LOG(ERROR) << "(logid=" << log_id + << ") Failed do infer in fluid model: " << engine_name().c_str(); return -1; } diff --git a/core/general-server/op/general_reader_op.cpp b/core/general-server/op/general_reader_op.cpp index 380f8616..ca4d0fcc 100644 --- a/core/general-server/op/general_reader_op.cpp +++ b/core/general-server/op/general_reader_op.cpp @@ -72,6 +72,7 @@ int conf_check(const Request *req, int GeneralReaderOp::inference() { // reade request from client const Request *req = dynamic_cast(get_request_message()); + uint64_t log_id = req->log_id(); int batch_size = req->insts_size(); int input_var_num = 0; @@ -83,25 +84,28 @@ int GeneralReaderOp::inference() { TensorVector *out = &res->tensor_vector; res->SetBatchSize(batch_size); + res->SetLogId(log_id); if (!res) { - LOG(ERROR) << "Failed get op tls reader object output"; + LOG(ERROR) << "(logid=" << log_id + << ") Failed get op tls reader object output"; } Timer timeline; int64_t start = timeline.TimeStampUS(); int var_num = req->insts(0).tensor_array_size(); - VLOG(2) << "var num: " << var_num; + VLOG(2) << "(logid=" << log_id << ") var num: " << var_num; - VLOG(2) << "start to call load general model_conf op"; + VLOG(2) << "(logid=" << log_id + << ") start to call load general model_conf op"; baidu::paddle_serving::predictor::Resource &resource = baidu::paddle_serving::predictor::Resource::instance(); - VLOG(2) << "get resource pointer done."; + VLOG(2) << "(logid=" << log_id << ") get resource pointer done."; std::shared_ptr model_config = resource.get_general_model_config(); - VLOG(2) << "print general model config done."; + VLOG(2) << "(logid=" << log_id << ") print general model config done."; // TODO(guru4elephant): how to do conditional check? /* @@ -122,7 +126,8 @@ int GeneralReaderOp::inference() { for (int i = 0; i < var_num; ++i) { paddle::PaddleTensor lod_tensor; elem_type[i] = req->insts(0).tensor_array(i).elem_type(); - VLOG(2) << "var[" << i << "] has elem type: " << elem_type[i]; + VLOG(2) << "(logid=" << log_id << ") var[" << i + << "] has elem type: " << elem_type[i]; if (elem_type[i] == 0) { // int64 elem_size[i] = sizeof(int64_t); lod_tensor.dtype = paddle::PaddleDType::INT64; @@ -137,17 +142,19 @@ int GeneralReaderOp::inference() { if (model_config->_is_lod_feed[i]) { lod_tensor.lod.resize(1); lod_tensor.lod[0].push_back(0); - VLOG(2) << "var[" << i << "] is lod_tensor"; + VLOG(2) << "(logid=" << log_id << ") var[" << i << "] is lod_tensor"; } else { lod_tensor.shape.push_back(batch_size); capacity[i] = 1; for (int k = 0; k < req->insts(0).tensor_array(i).shape_size(); ++k) { int dim = req->insts(0).tensor_array(i).shape(k); - VLOG(2) << "shape for var[" << i << "]: " << dim; + VLOG(2) << "(logid=" << log_id << ") shape for var[" << i + << "]: " << dim; capacity[i] *= dim; lod_tensor.shape.push_back(dim); } - VLOG(2) << "var[" << i << "] is tensor, capacity: " << capacity[i]; + VLOG(2) << "(logid=" << log_id << ") var[" << i + << "] is tensor, capacity: " << capacity[i]; } lod_tensor.name = model_config->_feed_name[i]; out->push_back(lod_tensor); @@ -167,11 +174,12 @@ int GeneralReaderOp::inference() { } else if (tensor.int_data_size() > 0) { data_len = tensor.int_data_size(); } - VLOG(2) << "tensor size for var[" << i << "]: " << data_len; + VLOG(2) << "(logid=" << log_id << ") tensor size for var[" << i + << "]: " << data_len; tensor_size += data_len; int cur_len = out->at(i).lod[0].back(); - VLOG(2) << "current len: " << cur_len; + VLOG(2) << "(logid=" << log_id << ") current len: " << cur_len; int sample_len = 0; if (tensor.shape_size() == 1) { @@ -180,7 +188,7 @@ int GeneralReaderOp::inference() { sample_len = tensor.shape(0); } out->at(i).lod[0].push_back(cur_len + sample_len); - VLOG(2) << "new len: " << cur_len + sample_len; + VLOG(2) << "(logid=" << log_id << ") new len: " << cur_len + sample_len; } out->at(i).data.Resize(tensor_size * elem_size[i]); out->at(i).shape = {out->at(i).lod[0].back()}; @@ -190,11 +198,11 @@ int GeneralReaderOp::inference() { if (out->at(i).shape.size() == 1) { out->at(i).shape.push_back(1); } - VLOG(2) << "var[" << i + VLOG(2) << "(logid=" << log_id << ") var[" << i << "] is lod_tensor and len=" << out->at(i).lod[0].back(); } else { out->at(i).data.Resize(batch_size * capacity[i] * elem_size[i]); - VLOG(2) << "var[" << i + VLOG(2) << "(logid=" << log_id << ") var[" << i << "] is tensor and capacity=" << batch_size * capacity[i]; } } @@ -203,8 +211,8 @@ int GeneralReaderOp::inference() { for (int i = 0; i < var_num; ++i) { if (elem_type[i] == 0) { int64_t *dst_ptr = static_cast(out->at(i).data.data()); - VLOG(2) << "first element data in var[" << i << "] is " - << req->insts(0).tensor_array(i).int64_data(0); + VLOG(2) << "(logid=" << log_id << ") first element data in var[" << i + << "] is " << req->insts(0).tensor_array(i).int64_data(0); int offset = 0; for (int j = 0; j < batch_size; ++j) { int elem_num = req->insts(j).tensor_array(i).int64_data_size(); @@ -219,8 +227,8 @@ int GeneralReaderOp::inference() { } } else if (elem_type[i] == 1) { float *dst_ptr = static_cast(out->at(i).data.data()); - VLOG(2) << "first element data in var[" << i << "] is " - << req->insts(0).tensor_array(i).float_data(0); + VLOG(2) << "(logid=" << log_id << ") first element data in var[" << i + << "] is " << req->insts(0).tensor_array(i).float_data(0); int offset = 0; for (int j = 0; j < batch_size; ++j) { int elem_num = req->insts(j).tensor_array(i).float_data_size(); @@ -235,8 +243,8 @@ int GeneralReaderOp::inference() { } } else if (elem_type[i] == 2) { int32_t *dst_ptr = static_cast(out->at(i).data.data()); - VLOG(2) << "first element data in var[" << i << "] is " - << req->insts(0).tensor_array(i).int_data(0); + VLOG(2) << "(logid=" << log_id << ") first element data in var[" << i + << "] is " << req->insts(0).tensor_array(i).int_data(0); int offset = 0; for (int j = 0; j < batch_size; ++j) { int elem_num = req->insts(j).tensor_array(i).int_data_size(); @@ -252,7 +260,7 @@ int GeneralReaderOp::inference() { } } - VLOG(2) << "output size: " << out->size(); + VLOG(2) << "(logid=" << log_id << ") output size: " << out->size(); timeline.Pause(); int64_t end = timeline.TimeStampUS(); @@ -260,7 +268,7 @@ int GeneralReaderOp::inference() { AddBlobInfo(res, start); AddBlobInfo(res, end); - VLOG(2) << "read data from client success"; + VLOG(2) << "(logid=" << log_id << ") read data from client success"; return 0; } DEFINE_OP(GeneralReaderOp); diff --git a/core/general-server/op/general_response_op.cpp b/core/general-server/op/general_response_op.cpp index b2d918be..02615faa 100644 --- a/core/general-server/op/general_response_op.cpp +++ b/core/general-server/op/general_response_op.cpp @@ -75,10 +75,12 @@ int GeneralResponseOp::inference() { VLOG(2) << "pre names[" << pi << "]: " << pre_name << " (" << pre_node_names.size() << ")"; input_blob = get_depend_argument(pre_name); + uint64_t curr_logid = input_blob->GetLogId(); // fprintf(stderr, "input(%s) blob address %x\n", pre_names.c_str(), // input_blob); if (!input_blob) { - LOG(ERROR) << "Failed mutable depended argument, op: " << pre_name; + LOG(ERROR) << "(logid=" << curr_logid + << ") Failed mutable depended argument, op: " << pre_name; return -1; } @@ -92,17 +94,19 @@ int GeneralResponseOp::inference() { for (auto &idx : fetch_index) { Tensor *tensor = fetch_inst->add_tensor_array(); if (model_config->_is_lod_fetch[idx]) { - VLOG(2) << "out[" << idx << "] " << model_config->_fetch_name[idx] - << " is lod_tensor"; + VLOG(2) << "(logid=" << curr_logid << ") out[" << idx << "] " + << model_config->_fetch_name[idx] << " is lod_tensor"; for (int k = 0; k < in->at(idx).shape.size(); ++k) { - VLOG(2) << "shape[" << k << "]: " << in->at(idx).shape[k]; + VLOG(2) << "(logid=" << curr_logid << ") shape[" << k + << "]: " << in->at(idx).shape[k]; tensor->add_shape(in->at(idx).shape[k]); } } else { - VLOG(2) << "out[" << idx << "] " << model_config->_fetch_name[idx] - << " is tensor"; + VLOG(2) << "(logid=" << curr_logid << ") out[" << idx << "] " + << model_config->_fetch_name[idx] << " is tensor"; for (int k = 0; k < in->at(idx).shape.size(); ++k) { - VLOG(2) << "shape[" << k << "]: " << in->at(idx).shape[k]; + VLOG(2) << "(logid=" << curr_logid << ") shape[" << k + << "]: " << in->at(idx).shape[k]; tensor->add_shape(in->at(idx).shape[k]); } } @@ -119,8 +123,8 @@ int GeneralResponseOp::inference() { auto dtype = in->at(idx).dtype; if (dtype == paddle::PaddleDType::INT64) { - VLOG(2) << "Prepare int64 var [" << model_config->_fetch_name[idx] - << "]."; + VLOG(2) << "(logid=" << curr_logid << ") Prepare int64 var [" + << model_config->_fetch_name[idx] << "]."; int64_t *data_ptr = static_cast(in->at(idx).data.data()); // from // https://stackoverflow.com/questions/15499641/copy-a-stdvector-to-a-repeated-field-from-protobuf-with-memcpy @@ -130,16 +134,16 @@ int GeneralResponseOp::inference() { fetch_p->mutable_tensor_array(var_idx)->mutable_int64_data()->Swap( &tmp_data); } else if (dtype == paddle::PaddleDType::FLOAT32) { - VLOG(2) << "Prepare float var [" << model_config->_fetch_name[idx] - << "]."; + VLOG(2) << "(logid=" << curr_logid << ") Prepare float var [" + << model_config->_fetch_name[idx] << "]."; float *data_ptr = static_cast(in->at(idx).data.data()); google::protobuf::RepeatedField tmp_data(data_ptr, data_ptr + cap); fetch_p->mutable_tensor_array(var_idx)->mutable_float_data()->Swap( &tmp_data); } else if (dtype == paddle::PaddleDType::INT32) { - VLOG(2) << "Prepare int32 var [" << model_config->_fetch_name[idx] - << "]."; + VLOG(2) << "(logid=" << curr_logid << ")Prepare int32 var [" + << model_config->_fetch_name[idx] << "]."; int32_t *data_ptr = static_cast(in->at(idx).data.data()); google::protobuf::RepeatedField tmp_data(data_ptr, data_ptr + cap); @@ -154,7 +158,8 @@ int GeneralResponseOp::inference() { } } - VLOG(2) << "fetch var [" << model_config->_fetch_name[idx] << "] ready"; + VLOG(2) << "(logid=" << curr_logid << ") fetch var [" + << model_config->_fetch_name[idx] << "] ready"; var_idx++; } } @@ -167,7 +172,9 @@ int GeneralResponseOp::inference() { // a more elegant way. for (uint32_t pi = 0; pi < pre_node_names.size(); ++pi) { input_blob = get_depend_argument(pre_node_names[pi]); - VLOG(2) << "p size for input blob: " << input_blob->p_size; + uint64_t curr_logid = input_blob->GetLogId(); + VLOG(2) << "(logid=" << curr_logid + << ") p size for input blob: " << input_blob->p_size; int profile_time_idx = -1; if (pi == 0) { profile_time_idx = 0; -- GitLab