Thread: What happens on a commit?
I am trying to diagnose a slowness issue in some of my databases. I think the issue is due to a hardware/network upgrade over the weekend, but like all dba's, I have to prove it.
Right now, I have almost all commits being issues taking between 1 and 5 seconds to complete. The can take as long as 20 seconds. What exactly happens when a commit is issues to PostgreSQL?
Is there a way to trace what is going on internally? I do have a large process that I can start that will run many transactions during a single session.
Anyway, any help would be appreciated.
Thanks,
Chris
PG 8.1.3
RH 4.0 AS
Right now, I have almost all commits being issues taking between 1 and 5 seconds to complete. The can take as long as 20 seconds. What exactly happens when a commit is issues to PostgreSQL?
Is there a way to trace what is going on internally? I do have a large process that I can start that will run many transactions during a single session.
Anyway, any help would be appreciated.
Thanks,
Chris
PG 8.1.3
RH 4.0 AS
I found an e-mail showing how to strace and here is what I have found. Does it help/mean anything to those who can decode this?
We are installing PostgreSQL from the official rpms.
Chris
time strace -c -p 2690
Process 2690 attached - interrupt to quit
Process 2690 detached
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
42.80 13.003288 251 51790 recv
17.47 5.306686 30 175916 send
16.23 4.930150 14 342118 stat64
10.26 3.117593 18 174533 write
8.22 2.497767 9 292070 gettimeofday
2.63 0.798323 462 1727 fdatasync
1.83 0.554745 6 92179 _llseek
0.46 0.138782 11 12896 brk
0.09 0.026920 19 1433 semop
0.02 0.006847 4 1734 time
0.00 0.000494 16 31 read
0.00 0.000253 23 11 open
0.00 0.000088 7 12 close
0.00 0.000013 13 1 kill
0.00 0.000010 10 1 sigreturn
0.00 0.000001 1 1 fsync
------ ----------- ----------- --------- --------- ----------------
100.00 30.381960 1146453 total
real 27m21.090s
user 0m5.379s
sys 0m23.073s
We are installing PostgreSQL from the official rpms.
Chris
time strace -c -p 2690
Process 2690 attached - interrupt to quit
Process 2690 detached
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
42.80 13.003288 251 51790 recv
17.47 5.306686 30 175916 send
16.23 4.930150 14 342118 stat64
10.26 3.117593 18 174533 write
8.22 2.497767 9 292070 gettimeofday
2.63 0.798323 462 1727 fdatasync
1.83 0.554745 6 92179 _llseek
0.46 0.138782 11 12896 brk
0.09 0.026920 19 1433 semop
0.02 0.006847 4 1734 time
0.00 0.000494 16 31 read
0.00 0.000253 23 11 open
0.00 0.000088 7 12 close
0.00 0.000013 13 1 kill
0.00 0.000010 10 1 sigreturn
0.00 0.000001 1 1 fsync
------ ----------- ----------- --------- --------- ----------------
100.00 30.381960 1146453 total
real 27m21.090s
user 0m5.379s
sys 0m23.073s
Chris Hoover escribió: > I found an e-mail showing how to strace and here is what I have found. Does > it help/mean anything to those who can decode this? > > We are installing PostgreSQL from the official rpms. > > Chris > > time strace -c -p 2690 > Process 2690 attached - interrupt to quit > Process 2690 detached > % time seconds usecs/call calls errors syscall > ------ ----------- ----------- --------- --------- ---------------- > 42.80 13.003288 251 51790 recv > 17.47 5.306686 30 175916 send This means that 60% of the time spent by system calls is due to network operations. But they account to 18.3 seconds, whereas this > real 27m21.090s > user 0m5.379s > sys 0m23.073s says that the total time spent is 27:21. So you have to explain the remaining 27:03 which are elsewhere. -- Alvaro Herrera http://www.CommandPrompt.com/ The PostgreSQL Company - Command Prompt, Inc.
Ok, we are looking more into this. In the mean time, can someone please explain to me (or point me to the correct documentation) what happens in PostgreSQL when a commit is issued. What exactly does the database do?
Thanks,
Chris
Thanks,
Chris
On 5/22/07, Alvaro Herrera <alvherre@commandprompt.com> wrote:
Chris Hoover escribió:
> I found an e-mail showing how to strace and here is what I have found. Does
> it help/mean anything to those who can decode this?
>
> We are installing PostgreSQL from the official rpms.
>
> Chris
>
> time strace -c -p 2690
> Process 2690 attached - interrupt to quit
> Process 2690 detached
> % time seconds usecs/call calls errors syscall
> ------ ----------- ----------- --------- --------- ----------------
> 42.80 13.003288 251 51790 recv
> 17.47 5.306686 30 175916 send
This means that 60% of the time spent by system calls is due to network
operations. But they account to 18.3 seconds, whereas this
> real 27m21.090s
> user 0m5.379s
> sys 0m23.073s
says that the total time spent is 27:21. So you have to explain the
remaining 27:03 which are elsewhere.
--
Alvaro Herrera http://www.CommandPrompt.com/
The PostgreSQL Company - Command Prompt, Inc.
Chris Hoover escribió: > Ok, we are looking more into this. In the mean time, can someone please > explain to me (or point me to the correct documentation) what happens in > PostgreSQL when a commit is issued. What exactly does the database do? It writes a commit WAL record and flushes (fsync) the WAL up to that point. This is the more important bit. Also, async notifies are sent (those you started with NOTIFY), and files corresponding to some commands are deleted (e.g. TRUNCATE, CLUSTER, REINDEX). Temp tables with ON COMMIT setting may be operated upon. It entirely depends on what the transaction did. -- Alvaro Herrera http://www.CommandPrompt.com/ The PostgreSQL Company - Command Prompt, Inc.