Summary: - Excel exports were awfully memory-inefficient, causing occasional docWorker crashes. The fix is to use the "streaming writer" option of ExcelJS https://github.com/exceljs/exceljs#streaming-xlsx-writercontents. (Empirically on one example, max memory went down from 3G to 100M) - It's also CPU intensive and synchronous, and can block node for tens of seconds. The fix is to use a worker-thread. This diff uses "piscina" library for a pool of threads. - Additionally, adds ProcessMonitor that logs memory and cpu usage, particularly when those change significantly. - Also introduces request cancellation, so that a long download cancelled by the user will cancel the work being done in the worker thread. Test Plan: Updated previous export tests; memory and CPU performance tested manually by watching output of ProcessMonitor. Difference visible in these log excerpts: Before (total time to serve request 22 sec): ``` Telemetry processMonitor heapUsedMB=2187, heapTotalMB=2234, cpuAverage=1.13, intervalMs=17911 Telemetry processMonitor heapUsedMB=2188, heapTotalMB=2234, cpuAverage=0.66, intervalMs=5005 Telemetry processMonitor heapUsedMB=2188, heapTotalMB=2234, cpuAverage=0, intervalMs=5005 Telemetry processMonitor heapUsedMB=71, heapTotalMB=75, cpuAverage=0.13, intervalMs=5002 ``` After (total time to server request 18 sec): ``` Telemetry processMonitor heapUsedMB=109, heapTotalMB=144, cpuAverage=0.5, intervalMs=5001 Telemetry processMonitor heapUsedMB=109, heapTotalMB=144, cpuAverage=1.39, intervalMs=5002 Telemetry processMonitor heapUsedMB=94, heapTotalMB=131, cpuAverage=1.13, intervalMs=5000 Telemetry processMonitor heapUsedMB=94, heapTotalMB=131, cpuAverage=1.35, intervalMs=5001 ``` Note in "Before" that heapTotalMB goes up to 2GB in the first case, and "intervalMs" of 17 seconds indicates that node was unresponsive for that long. In the second case, heapTotalMB stays low, and the main thread remains responsive the whole time. Reviewers: jarek Reviewed By: jarek Differential Revision: https://phab.getgrist.com/D3906pull/526/head
Dmitry S
12 months ago
parent
6b338256e0
commit
d191859be7
@ -0,0 +1,79 @@
|
||||
import { TelemetryManager } from 'app/server/lib/TelemetryManager';
|
||||
|
||||
const MONITOR_PERIOD_MS = 5_000; // take a look at memory usage this often
|
||||
const MEMORY_DELTA_FRACTION = 0.1; // fraction by which usage should change to get reported
|
||||
const CPU_DELTA_FRACTION = 0.1; // by how much cpu usage should change to get reported
|
||||
const MONITOR_LOG_PERIOD_MS = 600_000; // log usage at least this often
|
||||
|
||||
let _timer: NodeJS.Timeout|undefined;
|
||||
let _lastTickTime: number = Date.now();
|
||||
let _lastReportTime: number = 0;
|
||||
let _lastReportedHeapUsed: number = 0;
|
||||
let _lastCpuUsage: NodeJS.CpuUsage = {system: 0, user: 0};
|
||||
let _lastReportedCpuAverage: number = 0;
|
||||
|
||||
/**
|
||||
* Monitor process memory (heap) and CPU usage, reporting as telemetry on an interval, and more
|
||||
* often when usage ticks up or down by a big enough delta.
|
||||
*
|
||||
* There is a single global process monitor, reporting to the telemetryManager passed into the
|
||||
* first call to start().
|
||||
*
|
||||
* Returns a function that stops the monitor, or null if there was already a process monitor
|
||||
* running, and no new one was started.
|
||||
*
|
||||
* Reports:
|
||||
* - heapUsedMB: Size of JS heap in use, in MiB.
|
||||
* - heapTotalMB: Total heap size, in MiB, allocated for JS by v8.
|
||||
* - cpuAverage: Fraction between 0 and 1, cpu usage over the last MONITOR_PERIOD_MS. Note it
|
||||
* includes usage from all threads, so may exceed 1.
|
||||
* - intervalMs: Interval (in milliseconds) over which cpuAverage is reported. Being much
|
||||
* higher than MONITOR_PERIOD_MS is a sign of being CPU bound for that long.
|
||||
*/
|
||||
export function start(telemetryManager: TelemetryManager): (() => void) | undefined {
|
||||
if (!_timer) {
|
||||
// Initialize variables needed for accurate first-tick measurement.
|
||||
_lastTickTime = Date.now();
|
||||
_lastCpuUsage = process.cpuUsage();
|
||||
_timer = setInterval(() => monitor(telemetryManager), MONITOR_PERIOD_MS);
|
||||
|
||||
return function stop() {
|
||||
clearInterval(_timer);
|
||||
_timer = undefined;
|
||||
};
|
||||
}
|
||||
}
|
||||
|
||||
function monitor(telemetryManager: TelemetryManager) {
|
||||
const memoryUsage = process.memoryUsage();
|
||||
const heapUsed = memoryUsage.heapUsed;
|
||||
const cpuUsage = process.cpuUsage();
|
||||
const now = Date.now();
|
||||
|
||||
const intervalMs = now - _lastTickTime;
|
||||
// Note that cpuUsage info is in microseconds, while intervalMs is milliseconds.
|
||||
const cpuAverage = (cpuUsage.system + cpuUsage.user - _lastCpuUsage.system - _lastCpuUsage.user)
|
||||
/ 1000 / intervalMs;
|
||||
_lastCpuUsage = cpuUsage;
|
||||
_lastTickTime = now;
|
||||
|
||||
// Report usage when:
|
||||
// (a) enough time has passed (MONITOR_LOG_PERIOD_MS)
|
||||
// (b) memory usage ticked up or down enough since the last report
|
||||
// (c) average cpu usage ticked up or down enough since the last report
|
||||
if (
|
||||
now > _lastReportTime + MONITOR_LOG_PERIOD_MS ||
|
||||
Math.abs(heapUsed - _lastReportedHeapUsed) > _lastReportedHeapUsed * MEMORY_DELTA_FRACTION ||
|
||||
Math.abs(cpuAverage - _lastReportedCpuAverage) > CPU_DELTA_FRACTION
|
||||
) {
|
||||
telemetryManager.logEvent('processMonitor', {
|
||||
heapUsedMB: Math.round(memoryUsage.heapUsed/1024/1024),
|
||||
heapTotalMB: Math.round(memoryUsage.heapTotal/1024/1024),
|
||||
cpuAverage: Math.round(cpuAverage * 100) / 100,
|
||||
intervalMs,
|
||||
});
|
||||
_lastReportedHeapUsed = heapUsed;
|
||||
_lastReportedCpuAverage = cpuAverage;
|
||||
_lastReportTime = now;
|
||||
}
|
||||
}
|
||||
@ -0,0 +1,72 @@
|
||||
import {PassThrough} from 'stream';
|
||||
import {ActiveDocSource} from 'app/server/lib/Export';
|
||||
import * as ExportXLSX from 'app/server/lib/ExportXLSX';
|
||||
import * as log from 'app/server/lib/log';
|
||||
import {Rpc} from 'grain-rpc';
|
||||
import {Stream} from 'stream';
|
||||
import {MessagePort, threadId} from 'worker_threads';
|
||||
|
||||
export const makeXLSX = handleExport(ExportXLSX.makeXLSX);
|
||||
export const makeXLSXFromTable = handleExport(ExportXLSX.makeXLSXFromTable);
|
||||
export const makeXLSXFromViewSection = handleExport(ExportXLSX.makeXLSXFromViewSection);
|
||||
|
||||
function handleExport<T extends any[]>(
|
||||
make: (a: ActiveDocSource, testDates: boolean, output: Stream, ...args: T) => Promise<void>
|
||||
) {
|
||||
return async function({port, testDates, args}: {port: MessagePort, testDates: boolean, args: T}) {
|
||||
try {
|
||||
const start = Date.now();
|
||||
log.debug("workerExporter %s %s: started", threadId, make.name);
|
||||
const rpc = new Rpc({
|
||||
sendMessage: async (m) => port.postMessage(m),
|
||||
logger: { info: m => {}, warn: m => log.warn(m) },
|
||||
});
|
||||
const activeDocSource = rpc.getStub<ActiveDocSource>("activeDocSource");
|
||||
port.on('message', (m) => rpc.receiveMessage(m));
|
||||
const outputStream = new PassThrough();
|
||||
bufferedPipe(outputStream, (chunk) => rpc.postMessage(chunk));
|
||||
await make(activeDocSource, testDates, outputStream, ...args);
|
||||
port.close();
|
||||
log.debug("workerExporter %s %s: done in %s ms", threadId, make.name, Date.now() - start);
|
||||
} catch (e) {
|
||||
log.debug("workerExporter %s %s: error %s", threadId, make.name, String(e));
|
||||
// When Error objects move across threads, they keep only the 'message' property. We can
|
||||
// keep other properties (like 'status') if we throw a plain object instead. (Didn't find a
|
||||
// good reference on this, https://github.com/nodejs/node/issues/35506 is vaguely related.)
|
||||
throw {message: e.message, ...e};
|
||||
}
|
||||
};
|
||||
}
|
||||
|
||||
// ExcelJS's WorkbookWriter produces many tiny writes (even though they pass through zipping). To
|
||||
// reduce overhead and context switching, buffer them and pass on in chunks. (In practice, this
|
||||
// helps performance only slightly.)
|
||||
function bufferedPipe(stream: Stream, callback: (chunk: Buffer) => void, threshold = 64*1024) {
|
||||
let buffers: Buffer[] = [];
|
||||
let length = 0;
|
||||
let flushed = 0;
|
||||
|
||||
function flush() {
|
||||
if (length > 0) {
|
||||
const data = Buffer.concat(buffers);
|
||||
flushed += data.length;
|
||||
callback(data);
|
||||
buffers = [];
|
||||
length = 0;
|
||||
}
|
||||
}
|
||||
|
||||
stream.on('data', (chunk) => {
|
||||
// Whenever data is written to the stream, add it to the buffer.
|
||||
buffers.push(chunk);
|
||||
length += chunk.length;
|
||||
// If the buffer is large enough, post it to the callback. Also post the very first chunk:
|
||||
// since this becomes an HTTP response, a quick first chunk lets the browser prompt the user
|
||||
// more quickly about what to do with the download.
|
||||
if (length >= threshold || flushed === 0) {
|
||||
flush();
|
||||
}
|
||||
});
|
||||
|
||||
stream.on('end', flush);
|
||||
}
|
||||
Binary file not shown.
Binary file not shown.
Binary file not shown.
Binary file not shown.
Binary file not shown.
Binary file not shown.
Loading…
Reference in new issue