利用java-tracer来录制方法调用过程

介绍

对于程序开发一般要从两个角度去考虑，业务开发更关注功能逻辑实现，是一个业务问题；技术开发则需要关注性能稳定性，是一个纯技术问题。功能逻辑是一个大话题，涉及思维方式，业务需求，比较复杂，不太好量化，但是对于性能稳定性，却是一个技术领域的问题，对性能的追求是一个码农应有的素质。
要想对性能有所追求，就要对系统有所了解，项目开发不是一个独立的事件，大的工程往往依赖很多人很多工具的辅助才能完成。正常情况下只需要定义好接口，把功能当一个黑盒来使用就行了，但是涉及到性能，有时候，就有必要适当考虑一下“黑盒”内部实现结节了。
说了半天闲话，其实对于程序开发者尤其是java开发者，我们开发中经常用到各种成熟的框架，用起来很舒服，用得舒服的时候往往会想为啥用得这么舒服，这时候就会去看文档了，但是要想学习精髓，还是得写demo, 看源码，debug，本文即介绍一个辅助看源码和debug的工具

工具

地址

项目地址：https://github.com/fengzhongke/java-tracer
工具地址：https://github.com/fengzhongke/java-tracer/raw/master/java-tracer.jar

功能

java-tracer工具通过agent的方式，启动的时候挂载到java进程上，就可以记录某些方法运行的栈记录了，这些运行栈记录以xml的形式展现，以便收缩和展开

使用

1.写一个交互式数据库查询程序，类名com.hema.sre.pool.test.JdbcTest，当从console输入一条sql加回车之后，执行函数execSql并返回结果

//com.hema.sre.pool.test.JdbcTest
public class JdbcTest {
    public static void main(String[] args) throws Exception {
        try (Scanner scanner = new Scanner(System.in)) {
            while (scanner.hasNext()) {
                String line = scanner.nextLine();
                if (!"q".equalsIgnoreCase(line)) {
                    execSql(line);
                }
            }
        }
    }
    public static void execSql(String sql) throws SQLException{
        String url = "jdbc:mysql://127.0.0.1:3306";
        String user = "kongche";
        String password = "hanlang.hl";
        Connection conn = null;
        Statement stmt = null;
        ResultSet rs = null;
        try {
            conn = getConn(url, user, password);
            stmt = conn.createStatement();
            rs = stmt.executeQuery(sql);
            ResultSetMetaData meta = rs.getMetaData();
            int size = meta.getColumnCount();
            while (rs.next()) {
                for (int i = 1; i <= size; i++)System.out.println(meta.getColumnName(i) + ":" + rs.getString(i));
            }
        } finally {
            if (rs != null)rs.close();
            if (stmt != null)stmt.close();
            if (conn != null)conn.close();
        }
    }
    public static Connection getConn(String url, String user, String password) throws SQLException {
        return DriverManager.getConnection(url, user, password);
    }
}

2.用下载java-tracer.jar，放在本地，例如放在/tmp/java-tracer.jar
3.启动程序
如果为IDE启动，则在VM参数里面添加 -javaagent:/tmp/java-tracer.jar
如果是直接脚本启动，可以在启动参数里面添加-javaagent:/tmp/java-tracer.jar

效果

基本信息

1.查看信息
用浏览器打开：http://127.0.0.1:18902/tracer/info可以看到

<handlers cnt="6">
	<handler path="/tracer/class" params="" desc="get class loaders and its classes"/>
	<handler path="/tracer/trace/del" params="" desc="delete the intercepter"/>
	<handler path="/tracer/info" params="" desc="get all handlers"/>
	<handler path="/tracer/trace/get" params="" desc="get xml trade of the method"/>
	<handler path="/tracer/thread" params="" desc="get system threads"/>
	<handler path="/tracer/trace/set" params="type(can be compressThread),class,method" desc="set intercepter "/>
</handlers>

说明有6个功能页面/tracer/info即为信息查询页面，接下来可以看其它5个页面了
2.查看类信息
用浏览器打开：http://127.0.0.1:18902/tracer/class 可以看到

<loaders cnt="3">
	<loader name="" cnt="469">...</loader>
	<loader name="sun.misc.Launcher_AppClassLoader@14dad5dc" cnt="109">...</loader>
	<loader name="com.ali.trace.agent.loader.SpyClassLoader@4e25154f" cnt="74">...</loader>
</loaders>

说明有3个classLoader, 每个classLoader分别加载了哪些类都可以展开看到
3.查看实时线程信息
用浏览器打开：http://127.0.0.1:18902/tracer/thread 可以看到

<threads cnt="13">
	<run class="java.lang.Thread" line="745" cnt="8">
		<run class="org.eclipse.jetty.util.thread.QueuedThreadPool_3" line="563" cnt="5">...</run>
		<run class="org.eclipse.jetty.util.thread.QueuedThreadPool_3" line="534" cnt="3">...</run>
	</run>
	<run class="java.lang.ref.Reference_ReferenceHandler" line="157" cnt="1">
		<wait class="java.lang.Object" line="502" cnt="1">
			<wait class="java.lang.Object" line="-2" cnt="1">
				<thread name="Reference Handler" tid="2"/>
			</wait>
		</wait>
	</run>
	<run class="com.mysql.jdbc.AbandonedConnectionCleanupThread" line="41" cnt="1">
		<remove class="java.lang.ref.ReferenceQueue" line="143" cnt="1">
			<wait class="java.lang.Object" line="-2" cnt="1">
				<thread name="Abandoned connection cleanup thread" tid="18"/>
			</wait>
		</remove>
	</run>
	<run class="java.lang.ref.Finalizer_FinalizerThread" line="209" cnt="1">
		<remove class="java.lang.ref.ReferenceQueue" line="164" cnt="1">
			<remove class="java.lang.ref.ReferenceQueue" line="143" cnt="1">
			<wait class="java.lang.Object" line="-2" cnt="1">
				<thread name="Finalizer" tid="3"/>
			</wait>
			</remove>
		</remove>
	</run>
	<thread name="DestroyJavaVM" tid="19"/>
	<thread name="Signal Dispatcher" tid="4"/>
</threads>

线程从最外层到里层，最内一层为线程名，由xml可知
1.系统总共有线程13个
2.第1个子xml说明线程java.lang.Thread.run启动的线程总共有8个
3.这8个线程，在其第2层处于org.eclipse.jetty.util.thread.QueuedThreadPool_3的run方法第563行的线程有5个，run方法第534行的有3个
依此类推

方法跟踪信息

1.设置需要跟踪记录的方法
浏览器请求：http://127.0.0.1:18902/tracer/trace/set?type=compressThread&class=com.hema.sre.pool.test.JdbcTest&method=execSql
其中参数class为类的全路径名，method为方法名
请求返回

set class:[com.hema.sre.pool.test.JdbcTest]method:[execSql]status:[true]

status true说明设置成功，可以在java进程的console下面输入sql，例如输入 show databases并回车，可以看到数据库执行结果
2.保证有一次com.hema.sre.pool.test.JdbcTest.execSql的执行之后，就可查看调用栈了
浏览器打开：http://127.0.0.1:18902/tracer/trace/get 可以看到

<execSql cnt="0" rt="42" c="com.hema.sre.pool.test.JdbcTest">
	<getConn cnt="1" rt="40" c="com.hema.sre.pool.test.JdbcTest">
		<connect cnt="1" rt="0" c="com.alibaba.druid.proxy.DruidDriver">...</connect>
		<connect cnt="1" rt="0" c="com.alibaba.druid.mock.MockDriver">...</connect>
		<connect cnt="1" rt="40" c="com.mysql.jdbc.NonRegisteringDriver">...</connect>
	</getConn>
	<getPedantic cnt="1" rt="0" c="com.mysql.jdbc.ConnectionPropertiesImpl">...</getPedantic>
	<getContinueBatchOnError cnt="1" rt="0" c="com.mysql.jdbc.ConnectionPropertiesImpl">...</getContinueBatchOnError>
	<getUseLegacyDatetimeCode cnt="1" rt="0" c="com.mysql.jdbc.ConnectionPropertiesImpl">...</getUseLegacyDatetimeCode>
	<getDontTrackOpenResources cnt="4" rt="0" c="com.mysql.jdbc.ConnectionPropertiesImpl">...</getDontTrackOpenResources>
	<getMaxAllowedPacket cnt="1" rt="0" c="com.mysql.jdbc.ConnectionPropertiesImpl">...</getMaxAllowedPacket>
	<getDefaultFetchSize cnt="1" rt="0" c="com.mysql.jdbc.ConnectionPropertiesImpl">...</getDefaultFetchSize>
	<getUseUnicode cnt="2" rt="0" c="com.mysql.jdbc.ConnectionPropertiesImpl"> </getUseUnicode>
	<getEncoding cnt="2" rt="0" c="com.mysql.jdbc.ConnectionPropertiesImpl"> </getEncoding>
	<getProfileSql cnt="1" rt="0" c="com.mysql.jdbc.ConnectionPropertiesImpl"> </getProfileSql>
	<getUseUsageAdvisor cnt="2" rt="0" c="com.mysql.jdbc.ConnectionPropertiesImpl"> </getUseUsageAdvisor>
	<getLogSlowQueries cnt="1" rt="0" c="com.mysql.jdbc.ConnectionPropertiesImpl">...</getLogSlowQueries>
	<getAutoGenerateTestcaseScript cnt="1" rt="0" c="com.mysql.jdbc.ConnectionPropertiesImpl"> </getAutoGenerateTestcaseScript>
	<getMaxRows cnt="1" rt="0" c="com.mysql.jdbc.ConnectionPropertiesImpl"> </getMaxRows>
	<getHoldResultsOpenOverStatementClose cnt="2" rt="0" c="com.mysql.jdbc.ConnectionPropertiesImpl">...</getHoldResultsOpenOverStatementClose>
	<escapeSQL cnt="1" rt="0" c="com.mysql.jdbc.EscapeProcessor"> </escapeSQL>
	<startsWithIgnoreCaseAndWs cnt="3" rt="0" c="com.mysql.jdbc.StringUtils">...</startsWithIgnoreCaseAndWs>
	<firstNonWsCharUc cnt="1" rt="0" c="com.mysql.jdbc.StringUtils"> </firstNonWsCharUc>
	<getUseCursorFetch cnt="2" rt="0" c="com.mysql.jdbc.ConnectionPropertiesImpl">...</getUseCursorFetch>
	<getEnableQueryTimeouts cnt="1" rt="0" c="com.mysql.jdbc.ConnectionPropertiesImpl">...</getEnableQueryTimeouts>
	<getCacheResultSetMetadata cnt="2" rt="0" c="com.mysql.jdbc.ConnectionPropertiesImpl"> </getCacheResultSetMetadata>
	<getGatherPerformanceMetrics cnt="3" rt="0" c="com.mysql.jdbc.ConnectionPropertiesImpl">...</getGatherPerformanceMetrics>
	<getHighAvailability cnt="1" rt="0" c="com.mysql.jdbc.ConnectionPropertiesImpl"> </getHighAvailability>
	<getIncludeThreadNamesAsStatementComment cnt="1" rt="0" c="com.mysql.jdbc.ConnectionPropertiesImpl">...</getIncludeThreadNamesAsStatementComment>
	<getBytes cnt="1" rt="0" c="com.mysql.jdbc.StringUtils">...</getBytes>
	<getEnablePacketDebug cnt="1" rt="0" c="com.mysql.jdbc.ConnectionPropertiesImpl">...</getEnablePacketDebug>
	<getMaintainTimeStats cnt="6" rt="0" c="com.mysql.jdbc.ConnectionPropertiesImpl"> </getMaintainTimeStats>
	<mysqlToJavaType cnt="1" rt="0" c="com.mysql.jdbc.MysqlDefs"> </mysqlToJavaType>
	<getUseOldUTF8Behavior cnt="1" rt="0" c="com.mysql.jdbc.ConnectionPropertiesImpl"> </getUseOldUTF8Behavior>
	<init cnt="5" rt="0" c="com.mysql.jdbc.ResultSetRow"> </init>
	<init cnt="5" rt="0" c="com.mysql.jdbc.ByteArrayRow"> </init>
	<init cnt="1" rt="0" c="com.mysql.jdbc.RowDataStatic"> </init>
	<isJdbc4 cnt="1" rt="0" c="com.mysql.jdbc.Util"> </isJdbc4>
	<handleNewInstance cnt="1" rt="0" c="com.mysql.jdbc.Util">...</handleNewInstance>
	<getUseOldAliasMetadataBehavior cnt="1" rt="0" c="com.mysql.jdbc.ConnectionPropertiesImpl">...</getUseOldAliasMetadataBehavior>
	<getYearIsDateType cnt="1" rt="0" c="com.mysql.jdbc.ConnectionPropertiesImpl">...</getYearIsDateType>
	<init cnt="1" rt="0" c="com.mysql.jdbc.ResultSetMetaData"> </init>
	<getColumnCount cnt="1" rt="0" c="com.mysql.jdbc.ResultSetMetaData"> </getColumnCount>
	<size cnt="12" rt="0" c="com.mysql.jdbc.RowDataStatic"> </size>
	<next cnt="6" rt="0" c="com.mysql.jdbc.RowDataStatic">...</next>
	<isDynamic cnt="6" rt="0" c="com.mysql.jdbc.RowDataStatic"> </isDynamic>
	<isBeforeFirst cnt="6" rt="0" c="com.mysql.jdbc.RowDataStatic"> </isBeforeFirst>
	<isAfterLast cnt="6" rt="0" c="com.mysql.jdbc.RowDataStatic"> </isAfterLast>
	<getColumnName cnt="5" rt="0" c="com.mysql.jdbc.ResultSetMetaData">...</getColumnName>
	<isNull cnt="5" rt="0" c="com.mysql.jdbc.ByteArrayRow"> </isNull>
	<getString cnt="5" rt="0" c="com.mysql.jdbc.ByteArrayRow">...</getString>
	<getNoDatetimeStringSync cnt="5" rt="0" c="com.mysql.jdbc.ConnectionPropertiesImpl">...</getNoDatetimeStringSync>
	<closeOpenStreams cnt="5" rt="0" c="com.mysql.jdbc.ByteArrayRow"> </closeOpenStreams>
	<close cnt="1" rt="0" c="com.mysql.jdbc.RowDataStatic"> </close>
	<removeInstance cnt="1" rt="0" c="com.mysql.jdbc.ProfilerEventHandlerFactory"> </removeInstance>
</execSql>

其中包括了数据库连接的过程，请求发送过程，以及每一步调用耗时情况，如果要关注某一步执行的内部调用细节，可以展开xml一层层查看
（xml是方法调用一次生成一个xml，http请求一次获取一个xml）
3.看完之后，也可以不再关注方法的调用，则调用http://127.0.0.1:18902/tracer/trace/del 可解除对方法的跟踪

结束

有了这工具是不是就可以轻松了解到spring, mybatis等的细节原理了呢？
欢迎大家给java-tracer贡献建议和意见，并一起深度开发这个工具
地址：https://github.com/fengzhongke/java-tracer