Обсуждение: Query is stuck

On Tue, Apr 13, 2010 at 06:28:18PM +0530, Satish Burnwal (sburnwal) wrote:
>
> In such a case what can I do ?

don't crosspost?

In response to Szymon Guz <mabewlun@gmail.com>:

> 2010/4/13 Satish Burnwal (sburnwal) <sburnwal@cisco.com>
>
> >  I have a query which is not giving me the result even after 30 minutes. I
> > want to know how to detect what is going and what’s wrong ?
> >
> >
> >
> > EXPLAIN query - gives me the following:
> >
> > controlsmartdb=# explain select report_id, dm_ip, dm_mac, dm_user, dm_os,
> > report_time, sys_name,  sys_user, sys_user_domain, ss_key, login_time,
> > role_id, new_vlan_id from repcopy as a where report_time = (select
> > max(report_time) from repcopy as b where a.dm_ip = b.dm_ip and
> > a.dm_user=b.dm_user and b.ss_key != '') and report_status = 0 and dm_user =
> > 'u1';
> >
> >                                                          QUERY PLAN
> >
> >
> >
----------------------------------------------------------------------------------------------------------------------------
> >
> >  Seq Scan on repcopy a  (cost=0.00..1630178118.35 rows=35 width=133)
> >
> >    Filter: ((report_status = 0) AND ((dm_user)::text = 'u1'::text) AND
> > (report_time = (subplan)))
> >
> >    SubPlan
> >
> >      ->  Aggregate  (cost=8151.65..8151.66 rows=1 width=8)
> >
> >            ->  Seq Scan on repcopy b  (cost=0.00..8151.65 rows=1 width=8)
> >
> >                  Filter: ((($0)::text = (dm_ip)::text) AND (($1)::text =
> > (dm_user)::text) AND ((ss_key)::text <> ''::text))
> >
> > (6 rows)
> >
> >
> >
> > But EXPLAIN ANALYSE query hangs (is not giving me any output even after 30
> > minutes).
> >
> >
> >
> > Pg_stat_activity shows this - SELECT procpid, usename, current_query,
> > query_start from pg_stat_activity:
> >
> > 2942 | postgres | select report_id, dm_ip, dm_mac, dm_user, dm_os,
> > report_time, sys_name,  sys_user, sys_user_domain, ss_key, login_time,
> > role_id, new_vlan_id from repcopy as a where report_time = (select
> > max(report_time) from repcopy as b where a.dm_ip = b.dm_ip and
> > a.dm_user=b.dm_user and b.ss_key != '') and report_status = 0 and dm_user =
> > 'u1'; | 2010-04-13 18:20:02.828623+05:30
> >
> >
> >
> >
> >
> > In such a case what can I do ?
> >
> >
> > First things that came to my mind:
>
> 1. Check if the query waits on some lock: add the column `waiting` to the
> above query from pg_stat_activity.
> 2. Run vacuum analyze on the table repcopy

In addition to that, indexes on report_time, report_status, and dm_user
might help.

And your query is not "hung", it's just taking a LOOOOONG time.  Based
on the explain, it could take several hours to complete.  How many
rows are in repcopy?  What is your vacuum schedule?  Do a vacuum verbose,
if the number of dead rows is very high on that table, you may benefit
from doing a VACUUM FULL + REINDEX or CLUSTER on the table.

--
Bill Moran
http://www.potentialtech.com
http://people.collaborativefusion.com/~wmoran/

On Tuesday 13 April 2010 6:03:43 am Satish Burnwal (sburnwal) wrote:
> controlsmartdb=# select * from pg_stat_activity where waiting='t';
>
> ERROR:  column "waiting" does not exist
>
>

From here:
http://www.postgresql.org/docs/8.4/interactive/monitoring-stats.html#MONITORING-STATS-VIEWS

My guess is you are being caught by this;

pg_stat_activity

"Furthermore, these columns are only visible if the user examining the view is a
superuser or the same as the user owning the process being reported on. '

--
Adrian Klaver
adrian.klaver@gmail.com

The information transmitted is intended only for the person or entity to which it is addressed and may contain confidential and/or privileged material. 
Any review, re-transmission, dissemination or other use of or taking of any action in reliance upon,this information by persons or entities other than the intended recipient is prohibited. 
If you received this in error, please contact the sender and delete the material from your computer. 
Microland takes all reasonable steps to ensure that its electronic communications are free from viruses. 
However, given Internet accessibility, the Company cannot accept liability for any virus introduced by this e-mail or any attachment and you are advised to use up-to-date virus checking software. 

I am using 8.1, so waiting coln is not there in pg_stat_activity.
I frequently see these in the server logs:

 LOG:  autovacuum: processing database "controlsmartdb"

Though I can give you the result of vacuum run (but it is not helping):
controlsmartdb=# vacuum full verbose  analyze repcopy;
INFO:  vacuuming "public.repcopy"
INFO:  "repcopy": found 0 removable, 200000 nonremovable row versions in 4652 pages
DETAIL:  0 dead row versions cannot be removed yet.
Nonremovable row versions range from 182 to 182 bytes long.
There were 0 unused item pointers.
Total free space (including removable row versions) is 416144 bytes.
0 pages are or will become empty, including 0 at the end of the table.
1 pages containing 6856 free bytes are potential move destinations.
CPU 0.00s/0.02u sec elapsed 0.02 sec.
INFO:  index "repcopy_pk" now contains 200000 row versions in 441 pages
DETAIL:  0 index pages have been deleted, 0 are currently reusable.
CPU 0.05s/0.00u sec elapsed 0.06 sec.
INFO:  "repcopy": moved 0 row versions, truncated 4652 to 4652 pages
DETAIL:  CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  vacuuming "pg_toast.pg_toast_18398"
INFO:  "pg_toast_18398": found 0 removable, 0 nonremovable row versions in 0 pages
DETAIL:  0 dead row versions cannot be removed yet.
Nonremovable row versions range from 0 to 0 bytes long.
There were 0 unused item pointers.
Total free space (including removable row versions) is 0 bytes.
0 pages are or will become empty, including 0 at the end of the table.
0 pages containing 0 free bytes are potential move destinations.
CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  index "pg_toast_18398_index" now contains 0 row versions in 1 pages
DETAIL:  0 index pages have been deleted, 0 are currently reusable.
CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  analyzing "public.repcopy"
INFO:  "repcopy": scanned 3000 of 4652 pages, containing 128964 live rows and 0 dead rows; 3000 rows in sample, 199980
estimatedtotal rows
 
VACUUM
controlsmartdb=# select distinct report_status from repcopy ;

There is no update happening to the table.

-------------------------

> 1. Check if the query waits on some lock: add the column `waiting` to the
> above query from pg_stat_activity.
> 2. Run vacuum analyze on the table repcopy

In addition to that, indexes on report_time, report_status, and dm_user
might help.

And your query is not "hung", it's just taking a LOOOOONG time.  Based
on the explain, it could take several hours to complete.  How many
rows are in repcopy?  What is your vacuum schedule?  Do a vacuum verbose,
if the number of dead rows is very high on that table, you may benefit
from doing a VACUUM FULL + REINDEX or CLUSTER on the table.

> INFO:  "repcopy": scanned 3000 of 4652 pages, containing 128964 live rows
> and 0 dead rows; 3000 rows in sample, 199980 estimated total rows
> VACUUM
> controlsmartdb=# select distinct report_status from repcopy ;

According to the vacuum output, there are about 200000 rows in the
"repcopy" table, occupying roughly 40MB. And according to the explain plan
you've posted earlier, there's a seq scan for each row - that gives 200000
sequential scans on the table ... which is about 8TB of data. Sure, most of
the data will be read from disk cache / shared buffers etc. but still it's
a lot of data to process - that's why it takes so long.

I'd recommend creating a index on (dm_user, dm_ip) columns, but it depends
on how many different values are in these columns (the more the better).

What information do we need to give better recommendations:

1) info about structure of the "repcopy" table (column data types, indexes)
2) info about data (how many different values are there)
3) what does the system do when running the query (use 'top' or 'dstat' to
get iowait / CPU / disk / memory etc.)

regards
Tomas

controlsmartdb=# \d repcopy;
                    Table "public.repcopy"
     Column      |              Type              | Modifiers
-----------------+--------------------------------+-----------
 report_id       | integer                        | not null
 dm_ip           | character varying(64)          |
 dm_mac          | character varying(64)          |
 dm_user         | character varying(255)         |
 dm_os           | character varying(64)          |
 report_time     | timestamp(0) without time zone |
 sys_name        | character varying(255)         |
 sys_user        | character varying(255)         |
 sys_user_domain | character varying(255)         |
 ss_key          | character varying(128)         |
 login_time      | character varying(64)          |
 role_id         | smallint                       |
 new_vlan_id     | character varying(64)          |
 report_status   | smallint                       |
Indexes:
    "repcopy_pk" PRIMARY KEY, btree (report_id)

controlsmartdb=# select count(*) from repcopy where dm_user = 'u3';
 count
-------
 25842
(1 row)

controlsmartdb=# select count(*) from repcopy where dm_user = 'u9';
 count
-------
 10283
(1 row)

As you see, for dm_user = 'u9', the original query :
select report_id, dm_ip, dm_mac, dm_user, dm_os, report_time, sys_name,  sys_user, sys_user_domain, ss_key, login_time,
role_id,new_vlan_id from repcopy as a where report_time = (select max(report_time) from repcopy as b where a.dm_ip =
b.dm_ipand a.dm_user=b.dm_user and b.ss_key != '') and report_status = 0 and dm_user = 'u1';
 

gives the result in less than a second. But when dm_user = 'u3' is used, it is taking very loooong time. Just 2.5 times
thenumber of records is increasing the query time by more than 1000 times.
 

Also, can you tell me whether in this case, I shall create index jointly on (dm_ip, dm_user) or separately on them ?

Thanks
-Satish


-----Original Message-----
From: tv@fuzzy.cz [mailto:tv@fuzzy.cz] 
Sent: Tuesday, April 13, 2010 7:56 PM
To: Satish Burnwal (sburnwal)
Cc: Bill Moran; pgsql-general@postgresql.org
Subject: Re: [GENERAL] [ADMIN] Query is stuck


I'd recommend creating a index on (dm_user, dm_ip) columns, but it depends
on how many different values are in these columns (the more the better).

What information do we need to give better recommendations:

1) info about structure of the "repcopy" table (column data types, indexes)
2) info about data (how many different values are there)
3) what does the system do when running the query (use 'top' or 'dstat' to
get iowait / CPU / disk / memory etc.)

regards
Tomas

In response to "Satish Burnwal (sburnwal)" <sburnwal@cisco.com>:

> controlsmartdb=# \d repcopy;
>                     Table "public.repcopy"
>      Column      |              Type              | Modifiers
> -----------------+--------------------------------+-----------
>  report_id       | integer                        | not null
>  dm_ip           | character varying(64)          |
>  dm_mac          | character varying(64)          |
>  dm_user         | character varying(255)         |
>  dm_os           | character varying(64)          |
>  report_time     | timestamp(0) without time zone |
>  sys_name        | character varying(255)         |
>  sys_user        | character varying(255)         |
>  sys_user_domain | character varying(255)         |
>  ss_key          | character varying(128)         |
>  login_time      | character varying(64)          |
>  role_id         | smallint                       |
>  new_vlan_id     | character varying(64)          |
>  report_status   | smallint                       |
> Indexes:
>     "repcopy_pk" PRIMARY KEY, btree (report_id)

Unless you truncated this output, you _really_ need to add some indexes
to this table.  Read back through earlier messages in the thread for
suggestions.

--
Bill Moran
http://www.potentialtech.com
http://people.collaborativefusion.com/~wmoran/

OK, I added now index:

Create index repcopy_index on repcopy (dm_user, dm_ip)

And even then query is taking long time. See below. As I mentioned
before, for dm_user=u9 I have about 10,000 records and for dm_user=u9 I
have about 25000 records. As you see in the output below, for u9, I get
results in 8.7 ms but for u3 it is very huge 689111 ms. What else do you
think I can change to make results faster ?

controlsmartdb=# explain analyze select report_id, dm_ip, dm_mac,
dm_user, dm_os, report_time, sys_name,  sys_user, sys_user_domain,
ss_key, login_time, role_id, new_vlan_id from repcopy as a where
report_time = (select max(report_time) from repcopy as b where
a.dm_user=b.dm_user and a.dm_ip = b.dm_ip and b.ss_key != '') and
report_status = 0 and dm_user = 'u3';

QUERY PLAN
------------------------------------------------------------------------
------------------------------------------------------------------------
------
 Index Scan using repcopy_index on repcopy a  (cost=0.00..87824607.17
rows=28 width=142) (actual time=11773.105..689111.440 rows=1 loops=1)
   Index Cond: ((dm_user)::text = 'u3'::text)
   Filter: ((report_status = 0) AND (report_time = (subplan)))
   SubPlan
     ->  Aggregate  (cost=3531.30..3531.31 rows=1 width=8) (actual
time=58.447..58.448 rows=1 loops=11788)
           ->  Index Scan using repcopy_index on repcopy b
(cost=0.00..3526.30 rows=2000 width=8) (actual time=0.017..36.779
rows=25842 loops=11788)
                 Index Cond: ((($0)::text = (dm_user)::text) AND
(($1)::text = (dm_ip)::text))
                 Filter: ((ss_key)::text <> ''::text)
 Total runtime: 689111.511 ms
(9 rows)

controlsmartdb=# explain analyze select report_id, dm_ip, dm_mac,
dm_user, dm_os, report_time, sys_name,  sys_user, sys_user_domain,
ss_key, login_time, role_id, new_vlan_id from repcopy as a where
report_time = (select max(report_time) from repcopy as b where
a.dm_user=b.dm_user and a.dm_ip = b.dm_ip and b.ss_key != '') and
report_status = 0 and dm_user = 'u9';
                                                            QUERY PLAN
------------------------------------------------------------------------
-----------------------------------------------------------
 Index Scan using repcopy_index on repcopy a  (cost=0.00..42856286.47
rows=14 width=142) (actual time=8.613..8.613 rows=0 loops=1)
   Index Cond: ((dm_user)::text = 'u9'::text)
   Filter: ((report_status = 0) AND (report_time = (subplan)))
   SubPlan
     ->  Aggregate  (cost=3531.30..3531.31 rows=1 width=8) (never
executed)
           ->  Index Scan using repcopy_index on repcopy b
(cost=0.00..3526.30 rows=2000 width=8) (never executed)
                 Index Cond: ((($0)::text = (dm_user)::text) AND
(($1)::text = (dm_ip)::text))
                 Filter: ((ss_key)::text <> ''::text)
 Total runtime: 8.670 ms
(9 rows)

-----Original Message-----
From: Bill Moran [mailto:wmoran@potentialtech.com]
Sent: Wednesday, April 14, 2010 6:06 PM
To: Satish Burnwal (sburnwal)
Cc: pgsql-general@postgresql.org
Subject: Re: [GENERAL] Query is stuck


Unless you truncated this output, you _really_ need to add some indexes
to this table.  Read back through earlier messages in the thread for
suggestions.

--
Bill Moran
http://www.potentialtech.com
http://people.collaborativefusion.com/~wmoran/

In response to "Satish Burnwal (sburnwal)" <sburnwal@cisco.com>:
>

<snip>

Man, it's hard to read your emails.  I've reformatted, I suggest you
improve the formatting on future emails, as I was about to say "to
hell with this question" because it was just too difficult to read,
and I expect there are others on the list who did just that.

Anyway ...

select report_id, dm_ip, dm_mac, dm_user,
       dm_os, report_time, sys_name,
       sys_user, sys_user_domain, ss_key,
       login_time, role_id, new_vlan_id
  from repcopy as a
  where report_time = (
    select max(report_time) from repcopy as b
      where a.dm_user=b.dm_user and a.dm_ip = b.dm_ip and b.ss_key != ''
      )
    and report_status = 0 and dm_user = 'u3';

QUERY PLAN
------------------------------------------------------------------------
------------------------------------------------------------------------
------
 Index Scan using repcopy_index on repcopy a  (cost=0.00..87824607.17 rows=28 width=142) (actual
time=11773.105..689111.440rows=1 loops=1) 
   Index Cond: ((dm_user)::text = 'u3'::text)
   Filter: ((report_status = 0) AND (report_time = (subplan)))
   SubPlan
     ->  Aggregate  (cost=3531.30..3531.31 rows=1 width=8) (actual time=58.447..58.448 rows=1 loops=11788)
           ->  Index Scan using repcopy_index on repcopy b (cost=0.00..3526.30 rows=2000 width=8) (actual
time=0.017..36.779rows=25842 loops=11788) 
                 Index Cond: ((($0)::text = (dm_user)::text) AND(($1)::text = (dm_ip)::text))
                 Filter: ((ss_key)::text <> ''::text)
 Total runtime: 689111.511 ms
(9 rows)

OK, now that I can read it, I noticed something that I missed before.
Your subquery is being run separately for every row that matches
report_status = 0 and dm_user = 'u3'.  This is equating to 11788
executions, which seems to be a significant part of the problem.

Can you rewrite the query to remove the subquery?  Or at least figure
out a way to filter the results more before calling the subquery.
I tried to suggest a rewrite, but I've found that I simply can't
understand what it is you're trying to accomplish with that query.

--
Bill Moran
http://www.potentialtech.com
http://people.collaborativefusion.com/~wmoran/

On 4/14/2010 9:20 AM, Satish Burnwal (sburnwal) wrote:

 Index Scan using repcopy_index on repcopy a  (cost=0.00..87824607.17
rows=28 width=142) (actual time=11773.105..689111.440 rows=1 loops=1)  Index Cond: ((dm_user)::text = 'u3'::text)  Filter: ((report_status = 0) AND (report_time = (subplan)))  SubPlan    ->  Aggregate  (cost=3531.30..3531.31 rows=1 width=8) (actual
time=58.447..58.448 rows=1 loops=11788)          ->  Index Scan using repcopy_index on repcopy b
(cost=0.00..3526.30 rows=2000 width=8) (actual time=0.017..36.779
rows=25842 loops=11788)                Index Cond: ((($0)::text = (dm_user)::text) AND
(($1)::text = (dm_ip)::text))                Filter: ((ss_key)::text <> ''::text)Total runtime: 689111.511 ms
(9 rows) 

The estimated cost and actual are way off.  Have you run Analyze on the table

you may want to change the statistics collected for this table
 
http://www.postgresql.org/docs/8.1/static/planner-stats.html

 ALTER [ COLUMN ] column SET STATISTICS integer

http://www.postgresql.org/docs/8.1/static/sql-altertable.html

All legitimate Magwerks Corporation quotations are sent in a .PDF file attachment with a unique ID number generated by our proprietary quotation system. Quotations received via any other form of communication will not be honored.

CONFIDENTIALITY NOTICE: This e-mail, including attachments, may contain legally privileged, confidential or other information proprietary to Magwerks Corporation and is intended solely for the use of the individual to whom it addresses. If the reader of this e-mail is not the intended recipient or authorized agent, the reader is hereby notified that any unauthorized viewing, dissemination, distribution or copying of this e-mail is strictly prohibited. If you have received this e-mail in error, please notify the sender by replying to this message and destroy all occurrences of this e-mail immediately.
Thank you.

On 4/14/2010 9:42 AM, Bill Moran wrote:
>
> Man, it's hard to read your emails.  I've reformatted, I suggest you
> improve the formatting on future emails, as I was about to say "to
> hell with this question" because it was just too difficult to read,
> and I expect there are others on the list who did just that.
>
I did for the most part.
> select report_id, dm_ip, dm_mac, dm_user,
>         dm_os, report_time, sys_name,
>         sys_user, sys_user_domain, ss_key,
>         login_time, role_id, new_vlan_id
>    from repcopy as a
>    where report_time = (
>      select max(report_time) from repcopy as b
>        where a.dm_user=b.dm_user and a.dm_ip = b.dm_ip and b.ss_key != ''
>        )
>      and report_status = 0 and dm_user = 'u3';
>
>
I suggest writting something like this.

select report_id, dm_ip, dm_mac, dm_user,
        dm_os, report_time, sys_name,
        sys_user, sys_user_domain, ss_key,
        login_time, role_id, new_vlan_id
   from repcopy as a
    (select max(report_time) as rtime,
              dm_user, dm_ip
        from repcopy
        group by dm_user, dm_ip
        where ss_key != '') as materialized
   where report_time = materialized.rtime
    and materialized.dm_user = a.dm_user
    and materialized.dm__ip = a_ip
    and report_status = 0
    and dm_user = 'u3';




All legitimate Magwerks Corporation quotations are sent in a .PDF file attachment with a unique ID number generated by
ourproprietary quotation system. Quotations received via any other form of communication will not be honored. 

CONFIDENTIALITY NOTICE: This e-mail, including attachments, may contain legally privileged, confidential or other
informationproprietary to Magwerks Corporation and is intended solely for the use of the individual to whom it
addresses.If the reader of this e-mail is not the intended recipient or authorized agent, the reader is hereby notified
thatany unauthorized viewing, dissemination, distribution or copying of this e-mail is strictly prohibited. If you have
receivedthis e-mail in error, please notify the sender by replying to this message and destroy all occurrences of this
e-mailimmediately. 
Thank you.

Great!! Your help is very valuable!!

-----Original Message-----
From: Justin Graf [mailto:justin@magwerks.com] 
Sent: Wednesday, April 14, 2010 7:35 PM
To: Bill Moran
Cc: Satish Burnwal (sburnwal); pgsql-general@postgresql.org
Subject: Re: [GENERAL] Query is stuck

I suggest writting something like this.

select report_id, dm_ip, dm_mac, dm_user,
        dm_os, report_time, sys_name,
        sys_user, sys_user_domain, ss_key,
        login_time, role_id, new_vlan_id
   from repcopy as a
    (select max(report_time) as rtime,     
              dm_user, dm_ip
        from repcopy
        group by dm_user, dm_ip
        where ss_key != '') as materialized
   where report_time = materialized.rtime
    and materialized.dm_user = a.dm_user
    and materialized.dm__ip = a_ip
    and report_status = 0
    and dm_user = 'u3';




All legitimate Magwerks Corporation quotations are sent in a .PDF file attachment with a unique ID number generated by
ourproprietary quotation system. Quotations received via any other form of communication will not be honored.
 

CONFIDENTIALITY NOTICE: This e-mail, including attachments, may contain legally privileged, confidential or other
informationproprietary to Magwerks Corporation and is intended solely for the use of the individual to whom it
addresses.If the reader of this e-mail is not the intended recipient or authorized agent, the reader is hereby notified
thatany unauthorized viewing, dissemination, distribution or copying of this e-mail is strictly prohibited. If you have
receivedthis e-mail in error, please notify the sender by replying to this message and destroy all occurrences of this
e-mailimmediately.
 
Thank you.