JVM memory pools – Code cache

One of our Jboss production servers runs out of Code cache based on the memory shortage reported when “CompilerThread1” is unable to proceed. I am not claiming at this time that I have understood this issue fully but I have attempted to track the utilization of the non-heap memory pool called ‘Code cache’ which is used to hold JIT compiled code.

The JMX API exposes this. I used Jboss’

    twiddle.sh

to dump this at frequent intervals.



Total Memory Pools: 5
Pool: Code Cache (Non-heap memory)
Peak Usage : init:2359296, used:14647936, committed:14680064, max:50331648
Current Usage : init:2359296, used:14646848, committed:14680064, max:50331648

|-------------------| committed:14Mb
+---------------------------------------------------------------------+
|///////////////////| | max:48Mb
+---------------------------------------------------------------------+
|-------------------| used:13.97Mb

Pool: PS Eden Space (Heap memory)
Peak Usage : init:89522176, used:229113856, committed:231866368, max:234684416
Current Usage : init:89522176, used:7292920, committed:229113856, max:232849408

|-------------------------------------------------------------------| committed:218.5Mb
+---------------------------------------------------------------------+
|// | | max:222.06Mb
+---------------------------------------------------------------------+
|-| used:6.96Mb

Pool: PS Survivor Space (Heap memory)
Peak Usage : init:14876672, used:23715856, committed:34996224, max:34996224
Current Usage : init:14876672, used:0, committed:1441792, max:1441792

|---------------------------------------------------------------------| committed:1.38Mb
+---------------------------------------------------------------------+
| | max:1.38Mb
+---------------------------------------------------------------------+
| used:0b

Pool: PS Old Gen (Heap memory)
Peak Usage : init:954466304, used:281887048, committed:954466304, max:1886519296
Current Usage : init:954466304, used:279802256, committed:954466304, max:1886519296

|----------------------------------| committed:910.25Mb
+---------------------------------------------------------------------+
|////////// | | max:1.76Gb
+---------------------------------------------------------------------+
|---------| used:266.84Mb

Pool: PS Perm Gen (Non-heap memory)
Peak Usage : init:16777216, used:127850824, committed:214171648, max:1073741824
Current Usage : init:16777216, used:127821200, committed:128319488, max:1073741824

|-------| committed:122.38Mb
+---------------------------------------------------------------------+
|///////| | max:1Gb
+---------------------------------------------------------------------+
|-------| used:121.9Mb

Total Memory Pools: 5
Pool: Code Cache (Non-heap memory)
Peak Usage : init:2359296, used:14673408, committed:14712832, max:50331648
Current Usage : init:2359296, used:14672000, committed:14712832, max:50331648

|-------------------| committed:14.03Mb
+---------------------------------------------------------------------+
|///////////////////| | max:48Mb
+---------------------------------------------------------------------+
|-------------------| used:13.99Mb

Pool: PS Eden Space (Heap memory)
Peak Usage : init:89522176, used:229113856, committed:231866368, max:234684416
Current Usage : init:89522176, used:47827272, committed:228982784, max:232718336

|-------------------------------------------------------------------| committed:218.38Mb
+---------------------------------------------------------------------+
|////////////// | | max:221.94Mb
+---------------------------------------------------------------------+
|-------------| used:45.61Mb

Pool: PS Survivor Space (Heap memory)
Peak Usage : init:14876672, used:23715856, committed:34996224, max:34996224
Current Usage : init:14876672, used:0, committed:1572864, max:1572864

|---------------------------------------------------------------------| committed:1.5Mb
+---------------------------------------------------------------------+
| | max:1.5Mb
+---------------------------------------------------------------------+
| used:0b

Pool: PS Old Gen (Heap memory)
Peak Usage : init:954466304, used:281887048, committed:954466304, max:1886519296
Current Usage : init:954466304, used:279509296, committed:954466304, max:1886519296

|----------------------------------| committed:910.25Mb
+---------------------------------------------------------------------+
|////////// | | max:1.76Gb
+---------------------------------------------------------------------+
|---------| used:266.56Mb

Pool: PS Perm Gen (Non-heap memory)
Peak Usage : init:16777216, used:128416856, committed:214171648, max:1073741824
Current Usage : init:16777216, used:128416856, committed:128450560, max:1073741824

|-------| committed:122.5Mb
+---------------------------------------------------------------------+
|///////| | max:1Gb
+---------------------------------------------------------------------+
|-------| used:122.47Mb

Total Memory Pools: 5
Pool: Code Cache (Non-heap memory)
Peak Usage : init:2359296, used:14996864, committed:15106048, max:50331648
Current Usage : init:2359296, used:14995456, committed:15106048, max:50331648

|--------------------| committed:14.41Mb
+---------------------------------------------------------------------+
|////////////////////| | max:48Mb
+---------------------------------------------------------------------+
|-------------------| used:14.3Mb

Pool: PS Eden Space (Heap memory)
Peak Usage : init:89522176, used:229113856, committed:231866368, max:234684416
Current Usage : init:89522176, used:23506784, committed:229113856, max:232194048

|--------------------------------------------------------------------| committed:218.5Mb
+---------------------------------------------------------------------+
|/////// || max:221.44Mb
+---------------------------------------------------------------------+
|------| used:22.42Mb

Pool: PS Survivor Space (Heap memory)
Peak Usage : init:14876672, used:23715856, committed:34996224, max:34996224
Current Usage : init:14876672, used:0, committed:1769472, max:1769472

|---------------------------------------------------------------------| committed:1.69Mb
+---------------------------------------------------------------------+
| | max:1.69Mb
+---------------------------------------------------------------------+
| used:0b

Pool: PS Old Gen (Heap memory)
Peak Usage : init:954466304, used:281951168, committed:954466304, max:1886519296
Current Usage : init:954466304, used:281951168, committed:954466304, max:1886519296

|----------------------------------| committed:910.25Mb
+---------------------------------------------------------------------+
|////////// | | max:1.76Gb
+---------------------------------------------------------------------+
|---------| used:268.89Mb

Pool: PS Perm Gen (Non-heap memory)
Peak Usage : init:16777216, used:128552160, committed:214171648, max:1073741824
Current Usage : init:16777216, used:128552160, committed:128974848, max:1073741824

|-------| committed:123Mb
+---------------------------------------------------------------------+
|///////| | max:1Gb
+---------------------------------------------------------------------+
|-------| used:122.6Mb

I have used <code></code> above because the lines are too long. So we don’t see the HTML tags.
The relevant section is shown below. I am interested in the non-heap memory pool called Code Cache
which holds the JIT compiled code.

<b>Total Memory Pools:</b> 5<blockquote><b>Pool: Code Cache</b> (Non-heap memory)
<blockquote>Peak Usage    : init:2359296, used:14647936, committed:14680064, max:50331648<br>
Current Usage : init:2359296, used:14646848, committed:14680064, max:50331648<blockquote>

First part of the code

library(XML)
library(stringr)

this.dir <- dirname(parent.frame(2)$ofile) 
setwd(this.dir)

tables <- htmlParse("D:\\Log Analysis\\MaxBank\\Oct 24\\memorypools")

y <- xpathSApply(tables,"//b//text()[contains(.,'Pool: Code Cache')]//following::blockquote[1]",xmlValue)
y <- data.frame(y)
y <- apply( y, 1, function(z) str_extract(z,"Current.*?[/|]"))

data <- str_extract_all(y,"[0-9]+(/,|/|)")
data <- data.frame(matrix(unlist(data),ncol=4,byrow=T))
colnames(data) <- c("Init", "Used", "Committed", "Max")


data["Time"] <- "NA"
data$Time <- seq(200, nrow(data)*200, by=200)


data$Used <- as.numeric(levels(data$Used)[data$Used])/(1024*1024)
data$Committed <- as.numeric(levels(data$Committed)[data$Committed])/(1024*1024)
data$Max<- as.numeric(levels(data$Max)[data$Max])/(1024*1024)

The most difficult part was the XPath in this line. ‘R’ has support for XPath. I use a combination of
XPath and Regex to get the current usage data and convert it to MB.

Since I know that the data was collected at an interval of 200 seconds I have added a column to the data frame with this data. The collected data does not have a timestamp.

y <- xpathSApply(tables,"//b//text()[contains(.,'Pool: Code Cache')]//following::blockquote[1]",xmlValue)

Second part of the code

 png(
"code-cache.png",
width =1200, height = 490)


plot(data$Time,as.numeric(data$Used),ylim=c(1,60),col="orangered",pch=2,type="b", ylab="Megabytes", xlab="",las=2,lwd=2,xaxt="n", cex.lab=1.2,cex.axis=1.2)
axis(1,at = seq(min(data$Time), max(data$Time), by=1000),las = 2,cex.axis=1)

par(mar=c(5,5.5,1,1))
par(oma=c(0,0,0,0) )
box("figure",lty="solid", col="green")

title("Time vs Used ,Committed and Maximum Code cache",cex.main=1.5,xlab="Time(Every 200 Seconds)")

points(data$Time,as.numeric(data$Committed),col="green",pch=3,lwd=2, cex.lab=1.2,cex.axis=1,type="b")
points(data$Time,as.numeric(data$Max),col="palevioletred3",pch=16,lwd=2, cex.lab=1.2,cex.axis=1,type="b")

par(xpd=TRUE)
 legend(3.8,-9,c("Used", "Committed", "Maximum"), pch = c(2,3,16), lty = c(1,2,3),col=c('orangered','green','palevioletred3'),ncol=3,bty ="n")

dev.off()

The Committed and Used graph lines are together because the data is almost the same. There are some lines of ‘R’ code that are from the forums. In fact some lines related to graph layout may not be required. I always find it difficult to layout the graph. In this case the legend is at the bottom and finding space for it was hard.

code-cache

When I started exploring this aspect of the JVM memory pool I was not aware that one could dump the current memory pool utilization data like this.

Kirk Pepperdine(jClarity) pointed out that he has a VisualVM plugin(https://java.net/projects/memorypoolview/) to look at JVM memory pools.

‘R’ regex

My Java Virtual Machine memory pool dump is this. I had earlier isolated only Code Cache memory pool for analysis and that is the following section. I converted this to data frame first.

1            Peak Usage    : init:2359296, used:13914944, committed:13959168, max:50331648Current Usage : init:2359296, used:13913536, committed:13959168, max:50331648|------------------| committed:13.31Mb+---------------------------------------------------------------------+|//////////////////|                                                  | max:48Mb+---------------------------------------------------------------------+|------------------| used:13.27Mb
2            Peak Usage    : init:2359296, used:13916608, committed:13959168, max:50331648Current Usage : init:2359296, used:13915200, committed:13959168, max:50331648|------------------| committed:13.31Mb+---------------------------------------------------------------------+|//////////////////|                                                  | max:48Mb+---------------------------------------------------------------------+|------------------| used:13.27Mb
3             Peak Usage    : init:2359296, used:13949120, committed:13991936, max:50331648Current Usage : init:2359296, used:13947712, committed:13991936, max:50331648|------------------| committed:13.34Mb+---------------------------------------------------------------------+|//////////////////|                                                  | max:48Mb+---------------------------------------------------------------------+|------------------| used:13.3Mb
4            Peak Usage    : init:2359296, used:13968576, committed:13991936, max:50331648Current Usage : init:2359296, used:13956224, committed:13991936, max:50331648|------------------| committed:13.34Mb+---------------------------------------------------------------------+|//////////////////|                                                  | max:48Mb+---------------------------------------------------------------------+|------------------| used:13.31Mb

I tried this to cut only Current Usage statistics. The regex is

    greedy

and matches upto the first ‘pipe’ character.

y <- apply( y, 1, function(z) str_extract(z,"Current.*?[/|]"))
  [1] "Current Usage : init:2359296, used:13913536, committed:13959168, max:50331648|"
  [2] "Current Usage : init:2359296, used:13915200, committed:13959168, max:50331648|"
  [3] "Current Usage : init:2359296, used:13947712, committed:13991936, max:50331648|"
  [4] "Current Usage : init:2359296, used:13956224, committed:13991936, max:50331648|"

R users’ list member Arun recommends this

> as.matrix(gsub("^.*(Current.*?[/|]).*","\\1",y$y))
       [,1]                                                                            
  [1,] "Current Usage : init:2359296, used:13913536, committed:13959168, max:50331648|"
  [2,] "Current Usage : init:2359296, used:13915200, committed:13959168, max:50331648|"
  [3,] "Current Usage : init:2359296, used:13947712, committed:13991936, max:50331648|"
  [4,] "Current Usage : init:2359296, used:13956224, committed:13991936, max:50331648|"
  [5,] "Current Usage : init:2359296, used:13968832, committed:14024704, max:50331648|"

Both work as expected.

Average memory utilization of httpd process

I drew a graph showing the average memory utilization of a httpd process. I am not claiming that this is a rigorous approach but I get average figures over a period of time. I don’t have time in the axes because it was not needed.

library(stringr)

this.dir setwd(this.dir)
png(file="httpdaveragememory.png",width=900,height=350,res=72)

input 6.2 httpd (18)
 4.0 httpd (11)
 4.0 httpd (11)
 3.3 httpd (9)
 4.2 httpd (12)
 4.2 httpd (12)
 4.2 httpd (12)
 4.2 httpd (12)
 4.2 httpd (12)
"))

data colnames(data) data["Average"] <- "NA"
data$Average plot(row(data)[,1], data$Average,xlim=c(0,nrow(data)),col="green",pch=16,type="b", ylab="MBytes", xlab="Hours",las=2,lwd=2.5,cex.axis=1)

print(data)
dev.off()

Steps followed to parse the data

> data <- read.table(text=gsub(“[()]”,””,str_trim(input[input!=””])),sep=””,header=FALSE,stringsAsFactors=FALSE)
> data
V1 V2 V3
1 6.2 httpd 18
2 4.0 httpd 11
3 4.0 httpd 11
4 3.3 httpd 9
5 4.2 httpd 12
6 4.2 httpd 12
7 4.2 httpd 12
8 4.2 httpd 12
9 4.2 httpd 12
> colnames(data) <- c(“MB”,”Process”,”Count”)
> data
MB Process Count
1 6.2 httpd 18
2 4.0 httpd 11
3 4.0 httpd 11
4 3.3 httpd 9
5 4.2 httpd 12
6 4.2 httpd 12
7 4.2 httpd 12
8 4.2 httpd 12
9 4.2 httpd 12
> data[“Average”] <- “NA”
> data
MB Process Count Average
1 6.2 httpd 18 NA
2 4.0 httpd 11 NA
3 4.0 httpd 11 NA
4 3.3 httpd 9 NA
5 4.2 httpd 12 NA
6 4.2 httpd 12 NA
7 4.2 httpd 12 NA
8 4.2 httpd 12 NA
9 4.2 httpd 12 NA
> data$Average <- data$MB / data$Count
> data
MB Process Count Average
1 6.2 httpd 18 0.3444444
2 4.0 httpd 11 0.3636364
3 4.0 httpd 11 0.3636364
4 3.3 httpd 9 0.3666667
5 4.2 httpd 12 0.3500000
6 4.2 httpd 12 0.3500000
7 4.2 httpd 12 0.3500000
8 4.2 httpd 12 0.3500000
9 4.2 httpd 12 0.3500000
> row(data)
[,1] [,2] [,3] [,4]
[1,] 1 1 1 1
[2,] 2 2 2 2
[3,] 3 3 3 3
[4,] 4 4 4 4
[5,] 5 5 5 5
[6,] 6 6 6 6
[7,] 7 7 7 7
[8,] 8 8 8 8
[9,] 9 9 9 9
> row(data)[,1]
[1] 1 2 3 4 5 6 7 8 9

Graph

httpdaveragememory

Graph of ‘Time and Hits vs MBytes’ using ‘R’

I am yet to crack the capacity planning method using statistical analysis but I am on my way to that exalted state of expertise.

Time and Hits vs MBytes


this.dir <- dirname(parent.frame(2)$ofile) 
setwd(this.dir)
 
 png(
"daily traffic-hits-bytes.png",
width =1200, height = 868)
par(mar=c(7, 9, 6, 8))
 
data = input <- readLines(textConnection("
07 22,864 27,574 49.79 MB 
08 225,337 252,366 303.75 MB 
09 306,007 318,463 256.01 MB 
10 322,103 331,298 252.89 MB 
11 314,393 322,646 241.72 MB 
12 302,438 309,236 228.91 MB 
13 283,773 290,291 217.17 MB 
14 299,020 306,326 241.34 MB 
15 299,792 307,692 241.76 MB 
16 227,502 232,658 188.31 MB 
17 106,205 108,890 107.65 MB 
18 26,589 27,667 28.13 MB 
19 5,952 6,143 11.72 MB 
20 2,212 2,213 2.49 MB 
21 937 944 1.33 MB"))
 
data <- read.table(text=data,sep=" ",header=FALSE,stringsAsFactors=FALSE,fill=TRUE)
data <- data.frame(data)
colnames(data) <- c("Hours", "Pages", "Hits", "Bandwidth")

plot(data$Hours,as.numeric(gsub(",","", data$Bandwidth)),col="green",pch=16,type="b", ylab="Hits", xlab="",las=2,lwd=2.5,xaxt="n", cex.lab=2,cex.axis=1.6)
axis(1,at = seq(min(data$Hours), max(data$Hours), by=1),las = 2,cex.axis=2)
title("Time and Hits vs MBytes",cex.main=3,xlab="Time(Hours)", cex.lab=2,1)
par(new=TRUE)
plot(data$Hours,as.numeric(gsub(",","",data$Pages)),yaxt="n",xlim=c(min(data$Hours),max(data$Hours)),col="blue",cex.axis=2.0,col.axis="blue",pch=6,type="b",xaxt="n",ylab="",xlab="",las=2,lwd=2.5, cex.lab=2)
mtext("Mbytes",side=4,line=5)
axis(4,at = seq(0, max(as.numeric(gsub(",","",data$Pages))), by=30000),las = 2,cex.axis=1.5)
legend("topleft", lty=c(1,1),lwd=c(3.5,3.5),c("Hits","Mbytes"), fill=c("green","blue"))
#box()
 
dev.off()

‘R’ code to understand number of concurrent connections

Proto Recv-Q Send-Q Local-Address               Foreign-Address             State      
tcp        0      0 112.30.110.2:80             101.13.4.18:3037              SYN_RECV    
tcp        0      0 112.30.110.2:80             101.13.4.18:3036              SYN_RECV    
tcp        0      0 112.30.110.2:80             101.15.1.6:2431               SYN_RECV    
tcp        0      0 112.30.110.2:80             101.16.32.19:1689             SYN_RECV    
tcp        0      0 112.30.110.2:80             101.13.4.18:3035              SYN_RECV    
tcp        0      0 ::ffff:172.210.100.12:80      ::ffff:101.11.5.7:3185        TIME_WAIT   
tcp        0      0 ::ffff:172.210.100.12:80      ::ffff:101.15.1.3:3189        TIME_WAIT   
tcp        0      0 ::ffff:172.210.100.12:80      ::ffff:101.15.5.7:3445        TIME_WAIT   
tcp        0      0 ::ffff:172.210.100.12:80      ::ffff:101.13.29.13:2671       TIME_WAIT   

I wanted to draw a graph showing the number of connections made by an IP(Foreign-Address) to our HTTP servers. This is a rough estimate of the concurrent connections. I know I have been smitten by ‘R’ but the power of this language is breathtaking.

I haven’t yet mastered the functional aspect of it but even so code like this one line to find the
frequency of values is really powerful. This line finds the count of the same IP’s(group) in the ‘Foreign-Address’ column in the data frame.

data <-as.data.frame(table(data$Foreign.Address))

The source code works perfectly but some of the parameters used to plot the graphs may not be needed. They don’t seem to interfere in any way but it is hard to understand all the parameters of the plotting API.


library(stringr)

this.dir <- dirname(parent.frame(2)$ofile) 
setwd(this.dir) 

par(mar=c(4,4,4,4))

data <- read.table("D:\\Log Analysis\\23-9-2013\\concurrentusage-node1",sep="",header=T,stringsAsFactors=FALSE, fill=TRUE)
var <- c("Foreign.Address")
data[,var] <- sapply(data[,var],function(x) ifelse(length(unlist(str_split(x,":")))==5,unlist(str_split(x,":"))[4],unlist(str_split(x,":"))[1]))
var <- c("Local.Address")
data[,var] <- sapply(data[,var],function(x) ifelse(length(unlist(str_split(x,":")))==5,paste(unlist(str_split(x,":"))[4],":",unlist(str_split(x,":"))[5]),
                                                   paste(unlist(str_split(x,":"))[1],":",unlist(str_split(x,":"))[2])))
#Begin stackoverflow.com answer
completeFun <- function(data, desiredCols) {
  completeVec <- complete.cases(data[, desiredCols])
  return(data[completeVec, ])
}
#End stackoverflow.com answer


data <- completeFun(data, c("Local.Address"))
data <- data[data$Proto == "tcp" ,]
data <-as.data.frame(table(data$Foreign.Address))
#data <- data[with(data, order(-Freq)), ]
data <-data.frame(data, stringsAsFactors = FALSE)


png(file="concurrencyhousers.png",width=700,height=250,res=72)

#User type 1
subsetdata <- subset(data, grepl("^172", Var1) & !grepl("^172.20.100.8", Var1) & !grepl("^172.20.100.9", Var1) )

plot(as.numeric(subsetdata$Var1),subsetdata$Freq,ylim=c(0,700),col="green",type="o",ylab="Number of connections",las=2,lwd=2.5,xaxt="n",xlab="IP")

axis(1,at=subsetdata$Var1,labels=subsetdata$Var1,las = 2,cex.axis=0.9,las=2)
title("Estimation of concurrent connections(HO Users-Sep,2013)",cex.main=1.3,line=1)
legend("topleft", lty=c(1,1),lwd=c(3.5,3.5),c(paste("Users",sep="--",length(subsetdata$Var1))))

#sink("parsedconcurrency.log")
#print(data)
#sink()
dev.off()

png(file="concurrencybranchusers.png",width=1300,height=450,res=72)

#User type 1
subsetdata <- subset(data, !grepl("^172", Var1) & !grepl("^127", Var1) )

plot(as.numeric(subsetdata$Var1),subsetdata$Freq,ylim=c(0,700),col="green",type="o",ylab="Number of connections",las=2,lwd=2.5,xaxt="n",xlab="IP")

axis(1,at=subsetdata$Var1,labels=subsetdata$Var1,las = 2,cex.axis=0.9,las=2)
title("Estimation of concurrent connections(Branch Users-Sep,2013)",cex.main=1.8,line=1)
legend("topleft", lty=c(1,1),lwd=c(3.5,3.5),c(paste("Users",sep="--",length(subsetdata$Var1))))

#sink("parsedconcurrency.log")
#print(data)
#sink()
dev.off()

concurrencybranchusers

GC analysis using ‘R’


library(stringr)

this.dir <- dirname(parent.frame(2)$ofile) 
setwd(this.dir) 




input <- readLines(textConnection("
2013-08-24T16:03:28.768+0530: 3.928: [Full GC (System) [PSYoungGen: 3600K->0K(382272K)] [PSOldGen: 0K->3285K(873856K)] 3600K->3285K(1256128K) [PSPermGen: 12862K->12862K(25984K)], 0.0541900 secs] [Times: user=0.06 sys=0.01, real=0.05 secs] 
2013-08-24T16:03:41.095+0530: 16.254: [Full GC (System) [PSYoungGen: 27968K->0K(382272K)] [PSOldGen: 3285K->30483K(873856K)] 31253K->30483K(1256128K) [PSPermGen: 39954K->39954K(70912K)], 0.2661260 secs] [Times: user=0.53 sys=0.01, real=0.27 secs] 
2013-08-24T17:03:41.377+0530: 3616.537: [Full GC (System) [PSYoungGen: 2600K->0K(337152K)] [PSOldGen: 299782K->301931K(873856K)] 302382K->301931K(1211008K) [PSPermGen: 160659K->158703K(285888K)], 1.2217540 secs] [Times: user=1.21 sys=0.01, real=1.22 secs] 
2013-08-24T18:03:43.156+0530: 7218.315: [Full GC (System) [PSYoungGen: 192K->0K(337600K)] [PSOldGen: 301931K->271735K(873856K)] 302123K->271735K(1211456K) [PSPermGen: 158716K->126555K(251904K)], 1.5164700 secs] [Times: user=1.52 sys=0.00, real=1.51 secs] 
2013-08-24T19:03:45.225+0530: 10820.385: [Full GC (System) [PSYoungGen: 288K->0K(338944K)] [PSOldGen: 271735K->271737K(873856K)] 272023K->271737K(1212800K) [PSPermGen: 126568K->126568K(246272K)], 1.2740980 secs] [Times: user=1.28 sys=0.00, real=1.27 secs] 
2013-08-24T20:03:47.052+0530: 14422.212: [Full GC (System) [PSYoungGen: 384K->0K(337792K)] [PSOldGen: 271737K->271740K(873856K)] 272121K->271740K(1211648K) [PSPermGen: 126588K->126588K(237952K)], 1.1500680 secs] [Times: user=1.15 sys=0.00, real=1.15 secs] 
2013-08-24T21:03:48.755+0530: 18023.915: [Full GC (System) [PSYoungGen: 288K->0K(343424K)] [PSOldGen: 271740K->271742K(873856K)] 272028K->271742K(1217280K) [PSPermGen: 126597K->126597K(228096K)], 1.2179020 secs] [Times: user=1.22 sys=0.00, real=1.22 secs] 
2013-08-24T22:03:50.526+0530: 21625.686: [Full GC (System) [PSYoungGen: 352K->0K(340928K)] [PSOldGen: 271742K->271735K(873856K)] 272094K->271735K(1214784K) [PSPermGen: 126606K->126573K(217152K)], 1.2736310 secs] [Times: user=1.27 sys=0.00, real=1.27 secs] 
2013-08-24T23:03:52.353+0530: 25227.513: [Full GC (System) [PSYoungGen: 352K->0K(349696K)] [PSOldGen: 271735K->271737K(873856K)] 272087K->271737K(1223552K) [PSPermGen: 126584K->126584K(206912K)], 1.2725880 secs] [Times: user=1.27 sys=0.00, real=1.27 secs] 
2013-08-25T00:03:54.181+0530: 28829.341: [Full GC (System) [PSYoungGen: 1244K->0K(366528K)] [PSOldGen: 286583K->287548K(873856K)] 287827K->287548K(1240384K) [PSPermGen: 152380K->152380K(227904K)], 1.2271970 secs] [Times: user=1.22 sys=0.00, real=1.22 secs] 
2013-08-25T01:03:55.963+0530: 32431.123: [Full GC (System) [PSYoungGen: 256K->0K(363264K)] [PSOldGen: 287548K->287550K(873856K)] 287804K->287550K(1237120K) [PSPermGen: 152384K->152384K(220544K)], 1.2622580 secs] [Times: user=1.26 sys=0.00, real=1.26 secs] 
2013-08-25T02:03:57.779+0530: 36032.939: [Full GC (System) [PSYoungGen: 320K->0K(372864K)] [PSOldGen: 287550K->284392K(873856K)] 287870K->284392K(1246720K) [PSPermGen: 152392K->151729K(212352K)], 1.5651720 secs] [Times: user=1.57 sys=0.00, real=1.57 secs] 
2013-08-25T03:03:59.898+0530: 39635.058: [Full GC (System) [PSYoungGen: 256K->0K(369664K)] [PSOldGen: 284392K->284394K(873856K)] 284648K->284394K(1243520K) [PSPermGen: 151738K->151738K(205056K)], 1.3093640 secs] [Times: user=1.30 sys=0.00, real=1.31 secs] 
2013-08-25T04:04:01.762+0530: 43236.922: [Full GC (System) [PSYoungGen: 416K->0K(379328K)] [PSOldGen: 284394K->284397K(873856K)] 284810K->284397K(1253184K) [PSPermGen: 151758K->151758K(198336K)], 1.2442820 secs] [Times: user=1.24 sys=0.00, real=1.24 secs] 
2013-08-25T05:04:03.562+0530: 46838.721: [Full GC (System) [PSYoungGen: 224K->0K(376064K)] [PSOldGen: 284397K->284400K(873856K)] 284621K->284400K(1249920K) [PSPermGen: 151766K->151766K(192128K)], 1.2820830 secs] [Times: user=1.29 sys=0.00, real=1.28 secs] 
2013-08-25T06:04:05.398+0530: 50440.558: [Full GC (System) [PSYoungGen: 288K->0K(385664K)] [PSOldGen: 284400K->284357K(873856K)] 284688K->284357K(1259520K) [PSPermGen: 151774K->151735K(186816K)], 1.5174430 secs] [Times: user=1.51 sys=0.00, real=1.52 secs] 
2013-08-25T07:04:07.470+0530: 54042.629: [Full GC (System) [PSYoungGen: 352K->0K(382528K)] [PSOldGen: 284357K->284359K(873856K)] 284709K->284359K(1256384K) [PSPermGen: 151743K->151743K(181632K)], 1.2664900 secs] [Times: user=1.27 sys=0.00, real=1.27 secs] 
2013-08-25T08:04:09.289+0530: 57644.449: [Full GC (System) [PSYoungGen: 384K->0K(391616K)] [PSOldGen: 284359K->284361K(873856K)] 284743K->284361K(1265472K) [PSPermGen: 151751K->151751K(177536K)], 1.2797050 secs] [Times: user=1.28 sys=0.01, real=1.28 secs] 
2013-08-25T09:04:11.124+0530: 61246.283: [Full GC (System) [PSYoungGen: 1302K->0K(392960K)] [PSOldGen: 291028K->291762K(873856K)] 292331K->291762K(1266816K) [PSPermGen: 156943K->156943K(179712K)], 1.3176180 secs] [Times: user=1.31 sys=0.01, real=1.32 secs] 
2013-08-25T10:04:12.997+0530: 64848.157: [Full GC (System) [PSYoungGen: 608K->0K(402880K)] [PSOldGen: 296941K->290294K(873856K)] 297549K->290294K(1276736K) [PSPermGen: 159091K->158257K(177152K)], 1.6291050 secs] [Times: user=1.62 sys=0.00, real=1.63 secs] 
2013-08-25T11:04:15.182+0530: 68450.342: [Full GC (System) [PSYoungGen: 975K->0K(406976K)] [PSOldGen: 294109K->294611K(873856K)] 295085K->294611K(1280832K) [PSPermGen: 159502K->159502K(175936K)], 1.2407930 secs] [Times: user=1.24 sys=0.00, real=1.24 secs] 
2013-08-25T12:04:16.984+0530: 72052.144: [Full GC (System) [PSYoungGen: 2065K->0K(410624K)] [PSOldGen: 299586K->300435K(873856K)] 301652K->300435K(1284480K) [PSPermGen: 162453K->162453K(176448K)], 1.2860060 secs] [Times: user=1.28 sys=0.00, real=1.29 secs] 
2013-08-25T13:04:18.832+0530: 75653.992: [Full GC (System) [PSYoungGen: 576K->0K(413504K)] [PSOldGen: 303252K->303507K(873856K)] 303828K->303507K(1287360K) [PSPermGen: 162992K->162992K(175360K)], 1.3077730 secs] [Times: user=1.31 sys=0.00, real=1.31 secs] 
2013-08-25T14:04:20.700+0530: 79255.859: [Full GC (System) [PSYoungGen: 2432K->0K(412352K)] [PSOldGen: 303507K->288540K(873856K)] 305939K->288540K(1286208K) [PSPermGen: 162994K->160158K(171200K)], 1.4892360 secs] [Times: user=1.49 sys=0.00, real=1.49 secs] 
2013-08-25T15:04:22.750+0530: 82857.910: [Full GC (System) [PSYoungGen: 4096K->0K(416640K)] [PSOldGen: 288540K->289267K(873856K)] 292636K->289267K(1290496K) [PSPermGen: 160643K->160643K(169984K)], 1.2662670 secs] [Times: user=1.27 sys=0.01, real=1.27 secs] 
2013-08-25T16:04:24.579+0530: 86459.739: [Full GC (System) [PSYoungGen: 4224K->0K(414976K)] [PSOldGen: 289267K->289839K(873856K)] 293491K->289839K(1288832K) [PSPermGen: 161142K->161142K(169472K)], 1.2932650 secs] [Times: user=1.29 sys=0.00, real=1.29 secs] 
2013-08-25T17:04:26.436+0530: 90061.596: [Full GC (System) [PSYoungGen: 2688K->0K(419328K)] [PSOldGen: 289839K->289862K(873856K)] 292527K->289862K(1293184K) [PSPermGen: 161150K->161150K(168768K)], 1.3088530 secs] [Times: user=1.31 sys=0.00, real=1.30 secs] 
2013-08-25T18:04:28.308+0530: 93663.468: [Full GC (System) [PSYoungGen: 2720K->0K(418176K)] [PSOldGen: 289862K->288528K(873856K)] 292582K->288528K(1292032K) [PSPermGen: 161158K->160169K(166656K)], 1.3218390 secs] [Times: user=1.32 sys=0.00, real=1.32 secs] 
2013-08-25T19:04:30.190+0530: 97265.349: [Full GC (System) [PSYoungGen: 2016K->0K(421248K)] [PSOldGen: 288528K->288552K(873856K)] 290544K->288552K(1295104K) [PSPermGen: 160177K->160177K(165568K)], 1.3263620 secs] [Times: user=1.33 sys=0.00, real=1.33 secs] 
2013-08-25T20:04:32.076+0530: 100867.235: [Full GC (System) [PSYoungGen: 1984K->0K(420416K)] [PSOldGen: 288552K->288575K(873856K)] 290536K->288575K(1294272K) [PSPermGen: 160185K->160185K(165056K)], 1.3303080 secs] [Times: user=1.33 sys=0.00, real=1.33 secs] 
2013-08-25T21:04:33.966+0530: 104469.126: [Full GC (System) [PSYoungGen: 2304K->0K(422976K)] [PSOldGen: 288575K->288598K(873856K)] 290879K->288598K(1296832K) [PSPermGen: 160193K->160193K(164416K)], 1.3543460 secs] [Times: user=1.35 sys=0.00, real=1.35 secs] 
2013-08-25T22:04:35.883+0530: 108071.043: [Full GC (System) [PSYoungGen: 2496K->0K(422144K)] [PSOldGen: 288598K->288528K(873856K)] 291094K->288528K(1296000K) [PSPermGen: 160201K->160169K(163840K)], 1.3320060 secs] [Times: user=1.33 sys=0.00, real=1.33 secs] 
2013-08-25T23:04:37.778+0530: 111672.937: [Full GC (System) [PSYoungGen: 2688K->0K(424640K)] [PSOldGen: 288528K->288551K(873856K)] 291216K->288551K(1298496K) [PSPermGen: 160177K->160177K(163328K)], 1.3344320 secs] [Times: user=1.33 sys=0.00, real=1.34 secs] 
2013-08-26T00:04:39.676+0530: 115274.836: [Full GC (System) [PSYoungGen: 2720K->0K(423872K)] [PSOldGen: 288551K->288575K(873856K)] 291271K->288575K(1297728K) [PSPermGen: 160185K->160185K(163136K)], 1.3371510 secs] [Times: user=1.34 sys=0.00, real=1.34 secs] 
2013-08-26T01:04:41.568+0530: 118876.728: [Full GC (System) [PSYoungGen: 384K->0K(425728K)] [PSOldGen: 288575K->288607K(873856K)] 288959K->288607K(1299584K) [PSPermGen: 160193K->160193K(162496K)], 1.3421990 secs] [Times: user=1.34 sys=0.00, real=1.34 secs] 
2013-08-26T02:04:43.472+0530: 122478.632: [Full GC (System) [PSYoungGen: 2592K->0K(425408K)] [PSOldGen: 288607K->288529K(873856K)] 291199K->288529K(1299264K) [PSPermGen: 160201K->160169K(161920K)], 1.3468410 secs] [Times: user=1.34 sys=0.00, real=1.35 secs] 
2013-08-26T03:04:45.382+0530: 126080.541: [Full GC (System) [PSYoungGen: 2656K->0K(427136K)] [PSOldGen: 288529K->288552K(873856K)] 291185K->288552K(1300992K) [PSPermGen: 160186K->160186K(161920K)], 1.3422060 secs] [Times: user=1.34 sys=0.00, real=1.34 secs] 
2013-08-26T04:04:47.286+0530: 129682.446: [Full GC (System) [PSYoungGen: 2688K->0K(426496K)] [PSOldGen: 288552K->288575K(873856K)] 291240K->288575K(1300352K) [PSPermGen: 160194K->160194K(161408K)], 1.3432010 secs] [Times: user=1.35 sys=0.00, real=1.35 secs] 
2013-08-26T05:04:49.189+0530: 133284.349: [Full GC (System) [PSYoungGen: 1728K->0K(428224K)] [PSOldGen: 288575K->288599K(873856K)] 290303K->288599K(1302080K) [PSPermGen: 160205K->160205K(161280K)], 1.3453110 secs] [Times: user=1.34 sys=0.00, real=1.34 secs] 
2013-08-26T06:04:51.095+0530: 136886.255: [Full GC (System) [PSYoungGen: 2048K->0K(427776K)] [PSOldGen: 288599K->288529K(873856K)] 290647K->288529K(1301632K) [PSPermGen: 160213K->160181K(161344K)], 1.3442980 secs] [Times: user=1.35 sys=0.00, real=1.34 secs] 
2013-08-26T07:04:53.001+0530: 140488.161: [Full GC (System) [PSYoungGen: 2368K->0K(429120K)] [PSOldGen: 288529K->288552K(873856K)] 290897K->288552K(1302976K) [PSPermGen: 160189K->160189K(161216K)], 1.3452220 secs] [Times: user=1.34 sys=0.00, real=1.34 secs] 
2013-08-26T08:04:54.908+0530: 144090.068: [Full GC (System) [PSYoungGen: 6091K->0K(419584K)] [PSOldGen: 311930K->313962K(873856K)] 318022K->313962K(1293440K) [PSPermGen: 169186K->169186K(176128K)], 1.4025960 secs] [Times: user=1.40 sys=0.00, real=1.40 secs] 
2013-08-26T09:04:56.871+0530: 147692.031: [Full GC (System) [PSYoungGen: 4608K->0K(417216K)] [PSOldGen: 721219K->405521K(873856K)] 725828K->405521K(1291072K) [PSPermGen: 200747K->200747K(227200K)], 1.6779290 secs] [Times: user=1.67 sys=0.01, real=1.68 secs] 
2013-08-26T10:04:59.107+0530: 151294.266: [Full GC (System) [PSYoungGen: 448K->0K(418880K)] [PSOldGen: 532766K->370092K(873856K)] 533214K->370092K(1292736K) [PSPermGen: 212473K->211292K(236544K)], 2.0952720 secs] [Times: user=2.10 sys=0.00, real=2.09 secs] 
2013-08-26T11:05:01.760+0530: 154896.919: [Full GC (System) [PSYoungGen: 2540K->0K(422208K)] [PSOldGen: 539017K->432818K(873856K)] 541558K->432818K(1296064K) [PSPermGen: 216295K->216295K(239296K)], 1.7726100 secs] [Times: user=1.77 sys=0.00, real=1.78 secs] 
2013-08-26T12:05:04.092+0530: 158499.252: [Full GC (System) [PSYoungGen: 4662K->0K(421568K)] [PSOldGen: 597561K->444897K(873856K)] 602224K->444897K(1295424K) [PSPermGen: 222015K->222015K(242368K)], 1.8551220 secs] [Times: user=1.85 sys=0.00, real=1.85 secs] 
2013-08-26T13:05:06.506+0530: 162101.666: [Full GC (System) [PSYoungGen: 3168K->0K(424256K)] [PSOldGen: 597850K->442066K(873856K)] 601018K->442066K(1298112K) [PSPermGen: 225426K->225426K(244608K)], 1.8385190 secs] [Times: user=1.84 sys=0.00, real=1.83 secs] 
2013-08-26T14:05:08.910+0530: 165704.069: [Full GC (System) [PSYoungGen: 3676K->0K(411328K)] [PSOldGen: 656036K->415314K(873856K)] 659712K->415314K(1285184K) [PSPermGen: 227539K->223902K(241856K)], 2.1566410 secs] [Times: user=2.16 sys=0.00, real=2.16 secs] 
2013-08-26T15:05:11.624+0530: 169306.784: [Full GC (System) [PSYoungGen: 1409K->0K(419712K)] [PSOldGen: 591866K->456335K(873856K)] 593276K->456335K(1293568K) [PSPermGen: 226173K->226173K(242944K)], 1.9383440 secs] [Times: user=1.94 sys=0.00, real=1.94 secs] 
2013-08-26T16:05:14.123+0530: 172909.283: [Full GC (System) [PSYoungGen: 3222K->0K(409216K)] [PSOldGen: 701507K->482170K(873856K)] 704729K->482170K(1283072K) [PSPermGen: 230151K->230151K(244992K)], 1.9809930 secs] [Times: user=1.98 sys=0.01, real=1.98 secs] 
2013-08-26T17:05:16.664+0530: 176511.823: [Full GC (System) [PSYoungGen: 4809K->0K(392192K)] [PSOldGen: 689255K->432828K(873856K)] 694065K->432828K(1266048K) [PSPermGen: 234505K->234505K(247616K)], 1.8189030 secs] [Times: user=1.81 sys=0.00, real=1.82 secs] 
2013-08-26T18:05:19.040+0530: 180114.200: [Full GC (System) [PSYoungGen: 1152K->0K(406592K)] [PSOldGen: 474135K->339348K(873856K)] 475287K->339348K(1280448K) [PSPermGen: 235014K->227479K(239936K)], 1.9517330 secs] [Times: user=1.95 sys=0.00, real=1.95 secs] 
2013-08-26T19:05:21.549+0530: 183716.709: [Full GC (System) [PSYoungGen: 2794K->0K(411648K)] [PSOldGen: 347094K->349430K(873856K)] 349888K->349430K(1285504K) [PSPermGen: 227894K->227894K(239936K)], 1.5431780 secs] [Times: user=1.54 sys=0.00, real=1.55 secs] 
2013-08-26T20:05:23.649+0530: 187318.809: [Full GC (System) [PSYoungGen: 480K->0K(415872K)] [PSOldGen: 359933K->360054K(873856K)] 360413K->360054K(1289728K) [PSPermGen: 229702K->229702K(240448K)], 1.6184180 secs] [Times: user=1.61 sys=0.01, real=1.61 secs] 
2013-08-26T21:05:25.851+0530: 190921.011: [Full GC (System) [PSYoungGen: 6976K->0K(402240K)] [PSOldGen: 383142K->363210K(873856K)] 390118K->363210K(1276096K) [PSPermGen: 230308K->230308K(239744K)], 1.5142840 secs]"))


# keep only the data
time <- str_extract(input,"T[^.]*")
timeframex<-data.frame(time)
timeframey<-subset(timeframex, timeframex[1] != "NA")
timeframey<-substring(timeframey$time,2,9)
timeframey <- timeframey[-1]
timeframey <- data.frame(timeframey)

duration <- str_extract(input,"real=(.*)(secs)")
duration <- gsub("[^0-9.]","",duration)
durationx<-data.frame(duration)
durationy<-subset(durationx, durationx[1] != "NA")


colnames(timeframey)<-c("duration")
timevsduration <- data.frame(timeframey,durationy)

par(mar=c(10,4,4,2))
set1 <- timevsduration[1:8,]
set2 <- timevsduration[9:24,]
set3 <- timevsduration[25:22,]

png(file="fullgc1.png",width=1400,height=450,res=72)

mgp=c(3,1,0)
set1$duration<- as.POSIXct(paste('2013-08-24', set1$duration))
plot(set1$duration,as.numeric(levels(set1$duration.1)[set1$duration.1]),type="b",col = "blue",  ylim=c(0,max(as.numeric(levels(set1$duration.1)[set1$duration.1]))),ylab="Duration", xaxt = 'n', xlab="Time",las=2,lwd=2.5, lty=1,cex.axis=1.2)

axis(1, at = set1$duration, labels = set1$duration, las = 2,cex.axis=1.2)
text(set1$duration,as.numeric(levels(set1$duration.1)[set1$duration.1]), as.numeric(levels(set1$duration.1)[set1$duration.1]), 2, cex=1.45)
dev.off()

png(file="fullgc2.png",width=1400,height=350,res=72)

set2$duration<- as.POSIXct(paste('2013-08-25', set2$duration))
plot(set2$duration,as.numeric(levels(set2$duration.1)[set2$duration.1]),type="b",col = "blue",  ylab="Duration", xaxt = 'n', xlab="Time",las=2,lwd=2.5, lty=1,cex.axis=1.2)
# now plot you times
axis(1,at = set2$duration, labels = set2$duration, las = 2,cex.axis=1.2)
text(set2$duration,as.numeric(levels(set2$duration.1)[set2$duration.1]), as.numeric(levels(set2$duration.1)[set2$duration.1]), 2, cex=1.45)

dev.off()
  
png(file="fullgc3.png",width=1400,height=350,res=72)

set3$duration<- as.POSIXct(paste('2013-08-26', set3$duration))
plot(set3$duration,as.numeric(levels(set3$duration.1)[set3$duration.1]),type="b",col = "blue",  ylab="Duration", xaxt = 'n', xlab="Time",las=2,lwd=2.5, lty=1,cex.axis=1.2)
# now plot you times
axis(1, at = set3$duration, labels = set3$duration, las = 2,cex.axis=1.2)
text(set3$duration,as.numeric(levels(set3$duration.1)[set3$duration.1]), as.numeric(levels(set3$duration.1)[set3$duration.1]), 2, cex=1.45)

dev.off()

fullgc1

fullgc2

fullgc3

Plotting ‘time’ values

Data in ‘time’ format seems to need a different type of process to plot properly. This code uses strptime to get a proper graph. I have plotted two sets of data on the same plot. This is not visually appealing but serves the purpose. So here the linux ‘pmap’ ouput, ‘Kbytes’ and ‘RSS’ are both plotted against the same time values.

The y-axis label colours differentiate the graphs from one another.


13:07:05 2691296 1600864 1583804
13:08:45 2691296 1601280 1584220
13:10:25 2691296 1601280 1584220
13:12:05 2691296 1601480 1584420
13:13:45 2691296 1601820 1584760
13:15:25 2691296 1601852 1584792
13:17:05 2691296 1601960 1584900
13:18:45 2691296 1601996 1584936
13:20:25 2691296 1603548 1586488


this.dir <- dirname(parent.frame(2)$ofile) 
setwd(this.dir)


data = read.table("D:\\Log analysis\\pmapdata-node1.1",header=F)
colnames(data) <- c("Time","Kbytes","RSS","Dirty Mode")


png(
"pmapanalysis4705.png",
width = 2324, height = 868)
par(mar=c(7, 9, 6, 8))

plot(strptime(data$Time,"%H:%M:%S"),data$Kbytes,pch=0,type="b",col = "red", col.axis="red", ylab="", xlab="",las=2,lwd=2.5,cex.axis=1.5)
title("",cex.main=3,xlab="Time", line=5.2,ylab="Kbytes", cex.lab=2,1)
par(new=T)
plot(strptime(data$Time,"%H:%M:%S"),data$RSS,col="blue",cex.axis=1.3,col.axis="blue",pch=6,type="b",xaxt="n",ylab="",xlab="",las=2,lwd=2.5)
legend("topleft", lty=c(1,1),lwd=c(3.5,3.5),c("Kbytes","RSS"), fill=c("red","blue"))
box()

dev.off()

 

pmapanalysis4705

One problem with this graph is that very few time values are plotted on the x-axis. I don’t know the reason for this but when I asked the ‘R’ forum Jim Holtman suggested this code.


this.dir <- dirname(parent.frame(2)$ofile) 
setwd(this.dir)


data = read.table("D:\\Log analysis\\pmapdata-node1.1",header=F)
colnames(data) <- c("Time","Kbytes","RSS","Dirty Mode")


png(
"pmapanalysis4705.png",
width = 2324, height = 868)
par(mar=c(7, 9, 6, 8))

data$tod <- as.POSIXct(paste('2013-08-28', data$Time))
plot(data$tod,data$Kbytes,type="b",col = "blue", ylab="", xaxt = 'n', xlab="",las=2,lwd=2.5, lty=1,cex.axis=1.5)
# now plot you times
axis(1, at = data$tod, labels = data$Time, las = 2)

box()

dev.off()

 

pmapanalysis4705

Update : Suggestion from Jim Lemon to use ‘plotrix’

this.dir <- dirname(parent.frame(2)$ofile) 
setwd(this.dir) 


data = read.table("D:\\Log analysis\\pmapdata-node1.1",header=F)
colnames(data) <- c("Time","Kbytes","RSS","Dirty Mode")


png(
  "pmapanalysis4705.png",
   width = 2324, height = 868)
par(mar=c(7, 9, 6, 8))

plot(strptime(data$Time,"%H:%M:%S"),data$Kbytes,pch=0,
  type="b",col="red",col.axis="red", ylab="",
  xlab="",las=2,lwd=2.5,xaxt="n")
library(plotrix)
staxlab(at=as.numeric(strptime(data$Time,"%H:%M:%S")),
  labels=as.character(data$Time),nlines=3,srt=90)

box()

dev.off()

pmapanalysis4705