On Tue, Dec 30, 2014 at 7:25 PM, Maxim Boguk <maxim.boguk@xxxxxxxxx> wrote:
On Wed, Dec 31, 2014 at 11:10 AM, Pawel Veselov <pawel.veselov@xxxxxxxxx> wrote[skipped]2) try pg_stat_statements, setting "pg_stat_statements.track = all". see:
http://www.postgresql.org/docs/9.4/static/pgstatstatements.html
I have used this to profile some functions, and it worked pretty well. Mostly I use it on a test box, but once ran it on the live, which was scary, but worked great.That looks promising. Turned it on, waiting for when I can turn the server at the next "quiet time".I have to say this turned out into a bit of a disappointment for this use case. It only measures total time spent in a call. So, it sends up operations that waited a lot on some lock. It's good, but it would be great if total_time was provided along with wait_time (and io_time may be as well, since I also see operations that just naturally have to fetch a lot of data)1) pg_stat_statements provide an information about io_time of each statement but you should have track_io_timing enabled for that.
Enabled that now. Still the top winners are the functions that probably lock for a long (relatively) time. This did help my find some crap that either was missing an index, or used an unreasonable join, and just needed re-writing. One entry that doesn't make sense to me is:
total_time - io_time = 1,366,773
calls = 666,542
query = SELECT * FROM q_SCHEDULER_STATE WHERE SCHED_NAME = ?
The table only has 18 rows, there is an index, but the analyzer chooses to ignore it, which is right since sched_name column has the same value for all rows. So all rows are returned in SELECT. The time to run that query under database load varies from 0.09 to 70ms.
This is a distraction from the main topic, though, but does stand out odd.
2) About locking I suggest enable log_lock_waits and set deadlock_timeout to say 100ms (just for testing purposes), and than any lock waiting more than 100ms will be logged with some useful additional info.
PPS: btw, please check the database logs for deadlocks messages, your setup around "and then call a pgsql function to merge the data from its tables into the common tables" part could be easily deadlock prone.
I don't have I have abnormal problem with locking. I wanted to eliminate locking time out of the pg_stat_statement, to address queries that aren't waiting on disk and/or locks first, as my problem is high CPU, not specific query performance. I don't have deadlocks for sure -- I had them before, and I would normally get an error if there was a deadlock. We process all the records in exactly the same order of keys to avoid deadlocks.
PPPS: and the last suggestion, after you finished with the "write all the data into its own tables", then application should perform analyze of these own tables (or you could have weird/inefficient plans during last stage).
Any references to back this up? I don't particularly mind doing it, but I wonder if analysis can be more expensive the processing. These tables get a few hundreds of records inserted/updated, then are entirely processed (with expected full scans), and then deleted...
PS: your setup look pretty complicated and hard to analyze without seeing all involved table structures, transaction/query flow, and (especially) involved procedures source code.
Sure :) At this point, I've put together the "bulk merge" code as well. I can't quite see much of a difference, actually, but it's hard to trust the execution times, as on the same amount of data they vary from, say, 0.5s to 2s, and the sample data is not stepping on any other locks. In general, I'm afraid all those left joins and multiple scans, even over small amount of data, is nullifying any positive effect.
primary table: http://pastebin.com/gE2TjZd3
secondary table(s): http://pastebin.com/aDVakUkp
There are actually 10 secondary tables, but they are more or less of the same structure.
The node tables have identical structure to the main tables.
First stage, which I don't particularly question, but may be wrongfully so, the application does:
- create data suitable for the rows in the primary/secondary tables
- starts transaction
- merges data into its own node tables (using merge_xxx PL/pgSQL functions) (<100 rows in primary table)
- prepares transactions
- deals with other data sources
- commits/rolls back prepared transaction depending on success of the previous step.
An example of a merge_xxx function: http://pastebin.com/6YYm8BVM
Second stage is really:
- start transaction
- call PL/pgSQL merge_all()
- commit
2 reasons for the 2 stages:
- if stage#2 fails, the data will be merged during the next iteration
- the lock time on the shared tables is minimized
It's possible that an external process may take over writing data for certain key subset (combination of (tagid,blockid)), to make sure there is no race condition with such process, such key pairs are "locked", that's what the whole r_locks table and get_r_lock() is about. This makes it a bit more cumbersome for the bulk merge. Here is the r_lock related pieces: http://pastebin.com/Y9NCemLV
This is the "old" code for merge_all function(): http://pastebin.com/5dn7WsvV
And this is the "new" code that I haven't finished testing, or put into service, but that's the gist of the change I'm considering: http://pastebin.com/XmgB5U0f
As always, any suggestions or pointers are greatly appreciated :)
