perf(subsUnion): unión en árbol, menos vértices, timeout y cota de memoria

Cuatro endurecimientos salidos del banco de carga (bench/union-bench.js), cada
uno con su número:

1. Unión en ÁRBOL en vez de en cadena. La cadena unía siempre contra un polígono
   acumulado que no paraba de crecer. Con 1.000 suscripciones repartidas por el
   mundo —el peor caso, círculos que no se solapan— eran 238 s; en árbol son
   3,6 s, con un documento idéntico. Con datos realistas (España) 10.000
   suscripciones bajan de 39,3 s a 23,5 s. test/server/calcUnionAsync.test.js
   comprueba la equivalencia contra una referencia calculada en cadena.

2. 64 vértices por círculo en vez de 144, configurable con
   `private.unionCircleSteps`. Con 10.000 suscripciones: 23,5 s → 10,0 s y el
   pico de RSS de 777 MB → 421 MB. En pantalla un círculo de 64 lados sigue
   siendo un círculo, y la capa de zonas es un adorno difuso; el host de
   despliegue tiene 5,9 GB para todo el stack.

3. Timeout del worker (10 min por defecto, `private.unionWorkerTimeoutMs`). Un
   worker que no contestaba dejaba la promesa colgada y con ella la cola entera:
   `busy` se quedaba en true y no se volvía a calcular ninguna unión hasta
   reiniciar, sin que nada fallase. Se reintenta una vez ante un error real,
   nunca ante un timeout.

4. Cota de heap del worker (1 GB, `private.unionWorkerMaxHeapMb`), para que un
   caso patológico muera con ERR_WORKER_OUT_OF_MEMORY —que esta capa convierte
   en un rechazo, dejando la unión anterior intacta— en vez de que el kernel se
   lleve por delante el proceso de Meteor.

Además unionTelemetry.js manda a GlitchTip las uniones que pasan de un minuto y
las que hay que degradar por tamaño, y registra duración/tamaño de cada una. El
único aviso de que la unión iba mal era, hasta ahora, que el mapa se quedaba
viejo.

Smoke REST byte-idéntico. 90 tests en verde.

imports/startup/server/calcUnionAsync.js

@@ -1,5 +1,6 @@
 import path from 'path';
 import { Worker } from 'worker_threads';
+import { Meteor } from 'meteor/meteor';
 
 const WORKER_PATH = path.resolve(process.cwd(), 'assets/app/workers/unionWorker.js');
 
@@ -19,27 +20,80 @@ const turfPaths = {
   truncate: path.join(NPM_MODULES, '@turf/truncate')
 };
 
+// A worker that never answers used to hang the promise forever, and with it the
+// queue in subsUnionLogic: `busy` stays true and no union is ever computed again
+// until the process restarts — silently, because nothing throws. Measured on
+// this hardware (bench/union-bench.js), a full recreate of 10.000 subscriptions
+// takes ~40 s, so ten minutes is a very wide margin over anything healthy while
+// still being a bound.
+const DEFAULT_TIMEOUT_MS = 10 * 60 * 1000;
+export const timeoutMs = () => (
+  (Meteor.settings.private && Meteor.settings.private.unionWorkerTimeoutMs) || DEFAULT_TIMEOUT_MS
+);
+
+
+class UnionWorkerTimeout extends Error {
+  constructor(ms) {
+    super(`union worker did not answer in ${ms} ms`);
+    this.name = 'UnionWorkerTimeout';
+    this.isTimeout = true;
+  }
+}
+
+// Cota de heap del worker. No es para que quepa: es para que un caso patológico
+// (miles de suscripciones que no se solapan) muera con ERR_WORKER_OUT_OF_MEMORY
+// —que esta capa convierte en un rechazo y deja la unión anterior intacta— en
+// vez de que el kernel se lleve por delante el proceso entero de Meteor. Medido:
+// 10.000 suscripciones con 64 vértices por círculo son ~421 MB de RSS de todo el
+// proceso, así que 1 GB de heap para el worker es holgado.
+const DEFAULT_MAX_HEAP_MB = 1024;
+const settingsOf = name => (Meteor.settings.private || {})[name];
+
+const runOnce = (subs, baseUnion, ms) => new Promise((resolve, reject) => {
+  const worker = new Worker(WORKER_PATH, {
+    workerData: { subs, baseUnion, turfPaths, steps: settingsOf('unionCircleSteps') },
+    resourceLimits: { maxOldGenerationSizeMb: settingsOf('unionWorkerMaxHeapMb') || DEFAULT_MAX_HEAP_MB }
+  });
+  let settled = false;
+  const finish = (fn, arg) => {
+    if (settled) return;
+    settled = true;
+    clearTimeout(timer);
+    // terminate() is what actually stops the thread burning a core; without it a
+    // timed-out union would keep computing forever next to its replacement.
+    worker.terminate();
+    fn(arg);
+  };
+  const timer = setTimeout(() => finish(reject, new UnionWorkerTimeout(ms)), ms);
+
+  worker.once('message', (msg) => {
+    if (msg.error) finish(reject, new Error(msg.error));
+    else finish(resolve, msg.union);
+  });
+  worker.once('error', err => finish(reject, err));
+});
+
 /**
  * Circle-union of already-validated, already-decorated subscriptions, run in a
  * worker thread so the main event loop (DDP/HTTP) stays free regardless of
  * how long any single turf.union call takes. subs must be an array of plain
  * { location: { lat, lon }, distance } objects. If baseUnion is given, subs
  * are merged into it instead of a union computed from scratch.
+ *
+ * Fails after a timeout, and retries once on a genuine error — a failure to
+ * spawn the thread, or a crash, is usually transient. A TIMEOUT is not retried:
+ * whatever made it take longer than the bound will still be there, and a second
+ * attempt only doubles the time the union stays stale.
  */
-const calcUnionAsync = (subs, baseUnion = null) => new Promise((resolve, reject) => {
-  const worker = new Worker(WORKER_PATH, { workerData: { subs, baseUnion, turfPaths } });
-  worker.once('message', (msg) => {
-    worker.terminate();
-    if (msg.error) {
-      reject(new Error(msg.error));
-    } else {
-      resolve(msg.union);
-    }
-  });
-  worker.once('error', (err) => {
-    worker.terminate();
-    reject(err);
-  });
-});
+const calcUnionAsync = async (subs, baseUnion = null) => {
+  const ms = timeoutMs();
+  try {
+    return await runOnce(subs, baseUnion, ms);
+  } catch (e) {
+    if (e.isTimeout) throw e;
+    console.warn('union worker failed, retrying once', e.message);
+    return runOnce(subs, baseUnion, ms);
+  }
+};
 
 export default calcUnionAsync;

imports/startup/server/subsUnion.js

@@ -9,6 +9,7 @@ import SiteSettings from '/imports/api/SiteSettings/SiteSettings';
 import calcUnionAsync from '/imports/startup/server/calcUnionAsync';
 import unionBounds from '/imports/startup/server/unionBounds';
 import createSubsUnion from '/imports/startup/server/subsUnionLogic';
+import unionTelemetry from '/imports/startup/server/unionTelemetry';
 import { isMailServerMaster } from '/imports/startup/server/email';
 
 Meteor.startup(async () => {
@@ -21,7 +22,8 @@ Meteor.startup(async () => {
     calcUnion: calcUnionAsync,
     SiteSettings,
     Subscriptions,
-    boundsOf: unionBounds
+    boundsOf: unionBounds,
+    telemetry: unionTelemetry
   });
 
   if (await subsUnion.isUnionOutdated()) {

imports/startup/server/subsUnionLogic.js

@@ -32,6 +32,8 @@ export const isValidSub = (osub, log = console) => {
  * @param {number}   [deps.maxUnionBytes]
  * @param {number}   [deps.perlinSeed] fixed seed makes the public "noise" reproducible in tests
  */
+const noTelemetry = { computed: () => {}, failed: () => {} };
+
 const createSubsUnion = ({
   calcUnion,
   SiteSettings,
@@ -40,7 +42,8 @@ const createSubsUnion = ({
   maxUnionBytes = MAX_UNION_BYTES,
   perlinSeed = Math.random(),
   debug = true,
-  log = console
+  log = console,
+  telemetry = noTelemetry
 }) => {
   Perlin.seed(perlinSeed);
 
@@ -112,18 +115,28 @@ const createSubsUnion = ({
     await SiteSettings.upsertAsync({ name: `subs-${publicl}-union-bounds` }, boundsSet, { multi: false });
     await SiteSettings.upsertAsync({ name: 'subs-union-count' }, sizeSet, { multi: false });
     if (debug) log.log(`${Publicl} subscription union calculated`);
-    return { degraded };
+    return { degraded, bytes: Buffer.byteLength(json, 'utf8') };
   };
 
   const recomputeOne = async (isPublic) => {
     const subscribers = await Subscriptions.find().fetchAsync();
     const decorated = subscribers.filter(s => isValidSub(s, log)).map(decoratorFor(isPublic));
 
+    const started = Date.now();
     try {
       const union = await calcUnion(decorated);
-      await storeUnion(isPublic, union, subscribers.length);
+      const { degraded, bytes } = await storeUnion(isPublic, union, subscribers.length);
+      telemetry.computed({
+        kind: 'recreate',
+        isPublic,
+        subs: decorated.length,
+        ms: Date.now() - started,
+        bytes,
+        degraded: degraded ? degraded.steps.join(' -> ') : null
+      });
     } catch (e) {
       log.error('subsUnion worker failed, union left unchanged', e);
+      telemetry.failed(e, { kind: 'recreate', isPublic, subs: decorated.length, ms: Date.now() - started });
     }
   };
 
@@ -172,13 +185,23 @@ const createSubsUnion = ({
       const current = await SiteSettings.findOneAsync({ name: `subs-${publicl}-union` });
       const baseUnion = current && current.value ? JSON.parse(current.value) : null;
 
+      const started = Date.now();
       try {
         // eslint-disable-next-line no-await-in-loop
         const union = await calcUnion([decorated], baseUnion);
         // eslint-disable-next-line no-await-in-loop
-        await storeUnion(isPublic, union, countSubs);
+        const { degraded, bytes } = await storeUnion(isPublic, union, countSubs);
+        telemetry.computed({
+          kind: 'incrementalAdd',
+          isPublic,
+          subs: countSubs,
+          ms: Date.now() - started,
+          bytes,
+          degraded: degraded ? degraded.steps.join(' -> ') : null
+        });
       } catch (e) {
         log.error('subsUnion incremental worker failed, falling back to a full recreate', e);
+        telemetry.failed(e, { kind: 'incrementalAdd', isPublic, subs: countSubs, ms: Date.now() - started });
         recomputePending = true;
         return;
       }

imports/startup/server/unionTelemetry.js

@@ -0,0 +1,51 @@
+/* eslint-disable import/no-absolute-path */
+
+// Telemetría de la unión de suscripciones (fase 12).
+//
+// Hasta ahora la única señal de que la unión iba mal era que el mapa se quedaba
+// viejo: los fallos del worker se registraban con console.error y ahí morían. Lo
+// que se manda a GlitchTip es deliberadamente poco: un aviso cuando una unión
+// tarda más de lo que el banco de carga considera sano, otro cuando hay que
+// degradar la geometría por tamaño, y los fallos. Las uniones normales solo
+// dejan una línea de log.
+
+import * as Sentry from '@sentry/node';
+import { Meteor } from 'meteor/meteor';
+import ravenLogger from '/imports/startup/server/ravenLogger';
+
+// Medido en bench/union-bench.js: 10.000 suscripciones repartidas por España son
+// ~40 s. Pasar del minuto significa o mucha más gente, o una distribución que no
+// se solapa (el caso caro), o algo que se ha torcido. En cualquiera de los tres
+// casos queremos enterarnos.
+const DEFAULT_SLOW_MS = 60 * 1000;
+
+const slowMs = () => (
+  (Meteor.settings.private && Meteor.settings.private.unionSlowMs) || DEFAULT_SLOW_MS
+);
+
+const unionTelemetry = {
+  computed({ kind, isPublic, subs, ms, bytes, degraded }) {
+    const scope = isPublic ? 'public' : 'private';
+    const line = `subsUnion ${kind} ${scope}: ${subs} subs, ${Math.round(ms)} ms, ${bytes} bytes${degraded ? ` (degradada: ${degraded})` : ''}`;
+    console.log(line);
+
+    if (ms > slowMs()) {
+      Sentry.captureMessage(`subsUnion lenta: ${Math.round(ms / 1000)} s con ${subs} suscripciones`, {
+        level: 'warning',
+        extra: { kind, scope, subs, ms, bytes }
+      });
+    }
+    if (degraded) {
+      Sentry.captureMessage(`subsUnion degradada por tamaño: ${degraded}`, {
+        level: 'warning',
+        extra: { kind, scope, subs, ms, bytes, degraded }
+      });
+    }
+  },
+
+  failed(error, context) {
+    ravenLogger.log(error, context);
+  }
+};
+
+export default unionTelemetry;