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

Baselines will not help you, the wait is before execution can even begin. In fact, a baseline can end up slowing the parse down as it may require multiple parses.

You may be better off kicking this off in a serial fashion, then you won’t have 199 sessions spinning on matches while waiting for 1 session to parse the SQL (and contending for the same cpu).

On Fri, 29 Jun 2018 at 15:27, Chris Stephens <cstephens16_at_gmail.com> wrote:

> 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