使用TProfiler分析並調優項目中的Fastjson序列化代碼

新項目年後就上線了，如今業務上沒什麼問題，就用TProfiler作了下性能分析，果真有坑。

##1、TProfiler入門 高手請自覺略過本節。

###1.簡介

TProfiler是阿里巴巴開源的一款性能分析工具。號稱能夠用於生產環境進行長期的性能分析。測試程序部署後，在低峯期對響應時間影響20%，在高峯期對QPS影響30%。詳細介紹請見官方WIKI。

###2.簡要的實現原理

TProfiler的實現基於JAVA的Instrumentation 和ASM。Instrumentation能夠理解爲一種虛擬機級別的AOP實現，無需對項目代碼和JDK有任何改動就能夠實現AOP功能。TProfiler利用Instrumentation提供的入口，調用ASM將待分析的類的字節碼進行修改，加入分析記錄方法。在Profiler運行時便可抽樣收集到相關類方法的調用信息。使用Instrumentation時也能夠經過JVMTI提供的接口實現對類的徹底控制。至於爲何TProfiler會選擇ASM，我想可能有兩方面的考慮：

1）性能上更高效。使用JVMTI在每一個類裝入時都要執行hook程序，而ASM沒有明顯的性能代價。

2）使用JVMTI對編程難度要求較高，要求對class文件結構和java字節碼有深入瞭解，而ASM雖然也有一些難度，可是相對來講仍是小一些。

###3.配置

TProfiler在使用上比較簡單，在待分析的程序啓動腳本中加入JVM參數

javaagent:/path/to/tprofiler.jar -Dprofile.properties=/path/to/profile.properties

並將jar包和profile.properties配置文件放置到前面指定位置就能夠了。

profile.properties能夠根據須要進行配置：

startProfTime = 9:00:00 開始profile的時間點
endProfTime = 11:00:00 結束profile的時間點
eachProfUseTime = 5 profile時間長度(單位秒)
eachProfIntervalTime = 50 兩次profile的時間間隔(單位秒)
samplerIntervalTime = 20 兩次採樣的時間間隔(單位秒)
debugMode = false 是否進入調試模式
needNanoTime = false 是否須要用納秒記錄時間
ignoreGetSetMethod = true 是否忽略採集get/set方法
logFilePath = /home/admin/logs/tprofiler.log profile log的存放位置
methodFilePath = /home/admin/logs/tmethod.log method log的存放位置
samplerFilePath = /home/admin/logs/tsampler.log sampler log的存放位置
excludeClassLoader = org.eclipse.osgi.internal.baseadaptor.DefaultClassLoader 不注入的類加載器(分號分割)
includePackageStartsWith = com.taobao 進行profile的類包名(分號分割)
excludePackageStartsWith = com.alibaba;com.taobao.forest.domain.dataobject 不進行profile的類包名(分號分割)

###4.遠程操做

TProfiler支持遠程操做：

遠程查看狀態操做:

java -cp tprofiler.jar com.taobao.profile.client.TProfilerClient 10.232.. 端口號 status

遠程開始操做:

java -cp tprofiler.jar com.taobao.profile.client.TProfilerClient 10.232.. 端口號 start

遠程中止操做:

java -cp tprofiler.jar com.taobao.profile.client.TProfilerClient 10.232.. 端口號 stop

遠程刷出方法數據:

java -cp tprofiler.jar com.taobao.profile.client.TProfilerClient 10.232.. 端口號 flushmethod

###5.日誌分析

運行採樣後會生成三個文件：tsampler.log、tprofiler.log、tmethod.log。endProfTime時間到了後纔會輸出tmethod.log。

獲得以上三個日誌文件後就能夠進行分析了。

分析sampler log命令: java -cp tprofiler.jar com.taobao.profile.analysis.SamplerLogAnalysis d:/tsampler.log d:/method.log d:/thread.log,會生成method.log和thread.log

分析profiler log命令: java -cp tprofiler.jar com.taobao.profile.analysis.ProfilerLogAnalysis d:/tprofiler.log d:/tmethod.log d:/topmethod.log d:/topobject.log,會生成topmethod.log和topobject.log

仍是那句話，詳細介紹請見官方WIKI，:P。

##2、開始性能測試 參照第一節配置好個人jetty啓動腳本jetty.sh後，使用ab進行壓測

ab -n 100000 -c 500 -p post-file http://urlpath    (post-file是post發送內容)

獲得日誌後分析耗時最長的方法：

java -cp tprofiler.jar com.taobao.profile.analysis.ProfilerLogAnalysis /var/tprofiler/logs/tprofiler.log /var/tprofiler/logs/tmethod.log /var/tprofiler/logs/topmethod.log /var/tprofiler/logs/topobject.log

能夠發現耗時最多的居然是json序列化，抽樣分析時共調用52412次，平均每次耗時809毫秒。對於這個結果比較詫異，和TProfiler系出同門的Fastjson的性能一直不錯，之前開始用以前也作了很多序列化和反序列化的測試，怎麼忽然就這麼耗時了呢。轉念一想，此次的web項目裏因爲須要支持客戶端自定義屬性獲取和日期格式化，因此須要Fastjson同時進行屬性的過濾（經過SerializeFilter）以及日期的自定義格式化（經過SerializeConfig自定義一個把Integer秒轉換成指定格式日期的IntegerCodec）。JSON類裏沒有原生的同時支持這兩種操做的方法，因此就在原生的JSON#toJSONString(Object object, SerializeFilter filter, SerializerFeature... features)方法的基礎上加了一個參數獲得了JSONUtil#toJSONString(Object object, SerializeConfig config, SerializeFilter filter ,SerializerFeature... features)。難道是這個緣由？話很少說，繼續測試。

##3、Fastjson併發測試 因爲懷疑新加的方法在併發下可能致使性能問題，因而比較了幾種對Fastjson不一樣方法的併發調用時間，怎麼簡單怎麼來，就不用什麼高大上的報表了，各位看官見笑了哈

第一列是普通的，第二列是帶屬性過濾的，第三列是自定義的同時支持屬性過濾和日期格式化的toJSONString。其中COUNT是每一個線程執行序列化的次數。這個併發的對比測試反應的問題有兩點：1）併發狀況下，性能確實變差；2）一樣參數對比下來耗時相差兩個數量級，我修改的方法確實有問題。

##4、問題代碼的review和問題解決

因而帶着這兩個問題，開始扒拉代碼：

<!-- lang: java -->
public static String toStringWithFieldFilterAndDateFormat(Object object ,final String[] fields,SerializerFeature... features ){
	SerializeFilter filter = null;
	// 只過濾第一層屬性
	if(fields != null ){
		// 得到須要過濾掉的字段
		final Set<String> tobeRemoved = getTobeRemovedFields(object,fields);
		if(toRemove != null && toRemove.size() > 0){
			// 須要過濾字段
			filter = new PropertyFilter() {
				@Override
				public boolean apply(Object object, String name, Object value) {
					// 轉換日期格式
					if(toRemove.contains(name)){
						return false ;
					}
					return true;
				}
			};
		}
	}
	SerializeConfig config = new SerializeConfig();
	if(NEED_FORMAT_DATE){
		config.put(Integer.class, CustomIntegerCodec.instance);
	}
	return toJSONString(object, config, filter,features);
}

這裏CustomIntegerCodec是基於IntegerCodec的Integer類序列化和反序列化器。而toJSONString(Object object, SerializeConfig config, SerializeFilter filter ,SerializerFeature... features)只是在new JSONSerializer(out)時使用了另外一個構造器new JSONSerializer(out,config)。

又看了一下Fastjson的源碼，發如今SerializeConfig中對ObjectSerializer作了緩存，若是每次都傳入一個新的SerializeConfig，必然每次都會進行沒必要要的解析和初始化操做，佔用大量的時間。問題找出來了，解決方法也很簡單，只要使用一個單例或靜態變量便可 private static final SerializeConfig customGlobalConfig = new SerializeConfig(); static { if(NEED_FORMAT_DATE){ customGlobalConfig .put(Integer.class, CustomIntegerCodec.instance); } } Fastjson默認的序列化方法其實也是使用的默認的靜態全局實例SerializeConfig

private final static SerializeConfig globalInstance = new SerializeConfig();

修改以後進行測試

O(∩_∩)O ##5、總結 本文介紹了TProfiler性能分析方面的實際應用，能夠看到經過TProfiler的分析結果，很是容易定位一些性能問題。而這些問題每每較爲隱蔽，你最熟悉的地方頗有可能早就被你挖了坑。 TProfiler自己也短小精煉，若是對Instrument、ASM感興趣、性能分析感興趣，推薦讀一讀。

再給幾個相關的資料，沒事翻翻

深刻 Java 調試體系: 第 1 部分，JPDA 體系概覽

深刻 Java 調試體系，第 2 部分: JVMTI 和 Agent 實現

Java SE 6 新特性: Instrumentation 新功能

AOP 的利器：ASM 3.0 介紹

新年快樂，羊年吉祥~咩咩