美文网首页
ANR研究开启|ANR trace中的mutator lock是

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

作者: 蚍蜉一生 | 来源:发表于2024-05-21 17:52 被阅读0次

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

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

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

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

    • 共享持有(shared held)指多个非GC线程在执行内存一致性的操作时,可以共同持有 mutator lock,它们之间没有互斥和影响,这时候这些线程一般处于运行时(Runnable);
    • 独占持有(exclusive held)指GC线程在关键阶段需要独占 mutator lock,以确保垃圾回收期间内存的一致性,当GC线程独占mutator lock 时候,共享持有 mutator lock的所有线程会被暂停(suspend),想申请mutator lock的线程也会被阻塞,直到GC线程释放独占mutator lock。

        所以我们可认为:共享持有(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)

    相关文章

      网友评论

          本文标题:ANR研究开启|ANR trace中的mutator lock是

          本文链接:https://www.haomeiwen.com/subject/dryafjtx.html