lifetime of a finalizable object obj
lifetime of a finalizable object obj
- When obj is allocated, the JVM internally records that obj is finalizable. This typically slows down the otherwise fast allocation path that modern JVMs have.
- When the garbage collector determines that obj is unreachable, it notices that obj is finalizable — as it had been recorded upon allocation — and adds it to the JVM’s finalization queue. It also ensures that all objects reachable from obj are retained, even if they are otherwise unreachable, as they might be accessed by the finalizer.
- At some point later (only gc knows when), the JVM’s finalizer thread will dequeue obj, call its finalize() method, and record that the obj’s finalizer has been called. At this point, obj is considered to be finalized.
- When the garbage collector rediscovers that obj is unreachable, it will reclaim its space along with everything reachable from it, provided that the latter is otherwise unreachable.
garbage collector needs a minimum of two cycles to reclaim obj and needs to retain all other objects reachable from obj during this process.
Additionally, the JVM does not guarantee that it will call the finalizers of all the finalizable objects that have been allocated. It might exit before the garbage collector discovers some of them to be unreachable.
Difference between keystore & truststore
Difference between keystore & truststore
========================================
1. A keystore contains a private key. You only need this if you are
a server, or if the server requires client authentication.
2. A truststore contains CA certifcates to trust. If your server’s
certificate is signed by a recognized CA, the default truststore
that ships with the JR will already trust it (because it already
trusts trustworthy CAs), so you don’t need to build your own,
or to add anything to the one from the JRE.
========================================
SSL provides you with privacy, integrity, and authentication. That is,
the messages are encrypted, tamper-evident, and come from an authenticated
identity. Whether that’s the identity you want to talk to is another
question. So the application has to perform the authorization step, i.e.
check the identity against what is expected. You do this by getting the
peer certificates out of the SSLSession, usually in a HandshakeCompletedListener,
and check that the identity of the server is what you expect. SSL can’t
do this for you as only the application knows who it expects to talk to.
Another way around this is to ship a custom truststore that only contains
the server certificate for the correct server, so it won’t trust anybody else.
========================================
java generating random string
import java.util.*;
public class RandomStr
{
private final char[] alphanumeric=alphanumeric();
private final Random rand;
public RandomStr(){this(null);}
public RandomStr(Random rand){
this.rand=(rand!=null) ? rand : new Random();
}
public String get(int len){
StringBuffer out=new StringBuffer();
while(out.length() < len){
int idx=Math.abs(( rand.nextInt() % alphanumeric.length ));
out.append(alphanumeric[idx]);
}
return out.toString();
}
// create alphanumeric char array
private char[] alphanumeric(){
StringBuffer buf=new StringBuffer(128);
for(int i=48; i<= 57;i++)buf.append((char)i); // 0-9
for(int i=65; i<= 90;i++)buf.append((char)i); // A-Z
for(int i=97; i<=122;i++)buf.append((char)i); // a-z
return buf.toString().toCharArray();
}
public static void main(String[] args){
RandomStr rand=new RandomStr();
System.out.println(
"10 chars random string="+rand.get(10)
);
System.out.println(
"128 chars random string="+rand.get(128)
);
}
}
later on I realize there is one-liner for this
Long.toHexString(Double.doubleToLongBits(Math.random()));
save image from clipboard to file
jython script to save image from system clipboard to a file
from java.io import File
from java.awt import Toolkit
from java.awt.datatransfer import DataFlavor
from javax.imageio import ImageIO
content=Toolkit.getDefaultToolkit().getSystemClipboard().getContents(None)
if content and content.isDataFlavorSupported(DataFlavor.imageFlavor):
img = content.getTransferData(DataFlavor.imageFlavor)
ImageIO.write(img,'png',File('c:/temp/1.png'))
java code
import java.io.*;
import java.awt.*;
import java.awt.image.*;
import java.awt.datatransfer.*;
import javax.imageio.*;
public class clipimg
{
public static
void main(String[] args)
throws Exception
{
System.err.println("usage: java clipimg [filename]");
String outputfile="/temp/1.png";
if(args.length > 0)outputfile=args[0];
copyTo(outputfile);
}
static
int copyTo(String filename) throws Exception {
Transferable content = Toolkit.getDefaultToolkit().getSystemClipboard().getContents(null);
if(content==null){
System.err.println("error: nothing found in clipboard");
return 1;
}
if(!content.isDataFlavorSupported(DataFlavor.imageFlavor)){
System.err.println("error: no image found in clipbaord");
return 2;
}
BufferedImage img = (BufferedImage)content.getTransferData(DataFlavor.imageFlavor);
String ext = ext(filename);
if(ext==null){
ext="png";
filename+="."+ext;
}
File outfile=new File(filename);
ImageIO.write(img,ext,outfile);
System.err.println("image copied to: " + outfile.getAbsolutePath());
return 0;
}
static String ext(String filename){
int pos=filename.lastIndexOf('.')+1;
if(pos==0 || pos >= filename.length() )return null;
return filename.substring(pos);
}
}
PrintGCStats
http://permalink.gmane.org/gmane.comp.java.openjdk.hotspot.gc.devel/51
http://java.sun.com/developer/technicalArticles/Programming/turbo/
http://java.sun.com/developer/technicalArticles/Programming/turbo/PrintGCStats.zip
=========================================================
plot promotion rate
./PrintGCStats2 -v plot=’promo(MB)’ gc.log | awk ‘{printf “%s,%sn”, $1,$2}’ > promotion.rate.csv
object allocation in MB
./PrintGCStats2 -v plot=’alloc(MB)’ gc.log | awk ‘{printf “%s,%sn”, $1,$2}’ > alloc.csv
plot young gen size before gc
./PrintGCStats2 -v plot=’used0(MB)‘ gc.log | awk ‘{printf “%s,%sn”, $1,$2}’ > used0.csv
plot heap size before gc
used(MB)
what was the old gen size when cms started
can’t seems to get it from PrintGCStats2
./PrintGCStats2 -v plot=’used1(MB)’ gc.log | awk ‘{printf “%s,%sn”, $1,$2}’ > used1.csv
use following script
$ perl -ne ‘printf(“%d%% old gen occupied, total=%dM occuped=%dM free=%dMn”,($1/$2)*100,$2/1024,$1/1024,($2-$1)/1024) if(/^d+.*d*: [GC [[0-9] CMS-initial-mark: (d+)K((d+)K)]/);’<gc.log | sort | uniq -c
1 20% old gen occupied, total=240M occuped=50M free=189M
1 92% old gen occupied, total=1112M occuped=1023M free=89M
3 92% old gen occupied, total=1260M occuped=1159M free=100M
4 92% old gen occupied, total=1260M occuped=1162M free=97M
1 92% old gen occupied, total=1260M occuped=1164M free=95M
1 93% old gen occupied, total=240M occuped=223M free=16M
following can get total secs in minor ParNew
egrep ‘[ParNew:' gc.log | perl -ne 'print /(d+.?d*) secs]$/;print “n”‘ | awk ‘{count+=$1}END{print count}’
this should be equals to gen0(s) ‘total’ column
minor ParNew collection count
egrep -c ‘[ParNew:' gc.log
this should be equals to gen0(s) 'count' column
full gc count
egrep -c '[Full' gc.log
this should be equals to gen1(s) 'count' column
count cms collection
grep -c "CMS-initial-mark" gc.log
this is equal to count column in cmsIM(s),cmsRM(s),cmsCM(s),cmsCP(s),cmsCS(s),cmsCR(s)
find gc log from last server restart
gc2.pl min <native_stdout.log
gc2.pl is posted elsewhere, basically we print lines when timestamp is decremented.
##############################################################
# Basic Output statistics:
#
# gen0(s) - young gen collection time, excluding gc_prologue & gc_epilogue.
# gen0t(s) - young gen collection time, including gc_prologue & gc_epilogue
# gen1i(s) - train generation incremental collection
# gen1t(s) - old generation collection/full GC
# cmsIM(s) - CMS initial mark pause
# cmsRM(s) - CMS remark pause
# cmsRS(s) - CMS resize pause
# GC(s) - all stop-the-world GC pauses
# cmsCM(s) - CMS concurrent mark phase
# cmsCP(s) - CMS concurrent preclean phase
# cmsCS(s) - CMS concurrent sweep phase
# cmsCR(s) - CMS concurrent reset phase
# alloc(MB) - object allocation in MB (approximate***)
# promo(MB) - object promotion in MB (approximate***)
# used0(MB) - young gen used memory size (before gc)
# used1(MB) - old gen used memory size (before gc)
# used(MB) - heap space used memory size (before gc) (excludes perm gen)
# commit0(MB) - young gen committed memory size (after gc)
# commit1(MB) - old gen committed memory size (after gc)
# commit(MB) - heap committed memory size (after gc) (excludes perm gen)
# apptime(s) - amount of time application threads were running
# safept(s) - amount of time the VM spent at safepoints (app threads stopped)
##############################################################
example
in time based stat like, gen0(s)
count is total number of collection,
total is total number of seconds
mean is total/count (an avg number of secs each collection took)
max is max secs a collection took
stddev secs stddev
for size based stats like, alloc(MB)
count is number of allocations
total is total MB allocation
mean total/count (avg allocation size is each allocation)
max max size a allocation did
stddev size stddev
what count total mean max stddev
gen0(s) 6833 305.804 0.04475 1.946 0.1045
gen0t(s) 6833 306.386 0.04484 1.946 0.1045
gen1t(s) 9 0.584 0.06488 0.368 0.1198
cmsIM(s) 11 0.200 0.01818 0.096 0.0258
cmsRM(s) 11 4.375 0.39772 1.369 0.4201
GC(s) 6853 311.545 0.04546 1.946 0.1066
cmsCM(s) 11 11.055 1.00500 1.154 0.1391
cmsCP(s) 11 0.240 0.02182 0.026 0.0055
cmsCS(s) 11 19.123 1.73845 5.673 1.8262
cmsCR(s) 11 3.314 0.30127 0.518 0.1423
alloc(MB) 6833 135186.275 19.78432 19.875 0.5748
promo(MB) 6833 7122.228 1.04233 9.991 1.7797
used0(MB) 6833 135186.275 19.78432 19.875 0.5748
used(MB) 6833 5464715.707 799.75351 1179.659 290.9408
commit0(MB) 6833 135631.750 19.84952 19.938 0.5748
commit1(MB) 6833 8357937.758 1223.17251 1260.000 178.4632
commit(MB) 6833 8493569.508 1243.02203 1279.938 178.9479
alloc/elapsed_time = 135186.275 MB / 208620.650 s = 0.648 MB/s
alloc/tot_cpu_time = 135186.275 MB / 1043103.250 s = 0.130 MB/s
alloc/mut_cpu_time = 135186.275 MB / 1041511.792 s = 0.130 MB/s
promo/elapsed_time = 7122.228 MB / 208620.650 s = 0.034 MB/s
promo/gc0_time = 7122.228 MB / 306.386 s = 23.246 MB/s
gc_seq_load = 1557.726 s / 1043103.250 s = 0.149%
gc_conc_load = 33.732 s / 1043103.250 s = 0.003%
gc_tot_load = 1591.458 s / 1043103.250 s = 0.153%
# Elapsed time. total number of seconds since jvm started
elapsed_time = lastTimeStamp - firstTimeStamp;
# Elapsed time scaled by cpus.
tot_cpu_time = elapsed_time * cpus;
e.g.
208620.650*5=1043103.25
208620.650 elapsed time
5 number of cpu
# Sequential gc time scaled by cpus.
seq_gc_cpu_time = total_gc_pause_time * cpus;
total_gc_pause_time is sum of all the [GC collection secs
# Concurrent gc time (scaling not necessary).
cms_gc_cpu_time = cms_concurrent_mark_time + cms_concurrent_preclean_time + cms_concurrent_sweep_time + cms_concurrent_reset_time;
# Cpu time available to mutators.
mut_cpu_time = tot_cpu_time - seq_gc_cpu_time - cms_gc_cpu_time;
# gc_seq_load - the percentage of cpu cycles used by gc 'serially'
# (i.e., while java application threads are stopped)
(seq_gc_cpu_time/tot_cpu_time)*100
# gc_conc_load - the percentage of cpu cycles used by gc 'concurrently'
# (i.e., while java application threads are also running)
(cms_gc_cpu_time/tot_cpu_time)*100
# gc_tot_load - the percentage of cpu cycles spent in gc
((seq_gc_cpu_time + cms_gc_cpu_time)/tot_cpu_time)*100
#############################################################
#! /usr/xpg4/bin/awk -f
# Note: /bin/nawk on Solaris 9 seems to have a bug; the RSTART and RLENGTH
# vars are not set correctly during the last call to match() in
# recordGCPauseEVM.
# PrintGCStats - summarize statistics about garbage collection, in particular gc
# pause time totals, averages, maximum and standard deviations.
#
# Attribution: written by John Coomes, based on earlier work by Peter Kessler,
# Ross Knippel and Jon Masamitsu.
#
# The input to this script should be the output from the HotSpot(TM)
# Virtual Machine when run with one or more of the following flags:
#
# -verbose:gc # produces minimal output so statistics are
# # limited, but available in all VMs
#
# -XX:+PrintGCTimeStamps # enables time-based statistics (e.g.,
# # allocation rates, intervals), but only
# # available in JDK 1.4.0 and later.
#
# -XX:+PrintGCDetails # enables more detailed statistics gathering,
# # but only available in JDK 1.4.1 and later.
#
# -XX:-TraceClassUnloading # [1.5.0 and later] disable messages about class
# # unloading, which are enabled as a side-effect
# # by -XX:+PrintGCDetails. The class unloading
# # messages confuse this script and will cause
# # some GC information in the log to be ignored.
# #
# # Note: This option only has an effect in 1.5.0
# # and later. Prior to 1.5.0, the option is
# # accepted, but is overridden by
# # -XX:+PrintGCDetails. In 1.4.2 and earlier
# # releases, use -XX:-ClassUnloading instead (see
# # below).
#
# -XX:-ClassUnloading # disable class unloading, since PrintGCDetails
# # turns on TraceClassUnloading, which cannot be
# # overridden from the command line until 1.5.0.
#
# Recommended command-line with JDK 1.5.0 and later:
#
# java -verbose:gc -XX:+PrintGCTimeStamps -XX:+PrintGCDetails
# -XX:-TraceClassUnloading …
#
# Recommended command-line with JDK 1.4.1 and 1.4.2:
#
# java -verbose:gc -XX:+PrintGCTimeStamps -XX:+PrintGCDetails
# -XX:-ClassUnloading …
#
# ——————————————————————————
#
# Usage:
#
# PrintGCStats -v cpus= [-v interval=] [-v verbose=1] [file ...]
# PrintGCStats -v plot=name [-v plotcolumns=] [-v verbose=1] [file ...]
#
# cpus - number of cpus on the machine where java was run, used to
# compute cpu time available and gc ‘load’ factors. No default;
# must be specified on the command line (defaulting to 1 is too
# error prone).
#
# ncpu - synonym for cpus, accepted for backward compatibility
#
# interval - print statistics at the end of each interval; requires
# output from -XX:+PrintGCTimeStamps. Default is 0 (disabled).
#
# plot - generate data points useful for plotting one of the collected
# statistics instead of the normal statistics summary. The name
# argument is the name of one of the output statistics, e.g.,
# “gen0t(s)”, “cmsRM(s)”, “commit0(MB)”, etc.
#
# The default output format for time-based statistics such as
# “gen0t(s)” includes four columns, described below. The
# default output format for size-based statistics such as
# “commit0(MB)” includes just the first two columns. The
# number of columns in the output can be set on the command
# line with -v plotcolumns=.
#
# The output columns are:
#
# 1) the starting timestamp if timestamps are present, or a
# simple counter if not
#
# 2) the value of the desired statistic (e.g., the length of a
# cms remark pause).
#
# 3) the ending timestamp (or counter)
#
# 4) the value of the desired statistic (again)
#
# The last column is to make plotting start & stop events
# easier.
#
# plotcolumns - the number of columns to include in the plot data.
#
# verbose - if non-zero, print each item on a separate line in addition
# to the summary statistics
#
# Typical usage:
#
# PrintGCStats -v cpus=4 gc.log > gc.stats
#
# ——————————————————————————
#
# Basic Output statistics:
#
# gen0(s) – young gen collection time, excluding gc_prologue & gc_epilogue.
# gen0t(s) – young gen collection time, including gc_prologue & gc_epilogue
# gen1i(s) – train generation incremental collection
# gen1t(s) – old generation collection/full GC
# cmsIM(s) – CMS initial mark pause
# cmsRM(s) – CMS remark pause
# cmsRS(s) – CMS resize pause
# GC(s) – all stop-the-world GC pauses
# cmsCM(s) – CMS concurrent mark phase
# cmsCP(s) – CMS concurrent preclean phase
# cmsCS(s) – CMS concurrent sweep phase
# cmsCR(s) – CMS concurrent reset phase
# alloc(MB) – object allocation in MB (approximate***)
# promo(MB) – object promotion in MB (approximate***)
# used0(MB) – young gen used memory size (before gc)
# used1(MB) – old gen used memory size (before gc)
# used(MB) – heap space used memory size (before gc) (excludes perm gen)
# commit0(MB) – young gen committed memory size (after gc)
# commit1(MB) – old gen committed memory size (after gc)
# commit(MB) – heap committed memory size (after gc) (excludes perm gen)
# apptime(s) – amount of time application threads were running
# safept(s) – amount of time the VM spent at safepoints (app threads stopped)
#
# *** – these values are approximate because there is no way to track
# allocations that occur directly into older generations.
#
# Some definitions:
#
# ‘mutator’ or ‘mutator thread’: a gc-centric term referring to a non-GC
# thread that modifies or ‘mutates’ the heap by allocating memory and/or
# updating object fields.
#
# promotion: when an object that was allocated in the young generation has
# survived long enough, it is copied, or promoted, into the old generation.
#
# Time-based Output Statistics (require -XX:+PrintGCTimeStamps):
#
# alloc/elapsed_time – allocation rate, based on elapsed time
# alloc/tot_cpu_time – allocation rate, based on total cpu time
# alloc/mut_cpu_time – allocation rate, based on cpu time available to mutators
# promo/elapsed_time – promotion rate, based on elapsed time
# promo/gc0_time – promotion rate, based on young gen gc time
# gc_seq_load – the percentage of cpu cycles used by gc ’serially’
# (i.e., while java application threads are stopped)
# gc_conc_load – the percentage of cpu cycles used by gc ‘concurrently’
# (i.e., while java application threads are also running)
# gc_tot_load – the percentage of cpu cycles spent in gc
BEGIN {
usage_msg = “PrintGCStats -v cpus= [-v interval=] ”
“[-v verbose=1] [file ...]n”
“PrintGCStats -v plot=name [-v plotcolumns=] “
“[-v verbose=1] [file ...]“;
# Seconds between printing per-interval statistics; a negative value disables
# intervals (the default). Allow command line to override.
timeStampDelta = interval == 0 ? -1 : interval;
# Number of cpus. Require this on the command line since defaulting to 1 is
# too error prone. Older versions used ncpu as the var name; accept it for
# compatibility.
if (cpus == 0) cpus = ncpu;
if (cpus == 0 && plot == “”) {
print usage_msg;
exit(1);
}
# A note on time stamps: the firstTimeStamp is not always assumed to be 0 so
# that we can get accurate elapsed time measurement for a partial log (e.g.,
# from the steady-state portion of a log from a long running server). This
# means that the elapsed time measurement can be wrong if a program runs for a
# significant amount of time before the first gc time stamp is reported. The
# best way to fix this is to have the VM emit a time stamp when heap
# initialization is complete.
firstTimeStamp = -1.0; # sentinel
prevTimeStamp = lastTimeStamp = firstTimeStamp;
lastFileName = “”; # Used to detect when the input file has changed.
# This value is added to time stamps so that input from multiple files appears
# to have monotonically increasing timestamps.
timeStampOffset = 0.0;
i = -1;
gen0c_idx = ++i; # With PrintGCDetails, DefNew collection time only.
gen0t_idx = ++i; # Includes gc_prologue() & gc_epilogue().
gen1i_idx = ++i; # Train incremental collection time.
gen1t_idx = ++i; # Full GCs or Tenured GCs
cmsIM_idx = ++i; # CMS Initial Mark
cmsRM_idx = ++i; # CMS Remark
cmsRS_idx = ++i; # CMS Resize (evm only)
totgc_idx = ++i; # Total gc pause time
# These must be greater than the totgc_idx.
cmsCM_idx = ++i; # CMS Concurrent Mark
cmsCP_idx = ++i; # CMS Concurrent Preclean
cmsCS_idx = ++i; # CMS Concurrent Sweep
cmsCR_idx = ++i; # CMS Concurrent Reset
MB_a_idx = ++i; # MB allocated
MB_p_idx = ++i; # MB promoted
MB_used0_idx = ++i; # MB used in young gen
MB_used1_idx = ++i; # MB used in old gen
MB_usedh_idx = ++i; # MB used in heap (occupancy)
MB_c0_idx = ++i; # MB committed for gen0
MB_c1_idx = ++i; # MB committed for gen1
MB_ch_idx = ++i; # MB committed for entire heap
safept_idx = ++i; # Time application threads were stopped at a safepoint,
# from -XX:+TraceGCApplicationStoppedTime
apptime_idx = ++i; # Time application threads were running, from
# -XX:+PrintGCApplicationConcurrentTime
# Parallel old phases from PrintParallelOldGCPhaseTimes.
PO_precomp_idx = ++i;
PO_marking_idx = ++i;
PO_parmark_idx = ++i;
PO_mark_flush_idx = ++i;
PO_summary_idx = ++i;
PO_adjroots_idx = ++i;
PO_permgen_idx = ++i;
PO_compact_idx = ++i;
PO_drain_ts_idx = ++i;
PO_dpre_ts_idx = ++i;
PO_steal_ts_idx = ++i;
PO_parcomp_idx = ++i;
PO_deferred_idx = ++i;
PO_postcomp_idx = ++i;
last_idx = ++i; # This is just the last *named* index; a corresponding
# delta_* array item exists for each of the above items
# starting at this point in the array.
plot_cnt = -1; # Used to identify plot lines if timestamps are not
# available.
# Init arrays.
name_v[gen0c_idx] = “gen0(s)”;
name_v[gen0t_idx] = “gen0t(s)”;
name_v[gen1i_idx] = “gen1i(s)”;
name_v[gen1t_idx] = “gen1t(s)”;
name_v[cmsIM_idx] = “cmsIM(s)”;
name_v[cmsRM_idx] = “cmsRM(s)”;
name_v[cmsRS_idx] = “cmsRS(s)”;
name_v[totgc_idx] = “GC(s)”;
name_v[cmsCM_idx] = “cmsCM(s)”;
name_v[cmsCP_idx] = “cmsCP(s)”;
name_v[cmsCS_idx] = “cmsCS(s)”;
name_v[cmsCR_idx] = “cmsCR(s)”;
name_v[MB_a_idx] = “alloc(MB)”;
name_v[MB_p_idx] = “promo(MB)”;
name_v[MB_used0_idx] = “used0(MB)”;
name_v[MB_used1_idx] = “used1(MB)”;
name_v[MB_usedh_idx] = “used(MB)”;
name_v[MB_c0_idx] = “commit0(MB)”;
name_v[MB_c1_idx] = “commit1(MB)”;
name_v[MB_ch_idx] = “commit(MB)”;
name_v[safept_idx] = “safept(s)”;
name_v[apptime_idx] = “apptime(s)”;
name_v[PO_precomp_idx] = “precomp(s)”;
name_v[PO_marking_idx] = “marking(s)”;
name_v[PO_parmark_idx] = “parmark(s)”;
name_v[PO_mark_flush_idx] = “mark-f(s)”;
name_v[PO_summary_idx] = “summary(s)”;
name_v[PO_adjroots_idx] = “adjroots(s)”;
name_v[PO_permgen_idx] = “permgen(s)”;
name_v[PO_compact_idx] = “compact(s)”;
name_v[PO_drain_ts_idx] = “drain_ts(s)”;
name_v[PO_dpre_ts_idx] = “dpre_ts(s)”;
name_v[PO_steal_ts_idx] = “steal_ts(s)”;
name_v[PO_parcomp_idx] = “parcomp(s)”;
name_v[PO_deferred_idx] = “deferred(s)”;
name_v[PO_postcomp_idx] = “postcomp(s)”;
for (i = 0; i < last_idx; ++i) {
count_v[i] = 0;
sum_v[i] = 0.0;
max_v[i] = 0.0;
sum_of_sq_v[i] = 0.0;
name_v[last_idx + i] = name_v[i]; # Copy names.
}
plot_idx = -1;
if (plot != “”) {
# Convert the plot=name value to a plot_idx. The default is no plotting,
# which occurs when plot_idx < 0.
for (i = 0; plot_idx < 0 && i < last_idx; ++i) {
if (plot == name_v[i]) {
plot_idx = i;
}
}
if (plot_idx < 0) {
print “PrintGCStats: unrecognized plot name plot=” plot “.”;
print usage_msg;
exit(1);
}
}
# If plotting, set plotcolumns based on the statistic being plotted (unless
# plotcolumns was set on the command line).
if (plot_idx >= 0 && plotcolumns == 0) {
if (plot_idx >= MB_a_idx && plot_idx <= MB_ch_idx) {
# Use 2 columns for size-based statistics.
plotcolumns = 2;
} else {
# Use 4 columns for time-based statistics.
plotcolumns = 4;
}
}
# Heap sizes at the start & end of the last gen0 collection.
gen0_sizes[0] = 0.0;
gen0_sizes[1] = 0.0;
gen0_sizes[2] = 0.0;
initIntervalVars();
last_cmsRcount = 0;
printFirstHeader = 1;
# Six columns: name, count, total, mean, max, standard deviation
headfmt = “%-11s” “ %7s” “ %13s” “ %12s” “ %12s” “ %9s” “n”;
datafmt = “%-11s” “ %7d” “ %13.3f” “ %12.5f” “ %12.3f” “ %9.4f” “n”;
# Frequently-used regular expressions.
# These are replicated in PrintGCFixup; keep them in sync.
full_gc_re = “\[Full GC (\(System\) )?";
heap_size_re = "[0-9]+[KM]“; # 8K
heap_size_paren_re = “\(” heap_size_re “\)”; # (8K)
heap_size_change_re = heap_size_re “->” heap_size_re; # 8K->4K
# 8K->4K(96K), or 8K->4K (96K)
heap_size_status_re = heap_size_change_re ” ?” heap_size_paren_re;
gc_time_re = “[0-9]+\.[0-9]+”;
gc_time_secs_re = gc_time_re ” secs”;
gc_time_ms_re = gc_time_re ” ms”;
timestamp_re = “(” gc_time_re “: *)?”;
timestamp_range_re = “(” gc_time_re “-” gc_time_re “: *)?”;
# Heap size status plus elapsed time: 8K->4K(96K), 0.0517089 secs
heap_report_re = heap_size_status_re “, ” gc_time_secs_re;
# Size printed at CMS initial mark and remark.
cms_heap_size_re = heap_size_re heap_size_paren_re; # 6K(9K)
cms_heap_report_re = cms_heap_size_re “, ” gc_time_secs_re;
cms_concurrent_phase_re = “(AS)?CMS-concurrent-(mark|(abortable-)?preclean|sweep|reset)”;
# Generations which print optional messages.
promo_failed_re = “( \(promotion failed\))?”
cms_gen_re = “(AS)?CMS( \(concurrent mode failure\))?”;
parnew_gen_re = “(AS)?ParNew”;
# ‘Framework’ GCs: DefNew, ParNew, Tenured, CMS
fw_yng_gen_re = “(DefNew|” parnew_gen_re “)” promo_failed_re;
fw_old_gen_re = “(Tenured|” cms_gen_re “)”;
# Garbage First (G1) pauses:
# [GC pause (young), 0.0082 secs]
# or [GC pause (partial), 0.082 secs]
# or [GC pause (young) (initial mark), 0.082 secs]
# or [GC remark, 0.082 secs]
# or [GC cleanup 11M->11M(25M), 0.126 secs]
g1_cleanup_re = “cleanup ” heap_size_status_re;
g1_pause_re = “pause \((young|partial)\)”;
g1_pause_re = g1_pause_re “( \((initial-mark|evacuation failed)\))?”;
g1_stw_re = “\[GC (" g1_pause_re "|remark|" g1_cleanup_re "), "
gc_time_secs_re "\]“;
}
function initIntervalVars() {
for (i = 0; i < last_idx; ++i) {
count_v[last_idx + i] = 0;
sum_v[last_idx + i] = 0.0;
max_v[last_idx + i] = 0.0;
sum_of_sq_v[last_idx + i] = 0.0;
}
}
function ratio(dividend, divisor) {
result = 0.0;
if (divisor != 0.0) {
result = dividend / divisor;
}
return result;
}
function stddev(count, sum, sum_of_squares) {
if (count < 2) return 0.0;
sum_squared_over_count = (sum * sum) / count;
# This has happened on occasion–not sure why–but only for total gc time,
# which includes samples from different populations.
if (sum_of_squares < sum_squared_over_count) return -1.0;
# print “stddev”, count, sum, sum_of_squares, sum_squared_over_count;
return sqrt((sum_of_squares – sum_squared_over_count) / (count – 1));
}
function printHeader() {
printf(headfmt, “what”, “count”, “total”, “mean”, “max”, “stddev”);
}
function printData(idx) {
cnt = count_v[idx];
sec = sum_v[idx];
sd = stddev(cnt, sec, sum_of_sq_v[idx]);
printf(datafmt, name_v[idx], cnt, sec, ratio(sec, cnt), max_v[idx], sd);
}
function printRate(name, tot, tot_units, period, period_units) {
printf(“%-21s = %10.3f %-2s / %10.3f %-2s = %7.3f %s/%sn”,
name, tot, tot_units, period, period_units, ratio(tot, period),
tot_units, period_units);
}
function printPercent(name, tot, tot_units, period, period_units) {
printf(“%-21s = %10.3f %-2s / %10.3f %-2s = %7.3f%%n”,
name, tot, tot_units, period, period_units, ratio(tot * 100.0, period));
}
function getTimeStamp() {
gts_tmp_str = $0;
# Note: want to match the time stamp just before the ‘[GC' or '[Full GC' or
# '[CMS-' string on the line, and there may be time stamps that appear
# earlier. Thus there is no beginning-of-line anchor ('^') in the regexp used
# with match().
if (sub(/:? ? ?[((Full )?GC|(AS)?CMS-).*/, "", gts_tmp_str) != 1) return -1.0;
if (! match(gts_tmp_str, "[0-9]+\.[0-9]+(e[+-][0-9]+)?$”)) return -1.0;
gts_tmp = substr(gts_tmp_str, RSTART, RLENGTH) + 0.0;
return gts_tmp;
}
function recordStatsInternal(idx, seconds) {
count_v[idx] += 1;
sum_v[idx] += seconds;
sum_of_sq_v[idx] += seconds * seconds;
if (seconds > max_v[idx]) max_v[idx] = seconds;
}
function writePlotData(tstamp, value) {
if (plotcolumns == 4) {
# Column 1 = start time, 2 = duration, 3 = end time, 4 = duration.
printf(“%9.7f %9.7f %9.7f %9.7fn”, tstamp, value, tstamp + value, value);
return;
}
if (plotcolumns == 2) {
# Column 1 = start time, 2 = value.
printf(“%9.7f %9.7fn”, tstamp, value);
return;
}
if (plotcolumns == 1) {
# Column 1 = start time.
printf(“%9.7fn”, tstamp);
return;
}
if (plotcolumns == 3) {
# Column 1 = start time, 2 = duration, 3 = end time.
printf(“%9.7f %9.7f %9.7fn”, tstamp, value, tstamp + value);
return;
}
}
function recordStats(idx, value) {
if (verbose) print name_v[idx] “:” NR “:” value;
if (plot_idx < 0) {
# Plotting disabled; record statistics.
recordStatsInternal(idx, value);
recordStatsInternal(idx + last_idx, value);
if (idx < totgc_idx) recordStatsInternal(totgc_idx, value);
} else if (idx == plot_idx || plot_idx == totgc_idx && idx < totgc_idx) {
# Plotting enabled; skip statistics and just print a plot line.
rs_tstamp = getTimeStamp();
if (rs_tstamp < 0.0) rs_tstamp = ++plot_cnt;
writePlotData(rs_tstamp, value);
}
}
function parseHeapSizes(sizes, str) {
sizes[0] = sizes[1] = 0.0;
if (!match(str, heap_size_re “->”)) return -1;
sizes[0] = substr(str, RSTART, RLENGTH – 3) + 0.0;
if (substr(str, RSTART + RLENGTH – 3, 1) == “K”) {
sizes[0] = sizes[0] / 1024.0;
}
if (!match(str, “[KM]->” heap_size_re)) return -1;
sizes[1] = substr(str, RSTART + 3, RLENGTH – 4) + 0.0;
if (substr(str, RSTART, 1) == “K”) {
sizes[1] = sizes[1] / 1024.0;
}
if (!match(str, heap_size_paren_re)) return -1;
sizes[2] = substr(str, RSTART + 1, RLENGTH – 3) + 0.0;
if (substr(str, RSTART + RLENGTH – 2, 1) == “K”) {
sizes[2] = sizes[2] / 1024.0;
}
return 0;
}
function recordHeapKb(str) {
if (parseHeapSizes(tmp_mb, str) < 0) return;
recordStats(MB_a_idx, tmp_mb[0] – gen0_sizes[1]);
# Occupancy (the before gc value is used).
recordStats(MB_usedh_idx, tmp_mb[0]);
# Total heap committed size.
recordStats(MB_ch_idx, tmp_mb[2]);
gen0_sizes[0] = tmp_mb[0];
gen0_sizes[1] = tmp_mb[1];
gen0_sizes[2] = tmp_mb[2];
}
function recordGen0Kb(str, allow_3_sizes) {
# Allocation info.
if (parseHeapSizes(tmp_mb, str) < 0) { return; }
str = substr(str, RSTART + RLENGTH);
# print $0;
# print tmp_mb[0],tmp_mb[1],gen0_sizes[0],gen0_sizes[1];
recordStats(MB_used0_idx, tmp_mb[0]);
recordStats(MB_a_idx, tmp_mb[0] – gen0_sizes[1]);
# Gen0 committed size.
recordStats(MB_c0_idx, tmp_mb[2]);
gen0_sizes[0] = tmp_mb[0];
gen0_sizes[1] = tmp_mb[1];
gen0_sizes[2] = tmp_mb[2];
# If there isn’t a second heap size figure (4096K->1024K) on the line,
# promotion and occupancy info aren’t available.
if (parseHeapSizes(tmp_mb, str) < 0) return;
# Promotion info. Amount promoted is inferred from the last nnnK->nnnK
# on the line, taking into account the amount collected:
#
# promoted = change-in-overall-heap-occupancy – change-in-gen0-occupancy -
# change-in-gen1-occupancy
#
str = substr(str, RSTART + RLENGTH);
if (match(str, heap_size_change_re) && allow_3_sizes) {
# There is a 3rd heap size on the line; the 2nd one just parsed is assumed
# to be from the old gen. Get the 3rd one and use that for the overall
# heap.
gen1_sizes[0] = tmp_mb[0];
gen1_sizes[1] = tmp_mb[1];
gen1_sizes[2] = tmp_mb[2];
parseHeapSizes(tmp_mb, str);
mb_promo = tmp_mb[1] – tmp_mb[0] – (gen0_sizes[1] – gen0_sizes[0]);
mb_promo -= (gen1_sizes[1] – gen1_sizes[0]);
} else {
# Only gen0 was collected.
mb_promo = tmp_mb[1] – tmp_mb[0] – (gen0_sizes[1] – gen0_sizes[0]);
}
recordStats(MB_p_idx, mb_promo);
# Occupancy (the before gc value is used).
recordStats(MB_usedh_idx, tmp_mb[0]);
# Total heap committed size.
recordStats(MB_ch_idx, tmp_mb[2]);
# Gen1 committed size.
recordStats(MB_c1_idx, tmp_mb[2] – gen0_sizes[2]);
}
function recordParOldPhaseTime(str, phase_label, idx) {
sub(“.*” phase_label ” *[,:] *”, “”, str);
sub(” secs\].*”, “”, str);
recordStats(idx, str + 0.0);
next;
}
function printInterval() {
# No intervals if plotting.
if (plot_idx >= 0) return;
# Check for a time stamp.
pi_tmp = getTimeStamp();
if (pi_tmp < 0.0) return;
# Update the global time stamp vars.
if (lastFileName == FILENAME) {
lastTimeStamp = timeStampOffset + pi_tmp;
} else {
if (firstTimeStamp < 0) {
# First call of the run; initialize.
lastTimeStamp = pi_tmp;
firstTimeStamp = prevTimeStamp = lastTimeStamp;
} else {
# First call after the input file changed.
timeStampOffset = lastTimeStamp;
lastTimeStamp = timeStampOffset + pi_tmp;
}
lastFileName = FILENAME;
# printf(“%10.3f %10.6f %s %sn”, timeStampOffset, pi_tmp,
# pi_tmp_str, FILENAME);
}
# Print out the statistics every timeStampDelta seconds.
if (timeStampDelta < 0) return;
if ((lastTimeStamp – prevTimeStamp) > timeStampDelta) {
prevTimeStamp = lastTimeStamp;
if ((printFirstHeader == 1) ||
((last_cmsRcount == 0) && (count_v[cmsRM_idx] != 0))) {
printf(“Incremental statistics at %d second intervalsn”, timeStampDelta);
printHeader();
last_cmsRcount = count_v[cmsRM_idx];
printFirstHeader = 0;
}
printf(“interval=%d, time=%5.3f secs, line=%dn”,
int((lastTimeStamp – firstTimeStamp) / timeStampDelta),
lastTimeStamp, NR);
for (i = 0; i < last_idx; ++i) {
if (count_v[last_idx + i] > 0) {
printData(last_idx + i);
}
}
initIntervalVars();
}
}
# Match CMS initial mark output from PrintGCDetails.
#
# [GC [1 CMS-initial-mark: 14136K(23568K)] 14216K(25680K), 0.0062443 secs]
#
#/[GC [1 (AS)?CMS-initial-mark: [0-9]+K([0-9]+K)] [0-9]+K([0-9]+K), [0-9][0-9.]* secs]/ {
# /[1 (AS)?CMS-initial-mark: [0-9]+K([0-9]+K)] [0-9]+K([0-9]+K), [0-9][0-9.]* secs]/ {
#
match($0, “\[1 (AS)?CMS-initial-mark: " cms_heap_size_re "\] ” cms_heap_report_re “\]”) {
tString = substr($0, RSTART, RLENGTH);
match(tString, gc_time_secs_re);
secs = substr(tString, RSTART, RLENGTH – 5) + 0;
recordStats(cmsIM_idx, secs);
next;
}
# Match cms remark output from PrintGCDetails.
#[GC[dirty card accumulation,
0.0006214 secs][dirty card rescan, 0.1919700 secs] [1
CMS-remark:10044K(16744K)] 10412K(18856K), 0.2095526 secs]
#
# /[GC.*CMS-remark.*, [0-9][0-9.]* secs]/ {
# /[1 CMS-remark.*, [0-9][0-9.]* secs]/ {
# /[1 (AS)?CMS-remark: [0-9]+K([0-9]+K)] [0-9]+K([0-9]+K), [0-9][0-9.]* secs]/ {
match($0, “\[1 (AS)?CMS-remark: " cms_heap_size_re "\] ” cms_heap_report_re “\]”) {
tString = substr($0, RSTART, RLENGTH);
match(tString, gc_time_secs_re);
secs = substr(tString, RSTART, RLENGTH – 5) + 0;
recordStats(cmsRM_idx, secs);
# recordStats incremented the total gc count; undo that.
count_v[totgc_idx] -= 1;
next;
}
# Match CMS initial mark or remark output from -verbose:gc.
#
# [GC 43466K(68920K), 0.0002577 secs]
match($0, “\[GC " cms_heap_report_re "\]“) {
match($0, gc_time_secs_re);
secs = substr($0, RSTART, RLENGTH – 5) + 0;
recordStats(gen1t_idx, secs);
# XXX – this updates the count of gen1 collections for both initial mark and
# remark. Would like to update it only once per cms cycle (i.e., for initial
# mark only). Doing the increment every other time would be more accurate,
# but still subject to error because of aborted CMS cycles.
next;
}
# Match cms concurrent phase output
# [CMS-concurrent-mark: 6.422/9.360 secs]
# 10820.4: [CMS-concurrent-mark: 6.422/9.360 secs]
# /[(AS)?CMS-concurrent-(mark|preclean|sweep|reset): [0-9.]+/[0-9.]+ secs]/ {
$0 ~ “\[" cms_concurrent_phase_re ": " gc_time_re "/" gc_time_secs_re "\]” {
match($0, cms_concurrent_phase_re “: “);
t_time_idx = RSTART + RLENGTH;
tString = substr($0, RSTART, RLENGTH);
if (match(tString, “-mark:”)) {
tIdx = cmsCM_idx;
} else if (match(tString, “-sweep:”)) {
tIdx = cmsCS_idx;
} else if (match(tString, “-preclean:”)) {
tIdx = cmsCP_idx;
} else {
tIdx = cmsCR_idx;
}
tString = substr($0, t_time_idx);
match(tString, “/” gc_time_secs_re);
secs = substr(tString, 1, RSTART – 1) + 0.0;
recordStats(tIdx, secs);
printInterval(); # Must do this before the getline below.
if (match($0, “\[(AS)?CMS" timestamp_re "\[" cms_concurrent_phase_re)) {
# If CMS is in the middle of a concurrent phase when System.gc() is called
# or concurrent mode failure causes a bail out to mark-sweep,
# the output is split across 2 lines, e.g.:
#
# 164.092: [Full GC 164.093: [CMS164.341: [CMS-concurrent-mark: 0.302/0.304 secs]
# :
26221K->24397K(43704K), 0.8347158 secs] 26285K->24397K(64952K),
[CMS Perm :2794K->2794K(16384K)], 0.8350998 secs]
#
getline;
tString = $0;
tInt = sub(“.*” heap_size_status_re “\]?, “, “”, tString);
tInt += sub(” secs.*”, “”, tString);
if (tInt == 2) {
secs = tString + 0.0;
recordStats(gen1t_idx, secs);
}
}
next;
}
# Match PrintGCDetails output for Tenured or CMS full GC
# [GC [DefNew:
2048K->64K(2112K), 0.1517089 secs][Tenured: 1859K->1912K(1920K),
0.1184458 secs]2048K->1923K(4032K), 0.2710333 secs]
# or with time stamps
# 0.177656: [GC 0.177728:
[DefNew: 2112K->0K(2176K), 0.1006331 secs]0.278442:
[Tenured:4092K->4092K(4208K), 0.1372500 secs]
4096K->4092K(6384K), 0.2385750 secs]
# 549.281: [GC 549.281:
[ParNew: 14783K->14783K(14784K), 0.0000680 secs]549.281:
[CMS:275188K->136280K(290816K), 3.7791360 secs]
289972K->136280K(305600K), 3.7795440 secs]
#
#
/[GC.*[(DefNew|(AS)?ParNew):
[0-9]+K->[0-9]+K([0-9]+K),.*secs].*[((AS)?CMS|Tenured):[0-9]+K->[0-9]+K([0-9]+K),.*secs]/
{
#
# [GC [ParNew:
7812K->7812K(8128K), 0.0000310 secs][CMS (concurrent mode
failure):382515K->384858K(385024K), 0.0657172 secs]
390327K->390327K(393152K), 0.0658860 secs]
$0 ~ “\[GC.*\[" fw_yng_gen_re ": " heap_report_re "\].*\[" fw_old_gen_re ": " heap_report_re "\]” {
tString = $0;
tInt = sub(“.*” heap_size_status_re “, “, “”, tString);
tInt = sub(” secs.*”, “”, tString);
secs = tString + 0.0;
recordStats(gen1t_idx, secs);
# Old gen occupancy before GC.
tString = $0;
tInt = sub(“.*\[" fw_old_gen_re ": ", "", tString);
parseHeapSizes(tmp_mb, tString);
recordStats(MB_used1_idx, tmp_mb[0]);
# Heap occupancy before GC.
tInt = sub(heap_report_re “\] “, “”, tString);
parseHeapSizes(tmp_mb, tString);
recordStats(MB_usedh_idx, tmp_mb[0]);
printInterval();
next;
}
# [Full GC [Tenured:
43464K->43462K(43712K), 0.0614658 secs] 63777K->63775K(64896K),
[Perm :1460K->1459K(16384K)], 0.0615839 secs]
#
# 0.502: [Full GC 0.502:
[Tenured: 43464K->43462K(43712K), 0.0724391 secs]
63777K->63775K(64896K),[Perm : 1460K->1459K(16384K)], 0.0725792
secs]
$0 ~ full_gc_re timestamp_re
“.*\[" fw_old_gen_re ": " heap_report_re "\] ” heap_size_status_re
“,\[((AS)?CMS )?Perm *: " heap_size_status_re "\], ” gc_time_secs_re
“\]” {
tString = $0;
tInt = sub(“.*” heap_size_status_re “\], “, “”, tString);
tInt = sub(” secs.*”, “”, tString);
secs = tString + 0.0;
recordStats(gen1t_idx, secs);
# Old gen occupancy before GC.
tString = $0;
tInt = sub(“.*\[" fw_old_gen_re ": ", "", tString);
parseHeapSizes(tmp_mb, tString);
recordStats(MB_used1_idx, tmp_mb[0]);
# Heap occupancy before GC.
tInt = sub(heap_report_re “\] “, “”, tString);
parseHeapSizes(tmp_mb, tString);
recordStats(MB_usedh_idx, tmp_mb[0]);
printInterval();
next;
}
# Full GC (System.gc()) w/CMS when the perm gen is *not* being collected.
#
# [Full GC [ParNew: 161K->238K(12288K), 0.0014651 secs] 161K->238K(61440K), 0.0015972 secs]
# 0.178: [Full GC 0.178: [ParNew: 161K->238K(12288K), 0.0014651 secs] 161K->238K(61440K), 0.0015972 secs]
$0 ~ full_gc_re timestamp_re “.*\[" fw_yng_gen_re ": " heap_report_re "\] ” heap_report_re “\]” {
match($0, “.*” heap_size_status_re “, “);
tString = substr($0, RSTART + RLENGTH);
tInt = sub(” secs.*”, “”, tString);
secs = tString + 0.0;
recordStats(gen1t_idx, secs);
printInterval();
next;
}
# Match PrintGCDetails output for Train incremental GCs.
/[GC.*[(Def|Par)New: [0-9]+K->[0-9]+K([0-9]+K),.*secs].*[Train:[0-9]+K->[0-9]+K([0-9]+K),.*secs]/ {
# Young gen part.
tString = $0;
tInt = sub(/ secs.*/, “”, tString);
tInt = sub(“.*” heap_size_status_re “\], “, “”, tString);
secs = tString + 0.0;
recordStats(gen0t_idx, secs);
# Train incremental part.
tString = $0;
tInt = sub(“.*Train: [^,]+, “, “”, tString);
tInt = sub(” secs.*”, “”, tString);
secs = tString + 0.0;
if (plot_idx < 0) {
# Skip the update of the totgc numbers, that was handled above.
recordStatsInternal(gen1i_idx, secs);
recordStatsInternal(gen1i_idx + last_idx, secs);
} else if (plot_idx == gen1i_idx) {
recordStats(gen1i_idx, secs);
}
recordGen0Kb($0, 1);
printInterval();
next;
}
# Match PrintGCDetails output for Train Full GC.
/.*[Train MSC: [0-9]+K->[0-9]+K([0-9]+K),.*secs]/ {
# Get the last number of seconds on the line.
tString = $0;
tInt = sub(“.*” heap_size_status_re “, “, “”, tString);
tInt = sub(” secs.*”, “”, tString);
secs = tString + 0.0;
recordStats(gen1t_idx, secs);
printInterval();
next;
}
# Match PrintGCDetails output for DefNew or ParNew
#[GC [DefNew: 2880K->63K(2944K), 0.4626167 secs] 16999K->16999K(26480K), 0.4627703 secs]
# or with time stamps
# 0.431984: [GC 0.432051: [DefNew: 2112K->0K(2176K), 0.0911555 secs] 6204K->6201K(9000K), 0.0912899 secs]
# /[GC.*[(DefNew|(AS)?ParNew): [0-9]+K->[0-9]+K([0-9]+K),.*secs][0-9]+K->[0-9]+K([0-9]+K),.*secs]/ {
$0 ~ “\[GC " timestamp_re "\[" fw_yng_gen_re ": " heap_report_re "\] ” heap_report_re “\]” {
# The first time on the line is for DefNew/ParNew gc work only.
match($0, gc_time_secs_re);
secs = substr($0, RSTART, RLENGTH – 5) + 0;
tString = substr($0, RSTART + RLENGTH);
if (plot_idx < 0) {
# Skip the update of the totgc numbers, that will be handled below.
recordStatsInternal(gen0c_idx, secs);
recordStatsInternal(gen0c_idx + last_idx, secs);
} else if (plot_idx == gen0c_idx) {
recordStats(gen0c_idx, secs);
}
# The second time is the total time, which includes prologue, epilogue and
# safepoint time.
match(tString, gc_time_secs_re);
secs = substr(tString, RSTART, RLENGTH – 5) + 0;
recordStats(gen0t_idx, secs);
recordGen0Kb($0, 0);
printInterval();
next;
}
# 17.438: [Full GC [PSYoungGen:
48K->0K(9536K)] [PSOldGen: 173K->179K(87424K)]
221K->179K(96960K)[PSPermGen: 1928K->1928K(16384K)], 0.0824100
secs]
# 17.438: [Full GC [PSYoungGen:
48K->0K(9536K)] [ParOldGen: 173K->179K(87424K)]
221K->179K(96960K)[PSPermGen: 1928K->1928K(16384K)], 0.0824100
secs]
$0 ~ full_gc_re “\[PSYoungGen: +" heap_size_status_re "\] \[(PS|Par)OldGen: +"
heap_size_status_re "\] ” heap_size_status_re ” \[PSPermGen: +" heap_size_status_re "\], “
gc_time_secs_re “\]” {
match($0, gc_time_secs_re);
secs = substr($0, RSTART, RLENGTH – 5) + 0;
recordStats(gen1t_idx, secs);
# Old gen occupancy before GC.
tString = $0;
tInt = sub(“.*\[(PS|Par)OldGen: +", "", tString);
parseHeapSizes(tmp_mb, tString);
recordStats(MB_used1_idx, tmp_mb[0]);
# Heap occupancy before GC.
tInt = sub(heap_size_status_re “\] “, “”, tString);
parseHeapSizes(tmp_mb, tString);
recordStats(MB_usedh_idx, tmp_mb[0]);
printInterval();
next;
}
# [GC [PSYoungGen: 1070K->78K(1091K)] 3513K->2521K(4612K), 0.2177698 secs]
$0 ~ “\[GC(--)? \[PSYoungGen: +" heap_size_status_re "\] ” heap_report_re “\]” {
match($0, gc_time_secs_re);
secs = substr($0, RSTART, RLENGTH – 5) + 0;
recordStats(gen0t_idx, secs);
recordGen0Kb($0, 0);
printInterval();
next;
}
# [GC[0: 511K->228K(1984K)], 0.0087278 secs]
# or [GC[1: 308K->230K(1984K)], 0.0212333 secs]
# or [GC[0: 8313K->8313K(8944K)][1: 8313K->8313K(8944K)], 0.2044176 secs]
# but this only handles generations 0 and 1.
#/[GC[.*], [0-9][0-9.]* secs]/ {
/[GC.*[.*], [0-9][0-9.]* secs]/ {
tString = $0;
tInt = sub(“.*, “, “”, tString);
tInt = sub(” secs.*”, “”, tString);
secs = tString + 0.0;
# If a line is for generation 1, we give it all the time.
# If it is just for generation 0, we give that generation the time.
if ($0 ~ /[1: /) {
recordStats(gen1t_idx, secs);
} else if ($0 ~ /[0: /) {
recordStats(gen0c_idx, secs);
recordGen0Kb($0, 0);
}
printInterval();
next;
}
# Match Garbage-First output:
# [GC pause (young), 0.0082 secs]
# or [GC pause (partial), 0.082 secs]
# or [GC pause (young) (initial mark), 0.082 secs]
# or [GC remark, 0.082 secs]
# or [GC cleanup 11M->11M(25M), 0.126 secs]
# /[GC.*, [0-9][0-9.]* secs]/ {
# $0 ~ g1_stw_re {
$0 ~ g1_stw_re {
match($0, gc_time_secs_re);
secs = substr($0, RSTART, RLENGTH – 5) + 0;
recordStats(gen1t_idx, secs);
printInterval();
next;
}
# Match -verbose:gc and pre-GC-interface output
# [GC 17648K->12496K(31744K), 0.0800696 secs]
# [GC-- 17648K->12496K(31744K), 0.0800696 secs]
# [ParNew 17648K->12496K(31744K), 0.0800696 secs]
# /[(GC(--)?|(AS)?ParNew) [0-9]+K->[0-9]+K([0-9]+K), [0-9][0-9.]* secs]/ {
$0 ~ “\[(GC(--)?|" parnew_gen_re ") " heap_report_re "\]” {
match($0, gc_time_secs_re);
secs = substr($0, RSTART, RLENGTH – 5) + 0;
recordStats(gen0c_idx, secs);
recordHeapKb($0);
printInterval();
next;
}
# Match -verbose:gc and pre-GC-interface output
# [Full GC 14538K->535K(31744K), 0.1335093 secs]
$0 ~ full_gc_re heap_report_re “\]” {
match($0, gc_time_secs_re);
secs = substr($0, RSTART, RLENGTH – 5) + 0;
recordStats(gen1t_idx, secs);
recordHeapKb($0);
printInterval();
next;
}
# Parallel Old Gen phases.
# 0.547: [par marking phase, 0.0400133 secs]
# 0.547: [par marking main, 0.0400133 secs]
# 0.547: [par marking flush, 0.0400133 secs]
# 0.587: [summary phase, 0.0022902 secs]
# 0.590: [adjust roots, 0.0056697 secs]
# 0.596: [compact perm gen, 0.1242983 secs]
# 0.720: [draining task setup , 0.0031352 secs]
# -or-
# 0.720: [drain task setup, 0.0031352 secs]
# 0.724: [dense prefix task setup , 0.0000029 secs]
# 0.724: [steal task setup , 0.0000227 secs]
# 0.724: [par compact, 0.0154057 secs]
# 0.739: [post compact, 0.0009566 secs]
/[pre compact *[,:] *[0-9][0-9.]* secs]/ {
recordParOldPhaseTime($0, “pre compact”, PO_precomp_idx);
}
/[(par )?marking phase *[,:] *[0-9][0-9.]* secs]/ {
recordParOldPhaseTime($0, “(par )?marking phase”, PO_marking_idx);
}
/[par mark *[,:] *[0-9][0-9.]* secs]/ {
recordParOldPhaseTime($0, “par mark”, PO_parmark_idx);
}
/[marking flush *[,:] *[0-9][0-9.]* secs]/ {
recordParOldPhaseTime($0, “marking flush”, PO_mark_flush_idx);
}
/[summary phase *[,:] *[0-9][0-9.]* secs]/ {
recordParOldPhaseTime($0, “summary phase”, PO_summary_idx);
}
/[adjust roots *[,:] *[0-9][0-9.]* secs]/ {
recordParOldPhaseTime($0, “adjust roots”, PO_adjroots_idx);
}
/[compact perm gen *[,:] *[0-9][0-9.]* secs]/ {
recordParOldPhaseTime($0, “compact perm gen”, PO_permgen_idx);
}
/[compaction phase *[,:] *[0-9][0-9.]* secs]/ {
recordParOldPhaseTime($0, “compaction phase”, PO_compact_idx);
}
/[drain(ing)? task setup *[,:] *[0-9][0-9.]* secs]/ {
recordParOldPhaseTime($0, “drain(ing)? task setup”, PO_drain_ts_idx);
}
/[dense prefix task setup *[,:] *[0-9][0-9.]* secs]/ {
recordParOldPhaseTime($0, “dense prefix task setup”, PO_dpre_ts_idx);
}
/[steal task setup *[,:] *[0-9][0-9.]* secs]/ {
recordParOldPhaseTime($0, “steal task setup”, PO_steal_ts_idx);
}
/[par compact *[,:] *[0-9][0-9.]* secs]/ {
recordParOldPhaseTime($0, “par compact”, PO_parcomp_idx);
}
/[deferred updates *[,:] *[0-9][0-9.]* secs]/ {
recordParOldPhaseTime($0, “deferred updates”, PO_deferred_idx);
}
/[post compact *[,:] *[0-9][0-9.]* secs]/ {
recordParOldPhaseTime($0, “post compact”, PO_postcomp_idx);
}
# Match output from -XX:+TraceGCApplicationStoppedTime.
/Total time for which application threads were stopped: [0-9][0-9.]* seconds/ {
match($0, “were stopped: [0-9][0-9.]* seconds”);
secs = substr($0, RSTART + 14, RLENGTH – 14 – 8) + 0;
recordStats(safept_idx, secs);
next;
}
# Match output from -XX:+TraceGCApplicationConcurrentTime.
/Application time:[ ]+[0-9][0-9.]* seconds/ {
match($0, “Application time:[ ]+[0-9][0-9.]* seconds”);
secs = substr($0, RSTART + 18, RLENGTH – 18 – 8) + 0;
recordStats(apptime_idx, secs);
next;
}
# Match +TraceGen*Time output
# $1 $2 $3 $4 $5 $6 $7
/[Accumulated GC generation [0-9]+ time [0-9.]+ secs]/ {
if ($4 == 0) {
gc0caccum = $6 + 0;
} else if ($4 == 1) {
gc1taccum = $6 + 0;
} else {
printf(“Accumulated GC generation out of boundsn”);
}
next;
}
# BEA JRockit GC times (very basic).
# Java(TM) 2 Runtime Environment, Standard Edition (build 1.5.0_04-b05)
# BEA JRockit(R) (build R26.1.0-22-54592-1.5.0_04-20051213-1629-solaris-sparcv9, )
#
# [memory ] -: GC K->K (K), ms
# [memory ] – start time of collection (seconds since jvm start)
# [memory ] – end time of collection (seconds since jvm start)
# [memory ] – memory used by objects before collection (KB)
# [memory ] – memory used by objects after collection (KB)
# [memory ] – size of heap after collection (KB)
# [memory ] – total pause time during collection (milliseconds)
#
# [memory ] 14.229-16.647: GC 1572864K->718K (10485760K), 2418.000 ms
# [memory ] 133.299-133.568: GC 10485760K->762425K (10485760K), 269.000 ms
match($0, “\[memory ?\] ” timestamp_range_re “GC ” heap_size_status_re “, ” gc_time_ms_re) {
match($0, gc_time_ms_re);
secs = substr($0, RSTART, RLENGTH – 3) / 1000.0;
recordStats(gen1t_idx, secs);
recordHeapKb($0);
# printInterval();
next;
}
# EVM allocation info.
#
# Starting GC at Tue Nov 12 10:44:23 2002; suspending threads.
# Gen[0](semi-spaces): size=12Mb(50% overhead), free=0kb, maxAlloc=0kb.
/Starting GC at .*; suspending threads/ {
evm_last_was_starting_gc = 1;
next;
}
evm_last_was_starting_gc &&
$0 ~ /Gen[0]([a-z-]+): size=[0-9]+Mb.*, free=[0-9]+kb,/ {
evm_last_was_starting_gc = 0;
match($0, “size=[0-9]+Mb”);
tString = substr($0, RSTART + 5, RLENGTH – 7);
tmp_size = tString * 512; # * 1024 / 2: the size includes both semispaces
match($0, “free=[0-9]+kb”);
tString = substr($0, RSTART + 5, RLENGTH – 7);
tmp_free = tString + 0;
recordStats(MB_a_idx, (tmp_size – tmp_free) / 1024);
next;
}
# EVM promotion info
#
# Gen0(semi-spaces)-GC #2030 tenure-thresh=0 42ms 0%->100% free, promoted 46712 obj’s/1978kb
# /Gen0([a-z-]+)-GC.* promoted / {
/% free, promoted [0-9]+ obj.s/[0-9]+kb/ {
tString = $0;
match($0, “obj.s/[0-9]+kb”);
tString = substr($0, RSTART + 6, RLENGTH – 8);
kb_promo = tString + 0;
recordStats(MB_p_idx, kb_promo / 1024.0);
next;
}
function recordGCPauseEVM(idx) {
evm_last_was_starting_gc = 0;
match($0, “in [0-9]+ ms:”);
tString = substr($0, RSTART + 3, RLENGTH – 7);
recordStats(idx, tString / 1000.0);
# Record committed and used stats for young gen collections.
if (idx == gen0t_idx && match($0, “ms: \([0-9]+[MmKk][Bb],”)) {
tString = substr($0, RSTART + 5, RLENGTH – 8);
evm_units = tolower(substr($0, RSTART + RLENGTH – 3, 2));
evm_factor = evm_units == “kb” ? 1024 : 1;
evm_val = tString + 0;
recordStats(MB_ch_idx, tString / evm_factor);
if (match($0, “, [0-9]+% free\)”)) {
tString = substr($0, RSTART + 2, RLENGTH – 7);
evm_val = evm_val * (100 – tString) / 100;
recordStats(MB_usedh_idx, evm_val / evm_factor);
}
}
# Application time.
if (match($0, “\[application [0-9]+ ms”)) {
tString = substr($0, RSTART + 13, RLENGTH – 16);
recordStats(apptime_idx, tString / 1000.0);
}
}
# EVM output with -verbose:gc -verbose:gc
#
# GC[0] in 50 ms: (656Mb, 80% free) -> (656Mb, 80% free) [application 353 ms requested 6 words]
# GC[1] in 3963 ms: (656Mb, 0% free) -> (656Mb, 81% free) [application 380 ms requested 28 words]
# GC[1: initial mark] in 84 ms: (656Mb, 97% free) -> (656Mb, 97% free) [application 65 ms requested 0 words]
# GC[1: remark] in 36 ms: (656Mb, 93% free) -> (656Mb, 93% free) [application 241 ms requested 0 words]
# GC[1: resize heap] in 0 ms: (656Mb, 97% free) -> (656Mb, 97% free) [application 213 ms requested 0 words]
/GC[0] in [0-9]+ ms: / {
recordGCPauseEVM(gen0t_idx);
printInterval();
next;
}
/GC[1] in [0-9]+ ms: / {
recordGCPauseEVM(gen1t_idx);
next;
}
/GC[1: initial mark] in [0-9]+ ms: / {
recordGCPauseEVM(cmsIM_idx);
next;
}
/GC[1: remark] in [0-9]+ ms: / {
recordGCPauseEVM(cmsRM_idx);
next;
}
/GC[1: resize heap] in [0-9]+ ms: / {
recordGCPauseEVM(cmsRS_idx);
next;
}
END {
# No summary stats if plotting.
if (plot_idx >= 0) exit(0);
if (interval >= 0) print “”;
printHeader();
for (i = 0; i < last_idx; ++i) {
if (count_v[i] > 0) {
printData(i);
}
}
if (lastTimeStamp != firstTimeStamp) {
# Elapsed time.
tot_time = lastTimeStamp – firstTimeStamp;
# Elapsed time scaled by cpus.
tot_cpu_time = tot_time * cpus;
# Sequential gc time scaled by cpus.
seq_gc_cpu_time = sum_v[totgc_idx] * cpus;
# Concurrent gc time (scaling not necessary).
cms_gc_cpu_time = sum_v[cmsCM_idx] + sum_v[cmsCP_idx] +
sum_v[cmsCS_idx] + sum_v[cmsCR_idx];
# Cpu time available to mutators.
mut_cpu_time = tot_cpu_time – seq_gc_cpu_time – cms_gc_cpu_time;
print “”;
printRate(“alloc/elapsed_time”,
sum_v[MB_a_idx], “MB”, tot_time, “s”);
printRate(“alloc/tot_cpu_time”,
sum_v[MB_a_idx], “MB”, tot_cpu_time, “s”);
printRate(“alloc/mut_cpu_time”,
sum_v[MB_a_idx], “MB”, mut_cpu_time, “s”);
printRate(“promo/elapsed_time”,
sum_v[MB_p_idx], “MB”, tot_time, “s”);
printRate(“promo/gc0_time”,
sum_v[MB_p_idx], “MB”, sum_v[gen0t_idx], “s”);
printPercent(“gc_seq_load”,
seq_gc_cpu_time, “s”, tot_cpu_time, “s”);
printPercent(“gc_conc_load”,
cms_gc_cpu_time, “s”, tot_cpu_time, “s”);
printPercent(“gc_tot_load”,
seq_gc_cpu_time + cms_gc_cpu_time, “s”, tot_cpu_time, “s”);
}
if (gc0caccum != 0 || gc1taccum != 0) {
genAccum = gc0caccum + gc1taccum;
printf(“Accumt%7.3fttt%7.3fttt%7.3fn”,
gc0caccum, gc1taccum, genAccum);
gc0cdelta = gc0cseconds – gc0caccum;
gc1tdelta = gc1tseconds – gc1taccum;
gcDelta = gcSeconds – genAccum;
printf(“Deltat%7.3fttt%7.3fttt%7.3fn”,
gc0cdelta, gc1tdelta, gcDelta);
}
}
#############################################################
perl -ne ‘print /^[[^]]+] (.*)/;print “n”‘ gc.log
perl -ne ‘print /^[[^]]+] (.*)/;print “n”‘ gc.log
The Zen of Python
http://www.python.org/dev/peps/pep-0020/
The Zen of Python
Beautiful is better than ugly.
Explicit is better than implicit.
Simple is better than complex.
Complex is better than complicated.
Flat is better than nested.
Sparse is better than dense.
Readability counts.
Special cases aren’t special enough to break the rules.
Although practicality beats purity.
Errors should never pass silently.
Unless explicitly silenced.
In the face of ambiguity, refuse the temptation to guess.
There should be one– and preferably only one –obvious way to do it.
Although that way may not be obvious at first unless you’re Dutch.
Now is better than never.
Although never is often better than *right* now.
If the implementation is hard to explain, it’s a bad idea.
If the implementation is easy to explain, it may be a good idea.
Namespaces are one honking great idea — let’s do more of those!
The Timeless Way of Building
The Timeless Way of Building
by Christopher Alexander
# Hardcover: 552 pages
# Publisher: Oxford University Press (1979)
# Language: English
# ISBN-10: 0195024028
# ISBN-13: 978-0195024029
http://www.amazon.com/gp/product/0195024028
add axis to webapp in tomcat
- Copy following jar files from C:toolsjavaapacheaxisaxis1_2axis-bin-1_2axis-1_2lib to C:toolsjavaapachejakartajakarta-tomcat-5.0.28commonlib
jaxrpc.jar
commons-discovery-0.2.jar
saaj.jar
wsdl4j.jar
log4j-1.2.8.jar
- Copy happyaxis.jsp, i18nLib.jsp in web application root dir
- Copy i18n.properties to WEB-INFclasses dir
- Copy web.xml below in WEB-INFweb.xml
C:toolsjavaapacheaxisaxis1_2axis-bin-1_2axis-1_2webappsaxisWEB-INFweb.xml
<!DOCTYPE web-app PUBLIC "-//Sun Microsystems, Inc.//DTD Web
Application 2.3//EN” “http://java.sun.com/dtd/web-app_2_3.dtd”>
Apache-Axis
org.apache.axis.transport.http.AxisHTTPSessionListener
AxisServlet
Apache-Axis Servlet
org.apache.axis.transport.http.AxisServlet
AdminServlet
Axis Admin Servlet
org.apache.axis.transport.http.AdminServlet
100
SOAPMonitorService
SOAPMonitorService
org.apache.axis.monitor.SOAPMonitorService
SOAPMonitorPort
5001
100
AxisServlet
/servlet/AxisServlet
AxisServlet
*.jws
AxisServlet
/services/*
SOAPMonitorService
/SOAPMonitor
<!–
AdminServlet
/servlet/AdminServlet
–>
5
<!– currently the W3C havent settled on a media type for WSDL;
http://www.w3.org/TR/2003/WD-wsdl12-20030303/#ietf-draft
for now we go with the basic ‘it’s XML’ response –>
wsdl
text/xml
xsd
text/xml
index.jsp
index.html
index.jws
prstat
Finding Processes that are Using Up the CPU
mpstat 5 5 command will print the CPU statistics 5 times at 5 second intervals.
| CPU | minf | mjf | xcal | intr | ithr | csw | icsw | migr | smtx | srw | syscl | usr | sys | wt | idl |
| 0 | 1 | 0 | 0 | 345 | 224 | 589 | 220 | 0 | 0 | 0 | 799 | 29 | 1 | 0 | 70 |
| 0 | 1 | 0 | 0 | 302 | 200 | 752 | 371 | 0 | 0 | 0 | 1191 | 99 | 1 | 0 | 0 |
| 0 | 0 | 0 | 0 | 341 | 221 | 767 | 375 | 0 | 0 | 0 | 1301 | 100 | 0 | 0 | 0 |
| 0 | 0 | 0 | 0 | 411 | 256 | 776 | 378 | 0 | 0 | 0 | 1313 | 99 | 1 | 0 | 0 |
| 0 | 0 | 0 | 0 | 382 | 241 | 738 | 363 | 0 | 0 | 0 | 1163 | 97 | 3 | 0 | 0 |
In the output sample above, 4 of the 5 samples have CPU 0 with a combined user time and sytem time at 100 and idle time at 0 (column headings usr, sys, idl). This indicates that the CPU is completely consumed on this system.
you can use prstat to identify which processes are consuming the CPU resources. prstat -s cpu -n 5 command is used to list the five processes that are consuming the most CPU resources. The -s cpu flag tells prstat to sort the output by CPU usage. The -n 5 flag tells prstat to restrict the output to the top five processes.
| PID | USERNAME | SIZE | RSS | STATE | PRI | NICE | TIME | CPU | PROCESS/NLWP |
| 13974 | kincaid | 888K | 432K | run | 40 | 0 | 36:14.51 | 67% | cpuhog/1 |
| 27354 | kincaid | 2216K | 1928K | run | 31 | 0 | 314:48.51 | 27% | server/5 |
| 14690 | root | 136M | 46M | sleep | 59 | 0 | 0:00.59 | 2.3% | Xsun/1 |
| 14797 | kincaid | 9192K | 7496K | sleep | 59 | 0 | 0:00.10 | 0.9% | dtwm/8 |
| 14851 | kincaid | 24M | 14M | sleep | 48 | 0 | 0:00.03 | 0.3% | netscape/1 |
|
Total: 97 processes, 190 lwps, load averages: 2.18, 2.15, 2.11 |
|||||||||
In the example output, there is a process named cpuhog that is consuming the majority (67 %) of the CPU cycles. If this process is killed using the kill -9 13974 command, and the mpstat command is subsequently repeated, the output shows that the CPU is idle the majority of the time.
Note: The -s cpu option is the default setting for prstat. Therefore, if the intent is to sort output by CPU usage, specifying the -s cpu option is not necessary. For the purpose of this article, the -s cpu option is set to distinguish it from other ways of sorting the output produced by prstat.
command prstat -s cpu -a -n 8 asks for the top 8 processes consuming the CPU and a list of resource consumption statistics for each user.
| PID | USERNAME | SIZE | RSS | STATE | PRI | NICE | TIME | CPU | PROCESS/NLWP |
| 17005 | larry | 888K | 432K | run | 21 | 0 | 0:03.15 | 38% | cpuhog/1 |
| 17015 | larry | 888K | 432K | run | 21 | 0 | 0:03.06 | 36% | cpuhog/1 |
| 17175 | larry | 944K | 872K | run | 24 | 0 | 0:00.37 | 5.7% | find/1 |
| 16911 | moe | 944K | 872K | sleep | 58 | 0 | 0:00.48 | 3.3% | find/1 |
| 16915 | moe | 944K | 872K | sleep | 59 | 0 | 0:00.43 | 3.3% | find/1 |
| 17849 | curly | 944K | 872K | run | 31 | 0 | 0:00.00 | 3.0% | find/1 |
| 16472 | root | 132M | 42M | sleep | 59 | 0 | 0:01.00 | 0.9% | Xsun/1 |
| 16827 | kincaid | 6864K | 4704K | sleep | 48 | 0 | 0:00.05 | 0.4% | dtterm/1 |
| NPROC | USERNAME | SIZE | RSS | MEMORY | TIME | CPU |
| 7 | larry | 7504K | 5656K | 0.6% | 0:06.58 | 80% |
| 8 | moe | 8248K | 6800K | 0.7% | 0:01.31 | 6.6% |
| 3 | curly | 3336K | 2832K | 0.3% | 0:00.00 | 3.0% |
| 34 | root | 213M | 95M | 9.5% | 0:03.05 | 1.0% |
| 78 | kincaid | 433M | 294M | 30% | 0:00.38 | 0.7% |
| Total: 132 processes, 218 lwps, load averages: 3.90, 4.29, 2.45 | ||||||
Identifying Virtual Memory Usage
A good tool for determining if a system is paging is sar. The sar -g command will yield the paging statistics for a given system.
$ sar -g 5 5
Getting the Resource Statistics for Each Thread Within a Process
SunOS tartan 5.8 Generic_108528-01 sun4u 02/12/01
| 13:20:37 | pgout/s | ppgout/s | pgfree/s | pgscan/s | %ufs_ipf |
| 13:20:42 | 39.92 | 538.72 | 670.26 | 1147.31 | 0.00 |
| 13:20:47 | 36.60 | 483.80 | 515.40 | 353.80 | 0.00 |
| 13:20:52 | 40.20 | 508.20 | 632.00 | 1125.20 | 0.00 |
| 13:20:57 | 35.80 | 462.60 | 580.40 | 1141.60 | 0.00 |
| 13:21:02 | 0.00 | 0.00 | 0.00 | 0.00 | 0.00 |
| Average | 30.51 | 398.72 | 479.69 | 753.74 | 0.00 |
A common cause for system paging is a process or group of processes that are using a majority of the system’s memory. prstat is an excellent tool for identifying which processes are consuming the majority of a system’s memory. Use prstat -s size, which is similar to the previous command, but which sorts prstat output by size instead of by CPU usage.
top five processes on a system in terms of virtual memory consumption
$ prstat -s size -n 5
| PID | USERNAME | SIZE | RSS | STATE | PRI | NICE | TIME | CPU | PROCESS/NLWP |
| 21307 | kincaid | 1001M | 616M | run | 2 | 0 | 0:01.16 | 32% | memhog/1 |
| 16472 | root | 138M | 43M | sleep | 59 | 0 | 0:17.28 | 1.2% | Xsun/1 |
| 18133 | kincaid | 92M | 31M | sleep | 49 | 0 | 0:01.42 | 0.0% | soffice.bin/9 |
| 16574 | kincaid | 44M | 24M | sleep | 49 | 0 | 0:10.37 | 0.2% | .netscape.bin/1 |
| 16674 | kincaid | 36M | 25M | sleep | 49 | 0 | 0:00.08 | 0.0% | sdtperfmeter/1 |
| Total: 130 processes, 220 lwps, load averages: 0.51, 0.36, 0.23 | |||||||||
$ sar -g 5 5
SunOS tartan 5.8 Generic_108528-01 sun4u 02/12/01
| 13:20:02 | pgout/s | ppgout/s | pgfree/s | pgscan/s | %ufs_ipf |
| 13:20:07 | 0.00 | 0.00 | 0.00 | 0.00 | 0.00 |
| 13:20:12 | 0.00 | 0.00 | 0.00 | 0.00 | 0.00 |
| 13:20:17 | 0.00 | 0.00 | 0.00 | 0.00 | 0.00 |
| 13:20:22 | 0.00 | 0.00 | 0.00 | 0.00 | 0.00 |
| 13:20:27 | 0.00 | 0.00 | 3.80 | 590.60 | 0.00 |
| Average | 0.00 | 0.00 | 0.76 | 118.07 | 0.00 |
Getting the Resource Statistics for Each Thread Within a Process
by using the -L switch, prstat will report statistics for each thread of a process.
$ prstat -L -p 3295
| PID | USERNAME | SIZE | RSS | STATE | PRI | NICE | TIME | CPU | PROCESS/LWPID |
| 3295 | kincaid | 28M | 10M | sleep | 38 | 0 | 0:00.01 | 2.1% | java/16 |
| 3295 | kincaid | 28M | 10M | sleep | 55 | 0 | 0:00.01 | 1.9% | java/17 |
| 3295 | kincaid | 28M | 10M | sleep | 48 | 0 | 0:00.01 | 1.8% | java/15 |
| 3295 | kincaid | 28M | 10M | sleep | 58 | 0 | 0:00.01 | 1.8% | java/23 |
| 3295 | kincaid | 28M | 10M | sleep | 52 | 0 | 0:00.01 | 1.7% | java/12 |
| 3295 | kincaid | 28M | 10M | sleep | 48 | 0 | 0:00.01 | 1.6% | java/22 |
| 3295 | kincaid | 28M | 10M | sleep | 58 | 0 | 0:00.01 | 1.5% | java/13 |
| 3295 | kincaid | 28M | 10M | sleep | 58 | 0 | 0:00.01 | 1.5% | java/14 |
| 3295 | kincaid | 28M | 10M | sleep | 48 | 0 | 0:00.01 | 1.4% | java/19 |
| 3295 | kincaid | 28M | 10M | sleep | 48 | 0 | 0:00.01 | 1.4% | java/18 |
| 3295 | kincaid | 28M | 10M | sleep | 38 | 0 | 0:00.01 | 1.4% | java/21 |
| 3295 | kincaid | 28M | 10M | sleep | 58 | 0 | 0:00.01 | 1.3% | java/24 |
| 3295 | kincaid | 28M | 10M | sleep | 58 | 0 | 0:00.01 | 1.2% | java/20 |
| 3295 | kincaid | 28M | 10M | sleep | 58 | 0 | 0:00.00 | 0.0% | java/1 |
| 3295 | kincaid | 28M | 10M | sleep | 58 | 0 | 0:00.00 | 0.0% | java/11 |
| 3295 | kincaid | 28M | 10M | sleep | 0 | 0 | 0:00.00 | 0.0% | java/10 |
| 3295 | kincaid | 28M | 10M | sleep | 59 | 0 | 0:00.00 | 0.0% | java/9 |
| 3295 | kincaid | 28M | 10M | sleep | 0 | 0 | 0:00.00 | 0.0% | java/8 |
| 3295 | kincaid | 28M | 10M | sleep | 0 | 0 | 0:00.00 | 0.0% | java/7 |
| 3295 | kincaid | 28M | 10M | sleep | 59 | 0 | 0:00.00 | 0.0% | java/6 |
| 3295 | kincaid | 28M | 10M | sleep | 58 | 0 | 0:00.00 | 0.0% | java/5 |
| Total: 1 processes, 24 lwps, load averages: 1.30, 1.22, 1.21 | |||||||||
Getting the micro statistics on a process
use the -m option to have prstat print out the micro statistics of the process.
| Column Heading | Meaning |
| USR | The percentage of time the process has spent in user mode |
| SYS | The percentage of time the process has spent in system mode |
| TRP | The percentage of time the process has spent in processing system traps |
| DFL | The percentage of time the process has spent processing data page faults |
| LCK | The percentage of time the process has spent waiting for user locks |
| SLP | The percentage of time the process has spent sleeping |
| TFL | The percentage of time the process has spent processing text page faults |
$ prstat -m -p 3295
PID USERNAME USR SYS TRP TFL DFL LCK SLP LAT VCX ICX SCL SIG PROCESS/NLWP 3295 kincaid 0.8 0.0 0.0 0.0 0.0 0.0 99 0.0 22 4 25 0 java/24
In addition, the -m option can be used with the -L option so the micro statistics of each thread of a process can be monitored.
Some of the other Solaris tools that are worth reading about are: sar, iostat, netstat, and mpstat. All of these are great tools for identifying system performance issues. prstat is a nice complement to these tools because it helps further identify the processes and threads that may be responsible for system performance problems.
Solaris perofmrnace monitor cmds
Solaris perofmrnace monitor cmds
iostat
vmstat
netstat
Read more…
