Movatterモバイル変換

Table 5.5 MySQL DTrace Probes

When extracting the argument data from the probes, each argument is available asargN, starting witharg0. To identify each argument within the definitions they are provided with a descriptive name, but you must access the information using the correspondingargN parameter.

Theconnection-start andconnection-done probes enclose a connection from a client, regardless of whether the connection is through a socket or network connection.

connection-start(connectionid, user, host)connection-done(status, connectionid)

The following D script quantifies and summarizes the average duration of individual connections, and provides a count, dumping the information every 60 seconds:

#!/usr/sbin/dtrace -smysql*:::connection-start{  self->start = timestamp;}mysql*:::connection-done/self->start/{  @ = quantize(((timestamp - self->start)/1000000));  self->start = 0;}tick-60s{  printa(@);}

When executed on a server with a large number of clients you might see output similar to this:

  1  57413                        :tick-60s           value  ------------- Distribution ------------- count              -1 |                                         0               0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 30011               1 |                                         59               2 |                                         5               4 |                                         20               8 |                                         29              16 |                                         18              32 |                                         27              64 |                                         30             128 |                                         11             256 |                                         10             512 |                                         1            1024 |                                         6            2048 |                                         8            4096 |                                         9            8192 |                                         8           16384 |                                         2           32768 |                                         1           65536 |                                         1          131072 |                                         0          262144 |                                         1524288 |                                         0

The command probes are executed before and after a client command is executed, including any SQL statement that might be executed during that period. Commands include operations such as the initialization of the DB, use of theCOM_CHANGE_USER operation (supported by the MySQL protocol), and manipulation of prepared statements. Many of these commands are used only by the MySQL client API from various connectors such as PHP and Java.

command-start(connectionid, command, user, host)command-done(status)

Thecommand-start andcommand-done probes are best used when combined with the statement probes to get an idea of overall execution time.

Thequery-start andquery-done probes are triggered when a specific query is received by the server and when the query has been completed and the information has been successfully sent to the client.

query-start(query, connectionid, database, user, host)query-done(status)

You can get a simple report of the execution time for each query using the following D script:

#!/usr/sbin/dtrace -s#pragma D option quietdtrace:::BEGIN{   printf("%-20s %-20s %-40s %-9s\n", "Who", "Database", "Query", "Time(ms)");}mysql*:::query-start{   self->query = copyinstr(arg0);   self->connid = arg1;   self->db    = copyinstr(arg2);   self->who   = strjoin(copyinstr(arg3),strjoin("@",copyinstr(arg4)));   self->querystart = timestamp;}mysql*:::query-done{   printf("%-20s %-20s %-40s %-9d\n",self->who,self->db,self->query,          (timestamp - self->querystart) / 1000000);}

When executing the above script you should get a basic idea of the execution time of your queries:

$> ./query.dWho                  Database             Query                                    Time(ms)root@localhost       test                 select * from t1 order by i limit 10     0root@localhost       test                 set global query_cache_size=0            0root@localhost       test                 select * from t1 order by i limit 10     776root@localhost       test                 select * from t1 order by i limit 10     773root@localhost       test                 select * from t1 order by i desc limit 10 795

The query parsing probes are triggered before the original SQL statement is parsed and when the parsing of the statement and determination of the execution model required to process the statement has been completed:

query-parse-start(query)query-parse-done(status)

For example, you could monitor the execution time for parsing a given query using the following D script:

#!/usr/sbin/dtrace -s#pragma D option quietmysql*:::query-parse-start{   self->parsestart = timestamp;   self->parsequery = copyinstr(arg0);}mysql*:::query-parse-done/arg0 == 0/{   printf("Parsing %s: %d microseconds\n", self->parsequery,((timestamp - self->parsestart)/1000));}mysql*:::query-parse-done/arg0 != 0/{   printf("Error parsing %s: %d microseconds\n", self->parsequery,((timestamp - self->parsestart)/1000));}

In the above script a predicate is used onquery-parse-done so that different output is generated based on the status value of the probe.

When running the script and monitoring the execution:

$> ./query-parsing.dError parsing select from t1 join (t2) on (t1.i = t2.i) order by t1.s,t1.i limit 10: 36 msParsing select * from t1 join (t2) on (t1.i = t2.i) order by t1.s,t1.i limit 10: 176 ms

The query cache probes are fired when executing any query. Thequery-cache-hit query is triggered when a query exists in the query cache and can be used to return the query cache information. The arguments contain the original query text and the number of rows returned from the query cache for the query. If the query is not within the query cache, or the query cache is not enabled, then thequery-cache-miss probe is triggered instead.

query-cache-hit(query, rows)query-cache-miss(query)

The query cache probes are best combined with a probe on the main query so that you can determine the differences in times between using or not using the query cache for specified queries. For example, in the following D script, the query and query cache information are combined into the information output during monitoring:

#!/usr/sbin/dtrace -s#pragma D option quietdtrace:::BEGIN{   printf("%-20s %-20s %-40s %2s %-9s\n", "Who", "Database", "Query", "QC", "Time(ms)");}mysql*:::query-start{   self->query = copyinstr(arg0);   self->connid = arg1;   self->db    = copyinstr(arg2);   self->who   = strjoin(copyinstr(arg3),strjoin("@",copyinstr(arg4)));   self->querystart = timestamp;   self->qc = 0;}mysql*:::query-cache-hit{   self->qc = 1;}mysql*:::query-cache-miss{   self->qc = 0;}mysql*:::query-done{   printf("%-20s %-20s %-40s %-2s %-9d\n",self->who,self->db,self->query,(self->qc ? "Y" : "N"),          (timestamp - self->querystart) / 1000000);}

When executing the script you can see the effects of the query cache. Initially the query cache is disabled. If you set the query cache size and then execute the query multiple times you should see that the query cache is being used to return the query data:

$> ./query-cache.droot@localhost       test                 select * from t1 order by i limit 10     N  1072root@localhost                            set global query_cache_size=262144       N  0root@localhost       test                 select * from t1 order by i limit 10     N  781root@localhost       test                 select * from t1 order by i limit 10     Y  0

The query execution probe is triggered when the actual execution of the query starts, after the parsing and checking the query cache but before any privilege checks or optimization. By comparing the difference between the start and done probes you can monitor the time actually spent servicing the query (instead of just handling the parsing and other elements of the query).

query-exec-start(query, connectionid, database, user, host, exec_type)query-exec-done(status)

The*row-{start,done} probes are triggered each time a row operation is pushed down to a storage engine. For example, if you execute anINSERT statement with 100 rows of data, then theinsert-row-start andinsert-row-done probes are triggered 100 times each, for each row insert.

insert-row-start(database, table)insert-row-done(status)update-row-start(database, table)update-row-done(status)delete-row-start(database, table)delete-row-done(status)

The arguments supported by the probes are consistent for the correspondingstart anddone probes in each case:

Because the row-level probes are triggered for each individual row access, these probes can be triggered many thousands of times each second, which may have a detrimental effect on both the monitoring script and MySQL. The DTrace environment should limit the triggering on these probes to prevent the performance being adversely affected. Either use the probes sparingly, or use counter or aggregation functions to report on these probes and then provide a summary when the script terminates or as part of aquery-done orquery-exec-done probes.

The following example script summarizes the duration of each row operation within a larger query:

#!/usr/sbin/dtrace -s#pragma D option quietdtrace:::BEGIN{   printf("%-2s %-10s %-10s %9s %9s %-s \n",          "St", "Who", "DB", "ConnID", "Dur ms", "Query");}mysql*:::query-start{   self->query = copyinstr(arg0);   self->who   = strjoin(copyinstr(arg3),strjoin("@",copyinstr(arg4)));   self->db    = copyinstr(arg2);   self->connid = arg1;   self->querystart = timestamp;   self->rowdur = 0;}mysql*:::query-done{   this->elapsed = (timestamp - self->querystart) /1000000;   printf("%2d %-10s %-10s %9d %9d %s\n",          arg0, self->who, self->db,          self->connid, this->elapsed, self->query);}mysql*:::query-done/ self->rowdur /{   printf("%34s %9d %s\n", "", (self->rowdur/1000000), "-> Row ops");}mysql*:::insert-row-start{   self->rowstart = timestamp;}mysql*:::delete-row-start{   self->rowstart = timestamp;}mysql*:::update-row-start{   self->rowstart = timestamp;}mysql*:::insert-row-done{   self->rowdur += (timestamp-self->rowstart);}mysql*:::delete-row-done{   self->rowdur += (timestamp-self->rowstart);}mysql*:::update-row-done{   self->rowdur += (timestamp-self->rowstart);}

Running the above script with a query that inserts data into a table, you can monitor the exact time spent performing the raw row insertion:

St Who        DB            ConnID    Dur ms Query 0 @localhost test              13     20767 insert into t1(select * from t2)                                        4827 -> Row ops

The read row probes are triggered at a storage engine level each time a row read operation occurs. These probes are specified within each storage engine (as opposed to the*row-start probes which are in the storage engine interface). These probes can therefore be used to monitor individual storage engine row-level operations and performance. Because these probes are triggered around the storage engine row read interface, they may be hit a significant number of times during a basic query.

read-row-start(database, table, scan_flag)read-row-done(status)

The index probes are triggered each time a row is read using one of the indexes for the specified table. The probe is triggered within the corresponding storage engine for the table.

index-read-row-start(database, table)index-read-row-done(status)

The lock probes are called whenever an external lock is requested by MySQL for a table using the corresponding lock mechanism on the table as defined by the table's engine type. There are three different types of lock, the read lock, write lock, and unlock operations. Using the probes you can determine the duration of the external locking routine (that is, the time taken by the storage engine to implement the lock, including any time waiting for another lock to become free) and the total duration of the lock/unlock process.

handler-rdlock-start(database, table)handler-rdlock-done(status)handler-wrlock-start(database, table)handler-wrlock-done(status)handler-unlock-start(database, table)handler-unlock-done(status)

You can use arrays to monitor the locking and unlocking of individual tables and then calculate the duration of the entire table lock using the following script:

#!/usr/sbin/dtrace -s#pragma D option quietmysql*:::handler-rdlock-start{   self->rdlockstart = timestamp;   this->lockref = strjoin(copyinstr(arg0),strjoin("@",copyinstr(arg1)));   self->lockmap[this->lockref] = self->rdlockstart;   printf("Start: Lock->Read   %s.%s\n",copyinstr(arg0),copyinstr(arg1));}mysql*:::handler-wrlock-start{   self->wrlockstart = timestamp;   this->lockref = strjoin(copyinstr(arg0),strjoin("@",copyinstr(arg1)));   self->lockmap[this->lockref] = self->rdlockstart;   printf("Start: Lock->Write  %s.%s\n",copyinstr(arg0),copyinstr(arg1));}mysql*:::handler-unlock-start{   self->unlockstart = timestamp;   this->lockref = strjoin(copyinstr(arg0),strjoin("@",copyinstr(arg1)));   printf("Start: Lock->Unlock %s.%s (%d ms lock duration)\n",          copyinstr(arg0),copyinstr(arg1),          (timestamp - self->lockmap[this->lockref])/1000000);}mysql*:::handler-rdlock-done{   printf("End:   Lock->Read   %d ms\n",          (timestamp - self->rdlockstart)/1000000);}mysql*:::handler-wrlock-done{   printf("End:   Lock->Write  %d ms\n",          (timestamp - self->wrlockstart)/1000000);}mysql*:::handler-unlock-done{   printf("End:   Lock->Unlock %d ms\n",          (timestamp - self->unlockstart)/1000000);}

When executed, you should get information both about the duration of the locking process itself, and of the locks on a specific table:

Start: Lock->Read   test.t2End:   Lock->Read   0 msStart: Lock->Unlock test.t2 (25743 ms lock duration)End:   Lock->Unlock 0 msStart: Lock->Read   test.t2End:   Lock->Read   0 msStart: Lock->Unlock test.t2 (1 ms lock duration)End:   Lock->Unlock 0 msStart: Lock->Read   test.t2End:   Lock->Read   0 msStart: Lock->Unlock test.t2 (1 ms lock duration)End:   Lock->Unlock 0 msStart: Lock->Read   test.t2End:   Lock->Read   0 ms

The filesort probes are triggered whenever a filesort operation is applied to a table. For more information on filesort and the conditions under which it occurs, seeSection 8.2.1.14, “ORDER BY Optimization”.

filesort-start(database, table)filesort-done(status, rows)

An example of this is in the following script, which tracks the duration of the filesort process in addition to the duration of the main query:

#!/usr/sbin/dtrace -s#pragma D option quietdtrace:::BEGIN{   printf("%-2s %-10s %-10s %9s %18s %-s \n",          "St", "Who", "DB", "ConnID", "Dur microsec", "Query");}mysql*:::query-start{   self->query = copyinstr(arg0);   self->who   = strjoin(copyinstr(arg3),strjoin("@",copyinstr(arg4)));   self->db    = copyinstr(arg2);   self->connid = arg1;   self->querystart = timestamp;   self->filesort = 0;   self->fsdb = "";   self->fstable = "";}mysql*:::filesort-start{  self->filesort = timestamp;  self->fsdb = copyinstr(arg0);  self->fstable = copyinstr(arg1);}mysql*:::filesort-done{   this->elapsed = (timestamp - self->filesort) /1000;   printf("%2d %-10s %-10s %9d %18d Filesort on %s\n",          arg0, self->who, self->fsdb,          self->connid, this->elapsed, self->fstable);}mysql*:::query-done{   this->elapsed = (timestamp - self->querystart) /1000;   printf("%2d %-10s %-10s %9d %18d %s\n",          arg0, self->who, self->db,          self->connid, this->elapsed, self->query);}

Executing a query on a large table with anORDER BY clause that triggers a filesort, and then creating an index on the table and then repeating the same query, you can see the difference in execution speed:

St Who        DB            ConnID       Dur microsec Query 0 @localhost test              14           11335469 Filesort on t1 0 @localhost test              14           11335787 select * from t1 order by i limit 100 0 @localhost test              14          466734378 create index t1a on t1 (i) 0 @localhost test              14              26472 select * from t1 order by i limit 100

The individual statement probes are provided to give specific information about different statement types. For the start probes the string of the query is provided as the only argument. Depending on the statement type, the information provided by the corresponding done probe can differ. For all done probes the status of the operation (0 for success,>0 for failure) is provided. ForSELECT,INSERT,INSERT ... (SELECT FROM ...),DELETE, andDELETE FROM t1,t2 operations the number of rows affected is returned.

ForUPDATE andUPDATE t1,t2 ... statements the number of rows matched and the number of rows actually changed is provided. This is because the number of rows actually matched by the correspondingWHERE clause, and the number of rows changed can differ. MySQL does not update the value of a row if the value already matches the new setting.

select-start(query)select-done(status,rows)insert-start(query)insert-done(status,rows)insert-select-start(query)insert-select-done(status,rows)update-start(query)update-done(status,rowsmatched,rowschanged)multi-update-start(query)multi-update-done(status,rowsmatched,rowschanged)delete-start(query)delete-done(status,rows)multi-delete-start(query)multi-delete-done(status,rows)

The arguments for the statement probes are:

You use these probes to monitor the execution of these statement types without having to monitor the user or client executing the statements. A simple example of this is to track the execution times:

#!/usr/sbin/dtrace -s#pragma D option quietdtrace:::BEGIN{   printf("%-60s %-8s %-8s %-8s\n", "Query", "RowsU", "RowsM", "Dur (ms)");}mysql*:::update-start, mysql*:::insert-start,mysql*:::delete-start, mysql*:::multi-delete-start,mysql*:::multi-delete-done, mysql*:::select-start,mysql*:::insert-select-start, mysql*:::multi-update-start{    self->query = copyinstr(arg0);    self->querystart = timestamp;}mysql*:::insert-done, mysql*:::select-done,mysql*:::delete-done, mysql*:::multi-delete-done, mysql*:::insert-select-done/ self->querystart /{    this->elapsed = ((timestamp - self->querystart)/1000000);    printf("%-60s %-8d %-8d %d\n",           self->query,           0,           arg1,           this->elapsed);    self->querystart = 0;}mysql*:::update-done, mysql*:::multi-update-done/ self->querystart /{    this->elapsed = ((timestamp - self->querystart)/1000000);    printf("%-60s %-8d %-8d %d\n",           self->query,           arg1,           arg2,           this->elapsed);    self->querystart = 0;}

When executed you can see the basic execution times and rows matches:

Query                                                        RowsU    RowsM    Dur (ms)select * from t2                                             0        275      0insert into t2 (select * from t2)                            0        275      9update t2 set i=5 where i > 75                               110      110      8update t2 set i=5 where i < 25                               254      134      12delete from t2 where i < 5                                   0        0        0

Another alternative is to use the aggregation functions in DTrace to aggregate the execution time of individual statements together:

#!/usr/sbin/dtrace -s#pragma D option quietmysql*:::update-start, mysql*:::insert-start,mysql*:::delete-start, mysql*:::multi-delete-start,mysql*:::multi-delete-done, mysql*:::select-start,mysql*:::insert-select-start, mysql*:::multi-update-start{    self->querystart = timestamp;}mysql*:::select-done{        @statements["select"] = sum(((timestamp - self->querystart)/1000000));}mysql*:::insert-done, mysql*:::insert-select-done{        @statements["insert"] = sum(((timestamp - self->querystart)/1000000));}mysql*:::update-done, mysql*:::multi-update-done{        @statements["update"] = sum(((timestamp - self->querystart)/1000000));}mysql*:::delete-done, mysql*:::multi-delete-done{        @statements["delete"] = sum(((timestamp - self->querystart)/1000000));}tick-30s{        printa(@statements);}

The script just shown aggregates the times spent doing each operation, which could be used to help benchmark a standard suite of tests.

 delete                                                            0  update                                                            0  insert                                                           23  select                                                         2484  delete                                                            0  update                                                            0  insert                                                           39  select                                                        10744  delete                                                            0  update                                                           26  insert                                                           56  select                                                        10944  delete                                                            0  update                                                           26  insert                                                         2287  select                                                        15985

The network probes monitor the transfer of information from the MySQL server and clients of all types over the network. The probes are defined as follows:

net-read-start()net-read-done(status, bytes)net-write-start(bytes)net-write-done(status)

You can use the network probes to monitor the time spent reading from and writing to network clients during execution. The following D script provides an example of this. Both the cumulative time for the read or write is calculated, and the number of bytes. Note that the dynamic variable size has been increased (using thedynvarsize option) to cope with the rapid firing of the individual probes for the network reads/writes.

#!/usr/sbin/dtrace -s#pragma D option quiet#pragma D option dynvarsize=4mdtrace:::BEGIN{   printf("%-2s %-30s %-10s %9s %18s %-s \n",          "St", "Who", "DB", "ConnID", "Dur microsec", "Query");}mysql*:::query-start{   self->query = copyinstr(arg0);   self->who   = strjoin(copyinstr(arg3),strjoin("@",copyinstr(arg4)));   self->db    = copyinstr(arg2);   self->connid = arg1;   self->querystart = timestamp;   self->netwrite = 0;   self->netwritecum = 0;   self->netwritebase = 0;   self->netread = 0;   self->netreadcum = 0;   self->netreadbase = 0;}mysql*:::net-write-start{   self->netwrite += arg0;   self->netwritebase = timestamp;}mysql*:::net-write-done{   self->netwritecum += (timestamp - self->netwritebase);   self->netwritebase = 0;}mysql*:::net-read-start{   self->netreadbase = timestamp;}mysql*:::net-read-done{   self->netread += arg1;   self->netreadcum += (timestamp - self->netreadbase);   self->netreadbase = 0;}mysql*:::query-done{   this->elapsed = (timestamp - self->querystart) /1000000;   printf("%2d %-30s %-10s %9d %18d %s\n",          arg0, self->who, self->db,          self->connid, this->elapsed, self->query);   printf("Net read: %d bytes (%d ms) write: %d bytes (%d ms)\n",               self->netread, (self->netreadcum/1000000),               self->netwrite, (self->netwritecum/1000000));}

When executing the above script on a machine with a remote client, you can see that approximately a third of the time spent executing the query is related to writing the query results back to the client.

St Who                            DB            ConnID       Dur microsec Query 0 root@::ffff:198.51.100.108      test              31               3495 select * from t1 limit 1000000Net read: 0 bytes (0 ms) write: 10000075 bytes (1220 ms)

The keycache probes are triggered when using the index key cache used with the MyISAM storage engine. Probes exist to monitor when data is read into the keycache, cached key data is written from the cache into a cached file, or when accessing the keycache.

Keycache usage indicates when data is read or written from the index files into the cache, and can be used to monitor how efficient the memory allocated to the keycache is being used. A high number of keycache reads across a range of queries may indicate that the keycache is too small for size of data being accessed.

keycache-read-start(filepath, bytes, mem_used, mem_free)keycache-read-block(bytes)keycache-read-hit()keycache-read-miss()keycache-read-done(mem_used, mem_free)keycache-write-start(filepath, bytes, mem_used, mem_free)keycache-write-block(bytes)keycache-write-done(mem_used, mem_free)

When reading data from the index files into the keycache, the process first initializes the read operation (indicated bykeycache-read-start), then loads blocks of data (keycache-read-block), and then the read block is either matches the data being identified (keycache-read-hit) or more data needs to be read (keycache-read-miss). Once the read operation has completed, reading stops with thekeycache-read-done.

Data can be read from the index file into the keycache only when the specified key is not already within the keycache.

Keycache writes occur when the index information is updated during anINSERT,UPDATE, orDELETE operation, and the cached key information is flushed back to the index file.