初探BTrace脚本 - 见见持续集成哪个环节比较慢
需求
这几天发现持续集成环境的执行效率比较低，所以想到用BTrace来看看是什么原因造成的，哪些环节比较慢。
持续集成环境的服务端是hudson，里面跑的主要是各个应用的单元测试，由maven管理执行。
获取资源
从BTrace官方下载它的工具包 http://kenai.com/projects/btrace/downloads/directory/releases
我这边下载的是 release-1.2 目录下的1.2版本。
简单的使用说明，可以参考用户手册：http://kenai.com/projects/btrace/pages/UserGuide
hudson中运行的是
hudson中跑的是单元测试代码内容类似如下：
package com.hugehard......test;
......
public class SomeBizServiceTest extends JTester {
......
@Test
public void testXX() {
...
}
@Test
public void testOO() {
...
}
...
}
所以我们需要监控的是单元测试类，这些类处于名称包含hugehard的包路径中。
我们希望知道testXX, testOO这样的方法的执行时间。
编写监控脚本
package hudson;
import static com.sun.btrace.BTraceUtils.print;
import static com.sun.btrace.BTraceUtils.println;
import com.sun.btrace.BTraceUtils.Time;
import com.sun.btrace.annotations.BTrace;
import com.sun.btrace.annotations.Kind;
import com.sun.btrace.annotations.Location;
import com.sun.btrace.annotations.OnMethod;
import com.sun.btrace.annotations.ProbeClassName;
import com.sun.btrace.annotations.ProbeMethodName;
import com.sun.btrace.annotations.TLS;
/**
* BtraceHudson.java
*
* @author caesar 2011-7-30 AM11:23:17
*/
@BTrace
public class BtraceHudson {
@TLS
static long starttime = 0;
@OnMethod(clazz = "/.*hugehard.*/", method = "/test.*/")
public static void startMethod(@ProbeClassName String probeClass,
@ProbeMethodName String probeMethodName) {
print("probeClass: ");
print(probeClass);
print(" ");
print("probeMethodName: ");
print(probeMethodName);
print(" start time: ");
starttime = Time.nanos();
println(starttime);
}
@OnMethod(clazz = "/.*hugehard.*/", method = "/test.*/",
location = @Location(Kind.RETURN))
public static void collectTestMethodExecutionEnd(@ProbeClassName String probeClass,
@ProbeMethodName String probeMethodName) {
print("probeClass: ");
print(probeClass);
print(" ");
print("probeMethodName: ");
print(probeMethodName);
print(" execute time: ");
long executeTime = Time.nanos() - starttime;
println(executeTime);
}
}
上面这段代码是参考博文 http://jarit.iteye.com/blog/1010908 中的内容，所以这里就不赘述它的原理了。
maven不能btrace？
我在自己的工程根目录下，执行“mvn clean test”。
通过“jps -l”拿到maven的PID。
而后通过“btrace <PID> BtraceHudson.java”，期望能够获得每个测试方法的执行时间。
但是没有获得任何的信息。
后来把标注 @OnMethod 中的clazz和method限定都放到最宽泛的程度，才发现，里面拿到的方法执行信息，根本与单元测试类毫无关联，而都是来自maven的代码类。
这时候想起来，maven在执行每个工程的单元测试的时候，它会创建独立的线程去执行它们pom.xml中定义的内容。
所以我这里拿到PID，仅仅是maven自身的线程信息，根本拿不到具体工程的线程中的方法执行信息。
javaagent模式
根目录的pom.xml中我们定义了jmockit的javaagent，用于执行test阶段的单元测试mock代码之用。配置如下：
<project>
<dependencies>
......
</dependencies>
<build>
<plugins>
<plugin>
<groupId>org.apache.maven.plugins</groupId>
<artifactId>maven-surefire-plugin</artifactId>
<version>2.4.2</version>
<configuration>
<argLine>-javaagent:"${settings.localRepository}/com/hugehard/external/test.jmockit/0.997/test.jmockit-0.997.jar"</argLine>
<junitArtifactName>com.alibaba.external:test.junit</junitArtifactName>
<testNGArtifactName>com.alibaba.external:test.testng.jdk15</testNGArtifactName>
</configuration>
<executions>
<execution>
<goals>
<goal>test</goal>
</goals>
</execution>
</executions>
</plugin>
</plugins>
</build>
</project>
这让我想起来，btrace也是有agent模式的，可以让它和应用一起启动。
这样每次maven创建新线程来执行单元测试的时候，会否也让btrace一起启动了呢？
参考官方文档，修改argLine配置如下：
<argLine>-javaagent:"${settings.localRepository}/com/hugehard/external/test.jmockit/0.997/test.jmockit-0.997.jar" -javaagent:/tmp/hudson-optimize/credit-shared-1/btrace-agent.jar=script=/tmp/hudson-optimize/BtraceHudson.class,scriptOutputFile=/tmp/hudson-optimize/btrace.${pom.artifactId}</argLine>
这里需要说明一下：
1、javaagent模式下，需要预编译btrace类
（详细请参考 http://kenai.com/projects/btrace/pages/UserGuide#precompile）
所以我们需要用如下指令先编译咱们的BtraceHudson.java
/work/ide/btrace/btrace-bin/bin/btracec -cp . BtraceHudson.java
而后会得到编译好的类 BtraceHudson.class。
2、javaagent中，请确保给出的btrace-agent.jar所在的目录中也包括了btrace-boot.jar, btrace-client.jar这两个包。
3、我们可以在scriptOutputFile中指定btrace的输出结果重定向到我们希望拿到报告的位置。
4、另外，这里使用的${pom.artifactId} 是为了每个pom.xml对应的工程在执行单元测试的时候，它们所生成的btrace报告不会互相覆盖。
接着像我们往常一样，执行“mvn clean test”指令，就能在咱们指定的目录中查看btrace报告，而后对它进行分析，找出执行效率低下的单元测试了。
== 全文完 ==