diff --git a/CHANGELOG.md b/CHANGELOG.md index 2ca5288..0c99035 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -13,11 +13,14 @@ _If you are upgrading from 1.x: please see [Migrating from 1.x](README.md#migrat ### Changed - **Breaking:** refuse `execute_anonymous` against production orgs, and orgs whose type cannot be read, unless the run is confirmed via [MCP elicitation](https://modelcontextprotocol.io/specification/2025-06-18/client/elicitation) or `--allow-production-orgs` is set ([#52]) -- **Breaking:** drop `file` from `get_apex_log_summary`, and the prose `summary` from `analyze_apex_log_performance` in favour of the scalar `topMethodsSelfPercentage` ([#86]) -- **Breaking:** report governor limits as a flat `{name, used, limit}` table, and include the limits at zero, so a caller can tell "no DML ran" from "DML was never read" ([#86]) +- **Breaking:** `analyze_apex_log_performance` now ranks every timed operation by self time, not methods alone: code units, managed packages, methods, system methods, queries, searches, DML, flows and workflows, in one table of `{kind, name, namespace, lineNumber, callCount, durationTotalMs, durationSelfMs, selfPercentage, soqlCount, dmlCount, soslCount, rowCount, thrownCount}` rows. `slowestMethods`, `totalMethods`, `totalExecutionTime`, `topMethodsSelfPercentage` and `recommendations` are gone, replaced by `operations`, `durationTotalMs` and `returnedSelfPercentage`. The `topMethods` and `minDuration` parameters are now `limit` and `minSelfMs`, beside new `kind`, `namespace` and `groupBy` parameters that select and fold the rows ([#108]) +- **Breaking:** `find_performance_bottlenecks` now returns one table of the governor limits at risk — `{limit, used, max, usedPercentage}` rows, worst first — beside the `threshold` that selected them. The `cpuBottlenecks`, `databaseBottlenecks`, `methodBottlenecks` and `governorLimitWarnings` sections, the `note`, and the `analysisType` parameter are gone; a new `threshold` parameter sets where a limit becomes worth reporting. All thirteen limits are covered, where the sections covered six, and the response costs 78% less ([#108]) +- **Breaking:** drop `file` from `get_apex_log_summary`, and the prose `summary` from `analyze_apex_log_performance` in favour of a scalar share of the runtime ([#86], [#108]) +- **Breaking:** `get_apex_log_summary` now reports where the time went and what each namespace consumed. `timeByKind` gives `{kind, logCategory, operationCount, durationSelfMs, selfPercentage}` for every kind of operation, and `limitsByNamespace` gives `{namespace, limit, used}` for each limit a namespace consumed, so a managed package that spends your CPU time is visible. `totalMethods`, `totalSOQLQueries`, `totalDMLOperations`, `totalSOQLRows` and `totalDMLRows` are gone, and searches are covered for the first time. `size`, `totalExecutionTime` and `parsingErrors` are now `fileSizeBytes`, `durationTotalMs` and `parsingErrorCount`, beside a new `truncated`. A `debugLevels` row names its `logCategory`, not its `category`, which is the name `timeByKind` uses for the same fact ([#62], [#108]) +- **Breaking:** report governor limits as a flat `{limit, used, max}` table, and include the limits at zero, so a caller can tell "no DML ran" from "DML was never read" ([#86], [#62]) - Make the `execute_anonymous` tool always discoverable, so agents can find it without server flags ([#52]) -- Reduce every tool response with no fact lost: `analyze_apex_log_performance` by 33%, `execute_anonymous` by 30% after the first run, `get_apex_log_summary` by 27% and `find_performance_bottlenecks` by 5% ([#86]) -- Reduce the standing cost of having the server connected by 31%, with no tool renamed, no parameter removed and no response changed: `execute_anonymous` by 49%, `find_performance_bottlenecks` by 12%, `get_apex_log_summary` by 11% and `analyze_apex_log_performance` by 4% ([#87]) +- Reduce every tool response with no fact lost: `analyze_apex_log_performance` by 33% ([#86], [#108]) and `execute_anonymous` by 30% after the first run ([#86]). `get_apex_log_summary` costs 16% more on a log that uses its limits, for the two tables it gained ([#62]) +- Reduce the standing cost of having the server connected by 26%: `execute_anonymous` by 49% and `find_performance_bottlenecks` by 25% ([#87], [#108]). `analyze_apex_log_performance` costs 32% more, for the five parameters that select what it ranks ([#108]) - Parse a log once rather than once per tool, cached by path, inode, size, modification time and change time, so a summary followed by a deeper tool no longer reads and parses the file again. The parse is dropped after five minutes unused, so a large log is not held for the life of the session ([#88]) ### Added @@ -34,8 +37,11 @@ _If you are upgrading from 1.x: please see [Migrating from 1.x](README.md#migrat ### Fixed - Declare `execute_anonymous` destructive, so clients stop treating it as safe to run unprompted ([#52]) -- Stop `analyze_apex_log_performance` reporting that performance looks good on a log that exhausted the CPU limit ([#86]) -- Report the same `totalMethods` from all three analysis tools on an unfiltered call; `get_apex_log_summary` did not count entry points, so it reported fewer methods than the other two ([#88]) +- Warn when a caller-given `execute_anonymous` `outputDir` resolves outside every root the client declared. The log is still written, and the response names where it went ([#109]) +- Close cleanly on `SIGTERM`, so a supervised restart or a container stop no longer kills the server mid-shutdown ([#109]) +- Return an absolute `filePath` from `execute_anonymous`, so the path it hands back is one the analysis tools accept. A relative `outputDir` now anchors to the project root, the same base the default uses ([#109]) +- Refuse a relative `logFilePath` instead of resolving it against the server's working directory, which is where the client spawned the server and not where the caller is ([#109]) +- Name the real cause when a log file cannot be opened. A permission error, a directory in place of a file, or an exhausted descriptor table were all reported as "Log file not found", sending the caller to look for a file that was there ([#109]) ## [1.0.0] - 2026-03-20 @@ -52,6 +58,9 @@ _If you are upgrading from 1.x: please see [Migrating from 1.x](README.md#migrat [#52]: https://github.com/certinia/debug-log-analyzer-mcp/issues/52 +[#62]: https://github.com/certinia/debug-log-analyzer-mcp/issues/62 [#86]: https://github.com/certinia/debug-log-analyzer-mcp/issues/86 [#87]: https://github.com/certinia/debug-log-analyzer-mcp/issues/87 [#88]: https://github.com/certinia/debug-log-analyzer-mcp/issues/88 +[#108]: https://github.com/certinia/debug-log-analyzer-mcp/issues/108 +[#109]: https://github.com/certinia/debug-log-analyzer-mcp/issues/109 diff --git a/CLAUDE.md b/CLAUDE.md index f946245..e9bfe44 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -32,9 +32,9 @@ pnpm start - Uses stdio transport for communication - Handles file validation, log parsing, analysis, and anonymous Apex execution -- **src/tools/responseShaping.ts**: Shared helpers for keeping responses lean — `omitEmpty`, `toLimitRows`, `roundMs`, `roundPercent`, `NS_TO_MS` +- **src/tools/responseShaping.ts**: Shared helpers for keeping responses lean — `omitEmpty`, `toLimitRows`, `toNamespaceLimitRows`, `roundMs`, `roundPercent`, `NS_TO_MS` -- **src/tools/apexLogSource.ts**: The one way the three analysis tools get a log — `loadApexLog` (reads and parses, caching the last parse by path and a fingerprint of everything a stat can see — inode, size, and modification and change time in nanoseconds, so a `cp -p` that keeps the modification time still misses; the file is opened once and both the stat and the read go to that handle, so nothing can put a different file at the path between the two; the slot holds the in-flight promise, so concurrent callers share one parse and a failed read is not kept; it is dropped five minutes after its last use, on an `unref`ed timer, because a parsed log holds four to five times the size of the file), `isMethodNode` (the one method test, so the tools agree on `totalMethods`) and `walkLog` +- **src/tools/apexLogSource.ts**: The one way the three analysis tools get a log — `loadApexLog` (reads and parses, caching the last parse by path and a fingerprint of everything a stat can see — inode, size, and modification and change time in nanoseconds, so a `cp -p` that keeps the modification time still misses; the file is opened once and both the stat and the read go to that handle, so nothing can put a different file at the path between the two; the slot holds the in-flight promise, so concurrent callers share one parse and a failed read is not kept; it is dropped five minutes after its last use, on an `unref`ed timer, because a parsed log holds four to five times the size of the file) and `walkLog` - **src/ApexLogParser.ts**: Complex log parsing engine (33k+ tokens) - Exports `parse()` function and `ApexLogParser` class @@ -45,7 +45,7 @@ pnpm start - `ApexLog`: Root log structure with duration, governor limits, namespaces - `LogLine`: Individual log entries with hierarchical relationships -- `SlowMethod`: Performance analysis result with timing and resource usage +- `Operation`: One timed thing the transaction did, with its timing and resource usage - `GovernorLimits`: Salesforce platform limits tracking ### MCP Integration @@ -81,20 +81,24 @@ dist/ # Compiled JavaScript output The server provides four main capabilities: -1. **Performance Analysis**: Identifies slowest methods with detailed metrics +1. **Performance Analysis**: Ranks every timed operation by self time, with detailed metrics 2. **Log Summary**: High-level execution statistics and governor limit usage 3. **Bottleneck Detection**: Analyzes CPU, database, and method performance patterns 4. **Execute Anonymous**: Executes anonymous Apex code snippets, saves the debug log to a file, and returns a summary with the file path Log analysis tools (1-3) accept absolute file paths to `.log` files and return structured JSON for AI processing. +## Naming + +Every tool, parameter and response field follows the rules in [DEVELOPING.md](DEVELOPING.md#-naming-tools-and-fields) — read them before you add or rename one. In short: prefix every tool `apexlog_`; the verb states the shape of the result (`get_` one, `list_` many, `search_` many matched to a caller query, `create`/`update`/`delete`/`write_` one resource written, `execute`/`run_` an effect outside the server) and the noun states what the result is; `analyze`, `process`, `handle`, `manage`, `find`, `detect`, `check` and `fetch` are banned; fields name the fact and not the calculation, carry their unit (`durationSelfMs`, `fileSizeBytes`), use `total` only for "including children" and `self` only for "excluding them" (so `durationTotalMs` names a log's duration and a row's alike), keep one name per fact across all tools, count as `Count`, fold acronyms in lowerCamel, and state booleans as bare adjectives (`truncated`). + ## Response Shaping -Responses are TOON-encoded and deliberately lean, but the saving comes from shape, never from dropping a fact — see the conventions in [DEVELOPING.md](DEVELOPING.md#️-shaping-tool-responses) and the helpers in `src/tools/responseShaping.ts`. In short: restructure before you delete (flatten nested objects into TOON tables — `toLimitRows` is the worked example, 45% cheaper than the nested form and still complete); always report a fixed-schema field even at zero, because an absent count cannot be told apart from one that was never parsed; use `omitEmpty` **only** for occurrence lists, where absence unambiguously means nothing happened; never report the same figure twice; never echo the caller's input back; round durations and percentages (`roundMs`/`roundPercent`); and keep every row of a table on the same key set so TOON keeps its one-header-plus-one-line-per-row form. +Responses are TOON-encoded and deliberately lean, but the saving comes from shape, never from dropping a fact — see the conventions in [DEVELOPING.md](DEVELOPING.md#️-shaping-tool-responses) and the helpers in `src/tools/responseShaping.ts`. In short: restructure before you delete (flatten nested objects into TOON tables — `toLimitRows` is the worked example, 45% cheaper than the nested form and still complete); always report a fixed-schema field even at zero, because an absent count cannot be told apart from one that was never parsed; use `omitEmpty` **only** for occurrence lists, where absence unambiguously means nothing happened; never report the same figure twice; never state what the caller can derive from the numbers beside it; never echo the caller's input back; round durations and percentages (`roundMs`/`roundPercent`); and keep every row of a table on the same key set so TOON keeps its one-header-plus-one-line-per-row form. -Concretely: `analyze_apex_log_performance` returns no prose `summary` — its one unique fact is the scalar `topMethodsSelfPercentage` — and omits `recommendations` only when nothing stands out; `get_apex_log_summary` returns no `file`, all thirteen governor limits as `{name, used, limit}` rows, the full `debugLevels` list, and omits only `logIssues`; `find_performance_bottlenecks` excludes from `governorLimitWarnings` any limit already detailed by a dedicated section; `execute_anonymous` emits the `.gitignore` tip only when it created the output directory. +Concretely: `analyze_apex_log_performance` returns no prose `summary` and no `recommendations` — its one unique fact beside the table is the scalar `returnedSelfPercentage`; `get_apex_log_summary` returns no `file`, all thirteen governor limits as `{limit, used, max}` rows, the limits each namespace consumed as `{namespace, limit, used}` rows, one `timeByKind` row per operation kind carrying the trace category that decides whether the kind was logged, the full `debugLevels` list, and omits only `logIssues`; `find_performance_bottlenecks` returns one `atRisk` table of `{limit, used, max, usedPercentage}` rows and reports it even when empty, beside the `threshold` that selected them, because a selection with no stated cutoff cannot be read; `execute_anonymous` emits the `.gitignore` tip only when it created the output directory. -The same rule governs the **tool definitions**, which every client loads on every turn whether a tool is called or not (`tools/list` is ~1,090 tokens for the four tools). Say each thing once: an enum already lists its values, so a `.describe()` must not repeat them — this is why `debugLevel` is one `z.partialRecord(z.enum(TRACE_CATEGORIES), z.enum(LOG_LEVELS))` with a single description rather than ten per-category properties, and why `LOG_LEVELS` and `TRACE_CATEGORIES` live only in `src/salesforce/debugLevels.ts`. A description earns its tokens only if the agent acts on it: response-shaping policy is a contributor fact and belongs here and in DEVELOPING.md, not on the wire. Set `title` at the top level only — `annotations.title` is a duplicate alias and is sent twice. Anything true of every tool (durations are milliseconds, which tool to start with) goes in the server `instructions` once. +The same rule governs the **tool definitions**, which every client loads on every turn whether a tool is called or not (`tools/list` is ~1,020 tokens for the four tools). Say each thing once: an enum already lists its values, so a `.describe()` must not repeat them — this is why `debugLevel` is one `z.partialRecord(z.enum(TRACE_CATEGORIES), z.enum(LOG_LEVELS))` with a single description rather than ten per-category properties, and why `LOG_LEVELS` and `TRACE_CATEGORIES` live only in `src/salesforce/debugLevels.ts`. A description earns its tokens only if the agent acts on it: response-shaping policy is a contributor fact and belongs here and in DEVELOPING.md, not on the wire. Set `title` at the top level only — `annotations.title` is a duplicate alias and is sent twice. Anything true of every tool (durations are milliseconds, which tool to start with) goes in the server `instructions` once. `pnpm run eval` (`scripts/eval.mjs`, wired into CI) is the gate for response-shape changes: it drives the built server over stdio against `tests/eval/fixtures/` and checks answerability, no duplication, a token budget and golden files. Once per run it also budgets the tool definitions — see [Shaping Tool Definitions](DEVELOPING.md#️-shaping-tool-definitions) — and regenerates both token cost tables in `README.md`, between the `` and `` markers, so any change that moves a published figure fails until the README is regenerated with it. The jest suite cannot do this — `moduleNameMapper` swaps `@toon-format/toon` for a JSON stand-in, so it never sees the real encoding. Re-record goldens with `pnpm run build && pnpm run eval:update` and read the diff. diff --git a/DEVELOPING.md b/DEVELOPING.md index 3a42cc4..268508d 100644 --- a/DEVELOPING.md +++ b/DEVELOPING.md @@ -12,9 +12,10 @@ Welcome to the development guide for the **Apex Log MCP Server**. This document 2. [Setting Up the Development Environment](#-setting-up-the-development-environment) 3. [Building](#-building) 4. [Running the Server Locally](#-running-the-server-locally) -5. [Shaping Tool Responses](#️-shaping-tool-responses) -6. [Shaping Tool Definitions](#️-shaping-tool-definitions) -7. [Testing Your Changes](#-testing-your-changes) +5. [Naming Tools and Fields](#-naming-tools-and-fields) +6. [Shaping Tool Responses](#️-shaping-tool-responses) +7. [Shaping Tool Definitions](#️-shaping-tool-definitions) +8. [Testing Your Changes](#-testing-your-changes) ## 🔧 Prerequisites @@ -108,6 +109,60 @@ Once you’ve built the server or run the watcher, you can run the MCP server fo To disable Apex execution altogether, use `--no-apex-execution`. See the [README](README.md#production-safety) for the full policy. +## 🔤 Naming Tools and Fields + +A name has to be decidable: for any new tool or field, exactly one name follows from these rules. The +reader is an agent that cannot ask what a name means. + +### Prefix every tool with `apexlog_` + +Unprefixed names collide across servers. `get_issue` and `list_issues` ship in both the GitHub and the +Sentry server; `search_files` and `read_file` in both Filesystem and Google Drive. A client with two of +those loaded cannot tell them apart. + +One unbroken unit — `apexlog_`, not `apex_log_`, as `slack_` is — so the boundary between the namespace +and the verb is visible. + +### The verb states the shape of the result + +The result is what the caller plans around. The work is invisible to it. + +| Verb | The caller gets back | +| --- | --- | +| `get_` | exactly one thing, identified by the input | +| `list_` | a collection; filters, thresholds and ranking are allowed | +| `search_` | a collection matched to a query the caller supplies | +| `create_` / `update_` / `delete_` / `write_` | one resource, written | +| `execute_` / `run_` | an effect outside this server | + +A filter does not make it a `search_` — Sentry's `list_issues` and GitHub's `list_pull_requests` both +take filters. `search_` is for a caller's query string. + +Banned: `analyze`, `process`, `handle` and `manage`, because they name work, so two tools can both +claim them; `find`, `detect`, `check` and `fetch`, because they are synonyms of the verbs above. + +The noun states what the result is, in the caller's words: `slow_operations`, not `timed_nodes`. + +A bare noun (`apexlog_summary`) is shorter, and `git_status` shows it can work — but only because git's +subcommands *are* its vocabulary, so `status` reads as a verb there. Ours is not, and a bare noun +cannot say whether one thing or many come back. + +### Fields + +1. **Name the fact, not the calculation**: `returnedSelfPercentage`, not `coveredSelfPercentage`. +2. **Carry the unit** when the type cannot: `durationSelfMs`, `fileSizeBytes`. +3. **`total` always means "including children", `self` always means "excluding them".** Never "summed + across rows". A log's duration *is* its root frame's, so `durationTotalMs` names it at every scope, + and the parser's own `duration.total` / `duration.self` reach the wire unrenamed. +4. **One name per fact, in every tool.** A word may still serve two unrelated facts where position + prevents confusion: `limit` is both the input row count and the column naming which governor limit + a row is about. +5. **Counts are `Count`**: `soqlCount`, `dmlRowCount`. Not `totalX`, not a plural alone. +6. **lowerCamel, acronyms folded**: `soqlCount`. +7. **Booleans are bare adjectives that read true**: `truncated`, `succeeded`. No `isX`, no `hasX`. +8. **An input names what it limits, on the axis it acts on**: `limit`, `minSelfMs`. `minDuration` + filtered on total time while the ranking used self time, and the name hid it. + ## ✂️ Shaping Tool Responses Every token a tool returns is a token the agent cannot spend on reasoning, so responses are kept as @@ -124,11 +179,17 @@ it, and it costs nothing. Measured on the 13 governor limits of a real 19 MB log | --- | --- | --- | | Nested objects, all 13 | ~151 | yes | | Nested objects, `used > 0` only | ~42 | **no** | -| **Flat table (`{name, used, limit}`), all 13** | **~84** | yes | +| **Flat table (`{limit, used, max}`), all 13** | **~84** | yes | The flat table is 45% cheaper than the nested form *and* complete. Deleting the zero rows buys 42 more tokens and costs the answer, so we don't. `toLimitRows` is the helper that does this. +Per-namespace usage is the exception that proves the rule. `toNamespaceLimitRows` reports only the +limits a namespace consumed, because there a row *is* an occurrence: whether a limit was measured at +all is a property of the transaction, which the whole-log table already answers, so a namespace with +no row for a limit consumed none of it. It states no ceiling either — the parser keeps one ceiling +per limit for the whole transaction, and it is already in `governorLimits`. + ### The conventions The helpers in [`src/tools/responseShaping.ts`](src/tools/responseShaping.ts) exist to make these @@ -137,13 +198,18 @@ one-liners. - **A fixed-schema field is always reported, even at zero.** The set of governor limits, debug categories and method columns is fixed and known, so a zero is a fact and an absent key is an ambiguity — the reader cannot tell "nothing ran" from "never parsed". Report the zero. -- **Only occurrence lists are omitted when empty** — issues found, recommendations made, errors +- **Only occurrence lists are omitted when empty** — issues found, errors encountered. There, absence is unambiguous: nothing occurred. `omitEmpty` is for these and nothing else; never pass a fixed-schema scalar through it. (`false` is *not* empty — it is an answer.) - **Say it once.** Never restate in prose a figure that is already in a table, and never report a - value in two sections. Recommendations say what to *do*; the numbers stay in the data. Where prose + value in two sections. Where prose carried a fact the table could not, replace it with a scalar rather than deleting it — `topMethodsSelfPercentage` is ~8 tokens where the paragraph it replaced was ~55. +- **Don't state what the caller can derive.** A sentence earns its tokens only if it carries a fact the + numbers do not. "No bottlenecks found" follows from an always-present empty list, so the fix is a + complete shape, not a sentence; "High CPU usage — consider optimizing algorithms" follows from the + percentage beside it. Advice built from one column and a hardcoded threshold is a worse copy of what + the agent does anyway, because the agent reads every column. - **Don't echo the input back.** If the caller supplied it (a file path, a flag), it does not belong in the response. - **Round to the precision someone acts on.** `roundMs` for durations (3dp, keeps microsecond diff --git a/README.md b/README.md index bb52f18..40b4397 100644 --- a/README.md +++ b/README.md @@ -68,10 +68,10 @@ Every request carries all four tool definitions, whether or not a tool is called | Tool | Tokens | 1.x | Change | | ------------------------------ | ----------------------------------- | ---------- | -------- | | `execute_anonymous` | ~428 | ~844 | -49% | -| `analyze_apex_log_performance` | ~238 | ~247 | -4% | -| `find_performance_bottlenecks` | ~234 | ~267 | -12% | -| `get_apex_log_summary` | ~153 | ~171 | -11% | -| **Total** | **~1,053** (0.5% of a 200K context) | **~1,529** | **-31%** | +| `analyze_apex_log_performance` | ~326 | ~247 | +32% | +| `find_performance_bottlenecks` | ~201 | ~267 | -25% | +| `get_apex_log_summary` | ~172 | ~171 | +1% | +| **Total** | **~1,127** (0.6% of a 200K context) | **~1,529** | **-26%** | @@ -83,12 +83,12 @@ The input side is the same for every analysis tool — a tool name and a log fil | Tool | Log | Response | 1.x | Change | | ------------------------------ | -------------------- | -------- | ---- | ------ | -| `get_apex_log_summary` | `governor-heavy.log` | ~220 | ~293 | -25% | -| `get_apex_log_summary` | `minimal.log` | ~174 | ~249 | -30% | -| `analyze_apex_log_performance` | `governor-heavy.log` | ~278 | ~408 | -32% | -| `analyze_apex_log_performance` | `minimal.log` | ~121 | ~190 | -36% | -| `find_performance_bottlenecks` | `governor-heavy.log` | ~79 | ~84 | -6% | -| `find_performance_bottlenecks` | `minimal.log` | ~30 | ~30 | 0% | +| `get_apex_log_summary` | `governor-heavy.log` | ~341 | ~293 | +16% | +| `get_apex_log_summary` | `minimal.log` | ~238 | ~249 | -4% | +| `analyze_apex_log_performance` | `governor-heavy.log` | ~275 | ~408 | -33% | +| `analyze_apex_log_performance` | `minimal.log` | ~87 | ~190 | -54% | +| `find_performance_bottlenecks` | `governor-heavy.log` | ~21 | ~84 | -75% | +| `find_performance_bottlenecks` | `minimal.log` | ~6 | ~30 | -80% | @@ -96,28 +96,36 @@ The input side is the same for every analysis tool — a tool name and a log fil All tools return [TOON](https://github.com/toon-format/toon)-encoded data, kept deliberately lean to save tokens — without dropping anything you might need to ask about. See [Token Cost](#token-cost) for what that is worth in practice. -- **Every governor limit, debug category and method column is returned**, including the ones at zero. "How many DML statements did this consume?" is answerable from the response, and `0` means none rather than not measured. +- **Every governor limit, debug category and operation column is returned**, including the ones at zero. "How many DML statements did this consume?" is answerable from the response, and `0` means none rather than not measured. - **The leanness comes from shape.** Data that used to be nested objects is returned as flat tables, which TOON encodes as one header plus one line per row. -- **Nothing is reported twice.** No prose summary restates the numbers in the table alongside it, and a governor limit detailed in its own section is not repeated in the generic warnings. +- **Nothing is reported twice.** No prose summary restates the numbers in the table alongside it, and no figure appears in two places. - **Durations are rounded** to 3 decimal places (ms) and percentages to 1. -- **Only lists of things that happened are omitted when empty** — log issues, recommendations. Nothing to report means the key is absent. +- **Only lists of things that happened are omitted when empty** — log issues. Nothing to report means the key is absent. ### analyze_apex_log_performance -Rank methods in an Apex debug log by self-execution time. Returns method names, durations (in ms), SOQL/DML counts, and optimization recommendations. Best for finding which specific methods to optimize. +Rank what an Apex debug log spent its time on by self-execution time — code units, managed packages, methods, queries, searches, DML, flows and workflows in one table, each row with its calls, durations (in ms), database counts and rows. Best for finding what to optimize. -| Parameter | Type | Required | Description | -| ------------- | ------ | -------- | ----------------------------------------------------------------- | -| `logFilePath` | string | Yes | Absolute path to the Apex debug log file (.log) | -| `topMethods` | number | No | Number of slowest methods to return (default: 10) | -| `minDuration` | number | No | Minimum duration in milliseconds to include a method (default: 0) | -| `namespace` | string | No | Filter methods by namespace | +Rows are `{kind, name, namespace, lineNumber, callCount, durationTotalMs, durationSelfMs, selfPercentage, soqlCount, dmlCount, soslCount, rowCount, thrownCount}`, beside the transaction's `durationTotalMs` and the `returnedSelfPercentage` the returned rows account for between them. + +`kind` is one of `codeUnit`, `managedPackage`, `method`, `systemMethod`, `soql`, `sosl`, `dml`, `flow` or `workflow`. A `managedPackage` row is the time a package spent where the log shows nothing, and is often most of a transaction. + +| Parameter | Type | Required | Description | +| ------------- | ------ | -------- | ------------------------------------------------------- | +| `logFilePath` | string | Yes | Absolute path to the Apex debug log file (.log) | +| `kind` | string | No | Rank only operations of this kind | +| `namespace` | string | No | Rank only this namespace | +| `minSelfMs` | number | No | Drop operations below this self time (default: 0) | +| `limit` | number | No | Rows to return (default: 10) | +| `groupBy` | string | No | Fold repeats into one row per `name` or per `namespace` | ### get_apex_log_summary -Get a high-level summary of an Apex debug log including total execution time (in ms), method count, SOQL/DML totals, governor limits, debug levels and active namespaces. Best for a quick overview before deeper analysis. +Get a high-level summary of an Apex debug log: how long the transaction ran (in ms), where the time went by kind of operation, every governor limit it and each namespace consumed, the debug levels it was logged at, and whether the log is complete. Best for a quick overview before deeper analysis. -All thirteen governor limits are listed as `{name, used, limit}` rows, at zero included, so you can ask what a transaction consumed and get an answer either way. `debugLevels` names every log category and its level, which is what tells you whether a missing detail was absent from the run or simply never logged. +All thirteen governor limits are listed as `{limit, used, max}` rows, at zero included, so you can ask what a transaction consumed and get an answer either way. `limitsByNamespace` adds `{namespace, limit, used}` rows for each limit a namespace consumed, which is how you see that a managed package spent your CPU time; it names no ceiling, because the parser keeps one ceiling per limit for the whole transaction and it is already in `governorLimits`. + +`timeByKind` gives `{kind, logCategory, operationCount, durationSelfMs, selfPercentage}` for every kind `analyze_apex_log_performance` ranks. `logCategory` is the trace category that decides whether the kind reaches the log at all, so a zero can be read: `soql 0` beside `DB NONE` in `debugLevels`, whose rows are `{logCategory, level}`, means the queries were not logged, and beside `DB FINEST` it means none ran. | Parameter | Type | Required | Description | | ------------- | ------ | -------- | ----------------------------------------------- | @@ -125,21 +133,14 @@ All thirteen governor limits are listed as `{name, used, limit}` rows, at zero i ### find_performance_bottlenecks -Check whether an Apex log transaction is approaching governor limits (flags usage above 80%). Analyzes CPU time, SOQL/DML limits, query rows, and method execution patterns by namespace. Best for checking if a transaction is at risk of hitting governor limits. - -| Parameter | Type | Required | Description | -| -------------- | ------ | -------- | ---------------------------------------------------- | -| `logFilePath` | string | Yes | Absolute path to the Apex debug log file (.log) | -| `analysisType` | string | No | Type of analysis (default: `all`). See values below. | +List the governor limits an Apex log transaction has nearly consumed — CPU time, heap, SOQL and SOSL queries, DML statements, and the rows each returned or wrote — worst first, with how much of each was used. Best for checking whether a transaction is at risk of failing on a limit. -**`analysisType` values:** +Rows are `{limit, used, max, usedPercentage}`. The `threshold` that produced them is reported alongside, so an empty table reads as "nothing is that far consumed" rather than as a missing answer. -| Value | Description | -| ---------- | ------------------------------------------------------ | -| `cpu` | Checks CPU time governor limit | -| `database` | Checks SOQL query, DML statement, and query row limits | -| `methods` | Groups methods by namespace with duration totals | -| `all` | Runs all three analysis types (default) | +| Parameter | Type | Required | Description | +| ------------- | ------ | -------- | ---------------------------------------------------------------- | +| `logFilePath` | string | Yes | Absolute path to the Apex debug log file (.log) | +| `threshold` | number | No | Report a limit once it is this percentage consumed (default: 80) | ### execute_anonymous @@ -255,7 +256,7 @@ This server implements the [Model Context Protocol (MCP)](https://modelcontextpr - **Runs as a local process** — your AI client spawns the server and communicates locally. No network requests, no API keys. - **Uses the same parser as the [Apex Log Analyzer VS Code extension](https://github.com/certinia/debug-log-analyzer)** — battle-tested parsing of the Apex debug log format. -- **Returns structured data** — all durations in milliseconds, governor limits as used/limit pairs, methods with SOQL/DML counts — so your AI assistant can reason about the results. +- **Returns structured data** — all durations in milliseconds, governor limits as used/max rows, operations with SOQL/DML counts — so your AI assistant can reason about the results. - **Keeps responses lean** — TOON encoding, no duplicated figures, and zero/empty fields omitted, so more of the context window is left for reasoning. - **Parses a log once, not once per tool** — a summary followed by a deeper analysis of the same file reuses the parse, so a large log is read and parsed one time. diff --git a/scripts/eval.mjs b/scripts/eval.mjs index dcd5f04..471e1e3 100644 --- a/scripts/eval.mjs +++ b/scripts/eval.mjs @@ -60,7 +60,6 @@ const ANSWERABILITY = { get_apex_log_summary: [ { question: "How many DML statements and SOQL queries were consumed?", - fields: ["totalDMLOperations", "totalSOQLQueries"], limits: ["dmlStatements", "soqlQueries"], }, { @@ -68,26 +67,47 @@ const ANSWERABILITY = { limits: ["cpuTime", "heapSize", "queryRows", "dmlRows"], }, { - question: "How long did the transaction take, and how much code ran?", - fields: ["totalExecutionTime", "totalMethods", "size"], + question: "Which searches and future calls did it use?", + limits: ["soslQueries", "futureCalls"], + }, + { + question: "Which namespace consumed the limits?", + keys: ["limitsByNamespace"], + }, + { + question: "How long did the transaction take, and how big is the log?", + fields: ["durationTotalMs", "fileSizeBytes"], + }, + { + question: "Where did the time go — methods, queries or a managed package?", + keys: ["timeByKind"], + columns: ["kind", "operationCount", "durationSelfMs"], }, { question: "Is detail missing because a log category was switched off?", keys: ["debugLevels"], + columns: ["logCategory", "level"], + }, + { + question: "Did the log parse cleanly, and did it capture the whole run?", + fields: ["parsingErrorCount"], + keys: ["truncated"], }, - { question: "Did the log parse cleanly?", fields: ["parsingErrors"] }, { question: "Which namespaces ran?", keys: ["namespaces"] }, ], analyze_apex_log_performance: [ - { question: "Which methods are the slowest?", keys: ["slowestMethods"] }, + { question: "What did the transaction spend its time on?", keys: ["operations"] }, + { + question: "Was it a method, a query, a search or DML?", + columns: ["kind", "callCount"], + }, { - question: "What share of the runtime do those methods account for?", - fields: ["topMethodsSelfPercentage", "totalExecutionTime"], + question: "What share of the runtime do those operations account for?", + fields: ["returnedSelfPercentage", "durationTotalMs"], }, - { question: "How many methods were considered?", fields: ["totalMethods"] }, { - question: "Did any of the slowest methods touch the database?", - columns: ["dmlCount", "soqlCount", "dmlRows", "soqlRows"], + question: "Did any of them touch the database, and how much did they move?", + columns: ["dmlCount", "soqlCount", "soslCount", "rowCount"], }, { question: "Where in the code are they, and whose namespace are they in?", @@ -96,14 +116,12 @@ const ANSWERABILITY = { ], find_performance_bottlenecks: [ { - question: "Is anything over or near a limit, and what should I look at?", - anyKey: [ - "cpuBottlenecks", - "databaseBottlenecks", - "methodBottlenecks", - "governorLimitWarnings", - "note", - ], + question: "Is any governor limit nearly consumed?", + keys: ["atRisk"], + }, + { + question: "How near does a limit have to be to appear here?", + fields: ["threshold"], }, ], }; @@ -120,13 +138,7 @@ const ANSWERABILITY = { */ const MINIMAL_ZEROS = { get_apex_log_summary: { - fields: [ - "totalSOQLQueries", - "totalDMLOperations", - "totalSOQLRows", - "totalDMLRows", - "parsingErrors", - ], + fields: ["parsingErrorCount"], allLimitsZero: true, }, }; @@ -138,12 +150,15 @@ const MINIMAL_ZEROS = { * than a surprise failure. */ const TOKEN_BUDGET = { - "get_apex_log_summary/governor-heavy": 230, - "get_apex_log_summary/minimal": 185, + // Raised for the two tables #62 added: what each namespace consumed of the + // limits, and where the time went by kind of operation. Both answer questions + // the 1.x summary could not. + "get_apex_log_summary/governor-heavy": 357, + "get_apex_log_summary/minimal": 249, "analyze_apex_log_performance/governor-heavy": 290, "analyze_apex_log_performance/minimal": 130, - "find_performance_bottlenecks/governor-heavy": 85, - "find_performance_bottlenecks/minimal": 35, + "find_performance_bottlenecks/governor-heavy": 40, + "find_performance_bottlenecks/minimal": 15, }; /** @@ -176,9 +191,13 @@ const V1_RESPONSE_TOKENS = { * not a silent tax on every request. */ const DEFINITION_BUDGET = { - analyze_apex_log_performance: 250, - get_apex_log_summary: 161, - find_performance_bottlenecks: 246, + // Raised for the five selection parameters, which the caller acts on: without + // them a ranking over every operation kind can only be read whole. + analyze_apex_log_performance: 338, + // Raised for the two facts the summary gained: per-namespace limit usage, and + // time by kind of operation. + get_apex_log_summary: 180, + find_performance_bottlenecks: 210, execute_anonymous: 449, }; @@ -200,7 +219,7 @@ const TOTAL_DEFINITION_BUDGET = Object.values(V1_DEFINITION_TOKENS).reduce( const SELECTION_KEYWORDS = { analyze_apex_log_performance: ["self-execution time", "optimize"], get_apex_log_summary: ["summary", "overview"], - find_performance_bottlenecks: ["governor limits", "CPU"], + find_performance_bottlenecks: ["governor limits", "CPU time"], execute_anonymous: ["anonymous Apex", "Salesforce org"], }; @@ -313,8 +332,8 @@ function inspect(toon) { if (Number.isFinite(numeric) && /^-?[\d.]+$/.test(value)) { scalars.set(key, numeric); } else { - // Prose at the top level — a `note`, a `recommendations` list, or a - // reintroduced `summary`. Scanned for restated figures below. + // Prose at the top level — a `note`, or a reintroduced `summary`. + // Scanned for restated figures below. strings.push(value); } } diff --git a/src/server.ts b/src/server.ts index 44f6934..6ba1038 100644 --- a/src/server.ts +++ b/src/server.ts @@ -67,7 +67,11 @@ class ApexLogServer { this.server.close(); process.exit(0); }; + // SIGTERM as well as SIGINT. A supervised restart, a container stop, and a + // client that ends a stdio server all send SIGTERM, and Node's default for + // it is to exit without running any of this. process.once("SIGINT", shutdown); + process.once("SIGTERM", shutdown); } private registerTools(): void { diff --git a/src/tools/analyzeLogPerformance.ts b/src/tools/analyzeLogPerformance.ts index fac3bbf..1bfdb19 100644 --- a/src/tools/analyzeLogPerformance.ts +++ b/src/tools/analyzeLogPerformance.ts @@ -3,31 +3,35 @@ */ import { z } from "zod"; -import { ApexLog } from "../ApexLogParser.js"; import { encode } from "@toon-format/toon"; -import { loadApexLog, isMethodNode, walkLog } from "./apexLogSource.js"; +import { loadApexLog, logFilePathSchema } from "./apexLogSource.js"; import { - NS_TO_MS, - omitEmpty, - roundMs, - roundPercent, -} from "./responseShaping.js"; + groupOperations, + listOperations, + OPERATION_KINDS, + type Operation, + type OperationKind, +} from "./operations.js"; +import { NS_TO_MS, roundMs, roundPercent } from "./responseShaping.js"; export const analyzeLogPerformanceInputSchema = { - logFilePath: z - .string() - .describe("Absolute path to the Apex debug log file (.log)"), - topMethods: z - .number() + logFilePath: logFilePathSchema, + kind: z + .enum(OPERATION_KINDS) .optional() - .describe("Number of slowest methods to return (default: 10)"), - minDuration: z + .describe("Rank only operations of this kind"), + namespace: z.string().optional().describe("Rank only this namespace"), + minSelfMs: z .number() .optional() + .describe("Drop operations below this self time (default: 0)"), + limit: z.number().optional().describe("Rows to return (default: 10)"), + groupBy: z + .enum(["name", "namespace"]) + .optional() .describe( - "Minimum duration in milliseconds to include a method (default: 0)", + "Fold repeats into one row per name or per namespace, carrying the calls and the summed time. Ungrouped by default, so each call is its own row.", ), - namespace: z.string().optional().describe("Filter methods by namespace"), }; export type AnalyzeLogArgs = z.infer< @@ -35,9 +39,9 @@ export type AnalyzeLogArgs = z.infer< >; export const analyzeLogPerformanceToolConfig = { - title: "Analyze Apex Log Performance", + title: "List Slow Apex Log Operations", description: - "Rank methods in an Apex debug log by self-execution time. Returns method names, durations, SOQL/DML counts, the share of total runtime the ranked methods account for, and optimization recommendations. Best for finding which specific methods to optimize.", + "Rank what an Apex debug log spent its time on by self-execution time — code units, methods, queries, searches, DML, flows and workflows in one table, each row with its calls, durations, database counts and rows, so the caller can see what to optimize and why.", inputSchema: analyzeLogPerformanceInputSchema, annotations: { readOnlyHint: true, @@ -45,82 +49,94 @@ export const analyzeLogPerformanceToolConfig = { }, }; -export interface SlowMethod { +/** One ranked row, in the units and the order the payload uses. */ +export interface SlowOperation { + kind: OperationKind; name: string; - duration: number; - selfDuration: number; namespace: string; lineNumber: string | number | null; - dmlCount: number; + callCount: number; + durationTotalMs: number; + durationSelfMs: number; + selfPercentage: number; soqlCount: number; - dmlRows: number; - soqlRows: number; - thrownCount: number; + dmlCount: number; soslCount: number; - soslRows: number; - selfPercentage: number; + rowCount: number; + thrownCount: number; } -export interface LogAnalysisResult { - totalMethods: number; - totalExecutionTime: number; +export interface SlowOperationsResult { + durationTotalMs: number; /** - * Share of total execution time the returned methods account for between them. - * A low figure says the cost is spread across the rest of the transaction - * rather than concentrated in these methods — the one thing the table itself - * does not say. + * Share of the transaction the returned rows account for between them. A low + * figure says the cost is spread across everything else rather than + * concentrated here — the one thing the table itself does not say. */ - topMethodsSelfPercentage: number; - slowestMethods: SlowMethod[]; - /** Omitted when nothing stands out; an empty list says the same thing. */ - recommendations?: string[]; + returnedSelfPercentage: number; + operations: SlowOperation[]; } export async function analyzeLogPerformance(args: AnalyzeLogArgs) { - const { logFilePath, topMethods = 10, minDuration = 0, namespace } = args; + const { + logFilePath, + kind, + namespace, + minSelfMs = 0, + limit = 10, + groupBy, + } = args; const apexLog = await loadApexLog(logFilePath); + const durationTotalNs = apexLog.duration.total; + const minSelfNs = minSelfMs * NS_TO_MS; - // Convert ms input to ns for internal filtering - const minDurationNs = minDuration * NS_TO_MS; - - // Extract all methods with their performance data - const methods = extractMethods(apexLog, minDurationNs, namespace); + const selected = listOperations(apexLog).filter( + (operation) => + (!kind || operation.kind === kind) && + (!namespace || operation.namespace === namespace), + ); - // Sort by self duration (descending) - methods.sort((a, b) => b.selfDuration - a.selfDuration); + // Grouped before the threshold, so a query that is slow only because it runs + // four hundred times is kept rather than dropped call by call. + const rows = groupBy ? groupOperations(selected, groupBy) : selected; - // Take top N methods - const slowestMethods = methods.slice(0, topMethods); - - // The column set is spelled out rather than spread so that the compiler fails - // the build if a `SlowMethod` field is ever added without deciding whether it - // belongs on the wire, and so the columns arrive in a readable order. It is a - // fixed set: a zero SOQL count reads as "none" rather than "not measured". - const msMethods: SlowMethod[] = slowestMethods.map((m) => ({ - name: m.name, - duration: roundMs(m.duration / NS_TO_MS), - selfDuration: roundMs(m.selfDuration / NS_TO_MS), - selfPercentage: roundPercent(m.selfPercentage), - namespace: m.namespace, - lineNumber: m.lineNumber, - dmlCount: m.dmlCount, - soqlCount: m.soqlCount, - dmlRows: m.dmlRows, - soqlRows: m.soqlRows, - thrownCount: m.thrownCount, - soslCount: m.soslCount, - soslRows: m.soslRows, + const ranked = rows + // Tested as ">= keep" rather than "< drop": a malformed timestamp parses to + // NaN, which fails both, and such an operation must be dropped, not ranked. + .filter((operation) => operation.durationSelfNs >= minSelfNs) + .sort((a, b) => b.durationSelfNs - a.durationSelfNs) + .slice(0, limit); + + const selfPercentageOf = (operation: Operation) => + durationTotalNs > 0 ? (operation.durationSelfNs / durationTotalNs) * 100 : 0; + + // The column set is spelled out rather than spread, so the compiler fails the + // build if an `Operation` field is added without deciding whether it belongs + // on the wire, and so the columns arrive in a readable order. It is a fixed + // set: a zero SOQL count reads as "none" rather than "not measured". + const operations: SlowOperation[] = ranked.map((operation) => ({ + kind: operation.kind, + name: operation.name, + namespace: operation.namespace, + lineNumber: operation.lineNumber, + callCount: operation.callCount, + durationTotalMs: roundMs(operation.durationTotalNs / NS_TO_MS), + durationSelfMs: roundMs(operation.durationSelfNs / NS_TO_MS), + selfPercentage: roundPercent(selfPercentageOf(operation)), + soqlCount: operation.soqlCount, + dmlCount: operation.dmlCount, + soslCount: operation.soslCount, + rowCount: operation.rowCount, + thrownCount: operation.thrownCount, })); - const result: LogAnalysisResult = { - totalMethods: methods.length, - totalExecutionTime: roundMs(apexLog.duration.total / NS_TO_MS), - topMethodsSelfPercentage: roundPercent( - slowestMethods.reduce((total, m) => total + m.selfPercentage, 0), + const result: SlowOperationsResult = { + durationTotalMs: roundMs(durationTotalNs / NS_TO_MS), + returnedSelfPercentage: roundPercent( + ranked.reduce((total, operation) => total + selfPercentageOf(operation), 0), ), - slowestMethods: msMethods, - ...omitEmpty({ recommendations: generateRecommendations(msMethods) }), + operations, }; return { @@ -132,73 +148,3 @@ export async function analyzeLogPerformance(args: AnalyzeLogArgs) { ], }; } - -export function extractMethods( - apexLog: ApexLog, - minDuration: number, - namespaceFilter?: string, -): SlowMethod[] { - const methods: SlowMethod[] = []; - const totalTime = apexLog.duration.total; - - walkLog(apexLog, (node) => { - if (!isMethodNode(node)) return; - // Tested as ">= keep" rather than "< drop": a malformed timestamp parses to - // NaN, which fails both, and such a method must be dropped, not reported. - if (!(node.duration.total >= minDuration)) return; - if (namespaceFilter && node.namespace !== namespaceFilter) return; - - methods.push({ - name: node.text || "Unknown Method", - duration: node.duration.total, - selfDuration: node.duration.self, - namespace: node.namespace || "default", - lineNumber: node.lineNumber, - dmlCount: node.dmlCount.total, - soqlCount: node.soqlCount.total, - dmlRows: node.dmlRowCount.total, - soqlRows: node.soqlRowCount.total, - thrownCount: node.totalThrownCount, - soslCount: node.soslCount.total, - soslRows: node.soslRowCount.total, - selfPercentage: - totalTime > 0 ? (node.duration.self / totalTime) * 100 : 0, - }); - }); - - return methods; -} - -/** - * Advice for the worst few methods, in the form the caller cannot derive from the - * table: which lever to pull. The figure that triggered each one is already a - * column on the method's row, so it is not repeated here. - * - * An empty list means nothing stood out, which is what omitting the field says. - */ -function generateRecommendations(methods: SlowMethod[]): string[] { - return methods - .slice(0, 3) - .map(getRecommendation) - .filter((recommendation): recommendation is string => recommendation !== null); -} - -function getRecommendation(method: SlowMethod): string | null { - if (method.selfPercentage > 10 && method.selfDuration > 0.1) { - return `${method.name}: dominates self time. Check whether it can be made faster, and how often it is called.`; - } - if (method.soqlRows > 1000) { - return `${method.name}: high SOQL row count. Add WHERE clauses or paginate.`; - } - if (method.soqlCount > 5) { - return `${method.name}: many SOQL queries. Bulkify or cache.`; - } - if (method.dmlCount > 3) { - return `${method.name}: many DML operations. Bulkify them.`; - } - if (method.soslCount > 3) { - return `${method.name}: many SOSL searches. Reduce or cache them.`; - } - - return null; -} diff --git a/src/tools/apexLogSource.ts b/src/tools/apexLogSource.ts index 04efc02..163f062 100644 --- a/src/tools/apexLogSource.ts +++ b/src/tools/apexLogSource.ts @@ -3,13 +3,29 @@ */ import { promises as fs, type BigIntStats } from "fs"; +import { isAbsolute } from "path"; +import { z } from "zod"; import { parse, ApexLog, LogLine, - type LogSubCategory, } from "../ApexLogParser.js"; +/** + * The one declaration of the log path, shared by every tool that takes one, so + * all three enforce it the same way. + * + * A relative path is refused rather than resolved: it would resolve against the + * server's working directory, which is where the client happened to spawn us + * and not where the caller is. Resolving would read a different file, or none, + * and report neither. Refinements do not reach the JSON schema, so this costs + * no tokens in the tool definition — `pnpm run eval` holds that to its budget. + */ +export const logFilePathSchema = z + .string() + .refine(isAbsolute, "must be an absolute path") + .describe("Absolute path to the Apex debug log file (.log)"); + type CachedLog = { path: string; fingerprint: string; @@ -79,9 +95,18 @@ export async function loadApexLog(logFilePath: string): Promise { try { handle = await fs.open(logFilePath, "r"); fingerprint = fingerprintOf(await handle.stat({ bigint: true })); - } catch { + } catch (error) { await handle?.close(); - throw new Error(`Log file not found: ${logFilePath}`); + // A missing file is one of several ways this fails. Reporting all of them + // as "not found" sends the caller to look for a file that is there, when + // the real cause was a permission, a directory in place of a file, or a + // full descriptor table. Name the cause, and keep the original as `cause`. + const code = (error as NodeJS.ErrnoException).code ?? String(error); + const message = + code === "ENOENT" + ? `Log file not found: ${logFilePath}` + : `Cannot read log file ${logFilePath}: ${code}`; + throw new Error(message, { cause: error }); } try { @@ -122,21 +147,6 @@ export function clearApexLogCache(): void { cached = undefined; } -/** - * The units the tools count and rank: entry points and the methods below them. - * Every tool uses this one test, so their method totals agree. - */ -export function isMethodNode(node: LogLine): boolean { - // subCategory is declared on TimedNode, a subclass, so it is read off the - // node rather than tested with instanceof. - const { subCategory } = node as LogLine & { subCategory?: LogSubCategory }; - return ( - node.type === "CODE_UNIT_STARTED" || - node.type === "METHOD_ENTRY" || - subCategory === "Method" - ); -} - /** Visit the node and every node below it, parents first. */ export function walkLog(node: LogLine, visit: (node: LogLine) => void): void { visit(node); diff --git a/src/tools/executeAnonymous.ts b/src/tools/executeAnonymous.ts index 677d4dd..fa2351f 100644 --- a/src/tools/executeAnonymous.ts +++ b/src/tools/executeAnonymous.ts @@ -109,14 +109,51 @@ export function executeAnonymousToolConfig(apexExecutionDisabled = false) { }; } -async function getProjectPath(server: McpServer): Promise { +async function getRootPaths(server: McpServer): Promise { try { const { roots } = await server.server.listRoots(); - const rootUri = roots[0]?.uri; - return rootUri ? new URL(rootUri).pathname : undefined; + return roots.map((root) => new URL(root.uri).pathname); } catch { + return []; + } +} + +/** The resolved path, or the path itself when it does not resolve. */ +async function realPathOrSelf(target: string): Promise { + return fs.realpath(target).catch(() => target); +} + +/** + * The MCP spec expects a server to work inside the roots the client declares, + * and `outputDir` is agent-supplied, so it is the path an injected instruction + * takes. Refusing would break a caller who means to write elsewhere, so say so + * instead: the response names where the log went, and the same line goes to + * stderr for the person watching the server. + * + * Symlinks are followed on both sides, so a link inside a root that points out + * of one is still outside. A client that declares no roots gives nothing to + * compare against, so it stays silent. + */ +async function warnIfOutsideRoots( + outputDir: string, + rootPaths: string[], +): Promise { + if (rootPaths.length === 0) { return undefined; } + + const target = await realPathOrSelf(outputDir); + const roots = await Promise.all(rootPaths.map(realPathOrSelf)); + const inside = roots.some( + (root) => target === root || target.startsWith(root + path.sep), + ); + if (inside) { + return undefined; + } + + const warning = `Debug log written to ${target}, which is outside every root this client declared.`; + console.error(`[apex-log-mcp] ${warning}`); + return warning; } async function getAliasForUsername( @@ -146,7 +183,8 @@ export async function executeAnonymous( return toolError(APEX_EXECUTION_DISABLED_MESSAGE); } - const projectPath = await getProjectPath(server); + const rootPaths = await getRootPaths(server); + const projectPath = rootPaths[0]; const org = await resolveOrg(projectPath, targetOrg); const connection = org.getConnection(); @@ -206,8 +244,14 @@ export async function executeAnonymous( const logId = logRecord.Id; const logBody = await connection.request(`/sobjects/ApexLog/${logId}/Body/`); - const outputDir = - args.outputDir ?? path.join(projectPath ?? process.cwd(), ".apex-log-mcp"); + // Absolute, because `filePath` below goes straight back to the analysis + // tools, which refuse a relative path. A relative `outputDir` anchors to the + // project root, the same base the default uses, rather than to wherever the + // client happened to spawn this server. + const outputDir = path.resolve( + projectPath ?? process.cwd(), + args.outputDir ?? ".apex-log-mcp", + ); // Resolves to the first directory created, or undefined when it already existed, // which is exactly when the .gitignore tip below is worth its tokens. const createdDir = await fs.mkdir(outputDir, { recursive: true }); @@ -216,12 +260,19 @@ export async function executeAnonymous( await fs.writeFile(filePath, logBody as string, "utf-8"); const stats = await fs.stat(filePath); + // Only for a caller-given directory: the default is inside the project root + // by construction, so checking it could only ever say the obvious. + const warning = args.outputDir + ? await warnIfOutsideRoots(outputDir, rootPaths) + : undefined; + return { content: [ { type: "text" as const, text: encode({ filePath, + ...(warning && { warning }), fileSizeBytes: stats.size, org: orgLabel, orgType: classification, diff --git a/src/tools/findPerformanceBottlenecks.ts b/src/tools/findPerformanceBottlenecks.ts index 7a98d3b..e07165c 100644 --- a/src/tools/findPerformanceBottlenecks.ts +++ b/src/tools/findPerformanceBottlenecks.ts @@ -3,21 +3,25 @@ */ import { z } from "zod"; -import { ApexLog } from "../ApexLogParser.js"; -import { type SlowMethod, extractMethods } from "./analyzeLogPerformance.js"; import { encode } from "@toon-format/toon"; -import { loadApexLog } from "./apexLogSource.js"; -import { NS_TO_MS, roundMs, roundPercent } from "./responseShaping.js"; +import type { GovernorLimits } from "../ApexLogParser.js"; +import { loadApexLog, logFilePathSchema } from "./apexLogSource.js"; +import { + percentageOf, + roundPercent, + toLimitRows, +} from "./responseShaping.js"; + +/** Where a limit becomes worth reporting, when the caller names no other. */ +export const WARNING_THRESHOLD = 80; export const findPerformanceBottlenecksInputSchema = { - logFilePath: z - .string() - .describe("Absolute path to the Apex debug log file (.log)"), - analysisType: z - .enum(["cpu", "database", "methods", "all"]) + logFilePath: logFilePathSchema, + threshold: z + .number() .optional() .describe( - "What to check: cpu = the CPU time limit, database = the SOQL query, DML statement and query row limits, methods = duration totals per namespace, all = all three (default).", + `Report a limit once it is this percentage consumed (default: ${WARNING_THRESHOLD})`, ), }; @@ -25,18 +29,27 @@ export type BottleneckArgs = z.infer< z.ZodObject >; -export interface BottleneckResult { - cpuBottlenecks?: Record; - databaseBottlenecks?: Record; - methodBottlenecks?: Record; - governorLimitWarnings?: Record; - note?: string; +export interface LimitRisk { + limit: string; + used: number; + max: number; + usedPercentage: number; +} + +export interface LimitRiskResult { + /** + * What "at risk" meant for this call. The rows are a selection, so without it + * an empty table cannot be told apart from a threshold nothing could reach. + */ + threshold: number; + /** Worst first. Empty means every limit is under the threshold. */ + atRisk: LimitRisk[]; } export const findPerformanceBottlenecksToolConfig = { - title: "Find Performance Bottlenecks", + title: "List Apex Log Limit Risks", description: - "Check whether an Apex log transaction is approaching governor limits (flags usage above 80%). Analyzes CPU time, SOQL/DML limits, query rows, and method execution patterns by namespace. Best for checking if a transaction is at risk of hitting governor limits.", + "List the governor limits an Apex log transaction has nearly consumed — CPU time, heap, SOQL and SOSL queries, DML statements, and the rows each returned or wrote — worst first, with how much of each was used. Best for checking whether a transaction is at risk of failing on a limit.", inputSchema: findPerformanceBottlenecksInputSchema, annotations: { readOnlyHint: true, @@ -44,169 +57,42 @@ export const findPerformanceBottlenecksToolConfig = { }, }; -export const WARNING_THRESHOLD = 80; - export async function findPerformanceBottlenecks(args: BottleneckArgs) { - const { logFilePath, analysisType = "all" } = args; + const { logFilePath, threshold = WARNING_THRESHOLD } = args; const apexLog = await loadApexLog(logFilePath); - const hasCpuSection = analysisType === "cpu" || analysisType === "all"; - - const bottlenecks: BottleneckResult = {}; - - // Limits already spelled out by a dedicated section, so the generic warning - // block does not report them a second time. - const reportedLimits = new Set(); - - if (hasCpuSection) { - const cpu = analyzeCPUBottlenecks(apexLog); - if (Object.keys(cpu).length > 0) { - bottlenecks.cpuBottlenecks = cpu; - reportedLimits.add("cpuTime"); - } - } - - if (analysisType === "database" || analysisType === "all") { - const db = analyzeDatabaseBottlenecks(apexLog); - if (Object.keys(db).length > 0) { - bottlenecks.databaseBottlenecks = db; - Object.keys(db).forEach((limit) => reportedLimits.add(limit)); - } - } - - if (analysisType === "methods" || analysisType === "all") { - const methods = analyzeMethodBottlenecks(apexLog); - if (Object.keys(methods).length > 0) { - bottlenecks.methodBottlenecks = methods; - } - } - - const governorWarnings = analyzeGovernorLimits(apexLog, reportedLimits); - if (Object.keys(governorWarnings).length > 0) { - bottlenecks.governorLimitWarnings = governorWarnings; - } - - if (Object.keys(bottlenecks).length === 0) { - bottlenecks.note = "No bottlenecks or governor limit warnings found."; - } + const result: LimitRiskResult = { + threshold, + atRisk: atRiskLimits(apexLog.governorLimits, threshold), + }; return { content: [ { type: "text" as const, - text: encode(bottlenecks), + text: encode(result), }, ], }; } -function analyzeCPUBottlenecks(apexLog: ApexLog): Record { - const { used, limit } = apexLog.governorLimits.cpuTime; - const cpuUsagePercent = limit > 0 ? (used / limit) * 100 : 0; - - if (cpuUsagePercent > WARNING_THRESHOLD) { - return { - cpuTimeUsed: used, - cpuTimeLimit: limit, - cpuUsagePercentage: roundPercent(cpuUsagePercent), - warning: "High CPU usage - consider optimizing algorithms", - }; - } - - return {}; -} - -function analyzeDatabaseBottlenecks(apexLog: ApexLog): Record { - const governorLimits = apexLog.governorLimits; - const bottlenecks: Record = {}; - - const soqlPercentage = - governorLimits.soqlQueries.limit > 0 - ? (governorLimits.soqlQueries.used / governorLimits.soqlQueries.limit) * - 100 - : 0; - - if (soqlPercentage > WARNING_THRESHOLD) { - bottlenecks.soqlQueries = { - used: governorLimits.soqlQueries.used, - limit: governorLimits.soqlQueries.limit, - percentage: roundPercent(soqlPercentage), - }; - } - - const dmlPercentage = - governorLimits.dmlStatements.limit > 0 - ? (governorLimits.dmlStatements.used / - governorLimits.dmlStatements.limit) * - 100 - : 0; - - if (dmlPercentage > WARNING_THRESHOLD) { - bottlenecks.dmlStatements = { - used: governorLimits.dmlStatements.used, - limit: governorLimits.dmlStatements.limit, - percentage: roundPercent(dmlPercentage), - }; - } - - const queryRowsPercentage = - governorLimits.queryRows.limit > 0 - ? (governorLimits.queryRows.used / governorLimits.queryRows.limit) * 100 - : 0; - - if (queryRowsPercentage > WARNING_THRESHOLD) { - bottlenecks.queryRows = { - used: governorLimits.queryRows.used, - limit: governorLimits.queryRows.limit, - percentage: roundPercent(queryRowsPercentage), - }; - } - - return bottlenecks; -} - -function analyzeMethodBottlenecks(apexLog: ApexLog): Record { - const methods = extractMethods(apexLog, 0); - const methodsByNamespace = methods.reduce( - (acc: Record, method) => { - (acc[method.namespace] ??= []).push(method); - return acc; - }, - {}, - ); - - return { - totalMethods: methods.length, - methodsByNamespace: Object.entries(methodsByNamespace).map(([ns, group]) => ({ - namespace: ns, - methodCount: group.length, - totalDuration: roundMs( - group.reduce((sum: number, m: SlowMethod) => sum + m.duration, 0) / - NS_TO_MS, - ), - })), - }; -} - -function analyzeGovernorLimits( - apexLog: ApexLog, - reportedLimits: Set, -): Record { - const limits = apexLog.governorLimits; - - const result: Record = {}; - - Object.entries(limits).forEach(([key, value]: [string, any]) => { - if (key === "byNamespace") return; - if (reportedLimits.has(key)) return; - if (value.limit > 0) { - const percentage = (value.used / value.limit) * 100; - if (percentage > WARNING_THRESHOLD) { - result[key] = value; - } - } - }); - - return result; +/** + * The limits at or above the threshold, worst first. + * + * A limit with no ceiling is skipped rather than reported at zero: the log did + * not say what it was, so no share of it can be worked out. + */ +function atRiskLimits( + governorLimits: GovernorLimits, + threshold: number, +): LimitRisk[] { + return toLimitRows(governorLimits) + .filter((row) => row.max > 0) + .map((row) => ({ + ...row, + usedPercentage: roundPercent(percentageOf(row.used, row.max)), + })) + .filter((risk) => risk.usedPercentage >= threshold) + .sort((a, b) => b.usedPercentage - a.usedPercentage); } diff --git a/src/tools/getLogSummary.ts b/src/tools/getLogSummary.ts index 20b6ca1..cd4a46f 100644 --- a/src/tools/getLogSummary.ts +++ b/src/tools/getLogSummary.ts @@ -3,20 +3,30 @@ */ import { z } from "zod"; -import { ApexLog } from "../ApexLogParser.js"; import { encode } from "@toon-format/toon"; -import { loadApexLog, isMethodNode, walkLog } from "./apexLogSource.js"; +import type { ApexLog, LogLine } from "../ApexLogParser.js"; +import { loadApexLog, logFilePathSchema } from "./apexLogSource.js"; +import { + listOperations, + logCategoryOf, + OPERATION_KINDS, + type Operation, + type OperationKind, +} from "./operations.js"; import { NS_TO_MS, omitEmpty, + percentageOf, roundMs, + roundPercent, toLimitRows, + toNamespaceLimitRows, + type LimitRow, + type NamespaceLimitRow, } from "./responseShaping.js"; export const getLogSummaryInputSchema = { - logFilePath: z - .string() - .describe("Absolute path to the Apex debug log file (.log)"), + logFilePath: logFilePathSchema, }; export type LogSummaryArgs = z.infer< @@ -26,7 +36,7 @@ export type LogSummaryArgs = z.infer< export const getLogSummaryToolConfig = { title: "Get Apex Log Summary", description: - "Get a high-level summary of an Apex debug log including total execution time, method count, SOQL/DML totals, governor limits, debug levels and active namespaces. Best for a quick overview before deeper analysis.", + "Get a high-level summary of an Apex debug log: how long the transaction ran, where the time went by kind of operation, every governor limit it and each namespace consumed, the debug levels it was logged at, and whether the log is complete. Best for a quick overview before deeper analysis.", inputSchema: getLogSummaryInputSchema, annotations: { readOnlyHint: true, @@ -34,34 +44,63 @@ export const getLogSummaryToolConfig = { }, }; +/** + * Where the transaction's time went, one row per kind of operation. + * + * `logCategory` is the trace category that decides whether the kind reaches the + * log at all, so a zero row can be read against `debugLevels`: `soql 0` beside + * `DB NONE` means the queries were not logged, and beside `DB FINEST` means + * none ran. + */ +interface KindRow { + kind: OperationKind; + logCategory: string; + operationCount: number; + durationSelfMs: number; + selfPercentage: number; +} + +interface LogSummaryResult { + fileSizeBytes: number; + durationTotalMs: number; + /** True when the log ran out before the transaction ended, so it is partial. */ + truncated: boolean; + parsingErrorCount: number; + namespaces: string[]; + debugLevels: { logCategory: string; level: string }[]; + governorLimits: LimitRow[]; + limitsByNamespace: NamespaceLimitRow[]; + timeByKind: KindRow[]; + logIssues?: { type: string; summary: string }[]; +} + export async function getLogSummary(args: LogSummaryArgs) { const { logFilePath } = args; const apexLog = await loadApexLog(logFilePath); + const durationTotalNs = apexLog.duration.total; const logIssues = apexLog.logIssues.map((issue) => ({ type: issue.type, summary: issue.summary, })); - // Every limit and every category is reported, at zero or NONE included: the - // caller has to be able to say "no DML statements ran" and "DB logging was - // off, so that detail is missing" without guessing from what is absent. - const summary = { - size: apexLog.size, - totalExecutionTime: roundMs(apexLog.duration.total / NS_TO_MS), - totalMethods: countMethods(apexLog), - totalSOQLQueries: apexLog.soqlCount.total, - totalDMLOperations: apexLog.dmlCount.total, - totalSOQLRows: apexLog.soqlRowCount.total, - totalDMLRows: apexLog.dmlRowCount.total, - governorLimits: toLimitRows(apexLog.governorLimits), + // Every limit and every kind is reported, at zero included: the caller has to + // be able to say "no DML statements ran" and "DB logging was off, so that + // detail is missing" without guessing from what is absent. + const summary: LogSummaryResult = { + fileSizeBytes: apexLog.size, + durationTotalMs: roundMs(durationTotalNs / NS_TO_MS), + truncated: isTruncated(apexLog), + parsingErrorCount: apexLog.parsingErrors.length, namespaces: apexLog.namespaces, debugLevels: apexLog.debugLevels.map((level) => ({ - category: level.logCategory, + logCategory: level.logCategory, level: level.logLevel, })), - parsingErrors: apexLog.parsingErrors.length, + governorLimits: toLimitRows(apexLog.governorLimits), + limitsByNamespace: toNamespaceLimitRows(apexLog.governorLimits.byNamespace), + timeByKind: timeByKind(listOperations(apexLog), durationTotalNs), ...omitEmpty({ logIssues }), }; @@ -75,12 +114,45 @@ export async function getLogSummary(args: LogSummaryArgs) { }; } -function countMethods(apexLog: ApexLog): number { - let count = 0; - walkLog(apexLog, (node) => { - if (isMethodNode(node)) { - count++; - } +/** + * Whether the log ran out before the transaction ended. + * + * The parser marks the line that lost its exit event, not the log: the root is + * a pseudo node it never terminates, so `apexLog.isTruncated` is always false. + * Truncation propagates up to a top-level line, so those are what is tested. + */ +function isTruncated(apexLog: ApexLog): boolean { + // isTruncated is declared on Method, a subclass, so it is read off the node + // rather than tested with instanceof. A line without one cannot be truncated. + return apexLog.children.some( + (child) => (child as LogLine & { isTruncated?: boolean }).isTruncated, + ); +} + +function timeByKind( + operations: Operation[], + durationTotalNs: number, +): KindRow[] { + // Seeded with every kind, so the loop only ever adds to a row that is there + // and the kinds nothing ran under are still reported, at zero. + const totals = Object.fromEntries( + OPERATION_KINDS.map((kind) => [kind, { operationCount: 0, selfNs: 0 }]), + ) as Record; + + operations.forEach(({ kind, durationSelfNs }) => { + const total = totals[kind]; + total.operationCount += 1; + total.selfNs += durationSelfNs; + }); + + return OPERATION_KINDS.map((kind) => { + const { operationCount, selfNs } = totals[kind]; + return { + kind, + logCategory: logCategoryOf(kind), + operationCount, + durationSelfMs: roundMs(selfNs / NS_TO_MS), + selfPercentage: roundPercent(percentageOf(selfNs, durationTotalNs)), + }; }); - return count; } diff --git a/src/tools/operations.ts b/src/tools/operations.ts new file mode 100644 index 0000000..99c4693 --- /dev/null +++ b/src/tools/operations.ts @@ -0,0 +1,204 @@ +/* + * Copyright (c) 2025 Certinia Inc. All rights reserved. + */ + +import type { ApexLog, LogLine, LogSubCategory } from "../ApexLogParser.js"; +import { walkLog } from "./apexLogSource.js"; + +/** + * What the log spent time on. Every timed node the parser produces falls into + * one of these, so a tool that ranks operations can rank all of them. + * + * This is not the debug log category: `subCategory` is a timeline grouping, and + * `soql` and `dml` both arrive under `DB`. `logCategoryOf` maps a kind back to + * the category that controls whether it was logged at all, so that an absence + * is readable — `soql 0` beside `DB NONE` means "not logged", and beside + * `DB FINEST` means "no queries ran". + */ +export const OPERATION_KINDS = [ + "codeUnit", + "managedPackage", + "method", + "systemMethod", + "soql", + "sosl", + "dml", + "flow", + "workflow", +] as const; + +export type OperationKind = (typeof OPERATION_KINDS)[number]; + +/** The trace category that decides whether a kind reaches the log. */ +const LOG_CATEGORY_BY_KIND: Record = { + codeUnit: "APEX_CODE", + managedPackage: "APEX_CODE", + method: "APEX_CODE", + systemMethod: "SYSTEM", + soql: "DB", + sosl: "DB", + dml: "DB", + flow: "WORKFLOW", + workflow: "WORKFLOW", +}; + +export function logCategoryOf(kind: OperationKind): string { + return LOG_CATEGORY_BY_KIND[kind]; +} + +/** + * One timed thing the transaction did. + * + * Durations stay in the parser's nanoseconds, because a caller that groups rows + * sums them, and rounding before the sum loses more than it saves. + */ +export interface Operation { + kind: OperationKind; + name: string; + namespace: string; + /** Null once rows are grouped, because the calls came from several lines. */ + lineNumber: number | string | null; + /** One, until `groupOperations` folds repeats together. */ + callCount: number; + durationTotalNs: number; + durationSelfNs: number; + soqlCount: number; + dmlCount: number; + soslCount: number; + /** Rows the operation touched: queried, searched, or written. */ + rowCount: number; + thrownCount: number; +} + +/** + * The transaction frame owns no time of its own: ranking it says only that the + * transaction took as long as it took. It carries the `Method` sub-category, so + * a test on sub-category alone counts it as a method and inflates every method + * total. + */ +const FRAME_TYPES = new Set(["EXECUTION_STARTED"]); + +/** + * Two types the sub-category cannot tell apart. + * + * SOSL shares the `SOQL` sub-category, and a search is not a query: it has its + * own governor limit and its own fix. A managed package entry carries `Method`, + * but its self time is the time the package spent where the log shows nothing — + * often most of the transaction, and never a method the caller can open. + */ +const KIND_BY_TYPE: Record = { + SOSL_EXECUTE_BEGIN: "sosl", + ENTERING_MANAGED_PKG: "managedPackage", +}; + +const KIND_BY_SUB_CATEGORY: Record = { + Method: "method", + "System Method": "systemMethod", + "Code Unit": "codeUnit", + DML: "dml", + SOQL: "soql", + Flow: "flow", + Workflow: "workflow", +}; + +function kindOf(node: LogLine): OperationKind | undefined { + if (node.type && FRAME_TYPES.has(node.type)) { + return undefined; + } + + // subCategory is declared on TimedNode, a subclass, so it is read off the + // node rather than tested with instanceof. A node without one is untimed. + const { subCategory } = node as LogLine & { subCategory?: LogSubCategory }; + return ( + (node.type ? KIND_BY_TYPE[node.type] : undefined) ?? + (subCategory ? KIND_BY_SUB_CATEGORY[subCategory] : undefined) + ); +} + +/** + * Flatten the log into the operations it performed, parents before children. + * + * This is the one classification in the server: every tool is a view over this + * list, so no two of them can disagree about what the log contains. + */ +export function listOperations(apexLog: ApexLog): Operation[] { + const operations: Operation[] = []; + + // The children, not the log: the root is a pseudo node the parser adds, and + // it holds the whole transaction as its own time. + const visit = (node: LogLine) => { + const kind = kindOf(node); + if (!kind) { + return; + } + + operations.push({ + kind, + name: node.text || node.type || "Unknown", + namespace: node.namespace || "default", + lineNumber: node.lineNumber, + callCount: 1, + durationTotalNs: node.duration.total, + durationSelfNs: node.duration.self, + soqlCount: node.soqlCount.total, + dmlCount: node.dmlCount.total, + soslCount: node.soslCount.total, + rowCount: + node.soqlRowCount.total + + node.dmlRowCount.total + + node.soslRowCount.total, + thrownCount: node.totalThrownCount, + }); + }; + + apexLog.children.forEach((child) => walkLog(child, visit)); + + return operations; +} + +export type GroupBy = "name" | "namespace"; + +/** + * Fold repeats together, so that a query run four hundred times in a loop is + * one row carrying its four hundred calls rather than four hundred rows the + * ranking pushes apart. + * + * `kind` is part of every key. A namespace that runs both queries and methods + * is two rows rather than one row that has to call itself mixed, and every + * column stays true of every row in it. + */ +export function groupOperations( + operations: Operation[], + by: GroupBy, +): Operation[] { + const groups = new Map(); + + operations.forEach((operation) => { + const label = by === "name" ? operation.name : operation.namespace; + const key = `${operation.kind} ${label}`; + const group = groups.get(key); + + if (!group) { + groups.set(key, { + ...operation, + name: label, + lineNumber: by === "name" ? operation.lineNumber : null, + }); + return; + } + + group.callCount += 1; + group.durationTotalNs += operation.durationTotalNs; + group.durationSelfNs += operation.durationSelfNs; + group.soqlCount += operation.soqlCount; + group.dmlCount += operation.dmlCount; + group.soslCount += operation.soslCount; + group.rowCount += operation.rowCount; + group.thrownCount += operation.thrownCount; + // The calls came from several lines, and naming one of them would say the + // repeats all happened there. + group.lineNumber = null; + }); + + return [...groups.values()]; +} diff --git a/src/tools/responseShaping.ts b/src/tools/responseShaping.ts index 33b4688..53f128a 100644 --- a/src/tools/responseShaping.ts +++ b/src/tools/responseShaping.ts @@ -27,12 +27,23 @@ export function roundPercent(percent: number): number { return Math.round(percent * 10) / 10; } +/** + * A part's share of a whole, as a percentage. + * + * Zero when there is no whole to take a share of, which a log with no stated + * duration and a limit with no stated ceiling both produce. Unrounded, because + * a caller that sums shares must round the sum and not each term. + */ +export function percentageOf(part: number, whole: number): number { + return whole > 0 ? (part / whole) * 100 : 0; +} + /** * Drop the lists that nothing was added to. * - * For occurrence lists only — issues found, recommendations made, errors - * encountered — where an absent key unambiguously means "nothing occurred". The - * signature takes only lists on purpose: a fixed-schema scalar must never go + * For occurrence lists only — issues found, errors encountered — where an + * absent key unambiguously means "nothing occurred". The signature takes only + * lists on purpose: a fixed-schema scalar must never go * through here, because an absent count cannot be told apart from a count that * was never parsed, so a zero is reported as a zero. */ @@ -45,25 +56,56 @@ export function omitEmpty>( } export interface LimitRow { - name: string; + limit: string; used: number; - limit: number; + /** The ceiling the org allows. Zero when the log did not state one. */ + max: number; } /** - * Flatten the parser's governor limits into rows. + * Flatten a set of governor limits into rows. * * All limits are kept, including those at zero — the set is fixed and known, so * a missing row would be a question the caller cannot answer. The saving comes * from the shape: as rows sharing three keys, TOON emits one header plus one * line per limit, which on a real log is a little over half the cost of the same * data as thirteen nested objects. + * + * The one flattener in the server, so no two tools can name a limit differently + * or count a different set of them. `byNamespace` is not a limit and is dropped + * here; `toNamespaceLimitRows` reports it. */ -export function toLimitRows(governorLimits: GovernorLimits): LimitRow[] { - return Object.entries(governorLimits) +export function toLimitRows(limits: Limits | GovernorLimits): LimitRow[] { + return Object.entries(limits) .filter(([name]) => name !== "byNamespace") .map(([name, value]) => { const { used, limit } = value as Limits[keyof Limits]; - return { name, used, limit }; + return { limit: name, used, max: limit }; }); } + +export interface NamespaceLimitRow { + namespace: string; + limit: string; + used: number; +} + +/** + * What each namespace consumed, one row per limit it used. + * + * Only the limits a namespace consumed are reported. A row is an occurrence, + * and whether a limit was measured at all is a property of the transaction, + * which the whole-transaction table already answers — so a namespace with no + * row for a limit consumed none of it. The ceiling is not reported either: the + * parser keeps one per limit for the whole transaction, and it is in that + * table. + */ +export function toNamespaceLimitRows( + byNamespace: Map, +): NamespaceLimitRow[] { + return [...byNamespace].flatMap(([namespace, limits]) => + toLimitRows(limits) + .filter((row) => row.used > 0) + .map(({ limit, used }) => ({ namespace, limit, used })), + ); +} diff --git a/tests/analyzeLogPerformance.test.ts b/tests/analyzeLogPerformance.test.ts index 6be7253..fcf0744 100644 --- a/tests/analyzeLogPerformance.test.ts +++ b/tests/analyzeLogPerformance.test.ts @@ -3,19 +3,18 @@ */ import { promises as fs, type BigIntStats } from "fs"; +import { decode } from "@toon-format/toon"; + import { clearApexLogCache } from "../src/tools/apexLogSource"; import { analyzeLogPerformance, - extractMethods, - AnalyzeLogArgs, - LogAnalysisResult, - analyzeLogPerformanceToolConfig, analyzeLogPerformanceInputSchema, + analyzeLogPerformanceToolConfig, + type AnalyzeLogArgs, + type SlowOperationsResult, } from "../src/tools/analyzeLogPerformance"; -import { parse } from "../src/ApexLogParser"; -import { decode } from "@toon-format/toon"; +import { parse, type ApexLog } from "../src/ApexLogParser"; -// Mock file system operations jest.mock("fs", () => { const stat = jest.fn(); const readFile = jest.fn(); @@ -38,8 +37,8 @@ jest.mock("../src/ApexLogParser", () => ({ parse: jest.fn(), })); -const mockedFs = fs as jest.Mocked; -const mockedParse = parse as jest.MockedFunction; +const mockFs = fs as jest.Mocked; +const mockParse = parse as jest.MockedFunction; const mockStats = { ino: 1n, size: 1n, @@ -47,6 +46,81 @@ const mockStats = { ctimeNs: 1n, } as BigIntStats; +const ARGS: AnalyzeLogArgs = { logFilePath: "/test/file.log" }; +const MS = 1_000_000; + +type NodeSpec = { + type?: string; + subCategory?: string; + text?: string | null; + namespace?: string; + lineNumber?: number | string | null; + totalNs?: number; + selfNs?: number; + soqlCount?: number; + dmlCount?: number; + soslCount?: number; + soqlRowCount?: number; + dmlRowCount?: number; + soslRowCount?: number; + thrownCount?: number; + children?: NodeSpec[]; +}; + +function node(spec: NodeSpec): unknown { + const total = spec.totalNs ?? 0; + return { + type: spec.type ?? null, + ...(spec.subCategory && { subCategory: spec.subCategory }), + text: spec.text ?? null, + namespace: spec.namespace ?? "default", + lineNumber: spec.lineNumber ?? null, + duration: { total, self: spec.selfNs ?? total }, + soqlCount: { total: spec.soqlCount ?? 0, self: 0 }, + dmlCount: { total: spec.dmlCount ?? 0, self: 0 }, + soslCount: { total: spec.soslCount ?? 0, self: 0 }, + soqlRowCount: { total: spec.soqlRowCount ?? 0, self: 0 }, + dmlRowCount: { total: spec.dmlRowCount ?? 0, self: 0 }, + soslRowCount: { total: spec.soslRowCount ?? 0, self: 0 }, + totalThrownCount: spec.thrownCount ?? 0, + children: (spec.children ?? []).map(node), + }; +} + +/** A log whose root is the transaction frame, and which runs `children`. */ +function mockLog(totalNs: number, ...children: NodeSpec[]): void { + mockFs.stat.mockResolvedValue(mockStats); + mockFs.readFile.mockResolvedValue("log content"); + mockParse.mockReturnValue( + node({ + type: "EXECUTION_STARTED", + text: "Root", + totalNs, + children, + }) as ApexLog, + ); +} + +const method = (spec: NodeSpec): NodeSpec => ({ + type: "METHOD_ENTRY", + subCategory: "Method", + ...spec, +}); + +const query = (spec: NodeSpec): NodeSpec => ({ + type: "SOQL_EXECUTE_BEGIN", + subCategory: "SOQL", + soqlCount: 1, + ...spec, +}); + +async function ranked( + args: AnalyzeLogArgs = ARGS, +): Promise { + const result = await analyzeLogPerformance(args); + return decode(result.content[0]!.text) as SlowOperationsResult; +} + describe("analyzeLogPerformance", () => { beforeEach(() => { jest.clearAllMocks(); @@ -55,18 +129,25 @@ describe("analyzeLogPerformance", () => { clearApexLogCache(); }); - describe("Tool Configuration", () => { - it("should have correct tool configuration", () => { + describe("tool configuration", () => { + it("says it ranks by self time, so a client can select it", () => { expect(analyzeLogPerformanceToolConfig.description).toContain( - "Rank methods in an Apex debug log by self-execution time", + "self-execution time", ); - expect(analyzeLogPerformanceInputSchema.logFilePath).toBeDefined(); - expect(analyzeLogPerformanceInputSchema.topMethods).toBeDefined(); - expect(analyzeLogPerformanceInputSchema.minDuration).toBeDefined(); - expect(analyzeLogPerformanceInputSchema.namespace).toBeDefined(); }); - it("should annotate only the hints that carry meaning for a read-only tool", () => { + it("takes every axis a caller narrows the ranking on", () => { + expect(Object.keys(analyzeLogPerformanceInputSchema)).toEqual([ + "logFilePath", + "kind", + "namespace", + "minSelfMs", + "limit", + "groupBy", + ]); + }); + + it("annotates only the hints that carry meaning for a read-only tool", () => { expect(analyzeLogPerformanceToolConfig.annotations).toEqual({ readOnlyHint: true, openWorldHint: false, @@ -74,895 +155,178 @@ describe("analyzeLogPerformance", () => { }); }); - describe("File Validation", () => { - it("should throw error when file does not exist", async () => { - const args: AnalyzeLogArgs = { logFilePath: "/nonexistent/file.log" }; - mockedFs.stat.mockRejectedValue(new Error("File not found")); - - await expect(analyzeLogPerformance(args)).rejects.toThrow( - "Log file not found: /nonexistent/file.log", - ); - - expect(mockedFs.stat).toHaveBeenCalledWith("/nonexistent/file.log", { bigint: true }); - }); - - it("should proceed when file exists", async () => { - const args: AnalyzeLogArgs = { logFilePath: "/valid/file.log" }; - const mockLogContent = "mock log content"; - const mockApexLog = createMockApexLog(); - - mockedFs.stat.mockResolvedValue(mockStats); - mockedFs.readFile.mockResolvedValue(mockLogContent); - mockedParse.mockReturnValue(mockApexLog); - - const result = await analyzeLogPerformance(args); + it("ranks a query alongside a method, slowest self time first", async () => { + mockLog( + 1000 * MS, + method({ text: "A.run", totalNs: 400 * MS }), + query({ text: "SELECT Id", totalNs: 500 * MS }), + ); - expect(mockedFs.stat).toHaveBeenCalledWith("/valid/file.log", { bigint: true }); - expect(mockedFs.readFile).toHaveBeenCalledWith( - "/valid/file.log", - "utf-8", - ); - expect(mockedParse).toHaveBeenCalledWith(mockLogContent); - expect(result.content).toHaveLength(1); - expect(result.content[0].type).toBe("text"); - }); + expect((await ranked()).operations.map((o) => [o.kind, o.name])).toEqual([ + ["soql", "SELECT Id"], + ["method", "A.run"], + ]); }); - describe("Basic Functionality", () => { - it("should analyze log with default parameters", async () => { - const args: AnalyzeLogArgs = { logFilePath: "/test/file.log" }; - const mockApexLog = createMockApexLog(); - - setupMocksForSuccess(mockApexLog); - - const result = await analyzeLogPerformance(args); - const parsedResult = toonDecode(result); - - expect(parsedResult.totalMethods).toBe(3); - expect(parsedResult.totalExecutionTime).toBe(1000); // 1s in ms - expect(parsedResult.slowestMethods).toHaveLength(3); - expect(parsedResult.slowestMethods[0].name).toBe("SlowMethod"); - expect(parsedResult.recommendations).toBeInstanceOf(Array); - }); - - it("should return durations in milliseconds", async () => { - const args: AnalyzeLogArgs = { logFilePath: "/test/file.log" }; - const mockApexLog = createMockApexLog(); - - setupMocksForSuccess(mockApexLog); - - const result = await analyzeLogPerformance(args); - const parsedResult = toonDecode(result); - - expect(parsedResult.slowestMethods[0].duration).toBe(500); // 500ms - expect(parsedResult.slowestMethods[0].selfDuration).toBe(500); // 500ms - expect(parsedResult.slowestMethods[1].duration).toBe(400); // 400ms - expect(parsedResult.slowestMethods[2].duration).toBe(100); // 100ms - }); - - it("should limit results with topMethods parameter", async () => { - const args: AnalyzeLogArgs = { - logFilePath: "/test/file.log", - topMethods: 2, - }; - const mockApexLog = createMockApexLog(); - - setupMocksForSuccess(mockApexLog); - - const result = await analyzeLogPerformance(args); - const parsedResult = toonDecode(result); - - expect(parsedResult.slowestMethods).toHaveLength(2); - expect(parsedResult.slowestMethods[0].name).toBe("SlowMethod"); - expect(parsedResult.slowestMethods[1].name).toBe("MediumMethod"); - }); - - it("should filter by minimum duration in milliseconds", async () => { - const args: AnalyzeLogArgs = { - logFilePath: "/test/file.log", - minDuration: 300, // 300ms - }; - const mockApexLog = createMockApexLog(); - - setupMocksForSuccess(mockApexLog); - - const result = await analyzeLogPerformance(args); - const parsedResult = toonDecode(result); - - expect(parsedResult.totalMethods).toBe(2); // Only SlowMethod and MediumMethod - expect(parsedResult.slowestMethods).toHaveLength(2); - expect( - parsedResult.slowestMethods.every((method) => method.duration >= 300), - ).toBe(true); - }); - - it("should filter by namespace", async () => { - const args: AnalyzeLogArgs = { - logFilePath: "/test/file.log", - namespace: "CustomNamespace", - }; - const mockApexLog = createMockApexLogWithNamespaces(); - - setupMocksForSuccess(mockApexLog); - - const result = await analyzeLogPerformance(args); - const parsedResult = toonDecode(result); - - expect(parsedResult.totalMethods).toBe(1); - expect(parsedResult.slowestMethods).toHaveLength(1); - expect(parsedResult.slowestMethods[0].namespace).toBe("CustomNamespace"); + it("reports durations in milliseconds and the share of the transaction", async () => { + mockLog(1000 * MS, method({ text: "A.run", totalNs: 500 * MS })); + + await expect(ranked()).resolves.toEqual({ + durationTotalMs: 1000, + returnedSelfPercentage: 50, + operations: [ + { + kind: "method", + name: "A.run", + namespace: "default", + lineNumber: null, + callCount: 1, + durationTotalMs: 500, + durationSelfMs: 500, + selfPercentage: 50, + soqlCount: 0, + dmlCount: 0, + soslCount: 0, + rowCount: 0, + thrownCount: 0, + }, + ], }); }); - describe("extractMethods function", () => { - it("should extract methods from log correctly", () => { - const mockApexLog = createMockApexLog(); - const methods = extractMethods(mockApexLog, 0); - - expect(methods).toHaveLength(3); - expect(methods[0].name).toBe("SlowMethod"); - expect(methods[0].duration).toBe(500000000); - expect(methods[0].selfPercentage).toBe(50); - expect(methods[0].dmlCount).toBe(5); - expect(methods[0].soqlCount).toBe(10); - }); - - it("should filter methods by minimum duration in nanoseconds", () => { - const mockApexLog = createMockApexLog(); - const methods = extractMethods(mockApexLog, 300000000); // 300ms in ns - - expect(methods).toHaveLength(2); - expect(methods.every((method) => method.duration >= 300000000)).toBe( - true, - ); - }); - - it("should drop a method whose timestamps did not parse to a number", () => { - const mockApexLog = createMockApexLog(); - mockApexLog.children.push(createMockLogLine("BrokenMethod", NaN, NaN)); - - const methods = extractMethods(mockApexLog, 0); - - expect(methods.map((method) => method.name)).not.toContain( - "BrokenMethod", - ); - }); - - it("should filter methods by namespace", () => { - const mockApexLog = createMockApexLogWithNamespaces(); - const methods = extractMethods(mockApexLog, 0, "CustomNamespace"); - - expect(methods).toHaveLength(1); - expect(methods[0].namespace).toBe("CustomNamespace"); - }); - - it("should handle methods with null or undefined properties", () => { - const mockApexLog = createMockApexLogWithNullValues(); - const methods = extractMethods(mockApexLog, 0); - - expect(methods).toHaveLength(1); - expect(methods[0].name).toBe("Unknown Method"); - expect(methods[0].namespace).toBe("default"); - expect(methods[0].lineNumber).toBeNull(); - }); - - it("should calculate self percentages correctly", () => { - const mockApexLog = createMockApexLog(); - const methods = extractMethods(mockApexLog, 0); - - expect(methods[0].selfPercentage).toBe(50); // 500000000 / 1000000000 * 100 - expect(methods[1].selfPercentage).toBe(40); // 400000000 / 1000000000 * 100 - expect(methods[2].selfPercentage).toBe(10); // 100000000 / 1000000000 * 100 - }); - - it("should extract thrownCount and SOSL metrics from log lines", () => { - const methodWithSOSL = createMockLogLine( - "SOSLMethod", - 500000000, - 500000000, - "default", - 1, - 0, // dmlCount - 0, // soqlCount - 0, // dmlRows - 0, // soqlRows - 5, // soslCount - 250, // soslRows - 3, // totalThrownCount - ); - - const mockApexLog = { - duration: { total: 1000000000, self: 0 }, - children: [methodWithSOSL], - type: "EXECUTION_STARTED", - text: "Root", - namespace: "default", - lineNumber: null, - dmlCount: { total: 0, self: 0 }, - soqlCount: { total: 0, self: 0 }, - dmlRowCount: { total: 0, self: 0 }, - soqlRowCount: { total: 0, self: 0 }, - }; - - const methods = extractMethods(mockApexLog as any, 0); - - expect(methods).toHaveLength(1); - expect(methods[0].thrownCount).toBe(3); - expect(methods[0].soslCount).toBe(5); - expect(methods[0].soslRows).toBe(250); - }); - - it("should handle zero total time", () => { - const mockApexLog = createMockApexLogWithZeroTotalTime(); - const methods = extractMethods(mockApexLog, 0); + it("says what share the returned rows account for, not what is missing", async () => { + mockLog( + 1000 * MS, + method({ text: "A.run", totalNs: 500 * MS }), + method({ text: "B.run", totalNs: 200 * MS }), + ); - expect(methods.every((method) => method.selfPercentage === 0)).toBe(true); - }); + expect((await ranked({ ...ARGS, limit: 1 })).returnedSelfPercentage).toBe( + 50, + ); }); - describe("Edge Cases", () => { - it("should handle empty log gracefully", async () => { - const args: AnalyzeLogArgs = { logFilePath: "/test/file.log" }; - const mockApexLog = createEmptyMockApexLog(); - - setupMocksForSuccess(mockApexLog); - - const result = await analyzeLogPerformance(args); - const parsedResult = toonDecode(result); - - // "No methods were found" is a result, not an absence of one. - expect(parsedResult.totalMethods).toBe(0); - expect(parsedResult.slowestMethods).toEqual([]); - }); - - it("should handle log with no matching methods after filtering", async () => { - const args: AnalyzeLogArgs = { - logFilePath: "/test/file.log", - namespace: "NonExistentNamespace", - }; - const mockApexLog = createMockApexLog(); - - setupMocksForSuccess(mockApexLog); - - const result = await analyzeLogPerformance(args); - const parsedResult = toonDecode(result); - - // The namespace matched nothing, and the empty table is how the caller - // learns that rather than guessing at a missing key. - expect(parsedResult.totalMethods).toBe(0); - expect(parsedResult.slowestMethods).toEqual([]); - }); - - it("should handle parsing errors gracefully", async () => { - const args: AnalyzeLogArgs = { logFilePath: "/test/file.log" }; - - mockedFs.stat.mockResolvedValue(mockStats); - mockedFs.readFile.mockResolvedValue("invalid log content"); - mockedParse.mockImplementation(() => { - throw new Error("Parsing failed"); - }); + it("returns no prose to restate the table", async () => { + mockLog(1000 * MS, method({ text: "A.run", totalNs: 500 * MS })); - await expect(analyzeLogPerformance(args)).rejects.toThrow( - "Parsing failed", - ); - }); - - it("should handle file read errors", async () => { - const args: AnalyzeLogArgs = { logFilePath: "/test/file.log" }; - - mockedFs.stat.mockResolvedValue(mockStats); - mockedFs.readFile.mockRejectedValue(new Error("Permission denied")); - - await expect(analyzeLogPerformance(args)).rejects.toThrow( - "Permission denied", - ); - }); + expect(Object.keys(await ranked())).toEqual([ + "durationTotalMs", + "returnedSelfPercentage", + "operations", + ]); }); - describe("Interface Contracts", () => { - it("should return SlowMethod objects with correct structure", async () => { - const args: AnalyzeLogArgs = { logFilePath: "/test/file.log" }; - const mockApexLog = createMockApexLog(); - - setupMocksForSuccess(mockApexLog); - - const result = await analyzeLogPerformance(args); - const parsedResult = toonDecode(result); - - const method = parsedResult.slowestMethods[0]; - expect(typeof method.name).toBe("string"); - expect(typeof method.duration).toBe("number"); - expect(typeof method.selfDuration).toBe("number"); - expect(typeof method.dmlCount).toBe("number"); - expect(typeof method.soqlCount).toBe("number"); - expect(typeof method.dmlRows).toBe("number"); - expect(typeof method.soqlRows).toBe("number"); - expect(typeof method.selfPercentage).toBe("number"); - expect(["number", "string", "object"]).toContain( - typeof method.lineNumber, - ); - // The column set is fixed, so a zero SOSL count reads as "none ran" rather - // than "not measured", and the shape is the same on every call. - expect(typeof method.namespace).toBe("string"); - expect(typeof method.thrownCount).toBe("number"); - expect(typeof method.soslCount).toBe("number"); - expect(typeof method.soslRows).toBe("number"); - }); - - it("should report the namespace of every method", async () => { - const args: AnalyzeLogArgs = { logFilePath: "/test/file.log" }; - - setupMocksForSuccess(createMockApexLogWithNamespaces()); - - const result = await analyzeLogPerformance(args); - const parsedResult = toonDecode(result); + it("reports zero share when the log recorded no duration", async () => { + mockLog(0, method({ text: "A.run" })); - expect( - parsedResult.slowestMethods.map((method) => method.namespace), - ).toEqual(["default", "CustomNamespace"]); - }); - - it("should return LogAnalysisResult with correct structure", async () => { - const args: AnalyzeLogArgs = { logFilePath: "/test/file.log" }; - const mockApexLog = createMockApexLog(); - - setupMocksForSuccess(mockApexLog); - - const result = await analyzeLogPerformance(args); - const parsedResult = toonDecode(result); - - expect(typeof parsedResult.totalMethods).toBe("number"); - expect(typeof parsedResult.totalExecutionTime).toBe("number"); - expect(typeof parsedResult.topMethodsSelfPercentage).toBe("number"); - expect(Array.isArray(parsedResult.slowestMethods)).toBe(true); - expect(Array.isArray(parsedResult.recommendations)).toBe(true); - }); - - it("should report what share of the run the returned methods account for", async () => { - const args: AnalyzeLogArgs = { logFilePath: "/test/file.log" }; - - setupMocksForSuccess(createMockApexLog()); - - const result = await analyzeLogPerformance(args); - const parsedResult = toonDecode(result); - - // The one thing the table cannot say for itself: whether the cost is - // concentrated in these methods or spread across the rest of the run. - expect(parsedResult.topMethodsSelfPercentage).toBe( - parsedResult.slowestMethods.reduce( - (total: number, method: { selfPercentage: number }) => - total + method.selfPercentage, - 0, - ), - ); - }); - - it("should not restate the table as a prose summary", async () => { - const args: AnalyzeLogArgs = { logFilePath: "/test/file.log" }; - const mockApexLog = createMockApexLog(); + const result = await ranked(); - setupMocksForSuccess(mockApexLog); - - const result = await analyzeLogPerformance(args); - const parsedResult = toonDecode(result); - - // The counts, the worst method and its duration are all already columns, so - // a sentence repeating them is pure duplication. - expect(parsedResult.summary).toBeUndefined(); - }); + expect(result.returnedSelfPercentage).toBe(0); + expect(result.operations[0]?.selfPercentage).toBe(0); }); - describe("Recommendations Generation", () => { - it("should generate SOQL query recommendations", async () => { - const args: AnalyzeLogArgs = { logFilePath: "/test/file.log" }; - const mockApexLog = createMockApexLogWithHighSOQL(); - - setupMocksForSuccess(mockApexLog); - - const result = await analyzeLogPerformance(args); - const parsedResult = toonDecode(result); - - expect(parsedResult.recommendations).toEqual([ - "HighSOQLMethod: many SOQL queries. Bulkify or cache.", - ]); - }); - - it("should generate DML recommendations", async () => { - const args: AnalyzeLogArgs = { logFilePath: "/test/file.log" }; - const mockApexLog = createMockApexLogWithHighDML(); - - setupMocksForSuccess(mockApexLog); - - const result = await analyzeLogPerformance(args); - const parsedResult = toonDecode(result); - - expect(parsedResult.recommendations).toEqual([ - "HighDMLMethod: many DML operations. Bulkify them.", - ]); - }); - - it("should generate SOQL rows recommendations", async () => { - const args: AnalyzeLogArgs = { logFilePath: "/test/file.log" }; - const mockApexLog = createMockApexLogWithHighSOQLRows(); - - setupMocksForSuccess(mockApexLog); - - const result = await analyzeLogPerformance(args); - const parsedResult = toonDecode(result); - - expect(parsedResult.recommendations).toEqual([ - "HighRowsMethod: high SOQL row count. Add WHERE clauses or paginate.", - ]); - }); - - it("should generate high percentage recommendations", async () => { - const args: AnalyzeLogArgs = { logFilePath: "/test/file.log" }; - const mockApexLog = createMockApexLogWithHighPercentage(); - - setupMocksForSuccess(mockApexLog); - - const result = await analyzeLogPerformance(args); - const parsedResult = toonDecode(result); - - // The percentage that triggered this is already a column on the method's row, - // so the advice names the lever and leaves the figure out. - expect(parsedResult.recommendations).toEqual([ - "HighPercentageMethod: dominates self time. Check whether it can be made faster, and how often it is called.", - ]); - }); - - it("should generate SOSL search recommendations", async () => { - const args: AnalyzeLogArgs = { logFilePath: "/test/file.log" }; - const mockApexLog = createMockApexLogWithHighSOSL(); - - setupMocksForSuccess(mockApexLog); - - const result = await analyzeLogPerformance(args); - const parsedResult = toonDecode(result); - - expect(parsedResult.recommendations).toEqual([ - "HighSOSLMethod: many SOSL searches. Reduce or cache them.", - ]); - }); - - it("should omit recommendations entirely when nothing stands out", async () => { - const args: AnalyzeLogArgs = { logFilePath: "/test/file.log" }; - const mockApexLog = createMockApexLogWithGoodPerformance(); + it("ranks only the kind the caller asked for", async () => { + mockLog( + 1000 * MS, + method({ text: "A.run", totalNs: 500 * MS }), + query({ text: "SELECT Id", totalNs: 400 * MS }), + ); - setupMocksForSuccess(mockApexLog); + expect((await ranked({ ...ARGS, kind: "soql" })).operations).toEqual([ + expect.objectContaining({ name: "SELECT Id" }), + ]); + }); - const result = await analyzeLogPerformance(args); - const parsedResult = toonDecode(result); + it("ranks only the namespace the caller asked for", async () => { + mockLog( + 1000 * MS, + method({ text: "A.run", totalNs: 500 * MS }), + method({ text: "B.run", namespace: "Custom", totalNs: 400 * MS }), + ); - // An "all good" sentence costs tokens to say what an absent field already says. - expect(parsedResult.recommendations).toBeUndefined(); - }); + expect( + (await ranked({ ...ARGS, namespace: "Custom" })).operations, + ).toEqual([expect.objectContaining({ name: "B.run" })]); + }); - it("should only analyze top 3 methods for recommendations", async () => { - const args: AnalyzeLogArgs = { - logFilePath: "/test/file.log", - topMethods: 10, - }; - const mockApexLog = createMockApexLogWithManyMethods(); + it("drops an operation below the caller's self time", async () => { + mockLog( + 1000 * MS, + method({ text: "A.run", totalNs: 500 * MS }), + method({ text: "B.run", totalNs: 100 * MS }), + ); - setupMocksForSuccess(mockApexLog); + expect( + (await ranked({ ...ARGS, minSelfMs: 300 })).operations.map((o) => o.name), + ).toEqual(["A.run"]); + }); - const result = await analyzeLogPerformance(args); - const parsedResult = toonDecode(result); + it("drops an operation whose timestamps did not parse to a number", async () => { + mockLog(1000 * MS, method({ text: "A.run", totalNs: NaN })); - const mentionsMethod4 = parsedResult.recommendations.some((rec) => - rec.includes("Method4"), - ); - expect(mentionsMethod4).toBe(false); - }); + expect((await ranked({ ...ARGS, minSelfMs: 0 })).operations).toEqual([]); }); - // Helper function for decoding TOON-formatted data - function toonDecode(result: any): LogAnalysisResult { - return decode(result.content[0].text) as unknown as LogAnalysisResult; - } - - // Helper functions for creating mock data - function setupMocksForSuccess(mockApexLog: any): void { - mockedFs.stat.mockResolvedValue(mockStats); - mockedFs.readFile.mockResolvedValue("mock log content"); - mockedParse.mockReturnValue(mockApexLog); - } - - function createMockLogLine( - name: string, - duration: number, - selfDuration: number, - namespace: string = "default", - lineNumber: number | string | null = 1, - dmlCount: number = 0, - soqlCount: number = 0, - dmlRows: number = 0, - soqlRows: number = 0, - soslCount: number = 0, - soslRows: number = 0, - totalThrownCount: number = 0, - ): any { - return { - type: "METHOD_ENTRY", - text: name, - namespace, - lineNumber, - duration: { total: duration, self: selfDuration }, - dmlCount: { total: dmlCount, self: dmlCount }, - soqlCount: { total: soqlCount, self: soqlCount }, - dmlRowCount: { total: dmlRows, self: dmlRows }, - soqlRowCount: { total: soqlRows, self: soqlRows }, - soslCount: { total: soslCount, self: soslCount }, - soslRowCount: { total: soslRows, self: soslRows }, - totalThrownCount, - children: [], - }; - } - - function createMockApexLog(): any { - const slowMethod = createMockLogLine( - "SlowMethod", - 500000000, - 500000000, - "default", - 1, - 5, - 10, - 100, - 1000, - ); - const mediumMethod = createMockLogLine( - "MediumMethod", - 400000000, - 400000000, - "default", - 2, - 2, - 3, - 50, - 200, - ); - const fastMethod = createMockLogLine( - "FastMethod", - 100000000, - 100000000, - "default", - 3, - 1, - 1, - 10, - 50, + it("returns at most the rows the caller asked for", async () => { + mockLog( + 1000 * MS, + method({ text: "A.run", totalNs: 500 * MS }), + method({ text: "B.run", totalNs: 400 * MS }), ); - return { - duration: { total: 1000000000, self: 0 }, - children: [slowMethod, mediumMethod, fastMethod], - type: "EXECUTION_STARTED", - text: "Root", - namespace: "default", - lineNumber: null, - dmlCount: { total: 8, self: 0 }, - soqlCount: { total: 14, self: 0 }, - dmlRowCount: { total: 160, self: 0 }, - soqlRowCount: { total: 1250, self: 0 }, - }; - } - - function createMockApexLogWithNamespaces(): any { - const defaultMethod = createMockLogLine( - "DefaultMethod", - 500000000, - 500000000, - "default", - 1, - ); - const customMethod = createMockLogLine( - "CustomMethod", - 400000000, - 400000000, - "CustomNamespace", - 2, - ); - - return { - duration: { total: 1000000000, self: 100000000 }, - children: [defaultMethod, customMethod], - type: "EXECUTION_STARTED", - text: "Root", - namespace: "default", - lineNumber: null, - dmlCount: { total: 0, self: 0 }, - soqlCount: { total: 0, self: 0 }, - dmlRowCount: { total: 0, self: 0 }, - soqlRowCount: { total: 0, self: 0 }, - }; - } - - function createMockApexLogWithNullValues(): any { - const nullMethod: any = { - type: "METHOD_ENTRY", - text: null, - namespace: null, - lineNumber: null, - duration: { total: 500000000, self: 500000000 }, - dmlCount: { total: 0, self: 0 }, - soqlCount: { total: 0, self: 0 }, - dmlRowCount: { total: 0, self: 0 }, - soqlRowCount: { total: 0, self: 0 }, - soslCount: { total: 0, self: 0 }, - soslRowCount: { total: 0, self: 0 }, - totalThrownCount: 0, - children: [], - }; - - return { - duration: { total: 1000000000, self: 500000000 }, - children: [nullMethod], - type: "EXECUTION_STARTED", - text: "Root", - namespace: "default", - lineNumber: null, - dmlCount: { total: 0, self: 0 }, - soqlCount: { total: 0, self: 0 }, - dmlRowCount: { total: 0, self: 0 }, - soqlRowCount: { total: 0, self: 0 }, - }; - } - - function createMockApexLogWithZeroTotalTime(): any { - const method = createMockLogLine("TestMethod", 500000000, 500000000); - - return { - duration: { total: 0, self: 0 }, - children: [method], - type: "EXECUTION_STARTED", - text: "Root", - namespace: "default", - lineNumber: null, - dmlCount: { total: 0, self: 0 }, - soqlCount: { total: 0, self: 0 }, - dmlRowCount: { total: 0, self: 0 }, - soqlRowCount: { total: 0, self: 0 }, - }; - } - - function createEmptyMockApexLog(): any { - return { - duration: { total: 0, self: 0 }, - children: [], - type: "EXECUTION_STARTED", - text: "Root", - namespace: "default", - lineNumber: null, - dmlCount: { total: 0, self: 0 }, - soqlCount: { total: 0, self: 0 }, - dmlRowCount: { total: 0, self: 0 }, - soqlRowCount: { total: 0, self: 0 }, - }; - } - - function createMockApexLogWithHighSOQL(): any { - const highSOQLMethod = createMockLogLine( - "HighSOQLMethod", - 500000000, - 50000000, // Low self duration to get selfPercentage < 10% - "default", - 1, - 2, - 8, - 50, - 500, - ); + expect((await ranked({ ...ARGS, limit: 1 })).operations).toHaveLength(1); + }); - return { - duration: { total: 1000000000, self: 500000000 }, - children: [highSOQLMethod], - type: "EXECUTION_STARTED", - text: "Root", - namespace: "default", - lineNumber: null, - dmlCount: { total: 2, self: 0 }, - soqlCount: { total: 8, self: 0 }, - dmlRowCount: { total: 50, self: 0 }, - soqlRowCount: { total: 500, self: 0 }, - }; - } - - function createMockApexLogWithHighDML(): any { - const highDMLMethod = createMockLogLine( - "HighDMLMethod", - 500000000, - 50000000, // Low self duration to get selfPercentage < 10% - "default", - 1, - 6, - 2, - 100, - 50, + it("returns ten rows when the caller sets no limit", async () => { + mockLog( + 1000 * MS, + ...Array.from({ length: 12 }, (_, index) => + method({ text: `M${index}`, totalNs: (index + 1) * MS }), + ), ); - return { - duration: { total: 1000000000, self: 500000000 }, - children: [highDMLMethod], - type: "EXECUTION_STARTED", - text: "Root", - namespace: "default", - lineNumber: null, - dmlCount: { total: 6, self: 0 }, - soqlCount: { total: 2, self: 0 }, - dmlRowCount: { total: 100, self: 0 }, - soqlRowCount: { total: 50, self: 0 }, - }; - } - - function createMockApexLogWithHighSOSL(): any { - const highSOSLMethod = createMockLogLine( - "HighSOSLMethod", - 500000000, - 50000000, // Low self duration to get selfPercentage < 10% - "default", - 1, - 1, // dmlCount - 2, // soqlCount - 10, // dmlRows - 50, // soqlRows - 5, // soslCount (> 3 triggers recommendation) - 200, // soslRows - ); + expect((await ranked()).operations).toHaveLength(10); + }); - return { - duration: { total: 1000000000, self: 500000000 }, - children: [highSOSLMethod], - type: "EXECUTION_STARTED", - text: "Root", - namespace: "default", - lineNumber: null, - dmlCount: { total: 1, self: 0 }, - soqlCount: { total: 2, self: 0 }, - dmlRowCount: { total: 10, self: 0 }, - soqlRowCount: { total: 50, self: 0 }, - }; - } - - function createMockApexLogWithHighSOQLRows(): any { - const highRowsMethod = createMockLogLine( - "HighRowsMethod", - 500000000, - 50000000, // Low self duration to get selfPercentage < 10% - "default", - 1, - 1, - 2, - 10, - 1500, - ); + it("folds a repeated query into one row before the self time drops it", async () => { + const repeat = () => + query({ text: "SELECT Id", lineNumber: 12, totalNs: 100 * MS }); + mockLog(1000 * MS, repeat(), repeat(), repeat()); + + expect( + (await ranked({ ...ARGS, groupBy: "name", minSelfMs: 250 })).operations, + ).toEqual([ + expect.objectContaining({ + name: "SELECT Id", + callCount: 3, + durationSelfMs: 300, + soqlCount: 3, + lineNumber: null, + }), + ]); + }); - return { - duration: { total: 1000000000, self: 500000000 }, - children: [highRowsMethod], - type: "EXECUTION_STARTED", - text: "Root", - namespace: "default", - lineNumber: null, - dmlCount: { total: 1, self: 0 }, - soqlCount: { total: 2, self: 0 }, - dmlRowCount: { total: 10, self: 0 }, - soqlRowCount: { total: 1500, self: 0 }, - }; - } - - function createMockApexLogWithHighPercentage(): any { - const highPercentageMethod = createMockLogLine( - "HighPercentageMethod", - 300000000, - 300000000, - "default", - 1, - 1, - 1, - 10, - 50, + it("groups by namespace, and names each row after it", async () => { + mockLog( + 1000 * MS, + method({ text: "A.run", namespace: "Custom", totalNs: 300 * MS }), + method({ text: "B.run", namespace: "Custom", totalNs: 200 * MS }), ); - return { - duration: { total: 1000000000, self: 700000000 }, - children: [highPercentageMethod], - type: "EXECUTION_STARTED", - text: "Root", - namespace: "default", - lineNumber: null, - dmlCount: { total: 1, self: 0 }, - soqlCount: { total: 1, self: 0 }, - dmlRowCount: { total: 10, self: 0 }, - soqlRowCount: { total: 50, self: 0 }, - }; - } - - function createMockApexLogWithGoodPerformance(): any { - const goodMethod = createMockLogLine( - "GoodMethod", - 100000000, - 100000000, - "default", - 1, - 1, - 2, - 50, - 100, - ); + expect( + (await ranked({ ...ARGS, groupBy: "namespace" })).operations, + ).toEqual([ + expect.objectContaining({ name: "Custom", callCount: 2 }), + ]); + }); - return { - duration: { total: 1000000000, self: 900000000 }, - children: [goodMethod], - type: "EXECUTION_STARTED", - text: "Root", - namespace: "default", - lineNumber: null, - dmlCount: { total: 1, self: 0 }, - soqlCount: { total: 2, self: 0 }, - dmlRowCount: { total: 50, self: 0 }, - soqlRowCount: { total: 100, self: 0 }, - }; - } - - function createMockApexLogWithManyMethods(): any { - const method1 = createMockLogLine( - "Method1", - 400000000, - 400000000, - "default", - 1, - 8, - 8, - 100, - 1200, - ); - const method2 = createMockLogLine( - "Method2", - 300000000, - 300000000, - "default", - 2, - 6, - 6, - 80, - 1000, - ); - const method3 = createMockLogLine( - "Method3", - 200000000, - 200000000, - "default", - 3, - 4, - 4, - 60, - 800, - ); - const method4 = createMockLogLine( - "Method4", - 100000000, - 100000000, - "default", - 4, - 8, - 8, - 100, - 1200, + it("names the real cause when the log cannot be read", async () => { + mockFs.stat.mockRejectedValue( + Object.assign(new Error("ENOENT"), { code: "ENOENT" }), ); - return { - duration: { total: 1000000000, self: 0 }, - children: [method1, method2, method3, method4], - type: "EXECUTION_STARTED", - text: "Root", - namespace: "default", - lineNumber: null, - dmlCount: { total: 26, self: 0 }, - soqlCount: { total: 26, self: 0 }, - dmlRowCount: { total: 340, self: 0 }, - soqlRowCount: { total: 4200, self: 0 }, - }; - } + await expect( + analyzeLogPerformance({ logFilePath: "/nonexistent/file.log" }), + ).rejects.toThrow("Log file not found: /nonexistent/file.log"); + }); }); diff --git a/tests/apexLogSource.test.ts b/tests/apexLogSource.test.ts index 2735ed5..6b5ab79 100644 --- a/tests/apexLogSource.test.ts +++ b/tests/apexLogSource.test.ts @@ -6,8 +6,8 @@ import { promises as fs, type BigIntStats } from "fs"; import { clearApexLogCache, - isMethodNode, loadApexLog, + logFilePathSchema, walkLog, } from "../src/tools/apexLogSource"; import { parse, ApexLog, LogLine } from "../src/ApexLogParser"; @@ -49,9 +49,6 @@ const statsOf = ( ctimeNs: BigInt(ctimeNs), }) as BigIntStats; -const nodeOf = (props: Record): LogLine => - props as unknown as LogLine; - /** * Run the body with the clock under our control. `jest.useRealTimers()` leaves * `globalThis.clearTimeout` deleted rather than restored in this environment, @@ -207,7 +204,9 @@ describe("apexLogSource", () => { }); it("reports a missing file and does not read it", async () => { - mockFs.stat.mockRejectedValue(new Error("ENOENT")); + mockFs.stat.mockRejectedValue( + Object.assign(new Error("ENOENT"), { code: "ENOENT" }), + ); await expect(loadApexLog("/path/to/missing.log")).rejects.toThrow( "Log file not found: /path/to/missing.log", @@ -216,17 +215,22 @@ describe("apexLogSource", () => { }); }); - describe("isMethodNode", () => { - it("accepts code units, method entries and timed method nodes", () => { - expect(isMethodNode(nodeOf({ type: "CODE_UNIT_STARTED" }))).toBe(true); - expect(isMethodNode(nodeOf({ type: "METHOD_ENTRY" }))).toBe(true); - expect(isMethodNode(nodeOf({ type: "SOQL_EXECUTE_BEGIN" }))).toBe(false); - expect( - isMethodNode( - nodeOf({ type: "CONSTRUCTOR_ENTRY", subCategory: "Method" }), - ), - ).toBe(true); + describe("logFilePathSchema", () => { + it("accepts an absolute path", () => { + expect(logFilePathSchema.safeParse("/logs/run.log").success).toBe(true); }); + + it.each(["./run.log", ""])( + "refuses %p rather than resolving it against our cwd", + (path) => { + const result = logFilePathSchema.safeParse(path); + + expect(result.success).toBe(false); + expect(result.error?.issues[0]?.message).toBe( + "must be an absolute path", + ); + }, + ); }); describe("walkLog", () => { diff --git a/tests/eval/golden/analyze_apex_log_performance.governor-heavy.expected.txt b/tests/eval/golden/analyze_apex_log_performance.governor-heavy.expected.txt index d2fcaa6..58df72e 100644 --- a/tests/eval/golden/analyze_apex_log_performance.governor-heavy.expected.txt +++ b/tests/eval/golden/analyze_apex_log_performance.governor-heavy.expected.txt @@ -1,15 +1,13 @@ -totalMethods: 13 -totalExecutionTime: 24608.108 -topMethodsSelfPercentage: 96.6 -slowestMethods[10]{name,duration,selfDuration,selfPercentage,namespace,lineNumber,dmlCount,soqlCount,dmlRows,soqlRows,thrownCount,soslCount,soslRows}: - srm_pkg,20479.388,20479.388,83.2,srm_pkg,null,0,0,0,0,0,0,0 - "Flow:Account",3040.037,3040.037,12.4,default,null,0,0,0,0,0,0,0 - core_pkg,131.423,131.423,0.5,core_pkg,null,0,0,0,0,0,0,0 - execute_anonymous_apex,24607.193,79.143,0.3,default,null,1,1,300,0,0,0,0 - core_pkg,10.528,10.528,0,core_pkg,null,0,0,0,0,0,0,0 - srm_pkg,10.032,10.032,0,srm_pkg,null,0,0,0,0,0,0,0 - core_pkg,6.668,6.668,0,core_pkg,null,0,0,0,0,0,0,0 - AccountService.createAccountsAndContacts(),24527.816,3.58,0,default,1,1,1,300,0,0,0,0 - "System.Math.mod(Integer, Integer)",1.065,1.065,0,default,143,0,0,0,0,0,0,0 - AccountService.getDayValue(Date),1.282,0.153,0,default,120,0,0,0,0,0,0,0 -recommendations[2]: "srm_pkg: dominates self time. Check whether it can be made faster, and how often it is called.","Flow:Account: dominates self time. Check whether it can be made faster, and how often it is called." +durationTotalMs: 24608.108 +returnedSelfPercentage: 100 +operations[10]{kind,name,namespace,lineNumber,callCount,durationTotalMs,durationSelfMs,selfPercentage,soqlCount,dmlCount,soslCount,rowCount,thrownCount}: + managedPackage,srm_pkg,srm_pkg,null,1,20479.388,20479.388,83.2,0,0,0,0,0 + codeUnit,"Flow:Account",default,null,1,3040.037,3040.037,12.4,0,0,0,0,0 + dml,"DML Op:Insert Type:Account",default,36,1,24468.441,765.749,3.1,1,1,0,300,0 + managedPackage,core_pkg,core_pkg,null,1,131.423,131.423,0.5,0,0,0,0,0 + codeUnit,execute_anonymous_apex,default,null,1,24607.193,79.143,0.3,1,1,0,300,0 + systemMethod,List.add(Object),default,19,1,24521.782,53.321,0.2,1,1,0,300,0 + soql,"SELECT Name, Id, core_pkg__group_key__c, (SELECT core_pkg__Value__c FROM core_pkg__Values__r ORDER BY core_pkg__Sort__c ASC NULLS FIRST) FROM core_pkg__Config_Option__c",default,19,1,24.617,24.617,0.1,1,0,0,0,0 + managedPackage,core_pkg,core_pkg,null,1,10.528,10.528,0,0,0,0,0,0 + managedPackage,srm_pkg,srm_pkg,null,1,10.032,10.032,0,0,0,0,0,0 + managedPackage,core_pkg,core_pkg,null,1,6.668,6.668,0,0,0,0,0,0 diff --git a/tests/eval/golden/analyze_apex_log_performance.minimal.expected.txt b/tests/eval/golden/analyze_apex_log_performance.minimal.expected.txt index abdb297..5fafa86 100644 --- a/tests/eval/golden/analyze_apex_log_performance.minimal.expected.txt +++ b/tests/eval/golden/analyze_apex_log_performance.minimal.expected.txt @@ -1,7 +1,5 @@ -totalMethods: 2 -totalExecutionTime: 0.561 -topMethodsSelfPercentage: 100 -slowestMethods[2]{name,duration,selfDuration,selfPercentage,namespace,lineNumber,dmlCount,soqlCount,dmlRows,soqlRows,thrownCount,soslCount,soslRows}: - execute_anonymous_apex,0.546,0.546,97.3,default,null,0,0,0,0,0,0,0 - EXECUTION_STARTED,0.561,0.015,2.7,default,null,0,0,0,0,0,0,0 -recommendations[1]: "execute_anonymous_apex: dominates self time. Check whether it can be made faster, and how often it is called." +durationTotalMs: 0.561 +returnedSelfPercentage: 97.3 +operations[2]{kind,name,namespace,lineNumber,callCount,durationTotalMs,durationSelfMs,selfPercentage,soqlCount,dmlCount,soslCount,rowCount,thrownCount}: + codeUnit,execute_anonymous_apex,default,null,1,0.546,0.546,97.3,0,0,0,0,0 + systemMethod,CUMULATIVE_LIMIT_USAGE,default,null,1,0,0,0,0,0,0,0,0 diff --git a/tests/eval/golden/find_performance_bottlenecks.governor-heavy.expected.txt b/tests/eval/golden/find_performance_bottlenecks.governor-heavy.expected.txt index ed80652..f557e33 100644 --- a/tests/eval/golden/find_performance_bottlenecks.governor-heavy.expected.txt +++ b/tests/eval/golden/find_performance_bottlenecks.governor-heavy.expected.txt @@ -1,11 +1,3 @@ -cpuBottlenecks: - cpuTimeUsed: 15163 - cpuTimeLimit: 10000 - cpuUsagePercentage: 151.6 - warning: High CPU usage - consider optimizing algorithms -methodBottlenecks: - totalMethods: 13 - methodsByNamespace[3]{namespace,methodCount,totalDuration}: - default,8,76786.322 - core_pkg,3,148.619 - srm_pkg,2,20489.42 +threshold: 80 +atRisk[1]{limit,used,max,usedPercentage}: + cpuTime,15163,10000,151.6 diff --git a/tests/eval/golden/find_performance_bottlenecks.minimal.expected.txt b/tests/eval/golden/find_performance_bottlenecks.minimal.expected.txt index c333425..8df741d 100644 --- a/tests/eval/golden/find_performance_bottlenecks.minimal.expected.txt +++ b/tests/eval/golden/find_performance_bottlenecks.minimal.expected.txt @@ -1,4 +1,2 @@ -methodBottlenecks: - totalMethods: 2 - methodsByNamespace[1]{namespace,methodCount,totalDuration}: - default,2,1.107 +threshold: 80 +atRisk: [] diff --git a/tests/eval/golden/get_apex_log_summary.governor-heavy.expected.txt b/tests/eval/golden/get_apex_log_summary.governor-heavy.expected.txt index 898b847..a03b7cb 100644 --- a/tests/eval/golden/get_apex_log_summary.governor-heavy.expected.txt +++ b/tests/eval/golden/get_apex_log_summary.governor-heavy.expected.txt @@ -1,11 +1,21 @@ -size: 39532 -totalExecutionTime: 24608.108 -totalMethods: 13 -totalSOQLQueries: 1 -totalDMLOperations: 1 -totalSOQLRows: 0 -totalDMLRows: 300 -governorLimits[13]{name,used,limit}: +fileSizeBytes: 39532 +durationTotalMs: 24608.108 +truncated: false +parsingErrorCount: 11 +namespaces[3]: default,core_pkg,srm_pkg +debugLevels[11]{logCategory,level}: + APEX_CODE,FINE + APEX_PROFILING,FINE + CALLOUT,FINEST + DATA_ACCESS,INFO + DB,FINEST + NBA,FINE + SYSTEM,FINE + VALIDATION,INFO + VISUALFORCE,FINE + WAVE,FINE + WORKFLOW,FINE +governorLimits[13]{limit,used,max}: soqlQueries,5,100 soslQueries,0,20 queryRows,602,50000 @@ -19,20 +29,24 @@ governorLimits[13]{name,used,limit}: futureCalls,0,50 queueableJobsAddedToQueue,0,50 mobileApexPushCalls,0,10 -namespaces[3]: default,core_pkg,srm_pkg -debugLevels[11]{category,level}: - APEX_CODE,FINE - APEX_PROFILING,FINE - CALLOUT,FINEST - DATA_ACCESS,INFO - DB,FINEST - NBA,FINE - SYSTEM,FINE - VALIDATION,INFO - VISUALFORCE,FINE - WAVE,FINE - WORKFLOW,FINE -parsingErrors: 11 +limitsByNamespace[7]{namespace,limit,used}: + default,soqlQueries,5 + default,queryRows,600 + default,dmlStatements,6 + default,dmlRows,1200 + default,cpuTime,15163 + default,heapSize,219591 + core_pkg,queryRows,2 +timeByKind[9]{kind,logCategory,operationCount,durationSelfMs,selfPercentage}: + codeUnit,APEX_CODE,2,3119.179,12.7 + managedPackage,APEX_CODE,5,20638.038,83.9 + method,APEX_CODE,5,5.058,0 + systemMethod,SYSTEM,98,54.552,0.2 + soql,DB,1,24.617,0.1 + sosl,DB,0,0,0 + dml,DB,1,765.749,3.1 + flow,WORKFLOW,0,0,0 + workflow,WORKFLOW,0,0,0 logIssues[2]{type,summary}: unexpected,Unexpected-Exit error,"FATAL ERROR! cause=System.LimitException: Apex CPU time limit exceeded\n" diff --git a/tests/eval/golden/get_apex_log_summary.minimal.expected.txt b/tests/eval/golden/get_apex_log_summary.minimal.expected.txt index 85ef6d3..a8ef968 100644 --- a/tests/eval/golden/get_apex_log_summary.minimal.expected.txt +++ b/tests/eval/golden/get_apex_log_summary.minimal.expected.txt @@ -1,11 +1,21 @@ -size: 1274 -totalExecutionTime: 0.561 -totalMethods: 2 -totalSOQLQueries: 0 -totalDMLOperations: 0 -totalSOQLRows: 0 -totalDMLRows: 0 -governorLimits[13]{name,used,limit}: +fileSizeBytes: 1274 +durationTotalMs: 0.561 +truncated: false +parsingErrorCount: 0 +namespaces[1]: default +debugLevels[11]{logCategory,level}: + APEX_CODE,FINE + APEX_PROFILING,NONE + CALLOUT,NONE + DATA_ACCESS,NONE + DB,NONE + NBA,NONE + SYSTEM,DEBUG + VALIDATION,NONE + VISUALFORCE,NONE + WAVE,NONE + WORKFLOW,NONE +governorLimits[13]{limit,used,max}: soqlQueries,0,100 soslQueries,0,20 queryRows,0,50000 @@ -19,17 +29,14 @@ governorLimits[13]{name,used,limit}: futureCalls,0,50 queueableJobsAddedToQueue,0,50 mobileApexPushCalls,0,10 -namespaces[1]: default -debugLevels[11]{category,level}: - APEX_CODE,FINE - APEX_PROFILING,NONE - CALLOUT,NONE - DATA_ACCESS,NONE - DB,NONE - NBA,NONE - SYSTEM,DEBUG - VALIDATION,NONE - VISUALFORCE,NONE - WAVE,NONE - WORKFLOW,NONE -parsingErrors: 0 +limitsByNamespace: [] +timeByKind[9]{kind,logCategory,operationCount,durationSelfMs,selfPercentage}: + codeUnit,APEX_CODE,1,0.546,97.3 + managedPackage,APEX_CODE,0,0,0 + method,APEX_CODE,0,0,0 + systemMethod,SYSTEM,1,0,0 + soql,DB,0,0,0 + sosl,DB,0,0,0 + dml,DB,0,0,0 + flow,WORKFLOW,0,0,0 + workflow,WORKFLOW,0,0,0 diff --git a/tests/executeAnonymous.test.ts b/tests/executeAnonymous.test.ts index 8270c74..e59d38b 100644 --- a/tests/executeAnonymous.test.ts +++ b/tests/executeAnonymous.test.ts @@ -7,6 +7,8 @@ jest.mock("node:fs", () => ({ mkdir: jest.fn().mockResolvedValue(undefined), writeFile: jest.fn().mockResolvedValue(undefined), stat: jest.fn().mockResolvedValue({ size: 1024 }), + // No symlinks in the test filesystem, so every path resolves to itself. + realpath: jest.fn((target: string) => Promise.resolve(target)), }, })); @@ -847,6 +849,101 @@ describe("Execute Anonymous", () => { ); }); + it("anchors a relative outputDir to the project root, so the returned path is absolute", async () => { + (mockServer.server.listRoots as jest.Mock).mockResolvedValue({ + roots: [{ uri: "file:///my/project" }], + }); + + const args: ExecuteAnonymousArgs = { + apex: testApexCode, + outputDir: "logs", + }; + + await executeAnonymous(mockServer, args, policy()); + + expect(mockMkdir).toHaveBeenCalledWith("/my/project/logs", { + recursive: true, + }); + expect(mockWriteFile).toHaveBeenCalledWith( + expect.stringMatching(/^\/my\/project\/logs\/.+\.log$/), + testLogBody, + "utf-8", + ); + }); + + describe("outputDir outside the client roots", () => { + const textOf = (result: Awaited>) => + result.content[0]?.text ?? ""; + + let consoleError: jest.SpyInstance; + + beforeEach(() => { + consoleError = jest.spyOn(console, "error").mockImplementation(); + }); + + afterEach(() => consoleError.mockRestore()); + + const withRoot = async (outputDir?: string) => { + (mockServer.server.listRoots as jest.Mock).mockResolvedValue({ + roots: [{ uri: "file:///my/project" }], + }); + return executeAnonymous( + mockServer, + { apex: testApexCode, ...(outputDir && { outputDir }) }, + policy(), + ); + }; + + it("warns in the response and on stderr, and still writes the log", async () => { + const result = await withRoot("/elsewhere/logs"); + + expect(textOf(result)).toContain( + "Debug log written to /elsewhere/logs, which is outside every root this client declared.", + ); + expect(consoleError).toHaveBeenCalledWith( + expect.stringContaining("/elsewhere/logs"), + ); + expect(mockWriteFile).toHaveBeenCalled(); + }); + + it.each([ + ["inside a root", "/my/project/logs"], + ["the root itself", "/my/project"], + ])("stays silent for %s", async (_name, outputDir) => { + expect(textOf(await withRoot(outputDir))).not.toContain("warning"); + }); + + it("stays silent for the default outputDir", async () => { + expect(textOf(await withRoot())).not.toContain("warning"); + }); + + it("stays silent when the client declares no roots", async () => { + (mockServer.server.listRoots as jest.Mock).mockResolvedValue({ + roots: [], + }); + + const result = await executeAnonymous( + mockServer, + { apex: testApexCode, outputDir: "/elsewhere/logs" }, + policy(), + ); + + expect(textOf(result)).not.toContain("warning"); + }); + + it("follows symlinks, so a link inside a root that leaves one warns", async () => { + // The first call resolves outputDir; the roots after it keep the + // resolves-to-itself default. + (fs.realpath as unknown as jest.Mock).mockImplementationOnce(() => + Promise.resolve("/elsewhere/logs"), + ); + + expect(textOf(await withRoot("/my/project/logs"))).toContain( + "/elsewhere/logs", + ); + }); + }); + it("should default outputDir to .apex-log-mcp in project root", async () => { (mockServer.server.listRoots as jest.Mock).mockResolvedValue({ roots: [{ uri: "file:///my/project" }], diff --git a/tests/findPerformanceBottlenecks.test.ts b/tests/findPerformanceBottlenecks.test.ts index 90e643a..64dbf33 100644 --- a/tests/findPerformanceBottlenecks.test.ts +++ b/tests/findPerformanceBottlenecks.test.ts @@ -3,19 +3,18 @@ */ import { promises as fs, type BigIntStats } from "fs"; +import { decode } from "@toon-format/toon"; import { clearApexLogCache } from "../src/tools/apexLogSource"; import { findPerformanceBottlenecks, - BottleneckArgs, - BottleneckResult, findPerformanceBottlenecksToolConfig, + WARNING_THRESHOLD, + type BottleneckArgs, + type LimitRiskResult, } from "../src/tools/findPerformanceBottlenecks"; import { parse, ApexLog, Limits, GovernorLimits } from "../src/ApexLogParser"; -import { extractMethods, SlowMethod } from "../src/tools/analyzeLogPerformance"; -import { decode } from "@toon-format/toon"; -// Mock dependencies jest.mock("fs", () => { const stat = jest.fn(); const readFile = jest.fn(); @@ -38,15 +37,8 @@ jest.mock("../src/ApexLogParser", () => ({ parse: jest.fn(), })); -jest.mock("../src/tools/analyzeLogPerformance", () => ({ - extractMethods: jest.fn(), -})); - const mockFs = fs as jest.Mocked; const mockParse = parse as jest.MockedFunction; -const mockExtractMethods = extractMethods as jest.MockedFunction< - typeof extractMethods ->; const mockStats = { ino: 1n, size: 1n, @@ -54,11 +46,10 @@ const mockStats = { ctimeNs: 1n, } as BigIntStats; -// Helper function to create mock governor limits -function createMockGovernorLimits( - overrides: Partial = {}, -): GovernorLimits { - const defaultLimits: Limits = { +const ARGS: BottleneckArgs = { logFilePath: "/test/file.log" }; + +function governorLimits(overrides: Partial = {}): GovernorLimits { + const defaults: Limits = { soqlQueries: { used: 0, limit: 100 }, soslQueries: { used: 0, limit: 20 }, queryRows: { used: 0, limit: 50000 }, @@ -75,783 +66,112 @@ function createMockGovernorLimits( }; return { - ...defaultLimits, + ...defaults, ...overrides, byNamespace: new Map(), }; } -// Helper function to create mock ApexLog -function createMockApexLog(governorLimits?: Partial): ApexLog { - const mockLog = { - type: null, - text: "LOG_ROOT", - timestamp: 0, - exitStamp: 1000000000, - size: 1024, - debugLevels: [], - namespaces: ["default", "MyNamespace"], - logIssues: [], - parsingErrors: [], - governorLimits: createMockGovernorLimits(governorLimits), - duration: { - total: 1000000000, // 1 second in nanoseconds - self: 1000000000, - }, - children: [], - parent: null, - lineNumber: null, - namespace: "default", - dmlCount: { total: 0, self: 0 }, - soqlCount: { total: 0, self: 0 }, - dmlRowCount: { total: 0, self: 0 }, - soqlRowCount: { total: 0, self: 0 }, - } as unknown as ApexLog; - - return mockLog; +function mockLog(overrides: Partial = {}): void { + mockFs.stat.mockResolvedValue(mockStats); + mockFs.readFile.mockResolvedValue("log content"); + mockParse.mockReturnValue({ + governorLimits: governorLimits(overrides), + } as unknown as ApexLog); } -// Helper function to create mock slow methods -function createMockSlowMethods(): SlowMethod[] { - return [ - { - name: "MyClass.slowMethod1", - duration: 500000000, // 500ms - selfDuration: 300000000, - namespace: "MyNamespace", - lineNumber: 10, - dmlCount: 5, - soqlCount: 8, - dmlRows: 100, - soqlRows: 1500, - thrownCount: 0, - soslCount: 0, - soslRows: 0, - selfPercentage: 50.0, - }, - { - name: "MyClass.slowMethod2", - duration: 300000000, // 300ms - selfDuration: 250000000, - namespace: "default", - lineNumber: 25, - dmlCount: 2, - soqlCount: 3, - dmlRows: 50, - soqlRows: 500, - thrownCount: 0, - soslCount: 0, - soslRows: 0, - selfPercentage: 30.0, - }, - { - name: "AnotherClass.method", - duration: 200000000, // 200ms - selfDuration: 150000000, - namespace: "MyNamespace", - lineNumber: 42, - dmlCount: 1, - soqlCount: 2, - dmlRows: 25, - soqlRows: 200, - thrownCount: 0, - soslCount: 0, - soslRows: 0, - selfPercentage: 20.0, - }, - ]; +async function risks(args: BottleneckArgs = ARGS): Promise { + const result = await findPerformanceBottlenecks(args); + return decode(result.content[0]!.text) as LimitRiskResult; } describe("findPerformanceBottlenecks", () => { - const mockLogFilePath = "/path/to/test.log"; - const mockLogContent = "mock log content"; - beforeEach(() => { jest.clearAllMocks(); // The suites reuse one path with different content, which the cache would // otherwise hide. clearApexLogCache(); - mockFs.stat.mockResolvedValue(mockStats); - mockFs.readFile.mockResolvedValue(mockLogContent); }); - describe("Tool configuration", () => { - it("should annotate only the hints that carry meaning for a read-only tool", () => { - expect(findPerformanceBottlenecksToolConfig.annotations).toEqual({ - readOnlyHint: true, - openWorldHint: false, - }); - }); - }); - - describe("File validation and error handling", () => { - it("should throw an error if log file does not exist", async () => { - const args: BottleneckArgs = { logFilePath: "/nonexistent/file.log" }; - mockFs.stat.mockRejectedValue(new Error("File not found")); - - await expect(findPerformanceBottlenecks(args)).rejects.toThrow( - "Log file not found: /nonexistent/file.log", - ); - - expect(mockFs.stat).toHaveBeenCalledWith("/nonexistent/file.log", { bigint: true }); - expect(mockFs.readFile).not.toHaveBeenCalled(); - expect(mockParse).not.toHaveBeenCalled(); - }); - - it("should handle file system errors during file reading", async () => { - const args: BottleneckArgs = { logFilePath: mockLogFilePath }; - mockFs.readFile.mockRejectedValue(new Error("Permission denied")); - - await expect(findPerformanceBottlenecks(args)).rejects.toThrow( - "Permission denied", + describe("tool configuration", () => { + it("says which limits it covers, so a client can select it", () => { + expect(findPerformanceBottlenecksToolConfig.description).toContain( + "governor limits", ); - - expect(mockFs.stat).toHaveBeenCalledWith(mockLogFilePath, { bigint: true }); - expect(mockFs.readFile).toHaveBeenCalledWith(mockLogFilePath, "utf-8"); - expect(mockParse).not.toHaveBeenCalled(); }); - it("should handle parsing errors", async () => { - const args: BottleneckArgs = { logFilePath: mockLogFilePath }; - mockParse.mockImplementation(() => { - throw new Error("Invalid log format"); + it("annotates only the hints that carry meaning for a read-only tool", () => { + expect(findPerformanceBottlenecksToolConfig.annotations).toEqual({ + readOnlyHint: true, + openWorldHint: false, }); - - await expect(findPerformanceBottlenecks(args)).rejects.toThrow( - "Invalid log format", - ); - - expect(mockFs.stat).toHaveBeenCalledWith(mockLogFilePath, { bigint: true }); - expect(mockFs.readFile).toHaveBeenCalledWith(mockLogFilePath, "utf-8"); - expect(mockParse).toHaveBeenCalledWith(mockLogContent); }); }); - describe('Analysis type "all" (default)', () => { - it('should perform all types of analysis when analysisType is "all"', async () => { - const args: BottleneckArgs = { - logFilePath: mockLogFilePath, - analysisType: "all", - }; - - const mockLog = createMockApexLog({ - cpuTime: { used: 8500, limit: 10000 }, // 85% usage - soqlQueries: { used: 90, limit: 100 }, // 90% usage - dmlStatements: { used: 120, limit: 150 }, // 80% usage - }); - - mockParse.mockReturnValue(mockLog); - mockExtractMethods.mockReturnValue(createMockSlowMethods()); - - const result = await findPerformanceBottlenecks(args); - - expect(result.content).toHaveLength(1); - expect(result.content[0].type).toBe("text"); - - const parsedResult = toonDecode(result); - - // Should contain all analysis types - expect(parsedResult).toHaveProperty("cpuBottlenecks"); - expect(parsedResult).toHaveProperty("databaseBottlenecks"); - expect(parsedResult).toHaveProperty("methodBottlenecks"); - - // Verify CPU analysis - expect(parsedResult.cpuBottlenecks).toMatchObject({ - cpuTimeUsed: 8500, - cpuTimeLimit: 10000, - cpuUsagePercentage: 85, - warning: "High CPU usage - consider optimizing algorithms", - }); - - // Verify database analysis - only soqlQueries should be present (>80%) - expect(parsedResult.databaseBottlenecks!.soqlQueries).toMatchObject({ - used: 90, - limit: 100, - percentage: 90, - }); - expect(parsedResult.databaseBottlenecks!.dmlStatements).toBeUndefined(); - - // Verify method analysis with ms durations - expect(parsedResult.methodBottlenecks).toMatchObject({ - totalMethods: 3, - methodsByNamespace: expect.arrayContaining([ - expect.objectContaining({ - namespace: "MyNamespace", - methodCount: 2, - totalDuration: 700, // 700ms - }), - expect.objectContaining({ - namespace: "default", - methodCount: 1, - totalDuration: 300, // 300ms - }), - ]), - }); - - // cpuTime and soqlQueries are the only limits over threshold and both already - // have a dedicated section, so there is nothing left to warn about. - expect(parsedResult.governorLimitWarnings).toBeUndefined(); - }); - - it('should use "all" as default when analysisType is not specified', async () => { - const args: BottleneckArgs = { logFilePath: mockLogFilePath }; - const mockLog = createMockApexLog(); + it("reports a limit over the threshold, with what it cost", async () => { + mockLog({ cpuTime: { used: 9500, limit: 10000 } }); - mockParse.mockReturnValue(mockLog); - mockExtractMethods.mockReturnValue([]); - - const result = await findPerformanceBottlenecks(args); - const parsedResult = toonDecode(result); - - // Methods section is always present when analysisType includes it - expect(parsedResult).toHaveProperty("methodBottlenecks"); - // No governor limit warnings when usage is low - expect(parsedResult).not.toHaveProperty("governorLimitWarnings"); + await expect(risks()).resolves.toEqual({ + threshold: WARNING_THRESHOLD, + atRisk: [ + { limit: "cpuTime", used: 9500, max: 10000, usedPercentage: 95 }, + ], }); }); - describe('Analysis type "cpu"', () => { - it('should only perform CPU analysis when analysisType is "cpu"', async () => { - const args: BottleneckArgs = { - logFilePath: mockLogFilePath, - analysisType: "cpu", - }; - - const mockLog = createMockApexLog({ - cpuTime: { used: 9000, limit: 10000 }, // 90% usage - }); - - mockParse.mockReturnValue(mockLog); - - const result = await findPerformanceBottlenecks(args); - const parsedResult = toonDecode(result); - - // Should only contain CPU analysis (no database or methods) - expect(parsedResult).toHaveProperty("cpuBottlenecks"); - expect(parsedResult).not.toHaveProperty("databaseBottlenecks"); - expect(parsedResult).not.toHaveProperty("methodBottlenecks"); - - expect(parsedResult.cpuBottlenecks).toMatchObject({ - cpuTimeUsed: 9000, - cpuTimeLimit: 10000, - cpuUsagePercentage: 90, - warning: "High CPU usage - consider optimizing algorithms", - }); + it("reports the worst limit first", async () => { + mockLog({ + cpuTime: { used: 8500, limit: 10000 }, + soqlQueries: { used: 99, limit: 100 }, }); - it("should not show CPU information when usage is below 80%", async () => { - const args: BottleneckArgs = { - logFilePath: mockLogFilePath, - analysisType: "cpu", - }; - - const mockLog = createMockApexLog({ - cpuTime: { used: 5000, limit: 10000 }, // 50% usage - }); - - mockParse.mockReturnValue(mockLog); - - const result = await findPerformanceBottlenecks(args); - const parsedResult = toonDecode(result); - - // Empty section omitted - expect(parsedResult).not.toHaveProperty("cpuBottlenecks"); - expect(parsedResult).toHaveProperty("note"); - }); - - it("should handle zero CPU limit", async () => { - const args: BottleneckArgs = { - logFilePath: mockLogFilePath, - analysisType: "cpu", - }; - - const mockLog = createMockApexLog({ - cpuTime: { used: 1000, limit: 0 }, - }); - - mockParse.mockReturnValue(mockLog); - - const result = await findPerformanceBottlenecks(args); - const parsedResult = toonDecode(result); - - expect(parsedResult).not.toHaveProperty("cpuBottlenecks"); - expect(parsedResult).toHaveProperty("note"); - }); + expect((await risks()).atRisk.map((risk) => risk.limit)).toEqual([ + "soqlQueries", + "cpuTime", + ]); }); - describe('Analysis type "database"', () => { - it('should only perform database analysis when analysisType is "database"', async () => { - const args: BottleneckArgs = { - logFilePath: mockLogFilePath, - analysisType: "database", - }; - - const mockLog = createMockApexLog({ - soqlQueries: { used: 75, limit: 100 }, - dmlStatements: { used: 100, limit: 150 }, - queryRows: { used: 30000, limit: 50000 }, - }); - - mockParse.mockReturnValue(mockLog); - - const result = await findPerformanceBottlenecks(args); - const parsedResult = toonDecode(result); - - // Should not contain CPU or method analysis - expect(parsedResult).not.toHaveProperty("cpuBottlenecks"); - expect(parsedResult).not.toHaveProperty("methodBottlenecks"); - - // None of these exceed 80%, so databaseBottlenecks omitted - expect(parsedResult).not.toHaveProperty("databaseBottlenecks"); - }); - - it("should handle zero database limits", async () => { - const args: BottleneckArgs = { - logFilePath: mockLogFilePath, - analysisType: "database", - }; + it("returns an empty table when every limit is comfortable", async () => { + mockLog({ cpuTime: { used: 10, limit: 10000 } }); - const mockLog = createMockApexLog({ - soqlQueries: { used: 10, limit: 0 }, - dmlStatements: { used: 5, limit: 0 }, - queryRows: { used: 1000, limit: 0 }, - }); - - mockParse.mockReturnValue(mockLog); - - const result = await findPerformanceBottlenecks(args); - const parsedResult = toonDecode(result); - - expect(parsedResult).not.toHaveProperty("databaseBottlenecks"); + // Reported rather than omitted: "nothing is at risk" is an answer, and an + // absent table cannot be told apart from a limit block that never parsed. + await expect(risks()).resolves.toEqual({ + threshold: WARNING_THRESHOLD, + atRisk: [], }); }); - describe('Analysis type "methods"', () => { - it('should only perform method analysis when analysisType is "methods"', async () => { - const args: BottleneckArgs = { - logFilePath: mockLogFilePath, - analysisType: "methods", - }; - - const mockLog = createMockApexLog(); - const mockMethods = createMockSlowMethods(); - - mockParse.mockReturnValue(mockLog); - mockExtractMethods.mockReturnValue(mockMethods); - - const result = await findPerformanceBottlenecks(args); - const parsedResult = toonDecode(result); - - // Should not contain CPU or database analysis - expect(parsedResult).not.toHaveProperty("cpuBottlenecks"); - expect(parsedResult).not.toHaveProperty("databaseBottlenecks"); - expect(parsedResult).toHaveProperty("methodBottlenecks"); - - expect(parsedResult.methodBottlenecks).toMatchObject({ - totalMethods: 3, - methodsByNamespace: expect.arrayContaining([ - expect.objectContaining({ - namespace: "MyNamespace", - methodCount: 2, - totalDuration: 700, // 700ms - }), - expect.objectContaining({ - namespace: "default", - methodCount: 1, - totalDuration: 300, // 300ms - }), - ]), - }); - - expect(mockExtractMethods).toHaveBeenCalledWith(mockLog, 0); - }); - - it("should handle empty methods list", async () => { - const args: BottleneckArgs = { - logFilePath: mockLogFilePath, - analysisType: "methods", - }; - - const mockLog = createMockApexLog(); - - mockParse.mockReturnValue(mockLog); - mockExtractMethods.mockReturnValue([]); - - const result = await findPerformanceBottlenecks(args); - const parsedResult = toonDecode(result); - - expect(parsedResult.methodBottlenecks).toMatchObject({ - totalMethods: 0, - methodsByNamespace: [], - }); - }); - - it("should group methods by namespace correctly", async () => { - const args: BottleneckArgs = { - logFilePath: mockLogFilePath, - analysisType: "methods", - }; - - const mockLog = createMockApexLog(); - const methodsWithSingleNamespace: SlowMethod[] = [ - { - name: "Method1", - duration: 100000000, - selfDuration: 80000000, - namespace: "TestNamespace", - lineNumber: 1, - dmlCount: 1, - soqlCount: 1, - dmlRows: 10, - soqlRows: 100, - thrownCount: 0, - soslCount: 0, - soslRows: 0, - selfPercentage: 10, - }, - { - name: "Method2", - duration: 200000000, - selfDuration: 150000000, - namespace: "TestNamespace", - lineNumber: 2, - dmlCount: 2, - soqlCount: 2, - dmlRows: 20, - soqlRows: 200, - thrownCount: 0, - soslCount: 0, - soslRows: 0, - selfPercentage: 20, - }, - ]; - - mockParse.mockReturnValue(mockLog); - mockExtractMethods.mockReturnValue(methodsWithSingleNamespace); + it("reports a limit exactly at the threshold", async () => { + mockLog({ cpuTime: { used: 8000, limit: 10000 } }); - const result = await findPerformanceBottlenecks(args); - const parsedResult = toonDecode(result); - const methodBottlenecks = parsedResult.methodBottlenecks as any; - - expect(methodBottlenecks.methodsByNamespace).toHaveLength(1); - expect(methodBottlenecks.methodsByNamespace[0]).toMatchObject({ - namespace: "TestNamespace", - methodCount: 2, - totalDuration: 300, // 300ms - }); - }); + expect((await risks()).atRisk).toHaveLength(1); }); - describe("Governor limit warnings", () => { - it("should return structured limit data for high governor limit usage (>80%)", async () => { - const args: BottleneckArgs = { logFilePath: mockLogFilePath }; - - const mockLog = createMockApexLog({ - cpuTime: { used: 8500, limit: 10000 }, // 85% - soqlQueries: { used: 90, limit: 100 }, // 90% - dmlStatements: { used: 135, limit: 150 }, // 90% - queryRows: { used: 45000, limit: 50000 }, // 90% - heapSize: { used: 5100000, limit: 6000000 }, // 85% - }); - - mockParse.mockReturnValue(mockLog); - mockExtractMethods.mockReturnValue([]); - - const result = await findPerformanceBottlenecks(args); - const parsedResult = toonDecode(result); - - // Every limit a dedicated section already spelled out is left out here rather - // than reported a second time: cpuTime by cpuBottlenecks, the rest by - // databaseBottlenecks. - expect(parsedResult.governorLimitWarnings!.cpuTime).toBeUndefined(); - expect(parsedResult.governorLimitWarnings!.soqlQueries).toBeUndefined(); - expect(parsedResult.governorLimitWarnings!.dmlStatements).toBeUndefined(); - expect(parsedResult.governorLimitWarnings!.queryRows).toBeUndefined(); - // heapSize has no dedicated section, so it is only reported here. - expect(parsedResult.governorLimitWarnings!.heapSize).toMatchObject({ - used: 5100000, - limit: 6000000, - }); - expect(parsedResult.databaseBottlenecks).toMatchObject({ - soqlQueries: { used: 90, limit: 100, percentage: 90 }, - dmlStatements: { used: 135, limit: 150, percentage: 90 }, - queryRows: { used: 45000, limit: 50000, percentage: 90 }, - }); - }); - - it("should not include governorLimitWarnings when usage is low (<=80%)", async () => { - const args: BottleneckArgs = { logFilePath: mockLogFilePath }; - - const mockLog = createMockApexLog({ - cpuTime: { used: 7000, limit: 10000 }, // 70% - soqlQueries: { used: 50, limit: 100 }, // 50% - dmlStatements: { used: 100, limit: 150 }, // 66.67% - queryRows: { used: 30000, limit: 50000 }, // 60% - }); - - mockParse.mockReturnValue(mockLog); - mockExtractMethods.mockReturnValue([]); - - const result = await findPerformanceBottlenecks(args); - const parsedResult = toonDecode(result); - - // No governor warnings when usage is low - expect(parsedResult).not.toHaveProperty("governorLimitWarnings"); - }); - - it("should not include governorLimitWarnings for zero limits", async () => { - const args: BottleneckArgs = { logFilePath: mockLogFilePath }; - - const mockLog = createMockApexLog({ - cpuTime: { used: 1000, limit: 0 }, - soqlQueries: { used: 10, limit: 0 }, - dmlStatements: { used: 5, limit: 0 }, - }); - - mockParse.mockReturnValue(mockLog); - mockExtractMethods.mockReturnValue([]); - - const result = await findPerformanceBottlenecks(args); - const parsedResult = toonDecode(result); - - expect(parsedResult).not.toHaveProperty("governorLimitWarnings"); - }); - - it("should not include governorLimitWarnings when usage is low", async () => { - const args: BottleneckArgs = { logFilePath: mockLogFilePath }; - - const customLimits = { - cpuTime: { used: 5000, limit: 10000 }, - soqlQueries: { used: 25, limit: 100 }, - dmlStatements: { used: 50, limit: 150 }, - }; - const mockLog = createMockApexLog(customLimits); - - mockParse.mockReturnValue(mockLog); - mockExtractMethods.mockReturnValue([]); - - const result = await findPerformanceBottlenecks(args); - const parsedResult = toonDecode(result); - - expect(parsedResult).not.toHaveProperty("governorLimitWarnings"); - }); - - it("should handle edge case of exactly 80% usage", async () => { - const args: BottleneckArgs = { logFilePath: mockLogFilePath }; - - const mockLog = createMockApexLog({ - cpuTime: { used: 8000, limit: 10000 }, // Exactly 80% - }); - - mockParse.mockReturnValue(mockLog); - mockExtractMethods.mockReturnValue([]); - - const result = await findPerformanceBottlenecks(args); - const parsedResult = toonDecode(result); + it("honours a caller threshold, and reports which one it used", async () => { + mockLog({ cpuTime: { used: 5000, limit: 10000 } }); - // Exactly 80% is not > 80% - expect(parsedResult).not.toHaveProperty("governorLimitWarnings"); - }); - - it("should handle edge case of just over 80% usage", async () => { - const args: BottleneckArgs = { logFilePath: mockLogFilePath }; - - const mockLog = createMockApexLog({ - cpuTime: { used: 8001, limit: 10000 }, // 80.01% - }); - - mockParse.mockReturnValue(mockLog); - mockExtractMethods.mockReturnValue([]); - - const result = await findPerformanceBottlenecks(args); - const parsedResult = toonDecode(result); - - // cpuTime should be in cpuBottlenecks, not in governorLimitWarnings (deduplicated) - expect(parsedResult).toHaveProperty("cpuBottlenecks"); - // governorLimitWarnings should not have cpuTime since it's deduplicated - if (parsedResult.governorLimitWarnings) { - expect(parsedResult.governorLimitWarnings.cpuTime).toBeUndefined(); - } + await expect(risks({ ...ARGS, threshold: 50 })).resolves.toEqual({ + threshold: 50, + atRisk: [ + { limit: "cpuTime", used: 5000, max: 10000, usedPercentage: 50 }, + ], }); }); - describe("Integration scenarios", () => { - it("should handle complex scenario with multiple bottlenecks", async () => { - const args: BottleneckArgs = { - logFilePath: mockLogFilePath, - analysisType: "all", - }; - - // Create a scenario with high usage across multiple areas - const mockLog = createMockApexLog({ - cpuTime: { used: 9500, limit: 10000 }, // 95% - High CPU - soqlQueries: { used: 95, limit: 100 }, // 95% - High SOQL - dmlStatements: { used: 140, limit: 150 }, // 93.33% - High DML - queryRows: { used: 48000, limit: 50000 }, // 96% - High query rows - heapSize: { used: 5500000, limit: 6000000 }, // 91.67% - High heap - }); - - const mockMethods = [ - { - name: "HighCPUMethod", - duration: 800000000, // 800ms - selfDuration: 600000000, - namespace: "Performance", - lineNumber: 100, - dmlCount: 15, // High DML - soqlCount: 20, // High SOQL - dmlRows: 2000, - soqlRows: 10000, // High rows - thrownCount: 0, - soslCount: 0, - soslRows: 0, - selfPercentage: 80, - }, - { - name: "DatabaseHeavyMethod", - duration: 150000000, // 150ms - selfDuration: 120000000, - namespace: "Database", - lineNumber: 200, - dmlCount: 25, // Very high DML - soqlCount: 30, // Very high SOQL - dmlRows: 5000, - soqlRows: 25000, // Very high rows - thrownCount: 0, - soslCount: 0, - soslRows: 0, - selfPercentage: 15, - }, - ]; - - mockParse.mockReturnValue(mockLog); - mockExtractMethods.mockReturnValue(mockMethods); - - const result = await findPerformanceBottlenecks(args); - const parsedResult = toonDecode(result); - const databaseBottlenecks = parsedResult.databaseBottlenecks as any; - const methodBottlenecks = parsedResult.methodBottlenecks as any; - - // Should identify all bottleneck types - expect(parsedResult.cpuBottlenecks!.warning).toBe( - "High CPU usage - consider optimizing algorithms", - ); - expect(parsedResult.cpuBottlenecks!.cpuUsagePercentage).toBe(95); - - // Database bottlenecks should show high usage - expect(databaseBottlenecks.soqlQueries.percentage).toBe(95); - expect(databaseBottlenecks.dmlStatements.percentage).toBeCloseTo( - 93.33, - 1, - ); - expect(databaseBottlenecks.queryRows.percentage).toBe(96); - - // Method analysis should show multiple namespaces - expect(methodBottlenecks.totalMethods).toBe(2); - expect(methodBottlenecks.methodsByNamespace).toHaveLength(2); - - // Only heapSize is left to warn about: every other limit over threshold was - // already detailed by the CPU or database section. - expect(parsedResult.governorLimitWarnings).toEqual({ - heapSize: { used: 5500000, limit: 6000000 }, - }); - }); - - it("should handle optimal performance scenario", async () => { - const args: BottleneckArgs = { - logFilePath: mockLogFilePath, - analysisType: "all", - }; - - // Create a scenario with low usage across all areas - const mockLog = createMockApexLog({ - cpuTime: { used: 1000, limit: 10000 }, // 10% - soqlQueries: { used: 5, limit: 100 }, // 5% - dmlStatements: { used: 10, limit: 150 }, // 6.67% - queryRows: { used: 1000, limit: 50000 }, // 2% - heapSize: { used: 500000, limit: 6000000 }, // 8.33% - }); - - const mockMethods = [ - { - name: "EfficientMethod", - duration: 50000000, // 50ms - selfDuration: 40000000, - namespace: "Optimized", - lineNumber: 50, - dmlCount: 1, - soqlCount: 1, - dmlRows: 10, - soqlRows: 100, - thrownCount: 0, - soslCount: 0, - soslRows: 0, - selfPercentage: 5, - }, - ]; - - mockParse.mockReturnValue(mockLog); - mockExtractMethods.mockReturnValue(mockMethods); + it("skips a limit the log gave no ceiling for", async () => { + mockLog({ cpuTime: { used: 9000, limit: 0 } }); - const result = await findPerformanceBottlenecks(args); - const parsedResult = toonDecode(result); - - // No CPU bottleneck (below 80%) — section omitted - expect(parsedResult).not.toHaveProperty("cpuBottlenecks"); - - // Low database usage - section omitted - expect(parsedResult).not.toHaveProperty("databaseBottlenecks"); - - // Method analysis still present - const methodBottlenecks = parsedResult.methodBottlenecks as any; - expect(methodBottlenecks.totalMethods).toBe(1); - - // No governor limit warnings - expect(parsedResult).not.toHaveProperty("governorLimitWarnings"); - }); + expect((await risks()).atRisk).toEqual([]); }); - describe("Type validation and edge cases", () => { - it("should validate that result has correct structure", async () => { - const args: BottleneckArgs = { logFilePath: mockLogFilePath }; - const mockLog = createMockApexLog(); + it("names the real cause when the log cannot be read", async () => { + mockFs.stat.mockRejectedValue( + Object.assign(new Error("ENOENT"), { code: "ENOENT" }), + ); - mockParse.mockReturnValue(mockLog); - mockExtractMethods.mockReturnValue([]); - - const result = await findPerformanceBottlenecks(args); - - // Validate top-level structure - expect(result).toHaveProperty("content"); - expect(result.content).toHaveLength(1); - expect(result.content[0]).toHaveProperty("type", "text"); - expect(result.content[0]).toHaveProperty("text"); - - // Validate structure — methodBottlenecks always present for "all" - const parsedResult = toonDecode(result); - expect(parsedResult).toHaveProperty("methodBottlenecks"); - }); - - it("should handle undefined values gracefully", async () => { - const args: BottleneckArgs = { logFilePath: mockLogFilePath }; - - // Create a mock log with some undefined/null values - const mockLog = createMockApexLog(); - mockLog.governorLimits.cpuTime = { used: 5000, limit: 10000 }; - - mockParse.mockReturnValue(mockLog); - mockExtractMethods.mockReturnValue([]); - - const result = await findPerformanceBottlenecks(args); - const parsedResult = toonDecode(result); - - // Should still work without errors - expect(parsedResult).toBeDefined(); - }); + await expect( + findPerformanceBottlenecks({ logFilePath: "/nonexistent/file.log" }), + ).rejects.toThrow("Log file not found: /nonexistent/file.log"); }); - - // Helper function for decoding TOON-formatted data - function toonDecode(result: any): BottleneckResult { - return decode(result.content[0].text) as unknown as BottleneckResult; - } }); diff --git a/tests/getLogSummary.test.ts b/tests/getLogSummary.test.ts index e63ea03..a0fb7a2 100644 --- a/tests/getLogSummary.test.ts +++ b/tests/getLogSummary.test.ts @@ -10,6 +10,7 @@ import { getLogSummaryToolConfig, } from "../src/tools/getLogSummary"; import { clearApexLogCache } from "../src/tools/apexLogSource"; +import { OPERATION_KINDS } from "../src/tools/operations"; import { parse, ApexLog, @@ -53,36 +54,38 @@ const mockStats = { ctimeNs: 1n, } as BigIntStats; -// Helper function to create a mock LogLine -const createMockLogLine = ( - type: string, - subCategory?: string, - children: LogLine[] = [], -): LogLine => +const counts = { total: 0, self: 0 }; + +/** A timed node, as the tools read one: a sub-category and its own time. */ +const node = ({ + type = null, + subCategory, + selfNs = 0, + children = [], + isTruncated = false, +}: { + type?: string | null; + subCategory?: string; + selfNs?: number; + children?: LogLine[]; + isTruncated?: boolean; +}): LogLine => ({ - type: type as any, - subCategory: subCategory as any, + type, + subCategory, children, - logParser: {} as ApexLogParser, - parent: null, - logLine: "", - text: "", + isTruncated, + text: type ?? "", + namespace: "default", lineNumber: null, - logCategory: null, - acceptsText: false, - isExit: false, - textData: "", - timestamp: 0, - dmlRowCount: { total: 0, self: 0 }, - soqlRowCount: { total: 0, self: 0 }, - soqlCount: { total: 0, self: 0 }, - dmlCount: { total: 0, self: 0 }, - soslCount: { total: 0, self: 0 }, - soslRowCount: { total: 0, self: 0 }, - cpuSelfTime: 0, - cpuTotalTime: 0, - parseTimestamp: () => 0, - parseLineNumber: () => null, + duration: { total: selfNs, self: selfNs }, + soqlCount: counts, + dmlCount: counts, + soslCount: counts, + soqlRowCount: counts, + dmlRowCount: counts, + soslRowCount: counts, + totalThrownCount: 0, }) as unknown as LogLine; describe("getLogSummary", () => { @@ -106,645 +109,326 @@ describe("getLogSummary", () => { return decode(result.content[0].text) as any; } - const createMockApexLog = (overrides: Partial = {}): ApexLog => { - const mockGovernorLimits: GovernorLimits = { - soqlQueries: { used: 5, limit: 100 }, - soslQueries: { used: 1, limit: 20 }, - queryRows: { used: 150, limit: 50000 }, - dmlStatements: { used: 3, limit: 150 }, - publishImmediateDml: { used: 0, limit: 10 }, - dmlRows: { used: 25, limit: 10000 }, - cpuTime: { used: 1500, limit: 10000 }, - heapSize: { used: 2048, limit: 6000000 }, - callouts: { used: 0, limit: 100 }, - emailInvocations: { used: 0, limit: 10 }, - futureCalls: { used: 0, limit: 50 }, - queueableJobsAddedToQueue: { used: 0, limit: 50 }, - mobileApexPushCalls: { used: 0, limit: 10 }, - byNamespace: new Map(), - }; - - const mockLogIssues: LogIssue[] = []; - const mockParsingErrors: string[] = []; - - // Create mock log lines with METHOD_ENTRY types for counting - const mockChildren: LogLine[] = [ - createMockLogLine("METHOD_ENTRY", undefined, [ - createMockLogLine("METHOD_ENTRY"), - createMockLogLine("STATEMENT_EXECUTE"), - ]), - createMockLogLine("SOQL_EXECUTE_BEGIN", "Method"), - createMockLogLine("DML_BEGIN"), - ]; - - // Create a proper mock ApexLog by extending the base structure - const baseMockApexLog = { - // ApexLog specific properties + const LIMIT_NAMES: (keyof Limits)[] = [ + "soqlQueries", + "soslQueries", + "queryRows", + "dmlStatements", + "publishImmediateDml", + "dmlRows", + "cpuTime", + "heapSize", + "callouts", + "emailInvocations", + "futureCalls", + "queueableJobsAddedToQueue", + "mobileApexPushCalls", + ]; + + const limitsOf = ( + used: Partial>, + limit = 100, + ): Limits => + Object.fromEntries( + LIMIT_NAMES.map((name) => [name, { used: used[name] ?? 0, limit }]), + ) as Limits; + + const governorLimitsOf = ( + used: Partial> = {}, + byNamespace = new Map(), + ): GovernorLimits => + ({ ...limitsOf(used), byNamespace }) as unknown as GovernorLimits; + + const createMockApexLog = (overrides: Partial = {}): ApexLog => + ({ type: null, text: "LOG_ROOT", - timestamp: 0, - exitStamp: 12500, size: 15000, debugLevels: [], namespaces: ["default", "MyNamespace"], - logIssues: mockLogIssues, - parsingErrors: mockParsingErrors, - governorLimits: mockGovernorLimits, - executionEndTime: 12500, - - // Method properties (ApexLog extends Method) - isTruncated: false, - exitTypes: ["EXECUTION_FINISHED"], - - // TimedNode properties (Method extends TimedNode) - subCategory: "Code Unit" as any, - cpuType: "" as any, - - // LogLine properties (TimedNode extends LogLine) + logIssues: [] as LogIssue[], + parsingErrors: [] as string[], + governorLimits: governorLimitsOf({ + soqlQueries: 5, + dmlStatements: 3, + cpuTime: 1500, + }), logParser: {} as ApexLogParser, parent: null, - children: mockChildren, - logLine: "", + children: [] as LogLine[], lineNumber: null, - logCategory: null, - acceptsText: false, - isExit: false, - textData: "", - - // Counting properties - duration: { total: 12500000000, self: 12500000000 }, - dmlRowCount: { total: 25, self: 25 }, - soqlRowCount: { total: 150, self: 150 }, - soqlCount: { total: 5, self: 5 }, - dmlCount: { total: 3, self: 3 }, - soslCount: { total: 1, self: 1 }, - soslRowCount: { total: 10, self: 10 }, - cpuSelfTime: 1500, - cpuTotalTime: 1500, - - // Methods that might be called - parseTimestamp: () => 0, - parseLineNumber: () => null, - setTimes: () => {}, - addChild: () => {}, - recalculateDurations: () => {}, - }; - - const defaultApexLog = { - ...baseMockApexLog, + duration: { total: 12_500_000_000, self: 12_500_000_000 }, ...overrides, - } as unknown as ApexLog; - - return defaultApexLog; - }; - - describe("successful log summary generation", () => { - it("should generate a complete log summary with valid log data", async () => { - const mockLogContent = "mock log content"; - const mockApexLog = createMockApexLog(); + }) as unknown as ApexLog; - mockFs.stat.mockResolvedValue(mockStats); - mockFs.readFile.mockResolvedValue(mockLogContent); - mockParse.mockReturnValue(mockApexLog); + const summaryOf = async ( + overrides: Partial = {}, + logFilePath = "/path/to/test-log.log", + ) => { + mockFs.stat.mockResolvedValue(mockStats); + mockFs.readFile.mockResolvedValue("mock log content"); + mockParse.mockReturnValue(createMockApexLog(overrides)); - const args: LogSummaryArgs = { - logFilePath: "/path/to/test-log.log", - }; + return toonDecode(await getLogSummary({ logFilePath } as LogSummaryArgs)); + }; - const result = await getLogSummary(args); + describe("the transaction", () => { + it("should report how big the log is, how long it ran and whether it is whole", async () => { + const summary = await summaryOf(); - expect(mockFs.stat).toHaveBeenCalledWith("/path/to/test-log.log", { bigint: true }); - expect(mockFs.readFile).toHaveBeenCalledWith( - "/path/to/test-log.log", - "utf-8", - ); - expect(mockParse).toHaveBeenCalledWith(mockLogContent); - - const parsedResult = toonDecode(result); - - expect(parsedResult.size).toBe(15000); - expect(parsedResult.totalExecutionTime).toBe(12500); // ms - expect(parsedResult.totalMethods).toBe(3); // 2 METHOD_ENTRY + 1 with subCategory 'Method' - expect(parsedResult.totalSOQLQueries).toBe(5); - expect(parsedResult.totalDMLOperations).toBe(3); - expect(parsedResult.totalSOQLRows).toBe(150); - expect(parsedResult.totalDMLRows).toBe(25); - expect(parsedResult.namespaces).toEqual(["default", "MyNamespace"]); - // The only omission: the log contained no issues, and an absent list says so. - expect(parsedResult.logIssues).toBeUndefined(); - expect(parsedResult.parsingErrors).toBe(0); - - // Every limit is a row, whether or not anything was spent against it. - expect(parsedResult.governorLimits).toHaveLength(13); - expect(parsedResult.governorLimits).toContainEqual({ - name: "cpuTime", - used: 1500, - limit: 10000, - }); - expect(parsedResult.governorLimits).toContainEqual({ - name: "dmlStatements", - used: 3, - limit: 150, - }); - expect(parsedResult.governorLimits).toContainEqual({ - name: "callouts", - used: 0, - limit: 100, + expect(mockFs.stat).toHaveBeenCalledWith("/path/to/test-log.log", { + bigint: true, }); + expect(mockParse).toHaveBeenCalledWith("mock log content"); + expect(summary.fileSizeBytes).toBe(15000); + expect(summary.durationTotalMs).toBe(12500); + expect(summary.truncated).toBe(false); + expect(summary.parsingErrorCount).toBe(0); + expect(summary.namespaces).toEqual(["default", "MyNamespace"]); }); - it("should report every log category and its level", async () => { - const mockApexLog = createMockApexLog({ - debugLevels: [ - { logCategory: "Apex_code", logLevel: "DEBUG" }, - { logCategory: "System", logLevel: "INFO" }, - { logCategory: "Callout", logLevel: "NONE" }, - { logCategory: "Workflow", logLevel: "NONE" }, - ] as any, + it("should say when the log stopped before the transaction did", async () => { + // The parser marks the line that lost its exit event. The root is never + // marked, so reading it there reports every truncated log as whole. + const summary = await summaryOf({ + children: [node({ subCategory: "Method", isTruncated: true })], }); - mockFs.stat.mockResolvedValue(mockStats); - mockFs.readFile.mockResolvedValue("mock log content"); - mockParse.mockReturnValue(mockApexLog); - - const args: LogSummaryArgs = { - logFilePath: "/path/to/debug-levels.log", - }; - - const result = await getLogSummary(args); - const parsedResult = toonDecode(result); + expect(summary.truncated).toBe(true); + }); + it("should report every log category and its level", async () => { // The levels tie log content to log configuration: what was captured, and // what is missing because a category was switched off. - expect(parsedResult.debugLevels).toEqual([ - { category: "Apex_code", level: "DEBUG" }, - { category: "System", level: "INFO" }, - { category: "Callout", level: "NONE" }, - { category: "Workflow", level: "NONE" }, - ]); - }); - - it("should handle logs with different namespaces", async () => { - const mockApexLog = createMockApexLog({ - namespaces: ["default", "CustomApp", "ThirdParty"], + const summary = await summaryOf({ + debugLevels: [ + { logCategory: "Apex_code", logLevel: "DEBUG" }, + { logCategory: "Db", logLevel: "NONE" }, + ] as any, }); - mockFs.stat.mockResolvedValue(mockStats); - mockFs.readFile.mockResolvedValue("mock log content"); - mockParse.mockReturnValue(mockApexLog); - - const args: LogSummaryArgs = { - logFilePath: "/path/to/namespace-test.log", - }; - - const result = await getLogSummary(args); - const parsedResult = toonDecode(result); - - expect(parsedResult.namespaces).toEqual([ - "default", - "CustomApp", - "ThirdParty", + expect(summary.debugLevels).toEqual([ + { logCategory: "Apex_code", level: "DEBUG" }, + { logCategory: "Db", level: "NONE" }, ]); }); - it("should include log issues as array of {type, summary} objects", async () => { - const mockLogIssues: LogIssue[] = [ - { - summary: "CPU time exceeded", - description: "Maximum CPU time limit exceeded", - type: "error", - startTime: 8000, - }, - ]; - - const mockApexLog = createMockApexLog({ - logIssues: mockLogIssues, + it("should report log issues and count parsing errors", async () => { + const summary = await summaryOf({ + logIssues: [ + { + summary: "CPU time exceeded", + description: "Maximum CPU time limit exceeded", + type: "error", + startTime: 8000, + }, + ] as LogIssue[], parsingErrors: ["Unknown log event type: CUSTOM_EVENT"], }); - mockFs.stat.mockResolvedValue(mockStats); - mockFs.readFile.mockResolvedValue("mock log content"); - mockParse.mockReturnValue(mockApexLog); - - const args: LogSummaryArgs = { - logFilePath: "/path/to/error-log.log", - }; - - const result = await getLogSummary(args); - const parsedResult = toonDecode(result); - - expect(parsedResult.logIssues).toEqual([ + expect(summary.logIssues).toEqual([ { type: "error", summary: "CPU time exceeded" }, ]); - expect(parsedResult.parsingErrors).toBe(1); + expect(summary.parsingErrorCount).toBe(1); }); - it("should count methods correctly with nested structures", async () => { - const mockChildren: LogLine[] = [ - createMockLogLine("METHOD_ENTRY", undefined, [ - createMockLogLine("METHOD_ENTRY", undefined, [ - createMockLogLine("METHOD_ENTRY"), - ]), - ]), - createMockLogLine("SOQL_EXECUTE_BEGIN", "Method", [ - createMockLogLine("CONSTRUCTOR_ENTRY", "Method"), - ]), - createMockLogLine("SOME_OTHER_EVENT"), - ]; - - const mockApexLog = createMockApexLog({ - children: mockChildren, - }); + it("should drop logIssues, the one occurrence list, when nothing occurred", async () => { + const summary = await summaryOf(); - mockFs.stat.mockResolvedValue(mockStats); - mockFs.readFile.mockResolvedValue("mock log content"); - mockParse.mockReturnValue(mockApexLog); - - const args: LogSummaryArgs = { - logFilePath: "/path/to/nested-methods.log", - }; + expect(summary.logIssues).toBeUndefined(); + // The rest are part of the fixed schema and report their emptiness. + expect(summary.parsingErrorCount).toBe(0); + }); - const result = await getLogSummary(args); - const parsedResult = toonDecode(result); + it("should not echo the log file path back to the caller", async () => { + // The caller supplied the path, so repeating it back only costs tokens. + const summary = await summaryOf({}, "/Users/test/apex-debug-123.log"); - // Should count: 3 METHOD_ENTRY + 1 with subCategory 'Method' + 1 CONSTRUCTOR_ENTRY with subCategory 'Method' = 5 - expect(parsedResult.totalMethods).toBe(5); + expect(summary.file).toBeUndefined(); + expect(summary.logFilePath).toBeUndefined(); }); + }); - it("should handle logs with zero values", async () => { - const emptyGovernorLimits: GovernorLimits = { - soqlQueries: { used: 0, limit: 0 }, - soslQueries: { used: 0, limit: 0 }, - queryRows: { used: 0, limit: 0 }, - dmlStatements: { used: 0, limit: 0 }, - publishImmediateDml: { used: 0, limit: 0 }, - dmlRows: { used: 0, limit: 0 }, - cpuTime: { used: 0, limit: 0 }, - heapSize: { used: 0, limit: 0 }, - callouts: { used: 0, limit: 0 }, - emailInvocations: { used: 0, limit: 0 }, - futureCalls: { used: 0, limit: 0 }, - queueableJobsAddedToQueue: { used: 0, limit: 0 }, - mobileApexPushCalls: { used: 0, limit: 0 }, - byNamespace: new Map(), - }; - - const mockApexLog = createMockApexLog({ - duration: { total: 0, self: 0 }, - soqlCount: { total: 0, self: 0 }, - dmlCount: { total: 0, self: 0 }, - soqlRowCount: { total: 0, self: 0 }, - dmlRowCount: { total: 0, self: 0 }, - governorLimits: emptyGovernorLimits, - namespaces: ["default"], - children: [], + describe("governorLimits", () => { + it("should report every limit as a row, including the ones at zero", async () => { + const summary = await summaryOf({ + governorLimits: governorLimitsOf({ cpuTime: 8000, soqlQueries: 50 }), }); - mockFs.stat.mockResolvedValue(mockStats); - mockFs.readFile.mockResolvedValue("mock log content"); - mockParse.mockReturnValue(mockApexLog); - - const args: LogSummaryArgs = { - logFilePath: "/path/to/empty-log.log", - }; - - const result = await getLogSummary(args); - const parsedResult = toonDecode(result); - - // "Nothing ran" is an answer, and only a reported zero gives it. An absent - // counter cannot be told apart from one the parser never populated. - expect(parsedResult.totalExecutionTime).toBe(0); - expect(parsedResult.totalMethods).toBe(0); - expect(parsedResult.totalSOQLQueries).toBe(0); - expect(parsedResult.totalDMLOperations).toBe(0); - expect(parsedResult.totalSOQLRows).toBe(0); - expect(parsedResult.totalDMLRows).toBe(0); - expect(parsedResult.governorLimits).toHaveLength(13); - expect(parsedResult.governorLimits).toContainEqual({ - name: "dmlStatements", + expect(summary.governorLimits).toHaveLength(LIMIT_NAMES.length); + expect(summary.governorLimits).toContainEqual({ + limit: "cpuTime", + used: 8000, + max: 100, + }); + // "No callouts were made" is an answer, and only a reported zero gives it. + expect(summary.governorLimits).toContainEqual({ + limit: "callouts", used: 0, - limit: 0, + max: 100, }); }); - it("should not echo the log file path back to the caller", async () => { - const paths = [ - "/Users/test/apex-debug-123.log", - "C:\\Logs\\production.log", - "/var/logs/debug-output.txt", - "simple.log", - ]; - - for (const logFilePath of paths) { - mockFs.stat.mockResolvedValue(mockStats); - mockFs.readFile.mockResolvedValue("mock log content"); - mockParse.mockReturnValue(createMockApexLog()); - - const result = await getLogSummary({ logFilePath }); - const parsedResult = toonDecode(result); - - // The caller supplied the path, so repeating it back only costs tokens. - expect(parsedResult.file).toBeUndefined(); - expect(mockFs.readFile).toHaveBeenCalledWith(logFilePath, "utf-8"); - } + it("should not report byNamespace as a limit", async () => { + const summary = await summaryOf(); + + expect( + summary.governorLimits.map((row: { limit: string }) => row.limit), + ).not.toContain("byNamespace"); }); }); - describe("error handling", () => { - it("should throw an error when log file does not exist", async () => { - const fileNotFoundError = new Error("ENOENT: no such file or directory"); - mockFs.stat.mockRejectedValue(fileNotFoundError); - - const args: LogSummaryArgs = { - logFilePath: "/path/to/nonexistent.log", - }; - - await expect(getLogSummary(args)).rejects.toThrow( - "Log file not found: /path/to/nonexistent.log", - ); + describe("limitsByNamespace", () => { + it("should report what each namespace consumed", async () => { + const summary = await summaryOf({ + governorLimits: governorLimitsOf( + { soqlQueries: 6, cpuTime: 1500 }, + new Map([ + ["srm_pkg", limitsOf({ soqlQueries: 4, cpuTime: 900 })], + ["default", limitsOf({ soqlQueries: 2 })], + ]), + ), + }); - expect(mockFs.stat).toHaveBeenCalledWith("/path/to/nonexistent.log", { bigint: true }); - expect(mockFs.readFile).not.toHaveBeenCalled(); - expect(mockParse).not.toHaveBeenCalled(); + expect(summary.limitsByNamespace).toEqual([ + { namespace: "srm_pkg", limit: "soqlQueries", used: 4 }, + { namespace: "srm_pkg", limit: "cpuTime", used: 900 }, + { namespace: "default", limit: "soqlQueries", used: 2 }, + ]); }); - it("should throw an error when file access check fails for other reasons", async () => { - const permissionError = new Error("EACCES: permission denied"); - mockFs.stat.mockRejectedValue(permissionError); - - const args: LogSummaryArgs = { - logFilePath: "/path/to/restricted.log", - }; - - await expect(getLogSummary(args)).rejects.toThrow( - "Log file not found: /path/to/restricted.log", - ); + it("should report no rows when the log attributed nothing to a namespace", async () => { + expect((await summaryOf()).limitsByNamespace).toEqual([]); }); + }); - it("should propagate file read errors", async () => { - mockFs.stat.mockResolvedValue(mockStats); - const readError = new Error("Failed to read file"); - mockFs.readFile.mockRejectedValue(readError); - - const args: LogSummaryArgs = { - logFilePath: "/path/to/unreadable.log", - }; - - await expect(getLogSummary(args)).rejects.toThrow("Failed to read file"); + describe("timeByKind", () => { + it("should report a row for every kind, so a zero can be read", async () => { + const summary = await summaryOf(); - expect(mockFs.stat).toHaveBeenCalledWith("/path/to/unreadable.log", { bigint: true }); - expect(mockFs.readFile).toHaveBeenCalledWith( - "/path/to/unreadable.log", - "utf-8", + expect(summary.timeByKind.map((row: { kind: string }) => row.kind)).toEqual( + [...OPERATION_KINDS], ); - expect(mockParse).not.toHaveBeenCalled(); }); - it("should propagate parsing errors", async () => { - mockFs.stat.mockResolvedValue(mockStats); - mockFs.readFile.mockResolvedValue("invalid log content"); - const parseError = new Error("Failed to parse log"); - mockParse.mockImplementation(() => { - throw parseError; + it("should count the operations of a kind and sum their self time", async () => { + const summary = await summaryOf({ + children: [ + node({ + type: "METHOD_ENTRY", + subCategory: "Method", + selfNs: 2_000_000_000, + children: [ + node({ + type: "SOQL_EXECUTE_BEGIN", + subCategory: "SOQL", + selfNs: 1_000_000_000, + }), + ], + }), + node({ + type: "METHOD_ENTRY", + subCategory: "Method", + selfNs: 500_000_000, + }), + ], }); - const args: LogSummaryArgs = { - logFilePath: "/path/to/corrupted.log", - }; + const rowOf = (kind: string) => + summary.timeByKind.find((row: { kind: string }) => row.kind === kind); - await expect(getLogSummary(args)).rejects.toThrow("Failed to parse log"); - - expect(mockFs.stat).toHaveBeenCalledWith("/path/to/corrupted.log", { bigint: true }); - expect(mockFs.readFile).toHaveBeenCalledWith( - "/path/to/corrupted.log", - "utf-8", - ); - expect(mockParse).toHaveBeenCalledWith("invalid log content"); - }); - - it("should handle undefined or null properties gracefully", async () => { - // Create an ApexLog with some undefined/null properties to test resilience - const mockApexLog = createMockApexLog({ - namespaces: [], // empty namespaces array - logIssues: [], // empty log issues - parsingErrors: [], // empty parsing errors + expect(rowOf("method")).toEqual({ + kind: "method", + logCategory: "APEX_CODE", + operationCount: 2, + durationSelfMs: 2500, + selfPercentage: 20, }); + expect(rowOf("soql")).toEqual({ + kind: "soql", + logCategory: "DB", + operationCount: 1, + durationSelfMs: 1000, + selfPercentage: 8, + }); + }); - mockFs.stat.mockResolvedValue(mockStats); - mockFs.readFile.mockResolvedValue("mock log content"); - mockParse.mockReturnValue(mockApexLog); - - const args: LogSummaryArgs = { - logFilePath: "/path/to/edge-case.log", - }; - - const result = await getLogSummary(args); - const parsedResult = toonDecode(result); + it("should name the trace category that decides whether a kind was logged", async () => { + // A `soql 0` row beside `DB NONE` means the queries were not logged; the + // same row beside `DB FINEST` means none ran. + const summary = await summaryOf(); + const rowOf = (kind: string) => + summary.timeByKind.find((row: { kind: string }) => row.kind === kind); - // `logIssues` is the one occurrence list, so it is the one key that goes - // away. The rest are part of the fixed schema and report their emptiness. - expect(parsedResult.logIssues).toBeUndefined(); - expect(parsedResult.namespaces).toEqual([]); - expect(parsedResult.parsingErrors).toBe(0); + expect(rowOf("soql").logCategory).toBe("DB"); + expect(rowOf("systemMethod").logCategory).toBe("SYSTEM"); + expect(rowOf("workflow").logCategory).toBe("WORKFLOW"); }); - }); - describe("method counting functionality", () => { - it("should count only METHOD_ENTRY types and subCategory Method nodes", async () => { - const mockChildren: LogLine[] = [ - createMockLogLine("METHOD_ENTRY"), - createMockLogLine("CONSTRUCTOR_ENTRY"), - createMockLogLine("SYSTEM_METHOD_ENTRY", "Method"), - createMockLogLine("SOQL_EXECUTE_BEGIN", "SOQL"), - createMockLogLine("DML_BEGIN", "DML"), - createMockLogLine("USER_DEBUG"), - ]; - - const mockApexLog = createMockApexLog({ - children: mockChildren, + it("should report zeros rather than divide by a log that ran no time", async () => { + const summary = await summaryOf({ + duration: { total: 0, self: 0 }, + children: [], }); - mockFs.stat.mockResolvedValue(mockStats); - mockFs.readFile.mockResolvedValue("mock log content"); - mockParse.mockReturnValue(mockApexLog); - - const args: LogSummaryArgs = { - logFilePath: "/path/to/method-counting.log", - }; - - const result = await getLogSummary(args); - const parsedResult = toonDecode(result); - - // Should count: 1 METHOD_ENTRY + 1 with subCategory 'Method' = 2 - expect(parsedResult.totalMethods).toBe(2); + expect(summary.durationTotalMs).toBe(0); + summary.timeByKind.forEach( + (row: { operationCount: number; selfPercentage: number }) => { + expect(row.operationCount).toBe(0); + expect(row.selfPercentage).toBe(0); + }, + ); }); + }); - it("should handle deeply nested method structures", async () => { - const createNestedStructure = (depth: number): LogLine => { - if (depth === 0) { - return createMockLogLine("METHOD_ENTRY"); - } - return createMockLogLine("METHOD_ENTRY", undefined, [ - createNestedStructure(depth - 1), - ]); - }; - - const mockChildren: LogLine[] = [ - createNestedStructure(5), // Creates a 6-level deep nested structure - createMockLogLine("SOME_OTHER_EVENT", "Method", [ - createMockLogLine("METHOD_ENTRY"), - ]), - ]; - - const mockApexLog = createMockApexLog({ - children: mockChildren, - }); - - mockFs.stat.mockResolvedValue(mockStats); - mockFs.readFile.mockResolvedValue("mock log content"); - mockParse.mockReturnValue(mockApexLog); + describe("error handling", () => { + it("should throw an error when log file does not exist", async () => { + mockFs.stat.mockRejectedValue( + Object.assign(new Error("ENOENT: no such file or directory"), { + code: "ENOENT", + }), + ); - const args: LogSummaryArgs = { - logFilePath: "/path/to/deep-nested.log", - }; + await expect( + getLogSummary({ logFilePath: "/path/to/nonexistent.log" }), + ).rejects.toThrow("Log file not found: /path/to/nonexistent.log"); + expect(mockFs.readFile).not.toHaveBeenCalled(); + expect(mockParse).not.toHaveBeenCalled(); + }); - const result = await getLogSummary(args); - const parsedResult = toonDecode(result); + it("names the cause when the file is there but cannot be opened", async () => { + mockFs.stat.mockRejectedValue( + Object.assign(new Error("EACCES: permission denied"), { + code: "EACCES", + }), + ); - // Should count: 6 METHOD_ENTRY nodes + 1 with subCategory 'Method' + 1 nested METHOD_ENTRY = 8 - expect(parsedResult.totalMethods).toBe(8); + await expect( + getLogSummary({ logFilePath: "/path/to/restricted.log" }), + ).rejects.toThrow("Cannot read log file /path/to/restricted.log: EACCES"); }); - it("should not count non-method events", async () => { - const mockChildren: LogLine[] = [ - createMockLogLine("EXECUTION_STARTED"), - createMockLogLine("EXECUTION_FINISHED"), - createMockLogLine("USER_DEBUG"), - createMockLogLine("HEAP_ALLOCATE"), - createMockLogLine("STATEMENT_EXECUTE"), - ]; - - const mockApexLog = createMockApexLog({ - children: mockChildren, - }); - + it("should propagate file read errors", async () => { mockFs.stat.mockResolvedValue(mockStats); - mockFs.readFile.mockResolvedValue("mock log content"); - mockParse.mockReturnValue(mockApexLog); - - const args: LogSummaryArgs = { - logFilePath: "/path/to/non-methods.log", - }; + mockFs.readFile.mockRejectedValue(new Error("Failed to read file")); - const result = await getLogSummary(args); - const parsedResult = toonDecode(result); - - expect(parsedResult.totalMethods).toBe(0); + await expect( + getLogSummary({ logFilePath: "/path/to/unreadable.log" }), + ).rejects.toThrow("Failed to read file"); + expect(mockParse).not.toHaveBeenCalled(); }); - }); - - describe("governor limits handling", () => { - it("should report every governor limit as a row", async () => { - const customGovernorLimits: GovernorLimits = { - soqlQueries: { used: 50, limit: 100 }, - soslQueries: { used: 5, limit: 20 }, - queryRows: { used: 2500, limit: 50000 }, - dmlStatements: { used: 25, limit: 150 }, - publishImmediateDml: { used: 2, limit: 10 }, - dmlRows: { used: 500, limit: 10000 }, - cpuTime: { used: 8000, limit: 10000 }, - heapSize: { used: 5000000, limit: 6000000 }, - callouts: { used: 3, limit: 100 }, - emailInvocations: { used: 1, limit: 10 }, - futureCalls: { used: 2, limit: 50 }, - queueableJobsAddedToQueue: { used: 1, limit: 50 }, - mobileApexPushCalls: { used: 0, limit: 10 }, - byNamespace: new Map(), - }; - - const mockApexLog = createMockApexLog({ - governorLimits: customGovernorLimits, - }); + it("should propagate parsing errors", async () => { mockFs.stat.mockResolvedValue(mockStats); - mockFs.readFile.mockResolvedValue("mock log content"); - mockParse.mockReturnValue(mockApexLog); - - const args: LogSummaryArgs = { - logFilePath: "/path/to/governor-limits.log", - }; - - const result = await getLogSummary(args); - const parsedResult = toonDecode(result); - - // The whole fixed set, flattened to rows that share three keys so TOON can - // emit one header and one line per limit. - expect(parsedResult.governorLimits).toEqual([ - { name: "soqlQueries", used: 50, limit: 100 }, - { name: "soslQueries", used: 5, limit: 20 }, - { name: "queryRows", used: 2500, limit: 50000 }, - { name: "dmlStatements", used: 25, limit: 150 }, - { name: "publishImmediateDml", used: 2, limit: 10 }, - { name: "dmlRows", used: 500, limit: 10000 }, - { name: "cpuTime", used: 8000, limit: 10000 }, - { name: "heapSize", used: 5000000, limit: 6000000 }, - { name: "callouts", used: 3, limit: 100 }, - { name: "emailInvocations", used: 1, limit: 10 }, - { name: "futureCalls", used: 2, limit: 50 }, - { name: "queueableJobsAddedToQueue", used: 1, limit: 50 }, - // Nothing was spent against this one, and the row says exactly that. - { name: "mobileApexPushCalls", used: 0, limit: 10 }, - ]); - }); - - it("should handle maximum governor limit values", async () => { - const maxGovernorLimits: GovernorLimits = { - soqlQueries: { used: 100, limit: 100 }, - soslQueries: { used: 20, limit: 20 }, - queryRows: { used: 50000, limit: 50000 }, - dmlStatements: { used: 150, limit: 150 }, - publishImmediateDml: { used: 10, limit: 10 }, - dmlRows: { used: 10000, limit: 10000 }, - cpuTime: { used: 10000, limit: 10000 }, - heapSize: { used: 6000000, limit: 6000000 }, - callouts: { used: 100, limit: 100 }, - emailInvocations: { used: 10, limit: 10 }, - futureCalls: { used: 50, limit: 50 }, - queueableJobsAddedToQueue: { used: 50, limit: 50 }, - mobileApexPushCalls: { used: 10, limit: 10 }, - byNamespace: new Map(), - }; - - const mockApexLog = createMockApexLog({ - governorLimits: maxGovernorLimits, + mockFs.readFile.mockResolvedValue("invalid log content"); + mockParse.mockImplementation(() => { + throw new Error("Failed to parse log"); }); - mockFs.stat.mockResolvedValue(mockStats); - mockFs.readFile.mockResolvedValue("mock log content"); - mockParse.mockReturnValue(mockApexLog); - - const args: LogSummaryArgs = { - logFilePath: "/path/to/max-limits.log", - }; - - const result = await getLogSummary(args); - const parsedResult = toonDecode(result); - - // Every limit is at its ceiling, so `used` and `limit` match on every row. - expect(parsedResult.governorLimits).toHaveLength(13); - for (const row of parsedResult.governorLimits) { - expect(row.used).toBe(row.limit); - } - expect(parsedResult.governorLimits).toContainEqual({ - name: "cpuTime", - used: 10000, - limit: 10000, - }); - expect(parsedResult.governorLimits).toContainEqual({ - name: "heapSize", - used: 6000000, - limit: 6000000, - }); + await expect( + getLogSummary({ logFilePath: "/path/to/corrupted.log" }), + ).rejects.toThrow("Failed to parse log"); + expect(mockParse).toHaveBeenCalledWith("invalid log content"); }); }); }); diff --git a/tests/operations.test.ts b/tests/operations.test.ts new file mode 100644 index 0000000..5998777 --- /dev/null +++ b/tests/operations.test.ts @@ -0,0 +1,225 @@ +/* + * Copyright (c) 2025 Certinia Inc. All rights reserved. + */ + +import type { ApexLog } from "../src/ApexLogParser"; +import { + groupOperations, + listOperations, + logCategoryOf, + OPERATION_KINDS, + type Operation, +} from "../src/tools/operations"; + +type NodeSpec = { + type?: string | null; + subCategory?: string; + text?: string | null; + namespace?: string | null; + lineNumber?: number | string | null; + totalNs?: number; + selfNs?: number; + soqlCount?: number; + dmlCount?: number; + soslCount?: number; + soqlRowCount?: number; + dmlRowCount?: number; + soslRowCount?: number; + thrownCount?: number; + children?: NodeSpec[]; +}; + +function node(spec: NodeSpec): unknown { + const total = spec.totalNs ?? 0; + return { + type: spec.type ?? null, + ...(spec.subCategory && { subCategory: spec.subCategory }), + text: spec.text ?? null, + namespace: spec.namespace ?? "default", + lineNumber: spec.lineNumber ?? null, + duration: { total, self: spec.selfNs ?? total }, + soqlCount: { total: spec.soqlCount ?? 0, self: 0 }, + dmlCount: { total: spec.dmlCount ?? 0, self: 0 }, + soslCount: { total: spec.soslCount ?? 0, self: 0 }, + soqlRowCount: { total: spec.soqlRowCount ?? 0, self: 0 }, + dmlRowCount: { total: spec.dmlRowCount ?? 0, self: 0 }, + soslRowCount: { total: spec.soslRowCount ?? 0, self: 0 }, + totalThrownCount: spec.thrownCount ?? 0, + children: (spec.children ?? []).map(node), + }; +} + +/** A log whose root is the transaction frame the parser always emits. */ +function logOf(...children: NodeSpec[]): ApexLog { + return node({ + type: "EXECUTION_STARTED", + text: "Root", + totalNs: 1_000_000_000, + children, + }) as ApexLog; +} + +const named = (operations: Operation[]) => operations.map((o) => o.name); + +describe("listOperations", () => { + it("ranks a query and a DML alongside methods, not below them", () => { + const operations = listOperations( + logOf( + { type: "METHOD_ENTRY", subCategory: "Method", text: "A.run" }, + { type: "SOQL_EXECUTE_BEGIN", subCategory: "SOQL", text: "SELECT Id" }, + { type: "DML_BEGIN", subCategory: "DML", text: "DML Insert Account" }, + ), + ); + + expect(operations.map((o) => o.kind)).toEqual(["method", "soql", "dml"]); + }); + + it.each([ + ["CODE_UNIT_STARTED", "Code Unit", "codeUnit"], + ["ENTERING_MANAGED_PKG", "Method", "managedPackage"], + ["METHOD_ENTRY", "Method", "method"], + ["SYSTEM_METHOD_ENTRY", "System Method", "systemMethod"], + ["SOQL_EXECUTE_BEGIN", "SOQL", "soql"], + ["SOSL_EXECUTE_BEGIN", "SOQL", "sosl"], + ["DML_BEGIN", "DML", "dml"], + ["FLOW_ELEMENT_BEGIN", "Flow", "flow"], + ["WF_RULE_EVAL_BEGIN", "Workflow", "workflow"], + ])("classifies %s as %s", (type, subCategory, kind) => { + const [operation] = listOperations(logOf({ type, subCategory })); + + expect(operation?.kind).toBe(kind); + }); + + it("covers every kind it declares", () => { + expect(new Set(OPERATION_KINDS).size).toBe(OPERATION_KINDS.length); + OPERATION_KINDS.forEach((kind) => expect(logCategoryOf(kind)).toBeTruthy()); + }); + + it("drops the transaction frame, which owns no time of its own", () => { + const operations = listOperations( + logOf({ + type: "EXECUTION_STARTED", + subCategory: "Method", + text: "Root", + }), + ); + + expect(operations).toEqual([]); + }); + + it("drops the root, which the parser adds and which holds the whole log", () => { + const root = node({ + type: null, + subCategory: "Method", + text: "LOG_ROOT", + totalNs: 1_000_000_000, + }) as ApexLog; + + expect(listOperations(root)).toEqual([]); + }); + + it("drops an untimed node, which has no sub-category", () => { + expect(listOperations(logOf({ type: "USER_INFO" }))).toEqual([]); + }); + + it("visits children, so a query inside a method is its own row", () => { + const operations = listOperations( + logOf({ + type: "METHOD_ENTRY", + subCategory: "Method", + text: "A.run", + children: [ + { type: "SOQL_EXECUTE_BEGIN", subCategory: "SOQL", text: "SELECT Id" }, + ], + }), + ); + + expect(named(operations)).toEqual(["A.run", "SELECT Id"]); + }); + + it("sums the rows an operation queried, searched and wrote", () => { + const [operation] = listOperations( + logOf({ + type: "METHOD_ENTRY", + subCategory: "Method", + soqlRowCount: 100, + dmlRowCount: 20, + soslRowCount: 3, + }), + ); + + expect(operation?.rowCount).toBe(123); + }); + + it("names an operation by its type when the parser gave it no text", () => { + const [operation] = listOperations( + logOf({ type: "METHOD_ENTRY", subCategory: "Method", text: null }), + ); + + expect(operation).toMatchObject({ + name: "METHOD_ENTRY", + namespace: "default", + }); + }); +}); + +describe("groupOperations", () => { + const repeatedQuery = (namespace: string, lineNumber: number) => ({ + type: "SOQL_EXECUTE_BEGIN", + subCategory: "SOQL", + text: "SELECT Id FROM Account", + namespace, + lineNumber, + totalNs: 10_000_000, + soqlCount: 1, + soqlRowCount: 5, + }); + + it("folds a query repeated in a loop into one row carrying its call count", () => { + const operations = listOperations( + logOf(repeatedQuery("default", 12), repeatedQuery("default", 12)), + ); + + expect(groupOperations(operations, "name")).toEqual([ + expect.objectContaining({ + name: "SELECT Id FROM Account", + callCount: 2, + durationTotalNs: 20_000_000, + soqlCount: 2, + rowCount: 10, + lineNumber: null, + }), + ]); + }); + + it("keeps the line number while a row is still one call", () => { + const operations = listOperations(logOf(repeatedQuery("default", 12))); + + expect(groupOperations(operations, "name")[0]?.lineNumber).toBe(12); + }); + + it("groups by namespace, and names the row after it", () => { + const operations = listOperations( + logOf(repeatedQuery("default", 1), repeatedQuery("Custom", 2)), + ); + + expect(groupOperations(operations, "namespace")).toEqual([ + expect.objectContaining({ name: "default", callCount: 1 }), + expect.objectContaining({ name: "Custom", callCount: 1 }), + ]); + }); + + it("keeps kinds apart, so every column stays true of every row", () => { + const operations = listOperations( + logOf( + { type: "METHOD_ENTRY", subCategory: "Method", namespace: "Custom" }, + repeatedQuery("Custom", 3), + ), + ); + + expect(groupOperations(operations, "namespace").map((o) => o.kind)).toEqual([ + "method", + "soql", + ]); + }); +}); diff --git a/tests/responseShaping.test.ts b/tests/responseShaping.test.ts index f638297..e52138e 100644 --- a/tests/responseShaping.test.ts +++ b/tests/responseShaping.test.ts @@ -7,6 +7,7 @@ import { roundMs, roundPercent, toLimitRows, + toNamespaceLimitRows, } from "../src/tools/responseShaping"; import type { GovernorLimits, Limits } from "../src/ApexLogParser"; @@ -52,41 +53,38 @@ describe("responseShaping", () => { }); }); - describe("toLimitRows", () => { - const limitNames: (keyof Limits)[] = [ - "soqlQueries", - "soslQueries", - "queryRows", - "dmlStatements", - "publishImmediateDml", - "dmlRows", - "cpuTime", - "heapSize", - "callouts", - "emailInvocations", - "futureCalls", - "queueableJobsAddedToQueue", - "mobileApexPushCalls", - ]; - - const buildLimits = ( - used: Partial> = {}, - ): GovernorLimits => - ({ - ...Object.fromEntries( - limitNames.map((name) => [ - name, - { used: used[name] ?? 0, limit: 100 }, - ]), - ), - byNamespace: new Map(), - }) as GovernorLimits; + const limitNames: (keyof Limits)[] = [ + "soqlQueries", + "soslQueries", + "queryRows", + "dmlStatements", + "publishImmediateDml", + "dmlRows", + "cpuTime", + "heapSize", + "callouts", + "emailInvocations", + "futureCalls", + "queueableJobsAddedToQueue", + "mobileApexPushCalls", + ]; + + const limitsOf = (used: Partial>): Limits => + Object.fromEntries( + limitNames.map((name) => [name, { used: used[name] ?? 0, limit: 100 }]), + ) as Limits; + + const buildLimits = ( + used: Partial> = {}, + ): GovernorLimits => + ({ ...limitsOf(used), byNamespace: new Map() }) as GovernorLimits; + describe("toLimitRows", () => { it("should return one row per limit in parser order", () => { const rows = toLimitRows(buildLimits()); expect(rows).toHaveLength(limitNames.length); - expect(rows.map((row) => row.name)).toEqual(limitNames); + expect(rows.map((row) => row.limit)).toEqual(limitNames); }); it("should keep a limit nothing was spent against", () => { @@ -95,17 +93,58 @@ describe("responseShaping", () => { const rows = toLimitRows(buildLimits({ cpuTime: 15163 })); expect(rows).toContainEqual({ - name: "dmlStatements", + limit: "dmlStatements", used: 0, - limit: 100, + max: 100, }); - expect(rows).toContainEqual({ name: "cpuTime", used: 15163, limit: 100 }); + expect(rows).toContainEqual({ limit: "cpuTime", used: 15163, max: 100 }); }); it("should skip byNamespace, which is not a limit", () => { - expect(toLimitRows(buildLimits()).map((row) => row.name)).not.toContain( + expect(toLimitRows(buildLimits()).map((row) => row.limit)).not.toContain( "byNamespace", ); }); }); + + describe("toNamespaceLimitRows", () => { + it("should report one row per limit a namespace consumed", () => { + const rows = toNamespaceLimitRows( + new Map([ + ["srm_pkg", limitsOf({ soqlQueries: 4, cpuTime: 900 })], + ["default", limitsOf({ dmlStatements: 2 })], + ]), + ); + + expect(rows).toEqual([ + { namespace: "srm_pkg", limit: "soqlQueries", used: 4 }, + { namespace: "srm_pkg", limit: "cpuTime", used: 900 }, + { namespace: "default", limit: "dmlStatements", used: 2 }, + ]); + }); + + it("should drop the limits a namespace did not consume", () => { + // A row here is an occurrence. Whether a limit was measured at all is a + // property of the transaction, and the whole-log table answers that. + const rows = toNamespaceLimitRows( + new Map([["srm_pkg", limitsOf({ cpuTime: 900 })]]), + ); + + expect(rows).toEqual([ + { namespace: "srm_pkg", limit: "cpuTime", used: 900 }, + ]); + }); + + it("should not repeat the ceiling, which belongs to the transaction", () => { + const [row] = toNamespaceLimitRows( + new Map([["srm_pkg", limitsOf({ cpuTime: 900 })]]), + ); + + expect(row).not.toHaveProperty("max"); + }); + + it("should return no rows when the log named no namespace", () => { + expect(toNamespaceLimitRows(new Map())).toEqual([]); + }); + }); }); diff --git a/tests/server.test.ts b/tests/server.test.ts index bde443a..7f0472d 100644 --- a/tests/server.test.ts +++ b/tests/server.test.ts @@ -101,11 +101,9 @@ describe("ApexLogServer", () => { { type: "text" as const, text: JSON.stringify({ - totalMethods: 5, - totalExecutionTime: 1000000, - slowestMethods: [], - summary: "Test summary", - recommendations: [], + durationTotalMs: 1000, + returnedSelfPercentage: 0, + operations: [], }), }, ], @@ -130,9 +128,8 @@ describe("ApexLogServer", () => { { type: "text" as const, text: JSON.stringify({ - cpuBottlenecks: {}, - databaseBottlenecks: {}, - governorLimitWarnings: {}, + threshold: 80, + atRisk: [], }), }, ], @@ -213,6 +210,7 @@ describe("ApexLogServer", () => { afterEach(() => { jest.clearAllMocks(); process.removeAllListeners("SIGINT"); + process.removeAllListeners("SIGTERM"); }); afterAll(() => { @@ -253,15 +251,12 @@ describe("ApexLogServer", () => { expect(mockConsoleError).toHaveBeenCalledWith("[MCP Error]", testError); }); - it("should setup SIGINT handler", async () => { + it.each(["SIGINT", "SIGTERM"])("closes cleanly on %s", async (signal) => { const mockProcessOnce = jest.spyOn(process, "once"); new ApexLogServer(); - expect(mockProcessOnce).toHaveBeenCalledWith( - "SIGINT", - expect.any(Function), - ); + expect(mockProcessOnce).toHaveBeenCalledWith(signal, expect.any(Function)); }); }); @@ -326,7 +321,7 @@ describe("ApexLogServer", () => { const tool = registeredTools.get("analyze_apex_log_performance")!; const args = { logFilePath: "/path/to/test.log", - topMethods: 5, + limit: 5, }; const result = await tool.callback(args, {} as any); @@ -353,7 +348,7 @@ describe("ApexLogServer", () => { const tool = registeredTools.get("find_performance_bottlenecks")!; const args = { logFilePath: "/path/to/test.log", - analysisType: "cpu", + threshold: 90, }; const result = await tool.callback(args, {} as any); @@ -491,8 +486,8 @@ describe("ApexLogServer", () => { const tool = registeredTools.get("analyze_apex_log_performance")!; const args = { logFilePath: "/path/to/test.log", - topMethods: 10, - minDuration: 1000, + limit: 10, + minSelfMs: 1000, }; const result = await tool.callback(args, {} as any); @@ -524,7 +519,7 @@ describe("ApexLogServer", () => { const tool = registeredTools.get("find_performance_bottlenecks")!; const args = { logFilePath: "/path/to/test.log", - analysisType: "database" as const, + threshold: 50, }; await tool.callback(args, {} as any);