Why would a function called from another not show in the profile output of a node app?

Question

I have a NodeJS program. This is a trimmed down version of a much larger program with a lot of complexity that's irrelevant to this question removed. It goes through lists looking for matching objects:

/**
 * Checks that the given attributes are defined in the given dictionaries
 * and have the same value
 */
function areDefinedAndEqual(a, b, keys) {
  return (
    a &&
    b &&
    keys
      .map(function (k) {
        return a[k] && b[k] && a[k] === b[k]
      })
      .reduce(function (a, b) {
        return a && b
      }, true)
  )
}

function calculateOrder() {
  const matchingRules = [
    {
      desc: 'stuff, more stuff and different stuff',
      find: (po, dp) => areDefinedAndEqual(po, dp, ['stuff', 'more_stuff', 'different_stuff'])
    },
    {
      desc: 'stuff and different stuff',
      find: (po, dp) => areDefinedAndEqual(po, dp, ['stuff', 'different_stuff'])
    },
    {
      desc: 'just stuff',
      find: (po, dp) => areDefinedAndEqual(po, dp, ['stuff'])
    }
  ]
  let listOfStuff = []
  listOfStuff[999] = { stuff: 'Hello' }
  listOfStuff[9999] = { stuff: 'World' }
  listOfStuff[99999] = { stuff: 'Hello World' }
  // Run through lots of objects running through different rules to
  // find things that look similar to what we're searching for
  for (let i = 0; i < 100000000; i++) {
    for (let j = 0; j < matchingRules.length; j++) {
      if (matchingRules[j].find({ stuff: 'Hello World' }, listOfStuff[i])) {
        console.log(`Found match at position ${i} on ${matchingRules[j].desc}`)
      }
    }
  }
}

calculateOrder()

Now all calculateOrder does is repeatedly call functions listed under matchingRules which in turn call areDefinedAndEqual which does some actual checking.

Now if I run this as follows:

richard@sophia:~/cc/sheetbuilder (main) $ node --prof fred.js 
Found match at position 99999 on just stuff
richard@sophia:~/cc/sheetbuilder (main) $ 

I get just what I'd expect. So far so good. I can then run the profile output through prof-process to get something more readable.

node --prof-process isolate-0x57087f0-56563-v8.log

However if I look at the output, I see this:

 [JavaScript]:
   ticks  total  nonlib   name
   4197   46.0%   89.0%  LazyCompile: *calculateOrder /home/richard/cogcred/eng-data_pipeline_misc/sheetbuilder/fred.js:19:24

All the time is being spent in calculateOrder. I'd expect to see a large %age of the time spent in the various "find" functions and in areDefinedAndEqual but I don't. There's no mention of any of them at all. Why? Are they potentially being optimized out / inlined in some way? If so, how do I begin to debug that? Or is there some restrictions on certain functions not showing in the output? In which case, where are those retrictions defined? Any pointers would be much appreciated.

I'm running Node v16.5.0

Answer 1

Functions show up in the profile when tick samples have been collected for them. Since sample-based profiling is a statistical affair, it could happen that a very short-running function just wasn't sampled.

In the case at hand, inlining is the more likely answer. Running node with --trace-turbo-inlining spits out a bunch of information about inlining decisions.

If I run the example you posted, I see areDefinedEqual getting inlined into find, and accordingly find (and calculateOrder) are showing up high on the profile. Looking closely, in the particular run I profiled, areDefinedEqual was caught by a single profiler tick -- before it got inlined.