swung0x48/MobileGL
1
0
Fork 0
mirror of https://github.com/MobileGL-Dev/MobileGL synced 2026-11-07 01:53:24 +09:00
Code Issues Packages Projects Releases Wiki Activity

[MG_Remote, MG_Test, MG_IntegrationTest, scripts] (P7): a spawned server reports SurfaceProgress while its apply thread runs a surface op, so the client's reply budget bounds silence and a cold bring-up past 20 s is waited for

Browse Source
This commit is contained in:
swung0x48
2026-09-23 18:17:02 -04:00
parent dd415408dd
commit cfe830cf44
14 changed files with 556 additions and 14 deletions
Download Patch File Download Diff File Expand all files Collapse all files
MobileGL/MG_IntegrationTest/CMakeLists.txt
+5
View File
@@ -2839,6 +2839,11 @@ if (MOBILEGL_BUILD_DISAGGREGATED)
# "remote spawn bring-up failed" - the CI failure in miniature. A 3 s lever under a 2 s steady
# knob was faster but proved less: the pre-fix client never read MOBILEGL_IPC_CONTROL_TIMEOUT_MS,
# so its 5 s bound outlasted the lever and the entries were green at 14e1c8b9 (measured).
# SINCE p7/spawnhang THEY ARE NO LONGER THE BUDGET SELECTION'S RED-ONCE: a 20 s bring-up outran
# the cold-start budget too (run 35912252677), so both budgets now bound SILENCE - the server
# reports Wire::SurfaceProgress every 250 ms while it runs the op, and each report restarts the
# client's budget. These entries stay as the end-to-end check that a held bring-up is waited
# for on both backends; the mechanism's red-once is ServerSpawnTest's cold-bring-up case (unit).
# Each entry takes ~25 s, because the harness's pre-flight child brings a server up as well.
# NOT on integration-spawn: this is not a copy of the split lane (spawn_lane_parity.py). The
# DirectVulkan entry does carry integration-gpu, unlike the Magma arms' informational tiers
MobileGL/MG_Remote/CONTRACT-P5.md
+2 -2
View File
@@ -394,8 +394,8 @@ is a pull-build symbol and G1 admits **no resize**, which is the same reason the
| `MOBILEGL_IPC_STRICT_ERRORS` | 0 | promotes BARRIER-PULLED reads — and, in a split build, the seven sticky forwards — to `Fatal`. |
| `MOBILEGL_IPC_AUDIT` | 0 | `0xDD` over retired staging bytes (rule C's mechanical control). |
| `MOBILEGL_IPC_SERVER_AFFINITY` | `auto` | kept as the raw string; whoever starts the apply thread logs the **resolved mask**, because an affinity that silently did nothing looks exactly like one that worked. |
| `MOBILEGL_IPC_CONTROL_TIMEOUT_MS` | 5000 | (P6 D5b, parsed from P7) a spawn/tcp client's wait for one surface-control `SurfaceReply` once the server's backend is up. Expiry is **not** fatal: dead latches device-lost, alive-but-silent is a named diagnostic. Range 100..600000. |
| `MOBILEGL_IPC_COLD_START_MS` | 20000 | (P7) the same wait for `CreatePbufferSurface` / `CreateWindowSurface` / `MakeCurrent` until the session's first `MakeCurrent` is answered ok - the ops a server brings its native backend up inside, lazily. Never shorter than `CONTROL_TIMEOUT_MS`. Measured need: retrace-split spawn legs outlasted 5 s on loaded CI runners. The test lever is the server's `MOBILEGL_TEST_DELAY_FIRST_BRINGUP_MS`. |
| `MOBILEGL_IPC_CONTROL_TIMEOUT_MS` | 5000 | (P6 D5b, parsed from P7) a spawn/tcp client's wait for one surface-control `SurfaceReply` once the server's backend is up. Expiry is **not** fatal: dead latches device-lost, alive-but-silent is a named diagnostic. Range 100..600000. Since p7/spawnhang it bounds **silence**, not the op: each `SurfaceProgress` the server sends while its apply thread runs the op (every 250 ms, `ServerLoop::kControlProgressIntervalMs`) restarts it, up to `kBarrierTimeoutMs` (120 s) from the send. |
| `MOBILEGL_IPC_COLD_START_MS` | 20000 | (P7) the same wait for `CreatePbufferSurface` / `CreateWindowSurface` / `MakeCurrent` until the session's first `MakeCurrent` is answered ok - the ops a server brings its native backend up inside, lazily. Never shorter than `CONTROL_TIMEOUT_MS`. Measured need: retrace-split spawn legs outlasted 5 s on loaded CI runners, and one outlasted 20 s (run 35912252677, `CreatePbufferSurface` seq 2) - which is why, since p7/spawnhang, this too is a silence budget that the server's `SurfaceProgress` reports restart (row above). The test lever is the server's `MOBILEGL_TEST_DELAY_FIRST_BRINGUP_MS`. |
**One consequence, stated so it is not rediscovered.** In a build *without*
`MOBILEGL_BUILD_DISAGGREGATED`, `MOBILEGL_TRANSPORT=inproc` is accepted by the environment and
MobileGL/MG_Remote/CONTRACT-P6.md
+3 -1
View File
@@ -335,7 +335,9 @@ into the pull build too, and is now guarded for the same reason.
its expiry is `Fatal{ControlReplyTimeout, "<op>@<seq>"}`. (b) The client's *cross-process* reply wait
is bounded by `MOBILEGL_IPC_CONTROL_TIMEOUT_MS` (default 5000) and its expiry is **not** fatal: the
client consults the doorbell's death latch — dead latches device-lost, alive-but-silent is a named
diagnostic. Packages: `cp` (a), `dl` (b).
diagnostic. Packages: `cp` (a), `dl` (b). (P7, p7/spawnhang: "silent" is now literal — a server whose
apply thread is running the op says so every 250 ms with `SurfaceProgress`, and each report restarts
the client's bound, up to 120 s; a server that never took the op, or is frozen, sends none.)
> **D5c — the client's self-bell CANNOT witness the server's death, and `sm` is why.** Measured, not
> predicted: `minecraft-1.21.4-fabric-iris-iterationrp-in-world` kills the *server* process outright
MobileGL/MG_Remote/Client/ClientSession.cpp
+71 -2
View File
@@ -1251,9 +1251,32 @@ namespace MobileGL::MG_Remote::Client {
// The reply. A BOUNDED wait whose expiry is NOT fatal (CONTRACT-P6 §5.4
// D5b): a peer that is gone is a different fact from a peer that is slow,
// and only the doorbell's death latch may say which.
//
// P7 (p7/spawnhang): THE BUDGET BOUNDS SILENCE, NOT THE OP. It used to be one deadline
// for the whole reply, so a server that was still running the op - a cold native
// bring-up, eglInitialize loading a software rasteriser off a runner's cold disk for
// ~20 s (retrace-split run 35912252677) - was reported ALIVE BUT SILENT and its surface
// creation failed, although it was about to answer. The server now says so while it runs
// an op it has taken (Wire::SurfaceProgress, every ServerLoop::kControlProgressIntervalMs),
// and each report restarts this budget. What still times out, named as before: a server
// that never took the op or is frozen (no report arrives), and one that reports progress
// past kBarrierTimeoutMs - the bound the verb barrier gives one record's apply, which is
// what a surface op that is being run IS.
const auto sentAt = std::chrono::steady_clock::now();
const Uint32 ceilingMs = std::max<Uint32>(budgetMs, kBarrierTimeoutMs);
Uint32 progressReports = 0;
Uint32 lastProgressMs = 0;
for (;;) {
std::vector<Uint8> reply;
const MobileGLResult received = ReceiveControlFrame(reply, budgetMs);
Uint32 waitMs = budgetMs;
if (progressReports != 0) {
const auto spentMs = std::chrono::duration_cast<std::chrono::milliseconds>(
std::chrono::steady_clock::now() - sentAt).count();
waitMs = spentMs >= ceilingMs ? 0u : std::min<Uint32>(budgetMs, ceilingMs - static_cast<Uint32>(spentMs));
}
// A zero wait is the ceiling, reached: answered exactly as an expired budget is.
const MobileGLResult received =
waitMs == 0 ? MOBILEGL_ERR_TIMEOUT : ReceiveControlFrame(reply, waitMs);
if (received != MOBILEGL_OK) {
// `dl` (D5b): THE EXPIRY IS NOT FATAL AND IT IS NOT ONE ANSWER. The transport
// already distinguishes the two states this wait can end in, and the contract
@@ -1272,6 +1295,14 @@ namespace MobileGL::MG_Remote::Client {
} else if (const Transport::Doorbell* bell = m_producer.SelfDoorbell();
bell != nullptr && bell->PeerHungUp()) {
LatchDeviceLost("a control reply timed out and the peer had hung up");
} else if (progressReports != 0 && waitMs == 0) {
MGLOG_E("MG_Remote client: the server is ALIVE AND BUSY past the ceiling - it "
"reported %u time(s) that it was still running %s seq %llu (the last "
"at %u ms) and has not answered within %u ms, the bound the verb "
"barrier gives one apply. This is NOT device loss (CONTRACT-P6 5.4); "
"the op itself is not returning on the server's apply thread.",
progressReports, Server::SurfaceControlOpName(frame.kind),
static_cast<unsigned long long>(frame.seq), lastProgressMs, ceilingMs);
} else {
MGLOG_E("MG_Remote client: the server is ALIVE BUT SILENT - no SurfaceReply "
"for %s seq %llu within %u ms (%s) and the control stream is still "
@@ -1283,9 +1314,23 @@ namespace MobileGL::MG_Remote::Client {
coldStart ? "the cold-start budget, MOBILEGL_IPC_COLD_START_MS: the "
"server may still have been bringing its backend up"
: "the steady bound, MOBILEGL_IPC_CONTROL_TIMEOUT_MS");
// WHICH SILENCE (p7/spawnhang). A server running the op reports progress, so
// none at all means it never started it (or froze before it could say so);
// reports that stopped mean it froze mid-op.
if (progressReports == 0)
MGLOG_E("MG_Remote client: no SurfaceProgress arrived for seq %llu either (a "
"server reports every %u ms while it runs an op): it did not start "
"the op, or it is frozen",
static_cast<unsigned long long>(frame.seq),
Server::ServerLoop::kControlProgressIntervalMs);
else
MGLOG_E("MG_Remote client: the server had reported progress on seq %llu "
"%u time(s), the last at %u ms, and then stopped",
static_cast<unsigned long long>(frame.seq), progressReports,
lastProgressMs);
}
MGLOG_E("MG_Remote client: no SurfaceReply for seq %llu within %u ms (rc=%d)",
static_cast<unsigned long long>(frame.seq), budgetMs,
static_cast<unsigned long long>(frame.seq), waitMs == 0 ? ceilingMs : budgetMs,
static_cast<int>(received));
return received;
}
@@ -1304,6 +1349,30 @@ namespace MobileGL::MG_Remote::Client {
}
continue;
}
if (envelope->msg_type() == ::MobileGL::Wire::CtrlMsg::SurfaceProgress) {
// THE SERVER IS STILL RUNNING THIS OP (p7/spawnhang, above): the budget restarts.
// One op is outstanding at a time (m_remoteControlMutex), so a report naming any
// other seq is a server that has lost track of which op it is running.
const auto* progress = envelope->msg_as_SurfaceProgress();
if (progress == nullptr || progress->seq() != frame.seq) {
MGLOG_E("MG_Remote client: a SurfaceProgress names seq %llu while seq %llu is "
"the op outstanding",
static_cast<unsigned long long>(progress == nullptr ? 0 : progress->seq()),
static_cast<unsigned long long>(frame.seq));
return MOBILEGL_ERR_PROTOCOL_MISMATCH;
}
if (progressReports == 0) {
MGLOG_I("MG_Remote client: the server is still running %s seq %llu (%u ms after "
"it was posted to its apply thread); the reply budget of %u ms restarts "
"on each progress report, up to %u ms",
Server::SurfaceControlOpName(frame.kind),
static_cast<unsigned long long>(frame.seq), progress->elapsedMs(), budgetMs,
ceilingMs);
}
++progressReports;
lastProgressMs = progress->elapsedMs();
continue;
}
if (envelope->msg_type() == ::MobileGL::Wire::CtrlMsg::Fatal) {
// `dl` step three: the server published a SessionFault before it aborted, so this
// is a death that NAMES ITSELF instead of arriving as a bare EOF. Log the family
MobileGL/MG_Remote/Client/ClientSession.h
+2 -1
View File
@@ -458,7 +458,8 @@ namespace MobileGL::MG_Remote::Client {
Uint64 m_remoteControlSeq = 0;
// P7 CI: false until this session's first MakeCurrent is answered ok. Until then the
// ops the server may bring its native backend up inside wait MOBILEGL_IPC_COLD_START_MS
// for their reply instead of MOBILEGL_IPC_CONTROL_TIMEOUT_MS (Config.h has both).
// for their reply instead of MOBILEGL_IPC_CONTROL_TIMEOUT_MS (Config.h has both). Either
// budget bounds SILENCE (p7/spawnhang): a Wire::SurfaceProgress for the op restarts it.
// Guarded by m_remoteControlMutex, like the seq above; reset by Stop().
Bool m_serverBackendWarm = false;
MobileGL/MG_Remote/Protocol/generated/protocol_generated.h
+84 -5
View File
@@ -77,6 +77,9 @@ struct FatalBuilder;
struct LogLine;
struct LogLineBuilder;
struct SurfaceProgress;
struct SurfaceProgressBuilder;
struct CtrlEnvelope;
struct CtrlEnvelopeBuilder;
@@ -506,11 +509,12 @@ enum class CtrlMsg : uint8_t {
Refuse = 11,
LogFlush = 12,
DataBind = 13,
SurfaceProgress = 14,
MIN = NONE,
MAX = DataBind
MAX = SurfaceProgress
};
inline const CtrlMsg (&EnumValuesCtrlMsg())[14] {
inline const CtrlMsg (&EnumValuesCtrlMsg())[15] {
static const CtrlMsg values[] = {
CtrlMsg::NONE,
CtrlMsg::Hello,
@@ -525,13 +529,14 @@ inline const CtrlMsg (&EnumValuesCtrlMsg())[14] {
CtrlMsg::LogLine,
CtrlMsg::Refuse,
CtrlMsg::LogFlush,
CtrlMsg::DataBind
CtrlMsg::DataBind,
CtrlMsg::SurfaceProgress
};
return values;
}
inline const char * const *EnumNamesCtrlMsg() {
static const char * const names[15] = {
static const char * const names[16] = {
"NONE",
"Hello",
"Welcome",
@@ -546,13 +551,14 @@ inline const char * const *EnumNamesCtrlMsg() {
"Refuse",
"LogFlush",
"DataBind",
"SurfaceProgress",
nullptr
};
return names;
}
inline const char *EnumNameCtrlMsg(CtrlMsg e) {
if (::flatbuffers::IsOutRange(e, CtrlMsg::NONE, CtrlMsg::DataBind)) return "";
if (::flatbuffers::IsOutRange(e, CtrlMsg::NONE, CtrlMsg::SurfaceProgress)) return "";
const size_t index = static_cast<size_t>(e);
return EnumNamesCtrlMsg()[index];
}
@@ -613,6 +619,10 @@ template<> struct CtrlMsgTraits<MobileGL::Wire::DataBind> {
static const CtrlMsg enum_value = CtrlMsg::DataBind;
};
template<> struct CtrlMsgTraits<MobileGL::Wire::SurfaceProgress> {
static const CtrlMsg enum_value = CtrlMsg::SurfaceProgress;
};
template <bool B = false>
bool VerifyCtrlMsg(::flatbuffers::VerifierTemplate<B> &verifier, const void *obj, CtrlMsg type);
template <bool B = false>
@@ -2220,6 +2230,64 @@ inline ::flatbuffers::Offset<LogLine> CreateLogLineDirect(
text__);
}
struct SurfaceProgress FLATBUFFERS_FINAL_CLASS : private ::flatbuffers::Table {
typedef SurfaceProgressBuilder Builder;
struct Traits;
enum FlatBuffersVTableOffset FLATBUFFERS_VTABLE_UNDERLYING_TYPE {
VT_SEQ = 4,
VT_ELAPSEDMS = 6
};
uint64_t seq() const {
return GetField<uint64_t>(VT_SEQ, 0);
}
uint32_t elapsedMs() const {
return GetField<uint32_t>(VT_ELAPSEDMS, 0);
}
template <bool B = false>
bool Verify(::flatbuffers::VerifierTemplate<B> &verifier) const {
return VerifyTableStart(verifier) &&
VerifyField<uint64_t>(verifier, VT_SEQ, 8) &&
VerifyField<uint32_t>(verifier, VT_ELAPSEDMS, 4) &&
verifier.EndTable();
}
};
struct SurfaceProgressBuilder {
typedef SurfaceProgress Table;
::flatbuffers::FlatBufferBuilder &fbb_;
::flatbuffers::uoffset_t start_;
void add_seq(uint64_t seq) {
fbb_.AddElement<uint64_t>(SurfaceProgress::VT_SEQ, seq, 0);
}
void add_elapsedMs(uint32_t elapsedMs) {
fbb_.AddElement<uint32_t>(SurfaceProgress::VT_ELAPSEDMS, elapsedMs, 0);
}
explicit SurfaceProgressBuilder(::flatbuffers::FlatBufferBuilder &_fbb)
: fbb_(_fbb) {
start_ = fbb_.StartTable();
}
::flatbuffers::Offset<SurfaceProgress> Finish() {
const auto end = fbb_.EndTable(start_);
auto o = ::flatbuffers::Offset<SurfaceProgress>(end);
return o;
}
};
inline ::flatbuffers::Offset<SurfaceProgress> CreateSurfaceProgress(
::flatbuffers::FlatBufferBuilder &_fbb,
uint64_t seq = 0,
uint32_t elapsedMs = 0) {
SurfaceProgressBuilder builder_(_fbb);
builder_.add_seq(seq);
builder_.add_elapsedMs(elapsedMs);
return builder_.Finish();
}
struct SurfaceProgress::Traits {
using type = SurfaceProgress;
static auto constexpr Create = CreateSurfaceProgress;
};
struct CtrlEnvelope FLATBUFFERS_FINAL_CLASS : private ::flatbuffers::Table {
typedef CtrlEnvelopeBuilder Builder;
struct Traits;
@@ -2273,6 +2341,9 @@ struct CtrlEnvelope FLATBUFFERS_FINAL_CLASS : private ::flatbuffers::Table {
const MobileGL::Wire::DataBind *msg_as_DataBind() const {
return msg_type() == MobileGL::Wire::CtrlMsg::DataBind ? static_cast<const MobileGL::Wire::DataBind *>(msg()) : nullptr;
}
const MobileGL::Wire::SurfaceProgress *msg_as_SurfaceProgress() const {
return msg_type() == MobileGL::Wire::CtrlMsg::SurfaceProgress ? static_cast<const MobileGL::Wire::SurfaceProgress *>(msg()) : nullptr;
}
template <bool B = false>
bool Verify(::flatbuffers::VerifierTemplate<B> &verifier) const {
return VerifyTableStart(verifier) &&
@@ -2335,6 +2406,10 @@ template<> inline const MobileGL::Wire::DataBind *CtrlEnvelope::msg_as<MobileGL:
return msg_as_DataBind();
}
template<> inline const MobileGL::Wire::SurfaceProgress *CtrlEnvelope::msg_as<MobileGL::Wire::SurfaceProgress>() const {
return msg_as_SurfaceProgress();
}
struct CtrlEnvelopeBuilder {
typedef CtrlEnvelope Table;
::flatbuffers::FlatBufferBuilder &fbb_;
@@ -2429,6 +2504,10 @@ inline bool VerifyCtrlMsg(::flatbuffers::VerifierTemplate<B> &verifier, const vo
auto ptr = reinterpret_cast<const MobileGL::Wire::DataBind *>(obj);
return verifier.VerifyTable(ptr);
}
case CtrlMsg::SurfaceProgress: {
auto ptr = reinterpret_cast<const MobileGL::Wire::SurfaceProgress *>(obj);
return verifier.VerifyTable(ptr);
}
default: return true;
}
}
MobileGL/MG_Remote/Protocol/mg_protocol_base.h
+2 -1
View File
@@ -64,7 +64,8 @@ extern "C" {
// it runs as ProtocolSchema.RevisionPinsDigest (label unit) and in CI's flatc-check job. After a
// bump: `python3 scripts/ci/protocol_revision_pin.py --write` records the new row.
// 1 P7 wave 2-F, PH-7 (4): Welcome.dataNonce and the DataBind message.
#define MOBILEGL_PROTOCOL_CONTROL_REVISION 1
// 2 P7 (p7/spawnhang): the SurfaceProgress message.
#define MOBILEGL_PROTOCOL_CONTROL_REVISION 2
#define MOBILEGL_ABI_VERSION(major, minor) (((uint32_t)(major) << 16) | (uint32_t)(minor))
#define MOBILEGL_ABI_MAJOR_OF(version) ((uint32_t)(version) >> 16)
MobileGL/MG_Remote/Protocol/protocol.fbs
+14
View File
@@ -340,6 +340,19 @@ table LogLine {
text: string;
}
// P7 (p7/spawnhang). THE SERVER IS STILL RUNNING THE CLIENT'S SURFACE OP. Sent only by the
// server's control pump, only while its apply thread is running a SurfaceOp it has TAKEN, and
// only before that op's SurfaceReply - once per progress interval after the op has run that long
// (ServerLoop.cpp, kControlProgressIntervalMs). It is how a client tells a server that is BUSY
// with its op (a cold native bring-up inside the first surface creation or MakeCurrent: eglInitialize
// loading a software rasteriser off a cold disk) from one that is SILENT: the client's reply budget
// restarts on each report, up to a ceiling. A server that never took the op, or is frozen, sends
// none and still times out by name (CONTRACT-P6 5.4 D5b).
table SurfaceProgress {
seq: ulong; // the SurfaceOp.seq being run
elapsedMs: uint; // since the op was posted to the apply thread
}
// ---------------------------------------------------------------------------
// Envelope
// ---------------------------------------------------------------------------
@@ -363,6 +376,7 @@ union CtrlMsg {
Refuse,
LogFlush,
DataBind,
SurfaceProgress,
}
table CtrlEnvelope {
MobileGL/MG_Remote/Server/ServerLoop.cpp
+44 -1
View File
@@ -633,9 +633,21 @@ namespace MobileGL::MG_Remote::Server {
// The dispatch runs OUTSIDE the lock, exactly as the old work(user) did, and fills the
// frame's reply half; the reply is then published back into the slot under the lock so
// the poster's copy-out after m_controlDone sees it.
const auto dispatchStart = std::chrono::steady_clock::now();
const MobileGLResult result = ApplySurfaceControlFrame(
frame, m_controlProbeHook.load(std::memory_order_acquire),
m_controlProbeUser.load(std::memory_order_acquire));
// p7/spawnhang: A SLOW DISPATCH NAMES ITSELF. The first surface creation / MakeCurrent is
// where a lazy native bring-up runs, and on a cold CI runner it outran the client's whole
// reply budget with nothing in this log to say so - the investigation had to infer it.
const auto dispatchMs = std::chrono::duration_cast<std::chrono::milliseconds>(
std::chrono::steady_clock::now() - dispatchStart).count();
if (dispatchMs >= static_cast<long long>(kSlowControlDispatchMs)) {
MGLOG_W("MG_Remote server: %s seq %llu ran %lld ms on mgl-srv-apply (a lazy native "
"bring-up runs inside the first surface creation or MakeCurrent)",
SurfaceControlOpName(frame.kind), static_cast<unsigned long long>(frame.seq),
static_cast<long long>(dispatchMs));
}
{
const std::lock_guard<std::mutex> lock(m_controlMutex);
m_controlFrame = frame;
@@ -844,11 +856,42 @@ namespace MobileGL::MG_Remote::Server {
if (m_session != nullptr) {
m_session->DataLink()->ConsumerBell().Notify();
}
m_controlDone.wait(lock, [this] { return m_controlFinished; });
// p7/spawnhang: THE WAIT IS SLICED, AND A SLICE THE APPLY THREAD SPENT RUNNING THIS FRAME IS
// REPORTED (SetControlProgressSink). It used to be one untimed wait, so the poster - under
// spawn, the control pump in ServerMain, the only thread that talks to the client - was mute
// for as long as the dispatch ran, and a client could not tell a cold bring-up from a wedge.
// "Running" is read under this lock from the mailbox's own fields: the pump clears the
// shadow when it TAKES the frame (PumpControlRequest), and m_controlPending stays true until
// the reply is published under this same lock. Posted-but-not-taken says nothing. The sink
// runs without the lock, so a dispatch finishing meanwhile is not held up by the send; the
// predicate is re-asked on the way back in. Only the timing of the wakeups changed: the
// handshake, the C2 exit block's answer and the copy-out below are exactly as before.
const auto postedAt = std::chrono::steady_clock::now();
while (!m_controlDone.wait_for(lock, std::chrono::milliseconds(kControlProgressIntervalMs),
[this] { return m_controlFinished; })) {
const Bool running = m_controlPending && !m_controlPosted.load(std::memory_order_acquire);
const ControlProgressSink sink = m_progressSink;
void* const user = m_progressUser;
if (!running || sink == nullptr) continue;
const auto elapsedMs = std::chrono::duration_cast<std::chrono::milliseconds>(
std::chrono::steady_clock::now() - postedAt).count();
lock.unlock();
sink(user, frame.kind, frame.seq,
static_cast<Uint32>(std::min<long long>(elapsedMs, 0xFFFFFFFFll)));
lock.lock();
}
frame = m_controlFrame; // the reply half, written by the dispatch
return m_controlResult;
}
void ServerLoop::SetControlProgressSink(ControlProgressSink sink, void* user) {
// Under the mailbox's lock, which the poster holds when it reads the pair, so a sink is
// never called with another sink's user.
const std::lock_guard<std::mutex> lock(m_controlMutex);
m_progressSink = sink;
m_progressUser = user;
}
MobileGLResult ServerLoop::RunProbeOnApplyThreadForTesting(ControlProbeHook hook, void* user) {
SurfaceControlFrame frame;
frame.kind = SurfaceControlOp::ProbeForTesting;
MobileGL/MG_Remote/Server/ServerLoop.h
+26
View File
@@ -249,6 +249,28 @@ namespace MobileGL::MG_Remote::Server {
using ControlProbeHook = MobileGLResult (*)(void* user);
MobileGLResult RunProbeOnApplyThreadForTesting(ControlProbeHook hook, void* user);
// P7 (p7/spawnhang). WHAT A POSTER SAYS WHILE THE APPLY THREAD RUNS ITS FRAME.
//
// A posted frame is waited for in slices of kControlProgressIntervalMs, and after every
// slice in which the apply thread is RUNNING it - taken, not yet answered - the poster calls
// this sink with the frame's kind, its seq and how long ago it was posted, WITHOUT
// m_controlMutex held. ServerMain installs one that sends Wire::SurfaceProgress on the
// control connection: that is how a spawn / TCP client tells a server BUSY with its op (a
// cold native bring-up - eglInitialize loading a software rasteriser off a cold disk ran
// ~20 s on a CI runner) from a SILENT one, and restarts its reply budget. A frame posted but
// NOT TAKEN reports nothing, because that silence is exactly what the client's budget
// exists to name. Null (inproc, and every case that does not set one): the slices are
// waited out and nothing is said. Read on the posting thread, set from any (both under
// m_controlMutex).
using ControlProgressSink = void (*)(void* user, SurfaceControlOp kind, Uint64 seq, Uint32 elapsedMs);
void SetControlProgressSink(ControlProgressSink sink, void* user);
// Well inside the smallest default reply budget (MOBILEGL_IPC_CONTROL_TIMEOUT_MS, 5000),
// and a frame's worth of bytes per interval only while an op runs that long.
static constexpr Uint32 kControlProgressIntervalMs = 250;
// A dispatch that runs at least this long is logged, with its op, seq and duration, on the
// apply thread when it returns - the line the retrace-split investigation did not have.
static constexpr Uint32 kSlowControlDispatchMs = 1000;
// How many frames this loop has dispatched (every kind, probe included). Reset by
// Start(). The frame channel's own red-once handle: a forwarder that stopped posting
// frames leaves this unmoved.
@@ -451,6 +473,10 @@ namespace MobileGL::MG_Remote::Server {
// published; held until its reply returns. Re-entrant probes use call-local arguments.
std::atomic<ControlProbeHook> m_controlProbeHook{nullptr};
std::atomic<void*> m_controlProbeUser{nullptr};
// SetControlProgressSink's pair (p7/spawnhang). Guarded by m_controlMutex: the poster reads
// both while it holds that lock between slices, so the pair is always read whole.
ControlProgressSink m_progressSink = nullptr;
void* m_progressUser = nullptr;
// The BOUNDED join's other half. std::thread::join has no deadline, so a lost wakeup
// would wedge CI rather than fail it; the thread signals here last and Stop() waits
MobileGL/MG_Remote/Server/ServerMain.cpp
+21
View File
@@ -57,6 +57,22 @@ void ForwardLog(void* user, const char* text) {
(void)transport.SendFrame({builder.GetBufferPointer(), builder.GetSize()});
}
// p7/spawnhang. THE PROGRESS REPORT: Wire::SurfaceProgress, sent by the thread that posted the op
// - RunSession's control pump, waiting in ServerApplyWireSurfaceOp - after each
// ServerLoop::kControlProgressIntervalMs that mgl-srv-apply has spent running it
// (ServerLoop::SetControlProgressSink). The client's reply budget restarts on each one, so a cold
// native bring-up that outruns MOBILEGL_IPC_COLD_START_MS is waited for instead of being reported
// ALIVE BUT SILENT (retrace-split run 35912252677). A send failure is left to the reply's send,
// which already ends the session on it.
void SendSurfaceProgress(void* user, Server::SurfaceControlOp, std::uint64_t seq, std::uint32_t elapsedMs) {
auto& transport = *static_cast<SocketTransport*>(user);
flatbuffers::FlatBufferBuilder builder(64);
auto progress = Protocol::CreateSurfaceProgress(builder, seq, elapsedMs);
auto envelope = Protocol::CreateCtrlEnvelope(builder, Protocol::CtrlMsg::SurfaceProgress, progress.Union());
Protocol::FinishCtrlEnvelopeBuffer(builder, envelope);
(void)transport.SendFrame({builder.GetBufferPointer(), builder.GetSize()});
}
void RefuseBusy(SocketTransport& transport, const char* detail) {
// Unread Hello bytes can make close send RST and discard our Refuse.
std::uint64_t bytes = 0;
@@ -459,6 +475,10 @@ void DelaySessionHandshakeForTest() {
if (tcp && (!forwarding || std::strcmp(forwarding, "0") != 0))
MobileGL::MG_Util::Debug::SetLogForwarder(&ForwardLog, control.get());
auto& loop = Server::ServerLoopInstance();
// p7/spawnhang: this thread posts every surface op the client sends (ServerApplyWireSurfaceOp,
// below) and is the one that says "still running" while the apply thread runs it. Cleared
// after the loop, on this same thread, so no post can be in flight when it goes.
loop.SetControlProgressSink(&SendSurfaceProgress, control.get());
if (loop.Start(session) != MOBILEGL_OK) ::_exit(70);
WireLogError("MG_Remote server: pid=%d transport=spawn role=server ready control=%s data=%s",
selfPid, tcp ? "tcp" : "unix", tcp ? "stream" : "shm");
@@ -595,6 +615,7 @@ void DelaySessionHandshakeForTest() {
break;
}
}
loop.SetControlProgressSink(nullptr, nullptr);
loop.Stop();
// Publish the final server window while log forwarding is still attached.
MobileGL::MG_Util::PipeStats::Shutdown();
MobileGL/MG_Test/Wire/ServerLoopTest.cpp
+170
View File
@@ -75,6 +75,7 @@
#include <fstream>
#include <functional>
#include <memory>
#include <mutex>
#include <string>
#include <thread>
#include <vector>
@@ -444,6 +445,175 @@ TEST(ServerLoopTest, TheControlShadowIsClearedWhenThePumpTakesTheRequest) {
fixture.Stop();
}
// =====================================================================================
// p7/spawnhang: the poster reports a frame the apply thread is RUNNING, and only that
// =====================================================================================
//
// retrace-split run 35912252677: a spawned server's first CreatePbufferSurface ran its lazy native
// bring-up (eglInitialize, a software rasteriser read off a cold runner disk) for ~20 s - the whole
// cold-start reply budget - and the client, which could not tell a busy server from a wedged one,
// gave up while the server was about to answer. The poster now waits in slices and, after every
// slice the apply thread spent RUNNING its frame, tells the installed sink (ServerMain's sends
// Wire::SurfaceProgress; ServerSpawnTest's cold-bring-up case is the end-to-end half). Two
// halves, each red for its own reason:
// - a frame the apply thread runs for several slices IS reported, with its kind, one seq and a
// growing elapsed time - with the old untimed wait there is no report at all;
// - a frame POSTED BUT NOT TAKEN (the apply thread is held in a drain) is NOT, however long it
// waits: that silence is what the client's budget still names, and a poster that reported
// every slice regardless would turn a stuck apply thread into an endless wait.
namespace {
struct ProgressLog {
struct Report {
Server::SurfaceControlOp kind;
Uint64 seq;
Uint32 elapsedMs;
};
std::mutex mutex;
std::vector<Report> reports;
static void Sink(void* user, Server::SurfaceControlOp kind, Uint64 seq, Uint32 elapsedMs) {
auto* log = static_cast<ProgressLog*>(user);
const std::lock_guard<std::mutex> lock(log->mutex);
log->reports.push_back(Report{kind, seq, elapsedMs});
}
std::vector<Report> Snapshot() {
const std::lock_guard<std::mutex> lock(mutex);
return reports;
}
};
// Six slices: long enough that a poster oversleeping by most of a second under a loaded `-j`
// still wakes at least once while the frame runs.
constexpr Uint32 kProgressProbeRunMs = 6 * Server::ServerLoop::kControlProgressIntervalMs;
// Posts `hook` from a helper thread (N-9's reason: a lost post must be said in the case's own
// words, not as ctest's timeout) and waits for its answer within `deadlineMs`.
bool PostProbeAndWait(Server::ServerLoop::ControlProbeHook hook, void* user, Uint32 deadlineMs,
MobileGLResult* rc, long long* waitedMs) {
std::atomic<Bool> answered{false};
std::thread poster([&] {
const auto start = std::chrono::steady_clock::now();
*rc = Server::ServerLoopInstance().RunProbeOnApplyThreadForTesting(hook, user);
*waitedMs = std::chrono::duration_cast<std::chrono::milliseconds>(
std::chrono::steady_clock::now() - start).count();
answered.store(true, std::memory_order_release);
});
const auto deadline = std::chrono::steady_clock::now() + std::chrono::milliseconds(deadlineMs);
while (!answered.load(std::memory_order_acquire) && std::chrono::steady_clock::now() < deadline) {
std::this_thread::sleep_for(std::chrono::milliseconds(1));
}
const Bool ok = answered.load(std::memory_order_acquire);
if (!ok) Server::ServerLoopInstance().Stop(); // frees the poster (C2's exit block answers it)
poster.join();
return ok;
}
} // namespace
TEST(ServerLoopTest, AFrameTheApplyThreadIsRunningIsReportedToTheProgressSinkWhileItRuns) {
ServerFixture fixture;
ASSERT_TRUE(fixture.Handshake());
ASSERT_TRUE(fixture.StartLoop());
Server::ServerLoop& loop = Server::ServerLoopInstance();
ProgressLog log;
loop.SetControlProgressSink(&ProgressLog::Sink, &log);
MobileGLResult rc = MOBILEGL_ERR_INVALID_ARGUMENT;
long long waitedMs = 0;
const Bool answered = PostProbeAndWait(
+[](void*) -> MobileGLResult {
std::this_thread::sleep_for(std::chrono::milliseconds(kProgressProbeRunMs));
return MOBILEGL_OK;
},
nullptr, 20000, &rc, &waitedMs);
loop.SetControlProgressSink(nullptr, nullptr);
// EXPECT, never ASSERT, from here to Stop(): a case that returns early leaves the apply thread
// parked and the process does not exit.
EXPECT_TRUE(answered) << "a posted probe was never answered";
EXPECT_EQ(rc, MOBILEGL_OK);
const std::vector<ProgressLog::Report> reports = log.Snapshot();
EXPECT_FALSE(reports.empty())
<< "the apply thread ran the frame for " << waitedMs << " ms and the poster said nothing: "
<< "a spawn client would have seen silence for the whole of a cold bring-up and given up "
"on a server that was about to answer";
for (std::size_t i = 0; i < reports.size(); ++i) {
EXPECT_EQ(reports[i].kind, Server::SurfaceControlOp::ProbeForTesting) << "report " << i;
EXPECT_NE(reports[i].seq, 0u) << "report " << i << " names no seq";
EXPECT_EQ(reports[i].seq, reports.front().seq) << "one frame, one seq (report " << i << ")";
EXPECT_GE(reports[i].elapsedMs, Server::ServerLoop::kControlProgressIntervalMs)
<< "report " << i << " came before one whole interval had passed";
if (i != 0) EXPECT_GT(reports[i].elapsedMs, reports[i - 1].elapsedMs) << "report " << i;
}
// THE SERVER LOG NAMES THE SLOW DISPATCH TOO: the line the investigation did not have.
const std::string text = ReadLog();
EXPECT_NE(text.find("ProbeForTesting seq"), std::string::npos)
<< "a dispatch that ran " << waitedMs << " ms was not named in the server log";
EXPECT_NE(text.find("ms on mgl-srv-apply"), std::string::npos);
fixture.Stop();
}
TEST(ServerLoopTest, AFramePostedButNotYetTakenIsNotReportedHoweverLongItWaits) {
ServerFixture fixture;
ASSERT_TRUE(fixture.Handshake());
ASSERT_TRUE(fixture.StartLoop());
Server::ServerLoop& loop = Server::ServerLoopInstance();
// HOLD THE APPLY THREAD IN A DRAIN, where it cannot take a posted frame: the retire hook runs
// on the apply thread after a record is applied and before it is retired (DrainRing).
static std::atomic<Bool> s_inDrain{false};
static std::atomic<Bool> s_releaseDrain{false};
s_inDrain.store(false);
s_releaseDrain.store(false);
loop.SetBeforeRetireHookForTesting(+[] {
s_inDrain.store(true, std::memory_order_release);
const auto deadline = std::chrono::steady_clock::now() + std::chrono::seconds(10);
while (!s_releaseDrain.load(std::memory_order_acquire) && std::chrono::steady_clock::now() < deadline) {
std::this_thread::sleep_for(std::chrono::milliseconds(1));
}
});
const MG_Pipe::MGPClear clear = WholeFramebufferClear();
const Uint64 seq = fixture.encoder.EncodeRecord(MG_Pipe::MGPWireOp::Clear, &clear, sizeof(clear));
ASSERT_NE(seq, Codec::kInvalidSeq);
fixture.encoder.Publish();
fixture.producer.PublishAndNotify(seq);
const auto holdDeadline = std::chrono::steady_clock::now() + std::chrono::seconds(5);
while (!s_inDrain.load(std::memory_order_acquire) && std::chrono::steady_clock::now() < holdDeadline) {
std::this_thread::sleep_for(std::chrono::milliseconds(1));
}
ASSERT_TRUE(s_inDrain.load(std::memory_order_acquire)) << "the apply thread never reached the drain";
ProgressLog log;
loop.SetControlProgressSink(&ProgressLog::Sink, &log);
// The probe is posted from a helper while the drain holds the apply thread for six slices,
// then the drain is let go from here and the probe - instant once taken - is answered.
std::thread releaser([] {
std::this_thread::sleep_for(std::chrono::milliseconds(kProgressProbeRunMs));
s_releaseDrain.store(true, std::memory_order_release);
});
MobileGLResult rc = MOBILEGL_ERR_INVALID_ARGUMENT;
long long waitedMs = 0;
const Bool answered =
PostProbeAndWait(+[](void*) -> MobileGLResult { return MOBILEGL_OK; }, nullptr, 20000, &rc, &waitedMs);
releaser.join();
loop.SetControlProgressSink(nullptr, nullptr);
loop.SetBeforeRetireHookForTesting(nullptr);
EXPECT_TRUE(answered) << "a posted probe was never answered once the drain let go";
EXPECT_EQ(rc, MOBILEGL_OK);
// THE WINDOW WAS REAL: the probe waited behind the drain for several slices.
EXPECT_GE(waitedMs, static_cast<long long>(2 * Server::ServerLoop::kControlProgressIntervalMs))
<< "the probe was answered after " << waitedMs << " ms, so it was never posted-and-waiting "
"long enough for this case to say anything";
EXPECT_TRUE(log.Snapshot().empty())
<< log.Snapshot().size() << " progress report(s) for a frame the apply thread had NOT "
<< "taken: the poster reports every slice, so a client would wait on a server whose apply "
"thread never started its op";
fixture.Stop();
}
// Re-entrancy is not a deadlock: ~BackendObject_DirectGLES reaches ReleaseEGLResources FROM the
// apply thread, so a post from there must run inline.
TEST(ServerLoopTest, APostFromTheApplyThreadItselfRunsInlineRatherThanDeadlocking) {
MobileGL/MG_Test/Wire/ServerSpawnTest.cpp
+110
View File
@@ -33,6 +33,7 @@
// SCM_RIGHTS works across - the mechanism the four segments ride on, proven
// the boundary before the data plane needs it.
#include <Config.h>
#include <MG_Remote/Client/ClientSession.h>
#include <MG_Remote/FatalFunnel.h>
#include <MG_Remote/Server/ServerLoop.h>
@@ -968,6 +969,115 @@ TEST(ServerSpawnTest, AnEglControlOpCrossesToTheOtherProcessAndAnswers) {
ASSERT_EQ(Server::ReapServer(session.server, 5000, &exitCode), MOBILEGL_OK);
}
namespace {
// p7/spawnhang. The client's two reply budgets, shortened for one case and put back after it,
// and the harness's headless EGL for the server it starts (EventForfeitPeerTest's PinHeadlessEgl:
// the first surface creation runs a real eglInitialize, and a runner has no DISPLAY).
struct ShortReplyBudgets {
MobileGL::Uint32 steady = MobileGL::MG_Config::Ipc.ControlTimeoutMs;
MobileGL::Uint32 cold = MobileGL::MG_Config::Ipc.ColdStartMs;
explicit ShortReplyBudgets(MobileGL::Uint32 ms) {
MobileGL::MG_Config::Ipc.ControlTimeoutMs = ms;
MobileGL::MG_Config::Ipc.ColdStartMs = ms;
}
~ShortReplyBudgets() {
MobileGL::MG_Config::Ipc.ControlTimeoutMs = steady;
MobileGL::MG_Config::Ipc.ColdStartMs = cold;
}
};
std::string HeadlessEglPlatform() {
const char* pinned = std::getenv("EGL_PLATFORM");
return pinned != nullptr ? pinned : "surfaceless";
}
Server::SurfaceControlFrame PbufferCreation() {
Server::SurfaceControlFrame frame{};
frame.kind = Server::SurfaceControlOp::CreatePbufferSurface;
frame.surface = 1;
frame.width = 16;
frame.height = 16;
return frame;
}
long long MillisecondsSince(std::chrono::steady_clock::time_point start) {
return std::chrono::duration_cast<std::chrono::milliseconds>(std::chrono::steady_clock::now() - start)
.count();
}
} // namespace
// p7/spawnhang: retrace-split run 35912252677, in miniature and in seconds instead of twenty.
//
// A spawned server brings its native backend up lazily, INSIDE the first surface creation
// (eglInitialize). On a cold CI runner that read a software rasteriser off disk for ~20 s - the
// whole MOBILEGL_IPC_COLD_START_MS - and the client, which measured the op's DURATION against a
// budget meant for SILENCE, reported the server ALIVE BUT SILENT and failed the pbuffer with
// EGL_BAD_ALLOC while the server was about to answer. The server now reports progress while its
// apply thread runs an op it has taken (Wire::SurfaceProgress), and each report restarts the
// client's budget.
//
// Here the server's own test lever holds its first CreatePbufferSurface for 3000 ms and the client's
// budgets are 1000 ms - the same shape as 20 s of bring-up against a 20 s budget, three times over.
// Against the client and server as they were (one untimed wait on the server, one deadline on the
// client) the op comes back TIMEOUT at ~1000 ms: the CI failure, named the way CI named it. With
// the progress reports it comes back answered, after the lever let it go.
TEST(ServerSpawnTest, AColdBringUpThatOutlastsTheReplyBudgetIsWaitedForBecauseTheServerReportsProgress) {
const ScopedEnvironment lever("MOBILEGL_TEST_DELAY_FIRST_BRINGUP_MS", "3000");
const ScopedEnvironment headless("EGL_PLATFORM", HeadlessEglPlatform());
const ShortReplyBudgets budgets(1000);
Session session;
ASSERT_TRUE(Bring("coldprogress", &session));
ScopedSessionCleanup cleanup{session};
ASSERT_EQ(Handshake(session), MOBILEGL_OK);
Server::SurfaceControlFrame frame = PbufferCreation();
const auto start = std::chrono::steady_clock::now();
const MobileGLResult rc = Client::ClientSessionInstance().RunRemoteSurfaceControlFrame(frame);
const long long elapsedMs = MillisecondsSince(start);
// THE ROUND TRIP, not the EGL answer: whether a headless runner can make a pbuffer is not
// this case's question (`ok` is whatever the driver said); whether the reply was WAITED FOR is.
EXPECT_EQ(rc, MOBILEGL_OK)
<< "the op came back rc=" << static_cast<int>(rc) << " after " << elapsedMs
<< " ms: the client gave up on a server that was still running it - the retrace-split "
"failure (\"ALIVE BUT SILENT - no SurfaceReply for CreatePbufferSurface seq 2\")";
if (rc == MOBILEGL_OK) {
EXPECT_GE(elapsedMs, 3000)
<< "the reply came back before the server's lever released the op, so the lever did not "
"hold the bring-up and this case proved nothing about waiting for one";
}
EXPECT_FALSE(Client::ClientSession::DeviceLost()) << "a slow server is not a lost device (5.4)";
}
// The other half, and the reason the budget still exists: a server that is ALIVE BUT FROZEN reports
// nothing, so the same op against it still ends at the budget, by name, rather than waiting on
// progress that never comes. SIGSTOP freezes the whole process - the pump that would report as well
// as the apply thread - and keeps every descriptor open, so it is not a hangup either.
TEST(ServerSpawnTest, AFrozenServerReportsNoProgressAndTheOpStillTimesOutAtTheBudget) {
const ScopedEnvironment headless("EGL_PLATFORM", HeadlessEglPlatform());
const ShortReplyBudgets budgets(1000);
Session session;
ASSERT_TRUE(Bring("frozenprogress", &session));
ScopedSessionCleanup cleanup{session};
ASSERT_EQ(Handshake(session), MOBILEGL_OK);
ASSERT_EQ(::kill(session.server.pid, SIGSTOP), 0);
Server::SurfaceControlFrame frame = PbufferCreation();
const auto start = std::chrono::steady_clock::now();
const MobileGLResult rc = Client::ClientSessionInstance().RunRemoteSurfaceControlFrame(frame);
const long long elapsedMs = MillisecondsSince(start);
(void)::kill(session.server.pid, SIGCONT);
EXPECT_EQ(rc, MOBILEGL_ERR_TIMEOUT)
<< "a frozen server was not timed out (rc=" << static_cast<int>(rc) << ")";
EXPECT_LT(elapsedMs, 10000)
<< "took " << elapsedMs << " ms against a 1000 ms budget: something other than a progress "
"report restarted the wait";
EXPECT_FALSE(Client::ClientSession::DeviceLost()) << "a frozen server is not a lost device (5.4)";
}
TEST(ServerSpawnTest, TheHandshakeCarriesTwoDifferentProcessIdsAndNotTwoZeroes) {
// CONTRACT-P6 4.3. Hello::pid was hard-coded 0 and Welcome::serverPid ECHOED it back, so the
// handshake carried 0 and 0 and named nothing at all. Both now carry real ids, which makes
scripts/ci/protocol_revision_pins.json
+2 -1
View File
@@ -1,3 +1,4 @@
{
"1": "7fc859f7fa756818401f4162e7d49a25d430b91e44d89c297321e3cb36c69638"
"1": "7fc859f7fa756818401f4162e7d49a25d430b91e44d89c297321e3cb36c69638",
"2": "b30928e6fc93ddc015fd86f634a6820f775a6f2f6de5a848d273981e706b2597"
}