feat(analytics): enrich query_logs metadata + query_log_insights view
For continuous optimization we need to attribute slow/failed decodes to the right cause. query_logs.timings jsonb is now a structured decode-meta blob, not just stage timings: - wmi: first 3 chars of VIN (per-brand aggregation) - result_kind: vehicle / pcat_candidates / emex_candidates / unknown / aborted - cache_source: db_hit / redis_positive / redis_negative / lock_wait / miss - candidate_pick: pcat / emex / none (when user picks from candidate modal) - pcat_car_count, emex_candidate_count (cardinality, drives candidate-modal rate) - pl24_circuit_open, pl24_skipped (CB state at request time) - vin_api_used, vin_api timing (NHTSA fallback frequency) Migration 0003 adds a query_log_insights VIEW that flattens these keys into typed columns, so ad-hoc SQL doesn't need json operators. New meta keys appear automatically as NULL; the VIEW stays stable. docs/analytics-queries.sql has 8 starter queries: cache hit ratio, per-source latency, slowest WMIs, stage breakdowns, CB/abort frequency, candidate-modal rate, top failing VINs, dedup effectiveness. Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
This commit is contained in:
32
apps/api/drizzle/0003_query_log_insights.sql
Normal file
32
apps/api/drizzle/0003_query_log_insights.sql
Normal file
@@ -0,0 +1,32 @@
|
||||
-- Analytics-friendly view over query_logs.
|
||||
-- Flattens commonly-queried keys from the `timings` jsonb so ad-hoc SQL
|
||||
-- doesn't need to remember every json path. New keys can be added without
|
||||
-- breaking existing queries (json operator returns NULL for missing keys).
|
||||
CREATE OR REPLACE VIEW "query_log_insights" AS
|
||||
SELECT
|
||||
ql.id,
|
||||
ql.user_id,
|
||||
ql.vin,
|
||||
substring(ql.vin from 1 for 3) AS wmi,
|
||||
ql.brand_id,
|
||||
ql.source,
|
||||
ql.success,
|
||||
ql.response_time_ms,
|
||||
ql.error_message,
|
||||
ql.created_at,
|
||||
(ql.timings->>'result_kind') AS result_kind,
|
||||
(ql.timings->>'cache_source') AS cache_source,
|
||||
(ql.timings->>'candidate_pick') AS candidate_pick,
|
||||
(ql.timings->>'pcat')::int AS pcat_ms,
|
||||
(ql.timings->>'emex')::int AS emex_ms,
|
||||
(ql.timings->>'pl24')::int AS pl24_ms,
|
||||
(ql.timings->>'vin_api')::int AS vin_api_ms,
|
||||
(ql.timings->>'lock_wait')::int AS lock_wait_ms,
|
||||
(ql.timings->>'pcat_car_count')::int AS pcat_car_count,
|
||||
(ql.timings->>'emex_candidate_count')::int AS emex_candidate_count,
|
||||
(ql.timings->>'pl24_circuit_open')::bool AS pl24_circuit_open,
|
||||
(ql.timings ? 'pl24_skipped') AS pl24_skipped,
|
||||
(ql.timings ? 'aborted') AS aborted,
|
||||
(ql.timings->>'vin_api_used')::bool AS vin_api_used,
|
||||
ql.timings AS raw_meta
|
||||
FROM query_logs ql;
|
||||
5173
apps/api/drizzle/meta/0003_snapshot.json
Normal file
5173
apps/api/drizzle/meta/0003_snapshot.json
Normal file
File diff suppressed because it is too large
Load Diff
@@ -22,6 +22,13 @@
|
||||
"when": 1778584574615,
|
||||
"tag": "0002_boring_the_stranger",
|
||||
"breakpoints": true
|
||||
},
|
||||
{
|
||||
"idx": 3,
|
||||
"version": "7",
|
||||
"when": 1778587000000,
|
||||
"tag": "0003_query_log_insights",
|
||||
"breakpoints": true
|
||||
}
|
||||
]
|
||||
}
|
||||
@@ -31,9 +31,14 @@ import { PrefetchSource } from "../jobs/prefetch.types";
|
||||
import { CATALOG_PREFETCH_QUEUE } from "../jobs/queues/catalog-prefetch.queue";
|
||||
import { RedisService } from "../redis/redis.service";
|
||||
|
||||
/** Per-call stage timings, populated by resolveVin so logQuery can persist them. */
|
||||
/**
|
||||
* Per-decode metadata, persisted to `query_logs.timings` jsonb. Despite the
|
||||
* column name, this is a structured "decode_meta" blob — timings + cardinality
|
||||
* + cache classification + circuit-breaker state. The `query_log_insights`
|
||||
* VIEW (migration 0003) flattens common keys for ad-hoc analytics.
|
||||
*/
|
||||
interface ResolveContext {
|
||||
timings: Record<string, number>;
|
||||
timings: Record<string, number | string | boolean>;
|
||||
}
|
||||
|
||||
interface VinResolveResult {
|
||||
@@ -72,7 +77,12 @@ export class VehiclesService {
|
||||
|
||||
async decodeVin(vin: string, userId: string, pcatCarId?: string, emexCarIndex?: number) {
|
||||
const startTime = Date.now();
|
||||
const ctx: ResolveContext = { timings: {} };
|
||||
const ctx: ResolveContext = {
|
||||
timings: {
|
||||
wmi: vin.length >= 3 ? vin.substring(0, 3).toUpperCase() : "",
|
||||
candidate_pick: pcatCarId ? "pcat" : emexCarIndex !== undefined ? "emex" : "none",
|
||||
},
|
||||
};
|
||||
|
||||
if (!isValidVin(vin)) {
|
||||
throw new BadRequestException("Geçersiz şase numarası");
|
||||
@@ -87,6 +97,8 @@ export class VehiclesService {
|
||||
await this.checkBrandAccess(userId, existing.brandId);
|
||||
}
|
||||
await this.ensureUserVehicleLink(userId, existing.id);
|
||||
ctx.timings.cache_source = "db_hit";
|
||||
ctx.timings.result_kind = "vehicle";
|
||||
await this.logQuery(
|
||||
userId,
|
||||
vin,
|
||||
@@ -95,7 +107,7 @@ export class VehiclesService {
|
||||
true,
|
||||
Date.now() - startTime,
|
||||
undefined,
|
||||
{ db_hit: 1 },
|
||||
ctx.timings,
|
||||
);
|
||||
return existing;
|
||||
}
|
||||
@@ -170,7 +182,10 @@ export class VehiclesService {
|
||||
// biome-ignore lint/suspicious/noExplicitAny: NHTSA VIN API response not strongly typed
|
||||
let vinApiData: any = null;
|
||||
if (resolved.source === "corgi") {
|
||||
const vinApiStart = Date.now();
|
||||
vinApiData = await this.vinApiService.decodeVin(vin);
|
||||
ctx.timings.vin_api = Date.now() - vinApiStart;
|
||||
ctx.timings.vin_api_used = vinApiData !== null;
|
||||
source = vinApiData ? "vin-api" : "corgi";
|
||||
}
|
||||
|
||||
@@ -347,12 +362,22 @@ export class VehiclesService {
|
||||
const cached = await this.redis.getJson<VinResolveResult>(cacheKey);
|
||||
if (cached) {
|
||||
this.logger.debug(`VIN resolve cache hit for ${vin}`);
|
||||
if (ctx) ctx.timings.cache_hit = 1;
|
||||
if (ctx) {
|
||||
ctx.timings.cache_source = "redis_positive";
|
||||
ctx.timings.result_kind = cached.pcatCandidates
|
||||
? "pcat_candidates"
|
||||
: cached.emexCandidates
|
||||
? "emex_candidates"
|
||||
: "vehicle";
|
||||
}
|
||||
return cached;
|
||||
}
|
||||
if (await this.redis.exists(negKey)) {
|
||||
this.logger.debug(`VIN resolve negative cache hit for ${vin}`);
|
||||
if (ctx) ctx.timings.cache_neg_hit = 1;
|
||||
if (ctx) {
|
||||
ctx.timings.cache_source = "redis_negative";
|
||||
ctx.timings.result_kind = "unknown";
|
||||
}
|
||||
return null;
|
||||
}
|
||||
|
||||
@@ -362,8 +387,16 @@ export class VehiclesService {
|
||||
// Another request is decoding this VIN — wait for its result.
|
||||
const waitStart = Date.now();
|
||||
const waited = await this.waitForResolve(vin, cacheKey, negKey);
|
||||
if (ctx) ctx.timings.lock_wait = Date.now() - waitStart;
|
||||
if (waited !== "timeout") return waited;
|
||||
if (ctx) {
|
||||
ctx.timings.lock_wait = Date.now() - waitStart;
|
||||
ctx.timings.cache_source = "lock_wait";
|
||||
}
|
||||
if (waited !== "timeout") {
|
||||
if (ctx) {
|
||||
ctx.timings.result_kind = waited === null ? "unknown" : "vehicle";
|
||||
}
|
||||
return waited;
|
||||
}
|
||||
// Waiter timed out (decode is taking longer than expected). Fall through
|
||||
// and decode ourselves — duplicate work, but better than blocking forever.
|
||||
this.logger.warn(`VIN ${vin} lock wait timed out — decoding ourselves`);
|
||||
@@ -375,16 +408,29 @@ export class VehiclesService {
|
||||
const ac = new AbortController();
|
||||
const budgetTimer = setTimeout(() => ac.abort(), VehiclesService.RESOLVE_BUDGET_MS);
|
||||
|
||||
if (ctx && !ctx.timings.cache_source) ctx.timings.cache_source = "miss";
|
||||
try {
|
||||
const result = await this.doResolveVin(vin, userId, ctx, ac.signal);
|
||||
if (ac.signal.aborted) {
|
||||
this.logger.warn(
|
||||
`VIN ${vin} decode aborted by budget (${VehiclesService.RESOLVE_BUDGET_MS}ms)`,
|
||||
);
|
||||
if (ctx) ctx.timings.aborted = 1;
|
||||
if (ctx) {
|
||||
ctx.timings.aborted = 1;
|
||||
ctx.timings.result_kind = "aborted";
|
||||
}
|
||||
// Don't cache: this was a transient timeout, not a permanent failure.
|
||||
return null;
|
||||
}
|
||||
if (ctx && !ctx.timings.result_kind) {
|
||||
ctx.timings.result_kind = result
|
||||
? result.pcatCandidates
|
||||
? "pcat_candidates"
|
||||
: result.emexCandidates
|
||||
? "emex_candidates"
|
||||
: "vehicle"
|
||||
: "unknown";
|
||||
}
|
||||
if (result) {
|
||||
await this.redis.setJson(cacheKey, result, VehiclesService.RESOLVE_TTL_POSITIVE_S);
|
||||
} else {
|
||||
@@ -520,6 +566,12 @@ export class VehiclesService {
|
||||
if (signal?.aborted) return null;
|
||||
}
|
||||
|
||||
if (ctx) {
|
||||
ctx.timings.pcat_car_count = pcatResult?.cars?.length ?? 0;
|
||||
ctx.timings.emex_candidate_count =
|
||||
emexResult?.type === "candidates" ? emexResult.candidates.length : 0;
|
||||
}
|
||||
|
||||
// Decision 1: pcat returned exactly 1 car → use it, ignore EMEX
|
||||
if (pcatResult?.cars?.length === 1) {
|
||||
const car = pcatResult.cars[0];
|
||||
@@ -573,6 +625,7 @@ export class VehiclesService {
|
||||
this.logger.log(`PL24 fallback triggered for ${vin} (EMEX: ${emexResult?.type ?? "timeout"})`);
|
||||
|
||||
const pl24CircuitOpen = await this.isPl24CircuitOpen();
|
||||
if (ctx) ctx.timings.pl24_circuit_open = pl24CircuitOpen;
|
||||
if (pl24CircuitOpen) {
|
||||
this.logger.warn(`PL24 skipped for ${vin}: circuit breaker is open`);
|
||||
if (ctx) ctx.timings.pl24_skipped = 1;
|
||||
@@ -978,7 +1031,7 @@ export class VehiclesService {
|
||||
success: boolean,
|
||||
responseTimeMs: number,
|
||||
errorMessage?: string,
|
||||
timings?: Record<string, number>,
|
||||
timings?: Record<string, number | string | boolean>,
|
||||
) {
|
||||
try {
|
||||
await this.db.insert(queryLogs).values({
|
||||
|
||||
Reference in New Issue
Block a user