Documentation Home
MySQL 5.7 Reference Manual
Related Documentation Download this Manual
PDF (US Ltr) - 35.1Mb
PDF (A4) - 35.2Mb
Man Pages (TGZ) - 255.8Kb
Man Pages (Zip) - 360.8Kb
Info (Gzip) - 3.4Mb
Info (Zip) - 3.4Mb
Excerpts from this Manual

MySQL 5.7 Reference Manual  /  ...  /  mysqld DTrace Probe Reference

5.8.4.1 mysqld DTrace Probe Reference

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
Group Probes

Note

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

5.8.4.1.1 Connection Probes

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.

Press CTRL+C to copy
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:

Press CTRL+C to copy
#!/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:

Press CTRL+C to copy
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
5.8.4.1.2 Command Probes

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.

Press CTRL+C to copy
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
      Value Name Description
    • 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.

5.8.4.1.3 Query Probes

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.

Press CTRL+C to copy
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:

Press CTRL+C to copy
#!/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:

Press CTRL+C to copy
$> ./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
5.8.4.1.4 Query Parsing Probes

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:

Press CTRL+C to copy
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:

Press CTRL+C to copy
#!/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:

Press CTRL+C to copy
$> ./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
5.8.4.1.5 Query Cache Probes

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.

Press CTRL+C to copy
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:

Press CTRL+C to copy
#!/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:

Press CTRL+C to copy
$> ./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
5.8.4.1.6 Query Execution Probes

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).

Press CTRL+C to copy
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 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.

5.8.4.1.7 Row-Level Probes

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.

Press CTRL+C to copy
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:

Press CTRL+C to copy
#!/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:

Press CTRL+C to copy
St Who DB ConnID Dur ms Query 0 @localhost test 13 20767 insert into t1(select * from t2) 4827 -> Row ops
5.8.4.1.8 Read Row Probes

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.

Press CTRL+C to copy
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.

5.8.4.1.9 Index Probes

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.

Press CTRL+C to copy
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.

5.8.4.1.10 Lock Probes

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.

Press CTRL+C to copy
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:

Press CTRL+C to copy
#!/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:

Press CTRL+C to copy
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
5.8.4.1.11 Filesort Probes

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.14, “ORDER BY Optimization”.

Press CTRL+C to copy
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:

Press CTRL+C to copy
#!/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:

Press CTRL+C to copy
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
5.8.4.1.12 Statement Probes

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.

Press CTRL+C to copy
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:

Press CTRL+C to copy
#!/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:

Press CTRL+C to copy
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:

Press CTRL+C to copy
#!/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.

Press CTRL+C to copy
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
5.8.4.1.13 Network Probes

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:

Press CTRL+C to copy
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.

Press CTRL+C to copy
#!/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.

Press CTRL+C to copy
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)
5.8.4.1.14 Keycache Probes

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.

Press CTRL+C to copy
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 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.