string1 = "http://www.google.com.hk/search?sclient=psy-ab&hl=en&newwindow=1&safe=strict&biw=1440&bih=693&noj=1&source=hp&q=wicket+1.5+URL&oq=wicket+1.5+URL&aq=f&aqi=g2&aql=&gs_sm=e&gs_upl=3231l4087l0l4226l4l4l0l0l0l2l302l832l2-2.1l3l0";
if (string1.include? "?")
string1.insert(-1, "&")
string1.gsub!(/=(.*?)&/, "&")
puts string1.chomp!("&")
end
http://www.google.com.hk/search?sclient&hl&newwindow&safe&biw&bih&noj&source&q&oq&aq&aqi&aql&gs_sm&gs_upl
- Health indicator: it will show you if the current status of your application farm is in good shape or not; or let you predict the trend;
- Find out the bottleneck of your system from a high level, it is really helpful for Engineers to get start to get issue fixed;
- Help to do trouble shooting: the counters will drive us to the right direction from different angles to find the root cause instead of "smart guess";
- Operation management： Capacity Planning and Risk management， try to resolve any performance or stability issues before it comes!
| Counters For OS | Explaination | |
|---|---|---|
| Server Uptime | elapse time since server recent start up | |
| Processor--Total CPU% | the percentage of elapsed time that the processor spends to execute a non-Idle thread. | |
| Processor--% User Time | the percentage of elapsed time the processor spends in the user mode. | |
| System--Processor Queue Length | the number of threads in the processor queue. There is a single queue for processor time even on computers with multiple processors. Therefore, if a computer has multiple processors, you need to divide this value by the number of processors servicing the workload. A sustained processor queue of less than 10 threads per processor is normally acceptable, dependent of the workload. | |
| Memory--% MEM in use | the ratio of Memory\\Committed Bytes to the Memory\\Commit Limit. | |
| Memory--pages/sec | the rate at which pages are read from or written to disk to resolve hard page faults. | |
| Disk Space--DISK C: | the percentage of Used space on Disk C | |
| Disk Space--DISK D: | the percentage of Used space on Disk D | |
| Disk Space--DISK E: | the percentage of Used space on Disk E | |
| DISK IO --Avg. Disk Queue Length | the average number of both read and write requests that were queued for the selected disk during the sample interval. | |
| DISK IO --% Disk Time | the percentage of elapsed time that the selected disk drive was busy servicing read or write requests. | |
| DISK IO --Avg. Disk sec/Read | the average time, in seconds, of a read of data from the disk. | |
| DISK IO --Avg. Disk sec/Write | the average time, in seconds, of a write of data to the disk. | |
| DISK IO --Disk Reads/sec | the rate of read operations on the disk. | |
| DISK IO --Disk Writes/sec | the rate of write operations on the disk. | |
| NetWork IO--Packets Sent/sec | the rate at which packets are sent on the network interface. | |
| NetWork IO--Packets received/sec | the rate at which packets are received on the network interface. | |
| TCP--TCP Connections EST | the number of TCP connections for which the current state is either ESTABLISHED or CLOSE-WAIT | |
| Total Process cnt | Total number of processes on the server | |
| Counters For Specific Process instance | Explaination | |
|---|---|---|
| Apache Http Server -- Apache Process | ||
| Process Uptime | elapse time since apache process recent start up | |
| Process CPU% | the percentage of elapsed time that the processor spends on Apache Process. | |
| Process Memory in use | Memory usage by apache process | |
| Busy workers cnt | the number of threads which are in use for requests | |
| Idle workers cnt | the number of threads which are not receiving any request | |
| requests/sec | throughput of apache Http server | |
| KB/sec | throughput of apache Http server | |
| Application Server -- Java Process | ||
| Process Uptime | elapse time since java process recent start up | |
| Process CPU% | the percentage of elapsed time that the processor spends on java Process. | |
| Private Bytes | the current size, in bytes, of memory that this process has allocated that cannot be shared with other processes. | |
| Working Set | Working Set is the current size, in bytes, of the Working Set of this process. The Working Set is the set of memory pages touched recently by the threads in the process | |
| Used Heap Size | JVM Heap size is in use currently | |
| Live Threads cnt | The number of threads currently active in this process | |
| Accumulate GCTime | the total time taken by GC activities | |
| Async Server--JMS MQ Process | ||
| Process Uptime | elapse time since JMS process recent start up | |
| Process CPU% | the percentage of elapsed time that the processor spends on JMS Process. | |
| Private Bytes | the current size, in bytes, of memory that this process has allocated that cannot be shared with other processes. | |
| Working Set | Working Set is the current size, in bytes, of the Working Set of this process. The Working Set is the set of memory pages touched recently by the threads in the process | |
| Message Queue Depth | the current number of messages that are waiting on the queue | |
| DLQ cnt | the current number of messages which in Dead Letter Queue | |
| Live Threads cnt | The number of threads currently active in this process | |
| DB Connections cnt | the current number of open database connections used by this process | |
| DB Server -- SQL Server Process | ||
| Process Uptime | elapse time since SQL Server process recent start up | |
| Process CPU% | the percentage of elapsed time that the processor spends on SQL Server Process. | |
| Process Memory in use | Memory usage by SQL Server process | |
| Free Space in Temp DB | Tracks free space in tempdb in kilobytes | |
| User Connections | the current number of connections (and users) are using the server | |
| Buffer Cache Hit Ratio | indicates how often SQL Server goes to the buffer, not the hard disk, to get data. Had better larger than 90% | |
| Full Scans/Sec | the number of unrestricted full scans during unit time. These can either be base table or full index scans. | |
| Transactions/Sec | The number of transactions started for the database during unit time | |
| Average Wait Time | the average amount of wait time (milliseconds) for each lock request that resulted in a wait |
170609.479: [GC 170609.479: [ParNew: 1699544K->17689K(1887488K), 0.0537160 secs] 1728778K->47004K(5033216K) icms_dc=0 , 0.0538078 secs] [Times: user=0.08 sys=0.00, real=0.06 secs]
172980.190: [GC 172980.190: [ParNew: 1695513K->4310K(1887488K), 0.0147373 secs] 1724828K->33657K(5033216K) icms_dc=0 , 0.0148245 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]
174228.363: [Full GC 174228.363: [CMS: 29346K->31421K(3145728K), 0.5658221 secs] 955586K->31421K(5033216K), [CMS Perm : 58212K->57316K(58536K)] icms_dc=0 , 0.5660007 secs] [Times: user=0.51 sys=0.00, real=0.56 secs]
174228.930: [GC [1 CMS-initial-mark: 31421K(3145728K)] 31421K(5033216K), 0.0013385 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 174228.931: [CMS-concurrent-mark-start]
175694.396: [GC 175694.396: [ParNew: 1677824K->25622K(1887488K), 0.0726440 secs] 1709245K->57044K(5033216K) icms_dc=0 , 0.0727338 secs] [Times: user=0.06 sys=0.00, real=0.06 secs]
177309.350: [GC 177309.350: [ParNew: 1703446K->23200K(1887488K), 0.0730725 secs] 1734868K->54622K(5033216K) icms_dc=0 , 0.0731623 secs] [Times: user=0.06 sys=0.00, real=0.06 secs] 179729.274: [GC 179729.274: [ParNew: 1701024K->4428K(1887488K), 0.0138419 secs] 1732446K->35850K(5033216K) icms_dc=0 , 0.0139156 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]I am always confused and painful to get what the exactly time stamp of each GC activity is(BTW, currently i am using GCViewer to do the analysis), so that i can not easily to correlate the GC log with Access log when doing further analyzing and trouble shooting the memory problems... So i am writing a ruby program to calculate the time stamp for your further investigation， called gcanalyzer.rb:
require 'csv'
def gcanalyzer(filename)
i = File.new(filename);
arr1 = [0];
arr2 = [];
@@maxpasuetime = 0.0000;
@@fullgc_count = 0;
m = 0;
endstamp = i.mtime
if (!endstamp.isdst) #Summer Time
zone = 15
else
zone = 16
end
a = i.readlines()
endsec = a[a.count-1].to_i
outputfilename = 'GC_log' + endstamp.strftime("_%m-%d-%H%M%S") + '.csv';
j = File.new(filename);
open(outputfilename, "a"){|f|
j.each_line { |line|
if (s = line.split('->')[2])!= nil
offset = endsec - line.split(':')[0].to_i
ctime = endstamp - offset -zone*3600
timestamp = ctime.strftime("%m/%d-%H:%M:%S")
usedheap = s.split('K(')[0]
f << timestamp + "," + usedheap + "\n"
#prepare pause time
# This is for +UseParallelGC
if line =~/PSYoungGen/
if line =~ /Full/
@@fullgc_count = @@fullgc_count + 1
arr2.push(timestamp);
end
t1 = line.split(',')[1]
elsif # This is for CMS case
if line =~ /Full/
@@fullgc_count = @@fullgc_count + 1
arr2.push(timestamp);
t1 = line.split(',')[3]
elsif
t1 = line.split(',')[2]
end
end
pausetime = t1.split('secs')[0].strip.to_f
arr1[0] = arr1[0] + pausetime
#prepare maxpausetime
if pausetime > @@maxpasuetime
@@maxpasuetime = pausetime;
end
end
}
}
elapsedday = endsec/(24*3600);
ed = (endsec - elapsedday*24*3600);
elapsedhour = ed/3600;
elapsedmin = (ed - elapsedhour*3600)/60;
printf("Total Elapse Time: %d (%dday-%dhour-%dmin)\n", endsec, elapsedday, elapsedhour,elapsedmin) ;
printf("Total GC Puase Time: %.3f \n" , arr1[0]) ;
printf("GC Throughput: %.3f \n" ,(1-arr1[0]/endsec)*100) ;
printf("Max Pause Time: %.3f \n",@@maxpasuetime) ;
printf("Avg Puase Time: %.3f \n", (arr1[0]/(a.count-1)));
printf("Total GC Occurency: %d \n", (a.count-1));
printf("GC Frenquency: %.3f \n", endsec/(a.count-1));
printf("Full GC Occurency: %d \n", @@fullgc_count);
printf("Full GC Time stamp: #{arr2}");
# consider to make a chart based on new file in the future
end
>ruby gcanalyzer.rb "D:\\app01_garbage_collection.log"There will be a new file created with accurate time stamp of each GC, and also Output Summary info to the console, something like this:
Total Elapse Time: 2341621 (27day-2hour-27min)
Total GC Puase Time: 636.061
GC Throughput(%): 99.973
Max Pause Time: 0.566
Avg Puase Time: 0.162
Total GC Occurency: 3936
GC Frenquency(sec): 594.000
Full GC Occurency: 1
Full GC Time stamp: ["09/25-05:51:15"]
Overall Performance Engineering Methodology:
* Performance Analysis for Java Web Sites By Stacy Joines
* Software Performance and Scalability: A Quantitative Approach By Henry Liu
* Improve .Net Application Performance and Scalability By Microsoft
* Building Scalable Web Sites By Cal Henderson
Performance Testing Process & Practice:
* Performance Testing Guidance for Web Application By Microsoft
* The Art of Application Performance Testing By Ian Molyneaux
DB Performance tuning:
* Inside SQL Server 2005 Query Tuning and Optimization By Kalen Delaney
* High Performance MySQL By Baron Shwartz
Programming Language Performance Tuning:
* Effective Java By Joshua Bloch
* Java Concurrency in Practice By Brian Goetz
* The Art of Concurrency by Clay Breshears
* Java Performance Tuning by Jack Shirazi
Front-End Performance Optimization Practice:
* High Perforamnce WebSites By Steve Souders
* Even Faster WebSites By Steve Souders
* High Performance Javascript By Zakas
Web Operations and Capacity Planning:
* Web Operations By John Allspaw
* The Art of Capacity Planning By John Allspaw
"1658227@qtp-25018827-56" - Thread t@321
java.lang.Thread.State: WAITING
at java.lang.Object.wait(Native Method)
- waiting on <103344b> (a com.mchange.v2.resourcepool.BasicResourcePool)
at com.mchange.v2.resourcepool.BasicResourcePool.awaitAvailable(BasicResourcePool.java:1315)
at com.mchange.v2.resourcepool.BasicResourcePool.prelimCheckoutResource(BasicResourcePool.java:557)
at com.mchange.v2.resourcepool.BasicResourcePool.checkoutResource(BasicResourcePool.java:477)
at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutPooledConnection(C3P0PooledConnectionPool.java:525)
at com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource.getConnection(AbstractPoolBackedDataSource.java:128)
at org.apache.ibatis.session.defaults.DefaultSqlSessionFactory.openSessionFromDataSource(DefaultSqlSessionFactory.java:72)
at org.apache.ibatis.session.defaults.DefaultSqlSessionFactory.openSession(DefaultSqlSessionFactory.java:32)
1297 while ((avail = unused.size()) == 0)
1298 {
1299 // the if case below can only occur when 1) a user attempts a
1300 // checkout which would provoke an acquire; 2) this
1301 // increments the pending acquires, so we go to the
1302 // wait below without provoking postAcquireMore(); 3)
1303 // the resources are acquired; 4) external management
1304 // of the pool (via for instance unpoolResource()
1305 // depletes the newly acquired resources before we
1306 // regain this' monitor; 5) we fall into wait() with
1307 // no acquires being scheduled, and perhaps a managed.size()
1308 // of zero, leading to deadlock. This could only occur in
1309 // fairly pathological situations where the pool is being
1310 // externally forced to a very low (even zero) size, but
1311 // since I've seen it, I've fixed it.
1312 if (pending_acquires == 0 && managed.size() < max)
1313 _recheckResizePool();
1314
1315 this.wait(timeout);
1316 if (timeout > 0 && System.currentTimeMillis() - start > timeout)
1317 throw new TimeoutException("A client timed out while waiting to acquire a resource from " + this + " -- timeout at awaitAvailable()");
1318 if (force_kill_acquires)
1319 throw new CannotAcquireResourceException("A ResourcePool could not acquire a resource from its primary factory or source.");
1320 ensureNotBroken();
1321 }
checkoutTimeout
Default: 0
The number of milliseconds a client calling getConnection() will wait for a Connection to be checked-in or acquired when the pool is exhausted. Zero means wait indefinitely. Setting any positive value will cause the getConnection() call to time-out and break with an SQLException after the specified number of milliseconds.
unreturnedConnectionTimeout
Default: 0
Seconds. If set, if an application checks out but then fails to check-in [i.e. close()] a Connection within the specified period of time, the pool will unceremoniously destroy() the Connection. This permits applications with occasional Connection leaks to survive, rather than eventually exhausting the Connection pool. And that's a shame. Zero means no timeout, applications are expected to close() their own Connections. Obviously, if a non-zero value is set, it should be to a value longer than any Connection should reasonably be checked-out. Otherwise, the pool will occasionally kill Connections in active use, which is bad. This is basically a bad idea, but it's a commonly requested feature. Fix your $%!@% applications so they don't leak Connections! Use this temporarily in combination with debugUnreturnedConnectionStackTraces to figure out where Connections are being checked-out that don't make it back into the pool!
checkoutTimeout= 30000
unreturnedConnectionTimeout=30
SELECT TOP 50
DB_Name(dbid) AS [DB_Name],
total_worker_time/execution_count AS [Avg_CPU_Time],
total_elapsed_time/execution_count AS [Avg_Duration],
total_elapsed_time AS [Total_Duration],
total_worker_time AS [Total_CPU_Time],
execution_count,
SUBSTRING(st.text, (qs.statement_start_offset/2)+1,
((CASE qs.statement_end_offset
WHEN -1 THEN DATALENGTH(st.text)
ELSE qs.statement_end_offset
END - qs.statement_start_offset)/2) + 1) AS statement_text
FROM sys.dm_exec_query_stats AS qs
CROSS APPLY sys.dm_exec_sql_text(qs.sql_handle) AS st
WHERE dbid in (
SELECT DB_ID('yourtablename') AS [Database ID]
)
ORDER BY Avg_CPU_Time DESC;
SELECT TOP 50
DB_Name(dbid) AS [DB_Name],
Execution_Count,
(total_logical_reads/Cast(execution_count as Decimal(38,16))) as avg_logical_reads,
(total_logical_writes/Cast(execution_count as Decimal(38,16))) as avg_logical_writes,
(total_physical_reads/Cast(execution_count as Decimal(38,16))) as avg_physical_reads,
max_logical_reads,
max_logical_writes,
max_physical_reads,
SUBSTRING(st.text, (qs.statement_start_offset/2)+1,
((CASE qs.statement_end_offset
WHEN -1 THEN DATALENGTH(st.text)
ELSE qs.statement_end_offset
END - qs.statement_start_offset)/2) + 1) AS statement_text
FROM sys.dm_exec_query_stats AS qs
CROSS APPLY sys.dm_exec_sql_text(qs.sql_handle) AS st
WHERE dbid in (
SELECT DB_ID('yourtablename') AS [Database ID]
)
ORDER BY avg_logical_reads DESC;
SELECT top 50
idx.name as Index_name
,obj.name
,dmv.object_id
,sampledatetime=Getdate()
,dmv.index_id
,user_seeks
,user_scans
,user_lookups
FROM sys.dm_db_index_usage_stats dmv
INNER JOIN sys.indexes idx on dmv.object_id = idx.object_id and dmv.index_id = idx.index_id
Cross Apply sys.objects obj
WHERE dmv.object_id = obj.object_id and database_id in (
SELECT DB_ID('yourtablename') AS [Database ID]
)
ORDER BY user_scans desc
SELECT TOP 50
DB_NAME(qt.dbid),
[Average Time Blocked] = (total_elapsed_time - total_worker_time) / qs.execution_count,
[Total Time Blocked] = total_elapsed_time - total_worker_time,
[Execution count] = qs.execution_count,
SUBSTRING(qt.text, (qs.statement_start_offset/2)+1,
((CASE qs.statement_end_offset
WHEN -1 THEN DATALENGTH(qt.text)
ELSE qs.statement_end_offset
END - qs.statement_start_offset)/2) + 1) AS statement_text,
[Parent Query] = qt.text
FROM sys.dm_exec_query_stats qs
CROSS APPLY sys.dm_exec_sql_text(qs.sql_handle) as qt
WHERE DB_NAME(qt.dbid) = 'yourtablename'
ORDER BY [Average Time Blocked] DESC;
SELECT getdate(),
SUM(user_object_reserved_page_count) * 8 as user_objects_kb,
SUM(internal_object_reserved_page_count) * 8 as internal_objects_kb,
SUM(version_store_reserved_page_count) * 8 as version_store_kb,
SUM(unallocated_extent_page_count) * 8 as freespace_kb
FROM sys.dm_db_file_Space_Usage
where database_id = 2
DECLARE @ts_now bigint;
SELECT @ts_now = cpu_ticks / CONVERT(float, cpu_ticks_in_ms) FROM sys.dm_os_sys_info
SELECT TOP(10) SQLProcessUtilization AS [SQL Server Process CPU Utilization],
SystemIdle AS [System Idle Process],
100 - SystemIdle - SQLProcessUtilization AS [Other Process CPU Utilization],
DATEADD(ms, -1 * (@ts_now - [timestamp]), GETDATE()) AS [Event Time]
FROM (
SELECT record.value('(./Record/@id)[1]', 'int') AS record_id,
record.value('(./Record/SchedulerMonitorEvent/SystemHealth/SystemIdle)[1]', 'int')
AS [SystemIdle],
record.value('(./Record/SchedulerMonitorEvent/SystemHealth/ProcessUtilization)[1]', 'int')
AS [SQLProcessUtilization], [timestamp]
FROM (
SELECT [timestamp], CONVERT(xml, record) AS [record]
FROM sys.dm_os_ring_buffers
WHERE ring_buffer_type = N'RING_BUFFER_SCHEDULER_MONITOR'
AND record LIKE '%<SystemHealth>%') AS x
) AS y
ORDER BY record_id DESC;
select loginame, *
from master.dbo.sysprocesses
where spid> 50
order by cpu desc
dbcc inputbuffer(102)
@Profiled
public void clickLoginBtn() throws InterruptedException{
driver.findElement(By.id("login")).click();
if(!myWaiter.waitForMe(By.cssSelector("div.starcite-hyperlink"), 25, timeout)) return ;
}
import java.lang.annotation.ElementType;
import java.lang.annotation.Retention;
import java.lang.annotation.RetentionPolicy;
import java.lang.annotation.Target;
@Retention(RetentionPolicy.RUNTIME)
@Target(ElementType.METHOD)
public @interface Profiled {
}
import com.google.inject.AbstractModule;
import com.google.inject.matcher.Matchers;
public class ProfiledModule extends AbstractModule {
@Override
public void configure() {
// TODO Auto-generated method stub
PerfTracing perftracing = new PerfTracing();
requestInjection(perftracing);
bindInterceptor(
Matchers.any(),
Matchers.annotatedWith(Profiled.class),
perftracing);
}
}
import java.util.Arrays;
import org.aopalliance.intercept.MethodInterceptor;
import org.aopalliance.intercept.MethodInvocation;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
public class PerfTracing implements MethodInterceptor{
private Logger logger = LoggerFactory.getLogger("PerfLog");
@Override
public Object invoke( MethodInvocation invocation) throws Throwable {
// TODO Auto-generated method stub
long start = System.nanoTime();
try {
return invocation.proceed();
}
finally {
if(logger.isDebugEnabled()){
Object[] paramArray = { invocation.getMethod().getName(),
Arrays.toString(invocation.getArguments()),
(System.nanoTime() - start) / 1000000};
logger.debug("Invocation of method: {} with parameters: {} took: {} ms." , paramArray);
}
}
}
}
<?xml version="1.0" encoding="UTF-8"?>
<!-- Reference Manual http://logback.qos.ch/manual/index.html -->
<configuration>
<appender name="stdout" class="ch.qos.logback.core.ConsoleAppender">
<encoder charset="UTF-8">
<pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger - %msg%n</pattern>
</encoder>
</appender>
<appender name="PerfLog" class="ch.qos.logback.core.rolling.RollingFileAppender">
<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<fileNamePattern>PerfLog-%d{yyyy-MM-dd}.log</fileNamePattern>
<maxHistory>30</maxHistory>
</rollingPolicy>
<encoder>
<pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger - %msg%n</pattern>
</encoder>
</appender>
<logger name="PerfLog" additivity="false">
<level value="DEBUG"/>
<appender-ref ref="PerfLog" />
</logger>
<root level="ERROR">
<appender-ref ref="stdout" />
</root>
</configuration>
15:02:49.351 [main] DEBUG PerfLog - Invocation of method: clickLoginBtn with parameters: [] took: 3027 ms.
* Classes must be public or package-private.
* Classes must be non-final
* Methods must be public, package-private or protected
* Methods must be non-final
* Instances must be created by Guice by an @Inject-annotated or no-argument constructor