[new-exec] refine vlog of interpretercore (#36865)

* refine vlog of interpretercore

* fix ut

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 <unordered_set>
-
 #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);
   }
 }
 

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<LoDTensor>()) {
         garbages->emplace_back(
             var->GetMutable<LoDTensor>()->MoveMemoryHolder());

paddle/fluid/framework/operator.cc

@@ -62,7 +62,7 @@ std::vector<std::tuple<platform::Place, LibraryType>> 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<std::string>& 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:{";
 

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; }

paddle/fluid/memory/allocation/allocator_facade.cc

@@ -202,7 +202,7 @@ class AllocatorFacadePrivate {
 
   inline const std::shared_ptr<Allocator>& 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_

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(

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);
   }
 

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),