Garbage Collection

I enable gc logging on our server and then compared it to the numbers in the host dashboard GC times. The GC Times shown by dynatrace was something like this..

It shows absolute GC times of 10 to 15 seconds.

However in the GC log between 2:00 and 2:15pm, the totalms has never gone over 1 second. How is it calculating those numbers?

<sys id="620" timestamp="Jun 12 14:00:13 2013" intervalms="60009.542">
<time exclusiveaccessms="0.173" />
<tenured freebytes="64877252" totalbytes="1073741824" percent="6" >
<soa freebytes="64877252" totalbytes="1073741824" percent="6" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
<con event="completed full sweep" timestamp="Jun 12 14:00:13 2013">
<stats sweepbytes="0" sweeptime="0.520" connectbytes="124518400" connecttime="0.285" />
</con>
<gc type="global" id="711" totalid="711" intervalms="60014.401">
<refs_cleared soft="3431" threshold="32" weak="2607" phantom="0" />
<finalization objectsqueued="2338" />
<timesms mark="317.688" sweep="0.985" compact="0.000" total="319.824" />
<tenured freebytes="550906432" totalbytes="1073741824" percent="51" >
<soa freebytes="550906432" totalbytes="1073741824" percent="51" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
</gc>
<tenured freebytes="550906432" totalbytes="1073741824" percent="51" >
<soa freebytes="550906432" totalbytes="1073741824" percent="51" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
<time totalms="327.482" />
</sys>

<sys id="621" timestamp="Jun 12 14:01:13 2013" intervalms="60051.469">
<time exclusiveaccessms="0.256" />
<tenured freebytes="68896568" totalbytes="1073741824" percent="6" >
<soa freebytes="68896568" totalbytes="1073741824" percent="6" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
<con event="completed full sweep" timestamp="Jun 12 14:01:13 2013">
<stats sweepbytes="0" sweeptime="0.510" connectbytes="133955584" connecttime="0.337" />
</con>
<gc type="global" id="712" totalid="712" intervalms="60064.290">
<refs_cleared soft="3102" threshold="32" weak="2752" phantom="0" />
<finalization objectsqueued="2297" />
<timesms mark="412.219" sweep="4.816" compact="0.000" total="418.945" />
<tenured freebytes="550495872" totalbytes="1073741824" percent="51" >
<soa freebytes="550495872" totalbytes="1073741824" percent="51" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
</gc>
<tenured freebytes="550495872" totalbytes="1073741824" percent="51" >
<soa freebytes="550495872" totalbytes="1073741824" percent="51" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
<time totalms="419.822" />
</sys>

<con event="completed sweep" timestamp="Jun 12 14:01:55 2013">
<stats bytes="0" time="0.005" />
</con>

<con event="kickoff" timestamp="Jun 12 14:01:55 2013">
<kickoff reason="Kickoff threshold reached" />
<stats tenurefreebytes="40317732" tracetarget="320490240" kickoff="40356192" tracerate="8.00" />
</con>

<con event="collection" id="69" timestamp="Jun 12 14:02:02 2013" intervalms="531581.702">
<time exclusiveaccessms="0.181" />
<tenured freebytes="3629644" totalbytes="1073741824" percent="0" >
<soa freebytes="3629644" totalbytes="1073741824" percent="0" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
<stats tracetarget="320490240">
<traced total="292822152" mutators="22114076" helpers="270708076" percent="91" />
<cards cleaned="4053" kickoff="13452064" />
</stats>
<con event="completed full sweep" timestamp="Jun 12 14:02:02 2013">
<stats sweepbytes="0" sweeptime="0.169" connectbytes="7077888" connecttime="0.015" />
</con>
<con event="final card cleaning">
<stats cardscleaned="192" traced="1861108" durationms="7.539" />
</con>
<gc type="global" id="713" totalid="713" intervalms="48705.410">
<refs_cleared soft="5663" threshold="32" weak="2513" phantom="0" />
<finalization objectsqueued="2130" />
<timesms mark="99.849" sweep="1.021" compact="0.000" total="101.611" />
<tenured freebytes="549968896" totalbytes="1073741824" percent="51" >
<soa freebytes="549968896" totalbytes="1073741824" percent="51" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
</gc>
<tenured freebytes="549968896" totalbytes="1073741824" percent="51" >
<soa freebytes="549968896" totalbytes="1073741824" percent="51" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
<time totalms="121.839" />
</con>

<sys id="622" timestamp="Jun 12 14:03:03 2013" intervalms="108812.555">
<time exclusiveaccessms="0.131" />
<tenured freebytes="90043312" totalbytes="1073741824" percent="8" >
<soa freebytes="90043312" totalbytes="1073741824" percent="8" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
<con event="completed full sweep" timestamp="Jun 12 14:03:03 2013">
<stats sweepbytes="0" sweeptime="0.427" connectbytes="175636480" connecttime="1.057" />
</con>
<gc type="global" id="714" totalid="714" intervalms="60010.501">
<refs_cleared soft="3337" threshold="32" weak="2794" phantom="0" />
<finalization objectsqueued="2311" />
<timesms mark="317.018" sweep="1.135" compact="0.000" total="319.147" />
<tenured freebytes="549253568" totalbytes="1073741824" percent="51" >
<soa freebytes="549253568" totalbytes="1073741824" percent="51" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
</gc>
<tenured freebytes="549253568" totalbytes="1073741824" percent="51" >
<soa freebytes="549253568" totalbytes="1073741824" percent="51" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
<time totalms="319.625" />
</sys>

<sys id="623" timestamp="Jun 12 14:04:03 2013" intervalms="60005.155">
<time exclusiveaccessms="0.222" />
<tenured freebytes="124586568" totalbytes="1073741824" percent="11" >
<soa freebytes="124586568" totalbytes="1073741824" percent="11" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
<con event="completed full sweep" timestamp="Jun 12 14:04:03 2013">
<stats sweepbytes="0" sweeptime="0.415" connectbytes="143917056" connecttime="2.065" />
</con>
<gc type="global" id="715" totalid="715" intervalms="60011.958">
<refs_cleared soft="2710" threshold="32" weak="2694" phantom="0" />
<finalization objectsqueued="1985" />
<timesms mark="377.093" sweep="1.189" compact="0.000" total="379.849" />
<tenured freebytes="549245440" totalbytes="1073741824" percent="51" >
<soa freebytes="549245440" totalbytes="1073741824" percent="51" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
</gc>
<tenured freebytes="549245440" totalbytes="1073741824" percent="51" >
<soa freebytes="549245440" totalbytes="1073741824" percent="51" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
<time totalms="390.390" />
</sys>

<sys id="624" timestamp="Jun 12 14:05:03 2013" intervalms="60045.995">
<time exclusiveaccessms="41.490" />
<tenured freebytes="140477224" totalbytes="1073741824" percent="13" >
<soa freebytes="140477224" totalbytes="1073741824" percent="13" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
<con event="completed full sweep" timestamp="Jun 12 14:05:03 2013">
<stats sweepbytes="0" sweeptime="6.368" connectbytes="247201792" connecttime="1.353" />
</con>
<gc type="global" id="716" totalid="716" intervalms="60068.493">
<refs_cleared soft="2315" threshold="32" weak="2585" phantom="0" />
<finalization objectsqueued="1990" />
<timesms mark="624.967" sweep="1.095" compact="0.000" total="627.729" />
<tenured freebytes="549764352" totalbytes="1073741824" percent="51" >
<soa freebytes="549764352" totalbytes="1073741824" percent="51" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
</gc>
<tenured freebytes="549764352" totalbytes="1073741824" percent="51" >
<soa freebytes="549764352" totalbytes="1073741824" percent="51" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
<time totalms="670.384" />
</sys>

<sys id="625" timestamp="Jun 12 14:06:04 2013" intervalms="60003.794">
<time exclusiveaccessms="0.183" />
<tenured freebytes="123952248" totalbytes="1073741824" percent="11" >
<soa freebytes="123952248" totalbytes="1073741824" percent="11" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
<con event="completed full sweep" timestamp="Jun 12 14:06:04 2013">
<stats sweepbytes="0" sweeptime="0.431" connectbytes="241696768" connecttime="0.654" />
</con>
<gc type="global" id="717" totalid="717" intervalms="60009.550">
<refs_cleared soft="2867" threshold="32" weak="2163" phantom="0" />
<finalization objectsqueued="1997" />
<timesms mark="503.710" sweep="0.982" compact="0.000" total="505.913" />
<tenured freebytes="550053952" totalbytes="1073741824" percent="51" >
<soa freebytes="550053952" totalbytes="1073741824" percent="51" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
</gc>
<tenured freebytes="550053952" totalbytes="1073741824" percent="51" >
<soa freebytes="550053952" totalbytes="1073741824" percent="51" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
<time totalms="506.528" />
</sys>

<sys id="626" timestamp="Jun 12 14:07:04 2013" intervalms="60010.544">
<time exclusiveaccessms="0.215" />
<tenured freebytes="52535312" totalbytes="1073741824" percent="4" >
<soa freebytes="52535312" totalbytes="1073741824" percent="4" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
<con event="completed full sweep" timestamp="Jun 12 14:07:04 2013">
<stats sweepbytes="0" sweeptime="0.496" connectbytes="102498304" connecttime="0.352" />
</con>
<gc type="global" id="718" totalid="718" intervalms="60015.140">
<refs_cleared soft="4067" threshold="32" weak="3079" phantom="0" />
<finalization objectsqueued="2250" />
<timesms mark="291.754" sweep="0.970" compact="0.000" total="293.834" />
<tenured freebytes="550869632" totalbytes="1073741824" percent="51" >
<soa freebytes="550869632" totalbytes="1073741824" percent="51" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
</gc>
<tenured freebytes="550869632" totalbytes="1073741824" percent="51" >
<soa freebytes="550869632" totalbytes="1073741824" percent="51" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
<time totalms="301.423" />
</sys>

<sys id="627" timestamp="Jun 12 14:08:05 2013" intervalms="60002.955">
<time exclusiveaccessms="0.175" />
<tenured freebytes="171305608" totalbytes="1073741824" percent="15" >
<soa freebytes="171305608" totalbytes="1073741824" percent="15" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
<con event="completed full sweep" timestamp="Jun 12 14:08:05 2013">
<stats sweepbytes="0" sweeptime="0.405" connectbytes="333709312" connecttime="1.472" />
</con>
<gc type="global" id="719" totalid="719" intervalms="60015.252">
<refs_cleared soft="1922" threshold="32" weak="2143" phantom="0" />
<finalization objectsqueued="1907" />
<timesms mark="343.680" sweep="1.028" compact="0.000" total="345.915" />
<tenured freebytes="551179648" totalbytes="1073741824" percent="51" >
<soa freebytes="551179648" totalbytes="1073741824" percent="51" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
</gc>
<tenured freebytes="551179648" totalbytes="1073741824" percent="51" >
<soa freebytes="551179648" totalbytes="1073741824" percent="51" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
<time totalms="346.569" />
</sys>

<con event="completed sweep" timestamp="Jun 12 14:09:01 2013">
<stats bytes="0" time="0.003" />
</con>

<con event="kickoff" timestamp="Jun 12 14:09:01 2013">
<kickoff reason="Kickoff threshold reached" />
<stats tenurefreebytes="40258856" tracetarget="320566208" kickoff="40365688" tracerate="8.88" />
</con>

<sys id="628" timestamp="Jun 12 14:09:05 2013" intervalms="60009.325">
<time exclusiveaccessms="0.166" />
<tenured freebytes="10658544" totalbytes="1073741824" percent="0" >
<soa freebytes="10658544" totalbytes="1073741824" percent="0" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
<con event="completed full sweep" timestamp="Jun 12 14:09:05 2013">
<stats sweepbytes="0" sweeptime="0.474" connectbytes="20185088" connecttime="0.039" />
</con>
<con event="halted" mode="trace only" state="Card cleaning incomplete">
<stats tracetarget="320566208">
<traced total="285854584" mutators="26290396" helpers="259564188" percent="89" />
<cards cleaned="4053" kickoff="13455229" />
</stats>
</con>
<con event="complete marking">
<stats traced="56" timetakenms="0.155" />
</con>
<con event="final card cleaning">
<stats cardscleaned="9839" traced="2863852" durationms="13.027" />
</con>
<gc type="global" id="720" totalid="720" intervalms="60026.128">
<classloadersunloaded count="2" timetakenms="196.800" />
<refs_cleared soft="5484" threshold="32" weak="2754" phantom="0" />
<finalization objectsqueued="2304" />
<timesms mark="106.824" sweep="0.954" compact="0.000" total="305.451" />
<tenured freebytes="552247808" totalbytes="1073741824" percent="51" >
<soa freebytes="552247808" totalbytes="1073741824" percent="51" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
</gc>
<tenured freebytes="552247808" totalbytes="1073741824" percent="51" >
<soa freebytes="552247808" totalbytes="1073741824" percent="51" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
<time totalms="309.827" />
</sys>

<con event="completed sweep" timestamp="Jun 12 14:09:57 2013">
<stats bytes="0" time="0.005" />
</con>

<con event="kickoff" timestamp="Jun 12 14:09:57 2013">
<kickoff reason="Kickoff threshold reached" />
<stats tenurefreebytes="40346696" tracetarget="320566208" kickoff="40365688" tracerate="8.00" />
</con>

<con event="collection" id="70" timestamp="Jun 12 14:10:04 2013" intervalms="481463.802">
<time exclusiveaccessms="0.160" />
<tenured freebytes="3874448" totalbytes="1073741824" percent="0" >
<soa freebytes="3874448" totalbytes="1073741824" percent="0" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
<stats tracetarget="320566208">
<traced total="292239408" mutators="24304200" helpers="267935208" percent="91" />
<cards cleaned="5046" kickoff="13455229" />
</stats>
<con event="completed full sweep" timestamp="Jun 12 14:10:04 2013">
<stats sweepbytes="0" sweeptime="0.206" connectbytes="6815744" connecttime="0.024" />
</con>
<con event="final card cleaning">
<stats cardscleaned="1443" traced="450184" durationms="1.664" />
</con>
<gc type="global" id="721" totalid="721" intervalms="58541.675">
<refs_cleared soft="5801" threshold="32" weak="2718" phantom="0" />
<finalization objectsqueued="2408" />
<timesms mark="74.755" sweep="1.058" compact="0.000" total="76.662" />
<tenured freebytes="552126912" totalbytes="1073741824" percent="51" >
<soa freebytes="552126912" totalbytes="1073741824" percent="51" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
</gc>
<tenured freebytes="552126912" totalbytes="1073741824" percent="51" >
<soa freebytes="552126912" totalbytes="1073741824" percent="51" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
<time totalms="88.331" />
</con>

<sys id="629" timestamp="Jun 12 14:11:04 2013" intervalms="118632.329">
<time exclusiveaccessms="0.161" />
<tenured freebytes="89098568" totalbytes="1073741824" percent="8" >
<soa freebytes="89098568" totalbytes="1073741824" percent="8" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
<con event="completed full sweep" timestamp="Jun 12 14:11:04 2013">
<stats sweepbytes="0" sweeptime="0.446" connectbytes="173015040" connecttime="1.729" />
</con>
<gc type="global" id="722" totalid="722" intervalms="60023.578">
<refs_cleared soft="3799" threshold="32" weak="2391" phantom="0" />
<finalization objectsqueued="2127" />
<timesms mark="364.969" sweep="1.220" compact="0.000" total="367.115" />
<tenured freebytes="551251584" totalbytes="1073741824" percent="51" >
<soa freebytes="551251584" totalbytes="1073741824" percent="51" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
</gc>
<tenured freebytes="551251584" totalbytes="1073741824" percent="51" >
<soa freebytes="551251584" totalbytes="1073741824" percent="51" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
<time totalms="367.910" />
</sys>

<sys id="630" timestamp="Jun 12 14:12:04 2013" intervalms="60006.328">
<time exclusiveaccessms="0.120" />
<tenured freebytes="69737704" totalbytes="1073741824" percent="6" >
<soa freebytes="69737704" totalbytes="1073741824" percent="6" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
<con event="completed full sweep" timestamp="Jun 12 14:12:04 2013">
<stats sweepbytes="0" sweeptime="0.421" connectbytes="135790592" connecttime="3.721" />
</con>
<gc type="global" id="723" totalid="723" intervalms="60026.304">
<refs_cleared soft="3669" threshold="32" weak="2442" phantom="0" />
<finalization objectsqueued="2137" />
<timesms mark="529.675" sweep="0.973" compact="0.000" total="531.730" />
<tenured freebytes="551667008" totalbytes="1073741824" percent="51" >
<soa freebytes="551667008" totalbytes="1073741824" percent="51" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
</gc>
<tenured freebytes="551667008" totalbytes="1073741824" percent="51" >
<soa freebytes="551667008" totalbytes="1073741824" percent="51" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
<time totalms="532.701" />
</sys>

<sys id="631" timestamp="Jun 12 14:13:05 2013" intervalms="60007.387">
<time exclusiveaccessms="0.218" />
<tenured freebytes="175525560" totalbytes="1073741824" percent="16" >
<soa freebytes="175525560" totalbytes="1073741824" percent="16" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
<con event="completed full sweep" timestamp="Jun 12 14:13:05 2013">
<stats sweepbytes="0" sweeptime="0.564" connectbytes="292552704" connecttime="1.513" />
</con>
<gc type="global" id="724" totalid="724" intervalms="60013.547">
<refs_cleared soft="1539" threshold="32" weak="1997" phantom="0" />
<finalization objectsqueued="1829" />
<timesms mark="295.659" sweep="0.864" compact="0.000" total="297.499" />
<tenured freebytes="552200384" totalbytes="1073741824" percent="51" >
<soa freebytes="552200384" totalbytes="1073741824" percent="51" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
</gc>
<tenured freebytes="552200384" totalbytes="1073741824" percent="51" >
<soa freebytes="552200384" totalbytes="1073741824" percent="51" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
<time totalms="298.060" />
</sys>

<sys id="632" timestamp="Jun 12 14:14:05 2013" intervalms="60005.877">
<time exclusiveaccessms="0.242" />
<tenured freebytes="166363712" totalbytes="1073741824" percent="15" >
<soa freebytes="166363712" totalbytes="1073741824" percent="15" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
<con event="completed full sweep" timestamp="Jun 12 14:14:05 2013">
<stats sweepbytes="0" sweeptime="0.491" connectbytes="298057728" connecttime="1.051" />
</con>
<gc type="global" id="725" totalid="725" intervalms="60011.670">
<refs_cleared soft="1774" threshold="32" weak="1938" phantom="0" />
<finalization objectsqueued="1787" />
<timesms mark="311.538" sweep="1.043" compact="0.000" total="314.126" />
<tenured freebytes="553075072" totalbytes="1073741824" percent="51" >
<soa freebytes="553075072" totalbytes="1073741824" percent="51" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
</gc>
<tenured freebytes="553075072" totalbytes="1073741824" percent="51" >
<soa freebytes="553075072" totalbytes="1073741824" percent="51" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
<time totalms="315.392" />
</sys>

<con event="completed sweep" timestamp="Jun 12 14:14:57 2013">
<stats bytes="0" time="0.003" />
</con>

<con event="kickoff" timestamp="Jun 12 14:14:57 2013">
<kickoff reason="Kickoff threshold reached" />
<stats tenurefreebytes="40314012" tracetarget="320623616" kickoff="40372864" tracerate="8.88" />
</con>

<sys id="633" timestamp="Jun 12 14:15:06 2013" intervalms="60010.759">
<time exclusiveaccessms="0.132" />
<tenured freebytes="4783480" totalbytes="1073741824" percent="0" >
<soa freebytes="4783480" totalbytes="1073741824" percent="0" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
<con event="completed full sweep" timestamp="Jun 12 14:15:06 2013">
<stats sweepbytes="0" sweeptime="0.201" connectbytes="8650752" connecttime="0.022" />
</con>
<con event="halted" mode="clean trace" state="Card cleaning incomplete">
<stats tracetarget="320623616">
<traced total="287804080" mutators="27203352" helpers="260600728" percent="89" />
<cards cleaned="41" kickoff="13457621" />
</stats>
</con>
<con event="complete marking">
<stats traced="608" timetakenms="0.217" />
</con>
<con event="final card cleaning">
<stats cardscleaned="3890" traced="2929988" durationms="12.309" />
</con>
<gc type="global" id="726" totalid="726" intervalms="60027.570">
<refs_cleared soft="5645" threshold="32" weak="3643" phantom="0" />
<finalization objectsqueued="2180" />
<timesms mark="32.026" sweep="1.188" compact="0.000" total="34.186" />
<tenured freebytes="553812992" totalbytes="1073741824" percent="51" >
<soa freebytes="553812992" totalbytes="1073741824" percent="51" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
</gc>
<tenured freebytes="553812992" totalbytes="1073741824" percent="51" >
<soa freebytes="553812992" totalbytes="1073741824" percent="51" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
<time totalms="34.732" />
</sys>

Our Agent gets these timings either directly from the JVM or through JMX measures. You can look at the details of the Measure Definition to see which JMX measures we are actually collecting - or - you can also create new Measures in case the ones we deliver out-of-the-box are not sufficient

Tuning is a different topic - here I suggest you read our online java performance book. it has a chapter on Memory Management