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).

[github-actions]

Marking this PR as stale due to inactivity; it will be closed in 7 days.

[victormlg]

To generate a flamegraph:

$ sudo /var/cfengine/bin/cf-agent -Kp > output.json
$ cat output.json | python3 cf-profile.py --flamegraph callstack.txt
$ ./flamegraph callstack.txt > flamegraph.svg

[nickanderson]

With a recent build from master I get JSON decode error:

# cat agent-profile.json | python3 ./cf-profile.py --promises --functions --top 5
Traceback (most recent call last):
  File "./cf-profile.py", line 149, in <module>
    main()
  File "./cf-profile.py", line 139, in main
    data = json.loads(m.group(0))
  File "/usr/lib/python3.8/json/__init__.py", line 357, in loads
    return _default_decoder.decode(s)
  File "/usr/lib/python3.8/json/decoder.py", line 340, in decode
    raise JSONDecodeError("Extra data", s, end)
json.decoder.JSONDecodeError: Extra data: line 30175 column 8 (char 948352)

Seems to error on the last event before policy:

        {
          "elapsed": 99538680,
          "filename": "/var/cfengine/inputs/lib/service_config.cf",
          "id": "bundle_service_config_/var/cfengine/inputs/lib/service_config.cf_887708_3",
          "name": "service_config",
          "offset": {
            "context": 0,
            "end": 888977,
            "line": 3,
            "start": 887708
          },
          "type": "bundle"
        }
      ],
      "policy": {
        "bodies": [
          {

[larsewi]

LGTM 🚀

[olehermanse]

@cf-bottom jenkins, please

[cf-bottom]

Alright, I triggered a build:

Jenkins: https://ci.cfengine.com/job/pr-pipeline/13231/

Packages: http://buildcache.cfengine.com/packages/testing-pr/jenkins-pr-pipeline-13231/