diff --git a/docs/dfx/host-trace.md b/docs/dfx/host-trace.md index 26e0df14bf..ba4ff4b218 100644 --- a/docs/dfx/host-trace.md +++ b/docs/dfx/host-trace.md @@ -62,6 +62,14 @@ boundary, not a clean floor. A system tracer would hand the bytes to a consumer instead, and would bound its buffer and count what it drops; this does neither, deliberately. +Every DSO that compiles the logger holds its own buffered stream on that one +file, so the buffering above is per module rather than per process: a `WARN` from +one module does not put another module's pending records on disk. Unloading a +module closes its stream, so a `dlclose` — which the sim device runner performs +on the AICPU SO at every teardown — leaves no records behind in the mapping it +drops. A stream inherited across `fork` belongs to the parent and is left alone, +so a child never flushes the parent's copied buffer a second time. + ## Reading a run back Every record carries its own `pid`, so the tools take several inputs and diff --git a/docs/logging.md b/docs/logging.md index f72f3287d0..825f2250a3 100644 --- a/docs/logging.md +++ b/docs/logging.md @@ -29,9 +29,9 @@ Each host module: └─ simpler_host_log_bind_state(state*) Device logging: - AICPU keeps the device backend - ├─ sim: set_log_level(...) seeds its current level flags - └─ onboard: CANN level is sampled during device init + dev_vlog_* compatibility interface + ├─ sim: bound HostLogger → same state, envelope, and destination + └─ onboard: separate CANN backend sampled during device init ``` One threshold controls `DEBUG / INFO / TIMING / WARN / ERROR`; `NUL` suppresses @@ -59,7 +59,7 @@ src/common/platform/ ├── include/aicpu/device_log.h device backend declarations ├── shared/aicpu/unified_log_device.cpp LOG_* ABI → dev_vlog_* adapter ├── onboard/aicpu/device_log.cpp onboard CANN backend -└── sim/aicpu/device_log.cpp sim AICPU stderr backend +└── sim/aicpu/device_log.cpp dev_vlog_* → bound HostLogger adapter ``` There is no standalone `libsimpler_log.so`. Host consumers compile the two @@ -133,9 +133,11 @@ Machine-readable `[STRACE]` records satisfy that bound. Longer human-readable records are best-effort and may interleave across module boundaries. Blocking and drop accounting for those writes remain part of issue #1792 item 6. -The AICPU `dev_vlog_*` functions remain separate. Sim formats a single stderr -record; onboard forwards through CANN dlog. Folding sim's device logger into -the host backend is tracked separately by issue #1792 item 5. +The AICPU `dev_vlog_*` interface remains source-compatible on both platforms. +Sim implements it as a thin `va_list` adapter into its bound `HostLogger`, so it +shares the live threshold, envelope, destination, and fallback with the other +host-side modules in that process. Only real-silicon AICPU retains a separate +backend, because its records go through CANN dlog rather than a host process. ## Cross-DSO host state @@ -229,16 +231,14 @@ trace/swimlane JSON while leaving event timestamps monotonic and relative. See ### AICPU sim ```text -[DEBUG] func: [file.cpp:line] message -[INFO] func: [file.cpp:line] message -[TIMING] func: [file.cpp:line] message -[WARN] func: [file.cpp:line] message -[ERROR] func: [file.cpp:line] message +[mono_ns=MONOTONIC_NS][T0xTID][LEVEL] func: [file.cpp:line] message ``` -This is still the sim device backend, so it has no host monotonic/tid prefix. -Onboard AICPU uses the CANN dlog format. Device TIMING uses CANN WARN and adds a -`[TIMING]` message tag. +Sim AICPU runs on a host CPU inside the host process and uses the same envelope +and destination as every other bound host module. The `dev_vlog_*` names remain +as the compatibility boundary `unified_log_device.cpp` consumes. Onboard AICPU +uses the CANN dlog format. Device TIMING uses CANN WARN and adds a `[TIMING]` +message tag. ## Configuration flow @@ -250,7 +250,7 @@ Onboard AICPU uses the CANN dlog format. Device TIMING uses CANN WARN and adds a | `_ChipWorker.init()` | Load sim context and host runtime, then bind each module's logger state | `src/common/worker/chip_worker.cpp` | | `simpler_init` | Onboard maps the bound threshold to CANN; attach and take executor binaries | `src/common/platform/{onboard,sim}/host/c_api_shared.cpp` | | Nested host load | Bind generated host orchestration/AICore logger state before entry | runtime maker / sim device runner | -| AICPU init | Snapshot the applicable device threshold | platform AICPU init | +| AICPU init | Sim binds the live host state; onboard snapshots CANN policy | platform AICPU init | The Python level is still sampled during worker initialization. Calling `logger.setLevel(...)` does not itself call the native setter; recreate or @@ -321,6 +321,8 @@ There is no logger build step or logger field in `RuntimeBinaries`. Instead: - `_task_interface`, all host runtimes, sim-context, and sim AICore targets add `host_log.cpp` and `unified_log_host.cpp` to their source lists. +- Sim AICPU targets add `host_log.cpp` while keeping `unified_log_device.cpp`; + the device ABI delegates to HostLogger there. - Host-compiled generated orchestration SOs receive the same sources through `KernelCompiler.get_orchestration_cache_inputs`; those sources therefore participate in the scene-test cache key. @@ -336,7 +338,7 @@ There is no logger build step or logger field in `RuntimeBinaries`. Instead: | Change the user-facing level model | `python/simpler/_log.py` and `docs/testing.md` | | Change host output or STRACE grammar | `src/common/log/host_log.cpp` | | Change the shared-state ABI | `src/common/log/include/common/host_log_state.h` | -| Change sim AICPU output | `src/common/platform/sim/aicpu/device_log.cpp` | +| Change sim AICPU adaptation | `src/common/platform/sim/aicpu/device_log.cpp` | | Change onboard CANN tagging | `src/common/platform/onboard/aicpu/device_log.cpp` | | Add a host logging consumer | compile both host logger sources, include `src/common/log/include`, and bind state during module init | | Add a level | `log_level.h`, `_log.py`, `simpler_setup/log_config.py`, and AICPU `set_log_level` | diff --git a/src/a2a3/platform/sim/aicpu/CMakeLists.txt b/src/a2a3/platform/sim/aicpu/CMakeLists.txt index ecb751f7b4..9917da9ab3 100644 --- a/src/a2a3/platform/sim/aicpu/CMakeLists.txt +++ b/src/a2a3/platform/sim/aicpu/CMakeLists.txt @@ -56,6 +56,7 @@ file(GLOB COMMON_SOURCES CONFIGURE_DEPENDS "${CMAKE_CURRENT_SOURCE_DIR}/../../../../common/platform/sim/aicpu/*.cpp" ) list(APPEND AICPU_SOURCES ${COMMON_SOURCES}) +list(APPEND AICPU_SOURCES "${CMAKE_CURRENT_SOURCE_DIR}/../../../../common/log/host_log.cpp") # Then, collect sources from CUSTOM_SOURCE_DIRS (runtime sources) if(DEFINED CUSTOM_SOURCE_DIRS) diff --git a/src/a2a3/platform/sim/host/device_runner.cpp b/src/a2a3/platform/sim/host/device_runner.cpp index a559d365ee..d676835883 100644 --- a/src/a2a3/platform/sim/host/device_runner.cpp +++ b/src/a2a3/platform/sim/host/device_runner.cpp @@ -204,17 +204,17 @@ int DeviceRunner::ensure_binaries_loaded() { if (!load_sym("set_platform_scope_stats_base", reinterpret_cast(&set_platform_scope_stats_base_func_))) return PTO_RUNTIME_ERR_INTERNAL; - // The AICPU sim SO owns its level flags because it is RTLD_LOCAL. - // Forward the process-wide HostLogger threshold explicitly. + // The AICPU sim SO binds its private HostLogger before the compatibility + // level setter can emit a clock anchor. using SetLogLevelFunc = void (*)(int); SetLogLevelFunc set_log_level_func = nullptr; if (!load_sym("set_log_level", reinterpret_cast(&set_log_level_func))) return PTO_RUNTIME_ERR_INTERNAL; - set_log_level_func(HostLogger::get_instance().level()); using SetHostLogStateFunc = void (*)(SimplerHostLogState *); SetHostLogStateFunc set_host_log_state_func = nullptr; if (!load_sym("set_host_log_state", reinterpret_cast(&set_host_log_state_func))) return PTO_RUNTIME_ERR_INTERNAL; set_host_log_state_func(HostLogger::get_instance().state()); + set_log_level_func(HostLogger::get_instance().level()); aicpu_so_loaded_ = true; LOG_INFO("DeviceRunner(sim): Loaded aicpu_execute from %s", aicpu_so_path_.c_str()); diff --git a/src/a5/platform/sim/aicpu/CMakeLists.txt b/src/a5/platform/sim/aicpu/CMakeLists.txt index 0c8ee16740..1137e74024 100644 --- a/src/a5/platform/sim/aicpu/CMakeLists.txt +++ b/src/a5/platform/sim/aicpu/CMakeLists.txt @@ -54,6 +54,7 @@ file(GLOB COMMON_SOURCES CONFIGURE_DEPENDS "${CMAKE_CURRENT_SOURCE_DIR}/../../../../common/platform/sim/aicpu/*.cpp" ) list(APPEND AICPU_SOURCES ${COMMON_SOURCES}) +list(APPEND AICPU_SOURCES "${CMAKE_CURRENT_SOURCE_DIR}/../../../../common/log/host_log.cpp") # Then, collect sources from CUSTOM_SOURCE_DIRS (runtime sources) if(DEFINED CUSTOM_SOURCE_DIRS) diff --git a/src/a5/platform/sim/host/device_runner.cpp b/src/a5/platform/sim/host/device_runner.cpp index 34c5fd901c..4f1a4c542b 100644 --- a/src/a5/platform/sim/host/device_runner.cpp +++ b/src/a5/platform/sim/host/device_runner.cpp @@ -190,17 +190,17 @@ int DeviceRunner::ensure_binaries_loaded() { if (!load_sym("set_platform_scope_stats_base", reinterpret_cast(&set_platform_scope_stats_base_func_))) return PTO_RUNTIME_ERR_INTERNAL; - // The AICPU sim SO owns its level flags because it is RTLD_LOCAL. - // Forward the process-wide HostLogger threshold explicitly. + // The AICPU sim SO binds its private HostLogger before the compatibility + // level setter can emit a clock anchor. using SetLogLevelFunc = void (*)(int); SetLogLevelFunc set_log_level_func = nullptr; if (!load_sym("set_log_level", reinterpret_cast(&set_log_level_func))) return PTO_RUNTIME_ERR_INTERNAL; - set_log_level_func(HostLogger::get_instance().level()); using SetHostLogStateFunc = void (*)(SimplerHostLogState *); SetHostLogStateFunc set_host_log_state_func = nullptr; if (!load_sym("set_host_log_state", reinterpret_cast(&set_host_log_state_func))) return PTO_RUNTIME_ERR_INTERNAL; set_host_log_state_func(HostLogger::get_instance().state()); + set_log_level_func(HostLogger::get_instance().level()); aicpu_so_loaded_ = true; LOG_INFO("DeviceRunner(sim): Loaded aicpu_execute from %s", aicpu_so_path_.c_str()); diff --git a/src/common/log/host_log.cpp b/src/common/log/host_log.cpp index e1dd88c82a..9fc30d5c65 100644 --- a/src/common/log/host_log.cpp +++ b/src/common/log/host_log.cpp @@ -155,6 +155,7 @@ long host_trace_tid() { struct HostLogFileSink { HostLogFileSink(); + ~HostLogFileSink(); std::mutex mutex; FILE *stream = nullptr; @@ -178,6 +179,18 @@ HostLogFileSink::HostLogFileSink() { (void)pthread_atfork(host_log_sink_before_fork, host_log_sink_after_fork, host_log_sink_after_fork); } +// One sink per DSO that compiles this file, so each holds its own buffered +// stream on the shared per-process log. Closing it here is what puts that +// buffer's tail on disk when the DSO is unloaded: dlclose runs this destructor, +// and a dlopened module's records would otherwise be discarded with its mapping. +// A stream this process did not open belongs to the parent that forked it and +// is left alone, so the parent's copied stdio buffer is never flushed twice. +HostLogFileSink::~HostLogFileSink() { + std::scoped_lock lock(mutex); + if (stream != nullptr && pid == getpid()) (void)std::fclose(stream); + stream = nullptr; +} + // Append one already-formatted record. The <=`PIPE_BUF` single-write rule that // makes a stderr record indivisible neither applies nor is needed here: this file // has exactly one writer process and the sink mutex serializes the writers inside @@ -242,10 +255,7 @@ namespace { // binds the process-owned state. Missing binding is therefore observable as an // absent module stream rather than output filtered at the wrong threshold. SimplerHostLogState g_module_log_state{ - SIMPLER_HOST_LOG_STATE_ABI_VERSION, - sizeof(SimplerHostLogState), - static_cast(LogLevel::NUL), - 0, + SIMPLER_HOST_LOG_STATE_ABI_VERSION, sizeof(SimplerHostLogState), static_cast(LogLevel::NUL), 0, 0, {}, }; int32_t atomic_load_i32(const int32_t *value) { return __atomic_load_n(value, __ATOMIC_ACQUIRE); } diff --git a/src/common/platform/include/aicpu/device_log.h b/src/common/platform/include/aicpu/device_log.h index 37595b88ef..4a478bb71a 100644 --- a/src/common/platform/include/aicpu/device_log.h +++ b/src/common/platform/include/aicpu/device_log.h @@ -14,16 +14,16 @@ * * Layered design: * - Low-level dev_log_*() functions are platform-specific (CANN dlog on - * real hardware, fprintf(stderr,...) in simulation). + * real hardware, the process-owned HostLogger in simulation). * - Onboard fills DEBUG/INFO/WARN/ERROR from CheckLogLevel(AICPU,...); - * simulation fills all flags from the host-provided threshold. + * simulation queries the live threshold in its bound HostLogger state. * - TIMING is a simpler level between INFO and WARN. Both backends gate it * from the host threshold; onboard emits enabled messages through CANN * WARN because CANN has no intermediate level. * * Platform Support: * - a2a3 / a5 : Real hardware with CANN dlog API - * - a2a3sim / a5sim : Host-based simulation using fprintf(stderr,...) + * - a2a3sim / a5sim : Host-based simulation using HostLogger */ #pragma once @@ -44,14 +44,15 @@ #endif // ============================================================================= -// Severity enable flags (defined in platform-specific device_log.cpp) +// Platform-specific severity queries. Sim reads a live bound HostLogger state; +// onboard reads the CANN-derived flags cached by its platform backend. // ============================================================================= -extern bool g_is_log_enable_debug; -extern bool g_is_log_enable_info; -extern bool g_is_log_enable_timing; -extern bool g_is_log_enable_warn; -extern bool g_is_log_enable_error; +bool is_log_enable_debug(); +bool is_log_enable_info(); +bool is_log_enable_timing(); +bool is_log_enable_warn(); +bool is_log_enable_error(); // ============================================================================= // Configuration setters (called by AICPU kernel init from KernelArgs) @@ -59,7 +60,7 @@ extern bool g_is_log_enable_error; // Levels use Python-compatible thresholds: DEBUG=10, INFO=20, TIMING=25, // WARN=30, ERROR=40, NUL=60. Onboard applies the threshold to TIMING while -// CANN owns its native levels; simulation applies it to the full flag table. +// CANN owns its native levels; simulation updates its bound HostLogger state. extern "C" void set_log_level(int level); // Hand the process-owned host-log state to the simulation AICPU backend, which @@ -78,11 +79,9 @@ int bind_orchestration_host_log_state(void *handle, const char **error); // Platform-specific logging functions (low-level layer) // // va_list primitives used by the unified_log_* adapter to forward a caller's -// variadic args. Both backends format a whole record into one stack buffer and -// emit it in a single call: sim writes it with one write(2), kept under -// PIPE_BUF so concurrent threads / forked workers on a shared stderr never -// interleave partial records; onboard buffers because CANN's dlog API has no -// va_list variant. Caller owns va_start/va_end. +// variadic args. Sim delegates formatting and destination selection to +// HostLogger; onboard buffers because CANN's dlog API has no va_list variant. +// Caller owns va_start/va_end. // ============================================================================= #include @@ -94,14 +93,8 @@ void dev_vlog_warn(const char *func, const char *fmt, va_list args); void dev_vlog_error(const char *func, const char *fmt, va_list args); // ============================================================================= -// Helper Functions +// Initialization // ============================================================================= -inline bool is_log_enable_debug() { return g_is_log_enable_debug; } -inline bool is_log_enable_info() { return g_is_log_enable_info; } -inline bool is_log_enable_timing() { return g_is_log_enable_timing; } -inline bool is_log_enable_warn() { return g_is_log_enable_warn; } -inline bool is_log_enable_error() { return g_is_log_enable_error; } - // Initialize log switch (platform-specific implementation) void init_log_switch(); diff --git a/src/common/platform/onboard/aicpu/device_log.cpp b/src/common/platform/onboard/aicpu/device_log.cpp index 7b47cbac4f..44eb946693 100644 --- a/src/common/platform/onboard/aicpu/device_log.cpp +++ b/src/common/platform/onboard/aicpu/device_log.cpp @@ -24,11 +24,23 @@ #include #include +namespace { bool g_is_log_enable_debug = false; bool g_is_log_enable_info = false; bool g_is_log_enable_timing = false; bool g_is_log_enable_warn = false; bool g_is_log_enable_error = false; +} // namespace + +bool is_log_enable_debug() { return g_is_log_enable_debug; } + +bool is_log_enable_info() { return g_is_log_enable_info; } + +bool is_log_enable_timing() { return g_is_log_enable_timing; } + +bool is_log_enable_warn() { return g_is_log_enable_warn; } + +bool is_log_enable_error() { return g_is_log_enable_error; } void init_log_switch() { g_is_log_enable_debug = CheckLogLevel(AICPU, DLOG_DEBUG); diff --git a/src/common/platform/shared/aicpu/unified_log_device.cpp b/src/common/platform/shared/aicpu/unified_log_device.cpp index 34398f2c79..aa1c139c33 100644 --- a/src/common/platform/shared/aicpu/unified_log_device.cpp +++ b/src/common/platform/shared/aicpu/unified_log_device.cpp @@ -13,11 +13,12 @@ * @brief Unified logging - Device implementation. * * Forwards the unified C ABI to dev_vlog_* primitives via va_list — no - * intermediate vsnprintf-to-buffer round-trip in this layer. On sim, - * dev_vlog_* is a single vfprintf (buffer-free); on onboard, it still - * buffers internally because CANN's dlog has no va_list variant. + * intermediate vsnprintf-to-buffer round-trip in this layer. Sim dev_vlog_* + * delegates to the bound HostLogger; onboard buffers internally because + * CANN's dlog has no va_list variant. * - * Level flags come from device_log.cpp's globals (set at init time). + * Severity queries are platform-specific: sim reads the live bound threshold, + * while onboard reads the CANN-derived flags initialized by device_log.cpp. */ #include "common/unified_log.h" diff --git a/src/common/platform/sim/aicpu/device_log.cpp b/src/common/platform/sim/aicpu/device_log.cpp index 8d89483766..39e7ab85ce 100644 --- a/src/common/platform/sim/aicpu/device_log.cpp +++ b/src/common/platform/sim/aicpu/device_log.cpp @@ -12,118 +12,82 @@ * @file device_log.cpp (sim) * @brief Simulation Platform Log Implementation * - * Level flags are populated by host via set_log_level() at AICPU kernel init - * (see kernel.cpp / aicpu_executor.cpp); this file does not read env vars. + * The process-owned HostLogger state is bound by the sim host before AICPU + * execution begins; this file does not read env vars. */ #include "aicpu/device_log.h" #include "common/host_log_binding.h" +#include "host_log.h" -#include #include -#include -#include -#include - -// ============================================================================= -// Level enable flags (mutated by the setter below) -// ============================================================================= - -bool g_is_log_enable_debug = false; -bool g_is_log_enable_info = false; -bool g_is_log_enable_timing = true; -bool g_is_log_enable_warn = true; -bool g_is_log_enable_error = true; namespace { SimplerHostLogState *g_host_log_state = nullptr; } +bool is_log_enable_debug() { return HostLogger::get_instance().is_enabled(simpler::log::LogLevel::DEBUG); } + +bool is_log_enable_info() { return HostLogger::get_instance().is_enabled(simpler::log::LogLevel::INFO); } + +bool is_log_enable_timing() { return HostLogger::get_instance().is_enabled(simpler::log::LogLevel::TIMING); } + +bool is_log_enable_warn() { return HostLogger::get_instance().is_enabled(simpler::log::LogLevel::WARN); } + +bool is_log_enable_error() { return HostLogger::get_instance().is_enabled(simpler::log::LogLevel::ERROR); } + // ============================================================================= // Setters (called by AICPU init from KernelArgs) // ============================================================================= extern "C" void set_log_level(int level) { - g_is_log_enable_debug = level <= 10; - g_is_log_enable_info = level <= 20; - g_is_log_enable_timing = level <= 25; - g_is_log_enable_warn = level <= 30; - g_is_log_enable_error = level <= 40; + if (g_host_log_state != nullptr && simpler::log::is_valid_level(level)) { + HostLogger::get_instance().set_level(static_cast(level)); + } } -extern "C" void set_host_log_state(SimplerHostLogState *state) { g_host_log_state = state; } +extern "C" void set_host_log_state(SimplerHostLogState *state) { + if (HostLogger::get_instance().bind_state(state) == 0) g_host_log_state = state; +} int bind_orchestration_host_log_state(void *handle, const char **error) { return simpler::log::bind_loaded_host_log_state(handle, g_host_log_state, error); } // ============================================================================= -// init_log_switch: sim respects host-pushed config. The no-op entry point is -// retained for ABI compatibility with onboard, where it queries CANN dlog. +// init_log_switch: the sim threshold lives in the bound host-log state. The +// no-op entry point shares the platform interface with the onboard CANN query. // ============================================================================= void init_log_switch() { - // Sim has no env / dlog to consult. Defaults already applied at static - // init; host overrides via set_log_level() before this - // is called. + // Sim has no CANN log switch to query. } // ============================================================================= // Low-level dev_log_* / dev_vlog_* // -// Each record "[TAG] func: body\n" is formatted into a single stack buffer and -// emitted with one write(). The buffer caps the record at 2048 bytes, below -// Linux PIPE_BUF (4096), so a record is delivered atomically when stderr is a -// pipe — concurrent AICPU sim threads and forked chip workers sharing stderr -// never interleave partial records. +// The shared AICPU adapter retains this va_list interface on both platforms. +// HostLogger owns the sim envelope, threshold and configured output; onboard +// supplies the corresponding CANN-backed definitions in its platform +// implementation. // ============================================================================= -namespace { - -void emit_record(const char *level_tag, const char *func, const char *fmt, va_list args) { - char buffer[2048]; - constexpr size_t kNewlineSlot = 1; - constexpr size_t kBodyLimit = sizeof(buffer) - kNewlineSlot; - - int prefix = snprintf(buffer, sizeof(buffer), "[%s] %s: ", level_tag, func); - size_t len = (prefix < 0) ? 0 : static_cast(prefix); - if (len > kBodyLimit) { - len = kBodyLimit; // prefix filled the buffer; reserve the newline slot - } - - int body = vsnprintf(buffer + len, sizeof(buffer) - len, fmt, args); - if (body > 0) { - len += static_cast(body); - if (len > kBodyLimit) { - len = kBodyLimit; // body truncated; reserve the newline slot - } - } - - buffer[len++] = '\n'; - // On a pipe this transfers the whole record (<= PIPE_BUF) in one atomic - // call; the loop only iterates for a non-pipe stderr (regular file, socket) - // where write(2) may be interrupted or short, and must not leave a record - // without its terminating newline. - for (size_t off = 0; off < len;) { - ssize_t written = write(STDERR_FILENO, buffer + off, len - off); - if (written < 0) { - if (errno == EINTR) { - continue; - } - break; // nothing the device-log backend can do on a hard failure - } - off += static_cast(written); - } +void dev_vlog_debug(const char *func, const char *fmt, va_list args) { + HostLogger::get_instance().vlog(simpler::log::LogLevel::DEBUG, func, fmt, args); } -} // namespace - -void dev_vlog_debug(const char *func, const char *fmt, va_list args) { emit_record("DEBUG", func, fmt, args); } - -void dev_vlog_info(const char *func, const char *fmt, va_list args) { emit_record("INFO", func, fmt, args); } +void dev_vlog_info(const char *func, const char *fmt, va_list args) { + HostLogger::get_instance().vlog(simpler::log::LogLevel::INFO, func, fmt, args); +} -void dev_vlog_timing(const char *func, const char *fmt, va_list args) { emit_record("TIMING", func, fmt, args); } +void dev_vlog_timing(const char *func, const char *fmt, va_list args) { + HostLogger::get_instance().vlog(simpler::log::LogLevel::TIMING, func, fmt, args); +} -void dev_vlog_warn(const char *func, const char *fmt, va_list args) { emit_record("WARN", func, fmt, args); } +void dev_vlog_warn(const char *func, const char *fmt, va_list args) { + HostLogger::get_instance().vlog(simpler::log::LogLevel::WARN, func, fmt, args); +} -void dev_vlog_error(const char *func, const char *fmt, va_list args) { emit_record("ERROR", func, fmt, args); } +void dev_vlog_error(const char *func, const char *fmt, va_list args) { + HostLogger::get_instance().vlog(simpler::log::LogLevel::ERROR, func, fmt, args); +} diff --git a/tests/ut/cpp/CMakeLists.txt b/tests/ut/cpp/CMakeLists.txt index 349362b780..7aefab1a97 100644 --- a/tests/ut/cpp/CMakeLists.txt +++ b/tests/ut/cpp/CMakeLists.txt @@ -1112,6 +1112,40 @@ target_link_libraries(test_host_log_unbound PRIVATE ) add_test(NAME test_host_log_unbound COMMAND test_host_log_unbound) +# A dlopened module that compiles the host logger owns a private buffered +# stream on the shared log file, so unloading it must not strand that buffer. +add_library(test_host_log_unload_consumer SHARED + common/test_host_log_unload_consumer.cpp + ${HOST_LOG_TEST_SOURCES} +) +target_include_directories(test_host_log_unload_consumer PRIVATE + ${SIMPLER_LOG_DIR} + ${SIMPLER_LOG_DIR}/include +) +target_link_libraries(test_host_log_unload_consumer PRIVATE pthread) + +add_executable(test_host_log_dso_unload + common/test_host_log_dso_unload.cpp + ${HOST_LOG_TEST_SOURCES} +) +target_compile_definitions(test_host_log_dso_unload PRIVATE + TEST_HOST_LOG_UNLOAD_CONSUMER_PATH="$" +) +target_include_directories(test_host_log_dso_unload PRIVATE + ${GTEST_INCLUDE_DIRS} + ${SIMPLER_LOG_DIR} + ${SIMPLER_LOG_DIR}/include +) +target_link_libraries(test_host_log_dso_unload PRIVATE + ${GTEST_MAIN_LIB} + ${GTEST_LIB} + ${CMAKE_DL_LIBS} + pthread +) +add_dependencies(test_host_log_dso_unload test_host_log_unload_consumer) +add_test(NAME test_host_log_dso_unload COMMAND test_host_log_dso_unload) +set_tests_properties(test_host_log_dso_unload PROPERTIES LABELS "no_hardware") + set(COMMON_PLATFORM_DIR ${CMAKE_SOURCE_DIR}/../../../src/common/platform) function(add_device_phase_capture_test name host_strace device_strace expected) add_executable(${name} @@ -1167,12 +1201,13 @@ target_link_libraries(test_onboard_device_log_level PRIVATE add_test(NAME test_onboard_device_log_level COMMAND test_onboard_device_log_level) set_tests_properties(test_onboard_device_log_level PROPERTIES LABELS "no_hardware") -# Sim device-log record atomicity: concurrent threads and forked workers must -# not interleave partial records on the shared stderr. Pure host code — compile -# the sim backend alongside the test; no CANN, no hardware. +# Sim device logging uses the bound HostLogger threshold, envelope, and output. +# Pure host code — compile the sim adapter and HostLogger alongside the test; +# no CANN, no hardware. add_executable(test_sim_device_log common/test_sim_device_log.cpp ${COMMON_PLATFORM_DIR}/sim/aicpu/device_log.cpp + ${SIMPLER_LOG_DIR}/host_log.cpp ) target_include_directories(test_sim_device_log PRIVATE ${GTEST_INCLUDE_DIRS} diff --git a/tests/ut/cpp/common/test_host_log_dso_unload.cpp b/tests/ut/cpp/common/test_host_log_dso_unload.cpp new file mode 100644 index 0000000000..6ef83f7c83 --- /dev/null +++ b/tests/ut/cpp/common/test_host_log_dso_unload.cpp @@ -0,0 +1,78 @@ +/* + * Copyright (c) PyPTO Contributors. + * This program is free software, you can redistribute it and/or modify it under the terms and conditions of + * CANN Open Software License Agreement Version 2.0 (the "License"). + * Please refer to the License for details. You may not use this file except in compliance with the License. + * THIS SOFTWARE IS PROVIDED ON AN "AS IS" BASIS, WITHOUT WARRANTIES OF ANY KIND, EITHER EXPRESS OR IMPLIED, + * INCLUDING BUT NOT LIMITED TO NON-INFRINGEMENT, MERCHANTABILITY, OR FITNESS FOR A PARTICULAR PURPOSE. + * See LICENSE in the root of the software repository for the full text of the License. + * ----------------------------------------------------------------------------------------------------------- + */ + +// Every DSO that compiles the host logger owns a private buffered stream on the +// shared per-process log file. This pins the consequence: unloading such a +// module must put that stream's tail on disk, because dlclose discards the +// mapping the buffer lives in. DeviceRunner::unload_executor_binaries() does +// exactly this to the sim AICPU SO on every teardown. + +#include +#include + +#include +#include + +#include + +#include "common/host_log_state.h" +#include "host_log.h" + +using simpler::log::LogLevel; + +namespace { + +size_t count_occurrences(const std::string &haystack, const std::string &needle) { + size_t total = 0; + for (size_t at = haystack.find(needle); at != std::string::npos; at = haystack.find(needle, at + needle.size())) { + ++total; + } + return total; +} + +} // namespace + +TEST(HostLogUnloadTest, UnloadedModuleLeavesNoRecordsInItsPrivateBuffer) { + constexpr int kRecords = 200; + + char directory_template[] = "/tmp/simpler-host-log-unload-XXXXXX"; + char *directory = mkdtemp(directory_template); + ASSERT_NE(directory, nullptr); + + HostLogger &owner = HostLogger::get_instance(); + owner.set_level(LogLevel::DEBUG); + owner.set_log_directory(directory); + + void *handle = dlopen(TEST_HOST_LOG_UNLOAD_CONSUMER_PATH, RTLD_NOW | RTLD_LOCAL); + ASSERT_NE(handle, nullptr) << dlerror(); + + dlerror(); + auto bind = reinterpret_cast(dlsym(handle, "test_host_log_unload_bind")); + ASSERT_NE(bind, nullptr) << dlerror(); + dlerror(); + auto emit = reinterpret_cast(dlsym(handle, "test_host_log_unload_emit")); + ASSERT_NE(emit, nullptr) << dlerror(); + + ASSERT_EQ(bind(owner.state()), 0); + emit(kRecords); + ASSERT_EQ(dlclose(handle), 0); + + const std::string path = std::string(directory) + "/host." + std::to_string(static_cast(getpid())) + ".log"; + std::ifstream input(path); + ASSERT_TRUE(input.good()); + const std::string contents((std::istreambuf_iterator(input)), std::istreambuf_iterator()); + input.close(); + + EXPECT_EQ(count_occurrences(contents, "] unloaded_module: record="), static_cast(kRecords)); + + EXPECT_EQ(unlink(path.c_str()), 0); + EXPECT_EQ(rmdir(directory), 0); +} diff --git a/tests/ut/cpp/common/test_host_log_unload_consumer.cpp b/tests/ut/cpp/common/test_host_log_unload_consumer.cpp new file mode 100644 index 0000000000..59a703a63d --- /dev/null +++ b/tests/ut/cpp/common/test_host_log_unload_consumer.cpp @@ -0,0 +1,28 @@ +/* + * Copyright (c) PyPTO Contributors. + * This program is free software, you can redistribute it and/or modify it under the terms and conditions of + * CANN Open Software License Agreement Version 2.0 (the "License"). + * Please refer to the License for details. You may not use this file except in compliance with the License. + * THIS SOFTWARE IS PROVIDED ON AN "AS IS" BASIS, WITHOUT WARRANTIES OF ANY KIND, EITHER EXPRESS OR IMPLIED, + * INCLUDING BUT NOT LIMITED TO NON-INFRINGEMENT, MERCHANTABILITY, OR FITNESS FOR A PARTICULAR PURPOSE. + * See LICENSE in the root of the software repository for the full text of the License. + * ----------------------------------------------------------------------------------------------------------- + */ + +// Stands in for a dlopened module that compiles the host logger and is unloaded +// while the process continues — the sim AICPU SO, the sim AICore SO, and the +// generated orchestration SO are all this shape. + +#include "host_log.h" + +extern "C" __attribute__((visibility("default"))) int test_host_log_unload_bind(SimplerHostLogState *state) { + return HostLogger::get_instance().bind_state(state); +} + +extern "C" __attribute__((visibility("default"))) void test_host_log_unload_emit(int count) { + for (int index = 0; index < count; ++index) { + // INFO rides this module's own stdio buffer: severity below WARN selects + // no write-through, which is what leaves a tail to lose at unload. + HostLogger::get_instance().log(simpler::log::LogLevel::INFO, "unloaded_module", "record=%d", index); + } +} diff --git a/tests/ut/cpp/common/test_sim_device_log.cpp b/tests/ut/cpp/common/test_sim_device_log.cpp index da3fdc515c..25c512a182 100644 --- a/tests/ut/cpp/common/test_sim_device_log.cpp +++ b/tests/ut/cpp/common/test_sim_device_log.cpp @@ -9,15 +9,13 @@ * ----------------------------------------------------------------------------------------------------------- */ -// Sim device-log atomicity: every dev_vlog_* call emits exactly one intact -// physical line, even when many AICPU sim threads or forked chip workers write -// the shared stderr concurrently. A record no larger than the pipe's PIPE_BUF -// reaches it in one indivisible write(2), so it cannot interleave with another -// writer. The records here are ~30 bytes, inside even the portable -// _POSIX_PIPE_BUF floor of 512 that macOS uses. +// Sim AICPU records use the bound HostLogger threshold and host envelope. The +// short records below also stay intact when many threads or forked chip workers +// share the stderr fallback. #include #include +#include #include #include #include @@ -31,13 +29,24 @@ #include #include "aicpu/device_log.h" +#include "common/host_log_state.h" +#include "common/log_level.h" +#include "host_log.h" namespace { constexpr const char *kTags[] = {"DEBUG", "INFO", "TIMING", "WARN", "ERROR"}; -// dev_vlog_* gate on nothing (the unified_log_* adapter owns level filtering), -// so these thin wrappers always emit. level_idx selects the backend under test. +SimplerHostLogState g_log_state{ + SIMPLER_HOST_LOG_STATE_ABI_VERSION, + sizeof(SimplerHostLogState), + static_cast(simpler::log::LogLevel::ERROR), + 0, + 0, + {}, +}; + +// level_idx selects the compatibility entry point under test. void emit(int level_idx, const char *func, const char *fmt, ...) { va_list ap; va_start(ap, fmt); @@ -65,6 +74,15 @@ std::string record(int level_idx, const char *func, const std::string &body) { return std::string("[") + kTags[level_idx % 5] + "] " + func + ": " + body; } +void bind_level(simpler::log::LogLevel level) { + g_log_state.threshold = static_cast(level); + g_log_state.clock_anchor_pid = static_cast(getpid()); + g_log_state.log_directory_bound = 0; + g_log_state.log_directory[0] = '\0'; + set_host_log_state(&g_log_state); + set_log_level(static_cast(level)); +} + // Redirect stderr onto a fresh pipe, drained from the moment it is installed. // // A pipe holds a bounded amount of unread data — 16 KiB on macOS, 64 KiB on @@ -74,10 +92,8 @@ std::string record(int level_idx, const char *func, const std::string &body) { // runs concurrently so the writers never block, whatever they emit. // // The reader owns the buffer through a shared_ptr, so returning `Capture` by -// value cannot leave the thread writing into a moved-from string. `fork` is safe -// alongside it because the record path allocates nothing: it formats into a -// stack buffer and calls write(2), so a child cannot deadlock on a malloc lock -// this thread happened to hold. +// value cannot leave the thread writing into a moved-from string. No logger +// producer is active at the fork boundary in the process tests below. struct Capture { int read_fd = -1; int saved_stderr = -1; @@ -123,8 +139,13 @@ void expect_intact(const std::string &captured, std::multiset expec while (start < captured.size()) { size_t nl = captured.find('\n', start); ASSERT_NE(nl, std::string::npos) << "record missing terminating newline"; - std::string line = captured.substr(start, nl - start); - auto it = expected.find(line); + const std::string line = captured.substr(start, nl - start); + const size_t monotonic_end = line.find("]["); + ASSERT_NE(monotonic_end, std::string::npos) << "host envelope missing from: '" << line << "'"; + const size_t thread_end = line.find("][", monotonic_end + 2); + ASSERT_NE(thread_end, std::string::npos) << "host envelope missing from: '" << line << "'"; + const std::string payload = line.substr(thread_end + 1); + auto it = expected.find(payload); ASSERT_NE(it, expected.end()) << "torn or unexpected record: '" << line << "'"; expected.erase(it); start = nl + 1; @@ -134,10 +155,63 @@ void expect_intact(const std::string &captured, std::multiset expec } // namespace +TEST(SimDeviceLogTest, UsesHostEnvelopeAndLiveBoundThreshold) { + bind_level(simpler::log::LogLevel::ERROR); + + testing::internal::CaptureStderr(); + emit(3, "worker", "warn-hidden"); + emit(4, "worker", "error-visible"); + std::string captured = testing::internal::GetCapturedStderr(); + + EXPECT_EQ(captured.find("warn-hidden"), std::string::npos); + EXPECT_NE(captured.find("][ERROR] worker: error-visible\n"), std::string::npos); + EXPECT_NE(captured.find("[mono_ns="), std::string::npos); + EXPECT_NE(captured.find("][T0x"), std::string::npos); + + // The adapter reads the shared state on every query; no second push into a + // private sim flag table is required. + g_log_state.threshold = static_cast(simpler::log::LogLevel::WARN); + testing::internal::CaptureStderr(); + emit(3, "worker", "warn-visible"); + captured = testing::internal::GetCapturedStderr(); + EXPECT_NE(captured.find("][WARN] worker: warn-visible\n"), std::string::npos); +} + +TEST(SimDeviceLogTest, BoundLogDirectoryTakesSimRecordsInsteadOfStderr) { + char directory_template[] = "/tmp/simpler-sim-device-log-XXXXXX"; + char *directory = mkdtemp(directory_template); + ASSERT_NE(directory, nullptr); + + bind_level(simpler::log::LogLevel::DEBUG); + HostLogger::get_instance().set_log_directory(directory); + + testing::internal::CaptureStderr(); + emit(4, "chip_worker", "device-record-to-file"); + const std::string captured = testing::internal::GetCapturedStderr(); + EXPECT_EQ(captured.find("device-record-to-file"), std::string::npos) + << "a bound directory is the logger's destination for device records too"; + + // The destination is a property of the logger, so a sim device record lands + // in the same per-process file as every host record. An ERROR is written + // through rather than buffered, so it is on disk by the time this reads. + const std::string path = std::string(directory) + "/host." + std::to_string(static_cast(getpid())) + ".log"; + std::ifstream input(path); + ASSERT_TRUE(input.good()); + const std::string contents((std::istreambuf_iterator(input)), std::istreambuf_iterator()); + input.close(); + EXPECT_NE(contents.find("][ERROR] chip_worker: device-record-to-file\n"), std::string::npos); + + g_log_state.log_directory_bound = 0; + g_log_state.log_directory[0] = '\0'; + EXPECT_EQ(unlink(path.c_str()), 0); + EXPECT_EQ(rmdir(directory), 0); +} + TEST(SimDeviceLogTest, MultiThreadedRecordsStayIntact) { constexpr int kThreads = 4; constexpr int kPerThread = 200; + bind_level(simpler::log::LogLevel::DEBUG); std::multiset expected; for (int t = 0; t < kThreads; ++t) { for (int i = 0; i < kPerThread; ++i) { @@ -169,6 +243,7 @@ TEST(SimDeviceLogTest, ForkedProcessesEmitWholeRecords) { constexpr int kChildren = 8; constexpr int kPerChild = 100; + bind_level(simpler::log::LogLevel::DEBUG); std::multiset expected; for (int c = 0; c < kChildren; ++c) { for (int i = 0; i < kPerChild; ++i) { @@ -185,6 +260,7 @@ TEST(SimDeviceLogTest, ForkedProcessesEmitWholeRecords) { pid_t pid = fork(); ASSERT_GE(pid, 0); if (pid == 0) { + g_log_state.clock_anchor_pid = static_cast(getpid()); for (int i = 0; i < kPerChild; ++i) { emit(c, "chip_worker", "c%d-r%03d", c, i); } @@ -214,6 +290,7 @@ TEST(SimDeviceLogTest, WritersOutrunASmallPipeWithoutDeadlocking) { constexpr int kChildren = 4; constexpr int kPerChild = 400; + bind_level(simpler::log::LogLevel::DEBUG); std::multiset expected; for (int c = 0; c < kChildren; ++c) { for (int i = 0; i < kPerChild; ++i) { @@ -235,6 +312,7 @@ TEST(SimDeviceLogTest, WritersOutrunASmallPipeWithoutDeadlocking) { pid_t pid = fork(); ASSERT_GE(pid, 0); if (pid == 0) { + g_log_state.clock_anchor_pid = static_cast(getpid()); for (int i = 0; i < kPerChild; ++i) { emit(c, "chip_worker", "c%d-r%03d", c, i); }