Android JNI调用OpenCV,长时间运行内存异常,导致闪退的log分析和解决---(ReferenceTable overflow (max=1024)造成的)

首先交代下问题背景,前些日子自己在android上搞了个入侵检测玩。就是camera当作监控设备,每隔一定时间检测是否有东西入侵,如果入侵率到一定程度就报警的东西。最近发现,每次运行超过20分钟,app直接挂掉消失。下面附上核心完整log:

01-01 21:17:42.321 I/yan     ( 2588): /storage/sdcard0/InvadeDetect/ 1111111111111

01-01 21:17:42.650 E/PowerManagerService(  501): (GYP)enter sleep check_in_PowerMonitorHandler,mScreenIsOff=true;mScreenIsSwitchToOn=false mRequestSleepCount=4 mScreenOffTime=514309

01-01 21:17:43.008 D/NvOsDebugPrintf(  163): NvCamGrinder HAL_camera_device_enable_msg_type 3

01-01 21:17:43.008 D/NvOsDebugPrintf(  163): NvCamGrinder HAL_camera_device_enable_msg_type 3

01-01 21:17:43.057 I/dalvikvm-heap( 2588): Grow heap (frag case) to 18.527MB for 1228816-byte allocation

01-01 21:17:43.057 W/dalvikvm( 2588): JNI: pin count on array 0x410f1fd8 ([I) is now 1019

01-01 21:17:43.063 W/dalvikvm( 2588): JNI: pin count on array 0x410f1fd8 ([I) is now 1019

01-01 21:17:43.066 D/dalvikvm( 2588): GC_CONCURRENT freed 5780K, 45% free 7740K/14060K, paused 2ms+2ms, total 9ms

01-01 21:17:43.324 W/dalvikvm( 2588): ReferenceTable overflow (max=1024)

01-01 21:17:43.324 W/dalvikvm( 2588): JNI pinned array reference table (0x5d4440a8) dump:

01-01 21:17:43.324 W/dalvikvm( 2588):   Last 10 entries (of 1024):

01-01 21:17:43.324 W/dalvikvm( 2588):      1023: 0x410f1f70 char[] (3 elements)

01-01 21:17:43.324 W/dalvikvm( 2588):      1022: 0x40c622e8 char[] (1 elements)

01-01 21:17:43.325 W/dalvikvm( 2588):      1021: 0x40c62268 char[] (1 elements)

01-01 21:17:43.325 W/dalvikvm( 2588):      1020: 0x40c61648 char[] (1 elements)

01-01 21:17:43.325 W/dalvikvm( 2588):      1019: 0x40e28ab8 char[] (5 elements)

01-01 21:17:43.325 W/dalvikvm( 2588):      1018: 0x410f1fd8 int[] (307200 elements)

01-01 21:17:43.325 W/dalvikvm( 2588):      1017: 0x410f1fd8 int[] (307200 elements)

01-01 21:17:43.325 W/dalvikvm( 2588):      1016: 0x410f1fd8 int[] (307200 elements)

01-01 21:17:43.325 W/dalvikvm( 2588):      1015: 0x410f1fd8 int[] (307200 elements)

01-01 21:17:43.325 W/dalvikvm( 2588):      1014: 0x410f1fd8 int[] (307200 elements)

01-01 21:17:43.325 W/dalvikvm( 2588):   Summary:

01-01 21:17:43.326 W/dalvikvm( 2588):         3 of char[] (1 elements) (3 unique instances)

01-01 21:17:43.326 W/dalvikvm( 2588):         1 of char[] (3 elements)

01-01 21:17:43.326 W/dalvikvm( 2588):         1 of char[] (5 elements)

01-01 21:17:43.326 W/dalvikvm( 2588):      1019 of int[] (307200 elements) (1 unique instances)

01-01 21:17:43.326 E/dalvikvm( 2588): Failed adding to JNI pinned array ref table (1024 entries)

01-01 21:17:43.326 I/dalvikvm( 2588): "Thread-183" prio=5 tid=14 RUNNABLE

01-01 21:17:43.326 I/dalvikvm( 2588):   | group="main" sCount=0 dsCount=0 obj=0x40f89e08 self=0x5a6ca710

01-01 21:17:43.327 I/dalvikvm( 2588):   | sysTid=3823 nice=0 sched=0/0 cgrp=apps handle=1517075840

01-01 21:17:43.327 I/dalvikvm( 2588):   | state=R schedstat=( 967539651465 45738384690 224828 ) utm=95515 stm=1238 core=2

01-01 21:17:43.327 I/dalvikvm( 2588):   at libcore.icu.NativeDecimalFormat.open(Native Method)

01-01 21:17:43.327 I/dalvikvm( 2588):   at libcore.icu.NativeDecimalFormat.<init>(NativeDecimalFormat.java:123)

01-01 21:17:43.327 I/dalvikvm( 2588):   at java.text.DecimalFormat.initNative(DecimalFormat.java:556)

01-01 21:17:43.327 I/dalvikvm( 2588):   at java.text.DecimalFormat.<init>(DecimalFormat.java:551)

01-01 21:17:43.327 I/dalvikvm( 2588):   at java.text.DecimalFormat.<init>(DecimalFormat.java:529)

01-01 21:17:43.328 I/dalvikvm( 2588):   at org.mo.invadedetect.CameraActivity.getRate(CameraActivity.java:513)

01-01 21:17:43.328 I/dalvikvm( 2588):   at org.mo.invadedetect.CameraActivity$CheckProcessThread.run(CameraActivity.java:402)

01-01 21:17:43.328 I/dalvikvm( 2588): 

01-01 21:17:43.328 E/dalvikvm( 2588): VM aborting

01-01 21:17:43.328 F/libc    ( 2588): Fatal signal 11 (SIGSEGV) at 0xdeadd00d (code=1), thread 3823 (Thread-183)

01-01 21:17:43.430 I/DEBUG   (  157): *** *** *** *** *** *** *** *** *** *** *** *** *** *** *** ***

01-01 21:17:43.430 I/DEBUG   (  157): Build fingerprint: ‘generic/pluto/pluto:4.2.2/JDQ39/eng.ztetd.20131210.002516:eng/release-keys‘

01-01 21:17:43.430 I/DEBUG   (  157): Revision: ‘0‘

01-01 21:17:43.431 I/DEBUG   (  157): pid: 2588, tid: 3823, name: Thread-183  >>> org.mo.invadedetect <<<

01-01 21:17:43.431 I/DEBUG   (  157): signal 11 (SIGSEGV), code 1 (SEGV_MAPERR), fault addr deadd00d

01-01 21:17:43.553 I/DEBUG   (  157):     r0 00000000  r1 00000000  r2 deadd00d  r3 00000000

01-01 21:17:43.553 I/DEBUG   (  157):     r4 4081cb58  r5 0000020c  r6 00000000  r7 4081cec0

01-01 21:17:43.553 I/DEBUG   (  157):     r8 5c775c54  r9 5c675e38  sl 5a6ca720  fp 5c775c6c

01-01 21:17:43.553 I/DEBUG   (  157):     ip 00004000  sp 5c775598  lr 4004f3f9  pc 407a927c  cpsr 600b0030

01-01 21:17:43.554 I/DEBUG   (  157):     d0  74726f6261204d56  d1  6a2e79746976696e

01-01 21:17:43.554 I/DEBUG   (  157):     d2  656d61432e746375  d3  697669746341616c

01-01 21:17:43.554 I/DEBUG   (  157):     d4  7fefffffffffffff  d5  7fefffffffffffff

01-01 21:17:43.554 I/DEBUG   (  157):     d6  c7efffffe0000000  d7  0000000000000000

01-01 21:17:43.555 I/DEBUG   (  157):     d8  3e6041893a83126f  d9  c0100000ffffffff

01-01 21:17:43.555 I/DEBUG   (  157):     d10 bff3441350a65936  d11 3fd34413509f79fe

01-01 21:17:43.555 I/DEBUG   (  157):     d12 3ddb7cdfd9d7bdbb  d13 0000000000000000

01-01 21:17:43.555 I/DEBUG   (  157):     d14 0000000000000000  d15 0000000000000000

01-01 21:17:43.555 I/DEBUG   (  157):     d16 0000000000000000  d17 4330000000000000

01-01 21:17:43.555 I/DEBUG   (  157):     d18 3fb0000000000000  d19 fffc0000fffc0000

01-01 21:17:43.555 I/DEBUG   (  157):     d20 0000000300000004  d21 0000000100000002

01-01 21:17:43.556 I/DEBUG   (  157):     d22 0707070703030303  d23 0000027f0000027f

01-01 21:17:43.556 I/DEBUG   (  157):     d24 fffe0000ffff0000  d25 fffc0000fffd0000

01-01 21:17:43.556 I/DEBUG   (  157):     d26 0000028000000280  d27 0000028000000280

01-01 21:17:43.556 I/DEBUG   (  157):     d28 0000000200000003  d29 0000000000000001

01-01 21:17:43.556 I/DEBUG   (  157):     d30 0000000000000000  d31 0000000000000000

01-01 21:17:43.557 I/DEBUG   (  157):     scr 60000013

01-01 21:17:43.561 I/DEBUG   (  157): 

01-01 21:17:43.561 I/DEBUG   (  157): backtrace:

01-01 21:17:43.562 I/DEBUG   (  157):     #00  pc 0004527c  /system/lib/libdvm.so (dvmAbort+75)

01-01 21:17:43.562 I/DEBUG   (  157):     #01  pc 00048499  /system/lib/libdvm.so

01-01 21:17:43.562 I/DEBUG   (  157):     #02  pc 0004a7e5  /system/lib/libdvm.so

01-01 21:17:43.562 I/DEBUG   (  157):     #03  pc 0003b87f  /system/lib/libdvm.so

01-01 21:17:43.562 I/DEBUG   (  157):     #04  pc 00016117  /system/lib/libjavacore.so

01-01 21:17:43.562 I/DEBUG   (  157):     #05  pc 00019471  /system/lib/libjavacore.so

01-01 21:17:43.563 I/DEBUG   (  157):     #06  pc 0001979b  /system/lib/libjavacore.so

01-01 21:17:43.563 I/DEBUG   (  157):     #07  pc 0001d850  /system/lib/libdvm.so (dvmPlatformInvoke+112)

01-01 21:17:43.563 I/DEBUG   (  157):     #08  pc 0004ca1d  /system/lib/libdvm.so (dvmCallJNIMethod(unsigned int const*, JValue*, Method const*, Thread*)+396)

01-01 21:17:43.563 I/DEBUG   (  157):     #09  pc 000381d5  /system/lib/libdvm.so (dvmCheckCallJNIMethod(unsigned int const*, JValue*, Method const*, Thread*)+8)

01-01 21:17:43.563 I/DEBUG   (  157):     #10  pc 00026c60  /system/lib/libdvm.so

01-01 21:17:43.564 I/DEBUG   (  157):     #11  pc 0002ab4c  /system/lib/libdvm.so (dvmInterpret(Thread*, Method const*, JValue*)+184)

01-01 21:17:43.564 I/DEBUG   (  157):     #12  pc 0005f2b1  /system/lib/libdvm.so (dvmCallMethodV(Thread*, Method const*, Object*, bool, JValue*, std::__va_list)+272)

01-01 21:17:43.564 I/DEBUG   (  157):     #13  pc 0005f2db  /system/lib/libdvm.so (dvmCallMethod(Thread*, Method const*, Object*, JValue*, ...)+20)

01-01 21:17:43.564 I/DEBUG   (  157):     #14  pc 00053e57  /system/lib/libdvm.so

01-01 21:17:43.564 I/DEBUG   (  157):     #15  pc 0000e408  /system/lib/libc.so (__thread_entry+72)

01-01 21:17:43.564 I/DEBUG   (  157):     #16  pc 0000daf4  /system/lib/libc.so (pthread_create+160)

01-01 21:17:43.565 I/DEBUG   (  157): 

01-01 21:17:43.565 I/DEBUG   (  157): stack:

01-01 21:17:43.565 I/DEBUG   (  157):          5c775558  00000001  

01-01 21:17:43.565 I/DEBUG   (  157):          5c77555c  4007a1b4  /system/lib/libc.so

01-01 21:17:43.565 I/DEBUG   (  157):          5c775560  4007a1b4  /system/lib/libc.so

01-01 21:17:43.565 I/DEBUG   (  157):          5c775564  4007a1b4  /system/lib/libc.so

01-01 21:17:43.565 I/DEBUG   (  157):          5c775568  4007a1b4  /system/lib/libc.so

01-01 21:17:43.566 I/DEBUG   (  157):          5c77556c  4004f3f9  /system/lib/libc.so (__sflush_locked+36)

01-01 21:17:43.566 I/DEBUG   (  157):          5c775570  4007a254  /system/lib/libc.so

01-01 21:17:43.566 I/DEBUG   (  157):          5c775574  4007a1b4  /system/lib/libc.so

01-01 21:17:43.567 I/DEBUG   (  157):          5c775578  00000000  

01-01 21:17:43.567 I/DEBUG   (  157):          5c77557c  400503c9  /system/lib/libc.so (_fwalk+32)

01-01 21:17:43.567 I/DEBUG   (  157):          5c775580  4081cb58  /system/lib/libdvm.so

01-01 21:17:43.567 I/DEBUG   (  157):          5c775584  0000020c  

01-01 21:17:43.567 I/DEBUG   (  157):          5c775588  00000000  

01-01 21:17:43.567 I/DEBUG   (  157):          5c77558c  4081cec0  /system/lib/libdvm.so

01-01 21:17:43.567 I/DEBUG   (  157):          5c775590  df0027ad  

01-01 21:17:43.568 I/DEBUG   (  157):          5c775594  00000000  

01-01 21:17:43.568 I/DEBUG   (  157):     #00  5c775598  00000000  

01-01 21:17:43.568 I/DEBUG   (  157):          5c77559c  6c756e28  

01-01 21:17:43.568 I/DEBUG   (  157):          5c7755a0  0000296c  

01-01 21:17:43.569 I/DEBUG   (  157):          5c7755a4  00000000  

01-01 21:17:43.569 I/DEBUG   (  157):          5c7755a8  00000000  

01-01 21:17:43.569 I/DEBUG   (  157):          5c7755ac  00000000  

01-01 21:17:43.569 I/DEBUG   (  157):          5c7755b0  00000000  

01-01 21:17:43.569 I/DEBUG   (  157):          5c7755b4  00000000  

01-01 21:17:43.570 I/DEBUG   (  157):          5c7755b8  00000000  

01-01 21:17:43.570 I/DEBUG   (  157):          5c7755bc  00000000  

01-01 21:17:43.570 I/DEBUG   (  157):          5c7755c0  00000000  

01-01 21:17:43.570 I/DEBUG   (  157):          5c7755c4  00000000  

01-01 21:17:43.570 I/DEBUG   (  157):          5c7755c8  00000000  

01-01 21:17:43.571 I/DEBUG   (  157):          5c7755cc  00000000  

01-01 21:17:43.571 I/DEBUG   (  157):          5c7755d0  00000000  

01-01 21:17:43.571 I/DEBUG   (  157):          5c7755d4  00000000  

01-01 21:17:43.571 I/DEBUG   (  157):          ........  ........

01-01 21:17:43.571 I/DEBUG   (  157):     #01  5c7757b0  40c61bc8  /dev/ashmem/dalvik-heap (deleted)

01-01 21:17:43.572 I/DEBUG   (  157):          5c7757b4  000009b9  

01-01 21:17:43.572 I/DEBUG   (  157):          5c7757b8  9b900019  

01-01 21:17:43.572 I/DEBUG   (  157):          5c7757bc  40c61ba8  /dev/ashmem/dalvik-heap (deleted)

01-01 21:17:43.572 I/DEBUG   (  157):          5c7757c0  00000000  

01-01 21:17:43.572 I/DEBUG   (  157):          5c7757c4  00000000  

01-01 21:17:43.572 I/DEBUG   (  157):          5c7757c8  9b900019  

01-01 21:17:43.573 I/DEBUG   (  157):          5c7757cc  407ae7e9  /system/lib/libdvm.so

01-01 21:17:43.573 I/DEBUG   (  157):     #02  5c7757d0  5b1ed1a8  

01-01 21:17:43.573 I/DEBUG   (  157):          5c7757d4  5a6ca710  

01-01 21:17:43.574 I/DEBUG   (  157):          5c7757d8  00000000  

01-01 21:17:43.574 I/DEBUG   (  157):          5c7757dc  00000001  

01-01 21:17:43.574 I/DEBUG   (  157):          5c7757e0  5b1ed1a8  

上面log里stack往下还有,我就不贴了。首先交代下,在这之前我并不知道问题是由ReferenceTable overflow (max=1024)造成的。拿到log后搜关键字"fatal"(除此外还可搜fault、error、fail),很幸运直接定位到了问题:VM aborting虚拟机直接挂掉了,Fatal signal 11 (SIGSEGV) at 0xdeadd00d (code=1), thread 3823 (Thread-183),第一感觉是内存是不是泄漏或溢出了。顺着这个线索往下找,看到关键字backtrace,凡是backtrace下带pc字样的地址都可以用NDK中或linux下的arm-linux-androideabi-addr2line工具将地址映射成函数名字。

01-01 21:17:43.561 I/DEBUG   (  157): backtrace:
01-01 21:17:43.562 I/DEBUG   (  157):     #00  pc 0004527c  /system/lib/libdvm.so (dvmAbort+75)
01-01 21:17:43.562 I/DEBUG   (  157):     #01  pc 00048499  /system/lib/libdvm.so
01-01 21:17:43.562 I/DEBUG   (  157):     #02  pc 0004a7e5  /system/lib/libdvm.so
01-01 21:17:43.562 I/DEBUG   (  157):     #03  pc 0003b87f  /system/lib/libdvm.so
01-01 21:17:43.562 I/DEBUG   (  157):     #04  pc 00016117  /system/lib/libjavacore.so
01-01 21:17:43.562 I/DEBUG   (  157):     #05  pc 00019471  /system/lib/libjavacore.so
01-01 21:17:43.563 I/DEBUG   (  157):     #06  pc 0001979b  /system/lib/libjavacore.so
01-01 21:17:43.563 I/DEBUG   (  157):     #07  pc 0001d850  /system/lib/libdvm.so (dvmPlatformInvoke+112)
01-01 21:17:43.563 I/DEBUG   (  157):     #08  pc 0004ca1d  /system/lib/libdvm.so (dvmCallJNIMethod(unsigned int const*, JValue*, Method const*, Thread*)+396)
01-01 21:17:43.563 I/DEBUG   (  157):     #09  pc 000381d5  /system/lib/libdvm.so (dvmCheckCallJNIMethod(unsigned int const*, JValue*, Method const*, Thread*)+8)
01-01 21:17:43.563 I/DEBUG   (  157):     #10  pc 00026c60  /system/lib/libdvm.so
01-01 21:17:43.564 I/DEBUG   (  157):     #11  pc 0002ab4c  /system/lib/libdvm.so (dvmInterpret(Thread*, Method const*, JValue*)+184)
01-01 21:17:43.564 I/DEBUG   (  157):     #12  pc 0005f2b1  /system/lib/libdvm.so (dvmCallMethodV(Thread*, Method const*, Object*, bool, JValue*, std::__va_list)+272)
01-01 21:17:43.564 I/DEBUG   (  157):     #13  pc 0005f2db  /system/lib/libdvm.so (dvmCallMethod(Thread*, Method const*, Object*, JValue*, ...)+20)
01-01 21:17:43.564 I/DEBUG   (  157):     #14  pc 00053e57  /system/lib/libdvm.so
01-01 21:17:43.564 I/DEBUG   (  157):     #15  pc 0000e408  /system/lib/libc.so (__thread_entry+72)
01-01 21:17:43.564 I/DEBUG   (  157):     #16  pc 0000daf4  /system/lib/libc.so (pthread_create+160)

backtrace下面列的从#16到#00,是一个堆栈式调用,#16在栈底所以是最先进栈,即最先调用的,然后是#15依次类推。从上面来看都是libc.so和libdvm.so出的问题,这些都是系统标准的一般不可能出问题。如果是自己生成的so的话,还真可能是自己的so造成的内存异常,稍后我会贡献一个示例,顺便介绍下addr2line的使用。

所以我怀疑找错了方向,那不是在VM挂掉之前log里就有异常了?往上看,看到Failed adding to JNI pinned array ref table (1024 entries),不能够将jni里指向的数组引用添加。再往上找看到关键的一句:ReferenceTable overflow (max=1024),经查是引用计数器溢出了,最大为1024.即java的内存管理机制是基于引用的,需要计数器来记录引用的次数。在overflow这句话得后面当引用计数达到1024时还dump出了最近的10个引用,Summary了哪些引用有多少个,可以看到有1019个对int[]数组的引用,剩下的是对char[]的引用。我恍然大悟,我在jni里不停的通过下面来接收int数组,将其转为opencv的mat矩阵:

	jint *cbuf;
	cbuf = env->GetIntArrayElements(buf, false);
	if(cbuf == NULL)
	{
		return ;
	}
	Mat mat(h, w, CV_8UC4, (unsigned char*)cbuf);
却一直没有释放。想到这,又搜了下资料,参考这里 在原有代码基础上增加释放cbuf的语句就ok了:env->ReleaseIntArrayElements(buf, cbuf, 0);

参考Android NDK之JNI陷阱 在用到NewByteArray类似方法时一定要DeleteLocalRef(),使用GetByteArrayELement时(本文即使如此)要用ReleaseByteArrayElements来进行释放。

稍后,会介绍Android和JNI层的OpenCV交互时,关于怎么传数据的两种方法,本例中使用的是传int数组的方法,如果有图片需要返回,就再返回一个jnitArray。

结语: 碰到内存泄漏或异常的问题不要怕,寻根探源只要能定位到问题便解决了一大半了。正如六祖曰烦恼即菩提,李小龙说问题即答案,当你真正明白了问题,也就找到了答案!呵呵,漫漫程序路, 何尝不是如此呢。。。

--------------------------------------------------------本文系原创,转载请注明作者:yanzi1225627



郑重声明:本站内容如果来自互联网及其他传播媒体,其版权均属原媒体及文章作者所有。转载目的在于传递更多信息及用于网络分享,并不代表本站赞同其观点和对其真实性负责,也不构成任何其他建议。