5.7.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 will be triggered 100 times each, for each row insert.

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

The arguments supported by the probes are consistent for the corresponding start and done probes in each case:

Because the row-level probes are triggered for each individual row access, these probes can be triggered many thousands of times each second, which may have a detrimental effect on both the monitoring script and MySQL. The DTrace environment should limit the triggering on these probes to prevent the performance being adversely affected. Either use the probes sparingly, or use counter or aggregation functions to report on these probes and then provide a summary when the script terminates or as part of 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 quietdtrace:::BEGIN{   printf("%-2s %-10s %-10s %9s %9s %-s \n",          "St", "Who", "DB", "ConnID", "Dur ms", "Query");}mysql*:::query-start{   self->query = copyinstr(arg0);   self->who   = strjoin(copyinstr(arg3),strjoin("@",copyinstr(arg4)));   self->db    = copyinstr(arg2);   self->connid = arg1;   self->querystart = timestamp;   self->rowdur = 0;}mysql*:::query-done{   this->elapsed = (timestamp - self->querystart) /1000000;   printf("%2d %-10s %-10s %9d %9d %s\n",          arg0, self->who, self->db,          self->connid, this->elapsed, self->query);}mysql*:::query-done/ self->rowdur /{   printf("%34s %9d %s\n", "", (self->rowdur/1000000), "-> Row ops");}mysql*:::insert-row-start{   self->rowstart = timestamp;}mysql*:::delete-row-start{   self->rowstart = timestamp;}mysql*:::update-row-start{   self->rowstart = timestamp;}mysql*:::insert-row-done{   self->rowdur += (timestamp-self->rowstart);}mysql*:::delete-row-done{   self->rowdur += (timestamp-self->rowstart);}mysql*:::update-row-done{   self->rowdur += (timestamp-self->rowstart);}

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

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