Tuesday Jun 30, 2009

How to add DTrace probes to your application

MC Brown and I co-presented a session at CommunityOne West on how to add probes to applications, using MySQL and PostgreSQL as case study. In the presentation, I used a very simple example to demonstrate how easy it is to add probes. If you want to try out yourself, here is the code. Extract the files, run gmake (or gnumake on OS X) to build, and run the executable in one terminal and the DTrace script in another terminal to see the output from the probes. To see more complicated examples, checkout the MySQL or PostgreSQL source code.

Monday Jun 29, 2009

More on the demos from PgCon 2009

At PgCon 2009 in Ottawa, I did a lightning talk on DTrace probes in PostreSQL 8.4. I wanted to show several demos but ran out of time. If you want to try them out, use the scripts below.

Here is the script, query_time.d, used in slide 14. This script is used to identify slow queries by printing out the query execution time.


#!/usr/sbin/dtrace -s
#pragma D option quiet

dtrace:::BEGIN
{
  printf("Tracing... Hit Ctrl-C to end.\\n");
}

postgresql\*:::query-start
{
    self->query = copyinstr(arg0);
    self->ts = timestamp;
}

postgresql\*:::query-done
/self->ts/
{
    @query_time[self->query] = avg(timestamp - self->ts);
    self->query = 0;
    self->ts = 0;
}

dtrace:::END
{
     printf("%10s %s\\n", "TIME (ns)", "QUERY");
     printf("==============================================================\\n");
     printa("%@10d %s\\n", @query_time);
}

Here is the second script, sort.d, used in slide 16. This script tells the type of sort, whether the sort was done in memory or on disk, and the time to perform the sort.


#!/usr/sbin/dtrace -qs

dtrace:::BEGIN
{
        sorttype[0] = "TUPLE";
        sorttype[1] = "INDEX";
        sorttype[2] = "DATUM";

        sortmethod[0] = "INTERNAL";
        sortmethod[1] = "EXTERNAL";
}

postgresql\*:::sort-start
{
        self->ts = timestamp;
        printf("\\nBegin %s sort, workmem = %d KB \\n", sorttype[arg0], arg3);
}

postgresql\*:::sort-done
/self->ts && arg0 == 0/
{
        /\* Internal Sort \*/
        printf("%s sort ended, space used = %d KB \\n", sortmethod[arg0], arg1);
        printf("Sort time = %d ms\\n\\n", (timestamp - self->ts) / 1000000);
}

postgresql\*:::sort-done
/self->ts && arg0 == 1 /
{        /\* External Sort \*/
        printf("%s sort ended, space used = %d disk blocks\\n", sortmethod[arg0], 
arg1);
        printf("Sort time = %d ms\\n\\n", (timestamp - self->ts) / 1000000);
}

Below is the last script, query_trace.d, used in slide 23. This script provides useful data that will allow you to dig down deeper. In this example, the buffer reads to table 16397 (this is the OID) is huge. This signals a red flag that an index may be needed for this table. To find out the table name from OID, run "SELECT relname FROM pg_class WHERE relfilenode=16397" in psql.


#!/usr/sbin/dtrace -qs

postgresql\*:::query-start
{
        self->ts = timestamp;
        self->pid = pid;
}

postgresql\*:::buffer-read-start
/self->pid/
{
        self->readts = timestamp;
}

postgresql\*:::buffer-read-done
/self->pid && arg7/
{
        /\* Buffer cache hit \*/
        @read_count[arg2, arg3, arg4] = count();
        @read_hit_total["Total buffer cache hits      : "] = count();
        @read_hit_time["Average read time from cache : "] = avg (timestamp - self->readts);
        self->readts = 0;
}

postgresql\*:::buffer-read-done
/self->pid && !arg7/
{
        /\* Buffer cache miss \*/
        @read_count[arg2, arg3, arg4] = count();
        @read_miss_total["Total buffer cache misses    : "] = count();
        @read_miss_time["Average read time from disk  : "] = avg (timestamp - self->readts);
        self->readts = 0;
}

postgresql\*:::buffer-flush-start
/self->pid/
{
        self->writets = timestamp;
}

postgresql\*:::buffer-flush-done
/self->pid/
{
        @write_count[arg2, arg3, arg4] = count();
        @write_time["Average write time to disk   : "] = avg (timestamp - self->writets);
        self->writets = 0;
}

postgresql\*:::query-done
/self->ts && self->pid == pid/
{
        printf("\\n============ Buffer Read Counts ============\\n");
        printf("%10s %10s %10s %10s\\n","Tablespace", "Database", "Table", "Count");
        printa("%10d %10d %10d %@10d\\n",@read_count);

        printf("\\n======= Buffer Write Request Counts ========\\n");
        printf("%10s %10s %10s %10s\\n","Tablespace", "Database", "Table", "Count");
        printa("%10d %10d %10d %@10d\\n",@write_count);

        printf("\\n========== Additional Statistics ===========\\n");

        printf ("Backend PID    : %d\\n", pid);
        printf ("SQL Statement  : %s\\n", copyinstr(arg0));
        printf ("Execution time : %d.%03d sec (%d ns)\\n", (timestamp - self->ts) / 1000000000, ((timestamp - self->ts) / 1000000) % 1000, timestamp - self->ts);
        printa("\\n%19s %@8d\\n",@read_hit_total);
        printa("%19s %@8d\\n",@read_miss_total);
        printa("%19s %@8d (ns)\\n",@read_hit_time);
        printa("%19s %@8d (ns)\\n",@read_miss_time);
        printa("%19s %@8d (ns)\\n",@write_time);
        printf("\\n\\n");

        trunc(@read_count);
        trunc(@write_count);
        trunc(@read_hit_total);
        trunc(@read_miss_total);
        trunc(@read_hit_time);
        trunc(@read_miss_time);
        trunc(@write_time);

        self->ts = 0;
        self->pid = 0;
}

To see more sample scripts as well as a GUI tool, check out the PostgreSQL DTrace Toolkit.

Sunday Jun 28, 2009

PostgreSQL DTrace Toolkit

As many of you know, PostgreSQL 8.4 has quite a few more DTrace probes. See my previous blog post for more details . To use the probes, you need to write DTrace scripts, which is quite easy to do, but to make it easier to use the probes (especially for those who are new to DTrace), I have written some scripts that you can just run from the command line. In addition, I've integrated some of those script with Chime to make it even easier to visualize the data. Check out the toolkit on PgFoundry.
About

rnl

Search

Categories
Archives
« June 2009
SunMonTueWedThuFriSat
 
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
    
       
Today