MySQL 5.7 Release Notes
MySQL supports the following static probes, organized into groups of functionality.
Table 5.5 MySQL DTrace Probes
| Group | Probes |
|---|---|
| Connection | connection-start, connection-done |
| Command | command-start, command-done |
| Query | query-start, query-done |
| Query Parsing | query-parse-start,
query-parse-done |
| Query Cache | query-cache-hit, query-cache-miss |
| Query Execution | query-exec-start, query-exec-done |
| Row Level | insert-row-start, insert-row-done |
update-row-start, update-row-done |
|
delete-row-start, delete-row-done |
|
| Row Reads | read-row-start, read-row-done |
| Index Reads | index-read-row-start,
index-read-row-done |
| Lock | handler-rdlock-start,
handler-rdlock-done |
handler-wrlock-start,
handler-wrlock-done |
|
handler-unlock-start,
handler-unlock-done |
|
| Filesort | filesort-start, filesort-done |
| Statement | select-start, select-done |
insert-start, insert-done |
|
insert-select-start,
insert-select-done |
|
update-start, update-done |
|
multi-update-start,
multi-update-done |
|
delete-start, delete-done |
|
multi-delete-start,
multi-delete-done |
|
| Network | net-read-start, net-read-done,
net-write-start,
net-write-done |
| Keycache | keycache-read-start,
keycache-read-block,
keycache-read-done,
keycache-read-hit,
keycache-read-miss,
keycache-write-start,
keycache-write-block,
keycache-write-done |
Note
When extracting the argument data from the probes, each
argument is available as
arg, starting
with Narg0. To identify each argument within
the definitions they are provided with a descriptive name, but
you must access the information using the corresponding
arg parameter.
N
The connection-start and
connection-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)connection-start: Triggered after a connection and successful login/authentication have been completed by a client. The arguments contain the connection information:connectionid: Anunsigned longcontaining the connection ID. This is the same as the process ID shown as theIdvalue in the output fromSHOW PROCESSLIST.user: The username used when authenticating. The value is blank for the anonymous user.host: The host of the client connection. For a connection made using Unix sockets, the value is blank.
connection-done: Triggered just as the connection to the client has been closed. The arguments are:status: The status of the connection when it was closed. A logout operation has a value of 0; any other termination of the connection has a nonzero value.connectionid: The connection ID of the connection that was closed.
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 -s
mysql*:::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 | 1
524288 | 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 the
COM_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)command-start: Triggered when a command is submitted to the server.connectionid: The connection ID of the client executing the command.command: An integer representing the command that was executed. Possible values are shown in the following table.Value Name Description 00 COM_SLEEP Internal thread state 01 COM_QUIT Close connection 02 COM_INIT_DB Select database ( USE ...)03 COM_QUERY Execute a query 04 COM_FIELD_LIST Get a list of fields 05 COM_CREATE_DB Create a database (deprecated) 06 COM_DROP_DB Drop a database (deprecated) 07 COM_REFRESH Refresh connection 08 COM_SHUTDOWN Shutdown server 09 COM_STATISTICS Get statistics 10 COM_PROCESS_INFO Get processes ( SHOW PROCESSLIST)11 COM_CONNECT Initialize connection 12 COM_PROCESS_KILL Kill process 13 COM_DEBUG Get debug information 14 COM_PING Ping 15 COM_TIME Internal thread state 16 COM_DELAYED_INSERT Internal thread state 17 COM_CHANGE_USER Change user 18 COM_BINLOG_DUMP Used by a replica or mysqlbinlog to initiate a binary log read 19 COM_TABLE_DUMP Used by a replica to get the source table information 20 COM_CONNECT_OUT Used by a replica to log a connection to the server 21 COM_REGISTER_SLAVE Used by a replica during registration 22 COM_STMT_PREPARE Prepare a statement 23 COM_STMT_EXECUTE Execute a statement 24 COM_STMT_SEND_LONG_DATA Used by a client when requesting extended data 25 COM_STMT_CLOSE Close a prepared statement 26 COM_STMT_RESET Reset a prepared statement 27 COM_SET_OPTION Set a server option 28 COM_STMT_FETCH Fetch a prepared statement user: The user executing the command.host: The client host.
command-done: Triggered when the command execution completes. Thestatusargument contains 0 if the command executed successfully, or 1 if the statement was terminated before normal completion.
The command-start and
command-done probes are best used when
combined with the statement probes to get an idea of overall
execution time.
The query-start and
query-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)query-start: Triggered after the query string has been received from the client. The arguments are:query: The full text of the submitted query.connectionid: The connection ID of the client that submitted the query. The connection ID equals the connection ID returned when the client first connects and theIdvalue in the output fromSHOW PROCESSLIST.database: The database name on which the query is being executed.user: The username used to connect to the server.host: The hostname of the client.
query-done: Triggered once the query has been executed and the information has been returned to the client. The probe includes a single argument,status, which returns 0 when the query is successfully executed and 1 if there was an error.
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 quiet
dtrace:::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.d
Who Database Query Time(ms)
root@localhost test select * from t1 order by i limit 10 0
root@localhost test set global query_cache_size=0 0
root@localhost test select * from t1 order by i limit 10 776
root@localhost test select * from t1 order by i limit 10 773
root@localhost test select * from t1 order by i desc limit 10 795The 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)query-parse-start: Triggered just before the statement is parsed by the MySQL query parser. The single argument,query, is a string containing the full text of the original query.query-parse-done: Triggered when the parsing of the original statement has been completed. Thestatusis an integer describing the status of the operation. A0indicates that the query was successfully parsed. A1indicates that the parsing of the query failed.
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 quiet
mysql*:::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 on
query-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.d
Error parsing select from t1 join (t2) on (t1.i = t2.i) order by t1.s,t1.i limit 10: 36 ms
Parsing 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. The
query-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 the
query-cache-miss probe is triggered
instead.
query-cache-hit(query, rows)
query-cache-miss(query)query-cache-hit: Triggered when the query has been found within the query cache. The first argument,query, contains the original text of the query. The second argument,rows, is an integer containing the number of rows in the cached query.query-cache-miss: Triggered when the query is not found within the query cache. The first argument,query, contains the original text of the 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 quiet
dtrace:::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.d
root@localhost test select * from t1 order by i limit 10 N 1072
root@localhost set global query_cache_size=262144 N 0
root@localhost test select * from t1 order by i limit 10 N 781
root@localhost test select * from t1 order by i limit 10 Y 0The 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)
Note
The information provided in the arguments for
query-start and
query-exec-start are almost identical and
designed so that you can choose to monitor either the entire
query process (using query-start) or only
the execution (using query-exec-start)
while exposing the core information about the user, client,
and query being executed.
query-exec-start: Triggered when the execution of a individual query is started. The arguments are:query: The full text of the submitted query.connectionid: The connection ID of the client that submitted the query. The connection ID equals the connection ID returned when the client first connects and theIdvalue in the output fromSHOW PROCESSLIST.database: The database name on which the query is being executed.user: The username used to connect to the server.host: The hostname of the client.exec_type: The type of execution. Execution types are determined based on the contents of the query and where it was submitted. The values for each type are shown in the following table.Value Description 0 Executed query from sql_parse, top-level query. 1 Executed prepared statement 2 Executed cursor statement 3 Executed query in stored procedure
query-exec-done: Triggered when the execution of the query has completed. The probe includes a single argument,status, which returns 0 when the query is successfully executed and 1 if there was an error.
The *row-{start,done} probes are triggered
each time a row operation is pushed down to a storage engine.
For example, if you execute an
INSERT statement with 100 rows
of data, then the insert-row-start and
insert-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)insert-row-start: Triggered before a row is inserted into a table.insert-row-done: Triggered after a row is inserted into a table.update-row-start: Triggered before a row is updated in a table.update-row-done: Triggered before a row is updated in a table.delete-row-start: Triggered before a row is deleted from a table.delete-row-done: Triggered before a row is deleted from a table.
The arguments supported by the probes are consistent for the
corresponding start and
done probes in each case:
database: The database name.table: The table name.status: The status; 0 for success or 1 for failure.
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 a query-done or
query-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 quiet
dtrace:::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)read-row-start: Triggered when a row is read by the storage engine from the specifieddatabaseandtable. Thescan_flagis set to 1 (true) when the read is part of a table scan (that is, a sequential read), or 0 (false) when the read is of a specific record.read-row-done: Triggered when a row read operation within a storage engine completes. Thestatusreturns 0 on success, or a positive value on failure.
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)index-read-row-start: Triggered when a row is read by the storage engine from the specifieddatabaseandtable.index-read-row-done: Triggered when an indexed row read operation within a storage engine completes. Thestatusreturns 0 on success, or a positive value on failure.
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)handler-rdlock-start: Triggered when a read lock is requested on the specifieddatabaseandtable.handler-wrlock-start: Triggered when a write lock is requested on the specifieddatabaseandtable.handler-unlock-start: Triggered when an unlock request is made on the specifieddatabaseandtable.handler-rdlock-done: Triggered when a read lock request completes. Thestatusis 0 if the lock operation succeeded, or>0on failure.handler-wrlock-done: Triggered when a write lock request completes. Thestatusis 0 if the lock operation succeeded, or>0on failure.handler-unlock-done: Triggered when an unlock request completes. Thestatusis 0 if the unlock operation succeeded, or>0on failure.
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 quiet
mysql*:::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.t2
End: Lock->Read 0 ms
Start: Lock->Unlock test.t2 (25743 ms lock duration)
End: Lock->Unlock 0 ms
Start: Lock->Read test.t2
End: Lock->Read 0 ms
Start: Lock->Unlock test.t2 (1 ms lock duration)
End: Lock->Unlock 0 ms
Start: Lock->Read test.t2
End: Lock->Read 0 ms
Start: Lock->Unlock test.t2 (1 ms lock duration)
End: Lock->Unlock 0 ms
Start: Lock->Read test.t2
End: Lock->Read 0 msThe 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, see Section 8.2.1.14, “ORDER BY Optimization”.
filesort-start(database, table)
filesort-done(status, rows)filesort-start: Triggered when the filesort operation starts on a table. The two arguments to the probe,databaseandtable, identify the table being sorted.filesort-done: Triggered when the filesort operation completes. Two arguments are supplied, thestatus(0 for success, 1 for failure), and the number of rows sorted during the filesort process.
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 quiet
dtrace:::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 an ORDER
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. For SELECT,
INSERT,
INSERT ... (SELECT
FROM ...), DELETE,
and DELETE FROM
t1,t2 operations the number of rows affected is
returned.
For UPDATE and
UPDATE 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 corresponding
WHERE 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)select-start: Triggered before aSELECTstatement.select-done: Triggered at the end of aSELECTstatement.insert-start: Triggered before aINSERTstatement.insert-done: Triggered at the end of anINSERTstatement.insert-select-start: Triggered before anINSERT ... SELECTstatement.insert-select-done: Triggered at the end of anINSERT ... SELECTstatement.update-start: Triggered before anUPDATEstatement.update-done: Triggered at the end of anUPDATEstatement.multi-update-start: Triggered before anUPDATEstatement involving multiple tables.multi-update-done: Triggered at the end of anUPDATEstatement involving multiple tables.delete-start: Triggered before aDELETEstatement.delete-done: Triggered at the end of aDELETEstatement.multi-delete-start: Triggered before aDELETEstatement involving multiple tables.multi-delete-done: Triggered at the end of aDELETEstatement involving multiple tables.
The arguments for the statement probes are:
query: The query string.status: The status of the query.0for success, and>0for failure.rows: The number of rows affected by the statement. This returns the number rows found forSELECT, the number of rows deleted forDELETE, and the number of rows successfully inserted forINSERT.rowsmatched: The number of rows matched by theWHEREclause of anUPDATEoperation.rowschanged: The number of rows actually changed during anUPDATEoperation.
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 quiet
dtrace:::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 0
insert into t2 (select * from t2) 0 275 9
update t2 set i=5 where i > 75 110 110 8
update t2 set i=5 where i < 25 254 134 12
delete from t2 where i < 5 0 0 0Another 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 quiet
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->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 15985The 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)net-read-start: Triggered when a network read operation is started.net-read-done: Triggered when the network read operation completes. Thestatusis anintegerrepresenting the return status for the operation,0for success and1for failure. Thebytesargument is an integer specifying the number of bytes read during the process.net-start-bytes: Triggered when data is written to a network socket. The single argument,bytes, specifies the number of bytes written to the network socket.net-write-done: Triggered when the network write operation has completed. The single argument,status, is an integer representing the return status for the operation,0for success and1for failure.
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 the dynvarsize 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=4m
dtrace:::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 1000000
Net 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 by
keycache-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 the
keycache-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-read-start: Triggered when the keycache read operation is started. Data is read from the specifiedfilepath, reading the specified number ofbytes. Themem_usedandmem_availindicate memory currently used by the keycache and the amount of memory available within the keycache.keycache-read-block: Triggered when the keycache reads a block of data, of the specified number ofbytes, from the index file into the keycache.keycache-read-hit: Triggered when the block of data read from the index file matches the key data requested.keycache-read-miss: Triggered when the block of data read from the index file does not match the key data needed.keycache-read-done: Triggered when the keycache read operation has completed. Themem_usedandmem_availindicate memory currently used by the keycache and the amount of memory available within the keycache.
Keycache writes occur when the index information is updated
during an INSERT,
UPDATE, or DELETE
operation, and the cached key information is flushed back to
the index file.
keycache-write-start: Triggered when the keycache write operation is started. Data is written to the specifiedfilepath, reading the specified number ofbytes. Themem_usedandmem_availindicate memory currently used by the keycache and the amount of memory available within the keycache.keycache-write-block: Triggered when the keycache writes a block of data, of the specified number ofbytes, to the index file from the keycache.keycache-write-done: Triggered when the keycache write operation has completed. Themem_usedandmem_availindicate memory currently used by the keycache and the amount of memory available within the keycache.