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

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_at_jlcomp.demon.co.uk> 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_at_freelists.org <oracle-l-bounce_at_freelists.org> on
> behalf of Chris Stephens <cstephens16_at_gmail.com>
> 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> _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