5.7.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:

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

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

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