Added DTrace example scripts

support-files/dtrace/locktime.d

@@ -0,0 +1,49 @@
+#!/usr/sbin/dtrace -s                                                                                                            
+#
+# Shows the time that an individual lock is applied to a database and table
+# Shows the time to achieve the lock, and the time the table was locked
+
+o#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);
+}

support-files/dtrace/query-execandqc.d

@@ -0,0 +1,36 @@
+#!/usr/sbin/dtrace -s
+#
+# Show query execution times, indicating whether the query-cache was used
+
+#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);
+}

support-files/dtrace/query-filesort-time.d

@@ -0,0 +1,47 @@
+#!/usr/sbin/dtrace -s
+#
+# Show the time taken for a query, including the time taken to 
+# sort the results using filesort 
+
+#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);
+}

support-files/dtrace/query-network-time.d

@@ -0,0 +1,63 @@
+#!/usr/sbin/dtrace -s
+#
+# Show the time taken to execute a query, include the bytes and time taken
+# to transfer the information over the network to/from the client
+
+#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));
+}

support-files/dtrace/query-parse-time.d

@@ -0,0 +1,23 @@
+#!/usr/sbin/dtrace -s
+#
+# Shows time take to actually parse the query statement
+
+#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));
+}

support-files/dtrace/query-rowops.d

@@ -0,0 +1,66 @@
+#!/usr/sbin/dtrace -s
+#
+# Calculates the time (and operations) for accessing data from individual
+# rows for each query
+
+#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);
+}

support-files/dtrace/query-time.d

@@ -0,0 +1,25 @@
+#!/usr/sbin/dtrace -s
+#
+# Shows basic query execution time, who execute the query, and on what database
+
+#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);
+}

support-files/dtrace/statement-time.d

@@ -0,0 +1,45 @@
+#!/usr/sbin/dtrace -s
+#
+# Creates a report on each query executed at the individual statement
+# level, showing rows matched, updated, and total query time
+
+#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;
+}

support-files/dtrace/statement-type-aggregate.d

@@ -0,0 +1,46 @@
+#!/usr/sbin/dtrace -s
+# 
+# Creates an aggregate report of the time spent perform queries of the four main
+# types (select, insert, update, delete)
+#
+# Report generated every 30s
+
+#pragma D option quiet
+
+dtrace:::BEGIN
+{
+   printf("Reporting...Control-C to stop\n");
+}
+
+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);
+}