nick-doc/Issues/ISSUE-136-backend-api-profiling-mongo-hot-path-cache-query-fanout.md

issue, title, severity, domain, labels, status, created, source

issue	title	severity	domain	labels	status	created	source
136	Backend: API profiling shows Mongo hot paths are index-backed but still do avoidable repeated reads	low	Performance	performance backend mongodb caching	open	2026-05-31	Live dev performance profiling 2026-05-31

Backend: API profiling shows Mongo hot paths are index-backed but still do avoidable repeated reads

Severity: low Domain: Performance Labels: performance, backend, mongodb, caching

Description

Live profiling on dev.manwe.qzz.io after the direct Caddy cutover showed the tested API routes are still Mongo-backed, not Postgres-backed. Postgres pg_stat_statements recorded no application SQL for these request windows; the only SQL activity came from profiling probes and database housekeeping.

The good news: the Mongo queries that did run were using indexes and were effectively sub-millisecond on the tiny dev dataset. The useful optimization work is therefore not "fix a slow scan" yet, but reducing repeated query fan-out and avoiding unnecessary reads before real data volume grows.

Profiling Snapshot

Environment:

• Backend 2.6.84
• Public entrypoint: https://dev.manwe.qzz.io through Caddy -> local nginx -> backend
• MongoDB 6.0.28, bounded system.profile capture with slowms: 0
• PostgreSQL 18.4, pg_stat_statements enabled
• Docker block I/O deltas sampled per endpoint window

Representative results:

Endpoint	Result	Mongo profile
GET /api/marketplace/categories	40 req, avg 296ms, p99 721ms	1 total categories query across the window; Redis category cache is working
GET /api/marketplace/categories/tree	40 req, avg 319ms, p99 763ms	40 categories queries, 24 docs/request, IXSCAN { isActive: 1 }
GET /api/marketplace/sellers	20 req, avg 306ms, p99 722ms	1 users query/request, IXSCAN { role: 1 }
GET /api/marketplace/request-templates/public/:shareableLink	20 req, avg 315ms, p99 781ms	3 queries/request: template by shareableLink, seller by _id, category by _id
GET /api/payment/request-network/options?sellerId&templateId	293 req, avg 270ms, p99 806ms	2 queries/request: requesttemplates by _id, shopsettings by sellerId
GET /api/addresses	15 req, avg 315ms, p99 722ms	1 addresses query/request, IXSCAN { userId: 1 }
GET /api/marketplace/purchase-requests/my	15 req, avg 314ms, p99 702ms	3 queries/request: request list, request count, payment lookup
POST /api/auth/login	5 req, avg 691ms, p99 1058ms	user find + user updates; Mongo time rounded to 0ms, so latency is likely bcrypt/JWT/update path rather than query scan

Disk write notes:

• Mongo profiler itself wrote about 1 MB in some windows; this is measurement overhead, not normal app write load.
• Scanner wrote small background chunks, about 17-24 KB, unrelated to the tested API routes.
• No meaningful app SQL write/read pressure appeared in the API windows.

Recommended Work

1. Cache GET /api/marketplace/categories/tree.

   • getAllCategories() already uses Redis via cacheService.
   • getCategoryTree() re-queries Mongo every request even though it uses the same active category set.

2. Add a short TTL cache for resolved payment rails.

   • Cache by (sellerId, templateId) or a normalized key.
   • Invalidate on template payment config updates and shop settings updates.
   • This removes two Mongo reads from every checkout options poll.

3. Avoid empty payment lookups in getPurchaseRequestsByBuyer.

   • The profiled buyer had no matching requests, but the code still performed a payments lookup with purchaseRequestId: { $in: [] }.
   • Short-circuit when the page result is empty.

4. Add or confirm compound indexes before the dataset grows.

   • PurchaseRequest: { buyerId: 1, createdAt: -1 }
   • Address: { userId: 1, primary: -1, createdAt: -1 }
   • User: consider { role: 1, isEmailVerified: 1 } for public seller lists.

5. Keep pg_stat_statements enabled and add a repeatable profiling script.

   • The dev server now has SQL statement profiling available.
   • nick-doc/scripts/profile-mongo-api.mjs runs the Mongo profiler around the same endpoint matrix and emits JSON/Markdown so future Postgres migrations can be compared cleanly.

Affected Files

• backend/src/services/marketplace/CategoryService.ts:38 — category tree bypasses the existing category cache.
• backend/src/services/payment/sellerPaymentConfig.ts:44 — payment rail resolver performs per-call template/shop lookups.
• backend/src/services/marketplace/RequestTemplateService.ts:465 — public template fetch fans out to template, seller, and category queries.
• backend/src/services/marketplace/PurchaseRequestService.ts — buyer list should skip downstream payment lookup when no request IDs exist.
• backend/src/services/address/addressController.ts:23 — address list is index-backed; compound sort index should be confirmed.

Acceptance Criteria

1. categories/tree uses the same cached category source as categories and invalidates on category writes.
2. Payment options with sellerId + templateId returns from cache for repeated calls and invalidates on relevant seller/template settings changes.
3. Empty purchase request result pages do not issue a payments query.
4. Required compound indexes are present in model definitions or migration/startup index setup.
5. A repeatable profiling command records per-endpoint latency, Mongo query groups, and block I/O deltas; SQL profiling remains available through the separate pg_stat_statements pass.

Latest Repeatable Mongo Profile

Generated report:

• 09 - Audits/Mongo API Profiles/2026-05-31T14-26-19-969Z/summary.md
• 09 - Audits/Mongo API Profiles/2026-05-31T14-26-19-969Z/mongo-api-profile.json

This pass used the script's RESET_BACKEND_LIMITER=1 option to restart the dev backend first. That clears the process-local express-rate-limit global limiter, so authenticated endpoint windows profile Mongo queries instead of stale 429 responses.

Clean run highlights:

Endpoint	Requests	Non-2xx	Mongo ops	Top Mongo profile
GET /api/marketplace/categories/tree	10	0	10	categories find, IXSCAN { isActive: 1 }, 24 docs/request
GET /api/payment/request-network/options?sellerId&templateId	50	0	100	requesttemplates IDHACK + shopsettings by sellerId every request
GET /api/addresses	10	0	10	addresses find, IXSCAN { userId: 1 }, sorted by primary and createdAt
GET /api/marketplace/purchase-requests/my	10	0	30	list + count + unnecessary payments query with purchaseRequestId: { $in: [] }
POST /api/auth/login	5	0	15	indexed user find plus user update operations; latency is outside Mongo query time

Repeatable Mongo Profiling Command

cd nick-doc
RESET_BACKEND_LIMITER=1 \
BASE_URL=https://dev.manwe.qzz.io \
SSH_HOST=root@5.78.213.189 \
SSH_KEY=~/CascadeProjects/wzp \
node scripts/profile-mongo-api.mjs

The script enables Mongo system.profile only for each bounded endpoint window, groups captured query shapes by namespace/plan/query shape, writes a raw JSON profile and a Markdown summary under 09 - Audits/Mongo API Profiles/, then disables profiling again. Leave RESET_BACKEND_LIMITER unset when you do not want the script to restart the dev backend.

References

• Live profiling on dev.manwe.qzz.io — 2026-05-31
• Caddy direct-path profiling pass after Pangolin/newt removal