From 4c93c4c3bcd3102c6c2a85a7acc165197c7a9dec Mon Sep 17 00:00:00 2001 From: Leo Chen Date: Mon, 1 Nov 2021 19:54:15 +0800 Subject: [PATCH] [new-exec] refine vlog of interpretercore (#36865) * refine vlog of interpretercore * fix ut --- .../framework/new_executor/interpretercore.cc | 31 ++++++++++++++----- .../new_executor/interpretercore_util.cc | 4 +-- paddle/fluid/framework/operator.cc | 14 ++++----- paddle/fluid/framework/operator.h | 2 +- .../memory/allocation/allocator_facade.cc | 2 +- paddle/fluid/platform/device_context.cc | 2 +- .../pybind/global_value_getter_setter.cc | 1 + .../interpreter/test_standalone_executor.py | 2 +- 8 files changed, 38 insertions(+), 20 deletions(-) diff --git a/paddle/fluid/framework/new_executor/interpretercore.cc b/paddle/fluid/framework/new_executor/interpretercore.cc index 8367607adb..3ea8b8d309 100644 --- a/paddle/fluid/framework/new_executor/interpretercore.cc +++ b/paddle/fluid/framework/new_executor/interpretercore.cc @@ -13,18 +13,18 @@ // limitations under the License. #include "paddle/fluid/framework/new_executor/interpretercore.h" -#include "paddle/fluid/framework/new_executor/interpretercore_util.h" - #include - #include "paddle/fluid/framework/details/nan_inf_utils.h" #include "paddle/fluid/framework/details/share_tensor_buffer_functor.h" +#include "paddle/fluid/framework/new_executor/interpretercore_util.h" +#include "paddle/fluid/framework/operator.h" #include "paddle/fluid/platform/profiler.h" PADDLE_DEFINE_EXPORTED_bool(new_executor_use_inplace, true, "Use inplace in new executor"); DECLARE_bool(check_nan_inf); +DECLARE_bool(benchmark); constexpr const char* kExceptionCaught = "ExceptionCaught"; @@ -311,7 +311,9 @@ void InterpreterCore::BuildSkipShareLoDInfo() { } void InterpreterCore::RunInstruction(const Instruction& instr_node) { - VLOG(3) << "RunInstruction: " << instr_node.OpBase()->Type(); + auto* op = instr_node.OpBase(); + auto place = instr_node.DeviceContext().GetPlace(); + VLOG(4) << place << " " << op->DebugStringEx(global_scope_); { platform::RecordEvent infershape_event("InferShape"); @@ -334,12 +336,27 @@ void InterpreterCore::RunInstruction(const Instruction& instr_node) { instr_node.KernelFunc()(*instr_node.InnerExecutionContext().get()); } + VLOG(3) << place << " " << op->DebugStringEx(global_scope_); + + /*For profiling/benchmark only*/ + if (FLAGS_benchmark) { + instr_node.DeviceContext().Wait(); +#if defined(PADDLE_WITH_CUDA) + PADDLE_ENFORCE_CUDA_SUCCESS(cudaGetLastError()); + VLOG(4) << "Operator(" << op->Type() + << "): context wait and get last error"; +#endif +#if defined(PADDLE_WITH_HIP) + PADDLE_ENFORCE_CUDA_SUCCESS(hipGetLastError()); + VLOG(4) << "Operator(" << op->Type() + << "): context wait and get last error"; +#endif + } + // for debug nan/inf if (FLAGS_check_nan_inf) { VLOG(4) << "Check nan/inf"; - framework::details::CheckOpHasNanOrInf( - *instr_node.OpBase(), *global_scope_, - instr_node.DeviceContext().GetPlace()); + framework::details::CheckOpHasNanOrInf(*op, *global_scope_, place); } } diff --git a/paddle/fluid/framework/new_executor/interpretercore_util.cc b/paddle/fluid/framework/new_executor/interpretercore_util.cc index 32e26f795a..a4443b0884 100644 --- a/paddle/fluid/framework/new_executor/interpretercore_util.cc +++ b/paddle/fluid/framework/new_executor/interpretercore_util.cc @@ -229,7 +229,7 @@ void build_op_func_list(const platform::Place& place, size_t ops_index = 0; for (auto& op : global_block.AllOps()) { - VLOG(3) << "Build OpFuncNode from : " << op->Type(); + VLOG(6) << "Build OpFuncNode from : " << op->Type(); auto op_base = ops[ops_index++]; auto inputs_names = op->Inputs(); @@ -435,7 +435,7 @@ void build_op_func_list(const platform::Place& place, continue; } - VLOG(2) << "Erase variable " << var_name; + VLOG(6) << "Erase variable " << var_name; if (var->IsType()) { garbages->emplace_back( var->GetMutable()->MoveMemoryHolder()); diff --git a/paddle/fluid/framework/operator.cc b/paddle/fluid/framework/operator.cc index 33763672e7..d317aac859 100644 --- a/paddle/fluid/framework/operator.cc +++ b/paddle/fluid/framework/operator.cc @@ -62,7 +62,7 @@ std::vector> kKernelPriority = { std::make_tuple(platform::CPUPlace(), LibraryType::kPlain), }; -static DDim GetDimsDebug(const Scope& scope, const std::string& name, +static DDim GetDimsDebug(const ScopeBase& scope, const std::string& name, bool get_actual_dim = false) { Variable* var = scope.FindVar(name); if (var == nullptr) { @@ -85,13 +85,13 @@ static DDim GetDimsDebug(const Scope& scope, const std::string& name, } } -static bool VarInited(const Scope& scope, const std::string& name) { +static bool VarInited(const ScopeBase& scope, const std::string& name) { Variable* var = scope.FindVar(name); if (var == nullptr) return false; return var->IsInitialized(); } -static std::string GetDtype(const Scope& scope, const std::string& name) { +static std::string GetDtype(const ScopeBase& scope, const std::string& name) { Variable* var = scope.FindVar(name); if (var == nullptr) { return ""; @@ -117,7 +117,7 @@ static std::string GetDtype(const Scope& scope, const std::string& name) { } } -static std::string GetPlace(const Scope& scope, const std::string& name) { +static std::string GetPlace(const ScopeBase& scope, const std::string& name) { Variable* var = scope.FindVar(name); if (var == nullptr) { return ""; @@ -146,7 +146,7 @@ static std::string GetPlace(const Scope& scope, const std::string& name) { } } -static int GetRowSize(const Scope& scope, const std::string& name) { +static int GetRowSize(const ScopeBase& scope, const std::string& name) { Variable* var = scope.FindVar(name); if (var == nullptr) { return -1; @@ -159,7 +159,7 @@ static int GetRowSize(const Scope& scope, const std::string& name) { return -1; } -static LoD GetLoDDebug(const Scope& scope, const std::string& name) { +static LoD GetLoDDebug(const ScopeBase& scope, const std::string& name) { Variable* var = scope.FindVar(name); auto default_lod = LoD({{}}); @@ -308,7 +308,7 @@ const std::vector& OperatorBase::Outputs( return it->second; } -std::string OperatorBase::DebugStringEx(const Scope* scope) const { +std::string OperatorBase::DebugStringEx(const ScopeBase* scope) const { std::stringstream ss; ss << "Op(" << type_ << "), inputs:{"; diff --git a/paddle/fluid/framework/operator.h b/paddle/fluid/framework/operator.h index 170dd910b2..575ce8956d 100644 --- a/paddle/fluid/framework/operator.h +++ b/paddle/fluid/framework/operator.h @@ -154,7 +154,7 @@ class OperatorBase { virtual void Stop() {} /// if scope is not null, also show dimensions of arguments - virtual std::string DebugStringEx(const Scope* scope) const; + virtual std::string DebugStringEx(const ScopeBase* scope) const; std::string DebugString() const { return DebugStringEx(nullptr); } virtual bool SupportGPU() const { return false; } diff --git a/paddle/fluid/memory/allocation/allocator_facade.cc b/paddle/fluid/memory/allocation/allocator_facade.cc index 281902f3a2..93c9887913 100644 --- a/paddle/fluid/memory/allocation/allocator_facade.cc +++ b/paddle/fluid/memory/allocation/allocator_facade.cc @@ -202,7 +202,7 @@ class AllocatorFacadePrivate { inline const std::shared_ptr& GetAllocator( const platform::Place& place, size_t size) { - VLOG(4) << "GetAllocator" + VLOG(6) << "GetAllocator" << " " << place << " " << size; const auto& allocators = (size > 0 ? (UNLIKELY(FLAGS_use_system_allocator) ? system_allocators_ diff --git a/paddle/fluid/platform/device_context.cc b/paddle/fluid/platform/device_context.cc index 587ad5f37e..d934918d01 100644 --- a/paddle/fluid/platform/device_context.cc +++ b/paddle/fluid/platform/device_context.cc @@ -91,7 +91,7 @@ DeviceType Place2DeviceType(const platform::Place& place) { DeviceContextPool* DeviceContextPool::pool = nullptr; platform::DeviceContext* DeviceContextPool::Get(const platform::Place& place) { - VLOG(4) << "DeviceContextPool Get: " << place; + VLOG(6) << "DeviceContextPool Get: " << place; auto it = device_contexts_.find(place); if (it == device_contexts_.end()) { PADDLE_THROW(platform::errors::Unimplemented( diff --git a/paddle/fluid/pybind/global_value_getter_setter.cc b/paddle/fluid/pybind/global_value_getter_setter.cc index e7f1bef4be..276c528f2a 100644 --- a/paddle/fluid/pybind/global_value_getter_setter.cc +++ b/paddle/fluid/pybind/global_value_getter_setter.cc @@ -145,6 +145,7 @@ class PYBIND11_HIDDEN GlobalVarGetterSetterRegistry { } void Set(const std::string &name, const py::object &value) const { + VLOG(4) << "set " << name << " to " << value; SetterMethod(name)(value); } diff --git a/python/paddle/fluid/tests/unittests/interpreter/test_standalone_executor.py b/python/paddle/fluid/tests/unittests/interpreter/test_standalone_executor.py index 60028bf302..03062ab8e2 100644 --- a/python/paddle/fluid/tests/unittests/interpreter/test_standalone_executor.py +++ b/python/paddle/fluid/tests/unittests/interpreter/test_standalone_executor.py @@ -295,7 +295,7 @@ class TestException(unittest.TestCase): self.assertRaises(ValueError, self.run_new_executor, feed) def test_nan(self): - flags = {'FLAGS_check_nan_inf': True} + flags = {'FLAGS_check_nan_inf': True, 'FLAGS_benchmark': True} paddle.fluid.set_flags(flags) feed = [{ 'id': np.array([1, 2, 3, 4, 5]).astype(np.int64), -- GitLab