perf(uploads): threadpool 64→8 + GC/heap instrumentation (decisive high-concurrency lag build, v3.3.97)
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) <noreply@anthropic.com>
This commit is contained in:
parent
59dbd4b41c
commit
a5b835f76a
32
main.js
32
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 {}
|
||||
}
|
||||
|
||||
@ -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": {
|
||||
|
||||
@ -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.
|
||||
|
||||
@ -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):
|
||||
|
||||
Loading…
Reference in New Issue
Block a user