1:/* read verbose GC from logs - 3/14/06 - Mike Measel */ 2:-- 9/29/06 - v1.1 - added alloc req size & time and counts of references by catagory 3:-- 8/6/07 - v2.0 - added event message for "mark stack overflow" 4:-- added error event for action=4 & 6 5:-- 12/13/07 - v3.0 - modified for 1.5 6:--02/11/08 - v3.1 - changed some metrics to counters for more appropriate representation 7: 8:import java.text 9:method main(arg = String[], prtWrt = java.io.PrintStream) static 10:fd = SimpleDateFormat("MM/dd/yy hh:mm:ss a z") 11:dt = fd.format(Date()) 12:ct = Thread.currentThread() 13:logdata = Rexx '' 14:logfilename = Rexx arg[0] 15: 16:say dt '[INFO] [EPAClass GCWatch] GC Verbose timing monitor - v3.1' 17:say dt '[INFO] [EPAClass GCWatch] Started' 18:say dt '[INFO] [EPAClass GCWatch] Reading log file:' logfilename 19:--logfilename = "c:\\Introscope\\logs\\stdout" 20: infile = FileReader(logfilename) 21: source = BufferedReader(infile) 22:--create friendly name for Introscope 23:logfilename = logfilename.changestr('\\','-') 24:logfilename = logfilename.changestr('/','-') 25:logfilename = logfilename.changestr('.','_') 26:logfilename = logfilename.changestr(':','') 27: 28:loop forever 29: 30: 31: loop while source.ready 32: logdata = source.readLine() 33: if logdata = null then do 34: leave /* exit reading loop */ 35: end 36: parse logdata . '<' mword msg 37: 38: select 39: when mword = 'gc' then 40: do 41: parse msg . 'id="' gcid '"' . 'intervalms="' gcTime '.' . 42: gcTimelast = (gcTime / 1000) 43: parse gcTimelast gcTime '.' . 44: prtWrt.printLn('<metric type="IntCounter" name="Logs|'||logfilename||'|GC:count" value="'||gcid||'" />') 45: prtWrt.printLn('<metric type="IntAverage" name="Logs|'||logfilename||'|GC:seconds since last" value="'||gcTime||'" />') 46: end 47: when mword = 'nursery' && mword = 'tenured' && mword = 'soa' && mword = 'loa' then -- <tenured freebytes="5965800" totalbytes="21635584" percent="27" > 48: do 49: -- say mword 50: parse msg 'freebytes="' freebytes '"' 'totalbytes="' totalbytes '"' 'percent="' gcPCT '"' . 51: --gcFreed = gcFreed.strip 52: --gcPCT = gcPCT.strip('t','%') 53: -- say 'freed>'gcFreed'<>'gcPCT'<>'gcTime'<' 54: 55: prtWrt.printLn('<metric type="IntCounter" name="Logs|'||logfilename||'|GC|Memory|'||mword||'| Free:Percent" value="'||gcPCT||'" />') 56: prtWrt.printLn('<metric type="IntCounter" name="Logs|'||logfilename||'|GC|Memory|'||mword||'| Free:Bytes" value="'||freebytes||'" />') 57: prtWrt.printLn('<metric type="IntCounter" name="Logs|'||logfilename||'|GC|Memory|'||mword||'| Total:Bytes" value="'||totalbytes||'" />') 58: end 59: when mword = 'timesms' then -- <timesms mark="996.919" sweep="21.155" compact="0.000" total="1025.080" /> 60: do 61: -- say mword 62: parse msg 'mark="' gcMark '.' . 'sweep="' gcSweep '.' . 'compact="' gcCompact '.' . 63: -- say 'mark>'gcMark'<>'gcSweep'<>'gcCompact'<' 64: gcMark = gcMark.strip('b',' ') 65: gcSweep = gcSweep.strip('b',' ') 66: gcCompact = gcCompact.strip('b',' ') 67: prtWrt.printLn('<metric type="IntAverage" name="Logs|'||logfilename||'|GC|Mark phase:Average Time (ms)" value="'||gcMark||'" />') 68: prtWrt.printLn('<metric type="IntAverage" name="Logs|'||logfilename||'|GC|Sweep phase:Average Time (ms)" value="'||gcSweep||'" />') 69: prtWrt.printLn('<metric type="IntAverage" name="Logs|'||logfilename||'|GC|Compact phase:Average Time (ms)" value="'||gcCompact||'" />') 70: end 71: when mword = 'af' then -- <af type="tenured" id="2" timestamp="Thu Dec 13 09:27:44 2007" intervalms="17511.427"> 72: do 73: -- say mword 74: parse msg . 'intervalms="' gcAFTime '"' 75: --gcAFTime = gcAFTime.strip 76: gcAFTimeWS = (gcAFTime / 1000) 77: parse gcAFTimeWS gcAFTime '.' . 78: prtWrt.printLn('<metric type="IntAverage" name="Logs|'||logfilename||'|GC|Allocation Failure:Seconds since last" value="'||gcAFTime||'" />') 79: 80: end 81: when mword = 'sys' then -- <sys id="1" timestamp="Thu Dec 13 09:29:10 2007" intervalms="0.000"> 82: do 83: -- say mword 84: parse msg . 'intervalms="' gcAFTime '"' 85: --gcAFTime = gcAFTime.strip 86: gcAFTimeWS = (gcAFTime / 1000) 87: parse gcAFTimeWS gcAFTime '.' . 88: prtWrt.printLn('<metric type="IntAverage" name="Logs|'||logfilename||'|GC|SystemGC:Seconds since last" value="'||gcAFTime||'" />') 89: 90: end 91: when mword = 'minimum' then -- <minimum requested_bytes="56" /> 92: do 93: -- say mword 94: parse msg . 'requested_bytes="' gcNeed '"' 95: prtWrt.printLn('<metric type="IntAverage" name="Logs|'||logfilename||'|GC|Allocation Failure:Average Request size (bytes)" value="'||gcNeed||'" />') 96: 97: end 98: when mword = 'refs_cleared' then -- <refs_cleared soft="651" threshold="32" weak="11276" phantom="8" /> 99: do 100: -- say mword 101: parse msg . 'soft="' refSoft '"' . 'threshold="' refThreshold '"' . 'weak="' refWeak '"' . 'phantom="' refPhantom '"' . 102: --refSoft = refSoft.strip 103: --refWeak = refWeak.strip 104: --refThreshold = refThreshold.strip 105: --refPhantom = refPhantom.strip 106: -- say 'ref===>'refSoft'<>'refWeak'<>'refFinal'<>'refPhantom'<' 107: prtWrt.printLn('<metric type="IntCounter" name="Logs|'||logfilename||'|GC|References|Soft:Count" value="'||refSoft||'" />') 108: prtWrt.printLn('<metric type="IntCounter" name="Logs|'||logfilename||'|GC|References|Weak:Count" value="'||refWeak||'" />') 109: prtWrt.printLn('<metric type="IntCounter" name="Logs|'||logfilename||'|GC|References|Threshold:Count" value="'||refThreshold||'" />') 110: prtWrt.printLn('<metric type="IntCounter" name="Logs|'||logfilename||'|GC|References|Phantom:Count" value="'||refPhantom||'" />') 111: end 112: when mword = 'expansion' then -- Expanded System Heap by 65536 bytes 113: do 114: -- say mword 115: parse msg 'type="' memType '"' . 'amount="' exBytes '"' . . 116: prtWrt.printLn('<metric type="IntAverage" name="Logs|'||logfilename||'|GC|Heap Expansion|'||memType||' Size:Average Bytes" value="'||exBytes||'" />') 117: end 118: /* 119: when mword = 'managing' then -- <AF[2]: managing allocation failure, action=0 (1017627776/1073740288)> 120: do 121: parse msg . . 'action=' afAction . 122: if afAction = '4' then -- Clearing any remaining soft references. This is only done if there is less than 12% free space in a fully expanded heap. 123: prtWrt.printLn('<event resource="JVM"> <param name="Trace Type" value="ErrorSnapshot"/> <calledComponent resource="GC"> <param name="log msg" value="'||logdata||'" /> <param name="Error Message" value="Clearing soft references - less than 12% free space in a fully expanded heap"/> </calledComponent> </event>') 124: if afAction = '6' then 125: prtWrt.printLn('<event resource="JVM"> <param name="Trace Type" value="ErrorSnapshot"/> <calledComponent resource="GC"> <param name="log msg" value="'||logdata||'" /> <param name="Error Message" value="Very low on heap space"/> </calledComponent> </event>') 126: end 127: when mword = 'mark' then -- <GC(63): mark stack overflow[2]> 128: do 129: -- prtWrt.printLn('event:type= ErrorSnapshot&resource=GC Heap&error=Mark Stack Overflow&msg="'||logdata||'"') 130: 131: logdata = logdata.changestr('<',' ') 132: logdata = logdata.changestr('>',' ') 133: -- logdata = logdata.changestr('(',' ') 134: -- logdata = logdata.changestr(')',' ') 135: -- logdata = logdata.changestr('[',' ') 136: -- logdata = logdata.changestr(']',' ') 137: 138: 139: prtWrt.printLn('<event resource="JVM"> <param name="Trace Type" value="ErrorSnapshot"/> <calledComponent resource="GC"> <param name="log msg" value="'||logdata||'" /> <param name="Error Message" value="GC Mark Stack Overflow"/> </calledComponent> </event>') 140: 141: end 142: */ 143: otherwise 144: iterate 145: end 146: -- say 'x' 147: end 148: -- say 'sleep' 149: ct.sleep(7500) -- same as the agent 150: catch e=IOException 151: say 'IOException caught:' e '\n ' e.getMessage() 152: 153:end 154: 155:return 156: