Merge branch 'develop' into add-nvidia-wiki-to-docker-images-doc

core/configure/proto/multi_lang_general_model_service.proto

@@ -37,6 +37,7 @@ message InferenceRequest {
   repeated string feed_var_names = 2;
   repeated string fetch_var_names = 3;
   required bool is_python = 4 [ default = false ];
+  required uint64 log_id = 5 [ default = 0 ];
 };
 
 message InferenceResponse {

core/general-client/include/general_model.h

@@ -227,7 +227,8 @@ class PredictorClient {
       const std::vector<std::vector<int>>& int_shape,
       const std::vector<std::string>& fetch_name,
       PredictorRes& predict_res_batch,  // NOLINT
-      const int& pid);
+      const int& pid,
+      const uint64_t log_id);
 
   int numpy_predict(
       const std::vector<std::vector<py::array_t<float>>>& float_feed_batch,
@@ -238,7 +239,8 @@ class PredictorClient {
       const std::vector<std::vector<int>>& int_shape,
       const std::vector<std::string>& fetch_name,
       PredictorRes& predict_res_batch,  // NOLINT
-      const int& pid);
+      const int& pid,
+      const uint64_t log_id);
 
  private:
   PredictorApi _api;

core/general-client/src/general_model.cpp

@@ -144,7 +144,8 @@ int PredictorClient::batch_predict(
     const std::vector<std::vector<int>> &int_shape,
     const std::vector<std::string> &fetch_name,
     PredictorRes &predict_res_batch,
-    const int &pid) {
+    const int &pid,
+    const uint64_t log_id) {
   int batch_size = std::max(float_feed_batch.size(), int_feed_batch.size());
 
   predict_res_batch.clear();
@@ -162,6 +163,7 @@ int PredictorClient::batch_predict(
   VLOG(2) << "int feed name size: " << int_feed_name.size();
   VLOG(2) << "max body size : " << brpc::fLU64::FLAGS_max_body_size;
   Request req;
+  req.set_log_id(log_id);
   for (auto &name : fetch_name) {
     req.add_fetch_var_names(name);
   }
@@ -356,7 +358,8 @@ int PredictorClient::numpy_predict(
     const std::vector<std::vector<int>> &int_shape,
     const std::vector<std::string> &fetch_name,
     PredictorRes &predict_res_batch,
-    const int &pid) {
+    const int &pid,
+    const uint64_t log_id) {
   int batch_size = std::max(float_feed_batch.size(), int_feed_batch.size());
   VLOG(2) << "batch size: " << batch_size;
   predict_res_batch.clear();
@@ -374,6 +377,7 @@ int PredictorClient::numpy_predict(
   VLOG(2) << "int feed name size: " << int_feed_name.size();
   VLOG(2) << "max body size : " << brpc::fLU64::FLAGS_max_body_size;
   Request req;
+  req.set_log_id(log_id);
   for (auto &name : fetch_name) {
     req.add_fetch_var_names(name);
   }

core/general-client/src/pybind_general_model.cpp

@@ -107,7 +107,8 @@ PYBIND11_MODULE(serving_client, m) {
               const std::vector<std::vector<int>> &int_shape,
               const std::vector<std::string> &fetch_name,
               PredictorRes &predict_res_batch,
-              const int &pid) {
+              const int &pid,
+              const uint64_t log_id) {
              return self.batch_predict(float_feed_batch,
                                        float_feed_name,
                                        float_shape,
@@ -116,7 +117,8 @@ PYBIND11_MODULE(serving_client, m) {
                                        int_shape,
                                        fetch_name,
                                        predict_res_batch,
-                                       pid);
+                                       pid,
+                                       log_id);
            },
            py::call_guard<py::gil_scoped_release>())
       .def("numpy_predict",
@@ -131,7 +133,8 @@ PYBIND11_MODULE(serving_client, m) {
               const std::vector<std::vector<int>> &int_shape,
               const std::vector<std::string> &fetch_name,
               PredictorRes &predict_res_batch,
-              const int &pid) {
+              const int &pid,
+              const uint64_t log_id) {
              return self.numpy_predict(float_feed_batch,
                                        float_feed_name,
                                        float_shape,
@@ -140,7 +143,8 @@ PYBIND11_MODULE(serving_client, m) {
                                        int_shape,
                                        fetch_name,
                                        predict_res_batch,
-                                       pid);
+                                       pid,
+                                       log_id);
            },
            py::call_guard<py::gil_scoped_release>());
 }

core/general-server/op/general_copy_op.cpp

@@ -45,36 +45,41 @@ int GeneralCopyOp::inference() {
   const std::string pre_name = pre_node_names[0];
 
   const GeneralBlob *input_blob = get_depend_argument<GeneralBlob>(pre_name);
-  VLOG(2) << "precedent name: " << pre_name;
+  uint64_t log_id = input_blob->GetLogId();
+
+  VLOG(2) << "(logid=" << log_id << ") precedent name: " << pre_name;
   const TensorVector *in = &input_blob->tensor_vector;
-  VLOG(2) << "input size: " << in->size();
+  VLOG(2) << "(logid=" << log_id << ") input size: " << in->size();
   int batch_size = input_blob->GetBatchSize();
   int input_var_num = 0;
 
   GeneralBlob *res = mutable_data<GeneralBlob>();
+  res->SetLogId(log_id);
   TensorVector *out = &res->tensor_vector;
 
-  VLOG(2) << "input batch size: " << batch_size;
+  VLOG(2) << "(logid=" << log_id << ") input batch size: " << batch_size;
   res->SetBatchSize(batch_size);
 
   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();
 
-  VLOG(2) << "Going to init lod tensor";
+  VLOG(2) << "(logid=" << log_id << ") Going to init lod tensor";
   for (int i = 0; i < in->size(); ++i) {
     paddle::PaddleTensor lod_tensor;
     CopyLod(&in->at(i), &lod_tensor);
     lod_tensor.dtype = in->at(i).dtype;
     lod_tensor.name = in->at(i).name;
-    VLOG(2) << "lod tensor [" << i << "].name = " << lod_tensor.name;
+    VLOG(2) << "(logid=" << log_id << ") lod tensor [" << i
+            << "].name = " << lod_tensor.name;
     out->push_back(lod_tensor);
   }
 
-  VLOG(2) << "pack done.";
+  VLOG(2) << "(logid=" << log_id << ") pack done.";
 
   for (int i = 0; i < out->size(); ++i) {
     int64_t *src_ptr = static_cast<int64_t *>(in->at(i).data.data());
@@ -86,7 +91,7 @@ int GeneralCopyOp::inference() {
     }
   }
 
-  VLOG(2) << "output done.";
+  VLOG(2) << "(logid=" << log_id << ") output done.";
 
   timeline.Pause();
   int64_t end = timeline.TimeStampUS();
@@ -94,7 +99,7 @@ int GeneralCopyOp::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;
 }
 

core/general-server/op/general_dist_kv_infer_op.cpp

@@ -50,18 +50,20 @@ int GeneralDistKVInferOp::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>();
 
   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;
   std::vector<uint64_t> keys;
   std::vector<rec::mcube::CubeValue> values;
   int sparse_count = 0;
@@ -96,13 +98,14 @@ int GeneralDistKVInferOp::inference() {
   rec::mcube::CubeAPI *cube = rec::mcube::CubeAPI::instance();
   std::vector<std::string> table_names = cube->get_table_names();
   if (table_names.size() == 0) {
-    LOG(ERROR) << "cube init error or cube config not given.";
+    LOG(ERROR) << "(logid=" << log_id
+               << ") cube init error or cube config not given.";
     return -1;
   }
   int ret = cube->seek(table_names[0], keys, &values);
   int64_t cube_end = timeline.TimeStampUS();
   if (values.size() != keys.size() || values[0].buff.size() == 0) {
-    LOG(ERROR) << "cube value return null";
+    LOG(ERROR) << "(logid=" << log_id << ") cube value return null";
   }
   size_t EMBEDDING_SIZE = values[0].buff.size() / sizeof(float);
   TensorVector sparse_out;
@@ -153,14 +156,16 @@ int GeneralDistKVInferOp::inference() {
   infer_in.insert(infer_in.end(), sparse_out.begin(), sparse_out.end());
 
   output_blob->SetBatchSize(batch_size);
+  output_blob->SetLogId(log_id);
 
-  VLOG(2) << "infer batch size: " << batch_size;
+  VLOG(2) << "(logid=" << log_id << ") infer batch size: " << batch_size;
 
   int64_t start = timeline.TimeStampUS();
 
   if (InferManager::instance().infer(
           engine_name().c_str(), &infer_in, out, batch_size)) {
-    LOG(ERROR) << "Failed do infer in fluid model: " << engine_name();
+    LOG(ERROR) << "(logid=" << log_id
+               << ") Failed do infer in fluid model: " << engine_name();
     return -1;
   }
 

core/general-server/op/general_dist_kv_quant_infer_op.cpp

@@ -59,10 +59,13 @@ int GeneralDistKVQuantInferOp::inference() {
     return -1;
   }
 
+  uint64_t log_id = input_blob->GetLogId();
+  output_blob->SetLogId(log_id);
+
   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;
   std::vector<uint64_t> keys;
   std::vector<rec::mcube::CubeValue> values;
   int sparse_count = 0;
@@ -94,13 +97,14 @@ int GeneralDistKVQuantInferOp::inference() {
   rec::mcube::CubeAPI *cube = rec::mcube::CubeAPI::instance();
   std::vector<std::string> table_names = cube->get_table_names();
   if (table_names.size() == 0) {
-    LOG(ERROR) << "cube init error or cube config not given.";
+    LOG(ERROR) << "(logid=" << log_id
+               << ") cube init error or cube config not given.";
     return -1;
   }
   int ret = cube->seek(table_names[0], keys, &values);
 
   if (values.size() != keys.size() || values[0].buff.size() == 0) {
-    LOG(ERROR) << "cube value return null";
+    LOG(ERROR) << "(logid=" << log_id << ") cube value return null";
   }
 
   TensorVector sparse_out;
@@ -182,7 +186,7 @@ int GeneralDistKVQuantInferOp::inference() {
 
   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();
@@ -190,7 +194,8 @@ int GeneralDistKVQuantInferOp::inference() {
 
   if (InferManager::instance().infer(
           engine_name().c_str(), &infer_in, out, batch_size)) {
-    LOG(ERROR) << "Failed do infer in fluid model: " << engine_name();
+    LOG(ERROR) << "(logid=" << log_id
+               << ") Failed do infer in fluid model: " << engine_name();
     return -1;
   }
 

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

@@ -37,9 +37,9 @@ int conf_check(const Request *req,
                const std::shared_ptr<PaddleGeneralModelConfig> &model_config) {
   int var_num = req->insts(0).tensor_array_size();
   if (var_num != model_config->_feed_type.size()) {
-    VLOG(2) << "var num: " << var_num;
-    VLOG(2) << "model config var num: " << model_config->_feed_type.size();
-    LOG(ERROR) << "feed var number not match.";
+    LOG(ERROR) << "feed var number not match: model config["
+               << model_config->_feed_type.size() << "] vs. actual[" << var_num
+               << "]";
     return -1;
   }
 
@@ -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

@@ -42,6 +42,9 @@ using baidu::paddle_serving::predictor::PaddleGeneralModelConfig;
 int GeneralResponseOp::inference() {
   const std::vector<std::string> pre_node_names = pre_names();
   VLOG(2) << "pre node names size: " << pre_node_names.size();
+  const GeneralBlob *input_blob;
+  uint64_t log_id =
+      get_depend_argument<GeneralBlob>(pre_node_names[0])->GetLogId();
 
   const Request *req = dynamic_cast<const Request *>(get_request_message());
   // response inst with only fetch_var_names
@@ -52,15 +55,17 @@ int GeneralResponseOp::inference() {
   // timeline.Start();
   int64_t start = timeline.TimeStampUS();
 
-  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) << "max body size : " << brpc::fLU64::FLAGS_max_body_size;
+  VLOG(2) << "(logid=" << log_id
+          << ") max body size : " << brpc::fLU64::FLAGS_max_body_size;
 
   std::vector<int> fetch_index;
   fetch_index.resize(req->fetch_var_names_size());
@@ -69,16 +74,16 @@ int GeneralResponseOp::inference() {
         model_config->_fetch_alias_name_to_index[req->fetch_var_names(i)];
   }
 
-  const GeneralBlob *input_blob;
   for (uint32_t pi = 0; pi < pre_node_names.size(); ++pi) {
     const std::string &pre_name = pre_node_names[pi];
-    VLOG(2) << "pre names[" << pi << "]: " << pre_name << " ("
-            << pre_node_names.size() << ")";
+    VLOG(2) << "(logid=" << log_id << ") pre names[" << pi << "]: " << pre_name
+            << " (" << pre_node_names.size() << ")";
     input_blob = get_depend_argument<GeneralBlob>(pre_name);
     // 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=" << log_id
+                 << ") Failed mutable depended argument, op: " << pre_name;
       return -1;
     }
 
@@ -92,17 +97,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=" << log_id << ") 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=" << log_id << ") 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=" << log_id << ") 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=" << log_id << ") shape[" << k
+                  << "]: " << in->at(idx).shape[k];
           tensor->add_shape(in->at(idx).shape[k]);
         }
       }
@@ -119,8 +126,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=" << log_id << ") 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 +137,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=" << log_id << ") 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=" << log_id << ")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 +161,8 @@ int GeneralResponseOp::inference() {
         }
       }
 
-      VLOG(2) << "fetch var [" << model_config->_fetch_name[idx] << "] ready";
+      VLOG(2) << "(logid=" << log_id << ") fetch var ["
+              << model_config->_fetch_name[idx] << "] ready";
       var_idx++;
     }
   }
@@ -167,7 +175,8 @@ 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;
+      VLOG(2) << "(logid=" << log_id
+              << ") p size for input blob: " << input_blob->p_size;
       int profile_time_idx = -1;
       if (pi == 0) {
         profile_time_idx = 0;

core/general-server/op/general_text_reader_op.cpp

@@ -35,6 +35,7 @@ using baidu::paddle_serving::predictor::PaddleGeneralModelConfig;
 int GeneralTextReaderOp::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;
@@ -44,16 +45,18 @@ int GeneralTextReaderOp::inference() {
   std::vector<int64_t> capacity;
 
   GeneralBlob *res = mutable_data<GeneralBlob>();
-  TensorVector *out = &res->tensor_vector;
-
-  res->SetBatchSize(batch_size);
 
   if (!res) {
-    LOG(ERROR) << "Failed get op tls reader object output";
+    LOG(ERROR) << "(logid=" << log_id
+               << ") Failed get op tls reader object output";
   }
 
+  TensorVector *out = &res->tensor_vector;
+  res->SetBatchSize(batch_size);
+  res->SetLogId(log_id);
+
   if (batch_size <= 0) {
-    LOG(ERROR) << "Batch size < 0";
+    LOG(ERROR) << "(logid=" << log_id << ") Batch size < 0";
     return -1;
   }
 
@@ -61,17 +64,18 @@ int GeneralTextReaderOp::inference() {
   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.";
 
   elem_type.resize(var_num);
   elem_size.resize(var_num);
@@ -79,7 +83,8 @@ int GeneralTextReaderOp::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;
@@ -91,17 +96,19 @@ int GeneralTextReaderOp::inference() {
     if (req->insts(0).tensor_array(i).shape(0) == -1) {
       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);
@@ -117,11 +124,11 @@ int GeneralTextReaderOp::inference() {
       }
       out->at(i).data.Resize(out->at(i).lod[0].back() * elem_size[i]);
       out->at(i).shape = {out->at(i).lod[0].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];
     }
   }
@@ -163,7 +170,7 @@ int GeneralTextReaderOp::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(GeneralTextReaderOp);

core/general-server/op/general_text_response_op.cpp

@@ -40,6 +40,9 @@ int GeneralTextResponseOp::inference() {
   VLOG(2) << "Going to run inference";
   const std::vector<std::string> pre_node_names = pre_names();
   VLOG(2) << "pre node names size: " << pre_node_names.size();
+  const GeneralBlob *input_blob;
+  uint64_t log_id =
+      get_depend_argument<GeneralBlob>(pre_node_names[0])->GetLogId();
 
   const Request *req = dynamic_cast<const Request *>(get_request_message());
   // response inst with only fetch_var_names
@@ -48,11 +51,12 @@ int GeneralTextResponseOp::inference() {
   Timer timeline;
   int64_t start = timeline.TimeStampUS();
 
-  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();
 
@@ -63,20 +67,20 @@ int GeneralTextResponseOp::inference() {
         model_config->_fetch_alias_name_to_index[req->fetch_var_names(i)];
   }
 
-  const GeneralBlob *input_blob;
   for (uint32_t pi = 0; pi < pre_node_names.size(); ++pi) {
     const std::string &pre_name = pre_node_names[pi];
-    VLOG(2) << "pre names[" << pi << "]: " << pre_name << " ("
-            << pre_node_names.size() << ")";
+    VLOG(2) << "(logid=" << log_id << ") pre names[" << pi << "]: " << pre_name
+            << " (" << pre_node_names.size() << ")";
     input_blob = get_depend_argument<GeneralBlob>(pre_name);
     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;
     int batch_size = input_blob->GetBatchSize();
-    VLOG(2) << "input batch size: " << batch_size;
+    VLOG(2) << "(logid=" << log_id << ") input batch size: " << batch_size;
 
     ModelOutput *output = res->add_outputs();
     output->set_engine_name(
@@ -88,12 +92,13 @@ int GeneralTextResponseOp::inference() {
         // currently only response float tensor or lod_tensor
         tensor->set_elem_type(1);
         if (model_config->_is_lod_fetch[idx]) {
-          VLOG(2) << "out[" << idx << " is lod_tensor";
+          VLOG(2) << "(logid=" << log_id << ") out[" << idx << " is lod_tensor";
           tensor->add_shape(-1);
         } else {
-          VLOG(2) << "out[" << idx << "] is tensor";
+          VLOG(2) << "(logid=" << log_id << ") out[" << idx << "] is tensor";
           for (int k = 1; k < in->at(idx).shape.size(); ++k) {
-            VLOG(2) << "shape[" << k - 1 << "]: " << in->at(idx).shape[k];
+            VLOG(2) << "(logid=" << log_id << ") shape[" << k - 1
+                    << "]: " << in->at(idx).shape[k];
             tensor->add_shape(in->at(idx).shape[k]);
           }
         }
@@ -137,7 +142,8 @@ int GeneralTextResponseOp::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;
+      VLOG(2) << "(logid=" << log_id
+              << ") p size for input blob: " << input_blob->p_size;
       int profile_time_idx = -1;
       if (pi == 0) {
         profile_time_idx = 0;

core/general-server/proto/general_model_service.proto

@@ -37,6 +37,7 @@ message Request {
   repeated FeedInst insts = 1;
   repeated string fetch_var_names = 2;
   optional bool profile_server = 3 [ default = false ];
+  required uint64 log_id = 4 [ default = 0 ];
 };
 
 message Response {

core/general-server/proto/load_general_model_service.proto

@@ -21,6 +21,7 @@ option cc_generic_services = true;
 message RequestAndResponse {
   required int32 a = 1;
   required float b = 2;
+  required uint64 log_id = 3 [ default = 0 ];
 };
 
 service LoadGeneralModelService {

core/pdcodegen/src/pdcodegen.cpp

@@ -280,25 +280,29 @@ class PdsCodeGenerator : public CodeGenerator {
             "  baidu::rpc::ClosureGuard done_guard(done);\n"
             "  baidu::rpc::Controller* cntl = \n"
             "        static_cast<baidu::rpc::Controller*>(cntl_base);\n"
+            "  uint64_t log_id = request->log_id();\n"
+            "  cntl->set_log_id(log_id);\n"
             "  ::baidu::paddle_serving::predictor::InferService* svr = \n"
             "       "
             "::baidu::paddle_serving::predictor::InferServiceManager::instance("
             ").item(\"$service$\");\n"
             "  if (svr == NULL) {\n"
-            "    LOG(ERROR) << \"Not found service: $service$\";\n"
+            "    LOG(ERROR) << \"(logid=\" << log_id << \") Not found service: "
+            "$service$\";\n"
             "    cntl->SetFailed(404, \"Not found service: $service$\");\n"
             "    return ;\n"
             "  }\n"
-            "  LOG(INFO) << \" remote_side=\[\" << cntl->remote_side() << "  // NOLINT
-            "\"\]\";\n"
-            "  LOG(INFO) << \" local_side=\[\" << cntl->local_side() << "  // NOLINT
-            "\"\]\";\n"
-            "  LOG(INFO) << \" service_name=\[\" << \"$name$\" << \"\]\";\n"  // NOLINT
-            "  LOG(INFO) << \" log_id=\[\" << cntl->log_id() << \"\]\";\n"  // NOLINT
-            "  int err_code = svr->inference(request, response);\n"
+            "  LOG(INFO) << \"(logid=\" << log_id << \") remote_side=\[\" "  // NOLINT
+            "<< cntl->remote_side() << \"\]\";\n"
+            "  LOG(INFO) << \"(logid=\" << log_id << \") local_side=\[\" "  // NOLINT
+            "<< cntl->local_side() << \"\]\";\n"
+            "  LOG(INFO) << \"(logid=\" << log_id << \") service_name=\[\" "  // NOLINT
+            "<< \"$name$\" << \"\]\";\n"
+            "  int err_code = svr->inference(request, response, log_id);\n"
             "  if (err_code != 0) {\n"
             "    LOG(WARNING)\n"
-            "        << \"Failed call inferservice[$name$], name[$service$]\"\n"
+            "        << \"(logid=\" << log_id << \") Failed call "
+            "inferservice[$name$], name[$service$]\"\n"
             "        << \", error_code: \" << err_code;\n"
             "    cntl->SetFailed(err_code, \"InferService inference "
             "failed!\");\n"
@@ -306,7 +310,8 @@ class PdsCodeGenerator : public CodeGenerator {
             "  gettimeofday(&tv, NULL);\n"
             "  long end = tv.tv_sec * 1000000 + tv.tv_usec;\n"
             "  // flush notice log\n"
-            "  LOG(INFO) << \" tc=\[\" << (end - start) << \"\]\";\n",  // NOLINT
+            "  LOG(INFO) << \"(logid=\" << log_id << \") tc=\[\" << (end - "  // NOLINT
+            "start) << \"\]\";\n",  // NOLINT
             "name",
             class_name,
             "service",
@@ -317,26 +322,31 @@ class PdsCodeGenerator : public CodeGenerator {
             "  baidu::rpc::ClosureGuard done_guard(done);\n"
             "  baidu::rpc::Controller* cntl = \n"
             "        static_cast<baidu::rpc::Controller*>(cntl_base);\n"
+            "  uint64_t log_id = equest->log_id();\n"
+            "  cntl->set_log_id(log_id);\n"
             "  ::baidu::paddle_serving::predictor::InferService* svr = \n"
             "       "
             "::baidu::paddle_serving::predictor::InferServiceManager::instance("
             ").item(\"$service$\");\n"
             "  if (svr == NULL) {\n"
-            "    LOG(ERROR) << \"Not found service: $service$\";\n"
+            "    LOG(ERROR) << \"(logid=\" << log_id << \") Not found service: "
+            "$service$\";\n"
             "    cntl->SetFailed(404, \"Not found service: $service$\");\n"
             "    return ;\n"
             "  }\n"
-            "  LOG(INFO) << \" remote_side=\[\" << cntl->remote_side() << "  // NOLINT
-            "\"\]\";\n"
-            "  LOG(INFO) << \" local_side=\[\" << cntl->local_side() << "  // NOLINT
-            "\"\]\";\n"
-            "  LOG(INFO) << \" service_name=\[\" << \"$name$\" << \"\]\";\n"  // NOLINT
-            "  LOG(INFO) << \" log_id=\[\" << cntl->log_id() << \"\]\";\n"  // NOLINT
+            "  LOG(INFO) << \"(logid=\" << log_id << \") remote_side=\[\" "  // NOLINT
+            "<< cntl->remote_side() << \"\]\";\n"
+            "  LOG(INFO) << \"(logid=\" << log_id << \") local_side=\[\" "  // NOLINT
+            "<< cntl->local_side() << \"\]\";\n"
+            "  LOG(INFO) << \"(logid=\" << log_id << \") service_name=\[\" "  // NOLINT
+            "<< \"$name$\" << \"\]\";\n"
             "  butil::IOBufBuilder debug_os;\n"
-            "  int err_code = svr->inference(request, response, &debug_os);\n"
+            "  int err_code = svr->inference(request, response, log_id, "
+            "&debug_os);\n"
             "  if (err_code != 0) {\n"
             "    LOG(WARNING)\n"
-            "        << \"Failed call inferservice[$name$], name[$service$]\"\n"
+            "        << \"(logid=\" << log_id << \") Failed call "
+            "inferservice[$name$], name[$service$]\"\n"
             "        << \", error_code: \" << err_code;\n"
             "    cntl->SetFailed(err_code, \"InferService inference "
             "failed!\");\n"
@@ -345,9 +355,11 @@ class PdsCodeGenerator : public CodeGenerator {
             "  gettimeofday(&tv, NULL);\n"
             "  long end = tv.tv_sec * 1000000 + tv.tv_usec;\n"
             "  // flush notice log\n"
-            "  LOG(INFO) << \" tc=\[\" << (end - start) << \"\]\";\n"  // NOLINT
+            "  LOG(INFO) << \"(logid=\" << log_id << \") tc=\[\" << (end - "  // NOLINT
+            "start) << \"\]\";\n"
             "  LOG(INFO)\n"
-            "      << \"TC=[\" << (end - start) << \"] Received debug "
+            "      << \"(logid=\" << log_id << \") TC=[\" << (end - start) << "
+            "\"] Received debug "
             "request[log_id=\" << cntl->log_id()\n"
             "      << \"] from \" << cntl->remote_side()\n"
             "      << \" to \" << cntl->local_side();\n",
@@ -1011,25 +1023,31 @@ class PdsCodeGenerator : public CodeGenerator {
             "  brpc::ClosureGuard done_guard(done);\n"
             "  brpc::Controller* cntl = \n"
             "        static_cast<brpc::Controller*>(cntl_base);\n"
+            "  uint64_t log_id = request->log_id();\n"
+            "  cntl->set_log_id(log_id);\n"
             "  ::baidu::paddle_serving::predictor::InferService* svr = \n"
             "       "
             "::baidu::paddle_serving::predictor::InferServiceManager::instance("
             ").item(\"$service$\");\n"
             "  if (svr == NULL) {\n"
-            "    LOG(ERROR) << \"Not found service: $service$\";\n"
+            "    LOG(ERROR) << \"(logid=\" << log_id << \") Not found service: "
+            "$service$\";\n"
             "    cntl->SetFailed(404, \"Not found service: $service$\");\n"
             "    return ;\n"
             "  }\n"
-            "  LOG(INFO) << \" remote_side=\[\" << cntl->remote_side() << "  // NOLINT
+            "  LOG(INFO) << \"(logid=\" << log_id << \") "
+            "remote_side=\[\" << cntl->remote_side() << "  // NOLINT
             "\"\]\";\n"
-            "  LOG(INFO) << \" local_side=\[\" << cntl->local_side() << "  // NOLINT
+            "  LOG(INFO) << \"(logid=\" << log_id << \") "
+            "local_side=\[\" << cntl->local_side() << "  // NOLINT
             "\"\]\";\n"
-            "  LOG(INFO) << \" service_name=\[\" << \"$name$\" << \"\]\";\n"  // NOLINT
-            "  LOG(INFO) << \" log_id=\[\" << cntl->log_id() << \"\]\";\n"  // NOLINT
-            "  int err_code = svr->inference(request, response);\n"
+            "  LOG(INFO) << \"(logid=\" << log_id << \") "
+            "service_name=\[\" << \"$name$\" << \"\]\";\n"  // NOLINT
+            "  int err_code = svr->inference(request, response, log_id);\n"
             "  if (err_code != 0) {\n"
             "    LOG(WARNING)\n"
-            "        << \"Failed call inferservice[$name$], name[$service$]\"\n"
+            "        << \"(logid=\" << log_id << \") Failed call "
+            "inferservice[$name$], name[$service$]\"\n"
             "        << \", error_code: \" << err_code;\n"
             "    cntl->SetFailed(err_code, \"InferService inference "
             "failed!\");\n"
@@ -1037,7 +1055,8 @@ class PdsCodeGenerator : public CodeGenerator {
             "  gettimeofday(&tv, NULL);\n"
             "  long end = tv.tv_sec * 1000000 + tv.tv_usec;\n"
             "  // flush notice log\n"
-            "  LOG(INFO) << \" tc=\[\" << (end - start) << \"\]\";\n",  // NOLINT
+            "  LOG(INFO) << \"(logid=\" << log_id << \") tc=\[\" << (end - "  // NOLINT
+            "start) << \"\]\";\n",  // NOLINT
             "name",
             class_name,
             "service",
@@ -1048,26 +1067,31 @@ class PdsCodeGenerator : public CodeGenerator {
             "  brpc::ClosureGuard done_guard(done);\n"
             "  brpc::Controller* cntl = \n"
             "        static_cast<brpc::Controller*>(cntl_base);\n"
+            "  uint64_t log_id = request->log_id();\n"
+            "  cntl->set_log_id(log_id);\n"
             "  ::baidu::paddle_serving::predictor::InferService* svr = \n"
             "       "
             "::baidu::paddle_serving::predictor::InferServiceManager::instance("
             ").item(\"$service$\");\n"
             "  if (svr == NULL) {\n"
-            "    LOG(ERROR) << \"Not found service: $service$\";\n"
+            "    LOG(ERROR) << \"(logid=\" << log_id << \") Not found service: "
+            "$service$\";\n"
             "    cntl->SetFailed(404, \"Not found service: $service$\");\n"
             "    return ;\n"
             "  }\n"
-            "  LOG(INFO) << \" remote_side=\[\" << cntl->remote_side() << "  // NOLINT
-            "\"\]\";\n"
-            "  LOG(INFO) << \" local_side=\[\" << cntl->local_side() << "  // NOLINT
-            "\"\]\";\n"
-            "  LOG(INFO) << \" service_name=\[\" << \"$name$\" << \"\]\";\n"  // NOLINT
-            "  LOG(INFO) << \" log_id=\[\" << cntl->log_id() << \"\]\";\n"  // NOLINT
+            "  LOG(INFO) << \"(logid=\" << log_id << \") remote_side=\[\" "  // NOLINT
+            " << cntl->remote_side() << \"\]\";\n"
+            "  LOG(INFO) << \"(logid=\" << log_id << \") local_side=\[\" "  // NOLINT
+            "<< cntl->local_side() << \"\]\";\n"
+            "  LOG(INFO) << \"(logid=\" << log_id << \") service_name=\[\" "  // NOLINT
+            "<< \"$name$\" << \"\]\";\n"
             "  butil::IOBufBuilder debug_os;\n"
-            "  int err_code = svr->inference(request, response, &debug_os);\n"
+            "  int err_code = svr->inference(request, response, log_id, "
+            "&debug_os);\n"
             "  if (err_code != 0) {\n"
             "    LOG(WARNING)\n"
-            "        << \"Failed call inferservice[$name$], name[$service$]\"\n"
+            "        << \"(logid=\" << log_id << \") Failed call "
+            "inferservice[$name$], name[$service$]\"\n"
             "        << \", error_code: \" << err_code;\n"
             "    cntl->SetFailed(err_code, \"InferService inference "
             "failed!\");\n"
@@ -1076,9 +1100,11 @@ class PdsCodeGenerator : public CodeGenerator {
             "  gettimeofday(&tv, NULL);\n"
             "  long end = tv.tv_sec * 1000000 + tv.tv_usec;\n"
             "  // flush notice log\n"
-            "  LOG(INFO) << \" tc=\[\" << (end - start) << \"\]\";\n"  // NOLINT
+            "  LOG(INFO) << \"(logid=\" << log_id << \") tc=\[\" << (end - "  // NOLINT
+            "start) << \"\]\";\n"  // NOLINT
             "  LOG(INFO)\n"
-            "      << \"TC=[\" << (end - start) << \"] Received debug "
+            "      << \"(logid=\" << log_id << \") TC=[\" << (end - start) << "
+            "\"] Received debug "
             "request[log_id=\" << cntl->log_id()\n"
             "      << \"] from \" << cntl->remote_side()\n"
             "      << \" to \" << cntl->local_side();\n",

core/predictor/framework/channel.h

@@ -72,9 +72,10 @@ class Channel {
 
   const std::string& op() { return _op; }
 
-  int share_to_bus(Bus* bus) {
+  int share_to_bus(Bus* bus, const uint64_t log_id) {
     if (bus->regist(_op, this) != 0) {
-      LOG(ERROR) << "Failed regist channel[" << _op << "] to bus!";
+      LOG(ERROR) << "(logid=" << log_id << ") Failed regist channel[" << _op
+                 << "] to bus!";
       return -1;
     }
 

core/predictor/framework/dag.cpp

@@ -155,13 +155,11 @@ int Dag::init(const configure::Workflow& conf, const std::string& name) {
   }
 
   if (FLAGS_el_log_level == 16) {
-    LOG(INFO) << "DAG: " << _dag_name;
-    LOG(INFO) << ", Op Num: " << _index_nodes.size();
+    LOG(INFO) << "DAG: " << _dag_name << ", Op Num: " << _index_nodes.size();
     for (uint32_t nid = 0; nid < _index_nodes.size(); nid++) {
       DagNode* node = _index_nodes[nid];
-      LOG(INFO) << ", OP-" << node->id << "-" << node->name << "-"
-                << node->type;
-      LOG(INFO) << " depends: " << node->depends.size();
+      LOG(INFO) << "OP-" << node->id << "-" << node->name << "-" << node->type
+                << " depends: " << node->depends.size();
 
       boost::unordered_map<std::string, EdgeMode>::iterator it;
       for (it = node->depends.begin(); it != node->depends.end(); it++) {
@@ -214,8 +212,8 @@ int Dag::topo_sort() {
     }
   }
   for (int i = 0; i < in_degree.size(); ++i) {
-    LOG(INFO) << "(" << _index_nodes[i]->name << ") in_degree[" << i
-              << "]: " << in_degree[i];
+    VLOG(2) << "(" << _index_nodes[i]->name << ") in_degree[" << i
+            << "]: " << in_degree[i];
   }
   int sorted_num = 0;
   DagStage* stage = new (std::nothrow) DagStage();

core/predictor/framework/dag_view.cpp

@@ -26,7 +26,9 @@ namespace baidu {
 namespace paddle_serving {
 namespace predictor {
 
-int DagView::init(Dag* dag, const std::string& service_name) {
+int DagView::init(Dag* dag,
+                  const std::string& service_name,
+                  const uint64_t log_id) {
   _name = dag->name();
   _full_name = service_name + NAME_DELIMITER + dag->name();
   _bus = butil::get_object<Bus>();
@@ -36,17 +38,20 @@ int DagView::init(Dag* dag, const std::string& service_name) {
   for (uint32_t si = 0; si < stage_size; si++) {
     const DagStage* stage = dag->stage_by_index(si);
     if (stage == NULL) {
-      LOG(ERROR) << "Failed get stage by index:" << si;
+      LOG(ERROR) << "(logid=" << log_id << ") Failed get stage by index:" << si;
       return ERR_INTERNAL_FAILURE;
     }
     ViewStage* vstage = butil::get_object<ViewStage>();
     if (vstage == NULL) {
-      LOG(ERROR) << "Failed get vstage from object pool"
+      LOG(ERROR) << "(logid=" << log_id
+                 << ") Failed get vstage from object pool"
                  << "at:" << si;
       return ERR_MEM_ALLOC_FAILURE;
     }
-    VLOG(2) << "stage[" << si << "] name: " << stage->full_name;
-    VLOG(2) << "stage[" << si << "] node size: " << stage->nodes.size();
+    VLOG(2) << "(logid=" << log_id << ") stage[" << si
+            << "] name: " << stage->full_name;
+    VLOG(2) << "(logid=" << log_id << ") stage[" << si
+            << "] node size: " << stage->nodes.size();
     vstage->full_name = service_name + NAME_DELIMITER + stage->full_name;
     uint32_t node_size = stage->nodes.size();
     // create tls view node
@@ -54,31 +59,39 @@ int DagView::init(Dag* dag, const std::string& service_name) {
       DagNode* node = stage->nodes[ni];
       ViewNode* vnode = butil::get_object<ViewNode>();
       if (vnode == NULL) {
-        LOG(ERROR) << "Failed get vnode at:" << ni;
+        LOG(ERROR) << "(logid=" << log_id << ") Failed get vnode at:" << ni;
         return ERR_MEM_ALLOC_FAILURE;
       }
       // factory type
       Op* op = OpRepository::instance().get_op(node->type);
       if (op == NULL) {
-        LOG(ERROR) << "Failed get op with type:" << node->type;
+        LOG(ERROR) << "(logid=" << log_id
+                   << ") Failed get op with type:" << node->type;
         return ERR_INTERNAL_FAILURE;
       }
 
       // initialize a TLS op object
-      VLOG(2) << "dag view initialized: \n"
+      VLOG(2) << "(logid=" << log_id << ") dag view initialized: \n"
               << "node id: " << node->id << "\n"
               << "node name: " << node->name << "\n"
               << "node type: " << node->type;
-      if (op->init(_bus, dag, node->id, node->name, node->type, node->conf) !=
-          0) {
-        LOG(WARNING) << "Failed init op, type:" << node->type;
+      if (op->init(_bus,
+                   dag,
+                   node->id,
+                   node->name,
+                   node->type,
+                   node->conf,
+                   log_id) != 0) {
+        LOG(WARNING) << "(logid=" << log_id
+                     << ") Failed init op, type:" << node->type;
         return ERR_INTERNAL_FAILURE;
       }
 
       op->set_full_name(service_name + NAME_DELIMITER + node->full_name);
 
       // Set the name of the Op as the key of the matching engine.
-      VLOG(2) << "op->set_engine_name(" << node->name.c_str() << ")";
+      VLOG(2) << "(logid=" << log_id << ") op->set_engine_name("
+              << node->name.c_str() << ")";
       op->set_engine_name(node->name);
 
       vnode->conf = node;
@@ -88,7 +101,7 @@ int DagView::init(Dag* dag, const std::string& service_name) {
            it != vnode->conf->depends.end();
            ++it) {
         std::string pre_node_name = it->first;
-        VLOG(2) << "add op pre name: \n"
+        VLOG(2) << "(logid=" << log_id << ") add op pre name: \n"
                 << "current op name: " << vnode->op->op_name()
                 << ", previous op name: " << pre_node_name;
         vnode->op->add_pre_node_name(pre_node_name);
@@ -102,7 +115,7 @@ int DagView::init(Dag* dag, const std::string& service_name) {
     //<< " previous op name: "
     //<< _view[si - 1]->nodes.back()->op->op_name();
     // vstage->nodes.back()->op->set_pre_node_name(
-    //_view[si - 1]->nodes.back()->op->op_name());
+    // _view[si - 1]->nodes.back()->op->op_name());
     /*}*/
     _view.push_back(vstage);
   }
@@ -133,14 +146,15 @@ int DagView::deinit() {
   return ERR_OK;
 }
 
-int DagView::execute(butil::IOBufBuilder* debug_os) {
+int DagView::execute(const uint64_t log_id, butil::IOBufBuilder* debug_os) {
   uint32_t stage_size = _view.size();
   for (uint32_t si = 0; si < stage_size; si++) {
-    TRACEPRINTF("start to execute stage[%u]", si);
-    int errcode = execute_one_stage(_view[si], debug_os);
-    TRACEPRINTF("finish to execute stage[%u]", si);
+    TRACEPRINTF("(logid=%" PRIu64 ") start to execute stage[%u]", log_id, si);
+    int errcode = execute_one_stage(_view[si], log_id, debug_os);
+    TRACEPRINTF("(logid=%" PRIu64 ") finish to execute stage[%u]", log_id, si);
     if (errcode < 0) {
-      LOG(ERROR) << "failed execute stage[" << _view[si]->debug();
+      LOG(ERROR) << "(logid=" << log_id << ") Failed execute stage["
+                 << _view[si]->debug();
       return errcode;
     }
   }
@@ -151,29 +165,34 @@ int DagView::execute(butil::IOBufBuilder* debug_os) {
 // You can derive a subclass to implement this func.
 // ParallelDagView maybe the one you want.
 int DagView::execute_one_stage(ViewStage* vstage,
+                               const uint64_t log_id,
                                butil::IOBufBuilder* debug_os) {
   butil::Timer stage_time(butil::Timer::STARTED);
   uint32_t node_size = vstage->nodes.size();
-  VLOG(2) << "vstage->nodes.size(): " << node_size;
+  VLOG(2) << "(logid=" << log_id << ") vstage->nodes.size(): " << node_size;
   for (uint32_t ni = 0; ni < node_size; ni++) {
     ViewNode* vnode = vstage->nodes[ni];
     DagNode* conf = vnode->conf;
     Op* op = vnode->op;
-    TRACEPRINTF("start to execute op[%s]", op->name());
-    int errcode = op->process(debug_os != NULL);
-    TRACEPRINTF("finish to execute op[%s]", op->name());
+    TRACEPRINTF(
+        "(logid=%" PRIu64 ") start to execute op[%s]", log_id, op->name());
+    int errcode = op->process(log_id, debug_os != NULL);
+    TRACEPRINTF(
+        "(logid=%" PRIu64 ") finish to execute op[%s]", log_id, op->name());
     if (errcode < 0) {
-      LOG(ERROR) << "Execute failed, Op:" << op->debug_string();
+      LOG(ERROR) << "(logid=" << log_id
+                 << ") Execute failed, Op:" << op->debug_string();
       return errcode;
     }
 
     if (errcode > 0) {
-      LOG(INFO) << "Execute ignore, Op:" << op->debug_string();
+      LOG(INFO) << "(logid=" << log_id
+                << ") Execute ignore, Op:" << op->debug_string();
       continue;
     }
 
     if (debug_os) {
-      (*debug_os) << "{\"op_name\": \"" << op->name()
+      (*debug_os) << "(logid=" << log_id << ") {\"op_name\": \"" << op->name()
                   << "\", \"debug_str:\": \"" << op->debug_string()
                   << "\", \"time_info\": \"" << op->time_info() << "\"}";
     }
@@ -186,34 +205,34 @@ int DagView::execute_one_stage(ViewStage* vstage,
   return ERR_OK;
 }
 
-int DagView::set_request_channel(Channel& request) {
+int DagView::set_request_channel(Channel& request, const uint64_t log_id) {
   // Each workflow should get the very beginning
   // request (channel), and commit it to bus, for
   // the first stage ops consuming.
 
-  request.share_to_bus(_bus);
+  request.share_to_bus(_bus, log_id);
 
   return ERR_OK;
 }
 
-const Channel* DagView::get_response_channel() const {
+const Channel* DagView::get_response_channel(const uint64_t log_id) const {
   // Caller obtains response channel from bus, and
   // writes it to rpc response(protbuf/json)
   if (_view.size() < 1) {
-    LOG(ERROR) << "invalid empty view stage!";
+    LOG(ERROR) << "(logid=" << log_id << ") invalid empty view stage!";
     return NULL;
   }
 
   ViewStage* last_stage = _view[_view.size() - 1];
   if (last_stage->nodes.size() != 1 || last_stage->nodes[0] == NULL) {
-    LOG(ERROR) << "Invalid last stage, size[" << last_stage->nodes.size()
-               << "] != 1";
+    LOG(ERROR) << "(logid=" << log_id << ") Invalid last stage, size["
+               << last_stage->nodes.size() << "] != 1";
     return NULL;
   }
 
   Op* last_op = last_stage->nodes[0]->op;
   if (last_op == NULL) {
-    LOG(ERROR) << "Last op is NULL";
+    LOG(ERROR) << "(logid=" << log_id << ") Last op is NULL";
     return NULL;
   }
   return last_op->mutable_channel();

core/predictor/framework/dag_view.h

@@ -47,21 +47,22 @@ class DagView {
 
   ~DagView() {}
 
-  int init(Dag* dag, const std::string& service_name);
+  int init(Dag* dag, const std::string& service_name, const uint64_t log_id);
 
   int deinit();
 
-  int execute(butil::IOBufBuilder* debug_os);
+  int execute(const uint64_t log_id, butil::IOBufBuilder* debug_os);
 
   // The default execution strategy is in sequencing
   // You can derive a subclass to implement this func.
   // ParallelDagView maybe the one you want.
   virtual int execute_one_stage(ViewStage* vstage,
+                                const uint64_t log_id,
                                 butil::IOBufBuilder* debug_os);
 
-  int set_request_channel(Channel& request);  // NOLINT
+  int set_request_channel(Channel& request, const uint64_t log_id);  // NOLINT
 
-  const Channel* get_response_channel() const;
+  const Channel* get_response_channel(const uint64_t log_id) const;
 
   const std::string& name() const { return _name; }
 

core/predictor/framework/service.cpp

@@ -19,6 +19,7 @@
 #include <butil/time.h>  // butil::Timer
 #endif
 
+#include <inttypes.h>
 #include <list>
 #include <string>
 #include <vector>
@@ -135,50 +136,63 @@ const std::string& InferService::name() const { return _infer_service_format; }
 // ´®ÐÐÖ´ÐÐÿ¸öworkflow
 int InferService::inference(const google::protobuf::Message* request,
                             google::protobuf::Message* response,
+                            const uint64_t log_id,
                             butil::IOBufBuilder* debug_os) {
-  TRACEPRINTF("start to inference");
+  TRACEPRINTF("(logid=%" PRIu64 ") start to inference", log_id);
   // when funtion call begins, framework will reset
   // thread local variables&resources automatically.
   if (Resource::instance().thread_clear() != 0) {
-    LOG(ERROR) << "Failed thread clear whole resource";
+    LOG(ERROR) << "(logid=" << log_id << ") Failed thread clear whole resource";
     return ERR_INTERNAL_FAILURE;
   }
 
-  TRACEPRINTF("finish to thread clear");
+  TRACEPRINTF("(logid=%" PRIu64 ") finish to thread clear", log_id);
 
   if (_enable_map_request_to_workflow) {
-    LOG(INFO) << "enable map request == True";
-    std::vector<Workflow*>* workflows = _map_request_to_workflow(request);
+    VLOG(2) << "(logid=" << log_id << ") enable map request == True";
+    std::vector<Workflow*>* workflows =
+        _map_request_to_workflow(request, log_id);
     if (!workflows || workflows->size() == 0) {
-      LOG(ERROR) << "Failed to map request to workflow";
+      LOG(ERROR) << "(logid=" << log_id
+                 << ") Failed to map request to workflow";
       return ERR_INTERNAL_FAILURE;
     }
     size_t fsize = workflows->size();
     for (size_t fi = 0; fi < fsize; ++fi) {
       Workflow* workflow = (*workflows)[fi];
       if (workflow == NULL) {
-        LOG(ERROR) << "Failed to get valid workflow at: " << fi;
+        LOG(ERROR) << "(logid=" << log_id
+                   << ") Failed to get valid workflow at: " << fi;
         return ERR_INTERNAL_FAILURE;
       }
-      TRACEPRINTF("start to execute workflow[%s]", workflow->name().c_str());
-      int errcode = _execute_workflow(workflow, request, response, debug_os);
-      TRACEPRINTF("finish to execute workflow[%s]", workflow->name().c_str());
+      TRACEPRINTF("(logid=%" PRIu64 ") start to execute workflow[%s]",
+                  log_id,
+                  workflow->name().c_str());
+      int errcode =
+          _execute_workflow(workflow, request, response, log_id, debug_os);
+      TRACEPRINTF("(logid=%" PRIu64 ") finish to execute workflow[%s]",
+                  log_id,
+                  workflow->name().c_str());
       if (errcode < 0) {
-        LOG(ERROR) << "Failed execute workflow[" << workflow->name()
-                   << "] in:" << name();
+        LOG(ERROR) << "(logid=" << log_id << ") Failed execute workflow["
+                   << workflow->name() << "] in:" << name();
         return errcode;
       }
     }
   } else {
-    LOG(INFO) << "enable map request == False";
-    TRACEPRINTF("start to execute one workflow");
+    VLOG(2) << "(logid=" << log_id << ") enable map request == False";
+    TRACEPRINTF("(logid=%" PRIu64 ") start to execute one workflow", log_id);
     size_t fsize = _flows.size();
     for (size_t fi = 0; fi < fsize; ++fi) {
-      TRACEPRINTF("start to execute one workflow-%lu", fi);
-      int errcode = execute_one_workflow(fi, request, response, debug_os);
-      TRACEPRINTF("finish to execute one workflow-%lu", fi);
+      TRACEPRINTF(
+          "(logid=%" PRIu64 ") start to execute one workflow-%lu", log_id, fi);
+      int errcode =
+          execute_one_workflow(fi, request, response, log_id, debug_os);
+      TRACEPRINTF(
+          "(logid=%" PRIu64 ") finish to execute one workflow-%lu", log_id, fi);
       if (errcode < 0) {
-        LOG(ERROR) << "Failed execute 0-th workflow in:" << name();
+        LOG(ERROR) << "(logid=" << log_id
+                   << ") Failed execute 0-th workflow in:" << name();
         return errcode;
       }
     }
@@ -188,26 +202,30 @@ int InferService::inference(const google::protobuf::Message* request,
 
 int InferService::debug(const google::protobuf::Message* request,
                         google::protobuf::Message* response,
+                        const uint64_t log_id,
                         butil::IOBufBuilder* debug_os) {
-  return inference(request, response, debug_os);
+  return inference(request, response, log_id, debug_os);
 }
 
 int InferService::execute_one_workflow(uint32_t index,
                                        const google::protobuf::Message* request,
                                        google::protobuf::Message* response,
+                                       const uint64_t log_id,
                                        butil::IOBufBuilder* debug_os) {
   if (index >= _flows.size()) {
-    LOG(ERROR) << "Faield execute workflow, index: " << index
+    LOG(ERROR) << "(logid=" << log_id
+               << ") Faield execute workflow, index: " << index
                << " >= max:" << _flows.size();
     return ERR_OVERFLOW_FAILURE;
   }
   Workflow* workflow = _flows[index];
-  return _execute_workflow(workflow, request, response, debug_os);
+  return _execute_workflow(workflow, request, response, log_id, debug_os);
 }
 
 int InferService::_execute_workflow(Workflow* workflow,
                                     const google::protobuf::Message* request,
                                     google::protobuf::Message* response,
+                                    const uint64_t log_id,
                                     butil::IOBufBuilder* debug_os) {
   butil::Timer workflow_time(butil::Timer::STARTED);
   // create and submit beginer channel
@@ -215,54 +233,62 @@ int InferService::_execute_workflow(Workflow* workflow,
   req_channel.init(0, START_OP_NAME);
   req_channel = request;
 
-  DagView* dv = workflow->fetch_dag_view(full_name());
-  dv->set_request_channel(req_channel);
+  DagView* dv = workflow->fetch_dag_view(full_name(), log_id);
+  dv->set_request_channel(req_channel, log_id);
 
   // call actual inference interface
-  int errcode = dv->execute(debug_os);
+  int errcode = dv->execute(log_id, debug_os);
   if (errcode < 0) {
-    LOG(ERROR) << "Failed execute dag for workflow:" << workflow->name();
+    LOG(ERROR) << "(logid=" << log_id
+               << ") Failed execute dag for workflow:" << workflow->name();
     return errcode;
   }
 
-  TRACEPRINTF("finish to dv execute");
+  TRACEPRINTF("(logid=%" PRIu64 ") finish to dv execute", log_id);
   // create ender channel and copy
-  const Channel* res_channel = dv->get_response_channel();
+  const Channel* res_channel = dv->get_response_channel(log_id);
+  if (res_channel == NULL) {
+    LOG(ERROR) << "(logid=" << log_id << ") Failed get response channel";
+    return ERR_INTERNAL_FAILURE;
+  }
+
   if (!_merger || !_merger->merge(res_channel->message(), response)) {
-    LOG(ERROR) << "Failed merge channel res to response";
+    LOG(ERROR) << "(logid=" << log_id
+               << ") Failed merge channel res to response";
     return ERR_INTERNAL_FAILURE;
   }
-  TRACEPRINTF("finish to copy from");
+  TRACEPRINTF("(logid=%" PRIu64 ") finish to copy from", log_id);
 
   workflow_time.stop();
-  LOG(INFO) << "workflow total time: " << workflow_time.u_elapsed();
+  LOG(INFO) << "(logid=" << log_id
+            << ") workflow total time: " << workflow_time.u_elapsed();
   PredictorMetric::GetInstance()->update_latency_metric(
       WORKFLOW_METRIC_PREFIX + dv->full_name(), workflow_time.u_elapsed());
 
   // return tls data to object pool
   workflow->return_dag_view(dv);
-  TRACEPRINTF("finish to return dag view");
+  TRACEPRINTF("(logid=%" PRIu64 ") finish to return dag view", log_id);
   return ERR_OK;
 }
 
 std::vector<Workflow*>* InferService::_map_request_to_workflow(
-    const google::protobuf::Message* request) {
+    const google::protobuf::Message* request, const uint64_t log_id) {
   const google::protobuf::Descriptor* desc = request->GetDescriptor();
   const google::protobuf::FieldDescriptor* field =
       desc->FindFieldByName(_request_field_key);
   if (field == NULL) {
-    LOG(ERROR) << "No field[" << _request_field_key << "] in ["
-               << desc->full_name() << "].";
+    LOG(ERROR) << "(logid=" << log_id << ") No field[" << _request_field_key
+               << "] in [" << desc->full_name() << "].";
     return NULL;
   }
   if (field->is_repeated()) {
-    LOG(ERROR) << "field[" << desc->full_name() << "." << _request_field_key
-               << "] is repeated.";
+    LOG(ERROR) << "(logid=" << log_id << ") field[" << desc->full_name() << "."
+               << _request_field_key << "] is repeated.";
     return NULL;
   }
   if (field->cpp_type() != google::protobuf::FieldDescriptor::CPPTYPE_STRING) {
-    LOG(ERROR) << "field[" << desc->full_name() << "." << _request_field_key
-               << "] should be string";
+    LOG(ERROR) << "(logid=" << log_id << ") field[" << desc->full_name() << "."
+               << _request_field_key << "] should be string";
     return NULL;
   }
   const std::string& field_value =
@@ -270,7 +296,7 @@ std::vector<Workflow*>* InferService::_map_request_to_workflow(
   std::vector<Workflow*>* p_workflow =
       _request_to_workflow_map.seek(field_value);
   if (p_workflow == NULL) {
-    LOG(ERROR) << "cannot find key[" << field_value
+    LOG(ERROR) << "(logid=" << log_id << ") cannot find key[" << field_value
                << "] in _request_to_workflow_map";
     return NULL;
   }

core/predictor/framework/service.h

@@ -52,25 +52,29 @@ class InferService {
   // Execute each workflow serially
   virtual int inference(const google::protobuf::Message* request,
                         google::protobuf::Message* response,
+                        const uint64_t log_id,
                         butil::IOBufBuilder* debug_os = NULL);
 
   int debug(const google::protobuf::Message* request,
             google::protobuf::Message* response,
+            const uint64_t log_id,
             butil::IOBufBuilder* debug_os);
 
   int execute_one_workflow(uint32_t index,
                            const google::protobuf::Message* request,
                            google::protobuf::Message* response,
+                           const uint64_t log_id,
                            butil::IOBufBuilder* debug_os);
 
  private:
   int _execute_workflow(Workflow* workflow,
                         const google::protobuf::Message* request,
                         google::protobuf::Message* response,
+                        const uint64_t log_id,
                         butil::IOBufBuilder* debug_os);
 
   std::vector<Workflow*>* _map_request_to_workflow(
-      const google::protobuf::Message* request);
+      const google::protobuf::Message* request, const uint64_t log_id);
 
  private:
   std::vector<Workflow*> _flows;
@@ -88,6 +92,7 @@ class ParallelInferService : public InferService {
   // Execute workflows in parallel
   int inference(const google::protobuf::Message* request,
                 google::protobuf::Message* response,
+                const uint64_t log_id,
                 butil::IOBufBuilder* debug_os) {
     return 0;
   }

core/predictor/framework/workflow.cpp

@@ -32,21 +32,22 @@ int Workflow::init(const configure::Workflow& conf) {
   return 0;
 }
 
-DagView* Workflow::fetch_dag_view(const std::string& service_name) {
+DagView* Workflow::fetch_dag_view(const std::string& service_name,
+                                  const uint64_t log_id) {
   DagView* view = NULL;
   if (_type == "Sequence") {
     view = butil::get_object<DagView>();
   } else if (_type == "Parallel") {
     view = butil::get_object<ParallelDagView>();
   } else {
-    LOG(ERROR) << "Unknown dag type:" << _type << "!";
+    LOG(ERROR) << "(logid=" << log_id << ") Unknown dag type:" << _type << "!";
     return NULL;
   }
   if (view == NULL) {
-    LOG(ERROR) << "create dag view from pool failed!";
+    LOG(ERROR) << "(logid=" << log_id << ") create dag view from pool failed!";
     return NULL;
   }
-  view->init(&_dag, service_name);
+  view->init(&_dag, service_name, log_id);
   return view;
 }
 

core/predictor/framework/workflow.h

@@ -36,7 +36,8 @@ class Workflow {
   // different apps.
   int init(const configure::Workflow& conf);
 
-  DagView* fetch_dag_view(const std::string& service_name);
+  DagView* fetch_dag_view(const std::string& service_name,
+                          const uint64_t log_id);
 
   int deinit() { return 0; }
 

core/predictor/op/op.cpp

@@ -35,7 +35,8 @@ int Op::init(Bus* bus,
              uint32_t id,
              const std::string& name,
              const std::string& type,
-             void* conf) {
+             void* conf,
+             const uint64_t log_id) {
   _bus = bus;
   _dag = dag;
   _id = id;
@@ -45,7 +46,8 @@ int Op::init(Bus* bus,
 
   _timer = butil::get_object<TimerFlow>();
   if (!_timer) {
-    LOG(ERROR) << "Invalid timerflow in op:" << this->name();
+    LOG(ERROR) << "(logid=" << log_id
+               << ") Invalid timerflow in op:" << this->name();
     return -1;
   }
 
@@ -55,7 +57,8 @@ int Op::init(Bus* bus,
 
   Channel* channel = mutable_channel();
   if (channel == NULL) {
-    LOG(ERROR) << "Failed mutable channel in op: " << this->id() << ", "
+    LOG(ERROR) << "(logid=" << log_id
+               << ") Failed mutable channel in op: " << this->id() << ", "
                << this->name() << "!";
     return -1;
   }
@@ -96,18 +99,20 @@ int Op::check_time(const char* tag) {
   return 0;
 }
 
-int Op::process(bool debug) {
+int Op::process(const uint64_t log_id, bool debug) {
   butil::Timer op_time(butil::Timer::STARTED);
   if (debug && _timer) {
     _timer->start();
   }
   if (!_has_init) {
-    LOG(ERROR) << "Make sure op has been init before inference";
+    LOG(ERROR) << "(logid=" << log_id
+               << ") Make sure op has been init before inference";
     return ERR_INTERNAL_FAILURE;
   }
 
   if (_has_calc) {
-    LOG(INFO) << "Op: " << _name << " already processed before";
+    LOG(INFO) << "(logid=" << log_id << ") Op: " << _name
+              << " already processed before";
     return ERR_OK;
   }
 
@@ -143,7 +148,7 @@ int Op::process(bool debug) {
 
   // 3. share output to bus
   Channel* channel = mutable_channel();
-  channel->share_to_bus(_bus);
+  channel->share_to_bus(_bus, log_id);
 
   // 4. mark has calculated
   _has_calc = true;
@@ -156,7 +161,8 @@ int Op::process(bool debug) {
   op_time.stop();
   PredictorMetric::GetInstance()->update_latency_metric(
       OP_METRIC_PREFIX + full_name(), op_time.u_elapsed());
-  LOG(INFO) << " " << name() << "_time=[" << op_time.u_elapsed() << "]";
+  LOG(INFO) << "(logid=" << log_id << ") " << name() << "_time=["
+            << op_time.u_elapsed() << "]";
   return ERR_OK;
 }
 

core/predictor/op/op.h

@@ -113,13 +113,14 @@ class Op {
            uint32_t id,
            const std::string& name,
            const std::string& type,
-           void* conf);
+           void* conf,
+           const uint64_t log_id);
 
   int deinit();
 
   int check_time(const char* tag);
 
-  int process(bool debug);
+  int process(const uint64_t log_id, bool debug);
 
   std::string time_info();
 

core/sdk-cpp/proto/general_model_service.proto

@@ -37,6 +37,7 @@ message Request {
   repeated FeedInst insts = 1;
   repeated string fetch_var_names = 2;
   optional bool profile_server = 3 [ default = false ];
+  required uint64 log_id = 4 [ default = 0 ];
 };
 
 message Response {

doc/PIPELINE_SERVING.md

@@ -33,6 +33,7 @@ The graph execution engine consists of OPs and Channels, and the connected OPs s
 - The default function of a single OP is to access a single Paddle Serving Service based on the input Channel data and put the result into the output Channel.
 - OP supports user customization, including preprocess, process, postprocess functions that can be inherited and implemented by the user.
 - OP can set the number of concurrencies to increase the number of concurrencies processed.
+- OP can obtain data from multiple different RPC requests for Auto-Batching.
 - OP can be started by a thread or process.
 
 ### Channel Design
@@ -46,6 +47,7 @@ The graph execution engine consists of OPs and Channels, and the connected OPs s
 </center>
 
 
+
 ### Extreme Case Consideration
 
 - Request timeout
@@ -59,9 +61,9 @@ The graph execution engine consists of OPs and Channels, and the connected OPs s
 - Whether input buffers and output buffers in Channel will increase indefinitely
 
   - It will not increase indefinitely. The input to the entire graph execution engine is placed inside a Channel's internal queue, directly acting as a traffic control buffer queue for the entire service.
-  - For input buffer, adjust the number of concurrencies of OP1 and OP2 according to the amount of computation, so that the number of input buffers from each input OP is relatively balanced.
-  - For output buffer, you can use a similar process as input buffer, which adjusts the concurrency of OP3 and OP4 to control the buffer length of output buffer.
-  - Note: The length of the input buffer depends on the speed at which each item in the internal queue is ready, and the length of the output buffer depends on the speed at which downstream OPs obtain data from the output buffer.
+  - For input buffer, adjust the number of concurrencies of OP1 and OP2 according to the amount of computation, so that the number of input buffers from each input OP is relatively balanced. (The length of the input buffer depends on the speed at which each item in the internal queue is ready)
+  - For output buffer, you can use a similar process as input buffer, which adjusts the concurrency of OP3 and OP4 to control the buffer length of output buffer. (The length of the output buffer depends on the speed at which downstream OPs obtain data from the output buffer)
+  - The amount of data in the Channel will not exceed `worker_num` of gRPC, that is, it will not exceed the thread pool size.
 
 ## Detailed Design
 
@@ -79,31 +81,36 @@ def __init__(name=None,
              client_config=None,
              concurrency=1,
              timeout=-1,
-             retry=1)
+             retry=1,
+             batch_size=1,
+             auto_batching_timeout=None)
 ```
 
 The meaning of each parameter is as follows:
 
-|    Parameter     |                           Meaning                            |
-| :--------------: | :----------------------------------------------------------: |
-|       name       | (str) String used to identify the OP type, which must be globally unique. |
-|    input_ops     |     (list) A list of all previous OPs of the current Op.     |
-| server_endpoints | (list) List of endpoints for remote Paddle Serving Service. If this parameter is not set, the OP will not access the remote Paddle Serving Service, that is, the process operation will not be performed. |
-|    fetch_list    | (list) List of fetch variable names for remote Paddle Serving Service. |
-|  client_config   | (str) The path of the client configuration file corresponding to the Paddle Serving Service. |
-|   concurrency    |             (int) The number of concurrent OPs.              |
-|     timeout      | (int) The timeout time of the process operation, in seconds. If the value is less than zero, no timeout is considered. |
-|      retry       | (int) Timeout number of retries. When the value is 1, no retries are made. |
+|       Parameter       |                           Meaning                            |
+| :-------------------: | :----------------------------------------------------------: |
+|         name          | (str) String used to identify the OP type, which must be globally unique. |
+|       input_ops       |     (list) A list of all previous OPs of the current Op.     |
+|   server_endpoints    | (list) List of endpoints for remote Paddle Serving Service. If this parameter is not set, the OP will not access the remote Paddle Serving Service, that is, the process operation will not be performed. |
+|      fetch_list       | (list) List of fetch variable names for remote Paddle Serving Service. |
+|     client_config     | (str) The path of the client configuration file corresponding to the Paddle Serving Service. |
+|      concurrency      |             (int) The number of concurrent OPs.              |
+|        timeout        | (int) The timeout time of the process operation, in ms. If the value is less than zero, no timeout is considered. |
+|         retry         | (int) Timeout number of retries. When the value is 1, no retries are made. |
+|      batch_size       | (int) The expected batch_size of Auto-Batching, since building batches may time out, the actual batch_size may be less than the set value. |
+| auto_batching_timeout | (float) Timeout for building batches of Auto-Batching (the unit is ms). |
+
 
 #### 2. General OP Secondary Development Interface
 
-|             Interface or Variable              |                           Explain                            |
-| :--------------------------------------------: | :----------------------------------------------------------: |
-|       def preprocess(self, input_dicts)        | Process the data obtained from the channel, and the processed data will be used as the input of the **process** function. |
-|          def process(self, feed_dict)          | The RPC prediction process is based on the Paddle Serving Client, and the processed data will be used as the input of the **postprocess** function. |
-| def postprocess(self, input_dicts, fetch_dict) | After processing the prediction results, the processed data will be put into the subsequent Channel to be obtained by the subsequent OP. |
-|               def init_op(self)                |      Used to load resources (such as word dictionary).       |
-|              self.concurrency_idx              | Concurrency index of current thread / process (different kinds of OP are calculated separately). |
+|              Interface or Variable               |                           Explain                            |
+| :----------------------------------------------: | :----------------------------------------------------------: |
+|        def preprocess(self, input_dicts)         | Process the data obtained from the channel, and the processed data will be used as the input of the **process** function. (This function handles a **sample**) |
+| def process(self, feed_dict_list, typical_logid) | The RPC prediction process is based on the Paddle Serving Client, and the processed data will be used as the input of the **postprocess** function. (This function handles a **batch**) |
+|  def postprocess(self, input_dicts, fetch_dict)  | After processing the prediction results, the processed data will be put into the subsequent Channel to be obtained by the subsequent OP. (This function handles a **sample**) |
+|                def init_op(self)                 |      Used to load resources (such as word dictionary).       |
+|               self.concurrency_idx               | Concurrency index of current process(not thread) (different kinds of OP are calculated separately). |
 
 In a running cycle, OP will execute three operations: preprocess, process, and postprocess (when the `server_endpoints` parameter is not set, the process operation is not executed). Users can rewrite these three functions. The default implementation is as follows:
 
@@ -117,24 +124,28 @@ def preprocess(self, input_dicts):
   (_, input_dict), = input_dicts.items()
   return input_dict
 
-def process(self, feed_dict):
-  err, err_info = ChannelData.check_npdata(feed_dict)
+def process(self, feed_dict_list, typical_logid):
+  err, err_info = ChannelData.check_batch_npdata(feed_dict_list)
   if err != 0:
     raise NotImplementedError(
       "{} Please override preprocess func.".format(err_info))
   call_result = self.client.predict(
-    feed=feed_dict, fetch=self._fetch_names)
+    feed=feed_dict_list, fetch=self._fetch_names, log_id=typical_logid)
+  if isinstance(self.client, MultiLangClient):
+    if call_result is None or call_result["serving_status_code"] != 0:
+      return None
+    call_result.pop("serving_status_code")
   return call_result
 
 def postprocess(self, input_dicts, fetch_dict):
   return fetch_dict
 ```
 
-The parameter of **preprocess** is the data `input_dicts` in the previous Channel. This variable is a dictionary with the name of the previous OP as key and the output of the corresponding OP as value.
+The parameter of **preprocess** is the data `input_dicts` in the previous Channel. This variable (as a **sample**) is a dictionary with the name of the previous OP as key and the output of the corresponding OP as value.
 
-The parameter of **process** is the input variable `fetch_dict` (the return value of the preprocess function) of the Paddle Serving Client prediction interface. This variable is a dictionary with feed_name as the key and the data in the ndarray format as the value.
+The parameter of **process** is the input variable `fetch_dict_list` (a list of the return value of the preprocess function) of the Paddle Serving Client prediction interface. This variable (as a **batch**) is a list of dictionaries with feed_name as the key and the data in the ndarray format as the value. `typical_logid` is used as the logid that penetrates to PaddleServingService.
 
-The parameters of **postprocess** are `input_dicts` and `fetch_dict`. `input_dicts` is consistent with the parameter of preprocess, and `fetch_dict` is the return value of the process function (if process is not executed, this value is the return value of preprocess).
+The parameters of **postprocess** are `input_dicts` and `fetch_dict`. `input_dicts` is consistent with the parameter of preprocess, and `fetch_dict` (as a **sample**) is a sample of the return batch of the process function (if process is not executed, this value is the return value of preprocess).
 
 Users can also rewrite the **init_op** function to load some custom resources (such as word dictionary). The default implementation is as follows:
 
@@ -143,7 +154,7 @@ def init_op(self):
   pass
 ```
 
-It should be noted that in the threaded version of OP, each OP will only call this function once, so the loaded resources must be thread safe.
+It should be **noted** that in the threaded version of OP, each OP will only call this function once, so the loaded resources must be thread safe.
 
 #### 3. RequestOp Definition
 
@@ -248,6 +259,8 @@ dag:
     client_type: brpc  # Use brpc or grpc client. The default is brpc
     retry: 1  # The number of times DAG executor retries after failure. The default value is 1, that is, no retrying
     use_profile: false  # Whether to print the log on the server side. The default is false
+    tracer:
+        interval_s: 600 # Monitoring time interval of Tracer (in seconds). Do not start monitoring when the value is less than 1. The default value is -1
 ```
 
 
@@ -282,14 +295,8 @@ from paddle_serving_server.pipeline import PipelineServer
 from paddle_serving_server.pipeline.proto import pipeline_service_pb2
 from paddle_serving_server.pipeline.channel import ChannelDataEcode
 import numpy as np
-import logging
 from paddle_serving_app.reader import IMDBDataset
 
-logging.basicConfig(level=logging.DEBUG)
-
-_LOGGER = logging.getLogger()
-
-
 class ImdbRequestOp(RequestOp):
     def init_op(self):
         self.imdb_dataset = IMDBDataset()
@@ -390,15 +397,23 @@ dag:
     use_profile: true
 ```
 
-After the function is enabled, the server will print the corresponding log information to the standard output in the process of prediction. In order to show the time consumption of each stage more intuitively, scripts are provided for further analysis and processing of log files.
+After the function is enabled, the server will print the corresponding log information to the standard output in the process of prediction. In order to show the time consumption of each stage more intuitively, Analyst module is provided for further analysis and processing of log files.
 
-The output of the server is first saved to a file. Taking profile as an example, the script converts the time monitoring information in the log into JSON format and saves it to the trace file. The trace file can be visualized through the tracing function of Chrome browser.
+The output of the server is first saved to a file. Taking `profile.txt` as an example, the script converts the time monitoring information in the log into JSON format and saves it to the `trace` file. The `trace` file can be visualized through the tracing function of Chrome browser.
 
 ```shell
-python timeline_trace.py profile trace
+from paddle_serving_server.pipeline import Analyst
+import json
+import sys
+
+if __name__ == "__main__":
+    log_filename = "profile.txt"
+    trace_filename = "trace"
+    analyst = Analyst(log_filename)
+    analyst.save_trace(trace_filename)
 ```
 
-Specific operation: open Chrome browser, input in the address bar `chrome://tracing/` , jump to the tracing page, click the load button, open the saved trace file, and then visualize the time information of each stage of the prediction service.
+Specific operation: open Chrome browser, input in the address bar `chrome://tracing/` , jump to the tracing page, click the load button, open the saved `trace` file, and then visualize the time information of each stage of the prediction service.
 
 ### Output profile information on client side
 

doc/PIPELINE_SERVING_CN.md

@@ -6,6 +6,7 @@ Paddle Serving 通常用于单模型的一键部署，但端到端的深度学
 
 Paddle Serving 提供了用户友好的多模型组合服务编程框架，Pipeline Serving，旨在降低编程门槛，提高资源使用率（尤其是GPU设备），提升整体的预估效率。
 
+
 ## 整体架构设计
 
 Server端基于 gRPC 和图执行引擎构建，两者的关系如下图所示。
@@ -30,9 +31,10 @@ Server端基于 gRPC 和图执行引擎构建，两者的关系如下图所示
 
 ### OP的设计
 
-- 单个OP默认的功能是根据输入的 Channel 数据，访问一个 Paddle Serving 的单模型服务，并将结果存在输出的 Channel
+- 单个 OP 默认的功能是根据输入的 Channel 数据，访问一个 Paddle Serving 的单模型服务，并将结果存在输出的 Channel
 - 单个 OP 可以支持用户自定义，包括 preprocess，process，postprocess 三个函数都可以由用户继承和实现
 - 单个 OP 可以控制并发数，从而增加处理并发数
+- 单个 OP 可以获取多个不同 RPC 请求的数据，以实现 Auto-Batching
 - OP 可以由线程或进程启动
 
 ### Channel的设计
@@ -59,11 +61,9 @@ Server端基于 gRPC 和图执行引擎构建，两者的关系如下图所示
 - Channel 设计中的 input buffer 和 output buffer 是否会无限增加
 
   - 不会。整个图执行引擎的输入会放到一个 Channel 的 internal queue 里面，直接作为整个服务的流量控制缓冲队列
-  - 对于 input buffer，根据计算量的情况调整 OP1 和 OP2 的并发数，使得 input buffer 来自各个输入 OP 的数量相对平衡
-  - 对于 output buffer，可以采用和 input buffer 类似的处理方法，即调整 OP3 和 OP4 的并发数，使得 output buffer 的缓冲长度得到控制
-  - 注：input buffer 的长度取决于 internal queue 中每个 item 完全 ready 的速度，output buffer 的长度取决于下游 OP 从 output buffer 获取数据的速度
-
-## 详细设计
+  - 对于 input buffer，根据计算量的情况调整 OP1 和 OP2 的并发数，使得 input buffer 来自各个输入 OP 的数量相对平衡（input buffer 的长度取决于 internal queue 中每个 item 完全 ready 的速度）
+  - 对于 output buffer，可以采用和 input buffer 类似的处理方法，即调整 OP3 和 OP4 的并发数，使得 output buffer 的缓冲长度得到控制（output buffer 的长度取决于下游 OP 从 output buffer 获取数据的速度）
+  - 同时 Channel 中数据量不会超过 gRPC 的 `worker_num`，即线程池大小
 
 ### 用户接口设计
 
@@ -79,31 +79,36 @@ def __init__(name=None,
              client_config=None,
              concurrency=1,
              timeout=-1,
-             retry=1)
+             retry=1,
+             batch_size=1,
+             auto_batching_timeout=None)
 ```
 
 各参数含义如下
 
-|      参数名      |                             含义                             |
-| :--------------: | :----------------------------------------------------------: |
-|       name       |    （str）用于标识 OP 类型的字符串，该字段必须全局唯一。     |
-|    input_ops     |            （list）当前 OP 的所有前继 OP 的列表。            |
-| server_endpoints | （list）远程 Paddle Serving Service 的 endpoints 列表。如果不设置该参数，则不访问远程 Paddle Serving Service，即 不会执行 process 操作。 |
-|    fetch_list    |     （list）远程 Paddle Serving Service 的 fetch 列表。      |
-|  client_config   | （str）Paddle Serving Service 对应的 Client 端配置文件路径。 |
-|   concurrency    |                     （int）OP 的并发数。                     |
-|     timeout      | （int）process 操作的超时时间，单位为秒。若该值小于零，则视作不超时。 |
-|      retry       |       （int）超时重试次数。当该值为 1 时，不进行重试。       |
+|        参数名         |                             含义                             |
+| :-------------------: | :----------------------------------------------------------: |
+|         name          |    （str）用于标识 OP 类型的字符串，该字段必须全局唯一。     |
+|       input_ops       |            （list）当前 OP 的所有前继 OP 的列表。            |
+|   server_endpoints    | （list）远程 Paddle Serving Service 的 endpoints 列表。如果不设置该参数，则不访问远程 Paddle Serving Service，即 不会执行 process 操作。 |
+|      fetch_list       |     （list）远程 Paddle Serving Service 的 fetch 列表。      |
+|     client_config     | （str）Paddle Serving Service 对应的 Client 端配置文件路径。 |
+|      concurrency      |                     （int）OP 的并发数。                     |
+|        timeout        | （int）process 操作的超时时间，单位为毫秒。若该值小于零，则视作不超时。 |
+|         retry         |       （int）超时重试次数。当该值为 1 时，不进行重试。       |
+|      batch_size       | （int）进行 Auto-Batching 的期望 batch_size 大小，由于构建 batch 可能超时，实际 batch_size 可能小于设定值。 |
+| auto_batching_timeout | （float）进行 Auto-Batching 构建 batch 的超时时间，单位为毫秒。 |
+
 
 #### 2. 普通 OP二次开发接口
 
-|                   变量或接口                   |                             说明                             |
-| :--------------------------------------------: | :----------------------------------------------------------: |
-|       def preprocess(self, input_dicts)        | 对从 Channel 中获取的数据进行处理，处理完的数据将作为 **process** 函数的输入。 |
-|          def process(self, feed_dict)          | 基于 Paddle Serving Client 进行 RPC 预测，处理完的数据将作为 **postprocess** 函数的输入。 |
-| def postprocess(self, input_dicts, fetch_dict) | 处理预测结果，处理完的数据将被放入后继 Channel 中，以被后继 OP 获取。 |
-|               def init_op(self)                |                  用于加载资源（如字典等）。                  |
-|              self.concurrency_idx              |   当前线程（进程）的并发数索引（不同种类的 OP 单独计算）。   |
+|                    变量或接口                    |                             说明                             |
+| :----------------------------------------------: | :----------------------------------------------------------: |
+|        def preprocess(self, input_dicts)         | 对从 Channel 中获取的数据进行处理，处理完的数据将作为 **process** 函数的输入。（该函数对一个 **sample** 进行处理） |
+| def process(self, feed_dict_list, typical_logid) | 基于 Paddle Serving Client 进行 RPC 预测，处理完的数据将作为 **postprocess** 函数的输入。（该函数对一个 **batch** 进行处理） |
+|  def postprocess(self, input_dicts, fetch_dict)  | 处理预测结果，处理完的数据将被放入后继 Channel 中，以被后继 OP 获取。（该函数对一个 **sample** 进行处理） |
+|                def init_op(self)                 |                  用于加载资源（如字典等）。                  |
+|               self.concurrency_idx               |  当前进程（非线程）的并发数索引（不同种类的 OP 单独计算）。  |
 
 OP 在一个运行周期中会依次执行 preprocess，process，postprocess 三个操作（当不设置 `server_endpoints` 参数时，不执行 process 操作），用户可以对这三个函数进行重写，默认实现如下：
 
@@ -117,25 +122,28 @@ def preprocess(self, input_dicts):
   (_, input_dict), = input_dicts.items()
   return input_dict
 
-def process(self, feed_dict):
-  err, err_info = ChannelData.check_npdata(feed_dict)
+def process(self, feed_dict_list, typical_logid):
+  err, err_info = ChannelData.check_batch_npdata(feed_dict_list)
   if err != 0:
     raise NotImplementedError(
       "{} Please override preprocess func.".format(err_info))
   call_result = self.client.predict(
-    feed=feed_dict, fetch=self._fetch_names)
+    feed=feed_dict_list, fetch=self._fetch_names, log_id=typical_logid)
+  if isinstance(self.client, MultiLangClient):
+    if call_result is None or call_result["serving_status_code"] != 0:
+      return None
+    call_result.pop("serving_status_code")
   return call_result
 
 def postprocess(self, input_dicts, fetch_dict):
   return fetch_dict
 ```
 
+**preprocess** 的参数是前继 Channel 中的数据 `input_dicts`，该变量（作为一个 **sample**）是一个以前继 OP 的 name 为 Key，对应 OP 的输出为 Value 的字典。
 
-**preprocess** 的参数是前继 Channel 中的数据 `input_dicts`，该变量是一个以前继 OP 的 name 为 Key，对应 OP 的输出为 Value 的字典。
+**process** 的参数是 Paddle Serving Client 预测接口的输入变量 `fetch_dict_list`（preprocess 函数的返回值的列表），该变量（作为一个 **batch**）是一个列表，列表中的元素为以 feed_name 为 Key，对应 ndarray 格式的数据为 Value 的字典。`typical_logid` 作为向 PaddleServingService 穿透的 logid。
 
-**process** 的参数是 Paddle Serving Client 预测接口的输入变量 `fetch_dict`（preprocess 函数的返回值），该变量是一个以 feed_name 为 Key，对应 ndarray 格式的数据为 Value 的字典。
-
-**postprocess** 的参数是 `input_dicts` 和 `fetch_dict`，`input_dicts` 与 preprocess 的参数一致，`fetch_dict` 是 process 函数的返回值（如果没有执行 process ，则该值为 preprocess 的返回值）。
+**postprocess** 的参数是 `input_dicts` 和 `fetch_dict`，`input_dicts` 与 preprocess 的参数一致，`fetch_dict` （作为一个 **sample**）是 process 函数的返回 batch 中的一个 sample（如果没有执行 process ，则该值为 preprocess 的返回值）。
 
 用户还可以对 **init_op** 函数进行重写，已加载自定义的一些资源（比如字典等），默认实现如下：
 
@@ -144,7 +152,7 @@ def init_op(self):
   pass
 ```
 
-需要注意的是，在线程版 OP 中，每个 OP 只会调用一次该函数，故加载的资源必须要求是线程安全的。
+需要**注意**的是，在线程版 OP 中，每个 OP 只会调用一次该函数，故加载的资源必须要求是线程安全的。
 
 #### 3. RequestOp 定义
 
@@ -249,6 +257,8 @@ dag:
     client_type: brpc  # 使用 brpc 或 grpc client，默认为 brpc
     retry: 1  # DAG Executor 在失败后重试次数，默认为 1，即不重试
     use_profile: false  # 是否在 Server 端打印日志，默认为 false
+    tracer:
+        interval_s: 600 # Tracer 监控的时间间隔，单位为秒。当该值小于 1 时不启动监控，默认为 -1
 ```
 
 
@@ -283,14 +293,8 @@ from paddle_serving_server.pipeline import PipelineServer
 from paddle_serving_server.pipeline.proto import pipeline_service_pb2
 from paddle_serving_server.pipeline.channel import ChannelDataEcode
 import numpy as np
-import logging
 from paddle_serving_app.reader import IMDBDataset
 
-logging.basicConfig(level=logging.DEBUG)
-
-_LOGGER = logging.getLogger()
-
-
 class ImdbRequestOp(RequestOp):
     def init_op(self):
         self.imdb_dataset = IMDBDataset()
@@ -311,7 +315,6 @@ class CombineOp(Op):
     def preprocess(self, input_data):
         combined_prediction = 0
         for op_name, data in input_data.items():
-            _LOGGER.info("{}: {}".format(op_name, data["prediction"]))
             combined_prediction += data["prediction"]
         data = {"prediction": combined_prediction / 2}
         return data
@@ -391,15 +394,23 @@ dag:
     use_profile: true
 ```
 
-开启该功能后，Server 端在预测的过程中会将对应的日志信息打印到标准输出，为了更直观地展现各阶段的耗时，提供脚本对日志文件做进一步的分析处理。
+开启该功能后，Server 端在预测的过程中会将对应的日志信息打印到标准输出，为了更直观地展现各阶段的耗时，提供 Analyst 模块对日志文件做进一步的分析处理。
 
-使用时先将 Server 的输出保存到文件，以 profile 为例，脚本将日志中的时间打点信息转换成 json 格式保存到trace 文件，trace 文件可以通过 chrome 浏览器的 tracing 功能进行可视化。
+使用时先将 Server 的输出保存到文件，以 `profile.txt` 为例，脚本将日志中的时间打点信息转换成 json 格式保存到 `trace` 文件，`trace` 文件可以通过 chrome 浏览器的 tracing 功能进行可视化。
 
-```shell
-python timeline_trace.py profile trace
+```python
+from paddle_serving_server.pipeline import Analyst
+import json
+import sys
+
+if __name__ == "__main__":
+    log_filename = "profile.txt"
+    trace_filename = "trace"
+    analyst = Analyst(log_filename)
+    analyst.save_trace(trace_filename)
 ```
 
-具体操作：打开 chrome 浏览器，在地址栏输入 chrome://tracing/ ，跳转至 tracing 页面，点击 load 按钮，打开保存的 trace 文件，即可将预测服务的各阶段时间信息可视化。
+具体操作：打开 chrome 浏览器，在地址栏输入 `chrome://tracing/` ，跳转至 tracing 页面，点击 load 按钮，打开保存的 `trace` 文件，即可将预测服务的各阶段时间信息可视化。
 
 ### 在 Client 端输出 Profile 信息
 

java/src/main/java/io/paddle/serving/client/Client.java

@@ -192,14 +192,16 @@ public class Client {
 
     private InferenceRequest _packInferenceRequest(
             List<HashMap<String, INDArray>> feed_batch,
-            Iterable<String> fetch) throws IllegalArgumentException {
+            Iterable<String> fetch,
+            long log_id) throws IllegalArgumentException {
         List<String> feed_var_names = new ArrayList<String>();
         feed_var_names.addAll(feed_batch.get(0).keySet());
 
         InferenceRequest.Builder req_builder = InferenceRequest.newBuilder()
             .addAllFeedVarNames(feed_var_names)
             .addAllFetchVarNames(fetch)
-            .setIsPython(false);
+            .setIsPython(false)
+            .setLogId(log_id);
         for (HashMap<String, INDArray> feed_data: feed_batch) {
             FeedInst.Builder inst_builder = FeedInst.newBuilder();
             for (String name: feed_var_names) {
@@ -332,76 +334,151 @@ public class Client {
     public Map<String, INDArray> predict(
             HashMap<String, INDArray> feed,
             Iterable<String> fetch) {
-        return predict(feed, fetch, false);
+        return predict(feed, fetch, false, 0);
+    }
+
+    public Map<String, INDArray> predict(
+            HashMap<String, INDArray> feed,
+            Iterable<String> fetch,
+            long log_id) {
+        return predict(feed, fetch, false, log_id);
     }
 
     public Map<String, HashMap<String, INDArray>> ensemble_predict(
             HashMap<String, INDArray> feed,
             Iterable<String> fetch) {
-        return ensemble_predict(feed, fetch, false);
+        return ensemble_predict(feed, fetch, false, 0);
+    }
+
+    public Map<String, HashMap<String, INDArray>> ensemble_predict(
+            HashMap<String, INDArray> feed,
+            Iterable<String> fetch,
+            long log_id) {
+        return ensemble_predict(feed, fetch, false, log_id);
     }
 
     public PredictFuture asyn_predict(
             HashMap<String, INDArray> feed,
             Iterable<String> fetch) {
-        return asyn_predict(feed, fetch, false);
+        return asyn_predict(feed, fetch, false, 0);
+    }
+
+    public PredictFuture asyn_predict(
+            HashMap<String, INDArray> feed,
+            Iterable<String> fetch,
+            long log_id) {
+        return asyn_predict(feed, fetch, false, log_id);
     }
 
     public Map<String, INDArray> predict(
             HashMap<String, INDArray> feed,
             Iterable<String> fetch,
             Boolean need_variant_tag) {
+        return predict(feed, fetch, need_variant_tag, 0);
+    }
+
+    public Map<String, INDArray> predict(
+            HashMap<String, INDArray> feed,
+            Iterable<String> fetch,
+            Boolean need_variant_tag,
+            long log_id) {
         List<HashMap<String, INDArray>> feed_batch
             = new ArrayList<HashMap<String, INDArray>>();
         feed_batch.add(feed);
-        return predict(feed_batch, fetch, need_variant_tag);
+        return predict(feed_batch, fetch, need_variant_tag, log_id);
     }
-    
+
     public Map<String, HashMap<String, INDArray>> ensemble_predict(
             HashMap<String, INDArray> feed,
             Iterable<String> fetch,
             Boolean need_variant_tag) {
+        return ensemble_predict(feed, fetch, need_variant_tag, 0);
+    }
+    
+    public Map<String, HashMap<String, INDArray>> ensemble_predict(
+            HashMap<String, INDArray> feed,
+            Iterable<String> fetch,
+            Boolean need_variant_tag,
+            long log_id) {
         List<HashMap<String, INDArray>> feed_batch
             = new ArrayList<HashMap<String, INDArray>>();
         feed_batch.add(feed);
-        return ensemble_predict(feed_batch, fetch, need_variant_tag);
+        return ensemble_predict(feed_batch, fetch, need_variant_tag, log_id);
     }
 
     public PredictFuture asyn_predict(
             HashMap<String, INDArray> feed,
             Iterable<String> fetch,
             Boolean need_variant_tag) {
+        return asyn_predict(feed, fetch, need_variant_tag, 0);
+    }
+
+    public PredictFuture asyn_predict(
+            HashMap<String, INDArray> feed,
+            Iterable<String> fetch,
+            Boolean need_variant_tag,
+            long log_id) {
         List<HashMap<String, INDArray>> feed_batch
             = new ArrayList<HashMap<String, INDArray>>();
         feed_batch.add(feed);
-        return asyn_predict(feed_batch, fetch, need_variant_tag);
+        return asyn_predict(feed_batch, fetch, need_variant_tag, log_id);
     }
 
     public Map<String, INDArray> predict(
             List<HashMap<String, INDArray>> feed_batch,
             Iterable<String> fetch) {
-        return predict(feed_batch, fetch, false);
+        return predict(feed_batch, fetch, false, 0);
+    }
+
+    public Map<String, INDArray> predict(
+            List<HashMap<String, INDArray>> feed_batch,
+            Iterable<String> fetch,
+            long log_id) {
+        return predict(feed_batch, fetch, false, log_id);
     }
     
     public Map<String, HashMap<String, INDArray>> ensemble_predict(
             List<HashMap<String, INDArray>> feed_batch,
             Iterable<String> fetch) {
-        return ensemble_predict(feed_batch, fetch, false);
+        return ensemble_predict(feed_batch, fetch, false, 0);
+    }
+
+    public Map<String, HashMap<String, INDArray>> ensemble_predict(
+            List<HashMap<String, INDArray>> feed_batch,
+            Iterable<String> fetch,
+            long log_id) {
+        return ensemble_predict(feed_batch, fetch, false, log_id);
     }
 
     public PredictFuture asyn_predict(
             List<HashMap<String, INDArray>> feed_batch,
             Iterable<String> fetch) {
-        return asyn_predict(feed_batch, fetch, false);
+        return asyn_predict(feed_batch, fetch, false, 0);
+    }
+
+    public PredictFuture asyn_predict(
+            List<HashMap<String, INDArray>> feed_batch,
+            Iterable<String> fetch,
+            long log_id) {
+        return asyn_predict(feed_batch, fetch, false, log_id);
     }
 
     public Map<String, INDArray> predict(
             List<HashMap<String, INDArray>> feed_batch,
             Iterable<String> fetch,
             Boolean need_variant_tag) {
+        return predict(feed_batch, fetch, need_variant_tag, 0);        
+    }
+
+    public Map<String, INDArray> predict(
+            List<HashMap<String, INDArray>> feed_batch,
+            Iterable<String> fetch,
+            Boolean need_variant_tag,
+            long log_id) {
         try {
             profiler_.record("java_prepro_0");
-            InferenceRequest req = _packInferenceRequest(feed_batch, fetch);
+            InferenceRequest req = _packInferenceRequest(
+                    feed_batch, fetch, log_id);
             profiler_.record("java_prepro_1");
             
             profiler_.record("java_client_infer_0");
@@ -415,7 +492,7 @@ public class Client {
                 = new ArrayList<Map.Entry<String, HashMap<String, INDArray>>>(
                     ensemble_result.entrySet());
             if (list.size() != 1) {
-                System.out.format("predict failed: please use ensemble_predict impl.\n");
+                System.out.format("Failed to predict: please use ensemble_predict impl.\n");
                 return null;
             }
             profiler_.record("java_postpro_1");
@@ -423,7 +500,7 @@ public class Client {
 
             return list.get(0).getValue();
         } catch (StatusRuntimeException e) {
-            System.out.format("predict failed: %s\n", e.toString());
+            System.out.format("Failed to predict: %s\n", e.toString());
             return null;
         }
     }
@@ -432,9 +509,18 @@ public class Client {
             List<HashMap<String, INDArray>> feed_batch,
             Iterable<String> fetch,
             Boolean need_variant_tag) {
+        return ensemble_predict(feed_batch, fetch, need_variant_tag, 0);        
+    }
+     
+    public Map<String, HashMap<String, INDArray>> ensemble_predict(
+            List<HashMap<String, INDArray>> feed_batch,
+            Iterable<String> fetch,
+            Boolean need_variant_tag,
+            long log_id) {
         try {
             profiler_.record("java_prepro_0");
-            InferenceRequest req = _packInferenceRequest(feed_batch, fetch);
+            InferenceRequest req = _packInferenceRequest(
+                    feed_batch, fetch, log_id);
             profiler_.record("java_prepro_1");
             
             profiler_.record("java_client_infer_0");
@@ -449,7 +535,7 @@ public class Client {
 
             return ensemble_result;
         } catch (StatusRuntimeException e) {
-            System.out.format("predict failed: %s\n", e.toString());
+            System.out.format("Failed to predict: %s\n", e.toString());
             return null;
         }
     }
@@ -458,7 +544,16 @@ public class Client {
             List<HashMap<String, INDArray>> feed_batch,
             Iterable<String> fetch,
             Boolean need_variant_tag) {
-        InferenceRequest req = _packInferenceRequest(feed_batch, fetch);
+        return asyn_predict(feed_batch, fetch, need_variant_tag, 0);
+    }
+
+    public PredictFuture asyn_predict(
+            List<HashMap<String, INDArray>> feed_batch,
+            Iterable<String> fetch,
+            Boolean need_variant_tag,
+            long log_id) {
+        InferenceRequest req = _packInferenceRequest(
+                feed_batch, fetch, log_id);
         ListenableFuture<InferenceResponse> future = futureStub_.inference(req);
         PredictFuture predict_future = new PredictFuture(future, 
             (InferenceResponse resp) -> {

java/src/main/proto/multi_lang_general_model_service.proto

@@ -37,6 +37,7 @@ message InferenceRequest {
   repeated string feed_var_names = 2;
   repeated string fetch_var_names = 3;
   required bool is_python = 4 [ default = false ];
+  required uint64 log_id = 5 [ default = 0 ];
 };
 
 message InferenceResponse {

python/examples/pipeline/imdb_model_ensemble/config.yml

 port: 18080
-worker_num: 1
+worker_num: 4
 build_dag_each_worker: false
 dag:
-    is_thread_op: true
+    is_thread_op: false
     client_type: brpc
     retry: 1
     use_profile: false
+    tracer:
+        interval_s: 10

python/examples/pipeline/imdb_model_ensemble/test_pipeline_client.py

@@ -11,7 +11,7 @@
 # WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
 # See the License for the specific language governing permissions and
 # limitations under the License.
-from paddle_serving_client.pipeline import PipelineClient
+from paddle_serving_server.pipeline import PipelineClient
 import numpy as np
 
 client = PipelineClient()
@@ -20,12 +20,16 @@ client.connect(['127.0.0.1:18080'])
 words = 'i am very sad | 0'
 
 futures = []
-for i in range(100):
+for i in range(4):
     futures.append(
         client.predict(
-            feed_dict={"words": words}, fetch=["prediction"], asyn=True))
+            feed_dict={"words": words},
+            fetch=["prediction"],
+            asyn=True,
+            profile=False))
 
 for f in futures:
     res = f.result()
     if res["ecode"] != 0:
         print("predict failed: {}".format(res))
+    print(res)

python/examples/pipeline/imdb_model_ensemble/test_pipeline_server.py

@@ -12,18 +12,21 @@
 # See the License for the specific language governing permissions and
 # limitations under the License.
 # pylint: disable=doc-string-missing
-
 from paddle_serving_server.pipeline import Op, RequestOp, ResponseOp
 from paddle_serving_server.pipeline import PipelineServer
 from paddle_serving_server.pipeline.proto import pipeline_service_pb2
 from paddle_serving_server.pipeline.channel import ChannelDataEcode
 import numpy as np
-import logging
 from paddle_serving_app.reader import IMDBDataset
-
-logging.basicConfig(level=logging.DEBUG)
+import logging
 
 _LOGGER = logging.getLogger()
+user_handler = logging.StreamHandler()
+user_handler.setLevel(logging.INFO)
+user_handler.setFormatter(
+    logging.Formatter(
+        "%(levelname)s %(asctime)s [%(filename)s:%(lineno)d] %(message)s"))
+_LOGGER.addHandler(user_handler)
 
 
 class ImdbRequestOp(RequestOp):
@@ -76,7 +79,9 @@ bow_op = Op(name="bow",
             client_config="imdb_bow_client_conf/serving_client_conf.prototxt",
             concurrency=1,
             timeout=-1,
-            retry=1)
+            retry=1,
+            batch_size=3,
+            auto_batching_timeout=1000)
 cnn_op = Op(name="cnn",
             input_ops=[read_op],
             server_endpoints=["127.0.0.1:9292"],
@@ -84,13 +89,17 @@ cnn_op = Op(name="cnn",
             client_config="imdb_cnn_client_conf/serving_client_conf.prototxt",
             concurrency=1,
             timeout=-1,
-            retry=1)
+            retry=1,
+            batch_size=1,
+            auto_batching_timeout=None)
 combine_op = CombineOp(
     name="combine",
     input_ops=[bow_op, cnn_op],
-    concurrency=5,
+    concurrency=1,
     timeout=-1,
-    retry=1)
+    retry=1,
+    batch_size=2,
+    auto_batching_timeout=None)
 
 # fetch output of bow_op
 # response_op = ImdbResponseOp(input_ops=[bow_op])

python/paddle_serving_client/__init__.py

@@ -233,7 +233,7 @@ class Client(object):
             #    key))
             pass
 
-    def predict(self, feed=None, fetch=None, need_variant_tag=False):
+    def predict(self, feed=None, fetch=None, need_variant_tag=False, log_id=0):
         self.profile_.record('py_prepro_0')
 
         if feed is None or fetch is None:
@@ -319,12 +319,12 @@ class Client(object):
             res = self.client_handle_.numpy_predict(
                 float_slot_batch, float_feed_names, float_shape, int_slot_batch,
                 int_feed_names, int_shape, fetch_names, result_batch_handle,
-                self.pid)
+                self.pid, log_id)
         elif self.has_numpy_input == False:
             res = self.client_handle_.batch_predict(
                 float_slot_batch, float_feed_names, float_shape, int_slot_batch,
                 int_feed_names, int_shape, fetch_names, result_batch_handle,
-                self.pid)
+                self.pid, log_id)
         else:
             raise ValueError(
                 "Please make sure the inputs are all in list type or all in numpy.array type"
@@ -347,6 +347,11 @@ class Client(object):
                     result_map[name] = result_batch_handle.get_int64_by_name(
                         mi, name)
                     shape = result_batch_handle.get_shape(mi, name)
+                    if result_map[name].size == 0:
+                        raise ValueError(
+                            "Failed to fetch, maybe the type of [{}]"
+                            " is wrong, please check the model file".format(
+                                name))
                     result_map[name].shape = shape
                     if name in self.lod_tensor_set:
                         result_map["{}.lod".format(
@@ -354,6 +359,11 @@ class Client(object):
                 elif self.fetch_names_to_type_[name] == float32_type:
                     result_map[name] = result_batch_handle.get_float_by_name(
                         mi, name)
+                    if result_map[name].size == 0:
+                        raise ValueError(
+                            "Failed to fetch, maybe the type of [{}]"
+                            " is wrong, please check the model file".format(
+                                name))
                     shape = result_batch_handle.get_shape(mi, name)
                     result_map[name].shape = shape
                     if name in self.lod_tensor_set:
@@ -364,6 +374,11 @@ class Client(object):
                     # result_map[name] will be py::array(numpy array)
                     result_map[name] = result_batch_handle.get_int32_by_name(
                         mi, name)
+                    if result_map[name].size == 0:
+                        raise ValueError(
+                            "Failed to fetch, maybe the type of [{}]"
+                            " is wrong, please check the model file".format(
+                                name))
                     shape = result_batch_handle.get_shape(mi, name)
                     result_map[name].shape = shape
                     if name in self.lod_tensor_set:
@@ -466,10 +481,11 @@ class MultiLangClient(object):
             if var.is_lod_tensor:
                 self.lod_tensor_set_.add(var.alias_name)
 
-    def _pack_inference_request(self, feed, fetch, is_python):
+    def _pack_inference_request(self, feed, fetch, is_python, log_id):
         req = multi_lang_general_model_service_pb2.InferenceRequest()
         req.fetch_var_names.extend(fetch)
         req.is_python = is_python
+        req.log_id = log_id
         feed_batch = None
         if isinstance(feed, dict):
             feed_batch = [feed]
@@ -602,12 +618,13 @@ class MultiLangClient(object):
                 fetch,
                 need_variant_tag=False,
                 asyn=False,
-                is_python=True):
+                is_python=True,
+                log_id=0):
         if not asyn:
             try:
                 self.profile_.record('py_prepro_0')
                 req = self._pack_inference_request(
-                    feed, fetch, is_python=is_python)
+                    feed, fetch, is_python=is_python, log_id=log_id)
                 self.profile_.record('py_prepro_1')
 
                 self.profile_.record('py_client_infer_0')
@@ -626,7 +643,8 @@ class MultiLangClient(object):
             except grpc.RpcError as e:
                 return {"serving_status_code": e.code()}
         else:
-            req = self._pack_inference_request(feed, fetch, is_python=is_python)
+            req = self._pack_inference_request(
+                feed, fetch, is_python=is_python, log_id=log_id)
             call_future = self.stub_.Inference.future(
                 req, timeout=self.rpc_timeout_s_)
             return MultiLangPredictFuture(

python/paddle_serving_server/__init__.py

@@ -502,6 +502,7 @@ class MultiLangServerServiceServicer(multi_lang_general_model_service_pb2_grpc.
         feed_names = list(request.feed_var_names)
         fetch_names = list(request.fetch_var_names)
         is_python = request.is_python
+        log_id = request.log_id
         feed_batch = []
         for feed_inst in request.insts:
             feed_dict = {}
@@ -530,7 +531,7 @@ class MultiLangServerServiceServicer(multi_lang_general_model_service_pb2_grpc.
                 data.shape = list(feed_inst.tensor_array[idx].shape)
                 feed_dict[name] = data
             feed_batch.append(feed_dict)
-        return feed_batch, fetch_names, is_python
+        return feed_batch, fetch_names, is_python, log_id
 
     def _pack_inference_response(self, ret, fetch_names, is_python):
         resp = multi_lang_general_model_service_pb2.InferenceResponse()
@@ -583,10 +584,13 @@ class MultiLangServerServiceServicer(multi_lang_general_model_service_pb2_grpc.
         return resp
 
     def Inference(self, request, context):
-        feed_dict, fetch_names, is_python = self._unpack_inference_request(
-            request)
+        feed_dict, fetch_names, is_python, log_id = \
+                self._unpack_inference_request(request)
         ret = self.bclient_.predict(
-            feed=feed_dict, fetch=fetch_names, need_variant_tag=True)
+            feed=feed_dict,
+            fetch=fetch_names,
+            need_variant_tag=True,
+            log_id=log_id)
         return self._pack_inference_response(ret, fetch_names, is_python)
 
     def GetClientConfig(self, request, context):

python/paddle_serving_server_gpu/__init__.py

@@ -552,6 +552,7 @@ class MultiLangServerServiceServicer(multi_lang_general_model_service_pb2_grpc.
         feed_names = list(request.feed_var_names)
         fetch_names = list(request.fetch_var_names)
         is_python = request.is_python
+        log_id = request.log_id
         feed_batch = []
         for feed_inst in request.insts:
             feed_dict = {}
@@ -580,7 +581,7 @@ class MultiLangServerServiceServicer(multi_lang_general_model_service_pb2_grpc.
                 data.shape = list(feed_inst.tensor_array[idx].shape)
                 feed_dict[name] = data
             feed_batch.append(feed_dict)
-        return feed_batch, fetch_names, is_python
+        return feed_batch, fetch_names, is_python, log_id
 
     def _pack_inference_response(self, ret, fetch_names, is_python):
         resp = multi_lang_general_model_service_pb2.InferenceResponse()
@@ -633,10 +634,13 @@ class MultiLangServerServiceServicer(multi_lang_general_model_service_pb2_grpc.
         return resp
 
     def Inference(self, request, context):
-        feed_dict, fetch_names, is_python = self._unpack_inference_request(
-            request)
+        feed_dict, fetch_names, is_python, log_id \
+                = self._unpack_inference_request(request)
         ret = self.bclient_.predict(
-            feed=feed_dict, fetch=fetch_names, need_variant_tag=True)
+            feed=feed_dict,
+            fetch=fetch_names,
+            need_variant_tag=True,
+            log_id=log_id)
         return self._pack_inference_response(ret, fetch_names, is_python)
 
     def GetClientConfig(self, request, context):

python/pipeline/__init__.py

@@ -11,7 +11,7 @@
 # WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
 # See the License for the specific language governing permissions and
 # limitations under the License.
-
+import logger  # this module must be the first to import
 from operator import Op, RequestOp, ResponseOp
 from pipeline_server import PipelineServer
 from pipeline_client import PipelineClient

python/pipeline/analyse.py

@@ -17,7 +17,7 @@ import copy
 import re
 import logging
 
-_LOGGER = logging.getLogger()
+_LOGGER = logging.getLogger(__name__)
 
 
 class Analyst(object):
@@ -69,7 +69,7 @@ class Analyst(object):
         with open(self._profile_file) as f:
             for line in f.readlines():
                 line = line.strip().split("\t")
-                if line[0] == "PROFILE":
+                if line[0] == "PROFILE" and len(line) >= 3:
                     trace_list = self._prase_line(line[1], line[2], counter)
                     counter += 1
                     for trace in trace_list:
@@ -164,7 +164,7 @@ class OpAnalyst(object):
 
     def add(self, name_str, ts_list):
         if self._close:
-            _LOGGER.error("OpAnalyst is closed.")
+            _LOGGER.error("Failed to add item: OpAnalyst is closed.")
             return
         op_name, curr_idx, step = self._parse(name_str)
         if op_name not in self.op_time_list_dict:

python/pipeline/channel.py

@@ -12,6 +12,7 @@
 # See the License for the specific language governing permissions and
 # limitations under the License.
 # pylint: disable=doc-string-missing
+from time import time as _time
 import threading
 import multiprocessing
 import multiprocessing.queues
@@ -25,9 +26,10 @@ else:
 import numpy as np
 import logging
 import enum
+import os
 import copy
 
-_LOGGER = logging.getLogger()
+_LOGGER = logging.getLogger(__name__)
 
 
 class ChannelDataEcode(enum.Enum):
@@ -68,21 +70,25 @@ class ChannelData(object):
         '''
         if ecode is not None:
             if data_id is None or error_info is None:
-                raise ValueError("data_id and error_info cannot be None")
+                _LOGGER.critical("Failed to generate ChannelData: data_id"
+                                 " and error_info cannot be None")
+                os._exit(-1)
             datatype = ChannelDataType.ERROR.value
         else:
             if datatype == ChannelDataType.CHANNEL_NPDATA.value:
                 ecode, error_info = ChannelData.check_npdata(npdata)
                 if ecode != ChannelDataEcode.OK.value:
                     datatype = ChannelDataType.ERROR.value
-                    _LOGGER.error(error_info)
+                    _LOGGER.error("(logid={}) {}".format(data_id, error_info))
             elif datatype == ChannelDataType.DICT.value:
                 ecode, error_info = ChannelData.check_dictdata(dictdata)
                 if ecode != ChannelDataEcode.OK.value:
                     datatype = ChannelDataType.ERROR.value
-                    _LOGGER.error(error_info)
+                    _LOGGER.error("(logid={}) {}".format(data_id, error_info))
             else:
-                raise ValueError("datatype not match")
+                _LOGGER.critical("(logid={}) datatype not match".format(
+                    data_id))
+                os._exit(-1)
         self.datatype = datatype
         self.npdata = npdata
         self.dictdata = dictdata
@@ -106,14 +112,24 @@ class ChannelData(object):
             for sample in dictdata:
                 if not isinstance(sample, dict):
                     ecode = ChannelDataEcode.TYPE_ERROR.value
-                    error_info = "the value of data must " \
-                            "be dict, but get {}.".format(type(sample))
+                    error_info = "Failed to check data: the type of " \
+                            "data must be dict, but get {}.".format(type(sample))
                     break
         elif not isinstance(dictdata, dict):
             # batch size = 1
             ecode = ChannelDataEcode.TYPE_ERROR.value
-            error_info = "the value of data must " \
-                        "be dict, but get {}.".format(type(dictdata))
+            error_info = "Failed to check data: the type of data must " \
+                    "be dict, but get {}.".format(type(dictdata))
+        return ecode, error_info
+
+    @staticmethod
+    def check_batch_npdata(batch):
+        ecode = ChannelDataEcode.OK.value
+        error_info = None
+        for npdata in batch:
+            ecode, error_info = ChannelData.check_npdata(npdata)
+            if ecode != ChannelDataEcode.OK.value:
+                break
         return ecode, error_info
 
     @staticmethod
@@ -125,27 +141,30 @@ class ChannelData(object):
             for sample in npdata:
                 if not isinstance(sample, dict):
                     ecode = ChannelDataEcode.TYPE_ERROR.value
-                    error_info = "the value of data must " \
-                            "be dict, but get {}.".format(type(sample))
+                    error_info = "Failed to check data: the " \
+                            "value of data must be dict, but get {}.".format(
+                                    type(sample))
                     break
                 for _, value in sample.items():
                     if not isinstance(value, np.ndarray):
                         ecode = ChannelDataEcode.TYPE_ERROR.value
-                        error_info = "the value of data must " \
-                                "be np.ndarray, but get {}.".format(type(value))
+                        error_info = "Failed to check data: the" \
+                                " value of data must be np.ndarray, but get {}.".format(
+                                        type(value))
                         return ecode, error_info
         elif isinstance(npdata, dict):
             # batch_size = 1
             for _, value in npdata.items():
                 if not isinstance(value, np.ndarray):
                     ecode = ChannelDataEcode.TYPE_ERROR.value
-                    error_info = "the value of data must " \
-                            "be np.ndarray, but get {}.".format(type(value))
+                    error_info = "Failed to check data: the value " \
+                            "of data must be np.ndarray, but get {}.".format(
+                                    type(value))
                     break
         else:
             ecode = ChannelDataEcode.TYPE_ERROR.value
-            error_info = "the value of data must " \
-                    "be dict, but get {}.".format(type(npdata))
+            error_info = "Failed to check data: the value of data " \
+                    "must be dict, but get {}.".format(type(npdata))
         return ecode, error_info
 
     def parse(self):
@@ -157,9 +176,19 @@ class ChannelData(object):
             # return dict
             feed = self.dictdata
         else:
-            raise TypeError("Error type({}) in datatype.".format(self.datatype))
+            _LOGGER.critical("Failed to parse channeldata: error " \
+                    "type({}) in datatype.".format(self.datatype))
+            os._exit(-1)
         return feed
 
+    def __cmp__(self, other):
+        if self.id < other.id:
+            return -1
+        elif self.id == other.id:
+            return 0
+        else:
+            return 1
+
     def __str__(self):
         return "type[{}], ecode[{}], id[{}]".format(
             ChannelDataType(self.datatype).name, self.ecode, self.id)
@@ -175,7 +204,7 @@ class ProcessChannel(object):
         Only when all types of Ops get the data of the same ID,
         the data will be poped; The Op of the same type will not
         get the data of the same ID.
-    3. (TODO) Timeout and BatchSize are not fully supported.
+    3. Function front support timeout param to make auto-batching.
 
     Note:
     1. The ID of the data in the channel must be different.
@@ -194,16 +223,15 @@ class ProcessChannel(object):
         maintains the data obtained from queue.
     """
 
-    def __init__(self, manager, name=None, maxsize=0, timeout=None):
+    def __init__(self, manager, name=None, maxsize=0):
         # For queue multiprocess: after putting an object on 
         # an empty queue there may be an infinitessimal delay
         # before the queue's :meth:`~Queue.empty`
         # see more:
         # - https://bugs.python.org/issue18277
         # - https://hg.python.org/cpython/rev/860fc6a2bd21
-        self._que = manager.Queue(maxsize=maxsize)
+        self._que = manager.PriorityQueue(maxsize=maxsize)
         self._maxsize = maxsize
-        self._timeout = timeout
         self.name = name
         self._stop = manager.Value('i', 0)
 
@@ -219,6 +247,12 @@ class ProcessChannel(object):
         self._base_cursor = manager.Value('i', 0)
         self._output_buf = manager.list()
 
+    def get_maxsize(self):
+        return self._maxsize
+
+    def size(self):
+        return self._que.qsize()
+
     def get_producers(self):
         return self._producers
 
@@ -228,37 +262,41 @@ class ProcessChannel(object):
     def _log(self, info_str):
         return "[{}] {}".format(self.name, info_str)
 
-    def debug(self):
-        return self._log("p: {}, c: {}".format(self.get_producers(),
-                                               self.get_consumers()))
-
     def add_producer(self, op_name):
         """ not thread safe, and can only be called during initialization. """
         if op_name in self._producers:
-            raise ValueError(
-                self._log("producer({}) is already in channel".format(op_name)))
+            _LOGGER.critical(
+                self._log("Failed to add producer: producer({})" \
+                        " is already in channel".format(op_name)))
+            os._exit(-1)
         self._producers.append(op_name)
+        _LOGGER.debug(self._log("Succ add a producer: {}".format(op_name)))
 
     def add_consumer(self, op_name):
         """ not thread safe, and can only be called during initialization. """
         if op_name in self._consumer_cursors:
-            raise ValueError(
-                self._log("consumer({}) is already in channel".format(op_name)))
+            _LOGGER.critical(
+                    self._log("Failed to add consumer: consumer({})" \
+                            " is already in channel".format(op_name)))
+            os._exit(-1)
         self._consumer_cursors[op_name] = 0
 
         if self._cursor_count.get(0) is None:
             self._cursor_count[0] = 0
         self._cursor_count[0] += 1
+        _LOGGER.debug(self._log("Succ add a consumer: {}".format(op_name)))
 
     def push(self, channeldata, op_name=None):
         _LOGGER.debug(
-            self._log("{} try to push data: {}".format(op_name,
-                                                       channeldata.__str__())))
+            self._log("(logid={}) Op({}) Pushing data".format(channeldata.id,
+                                                              op_name)))
         if len(self._producers) == 0:
-            raise Exception(
+            _LOGGER.critical(
                 self._log(
-                    "expected number of producers to be greater than 0, but the it is 0."
-                ))
+                    "(logid={}) Op({}) Failed to push data: expected number"
+                    " of producers to be greater than 0, but the it is 0.".
+                    format(channeldata.id, op_name)))
+            os._exit(-1)
         elif len(self._producers) == 1:
             with self._cv:
                 while self._stop.value == 0:
@@ -269,23 +307,23 @@ class ProcessChannel(object):
                         self._cv.wait()
                 if self._stop.value == 1:
                     raise ChannelStopError()
-                _LOGGER.debug(
-                    self._log("{} channel size: {}".format(op_name,
-                                                           self._que.qsize())))
                 self._cv.notify_all()
-                _LOGGER.debug(self._log("{} notify all".format(op_name)))
-            _LOGGER.debug(self._log("{} push data succ!".format(op_name)))
+            _LOGGER.debug(
+                self._log("(logid={}) Op({}) Pushed data into internal queue.".
+                          format(channeldata.id, op_name)))
             return True
         elif op_name is None:
-            raise Exception(
+            _LOGGER.critical(
                 self._log(
-                    "There are multiple producers, so op_name cannot be None."))
+                    "(logid={}) Op({}) Failed to push data: there are multiple "
+                    "producers, so op_name cannot be None.".format(
+                        channeldata.id, op_name)))
+            os._exit(-1)
 
         producer_num = len(self._producers)
         data_id = channeldata.id
         put_data = None
         with self._cv:
-            _LOGGER.debug(self._log("{} get lock".format(op_name)))
             if data_id not in self._input_buf:
                 self._input_buf[data_id] = {
                     name: None
@@ -307,14 +345,12 @@ class ProcessChannel(object):
 
             if put_data is None:
                 _LOGGER.debug(
-                    self._log("{} push data succ, but not push to queue.".
-                              format(op_name)))
+                    self._log(
+                        "(logid={}) Op({}) Pushed data into input_buffer.".
+                        format(data_id, op_name)))
             else:
                 while self._stop.value == 0:
                     try:
-                        _LOGGER.debug(
-                            self._log("{} push data succ: {}".format(
-                                op_name, put_data.__str__())))
                         self._que.put(put_data, timeout=0)
                         break
                     except Queue.Empty:
@@ -323,43 +359,59 @@ class ProcessChannel(object):
                     raise ChannelStopError()
 
                 _LOGGER.debug(
-                    self._log("multi | {} push data succ!".format(op_name)))
+                    self._log(
+                        "(logid={}) Op({}) Pushed data into internal_queue.".
+                        format(data_id, op_name)))
             self._cv.notify_all()
         return True
 
-    def front(self, op_name=None):
-        _LOGGER.debug(self._log("{} try to get data...".format(op_name)))
+    def front(self, op_name=None, timeout=None):
+        _LOGGER.debug(
+            self._log("Op({}) Getting data[?]; timeout(s)={}".format(op_name,
+                                                                     timeout)))
+        endtime = None
+        if timeout is not None:
+            if timeout <= 0:
+                timeout = None
+            else:
+                endtime = _time() + timeout
+
         if len(self._consumer_cursors) == 0:
-            raise Exception(
+            _LOGGER.critical(
                 self._log(
-                    "expected number of consumers to be greater than 0, but the it is 0."
-                ))
+                    "Op({}) Failed to get data: expected number of consumers to be " \
+                            "greater than 0, but the it is 0.".format(op_name)))
+            os._exit(-1)
         elif len(self._consumer_cursors) == 1:
             resp = None
             with self._cv:
                 while self._stop.value == 0 and resp is None:
                     try:
-                        _LOGGER.debug(
-                            self._log("{} try to get(with channel empty: {})".
-                                      format(op_name, self._que.empty())))
                         resp = self._que.get(timeout=0)
                         break
                     except Queue.Empty:
-                        _LOGGER.debug(
-                            self._log(
-                                "{} wait for empty queue(with channel empty: {})".
-                                format(op_name, self._que.empty())))
-                        self._cv.wait()
+                        if timeout is not None:
+                            remaining = endtime - _time()
+                            if remaining <= 0.0:
+                                _LOGGER.debug(
+                                    self._log("Op({}) Failed to get data: "
+                                              "timeout".format(op_name)))
+                                raise ChannelTimeoutError()
+                            self._cv.wait(remaining)
+                        else:
+                            self._cv.wait()
                 if self._stop.value == 1:
                     raise ChannelStopError()
             _LOGGER.debug(
-                self._log("{} get data succ: {}".format(op_name, resp.__str__(
-                ))))
+                self._log("(logid={}) Op({}) Got data".format(resp.values()[0]
+                                                              .id, op_name)))
             return resp
         elif op_name is None:
-            raise Exception(
+            _LOGGER.critical(
                 self._log(
-                    "There are multiple consumers, so op_name cannot be None."))
+                    "Op({}) Failed to get data: there are multiple consumers, "
+                    "so op_name cannot be None.".format(op_name)))
+            os._exit(-1)
 
         # In output_buf, different Ops (according to op_name) have different
         # cursors. In addition, there is a base_cursor. Their difference is
@@ -376,24 +428,25 @@ class ProcessChannel(object):
             # it is necessary to obtain a data from queue and add it to output_buf.
             while self._stop.value == 0 and self._consumer_cursors[
                     op_name] - self._base_cursor.value >= len(self._output_buf):
-                _LOGGER.debug(
-                    self._log(
-                        "({}) B self._consumer_cursors: {}, self._base_cursor: {}, len(self._output_buf): {}".
-                        format(op_name, self._consumer_cursors,
-                               self._base_cursor.value, len(self._output_buf))))
                 try:
-                    _LOGGER.debug(
-                        self._log("{} try to get(with channel size: {})".format(
-                            op_name, self._que.qsize())))
                     channeldata = self._que.get(timeout=0)
                     self._output_buf.append(channeldata)
-                    break
-                except Queue.Empty:
                     _LOGGER.debug(
                         self._log(
-                            "{} wait for empty queue(with channel size: {})".
-                            format(op_name, self._que.qsize())))
-                    self._cv.wait()
+                            "(logid={}) Op({}) Pop ready item into output_buffer".
+                            format(channeldata.values()[0].id, op_name)))
+                    break
+                except Queue.Empty:
+                    if timeout is not None:
+                        remaining = endtime - _time()
+                        if remaining <= 0.0:
+                            _LOGGER.debug(
+                                self._log("Op({}) Failed to get data: timeout".
+                                          format(op_name)))
+                            raise ChannelTimeoutError()
+                        self._cv.wait(remaining)
+                    else:
+                        self._cv.wait()
             if self._stop.value == 1:
                 raise ChannelStopError()
 
@@ -401,7 +454,6 @@ class ProcessChannel(object):
             base_cursor = self._base_cursor.value
             data_idx = consumer_cursor - base_cursor
             resp = self._output_buf[data_idx]
-            _LOGGER.debug(self._log("{} get data: {}".format(op_name, resp)))
 
             self._cursor_count[consumer_cursor] -= 1
             if consumer_cursor == base_cursor and self._cursor_count[
@@ -413,6 +465,7 @@ class ProcessChannel(object):
                 self._base_cursor.value += 1
                 # to avoid cursor overflow
                 if self._base_cursor.value >= self._reset_max_cursor:
+                    _LOGGER.info(self._log("Reset cursor in Channel"))
                     self._base_cursor.value -= self._reset_max_cursor
                     for name in self._consumer_cursors.keys():
                         self._consumer_cursors[name] -= self._reset_max_cursor
@@ -430,25 +483,21 @@ class ProcessChannel(object):
                 self._cursor_count[new_consumer_cursor] = 0
             self._cursor_count[new_consumer_cursor] += 1
 
-            _LOGGER.debug(
-                self._log(
-                    "({}) A self._consumer_cursors: {}, self._base_cursor: {}, len(self._output_buf): {}".
-                    format(op_name, self._consumer_cursors,
-                           self._base_cursor.value, len(self._output_buf))))
-            _LOGGER.debug(self._log("{} notify all".format(op_name)))
             self._cv.notify_all()
 
-        _LOGGER.debug(self._log("multi | {} get data succ!".format(op_name)))
-        return resp  # reference, read only
+        _LOGGER.debug(
+            self._log("(logid={}) Op({}) Got data from output_buffer".format(
+                resp.values()[0].id, op_name)))
+        return resp
 
     def stop(self):
-        _LOGGER.debug(self._log("stop."))
+        _LOGGER.info(self._log("stop."))
         self._stop.value = 1
         with self._cv:
             self._cv.notify_all()
 
 
-class ThreadChannel(Queue.Queue):
+class ThreadChannel(Queue.PriorityQueue):
     """ 
     (Thread version)The channel used for communication between Ops.
 
@@ -458,7 +507,7 @@ class ThreadChannel(Queue.Queue):
         Only when all types of Ops get the data of the same ID,
         the data will be poped; The Op of the same type will not
         get the data of the same ID.
-    3. (TODO) Timeout and BatchSize are not fully supported.
+    3. Function front support timeout param to make auto-batching.
 
     Note:
     1. The ID of the data in the channel must be different.
@@ -477,10 +526,9 @@ class ThreadChannel(Queue.Queue):
         maintains the data obtained from queue.
     """
 
-    def __init__(self, name=None, maxsize=-1, timeout=None):
+    def __init__(self, name=None, maxsize=-1):
         Queue.Queue.__init__(self, maxsize=maxsize)
         self._maxsize = maxsize
-        self._timeout = timeout
         self.name = name
         self._stop = False
 
@@ -496,6 +544,12 @@ class ThreadChannel(Queue.Queue):
         self._base_cursor = 0
         self._output_buf = []
 
+    def get_maxsize(self):
+        return self._maxsize
+
+    def size(self):
+        return self.qsize()
+
     def get_producers(self):
         return self._producers
 
@@ -505,37 +559,41 @@ class ThreadChannel(Queue.Queue):
     def _log(self, info_str):
         return "[{}] {}".format(self.name, info_str)
 
-    def debug(self):
-        return self._log("p: {}, c: {}".format(self.get_producers(),
-                                               self.get_consumers()))
-
     def add_producer(self, op_name):
         """ not thread safe, and can only be called during initialization. """
         if op_name in self._producers:
-            raise ValueError(
-                self._log("producer({}) is already in channel".format(op_name)))
+            _LOGGER.critical(
+                self._log("Failed to add producer: producer({}) is "
+                          "already in channel".format(op_name)))
+            os._exit(-1)
         self._producers.append(op_name)
+        _LOGGER.debug(self._log("Succ add a producer: {}".format(op_name)))
 
     def add_consumer(self, op_name):
         """ not thread safe, and can only be called during initialization. """
         if op_name in self._consumer_cursors:
-            raise ValueError(
-                self._log("consumer({}) is already in channel".format(op_name)))
+            _LOGGER.critical(
+                self._log("Failed to add consumer: consumer({}) is "
+                          "already in channel".format(op_name)))
+            os._exit(-1)
         self._consumer_cursors[op_name] = 0
 
         if self._cursor_count.get(0) is None:
             self._cursor_count[0] = 0
         self._cursor_count[0] += 1
+        _LOGGER.debug(self._log("Succ add a consumer: {}".format(op_name)))
 
     def push(self, channeldata, op_name=None):
         _LOGGER.debug(
-            self._log("{} try to push data: {}".format(op_name,
-                                                       channeldata.__str__())))
+            self._log("(logid={}) Op({}) Pushing data".format(channeldata.id,
+                                                              op_name)))
         if len(self._producers) == 0:
-            raise Exception(
+            _LOGGER.critical(
                 self._log(
-                    "expected number of producers to be greater than 0, but the it is 0."
-                ))
+                    "(logid={}) Op({}) Failed to push data: expected number of "
+                    "producers to be greater than 0, but the it is 0.".format(
+                        channeldata.id, op_name)))
+            os._exit(-1)
         elif len(self._producers) == 1:
             with self._cv:
                 while self._stop is False:
@@ -547,18 +605,22 @@ class ThreadChannel(Queue.Queue):
                 if self._stop:
                     raise ChannelStopError()
                 self._cv.notify_all()
-            _LOGGER.debug(self._log("{} push data succ!".format(op_name)))
+            _LOGGER.debug(
+                self._log("(logid={}) Op({}) Pushed data into internal_queue.".
+                          format(channeldata.id, op_name)))
             return True
         elif op_name is None:
-            raise Exception(
+            _LOGGER.critical(
                 self._log(
-                    "There are multiple producers, so op_name cannot be None."))
+                    "(logid={}) Op({}) Failed to push data: there are multiple"
+                    " producers, so op_name cannot be None.".format(
+                        channeldata.id, op_name)))
+            os._exit(-1)
 
         producer_num = len(self._producers)
         data_id = channeldata.id
         put_data = None
         with self._cv:
-            _LOGGER.debug(self._log("{} get lock".format(op_name)))
             if data_id not in self._input_buf:
                 self._input_buf[data_id] = {
                     name: None
@@ -575,8 +637,9 @@ class ThreadChannel(Queue.Queue):
 
             if put_data is None:
                 _LOGGER.debug(
-                    self._log("{} push data succ, but not push to queue.".
-                              format(op_name)))
+                    self._log(
+                        "(logid={}) Op({}) Pushed data into input_buffer.".
+                        format(data_id, op_name)))
             else:
                 while self._stop is False:
                     try:
@@ -588,17 +651,29 @@ class ThreadChannel(Queue.Queue):
                     raise ChannelStopError()
 
                 _LOGGER.debug(
-                    self._log("multi | {} push data succ!".format(op_name)))
+                    self._log(
+                        "(logid={}) Op({}) Pushed data into internal_queue.".
+                        format(data_id, op_name)))
             self._cv.notify_all()
         return True
 
-    def front(self, op_name=None):
-        _LOGGER.debug(self._log("{} try to get data".format(op_name)))
+    def front(self, op_name=None, timeout=None):
+        _LOGGER.debug(
+            self._log("Op({}) Getting data[?]; timeout(s)={}".format(op_name,
+                                                                     timeout)))
+        endtime = None
+        if timeout is not None:
+            if timeout <= 0:
+                timeout = None
+            else:
+                endtime = _time() + timeout
+
         if len(self._consumer_cursors) == 0:
-            raise Exception(
+            _LOGGER.critical(
                 self._log(
-                    "expected number of consumers to be greater than 0, but the it is 0."
-                ))
+                    "Op({}) Failed to get data: expected number of consumers to be "
+                    "greater than 0, but the it is 0.".format(op_name)))
+            os._exit(-1)
         elif len(self._consumer_cursors) == 1:
             resp = None
             with self._cv:
@@ -607,17 +682,29 @@ class ThreadChannel(Queue.Queue):
                         resp = self.get(timeout=0)
                         break
                     except Queue.Empty:
-                        self._cv.wait()
+                        if timeout is not None:
+                            remaining = endtime - _time()
+                            if remaining <= 0.0:
+                                _LOGGER.debug(
+                                    self._log(
+                                        "Op({}) Failed to get data: timeout".
+                                        format(op_name)))
+                                raise ChannelTimeoutError()
+                            self._cv.wait(remaining)
+                        else:
+                            self._cv.wait()
                 if self._stop:
                     raise ChannelStopError()
             _LOGGER.debug(
-                self._log("{} get data succ: {}".format(op_name, resp.__str__(
-                ))))
+                self._log("(logid={}) Op({}) Got data".format(resp.values()[0]
+                                                              .id, op_name)))
             return resp
         elif op_name is None:
-            raise Exception(
-                self._log(
-                    "There are multiple consumers, so op_name cannot be None."))
+            _LOGGER.critical(
+                self._log("Op({}) Failed to get data: there are multiple "
+                          "consumers, so op_name cannot be None.".format(
+                              op_name)))
+            os._exit(-1)
 
         # In output_buf, different Ops (according to op_name) have different
         # cursors. In addition, there is a base_cursor. Their difference is
@@ -637,9 +724,22 @@ class ThreadChannel(Queue.Queue):
                 try:
                     channeldata = self.get(timeout=0)
                     self._output_buf.append(channeldata)
+                    _LOGGER.debug(
+                        self._log(
+                            "(logid={}) Op({}) Pop ready item into output_buffer".
+                            format(channeldata.values()[0].id, op_name)))
                     break
                 except Queue.Empty:
-                    self._cv.wait()
+                    if timeout is not None:
+                        remaining = endtime - _time()
+                        if remaining <= 0.0:
+                            _LOGGER.debug(
+                                self._log("Op({}) Failed to get data: timeout".
+                                          format(op_name)))
+                            raise ChannelTimeoutError()
+                        self._cv.wait(remaining)
+                    else:
+                        self._cv.wait()
             if self._stop:
                 raise ChannelStopError()
 
@@ -659,6 +759,7 @@ class ThreadChannel(Queue.Queue):
                 self._base_cursor += 1
                 # to avoid cursor overflow
                 if self._base_cursor >= self._reset_max_cursor:
+                    _LOGGER.info(self._log("Reset cursor in Channel"))
                     self._base_cursor -= self._reset_max_cursor
                     for name in self._consumer_cursors:
                         self._consumer_cursors[name] -= self._reset_max_cursor
@@ -668,7 +769,6 @@ class ThreadChannel(Queue.Queue):
                     }
             else:
                 resp = copy.deepcopy(self._output_buf[data_idx])
-            _LOGGER.debug(self._log("{} get data: {}".format(op_name, resp)))
 
             self._consumer_cursors[op_name] += 1
             new_consumer_cursor = self._consumer_cursors[op_name]
@@ -678,16 +778,23 @@ class ThreadChannel(Queue.Queue):
 
             self._cv.notify_all()
 
-        _LOGGER.debug(self._log("multi | {} get data succ!".format(op_name)))
+        _LOGGER.debug(
+            self._log("(logid={}) Op({}) Got data from output_buffer".format(
+                resp.values()[0].id, op_name)))
         return resp
 
     def stop(self):
-        _LOGGER.debug(self._log("stop."))
+        _LOGGER.info(self._log("stop."))
         self._stop = True
         with self._cv:
             self._cv.notify_all()
 
 
+class ChannelTimeoutError(RuntimeError):
+    def __init__(self):
+        pass
+
+
 class ChannelStopError(RuntimeError):
     def __init__(self):
         pass

python/pipeline/dag.py

@@ -24,42 +24,45 @@ else:
     raise Exception("Error Python version")
 import os
 import logging
+import collections
 
 from .operator import Op, RequestOp, ResponseOp, VirtualOp
 from .channel import (ThreadChannel, ProcessChannel, ChannelData,
                       ChannelDataEcode, ChannelDataType, ChannelStopError)
-from .profiler import TimeProfiler
-from .util import NameGenerator
+from .profiler import TimeProfiler, PerformanceTracer
+from .util import NameGenerator, ThreadIdGenerator, PipelineProcSyncManager
+from .proto import pipeline_service_pb2
 
-_LOGGER = logging.getLogger()
+_LOGGER = logging.getLogger(__name__)
 
 
 class DAGExecutor(object):
-    def __init__(self, response_op, dag_config, show_info):
-        self._retry = dag_config.get('retry', 1)
+    def __init__(self, response_op, server_conf, worker_idx):
+        build_dag_each_worker = server_conf["build_dag_each_worker"]
+        server_worker_num = server_conf["worker_num"]
+        dag_conf = server_conf["dag"]
 
-        client_type = dag_config.get('client_type', 'brpc')
-        self._server_use_profile = dag_config.get('use_profile', False)
-        channel_size = dag_config.get('channel_size', 0)
-        self._is_thread_op = dag_config.get('is_thread_op', True)
+        self._retry = dag_conf["retry"]
+        client_type = dag_conf["client_type"]
+        self._server_use_profile = dag_conf["use_profile"]
+        channel_size = dag_conf["channel_size"]
+        self._is_thread_op = dag_conf["is_thread_op"]
 
-        if show_info and self._server_use_profile:
-            _LOGGER.info("================= PROFILER ================")
-            if self._is_thread_op:
-                _LOGGER.info("op: thread")
-                _LOGGER.info("profile mode: sync")
-            else:
-                _LOGGER.info("op: process")
-                _LOGGER.info("profile mode: asyn")
-            _LOGGER.info("-------------------------------------------")
+        tracer_conf = dag_conf["tracer"]
+        tracer_interval_s = tracer_conf["interval_s"]
 
-        self.name = "@G"
+        self.name = "@DAGExecutor"
         self._profiler = TimeProfiler()
         self._profiler.enable(True)
 
+        self._tracer = None
+        if tracer_interval_s >= 1:
+            self._tracer = PerformanceTracer(
+                self._is_thread_op, tracer_interval_s, server_worker_num)
+
         self._dag = DAG(self.name, response_op, self._server_use_profile,
                         self._is_thread_op, client_type, channel_size,
-                        show_info)
+                        build_dag_each_worker, self._tracer)
         (in_channel, out_channel, pack_rpc_func,
          unpack_rpc_func) = self._dag.build()
         self._dag.start()
@@ -69,15 +72,23 @@ class DAGExecutor(object):
         self._pack_rpc_func = pack_rpc_func
         self._unpack_rpc_func = unpack_rpc_func
 
-        _LOGGER.debug(self._log(in_channel.debug()))
-        _LOGGER.debug(self._log(out_channel.debug()))
+        if self._tracer is not None:
+            self._tracer.start()
+
+        # generate id: data_id == request_id == log_id
+        base_counter = 0
+        gen_id_step = 1
+        if build_dag_each_worker:
+            base_counter = worker_idx
+            gen_id_step = server_worker_num
+        self._id_generator = ThreadIdGenerator(
+            max_id=1000000000000000000,
+            base_counter=base_counter,
+            step=gen_id_step)
 
-        self._id_lock = threading.Lock()
-        self._id_counter = 0
-        self._reset_max_id = 1000000000000000000
         self._cv_pool = {}
         self._cv_for_cv_pool = threading.Condition()
-        self._fetch_buffer = None
+        self._fetch_buffer = {}
         self._recive_func = None
 
         self._client_profile_key = "pipeline.profile"
@@ -86,32 +97,38 @@ class DAGExecutor(object):
     def start(self):
         self._recive_func = threading.Thread(
             target=DAGExecutor._recive_out_channel_func, args=(self, ))
+        self._recive_func.daemon = True
         self._recive_func.start()
+        _LOGGER.debug("[DAG Executor] Start recive thread")
 
     def stop(self):
         self._dag.stop()
         self._dag.join()
+        _LOGGER.info("[DAG Executor] Stop")
 
     def _get_next_data_id(self):
-        with self._id_lock:
-            if self._id_counter >= self._reset_max_id:
-                self._id_counter -= self._reset_max_id
-            self._id_counter += 1
-            return self._id_counter - 1
+        data_id = self._id_generator.next()
+        cond_v = threading.Condition()
+        with self._cv_for_cv_pool:
+            self._cv_pool[data_id] = cond_v
+            self._fetch_buffer[data_id] = None
+        return data_id, cond_v
 
     def _set_in_channel(self, in_channel):
         if not isinstance(in_channel, (ThreadChannel, ProcessChannel)):
-            raise TypeError(
-                self._log('in_channel must be Channel type, but get {}'.format(
-                    type(in_channel))))
+            _LOGGER.critical("[DAG Executor] Failed to set in_channel: "
+                             "in_channel must be Channel type, but get {}".
+                             format(type(in_channel)))
+            os._exit(-1)
         in_channel.add_producer(self.name)
         self._in_channel = in_channel
 
     def _set_out_channel(self, out_channel):
         if not isinstance(out_channel, (ThreadChannel, ProcessChannel)):
-            raise TypeError(
-                self._log('out_channel must be Channel type, but get {}'.format(
-                    type(out_channel))))
+            _LOGGER.critical("[DAG Executor] Failed to set out_channel: "
+                             "must be Channel type, but get {}".format(
+                                 type(out_channel)))
+            os._exit(-1)
         out_channel.add_consumer(self.name)
         self._out_channel = out_channel
 
@@ -121,7 +138,7 @@ class DAGExecutor(object):
             try:
                 channeldata_dict = self._out_channel.front(self.name)
             except ChannelStopError:
-                _LOGGER.debug(self._log("stop."))
+                _LOGGER.info("[DAG Executor] Stop.")
                 with self._cv_for_cv_pool:
                     for data_id, cv in self._cv_pool.items():
                         closed_errror_data = ChannelData(
@@ -129,46 +146,61 @@ class DAGExecutor(object):
                             error_info="dag closed.",
                             data_id=data_id)
                         with cv:
-                            self._fetch_buffer = closed_errror_data
+                            self._fetch_buffer[data_id] = closed_errror_data
                             cv.notify_all()
                 break
 
             if len(channeldata_dict) != 1:
-                _LOGGER.error("out_channel cannot have multiple input ops")
+                _LOGGER.critical(
+                    "[DAG Executor] Failed to fetch result: out_channel "
+                    "cannot have multiple input ops")
                 os._exit(-1)
             (_, channeldata), = channeldata_dict.items()
             if not isinstance(channeldata, ChannelData):
-                raise TypeError(
-                    self._log('data must be ChannelData type, but get {}'.
-                              format(type(channeldata))))
+                _LOGGER.critical(
+                    '[DAG Executor] Failed to fetch result: data in out_channel" \
+                    " must be ChannelData type, but get {}'
+                    .format(type(channeldata)))
+                os._exit(-1)
 
             data_id = channeldata.id
-            _LOGGER.debug("recive thread fetch data: {}".format(data_id))
+            _LOGGER.debug("(logid={}) [recive thread] Fetched data".format(
+                data_id))
             with self._cv_for_cv_pool:
-                cv = self._cv_pool[data_id]
-            with cv:
-                self._fetch_buffer = channeldata
-                cv.notify_all()
-
-    def _get_channeldata_from_fetch_buffer(self, data_id):
-        resp = None
-        cv = threading.Condition()
-        with self._cv_for_cv_pool:
-            self._cv_pool[data_id] = cv
-        with cv:
-            cv.wait()
-            _LOGGER.debug("resp func get lock (data_id: {})".format(data_id))
-            resp = copy.deepcopy(self._fetch_buffer)
-        with self._cv_for_cv_pool:
-            self._cv_pool.pop(data_id)
-        return resp
+                cond_v = self._cv_pool[data_id]
+            with cond_v:
+                self._fetch_buffer[data_id] = channeldata
+                cond_v.notify_all()
+
+    def _get_channeldata_from_fetch_buffer(self, data_id, cond_v):
+        ready_data = None
+
+        with cond_v:
+            with self._cv_for_cv_pool:
+                if self._fetch_buffer[data_id] is not None:
+                    # The requested data is already ready
+                    ready_data = self._fetch_buffer[data_id]
+                    self._cv_pool.pop(data_id)
+                    self._fetch_buffer.pop(data_id)
+            if ready_data is None:
+                # Wait for data ready
+                cond_v.wait()
+                with self._cv_for_cv_pool:
+                    ready_data = self._fetch_buffer[data_id]
+                    self._cv_pool.pop(data_id)
+                    self._fetch_buffer.pop(data_id)
+        _LOGGER.debug("(logid={}) [resp thread] Got data".format(data_id))
+        return ready_data
 
     def _pack_channeldata(self, rpc_request, data_id):
-        _LOGGER.debug(self._log('start inferce'))
         dictdata = None
         try:
             dictdata = self._unpack_rpc_func(rpc_request)
         except Exception as e:
+            _LOGGER.error(
+                "(logid={}) Failed to parse RPC request package: {}"
+                .format(data_id, e),
+                exc_info=True)
             return ChannelData(
                 ecode=ChannelDataEcode.RPC_PACKAGE_ERROR.value,
                 error_info="rpc package error: {}".format(e),
@@ -181,58 +213,86 @@ class DAGExecutor(object):
                 if key == self._client_profile_key:
                     profile_value = rpc_request.value[idx]
                     break
+            client_need_profile = (profile_value == self._client_profile_value)
+            _LOGGER.debug("(logid={}) Need profile in client: {}".format(
+                data_id, client_need_profile))
             return ChannelData(
                 datatype=ChannelDataType.DICT.value,
                 dictdata=dictdata,
                 data_id=data_id,
-                client_need_profile=(
-                    profile_value == self._client_profile_value))
+                client_need_profile=client_need_profile)
 
     def call(self, rpc_request):
-        data_id = self._get_next_data_id()
+        if self._tracer is not None:
+            trace_buffer = self._tracer.data_buffer()
+
+        data_id, cond_v = self._get_next_data_id()
+        _LOGGER.info("(logid={}) Succ generate id".format(data_id))
+
+        start_call, end_call = None, None
         if not self._is_thread_op:
-            self._profiler.record("call_{}#DAG-{}_0".format(data_id, data_id))
+            start_call = self._profiler.record("call_{}#DAG-{}_0".format(
+                data_id, data_id))
         else:
-            self._profiler.record("call_{}#DAG_0".format(data_id))
+            start_call = self._profiler.record("call_{}#DAG_0".format(data_id))
 
+        _LOGGER.debug("(logid={}) Parsing RPC request package".format(data_id))
         self._profiler.record("prepack_{}#{}_0".format(data_id, self.name))
         req_channeldata = self._pack_channeldata(rpc_request, data_id)
         self._profiler.record("prepack_{}#{}_1".format(data_id, self.name))
 
         resp_channeldata = None
         for i in range(self._retry):
-            _LOGGER.debug(self._log('push data'))
-            #self._profiler.record("push_{}#{}_0".format(data_id, self.name))
+            _LOGGER.debug("(logid={}) Pushing data into Graph engine".format(
+                data_id))
             try:
                 self._in_channel.push(req_channeldata, self.name)
             except ChannelStopError:
-                _LOGGER.debug(self._log("stop."))
+                _LOGGER.debug("[DAG Executor] Stop")
+                with self._cv_for_cv_pool:
+                    self._cv_pool.pop(data_id)
                 return self._pack_for_rpc_resp(
                     ChannelData(
                         ecode=ChannelDataEcode.CLOSED_ERROR.value,
                         error_info="dag closed.",
                         data_id=data_id))
-            #self._profiler.record("push_{}#{}_1".format(data_id, self.name))
 
-            _LOGGER.debug(self._log('wait for infer'))
-            #self._profiler.record("fetch_{}#{}_0".format(data_id, self.name))
-            resp_channeldata = self._get_channeldata_from_fetch_buffer(data_id)
-            #self._profiler.record("fetch_{}#{}_1".format(data_id, self.name))
+            _LOGGER.debug("(logid={}) Wait for Graph engine...".format(data_id))
+            resp_channeldata = self._get_channeldata_from_fetch_buffer(data_id,
+                                                                       cond_v)
 
             if resp_channeldata.ecode == ChannelDataEcode.OK.value:
+                _LOGGER.info("(logid={}) Succ predict".format(data_id))
                 break
+            else:
+                _LOGGER.error("(logid={}) Failed to predict: {}"
+                              .format(data_id, resp_channeldata.error_info))
+                if resp_channeldata.ecode != ChannelDataEcode.TIMEOUT.value:
+                    break
+
             if i + 1 < self._retry:
-                _LOGGER.warn("retry({}): {}".format(
-                    i + 1, resp_channeldata.error_info))
+                _LOGGER.warning("(logid={}) DAGExecutor retry({}/{})".format(
+                    data_id, i + 1, self._retry))
 
+        _LOGGER.debug("(logid={}) Packing RPC response package".format(data_id))
         self._profiler.record("postpack_{}#{}_0".format(data_id, self.name))
         rpc_resp = self._pack_for_rpc_resp(resp_channeldata)
         self._profiler.record("postpack_{}#{}_1".format(data_id, self.name))
         if not self._is_thread_op:
-            self._profiler.record("call_{}#DAG-{}_1".format(data_id, data_id))
+            end_call = self._profiler.record("call_{}#DAG-{}_1".format(data_id,
+                                                                       data_id))
         else:
-            self._profiler.record("call_{}#DAG_1".format(data_id))
-        #self._profiler.print_profile()
+            end_call = self._profiler.record("call_{}#DAG_1".format(data_id))
+
+        if self._tracer is not None:
+            trace_buffer.put({
+                "name": "DAG",
+                "id": data_id,
+                "succ": resp_channeldata.ecode == ChannelDataEcode.OK.value,
+                "actions": {
+                    "call_{}".format(data_id): end_call - start_call,
+                },
+            })
 
         profile_str = self._profiler.gen_profile_str()
         if self._server_use_profile:
@@ -250,25 +310,33 @@ class DAGExecutor(object):
         return rpc_resp
 
     def _pack_for_rpc_resp(self, channeldata):
-        _LOGGER.debug(self._log('get channeldata'))
-        return self._pack_rpc_func(channeldata)
-
-    def _log(self, info_str):
-        return "[{}] {}".format(self.name, info_str)
+        try:
+            return self._pack_rpc_func(channeldata)
+        except Exception as e:
+            _LOGGER.error(
+                "(logid={}) Failed to pack RPC response package: {}"
+                .format(channeldata.id, e),
+                exc_info=True)
+            resp = pipeline_service_pb2.Response()
+            resp.ecode = ChannelDataEcode.RPC_PACKAGE_ERROR.value
+            resp.error_info = "rpc package error: {}".format(e)
+            return resp
 
 
 class DAG(object):
     def __init__(self, request_name, response_op, use_profile, is_thread_op,
-                 client_type, channel_size, show_info):
+                 client_type, channel_size, build_dag_each_worker, tracer):
         self._request_name = request_name
         self._response_op = response_op
         self._use_profile = use_profile
         self._is_thread_op = is_thread_op
         self._channel_size = channel_size
         self._client_type = client_type
-        self._show_info = show_info
+        self._build_dag_each_worker = build_dag_each_worker
+        self._tracer = tracer
         if not self._is_thread_op:
-            self._manager = multiprocessing.Manager()
+            self._manager = PipelineProcSyncManager()
+        _LOGGER.info("[DAG] Succ init")
 
     def get_use_ops(self, response_op):
         unique_names = set()
@@ -288,8 +356,10 @@ class DAG(object):
                     used_ops.add(pred_op)
                     # check the name of op is globally unique
                     if pred_op.name in unique_names:
-                        raise Exception("the name of Op must be unique: {}".
-                                        format(pred_op.name))
+                        _LOGGER.critical("Failed to get used Ops: the"
+                                         " name of Op must be unique: {}".
+                                         format(pred_op.name))
+                        os._exit(-1)
                     unique_names.add(pred_op.name)
         return used_ops, succ_ops_of_use_op
 
@@ -301,10 +371,13 @@ class DAG(object):
         else:
             channel = ProcessChannel(
                 self._manager, name=name_gen.next(), maxsize=self._channel_size)
+        _LOGGER.debug("[DAG] Generate channel: {}".format(channel.name))
         return channel
 
     def _gen_virtual_op(self, name_gen):
-        return VirtualOp(name=name_gen.next())
+        vir_op = VirtualOp(name=name_gen.next())
+        _LOGGER.debug("[DAG] Generate virtual_op: {}".format(vir_op.name))
+        return vir_op
 
     def _topo_sort(self, used_ops, response_op, out_degree_ops):
         out_degree_num = {
@@ -318,7 +391,9 @@ class DAG(object):
             if len(op.get_input_ops()) == 0:
                 zero_indegree_num += 1
         if zero_indegree_num != 1:
-            raise Exception("DAG contains multiple input Ops")
+            _LOGGER.critical("Failed to topo sort: DAG contains "
+                             "multiple RequestOps")
+            os._exit(-1)
         last_op = response_op.get_input_ops()[0]
         ques[que_idx].put(last_op)
 
@@ -342,37 +417,47 @@ class DAG(object):
                 break
             que_idx = (que_idx + 1) % 2
         if sorted_op_num < len(used_ops):
-            raise Exception("not legal DAG")
+            _LOGGER.critical("Failed to topo sort: not legal DAG")
+            os._exit(-1)
 
         return dag_views, last_op
 
     def _build_dag(self, response_op):
         if response_op is None:
-            raise Exception("response_op has not been set.")
+            _LOGGER.critical("Failed to build DAG: ResponseOp"
+                             " has not been set.")
+            os._exit(-1)
         used_ops, out_degree_ops = self.get_use_ops(response_op)
-        if self._show_info:
+        if not self._build_dag_each_worker:
             _LOGGER.info("================= USED OP =================")
             for op in used_ops:
                 if op.name != self._request_name:
                     _LOGGER.info(op.name)
             _LOGGER.info("-------------------------------------------")
         if len(used_ops) <= 1:
-            raise Exception(
-                "Besides RequestOp and ResponseOp, there should be at least one Op in DAG."
-            )
+            _LOGGER.critical(
+                "Failed to build DAG: besides RequestOp and ResponseOp, "
+                "there should be at least one Op in DAG.")
+            os._exit(-1)
+        if self._build_dag_each_worker:
+            _LOGGER.info("Because `build_dag_each_worker` mode is used, "
+                         "Auto-batching is set to the default config: "
+                         "batch_size=1, auto_batching_timeout=None")
+            for op in used_ops:
+                op.use_default_auto_batching_config()
 
         dag_views, last_op = self._topo_sort(used_ops, response_op,
                                              out_degree_ops)
         dag_views = list(reversed(dag_views))
-        if self._show_info:
-            _LOGGER.info("================== DAG ====================")
+        if not self._build_dag_each_worker:
+            _LOGGER.debug("================== DAG ====================")
             for idx, view in enumerate(dag_views):
-                _LOGGER.info("(VIEW {})".format(idx))
+                _LOGGER.debug("(VIEW {})".format(idx))
                 for op in view:
-                    _LOGGER.info("  [{}]".format(op.name))
+                    _LOGGER.debug("  [{}]".format(op.name))
                     for out_op in out_degree_ops[op.name]:
-                        _LOGGER.info("    - {}".format(out_op.name))
-            _LOGGER.info("-------------------------------------------")
+                        _LOGGER.debug("    - {}".format(out_op.name))
+            _LOGGER.debug("-------------------------------------------")
 
         # create channels and virtual ops
         virtual_op_name_gen = NameGenerator("vir")
@@ -414,7 +499,6 @@ class DAG(object):
                     continue
                 channel = self._gen_channel(channel_name_gen)
                 channels.append(channel)
-                _LOGGER.debug("{} => {}".format(channel.name, op.name))
                 op.add_input_channel(channel)
                 pred_ops = pred_op_of_next_view_op[op.name]
                 if v_idx == 0:
@@ -422,8 +506,6 @@ class DAG(object):
                 else:
                     # if pred_op is virtual op, it will use ancestors as producers to channel
                     for pred_op in pred_ops:
-                        _LOGGER.debug("{} => {}".format(pred_op.name,
-                                                        channel.name))
                         pred_op.add_output_channel(channel)
                 processed_op.add(op.name)
                 # find same input op to combine channel
@@ -439,8 +521,6 @@ class DAG(object):
                             same_flag = False
                             break
                     if same_flag:
-                        _LOGGER.debug("{} => {}".format(channel.name,
-                                                        other_op.name))
                         other_op.add_input_channel(channel)
                         processed_op.add(other_op.name)
         output_channel = self._gen_channel(channel_name_gen)
@@ -458,14 +538,19 @@ class DAG(object):
             actual_ops.append(op)
 
         for c in channels:
-            _LOGGER.debug(c.debug())
+            _LOGGER.debug("Channel({}):\n\t- producers: {}\n\t- consumers: {}"
+                          .format(c.name, c.get_producers(), c.get_consumers()))
 
         return (actual_ops, channels, input_channel, output_channel, pack_func,
                 unpack_func)
 
+    def get_channels(self):
+        return self._channels
+
     def build(self):
         (actual_ops, channels, input_channel, output_channel, pack_func,
          unpack_func) = self._build_dag(self._response_op)
+        _LOGGER.info("[DAG] Succ build DAG")
 
         self._actual_ops = actual_ops
         self._channels = channels
@@ -474,18 +559,24 @@ class DAG(object):
         self._pack_func = pack_func
         self._unpack_func = unpack_func
 
+        if self._tracer is not None:
+            self._tracer.set_channels(self._channels)
+
         return self._input_channel, self._output_channel, self._pack_func, self._unpack_func
 
     def start(self):
         self._threads_or_proces = []
         for op in self._actual_ops:
             op.use_profiler(self._use_profile)
+            op.set_tracer(self._tracer)
             if self._is_thread_op:
                 self._threads_or_proces.extend(
                     op.start_with_thread(self._client_type))
             else:
                 self._threads_or_proces.extend(
                     op.start_with_process(self._client_type))
+        _LOGGER.info("[DAG] start")
+
         # not join yet
         return self._threads_or_proces
 

python/pipeline/logger.py

+# Copyright (c) 2020 PaddlePaddle Authors. All Rights Reserved.
+#
+# Licensed under the Apache License, Version 2.0 (the "License");
+# you may not use this file except in compliance with the License.
+# You may obtain a copy of the License at
+#
+#     http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+
+import logging
+import logging.config
+import os
+
+
+class SectionLevelFilter(object):
+    def __init__(self, levels):
+        self._levels = levels
+
+    def filter(self, logRecord):
+        return logRecord.levelno in self._levels
+
+
+log_dir = "PipelineServingLogs"
+if not os.path.exists(log_dir):
+    os.makedirs(log_dir)
+
+logger_config = {
+    "version": 1,
+    "formatters": {
+        "normal_fmt": {
+            "format":
+            "%(levelname)s %(asctime)s [%(filename)s:%(lineno)d] %(message)s",
+        },
+        "tracer_fmt": {
+            "format": "%(asctime)s %(message)s",
+        },
+    },
+    "handlers": {
+        "f_pipeline.log": {
+            "class": "logging.FileHandler",
+            "level": "INFO",
+            "formatter": "normal_fmt",
+            "filename": os.path.join(log_dir, "pipeline.log"),
+        },
+        "f_pipeline.log.wf": {
+            "class": "logging.FileHandler",
+            "level": "WARNING",
+            "formatter": "normal_fmt",
+            "filename": os.path.join(log_dir, "pipeline.log.wf"),
+        },
+        "f_tracer.log": {
+            "class": "logging.FileHandler",
+            "level": "INFO",
+            "formatter": "tracer_fmt",
+            "filename": os.path.join(log_dir, "pipeline.tracer"),
+        },
+    },
+    "loggers": {
+        # propagate = True
+        ".".join(__name__.split(".")[:-1] + ["profiler"]): {
+            "level": "INFO",
+            "handlers": ["f_tracer.log"],
+        },
+    },
+    "root": {
+        "level": "DEBUG",
+        "handlers": ["f_pipeline.log", "f_pipeline.log.wf"],
+    },
+}
+
+logging.config.dictConfig(logger_config)

python/pipeline/operator.py

@@ -12,7 +12,8 @@
 # See the License for the specific language governing permissions and
 # limitations under the License.
 # pylint: disable=doc-string-missing
-
+from time import time as _time
+import time
 import threading
 import multiprocessing
 from paddle_serving_client import MultiLangClient, Client
@@ -21,16 +22,24 @@ import logging
 import func_timeout
 import os
 import sys
+import collections
 import numpy as np
 from numpy import *
+if sys.version_info.major == 2:
+    import Queue
+elif sys.version_info.major == 3:
+    import queue as Queue
+else:
+    raise Exception("Error Python version")
 
 from .proto import pipeline_service_pb2
 from .channel import (ThreadChannel, ProcessChannel, ChannelDataEcode,
-                      ChannelData, ChannelDataType, ChannelStopError)
+                      ChannelData, ChannelDataType, ChannelStopError,
+                      ChannelTimeoutError)
 from .util import NameGenerator
-from .profiler import TimeProfiler
+from .profiler import UnsafeTimeProfiler as TimeProfiler
 
-_LOGGER = logging.getLogger()
+_LOGGER = logging.getLogger(__name__)
 _op_name_gen = NameGenerator("Op")
 
 
@@ -43,7 +52,9 @@ class Op(object):
                  client_config=None,
                  concurrency=1,
                  timeout=-1,
-                 retry=1):
+                 retry=1,
+                 batch_size=1,
+                 auto_batching_timeout=None):
         if name is None:
             name = _op_name_gen.next()
         self.name = name  # to identify the type of OP, it must be globally unique
@@ -57,41 +68,82 @@ class Op(object):
         self._client_config = client_config
         self._fetch_names = fetch_list
 
-        self._timeout = timeout
+        if timeout > 0:
+            self._timeout = timeout / 1000.0
+        else:
+            self._timeout = -1
         self._retry = max(1, retry)
         self._input = None
         self._outputs = []
 
+        self._batch_size = batch_size
+        self._auto_batching_timeout = auto_batching_timeout
+        if self._auto_batching_timeout is not None:
+            if self._auto_batching_timeout <= 0 or self._batch_size == 1:
+                _LOGGER.warning(
+                    self._log(
+                        "Because auto_batching_timeout <= 0 or batch_size == 1,"
+                        " set auto_batching_timeout to None."))
+                self._auto_batching_timeout = None
+            else:
+                self._auto_batching_timeout = self._auto_batching_timeout / 1000.0
+        if not isinstance(self, RequestOp) and not isinstance(self, ResponseOp):
+            _LOGGER.info(
+                self._log("\n\tinput_ops: {},"
+                          "\n\tserver_endpoints: {}"
+                          "\n\tfetch_list: {}"
+                          "\n\tclient_config: {}"
+                          "\n\tconcurrency: {},"
+                          "\n\ttimeout(s): {},"
+                          "\n\tretry: {},"
+                          "\n\tbatch_size: {},"
+                          "\n\tauto_batching_timeout(s): {}".format(
+                              ", ".join([op.name for op in input_ops
+                                         ]), self._server_endpoints,
+                              self._fetch_names, self._client_config,
+                              self.concurrency, self._timeout, self._retry,
+                              self._batch_size, self._auto_batching_timeout)))
+
         self._server_use_profile = False
+        self._tracer = None
 
-        # only for multithread
+        # only for thread op
         self._for_init_op_lock = threading.Lock()
         self._for_close_op_lock = threading.Lock()
         self._succ_init_op = False
         self._succ_close_op = False
 
+    def use_default_auto_batching_config(self):
+        if self._batch_size != 1:
+            _LOGGER.warning("Op({}) reset batch_size=1 (original: {})"
+                            .format(self.name, self._batch_size))
+            self._batch_size = 1
+        if self._auto_batching_timeout != None:
+            _LOGGER.warning(
+                "Op({}) reset auto_batching_timeout=None (original: {})"
+                .format(self.name, self._auto_batching_timeout))
+            self._auto_batching_timeout = None
+
     def use_profiler(self, use_profile):
         self._server_use_profile = use_profile
 
-    def _profiler_record(self, string):
-        if self._profiler is None:
-            return
-        self._profiler.record(string)
+    def set_tracer(self, tracer):
+        self._tracer = tracer
 
     def init_client(self, client_type, client_config, server_endpoints,
                     fetch_names):
         if self.with_serving == False:
-            _LOGGER.debug("{} no client".format(self.name))
+            _LOGGER.info("Op({}) has no client (and it also do not "
+                         "run the process function)".format(self.name))
             return None
-        _LOGGER.debug("{} client_config: {}".format(self.name, client_config))
-        _LOGGER.debug("{} fetch_names: {}".format(self.name, fetch_names))
         if client_type == 'brpc':
             client = Client()
             client.load_client_config(client_config)
         elif client_type == 'grpc':
             client = MultiLangClient()
         else:
-            raise ValueError("unknow client type: {}".format(client_type))
+            raise ValueError("Failed to init client: unknow client "
+                             "type {}".format(client_type))
         client.connect(server_endpoints)
         self._fetch_names = fetch_names
         return client
@@ -105,16 +157,19 @@ class Op(object):
         self._input_ops = []
         for op in ops:
             if not isinstance(op, Op):
-                raise TypeError(
-                    self._log('input op must be Op type, not {}'.format(
-                        type(op))))
+                _LOGGER.critical(
+                    self._log("Failed to set input_ops: input op "
+                              "must be Op type, not {}".format(type(op))))
+                os._exit(-1)
             self._input_ops.append(op)
 
     def add_input_channel(self, channel):
         if not isinstance(channel, (ThreadChannel, ProcessChannel)):
-            raise TypeError(
-                self._log('input channel must be Channel type, not {}'.format(
-                    type(channel))))
+            _LOGGER.critical(
+                self._log("Failed to set input_channel: input "
+                          "channel must be Channel type, not {}".format(
+                              type(channel))))
+            os._exit(-1)
         channel.add_consumer(self.name)
         self._input = channel
 
@@ -126,9 +181,10 @@ class Op(object):
 
     def add_output_channel(self, channel):
         if not isinstance(channel, (ThreadChannel, ProcessChannel)):
-            raise TypeError(
-                self._log('output channel must be Channel type, not {}'.format(
-                    type(channel))))
+            _LOGGER.critical(
+                self._log("Failed to add output_channel: output channel "
+                          "must be Channel type, not {}".format(type(channel))))
+            os._exit(-1)
         channel.add_producer(self.name)
         self._outputs.append(channel)
 
@@ -141,21 +197,28 @@ class Op(object):
     def preprocess(self, input_dicts):
         # multiple previous Op
         if len(input_dicts) != 1:
-            raise NotImplementedError(
-                'this Op has multiple previous inputs. Please override this func.'
-            )
+            _LOGGER.critical(
+                self._log(
+                    "Failed to run preprocess: this Op has multiple previous "
+                    "inputs. Please override this func."))
+            os._exit(-1)
 
         (_, input_dict), = input_dicts.items()
         return input_dict
 
-    def process(self, feed_dict):
-        err, err_info = ChannelData.check_npdata(feed_dict)
+    def process(self, feed_batch, typical_logid):
+        err, err_info = ChannelData.check_batch_npdata(feed_batch)
         if err != 0:
-            raise NotImplementedError(
-                "{} Please override preprocess func.".format(err_info))
+            _LOGGER.critical(
+                self._log("Failed to run process: {}. Please override "
+                          "preprocess func.".format(err_info)))
+            os._exit(-1)
         call_result = self.client.predict(
-            feed=feed_dict, fetch=self._fetch_names)
-        _LOGGER.debug(self._log("get call_result"))
+            feed=feed_batch, fetch=self._fetch_names, log_id=typical_logid)
+        if isinstance(self.client, MultiLangClient):
+            if call_result is None or call_result["serving_status_code"] != 0:
+                return None
+            call_result.pop("serving_status_code")
         return call_result
 
     def postprocess(self, input_dict, fetch_dict):
@@ -184,43 +247,51 @@ class Op(object):
                                  data,
                                  channels,
                                  name=None,
+                                 profile_str=None,
                                  client_need_profile=False,
                                  profile_set=None):
         if name is None:
             name = self.name
-        self._add_profile_into_channeldata(data, client_need_profile,
-                                           profile_set)
-        for channel in channels:
-            channel.push(data, name)
-
-    def _add_profile_into_channeldata(self, data, client_need_profile,
-                                      profile_set):
-        profile_str = self._profiler.gen_profile_str()
-        if self._server_use_profile:
-            sys.stderr.write(profile_str)
 
+        # add profile into channeldata
         if client_need_profile and profile_set is not None:
-            profile_set.add(profile_str)
+            if profile_str is not None:
+                profile_set.add(profile_str)
             data.add_profile(profile_set)
 
+        for channel in channels:
+            channel.push(data, name)
+
     def start_with_process(self, client_type):
+        trace_buffer = None
+        if self._tracer is not None:
+            trace_buffer = self._tracer.data_buffer()
         proces = []
         for concurrency_idx in range(self.concurrency):
             p = multiprocessing.Process(
                 target=self._run,
                 args=(concurrency_idx, self._get_input_channel(),
-                      self._get_output_channels(), client_type, False))
+                      self._get_output_channels(), client_type, False,
+                      trace_buffer))
+            p.daemon = True
             p.start()
             proces.append(p)
         return proces
 
     def start_with_thread(self, client_type):
+        trace_buffer = None
+        if self._tracer is not None:
+            trace_buffer = self._tracer.data_buffer()
         threads = []
         for concurrency_idx in range(self.concurrency):
             t = threading.Thread(
                 target=self._run,
                 args=(concurrency_idx, self._get_input_channel(),
-                      self._get_output_channels(), client_type, True))
+                      self._get_output_channels(), client_type, True,
+                      trace_buffer))
+            # When a process exits, it attempts to terminate
+            # all of its daemonic child processes.
+            t.daemon = True
             t.start()
             threads.append(t)
         return threads
@@ -228,252 +299,459 @@ class Op(object):
     def init_op(self):
         pass
 
-    def _run_preprocess(self, parsed_data, data_id, log_func):
-        preped_data, error_channeldata = None, None
-        try:
-            preped_data = self.preprocess(parsed_data)
-        except NotImplementedError as e:
-            # preprocess function not implemented
-            error_info = log_func(e)
-            _LOGGER.error(error_info)
-            error_channeldata = ChannelData(
-                ecode=ChannelDataEcode.NOT_IMPLEMENTED.value,
-                error_info=error_info,
-                data_id=data_id)
-        except TypeError as e:
-            # Error type in channeldata.datatype
-            error_info = log_func(e)
-            _LOGGER.error(error_info)
-            error_channeldata = ChannelData(
-                ecode=ChannelDataEcode.TYPE_ERROR.value,
-                error_info=error_info,
-                data_id=data_id)
-        except Exception as e:
-            error_info = log_func(e)
-            _LOGGER.error(error_info)
-            error_channeldata = ChannelData(
-                ecode=ChannelDataEcode.UNKNOW.value,
-                error_info=error_info,
-                data_id=data_id)
-        return preped_data, error_channeldata
-
-    def _run_process(self, preped_data, data_id, log_func):
-        midped_data, error_channeldata = None, None
+    def _run_preprocess(self, parsed_data_dict, op_info_prefix):
+        _LOGGER.debug("{} Running preprocess".format(op_info_prefix))
+        preped_data_dict = collections.OrderedDict()
+        err_channeldata_dict = collections.OrderedDict()
+        for data_id, parsed_data in parsed_data_dict.items():
+            preped_data, error_channeldata = None, None
+            try:
+                preped_data = self.preprocess(parsed_data)
+            except TypeError as e:
+                # Error type in channeldata.datatype
+                error_info = "(logid={}) {} Failed to preprocess: {}".format(
+                    data_id, op_info_prefix, e)
+                _LOGGER.error(error_info, exc_info=True)
+                error_channeldata = ChannelData(
+                    ecode=ChannelDataEcode.TYPE_ERROR.value,
+                    error_info=error_info,
+                    data_id=data_id)
+            except Exception as e:
+                error_info = "(logid={}) {} Failed to preprocess: {}".format(
+                    data_id, op_info_prefix, e)
+                _LOGGER.error(error_info, exc_info=True)
+                error_channeldata = ChannelData(
+                    ecode=ChannelDataEcode.UNKNOW.value,
+                    error_info=error_info,
+                    data_id=data_id)
+            if error_channeldata is not None:
+                err_channeldata_dict[data_id] = error_channeldata
+            else:
+                preped_data_dict[data_id] = preped_data
+        _LOGGER.debug("{} Succ preprocess".format(op_info_prefix))
+        return preped_data_dict, err_channeldata_dict
+
+    def _run_process(self, preped_data_dict, op_info_prefix):
+        _LOGGER.debug("{} Running process".format(op_info_prefix))
+        midped_data_dict = collections.OrderedDict()
+        err_channeldata_dict = collections.OrderedDict()
         if self.with_serving:
+            data_ids = preped_data_dict.keys()
+            typical_logid = data_ids[0]
+            if len(data_ids) != 1:
+                for data_id in data_ids:
+                    _LOGGER.info(
+                        "(logid={}) {} During access to PaddleServingService,"
+                        " we selected logid={} (from batch: {}) as a "
+                        "representative for logging.".format(
+                            data_id, op_info_prefix, typical_logid, data_ids))
+
+            # combine samples to batch
+            one_input = preped_data_dict[data_ids[0]]
+            feed_batch = []
+            input_offset = None
+            if isinstance(one_input, dict):
+                # sample input
+                feed_batch = [preped_data_dict[data_id] for data_id in data_ids]
+                input_offset = list(range(len(data_ids) + 1))
+            elif isinstance(one_input, list):
+                # batch input
+                input_offset = [0]
+                for data_id in data_ids:
+                    batch_input = preped_data_dict[data_id]
+                    offset = input_offset[-1] + len(batch_input)
+                    feed_batch += batch_input
+                    input_offset.append(offset)
+            else:
+                _LOGGER.critical(
+                    "{} Failed to process: expect input type is dict(sample"
+                    " input) or list(batch input), but get {}".format(
+                        op_info_prefix, type(one_input)))
+                os._exit(-1)
+
+            midped_batch = None
             ecode = ChannelDataEcode.OK.value
             if self._timeout <= 0:
                 try:
-                    midped_data = self.process(preped_data)
+                    midped_batch = self.process(feed_batch, typical_logid)
                 except Exception as e:
                     ecode = ChannelDataEcode.UNKNOW.value
-                    error_info = log_func(e)
-                    _LOGGER.error(error_info)
+                    error_info = "(logid={}) {} Failed to process(batch: {}): {}".format(
+                        typical_logid, op_info_prefix, data_ids, e)
+                    _LOGGER.error(error_info, exc_info=True)
             else:
                 for i in range(self._retry):
                     try:
-                        midped_data = func_timeout.func_timeout(
-                            self._timeout, self.process, args=(preped_data, ))
+                        midped_batch = func_timeout.func_timeout(
+                            self._timeout,
+                            self.process,
+                            args=(feed_batch, typical_logid))
                     except func_timeout.FunctionTimedOut as e:
                         if i + 1 >= self._retry:
                             ecode = ChannelDataEcode.TIMEOUT.value
-                            error_info = log_func(e)
+                            error_info = "(logid={}) {} Failed to process(batch: {}): " \
+                                    "exceeded retry count.".format(
+                                            typical_logid, op_info_prefix, data_ids)
                             _LOGGER.error(error_info)
                         else:
-                            _LOGGER.warn(
-                                log_func("timeout, retry({})".format(i + 1)))
+                            _LOGGER.warning(
+                                "(logid={}) {} Failed to process(batch: {}): timeout,"
+                                " and retrying({}/{})...".format(
+                                    typical_logid, op_info_prefix, data_ids, i +
+                                    1, self._retry))
                     except Exception as e:
                         ecode = ChannelDataEcode.UNKNOW.value
-                        error_info = log_func(e)
-                        _LOGGER.error(error_info)
+                        error_info = "(logid={}) {} Failed to process(batch: {}): {}".format(
+                            typical_logid, op_info_prefix, data_ids, e)
+                        _LOGGER.error(error_info, exc_info=True)
                         break
                     else:
                         break
             if ecode != ChannelDataEcode.OK.value:
-                error_channeldata = ChannelData(
-                    ecode=ecode, error_info=error_info, data_id=data_id)
-            elif midped_data is None:
+                for data_id in data_ids:
+                    err_channeldata_dict[data_id] = ChannelData(
+                        ecode=ecode, error_info=error_info, data_id=data_id)
+            elif midped_batch is None:
                 # op client return None
-                error_channeldata = ChannelData(
-                    ecode=ChannelDataEcode.CLIENT_ERROR.value,
-                    error_info=log_func(
-                        "predict failed. pls check the server side."),
-                    data_id=data_id)
+                error_info = "(logid={}) {} Failed to predict, please check if " \
+                        "PaddleServingService is working properly.".format(
+                                typical_logid, op_info_prefix)
+                _LOGGER.error(error_info)
+                for data_id in data_ids:
+                    err_channeldata_dict[data_id] = ChannelData(
+                        ecode=ChannelDataEcode.CLIENT_ERROR.value,
+                        error_info=error_info,
+                        data_id=data_id)
+            else:
+                # transform np format to dict format
+                var_names = midped_batch.keys()
+                lod_var_names = set()
+                lod_offset_names = set()
+                for name in var_names:
+                    lod_offset_name = "{}.lod".format(name)
+                    if lod_offset_name in var_names:
+                        _LOGGER.debug("(logid={}) {} {} is LodTensor".format(
+                            typical_logid, op_info_prefix, name))
+                        lod_var_names.add(name)
+                        lod_offset_names.add(lod_offset_name)
+
+                for idx, data_id in enumerate(data_ids):
+                    midped_data_dict[data_id] = {}
+
+                for name, value in midped_batch.items():
+                    if name in lod_offset_names:
+                        continue
+                    if name in lod_var_names:
+                        # lodtensor
+                        lod_offset_name = "{}.lod".format(name)
+                        lod_offset = midped_batch[lod_offset_name]
+                        for idx, data_id in enumerate(data_ids):
+                            data_offset_left = input_offset[idx]
+                            data_offset_right = input_offset[idx + 1]
+                            lod_offset_left = lod_offset[data_offset_left]
+                            lod_offset_right = lod_offset[data_offset_right]
+                            midped_data_dict[data_id][name] = value[
+                                lod_offset_left:lod_offset_right]
+                            midped_data_dict[data_id][lod_offset_name] = \
+                                    lod_offset[data_offset_left:data_offset_right + 1] - lod_offset[data_offset_left]
+                    else:
+                        # normal tensor
+                        for idx, data_id in enumerate(data_ids):
+                            left = input_offset[idx]
+                            right = input_offset[idx + 1]
+                            midped_data_dict[data_id][name] = value[left:right]
         else:
-            midped_data = preped_data
-        return midped_data, error_channeldata
+            midped_data_dict = preped_data_dict
+        _LOGGER.debug("{} Succ process".format(op_info_prefix))
+        return midped_data_dict, err_channeldata_dict
+
+    def _run_postprocess(self, parsed_data_dict, midped_data_dict,
+                         op_info_prefix):
+        _LOGGER.debug("{} Running postprocess".format(op_info_prefix))
+        postped_data_dict = collections.OrderedDict()
+        err_channeldata_dict = collections.OrderedDict()
+        for data_id, midped_data in midped_data_dict.items():
+            postped_data, err_channeldata = None, None
+            try:
+                postped_data = self.postprocess(parsed_data_dict[data_id],
+                                                midped_data)
+            except Exception as e:
+                error_info = "(logid={}) {} Failed to postprocess: {}".format(
+                    data_id, op_info_prefix, e)
+                _LOGGER.error(error_info, exc_info=True)
+                err_channeldata = ChannelData(
+                    ecode=ChannelDataEcode.UNKNOW.value,
+                    error_info=error_info,
+                    data_id=data_id)
+            if err_channeldata is not None:
+                err_channeldata_dict[data_id] = err_channeldata
+                continue
+            else:
+                if not isinstance(postped_data, dict):
+                    error_info = "(logid={}) {} Failed to postprocess: " \
+                            "output of postprocess funticon must be " \
+                            "dict type, but get {}".format(
+                                data_id, op_info_prefix,
+                                type(postped_data))
+                    _LOGGER.error(error_info)
+                    err_channeldata = ChannelData(
+                        ecode=ChannelDataEcode.UNKNOW.value,
+                        error_info=error_info,
+                        data_id=data_id)
+                    err_channeldata_dict[data_id] = err_channeldata
+                    continue
+
+                output_data = None
+                err, _ = ChannelData.check_npdata(postped_data)
+                if err == 0:
+                    output_data = ChannelData(
+                        ChannelDataType.CHANNEL_NPDATA.value,
+                        npdata=postped_data,
+                        data_id=data_id)
+                else:
+                    output_data = ChannelData(
+                        ChannelDataType.DICT.value,
+                        dictdata=postped_data,
+                        data_id=data_id)
+                postped_data_dict[data_id] = output_data
+        _LOGGER.debug("{} Succ postprocess".format(op_info_prefix))
+        return postped_data_dict, err_channeldata_dict
+
+    def _auto_batching_generator(self, input_channel, op_name, batch_size,
+                                 timeout, op_info_prefix):
+        while True:
+            batch = []
+            while len(batch) == 0:
+                endtime = None
+                if timeout is not None:
+                    endtime = _time() + timeout
+                for idx in range(batch_size):
+                    try:
+                        channeldata_dict = None
+                        if timeout is not None:
+                            remaining = endtime - _time()
+                            if remaining <= 0.0:
+                                _LOGGER.debug("{} Failed to generate batch: "
+                                              "timeout".format(op_info_prefix))
+                                break
+                            channeldata_dict = input_channel.front(op_name,
+                                                                   timeout)
+                        else:
+                            channeldata_dict = input_channel.front(op_name)
+                        batch.append(channeldata_dict)
+                    except ChannelTimeoutError:
+                        _LOGGER.debug("{} Failed to generate batch: "
+                                      "timeout".format(op_info_prefix))
+                        break
+            _LOGGER.debug("{} Got actual batch_size: {}".format(op_info_prefix,
+                                                                len(batch)))
+            yield batch
+
+    def _parse_channeldata_batch(self, batch, output_channels):
+        parsed_data_dict = collections.OrderedDict()
+        need_profile_dict = {}
+        profile_dict = {}
+        for channeldata_dict in batch:
+            (data_id, error_channeldata, parsed_data,
+                    client_need_profile, profile_set) = \
+                            self._parse_channeldata(channeldata_dict)
+            if error_channeldata is None:
+                parsed_data_dict[data_id] = parsed_data
+                need_profile_dict[data_id] = client_need_profile
+                profile_dict[data_id] = profile_set
+            else:
+                # error data in predecessor Op
+                # (error_channeldata with profile info)
+                self._push_to_output_channels(error_channeldata,
+                                              output_channels)
 
-    def _run_postprocess(self, input_dict, midped_data, data_id, log_func):
-        output_data, error_channeldata = None, None
-        try:
-            postped_data = self.postprocess(input_dict, midped_data)
-        except Exception as e:
-            error_info = log_func(e)
-            _LOGGER.error(error_info)
-            error_channeldata = ChannelData(
-                ecode=ChannelDataEcode.UNKNOW.value,
-                error_info=error_info,
-                data_id=data_id)
-            return output_data, error_channeldata
-
-        if not isinstance(postped_data, dict):
-            error_info = log_func("output of postprocess funticon must be " \
-                    "dict type, but get {}".format(type(postped_data)))
-            _LOGGER.error(error_info)
-            error_channeldata = ChannelData(
-                ecode=ChannelDataEcode.UNKNOW.value,
-                error_info=error_info,
-                data_id=data_id)
-            return output_data, error_channeldata
-
-        err, _ = ChannelData.check_npdata(postped_data)
-        if err == 0:
-            output_data = ChannelData(
-                ChannelDataType.CHANNEL_NPDATA.value,
-                npdata=postped_data,
-                data_id=data_id)
-        else:
-            output_data = ChannelData(
-                ChannelDataType.DICT.value,
-                dictdata=postped_data,
-                data_id=data_id)
-        return output_data, error_channeldata
+        return parsed_data_dict, need_profile_dict, profile_dict
 
     def _run(self, concurrency_idx, input_channel, output_channels, client_type,
-             is_thread_op):
-        def get_log_func(op_info_prefix):
-            def log_func(info_str):
-                return "{} {}".format(op_info_prefix, info_str)
-
-            return log_func
-
+             is_thread_op, trace_buffer):
         op_info_prefix = "[{}|{}]".format(self.name, concurrency_idx)
-        log = get_log_func(op_info_prefix)
         tid = threading.current_thread().ident
 
         # init op
-        self.concurrency_idx = concurrency_idx
+        profiler = None
         try:
-            if is_thread_op:
-                with self._for_init_op_lock:
-                    if not self._succ_init_op:
-                        # init profiler
-                        self._profiler = TimeProfiler()
-                        self._profiler.enable(True)
-                        # init client
-                        self.client = self.init_client(
-                            client_type, self._client_config,
-                            self._server_endpoints, self._fetch_names)
-                        # user defined
-                        self.init_op()
-                        self._succ_init_op = True
-                        self._succ_close_op = False
-            else:
-                # init profiler
-                self._profiler = TimeProfiler()
-                self._profiler.enable(True)
-                # init client
-                self.client = self.init_client(client_type, self._client_config,
-                                               self._server_endpoints,
-                                               self._fetch_names)
-                # user defined
-                self.init_op()
+            profiler = self._initialize(is_thread_op, client_type,
+                                        concurrency_idx)
         except Exception as e:
-            _LOGGER.error(log(e))
+            _LOGGER.critical(
+                "{} Failed to init op: {}".format(op_info_prefix, e),
+                exc_info=True)
             os._exit(-1)
+        _LOGGER.info("{} Succ init".format(op_info_prefix))
 
+        batch_generator = self._auto_batching_generator(
+            input_channel=input_channel,
+            op_name=self.name,
+            batch_size=self._batch_size,
+            timeout=self._auto_batching_timeout,
+            op_info_prefix=op_info_prefix)
+
+        start, end = None, None
+        trace_que = collections.deque()
         while True:
-            #self._profiler_record("get#{}_0".format(op_info_prefix))
+            start = int(round(_time() * 1000000))
             try:
-                channeldata_dict = input_channel.front(self.name)
+                channeldata_dict_batch = next(batch_generator)
             except ChannelStopError:
-                _LOGGER.debug(log("stop."))
-                if is_thread_op:
-                    with self._for_close_op_lock:
-                        if not self._succ_close_op:
-                            self._profiler = None
-                            self.client = None
-                            self._succ_init_op = False
-                            self._succ_close_op = True
+                _LOGGER.debug("{} Stop.".format(op_info_prefix))
+                self._finalize(is_thread_op)
                 break
-            #self._profiler_record("get#{}_1".format(op_info_prefix))
-            _LOGGER.debug(log("input_data: {}".format(channeldata_dict)))
+            end = int(round(_time() * 1000000))
+            in_time = end - start
 
-            (data_id, error_channeldata, parsed_data, client_need_profile,
-             profile_set) = self._parse_channeldata(channeldata_dict)
-            # error data in predecessor Op
-            if error_channeldata is not None:
-                try:
-                    # error_channeldata with profile info
-                    self._push_to_output_channels(error_channeldata,
-                                                  output_channels)
-                except ChannelStopError:
-                    _LOGGER.debug(log("stop."))
-                    break
+            # parse channeldata batch
+            try:
+                parsed_data_dict, need_profile_dict, profile_dict \
+                        = self._parse_channeldata_batch(
+                                channeldata_dict_batch, output_channels)
+            except ChannelStopError:
+                _LOGGER.debug("{} Stop.".format(op_info_prefix))
+                self._finalize(is_thread_op)
+                break
+            if len(parsed_data_dict) == 0:
+                # data in the whole batch is all error data
                 continue
 
             # preprecess
-            self._profiler_record("prep#{}_0".format(op_info_prefix))
-            preped_data, error_channeldata = self._run_preprocess(parsed_data,
-                                                                  data_id, log)
-            self._profiler_record("prep#{}_1".format(op_info_prefix))
-            if error_channeldata is not None:
-                try:
+            start = profiler.record("prep#{}_0".format(op_info_prefix))
+            preped_data_dict, err_channeldata_dict \
+                    = self._run_preprocess(parsed_data_dict, op_info_prefix)
+            end = profiler.record("prep#{}_1".format(op_info_prefix))
+            prep_time = end - start
+            try:
+                for data_id, err_channeldata in err_channeldata_dict.items():
                     self._push_to_output_channels(
-                        error_channeldata,
-                        output_channels,
-                        client_need_profile=client_need_profile,
-                        profile_set=profile_set)
-                except ChannelStopError:
-                    _LOGGER.debug(log("stop."))
-                    break
+                        data=err_channeldata,
+                        channels=output_channels,
+                        client_need_profile=need_profile_dict[data_id],
+                        profile_set=profile_dict[data_id])
+            except ChannelStopError:
+                _LOGGER.debug("{} Stop.".format(op_info_prefix))
+                self._finalize(is_thread_op)
+                break
+            if len(preped_data_dict) == 0:
                 continue
 
             # process
-            self._profiler_record("midp#{}_0".format(op_info_prefix))
-            midped_data, error_channeldata = self._run_process(preped_data,
-                                                               data_id, log)
-            self._profiler_record("midp#{}_1".format(op_info_prefix))
-            if error_channeldata is not None:
-                try:
+            start = profiler.record("midp#{}_0".format(op_info_prefix))
+            midped_data_dict, err_channeldata_dict \
+                    = self._run_process(preped_data_dict, op_info_prefix)
+            end = profiler.record("midp#{}_1".format(op_info_prefix))
+            midp_time = end - start
+            try:
+                for data_id, err_channeldata in err_channeldata_dict.items():
                     self._push_to_output_channels(
-                        error_channeldata,
-                        output_channels,
-                        client_need_profile=client_need_profile,
-                        profile_set=profile_set)
-                except ChannelStopError:
-                    _LOGGER.debug(log("stop."))
-                    break
+                        data=err_channeldata,
+                        channels=output_channels,
+                        client_need_profile=need_profile_dict[data_id],
+                        profile_set=profile_dict[data_id])
+            except ChannelStopError:
+                _LOGGER.debug("{} Stop.".format(op_info_prefix))
+                self._finalize(is_thread_op)
+                break
+            if len(midped_data_dict) == 0:
                 continue
 
             # postprocess
-            self._profiler_record("postp#{}_0".format(op_info_prefix))
-            output_data, error_channeldata = self._run_postprocess(
-                parsed_data, midped_data, data_id, log)
-            self._profiler_record("postp#{}_1".format(op_info_prefix))
-            if error_channeldata is not None:
-                try:
+            start = profiler.record("postp#{}_0".format(op_info_prefix))
+            postped_data_dict, err_channeldata_dict \
+                    = self._run_postprocess(
+                            parsed_data_dict, midped_data_dict, op_info_prefix)
+            end = profiler.record("postp#{}_1".format(op_info_prefix))
+            postp_time = end - start
+            try:
+                for data_id, err_channeldata in err_channeldata_dict.items():
                     self._push_to_output_channels(
-                        error_channeldata,
-                        output_channels,
-                        client_need_profile=client_need_profile,
-                        profile_set=profile_set)
-                except ChannelStopError:
-                    _LOGGER.debug(log("stop."))
-                    break
+                        data=err_channeldata,
+                        channels=output_channels,
+                        client_need_profile=need_profile_dict[data_id],
+                        profile_set=profile_dict[data_id])
+            except ChannelStopError:
+                _LOGGER.debug("{} Stop.".format(op_info_prefix))
+                self._finalize(is_thread_op)
+                break
+            if len(postped_data_dict) == 0:
                 continue
 
             # push data to channel (if run succ)
-            #self._profiler_record("push#{}_0".format(op_info_prefix))
+            start = int(round(_time() * 1000000))
             try:
-                self._push_to_output_channels(
-                    output_data,
-                    output_channels,
-                    client_need_profile=client_need_profile,
-                    profile_set=profile_set)
+                profile_str = profiler.gen_profile_str()
+                for data_id, postped_data in postped_data_dict.items():
+                    if self._server_use_profile:
+                        sys.stderr.write(profile_str)
+                    self._push_to_output_channels(
+                        data=postped_data,
+                        channels=output_channels,
+                        profile_str=profile_str,
+                        client_need_profile=need_profile_dict[data_id],
+                        profile_set=profile_dict[data_id])
             except ChannelStopError:
-                _LOGGER.debug(log("stop."))
+                _LOGGER.debug("{} Stop.".format(op_info_prefix))
+                self._finalize(is_thread_op)
                 break
-            #self._profiler_record("push#{}_1".format(op_info_prefix))
+            end = int(round(_time() * 1000000))
+            out_time = end - start
+            if trace_buffer is not None:
+                trace_que.append({
+                    "name": self.name,
+                    "actions": {
+                        "in": in_time,
+                        "prep": prep_time,
+                        "midp": midp_time,
+                        "postp": postp_time,
+                        "out": out_time,
+                    }
+                })
+                while trace_que:
+                    info = trace_que[0]
+                    try:
+                        trace_buffer.put_nowait(info)
+                        trace_que.popleft()
+                    except Queue.Full:
+                        break
+
+    def _initialize(self, is_thread_op, client_type, concurrency_idx):
+        if is_thread_op:
+            with self._for_init_op_lock:
+                if not self._succ_init_op:
+                    # for the threaded version of Op, each thread cannot get its concurrency_idx
+                    self.concurrency_idx = None
+                    # init client
+                    self.client = self.init_client(
+                        client_type, self._client_config,
+                        self._server_endpoints, self._fetch_names)
+                    # user defined
+                    self.init_op()
+                    self._succ_init_op = True
+                    self._succ_close_op = False
+        else:
+            self.concurrency_idx = concurrency_idx
+            # init client
+            self.client = self.init_client(client_type, self._client_config,
+                                           self._server_endpoints,
+                                           self._fetch_names)
+            # user defined
+            self.init_op()
+
+        # use a separate TimeProfiler per thread or process
+        profiler = TimeProfiler()
+        profiler.enable(True)
+        return profiler
+
+    def _finalize(self, is_thread_op):
+        if is_thread_op:
+            with self._for_close_op_lock:
+                if not self._succ_close_op:
+                    self._profiler = None
+                    self.client = None
+                    self._succ_init_op = False
+                    self._succ_close_op = True
 
     def _log(self, info):
         return "{} {}".format(self.name, info)
@@ -483,13 +761,13 @@ class RequestOp(Op):
     """ RequestOp do not run preprocess, process, postprocess. """
 
     def __init__(self):
-        # PipelineService.name = "@G"
-        super(RequestOp, self).__init__(name="@G", input_ops=[])
+        # PipelineService.name = "@DAGExecutor"
+        super(RequestOp, self).__init__(name="@DAGExecutor", input_ops=[])
         # init op
         try:
             self.init_op()
         except Exception as e:
-            _LOGGER.error(e)
+            _LOGGER.critical("Op(Request) Failed to init: {}".format(e))
             os._exit(-1)
 
     def unpack_request_package(self, request):
@@ -508,12 +786,14 @@ class ResponseOp(Op):
     """ ResponseOp do not run preprocess, process, postprocess. """
 
     def __init__(self, input_ops):
-        super(ResponseOp, self).__init__(name="@R", input_ops=input_ops)
+        super(ResponseOp, self).__init__(
+            name="@DAGExecutor", input_ops=input_ops)
         # init op
         try:
             self.init_op()
         except Exception as e:
-            _LOGGER.error(e)
+            _LOGGER.critical("Op(ResponseOp) Failed to init: {}".format(
+                e, exc_info=True))
             os._exit(-1)
 
     def pack_response_package(self, channeldata):
@@ -524,7 +804,7 @@ class ResponseOp(Op):
                 feed = channeldata.parse()
                 # ndarray to string:
                 # https://stackoverflow.com/questions/30167538/convert-a-numpy-ndarray-to-stringor-bytes-and-convert-it-back-to-numpy-ndarray
-                np.set_printoptions(threshold=np.nan)
+                np.set_printoptions(threshold=sys.maxsize)
                 for name, var in feed.items():
                     resp.value.append(var.__repr__())
                     resp.key.append(name)
@@ -536,14 +816,19 @@ class ResponseOp(Op):
                         resp.error_info = self._log(
                             "fetch var type must be str({}).".format(
                                 type(var)))
+                        _LOGGER.error("(logid={}) Failed to pack RPC "
+                                      "response package: {}".format(
+                                          channeldata.id, resp.error_info))
                         break
                     resp.value.append(var)
                     resp.key.append(name)
             else:
                 resp.ecode = ChannelDataEcode.TYPE_ERROR.value
                 resp.error_info = self._log(
-                    "Error type({}) in datatype.".format(channeldata.datatype))
-                _LOGGER.error(resp.error_info)
+                    "error type({}) in datatype.".format(channeldata.datatype))
+                _LOGGER.error("(logid={}) Failed to pack RPC response"
+                              " package: {}".format(channeldata.id,
+                                                    resp.error_info))
         else:
             resp.error_info = channeldata.error_info
         return resp
@@ -561,6 +846,7 @@ class VirtualOp(Op):
         self._virtual_pred_ops.append(op)
 
     def _actual_pred_op_names(self, op):
+        # can use disjoint-set, but it's not necessary
         if not isinstance(op, VirtualOp):
             return [op.name]
         names = []
@@ -570,9 +856,11 @@ class VirtualOp(Op):
 
     def add_output_channel(self, channel):
         if not isinstance(channel, (ThreadChannel, ProcessChannel)):
-            raise TypeError(
-                self._log('output channel must be Channel type, not {}'.format(
-                    type(channel))))
+            _LOGGER.critical(
+                self._log("Failed to add output_channel: output_channel"
+                          " must be Channel type, not {}".format(
+                              type(channel))))
+            os._exit(-1)
         for op in self._virtual_pred_ops:
             for op_name in self._actual_pred_op_names(op):
                 channel.add_producer(op_name)
@@ -580,27 +868,31 @@ class VirtualOp(Op):
 
     def _run(self, concurrency_idx, input_channel, output_channels, client_type,
              is_thread_op):
-        def get_log_func(op_info_prefix):
-            def log_func(info_str):
-                return "{} {}".format(op_info_prefix, info_str)
-
-            return log_func
-
         op_info_prefix = "[{}|{}]".format(self.name, concurrency_idx)
         log = get_log_func(op_info_prefix)
         tid = threading.current_thread().ident
 
+        batch_generator = self._auto_batching_generator(
+            input_channel=input_channel,
+            op_name=self.name,
+            batch_size=1,
+            timeout=None,
+            log_func=log)
+
         while True:
             try:
-                channeldata_dict = input_channel.front(self.name)
+                channeldata_dict_batch = next(batch_generator)
             except ChannelStopError:
-                _LOGGER.debug(log("stop."))
+                _LOGGER.debug("{} Stop.".format(op_info_prefix))
+                self._finalize(is_thread_op)
                 break
 
             try:
-                for name, data in channeldata_dict.items():
-                    self._push_to_output_channels(
-                        data, channels=output_channels, name=name)
+                for channeldata_dict in channeldata_dict_batch:
+                    for name, data in channeldata_dict.items():
+                        self._push_to_output_channels(
+                            data, channels=output_channels, name=name)
             except ChannelStopError:
-                _LOGGER.debug(log("stop."))
+                _LOGGER.debug("{} Stop.".format(op_info_prefix))
+                self._finalize(is_thread_op)
                 break

python/pipeline/pipeline_client.py

@@ -18,10 +18,11 @@ import numpy as np
 from numpy import *
 import logging
 import functools
+from .channel import ChannelDataEcode
 from .proto import pipeline_service_pb2
 from .proto import pipeline_service_pb2_grpc
 
-_LOGGER = logging.getLogger()
+_LOGGER = logging.getLogger(__name__)
 
 
 class PipelineClient(object):
@@ -59,7 +60,11 @@ class PipelineClient(object):
 
     def _unpack_response_package(self, resp, fetch):
         if resp.ecode != 0:
-            return {"ecode": resp.ecode, "error_info": resp.error_info}
+            return {
+                "ecode": resp.ecode,
+                "ecode_desc": ChannelDataEcode(resp.ecode),
+                "error_info": resp.error_info,
+            }
         fetch_map = {"ecode": resp.ecode}
         for idx, key in enumerate(resp.key):
             if key == self._profile_key:

python/pipeline/pipeline_server.py

@@ -15,6 +15,7 @@
 from concurrent import futures
 import grpc
 import logging
+import json
 import socket
 import contextlib
 from contextlib import closing
@@ -25,24 +26,21 @@ from .proto import pipeline_service_pb2_grpc
 from .operator import ResponseOp
 from .dag import DAGExecutor
 
-_LOGGER = logging.getLogger()
+_LOGGER = logging.getLogger(__name__)
 
 
-class PipelineService(pipeline_service_pb2_grpc.PipelineServiceServicer):
-    def __init__(self, response_op, dag_config, show_info):
-        super(PipelineService, self).__init__()
+class PipelineServicer(pipeline_service_pb2_grpc.PipelineServiceServicer):
+    def __init__(self, response_op, dag_conf, worker_idx=-1):
+        super(PipelineServicer, self).__init__()
         # init dag executor
-        self._dag_executor = DAGExecutor(
-            response_op, dag_config, show_info=show_info)
+        self._dag_executor = DAGExecutor(response_op, dag_conf, worker_idx)
         self._dag_executor.start()
+        _LOGGER.info("[PipelineServicer] succ init")
 
     def inference(self, request, context):
         resp = self._dag_executor.call(request)
         return resp
 
-    def __del__(self):
-        self._dag_executor.stop()
-
 
 @contextlib.contextmanager
 def _reserve_port(port):
@@ -66,9 +64,11 @@ class PipelineServer(object):
 
     def set_response_op(self, response_op):
         if not isinstance(response_op, ResponseOp):
-            raise Exception("response_op must be ResponseOp type.")
+            raise Exception("Failed to set response_op: response_op "
+                            "must be ResponseOp type.")
         if len(response_op.get_input_ops()) != 1:
-            raise Exception("response_op can only have one previous op.")
+            raise Exception("Failed to set response_op: response_op "
+                            "can only have one previous op.")
         self._response_op = response_op
 
     def _port_is_available(self, port):
@@ -78,28 +78,26 @@ class PipelineServer(object):
         return result != 0
 
     def prepare_server(self, yml_file):
-        with open(yml_file) as f:
-            yml_config = yaml.load(f.read())
-        self._port = yml_config.get('port')
-        if self._port is None:
-            raise SystemExit("Please set *port* in [{}] yaml file.".format(
-                yml_file))
+        conf = ServerYamlConfChecker.load_server_yaml_conf(yml_file)
+
+        self._port = conf["port"]
         if not self._port_is_available(self._port):
-            raise SystemExit("Prot {} is already used".format(self._port))
-        self._worker_num = yml_config.get('worker_num', 1)
-        self._build_dag_each_worker = yml_config.get('build_dag_each_worker',
-                                                     False)
+            raise SystemExit("Failed to prepare_server: prot {} "
+                             "is already used".format(self._port))
+        self._worker_num = conf["worker_num"]
+        self._build_dag_each_worker = conf["build_dag_each_worker"]
+
         _LOGGER.info("============= PIPELINE SERVER =============")
-        _LOGGER.info("port: {}".format(self._port))
-        _LOGGER.info("worker_num: {}".format(self._worker_num))
-        servicer_info = "build_dag_each_worker: {}".format(
-            self._build_dag_each_worker)
+        _LOGGER.info("\n{}".format(
+            json.dumps(
+                conf, indent=4, separators=(',', ':'))))
         if self._build_dag_each_worker is True:
-            servicer_info += " (Make sure that install grpcio whl with --no-binary flag)"
-        _LOGGER.info(servicer_info)
+            _LOGGER.warning(
+                "(Make sure that install grpcio whl with --no-binary flag: "
+                "pip install grpcio --no-binary grpcio)")
         _LOGGER.info("-------------------------------------------")
 
-        self._dag_config = yml_config.get("dag", {})
+        self._conf = conf
 
     def run_server(self):
         if self._build_dag_each_worker:
@@ -110,29 +108,167 @@ class PipelineServer(object):
                     show_info = (i == 0)
                     worker = multiprocessing.Process(
                         target=self._run_server_func,
-                        args=(bind_address, self._response_op,
-                              self._dag_config))
+                        args=(bind_address, self._response_op, self._conf, i))
                     worker.start()
                     workers.append(worker)
                 for worker in workers:
                     worker.join()
         else:
             server = grpc.server(
-                futures.ThreadPoolExecutor(max_workers=self._worker_num))
+                futures.ThreadPoolExecutor(max_workers=self._worker_num),
+                options=[('grpc.max_send_message_length', 256 * 1024 * 1024),
+                         ('grpc.max_receive_message_length', 256 * 1024 * 1024)
+                         ])
             pipeline_service_pb2_grpc.add_PipelineServiceServicer_to_server(
-                PipelineService(self._response_op, self._dag_config, True),
-                server)
+                PipelineServicer(self._response_op, self._conf), server)
             server.add_insecure_port('[::]:{}'.format(self._port))
             server.start()
             server.wait_for_termination()
 
-    def _run_server_func(self, bind_address, response_op, dag_config):
-        options = (('grpc.so_reuseport', 1), )
+    def _run_server_func(self, bind_address, response_op, dag_conf, worker_idx):
+        options = [('grpc.so_reuseport', 1),
+                   ('grpc.max_send_message_length', 256 * 1024 * 1024),
+                   ('grpc.max_send_message_length', 256 * 1024 * 1024)]
         server = grpc.server(
             futures.ThreadPoolExecutor(
                 max_workers=1, ), options=options)
         pipeline_service_pb2_grpc.add_PipelineServiceServicer_to_server(
-            PipelineService(response_op, dag_config, False), server)
+            PipelineServicer(response_op, dag_conf, worker_idx), server)
         server.add_insecure_port(bind_address)
         server.start()
         server.wait_for_termination()
+
+
+class ServerYamlConfChecker(object):
+    def __init__(self):
+        pass
+
+    @staticmethod
+    def load_server_yaml_conf(yml_file):
+        with open(yml_file) as f:
+            conf = yaml.load(f.read())
+        ServerYamlConfChecker.check_server_conf(conf)
+        ServerYamlConfChecker.check_dag_conf(conf["dag"])
+        ServerYamlConfChecker.check_tracer_conf(conf["dag"]["tracer"])
+        return conf
+
+    @staticmethod
+    def check_conf(conf, default_conf, conf_type, conf_qualification):
+        ServerYamlConfChecker.fill_with_default_conf(conf, default_conf)
+        ServerYamlConfChecker.check_conf_type(conf, conf_type)
+        ServerYamlConfChecker.check_conf_qualification(conf, conf_qualification)
+
+    @staticmethod
+    def check_server_conf(conf):
+        default_conf = {
+            "port": 9292,
+            "worker_num": 1,
+            "build_dag_each_worker": False,
+            "dag": {},
+        }
+
+        conf_type = {
+            "port": int,
+            "worker_num": int,
+            "build_dag_each_worker": bool,
+        }
+
+        conf_qualification = {
+            "port": [(">=", 1024), ("<=", 65535)],
+            "worker_num": (">=", 1),
+        }
+
+        ServerYamlConfChecker.check_conf(conf, default_conf, conf_type,
+                                         conf_qualification)
+
+    @staticmethod
+    def check_tracer_conf(conf):
+        default_conf = {"interval_s": -1, }
+
+        conf_type = {"interval_s": int, }
+
+        conf_qualification = {}
+
+        ServerYamlConfChecker.check_conf(conf, default_conf, conf_type,
+                                         conf_qualification)
+
+    @staticmethod
+    def check_dag_conf(conf):
+        default_conf = {
+            "retry": 1,
+            "client_type": "brpc",
+            "use_profile": False,
+            "channel_size": 0,
+            "is_thread_op": True,
+            "tracer": {},
+        }
+
+        conf_type = {
+            "retry": int,
+            "client_type": str,
+            "use_profile": bool,
+            "channel_size": int,
+            "is_thread_op": bool,
+        }
+
+        conf_qualification = {
+            "retry": (">=", 1),
+            "client_type": ("in", ["brpc", "grpc"]),
+            "channel_size": (">=", 0),
+        }
+
+        ServerYamlConfChecker.check_conf(conf, default_conf, conf_type,
+                                         conf_qualification)
+
+    @staticmethod
+    def fill_with_default_conf(conf, default_conf):
+        for key, val in default_conf.items():
+            if conf.get(key) is None:
+                _LOGGER.warning("[CONF] {} not set, use default: {}"
+                                .format(key, val))
+                conf[key] = val
+
+    @staticmethod
+    def check_conf_type(conf, conf_type):
+        for key, val in conf_type.items():
+            if not isinstance(conf[key], val):
+                raise SystemExit("[CONF] {} must be {} type, but get {}."
+                                 .format(key, val, type(conf[key])))
+
+    @staticmethod
+    def check_conf_qualification(conf, conf_qualification):
+        for key, qualification in conf_qualification.items():
+            if not isinstance(qualification, list):
+                qualification = [qualification]
+            if not ServerYamlConfChecker.qualification_check(conf[key],
+                                                             qualification):
+                raise SystemExit("[CONF] {} must be {}, but get {}."
+                                 .format(key, ", ".join([
+                                     "{} {}"
+                                     .format(q[0], q[1]) for q in qualification
+                                 ]), conf[key]))
+
+    @staticmethod
+    def qualification_check(value, qualifications):
+        if not isinstance(qualifications, list):
+            qualifications = [qualifications]
+        ok = True
+        for q in qualifications:
+            operator, limit = q
+            if operator == "<":
+                ok = value < limit
+            elif operator == "==":
+                ok = value == limit
+            elif operator == ">":
+                ok = value > limit
+            elif operator == "<=":
+                ok = value <= limit
+            elif operator == ">=":
+                ok = value >= limit
+            elif operator == "in":
+                ok = value in limit
+            else:
+                raise SystemExit("unknow operator: {}".format(operator))
+            if ok == False:
+                break
+        return ok

python/pipeline/profiler.py

@@ -22,10 +22,165 @@ elif sys.version_info.major == 3:
     import queue as Queue
 else:
     raise Exception("Error Python version")
+from time import time as _time
 import time
 import threading
+import multiprocessing
 
-_LOGGER = logging.getLogger()
+_LOGGER = logging.getLogger(__name__)
+_LOGGER.propagate = False
+
+
+class PerformanceTracer(object):
+    def __init__(self, is_thread_mode, interval_s, server_worker_num):
+        self._is_thread_mode = is_thread_mode
+        if is_thread_mode:
+            # Because the Channel in the thread mode cannot be
+            # accessed across processes, when using thread mode,
+            # the PerformanceTracer is also the thread mode.
+            # However, performance may be affected by GIL.
+            self._data_buffer = Queue.Queue()
+        else:
+            self._data_buffer = multiprocessing.Manager().Queue()
+        self._interval_s = interval_s
+        self._thrd = None
+        self._proc = None
+        self._channels = []
+        # The size of data in Channel will not exceed server_worker_num
+        self._server_worker_num = server_worker_num
+
+    def data_buffer(self):
+        return self._data_buffer
+
+    def start(self):
+        if self._is_thread_mode:
+            self._thrd = threading.Thread(
+                target=self._trace_func, args=(self._channels, ))
+            self._thrd.daemon = True
+            self._thrd.start()
+        else:
+            self._proc = multiprocessing.Process(
+                target=self._trace_func, args=(self._channels, ))
+            self._proc.daemon = True
+            self._proc.start()
+
+    def set_channels(self, channels):
+        self._channels = channels
+
+    def _trace_func(self, channels):
+        all_actions = ["in", "prep", "midp", "postp", "out"]
+        calcu_actions = ["prep", "midp", "postp"]
+        while True:
+            op_cost = {}
+            err_request = []
+            err_count = 0
+
+            _LOGGER.info("==================== TRACER ======================")
+            # op
+            while True:
+                try:
+                    item = self._data_buffer.get_nowait()
+                    name = item["name"]
+                    actions = item["actions"]
+
+                    if name == "DAG":
+                        succ = item["succ"]
+                        req_id = item["id"]
+                        if not succ:
+                            err_count += 1
+                            err_request.append(req_id)
+
+                    if name not in op_cost:
+                        op_cost[name] = {}
+
+                    for action, cost in actions.items():
+                        if action not in op_cost[name]:
+                            op_cost[name][action] = []
+                        op_cost[name][action].append(cost)
+                except Queue.Empty:
+                    break
+
+            if len(op_cost) != 0:
+                for name in op_cost:
+                    tot_cost, calcu_cost = 0.0, 0.0
+                    for action, costs in op_cost[name].items():
+                        op_cost[name][action] = sum(costs) / (1e3 * len(costs))
+                        tot_cost += op_cost[name][action]
+
+                    if name != "DAG":
+                        _LOGGER.info("Op({}):".format(name))
+                        for action in all_actions:
+                            if action in op_cost[name]:
+                                _LOGGER.info("\t{}[{} ms]".format(
+                                    action, op_cost[name][action]))
+                        for action in calcu_actions:
+                            if action in op_cost[name]:
+                                calcu_cost += op_cost[name][action]
+                        _LOGGER.info("\tidle[{}]".format(1 - 1.0 * calcu_cost /
+                                                         tot_cost))
+
+            if "DAG" in op_cost:
+                calls = op_cost["DAG"].values()
+                calls.sort()
+                tot = len(calls)
+                qps = 1.0 * tot / self._interval_s
+                ave_cost = sum(calls) / tot
+                latencys = [50, 60, 70, 80, 90, 95, 99]
+                _LOGGER.info("DAGExecutor:")
+                _LOGGER.info("\tQuery count[{}]".format(tot))
+                _LOGGER.info("\tQPS[{} q/s]".format(qps))
+                _LOGGER.info("\tSucc[{}]".format(1 - 1.0 * err_count / tot))
+                _LOGGER.info("\tError req[{}]".format(", ".join(
+                    [str(x) for x in err_request])))
+                _LOGGER.info("\tLatency:")
+                _LOGGER.info("\t\tave[{} ms]".format(ave_cost))
+                for latency in latencys:
+                    _LOGGER.info("\t\t.{}[{} ms]".format(latency, calls[int(
+                        tot * latency / 100.0)]))
+
+            # channel
+            _LOGGER.info("Channel (server worker num[{}]):".format(
+                self._server_worker_num))
+            for channel in channels:
+                _LOGGER.info("\t{}(In: {}, Out: {}) size[{}/{}]".format(
+                    channel.name,
+                    channel.get_producers(),
+                    channel.get_consumers(),
+                    channel.size(), channel.get_maxsize()))
+            time.sleep(self._interval_s)
+
+
+class UnsafeTimeProfiler(object):
+    """ thread unsafe profiler """
+
+    def __init__(self):
+        self.pid = os.getpid()
+        self.print_head = 'PROFILE\tpid:{}\t'.format(self.pid)
+        self.time_record = [self.print_head]
+        self._enable = False
+
+    def enable(self, enable):
+        self._enable = enable
+
+    def record(self, name):
+        if self._enable is False:
+            return
+        timestamp = int(round(_time() * 1000000))
+        self.time_record.append('{}:{} '.format(name, timestamp))
+        return timestamp
+
+    def print_profile(self):
+        if self._enable is False:
+            return
+        sys.stderr.write(self.gen_profile_str())
+
+    def gen_profile_str(self):
+        if self._enable is False:
+            return
+        self.time_record.append('\n')
+        profile_str = ''.join(self.time_record)
+        self.time_record = [self.print_head]
+        return profile_str
 
 
 class TimeProfiler(object):
@@ -42,12 +197,13 @@ class TimeProfiler(object):
     def record(self, name_with_tag):
         if self._enable is False:
             return
-        timestamp = int(round(time.time() * 1000000))
+        timestamp = int(round(_time() * 1000000))
         name_with_tag = name_with_tag.split("_")
         tag = name_with_tag[-1]
         name = '_'.join(name_with_tag[:-1])
         with self._lock:
             self._time_record.put((name, tag, timestamp))
+        return timestamp
 
     def print_profile(self):
         if self._enable is False:

python/pipeline/util.py

@@ -13,13 +13,101 @@
 # limitations under the License.
 
 import sys
+import logging
+import threading
+import multiprocessing
+import multiprocessing.managers
+if sys.version_info.major == 2:
+    import Queue
+    from Queue import PriorityQueue
+elif sys.version_info.major == 3:
+    import queue as Queue
+    from queue import PriorityQueue
+else:
+    raise Exception("Error Python version")
+
+_LOGGER = logging.getLogger(__name__)
 
 
 class NameGenerator(object):
+    # use unsafe-id-generator
     def __init__(self, prefix):
         self._idx = -1
         self._prefix = prefix
+        self._id_generator = UnsafeIdGenerator(1000000000000000000)
+
+    def next(self):
+        next_id = self._id_generator.next()
+        return "{}{}".format(self._prefix, next_id)
+
+
+class UnsafeIdGenerator(object):
+    def __init__(self, max_id, base_counter=0, step=1):
+        self._base_counter = base_counter
+        self._counter = self._base_counter
+        self._step = step
+        self._max_id = max_id  # for reset
+
+    def next(self):
+        if self._counter >= self._max_id:
+            self._counter = self._base_counter
+            _LOGGER.info("Reset Id: {}".format(self._counter))
+        next_id = self._counter
+        self._counter += self._step
+        return next_id
+
+
+class ThreadIdGenerator(UnsafeIdGenerator):
+    def __init__(self, max_id, base_counter=0, step=1, lock=None):
+        # if you want to use your lock, you may need to use Reentrant-Lock
+        self._lock = lock
+        if self._lock is None:
+            self._lock = threading.Lock()
+        super(ThreadIdGenerator, self).__init__(max_id, base_counter, step)
 
     def next(self):
-        self._idx += 1
-        return "{}{}".format(self._prefix, self._idx)
+        next_id = None
+        with self._lock:
+            if self._counter >= self._max_id:
+                self._counter = self._base_counter
+                _LOGGER.info("Reset Id: {}".format(self._counter))
+            next_id = self._counter
+            self._counter += self._step
+        return next_id
+
+
+class ProcessIdGenerator(UnsafeIdGenerator):
+    def __init__(self, max_id, base_counter=0, step=1, lock=None):
+        # if you want to use your lock, you may need to use Reentrant-Lock
+        self._lock = lock
+        if self._lock is None:
+            self._lock = multiprocessing.Lock()
+        self._base_counter = base_counter
+        self._counter = multiprocessing.Manager().Value('i', 0)
+        self._step = step
+        self._max_id = max_id
+
+    def next(self):
+        next_id = None
+        with self._lock:
+            if self._counter.value >= self._max_id:
+                self._counter.value = self._base_counter
+                _LOGGER.info("Reset Id: {}".format(self._counter.value))
+            next_id = self._counter.value
+            self._counter.value += self._step
+        return next_id
+
+
+def PipelineProcSyncManager():
+    """
+    add PriorityQueue into SyncManager, see more: 
+    https://stackoverflow.com/questions/25324560/strange-queue-priorityqueue-behaviour-with-multiprocessing-in-python-2-7-6?answertab=active#tab-top
+    """
+
+    class PipelineManager(multiprocessing.managers.SyncManager):
+        pass
+
+    PipelineManager.register("PriorityQueue", PriorityQueue)
+    m = PipelineManager()
+    m.start()
+    return m

tools/serving_build.sh

@@ -776,7 +776,7 @@ function python_test_pipeline(){
             # test: thread servicer & thread op
             cat << EOF > config.yml
 port: 18080
-worker_num: 2
+worker_num: 4
 build_dag_each_worker: false
 dag:
     is_thread_op: true
@@ -793,7 +793,7 @@ EOF
             # test: thread servicer & process op
             cat << EOF > config.yml
 port: 18080
-worker_num: 2
+worker_num: 4
 build_dag_each_worker: false
 dag:
     is_thread_op: false
@@ -807,13 +807,13 @@ EOF
             ps -ef | grep "pipeline_server" | grep -v grep | awk '{print $2}' | xargs kill
             kill_process_by_port 18080
 
-            # test: process servicer & thread op
+            # test: process servicer & process op
             cat << EOF > config.yml
 port: 18080
-worker_num: 2
-build_dag_each_worker: true
+worker_num: 4
+build_dag_each_worker: false
 dag:
-    is_thread_op: flase
+    is_thread_op: false
     client_type: brpc
     retry: 1
     use_profile: false
@@ -823,12 +823,14 @@ EOF
             check_cmd "python test_pipeline_client.py"
             ps -ef | grep "pipeline_server" | grep -v grep | awk '{print $2}' | xargs kill
             kill_process_by_port 18080
-
-            # test: process servicer & process op
+            
+            # test: process servicer & thread op
+            pip uninstall grpcio -y
+            pip install grpcio --no-binary=grpcio
             cat << EOF > config.yml
 port: 18080
-worker_num: 2
-build_dag_each_worker: false
+worker_num: 4
+build_dag_each_worker: true
 dag:
     is_thread_op: false
     client_type: brpc
@@ -840,7 +842,7 @@ EOF
             check_cmd "python test_pipeline_client.py"
             ps -ef | grep "pipeline_server" | grep -v grep | awk '{print $2}' | xargs kill
             kill_process_by_port 18080
-            
+
             kill_server_process
             kill_process_by_port 9292
             kill_process_by_port 9393
@@ -851,7 +853,7 @@ EOF
             sleep 5
             cat << EOF > config.yml
 port: 18080
-worker_num: 2
+worker_num: 4
 build_dag_each_worker: false
 dag:
     is_thread_op: false