Re: [PERFORM] Help with duration of statement: EXECUTE unnamed [PREPARE: COMMIT]
On 10-10-18 11:02 AM, Tom Lane wrote: Mladen Gogalamladen.gog...@vmsinfo.com writes: Tom Lane wrote: My guess would be overstressed disk subsystem. A COMMIT doesn't require much except fsync'ing the commit WAL record down to disk ... Doesn't the commit statement also release all the locks held by the transaction? Yeah, and there's a nontrivial amount of other cleanup too, but it all amounts to just changes in in-memory data structures. I don't see that taking five seconds, especially not if commits of similar transactions usually take much less than that. regards, tom lane Thanks for the info. The system is a QA system under load. It is running 200 jobs per minute, so yes the disk it stressed. Our application bundles PG into its install and installs the app and database all on the same filesystem. The QA folks probably have lots of logging turned on as well. I am not sure what front-end client is doing the prepare/execute on a commit - I found it strange, I'm glad someone else does as well. The web app is using jboss with connection pooling, but there is a scheduler built in C using libpq as well. Thanks for the hint on deferred fk, I'll check, but I think if that was the case it would be happening much more often - like maybe almost all commits for this transaction type. The OS is RH 5.2 64-bit, and I'm surprised they don't have iostat installed on it by default. There is vmstat. The load avg is 06:36:49 up 28 days, 15:20, 5 users, load average: 19.44, 22.59, 22.50 Okay - I'm starting to see other stmts other than just commits taking longer than 5 secs sometimes as well now - stress test has been running for 3 days now...some commits 17 and 15 secs ouch... 2010-10-19 05:44:35 EDT [11760]: [10-1] LOG: duration: 17137.425 ms statement: commit 2010-10-19 05:44:36 EDT [10704]: [14-1] LOG: duration: 14928.903 ms statement: EXECUTE unnamed [PREPARE: COMMIT] 2010-10-19 05:44:36 EDT [12535]: [1-1] LOG: duration: 13241.032 ms statement: EXECUTE unnamed [PREPARE: update scheduled_job set active_filename=$1, active_state=$2, begin_time=$3, changed_by=$4, changed_on=$5, created_by=$6, created_on=$7, current_run=$8, deferred_time=$9, deleted=$10, end_time=$11, expire_at=$12, frequency_spec=$13, job_class=$14, contract_id=$15, job_name=$16, last_active_status_msg=$17, last_exit_code=$18, package_id=$19, perc_denominator=$20, perc_numerator=$21, retry_at=$22, scheduled_at=$23, scheduled_state=$24, start_at=$25, states_list=$26, timezone=$27, total_runs=$28 where id=$29] 2010-10-19 05:44:41 EDT [11760]: [11-1] LOG: duration: 6000.118 ms statement: commit 2010-10-19 05:44:49 EDT [10704]: [15-1] LOG: duration: 13804.450 ms statement: EXECUTE unnamed [PREPARE: COMMIT] 2010-10-19 05:44:49 EDT [12535]: [2-1] LOG: duration: 13807.317 ms statement: EXECUTE unnamed [PREPARE: COMMIT] 2010-10-19 05:45:00 EDT [11760]: [12-1] LOG: duration: 18879.010 ms statement: commit 2010-10-19 05:45:18 EDT [10704]: [16-1] LOG: duration: 28177.626 ms statement: EXECUTE unnamed [PREPARE: COMMIT] 2010-10-19 05:45:20 EDT [11760]: [13-1] LOG: duration: 19740.822 ms statement: commit 2010-10-19 05:45:20 EDT [13093]: [1-1] LOG: duration: 20828.412 ms statement: EXECUTE unnamed [PREPARE: COMMIT] I do not have a vmstat to look at from when the stmts above executed, wish I did, here is vmstat 5, now but at this time everything is executing under 5 secs... procs ---memory-- ---swap-- -io --system-- -cpu-- r b swpd free buff cache si sobibo in cs us sy id wa st 65 0 3232 340480 166812 221288400 0 1519 1676 50841 70 30 0 0 0 57 0 3232 273332 166856 221279600 0 1157 1609 52887 69 31 0 0 0 73 0 3232 320668 166884 221266800 0 781 1458 53420 70 30 0 0 0 44 0 3232 393240 166900 22132720043 1336 1578 53155 70 30 0 0 0 42 0 3232 349176 166928 221324400 2 656 1449 52006 70 30 0 0 0 35 0 3232 299320 166972 221343600 3 1312 1582 51126 75 25 0 0 0 68 0 3232 265868 167012 221342000 0 739 1484 51982 74 26 0 0 0 42 0 3232 234672 167048 221244000 2 772 1550 50536 74 26 0 0 0 72 0 3232 252232 167080 221300400 0 1192 1616 48063 77 23 0 0 0 56 0 3232 336852 167112 221322000 0 699 1433 50655 78 22 0 0 0 38 0 3232 302212 167148 221338000 0 786 1578 49895 76 24 0 0 0 61 0 3232 381884 167180 221326000 6 943 1525 46474 77 23 0 0 0 66 0 3232 366568 167216 221371600 0 1150 1491 39232 82 18 0 0 0 93 0 3232 343792 167232 221368000 2 946 1504 39030 82 18 0 0 0 66 0 3232 377376 167268 221326000 0 954 1427 37206 84 16 0 0 0 60 0 3232 319552 167288 221295200 0 385 1365 34413 83 17 0 0 0 53 0
Re: [PERFORM] Help with duration of statement: EXECUTE unnamed [PREPARE: COMMIT]
Eric Comeau ecom...@signiant.com writes: Okay - I'm starting to see other stmts other than just commits taking longer than 5 secs sometimes as well now - stress test has been running for 3 days now...some commits 17 and 15 secs ouch... If it's not just commits then some of the stranger theories go away. I think you're almost certainly looking at overstressed disk. It'd be worth your while to turn on checkpoint logging and see if the slow operations occur during checkpoints. If so, you might be able to ameliorate things by tweaking the checkpoint parameters to spread out checkpoint I/O load some more. But the bottom line here is that you haven't got much headroom between your application's needs and the max throughput available from your disk. Better disk hardware will be the only real cure. regards, tom lane -- Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-performance
[PERFORM] Help with duration of statement: EXECUTE unnamed [PREPARE: COMMIT]
We currently have log_min_duration_statement = 5000 and are seeing statements like the following logged 2010-10-16 05:55:52 EDT [6334]: [1-1] LOG: duration: 5572.517 ms statement: EXECUTE unnamed [PREPARE: COMMIT] 2010-10-16 06:06:24 EDT [26856]: [1-1] LOG: duration: 5617.866 ms statement: EXECUTE unnamed [PREPARE: COMMIT] 2010-10-16 06:06:24 EDT [20740]: [13-1] LOG: duration: 5210.190 ms statement: EXECUTE unnamed [PREPARE: COMMIT] 2010-10-16 08:24:06 EDT [8743]: [1-1] LOG: duration: 6487.346 ms statement: EXECUTE unnamed [PREPARE: COMMIT] Questions; 1) What do these statements mean? 2) How do I dig deeper to determine why they are taking longer than 5 secs. Version Info -- select version(); version PostgreSQL 8.1.17 on x86_64-unknown-linux-gnu, compiled by GCC gcc (GCC) 4.1.1 20070105 (Red Hat 4.1.1-52) -- Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-performance
Re: [PERFORM] Help with duration of statement: EXECUTE unnamed [PREPARE: COMMIT]
Eric Comeau ecom...@signiant.com writes: 2010-10-16 05:55:52 EDT [6334]: [1-1] LOG: duration: 5572.517 ms statement: EXECUTE unnamed [PREPARE: COMMIT] 2010-10-16 06:06:24 EDT [26856]: [1-1] LOG: duration: 5617.866 ms statement: EXECUTE unnamed [PREPARE: COMMIT] 2010-10-16 06:06:24 EDT [20740]: [13-1] LOG: duration: 5210.190 ms statement: EXECUTE unnamed [PREPARE: COMMIT] 2010-10-16 08:24:06 EDT [8743]: [1-1] LOG: duration: 6487.346 ms statement: EXECUTE unnamed [PREPARE: COMMIT] Questions; 1) What do these statements mean? They appear to be COMMIT commands. (It's pretty stupid to be using the PREPARE/EXECUTE machinery to execute a COMMIT, but that's evidently what your client-side code is doing.) 2) How do I dig deeper to determine why they are taking longer than 5 secs. My guess would be overstressed disk subsystem. A COMMIT doesn't require much except fsync'ing the commit WAL record down to disk ... but if the disk is too busy to process that request quickly, you might have to wait. It also seems possible that the filesystem is interlocking the fsync on the WAL file with previous writes to other files. Anyway, watching things with vmstat or iostat to see if there's an activity spike when this is happening would confirm or refute that idea. [ thinks for a bit ... ] Actually, it's possible that the COMMIT command is doing nontrivial work before it can really commit. Perhaps you have deferred foreign keys to check? regards, tom lane -- Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-performance
Re: [PERFORM] Help with duration of statement: EXECUTE unnamed [PREPARE: COMMIT]
Tom Lane wrote: My guess would be overstressed disk subsystem. A COMMIT doesn't require much except fsync'ing the commit WAL record down to disk ... Doesn't the commit statement also release all the locks held by the transaction? -- Mladen Gogala Sr. Oracle DBA 1500 Broadway New York, NY 10036 (212) 329-5251 http://www.vmsinfo.com The Leader in Integrated Media Intelligence Solutions -- Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-performance
Re: [PERFORM] Help with duration of statement: EXECUTE unnamed [PREPARE: COMMIT]
Mladen Gogala mladen.gog...@vmsinfo.com writes: Tom Lane wrote: My guess would be overstressed disk subsystem. A COMMIT doesn't require much except fsync'ing the commit WAL record down to disk ... Doesn't the commit statement also release all the locks held by the transaction? Yeah, and there's a nontrivial amount of other cleanup too, but it all amounts to just changes in in-memory data structures. I don't see that taking five seconds, especially not if commits of similar transactions usually take much less than that. regards, tom lane -- Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-performance
