Does GC block IO operations?
130 views
Skip to first unread message
段启智
Nov 9, 2015, 7:35:21 PM11/9/15
to Android Linux Kernel Development
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:
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)
Reply all
Reply to author
Forward
0 new messages