From b91633502549377bcd52d1f1c78d02d3b048d4bb Mon Sep 17 00:00:00 2001 From: Chen Weihang Date: Fri, 27 Sep 2019 11:07:09 +0800 Subject: [PATCH] Paddle error message stack shaping and optimization (#19895) * shape and optimize paddle error message stack, test=develop * limit exception type & add unittest, test=develop * fix multi-platform problem, test=develop * fix related unnitest failed, test=develop * add doc & fix unittest errors, test=develop * fix function name error, test=develop * update tensor test exception msg compare, test=develop * remove unittest on win32, the dir format is different, test=develop * remove useless package, test=develop * add paddle enforce handler unittest, test=develop * add exception checkout, test=develop * fix coverage failed, test=develop * fix op registry test failed, test=develop * refactor whole pr, test=develop * remove test in CMakelist, test=develop * fix coverage, test=develop --- paddle/fluid/framework/op_call_stack.cc | 34 +++++++--- paddle/fluid/framework/op_registry_test.cc | 18 ++--- paddle/fluid/framework/tensor_test.cc | 24 +++---- paddle/fluid/platform/enforce.h | 76 ++++++++++++---------- paddle/fluid/platform/enforce_test.cc | 63 +++++++++--------- python/paddle/fluid/executor.py | 3 +- 6 files changed, 118 insertions(+), 100 deletions(-) diff --git a/paddle/fluid/framework/op_call_stack.cc b/paddle/fluid/framework/op_call_stack.cc index cf3b7188acb..91da3202613 100644 --- a/paddle/fluid/framework/op_call_stack.cc +++ b/paddle/fluid/framework/op_call_stack.cc @@ -29,17 +29,35 @@ void InsertCallStackInfo(const std::string &type, const AttributeMap &attrs, auto &callstack = boost::get>( attrs.at(OpProtoAndCheckerMaker::OpCreationCallstackAttrName())); - if (callstack.empty()) { - return; - } std::ostringstream sout; - sout << "Invoke operator " << type << " error.\n"; - sout << "Python Call stacks: \n"; - for (auto &line : callstack) { - sout << line; + std::ostringstream sout_py_trace; + // Step 1. Construct python call stack string + if (!callstack.empty()) { + sout_py_trace << "\n------------------------------------------\n"; + sout_py_trace << "Python Call Stacks (More useful to users):"; + sout_py_trace << "\n------------------------------------------\n"; + for (auto &line : callstack) { + sout_py_trace << line; + } } - sout << "C++ Call stacks: \n"; + // Step 2. Insert python traceback into err_str_ + std::size_t found = exception->err_str_.rfind("PaddleCheckError:"); + if (found != std::string::npos) { + exception->err_str_.insert(found, sout_py_trace.str()); + exception->err_str_.insert(found + sout_py_trace.str().length(), + "\n----------------------\nError Message " + "Summary:\n----------------------\n"); + } else { + exception->err_str_.append(sout_py_trace.str()); + } + // Step 3. Construct final call stack + sout << "\n\n--------------------------------------------\n"; + sout << "C++ Call Stacks (More useful to developers):"; + sout << "\n--------------------------------------------\n"; sout << exception->err_str_; + if (!callstack.empty()) { + sout << " [operator < " << type << " > error]"; + } exception->err_str_ = sout.str(); } diff --git a/paddle/fluid/framework/op_registry_test.cc b/paddle/fluid/framework/op_registry_test.cc index 04996d7b09c..66d08759e37 100644 --- a/paddle/fluid/framework/op_registry_test.cc +++ b/paddle/fluid/framework/op_registry_test.cc @@ -118,10 +118,8 @@ TEST(OpRegistry, IllegalAttr) { } catch (paddle::platform::EnforceNotMet err) { caught = true; std::string msg = "larger_than check fail"; - const char* err_msg = err.what(); - for (size_t i = 0; i < msg.length(); ++i) { - ASSERT_EQ(err_msg[i], msg[i]); - } + std::string err_msg = err.what(); + ASSERT_TRUE(err_msg.find(msg) != std::string::npos); } ASSERT_TRUE(caught); } @@ -154,10 +152,8 @@ TEST(OpRegistry, CustomChecker) { } catch (paddle::platform::EnforceNotMet err) { caught = true; std::string msg = "Attribute 'test_attr' is required!"; - const char* err_msg = err.what(); - for (size_t i = 0; i < msg.length(); ++i) { - ASSERT_EQ(err_msg[i], msg[i]); - } + std::string err_msg = err.what(); + ASSERT_TRUE(err_msg.find(msg) != std::string::npos); } ASSERT_TRUE(caught); @@ -172,10 +168,8 @@ TEST(OpRegistry, CustomChecker) { } catch (paddle::platform::EnforceNotMet err) { caught = true; std::string msg = "'test_attr' must be even!"; - const char* err_msg = err.what(); - for (size_t i = 0; i < msg.length(); ++i) { - ASSERT_EQ(err_msg[i], msg[i]); - } + std::string err_msg = err.what(); + ASSERT_TRUE(err_msg.find(msg) != std::string::npos); } ASSERT_TRUE(caught); diff --git a/paddle/fluid/framework/tensor_test.cc b/paddle/fluid/framework/tensor_test.cc index f94c0c532bd..4c124a998a4 100644 --- a/paddle/fluid/framework/tensor_test.cc +++ b/paddle/fluid/framework/tensor_test.cc @@ -38,13 +38,11 @@ TEST(Tensor, DataAssert) { src_tensor.data(); } catch (platform::EnforceNotMet err) { caught = true; - std::string msg = - "holder_ should not be null\nTensor holds no memory. Call " - "Tensor::mutable_data first."; - const char* what = err.what(); - for (size_t i = 0; i < msg.length(); ++i) { - ASSERT_EQ(what[i], msg[i]); - } + std::string ex_msg = err.what(); + EXPECT_TRUE(ex_msg.find("holder_ should not be null\nTensor holds no " + "memory. Call " + "Tensor::mutable_data first.") != + std::string::npos); } ASSERT_TRUE(caught); } @@ -155,13 +153,11 @@ TEST(Tensor, ShareDataWith) { dst_tensor.ShareDataWith(src_tensor); } catch (paddle::platform::EnforceNotMet err) { caught = true; - std::string msg = - "holder_ should not be null\nTensor holds no memory. Call " - "Tensor::mutable_data first."; - const char* what = err.what(); - for (size_t i = 0; i < msg.length(); ++i) { - ASSERT_EQ(what[i], msg[i]); - } + std::string ex_msg = err.what(); + EXPECT_TRUE(ex_msg.find("holder_ should not be null\nTensor holds no " + "memory. Call " + "Tensor::mutable_data first.") != + std::string::npos); } ASSERT_TRUE(caught); diff --git a/paddle/fluid/platform/enforce.h b/paddle/fluid/platform/enforce.h index f9ae4113f9d..db01414a8bb 100644 --- a/paddle/fluid/platform/enforce.h +++ b/paddle/fluid/platform/enforce.h @@ -52,6 +52,8 @@ limitations under the License. */ #endif // __APPLE__ #endif // PADDLE_WITH_CUDA +#define WITH_SIMPLE_TRACEBACK + namespace paddle { namespace platform { @@ -72,18 +74,22 @@ inline std::string GetTraceBackString(StrType&& what, const char* file, static constexpr int TRACE_STACK_LIMIT = 100; std::ostringstream sout; - sout << string::Sprintf("%s at [%s:%d]", std::forward(what), file, - line) - << std::endl; - sout << "PaddlePaddle Call Stacks: " << std::endl; #if !defined(_WIN32) void* call_stack[TRACE_STACK_LIMIT]; auto size = backtrace(call_stack, TRACE_STACK_LIMIT); auto symbols = backtrace_symbols(call_stack, size); Dl_info info; + int idx = 0; for (int i = 0; i < size; ++i) { if (dladdr(call_stack[i], &info) && info.dli_sname) { auto demangled = demangle(info.dli_sname); +#ifdef WITH_SIMPLE_TRACEBACK + std::string path(info.dli_fname); + // C++ traceback info are from core.so + if (path.substr(path.length() - 3).compare(".so") == 0) { + sout << string::Sprintf("%-3d %s\n", idx++, demangled); + } +#else auto addr_offset = static_cast(call_stack[i]) - static_cast(info.dli_saddr); sout << string::Sprintf("%-3d %*0p %s + %zd\n", i, 2 + sizeof(void*) * 2, @@ -91,12 +97,16 @@ inline std::string GetTraceBackString(StrType&& what, const char* file, } else { sout << string::Sprintf("%-3d %*0p\n", i, 2 + sizeof(void*) * 2, call_stack[i]); +#endif } } free(symbols); #else sout << "Windows not support stack backtrace yet."; #endif + sout << string::Sprintf("PaddleCheckError: %s at [%s:%d]", + std::forward(what), file, line) + << std::endl; return sout.str(); } @@ -338,7 +348,7 @@ DEFINE_CUDA_STATUS_TYPE(ncclResult_t, ncclSuccess); * PADDLE_ENFORCE_EQ(a, b); * * will raise an expression described as follows: - * "Enforce failed. Expected input a == b, but received a(1) != b(2)." + * "Expected input a == b, but received a(1) != b(2)." * with detailed stack information. * * extra messages is also supported, for example: @@ -445,8 +455,8 @@ struct BinaryCompareMessageConverter { constexpr bool __kCanToString__ = \ ::paddle::platform::details::CanToString<__TYPE1__>::kValue && \ ::paddle::platform::details::CanToString<__TYPE2__>::kValue; \ - PADDLE_THROW("Enforce failed. Expected %s " #__CMP \ - " %s, but received %s " #__INV_CMP " %s.\n%s", \ + PADDLE_THROW("Expected %s " #__CMP " %s, but received %s " #__INV_CMP \ + " %s.\n%s", \ #__VAL1, #__VAL2, \ ::paddle::platform::details::BinaryCompareMessageConverter< \ __kCanToString__>::Convert(#__VAL1, __val1), \ @@ -469,32 +479,32 @@ struct BinaryCompareMessageConverter { #define PADDLE_ENFORCE_LE(__VAL0, __VAL1, ...) \ __PADDLE_BINARY_COMPARE(__VAL0, __VAL1, <=, >, __VA_ARGS__) -#define __PADDLE_INFERSHAPE_BINARY_COMPARE(__CTX, __VAL1, __VAL2, __CMP, \ - __INV_CMP, ...) \ - do { \ - auto __val1 = (__VAL1); \ - auto __val2 = (__VAL2); \ - if (!__CTX->IsRuntime()) { \ - if (__val1 == -1 || __val2 == -1) { \ - break; \ - } \ - } \ - using __TYPE1__ = decltype(__val1); \ - using __TYPE2__ = decltype(__val2); \ - using __COMMON_TYPE1__ = \ - ::paddle::platform::details::CommonType1<__TYPE1__, __TYPE2__>; \ - using __COMMON_TYPE2__ = \ - ::paddle::platform::details::CommonType2<__TYPE1__, __TYPE2__>; \ - bool __is_not_error = (static_cast<__COMMON_TYPE1__>(__val1))__CMP( \ - static_cast<__COMMON_TYPE2__>(__val2)); \ - if (UNLIKELY(!__is_not_error)) { \ - PADDLE_THROW("Enforce failed. Expected %s " #__CMP \ - " %s, but received %s:%s " #__INV_CMP " %s:%s.\n%s", \ - #__VAL1, #__VAL2, #__VAL1, \ - ::paddle::string::to_string(__val1), #__VAL2, \ - ::paddle::string::to_string(__val2), \ - ::paddle::string::Sprintf(__VA_ARGS__)); \ - } \ +#define __PADDLE_INFERSHAPE_BINARY_COMPARE(__CTX, __VAL1, __VAL2, __CMP, \ + __INV_CMP, ...) \ + do { \ + auto __val1 = (__VAL1); \ + auto __val2 = (__VAL2); \ + if (!__CTX->IsRuntime()) { \ + if (__val1 == -1 || __val2 == -1) { \ + break; \ + } \ + } \ + using __TYPE1__ = decltype(__val1); \ + using __TYPE2__ = decltype(__val2); \ + using __COMMON_TYPE1__ = \ + ::paddle::platform::details::CommonType1<__TYPE1__, __TYPE2__>; \ + using __COMMON_TYPE2__ = \ + ::paddle::platform::details::CommonType2<__TYPE1__, __TYPE2__>; \ + bool __is_not_error = (static_cast<__COMMON_TYPE1__>(__val1))__CMP( \ + static_cast<__COMMON_TYPE2__>(__val2)); \ + if (UNLIKELY(!__is_not_error)) { \ + PADDLE_THROW("Expected %s " #__CMP " %s, but received %s:%s " #__INV_CMP \ + " %s:%s.\n%s", \ + #__VAL1, #__VAL2, #__VAL1, \ + ::paddle::string::to_string(__val1), #__VAL2, \ + ::paddle::string::to_string(__val2), \ + ::paddle::string::Sprintf(__VA_ARGS__)); \ + } \ } while (0) #define PADDLE_INFERSHAPE_ENFORCE_EQ(__CTX, __VAL0, __VAL1, ...) \ diff --git a/paddle/fluid/platform/enforce_test.cc b/paddle/fluid/platform/enforce_test.cc index 4e34f3cbf5b..2a2a8564693 100644 --- a/paddle/fluid/platform/enforce_test.cc +++ b/paddle/fluid/platform/enforce_test.cc @@ -17,10 +17,6 @@ limitations under the License. */ #include "gtest/gtest.h" #include "paddle/fluid/platform/enforce.h" -#include "paddle/fluid/string/piece.h" - -using StringPiece = paddle::string::Piece; -using paddle::string::HasPrefix; TEST(ENFORCE, OK) { PADDLE_ENFORCE(true, "Enforce is ok %d now %f", 123, 0.345); @@ -35,8 +31,9 @@ TEST(ENFORCE, FAILED) { PADDLE_ENFORCE(false, "Enforce is not ok %d at all", 123); } catch (paddle::platform::EnforceNotMet error) { caught_exception = true; - EXPECT_TRUE( - HasPrefix(StringPiece(error.what()), "Enforce is not ok 123 at all")); + std::string ex_msg = error.what(); + EXPECT_TRUE(ex_msg.find("Enforce is not ok 123 at all") != + std::string::npos); } EXPECT_TRUE(caught_exception); @@ -45,8 +42,8 @@ TEST(ENFORCE, FAILED) { PADDLE_ENFORCE(false, "Enforce is not ok at all"); } catch (paddle::platform::EnforceNotMet error) { caught_exception = true; - EXPECT_TRUE( - HasPrefix(StringPiece(error.what()), "Enforce is not ok at all")); + std::string ex_msg = error.what(); + EXPECT_TRUE(ex_msg.find("Enforce is not ok at all") != std::string::npos); } EXPECT_TRUE(caught_exception); @@ -75,9 +72,9 @@ TEST(ENFORCE_EQ, NO_EXTRA_MSG_FAIL) { PADDLE_ENFORCE_EQ(a, 1 + 3); } catch (paddle::platform::EnforceNotMet error) { caught_exception = true; - HasPrefix( - StringPiece(error.what()), - "Enforce failed. Expected a == 1 + 3, but received a:2 != 1 + 3:4."); + std::string ex_msg = error.what(); + EXPECT_TRUE(ex_msg.find("Expected a == 1 + 3, but received a:2 != 1 " + "+ 3:4.") != std::string::npos); } EXPECT_TRUE(caught_exception); } @@ -89,9 +86,9 @@ TEST(ENFORCE_EQ, EXTRA_MSG_FAIL) { PADDLE_ENFORCE_EQ(a, 1 + 3, "%s size not match", "their"); } catch (paddle::platform::EnforceNotMet error) { caught_exception = true; - HasPrefix(StringPiece(error.what()), - "Enforce failed. Expected a == 1 + 3, but received a:2 != 1 + " - "3:4.\ntheir size not match"); + std::string ex_msg = error.what(); + EXPECT_TRUE(ex_msg.find("Expected a == 1 + 3, but received a:2 != 1 + " + "3:4.\ntheir size not match") != std::string::npos); } EXPECT_TRUE(caught_exception); } @@ -108,10 +105,9 @@ TEST(ENFORCE_NE, FAIL) { PADDLE_ENFORCE_NE(1.0, 1UL); } catch (paddle::platform::EnforceNotMet error) { caught_exception = true; - EXPECT_TRUE(HasPrefix( - StringPiece(error.what()), - "Enforce failed. Expected 1.0 != 1UL, but received 1.0:1 == 1UL:1.")) - << error.what() << " does not have expected prefix"; + std::string ex_msg = error.what(); + EXPECT_TRUE(ex_msg.find("Expected 1.0 != 1UL, but " + "received 1.0:1 == 1UL:1.") != std::string::npos); } EXPECT_TRUE(caught_exception); } @@ -123,9 +119,9 @@ TEST(ENFORCE_GT, FAIL) { PADDLE_ENFORCE_GT(1, 2); } catch (paddle::platform::EnforceNotMet error) { caught_exception = true; - EXPECT_TRUE( - HasPrefix(StringPiece(error.what()), - "Enforce failed. Expected 1 > 2, but received 1:1 <= 2:2.")); + std::string ex_msg = error.what(); + EXPECT_TRUE(ex_msg.find("Expected 1 > 2, but received 1:1 <= 2:2.") != + std::string::npos); } EXPECT_TRUE(caught_exception); } @@ -141,9 +137,9 @@ TEST(ENFORCE_GE, FAIL) { PADDLE_ENFORCE_GE(1, 2); } catch (paddle::platform::EnforceNotMet error) { caught_exception = true; - EXPECT_TRUE( - HasPrefix(StringPiece(error.what()), - "Enforce failed. Expected 1 >= 2, but received 1:1 < 2:2.")); + std::string ex_msg = error.what(); + EXPECT_TRUE(ex_msg.find("Expected 1 >= 2, but received 1:1 < 2:2.") != + std::string::npos); } EXPECT_TRUE(caught_exception); } @@ -161,9 +157,9 @@ TEST(ENFORCE_LE, FAIL) { PADDLE_ENFORCE_GT(1, 2); } catch (paddle::platform::EnforceNotMet error) { caught_exception = true; - EXPECT_TRUE( - HasPrefix(StringPiece(error.what()), - "Enforce failed. Expected 1 > 2, but received 1:1 <= 2:2.")); + std::string ex_msg = error.what(); + EXPECT_TRUE(ex_msg.find("Expected 1 > 2, but received 1:1 <= 2:2.") != + std::string::npos); } EXPECT_TRUE(caught_exception); } @@ -179,9 +175,10 @@ TEST(ENFORCE_LT, FAIL) { PADDLE_ENFORCE_LT(1UL, 0.12); } catch (paddle::platform::EnforceNotMet error) { caught_exception = true; - EXPECT_TRUE(HasPrefix(StringPiece(error.what()), - "Enforce failed. Expected 1UL < 0.12, but " - "received 1UL:1 >= 0.12:0.12.")); + std::string ex_msg = error.what(); + EXPECT_TRUE(ex_msg.find("Expected 1UL < 0.12, but " + "received 1UL:1 >= 0.12:0.12.") != + std::string::npos); } EXPECT_TRUE(caught_exception); } @@ -198,7 +195,8 @@ TEST(ENFORCE_NOT_NULL, FAIL) { PADDLE_ENFORCE_NOT_NULL(a); } catch (paddle::platform::EnforceNotMet error) { caught_exception = true; - EXPECT_TRUE(HasPrefix(StringPiece(error.what()), "a should not be null")); + std::string ex_msg = error.what(); + EXPECT_TRUE(ex_msg.find("a should not be null") != std::string::npos); } EXPECT_TRUE(caught_exception); } @@ -251,7 +249,8 @@ TEST(EOF_EXCEPTION, THROW_EOF) { PADDLE_THROW_EOF(); } catch (paddle::platform::EOFException error) { caught_eof = true; - EXPECT_TRUE(HasPrefix(StringPiece(error.what()), "There is no next data.")); + std::string ex_msg = error.what(); + EXPECT_TRUE(ex_msg.find("There is no next data.") != std::string::npos); } EXPECT_TRUE(caught_eof); } diff --git a/python/paddle/fluid/executor.py b/python/paddle/fluid/executor.py index 27117585bef..33617bae90e 100644 --- a/python/paddle/fluid/executor.py +++ b/python/paddle/fluid/executor.py @@ -712,7 +712,8 @@ class Executor(object): use_program_cache=use_program_cache) except Exception as e: if not isinstance(e, core.EOFException): - print("!!!A non-EOF exception is thrown.") + warnings.warn( + "The following exception is not an EOF exception.") six.reraise(*sys.exc_info()) def _run_impl(self, program, feed, fetch_list, feed_var_name, -- GitLab