Oracle Scratchpad

September 9, 2007

Set Role

Filed under: Oracle,Troubleshooting — Jonathan Lewis @ 7:24 pm GMT Sep 9,2007

I’ve been meaning to post a couple of comments about the set role command for several months – and a few days ago someone came on to the OTN Database Forum with the exact problem that I had been meaning to write about (except that it turned out that there was an even more important problem [thread subsequently deleted, unfortunately] causing the issue).

Try executing the following SQL (if you have an account that’s allowed to use the plustrace role).

set role plustrace, plustrace, plustrace, plustrace, plustrace;

Then go and look for the following SQL statements in your library cache (v$sql).

select
	privilege#,level
from
	sysauth$
connect by
	grantee# = prior privilege# and privilege# > 0
start with
	grantee# = :1 and privilege# > 0     

select
	max(nvl(option$,0))
from
	sysauth$
where
	privilege#=:1
connect by
	grantee# = prior privilege# and privilege# > 0
start with
	(grantee#=:2 or grantee#=1) and privilege# > 0
group by
	privilege#

Depending on your version of Oracle, the hash_value for the statements will be (respectively):

10g  2747636884     2195418186
9i   4143084494     3785480933
8i   502510949      1498920852

(In 10g, the old_hash_value will match the 9i hash_value, but the hash_value is the efficient query option).

You will find that every time you run the set role command I’ve shown, the other two statements will execute five times (once for each of the roles I’ve set – even though it’s actually the same role setĀ five times).

Be very careful what you do with the set role command. I have seen a couple of web-based systems coded to run a statement of this type as a precursor to every other call they make to the database – with the effect that the two recursive statements account for several percent of the total CPU used by the application.

13 Comments »

  1. Excellent comment

    Comment by Vishal Gupta — September 9, 2007 @ 7:47 pm GMT Sep 9,2007 | Reply

  2. All,

    I’m having the exact same problem on a 10.2.0.3 database with the privile# query being the top execution statement but I can’t figure out who would be doing a “set role”. Is there any way to find out who’s issuing the command (it’s not in v$sqlarea). This is a php application.

    Thanks,
    Brian Motzer (bmotzer@digitalriver.com)

    Comment by Brian Motzer — September 13, 2007 @ 4:38 am GMT Sep 13,2007 | Reply

  3. Jonathan,

    Excellent!
    With this post, you have answered a one and a half year old question of mine:

    http://forums.oracle.com/forums/thread.jspa?messageID=1434902&#1434902

    A big thank you, as we can now look for the set role command.

    Regards,
    Rob.

    Comment by Rob van Wijk — September 18, 2007 @ 3:31 pm GMT Sep 18,2007 | Reply

  4. Jonathan,

    I know it’s an old post, but I am experiencing exactly the same issue, with this query on Top Queries, with more than 20 million executions. How could I find a session executing it? I tried to do a test issuing “SET ROLE” in a session, and it really increased the execution count of that query. But, I can’t find any session issuing it, probably because it’s issued followed by a lot of other commands. In my environment we have Oracle E-Business Suite 11.5.8, and I would like to know if it is that APP that is issuing it or some other kind of connection. Thanks in advance.

    Comment by Eduardo — March 15, 2010 @ 8:54 pm GMT Mar 15,2010 | Reply

    • Eduardo,

      I think your suggestion about sessions issuing a lot more commands is probably correct. This does make it difficult, and I can only think of two things to experiment with:

      a) create a logon trigger that enables sql_trace on an EBS account. Enable it for a short period so that you can see if the SET ROLE appears very early on in a few traces.

      b) write a pl/sql loop that keeps scanning v$open_cursor for sql_text like ‘SET ROLE%’ then stops and captures all the entries for the session id if it finds a session executing it.

      Comment by Jonathan Lewis — March 20, 2010 @ 1:04 pm GMT Mar 20,2010 | Reply

  5. Jonathan, thanks for the response. But, my doubt persists: I see hundreds of executions of this query on sysauth$ every minute, but I never can find a statement like SET ROLE in V$SQL:

    SQL> select sysdate, hash_value, executions, sql_text from v$sql where hash_value=4143084494;
    
    SYSDATE                 HASH_VALUE EXECUTIONS SQL_TEXT
    -------------------- ------------- ---------- ----------------------------------------------------------------
    26-MAR-2010 14:56:08    4143084494   30243518 select privilege#,level from sysauth$ connect by grantee#=prior
                                                  privilege# and privilege#>0 start with grantee#=:1 and
                                                  privilege#>0
    
    
    1 row selected.
    
    SQL> /
    
    SYSDATE                 HASH_VALUE EXECUTIONS SQL_TEXT
    -------------------- ------------- ---------- ----------------------------------------------------------------
    26-MAR-2010 14:56:10    4143084494   30243551 select privilege#,level from sysauth$ connect by grantee#=prior
                                                  privilege# and privilege#>0 start with grantee#=:1 and
                                                  privilege#>0
    
    
    1 row selected.
    
    SQL> /
    
    SYSDATE                 HASH_VALUE EXECUTIONS SQL_TEXT
    -------------------- ------------- ---------- ----------------------------------------------------------------
    26-MAR-2010 14:56:13    4143084494   30243595 select privilege#,level from sysauth$ connect by grantee#=prior
                                                  privilege# and privilege#>0 start with grantee#=:1 and
                                                  privilege#>0
    
    
    1 row selected.
    
    SQL> /
    
    SYSDATE                 HASH_VALUE EXECUTIONS SQL_TEXT
    -------------------- ------------- ---------- ----------------------------------------------------------------
    26-MAR-2010 14:56:14    4143084494   30243606 select privilege#,level from sysauth$ connect by grantee#=prior
                                                  privilege# and privilege#>0 start with grantee#=:1 and
                                                  privilege#>0
    
    
    1 row selected.
    
    SQL> select * from v$sql where upper(sql_text) like '%SET ROLE%';
    
    SQL_TEXT                                                         SHARABLE_MEM PERSISTENT_MEM RUNTIME_MEM SORTS LO
    ---------------------------------------------------------------- ------------ -------------- ----------- ----- --
    select * from v$sql where upper(sql_text) like '%SET ROLE%'            209028           5024       20496     0          
    
    
    1 row selected.
    
    

    —-
    Can you figure out why?

    Comment by Eduardo — March 26, 2010 @ 6:01 pm GMT Mar 26,2010 | Reply

  6. Jonathan, I think I finally discovered: when a session connect, it does SET ROLE for every ROLE the user has as DEFAULT. The statement SET ROLE does not appear in the V$SQL / V$SQLAREA, but the query on SYSAUTH$ is executed.

    I have done tests in a DEV environment, where APPS user has 17 roles, 11 as DEFAULT. And every time I connect, the executions of the query on SYSAUTH$ increases by 11 exactly.

    Does it make sense?

    Comment by Eduardo — March 26, 2010 @ 6:30 pm GMT Mar 26,2010 | Reply

    • Eduardo,

      That definitely makes sense.

      If you want to increase your confidence in your hypothesis – turn one of the non-default roles into a default role and see if the execution count jumps by 12 at a time; then see if you can make it drop.

      It’s the scientific method – you have a hypothesis, so make a prediction based on the hypothesis and see if it comes true.

      Comment by Jonathan Lewis — March 26, 2010 @ 10:06 pm GMT Mar 26,2010 | Reply

  7. Jonathan, thanks for your advise. I tried the hypothesis, and found little different results:

    a) Initial situation: APPS user with 16 roles associated, 11 default. Every time I connected, the EXECUTIONS of the STATEMENT with HASH_VALUE=4143084494 increases by 11.

    b) Changed APPS user to have just ONE role as default, and the TWO roles as default. As expected, the EXECUTIONS of that STATEMENT increased first by 1, then by 2. That was proving my hypothesis.

    c) Changed APPS to have ALL 16 roles as default. Here is the unexpected: with ALL roles as default, that STATEMENT did not increased ANY EXECUTION. Instead, another similar one, increase by 1 after every connect:

    HASH_VALUE 1356713530
    
    select privilege#,level from sysauth$ 
    connect by grantee#=prior privilege# 
    and privilege#>0 
    start with (grantee#=:1 or grantee#=1) 
    and privilege#>0
    

    So, my conclusion is: if we have roles as DEFAULT and NON DEFAULT at the same time, Oracle executes that first statment (HV 4143084494) for every DEFAULT role. But, i fwe have ONLY DEFAULT ROLES, Oracle executes the second statement (HV 1356713530) for every connection, not every role.

    What do you think?

    Comment by Eduardo — March 29, 2010 @ 9:12 pm GMT Mar 29,2010 | Reply

  8. Hi Jonathan, I have read your book on CBO its very good one…
    At the customer I am working we have a database, which at times hits 100% CPU and we see library cache: mutex X as top wait event and Avg wait (ms) 709076 and this is causing hang like situation, and in the ASH report I see below query causing the high mutex x wait events, the number of users logons are also very about 4000 per every 5 mins.

    select  privilege# from sysauth$ where (grantee#=:1 or grantee#=1) and privilege#>0, 
    

    on the top sql with top event

    Top SQL with Top Events
    SQL ID Planhash Sampled # of Executions % Activity Event % Event Top Row Source % RwSrc SQL Text 
    0k8522rmdzg4k 781879863 200 1.32 library cache: mutex X 1.32 SELECT STATEMENT 1.32 select privilege# from sysauth... 
    

    Do you think the above query has potential to cause the high library cache mutex X, and the database version is 11.2.0.2

    Comment by Sharath — December 7, 2011 @ 8:04 pm GMT Dec 7,2011 | Reply

  9. Sharath,

    4,000 user logins in 5 minutes is about 13 per second. It’s quite a lot, and may be unnecessary, but it should be perfectly possible for Oracle to cope with this level of concurrency. But do take note of the previous comments about the number of roles and default roles a user has.

    Problems with high levels of CPU usage combined with waits on mutexes are difficult to solve without some very detailed investigation, as it’s hard to say which is the cause and which the effect – or whether something completely different is the cause and both the symptoms are a side effect.

    You need to read through the material that Andrey Nikolaev ( http://andreynikolaev.wordpress.com/ ) has written about latches and mutexes, and the stuff that Tanel Poder has written about drilling into problems with tools like his snapper and latchprofx.

    I would also look at the release notes for 11.2.0.3 for any bug fixes relating to mutexes.

    Comment by Jonathan Lewis — December 11, 2011 @ 3:37 pm GMT Dec 11,2011 | Reply

  10. Hello Jonathan,
    I have a performance problem with a query oracle judge him given two different execution plan.
    You will find below an extract of the report when tracing the application:

    
    SELECT DP.*,PMP.* FROM DONNEE_COMMANDE DC INNER JOIN DONNEE_PAIEMENT DP ON DC.PAIE_ID = DP.PAIE_ID INNER JOIN
    DONNEE_ADP DA ON DA.CDE_REFERENCE = DC.CDE_REFERENCE INNER JOIN PARAM_MODE_PAIEMENT PMP ON PMP.MODE_PAIEMENT_ID =
    DA.ADP_PAIEMENT_PAR AND DA.ADP_TYPE_PAIEMENT IN ('P') WHERE DA.CDE_REFERENCE like :1
    - Changement de plan -
    .  plan_hash      Debut periode     Fin periode   NbSNAPs  disk_reads  buffer_gets  executions   cpu_time elapsed_time
    +--------------+----------------+----------------+------+------------+------------+------------+----------+----------+
    | 618324501    | 20121126 09:30 | 20121126 12:00 |    4 |      99077 |     214002 |          6 |        7 |        7 |
    |              |(Snap:151031)   |(Snap:151081)   |      |            |            |            |          |          |
    +--------------+----------------+----------------+------+------------+------------+------------+----------+----------+
    | 2037534432   | 20121126 13:30 | 20121126 14:30 |    3 |    1537493 |    2718319 |         56 |       95 |       97 |
    |              |(Snap:151111)   |(Snap:151131)   |      |            |            |            |          |          |
    +--------------+----------------+----------------+------+------------+------------+------------+----------+----------+
    | 618324501    | 20121126 15:00 | 20121126 15:30 |    2 |     274608 |     499340 |         14 |       16 |       17 |
    |              |(Snap:151141)   |(Snap:151151)   |      |            |            |            |          |          |
    +--------------+----------------+----------------+------+------------+------------+------------+----------+----------+
    1. Plan d'execution No 618324501
    +-----+--------------------------------+---------------------------+------+------+------+------+---------------------+
    | Id  | Operation                      |  Objet                    | Card | Bytes| Temp | Cost | Optimiser           |
    +-----+--------------------------------+---------------------------+------+------+------+------+---------------------+
    |   0 | SELECT STATEMENT               |                           |   0  |   0  |   0  |   7K | CHOOSE              |
    |   1 |  NESTED LOOPS                  |                           |   1  |   0  |   0  |   7K |                     |
    |   2 |   NESTED LOOPS                 |                           |   1  |   0  |   0  |   7K |                     |
    |   3 |    NESTED LOOPS                |                           |   1  |   0  |   0  |   7K |                     |
    |   4 |     TABLE ACCESS FULL          | DONNEE_ADP                |   1  |   0  |   0  |   7K |                     |
    |   5 |     TABLE ACCESS BY INDEX ROWI | PARAM_MODE_PAIEMENT       |   1  |   0  |   0  |   1  |                     |
    |   6 |      INDEX UNIQUE SCAN         | PK_PARAM_MODE_PAIEMENT    |   1  |   0  |   0  |   0  |                     |
    |   7 |    TABLE ACCESS BY INDEX ROWID | DONNEE_COMMANDE           |   1  |   0  |   0  |   2  |                     |
    |   8 |     INDEX UNIQUE SCAN          | PK_DONNEE_COMMANDE        |   1  |   0  |   0  |   1  |                     |
    |   9 |   TABLE ACCESS BY INDEX ROWID  | DONNEE_PAIEMENT           |   1  |   0  |   0  |   2  |                     |
    |  10 |    INDEX UNIQUE SCAN           | PK_DONNEE_PAIEMENT        |   1  |   0  |   0  |   1  |                     |
    +-----+--------------------------------+---------------------------+------+------+------+------+---------------------+
    2. Plan d'execution No 2037534432
    +-----+--------------------------------+---------------------------+------+------+------+------+---------------------+
    | Id  | Operation                      |  Objet                    | Card | Bytes| Temp | Cost | Optimiser           |
    +-----+--------------------------------+---------------------------+------+------+------+------+---------------------+
    |   0 | SELECT STATEMENT               |                           |   0  |   0  |   0  |  17K | CHOOSE              |
    |   1 |  HASH JOIN                     |                           |  48K |   9K |   0  |  17K |                     |
    |   2 |   TABLE ACCESS FULL            | PARAM_MODE_PAIEMENT       |   8  |   0  |   0  |   9  |                     |
    |   3 |   HASH JOIN                    |                           |  48K |   8K |   0  |  17K |                     |
    |   4 |    TABLE ACCESS FULL           | DONNEE_ADP                |  47K | 741  |   0  |   7K |                     |
    |   5 |    HASH JOIN                   |                           |  48K |   7K |   0  |  10K |                     |
    |   6 |     TABLE ACCESS BY INDEX ROWI | DONNEE_COMMANDE           |  48K | 795  |   0  |   5K |                     |
    |   7 |      INDEX RANGE SCAN          | PK_DONNEE_COMMANDE        |   9K |   0  |   0  |  49  |                     |
    |   8 |     TABLE ACCESS FULL          | DONNEE_PAIEMENT           | 931K | 125K |   0  |   5K |                     |
    +-----+--------------------------------+---------------------------+------+------+------+------+---------------------+
    

    I want to know why Oracle has chosen two implementation plan ??

    Thank you very mutch

    Comment by ZH — November 27, 2012 @ 2:32 pm GMT Nov 27,2012 | Reply

    • Notice the LIKE predicate that uses a bind variable.
      Notice also the extremely different cardinality estimates.
      This looks like a typical case of bind variable peeking where a different input value has caused Oracle to choose a dramatically different execution plan.
      There is something a little odd about your output, by the way – what code are you using, it looks like headings on the Bytes and Card columns are the wrong way round.

      Comment by Jonathan Lewis — December 13, 2012 @ 6:42 pm GMT Dec 13,2012 | Reply


RSS feed for comments on this post. TrackBack URI

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

The Rubric Theme. Blog at WordPress.com.

Follow

Get every new post delivered to your Inbox.

Join 4,522 other followers