Issue 60948

Summary: Add profiling output to dmake
Product: Build Tools Reporter: quetschke
Component: dmakeAssignee: hjs <hans-joachim.lankenau>
Status: CLOSED FIXED QA Contact: issues@tools <issues>
Severity: Trivial    
Priority: P3 CC: hans-joachim.lankenau, issues, kai
Version: current   
Target Milestone: ---   
Hardware: All   
OS: All   
Issue Type: ENHANCEMENT Latest Confirmation in: ---
Developer Difficulty: ---
Attachments:
Description Flags
Profile patch for dmake
none
Adds profile output to build.pl
none
Combined profile patch
none
Sample build log for a single module.
none
Combined profile patch v2
none
Profiling patch for dmake/ none

Description quetschke 2006-01-21 17:44:54 UTC
Following a suggestion from Kai I implemented a proof of concept patch (hack ;)
for dmake to output profiling information.

It outputs the start and end time for each target and also the start and end
time for each recipe line, like this:

If a target is beeing started to make it looks like this:
(The number is the unix time in seconds since 1970 (or so) and the string
behind the number is the target name (all2 in this case))
s target 1137863769 all2

When a recipe starts it prints:
s recipe 1137863769 all2
When it ends:
e recipe 1137863769 all2

And when all recipe lines are made it prints:
e target 1137863769 all2

For this example makefile:
-- snip --
SHELL*:=/bin/sh 
SHELLFLAGS*:=-ce

all: all2
	+echo all-1
	+echo all-2

all2:
	+echo all2
-- snap --

You get this output:
$ dmake/dmake.exe -P2 -r      
s target 1137863769 all2
echo all2
s recipe 1137863769 all2
all2
e recipe 1137863769 all2
e target 1137863769 all2
s target 1137863769 all
echo all-1
s recipe 1137863769 all
echo all-2
all-1
e recipe 1137863769 all
s recipe 1137863769 all
all-2
e recipe 1137863769 all
e target 1137863769 all
s target 1137863769 .TARGETS
e target 1137863769 .TARGETS
s target 1137863769 .ROOT
e target 1137863769 .ROOT


(.ROOT and .TARGETS are internal targets, ignore them ;) )

It even works for parallel builds ;) Unfortunately all commands are so fast that
everything is executed in the same second, but you get the idea. ;)

If someone tells me a nice name for this switch, or two for seperately
controling target and recipe information I will implement it into dmake43p01.

Suggestions are welcome!
Comment 1 quetschke 2006-01-21 17:47:27 UTC
Created attachment 33436 [details]
Profile patch for dmake
Comment 2 quetschke 2006-01-21 17:48:42 UTC
Please note that you need the dmake from branch cws_src680_dmake43p01 to use
this patch.
Comment 3 quetschke 2006-01-23 23:23:14 UTC
I will implement the following:

-m[tra] Measure timing information. Print the time when targets and/or
        recipes are started and finished to stdout. The following format
        is used:
           {s|e} {target|recipe} time target
        s or e stands for started or ended, target or recipe denotes if this
        line refers to the whole target or a recipe. time is displayed in
        Unix time format, i.e. the number of seconds since an epoch. (Since
        1970-01-01T00:00:00Z). target obviously represents the target the
        information is given for. The optional flags [tra] can be used to
        restrict the information that is displayed. If no optional flags are
        given all flags are assumed to be selected. The optional flags stand
        for:

        t  Display the start and end of each target.
        r  Display the start and end of each recipe.
        a  Display the target as an absolute path, i.e. prepend the current
           working directory.
Comment 4 kaibackman 2006-01-25 12:56:47 UTC
Created attachment 33546 [details]
Adds profile output to build.pl
Comment 5 kaibackman 2006-01-25 12:59:50 UTC
Thanks Volker! :-)

I also added a quick hack to build.pl to get the total build time. Volker, if 
dmake is called through build, how can we pass it parameters to ensure all 
nested dmake calls will produce profile output?
Comment 6 kaibackman 2006-01-25 14:44:06 UTC
Created attachment 33549 [details]
Combined profile patch
Comment 7 kaibackman 2006-01-25 14:45:41 UTC
Created attachment 33550 [details]
Sample build log for a single module.
Comment 8 kaibackman 2006-01-25 15:05:08 UTC
Created attachment 33552 [details]
Combined profile patch v2
Comment 9 kaibackman 2006-01-25 15:11:45 UTC
The profile_combined2.diff is now the patch you should use if you want to 
provide profile information on your build.

Take a look at this wiki page for profile instructions:
http://wiki.services.openoffice.org/wiki/BuildSpeedup

In summary: redirect both stdout and stderr to the same log file.

Changes versus vq's dmake patch and my earlier patches:
- Removed recipe line output (target information is enough)
- dmake now reports timing information in ms instead of sec
- Only report targets we are actually rebuilding
- cleaned up the output somewhat by ignoring shell escape end targets (?)
- patch works on standard dmake, no need for dmake43p01
Comment 10 quetschke 2006-02-01 23:30:45 UTC
Created attachment 33774 [details]
Profiling patch for dmake/
Comment 11 quetschke 2006-02-01 23:33:42 UTC
I committed the previous patch to dmake43p01.

See dmake/man/dmake.tf for a description of the new feature.
Comment 12 quetschke 2006-02-01 23:39:23 UTC
@ause: Please verify!

P.S.: Only the dmake related parts were considered/committed. The build.pl part
has to be handled by another issue.
Comment 13 hjs 2006-06-13 18:10:59 UTC
oops... doesn't appear here as an issue of dmake43p01.
Comment 14 hjs 2006-06-13 18:20:23 UTC
.