2月 19 2016

hacking fastjson

使用 java agent 横向收集一些日志，在上线老应用servicemanager的时候，cpu和load飙升。

第一次尝试

先用了这个脚本跑了下获取cpu最高的几个线程对应的jstack（此脚本适用于由固定生命周期长的线程引起的cpu飙升）：

#!/bin/bash

JAVA_HOME="/opt/taobao/java"
PID=$(${JAVA_HOME}/bin/jps | grep "Bootstrap" | cut -d " " -f1)
tmp_dir="/tmp/java_${PID}"
tmp_file="java_${PID}_trace.log"
threads_file="threads_${PID}_trace.log"
stack_file="stack_${PID}_trace.log"

if [ -d "${tmp_dir}" ]; then
        rm -r ${tmp_dir}
fi

mkdir ${tmp_dir}
cd ${tmp_dir}

if [ -f "${stack_file}" ]; then
        rm ${stack_file}
fi

touch ${stack_file}

${JAVA_HOME}/bin/jstack ${PID} > ${tmp_file}

ps H -eo user,pid,ppid,tid,time,%cpu --sort=%cpu --no-headers \
        | tail -10 \
        | awk -v "pid=${PID}" '$2==pid{print $4"\t"$6}' > ${threads_file}

for index in $( seq 1 10 )
do
        line=$(cat ${threads_file} | sed -n "${index}, ${index}p")
        nid=$(echo "${line}"|awk '{printf("0x%x",$1)}')
        cpu=$(echo "${line}"|awk '{print $2}')
        awk -v "cpu=${cpu}" '/nid='"${nid}"'/,/^$/{print $0"\t"(isF+    +?"":"cpu="cpu"%");}' ${tmp_file} >> ${stack_file}
done

发现从top 10的cpu占用的栈信息上面看不出来啥。应该不满足 固定生命周期长线程 前提。

第二次尝试

用 @沉思所写的oncrash脚本收集所有的信息，脚本如下：

mkdir dumpdir
cd dumpdir
echo '
#!/bin/bash

if [ "x${JAVA_HOME}" == "x" ]
then
        JAVA_HOME="/opt/taobao/java"
fi

NOW=$(date '+%Y%m%d-%H%M%S')
PID=$(${JAVA_HOME}/bin/jps -l | grep 'org.apache.catalina.startup.Bootstrap' | cut -d " " -f1)

echo "JAVA_HOME=${JAVA_HOME}"
echo "PID=${PID}"
echo

echo "jstack"
${JAVA_HOME}/bin/jstack ${PID} > stack.${NOW}

echo "histo"
${JAVA_HOME}/bin/jmap -histo ${PID} > histo.${NOW}

echo "ps -Tel"
ps -Tel > ps.${NOW}

echo "top -c -M"
top -c -M -n3  > top.${NOW}

echo "top -H -p -c -M"
top -H -p ${PID} -c -M -n3 > top-java.${NOW}

echo "who"
w > w.${NOW}

echo "vmstat 1 10"
vmstat 1 10 > vmstat.${NOW}

echo "ps aux"
ps -aux > psaux.${NOW}

echo "free"
free -m > free.${NOW}

echo "netstat"
netstat -apn > netstat.${NOW}

echo "jstat -gcutil"
${JAVA_HOME}/bin/jstat -gcutil ${PID} > jstat-gcutil.${NOW}

echo "jstat -gc 1000 5"
${JAVA_HOME}/bin/jstat -gc ${PID} 1000 5 > jstat-gc.${NOW}

echo "lsof"
lsof -p ${PID} > lsof.${NOW}

echo "sar -n Sock"
sar -n SOCK > sarnsock.${NOW}

echo "sar -n DEV"
sar -n DEV >sarndev.${NOW}

echo "sar -b"
sar -b > sarb.${NOW}

echo "iostat 1 5"
iostat -k 1 5 > iostat.${NOW}

echo "jmapdump"
${JAVA_HOME}/bin/jmap -dump:format=b,file=jmapdump.${NOW}.bin ${PID}

' > ./call.sh
bash ./call.sh
rm ./call.sh
cd -
echo

获得栈信息如下：
fastjson

然后翻翻代码意识到了JDK6 ClassLoader里面使用了大量的synchronized。

主要性能问题来源于两个原因：

代码中没有对Class和Method做cache，多个线程同时执行load某个类的时候就会有并发问题。
json string的数据量大，所依赖的fastjson的方法 JSON.parseObject(String text, Class<?> class) 使用了asm修改了客户端自定义的pojo类，然后调用了defineClass来加载字节码，从stack中可以看到checkCerts也是有锁的。

最后cache所有使用到的Class和Method；去掉了fastjson的依赖，手动解析json；解决了问题。

磐石

工程狮

hacking fastjson

第一次尝试

第二次尝试