Android程序崩溃调试案例：Reference table overflow

问题描述：
起初发现一段程序在运行一段时间后发生崩溃。经过多次测试，发现程序规律性地每持续运行30分钟必发生崩溃问题。崩溃时log记录到如下内容：

ReferenceTable overflow (max=1024)
JNI pinned array reference table (0x6080b458) dump:
  Last 10 entries (of 1024):
     1023: 0x423b76d0 int[] (1 elements)
     1022: 0x4209cea0 int[] (1 elements)
     1021: 0x4209c890 int[] (1 elements)
     1020: 0x42242198 int[] (1 elements)
     1019: 0x421b7b60 int[] (1 elements)
     1018: 0x420c0e08 int[] (1 elements)
     1017: 0x42107c18 int[] (1 elements)
     1016: 0x421078e8 byte[] (1 elements)
     1015: 0x42116a18 int[] (1 elements)
     1014: 0x42116408 int[] (1 elements)
  Summary:
        1 of byte[] (1 elements)
     1023 of int[] (1 elements) (1023 unique instances)
Failed adding to JNI pinned array ref table (1024 entries)
"main" prio=5 tid=1 RUNNABLE
  | group="main" sCount=0 dsCount=0 obj=0x417f5de0 self=0x417e44a8
  | sysTid=7820 nice=0 sched=0/0 cgrp=apps handle=1074331988
  | state=R schedstat=( 0 0 0 ) utm=972 stm=228 core=0
  at libcore.icu.NativeDecimalFormat.formatLong(Native Method)
  at libcore.icu.NativeDecimalFormat.formatLong(NativeDecimalFormat.java:253)
  at java.text.DecimalFormat.format(DecimalFormat.java:684)
  at java.text.NumberFormat.format(NumberFormat.java:299)
  at java.text.DecimalFormat.format(DecimalFormat.java:702)
  at java.text.SimpleDateFormat.appendNumber(SimpleDateFormat.java:785)
  at java.text.SimpleDateFormat.append(SimpleDateFormat.java:676)
  at java.text.SimpleDateFormat.formatImpl(SimpleDateFormat.java:553)
  at java.text.SimpleDateFormat.format(SimpleDateFormat.java:818)
  at java.text.DateFormat.format(DateFormat.java:307)
  at com.tuyou.tsd.launcher.SleepingActivity.updateTime(SleepingActivity.java:206)
  at com.tuyou.tsd.launcher.SleepingActivity.access$1(SleepingActivity.java:204)
  at com.tuyou.tsd.launcher.SleepingActivity$2.handleMessage(SleepingActivity.java:66)
  at android.os.Handler.dispatchMessage(Handler.java:102)
  at android.os.Looper.loop(Looper.java:136)
  at android.app.ActivityThread.main(ActivityThread.java:5146)
  at java.lang.reflect.Method.invokeNative(Native Method)
  at java.lang.reflect.Method.invoke(Method.java:515)
  at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:732)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:566)
  at dalvik.system.NativeStart.main(Native Method)
VM aborting
Fatal signal 6 (SIGABRT) at 0x00001e8c (code=-6), thread 7820 (com.tuyou.tsd)

从打印的堆栈进行分析，一开始认为是updateTime()中调用的DateFormat.format()导致的问题，因为updateTime()方法在一个定时器线程中，每隔一秒钟触发执行一次。查看format()方法发现该方法的实现如下：

return format(date, new StringBuffer(), new FieldPosition(0)).toString();

所以一开始怀疑是频繁的创建StringBuffer和FieldPosition对象有可能导致JVM来不及进行垃圾回收最终导致了引用表溢出的错误。再之后尝试着复用StringBuffer和FieldPosition对象实例，以及将部分代码注释掉，但问题仍然存在（运行30分钟后报出引用表溢出错误，但打印出的堆栈内容不同）。这时开始怀疑问题可能另有原因。

于是首先单独写了一个定时器更新时间的小程序进行测试，连续运行一个小时没有出现问题，由此可以判断定时器并非是导致引用表错误的根源。这时再仔细看log的这几句：

ReferenceTable overflow (max=1024)
...
  Summary:
        1 of byte[] (1 elements)
     1023 of int[] (1 elements) (1023 unique instances)
Failed adding to JNI pinned array ref table (1024 entries)

仔细想想出现的问题是引用表的内容超出了1024个的限制，内容是1个byte[]和1023个int[]。并且最后一句显示向JNI指向的数组引用表添加失败。由此分析问题应该出在JNI调用上。于是查找程序中的JNI部分，发现了如下两个函数：

JNIEXPORT jint
Java_com_tuyou_tsd_common_util_TsdHelper_readport(JNIEnv* env, jobject thiz,int fd,jbyteArray buf,jint size)
{
    unsigned char *buf_char = (char*)((*env)->GetByteArrayElements(env,buf, NULL));
    return read(fd, buf_char,  size);
}

JNIEXPORT jint
Java_com_tuyou_tsd_common_util_TsdHelper_writeport(JNIEnv* env, jobject thiz,int fd,jbyteArray buf,jint size)
{
    unsigned char *buf_char = (char*)((*env)->GetByteArrayElements(env,buf, NULL));
    return write(fd, buf_char,  size);
}

正是这两个函数中引用了GetByteArrayElements但是之后没有将该对象释放，而readport这个函数在程序运行时在另外一个定时器线程中每2秒被调用一次，所以真正导致出错的地方在这里。

找到根源后解决方法就简单了，只需将上面两段函数改写，在返回前将引用的buffer对象释放即可。修改后如下：

JNIEXPORT jint
Java_com_tuyou_tsd_common_util_TsdHelper_readport(JNIEnv* env, jobject thiz,int fd,jbyteArray buf,jint size)
{
    unsigned char *buf_char = (char*)((*env)->GetByteArrayElements(env,buf, NULL));
    read(fd, buf_char,  size);

    int result = buf_char != NULL ? buf_char[0] : -1;

    (*env)->ReleaseByteArrayElements(env, buf, buf_char, JNI_ABORT);

    LOGD("read from port result: %d", result);
    return result;
}

JNIEXPORT jint
Java_com_tuyou_tsd_common_util_TsdHelper_writeport(JNIEnv* env, jobject thiz,int fd,jbyteArray buf,jint size)
{
    unsigned char *buf_char = (char*)((*env)->GetByteArrayElements(env,buf, NULL));
    int result = write(fd, buf_char,  size);

    (*env)->ReleaseByteArrayElements(env, buf, buf_char, JNI_ABORT);

    LOGD("write to port result: %d", result);
    return result;
}

最后再次测试，程序运行后再未发生崩溃问题。