add logid into Op

core/general-server/op/general_infer_helper.h

@@ -35,6 +35,7 @@ struct GeneralBlob {
   std::vector<paddle::PaddleTensor> 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!"; }
 };
 

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<GeneralBlob>(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<GeneralBlob>();
+  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;
   }
 

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<const Request *>(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<PaddleGeneralModelConfig> 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<int64_t *>(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<float *>(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<int32_t *>(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);

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<GeneralBlob>(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<int64_t *>(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<float *>(in->at(idx).data.data());
         google::protobuf::RepeatedField<float> 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<int32_t *>(in->at(idx).data.data());
         google::protobuf::RepeatedField<int32_t> 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<GeneralBlob>(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;