diff --git a/README.md b/README.md index 870f2f587f35ba1526c49f58698ae4db17ff0f81..dfd37eb32e9f380918df5823bae1c68e54204d07 100644 --- a/README.md +++ b/README.md @@ -172,6 +172,11 @@ Here, `client.predict` function has two arguments. `feed` is a `python dict` wit - [An End-to-end tutorial from training to inference service deployment](doc/TRAIN_TO_SERVICE.md) - [Write Bert-as-Service in 10 minutes](doc/BERT_10_MINS.md) +### Tutorial at AIStudio +- [Introduction to PaddleServing](https://aistudio.baidu.com/aistudio/projectdetail/605819) +- [Image Segmentation on Paddle Serving](https://aistudio.baidu.com/aistudio/projectdetail/457715) +- [Sentimental Analysis](https://aistudio.baidu.com/aistudio/projectdetail/509014) + ### Developers - [How to config Serving native operators on server side?](doc/SERVER_DAG.md) - [How to develop a new Serving operator?](doc/NEW_OPERATOR.md) diff --git a/README_CN.md b/README_CN.md index 6317a79513a3d5e3247d249885d8bfe06de0e1c9..e00f81b059f2b195149f23a5f465262666647664 100644 --- a/README_CN.md +++ b/README_CN.md @@ -169,6 +169,11 @@ print(fetch_map) - [端到端完成从训练到部署全流程](doc/TRAIN_TO_SERVICE_CN.md) - [十分钟构建Bert-As-Service](doc/BERT_10_MINS_CN.md) +### AIStudio教程 +- [PaddleServing作业](https://aistudio.baidu.com/aistudio/projectdetail/605819) +- [PaddleServing图像分割](https://aistudio.baidu.com/aistudio/projectdetail/457715) +- [PaddleServing情感分析](https://aistudio.baidu.com/aistudio/projectdetail/509014) + ### 开发者教程 - [如何配置Server端的计算图?](doc/SERVER_DAG_CN.md) - [如何开发一个新的General Op?](doc/NEW_OPERATOR_CN.md) diff --git a/core/configure/proto/multi_lang_general_model_service.proto b/core/configure/proto/multi_lang_general_model_service.proto index b83450aed666b96de324050d53b10c56e059a8d5..c23f4dbb243e8d23b8e4bfef419649b262f0dcd3 100644 --- a/core/configure/proto/multi_lang_general_model_service.proto +++ b/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 { diff --git a/core/general-client/include/general_model.h b/core/general-client/include/general_model.h index b5d27df5edbaf9278ecb8614e282d104347206f8..a81a0005473f3eb4039dd77aa430957e52eda687 100644 --- a/core/general-client/include/general_model.h +++ b/core/general-client/include/general_model.h @@ -227,7 +227,8 @@ class PredictorClient { const std::vector>& int_shape, const std::vector& fetch_name, PredictorRes& predict_res_batch, // NOLINT - const int& pid); + const int& pid, + const uint64_t log_id); int numpy_predict( const std::vector>>& float_feed_batch, @@ -238,7 +239,8 @@ class PredictorClient { const std::vector>& int_shape, const std::vector& fetch_name, PredictorRes& predict_res_batch, // NOLINT - const int& pid); + const int& pid, + const uint64_t log_id); private: PredictorApi _api; diff --git a/core/general-client/src/general_model.cpp b/core/general-client/src/general_model.cpp index 9f709c71045577f7b043777a7ad1528a0e2ccc28..6804a9e80d4140d02a5d46c7f3358f2403ee4fbb 100644 --- a/core/general-client/src/general_model.cpp +++ b/core/general-client/src/general_model.cpp @@ -144,7 +144,8 @@ int PredictorClient::batch_predict( const std::vector> &int_shape, const std::vector &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> &int_shape, const std::vector &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); } diff --git a/core/general-client/src/pybind_general_model.cpp b/core/general-client/src/pybind_general_model.cpp index 3e065e4de1ff3c01ff6bc05cb39a2607620915b4..1e79a8d2489a9ebc2024402bada32a4be2000146 100644 --- a/core/general-client/src/pybind_general_model.cpp +++ b/core/general-client/src/pybind_general_model.cpp @@ -107,7 +107,8 @@ PYBIND11_MODULE(serving_client, m) { const std::vector> &int_shape, const std::vector &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()) .def("numpy_predict", @@ -131,7 +133,8 @@ PYBIND11_MODULE(serving_client, m) { const std::vector> &int_shape, const std::vector &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()); } diff --git a/core/general-server/op/general_copy_op.cpp b/core/general-server/op/general_copy_op.cpp index 322bcc07795f1b053847991eae17cb3922dd7a7b..0391a98bcb7f471c0a0687dd9deb7b404a15a2bf 100644 --- a/core/general-server/op/general_copy_op.cpp +++ b/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(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(); + 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(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; } diff --git a/core/general-server/op/general_dist_kv_infer_op.cpp b/core/general-server/op/general_dist_kv_infer_op.cpp index adaa6cbc1818fc5300faf662d98ad47c9af4c468..6809907226511f7de576f1e2bbdc21b7ac401422 100644 --- a/core/general-server/op/general_dist_kv_infer_op.cpp +++ b/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(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(); 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 keys; std::vector values; int sparse_count = 0; @@ -96,13 +98,14 @@ int GeneralDistKVInferOp::inference() { rec::mcube::CubeAPI *cube = rec::mcube::CubeAPI::instance(); std::vector 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; } diff --git a/core/general-server/op/general_dist_kv_quant_infer_op.cpp b/core/general-server/op/general_dist_kv_quant_infer_op.cpp index 8752e8a72085c946b097cecf62a0bdbf90d682c4..93ce76f3d3399ac62435352d2271154ab7f84235 100644 --- a/core/general-server/op/general_dist_kv_quant_infer_op.cpp +++ b/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 keys; std::vector values; int sparse_count = 0; @@ -94,13 +97,14 @@ int GeneralDistKVQuantInferOp::inference() { rec::mcube::CubeAPI *cube = rec::mcube::CubeAPI::instance(); std::vector 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; } diff --git a/core/general-server/op/general_infer_helper.h b/core/general-server/op/general_infer_helper.h index 4fa1995664a2dca449ebc228079c86919a32d328..9b5a023b8f5df49c6fb5404f11d7e4c7b2979176 100644 --- a/core/general-server/op/general_infer_helper.h +++ b/core/general-server/op/general_infer_helper.h @@ -35,6 +35,7 @@ struct GeneralBlob { std::vector tensor_vector; int64_t time_stamp[20]; int p_size = 0; + uint64_t _log_id = -1; // for logging int _batch_size; @@ -46,9 +47,11 @@ struct GeneralBlob { tensor_vector.clear(); } - int SetBatchSize(int batch_size) { _batch_size = batch_size; } + void SetBatchSize(int batch_size) { _batch_size = batch_size; } + void SetLogId(uint64_t log_id) { _log_id = log_id; } int GetBatchSize() const { return _batch_size; } + uint64_t GetLogId() const { return _log_id; } std::string ShortDebugString() const { return "Not implemented!"; } }; diff --git a/core/general-server/op/general_infer_op.cpp b/core/general-server/op/general_infer_op.cpp index a9ff2e7226b25842889e391d82217b3b6a140170..1fe9e738c001163b9d14beea25f8c311b861510a 100644 --- a/core/general-server/op/general_infer_op.cpp +++ b/core/general-server/op/general_infer_op.cpp @@ -47,22 +47,25 @@ int GeneralInferOp::inference() { const std::string pre_name = pre_node_names[0]; const GeneralBlob *input_blob = get_depend_argument(pre_name); - VLOG(2) << "Get precedent op name: " << pre_name; + uint64_t log_id = input_blob->GetLogId(); + VLOG(2) << "(logid=" << log_id << ") Get precedent op name: " << pre_name; GeneralBlob *output_blob = mutable_data(); + output_blob->SetLogId(log_id); if (!input_blob) { - LOG(ERROR) << "Failed mutable depended argument, op:" << pre_name; + LOG(ERROR) << "(logid=" << log_id + << ") Failed mutable depended argument, op:" << pre_name; return -1; } const TensorVector *in = &input_blob->tensor_vector; TensorVector *out = &output_blob->tensor_vector; int batch_size = input_blob->GetBatchSize(); - VLOG(2) << "input batch size: " << batch_size; + VLOG(2) << "(logid=" << log_id << ") input batch size: " << batch_size; output_blob->SetBatchSize(batch_size); - VLOG(2) << "infer batch size: " << batch_size; + VLOG(2) << "(logid=" << log_id << ") infer batch size: " << batch_size; Timer timeline; int64_t start = timeline.TimeStampUS(); @@ -70,7 +73,8 @@ int GeneralInferOp::inference() { if (InferManager::instance().infer( engine_name().c_str(), in, out, batch_size)) { - LOG(ERROR) << "Failed do infer in fluid model: " << engine_name().c_str(); + LOG(ERROR) << "(logid=" << log_id + << ") Failed do infer in fluid model: " << engine_name().c_str(); return -1; } diff --git a/core/general-server/op/general_reader_op.cpp b/core/general-server/op/general_reader_op.cpp index 380f861606a7719a33407dd946c5ac476629fdb7..8a4aa1a11edd27a4c035cf707e335ac70647365b 100644 --- a/core/general-server/op/general_reader_op.cpp +++ b/core/general-server/op/general_reader_op.cpp @@ -37,9 +37,9 @@ int conf_check(const Request *req, const std::shared_ptr &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(get_request_message()); + uint64_t log_id = req->log_id(); int batch_size = req->insts_size(); int input_var_num = 0; @@ -83,25 +84,28 @@ int GeneralReaderOp::inference() { TensorVector *out = &res->tensor_vector; res->SetBatchSize(batch_size); + res->SetLogId(log_id); if (!res) { - LOG(ERROR) << "Failed get op tls reader object output"; + LOG(ERROR) << "(logid=" << log_id + << ") Failed get op tls reader object output"; } Timer timeline; int64_t start = timeline.TimeStampUS(); int var_num = req->insts(0).tensor_array_size(); - VLOG(2) << "var num: " << var_num; + VLOG(2) << "(logid=" << log_id << ") var num: " << var_num; - VLOG(2) << "start to call load general model_conf op"; + VLOG(2) << "(logid=" << log_id + << ") start to call load general model_conf op"; baidu::paddle_serving::predictor::Resource &resource = baidu::paddle_serving::predictor::Resource::instance(); - VLOG(2) << "get resource pointer done."; + VLOG(2) << "(logid=" << log_id << ") get resource pointer done."; std::shared_ptr model_config = resource.get_general_model_config(); - VLOG(2) << "print general model config done."; + VLOG(2) << "(logid=" << log_id << ") print general model config done."; // TODO(guru4elephant): how to do conditional check? /* @@ -122,7 +126,8 @@ int GeneralReaderOp::inference() { for (int i = 0; i < var_num; ++i) { paddle::PaddleTensor lod_tensor; elem_type[i] = req->insts(0).tensor_array(i).elem_type(); - VLOG(2) << "var[" << i << "] has elem type: " << elem_type[i]; + VLOG(2) << "(logid=" << log_id << ") var[" << i + << "] has elem type: " << elem_type[i]; if (elem_type[i] == 0) { // int64 elem_size[i] = sizeof(int64_t); lod_tensor.dtype = paddle::PaddleDType::INT64; @@ -137,17 +142,19 @@ int GeneralReaderOp::inference() { if (model_config->_is_lod_feed[i]) { lod_tensor.lod.resize(1); lod_tensor.lod[0].push_back(0); - VLOG(2) << "var[" << i << "] is lod_tensor"; + VLOG(2) << "(logid=" << log_id << ") var[" << i << "] is lod_tensor"; } else { lod_tensor.shape.push_back(batch_size); capacity[i] = 1; for (int k = 0; k < req->insts(0).tensor_array(i).shape_size(); ++k) { int dim = req->insts(0).tensor_array(i).shape(k); - VLOG(2) << "shape for var[" << i << "]: " << dim; + VLOG(2) << "(logid=" << log_id << ") shape for var[" << i + << "]: " << dim; capacity[i] *= dim; lod_tensor.shape.push_back(dim); } - VLOG(2) << "var[" << i << "] is tensor, capacity: " << capacity[i]; + VLOG(2) << "(logid=" << log_id << ") var[" << i + << "] is tensor, capacity: " << capacity[i]; } lod_tensor.name = model_config->_feed_name[i]; out->push_back(lod_tensor); @@ -167,11 +174,12 @@ int GeneralReaderOp::inference() { } else if (tensor.int_data_size() > 0) { data_len = tensor.int_data_size(); } - VLOG(2) << "tensor size for var[" << i << "]: " << data_len; + VLOG(2) << "(logid=" << log_id << ") tensor size for var[" << i + << "]: " << data_len; tensor_size += data_len; int cur_len = out->at(i).lod[0].back(); - VLOG(2) << "current len: " << cur_len; + VLOG(2) << "(logid=" << log_id << ") current len: " << cur_len; int sample_len = 0; if (tensor.shape_size() == 1) { @@ -180,7 +188,7 @@ int GeneralReaderOp::inference() { sample_len = tensor.shape(0); } out->at(i).lod[0].push_back(cur_len + sample_len); - VLOG(2) << "new len: " << cur_len + sample_len; + VLOG(2) << "(logid=" << log_id << ") new len: " << cur_len + sample_len; } out->at(i).data.Resize(tensor_size * elem_size[i]); out->at(i).shape = {out->at(i).lod[0].back()}; @@ -190,11 +198,11 @@ int GeneralReaderOp::inference() { if (out->at(i).shape.size() == 1) { out->at(i).shape.push_back(1); } - VLOG(2) << "var[" << i + VLOG(2) << "(logid=" << log_id << ") var[" << i << "] is lod_tensor and len=" << out->at(i).lod[0].back(); } else { out->at(i).data.Resize(batch_size * capacity[i] * elem_size[i]); - VLOG(2) << "var[" << i + VLOG(2) << "(logid=" << log_id << ") var[" << i << "] is tensor and capacity=" << batch_size * capacity[i]; } } @@ -203,8 +211,8 @@ int GeneralReaderOp::inference() { for (int i = 0; i < var_num; ++i) { if (elem_type[i] == 0) { int64_t *dst_ptr = static_cast(out->at(i).data.data()); - VLOG(2) << "first element data in var[" << i << "] is " - << req->insts(0).tensor_array(i).int64_data(0); + VLOG(2) << "(logid=" << log_id << ") first element data in var[" << i + << "] is " << req->insts(0).tensor_array(i).int64_data(0); int offset = 0; for (int j = 0; j < batch_size; ++j) { int elem_num = req->insts(j).tensor_array(i).int64_data_size(); @@ -219,8 +227,8 @@ int GeneralReaderOp::inference() { } } else if (elem_type[i] == 1) { float *dst_ptr = static_cast(out->at(i).data.data()); - VLOG(2) << "first element data in var[" << i << "] is " - << req->insts(0).tensor_array(i).float_data(0); + VLOG(2) << "(logid=" << log_id << ") first element data in var[" << i + << "] is " << req->insts(0).tensor_array(i).float_data(0); int offset = 0; for (int j = 0; j < batch_size; ++j) { int elem_num = req->insts(j).tensor_array(i).float_data_size(); @@ -235,8 +243,8 @@ int GeneralReaderOp::inference() { } } else if (elem_type[i] == 2) { int32_t *dst_ptr = static_cast(out->at(i).data.data()); - VLOG(2) << "first element data in var[" << i << "] is " - << req->insts(0).tensor_array(i).int_data(0); + VLOG(2) << "(logid=" << log_id << ") first element data in var[" << i + << "] is " << req->insts(0).tensor_array(i).int_data(0); int offset = 0; for (int j = 0; j < batch_size; ++j) { int elem_num = req->insts(j).tensor_array(i).int_data_size(); @@ -252,7 +260,7 @@ int GeneralReaderOp::inference() { } } - VLOG(2) << "output size: " << out->size(); + VLOG(2) << "(logid=" << log_id << ") output size: " << out->size(); timeline.Pause(); int64_t end = timeline.TimeStampUS(); @@ -260,7 +268,7 @@ int GeneralReaderOp::inference() { AddBlobInfo(res, start); AddBlobInfo(res, end); - VLOG(2) << "read data from client success"; + VLOG(2) << "(logid=" << log_id << ") read data from client success"; return 0; } DEFINE_OP(GeneralReaderOp); diff --git a/core/general-server/op/general_response_op.cpp b/core/general-server/op/general_response_op.cpp index b2d918bef0f3c715aa69f52a65edd48cdcc5e87b..3a723e5ce4a19a1fd1754d01b95c4f9ad580b5fe 100644 --- a/core/general-server/op/general_response_op.cpp +++ b/core/general-server/op/general_response_op.cpp @@ -42,6 +42,9 @@ using baidu::paddle_serving::predictor::PaddleGeneralModelConfig; int GeneralResponseOp::inference() { const std::vector 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(pre_node_names[0])->GetLogId(); const Request *req = dynamic_cast(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 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 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(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(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(in->at(idx).data.data()); google::protobuf::RepeatedField tmp_data(data_ptr, data_ptr + cap); fetch_p->mutable_tensor_array(var_idx)->mutable_float_data()->Swap( &tmp_data); } else if (dtype == paddle::PaddleDType::INT32) { - VLOG(2) << "Prepare int32 var [" << model_config->_fetch_name[idx] - << "]."; + VLOG(2) << "(logid=" << log_id << ")Prepare int32 var [" + << model_config->_fetch_name[idx] << "]."; int32_t *data_ptr = static_cast(in->at(idx).data.data()); google::protobuf::RepeatedField tmp_data(data_ptr, data_ptr + cap); @@ -154,7 +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(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; diff --git a/core/general-server/op/general_text_reader_op.cpp b/core/general-server/op/general_text_reader_op.cpp index 154e975d314a72515624b7bbf1aff85f70b8b5d3..3fa433c6cc31a3dbce331013780212d50e7f643c 100644 --- a/core/general-server/op/general_text_reader_op.cpp +++ b/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(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 capacity; GeneralBlob *res = mutable_data(); - 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 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); diff --git a/core/general-server/op/general_text_response_op.cpp b/core/general-server/op/general_text_response_op.cpp index ae194119f1fc3edad01662041035f7011873998a..03eea7d76c83782b661ea4553fc5fc0eee99e372 100644 --- a/core/general-server/op/general_text_response_op.cpp +++ b/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 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(pre_node_names[0])->GetLogId(); const Request *req = dynamic_cast(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 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(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(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; diff --git a/core/general-server/proto/general_model_service.proto b/core/general-server/proto/general_model_service.proto index 8581ecb2a2e10deced910a20ce26c2beaca956fa..e7dd5fccf54be43db8e65a9ed1112ceaece93700 100644 --- a/core/general-server/proto/general_model_service.proto +++ b/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 { diff --git a/core/general-server/proto/load_general_model_service.proto b/core/general-server/proto/load_general_model_service.proto index b8a86497f8c0b683f4e95f4517d83f576e79baad..f844bd5b2c0ddb34a32d00559b087c2fbb2ebfed 100644 --- a/core/general-server/proto/load_general_model_service.proto +++ b/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 { diff --git a/core/pdcodegen/plugin/pdcodegen b/core/pdcodegen/plugin/pdcodegen deleted file mode 100755 index bb81217121a15b99cda8a320f357f716357f96c5..0000000000000000000000000000000000000000 Binary files a/core/pdcodegen/plugin/pdcodegen and /dev/null differ diff --git a/core/pdcodegen/src/pdcodegen.cpp b/core/pdcodegen/src/pdcodegen.cpp index af4081a985ece584f82120799fc9a384f83830be..c505ca66385dd363ad0a76470012f07a925bcd17 100644 --- a/core/pdcodegen/src/pdcodegen.cpp +++ b/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(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(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(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(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", diff --git a/core/predictor/framework/channel.h b/core/predictor/framework/channel.h index a48368329469f36ab7881972e6a7059ab8066b5d..67808be16409cdf0610363d0039accf0f3a9d5cb 100644 --- a/core/predictor/framework/channel.h +++ b/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; } diff --git a/core/predictor/framework/dag.cpp b/core/predictor/framework/dag.cpp index f039ac70ffe2e55a59f926d754ca411a034058f4..c45952f8fb8f3b6d48c2e1295d6a43d45ad185e5 100644 --- a/core/predictor/framework/dag.cpp +++ b/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::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(); diff --git a/core/predictor/framework/dag_view.cpp b/core/predictor/framework/dag_view.cpp index bde8084b41fee00bc95d2a35444a15258d2a12a8..29a4e97378c20d6f9caae8a97de7dc5f714960e9 100644 --- a/core/predictor/framework/dag_view.cpp +++ b/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(); @@ -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(); 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(); 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(); diff --git a/core/predictor/framework/dag_view.h b/core/predictor/framework/dag_view.h index 4999f64b47eb667e90437d387a5ac5ba5337fc64..8ba9d224c577b475d0a52b79e92f72bd1abaa187 100644 --- a/core/predictor/framework/dag_view.h +++ b/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; } diff --git a/core/predictor/framework/service.cpp b/core/predictor/framework/service.cpp index 95c7db9f96a6e78522190e3f522d38669423475b..cb02a3278b37bd76631193fbd78cf026eed633c9 100644 --- a/core/predictor/framework/service.cpp +++ b/core/predictor/framework/service.cpp @@ -19,6 +19,7 @@ #include // butil::Timer #endif +#include #include #include #include @@ -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* workflows = _map_request_to_workflow(request); + VLOG(2) << "(logid=" << log_id << ") enable map request == True"; + std::vector* 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* 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* InferService::_map_request_to_workflow( std::vector* 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; } diff --git a/core/predictor/framework/service.h b/core/predictor/framework/service.h index ef6d3a3a468d1fc47c3012ad5d664bb64595a52c..d3fb0b988f002ab68d28173f9993c02b8eb76813 100644 --- a/core/predictor/framework/service.h +++ b/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* _map_request_to_workflow( - const google::protobuf::Message* request); + const google::protobuf::Message* request, const uint64_t log_id); private: std::vector _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; } diff --git a/core/predictor/framework/workflow.cpp b/core/predictor/framework/workflow.cpp index 16c4a6e9f475bf575f84bd24764d6348ac65120c..147ab36b79330c781c605d2d29ffb04c4f761aa7 100644 --- a/core/predictor/framework/workflow.cpp +++ b/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(); } else if (_type == "Parallel") { view = butil::get_object(); } 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; } diff --git a/core/predictor/framework/workflow.h b/core/predictor/framework/workflow.h index a4b3ed1dadccaa24cbeb6813ec7bcc18bac2aad8..14e4d567a540a19579208c91d046ba83de1679e3 100644 --- a/core/predictor/framework/workflow.h +++ b/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; } diff --git a/core/predictor/op/op.cpp b/core/predictor/op/op.cpp index 59ef6aed71977a3f762ff4fbe9480db19cb4057e..33dba2b506543ed1103cb0b456f5f054969f17fa 100644 --- a/core/predictor/op/op.cpp +++ b/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(); 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; } diff --git a/core/predictor/op/op.h b/core/predictor/op/op.h index ae52975fe6f2506fb0bf483318f607df137c8a96..ea700cce164805d04ddd10b72311f068245e2f10 100644 --- a/core/predictor/op/op.h +++ b/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(); diff --git a/core/sdk-cpp/proto/general_model_service.proto b/core/sdk-cpp/proto/general_model_service.proto index 51c0335a9db896e1260e83915de81e51451a904b..9988b298bdd22210fbe3127b9e4b57c89077f3ff 100644 --- a/core/sdk-cpp/proto/general_model_service.proto +++ b/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 { diff --git a/doc/COMPILE.md b/doc/COMPILE.md index 532a030a06dde79e8a1308bfdfc5ae1e5a62d01f..df9da776f0cb322d7da5f8f9de0f3f1054ed5d2a 100644 --- a/doc/COMPILE.md +++ b/doc/COMPILE.md @@ -23,7 +23,7 @@ | libXext | 1.3.3 | | libSM | 1.2.2 | | libXrender | 0.9.10 | -| python-whl | numpy>=1.12, <=1.16.4
google>=2.0.3
protobuf>=3.12.2
grpcio-tools>=1.28.1
grpcio>=1.28.1
func-timeout>=4.3.5
pyyaml>=1.3.0
sentencepiece==0.1.92
flask>=1.1.2
ujson>=2.0.3 | +| python-whl | numpy>=1.12, <=1.16.4
wheel>=0.34.0, <0.35.0
setuptools>=44.1.0
opencv-python==4.2.0.32
google>=2.0.3
protobuf>=3.12.2
grpcio-tools>=1.28.1
grpcio>=1.28.1
func-timeout>=4.3.5
pyyaml>=1.3.0
sentencepiece==0.1.92
flask>=1.1.2
ujson>=2.0.3 | It is recommended to use Docker for compilation. We have prepared the Paddle Serving compilation environment for you, see [this document](DOCKER_IMAGES.md). diff --git a/doc/COMPILE_CN.md b/doc/COMPILE_CN.md index a38faff4289a4946d82f8b4a71afd521c7cd48fd..1235653e69161ba8f71d3f8098a1860dca4d357d 100644 --- a/doc/COMPILE_CN.md +++ b/doc/COMPILE_CN.md @@ -23,7 +23,7 @@ | libXext | 1.3.3 | | libSM | 1.2.2 | | libXrender | 0.9.10 | -| python-whl | numpy>=1.12, <=1.16.4
google>=2.0.3
protobuf>=3.12.2
grpcio-tools>=1.28.1
grpcio>=1.28.1
func-timeout>=4.3.5
pyyaml>=1.3.0
sentencepiece==0.1.92
flask>=1.1.2
ujson>=2.0.3 | +| python-whl | numpy>=1.12, <=1.16.4
wheel>=0.34.0, <0.35.0
setuptools>=44.1.0
opencv-python==4.2.0.32
google>=2.0.3
protobuf>=3.12.2
grpcio-tools>=1.28.1
grpcio>=1.28.1
func-timeout>=4.3.5
pyyaml>=1.3.0
sentencepiece==0.1.92
flask>=1.1.2
ujson>=2.0.3 | 推荐使用Docker编译，我们已经为您准备好了Paddle Serving编译环境，详见[该文档](DOCKER_IMAGES_CN.md)。 diff --git a/doc/INFERENCE_TO_SERVING.md b/doc/INFERENCE_TO_SERVING.md index 8334159ea255ca65241a2b567e43682a148bb775..e10ee976fb455c8cc49a0d5fa44ed4cc1f300ba9 100644 --- a/doc/INFERENCE_TO_SERVING.md +++ b/doc/INFERENCE_TO_SERVING.md @@ -2,6 +2,20 @@ ([简体中文](./INFERENCE_TO_SERVING_CN.md)|English) +We should know something before converting to serving model + +**inference_model_dir**：the directory of Paddle inference model + +**serving_client_dir**: the directory of server side configuration + +**serving_client_dir**: the directory of client side configuration + +**model_filename**: this is model description file whose default value is `__model__`, if it's not default name, set `model_filename` explicitly + +**params_filename**: during `save_inference_model` every Variable will be save as a single file. If we have the inference model whose params are compressed into one file, please set `params_filename` explicitly + + + ## Example ``` python @@ -12,3 +26,11 @@ serving_server_dir = "serving_server_dir" feed_var_names, fetch_var_names = inference_model_to_serving( inference_model_dir, serving_client_dir, serving_server_dir) ``` + +if your model file and params file are both standalone, please use the following api. + +``` +feed_var_names, fetch_var_names = inference_model_to_serving( + inference_model_dir, serving_client_dir, serving_server_dir, + model_filename="model", params_filename="params") +``` diff --git a/doc/INFERENCE_TO_SERVING_CN.md b/doc/INFERENCE_TO_SERVING_CN.md index 94d1def424db467e200020c69fbd6d1599a5ffde..e7e909ac04be3b1a0885b3390d99a153dfbd170e 100644 --- a/doc/INFERENCE_TO_SERVING_CN.md +++ b/doc/INFERENCE_TO_SERVING_CN.md @@ -4,6 +4,19 @@ ## 示例 +在下列代码中，我们需要知道以下信息。 + +**模型文件夹**：这个文件夹就是Paddle的inference_model所在的文件夹 + +**serving_client_dir**: 这个文件夹是inference_model转换成Serving模型后，服务端配置的保存路径 + +**serving_client_dir**: 这个文件夹是inference_model转换成Serving模型后，客户端配置的保存路径 + +**模型描述文件**: 模型描述文件也就是`model_filename`默认值为`__model__`,是一个pb2文本文件，如果是别的文件名需要显式指定 + +**模型参数文件**: 在`save_inference_model`阶段，默认方式是每一个Variable保存一个二进制文件，如果是这种情况就不需要做指定。如果所有参数用压缩成一个文件的形式保存，则需要显式指定`params_filename` + + ``` python from paddle_serving_client.io import inference_model_to_serving inference_model_dir = "your_inference_model" @@ -12,3 +25,9 @@ serving_server_dir = "serving_server_dir" feed_var_names, fetch_var_names = inference_model_to_serving( inference_model_dir, serving_client_dir, serving_server_dir) ``` +如果模型中有模型描述文件`model_filename` 和 模型参数文件`params_filename`，那么请用 +``` +feed_var_names, fetch_var_names = inference_model_to_serving( + inference_model_dir, serving_client_dir, serving_server_dir, + model_filename="model", params_filename="params") +``` diff --git a/doc/PIPELINE_SERVING.md b/doc/PIPELINE_SERVING.md index bfc408c2a37813a4b5c301cff3ee9e1efa6be656..7270cc134558906f6989a2c315a1dd4e2a640c59 100644 --- a/doc/PIPELINE_SERVING.md +++ b/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 + ### 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 diff --git a/doc/PIPELINE_SERVING_CN.md b/doc/PIPELINE_SERVING_CN.md index 9e3fe9b9883c404eb476e81349d8a2096774bfc1..3214487c31bcc47ec67d2ad28d987bff845fa13b 100644 --- a/doc/PIPELINE_SERVING_CN.md +++ b/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 信息 diff --git a/doc/pipeline_serving-image1.png b/doc/pipeline_serving-image1.png index f46765124c8049dddc13092dec8e57dd2d932f73..731f54973946e46eb2d4e8d72d57d00239c4384a 100644 Binary files a/doc/pipeline_serving-image1.png and b/doc/pipeline_serving-image1.png differ diff --git a/java/src/main/java/io/paddle/serving/client/Client.java b/java/src/main/java/io/paddle/serving/client/Client.java index 1e09e0c23c89dd4f0d70e0c93269b2185a69807f..742d4f91ce17555a2ea96f2a629717228ba18cef 100644 --- a/java/src/main/java/io/paddle/serving/client/Client.java +++ b/java/src/main/java/io/paddle/serving/client/Client.java @@ -192,14 +192,16 @@ public class Client { private InferenceRequest _packInferenceRequest( List> feed_batch, - Iterable fetch) throws IllegalArgumentException { + Iterable fetch, + long log_id) throws IllegalArgumentException { List feed_var_names = new ArrayList(); 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 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 predict( HashMap feed, Iterable fetch) { - return predict(feed, fetch, false); + return predict(feed, fetch, false, 0); + } + + public Map predict( + HashMap feed, + Iterable fetch, + long log_id) { + return predict(feed, fetch, false, log_id); } public Map> ensemble_predict( HashMap feed, Iterable fetch) { - return ensemble_predict(feed, fetch, false); + return ensemble_predict(feed, fetch, false, 0); + } + + public Map> ensemble_predict( + HashMap feed, + Iterable fetch, + long log_id) { + return ensemble_predict(feed, fetch, false, log_id); } public PredictFuture asyn_predict( HashMap feed, Iterable fetch) { - return asyn_predict(feed, fetch, false); + return asyn_predict(feed, fetch, false, 0); + } + + public PredictFuture asyn_predict( + HashMap feed, + Iterable fetch, + long log_id) { + return asyn_predict(feed, fetch, false, log_id); } public Map predict( HashMap feed, Iterable fetch, Boolean need_variant_tag) { + return predict(feed, fetch, need_variant_tag, 0); + } + + public Map predict( + HashMap feed, + Iterable fetch, + Boolean need_variant_tag, + long log_id) { List> feed_batch = new ArrayList>(); feed_batch.add(feed); - return predict(feed_batch, fetch, need_variant_tag); + return predict(feed_batch, fetch, need_variant_tag, log_id); } - + public Map> ensemble_predict( HashMap feed, Iterable fetch, Boolean need_variant_tag) { + return ensemble_predict(feed, fetch, need_variant_tag, 0); + } + + public Map> ensemble_predict( + HashMap feed, + Iterable fetch, + Boolean need_variant_tag, + long log_id) { List> feed_batch = new ArrayList>(); 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 feed, Iterable fetch, Boolean need_variant_tag) { + return asyn_predict(feed, fetch, need_variant_tag, 0); + } + + public PredictFuture asyn_predict( + HashMap feed, + Iterable fetch, + Boolean need_variant_tag, + long log_id) { List> feed_batch = new ArrayList>(); 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 predict( List> feed_batch, Iterable fetch) { - return predict(feed_batch, fetch, false); + return predict(feed_batch, fetch, false, 0); + } + + public Map predict( + List> feed_batch, + Iterable fetch, + long log_id) { + return predict(feed_batch, fetch, false, log_id); } public Map> ensemble_predict( List> feed_batch, Iterable fetch) { - return ensemble_predict(feed_batch, fetch, false); + return ensemble_predict(feed_batch, fetch, false, 0); + } + + public Map> ensemble_predict( + List> feed_batch, + Iterable fetch, + long log_id) { + return ensemble_predict(feed_batch, fetch, false, log_id); } public PredictFuture asyn_predict( List> feed_batch, Iterable fetch) { - return asyn_predict(feed_batch, fetch, false); + return asyn_predict(feed_batch, fetch, false, 0); + } + + public PredictFuture asyn_predict( + List> feed_batch, + Iterable fetch, + long log_id) { + return asyn_predict(feed_batch, fetch, false, log_id); } public Map predict( List> feed_batch, Iterable fetch, Boolean need_variant_tag) { + return predict(feed_batch, fetch, need_variant_tag, 0); + } + + public Map predict( + List> feed_batch, + Iterable 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>>( 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> feed_batch, Iterable fetch, Boolean need_variant_tag) { + return ensemble_predict(feed_batch, fetch, need_variant_tag, 0); + } + + public Map> ensemble_predict( + List> feed_batch, + Iterable 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> feed_batch, Iterable 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> feed_batch, + Iterable fetch, + Boolean need_variant_tag, + long log_id) { + InferenceRequest req = _packInferenceRequest( + feed_batch, fetch, log_id); ListenableFuture future = futureStub_.inference(req); PredictFuture predict_future = new PredictFuture(future, (InferenceResponse resp) -> { diff --git a/java/src/main/proto/multi_lang_general_model_service.proto b/java/src/main/proto/multi_lang_general_model_service.proto index b83450aed666b96de324050d53b10c56e059a8d5..c23f4dbb243e8d23b8e4bfef419649b262f0dcd3 100644 --- a/java/src/main/proto/multi_lang_general_model_service.proto +++ b/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 { diff --git a/python/examples/blazeface/README.md b/python/examples/blazeface/README.md index f569841ce4a3ae69b1ff16041f7fb7d4617177f7..6f9d3c5adab5f3275989479078cb4329d14589fd 100644 --- a/python/examples/blazeface/README.md +++ b/python/examples/blazeface/README.md @@ -3,7 +3,7 @@ ## Get Model ``` python -m paddle_serving_app.package --get_model blazeface -tar -xzvf blazeface.tar.gz +tar -xf blazeface.tar.gz ``` ## RPC Service diff --git a/python/examples/ocr/README.md b/python/examples/ocr/README.md index ca9bbabdf57ce95763b25fec3751a85e4c8f9401..a0fc9f60160506183076233f33face1732a278c7 100644 --- a/python/examples/ocr/README.md +++ b/python/examples/ocr/README.md @@ -21,8 +21,13 @@ tar xf test_imgs.tar ### Start Service ``` +#choose one of cpu/gpu commands as following +#for cpu user +python -m paddle_serving_server.serve --model ocr_det_model --port 9293 +python ocr_web_server.py cpu +#for gpu user python -m paddle_serving_server_gpu.serve --model ocr_det_model --port 9293 --gpu_id 0 -python ocr_web_server.py +python ocr_web_server.py gpu ``` ### Client Prediction @@ -33,7 +38,11 @@ If you want a faster web service, please try Web Debugger Service ## Web Debugger Service ``` -python ocr_debugger_server.py +#choose one of cpu/gpu commands as following +#for cpu user +python ocr_debugger_server.py cpu +#for gpu user +python ocr_debugger_server.py gpu ``` ## Web Debugger Client Prediction @@ -54,15 +63,17 @@ Dataset: RCTW 500 sample images | Serving web service | 8.69 | 13.41 | 109.97 | 2.82 | 87.76 | 4.29 | 3.98 | 78.51 | 3.66 | 4.12 | 181.02 | 136.49 | 317.51 | | Serving Debugger web service | 8.73 | 16.42 | 115.27 | 2.93 | 20.63 | 3.97 | 4.48 | 13.84 | 3.60 | 6.91 | 49.45 | 147.33 | 196.78 | -## Appendix: Det or Rec only +## Appendix: For Users who want to launch Det or Rec only if you are going to detect images not recognize it or directly recognize the words from images. We also provide Det and Rec server for you. ### Det Server ``` -python det_web_server.py +python det_web_server.py cpu #for cpu user +python det_web_server.py gpu #for gpu user #or -python det_debugger_server.py +python det_debugger_server.py cpu #for cpu user +python det_debugger_server.py gpu #for gpu user ``` ### Det Client @@ -75,9 +86,11 @@ python ocr_web_client.py ### Rec Server ``` -python rec_web_server.py +python rec_web_server.py cpu #for cpu user +python rec_web_server.py gpu #for gpu user #or -python rec_debugger_server.py +python rec_debugger_server.py cpu #for cpu user +python rec_debugger_server.py gpu #for gpu user ``` ### Rec Client diff --git a/python/examples/ocr/README_CN.md b/python/examples/ocr/README_CN.md index 65bc066a43a34d1a35cb4236473c571106c5f61b..8bdc45cf8e390b378708fbee2dbfe318132aea44 100644 --- a/python/examples/ocr/README_CN.md +++ b/python/examples/ocr/README_CN.md @@ -15,19 +15,18 @@ wget --no-check-certificate https://paddle-serving.bj.bcebos.com/ocr/test_imgs.t tar xf test_imgs.tar ``` -### 客户端预测 - -``` -python ocr_rpc_client.py -``` - ## Web Service服务 ### 启动服务 ``` +#根据CPU/GPU设备选择一种启动方式 +#for cpu user +python -m paddle_serving_server.serve --model ocr_det_model --port 9293 +python ocr_web_server.py cpu +#for gpu user python -m paddle_serving_server_gpu.serve --model ocr_det_model --port 9293 --gpu_id 0 -python ocr_web_server.py +python ocr_web_server.py gpu ``` ### 启动客户端 @@ -38,7 +37,11 @@ python ocr_web_client.py 如果用户需要更快的执行速度，请尝试Debugger版Web服务 ## 启动Debugger版Web服务 ``` -python ocr_debugger_server.py +#根据CPU/GPU设备选择一种启动方式 +#for cpu user +python ocr_debugger_server.py cpu +#for gpu user +python ocr_debugger_server.py gpu ``` ## 启动客户端 @@ -66,9 +69,11 @@ GPU: Nvidia Tesla V100单卡 ### 启动检测服务 ``` -python det_web_server.py +python det_web_server.py cpu #for cpu user +python det_web_server.py gpu #for gpu user #or -python det_debugger_server.py +python det_debugger_server.py cpu #for cpu user +python det_debugger_server.py gpu #for gpu user ``` ### 检测服务客户端 @@ -81,9 +86,11 @@ python ocr_web_client.py ### 启动识别服务 ``` -python rec_web_server.py +python rec_web_server.py cpu #for cpu user +python rec_web_server.py gpu #for gpu user #or -python rec_debugger_server.py +python rec_debugger_server.py cpu #for cpu user +python rec_debugger_server.py gpu #for gpu user ``` ### 识别服务客户端 diff --git a/python/examples/ocr/det_debugger_server.py b/python/examples/ocr/det_debugger_server.py index acfccdb6d24a7e1ba490705dd147f21dbf921d31..913a0bb4c9a099cbef886beb3889337d024d10d6 100644 --- a/python/examples/ocr/det_debugger_server.py +++ b/python/examples/ocr/det_debugger_server.py @@ -21,7 +21,10 @@ from paddle_serving_client import Client from paddle_serving_app.reader import Sequential, ResizeByFactor from paddle_serving_app.reader import Div, Normalize, Transpose from paddle_serving_app.reader import DBPostProcess, FilterBoxes -from paddle_serving_server_gpu.web_service import WebService +if sys.argv[1] == 'gpu': + from paddle_serving_server_gpu.web_service import WebService +elif sys.argv[1] == 'cpu': + from paddle_serving_server.web_service import WebService import time import re import base64 @@ -64,8 +67,12 @@ class OCRService(WebService): ocr_service = OCRService(name="ocr") ocr_service.load_model_config("ocr_det_model") -ocr_service.set_gpus("0") -ocr_service.prepare_server(workdir="workdir", port=9292, device="gpu", gpuid=0) +if sys.argv[1] == 'gpu': + ocr_service.set_gpus("0") + ocr_service.prepare_server( + workdir="workdir", port=9292, device="gpu", gpuid=0) +elif sys.argv[1] == 'cpu': + ocr_service.prepare_server(workdir="workdir", port=9292) ocr_service.init_det() ocr_service.run_debugger_service() ocr_service.run_web_service() diff --git a/python/examples/ocr/det_web_server.py b/python/examples/ocr/det_web_server.py index dd69be0c70eb0f4dd627aa47ad33045a204f78c0..38c6541c70e9871d13dd81751d4edb2bc771a904 100644 --- a/python/examples/ocr/det_web_server.py +++ b/python/examples/ocr/det_web_server.py @@ -21,7 +21,10 @@ from paddle_serving_client import Client from paddle_serving_app.reader import Sequential, ResizeByFactor from paddle_serving_app.reader import Div, Normalize, Transpose from paddle_serving_app.reader import DBPostProcess, FilterBoxes -from paddle_serving_server_gpu.web_service import WebService +if sys.argv[1] == 'gpu': + from paddle_serving_server_gpu.web_service import WebService +elif sys.argv[1] == 'cpu': + from paddle_serving_server.web_service import WebService import time import re import base64 @@ -65,8 +68,12 @@ class OCRService(WebService): ocr_service = OCRService(name="ocr") ocr_service.load_model_config("ocr_det_model") -ocr_service.set_gpus("0") -ocr_service.prepare_server(workdir="workdir", port=9292, device="gpu", gpuid=0) +if sys.argv[1] == 'gpu': + ocr_service.set_gpus("0") + ocr_service.prepare_server( + workdir="workdir", port=9292, device="gpu", gpuid=0) +elif sys.argv[1] == 'cpu': + ocr_service.prepare_server(workdir="workdir", port=9292, device="cpu") ocr_service.init_det() ocr_service.run_rpc_service() ocr_service.run_web_service() diff --git a/python/examples/ocr/ocr_debugger_server.py b/python/examples/ocr/ocr_debugger_server.py index 93e2d7a3d1dc64451774ecf790c2ebd3b39f1d91..f7458c3036734e4bb6e554097029270e11912a3a 100644 --- a/python/examples/ocr/ocr_debugger_server.py +++ b/python/examples/ocr/ocr_debugger_server.py @@ -22,7 +22,10 @@ from paddle_serving_client import Client from paddle_serving_app.reader import Sequential, URL2Image, ResizeByFactor from paddle_serving_app.reader import Div, Normalize, Transpose from paddle_serving_app.reader import DBPostProcess, FilterBoxes, GetRotateCropImage, SortedBoxes -from paddle_serving_server_gpu.web_service import WebService +if sys.argv[1] == 'gpu': + from paddle_serving_server_gpu.web_service import WebService +elif sys.argv[1] == 'cpu': + from paddle_serving_server.web_service import WebService from paddle_serving_app.local_predict import Debugger import time import re @@ -37,8 +40,12 @@ class OCRService(WebService): (2, 0, 1)) ]) self.det_client = Debugger() - self.det_client.load_model_config( - det_model_config, gpu=True, profile=False) + if sys.argv[1] == 'gpu': + self.det_client.load_model_config( + det_model_config, gpu=True, profile=False) + elif sys.argv[1] == 'cpu': + self.det_client.load_model_config( + det_model_config, gpu=False, profile=False) self.ocr_reader = OCRReader() def preprocess(self, feed=[], fetch=[]): @@ -99,5 +106,8 @@ ocr_service = OCRService(name="ocr") ocr_service.load_model_config("ocr_rec_model") ocr_service.prepare_server(workdir="workdir", port=9292) ocr_service.init_det_debugger(det_model_config="ocr_det_model") -ocr_service.run_debugger_service(gpu=True) +if sys.argv[1] == 'gpu': + ocr_service.run_debugger_service(gpu=True) +elif sys.argv[1] == 'cpu': + ocr_service.run_debugger_service() ocr_service.run_web_service() diff --git a/python/examples/ocr/ocr_web_server.py b/python/examples/ocr/ocr_web_server.py index d017f6b9b560dc82158641b9f3a9f80137b40716..de83ca94a4c1f55d886175d9a87b6a34db34c2a5 100644 --- a/python/examples/ocr/ocr_web_server.py +++ b/python/examples/ocr/ocr_web_server.py @@ -22,7 +22,10 @@ from paddle_serving_client import Client from paddle_serving_app.reader import Sequential, URL2Image, ResizeByFactor from paddle_serving_app.reader import Div, Normalize, Transpose from paddle_serving_app.reader import DBPostProcess, FilterBoxes, GetRotateCropImage, SortedBoxes -from paddle_serving_server_gpu.web_service import WebService +if sys.argv[1] == 'gpu': + from paddle_serving_server_gpu.web_service import WebService +elif sys.argv[1] == 'cpu': + from paddle_serving_server.web_service import WebService import time import re import base64 @@ -90,8 +93,12 @@ class OCRService(WebService): ocr_service = OCRService(name="ocr") ocr_service.load_model_config("ocr_rec_model") -ocr_service.set_gpus("0") -ocr_service.prepare_server(workdir="workdir", port=9292, device="gpu", gpuid=0) +if sys.argv[1] == 'gpu': + ocr_service.set_gpus("0") + ocr_service.prepare_server( + workdir="workdir", port=9292, device="gpu", gpuid=0) +elif sys.argv[1] == 'cpu': + ocr_service.prepare_server(workdir="workdir", port=9292) ocr_service.init_det_client( det_port=9293, det_client_config="ocr_det_client/serving_client_conf.prototxt") diff --git a/python/examples/ocr/rec_web_server.py b/python/examples/ocr/rec_web_server.py index 684c313d4d50cfe00c576c81aad05a810525dcce..aae97fd9e3fbd1d29b6cf2ef160b92a522db2e22 100644 --- a/python/examples/ocr/rec_web_server.py +++ b/python/examples/ocr/rec_web_server.py @@ -22,7 +22,10 @@ from paddle_serving_client import Client from paddle_serving_app.reader import Sequential, URL2Image, ResizeByFactor from paddle_serving_app.reader import Div, Normalize, Transpose from paddle_serving_app.reader import DBPostProcess, FilterBoxes, GetRotateCropImage, SortedBoxes -from paddle_serving_server_gpu.web_service import WebService +if sys.argv[1] == 'gpu': + from paddle_serving_server_gpu.web_service import WebService +elif sys.argv[1] == 'cpu': + from paddle_serving_server.web_service import WebService import time import re import base64 @@ -64,8 +67,12 @@ class OCRService(WebService): ocr_service = OCRService(name="ocr") ocr_service.load_model_config("ocr_rec_model") -ocr_service.set_gpus("0") ocr_service.init_rec() -ocr_service.prepare_server(workdir="workdir", port=9292, device="gpu", gpuid=0) +if sys.argv[1] == 'gpu': + ocr_service.set_gpus("0") + ocr_service.prepare_server( + workdir="workdir", port=9292, device="gpu", gpuid=0) +elif sys.argv[1] == 'cpu': + ocr_service.prepare_server(workdir="workdir", port=9292, device="cpu") ocr_service.run_rpc_service() ocr_service.run_web_service() diff --git a/python/examples/pipeline/imdb_model_ensemble/config.yml b/python/examples/pipeline/imdb_model_ensemble/config.yml index 7dac6eec2a2d7d90be3d4684f2aaaec7496249d9..3f0b1bb8d4eedb073fa5014eb20e1a170f0d811b 100644 --- a/python/examples/pipeline/imdb_model_ensemble/config.yml +++ b/python/examples/pipeline/imdb_model_ensemble/config.yml @@ -1,8 +1,10 @@ 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 diff --git a/python/examples/pipeline/imdb_model_ensemble/test_pipeline_client.py b/python/examples/pipeline/imdb_model_ensemble/test_pipeline_client.py index 9cf476c4705c2267aa42337f90970d9fd051b7fd..765ab7fd5a02a4af59b0773135bc59c802464b42 100644 --- a/python/examples/pipeline/imdb_model_ensemble/test_pipeline_client.py +++ b/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) diff --git a/python/examples/pipeline/imdb_model_ensemble/test_pipeline_server.py b/python/examples/pipeline/imdb_model_ensemble/test_pipeline_server.py index 47c2ec7ad37b77916c2cc3e168965cec7d3c7e07..92a15379c0b6ae1ad0cdc1401a01556e41c7eed7 100644 --- a/python/examples/pipeline/imdb_model_ensemble/test_pipeline_server.py +++ b/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]) diff --git a/python/paddle_serving_client/__init__.py b/python/paddle_serving_client/__init__.py index cf669c54f3492fc739bedcfacc49537a5ecc545f..1af7f754ec61ca2e91292034c1d4f6aca1414520 100644 --- a/python/paddle_serving_client/__init__.py +++ b/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( diff --git a/python/paddle_serving_server/__init__.py b/python/paddle_serving_server/__init__.py index 678c0583d1e132791a1199e315ea380a4ae3108b..1fea9ab187a8c41cd4264a10138d6c13a09897f5 100644 --- a/python/paddle_serving_server/__init__.py +++ b/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): diff --git a/python/paddle_serving_server/web_service.py b/python/paddle_serving_server/web_service.py index b0c1b79bda5041b4eca114d778a23d3a123c226e..22b160341eba42ed02743dd03b99d4af2f737434 100755 --- a/python/paddle_serving_server/web_service.py +++ b/python/paddle_serving_server/web_service.py @@ -91,6 +91,8 @@ class WebService(object): request.json["fetch"]) if isinstance(feed, dict) and "fetch" in feed: del feed["fetch"] + if len(feed) == 0: + raise ValueError("empty input") fetch_map = self.client.predict(feed=feed, fetch=fetch) result = self.postprocess( feed=request.json["feed"], fetch=fetch, fetch_map=fetch_map) @@ -122,6 +124,32 @@ class WebService(object): self.app_instance = app_instance + def run_debugger_service(self): + import socket + localIP = socket.gethostbyname(socket.gethostname()) + print("web service address:") + print("http://{}:{}/{}/prediction".format(localIP, self.port, + self.name)) + app_instance = Flask(__name__) + + @app_instance.before_first_request + def init(): + self._launch_local_predictor() + + service_name = "/" + self.name + "/prediction" + + @app_instance.route(service_name, methods=["POST"]) + def run(): + return self.get_prediction(request) + + self.app_instance = app_instance + + def _launch_local_predictor(self): + from paddle_serving_app.local_predict import Debugger + self.client = Debugger() + self.client.load_model_config( + "{}".format(self.model_config), gpu=False, profile=False) + def run_web_service(self): self.app_instance.run(host="0.0.0.0", port=self.port, diff --git a/python/paddle_serving_server_gpu/__init__.py b/python/paddle_serving_server_gpu/__init__.py index becfbb20090799aaf40d79973964e497cf599436..7ab27dc0cb71041506d715d1ab4ca58c25d2c6d9 100644 --- a/python/paddle_serving_server_gpu/__init__.py +++ b/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): diff --git a/python/pipeline/__init__.py b/python/pipeline/__init__.py index f720e4d2c851cec6270d31d6d44a766acc246291..9f3056708c4394637ea6898fa50911af9871cd9d 100644 --- a/python/pipeline/__init__.py +++ b/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 diff --git a/python/pipeline/analyse.py b/python/pipeline/analyse.py index 0cb4196c53900e77f0d9ba346a6a16a264ef95de..424b7e025394467840ae77a696e42cefc5a06eed 100644 --- a/python/pipeline/analyse.py +++ b/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: diff --git a/python/pipeline/channel.py b/python/pipeline/channel.py index bff22ad9216fb6e639eb2857e6a189dcb2643d67..6f86658b262af79016c80172cac45d0dba15fe81 100644 --- a/python/pipeline/channel.py +++ b/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 diff --git a/python/pipeline/dag.py b/python/pipeline/dag.py index d965b8f18921bd8f617cf42bcbc9dae6e7d4a869..0e058dbeab8be4741268cadad0ab887f03a7d8a7 100644 --- a/python/pipeline/dag.py +++ b/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 diff --git a/python/pipeline/logger.py b/python/pipeline/logger.py new file mode 100644 index 0000000000000000000000000000000000000000..b566c012d3ced8f4f1bddd9b1622abc4beb9c8a5 --- /dev/null +++ b/python/pipeline/logger.py @@ -0,0 +1,76 @@ +# 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) diff --git a/python/pipeline/operator.py b/python/pipeline/operator.py index 0e5e66ae326f4ae5b131458121d11b455a721a72..b18b5ed8c43312481384913109be2830ad1eeb0f 100644 --- a/python/pipeline/operator.py +++ b/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 diff --git a/python/pipeline/pipeline_client.py b/python/pipeline/pipeline_client.py index 6d96b9264773b861ad9480cf59449e3fbf562b5e..ad78c6d39002b206082de8eab238be1abf543fee 100644 --- a/python/pipeline/pipeline_client.py +++ b/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: diff --git a/python/pipeline/pipeline_server.py b/python/pipeline/pipeline_server.py index 3f8492c9da728446486a9cf076ecf26394235f91..e8229e810308b10d35f903a8415d898177bc2239 100644 --- a/python/pipeline/pipeline_server.py +++ b/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 diff --git a/python/pipeline/profiler.py b/python/pipeline/profiler.py index e6fe43b10a17aafc2b4058c47e72f1e640e7912e..b83bdd1dc8c5c948353c8ee95f51fe325e38dbfc 100644 --- a/python/pipeline/profiler.py +++ b/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: diff --git a/python/pipeline/util.py b/python/pipeline/util.py index a24c1a057ca4bbb5cf33f2402559ce3d14f3e6b9..fb5e14ce808fd34de75b1a640630ca172510cd6c 100644 --- a/python/pipeline/util.py +++ b/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 diff --git a/python/requirements.txt b/python/requirements.txt index 697b24fd4db6aff6b30913d8a5d23416dc208c80..23b5289d5109fcb119f143eef4deb65198555d6a 100644 --- a/python/requirements.txt +++ b/python/requirements.txt @@ -1,5 +1,9 @@ numpy>=1.12, <=1.16.4 ; python_version<"3.5" +wheel>=0.34.0, <0.35.0 +setuptools>=44.1.0 +opencv-python==4.2.0.32 google>=2.0.3 +opencv-python==4.2.0.32 protobuf>=3.12.2 grpcio-tools>=1.28.1 grpcio>=1.28.1 diff --git a/python/setup.py.app.in b/python/setup.py.app.in index 1ee1cabb5a572536e6869852e3ab638cda6adcb8..2b7ae9303aa95eace7b0eab99d787ca43af48e00 100644 --- a/python/setup.py.app.in +++ b/python/setup.py.app.in @@ -42,7 +42,7 @@ if '${PACK}' == 'ON': REQUIRED_PACKAGES = [ - 'six >= 1.10.0', 'sentencepiece', 'opencv-python', 'pillow', + 'six >= 1.10.0', 'sentencepiece', 'opencv-python<=4.2.0.32', 'pillow', 'shapely', 'pyclipper' ] diff --git a/tools/Dockerfile b/tools/Dockerfile index 6c61937755ea5e0257e70ce27cab528b76222b12..bf4254495e5a1163455887008540945d5898182e 100644 --- a/tools/Dockerfile +++ b/tools/Dockerfile @@ -12,4 +12,5 @@ RUN yum -y install wget && \ RUN curl https://bootstrap.pypa.io/get-pip.py -o get-pip.py && \ python get-pip.py && rm get-pip.py && \ localedef -c -i en_US -f UTF-8 en_US.UTF-8 && \ - echo "export LANG=en_US.utf8" >> /root/.bashrc + echo "export LANG=en_US.utf8" >> /root/.bashrc && \ + echo "export LANGUAGE=en_US.utf8" >> /root/.bashrc diff --git a/tools/Dockerfile.centos6.cuda9.0-cudnn7.devel b/tools/Dockerfile.centos6.cuda9.0-cudnn7.devel index 9ee3591b9a1e2ea5881106cf7e67ca28b24c1890..b4af571c19cec131800dd871b558c00d601b2f5e 100644 --- a/tools/Dockerfile.centos6.cuda9.0-cudnn7.devel +++ b/tools/Dockerfile.centos6.cuda9.0-cudnn7.devel @@ -31,7 +31,6 @@ RUN yum -y install wget && \ curl https://bootstrap.pypa.io/get-pip.py -o get-pip.py && \ python get-pip.py && \ rm get-pip.py && \ - pip install google protobuf setuptools wheel flask numpy==1.16.4 && \ wget https://www.python.org/ftp/python/3.6.8/Python-3.6.8.tgz && \ tar -zxf Python-3.6.8.tgz && \ cd Python-3.6.8 && \ @@ -42,7 +41,7 @@ RUN yum -y install wget && \ echo 'export LD_LIBRARY_PATH=/usr/local/python3.6/lib:$LD_LIBRARY_PATH' >> /root/.bashrc && \ source /root/.bashrc && \ cd .. && rm -rf Python-3.6.8* && \ - pip3 install google protobuf setuptools wheel flask numpy==1.16.4 && \ yum -y install epel-release && yum -y install patchelf libXext libSM libXrender && \ yum clean all && \ - echo "export LANG=en_US.utf8" >> /root/.bashrc + echo "export LANG=en_US.utf8" >> /root/.bashrc && \ + echo "export LANGUAGE=en_US.utf8" >> /root/.bashrc diff --git a/tools/Dockerfile.centos6.devel b/tools/Dockerfile.centos6.devel index 83981dcc4731252dfc75270b5ce6fc623a0266a8..6dfc304cb281f5bb7c7d60a0b38354118c893f39 100644 --- a/tools/Dockerfile.centos6.devel +++ b/tools/Dockerfile.centos6.devel @@ -31,7 +31,6 @@ RUN yum -y install wget && \ curl https://bootstrap.pypa.io/get-pip.py -o get-pip.py && \ python get-pip.py && \ rm get-pip.py && \ - pip install google protobuf setuptools wheel flask numpy==1.16.4 && \ wget https://www.python.org/ftp/python/3.6.8/Python-3.6.8.tgz && \ tar -zxf Python-3.6.8.tgz && \ cd Python-3.6.8 && \ @@ -42,8 +41,8 @@ RUN yum -y install wget && \ echo 'export LD_LIBRARY_PATH=/usr/local/python3.6/lib:$LD_LIBRARY_PATH' >> /root/.bashrc && \ source /root/.bashrc && \ cd .. && rm -rf Python-3.6.8* && \ - pip3 install google protobuf setuptools wheel flask numpy==1.16.4 && \ yum -y install epel-release && yum -y install patchelf libXext libSM libXrender && \ yum clean all && \ localedef -c -i en_US -f UTF-8 en_US.UTF-8 && \ - echo "export LANG=en_US.utf8" >> /root/.bashrc + echo "export LANG=en_US.utf8" >> /root/.bashrc && \ + echo "export LANGUAGE=en_US.utf8" >> /root/.bashrc diff --git a/tools/Dockerfile.ci b/tools/Dockerfile.ci index 92aee9e777387374397682b3a22dafe1294ccde4..0eb695d301f6b45c73d3f3b4af018bd2c83860ac 100644 --- a/tools/Dockerfile.ci +++ b/tools/Dockerfile.ci @@ -23,7 +23,6 @@ RUN wget https://dl.google.com/go/go1.14.linux-amd64.tar.gz >/dev/null \ RUN yum -y install python-devel sqlite-devel >/dev/null \ && curl https://bootstrap.pypa.io/get-pip.py -o get-pip.py >/dev/null \ && python get-pip.py >/dev/null \ - && pip install google protobuf setuptools wheel flask >/dev/null \ && rm get-pip.py RUN wget http://nixos.org/releases/patchelf/patchelf-0.10/patchelf-0.10.tar.bz2 \ @@ -35,8 +34,7 @@ RUN wget http://nixos.org/releases/patchelf/patchelf-0.10/patchelf-0.10.tar.bz2 && cd .. \ && rm -rf patchelf-0.10* -RUN yum install -y python3 python3-devel \ - && pip3 install google protobuf setuptools wheel flask +RUN yum install -y python3 python3-devel RUN yum -y update >/dev/null \ && yum -y install dnf >/dev/null \ diff --git a/tools/Dockerfile.cuda10.0-cudnn7 b/tools/Dockerfile.cuda10.0-cudnn7 index d2a5b2c93a3e78b807c7828c984a5fc29f50fd2d..c26eaeb986cbd7d66ee51bac1444cf293800d839 100644 --- a/tools/Dockerfile.cuda10.0-cudnn7 +++ b/tools/Dockerfile.cuda10.0-cudnn7 @@ -18,6 +18,7 @@ RUN ln -s /usr/local/cuda-10.0/lib64/libcublas.so.10.0 /usr/local/cuda-10.0/lib6 ln -s /usr/local/cuda-10.0/targets/x86_64-linux/lib/libcudnn.so.7 /usr/local/cuda-10.0/targets/x86_64-linux/lib/libcudnn.so && \ echo 'export LD_LIBRARY_PATH=/usr/local/cuda-10.0/targets/x86_64-linux/lib:$LD_LIBRARY_PATH' >> /root/.bashrc && \ echo "export LANG=en_US.utf8" >> /root/.bashrc && \ + echo "export LANGUAGE=en_US.utf8" >> /root/.bashrc && \ mkdir -p /usr/local/cuda/extras COPY --from=builder /usr/local/cuda/extras/CUPTI /usr/local/cuda/extras/CUPTI diff --git a/tools/Dockerfile.cuda10.0-cudnn7.devel b/tools/Dockerfile.cuda10.0-cudnn7.devel index b46f9b96cf0d081cf9cdfc12cb46be037677ac86..d65e1e256c8772101a51fcc58ab525aff9f182a1 100644 --- a/tools/Dockerfile.cuda10.0-cudnn7.devel +++ b/tools/Dockerfile.cuda10.0-cudnn7.devel @@ -23,13 +23,12 @@ RUN wget https://dl.google.com/go/go1.14.linux-amd64.tar.gz >/dev/null \ RUN yum -y install python-devel sqlite-devel \ && curl https://bootstrap.pypa.io/get-pip.py -o get-pip.py >/dev/null \ && python get-pip.py >/dev/null \ - && pip install google protobuf setuptools wheel flask >/dev/null \ && rm get-pip.py RUN yum install -y python3 python3-devel \ - && pip3 install google protobuf setuptools wheel flask \ && yum -y install epel-release && yum -y install patchelf libXext libSM libXrender\ && yum clean all RUN localedef -c -i en_US -f UTF-8 en_US.UTF-8 \ - && echo "export LANG=en_US.utf8" >> /root/.bashrc + && echo "export LANG=en_US.utf8" >> /root/.bashrc \ + && echo "export LANGUAGE=en_US.utf8" >> /root/.bashrc diff --git a/tools/Dockerfile.cuda9.0-cudnn7 b/tools/Dockerfile.cuda9.0-cudnn7 index 145cd53eb0b9848349d591fdc078833ec5a89740..ead1cfe77d7148789d84bc01fb05cedda5ff1fe6 100644 --- a/tools/Dockerfile.cuda9.0-cudnn7 +++ b/tools/Dockerfile.cuda9.0-cudnn7 @@ -18,6 +18,7 @@ RUN ln -s /usr/local/cuda-9.0/lib64/libcublas.so.9.0 /usr/local/cuda-9.0/lib64/l ln -s /usr/local/cuda-9.0/targets/x86_64-linux/lib/libcudnn.so.7 /usr/local/cuda-9.0/targets/x86_64-linux/lib/libcudnn.so && \ echo 'export LD_LIBRARY_PATH=/usr/local/cuda-9.0/targets/x86_64-linux/lib:$LD_LIBRARY_PATH' >> /root/.bashrc && \ echo "export LANG=en_US.utf8" >> /root/.bashrc && \ + echo "export LANGUAGE=en_US.utf8" >> /root/.bashrc && \ mkdir -p /usr/local/cuda/extras COPY --from=builder /usr/local/cuda/extras/CUPTI /usr/local/cuda/extras/CUPTI diff --git a/tools/Dockerfile.cuda9.0-cudnn7.devel b/tools/Dockerfile.cuda9.0-cudnn7.devel index c101b32118bf735a100bdb07f2e33f7978a8a30c..b33ed58a2a97a6bea7a8f408c2e6a7f6ccc7d448 100644 --- a/tools/Dockerfile.cuda9.0-cudnn7.devel +++ b/tools/Dockerfile.cuda9.0-cudnn7.devel @@ -22,13 +22,12 @@ RUN wget https://dl.google.com/go/go1.14.linux-amd64.tar.gz >/dev/null \ RUN yum -y install python-devel sqlite-devel \ && curl https://bootstrap.pypa.io/get-pip.py -o get-pip.py >/dev/null \ && python get-pip.py >/dev/null \ - && pip install google protobuf setuptools wheel flask >/dev/null \ && rm get-pip.py RUN yum install -y python3 python3-devel \ - && pip3 install google protobuf setuptools wheel flask \ && yum -y install epel-release && yum -y install patchelf libXext libSM libXrender\ && yum clean all RUN localedef -c -i en_US -f UTF-8 en_US.UTF-8 \ - && echo "export LANG=en_US.utf8" >> /root/.bashrc + && echo "export LANG=en_US.utf8" >> /root/.bashrc \ + && echo "export LANGUAGE=en_US.utf8" >> /root/.bashrc diff --git a/tools/Dockerfile.devel b/tools/Dockerfile.devel index dc00384e39bb742400fee74663a551cf44019d61..83e3b491c30fe99eaa615e836efeef6aad0c0cc4 100644 --- a/tools/Dockerfile.devel +++ b/tools/Dockerfile.devel @@ -19,13 +19,12 @@ RUN wget https://dl.google.com/go/go1.14.linux-amd64.tar.gz >/dev/null \ RUN yum -y install python-devel sqlite-devel \ && curl https://bootstrap.pypa.io/get-pip.py -o get-pip.py >/dev/null \ && python get-pip.py >/dev/null \ - && pip install google protobuf setuptools wheel flask >/dev/null \ && rm get-pip.py RUN yum install -y python3 python3-devel \ - && pip3 install google protobuf setuptools wheel flask \ && yum -y install epel-release && yum -y install patchelf libXext libSM libXrender\ && yum clean all RUN localedef -c -i en_US -f UTF-8 en_US.UTF-8 \ - && echo "export LANG=en_US.utf8" >> /root/.bashrc + && echo "export LANG=en_US.utf8" >> /root/.bashrc \ + && echo "export LANGUAGE=en_US.utf8" >> /root/.bashrc diff --git a/tools/serving_build.sh b/tools/serving_build.sh index ac6e5f8cb5fcb7db5e7890c09b08d12ba14d0294..c54631a733fecc532f22d3ce1793ff8554e21f7d 100644 --- a/tools/serving_build.sh +++ b/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