Thread: Fw: Infinite CPU loop due to field ::type casting, Take II :-)

Fw: Infinite CPU loop due to field ::type casting, Take II :-)

From
Steven Rosenstein
Date:



I just realized in my haste to send this email out I provided the wrong
table in my example.  Below is the same email, but with
vsa.dtbl_logged_event_20040922 substituted for vsa.tbl_sad_event.

Sorry for the inconvenience.

--- Steve


Gentlefolk,

I'm not sure if this is the proper forum for this question, and it might
have been answered in a previous thread, but I'm new to PostgreSQL and the
research I did in the archives did not turn up anything addressing this
issue.  Please direct me to the proper forum is this is not the correct
venue.

Environment: Red Hat Enterprise Linux 3 Workstation, PostgreSQL V7.3.6
(stock with the RHEL distribution)

The two tables I used in the example are tbl_device and
dtbl_logged_event_20040922:

vsa=# \d vsa.tbl_device;
                                       Table "vsa.tbl_device"
     Column     |           Type           |
Modifiers
----------------+--------------------------+---------------------------------------------------------
 id             | integer                  | not null default
nextval('vsa.tbl_device_id_seq'::text)
 name           | character varying(100)   | not null
 account_id     | bigint                   | not null
 vss_site_id    | bigint                   | not null
 org_site_id    | bigint                   | not null default 0
 device_type_id | integer                  | not null default 1
 os_family_id   | integer                  | not null default 0
 status_id      | integer                  | not null default 0
 timezone       | character varying(80)    |
 clientkey      | character varying(2048)  | not null
 record_created | timestamp with time zone | default now()
Indexes: pk_tbl_device primary key btree (id),
         idx_d_uniq_name_site_account_key unique btree (name, vss_site_id,
account_id, clientkey),
         tbl_device_clientkey_key unique btree (clientkey),
         idx_d_account_id btree (account_id),
         idx_d_account_site_name btree (account_id, vss_site_id, name),
         idx_d_device_type_id btree (device_type_id),
         idx_d_name btree (name),
         idx_d_org_site_id btree (org_site_id),
         idx_d_os_family_id btree (os_family_id),
         idx_d_status_id btree (status_id),
         idx_d_vss_site_id btree (vss_site_id)
Foreign Key constraints: fk_d_va FOREIGN KEY (account_id) REFERENCES
vsa.tbl_vsa_account(id) ON UPDATE NO ACTION ON DELETE NO ACTION,
                         fk_d_vs FOREIGN KEY (vss_site_id) REFERENCES
vsa.tbl_vss_site(id) ON UPDATE NO ACTION ON DELETE NO ACTION,
                         fk_d_dof FOREIGN KEY (os_family_id) REFERENCES
vsa.enum_device_os_family(id) ON UPDATE NO ACTION ON DELETE NO ACTION,
                         fk_d_dsc FOREIGN KEY (status_id) REFERENCES
vsa.enum_device_status_code(id) ON UPDATE NO ACTION ON DELETE NO ACTION,
                         fk_d_dt FOREIGN KEY (device_type_id) REFERENCES
vsa.enum_device_type(id) ON UPDATE NO ACTION ON DELETE NO ACTION
Triggers: trg_clean_device_name

vsa=# \d vsa.dtbl_logged_event_20040922
                                         Table
"vsa.dtbl_logged_event_20040922"
     Column      |            Type             |
Modifiers

-----------------+-----------------------------+-------------------------------------------------------------------------
 id              | integer                     | not null default
nextval('vsa.dtbl_logged_event_20040922_id_seq'::text)
 device_id       | bigint                      | not null
 report_datetime | timestamp without time zone |
 time_logged     | timestamp without time zone |
 log_type        | integer                     | not null
 type            | character varying(50)       |
 severity        | character varying(30)       |
 source_tag      | character varying(30)       |
 remote_host     | character varying(100)      |
 user_name       | character varying(50)       |
 event_code      | character varying(10)       |
 description     | text                        |
 record_created  | timestamp with time zone    | default now()
 event_code_new  | character varying(30)       |
 remote_user     | character varying(50)       |
Indexes: pk_dtbl_logged_event_20040922 primary key btree (id),
         idx_le_device_id_20040922 btree (device_id),
         idx_le_id_source_event_20040922 btree (device_id, source_tag,
event_code),
         idx_le_id_src_20040922 btree (device_id, source_tag),
         idx_le_id_type_severity_evtcode_20040922 btree (device_id,
log_type, severity, event_code),
         idx_le_log_type_20040922 btree (log_type),
         idx_le_source_tag_20040922 btree (source_tag),
         idx_le_time_logged_20040922 btree (time_logged),
         idx_le_time_type_20040922 btree (time_logged, log_type)
Foreign Key constraints: fk_le_lelt_20040922 FOREIGN KEY (log_type)
REFERENCES vsa.enum_le_log_type(id) ON UPDATE NO ACTION ON DELETE NO
ACTION,
                         fk_le_d_20040922 FOREIGN KEY (device_id)
REFERENCES vsa.tbl_device(id) ON UPDATE NO ACTION ON DELETE CASCADE


Here is my original query, and the query plan generated by the planner:

vsa=# explain
SELECT dev.name, dev.vss_site_id, tbl.log_type, tbl.severity, tbl.count
FROM vsa.tbl_device AS dev
LEFT OUTER JOIN
  (SELECT stbl.device_id, stbl.log_type, stbl.severity, count(*)
   FROM vsa.dtbl_logged_event_20040922 AS stbl
   WHERE stbl.log_type IN (2, 3, 4, 5)
   GROUP BY stbl.device_id, stbl.log_type, stbl.severity) AS tbl
  ON (dev.id=tbl.device_id)
ORDER BY dev.name;
                                                                                  QUERY PLAN


------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Sort  (cost=40893.18..40960.93 rows=27100 width=79)
   Sort Key: dev.name
   ->  Merge Join  (cost=38417.13..38897.77 rows=27100 width=79)
         Merge Cond: ("outer".id = "inner".device_id)
         ->  Sort  (cost=869.52..872.70 rows=1275 width=26)
               Sort Key: dev.id
               ->  Seq Scan on tbl_device dev  (cost=0.00..803.75 rows=1275 width=26)
         ->  Sort  (cost=37547.62..37615.37 rows=27100 width=26)
               Sort Key: tbl.device_id
               ->  Subquery Scan tbl  (cost=0.00..35552.21 rows=27100 width=26)
                     ->  Aggregate  (cost=0.00..35552.21 rows=27100 width=26)
                           ->  Group  (cost=0.00..34874.70 rows=271005 width=26)
                                 ->  Index Scan using idx_le_id_type_severity_evtcode_20040922 on
dtbl_logged_event_20040922stbl 
(cost=0.00..32842.16 rows=271005 width=26)
                                       Filter: ((log_type = 2) OR (log_type = 3) OR (log_type = 4) OR (log_type = 5))
(14 rows)

Time: 1.43 ms


Late in the development I realized that we had created an inconsistency in
our design by having vsa.tbl_device.id defined as "int", and
vsa.dtbl_logged_event_20040922.device_id defined as "bigint".  These two
fields are used in the ON clause (ON (dev.id=tbl.device_id)), and my
understanding is that they should be of the same type cast.  Trying to
remedy this situation, I explicitly tried casting
vsa.dtbl_logged_event_20040922.device_id as "int" (::int):

vsa=# explain
SELECT dev.name, dev.vss_site_id, tbl.log_type, tbl.severity, tbl.count
FROM vsa.tbl_device AS dev
LEFT OUTER JOIN
  (SELECT stbl.device_id, stbl.log_type, stbl.severity, count(*)
   FROM vsa.dtbl_logged_event_20040922 AS stbl
   WHERE stbl.log_type IN (2, 3, 4, 5) GROUP BY stbl.device_id,
stbl.log_type, stbl.severity) AS tbl
  ON (dev.id=tbl.device_id::int)
ORDER BY dev.name;
                                                                            QUERY PLAN


------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Nested Loop  (cost=0.00..45848850.65 rows=27100 width=79)
   Join Filter: ("outer".id = ("inner".device_id)::integer)
   ->  Index Scan using idx_d_name on tbl_device dev  (cost=0.00..1490.19 rows=1275 width=26)
   ->  Subquery Scan tbl  (cost=0.00..35552.21 rows=27100 width=26)
         ->  Aggregate  (cost=0.00..35552.21 rows=27100 width=26)
               ->  Group  (cost=0.00..34874.70 rows=271005 width=26)
                     ->  Index Scan using idx_le_id_type_severity_evtcode_20040922 on dtbl_logged_event_20040922 stbl
(cost=0.00..32842.16
rows=271005 width=26)
                           Filter: ((log_type = 2) OR (log_type = 3) OR (log_type = 4) OR (log_type = 5))
(8 rows)

Time: 1.62 ms


Notice that the query plan changes completely when I cast device_id as int.
What is worse (and why I'm writing) is that when I run the second query, it
goes into an infinite CPU loop.  The original query completed in under 4
seconds.  I've left the second query running for 30 minutes or more, and
TOP show 100% CPU utilization and 0% disk I/O (0% iowait).

We are starting to see this phenomenon in other queries which do *not* have
any explicit type casting, but in which something like
"cast(vsa.dtbl_logged_event_20040922.time_logged AS date)" is used in a
WHERE clause.  It's becoming a show-stopper until we understand what is
happening.

Any information or suggestions about this problem or making the query more
efficient will be greatly appreciated.

Thanks!
--- Steve


Re: Fw: Infinite CPU loop due to field ::type casting, Take II :-)

From
Tom Lane
Date:
Steven Rosenstein <srosenst@us.ibm.com> writes:
> Environment: Red Hat Enterprise Linux 3 Workstation, PostgreSQL V7.3.6

> vsa=# explain
> SELECT dev.name, dev.vss_site_id, tbl.log_type, tbl.severity, tbl.count
> FROM vsa.tbl_device AS dev
> LEFT OUTER JOIN
>   (SELECT stbl.device_id, stbl.log_type, stbl.severity, count(*)
>    FROM vsa.dtbl_logged_event_20040922 AS stbl
>    WHERE stbl.log_type IN (2, 3, 4, 5) GROUP BY stbl.device_id,
> stbl.log_type, stbl.severity) AS tbl
>   ON (dev.id=tbl.device_id::int)
> ORDER BY dev.name;
>                                                                             QUERY PLAN

>
------------------------------------------------------------------------------------------------------------------------------------------------------------------
>  Nested Loop  (cost=0.00..45848850.65 rows=27100 width=79)
>    Join Filter: ("outer".id = ("inner".device_id)::integer)
>    ->  Index Scan using idx_d_name on tbl_device dev  (cost=0.00..1490.19 rows=1275 width=26)
>    ->  Subquery Scan tbl  (cost=0.00..35552.21 rows=27100 width=26)
>          ->  Aggregate  (cost=0.00..35552.21 rows=27100 width=26)
>                ->  Group  (cost=0.00..34874.70 rows=271005 width=26)
>                      ->  Index Scan using idx_le_id_type_severity_evtcode_20040922 on dtbl_logged_event_20040922 stbl
(cost=0.00..32842.16 
> rows=271005 width=26)
>                            Filter: ((log_type = 2) OR (log_type = 3) OR (log_type = 4) OR (log_type = 5))
> (8 rows)

> Time: 1.62 ms


> Notice that the query plan changes completely when I cast device_id as int.
> What is worse (and why I'm writing) is that when I run the second query, it
> goes into an infinite CPU loop.

"Bad plan" and "infinite loop" are two very different things.

In 7.3 you'd be better off without the cast, as you just found out.  The
7.3 backend can only handle merge or hash joins that use a join clause
of the form "variable = variable" --- anything more complicated falls
back to a nested loop join.  It does handle mergejoins between unlike
data types, though, so you were doing okay with the undecorated query.

7.4 is smarter; dunno if you want to upgrade at this point.

            regards, tom lane