search

Tencent / MMKV

An efficient, small mobile key-value storage framework developed by WeChat. Works on Android, iOS, macOS, Windows, and POSIX.
Other
17.35k stars 1.9k forks source link

mmkv encodeBytes 崩溃 #459

Closed free46000 closed 4 years ago

free46000 commented 4 years ago

The language of MMKV

Java

The version of MMKV

v1.1.1 （com.tencent:mmkv-static:1.1.1）

The platform of MMKV

Android

The installation of MMKV

Maven

What's the issue?

native crash stacktrace：

0 | libc.so NativeException: Operating system: Android
1 | 0.0.0 Linux 4.9.148 #1 SMP PREEMPT Thu Apr 9 10:34:42 CST 2020 armv8l
2 | CPU: arm
3 | ARMv1 ARM part(0x4100d030) features: half,thumb,fastmult,vfpv2,edsp,neon,vfpv3,tls,vfpv4,idiva,idivt
4 | 8 CPUs
5 | GPU: UNKNOWN
6 | Crash reason: SIGABRT
7 | Crash address: 0x7212
8 | Process uptime: not available
9 | Thread 23 (crashed)
10 | 0 libc.so + 0x1d796
11 | r0 = 0x00000000 r1 = 0x00007254 r2 = 0x00000006 r3 = 0x00000008
12 | r4 = 0x00007212 r5 = 0x00007254 r6 = 0xc6f7edcc r7 = 0x0000010c
13 | r8 = 0x00000001 r9 = 0xe221be00 r10 = 0x14a403e8 r12 = 0x00000041
14 | fp = 0x13e8bec8 sp = 0xc6f7edb8 lr = 0xeb4a8a6d pc = 0xeb4a0796
15 | Found by: given as instruction pointer in context
16 | 1 dalvik-main space (region space) (deleted) + 0x1e403e6
17 | sp = 0xc6f7edc4 pc = 0x14a403e8
18 | Found by: stack scanning
19 | 2 libc.so + 0x5d7a7
20 | sp = 0xc6f7edc8 pc = 0xeb4e07a9
21 | Found by: stack scanning
22 | 3 libmmkv.so + 0x22b56
23 | sp = 0xc6f7edd8 pc = 0xc89a4b58
24 | Found by: stack scanning
25 | 4 libc.so + 0x1da01
26 | sp = 0xc6f7ede8 pc = 0xeb4a0a03
27 | Found by: stack scanning
28 | 5 libmmkv.so + 0x229ad
29 | sp = 0xc6f7edf8 pc = 0xc89a49af
30 | Found by: stack scanning
31 | 6 libmmkv.so + 0x44b99
32 | sp = 0xc6f7ee10 pc = 0xc89c6b9b
33 | Found by: stack scanning
34 | 7 libmmkv.so + 0x22ac7
35 | sp = 0xc6f7ee1c pc = 0xc89a4ac9
36 | Found by: stack scanning
37 | 8 libmmkv.so + 0x44b99
38 | sp = 0xc6f7ee20 pc = 0xc89c6b9b
39 | Found by: stack scanning
40 | 9 dalvik-main space (region space) (deleted) + 0x27a47471
41 | sp = 0xc6f7ee38 pc = 0x3a647473
42 | Found by: stack scanning
43 | 10 boot-framework.vdex + 0xe3af38
44 | sp = 0xc6f7ee3c pc = 0x74756f3a
45 | Found by: stack scanning

java stacktrace

0 | com.tencent.mmkv.MMKV.encodeBytes(Native Method)
1 | com.tencent.mmkv.MMKV.encode(SourceFile:399)
2 | com.tencent.mmkv.MMKV.putBytes(SourceFile:599)
...

mmkv已经集成上线一个版本正常，这次发版突然出现上述问题，这次针对mmkv的改动主要有两点一个是设置了日志级别： MMKV.setLogLevel(MMKVLogLevel.LevelWarning) 另外就是有处调用改为了MULTI_PROCESS_MODE：MMKV.mmkvWithID("name", MMKV.MULTI_PROCESS_MODE)

麻烦咨询下这可能是什么原因导致的呢?

lingol commented 4 years ago

It's quite possible that you access the same MMKV ID in multi-process, while setting either one of them SINGLE_PROCESS_MODE.

free46000 commented 4 years ago

你的意思是让我把MMKV.mmkvWithID("name", MMKV.MULTI_PROCESS_MODE)这处改动还原是吧？

free46000 commented 4 years ago

那我有个疑问是，既然多进程下同时访问了相同的mmkv id，不应该加上 MMKV.MULTI_PROCESS_MODE 模式吗？因为我调整这个多进程模式的原因也是因为线上偶现一些mmkv的问题，看历史issue很像是因为没有设置多进程模式导致的

lingol commented 4 years ago

你的意思是让我把MMKV.mmkvWithID("name", MMKV.MULTI_PROCESS_MODE)这处改动还原是吧？

NO, quite the opposite. I think there's someone accessing an MMKV from multi-process while not setting MULTI_PROCESS_MODE. Including the default MMKV instance.

free46000 commented 4 years ago

好的，那我在排查一遍代码，多谢

free46000 commented 4 years ago

刚才排查了一遍，所有调用MMKV.mmkvWithID已经都设置了 MULTI_PROCESS_MODE,并且我们也没有调用 MMKV.defaultMMKV 方法 @lingol

lingol commented 4 years ago

Well, you can provide logs of MMKV when this crash happended. And we can check on that.

lingol commented 4 years ago

By the way, the native crash stack you provided can be symbolized by me, maybe you should symbolize them on your crash report system.

free46000 commented 4 years ago

logcat 日志

84 |  beginning of crash
85 | 05-26 15:31:32.819 F/libc (27125): /Volumes/Android/buildbot/src/android/ndk-release-r16/external/libcxx/../../external/libcxxabi/src/abort_message.cpp:73: abort_message: assertion "terminating with uncaught exception of type std::out_of_range: OutOfSpace" failed
86 | 05-26 15:31:32.892 E/Zygote (27317): register_com_android_internal_os_Zygote num = 0
87 | 05-26 15:31:32.979 D/AndroidRuntime(27317): Calling main entry com.android.commands.pm.Pm
88 | 05-26 15:31:33.009 W/MessageQueue(27317): Handler (android.os.Handler) {c9592a2} sending message to a Handler on a dead thread
89 | 05-26 15:31:33.009 W/MessageQueue(27317): java.lang.IllegalStateException: Handler (android.os.Handler) {c9592a2} sending message to a Handler on a dead thread
90 | 05-26 15:31:33.009 W/MessageQueue(27317): at android.os.MessageQueue.enqueueMessage(MessageQueue.java:639)
91 | 05-26 15:31:33.009 W/MessageQueue(27317): at android.os.Handler.enqueueMessage(Handler.java:681)
92 | 05-26 15:31:33.009 W/MessageQueue(27317): at android.os.Handler.sendMessageAtTime(Handler.java:650)
93 | 05-26 15:31:33.009 W/MessageQueue(27317): at android.os.Handler.sendMessageDelayed(Handler.java:620)
94 | 05-26 15:31:33.009 W/MessageQueue(27317): at android.os.Handler.post(Handler.java:364)
95 | 05-26 15:31:33.009 W/MessageQueue(27317): at android.os.ResultReceiver$MyResultReceiver.send(ResultReceiver.java:57)
96 | 05-26 15:31:33.009 W/MessageQueue(27317): at com.android.internal.os.IResultReceiver$Stub.onTransact(IResultReceiver.java:58)
97 | 05-26 15:31:33.009 W/MessageQueue(27317): at android.os.Binder.execTransact(Binder.java:698)
98 | 05-26 15:31:33.011 I/app_process(27317): System.exit called, status: 0
99 | 05-26 15:31:33.011 I/AndroidRuntime(27317): VM exiting with result code 0.
100 | 05-26 15:31:33.845 I/zygote (27125): WaitForGcToComplete blocked HeapTrim on ProfileSaver for 9.368ms
101 | 05-26 15:31:33.900 W/zygote (27125): No such thread for suspend: 0xc47fefe0:pool-2-thread-1
102 | 05-26 15:31:33.933 I/zygote (27125): Starting profile saver IsSaveProfileNow end.
103 | 05-26 15:31:33.991 D/TelephonyManager(27380): getAllCellInfo calling app is *
104 | 05-26 15:31:34.014 I/Choreographer(27125): Skipped 87 frames! The application may be doing too much work on its main thread.
105 | 05-26 15:31:34.097 I/DeviceProfileManager(27125): send success
106 | 05-26 15:31:34.233 D/CubicBezierInterpolator(27125): CubicBezierInterpolator mControlPoint1x = 0.23, mControlPoint1y = 0.06, mControlPoint2x = 0.09, mControlPoint2y = 0.97
107 | 05-26 15:31:34.235 D/CubicBezierInterpolator(27125): CubicBezierInterpolator mControlPoint1x = 0.6, mControlPoint1y = 0.9, mControlPoint2x = 0.8, mControlPoint2y = 1.0
108 | 05-26 15:31:34.235 D/CubicBezierInterpolator(27125): CubicBezierInterpolator mControlPoint1x = 0.23, mControlPoint1y = 0.06, mControlPoint2x = 0.09, mControlPoint2y = 0.97
109 | 05-26 15:31:34.236 D/CubicBezierInterpolator(27125): CubicBezierInterpolator mControlPoint1x = 0.6, mControlPoint1y = 0.9, mControlPoint2x = 0.8, mControlPoint2y = 1.0
110 | 05-26 15:31:34.238 W/getprop (27547): type=1400 audit(0.0:886922): avc: denied { open } for path="/dev/__properties__/u:object_r:logcat_prop:s0" dev="tmpfs" ino=2437 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:logcat_prop:s0 tclass=file permissive=0

其中多个崩溃用户的logcat日志中都看到了这个

F/libc (27125): /Volumes/Android/buildbot/src/android/ndk-release-r16/external/libcxx/../../external/libcxxabi/src/abort_message.cpp:73: abort_message: assertion "terminating with uncaught exception of type std::out_of_range: OutOfSpace" failed
lingol commented 4 years ago

logcat 日志

84 |  beginning of crash
85 | 05-26 15:31:32.819 F/libc (27125): /Volumes/Android/buildbot/src/android/ndk-release-r16/external/libcxx/../../external/libcxxabi/src/abort_message.cpp:73: abort_message: assertion "terminating with uncaught exception of type std::out_of_range: OutOfSpace" failed
86 | 05-26 15:31:32.892 E/Zygote (27317): register_com_android_internal_os_Zygote num = 0
87 | 05-26 15:31:32.979 D/AndroidRuntime(27317): Calling main entry com.android.commands.pm.Pm
88 | 05-26 15:31:33.009 W/MessageQueue(27317): Handler (android.os.Handler) {c9592a2} sending message to a Handler on a dead thread
89 | 05-26 15:31:33.009 W/MessageQueue(27317): java.lang.IllegalStateException: Handler (android.os.Handler) {c9592a2} sending message to a Handler on a dead thread
90 | 05-26 15:31:33.009 W/MessageQueue(27317): at android.os.MessageQueue.enqueueMessage(MessageQueue.java:639)
91 | 05-26 15:31:33.009 W/MessageQueue(27317): at android.os.Handler.enqueueMessage(Handler.java:681)
92 | 05-26 15:31:33.009 W/MessageQueue(27317): at android.os.Handler.sendMessageAtTime(Handler.java:650)
93 | 05-26 15:31:33.009 W/MessageQueue(27317): at android.os.Handler.sendMessageDelayed(Handler.java:620)
94 | 05-26 15:31:33.009 W/MessageQueue(27317): at android.os.Handler.post(Handler.java:364)
95 | 05-26 15:31:33.009 W/MessageQueue(27317): at android.os.ResultReceiver$MyResultReceiver.send(ResultReceiver.java:57)
96 | 05-26 15:31:33.009 W/MessageQueue(27317): at com.android.internal.os.IResultReceiver$Stub.onTransact(IResultReceiver.java:58)
97 | 05-26 15:31:33.009 W/MessageQueue(27317): at android.os.Binder.execTransact(Binder.java:698)
98 | 05-26 15:31:33.011 I/app_process(27317): System.exit called, status: 0
99 | 05-26 15:31:33.011 I/AndroidRuntime(27317): VM exiting with result code 0.
100 | 05-26 15:31:33.845 I/zygote (27125): WaitForGcToComplete blocked HeapTrim on ProfileSaver for 9.368ms
101 | 05-26 15:31:33.900 W/zygote (27125): No such thread for suspend: 0xc47fefe0:pool-2-thread-1
102 | 05-26 15:31:33.933 I/zygote (27125): Starting profile saver IsSaveProfileNow end.
103 | 05-26 15:31:33.991 D/TelephonyManager(27380): getAllCellInfo calling app is *
104 | 05-26 15:31:34.014 I/Choreographer(27125): Skipped 87 frames! The application may be doing too much work on its main thread.
105 | 05-26 15:31:34.097 I/DeviceProfileManager(27125): send success
106 | 05-26 15:31:34.233 D/CubicBezierInterpolator(27125): CubicBezierInterpolator mControlPoint1x = 0.23, mControlPoint1y = 0.06, mControlPoint2x = 0.09, mControlPoint2y = 0.97
107 | 05-26 15:31:34.235 D/CubicBezierInterpolator(27125): CubicBezierInterpolator mControlPoint1x = 0.6, mControlPoint1y = 0.9, mControlPoint2x = 0.8, mControlPoint2y = 1.0
108 | 05-26 15:31:34.235 D/CubicBezierInterpolator(27125): CubicBezierInterpolator mControlPoint1x = 0.23, mControlPoint1y = 0.06, mControlPoint2x = 0.09, mControlPoint2y = 0.97
109 | 05-26 15:31:34.236 D/CubicBezierInterpolator(27125): CubicBezierInterpolator mControlPoint1x = 0.6, mControlPoint1y = 0.9, mControlPoint2x = 0.8, mControlPoint2y = 1.0
110 | 05-26 15:31:34.238 W/getprop (27547): type=1400 audit(0.0:886922): avc: denied { open } for path="/dev/__properties__/u:object_r:logcat_prop:s0" dev="tmpfs" ino=2437 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:logcat_prop:s0 tclass=file permissive=0

其中多个崩溃用户的logcat日志中都看到了这个

F/libc (27125): /Volumes/Android/buildbot/src/android/ndk-release-r16/external/libcxx/../../external/libcxxabi/src/abort_message.cpp:73: abort_message: assertion "terminating with uncaught exception of type std::out_of_range: OutOfSpace" failed

That's far from enough. Logs from the beginning of MMKV initialize would be better.

free46000 commented 4 years ago 
0   --------- beginning of main
1   05-26 15:31:53.542 D/AudioManager(20746): getStreamVolume isRestricted mode = 0
2   05-26 15:31:53.542 I/chatty (20746): uid=10232(xxx.xxx) AsyncTask #1 identical 2 lines
3   05-26 15:31:53.542 D/AudioManager(20746): getStreamVolume isRestricted mode = 0
4   05-26 15:31:53.536 W/cat (20934): type=1400 audit(0.0:269117): avc: denied { search } for name="net" dev="sysfs" ino=49406 scontext=u:r:untrusted_app:s0:c232,c256,c512,c768 tcontext=u:object_r:sysfs_net:s0 tclass=dir permissive=0
5   05-26 15:31:53.580 E/xxx.xxx(20746): Invalid ID 0x00000000.
6   05-26 15:31:53.601 I/xxx.xxx:xx(20929): The ClassLoaderContext is a special shared library.
7   05-26 15:31:53.601 D/miuisdk (20746): current sdk level is 18
8   05-26 15:31:53.613 I/xxx.xxx:xx(20929): Waiting for a blocking GC AddRemoveAppImageSpace
9   05-26 15:31:53.615 E/om.abcde:remot(20948): Not starting debugger since process cannot load the jdwp agent.
10  05-26 15:31:53.629 I/xxx.xxx:xx(20929): WaitForGcToComplete blocked AddRemoveAppImageSpace on HeapTrim for 15.614ms
11  05-26 15:31:53.634 W/xxx.xxx:xx(20929): resources.arsc in APK '/data/app/xxx.xxx-KIPD6An2MLaO57UX0jyxxA==/base.apk' is compressed.
12  05-26 15:31:53.665 I/Perf (20929): Connecting to perf service.
13  05-26 15:31:53.676 I/MultiDex(20929): VM with version 2.1.0 has multidex support
14  05-26 15:31:53.676 I/MultiDex(20929): Installing application
15  05-26 15:31:53.676 I/MultiDex(20929): VM has multidex support, MultiDex support library is disabled.
16  05-26 15:31:53.683 I/System.out(20929): 注释长度 = 0
17  05-26 15:31:53.697 I/om.abcde:remot(20948): The ClassLoaderContext is a special shared library.
18  05-26 15:31:53.699 I/MMKV (20929): <native-bridge.cpp:108::JNI_OnLoad> current API level = 28
19  05-26 15:31:53.699 I/MMKV (20929): <MMKV.cpp:143::initialize> page size:4096
20  05-26 15:31:53.699 I/MMKV (20929): <MMKV.cpp:156::initializeMMKV> root dir: /data/user/0/xxx.xxx/files/kv_storage
21  05-26 15:31:53.711 E/HMSSDK_HMSPackageManager(20746): Failed to find HMS apk
22  05-26 15:31:53.726 W/om.abcde:remot(20948): resources.arsc in APK '/data/app/xxx.xxx-KIPD6An2MLaO57UX0jyxxA==/base.apk' is compressed.
23  05-26 15:31:53.730 W/xxx.xxx(20746): resources.arsc in APK '/data/app/com.tencent.qqmusic-a-C_XSjwIUpROOg4Z1V7AQ==/base.apk' is compressed.
24  05-26 15:31:53.738 I/Perf (20948): Connecting to perf service.
25  05-26 15:31:53.742 I/MultiDex(20948): VM with version 2.1.0 has multidex support
26  05-26 15:31:53.742 I/MultiDex(20948): Installing application
27  05-26 15:31:53.742 I/MultiDex(20948): VM has multidex support, MultiDex support library is disabled.
28  05-26 15:31:53.747 I/HMSSDK_HMSBIInitializer(20746): Builder->biInitFlag :false
29  05-26 15:31:53.748 I/System.out(20948): 注释长度 = 0
30  05-26 15:31:53.748 I/HMSSDK_HMSBIInitializer(20746): Builder->biSetting :false
31  05-26 15:31:53.748 I/HMSSDK_CountryCodeBean(20746): getCountryCode get country code from SIM_COUNTRY
32  05-26 15:31:53.750 I/HMSSDK_CountryCodeBean(20746): getCountryCode get country code from SIM_COUNTRY
33  05-26 15:31:53.754 I/MMKV (20948): <native-bridge.cpp:108::JNI_OnLoad> current API level = 28
34  05-26 15:31:53.754 I/MMKV (20948): <MMKV.cpp:143::initialize> page size:4096
35  05-26 15:31:53.754 I/MMKV (20948): <MMKV.cpp:156::initializeMMKV> root dir: /data/user/0/xxx.xxx/files/kv_storage
36  05-26 15:31:53.804 I/WebViewFactory(20929): Loading com.google.android.webview version 74.0.3729.136 (code 372913650)
37  05-26 15:31:53.813 W/NetworkKit_c(20746): 20746-21001|null|com.huawei.hms.framework.network.grs.c.c|a|76|local config file is not exist.filename is {grs_app_global_route_config.json}
38  05-26 15:31:53.806 W/r.QANRContext$3(20929): type=1400 audit(0.0:269118): avc: denied { read } for name="anr" dev="sda34" ino=3145729 scontext=u:r:untrusted_app:s0:c232,c256,c512,c768 tcontext=u:object_r:anr_data_file:s0 tclass=dir permissive=0
39  05-26 15:31:53.826 W/ls (21004): type=1400 audit(0.0:269119): avc: denied { getattr } for path="/data/anr" dev="sda34" ino=3145729 scontext=u:r:untrusted_app:s0:c232,c256,c512,c768 tcontext=u:object_r:anr_data_file:s0 tclass=dir permissive=0
40  05-26 15:31:53.837 I/NetworkKit_AbstractLocalManager(20746): 20746-21001|null|com.huawei.hms.framework.network.grs.local.a|a|65|load SDK_CONFIG_FILE sucess.
41  05-26 15:31:53.842 I/WebViewFactory(20948): Loading com.google.android.webview version 74.0.3729.136 (code 372913650)
42  05-26 15:31:53.849 I/cr_LibraryLoader(20929): Time to load native libraries: 1 ms (timestamps 9373-9374)
43  05-26 15:31:53.854 W/chromium(20929): [0526/153153.854275:WARNING:library_prefetcher.cc(328)] Code not ordered, madvise optimization skipped
44  05-26 15:31:53.854 I/chromium(20929): [INFO:library_loader_hooks.cc(50)] Chromium logging enabled: level = 0, default verbosity = 0
45  05-26 15:31:53.854 I/cr_LibraryLoader(20929): Expected native library version number "74.0.3729.136", actual native library version number "74.0.3729.136"
46  05-26 15:31:53.856 I/NetworkKit_a(20746): 20746-20746|null|com.huawei.hms.framework.network.grs.a|a|22|get url from sp is not empty.
47  05-26 15:31:53.862 I/cr_LibraryLoader(20948): Time to load native libraries: 1 ms (timestamps 9386-9387)
48  05-26 15:31:53.866 I/HMSSDK_HMSBIInitializer(20746): BI URL acquired successfully
49  05-26 15:31:53.867 I/HMS-Awa (20746): [AwarenessConnection] setEnableUpdateWindow: false
50  05-26 15:31:53.871 I/xxx.xxx(20746): Background concurrent copying GC freed 86159(5MB) AllocSpace objects, 64(2MB) LOS objects, 49% free, 9MB/18MB, paused 2.377ms total 141.356ms
51  05-26 15:31:53.875 D/IdProviderImpl(20746): getOAID
52  05-26 15:31:53.877 W/chromium(20948): [0526/153153.877395:WARNING:library_prefetcher.cc(328)] Code not ordered, madvise optimization skipped
53  05-26 15:31:53.878 I/chromium(20948): [INFO:library_loader_hooks.cc(50)] Chromium logging enabled: level = 0, default verbosity = 0
54  05-26 15:31:53.878 I/cr_LibraryLoader(20948): Expected native library version number "74.0.3729.136", actual native library version number "74.0.3729.136"
55  05-26 15:31:53.880 D/IdProviderImpl(20746): getVAID
56  05-26 15:31:53.883 D/IdProviderImpl(20746): getAAID
57  05-26 15:31:53.889 D/IdProviderImpl(20746): getOAID
58  05-26 15:31:53.891 D/IdProviderImpl(20746): getVAID
59  05-26 15:31:53.893 I/HMSSDK_HuaweiApiManager(20746): sendRequest
60  05-26 15:31:53.894 I/HMSSDK_BaseHmsClient(20746): ====== HMSSDK version: 40002300 ======
61  05-26 15:31:53.895 I/HMSSDK_BaseHmsClient(20746): Enter connect, Connection Status: 1
62  05-26 15:31:53.896 I/HMSSDK_BaseHmsClient(20746): connect minVersion:40001100
63  05-26 15:31:53.899 E/HMSSDK_HMSPackageManager(20746): Failed to find HMS apk
64  05-26 15:31:53.900 I/HMSSDK_AvailableAdapter(20746): HMS is not installed
65  05-26 15:31:53.900 I/HMSSDK_BaseHmsClient(20746): check available result: 1
66  05-26 15:31:53.901 I/HMSSDK_BaseHmsClient(20746): enter HmsCore resolution
67  05-26 15:31:53.901 I/HMSSDK_BaseHmsClient(20746): notifyFailed result: 26
68  05-26 15:31:53.902 I/HMSSDK_HuaweiApiManager(20746): onConnectionFailed
69  05-26 15:31:53.904 I/HMSSDK_BaseHmsClient(20746): Enter disconnect, Connection Status: 5
70  05-26 15:31:53.905 D/IdProviderImpl(20746): getAAID
71  05-26 15:31:53.910 D/NetworkSecurityConfig(20929): Using Network Security Config from resource spider_network_security_config debugBuild: false
72  05-26 15:31:53.917 D/baidu_location_service(20948): baidu location service start1 ...20190725...20948
73  05-26 15:31:53.918 D/baidu_location_client(20746): baidu location connected ...
74  05-26 15:31:53.924 I/BaiduApiAuth(20948): BaiduApiAuth SDK Version:1.0.23
75  05-26 15:31:53.924 W/System.err(20746): android.content.pm.PackageManager$NameNotFoundException: com.bbk.appstore
76  05-26 15:31:53.928 W/System.err(20746): at android.app.ApplicationPackageManager.getPackageInfoAsUser(ApplicationPackageManager.java:183)
77  05-26 15:31:53.928 W/System.err(20746): at android.app.ApplicationPackageManager.getPackageInfo(ApplicationPackageManager.java:153)
78  05-26 15:31:53.928 W/System.err(20746): at xxx.xxx.xxx.xxx.Checker.a(SourceFile:225)
79  05-26 15:31:53.928 W/System.err(20746): at xxx.xxx.xxx.xxx.Checker.a(SourceFile:267)
80  05-26 15:31:53.928 W/System.err(20746): at xxx.xxx.xxx.xxx.Checker.access$300(SourceFile:39)
81  05-26 15:31:53.928 W/System.err(20746): at xxx.xxx.xxx.xxx.Checker$3.a(SourceFile:295)
82  05-26 15:31:53.928 W/System.err(20746): at xxx.xxx.xxx.xxx.Checker$3.doInBackground(SourceFile:291)
83  05-26 15:31:53.928 W/System.err(20746): at android.os.AsyncTask$2.call(AsyncTask.java:333)
84  05-26 15:31:53.928 W/System.err(20746): at java.util.concurrent.FutureTask.run(FutureTask.java:266)
85  05-26 15:31:53.928 W/System.err(20746): at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
86  05-26 15:31:53.928 W/System.err(20746): at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
87  05-26 15:31:53.928 W/System.err(20746): at java.lang.Thread.run(Thread.java:764)
88  05-26 15:31:53.933 D/NetworkSecurityConfig(20948): Using Network Security Config from resource spider_network_security_config debugBuild: false
89  05-26 15:31:53.950 I/baidu_location_service(20948): LocationAuthManager Authentication AUTHENTICATE_SUCC
90  --------- beginning of crash
91  05-26 15:31:53.968 F/libc (20746): /Volumes/Android/buildbot/src/android/ndk-release-r16/external/libcxx/../../external/libcxxabi/src/abort_message.cpp:73: abort_message: assertion "terminating with uncaught exception of type std::out_of_range: OutOfSpace" failed
92  05-26 15:31:53.974 I/xxx.xxx:xx(20929): Background concurrent copying GC freed 16737(1412KB) AllocSpace objects, 11(220KB) LOS objects, 50% free, 6MB/12MB, paused 192us total 106.524ms
93  05-26 15:31:54.048 D/baidu_location_service(20948): baidu location service register ...
94  05-26 15:31:54.048 D/baidu_location_service(20948): start gps...
95  05-26 15:31:54.102 W/System.err(20948): load indoor lib success.
96  05-26 15:31:54.532 V/xiaomi (20746): [Thread:1107] sdk_version = 3_7_0
97  05-26 15:31:54.574 V/xiaomi (20746): [Thread:1122] (Local) begin execute onCommandResult, command=register, resultCode=0, reason=null
98  05-26 15:31:54.576 V/xiaomi (20746): [Thread:1122] ASSEMBLE_PUSH : assemble push register
99  05-26 15:31:54.577 V/xiaomi (20746): [Thread:1122] (Local) begin execute onCommandResult, command=set-alias, resultCode=0, reason=null
100 05-26 15:31:54.600 W/Settings(20746): Setting always_finish_activities has moved from android.provider.Settings.System to android.provider.Settings.Global, returning read-only value.
101 05-26 15:31:54.622 W/xxx.xxx(20746): resources.arsc in APK '/data/app/com.xingin.xhs-0QmNvQCMXNGKiALB9qCAqg==/base.apk' is compressed.

这个日志里面包含了mmkv的初始化日志，但是由于我在初始化后调整了mmkv的日志级别，现在没有过多的info级别的日志信息了。你看下这个够吗

lingol commented 4 years ago

NO. There's nothing to see here. You should keep the default log level, which is the Info level.

free46000 commented 4 years ago

好的，等我改回原来的日志级别，在本地尝试复现下问题，在贴出日志

lingol commented 4 years ago

好的，等我改回原来的日志级别，在本地尝试复现下问题，在贴出日志

Looking forward to that.
By the way, you'd better track down which MMKV instance cause that crash. Maybe you can figure that out by looking into your Java crash call-stacks.

free46000 commented 4 years ago

通过java堆栈我能确定是哪个实例出现的问题，这个实例和其他实例有一个区别是，这个实例会频繁调用mmkv.removeValuesForKeys方法，我看这个方法每次调用会触发清理相关的动作，不知道和这个有没有关系，下面是调用mmkv.removeValuesForKeys的相关日志

05-25 07:57:31.286 I/MMKV (12762): <MMKV.cpp:481::clearAll> cleaning all key-values from [name]
05-25 07:57:31.286 I/MMKV (12762): <MMKV.cpp:509::clearMemoryCache> clearMemoryCache [name]
05-25 07:57:31.286 I/MMKV (12762): <MMKV.cpp:263::loadFromFile> loading [name] with 0 actual size, file size 4096, InterProcess 1, meta info version:3
05-25 07:57:31.287 I/MMKV (12762): <MMKV.cpp:296::loadFromFile> loaded [name] with 0 values
lingol commented 4 years ago

通过java堆栈我能确定是哪个实例出现的问题，这个实例和其他实例有一个区别是，这个实例会频繁调用mmkv.removeValuesForKeys方法，我看这个方法每次调用会触发清理相关的动作，不知道和这个有没有关系，下面是调用mmkv.removeValuesForKeys的相关日志

05-25 07:57:31.286 I/MMKV (12762): <MMKV.cpp:481::clearAll> cleaning all key-values from [name]
05-25 07:57:31.286 I/MMKV (12762): <MMKV.cpp:509::clearMemoryCache> clearMemoryCache [name]
05-25 07:57:31.286 I/MMKV (12762): <MMKV.cpp:263::loadFromFile> loading [name] with 0 actual size, file size 4096, InterProcess 1, meta info version:3
05-25 07:57:31.287 I/MMKV (12762): <MMKV.cpp:296::loadFromFile> loaded [name] with 0 values

Maybe, but that little logs didn't help much either.
Waiting for your Info logs when you catch this crash.

free46000 commented 4 years ago 
0   --------- beginning of main
1   05-27 15:03:38.980 D/SoLoader(26936): libimagepipeline.so found on /data/app/com.xxx-2/lib/arm
2   05-27 15:03:38.980 D/SoLoader(26936): Not resolving dependencies for libimagepipeline.so
3   05-27 15:03:38.998 D/SoLoader(26936): Loaded: libimagepipeline.so
4   05-27 15:03:39.028 W/System.err(26936): android.content.pm.PackageManager$NameNotFoundException: com.bbk.appstore
5   05-27 15:03:39.028 W/System.err(26936): at android.app.ApplicationPackageManager.getPackageInfo(ApplicationPackageManager.java:168)
6   05-27 15:03:39.028 W/System.err(26936): at com.xxx.upgrader.platform.Checker.a(SourceFile:225)
7   05-27 15:03:39.028 W/System.err(26936): at com.xxx.upgrader.platform.Checker.a(SourceFile:267)
8   05-27 15:03:39.028 W/System.err(26936): at com.xxx.upgrader.platform.Checker.access$300(SourceFile:39)
9   05-27 15:03:39.028 W/System.err(26936): at com.xxx.upgrader.platform.Checker$3.a(SourceFile:295)
10  05-27 15:03:39.028 W/System.err(26936): at com.xxx.upgrader.platform.Checker$3.doInBackground(SourceFile:291)
11  05-27 15:03:39.028 W/System.err(26936): at android.os.AsyncTask$2.call(AsyncTask.java:295)
12  05-27 15:03:39.028 W/System.err(26936): at java.util.concurrent.FutureTask.run(FutureTask.java:237)
13  05-27 15:03:39.028 W/System.err(26936): at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1113)
14  05-27 15:03:39.028 W/System.err(26936): at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:588)
15  05-27 15:03:39.029 W/System.err(26936): at java.lang.Thread.run(Thread.java:818)
16  05-27 15:03:39.044 I/MMKV (26936): <MMKV.cpp:553::trim> prepare to trim hen
17  05-27 15:03:39.061 I/MMKV (26936): <MMKV.cpp:576::trim> trimming hen from 65536 to 32768, actualSize 20687
18  05-27 15:03:39.063 I/MMKV (26936): <MMKV.cpp:586::trim> finish trim hen from 65536 to 32768
19  05-27 15:03:39.072 I/MMKV (27088): <MMKV.cpp:436::checkLoadData> [hen] oldSeq 18, newSeq 19
20  05-27 15:03:39.072 I/MMKV (27088): <MMKV.cpp:509::clearMemoryCache> clearMemoryCache [hen]
21  05-27 15:03:39.073 I/MMKV (27088): <MMKV.cpp:263::loadFromFile> loading [hen] with 20687 actual size, file size 32768, InterProcess 1, meta info version:3
22  05-27 15:03:39.073 I/MMKV (27088): <MMKV.cpp:268::loadFromFile> loading [hen] with crc 225677671 sequence 19 version 3
23  05-27 15:03:39.073 I/MMKV (27088): <MMKV.cpp:296::loadFromFile> loaded [hen] with 39 values
24  05-27 15:03:39.077 I/WebViewFactory(27052): Loading com.google.android.webview version 55.0.2883.91 (code 288309150)
25  05-27 15:03:39.102 I/MMKV (26936): <MMKV.cpp:553::trim> prepare to trim nxxx_ue
26  05-27 15:03:39.103 I/MMKV (26936): <MMKV.cpp:576::trim> trimming nxxx_ue from 16384 to 2048, actualSize 1124
27  05-27 15:03:39.107 I/MMKV (26936): <MMKV.cpp:586::trim> finish trim nxxx_ue from 16384 to 2048
28  05-27 15:03:39.117 D/SoLoader(26936): About to load: libnative-imagetranscoder.so
29  05-27 15:03:39.119 I/MMKV (26936): <MMKV.cpp:553::trim> prepare to trim xxx_cross_components
30  05-27 15:03:39.119 D/SoLoader(26936): libnative-imagetranscoder.so not found on /data/data/com.xxx/lib-main
31  05-27 15:03:39.120 D/SoLoader(26936): libnative-imagetranscoder.so found on /data/app/com.xxx-2/lib/arm
32  05-27 15:03:39.120 D/SoLoader(26936): Not resolving dependencies for libnative-imagetranscoder.so
33  05-27 15:03:39.133 W/System (27052): ClassLoader referenced unknown path: /system/app/WebViewGoogle/lib/arm
34  05-27 15:03:39.141 I/art (27052): Rejecting re-init on previously-failed class java.lang.Class<com.android.webview.chromium.TokenBindingManagerAdapter>
35  05-27 15:03:39.141 I/art (27052): Rejecting re-init on previously-failed class java.lang.Class<com.android.webview.chromium.TokenBindingManagerAdapter>
36  05-27 15:03:39.146 I/art (27052): Rejecting re-init on previously-failed class java.lang.Class<com.android.webview.chromium.ServiceWorkerControllerAdapter>
37  05-27 15:03:39.147 I/art (27052): Rejecting re-init on previously-failed class java.lang.Class<com.android.webview.chromium.ServiceWorkerControllerAdapter>
38  05-27 15:03:39.150 I/MMKV (26936): <MMKV.cpp:553::trim> prepare to trim com.xxx.atom.alexhome
39  05-27 15:03:39.155 I/cr_LibraryLoader(27052): Time to load native libraries: 3 ms (timestamps 7267-7270)
40  05-27 15:03:39.155 I/cr_LibraryLoader(27052): Expected native library version number "55.0.2883.91", actual native library version number "55.0.2883.91"
41  05-27 15:03:39.158 I/MMKV (26936): <MMKV.cpp:572::trim> there's no need to trim com.xxx.atom.alexhome with size 65536, actualSize 34983
42  05-27 15:03:39.170 I/System.out(26936): [socket] connection slugger.xxx.com/123.59.180.146:443;LocalPort=34033(80000)
43  05-27 15:03:39.177 I/MMKV (27052): <MMKV.cpp:263::loadFromFile> loading [nxxx_ue] with 1124 actual size, file size 4096, InterProcess 1, meta info version:3
44  05-27 15:03:39.177 I/MMKV (27052): <MMKV.cpp:268::loadFromFile> loading [nxxx_ue] with crc 2503740374 sequence 174 version 3
45  05-27 15:03:39.177 I/MMKV (27052): <MMKV.cpp:296::loadFromFile> loaded [nxxx_ue] with 6 values
46  05-27 15:03:39.182 D/libc-netbsd(26936): [getaddrinfo]: hostname=minislugger.xxx.com; servname=(null); app_uid=10139; ai_addrlen=0; ai_canonname=(null); ai_flags=1024; ai_family=0 from prox result 0
47  05-27 15:03:39.195 I/MMKV (26936): <MMKV.cpp:553::trim> prepare to trim com.xxx.atom.attemper
48  05-27 15:03:39.200 V/SensorManager(26936): unRegisterListener by com.xxx.lib.riskcontrol.GetInfoUtils$2
49  05-27 15:03:39.201 D/SoLoader(27052): init start
50  05-27 15:03:39.201 D/SoLoader(27052): adding system library source: /vendor/lib
51  05-27 15:03:39.202 D/SoLoader(27052): adding system library source: /system/lib
52  05-27 15:03:39.202 D/SoLoader(27052): adding application source: com.facebook.soloader.DirectorySoSource[root = /data/app/com.xxx-2/lib/arm flags = 0]
53  05-27 15:03:39.203 D/SoLoader(27052): adding backup source from : com.facebook.soloader.ApkSoSource[root = /data/data/com.xxx/lib-main flags = 1]
54  05-27 15:03:39.203 D/SoLoader(27052): Preparing SO source: com.facebook.soloader.DirectorySoSource[root = /system/lib flags = 2]
55  05-27 15:03:39.203 D/SoLoader(27052): Preparing SO source: com.facebook.soloader.DirectorySoSource[root = /system/vendor/lib flags = 2]
56  05-27 15:03:39.203 D/SoLoader(27052): Preparing SO source: com.facebook.soloader.DirectorySoSource[root = /data/app/com.xxx-2/lib/arm flags = 0]
57  05-27 15:03:39.203 D/SoLoader(27052): Preparing SO source: com.facebook.soloader.ApkSoSource[root = /data/data/com.xxx/lib-main flags = 1]
58  05-27 15:03:39.204 V/fb-UnpackingSoSource(27052): locked dso store /data/user/0/com.xxx/lib-main
59  05-27 15:03:39.206 I/fb-UnpackingSoSource(27052): dso store is up-to-date: /data/user/0/com.xxx/lib-main
60  05-27 15:03:39.206 V/fb-UnpackingSoSource(27052): releasing dso store lock for /data/user/0/com.xxx/lib-main
61  05-27 15:03:39.206 D/SoLoader(27052): init finish: 4 SO sources prepared
62  05-27 15:03:39.206 D/SoLoader(27052): init exiting
63  05-27 15:03:39.207 V/SensorManager(26936): unRegisterListener by com.xxx.lib.riskcontrol.GetInfoUtils$4
64  --------- beginning of crash
65  05-27 15:03:39.218 F/libc (26936): /Volumes/Android/buildbot/src/android/ndk-release-r16/external/libcxx/../../external/libcxxabi/src/abort_message.cpp:73: abort_message: assertion "terminating with uncaught exception of type std::out_of_range: OutOfSpace" failed
66  05-27 15:03:39.235 I/MMKV (27052): <MMKV.cpp:436::checkLoadData> [hen] oldSeq 18, newSeq 19
67  05-27 15:03:39.235 I/MMKV (27052): <MMKV.cpp:509::clearMemoryCache> clearMemoryCache [hen]
68  05-27 15:03:39.236 I/MMKV (27052): <MMKV.cpp:263::loadFromFile> loading [hen] with 21885 actual size, file size 32768, InterProcess 1, meta info version:3
69  05-27 15:03:39.236 I/MMKV (27052): <MMKV.cpp:268::loadFromFile> loading [hen] with crc 4046393631 sequence 19 version 3
70  05-27 15:03:39.236 I/MMKV (27052): <MMKV.cpp:296::loadFromFile> loaded [hen] with 39 values
71  05-27 15:03:39.237 I/WebViewFactory(27088): Loading com.google.android.webview version 55.0.2883.91 (code 288309150)
72  05-27 15:03:39.292 W/System (27088): ClassLoader referenced unknown path: /system/app/WebViewGoogle/lib/arm
73  05-27 15:03:39.296 D/libc-netbsd(27052): [getaddrinfo]: hostname=qcweb.xxx.com; servname=(null); app_uid=10139; ai_addrlen=0; ai_canonname=(null); ai_flags=1024; ai_family=0 from prox result 0
74  05-27 15:03:39.297 I/System.out(27052): [socket] connection qcweb.xxx.com/117.122.224.157:443;LocalPort=51585(10000)
75  05-27 15:03:39.299 I/art (27088): Rejecting re-init on previously-failed class java.lang.Class<com.android.webview.chromium.TokenBindingManagerAdapter>
76  05-27 15:03:39.300 I/art (27088): Rejecting re-init on previously-failed class java.lang.Class<com.android.webview.chromium.TokenBindingManagerAdapter>
77  05-27 15:03:39.303 I/art (27088): Rejecting re-init on previously-failed class java.lang.Class<com.android.webview.chromium.ServiceWorkerControllerAdapter>
78  05-27 15:03:39.304 I/art (27088): Rejecting re-init on previously-failed class java.lang.Class<com.android.webview.chromium.ServiceWorkerControllerAdapter>
79  05-27 15:03:39.310 I/cr_LibraryLoader(27088): Time to load native libraries: 3 ms (timestamps 7422-7425)
80  05-27 15:03:39.310 I/cr_LibraryLoader(27088): Expected native library version number "55.0.2883.91", actual native library version number "55.0.2883.91"
81  05-27 15:03:39.360 I/DpmTcmClient(26936): RegisterTcmMonitor from: com.android.okhttp.TcmIdleTimerMonitor
82  05-27 15:03:39.364 I/System.out(26936): Not need to boost!
83  05-27 15:03:39.771 D/AndroidRuntime(27111): >>>>>> START com.android.internal.os.RuntimeInit uid 10139 <<<<<<
84  05-27 15:03:39.772 D/libc-netbsd(27052): [getaddrinfo]: hostname=qpush.xxx.com; servname=(null); app_uid=10139; ai_addrlen=0; ai_canonname=(null); ai_flags=1024; ai_family=0 from prox result 0
85  05-27 15:03:39.773 I/System.out(27052): [socket] connection qpush.xxx.com/59.151.47.238:8883;LocalPort=50195(30000)
86  05-27 15:03:39.786 D/AndroidRuntime(27111): CheckJNI is OFF
87  05-27 15:03:39.868 D/ICU (27111): No timezone override file found: /data/misc/zoneinfo/current/icu/icu_tzdata.dat
88  05-27 15:03:39.909 D/SoLoader(26936): Loaded: libnative-imagetranscoder.so
89  05-27 15:03:39.955 D/libc-netbsd(26936): [getaddrinfo]: hostname=loc.map.baidu.com; servname=(null); app_uid=10139; ai_addrlen=0; ai_canonname=(null); ai_flags=1024; ai_family=0 from prox result 0
90  05-27 15:03:39.959 I/System.out(26936): [socket] connection loc.map.baidu.com/103.235.47.89:443;LocalPort=59568(12000)
91  05-27 15:03:40.004 I/Radio-JNI(27111): register_android_hardware_Radio DONE
92  05-27 15:03:40.046 I/art (26936): Background partial concurrent mark sweep GC freed 74542(4MB) AllocSpace objects, 31(1456KB) LOS objects, 39% free, 19MB/33MB, paused 4.489ms total 108.834ms
93  05-27 15:03:40.085 I/art (26936): Rejecting re-init on previously-failed class java.lang.Class<androidx.core.view.ViewCompat$OnUnhandledKeyEventListenerWrapper>
94  05-27 15:03:40.086 I/art (26936): Rejecting re-init on previously-failed class java.lang.Class<androidx.core.view.ViewCompat$OnUnhandledKeyEventListenerWrapper>
95  05-27 15:03:40.126 D/AndroidRuntime(27111): Calling main entry com.android.commands.pm.Pm
96  05-27 15:03:40.187 W/art (26936): Before Android 4.1, method void com.xxx.framework.view.IcsLinearLayout.drawDividersHorizontal(android.graphics.Canvas) would have incorrectly overridden the package-private method in android.widget.LinearLayout
97  05-27 15:03:40.187 W/art (26936): Before Android 4.1, method void com.xxx.framework.view.IcsLinearLayout.drawDividersVertical(android.graphics.Canvas) would have incorrectly overridden the package-private method in android.widget.LinearLayout
98  05-27 15:03:40.188 W/art (26936): Before Android 4.1, method void com.xxx.framework.view.IcsLinearLayout.drawHorizontalDivider(android.graphics.Canvas, int) would have incorrectly overridden the package-private method in android.widget.LinearLayout
99  05-27 15:03:40.188 W/art (26936): Before Android 4.1, method void com.xxx.framework.view.IcsLinearLayout.drawVerticalDivider(android.graphics.Canvas, int) would have incorrectly overridden the package-private method in android.widget.LinearLayout
100 05-27 15:03:40.215 I/art (27111): System.exit called, status: 0
101 05-27 15:03:40.215 I/AndroidRuntime(27111): VM exiting with result code 0.

这次日志麻烦看下，通过日志确实可以看出是在多进程下同时操作了mmkv，其中26936是主进程，27052是子进程，麻烦看下有没有什么问题？

free46000 commented 4 years ago

再补充下场景，这个崩溃并不是必现的概率大概2%左右，并且单个用户重复崩溃的场景也很少

lingol commented 4 years ago

Two questions:

  1. I need logs from the beginning of MMKV initialize, not just logs around the crash.
  2. Which MMKV causes the crash according to your Java call-stacks? Is it hen, nxxx_ue or xxx_cross_components or com.xxx.atom.alexhome or com.xxx.atom.attemper?

By the way, I don't recommend changing the names of MMKV instances in your logs before posting here. Nor should you delete some of the logs.

lingol commented 4 years ago

If the logs are too large, you should just upload them as an attachment.

lingol commented 4 years ago

26 05-27 15:03:39.103 I/MMKV (26936): trimming nxxx_ue from 16384 to 2048, actualSize 1124

I kind of know what's the problem, 2048 is smaller than the pagesize. Let me check for it.

free46000 commented 4 years ago

31 05-27 15:19:26.217 I/MMKV ( 6624): prepare to trim nxxx_ue 32 05-27 15:19:26.217 I/MMKV ( 6624): prepare to trim hen 33 05-27 15:19:26.218 I/MMKV ( 6624): trimming nxxx_ue from 1048576 to 512, actualSize 383

我去看了看日志，还有的 trim 到 512 的日志

lingol commented 4 years ago

Fixed with commit https://github.com/Tencent/MMKV/commit/14e06bd684a542d2233149399ba7cb88e60c56de on the dev branch. A hotfix release will roll out this week ASAP. For the time being, you can remove those trim() call.

free46000 commented 4 years ago

好的，多谢

lingol commented 4 years ago

Solved with v1.1.2.