From a5b835f76abdc9cde60c3fe66c2957ccd2bac708 Mon Sep 17 00:00:00 2001 From: Administrator Date: Sun, 21 Jun 2026 17:09:46 +0200 Subject: [PATCH] =?UTF-8?q?perf(uploads):=20threadpool=2064=E2=86=928=20+?= =?UTF-8?q?=20GC/heap=20instrumentation=20(decisive=20high-concurrency=20l?= =?UTF-8?q?ag=20build,=20v3.3.97)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The v3.3.96 eventloop-delay logs from a real 70-connection run pinpointed the high-concurrency lag to the file-read path. At a CONSTANT active-job count the process flips between two clean regimes: HEALTHY ELD ~11ms, rss 268-308MB: SimpleWriteWrap ≈ active, FSReqCallback ≈ 0-1 BLOCKED ELD 49-217ms, rss 540-610MB: FSReqCallback ≈ active (62-71 reads in flight), SimpleWriteWrap ≈ 0-4 Both the ELD spike and the rss balloon track FSReqCallback (libuv-threadpool file reads) exactly — not crypto, not the renderer, not GC alone. All five uploaders read identically via fs.createReadStream({highWaterMark: 256KB}); byse/doodstream/ voe run through the generic uploadFile in hosters.js (no dedicated module). This build is both a candidate fix and a discriminator, per advisor review: - UV_THREADPOOL_SIZE 64→8 (main.js:1). One reversible line, NOT an upload cap — 70 uploads still run. 8 concurrent 256KB reads sustain ~100MB/s, far above the 41MB/s aggregate, so it cannot bottleneck throughput even on the slow VM disk. Strong suspicion that tp=64 made it worse: it removed the natural read- serialization (default 4 threads) and let all 70 streams' reads fire at once, flooding the loop with completion callbacks in lock-step bursts. - ELD line now also logs heap=heapUsed ext=external ab=arrayBuffers and gc=/gcTotal=/gcMax=ms (PerformanceObserver entryTypes:['gc'], reset per window). The 70×256KB ≈ 18MB of read buffers cannot account for the ~300MB rss swing — that is heap/object churn, so GC must be measured directly. Decision rule for the next real-run log: - ELD drops with tp=8 → read over-parallelism confirmed (keep 8 or add a dedicated read-semaphore). - ELD high + GC pauses align → heap churn, hunt the allocator. - ELD high + GC flat → causation was reversed, pivot. No upload-behavior change; the concurrency cap the user explicitly rejected is untouched. Co-Authored-By: Claude Opus 4.8 (1M context) --- main.js | 32 +++++++++++++++++++++++++++----- package.json | 2 +- tasks/lessons.md | 15 +++++++++++++++ tasks/todo.md | 29 +++++++++++++++++++++++++++++ 4 files changed, 72 insertions(+), 6 deletions(-) diff --git a/main.js b/main.js index 286bd7e..4796004 100644 --- a/main.js +++ b/main.js @@ -1,5 +1,5 @@ -process.env.UV_THREADPOOL_SIZE = process.env.UV_THREADPOOL_SIZE || '64'; -const { monitorEventLoopDelay } = require('perf_hooks'); +process.env.UV_THREADPOOL_SIZE = process.env.UV_THREADPOOL_SIZE || '8'; +const { monitorEventLoopDelay, PerformanceObserver } = require('perf_hooks'); const { app, BrowserWindow, ipcMain, dialog, clipboard, nativeTheme, Tray, Menu, nativeImage } = require('electron'); nativeTheme.themeSource = 'dark'; const path = require('path'); @@ -32,6 +32,19 @@ _eventLoopDelay.enable(); let _eldLastLog = 0; let _lastCpu = process.cpuUsage(); let _lastCpuT = Date.now(); +let _gcCount = 0; +let _gcTotalMs = 0; +let _gcMaxMs = 0; +try { + const _gcObserver = new PerformanceObserver((list) => { + for (const entry of list.getEntries()) { + _gcCount++; + _gcTotalMs += entry.duration; + if (entry.duration > _gcMaxMs) _gcMaxMs = entry.duration; + } + }); + _gcObserver.observe({ entryTypes: ['gc'] }); +} catch {} let mainWindow; let _lastImportPath = null; @@ -212,11 +225,20 @@ function _maybeLogEventLoopDelay(activeJobs) { const d = process.cpuUsage(_lastCpu); const wall = now - _lastCpuT; const pct = wall > 0 ? Math.round((d.user + d.system) / 1000 / wall * 100) : 0; - const rss = Math.round(process.memoryUsage().rss / 1048576); - cpuStr = ` cpu=${pct}%core rss=${rss}MB`; + const mem = process.memoryUsage(); + const rss = Math.round(mem.rss / 1048576); + const heap = Math.round(mem.heapUsed / 1048576); + const ext = Math.round(mem.external / 1048576); + const ab = Math.round((mem.arrayBuffers || 0) / 1048576); + cpuStr = ` cpu=${pct}%core rss=${rss}MB heap=${heap}MB ext=${ext}MB ab=${ab}MB`; _lastCpu = process.cpuUsage(); _lastCpuT = now; } catch {} + let gcStr = ''; + try { + gcStr = ` gc=${_gcCount} gcTotal=${_gcTotalMs.toFixed(0)}ms gcMax=${_gcMaxMs.toFixed(0)}ms`; + _gcCount = 0; _gcTotalMs = 0; _gcMaxMs = 0; + } catch {} let upStr = ''; try { if (uploadManager && typeof uploadManager.getDiagnostics === 'function') { @@ -225,7 +247,7 @@ function _maybeLogEventLoopDelay(activeJobs) { upStr = ` active-by-hoster={${byHoster}} transient-errs=${d.transientErrors || 0} pending=${d.pending || 0}`; } } catch {} - logInfo(`eventloop-delay active=${activeJobs} mean=${mean}ms p99=${p99}ms max=${max}ms stddev=${stddev}ms threadpool=${process.env.UV_THREADPOOL_SIZE}${cpuStr}${resStr}${upStr}`); + logInfo(`eventloop-delay active=${activeJobs} mean=${mean}ms p99=${p99}ms max=${max}ms stddev=${stddev}ms threadpool=${process.env.UV_THREADPOOL_SIZE}${cpuStr}${gcStr}${resStr}${upStr}`); _eventLoopDelay.reset(); } catch {} } diff --git a/package.json b/package.json index 7d0e75d..c092181 100644 --- a/package.json +++ b/package.json @@ -1,6 +1,6 @@ { "name": "multi-hoster-uploader", - "version": "3.3.96", + "version": "3.3.97", "description": "Upload files to doodstream, voe, vidmoly, byse simultaneously", "main": "main.js", "scripts": { diff --git a/tasks/lessons.md b/tasks/lessons.md index 5a1125f..bdb77ed 100644 --- a/tasks/lessons.md +++ b/tasks/lessons.md @@ -1,5 +1,20 @@ # Lessons +## 2026-06-21 — Histogram-Korrelation beweist KEINE Kausalrichtung; rss-Mathe als Sanity-Check +**Symptom:** ELD-Spikes korrelierten exakt mit hohem `FSReqCallback` (File-Reads in flight) → ich wollte +sofort ein Read-Concurrency-Semaphore über 5 Dateien bauen. +**Root cause / Korrektur (Advisor):** (1) Korrelation ≠ Kausalität: hohe in-flight-Reads können auch SYMPTOM +sein — ein aus ANDEREM Grund blockierter Loop drained die Read-Completions nicht, also stapeln sie sich im +Snapshot. (2) rss-Mathe widerlegte meine „Read-Buffer ballonen den Speicher"-These: 70 Streams × 256KB ≈ +18MB, aber rss schwang ~300MB → das ist Heap-/Objekt-Churn (GC), nicht die Read-Buffer. +**Regel:** Bevor ich auf Basis einer Histogramm-Korrelation einen Multi-File-Refactor baue: (a) Kausalrichtung +mit einem BILLIGEN reversiblen 1-Zeilen-Hebel testen (hier UV_THREADPOOL_SIZE 64→8), (b) die Größenordnung +gegenrechnen (passt die vermutete Quelle zahlenmäßig zur beobachteten Wirkung?), (c) den fehlenden Co-Faktor +(GC) erst MESSEN, bevor ich ihn aus- oder einschließe. Ein Build kann gleichzeitig Kandidaten-Fix UND +Diskriminator sein. +**Wie anwenden:** Bei „X korreliert mit Y, also fixe X": erst fragen „könnte Y → X statt X → Y?" und „passt +die Magnitude?". Wenn nein/unklar → erst der billige reversible Knopf + Messung, dann der teure Refactor. + ## 2026-04-21 — DOM-Doppelrender bei Bulk-State-Changes **Symptom:** User klickt auf "Erneut versuchen" mit 500+ Jobs → App hängt sekundenlang. **Root cause:** `retrySelectedJobs()` ruft `renderQueueTable + updateQueueActionButtons + updateStatusBar` auf, `startSelectedUpload()` ruft direkt danach genau dieselben Funktionen nochmal auf. diff --git a/tasks/todo.md b/tasks/todo.md index cbbea97..a492c75 100644 --- a/tasks/todo.md +++ b/tasks/todo.md @@ -1,3 +1,32 @@ +# v3.3.97 — DECISIVE ELD finding: file-read phase-flip + threadpool 64→8 + GC instrument + +The v3.3.96 `eventloop-delay` logs gave the decisive signal. At CONSTANT active-count, the system flips +between two regimes: +- HEALTHY (ELD ~11ms, rss 268–308MB): `SimpleWriteWrap ≈ active`, `FSReqCallback ≈ 0–1` (write/network-bound) +- BLOCKED (ELD 49–217ms, rss 540–610MB): `FSReqCallback ≈ active` (62–71 file reads in flight), `SimpleWriteWrap ≈ 0–4` +ELD spike + rss balloon both track `FSReqCallback` → file-read path through the libuv threadpool, NOT crypto, +NOT renderer, NOT GC-alone. All 5 uploaders read identically (256KB createReadStream); byse/dood/voe run +through the GENERIC uploadFile in hosters.js (no dedicated module). + +Advisor caveats baked into the build (do NOT skip on re-measure): +1. Causation UNPROVEN — high FSReqCallback could be a SYMPTOM (blocked loop can't drain read-completions). +2. rss math kills "read buffers ballooned": 70×256KB ≈ 18MB, but rss swings ~300MB → heap/object churn (GC). +3. Cheapest discriminator already wired: `UV_THREADPOOL_SIZE` 64→8 (1 line, reversible, NOT an upload cap; + 8×256KB reads ≈ 100MB/s ≫ 41MB/s aggregate). Suspect tp=64 made it WORSE (removed read-serialization). + +Shipped v3.3.97 = candidate-fix + discriminator in one build: +- main.js:1 `UV_THREADPOOL_SIZE` 64→8. +- ELD line now also logs `heap=`(heapUsed) `ext=`(external) `ab=`(arrayBuffers) `gc=`/`gcTotal=`/`gcMax=`ms + (PerformanceObserver entryTypes:['gc'], reset per window). + +DECISION RULE for the next user log: +- ELD drops with tp=8 → read over-parallelism confirmed → keep 8 or productionize a DEDICATED read-semaphore. +- ELD high + gcTotal/gcMax align with spikes → heap churn → hunt the allocator (semaphore would be wasted). +- ELD high + gc flat → causation reversed (symptom) → pivot. +WAIT for the next `eventloop-delay` log before any read-path refactor. NO upload cap (user rejected it). + +--- + # v3.3.94 — comprehensive measurement build (user: "mach alles messen was man messen kann") Localization so far (each step EMPIRICAL, not by elimination — advisor caught the elimination-leap):