[MIOpen] Message buffer for logging #3669

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open

cderb wants to merge 43 commits into develop from users/cderb/log_buffer

projects/miopen/CHANGELOG.md

-Original file line number
+Diff line change
@@ Expand Up @@
     * [BatchNorm] Added V3 batch normalization API with separate running statistics buffers (prevResultRunningMean/Variance and nextResultRunningMean/Variance)
     * [BatchNorm] New API entry-points `miopenBatchNormalizationForwardInferenceInvVariance` and
       `miopenBatchNormForwardInferenceActivationInvVariance` to support hipDNN.
+    * Recent logs dumped to file (`/tmp/miopen_error_<pid>`) on error log or MIOpen throw.
     * [Conv] Enabled CK wrw and bwd solvers with split-k disabled in deterministic mode.
     * [Conv] Added initial Composable Kernel (CK) support for RDNA3.X and RDNA4
@@ Expand Down @@

projects/miopen/docs/how-to/debug-log.rst

-Original file line number
+Diff line change
@@ Expand Up @@
     * ``MIOPEN_WARN_SEARCH``: Elevate log messages for Search to warnings.
+    * ``MIOPEN_LOG_BUFFER_SIZE``: Message length of the Info2 buffer.
+      If ``MIOPEN_LOG_LEVEL`` is less than 6, then log messages will be buffered.
+      The buffered logs will be dumped to a log file when MIOpen logs an error message,
+      or an error is thrown by MIOpen.
+      This log can be found in ``/tmp/miopen_error_<pid>``.
     .. note::
       If you require technical support, include the console log that is produced from these settings:
@@ Expand Down @@

projects/miopen/src/include/miopen/errors.hpp

-Original file line number
+Diff line change
@@ Expand Up / @@ -28,6 +28,7 @@ @@
     #include <exception>
     #include <iostream>
+    #include <miopen/logger.hpp>
     #include <miopen/miopen.h>
     #include <miopen/object.hpp>
     #include <miopen/returns.hpp>
@@ Expand Down Expand Up @@
     template <class... Params>
     [[noreturn]] void MIOpenThrow(const std::string& file, int line, Params&&... args)
     {
-        throw miopen::Exception(std::forward<Params>(args)...).SetContext(file, line);
+        auto exe = miopen::Exception(std::forward<Params>(args)...);
+        MIOPEN_LOG_E_FROM(file + ":" + std::to_string(line), exe.message);
+        throw exe.SetContext(file, line);
     }
     #define MIOPEN_THROW(...)                                     \
@@ Expand Down @@

projects/miopen/src/include/miopen/logger.hpp

-Original file line number
+Diff line change
@@ Expand Up / @@ -34,14 +34,17 @@ @@
     #include <type_traits>
     #include <chrono>
-    #include <miopen/each_args.hpp>
     #include <miopen/object.hpp>
     #include <miopen/config.hpp>
     #if MIOPEN_USE_ROCTRACER
     #include <roctracer/roctx.h>
     #endif
+    #ifdef _WIN32
+    MIOPEN_INTERNALS_EXPORT size_t getpid();
+    #endif
     // See https://github.com/pfultz2/Cloak/wiki/C-Preprocessor-tricks,-tips,-and-idioms
     #define MIOPEN_PP_CAT(x, y) MIOPEN_PP_PRIMITIVE_CAT(x, y)
     #define MIOPEN_PP_PRIMITIVE_CAT(x, y) x##y
@@ Expand Down Expand Up @@
     #define MIOPEN_GET_FN_NAME miopen::LoggingParseFunction(__func__, __PRETTY_FUNCTION__)
     #endif
-    #define MIOPEN_LOG_XQ_CUSTOM(level, disableQuieting, category, fn_name, ...)                \
-        do                                                                                      \
-        {                                                                                       \
-            if(miopen::IsLogging(level, disableQuieting))                                       \
-            {                                                                                   \
-                std::ostringstream miopen_log_ss;                                               \
-                miopen_log_ss << miopen::LoggingPrefix() << category << " [" << fn_name << "] " \
-                              << __VA_ARGS__ << std::endl;                                      \
-                std::cerr << miopen_log_ss.str();                                               \
-            }                                                                                   \
+    MIOPEN_INTERNALS_EXPORT void ClearBufferLog();
+    MIOPEN_INTERNALS_EXPORT void BufferLog(std::string line);
+    MIOPEN_INTERNALS_EXPORT void OutputBufferedLogs();
+    #define MIOPEN_LOG_XQ_CUSTOM(level, disableQuieting, category, fn_name, ...)            \
+        do                                                                                  \
+        {                                                                                   \
+            std::ostringstream miopen_log_ss;                                               \
+            miopen_log_ss << miopen::LoggingPrefix() << category << " [" << fn_name << "] " \
+                          << __VA_ARGS__ << std::endl;                                      \
+            if(miopen::IsLogging(level, disableQuieting))                                   \
+            {                                                                               \
+                std::cerr << miopen_log_ss.str();                                           \
+            }                                                                               \
+            if(!miopen::IsLogging(miopen::LoggingLevel::Info2, disableQuieting))            \
+            {                                                                               \
+                if(level < miopen::LoggingLevel::Trace)                                     \
+                {                                                                           \
+                    miopen::BufferLog(miopen_log_ss.str());                                 \
+                }                                                                           \
+                if(level == miopen::LoggingLevel::Error)                                    \
+                {                                                                           \
+                    miopen::OutputBufferedLogs();                                           \
+                }                                                                           \
+            }                                                                               \
         } while(false)
     #define MIOPEN_LOG_XQ_(level, disableQuieting, fn_name, ...) \
@@ Expand Down @@

projects/miopen/src/logger.cpp

-Original file line number
+Diff line change
@@ Expand Up / @@ -24,12 +24,14 @@ @@
      *
      *******************************************************************************/
     #include <miopen/env.hpp>
+    #include <miopen/filesystem.hpp>
     #include <miopen/logger.hpp>
     #include <miopen/config.h>
     #include <miopen/sysinfo_utils.hpp>
     #include <cstdlib>
     #include <chrono>
+    #include <fstream>
     #include <ios>
     #include <iomanip>
     #include <sstream>
@@ Expand All / @@ -39,6 +41,11 @@ @@
     #include <sys/syscall.h> /* For SYS_xxx definitions */
     #endif
+    #ifdef _WIN32
+    #include <windows.h>
+    size_t getpid() { return _getpid(); }
+    #endif
     /// Enable logging of the most important function calls.
     /// Name of envvar in a bit inadequate due to historical reasons.
     MIOPEN_DECLARE_ENV_VAR_BOOL(MIOPEN_ENABLE_LOGGING)
@@ Expand Down Expand Up / @@ -68,8 +75,48 @@ MIOPEN_DECLARE_ENV_VAR_BOOL(MIOPEN_ENABLE_LOGGING_ROCTX) @@
     /// Disable logging quieting.
     MIOPEN_DECLARE_ENV_VAR_BOOL(MIOPEN_DEBUG_LOGGING_QUIETING_DISABLE)
+    MIOPEN_DECLARE_ENV_VAR_UINT64(MIOPEN_LOG_BUFFER_SIZE, 128);
     namespace miopen {
+    // NOLINTNEXTLINE(cppcoreguidelines-avoid-non-const-global-variables, cert-err58-cpp)
+    static thread_local size_t log_buffer_size = env::value(MIOPEN_LOG_BUFFER_SIZE);
+    // NOLINTNEXTLINE(cppcoreguidelines-avoid-non-const-global-variables, cert-err58-cpp)
+    static thread_local size_t log_buffer_i = 0;
+    // NOLINTNEXTLINE(cppcoreguidelines-avoid-non-const-global-variables, cert-err58-cpp)
+    static thread_local std::vector<std::string> log_buffer(log_buffer_size, "");
+    void ClearBufferLog()
+    {
+        log_buffer_i = 0;
+        log_buffer   = std::vector<std::string>(miopen::log_buffer_size, "");
+    }
+    void BufferLog(std::string line)
+    {
+        log_buffer[log_buffer_i] = line;
+        log_buffer_i             = (log_buffer_i + 1) % log_buffer_size;
+    }
+    void OutputBufferedLogs()
+    {
+        auto buffer_size = (log_buffer[log_buffer_size - 1] == "") ? log_buffer_i : log_buffer_size;
+        auto filename =
+            fs::temp_directory_path() / ("miopen_error_" + std::to_string(::getpid()) + ".log");
+        std::cerr << "Buffered " << buffer_size << " messages to file: " << sysinfo::GetSystemHostname()
+                  << ":" << filename.string() << std::endl;
+        auto err_file = std::ofstream{filename};
+        size_t i      = log_buffer_i;
+        do
+        {
+            if(log_buffer[i] != "")
+            {
+                err_file << log_buffer[i];
+            }
+            i = (i + 1) % log_buffer_size;
+        } while(i != log_buffer_i);
+    }
     namespace debug {
     // NOLINTNEXTLINE (cppcoreguidelines-avoid-non-const-global-variables)
@@ Expand Down @@

projects/miopen/test/gtest/log.cpp

-Original file line number
+Diff line change
@@ Expand Up / @@ -28,8 +28,10 @@ @@
     #include "get_handle.hpp"
     #include "../lib_env_var.hpp"
+    #include <gtest/gtest_common.hpp>
     #include <miopen/config.h>
     #include <miopen/fusion_plan.hpp>
+    #include <miopen/logger.hpp>
     #include "../random.hpp"
     #if MIOPEN_BACKEND_OPENCL
@@ Expand Down Expand Up @@
         else
             ASSERT_FALSE(isSubStr(str, sub_str)) << "str     : " << str << "str_sub : " << sub_str;
     }
+    void TestLogBufferOn()
+    {
+        auto filename =
+            fs::temp_directory_path() / ("miopen_error_" + std::to_string(getpid()) + ".log");
+        size_t line_i = 0;
+        std::string line;
+        fs::remove(filename);
+        ScopedEnvironment<std::string> log_level_env(MIOPEN_LOG_LEVEL,
+                                                     "5"); // miopen::LoggingLevel::Info
+        // test log dump after error
+        miopen::ClearBufferLog();
+        MIOPEN_LOG_W("warn");
+        MIOPEN_LOG_I("info");
+        MIOPEN_LOG_I2("info2");
+        MIOPEN_LOG_T("trace");
+        MIOPEN_LOG_E("error");
+        ASSERT_TRUE(fs::exists(filename));
+        {
+            auto log_file = std::ifstream{filename};
+            while(std::getline(log_file, line))
+            {
+                switch(line_i)
+                {
+                case 0: ASSERT_TRUE(isSubStr(line, "warn")); break;
+                case 1: ASSERT_TRUE(isSubStr(line, "info")); break;
+                case 2: ASSERT_TRUE(isSubStr(line, "info2")); break;
+                case 3:
+                    ASSERT_FALSE(isSubStr(line, "trace"));
+                    ASSERT_TRUE(isSubStr(line, "error"));
+                    break;
+                }
+                line_i++;
+            }
+        }
+        fs::remove(filename);
+        // test log dump after throw
+        miopen::ClearBufferLog();
+        MIOPEN_LOG_W("warn");
+        MIOPEN_LOG_I("info");
+        MIOPEN_LOG_I2("info2");
+        MIOPEN_LOG_T("trace");
+        EXPECT_ANY_THROW({ MIOPEN_THROW("throw"); });
+        EXPECT_TRUE(fs::exists(filename));
+        {
+            auto log_file = std::ifstream{filename};
+            line_i        = 0;
+            while(std::getline(log_file, line))
+            {
+                switch(line_i)
+                {
+                case 0: ASSERT_TRUE(isSubStr(line, "warn")); break;
+                case 1: ASSERT_TRUE(isSubStr(line, "info")); break;
+                case 2: ASSERT_TRUE(isSubStr(line, "info2")); break;
+                case 3: ASSERT_TRUE(isSubStr(line, "throw")); break;
+                }
+                line_i++;
+            }
+        }
+        fs::remove(filename);
+    }
+    void TestLogBufferOff()
+    {
+        auto filename =
+            fs::temp_directory_path() / ("miopen_error_" + std::to_string(getpid()) + ".log");
+        fs::remove(filename);
+        ScopedEnvironment<std::string> log_level_env(MIOPEN_LOG_LEVEL,
+                                                     "6"); // miopen::LoggingLevel::Info2
+        miopen::ClearBufferLog();
+        // log messages
+        MIOPEN_LOG_W("warn");
+        MIOPEN_LOG_I("info");
+        MIOPEN_LOG_I2("info2");
+        MIOPEN_LOG_T("trace");
+        // test log dump after error
+        MIOPEN_LOG_E("error");
+        ASSERT_FALSE(fs::exists(filename));
+    }

projects/miopen/test/gtest/log.hpp

-Original file line number
+Diff line change
@@ Expand Up @@
     void TestLogCmdBNormFusion(std::function<void(const miopenFusionPlanDescriptor_t)> const& func,
                                std::string sub_str,
                                bool set_env);
+    void TestLogBufferOn();
+    void TestLogBufferOff();

projects/miopen/test/gtest/log_test.cpp

-Original file line number
+Diff line change
@@ Expand Up / @@ -38,6 +38,10 @@ TEST(CPU_LOG_TEST_ASSERT_NONE, AssertLogFindCmdOutput) @@
         TestLogFun(miopen::debug::LogCmdFindConvolution, logFindConv, true);
     }
+    TEST(CPU_LOG_TEST_ASSERT_NONE, AssertLogBufferOn) { TestLogBufferOn(); }
+    TEST(CPU_LOG_TEST_ASSERT_NONE, AssertLogBufferOff) { TestLogBufferOff(); }
     TEST(CPU_LOG_TEST_FUSION_NONE, AssertTestLogCmdCBAFusionOutput)
     {
         TestLogCmdCBAFusion(miopen::debug::LogCmdFusion, logFusionConvBiasActiv, true);
@@ Expand Down @@

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[MIOpen] Message buffer for logging #3669

Uh oh!

Diff view

Diff view

There are no files selected for viewing

Uh oh!

Uh oh!

Uh oh!

Uh oh!

[MIOpen] Message buffer for logging #3669

Are you sure you want to change the base?

Uh oh!

[MIOpen] Message buffer for logging #3669

Uh oh!

Uh oh!

Diff view

Diff view

There are no files selected for viewing

Uh oh!

Uh oh!

Uh oh!

Uh oh!