Обсуждение: slow query : very simple delete, 100% cpu, nearly no disk activity
Hi list,
I've been running this simple delete since yesterday afternoon :
> db=# explain delete from message where datetime < '2009-03-03';
> Seq Scan on message (cost=0.00..34131.95 rows=133158 width=6)
> Filter: (datetime < '2009-03-03 00:00:00'::timestamp without time zone)
There is no index on that column, so a seqscan is fine. But it really
shouldn't take > 15 hours to delete :
> db=# select count(*) from message where datetime < '2009-03-03';
> 184368
> Time: 751.721 ms
>
> db=# select count(*) from message;
> 1079463
> Time: 593.899 ms
>
> db=# select pg_size_pretty(pg_relation_size('message'));
> 161 MB
> Time: 96.062 ms
>
> db=# \o /dev/null
> db=# select * from message where datetime < '2009-03-03';
> Time: 4975.123 ms
Most of the time, there is no other connection to that database. This is on an
oldish laptop. atop reports 100% cpu and about 24KB/s of writes for postgres.
Machine is mostly idle (although I did run a multi-hours compile during the
night). Nothing looks wrong in postgres logs.
PostgreSQL 8.3.7 on i686-pc-linux-gnu, compiled by GCC i686-pc-linux-gnu-gcc
(Gentoo 4.3.2-r3 p1.6, pie-10.1.5) 4.3.2
postgresql.conf :
> max_connections = 100
> shared_buffers = 24MB
> max_fsm_pages = 153600
> log_destination = 'stderr'
> logging_collector = on
> log_directory = '/var/log/postgres/'
> log_filename = '%Y-%m-%d_%H%M%S.log'
> log_rotation_size = 100MB
> log_min_duration_statement = 30000
> log_line_prefix = '%t %d %p '
> datestyle = 'iso, mdy'
> lc_messages = 'C'
> lc_monetary = 'C'
> lc_numeric = 'C'
> lc_time = 'C'
> default_text_search_config = 'pg_catalog.english'
Not sure what to look at to debug this further (I could work around the
problem with pg_dump + grep, but that's beside the point). Any idea ?
Thanks.
--
Vincent de Phily
Mobile Devices
+33 (0) 666 301 306
+33 (0) 142 119 325
Warning
This message (and any associated files) is intended only for the use of its
intended recipient and may contain information that is confidential, subject
to copyright or constitutes a trade secret. If you are not the intended
recipient you are hereby notified that any dissemination, copying or
distribution of this message, or files associated with this message, is
strictly prohibited. If you have received this message in error, please
notify us immediately by replying to the message and deleting it from your
computer. Any views or opinions presented are solely those of the author
vincent.dephily@mobile-devices.fr and do not necessarily represent those of
the
company. Although the company has taken reasonable precautions to ensure no
viruses are present in this email, the company cannot accept responsibility
for any loss or damage arising from the use of this email or attachments.
Vincent de Phily <vincent.dephily@mobile-devices.fr> writes:
> I've been running this simple delete since yesterday afternoon :
>> db=# explain delete from message where datetime < '2009-03-03';
>> Seq Scan on message (cost=0.00..34131.95 rows=133158 width=6)
>> Filter: (datetime < '2009-03-03 00:00:00'::timestamp without time zone)
> There is no index on that column, so a seqscan is fine. But it really
> shouldn't take > 15 hours to delete :
99% of the time, the reason a delete takes way longer than it seems like
it should is trigger firing time. In particular, foreign key triggers
where you don't have an index on the referencing column. Are there
any foreign keys linking to this table?
regards, tom lane
On Monday 07 September 2009 03:25:23 Tom Lane wrote:
> Vincent de Phily <vincent.dephily@mobile-devices.fr> writes:
> > I've been running this simple delete since yesterday afternoon :
> >> db=# explain delete from message where datetime < '2009-03-03';
> >> Seq Scan on message (cost=0.00..34131.95 rows=133158 width=6)
> >> Filter: (datetime < '2009-03-03 00:00:00'::timestamp without time zone)
> >
> > There is no index on that column, so a seqscan is fine. But it really
> > shouldn't take > 15 hours to delete :
>
> 99% of the time, the reason a delete takes way longer than it seems like
> it should is trigger firing time. In particular, foreign key triggers
> where you don't have an index on the referencing column. Are there
> any foreign keys linking to this table?
Yes, but they look fine to me (?). Only one FK references the table; it's an
internal reference :
Table "public.message"
Column | Type | Modifiers
-----------+-----------------------------+------------------------------------------------------
id | integer | not null default
nextval('message_id_seq'::regclass)
unitid | integer | not null
userid | integer |
refid | integer |
(...)
Indexes:
"message_pkey" PRIMARY KEY, btree (id)
"message_unitid_fromto_status_idx" btree (unitid, fromto, status)
"message_userid_idx" btree (userid)
Foreign-key constraints:
"message_refid_fkey" FOREIGN KEY (refid) REFERENCES message(id) ON UPDATE
CASCADE ON DELETE CASCADE
"message_unitid_fkey" FOREIGN KEY (unitid) REFERENCES units(id) ON UPDATE
CASCADE ON DELETE CASCADE
"message_userid_fkey" FOREIGN KEY (userid) REFERENCES users(id) ON UPDATE
CASCADE ON DELETE CASCADE
Table "public.units"
Column | Type | Modifiers
-------------+-----------------------------+----------------------------------------------------
id | integer | not null default
nextval('units_id_seq'::regclass)
(...)
Indexes:
"units_pkey" PRIMARY KEY, btree (id)
"units_modid_ukey" UNIQUE, btree (modid)
"units_profileid_idx" btree (profileid)
Foreign-key constraints:
"units_profileid_fkey" FOREIGN KEY (profileid) REFERENCES profiles(id) ON
UPDATE CASCADE ON DELETE RESTRICT
Table "public.users"
Column | Type | Modifiers
----------+-----------------------+----------------------------------------------------
id | integer | not null default
nextval('users_id_seq'::regclass)
(...)
Indexes:
"users_pkey" PRIMARY KEY, btree (id)
"users_login_ukey" UNIQUE, btree (login)
Table users has a handdull of rows, table units has around 40000. 43% of
message.refid is NULL.
The delete finished during the weekend (DELETE 184368). Nothing in the logs
except the duration time (103113291.307 ms). I took a db dump before the
delete finished, in order to be able to reproduce the issue (a 30min test
shows me it is still slow).
--
Vincent de Phily
Mobile Devices
+33 (0) 666 301 306
+33 (0) 142 119 325
Warning
This message (and any associated files) is intended only for the use of its
intended recipient and may contain information that is confidential, subject
to copyright or constitutes a trade secret. If you are not the intended
recipient you are hereby notified that any dissemination, copying or
distribution of this message, or files associated with this message, is
strictly prohibited. If you have received this message in error, please
notify us immediately by replying to the message and deleting it from your
computer. Any views or opinions presented are solely those of the author
vincent.dephily@mobile-devices.fr and do not necessarily represent those of
the
company. Although the company has taken reasonable precautions to ensure no
viruses are present in this email, the company cannot accept responsibility
for any loss or damage arising from the use of this email or attachments.
On Mon, Sep 7, 2009 at 5:05 AM, Vincent de Phily
<vincent.dephily@mobile-devices.fr> wrote:
> On Monday 07 September 2009 03:25:23 Tom Lane wrote:
>> Vincent de Phily <vincent.dephily@mobile-devices.fr> writes:
>> > I've been running this simple delete since yesterday afternoon :
>> >> db=# explain delete from message where datetime < '2009-03-03';
>> >> Seq Scan on message (cost=0.00..34131.95 rows=133158 width=6)
>> >> Filter: (datetime < '2009-03-03 00:00:00'::timestamp without time zone)
>> >
>> > There is no index on that column, so a seqscan is fine. But it really
>> > shouldn't take > 15 hours to delete :
>>
>> 99% of the time, the reason a delete takes way longer than it seems like
>> it should is trigger firing time. In particular, foreign key triggers
>> where you don't have an index on the referencing column. Are there
>> any foreign keys linking to this table?
>
> Yes, but they look fine to me (?). Only one FK references the table; it's an
> internal reference :
>
> Table "public.message"
> Column | Type | Modifiers
> -----------+-----------------------------+------------------------------------------------------
> id | integer | not null default
> nextval('message_id_seq'::regclass)
> unitid | integer | not null
> userid | integer |
> refid | integer |
> (...)
> Indexes:
> "message_pkey" PRIMARY KEY, btree (id)
> "message_unitid_fromto_status_idx" btree (unitid, fromto, status)
> "message_userid_idx" btree (userid)
> Foreign-key constraints:
> "message_refid_fkey" FOREIGN KEY (refid) REFERENCES message(id) ON UPDATE
> CASCADE ON DELETE CASCADE
> "message_unitid_fkey" FOREIGN KEY (unitid) REFERENCES units(id) ON UPDATE
> CASCADE ON DELETE CASCADE
> "message_userid_fkey" FOREIGN KEY (userid) REFERENCES users(id) ON UPDATE
> CASCADE ON DELETE CASCADE
>
> Table "public.units"
> Column | Type | Modifiers
> -------------+-----------------------------+----------------------------------------------------
> id | integer | not null default
> nextval('units_id_seq'::regclass)
> (...)
> Indexes:
> "units_pkey" PRIMARY KEY, btree (id)
> "units_modid_ukey" UNIQUE, btree (modid)
> "units_profileid_idx" btree (profileid)
> Foreign-key constraints:
> "units_profileid_fkey" FOREIGN KEY (profileid) REFERENCES profiles(id) ON
> UPDATE CASCADE ON DELETE RESTRICT
>
> Table "public.users"
> Column | Type | Modifiers
> ----------+-----------------------+----------------------------------------------------
> id | integer | not null default
> nextval('users_id_seq'::regclass)
> (...)
> Indexes:
> "users_pkey" PRIMARY KEY, btree (id)
> "users_login_ukey" UNIQUE, btree (login)
>
>
> Table users has a handdull of rows, table units has around 40000. 43% of
> message.refid is NULL.
>
> The delete finished during the weekend (DELETE 184368). Nothing in the logs
> except the duration time (103113291.307 ms). I took a db dump before the
> delete finished, in order to be able to reproduce the issue (a 30min test
> shows me it is still slow).
I would try EXPLAIN ANALYZE DELETE ... with a query that is modified
so as to delete only a handful of rows. That will report the amount
of time spent in triggers vs. the main query, which will help you
assess whether your conclusion that the foreign keys are OK is
correct.
...Robert
On Mon, Sep 7, 2009 at 5:05 AM, Vincent de Phily
<vincent.dephily@mobile-devices.fr> wrote:
> On Monday 07 September 2009 03:25:23 Tom Lane wrote:
>> Vincent de Phily <vincent.dephily@mobile-devices.fr> writes:
>> > I've been running this simple delete since yesterday afternoon :
>> >> db=# explain delete from message where datetime < '2009-03-03';
>> >> Seq Scan on message (cost=0.00..34131.95 rows=133158 width=6)
>> >> Filter: (datetime < '2009-03-03 00:00:00'::timestamp without time zone)
>> >
>> > There is no index on that column, so a seqscan is fine. But it really
>> > shouldn't take > 15 hours to delete :
>>
>> 99% of the time, the reason a delete takes way longer than it seems like
>> it should is trigger firing time. In particular, foreign key triggers
>> where you don't have an index on the referencing column. Are there
>> any foreign keys linking to this table?
>
> Yes, but they look fine to me (?). Only one FK references the table; it's an
> internal reference :
>
> Table "public.message"
> Column | Type | Modifiers
> -----------+-----------------------------+------------------------------------------------------
> id | integer | not null default
> nextval('message_id_seq'::regclass)
> unitid | integer | not null
> userid | integer |
> refid | integer |
> Indexes:
> "message_pkey" PRIMARY KEY, btree (id)
> "message_unitid_fromto_status_idx" btree (unitid, fromto, status)
> "message_userid_idx" btree (userid)
> Foreign-key constraints:
> "message_refid_fkey" FOREIGN KEY (refid) REFERENCES message(id) ON UPDATE
> CASCADE ON DELETE CASCADE
> "message_unitid_fkey" FOREIGN KEY (unitid) REFERENCES units(id) ON UPDATE
> CASCADE ON DELETE CASCADE
> "message_userid_fkey" FOREIGN KEY (userid) REFERENCES users(id) ON UPDATE
> CASCADE ON DELETE CASCADE
where is the index on refid?
merlin
On Mon, Sep 21, 2009 at 10:50 AM, Vincent de Phily
<vincent.dephily@mobile-devices.fr> wrote:
> On Friday 11 September 2009 23:55:09 Merlin Moncure wrote:
>> On Mon, Sep 7, 2009 at 5:05 AM, Vincent de Phily
>> <vincent.dephily@mobile-devices.fr> wrote:
>> > Table "public.message"
>> > Column | Type | Modifiers
>> > -----------+-----------------------------+-------------------------------
>> >----------------------- id | integer | not null
>> > default
>> > nextval('message_id_seq'::regclass)
>> > unitid | integer | not null
>> > userid | integer |
>> > refid | integer |
>> >
>> > Indexes:
>> > "message_pkey" PRIMARY KEY, btree (id)
>> > "message_unitid_fromto_status_idx" btree (unitid, fromto, status)
>> > "message_userid_idx" btree (userid)
>> > Foreign-key constraints:
>> > "message_refid_fkey" FOREIGN KEY (refid) REFERENCES message(id) ON
>> > UPDATE CASCADE ON DELETE CASCADE
>> > "message_unitid_fkey" FOREIGN KEY (unitid) REFERENCES units(id) ON
>> > UPDATE CASCADE ON DELETE CASCADE
>> > "message_userid_fkey" FOREIGN KEY (userid) REFERENCES users(id) ON
>> > UPDATE CASCADE ON DELETE CASCADE
>>
>> where is the index on refid?
>
> It's
> "message_pkey" PRIMARY KEY, btree (id)
> because
> (refid) REFERENCES message(id)
You are thinking about this backwards. Every time you delete a
message, the table has to be scanned for any messages that reference
the message being deleted because of the refid constraint (in order to
see if any deletions must be cascaded). PostgreSQL creates a backing
index for primary keys automatically but not foreign keys...so you
likely need to create an index on refid.
merlin
On Friday 11 September 2009 23:30:37 Robert Haas wrote: > On Mon, Sep 7, 2009 at 5:05 AM, Vincent de Phily > <vincent.dephily@mobile-devices.fr> wrote: > > On Monday 07 September 2009 03:25:23 Tom Lane wrote: > >> > >> 99% of the time, the reason a delete takes way longer than it seems like > >> it should is trigger firing time. In particular, foreign key triggers > >> where you don't have an index on the referencing column. Are there > >> any foreign keys linking to this table? > > > > Yes, but they look fine to me (?). Only one FK references the table; it's > > an internal reference : > > (...) > I would try EXPLAIN ANALYZE DELETE ... with a query that is modified > so as to delete only a handful of rows. That will report the amount > of time spent in triggers vs. the main query, which will help you > assess whether your conclusion that the foreign keys are OK is > correct. Good idea. I'll try that in a little while and report the result. -- Vincent de Phily Mobile Devices +33 (0) 666 301 306 +33 (0) 142 119 325 Warning This message (and any associated files) is intended only for the use of its intended recipient and may contain information that is confidential, subject to copyright or constitutes a trade secret. If you are not the intended recipient you are hereby notified that any dissemination, copying or distribution of this message, or files associated with this message, is strictly prohibited. If you have received this message in error, please notify us immediately by replying to the message and deleting it from your computer. Any views or opinions presented are solely those of the author vincent.dephily@mobile-devices.fr and do not necessarily represent those of the company. Although the company has taken reasonable precautions to ensure no viruses are present in this email, the company cannot accept responsibility for any loss or damage arising from the use of this email or attachments.
On Friday 11 September 2009 23:55:09 Merlin Moncure wrote:
> On Mon, Sep 7, 2009 at 5:05 AM, Vincent de Phily
> <vincent.dephily@mobile-devices.fr> wrote:
> > Table "public.message"
> > Column | Type | Modifiers
> > -----------+-----------------------------+-------------------------------
> >----------------------- id | integer | not null
> > default
> > nextval('message_id_seq'::regclass)
> > unitid | integer | not null
> > userid | integer |
> > refid | integer |
> >
> > Indexes:
> > "message_pkey" PRIMARY KEY, btree (id)
> > "message_unitid_fromto_status_idx" btree (unitid, fromto, status)
> > "message_userid_idx" btree (userid)
> > Foreign-key constraints:
> > "message_refid_fkey" FOREIGN KEY (refid) REFERENCES message(id) ON
> > UPDATE CASCADE ON DELETE CASCADE
> > "message_unitid_fkey" FOREIGN KEY (unitid) REFERENCES units(id) ON
> > UPDATE CASCADE ON DELETE CASCADE
> > "message_userid_fkey" FOREIGN KEY (userid) REFERENCES users(id) ON
> > UPDATE CASCADE ON DELETE CASCADE
>
> where is the index on refid?
It's
"message_pkey" PRIMARY KEY, btree (id)
because
(refid) REFERENCES message(id)
--
Vincent de Phily
Mobile Devices
+33 (0) 666 301 306
+33 (0) 142 119 325
Warning
This message (and any associated files) is intended only for the use of its
intended recipient and may contain information that is confidential, subject
to copyright or constitutes a trade secret. If you are not the intended
recipient you are hereby notified that any dissemination, copying or
distribution of this message, or files associated with this message, is
strictly prohibited. If you have received this message in error, please
notify us immediately by replying to the message and deleting it from your
computer. Any views or opinions presented are solely those of the author
vincent.dephily@mobile-devices.fr and do not necessarily represent those of
the
company. Although the company has taken reasonable precautions to ensure no
viruses are present in this email, the company cannot accept responsibility
for any loss or damage arising from the use of this email or attachments.
On Monday 21 September 2009 17:00:36 Merlin Moncure wrote:
> On Mon, Sep 21, 2009 at 10:50 AM, Vincent de Phily
>
> <vincent.dephily@mobile-devices.fr> wrote:
> > On Friday 11 September 2009 23:55:09 Merlin Moncure wrote:
> >> On Mon, Sep 7, 2009 at 5:05 AM, Vincent de Phily
> >>
> >> <vincent.dephily@mobile-devices.fr> wrote:
> >> > Table "public.message"
> >> > Column | Type |
> >> > Modifiers
> >> > -----------+-----------------------------+----------------------------
> >> >--- ----------------------- id | integer |
> >> > not null default
> >> > nextval('message_id_seq'::regclass)
> >> > unitid | integer | not null
> >> > userid | integer |
> >> > refid | integer |
> >> >
> >> > Indexes:
> >> > "message_pkey" PRIMARY KEY, btree (id)
> >> > "message_unitid_fromto_status_idx" btree (unitid, fromto, status)
> >> > "message_userid_idx" btree (userid)
> >> > Foreign-key constraints:
> >> > "message_refid_fkey" FOREIGN KEY (refid) REFERENCES message(id) ON
> >> > UPDATE CASCADE ON DELETE CASCADE
> >> > "message_unitid_fkey" FOREIGN KEY (unitid) REFERENCES units(id) ON
> >> > UPDATE CASCADE ON DELETE CASCADE
> >> > "message_userid_fkey" FOREIGN KEY (userid) REFERENCES users(id) ON
> >> > UPDATE CASCADE ON DELETE CASCADE
> >>
> >> where is the index on refid?
> >
> > It's
> > "message_pkey" PRIMARY KEY, btree (id)
> > because
> > (refid) REFERENCES message(id)
>
> You are thinking about this backwards. Every time you delete a
> message, the table has to be scanned for any messages that reference
> the message being deleted because of the refid constraint (in order to
> see if any deletions must be cascaded). PostgreSQL creates a backing
> index for primary keys automatically but not foreign keys...so you
> likely need to create an index on refid.
D'Oh ! Sounds obvious now that you mention it, and it's a very good
explanation of the delete's slowness.
I'll test this tonight or tomorrow.
--
Vincent de Phily
Mobile Devices
+33 (0) 666 301 306
+33 (0) 142 119 325
Warning
This message (and any associated files) is intended only for the use of its
intended recipient and may contain information that is confidential, subject
to copyright or constitutes a trade secret. If you are not the intended
recipient you are hereby notified that any dissemination, copying or
distribution of this message, or files associated with this message, is
strictly prohibited. If you have received this message in error, please
notify us immediately by replying to the message and deleting it from your
computer. Any views or opinions presented are solely those of the author
vincent.dephily@mobile-devices.fr and do not necessarily represent those of
the
company. Although the company has taken reasonable precautions to ensure no
viruses are present in this email, the company cannot accept responsibility
for any loss or damage arising from the use of this email or attachments.