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: