How to Enable Xentrace Logging and Format With Xentrace_Format

This article describes how to enable Xentrace logging and format with Xentrace_Format.

Xentrace is used to capture trace buffer data from XenServer. Among other things, It can be used to identify where large amounts of time are spent in the hypervisor, track the series of hypervisor interactions leading to a crash, or to identify runtime attributes of a system.

Usage

xentrace [OPTIONS] [FILE]

Data is output in the following binary format:

CPU(uint) TSC(u64) EVENT(u32) D1 D2 D3 D4 D5 (all u32)

Where CPU is the processor number, TSC is the record's timestamp (the value of the CPU cycle counter), EVENT is the event ID and D1 through D5 are the trace data.

Data from xentrace is dumped on to the standard output (which must not be a TTY) or a FILE specified on the command line. The output should be parsed using the tool xentrace_format, which can produce human-readable output in ASCII format.

xentrace_format parses trace data in xentrace binary format from standard input and reformats it according to the rules in a file of definitions (DEFS-FILE). The rules in DEFS-FILE should have the following format:

event_id whitespace format

Each rule should start on a new line. The format string may include format specifiers, such as: %(cpu)d, %(tsc)d, %(event)d, %(1)d, %(2)d, %(3)d, %(4)d, %(5)d

Note: the 'd' format specifier outputs in decimal, 'x' outputs in hexadecimal, and 'o' outputs in octal

As noted earlier, these correspond to the CPU number, event ID, timestamp counter and the five data fields from the trace record. There should be one such rule for each type of event to be printed (events which do not have formatting rules are ignored).

A sample format file for Xen's predefined trace events is available in disk one of the XenServer source code (available from the Citrix XenServer download page):

{cd media}\xen\xen-3.2.1-5.0.0.235.17085.src\xen-3.2.1\tools\xentrace\formats

usage

xentrace_format 

Usage examples:

cat {xentrace output file} | xentrace_format {defs-file} | more
cat {xentrace output file} | xentrace_format {defs-file} | grep -v "unknown" | more
cat {xentrace output file} | xentrace_format {defs-file} | grep -v "unknown" | more > {formatted-file}

Xentrace Recipes

Tracing until you want to stop:

xentrace -D -e all -S 256 {filename}

This command will set up a large trace buffer if it's not done already (-S 256), flush the buffer if you've done tracing before (-D), and trace all events (-e all). The tracing will continue until you kill it (ctrl-C or SIGINT). It will also exit, by default, when there's less than 50 megs left on the target filesystem.

This is useful for taking a trace of an entire run of something to see how things progress over time or to analyze an entire run.

Taking a 30-second sample:

xentrace -D -e all -S 256 -T 30 {filename}

Same basic setup as above, but will exit automatically after 30 seconds.

Useful for a shorter sample of a run. If you're going to transfer files anywhere, this might be a better idea than taking an unrestricted trace.

Taking a trace of how domains are running:

xentrace -D -e 0x21000 -S 256 {filename} -s 1000

This traces just runstate changes (-e 0x21000). Xentrace wakes up and actively check the buffer every second (-s 1000), rather than the default 100ms (Scheduling every 100ms might impact how often domain 0 is scheduled, if this is of concern, then use this flag).

This is useful to see how multiple domains interact, how much time domains spend running/blocked/waiting for the cpu, and how vcpus of a multi processor domain interact (that is, running at the same time, only one running, one running while another is blocked, and so on).

Investigating the recent past when something bad happens:

xentrace -D -e all -S 256 -M 64M {filename}

Sometimes it takes a long time for the event you are interested in to actually happen - say, a bluescreen, or some other failure. Instead of taking a several-gigabyte trace (which might impact disk throughput), you can grab just the last several megabytes of data. The -M 64M option tells xentrace to copy data from the Xen buffer into a circular buffer in dom0 process memory. This buffer dumps in to {filename} when xentrace exits:

killall -INT xentrace

Tracing to memory has a much lower impact on the system, especially disk I/O.