Added cf-profile.py script for processing profiling output

[victormlg]

sudo /var/cfengine/bin/cf-agent -Kp | python3 contrib/cf-profile/cf-profile.py --promises --functions --top 5

output:

Component                                                    Location                                                                                                   Time
promise methods                                              /var/cfengine/inputs/cfe_internal/CFE_cfengine.cf:70                                                 1703.08 ms
promise methods                                              /var/cfengine/inputs/cfe_internal/enterprise/mission_portal.cf:91                                    1442.38 ms
promise vars                                                 /var/cfengine/inputs/cfe_internal/enterprise/mission_portal.cf:201                                   1247.32 ms
function datastate                                           /var/cfengine/inputs/cfe_internal/enterprise/mission_portal.cf:201                                    352.50 ms
promise vars                                                 /var/cfengine/inputs/cfe_internal/enterprise/federation/federation.cf:905                             260.92 ms

[nickanderson]

Nice.

Times could be human readable (N seconds, minutes).

maybe it would be nice to be able to exclude , but probably that's scope creep for no good reason since you can just --top MORE.

[olehermanse]

@victormlg nice, some things to improve, mainly based on your example output;

1. Avoid using the word component here since we already have another specific meaning for that. For example Type would be better.
2. --promises as the filter should exclude methods promises, AKA bundle invocations. To see those, user should specify --bundles as the filter.
3. The left column reads weird / backwards. Suggest these changes:
   • promise vars -> vars promise.
   • function datastate -> datastate() function call.
   • promise methods -> bundle invocation.
4. As Nick said, printing seconds / minutes might be nicer. In your example it's not a problem, but imagine a slow policy where things take several minutes, reading 632241.12 ms will not be so nice. To make things simple you could print it like it is now for smaller than 1 second, then switch to printing seconds when it's 1000ms or more (e.g. 2.58s), and then switch again once you pass 60 seconds (1m32s).