Annotation

12 minute read

As eMake runs a build, it discovers a large amount of information about the build structure. This information can be written to an annotation file for use after the build completes. Annotation is represented as an XML document to make parsing easy.

eMake collects many different types of information about the build depending on various eMake command-line options. This information includes:

  • Makefile structure

  • Commands and command output

  • List of file accesses by each job

  • Dependencies between jobs

  • Detailed timing measurements

  • eMake invocation arguments and environment

  • Performance metrics

eMake can also be configured to upload annotation information to the Cluster Manager for centralized reporting.

Configuring eMake to generate an annotation file

By default, eMake collects configuration information and performance metrics only, which it sends to the Cluster Manager at the end of the build. This data is used to display reports on the Build Details page.

You can configure eMake to collect additional information. This information is written to an XML file in the build directory ( emake.xml by default). The --emake-annodetail option controls the amount of information that eMake collects. Default annotation detail is determined by the build class for that build.

Collecting annotation information might cause your build to run about 5% slower.

Following are the annotation detail arguments:

Argument Description

basic

Information about every command run by the build. Detailed information about each “job” in the build is recorded, including command arguments, output, exit code, timing, and source location. Also, the build structure is a tree where each recursive make level is represented in the XML output.

If the JobCache feature is enabled, basic annotation includes annotation about cache hits and misses. For details, see Interpreting JobCache Annotation Information.

env

Environment variable modifications

file

Files read or written by each job (excluding files that were looked up)

history

Missing serializations discovered by eMake. This includes information about which file caused two jobs to become serialized by the eMake history mechanism

lookup

Files that were looked up by each job. This mode can cause the annotation file to become quite large.

md5

Computes MD5 checksums for files read and written by the build, and includes that information as an MD5 attribute on appropriate <op> tags. The operation types that will include the checksum are read, create, and modify.

No checksum is generated or emitted for operations on directories, symlinks. or append operations. If a read file was appended to, and the read occurs before the appended update is committed, a zero checksum appears on that read operation (by design because reading files that were appended to occurs rarely).

This argument implies “file” level annotation. This mode is configurable through the command line only; it is not available on the web interface.

registry

Registry operations

waiting

Information for reconstructing the complete dependency graph for the build

Any detail argument enables “basic” annotation automatically.

The --emake-annoupload option controls whether eMake sends a copy of the annotation file to the Cluster Manager as the build runs. By default, eMake sends minimal information to the Cluster Manager, even if more detailed annotation is enabled. eMake sends the full annotation file if annotation uploading is configured by the build class or via the eMake command line.

You cannot disable mergestreams if you enable annotation. Enabling annotation automatically enables mergestreams, even if it was explicitly disabled on the command line.

Annotation file splitting

Because of limitations in the 32-bit version of the Insight tool, 32-bit eMake as well as 32-bit Electrify automatically partition annotation files into 1.6 GB “chunks.” The first chunk is named using the file name that you specify with the --emake-annofile option or with “emake.xml,” if --emake-annofile is not specified. The second chunk uses that name as the base but adds the suffix _1, the third chunk adds the suffix _2, and so on. For example, a four-part annotation file might consist of files named emake.xml, emake.xml_1, emake.xml_2, and emake.xml_3.

No special action is required to load a multipart annotation file into Insight. If all parts are in the same directory, Insight automatically finds and loads the content of each file—simply specify the name of the first chunk when opening the file in Insight.

For loading large annotation files, CloudBees recommends the 64-bit version of Insight.

Working with annotation files

The simplest way to use an eMake annotation file is to load it into Insight. This tool lets you see a graphical representation of the build, search the annotation file for interesting patterns, and perform sophisticated build analysis using its built-in reporting tools.

Creating tools for tasks that use annotation output

You can write your own tools to perform simple tasks that use annotation output. For example, reporting on failures in the build by looking for “failed” elements inside job elements and then reporting details about the failed job such as the commands, their output, and the line of the makefile that contains the rule for the command. See the DTD below or the annotation file format.

Annotation XML DTD

<!-- build.dtd --> <!-- The DTD for Emake's annotated output. --> <!-- --> <!-- Copyright (c) 2004-2008 CloudBees, Inc. All rights reserved. -->
<!ENTITY % hexnum "CDATA"> <!ENTITY % job "(message*, job)"> <!ENTITY % valueName "name NMTOKEN #REQUIRED"> <!-- Can't use NMTOKEN because Windows has environment variables like "=D:". --> <!ENTITY % envValueName "name CDATA #REQUIRED">
<!ELEMENT build (properties?, environment?, (message* | make)+, fs?, metrics? ) > <!ATTLIST build id CDATA #REQUIRED cm CDATA #IMPLIED start CDATA #REQUIRED > <!-- Out of band build messages -->
<!ELEMENT message (#PCDATA) > <!ATTLIST message thread %hexnum; #REQUIRED time CDATA #REQUIRED code CDATA #REQUIRED severity ( warning | error ) #REQUIRED > <!-- Properties list -->
<!ELEMENT properties (property*) > <!ELEMENT property (#PCDATA) > <!ATTLIST property %valueName; > <!-- Environment list -->
<!ELEMENT environment (var*) > <!ELEMENT var (#PCDATA) > <!ATTLIST var %envValueName; op ( add | modify | delete ) "add" > <!-- File system dump -->
<!ELEMENT fs (roots, symRoots, (content|name)*) > <!ELEMENT roots (root+) > <!ELEMENT root (#PCDATA) > <!ATTLIST root nameid CDATA #REQUIRED > <!ELEMENT symRoots (symRoot*) > <!ELEMENT symRoot (#PCDATA) > <!ATTLIST symRoot symLinkPath CDATA #REQUIRED > <!ELEMENT content (contentver+)> <!ATTLIST content contentid CDATA #REQUIRED > <!ELEMENT contentver EMPTY> <!ATTLIST contentver job CDATA #REQUIRED > <!ELEMENT name (namever*) > <!ATTLIST name nameid CDATA #REQUIRED dir CDATA #REQUIRED name CDATA #REQUIRED > <!ELEMENT namever EMPTY> <!ATTLIST namever job CDATA #REQUIRED contentid CDATA #REQUIRED > <!-- Metrics list -->
<!ELEMENT metrics (metric*) > <!ELEMENT metric (#PCDATA) > <!ATTLIST metric %valueName; > <!-- Make subtree -->
<!ELEMENT make (environment?, ( message | job | make )*) > <!ATTLIST make level CDATA #REQUIRED cmd CDATA #REQUIRED cwd CDATA #REQUIRED mode ( gmake | nmake | symbian ) #REQUIRED > <!-- Job -->
<!ELEMENT job (environment?,(output | command | conflict)*,depList?,opList?, registryOpList?,timing+,failed?,waitingJobs?) > <!ATTLIST job thread %hexnum; #REQUIRED id ID #REQUIRED status ( normal | rerun | conflict | reverted | skipped ) "normal" type ( continuation | end | exist | follow | parse | remake | rule ) #REQUIRED name CDATA #IMPLIED file CDATA #IMPLIED line CDATA #IMPLIED neededby IDREF #IMPLIED partof IDREF #IMPLIED node CDATA #IMPLIED > <!-- Command and related output, output blocks can contain nested --> <!-- make subtrees in local mode. -->
<!ELEMENT command (argv,inline*,(output | make)*) > <!ATTLIST command line CDATA #IMPLIED > <!ELEMENT argv (#PCDATA)> <!ELEMENT inline (#PCDATA)> <!ATTLIST inline file CDATA #REQUIRED > ‘<!ELEMENT output (#PCDATA)> <!ATTLIST output src ( prog | make ) "make" > <!-- Conflict description -->
<!ELEMENT conflict EMPTY> <!ATTLIST conflict type ( file | cascade | name | key | value ) "cascade" writejob IDREF #IMPLIED file CDATA #IMPLIED rerunby IDREF #IMPLIED hkey CDATA #IMPLIED path CDATA #IMPLIED value CDATA #IMPLIED > <!-- Job failure code -->
<!ELEMENT failed EMPTY> <!ATTLIST failed code CDATA #REQUIRED > <!-- List of jobs waiting for this job, local mode only -->
<!ELEMENT waitingJobs EMPTY> <!ATTLIST waitingJobs idList IDREFS #IMPLIED > <!-- Start and stop times of this job -->
<!ELEMENT timing EMPTY> <!ATTLIST timing invoked CDATA #REQUIRED completed CDATA #REQUIRED node CDATA #IMPLIED > <!-- Dependency list, only used when annoDetail includes 'history' -->
<!ELEMENT depList (dep*)> <!ELEMENT dep EMPTY> <!ATTLIST dep writejob IDREF #REQUIRED file CDATA #REQUIRED > <!-- Operation list, only present when annoDetail includes --> <!-- 'file' or 'lookup' -->
<!ELEMENT opList (op*)> <!ELEMENT op EMPTY> <!ATTLIST op type ( lookup | read | create | modify | unlink | rename | link | modifyAttrs | append | blindcreate ) #REQUIRED file CDATA #REQUIRED other CDATA #IMPLIED found ( 1 | 0 ) "1" isdir ( 1 | 0 ) "0" filetype ( file | symlink | dir ) "file" atts CDATA #IMPLIED > <!-- Registry operation list, only present when annoDetail includes --> <!-- 'registry' -->
<!ELEMENT registryOpList (regop*)> <!ELEMENT regop (#PCDATA)> <!ATTLIST regop type ( createkey | deletekey | setvalue | deletevalue | lookupkey | readkey ) #REQUIRED hkey CDATA #REQUIRED path CDATA #REQUIRED name CDATA #IMPLIED datatype ( none | sz | expandsz | binary | dword | dwordbe | link | multisz | resourcelist | resourcedesc | resourcereqs | qword ) "none" >

Metrics in annotation files

The following values are available when you select the Metrics option from the drop-down menu on the Build Details page in the web interface. Some performance metrics are available only with --emake-debug=g.

Timer annotation

Most timers are available unless you use --emake-debug=g (for profiling). These timers correspond to the amount of time that eMake spent in certain areas of the code or in a certain state.

Metric Description

timer:agentManager.should RequestAgents

Time spent checking to see if eMake should be requesting agents, which involves talking to the Cluster Manager

timer:agentManager.startup

Time spent for the Agent Manager to start up

timer:agentManager.stop

Time spent for the Agent Manager to shut down

timer:agentManager.work

Time spent with the Agent Manager actively doing work outside shouldRequestAgents

timer:annoUpload.startup

Time spent starting up the thread to upload annotation

timer:annoUpload.work

Time spent uploading annotation

timer:bench

Benchmark showing the cost of 100 invocations of the timer code (start/stop)

timer:directory.populate

Time spent making sure that eMake’s model of the directory contents is fully populated

timer:history.parsePrune

Time spent in parse jobs signaling stale history entries to prune stale events

timer:history.pruneFollowers

Time spent signaling stale submakes (for jobs that have followers) to be pruned

timer:history.pruneNo Follower

Time spent signaling stale submakes (for jobs that have no followers) to be pruned in job

timer:idle.agentManager

Time spent in the Agent Manager sleeping between shouldRequestAgents checks

timer:idle.agent ManagerRequest

Time spent in the Agent Manager waiting for the Cluster Manager to respond to a request for agents

timer:idle.agentRun

Time spent by worker threads waiting for requests from the agent

timer:idle.annoUpload

Time spent by the annotation upload thread waiting for data

timer:idle.noJobs

Time spent by worker threads waiting for a new runnable job to enter the job queue

timer:idle.untilCompleted

Time spent by the Terminator thread waiting for jobs to be completed

timer:idle.waitForAgent

Time spent by worker threads waiting for an agent to become available

timer:jobCache.sharedMiss

(Shared JobCache only) Sum of seconds spent trying to find a match in the shared cache but ultimately failing to do so

timer:jobqueue

Time spent within the lock guarding the job queue

timer:Ledger.close

Time spent closing the Ledger and flushing data to disk

timer:Ledger.commit

Time spent committing Ledger data to the database

timer:Ledger.isUpToDate

Time spent querying the Ledger to find if a file is up to date

timer:Ledger.staleAttributes

Time spent by the Ledger code statting files to ensure recorded attributes match the actual attributes on disk

timer:Ledger.update

Time spent updating the Ledger

timer:main.commit

Time spent by the Terminator thread committing jobs, less time spent flushing deferred writes to disk

timer:main.history

Time spent reading and writing history files.

timer:main. lockedWriteToDisk

Time spent by the Terminator thread flushing deferred writes to disk

timer:main.terminate

Time spent by the Terminator thread terminating jobs

timer:main.writeToDisk

Time spent by the Terminator thread writing operations to disk, less the time covered by any of the other main.writeToDisk timers

timer:main.writeTodisk append

Time spent appending to existing files on disk

timer:main.writeTodisk createdir

Time spent creating directories on disk

timer:main.writeTodisk createdir.attrs

Time spent changing directory attributes on disk for new directories

timer:main.writeTodisk createdir.chown

Time spent changing file ownership on disk for new files

timer:main.writeTodisk createdir.chown

Time spent changing directory ownership on disk for new directories

timer:main.writeTodisk createdir.times

Time spent changing directory times on disk for new directories

timer:main.writeTodisk createfile

Time spent writing file data to disk for new files

timer:main.writeTodisk createfile.attrs

Time spent changing file attributes on disk for new files

timer:main.writeTodisk createfile.times

Time spent changing file times on disk for new files

timer:main.writeTodisklink

Time spent creating links on disk

timer:main.writeTodisk modify

Time spent modifying existing files on disk

timer:main.writeTodisk modifyAttrs

Other time spent in writing attribute changes to disk (mostly notifying the file system that attributes have gone “stale”)

timer:main.writeTodisk modifyAttrs.attrs

Time spent modifying attributes of existing files on disk

timer:main.writeTodisk modifyAttrs.chown

Time spent modifying ownership of existing files on disk

timer:main.writeTodisk modifyAttrs.times

Time spent modifying times of existing files on disk

timer:main.writeTodisk unlink

Time spent unlinking existing files on disk

timer:main.writeTodisk unlink.data

Time spent recording the fact that a file was removed

timer:main.writeTodisk unlink.tree

Time spent removing entire trees on disk

timer:mergeArchiveRefs

Time spent modifying word lists for multi-word archive references such as lib(member1 member2 …​)

timer:mutex.DirCache

Time spent waiting for a directory cache

timer:mutex.filedata.nodelist

Time spent within the lock guarding the list of agents allocated to the build

timer:mutex.jobcreate

Time spent within the lock used to synchronize the terminator and worker threads when creating jobs

timer:mutex.joblist

Time spent within the lock used to protect the job list

timer:mutex.jobrunstate

Time spent within the lock used to coordinate starting and canceling jobs

timer:mutex.nodeinit

Time spent within the lock used to protect the list of hosts while initializing agents

timer:mutex.target

Time spent within the lock protecting failure tracking on a target

timer:node.putAllVersions. getShortName

Time spent getting file short names on Windows when doing an E2A_PUT_ALL_VERSIONS

timer:node.setup

Time spent connecting to hosts and initializing them

timer:node.svc.getData

Time spent handling A2E_GET_FILE_DATA and A2E_RESEND_FILE_DATA, not including the time spent sending data in response

timer:node.svc.getData. acquireLock

Time spent waiting for the ChainLock when handling A2E_GET_FILE_DATA and A2E_RESEND_FILE_DATA

timer:node.svc.getData.copy

Time spent copying file data for E2A_LOAD_LOCAL_FILE. This is the local agent version of timer:node.svc.getData.send

timer:node.svc.getData. insideLock

Time spent holding the ChainLock when handling A2E_GET_FILE_DATA and A2E_RESEND_FILE_DATA

timer:node.svc.getData.send

Time spent sending file data during E2A_PUT_FILE_DATA and E2A_PUT_BIG_FILE_DATA.

timer:node.svc.getDir

Time spent sending directory entry data to the agent

timer:node.svc.getVersions

Time spent handling A2E_GET_ALL_VERSIONS requests

timer:node.svc.getVersions. acquireLock

Time spent waiting for the ChainLock when handling A2E_GET_ALL_VERSIONS

timer:node.svc.getVersions. insideLock

Time spent holding the ChainLock when handling A2E_GET_ALL_VERSIONS

timer:node.svc.runCommand

Time spent handling A2E_RUN_COMMAND requests

timer:usage.io

Time spent reading and responding to usage data

timer:usage.io.makedata

Time spent creating file data from usage

timer:usage.io. makedata.local

Time spent copying file data from usage reported by local agents; a subset of timer:usage.io.makedata

timer:usage.latency

Time spent dispatching incoming usage data and saving output files

timer:usage.record

Time spent recording usage data, including resolving new name IDs, removing duplicate lookup records, and so on

timer:worker.continuationjob

Time spent by worker threads running continuationJobs

timer:worker.endjob

Time spent by worker threads running endJobs.

timer:worker.existencejob

Time spent by worker threads running existenceJobs

timer:worker.followjob

Time spent by worker threads running followJobs

timer:worker.invoke

Time spent invoking remote jobs

timer:worker.invokelocal

Time spent invoking local jobs

timer:worker.other

Otherwise unaccounted time spent by worker threads

timer:worker.parsejob

Time spent by worker threads running parseJobs.

timer:worker.remakejob

Time spent by worker threads running remakeJobs

timer:worker.rulejob

Time spent by worker threads running ruleJobs, less the time spent actually running commands and figuring out if it needs to run

timer:worker.rulejob. needtorun

Time spent by ruleJobs figuring out if they need to run

timer:worker. runcommands

Time spent by worker threads running commands in commandJobs

timer:worker. shouldRequestAgents

Time spent by worker threads checking to see if they should request agents

timer:worker.startup

Time spent by worker threads initializing

timer:worker.stop

Time spent shutting down worker threads

timerThreadCount

Number of threads in eMake

Other annotation

Metric Description

chainLatestReads

Number of times the latest version of an FSChain was requested

chainSerialReads

Number of times an FSChain was requested to match a particular spot in the serial order

chainWrites

Number of new versions created, which occurs any time a new name is created, or the content of a file changes

clusterAvailability

Cluster availability percentage

compressBytesIn

Number of bytes passed in for compression

compressBytesOut

Number of bytes returned from compression

compressTime

Time spent compressing data

conflicts

Number of jobs that ran into conflicts and had to be rerun

decompressBytesIn

Number of bytes passed in for decompression

decompressBytesOut

Number of bytes returned from decompression

decompressTime

Time spent decompressing data

diskReadBytes

Number of bytes read from the local disk

diskReadTime

Time spent reading data from the local disk

diskReadWaitTime

Time spent waiting for data to be read from the local disk

diskWriteBytes

Number of bytes written to the local disk

diskWriteTime

Time spent writing data to the local disk

diskWriteWaitTime

Time spent waiting for data to be written to the local disk

duration

Duration of build (in seconds)

elapsed

The total elapsed time for the build

emptyNameVersions

Total number of Name versions with no associated Content. Available with --emake-debug=g

fitness

Indicates the "fitness" of the history, which is how closely the history used for a given build "matched" that build. The range of values is 0 (history did not match at all) to 1 (history already had information about all implicit dependencies)

Available with --emake-debug=g

freezeTime

Time the job queue was frozen, which means only high priority items are taken of the queue

hiddenWarningCount

Number of warning messages hidden by the eMake client and all remote parse jobs, with one count for every message number for which at least one message was hidden. The count does not include messages hidden by eMake stubs or rlocal-mode eMakes

jobcache.hit

Number of jobs for which eMake obtained job cache hits. A hit means that the job was replayed from the cache. This is the sum of the jobcache.hit.local and jobcache.hit.shared hits

jobcache.hit.local

(Shared JobCache only) Number of jobs for which eMake obtained job cache hits from the developer’s local cache (instead of the shared cache). A hit means that the job was replayed from the local cache

jobcache.hit.shared

(Shared JobCache only) Number of jobs for which eMake obtained job cache hits from the shared cache (instead of the developer’s local cache). A hit means that the job was replayed from the shared cache

jobcache.miss

Number of jobs for which a file system input changed since the last time the job was saved into the cache

jobcache.na

Number of jobs for which job caching was not applicable. For example, jobs for which the output files are not object files

jobcache.newslot

Number of jobs for which eMake created a new cache slot. This occurs when the previously-cached jobs differed from these jobs in their command-line arguments, relevant environment variables, or working directories. Together, these parameters of a job choose the slot for that job, which is where eMake stores the results of that job

jobcache.rootschanged

Number of jobs for which there is no natural mapping from the old eMake roots to the new eMake roots

jobcache.sharedmiss

(Shared JobCache only) Number times that eMake found a matching slot in the shared cache but determined it was a mismatch because a file system input changed

jobcache.sharednewslot

(Shared JobCache only) Number of times that eMake failed to find a matching slot in the shared cache

jobcache.uncacheable

Number of jobs for which eMake encountered an issue updating the job’s relevant cache slot. Look for ERROR and WARNING messages in the console output from eMake. Jobs that failed, jobs for which caching was disabled by the #pragma jobcache none pragma, and jobs that did not access files inside the eMake root are included in this metric

jobcache.unneeded

Number of jobs for which JobCache was enabled but not needed (because the target was already up to date according to ordinary GNU Make rules). The cache was not consulted, even though caching was requested for that target

jobcache.workloadsaved

Difference between agent usage (in seconds) with and without the JobCache feature. This represents an estimate of the agent usage saved by the JobCache feature

localAgentReadBytes

Bytes copied from local agents

localAgentReadTime

Time spent copying data from local agents

localAgentWriteBytes

Bytes copied to local agents

localAgentWriteTime

Time spent copying data to local agents

maxArenaCount

Peak active arenas during the build

maxMakeCount

Peak active make instances during the build

noAgentsWaitTime

Time spent waiting with no agents allocated to the build because the number of running agents has reached the license limit

noLicenseWaitTime

Time spent waiting for a build license because the number of concurrent builds has reached the license limit.

nodeReadBytes

Number of bytes read from agents

nodeReadTime

Time spent reading data from agents

nodeReadWaitTime

Time spent waiting for data to be read from agents

nodeWriteBytes

Number of bytes written to agents

nodeWriteTime

Time spent writing data to agents

nodeWriteWaitTime

Time spent waiting for data to be written to agents

OutputHistoryMD5

MD5 checksum of the history file that was generated by a build

runjobs

Number of jobs that did work

symlinkReads

Number of times the application read symlinks from the local disk

termDiskCopiedBytes

Number of bytes committed by copying. This should be a small number if possible. If you are using ClearCase and this number is nonzero, look into the --emake-clearcase=vobs option

termDiskCopiedFiles

Number of files committed by copying. This number should be small if possible

termDiskMovedBytes

Number of bytes committed by moving. You want this to be big number if possible

termDiskMovedFiles

Number of files committed by moving. You want this to be a big number if possible

termDiskRemovedBytes

Number of bytes committed by remove (original file)

termDiskRemovedFiles

Number of files committed by remove (original file)

termDiskRemoved TmpBytes

Number of bytes committed by remove (temporary file)

termDiskRemoved TmpFiles

Number of files committed by remove (temporary file)

terminated

Number of jobs that ran to completion. These jobs might not necessarily have done anything

totalAgentCount

Total number of agents in cluster

totalChains

Total number of FSChains in the build—anything in the file system tracked by eMake for versioning is an FSChain, for example, file names, file contents. Because both names and contents are tracked, this should be at least twice the number of files accessed in the build

totalNameVersions

Total number of Name versions. Available with --emake-debug=g

totalVersions

Total number of FSChain versions. Available with --emake-debug=g

totality

The percentage of jobs were that were not up-to-date. A full clean build would have a totality of 100.

timer:jobcache.sharedMiss

(Shared JobCache only) Sum of seconds spent trying to find a match in the shared cache but ultimately failing to do so

usageBytes

Number of bytes received for usage data

workload

Sum of agent usage over all agents (in seconds). This value is also reported to the Cluster Manager

writeThrottleWaitTime

Time spent waiting for the write throttle (which is in place to avoid slowing the build by seeking the disk head back and forth too often)