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.
