Possible wrong Total Time with recursions

[KMakowsky]

I wrote a simple script to check how the "Total Time" is presented while using recursive functions.

function fac(n) {
	if (n === 1) {
		return 1
	}
	return fac(n - 1) * n
}

function doStuff() {
	for (let i = 0; i < 100000; i++) {
		fac(10)
	}
}
doStuff()

And cpu profiled it with
node --cpu-prof --cpu-prof-interval=1 scripts/test.js
profile.cpuprofile

As it turns out, the Total Time of the fac method is a lot higher than expected. (The total time of the cpuprofile is 16.166ms)
In general I don't really get what the Total Time tries to represent.

So I looked into the buildModel Function and build the cpu model via the buildModel function in packages/vscode-js-profile-core/src/cpu/model.ts:
model.json

As I inspected the buildModel function I recognized a weird behavior.
During the calculation of the aggregatedTime of a source location it sums up all aggregatedTimes of all nodes that reference the location. For the case of a recursive function this implies, that the aggregated time gets summed up multiple times, even though it is already part of another aggregated time.

So for my given example the location with the id 569 there is are nodes like this:

{ ..., "node": [ { "id": 153, "selfTime": 168, "aggregateTime": 4792, "locationId": 569, "children": [ 154 ], "parent": 151 }, { "id": 154, "selfTime": 1040, "aggregateTime": 4624, "locationId": 569, "children": [ 155 ], "parent": 153 }, { "id": 155, "selfTime": 668, "aggregateTime": 3584, "locationId": 569, "children": [ 156 ], "parent": 154 }, { "id": 156, "selfTime": 542, "aggregateTime": 2916, "locationId": 569, "children": [ 157 ], "parent": 155 }, { "id": 157, "selfTime": 584, "aggregateTime": 2374, "locationId": 569, "children": [ 158 ], "parent": 156 }, { "id": 158, "selfTime": 458, "aggregateTime": 1790, "locationId": 569, "children": [ 159 ], "parent": 157 }, { "id": 159, "selfTime": 417, "aggregateTime": 1332, "locationId": 569, "children": [ 160 ], "parent": 158 }, { "id": 160, "selfTime": 289, "aggregateTime": 915, "locationId": 569, "children": [ 161 ], "parent": 159 }, { "id": 161, "selfTime": 500, "aggregateTime": 626, "locationId": 569, "children": [ 162 ], "parent": 160 },... ] }

And as it seems plausible one parent node has as aggregated time the aggtregated time of its children plus its self time.

But as the aggregated time of the locations is determined like this:

// 3. Add the aggregate times for all node children and locations
for (let i = 0; i < nodes.length; i++) {
  const node = nodes[i];
  const location = locations[node.locationId];
  location.aggregateTime += computeAggregateTime(i, nodes);
  location.selfTime += node.selfTime;
}

Those aggregated times of each node is added up again, but since the node with the id: 153 already contains the aggregated times of the nodes 154 to 161, the total sum gets way bigger than expected.
In my understanding the aggregated time of a source location should not contain more time than actually needed.

Is my understanding just wrong or is this really an unexpected behavior?

[connor4312]

It is kind of weird in this case, I agree. We follow the same strategy that the Chrome devtools do which do the same thing: (slight number difference in the way we calculate thing)

Total time is the time spent in the function and everything the function calls. For the recursive case this can be a little misleading. I would take a PR to try to fix this.

[KMakowsky]

One way to fix this could be to traverse the children of each node and exclude source locations that have already been visited.

My approach:

// 3. Add the aggregate times for all node children and locations
const calcAggregatedTimeOfLocations = (node: IComputedNode, visited: Set<number>) => {
  const location = locations[node.locationId]
  let selfAdded = false
  if (!visited.has(node.locationId)) {
    // node is not an ancestor of a node with the same location
    visited.add(node.locationId)
    selfAdded = true
    location.aggregateTime += computeAggregateTime(node.id, nodes)
  }
  location.selfTime += node.selfTime
  for (const child of node.children) {
    calcAggregatedTimeOfLocations(nodes[child], visited)
  }
  if (selfAdded) {
    visited.delete(node.locationId)
  }
}
calcAggregatedTimeOfLocations(nodes[0], new Set<number>())

instead of the:

// 3. Add the aggregate times for all node children and locations
for (let i = 0; i < nodes.length; i++) {
  const node = nodes[i];
  const location = locations[node.locationId];
  location.aggregateTime += computeAggregateTime(i, nodes);
  location.selfTime += node.selfTime;
}

This will produce identical values to those on https://www.speedscope.app/, with a minor variation, as Speedscope assigns the CPU time of the garbage collector to functions (even though the gc is not an ancestor node of those functions).

[connor4312]

Sounds good to me, PR welcome :)