wilsonwatson
commented
1 month ago Now produces a JSON output.
Example:
{
"visitCount": 509,
"totalTime": 10.339664,
"percentOfRoot": 100.0,
"maxTime": 0.181757,
"minTime": 0.019748,
"avgTime": 0.020313681728880158,
"children": {
"robotPeriodic()": {
"visitCount": 509,
"totalTime": 0.340188,
"percentOfParent": 3.2901262555533717,
"percentOfRoot": 3.2901262555533717,
"maxTime": 0.180822,
"minTime": 1.19E-4,
"avgTime": 6.683457760314342E-4,
"children": {
"manual-gc": {
"visitCount": 509,
"totalTime": 6.36E-4,
"percentOfParent": 0.1869554481639564,
"percentOfRoot": 0.0061510702862298035,
"maxTime": 2.9E-5,
"minTime": 0.0,
"avgTime": 1.24950884086444E-6,
"children": {}
},
"draw_state_to_shuffleboard": {
"visitCount": 509,
"totalTime": 0.007479,
"percentOfParent": 2.198490246569544,
"percentOfRoot": 0.07233310482816463,
"maxTime": 4.2E-5,
"minTime": 4.0E-6,
"avgTime": 1.469351669941061E-5,
"children": {}
},
"command_scheduler": {
"visitCount": 509,
"totalTime": 0.329564,
"percentOfParent": 96.87702094136183,
"percentOfRoot": 3.187376301589684,
"maxTime": 0.180232,
"minTime": 1.12E-4,
"avgTime": 6.474734774066798E-4,
"children": {
"swerve_periodic": {
"visitCount": 509,
"totalTime": 0.25498,
"percentOfParent": 77.3688873784758,
"percentOfRoot": 2.4660375811051503,
"maxTime": 0.178467,
"minTime": 5.1E-5,
"avgTime": 5.00943025540275E-4,
"children": {
"update_shuffleboard": {
"visitCount": 509,
"totalTime": 0.19864,
"percentOfParent": 77.90414934504668,
"percentOfRoot": 1.9211456000891323,
"maxTime": 0.174765,
"minTime": 1.5E-5,
"avgTime": 3.9025540275049116E-4,
"children": {}
},
"update_inputs": {
"visitCount": 509,
"totalTime": 4.83E-4,
"percentOfParent": 0.18942662169581928,
"percentOfRoot": 0.004671331679636785,
"maxTime": 1.0E-5,
"minTime": 0.0,
"avgTime": 9.489194499017682E-7,
"children": {}
},
"do_camera_stuff": {
"visitCount": 509,
"totalTime": 9.22E-4,
"percentOfParent": 0.36159698799905876,
"percentOfRoot": 0.008917117616201068,
"maxTime": 1.0E-5,
"minTime": 0.0,
"avgTime": 1.8113948919449901E-6,
"children": {}
},
"process_cameras": {
"visitCount": 509,
"totalTime": 1.33E-4,
"percentOfParent": 0.05216095380029806,
"percentOfRoot": 0.0012863087233782452,
"maxTime": 4.0E-6,
"minTime": 0.0,
"avgTime": 2.612966601178782E-7,
"children": {}
},
"update_swerve_odometry": {
"visitCount": 509,
"totalTime": 0.038325,
"percentOfParent": 15.030590634559573,
"percentOfRoot": 0.3706600137103101,
"maxTime": 0.003442,
"minTime": 2.3E-5,
"avgTime": 7.529469548133595E-5,
"children": {}
},
"process_inputs": {
"visitCount": 509,
"totalTime": 0.002145,
"percentOfParent": 0.8412424503882657,
"percentOfRoot": 0.020745354974784483,
"maxTime": 4.8E-5,
"minTime": 1.0E-6,
"avgTime": 4.214145383104126E-6,
"children": {}
},
"update_swerve_mods": {
"visitCount": 509,
"totalTime": 0.010872,
"percentOfParent": 4.263863832457448,
"percentOfRoot": 0.10514848451555099,
"maxTime": 1.48E-4,
"minTime": 7.0E-6,
"avgTime": 2.1359528487229863E-5,
"children": {
"updateInputs": {
"visitCount": 2036,
"totalTime": 3.64E-4,
"percentOfParent": 3.3480500367917587,
"percentOfRoot": 0.0035204238745088815,
"maxTime": 1.3E-5,
"minTime": 0.0,
"avgTime": 1.787819253438114E-7,
"children": {}
},
"processInputs": {
"visitCount": 2036,
"totalTime": 0.006107,
"percentOfParent": 56.17181751287712,
"percentOfRoot": 0.05906381483963115,
"maxTime": 4.1E-5,
"minTime": 0.0,
"avgTime": 2.99950884086444E-6,
"children": {}
}
}
}
}
},
"teleop_swerve": {
"visitCount": 391,
"totalTime": 0.011305,
"percentOfParent": 3.430289716109769,
"percentOfRoot": 0.10933624148715083,
"maxTime": 0.001373,
"minTime": 1.2E-5,
"avgTime": 2.891304347826087E-5,
"children": {
"swerve.drive()": {
"visitCount": 391,
"totalTime": 0.009202,
"percentOfParent": 81.39761167624945,
"percentOfRoot": 0.08899708926711739,
"maxTime": 0.00133,
"minTime": 9.0E-6,
"avgTime": 2.3534526854219948E-5,
"children": {}
}
}
}
}
}
}
},
"teleopInit()": {
"visitCount": 1,
"totalTime": 5.0E-6,
"percentOfParent": 4.835747080369343E-5,
"percentOfRoot": 4.835747080369343E-5,
"maxTime": 5.0E-6,
"minTime": 5.0E-6,
"avgTime": 5.0E-6,
"children": {}
}
}
}(Note: this might be unrealistic, since it was run in simulation. In this case, most things, except NT calls, are effectively no-ops. I hope that shuffleboard calls are not nearly this problematic in reality, but its something we should investigate.)
In order to tune the performance of our code, we need to profile it.
Using VisualVM last year was somewhat sufficient, but it was coarse, and didn't have a concept of the robot's "main loop". Additionally, it was hard to determine the cost of oneshot steps (like command initialization) since all we saw in VisualVM were aggregate totals.
This profiler keeps the same aggregate totals, but in number of main loop iterations (instead of unassociated profile ticks) and also keeps running metrics useful for finding inefficient code, like the maximum and average time spent in a code section. Additionally, the profiler uses string identifiers instead of the function name, allowing us to split up the function into smaller profiled sections without requiring some potentially messy functional decomposition.
Included in this PR is the profiling implementation of our swerve code (though it could be more thorough). It outputs the following on my machine in simulation mode. The numbers will necessarily vary from run to run, but overall trends should be considered when looking for slow code.
This is saved whenever
disabledInit()occurs, and resides next to the AdvantageKit log file.