Add profiling utilities #126
Merged
Conversation
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
|
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.) |
|
This is probably ready for use. Of course we'll want to change things as we go, but those can be part of different PRs. |
|
Ran on robot today. Many disconnects from NetworkTables, caused by slow update rates: {
"visitCount": 221,
"totalTime": 6.136004,
"percentOfRoot": 100.0,
"maxTime": 1.02012,
"minTime": 0.01113,
"avgTime": 0.02776472398190045,
"children": {
"robotPeriodic()": {
"visitCount": 221,
"totalTime": 3.466921,
"percentOfParent": 56.50128324557807,
"percentOfRoot": 56.50128324557807,
"maxTime": 0.9518,
"minTime": 0.005917,
"avgTime": 0.015687425339366515,
"children": {
"manual-gc": {
"visitCount": 221,
"totalTime": 0.005231,
"percentOfParent": 0.1508831611680797,
"percentOfRoot": 0.08525092226145875,
"maxTime": 0.001187,
"minTime": 0.0,
"avgTime": 2.3669683257918552E-5,
"children": {}
},
"draw_state_to_shuffleboard": {
"visitCount": 221,
"totalTime": 0.029186,
"percentOfParent": 0.8418420840855617,
"percentOfRoot": 0.4756515804096607,
"maxTime": 0.001187,
"minTime": 5.5E-5,
"avgTime": 1.320633484162896E-4,
"children": {}
},
"command_scheduler": {
"visitCount": 221,
"totalTime": 3.377213,
"percentOfParent": 97.41245906670501,
"percentOfRoot": 55.03928941376179,
"maxTime": 0.921008,
"minTime": 0.005769,
"avgTime": 0.015281506787330316,
"children": {
"swerve_periodic": {
"visitCount": 221,
"totalTime": 2.353467,
"percentOfParent": 69.68666175334513,
"percentOfRoot": 38.35504344521288,
"maxTime": 0.826199,
"minTime": 0.002671,
"avgTime": 0.010649171945701358,
"children": {
"update_shuffleboard": {
"visitCount": 221,
"totalTime": 0.728499,
"percentOfParent": 30.954289990044476,
"percentOfRoot": 11.87253137383874,
"maxTime": 0.604044,
"minTime": 2.79E-4,
"avgTime": 0.0032963755656108596,
"children": {}
},
"update_inputs": {
"visitCount": 221,
"totalTime": 0.008889,
"percentOfParent": 0.37769809391846154,
"percentOfRoot": 0.14486626801416688,
"maxTime": 0.001076,
"minTime": 0.0,
"avgTime": 4.022171945701357E-5,
"children": {}
},
"do_camera_stuff": {
"visitCount": 221,
"totalTime": 0.664337,
"percentOfParent": 28.228014244516707,
"percentOfRoot": 10.826867127205263,
"maxTime": 0.037712,
"minTime": 7.05E-4,
"avgTime": 0.003006049773755656,
"children": {}
},
"process_cameras": {
"visitCount": 221,
"totalTime": 0.242648,
"percentOfParent": 10.310235920027772,
"percentOfRoot": 3.9544954664305956,
"maxTime": 0.061085,
"minTime": 3.89E-4,
"avgTime": 0.0010979547511312218,
"children": {}
},
"update_swerve_odometry": {
"visitCount": 221,
"totalTime": 0.251536,
"percentOfParent": 10.687891523441799,
"percentOfRoot": 4.0993454371933264,
"maxTime": 0.131389,
"minTime": 1.3E-4,
"avgTime": 0.0011381719457013574,
"children": {}
},
"process_inputs": {
"visitCount": 221,
"totalTime": 0.022414,
"percentOfParent": 0.9523821663953648,
"percentOfRoot": 0.3652865936854018,
"maxTime": 0.001781,
"minTime": 3.7E-5,
"avgTime": 1.01420814479638E-4,
"children": {}
},
"update_swerve_mods": {
"visitCount": 221,
"totalTime": 0.379823,
"percentOfParent": 16.13887086583326,
"percentOfRoot": 6.19007093215715,
"maxTime": 0.014469,
"minTime": 7.24E-4,
"avgTime": 0.001718656108597285,
"children": {
"updateInputs": {
"visitCount": 884,
"totalTime": 0.200015,
"percentOfParent": 52.66005481500594,
"percentOfRoot": 3.259694745961704,
"maxTime": 0.002319,
"minTime": 7.4E-5,
"avgTime": 2.2626131221719457E-4,
"children": {}
},
"processInputs": {
"visitCount": 884,
"totalTime": 0.089001,
"percentOfParent": 23.43223027568104,
"percentOfRoot": 1.4504716750510593,
"maxTime": 0.001262,
"minTime": 3.7E-5,
"avgTime": 1.0067986425339367E-4,
"children": {}
}
}
}
}
},
"teleop_swerve": {
"visitCount": 84,
"totalTime": 0.15469,
"percentOfParent": 4.580404019527344,
"percentOfRoot": 2.521021824627233,
"maxTime": 0.063682,
"minTime": 5.75E-4,
"avgTime": 0.001841547619047619,
"children": {
"swerve.drive()": {
"visitCount": 84,
"totalTime": 0.147641,
"percentOfParent": 95.44314435322258,
"percentOfRoot": 2.406142499255216,
"maxTime": 0.063293,
"minTime": 5.01E-4,
"avgTime": 0.0017576309523809524,
"children": {}
}
}
},
"ElevatorWrist periodic": {
"visitCount": 221,
"totalTime": 0.27999,
"percentOfParent": 8.290563846580005,
"percentOfRoot": 4.563067429551871,
"maxTime": 0.009127,
"minTime": 5.56E-4,
"avgTime": 0.001266923076923077,
"children": {
"Publish to SmartDashboard": {
"visitCount": 221,
"totalTime": 0.05901,
"percentOfParent": 21.075752705453766,
"percentOfRoot": 0.961700807235458,
"maxTime": 0.00306,
"minTime": 1.11E-4,
"avgTime": 2.670135746606335E-4,
"children": {}
},
"PID stuff": {
"visitCount": 221,
"totalTime": 0.096493,
"percentOfParent": 34.46301653630487,
"percentOfRoot": 1.5725706828092028,
"maxTime": 0.004638,
"minTime": 1.67E-4,
"avgTime": 4.366199095022624E-4,
"children": {}
},
"updateInputs": {
"visitCount": 221,
"totalTime": 0.039408,
"percentOfParent": 14.074788385299474,
"percentOfRoot": 0.6422420845879501,
"maxTime": 0.004136,
"minTime": 7.4E-5,
"avgTime": 1.7831674208144795E-4,
"children": {}
},
"processInputs": {
"visitCount": 221,
"totalTime": 0.051389,
"percentOfParent": 18.353869781063608,
"percentOfRoot": 0.8374994540420769,
"maxTime": 0.002411,
"minTime": 1.11E-4,
"avgTime": 2.3252941176470586E-4,
"children": {}
}
}
}
}
}
}
},
"teleopInit()": {
"visitCount": 1,
"totalTime": 1.8E-5,
"percentOfParent": 2.933505258471148E-4,
"percentOfRoot": 2.933505258471148E-4,
"maxTime": 1.8E-5,
"minTime": 1.8E-5,
"avgTime": 1.8E-5,
"children": {}
}
}
} |
|
We think we can merge this?? |
|
Was going to bring it up at today's meeting. We have several branches that should be merged so main is up to date. |
ok cool. I think this plus I need to split the simulation stuff that I got working in my triggers branch into a separate branch |
Draft
legoguy1000
approved these changes
Oct 3, 2024
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
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.