DCAM4 capture: bound every wait, arm it before the start, clean up on every exit

CHANGELOG.md

@@ -8,6 +8,47 @@ the README's Installation section: in `0.x.y`, `x` is the breaking component
 and `y` is the non-breaking one (releases are tagged; between them `main` carries
 the next version with `-DEV`).
 
+## [Unreleased]
+
+### Added
+
+- Opt-in per-call trace of the DCAM library calls (`DCAM4.dcam_trace!(path)`, or ENV `MC_DCAM4_TRACE=<path>`
+  at load): a flushed BEGIN and END line per call with arguments, elapsed time, return value and cumulative GC
+  time, to name a call that hangs. Off by default; one `Ref{Bool}` check per call.
+
+### Fixed
+
+- `DCAM4Camera` `capture` could hang, or leave the camera unusable after a missed frame. Its frame wait is now
+  bounded by 2 x (exposure + readout) + 1 s, with the readout read from the camera
+  (`DCAM_IDPROP_TIMING_READOUTTIME`); the wait is armed before the capture starts; the wait's parameter struct
+  carries its size (it was sent as 0); and every exit stops the capture, releases the buffer and closes the wait.
+  A timeout or failed wait logs, sets `last_error` and throws a clear error (it threw a MethodError before).
+  Reported from the quickbeam rig: full frame at 12.5 ms and at 100 ms, including the first capture in a fresh
+  session.
+- `DCAM4Camera` `getlastframe`: a timeout or failed wait no longer throws a MethodError. It logs, sets `last_error`
+  and returns `nothing`, as the code intended. Its wait is bounded the same way, with the readout time read once per
+  `live`, `sequence` or `capture` and cached. A frame that cannot be copied, here or in `capture`, sets `last_error`.
+- `DCAM4Camera` `getdata` in SEQUENCE mode polls the capture status against a deadline of
+  2 x N x (exposure + readout) + 1 s instead of waiting for the end-of-cycle event. A sequence that has already
+  ended cannot be missed, a full-frame sequence of short exposures no longer times out, and an interrupt can land
+  while it waits. A frame that cannot be read returns `nothing` with `last_error` set (it threw a MethodError).
+  Every exit stops the capture and releases the buffer. A sequence that transferred fewer frames than requested (or
+  never ran) returns `nothing` with `last_error` set to `DCAMERR_LOSTFRAME`. In LIVE mode `getdata` returns the
+  newest frame at once and leaves the live view running; it used to clear `is_running` while the view ran on.
+- `DCAM4Camera` `sequence`: the task that marks the sequence finished gives up at the same deadline and stops a
+  capture stuck running, so `is_running` can no longer stay true forever. It acts only while its sequence is
+  current, so it never stops or marks finished a newer live view or sequence, and a failed status read is retried
+  until the deadline.
+- `DCAM4Camera`: clearing a leftover capture handles every state (a capture in the ERROR state was neither stopped
+  nor released), and `abort` now does exactly that.
+
+### Changed
+
+- `DCAM4Camera` `capture` refuses (throws "Stop the live view or sequence first") while a live view or sequence is
+  running (`is_running`), instead of failing at the buffer allocation and returning `nothing`. It never releases a
+  buffer another task may be waiting on. A leftover from an earlier call (a failed capture, or a sequence that
+  ended and was never read) is stopped and released first.
+
 ## [0.2.5] - 2026-09-29
 
 A non-breaking release. It brings the TCube laser's closed-loop (power) mode and

Project.toml

@@ -1,6 +1,6 @@
 name = "MicroscopeControl"
 uuid = "aa70d9ae-4a1e-49fd-870a-8ccfd99f4c3e"
-version = "0.2.5"
+version = "0.2.6-DEV"
 authors = ["klidke@unm.edu"]
 
 [deps]

src/hardware_implementations/dcam4_camera/DCAM4.jl

@@ -25,6 +25,7 @@ export dcamprop_getvalue, DCAM_IDPROP_INTERNALFRAMERATE, CameraROI, dcamapi_unin
 include("dcamerr.jl")
 include("dcam_idprop.jl")
 include("types.jl")
+include("dcam_trace.jl")
 include("dcamapi.jl")
 include("dcamdev.jl")
 include("dcamprop.jl")

src/hardware_implementations/dcam4_camera/dcam_helpers.jl

@@ -203,5 +203,122 @@ function settriggermode!(camera::DCAM4Camera, trigger_mode::TriggerMode)
     settriggermode!(camera)
 end
 
+"""
+    capture_timeout_ms(exposure_s, readout_s) -> Int32
+
+The timeout for one frame wait, in milliseconds: `2 * (exposure_s + readout_s)` seconds plus 1 s. The readout term
+matters: a full ORCA frame reads out in tens of milliseconds, far longer than a short exposure. Throws for a
+negative or non-finite input, and for a result beyond `typemax(Int32)` ms, so a wait is never unbounded
+(DCAM reads the negative value `0x80000000` as INFINITE).
+"""
+function capture_timeout_ms(exposure_s::Real, readout_s::Real)
+    (isfinite(exposure_s) && exposure_s >= 0) ||
+        error("capture_timeout_ms: exposure $(exposure_s) s must be finite and non-negative")
+    (isfinite(readout_s) && readout_s >= 0) ||
+        error("capture_timeout_ms: readout $(readout_s) s must be finite and non-negative")
+    t = 2000 * (Float64(exposure_s) + Float64(readout_s)) + 1000
+    t <= typemax(Int32) || error("capture_timeout_ms: $(t) ms does not fit a DCAM timeout (Int32 ms)")
+    return Int32(round(t))
+end
+
+"""
+    READOUT_FALLBACK_S
+
+The readout time, in seconds, that `readout_time` assumes when the camera does not report
+`DCAM_IDPROP_TIMING_READOUTTIME`. It is deliberately generous, since it only lengthens a timeout.
+"""
+const READOUT_FALLBACK_S = 1.0
+
+"""
+    readout_time(camera::DCAM4Camera) -> Float64
+
+The sensor readout time in seconds, read from the camera's `DCAM_IDPROP_TIMING_READOUTTIME`, which depends on the
+current ROI and readout speed, so read it after `setroi!`. It reads the camera and caches the value in
+`camera.readout_s`. If the read fails or the value is not a finite, non-negative number, it warns and returns (and
+caches) `READOUT_FALLBACK_S`.
+"""
+function readout_time(camera::DCAM4Camera)
+    err, t = dcamprop_getvalue(camera.camera_handle, DCAM_IDPROP_TIMING_READOUTTIME)
+    if is_failed(err) || !isfinite(t) || t < 0
+        @warn "DCAM4Camera $(camera.unique_id): the camera did not report its readout time ($(err), $(t)); assuming $(READOUT_FALLBACK_S) s for the frame-wait timeout" maxlog = 1
+        camera.readout_s = READOUT_FALLBACK_S
+        return READOUT_FALLBACK_S
+    end
+    camera.readout_s = Float64(t)
+    return Float64(t)
+end
+
+"""
+    cached_readout_time(camera::DCAM4Camera) -> Float64
+
+The readout time cached by the last `readout_time` call (`live`, `sequence` and `capture` refresh it after
+`setroi!`), or a fresh read if none is cached. Used on per-frame paths, so a live view does not read a
+property per frame.
+"""
+cached_readout_time(camera::DCAM4Camera) =
+    isfinite(camera.readout_s) ? camera.readout_s : readout_time(camera)
 
+"""
+    stop_and_release!(camera::DCAM4Camera)
+
+Leave the camera with no capture running and no buffer attached, whatever an earlier call left behind (a live view,
+a sequence, or a capture that failed). It reads the status first and does nothing only when the status is known to be
+STABLE (no buffer) or UNSTABLE. A failed status read, BUSY or ERROR is stopped (unless READY, which is already
+stopped); then anything with a buffer is released. The helpers log their own failures and never throw. Sets
+`camera.is_running = false`. It also increments `capture_generation`, so a `sequence` poller started before it no
+longer acts. Every start goes through it first: `live` and `sequence` through `abort`, and `capture` directly.
+"""
+function stop_and_release!(camera::DCAM4Camera)
+    camera.capture_generation += 1  # any stop makes every older sequence poller stale
+    hdcam = camera.camera_handle
+    err, status = dcamcap_status(hdcam)
+    # Nothing to do only when the status is known to be STABLE (no buffer) or UNSTABLE. A failed
+    # status read, BUSY or ERROR is stopped; then anything with a buffer is released. The helpers
+    # log their own failures and never throw.
+    if is_failed(err) || !(status == DCAMCAP_STATUS_STABLE || status == DCAMCAP_STATUS_UNSTABLE)
+        status == DCAMCAP_STATUS_READY || dcamcap_stop(hdcam)
+        dcambuf_release(hdcam)
+    end
+    camera.is_running = false
+    return nothing
+end
+
+"""
+    STATUS_POLL_S
 
+The interval, in seconds, at which `wait_not_busy` polls the capture status.
+"""
+const STATUS_POLL_S = 0.01
+
+"""
+    wait_not_busy(camera::DCAM4Camera, timeout_ms, what; current = () -> true) -> Bool
+
+Poll the capture status every `STATUS_POLL_S` until it is no longer BUSY, for at most `timeout_ms`. Returns `true`
+when the capture has ended. A failed status read is logged once and retried until the deadline. At the deadline
+it logs (naming `what`), sets `last_error` (the status read's error if the last read failed, else
+`DCAMERR_TIMEOUT`) and returns `false`. It sleeps between polls, so an interrupt can land, unlike a blocking DCAM
+wait. It also returns `false` as soon as `current()` is false (a newer capture replaced the one it watches),
+touching nothing.
+"""
+function wait_not_busy(camera::DCAM4Camera, timeout_ms::Integer, what::AbstractString;
+                       current::Function = () -> true)
+    deadline = time() + timeout_ms / 1000
+    logged = false
+    while current()
+        err, status = dcamcap_status(camera.camera_handle)
+        if is_failed(err)
+            logged || @error "DCAM4Camera $(camera.unique_id): $(what) could not read the capture status ($(err)); retrying until the deadline"
+            logged = true
+        elseif status != DCAMCAP_STATUS_BUSY
+            return true
+        end
+        if time() >= deadline
+            camera.last_error = is_failed(err) ? err : DCAMERR_TIMEOUT
+            @error "DCAM4Camera $(camera.unique_id): $(what) timed out after $(timeout_ms) ms " *
+                   (is_failed(err) ? "(the status read fails: $(err))" : "with the capture still running")
+            return false
+        end
+        sleep(STATUS_POLL_S)
+    end
+    return false
+end

src/hardware_implementations/dcam4_camera/dcam_trace.jl

@@ -0,0 +1,130 @@
+# Opt-in per-call trace of the DCAM library calls. A hang inside a DCAM ccall leaves no Julia frame
+# to inspect, so `@dcamcall` (used at every DCAM ccall site in place of `@ccall`) can write a BEGIN
+# line before and an END line after each call, flushed at once so a killed process leaves its last
+# BEGIN on disk. Cumulative GC time is on every BEGIN and END line: a GC requested by another
+# thread while this thread sits in a long ccall (which is not a GC safe point) makes that thread
+# spin until the call returns, and shows as a jump between a call's BEGIN and END.
+#
+# Off by default; the cost when off is one `Ref{Bool}` check per call. Turn on with
+# `dcam_trace!(path)` (`dcam_trace!(nothing)` turns it off) or ENV `MC_DCAM4_TRACE=<path>` at load.
+
+using Dates: Dates
+
+const TRACE_ON = Ref(false)
+const TRACE_IO = Ref{Union{IOStream, Nothing}}(nothing)
+const TRACE_LOCK = ReentrantLock()
+
+"""
+    dcam_trace!(path)
+    dcam_trace!(nothing)
+
+Append a BEGIN/END line for every DCAM library call to `path`, or stop tracing and close the file.
+"""
+function dcam_trace!(path::Union{AbstractString, Nothing})
+    lock(TRACE_LOCK) do
+        TRACE_ON[] = false
+        TRACE_IO[] === nothing || close(TRACE_IO[])
+        TRACE_IO[] = nothing
+        if path !== nothing
+            TRACE_IO[] = open(path, "a")
+            TRACE_ON[] = true
+        end
+    end
+    return nothing
+end
+
+function trace_line(kind, name, rest::AbstractString)
+    lock(TRACE_LOCK) do
+        io = TRACE_IO[]
+        io === nothing && return
+        t = Dates.format(Dates.now(), "yyyy-mm-dd HH:MM:SS.sss")
+        println(io, t, " tid=", Threads.threadid(), " ", kind, " ", name, rest)
+        flush(io)
+    end
+    return nothing
+end
+
+gc_ms() = Base.gc_num().total_time / 1e6
+
+"""
+    dcam_trace_note(msg)
+
+Write a marker line to the trace, if tracing is on.
+"""
+function dcam_trace_note(msg)
+    TRACE_ON[] && trace_line("NOTE", "", " " * string(msg))
+    return nothing
+end
+
+function trace_arg(v)
+    v isa Base.RefValue && (v = v[])
+    if v isa Integer || v isa AbstractFloat
+        return string(v)
+    elseif v isa Ptr
+        return string("0x", string(UInt(v), base = 16))
+    elseif isstructtype(typeof(v)) && !(v isa Union{AbstractArray, AbstractString}) && fieldcount(typeof(v)) > 0
+        parts = String[]
+        for f in fieldnames(typeof(v))
+            fv = getfield(v, f)
+            fv isa Int32 && push!(parts, string(f, "=", fv))
+        end
+        return string(typeof(v).name.name, "{", join(parts, ","), "}")
+    else
+        return string(typeof(v))
+    end
+end
+
+function trace_begin(name, vals)
+    trace_line("BEGIN", name, string(" args=(", join(map(trace_arg, vals), ", "), ") gc_ms=", round(gc_ms(), digits = 3)))
+    return time_ns()
+end
+
+function trace_end(name, t0, ret)
+    ms = (time_ns() - t0) / 1e6
+    trace_line("END", name, string(" elapsed_ms=", round(ms, digits = 3), " ret=", ret, " gc_ms=", round(gc_ms(), digits = 3)))
+    return nothing
+end
+
+"""
+    @dcamcall [lib.]fn(arg::T, ...)::Ret
+
+`@ccall`, plus a BEGIN and an END trace line when tracing is on (see `dcam_trace!`). Each argument
+expression is evaluated once.
+"""
+macro dcamcall(expr)
+    Meta.isexpr(expr, :(::), 2) && Meta.isexpr(expr.args[1], :call) || error("@dcamcall: expected fn(args...)::Ret")
+    call, ret = expr.args
+    target = call.args[1]
+    fname = string(target isa Expr ? target.args[end] : target)
+    fname = startswith(fname, ":") ? fname[2:end] : fname
+    binds = Expr[]
+    tmps = Symbol[]
+    newargs = Any[target]
+    for a in call.args[2:end]
+        Meta.isexpr(a, :(::), 2) || error("@dcamcall: every argument needs a type annotation, got $a")
+        t = gensym("arg")
+        push!(binds, :($t = $(a.args[1])))
+        push!(tmps, t)
+        push!(newargs, Expr(:(::), t, a.args[2]))
+    end
+    plain = :(Base.@ccall $(Expr(:(::), Expr(:call, newargs...), ret)))
+    r = gensym("ret"); t0 = gensym("t0")
+    on = GlobalRef(@__MODULE__, :TRACE_ON)
+    return esc(quote
+        let $(binds...)
+            if $on[]
+                $t0 = $(GlobalRef(@__MODULE__, :trace_begin))($fname, ($(tmps...),))
+                $r = $plain
+                $(GlobalRef(@__MODULE__, :trace_end))($fname, $t0, $r)
+                $r
+            else
+                $plain
+            end
+        end
+    end)
+end
+
+function __init__()
+    path = get(ENV, "MC_DCAM4_TRACE", "")
+    isempty(path) || dcam_trace!(path)
+end

src/hardware_implementations/dcam4_camera/dcamapi.jl

@@ -17,15 +17,15 @@ end
 
 function dcamapi_init()
     dci = DCAMAPI_INIT()
-    err = @ccall "dcamapi.dll".dcamapi_init(dci::Ref{DCAMAPI_INIT})::DCAMERR
+    err = @dcamcall "dcamapi.dll".dcamapi_init(dci::Ref{DCAMAPI_INIT})::DCAMERR
     if is_failed(err)
         @error "DCAM Failed to Initialize"
     end
     return err, dci
 end
 
 function dcamapi_uninit()
-    err = @ccall "dcamapi.dll".dcamapi_uninit()::DCAMERR
+    err = @dcamcall "dcamapi.dll".dcamapi_uninit()::DCAMERR
     if is_failed(err)
         @error "DCAM Failed to Un-Initialize"
     end