diff --git a/tf_adapter/common/adp_logger.cc b/tf_adapter/common/adp_logger.cc new file mode 100644 index 0000000000000000000000000000000000000000..26ab1c344efafd250eb206ae84e2fefb1e1bd819 --- /dev/null +++ b/tf_adapter/common/adp_logger.cc @@ -0,0 +1,5 @@ +#include "tf_adapter/common/adp_logger.h" + +AdapterLogger::~AdapterLogger(){ + DlogSub(FMK_MODULE_NAME, ADP_MODULE_NAME, severity_, "%s", str().c_str()); +} \ No newline at end of file diff --git a/tf_adapter/common/adp_logger.h b/tf_adapter/common/adp_logger.h new file mode 100644 index 0000000000000000000000000000000000000000..104ebe5b7fddcd8f477dbfbadc28cbc61cce3cee --- /dev/null +++ b/tf_adapter/common/adp_logger.h @@ -0,0 +1,44 @@ +/* + *Copyright (c) Huawei Technologies Co., Ltd. 2020. All rights reserved. + *Description: Common depends and micro defines for and only for data preprocess moudle + */ +#ifndef TENSORFLOW_ADP_LOGGER_H +#define TENSORFLOW_ADP_LOGGER_H + +#include +#include +#include "toolchain/slog.h" +#include +#include + +#define FMK_MODULE_NAME static_cast(FMK) +#define ADP_MODULE_NAME "TF_ADAPTER" + +const int ADP_DEBUG = 0; +const int ADP_INFO = 1; +const int ADP_WARNING = 2; +const int ADP_ERROR = 3; +const int ADP_EVENT = 16; + + +class AdapterLogger : public std::basic_ostringstream { + public: + AdapterLogger(const char* fname, int line, int severity) { + *this << " [" << fname << ":" << line << "]" << " "; + severity_ = severity; + } + ~AdapterLogger(); + + private: + int severity_; +}; + + +#define _ADP_LOG_INFO AdapterLogger(__FILE__, __LINE__, ADP_INFO) +#define _ADP_LOG_WARNING AdapterLogger(__FILE__, __LINE__, ADP_WARNING) +#define _ADP_LOG_ERROR AdapterLogger(__FILE__, __LINE__, ADP_ERROR) +#define _ADP_LOG_EVENT AdapterLogger(__FILE__, __LINE__, ADP_EVENT) +#define _ADP_LOG_DEBUG AdapterLogger(__FILE__, __LINE__, ADP_DEBUG) + +#define ADP_LOG(LEVEL) _ADP_LOG_##LEVEL +#endif \ No newline at end of file diff --git a/tf_adapter/common/common.h b/tf_adapter/common/common.h index 10a5eee5861b87071967db9b4862cb004e3928c9..3059da5bac387f8bdf16e6043904535853c63d27 100644 --- a/tf_adapter/common/common.h +++ b/tf_adapter/common/common.h @@ -29,15 +29,18 @@ limitations under the License. #define TENSORFLOW_COMMON_COMMON_H_ #include "tensorflow/core/platform/env.h" +#include "tf_adapter/common/adp_logger.h" #define CHECK_NOT_NULL(v) \ if ((v) == nullptr) { \ + ADP_LOG(ERROR) << #v " is nullptr."; \ LOG(ERROR) << #v " is nullptr."; \ return; \ } #define REQUIRES_NOT_NULL(v) \ if ((v) == nullptr) { \ + ADP_LOG(ERROR) << #v " is nullptr."; \ LOG(ERROR) << #v " is nullptr."; \ return errors::InvalidArgument(#v " is nullptr."); \ } diff --git a/tf_adapter/kernels/adam_apply_one_assign.cc b/tf_adapter/kernels/adam_apply_one_assign.cc index cd10fba2b74809bf5c0ad945ef33e01fc7ebb6e1..333ca225eb09c5f58acc51c5aa1aa9f1932a7dde 100644 --- a/tf_adapter/kernels/adam_apply_one_assign.cc +++ b/tf_adapter/kernels/adam_apply_one_assign.cc @@ -26,6 +26,7 @@ limitations under the License. ==============================================================================*/ #include "tensorflow/core/framework/op_kernel.h" +#include "tf_adapter/common/adp_logger.h" namespace tensorflow { class AdamApplyOneAssignOp : public OpKernel { @@ -33,7 +34,7 @@ class AdamApplyOneAssignOp : public OpKernel { explicit AdamApplyOneAssignOp(OpKernelConstruction *context) : OpKernel(context) {} ~AdamApplyOneAssignOp() override = default; void Compute(OpKernelContext *context) override { - LOG(INFO) << "AdamApplyOneAssignOp Compute, num_inputs: " << context->num_inputs(); + ADP_LOG(INFO) << "AdamApplyOneAssignOp Compute, num_inputs: " << context->num_inputs(); } bool IsExpensive() override { return false; } }; diff --git a/tf_adapter/kernels/adam_apply_one_with_decay_assign.cc b/tf_adapter/kernels/adam_apply_one_with_decay_assign.cc index 02b5b882ab784e3d598f0f58ac5d0eb30b710f2d..d3ed5cbf8f728636de0a36578f860fb7a178a434 100644 --- a/tf_adapter/kernels/adam_apply_one_with_decay_assign.cc +++ b/tf_adapter/kernels/adam_apply_one_with_decay_assign.cc @@ -26,6 +26,7 @@ limitations under the License. ==============================================================================*/ #include "tensorflow/core/framework/op_kernel.h" +#include "tf_adapter/common/adp_logger.h" namespace tensorflow { class AdamApplyOneWithDecayAssignOp : public OpKernel { @@ -33,7 +34,7 @@ class AdamApplyOneWithDecayAssignOp : public OpKernel { explicit AdamApplyOneWithDecayAssignOp(OpKernelConstruction *context) : OpKernel(context) {} ~AdamApplyOneWithDecayAssignOp() override = default; void Compute(OpKernelContext *context) override { - LOG(INFO) << "AdamApplyOneWithDecayAssignOp Compute, num_inputs: " << context->num_inputs(); + ADP_LOG(INFO) << "AdamApplyOneWithDecayAssignOp Compute, num_inputs: " << context->num_inputs(); } bool IsExpensive() override { return false; } }; diff --git a/tf_adapter/kernels/basic_lstm_cell.cc b/tf_adapter/kernels/basic_lstm_cell.cc index ebc36084b0cf5fcaa9422a2ea653437e713e0bbe..7edcef55da38e8d7fc08d4998d437eeccea883fa 100644 --- a/tf_adapter/kernels/basic_lstm_cell.cc +++ b/tf_adapter/kernels/basic_lstm_cell.cc @@ -26,6 +26,7 @@ limitations under the License. ==============================================================================*/ #include "tensorflow/core/framework/op_kernel.h" +#include "tf_adapter/common/adp_logger.h" namespace tensorflow { class BasicLSTMCellOp : public OpKernel { @@ -33,7 +34,7 @@ class BasicLSTMCellOp : public OpKernel { explicit BasicLSTMCellOp(OpKernelConstruction *context) : OpKernel(context) {} ~BasicLSTMCellOp() override = default; void Compute(OpKernelContext *context) override { - LOG(INFO) << "BasicLSTMCellOp Compute, num_inputs: " << context->num_inputs(); + ADP_LOG(INFO) << "BasicLSTMCellOp Compute, num_inputs: " << context->num_inputs(); } bool IsExpensive() override { return false; } }; diff --git a/tf_adapter/kernels/basic_lstm_cell_grad.cc b/tf_adapter/kernels/basic_lstm_cell_grad.cc index 948c7a1b38e306ad95945dc69c97882da571a7ff..a909f9b9c50b69933c11f149388d15a5ee48e0e6 100644 --- a/tf_adapter/kernels/basic_lstm_cell_grad.cc +++ b/tf_adapter/kernels/basic_lstm_cell_grad.cc @@ -26,13 +26,14 @@ limitations under the License. ==============================================================================*/ #include "tensorflow/core/framework/op_kernel.h" +#include "tf_adapter/common/adp_logger.h" namespace tensorflow { class BasicLSTMCellCStateGradOp : public OpKernel { public: explicit BasicLSTMCellCStateGradOp(OpKernelConstruction *context) : OpKernel(context) {} ~BasicLSTMCellCStateGradOp() override = default; - void Compute(OpKernelContext *context) override { LOG(INFO) << "BasicLSTMCellCStateGradOp Compute"; } + void Compute(OpKernelContext *context) override { ADP_LOG(INFO) << "BasicLSTMCellCStateGradOp Compute"; } bool IsExpensive() override { return false; } }; @@ -40,7 +41,7 @@ class BasicLSTMCellWeightGradOp : public OpKernel { public: explicit BasicLSTMCellWeightGradOp(OpKernelConstruction *context) : OpKernel(context) {} ~BasicLSTMCellWeightGradOp() override = default; - void Compute(OpKernelContext *context) override { LOG(INFO) << "BasicLSTMCellWeightGradOp Compute"; } + void Compute(OpKernelContext *context) override { ADP_LOG(INFO) << "BasicLSTMCellWeightGradOp Compute"; } bool IsExpensive() override { return false; } }; @@ -48,7 +49,7 @@ class BasicLSTMCellInputGradOp : public OpKernel { public: explicit BasicLSTMCellInputGradOp(OpKernelConstruction *context) : OpKernel(context) {} ~BasicLSTMCellInputGradOp() override = default; - void Compute(OpKernelContext *context) override { LOG(INFO) << "BasicLSTMCellInputGradOp Compute"; } + void Compute(OpKernelContext *context) override { ADP_LOG(INFO) << "BasicLSTMCellInputGradOp Compute"; } bool IsExpensive() override { return false; } }; diff --git a/tf_adapter/kernels/decode_image_ops.cc b/tf_adapter/kernels/decode_image_ops.cc index de97602a417a8f6ba029db6cf0296c4c2d8f8b27..2ddf1336b7289088bae53ba55ae9eeb664ab6b27 100644 --- a/tf_adapter/kernels/decode_image_ops.cc +++ b/tf_adapter/kernels/decode_image_ops.cc @@ -28,6 +28,7 @@ limitations under the License. #include "soft_dp/ExternalSoftDp.h" #include "tensorflow/core/framework/op_kernel.h" #include "tf_adapter/util/plugin_load_manager.h" +#include "tf_adapter/common/adp_logger.h" #include namespace tensorflow { @@ -58,9 +59,9 @@ class DecodeImageOp : public OpKernel { ~DecodeImageOp() override { if (handle_ != nullptr) { (void)dlclose(handle_); - LOG(INFO) << "dlclose handle finish."; + ADP_LOG(INFO) << "dlclose handle finish."; } else { - LOG(INFO) << "handle is null."; + ADP_LOG(INFO) << "handle is null."; } } @@ -85,6 +86,7 @@ class DecodeImageOp : public OpKernel { int width = resize_vec(1); Status status(context->allocate_output(0, TensorShape({height, width, 3}), &output)); if (!status.ok()) { + ADP_LOG(ERROR) << "DecodeImageOp, Decode image failed when allocate output"; LOG(ERROR) << "DecodeImageOp, Decode image failed when allocate output"; context->SetStatus(status); return; diff --git a/tf_adapter/kernels/dp_iterator_ops.cc b/tf_adapter/kernels/dp_iterator_ops.cc index 4bb87ae3a24472586364c0cc7390bce12b58c395..cb30220077bef88601b26b348d5957957b03cc01 100644 --- a/tf_adapter/kernels/dp_iterator_ops.cc +++ b/tf_adapter/kernels/dp_iterator_ops.cc @@ -29,6 +29,7 @@ limitations under the License. #include "tensorflow/core/kernels/data/iterator_ops.h" #include "tf_adapter/common/common.h" +#include "tf_adapter/common/adp_logger.h" namespace tensorflow { namespace data { @@ -43,7 +44,7 @@ const char kOutputTypes[] = "output_types"; } // namespace void DpMakeIteratorOp::Compute(OpKernelContext *ctx) { - LOG(INFO) << "===Begin Computer MakeIterator==="; + ADP_LOG(INFO) << "===Begin Computer MakeIterator==="; CHECK_NOT_NULL(ctx); DatasetBase *dataset = nullptr; OP_REQUIRES_OK(ctx, GetDatasetFromVariantTensor(ctx->input(0), &dataset)); @@ -52,7 +53,7 @@ void DpMakeIteratorOp::Compute(OpKernelContext *ctx) { Status s = iterator_resource->SetIteratorFromDataset(ctx, dataset); iterator_resource->Unref(); if (!s.ok()) { ctx->SetStatus(s); } - LOG(INFO) << "===End Computer MakeIterator==="; + ADP_LOG(INFO) << "===End Computer MakeIterator==="; } namespace { diff --git a/tf_adapter/kernels/dpgroup_dataset_op.cc b/tf_adapter/kernels/dpgroup_dataset_op.cc index 82786a53f05ece92d79d627be683be21e1eb17a7..d9b77ae6a9b5471e68dd35d078d199ab47f700a1 100644 --- a/tf_adapter/kernels/dpgroup_dataset_op.cc +++ b/tf_adapter/kernels/dpgroup_dataset_op.cc @@ -28,6 +28,7 @@ limitations under the License. #include "tensorflow/core/common_runtime/function.h" #include "tensorflow/core/kernels/data/captured_function.h" #include "tf_adapter/common/common.h" +#include "tf_adapter/common/adp_logger.h" namespace tensorflow { namespace data { @@ -90,7 +91,7 @@ class DPGroupDatasetOp : public DatasetOpKernel { ~Iterator() {} Status Initialize(IteratorContext *ctx) override { REQUIRES_NOT_NULL(ctx); - LOG(INFO) << "Start to initialize iterator of DPGroupDatasetOp"; + ADP_LOG(INFO) << "Start to initialize iterator of DPGroupDatasetOp"; mutex_lock l(mu_); try { input_impls_.resize(dataset()->inputs_.size()); diff --git a/tf_adapter/kernels/dropout_ops.cc b/tf_adapter/kernels/dropout_ops.cc index 91154c6c4e51e0370a52dca0a18724a13aa2fffc..7f58b314bb273ad44cd5e40b2999664370602d63 100644 --- a/tf_adapter/kernels/dropout_ops.cc +++ b/tf_adapter/kernels/dropout_ops.cc @@ -27,13 +27,14 @@ limitations under the License. #include "tensorflow/core/framework/op_kernel.h" #include "third_party/eigen3/unsupported/Eigen/CXX11/Tensor" +#include "tf_adapter/common/adp_logger.h" namespace tensorflow { class DropOutDoMaskOp : public OpKernel { public: explicit DropOutDoMaskOp(OpKernelConstruction *context) : OpKernel(context) {} ~DropOutDoMaskOp() {} - void Compute(OpKernelContext *context) override { LOG(INFO) << "DropOutDoMaskOp Compute "; } + void Compute(OpKernelContext *context) override { ADP_LOG(INFO) << "DropOutDoMaskOp Compute "; } bool IsExpensive() override { return false; } }; @@ -41,7 +42,7 @@ class DropOutGenMaskOp : public OpKernel { public: explicit DropOutGenMaskOp(OpKernelConstruction *context) : OpKernel(context) {} ~DropOutGenMaskOp() {} - void Compute(OpKernelContext *context) override { LOG(INFO) << "DropOutGenMaskOp Compute"; } + void Compute(OpKernelContext *context) override { ADP_LOG(INFO) << "DropOutGenMaskOp Compute"; } bool IsExpensive() override { return false; } }; diff --git a/tf_adapter/kernels/geop_dataset_op.cc b/tf_adapter/kernels/geop_dataset_op.cc index f1c06ef6eebb83e330d4e7ae27bfc071759f96e8..9169fd75374587fa9b2767da088e47cc56435276 100644 --- a/tf_adapter/kernels/geop_dataset_op.cc +++ b/tf_adapter/kernels/geop_dataset_op.cc @@ -28,6 +28,7 @@ limitations under the License. #include "tensorflow/core/common_runtime/function.h" #include "tensorflow/core/kernels/data/captured_function.h" #include "tf_adapter/common/common.h" +#include "tf_adapter/common/adp_logger.h" namespace tensorflow { namespace data { @@ -43,10 +44,10 @@ class GEOPDatasetOp : public DatasetOpKernel { } ~GEOPDatasetOp() { if (f_handle_ != kInvalidHandle && lib_ != nullptr) { - LOG(INFO) << "Release function handle:" << f_handle_ << " owned by node instance:" << name(); + ADP_LOG(INFO) << "Release function handle:" << f_handle_ << " owned by node instance:" << name(); Status s = lib_->ReleaseHandle(f_handle_); if (s != Status::OK()) { - LOG(INFO) << "Release function handle:" << f_handle_ << " owned by node instance:" << name() + ADP_LOG(INFO) << "Release function handle:" << f_handle_ << " owned by node instance:" << name() << " failed. original err msg: " << s.error_message(); return; } @@ -101,7 +102,7 @@ class GEOPDatasetOp : public DatasetOpKernel { explicit Iterator(const Params ¶ms) : DatasetIterator(params) {} ~Iterator() {} Status Initialize(IteratorContext *ctx) override { - LOG(INFO) << "Start to initialize iterator of GEOPDatasetOp"; + ADP_LOG(INFO) << "Start to initialize iterator of GEOPDatasetOp"; REQUIRES_NOT_NULL(ctx); REQUIRES_NOT_NULL(dataset()); REQUIRES_NOT_NULL(dataset()->kernel()); @@ -144,7 +145,10 @@ class GEOPDatasetOp : public DatasetOpKernel { n.Notify(); }); n.WaitForNotification(); - if (!s.ok()) { LOG(ERROR) << s; } + if (!s.ok()) { + ADP_LOG(ERROR) << s; + LOG(ERROR) << s; + } return s; } @@ -155,7 +159,7 @@ class GEOPDatasetOp : public DatasetOpKernel { std::string node_name = ndef.name(); if (str_util::StartsWith(node_name, "GeOp_")) { AddNodeAttr("_session", session, &ndef); - LOG(INFO) << "Node " << node_name << " add session info " << session << " success."; + ADP_LOG(INFO) << "Node " << node_name << " add session info " << session << " success."; } } } diff --git a/tf_adapter/kernels/geop_npu.cc b/tf_adapter/kernels/geop_npu.cc index a7e5adb9cc18adf061bcee218d111bd3e88c60c7..8d7c7b24c2340fffe293c4fa44acdb772cc7ad1f 100644 --- a/tf_adapter/kernels/geop_npu.cc +++ b/tf_adapter/kernels/geop_npu.cc @@ -41,6 +41,7 @@ limitations under the License. #include #include +#include "tf_adapter/common/adp_logger.h" #include "tf_adapter/common/common.h" #include "tf_adapter/util/ge_plugin.h" #include "tf_adapter/util/infershape_util.h" @@ -77,8 +78,9 @@ inline string ToString(ge::Status status) { return ::ge::StatusFactory::Instance Status BuildOutputTensorInfo(OpKernelContext *ctx, std::vector &outputs) { // ctx is not nullptr int num_outputs = ctx->num_outputs(); - LOG(INFO) << "BuildOutputTensorInfo, num_outputs:" << num_outputs; + ADP_LOG(INFO) << "BuildOutputTensorInfo, num_outputs:" << num_outputs; if (num_outputs != static_cast(outputs.size())) { + ADP_LOG(ERROR) << "[GEOP] Outputs num mismatched, need:" << num_outputs << ", while GE return:" << outputs.size(); LOG(ERROR) << "[GEOP] Outputs num mismatched, need:" << num_outputs << ", while GE return:" << outputs.size(); return errors::InvalidArgument("Outputs num mismatched, need:", num_outputs, ", while GE return:", outputs.size()); } @@ -99,16 +101,18 @@ Status BuildOutputTensorInfo(OpKernelContext *ctx, std::vectorTotalBytes(); void *tensor_ptr = DMAHelper::base(tensor); if (total_bytes != static_cast(output.length)) { + ADP_LOG(ERROR) << "[GEOP] Outputs len mismatched, index:" << i << ", alloc output:" << total_bytes + << ", while GE return:" << output.length; LOG(ERROR) << "[GEOP] Outputs len mismatched, index:" << i << ", alloc output:" << total_bytes << ", while GE return:" << output.length; return errors::InvalidArgument("Outputs num mismatched, index:", i, ", alloc output:", total_bytes, ", while GE return:", outputs[i].length); } - LOG(INFO) << "BuildOutputTensorInfo, output index:" << i << ", total_bytes:" << total_bytes + ADP_LOG(INFO) << "BuildOutputTensorInfo, output index:" << i << ", total_bytes:" << total_bytes << ", shape:" << dim_string << ", tensor_ptr:" << reinterpret_cast(tensor_ptr) << ", output" << reinterpret_cast(output.data.get()); if (total_bytes == 0) { - LOG(INFO) << "BuildOutputTensorInfo, output index:" << i << ", total_bytes is 0, continue do next. "; + ADP_LOG(INFO) << "BuildOutputTensorInfo, output index:" << i << ", total_bytes is 0, continue do next. "; continue; } @@ -119,6 +123,9 @@ Status BuildOutputTensorInfo(OpKernelContext *ctx, std::vector SECUREC_MEM_MAX_LEN) { auto err = memcpy_s(dst_ptr, SECUREC_MEM_MAX_LEN, src_ptr, SECUREC_MEM_MAX_LEN); if (err != EOK) { + ADP_LOG(ERROR) << "[GEOP] Outputs mem copy failed, index:" << i << ", errret:" << err + << ", dst_ptr:" << (uintptr_t) dst_ptr << ", dst_size:" << SECUREC_MEM_MAX_LEN + << ", src_ptr:" << (uintptr_t) src_ptr << ", src_size:" << SECUREC_MEM_MAX_LEN; LOG(ERROR) << "[GEOP] Outputs mem copy failed, index:" << i << ", errret:" << err << ", dst_ptr:" << (uintptr_t) dst_ptr << ", dst_size:" << SECUREC_MEM_MAX_LEN << ", src_ptr:" << (uintptr_t) src_ptr << ", src_size:" << SECUREC_MEM_MAX_LEN; @@ -133,6 +140,9 @@ Status BuildOutputTensorInfo(OpKernelContext *ctx, std::vector, uint32_t> &p1, const std::pai bool CmpVecValue(Node *node1, Node *node2) { if (node1 == nullptr || node2 == nullptr) { + ADP_LOG(ERROR) << "node1 or node2 is nullptr."; LOG(ERROR) << "node1 or node2 is nullptr."; return false; } @@ -185,8 +196,9 @@ GeOp::~GeOp() { Finalize(); } void GeOp::Initialize(OpKernelConstruction *ctx) { int64 startTime = InferShapeUtil::GetCurrentTimestap(); - LOG(INFO) << "[GEOP] Begin GeOp initialize."; + ADP_LOG(INFO) << "[GEOP] Begin GeOp initialize."; if (init_flag_) { + ADP_LOG(WARNING) << "[GEOP] GEOP already Initialize."; LOG(WARNING) << "[GEOP] GEOP already Initialize."; return; } @@ -200,7 +212,7 @@ void GeOp::Initialize(OpKernelConstruction *ctx) { this->data_format_ = data_format; Status s = ctx->GetAttr("_session", &tf_session_); - if (s.ok()) { LOG(INFO) << "[GEOP] get session info from attr, tf session: " << tf_session_; } + if (s.ok()) { ADP_LOG(INFO) << "[GEOP] get session info from attr, tf session: " << tf_session_; } // global environment Initialize, invoke once for each process string sess_config = ""; @@ -209,14 +221,14 @@ void GeOp::Initialize(OpKernelConstruction *ctx) { iteration_per_loop_ = std::atoi(pass_options["iterations_per_loop"].c_str()); job_type_ = pass_options["job"]; if (GePlugin::GetInstance()->IsGlobal()) { - LOG(INFO) << "[GEOP] GePlugin global, skip GePlugin init"; + ADP_LOG(INFO) << "[GEOP] GePlugin global, skip GePlugin init"; std::map global_init_options = GePlugin::GetInstance()->GetInitOptions(); GetMsTuneConfig(global_init_options); } else { std::map init_options = NpuAttrs::GetInitOptions(ctx); GetMsTuneConfig(init_options); GePlugin::GetInstance()->Init(init_options_); - LOG(INFO) << "[GEOP] GePlugin init success"; + ADP_LOG(INFO) << "[GEOP] GePlugin init success"; } if (!mstune_mode_.empty() && !work_path_.empty()) { @@ -230,20 +242,21 @@ void GeOp::Initialize(OpKernelConstruction *ctx) { init_flag_ = true; int64 endTime = InferShapeUtil::GetCurrentTimestap(); - LOG(INFO) << "[GEOP] GeOp Initialize success, cost:" + ADP_LOG(INFO) << "[GEOP] GeOp Initialize success, cost:" << " [" << ((endTime - startTime) / kMicrosToMillis) << " ms]"; return; } void GeOp::Finalize() { { - LOG(INFO) << "[GEOP] GeOp start to finalize, tf session: " << tf_session_ << ", graph_id_: " << graph_id_; + ADP_LOG(INFO) << "[GEOP] GeOp start to finalize, tf session: " << tf_session_ << ", graph_id_: " << graph_id_; // global environment finalize, invoke once for each process { mutex_lock lock{mu_}; uint32_t graph_id = -1; bool ret = DecrementGraphIdCount(tf_session_, graph_id); if (!ret || graph_id < kInvalidGraphId) { + ADP_LOG(ERROR) << "tf session " << tf_session_ << " sub graph id failed."; LOG(ERROR) << "tf session " << tf_session_ << " sub graph id failed."; return; } @@ -255,11 +268,12 @@ void GeOp::Finalize() { if (!SessionManager::GetInstance().IsGeSessionExist()) { if (!GePlugin::GetInstance()->IsGlobal()) { GePlugin::GetInstance()->Finalize(); - LOG(INFO) << "[GEOP] GePlugin Finalize success"; + ADP_LOG(INFO) << "[GEOP] GePlugin Finalize success"; } else { - LOG(INFO) << "[GEOP] GePlugin global, skip GePlugin Finalize"; + ADP_LOG(INFO) << "[GEOP] GePlugin global, skip GePlugin Finalize"; } if (!GenerateReport::GetInstance()->SaveUnsupportedInfo().ok()) { + ADP_LOG(WARNING) << "[GEOP] Save check report failed."; LOG(WARNING) << "[GEOP] Save check report failed."; } if (handle_ != nullptr) { @@ -269,7 +283,7 @@ void GeOp::Finalize() { } } init_flag_ = false; - LOG(INFO) << "[GEOP] GeOp Finalize success, tf session: " << tf_session_ << ", graph_id_: " << graph_id_; + ADP_LOG(INFO) << "[GEOP] GeOp Finalize success, tf session: " << tf_session_ << ", graph_id_: " << graph_id_; return; } @@ -285,25 +299,27 @@ void GeOp::GetMsTuneConfig(std::map init_options) { int GeOp::InitRebuildFlag(uint32_t cache_graph_id) { if (!build_flag_) { - LOG(INFO) << "[GEOP] tf session " << tf_session_ << ", graph id: " << cache_graph_id + ADP_LOG(INFO) << "[GEOP] tf session " << tf_session_ << ", graph id: " << cache_graph_id << " does not build yet, no need to check rebuild"; return 0; } if (ge_session_ == nullptr) { + ADP_LOG(ERROR) << "[GEOP] GE session is nullptr"; LOG(ERROR) << "[GEOP] GE session is nullptr"; return -1; } if (!ge_session_->IsGraphNeedRebuild(cache_graph_id)) { - LOG(INFO) << "[GEOP] tf session " << tf_session_ << ", graph id: " << cache_graph_id << " no need to rebuild"; + ADP_LOG(INFO) << "[GEOP] tf session " << tf_session_ << ", graph id: " << cache_graph_id << " no need to rebuild"; return 0; } - LOG(INFO) << "[GEOP] The graph need rebuild, graph id " << cache_graph_id; + ADP_LOG(INFO) << "[GEOP] The graph need rebuild, graph id " << cache_graph_id; // The graph need to rebuild, remove it from GE first. - LOG(INFO) << "[GEOP] tf session: " << tf_session_ << ", graph id: " << cache_graph_id; + ADP_LOG(INFO) << "[GEOP] tf session: " << tf_session_ << ", graph id: " << cache_graph_id; auto ret = ge_session_->RemoveGraph(cache_graph_id); if (ret != ge::SUCCESS) { + ADP_LOG(ERROR) << "[GEOP] Failed to remove graph " << cache_graph_id << " from ge, error code " << ret; LOG(ERROR) << "[GEOP] Failed to remove graph " << cache_graph_id << " from ge, error code " << ret; return -1; } @@ -315,6 +331,7 @@ int GeOp::InitRebuildFlag(uint32_t cache_graph_id) { bool GeOp::IncrementGraphIdCount(std::string &tf_session, uint32_t &graph_id) { if (tf_session_.empty()) { + ADP_LOG(ERROR) << "[GEOP] Add graph id failed, tf session is empty."; LOG(ERROR) << "[GEOP] Add graph id failed, tf session is empty."; return false; } @@ -331,6 +348,7 @@ bool GeOp::IncrementGraphIdCount(std::string &tf_session, uint32_t &graph_id) { bool GeOp::DecrementGraphIdCount(std::string &tf_session, uint32_t &graph_id) { if (tf_session_.empty()) { + ADP_LOG(ERROR) << "[GEOP] Sub graph id failed, tf session is empty."; LOG(ERROR) << "[GEOP] Sub graph id failed, tf session is empty."; return false; } @@ -346,6 +364,7 @@ bool GeOp::DecrementGraphIdCount(std::string &tf_session, uint32_t &graph_id) { graph_id = it->second; return true; } + ADP_LOG(ERROR) << "[GEOP] Sub graph id failed, can not find tf session " << tf_session; LOG(ERROR) << "[GEOP] Sub graph id failed, can not find tf session " << tf_session; return false; } @@ -369,13 +388,16 @@ void GeOp::GetExecGraphId(OpKernelContext *ctx, uint32_t &cache_graph_id, build_flag_ = true; } else { if (num >= kMaxCacheNum) { - LOG(INFO) << "[GEOP] the cache vector size is : " << num << " , begin erase the least uesed"; + ADP_LOG(INFO) << "[GEOP] the cache vector size is : " << num << " , begin erase the least uesed"; std::sort(graph_counts_.begin(), graph_counts_.end(), CmpValue); uint32_t erased_graph_id = cache_graphs_[graph_counts_[0].first]; cache_graphs_.erase(graph_counts_[0].first); graph_counts_.erase(graph_counts_.begin()); ge::Status status = ge_session_->RemoveGraph(erased_graph_id); - if (status != ge::SUCCESS) { LOG(WARNING) << "[GEOP] GE Remove Graph failed, ret : " << ToString(status); } + if (status != ge::SUCCESS) { + ADP_LOG(WARNING) << "[GEOP] GE Remove Graph failed, ret : " << ToString(status); + LOG(WARNING) << "[GEOP] GE Remove Graph failed, ret : " << ToString(status); + } cache_graph_id = erased_graph_id; } else { cache_graph_id = graph_id_ + num; @@ -392,12 +414,12 @@ void GeOp::ComputeAsync(OpKernelContext *ctx, DoneCallback done) { if (!sess_init_flag_) { if (job_type_ != "localhost") { // in ps mode : ctx->session_handle() is empty tf_session_ = "ps_worker_session"; - LOG(INFO) << "[GEOP] get tf session " << tf_session_ << " when in ps mode."; + ADP_LOG(INFO) << "[GEOP] get tf session " << tf_session_ << " when in ps mode."; } if (tf_session_.empty()) { tf_session_ = ctx->session_handle(); - LOG(INFO) << "[GEOP] get tf session " << tf_session_ << " from session handle."; + ADP_LOG(INFO) << "[GEOP] get tf session " << tf_session_ << " from session handle."; } { @@ -408,20 +430,20 @@ void GeOp::ComputeAsync(OpKernelContext *ctx, DoneCallback done) { return; } - LOG(INFO) << "[GEOP] Node name: " << ctx->op_kernel().name() << " , tf session: " << tf_session_; + ADP_LOG(INFO) << "[GEOP] Node name: " << ctx->op_kernel().name() << " , tf session: " << tf_session_; res = SessionManager::GetInstance().GetOrCreateGeSession(tf_session_, ge_session_, sess_options_); if (!res || tf_session_.empty() || ge_session_ == nullptr) { OP_REQUIRES_ASYNC(ctx, false, errors::Unavailable("Get ge session failed."), done); return; } - LOG(INFO) << "[GEOP] tf session: " << tf_session_ << " get ge session success."; + ADP_LOG(INFO) << "[GEOP] tf session: " << tf_session_ << " get ge session success."; sess_init_flag_ = true; } } string geop_name = ctx->op_kernel().name(); uint32_t num_inputs = static_cast(ctx->num_inputs()); - LOG(INFO) << "[GEOP] Begin GeOp::ComputeAsync" + ADP_LOG(INFO) << "[GEOP] Begin GeOp::ComputeAsync" << ", kernel_name:" << geop_name << ", num_inputs:" << num_inputs << ", num_outputs:" << ctx->num_outputs(); int64 startTime = InferShapeUtil::GetCurrentTimestap(); std::vector input_shapes; @@ -434,6 +456,7 @@ void GeOp::ComputeAsync(OpKernelContext *ctx, DoneCallback done) { bool is_set_dynamic_config = !sess_options_["ge.inputShape"].empty() && !sess_options_["ge.dynamicDims"].empty(); bool is_tuning = !mstune_mode_.empty() && !work_path_.empty(); if (is_set_dynamic_config && is_tuning) { + ADP_LOG(ERROR) << "dynamic input config can not use with mstuning."; LOG(FATAL) << "dynamic input config can not use with mstuning."; } else if (is_set_dynamic_config && !is_tuning) { cache_graph_id = graph_id_; @@ -487,9 +510,9 @@ void GeOp::ComputeAsync(OpKernelContext *ctx, DoneCallback done) { Status status_out = WriteTextProto(Env::Default(), tmodel_path, ori_graph_def); } int64 endTime = InferShapeUtil::GetCurrentTimestap(); - LOG(INFO) << "[GEOP] In GEOP computeAsync, kernel_name:" << geop_name << " ,TFadapter cost time: [" + ADP_LOG(INFO) << "[GEOP] In GEOP computeAsync, kernel_name:" << geop_name << " ,TFadapter cost time: [" << ((endTime - startTime) / kMicrosToMillis) << " ms]"; - LOG(INFO) << "[GEOP] TFadpter process graph success, GE parser begin, kernel_name:" << geop_name + ADP_LOG(INFO) << "[GEOP] TFadpter process graph success, GE parser begin, kernel_name:" << geop_name << " ,tf session: " << tf_session_ << " ,graph id :" << cache_graph_id; // parser, tensorflow graph to ge graph std::shared_ptr model_parser = @@ -505,9 +528,10 @@ void GeOp::ComputeAsync(OpKernelContext *ctx, DoneCallback done) { auto build_sub_graph = [this, flib_def](const google::protobuf::Message *root_proto, const std::string &graph) -> std::unique_ptr { // const tensorflow::GraphDef *graph_def_in = reinterpret_cast(root_proto); - LOG(INFO) << "[GEOP] build_sub_graph enter, sub graph name is " << graph; + ADP_LOG(INFO) << "[GEOP] build_sub_graph enter, sub graph name is " << graph; const FunctionDef *func_def = flib_def->Find(graph); if (func_def == nullptr) { + ADP_LOG(ERROR) << "[GEOP] Sub graph not found in library, sub graph name is " << graph; LOG(ERROR) << "[GEOP] Sub graph not found in library, sub graph name is " << graph; return nullptr; } @@ -515,10 +539,11 @@ void GeOp::ComputeAsync(OpKernelContext *ctx, DoneCallback done) { Graph subgraph(flib_def); Status status = InferShapeUtil::GetSubGraphFromFunctionDef(*flib_def, *func_def, &subgraph); if (status != Status::OK()) { + ADP_LOG(ERROR) << "[GEOP] Get subgraph from functiondef fail."; LOG(ERROR) << "[GEOP] Get subgraph from functiondef fail."; return nullptr; } - LOG(INFO) << "[GEOP] Get subgraph from functiondef success."; + ADP_LOG(INFO) << "[GEOP] Get subgraph from functiondef success."; bool is_initialize = false; for (Node *node : subgraph.nodes()) { @@ -526,6 +551,8 @@ void GeOp::ComputeAsync(OpKernelContext *ctx, DoneCallback done) { // Add Input&Output Desc into NodeDef if (GenerateDesc(node) != Status::OK()) { + ADP_LOG(WARNING) << "[GEOP] name: " << node->name() << " op:" << node->type_string() + << " Generate desc failed in subgraph."; LOG(WARNING) << "[GEOP] name: " << node->name() << " op:" << node->type_string() << " Generate desc failed in subgraph."; } @@ -533,6 +560,7 @@ void GeOp::ComputeAsync(OpKernelContext *ctx, DoneCallback done) { unique_ptr sub_graph_def(new (std::nothrow) GraphDef()); if (sub_graph_def == nullptr) { + ADP_LOG(ERROR) << "[GEOP] Malloc memory for subgraph def fail."; LOG(ERROR) << "[GEOP] Malloc memory for subgraph def fail."; return nullptr; } @@ -546,7 +574,7 @@ void GeOp::ComputeAsync(OpKernelContext *ctx, DoneCallback done) { string tmodel_path = tmpmodel_path + graph.c_str() + ".pbtxt"; Status status_out = WriteTextProto(Env::Default(), tmodel_path, *graph_def_out.get()); } - LOG(INFO) << "[GEOP] build_sub_graph exit, sub graph name is " << graph; + ADP_LOG(INFO) << "[GEOP] build_sub_graph exit, sub graph name is " << graph; return graph_def_out; }; @@ -556,7 +584,7 @@ void GeOp::ComputeAsync(OpKernelContext *ctx, DoneCallback done) { done); domi::GetContext().format = ge::GetParserContext().format; - LOG(INFO) << "[GEOP] Tensorflow graph parse to ge graph success, kernel_name:" << geop_name + ADP_LOG(INFO) << "[GEOP] Tensorflow graph parse to ge graph success, kernel_name:" << geop_name << " ,tf session: " << tf_session_ << " ,graph id: " << cache_graph_id; size_t nodes = compute_graph->GetAllNodesSize(); @@ -564,7 +592,7 @@ void GeOp::ComputeAsync(OpKernelContext *ctx, DoneCallback done) { build_flag_ = true; compute_graph_empty_ = true; int64 endTime = InferShapeUtil::GetCurrentTimestap(); - LOG(INFO) << "[GEOP] End GeOp::ComputeAsync, compute_graph is empty, kernel_name:" << geop_name + ADP_LOG(INFO) << "[GEOP] End GeOp::ComputeAsync, compute_graph is empty, kernel_name:" << geop_name << ", ret_status:" << ToString(ge::SUCCESS) << " , tf session: " << tf_session_ << " ,graph id: " << cache_graph_id << " [" << ((endTime - startTime) / kMicrosToMillis) << " ms]"; done(); @@ -578,12 +606,12 @@ void GeOp::ComputeAsync(OpKernelContext *ctx, DoneCallback done) { } if (is_host_graph_) { - LOG(INFO) << "[GEOP] set graph option."; + ADP_LOG(INFO) << "[GEOP] set graph option."; graph_options_["ge.exec.placement"] = "HOST"; } if (is_tuning) { if (!is_train_graph_) { - LOG(INFO) << "[GEOP] in tune mode, nontraining graphs should be cache."; + ADP_LOG(INFO) << "[GEOP] in tune mode, nontraining graphs should be cache."; OP_REQUIRES_ASYNC(ctx, SessionManager::GetInstance().CacheGeGraphs(ge_session_, ge_graph), errors::Internal("[GEOP] cache ge session failed."), done); build_flag_ = true; @@ -591,10 +619,10 @@ void GeOp::ComputeAsync(OpKernelContext *ctx, DoneCallback done) { done(); return; } else { - LOG(INFO) << "[GEOP] in tune mode, training graph handled by tools."; + ADP_LOG(INFO) << "[GEOP] in tune mode, training graph handled by tools."; uint32_t device_id = 0; OP_REQUIRES_OK_ASYNC(ctx, GetEnvDeviceID(device_id), done); - LOG(INFO) << "[GEOP] in tuning func, mstune_mode_:" << mstune_mode_ + ADP_LOG(INFO) << "[GEOP] in tuning func, mstune_mode_:" << mstune_mode_ << " auto_tune_mode_:" << auto_tune_mode_; std::map tune_options = {{"work_path", work_path_}, {"job_type", mstune_mode_}, @@ -609,7 +637,7 @@ void GeOp::ComputeAsync(OpKernelContext *ctx, DoneCallback done) { errors::Internal("[GEOP] ge ge session nontraining graphs failed."), done); MsTuneStatus tune_ret = (*tuning_api_)(ge_graph, ge_graphs, ge_session_, options); OP_REQUIRES_ASYNC(ctx, tune_ret == MSTUNE_SUCCESS, errors::Internal("[GEOP] exec msTuning func failed."), done); - LOG(INFO) << "[GEOP] msTuning success."; + ADP_LOG(INFO) << "[GEOP] msTuning success."; build_flag_ = true; BuildOutTensorInfo(ctx); done(); @@ -621,13 +649,15 @@ void GeOp::ComputeAsync(OpKernelContext *ctx, DoneCallback done) { status = ge_session_->AddGraph(cache_graph_id, ge_graph, graph_options_); if (status != ge::SUCCESS) { std::this_thread::sleep_for(std::chrono::milliseconds(kFatalSleepTime)); + ADP_LOG(ERROR) << "[GEOP] call ge session add graph failed, kernel: " << geop_name << " ,tf session: " + << tf_session_ << ", graph id: " << cache_graph_id; LOG(FATAL) << "[GEOP] call ge session add graph failed, kernel: " << geop_name << " ,tf session: " << tf_session_ << ", graph id: " << cache_graph_id; OP_REQUIRES_ASYNC(ctx, status == ge::SUCCESS, errors::Unavailable("[GEOP] GE session add graph failed, domi_ret : ", ToString(status)), done); } else { add_graph_flag_ = true; - LOG(INFO) << "[GEOP] Add graph to ge session success, kernel_name:" << geop_name + ADP_LOG(INFO) << "[GEOP] Add graph to ge session success, kernel_name:" << geop_name << " ,tf session: " << tf_session_ << " ,graph id:" << cache_graph_id; } build_flag_ = true; @@ -638,7 +668,7 @@ void GeOp::ComputeAsync(OpKernelContext *ctx, DoneCallback done) { } else { if (compute_graph_empty_) { int64 endTime = InferShapeUtil::GetCurrentTimestap(); - LOG(INFO) << "[GEOP] End GeOp::ComputeAsync, compute_graph is empty, kernel_name:" << geop_name + ADP_LOG(INFO) << "[GEOP] End GeOp::ComputeAsync, compute_graph is empty, kernel_name:" << geop_name << ", ret_status:" << ToString(ge::SUCCESS) << " , tf session: " << tf_session_ << " ,graph id: " << cache_graph_id << " [" << ((endTime - startTime) / kMicrosToMillis) << " ms]"; done(); @@ -647,7 +677,7 @@ void GeOp::ComputeAsync(OpKernelContext *ctx, DoneCallback done) { } if (is_tuning) { - LOG(INFO) << "in mstune mode, graph only execute once, The remaining steps return directly."; + ADP_LOG(INFO) << "in mstune mode, graph only execute once, The remaining steps return directly."; BuildOutTensorInfo(ctx); done(); return; @@ -657,31 +687,36 @@ void GeOp::ComputeAsync(OpKernelContext *ctx, DoneCallback done) { auto callback = [done, ctx, run_start_time](ge::Status ge_status, std::vector &outputs) { if (ge_status == ge::SUCCESS) { if (BuildOutputTensorInfo(ctx, outputs) != Status::OK()) { + ADP_LOG(ERROR) << ctx->op_kernel().name() << " GEOP::DoRunAsync get output failed."; LOG(FATAL) << ctx->op_kernel().name() << " GEOP::DoRunAsync get output failed."; } } else if (ge_status == ge::END_OF_SEQUENCE) { ctx->SetStatus(errors::OutOfRange("End of sequence")); + ADP_LOG(ERROR) << "[GEOP] Out of range: End of sequence."; LOG(ERROR) << "[GEOP] Out of range: End of sequence."; } else if (ge_status != ge::SUCCESS) { tensorflow::Status tfStatus = errors::Unavailable(ToString(ge_status)); ctx->CtxFailureWithWarning(tfStatus); std::this_thread::sleep_for(std::chrono::milliseconds(kFatalSleepTime)); + ADP_LOG(ERROR) << ctx->op_kernel().name() << "GEOP::::DoRunAsync Failed"; LOG(FATAL) << ctx->op_kernel().name() << "GEOP::::DoRunAsync Failed"; } int64 run_end_time = InferShapeUtil::GetCurrentTimestap(); - LOG(INFO) << "[GEOP] RunGraphAsync callback, status:" << ge_status << ", kernel_name:" << ctx->op_kernel().name() - << "[ " << (run_end_time - run_start_time) << "us]"; + ADP_LOG(INFO) << "[GEOP] RunGraphAsync callback, status:" << ge_status << ", kernel_name:" + << ctx->op_kernel().name() << "[ " << (run_end_time - run_start_time) << "us]"; done(); }; std::vector inputs; OP_REQUIRES_OK_ASYNC(ctx, (BuildInputTensorInfo(ctx, inputs)), done); - LOG(INFO) << "[GEOP] Call ge session RunGraphAsync, kernel_name:" << geop_name << " ,tf session: " << tf_session_ + ADP_LOG(INFO) << "[GEOP] Call ge session RunGraphAsync, kernel_name:" << geop_name << " ,tf session: " << tf_session_ << " ,graph id: " << cache_graph_id; // call ge session runGraphAsync api ge::Status status = ge_session_->RunGraphAsync(cache_graph_id, inputs, callback); if (status != ge::SUCCESS) { std::this_thread::sleep_for(std::chrono::milliseconds(kFatalSleepTime)); + ADP_LOG(ERROR) << "[GEOP] call ge session RunGraphAsync Failed, kernel:" << geop_name << " ,tf session: " + << tf_session_ << " ,graph id: " << cache_graph_id; LOG(FATAL) << "[GEOP] call ge session RunGraphAsync Failed, kernel:" << geop_name << " ,tf session: " << tf_session_ << " ,graph id: " << cache_graph_id; } @@ -689,7 +724,7 @@ void GeOp::ComputeAsync(OpKernelContext *ctx, DoneCallback done) { errors::Unavailable("ge session run graph failed, ret_status:", ToString(status)), done); int64 endTime = InferShapeUtil::GetCurrentTimestap(); - LOG(INFO) << "[GEOP] End GeOp::ComputeAsync, kernel_name:" << geop_name << ", ret_status:" << ToString(status) + ADP_LOG(INFO) << "[GEOP] End GeOp::ComputeAsync, kernel_name:" << geop_name << ", ret_status:" << ToString(status) << " ,tf session: " << tf_session_ << " ,graph id: " << cache_graph_id << " [" << ((endTime - startTime) / kMicrosToMillis) << " ms]"; return; @@ -705,11 +740,11 @@ void GeOp::AddNodeAttrs(Node *node, bool &is_initialize) { if (node_def.op() == "Where") { is_initialize = InferShapeUtil::IsInitializedGraph(node); } if (node->name() == "IterationOp") { this->need_iteration_ = true; - LOG(INFO) << "subgraph has iteration op."; + ADP_LOG(INFO) << "subgraph has iteration op."; } if (node->name() == "var_in_host") { is_host_graph_ = true; - LOG(INFO) << "[GEOP] variable subgraph is initialized in host."; + ADP_LOG(INFO) << "[GEOP] variable subgraph is initialized in host."; } if (node->name().find("_Allreduce") != string::npos) { is_train_graph_ = true; @@ -730,6 +765,7 @@ Status GeOp::BuildGraphDef(const FunctionLibraryDefinition &flib_def, const Func Graph graph(OpRegistry::Global()); Status ret = InferShapeUtil::InferShape(input_vec, &flib_def, &func_def, &graph); if (!ret.ok()) { + ADP_LOG(ERROR) << "[GEOP] InferShape failed, " << ret.error_message(); LOG(ERROR) << "[GEOP] InferShape failed, " << ret.error_message(); return ret; } @@ -744,6 +780,8 @@ Status GeOp::BuildGraphDef(const FunctionLibraryDefinition &flib_def, const Func // Add Input&Output Desc into NodeDef ret = this->GenerateDesc(node); if (!ret.ok()) { + ADP_LOG(ERROR) << "[GEOP] node: " << node->name() << " GenerateDesc failed, " + << ret.error_message(); LOG(ERROR) << "[GEOP] node: " << node->name() << " GenerateDesc failed, " << ret.error_message(); return ret; @@ -773,6 +811,7 @@ Status GeOp::BuildGraphDef(const FunctionLibraryDefinition &flib_def, const Func if (is_set_dynamic_config) { ret = ChangeInputsShapeDesc(); if (!ret.ok()) { + ADP_LOG(ERROR) << "[GEOP] ChangeInputsShapeDesc failed, " << ret.error_message(); LOG(ERROR) << "[GEOP] ChangeInputsShapeDesc failed, " << ret.error_message(); return ret; } @@ -825,7 +864,7 @@ Status GeOp::ChangeInputsShapeDesc() { Split(input_shapes, result, ";"); //e.g. result:["data:2,3", "data1:3,4"] if (dynamic_shape_nodes_.size() == 1 && dynamic_shape_nodes_[0]->type_string() == "IteratorGetNext") { - LOG(INFO) << "[GEOP] change " << dynamic_shape_nodes_[0]->name() << " shape desc."; + ADP_LOG(INFO) << "[GEOP] change " << dynamic_shape_nodes_[0]->name() << " shape desc."; if (dynamic_shape_nodes_[0]->num_outputs() != result.size()) { return errors::InvalidArgument("input_shape is not match inputs num in graph"); } @@ -843,7 +882,7 @@ Status GeOp::ChangeInputsShapeDesc() { } } for (size_t i = 0; i < dynamic_shape_nodes_.size(); ++i) { - LOG(INFO) << "[GEOP] change " << dynamic_shape_nodes_[i]->name() << " shape desc."; + ADP_LOG(INFO) << "[GEOP] change " << dynamic_shape_nodes_[i]->name() << " shape desc."; NodeDef &node_def = const_cast(dynamic_shape_nodes_[i]->def()); AttrValue &output_tensor_descs = (*node_def.mutable_attr())[OUTPUT_DESC]; AttrValue attr_shape_value; @@ -851,24 +890,27 @@ Status GeOp::ChangeInputsShapeDesc() { (*output_tensor_descs.mutable_list()->mutable_func(0)->mutable_attr())[SERIALIZE_SHAPE] = attr_shape_value; } } - LOG(INFO) << "[GEOP] change input shapes desc success."; + ADP_LOG(INFO) << "[GEOP] change input shapes desc success."; return Status::OK(); } void GeOp::SetShapesToOutputDesc(const std::vector &input_shapes, const int &index, AttrValue &attr_shape_value) { if (input_shapes.empty()) { + ADP_LOG(ERROR) << "[GEOP] input_shapes is empty."; LOG(ERROR) << "[GEOP] input_shapes is empty."; return; } if (index < 0) { + ADP_LOG(ERROR) << "[GEOP] index must more than 0."; LOG(ERROR) << "[GEOP] index must more than 0."; return; } - LOG(INFO) << "[GEOP] get input: " << index << " input shape is: " << input_shapes[index]; + ADP_LOG(INFO) << "[GEOP] get input: " << index << " input shape is: " << input_shapes[index]; std::vector shape; Split(input_shapes[index], shape, ":"); // e.g. shape:["data", "2,3,4"] if (shape.empty() || shape.size() != 2) { + ADP_LOG(ERROR) << "[GEOP] shape is empty or shape size is not 2."; LOG(ERROR) << "[GEOP] shape is empty or shape size is not 2."; return; } @@ -900,6 +942,7 @@ Status GeOp::BuildInputTensorInfo(OpKernelContext *ctx, std::vectorConvertToGeDataType(static_cast(data_type)); if (type == ge::DT_UNDEFINED) { + ADP_LOG(ERROR) << "[GEOP] No Supported datatype : " << data_type; LOG(ERROR) << "[GEOP] No Supported datatype : " << data_type; return errors::InvalidArgument("No Supported datatype : ", data_type); } @@ -962,7 +1005,7 @@ Status GeOp::GenerateDesc(Node *&node) { NameAttrList desc_attr = in_node->def().attr().at(OUTPUT_DESC).list().func(src_output); *(input_tensor_descs.mutable_list()->add_func()) = desc_attr; } else { - LOG(INFO) << "[GEOP] no OUTPUT_DESC: " << node->name() << " <-- " << in_node->name(); + ADP_LOG(INFO) << "[GEOP] no OUTPUT_DESC: " << node->name() << " <-- " << in_node->name(); if (num > 0 && node->type_string() == "Merge" && in_node->type_string() == "NextIteration") { node->input_node(num - 1, &in_node); node->input_edge(num - 1, &in_edge); @@ -986,11 +1029,13 @@ Status GeOp::GenerateDesc(Node *&node) { AttrValue shape_value; const auto &it = node_def.attr().find(KEY_SHAPE); if (it == node_def.attr().end()) { // no find + ADP_LOG(WARNING) << "[GEOP] There is no infershape of node : " << node_def.name(); LOG(WARNING) << "[GEOP] There is no infershape of node : " << node_def.name(); } else { shape_value = node_def.attr().at(KEY_SHAPE); uint32_t shape_size = static_cast(shape_value.list().shape_size()); if (shape_size != outputs.size()) { + ADP_LOG(ERROR) << "[GEOP] size not equal, shape_size : " << shape_size << " outputs size:" << outputs.size(); LOG(ERROR) << "[GEOP] size not equal, shape_size : " << shape_size << " outputs size:" << outputs.size(); shape_value.clear_list(); } diff --git a/tf_adapter/kernels/hccl_ops.cc b/tf_adapter/kernels/hccl_ops.cc index d5d474b1c4cdd0e1ff2d7fdb7d531b05946684b2..fc7b69e6657ed6511c9977f8805a84335afe5748 100644 --- a/tf_adapter/kernels/hccl_ops.cc +++ b/tf_adapter/kernels/hccl_ops.cc @@ -26,13 +26,14 @@ limitations under the License. ==============================================================================*/ #include "tensorflow/core/framework/op_kernel.h" +#include "tf_adapter/common/adp_logger.h" namespace tensorflow { class HcomAllReduceOpKernel : public OpKernel { public: explicit HcomAllReduceOpKernel(OpKernelConstruction *context) : OpKernel(context) {} ~HcomAllReduceOpKernel() {} - void Compute(OpKernelContext *context) override { LOG(INFO) << "HcomAllReduceOp Compute."; } + void Compute(OpKernelContext *context) override { ADP_LOG(INFO) << "HcomAllReduceOp Compute."; } }; REGISTER_KERNEL_BUILDER(Name("HcomAllReduce").Device(DEVICE_CPU), HcomAllReduceOpKernel); @@ -41,7 +42,7 @@ class HcomAllGatherOpKernel : public OpKernel { public: explicit HcomAllGatherOpKernel(OpKernelConstruction *context) : OpKernel(context) {} ~HcomAllGatherOpKernel() {} - void Compute(OpKernelContext *context) override { LOG(INFO) << "HcomAllGatherOp Compute."; } + void Compute(OpKernelContext *context) override { ADP_LOG(INFO) << "HcomAllGatherOp Compute."; } }; REGISTER_KERNEL_BUILDER(Name("HcomAllGather").Device(DEVICE_CPU), HcomAllGatherOpKernel); @@ -50,7 +51,7 @@ class HcomBroadcastOpKernel : public OpKernel { public: explicit HcomBroadcastOpKernel(OpKernelConstruction *context) : OpKernel(context) {} ~HcomBroadcastOpKernel() {} - void Compute(OpKernelContext *context) override { LOG(INFO) << "HcomBroadcastOp Compute."; } + void Compute(OpKernelContext *context) override { ADP_LOG(INFO) << "HcomBroadcastOp Compute."; } }; REGISTER_KERNEL_BUILDER(Name("HcomBroadcast").Device(DEVICE_CPU), HcomBroadcastOpKernel); @@ -59,7 +60,7 @@ class HcomReduceOpKernel : public OpKernel { public: explicit HcomReduceOpKernel(OpKernelConstruction *context) : OpKernel(context) {} ~HcomReduceOpKernel() {} - void Compute(OpKernelContext *context) override { LOG(INFO) << "HcomReduceOp Compute."; } + void Compute(OpKernelContext *context) override { ADP_LOG(INFO) << "HcomReduceOp Compute."; } }; REGISTER_KERNEL_BUILDER(Name("HcomReduce").Device(DEVICE_CPU), HcomReduceOpKernel); @@ -68,7 +69,7 @@ class HcomReduceScatterOpKernel : public OpKernel { public: explicit HcomReduceScatterOpKernel(OpKernelConstruction *context) : OpKernel(context) {} ~HcomReduceScatterOpKernel() {} - void Compute(OpKernelContext *context) override { LOG(INFO) << "HcomReduceScatterOp Compute."; } + void Compute(OpKernelContext *context) override { ADP_LOG(INFO) << "HcomReduceScatterOp Compute."; } }; REGISTER_KERNEL_BUILDER(Name("HcomReduceScatter").Device(DEVICE_CPU), HcomReduceScatterOpKernel); @@ -77,7 +78,7 @@ class HcomSendOpKernel : public OpKernel { public: explicit HcomSendOpKernel(OpKernelConstruction *context) : OpKernel(context) {} ~HcomSendOpKernel() {} - void Compute(OpKernelContext *context) override { LOG(INFO) << "HcomSendOpKernel Compute."; } + void Compute(OpKernelContext *context) override { ADP_LOG(INFO) << "HcomSendOpKernel Compute."; } }; REGISTER_KERNEL_BUILDER(Name("HcomSend").Device(DEVICE_CPU), HcomSendOpKernel); @@ -86,7 +87,7 @@ class HcomReceiveOpKernel : public OpKernel { public: explicit HcomReceiveOpKernel(OpKernelConstruction *context) : OpKernel(context) {} ~HcomReceiveOpKernel() {} - void Compute(OpKernelContext *context) override { LOG(INFO) << "HcomReceiveOpKernel Compute."; } + void Compute(OpKernelContext *context) override { ADP_LOG(INFO) << "HcomReceiveOpKernel Compute."; } }; REGISTER_KERNEL_BUILDER(Name("HcomReceive").Device(DEVICE_CPU), HcomReceiveOpKernel); @@ -97,7 +98,7 @@ public: ~HcomRemoteReadOpKernel() {} void Compute(OpKernelContext* context) override { - LOG(INFO) << "HcomRemoteReadOpKernel Compute."; + ADP_LOG(INFO) << "HcomRemoteReadOpKernel Compute."; } }; @@ -109,7 +110,7 @@ public: ~HcomRemoteRefReadOpKernel() {} void Compute(OpKernelContext* context) override { - LOG(INFO) << "HcomRemoteRefRead Compute."; + ADP_LOG(INFO) << "HcomRemoteRefRead Compute."; } }; @@ -121,7 +122,7 @@ public: ~HcomRemoteWriteKernel() {} void Compute(OpKernelContext* context) override { - LOG(INFO) << "HcomRemoteWriteKernel Compute."; + ADP_LOG(INFO) << "HcomRemoteWriteKernel Compute."; } }; @@ -133,7 +134,7 @@ public: ~HcomRemoteScatterWriteOpKernel() {} void Compute(OpKernelContext* context) override { - LOG(INFO) << "HcomRemoteScatterWrite Compute."; + ADP_LOG(INFO) << "HcomRemoteScatterWrite Compute."; } }; diff --git a/tf_adapter/kernels/host_queue_dataset_op.cc b/tf_adapter/kernels/host_queue_dataset_op.cc index b55e557366f476512e05dc99c4b929ceca622708..95ccbeb07eb7275ae79b7468251e4eb544839de1 100644 --- a/tf_adapter/kernels/host_queue_dataset_op.cc +++ b/tf_adapter/kernels/host_queue_dataset_op.cc @@ -37,6 +37,7 @@ limitations under the License. #include "tensorflow/core/lib/strings/str_util.h" #include "tensorflow/core/util/env_var.h" #include "tf_adapter/common/common.h" +#include "tf_adapter/common/adp_logger.h" #include "tf_adapter/util/npu_attrs.h" #include #include @@ -66,7 +67,7 @@ class HostQueueDatasetOp : public DatasetOpKernel { OP_REQUIRES_OK(ctx, ctx->GetAttr("channel_name", &channel_name_)); OP_REQUIRES_OK(ctx, ctx->GetAttr("output_types", &output_types_)); OP_REQUIRES_OK(ctx, ctx->GetAttr("output_shapes", &output_shapes_)); - LOG(INFO) << "Start to init tdt."; + ADP_LOG(INFO) << "Start to init tdt."; uint32_t device_id = 0; OP_REQUIRES_OK(ctx, GetEnvDeviceID(device_id)); int32_t tdt_status = TdtHostInit(device_id); @@ -74,13 +75,14 @@ class HostQueueDatasetOp : public DatasetOpKernel { tdt_release = false; } ~HostQueueDatasetOp() { - LOG(INFO) << "Start to destroy tdt."; + ADP_LOG(INFO) << "Start to destroy tdt."; if (!tdt_release) { int32_t tdt_status = TdtHostDestroy(); if (tdt_status != 0) { + ADP_LOG(ERROR) << "Tdt client close failed."; LOG(ERROR) << "Tdt client close failed."; } else { - LOG(INFO) << "Tdt client close success."; + ADP_LOG(INFO) << "Tdt client close success."; tdt_release = true; } } @@ -143,7 +145,7 @@ class HostQueueDatasetOp : public DatasetOpKernel { cancelled_ = true; cond_var_.notify_all(); } - LOG(INFO) << "HostQueueDatasetOp's iterator is released."; + ADP_LOG(INFO) << "HostQueueDatasetOp's iterator is released."; } void GetDataThread(const std::shared_ptr &ctx) { @@ -169,9 +171,10 @@ class HostQueueDatasetOp : public DatasetOpKernel { if (!buffer_element.status.ok() || (buffer_element.status.ok() && end_of_sequence)) { if (!buffer_element.status.ok()) { + ADP_LOG(ERROR) << "Failed to get tensor data, Status:" << buffer_element.status.ToString(); LOG(ERROR) << "Failed to get tensor data, Status:" << buffer_element.status.ToString(); } else { - LOG(INFO) << "Finish to get tensor data, Status:" << buffer_element.status.ToString() + ADP_LOG(INFO) << "Finish to get tensor data, Status:" << buffer_element.status.ToString() << "; end_of_sequence:" << end_of_sequence; } mutex_lock lck(mu_); @@ -185,6 +188,7 @@ class HostQueueDatasetOp : public DatasetOpKernel { mutex_lock lck(mu_); for (auto &tensor : args) { if (tensor.TotalBytes() > UINT64_MAX - total_bytes_) { + ADP_LOG(ERROR) << "The size of tensor is too big"; LOG(ERROR) << "The size of tensor is too big"; buffer_element.host_thread_finished = true; buffer_.push_back(std::move(buffer_element)); @@ -210,7 +214,7 @@ class HostQueueDatasetOp : public DatasetOpKernel { RecordStart(ctx.get()); } if (cancelled_ || finish_send_) { - LOG(INFO) << "Host queue " << dataset()->channel_name_ + ADP_LOG(INFO) << "Host queue " << dataset()->channel_name_ << " push data thread exit with cancelled: " << cancelled_ << ", finished:" << finish_send_ << " when wait data."; return; @@ -220,14 +224,15 @@ class HostQueueDatasetOp : public DatasetOpKernel { DataItem end_item; if (buffer_.front().status.ok()) { end_item.dataType_ = TDT_END_OF_SEQUENCE; - LOG(INFO) << "Push data finish, end_of_sequence_ is true."; + ADP_LOG(INFO) << "Push data finish, end_of_sequence_ is true."; } else { end_item.dataType_ = TDT_ABNORMAL; + ADP_LOG(ERROR) << "Get data failed " << buffer_.front().status.ToString(); LOG(ERROR) << "Get data failed " << buffer_.front().status.ToString(); } items.emplace_back(end_item); int32_t tdt_status = TdtHostPushData(dataset()->channel_name_, items); - if (tdt_status != 0) { LOG(INFO) << "End training as tdt host push end data failed " << tdt_status; } + if (tdt_status != 0) { ADP_LOG(INFO) << "End training as tdt host push end data failed " << tdt_status; } cancelled_ = true; cond_var_.notify_all(); return; @@ -252,6 +257,9 @@ class HostQueueDatasetOp : public DatasetOpKernel { std::shared_ptr(const_cast(tensor.tensor_data().data()), [](void *elem) {}); } else if (tensor.dtype() == DT_STRING) { if (tensor.dims() != 0) { + ADP_LOG(ERROR) << "input of DT_STRING type should be scalar," + " current dims:" + << tensor.dims(); LOG(ERROR) << "input of DT_STRING type should be scalar," " current dims:" << tensor.dims(); @@ -264,6 +272,7 @@ class HostQueueDatasetOp : public DatasetOpKernel { data_item.dataLen_ = value.size(); data_item.dataPtr_ = std::shared_ptr(const_cast(value.data()), [](void *elem) {}); } else { + ADP_LOG(ERROR) << "Unexpected data type " << DataTypeString(tensor.dtype()); LOG(ERROR) << "Unexpected data type " << DataTypeString(tensor.dtype()); mutex_lock lck(mu_); cancelled_ = true; @@ -276,7 +285,7 @@ class HostQueueDatasetOp : public DatasetOpKernel { // call tdt interface int32_t tdt_status = TdtHostPushData(dataset()->channel_name_, items); if (tdt_status != 0) { - LOG(INFO) << "End training as tdt host push data finished: " << tdt_status; + ADP_LOG(INFO) << "End training as tdt host push data finished: " << tdt_status; mutex_lock lck(mu_); cancelled_ = true; cond_var_.notify_all(); @@ -314,12 +323,12 @@ class HostQueueDatasetOp : public DatasetOpKernel { } Status Initialize(IteratorContext *ctx) override { - LOG(INFO) << "Start to check channel name. channelName: " << dataset()->channel_name_; + ADP_LOG(INFO) << "Start to check channel name. channelName: " << dataset()->channel_name_; if (dataset()->channel_name_.empty()) { return errors::InvalidArgument("HostQueueDataset channel_name is null."); } - LOG(INFO) << "Start to check receive and send thread."; + ADP_LOG(INFO) << "Start to check receive and send thread."; try { input_impls_.resize(dataset()->inputs_.size()); } catch (...) { return errors::InvalidArgument("HostQueueDataset resize failed."); } @@ -334,13 +343,13 @@ class HostQueueDatasetOp : public DatasetOpKernel { TF_RETURN_IF_ERROR(EnsureSendThreadStarted(ctx)); } - LOG(INFO) << "HostQueue success to Initialize. channelName: " << dataset()->channel_name_; + ADP_LOG(INFO) << "HostQueue success to Initialize. channelName: " << dataset()->channel_name_; return Status::OK(); } Status GetNextInternal(IteratorContext *ctx, vector *outTensors, bool *endOfSequence) override { *endOfSequence = false; - LOG(INFO) << "HostQueue Get Next data."; + ADP_LOG(INFO) << "HostQueue Get Next data."; return Status::OK(); } diff --git a/tf_adapter/kernels/infeed_outfeed_ops.cc b/tf_adapter/kernels/infeed_outfeed_ops.cc index ef218493ab1d913c421b2458ca67cc6a9af50bbb..e9a2d67fb31ca44c8544e570b9412c8c0f4ac6a7 100644 --- a/tf_adapter/kernels/infeed_outfeed_ops.cc +++ b/tf_adapter/kernels/infeed_outfeed_ops.cc @@ -29,6 +29,7 @@ limitations under the License. #include "tdt/tdt_host_interface.h" #include "tensorflow/core/framework/op_kernel.h" #include "tf_adapter/common/common.h" +#include "tf_adapter/common/adp_logger.h" #include "third_party/eigen3/unsupported/Eigen/CXX11/Tensor" #include @@ -64,7 +65,7 @@ Status GetTensorShape(const string &tensor_shape, TensorShape &shape) { Status ConvertDataItem2Tensor(const std::vector &items, std::vector &tensors) { for (auto &item : items) { if (item.dataType_ == tdt::TDT_END_OF_SEQUENCE) { - LOG(INFO) << "End of processing."; + ADP_LOG(INFO) << "End of processing."; return Status::OK(); } DataType type = DT_FLOAT; @@ -96,10 +97,10 @@ class OutfeedEnqueueOp : public OpKernel { public: explicit OutfeedEnqueueOp(OpKernelConstruction *ctx) : OpKernel(ctx) { OP_REQUIRES_OK(ctx, ctx->GetAttr("channel_name", &channel_name_)); - LOG(INFO) << "OutfeedEnqueueOp built"; + ADP_LOG(INFO) << "OutfeedEnqueueOp built"; } - ~OutfeedEnqueueOp() override { LOG(INFO) << "OutfeedEnqueueOp has been destructed"; } - void Compute(OpKernelContext *ctx) override { LOG(INFO) << "OutfeedEnqueueOp running"; } + ~OutfeedEnqueueOp() override { ADP_LOG(INFO) << "OutfeedEnqueueOp has been destructed"; } + void Compute(OpKernelContext *ctx) override { ADP_LOG(INFO) << "OutfeedEnqueueOp running"; } bool IsExpensive() override { return false; } private: @@ -114,9 +115,9 @@ class OutfeedDequeueOp : public OpKernel { OP_REQUIRES_OK(ctx, ctx->GetAttr("output_types", &output_types_)); OP_REQUIRES_OK(ctx, ctx->GetAttr("output_shapes", &output_shapes_)); OP_REQUIRES(ctx, tdt::TdtHostPreparePopData() == 0, errors::Internal("Prepare Pop Data failed")); - LOG(INFO) << "OutfeedDequeueOp built"; + ADP_LOG(INFO) << "OutfeedDequeueOp built"; } - ~OutfeedDequeueOp() override { LOG(INFO) << "OutfeedDequeueOp has been destructed"; } + ~OutfeedDequeueOp() override { ADP_LOG(INFO) << "OutfeedDequeueOp has been destructed"; } void Compute(OpKernelContext *ctx) override { CHECK_NOT_NULL(ctx); std::vector bundle; @@ -142,11 +143,11 @@ class StopOutfeedDequeueOp : public OpKernel { public: explicit StopOutfeedDequeueOp(OpKernelConstruction *ctx) : OpKernel(ctx) { OP_REQUIRES_OK(ctx, ctx->GetAttr("channel_name", &channel_name_)); - LOG(INFO) << "StopOutfeedDequeueOp built"; + ADP_LOG(INFO) << "StopOutfeedDequeueOp built"; } - ~StopOutfeedDequeueOp() override { LOG(INFO) << "StopOutfeedDequeueOp has been destructed"; } + ~StopOutfeedDequeueOp() override { ADP_LOG(INFO) << "StopOutfeedDequeueOp has been destructed"; } void Compute(OpKernelContext *ctx) override { - LOG(INFO) << "StopOutfeedDequeueOp running"; + ADP_LOG(INFO) << "StopOutfeedDequeueOp running"; OP_REQUIRES(ctx, tdt::TdtHostStop(channel_name_) == 0, errors::Internal("TdtHostStop failed")); } bool IsExpensive() override { return false; } diff --git a/tf_adapter/kernels/lamb_apply_optimizer_assign.cc b/tf_adapter/kernels/lamb_apply_optimizer_assign.cc index 08ffd73757ccc7566ccaaec12c3d94cfbda4e3e7..8bf897d1e66836e7759fe17a60d9d7e4fe81d8cd 100644 --- a/tf_adapter/kernels/lamb_apply_optimizer_assign.cc +++ b/tf_adapter/kernels/lamb_apply_optimizer_assign.cc @@ -26,6 +26,7 @@ limitations under the License. ==============================================================================*/ #include "tensorflow/core/framework/op_kernel.h" +#include "tf_adapter/common/adp_logger.h" namespace tensorflow { class LambApplyOptimizerAssignOp : public OpKernel { @@ -33,7 +34,7 @@ class LambApplyOptimizerAssignOp : public OpKernel { explicit LambApplyOptimizerAssignOp(OpKernelConstruction *context) : OpKernel(context) {} ~LambApplyOptimizerAssignOp() override = default; void Compute(OpKernelContext *context) override { - LOG(INFO) << "LambApplyOptimizerAssignOp Compute, num_inputs: " << context->num_inputs(); + ADP_LOG(INFO) << "LambApplyOptimizerAssignOp Compute, num_inputs: " << context->num_inputs(); } bool IsExpensive() override { return false; } }; diff --git a/tf_adapter/kernels/lamb_apply_weight_assign.cc b/tf_adapter/kernels/lamb_apply_weight_assign.cc index f3ce002da44af8a8e9edc50df156f892b1a08c7e..53f0f1f5f08c62c48c846ea94fc70f1d0dbebc6d 100644 --- a/tf_adapter/kernels/lamb_apply_weight_assign.cc +++ b/tf_adapter/kernels/lamb_apply_weight_assign.cc @@ -26,6 +26,7 @@ limitations under the License. ==============================================================================*/ #include "tensorflow/core/framework/op_kernel.h" +#include "tf_adapter/common/adp_logger.h" namespace tensorflow { class LambApplyWeightAssignOp : public OpKernel { @@ -33,7 +34,7 @@ class LambApplyWeightAssignOp : public OpKernel { explicit LambApplyWeightAssignOp(OpKernelConstruction *context) : OpKernel(context) {} ~LambApplyWeightAssignOp() override = default; void Compute(OpKernelContext *context) override { - LOG(INFO) << "LambApplyWeightAssignOp Compute, num_inputs: " << context->num_inputs(); + ADP_LOG(INFO) << "LambApplyWeightAssignOp Compute, num_inputs: " << context->num_inputs(); } bool IsExpensive() override { return false; } }; diff --git a/tf_adapter/kernels/lars_ops.cc b/tf_adapter/kernels/lars_ops.cc index 327007964c153d6bcf2985bdebbda5330d361e72..2f8d33d024fdd2c0614635674655e952169b2b63 100644 --- a/tf_adapter/kernels/lars_ops.cc +++ b/tf_adapter/kernels/lars_ops.cc @@ -32,16 +32,18 @@ limitations under the License. #include "tensorflow/core/framework/op_kernel.h" #include "tensorflow/core/framework/register_types.h" +#include "tf_adapter/common/adp_logger.h" + namespace tensorflow { template class LarsOp : public OpKernel { public: - explicit LarsOp(OpKernelConstruction *context) : OpKernel(context) { LOG(INFO) << "new LarsOp"; } - ~LarsOp() override { LOG(INFO) << "del LarsOp"; } + explicit LarsOp(OpKernelConstruction *context) : OpKernel(context) { ADP_LOG(INFO) << "new LarsOp"; } + ~LarsOp() override { ADP_LOG(INFO) << "del LarsOp"; } void Compute(OpKernelContext *context) override { int input_num = num_inputs(); - LOG(INFO) << "LarsOp: input num " << input_num; + ADP_LOG(INFO) << "LarsOp: input num " << input_num; input_num = ((input_num - 1) / 2); for (int j = 0; j < input_num; j++) { @@ -60,18 +62,18 @@ class LarsOp : public OpKernel { // Set the value of each element const int N = w_input.size(); - LOG(INFO) << "LarsOp idx " << j << ", data num " << N; + ADP_LOG(INFO) << "LarsOp idx " << j << ", data num " << N; auto sum_w = w_input(0); auto sum_g = g_input(0); for (int i = 1; i < N; i++) { auto w = w_input(i); sum_w += w; - LOG(INFO) << "LarsOp w " << w << ", sum_w " << sum_w; + ADP_LOG(INFO) << "LarsOp w " << w << ", sum_w " << sum_w; auto g = g_input(i); sum_g += g; - LOG(INFO) << "LarsOp g " << g << ", sum_g " << sum_g; + ADP_LOG(INFO) << "LarsOp g " << g << ", sum_g " << sum_g; } auto w_norm = sqrt(sum_w); @@ -85,7 +87,7 @@ class LarsOp : public OpKernel { } } - LOG(INFO) << "in LarsOp"; + ADP_LOG(INFO) << "in LarsOp"; } bool IsExpensive() override { return false; } }; diff --git a/tf_adapter/kernels/lars_v2_op.cc b/tf_adapter/kernels/lars_v2_op.cc index d925820ac6f8e5cc4b6c46a88738c171494d8514..f81810af99cf427d36bf76ecdca2935bd5f1e3a3 100644 --- a/tf_adapter/kernels/lars_v2_op.cc +++ b/tf_adapter/kernels/lars_v2_op.cc @@ -26,16 +26,17 @@ limitations under the License. ==============================================================================*/ #include "tensorflow/core/framework/op_kernel.h" +#include "tf_adapter/common/adp_logger.h" namespace tensorflow { template class LarsV2OP : public OpKernel { public: - explicit LarsV2OP(OpKernelConstruction *context) : OpKernel(context) { LOG(INFO) << "new LarsV2OP"; } - ~LarsV2OP() override { LOG(INFO) << "del LarsV2OP"; } + explicit LarsV2OP(OpKernelConstruction *context) : OpKernel(context) { ADP_LOG(INFO) << "new LarsV2OP"; } + ~LarsV2OP() override { ADP_LOG(INFO) << "del LarsV2OP"; } void Compute(OpKernelContext *context) override { - LOG(INFO) << "LarsV2OP Compute, num_inputs: " << context->num_inputs(); + ADP_LOG(INFO) << "LarsV2OP Compute, num_inputs: " << context->num_inputs(); // Grab the w_input tensor const Tensor &w_tensor = context->input(0); @@ -58,11 +59,11 @@ class LarsV2OP : public OpKernel { for (int i = 1; i < N; i++) { auto w = w_input(i); sum_w += w; - LOG(INFO) << "LarsV2OP w " << w << ", sum_w " << sum_w; + ADP_LOG(INFO) << "LarsV2OP w " << w << ", sum_w " << sum_w; auto g = g_input(i); sum_g += g; - LOG(INFO) << "LarsV2OP g " << g << ", sum_g " << sum_g; + ADP_LOG(INFO) << "LarsV2OP g " << g << ", sum_g " << sum_g; } auto w_norm = sqrt(sum_w); diff --git a/tf_adapter/kernels/log_time_stamp_ops.cc b/tf_adapter/kernels/log_time_stamp_ops.cc index e027bbae787695b6e76c1ef0e04e6421916e3d06..fda1f39ca8ea155bba7c8f05b42e45e8eff36599 100644 --- a/tf_adapter/kernels/log_time_stamp_ops.cc +++ b/tf_adapter/kernels/log_time_stamp_ops.cc @@ -32,13 +32,14 @@ limitations under the License. #include "tensorflow/core/framework/op_kernel.h" #include "tensorflow/core/framework/tensor_types.h" #include "tensorflow/core/platform/macros.h" +#include "tf_adapter/common/adp_logger.h" namespace tensorflow { class LogTimeStampOP : public OpKernel { public: - explicit LogTimeStampOP(OpKernelConstruction *ctx) : OpKernel(ctx) { LOG(INFO) << "new LogTimeStampOP"; } - ~LogTimeStampOP() { LOG(INFO) << "del LogTimeStampOP"; } - void Compute(OpKernelContext *ctx) override { LOG(INFO) << "in LogTimeStampOP"; } + explicit LogTimeStampOP(OpKernelConstruction *ctx) : OpKernel(ctx) { ADP_LOG(INFO) << "new LogTimeStampOP"; } + ~LogTimeStampOP() { ADP_LOG(INFO) << "del LogTimeStampOP"; } + void Compute(OpKernelContext *ctx) override { ADP_LOG(INFO) << "in LogTimeStampOP"; } bool IsExpensive() override { return false; } }; diff --git a/tf_adapter/kernels/maxpooling_op.cc b/tf_adapter/kernels/maxpooling_op.cc index c8180d9bff3e4361610e559188fcde7a180bb35e..fec568c9a3954e54ae4fb0339bc4314cb702aa01 100644 --- a/tf_adapter/kernels/maxpooling_op.cc +++ b/tf_adapter/kernels/maxpooling_op.cc @@ -30,6 +30,7 @@ limitations under the License. #include "tensorflow/core/framework/types.h" #include "tensorflow/core/platform/macros.h" #include "third_party/eigen3/unsupported/Eigen/CXX11/Tensor" +#include "tf_adapter/common/adp_logger.h" namespace tensorflow { namespace { @@ -37,11 +38,11 @@ namespace { class MaxPoolingGradGradWithArgmaxOp : public OpKernel { public: explicit MaxPoolingGradGradWithArgmaxOp(OpKernelConstruction *ctx) : OpKernel(ctx) { - LOG(INFO) << "MaxPoolingGradGradWithArgmaxOp built"; + ADP_LOG(INFO) << "MaxPoolingGradGradWithArgmaxOp built"; } - ~MaxPoolingGradGradWithArgmaxOp() { LOG(INFO) << "MaxPoolingGradGradWithArgmaxOp has been destructed"; } + ~MaxPoolingGradGradWithArgmaxOp() { ADP_LOG(INFO) << "MaxPoolingGradGradWithArgmaxOp has been destructed"; } void Compute(OpKernelContext *ctx) override { - LOG(INFO) << "[ATTENTION] MaxPoolingGradGradWithArgmaxOp can not run on cpu, \ + ADP_LOG(INFO) << "[ATTENTION] MaxPoolingGradGradWithArgmaxOp can not run on cpu, \ only running on npu, please open use_off_line "; } bool IsExpensive() override { return false; } diff --git a/tf_adapter/kernels/npu_cpu_ops.cc b/tf_adapter/kernels/npu_cpu_ops.cc index 533f3499a9523b5dd3f3bf776d04f742cbc0bdf0..15057b605688cd443a218280ec7370bbe985eb7c 100644 --- a/tf_adapter/kernels/npu_cpu_ops.cc +++ b/tf_adapter/kernels/npu_cpu_ops.cc @@ -31,19 +31,20 @@ limitations under the License. #include "tensorflow/core/framework/shape_inference.h" #include "tensorflow/core/framework/resource_op_kernel.h" #include "tf_adapter/util/cache_interface.h" +#include "tf_adapter/common/adp_logger.h" namespace tensorflow { class EmbeddingRankIdOpKernel : public OpKernel { public: explicit EmbeddingRankIdOpKernel(OpKernelConstruction *context) : OpKernel(context) {} ~EmbeddingRankIdOpKernel() {} - void Compute(OpKernelContext *context) override { LOG(INFO) << "EmbeddingRankIdOp Compute."; } + void Compute(OpKernelContext *context) override { ADP_LOG(INFO) << "EmbeddingRankIdOp Compute."; } }; class LruCacheOp : public ResourceOpKernel { public: explicit LruCacheOp(OpKernelConstruction* context) : ResourceOpKernel(context) {} - void Compute(OpKernelContext* context) override { LOG(INFO) << "LruCacheOp Compute"; } + void Compute(OpKernelContext* context) override { ADP_LOG(INFO) << "LruCacheOp Compute"; } private: Status CreateResource(CacheInterface** resource) override EXCLUSIVE_LOCKS_REQUIRED(mu_) { @@ -54,13 +55,13 @@ class LruCacheOp : public ResourceOpKernel { class CacheAddOp : public OpKernel { public: explicit CacheAddOp(OpKernelConstruction *context) : OpKernel(context) {} - void Compute(OpKernelContext *context) override { LOG(INFO) << "CacheAddOp Compute"; } + void Compute(OpKernelContext *context) override { ADP_LOG(INFO) << "CacheAddOp Compute"; } }; class CacheRemoteIndexToLocalOp : public OpKernel { public: explicit CacheRemoteIndexToLocalOp(OpKernelConstruction *context) : OpKernel(context) {} - void Compute(OpKernelContext *context) override { LOG(INFO) << "CacheRemoteIndexToLocalOp Compute"; } + void Compute(OpKernelContext *context) override { ADP_LOG(INFO) << "CacheRemoteIndexToLocalOp Compute"; } }; template @@ -69,7 +70,7 @@ class DeformableOffsetsOp : public OpKernel { explicit DeformableOffsetsOp(OpKernelConstruction *context) : OpKernel(context) {} ~DeformableOffsetsOp() override {} void Compute(OpKernelContext *context) override { - LOG(INFO) << "DeformableOffsetsOp Compute, num_inputs: " + ADP_LOG(INFO) << "DeformableOffsetsOp Compute, num_inputs: " << context->num_inputs(); } bool IsExpensive() override { return false; } @@ -81,7 +82,7 @@ class DeformableOffsetsGradOp : public OpKernel { explicit DeformableOffsetsGradOp(OpKernelConstruction *context) : OpKernel(context) {} ~DeformableOffsetsGradOp() override {} void Compute(OpKernelContext *context) override { - LOG(INFO) << "DeformableOffsetsGradOp Compute, num_inputs: " + ADP_LOG(INFO) << "DeformableOffsetsGradOp Compute, num_inputs: " << context->num_inputs(); } bool IsExpensive() override { return false; } diff --git a/tf_adapter/kernels/npu_sys_ctl_ops.cc b/tf_adapter/kernels/npu_sys_ctl_ops.cc index 8924810224170079f6c77c6573ffb733c19f6d13..17e5fbb62cb852cc3bc70a12ce3f5de21fb9f004 100644 --- a/tf_adapter/kernels/npu_sys_ctl_ops.cc +++ b/tf_adapter/kernels/npu_sys_ctl_ops.cc @@ -47,6 +47,7 @@ limitations under the License. #include "tf_adapter/kernels/geop_npu.h" #include "tf_adapter/util/ge_plugin.h" #include "tf_adapter/util/npu_attrs.h" +#include "tf_adapter/common/adp_logger.h" using namespace tdt; @@ -57,6 +58,7 @@ static int64 GetCurrentTimestamp() { struct timeval tv; int ret = gettimeofday(&tv, nullptr); if (ret != 0) { + ADP_LOG(ERROR) << "Func gettimeofday failed, ret:" << ret; LOG(ERROR) << "Func gettimeofday failed, ret:" << ret; return 0; } @@ -79,7 +81,7 @@ class NPUInit : public OpKernel { }; NPUInit::NPUInit(OpKernelConstruction *ctx) : OpKernel(ctx) { - LOG(INFO) << "NPUInit"; + ADP_LOG(INFO) << "NPUInit"; mutex_lock lock{g_mu}; g_npuInitNum++; string sess_config; @@ -87,41 +89,42 @@ NPUInit::NPUInit(OpKernelConstruction *ctx) : OpKernel(ctx) { if (s.ok()) { init_options_ = NpuAttrs::GetInitOptions(ctx); } else { - LOG(INFO) << "[NPUInit] NPUInit can not get _NpuOptimizer attr, use default init options"; + ADP_LOG(INFO) << "[NPUInit] NPUInit can not get _NpuOptimizer attr, use default init options"; init_options_ = NpuAttrs::GetDefaultInitOptions(); } } void NPUInit::Compute(OpKernelContext *ctx) { if (GePlugin::GetInstance()->IsGlobal()) { - LOG(INFO) << "[NPUInit] GePlugin global, skip GePlugin init"; + ADP_LOG(INFO) << "[NPUInit] GePlugin global, skip GePlugin init"; return; } GePlugin::GetInstance()->Init(init_options_); - LOG(INFO) << "[NPUInit] GePlugin init success"; + ADP_LOG(INFO) << "[NPUInit] GePlugin init success"; } NPUInit::~NPUInit() { - LOG(INFO) << "[~NPUInit] NPUInit destructed"; + ADP_LOG(INFO) << "[~NPUInit] NPUInit destructed"; int64 unInitStartTime = GetCurrentTimestamp(); { mutex_lock lock{g_mu}; if (g_npuInitNum > 0) { g_npuInitNum--; } if (g_npuInitNum != 0) { int64 unInitEndTime = GetCurrentTimestamp(); - LOG(INFO) << "[~NPUInit] NPU Shutdown success. [" << ((unInitEndTime - unInitStartTime) / kMicrosToMillis) + ADP_LOG(INFO) << "[~NPUInit] NPU Shutdown success. [" << ((unInitEndTime - unInitStartTime) / kMicrosToMillis) << " ms]"; return; } } if (!GePlugin::GetInstance()->IsGlobal()) { GePlugin::GetInstance()->Finalize(); - LOG(INFO) << "[~NPUInit] GePlugin Finalize success"; + ADP_LOG(INFO) << "[~NPUInit] GePlugin Finalize success"; } else { - LOG(INFO) << "[~NPUInit] GePlugin global, skip GePlugin Finalize"; + ADP_LOG(INFO) << "[~NPUInit] GePlugin global, skip GePlugin Finalize"; } int64 unInitEndTime = GetCurrentTimestamp(); - LOG(INFO) << "[~NPUInit] NPU Shutdown success. [" << ((unInitEndTime - unInitStartTime) / kMicrosToMillis) << " ms]"; + ADP_LOG(INFO) << "[~NPUInit] NPU Shutdown success. [" << ((unInitEndTime - unInitStartTime) / kMicrosToMillis) + << " ms]"; } class NPUShutdown : public OpKernel { @@ -131,16 +134,16 @@ class NPUShutdown : public OpKernel { ~NPUShutdown() override = default; }; void NPUShutdown::Compute(OpKernelContext *ctx) { - LOG(INFO) << "[NPUShutdown] NPUShutdown Compute"; + ADP_LOG(INFO) << "[NPUShutdown] NPUShutdown Compute"; { mutex_lock lock{g_mu}; g_npuInitNum = 0; } if (!GePlugin::GetInstance()->IsGlobal()) { GePlugin::GetInstance()->Finalize(); - LOG(INFO) << "[~NPUShutdown] GePlugin Finalize success"; + ADP_LOG(INFO) << "[~NPUShutdown] GePlugin Finalize success"; } else { - LOG(INFO) << "[~NPUShutdown] GePlugin global, skip GePlugin Finalize"; + ADP_LOG(INFO) << "[~NPUShutdown] GePlugin global, skip GePlugin Finalize"; } } diff --git a/tf_adapter/optimizers/add_input_pass.cc b/tf_adapter/optimizers/add_input_pass.cc index 6055ade49f5c469389b6e61bd0749e4d0178bfb4..6d195308cae4b119235df7062a3dcef1179abefe 100644 --- a/tf_adapter/optimizers/add_input_pass.cc +++ b/tf_adapter/optimizers/add_input_pass.cc @@ -39,6 +39,7 @@ limitations under the License. #include "tf_adapter/common/common.h" #include "tf_adapter/util/infershape_util.h" #include "tf_adapter/util/npu_attrs.h" +#include "tf_adapter/common/adp_logger.h" namespace tensorflow { static const int64 kMicrosToMillis = 1000; @@ -73,7 +74,7 @@ Status AddInputPass::Run(const GraphOptimizationPassOptions &options) { for (Node *n : graph->get()->nodes()) { REQUIRES_NOT_NULL(n); if (n->attrs().Find("_NoNeedOptimize")) { - LOG(INFO) << "Found mark of noneed optimize on node [" << n->name() << "], skip AddInputPass."; + ADP_LOG(INFO) << "Found mark of noneed optimize on node [" << n->name() << "], skip AddInputPass."; findMarkNoNeed = true; break; } @@ -93,7 +94,7 @@ Status AddInputPass::Run(const GraphOptimizationPassOptions &options) { std::string job = pass_options["job"]; if (job == "ps" || job == "default" || job == "localhost") { - LOG(INFO) << "job is " << job << " Skip the optimizer : AddInputPass."; + ADP_LOG(INFO) << "job is " << job << " Skip the optimizer : AddInputPass."; continue; } @@ -126,7 +127,7 @@ Status AddInputPass::Run(const GraphOptimizationPassOptions &options) { Status status_o = WriteTextProto(Env::Default(), tmodel_path, omg_graph_def); } int64 endTime = InferShapeUtil::GetCurrentTimestap(); - LOG(INFO) << "AddInputPass subgraph_" << std::to_string(graph_num) << " success. [" + ADP_LOG(INFO) << "AddInputPass subgraph_" << std::to_string(graph_num) << " success. [" << ((endTime - startTime) / kMicrosToMillis) << " ms]"; } diff --git a/tf_adapter/optimizers/control_flow_conversion_pass.cc b/tf_adapter/optimizers/control_flow_conversion_pass.cc index 0104277ea439b0e698913093186f5cdb6e33c0cc..4629381c0552fef4bd4cdf1a87d0215b1d209e73 100644 --- a/tf_adapter/optimizers/control_flow_conversion_pass.cc +++ b/tf_adapter/optimizers/control_flow_conversion_pass.cc @@ -31,6 +31,7 @@ limitations under the License. #include "tensorflow/core/graph/node_builder.h" #include "tensorflow/core/public/session_options.h" #include "tf_adapter/util/npu_attrs.h" +#include "tf_adapter/common/adp_logger.h" namespace tensorflow { namespace { @@ -49,7 +50,7 @@ Status ControlFlowConversionPass::Run(const GraphOptimizationPassOptions &option std::map pass_options = NpuAttrs::GetPassOptions(options); std::string job = pass_options["job"]; if (job == "ps" || job == "default") { - LOG(INFO) << "job is " << job << " Skip the optimizer : ControlFlowConversionPass."; + ADP_LOG(INFO) << "job is " << job << " Skip the optimizer : ControlFlowConversionPass."; return Status::OK(); } @@ -61,7 +62,7 @@ Status ControlFlowConversionPass::Run(const GraphOptimizationPassOptions &option bool use_off_line = pass_options["use_off_line"] == "1"; bool lower_functional_ops = pass_options["lower_functional_ops"] == "1"; if (!use_off_line || lower_functional_ops) { - LOG(INFO) << "Skip the optimizer"; + ADP_LOG(INFO) << "Skip the optimizer"; return Status::OK(); } diff --git a/tf_adapter/optimizers/dp_tf_ge_conversion_pass.cc b/tf_adapter/optimizers/dp_tf_ge_conversion_pass.cc index b28cd32f938abce5991c5fb4f3abe2963f5f7bd0..cc505f83542bc98c51d1dc0fcf3620aa804c966c 100644 --- a/tf_adapter/optimizers/dp_tf_ge_conversion_pass.cc +++ b/tf_adapter/optimizers/dp_tf_ge_conversion_pass.cc @@ -45,6 +45,7 @@ limitations under the License. #include "tf_adapter/common/common.h" #include "tf_adapter/util/infershape_util.h" #include "tf_adapter/util/npu_attrs.h" +#include "tf_adapter/common/adp_logger.h" namespace tensorflow { static const int64 kMicrosToMillis = 1000; @@ -191,14 +192,14 @@ bool DpTfToGEConversionPassImpl::CheckMakeIteratorNode(Node *&n) const { for (const Edge *e : n->in_edges()) { // MakeIterator is contains group_deps if (e == nullptr || e->src() == nullptr) { continue; } if (str_util::StartsWith(e->src()->def().name(), DP_INIT_GRAPH_MARK)) { - LOG(INFO) << "Remove node: " << n->type_string(); + ADP_LOG(INFO) << "Remove node: " << n->type_string(); n = e->src(); if (e->IsControlEdge()) { graph_->RemoveControlEdge(e); } else { graph_->RemoveEdge(e); } - LOG(INFO) << "PruneForReverseReachability node: " << n->type_string(); + ADP_LOG(INFO) << "PruneForReverseReachability node: " << n->type_string(); PruneForReverseReachability(&*graph_, {n}); return true; } @@ -290,19 +291,21 @@ bool DpTfToGEConversionPassImpl::IsDeviceSupportedOp(const NodeDef &n) const { const OpRegistrationData *op_reg_data = nullptr; // Tenorflow original op if (OpRegistry::Global() == nullptr) { + ADP_LOG(ERROR) << "OpRegistry global is nullptr"; LOG(ERROR) << "OpRegistry global is nullptr"; return false; } if (OpRegistry::Global()->LookUp(n.op(), &op_reg_data).ok()) { // Node in GE supported if (!CheckNode(n.op())) { - LOG(INFO) << "Node [" << n.name() << "] op [" << n.op() << "] not supported by GE"; + ADP_LOG(INFO) << "Node [" << n.name() << "] op [" << n.op() << "] not supported by GE"; return false; } else { // Top node supported by GE, check its owned function for (auto &attr : n.attr()) { if (attr.second.has_func()) { if (!IsDeviceSupportedFunc(attr.second.func().name())) { - LOG(INFO) << "Node [" << n.name() << "] function [" << attr.second.func().name() << "] not supported by GE"; + ADP_LOG(INFO) << "Node [" << n.name() << "] function [" << attr.second.func().name() + << "] not supported by GE"; return false; } } @@ -310,7 +313,7 @@ bool DpTfToGEConversionPassImpl::IsDeviceSupportedOp(const NodeDef &n) const { } } else { // Not tenorflow original op, this must be a function node if (!IsDeviceSupportedFunc(n.op())) { - LOG(INFO) << "Node [" << n.name() << "] op [" << n.op() << "] is not a supported function by GE"; + ADP_LOG(INFO) << "Node [" << n.name() << "] op [" << n.op() << "] is not a supported function by GE"; return false; } } @@ -321,13 +324,14 @@ bool DpTfToGEConversionPassImpl::IsDeviceSupportedFunc(const std::string &fn) co const FunctionDef *fdef = flib_def_->Find(fn); // Node contains not found function if (fdef == nullptr) { + ADP_LOG(ERROR) << "Function [" << fn << "] not found"; LOG(ERROR) << "Function [" << fn << "] not found"; return false; } // Recursive check function node for (const NodeDef &node : fdef->node_def()) { if (!IsDeviceSupportedOp(node)) { - LOG(INFO) << "Function [" << fn << "] node [" << node.name() << "] not supported by GE"; + ADP_LOG(INFO) << "Function [" << fn << "] node [" << node.name() << "] not supported by GE"; return false; } } @@ -341,7 +345,7 @@ Status DpTfToGEConversionPassImpl::GetSplitEdges(const Node *n, std::vectorsrc())) { last_edge = e; - LOG(INFO) << strings::StrCat("last edge", GetEdgeName(last_edge)); + ADP_LOG(INFO) << strings::StrCat("last edge", GetEdgeName(last_edge)); } } } @@ -360,13 +364,13 @@ Status DpTfToGEConversionPassImpl::GetSplitEdges(const Node *n, std::vectorsrc(), split_edges, last_edge); if (!s.ok()) { return s; } } else { // GE unsupported node, this is a split edge - LOG(INFO) << strings::StrCat("Split_", GetEdgeName(e)); - LOG(INFO) << "Begin check split edge."; + ADP_LOG(INFO) << strings::StrCat("Split_", GetEdgeName(e)); + ADP_LOG(INFO) << "Begin check split edge."; if (IsSkipDataset(e->dst())) { - LOG(INFO) << "ADD last edge " << GetEdgeName(last_edge); + ADP_LOG(INFO) << "ADD last edge " << GetEdgeName(last_edge); split_edges.push_back(last_edge); } else { - LOG(INFO) << "ADD last edge " << GetEdgeName(e); + ADP_LOG(INFO) << "ADD last edge " << GetEdgeName(e); split_edges.push_back(e); } } @@ -377,7 +381,7 @@ Status DpTfToGEConversionPassImpl::GetSplitEdges(const Node *n, std::vectorsrc()); @@ -385,7 +389,7 @@ Status DpTfToGEConversionPassImpl::InsertChannelQueue(Node *topo_end, std::strin std::string queue_name = strings::StrCat("Queue_", GetEdgeName(e), "_", GetRandomName()); host_queue_name = strings::StrCat("Host", queue_name); device_queue_name = strings::StrCat("Device", queue_name); - LOG(INFO) << "Add_" << host_queue_name; + ADP_LOG(INFO) << "Add_" << host_queue_name; // Host and Device queue should save type and shape auto m_src = e->src()->def().attr(); bool type_status = false; @@ -403,7 +407,7 @@ Status DpTfToGEConversionPassImpl::InsertChannelQueue(Node *topo_end, std::strin .Attr("output_shapes", m_src["output_shapes"]) .Finalize(&*graph_, &queue_node_host)); REQUIRES_NOT_NULL(queue_node_host); - LOG(INFO) << "Add_" << device_queue_name; + ADP_LOG(INFO) << "Add_" << device_queue_name; Node *queue_node_device = nullptr; // Make sure that 'queue_name' of host and device queue be same TF_CHECK_OK(NodeBuilder(device_queue_name, "DeviceQueueDataset") @@ -421,18 +425,18 @@ Status DpTfToGEConversionPassImpl::InsertChannelQueue(Node *topo_end, std::strin Status DpTfToGEConversionPassImpl::RemoveNotSupportDataset(Graph *g, const std::string &device_queue_dataset, const std::string &make_iterator) const { - LOG(INFO) << "Begin RemoveSplitDataset."; + ADP_LOG(INFO) << "Begin RemoveSplitDataset."; // find device_queue_dataset and make_iterator Node *node = nullptr; Node *topo_end = nullptr; for (Node *n : g->op_nodes()) { REQUIRES_NOT_NULL(n); if (n->type_string() == "DeviceQueueDataset" && n->name() == device_queue_dataset) { - LOG(INFO) << "device queue dataset node is " << n->name(); + ADP_LOG(INFO) << "device queue dataset node is " << n->name(); node = n; } if (n->type_string() == "MakeIterator" && n->name() == make_iterator) { - LOG(INFO) << "make iterator node is " << n->name(); + ADP_LOG(INFO) << "make iterator node is " << n->name(); topo_end = n; } } @@ -446,6 +450,7 @@ Status DpTfToGEConversionPassImpl::RemoveNotSupportDataset(Graph *g, const std:: end_dataset = node; } if (node->num_outputs() != 1) { + ADP_LOG(ERROR) << "Invalid node " << node->name() << ", op is" << node->type_string(); LOG(ERROR) << "Invalid node " << node->name() << ", op is" << node->type_string(); return errors::InvalidArgument("RemoveSplitDataset: find invalid node."); } @@ -456,21 +461,21 @@ Status DpTfToGEConversionPassImpl::RemoveNotSupportDataset(Graph *g, const std:: node = edge->dst(); } if (delete_nodes.empty()) { - LOG(INFO) << "all sink datasets are supported."; + ADP_LOG(INFO) << "all sink datasets are supported."; return Status::OK(); } for (Node *n : delete_nodes) { - LOG(INFO) << "ready to remove node " << n->name(); + ADP_LOG(INFO) << "ready to remove node " << n->name(); g->RemoveNode(n); } - LOG(INFO) << "end dataset node is " << end_dataset->name(); + ADP_LOG(INFO) << "end dataset node is " << end_dataset->name(); REQUIRES_NOT_NULL(g->AddEdge(end_dataset, 0, topo_end, 0)); return Status::OK(); } void DpTfToGEConversionPassImpl::RemoveSplitEdges(Node *topo_end) { for (const Edge *e : split_edges_.at(topo_end)) { - LOG(INFO) << "Remove_" << GetEdgeName(e); + ADP_LOG(INFO) << "Remove_" << GetEdgeName(e); graph_->RemoveEdge(e); } } @@ -508,7 +513,7 @@ bool DpTfToGEConversionPassImpl::GetNodeFuncs(const FunctionLibraryDefinition *f bool DpTfToGEConversionPassImpl::RunPass(std::unique_ptr *g, FunctionLibraryDefinition *flib, std::map all_options) { - LOG(INFO) << ">>>> DpTfToGEConversionPassImpl::RunPass <<<<"; + ADP_LOG(INFO) << ">>>> DpTfToGEConversionPassImpl::RunPass <<<<"; // Convert just for convenient access split_edges_.clear(); graph_ = &**g; @@ -521,7 +526,7 @@ bool DpTfToGEConversionPassImpl::RunPass(std::unique_ptr *g, FunctionLibr for (Node *in_node : node->in_nodes()) { if (IsIteratorNode(in_node)) { topo_ends.push_back(node); - LOG(INFO) << "Insert topo end node " << node->name(); + ADP_LOG(INFO) << "Insert topo end node " << node->name(); break; } } @@ -529,11 +534,11 @@ bool DpTfToGEConversionPassImpl::RunPass(std::unique_ptr *g, FunctionLibr } // After traversal, topo_ends should store MakeIterator Nodes. if (topo_ends.empty()) { - LOG(INFO) << "Do not find MakeIterator <- IteratorV2 connects in the graph," + ADP_LOG(INFO) << "Do not find MakeIterator <- IteratorV2 connects in the graph," << " pass datapreprocess pass."; return true; } - LOG(INFO) << "Start to write graph's pbtxt before optimization."; + ADP_LOG(INFO) << "Start to write graph's pbtxt before optimization."; const char *need_print = getenv("PRINT_MODEL"); if (nullptr != need_print && strcmp("1", need_print) == 0) { @@ -544,10 +549,10 @@ bool DpTfToGEConversionPassImpl::RunPass(std::unique_ptr *g, FunctionLibr TF_DO_CHECK_OK(WriteTextProto(Env::Default(), pmodel_path, before_graphdef), ERROR); } - LOG(INFO) << "Start to optimize dp_init topological graph"; + ADP_LOG(INFO) << "Start to optimize dp_init topological graph"; for (Node *topo_end : topo_ends) { // Get all edges that should be replace with HostQueue->DeviceQueue - LOG(INFO) << "Start to find split edges, topo_end node is : " << topo_end->name() << ", op is " + ADP_LOG(INFO) << "Start to find split edges, topo_end node is : " << topo_end->name() << ", op is " << topo_end->type_string(); const Edge *tmp_edge = nullptr; TF_DO_CHECK_OK(GetSplitEdges(topo_end, split_edges_[topo_end], tmp_edge), ERROR); @@ -555,20 +560,21 @@ bool DpTfToGEConversionPassImpl::RunPass(std::unique_ptr *g, FunctionLibr const string DEFAULT_DEVICE = topo_end->def().device(); // Start optimize graph // Insert Host and Device queue - LOG(INFO) << "Start to add host and device queue on split edges"; + ADP_LOG(INFO) << "Start to add host and device queue on split edges"; std::string host_queue_name; std::string device_queue_name; TF_DO_CHECK_OK(InsertChannelQueue(topo_end, host_queue_name, device_queue_name), ERROR); - LOG(INFO) << "host queue name is " << host_queue_name; - LOG(INFO) << "device queue name is " << device_queue_name; + ADP_LOG(INFO) << "host queue name is " << host_queue_name; + ADP_LOG(INFO) << "device queue name is " << device_queue_name; // Remove all split edges - LOG(INFO) << "Start to remove split edges"; + ADP_LOG(INFO) << "Start to remove split edges"; RemoveSplitEdges(topo_end); // Make a copy of graph for pruned GE - LOG(INFO) << "Start to prune GE graph"; + ADP_LOG(INFO) << "Start to prune GE graph"; std::unique_ptr graph_ge(new (std::nothrow) Graph(OpRegistry::Global())); if (graph_ge == nullptr) { + ADP_LOG(ERROR) << "new graph ge failed"; LOG(ERROR) << "new graph ge failed"; return false; } @@ -583,18 +589,19 @@ bool DpTfToGEConversionPassImpl::RunPass(std::unique_ptr *g, FunctionLibr } TF_DO_CHECK_OK(RemoveNotSupportDataset(&*graph_ge, device_queue_name, topo_end->name()), ERROR); - LOG(INFO) << "Start to to PruneForReverseReachability."; + ADP_LOG(INFO) << "Start to to PruneForReverseReachability."; PruneForReverseReachability(&*graph_ge, visiable_ge); // add function_def begin - LOG(INFO) << "Start to add function_def for GEOP's func"; + ADP_LOG(INFO) << "Start to add function_def for GEOP's func"; FunctionDefLibrary fdeflib; for (auto node : graph_ge->nodes()) { std::vector node_funcs; if (GetNodeFuncs(flib, node, node_funcs)) { - LOG(INFO) << "Node [" << node->name() << "] has func:"; + ADP_LOG(INFO) << "Node [" << node->name() << "] has func:"; for (const auto &func : node_funcs) { FunctionDef *fdef = fdeflib.add_function(); if (flib->Find(func) == nullptr) { + ADP_LOG(ERROR) << "function def is nullptr"; LOG(ERROR) << "function def is nullptr"; return false; } @@ -610,17 +617,19 @@ bool DpTfToGEConversionPassImpl::RunPass(std::unique_ptr *g, FunctionLibr std::string iterator_name = ""; for (auto in_node : topo_end->in_nodes()) { if (in_node == nullptr) { + ADP_LOG(ERROR) << "topo end node is nullptr"; LOG(ERROR) << "topo end node is nullptr"; return false; } - LOG(INFO) << "in_node name is " << in_node->name(); + ADP_LOG(INFO) << "in_node name is " << in_node->name(); if (IsIteratorNode(in_node)) { iterator_name = in_node->name(); - LOG(INFO) << "iterator name is " << iterator_name; + ADP_LOG(INFO) << "iterator name is " << iterator_name; break; } } if (iterator_name.empty()) { + ADP_LOG(ERROR) << "There is no connection between MakeIteraotr and IteratorV2"; LOG(ERROR) << "There is no connection between MakeIteraotr and IteratorV2"; return false; } @@ -629,14 +638,14 @@ bool DpTfToGEConversionPassImpl::RunPass(std::unique_ptr *g, FunctionLibr if (node->type_string() == "DeviceQueueDataset") { node->AddAttr(DP_ITERATOR_MARK, iterator_name); } if (std::find(CUSTOMIZE_DATASET_LIST.begin(), CUSTOMIZE_DATASET_LIST.end(), node->type_string()) != CUSTOMIZE_DATASET_LIST.end()) { - LOG(INFO) << node->name() << " is " << node->type_string() << ", need to add label."; + ADP_LOG(INFO) << node->name() << " is " << node->type_string() << ", need to add label."; node->AddAttr("_kernel", "dp"); node->AddAttr(DP_ITERATOR_MARK, iterator_name); } } // Convert GE graph to GEOP function body { - LOG(INFO) << "Start to convert GE graph to geop function"; + ADP_LOG(INFO) << "Start to convert GE graph to geop function"; FunctionDef *fd = fdeflib.add_function(); TF_DO_CHECK_OK(GraphToFunctionDef(*graph_ge, fn_dpop, fd), ERROR); } @@ -646,15 +655,17 @@ bool DpTfToGEConversionPassImpl::RunPass(std::unique_ptr *g, FunctionLibr fdeflib.SerializeToString(&func_def_str); // DPOP node should created by function of geop - LOG(INFO) << "Start to convert dpop node to geop function"; + ADP_LOG(INFO) << "Start to convert dpop node to geop function"; FunctionDef *fd = fdeflib.add_function(); if (fd == nullptr || fd->mutable_signature() == nullptr) { + ADP_LOG(ERROR) << "fd is nullptr"; LOG(ERROR) << "fd is nullptr"; return false; } fd->mutable_signature()->set_name(fn_geop); NodeDef *n = fd->add_node_def(); if (n == nullptr) { + ADP_LOG(ERROR) << "fd node def is nullptr"; LOG(ERROR) << "fd node def is nullptr"; return false; } @@ -673,15 +684,17 @@ bool DpTfToGEConversionPassImpl::RunPass(std::unique_ptr *g, FunctionLibr } { // GEOP node should created by function of geopDataset - LOG(INFO) << "Start to convert geop node to geopdataset function"; + ADP_LOG(INFO) << "Start to convert geop node to geopdataset function"; FunctionDef *fd = fdeflib.add_function(); if (fd == nullptr || fd->mutable_signature() == nullptr) { + ADP_LOG(ERROR) << "fd is nullptr"; LOG(ERROR) << "fd is nullptr"; return false; } fd->mutable_signature()->set_name(fn_geop_dataset); NodeDef *n = fd->add_node_def(); if (n == nullptr) { + ADP_LOG(ERROR) << "fd node def is nullptr"; LOG(ERROR) << "fd node def is nullptr"; return false; } @@ -705,7 +718,7 @@ bool DpTfToGEConversionPassImpl::RunPass(std::unique_ptr *g, FunctionLibr AddNodeAttr("_NpuOptimizer", "NpuOptimizer", n); } // Update graph function libray - LOG(INFO) << "Start to add geop and geopdataset function in graph library"; + ADP_LOG(INFO) << "Start to add geop and geopdataset function in graph library"; // Not a must, just for Tensorbord viewing convenience graph_->AddFunctionLibrary(fdeflib); flib->AddLibrary(fdeflib); @@ -716,12 +729,13 @@ bool DpTfToGEConversionPassImpl::RunPass(std::unique_ptr *g, FunctionLibr Node *geop_dataset_node = nullptr; std::unordered_set isolated_nodes; { - LOG(INFO) << "Start to add geopdataset node in graph"; + ADP_LOG(INFO) << "Start to add geopdataset node in graph"; const Node *n = nullptr; for (const Edge *e : topo_end_input_edges) { if (IsIteratorNode(e->src())) { n = e->src(); } } if (n == nullptr) { + ADP_LOG(ERROR) << "edge src is nullptr"; LOG(ERROR) << "edge src is nullptr"; return false; } @@ -736,7 +750,7 @@ bool DpTfToGEConversionPassImpl::RunPass(std::unique_ptr *g, FunctionLibr if (IsMakeIteratorNode(n)) { n->AddAttr("_kernel", "dp"); } if (n->type_string() == "HostQueueDataset" && n->name() == host_queue_name) { // 0: Host queue always generate one dataset - LOG(INFO) << "inputs add node : name is " << n->name() << ", op is " << n->type_string(); + ADP_LOG(INFO) << "inputs add node : name is " << n->name() << ", op is " << n->type_string(); inputs.push_back(NodeBuilder::NodeOut(n, 0)); } if (n->type_string().compare("DeviceQueueDataset") == 0 && n->name() == device_queue_name) { @@ -765,7 +779,7 @@ bool DpTfToGEConversionPassImpl::RunPass(std::unique_ptr *g, FunctionLibr } } // Remove all edges flow to MakeIterator except the one from IteratorV2 - LOG(INFO) << "Start to combine geopdataset with iterator node and remove " + ADP_LOG(INFO) << "Start to combine geopdataset with iterator node and remove " "orignal edges"; // We must copy all topoend input edges as we can't modify it when combine @@ -773,26 +787,26 @@ bool DpTfToGEConversionPassImpl::RunPass(std::unique_ptr *g, FunctionLibr for (const Edge *e : topo_end_input_edges) { if (!IsIteratorNode(e->src())) { CHECK_NOTNULL(graph_->AddEdge(dpgroup_dataset_node, 0, e->dst(), e->dst_input())); - LOG(INFO) << "Remove_" << GetEdgeName(e); + ADP_LOG(INFO) << "Remove_" << GetEdgeName(e); graph_->RemoveEdge(e); } } // Prune for the final optimized graph - LOG(INFO) << "Start to prune final optimized graph"; + ADP_LOG(INFO) << "Start to prune final optimized graph"; RemoveIsolatedNode(&*graph_, isolated_nodes); - LOG(INFO) << "Start to assign unassigned node on default device"; + ADP_LOG(INFO) << "Start to assign unassigned node on default device"; // We do pass after assign, so we must assign all new added nodes for (Node *n : (*g)->op_nodes()) { if (n->assigned_device_name().empty()) { // Use device of MakeIterator node as default n->set_assigned_device_name(DEFAULT_DEVICE); - LOG(INFO) << "Assigned node [" << n->name() << "] on device [" << n->assigned_device_name() << "]"; + ADP_LOG(INFO) << "Assigned node [" << n->name() << "] on device [" << n->assigned_device_name() << "]"; } } } - LOG(INFO) << "End optimize dp_init topological graph"; + ADP_LOG(INFO) << "End optimize dp_init topological graph"; if (nullptr != need_print && strcmp("1", need_print) == 0) { GraphDef after_graphdef; (*g)->ToGraphDef(&after_graphdef); @@ -880,7 +894,7 @@ Status DpTfToGEConversionPassImpl::ProcessGraph(std::unique_ptr *graph, F for (Node *n : graph->get()->nodes()) { REQUIRES_NOT_NULL(n); if (n->attrs().Find("_NoNeedOptimize")) { - LOG(INFO) << "Found mark of noneed optimize on node [" << n->name() << "], skip DpTfToGEConversionPass."; + ADP_LOG(INFO) << "Found mark of noneed optimize on node [" << n->name() << "], skip DpTfToGEConversionPass."; return Status::OK(); } } @@ -899,7 +913,7 @@ Status DpTfToGEConversionPassImpl::ProcessGraph(std::unique_ptr *graph, F } std::string job = pass_options["job"]; if (job == "ps" || job == "default") { - LOG(INFO) << "job is " << job << " Skip the optimizer : DpTfToGEConversionPass."; + ADP_LOG(INFO) << "job is " << job << " Skip the optimizer : DpTfToGEConversionPass."; return Status::OK(); } if (job == "localhost" && pass_group_value != OptimizationPassRegistry::POST_REWRITE_FOR_EXEC) { @@ -912,7 +926,7 @@ Status DpTfToGEConversionPassImpl::ProcessGraph(std::unique_ptr *graph, F bool do_npu_optimizer = (pass_options["do_npu_optimizer"] == "1"); if (do_npu_optimizer) { if (!use_off_line) { - LOG(INFO) << "Run online process and skip the optimizer"; + ADP_LOG(INFO) << "Run online process and skip the optimizer"; return Status::OK(); } } else { @@ -920,7 +934,7 @@ Status DpTfToGEConversionPassImpl::ProcessGraph(std::unique_ptr *graph, F } if (!enableDP) { - LOG(INFO) << "DpTfToGEConversionPassImpl::RunPass, enable data preproc is false"; + ADP_LOG(INFO) << "DpTfToGEConversionPassImpl::RunPass, enable data preproc is false"; return Status::OK(); } auto process_graph = [&](std::unique_ptr *g, FunctionLibraryDefinition *flib, @@ -929,7 +943,7 @@ Status DpTfToGEConversionPassImpl::ProcessGraph(std::unique_ptr *graph, F // For any pre-partitioning phase, graph is stored in options.graph. process_graph(graph, func_lib, all_options); int64 endTime = InferShapeUtil::GetCurrentTimestap(); - LOG(INFO) << "DpTfToGEConversionPassImpl Run success. [" << ((endTime - startTime) / kMicrosToMillis) << " ms]"; + ADP_LOG(INFO) << "DpTfToGEConversionPassImpl Run success. [" << ((endTime - startTime) / kMicrosToMillis) << " ms]"; return Status::OK(); } diff --git a/tf_adapter/optimizers/get_attr_optimize_pass.cc b/tf_adapter/optimizers/get_attr_optimize_pass.cc index 52d62a45b1b12d724ac85c66b2abd6f48308d2f2..3c3cfe9fd1e977e7ede7985df5f267974e0d6d3f 100644 --- a/tf_adapter/optimizers/get_attr_optimize_pass.cc +++ b/tf_adapter/optimizers/get_attr_optimize_pass.cc @@ -39,6 +39,7 @@ limitations under the License. #include "tf_adapter/common/common.h" #include "tf_adapter/util/infershape_util.h" #include "tf_adapter/util/npu_attrs.h" +#include "tf_adapter/common/adp_logger.h" namespace tensorflow { static const int64 kMicrosToMillis = 1000; @@ -61,21 +62,21 @@ Status GetAttrOptimizePass::Run(const GraphOptimizationPassOptions &options) { std::map pass_options = NpuAttrs::GetPassOptions(options); std::string job = pass_options["job"]; - LOG(INFO) << "NpuAttrs job is " << job; + ADP_LOG(INFO) << "NpuAttrs job is " << job; if (job == "ps" || job == "default") { - LOG(INFO) << "job is " << job << " Skip the optimizer : GetAttrOptimizePass."; + ADP_LOG(INFO) << "job is " << job << " Skip the optimizer : GetAttrOptimizePass."; return Status::OK(); } for (Node *n : options.graph->get()->nodes()) { REQUIRES_NOT_NULL(n); if (n->attrs().Find("_NoNeedOptimize")) { - LOG(INFO) << "Found mark of noneed optimize on node [" << n->name() << "], skip AddSrcOpAttrPass."; + ADP_LOG(INFO) << "Found mark of noneed optimize on node [" << n->name() << "], skip AddSrcOpAttrPass."; return Status::OK(); } if (n->attrs().Find("_NpuOptimizer")) { - LOG(INFO) << "Found mark of get attr optimize on node [" << n->name() << "], skip AddSrcOpAttrPass."; + ADP_LOG(INFO) << "Found mark of get attr optimize on node [" << n->name() << "], skip AddSrcOpAttrPass."; return Status::OK(); } } @@ -97,7 +98,7 @@ Status GetAttrOptimizePass::Run(const GraphOptimizationPassOptions &options) { if (!device_name.empty() && device_name.find("/job:ps") == std::string::npos) { Status s = NpuAttrs::SetNpuOptimizerAttr(options, n); if (s != Status::OK()) { - LOG(INFO) << "set npu optimizer error."; + ADP_LOG(INFO) << "set npu optimizer error."; return s; } break; @@ -125,7 +126,7 @@ Status GetAttrOptimizePass::Run(const GraphOptimizationPassOptions &options) { Status status_o = WriteTextProto(Env::Default(), tmodel_path, omg_graph_def); } int64 endTime = InferShapeUtil::GetCurrentTimestap(); - LOG(INFO) << "GetAttrOptimizePass_" << std::to_string(graph_num) << " success. [" + ADP_LOG(INFO) << "GetAttrOptimizePass_" << std::to_string(graph_num) << " success. [" << ((endTime - startTime) / kMicrosToMillis) << " ms]"; return Status::OK(); diff --git a/tf_adapter/optimizers/gradient_fusion_optimizer.cc b/tf_adapter/optimizers/gradient_fusion_optimizer.cc index 0235497e071eee143e04b7b6c94e2695c1af7743..0686d8f1c82b8b8990281efe5c42ca58ca4c187c 100644 --- a/tf_adapter/optimizers/gradient_fusion_optimizer.cc +++ b/tf_adapter/optimizers/gradient_fusion_optimizer.cc @@ -27,6 +27,7 @@ limitations under the License. #include "tf_adapter/optimizers/gradient_fusion_optimizer.h" #include "tf_adapter/common/common.h" +#include "tf_adapter/common/adp_logger.h" #include "tensorflow/core/grappler/grappler_item.h" #include "tensorflow/core/grappler/utils/topological_sort.h" @@ -89,7 +90,7 @@ Status GradFusionOptimizer::GetInputTensorSize(NodeDef &nodeDef, int64_t &inputT for (int i = 0; i < inputsNameSize; i++) { const string &inputNodeName = nodeDef.input(i); if (inputNodeName.empty()) { - LOG(INFO) << "Cannot get input node name, curr node : " << nodeDef.name() << " index: " << i; + ADP_LOG(INFO) << "Cannot get input node name, curr node : " << nodeDef.name() << " index: " << i; continue; } NodeDef inputNode = nameToNode_[inputNodeName]; @@ -168,7 +169,7 @@ Status GradFusionOptimizer::FusionOp(std::vector fusionHcomOps, GraphDe fusionNode->set_device(fusionHcomOps[0].device()); fusionNode->set_op(opType); - LOG(INFO) << "INFO: GradFusionOptimizer::FusionOp New FusionNodeName: " << fusionNodeName; + ADP_LOG(INFO) << "INFO: GradFusionOptimizer::FusionOp New FusionNodeName: " << fusionNodeName; int fusionOutputIdx = 0; std::set fusionInputs; std::set fusionCtrlInputs; @@ -248,8 +249,8 @@ Status GradFusionOptimizer::Optimize(Cluster *cluster, const GrapplerItem &item, std::map, std::vector> fusionHcomOps; std::map, int64_t> currentGradSumSize; *optimizedGraph = item.graph; - LOG(INFO) << "INFO: GradFusionOptimizer::Optimize begin, OriginNodeNum: " << item.graph.node_size(); - LOG(INFO) << "INFO: FUSION_TENSOR_SIZE: " << fusionTensorSize; + ADP_LOG(INFO) << "INFO: GradFusionOptimizer::Optimize begin, OriginNodeNum: " << item.graph.node_size(); + ADP_LOG(INFO) << "INFO: FUSION_TENSOR_SIZE: " << fusionTensorSize; if (fusionTensorSize < 0) { return errors::InvalidArgument("FUSION_TENSOR_SIZE is invalid"); } @@ -269,7 +270,7 @@ Status GradFusionOptimizer::Optimize(Cluster *cluster, const GrapplerItem &item, if (iter != attrMap.end()) { dType = iter->second.list().type(0); } else { - LOG(INFO) << "INFO: Use default dataType: DT_FLOAT"; + ADP_LOG(INFO) << "INFO: Use default dataType: DT_FLOAT"; dType = DT_FLOAT; } std::pair key = std::make_pair(nodeDef.op(), dType); @@ -300,7 +301,7 @@ Status GradFusionOptimizer::Optimize(Cluster *cluster, const GrapplerItem &item, iter.second.clear(); } } - LOG(INFO) << "INFO: GradFusionOptimizer::Optimize end, finalNodeNum: " << optimizedGraph->node_size(); + ADP_LOG(INFO) << "INFO: GradFusionOptimizer::Optimize end, finalNodeNum: " << optimizedGraph->node_size(); return Status::OK(); } diff --git a/tf_adapter/optimizers/mark_noneed_optimize_pass.cc b/tf_adapter/optimizers/mark_noneed_optimize_pass.cc index 1d028444ab4344acd974b5b3d31628eed212fa88..c6bb4f6d39f27fe1bdce010becafee7094b58afa 100644 --- a/tf_adapter/optimizers/mark_noneed_optimize_pass.cc +++ b/tf_adapter/optimizers/mark_noneed_optimize_pass.cc @@ -28,6 +28,7 @@ limitations under the License. #include "tensorflow/core/common_runtime/optimization_registry.h" #include "tf_adapter/common/common.h" #include "tf_adapter/util/npu_attrs.h" +#include "tf_adapter/common/adp_logger.h" namespace tensorflow { @@ -71,7 +72,7 @@ Status MarkNoNeedOptimizePass::ProcessGraph(std::unique_ptr *graph, Funct for (Node *n : graph->get()->nodes()) { if (n != nullptr && n->attrs().Find("_NoNeedOptimize")) { - LOG(INFO) << "Found mark of noneed optimize on node [" << n->name() << "], skip MarkNoNeedOptimizePass."; + ADP_LOG(INFO) << "Found mark of noneed optimize on node [" << n->name() << "], skip MarkNoNeedOptimizePass."; return Status::OK(); } } @@ -89,7 +90,7 @@ Status MarkNoNeedOptimizePass::ProcessGraph(std::unique_ptr *graph, Funct job = pass_options["job"]; if (job == "ps" || job == "default") { - LOG(INFO) << "job is " << job << " Skip the optimizer : MarkNoNeedOptimizePass."; + ADP_LOG(INFO) << "job is " << job << " Skip the optimizer : MarkNoNeedOptimizePass."; return Status::OK(); } if (job == "localhost" && pass_group_value != OptimizationPassRegistry::POST_REWRITE_FOR_EXEC) { @@ -99,13 +100,13 @@ Status MarkNoNeedOptimizePass::ProcessGraph(std::unique_ptr *graph, Funct bool mix_compile_mode = pass_options["mix_compile_mode"] == "1"; int iterations_per_loop = std::atoi(pass_options["iterations_per_loop"].c_str()); - LOG(INFO) << "mix_compile_mode is " << (mix_compile_mode ? "True" : "False"); - LOG(INFO) << "iterations_per_loop is " << iterations_per_loop; + ADP_LOG(INFO) << "mix_compile_mode is " << (mix_compile_mode ? "True" : "False"); + ADP_LOG(INFO) << "iterations_per_loop is " << iterations_per_loop; for (const auto &func_name : func_lib->ListFunctionNames()) { auto *fdef = const_cast(func_lib->Find(func_name)); if (fdef == nullptr) continue; - LOG(INFO) << "Mark function as no need optimize [" << fdef->signature().name() << "]"; + ADP_LOG(INFO) << "Mark function as no need optimize [" << fdef->signature().name() << "]"; for (NodeDef &ndef : *fdef->mutable_node_def()) { (*ndef.mutable_attr())["_NoNeedOptimize"].set_b(true); } } diff --git a/tf_adapter/optimizers/mark_start_node_pass.cc b/tf_adapter/optimizers/mark_start_node_pass.cc index 9329dba960b051fa2d5dcf911a627e9e67102e89..a2c5bce7e57b35f61003a43542989c276a896835 100644 --- a/tf_adapter/optimizers/mark_start_node_pass.cc +++ b/tf_adapter/optimizers/mark_start_node_pass.cc @@ -40,6 +40,7 @@ limitations under the License. #include "tf_adapter/common/common.h" #include "tf_adapter/util/infershape_util.h" #include "tf_adapter/util/npu_attrs.h" +#include "tf_adapter/common/adp_logger.h" namespace tensorflow { static const int64 kMicrosToMillis = 1000; @@ -79,7 +80,7 @@ Status MarkStartNodePass::Run(const GraphOptimizationPassOptions &options) { std::map pass_options = NpuAttrs::GetPassOptions(options); std::string job = pass_options["job"]; if (job == "ps" || job == "default" || job == "localhost") { - LOG(INFO) << "job is " << job << " Skip the optimizer : MarkStartNodePass."; + ADP_LOG(INFO) << "job is " << job << " Skip the optimizer : MarkStartNodePass."; return Status::OK(); } @@ -88,12 +89,12 @@ Status MarkStartNodePass::Run(const GraphOptimizationPassOptions &options) { for (Node *n : graph->get()->nodes()) { REQUIRES_NOT_NULL(n); if (n->attrs().Find("_NoNeedOptimize")) { - LOG(INFO) << "Found mark of noneed optimize on node [" << n->name() << "], skip MarkStartNodePass."; + ADP_LOG(INFO) << "Found mark of noneed optimize on node [" << n->name() << "], skip MarkStartNodePass."; return Status::OK(); } if (n->attrs().Find("_StartNodeName")) { - LOG(INFO) << "Found mark of startnode optimize on node [" << n->name() << "], skip MarkStartNodePass."; + ADP_LOG(INFO) << "Found mark of startnode optimize on node [" << n->name() << "], skip MarkStartNodePass."; return Status::OK(); } } @@ -152,7 +153,7 @@ Status MarkStartNodePass::Run(const GraphOptimizationPassOptions &options) { Status status_o = WriteTextProto(Env::Default(), tmodel_path, omg_graph_def); } int64 endTime = InferShapeUtil::GetCurrentTimestap(); - LOG(INFO) << "MarkStartNodePass_" << std::to_string(graph_num) << " success. [" + ADP_LOG(INFO) << "MarkStartNodePass_" << std::to_string(graph_num) << " success. [" << ((endTime - startTime) / kMicrosToMillis) << " ms]"; return Status::OK(); @@ -177,7 +178,7 @@ Status MarkStartNodePass::TraverseNode(Node *start_node) { n->AddAttr("_StartNodeName", start_node_name); s = TraverseNode(n); if (s != Status::OK()) { - LOG(INFO) << "traverse node : " << start_node->name() << " to add start node name failed."; + ADP_LOG(INFO) << "traverse node : " << start_node->name() << " to add start node name failed."; return s; } } diff --git a/tf_adapter/optimizers/om_partition_subgraphs_pass.cc b/tf_adapter/optimizers/om_partition_subgraphs_pass.cc index 151f21f9f1463bb88b0974b090acbb2368a3b9df..d609e8924ab687dadfdaa23e3328c1777be3b501 100644 --- a/tf_adapter/optimizers/om_partition_subgraphs_pass.cc +++ b/tf_adapter/optimizers/om_partition_subgraphs_pass.cc @@ -50,6 +50,7 @@ limitations under the License. #include "tf_adapter/util/infershape_util.h" #include "tf_adapter/util/npu_attrs.h" #include "tf_adapter/util/npu_ops_identifier.h" +#include "tf_adapter/common/adp_logger.h" namespace tensorflow { static const int64 kMicrosToMillis = 1000; @@ -225,7 +226,7 @@ bool IsWhiteListSupport(const string &op_name, bool mix_compile_mode, const stri if (!ans) { auto ret = not_support_nodes.insert(op_name); if (ret.second) { - LOG(INFO) << "node: " << op_name << " is not in white list, " + ADP_LOG(INFO) << "node: " << op_name << " is not in white list, " << "so currently not support"; } } @@ -255,7 +256,7 @@ Status SetIteratorShardName(Node *node) { } node->ClearAttr(ATTR_NAME_SHARED_NAME); node->AddAttr(ATTR_NAME_SHARED_NAME, node->name()); - LOG(INFO) << "shardName is " << shardName; + ADP_LOG(INFO) << "shardName is " << shardName; return Status::OK(); } @@ -274,10 +275,12 @@ const int kMaxRecursionDepth = 10; bool IsNpuSupportingFunc(const string &func_name, FunctionLibraryDefinition *func_lib, int depth) { if (func_lib == nullptr) { + ADP_LOG(ERROR) << "func lib is nullptr, function name is " << func_name; LOG(ERROR) << "func lib is nullptr, function name is " << func_name; return false; } if (depth >= kMaxRecursionDepth) { + ADP_LOG(ERROR) << "Rejecting " << func_name << ": function depth limit exceeded."; LOG(ERROR) << "Rejecting " << func_name << ": function depth limit exceeded."; return false; } @@ -287,7 +290,7 @@ bool IsNpuSupportingFunc(const string &func_name, FunctionLibraryDefinition *fun } for (NodeDef node_def : func_def->node_def()) { if (node_def.op() == "Const") { - LOG(INFO) << "Const in func can dump"; + ADP_LOG(INFO) << "Const in func can dump"; } else if (!IsNpuSupportingNode(node_def, compile_mode, func_lib)) { return false; } @@ -346,17 +349,17 @@ Status FindNpuSupportCandidates(const Graph &graph, OrderedNodeSet *candidates, if (hasStopOutfeedDequeueOp || hasOutfeedDequeueOp) { candidates->clear(); - LOG(INFO) << "hostcall subgraph will run on host."; + ADP_LOG(INFO) << "hostcall subgraph will run on host."; return Status::OK(); } std::sort(sortedNodes.begin(), sortedNodes.end(), NodeCompare()); - LOG(INFO) << "FindNpuSupportCandidates enableDP:" << enableDP << ", mix_compile_mode: " << compile_mode + ADP_LOG(INFO) << "FindNpuSupportCandidates enableDP:" << enableDP << ", mix_compile_mode: " << compile_mode << ", hasMakeIteratorOp:" << hasMakeIteratorOp << ", hasIteratorOp:" << hasIteratorOp; if (hasMakeIteratorOp && hasIteratorOp) { candidates->clear(); - LOG(INFO) << "preprocessing subgraph will at dp_tf_ge_conversion_pass."; + ADP_LOG(INFO) << "preprocessing subgraph will at dp_tf_ge_conversion_pass."; return Status::OK(); } @@ -373,14 +376,14 @@ Status FindNpuSupportCandidates(const Graph &graph, OrderedNodeSet *candidates, if (node->type_string() == "IteratorGetNext") { for (Node *n : node->in_nodes()) { REQUIRES_NOT_NULL(n); - LOG(INFO) << node->name() << " has in nodes " << n->name(); + ADP_LOG(INFO) << node->name() << " has in nodes " << n->name(); if (n->type_string() == "Iterator" || n->type_string() == "IteratorV2") { candidates->insert(node); } } } if (node->type_string() == "Iterator" || node->type_string() == "IteratorV2") { for (Node *n : node->out_nodes()) { REQUIRES_NOT_NULL(n); - LOG(INFO) << node->name() << " has in nodes " << n->name(); + ADP_LOG(INFO) << node->name() << " has in nodes " << n->name(); if (n->type_string() == "IteratorGetNext") { candidates->insert(node); } } } @@ -450,8 +453,8 @@ Status FindNpuSupportCandidates(const Graph &graph, OrderedNodeSet *candidates, if (IsRefType(dtypeDst) && candidates->count(edge->dst()) > 0) { candidates->erase(edge->dst()); outSet.insert(edge->dst()); - LOG(INFO) << "Remove node : " << edge->dst()->name() << " from candidates, because of node : " << node->name() - << " REF input."; + ADP_LOG(INFO) << "Remove node : " << edge->dst()->name() << " from candidates, because of node : " + << node->name() << " REF input."; continue; } if (dtypeDst == DT_STRING || dtypeDst == DT_RESOURCE) { @@ -470,8 +473,8 @@ Status FindNpuSupportCandidates(const Graph &graph, OrderedNodeSet *candidates, if (IsRefType(dtypeDst) && candidates->count(edge->src()) > 0) { candidates->erase(edge->src()); outSet.insert(edge->src()); - LOG(INFO) << "Remove node : " << edge->dst()->name() << " from candidates, because of node : " << node->name() - << " REF Output."; + ADP_LOG(INFO) << "Remove node : " << edge->dst()->name() << " from candidates, because of node : " + << node->name() << " REF Output."; continue; } if (dtypeDst == DT_STRING || dtypeDst == DT_RESOURCE) { @@ -481,7 +484,8 @@ Status FindNpuSupportCandidates(const Graph &graph, OrderedNodeSet *candidates, } } int64 endTime = InferShapeUtil::GetCurrentTimestap(); - LOG(INFO) << "TFadapter find Npu support candidates cost: [" << ((endTime - startTime) / kMicrosToMillis) << " ms]"; + ADP_LOG(INFO) << "TFadapter find Npu support candidates cost: [" << ((endTime - startTime) / kMicrosToMillis) + << " ms]"; return Status::OK(); } @@ -594,7 +598,7 @@ Status MergeSubgraphsInNewWay(std::vector> &sortedCluster } } int64 endTime = InferShapeUtil::GetCurrentTimestap(); - LOG(INFO) << "TFadapter merge clusters cost: [" << ((endTime - startTime) / kMicrosToMillis) << " ms]"; + ADP_LOG(INFO) << "TFadapter merge clusters cost: [" << ((endTime - startTime) / kMicrosToMillis) << " ms]"; return Status::OK(); } @@ -638,7 +642,7 @@ Status MergeSubgraphs(std::vector> &sortedCluster, Ordere } } int64 endTime = InferShapeUtil::GetCurrentTimestap(); - LOG(INFO) << "TFadapter merge clusters cost: [" << ((endTime - startTime) / kMicrosToMillis) << " ms]"; + ADP_LOG(INFO) << "TFadapter merge clusters cost: [" << ((endTime - startTime) / kMicrosToMillis) << " ms]"; return Status::OK(); } @@ -694,6 +698,7 @@ Status MarkForPartition(std::unique_ptr *graphIn, int &clusterNum, bool m // Skip NextIteration if (src->IsNextIteration()) { continue; } if (!cycles.InsertEdge(cluster_map[src]->index, cluster_map[dst]->index)) { + ADP_LOG(ERROR) << "Failing due to cycle"; LOG(ERROR) << "Failing due to cycle"; return errors::Unimplemented("Input graph has a cycle (inserting an edge from ", src->DebugString(), " to ", dst->DebugString(), " would create a cycle)"); @@ -730,7 +735,7 @@ Status MarkForPartition(std::unique_ptr *graphIn, int &clusterNum, bool m for (const auto &dst_start_name : cluster_dst->start_nodes_name) { if (src_start_name == dst_start_name) { find_same_start = true; - LOG(INFO) << "node : " << src->name() << " and node : " << dst->name() + ADP_LOG(INFO) << "node : " << src->name() << " and node : " << dst->name() << " has same start node : " << src_start_name; break; } @@ -768,7 +773,7 @@ Status MarkForPartition(std::unique_ptr *graphIn, int &clusterNum, bool m } if (hasSupportNode && hasNonSupportNode) { - LOG(INFO) << "Cluster " << cluster->index << " has both Candidate and non-Candidate nodes"; + ADP_LOG(INFO) << "Cluster " << cluster->index << " has both Candidate and non-Candidate nodes"; return errors::Internal("Cluster ", cluster->index, " has both Candidate and non-Candidate nodes"); } @@ -860,14 +865,14 @@ Status MarkForPartition(std::unique_ptr *graphIn, int &clusterNum, bool m return errors::Internal("Sorted cluster size should be equal to origin subgraph num. ", "Sorted cluster size is ", sortedCluster.size(), ", origin subgraph num is ", clusterNum); } - LOG(INFO) << "cluster Num is " << clusterNum; + ADP_LOG(INFO) << "cluster Num is " << clusterNum; if (clusterNum == 0) { return Status::OK(); } int minGroupSizeTemp = 1; int minGroupSize = (((minGroupSizeTemp > 0) && (minGroupSizeTemp < MAX_GROUP_SIZE)) ? (minGroupSizeTemp) : (1)); // default threshold is 10. - LOG(INFO) << "All nodes in graph: " << graph->num_nodes() << ", max nodes count: " << sortedCluster[0].second + ADP_LOG(INFO) << "All nodes in graph: " << graph->num_nodes() << ", max nodes count: " << sortedCluster[0].second << " in subgraph: " << sortedCluster[0].first << " minGroupSize: " << minGroupSize; bool isDateSetCluster = false; @@ -894,7 +899,7 @@ Status MarkForPartition(std::unique_ptr *graphIn, int &clusterNum, bool m return s; } n->ClearAttr(PARTITION_SUB_GRAPH_ATTR); - LOG(INFO) << "Clear isolated NoOp from " << name; + ADP_LOG(INFO) << "Clear isolated NoOp from " << name; clusterNum -= 1; } } @@ -908,7 +913,7 @@ Status MarkForPartition(std::unique_ptr *graphIn, int &clusterNum, bool m } } } else { - LOG(INFO) << "Clear all node PARTITION_SUB_GRAPH_ATTR attr."; + ADP_LOG(INFO) << "Clear all node PARTITION_SUB_GRAPH_ATTR attr."; for (Node *n : npuSupportCandidates) { n->ClearAttr(PARTITION_SUB_GRAPH_ATTR); } clusterNum = 0; } @@ -1183,6 +1188,7 @@ Node *OMSplitter::Subgraph::MakeNodeImage(const Graph *graphIn, Node *node) { if (graph_ == nullptr) { graph_.reset(new (std::nothrow) Graph(graphIn->op_registry())); if (graph_ == nullptr) { + ADP_LOG(ERROR) << "graph new failed"; LOG(ERROR) << "graph new failed"; return nullptr; } @@ -1200,12 +1206,14 @@ Node *OMSplitter::Subgraph::MakeNodeImage(const Graph *graphIn, Node *node) { } else if (job == "localhost") { device_ = string("/job:localhost/replica:0/task:0/device:CPU:0"); } else { + ADP_LOG(ERROR) << "job type is : " << job << " not support. "; LOG(ERROR) << "job type is : " << job << " not support. "; return nullptr; } } Node *nodeOut = graph_->CopyNode(node); if (nodeOut == nullptr) { + ADP_LOG(ERROR) << "copy node failed"; LOG(ERROR) << "copy node failed"; return nullptr; } @@ -1297,9 +1305,9 @@ Status OMSplitter::Subgraph::BuildFunctionDef(const string &name, FunctionLibrar if (GetNodeFuncs(library, node, nodeFuncs)) { std::unique_ptr func_def_lib(new (std::nothrow) FunctionDefLibrary()); REQUIRES_NOT_NULL(func_def_lib); - LOG(INFO) << "Node [" << node->name() << "] has funcs:"; + ADP_LOG(INFO) << "Node [" << node->name() << "] has funcs:"; for (const auto &func : nodeFuncs) { - LOG(INFO) << func; + ADP_LOG(INFO) << func; FunctionDef *fdef = func_def_lib->add_function(); REQUIRES_NOT_NULL(fdef); REQUIRES_NOT_NULL(library->Find(func)); @@ -1378,7 +1386,7 @@ Status OMSplitter::CopySubgraphNodes(std::unordered_map *n Subgraph &subgraph = subgraphs_[subgraphId]; Status s = subgraph.SetOptions(npu_optimizer_options_, pass_options_); if (s != Status::OK()) { - LOG(INFO) << "Subgraph Id: " << subgraphId << "set npu optimizer error."; + ADP_LOG(INFO) << "Subgraph Id: " << subgraphId << "set npu optimizer error."; return s; } Node *image = subgraph.MakeNodeImage(graphIn_, node); @@ -1481,7 +1489,7 @@ Status OMSplitter::SplitIntoSubgraphs(uint32_t &subgraphNum) { for (string &subgraphName : allSubgraphNames) { Subgraph &subgraph = subgraphs_[subgraphName]; if (subgraph.isIsolatedSubgraph()) { - LOG(INFO) << "IsolatedSubgraph: " << subgraphName; + ADP_LOG(INFO) << "IsolatedSubgraph: " << subgraphName; subgraphs_.erase(subgraphName); for (Node *node : graphIn_->op_nodes()) { string subgraphId; @@ -1492,7 +1500,7 @@ Status OMSplitter::SplitIntoSubgraphs(uint32_t &subgraphNum) { } subgraphNum = subgraphs_.size(); - LOG(INFO) << "subgraphNum: " << subgraphNum; + ADP_LOG(INFO) << "subgraphNum: " << subgraphNum; return Status::OK(); } @@ -1665,7 +1673,7 @@ Status OMPartitionSubgraphsInFunctions(string groupAttribute, std::unique_ptr *graph, Fun for (Node *n : graph->get()->nodes()) { REQUIRES_NOT_NULL(n); if (n->attrs().Find("_NoNeedOptimize")) { - LOG(INFO) << "Found mark of noneed optimize on node [" << n->name() << "], skip OMPartitionSubgraphsPass."; + ADP_LOG(INFO) << "Found mark of noneed optimize on node [" << n->name() << "], skip OMPartitionSubgraphsPass."; return Status::OK(); } } @@ -1737,7 +1745,7 @@ Status OMPartitionSubgraphsPass::ProcessGraph(std::unique_ptr *graph, Fun std::string job = pass_options["job"]; if (job == "ps" || job == "default") { - LOG(INFO) << "job is " << job << " Skip the optimizer : OMPartitionSubgraphsPass."; + ADP_LOG(INFO) << "job is " << job << " Skip the optimizer : OMPartitionSubgraphsPass."; return Status::OK(); } if (job == "localhost" && pass_group_value != OptimizationPassRegistry::POST_REWRITE_FOR_EXEC) { @@ -1749,26 +1757,33 @@ Status OMPartitionSubgraphsPass::ProcessGraph(std::unique_ptr *graph, Fun bool mix_compile_mode = pass_options["mix_compile_mode"] == "1"; int iterations_per_loop = std::atoi(pass_options["iterations_per_loop"].c_str()); int task_index = std::atoi(pass_options["task_index"].c_str()); - if (!iterations_per_loop) { LOG(FATAL) << "iterator_per_loop should be int and must >= 1"; } - if (task_index < 0) { LOG(FATAL) << "task_index should be int and must >= 0"; } + if (!iterations_per_loop) { + ADP_LOG(ERROR) << "iterator_per_loop should be int and must >= 1"; + LOG(FATAL) << "iterator_per_loop should be int and must >= 1"; + } + if (task_index < 0) { + ADP_LOG(ERROR) << "task_index should be int and must >= 0"; + LOG(FATAL) << "task_index should be int and must >= 0"; + } bool do_npu_optimizer = pass_options["do_npu_optimizer"] == "1"; if (do_npu_optimizer) { if (!use_off_line) { - LOG(INFO) << "Run online process and skip the optimizer"; + ADP_LOG(INFO) << "Run online process and skip the optimizer"; return Status::OK(); } } else { return Status::OK(); } - LOG(INFO) << "OMPartition subgraph_" << std::to_string(graph_num) << " begin."; - LOG(INFO) << "mix_compile_mode is " << (mix_compile_mode ? "True" : "False"); - LOG(INFO) << "iterations_per_loop is " << iterations_per_loop; - LOG(INFO) << "input_shape: " << all_options["input_shape"] + ADP_LOG(INFO) << "OMPartition subgraph_" << std::to_string(graph_num) << " begin."; + ADP_LOG(INFO) << "mix_compile_mode is " << (mix_compile_mode ? "True" : "False"); + ADP_LOG(INFO) << "iterations_per_loop is " << iterations_per_loop; + ADP_LOG(INFO) << "input_shape: " << all_options["input_shape"] << "dynamic_dims: " << all_options["dynamic_dims"]; bool is_set_dynamic_config = !all_options["input_shape"].empty() && !all_options["dynamic_dims"].empty(); if (is_set_dynamic_config && mix_compile_mode) { + ADP_LOG(ERROR) << "dynamic config can not use with mix compile."; LOG(FATAL) << "dynamic config can not use with mix compile."; } @@ -1796,10 +1811,10 @@ Status OMPartitionSubgraphsPass::ProcessGraph(std::unique_ptr *graph, Fun } if (node->type_string() == "_UnaryOpsComposition") { - LOG(INFO) << "begin split _UnaryOpsComposition."; + ADP_LOG(INFO) << "begin split _UnaryOpsComposition."; Node *pre_node = nullptr; if (node->in_edges().size() != 1) { - LOG(INFO) << "edge size if not 1, not support in _UnaryOpsComposition."; + ADP_LOG(INFO) << "edge size if not 1, not support in _UnaryOpsComposition."; continue; } pre_node = (*node->in_edges().begin())->src(); @@ -1809,17 +1824,17 @@ Status OMPartitionSubgraphsPass::ProcessGraph(std::unique_ptr *graph, Fun for (int i = 0; i < node_list.s_size(); i++) { const string &node_name = node_list.s(i); string op_name = node->name() + "_" + std::to_string(i) + "_" + node_name; - LOG(INFO) << "op_names node_list: " << i << " is node: " << node_name; + ADP_LOG(INFO) << "op_names node_list: " << i << " is node: " << node_name; TF_CHECK_OK(NodeBuilder(op_name, node_name) .Input(pre_node, 0) .Device(pre_node->def().device()) .Finalize(&*graphIn, &unary_node)); REQUIRES_NOT_NULL(unary_node); - LOG(INFO) << unary_node->type_string() << " has built success."; + ADP_LOG(INFO) << unary_node->type_string() << " has built success."; pre_node = unary_node; } for (auto out_edge : node->out_edges()) { - LOG(INFO) << "begin add edge "; + ADP_LOG(INFO) << "begin add edge "; graphIn->AddEdge(unary_node, 0, out_edge->dst(), out_edge->dst_input()); } graphIn->RemoveNode(node); @@ -1829,12 +1844,15 @@ Status OMPartitionSubgraphsPass::ProcessGraph(std::unique_ptr *graph, Fun } } if (getnext_node_count > 1) { + ADP_LOG(ERROR) << "dynamic dims func can not support graph with " + << getnext_node_count << " IteratorGetNext node."; LOG(FATAL) << "dynamic dims func can not support graph with " << getnext_node_count << " IteratorGetNext node."; } for (Node *node : graphIn->op_nodes()) { if (node->type_string() == "OneShotIterator" && iterations_per_loop != 1) { + ADP_LOG(ERROR) << "iterator_per_loop only support 1 when using OneShotIterator"; LOG(FATAL) << "iterator_per_loop only support 1 when using OneShotIterator"; } @@ -1864,9 +1882,9 @@ Status OMPartitionSubgraphsPass::ProcessGraph(std::unique_ptr *graph, Fun int subgraphNum = 0; TF_RETURN_IF_ERROR( OMSplitter::MarkForPartition(graph, subgraphNum, mix_compile_mode, graph_num, func_lib, pass_options)); - LOG(INFO) << "OMPartition subgraph_" << std::to_string(graph_num) << " markForPartition success."; + ADP_LOG(INFO) << "OMPartition subgraph_" << std::to_string(graph_num) << " markForPartition success."; if (subgraphNum < 1) { - LOG(INFO) << "subgraphNum is " << subgraphNum; + ADP_LOG(INFO) << "subgraphNum is " << subgraphNum; return Status::OK(); } if (mix_compile_mode) { @@ -1943,7 +1961,7 @@ Status OMPartitionSubgraphsPass::ProcessGraph(std::unique_ptr *graph, Fun nodeCopy->ClearAttr(partitionAttr); nodeCopy->AddAttr(partitionAttr, dstSubgraphId); copiedConsts[dstSubgraphId] = nodeCopy; - LOG(INFO) << "Copy const node:" << node->name(); + ADP_LOG(INFO) << "Copy const node:" << node->name(); } Node *nodeCopy = copiedConsts[dstSubgraphId]; graphIn->AddEdge(nodeCopy, edge->src_output(), edge->dst(), edge->dst_input()); @@ -1956,7 +1974,7 @@ Status OMPartitionSubgraphsPass::ProcessGraph(std::unique_ptr *graph, Fun } TF_RETURN_IF_ERROR(OMSplitter::OMPartitionSubgraphsInFunctions( OMSplitter::PARTITION_SUB_GRAPH_ATTR, graph, graph_format_value, func_lib, all_options, pass_options)); - LOG(INFO) << "OMPartition subgraph_" << std::to_string(graph_num) << " SubgraphsInFunctions success."; + ADP_LOG(INFO) << "OMPartition subgraph_" << std::to_string(graph_num) << " SubgraphsInFunctions success."; FixupSourceAndSinkEdges(graph->get()); if (need_print != nullptr && strcmp("1", need_print) == 0) { @@ -1967,7 +1985,7 @@ Status OMPartitionSubgraphsPass::ProcessGraph(std::unique_ptr *graph, Fun Status status_o = WriteTextProto(Env::Default(), tmodel_path, omg_graph_def); } int64 endTime = InferShapeUtil::GetCurrentTimestap(); - LOG(INFO) << "OMPartition subgraph_" << std::to_string(graph_num) << " success. [" + ADP_LOG(INFO) << "OMPartition subgraph_" << std::to_string(graph_num) << " success. [" << ((endTime - startTime) / kMicrosToMillis) << " ms]"; return Status::OK(); } diff --git a/tf_adapter/optimizers/om_set_var_format_pass.cc b/tf_adapter/optimizers/om_set_var_format_pass.cc index a843e86a29407c2c198a0be4a793fd5afe97cbc5..5149e61b23583d81509a427cf047db22615fba14 100644 --- a/tf_adapter/optimizers/om_set_var_format_pass.cc +++ b/tf_adapter/optimizers/om_set_var_format_pass.cc @@ -36,6 +36,7 @@ limitations under the License. #include "tensorflow/core/public/session_options.h" #include "tf_adapter/common/common.h" #include "tf_adapter/util/npu_attrs.h" +#include "tf_adapter/common/adp_logger.h" namespace tensorflow { static const int g_iInputNum = 1; // the second input @@ -141,7 +142,7 @@ Status SetVarFormatPass::Run(const GraphOptimizationPassOptions &options) { std::map pass_options = NpuAttrs::GetPassOptions(options); std::string job = pass_options["job"]; if (job == "ps" || job == "default") { - LOG(INFO) << "job is " << job << " Skip the optimizer : SetVarFormatPass."; + ADP_LOG(INFO) << "job is " << job << " Skip the optimizer : SetVarFormatPass."; return Status::OK(); } diff --git a/tf_adapter/util/ge_plugin.cc b/tf_adapter/util/ge_plugin.cc index c33b8afa1d31489e76bcfe7dc9b95bde6cb166ec..9f4820acc2fa5b2477beb345c09f5c387db44a9b 100644 --- a/tf_adapter/util/ge_plugin.cc +++ b/tf_adapter/util/ge_plugin.cc @@ -33,6 +33,7 @@ limitations under the License. #include "ge/ge_api_types.h" #include "tdt/tdt_host_interface.h" #include "tensorflow/core/util/env_var.h" +#include "tf_adapter/common/adp_logger.h" #include "tf_adapter/common/common.h" #include "tf_adapter/util/npu_attrs.h" #include "tf_adapter/util/npu_plugin.h" @@ -50,13 +51,13 @@ inline string ToString(ge::Status status) { return ::ge::StatusFactory::Instance GePlugin::GePlugin() : device_id_(0), isInit_(false), isGlobal_(false) { - LOG(INFO) << "[GePlugin] new constructor"; + ADP_LOG(INFO) << "[GePlugin] new constructor"; } GePlugin::~GePlugin() { - LOG(INFO) << "[GePlugin] destroy constructor begin"; + ADP_LOG(INFO) << "[GePlugin] destroy constructor begin"; Finalize(); - LOG(INFO) << "[GePlugin] destroy constructor end"; + ADP_LOG(INFO) << "[GePlugin] destroy constructor end"; } GePlugin *GePlugin::GetInstance() { @@ -67,7 +68,7 @@ GePlugin *GePlugin::GetInstance() { void GePlugin::Init(std::map &init_options, bool is_global) { std::lock_guard lock(mutex_); if (isInit_) { - LOG(INFO) << "[GePlugin] Ge has already initialized"; + ADP_LOG(INFO) << "[GePlugin] Ge has already initialized"; return; } init_options_ = init_options; @@ -78,11 +79,12 @@ void GePlugin::Init(std::map &init_options, bool is_gl try { config_info = json::parse(tf_config); } catch (json::exception &e) { + ADP_LOG(WARNING) << "[GePlugin] Failed to convert TF_CONFIG info from string to json ,reason: " << e.what(); LOG(WARNING) << "[GePlugin] Failed to convert TF_CONFIG info from string to json ,reason: " << e.what(); } if (config_info.is_object()) { if (config_info["task"]["type"] == "ps") { - LOG(INFO) << "The ps process does not need to be initialized"; + ADP_LOG(INFO) << "The ps process does not need to be initialized"; return; } if (config_info["task"]["type"] == "evaluator") { @@ -92,17 +94,21 @@ void GePlugin::Init(std::map &init_options, bool is_gl } init_options[OPTION_EXEC_HCCL_FLAG] = std::to_string(exec_hccl_flag); - LOG(INFO) << "[GePlugin] graph run mode : " << init_options[ge::OPTION_GRAPH_RUN_MODE]; + ADP_LOG(INFO) << "[GePlugin] graph run mode : " << init_options[ge::OPTION_GRAPH_RUN_MODE]; Status s = GetEnvDeviceID(device_id_); - if (!s.ok()) { LOG(FATAL) << s.error_message(); } + if (!s.ok()) { + ADP_LOG(ERROR) << s.error_message(); + LOG(FATAL) << s.error_message(); + } init_options[ge::OPTION_EXEC_DEVICE_ID] = std::to_string(device_id_); - LOG(INFO) << "[GePlugin] device id : " << init_options[ge::OPTION_EXEC_DEVICE_ID]; + ADP_LOG(INFO) << "[GePlugin] device id : " << init_options[ge::OPTION_EXEC_DEVICE_ID]; const char *env_job_id = std::getenv("JOB_ID"); if (env_job_id != nullptr) { init_options[ge::OPTION_EXEC_JOB_ID] = env_job_id; } else { + ADP_LOG(WARNING) << "[GePlugin] can not find Environment variable : JOB_ID"; LOG(WARNING) << "[GePlugin] can not find Environment variable : JOB_ID"; } @@ -110,6 +116,7 @@ void GePlugin::Init(std::map &init_options, bool is_gl (void) ReadInt64FromEnvVar("RANK_SIZE", 1, &rankSizeNum); if (rankSizeNum > UINT32_MAX) { rankSizeNum = UINT32_MAX; + ADP_LOG(WARNING) << "[GePlugin] RANK_SIZE is larger than UINT32_MAX, set to UINT32_MAX."; LOG(WARNING) << "[GePlugin] RANK_SIZE is larger than UINT32_MAX, set to UINT32_MAX."; } @@ -117,7 +124,7 @@ void GePlugin::Init(std::map &init_options, bool is_gl bool deploy_mode = false; char *env_rank_table_file = std::getenv("RANK_TABLE_FILE"); if ((env_rank_table_file != nullptr) && (rankSizeNum > 0)) { - LOG(INFO) << "[GePlugin] env RANK_TABLE_FILE:" << env_rank_table_file; + ADP_LOG(INFO) << "[GePlugin] env RANK_TABLE_FILE:" << env_rank_table_file; is_use_hcom = true; init_options[ge::OPTION_EXEC_RANK_TABLE_FILE] = env_rank_table_file; char *env_pod_name = std::getenv("POD_NAME"); @@ -127,10 +134,11 @@ void GePlugin::Init(std::map &init_options, bool is_gl } else { char *env_rank_id = std::getenv("RANK_ID"); if (env_rank_id != nullptr) { - LOG(INFO) << "[GePlugin] env RANK_ID:" << env_rank_id; + ADP_LOG(INFO) << "[GePlugin] env RANK_ID:" << env_rank_id; deploy_mode = false; init_options[ge::OPTION_EXEC_RANK_ID] = env_rank_id; } else { + ADP_LOG(ERROR) << "[GePlugin] Can't find rank_id or pod_name in env."; LOG(ERROR) << "[GePlugin] Can't find rank_id or pod_name in env."; } } @@ -140,47 +148,49 @@ void GePlugin::Init(std::map &init_options, bool is_gl init_options[ge::OPTION_EXEC_DEPLOY_MODE] = std::to_string(deploy_mode); // profiling configuration - LOG(INFO) << "[GePlugin] profiling_mode : " << init_options[ge::OPTION_EXEC_PROFILING_MODE] + ADP_LOG(INFO) << "[GePlugin] profiling_mode : " << init_options[ge::OPTION_EXEC_PROFILING_MODE] << ", profiling_options:" << init_options[ge::OPTION_EXEC_PROFILING_OPTIONS]; // mix precision configuration - LOG(INFO) << "[GePlugin] precision_mode : " << init_options[ge::PRECISION_MODE]; + ADP_LOG(INFO) << "[GePlugin] precision_mode : " << init_options[ge::PRECISION_MODE]; // auto tune configuration if (!init_options["ge.buildMode"].empty() && !init_options["ge.tuningPath"].empty()) { init_options[ge::AUTO_TUNE_MODE] = ""; } - LOG(INFO) << "[GePlugin] auto_tune_mode : " << init_options[ge::AUTO_TUNE_MODE]; + ADP_LOG(INFO) << "[GePlugin] auto_tune_mode : " << init_options[ge::AUTO_TUNE_MODE]; // debug configuration - LOG(INFO) << "[GePlugin] op_debug_level : " << init_options[ge::OP_DEBUG_LEVEL]; + ADP_LOG(INFO) << "[GePlugin] op_debug_level : " << init_options[ge::OP_DEBUG_LEVEL]; // scope fusion configuration - LOG(INFO) << "[GePlugin] enable_scope_fusion_passes : " << init_options[ge::OPTION_EXEC_ENABLE_SCOPE_FUSION_PASSES]; + ADP_LOG(INFO) << "[GePlugin] enable_scope_fusion_passes : " + << init_options[ge::OPTION_EXEC_ENABLE_SCOPE_FUSION_PASSES]; // exception dump configuration - LOG(INFO) << "[GePlugin] enable_exception_dump : " << init_options["ge.exec.enable_exception_dump"]; + ADP_LOG(INFO) << "[GePlugin] enable_exception_dump : " << init_options["ge.exec.enable_exception_dump"]; - LOG(INFO) << "[GePlugin] job_id : " << init_options[ge::OPTION_EXEC_JOB_ID]; + ADP_LOG(INFO) << "[GePlugin] job_id : " << init_options[ge::OPTION_EXEC_JOB_ID]; - LOG(INFO) << "[GePlugin] op_compiler_cache_mode : " << init_options["ge.op_compiler_cache_mode"]; + ADP_LOG(INFO) << "[GePlugin] op_compiler_cache_mode : " << init_options["ge.op_compiler_cache_mode"]; - LOG(INFO) << "[GePlugin] op_compiler_cache_dir : " << init_options["ge.op_compiler_cache_dir"]; + ADP_LOG(INFO) << "[GePlugin] op_compiler_cache_dir : " << init_options["ge.op_compiler_cache_dir"]; - LOG(INFO) << "[GePlugin] debugDir : " << init_options["ge.debugDir"]; + ADP_LOG(INFO) << "[GePlugin] debugDir : " << init_options["ge.debugDir"]; // mstune mode and work path if (!init_options["ge.buildMode"].empty()) { init_options["ge.buildMode"] = "tuning"; } - LOG(INFO) << "[GePlugin] mstune mode : " << init_options["ge.buildMode"] + ADP_LOG(INFO) << "[GePlugin] mstune mode : " << init_options["ge.buildMode"] << ", work path : " << init_options["ge.tuningPath"]; // Open TsdClient first, then call GEInitialize - LOG(INFO) << "[GePlugin] Open TsdClient and Init tdt host."; + ADP_LOG(INFO) << "[GePlugin] Open TsdClient and Init tdt host."; int32_t ret = tdt::TdtHostInit(static_cast(device_id_)); if (ret != 0) { std::this_thread::sleep_for(std::chrono::milliseconds(kFatalSleepTime)); + ADP_LOG(ERROR) << "[GePlugin] Tdt host init failed, tdt error code : " << ret; LOG(FATAL) << "[GePlugin] Tdt host init failed, tdt error code : " << ret; } @@ -188,18 +198,20 @@ void GePlugin::Init(std::map &init_options, bool is_gl ge::Status status = ge::GEInitialize(init_options); if (status != ge::SUCCESS) { std::this_thread::sleep_for(std::chrono::milliseconds(kFatalSleepTime)); + ADP_LOG(ERROR) << "[GePlugin] Initialize ge failed, ret : " << ToString(status); LOG(FATAL) << "[GePlugin] Initialize ge failed, ret : " << ToString(status); } domi::GetContext().train_flag = true; - LOG(INFO) << "[GePlugin] Initialize ge success."; + ADP_LOG(INFO) << "[GePlugin] Initialize ge success."; // parser Initialize ge::Status status_parser = ge::ParserInitialize(init_options); if (status_parser != ge::SUCCESS) { std::this_thread::sleep_for(std::chrono::milliseconds(kFatalSleepTime)); + ADP_LOG(ERROR) << "[GePlugin] Initialize parser failed, ret : " << ToString(status_parser); LOG(FATAL) << "[GePlugin] Initialize parser failed, ret : " << ToString(status_parser); } - LOG(INFO) << "[GePlugin] Initialize parser success."; + ADP_LOG(INFO) << "[GePlugin] Initialize parser success."; isInit_ = true; isGlobal_ = is_global; } @@ -211,19 +223,25 @@ std::map GePlugin::GetInitOptions() { void GePlugin::Finalize() { std::lock_guard lock(mutex_); if (!isInit_) { - LOG(INFO) << "[GePlugin] Ge has already finalized."; + ADP_LOG(INFO) << "[GePlugin] Ge has already finalized."; return; } // ge finalize ge::Status status = ge::GEFinalize(); - if (status != ge::SUCCESS) { LOG(ERROR) << "[GePlugin] GE finalize failed, ret : " << ToString(status); } + if (status != ge::SUCCESS) { + ADP_LOG(ERROR) << "[GePlugin] GE finalize failed, ret : " << ToString(status); + LOG(ERROR) << "[GePlugin] GE finalize failed, ret : " << ToString(status); + } // parser finalize ge::Status status_parser = ge::ParserFinalize(); - if (status_parser != ge::SUCCESS) { LOG(ERROR) << "[GePlugin] Parser finalize failed, ret : " << ToString(status); } + if (status_parser != ge::SUCCESS) { + ADP_LOG(ERROR) << "[GePlugin] Parser finalize failed, ret : " << ToString(status); + LOG(ERROR) << "[GePlugin] Parser finalize failed, ret : " << ToString(status); + } - LOG(INFO) << "[GePlugin] Close TsdClient and destroy tdt."; + ADP_LOG(INFO) << "[GePlugin] Close TsdClient and destroy tdt."; int32_t ret = tdt::TdtHostDestroy(); isInit_ = false; } @@ -235,46 +253,50 @@ bool GePlugin::IsGlobal() { void PluginInit(std::map &init_options) { GePlugin::GetInstance()->Init(init_options, true); - LOG(INFO) << "[GePlugin] npu plugin init success"; + ADP_LOG(INFO) << "[GePlugin] npu plugin init success"; } void PluginFinalize() { GePlugin::GetInstance()->Finalize(); - LOG(INFO) << "[GePlugin] npu plugin finalize success"; + ADP_LOG(INFO) << "[GePlugin] npu plugin finalize success"; } int32_t RdmaInitAndRegister(const std::vector &var_info, size_t size) { ge::Status ret = ge::InitRdmaPool(size); if (ret != ge::SUCCESS) { + ADP_LOG(ERROR) << "[GePlugin] init rdma pool failed, ret : " << ToString(ret); LOG(ERROR) << "[GePlugin] init rdma pool failed, ret : " << ToString(ret); return -1; } - LOG(INFO) << "[GePlugin] init rdma pool success."; + ADP_LOG(INFO) << "[GePlugin] init rdma pool success."; ret = ge::RdmaRemoteRegister(var_info); if (ret != ge::SUCCESS) { + ADP_LOG(ERROR) << "[GePlugin] rdma remote register failed, ret : " << ToString(ret); LOG(ERROR) << "[GePlugin] rdma remote register failed, ret : " << ToString(ret); return -1; } - LOG(INFO) << "[GePlugin] rdma remote register success."; + ADP_LOG(INFO) << "[GePlugin] rdma remote register success."; return 0; } int32_t GetVarAddrAndSize(const string &var_name, uint64_t &base_addr, uint64_t &var_size) { ge::Status ret = ge::GetVarBaseAddrAndSize(var_name, base_addr, var_size); if (ret != ge::SUCCESS) { + ADP_LOG(ERROR) << "[GePlugin] get " << var_name << " base addr and size failed, ret : " << ToString(ret); LOG(ERROR) << "[GePlugin] get " << var_name << " base addr and size failed, ret : " << ToString(ret); return -1; } - LOG(INFO) << "[GePlugin] get " << var_name << " base addr and size success."; + ADP_LOG(INFO) << "[GePlugin] get " << var_name << " base addr and size success."; return 0; } int32_t MallocSharedMem(const ge::TensorInfo &tensor_info, uint64_t &dev_addr, uint64_t &memory_size) { ge::Status ret = ge::MallocSharedMemory(tensor_info, dev_addr, memory_size); if (ret != ge::SUCCESS) { + ADP_LOG(ERROR) << "[GePlugin] malloc shared memory failed, ret : " << ToString(ret); LOG(ERROR) << "[GePlugin] malloc shared memory failed, ret : " << ToString(ret); return -1; } - LOG(INFO) << "[GePlugin] malloc shared memory success."; + ADP_LOG(INFO) << "[GePlugin] malloc shared memory success."; return 0; } \ No newline at end of file diff --git a/tf_adapter/util/generate_report.cc b/tf_adapter/util/generate_report.cc index f1a2cde56d0ae557a2c8f5b36f86ea58b2e9153b..6d398ef6aca46a30cf2a4c786cb8b611691d6b73 100644 --- a/tf_adapter/util/generate_report.cc +++ b/tf_adapter/util/generate_report.cc @@ -31,6 +31,7 @@ limitations under the License. #include #include "nlohmann/json.hpp" #include "tensorflow/core/platform/env.h" +#include "tf_adapter/common/adp_logger.h" namespace tensorflow { using Json = nlohmann::json; @@ -51,9 +52,9 @@ GenerateReport::GenerateReport() { if (getcwd(current_path, PATH_MAX) != nullptr){ string path = current_path; path = path + "/" + kUnsupportedInfoPath; - LOG(INFO) << "[GenerateReport] Remove check report path:" << path; + ADP_LOG(INFO) << "[GenerateReport] Remove check report path:" << path; if (remove(path.c_str()) == 0){ - LOG(INFO) << "[GenerateReport] Succeed remove check report path:" << path; + ADP_LOG(INFO) << "[GenerateReport] Succeed remove check report path:" << path; } } } @@ -92,7 +93,7 @@ Status GenerateReport::DeleteUnSupportedInfo(Node *node) { Status GenerateReport::SaveUnsupportedInfo() { if (check_info_map_.empty()){ - LOG(INFO) << "[GenerateReport] All nodes are supported, no need to save report."; + ADP_LOG(INFO) << "[GenerateReport] All nodes are supported, no need to save report."; return Status::OK(); } Json graph_info; diff --git a/tf_adapter/util/infershape_util.cc b/tf_adapter/util/infershape_util.cc index 090433ad61c125ac40973560e1631950cc5f8f36..761f1a560c681d2e9742568780407a56b4eeddef 100644 --- a/tf_adapter/util/infershape_util.cc +++ b/tf_adapter/util/infershape_util.cc @@ -27,6 +27,7 @@ limitations under the License. #include "tf_adapter/util/infershape_util.h" #include "tensorflow/core/framework/node_def_util.h" +#include "tf_adapter/common/adp_logger.h" #include "tf_adapter/common/common.h" #include "tf_adapter/util/npu_ops_identifier.h" @@ -45,6 +46,7 @@ int64 InferShapeUtil::GetCurrentTimestap() { struct timeval tv; int ret = gettimeofday(&tv, nullptr); if (ret != 0) { + ADP_LOG(ERROR) << "Func gettimeofday may failed, ret:" << ret; LOG(ERROR) << "Func gettimeofday may failed, ret:" << ret; return 0; } @@ -81,7 +83,7 @@ Status InferShapeUtil::setArgShapeFromTensorShape(std::vector vecTensor, Status InferShapeUtil::GetSubGraphFromFunctionDef(const FunctionLibraryDefinition &flib_def, const FunctionDef &func_def, Graph *graph) { - LOG(INFO) << "The signature name of FunctionDef is " << func_def.signature().name() << "."; + ADP_LOG(INFO) << "The signature name of FunctionDef is " << func_def.signature().name() << "."; InstantiationResult result; AttrSlice attrs(&func_def.attr()); TF_RETURN_IF_ERROR(InstantiateFunction( @@ -93,12 +95,12 @@ Status InferShapeUtil::GetSubGraphFromFunctionDef(const FunctionLibraryDefinitio return s; }, &result)); - LOG(INFO) << "InstantiateFunction " << func_def.signature().name() << " success."; + ADP_LOG(INFO) << "InstantiateFunction " << func_def.signature().name() << " success."; GraphConstructorOptions opts; opts.allow_internal_ops = true; opts.expect_device_spec = false; TF_RETURN_IF_ERROR(ConvertNodeDefsToGraph(opts, result.nodes, graph)); - LOG(INFO) << "ConvertNodeDefsToGraph " << func_def.signature().name() << " success."; + ADP_LOG(INFO) << "ConvertNodeDefsToGraph " << func_def.signature().name() << " success."; return Status::OK(); } @@ -124,7 +126,7 @@ bool InferShapeUtil::IsInitializedGraph(Node *node) { if (is_var_init_node->type_string() == "VarIsInitializedOp" || is_var_init_node->type_string() == "IsVariableInitialized") { - LOG(INFO) << "GEOP::IsInitializedGraph"; + ADP_LOG(INFO) << "GEOP::IsInitializedGraph"; return true; } @@ -163,6 +165,8 @@ void InferShapeUtil::setShapeOfEnterOP(ShapeRefiner &shapeRef, Node *pNode) { int iInputNums = pNode->num_inputs(); // Enter has only one input if (iInputNums != 1) { + ADP_LOG(ERROR) << "Node " << pNode->name() << ", type is " << pNode->type_string() + << ", must has only one input, but now=" << iInputNums; LOG(ERROR) << "Node " << pNode->name() << ", type is " << pNode->type_string() << ", must has only one input, but now=" << iInputNums; return; @@ -193,6 +197,8 @@ void InferShapeUtil::setShapeOfMergeOP(ShapeRefiner &shapeRef, Node *pNode) { Node *pNodeIn = e->src(); tensorflow::shape_inference::InferenceContext *pCxtIn = shapeRef.GetContext(pNodeIn); if (pCxtIn == nullptr) { + ADP_LOG(ERROR) << "Can't get context of the input " << pNodeIn->name() << " of the node " << pNode->name() + << "."; LOG(ERROR) << "Can't get context of the input " << pNodeIn->name() << " of the node " << pNode->name() << "."; return; } @@ -228,7 +234,8 @@ void InferShapeUtil::setShapeOfBroadcastGradientArgsOP(ShapeRefiner &shapeRef, N if (pCxt->DebugString(pCxt->output(i)).find('?') != std::string::npos) // the shape of this output has ? { pCxt->ShapeHandleToProto(inputShapes[iMaxDimIndex], &proto); - LOG(INFO) << "Node name " << pNode->name() << " add attr shape " << pCxt->DebugString(inputShapes[iMaxDimIndex]); + ADP_LOG(INFO) << "Node name " << pNode->name() << " add attr shape " + << pCxt->DebugString(inputShapes[iMaxDimIndex]); } else { pCxt->ShapeHandleToProto(pCxt->output(i), &proto); } @@ -251,7 +258,7 @@ void InferShapeUtil::setShapeOfReshapeOP(ShapeRefiner &shapeRef, Node *pNode) { TensorShapeProto proto; pCxt->ShapeHandleToProto(inShapes[0], &proto); pNode->AddAttr(KEY_SHAPE, proto); // Reshape has only one output - LOG(INFO) << "Node name " << pNode->name() << " add attr shape " << pCxt->DebugString(inShapes[0]); + ADP_LOG(INFO) << "Node name " << pNode->name() << " add attr shape " << pCxt->DebugString(inShapes[0]); } } @@ -264,6 +271,7 @@ void InferShapeUtil::inferShapeOfGraph(const Graph *graph, ShapeRefiner &shapeRe Status addStatus = shapeRef.AddNode(pNode); if (!addStatus.ok()) { if (iTime != INFER_SHAPE_FIRST_TIME) { + ADP_LOG(WARNING) << "AddNode failed, errormsg is " << addStatus.error_message() << "."; LOG(WARNING) << "AddNode failed, errormsg is " << addStatus.error_message() << "."; } continue; @@ -286,13 +294,13 @@ void InferShapeUtil::printGraphShape(ShapeRefiner &shapeRef, Graph *graph) { if (pCxt == nullptr) { continue; } iOutNums = pCxt->num_outputs(); if (iOutNums <= 0) { - LOG(INFO) << "Node " << pNode->name() << " has none outputs."; + ADP_LOG(INFO) << "Node " << pNode->name() << " has none outputs."; return; } for (int i = 0; i < iOutNums; i++) { tensorflow::shape_inference::ShapeHandle shape = pCxt->output(i); string strShape = pCxt->DebugString(shape); - LOG(INFO) << "The shape of node " << pNode->name() << " output " << i << " is " << strShape; + ADP_LOG(INFO) << "The shape of node " << pNode->name() << " output " << i << " is " << strShape; } } } @@ -301,6 +309,7 @@ Status InferShapeUtil::addShapeToAttr(ShapeRefiner &shapeRef, Node *pNode) { REQUIRES_NOT_NULL(pNode); shape_inference::InferenceContext *pCxt = shapeRef.GetContext(pNode); if (pCxt == nullptr) { + ADP_LOG(WARNING) << "The InferenceContext of node " << pNode->name() << " is null."; LOG(WARNING) << "The InferenceContext of node " << pNode->name() << " is null."; return Status::OK(); } @@ -310,7 +319,7 @@ Status InferShapeUtil::addShapeToAttr(ShapeRefiner &shapeRef, Node *pNode) { AttrSlice attrList = pNode->attrs(); if (attrList.Find(KEY_SHAPE) != nullptr) { - LOG(INFO) << "Node " << pNode->name() << " already has omop_shape attribute."; + ADP_LOG(INFO) << "Node " << pNode->name() << " already has omop_shape attribute."; return Status::OK(); } @@ -323,6 +332,8 @@ Status InferShapeUtil::addShapeToAttr(ShapeRefiner &shapeRef, Node *pNode) { string strShape = pCxt->DebugString(shape); if (strShape.find('?') != std::string::npos) { + ADP_LOG(WARNING) << "The shape of node " << pNode->name() << " output " << i << " is " << strShape + << ", unknown shape."; LOG(WARNING) << "The shape of node " << pNode->name() << " output " << i << " is " << strShape << ", unknown shape."; @@ -343,7 +354,7 @@ Status InferShapeUtil::InferShape(const std::vector &vecTensor, const Fu (void)flib_def; REQUIRES_NOT_NULL(graph); REQUIRES_NOT_NULL(func_def); - LOG(INFO) << "InferShapeUtil::InferShape"; + ADP_LOG(INFO) << "InferShapeUtil::InferShape"; int iTensorNums = vecTensor.size(); const OpDef &sig = func_def->signature(); int iInputArgNums = sig.input_arg_size(); @@ -366,7 +377,7 @@ Status InferShapeUtil::InferShape(const std::vector &vecTensor, const Fu if (e->IsControlEdge()) continue; if (e->dst_input() < 0) continue; - LOG(INFO) << "in_edges: " << e->src()->name() << " --> " << pNode->name(); + ADP_LOG(INFO) << "in_edges: " << e->src()->name() << " --> " << pNode->name(); if ((e->src()->type_string() == "NextIteration") || (e->src()->type_string() == "RefNextIteration")) { EdgeInfo edgeInfo(e->src(), pNode, e->src_output(), e->dst_input()); NextIterationEdges.push_back(edgeInfo); @@ -392,7 +403,7 @@ Status InferShapeUtil::InferShape(const std::vector &vecTensor, const Fu graph->AddEdge(edgeInfo.src_, edgeInfo.src_output_, edgeInfo.dst_, edgeInfo.dst_input_); } - LOG(INFO) << "InferShapeUtil::InferShape success"; + ADP_LOG(INFO) << "InferShapeUtil::InferShape success"; return Status::OK(); } } // namespace tensorflow diff --git a/tf_adapter/util/npu_attrs.cc b/tf_adapter/util/npu_attrs.cc index f03f7b5b4b6db169044d77527d7dabf0487a4d23..f0ffac24d6da4d05123970ded301fc538cb6010f 100644 --- a/tf_adapter/util/npu_attrs.cc +++ b/tf_adapter/util/npu_attrs.cc @@ -26,6 +26,7 @@ limitations under the License. ==============================================================================*/ #include "tdt/index_transform.h" +#include "tf_adapter/common/adp_logger.h" #include "tf_adapter/util/npu_attrs.h" #include "tensorflow/core/lib/strings/str_util.h" #include "tensorflow/core/util/env_var.h" @@ -43,6 +44,7 @@ Status GetEnvDeviceID(uint32_t &device_id) { const char* tmp_device_id = std::getenv("DEVICE_ID"); string env_device_id(tmp_device_id == nullptr ? "" : tmp_device_id); if (env_ascend_device_id.empty() && env_device_id.empty()) { + ADP_LOG(WARNING) << "[GePlugin] DEVICE_ID and ASCEND_DEVICE_ID is none, use default device id : 0"; LOG(WARNING) << "[GePlugin] DEVICE_ID and ASCEND_DEVICE_ID is none, use default device id : 0"; } else if (!env_ascend_device_id.empty()) { if (!strings::safe_strto64(env_ascend_device_id, &logic_device_id)) { @@ -237,17 +239,26 @@ std::map NpuAttrs::GetSessOptions(OpKernelConstruction if (enable_dump != std::to_string(false)) { if (ctx->GetAttr("_dump_step", &dump_step) == Status::OK() && !dump_step.empty()) { Status s = checkDumpStep(dump_step); - if (!s.ok()) { LOG(FATAL) << s.error_message(); } + if (!s.ok()) { + ADP_LOG(ERROR) << s.error_message(); + LOG(FATAL) << s.error_message(); + } } if (ctx->GetAttr("_dump_mode", &dump_mode) == Status::OK()) { Status s = checkDumpMode(dump_mode); - if (!s.ok()) { LOG(FATAL) << s.error_message(); } + if (!s.ok()) { + ADP_LOG(ERROR) << s.error_message(); + LOG(FATAL) << s.error_message(); + } } } if (enable_dump_debug != std::to_string(false)) { if (ctx->GetAttr("_dump_debug_mode", &dump_debug_mode) == Status::OK()) { Status s = checkDumpDebugMode(dump_debug_mode); - if (!s.ok()) { LOG(FATAL) << s.error_message(); } + if (!s.ok()) { + ADP_LOG(ERROR) << s.error_message(); + LOG(FATAL) << s.error_message(); + } } } ctx->GetAttr("_stream_max_parallel_num", &stream_max_parallel_num); @@ -590,20 +601,29 @@ std::map NpuAttrs::GetAllAttrOptions(AttrSlice attrs) dump_step = attrs.Find("_dump_step")->s(); if (!dump_step.empty()) { Status s = checkDumpStep(dump_step); - if (!s.ok()) { LOG(FATAL) << s.error_message(); } + if (!s.ok()) { + ADP_LOG(ERROR) << s.error_message(); + LOG(FATAL) << s.error_message(); + } } } if (attrs.Find("_dump_mode") != nullptr) { dump_mode = attrs.Find("_dump_mode")->s(); Status s = checkDumpMode(dump_mode); - if (!s.ok()) { LOG(FATAL) << s.error_message(); } + if (!s.ok()) { + ADP_LOG(ERROR) << s.error_message(); + LOG(FATAL) << s.error_message(); + } } } if (enable_dump_debug != std::to_string(false)) { if (attrs.Find("_dump_debug_mode") != nullptr) { dump_debug_mode = attrs.Find("_dump_debug_mode")->s(); Status s = checkDumpDebugMode(dump_debug_mode); - if (!s.ok()) { LOG(FATAL) << s.error_message(); } + if (!s.ok()) { + ADP_LOG(ERROR) << s.error_message(); + LOG(FATAL) << s.error_message(); + } } } if (attrs.Find("_stream_max_parallel_num") != nullptr) { @@ -793,8 +813,12 @@ Status NpuAttrs::SetNpuOptimizerAttr(const GraphOptimizationPassOptions &options if (params.count("dump_path")) { string tmp_path = params.at("dump_path").s(); Status s = CheckPath(tmp_path, dump_path); - if (!s.ok()) { LOG(FATAL) << s.error_message(); } + if (!s.ok()) { + ADP_LOG(ERROR) << s.error_message(); + LOG(FATAL) << s.error_message(); + } } else { + ADP_LOG(ERROR) << "if use dump function, dump_path must be set."; LOG(FATAL) << "if use dump function, dump_path must be set."; } } @@ -802,19 +826,28 @@ Status NpuAttrs::SetNpuOptimizerAttr(const GraphOptimizationPassOptions &options if (params.count("dump_step")) { dump_step = params.at("dump_step").s(); Status s = checkDumpStep(dump_step); - if (!s.ok()) { LOG(FATAL) << s.error_message(); } + if (!s.ok()) { + ADP_LOG(ERROR) << s.error_message(); + LOG(FATAL) << s.error_message(); + } } if (params.count("dump_mode")) { dump_mode = params.at("dump_mode").s(); Status s = checkDumpMode(dump_mode); - if (!s.ok()) { LOG(FATAL) << s.error_message(); } + if (!s.ok()) { + ADP_LOG(ERROR) << s.error_message(); + LOG(FATAL) << s.error_message(); + } } } if (enable_dump_debug) { if (params.count("dump_debug_mode")) { dump_debug_mode = params.at("dump_debug_mode").s(); Status s = checkDumpDebugMode(dump_debug_mode); - if (!s.ok()) { LOG(FATAL) << s.error_message(); } + if (!s.ok()) { + ADP_LOG(ERROR) << s.error_message(); + LOG(FATAL) << s.error_message(); + } } } if (params.count("stream_max_parallel_num")) { @@ -829,13 +862,17 @@ Status NpuAttrs::SetNpuOptimizerAttr(const GraphOptimizationPassOptions &options if (params.count("profiling_options")) { profiling_options = params.at("profiling_options").s(); } else { + ADP_LOG(ERROR) << "profiling_options must be set when use profiling"; LOG(FATAL) << "profiling_options must be set when use profiling"; } } if (params.count("auto_tune_mode")) { auto_tune_mode = params.at("auto_tune_mode").s(); } if (params.count("graph_run_mode")) { graph_run_mode = params.at("graph_run_mode").i(); - if (graph_run_mode > 1) { LOG(FATAL) << "graph_run_mode value must be 0 or 1"; } + if (graph_run_mode > 1) { + ADP_LOG(ERROR) << "graph_run_mode value must be 0 or 1"; + LOG(FATAL) << "graph_run_mode value must be 0 or 1"; + } } if (params.count("op_debug_level")) { op_debug_level = params.at("op_debug_level").i(); } if (params.count("enable_scope_fusion_passes")) { @@ -846,12 +883,19 @@ Status NpuAttrs::SetNpuOptimizerAttr(const GraphOptimizationPassOptions &options if (rank_size > 1 && params.count("mstune_mode")) { mstune_mode = params.at("mstune_mode").s(); Status s = CheckMstuneMode(mstune_mode); - if (!s.ok()) { LOG(FATAL) << s.error_message(); } + if (!s.ok()) { + ADP_LOG(ERROR) << s.error_message(); + LOG(FATAL) << s.error_message(); + } if (params.count("work_path")) { string tmp_path = params.at("work_path").s(); s = CheckPath(tmp_path, work_path); - if (!s.ok()) { LOG(FATAL) << s.error_message(); } + if (!s.ok()) { + ADP_LOG(ERROR) << s.error_message(); + LOG(FATAL) << s.error_message(); + } } else { + ADP_LOG(ERROR) << "work_path must be set when use mstune_mode."; LOG(FATAL) << "work_path must be set when use mstune_mode."; } } @@ -885,42 +929,59 @@ Status NpuAttrs::SetNpuOptimizerAttr(const GraphOptimizationPassOptions &options } else if (params.count("op_select_implmode") && !params.count("optypelist_for_implmode")) { op_select_implmode = params.at("op_select_implmode").s(); Status s = CheckOpImplMode(op_select_implmode); - if (!s.ok()) { LOG(FATAL) << s.error_message(); } + if (!s.ok()) { + ADP_LOG(ERROR) << s.error_message(); + LOG(FATAL) << s.error_message(); + } } else if (params.count("optypelist_for_implmode") && !params.count("op_select_implmode")) { + ADP_LOG(ERROR) << "when use optypelist_for_implmode, op_select_implmode must be set."; LOG(FATAL) << "when use optypelist_for_implmode, op_select_implmode must be set."; } else { op_select_implmode = params.at("op_select_implmode").s(); Status s = CheckOpImplMode(op_select_implmode); - if (!s.ok()) { LOG(FATAL) << s.error_message(); } + if (!s.ok()) { + ADP_LOG(ERROR) << s.error_message(); + LOG(FATAL) << s.error_message(); + } optypelist_for_implmode = params.at("optypelist_for_implmode").s(); } if (params.count("input_shape") && params.count("dynamic_dims") && params.count("dynamic_node_type")) { input_shape = params.at("input_shape").s(); Status s = CheckInputShape(input_shape); - if (!s.ok()) { LOG(FATAL) << s.error_message(); } + if (!s.ok()) { + ADP_LOG(ERROR) << s.error_message(); + LOG(FATAL) << s.error_message(); + } dynamic_dims = params.at("dynamic_dims").s(); s = CheckDynamicDims(dynamic_dims); - if (!s.ok()) { LOG(FATAL) << s.error_message(); } + if (!s.ok()) { + ADP_LOG(ERROR) << s.error_message(); + LOG(FATAL) << s.error_message(); + } dynamic_node_type = params.at("dynamic_node_type").i(); if (dynamic_node_type < 0 || dynamic_node_type > 1) { + ADP_LOG(ERROR) << "dynamic_node_type should be 0 or 1."; LOG(FATAL) << "dynamic_node_type should be 0 or 1."; } } else if (!params.count("input_shape") && !params.count("dynamic_dims") && !params.count("dynamic_node_type")) { // the three parameters are not set normally. } else { + ADP_LOG(ERROR) << "input_shape, dynamic_dims and dynamic_node_type should use together."; LOG(FATAL) << "input_shape, dynamic_dims and dynamic_node_type should use together."; } if (params.count("buffer_optimize")) { buffer_optimize = params.at("buffer_optimize").s(); if (buffer_optimize != "l2_optimize" && buffer_optimize != "off_optimize") { + ADP_LOG(ERROR) << "buffer_optimize is valid, should be one of [l2_optimize, off_optimize]"; LOG(FATAL) << "buffer_optimize is valid, should be one of [l2_optimize, off_optimize]"; } } if (params.count("enable_small_channel")) { enable_small_channel = params.at("enable_small_channel").i(); } if (params.count("fusion_switch_file")) { fusion_switch_file = params.at("fusion_switch_file").s(); } if (params.count("enable_compress_weight") && params.count("compress_weight_conf")) { + ADP_LOG(ERROR) << "enable_compress_weight can not use with compress_weight_conf."; LOG(FATAL) << "enable_compress_weight can not use with compress_weight_conf."; } if (params.count("enable_compress_weight")) { enable_compress_weight = params.at("enable_compress_weight").b(); } diff --git a/tf_adapter/util/npu_ops_identifier.cc b/tf_adapter/util/npu_ops_identifier.cc index 76b3e1f20dd4432822e8081dd4b2b0030028d01e..95c7e1bdcc3a3e53a1b2cfdad647f689bbb20a32 100644 --- a/tf_adapter/util/npu_ops_identifier.cc +++ b/tf_adapter/util/npu_ops_identifier.cc @@ -30,6 +30,7 @@ limitations under the License. #include "nlohmann/json.hpp" #include "tensorflow/core/platform/logging.h" +#include "tf_adapter/common/adp_logger.h" #include "tf_adapter/common/common.h" #include "tf_adapter/util/generate_report.h" using json = nlohmann::json; @@ -61,12 +62,12 @@ NpuOpsIdentifier::NpuOpsIdentifier(bool is_mix, json &ops_info) : is_mix_(is_mix opsPath = path_env; } else { opsPath = "/usr/local/Ascend/opp"; - LOG(INFO) << "environment variable ASCEND_OPP_PATH is not set, use default value[" << opsPath << "]"; + ADP_LOG(INFO) << "environment variable ASCEND_OPP_PATH is not set, use default value[" << opsPath << "]"; } std::string opsJsonPath = opsPath + kOpsInfoJson; - LOG(INFO) << "[" << mode << "] Parsing json from " << opsJsonPath; + ADP_LOG(INFO) << "[" << mode << "] Parsing json from " << opsJsonPath; int32_t opsCnt = NpuOpsIdentifier::ParseOps(opsJsonPath, ops_info_); - LOG(INFO) << opsCnt << " ops parsed"; + ADP_LOG(INFO) << opsCnt << " ops parsed"; VLOG(1) << ops_info_.dump(2); // 1 is vlog level, 2 is ops info index } // Parse and store the ops configuration json file, return num of parsed ops @@ -78,13 +79,13 @@ int32_t NpuOpsIdentifier::ParseOps(const std::string &f, json &root) { jsonConfigFileStream >> root; for (auto i = root.begin(); i != root.end(); ++i) { opsCnt++; } } catch (json::exception &e) { - LOG(INFO) << e.what(); + ADP_LOG(INFO) << e.what(); jsonConfigFileStream.close(); return 0; } jsonConfigFileStream.close(); } else { - LOG(INFO) << "Open " << f << " failed"; + ADP_LOG(INFO) << "Open " << f << " failed"; return 0; } return opsCnt; diff --git a/tf_adapter/util/plugin_load_manager.cc b/tf_adapter/util/plugin_load_manager.cc index a535d48460e214234c6117104aa8c24c43932bff..7d8f1bf8e0857697ea96e107d59e7442f692f22a 100644 --- a/tf_adapter/util/plugin_load_manager.cc +++ b/tf_adapter/util/plugin_load_manager.cc @@ -25,6 +25,7 @@ See the License for the specific language governing permissions and limitations under the License. ==============================================================================*/ +#include "tf_adapter/common/adp_logger.h" #include "tf_adapter/util/plugin_load_manager.h" #include "tensorflow/core/platform/env.h" #include @@ -33,39 +34,49 @@ limitations under the License. namespace tensorflow { void *PluginLoadManager::DlOpen(const std::string &path) { void *handle = dlopen(path.c_str(), RTLD_NOW); - if (handle == nullptr) { LOG(WARNING) << "dlopen failed, reason:" << dlerror(); } + if (handle == nullptr) { + ADP_LOG(WARNING) << "dlopen failed, reason:" << dlerror(); + LOG(WARNING) << "dlopen failed, reason:" << dlerror(); + } return handle; } void *PluginLoadManager::DlSym(void *handle, const std::string &func_name) { if (handle == nullptr) { + ADP_LOG(WARNING) << "handle is null, not valid!"; LOG(WARNING) << "handle is null, not valid!"; return nullptr; } void *func = dlsym(handle, func_name.c_str()); - if (func == nullptr) { LOG(WARNING) << "get func[" << func_name << "] failed, reason:" << dlerror(); } + if (func == nullptr) { + ADP_LOG(WARNING) << "get func[" << func_name << "] failed, reason:" << dlerror(); + LOG(WARNING) << "get func[" << func_name << "] failed, reason:" << dlerror(); + } return func; } std::string PluginLoadManager::GetTFPluginRealPath() { Dl_info dl_info; if (dladdr(reinterpret_cast(&PluginLoadManager::GetTFPluginRealPath), &dl_info) == 0) { + ADP_LOG(WARNING) << "can not get tf-adapter base path!"; LOG(WARNING) << "can not get tf-adapter base path!"; return string(); } else { std::string so_path = dl_info.dli_fname; char path[PATH_MAX] = {0}; if (so_path.length() >= PATH_MAX) { + ADP_LOG(WARNING) << "The shared library file path is too long!"; LOG(WARNING) << "The shared library file path is too long!"; return string(); } if (realpath(so_path.c_str(), path) == nullptr) { + ADP_LOG(WARNING) << "Failed to get realpath of " << so_path; LOG(WARNING) << "Failed to get realpath of " << so_path; return string(); } so_path = path; so_path = so_path.substr(0, so_path.rfind('/') + 1); - LOG(INFO) << "tf-plugin base path is: " << so_path; + ADP_LOG(INFO) << "tf-plugin base path is: " << so_path; return so_path; } } diff --git a/tf_adapter/util/session_manager.cc b/tf_adapter/util/session_manager.cc index e4d306fc0a3964a60848ddc3829657004234e4f8..74f29536da1b008465ca5dc973b4290f594be454 100644 --- a/tf_adapter/util/session_manager.cc +++ b/tf_adapter/util/session_manager.cc @@ -27,6 +27,7 @@ limitations under the License. #include "tf_adapter/util/session_manager.h" #include "tf_adapter/util/npu_attrs.h" +#include "tf_adapter/common/adp_logger.h" using namespace tensorflow; SessionManager &SessionManager::GetInstance() { @@ -39,6 +40,7 @@ bool SessionManager::GetOrCreateGeSession(std::string &tf_session, ge::Session * std::map &sess_options) { // find valid tf session handle if (tf_session.empty()) { + ADP_LOG(ERROR) << "tf session is empty, get ge session failed."; LOG(ERROR) << "tf session is empty, get ge session failed."; return false; } @@ -47,13 +49,14 @@ bool SessionManager::GetOrCreateGeSession(std::string &tf_session, ge::Session * auto it = ge_sessions_.find(tf_session); if (it != ge_sessions_.end()) { ge_session = it->second; - LOG(INFO) << "tf session " << tf_session << " get ge session success."; + ADP_LOG(INFO) << "tf session " << tf_session << " get ge session success."; return true; } PrintGeSessionOptions(sess_options); bool ret = SessionManager::CreateGeSession(tf_session, ge_session, sess_options); if (!ret) { + ADP_LOG(ERROR) << "tf session " << tf_session << " create ge session failed."; LOG(ERROR) << "tf session " << tf_session << " create ge session failed."; return false; } @@ -62,17 +65,20 @@ bool SessionManager::GetOrCreateGeSession(std::string &tf_session, ge::Session * // destroy ge session. void SessionManager::DestroyGeSession(const std::string &tf_session) { - if (tf_session.empty()) { LOG(ERROR) << "tf session is empty, can not destroy ge session."; } + if (tf_session.empty()) { + ADP_LOG(ERROR) << "tf session is empty, can not destroy ge session."; + LOG(ERROR) << "tf session is empty, can not destroy ge session."; + } auto it = ge_sessions_.find(tf_session); if (it != ge_sessions_.end()) { if (it->second != nullptr) { - LOG(INFO) << "find ge session connect with tf session " << tf_session; + ADP_LOG(INFO) << "find ge session connect with tf session " << tf_session; ge_graphs_.erase(it->second); delete it->second; it->second = nullptr; } ge_sessions_.erase(it); - LOG(INFO) << "destroy ge session connect with tf session " << tf_session << " success."; + ADP_LOG(INFO) << "destroy ge session connect with tf session " << tf_session << " success."; } } @@ -80,12 +86,13 @@ void SessionManager::DestroyGeSession(const std::string &tf_session) { bool SessionManager::CreateGeSession(const std::string &tf_session, ge::Session *&ge_session, std::map &sess_options) { // hcom parallel - LOG(INFO) << "[GEOP] hcom_parallel :" << sess_options[ge::HCOM_PARALLEL]; + ADP_LOG(INFO) << "[GEOP] hcom_parallel :" << sess_options[ge::HCOM_PARALLEL]; // stream max parallel num - LOG(INFO) << "[GEOP] stream_max_parallel_num :" << sess_options[ge::STREAM_MAX_PARALLEL_NUM]; + ADP_LOG(INFO) << "[GEOP] stream_max_parallel_num :" << sess_options[ge::STREAM_MAX_PARALLEL_NUM]; ge_session = new (std::nothrow) ge::Session(sess_options); if (ge_session == nullptr) { + ADP_LOG(ERROR) << "tf session " << tf_session << " create ge session failed."; LOG(ERROR) << "tf session " << tf_session << " create ge session failed."; return false; } @@ -98,37 +105,37 @@ bool SessionManager::IsGeSessionExist() { return !ge_sessions_.empty(); } void SessionManager::PrintGeSessionOptions(std::map &sess_options) { // variable acceleration configuration - LOG(INFO) << "[GEOP] variable_acceleration :" << sess_options["ge.exec.variable_acc"]; + ADP_LOG(INFO) << "[GEOP] variable_acceleration :" << sess_options["ge.exec.variable_acc"]; // hcom parallel - LOG(INFO) << "[GEOP] hcom_parallel :" << sess_options[ge::HCOM_PARALLEL]; + ADP_LOG(INFO) << "[GEOP] hcom_parallel :" << sess_options[ge::HCOM_PARALLEL]; // stream max parallel num - LOG(INFO) << "[GEOP] stream_max_parallel_num :" << sess_options[ge::STREAM_MAX_PARALLEL_NUM]; + ADP_LOG(INFO) << "[GEOP] stream_max_parallel_num :" << sess_options[ge::STREAM_MAX_PARALLEL_NUM]; // graph memory configuration if (!sess_options[ge::GRAPH_MEMORY_MAX_SIZE].empty()) { - LOG(INFO) << "[GEOP] set graph_memory_max_size: " << sess_options[ge::GRAPH_MEMORY_MAX_SIZE]; + ADP_LOG(INFO) << "[GEOP] set graph_memory_max_size: " << sess_options[ge::GRAPH_MEMORY_MAX_SIZE]; } else { sess_options.erase(ge::GRAPH_MEMORY_MAX_SIZE); } // variable memory configuration if (!sess_options[ge::VARIABLE_MEMORY_MAX_SIZE].empty()) { - LOG(INFO) << "[GEOP] set variable_memory_max_size: " << sess_options[ge::VARIABLE_MEMORY_MAX_SIZE]; + ADP_LOG(INFO) << "[GEOP] set variable_memory_max_size: " << sess_options[ge::VARIABLE_MEMORY_MAX_SIZE]; } else { sess_options.erase(ge::VARIABLE_MEMORY_MAX_SIZE); } // tailing optimization - LOG(INFO) << "[GEOP] is_tailing_optimization : " << sess_options["ge.exec.isTailingOptimization"]; + ADP_LOG(INFO) << "[GEOP] is_tailing_optimization : " << sess_options["ge.exec.isTailingOptimization"]; - LOG(INFO) << "[GEOP] op_select_implmode : " << sess_options[ge::OP_SELECT_IMPL_MODE]; + ADP_LOG(INFO) << "[GEOP] op_select_implmode : " << sess_options[ge::OP_SELECT_IMPL_MODE]; - LOG(INFO) << "[GEOP] optypelist_for_implmode : " << sess_options[ge::OPTYPELIST_FOR_IMPLMODE]; + ADP_LOG(INFO) << "[GEOP] optypelist_for_implmode : " << sess_options[ge::OPTYPELIST_FOR_IMPLMODE]; // dump configuration string dump_step = sess_options[ge::OPTION_EXEC_DUMP_STEP]; - LOG(INFO) << "[GEOP] enable_dump :" << sess_options[ge::OPTION_EXEC_ENABLE_DUMP] + ADP_LOG(INFO) << "[GEOP] enable_dump :" << sess_options[ge::OPTION_EXEC_ENABLE_DUMP] << ", dump_path :" << sess_options[ge::OPTION_EXEC_DUMP_PATH] << ", dump_step :" << (dump_step.empty() ? "NA" : dump_step) << ", dump_mode :" << sess_options[ge::OPTION_EXEC_DUMP_MODE] @@ -136,23 +143,24 @@ void SessionManager::PrintGeSessionOptions(std::map &s << ", dump_debug_mode :" << sess_options[ge::OPTION_EXEC_DUMP_DEBUG_MODE]; // dynamic input config - LOG(INFO) << "[GEOP] input_shape :" << sess_options["ge.inputShape"] + ADP_LOG(INFO) << "[GEOP] input_shape :" << sess_options["ge.inputShape"] << ", dynamic_dims :" << sess_options["ge.dynamicDims"] << ", dynamic_node_type :" << sess_options["ge.dynamicNodeType"]; - LOG(INFO) << "[GEOP] buffer_optimize :" << sess_options["ge.bufferOptimize"]; + ADP_LOG(INFO) << "[GEOP] buffer_optimize :" << sess_options["ge.bufferOptimize"]; - LOG(INFO) << "[GEOP] enable_small_channel :" << sess_options["ge.enableSmallChannel"]; + ADP_LOG(INFO) << "[GEOP] enable_small_channel :" << sess_options["ge.enableSmallChannel"]; - LOG(INFO) << "[GEOP] fusion_switch_file :" << sess_options["ge.fusionSwitchFile"]; + ADP_LOG(INFO) << "[GEOP] fusion_switch_file :" << sess_options["ge.fusionSwitchFile"]; - LOG(INFO) << "[GEOP] enable_compress_weight :" << sess_options["ge.enableCompressWeight"]; + ADP_LOG(INFO) << "[GEOP] enable_compress_weight :" << sess_options["ge.enableCompressWeight"]; - LOG(INFO) << "[GEOP] compress_weight_conf :" << sess_options["compress_weight_conf"]; + ADP_LOG(INFO) << "[GEOP] compress_weight_conf :" << sess_options["compress_weight_conf"]; } bool SessionManager::CacheGeGraphs(ge::Session *ge_session, ge::Graph &ge_graph) { if (ge_session == nullptr) { + ADP_LOG(ERROR) << "ge session is null ptr."; LOG(ERROR) << "ge session is null ptr."; return false; } @@ -162,15 +170,17 @@ bool SessionManager::CacheGeGraphs(ge::Session *ge_session, ge::Graph &ge_graph) bool SessionManager::GetGeGraphs(ge::Session *ge_session, std::vector &ge_graphs) { if (ge_session == nullptr) { + ADP_LOG(ERROR) << "ge session is null ptr."; LOG(ERROR) << "ge session is null ptr."; return false; } auto it = ge_graphs_.find(ge_session); if (it != ge_graphs_.end()) { ge_graphs = it->second; - LOG(INFO) << " get ge session nontraining graphs success."; + ADP_LOG(INFO) << " get ge session nontraining graphs success."; return true; } + ADP_LOG(ERROR) << "ge session get nontraining graphs failed."; LOG(ERROR) << "ge session get nontraining graphs failed."; return false; } \ No newline at end of file