[object Object]

← back to New Import Viewer

9790: fix /api/stats death-spiral — statement_timeout guard + non-blocking warmer

0d81ad39dd08fb6cfb6484f92da4560dfa4e9de8 · 2026-06-11 10:39:22 -0700 · SteveStudio2

Root cause: netnew count's NOT EXISTS vs dw_sku_registry had no functional
index (upper(trim(mfr_sku))) → seq scan → 75s+/never. Every page-load + the
boot warmer fired it; runs piled up (13 stacked 18-43min), saturating PG into
a death spiral that froze the whole single-threaded server ('and loading').

Fix (this commit): PGOPTIONS statement_timeout=30000 on q()+qAsync so no query
can ever run away/pile up again; background stats warmer + STATS_CACHE serve
/api/stats instantly.
DB side (not in git): CREATE INDEX idx_registry_mfr_upper_trim ON
dw_sku_registry (upper(trim(mfr_sku))) — drops the stats query to ~1.6s.

Files touched

Diff

commit 0d81ad39dd08fb6cfb6484f92da4560dfa4e9de8
Author: SteveStudio2 <stevestudio2@SteveStacStudio.lan>
Date:   Thu Jun 11 10:39:22 2026 -0700

    9790: fix /api/stats death-spiral — statement_timeout guard + non-blocking warmer
    
    Root cause: netnew count's NOT EXISTS vs dw_sku_registry had no functional
    index (upper(trim(mfr_sku))) → seq scan → 75s+/never. Every page-load + the
    boot warmer fired it; runs piled up (13 stacked 18-43min), saturating PG into
    a death spiral that froze the whole single-threaded server ('and loading').
    
    Fix (this commit): PGOPTIONS statement_timeout=30000 on q()+qAsync so no query
    can ever run away/pile up again; background stats warmer + STATS_CACHE serve
    /api/stats instantly.
    DB side (not in git): CREATE INDEX idx_registry_mfr_upper_trim ON
    dw_sku_registry (upper(trim(mfr_sku))) — drops the stats query to ~1.6s.
---
 server.js | 115 +++++++++++++++++++++++++++++++++++++++++++++++++++-----------
 1 file changed, 95 insertions(+), 20 deletions(-)

diff --git a/server.js b/server.js
index 266cae1..1d013d2 100644
--- a/server.js
+++ b/server.js
@@ -8,7 +8,7 @@
 const http = require('http');
 const fs = require('fs');
 const path = require('path');
-const { spawnSync } = require('child_process');
+const { spawnSync, spawn } = require('child_process');
 
 const PORT = process.env.PORT || 9790;
 const PSQL = process.env.PSQL || '/opt/homebrew/opt/postgresql@14/bin/psql';
@@ -129,12 +129,87 @@ const STATUS_FILTERS = {
   noimage:     "(vc.image_url IS NULL OR vc.image_url='')",
 };
 
+// PGOPTIONS pins a server-side statement_timeout on EVERY query this process
+// fires. Without it, one pathological query (e.g. an unindexed netnew NOT EXISTS)
+// runs for tens of minutes; the warmer + every page-load pile more on top, and the
+// concurrent load saturates Postgres into a death spiral (the 2026-06-11 9790
+// meltdown — 13 stats queries stacked 18-43 min each). 30s ceiling = fail fast,
+// never pile up. (The stats query itself now runs ~1.6s once idx_registry_mfr_upper_trim exists.)
+const PG_ENV = { ...process.env, PGOPTIONS: '-c statement_timeout=30000' };
+
 function q(sql) {
   const r = spawnSync(PSQL, ['-U', PGUSER, '-d', PGDB, '-tA', '-F', US, '-R', RS, '-c', sql],
-    { encoding: 'utf8', timeout: 60000, maxBuffer: 1 << 28 });
+    { encoding: 'utf8', timeout: 60000, maxBuffer: 1 << 28, env: PG_ENV });
   if (r.status !== 0) throw new Error((r.stderr || 'psql failed').slice(0, 400));
   return (r.stdout || '').replace(/\n+$/, '').split(RS).filter(l => l.length).map(l => l.split(US));
 }
+
+// Non-blocking async twin of q() — spawns psql (SAME args) and resolves to the
+// same parsed `rows` shape WITHOUT freezing the single-threaded event loop. Used
+// by the background stats warmer so /api/stats never blocks every other request.
+function qAsync(sql) {
+  return new Promise((resolve, reject) => {
+    const child = spawn(PSQL, ['-U', PGUSER, '-d', PGDB, '-tA', '-F', US, '-R', RS, '-c', sql],
+      { encoding: 'utf8', env: PG_ENV });
+    let out = '', err = '';
+    child.stdout.on('data', d => (out += d));
+    child.stderr.on('data', d => (err += d));
+    child.on('error', e => reject(e));
+    child.on('close', code => {
+      if (code !== 0) return reject(new Error((err || 'psql failed').slice(0, 400)));
+      resolve(out.replace(/\n+$/, '').split(RS).filter(l => l.length).map(l => l.split(US)));
+    });
+  });
+}
+
+// The EXACT whole-catalog status-breakdown query /api/stats serves. Heavy (~15s
+// cold over ~200k vendor_catalog rows joined to shopify_products), so it's run by
+// the background warmer into STATS_CACHE rather than inline on the request path.
+const STATS_SQL = `SELECT
+    count(*) FILTER (WHERE ${NEW_PRED}),
+    count(*) FILTER (WHERE vc.shopify_product_id IS NOT NULL OR vc.on_shopify IS TRUE),
+    count(*) FILTER (WHERE upper(sp.status)='ACTIVE'),
+    count(*) FILTER (WHERE upper(sp.status)='DRAFT'),
+    count(*) FILTER (WHERE upper(sp.status)='ARCHIVED'),
+    count(*),
+    to_char(max(vc.last_scraped_at),'YYYY-MM-DD HH24:MI'),
+    count(*) FILTER (WHERE vc.image_url IS NULL OR vc.image_url=''),
+    count(*) FILTER (WHERE ${NETNEW_PRED})
+  FROM vendor_catalog vc ${SP_JOIN}`;
+
+// Map one STATS_SQL result row to the {counts, newestCrawl} shape /api/stats emits.
+function rowToCounts(r) {
+  r = r || [];
+  return {
+    counts: {
+      netnew: +r[8] || 0, new: +r[0] || 0, onshopify: +r[1] || 0, published: +r[2] || 0,
+      unpublished: +r[3] || 0, archived: +r[4] || 0, all: +r[5] || 0,
+      noimage: +r[7] || 0,
+      // how many "new" rows are actually already on Shopify (the dup overlap)
+      newButOnShopify: (+r[0] || 0) - (+r[8] || 0),
+    },
+    newestCrawl: r[6] || null,
+  };
+}
+
+// Background stats cache + warmer. STATS_CACHE holds the last computed snapshot;
+// refreshStats() recomputes it off the event-loop critical path (via qAsync) and
+// keeps the prior cache on error. statsRefreshing guards against piling up
+// overlapping warmers while one is in flight.
+let STATS_CACHE = null;
+let statsRefreshing = false;
+async function refreshStats() {
+  if (statsRefreshing) return;
+  statsRefreshing = true;
+  try {
+    const rows = await qAsync(STATS_SQL);
+    STATS_CACHE = { ...rowToCounts(rows[0]), computedAt: Date.now() };
+  } catch (e) {
+    console.error('[new-import-viewer] stats refresh failed:', e && e.message || e);
+  } finally {
+    statsRefreshing = false;
+  }
+}
 const esc = (s) => String(s == null ? '' : s).replace(/'/g, "''");
 const SORTS = {
   newest:    'vc.last_scraped_at DESC NULLS LAST, vc.id DESC',
@@ -302,18 +377,18 @@ const server = http.createServer((req, res) => {
     if (u.pathname === '/img') { serveImg(u.searchParams.get('u') || '', res); return; }
     if (u.pathname === '/api/stats') {
       // Whole-catalog status breakdown for the header pills (vendor/term ignored here).
-      const r = q(`SELECT
-          count(*) FILTER (WHERE ${NEW_PRED}),
-          count(*) FILTER (WHERE vc.shopify_product_id IS NOT NULL OR vc.on_shopify IS TRUE),
-          count(*) FILTER (WHERE upper(sp.status)='ACTIVE'),
-          count(*) FILTER (WHERE upper(sp.status)='DRAFT'),
-          count(*) FILTER (WHERE upper(sp.status)='ARCHIVED'),
-          count(*),
-          to_char(max(vc.last_scraped_at),'YYYY-MM-DD HH24:MI'),
-          count(*) FILTER (WHERE vc.image_url IS NULL OR vc.image_url=''),
-          count(*) FILTER (WHERE ${NETNEW_PRED})
-        FROM vendor_catalog vc ${SP_JOIN}`)[0] || [];
+      // Served from STATS_CACHE so this endpoint NEVER blocks the single-threaded
+      // server on the ~15s cold whole-catalog FILTER-count. First-ever hit (null
+      // cache) does ONE synchronous compute to return real numbers; thereafter a
+      // stale (>45s) cache triggers a non-blocking background refresh and we serve
+      // the prior snapshot instantly.
       const armable = LIVE && !!SHOP_TOKEN && LIVE_ACTIONS.size > 0;
+      if (!STATS_CACHE) {
+        const r = q(STATS_SQL)[0] || [];
+        STATS_CACHE = { ...rowToCounts(r), computedAt: Date.now() };
+      } else if (Date.now() - STATS_CACHE.computedAt > 45000) {
+        refreshStats(); // non-blocking — serve the current snapshot now, refresh in background
+      }
       return send(res, 200, JSON.stringify({
         // `armable` = the .env ceiling permits live writes at all. The actual arm
         // is a per-session UI toggle (defaults OFF each load) the client tracks and
@@ -322,12 +397,9 @@ const server = http.createServer((req, res) => {
         armable,
         liveActions: armable ? [...LIVE_ACTIONS] : [],
         store: SHOP_STORE,
-        counts: { netnew: +r[8] || 0, new: +r[0] || 0, onshopify: +r[1] || 0, published: +r[2] || 0,
-                  unpublished: +r[3] || 0, archived: +r[4] || 0, all: +r[5] || 0,
-                  noimage: +r[7] || 0,
-                  // how many "new" rows are actually already on Shopify (the dup overlap)
-                  newButOnShopify: (+r[0] || 0) - (+r[8] || 0) },
-        newestCrawl: r[6] || null,
+        counts: STATS_CACHE.counts,
+        newestCrawl: STATS_CACHE.newestCrawl,
+        cachedAt: STATS_CACHE.computedAt,
       }));
     }
     if (u.pathname === '/api/vendors') {
@@ -515,4 +587,7 @@ const server = http.createServer((req, res) => {
     return send(res, 500, JSON.stringify({ error: e.message }));
   }
 });
-server.listen(PORT, '127.0.0.1', () => console.log(`[new-import-viewer] http://127.0.0.1:${PORT}  · store=${SHOP_STORE} · live-actions=[${[...LIVE_ACTIONS].join(',') || 'none'}]${SHOP_TOKEN ? '' : ' (NO TOKEN)'}`));
+server.listen(PORT, '127.0.0.1', () => {
+  console.log(`[new-import-viewer] http://127.0.0.1:${PORT}  · store=${SHOP_STORE} · live-actions=[${[...LIVE_ACTIONS].join(',') || 'none'}]${SHOP_TOKEN ? '' : ' (NO TOKEN)'}`);
+  refreshStats(); // warm the stats cache on boot so the first /api/stats hit is fast
+});

← 1fb9644 new-import-viewer: enforce 3-source NEVER-DUPLICATE in net-n  ·  back to New Import Viewer  ·  9790: document load-bearing dw_sku_registry functional index 6e38f8b →