MySQL 5.6 Reference Manual Including MySQL NDB Cluster 7.3-7.4 Reference Guide
MySQL supports the following static probes, organized into groups of functionality.
Table 5.6 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 |
When extracting the argument data from the probes, each
argument is available as
arg
, starting
with N
arg0
. 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
: An unsigned
long
containing the connection ID. This is
the same as the process ID shown as the
Id
value in the output from
SHOW 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. The status
argument 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 the Id
value in
the output from SHOW
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:
shell> ./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 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)
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. The
status
is an integer describing the
status of the operation. A 0
indicates
that the query was successfully parsed. A
1
indicates 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:
shell> ./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:
shell> ./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 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 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 the Id
value in
the output from SHOW
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 specified
database
and table
.
The scan_flag
is 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. The
status
returns 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 specified
database
and table
.
index-read-row-done
: Triggered when an
indexed row read operation within a storage engine
completes. The status
returns 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 specified
database
and table
.
handler-wrlock-start
: Triggered when a
write lock is requested on the specified
database
and table
.
handler-unlock-start
: Triggered when an
unlock request is made on the specified
database
and table
.
handler-rdlock-done
: Triggered when a
read lock request completes. The status
is 0 if the lock operation succeeded, or
>0
on failure.
handler-wrlock-done
: Triggered when a
write lock request completes. The
status
is 0 if the lock operation
succeeded, or >0
on failure.
handler-unlock-done
: Triggered when an
unlock request completes. The status
is
0 if the unlock operation succeeded, or
>0
on 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 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, see Section 8.2.1.13, “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, database
and
table
, identify the table being sorted.
filesort-done
: Triggered when the
filesort operation completes. Two arguments are supplied,
the status
(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 a the only
argument. Depending on the statement type, the information
provided by the corresponding done probe differs. 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 a
SELECT
statement.
select-done
: Triggered at the end of a
SELECT
statement.
insert-start
: Triggered before a
INSERT
statement.
insert-done
: Triggered at the end of an
INSERT
statement.
insert-select-start
: Triggered before
an INSERT ...
SELECT
statement.
insert-select-done
: Triggered at the
end of an INSERT
... SELECT
statement.
update-start
: Triggered before an
UPDATE
statement.
update-done
: Triggered at the end of an
UPDATE
statement.
multi-update-start
: Triggered before an
UPDATE
statement involving
multiple tables.
multi-update-done
: Triggered at the end
of an UPDATE
statement
involving multiple tables.
delete-start
: Triggered before a
DELETE
statement.
delete-done
: Triggered at the end of a
DELETE
statement.
multi-delete-start
: Triggered before a
DELETE
statement involving
multiple tables.
multi-delete-done
: Triggered at the end
of a DELETE
statement
involving multiple tables.
The arguments for the statement probes are:
query
: The query string.
status
: The status of the query.
0
for success, and
>0
for failure.
rows
: The number of rows affected by
the statement. This returns the number rows found for
SELECT
, the number of rows
deleted for DELETE
, and the
number of rows successfully inserted for
INSERT
.
rowsmatched
: The number of rows matched
by the WHERE
clause of an
UPDATE
operation.
rowschanged
: The number of rows
actually changed during an
UPDATE
operation.
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 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 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 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)
net-read-start
: Triggered when a
network read operation is started.
net-read-done
: Triggered when the
network read operation completes. The
status
is an integer
representing the return status for the operation,
0
for success and 1
for failure. The bytes
argument 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,
0
for success and 1
for 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 is 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
specified filepath
, reading the
specified number of bytes
. The
mem_used
and
mem_avail
indicate 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 of
bytes
, 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. The
mem_used
and
mem_avail
indicate 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 specified filepath
, reading the
specified number of bytes
. The
mem_used
and
mem_avail
indicate 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 of bytes
, to the index file from
the keycache.
keycache-write-done
: Triggered when the
keycache write operation has completed. The
mem_used
and
mem_avail
indicate memory currently
used by the keycache and the amount of memory available
within the keycache.