[FEA] When libcudf throws exception, it should also print out the stack trace

[ttnghia]

Currently, when an exception happens, it will be thrown with an error message. All we can see from it is just something like this:

RuntimeError: CUDF failure at:/opt/conda/conda-bld/work/cpp/include/cudf/utilities/type_dispatcher.hpp:531: Invalid type_id.

We have no idea which APIs have been called and cause that exception. It would be much much better if we can print out the stack trace like this:

 0# void throw_with_trace<std::logic_error>(std::logic_error const&) at ../example/throwing_st.cpp:22
 1# oops(int) at ../example/throwing_st.cpp:38
 2# bar(int) at ../example/throwing_st.cpp:54
 3# foo(int) at ../example/throwing_st.cpp:59
 4# bar(int) at ../example/throwing_st.cpp:49
 5# foo(int) at ../example/throwing_st.cpp:59
 6# main at ../example/throwing_st.cpp:76
 7# 0x00007FAC113BEF45 in /lib/x86_64-linux-gnu/libc.so.6
 8# 0x0000000000402ED9

Ref: https://www.boost.org/doc/libs/develop/doc/html/stacktrace/getting_started.html#stacktrace.getting_started.exceptions_with_stacktrace

We can adopt one of the very well-known opensource stack trace libraries such as https://github.com/boostorg/stacktrace or https://github.com/bombela/backward-cpp or write our own stack trace code. I believe that having the ability to print the call stack would significantly benefit our developers.

[vyasr]

I'm -1 on using a Boost solution. We ripped it out intentionally in #7932, it's a large dependency and I wouldn't want to make RAPIDS any harder to build than it already is.

I'm not opposed to providing a stack trace in general, though. A simpler solution for this would be nice. FWIW I adapted a much more hacked together solution in the stream identification library: https://github.com/rapidsai/cudf/blob/branch-23.02/cpp/tests/utilities/identify_stream_usage/identify_stream_usage.cpp#L45.

[ttnghia]

That's great. Should we extract that code out and make it a common utility function so CUDF_EXPECT can call it? I was afraid that implementing it ourselves would be difficult, didn't realize that we already have it.

[vyasr]

Sure I'm OK with extracting that code. I have a weak preference for using a simple, well-maintained, header-only library that is better than my solution, but I don't know if it's worth the effort right now so moving my code out into somewhere that can be used more generally in libcudf is fine.

[davidwendt]

There are over 1100 CUDF_EXPECTS calls in libcudf so I have a strong preference that this would not be a header-only solution.

[jlowe]

The problem with libcudf logging an exception and then throwing it is that this is the log-and-throw anti-pattern. This usually means the exception gets logged at least twice, once by libcudf and another by the application, or worse, the application has some recovery logic and then we get some unwanted prints from libcudf.

This would be very bad for RMM, for example, as our application is performing recovery on many RMM exceptions and retrying. If libcudf printed a stacktrace when an output column is too big (i.e.: row count > maxint), that would be annoying output if the application were to catch, recover, and retry (e.g.: by splitting the input into smaller chunks and iterating).

[vyasr]

There are over 1100 CUDF_EXPECTS calls in libcudf so I have a strong preference that this would not be a header-only solution.

Good point, I wasn't thinking about this too much. I'm less interested in it being header-only specifically, and more in it being lightweight. A single small header and source file would also be perfectly fine with me.

The problem with libcudf logging an exception and then throwing it is that this is the log-and-throw anti-pattern. This usually means the exception gets logged at least twice, once by libcudf and another by the application, or worse, the application has some recovery logic and then we get some unwanted prints from libcudf.

Perhaps I was misunderstanding @ttnghia's intent, but I don't think what I'm thinking of matches the antipattern you're referring to. We're not suggesting to do a try/catch/log/rethrow. These aren't exceptions coming from somewhere that we can't deal with. These are exceptional cases originating within cudf itself, and the suggestion is to simply provide a more informative exception message. We wouldn't print and then throw, we would concatenate the stack trace into the exception message and do a throw exception_type(reason_and_stack_trace). Does that address your concerns?

[ttnghia]

Today, again Spark team has to debug a subtle bug that only shows up in Dataproc + T4 GPU env. The bug can't be reproduced anywhere else, and only gives us a hint which doesn't help tracing back because it doesn't have stack trace:

ai.rapids.cudf.CudaFatalException: Fatal CUDA error encountered at: /home/jenkins/agent/workspace/jenkins-spark-rapids-jni_nightly-dev-406-cuda11/thirdparty/cudf/cpp/src/io/utilities/hostdevice_vector.hpp:149: 700 cudaErrorIllegalAddress an illegal memory access was encountered
	at ai.rapids.cudf.Table.writeORCChunk(Native Method)
	at ai.rapids.cudf.Table.access$1400(Table.java:41)
	at ai.rapids.cudf.Table$ORCTableWriter.write(Table.java:1477)
	at com.nvidia.spark.rapids.ColumnarOutputWriter.$anonfun$writeBatchWithRetry$5(ColumnarOutputWriter.scala:177)
	at com.nvidia.spark.rapids.ColumnarOutputWriter.$anonfun$writeBatchWithRetry$5$adapted(ColumnarOutputWriter.scala:174)
	at com.nvidia.spark.rapids.Arm$.withResource(Arm.scala:29)

I'm going to work on this ASAP. Given that cudf has a logging mechanism, we can log the stack trace without concatenating it into the thrown exception which should address the concern above.

[jlowe]

we can log the stack trace without concatenating it into the thrown exception

This is the log-then-throw anti-pattern I referred to above.

[ttnghia]

Yes, and I'm trying to think of a way to overcome that. For example, logging using a different log level (such as debug level) which is turned off and doesn't print anything by default. But when we want to debug something, we can turn it back on to chase the issue.

If you have other ideas then please let me know.

[jlowe]

Putting the stacktrace into the exception is usually the preferred route, either putting it in the exception message or attached to the exception object as a separate field/method that can be accessed for more detail. Then if the exception is not normally recovered by the application, the application has all the information needed to log it (and logged via the way the application wants to log).