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 e76ee547a53fcdadd34947ecd02bd34dbaa53097 Author: Wu Sheng <[email protected]> AuthorDate: Wed Jul 29 09:39:35 2026 +0800 fix(ai): start approved tasks ASAP, and stop hiding partial reads Third pass, closing the rest of the audit's confirmed findings. - Trace and eBPF creates sent a wall clock as `startTime`. OAP reads it as "begin AFTER this, based on agent side time" (profile.graphqls:23) and ProfileTaskCache only dispatches tasks whose start falls within +/-5 minutes of the SERVER clock, so a drifted browser produced a task that was accepted, returned an id, and never ran. Both schemas document an ASAP form -- trace's startTime is nullable ("if null means the task starts ASAP"), eBPF's uses <= 0 -- so use those and stop comparing clocks we do not own. The BFF's eBPF route no longer substitutes its own Date.now() either. - An unrecognised async/pprof event was rewritten to CPU, so an approved card reading "HEAP" fired a CPU profile. The vocabulary is an OAP GraphQL enum that validates and names its allowed values, so pass the event through and carry the doubt as a caveat -- an honest rejection beats a wrong profile. - EBPFProfilingAnalyzer splits each submitted range into 10s chunks under one deadline and returns an EMPTY list for any chunk that misses it (caught, log.warn'd), and it never sets `tip` -- so an over-wide request degraded to a silently partial flame we presented as whole. Budget the fan-out by the same chunk size, most recent schedules first, and set `tip` when we drop any. - An empty process-conversation graph was reported as "network profiling is unavailable here". A network task runs a server-fixed 10 minutes, so the workflow's own happy path (approve -> analyze shortly after) lands on a graph that is simply not populated yet. Report the read, and offer the missing Rover agent as the likely cause only once the window has elapsed. - pprof "self" counts sample RECORDS (FrameTreeBuilder increments by 1 and discards the sample value), so for HEAP/ALLOCS the top frame is the one with the most distinct allocation stacks, not the most memory. Say so. NOT changed, deliberately: the analyze path still reads FIXED_TIME tasks only. Continuous profiling is auto-triggered by policy, not created on demand, so it is not part of this ask -> approval workflow; blending an auto-triggered task into "analyze the task you approved" would confuse the two. Validated against a local e2e OAP: a trace create with no startTime is accepted and OAP stamps the task id with its own clock. --- CHANGELOG.md | 4 ++++ apps/bff/src/ai/skill/triggers/tools.ts | 35 ++++++++++++++++++++++++++++----- apps/bff/src/http/query/ebpf.ts | 6 +++++- apps/bff/src/logic/oap/profiling.ts | 29 +++++++++++++++++++++++++-- apps/ui/src/ai/ChatProposalBlock.vue | 11 +++++++++-- packages/api-client/src/profile.ts | 7 ++++++- 6 files changed, 81 insertions(+), 11 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index eda1d5d..3a3e439 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -15,6 +15,10 @@ 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 [...] +- **An approved profiling task starts immediately, timed by your backend rather than your laptop.** The task's start time was sent as the browser's wall clock, but OAP treats it as "begin after this moment" and only dispatches tasks starting within ±5 minutes of *its own* clock — so on a workstation whose clock had drifted (a suspended VM, a container host without NTP) the task was accepted, returned an id, the card said "started", and nothing ever ran. Both trace and eBPF tasks now use [...] +- **An event the assistant doesn't recognise is no longer silently swapped for CPU.** Asking for a profiling event outside its known list produced a card that read as requested but fired a CPU profile instead. The event is now passed through for OAP to accept or reject by name, and the assistant flags that it didn't recognise it — a clear rejection beats a wrong profile. Relatedly, when a **HEAP** or **ALLOCS** pprof profile is read back, the assistant now states that the ranking is a co [...] +- **Long eBPF profiles say when only part of the range was analyzed.** A wide eBPF task could exceed what OAP fetches in a single analysis, and the excess was dropped server-side with nothing on screen to indicate it — a partial flame graph presented as complete. The assistant now bounds the request to the most recent profiling schedules and tells you when it did. +- **An empty network process graph is no longer reported as a missing agent.** Because a network task runs for a fixed 10 minutes, analyzing shortly after approval legitimately finds nothing yet; that now reads as "still collecting", and a missing Rover agent is offered as the likely cause only once the window has actually elapsed. - **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. diff --git a/apps/bff/src/ai/skill/triggers/tools.ts b/apps/bff/src/ai/skill/triggers/tools.ts index ba729b2..69889be 100644 --- a/apps/bff/src/ai/skill/triggers/tools.ts +++ b/apps/bff/src/ai/skill/triggers/tools.ts @@ -105,7 +105,17 @@ function summarizeProfile(a: ProfilingAnalysis): string { a.profilingType === 'trace' ? `self time (share of ${Math.round(totalSelf)}ms total self time)` : `self samples (share of ${totalSelf} total self samples)`; - return top.length ? ` Hottest frames by ${basis}: ${top.join('; ')}.` : ''; + // OAP counts pprof sample RECORDS — each frame is incremented by 1 per sample + // and the sample's own value is discarded. For HEAP / ALLOCS that means the + // top frame is the one with the most distinct allocation stacks, NOT the one + // holding or allocating the most memory, which is what an operator chasing a + // leak will read it as unless told otherwise. + const memoryEvent = + a.profilingType === 'pprof' && ['HEAP', 'ALLOCS'].includes((a.summary.events?.[0] ?? '').toUpperCase()); + const caveat = memoryEvent + ? ' NOTE: this is a count of sample records, NOT bytes — it ranks by how many distinct allocation stacks hit a frame, not by memory held or allocated. Do not report it as a memory figure.' + : ''; + return top.length ? ` Hottest frames by ${basis}: ${top.join('; ')}.${caveat}` : ''; } export function triggerTools(ctx: AiRequestContext): StructuredToolInterface[] { @@ -233,13 +243,19 @@ export function triggerTools(ctx: AiRequestContext): StructuredToolInterface[] { ); } } - // Normalise the event to one this profiler knows (default CPU) so the card - // never fires a garbage event the BFF would silently drop. + // Default to CPU when no event was named. An event we don't recognise is + // passed THROUGH: the vocabulary is an OAP GraphQL enum, which validates + // and rejects with a clear message naming the allowed values. Silently + // rewriting it to CPU meant the operator approved a card reading "HEAP" + // and got a CPU profile — a wrong answer beats an honest rejection. let events: string[] | undefined; if (profilingType === 'async' || profilingType === 'pprof') { const known = profilingType === 'async' ? ASYNC_EVENTS : PPROF_EVENTS; const ev = (event ?? 'CPU').toUpperCase(); - events = [known.includes(ev) ? ev : 'CPU']; + events = [ev]; + if (!known.includes(ev)) { + caveats.push(`"${ev}" is not an event I know for ${profilingType} profiling (I know ${known.join(', ')}). I passed it through rather than substituting CPU — if OAP does not accept it, the approve will fail with the list it does accept.`); + } } // OAP fixes a NETWORK task at 10 minutes (NETWORK_PROFILING_DURATION) and // its create request carries no duration field at all, so any number the @@ -320,7 +336,16 @@ export function triggerTools(ctx: AiRequestContext): StructuredToolInterface[] { return `Could not read the network-profiling result for ${service}${where}: ${topo.error ?? 'unreachable'}.`; } if (!topo.nodes.length) { - return `No process-conversation data for ${service} (${scope}) — network/eBPF profiling needs a Rover eBPF agent, and none reported in that scope. Tell the user network profiling is unavailable here.`; + // An empty graph is NOT proof of a missing agent. A network task runs + // a server-fixed 10 minutes, so the common sequence — approve, then + // analyze a minute later — legitimately reads a graph that has not + // been populated yet. Say what was actually read and let the elapsed + // window decide; only a task well past its window says anything about + // the deployment. + const waiting = r.taskId + ? ` If this task was created within the last ~10 minutes it is still collecting — say that and analyze again after its window, do NOT conclude anything about the deployment yet.` + : ''; + return `No process-conversation data for ${service} (${scope}).${waiting} If the window has fully elapsed and the graph is still empty, THEN the likely cause is that no Rover eBPF agent is reporting processes for this service — report that as the likely cause, not as a certainty.`; } ctx.emitProcessTopology({ title: `Network profiling — ${service} · ${scope}`, diff --git a/apps/bff/src/http/query/ebpf.ts b/apps/bff/src/http/query/ebpf.ts index 028168a..2282cbc 100644 --- a/apps/bff/src/http/query/ebpf.ts +++ b/apps/bff/src/http/query/ebpf.ts @@ -446,10 +446,14 @@ export function registerEBPFRoutes(app: FastifyInstance, deps: EBPFRouteDeps): v payload.errorReason = `duration is required and must be ${MIN_EBPF_DURATION_SEC}..${MAX_EBPF_DURATION_SEC} seconds`; return reply.send(payload); } + // Absent or <= 0 means ASAP, per OAP's schema — pass the sentinel through + // rather than substituting a clock. Stamping our own `Date.now()` here + // made the task start relative to the BFF's clock, which OAP then compares + // against its own; ASAP has no clock to disagree about. const startTime = typeof raw.startTime === 'number' && Number.isFinite(raw.startTime) && raw.startTime > 0 ? Math.round(raw.startTime) - : Date.now(); + : 0; const sanitised: EBPFTaskCreationRequest = { serviceId: raw.serviceId, processLabels: sanitiseProcessLabels(raw.processLabels), diff --git a/apps/bff/src/logic/oap/profiling.ts b/apps/bff/src/logic/oap/profiling.ts index 18a4e56..fbe31e4 100644 --- a/apps/bff/src/logic/oap/profiling.ts +++ b/apps/bff/src/logic/oap/profiling.ts @@ -103,6 +103,12 @@ const ASYNC_EVENT_TO_JFR: Record<string, string[]> = { // take the slowest segments first so the busiest call paths dominate the flame. const MAX_TRACE_ANALYZE_QUERIES = 100; +// OAP's EBPFProfilingAnalyzer.FETCH_DATA_DURATION — the chunk size it splits +// every submitted eBPF time range into. Ours only has to MATCH it to budget the +// fan-out; OAP still does the splitting. +const EBPF_CHUNK_MS = 10_000; +const MAX_EBPF_ANALYZE_CHUNKS = 600; + const LIST_SERVICES_FOR_RESOLVE = /* GraphQL */ ` query ListServicesForProfilingResolve($layer: String!) { services: listServices(layer: $layer) { id name normal } @@ -884,8 +890,27 @@ async function analyzeEbpf( QUERY_EBPF_SCHEDULES, { taskId: task.taskId }, ); - const schedules = sc.schedules ?? []; - if (!schedules.length) return base; // task exists but no schedules collected yet + const allSchedules = sc.schedules ?? []; + if (!allSchedules.length) return base; // task exists but no schedules collected yet + // OAP splits every submitted range into 10-second chunks (FETCH_DATA_DURATION) + // and fetches them in parallel under one deadline; a chunk that misses the + // deadline is caught, logged and returned EMPTY, and the eBPF analyzer never + // sets `tip`. So an over-wide request degrades into a silently partial flame + // presented as the whole profile. Bound what we ask for — most recent + // schedules first, since those are the ones an investigation is about — and + // say so when we drop any, rather than letting OAP drop them invisibly. + const byRecency = [...allSchedules].sort((a, b) => (b.startTime ?? 0) - (a.startTime ?? 0)); + const schedules: typeof byRecency = []; + let chunks = 0; + for (const s of byRecency) { + const cost = Math.max(1, Math.ceil(((s.endTime ?? 0) - (s.startTime ?? 0)) / EBPF_CHUNK_MS)); + if (chunks + cost > MAX_EBPF_ANALYZE_CHUNKS && schedules.length) break; + schedules.push(s); + chunks += cost; + } + if (schedules.length < allSchedules.length) { + base.tip = `analyzed the ${schedules.length} most recent of ${allSchedules.length} profiling schedules — the full range exceeds what OAP can fetch in one analysis`; + } const scheduleIdList = schedules.map((s) => s.scheduleId); const timeRanges = schedules.map((s) => ({ start: s.startTime, end: s.endTime })); // The aggregate type has to follow the TARGET, because OAP gives the same diff --git a/apps/ui/src/ai/ChatProposalBlock.vue b/apps/ui/src/ai/ChatProposalBlock.vue index e6e71de..4d8561c 100644 --- a/apps/ui/src/ai/ChatProposalBlock.vue +++ b/apps/ui/src/ai/ChatProposalBlock.vue @@ -57,8 +57,12 @@ async function fireTask(s: ProposalSpec): Promise<{ ok: boolean; taskId?: string // OAP's endpointName is non-null and rejects an empty string — an endpoint-less // proposal can only fail on create, so fail the card instead of firing it. if (!s.endpoint) return { ok: false, error: t('Trace profiling requires an endpoint, and this proposal carries none.') }; + // No startTime: OAP reads it as "begin AFTER this, on agent-side time" and + // only dispatches tasks starting within ±5 minutes of its OWN clock, so a + // browser wall-clock that drifts (VM resume, no NTP) creates a task that is + // accepted, returns an id, and never runs. Omitting it means ASAP. const r = await bff.profile.create(layer, { - serviceId: s.serviceId, endpointName: s.endpoint, startTime: Date.now(), + serviceId: s.serviceId, endpointName: s.endpoint, duration: mins, minDurationThreshold: 0, dumpPeriod: 10, maxSamplingCount: 5, }); return { ok: r.reachable && !r.errorReason, taskId: r.id, error: r.errorReason ?? r.error }; @@ -79,8 +83,11 @@ async function fireTask(s: ProposalSpec): Promise<{ ok: boolean; taskId?: string return { ok: r.reachable && !r.errorReason, taskId: r.id, error: r.errorReason ?? r.error }; } if (s.profilingType === 'ebpf') { + // 0 is OAP's documented ASAP sentinel ("if less then or equal zero means + // the task starts ASAP") — same reason as trace above: never hand OAP a + // clock we don't own to compare against its own. const r = await bff.ebpf.create(layer, { - serviceId: s.serviceId, processLabels: s.processLabels ?? [], startTime: Date.now(), + serviceId: s.serviceId, processLabels: s.processLabels ?? [], startTime: 0, duration: mins * 60, targetType: s.targetType ?? 'ON_CPU', }); return { ok: r.reachable && r.status && !r.errorReason, taskId: r.id, error: r.errorReason ?? r.error }; diff --git a/packages/api-client/src/profile.ts b/packages/api-client/src/profile.ts index ab5f34e..9f744a9 100644 --- a/packages/api-client/src/profile.ts +++ b/packages/api-client/src/profile.ts @@ -151,7 +151,12 @@ export interface ProfileAnalyzeQuery { export interface ProfileTaskCreationRequest { serviceId: string; endpointName: string; - startTime: number; + /** OMIT to start ASAP. OAP's schema: "if null means the task starts ASAP, + * otherwise the task begin after the startTime(based on agent side time)" — + * so a value here is compared against clocks we do not own (OAP dispatches + * only tasks starting within ±5 minutes of ITS clock). Send one only when + * the caller genuinely means "start later". */ + startTime?: number; duration: number; minDurationThreshold: number; dumpPeriod: number;
