1
Vote

PerfMonitor GCTime Bug?

description

The calculation of GCTime has maybe a bug.
 
Sample:
 
PerfMonitorOutput.print.xml
<Event MSec= "1330.0184" PID="3376" PName= "Test" TID="2248" EventName="GCSuspendEEStart" Reason="SuspendForGC" Count="5" ClrInstanceID="13"/>
<Event MSec= "1330.0305" PID="3376" PName= "Test" TID="2248" EventName="GCSuspendEEStop" ClrInstanceID="13"/>
<Event MSec= "1330.0823" PID="3376" PName= "Test" TID="2248" EventName="GCStart" Count="6" Reason="AllocSmall" Depth="2" Type="BackgroundGC" ClrInstanceID="13"/>
<Event MSec= "1330.4250" PID="3376" PName= "Test" TID="2248" EventName="GCCreateConcurrentThread" ClrInstanceID="13"/>
<Event MSec= "1330.4278" PID="3376" PName= "Test" TID="2248" EventName="GCStart" Count="7" Reason="AllocSmall" Depth="0" Type="NonConcurrentGC" ClrInstanceID="13"/>
<Event MSec= "1336.2908" PID="3376" PName= "Test" TID="2248" EventName="GCStop" Count="7" Depth="0" ClrInstanceID="13"/>
<Event MSec= "1336.2946" PID="3376" PName= "Test" TID="2248" EventName="GCHeapStats" GenerationSize0="0x0000000C" TotalPromotedSize0="0x00279640" GenerationSize1="0x004AE2DC" TotalPromotedSize1="0x00000000" GenerationSize2="0x0065CD58" TotalPromotedSize2="0x00000000" GenerationSize3="0x000E42A0" TotalPromotedSize3="0x00000000" FinalizationPromotedSize="0x00000000" FinalizationPromotedCount="0" PinnedObjectCount="0" SinkBlockCount="1" GCHandleCount="22" ClrInstanceID="13"/>
<Event MSec= "1336.7422" PID="3376" PName= "Test" TID="2248" EventName="GCRestartEEStart" ClrInstanceID="13"/>
<Event MSec= "1336.7486" PID="3376" PName= "Test" TID="2248" EventName="GCRestartEEStop" ClrInstanceID="13"/>
<Event MSec= "1337.2008" PID="3376" PName= "Test" TID="2248" EventName="GCAllocationTick" AllocationAmount="0x0001A000" AllocationKind="Small" ClrInstanceID="13"/>
<Event MSec= "1341.1286" PID="3376" PName= "Test" TID="3516" EventName="GCSuspendEEStart" Reason="SuspendForGCPrep" Count="6" ClrInstanceID="13"/>
<Event MSec= "1341.1390" PID="3376" PName= "Test" TID="3516" EventName="GCSuspendEEStop" ClrInstanceID="13"/>
<Event MSec= "1341.5382" PID="3376" PName= "Test" TID="3516" EventName="GCRestartEEStart" ClrInstanceID="13"/>
<Event MSec= "1341.5427" PID="3376" PName= "Test" TID="3516" EventName="GCRestartEEStop" ClrInstanceID="13"/>
<Event MSec= "1344.5415" PID="3376" PName= "Test" TID="2248" EventName="GCAllocationTick" AllocationAmount="0x0001A000" AllocationKind="Small" ClrInstanceID="13"/>
<Event MSec= "1346.8216" PID="3376" PName= "Test" TID="3516" EventName="GCStop" Count="6" Depth="2" ClrInstanceID="13"/>
<Event MSec= "1346.8282" PID="3376" PName= "Test" TID="3516" EventName="GCHeapStats" GenerationSize0="0x00115FEC" TotalPromotedSize0="0x00279640" GenerationSize1="0x004AE2DC" TotalPromotedSize1="0x00268CB0" GenerationSize2="0x0065CD58" TotalPromotedSize2="0x0065CC88" GenerationSize3="0x000E4290" TotalPromotedSize3="0x00084210" FinalizationPromotedSize="0x00000000" FinalizationPromotedCount="0" PinnedObjectCount="0" SinkBlockCount="1" GCHandleCount="22" ClrInstanceID="13"/>
 
PerfMonitorOutput.GCTime.xml
<GCEvent PauseStartRelMSec="1330.018" PauseDurationMSec= "6.730" SizeBeforeMB= "16.200" SizeAfterMB= "12.514" SizeReclaimed= "3.686" RatioBeforeAfter="1.295" GCNumber= "6" GCGeneration="2" GCDurationMSec= "16.739" SuspendDurationMSec= "6.730" GCStartRelMSec="1330.082" Type= "BackgroundGC" Reason= "AllocSmall"/>
PauseDurationMSec= "6.730"
SuspendDurationMSec= "6.730"
<GCEvent PauseStartRelMSec="1330.018" PauseDurationMSec= "6.730" SizeBeforeMB= "16.200" SizeAfterMB= "12.514" SizeReclaimed= "3.686" RatioBeforeAfter="1.295" GCNumber= "7" GCGeneration="0" GCDurationMSec= "5.864" SuspendDurationMSec= "0.866" GCStartRelMSec="1330.428" Type= "NonConcurrentGC" Reason= "AllocSmall"/>
 
But I think the times for the background GC should be:
PauseDurationMSec = 1341.542 - 1341.128 = 0.414
SuspendDurationMSec = (1341.139 - 1341.128) + (1341.542 - 1341.538) = 0.015

comments

VanceMorrison wrote Apr 13, 2010 at 1:40 AM

With background GC, the accounting is not trivial and alot depends on your precise defintion of terms.
With Background GC you have a couple 'unusual' properties
One suspension can be shared among two GCs (in fact that happens between 1330.0184 and 1336.7486.
One GC can have multiple suspensions associated with it (the Background GC is suspended again at 1341.1286 and 1341.5427).
Currently we define the pause for a GC as the suspension 'surrounding' the GCStart event. Thus it gets the first case for both GC 6 and 7 which 'share' the same pause. This is actually reasonable, however later we add the pause times up, which is really assuming non-overlapping times. For this reason I do agree that this is a poor defintion (a bug). We should not 'double count' pause times. I will fix this...

haveriss wrote Jul 27, 2010 at 5:40 PM

Vance, could also own this one?

Sign in to add a comment or to set email notifications