Re: Monitoring PostgreSQL Process

On 11/22/06, Tomeh, Husam <htomeh(at)firstam(dot)com> wrote:
>
> This indicates that some stats parameters are not enabled in your "
> postgresql.conf" file. In particular, make sure that
> "stats_command_string" parameter is turned ON so that pg_stat_activity can
> report back the actual SQL statement.
>

Right, as I mentioned, I had stats_command_string turned off but turned it
on. What I expected to find is that the <command string not enabled> would
remain until another query was run by that process. But since these
processes are eating up so many CPU cycles, I thought they would show
something other than <command string not enabled> pretty quickly. Since
they did not show something new, why are they using so much of the CPU?
Could the be caught in some kind of massive , seemingly endless query?

In fact 30961 and 2830 are still not showing anything new and 30960 and
30306 show Idle most of the time.

I know the application is causing the problem, I am just trying to figure
out what part of the application is taking postgres so much.

Thanks,
Aaron

------------------------------
> *From:* aaron(dot)bono(at)gmail(dot)com [mailto:aaron(dot)bono(at)gmail(dot)com] *On Behalf Of *Aaron
> Bono
> *Sent:* Wednesday, November 22, 2006 1:14 PM
> *To:* Tomeh, Husam
> *Cc:* pgsql-admin(at)postgresql(dot)org
> *Subject:* Re: [ADMIN] Monitoring PostgreSQL Process
>
> On 11/22/06, Tomeh, Husam <htomeh(at)firstam(dot)com> wrote:
> >
> > You may query the system view, pg_stat_activity to check out the
> > current SQL statements running. To track down executed SQL statements into a
> > physical log file, you may want to enable statement logging. For more
> > details on that, check out:
> > http://www.postgresql.org/docs/8.1/static/runtime-config-logging.html
> >
> > Once you capture your SQL statement, you can run "explain" on it to
> > check out its execution plan.
> >
>
> So I went out to the server and selected on pg_stat_activity and found
> that stats_command_string had been turned off. I turned it on and gave
> postgres a reload command. Then I selected on pg_stat_activity again and
> got this:
>
> my_db=# select * from pg_stat_activity where procpid in (30960, 30961,
> 877, 30306, 2830);
> datid | datname | procpid | usesysid | usename |
> current_query | query_start |
> backend_start | client_addr | client_port
>
> -------+----------------------+---------+----------+----------+------------------------------+-------------------------------+-------------------------------+-------------+-------------
> 29246 | my_db | 30960 | 24114 | usr1 | <command string not enabled>
> | | 2006-11-20 07:20: 24.068052-06 |
> 127.0.0.1 | xxxxx
> 29246 | my_db | 30961 | 24114 | usr1 | <command string not enabled>
> | | 2006-11-20 07:20:24.072152-06 |
> 127.0.0.1 | xxxxx
> 29246 | my_db | 877 | 24114 | usr1 | <IDLE>
> | 2006-11-22 15:04:42.230017-06 | 2006-11-20 08:20:35.765786-06 |
> 127.0.0.1 | xxxxx
> 29246 | my_db | 2830 | 24114 | usr1 | <command string not enabled>
> | | 2006-11-22 10:45:09.528452-06 |
> 127.0.0.1 | xxxxx
> 29246 | my_db | 30306 | 24113 | usr2 | <BIND>
> | 2006-11-22 15:04:42.408911-06 | 2006-11-22 07:43:08.825445-06 |
> 127.0.0.1 | xxxxx
> (5 rows)
>
> I cleared out the client ports.
>
> The funny thing is that process ID's 30960, 30961 and 2830 are using a lot
> of the CPU but according to pg_stat_activity the <command string not
> enabled> has not been updated. Doesn't this suggest that those processes
> are NOT running anything on the database, or at least anything new?
>
> Here is what I get from "ps axuf":
>
> postgres 25635 0.0 0.2 34864 5592 ? S Oct01 0:02
> /usr/bin/postmaster -p 5432 -D /var/lib/pgsql/data
> postgres 25637 0.0 0.0 11220 768 ? S Oct01 1:07 \_
> postgres: logger process
> postgres 25639 0.0 0.8 35100 17624 ? S Oct01 5:03 \_
> postgres: writer process
> postgres 25640 0.0 0.0 12220 1568 ? S Oct01 0:50 \_
> postgres: stats buffer process
> postgres 25641 0.0 0.0 11908 1224 ? S Oct01 1:03 | \_
> postgres: stats collector process
> postgres 30950 2.2 1.1 38728 23000 ? S Nov20 74:23 \_
> postgres: user3 my_db 127.0.0.1(xxx) idle
> postgres 30951 2.1 1.1 38752 23328 ? S Nov20 70:22 \_
> postgres: user3 my_db 127.0.0.1(xxx) idle
> postgres 30960 21.3 1.1 39840 24740 ? S Nov20 715:38 \_
> postgres: user1 my_db 127.0.0.1(xxx) idle
> postgres 30961 17.2 1.1 39496 24356 ? S Nov20 578:08 \_
> postgres: user1 my_db 127.0.0.1(xxx) idle
> postgres 30962 9.5 1.1 39864 24588 ? R Nov20 320:22 \_
> postgres: user1 my_db 127.0.0.1(xxx) PARSE
> postgres 31068 0.0 0.2 36584 4940 ? S Nov20 0:00 \_
> postgres: user1 my_test_db 127.0.0.1(xxx) idle
> postgres 31069 0.6 0.9 36724 20268 ? S Nov20 22:09 \_
> postgres: user1 my_test_db 127.0.0.1(xxx) idle
> postgres 31070 0.0 0.2 35792 4548 ? S Nov20 0:00 \_
> postgres: user1 my_test_db 127.0.0.1(xxx) idle
> postgres 31199 1.8 1.1 39320 23708 ? S Nov20 62:14 \_
> postgres: user2 my_db 127.0.0.1(xxx) idle
> postgres 31359 0.6 1.0 37092 21308 ? S Nov20 21:11 \_
> postgres: user2 my_test_db 127.0.0.1(xxx) idle
> postgres 31361 0.0 0.2 36720 5000 ? S Nov20 0:00 \_
> postgres: user2 my_test_db 127.0.0.1(xxx) idle
> postgres 31362 1.5 1.0 38132 21384 ? S Nov20 53:26 \_
> postgres: user2 my_test_db 127.0.0.1(xxx) idle
> postgres 32030 5.1 1.1 39816 24740 ? S Nov20 171:42 \_
> postgres: user2 my_db 127.0.0.1(xxx) idle
> postgres 877 14.6 1.1 39812 24676 ? S Nov20 481:37 \_
> postgres: user1 my_db 127.0.0.1(xxx) idle
> postgres 3008 4.9 1.1 39404 24460 ? S Nov20 158:17 \_
> postgres: user2 my_db 127.0.0.1(xxx) idle in transaction
> postgres 3009 1.7 1.1 39012 23804 ? S Nov20 56:44 \_
> postgres: user2 my_db 127.0.0.1(xxx) idle in transaction
> postgres 17186 1.2 1.1 38804 23204 ? S Nov20 31:19 \_
> postgres: user3 my_db 127.0.0.1 (xxx) idle
> postgres 19966 2.7 1.1 38596 23056 ? S Nov21 25:08 \_
> postgres: user3 my_db 127.0.0.1(xxx) idle
> postgres 30306 19.4 1.1 39448 23908 ? S 07:43 86:45 \_
> postgres: user2 my_db 127.0.0.1 (xxx) idle
> postgres 2830 15.4 1.0 38992 22068 ? S 10:45 40:40 \_
> postgres: user1 my_db 127.0.0.1(xxx) idle
>
> Anyone have any clue why these processes are eating up so much CPU time?
>
> Thanks,
> Aaron
>
> --
> ==================================================================
> Aaron Bono
> Aranya Software Technologies, Inc.
> http://www.aranya.com
> http://codeelixir.com
> ==================================================================
>
> **********************************************************************
> This message contains confidential information intended only for the use
> of the addressee(s) named above and may contain information that is legally
> privileged. If you are not the addressee, or the person responsible for
> delivering it to the addressee, you are hereby notified that reading,
> disseminating, distributing or copying this message is strictly prohibited.
> If you have received this message by mistake, please immediately notify us
> by replying to the message and delete the original message immediately
> thereafter.
>
> Thank you.
>
>
> FADLD Tag
> **********************************************************************
>

--
==================================================================
Aaron Bono
Aranya Software Technologies, Inc.
http://www.aranya.com
http://codeelixir.com
==================================================================