Friday, July 08, 2011

Weekly Health check for SQL Server 2005 using DMV

Every Week, you can set up a benchmark by running following DMV, it can help to provide high level view to show whether your DB is healthy or not currently without any monitoring tools.

While, Some limitations you may have to pay attention to when you are using following DMV Queries:
(Thanks for a good reference provided by Vance: http://www.mssqltips.com/tip.asp?tip=1843)

1. Limitation with DMV queries: Keep this in mind when you are using the DMVs for query usage and performance stats. If you are using inline T-SQL and sp_executesql you may not be capturing all of the data that you need.
—Suggestion : think about using stored procedures for all data related operations instead of using inline T-SQL or sp_executesql in your application code.
2. Limitation with dbid column: there is a problem that it is limiting the result data to queries with a database id. The reason for this is that the dbid column is NULL for ad hoc and prepared SQL statements, So you can comment out the where condition which having dbid in (...);
—Suggestion : you may just comment out the dbid constrain or using “dbid = null” instead of assign a dbid in “where clause”


-- DMV FOR CHECKING CPU USAGE:
 
 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;  

-- DMV FOR CHECKING I/O USAGE
 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;  

-- DMV FOR CHECKING INDEX USAGE
 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  

-- DMV FOR CHECKING OBJECT BLOCKING/WAITING
 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;  

-- DMV FOR CHECKING TEMPDB USAGE
 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  

Thursday, June 30, 2011

Performance Toolkit in My Pocket

Please Note, this is a Draft Version, the list will be updated on the fly.

Kindly Warning:
Don’t be a slave of tools, but you can not leave without tools!
Be a master of your job with tools :)

Performance Toolkit in My Pocket:

1> Perf Testing Tools:
- Jmeter (Load generate tool for different Protocol)
- Loadrunner (Load generate tool for different Protocol)
- SoapUI (WebService load Testing preferred, or help to create mock services)
- Traffic Shaper XP (Network Bandwitch limiter)
- Badboy (HTTPS recording supported for .jmx scripts)
- JMeter plugin : http://code.google.com/p/jmeter-plugins/
- WebDriver Automation Framework for End-End Performance measurement
- ^Unit Performane testing tool need to be filled in...$ (Method level performance testing)

2> Perf Monitoring Tools:
- JConsole
- JVisualVM
- Task manager/PerfMon
- Process Explorer
- Hyperic HQ
- NetXMS
- Netstat
- typeperf Command line (with Ruby Programming)

3> Perf Profiling Tools:
- Jprofiler
- Btrace
- Jmap
- SQL Profiler
- Perf4j
- Guice AOP Profiling methods for Automation test
- HttpWatch
- Firebug
- Chrome Developer Tools
- Fiddler
- Charles
- Wireshark
- DBCC Command

4> Perf Analysis and Tuning Tools:
- Dynatrace Ajax
- MemoryAnalyzer
- TDA
- DB tuning adviser
- Yslow
- Page Speed
- Image Opertimazer : http://www.imageoptimizer.net/Pages/Home.aspx
- jpegmini - Sprite Me :http://spriteme.org/
- Minify JS :http://www.minifyjs.com/
- WebPageTest : http://www.webpagetest.org/

5> MISC:
- Text Editor/IDE you perferred: Netbeans with Ruby for me
- Windows Grep
- Regular Expression
- T-SQL
- Ruby/Python/Perl/Shell/Awk : http://www.ibm.com/developerworks/cn/education/aix/au-gawk/index.html
- STAF/STAX :
- Excel
- LogBack/Log4j
- JSLint (looks for problems in JavaScript programs)
- User Agent analysis: http://www.useragentstring.com/index.php

Tuesday, May 31, 2011

Dealing With High CPU% of SQL Server 2005

Sometimes, we experience performance problem with high CPU% on DB Server. How can we detect which process take most "contribution" to this pheromone step by step?

Step 1. Check if SQL Server Process has problem or not?
 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;  

Then you will get result like this:

The picture above shows 70% of CPU% is taking by SQL Server 2005 , not by other processes on DB server.

Step2. Drill down to particular Loginuser and SPID which is taking most of CPU%:
 select  loginame,  *    
 from  master.dbo.sysprocesses  
 where  spid> 50  
 order by cpu desc   

PS: Why "spid > 50" here? Notice that SPIDs 1 to 50 are reserved for internal SQL Server processes, while SPIDs 51 and above are external connections. So most of time we assume that the suspects for High CPU% are from external connections.

Step3: Query the most expensive CPU process by spid (taking spid = 102 for example):

 dbcc inputbuffer(102)   

Then you can start to take further actions for tuning expensive Query or SPs... or just kill the abnormal ones for free :)

Monday, May 30, 2011

To enable Performance Profiling log with Guice AOP and Logback

I always want my methods to be profiled, so that I can learn about how fast/slow it is from a high level perspective at first. Then break it down to make it even faster.

I am using WebDriver to do automation testing, so i want to trace certain end user experience from performance perspective as well.

For example, if I want to measure Login action's response time, my intention is to enable my profiling log by just add @Profiled annotation in front of corresponding "Login" method:
 
@Profiled
public void clickLoginBtn() throws InterruptedException{  
           driver.findElement(By.id("login")).click();  
           if(!myWaiter.waitForMe(By.cssSelector("div.starcite-hyperlink"), 25, timeout)) return ;  
      }  

To make @Profiled work, i chose Guice as it is so called light weight and easy of use:

Step1: Create an annotation called Profiled:
 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 {  
 }  

Step2:Create matchers for the classes and methods to be intercepted:

 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);  
        }  
      }  

Step3: Write your own MethodInterceptor to do profiling using Logback
 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);  
          }  
     }  
      }  
 }  

Why I choose Logback for logging? please refer to this post :)

For Logback configuration, here is my sample:
 <?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>  

The output in your log file should be like this:
 15:02:49.351 [main] DEBUG PerfLog - Invocation of method: clickLoginBtn with parameters: [] took: 3027 ms.  

Please notice Guice AOP's Limitations:
* 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

So You may have to change your source code to make Guice AOP work properly.

Saturday, May 21, 2011

My Current “Waiter” Class used by WebDriver Tests

My Current “Waiter” Class used by WebDriver automation tests, so keep away from your hard coded Thread.sleep() :

 import java.util.List;  
 import org.openqa.selenium.By;  
 import org.openqa.selenium.WebDriver;  
 import org.openqa.selenium.WebElement;  
 import org.openqa.selenium.support.ui.WebDriverWait;  
 import com.google.common.base.Function;  
 /*  
  * Two usage examples in your test code:  
  * MyWaiter myWaiter = new MyWaiter(driver);  
   WebElement search = myWaiter.waitForMe(By.name("btnG"), 10);  
   or  
   if(!myWaiter.waitForMe(By.name("btnG"), 1, 10)) return;  
   or if (!myWaiter.waitForMeDisappear(By.name("btnG"), 10)) return;  
  */  
 public class MyWaiter {  
      private WebDriver driver;  
      public MyWaiter(WebDriver driver){  
           this.driver = driver;  
      }  
      public WebElement waitForMe(By locatorname, int timeout){  
           WebDriverWait wait = new WebDriverWait(driver, timeout);  
           return wait.until(MyWaiter.presenceOfElementLocated(locatorname));  
      }  
      //Given certain number of web element to see if it is found within timeout  
      public Boolean waitForMe(By locatorname, int count, int timeout) throws InterruptedException{  
           long ctime = System.currentTimeMillis();  
           while ((timeout*1000 > System.currentTimeMillis()- ctime)){  
                List<WebElement> elementList = driver.findElements(locatorname);  
                if ((elementList.size()< count)){  
                     Thread.sleep(300);  
                }  
                //element is found within timeout   
                else  
                     return true;  
           }  
           // otherwise element is not found within timeout  
           return false;  
      }  
      //Given certain number of web element to see if it is disappear within timeout  
      public Boolean waitForMeDisappear(By locatorname, int timeout) throws InterruptedException{  
           long ctime = System.currentTimeMillis();  
           while ((timeout*1000 > System.currentTimeMillis()- ctime)){  
                List<WebElement> elementList = driver.findElements(locatorname);  
                if ((elementList.size()!= 0)){  
                     Thread.sleep(300);  
                }  
                //element is Disappear within timeout   
                else  
                     return true;  
           }  
           // otherwise element is still show up within timeout  
           return false;  
      }  
      public static Function<WebDriver, WebElement> presenceOfElementLocated(final By locator) {  
           // TODO Auto-generated method stub  
           return new Function<WebDriver, WebElement>() {  
                @Override  
                public WebElement apply(WebDriver driver) {  
                     if (driver.findElement(locator)!= null){  
                          return driver.findElement(locator);  
                     }  
                     else return null;  
                }  
           };  
      }  
 }  

Another useful method on implicitwait(), I also wrote a post related to it, FYI : http://joychester.blogspot.com/2010/09/webdriver-wait-is-easier-after-using.html

Wednesday, May 18, 2011

6 years since we met -- 2011-01-26

Cheng Shawn

PS: for how to draw a heart, please take a look at this link :)




Tuesday, May 17, 2011

Compressing Image with Image Opertimazer

Compressing plain text is easy by Zipping the files, however, images are said to be compressed by default, so often we are ignoring optimizing it.

I just found one awesome tool to optimize the website images without sacrificing much quality:Image Opertimazer

Here is the default Image, original size is 52KB:

After optimization, the size is 33KB, about 20% saving:

And you may heard of WebP created by Google, it is said that "WebP images were 39.8% smaller than jpeg images of similar quality", give it a try! Update: another awesome service to do Image compression, called JPEGmini : http://www.jpegmini.com/main/home

Tuesday, April 19, 2011

Leverage browser caching by dummy configuration on Apache HTTP Server

Leverage browser caching is quite critical for web performance, especially you have , but sometime you may have your static files get changed. So you may control the risks as much as possible.

There is a cool strategy to Use fingerprinting to dynamically enable caching if you can, but if you just want to do some simple configurations with limited risks, then here is my sample httpd.conf:

 
 LoadModule headers_module modules/mod_headers.so
 ... 
 #Disable Last-Modified Response Header  
 <FilesMatch "\.(ico|pdf|flv|jpg|jpeg|png|gif|js|css|swf|html|rpc)$">  
 Header unset Last-Modified  
 </FilesMatch>

 #Default Cache-control header for most static files  
 <FilesMatch "\.(ico|pdf|flv|jpg|jpeg|png|gif|js|css|swf)$">  
 Header set Cache-Control "max-age=7200, public"  
 </FilesMatch>  
 # Revalidate For No-cache files each time  
 <FilesMatch "\.nocache\.(ico|pdf|flv|jpg|jpeg|png|gif|js|css|swf)$">  
 Header set Cache-Control "max-age=0, no-cache, must-revalidate"  
 </FilesMatch>  
 # Revalidate html/rpc files each time  
 <FilesMatch "\.(html|rpc)$">  
 Header set Cache-Control "max-age=0, no-cache, must-revalidate"  
 </FilesMatch>  
 # Cache "forever" due to files are given a unique name every time they are built  
 <FilesMatch "\.cache\.(html|js|png|gif)$">  
 Header set Cache-Control "max-age=2592000, public"  
 </FilesMatch>  

Let’s assume one yourapp.js has been requested for the first time and load into Disk cache:

1. when the browser requests yourapp.js within 2 hours(7200 seconds) since loaded into Disk cache, it will be load from Disk cache directly without sending any http request;

2. when the browser requests yourapp.js after 2 hours(7200 seconds) since loaded into Disk cache, it will be fetched either from static file server (200 code returned) if Etag has been changed(which means static file changes) or from Disk Cache (304 code returned) if Etag is still the same as request head brings ("if-none-match" request header) (which means static file has no changes)

3. Some no Cached files will always re-validate to the server, to check if the the file is the latest or not based on Etag

4. Some Cached files will have far further cache-control header (set to 1 month from my side), Due to every new build, the static file name will be refreshed, and we do monthly release usually.

Friday, April 15, 2011

Aggeragte Performance Profiling Data using Ruby

 require 'csv'  
 def perflogana(csvfile)  
  #initial an Two-dimensional array
   a = Array.new(1){ Array.new(4) }  
   a[0][0] = '';  # Transaction name 
   a[0][1] = 0;  # Total Response time
   a[0][2] = 0;  # Invocations
   a[0][3] = 0;  # Average Response Time
   i = 0;  
   t = 0;  
   n = 0;  
   flag = 'unfound'  
  # Read each line from CSV file  
  CSV.foreach(csvfile) do |row|  
   if (!row[1].nil?) 
      #Trim Oid for the URL using regex
      if row[1].gsub!(/\/([\d\D][^\/]+?-)+\S*/, "")
         row[1] << ")"
      end 
    b = 0;  
    # modify total response time and invocations if current line being found  
    while b <= i  
     if !a[b][0].eql?(row[1])  
       b= b+1;  
       next;  
     else  
       # modify total response time and invocations  
       a[b][1] = a[b][1] + row[2].to_s.to_i;  
       a[b][2] = a[b][2] + 1;  
       flag = 'find'  
       break;  
     end  
    end  
    #append a new line if new transaction being found  
    if flag.eql?('unfound')  
      a << [row[1],row[2].to_s.to_i,1]  
      i = i+1;  
    end  
    flag = 'unfound'  
   end  
  end  
  a.shift  
  j = a.size  
  #calculate average response time for each transaction  
  while t < j  
   a[t][3] = a[t][1]/a[t][2]  
   t = t+1;  
  end  
  # sort by avg time and print to console  
  while n < j  
   print a[n][0],",",a[n][1],",",a[n][2],",",a[n][3]  
   puts  
   n = n + 1  
  end  
 end  
 perflogana("D:\\GWT_automation\\perf\.csv");