diff --git a/MobileGL/MG_Remote/Server/ServerMain.cpp b/MobileGL/MG_Remote/Server/ServerMain.cpp index daff1f18..ca3841a7 100644 --- a/MobileGL/MG_Remote/Server/ServerMain.cpp +++ b/MobileGL/MG_Remote/Server/ServerMain.cpp @@ -46,6 +46,7 @@ #include // MG_Config::Transport - D1 pins it to Spawn in this process #include // D1c: MGPipeSetServerProcessRole #include +#include // step 1.6: the counters' latch, server-process half #include // MG_ConfigLoader::Init - the child loads its own config (step 1.5) #include @@ -188,6 +189,46 @@ extern "C" __attribute__((visibility("default"))) int mobilegl_server_main(int a // them; without it they are compiled in and permanently false, which is worse than absent // because it reads as coverage. MobileGL::MG_Pipe::MGPipeSetServerProcessRole(true); + // ---- 1.6. THE MGPIPE COUNTERS, and this is the ONLY call site outside + // MobileGL::Initialize(). + // + // GATE 8'S SERVER HALF WAS STRUCTURALLY ZERO WITHOUT THIS, and the shape of the + // defect is worth stating: the child never runs MobileGL::Initialize, so + // PipeStats::Init() - a step of it - never ran here, and g_pipeStatsEnabled + // stayed false. Every one of the ~80 `if (Enabled())` sites in the backends and + // in MG_Remote (ServerLoop's own ServerWaits/ServerParks publish included) + // compiled in and was permanently false in this process. The contract's + // mandatory "socket doorbell vs inproc condvar" number therefore had no server + // half under `spawn` at all, and its absence read exactly like a real zero: + // `wait[srv=0 srvpark=0]` is what "the server never waited" looks like too. + // + // IT GOES AFTER THE CONFIG LOAD AND AFTER THE ROLE IS STATED, and both halves + // of that order are load-bearing: + // + // * AFTER MG_ConfigLoader::Init, because Init() LATCHES the flag out of + // MG_Config::Features.PipeStats, and the parser does not exist until the + // line above has run. Calling it earlier would latch the static default + // (false) and the MOBILEGL_PIPE_STATS the launcher passed would be read by + // nobody - the same class of defect the config load itself used to have. + // * AFTER MGPipeSetServerProcessRole, because that is what makes the LOG SINK + // know this process is the server, and PipeStats' summary line is emitted + // through MGLOG_I. The sink resolves its role from MOBILEGL_IPC_ROLE (which + // the launcher sets and its envp scrub preserves) and would in fact be + // right either way, but ordering it this way means the line cannot be filed + // under the client by a future change to that resolution. What the contract + // requires - that the summary lands in `.server.log` - is asserted by + // the lane, not assumed from this comment. + // + // MOBILEGL_PIPE_STATS / _PERIOD / _FILE MEAN EXACTLY WHAT THEY MEAN IN THE + // CLIENT PROCESS, and that is the whole point of routing through Init(): all + // three are read from the child's own environment by the same parser and + // latched by the same function. Nothing about the stats channel is spawn-shaped. + // One asymmetry is real and intended: this process has no backend Present of + // its own, so its line cadence rides the present RECORDS it applies + // (PipeApplier -> DirectGLES/DirectVulkan Present -> OnPresent) rather than a + // swap the server does not perform. A spawn session that presents N times + // produces N windows here, which is the same N the client's own line counts. + MobileGL::MG_Util::PipeStats::Init(); WireLogError("MG_Remote server: pid=%d config loaded, backend=%d, Transport pinned to Spawn " "(D1: this process IS the server arm)", selfPid, static_cast(MobileGL::MG_Config::ActiveBackendType)); @@ -390,6 +431,15 @@ extern "C" __attribute__((visibility("default"))) int mobilegl_server_main(int a loop.Stop(); session.Close(); control->Shutdown(); + // Step 1.6's other half, and its position is the same argument MobileGL::Destroy + // makes: AFTER loop.Stop(), because the apply thread is what publishes + // ServerWaits / ServerParks and a dump taken while it still runs is a race; and + // BEFORE _exit, because _exit runs no atexit handler and this is the only place + // the server's run totals and its JSON dump can be written at all. Without it + // the server printed whatever windows its last period boundary happened to + // reach and lost the final one - the same "the last frame's numbers can be + // lost" case Init.cpp's Shutdown call exists to avoid on the client side. + MobileGL::MG_Util::PipeStats::Shutdown(); std::fflush(nullptr); ::_exit(0); } diff --git a/MobileGL/MG_Remote/Wire/PipeWireCodec.cpp b/MobileGL/MG_Remote/Wire/PipeWireCodec.cpp index d0b2224e..ad5e27ce 100644 --- a/MobileGL/MG_Remote/Wire/PipeWireCodec.cpp +++ b/MobileGL/MG_Remote/Wire/PipeWireCodec.cpp @@ -38,6 +38,10 @@ #include #include #include +// P6 gate 8's two wire counters. MG_Util is BELOW MG_Remote in the build order and the pull build +// has no MG_Remote at all, which is why every counter this file touches is behind +// #if MOBILEGL_PIPE_PUSH - the same guard the header's producer readings live under. +#include #include #include @@ -857,6 +861,24 @@ namespace MobileGL::MG_Remote::Wire { static_cast(m_stageCapacity)); } + // P6 GATE 8's FIRST NUMBER (CONTRACT-P6.md §9 item 8): the bytes this producer staged. The + // blob's OWN bytes are recorded, from here - where the request first becomes an allocation + // - because this is the ONE place every writer of SEG_STAGE passes through (StageBytes is + // the only caller, and every buffer walk, texture slab, CSO archive and block name reaches + // them through it), which is what makes the count complete by construction rather than by + // a hand-kept list of callers. + // + // `size`, NOT `need`: the Align8 slack is the allocator's, not content the producer wrote, + // and charging it here would make a workload of 8-byte blobs look like one of 16-byte + // blobs. The allocator's wrap skip is excluded for the same reason. + // + // The sample below the byte add is the same call site for the same reason: the per-blob + // distribution is a property of what the PRODUCER handed over, before the arena rounds it. + if (MG_Util::PipeStats::Enabled()) { + MG_Util::PipeStats::AddBytes(MG_Util::PipeStats::ByteClass::StageSegmentBytes, size); + MG_Util::PipeStats::RecordStagedBlobBytes(size); + } + bool reclaimed = false; bool waited = false; for (;;) { @@ -1152,6 +1174,20 @@ namespace MobileGL::MG_Remote::Wire { // the measured answer on the reduced path is a different row entirely. m_maxRecordOp = op; } + // P6 GATE 8's SECOND NUMBER (CONTRACT-P6.md §9 item 8), and it is counted HERE rather than + // at any emitter for the reason the CallClass comment gives: after chunking, the emitter + // no longer knows how many records its one call produced. By this point the record is + // COMMITTED - Reserve succeeded, the body is written and the blob slots have been checked + // honest - so this is exactly "records/frame post-chunking", not "emitter calls/frame". + // + // A kRecPad FILLER CANNOT REACH HERE: Reserve returns the filler's wake-up as a refusal + // (kInvalidSeq) and the caller retries, so no pad is ever counted, which is what keeps + // this number comparable with the seq space R-3 defines. A REFUSED emission is not counted + // either - the early return above is what makes one record cost exactly one. + if (MG_Util::PipeStats::Enabled()) { + MG_Util::PipeStats::AddCalls(MG_Util::PipeStats::CallClass::WireRecords, 1); + } + ++m_emitSeq; // The stage mark: where SEG_STAGE stood once everything this record names had been // staged. ReclaimStagedBytes releases up to the newest mark the server has retired. diff --git a/MobileGL/MG_Test/Util/PipeStatsTest.cpp b/MobileGL/MG_Test/Util/PipeStatsTest.cpp index 6148a498..b4d57442 100644 --- a/MobileGL/MG_Test/Util/PipeStatsTest.cpp +++ b/MobileGL/MG_Test/Util/PipeStatsTest.cpp @@ -13,6 +13,7 @@ #include #include +#include #include #include @@ -93,6 +94,109 @@ namespace { PS::Init(); } + // THE LATCH IS THE WHOLE CONTRACT, and this case exists because a spawn server got + // it wrong in a way no other test could see. `Init()` is a step of + // MobileGL::Initialize(), and the spawn server process never calls that - it calls + // MG_ConfigLoader::Init + InitServerRoleForSpawn - so `g_pipeStatsEnabled` stayed + // false there and every `if (Enabled())` site in the process was permanently + // false. The observable consequence was not a wrong number but an ABSENT one: + // the server printed no summary line at all, and `wait[srv=0 srvpark=0]` (what a + // reader would have taken for "the server never waited") is in fact what this + // case's "false" arm looks like. + // + // It pins both directions, because only the pair is falsifiable: Init() must TAKE + // the config's value when it is true, and must CLEAR the latch when it is false - + // a version that only ever set the flag true would pass a one-sided test while + // making MOBILEGL_PIPE_STATS=0 mean nothing in a long-lived process. + TEST_F(PipeStatsTest, InitIsTheOnlyLatchAndItTakesTheConfigBothWays) { + const bool saved = MobileGL::MG_Config::Features.PipeStats; + + MobileGL::MG_Config::Features.PipeStats = true; + PS::Init(); + EXPECT_TRUE(PS::Enabled()) << "a true config must arm the counters"; + + MobileGL::MG_Config::Features.PipeStats = false; + PS::Init(); + EXPECT_FALSE(PS::Enabled()) << "and a false one must disarm them, not leave the old latch"; + + MobileGL::MG_Config::Features.PipeStats = saved; + PS::Init(); + } + + // A summary line is emitted by whichever role reaches OnPresent, and this is what makes + // the spawn server's line appear at all: it has no swap of its own, so its cadence + // rides the present records it applies. The assertion is the arithmetic that cadence + // rests on - k presentations produce k windows when the period is 1 - because that is + // the property the lane's per-frame rates divide by. + TEST_F(PipeStatsTest, PresentationsAtTheDefaultPeriodOfOneMakeOneWindowEach) { + const Uint32 saved = MobileGL::MG_Config::Features.PipeStatsPeriod; + MobileGL::MG_Config::Features.PipeStatsPeriod = 1; + PS::Init(); + + for (Uint32 i = 0; i < 5; ++i) { + PS::PublishGauge(PS::Gauge::ServerWaits, static_cast(100 * (i + 1))); + PS::OnPresent(); + } + EXPECT_EQ(PS::FrameCount(), 5u); + // The gauge is a RUN TOTAL: publishing five increasing values leaves the last one, + // never their sum. This is the mistake the report's first aggregation script made. + EXPECT_EQ(PS::GaugeValue(PS::Gauge::ServerWaits), 500u); + + MobileGL::MG_Config::Features.PipeStatsPeriod = saved; + PS::Init(); + } + + // P6 gate 8: THE DUMP PATH IS ROLE-DERIVED AND THE BASE NAME IS NOT A FILE. + // + // The trap this exists for: under `spawn` both roles reach PipeStats::Shutdown() (the client + // through MobileGL::Destroy, the server through ServerMain's own call), and before this both + // opened MOBILEGL_PIPE_STATS_FILE itself with trunc - so the second writer silently replaced + // the first, and a reader held one role's numbers under a name that claimed to be the run's. + // + // ---- WHAT THIS CASE ASSERTS, AND WHAT ITS FIRST VERSION GOT WRONG ---- + // + // The first version asserted about MG_Util::Debug::RoleLogPath directly: that the two roles get + // different paths, that neither equals the base name. All of that PASSED WITH THE FIX REVERTED - + // it tested the naming helper, which was never broken. What was broken was that the dump did + // not CALL it. A test that stays green while the defect is present is worse than no test. + // + // So the subject here is RoleDerivedJsonDumpPathForTesting(), the same expression the dump and + // the banner use; and the third assertion is the negative control the design rests on - the + // base name must not exist as a file, so a reader that was not updated gets ENOENT and says so + // rather than a file that looks like a complete run and is half of one. + TEST_F(PipeStatsTest, JsonDumpPathIsRoleDerivedAndTheBaseNameIsNeverOpened) { + using MobileGL::MG_Util::Debug::LogRole; + + const String saved = MobileGL::MG_Config::Features.PipeStatsFile; + const char* base = "/tmp/mobilegl-pipestats-role-test.json"; + + // Unset: no path at all, and specifically not the empty string spelled as a file name. + MobileGL::MG_Config::Features.PipeStatsFile = ""; + EXPECT_TRUE(PS::RoleDerivedJsonDumpPathForTesting().empty()); + + MobileGL::MG_Config::Features.PipeStatsFile = base; + const String path = PS::RoleDerivedJsonDumpPathForTesting(); + + // (1) THE DUMP PATH IS THE DERIVED ONE, spelled out, so a change to the rule is a change + // to this test. A unit process is the client role. + EXPECT_EQ(path, String("/tmp/mobilegl-pipestats-role-test.client.json")); + + // (2) THE BASE NAME IS NOT THE PATH. This is the collision itself: if the dump wrote the + // configured name, spawn's second writer would truncate the first. + EXPECT_NE(path, String(base)); + + // (3) THE NEGATIVE CONTROL. PipeStats writes the derived path, never the base, so nothing + // may have created the base. A fresh base is absent, and this fails if that ever stops + // being true - which is exactly what a revert of the derivation does. + std::remove(base); + std::ifstream baseFile(base); + EXPECT_FALSE(baseFile.good()) + << "the configured base name exists; something opened it directly, and under spawn " + "that is the trunc-versus-trunc collision this derivation exists to prevent"; + + MobileGL::MG_Config::Features.PipeStatsFile = saved; + } + TEST_F(PipeStatsTest, GateHitsAndMissesAreSeparateCounters) { for (Uint32 i = 0; i < 5; ++i) { PS::CountGate(PS::Gate::MagmaPipelineMemo, /*hit=*/true); @@ -171,6 +275,15 @@ namespace { // And the new ByteClass rides the ordinary bytes[] bracket under a short name that is // NOT "csob": the cso[] bracket above already prints csob= for the CSO bind count. EXPECT_NE(line.find("csob-blob="), String::npos) << line; + // P6 GATE 8'S TWO NUMBERS (CONTRACT-P6.md §9 item 8), pinned where an operator's grep + // would break. `seg` is the ByteClass that says how many bytes a frame stages into + // SEG_STAGE, and `wrec` / `wrec/f` are the post-chunking record count and its per-frame + // figure. The short name is `seg` and not `stage`, which would read as a prefix of + // `stage-buffer`'s long name and of nothing else in the bracket; it is also not `ssb`, + // because this is a per-frame BYTES field and `ssb` reads like a count. + EXPECT_NE(line.find("seg="), String::npos) << line; + EXPECT_NE(line.find("wrec="), String::npos) << line; + EXPECT_NE(line.find("wrec/f="), String::npos) << line; // P5d round 3's wait ledger. Four fields on a bracket of their own, and they are // pinned here for the reason every other short name is: they are what the inproc // performance work reads out of a run's log, so a rename or a dropped field breaks @@ -197,6 +310,114 @@ namespace { EXPECT_NE(line.find("buf=97.14"), String::npos) << line; } +#if MOBILEGL_PIPE_PUSH + // P6 GATE 8's TWO NUMBERS (CONTRACT-P6.md §9 item 8), and each half is pinned because each + // half is a way the deliverable can be wrong without looking wrong. + // + // `seg` IS THE PRODUCER'S OWN BYTES. The wire encoder adds `size` and not the allocator's + // Align8 of it (PipeWireCodec.cpp's StageAllocate), so a blob of 4096 stages 4096. Checked + // here on the module's own arithmetic because that is the only place the rule can be read + // without a live ring: the encoder's call site is deliberately one line and has no test of + // its own. + TEST_F(PipeStatsTest, StageSegmentBytesIsAWindowedByteClassLikeAnyOther) { + PS::AddBytes(PS::ByteClass::StageSegmentBytes, 4096); + PS::AddBytes(PS::ByteClass::StageSegmentBytes, 2048); + PS::AddCalls(PS::CallClass::Draws, 1); + PS::OnPresent(); + + EXPECT_EQ(PS::TotalBytes(PS::ByteClass::StageSegmentBytes), 6144u); + EXPECT_EQ(PS::FrameBytes(PS::ByteClass::StageSegmentBytes), 0u) << "a Present clears the frame"; + // 6144 over one frame, two decimals, in the ordinary bytes[] bracket. + EXPECT_NE(PS::FormatWindowLine().find("seg=6144.00"), String::npos) + << PS::FormatWindowLine(); + + PS::AdvanceSummaryWindow(); + // And it obeys the file's LABEL rule, not a rule of its own: the new window has no + // Present in it, so the bracket is relabelled "bytes[" and `seg` carries the window + // TOTAL verbatim rather than a figure divided by a faked frame count. That is the same + // rule the bytes[] bracket follows and the same one the two window-total tests below + // pin; asserting "seg=0.00" here is what the first cut of this case did, and it was + // asserting a per-frame form the line deliberately does not print. + const String empty = PS::FormatWindowLine(); + EXPECT_NE(empty.find("bytes["), String::npos) << empty; + EXPECT_EQ(empty.find("bytes/f["), String::npos) << empty; + EXPECT_NE(empty.find("seg=0"), String::npos) << empty; + } + + // `wrec` IS A COUNT, SO IT DOES NOT DIVIDE LIKE A BYTE CLASS - and the per-frame form must + // read off the line, which is why the field exists at all rather than the operator doing the + // division by hand. 26 records over 13 frames is 2.00; the window total is printed beside it + // so the pair is self-checking. + TEST_F(PipeStatsTest, WireRecordsCarryBothTheWindowCountAndItsPerFrameForm) { + PS::AddCalls(PS::CallClass::WireRecords, 26); + for (Uint32 i = 0; i < 13; ++i) { + PS::OnPresent(); + } + + const String line = PS::FormatWindowLine(); + EXPECT_NE(line.find("wrec=26"), String::npos) << line; + EXPECT_NE(line.find("wrec/f=2.00"), String::npos) << line; + } + + // AND THE LABEL RULE THE FILE ALREADY OWNS APPLIES TO IT: a window with no Present in it has + // no per-frame reading, so `wrec/f` carries the window total rather than a figure divided by + // a faked 1. This is the same 47x overstatement PipeStatsTest pins for the bytes[] bracket, + // one field over, and it is the shape a trace slice with no swap at all would hit. + TEST_F(PipeStatsTest, WireRecordsFallBackToTheWindowTotalWithoutAFrame) { + PS::AddCalls(PS::CallClass::WireRecords, 47); + + const String line = PS::FormatWindowLine(); + EXPECT_EQ(PS::FrameCount(), 0u); + EXPECT_NE(line.find("wrec=47"), String::npos) << line; + EXPECT_NE(line.find("wrec/f=47"), String::npos) << line; + EXPECT_EQ(line.find("wrec/f=47.00"), String::npos) << line; + } + + // THE STAGED-BLOB DISTRIBUTION, which is the optional deliverable MEASUREMENTS.md:342 says + // has never existed. It shares the draw-payload histogram's edges - bucket 0 is "0 bytes", + // bucket n>0 is [2^(n-1), 2^n) - so the two are read the same way, and it is a COUNT per + // bucket rather than a byte sum: the shape is the deliverable and the bytes have their own + // counter in `seg`. + TEST_F(PipeStatsTest, StagedBlobHistogramSharesThePayloadBucketEdges) { + PS::RecordStagedBlobBytes(1); // [1, 2) -> bucket 1 + PS::RecordStagedBlobBytes(4096); // [4096,8192)-> bucket 13 + PS::RecordStagedBlobBytes(4096); // same bucket + PS::RecordStagedBlobBytes(8192); // [8192,...) -> bucket 14: the edge is exclusive + + EXPECT_EQ(PS::TotalStagedBlobBucket(1), 1u); + EXPECT_EQ(PS::TotalStagedBlobBucket(13), 2u); + EXPECT_EQ(PS::TotalStagedBlobBucket(14), 1u); + EXPECT_EQ(PS::TotalStagedBlobBucket(0), 0u); + // Saturation and the out-of-range read, exactly as the draw-payload histogram's. + PS::RecordStagedBlobBytes(~Uint64{0}); + EXPECT_EQ(PS::TotalStagedBlobBucket(PS::kStagedBlobHistogramBuckets - 1), 1u); + EXPECT_EQ(PS::TotalStagedBlobBucket(PS::kStagedBlobHistogramBuckets), 0u); + } + + // A distribution is a RUN TOTAL and has no business being windowed: it is a shape over the + // whole workload, and a Present that cleared it would report the shape of one frame as if it + // were the run's. It reaches an operator through the JSON dump - the same channel and for the + // same reason the draw-payload histogram uses it - so that is where it is asserted. + TEST_F(PipeStatsTest, StagedBlobHistogramIsARunTotalAndReachesTheJsonDump) { + PS::RecordStagedBlobBytes(1024); + PS::OnPresent(); + + const String json = PS::FormatJson(); + EXPECT_NE(json.find("\"staged-blob-bytes-histogram\""), String::npos) << json; + EXPECT_NE(json.find("\"wire-records\""), String::npos) << json; + EXPECT_NE(json.find("\"stage-segment-bytes\""), String::npos) << json; + // Run total, not a window: the sample above survives the Present. + EXPECT_EQ(PS::TotalStagedBlobBucket(11), 1u); + + // The ordering is the JSON document's shape, not decoration: the new array is a SIBLING + // of the draw-payload one, so a reader that walks the object finds both where the two + // comments say they are. + EXPECT_LT(json.find("\"cmd-bytes-per-draw-histogram\""), + json.find("\"staged-blob-bytes-histogram\"")) + << json; + } +#endif + // Successive summaries report WINDOWS, not run totals: a run total over a workload that // changes shape (load, then steady state) averages away the very number section 2.3.1 // wants. Advancing the window is an explicit call, not a side effect of formatting. @@ -312,6 +533,10 @@ namespace { EXPECT_STREQ(PS::NameOf(PS::CallClass::ClientTextureUploadEmissions), "client-tex-upload-emissions"); EXPECT_STREQ(PS::NameOf(PS::ByteClass::CsoBlobBytes), "cso-blob-bytes"); + // P6 gate 8's two, under their long names - the JSON dump keys and the names the + // MEASUREMENTS.md entry will quote. + EXPECT_STREQ(PS::NameOf(PS::ByteClass::StageSegmentBytes), "stage-segment-bytes"); + EXPECT_STREQ(PS::NameOf(PS::CallClass::WireRecords), "wire-records"); #endif EXPECT_STREQ(PS::NameOf(PS::Gate::EsprytRenderState), "espryt-render-state"); EXPECT_STREQ(PS::NameOf(PS::Gate::EsprytTextureSyncList), "espryt-texture-sync-list"); diff --git a/MobileGL/MG_Util/Debug/Log.cpp b/MobileGL/MG_Util/Debug/Log.cpp index a5c59b5d..dfe1bccc 100644 --- a/MobileGL/MG_Util/Debug/Log.cpp +++ b/MobileGL/MG_Util/Debug/Log.cpp @@ -94,6 +94,17 @@ namespace MobileGL { } return path.substr(0, dot) + "." + roleSuffix + path.substr(dot); } + + // P6 gate 8: the role, in the two forms a caller can hold it in. Both are thin readers of + // state this file already keeps; neither adds a second source of truth. + LogRole CurrentThreadRole() { + if (t_logRole < 0) { + t_logRole = ProcessIsSpawnedServer() ? 1 : 0; + } + return t_logRole == 1 ? LogRole::Server : LogRole::Client; + } + + bool CurrentProcessIsSpawnedServer() { return ProcessIsSpawnedServer(); } #endif std::mutex& LogMutex() { diff --git a/MobileGL/MG_Util/Debug/Log.h b/MobileGL/MG_Util/Debug/Log.h index 758e6883..b89a9325 100644 --- a/MobileGL/MG_Util/Debug/Log.h +++ b/MobileGL/MG_Util/Debug/Log.h @@ -164,6 +164,24 @@ namespace MobileGL { // "the library never logged", which reads as a product failure. std::string RoleLogPath(const char* basePath, LogRole role); + // WHICH ROLE IS THE CALLING THREAD, exported for the same reason the naming rule is: + // a second answer to "am I the server" is a second answer that can disagree, and this + // one already exists twice inside this file (ThreadIsServerRole, ProcessIsSpawnedServer) + // in a form nothing outside can read. + // + // P6 GATE 8 NEEDS IT, and that is the caller that made it worth exporting. The MGPipe + // counters' JSON dump is written by whichever role reaches PipeStats::Shutdown(), and + // under `spawn` both roles do - in two processes, onto the same configured path. The + // fix is the log sink's own split (each role gets its own file), and the role is the + // only input that split needs. + LogRole CurrentThreadRole(); + // The same question about a whole PROCESS rather than a thread: true only for a + // spawned server image, which is the server on every thread. Exported because the + // distinction matters to callers that are deciding a FILE NAME before any role has + // been stamped on a thread. `bool` rather than `Bool`: this header is included from + // translation units that do not pull MobileGL/Defines.h (Log.cpp is one of them). + bool CurrentProcessIsSpawnedServer(); + // THE TWO OPERATIONS EVERY READER ACTUALLY WANTS, so that no caller has to know how // many roles there are or how they are spelled. // @@ -197,6 +215,13 @@ namespace MobileGL { return basePath == nullptr ? std::string() : std::string(basePath); } + // INLINE, like everything else in this pull arm, and for the same G1 reason. There is + // one role in this build, so "which role is this thread" has exactly one true answer + // and no state to read - but a caller must still compile and mean the right thing in + // both flavours rather than wrapping these in an `#if` it might get wrong once. + inline LogRole CurrentThreadRole() { return LogRole::Client; } + inline bool CurrentProcessIsSpawnedServer() { return false; } + inline std::string ReadRoleLogs(const char* basePath) { std::string all; if (basePath == nullptr) return all; diff --git a/MobileGL/MG_Util/Metrics/PipeStats.cpp b/MobileGL/MG_Util/Metrics/PipeStats.cpp index fccd0a0b..3f4c12db 100644 --- a/MobileGL/MG_Util/Metrics/PipeStats.cpp +++ b/MobileGL/MG_Util/Metrics/PipeStats.cpp @@ -9,6 +9,7 @@ #include "PipeStats.h" #include +#include #include @@ -93,10 +94,29 @@ // above. The two are different questions about the same bytes under // split, and adding them is wrong. // residual-value-block Placeholder, always 0 until P2 (plan section 6.3). +// stage-segment-bytes P6 gate 8, and the only class in this list that is neither a backend's +// copy nor a client's blob declaration: it counts what the WIRE put into +// SEG_STAGE. One site, PipeWireEncoder::StageAllocate, which is the single +// allocation call behind PipeWireEncoder::StageBytes - so every writer +// (the buffer content walks, the texture slabs, the CSO archives, the +// storage-block names) is covered by construction rather than by being on +// a list. Align8 slack and the allocator's wrap skip are real occupancy +// and are deliberately NOT counted; see the ByteClass comment. It is a +// per-frame average by construction, so the per-blob SHAPE - the thing +// that says whether the chunk budget is cutting where it should - is the +// staged-blob histogram in the JSON dump, not this number. // // Call classes // draws DirectGLES PrepareForDraw and DirectVulkan SetupDraw's entry. A // dispatch is not a draw and is not counted. +// wire-records P6 gate 8: one per record the wire encoder COMMITTED, on +// PipeWireEncoder::EncodeRecord's successful path. Post-chunking by +// construction - an application call whose content is cut at +// MGPipeStageChunkBytes() produces several. A kRecPad ring filler is not a +// record and is not counted; an emission Reserve refused is counted once, +// when the retry succeeds. The emitter-side Client*Emissions counters +// answer a different question and the two together are what show what the +// suppressors absorbed. // accessor-calls STATIC TALLIES at the instrumented entry points, NOT a wrapper // around all 293 pGLContext-> sites. Each instrumented function adds // the number of GLContext accessor calls that its OWN body executed @@ -144,6 +164,11 @@ namespace MobileGL::MG_Util::PipeStats { Counter g_totalGateMiss[kGateCount]; Counter g_totalPayloadBuckets[kPayloadHistogramBuckets]; Counter g_frameCount{0}; +#if MOBILEGL_PIPE_PUSH + // P6 gate 8's second histogram, and push-only for the same reason its accessor is: its + // only sampler is the wire encoder, which a pull build does not compile. + Counter g_totalStagedBlobBuckets[kStagedBlobHistogramBuckets]; +#endif // Window bases: the run totals as of the previous summary line. Only ever touched // from OnPresent()/Shutdown() (the present thread), so plain integers. @@ -201,7 +226,7 @@ namespace MobileGL::MG_Util::PipeStats { "stage-ubo-named", "stage-vertex-client", "stage-index-client", "stage-indirect-cmd", "persistent-map-push", "residual-value-block", #if MOBILEGL_PIPE_PUSH - "cso-blob-bytes", + "cso-blob-bytes", "stage-segment-bytes", #endif }; const char* const kCallClassNames[kCallClassCount] = { @@ -211,7 +236,7 @@ namespace MobileGL::MG_Util::PipeStats { "render-state-cso-mints", "render-state-cso-binds", "map-persistent-roundtrips", "framebuffer-emissions", "sampler-view-emissions", "sampler-state-emissions", "shader-image-emissions", "client-tex-upload-emissions", "tex-remint-pulls", - "residual-pulls", "server-verb-boundaries", + "residual-pulls", "server-verb-boundaries", "wire-records", #endif }; const char* const kGateNames[kGateCount] = { @@ -236,7 +261,7 @@ namespace MobileGL::MG_Util::PipeStats { const char* const kByteClassShort[kByteClassCount] = {"buf", "tex", "ubog", "ubon", "vtxc", "idxc", "icmd", "pmap", "resid", #if MOBILEGL_PIPE_PUSH - "csob-blob", + "csob-blob", "seg", #endif }; const char* const kGateShort[kGateCount] = {"ers", "etl", "eub", "mfp", "mpm", "mdt"}; @@ -265,6 +290,11 @@ namespace MobileGL::MG_Util::PipeStats { } g_frameCount.store(0, std::memory_order_relaxed); g_windowBaseFrames = 0; +#if MOBILEGL_PIPE_PUSH + for (Uint32 i = 0; i < kStagedBlobHistogramBuckets; ++i) { + g_totalStagedBlobBuckets[i].store(0, std::memory_order_relaxed); + } +#endif #if MOBILEGL_PIPE_PUSH for (Uint32 i = 0; i < kGaugeCount; ++i) { g_gauges[i].store(0, std::memory_order_relaxed); @@ -284,13 +314,57 @@ namespace MobileGL::MG_Util::PipeStats { } void WriteJsonDump() { +#if MOBILEGL_BUILD_DISAGGREGATED + // ---- THE DUMP PATH IS ROLE-DERIVED, AND THIS BLOCK IS WHY IT IS INSIDE A GUARD ---- + // + // Same reason as the log path it mirrors: under `spawn` there are two processes with + // two independent sets of counters, each reaching PipeStats::Shutdown(), and one + // configured path would have the second truncate and overwrite the first. A reader + // would then hold one role's numbers under a name that claims to be the run's, which is + // worse than a missing file because nothing about it looks wrong. + // + // THE BASE NAME RESOLVES TO NO FILE, deliberately. `.client.json` and + // `.server.json` are what exist; opening the bare configured name fails loudly. + // That is the log sink's own design ("with both names moved, an un-updated reader gets + // ENOENT and says so") and it is the right trade here too: a caller that has not been + // updated gets an error it must look at, rather than a file that is silently half a run. + // + // THE RULE IS NOT COPIED. MG_Util/Debug/Log.cpp owns `.` and exports + // it; a second implementation is a second thing to keep in step, and the one that falls + // behind opens a path nothing writes and reads as "the counters never dumped". + // + // ---- AND G1 IS WHY THE PULL ARM BELOW IS THE ORIGINAL, STATEMENT FOR STATEMENT ---- + // + // A monolith build has exactly ONE role, so deriving the path there is a no-op - but + // "a no-op" is not "no bytes", and the gate caught three separate leaks as this was + // written. They are worth recording because none is guessable from the code: + // + // 1. deriving UNCONDITIONALLY put a std::string temporary and a call into the + // monolith body: .text +24 bytes. + // 2. guarding it but keeping ONE shared `String` local in both arms still reds: the + // two arms are different code even when they compute the same value, and + // `Shutdown()` came out one byte different. + // 3. rewriting the two MGLOG_W format strings to name both the base and the derived + // path moved .rodata by 64 bytes, because a literal is a literal in whichever + // branch it sits and .rodata is measured too. + // + // So the rule for this file is stronger than "guard the new code": the OLD code must be + // left alone, character for character, and every addition lives inside the `#if`. + const String path = RoleDerivedJsonDumpPathForTesting(); + if (path.empty()) { + return; + } +#else + // The monolith arm, byte for byte as it was. Do not "tidy" this into the arm above. const String& path = MG_Config::Features.PipeStatsFile; if (path.empty()) { return; } +#endif std::ofstream out(path, std::ios::out | std::ios::trunc); if (!out) { - MGLOG_W("PipeStats: could not open MOBILEGL_PIPE_STATS_FILE='%s' for writing", path.c_str()); + MGLOG_W("PipeStats: could not open MOBILEGL_PIPE_STATS_FILE='%s' for writing", + path.c_str()); return; } out << FormatJson(); @@ -311,10 +385,27 @@ namespace MobileGL::MG_Util::PipeStats { ? kDefaultSummaryFramePeriod : static_cast(MG_Config::Features.PipeStatsPeriod); if (g_pipeStatsEnabled) { +#if MOBILEGL_BUILD_DISAGGREGATED + // THE ROLE-DERIVED PATH IS WHAT IS PRINTED, not the base name. An operator reading + // this banner wants to know which file the run will write, and under split the base + // name is not it - printing the base would send them to a path that is deliberately + // never opened (see WriteJsonDump). + // + // THE PULL ARM OF THIS `#if` IS THE ORIGINAL LINE, and the split arm repeats the same + // format literal rather than sharing one, for the reason WriteJsonDump's header spells + // out: a shared literal or a shared temporary is a byte the monolith build gains for a + // branch it can never take. Two copies of one format string in two arms of one `#if` is + // the price G1 charges for adding anything to this file at all. + const String dumpPath = RoleDerivedJsonDumpPathForTesting(); + MGLOG_I("MGPipe stats: counters ON (MOBILEGL_PIPE_STATS), summary every %llu frames%s%s", + static_cast(g_summaryPeriod), + dumpPath.empty() ? "" : ", JSON dump to ", dumpPath.c_str()); +#else MGLOG_I("MGPipe stats: counters ON (MOBILEGL_PIPE_STATS), summary every %llu frames%s%s", static_cast(g_summaryPeriod), MG_Config::Features.PipeStatsFile.empty() ? "" : ", JSON dump to ", MG_Config::Features.PipeStatsFile.c_str()); +#endif } } @@ -367,6 +458,15 @@ namespace MobileGL::MG_Util::PipeStats { void RecordDrawPayloadBytes(Uint64 bytes) { Bump(g_totalPayloadBuckets[PayloadBucketOf(bytes)], 1); } +#if MOBILEGL_PIPE_PUSH + // P6 gate 8's staged-blob distribution. A count, not a sum: the bytes already have a home + // in stage-segment-bytes, and what this exists to answer is the SHAPE (how many blobs there + // were and how big each one was), which a total cannot express. + void RecordStagedBlobBytes(Uint64 bytes) { + Bump(g_totalStagedBlobBuckets[PayloadBucketOf(bytes)], 1); + } +#endif + void OnPresent() { // Every frame accumulator is EXCHANGED for zero, and the exchanged value is what gets // plotted. A read followed by a store(0) would lose any Bump that lands in between - @@ -422,6 +522,11 @@ namespace MobileGL::MG_Util::PipeStats { Uint64 TotalPayloadBucket(Uint32 bucket) { return bucket < kPayloadHistogramBuckets ? Read(g_totalPayloadBuckets[bucket]) : 0; } +#if MOBILEGL_PIPE_PUSH + Uint64 TotalStagedBlobBucket(Uint32 bucket) { + return bucket < kStagedBlobHistogramBuckets ? Read(g_totalStagedBlobBuckets[bucket]) : 0; + } +#endif Uint64 FrameCount() { return Read(g_frameCount); } const char* NameOf(ByteClass byteClass) { return kByteClassNames[static_cast(byteClass)]; } @@ -522,6 +627,24 @@ namespace MobileGL::MG_Util::PipeStats { // positive control built on it would fail on the day the debt is paid. line += " vbs=" + std::to_string(calls[static_cast(CallClass::ServerVerbBoundaries)]); + // P6 GATE 8's SECOND NUMBER (CONTRACT-P6.md §9 item 8): records/frame AFTER chunking, i.e. + // the count of records the wire encoder actually committed this window rather than the + // number of times an emitter was asked for one. The gap between the two is the whole + // point of the counter: once the stage chunk budget landed, one application call can + // produce several records, so `wrec` is what a frame really costs SEG_CMD and the + // emitter-side counts can no longer answer it. It follows the line's ordinary + // per-frame/window rule - the run total when the window held no Present - like every + // field that is not one of the gauges, and the label says which it is. + // + // `wrec/f` AND NOT `wrec` ALONE, so the deliverable reads off the line directly. Both are + // printed because the pair is self-checking: a per-frame figure whose window total is not + // its numerator times the frame count is a formatting bug, and a per-frame figure over a + // window with no Present in it is the 47x overstatement PipeStatsTest already pins. + line += " wrec=" + std::to_string(calls[static_cast(CallClass::WireRecords)]); + line += " wrec/f=" + (perFrame + ? FormatFixed2(calls[static_cast(CallClass::WireRecords)], + windowFrames) + : std::to_string(calls[static_cast(CallClass::WireRecords)])); // P5's three wire gauges, and THEY ARE RUN TOTALS on a line whose every other field is // a window - see the Gauge enum for the argument. `maxrec` is R-10's proof obligation // (BRIEF 8 item 3): the largest single record this run wrote, in BYTES, beside the cap @@ -635,6 +758,23 @@ namespace MobileGL::MG_Util::PipeStats { } json += std::to_string(Read(g_totalPayloadBuckets[i])); } +#if MOBILEGL_PIPE_PUSH + // P6 gate 8's two per-frame numbers have their JSON homes where every other ByteClass and + // CallClass already does - the `bytes` and `calls` blocks above, under their long names + // (stage-segment-bytes, wire-records) - so there is nothing to add for them here. The + // staged-blob DISTRIBUTION does need one: it is the deliverable MEASUREMENTS.md:342 says + // has never been measured, and like the draw-payload histogram above it is a run-total + // distribution, which is exactly what Tracy cannot plot and this dump exists to carry. + // Bucket 0 is "0 bytes" and bucket n>0 is [2^(n-1), 2^n): the same edges PayloadBucketOf + // gives both histograms, so the two are read the same way. + json += "],\n \"staged-blob-bytes-histogram\": ["; + for (Uint32 i = 0; i < kStagedBlobHistogramBuckets; ++i) { + if (i != 0) { + json += ", "; + } + json += std::to_string(Read(g_totalStagedBlobBuckets[i])); + } +#endif json += "]\n}\n"; return json; } @@ -643,4 +783,18 @@ namespace MobileGL::MG_Util::PipeStats { void ResetForTesting() { ResetCounters(); } +#if MOBILEGL_BUILD_DISAGGREGATED + String RoleDerivedJsonDumpPathForTesting() { + // The SAME expression WriteJsonDump and the Init banner use, reached through the same + // helper - so a change that stopped deriving at either site has to change this too, and the + // test reds. That is the whole point: see the header for why asserting on RoleLogPath + // directly was not a control. + if (MG_Config::Features.PipeStatsFile.empty()) { + return String(); + } + return MG_Util::Debug::RoleLogPath(MG_Config::Features.PipeStatsFile.c_str(), + MG_Util::Debug::CurrentThreadRole()); + } +#endif + } // namespace MobileGL::MG_Util::PipeStats diff --git a/MobileGL/MG_Util/Metrics/PipeStats.h b/MobileGL/MG_Util/Metrics/PipeStats.h index 061e3ff5..0acf43f0 100644 --- a/MobileGL/MG_Util/Metrics/PipeStats.h +++ b/MobileGL/MG_Util/Metrics/PipeStats.h @@ -87,6 +87,32 @@ namespace MobileGL::MG_Util::PipeStats { // transport would actually have to move for the CSO families, as opposed to what the // records themselves cost. CsoBlobBytes, + // P6 GATE 8's FIRST NUMBER (CONTRACT-P6.md §9 item 8), and the reason it is a ByteClass + // rather than one more Gauge: the deliverable is BYTES PER FRAME, and a byte class IS + // the windowed sum this module already divides by the window's frame count. A gauge is + // a run total deliberately (see the Gauge enum) and windowing one is not a thing this + // module does. + // + // WHAT IT MEASURES, AND WHY IT IS NOT ANY OF THE stage-* CLASSES ABOVE. Those count what + // a BACKEND moves into its own driver, on the apply thread, from bytes the wire already + // delivered. This counts what the WIRE put into SEG_STAGE - the client-side staging + // arena a record's blobs are copied into - and it is read as "staged content per frame". + // + // COUNTED AT THE ALLOCATOR, WHICH IS THE ONE CHOKE POINT. Every writer that puts bytes + // into SEG_STAGE reaches them through PipeWireEncoder::StageBytes and that function's + // only allocation call is StageAllocate (PipeWireCodec.h:376), so a single site here + // covers the buffer content walks, the texture slabs, the CSO archives and the + // storage-block names alike. Summing at the CALLERS instead would be a hand-kept list of + // the paths that happen to exist today, and the next producer added would be missing + // from it with nothing to notice - which is the failure mode the site inventory at the + // top of PipeStats.cpp exists to forbid. + // + // IT IS THE PAYLOAD, NOT THE ARENA OCCUPANCY. Align8 slack and the allocator's wrap skip + // (a run that would straddle the segment's end skips the remainder) are real bytes of + // the segment and are NOT counted: neither is content the producer wrote, and neither + // is what MOBILEGL_IPC_STAGE_MB has to hold for one record. The per-blob distribution + // this average hides is the staged-blob histogram below. + StageSegmentBytes, #endif Count }; @@ -195,6 +221,34 @@ namespace MobileGL::MG_Util::PipeStats { // would start failing on the day the debt is paid. `vbs` is non-zero whenever the // server applied a verb at all, before and after retirement alike. ServerVerbBoundaries, + // P6 GATE 8's SECOND NUMBER (CONTRACT-P6.md §9 item 8): "records/frame post-chunking". + // + // ONE PER RECORD THE WIRE ENCODER ACTUALLY WROTE, which is what makes it the + // post-chunking count rather than a restatement of the emitter's call count. Before the + // stage chunk budget landed, one application call produced one record and the question + // could be answered from the emitter's side; now a call whose content is wider than + // MGPipeStageChunkBytes() produces SEVERAL - the buffer content walks cut themselves at + // the budget and one texture level is emitted as whole-width slabs - and only the + // encoder knows how many. So this is counted where the record is committed + // (PipeWireCodec.cpp's EncodeRecord, on the successful path), not where a caller asked + // for one. + // + // A kRecPad RING FILLER IS NOT A RECORD AND IS NOT COUNTED. Those are the bytes Reserve + // lays down when a record would have straddled the ring's boundary; they carry no + // opcode, both sides skip them, and they are already visible in the gauges as ringpads. + // An emission the ring REFUSED is not counted either: EncodeRecord returns kInvalidSeq + // and the caller publishes and retries, so the record is counted once, when it goes. + // + // Read it against the Client*Emission counters above: a sampler/framebuffer/texture set + // that is resolved and then suppressed does not reach this number, so records-per-frame + // is wire traffic while those are emission calls, and the difference between them is + // exactly what the suppressors absorbed. + // + // NOT SetBytes(), and that is the whole reason it is a CallClass rather than a Gauge: the + // deliverable is records PER FRAME, so it needs the windowed division and the label rule + // that goes with it (FormatWindowLine prints the run total instead when the window holds + // no Present). + WireRecords, #endif Count }; @@ -308,6 +362,30 @@ namespace MobileGL::MG_Util::PipeStats { // emit records only has to add the one call. inline constexpr Uint32 kPayloadHistogramBuckets = 24; +#if MOBILEGL_PIPE_PUSH + // Per-STAGED-BLOB size histogram, and it is a SECOND histogram rather than a wider + // kPayloadHistogramBuckets because the two answer different questions about different + // populations: the one above is the command payload of a draw (plan section 4.5.7, sizing + // SEG_CMD), this one is how big the blobs a workload stages into SEG_STAGE actually are. + // + // IT EXISTS FOR CONTRACT-P6.md §9 item 8, and MEASUREMENTS.md:342 says in as many words why: + // the chunking work landed (1e7c372e buffer walks, 9469d48e texture slabs) and every + // `maxrec` number the file carries predates it, so "the per-blob byte distribution after + // chunking" had no measurement at all. A per-frame AVERAGE cannot answer it either: an + // average of 8 MiB is the same number whether one blob of 8 MiB was staged or two of 4 MiB + // that the budget should have cut to one. The bucket edges are PayloadBucketOf's, shared so + // the two distributions are read the same way. + // + // PUSH-ONLY like every counter added since P2: its only sampler is the wire encoder, which a + // pull build does not compile, so the array, the reset, the JSON row and the accessor would + // all exist there for a population that could never be sampled (gate G1). + inline constexpr Uint32 kStagedBlobHistogramBuckets = kPayloadHistogramBuckets; + Uint64 TotalStagedBlobBucket(Uint32 bucket); + // Sample one staged blob. Called by the wire encoder where a blob is staged, behind the + // usual Enabled() predicate. + void RecordStagedBlobBytes(Uint64 bytes); +#endif + // Frames between two summary lines when MOBILEGL_PIPE_STATS=1. inline constexpr Uint64 kDefaultSummaryFramePeriod = 120; // The period Init() latched from MOBILEGL_PIPE_STATS_PERIOD (kDefaultSummaryFramePeriod @@ -369,4 +447,20 @@ namespace MobileGL::MG_Util::PipeStats { void SetEnabledForTesting(Bool enabled); void ResetForTesting(); +#if MOBILEGL_BUILD_DISAGGREGATED + // The role-derived path the JSON dump will actually write, or empty when + // MOBILEGL_PIPE_STATS_FILE is unset. Empty when unset; never the bare configured name. + // + // IT EXISTS BECAUSE THE OBVIOUS TEST IS NOT A CONTROL. The first version of this case asserted + // things about MG_Util::Debug::RoleLogPath directly - that the two roles get different paths, + // that neither equals the base name. Every one of those assertions passes with the fix REVERTED, + // because they test the naming helper, which was never broken; what was broken was that + // WriteJsonDump did not CALL it. A test that stays green while the defect is present is worse + // than no test, so this accessor exists to make the call site itself observable. + // + // Guarded on the DISAGGREGATED option rather than PIPE_PUSH, because the collision it describes + // only exists with two roles - a monolith build has one and needs no derivation (gate G1). + String RoleDerivedJsonDumpPathForTesting(); +#endif + } // namespace MobileGL::MG_Util::PipeStats diff --git a/tools/device_bench/p6/README.md b/tools/device_bench/p6/README.md new file mode 100644 index 00000000..ec06a02c --- /dev/null +++ b/tools/device_bench/p6/README.md @@ -0,0 +1,143 @@ +# `device_bench/p6` — the device A/B session runner + +Two scripts that run a **paired performance comparison on a real device** and turn its evidence into +markdown tables. They exist because the quantity a disaggregation A/B reads on (tenths of a +millisecond of client CPU per frame) is smaller than the drift a hand-driven session accumulates +between the CPU samples, the pin evidence and the library's own counters — and those three come from +three different mechanisms. Collected by hand they are minutes apart; collected by one process they +are one window. + +| file | role | +|---|---| +| `ab_session.py` | collects: reboot, pin, launch each arm in order, sample per-thread CPU, pull role logs, verify the arm | +| `render_ab.py` | renders: `session-summary.json` → the markdown tables a report needs | + +The split is deliberate. The renderer reads only what the runner recorded, so it cannot influence +what was collected. + +## Usage + +```bash +# One arm is TRANSPORT[:BACKEND[:CASE[:REPEATS]]]; repeat a spec to interleave it. +python tools/device_bench/p6/ab_session.py \ + --tree /c/Users/me/mobilegl-snapshot \ + --out /c/Users/me/evidence \ + --apk /c/Users/me/evidence/trace-debug-signed.apk \ + --package top.mobilegl.plugin.trace \ + --reboot --fan-level 2 --repeats 3 --session my-session \ + --arm monolith:DirectGLES:minecraft-1.21.4-rd12-odinlite-in-world:3 \ + --arm inproc:DirectGLES:minecraft-1.21.4-rd12-odinlite-in-world:3 \ + --arm spawn:DirectGLES:minecraft-1.21.4-rd12-odinlite-in-world:3 + +python tools/device_bench/p6/render_ab.py /c/Users/me/evidence/my-session/session-summary.json +``` + +`--tree` is the tree the APK and the runner come from. Point it at a **snapshot**, not the shared +tree, when anything else is editing the repository: a build that picks up a half-written source file +measures nothing, and the failure is invisible in the result. `--apk` must be signed with a key the +device already trusts for that package — the Gradle release build has no signing config locally +(`SIGNING_*` are CI secrets), so it has to be signed by hand first: + +```bash +apksigner sign --ks ~/.android/debug.keystore --ks-pass pass:android \ + --ks-key-alias androiddebugkey --key-pass pass:android --out signed.apk unsigned.apk +``` + +`--package` must match the APK's application id. A development build usually needs a suffix +(`-Pmobilegl.applicationIdSuffix=.mine`) so it can sit **beside** an existing install rather than +replacing it: two APKs signed by different keys cannot share an id, and `adb install -r` fails with +`INSTALL_FAILED_UPDATE_INCOMPATIBLE`. The runner then needs `MOBILEGL_TRACE_PACKAGE` set to the same +id (see `run_android_retrace_local.py`'s note beside `BACKENDS`), which `ab_session.py` does itself. + +## What the protocol guarantees + +The whole point of the script is that these are not optional: + +- **Reboot-clean.** `--reboot` reboots, waits for `sys.boot_completed`, and compares the boot id + before and after. An unchanged id means no reboot happened, which is reported as a failure rather + than recorded as a clean window. +- **Pinned frequencies, with evidence.** Every arm runs `pin_device.sh pin` before and + `... check` after; a non-`PINNED` exit voids the arm (`status: UNPROVEN`), it does not degrade it. + Un-pinned per-thread CPU is not comparable across arms. +- **One thermal window.** All arms in one session, interleaved by the order the `--arm` flags are + given, with a cool-down between them so a later arm is not measured hotter than an earlier one. +- **Arm proof.** Each arm is checked against the library's OWN private log: the transport marker, the + split knobs in the `Config: IPC` line, and for `spawn` the `spawn ARMED - the server role runs in + pid N` line — which only the client writes after launch, connect and handshake all succeeded. A + spawn lane that silently fell back to monolith passes every other check and fails this one. + +## Evidence layout + +``` +// + session-summary.json # session metadata: boot ids, fan, APK hash, per-arm summaries + ----r/ + arm-summary.json # this arm: status, problems, cpu, stats, benchmark runs + pin-before.txt pin-after.txt + mobilegl.client.log mobilegl.server.log # per role + benchmark-run1..N.json # per-frame wall + CPU series per repeat + benchmark.json result.json logcat.txt runner.stdout.txt runner.stderr.txt +``` + +### Two asymmetries of the `spawn` shape that the renderer handles + +Both are structural — the client and the server really are different processes — and both produce a +zero that looks like a measurement if read carelessly: + +1. **`srv`/`srvpark` live in the server log.** The apply thread publishes them into its own process's + PipeStats. Under `inproc` both roles are threads of one process, so the client's summary line + carries all four numbers; under `spawn` the client prints `srv=0 srvpark=0`, which means "another + process", not "never waited". `render_ab.py` reads the server pair from `mobilegl.server.log`. + +2. **The frame count lives in the server log too.** `frames=` is bumped by `PipeStats::OnPresent`, + which the backend calls on Present — and under `spawn` present is applied in the server process, + so the client's `frames=0 window=0`. That zero is the same shape as `srv=0`. The per-frame rates + therefore divide by whichever log counted the frames, and the rendered table names which one that + was. + +## Building the APK + +```bash +gradle --no-daemon -p /android-plugin :app:assembleTraceRelease \ + -Pmobilegl.buildDisaggregated=ON -Pmobilegl.buildDisaggregatedInproc=ON \ + -Pmobilegl.pipePush=ON -Pmobilegl.debuggableRelease=true \ + -Pmobilegl.applicationIdSuffix=.mine -Pmobilegl.apkSuffix=mine +``` + +`-Pmobilegl.debuggableRelease=true` is not optional: without it the release APK is not `run-as`-able, +`trace-replay-ci.sh` cannot pull the private logs, and every arm produces no library log — which is +indistinguishable from a run that produced none. + +## Pitfalls this tooling works around + +- **`--transport` is ignored in `--benchmark` mode.** `run_android_retrace_local.py` applies + `--transport` only on its `run_case` path; `run_benchmark_case` passes `args.env` alone. So + `--benchmark --transport spawn` runs monolith under a spawn label. This script passes the transport + as an explicit `--env MOBILEGL_TRANSPORT=…` and verifies it from the library's log. +- **`MOBILEGL_RETRACE_USE_PBUFFER` must be in the CI script's environment**, not passed as `--env` — + `trace-replay-ci.sh` reads it itself to decide the surface shape. Without it the `spawn` arm dies + with `Fatal{UnmigratedSurface, "AndroidNativeWindow@P12"}`, because an `ANativeWindow*` means + nothing in the server's process (Rule H). +- **`MOBILEGL_TRACE_SKIP_INSTALL=1`** keeps the script's own `adb install` out of the window. The + session installs once itself and waits for `dex2oat` to exit first: an `am_kill … due to + installPackageLI` landing inside an arm measures the installer. +- **A stale `benchmark.json` is worse than none.** The runner's result directory is keyed by case and + backend, not by arm, so a failed arm can leave the previous arm's file where `read_benchmark` will + pick it up. The directory is deleted before each arm. + +## Known limit + +Under `spawn`, the client's **windowed** fields (`frames=`, `window=`, `draws/f`, `wrec/f`, +`bytes/f[…]`) are structurally zero: `PipeStats::OnPresent` runs in the server process (the apply +thread applies the present record), so the spawn client never counts frames. Dividing any counter +by the client's `frames=` is undefined. The renderer therefore takes the frame denominator from the +log that actually counted frames (normally the server's), and names the source in the table. + +What is **valid** from the client log is the run-total gauges (`cli`, `clipark`, `maxrec`, +`ringwraps`, …): `PublishGauge` is a store, not an add, so the client's terminal `Shutdown()` line +reports true run totals. Symmetrically, the server log's `cli=0` and the client log's `srv=0` mean +"the other process", not "never waited". + +The server's own byte/record/wait classes are available since `PipeStats::Init()` runs in +`ServerMain.cpp` (P6 closeout; before that the server log carried no summary line at all and `srv` +had to be reported as unavailable). diff --git a/tools/device_bench/p6/ab_session.py b/tools/device_bench/p6/ab_session.py new file mode 100644 index 00000000..8c1ba343 --- /dev/null +++ b/tools/device_bench/p6/ab_session.py @@ -0,0 +1,891 @@ +#!/usr/bin/env python3 +"""Paired A/B on a disaggregated-campaign device: one reboot-clean thermal window, interleaved arms. + +Its first use was `CONTRACT-P6.md` section 9 item 7 (the paired device gate) and item 8-1 (the +doorbell ledger), and it is not specific to those: the thing it computes is "N transports, one +thermal window, identical protocol" for any transport/backend/case triple the runner accepts. +Everything it does is a step of the protocol in docs/Disaggregated/MEASUREMENTS.md sections 4.4 / 9 +/ 11 plus notes/p5f/device-report.md. + +Why it is a script and not a shell transcript: a run that wants to be quotable needs the CPU +samples, the pin evidence and the library's own wait ledger to come from the SAME window, and the +three of those are collected by three different mechanisms. Collected by hand they drift apart by +minutes, and the quantity being compared (a few tenths of a millisecond per frame between two +transports) is smaller than that drift. + +WHAT IT DELIBERATELY DOES NOT DO. + +- It does not decide anything about correctness. Benchmark mode takes no snapshot and compares no + golden (--benchmark replays the whole trace for timing), so an SSIM column here would be a + fabrication. Correctness on this device is P6 section 3 of CURRENT_STAGE_PROGRESS.md and the + retrace lanes. +- It does not read `MOBILEGL_TRANSPORT` out of `--transport` on the runner. That flag is applied by + run_android_retrace_local.py's run_case() path only; run_benchmark_case() passes `args.env` + alone, so `--transport spawn` alongside `--benchmark` is silently ignored and the arm runs + monolith while its label says spawn. Measured on this tree (a `--benchmark` run with + `--transport inproc` wrote no `Config: IPC` line at all, i.e. it was monolith). Every arm here + therefore spells its transport as an explicit `--env` entry, and every arm is verified against + the library's own log afterwards. `assert_arm` is the gate on that; an arm that does not prove + itself is not measured, it is retried and then reported as a failure. +""" + +from __future__ import annotations + +import argparse +import json +import os +import re +import shutil +import signal +import subprocess +import sys +import threading +import time +from datetime import datetime, timezone +from pathlib import Path + +SERIAL = "2f7cbe2e" + + +def find_git_bash(): + """The interpreter that runs pin_device.sh, resolved rather than hardcoded. + + Named explicitly because a bare `bash` on a host with several installations picks whichever is + first on PATH, and MSYS path translation differs between them - the failure mode is a + `No such file or directory` for a script that exists, which reads like a missing file rather + than a wrong interpreter. + """ + import shutil + candidates = [ + os.environ.get("GIT_BASH"), + r"C:\Program Files\Git\bin\bash.exe", + r"C:\Program Files (x86)\Git\bin\bash.exe", + shutil.which("bash"), + ] + for candidate in candidates: + if candidate and Path(candidate).exists(): + return candidate + return "bash" + + +GIT_BASH = find_git_bash() + +# The knobs CI's split acceptance lanes hand both arms, kept verbatim so a local run is the same +# run (run_android_retrace_local.py SPLIT_ACCEPTANCE_KNOBS). The arm proof reads the library's own +# `Config: IPC` line and requires all three, so omitting one here does not measure a weaker arm - +# it fails to prove any arm at all. +SPLIT_KNOBS = ( + "MOBILEGL_IPC_ROLE_SPLIT_STATE=1", + "MOBILEGL_IPC_STRICT_ERRORS=1", + "MOBILEGL_IPC_RUN_AHEAD=1", +) +# 120 is the P5-era default and it is what every historical number in MEASUREMENTS.md sections 9-11 +# was taken at, so the wait ledger here can be read beside them. +STATS_PERIOD = "120" + +TRANSPORT_MARKERS = { + "inproc": "Config: MOBILEGL_TRANSPORT=inproc", + "spawn": "Config: MOBILEGL_TRANSPORT=spawn", +} +SPAWN_ARMED = re.compile(r"spawn ARMED - the server role runs in pid (\d+)") + +WAIT_LEDGER = re.compile( + r"wait\[srv=(\d+) srvpark=(\d+) cli=(\d+) clipark=(\d+)\]") +SECTION = re.compile(r"\] ([a-z]+)\[") +STAGE_LINE = re.compile(r"stage=(\d+)MiB") + + +def run(argv, **kwargs): + kwargs.setdefault("capture_output", True) + kwargs.setdefault("text", True) + kwargs.setdefault("encoding", "utf-8") + kwargs.setdefault("errors", "replace") + return subprocess.run(argv, **kwargs) + + +class Adb: + """Every call pins the serial. There is more than one device class on this bench and a bare + `adb` is how a run measures the wrong phone.""" + + def __init__(self, serial): + self.serial = serial + + @staticmethod + def _env(): + env = dict(os.environ) + env["MSYS_NO_PATHCONV"] = "1" + env["MSYS2_ARG_CONV_EXCL"] = "*" + return env + + def shell(self, command, timeout=30): + result = run(["adb", "-s", self.serial, "shell", command], env=self._env(), timeout=timeout) + return result.stdout.replace("\r", "") + + def su(self, command, timeout=30): + return self.shell("su -c '%s'" % command, timeout=timeout) + + def reboot(self): + # `adb reboot` returns as soon as the request is queued; the wait is the caller's. + run(["adb", "-s", self.serial, "reboot"], env=self._env(), timeout=60) + + def wait_boot(self, timeout=300): + deadline = time.time() + timeout + run(["adb", "-s", self.serial, "wait-for-device"], env=self._env(), timeout=timeout) + while time.time() < deadline: + state = self.shell("getprop sys.boot_completed").strip() + if state == "1": + return True + time.sleep(3) + return False + + def boot_id(self): + return self.shell("cat /proc/sys/kernel/random/boot_id").strip() + + def clk_tck(self): + """The DEVICE's tick rate, which is what /proc//stat's counters are denominated in. + + Read rather than assumed, and not the host's CLK_TCK: a 100-vs-250 mismatch would scale + every CPU millisecond in the report by 2.5x and nothing downstream could tell. + """ + value = self.shell("getconf CLK_TCK").strip() + try: + return int(value) + except ValueError: + return host_ticks_per_second() + + +def host_ticks_per_second(): + """Only a fallback. The authoritative tick rate is the DEVICE's, read in Adb.__init__ - + /proc//stat reports ticks, and a host that assumes its own CLK_TCK while the device uses + another silently scales every CPU number by the ratio.""" + try: + return int(subprocess.run(["getconf", "CLK_TCK"], capture_output=True, text=True).stdout.strip()) + except Exception: + return 100 + + +TICKS = host_ticks_per_second() + + +class CpuSampler: + """Per-thread CPU over the arm, sampled from the host. + + `/proc//task//stat` rather than the process total, because the quantity under + comparison is a PER-THREAD one: the kernel ignores this app's affinity requests, so the client + GL thread and the apply thread land on different clusters and a process total mixes two + different clock domains (MEASUREMENTS.md section 9's caveat, which is why the primary metric is + the client thread's CPU and not wall time). + + Under `spawn` the server role is a separate PROCESS, so the same read is taken against that pid + as well - `/proc//task/*` yields exactly the server's threads, and `libMobileGLServer.so` + is the process name that identifies it. + + Read as a delta between two samples, so the residual is bounded by one poll interval and is + reported rather than hidden: `first_utc`/`last_utc` are written into the summary. + """ + + def __init__(self, adb, package, interval=0.5): + self.adb = adb + self.package = package + self.interval = interval + self._stop = threading.Event() + self._thread = None + self.samples = [] + + def _read_once(self): + # THE DEVICE SIDE ONLY LOCATES THE NUMBERS; EVERY FIELD IS INDEXED ON THIS SIDE. + # + # `stat` is `pid (comm) state ...` and comm is its ONLY space-bearing field, so the split + # point is the LAST ')' - which is a two-line string operation and belongs in Python, not in + # a device-side program trying to survive three layers of shell quoting. Two attempts at + # doing it on the device failed differently and both looked like data: `set -- $(cat stat); + # echo $14` is `$1` followed by a literal 4 on Android's sh, so the sampler echoed the pid + # into every counter column and every delta came out 0; and an inline `awk` program cannot be + # written inside `su -c '...'` without its own quotes closing that wrapper, which surfaces as + # `/system/bin/sh: syntax error: unexpected '('` and an empty read. + # + # So the device-side text is one line per thread with no quotes at all: + # | + # and `summarize_cpu` never sees the raw text - only the counters parsed out of it here. + # + # Comm is truncated to 15 characters by the kernel, so `MobileGLTraceReplay` reads back as + # `MobileGLTraceRe`; matching is on the PREFIX. + script = ( + "P=$(pidof %s); S=$(pidof libMobileGLServer.so); " + "for pid in $P $S; do " + "[ -n \"$pid\" ] || continue; " + "for t in /proc/$pid/task/*; do " + "echo \"$pid ${t##*/} | $(cat $t/stat 2>/dev/null)\"; " + "done; done" + ) % self.package + out = self.adb.su(script, timeout=25) + rows = [] + for line in out.splitlines(): + head, sep, stat_line = line.partition("|") + if not sep: + continue + ids = head.split() + if len(ids) < 2 or ")" not in stat_line: + continue + open_paren = stat_line.find("(") + close_paren = stat_line.rfind(")") + if open_paren < 0 or close_paren < open_paren: + continue + # After the ')', stat's fields are: state(3) ppid(4) ... utime(14) stime(15) ... + # starttime(22). `tail` is that sequence, so stat's field N sits at 0-based N-3. + tail = stat_line[close_paren + 1:].split() + if len(tail) < 20: + continue + try: + rows.append({ + "pid": int(ids[0]), "tid": int(ids[1]), + "comm": stat_line[open_paren + 1:close_paren], + "utime": int(tail[14 - 3]), "stime": int(tail[15 - 3]), + "starttime": int(tail[22 - 3]), + }) + except ValueError: + continue + return rows + + def _loop(self): + while not self._stop.is_set(): + try: + rows = self._read_once() + except Exception: + rows = [] + if rows: + self.samples.append((time.time(), rows)) + self._stop.wait(self.interval) + + def start(self): + self._thread = threading.Thread(target=self._loop, daemon=True) + self._thread.start() + + def stop(self): + self._stop.set() + if self._thread: + self._thread.join(timeout=10) + + def replay_windows(self, min_seconds=1.0): + """Split the samples into one window PER REPLAY. + + TWO BOUNDARIES, because neither alone is sufficient: + + 1. A CHANGE IN THE PACKAGE'S MAIN THREAD IDENTITY. Each repeat is a separate app launch - + trace-replay-ci.sh force-stops the package and `am start`s it again - so the main thread + has a new tid. This is the structural boundary and needs no threshold. + 2. A GAP WIDER THAN THREE POLL INTERVALS. Pids are recycled, and on a device that is + force-stopping and restarting one app, two consecutive replays really can receive the + same pid; the dead interval between them is then the only evidence that they were two + launches rather than one long one. The gap is also what separates the app sitting idle + from the app replaying. + + This matters because the divisor and the CPU counters have to describe the SAME stretch of + work. Summing CPU across three replays and dividing by ONE replay's frame count reports three + times the real per-frame cost; pairing a window with the wrong repeat's frames does the same + thing less visibly. + + Returns a list of (start_index, length) in sample order, keeping only windows at least + `min_seconds` long: shorter than that is start-up or teardown, not a replay. + """ + if not self.samples: + return [] + + def main_pid(rows): + """The pid of the CLIENT process, or None if it is not in this sample. + + Identified as "the process whose thread with tid == pid is not the server binary". tid == + pid is the definition of a main thread, so that half needs no evidence; the server + exclusion is needed because under `spawn` the server process is a separate main thread in + the same sample set. + + NOT matched on the package name: Android's comm for a main thread is the TAIL of the + process name truncated to 15 characters (`top.mobilegl.plugin.p6gate8.trace` reads back + as `n.p6gate8.trace`), so a prefix comparison against `top.mobilegl...` never matches and + would silently produce zero windows. + """ + for row in rows: + if row["tid"] != row["pid"]: + continue + if row["comm"].startswith("libMobileGL"): + continue + return row["pid"] + return None + + gap_limit = self.interval * 3 + windows = [] + run_start = 0 + current_pid = main_pid(self.samples[0][1]) + for index in range(1, len(self.samples)): + stamp, rows = self.samples[index] + pid = main_pid(rows) + gap = stamp - self.samples[index - 1][0] + pid_changed = pid is not None and current_pid is not None and pid != current_pid + if pid_changed or gap > gap_limit: + windows.append((run_start, index - run_start)) + run_start = index + if pid is not None: + current_pid = pid + windows.append((run_start, len(self.samples) - run_start)) + + kept = [] + for start, length in windows: + span = self.samples[start + length - 1][0] - self.samples[start][0] + if span >= min_seconds: + kept.append((start, length)) + return kept + + +def summarize_cpu(samples, clock_ticks): + """Per-thread CPU milliseconds over the sample window, keyed by (pid, tid, starttime). + + THE WINDOW IS ANCHORED ON EACH THREAD'S OWN FIRST AND LAST SIGHTING, not on the first and last + sample. The app's threads are not all alive for the whole window - the GL thread is created when + the replay starts, and under `spawn` the server process appears partway through - so a single + global pair of timestamps would report every late thread's counter as if it had been spent since + the window opened, i.e. as an overcount, and would report a thread that exited early as zero. + Anchoring per thread makes `cpu_ms` the CPU that thread really consumed while it existed; the + window it did so in is `window_seconds`, which is per thread for the same reason. + + `ms_per_frame` is filled in by the caller, which is the only place that knows the frame count + and the frame-to-frame mapping. + """ + if len(samples) < 2: + return {"threads": [], "window_seconds": 0.0, "clock_ticks": clock_ticks} + sightings = {} + for index, (stamp, rows) in enumerate(samples): + for row in rows: + # IDENTITY IS (pid, tid, STARTTIME). Two threads can share a tid across a process's + # lifetime - the kernel recycles them - and a short-lived thread spawned near the end of + # a window has tid values that look like an unrelated long-lived one's. Keying on + # (pid, tid) alone merged those and produced a handful of phantom entries with one + # sample each: under inproc the OpenRA replay's real GL thread showed up three times, + # once with the right 880 ms and twice with 0. `starttime` is what tells them apart, and + # it is why the device-side read carries field 22. + key = (row["pid"], row["tid"], row["starttime"]) + entry = sightings.setdefault(key, { + "pid": row["pid"], "tid": row["tid"], "comm": row["comm"], + "first_index": index, "last_index": index, "first": row, "last": row, "count": 0, + }) + entry["last_index"] = index + entry["last"] = row + entry["count"] += 1 + + threads = [] + for entry in sightings.values(): + dticks = ((entry["last"]["utime"] - entry["first"]["utime"]) + + (entry["last"]["stime"] - entry["first"]["stime"])) + span = samples[entry["last_index"]][0] - samples[entry["first_index"]][0] + threads.append({ + "pid": entry["pid"], "tid": entry["tid"], "comm": entry["comm"], + "cpu_ms": round(1000.0 * dticks / clock_ticks, 3), + "window_seconds": round(span, 3), + "samples": entry["count"], + "starttime": entry["first"]["starttime"], + # A thread seen in only ONE sample has no delta to measure, and `cpu_ms` for it is 0 by + # construction rather than by evidence. Flagged rather than dropped so the row can be + # excluded from the ROLE table while still being visible in the raw dump - a thread that + # only ever appeared once is not a measurement of anything, and a table that averages it + # in as a zero is worse than one that omits it. + "measurable": entry["count"] > 1, + }) + threads.sort(key=lambda t: -t["cpu_ms"]) + return { + "threads": threads, + "window_seconds": round(samples[-1][0] - samples[0][0], 3), + "clock_ticks": clock_ticks, + "first_utc": datetime.fromtimestamp(samples[0][0], timezone.utc).isoformat(), + "last_utc": datetime.fromtimestamp(samples[-1][0], timezone.utc).isoformat(), + } + + +def read_stats_line(log_path): + """The LAST `MGPipe stats:` line in a role log, parsed. + + Last and not first: the line is a WINDOW, and the first window of a run contains load and + shader warm-up. The last is the closest thing to steady state the trace has (for rd12, the + trailing window of a 251-frame benchmark). + """ + if not Path(log_path).is_file(): + return None + last = None + with open(log_path, encoding="utf-8", errors="replace") as handle: + for line in handle: + if "MGPipe stats:" in line: + last = line.strip() + if last is None: + return None + parsed = {"raw": last} + ledger = WAIT_LEDGER.search(last) + if ledger: + parsed["wait"] = { + "srv": int(ledger.group(1)), "srvpark": int(ledger.group(2)), + "cli": int(ledger.group(3)), "clipark": int(ledger.group(4)), + } + window = re.search(r"window=(\d+)", last) + if window: + parsed["window_frames"] = int(window.group(1)) + frames = re.search(r"\bframes=(\d+)", last) + if frames: + parsed["run_frames"] = int(frames.group(1)) + draws = re.search(r"draws/f=([\d.]+)", last) + if draws: + parsed["draws_per_frame"] = float(draws.group(1)) + # The byte classes, keyed by their short names, straight out of the `bytes/f[...]` bracket. + bracket = re.search(r"bytes/f\[([^\]]*)\]", last) or re.search(r"bytes\[([^\]]*)\]", last) + if bracket: + for entry in bracket.group(1).split(): + if "=" in entry: + name, value = entry.split("=", 1) + try: + parsed.setdefault("bytes_per_frame", {})[name] = float(value) + except ValueError: + pass + maxrec = re.search(r"maxrec=(\d+)", last) + if maxrec: + parsed["max_record_bytes"] = int(maxrec.group(1)) + maxcap = re.search(r"maxcap=(\d+)", last) + if maxcap: + parsed["max_record_cap"] = int(maxcap.group(1)) + ringwaits = re.search(r"ringwaits=(\d+)", last) + if ringwaits: + parsed["ring_waits"] = int(ringwaits.group(1)) + return parsed + + +class Arm: + def __init__(self, spec, args, out_root, index): + fields = spec.split(":") + self.transport = fields[0] + self.backend = fields[1] if len(fields) > 1 else "DirectGLES" + self.case = fields[2] if len(fields) > 2 else None + self.repeats = int(fields[3]) if len(fields) > 3 else args.repeats + self.tree = Path(args.tree).resolve() + self.package = args.package + self.label = f"{index:02d}-{self.case}-{self.backend}-{self.transport}-r{self.repeats}" + self.dir = out_root / self.label + self.dir.mkdir(parents=True, exist_ok=True) + self.adb = Adb(args.serial) + self.summary = { + "label": self.label, "case": self.case, "backend": self.backend, + "transport": self.transport, "repeats": self.repeats, + } + + def env_overrides(self): + env = ["MOBILEGL_PIPE_STATS=1", f"MOBILEGL_PIPE_STATS_PERIOD={STATS_PERIOD}"] + if self.transport != "monolith": + env.insert(0, f"MOBILEGL_TRANSPORT={self.transport}") + env.extend(SPLIT_KNOBS) + return env + + @staticmethod + def surface_env(): + """The surface shape, exported rather than passed as an override - and that distinction is + load-bearing. + + `MOBILEGL_RETRACE_USE_PBUFFER` is read by trace-replay-ci.sh ITSELF, to decide whether to + add `--ez use_pbuffer true` to the activity intent. A `--env MOBILEGL_RETRACE_USE_PBUFFER=1` + override only reaches the applier of env knobs deep inside the replay process, which is a + different mechanism and does not set that shell variable - so the retrace still asks for a + window surface. + + That is fatal on the spawn arm and only there: an ANativeWindow* is a pointer into the + CLIENT's process and the wire refuses it by name (Rule H). Measured on this tree - the spawn + arm died with `Fatal{UnmigratedSurface, "AndroidNativeWindow@P12"}` published as a + SessionFault, and the same run passes as soon as the variable is in the script's environment. + """ + return {"MOBILEGL_RETRACE_USE_PBUFFER": "1"} + + def result_dirs(self): + """The runner's result directory for this case/backend (it is fixed, not per-arm).""" + safe = "".join(c if c.isalnum() or c in "._-" else "_" for c in self.case) + return self.tree / ".trace-work" / "android-retrace-result" / f"{safe}-{self.backend}" + + def build_command(self): + return [ + sys.executable, "tools/trace_replay/run_android_retrace_local.py", + "--case", self.case, "--backend", self.backend, "--keep-results", + "--benchmark", "--benchmark-repeats", str(self.repeats), + "--benchmark-tail-frames", "200", "--benchmark-no-finish", + "--benchmark-timeout-seconds", "1800", + "--env", ";".join(self.env_overrides()), + ] + + def child_env(self): + env = dict(os.environ) + env["ANDROID_SERIAL"] = self.adb.serial + # Snapshot-local override so this build can sit beside an unrelated trace install under + # the canonical id (see run_android_retrace_local.py's note beside BACKENDS). + env["MOBILEGL_TRACE_PACKAGE"] = self.package + # The session installs the APK once, before the thermal window opens; the script's own + # `adb install -r` on the first repeat would otherwise run inside it. trace-replay-ci.sh + # puts its install behind this variable and leaves `copy_fixture_to_app` OUTSIDE the same + # branch, so skipping the install still gets the trace and golden onto the device - which + # matters here because the first repeat of every arm is a `reuse_fixture == 0` run. + env["MOBILEGL_TRACE_SKIP_INSTALL"] = "1" + env.update(self.surface_env()) + env["PYTHON"] = sys.executable + env["MSYS2_ARG_CONV_EXCL"] = "/data/*" + env.pop("MSYS_NO_PATHCONV", None) + return env + + def pin(self, action): + # Git Bash needs its own path form: `bash C:/Users/...` is not a path it resolves (measured + # "No such file or directory" for a script that exists). The /c/ form is what its own + # MSYS path layer understands, and the interpreter is named explicitly because a bare + # `bash` on this host can resolve to something that is not Git Bash at all. + script = self.tree.as_posix().replace("C:/", "/c/") + "/tools/device_bench/pin_device.sh" + result = run([GIT_BASH, script, self.adb.serial, action], cwd=str(self.tree)) + return result.returncode, result.stdout + result.stderr + + def thread_role(self, thread): + """Which of the two roles this thread carries, from its name and its process. + + The kernel truncates comm to 15 characters, so the names to match are PREFIXES: + `MobileGLTraceReplay` is `MobileGLTraceRe`, and `mgl-srv-apply` survives intact. + + Under `spawn` the whole server process is the server role, so every thread of that process + counts as one - the interesting one is whichever thread is busy, and naming it by process is + both simpler and truer than guessing from comm (the apply thread is named `mgl-srv-apply` + there too, but a future server-side thread would not be). + """ + if self.transport == "spawn" and thread["pid"] == self.summary.get("server_pid"): + return "server-process" + name = thread["comm"] + if name.startswith("MobileGLTraceRe"): + return "client-gl" + if name.startswith("mgl-srv"): + return "apply" + return "other" + + def run(self): + self.summary["boot_id"] = self.adb.boot_id() + self.summary["started_utc"] = datetime.now(timezone.utc).isoformat() + + # PURGE THE PREVIOUS ARM'S ARTEFACTS BEFORE THIS ONE STARTS, and not after it ends. + # The runner's result directory is keyed by case and backend, not by arm, so arm N+1 + # overwrites arm N's benchmark.json in place - and if arm N+1 fails early it leaves arm N's + # file sitting there under arm N+1's name. `read_benchmark` cannot tell: it reads whatever is + # at that path and files it as this run's result. Deleting first makes "no file" the only + # thing a failed run can leave behind, which `assert_arm` already refuses. + result_dir = self.result_dirs() + if result_dir.exists(): + shutil.rmtree(result_dir) + + gen, text = self.pin("pin") + (self.dir / "pin-before.txt").write_text(text, encoding="utf-8") + self.summary["pin_before_rc"] = gen + if gen != 0: + self.summary["status"] = "PIN_FAILED_BEFORE" + return + + # FORCE-STOP AND WAIT FOR IT TO ACTUALLY BE GONE BEFORE THE SAMPLER OPENS. + # + # A leftover instance from an earlier arm or an earlier session keeps answering `pidof`, so + # the sampler counts it as part of this arm's window - measured: a stray idle instance from a + # previous smoke run put 14 samples in front of the real repeat and made the window count + # disagree with the repeat count. trace-replay-ci.sh force-stops the package too, but only + # after it has pushed the fixture, which is well inside the sampler's lifetime; doing it here + # as well means the sampler's first sample cannot see anything but this arm. + self.adb.shell(f"am force-stop {self.package}") + for _ in range(20): + if not self.adb.shell(f"pidof {self.package}").strip(): + break + time.sleep(0.5) + + sampler = CpuSampler(self.adb, self.package) + sampler.start() + try: + result = run(self.build_command(), cwd=self.tree, env=self.child_env(), timeout=2000) + stdout = result.stdout + stderr = result.stderr + rc = result.returncode + except subprocess.TimeoutExpired as error: + stdout = (error.stdout or b"").decode("utf-8", "replace") + stderr = (error.stderr or b"").decode("utf-8", "replace") + rc = 124 + finally: + sampler.stop() + + (self.dir / "runner.stdout.txt").write_text(stdout, encoding="utf-8") + (self.dir / "runner.stderr.txt").write_text(stderr, encoding="utf-8") + self.summary["runner_rc"] = rc + + # ONE WINDOW PER REPLAY, matched to that repeat's own frame count. See + # CpuSampler.replay_windows: the boundary is the package's main-thread identity, and the + # divisor has to be the frames replayed inside the SAME window or the ratio is off by the + # repeat count in whichever direction the mistake was made. + windows = sampler.replay_windows() + clock = self.adb.clk_tck() + per_repeat = [] + for index, (start, length) in enumerate(windows): + window = sampler.samples[start:start + length] + per_repeat.append({ + "repeat": index + 1, + "start_utc": datetime.fromtimestamp(window[0][0], timezone.utc).isoformat(), + "end_utc": datetime.fromtimestamp(window[-1][0], timezone.utc).isoformat(), + "samples": length, + "cpu": summarize_cpu(window, clock), + }) + self.summary["sampler"] = { + "total_samples": len(sampler.samples), + "windows": len(windows), + "per_repeat": per_repeat, + } + + result_dir = self.result_dirs() + for role in ("client", "server"): + source = result_dir / f"mobilegl.{role}.log" + if source.is_file(): + shutil.copyfile(source, self.dir / f"mobilegl.{role}.log") + for name in ("benchmark.json", "transport-proof.json", "result.json", "logcat.txt"): + source = result_dir / name + if source.is_file(): + shutil.copyfile(source, self.dir / name) + + self.summary["stats"] = { + "client": read_stats_line(self.dir / "mobilegl.client.log"), + "server": read_stats_line(self.dir / "mobilegl.server.log"), + } + + reports = [] + for path in sorted(result_dir.glob("benchmark-run*.json")): + try: + reports.append(json.loads(path.read_text(encoding="utf-8"))) + except ValueError: + pass + if not reports and (result_dir / "benchmark.json").is_file(): + reports.append(json.loads((result_dir / "benchmark.json").read_text(encoding="utf-8"))) + self.summary["benchmark_runs"] = reports + + # THE ms/FRAME COLUMN IS COMPUTED FOR EVERY REPEAT, not just the best one, and the best-of-N + # row is chosen exactly as run_android_retrace_local.py chooses it - lowest mean frame time - + # so this row and the runner's own summary line describe one run rather than a median of a + # median. + # + # `repeat_count_matches_windows` is checked rather than assumed: every per-frame column pairs + # window N with repeat N, so if one record has a replay the other does not, the pairs are + # wrong in a way no individual number would reveal. + self.summary["repeat_count_matches_windows"] = len(reports) == len(per_repeat) + for index, repeat in enumerate(per_repeat): + repeat["repeat"] = index + 1 + report = reports[index] if index < len(reports) else {} + repeat["benchmark"] = { + "totalFrames": report.get("totalFrames"), "tailFrames": report.get("tailFrames"), + "meanFrameMs": report.get("meanFrameMs"), "medianFrameMs": report.get("medianFrameMs"), + "p95FrameMs": report.get("p95FrameMs"), "fps": report.get("fps"), + } + frames = report.get("totalFrames") or 0 + for thread in repeat["cpu"]["threads"]: + thread["role"] = self.thread_role(thread) + if frames: + thread["cpu_ms_per_frame"] = round(thread["cpu_ms"] / frames, 4) + + if reports: + best_index, best = min( + enumerate(reports), + key=lambda pair: pair[1].get("meanFrameMs", -1) if pair[1].get("meanFrameMs", -1) > 0 else float("inf"), + ) + self.summary["best_repeat"] = { + "index": best_index + 1, + "totalFrames": best.get("totalFrames"), "tailFrames": best.get("tailFrames"), + "meanFrameMs": best.get("meanFrameMs"), "medianFrameMs": best.get("medianFrameMs"), + "p95FrameMs": best.get("p95FrameMs"), "fps": best.get("fps"), + "meanFrameCpuMs": best.get("meanFrameCpuMs"), + "medianFrameCpuMs": best.get("medianFrameCpuMs"), + "p95FrameCpuMs": best.get("p95FrameCpuMs"), + } + self.summary["best_repeat_frames"] = best.get("totalFrames") or 0 + + gen2, text2 = self.pin("check") + (self.dir / "pin-after.txt").write_text(text2, encoding="utf-8") + self.summary["pin_after_rc"] = gen2 + + self.assert_arm() + self.summary["finished_utc"] = datetime.now(timezone.utc).isoformat() + (self.dir / "arm-summary.json").write_text( + json.dumps(self.summary, indent=2), encoding="utf-8") + + def assert_arm(self): + """Does the library's own log prove the arm it is labelled as? + + Two questions, and the second is the one that matters for `spawn`: + 1. did the transport resolve to what this arm claims (the ConfigLoader marker), and + 2. for spawn, did the server role actually leave this process (the `spawn ARMED` pid line, + which only ClientSession::StartSpawned writes and only after launch+connect+handshake + all succeeded). + A run that resolved spawn and then never reached another process produces the first line and + not the second; a run that fell back to monolith produces neither. Either way the arm is + `status: UNPROVEN` and its numbers are not evidence. + """ + problems = [] + client = self.dir / "mobilegl.client.log" + texts = {} + for role in ("client", "server"): + path = self.dir / f"mobilegl.{role}.log" + texts[role] = path.read_text(encoding="utf-8", errors="replace") if path.is_file() else "" + combined = texts["client"] + texts["server"] + + expected = TRANSPORT_MARKERS.get(self.transport) + if expected is not None: + if expected not in texts["client"]: + problems.append(f"client log does not carry the transport marker for {self.transport}") + configs = re.findall(r"Config: IPC[^\n]*", texts["client"]) + if not configs: + problems.append("no `Config: IPC` line on the client: the split knobs never resolved") + else: + for key in ("strict=1", "role-split-state=1", "run-ahead=1"): + if not any(key in line for line in configs): + problems.append(f"`Config: IPC` line missing {key}") + else: + # The control arm has to be a control: no IPC line and no transport marker. + if "Config: IPC" in combined: + problems.append("monolith arm wrote a `Config: IPC` line: the knobs were armed") + + if self.transport == "spawn": + armed = SPAWN_ARMED.search(texts["client"]) + if armed is None: + problems.append("no `spawn ARMED - the server role runs in pid N` line: " + "the server never left this process") + else: + self.summary["server_pid"] = int(armed.group(1)) + if not texts["server"]: + problems.append("spawn arm has no server-role log") + elif self.transport == "inproc": + if not texts["server"]: + problems.append("inproc arm has no server-role log (the apply thread's own file)") + + for path in self.dir.glob("mobilegl.*.log"): + for line in path.read_text(encoding="utf-8", errors="replace").splitlines(): + if "Fatal{" in line: + problems.append(f"Fatal{{ in {path.name}: {line.strip()[:200]}") + break + + if self.summary.get("pin_before_rc") != 0: + problems.append("pin did not take before the run") + if self.summary.get("pin_after_rc") != 0: + problems.append("pin check AFTER the run did not report PINNED: this arm is void") + if self.summary.get("runner_rc") != 0: + problems.append(f"runner exited {self.summary.get('runner_rc')}") + if not self.summary.get("benchmark_runs"): + problems.append("no benchmark.json was pulled") + + self.summary["problems"] = problems + self.summary["status"] = "OK" if not problems else "UNPROVEN" + + +def main(): + parser = argparse.ArgumentParser() + parser.add_argument("--tree", required=True, help="Snapshot tree the APK and runner come from") + parser.add_argument("--out", required=True, help="Evidence root for this session") + parser.add_argument("--serial", default=SERIAL) + parser.add_argument("--package", default="top.mobilegl.plugin.p6gate8.trace", + help="Application id of the installed trace APK. Defaults to the id this " + "campaign's development builds use; pass the canonical " + "top.mobilegl.plugin.trace for a stock install.") + parser.add_argument("--apk", required=True, help="Signed trace APK to install before the window") + parser.add_argument("--arm", action="append", required=True, + metavar="TRANSPORT[:BACKEND[:CASE[:REPEATS]]]", + help="One arm, in the order given. Repeating a spec interleaves it.") + parser.add_argument("--repeats", type=int, default=3) + parser.add_argument("--reboot", action="store_true", + help="Reboot and wait for boot_completed before the window") + parser.add_argument("--fan-level", default="2") + parser.add_argument("--session", default=None) + args = parser.parse_args() + + tree = Path(args.tree).resolve() + label = args.session or datetime.now(timezone.utc).strftime("%Y%m%dT%H%M%SZ") + out_root = Path(args.out).resolve() / label + out_root.mkdir(parents=True, exist_ok=True) + adb = Adb(args.serial) + + session = {"label": label, "serial": args.serial, "tree": str(tree), + "package": args.package, "apk": str(Path(args.apk).resolve()), + "apk_sha256": subprocess.run(["sha256sum", args.apk], capture_output=True, text=True) + .stdout.split()[0], + "arms": [a for a in args.arm], "repeats": args.repeats, + "stats_period": STATS_PERIOD, + # The DEVICE's tick rate, read here so the session records the divisor every arm's + # CPU number was computed with. `TICKS` (the host's) is only a fallback for a device + # that cannot answer, and printing it here would have looked like the answer. + "device_clock_ticks": adb.clk_tck()} + + # The fan is a CONSTANT of the protocol, not a treatment: both arms run under the same airflow, + # and on this device it is the difference between a 60 s cool-down between arms and a 20-minute + # one (notes/p4a/INTEGRATOR-DECISIONS.md). `real_speed` is read back because target_level alone + # is a request, not a fact. + fan = "/sys/class/xm_power/hw_monitor/pwm_fan" + adb.su(f"echo {args.fan_level} > {fan}/target_level") + time.sleep(3) + session["fan"] = { + "target_level": adb.su(f"cat {fan}/target_level").strip(), + "real_speed": adb.su(f"cat {fan}/real_speed").strip(), + "pwm_duty": adb.su(f"cat {fan}/pwm_duty").strip(), + } + + if args.reboot: + session["reboot_requested_utc"] = datetime.now(timezone.utc).isoformat() + boot_before = adb.boot_id() + adb.reboot() + if not adb.wait_boot(): + print("device did not reach boot_completed", file=sys.stderr) + return 2 + # boot_id must have CHANGED, or "reboot-clean" is a claim about a reboot that did not happen. + time.sleep(20) + boot_after = adb.boot_id() + session["boot_id_before"] = boot_before + session["boot_id"] = boot_after + session["rebooted_clean"] = boot_before != boot_after + if not session["rebooted_clean"]: + print(f"boot_id unchanged ({boot_before}): not a clean reboot", file=sys.stderr) + return 2 + # Re-assert the fan: an xm_power level does not always survive a reboot. + adb.su(f"echo {args.fan_level} > {fan}/target_level") + time.sleep(3) + else: + session["boot_id"] = adb.boot_id() + session["rebooted_clean"] = False + + install = run(["adb", "-s", args.serial, "install", "-r", str(Path(args.apk).resolve())]) + session["install"] = (install.stdout + install.stderr).strip().splitlines()[-1:] + # dex2oat outlives the install by a minute or two, and an `am_kill ... due to installPackageLI` + # landing inside the first arm is a measurement of the installer, not of the transport + # (MEASUREMENTS.md section 10). Wait for it by name. + for _ in range(60): + if not adb.shell("ps -A -o NAME | grep -c dex2oat").strip().isdigit(): + break + if adb.shell("ps -A -o NAME | grep -c dex2oat").strip() == "0": + break + time.sleep(5) + time.sleep(10) + + session["arms"] = [] + for index, spec in enumerate(args.arm, start=1): + started = time.time() + arm = Arm(spec, args, out_root, index) + print(f"=== arm {arm.label} ===", flush=True) + arm.run() + session["arms"].append(arm.summary) + print(f" status={arm.summary['status']} problems={arm.summary.get('problems')} " + f"({time.time() - started:.0f}s)", flush=True) + # Between-arm cool-down, gate at 40 C on the CPU-subsystem sensor the pin script reports. + for _ in range(60): + temp = adb.su("cat /sys/class/thermal/thermal_zone13/temp").strip() + try: + if int(temp) <= 36000: + break + except ValueError: + break + time.sleep(5) + + (out_root / "session-summary.json").write_text( + json.dumps(session, indent=2), encoding="utf-8") + print(json.dumps({"session": label, "out": str(out_root), + "arms": [{"label": a["label"], "status": a["status"]} + for a in session["arms"]]}, indent=2)) + return 0 if all(a["status"] == "OK" for a in session["arms"]) else 1 + + +if __name__ == "__main__": + raise SystemExit(main()) diff --git a/tools/device_bench/p6/render_ab.py b/tools/device_bench/p6/render_ab.py new file mode 100644 index 00000000..f2c31ddf --- /dev/null +++ b/tools/device_bench/p6/render_ab.py @@ -0,0 +1,369 @@ +#!/usr/bin/env python3 +"""Renders an ab_session.py session into the markdown tables the report needs. + +Separate from the runner on purpose: the runner's job is to COLLECT, and a renderer that is reading +its own session-summary.json cannot influence what was collected. Every number below is a lookup or +an arithmetic step over that file - nothing here re-derives anything from the device. + +Usage: + python render_ab.py /session-summary.json [--title T] +""" + +from __future__ import annotations + +import argparse +import json +import sys +from pathlib import Path + + +def fmt(value, digits=3): + if value is None: + return "-" + if isinstance(value, float): + return f"{value:.{digits}f}" + return str(value) + + +def steady_state_cpu(arm): + """Per-thread CPU ms/frame over the arm's steady-state frames, from the DEVICE's own two + independent series. + + WHY NOT the sampler's totals divided by the frame count, which is what this used to report: + those totals are correct and the per-frame ratio is wrong, because a replay's frames are not + interchangeable. Measured on the rd12 fixture with this build, frame 1 costs 7332 ms of CPU on + the client thread - one shader/pipeline bring-up - and the other 250 frames cost 7.7-8.5 ms + each. Dividing a whole replay's CPU by 251 frames charges every frame 1/251st of a compile that + happened once, which is why that column read ~32 ms/frame beside a device median of 7.9. It is + a real number and not a real per-frame cost. + + So the per-frame figures come from the two series the DEVICE already computes over the trailing + `tailFrames`: + + - `medianFrameCpuMs` / `p95FrameCpuMs`: the client thread's own `clock_gettime(CLOCK_THREAD_ + CPUTIME_ID)` deltas per frame, summarised over the tail. Host-side per-frame sampling cannot + reproduce this - a 0.5 s poll interval cannot resolve an 8 ms frame - and it is the primary + metric (MEASUREMENTS.md section 9). + - `medianFrameMs` / `p95FrameMs`: wall time per frame, which is what the frame budget is. + + The sampler's contribution is the ROLES: which thread carried the work, on which core, and how + much CPU each role spent in total, which is what the doorbell comparison needs and what the + device's single client-thread series cannot express. + """ + best = arm.get("best_repeat") or {} + return { + "median_frame_ms": best.get("medianFrameMs"), + "p95_frame_ms": best.get("p95FrameMs"), + "median_frame_cpu_ms": best.get("medianFrameCpuMs"), + "p95_frame_cpu_ms": best.get("p95FrameCpuMs"), + "mean_frame_cpu_ms": best.get("meanFrameCpuMs"), + "fps": best.get("fps"), + } + + +def role_totals(arm): + """(client cpu_ms, server cpu_ms) summed over the best repeat's window, and the window length. + + TOTALS, not rates. They answer "which role spent the CPU and how much core-time did it burn", + and they are directly comparable across arms because every arm here replays the same fixture + with the same frame count - the one thing that would break the comparison is a different frame + count, which `repeat_count_matches_windows` and the shared `totalFrames` both guard. + """ + index = (arm.get("best_repeat") or {}).get("index", 1) - 1 + repeats = arm.get("sampler", {}).get("per_repeat", []) + if not (0 <= index < len(repeats)): + return None, None, None + repeat = repeats[index] + client = server = 0.0 + seen_c = seen_s = False + for thread in repeat.get("cpu", {}).get("threads", []): + if not thread.get("measurable") or thread.get("cpu_ms", 0) <= 0: + continue + role = thread.get("role") + if role == "client-gl": + client += thread["cpu_ms"] + seen_c = True + elif role in ("apply", "server-process"): + server += thread["cpu_ms"] + seen_s = True + return (client if seen_c else None, server if seen_s else None, + repeat.get("cpu", {}).get("window_seconds")) + + +def per_repeat_rows(arm): + """One row per REPLAY, with the frame count taken from the matching benchmark run. + + The CPU windows and the benchmark.json files are two independent records of the same repeats, in + the same order, and they are joined BY ORDINAL - window N is repeat N. The ordinal is asserted + rather than assumed (`repeat_count_matches_windows` in the arm summary): a mismatch means one + record has a replay the other does not, and silently pairing them would attribute one replay's + CPU to another replay's frames. + """ + runs = arm.get("benchmark_runs") or [] + rows = [] + for repeat in arm.get("sampler", {}).get("per_repeat", []): + client = server = 0.0 + seen_c = seen_s = False + for thread in repeat.get("cpu", {}).get("threads", []): + if not thread.get("measurable") or thread.get("cpu_ms", 0) <= 0: + continue + role = thread.get("role") + if role == "client-gl": + client += thread["cpu_ms"] + seen_c = True + elif role in ("apply", "server-process"): + server += thread["cpu_ms"] + seen_s = True + index = repeat.get("repeat", 0) - 1 + report = runs[index] if 0 <= index < len(runs) else {} + rows.append({ + "repeat": repeat.get("repeat"), + "frames": report.get("totalFrames"), + "mean_frame_ms": report.get("meanFrameMs"), + "median_frame_ms": report.get("medianFrameMs"), + "median_frame_cpu_ms": report.get("medianFrameCpuMs"), + "fps": report.get("fps"), + "seconds": repeat.get("cpu", {}).get("window_seconds"), + "client_total_ms": client if seen_c else None, + "server_total_ms": server if seen_s else None, + }) + return rows + + +def best_frames(arm): + return arm.get("best_repeat_frames") or (arm.get("best_repeat") or {}).get("totalFrames") + + +def wait_delta(arm): + """The wait ledger for the arm, as run totals plus a per-frame rate. + + THE FOUR NUMBERS COME FROM TWO DIFFERENT LOGS ON A SPAWN ARM, and that is structural rather than + a collection gap. `srv`/`srvpark` are published by the server's own apply loop into the PipeStats + of the process it runs in, so: + + - under `inproc` both roles are threads of one process, and the client log's line carries all + four; + - under `spawn` the apply thread lives in the SERVER process, so its pair is written to + `mobilegl.server.log` and the client's line prints `srv=0 srvpark=0`. PipeStats.h documents + that shape: a zero that means "another process" printed like a zero that means "never + waited". So the pair is read from the server log here and the zeros are NOT reported as + evidence that the server never waited. + + `cli`/`clipark` are the client's own producer and are always in the client log. + + The per-frame rate divides by the RUN frame count (`frames=`, the third field on that line) and + NOT by `window=`. + + THOSE ARE TWO DIFFERENT DENOMINATORS AND ONLY ONE OF THEM IS RIGHT HERE. Everything in the + `bytes/f[...]`, `tex[...]` and `emit[...]` brackets is a WINDOW value (the last `window=` frames), + but the `wait[...]` bracket and the ring gauges above it are RUN TOTALS - PipeStats.h says so in + as many words beside the Gauge enum, because "a windowed difference of two counters published by + two threads at two different moments is not a quantity either of them ever held". Dividing a run + total by a window length inflates the rate by (run/window) - measured on a 128-frame OpenRA + replay that is 16x, which looks like a plausible number and is not one. + + WHICH LOG SUPPLIES THE RUN FRAME COUNT DEPENDS ON THE TRANSPORT, and this is the second + structural asymmetry of the spawn shape. The frame counter is bumped by `PipeStats::OnPresent`, + which the backend calls on Present, and under `spawn` Present is applied in the SERVER process: + + - `inproc`: one process. The client log carries the session's final line, emitted by + `PipeStats::Shutdown` at teardown, `frames=251`. The server log's own last line is at its + previous period boundary (`frames=240`) because the apply thread does not emit the + session-final one. So the client's number is the run. + - `spawn`: the client never presents, so its `frames=0 window=0`. That zero is structural - it + is the same shape as the `srv=0` zero - and dividing by it is undefined. The run's frame + count is the SERVER's `frames=251`. + + So the denominator is the client's when it is non-zero, and the server's when it is not, and + `run_frames_source` records which one was used. Using one log's frames with the other log's + counters - the obvious thing to write - is the mistake this paragraph exists to prevent. + """ + stats = arm.get("stats") or {} + client = stats.get("client") or {} + server = stats.get("server") or {} + wait = dict(client.get("wait") or {}) + source = "client-log" + if arm.get("transport") == "spawn": + server_wait = server.get("wait") + if server_wait: + # Replace the client log's structurally-zero server half with the server's own. + wait["srv"] = server_wait["srv"] + wait["srvpark"] = server_wait["srvpark"] + source = "client-log(cli) + server-log(srv)" + else: + source = "client-log only (no server-log summary line: srv NOT available)" + run_frames = client.get("run_frames") + run_frames_source = "client-log" + if not run_frames: + # The spawn shape: this process never presented, so it counted no frames. + run_frames = server.get("run_frames") + run_frames_source = "server-log (client frames=0: it never presents under spawn)" + out = {"source": source, "wait": wait or None, "run_frames": run_frames, + "run_frames_source": run_frames_source, + "client_run_frames": client.get("run_frames"), + "client_window_frames": client.get("window_frames"), + "server_run_frames": server.get("run_frames"), + "server_window_frames": server.get("window_frames")} + if wait and run_frames: + out["per_frame"] = {key: round(value / run_frames, 4) for key, value in wait.items()} + return out + + +def main(): + parser = argparse.ArgumentParser() + parser.add_argument("session") + parser.add_argument("--title", default=None) + args = parser.parse_args() + + session = json.loads(Path(args.session).read_text(encoding="utf-8")) + arms = session.get("arms", []) + lines = [] + + title = args.title or f"A/B session {session.get('label')}" + lines.append(f"## {title}") + lines.append("") + lines.append(f"- session directory: `{session.get('label')}`") + lines.append(f"- boot id: `{session.get('boot_id')}` " + f"(reboot-clean: {session.get('rebooted_clean')})") + lines.append(f"- package: `{session.get('package')}`") + lines.append(f"- APK sha256: `{session.get('apk_sha256')}`") + lines.append("") + + # --- headline: frame time and per-thread CPU ------------------------------------------------ + lines.append("### Frame time and per-thread CPU (best of N)") + lines.append("") + lines.append("The `frame cpu` column is the CLIENT thread's own per-frame CPU clock, summarised by the") + lines.append("device over the trailing `tailFrames` - the primary metric (MEASUREMENTS.md section 9).") + lines.append("`client total` / `server total` are the sampler's per-role CPU TOTALS over that repeat,") + lines.append("which includes the one-off shader bring-up frame; they are not per-frame rates. See") + lines.append("steady_state_cpu in this file.") + lines.append("") + lines.append("| arm | transport | status | frames | tail | mean ms | p50 ms | p95 ms | fps | frame cpu p50 ms | cpu p95 ms | client total ms | server total ms |") + lines.append("|---|---|---|---|---|---|---|---|---|---|---|---|---|") + for arm in arms: + best = arm.get("best_repeat") or {} + client_total, server_total, _window = role_totals(arm) + lines.append( + f"| {arm.get('label')} | {arm.get('transport')} | {arm.get('status')} " + f"| {fmt(best.get('totalFrames'))} | {fmt(best.get('tailFrames'))} " + f"| {fmt(best.get('meanFrameMs'))} | {fmt(best.get('medianFrameMs'))} " + f"| {fmt(best.get('p95FrameMs'))} | {fmt(best.get('fps'), 2)} " + f"| {fmt(best.get('medianFrameCpuMs'))} | {fmt(best.get('p95FrameCpuMs'))} " + f"| {fmt(client_total, 1)} | {fmt(server_total, 1)} |") + lines.append("") + + # --- the pair deltas ------------------------------------------------------------------------ + lines.append("### Paired deltas (inproc = A, spawn = B)") + lines.append("") + lines.append("| pair | metric | A | B | B - A | B/A - 1 |") + lines.append("|---|---|---|---|---|---|") + by_key = {} + for arm in arms: + by_key.setdefault((arm.get("case"), arm.get("backend"), arm.get("transport")), arm) + seen_pairs = set() + for (case, backend, _transport) in by_key: + if (case, backend) in seen_pairs: + continue + seen_pairs.add((case, backend)) + a = by_key.get((case, backend, "inproc")) + b = by_key.get((case, backend, "spawn")) + if not a or not b: + continue + for metric, getter in ( + ("mean frame ms", lambda x: (x.get("best_repeat") or {}).get("meanFrameMs")), + ("p50 frame ms", lambda x: (x.get("best_repeat") or {}).get("medianFrameMs")), + ("p95 frame ms", lambda x: (x.get("best_repeat") or {}).get("p95FrameMs")), + ("client frame cpu p50 ms", lambda x: (x.get("best_repeat") or {}).get("medianFrameCpuMs")), + ("client frame cpu p95 ms", lambda x: (x.get("best_repeat") or {}).get("p95FrameCpuMs")), + ("fps", lambda x: (x.get("best_repeat") or {}).get("fps")), + ): + va, vb = getter(a), getter(b) + if va and vb: + lines.append(f"| {case}/{backend} | {metric} | {fmt(va)} | {fmt(vb)} " + f"| {fmt(vb - va)} | {fmt(vb / va - 1, 4)} |") + for label, index in (("client cpu total ms", 0), ("server cpu total ms", 1)): + va, vb = role_totals(a)[index], role_totals(b)[index] + if va and vb: + lines.append(f"| {case}/{backend} | {label} | {fmt(va, 1)} | {fmt(vb, 1)} " + f"| {fmt(vb - va, 1)} | {fmt(vb / va - 1, 4)} |") + lines.append("") + + # --- the doorbell ledger -------------------------------------------------------------------- + lines.append("### The wait ledger") + lines.append("") + lines.append("The `wait[...]` bracket and the ring gauges are RUN TOTALS, so these rates divide by the run's") + lines.append("frame count (`frames=`), not by the `window=` of the same line. See wait_delta. The `used`") + lines.append("column names the log the frame count came from: under `spawn` the client's own `frames=` is") + lines.append("**structurally 0**, because it never presents - present is applied in the server process.") + lines.append("") + lines.append("| arm | counters from | frames from | used frames | cli frames= | srv frames= | srv | srvpark | cli | clipark | srv/f | srvpark/f | cli/f | clipark/f |") + lines.append("|---|---|---|---|---|---|---|---|---|---|---|---|---|---|") + for arm in arms: + entry = wait_delta(arm) + wait = entry["wait"] or {} + per = entry.get("per_frame") or {} + lines.append( + f"| {arm.get('label')} | {entry['source']} | {entry['run_frames_source']} " + f"| {fmt(entry.get('run_frames'))} | {fmt(entry.get('client_run_frames'))} " + f"| {fmt(entry.get('server_run_frames'))} " + f"| {fmt(wait.get('srv'))} | {fmt(wait.get('srvpark'))} | {fmt(wait.get('cli'))} " + f"| {fmt(wait.get('clipark'))} | {fmt(per.get('srv'))} | {fmt(per.get('srvpark'))} " + f"| {fmt(per.get('cli'))} | {fmt(per.get('clipark'))} |") + lines.append("") + + # --- per repeat ----------------------------------------------------------------------------- + lines.append("### Per-repeat windows") + lines.append("") + for arm in arms: + lines.append(f"**{arm.get('label')}** (windows={arm.get('sampler', {}).get('windows')}, " + f"repeats={len(arm.get('benchmark_runs') or [])}, " + f"replay={arm.get('best_repeat', {}).get('meanFrameMs')})") + lines.append("") + lines.append("| repeat | frames | window s | p50 frame ms | frame cpu p50 ms | client total ms | server total ms |") + lines.append("|---|---|---|---|---|---|---|") + for row in per_repeat_rows(arm): + lines.append(f"| {fmt(row['repeat'])} | {fmt(row['frames'])} | {fmt(row['seconds'], 1)} " + f"| {fmt(row['median_frame_ms'])} | {fmt(row['median_frame_cpu_ms'])} " + f"| {fmt(row['client_total_ms'], 1)} | {fmt(row['server_total_ms'], 1)} |") + lines.append("") + + # --- byte classes and records --------------------------------------------------------------- + lines.append("### Wire byte classes and record size (gate 8 items 2-3 input)") + lines.append("") + lines.append("| arm | role | window | frames | buf/f | tex/f | ubog/f | ubon/f | csob-blob/f | resid/f | vtxc/f | idxc/f | icmd/f | pmap/f | maxrec | maxcap |") + lines.append("|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|") + for arm in arms: + for role in ("client", "server"): + stats = (arm.get("stats") or {}).get(role) + if not stats: + continue + bytes_per_frame = stats.get("bytes_per_frame") or {} + lines.append( + f"| {arm.get('label')} | {role} | {fmt(stats.get('window_frames'))} " + f"| {fmt(stats.get('run_frames'))} " + f"| {fmt(bytes_per_frame.get('buf'))} | {fmt(bytes_per_frame.get('tex'))} " + f"| {fmt(bytes_per_frame.get('ubog'))} | {fmt(bytes_per_frame.get('ubon'))} " + f"| {fmt(bytes_per_frame.get('csob-blob'))} | {fmt(bytes_per_frame.get('resid'))} " + f"| {fmt(bytes_per_frame.get('vtxc'))} | {fmt(bytes_per_frame.get('idxc'))} " + f"| {fmt(bytes_per_frame.get('icmd'))} | {fmt(bytes_per_frame.get('pmap'))} " + f"| {fmt(stats.get('max_record_bytes'))} | {fmt(stats.get('max_record_cap'))} |") + lines.append("") + + # --- arm proof ------------------------------------------------------------------------------ + lines.append("### Arm proof and pin state") + lines.append("") + lines.append("| arm | pin before | pin after | server pid (spawn) | problems |") + lines.append("|---|---|---|---|---|") + for arm in arms: + problems = "; ".join(arm.get("problems") or []) or "none" + lines.append(f"| {arm.get('label')} | {fmt(arm.get('pin_before_rc'))} " + f"| {fmt(arm.get('pin_after_rc'))} | {fmt(arm.get('server_pid'))} " + f"| {problems} |") + lines.append("") + + print("\n".join(lines)) + return 0 + + +if __name__ == "__main__": + sys.exit(main()) diff --git a/tools/device_bench/pin_device.sh b/tools/device_bench/pin_device.sh index f133a444..ed1e7272 100755 --- a/tools/device_bench/pin_device.sh +++ b/tools/device_bench/pin_device.sh @@ -70,6 +70,33 @@ case "$SERIAL" in GPU_PINNED_FREQ=1100000000 # gpuclk is in Hz on kgsl, NOT kHz GPU_FREQ_UNIT=Hz ;; + 2f7cbe2e) # Redmi M332BF, same SoC as 35d0befa but a DIFFERENT board vendor lock + DEV_NAME="Redmi M332BF / SM8750 / Adreno 830v2" + GPU_STYLE=kgsl + # Read off THIS unit on 2026-09-22, then confirmed against a pinned window (pin written, + # every node read back equal to the pin, unpinned, every node back at the stock values + # recorded below). Same SM8750 as 35d0befa and the same policy ids, BUT THE STOCK RANGES + # DIFFER (policy6 max is 3072000 here vs 2841600 there) - which is exactly why copying the + # sibling row would have been wrong even though the two parts are the same silicon. + # Every write below needs root; the verify action re-reads all of them. + POLICIES="big:policy6:1958400:1017600:3072000 little:policy0:1555200:556800:2745600" + THERMAL_TYPE=cpuss-0-0 # thermal_zone13 on this boot; matched by type, never by number + KGSL=/sys/class/kgsl/kgsl-3d0 + # THE ONE PLACE THIS DEVICE DIFFERS FROM 35d0befa'S ROW, AND IT IS MEASURED, NOT ASSUMED. + # Collapsing the kgsl pwrlevel range onto 0 does NOT reach 1100 MHz here: gpuclk reads + # 1050000000 and stays there across repeated samples, because this unit ships + # thermal_pwrlevel=1 permanently (it latches - writing 0 returns success and the node reads + # back 1) and max_gpuclk is read-only at 1050000000. devfreq's own max_freq also clamps to + # 1050000000. So the pin is "the fastest frequency this board will actually run", not "the + # top OPP in the table" - recorded as 1050 MHz so `check` compares against the truth. + # Consequence for the campaign, stated where the number is: absolute times from this device + # are NOT comparable with the 35d0befa rows taken while it could still reach 1100. + GPU_PIN_LEVEL=0 # pwrlevel 0 = the 1050 MHz ceiling this board enforces + GPU_STOCK_MIN_LEVEL=12 + GPU_STOCK_MAX_LEVEL=0 + GPU_PINNED_FREQ=1050000000 # gpuclk is in Hz on kgsl, NOT kHz + GPU_FREQ_UNIT=Hz + ;; 3B159D009VZ00000) # Oppo PLG110 / ColorOS, MediaTek MT6993 (Dimensity 9500), Mali DEV_NAME="Oppo PLG110 / MT6993 / Mali (gpufreqv2)" GPU_STYLE=gpufreqv2 @@ -84,7 +111,7 @@ case "$SERIAL" in ;; *) echo "$0: unknown serial '$SERIAL'." >&2 - echo "Known: 35d0befa (Xiaomi/Adreno830), 3B159D009VZ00000 (Oppo/Mali)." >&2 + echo "Known: 35d0befa (Xiaomi/Adreno830), 2f7cbe2e (Redmi/Adreno830), 3B159D009VZ00000 (Oppo/Mali)." >&2 echo "Refusing to guess: the pin path differs per SoC and a wrong one fails silently." >&2 exit 64 ;; esac diff --git a/tools/trace_replay/run_android_retrace_local.py b/tools/trace_replay/run_android_retrace_local.py index 81f63d12..6297cea0 100644 --- a/tools/trace_replay/run_android_retrace_local.py +++ b/tools/trace_replay/run_android_retrace_local.py @@ -44,6 +44,25 @@ BACKENDS = { }, } +# The trace APK's application id, overridable so a development build can be installed BESIDE an +# existing trace install instead of replacing it. +# +# WHY IT IS NEEDED: `-Pmobilegl.applicationIdSuffix=` is the only way to put two trace APKs on one +# device, and two APKs signed by different keys cannot share an id at all (`adb install -r` fails +# with INSTALL_FAILED_UPDATE_INCOMPATIBLE). A machine that already carries a trace install under the +# canonical id - signed by whichever key was current when it was made - otherwise has to have that +# install destroyed before an A/B can run, which is destructive and, on a shared bench, rude. +# +# ABSENT MEANS THE CANONICAL ID, so every existing caller keeps the behaviour it had. What the +# override does NOT change: the Activity class, the intent action, the extras, the on-device app dir +# and the arm-proof markers all stay identical, so the lane under test is the real lane. The one +# thing that must move with it is `--package` in the same command, because trace-replay-ci.sh drives +# `am start`, `run-as` and `force-stop` off it. tools/device_bench/p6/ab_session.py sets both. +_trace_package_override = __import__("os").environ.get("MOBILEGL_TRACE_PACKAGE", "").strip() +if _trace_package_override: + for _backend in BACKENDS.values(): + _backend["package"] = _trace_package_override + CASES = load_trace_cases()