Issue 60948 - Add profiling output to dmake
Summary: Add profiling output to dmake
Status: CLOSED FIXED
Alias: None
Product: Build Tools
Classification: Code
Component: dmake (show other issues)
Version: current
Hardware: All All
: P3 Trivial (vote)
Target Milestone: ---
Assignee: hjs
QA Contact: issues@tools
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2006-01-21 17:44 UTC by quetschke
Modified: 2013-08-07 15:34 UTC (History)
3 users (show)

See Also:
Issue Type: ENHANCEMENT
Latest Confirmation in: ---
Developer Difficulty: ---


Attachments
Profile patch for dmake (4.25 KB, patch)
2006-01-21 17:47 UTC, quetschke
no flags Details | Diff
Adds profile output to build.pl (673 bytes, patch)
2006-01-25 12:56 UTC, kaibackman
no flags Details | Diff
Combined profile patch (3.40 KB, patch)
2006-01-25 14:44 UTC, kaibackman
no flags Details | Diff
Sample build log for a single module. (59.03 KB, text/plain)
2006-01-25 14:45 UTC, kaibackman
no flags Details
Combined profile patch v2 (3.25 KB, patch)
2006-01-25 15:05 UTC, kaibackman
no flags Details | Diff
Profiling patch for dmake/ (44.57 KB, patch)
2006-02-01 23:30 UTC, quetschke
no flags Details | Diff

Note You need to log in before you can comment on or make changes to this issue.
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
.