cursor: pin S wait on X querying data dictionary

From: Chris Stephens <cstephens16_at_gmail.com>
Date: Fri, 29 Jun 2018 09:26:23 -0500
Message-ID: <CAEFL0syARAiiAaFFv2faQbg67f6Ya1F5qPozO8HNURLH6ng=aA_at_mail.gmail.com>



3-node RAC 12.2 database on Centos7

We have an application which makes use of SQLAlchemy that is suffering mightily from "cursor: pin S wait on X" executing the following SQL:

SELECT col.column_name, col.data_type, col.char_length,

    col.data_precision, col.data_scale, col.nullable,
    col.data_default, com.comments
FROM all_tab_columns col

    LEFT JOIN all_col_comments com
    ON col.table_name = com.table_name
    AND col.column_name = com.column_name     AND col.owner = com.owner
    WHERE col.table_name = :table_name
    AND col.owner = :owner ORDER BY col.column_id

The application will launch ~200 concurrent sessions on startup. There is a long initial period where many of them are waiting on the event then things start clearing up and processing proceeds as expected. There are several different plan hash values for the SQL, one of which didn't seem to suffer from the issue so I created a sql baseline and crossed my fingers. I've collected dictionary statistics as well but that made no difference.

While I do my own searching, does any one have any suggestions on how to remove the delays?

Here is some ASH data showing the issue:

SQL> _at_ashtop sql_id,event "sql_id='0rz9dn5v75czn'" "TIMESTAMP'2018-06-28 18:45:00'" "TIMESTAMP'2018-06-29 00:00:00'"     Total

  Seconds     AAS %This   SQL_ID        EVENT
      FIRST_SEEN          LAST_SEEN           DIST_SQLEXEC_SEEN
--------- ------- ------- -------------

---------------------------------------- -------------------
------------------- -----------------
75469 4.0 84% | 0rz9dn5v75czn cursor: pin S wait on X 2018-06-28 20:11:34 2018-06-28 20:38:54 1 6441 .3 7% | 0rz9dn5v75czn library cache lock 2018-06-28 20:11:41 2018-06-28 20:38:36 1 6243 .3 7% | 0rz9dn5v75czn kksfbc child completion 2018-06-28 20:11:44 2018-06-28 20:38:43 1 1592 .1 2% | 0rz9dn5v75czn 2018-06-28 20:11:34 2018-06-28 20:38:55 105 182 .0 0% | 0rz9dn5v75czn cursor: pin S 2018-06-28 20:12:34 2018-06-28 20:38:34 1 133 .0 0% | 0rz9dn5v75czn library cache: mutex X 2018-06-28 20:12:09 2018-06-28 20:38:32 1 18 .0 0% | 0rz9dn5v75czn enq: PS - contention 2018-06-28 20:13:17 2018-06-28 20:38:55 18 15 .0 0% | 0rz9dn5v75czn cursor: pin X 2018-06-28 20:13:41 2018-06-28 20:38:36 1 select snap_id, end_interval_time 8 .0 0% | 0rz9dn5v75czn PGA memory operation 2018-06-28 20:15:24 2018-06-28 20:38:44 1 2 .0 0% | 0rz9dn5v75czn PX Deq: Join ACK 2018-06-28 20:13:26 2018-06-28 20:32:12 2 1 .0 0% | 0rz9dn5v75czn row cache read 2018-06-28 20:35:18 2018-06-28 20:35:18 1

11 rows selected.

SQL> _at_ashtop session_id,sql_id,event "sql_id='0rz9dn5v75czn'" "TIMESTAMP'2018-06-28 18:45:00'" "TIMESTAMP'2018-06-29 00:00:00'"     Total

  Seconds     AAS %This   SESSION_ID SQL_ID        EVENT
                FIRST_SEEN          LAST_SEEN           DIST_SQLEXEC_SEEN
--------- ------- ------- ---------- -------------

---------------------------------------- -------------------
------------------- -----------------
934 .0 1% | 2065 0rz9dn5v75czn cursor: pin S wait on X 2018-06-28 20:11:34 2018-06-28 20:37:03 1 925 .0 1% | 1459 0rz9dn5v75czn cursor: pin S wait on X 2018-06-28 20:11:34 2018-06-28 20:35:26 1 917 .0 1% | 613 0rz9dn5v75czn cursor: pin S wait on X 2018-06-28 20:13:26 2018-06-28 20:38:53 1 893 .0 1% | 4360 0rz9dn5v75czn cursor: pin S wait on X 2018-06-28 20:11:34 2018-06-28 20:38:45 1 873 .0 1% | 973 0rz9dn5v75czn cursor: pin S wait on X 2018-06-28 20:11:44 2018-06-28 20:38:26 1 861 .0 1% | 3276 0rz9dn5v75czn cursor: pin S wait on X 2018-06-28 20:11:44 2018-06-28 20:38:44 1 854 .0 1% | 3877 0rz9dn5v75czn cursor: pin S wait on X 2018-06-28 20:11:34 2018-06-28 20:38:52 1 828 .0 1% | 4602 0rz9dn5v75czn cursor: pin S wait on X 2018-06-28 20:11:44 2018-06-28 20:38:50 1 827 .0 1% | 2547 0rz9dn5v75czn cursor: pin S wait on X 2018-06-28 20:11:34 2018-06-28 20:38:47 1 826 .0 1% | 491 0rz9dn5v75czn cursor: pin S wait on X 2018-06-28 20:11:44 2018-06-28 20:38:44 1 823 .0 1% | 251 0rz9dn5v75czn cursor: pin S wait on X 2018-06-28 20:15:06 2018-06-28 20:38:51 1 818 .0 1% | 2790 0rz9dn5v75czn cursor: pin S wait on X 2018-06-28 20:15:06 2018-06-28 20:38:35 1 798 .0 1% | 124 0rz9dn5v75czn cursor: pin S wait on X 2018-06-28 20:11:44 2018-06-28 20:32:06 1 761 .0 1% | 129 0rz9dn5v75czn cursor: pin S wait on X 2018-06-28 20:11:34 2018-06-28 20:38:45 1 745 .0 1% | 6 0rz9dn5v75czn cursor: pin S wait on X 2018-06-28 20:11:44 2018-06-28 20:38:51 1 734 .0 1% | 738 0rz9dn5v75czn cursor: pin S wait on X 2018-06-28 20:11:44 2018-06-28 20:37:01 1 731 .0 1% | 123 0rz9dn5v75czn cursor: pin S wait on X 2018-06-28 20:13:24 2018-06-28 20:38:37 1 730 .0 1% | 4117 0rz9dn5v75czn cursor: pin S wait on X 2018-06-28 20:11:34 2018-06-28 20:38:43 1 726 .0 1% | 1216 0rz9dn5v75czn cursor: pin S wait on X 2018-06-28 20:17:17 2018-06-28 20:38:52 1 710 .0 1% | 3 0rz9dn5v75czn cursor: pin S wait on X 2018-06-28 20:16:46 2018-06-28 20:36:23 1

20 rows selected.

SQL> select distinct(plan_hash_value) from dba_hist_sqlstat where sql_id = '0rz9dn5v75czn' and snap_id >= 2378;

PLAN_HASH_VALUE


     2901843923
     1846450148
              0

SQL> l
  1 select plan_name, last_executed, enabled, accepted, fixed, executions   2 from dba_sql_plan_baselines
  3* where sql_text like '%col.column_name, col.data_type, col.char_length%' SQL> / PLAN_NAME LAST_EXECUTED ENABLED ACCEPTED FIXED EXECUTIONS
---------------------------------------- -------------------- ----------
---------- ---------- ----------
SQL_PLAN_78xa0f27qf69ye98653aa YES YES YES 38562

Anyone have any ideas?

Thanks as always!

--
http://www.freelists.org/webpage/oracle-l
Received on Fri Jun 29 2018 - 16:26:23 CEST

Original text of this message