Re: Debug advice when postgres connection maxing out

On 2010-11-23 20.56, anypossibility wrote:
> Thank you for your advice.I reviewed the query and it is the most simple one column value update with primary key query.
> I would like to share this with you and would like to receive advice as to whether I am on the right track.
>
>
> Facts: the connection maxed out and i could not even terminate postgres with SIGINT. I was afraid to do SIGQUIT so restarted the server itself (not sure if this was better decision).... the server has been running just fine until a few days ago. No hardware update. Other servers that has exactly same spec (code, version, hardware) is having no issue... from this facts, I am leaning towards hardware issue.. though I have no idea where to start... This started to happen on one server a few days ago. So far this happens once a day. No pattern what's so ever in terms of client request, time of the day...

Anything interesting in postgresql.log? Maybe you have to increase
logging to find anything.
Perhaps enable log_min_duration_statement to see if there are any long
running statements that could give you a hint.

For details see
http://www.postgresql.org/docs/8.3/static/runtime-config-logging.html

>
>
> My observation: From the look of output from the ps -ef | grep postgres (pasted below) what was happening is that postgres is not returning result or waiting for something. and that one process is holding up the rest of the process - basically nothing is processed yet postgres continue to receive request until it reaches to max connection. Where can I start to diagnose this issue? Any advice would be appreciated.
>
>
> -----------------------------------------------------------------------------------
> please note: Actual IP was replaced with Client_IP
>
>
> SQL:~ root# ps -ef | grep postgres
> 502 891 1 0 0:05.61 ?? 0:06.54 /Library/PostgresPlus/8.3/bin/postgres -D /data
> 502 892 891 0 0:01.41 ?? 0:01.98 postgres: logger process
> 502 894 891 0 0:17.91 ?? 0:27.16 postgres: writer process
> 502 895 891 0 0:05.43 ?? 0:06.88 postgres: wal writer process
> 502 896 891 0 0:01.59 ?? 0:03.26 postgres: autovacuum launcher process
> 502 897 891 0 1:09.83 ?? 1:35.88 postgres: stats collector process
> 502 1007 891 0 2:10.40 ?? 33:38.91 postgres: DBA DB_Name Client_IP(60096) UPDATE

I would be curious about this process since it stands out by the amount
of time it been running. I would watch for a similar long running
process and try to see what pg_stat_activity and pg_lock says about it.

What hardware are you running on and what size database? Could it be you
have a very large table on slow hardware and some client is trying to
update all of that table?

Any other services running on the same host? Could it be a shared
storage used by some other host?

/r

> 502 1008 891 0 0:00.82 ?? 0:20.91 postgres: DBA DB_Name Client_IP(60097) UPDATE
> 502 45397 891 0 0:00.01 ?? 0:00.11 postgres: DBA DB_Name Client_IP(64007) SELECT
> 502 45398 891 0 0:00.06 ?? 0:00.59 postgres: DBA DB_Name Client_IP(64008) idle
> 502 45399 891 0 0:00.00 ?? 0:00.01 postgres: DBA DB_Name Client_IP(64009) SELECT
> 502 45400 891 0 0:00.00 ?? 0:00.01 postgres: DBA DB_Name Client_IP(64012) SELECT
> 502 45401 891 0 0:00.00 ?? 0:00.01 postgres: DBA DB_Name Client_IP(64013) SELECT
> 502 45402 891 0 0:00.00 ?? 0:00.01 postgres: DBA DB_Name Client_IP(64014) SELECT
> 502 45403 891 0 0:00.00 ?? 0:00.01 postgres: DBA DB_Name Client_IP(64015) SELECT
> 502 45404 891 0 0:00.01 ?? 0:00.03 postgres: DBA DB_Name Client_IP(64016) SELECT
> 502 45405 891 0 0:00.00 ?? 0:00.01 postgres: DBA DB_Name Client_IP(64017) SELECT
> 502 45406 891 0 0:00.00 ?? 0:00.01 postgres: DBA DB_Name Client_IP(64018) UPDATE
> 502 45407 891 0 0:00.00 ?? 0:00.01 postgres: DBA DB_Name Client_IP(64019) SELECT
> 502 45408 891 0 0:00.00 ?? 0:00.01 postgres: DBA DB_Name Client_IP(64020) SELECT
> 502 45409 891 0 0:00.00 ?? 0:00.01 postgres: DBA DB_Name Client_IP(64021) SELECT
> 502 45410 891 0 0:00.00 ?? 0:00.01 postgres: DBA DB_Name Client_IP(64022) SELECT
> 502 45411 891 0 0:00.00 ?? 0:00.01 postgres: DBA DB_Name Client_IP(64023) SELECT
> 502 45412 891 0 0:00.00 ?? 0:00.01 postgres: DBA DB_Name Client_IP(64024) SELECT
> 502 45413 891 0 0:00.00 ?? 0:00.01 postgres: DBA DB_Name Client_IP(64025) SELECT
> 502 45414 891 0 0:00.00 ?? 0:00.01 postgres: DBA DB_Name Client_IP(64026) SELECT
> 502 45415 891 0 0:00.00 ?? 0:00.01 postgres: DBA DB_Name Client_IP(64027) UPDATE
> 502 45416 891 0 0:00.00 ?? 0:00.01 postgres: DBA DB_Name Client_IP(64028) SELECT
> 502 45417 891 0 0:00.00 ?? 0:00.01 postgres: DBA DB_Name Client_IP(64029) SELECT
> 502 45418 891 0 0:00.00 ?? 0:00.01 postgres: DBA DB_Name Client_IP(64030) SELECT
> 502 45419 891 0 0:00.00 ?? 0:00.01 postgres: DBA DB_Name Client_IP(64031) SELECT
> 502 45430 891 0 0:00.00 ?? 0:00.01 postgres: DBA DB_Name Client_IP(64032) SELECT
> 502 45434 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64033) startup
> 502 45435 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64034) startup
> 502 45436 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64035) startup
> 502 45437 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64036) startup
> 502 45438 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64037) startup
> 502 45439 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64038) startup
> 502 45440 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64039) startup
> 502 45441 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64040) startup
> 502 45442 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64043) startup
> 502 45443 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64044) startup
> 502 45444 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64045) startup
> 502 45445 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64046) startup
> 502 45446 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64047) startup
> 502 45447 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64048) startup
> 502 45448 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64049) startup
> 502 45449 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64050) startup
> 502 45450 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64051) startup
> 502 45451 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64052) startup
> 502 45452 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64053) startup
> 502 45453 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64054) startup
> 502 45456 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64055) startup
> 502 45470 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64056) startup
> 502 45471 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64057) startup
> 502 45472 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64058) startup
> 502 45473 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64059) startup
> 502 45474 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64060) startup
> 502 45475 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64061) startup
> 502 45476 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64062) startup
> 502 45477 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64063) startup
> 502 45478 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64064) startup
> 502 45479 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64065) startup
> 502 45480 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64068) startup
> 502 45481 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64069) startup
> 502 45482 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64070) startup
> 502 45483 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64071) startup
> 502 45484 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64072) startup
> 502 45485 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64074) startup
> 502 45486 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64075) startup
> 502 45487 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64076) startup
> 502 45488 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64077) startup
> 502 45489 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64078) startup
> 502 45490 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64079) startup
> 502 45491 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64080) startup
> 502 45505 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64081) startup
> 502 45506 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64082) startup
> 502 45507 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64083) startup
> 502 45508 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64084) startup
> 502 45509 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64085) startup
> 502 45510 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64086) startup
> 502 45511 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64087) startup
> 502 45512 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64088) startup
> 502 45513 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64089) startup
> 502 45514 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64090) startup
> 502 45515 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64092) startup
> 502 45516 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64094) startup
> 502 45517 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64095) startup
> 502 45518 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64096) startup
> 502 45519 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64097) startup
> 502 45520 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64098) startup
> 502 45521 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64099) startup
> 502 45522 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64100) startup
> 502 45523 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64101) startup
> 502 45537 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64104) startup
> 502 45539 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(64105) startup
> 502 45572 891 0 0:00.00 ?? 0:00.00 postgres: postgres DB_Name 127.0.0.1(53520) startup
> 502 45581 891 0 0:00.00 ?? 0:00.00 postgres: DBA DB_Name Client_IP(63737) startup
> 0 45764 45760 0 0:00.00 ttys000 0:00.00 grep postgres
> 0 45588 45585 0 0:00.01 ttys001 0:00.01 su - postgres
>
>
>
>
>
>
>
>
>
>
>
>
> ---- On Tue, 23 Nov 2010 04:00:07 -0800 Robert Gravsjö<robert(at)blogg(dot)se> wrote ----
>
>
>
> On 2010-11-22 20.41, anypossibility wrote:
> > Server: OS X 10.5
> > PostgreSQL version: 8.3
> >
> >
> > We experience this connection maxing out once in the full moon.
> > The request from client reaches to the server but client never receive response back.
> > The queries are very simple update on one record or select one record using primary key (checked current_query from pg_stat_activity).
> > Once this started, I normally disconnect all the client (quit client programs) however, the processes don't die on postgres server.
> > So I tried to quit PostgreSQL server using pg_ctl, no response. The only way to terminate is to restart the server (I will try kill -s INT next time.. i didn't know better).
> > Is there anything you can tell me from this symptoms or anything I can do to generate useful log to analyze?
>
> If track_activities is on in your postgresql.conf you can check
> pg_stats_activity to see what query creates the problem.
>
> Maybe http://www.postgresql.org/docs/8.3/static/monitoring-stats.html
> can give you some more ideas.
>

--
Regards,
Robert "roppert" Gravsjö