Xen Log 6-Xentrace

Xentrace 能够帮助你知道在Hypervisor中发生了什么,作为一个统计工具,可以记录所有的VMEnter/Exit、Schedule、Dom0ops等信息,并能够指定统计哪个cpu、记录哪些事件的信息。在进行一些验证、测试或Resource counting的时候有比较大的作用。

Debug 系列:

使用Xentrace非常简单,在安装Xen tools的时候就已经安装好了xentrace, 直接调用即可:

1
xentrace -D -e all -T 10 trace.raw

-D 删掉之前的buffer, -e 是设置trace的事件类型:

$XENDIR/xen/include/public/trace.h
1
2
3
4
5
6
7
8
9
10
11
12
13
ID                 Description

0x0001f001 TRC_LOST_RECORDS
0x0002f001 TRC_SCHED_DOM_ADD
0x0002f002 TRC_SCHED_DOM_REM
0x0002f003 TRC_SCHED_SLEEP
0x0002f004 TRC_SCHED_WAKE
0x0002f005 TRC_SCHED_YIELD
0x0002f006 TRC_SCHED_BLOCK
0x0002f007 TRC_SCHED_SHUTDOWN
0x0002f008 TRC_SCHED_CTL
0x0002f009 TRC_SCHED_ADJDOM
……

-T 是设置trace的时间

生成的内容是二进制,我们没有办法直接读取,这时就要借助xenformat: $XENDIR/tools/xentrace/xentrace_format

$XENDIR/tools/xentrace/
1
cat trace.raw | xentrace_format ~/$XENDIR/tools/xentrace/formats > trace.txt

在xentrace/formats 可以看到所有的事件类型和对应的输出格式,根据需要我们可以自行修改。

在Xen中,如果我们想要自己记录一些信息,除了在需要的地方加printk,还可以借助trace:

$XENDIR/xen/include/xen/trace.h
1
2
3
4
5
6
7
8
9
10
11
12
13
14
#define TRACE_0D(_e)                            \
do { \
trace_var(_e, 1, 0, NULL); \
} while ( 0 )

#define TRACE_1D(_e,d1) \
do { \
if ( unlikely(tb_init_done) ) \
{ \
u32 _d[1]; \
_d[0] = d1; \
__trace_var(_e, 1, sizeof(_d), _d); \
} \
} while ( 0 )

文件中的0D-5D就是记录的数据的多少,如果我们要记录3个数据,就选用3D即可。

如果想要增加自定义的事件类型,在$XENDIR/xen/include/public/trace.h中添加自己的事件类型:

$XENDIR/xen/include/public/trace.h
1
2
3
4
5
6
7
#define TRC_HVM_TRAP_DEBUG       (TRC_HVM_HANDLER + 0x24)
#define TRC_HVM_VLAPIC (TRC_HVM_HANDLER + 0x25)
/* Add customized event */
#define TRC_HVM_ALICE (TRC_HVM_HANDLER + 0x26)

/* Record our own event somewhere */
TRACE_0D(TRC_HVM_ALICE);

之后再trace.raw中就会出现我们自己定义的Trace.

Example

我们想捕捉所有关于HVM的信息:

1
2
# 0x8f000 is TRC_HVM, check in trace.h
sudo xentrace -D -e 0x8f000 -T 10 trace.raw

经过10s后:

1
cat trace.raw | xentrace_format $XENDIR/tools/xentrace/formats > trace.log

Log 中的结果如下:

1
2
3
4
5
6
7
8
CPU2  1712035142503524 (+   22501)  VMEXIT      [ exitcode = 0x00000010, rIP  = 0xffffffff8102d73f ]
CPU2 0 (+ 0) CR_READ [ CR# = 0, value = 0x000000008005003b ]
CPU2 0 (+ 0) CR_WRITE [ CR# = 0, value = 0x0000000080050033 ]
CPU2 1712035142544733 (+ 41209) vlapic_accept_pic_intr [ i8259_target = 1, accept_pic_int = 0 ]
CPU2 1712035142546137 (+ 1404) VMENTRY
CPU2 1712035142872709 (+ 326572) VMEXIT [ exitcode = 0x00000000, rIP = 0xffffffff810644f4 ]
CPU2 0 (+ 0) CR_READ [ CR# = 0, value = 0x0000000080050033 ]
CPU2 1712035142878262 (+ 5553) vlapic_accept_pic_intr [ i8259_target = 1, accept_pic_int = 0 ]

可以看到Trace记录了期间发生的所有关于HVM的相关事件,VMExit的原因等等,通过修改formats,我们可以使得输出符合我们自己的要求(比如去掉里面的+, 增加空格等)以方便后续进行处理。

Note

使用Trace的一大好处是我们可以记录一些频繁发生的事件,使用printk时会导致console有大量输出而无法响应,trace就可以很好解决我们的这一问题,同时trace可以用来统计一段时间内某个事件发生的频率等等。在debug或者测试的时候非常好用。

Change Log

  • 2017-05-11: Add Debug series