public
Created

MySQL slow queries caused by filesystem latency

  • Download Gist
mysql_pid_fslatency_slowlog0.d
D
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58
#!/usr/sbin/dtrace -s
/*
* mysqld_pid_fslatency_slowlog0.d Print slow filesystem I/O events.
*
* USAGE: ./mysql_pid_fslatency_slowlog0.d mysqld_PID
*
* This traces all mysqld filesystem I/O (including some that may be
* asynchronous to queries and not causing query latency), and prints
* those individual I/O taking longer than the MIN_FS_LATENCY_MS tunable.
*
* This is a monitoring tool (if Cloud Analytics is not available).
*
* TESTED: these pid-provider probes may only work on some mysqld versions.
* 5.0.51a: ok
*/
 
#pragma D option quiet
 
inline int MIN_FS_LATENCY_MS = 1000;
 
dtrace:::BEGIN
{
min_ns = MIN_FS_LATENCY_MS * 1000000;
}
 
pid$1::os_file_read:entry,
pid$1::os_file_write:entry,
pid$1::my_read:entry,
pid$1::my_write:entry
{
self->start = timestamp;
}
 
pid$1::os_file_read:return,
pid$1::my_read:return
/self->start && (timestamp - self->start) > min_ns/
{
this->ms = (timestamp - self->start) / 1000000;
printf("%Y filesystem read > %d ms: %d ms\n", walltimestamp,
MIN_FS_LATENCY_MS, this->ms);
}
 
pid$1::os_file_write:return,
pid$1::my_write:return
/self->start && (timestamp - self->start) > min_ns/
{
this->ms = (timestamp - self->start) / 1000000;
printf("%Y filesystem write > %d ms: %d ms\n", walltimestamp,
MIN_FS_LATENCY_MS, this->ms);
}
 
pid$1::os_file_read:return,
pid$1::os_file_write:return,
pid$1::my_read:return,
pid$1::my_write:return
{
self->start = 0;
}

Please sign in to comment on this gist.

Something went wrong with that request. Please try again.