diff --git a/CHANGELIST.md b/CHANGELIST.md index eb1c6740d2..332c958208 100644 --- a/CHANGELIST.md +++ b/CHANGELIST.md @@ -313,6 +313,7 @@ Z3 SMT solver bindings as a dynamic module, dasLLVM-style. - **The daspkg macos nightly fixed** (#3664, #3665) - Homebrew bison 3.x (stock 2.3 cannot parse the grammar), dasLLVM enabled so the `-exe` .app-bundle tests run - **Dagor config build support** (#3594) - **The release audit** (#3773, #3782) - `utils/internal/test-release`: the compile phase proves every shipped example and tutorial against the bundle's own binary (803 targets), and the utils phase exercises every shipped tool from the extracted bundle alone (exit code plus output only a working run prints). The RC1 sweep's structural yield: `examples/` and `tutorials/` install as whole directories, so 31 silently-dropped files ship again; three ship-defects fixed; package examples moved to their package repos +- **A hung sweep names the program that hung** (#3949) - dastest prints a timestamped `run N/M: ` before every program of a sequential sweep and `worker K starts: ` before every isolated batch, on stderr, flushed at once and printed under `--failures-only` too; the `run_tests_*` cmake targets carry `USES_TERMINAL`, so Ninja streams the sweep's output instead of holding it until the command ends - a lane cancelled mid-hang keeps its last line instead of losing everything the sweep printed. The first hang those lines named was `tests/debug_agent/test_callback_threadlock.das`: its hook waited on a thread that had yet to create its context, while the tick holds the agent registry every context creation needs - `DapiDebugAgent` carries the contract, and the test now proves the callback/pinvoke serialization from one thread with the new `try_invoke_in_context`, the non-blocking `invoke_in_context` that returns false, running nothing, while another thread holds the context lock - **Bounded apt on ubuntu runners** (#3785) - every workflow apt site goes through `ci/apt_install.sh`: the degrading Azure mirror swapped for the public archive (mirrorlist included), capped fetches, retried update - the worst case becomes a loud failure in minutes instead of a silent hours-long hang ### Examples and Tutorials diff --git a/daslib/ARCHITECTURE.md b/daslib/ARCHITECTURE.md index 46eef05630..97fe1f9703 100644 --- a/daslib/ARCHITECTURE.md +++ b/daslib/ARCHITECTURE.md @@ -136,6 +136,13 @@ Three companions carry a concern each; a section number is unique across all fou - **The debugger-ready query uses an explicit pinvoke** - generated `apply_in_context` verification would acquire the agent registry while holding the context mutex, opposite to the debugger tick's registry-to-context order. +- **A hook never waits on a thread that has yet to create a context** - the tick holds the + agent registry (`g_DebugAgentMutex`, `src/runtime/context.cpp`) for the whole callback, and + every `Context` construction walks that registry for `onCreateContext`, so a `new_thread` + started while a hook blocks cannot begin. `try_invoke_in_context` is the non-blocking attempt + on the context mutex - false while a hook runs - so the threadlock test proves the + callback/pinvoke serialization from one thread, with no timing window and no thread started + under a blocked hook. ### 24.2 Debugger worker startup {#debugger-worker-startup} diff --git a/daslib/debugger.das b/daslib/debugger.das index 2688d7a2d4..fc65829e0d 100644 --- a/daslib/debugger.das +++ b/daslib/debugger.das @@ -10,6 +10,13 @@ require debugapi public require daslib/rtti public +//! Every hook runs under the process-wide agent registry lock, and so does every context +//! creation (`onCreateContext` walks the registry). A hook therefore never waits on another +//! thread that has yet to create a context - `new_thread`, a fresh `Context` - or the process +//! deadlocks. A hook also runs under its own context's mutex, the same one `invoke_in_context` +//! takes, so a callback and a pinvoke into the agent context never overlap; +//! `try_invoke_in_context` is the non-blocking form - it returns false, running nothing, +//! while that mutex is held. class DapiDebugAgent { def abstract onInstall(agent : DebugAgent?) : void def abstract onUninstall(agent : DebugAgent?) : void diff --git a/dastest/dastest.das b/dastest/dastest.das index 35dde4674a..1be2cf0ff5 100644 --- a/dastest/dastest.das +++ b/dastest/dastest.das @@ -299,6 +299,7 @@ def private run_iso_batch(input : IsoInput#; t : int; perTestTimeout : float; ou // Batch timeout: per-test budget scaled by batch size (<=0 means none). let batchTimeout = perTestTimeout <= 0.0 ? perTestTimeout : perTestTimeout * float(nFiles) var br : BatchRun + log::started("worker {t + 1} starts: {join(input.uris, " ")}") run_iso_subprocess("{input.batchCmd}{widx}", batchTimeout, br) let k = min(length(br.results), nFiles) // Reported files (a prefix of the batch). The per-file JSON is authoritative, @@ -593,10 +594,13 @@ def main() : int { // nolint:STYLE037,STYLE038 - CLI dispatch, one arm per mode } elif (!empty(deser_file)) { res = deserialize_path(ctx, files, deser_file) } elif (!isolatedMode) { + var fileIndex = 0 for (file in files) { let uri = ctx.uriPaths ? file_name_to_uri(file) : file let fileTime = ref_time_ticks() currentTestFile = file + fileIndex ++ + log::started("run {fileIndex}/{length(files)}: {uri}") let status = suite::test_file(file, ctx) let fileDt = get_time_nsec(fileTime) / 1000 if (status.errors + status.failed == 0) { diff --git a/dastest/log.das b/dastest/log.das index b22cd44e84..6bfec3e696 100644 --- a/dastest/log.das +++ b/dastest/log.das @@ -6,6 +6,7 @@ module log shared require daslib/rtti require uriparser require strings +require daslib/fio require daslib/ansi_colors public @@ -27,6 +28,15 @@ def info(msg : string | #) { } } +//! a timestamped progress line that must survive the process dying right after it: printed in +//! every mode, --failures-only included, on stderr so a machine-read stdout (--bench-format +//! json, the isolated result protocol) stays clean, and flushed at once - a hung sweep's log +//! then ends with the program that hung and when it started, not with silence +def started(msg : string | #) { + fwrite(fstderr(), "{iso8601_now()} {msg}\n") + fflush(fstderr()) +} + //! prints a colored line with the newline outside the color wrap, so the closing reset //! escape can never land at the head of the next stdout line (it corrupts machine-read diff --git a/doc/reflections/das2rst.das b/doc/reflections/das2rst.das index 398b13a9b9..aeed88d1b8 100644 --- a/doc/reflections/das2rst.das +++ b/doc/reflections/das2rst.das @@ -414,7 +414,7 @@ def document_module_debugapi(_root : string) { var mod = get_module("debugapi") var groups <- array( group_by_regex("Agent lifecycle", mod, %regex~(fork_debug_agent_context|install_debug_agent|install_debug_agent_thread_local|install_new_debug_agent|install_new_thread_local_debug_agent|has_debug_agent_context|get_debug_agent_context|delete_debug_agent_context|is_in_debug_agent_creation|lock_debug_agent)$%%), - group_by_regex("Cross-context invocation", mod, %regex~(invoke_in_context|invoke_debug_agent_method|invoke_debug_agent_function)$%%), + group_by_regex("Cross-context invocation", mod, %regex~(invoke_in_context|try_invoke_in_context|invoke_debug_agent_method|invoke_debug_agent_function)$%%), group_by_regex("Agent construction", mod, %regex~(make_debug_agent|make_data_walker|make_stack_walker)$%%), group_by_regex("Agent tick and state collection", mod, %regex~(tick_debug_agent|collect_debug_agent_state|on_breakpoints_reset|report_context_state|debug_agent_command|debugger_stop_requested|debugger_thread_context_ready)$%%), group_by_regex("Instrumentation", mod, %regex~(instrument_node|instrument_function|instrument_all_functions|instrument_all_functions_thread_local|instrument_context_allocations|clear_instruments|set_single_step)$%%), diff --git a/doc/source/stdlib/handmade/function-debugapi-try_invoke_in_context-0x3b138017b43557c8.rst b/doc/source/stdlib/handmade/function-debugapi-try_invoke_in_context-0x3b138017b43557c8.rst new file mode 100644 index 0000000000..899bebddc8 --- /dev/null +++ b/doc/source/stdlib/handmade/function-debugapi-try_invoke_in_context-0x3b138017b43557c8.rst @@ -0,0 +1 @@ +The non-blocking `invoke_in_context`: tries the target context's lock instead of waiting on it. Returns `true` once the call ran, `false` - running nothing - when another thread holds that context, a debug-agent hook for instance. Same arguments as `invoke_in_context` by function name, up to 10 extra arguments; the target function must be marked `[export, pinvoke]`. diff --git a/include/daScript/simulate/aot_builtin_debugger.h b/include/daScript/simulate/aot_builtin_debugger.h index 5ef7aecf8e..eb8f4542dd 100644 --- a/include/daScript/simulate/aot_builtin_debugger.h +++ b/include/daScript/simulate/aot_builtin_debugger.h @@ -18,6 +18,7 @@ namespace das { const TBlock & blk, Context * context, LineInfoArg * at ); DAS_API vec4f pinvoke_impl ( Context & context, SimNode_CallBase * call, vec4f * args ); + DAS_API vec4f try_pinvoke_impl ( Context & context, SimNode_CallBase * call, vec4f * args ); DAS_API vec4f pinvoke_impl2 ( Context & context, SimNode_CallBase * call, vec4f * args ); DAS_API vec4f pinvoke_impl3 ( Context & context, SimNode_CallBase * call, vec4f * args ); DAS_API vec4f invokeInDebugAgent ( Context & context, SimNode_CallBase * call, vec4f * args ); diff --git a/src/builtin/module_builtin_debugger.cpp b/src/builtin/module_builtin_debugger.cpp index fd4ca0a27a..15898a9599 100644 --- a/src/builtin/module_builtin_debugger.cpp +++ b/src/builtin/module_builtin_debugger.cpp @@ -1140,16 +1140,16 @@ namespace debugger { // pinvoke(context,"function",....) - vec4f pinvoke_impl ( Context & context, SimNode_CallBase * call, vec4f * args ) { + static bool pinvoke_named ( Context & context, SimNode_CallBase * call, vec4f * args, vec4f & res, bool tryLock ) { auto invCtx = cast::to(args[0]); if ( !invCtx ) context.throw_error_at(call->debugInfo, "pinvoke with null context"); auto fn = cast::to(args[1]); if ( !fn ) context.throw_error_at(call->debugInfo, "can't pinvoke empty string"); if ( !invCtx->contextMutex ) context.throw_error_at(call->debugInfo,"threadlock_context is not set"); - vec4f res = v_zero(); + if ( tryLock && !invCtx->contextMutex->try_lock() ) return false; LineInfo exAt; string exText; - invCtx->threadlock_context([&](){ + auto body = [&](){ auto simFn = invCtx->findFunction(fn); if ( !simFn ) { exAt = call->debugInfo; @@ -1178,11 +1178,30 @@ namespace debugger { exAt = invCtx->exceptionAt; exText = invCtx->exception; } - }); + }; + if ( tryLock ) { + lock_guard guard(*invCtx->contextMutex, std::adopt_lock); + invCtx->lock(); + body(); + invCtx->unlock(); + } else { + invCtx->threadlock_context(body); + } if ( !exText.empty() ) context.throw_error_at(exAt, "%s", exText.c_str()); + return true; + } + + vec4f pinvoke_impl ( Context & context, SimNode_CallBase * call, vec4f * args ) { + vec4f res = v_zero(); + pinvoke_named(context, call, args, res, false); return res; } + vec4f try_pinvoke_impl ( Context & context, SimNode_CallBase * call, vec4f * args ) { + vec4f res = v_zero(); + return cast::from(pinvoke_named(context, call, args, res, true)); + } + vec4f pinvoke_impl2_core ( Context & context, SimNode_CallBase * call, vec4f * args, int32_t nUserArgs ) { auto invCtx = cast::to(args[0]); if ( !invCtx ) context.throw_error_at(call->debugInfo, "pinvoke with null context"); @@ -1644,6 +1663,28 @@ namespace debugger { addInterop(*this,lib,"invoke_in_context", SideEffects::worstDefault,"pinvoke_impl")->unsafeOperation = true; // pinvoke2 + addInterop(*this,lib,"try_invoke_in_context", + SideEffects::worstDefault,"try_pinvoke_impl")->unsafeOperation = true; + addInterop(*this,lib,"try_invoke_in_context", + SideEffects::worstDefault,"try_pinvoke_impl")->unsafeOperation = true; + addInterop(*this,lib,"try_invoke_in_context", + SideEffects::worstDefault,"try_pinvoke_impl")->unsafeOperation = true; + addInterop(*this,lib,"try_invoke_in_context", + SideEffects::worstDefault,"try_pinvoke_impl")->unsafeOperation = true; + addInterop(*this,lib,"try_invoke_in_context", + SideEffects::worstDefault,"try_pinvoke_impl")->unsafeOperation = true; + addInterop(*this,lib,"try_invoke_in_context", + SideEffects::worstDefault,"try_pinvoke_impl")->unsafeOperation = true; + addInterop(*this,lib,"try_invoke_in_context", + SideEffects::worstDefault,"try_pinvoke_impl")->unsafeOperation = true; + addInterop(*this,lib,"try_invoke_in_context", + SideEffects::worstDefault,"try_pinvoke_impl")->unsafeOperation = true; + addInterop(*this,lib,"try_invoke_in_context", + SideEffects::worstDefault,"try_pinvoke_impl")->unsafeOperation = true; + addInterop(*this,lib,"try_invoke_in_context", + SideEffects::worstDefault,"try_pinvoke_impl")->unsafeOperation = true; + addInterop(*this,lib,"try_invoke_in_context", + SideEffects::worstDefault,"try_pinvoke_impl")->unsafeOperation = true; addInterop(*this,lib,"invoke_in_context", SideEffects::worstDefault,"pinvoke_impl2")->unsafeOperation = true; addInterop(*this,lib,"invoke_in_context", diff --git a/tests/CMakeLists.txt b/tests/CMakeLists.txt index f239fab83d..15ed8e2bdf 100644 --- a/tests/CMakeLists.txt +++ b/tests/CMakeLists.txt @@ -29,12 +29,14 @@ if(NOT DAS_TOOLS_DISABLED) DEPENDS daslang WORKING_DIRECTORY ${PROJECT_SOURCE_DIR} COMMENT "Running tests (interpreter)" + USES_TERMINAL ) add_custom_target(run_tests_interpreter_isolated COMMAND $ ${_DAS_DASTEST} -- ${_DAS_TEST_COMMON} --isolated-mode --timeout ${DAS_TEST_TIMEOUT_ISOLATED} DEPENDS daslang WORKING_DIRECTORY ${PROJECT_SOURCE_DIR} COMMENT "Running tests (interpreter, isolated retry)" + USES_TERMINAL ) if(NOT DAS_LLVM_DISABLED) @@ -61,12 +63,14 @@ if(NOT DAS_TOOLS_DISABLED) DEPENDS daslang WORKING_DIRECTORY ${PROJECT_SOURCE_DIR} COMMENT "Running tests (JIT, isolated-parallel)" + USES_TERMINAL ) add_custom_target(run_tests_jit_isolated COMMAND $ ${_DAS_DASTEST} -jit -- ${_DAS_JIT_FLAGS} ${_DAS_TEST_COMMON} --isolated-mode --timeout 3600 DEPENDS daslang WORKING_DIRECTORY ${PROJECT_SOURCE_DIR} COMMENT "Running tests (JIT, isolated retry)" + USES_TERMINAL ) endif() endif() @@ -80,6 +84,7 @@ if(TARGET test_aot) DEPENDS test_aot WORKING_DIRECTORY ${PROJECT_SOURCE_DIR} COMMENT "Running tests (AOT)" + USES_TERMINAL ) endif() @@ -92,6 +97,7 @@ if(TARGET test_aot_subset) DEPENDS test_aot_subset WORKING_DIRECTORY ${PROJECT_SOURCE_DIR} COMMENT "Running tests (AOT, tests/language subset)" + USES_TERMINAL ) endif() @@ -106,5 +112,6 @@ if(TARGET test_llvm_aot) DEPENDS test_llvm_aot WORKING_DIRECTORY ${PROJECT_SOURCE_DIR} COMMENT "Running tests (LLVM-AOT)" + USES_TERMINAL ) endif() diff --git a/tests/dastest/test_start_lines.das b/tests/dastest/test_start_lines.das new file mode 100644 index 0000000000..ddbdd3305f --- /dev/null +++ b/tests/dastest/test_start_lines.das @@ -0,0 +1,48 @@ +options gen2 +options no_aot + +require dastest/testing_boost +require daslib/fio +require daslib/strings_boost + +// the start lines are what a hung sweep leaves behind, so they must be printed under +// --failures-only, in both modes, and not depend on the run finishing + +def run_dastest_capturing(t : T?; mode_args : array) : string { + let das_root = get_das_root() + var args <- [ + get_command_line_arguments()[0], + "-dasroot", das_root, + "{das_root}/dastest/dastest.das", + "--", + "--failures-only", + "--test", "{das_root}/tests/dastest/_fixture_pass.das" + ] + args |> push_from(mode_args) + var output : string + let exit_code = run_and_capture(args, output) + t |> equal(exit_code, 0, "the child dastest run must succeed; output:\n{output}") + return output +} + +[test] +def test_sequential_sweep_names_each_program(t : T?) { + let output = run_dastest_capturing(t, []) + let at = find(output, "run 1/1: ") + t |> success(at >= 0, "the sequential sweep prints `run N/M: ` before the program") + if (at >= 0) { + let line = (split(slice(output, at), "\n"))[0] + t |> success(find(line, "_fixture_pass.das") >= 0, "the start line names the program: {line}") + } +} + +[test] +def test_isolated_sweep_names_each_batch(t : T?) { + let output = run_dastest_capturing(t, ["--isolated-mode", "--isolated-mode-threads", "1"]) + let at = find(output, "worker 1 starts: ") + t |> success(at >= 0, "the isolated dispatcher prints `worker K starts: ` before the batch") + if (at >= 0) { + let line = (split(slice(output, at), "\n"))[0] + t |> success(find(line, "_fixture_pass.das") >= 0, "the batch line names its files: {line}") + } +} diff --git a/tests/debug_agent/REVIEW.md b/tests/debug_agent/REVIEW.md new file mode 100644 index 0000000000..ba0789c50d --- /dev/null +++ b/tests/debug_agent/REVIEW.md @@ -0,0 +1,9 @@ +# debug_agent tests Code Review Checklist + +**Read `REVIEW_COMMON.md` (repo root) first - its contract binds this checklist.** Architecture doc: +`daslib/ARCHITECTURE.md` (repo root). + +**A test in this folder that calls `tick_debug_agent` starts every thread its agent's +callbacks wait on before that call, and holds each such thread on an atomic flag until the +callback has entered.** A callback runs under the agent registry lock and `new_thread` cannot +create its context without that same lock, so the wait never ends. diff --git a/tests/debug_agent/test_callback_threadlock.das b/tests/debug_agent/test_callback_threadlock.das index 02ca8f3694..47c2172dfa 100644 --- a/tests/debug_agent/test_callback_threadlock.das +++ b/tests/debug_agent/test_callback_threadlock.das @@ -52,7 +52,6 @@ def test_callback_and_pinvoke_are_serialized(t : T?) { var active = atomic32_create() var overlap = atomic32_create() var tick_done = atomic32_create() - var probe_started = atomic32_create() let agent_context = unsafe(addr(get_debug_agent_context("callback_threadlock_test"))) unsafe { invoke_in_context( @@ -68,23 +67,18 @@ def test_callback_and_pinvoke_are_serialized(t : T?) { tick_debug_agent("callback_threadlock_test") tick_done |> set(1) } - new_thread() @() { - probe_started |> set(1) - unsafe { - invoke_in_context(*agent_context, "probe_callback_overlap") - } - } while ((entered |> get) == 0) { sleep(10u) } - while ((probe_started |> get) == 0) { - sleep(10u) - } - sleep(200u) + let refused = !unsafe(try_invoke_in_context(*agent_context, "probe_callback_overlap")) + t |> success(refused, "a pinvoke is refused while the callback holds the context lock") + t |> equal(overlap |> get, 0) release |> set(1) while ((tick_done |> get) == 0) { sleep(10u) } + let ran = unsafe(try_invoke_in_context(*agent_context, "probe_callback_overlap")) + t |> success(ran, "a pinvoke runs once the callback returned") } t |> equal(overlap |> get, 0) delete_debug_agent_context("callback_threadlock_test") @@ -94,7 +88,6 @@ def test_callback_and_pinvoke_are_serialized(t : T?) { atomic32_remove(active) atomic32_remove(overlap) atomic32_remove(tick_done) - atomic32_remove(probe_started) } } }