Skip to content

perf(slack): dedupe webhook JSON.parse + LOG_LEVEL=debug perf timings#443

Merged
JonasJesus42 merged 1 commit into
mainfrom
slack-perf-dedupe-parse-timing-log
May 14, 2026
Merged

perf(slack): dedupe webhook JSON.parse + LOG_LEVEL=debug perf timings#443
JonasJesus42 merged 1 commit into
mainfrom
slack-perf-dedupe-parse-timing-log

Conversation

@JonasJesus42
Copy link
Copy Markdown
Contributor

@JonasJesus42 JonasJesus42 commented May 14, 2026

Summary

Two small perf items spun out of the latency investigation in #442:

A. Eliminate the duplicate JSON.parse

verifySlackRequest was re-deserializing rawBody after the router had already parsed it. Two JSON.parse per webhook on the same payload. The function now returns a plain boolean and the router reuses its existing parsedPayload for shouldIgnoreEvent + processConnectionEventAsync. Saves ~1 ms and removes a dead code branch.

B. Perf-timing log gated on LOG_LEVEL=debug

receivedAt = Date.now() is now captured at the top of the webhook POST handler in router.ts and threaded through:

router → processConnectionEventAsync
       → SlackEventContext.{ traceId, receivedAt }
       → handleSlackEvent
       → per-handler HandlerMeta arg

Each chat-style handler (handleAppMention / handleDirectMessage / handleThreadReply, plus the triggerOnly fast path) emits two markers via logger.debug:

  • perf:thinking_sent — ms from webhook receipt to chat.postMessage of "Pensando..." resolving.
  • perf:trigger_published — ms from webhook receipt to trigger published.

logger.debug is dropped below the configured min level (see logger.ts:50if (LOG_LEVELS[level] < LOG_LEVELS[this.minLevel]) return), so these only flow to HyperDX when LOG_LEVEL=debug is set on the pod. Production runs (LOG_LEVEL=info, the default) pay only the Date.now() + branch cost.

Combined with the existing [Slack] sendMessage SUCCESS in Xms + the thread_messages count on the publisher's notify log, an operator can now decompose end-to-end webhook latency into pod overhead, Slack postMessage RTT, and trigger-enrichment time from logs alone — without code changes.

Test plan

  • Type-check + build clean (already green locally).
  • Deploy with LOG_LEVEL=info (default) → no perf:* entries in HyperDX. Bot still answers as before. Webhook latency should be marginally better (~1 ms from parse dedup).
  • Flip the pod to LOG_LEVEL=debugperf:thinking_sent and perf:trigger_published markers appear in HyperDX with duration_ms and trace_id. Correlate against [Slack] sendMessage SUCCESS in Xms for pod-vs-Slack breakdown.
  • Send a DM, an app_mention, and a thread reply → all three handlers emit both markers.
  • triggerOnly mode emits perf:trigger_published from handleSlackEvent directly (no thinking_sent marker since no Pensando is sent in that mode).

Summary by cubic

Removes duplicate JSON parsing in the Slack webhook path and adds debug-gated perf timing logs for chat handlers. This trims ~1 ms per webhook and lets operators break down latency from logs without code changes.

  • New Features

    • Debug perf markers via logger.debug: perf:thinking_sent and perf:trigger_published for app mentions, DMs, thread replies, and the triggerOnly path; emitted only when LOG_LEVEL=debug (no impact at LOG_LEVEL=info).
  • Refactors

    • Deduplicated webhook parsing: verifySlackRequest now returns a boolean; the router reuses its parsedPayload for shouldIgnoreEvent and processConnectionEventAsync.
    • Captured receivedAt in the router and threaded through SlackEventContext (with traceId) to support timing correlation.

Written for commit 2ee57b8. Summary will update on new commits.

…ings

(A) JSON.parse dedup
  verifySlackRequest used to JSON.parse(rawBody) a second time to derive
  the payload it returned. The router already parses rawBody once before
  calling it, so the same body was deserialized twice per webhook.
  Change verifySlackRequest to return a plain boolean and have the router
  pass through its existing parsedPayload (now used for shouldIgnoreEvent
  and processConnectionEventAsync). Saves ~1ms per webhook and removes
  the redundant code path.

(B) Perf timing logs gated on LOG_LEVEL=debug
  Adds receivedAt: number captured at the top of the webhook POST handler
  in router.ts and threads it through:
    processConnectionEventAsync -> SlackEventContext.{traceId,receivedAt}
      -> handleSlackEvent -> per-handler HandlerMeta arg.

  Each chat-style handler (handleAppMention / handleDirectMessage /
  handleThreadReply, plus the triggerOnly fast path in handleSlackEvent)
  emits two markers via logger.debug:
    perf:thinking_sent     -- ms from webhook receipt to chat.postMessage
                              of "Pensando..." resolved
    perf:trigger_published -- ms from webhook receipt to trigger published

  logger.debug is dropped below the configured min level (logger.ts:50),
  so these only flow to HyperDX when LOG_LEVEL=debug is set on the pod.
  Production runs (LOG_LEVEL=info) pay only the Date.now() + branch cost.

  Combined with the existing "[Slack] sendMessage SUCCESS in Xms" + the
  thread_messages count on the publisher's notify log, the operator can
  now break down end-to-end webhook latency into pod overhead, Slack
  postMessage RTT, and trigger enrichment time from logs alone.

Co-Authored-By: Claude Opus 4.7 <noreply@anthropic.com>
@JonasJesus42 JonasJesus42 merged commit c1cee0f into main May 14, 2026
2 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant