Build log verbosity changes

[Magnus Ihse Bursie]

On 2012-10-10 16:08, Jonathan Gibbons wrote:
> Magnus,
>
> This past week I've been running the build a number of times and been 
> monitoring how long javadoc takes to execute.  Does it make sense to 
> have some way to instrument how long different commands take to 
> execute, perhaps in some tracing mode, so that we can analyse attempts 
> to improve overall performance?

Very good idea!

I just created an unholy alliance of shell script magic and makefile 
voodoo, which does just this. (I can't decide if I'm proud or ashamed of 
the thing :-))

Basically, it runs each shell command from make (a line in a recipe or a 
$(shell) expression) using /usr/bin/time, and stores the output in a 
build-trace-time.log in the build output directory.

I'm not quite sure how helpful it will be to analyse performance. On the 
other hand, it should be quite simple to extend the shell-tracer.sh 
script to add more useful analysis. So this is more of a 
framework-with-a-proof-of-concept, perhaps.

If I let make run for a minute, and then do:

$ grep ^.TIME < build-trace-time.log | sort -nr | head -n 4

I get:

[TIME:0:41.31] -c (cd /localdata/hg/build-infra-jdk8/langtools/makefiles && /bin/bash /localdata/hg/build-infra-jdk8/common/bin/logger.sh /localdata/hg/build-infra-jdk8/build/linux-x86_64-normal-server-release/build.log /usr/bin/make  VERBOSE="" -R -I /localdata/hg/build-infra-jdk8/common/makefiles "SPEC=/localdata/hg/build-infra-jdk8/build/linux-x86_64-normal-server-release/spec.gmk" -j4)

[TIME:0:27.52] -c (cd /localdata/hg/build-infra-jdk8/jaxws/makefiles && /bin/bash /localdata/hg/build-infra-jdk8/common/bin/logger.sh /localdata/hg/build-infra-jdk8/build/linux-x86_64-normal-server-release/build.log /usr/bin/make  VERBOSE="" -R -I /localdata/hg/build-infra-jdk8/common/makefiles "SPEC=/localdata/hg/build-infra-jdk8/build/linux-x86_64-normal-server-release/spec.gmk" -j4)

[TIME:0:24.22] -c (cd /localdata/hg/build-infra-jdk8/corba/makefiles && /bin/bash /localdata/hg/build-infra-jdk8/common/bin/logger.sh /localdata/hg/build-infra-jdk8/build/linux-x86_64-normal-server-release/build.log /usr/bin/make  VERBOSE="" -R -I /localdata/hg/build-infra-jdk8/common/makefiles "SPEC=/localdata/hg/build-infra-jdk8/build/linux-x86_64-normal-server-release/spec.gmk" -j4)

[TIME:0:23.71] -c (/usr/lib/jvm/java-7-openjdk/bin/java -Xms64M -Xmx1100M -XX:PermSize=32m -XX:MaxPermSize=160m -XX:ThreadStackSize=1536 -Xbootclasspath/p:/localdata/hg/build-infra-jdk8/build/linux-x86_64-normal-server-release/langtools/dist/bootstrap/lib/javac.jar -jar /localdata/hg/build-infra-jdk8/build/linux-x86_64-normal-server-release/langtools/dist/bootstrap/lib/javac.jar -XDignore.symbol.file=true -Xlint:all,-varargs,-rawtypes,-deprecation,-unchecked,-serial,-dep-ann,-cast,-fallthrough,-static -g  -cp /localdata/hg/build-infra-jdk8/build/linux-x86_64-normal-server-release/jaxp/dist/lib/classes.jar -implicit:none -sourcepath "/localdata/hg/build-infra-jdk8/jaxws/src/share/jaxws_classes" -d /localdata/hg/build-infra-jdk8/build/linux-x86_64-normal-server-release/jaxws/jaxws_classes  @/localdata/hg/build-infra-jdk8/build/linux-x86_64-normal-server-release/jaxws/jaxws_classes/_the.batch.tmp && /bin/mv /localdata/hg/build-infra-jdk8/build/linux-x86_64-normal-server-release/jaxws/jaxws_classes/_the.batch.tmp /localdata/hg/build-infra-jdk8/build/linux-x86_64-normal-server-release/jaxws/jaxws_classes/_the.batch)


/Magnus