perf: reduce logging and optimize edge worker performance tests (#496)

# Reduce logging verbosity and improve performance test output

This PR makes several improvements to the edge worker's logging and test output:

1. Changes the default log level from `debug` to `warn` in the environment configuration
2. Adds a `debug` flag to worker payloads to make logging optional
3. Improves the test output in CI environments by:
   - Only showing progress bars in TTY environments
   - Adding percentage-based progress reporting for non-TTY environments
   - Including performance metrics (jobs/second) in test output
4. Reduces the performance test message count from 20,000 to 2,000 for faster test runs

These changes make the tests more efficient and provide better visibility into performance metrics while reducing unnecessary log output.

Author: jumski

pkgs/edge-worker/supabase/functions/.env

@@ -2,7 +2,7 @@ API_URL="http://127.0.0.1:50321"
 DB_URL="postgresql://postgres:postgres@127.0.0.1:50322/postgres"
 DB_POOL_URL="postgresql://postgres.pooler-dev:postgres@pooler:6543/postgres"
 DB_POOL_EXTERNAL_URL="postgresql://postgres.pooler-dev:postgres@localhost:50329/postgres"
-EDGE_WORKER_LOG_LEVEL=debug
+EDGE_WORKER_LOG_LEVEL=warn
 
 DB_PORT=50322
 DB_POOL_PORT=50329

pkgs/edge-worker/supabase/functions/cpu_intensive/index.ts

@@ -2,19 +2,27 @@ import { EdgeWorker } from '@pgflow/edge-worker';
 import { crypto } from 'jsr:@std/crypto';
 import { sql } from '../utils.ts';
 
-async function cpuIntensiveTask() {
+async function cpuIntensiveTask(payload: { debug?: boolean }) {
   let data = new TextEncoder().encode('burn');
   const timeId = `cpu_intensive_${Math.random()}`;
-  console.time(timeId);
+
+  if (payload.debug) {
+    console.time(timeId);
+  }
+
   for (let i = 0; i < 10000; i++) {
     data = new Uint8Array(await crypto.subtle.digest('SHA-256', data));
   }
-  console.timeEnd(timeId);
 
-  console.log(
-    '[cpu_intensive] last_val = ',
-    await sql`SELECT nextval('test_seq')`
-  );
+  if (payload.debug) {
+    console.timeEnd(timeId);
+    console.log(
+      '[cpu_intensive] last_val = ',
+      await sql`SELECT nextval('test_seq')`
+    );
+  } else {
+    await sql`SELECT nextval('test_seq')`;
+  }
 }
 
 EdgeWorker.start(cpuIntensiveTask, { queueName: 'cpu_intensive' });

pkgs/edge-worker/supabase/functions/max_concurrency/index.ts

@@ -1,13 +1,17 @@
 import { EdgeWorker } from '@pgflow/edge-worker';
 import { sleep, sql } from '../utils.ts';
 
-async function incrementSeq() {
+async function incrementSeq(payload: { debug?: boolean }) {
   await sleep(50);
 
-  console.log(
-    '[max_concurrency] last_val =',
-    await sql`SELECT nextval('test_seq')`
-  );
+  if (payload.debug) {
+    console.log(
+      '[max_concurrency] last_val =',
+      await sql`SELECT nextval('test_seq')`
+    );
+  } else {
+    await sql`SELECT nextval('test_seq')`;
+  }
 }
 
 EdgeWorker.start(incrementSeq, {

pkgs/edge-worker/tests/e2e/_helpers.ts

@@ -4,14 +4,16 @@ import ProgressBar from 'jsr:@deno-library/progress';
 import { dim } from 'https://deno.land/std@0.224.0/fmt/colors.ts';
 import { e2eConfig } from '../config.ts';
 
+const DEBUG = Deno.env.get('DEBUG') === '1' || Deno.env.get('VERBOSE') === '1';
+
 interface WaitForOptions {
   pollIntervalMs?: number;
   timeoutMs?: number;
   description?: string;
 }
 
 export function log(message: string, ...args: unknown[]) {
-  console.log(dim(` -> ${message}`), ...args);
+  if (DEBUG) console.log(dim(` -> ${message}`), ...args);
 }
 
 export async function waitFor<T>(
@@ -41,14 +43,15 @@ export async function waitFor<T>(
   }
 }
 
-export async function sendBatch(count: number, queueName: string) {
+export async function sendBatch(count: number, queueName: string, debug = false) {
   const sql = createSql();
+  const payload = JSON.stringify({ debug });
   try {
     return await sql`
       SELECT pgmq.send_batch(
         ${queueName},
         ARRAY(
-          SELECT '{}'::jsonb
+          SELECT ${payload}::jsonb
           FROM generate_series(1, ${count}::integer)
         )
       )`;
@@ -87,28 +90,41 @@ export async function waitForSeqToIncrementBy(
   options: WaitForSeqValueOptions = {}
 ): Promise<number> {
   const { seqName = 'test_seq' } = options;
+  const isTTY = Deno.stdout.isTerminal();
 
-  const perSecond = 0;
-
-  const progress = new ProgressBar({
-    title: `${seqName} (${perSecond}/s)`,
-    total: value,
-    width: 20,
-    display: dim(
-      ` -> incrementing "${seqName}": :completed/:total (:eta left) [:bar] :percent`
-    ),
-    prettyTime: true,
-  });
+  const progress = isTTY
+    ? new ProgressBar({
+        title: `${seqName}`,
+        total: value,
+        width: 20,
+        display: dim(
+          ` -> incrementing "${seqName}": :completed/:total (:eta left) [:bar] :percent`
+        ),
+        prettyTime: true,
+      })
+    : null;
 
   const startVal = await seqLastValue(seqName);
+  const startTime = Date.now();
   let lastVal = startVal;
+  let lastReportedPercent = 0;
 
   try {
     return await waitFor(
       async () => {
         lastVal = await seqLastValue(seqName);
-        progress.render(lastVal);
         const incrementedBy = lastVal - startVal;
+        const percent = Math.floor((incrementedBy / value) * 100);
+
+        if (progress) {
+          progress.render(incrementedBy);
+        } else if (percent >= lastReportedPercent + 10) {
+          // In CI, report every 10% with average speed
+          const elapsedSec = (Date.now() - startTime) / 1000;
+          const avgPerSec = Math.round(incrementedBy / elapsedSec);
+          console.log(dim(` -> ${seqName}: ${percent}% (${incrementedBy}/${value}) - ${avgPerSec}/s avg`));
+          lastReportedPercent = percent;
+        }
 
         return incrementedBy >= value ? lastVal : false;
       },
@@ -118,7 +134,12 @@ export async function waitForSeqToIncrementBy(
       }
     );
   } finally {
-    progress.end();
+    const totalSec = (Date.now() - startTime) / 1000;
+    const avgPerSec = Math.round(value / totalSec);
+    if (progress) {
+      progress.end();
+    }
+    console.log(dim(` -> ${seqName}: 100% complete in ${totalSec.toFixed(1)}s (${avgPerSec}/s avg)`));
   }
 }
 

pkgs/edge-worker/tests/e2e/performance.test.ts

@@ -7,12 +7,12 @@ import {
   log,
 } from './_helpers.ts';
 
-const MESSAGES_TO_SEND = 20000;
+const MESSAGES_TO_SEND = 2000;
 const WORKER_NAME = 'max_concurrency';
 
 Deno.test(
   {
-    name: 'worker can handle tens of thousands of jobs queued at once',
+    name: 'worker can handle thousands of jobs queued at once',
     sanitizeOps: false, // Progress bar uses async writes that don't complete before test ends
     sanitizeResources: false,
   },