Skip to content

fix: methodBottlenecks.totalDuration double counts nested methods #101

Description

@lukecotter

What happened?

methodBottlenecks.methodsByNamespace[].totalDuration in find_performance_bottlenecks sums each
method's total duration, so time spent in a nested method is counted once for that method and
again for every ancestor above it. The reported figure is therefore far larger than the transaction
it describes, and it grows with call depth rather than with cost.

src/tools/findPerformanceBottlenecks.ts:184-187:

totalDuration: roundMs(
  group.reduce((sum: number, m: SlowMethod) => sum + m.duration, 0) / NS_TO_MS,
),

SlowMethod.duration is node.duration.total (src/tools/analyzeLogPerformance.ts). The same
object already carries selfDuration, which is node.duration.self.

An agent that adds the namespace rows to get a transaction total, or that reads a percentage from
them, is misled. A namespace can appear to use more time than the whole run.

Steps to reproduce

  1. pnpm run build
  2. Call find_performance_bottlenecks on tests/eval/fixtures/governor-heavy.log.
  3. Compare methodBottlenecks against totalExecutionTime from get_apex_log_summary on the same
    log.

Input & output

The committed goldens disagree with each other.

tests/eval/golden/find_performance_bottlenecks.governor-heavy.expected.txt:

methodBottlenecks:
  totalMethods: 13
  methodsByNamespace[3]{namespace,methodCount,totalDuration}:
    default,8,76786.322
    core_pkg,3,148.619
    srm_pkg,2,20489.42

tests/eval/golden/get_apex_log_summary.governor-heavy.expected.txt:

totalExecutionTime: 24608.108

Eight methods in the default namespace are credited with 76,786 ms of a 24,608 ms transaction —
about 3.1 times the whole run. The three namespaces sum to 97,424 ms, close to 4 times.

Version & environment

main, and every version since the section was added. Reproduces from the committed fixtures alone,
so no org and no Salesforce release is involved.

Do

Sum selfDuration, the same way analyze_apex_log_performance derives
topMethodsSelfPercentage. Self time partitions the transaction, so the namespace rows then add up
to at most the total and each one is a share a caller can reason about.

Then re-record with pnpm run build && pnpm run eval:update. Three golden figures move and no field
is added or removed, so TOKEN_BUDGET is unaffected.

Worth an ANSWERABILITY question or a unit test that pins the sum of the namespace rows at or below
totalExecutionTime. The defect survived because nothing compared the two.

Metadata

Metadata

Assignees

No one assigned

    Labels

    bugSomething isn't working

    Type

    Projects

    No projects

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions