Skip to content

Unrecoverable host hang: main-loop work runs inside a SCSI phase #405

Description

@deltro68

Symptom

During a TCP download over DaynaPORT, the Mac hangs hard — no cursor, no
interrupts, hard reset required. The board is unaffected: it logs a clean,
completed transaction
(STATUS GOOD, message sent, BUS FREE) and then the host
issues nothing further, while the firmware keeps running and logging normally.

Reproduced on:

  • HW: Macintosh SE + MacEffects Performer 68030 accelerator; BlueSCSI V2
    Pico 2 W, DaynaPORT + disk images on one board
  • SW: System 6.0.8, MacTCP, an app doing an HTTP download

Intermittent — minutes to an hour. Enabling Debug = 1 on the board makes it
appear within minutes (see below, this turns out to be a clue rather than a
coincidence).

Evidence: where the Mac is stuck

MacsBug on the frozen machine:

uthread_coordinate+01CA
_DeQueue+0072
ServiceTimer+00B8
ServiceTimerGuts+00A8
CheckReceive+0072
doSCSIReceive2+016C
SCSICompleteHS+004E
_stScanLoop

SCSICompleteHS is the SCSI Manager routine that handshakes the status and
message bytes; _stScanLoop is its polling loop. Note ServiceTimerGuts — the
.ENET driver polls the DaynaPORT from a Time Manager task, i.e. interrupt
context, once per 16.63 ms tick. Board logs confirm a steady 17 ms cadence.

Evidence: how long the firmware holds the bus

Debug = 1, 554 consecutive transactions, timing the phase-change trace:

sel->cmd         mean 1.3 ms
cmd->data        mean 0.5 ms
data->status     mean 0.9 ms
status->msgin    mean 6.1 ms   p99 15   max 21   <-- main loop
msgin->busfree   mean 1.2 ms
TOTAL            mean 9.9 ms   p99 20   max 26

Real SCSI work is 3.9 ms; 62% is firmware housekeeping, on essentially every
transaction. At p99 20 ms and max 26 ms a transaction routinely outlasts the
16.63 ms tick — so the next tick fires while the driver is still inside
SCSICompleteHS, re-entering a SCSI Manager that is not reentrant. That matches
the symptom: the host is not waiting on the device, it is wedged on a bus where
nothing is active.

Not a timeout: Apple calibrates TimeSCSIDB at boot and wfREQ allows 256 ms,
so millisecond stalls cannot trip it. They can push a transaction past the
host's polling period, which is a much smaller number.

Cause

scsiPoll() can return with a transaction still in progress, so the main loop —
log flush to SD, cyw43 poll, hotplug check — runs while the initiator is blocked
waiting for REQ.

process_Status() ends at enter_MessageIn(), which sets only the phase; the
message byte waits for the next scsiPoll(), so a full main-loop pass runs in
between.

The biggest contributor is save_logfile(), whose existing comment states the
assumption:

// SD card writing takes a while, during which the code can't handle new
// SCSI requests, so normally we only want to save during a phase where
// the host is waiting for us.

The host waiting is the cost, not a free window. With Debug = 1 this flush runs
after every command; with debug off it is rate-limited — which is why debug
logging accelerates the hang so sharply.

Fix

  1. scsi.c — complete MESSAGE IN in the same scsiPoll() after
    process_Status(), guarded on phase == MESSAGE_IN so the OMTI
    linked-command path is unaffected.
  2. BlueSCSI.cpp — gate platform_network_poll / diskEjectButtonUpdate /
    blink_poll on phase == BUS_FREE. Watchdog kick stays unconditional.
  3. BlueSCSI.cpp — move the save_logfile() trigger from STATUS to BUS_FREE.
before after
status->msgin 6.1 ms 1.0 ms
transaction median 9–10 ms 5 ms
transaction p99 19–20 ms 9 ms
over 16.63 ms 1.5% 0.04%

No recurrence since, across repeated multi-app updates and sustained downloads.

(1) touches lib/SCSI2SD, shared with ZuluSCSI — you may prefer a different
remedy there. (2) and (3) are self-contained.

Scope

A Macintosh Plus does not exhibit this on the same firmware — so stock
hardware appears unaffected, and the accelerator is the differentiating
variable. I don't have a proven explanation for why the Plus is immune; the
plausible candidates are that its lower throughput means fewer polls carrying
data, and that its driver spends longer per poll in CPU terms without the tick
changing.

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions