ANR研究开启|ANR trace中的mutator lock是

2024-05-21  本文已影响0人  蚍蜉一生

mutator 英文意思是: 变异者、改写者;
mutator lock 意思是改写锁,具体来说就是线程改写内存时候需要持有的锁

mutator lock设计的初衷是为了在执行垃圾回收时锁定处于GC管理下的内存区域中的对象,防止并发修改导致的内存一致性问题;

mutator lock的定义和实现分散在 ART 的代码库中,特别是在 ART 的同步机制和垃圾回收相关的代码中。

mutator lock有两种持有方式:shared held: 共享持有,exclusive held:独占持有;

    所以我们可认为:共享持有(shared held)是一种标记,它标记了哪些线程(mutator thread)应该在GC内存回收阶段被暂停。

在了解上面知识后我们来看ANR中以下log的含义:

  1. Total mutator paused time: 71.263ms
    该进程自启动到抓取trace这个时间段内,所有线程因为GC线程独占mutator lock被暂停的时间;

  2. Total time waiting for GC to complete: 3.356s
    该进程自启动到抓取trace这个时间段内,该进程下所有线程等待GC线程所花费的时间.
    比如,一个线程需要操作分配一个大快内存,但是申请时候内存不足,启动GC线程进行内存整理,这段等待GC整理内存的时间就是等待GC时间;GC有并行GC和stop world GC,如有有stop world GC,这个等待时间就会包括这个线程mutator paused time,但是很多线程是不需要等待GC的只是因GC线程pause,所以不会包含进去他们的mutator paused time,所以Total mutator paused time和Total time waiting for GC to complete并不存在相互包含的关系。

  3. Total GC count: 247
    该进程自启动到抓取trace这个时间段内,GC次数;

  4. Total GC time: 12.861s
    该进程自启动到抓取trace这个时间段内,GC所花费的时间;

这四句log从不同层面反应了GC对其他线程的影响,都是分析ANR的重要参考指标。

附录

最后是一些trace中持有mutator lock的case,大家可以再次感受和理解下它的作用。

"AsyncTask #4" prio=5 tid=296 Runnable
| group="main" sCount=0 ucsCount=0 flags=0 obj=0x13bc2570 self=0xb4000075ca96dc00
| sysTid=28273 nice=10 cgrp=default sched=0/0 handle=0x751e89fcb0
| state=R schedstat=( 901454146 589993304 524 ) utm=71 stm=18 core=2 HZ=100
| stack=0x751e79c000-0x751e79e000 stackSize=1039KB
| held mutexes= "mutator lock"(shared held)
at android.util.ArraySet.valueAt(ArraySet.java:419)
at com.android.server.appop.AppOpsService.writeState(AppOpsService.java:5441)
-locked <0x05a7dbab> (a android.util.AtomicFile)
at com.android.server.appop.AppOpsService11.doInBackground(AppOpsService.java:336)
at com.android.server.appop.AppOpsService11.doInBackground(AppOpsService.java:334)
at android.os.AsyncTask$3.call(AsyncTask.java:394)
at java.util.concurrent.FutureTask.run(FutureTask.java:264)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1137)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:637)
at java.lang.Thread.run(Thread.java:1012)
——————————————————————————————————
"main" prio=5 tid=1 Runnable
| group="main" sCount=0 ucsCount=0 flags=0 obj=0x72daa0b8 self=0xb4000079e811b010
| sysTid=32173 nice=0 cgrp=foreground sched=0/0 handle=0x7b2f3ea4f8
| state=R schedstat=( 568779813 790500309 1388 ) utm=11 stm=45 core=2 HZ=100
| stack=0x7feaf64000-0x7feaf66000 stackSize=8188KB
| held mutexes= "mutator lock"(shared held)
at dalvik.system.DexClassLoader.<init>(DexClassLoader.java:55)
at com..dueros.logger.utils.a.a(FileUtils.java:26)
at com.
.iovsdk.pangu.shell.dynamic.e.c(PluginLoader.java:1)
——————————————————————————————————
210: DALVIK THREADS (58):
211: "fin-1-thread-2" prio=5 tid=54 Runnable
212: | group="main" sCount=0 dsCount=0 flags=0 obj=0x13242128 self=0x76481ea4d0
213: | sysTid=4989 nice=0 cgrp=default sched=0/0 handle=0x74c66bbcc0
214: | state=R schedstat=( 102433764 63919574 251 ) utm=3 stm=6 core=0 HZ=100
215: | stack=0x74c65b8000-0x74c65ba000 stackSize=1043KB
216: | held mutexes= "mutator lock"(shared held)
217: at java.lang.ref.FinalizerReference.add(FinalizerReference.java:61)
218: at com.android.org.conscrypt.OpenSSLEvpCipher.<init>(OpenSSLEvpCipher.java:38)
219: at com.android.org.conscrypt.OpenSSLEvpCipherAES.<init>
——————————————————————————————————

252: "report-deliver2" prio=5 tid=88 Runnable
253: | group="main" sCount=0 ucsCount=0 flags=0 obj=0x132c51b0 self=0x74b236b000
254: | sysTid=18548 nice=0 cgrp=default sched=0/0 handle=0x741fdb6cb0
255: | state=R schedstat=( 11609268 12135470 45 ) utm=0 stm=1 core=4 HZ=100
256: | stack=0x741fcb3000-0x741fcb5000 stackSize=1039KB
257: | held mutexes= "mutator lock"(shared held)
258: at org.json.JSONTokener.nextToInternal(JSONTokener.java:346)
259: at org.json.JSONTokener.readLiteral(JSONTokener.java:289)
260: at org.json.JSONTokener.nextValue(JSONTokener.java:115)
261: at org.json.JSONTokener.readObject(JSONTokener.java:394)
262: at org.json.JSONTokener.nextValue(JSONTokener.java:104)
263: at org.json.JSONObject.<init>(JSONObject.java:168)
264: at org.json.JSONObject.<init>(JSONObject.java:185)
265: at com..naviauto.crashsdk.component.http.BDCrashServiceApiImpl.crashStat(:-1)
266: at com.
.naviauto.crashsdk.component.crashstat.CrashStatReportWorker.deliver(:-1)
267: at com..mapauto.datareport.workers.NetworkAwareReportWorker.deliver(:-1)
268: at com.
.mapauto.datareport.workers.BatchReportWorker.flush(:-1)
269: at com..mapauto.datareport.workers.BatchReportWorker.deliver(:-1)
270: - locked <0x01fc6410> (a byte[])
271: at com.
.mapauto.datareport.ReportDispatcher.processOne(:-1)
272: at com..mapauto.datareport.ReportDispatcher.run(:-1)
273: at com.
.mapauto.datareport.internal.AutoQuitScheduler$1.handleMessage(:-1)
274: at android.os.Handler.dispatchMessage(Handler.java:106)
275: at android.os.Looper.loopOnce(Looper.java:211)
276: at android.os.Looper.loop(Looper.java:300)
277: at android.os.HandlerThread.run(HandlerThread.java:67)
——————————————————————————————————
252: "report-deliver1" prio=5 tid=27 Runnable
253: | group="main" sCount=0 ucsCount=0 flags=0 obj=0x134484b8 self=0x7075bf5000
254: | sysTid=25194 nice=0 cgrp=default sched=0/0 handle=0x7069530cb0
255: | state=R schedstat=( 447877287 609653340 1692 ) utm=39 stm=5 core=5 HZ=100
256: | stack=0x706942d000-0x706942f000 stackSize=1039KB
257: | held mutexes= "mutator lock"(shared held)
258: at java.util.WeakHashMap.remove(WeakHashMap.java:592)
259: at android.database.sqlite.SQLiteConnectionPool.releaseConnection(SQLiteConnectionPool.java:406)
260: - locked <0x06e3f0ca> (a java.lang.Object)
261: at android.database.sqlite.SQLiteSession.releaseConnection(SQLiteSession.java:908)
262: at android.database.sqlite.SQLiteSession.executeForCursorWindow(SQLiteSession.java:842)
263: at android.database.sqlite.SQLiteQuery.fillWindow(SQLiteQuery.java:62)
264: at android.database.sqlite.SQLiteCursor.fillWindow(SQLiteCursor.java:145)
265: at android.database.sqlite.SQLiteCursor.getCount(SQLiteCursor.java:132)
266: at android.database.AbstractCursor.moveToPosition(AbstractCursor.java:238)
267: at android.database.AbstractCursor.moveToFirst(AbstractCursor.java:277)
268: at android.database.CursorWrapper.moveToFirst(CursorWrapper.java:75)
269: at com..mapauto.datareport.internal.db.abs.AbsDbTable.queryOne(:-1)
270: at com.
.mapauto.datareport.internal.db.reports.ReportTable.queryOne(:-1)
271: at com..mapauto.datareport.ReportQueue.poll(:-1)
272: - locked <0x08a7423b> (a byte[])
273: at com.
.mapauto.datareport.ReportDispatcher.processOne(:-1)
274: at com..mapauto.datareport.ReportDispatcher.run(:-1)
275: at com.
.mapauto.datareport.internal.AutoQuitScheduler$1.handleMessage(:-1)
276: at android.os.Handler.dispatchMessage(Handler.java:106)
277: at android.os.Looper.loopOnce(Looper.java:211)
278: at android.os.Looper.loop(Looper.java:300

——————————————————————————————————
252: "main" prio=5 tid=1 Runnable
253: | group="main" sCount=0 ucsCount=0 flags=0 obj=0x72a4c0c8 self=0xb400007198ee1c00
254: | sysTid=24473 nice=-10 cgrp=default sched=0/0 handle=0x719a5424f8
255: | state=R schedstat=( 48058135897 9963815570 60051 ) utm=4593 stm=212 core=5 HZ=100
256: | stack=0x7fceae5000-0x7fceae7000 stackSize=8188KB
257: | held mutexes= "mutator lock"(shared held)
258: at android.os.Message.recycleUnchecked(Message.java:342)
259: at android.os.Looper.loopOnce(Looper.java:262)
260: at android.os.Looper.loop(Looper.java:300)
261: at android.app.ActivityThread.main(ActivityThread.java:8250)
262: at java.lang.reflect.Method.invoke(Native method)
263: at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:556)
264: at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1049)

——————————————————
265: "xcrash_trace_dp" prio=10 tid=24 Runnable
266: | group="main" sCount=0 dsCount=0 flags=0 obj=0x12d83840 self=0xb4000071644a3800
267: | sysTid=8177 nice=-10 cgrp=default sched=0/0 handle=0x71056dbcc0
268: | state=R schedstat=( 59939746 10690725 83 ) utm=1 stm=4 core=7 HZ=100
269: | stack=0x71055e4000-0x71055e6000 stackSize=995KB
270: | held mutexes= "mutator lock"(shared held)
271: native: #00 pc 00000000004a0c68 /apex/com.android.art/lib64/libart.so (art::DumpNativeStack(std::__1::basic_ostream<char, std::__1::char_traits<char> >&, int, BacktraceMap*, char const*, art::ArtMethod*, void*, bool)+140)
272: native: #01 pc 00000000005ae000 /apex/com.android.art/lib64/libart.so (art::Thread::DumpStack(std::__1::basic_ostream<char, std::__1::char_traits<char> >&, bool, BacktraceMap*, bool) const+376)

上一篇下一篇

猜你喜欢

热点阅读