Add time stamp to GC log to ease your pain

When analyzing Gc log like these:

170609.479: [GC 170609.479: [ParNew: 1699544K->17689K(1887488K), 0.0537160 secs] 1728778K->47004K(5033216K) icms_dc=0 , 0.0538078 secs] [Times: user=0.08 sys=0.00, real=0.06 secs] 

172980.190: [GC 172980.190: [ParNew: 1695513K->4310K(1887488K), 0.0147373 secs] 1724828K->33657K(5033216K) icms_dc=0 , 0.0148245 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 

174228.363: [Full GC 174228.363: [CMS: 29346K->31421K(3145728K), 0.5658221 secs] 955586K->31421K(5033216K), [CMS Perm : 58212K->57316K(58536K)] icms_dc=0 , 0.5660007 secs] [Times: user=0.51 sys=0.00, real=0.56 secs] 

174228.930: [GC [1 CMS-initial-mark: 31421K(3145728K)] 31421K(5033216K), 0.0013385 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 174228.931: [CMS-concurrent-mark-start] 

175694.396: [GC 175694.396: [ParNew: 1677824K->25622K(1887488K), 0.0726440 secs] 1709245K->57044K(5033216K) icms_dc=0 , 0.0727338 secs] [Times: user=0.06 sys=0.00, real=0.06 secs] 

177309.350: [GC 177309.350: [ParNew: 1703446K->23200K(1887488K), 0.0730725 secs] 1734868K->54622K(5033216K) icms_dc=0 , 0.0731623 secs] [Times: user=0.06 sys=0.00, real=0.06 secs] 179729.274: [GC 179729.274: [ParNew: 1701024K->4428K(1887488K), 0.0138419 secs] 1732446K->35850K(5033216K) icms_dc=0 , 0.0139156 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 

I am always confused and painful to get what the exactly time stamp of each GC activity is(BTW, currently i am using GCViewer to do the analysis), so that i can not easily to correlate the GC log with Access log when doing further analyzing and trouble shooting the memory problems... So i am writing a ruby program to calculate the time stamp for your further investigation， called gcanalyzer.rb:

Pre-Condition: you should have your Ruby1.9.2 installed on your computer, Ruby 1.8.* may not work properly.

 require 'csv'  
 def gcanalyzer(filename)  
 i = File.new(filename);  
 arr1 = [0];  
 arr2 = [];  
 @@maxpasuetime = 0.0000;  
 @@fullgc_count = 0;  
 m = 0;  
 endstamp = i.mtime  
 if (!endstamp.isdst) #Summer Time  
  zone = 15  
 else  
  zone = 16  
 end  
 a = i.readlines()  
 endsec = a[a.count-1].to_i  
 outputfilename = 'GC_log' + endstamp.strftime("_%m-%d-%H%M%S") + '.csv';  
 j = File.new(filename);  
 open(outputfilename, "a"){|f|  
  j.each_line { |line|  
   if (s = line.split('->')[2])!= nil  
    offset = endsec - line.split(':')[0].to_i  
    ctime = endstamp - offset -zone*3600  
    timestamp = ctime.strftime("%m/%d-%H:%M:%S")  
    usedheap = s.split('K(')[0]  
    f << timestamp + "," + usedheap + "\n"  
    #prepare pause time  
    # This is for +UseParallelGC  
    if line =~/PSYoungGen/  
     if line =~ /Full/  
       @@fullgc_count = @@fullgc_count + 1  
       arr2.push(timestamp);  
     end  
     t1 = line.split(',')[1]  
    elsif # This is for CMS case  
     if line =~ /Full/  
       @@fullgc_count = @@fullgc_count + 1  
       arr2.push(timestamp);  
       t1 = line.split(',')[3]  
     elsif  
       t1 = line.split(',')[2]  
     end  
    end  
    pausetime = t1.split('secs')[0].strip.to_f  
    arr1[0] = arr1[0] + pausetime  
    #prepare maxpausetime  
    if pausetime > @@maxpasuetime  
      @@maxpasuetime = pausetime;  
    end  
   end  
  }  
 }  
 elapsedday = endsec/(24*3600);  
 ed = (endsec - elapsedday*24*3600);  
 elapsedhour = ed/3600;  
 elapsedmin = (ed - elapsedhour*3600)/60;  
 printf("Total Elapse Time: %d (%dday-%dhour-%dmin)\n", endsec, elapsedday, elapsedhour,elapsedmin) ;  
 printf("Total GC Puase Time: %.3f \n" , arr1[0]) ;  
 printf("GC Throughput: %.3f \n" ,(1-arr1[0]/endsec)*100) ;  
 printf("Max Pause Time: %.3f \n",@@maxpasuetime) ;  
 printf("Avg Puase Time: %.3f \n", (arr1[0]/(a.count-1)));  
 printf("Total GC Occurency: %d \n", (a.count-1));  
 printf("GC Frenquency: %.3f \n", endsec/(a.count-1));  
 printf("Full GC Occurency: %d \n", @@fullgc_count);  
 printf("Full GC Time stamp: #{arr2}");  
 # consider to make a chart based on new file in the future  
 end  

How to use it:

>ruby gcanalyzer.rb "D:\\app01_garbage_collection.log"

There will be a new file created with accurate time stamp of each GC, and also Output Summary info to the console, something like this:

Total Elapse Time: 2341621 (27day-2hour-27min)

Total GC Puase Time: 636.061

GC Throughput(%): 99.973

Max Pause Time: 0.566

Avg Puase Time: 0.162

Total GC Occurency: 3936

GC Frenquency(sec): 594.000

Full GC Occurency: 1

Full GC Time stamp: ["09/25-05:51:15"]