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 |
---|---|
|
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. |
|
Environment variable modifications |
|
Files read or written by each job (excluding files that were looked up) |
|
Missing serializations discovered by eMake. This includes information about which file caused two jobs to become serialized by the eMake history mechanism |
|
Files that were looked up by each job. This mode can cause the annotation file to become quite large. |
|
Computes MD5 checksums for files read and written by the build, and includes that information as an MD5 attribute on appropriate 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 operations |
|
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 |
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 |
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 |
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 |
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 |
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 |
totalVersions |
Total number of FSChain versions. Available with |
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) |