From 5af2aec3a23350472cb385cb8ade0955378e8468 Mon Sep 17 00:00:00 2001 From: "S. Manohar Karlapalem" Date: Mon, 1 Jul 2019 15:28:20 -0700 Subject: [PATCH] [OpenVINO-EP] use logging infrastructure to display EP log messages (#1289) * Add logging messages Implements logging messages at INFO, WARNING and ERROR levels. Utilizes ONNX-RT's logging infrastrcture. Reversed IsGraphSupported check logic to facilitate logging. * Add MO exception text to WARNING log message --- .../openvino/openvino_execution_provider.cc | 140 +++++++++--------- .../core/providers/openvino/openvino_graph.cc | 16 ++ .../core/providers/openvino/openvino_graph.h | 2 + 3 files changed, 91 insertions(+), 67 deletions(-) diff --git a/onnxruntime/core/providers/openvino/openvino_execution_provider.cc b/onnxruntime/core/providers/openvino/openvino_execution_provider.cc index a4b37d5ea8..f86e5bdaff 100644 --- a/onnxruntime/core/providers/openvino/openvino_execution_provider.cc +++ b/onnxruntime/core/providers/openvino/openvino_execution_provider.cc @@ -14,12 +14,13 @@ #include "core/framework/compute_capability.h" #include "core/framework/tensorprotoutils.h" #include "core/session/onnxruntime_cxx_api.h" +#include "core/util/protobuf_parsing_utils.h" +#include "core/common/logging/logging.h" #include "openvino_execution_provider.h" #include "core/graph/model.h" #include "openvino_graph.h" -#include "core/util/protobuf_parsing_utils.h" namespace onnxruntime { constexpr const char* OpenVINO = "OpenVINO"; @@ -454,74 +455,78 @@ std::vector> OpenVINOExecutionProvider::GetCa std::set fused_inputs, fused_outputs; - if (IsGraphSupported(graph_viewer,device_id)) { - std::string model_proto_strbuf; - model_proto.SerializeToString(&model_proto_strbuf); - - std::string xml_string, weights_string; - - // Try converting with OpenVINO's Model Optimizer - try { - openvino_ep::OpenVINOGraph::ConvertONNXModelToOpenVINOIR(model_proto_strbuf, xml_string, weights_string, precision_fp32); - } catch (const char* msg) { - // Model Optimizer cannot convert this model. - return result; - } - - auto node_indexes = graph_viewer.GetNodesInTopologicalOrder(); - - for (auto index : node_indexes) { - sub_graph->nodes.push_back(index); - const auto node = graph_viewer.GetNode(index); - - // Track graph inputs and initializers - for (auto input_def : node->InputDefs()) { - if (fused_outputs.find(input_def) == fused_outputs.end()) { - fused_inputs.insert(input_def); - } else { - fused_outputs.erase(input_def); - } - } - - // Track graph outputs - for (auto output_def : node->OutputDefs()) { - if (fused_inputs.find(output_def) == fused_inputs.end()) { - fused_outputs.insert(output_def); - } else { - fused_inputs.erase(output_def); - } - } - } - - ONNX_NAMESPACE::AttributeProto xml_str_attr; - xml_str_attr.set_name("xml_str"); - xml_str_attr.set_type(ONNX_NAMESPACE::AttributeProto_AttributeType::AttributeProto_AttributeType_STRING); - xml_str_attr.set_s(xml_string); - - ONNX_NAMESPACE::AttributeProto weights_str_attr; - weights_str_attr.set_name("weights_str"); - weights_str_attr.set_type(ONNX_NAMESPACE::AttributeProto_AttributeType::AttributeProto_AttributeType_STRING); - weights_str_attr.set_s(weights_string); - - auto meta_def = std::make_unique<::onnxruntime::IndexedSubGraph::MetaDef>(); - meta_def->attributes["xml_str"] = xml_str_attr; - meta_def->attributes["weights_str"] = weights_str_attr; - meta_def->name = "OpenVINOKernel_" + std::to_string(counter++); - meta_def->domain = "OpenVINO"; - meta_def->since_version = 1; - - for (auto input : fused_inputs) { - meta_def->inputs.push_back(input->Name()); - } - - for (auto output : fused_outputs) { - meta_def->outputs.push_back(output->Name()); - } - - sub_graph->SetMetaDef(meta_def); - result.push_back(std::make_unique(std::move(sub_graph))); + if (!IsGraphSupported(graph_viewer,device_id)) { + LOGS_DEFAULT(WARNING) << openvino_ep::OpenVINOGraph::log_tag << "Rejecting as graph has unsupported operations."; + return result; } + std::string model_proto_strbuf; + model_proto.SerializeToString(&model_proto_strbuf); + + std::string xml_string, weights_string; + + // Try converting with OpenVINO's Model Optimizer + try { + openvino_ep::OpenVINOGraph::ConvertONNXModelToOpenVINOIR(model_proto_strbuf, xml_string, weights_string, precision_fp32); + } catch (const char* msg) { + // Model Optimizer cannot convert this model. + LOGS_DEFAULT(WARNING) << openvino_ep::OpenVINOGraph::log_tag << "Rejecting as Model Optimizer cannot convert this model." << msg; + return result; + } + + auto node_indexes = graph_viewer.GetNodesInTopologicalOrder(); + + for (auto index : node_indexes) { + sub_graph->nodes.push_back(index); + const auto node = graph_viewer.GetNode(index); + + // Track graph inputs and initializers + for (auto input_def : node->InputDefs()) { + if (fused_outputs.find(input_def) == fused_outputs.end()) { + fused_inputs.insert(input_def); + } else { + fused_outputs.erase(input_def); + } + } + + // Track graph outputs + for (auto output_def : node->OutputDefs()) { + if (fused_inputs.find(output_def) == fused_inputs.end()) { + fused_outputs.insert(output_def); + } else { + fused_inputs.erase(output_def); + } + } + } + + ONNX_NAMESPACE::AttributeProto xml_str_attr; + xml_str_attr.set_name("xml_str"); + xml_str_attr.set_type(ONNX_NAMESPACE::AttributeProto_AttributeType::AttributeProto_AttributeType_STRING); + xml_str_attr.set_s(xml_string); + + ONNX_NAMESPACE::AttributeProto weights_str_attr; + weights_str_attr.set_name("weights_str"); + weights_str_attr.set_type(ONNX_NAMESPACE::AttributeProto_AttributeType::AttributeProto_AttributeType_STRING); + weights_str_attr.set_s(weights_string); + + auto meta_def = std::make_unique<::onnxruntime::IndexedSubGraph::MetaDef>(); + meta_def->attributes["xml_str"] = xml_str_attr; + meta_def->attributes["weights_str"] = weights_str_attr; + meta_def->name = "OpenVINOKernel_" + std::to_string(counter++); + meta_def->domain = "OpenVINO"; + meta_def->since_version = 1; + + for (auto input : fused_inputs) { + meta_def->inputs.push_back(input->Name()); + } + + for (auto output : fused_outputs) { + meta_def->outputs.push_back(output->Name()); + } + + sub_graph->SetMetaDef(meta_def); + result.push_back(std::make_unique(std::move(sub_graph))); + return result; } @@ -534,6 +539,7 @@ common::Status OpenVINOExecutionProvider::Compile( openvino_graph = std::make_shared(fused_node); } catch (const char* msg) { + LOGS_DEFAULT(ERROR) << openvino_ep::OpenVINOGraph::log_tag << "Compilation error: " << msg; return Status(common::StatusCategory::ONNXRUNTIME, common::StatusCode::NOT_IMPLEMENTED, msg); } diff --git a/onnxruntime/core/providers/openvino/openvino_graph.cc b/onnxruntime/core/providers/openvino/openvino_graph.cc index f8bdea49bb..a8dfa066e1 100644 --- a/onnxruntime/core/providers/openvino/openvino_graph.cc +++ b/onnxruntime/core/providers/openvino/openvino_graph.cc @@ -16,12 +16,16 @@ #include "core/graph/graph.h" #include "core/framework/tensorprotoutils.h" #include "core/session/onnxruntime_cxx_api.h" +#include "core/common/logging/logging.h" #include "openvino_graph.h" namespace onnxruntime{ namespace openvino_ep { + +const std::string OpenVINOGraph::log_tag = "[OpenVINO-EP] "; + OpenVINOGraph::OpenVINOGraph(const onnxruntime::Node* fused_node) { device_id_ = "CPU"; @@ -227,6 +231,8 @@ std::vector OpenVINOGraph::GetExecutableHand plugin_path) .getPluginByDevice(device); + LOGS_DEFAULT(INFO) << log_tag << "Loaded plugins"; + // Configure input & output // Prepare input blobs @@ -301,11 +307,15 @@ std::vector OpenVINOGraph::GetExecutableHand InferenceEngine::ExecutableNetwork exeNetwork = plugin.LoadNetwork(*network, {}); + LOGS_DEFAULT(INFO) << log_tag << "Network loaded into accelerator plug-in succesfully"; + // Create infer request std::vector infer_requests; for (size_t i = 0; i < num_inf_reqs_; i++) { infer_requests.push_back(exeNetwork.CreateInferRequestPtr()); } + LOGS_DEFAULT(INFO) << log_tag << "Infer requests created: " << num_inf_reqs_; + return infer_requests; } @@ -321,6 +331,8 @@ size_t OpenVINOGraph::DeduceBatchSize(Ort::CustomOpApi ort, const OrtValue* inpu batch_size = input_shape[0]; } + LOGS_DEFAULT(INFO) << log_tag << "Deduced batch size: " << batch_size; + return batch_size; } @@ -424,6 +436,8 @@ void OpenVINOGraph::Infer(Ort::CustomOpApi ort, OrtKernelContext* context) { // Currently allows only one Infer execution at a time std::lock_guard lock(compute_lock_); + LOGS_DEFAULT(INFO) << log_tag << "Starting inference"; + // Get Input and Output tensors size_t input_count = openvino_network_->getInputsInfo().size(); size_t output_count = openvino_network_->getOutputsInfo().size(); @@ -465,6 +479,8 @@ void OpenVINOGraph::Infer(Ort::CustomOpApi ort, OrtKernelContext* context) { size_t batch_slice_idx = full_parallel_runs * num_inf_reqs_ + inf_req_idx; CompleteAsyncInference(ort, output_tensors, batch_slice_idx, inf_req_idx); } + + LOGS_DEFAULT(INFO) << log_tag << "Inference successful"; } } // namespace openvino_ep diff --git a/onnxruntime/core/providers/openvino/openvino_graph.h b/onnxruntime/core/providers/openvino/openvino_graph.h index c01ddfa146..2f53b62fed 100644 --- a/onnxruntime/core/providers/openvino/openvino_graph.h +++ b/onnxruntime/core/providers/openvino/openvino_graph.h @@ -27,6 +27,8 @@ class OpenVINOGraph { static void ConvertONNXModelToOpenVINOIR(const std::string& onnx_model, std::string& openvino_xml, std::string& openvino_bin, bool precision_fp32); + static const std::string log_tag; + private: std::shared_ptr BuildOpenVINONetworkWithMO();