*My case is watchdog kill system_server, because a thread held a lock monitor by watchdog and doing IO for more than 60s.* *I could find out system_server cost a lot of time(86.890s) by GC, would this block Posix.writeBytes()?*
*Partitial of log:The trace of system_server:* Cmd line: system_server ABI: arm64 Build type: optimized Zygote loaded classes=3699 post zygote classes=3243 Intern table: 57631 strong; 11578 weak JNI: CheckJNI is off; globals=3851 (plus 1142 weak) Libraries: /system/lib64/libImmVibeJ.so /system/lib64/libandroid.so /system/lib64/libandroid_servers.so /system/lib64/libaudioeffect_jni.so /system/lib64/libcompiler_rt.so /system/lib64/libjavacrypto.so /system/lib64/libjnigraphics.so /system/lib64/libmedia_jni.so /system/lib64/libmediatek_exceptionlog.so /system/lib64/libnativecheck-jni.so /system/lib64/librs_jni.so /system/lib64/libsoundpool.so /system/lib64/libwebviewchromium_loader.so /system/lib64/libwifi-service.so libjavacore.so (15) Heap: 2% free, 57MB/59MB; 500538 objects Dumping cumulative Gc timings Start Dumping histograms for 19 iterations for concurrent mark sweep ProcessMarkStack: Sum: 5.066s 99% C.I. 0.024ms-299.122ms Avg: 88.882ms Max: 299.122ms ScanGrayAllocSpaceObjects: Sum: 238.031ms 99% C.I. 0.014ms-22.274ms Avg: 6.263ms Max: 22.274ms SweepMallocSpace: Sum: 190.774ms 99% C.I. 0.072ms-19.068ms Avg: 5.020ms Max: 19.557ms MarkRootsCheckpoint: Sum: 124.074ms 99% C.I. 1.297ms-7.324ms Avg: 3.265ms Max: 7.325ms MarkConcurrentRoots: Sum: 102.340ms 99% C.I. 0.008ms-10.191ms Avg: 2.693ms Max: 10.615ms UpdateAndMarkImageModUnionTable: Sum: 88.087ms 99% C.I. 3.196ms-8.076ms Avg: 4.636ms Max: 8.188ms EnqueueFinalizerReferences: Sum: 52.468ms 99% C.I. 1.969ms-4.559ms Avg: 2.761ms Max: 4.606ms ReMarkRoots: Sum: 44.136ms 99% C.I. 1.631ms-3.831ms Avg: 2.322ms Max: 3.900ms MarkNonThreadRoots: Sum: 42.395ms 99% C.I. 0.471ms-6.925ms Avg: 1.115ms Max: 7.731ms (Paused)ScanGrayObjects: Sum: 37.901ms 99% C.I. 1.503ms-2.922ms Avg: 1.994ms Max: 2.922ms SweepSystemWeaks: Sum: 29.941ms 99% C.I. 1.016ms-1.965ms Avg: 1.575ms Max: 1.965ms MarkAllocStackAsLive: Sum: 25.792ms 99% C.I. 0.081ms-5.677ms Avg: 1.357ms Max: 5.987ms AllocSpaceClearCards: Sum: 19.284ms 99% C.I. 14us-910us Avg: 253.736us Max: 910us SweepLargeObjects: Sum: 12.291ms 99% C.I. 32us-2378us Avg: 646.894us Max: 2378us ProcessReferences: Sum: 10.008ms 99% C.I. 410us-818us Avg: 526.736us Max: 818us ImageModUnionClearCards: Sum: 9.686ms 99% C.I. 49us-5526.999us Avg: 254.894us Max: 6792us SweepZygoteSpace: Sum: 9.637ms 99% C.I. 348us-871.500us Avg: 507.210us Max: 881us FinishPhase: Sum: 9.499ms 99% C.I. 368us-573us Avg: 499.947us Max: 573us ZygoteModUnionClearCards: Sum: 7.144ms 99% C.I. 76us-2579.999us Avg: 188us Max: 3101us RevokeAllThreadLocalAllocationStacks: Sum: 3.399ms 99% C.I. 112us-340.500us Avg: 178.894us Max: 345us ScanGrayZygoteSpaceObjects: Sum: 2.302ms 99% C.I. 79us-165us Avg: 121.157us Max: 165us ScanGrayImageSpaceObjects: Sum: 1.883ms 99% C.I. 56us-160us Avg: 99.105us Max: 160us MarkingPhase: Sum: 1.395ms 99% C.I. 14us-1000.250us Avg: 73.421us Max: 1069us PreCleanCards: Sum: 580us 99% C.I. 16us-97us Avg: 30.526us Max: 97us ProcessCards: Sum: 418us 99% C.I. 6us-16us Avg: 11us Max: 16us ReclaimPhase: Sum: 416us 99% C.I. 10us-51us Avg: 21.894us Max: 51us (Paused)PausePhase: Sum: 381us 99% C.I. 16us-23us Avg: 20.052us Max: 23us SwapBitmaps: Sum: 373us 99% C.I. 13us-30us Avg: 19.631us Max: 30us Sweep: Sum: 325us 99% C.I. 12us-38us Avg: 17.105us Max: 38us MarkRoots: Sum: 169us 99% C.I. 6us-11us Avg: 8.894us Max: 11us RecursiveMark: Sum: 91us 99% C.I. 3us-6us Avg: 4.789us Max: 6us BindBitmaps: Sum: 75us 99% C.I. 2us-5us Avg: 3.947us Max: 5us SwapStacks: Sum: 72us 99% C.I. 3us-5us Avg: 3.789us Max: 5us InitializePhase: Sum: 65us 99% C.I. 2us-4us Avg: 3.421us Max: 4us (Paused)ProcessMarkStack: Sum: 37us 99% C.I. 1us-3us Avg: 1.947us Max: 3us UnBindBitmaps: Sum: 32us 99% C.I. 1us-3us Avg: 1.684us Max: 3us FindDefaultSpaceBitmap: Sum: 19us 99% C.I. 0.250us-2us Avg: 1us Max: 2us PreSweepingGcVerification: Sum: 16us 99% C.I. 250ns-1000ns Avg: 842ns Max: 1000ns Done Dumping histograms concurrent mark sweep paused: Sum: 87.484ms 99% C.I. 3.472ms-5.732ms Avg: 4.604ms Max: 5.732ms concurrent mark sweep total time: 6.131s mean time: 322.729ms concurrent mark sweep freed: 571499 objects with total size 61MB concurrent mark sweep throughput: 93214.6/s / 10MB/s Start Dumping histograms for 133 iterations for partial concurrent mark sweep ProcessMarkStack: Sum: 40.768s 99% C.I. 0.096ms-512.511ms Avg: 102.176ms Max: 666.921ms ScanGrayAllocSpaceObjects: Sum: 2.707s 99% C.I. 0.014ms-49.376ms Avg: 10.177ms Max: 65.996ms MarkRootsCheckpoint: Sum: 1.865s 99% C.I. 1.314ms-34.176ms Avg: 7.014ms Max: 805.413ms SweepMallocSpace: Sum: 1.307s 99% C.I. 0.075ms-25.340ms Avg: 4.915ms Max: 33.941ms MarkConcurrentRoots: Sum: 777.416ms 99% C.I. 0.007ms-17.868ms Avg: 2.922ms Max: 30.135ms UpdateAndMarkImageModUnionTable: Sum: 659.564ms 99% C.I. 2.427ms-24.008ms Avg: 4.959ms Max: 26.974ms EnqueueFinalizerReferences: Sum: 613.534ms 99% C.I. 2.444ms-11.143ms Avg: 4.613ms Max: 14.900ms ReMarkRoots: Sum: 403.843ms 99% C.I. 1.594ms-18.667ms Avg: 3.036ms Max: 18.737ms (Paused)ScanGrayObjects: Sum: 322.604ms 99% C.I. 1.038ms-5.400ms Avg: 2.425ms Max: 5.534ms MarkNonThreadRoots: Sum: 296.540ms 99% C.I. 0.488ms-6.701ms Avg: 1.114ms Max: 8.622ms SweepSystemWeaks: Sum: 244.284ms 99% C.I. 0.979ms-6.333ms Avg: 1.836ms Max: 6.397ms UpdateAndMarkZygoteModUnionTable: Sum: 204.868ms 99% C.I. 0.970ms-7.409ms Avg: 1.540ms Max: 10.994ms SweepLargeObjects: Sum: 192.088ms 99% C.I. 0.033ms-11.204ms Avg: 1.444ms Max: 12.628ms AllocSpaceClearCards: Sum: 138.149ms 99% C.I. 14us-2937.999us Avg: 259.678us Max: 7735us ProcessReferences: Sum: 90.434ms 99% C.I. 411us-2833.500us Avg: 679.954us Max: 2888us MarkAllocStackAsLive: Sum: 80.570ms 99% C.I. 113us-2885.250us Avg: 605.789us Max: 3612us FinishPhase: Sum: 66.799ms 99% C.I. 310us-3209us Avg: 502.248us Max: 6758us ZygoteModUnionClearCards: Sum: 34.788ms 99% C.I. 75us-484us Avg: 130.781us Max: 2711us ImageModUnionClearCards: Sum: 26.520ms 99% C.I. 50.071us-983.500us Avg: 99.699us Max: 2089us RevokeAllThreadLocalAllocationStacks: Sum: 25.044ms 99% C.I. 120us-467.250us Avg: 188.300us Max: 664us ScanGrayZygoteSpaceObjects: Sum: 16.742ms 99% C.I. 84us-333.500us Avg: 125.879us Max: 395us ScanGrayImageSpaceObjects: Sum: 14.525ms 99% C.I. 60us-178us Avg: 109.210us Max: 178us MarkingPhase: Sum: 4.293ms 99% C.I. 19us-317.750us Avg: 32.278us Max: 709us (Paused)PausePhase: Sum: 4.132ms 99% C.I. 17us-485.250us Avg: 31.067us Max: 1200us PreCleanCards: Sum: 3.596ms 99% C.I. 20us-83.500us Avg: 27.037us Max: 100us ReclaimPhase: Sum: 3.546ms 99% C.I. 12us-166.749us Avg: 26.661us Max: 196us ProcessCards: Sum: 3.308ms 99% C.I. 6us-133.500us Avg: 12.436us Max: 157us SwapBitmaps: Sum: 2.393ms 99% C.I. 11us-53us Avg: 17.992us Max: 53us Sweep: Sum: 2.019ms 99% C.I. 11us-22us Avg: 15.180us Max: 22us MarkRoots: Sum: 1.468ms 99% C.I. 7us-161us Avg: 11.037us Max: 161us RecursiveMark: Sum: 963us 99% C.I. 3us-167.250us Avg: 7.240us Max: 354us BindBitmaps: Sum: 641us 99% C.I. 2us-83.500us Avg: 4.819us Max: 133us SwapStacks: Sum: 518us 99% C.I. 2us-7us Avg: 3.894us Max: 7us InitializePhase: Sum: 475us 99% C.I. 2us-5us Avg: 3.571us Max: 5us UnBindBitmaps: Sum: 351us 99% C.I. 1us-8us Avg: 2.639us Max: 8us (Paused)ProcessMarkStack: Sum: 278us 99% C.I. 1us-4us Avg: 2.090us Max: 4us SweepZygoteSpace: Sum: 224us 99% C.I. 1us-3us Avg: 1.684us Max: 3us FindDefaultSpaceBitmap: Sum: 214us 99% C.I. 0.251us-66.750us Avg: 1.609us Max: 92us PreSweepingGcVerification: Sum: 131us 99% C.I. 250ns-3000ns Avg: 984ns Max: 3000ns Done Dumping histograms partial concurrent mark sweep paused: Sum: 815.760ms 99% C.I. 3.264ms-40.040ms Avg: 6.133ms Max: 49.298ms partial concurrent mark sweep total time: 50.885s mean time: 382.600ms partial concurrent mark sweep freed: 3203387 objects with total size 578MB partial concurrent mark sweep throughput: 62953.5/s / 11MB/s Start Dumping histograms for 468 iterations for sticky concurrent mark sweep ScanGrayAllocSpaceObjects: Sum: 10.030s 99% C.I. 0.014ms-58.623ms Avg: 5.358ms Max: 83.912ms FreeList: Sum: 4.602s 99% C.I. 4us-4118.799us Avg: 345.960us Max: 20313us MarkRootsCheckpoint: Sum: 3.807s 99% C.I. 1.281ms-30.111ms Avg: 4.068ms Max: 46.503ms MarkConcurrentRoots: Sum: 2.852s 99% C.I. 0.026ms-26.623ms Avg: 3.047ms Max: 303.745ms ReMarkRoots: Sum: 1.592s 99% C.I. 1.500ms-22.911ms Avg: 3.402ms Max: 103.434ms ProcessMarkStack: Sum: 1.486s 99% C.I. 5.418us-9285.333us Avg: 794.097us Max: 58529us (Paused)ScanGrayObjects: Sum: 1.059s 99% C.I. 0.845ms-12.119ms Avg: 2.263ms Max: 20.136ms SweepArray: Sum: 983.136ms 99% C.I. 0.042ms-11.251ms Avg: 2.100ms Max: 15.054ms MarkNonThreadRoots: Sum: 899.216ms 99% C.I. 402.437us-7927.999us Avg: 960.700us Max: 13934us SweepSystemWeaks: Sum: 891.560ms 99% C.I. 1.032ms-14.119ms Avg: 1.905ms Max: 20.655ms AllocSpaceClearCards: Sum: 545.103ms 99% C.I. 13us-2527.999us Avg: 291.187us Max: 10707us EnqueueFinalizerReferences: Sum: 204.879ms 99% C.I. 4us-7443.999us Avg: 437.775us Max: 10181us MarkingPhase: Sum: 144.317ms 99% C.I. 174us-1331.999us Avg: 308.369us Max: 5622us ScanGrayZygoteSpaceObjects: Sum: 139.400ms 99% C.I. 73us-1195.999us Avg: 148.931us Max: 9855us ScanGrayImageSpaceObjects: Sum: 130.032ms 99% C.I. 43us-1865.999us Avg: 138.923us Max: 15480us ZygoteModUnionClearCards: Sum: 122.566ms 99% C.I. 72us-1165.999us Avg: 130.946us Max: 4250us ImageModUnionClearCards: Sum: 89.082ms 99% C.I. 42us-1031.999us Avg: 95.173us Max: 5326us RevokeAllThreadLocalAllocationStacks: Sum: 83.745ms 99% C.I. 109us-832.999us Avg: 178.942us Max: 2146us ResetStack: Sum: 63.575ms 99% C.I. 19us-1965.999us Avg: 135.844us Max: 6405us FinishPhase: Sum: 34.132ms 99% C.I. 30us-365.999us Avg: 72.931us Max: 545us PreCleanCards: Sum: 29.849ms 99% C.I. 14us-199.854us Avg: 63.779us Max: 18114us ProcessCards: Sum: 20.092ms 99% C.I. 6us-99.819us Avg: 21.465us Max: 9294us ReclaimPhase: Sum: 18.332ms 99% C.I. 9us-846.999us Avg: 39.170us Max: 4677us (Paused)PausePhase: Sum: 10.263ms 99% C.I. 14us-141.499us Avg: 21.929us Max: 342us ProcessReferences: Sum: 8.550ms 99% C.I. 4us-182.999us Avg: 18.269us Max: 751us MarkRoots: Sum: 5.992ms 99% C.I. 5us-116.499us Avg: 12.803us Max: 1593us SwapBitmaps: Sum: 3.033ms 99% C.I. 4us-49.963us Avg: 6.480us Max: 59us BindBitmaps: Sum: 2.574ms 99% C.I. 2us-49.856us Avg: 5.500us Max: 816us InitializePhase: Sum: 2.397ms 99% C.I. 2us-49.856us Avg: 5.121us Max: 626us ForwardSoftReferences: Sum: 2.129ms 99% C.I. 2us-82.999us Avg: 4.549us Max: 338us SwapStacks: Sum: 2.042ms 99% C.I. 2us-49.856us Avg: 4.363us Max: 375us UnBindBitmaps: Sum: 1.764ms 99% C.I. 2us-49.856us Avg: 3.769us Max: 177us RecordFree: Sum: 967us 99% C.I. 1us-6us Avg: 2.066us Max: 6us (Paused)ProcessMarkStack: Sum: 884us 99% C.I. 1us-6us Avg: 1.888us Max: 6us FindDefaultSpaceBitmap: Sum: 807us 99% C.I. 1us-5us Avg: 1.724us Max: 5us PreSweepingGcVerification: Sum: 491us 99% C.I. 0.251us-49.963us Avg: 1.049us Max: 72us Done Dumping histograms sticky concurrent mark sweep paused: Sum: 2.845s 99% C.I. 2.728ms-27.319ms Avg: 6.080ms Max: 109.938ms sticky concurrent mark sweep total time: 29.872s mean time: 63.829ms sticky concurrent mark sweep freed: 13180490 objects with total size 764MB sticky concurrent mark sweep throughput: 441232/s / 25MB/s Total time spent in GC: 86.890s Mean GC size throughput: 86MB/s Mean GC object throughput: 1.59653e+06 objects/s Total number of allocations 139223040 Total bytes allocated 7GB Free memory 1500KB Free memory until GC 1500KB Free memory until OOME 454MB Total memory 59MB Max memory 512MB Total mutator paused time: 3.749s Total time waiting for GC to complete: 8.909s *You could see that total time spent in GC is 86.890s, over than 60s.* *android.fg is blocked and lead to watchdog kill system_server, in that wait to lock held by thread 91* "android.fg" prio=5 tid=25 Blocked | group="main" sCount=1 dsCount=0 obj=0x12eef900 self=0x7f7a8b1000 | sysTid=973 nice=0 cgrp=default sched=0/0 handle=0x7f644e9000 | state=S schedstat=( 3181688530 2206454929 8991 ) utm=251 stm=67 core=1 HZ=100 | stack=0x7f643e7000-0x7f643e9000 stackSize=1036KB | held mutexes= at com.android.server.wm.WindowManagerService.monitor(WindowManagerService.java:13125) - waiting to lock <0x126dccb8> (a java.util.HashMap) held by thread 91 at com.android.server.Watchdog$HandlerChecker.run(Watchdog.java:204) at android.os.Handler.handleCallback(Handler.java:815) at android.os.Handler.dispatchMessage(Handler.java:104) at android.os.Looper.loop(Looper.java:194) at android.os.HandlerThread.run(HandlerThread.java:61) at com.android.server.ServiceThread.run(ServiceThread.java:46) *The following are traces of thread 91, it blocked at pipe_wait for more than 60s.* "Binder_C" prio=5 tid=91 Native | group="main" sCount=1 dsCount=0 obj=0x12e540a0 self=0x7f63289000 | sysTid=1736 nice=0 cgrp=default sched=0/0 handle=0x7f6127c000 | state=S schedstat=( 96931835222 49673449591 260122 ) utm=7046 stm=2647 core=2 HZ=100 | stack=0x7f5ffbc000-0x7f5ffbe000 stackSize=1008KB | held mutexes= kernel: __switch_to+0x74/0x8c kernel: pipe_wait+0x60/0x9c kernel: pipe_write+0x278/0x5cc kernel: do_sync_write+0x90/0xcc kernel: vfs_write+0xa4/0x194 kernel: SyS_write+0x40/0x8c kernel: cpu_switch_to+0x48/0x4c at libcore.io.Posix.writeBytes(Native method) at libcore.io.Posix.write(Posix.java:258) at libcore.io.BlockGuardOs.write(BlockGuardOs.java:313) at libcore.io.IoBridge.write(IoBridge.java:537) at java.io.FileOutputStream.write(FileOutputStream.java:186) at com.android.internal.util.FastPrintWriter.flushBytesLocked(FastPrintWriter.java:334) at com.android.internal.util.FastPrintWriter.flushLocked(FastPrintWriter.java:355) at com.android.internal.util.FastPrintWriter.appendLocked(FastPrintWriter.java:303) at com.android.internal.util.FastPrintWriter.print(FastPrintWriter.java:466) - locked <@addr=0x134c4910> (a com.android.internal.util.FastPrintWriter$DummyWriter) at com.android.server.wm.WindowState.dump(WindowState.java:1510) at com.android.server.wm.WindowManagerService.dumpWindowsNoHeaderLocked(WindowManagerService.java:12279) at com.android.server.wm.WindowManagerService.dumpWindowsLocked(WindowManagerService.java:12266) at com.android.server.wm.WindowManagerService.dump(WindowManagerService.java:12654) - locked <0x126dccb8> (a java.util.HashMap) at android.os.Binder.dump(Binder.java:324) at android.os.Binder.onTransact(Binder.java:290) at android.view.IWindowManager$Stub.onTransact(IWindowManager.java:933) at com.android.server.wm.WindowManagerService.onTransact(WindowManagerService.java:1244) at android.os.Binder.execTransact(Binder.java:451) -- -- unsubscribe: [email protected] website: http://groups.google.com/group/android-kernel --- You received this message because you are subscribed to the Google Groups "Android Linux Kernel Development" group. To unsubscribe from this group and stop receiving emails from it, send an email to [email protected]. For more options, visit https://groups.google.com/d/optout.
