Optimize the SQL Server System with the Application Event Probe

When your SQL Server database system runs slowly, you may know more or less that you can use SQL Server
Profiler (SQL event probe) tool for tracking and analysis. Yes, profiler can be used to capture messages sent to SQL
All the server statements and statement execution performance data (such as the number of Read/writes pages, CPU usage, and statement duration) for the future
Analysis. However, this article does not describe how to use profiler
Instead, we will introduce how to use the read80trace tool (for details about this tool) in combination with custom stored procedures to outline and analyze the trace files captured by Profiler.
Finally, you can obtain exciting data analysis reports so that you can optimize the SQL Server database system.

This article analyzes the SQL
The performance of a large database system, such as dBA, is particularly useful. In database systems with large scale and complex application logic, the files generated by profiler are usually huge. For example, in
In profiler, only basic statement events are captured. the trace file captured after two hours of running may have a size of GB. The method described in this article can not only greatly save Analysis
The trace time and money free you from the massive amount of data in the trace file, and let you know the access mode of the database system, so as to know which type of statements have the greatest impact on performance and what type of statements
Statement needs to be optimized.

Traditional methods and limitations of Profiler trace file Performance Analysis

First, let's talk about the access mode of the database system. In addition to using trace files to solve problems such as deadlocks, blocking, and timeout, the most common and major function is to obtain the following important information from the trace file:

1. statements that run most frequently

2. Key statements that affect system performance

3. Proportion of various statement groups and related performance statistics

　
The access mode mentioned in this article is the above three information. We know that the modules of the database system are basically fixed, and each module accesses the SQL
The server method is also almost fixed. Specific to a menu, a button, are basically unchanged, so in a long enough time, access SQL
Server statements and their proportions are also fixed. In other words, as long as the profiler sampling time is long enough (I generally run for more than 2 hours ),
The access mode of the database system can be counted. Each database system has its own unique access mode. Analyze profiler
An important goal of the trace file is to find the access mode of the database system. Once you get the access mode, you can be confident and confident in optimizing the system. Unfortunately, it hasn't been until now.
Any tool can easily obtain this information.

There are two traditional trace analysis methods. One is to use the profiler tool itself. For example, you can use
The filter function of profiler filters statements that run for more than 10 seconds, or finds the statements that consume the most CPU according to the CPU order. The other is to import the trace file
To the database, and then use the T-SQL statement for statistical analysis. These two methods are effective for small trace files. However, if the number of Trace files is large (for example, four
Trace files larger than MB), so these two methods have great limitations. One of the limitations is that the analysis and statistics are not easy because of the huge file size, which often makes it impossible for you
Measure the test taker's knowledge about the execution performance of all statements. You can easily get confused by some statements and spend your energy on them. In fact, it is not a key statement that really requires attention. The second limitation is that you find that
Statement modes are very similar (only when the execution parameters are different), but there is no simple way to classify them together for statistics. In short, you cannot easily obtain the access mode of the database system.
In the optimization process, the solution is well-planned. This is the limitation of traditional analysis methods. The read80trace tool and custom stored procedures described below can overcome these limitations.
.

Read80trace tool introduction and its normalization Function

　
Read80trace is a command line tool. Using the read80trace tool can greatly save time on analyzing trace files and achieve twice the result with half the effort.
The main working principle of read80trace is to read the trace file and then perform normalize on the statement.
(Standardized), import to the database, and generate an HTML page for performance statistical analysis. In addition, read80trace can generate rml files, and then the ostress tool uses multiple rml files
Replay all events in the trace file in a thread. This is possible for statements that want to capture profiler on another server. This article is not detailed
Read80trace or ostress tool. If you are interested, please refer to the relevant materials. The software can be downloaded from the Microsoft website (Note: The software name is rml)

Http://www.microsoft.com/downloads/
I want to use the standardized functions of read80trace. What is standardization? It is to classify all statements with similar statement modes but different parameters. For example, there are several statements in the trace:

Select * from authors where au_lname = 'white'
Select * from authors where au_lname = 'green'
Select * from authors where au_lname = 'carson'

After standardization, the preceding statement is as follows:

Select * from authors where au_lname = {STR}
Select * from authors where au_lname = {STR}
Select * from authors where au_lname = {STR}

With standardized statements, it is no longer difficult to calculate the access mode of the database system. When running read80trace, I usually use the following command line:

Read80trace-F-dmydb-imytrace. TRC

The-F switch does not generate rml files because I do not need the replay function. The generated rml file is large. We recommend that you use the-F switch if you do not need to replay the file.

　
The-D switch tells read80trace to save the trace file processing result to the mydb database. The stored procedure created later accesses read80trace in
The tables generated in mydb for statistics. -The I switch specifies the trace file name to be analyzed. The read80trace tool is very clever. If there is a profiler generated in this directory
A series of Trace files, such as mytrace. TRC, mytrace1.trc, and mytrace2.trc, are read and processed sequentially.

　
In addition to the preceding descriptions, read80trace has many interesting functions. For example, the-I switch enables read80trace to be read from a ZIP or cab file.
Trace file, you do not need to decompress it yourself. All switches are described in details in read80trace. CHM. What I like most is the performance of read80trace. Analyze several gigabytes
It takes less than an hour to complete a small trace file. My computer is an old machine with only MB of memory. I am very satisfied with this performance.

You may use
Read80trace analyzes the trace files generated by stress testing. I suggest you analyze the trace files captured from the production environment. Because many stress testing tools cannot really simulate
In the real environment, the trace file cannot reflect the actual situation. Even some stress testing tools execute self-written statements cyclically, and do not reflect the accurate access mode. We recommend that you only press
The trace generated by force testing is used as a reference.

Analyze data after Normalize Using Stored Procedures

With standardized statements, you can use stored procedures for statistical analysis. The basic idea of analysis is to make group by statistics on the reads, CPU, and duration of all statements in the same mode to get the access mode information:

1. The total number of executions of certain statements, average number of read pages (READS), average CPU time, and average execution time.

2. The proportion of such statements in all statements, such as execution times, reads, and CPU.

The definition and description of a stored procedure are as follows:

Create procedure usp_getaccesspattern 8000
@ Duration_filter Int =-1 -- input parameter. statistics can be filtered based on the statement execution time.
As begin

/* First obtain the total performance data of all statements */
Declare @ sum_total float, @ sum_cpu float, @ sum_reads float, @ sum_duration float, @ sum_writes float
Select @ sum_total = count (*) * 0.01, -- this is the total number of all statements.
@ Sum_cpu = sum (CPU) * 0.01, -- this is the CPU time consumed by all statements
@ Sum_reads = sum (READS) * 0.01, -- this is the number of reads consumed by all statements, in 8 K.
@ Sum_writes = sum (writes) * 0.01, -- this is the number of writes consumed by all statements, in 8 K.
@ Sum_duration = sum (duration) * 0.01 -- this is the total execution time of all statements.
From tblbatches -- this is the table generated by read80trace, including all the statements in the trace file.
Where duration >=@ duration_filter -- whether to filter by execution time

/* Then perform group by to obtain the proportion occupied by certain statements */
Select ltrim (STR (count (*) exec_stats, ''+ STR (count (*)/@ sum_total, 4,1) + '%' execratio,
Ltrim (STR (sum (CPU) + ':' + + ltrim (STR (AVG (CPU) cpu_stats, ''+ STR (sum (CPU) /@ sum_cpu, 4, 1) + '%' cpuratio,
Ltrim (STR (sum (READS) + ':' + ltrim (STR (AVG (READS) reads_stats, ''+ STR (sum (READS)/@ sum_reads, 4, 1) + '%' readsratio,
-- Ltrim (STR (sum (writes) + ':' + ltrim (STR (AVG (writes) -- writes_stats, ''+ STR (sum (writes) /@ sum_writes, 4,1) + '% )',
Ltrim (STR (sum (duration) + ':' + ltrim (STR (AVG (duration) duration_stats, ''+ STR (sum (duration)/@ sum_duration, 4, 1) + '%' durratio,
Textdata, count (*)/@ sum_total TP, sum (CPU)/@ sum_cpu CP, sum (READS)/@ sum_reads RP, sum (duration)/@ sum_duration DP
Into # queries_staticstics from
/* All standardized statements are stored in the tbluniquebatches table. */
(Select reads, CPU, duration, writes, convert (varchar (2000), normtext) textdata from tblbatches
Inner join tbluniquebatches on tblbatches. hashid = tbluniquebatches. hashid where duration> @ duration_filter
) B group by textdata -- this group by is very important. It classifies and counts statements.

Print 'top 10 order by CPU + reads + duration'
Select top 10 * from # queries_staticstics order by CP + RP + dp DESC
Print 'top 10 order by CPU'
Select top 10 * from # queries_staticstics order by CP DESC
Print 'top 10 order by reads'
Select top 10 * from # queries_staticstics order by RP DESC
Print 'top 10 order by duration'
Select top 10 * from # queries_staticstics order by DP DESC
Print 'top 10 order by batches'
Select top 10 * from # queries_staticstics order by TP DESC

End

Considering that the output result is too long, writes is removed from the storage process. This is because most database systems are dominated by reads. You can easily modify the stored procedure to include write.

The stored procedure is not complex and easy to understand. You can see that the statistical results are placed in the queries_staticstics table, sorted by different conditions, and then output. For example:

Select top 10 * from # queries_staticstics order by CP DESC

In the preceding statement, records in the queries_staticstics table are sorted and output according to the proportion of the total CPU usage of certain statements CP (that is, sum (CPU)/@ sum_cpu. This allows you to quickly locate the type of statements that consume the most CPU resources when analyzing the CPU performance of the server.

Now let's look at the output of an instance:

Use mydb
Exec usp_getaccesspattern
/* You can enter an execution time as the filter parameter, in milliseconds. For example, usp_getaccesspattern 1000 */

Output result 1 (partial results. In addition, because the original output result is too long, the result is truncated into two parts for easy reading ):

Figure 1: sample output result 1

　
The preceding example samples the Business System of a large company. The problem with this system is that the application runs slowly, and SQL Server
The server's CPU usage is high (8 CPUs are all at 90% ~ 100% fluctuations ). I used the pssdiag tool to sample data for about 2 hours and then run read80trace and
Usp_getaccesspattern to get the above result. Reports are clear at a glance. The stored procedure DBO. x_dedup_proc runs 75 times in two hours, but occupies
90.8% of CPU resources, 94.6% of reads, from the perspective of access mode, the stored procedure is the key statement that leads to high CPU and slow system performance. Once the stored procedure is optimized
Performance problems will be solved. You may have doubts about the frequency of running 75 times in two hours. In fact, you can see that the average CPU time of this stored procedure is 681961 milliseconds, around 11 minutes left
Right. That is to say, a CPU can run a maximum of (60*2)/11 = 10 records in two hours. The system has a total of 8 CPUs, even if all the CPUs are used to run the statement, that is, at most
About 10*8 = 80. The above execution is 75, indicating that the stored procedure is continuously running.

So what are the statements that the system runs most frequently? I extract another part from the result (Figure 2 ):

Figure 2 sample output result 2

From the table above, we can see that the statements that run most frequently are

Use XB set quoted_identifier, ansi_null_dflt_on...

Obviously, this is an execution environment configuration statement with no reference value. The other two statements that occupy 8.2% of the total number of statements are worth noting:

Select count (*) from x_process_stats where process ......
Select count (*) from x_process_stats where process ......

In this example, the key statement DBO. x_dedup_proc is very prominent, and even the preceding two statements can be ignored.

Let's look at another example (Figure 3 ):

Figure 3: sample output result 3

In the preceding example, the key statements are as follows:

Select count (*) from gtbl7ms
Select caseno from patientdata_sum where MRN = @ p1

Subsequent checks showed that the relevant tables did not have a valid index, and the performance immediately improved a lot after the index was added .. To solve these two statements, we need to use the same method to continue analysis and optimization until the system performance can
So far .. Note that performance tuning is a long-term process. It is unlikely that you can solve all the problems within one or two days. The problem 80% may be solved in the first place, but the problem 20% in the later stage needs to be solved.
Another 80% of the time.

Tips for using usp_getaccesspattern

　
The output report of usp_getaccesspattern contains a wealth of information. You must have a general picture when analyzing reports. You can also choose the information you need. If yes
For systems with CPU performance bottlenecks, you need to pay attention to statements with a high CPU usage ratio. If the disk Io has a performance bottleneck, you need to find the reads occupying a large proportion and average
Reads statements are also very high. Note that sometimes statements that run frequently may not be the key statements you need to pay attention. The most ideal case is that the key statement is the most frequent statement. Sometimes even
The proportion of resources occupied by the most frequent statements is not high, but if optimization can be performed, minor optimization will bring considerable benefits to the system due to the amplification effect.

In use
When usp_getaccesspattern is used, the @ duration_filter parameter is used. Because the parameter is in milliseconds, it is recommended that the parameter be smaller than 1000, while
It should be a multiple of 1000.
For example, or. This parameter often provides very interesting output. The output overlaps with the running results without parameters. Overlapping statements are usually the statements that need attention. Note
The statement with the maximum number of rows is not necessarily executed for more than 1000 milliseconds. All statements with parameters may not include the most frequently executed statements. I often perform cross-analysis on four results at the same time. One result is obtained by running without parameters.
The other three are the results of parameter running with 5000, and milliseconds respectively. The four results of comparative analysis often give me a clear and thorough understanding of the database system access mode.

You may encounter an int integer overflow error when running the stored procedure. This is because the CPU and writes fields in the tblbatches table are int rather than bigint. You can run the following statement for correction:

Alter table tblbatches alter column reads bigint
Alter table tblbatches alter column CPU bigint
Alter table tblbatches alter column writes bigint

After modification, the overflow problem will be solved.

Snake foot: Which is a hot database?

This article has basically ended. You already know how to use read80trace and usp_getaccesspattern to obtain the access mode of the database system, and how to analyze the access mode report from the Global height, so that you can gain a thorough understanding when optimizing the system.

In addition, you can apply similar analysis ideas to obtain the proportion of resources occupied by each database. This is useful when SQL Server has multiple databases. From the report, you can immediately know which database is the most popular database that consumes the most system resources. The statement is as follows:

Print 'group by dbid'
Declare @ sum_total float, @ sum_cpu float, @ sum_reads float, @ sum_duration float, @ sum_writes float
Select @ sum_total = count (*) * 0.01, @ sum_cpu = sum (CPU) * 0.01, @ sum_reads = sum (READS) * 0.01, @ sum_writes = sum (writes) * 0.01,
@ Sum_duration = sum (duration) * 0.01 from tblbatches

Select dbid,
Ltrim (STR (count (*) exec_stats, ''+ STR (count (*)/@ sum_total, 4,1) + '%' execratio,
Ltrim (STR (sum (CPU) + ':' + + ltrim (STR (AVG (CPU) cpu_stats, ''+ STR (sum (CPU) /@ sum_cpu, 4, 1) + '%' cpuratio,
Ltrim (STR (sum (READS) + ':' + ltrim (STR (AVG (READS) reads_stats, ''+ STR (sum (READS)/@ sum_reads, 4, 1) + '%' readsratio,
Ltrim (STR (sum (duration) + ':' + ltrim (STR (AVG (duration) duration_stats, ''+ STR (sum (duration)/@ sum_duration, 4, 1) + '%' durratio,
Count (*)/@ sum_total TP, sum (CPU)/@ sum_cpu CP, sum (READS)/@ sum_reads RP, sum (duration)/@ sum_duration DP
Into # queries_staticstics_groupbydb from

(Select reads, CPU, duration, writes, convert (varchar (2000), normtext) textdata, dbid from tblbatches
Inner join tbluniquebatches on tblbatches. hashid = tbluniquebatches. hashid
) B group by dbid order by sum (READS) DESC

Select dbid, execratio batches, cpuratio CPU, readsratio reads, durratio duration
From # queries_staticstics_groupbydb

The following is an example of the above statement results:

Dbid batches CPU reads duration
---------------------------------
37 21.1% 18.7% 29.1% 27.1%
33 12.7% 32.4% 19.5% 24.8%
36 5.6% 28.3% 15.6% 26.1%
20 53.9% 2.9% 14.2% 2.1%
22 0.8% 7.2% 13.2% 6.6%
25 1.0% 3.6% 5.4% 3.5%
16 0.0% 1.5% 1.9% 0.7%
35 2.0% 2.7% 1.8% 5.7%
7 0. 1% 0.1% 1.1% 0.3%

The above results clearly tell us that databases with IDs 37, 33, and 36 are the most active databases. An interesting fact is that the total number of statements issued by database 20 is 53.9%, but the proportion of system resources it occupies is not high.