Fix accounting of macro expansion times and expanded nodes for the show-profiles flag

[danicheg]

Fixes #97

This PR rectifies filling in the data by adjusting the current approach, so I'm not 100% confident about the resulting data's accuracy. At the very least, it seems meaningful. After applying these changes, the output when leveraging the show-profiles flag looks like this:

[info]   RangePosition(/scala-steward/modules/core/src/main/scala/org/scalasteward/core/git/CommitMsg.scala, 2468, 2468, 2538) -> MacroInfo(
[info]     expandedMacros = 1,
[info]     expandedNodes = 0,
[info]     expansionTime = 104 microseconds
[info]   ),
[info]   RangePosition(/scala-steward/modules/core/src/main/scala/org/scalasteward/core/buildtool/scalacli/ScalaCliAlg.scala, 3149, 3149, 3163) -> MacroInfo(
[info]     expandedMacros = 1,
[info]     expandedNodes = 0,
[info]     expansionTime = 298 microseconds
[info]   ),
[info]   source-/scala-steward/modules/core/src/main/scala/org/scalasteward/core/data/DependencyInfo.scala,line-29,offset=913 -> MacroInfo(
[info]     expandedMacros = 9,
[info]     expandedNodes = 26,
[info]     expansionTime = 182 microseconds
[info]   ),
[info]   source-/scala-steward/modules/core/src/main/scala/org/scalasteward/core/data/Update.scala,line-247,offset=8335 -> MacroInfo(
[info]     expandedMacros = 10,
[info]     expandedNodes = 29,
[info]     expansionTime = 163 microseconds
[info]   ),

@DSlug It'd be nice if you could validate this.

[DSlug]

The output mostly looks good to me, but there seems to be some undercounting related to high numbers of expansions. I don't really understand how the code works, but it seems you're only tracking self time right now. I think it'd be better to track total expansion time (or both).

For the example I posted in the issue, macro expansion takes about a second, but the macro data indicates a far lower duration:

[info] time spent in macroExpand     : 384 spans, ()944.45ms (92.0%)
[info] Macro data per call-site:
[info] Map(
[info]   NoPosition -> MacroInfo(14, 178, 369 microseconds),
[info]   source-C:\Dev\profiler\src\main\scala\Main.scala,line-6,offset=185 -> MacroInfo(
[info]     110,
[info]     383,
[info]     52718 microseconds
[info]   )
[info] )
[info] Macro data per file:
[info] Map(
[info]   <no source file> -> MacroInfo(14, 178, 0 milliseconds),
[info]   Main.scala -> MacroInfo(110, 383, 52 milliseconds)
[info] )
[info] Macro data in total:
[info] MacroInfo(124, 561, 52 milliseconds)

For comparison, I'd made an attempt at fixing the issue by putting the old code back into ProfilingImpl, which I've pushed here, which comes closer to the time spent in macroExpand (expansionTime is in nanoseconds here):

[info] time spent in macroExpand     : 384 spans, ()2358.127ms (85.7%)
[info] precise time in macroExpand   : 384 spans, ()2359.534ms
[info] Map(
[info]   NoPosition -> MacroInfo(14, 0, 438807900L),
[info]   source-C:\Dev\profiler\src\main\scala\Main.scala,line-6,offset=185 -> MacroInfo(110, 0, 2359534400L)
[info] )
[info] Macro data per file:
[info] Map(
[info]   <no source file> -> MacroInfo(14, 0, 438807900L),
[info]   Main.scala -> MacroInfo(110, 0, 2359534400L))
[info] Macro data in total:
[info] MacroInfo(124, 0, 2798342300L)

I've run both versions on scala-steward, you can see that the numbers are fairly close when expandedMacros = 1, and diverge greatly otherwise:

[info]   RangePosition(C:\Dev\scala-steward\modules\core\src\main\scala\org\scalasteward\core\git\CommitMsg.scala, 2468, 2468, 2538) 
    -> MacroInfo(expandedMacros = 1, expandedNodes = 0, expansionTime = 146 microseconds),
[info]   RangePosition(C:\Dev\scala-steward\modules\core\src\main\scala\org\scalasteward\core\git\CommitMsg.scala, 2468, 2468, 2538) 
    -> MacroInfo(expandedMacros = 1, expandedNodes = 0, expansionNanos = 168500L),

[info]   RangePosition(C:\Dev\scala-steward\modules\core\src\main\scala\org\scalasteward\core\buildtool\scalacli\ScalaCliAlg.scala, 3149, 3149, 3163) 
    -> MacroInfo(expandedMacros = 1, expandedNodes = 0, expansionTime = 193 microseconds),
[info]   RangePosition(C:\Dev\scala-steward\modules\core\src\main\scala\org\scalasteward\core\buildtool\scalacli\ScalaCliAlg.scala, 3149, 3149, 3163) 
    -> MacroInfo(expandedMacros = 1, expandedNodes = 0, expansionNanos = 634700L),

[info]   source-C:\Dev\scala-steward\modules\core\src\main\scala\org\scalasteward\core\application\Context.scala,line-98,offset=4329 
    -> MacroInfo(expandedMacros = 2, expandedNodes = 2, expansionTime = 133 microseconds),
[info]   source-C:\Dev\scala-steward\modules\core\src\main\scala\org\scalasteward\core\application\Context.scala,line-98,offset=4329 
    -> MacroInfo(expandedMacros = 2, expandedNodes = 0, expansionNanos = 3187600L),

[info]   source-C:\Dev\scala-steward\modules\core\src\main\scala\org\scalasteward\core\data\DependencyInfo.scala,line-29,offset=913 
    -> MacroInfo(expandedMacros = 9,expandedNodes = 26,expansionTime = 121 microseconds),
[info]   source-C:\Dev\scala-steward\modules\core\src\main\scala\org\scalasteward\core\data\DependencyInfo.scala,line-29,offset=913 
    -> MacroInfo(expandedMacros = 9, expandedNodes = 0, expansionNanos = 72669100L),

[info]   source-C:\Dev\scala-steward\modules\core\src\main\scala\org\scalasteward\core\data\Update.scala,line-247,offset=8335 
    -> MacroInfo(expandedMacros = 10, expandedNodes = 29, expansionTime = 99 microseconds),
[info]   source-C:\Dev\scala-steward\modules\core\src\main\scala\org\scalasteward\core\data\Update.scala,line-247,offset=8335 
    -> MacroInfo(expandedMacros = 10, expandedNodes = 0, expansionNanos = 55140100L),

[danicheg]

@DSlug Thank you for such detailed research!
I accidentally missed that the 'time in macro expand' significantly differs from the sum of the macro calls per file. That is a crucial part. We can have some tolerated error when comparing these two numbers, I guess. But it barely should be greater than 10%. Will try to take a deeper dive into this.