Measuring Read/Write durations with DTrace

I had the situation, where I wanted to see if read/write operations take too much time.

It was something that I thought could be done easily with DTrace. Unfortunately, my DTrace skills are a bit rusty, so I contacted my personal DTrace guru Javier, who gave me a script.

Here is the script for read operations:


slow_read.d:

#!/usr/sbin/dtrace -s

#pragma D option quiet
#pragma D option switchrate=10hz

syscall::*read:entry
{
        this->filistp = curthread->t_procp->p_user.u_finfo.fi_list;
        this->ufentryp = (uf_entry_t *)((uint64_t)this->filistp + (uint64_t)arg0 * (uint64_t)sizeof (uf_entry_t));
        this->filep = this->ufentryp->uf_file;
        self->offset = this->filep->f_offset;
        this->vnodep = this->filep != 0 ? this->filep->f_vnode : 0;
        self->vpath = this->vnodep ? (this->vnodep->v_path != 0 ? cleanpath(this->vnodep->v_path) : "") : "";
        self->sc_trace = this->vnodep ? this->vnodep->v_type == VREG || this->vnodep->v_type == VDIR ? 1 : 0 : 0;
        self->start=timestamp;
}

syscall::*read:return
/self->sc_trace && (timestamp - self->start) > 30000000 /
{
        printf ("Read from %s took %d ms\n", self->vpath, ((timestamp-self->start)/1000000));
        self->vpath = 0;
        self->offset = 0;
        self->sc_trace = 0;
        self->start = 0;
}

The script will return all read operations that take longer than 30ms (adjustable by changing the value of 30000000) , with the respective file name. Of course, if you have large files, this dtrace script doesn't necesserily make sense, but it's perfect for my small files environment...

Running the script will produce this output:

./slow_read.d
Read from /blabla/xyz.log took 205 ms
Read from /blabla/xyz.log  took 42 ms
Read from /blabla/xyz.log took 65 ms
...


Turning this into scripts for writes was easy... just replace the syscall into "write".

slow_write.d:
#!/usr/sbin/dtrace -s

#pragma D option quiet
#pragma D option switchrate=10hz

syscall::*write:entry
{
        this->filistp = curthread->t_procp->p_user.u_finfo.fi_list;
        this->ufentryp = (uf_entry_t *)((uint64_t)this->filistp + (uint64_t)arg0 * (uint64_t)sizeof (uf_entry_t));
        this->filep = this->ufentryp->uf_file;
        self->offset = this->filep->f_offset;
        this->vnodep = this->filep != 0 ? this->filep->f_vnode : 0;
        self->vpath = this->vnodep ? (this->vnodep->v_path != 0 ? cleanpath(this->vnodep->v_path) : "") : "";
        self->sc_trace = this->vnodep ? this->vnodep->v_type == VREG || this->vnodep->v_type == VDIR ? 1 : 0 : 0;
        self->start=timestamp;
}

syscall::*write:return
/self->sc_trace && (timestamp - self->start) > 30000000 /
{
        printf ("Write to %s took %d ms\n", self->vpath, ((timestamp-self->start)/1000000));
        self->vpath = 0;
        self->offset = 0;
        self->sc_trace = 0;
        self->start = 0;
}


With little effort, I have now another view of how my storage is behaving.

Comments

Post a Comment

Popular posts from this blog

Heating up the Data Pipeline (Part 1)

Image
Pre-Processing Data I often hear the question from our customers, how data can be transformed prior to indexing in Splunk. Damien from  Baboonbones  has done a tremendous job in creating add-ons   providing custom inputs for Splunk. Most of his custom inputs provide the means to pre-process data by allowing custom event handlers to be written. Sometimes you still want to pre-process data that gets collected from Splunk's standard input types, like file monitors, Windows EventLogs, scripted inputs etc. Also, not everyone is capable of writing custom event handlers. A requirement these customers have, is that they have rolled out a large number of Splunk Universal Forwarders and they do not want to install another agent. To summarize, the solution capable of pre-processing data, should be easy to use, be easily integrated and be build on top of their existing architecture. How to plumb Splunk Pipelines Splunk has its own fittings to connect a Univer...
Read more

Heating up the Data Pipeline (Part 3)

Image
Welcome back to the "Heating up the Data Pipeline" blog series. In part 1 we talked about how to route data from Splunk to a 3rd party system. In part 2 walked through a simple data flow that passes data collected from Splunk Forwarders through Apache NiFi back to Splunk over the HTTP Event Collector. In this part, we will look at a more complex use case, where we route events to an index, based on the sending host's classification. The classification will be looked up from a CSV file. We will make use of Apache NiFi's new Record-Oriented  data handling capabilities, which will look initially a bit more complicated, but once you grasp it, it will make further Use Cases easier and faster to build. High-Level Dataflow We will again start with our ListentTCP input, but this time we will send the data to another Processor Group. The Processor Group will again emit events suitable for Splunk HEC. Note that we have increased the Max Batch Size from 1 ...
Read more

Heating up the Data Pipeline (Part 2)

Image
In Part 1 we went through how to route events from Splunk to a 3rd party system without losing metadata. Now I'll show you how events can be transformed using Apache NiFi and be sent back to Splunk into the  HTTP Event Collector . Note: The following is not a step-by-step documentation. To learn how to use Apache NiFi you should read the G etting Started Guide . Simple Pass-Through Flow As a first exercise we will create a simple flow, that only passes data through NiFi, without applying any complex transformations. The following picture shows a high-level NiFi flow, that receives events in our custom uncooked event format with a TCP listener, then sends the data further into a transformation "black box" (aka Processor Group), which emits events in a format, that can be ingested into a Splunk HTTP Event Collector input. Apache Nifi currently provides a rapidly growing number of processors (currently 266), which can be used for data ingestion, transfo...
Read more