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: 6:import java.text 7:method main(arg = String[], prtWrt = java.io.PrintStream) static 8:fd = SimpleDateFormat("MM/dd/yy hh:mm:ss a z") 9:dt = fd.format(Date()) 10:ct = Thread.currentThread() 11:logdata = Rexx '' 12:logfilename = Rexx arg[0] 13: 14:say dt '[INFO] [EPAClass GCWatch] GC Verbose timing monitor - v2.1' 15:say dt '[INFO] [EPAClass GCWatch] Started' 16:say dt '[INFO] [EPAClass GCWatch] Reading log file:' logfilename 17:--logfilename = "c:\\Introscope\\logs\\stdout" 18: infile = FileReader(logfilename) 19: source = BufferedReader(infile) 20:--create friendly name for Introscope 21:logfilename = logfilename.changestr('\\','-') 22:logfilename = logfilename.changestr('/','-') 23:logfilename = logfilename.changestr('.','_') 24:logfilename = logfilename.changestr(':','') 25: 26:loop forever 27: 28: 29: loop while source.ready 30: logdata = source.readLine() 31: if logdata = null then do 32: leave /* exit reading loop */ 33: end 34: parse logdata . ': ' mword msg 35: 36: select 37: when mword = 'freed' then -- freed 6948304 bytes, 44% free (38986232/87161344), in 26 ms> 38: do 39: -- say mword 40: parse msg gcFreed . gcPCT . 'in ' gcTime . 41: gcTime = gcTime.strip 42: gcFreed = gcFreed.strip 43: gcPCT = gcPCT.strip('t','%') 44: -- say 'freed>'gcFreed'<>'gcPCT'<>'gcTime'<' 45: prtWrt.printLn('<metric type="IntAverage" name="Logs|'||logfilename||'|GC|Collection:Average Time (ms)" value="'||gcTime||'" />') 46: prtWrt.printLn('<metric type="IntAverage" name="Logs|'||logfilename||'|GC|Memory Freed:Percent" value="'||gcPCT||'" />') 47: prtWrt.printLn('<metric type="IntAverage" name="Logs|'||logfilename||'|GC|Memory Freed:Average Bytes" value="'||gcFreed||'" />') 48: end 49: when mword = 'mark:' then -- mark: 3 ms, sweep: 1 ms, compact: 0 ms> 50: do 51: -- say mword 52: parse msg gcMark . ', sweep: ' gcSweep . ', compact:' gcCompact . '>' 53: -- say 'mark>'gcMark'<>'gcSweep'<>'gcCompact'<' 54: gcMark = gcMark.strip('b',' ') 55: gcSweep = gcSweep.strip('b',' ') 56: gcCompact = gcCompact.strip('b',' ') 57: prtWrt.printLn('<metric type="IntAverage" name="Logs|'||logfilename||'|GC|Memory Freed|Mark phase:Average Time (ms)" value="'||gcMark||'" />') 58: prtWrt.printLn('<metric type="IntAverage" name="Logs|'||logfilename||'|GC|Memory Freed|Sweep phase:Average Time (ms)" value="'||gcSweep||'" />') 59: prtWrt.printLn('<metric type="IntAverage" name="Logs|'||logfilename||'|GC|Memory Freed|Compact phase:Average Time (ms)" value="'||gcCompact||'" />') 60: end 61: when mword = 'Allocation' then -- Allocation Failure. need 304 bytes, 359967 ms since last AF> 62: /* <AF[108]: Allocation Failure caused by TLH replenishment, 1574 ms since last AF> */ 63: do 64: -- say mword 65: -- say msg 66: if msg.word(2) = 'caused' then 67: do 68: parse msg . 'replenishment,' gcAFTime . 69: gcAFTime = gcAFTime.strip 70: gcNeed = 0 71: logdata = logdata.changeStr('<',' ') 72: logdata = logdata.changeStr('>',' ') 73: 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="Allocation failure caused by TLH replenishment"/> </calledComponent> </event>') 74: end 75: else do 76: parse msg 'Failure. need' gcNeed 'bytes,' gcAFTime . 77: gcNeed = gcNeed.strip 78: gcAFTime = gcAFTime.strip 79: if gcAFTime > 0 then 80: do 81: gcAFTimeWS = (gcAFTime / 1000) 82: parse gcAFTimeWS gcAFTime '.' . 83: end 84: else 85: gcAFTime = 0 86: end 87: 88: -- say 'Alloc>'gcNeed'<>'gcAFTime'<' 89: prtWrt.printLn('<metric type="IntAverage" name="Logs|'||logfilename||'|GC|Allocation Failure:Average Request size (bytes)" value="'||gcNeed||'" />') 90: prtWrt.printLn('<metric type="IntAverage" name="Logs|'||logfilename||'|GC|Allocation Failure:Seconds since last" value="'||gcAFTime||'" />') 91: 92: end 93: when mword = 'refs:' then -- refs: soft 0 (age >= 32), weak 101, final 332, phantom 0> 94: do 95: -- say mword 96: parse msg 'soft' refSoft . 'weak' refWeak ', final' refFinal ', phantom' refPhantom '>' 97: refSoft = refSoft.strip 98: refWeak = refWeak.strip 99: refFinal = refFinal.strip 100: refPhantom = refPhantom.strip 101: -- say 'ref===>'refSoft'<>'refWeak'<>'refFinal'<>'refPhantom'<' 102: prtWrt.printLn('<metric type="IntAverage" name="Logs|'||logfilename||'|GC|References|Soft:Average Count" value="'||refSoft||'" />') 103: prtWrt.printLn('<metric type="IntAverage" name="Logs|'||logfilename||'|GC|References|Weak:Average Count" value="'||refWeak||'" />') 104: prtWrt.printLn('<metric type="IntAverage" name="Logs|'||logfilename||'|GC|References|Final:Average Count" value="'||refFinal||'" />') 105: prtWrt.printLn('<metric type="IntAverage" name="Logs|'||logfilename||'|GC|References|Phantom:Average Count" value="'||refPhantom||'" />') 106: end 107: when mword = 'Expanded' then -- Expanded System Heap by 65536 bytes 108: do 109: -- say mword 110: parse msg sys . . exBytes . 111: -- say 'sys>'sys'<' -- multiple possiblities 112: if sys \= 'System' then iterate 113: -- say 'SYSETEM' 114: exBytes = exBytes.strip 115: -- say 'Exp>'exBytes'<' 116: prtWrt.printLn('<metric type="IntAverage" name="Logs|'||logfilename||'|GC|Heap Expansion Size:Average Bytes" value="'||exBytes||'" />') 117: end 118: when mword = 'managing' then -- <AF[2]: managing allocation failure, action=0 (1017627776/1073740288)> 119: do 120: parse msg . . 'action=' afAction . 121: logdata = logdata.changestr('<',' ') 122: logdata = logdata.changestr('>',' ') 123: 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. 124: 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>') 125: if afAction = '6' then 126: 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>') 127: end 128: when mword = 'mark' then -- <GC(63): mark stack overflow[2]> 129: do 130: -- say mword 131: -- say logdata 132: -- prtWrt.printLn('event:type= ErrorSnapshot&resource=GC Heap&error=Mark Stack Overflow&msg="'||logdata||'"') 133: 134: logdata = logdata.changestr('<',' ') 135: logdata = logdata.changestr('>',' ') 136: -- logdata = logdata.changestr('(',' ') 137: -- logdata = logdata.changestr(')',' ') 138: -- logdata = logdata.changestr('[',' ') 139: -- logdata = logdata.changestr(']',' ') 140: 141: 142: 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>') 143: 144: end 145: otherwise 146: iterate 147: end 148: -- say 'x' 149: end 150: -- say 'sleep' 151: ct.sleep(7500) -- same as the agent 152: -- catch e1=IOException 153: -- say 'IOException caught:' e1 '\n ' e1.getMessage() 154: catch e2=NumberFormatException 155: say 'Number Format Exception ' logdata 156: catch e3=FileNotFoundException 157: say 'Input file not found ' logfilename 158: 159:end 160: 161:return 162: