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

[Fix] (MG_Remote): P9 W3 - a FATAL forward waits once per stall rather than once per line (MGLOG_F also marks survivable conditions), and F2 proves the flood got through on a live connection, inside TCP_USER_TIMEOUT

Browse Source
This commit is contained in:
swung0x48
2026-09-29 02:42:20 -04:00
parent 6bcfb1fba1
commit 24560ffe81
4 changed files with 82 additions and 9 deletions
Download Patch File Download Diff File Expand all files Collapse all files
MobileGL/MG_Remote/Transport/LogForward.cpp
+12
View File
@@ -189,10 +189,22 @@ namespace MobileGL::MG_Remote::Transport {
return;
}
// FATAL: wait - bounded - until the sender has written this line and everything before it.
//
// ONCE PER STALL, NOT ONCE PER LINE. MGLOG_F is not only the last word before an abort: the
// tree also uses it for survivable conditions (the EGL loader's "Failed to load EGL function"
// lines, several in a row). If an earlier FATAL wait already ran out and the sender has not
// written a single item since, the peer is still not reading and a second wait would only
// spend another fatalFlushMs of this thread's time on the same answer - so it is counted as
// a timeout at once. The line itself is queued either way.
if (m_fatalGaveUpAtWritten == m_writtenSeq) {
++m_counters.fatalFlushTimeouts;
return;
}
const auto deadline = started + std::chrono::milliseconds(m_limits.fatalFlushMs);
if (!m_cv.wait_until(lock, deadline,
[this, seq] { return m_writtenSeq >= seq || m_counters.transportFailed; })) {
++m_counters.fatalFlushTimeouts;
m_fatalGaveUpAtWritten = m_writtenSeq;
}
}
MobileGL/MG_Remote/Transport/LogForward.h
+7 -2
View File
@@ -43,8 +43,10 @@
// * FATAL is ERROR plus a wait: the logging thread is about to abort, and a line still in the
// queue when it does is a line the client never gets - the one it most needs. So a FATAL
// Offer waits until the sender has written everything up to and including it, for at most
// fatalFlushMs, and then returns whether or not the peer took it. (Log.cpp hands a FATAL line
// over outside the log mutex, so that wait holds nobody else's line.)
// fatalFlushMs, and then returns whether or not the peer took it - and once such a wait has run
// out, later FATAL lines do not wait again until the sender has written something (MGLOG_F also
// marks survivable conditions, several in a row). (Log.cpp hands a FATAL line over outside the
// log mutex, so that wait holds nobody else's line.)
// * A LogFlush acknowledgement (OfferControlFrame) is queued BEHIND every line offered before
// it, which is what makes MGPipeSyncPeerLog's promise ("every line before the flush is in the
// file when the ack arrives") still true now that a line is not on the wire when MGLOG returns.
@@ -176,6 +178,9 @@ namespace MobileGL::MG_Remote::Transport {
std::uint64_t m_errorBytes = 0;
std::uint64_t m_nextSeq = 1;
std::uint64_t m_writtenSeq = 0; // the seq of the last item the sender finished with
// m_writtenSeq when a FATAL wait last ran out; while it has not moved since, the next FATAL
// does not wait again (Offer). ~0 = no wait has run out.
std::uint64_t m_fatalGaveUpAtWritten = ~0ull;
std::uint64_t m_urgent = 0; // FATAL lines and control frames queued: do not pace
// A gap not yet marked in the stream, per class.
std::uint64_t m_gapLossyLines = 0;
MobileGL/MG_Test/Wire/EventForfeitPeerTest.cpp
+27 -7
View File
@@ -148,8 +148,16 @@ namespace {
// instead of the server: this host's tcp_rmem lets a receive buffer autotune to 32 MiB, and a
// peer whose socket takes the whole flood is not a peer that stopped reading.
constexpr int kStalledReceiveBufferBytes = 16 * 1024;
// How long the apply thread gets to log the whole flood with nobody reading it. It needs well
// under a second; the budget is for a loaded runner.
// How long the apply thread gets to log the whole flood with nobody reading it: it needs about
// half a second here. THE CEILING IS NOT SLACK, IT IS THE KERNEL'S. SocketTransport sets
// TCP_USER_TIMEOUT to 5000 ms on every TCP connection (SocketTransport.cpp), so a peer that keeps
// a zero window for 5 s has its control connection aborted (ETIMEDOUT) - which ends ANY stall,
// including a forward that held the apply thread in a socket write the whole time (the red-once
// run: the flood "completed" at 5.4 s, after the abort released it). So "the flood got through
// while nobody read" only means "the apply thread was not held" if it happened well inside those
// 5 s, on a live connection.
constexpr std::uint32_t kFloodWithinMs = 4000;
// The overall budget for the undrained arm's forfeit and reap, which do not race the kernel.
constexpr std::uint32_t kFloodBudgetMs = 15000;
// The longest one forward may take a logging thread (the summary's max-offer-us). The channel
// spends a lock and a copy; a forward that waited on the peer would spend the whole stall.
@@ -977,8 +985,15 @@ namespace {
const int code = WaitChild(peer, std::chrono::milliseconds(5000));
releasePeer.pid = -1;
::close(synced[0]);
FAIL() << "the flood peer did not get its records out (child exit " << code << ")\n"
<< ServerLog(logBase).substr(0, 20000);
// In the undrained arm the peer's ResourceCreate / Respecify / SubData WAIT behind the
// flood (exit 14..16): the apply thread has to get through 400 flooding records to answer
// them, so a forward that holds it shows up here first.
FAIL() << "the flood peer did not get its records out (child exit " << code
<< (code >= kBufferCreate && code <= kBufferContent
? ": its wait behind the flood was never answered - the apply thread was held"
: "")
<< ")\n"
<< LineWith(ServerLog(logBase), "log forwarding ended");
}
const auto every = std::chrono::milliseconds(200);
@@ -987,12 +1002,17 @@ namespace {
// own log must reach the flood's last record: every one of the kFloodRecords records is
// applied (and logs its ERROR line) while the control connection takes no byte. A forward
// that waits on the socket stalls the apply thread a few MiB in, and this never arrives.
const long long reachedMs =
WaitForLog(logBase, kFloodErrorNeedle, kFloodRecords, std::chrono::milliseconds(kFloodBudgetMs), every);
const long long reachedMs = WaitForLog(logBase, kFloodErrorNeedle, kFloodRecords,
std::chrono::milliseconds(kFloodWithinMs),
std::chrono::milliseconds(50));
ASSERT_GE(reachedMs, 0) << "the apply thread did not get through the flood while its client was not "
"reading control - it was held by logging ("
<< Count(ServerLog(logBase), kFloodErrorNeedle) << " of " << kFloodRecords
<< " records' ERROR lines logged after " << kFloodBudgetMs << " ms)";
<< " records' ERROR lines logged after " << kFloodWithinMs << " ms)";
// ...and on a LIVE connection: not released by the kernel aborting a zero-window socket.
ASSERT_EQ(ServerLog(logBase).find("recv failed"), std::string::npos)
<< "the flood finished only after the control connection died - the stall was ended by "
"TCP_USER_TIMEOUT, not survived";
// (2) The peer reads again and synchronises its log.
const char go = 1;
ASSERT_EQ(::write(release[1], &go, 1), 1);
MobileGL/MG_Test/Wire/LogForwardTest.cpp
+36
View File
@@ -315,6 +315,35 @@ namespace {
EXPECT_EQ(CapturedLevelOf("w3-logger-marker client-side"), -1);
}
// The other kind: the in-process display server's SESSION-scoped forwarder (SetSessionLogForwarder),
// which forwards only from the thread that installed it and threads that opted in, OUTSIDE the
// log mutex. Same levels, including FATAL.
TEST(LogForwardLogger, TheSessionScopedForwarderGetsEachLevelToo) {
(void)LogBase();
std::thread session([] {
Debug::SetThreadLogRole(Debug::LogRole::Server);
Debug::SetSessionLogForwarder(&Capture, nullptr);
MGLOG_I("w3-session-marker info");
MGLOG_W("w3-session-marker warn");
MGLOG_E("w3-session-marker error");
MGLOG_F("w3-session-marker fatal");
// A server-role thread that did NOT opt in is not this session's: it forwards nothing.
std::thread other([] {
Debug::SetThreadLogRole(Debug::LogRole::Server);
MGLOG_E("w3-session-marker not-opted-in");
});
other.join();
Debug::SetLogForwarder(nullptr, nullptr);
Debug::SetThreadForwardsLogToPeer(false);
});
session.join();
EXPECT_EQ(CapturedLevelOf("w3-session-marker info"), MOBILEGL_LOG_LEVEL_INFO);
EXPECT_EQ(CapturedLevelOf("w3-session-marker warn"), MOBILEGL_LOG_LEVEL_WARN);
EXPECT_EQ(CapturedLevelOf("w3-session-marker error"), MOBILEGL_LOG_LEVEL_ERROR);
EXPECT_EQ(CapturedLevelOf("w3-session-marker fatal"), MOBILEGL_LOG_LEVEL_FATAL);
EXPECT_EQ(CapturedLevelOf("w3-session-marker not-opted-in"), -1);
}
TEST(LogForwardLogger, APeerLineIsFiledUnderTheLevelTheWireCarried) {
const std::string serverLog = Debug::RoleLogPath(LogBase().c_str(), Debug::LogRole::Server);
// A line the server formatted is written as it came - its header already names its level.
@@ -532,6 +561,13 @@ namespace {
EXPECT_GE(waited, 250);
EXPECT_LT(waited, 3000);
EXPECT_EQ(channel.Counters().fatalFlushTimeouts, 1u);
// A second FATAL while nothing has been written since: the stall is known, the line is
// queued and the Offer does not spend another bound on the same answer (MGLOG_F also
// marks survivable conditions, and they come in runs).
const auto again = Clock::now();
channel.Offer(MOBILEGL_LOG_LEVEL_FATAL, "fatal held again\n");
EXPECT_LT(MillisecondsSince(again), 150) << "a second FATAL waited out the bound again on a known stall";
EXPECT_EQ(channel.Counters().fatalFlushTimeouts, 2u);
}
}