2007-06-06

DTrace & Postgresql - io tuning

We have one application based on postgresql database. Recently we encountered some performance problems with uploading bigger amount of data into the database. To find out what is going on I wanted to compare normal utility of the server to the state when we are loading the additional data and see the differences. One of the things to watch was IO. To see what the server was doing at the moment I ran simple dtrace one-liner:

time dtrace -wn 'io:::start {@[args[2]->fi_pathname, args[0]->b_flags & B_READ ? "R" : "W"] = count ();}' -n 'END {trunc(@,3)}'

dtrace: description 'io:::start ' matched 6 probes
dtrace: description 'END' matched 1 probe
dtrace: allowing destructive actions
^C
CPU ID FUNCTION:NAME
3 2 :END

/export/home/postgres/nowa_baza/base/16399/33743 R 4816
/export/home/postgres/nowa_baza/pg_xlog/000000010000000200000068 W 5436
/export/home/postgres/nowa_baza/base/16399/40932 R 138166

real 12m36.483s
user 0m0.601s
sys 0m0.477s


At the moment the server was really idle so such amount of reads from database file was astounding ! I told our DBA about it and he answered "Wait a moment ...". After a minute I ran again the same DTrace one-liner and :

dtrace: description 'io:::start ' matched 6 probes
dtrace: description 'END' matched 1 probe
dtrace: allowing destructive actions
^C
CPU ID FUNCTION:NAME
3 2 :END

/export/home/postgres/nowa_baza/pg_xlog/000000010000000200000067 W 3005
/export/home/postgres/nowa_baza/base/16399/33743 R 3812
/export/home/postgres/nowa_baza/pg_xlog/000000010000000200000068 W 4226

The reads from nowa_baza/base/16399/40932 disappeared ! I asked again our DBA what he had done and he answered "Just refreshed database statistics."

You know: just daily use of DTrace :-)



No comments: