Add environment variable to log cudf.pandas fallback calls

python/cudf/cudf/pandas/_logger.py

@@ -0,0 +1,26 @@
+# SPDX-FileCopyrightText: Copyright (c) 2023-2024, NVIDIA CORPORATION & AFFILIATES.
+# All rights reserved.
+# SPDX-License-Identifier: Apache-2.0
+
+from __future__ import annotations
+
+import json
+import logging
+
+# https://docs.python.org/3/howto/logging-cookbook.html#implementing-structured-logging
+
+
+class StructuredMessage:
+    def __init__(self, debug_type: str, /, **kwargs):
+        self.debug_type = debug_type
+        self.kwargs = kwargs
+
+    def __str__(self):
+        log = {"debug_type": self.debug_type}
+        return json.dumps({**log, **self.kwargs})
+
+
+logging.basicConfig(
+    filename="cudf_pandas_unit_tests_debug.log", level=logging.INFO
+)
+logger = logging.getLogger()

python/cudf/cudf/pandas/fast_slow_proxy.py

@@ -930,13 +930,49 @@ def _fast_slow_function_call(
                             "Pandas debugging mode failed. "
                             f"The exception was {e}."
                         )
-    except Exception:
+    except Exception as err:
         with nvtx.annotate(
             "EXECUTE_SLOW",
             color=_CUDF_PANDAS_NVTX_COLORS["EXECUTE_SLOW"],
             domain="cudf_pandas",
         ):
             slow_args, slow_kwargs = _slow_arg(args), _slow_arg(kwargs)
+            if _env_get_bool("CUDF_PANDAS_SLOW_LOG", False):
+                from ._logger import StructuredMessage, logger
+
+                def reprify(arg) -> str:
+                    try:
+                        return repr(arg)
+                    except Exception:
+                        return "<REPR FAILED>"
+
+                module = getattr(slow_args[0], "__module__", "")
+                obj_name = getattr(
+                    slow_args[0], "__name__", type(slow_args[0]).__name__
+                )
+                slow_object = f"{module}.{obj_name}"
+                # TODO: maybe use inspect.signature to map called args and kwargs
+                # to their keyword names
+                called_args = ",".join((reprify(val) for val in slow_args[1]))
+                if len(slow_args) == 3:
+                    fmt_kwargs = ",".join(
+                        f"{kwarg}={reprify(value)}"
+                        for kwarg, value in slow_args[2].items()
+                    )
+                    called_args = ",".join((called_args, fmt_kwargs))
+                    passed_kwargs = dict(slow_args[2].items())
+                else:
+                    passed_kwargs = None
+                message = StructuredMessage(
+                    "CUDF_PANDAS_SLOW_LOG",
+                    failed_call=f"{slow_object}({called_args})",
+                    exception=type(err).__name__,
+                    exception_message=str(err),
+                    pandas_object=slow_object,
+                    passed_args=called_args,
+                    passed_kwargs=passed_kwargs,
+                )
+                logger.info(message)
             with disable_module_accelerator():
                 result = func(*slow_args, **slow_kwargs)
     return _maybe_wrap_result(result, func, *args, **kwargs), fast

python/cudf/cudf/pandas/scripts/run-pandas-tests.sh

@@ -63,6 +63,11 @@ markers = [
   "arm_slow: mark a test as slow for arm64 architecture",
   "skip_ubsan: Tests known to fail UBSAN check",
 ]
+log_format = %(asctime)s %(levelname)s %(message)s
+log_date_format = %Y-%m-%d %H:%M:%S
+log_file = cudf_pandas_unit_tests_debug.log
+log_file_level = INFO
+log_cli = true
 EOF
     # append the contents of patch-confest.py to conftest.py
     cat ../python/cudf/cudf/pandas/scripts/conftest-patch.py >> pandas-tests/conftest.py