diff options
-rw-r--r-- | support-files/dtrace/locktime.d | 49 | ||||
-rw-r--r-- | support-files/dtrace/query-execandqc.d | 36 | ||||
-rw-r--r-- | support-files/dtrace/query-filesort-time.d | 47 | ||||
-rw-r--r-- | support-files/dtrace/query-network-time.d | 63 | ||||
-rw-r--r-- | support-files/dtrace/query-parse-time.d | 23 | ||||
-rw-r--r-- | support-files/dtrace/query-rowops.d | 66 | ||||
-rw-r--r-- | support-files/dtrace/query-time.d | 25 | ||||
-rw-r--r-- | support-files/dtrace/statement-time.d | 45 | ||||
-rw-r--r-- | support-files/dtrace/statement-type-aggregate.d | 46 |
9 files changed, 400 insertions, 0 deletions
diff --git a/support-files/dtrace/locktime.d b/support-files/dtrace/locktime.d new file mode 100644 index 00000000000..c9b509ca61e --- /dev/null +++ b/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); +} diff --git a/support-files/dtrace/query-execandqc.d b/support-files/dtrace/query-execandqc.d new file mode 100644 index 00000000000..64599223f55 --- /dev/null +++ b/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); +} diff --git a/support-files/dtrace/query-filesort-time.d b/support-files/dtrace/query-filesort-time.d new file mode 100644 index 00000000000..425ed3863aa --- /dev/null +++ b/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); +} diff --git a/support-files/dtrace/query-network-time.d b/support-files/dtrace/query-network-time.d new file mode 100644 index 00000000000..f0483778fb0 --- /dev/null +++ b/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)); +} diff --git a/support-files/dtrace/query-parse-time.d b/support-files/dtrace/query-parse-time.d new file mode 100644 index 00000000000..31fe1275e1a --- /dev/null +++ b/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)); +} diff --git a/support-files/dtrace/query-rowops.d b/support-files/dtrace/query-rowops.d new file mode 100644 index 00000000000..a16f3df90f4 --- /dev/null +++ b/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); +} diff --git a/support-files/dtrace/query-time.d b/support-files/dtrace/query-time.d new file mode 100644 index 00000000000..9983a73b7e5 --- /dev/null +++ b/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); +} diff --git a/support-files/dtrace/statement-time.d b/support-files/dtrace/statement-time.d new file mode 100644 index 00000000000..d00fc10348d --- /dev/null +++ b/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; +} diff --git a/support-files/dtrace/statement-type-aggregate.d b/support-files/dtrace/statement-type-aggregate.d new file mode 100644 index 00000000000..32d88cb5143 --- /dev/null +++ b/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); +} |