Skip to content

Enhance batch logging and retire x86_64 Intel Mac CI build - #13

Merged
nilshoffmann merged 8 commits into
ballal_codefrom
fix/batch-worker-observability
Sep 2, 2026
Merged

nilshoffmann merged 8 commits into
ballal_codefrom
fix/batch-worker-observability

Conversation

@nilshoffmann

Copy link
Copy Markdown
Member

Updating the logging configuration to track parallel workers with a custom diagnostic context for each. Fixed some issues related to appending the individual worker logs to the debug dialog. Tested the batch mode on Mac successfully, it worked before, but it took more than 60s before the first processing finished, so before, nothing was being logged. Also removed the x86_64 mac build due to repeated build issues and version problems. Added instructions to build for x86_64 mac to the README.md for the adventureous.

nilshoffmann and others added 8 commits September 2, 2026 06:42
Batch mode was reported as "only works on Windows". It does work off
Windows -- a 12-sample run completes normally from the macOS .app -- but
it looks dead while it does, and that is the actual defect.

Worker processes are started with the 'spawn' method, so they get a fresh
interpreter and do not inherit the TeeLogger the GUI installs over
builtins.print. In a windowed PyInstaller bundle their stdout and stderr
go to a null sink. Every "[PID n] START/Building MasterScan/DONE" line
and every worker traceback was therefore discarded, and the GUI showed
nothing between "Using N worker process(es)" and the first finished
sample -- over a minute of apparent hang per sample, since each spawned
worker re-imports the whole application and re-JITs numba.

The log_file argument was already plumbed into every worker and then
explicitly ignored ("kept for compatibility, not used here"). Use it:

- Workers rebind print() and sys.stdout/sys.stderr to a line-buffered
  sink that appends to the shared batch log, so their progress and their
  tracebacks land somewhere the user can see. Whole lines are written
  under O_APPEND, which is atomic at this size on POSIX and Windows, so
  concurrent workers do not tear each other's output.
- The debug window is now fed by tailing that log from a wx.Timer on the
  main thread. This is also a correctness fix: the batch thread used to
  reach StyledTextCtrl.AppendText through TeeLogger, and wx forbids
  touching the GUI off the main thread -- tolerated by wxMSW, not by
  wxOSX or wxGTK. TeeLogger's gui_writer is None to avoid double lines.
- Report per-sample errors instead of dropping them. "No hits" and "the
  worker raised" shared one ERROR/EMPTY line, so an empty sample was
  indistinguishable from a crashed one; they are now separate, the
  captured traceback is printed, and progress is counted as (n/total).
- Restore builtins.print when a run ends, so later output is not filed
  into a finished run's log.

Also two smaller things the above exposed: the log no longer advertises
per-sample CSV paths without saying they were deleted when "Save per
sample result" is unticked, and the empty per_sample_results directory is
cleaned up on the no-results path that returned before the cleanup block.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
csv.Sniffer.sniff is documented and typed as taking `delimiters: str | None`.
The list passed here worked -- the parameter is only ever consumed by
`char in delimiters` membership tests, which behave the same for a list of
single characters -- but it violates the signature and type checkers flag
it. Verified equivalent for all four candidates before changing.

Also drop a vacuous assertion in the blank-line test: it was written as
`assert x == "" if log.exists() else True`, and since a blank-only write
never creates the file, the test asserted True and checked nothing.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
install_as_print() only rebinds builtins.print, but warnings.warn() and
traceback.print_exc() write straight to sys.stderr -- which is a null sink
in a windowed PyInstaller build. So warnings raised in the parent process
during the merge were still being lost, including "Could not detect
delimiter ... falling back to comma", which silently changes how a result
file is parsed.

TeeLogger gains install_as_streams()/restore_streams(), pointing
sys.stdout and sys.stderr at a line buffer that feeds TeeLogger.log.
The buffer matters: traceback.print_exc() emits several write() calls per
line, and stamping each one would put a timestamp mid-sentence.

_finish_batch_logging restores the streams before the final drain, since
restore_streams() flushes a trailing partial line into the log and that
line still has to reach the window.

Separately, run_batch declared `n_cores: int = None` and
`occurrence_threshold: float = None`. Both defaults are deliberate --
Pool(processes=None) means "one worker per core", and a None threshold
skips the occurrence filter at merge_lipid_results -- so the runtime
behaviour was right and only the annotations were wrong. PEP 484 dropped
implicit Optional, so type checkers flag them. Now Optional[int] /
Optional[float], with log_file annotated too.

The warning test runs in a subprocess: pytest replaces
warnings._showwarnmsg_impl with its own recorder, so a warning raised
inside the test process never reaches sys.stderr and the capture could
not be observed in-process.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Worker output now reaches the debug window, but only the lines
process_sample writes itself carried a "[PID n]" marker. Everything from
the deeper code path -- doImport, readSpectra, the MFQL interpreter --
just calls print(), so with several workers interleaving in one log those
lines were anonymous and could not be tied to a sample.

Apply the context in the sink instead of at each call site, which is the
only place that can cover code with no idea a batch is running. Each
worker installs "[W3 240506_QC_49936_a]": the pool worker (stable for the
life of the process, taken from multiprocessing's own SpawnPoolWorker-N
name) and the sample it is on right now, since pool workers are reused
across samples.

The per-line "[PID n]" prefixes are dropped as redundant. The pid is
logged once on the START line, which is enough to tie a worker to a
process in `ps`.

Verified with 3 workers over 6 samples: 18/18 lines attributed, including
output from code that only calls print(), and the context correctly
follows a worker as it moves between samples.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Two things, both about the batch log.

TeeLogger gains the same optional context the worker sink has, and the GUI
sets it to "[MAIN]". Controller output is now labelled the way worker
output is, so every line in the log says which process wrote it -- and it
covers lines from code that has no idea a batch is running, since the
context is applied in log() rather than at each call site. The three
hand-written "[MAIN]" prefixes in run_batch are dropped as redundant.

The delimiter warnings that became visible once the log started showing
warnings.warn output were not caused by passing delimiters as a string
instead of a list: detection fails identically with a list, a string, and
None. The real cause is the fixed 4096-byte read in detect_delimiter. A
result row here is several hundred characters wide, so that read stops
mid-line, and the truncated last line has a different field count from the
rest -- which is what csv.Sniffer's consistency check rejects. Feeding the
sniffer whole lines only fixes it: all twelve files of a real benchmark run
went from "could not determine delimiter" to ',' detected correctly.

The fallback to comma had made this harmless so far, because pandas writes
the per-sample files with a comma. It would not have stayed harmless for a
tab-limited run, where every merged row would have collapsed into one
column.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
@nilshoffmann
nilshoffmann merged commit 02b1973 into ballal_code Sep 2, 2026
5 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant