Hession反序列化導(dǎo)致CPU占用飆高

今天發(fā)布一個(gè)線上服務(wù)，暫且稱之為O，發(fā)布完后，依賴O服務(wù)的2個(gè)服務(wù)C和W大量Time報(bào)警，并且這兩個(gè)服務(wù)的CPU占用都飆到了40%左右，平時(shí)只有10%的樣子。 

這時(shí)去看O服務(wù)的監(jiān)控，Time并沒有升高，QPS反倒降了一半。同時(shí)C和W服務(wù)器日志中出現(xiàn)了大量的WARNING，信息如下：

java.lang.ClassNotFoundException: com.我是不可描述的信息.PropertyAo Dec 02, 2016 6:24:33 PM com.alibaba.com.caucho.hessian.io.SerializerFactory getDeserializerWARNING: Hessian/Burlap: 'com.我是不可描述的信息.PropertyAo' is an unknown class in WebappClassLoader  context:  delegate: false  repositories:    /WEB-INF/classes/----------> Parent Classloader: org.apache.catalina.loader.StandardClassLoader@21bf4c80123456789123456789

短時(shí)間內(nèi)找不到原因，且C服務(wù)是核心服務(wù)，找QA童鞋把O服務(wù)回滾，C和W報(bào)警恢復(fù)，CPU占用回到正常。

定位

可能見過這個(gè)WARNING的朋友已經(jīng)知道了我這次發(fā)布干了啥，其實(shí)就是在API返回的模型中增加了兩個(gè)自定義類型的屬性，如下：

private List<PropertyAo> properties1;private List<PropertyAo> properties2;1212

這兩個(gè)屬性W中會(huì)用到，之所以會(huì)有上面提到的WARNING，是由于我先發(fā)布了O服務(wù)，O服務(wù)中設(shè)置了這兩個(gè)屬性，而W服務(wù)還沒有發(fā)布，這樣Hession在反序列化的時(shí)候，檢測到了PropertyAo不存在，所以給出了WARNING。但這與CPU飆高有關(guān)系嗎？ 
與同事討論了一番，他提到了Hession反序列化時(shí)會(huì)使用到反射，他之前遇到過CPU占用飆高的情況（是由于反射代碼被大量調(diào)用），這點(diǎn)提醒了我，順著com.alibaba.com.caucho.hessian.io.SerializerFactory getDeserializer這個(gè)方法看到了這樣的實(shí)現(xiàn)：

try {    Class cl = Class.forName(type, false, _loader);    deserializer = getDeserializer(cl); } catch (Exception e) {    log.warning("Hessian/Burlap: '" + type + "' is an unknown class in " + _loader + ":\n" + e);    log.log(Level.FINER, e.toString(), e); }12345671234567

可以看到Hession是通過名字去拿到Class，這里使用了反射，當(dāng)反射失敗時(shí)就會(huì)打出上面的warning。這時(shí)聰明的你可能想到了，即使沒有失敗也是在使用反射啊，繼續(xù)向下看代碼：

if (deserializer != null) {    if (_cachedTypeDeserializerMap == null)        _cachedTypeDeserializerMap = new HashMap(8);    synchronized (_cachedTypeDeserializerMap) {        _cachedTypeDeserializerMap.put(type, deserializer);    } }1234567812345678

反射成功就會(huì)將其cache起來，也就是說，如果反射成功，只會(huì)調(diào)用一次反射，反射失敗，則每次都會(huì)執(zhí)行反射。

驗(yàn)證

先將C升級到最新api，然后發(fā)布，再發(fā)布O服務(wù)，C表現(xiàn)正常，W的CPU又開始飆高，執(zhí)行jstack看一下事故現(xiàn)場，可以看到一些線程正在執(zhí)行反射，棧信息如下：

"New I/O worker #17" daemon prio=10 tid=0x00007fb1ed33b000 nid=0x63fe runnable [0x00007fb22fcfa000]    java.lang.Thread.State: RUNNABLE         at java.lang.Class.forName0(Native Method)         at java.lang.Class.forName(Class.java:270)         at com.alibaba.com.caucho.hessian.io.SerializerFactory.getDeserializer(SerializerFactory.java:500)1234512345

解決

當(dāng)服務(wù)端模型升級時(shí)，尤其是新增自定義類型時(shí)，盡量讓所有消費(fèi)端升級，但當(dāng)消費(fèi)端過多時(shí)，這個(gè)方案成本太高，且不友好

改進(jìn)SerializerFactory，把反射失敗的情況也緩存，避免重復(fù)反射

給Dubbo提了issue，不過估計(jì)不會(huì)解決

結(jié)論

Hession默認(rèn)的反序列化實(shí)現(xiàn)滿足下面2點(diǎn)條件時(shí)，就會(huì)導(dǎo)致CPU占用飆高：

服務(wù)端新增了自定義類型

對該服務(wù)接口的調(diào)用QPS較高，我的應(yīng)用中是100+

其本質(zhì)原因還是由于反射，所以開發(fā)過程中慎用反射，反射得到的信息盡量Cache，避免頻繁反射。