1

Context...

Our Production system is reporting(occasionally) query timing that is taking longer than usual.

I have already measured EXPLAIN ANALYZE against the SQL statement but nothing seems to explain the longer than usual query timing.

cprdb=# explain ANALYZE select ror from crns where crn='8000440008' limit 1;
                                                     QUERY PLAN
--------------------------------------------------------------------------------------------------------------------
 Limit  (cost=0.29..8.30 rows=1 width=6) (actual time=0.092..0.092 rows=1 loops=1)
   ->  Index Scan using crn_idx on crns  (cost=0.29..8.30 rows=1 width=6) (actual time=0.091..0.091 rows=1 loops=1)
         Index Cond: (crn = '8000440008'::bpchar)
 Planning time: 0.200 ms
 Execution time: 0.132 ms

My next bet is to log the PostgreSQL (DML) query time using log_min_duration_statement=0 and get a conclusive evidence as to where the problem is.

For that, I want to cross check ..

By Enabling query logging I would not deteriorate the overall PostgreSQL performance right?

2

How is the production system reporting the query times now? If you are already getting that data, it is questionable that getting it a separate way will be helpful.

But to answer your question, there are two kinds of overhead you will get.

Setting log_min_duration_statement to any non-negative value will cause the system clock to be queried more often. This should be almost negligible on modern common hardware and kernels, but can be quite slow on older things.

The other overhead is actually writing the log entries. If the server is very busy, this is probably going to be quite noticeable with log_min_duration_statement=0. You can probably come up with some threshold greater than 0 will that still log the slow statements, but without logging every single statement.

  • How is the production system reporting the query times now? If you are already getting that data, it is questionable that getting it a separate way will be helpful. We measure a time on our client side end_time - start_time This is not full proof but we get signs from the above metrics. that which section of code is slow .. – Ratatouille Feb 14 '18 at 5:54
0

Depending on how busy your DB you may get lots of queries setting log_min_duration_statement=0. In a truly busy environment one of two things may potentially happen (again.. for a truly busy environment)

  • If using syslog, you may miss some logs because syslog can't keep up.

  • If using csv, make sure you don't have the log going to a slow mount like NFS because it WILL slow you down. Going to CSV postgres guarantees the write for the log.

For something that you don't know when, or if, will happen again I would suggest sylog.

If the system is not crazy busy then there is not much of a downside to testing log_min_duration_statement=0 while you try to figure out the reason the query is sometimes slow.

One potential reason why the query is slow sometimes is locks. For example if you were trying to delete / update some rows and some other process is already updating / deleting in some of the impacted rows then the second process will be stuck in a waiting state. That will not show in the log. You need to run a process from cron to check for waiting connections.

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.