This is an automated email from the ASF dual-hosted git repository. wu-sheng pushed a commit to branch refactor/ai-profiling-oap-owned-rules in repository https://gitbox.apache.org/repos/asf/skywalking-horizon-ui.git
commit fe8eb4a16a74978f7bd9fa08566931d6b857f223 Author: Wu Sheng <[email protected]> AuthorDate: Wed Jul 29 08:45:11 2026 +0800 fix(ai): read profiling results the way OAP actually reports them Second pass over the profiling path, on the analyze side. Each of these was verified against the OAP source rather than inferred from field names. - A task's progress log says how far it got, and every flavour shares the vocabulary (ProfileTaskLogOperationType / AsyncProfilerTaskLogOperationType / PprofTaskLogOperationType): NOTIFIED means only "issued to the agent", EXECUTION_FINISHED means done, and the *_ERROR variants are hard failures. We treated "any log exists" as collected, so analyzing a task right after approving it -- the obvious thing to do -- answered "ran but produced no analyzable stacks, do not retry". Now: still-collecting, finished-empty and agent-failed are three different answers. - JFRConverter.collectMultiEvents splits every AllocationSample on `tlabSize != 0` into OBJECT_ALLOCATION_IN_NEW_TLAB and _OUTSIDE_TLAB. We mapped ALLOC to the in-TLAB tree only, silently dropping the large-object allocation paths. Events are also a list on the task, and we read events[0]. Both now fan out and render every tree. - ProcessRelation metrics carry `supportDownSampling = false`, i.e. MINUTE buckets only, but the network fallback probe passed the chat window's step through -- so any HOUR/DAY range read an empty bucket, which we reported as a missing Rover agent. The probe is re-cut at MINUTE. - ProfileTaskQueryService stamps `profiled` per SEGMENT (line 261), not per span, so one analyze query per profiled span asked the same segment N times over sub-ranges of one snapshot stream -- burning the 100-query cap N x faster and inflating totalSequenceCount enough to trip OAP's partial-analysis tip, which we relayed as truncation that had not happened. One query per segment. - pprof `dumpPeriod` is a sampling RATE (per pprof.graphqls: one event per N nanoseconds blocked for BLOCK, per N occurrences for MUTEX), where LOWER is more verbose. Clamping it to a `_SEC`-named ceiling of 60 turned a coarse request into near-maximum verbosity -- the opposite of a guard. OAP requires only `> 0`, so the rate is forwarded. - pprof duration is validated only for CPU/BLOCK/MUTEX, so point-in-time events land as 0 and rendered as a "0 min" window; they are labelled as snapshots. GraphQL listProcesses passes includeVirtual = true while the network create gate's getProcessCount(instanceId) passes false, so virtual rows are dropped before the list is served -- it was possible to offer an instance OAP rejects. Validated on a local e2e OAP: a mid-flight task now reports "still collecting" (logs: NOTIFIED) where it previously said it found nothing; a finished-empty task still reports finished-empty (NOTIFIED + EXECUTION_FINISHED); and the populated task renders the same 66 frames with per-segment queries. --- CHANGELOG.md | 5 ++ apps/bff/src/ai/skill/triggers/tools.ts | 24 ++++++- apps/bff/src/http/query/async-profile.ts | 14 +++- apps/bff/src/http/query/ebpf.ts | 11 ++- apps/bff/src/logic/oap/profiling.ts | 112 ++++++++++++++++++++++++------- packages/api-client/src/ebpf.ts | 3 + 6 files changed, 139 insertions(+), 30 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 19f44e5..eda1d5d 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -15,6 +15,11 @@ The version line is shared by every package in the monorepo (apps + shared packa - **It can propose profiling — the right kind for the target — and only you start it.** When metrics and traces can't localise a cause, the assistant presents a **decision card** explaining what it found, why profiling would help, and what it expects to reveal; nothing runs until you **approve it in the popout**, and only if you hold the profiling permission. It picks the profiling flavour that fits the target — **trace** sampling, **async-profiler** for a JVM service, **pprof** for a Go [...] - **Your backend decides what profiling is allowed — the assistant no longer refuses on its own guesses.** Previously the assistant could decline to even show a profiling card: because the layer's template didn't list that profiling type, because the instances reported a runtime the profiler doesn't match, because no process had advertised eBPF support recently, or because no process had reported in the last 30 minutes — and it phrased those as facts about your deployment ("the GENERAL l [...] - **Off-CPU eBPF profiles are ranked by time blocked, not by how often a thread yielded.** An OFF_CPU profile is what you reach for when the question is "what is this service waiting on", but its frames were ranked by scheduler switch *count* — so a method that yields thousands of times for microseconds outranked the one that blocks for a second, inverting the answer. Off-CPU results now aggregate by duration. Relatedly, the assistant now names each profiler's real unit when it reads a f [...] +- **A profiling task that is still collecting is no longer reported as one that found nothing.** Asking the assistant to analyze a task shortly after you approved it — the obvious thing to do — could come back with "the task ran but produced no analyzable stacks; do not retry", because *any* progress log was read as "it finished". The first log a task gets means only that it was handed to the agent. The assistant now distinguishes the three real states: **still collecting** (wait and ask [...] +- **Allocation and multi-event profiles are read whole.** An async-profiler **ALLOC** profile was showing only half its data: OAP splits allocations into in-TLAB and outside-TLAB trees, and only the first was read — so the large-object allocation paths, usually the reason for opening an allocation profile, were missing. A task started with several events (say CPU + ALLOC + LOCK) likewise rendered only the first. Both now render every tree the task produced. +- **Network profiling results no longer come back empty on a wide time range.** The process-conversation graph is built from metrics OAP only keeps at minute granularity, so reading it against an hour- or day-scale chat window returned nothing — which the assistant then reported as "no Rover agent / network profiling unavailable". The read is now always minute-granular. +- **Trace profile analysis stopped asking OAP the same question many times over.** One analysis query was issued per profiled *span*, though OAP marks profiling per *segment* — so a segment with 20 spans cost 20 near-identical queries, exhausted the analysis budget 20× faster, and could trip OAP's "only part of the snapshots were analyzed" warning, which was then relayed to you as a truncated profile that was never truncated. One query per segment now. +- **A point-in-time pprof profile (HEAP, GOROUTINE, ALLOCS, THREADCREATE) is labelled as one** instead of showing a "0 min" collection window, which read as a task that collected for no time. Relatedly, the process list used to confirm an instance can be network-profiled no longer counts virtual processes, which OAP's own check excludes — it was possible to be offered an instance OAP would then reject. - **pprof collection windows are validated in the unit OAP actually uses.** The pprof task duration is measured in **minutes** and capped at 15 by OAP, but Horizon was bounding it as if it were 600 seconds — so an over-long request sailed through and came back as an opaque backend error after you approved it. It is now bounded at OAP's real limit. Likewise, an async or pprof task targeting more instances than a single task allows is now **rejected with a clear reason** instead of quietly [...] - **Guided root-cause analysis.** Ask "what's the root cause?" and the assistant follows built-in investigation playbooks — a master method (locate the root service → calling chain → error stack; walk the dependency topology upstream and fix a sick upstream first; a remote / Virtual_* dependency exposes only its client-side edge metric) plus latency, error-rate/SLA, saturation, middleware, **Kubernetes-workload**, and service-mesh specializations. It can also follow the **cross-layer hie [...] - **Bring your own LLM — vendor-neutral, and off by default.** Enable it with the new `ai:` config block (`HORIZON_AI_*`). The default transport is **OpenAI-compatible** (any OpenAI-shaped endpoint — a hosted model, a local model, or an AI gateway; set model + base URL + API key); **Amazon Bedrock** is also supported (`provider: bedrock`). The API key is a secret, env-only, redacted from logs and excluded from the audit trail. The launcher shows for every signed-in user so the AI-powered [...] diff --git a/apps/bff/src/ai/skill/triggers/tools.ts b/apps/bff/src/ai/skill/triggers/tools.ts index d45f216..ba729b2 100644 --- a/apps/bff/src/ai/skill/triggers/tools.ts +++ b/apps/bff/src/ai/skill/triggers/tools.ts @@ -306,6 +306,7 @@ export function triggerTools(ctx: AiRequestContext): StructuredToolInterface[] { layerKey: layer, service, window: ctx.window, + rangeMs: { startMs: ctx.range.startMs, endMs: ctx.range.endMs }, offsetMinutes: await getServerOffsetMinutes(ctx.config, ctx.fetch), taskId, }); @@ -353,10 +354,27 @@ export function triggerTools(ctx: AiRequestContext): StructuredToolInterface[] { // fills neither logs nor segments — the one signal every flavor carries // is that a task was RESOLVED (its id + facts land on the summary), so // branch on that before blaming the deployment. - const collected = a.logs.length > 0 || (a.summary.segmentCount ?? 0) > 0; + // + // The LOG's operationType is what says how far the task got, and every + // flavour shares the vocabulary: NOTIFIED means only "issued to the + // agent" (still running — NOT a finished-but-empty profile), + // EXECUTION_FINISHED means the agent is done, and the *_ERROR variants + // (EXECUTION_TASK_ERROR, JFR/PPROF_UPLOAD_FILE_TOO_LARGE_ERROR) are hard + // failures. Treating "any log exists" as collected reported all three as + // "ran but found nothing, do not retry" — which told the operator to + // give up on a task that was still collecting, or hid a real agent error. + const failed = a.logs.filter((l) => l.operationType.endsWith('_ERROR')); + const finished = a.logs.some((l) => l.operationType === 'EXECUTION_FINISHED'); const taskFound = !!a.taskId && (a.summary.startTime != null || a.summary.durationLabel != null); - if (collected) { - return `The ${profilingType} profiling task for ${service} ran but produced no analyzable stacks${why} — nothing met the sampling threshold. Tell the user; do not retry indefinitely.`; + if (failed.length) { + const kinds = [...new Set(failed.map((l) => l.operationType))].join(', '); + return `The ${profilingType} profiling task for ${service} (task ${a.taskId}) FAILED on the agent — OAP logged ${kinds} for ${[...new Set(failed.map((l) => l.instanceName))].join(', ')}${why}. This is an agent-side error, not an empty profile: report the failure and what it means (a too-large upload means the profile exceeded what OAP accepts — propose a shorter window), and do not retry unchanged.`; + } + if (a.logs.length && !finished) { + return `The ${profilingType} profiling task for ${service} (task ${a.taskId}) has been issued to the agent and is still COLLECTING — no stacks yet${why}. Tell the user it is running and analyze again after its window elapses. Do NOT report this as a profile that found nothing.`; + } + if (finished || (a.summary.segmentCount ?? 0) > 0) { + return `The ${profilingType} profiling task for ${service} finished but produced no analyzable stacks${why} — nothing met the sampling threshold. Tell the user; do not retry indefinitely.`; } if (taskFound) { return `The ${profilingType} profiling task for ${service} (task ${a.taskId}) exists but has reported no stacks yet${why}. If it was JUST created, give it 2–4 minutes to collect, then analyze once more. If it has been running well past its window with nothing, say the agent likely cannot collect ${profilingType} profiles here (missing plugin / eBPF host access) — do not retry indefinitely.`; diff --git a/apps/bff/src/http/query/async-profile.ts b/apps/bff/src/http/query/async-profile.ts index ec70403..b15b55c 100644 --- a/apps/bff/src/http/query/async-profile.ts +++ b/apps/bff/src/http/query/async-profile.ts @@ -82,7 +82,6 @@ function clampTaskListLimit(raw: string | undefined): number { * could otherwise peg a fleet's CPU for hours. Never describe it as OAP's. */ const MAX_ASYNC_DURATION_SEC = 600; const MAX_PPROF_DURATION_MIN = 15; -const MAX_PPROF_DUMP_PERIOD_SEC = 60; const MAX_TARGET_INSTANCES = 32; const MAX_EVENTS_PER_TASK = 8; const MAX_EXEC_ARGS_LEN = 256; @@ -410,10 +409,21 @@ export function registerAsyncProfileRoutes( ...(raw.duration !== undefined ? { duration: clampPositiveInt(raw.duration, MAX_PPROF_DURATION_MIN, null) ?? 0 } : {}), + // NOT a period in seconds — OAP defines dumpPeriod as a sampling RATE: + // for BLOCK, one event per that many nanoseconds spent blocked; for + // MUTEX, one per that many contentions. Lower means MORE verbose (1 + // samples everything), so an upper bound is exactly the wrong guard — + // clamping a caller's 1_000_000 down to 60 turned a coarse sample into + // near-maximum verbosity. OAP requires only `dumpPeriod > 0` for + // BLOCK/MUTEX, so forward the caller's rate and let OAP judge it. ...(raw.dumpPeriod !== undefined ? { dumpPeriod: - clampPositiveInt(raw.dumpPeriod, MAX_PPROF_DUMP_PERIOD_SEC, null) ?? 1, + typeof raw.dumpPeriod === 'number' && + Number.isFinite(raw.dumpPeriod) && + raw.dumpPeriod > 0 + ? Math.round(raw.dumpPeriod) + : 1, } : {}), }; diff --git a/apps/bff/src/http/query/ebpf.ts b/apps/bff/src/http/query/ebpf.ts index da13929..028168a 100644 --- a/apps/bff/src/http/query/ebpf.ts +++ b/apps/bff/src/http/query/ebpf.ts @@ -364,11 +364,18 @@ function relationSeries(env: MqeEnv | undefined): Array<number | null> { }); } +// `detectType` matters because the two sides disagree on VIRTUAL processes: +// GraphQL listProcesses calls the DAO with includeVirtual = TRUE, while the gate +// that decides whether a network task may be created — +// getProcessCount(instanceId) — passes FALSE. Counting the rows this returns as +// "processes OAP will accept" therefore over-counts, and the operator gets +// "The instance doesn't have processes." for an instance we just listed some for. const LIST_PROCESSES = /* GraphQL */ ` query listNetworkProcesses($instanceId: ID!, $duration: Duration!) { listProcesses(instanceId: $instanceId, duration: $duration) { id name + detectType } } `; @@ -609,7 +616,9 @@ export function registerEBPFRoutes(app: FastifyInstance, deps: EBPFRouteDeps): v duration: { start: fmtMinute(startMs, offset), end: fmtMinute(endMs, offset), step: 'MINUTE' }, }, ); - payload.processes = data.listProcesses ?? []; + // Drop VIRTUAL rows so this list means what its callers read it as: + // the processes a network task can actually be created against. + payload.processes = (data.listProcesses ?? []).filter((p) => p.detectType !== 'VIRTUAL'); return reply.send(payload); } catch (err) { return reply.send(softErr(payload, err)); diff --git a/apps/bff/src/logic/oap/profiling.ts b/apps/bff/src/logic/oap/profiling.ts index 2141587..18a4e56 100644 --- a/apps/bff/src/logic/oap/profiling.ts +++ b/apps/bff/src/logic/oap/profiling.ts @@ -83,13 +83,19 @@ export interface ProfilingAnalysis { // async-profiler events fold into one JFR tree type; pick it to select which // tree the analyze returns. Inlined (not imported from the http route) to keep // the logic→client direction clean. -const ASYNC_EVENT_TO_JFR: Record<string, string> = { - CPU: 'EXECUTION_SAMPLE', - WALL: 'EXECUTION_SAMPLE', - CTIMER: 'EXECUTION_SAMPLE', - ITIMER: 'EXECUTION_SAMPLE', - LOCK: 'LOCK', - ALLOC: 'OBJECT_ALLOCATION_IN_NEW_TLAB', +// One capture event can yield MORE THAN ONE JFR tree, and a task legitimately +// carries several events — so this maps to a LIST and every entry is read. +// ALLOC is the trap: OAP's JFRConverter splits each AllocationSample on +// `tlabSize != 0` into OBJECT_ALLOCATION_IN_NEW_TLAB vs _OUTSIDE_TLAB, so +// reading only the in-TLAB half silently drops every large-object allocation +// path — the one an allocation profile is usually opened to find. +const ASYNC_EVENT_TO_JFR: Record<string, string[]> = { + CPU: ['EXECUTION_SAMPLE'], + WALL: ['EXECUTION_SAMPLE'], + CTIMER: ['EXECUTION_SAMPLE'], + ITIMER: ['EXECUTION_SAMPLE'], + LOCK: ['LOCK'], + ALLOC: ['OBJECT_ALLOCATION_IN_NEW_TLAB', 'OBJECT_ALLOCATION_OUTSIDE_TLAB'], }; // Cap the trace analyze fan-out: each profiled span becomes one analyze query, @@ -287,6 +293,9 @@ export interface AnalyzeNetworkProfilingInput { service: string; /** FALLBACK scope only — used when no NETWORK task pins an instance + window. */ window: { start: string; end: string; step: string }; + /** Epoch-ms mirror of `window`, so the process-graph probe can be re-cut at + * MINUTE granularity (see `minuteWindow`). */ + rangeMs: { startMs: number; endMs: number }; /** OAP-server UTC offset, to render a task's epoch-ms window OAP-local. */ offsetMinutes: number; /** Read this task; when absent, the service's most recent NETWORK task. */ @@ -327,6 +336,17 @@ async function findNetworkTask( // A task's data only exists for the span it ran, on the instance it watched. A // still-running (keep-alive) task reports no duration — read it up to now, the // same rule the network-profiling view applies. +function minuteWindow( + range: { startMs: number; endMs: number }, + offsetMinutes: number, +): { start: string; end: string; step: 'MINUTE' } { + return { + start: fmtMinute(range.startMs, offsetMinutes), + end: fmtMinute(range.endMs, offsetMinutes), + step: 'MINUTE', + }; +} + function taskDuration(task: NetworkTask, offsetMinutes: number): { start: string; end: string; step: 'MINUTE' } { const durMs = (task.fixedTriggerDuration ?? 0) * 1000; const endMs = durMs > 0 ? task.taskStartTime + durMs : Date.now(); @@ -533,7 +553,15 @@ export async function analyzeNetworkProfiling(input: AnalyzeNetworkProfilingInpu } const insts = await listServiceInstances(opts, serviceId, window); if (!insts.length) return result; - const probe = await probeProcessTopology(opts, insts, window); + // The process graph is built from ProcessRelation metrics, which OAP + // persists at MINUTE granularity ONLY (`supportDownSampling = false`), so + // an HOUR/DAY-stepped chat window reads a bucket that was never written and + // comes back empty — which we would then report as "no Rover agent". Re-cut + // the same instant range at MINUTE before probing. The task-scoped path + // above already builds its own MINUTE window. + const probeWindow = minuteWindow(input.rangeMs, offsetMinutes); + result.queried = { start: probeWindow.start, end: probeWindow.end }; + const probe = await probeProcessTopology(opts, insts, probeWindow); if (probe.hit) { result.instanceName = probe.hit.instance.name; result.topology.nodes = probe.hit.nodes; @@ -599,8 +627,14 @@ function mapEbpfTree(elements: EbpfStack[]): ProfileAnalyzationTree { }; } +// A pprof HEAP / GOROUTINE / ALLOCS / THREADCREATE task is a point-in-time +// snapshot: OAP validates (and the agent honours) `duration` only for CPU / +// BLOCK / MUTEX, so the field lands as 0 for the others. Rendering that as +// "0 min" reads as a task that collected for no time — the opposite of what a +// snapshot event means. function durationMinLabel(minutes: number | null | undefined): string | null { - return minutes == null ? null : `${minutes} min`; + if (minutes == null) return null; + return minutes > 0 ? `${minutes} min` : 'point-in-time snapshot'; } function durationSecLabel(seconds: number | null | undefined): string | null { return seconds == null ? null : `${seconds} s`; @@ -683,16 +717,36 @@ async function analyzeTrace( const segments = segs.segmentList ?? []; base.summary.segmentCount = segments.length; - // Slowest segments first, then one analyze query per profiled span, capped. + // Slowest segments first, then ONE analyze query per profiled SEGMENT — which + // is the granularity OAP stamps `profiled` at (ProfileTaskQueryService marks + // every span of a profiled segment, it does not select individual spans). One + // query per span instead asked the same segment N times over sub-ranges of the + // same snapshot stream: it burned the cap N× faster, and inflated OAP's + // totalSequenceCount enough to trip its "analyzed only part of the snapshots" + // tip, which we then relayed as a truncated profile that was never truncated. const bySlowest = [...segments].sort((a, b) => (b.duration ?? 0) - (a.duration ?? 0)); const queries: Array<{ segmentId: string; timeRange: { start: number; end: number } }> = []; - for (const seg of bySlowest) { + const seen = new Set<string>(); + outer: for (const seg of bySlowest) { + const bySegmentId = new Map<string, ProfileSpan[]>(); for (const span of seg.spans ?? []) { if (!span.profiled) continue; - queries.push({ segmentId: span.segmentId, timeRange: { start: span.startTime, end: span.endTime } }); - if (queries.length >= MAX_TRACE_ANALYZE_QUERIES) break; + const list = bySegmentId.get(span.segmentId); + if (list) list.push(span); + else bySegmentId.set(span.segmentId, [span]); + } + for (const [segmentId, spans] of bySegmentId) { + if (seen.has(segmentId)) continue; + seen.add(segmentId); + queries.push({ + segmentId, + timeRange: { + start: Math.min(...spans.map((s) => s.startTime)), + end: Math.max(...spans.map((s) => s.endTime)), + }, + }); + if (queries.length >= MAX_TRACE_ANALYZE_QUERIES) break outer; } - if (queries.length >= MAX_TRACE_ANALYZE_QUERIES) break; } // Carry the slowest profiled segment's trace for the waterfall beside the flame. @@ -765,19 +819,29 @@ async function analyzeStackList( base.error = 'The task targets no instances — nothing to analyze.'; return base; } - const request = isAsync - ? { taskId: task.id, instanceIds, eventType: ASYNC_EVENT_TO_JFR[events[0]] ?? 'EXECUTION_SAMPLE' } - : { taskId: task.id, instanceIds }; - const an = await graphqlPost<{ analysisResult: { tree: { elements: WireStack[] } | null } | null }>( - opts, - analyzeQuery, - { request }, + // async analyses ONE JFR tree per request, so a task with several capture + // events (or an ALLOC task, which OAP splits in two) needs one request each — + // reading only the first would present a fraction of the profile as the whole. + // pprof carries no event selector: a single request returns its one tree. + const jfrTypes = isAsync + ? [...new Set(events.flatMap((e) => ASYNC_EVENT_TO_JFR[e] ?? ['EXECUTION_SAMPLE']))] + : []; + const requests = isAsync + ? (jfrTypes.length ? jfrTypes : ['EXECUTION_SAMPLE']).map((eventType) => ({ taskId: task.id, instanceIds, eventType })) + : [{ taskId: task.id, instanceIds }]; + const results = await Promise.all( + requests.map((request) => + graphqlPost<{ analysisResult: { tree: { elements: WireStack[] } | null } | null }>(opts, analyzeQuery, { + request, + }), + ), ); // OAP merges the dumps under a synthesized zero-sample root, so an uncollected // task still analyzes to one all-zero element — that's empty, not a 1-frame profile. - const elements = an.analysisResult?.tree?.elements ?? []; - const collected = elements.length > 1 && elements.some((e) => e.dumpCount > 0); - base.trees = collected ? [mapWireTree(elements)] : []; + base.trees = results + .map((an) => an.analysisResult?.tree?.elements ?? []) + .filter((elements) => elements.length > 1 && elements.some((e) => e.dumpCount > 0)) + .map((elements) => mapWireTree(elements)); base.summary.frameCount = frameCount(base.trees); return base; } diff --git a/packages/api-client/src/ebpf.ts b/packages/api-client/src/ebpf.ts index 1225a58..cc4bd72 100644 --- a/packages/api-client/src/ebpf.ts +++ b/packages/api-client/src/ebpf.ts @@ -163,6 +163,9 @@ export interface ProcessTopologyResponse { export interface NetworkProcess { id: string; name: string; + /** OAP's process detect type. VIRTUAL rows are excluded before this list is + * served, because OAP's own create gate counts non-virtual processes only. */ + detectType?: string; } export interface NetworkProcessesResponse { processes: NetworkProcess[];
