Support outputting profiling information as json

[Arrowbox]

A project I work on uses recursive make extensively and I was trying to profile our build.There wasn't an easy way to correlate the individual callgrind.out files so I extended the functionality to pass PID and target to the recursive calls to make. I needed to parse the output to stitch the different files together so I added functionality to output as json.

There is a significant difference in how I am capturing timestamps. The current implementation increments the time when a target is actively being evaluated. However, I think the relevant metric is how long the target takes from the moment it is first considered until it is marked as completed. I also capture a timestamp when the recipe begins running.

• Extract output formatting from profile.c into callgrind_format.c
• Capture timestamps based on target state with profile_add_timestamp
• Capture dependencies explicitly with profile_add_dependency
• Add MAKEPARENT_PID to pass PID to recursive make
• Add MAKEPARENT_TARGET to pass target name to recursive make
• Add --profile-callgrind to output just callgrind files
• Add --profile-json to output just json files
• Use file_timestamp_now to capture timestamp and resolution
• Add --with-profiler-resolution to specify minimum timestamp resolution required

[rocky]

@Arrowbox Thanks for doing this!

I'm going to be out this week and may be pretty busy next week, I will look definitely look at after that though.

@boretom would you have a look at it, if you have a chance?

[Arrowbox]

I just saw that this is probably relevant to #19 to add a new format. I'll try to get my python tooling packaged up to push somewhere as an example as well.

[boretom]

Morning, Sorry for the late reply. I'll try and have a look this. I do fear though that I forgot the little I knew :) ... but we'll see.

[Arrowbox]

Thanks! I just pushed a change up to my branch. The timestamp was wrong because it wasn't using the macros to convert back to seconds and nanoseconds. And I also wanted to capture the maximum number of jobs allowed. This can help with post-processing to figure out "best case" time if everything was perfectly parallelized to show how close your Makefile is in comparison.

[rocky]

@Arrowbox I just had a chance to look everything over. Overall it looks good.

I have a couple of questions though. I see nothing describing how you use this. Sure, I see two options added, but a complete example showing a run and then what to do with it would be nice.

The files make.1 and and remake.texi should also include mention of the new options/features and how to use.

The second thing that I noticed is there is nothing in the way of how to test any of the new parts. In some of the old code I had a way to compile parts by setting -DSTANDALONE so that at least new pieces could be tried and run in isolation. If nothing else that makes debugging those parts easier. That is now gone so that option is no longer available. If there are tests and unit-like tests that'd be fine.

So have you given thought as to how to test this?

[Arrowbox]

I thought the -DSTANDALONE had been deprecated because I could not get the commands to work and the same function was mostly replicated in unittest/test_profile.c. The unit test does work now using make -C unittest check after running make once in the root directory. I should be able to add some tests to exercise the two output schemes.

I'll make sure to update the make.1 and remake.texi with better information.

As far as an example, I've been working on a python utility to ingest the json files and analyze them. It's not quite ready for public consumption though. As a brief output, I profile building remake and here is what my utility can dump:

❯ remake_auditor --input ../remake  --top-path
Path:
Dir:remake
  Entry:all
  PID:1587435
  Target:all
    Path:remake/Makefile:2066
    Time:2.639s
    Recipe: 0.0%: 0.0s
    Children: 2
      Parallel: 1.0 = 2.639/2.639
      100.0%: 2.639s: all-recursive
  Target:all-recursive
    Path:remake/Makefile:1415
    Time:2.639s
    Recipe: 99.99%: 2.639s
    Children: 7
      Parallel: 0.0 = 0/0.0
      55.16%: 1.456s: all-am
      21.02%: 0.555s: all
      14.25%: 0.376s: all
      7.55%: 0.199s: all
Dir:remake
  Entry:all-am
  PID:1587906
  Target:all-am
    Path:remake/Makefile:1717
    Time:1.456s
    Recipe: 0.0%: 0.0s
    Children: 33
      Parallel: 1.0 = 1.456/1.456
      100.0%: 1.456s: make
  Target:make
    Path:remake/Makefile:1270
    Time:1.456s
    Recipe: 2.95%: 0.043s
    Children: 41
      Parallel: 17.979 = 25.398/1.413
      96.31%: 1.402s: src/read.o
      84.84%: 1.235s: src/variable.o
      82.88%: 1.206s: src/remake.o
      81.47%: 1.186s: src/posixos.o
      78.71%: 1.146s: src/main.o
  Target:src/read.o
    Path:remake/src/.deps/read.Po:1
    Time:1.402s
    Recipe: 53.41%: 0.749s
    Children: 2
      Parallel: 0.0 = 0/0.653
  Target:../../../../usr/include/pwd.h
    Path:remake/src/.deps/read.Po:531
    Time:0.0s
    Recipe: 0.0%: 0.0s
    Children: 0
      Parallel: 0.0 = 0/0.0

I can also display some simple summary information:

❯ remake_auditor --input ../remake  --summary
key: remake.summary
name: Summary
date: 2021-09-24 15:20:17.843354
pid: 1587435
elapsed: 2.652
recipe: 14.721
parallel:
  jobs: 8
  ratio: 5.551
directory: /home/...git/remake
submake: 11
targets: 1657
dependencies: 1575
entry:
- all

The formatting for the summary one is a bit more structured because I am hoping to be able to easily send output back to github/bitbucket to display as annotations/reports on PRs.

[rocky]

Ok - I have created #128 as a branch in this repo which you can commit to, or update this PR. When the docs and interface are ready for public consumption we can just go ahead and merge everything.

Again, thanks for doing this. We just have a little further to go.

[boretom]

Since the master / @rocky already had a look at it, I do what I do best: simple stuff.

The help related handling got maybe some enhancement possibilities:

---

remake --help right now

...
  -P, --profile               Print profiling information for each target.
  --profile-json              Output profiling information in json format.
  --profile-callgrind         Output profiling information in callgrind format.
...

From that output it's not clear that -P|--profile outputs json and callgrind. Maybe extend the help text a little bit.

Or what I'd prefer would be short arguments for --profile-json (e.g. -J) and --profile-callgrind (e.g. -G) and get rid of -P|--profile all together. Unless it's common to use both profiles at all time. If there would be added another profile output how would that be handled?

---

man remake

...
       -P, --profile
            Creates  profile  output  in both json and callgrind format.  Callgrind output can be used with kcachegrind, call‐
            grind_annotate, or gprof2dot to analyze data. You can get not only timings, but a graph of the target dependencies
            checked

       -P, --profile-callgrind
            Creates callgrind profile output.  Callgrind output can be used with kcachegrind, callgrind_annotate, or gprof2dot
            to analyze data. You can get not only timings, but a graph of the target dependencies checked

       -P, --profile-json
            Creates json profile output.  Json output can be used with custom tools to analyze data.
...

If -P, --profile is kept then -P in the help text for --profile-callgrind and --profile-json is confusing. In the help text for -P, --profile it is already mentioned what is does. The help text for -P, --profile could even get rid of the description what json and callgrind does. It only needs mentioning that it will execute --profile-callgrind and --profile-json. Right below that option are the explanations what these two options do.

[rocky]

+1 for removing -P and --profile in favor of the more explicit version.

[Arrowbox]

Thanks for the feedback. The CLI flags were definitely something I was a bit iffy about. (Obviously, I like dumping json by default, but I'm biased. 😜) I'm not entirely familiar with make's flag handling, but maybe keep -P to enable profiling and default to callgrind. And also allow --profile=json or --Pjson to select the output type. Also allows for future output formatters.

I'm not sure how feasible that is in the arg parser, but I'll take a look if that sounds more acceptable.

[Arrowbox]

@rocky I don't think I quite follow what I should do with respect to #128 Should I be changing the target of this to the json_output branch in this repo?

[rocky]

@rocky I don't think I quite follow what I should do with respect to #128 Should I be changing the target of this to the json_output branch in this repo?

The short answer is that it simplifies trying stuff out. So if you don't mind if you could make this the base of the PR instead of say remake-4-3 then that helps trying it.

Part of this is that I don't understand git or github flow of PR's. If you do a pull request say from your repository by setting that in my .git/config then when I pull from multiple origins then switching branches is confused.

[rocky]

Thanks for the feedback. The CLI flags were definitely something I was a bit iffy about.

I find it weird too. I think the deal is that this is way old code that predates options-processing libraries like getopt-long.

(Obviously, I like dumping json by default, but I'm biased. stuck_out_tongue_winking_eye) I'm not entirely familiar with make's flag handling, but maybe keep -P to enable profiling and default to callgrind. And also allow --profile=json or --Pjson to select the output type. Also allows for future output formatters.

That is fine too. My take is that if there's consensus between you and @boretom then I am okay with this too.

I'm not sure how feasible that is in the arg parser, but I'll take a look if that sounds more acceptable.

Thanks in advance.

[Arrowbox]

Okay, changed the base and added a new commit to update the docs and choose output as a argument.

[Arrowbox]

I added another commit to allow for keeping all output in a specific directory. I can split it into a separate PR for after this one is merged.

[rocky]

Looking better all the time - thanks. I hope this weekend to look at this in more detail. My inclination right now is to merge though. Of course feel free to add more commits, and if you would prefer wait, let me know.

@boretom - your thoughts?

[Arrowbox]

I guess my only concern is I've not built it on macOS. I don't think I've done anything that should mess with that, but it does give me pause. I'm trying to find someone who can give it a spin to check.

As I've dug deeper into the source, I've been thinking that an alternative approach would have been to add the timestamps to the file_t struct and then walk the dependency tree and dump timestamps and connections. But I think the current implementation is good enough for merge.

[rocky]

Ok - thanks for the information. I have a GCC compile farm account on an OSX box that I can probably try this out on over the weekend.

[boretom]

Good Morning,

I like it, --profile [=TYPE] sounds good. Are you still able to generate both output at the same time, json and callgrind?

macOS: my two main computers are macOS (OS: latest and latest-1). I will compile it on them to make sure it still works fine.

[rocky]

@Arrowbox and @boretom I was able to build and try this on arm-apple-darwin20.3.0 after the usual hassle with GNU readline on OSX.

I will bump make-4.3 version number and then merge the other branch soon.

[boretom]

Excellent @rocky, my tests on Intel Macs with latest and latest-1 macOS was successful too.

[SvanteRichter]

@Arrowbox did you ever end up releasing remake_auditor? I could use something similar and it would be awesome if you were willing to share!

[Arrowbox]

I'm working on it. I hadn't published it yet.

[Arrowbox]

@SahAssar I've just pushed the code to github: https://github.com/Arrowbox/makegrind