Python runtime: stop a backend's log from deadlocking 2 threads

docs/source/using-executorch-runtime-integration.md

@@ -36,33 +36,45 @@ To register a custom PAL implementation, take the following steps:
 - Create an instance of the [PalImpl](https://github.com/pytorch/executorch/blob/7b39a0ce63bfb5124d4d29cfb6c8af85a3c580ba/runtime/platform/platform.h#L163) struct.
   - Set one or more fields to custom PAL function implementations. Leave fields as null to use the default platform implementation.
   - The PalImpl struct provides a [create](https://github.com/pytorch/executorch/blob/7b39a0ce63bfb5124d4d29cfb6c8af85a3c580ba/runtime/platform/platform.h#L168) method for this purpose.
-- Call `executorch::platform::register_pal(pal_impl)` to register the implementation.
+- Call `executorch::runtime::register_pal(pal_impl)` to register the implementation.
   - This can be done from as as a global constructor, as in the example below.
 
-Here is a complete example from [pybindings.cpp](https://github.com/pytorch/executorch/blob/7b39a0ce63bfb5124d4d29cfb6c8af85a3c580ba/extension/pybindings/pybindings.cpp#L1178), where logs are redirected to show up properly in a Python notebook environment.
+Here is a complete example that writes each log line to stderr.
 
 ```cpp
+#include <cstdio>
+
+#include <executorch/runtime/platform/platform.h>
+
 namespace {
-  void emit_log_message(
-      et_timestamp_t timestamp,
-      et_pal_log_level_t level,
-      const char* filename,
-      ET_UNUSED const char* function,
-      size_t line,
-      const char* message,
-      ET_UNUSED size_t length) {
-    std::cerr << "[" << filename << ":" << line << "] " << message << std::endl;
-  }
-
-  runtime::PalImpl build_pal() {
-    return runtime::PalImpl::create(emit_log_message, __FILE__);
-  }
-
-  // Update PAL to redirect logs.
-  ET_UNUSED bool registration_result = runtime::register_pal(build_pal());
+
+void emit_log_message(
+    ET_UNUSED et_timestamp_t timestamp,
+    ET_UNUSED et_pal_log_level_t level,
+    const char* filename,
+    ET_UNUSED const char* function,
+    size_t line,
+    const char* message,
+    size_t length) {
+  std::fprintf(
+      stderr, "[%s:%zu] %.*s\n", filename, line, static_cast<int>(length), message);
+  std::fflush(stderr);
 }
+
+ET_UNUSED const bool registered = executorch::runtime::register_pal(
+    executorch::runtime::PalImpl::create(emit_log_message, __FILE__));
+
+} // namespace
 ```
 
+The Python bindings register their PAL the same way, in
+[pybindings.cpp](https://github.com/pytorch/executorch/blob/main/extension/pybindings/pybindings.cpp).
+A backend can log while it holds a lock, and a log function that writes to
+Python at that moment can deadlock with another thread that waits for that lock,
+so their log function never calls Python. Their
+[README](https://github.com/pytorch/executorch/blob/main/extension/pybindings/README.md#note)
+says where their lines go.
+
 ### Weak Symbol Override
 ExecuTorch also provides a link-time method to override the PAL using weak symbols. This method is primarily maintained for backwards compatibility.
 

extension/pybindings/README.md

@@ -234,4 +234,45 @@ CMAKE_ARGS="-DEXECUTORCH_BUILD_VULKAN=ON" ./install_executorch.sh
 This class is currently empty and serves as a placeholder for future methods and attributes.
 - `verify_result_with_bundled_expected_output(method_name: str, testset_idx: int, rtol: float = 1e-5, atol: float = 1e-8)`: Verify result with bundled expected output.
 ## Note
-Runtime logs are forwarded to Python stderr.
+Runtime logs go straight to the process's stderr as they are logged. On Windows,
+a console shows text that is not ASCII in its own code page, so such text can
+look wrong there. If Python has replaced `sys.stderr`, for example with pytest's
+`capsys`, `contextlib.redirect_stderr` or in a Jupyter notebook, the lines go to
+`sys.stderr` instead, a little later. The lines a binding call logs wait until
+the call returns. A line logged outside any binding call, for example by the LLM
+runner, goes to `sys.stderr` before the next Python code runs if Python's main
+thread logged it. A line from another thread goes there a moment later, from a
+thread that the bindings start for this. Outside a call, only a thread that
+holds the GIL can tell where `sys.stderr` goes, so a line from a thread that
+does not hold it, such as one the LLM runner logs while it generates, goes to
+the process's stderr. The lines wait rather than go to Python at once because a
+backend can log while it holds a lock, and writing to Python at that moment
+could deadlock with another thread.
+
+On Linux and macOS, a line also waits once the process's stderr is a pipe or
+socket that stays full for 100 ms, so a thread that holds the GIL does not hang
+on it while a Python thread in the same process empties it, as under
+`wurlitzer.pipes()`. The rest of a binding call's lines then wait for the call
+to return. A thread that logs outside a call does not wait for room itself. It
+hands the line to the bindings' thread, which writes it without the GIL. While
+it writes, a binding call's lines wait for the call to return. A terminal is
+written at once, since its reader is normally another process. The process can
+still hang if another writer fills the process's stderr right after the check
+for room, or if a Python thread in the same process reads a terminal that is the
+process's stderr. On macOS, a pipe that has not grown past 16 KiB takes a line
+only once the line fits in 512 bytes beside what the pipe holds, because macOS
+reports room in such a pipe that it may not have.
+
+Up to 1 MiB of lines wait at a time; past that, about the newest 512 KiB to
+1 MiB are kept, with a note of how many earlier bytes were left out. A fatal
+line goes straight to the process's stderr while it has room, with the lines its
+binding call kept, since an abort usually follows. Any crash or hang of the
+process, including that abort, or an `os._exit()` loses the lines still waiting.
+Once Python starts to exit, the lines still waiting are written, and later lines
+logged outside a call go to the process's stderr while it has room. Lines for
+the process's stderr are left out instead if the bindings' thread is still
+writing to it then.
+
+On Linux with Python before 3.13.8, a daemon thread never writes through Python,
+because at exit Python can stop such a thread in the middle of that write, which
+crashes the process. The bindings' thread writes its lines instead.