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: