bugmake - Bugs: bug #40639, GNU Make with profiling information

 
 

bug #40639: GNU Make with profiling information

Submitter:  Eddy Petrișor <eddyp>
Submitted:  Tue 19 Nov 2013 09:31:16 PM UTC
   
 
Severity:  3 - Normal Item Group:  Enhancement
Status:  None Privacy:  Public
Assigned to:  None Open/Closed:  Open
Component Version:  4.1 Operating System:  Any
Fixed Release:  None Triage Status:  None
* Mandatory Fields

Add a New Comment Rich Markup
   

Jump to the original submission

Sat 07 Dec 2013 01:21:24 AM UTC, comment #7: 
Eddy Petrișor <eddyp>
Sat 07 Dec 2013 01:11:56 AM UTC, comment #6: 

Here is a new version of the patch.

Author: Eddy Petrișor <eddy.petrisor@gmail.com>
Date:   Tue Nov 19 05:14:40 2013 +0200

    Now can choose profile format from predefined options
   
    Define 4 hard-coded profile printing formats which can
    be prefixed with an arbitary string.
    Formats are: simple, startend, short and long.
   
    -P can have an argument respecting the following form:
   
        [[prefix]:[separator]]<fmtopt>
   
    The default argument is equivalent to:
   
        PROFILE::short
   
    Signed-off-by: Eddy Petrișor <eddy.petrisor@gmail.com>


The information printed by each option is:

simple /* %N:%S:%D */
startend /* %N:%S:%E */
short /* %N:%L:%P:%S:%E:%D */
long /* target=%N : level=%L : pid=%P : start=%S : end=%E : duration=%D */

Prefixed by the 'prefix' string and the fields separated by the 'separator'
character.

Where:

    %N target name
    %L recursion level for the make instance processing the target
    %P pid of the make instance processing the target
    %S start target timestamp (in miliseconds since 1 ian 1970)
    %E end target timestamp (in miliseconds since 1 ian 1970)
    %D difference between the target start and end timestamps (in miliseconds)

and 'separator' can be any of:

' ' '%' '#' '@' '!' '`' '&' ':' ';' ',' '.' '|' '_' '+' '=' '^' '<' '>' '/' '\t'.

I have removed the man page update since is no longer correct.
I haven't corrected the double issue and the portability issues since I want feedback on the core functionality.


Please tell me what you think.

(file #29800)

Eddy Petrișor <eddyp>
Tue 26 Nov 2013 09:39:59 AM UTC, comment #5: 

Pe 25.11.2013 04:33, "Paul D. Smith" a scris:

>
> Follow-up Comment #4, bug #40639 (project make):
>
> Hi Eddy; thanks for your interest in improving GNU make!


Hi Paul,

You're welcome.

>  I think the idea of
> providing more statistics for builds is very interesting.  While I agree it
> could be done externally (for example, by setting the SHELL variable to a
> command that would track the time spent) this could also have detrimental
> impacts (for example by setting SHELL you disable the fast-path ability of GNU
> make to directly fork/exec simple commands, without a shell).  You're also
> adding an extra fork/exec step into each command.
>
> I have a few things to mention, however.  First, the code as you have it won't
> work on all platforms; in particular it won't work on Windows as Windows
> doesn't (by default) provide a gettimeofday() function.  There are various
> implementations around, so this isn't a huge issue.


I'll have this in mind and fix it once other details are ironed out.

>
> Second, as written your patch is large enough that applying it would require
> copyright assignment of the changes by you to the FSF.  If you're interested
> in pursuing this email me directly and we'll discuss the details.


I have no problem with that. OTOH, the initial work was done by somebody else (identified himself as 'Openshift guest'/zlqhem - see my profile-rebase branch history), so I don't know how that fares with the FSF.

>
> Third, I'm not sure about some things: for example, why use doubles when we're
> talking about integral values?  Actually GNU make has support for building on
> systems which don't even support floating point, so it's best to avoid
> doubles.


This was part of the initial patch and the only reason to keep double was the precision of the time stamps calculation in milliseconds. I'll look into some other solution during the weekend.

> Lastly, and this is where we may need to have more conversation, I'm not so
> excited about adding the formatting capability, at least not this way.  I
> think that it could be a very useful thing to allow for specially-formatted
> output from GNU make.  For example, perhaps an output format in XML that could
> be easily sucked into tools like Eclipse or whatever for further parsing (I'm
> not a huge fan of XML but it is relatively universal).  Now that we have the
> output sync capability it would be straightforward to combine these and format
> the output of recipes for proper XML encoding as well.
>
> But I don't want to add multiple different formatting options, for different
> types of output.  I'd prefer to have one comprehensive formatting capability.


AFAICT, we are talking about two types of formatting:
- what information to print out
- how the information is presented (plain text, XML, other file format)

I think the second part should be more about some external tools getting the info from Make and presenting the info in other formats. So I'll focus from now on only on the first side of the issue.

>
> So what I'd prefer is to split it so that this change deals solely with the
> profile information, and (if requested) will print it out in a standard
> (predefined) format.
>
> Then at some future time someone can look into providing an output formatting
> definition capability for GNU make.
>
> What do you think about this idea?  It may require some post-processing via
> sed, or whatever, to get the format needed for various purposes.



The initial patch from zlqhem just printed out on stdout the target and time stamps for start and stop. I tried to use this patch as it was, but due to the lack of differentiating information, it was impossible. So the first thing I changed was to enclose the target name between square brackets and prefix the with some hard coded string ('PROFILING:').

I played with this version a little and thought this 'one size fits all' approach was good enough.

In practice I have found the exact opposite to be practical.

Once I tried measuring a more complex build system with recursive calls, the recursion level was important. So was the pid.

When importing the data into Calc, having the duration directly available (without effort from the importer) was very practical.

After adding these to the hard coded information string, I realised that for simpler build systems removing the extra info about recursion, pid and end time stamp during import in Calc was an extra effort that would limit the usability of the feature[1].

That's why I added the format string feature. I dislike the unused parameters in the prof_print_* functions, too, but I wasn't able to find a cleaner solution.

Maybe a good compromise would be to have some hard coded predefined formatting types and one could choose between them.

Something like these:
- short - prints target, start and duration - e.g.: 'PROFILE:foo:1384896401494:4' - equivalent of -P'PROFILE:%N:%S:%D'
- compact - all fields present separated by ':' (without extra text) - equivalent of -P'PROFILE:%N:%L:%P:%S:%E:%D'
- long - something like the current default formatting string, but more verbose. - equivalent of -P"PROFILE:target=%N:level=%L:pid=%P:start=%S;end=%E;duration=%D"

This way the profiling info can scale from simple builds to complex ones, maybe the parsing could be eliminated entirely and the prof_print_* functions can be dropped etc.

We can set the details later, so what do you think?



[1] TBH, I found that what would have been exceptionally useful was if I could print time stamps relative to the earliest start time stamp so this calculation was not necessary at all in Calc. But having all the make instances communicate and arbitrate the minimum among them while deciding what to print seemed like too much code would be necessary and raised some questions regarding the printing: what happens if a slow target has the earliest start? Should the strings be stored and then recalibrated and printed at the very end? How useful would the partial info be for long builds?

Eddy Petrișor <eddyp>
Mon 25 Nov 2013 02:33:05 AM UTC, comment #4: 

Hi Eddy; thanks for your interest in improving GNU make!  I think the idea of providing more statistics for builds is very interesting.  While I agree it could be done externally (for example, by setting the SHELL variable to a command that would track the time spent) this could also have detrimental impacts (for example by setting SHELL you disable the fast-path ability of GNU make to directly fork/exec simple commands, without a shell).  You're also adding an extra fork/exec step into each command.

I have a few things to mention, however.  First, the code as you have it won't work on all platforms; in particular it won't work on Windows as Windows doesn't (by default) provide a gettimeofday() function.  There are various implementations around, so this isn't a huge issue.

Second, as written your patch is large enough that applying it would require copyright assignment of the changes by you to the FSF.  If you're interested in pursuing this email me directly and we'll discuss the details.

Third, I'm not sure about some things: for example, why use doubles when we're talking about integral values?  Actually GNU make has support for building on systems which don't even support floating point, so it's best to avoid doubles.

Lastly, and this is where we may need to have more conversation, I'm not so excited about adding the formatting capability, at least not this way.  I think that it could be a very useful thing to allow for specially-formatted output from GNU make.  For example, perhaps an output format in XML that could be easily sucked into tools like Eclipse or whatever for further parsing (I'm not a huge fan of XML but it is relatively universal).  Now that we have the output sync capability it would be straightforward to combine these and format the output of recipes for proper XML encoding as well.

But I don't want to add multiple different formatting options, for different types of output.  I'd prefer to have one comprehensive formatting capability.

So what I'd prefer is to split it so that this change deals solely with the profile information, and (if requested) will print it out in a standard (predefined) format.

Then at some future time someone can look into providing an output formatting definition capability for GNU make.

What do you think about this idea?  It may require some post-processing via sed, or whatever, to get the format needed for various purposes.

Paul D. Smith <psmith>
Group administrator
Sun 24 Nov 2013 04:20:40 PM UTC, comment #3: 

I rebased the patch on top of f5f5adb6, updated to use O and OS macros, and strlist type for the -P/--profile/--profile-format option parameter.

The patch is attached.

(file #29698)

Eddy Petrișor <eddyp>
Thu 21 Nov 2013 01:22:51 AM UTC, comment #2: 

I have cleaned up the code to remove the warnings that were generated by the newly introduced code.

I also reworked the rebase on the profile-rebase branch to contain cleaner patches and to separate the non-essential changes (e.g.: some whitespace fixes) from essential ones. Also the code for formattable profiling and the switch to using -P instead of -u have been squashed into a single commit for easier review.

The code is on the same branch as before:

https://github.com/eddyp/make-profiler/tree/profile-rebase


Eddy Petrișor <eddyp>
Tue 19 Nov 2013 10:29:22 PM UTC, comment #1: 

I have created a cleaned up rebased branch that contains only changes for the profiling feature so it can be easier to review.

https://github.com/eddyp/make-profiler/tree/profile-rebase


Please note this branch will be rebased. Use 'git pull --rebase' if you need to resync.

Eddy Petrișor <eddyp>
Tue 19 Nov 2013 09:31:16 PM UTC, original submission:  

Hello all,

For perfomance analysis of the build systems I maintain I have found the need for GNU Make to provide profiling information so it can help the developer with spotting the slow parts of the build system.

I have found others had the same need (see also the related patch #7447), but nobody was motivated enough to refine the patch to something useful.

I have taken the crude work done by OpenShift guest <zlqhem@daum.net> on profiling for make 3.82, I reworked it and updated to on top of the master version. I now I consider the profiling feature ready to be proposed for review.


Here is how it looks when used:

  1. eddy@heidi ~/usr/src/make/make-profiler $ ./make -P"target=%N start=%S duration=%D" >/dev/null

target=all start=1384896401494 duration=0
target=all-am start=1384896401494 duration=0
target=all start=1384896401498 duration=0
target=all-am start=1384896401498 duration=0
target=all start=1384896401508 duration=0
target=all-yes start=1384896401508 duration=0
target=check-macro-version start=1384896401503 duration=5
target=all start=1384896401512 duration=0
target=all-am start=1384896401512 duration=0
target=all-am start=1384896401539 duration=0
target=config.h start=1384896401527 duration=5
target=all-recursive start=1384896401487 duration=53
target=all start=1384896401466 duration=75
target=config.h start=1384896401462 duration=4




The new profiling parameter is -P[FMT]/--profile[=FMT]/--profile-format[=FMT].

The man page is also updated, so here is a quote:

 -P[FMT], --profile[=FMT], --profile-format[=FMT]
      Print to stderr profiling information for  each  run  target,  one
      line  per  target, according to format string FMT.  The FMT string
      can contain plain text and the following formatting sequences:

         %N target name
         %L recursion level for the make instance processing the target
         %P pid of the make instance processing the target
         %S start target timestamp (in miliseconds since 1 ian 1970)
         %E end target timestamp (in miliseconds since 1 ian 1970)
         %D difference between the target start and end  timestamps  (in
         miliseconds)
         %% literal %

         If  the option is repeated, all the FMT parameters are concate‐
         nated internally into a single formatting string.

         Any unrecognized % sequence will generate an error.  If the FMT
         string ends with a single % character, then that character will
         be ignored.

         The default FMT string is [PROF:%N:lvl=%L:pid=%P] %S;%E;%D.


My git repo is at (work is rebased on top of official master):

https://github.com/eddyp/make-profiler


The first results I got based on Make's own build system can be visible in this screenshot:

https://github.com/eddyp/make-profiler/blob/master-rebase/make-j_profile.png

Please tell me what you think, or tell me if you prefer a unified diff patch attached to this report for a review. Or maybe you prefer me to squash the profile related changes into a single commit.


Notes:
 - My master-rebase branch, as the name suggests, will be rebased
 - I am aware the code in my master-rebase contains the more mature profiling feature code and the less polished graph code; I will separate the profiling code from the graph code on different branches, but I have had the need to use both features

Eddy Petrișor <eddyp>

 

(Note: upload size limit is set to 16384 kB, after insertion of the required escape characters.)

Attach Files:
   
   
Comment:
   

Attached Files
file #29801:  profile-predefs-ga4937bc8.patch added by eddyp (10KiB - text/x-patch - The correct patch)
file #29698:  profile-gf5f5adb6.patch added by eddyp (13KiB - text/x-patch)

 

Depends on the following items: None found

Items that depend on this one: None found

 

Carbon-Copy List
  • -email is unavailable- added by psmith (Posted a comment)
  • -email is unavailable- added by eddyp (Submitted the item)
  •  

    There are 0 votes so far. Votes easily highlight which items people would like to see resolved in priority, independently of the priority of the item set by tracker managers.

    Only logged-in users can vote.

     

    Follow 3 latest changes.

    Date Changed by Updated Field Previous Value => Replaced by
    2013-12-07 eddyp Attached File- Added profile-predefs-ga4937bc8.patch, #29801
    2013-12-07 eddyp Attached File- Added profile-predefs-ga4937bc8.patch, #29800
    2013-11-24 eddyp Attached File- Added profile-gf5f5adb6.patch, #29698

    Back to the top

    Powered by Savane 3.13-02a9.
    Corresponding source code