Pushing the envelope of build performance

Basics of annotation files

If you've been working with SparkBuild and SparkBuild Insight for a while, you may be wondering about annotation files. There's a ton of data wrapped up in that xml structure, so here's a basic guide to the format and content of annotation.

Definition: Annotation is an XML document that is optionally produced by emake as it runs: it describes a build in detail

It looks like this:

<build id="8" start="9/27/2008 5:56:33 PM">    <properties>...</properties>
    <environment>...</environment>

    <make level="0" cmd="emake.exe --emake-annodetail=basic all"

                    cwd="C:/Documents and Settings/hpotter/home/tmp" mode="gmake">

        ...

        <job id="J012ba000" node="hogwarts1" type="rule"

             name="all" file="Makefile" line="2">

            <command line="3">

                <argv>echo hi</argv>

                <output src="prog">hi</output>

            </command>

            <timing invoked="0.286931" completed="0.359631" node="hogwarts1"/>

        </job>

        ...

    </make>

    <metrics>...</metrics>

</build>

There are different kinds of information which can be written into the annotation format, and the detail selection is set by a parameter to emake:

--emake-annodetail=<detail>

Detail levels include:

basic	arguments, commands, output - always present
waiting	dependent jobs ("who's waiting for me?")
env	environment variables across submakes

Elements of basic annotation include the <build>, <property>, and <var> elements:

<build id="10" start="9/28/2008 4:00:43 PM">

<property name="CommandLine">emake.exe --emake-annodetail=basic all</property>

<var name="HOST">bertie</var>

These tags are a great source of bookkeeping information. A lot of problems can be fixed just by looking at command line, versions, PATH and other environment variable settings.

Annotation also includes the <make> element, which tracks an individual submake:

<make level="0"    cmd="emake.exe --emake-annodetail=basic"
    cwd="C:/Documents and Settings/hpotter/home/tmp"

    mode="gmake">

Every place $(MAKE) is invoked, you get a <make> element

You'll also see <job> and <timing> elements, which track build work executed:

<job id="J012beac0" thread="df0590"     node="gryffindor1-1" type="rule"
     name="all" file="Makefile" line="2">

     <command ...>...</command>

     <timing invoked="0.521839" completed="0.627189" node="gryffindor-1"/>

</job>

Insight uses the <timing> elements inside each job to produce the treemap of build time.

Finally, <command> elements track process execution.
<argv> subelements tell you what was actually executed.
<output> elements tell you what was written to stdout/stderr.

<command line="3">    <argv>echo hi</argv>
    <output>echo hi

    </output>

    <output src="prog">hi

    </output>

</command>

<output> without a src attribute is from emake (like the echo for a command without an @ before it), while <output> with src="prog" is from the program.

Generating annotation output is easy:

emake --emake-annodetail=basic

will cause emake to print the annotation data to the console as the build runs. Since annotation contains everything which would normally have been printed to stdout, as well as additional markup data, it is straightforward to extract that 'original' log. SparkBuild ships with a utility to perform this task:

anno2log < anno.xml > logfile.stdout

Most people will find it useful to get ordinary build output on the console, and the annotation data in a file. This can be accomplished with anno2log as well:

emake ... | tee anno.xml | anno2log

The fastest way to read annotation is to open it with SparkBuild Insight:

sbinsight anno.xml

but you can also use text manipulation tools to parse it for information:

cat emake.local.xml | grep "type=\"rule" | wc -l

(This one-liner will print the number of makefile rules executed as part of your build.)

Now that you've got a basic primer for the annotation file format, try it out! You'll be amazed how much easier it is to debug a broken build when you have this kind of information.

Tags: annotation, debugging, emake, sparkbuild, xml

Comment

You need to be a member of SparkBuild Community to add comments!

Join SparkBuild Community

Comment by Eric Melski on November 12, 2009 at 8:34am: @Alex: great! Thanks for helping me track down the problem.

Comment by Alexander Gromnitsky on November 12, 2009 at 12:20am: The wrapped anno2log works fine. Thank you!

Comment by Eric Melski on November 12, 2009 at 12:01am: OK, I tried a newer version of TclXML and it seems that the 3.x line does not support partial input (which is odd, since the 2.x line did). I think the easiest thing to try next is a new wrapped anno2log that includes the patches I've given you previously — this way we can be sure that you are using the same Tcl and TclXML versions that I am. Let us know how this works for you: anno2log.

Comment by Alexander Gromnitsky on November 11, 2009 at 11:47pm: This is on Fedora 11:

> tclsh
% set tcl_patchLevel
8.5.6
% package require xml
3.2

texinfo-anno2log-patched-2.txt
anno.xml-2-fedora

Comment by Eric Melski on November 11, 2009 at 4:36pm: OK, both of those work fine for me. Perhaps it's a problem with the version of tcl or the TclXML package you are using? I'm using Tcl 8.4.6 with TclXML 2.6.

In any case, the error you're getting really means that the XML parser choked on the XML stream for some reason. This patch improves the error reporting there so we can see what the actual failure is: anno2log_error_report.diff.

Comment by Alexander Gromnitsky on November 11, 2009 at 1:17pm: I see the same errors on FreeBSD 7.2 and Fedora 11.

% uname -v
FreeBSD 7.2-STABLE #0: Sat May 16 10:09:13 EEST 2009 root@goliard.medieval:/usr/obj/usr/src/sys/ag_72_vmware_20090516
anno.xml-freebsd

% uname -a
Linux fedora.medieval 2.6.29.4-167.fc11.i686.PAE #1 SMP Wed May 27 17:28:22 EDT 2009 i686 i686 i386 GNU/Linux
anno.xml-fedora

Are we talking about the same version of anno2log? Mine after applying your patch is anno2log.

Comment by Eric Melski on November 11, 2009 at 12:46pm: I downloaded texinfo 4.13 and tried the same thing with no problems. What platform are you on? Can you upload the anno.xml that was generated by your build? Maybe there's some special character in there that's tripping up anno2log.

Comment by Alexander Gromnitsky on November 11, 2009 at 11:32am: I'm testing it with texinfo 4.13. See the log: texinfo-anno2log-patched.txt

Comment by Eric Melski on November 11, 2009 at 8:32am: @Alex, I'm not sure why you think it's not working — works as expected when I try it, even with your slow cat (in fact, I had written almost the same thing myself to test the patch before I posted it). One thing to watch out for here is that there are probably a couple hundred lines of other data in the annotation file before the first <output> tag appears; with this artificial test, that means it could be several seconds before you see any output. That might lead you to believe that the patch is not working, but once the slow cat gets into the actual meat of the annotation file you'll see that the output does start streaming as desired.

Comment by Alexander Gromnitsky on November 10, 2009 at 10:35pm: @Eric, I'm sorry but your fix ain't gonna work. :)

Try to test it with a dumb version of cat: cat_slow.

% ./cat_slow < anno.xml | ./anno2log-patched

Basics of annotation files

You need to be a member of SparkBuild Community to add comments!

Share