Re: cursor: pin S wait on X querying data dictionary

  • From: Chris Stephens <cstephens16@xxxxxxxxx>
  • To: Jonathan Lewis <jonathan@xxxxxxxxxxxxxxxxxx>
  • Date: Sat, 30 Jun 2018 06:35:46 -0500

Thanks so much for taking the time to look at this. Yes, this is a single
tenant CDB/PDB.

The developer reworked the code to eliminate the metadata queries and
problem vanished.

I’ll have access to the system tomorrow and will check and let you know
what I find. ..assuming ASH data is still around.

Thanks again!


On Sat, Jun 30, 2018 at 4:16 AM Jonathan Lewis <jonathan@xxxxxxxxxxxxxxxxxx>
wrote:


Is this a PDB running inside a CDB, or is it a non-PDB database ?
Have you checked the execution plan for the query.

Running on a PDB inside a CDB (which is all I can get hands on at the
moment) I can see that there's a cross database call which causes parallel
servers to start up. It's possible that the the issue with cursor pinning
is a side effect of this parallelism; when I ran the query it was one of my
PX slaves that had happened to wait on 'cursor: pin S wait on X'.

A quick check on ASH to see if the parallelism is a problem would be to
split the counts for the wait into one ones where qc_session_id was null
(the query coordinators) and qc_session_id is not null (PX slaves).

I don't know what the parallelism is for - but possibly the effect is made
worse by the presence of RAC - perhaps some of the slaves are being
allocated remotely when ideally they should be allocated locally.


The other problem, of course, is that the data is likely to be extremely
skewed for a few owners - so the optimizer probably does a lot of work
calculating inflection points (my plan show 6 possible inflection points).
Have you checked the data dictionary to see if the stats are reasonably
accurate, and whether you could create some column groups that might help
the optimizer get better estimates of cardinality.  Anything which reduces
actual optimisation time might help.

Regards
Jonathan Lewis


________________________________________
From: oracle-l-bounce@xxxxxxxxxxxxx <oracle-l-bounce@xxxxxxxxxxxxx> on
behalf of Chris Stephens <cstephens16@xxxxxxxxx>
Sent: 29 June 2018 15:26:23
To: oracle-l
Subject: cursor: pin S wait on X querying data dictionary

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> @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> @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!

Other related posts: