Android 8.0频现GC crash

问题现象

  • 复现步骤
    • 手机(Android 8.0, build id为opr6.170623.013)
    • 复现场景一: app crash
      • 选择一个大的txt文档,如:228k.txt
      • 用html方式打开
      • 打开后长按内容,点击全选,后点击分享到信息
      • 选择号码后等待
      • com.android.messaging进程几乎必现native crash
    • 复现场景二: system_server crash
      • 执行MSR压力测试
      • system_server高概率出现native crash

定位分析

  • 相关log
    • tombstone
      ABI: 'arm' 
      pid: 24785, tid: 24795, name: HeapTaskDaemon  >>> system_server <<<
      signal 6 (SIGABRT), code -6 (SI_TKILL), fault addr --------
      Abort message: 'utils.cc:123] 12c00000-52c00000 rw-p 00000000 00:05 3180718    /dev/ashmem/dalvik-main space (region space) (deleted)'
          r0 00000000  r1 000060db  r2 00000006  r3 00000008
          r4 000060d1  r5 000060db  r6 9bbc11d0  r7 0000010c
          r8 0000000b  r9 9bbc1231  sl 0000000a  fp 9bbc1230
          ip 00000000  sp 9bbc11c0  lr b4fee417  pc b501e97c  cpsr 200f0010
          d0  2e656d69746e7572  d1  3031306666646631
          d2  3135373066383036  d3  6f5f646c65696638
          d4  6636633537373864  d5  6636633535373839
          d6  6636633538373837  d7  363533613338317c
          d8  0000000000000000  d9  0000000000000000
          d10 0000000000000000  d11 0000000000000000
          d12 0000000000000000  d13 0000000000000000
          d14 0000000000000000  d15 0000000000000000
          d16 2e74736973726570  d17 2e6761742e676f6c
          d18 00000000c3394019  d19 000000005c000000
          d20 0000000000000000  d21 000000000000005c
          d22 0000000400000004  d23 0000000400000004
          d24 000022c1000002c1  d25 000062c1000042c1
          d26 000022c0000002c0  d27 000062c0000042c0
          d28 720410f8720410f0  d29 7204110872041100
          d30 0000001806897c20  d31 7204110872041100
          scr 20000013
      backtrace:
          #00 pc 0004a97c  /system/lib/libc.so (tgkill+12)
          #01 pc 0001a413  /system/lib/libc.so (abort+54)
          #02 pc 003385df  /system/lib/libart.so (_ZN3art7Runtime5AbortEPKc+230)
          #03 pc 00338c6f  /system/lib/libart.so (_ZN3art7Runtime7AborterEPKc+10)
          #04 pc 003efacd  /system/lib/libart.so (_ZN7android4base10LogMessageD1Ev+456)
          #05 pc 001c1c3f  /system/lib/libart.so (_ZNK3art2gc12Verification17LogHeapCorruptionENS_6ObjPtrINS_6mirror6ObjectEEENS_12MemberOffsetEPS4_b+926)
          #06 pc 001769fb  /system/lib/libart.so (_ZN3art2gc9collector17ConcurrentCopying13MarkNonMovingEPNS_6mirror6ObjectES5_NS_12MemberOffsetE+290)
          #07 pc 00178097  /system/lib/libart.so (_ZN3art6mirror6Object15VisitReferencesILb1ELNS_17VerifyObjectFlagsE0ELNS_17ReadBarrierOptionE1ENS_2gc9collector17ConcurrentCopying16RefFieldsVisitorES8_EEvRKT2_RKT3_+218)
          #08 pc 00173537  /system/lib/libart.so (_ZN3art2gc9collector17ConcurrentCopying19ProcessMarkStackRefEPNS_6mirror6ObjectE+98)
          #09 pc 00173077  /system/lib/libart.so (_ZN3art2gc9collector17ConcurrentCopying20ProcessMarkStackOnceEv+402)
          #10 pc 00172ed7  /system/lib/libart.so (_ZN3art2gc9collector17ConcurrentCopying16ProcessMarkStackEv+18)
          #11 pc 0016e695  /system/lib/libart.so (_ZN3art2gc9collector17ConcurrentCopying12MarkingPhaseEv+456)
          #12 pc 0016dc75  /system/lib/libart.so (_ZN3art2gc9collector17ConcurrentCopying9RunPhasesEv+540)
          #13 pc 0017ccc5  /system/lib/libart.so (_ZN3art2gc9collector16GarbageCollector3RunENS0_7GcCauseEb+268)
          #14 pc 00197adf  /system/lib/libart.so (_ZN3art2gc4Heap22CollectGarbageInternalENS0_9collector6GcTypeENS0_7GcCauseEb+2726)
          #15 pc 001a2f2f  /system/lib/libart.so (_ZN3art2gc4Heap12ConcurrentGCEPNS_6ThreadENS0_7GcCauseEb+70)
          #16 pc 001a8949  /system/lib/libart.so (_ZN3art2gc4Heap16ConcurrentGCTask3RunEPNS_6ThreadE+20)
          #17 pc 001c147b  /system/lib/libart.so (_ZN3art2gc13TaskProcessor11RunAllTasksEPNS_6ThreadE+30)
          #18 pc 7049a4cb  /data/dalvik-cache/arm/system@framework@boot.oat (offset 0x9a3000)
      

初步分析

  • gdb 堆栈

    (gdb) bt
    #0  tgkill () at bionic/libc/arch-arm/syscalls/tgkill.S:10
    #1  0xb4fee416 in abort () at bionic/libc/bionic/abort.cpp:49
    #2  0xb206e5e2 in art::Runtime::Abort (msg=<optimized out>) at art/runtime/runtime.cc:523
    #3  0xb206ec72 in art::Runtime::Aborter (abort_message=0x979bd380 "GC tried to mark invalid reference 0x17\nref=0x17 <invalid address>\nholder=0x13780000 klass=0x6f353a18(java.lang.Class<java.lang.Object[]>) length=131069 space=main space (region space) 0x12c00000-0x52"...) at art/runtime/runtime.cc:2333
    #4  0xb2125ace in std::__1::function<void (char const*)>::operator()(char const*) const (this=<optimized out>, __arg=0x979bd380 "GC tried to mark invalid reference 0x17\nref=0x17 <invalid address>\nholder=0x13780000 klass=0x6f353a18(java.lang.Class<java.lang.Object[]>) length=131069 space=main space (region space) 0x12c00000-0x52"...) at external/libcxx/include/functional:1915
    #5  android::base::LogMessage::~LogMessage (this=0x9bbc1288) at system/core/base/logging.cpp:433
    #6  0xb1ef7c42 in art::gc::Verification::LogHeapCorruption (this=<optimized out>, holder=..., offset=..., ref=0x17, fatal=<optimized out>) at external/libcxx/include/new:235
    #7  0xb1eac9fe in art::gc::collector::ConcurrentCopying::MarkNonMoving (this=0xb22c3700, ref=0x17, holder=0x13780000, offset=...) at art/runtime/gc/collector/concurrent_copying.cc:2435
    #8  0xb1eae09a in art::gc::collector::ConcurrentCopying::RefFieldsVisitor::operator() (this=<optimized out>, obj=0x13780000, offset=...) at art/runtime/gc/collector/concurrent_copying.cc:1911
    #9  art::mirror::ObjectArray<art::mirror::Object>::VisitReferences<art::gc::collector::ConcurrentCopying::RefFieldsVisitor> (visitor=..., this=<optimized out>) at art/runtime/mirror/object_array-inl.h:373
    #10 art::mirror::Object::VisitReferences<true, (art::VerifyObjectFlags)0, (art::ReadBarrierOption)1, art::gc::collector::ConcurrentCopying::RefFieldsVisitor, art::gc::collector::ConcurrentCopying::RefFieldsVisitor> (this=0x13780000, visitor=..., ref_visitor=...) at art/runtime/mirror/object-refvisitor-inl.h:54
    #11 0xb1ea953a in art::gc::collector::ConcurrentCopying::Scan (to_ref=0x13780000, this=<optimized out>) at art/runtime/gc/collector/concurrent_copying.cc:1950
    #12 art::gc::collector::ConcurrentCopying::ProcessMarkStackRef (this=0xb22c3700, to_ref=0x13780000) at art/runtime/gc/collector/concurrent_copying.cc:1446
    #13 0xb1ea907a in art::gc::collector::ConcurrentCopying::ProcessMarkStackOnce (this=0xb22c3700) at art/runtime/gc/collector/concurrent_copying.cc:1347
    #14 0xb1ea8eda in art::gc::collector::ConcurrentCopying::ProcessMarkStack (this=0xb22c3700) at art/runtime/gc/collector/concurrent_copying.cc:1326
    #15 0xb1ea4696 in art::gc::collector::ConcurrentCopying::MarkingPhase (this=0xb22c3700) at art/runtime/gc/collector/concurrent_copying.cc:756
    #16 0xb1ea3c78 in art::gc::collector::ConcurrentCopying::RunPhases (this=0xb22c3700) at art/runtime/gc/collector/concurrent_copying.cc:169
    #17 0xb1eb2cc6 in art::gc::collector::GarbageCollector::Run (this=<optimized out>, gc_cause=art::gc::kGcCauseBackground, clear_soft_references=<optimized out>) at art/runtime/gc/collector/garbage_collector.cc:95
    #18 0xb1ecdae2 in art::gc::Heap::CollectGarbageInternal (this=0xb22fd400, gc_type=<optimized out>, gc_cause=art::gc::kGcCauseBackground, clear_soft_references=<optimized out>) at art/runtime/gc/heap.cc:2748
    #19 0xb1ed8f32 in art::gc::Heap::ConcurrentGC (this=0xb22fd400, self=<optimized out>, cause=art::gc::kGcCauseBackground, force_full=<optimized out>) at art/runtime/gc/heap.cc:3752
    #20 0xb1ede94c in art::gc::Heap::ConcurrentGCTask::Run (this=<optimized out>, self=0x60db) at art/runtime/gc/heap.cc:3713
    #21 0xb1ef747c in art::gc::TaskProcessor::RunAllTasks (this=0xb221eb80, self=0xaac57200) at art/runtime/gc/task_processor.cc:124
    #22 0x7049a4cc in ?? ()
    
  • log分析

    #3报出的abort_message完整log为
    (gdb) p (char *)0x979bd380 
    $1 = 0x979bd380 "GC tried to mark invalid reference 0x17\nref=0x17 <invalid address>\nholder=0x13780000 klass=0x6f353a18(java.lang.Class<java.lang.Object[]>) length=131069 space=main space (region space) 0x12c00000-0x52c00000 card=0 adjacent_ram=58775c6fd8775c6f98755c6f78785c6f|183a356f00000010fdff010008f07513field_offset=262168\n"
    
    
  • 查看当前obj=0x17

    (gdb) x /4xw 0x13780000+262168
    0x137c0018:   0x00000017  0x00300032  0x00200030  0x00200035
    

对比实验

  • Nexus 6p无法复现
  • 通过添加log, 发现没有走GC操作

深入分析

  • 查看obj相关的region[]

    ... ...
    $49 = {
      idx_ = 46,  
      begin_ = 0x13780000 "\030:5o", 
      top_ = {
      <std::__1::atomic<unsigned char*>> = {
        <std::__1::__atomic_base<unsigned char*, false>> = {
          __a_ = 0x137e0008 ""
        }, <No data fields>}, <No data fields>}, 
      end_ = 0x137c0000 "\260\207(o", 
      state_ = art::gc::space::RegionSpace::RegionState::kRegionStateLarge, 
      type_ = art::gc::space::RegionSpace::RegionType::kRegionTypeUnevacFromSpace, 
      objects_allocated_ = {
      <std::__1::atomic<unsigned int>> = {
        <std::__1::__atomic_base<unsigned int, true>> = {
          <std::__1::__atomic_base<unsigned int, false>> = {
            __a_ = 0
          }, <No data fields>}, <No data fields>}, <No data fields>}, 
      alloc_time_ = 13,  
      live_bytes_ = 0, 
      is_newly_allocated_ = false, 
      is_a_tlab_ = false, 
      thread_ = 0x0
    }
    
    $50 = {
      idx_ = 47,  
      begin_ = 0x137c0000 "\260\207(o", 
      top_ = {
      <std::__1::atomic<unsigned char*>> = {
        <std::__1::__atomic_base<unsigned char*, false>> = {
          __a_ = 0x137c4000 ""
        }, <No data fields>}, <No data fields>}, 
      end_ = 0x13800000 "\260\207(o", 
      state_ = art::gc::space::RegionSpace::RegionState::kRegionStateAllocated, 
      type_ = art::gc::space::RegionSpace::RegionType::kRegionTypeUnevacFromSpace, 
      objects_allocated_ = {
      <std::__1::atomic<unsigned int>> = {
        <std::__1::__atomic_base<unsigned int, true>> = {
          <std::__1::__atomic_base<unsigned int, false>> = {
            __a_ = 191
          }, <No data fields>}, <No data fields>}, <No data fields>},
      alloc_time_ = 14,
      live_bytes_ = 0,
      is_newly_allocated_ = true,
      is_a_tlab_ = false,
      thread_ = 0x0
    }
    ... ...
    

    可看到,

    • regions_[46]和regions_[47]原本是一个large object, regions_[46]的top_已指向regions_[47],
    • regions_[47]当前的状态为art::gc::space::RegionSpace::RegionState::kRegionStateAllocated, 表示已分配出去,理论上来讲应该是art::gc::space::RegionSpace::RegionState::kRegionStateLargeTail
    • regions_[46]的alloc_time是13, regions_[47]的alloc_time是14, 说明regions_[47]后续在使用过程中又被分配出去了.
  • 网络求助

  • Goolge ART求助

    向Google ART的Nicolas Geoffray发一封求助邮件,描述复现和分析详情,很快收到回复(12分钟).

    Nicolas说此问题已解决,并提供了解决方案的链接.

    Hi Tim,
    
    The change you're looking for is:
    https://android-review.googlesource.com/#/c/platform/art/+/430379/
    
    Thanks for your links. And sorry you got hit by the bug.
    

    同时,Nicolas又更新了https://issuetracker.google.com/issues/65268761

    ng...@google.com  <ng...@google.com>  #4 Sep 6, 2017 04:58PM
    
    The change in AOSP that fixed this is:
    https://android-review.googlesource.com/#/c/platform/art/+/430379/
    
    Unfortunately, it's not known yet when the fix will be available.
    

解决方案

    原文作者:younghuster
    原文地址: https://www.jianshu.com/p/ce3478d296d9
    本文转自网络文章,转载此文章仅为分享知识,如有侵权,请联系博主进行删除。
点赞