Страницы

воскресенье, 21 июля 2019 г.

v$db_pipes: Unveiling the Truth of Oracle Hash Value

A question about optimizing access to v$db_pipes just came up recently on the SQL.RU Oracle database forum. The Topic Starter wanted to find out if there is a way to speed up the query against v$db_pipes or there are any other options to see if a named pipe exists.
So here is the query that was run and its plan:
SQL> explain plan for
  2  select count(*)
  3    from v$db_pipes
  4   where name = 'MY_PIPE';

Explained.

SQL> select * from table(dbms_xplan.display);

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------
Plan hash value: 2656999297

-----------------------------------------------------------------------------
| Id  | Operation         | Name    | Rows  | Bytes | Cost (%CPU)| Time     |
-----------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |         |     1 |   148 |     1 (100)| 00:00:01 |
|   1 |  SORT AGGREGATE   |         |     1 |   148 |            |          |
|*  2 |   FIXED TABLE FULL| X$KGLOB |     1 |   148 |     1 (100)| 00:00:01 |
-----------------------------------------------------------------------------

Predicate Information (identified by operation id):

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------
---------------------------------------------------

   2 - filter("KGLNAOBJ"='MY_PIPE' AND "KGLHDNSP"=7 AND "KGLOBSTA"<>0
              AND "INST_ID"=USERENV('INSTANCE'))
It is seen that v$db_pipes is built on top of x$kglob, which is a fixed table.
Obviously, doing a FULL TABLE SCAN against it is not the best thing to do, especially when we work with a large enough shared pool.
Fixed tables can have Oracle provided indexes and x$kglob has the following ones:
SQL> select index_number, column_name from v$indexed_fixed_column where table_name='X$KGLOB';

INDEX_NUMBER COLUMN_NAME
------------ ------------
           1 KGLNAHSH
           2 KGLOBT03
KGLOBT03 is not populated for pipes and it stores the SQL_ID of a statement being executed.
KGLNAHSH is a hash value and it seems to store last 4 bytes of KGLNAHSV which is a full hash value:
SQL> select kglnaobj, kglnahsv, kglnahsh, to_char(kglnahsh, 'fm0xxxxxxx') hex_hash, kglhdnsp from x$kglob where kglnaobj in ('MY_PIPE',  'MY_PIPE1', 'MY_PIPE2');

KGLNAOBJ                       KGLNAHSV                           KGLNAHSH HEX_HASH    KGLHDNSP
------------------------------ -------------------------------- ---------- --------- ----------
MY_PIPE2                       53e58fa645a35847070108600b3043ce  187712462 0b3043ce           7
MY_PIPE1                       1bb0749b381c19f0dd4d47413a125cc1  974281921 3a125cc1           7
MY_PIPE                        cdff652a7449f169da313e5685b962d8 2243519192 85b962d8           7
If I knew a way to calculate the hash value upfront, then I could query x$kglob passing the hash value as a filter to get an indexed access path:
SQL> explain plan for
  2  select count(*)
  3    from x$kglob
  4   where kglnaobj = 'MY_PIPE'
  5     and kglhdnsp = 7
  6     and kglobsta <> 0
  7     and inst_id = userenv('instance')
  8     and kglnahsh = 2243519192;

Explained.

SQL>
SQL> select * from table(dbms_xplan.display);

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------
Plan hash value: 2109255596

--------------------------------------------------------------------------------------------
| Id  | Operation                | Name            | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT         |                 |     1 |   155 |     0   (0)| 00:00:01 |
|   1 |  SORT AGGREGATE          |                 |     1 |   155 |            |          |
|*  2 |   FIXED TABLE FIXED INDEX| X$KGLOB (ind:1) |     1 |   155 |     0   (0)| 00:00:01 |
--------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------

   2 - filter("KGLNAHSH"=2243519192 AND "KGLNAOBJ"='MY_PIPE' AND "KGLHDNSP"=7 AND
              "KGLOBSTA"<>0 AND "INST_ID"=USERENV('INSTANCE'))
I decided to try to find out how the hash value is calculated.
Firstly, I took the library cache dump:
Bucket: #=90840 Mutex=0x6cb2aa60(283467841536, 2, 0, 6)
  LibraryHandle:  Address=0x654cc068 Hash=85b962d8 LockMode=0 PinMode=0 LoadLockMode=0 Status=VALD
    ObjectName:  Name=CDB$ROOT.MY_PIPE
      FullHashValue=cdff652a7449f169da313e5685b962d8 Namespace=PIPE(07) Type=PIPE(18) ContainerId=1 ContainerUid=1 Identifier=0 OwnerIdn=2147483644
    Statistics:  InvalidationCount=0 ExecutionCount=0 LoadCount=1 ActiveLocks=0 TotalLockCount=1 TotalPinCount=1
    Counters:  BrokenCount=1 RevocablePointer=1 KeepDependency=0 Version=0 BucketInUse=0 HandleInUse=0 HandleReferenceCount=0
    Concurrency:  DependencyMutex=0x654cc118(0, 0, 0, 0) Mutex=0x654cc1b8(66, 8, 0, 6)
    Flags=RON/PN0/[10012001] Flags2=[0000]
    WaitersLists:
      Lock=0x654cc0f8[0x654cc0f8,0x654cc0f8]
      Pin=0x654cc0d8[0x654cc0d8,0x654cc0d8]
      LoadLock=0x654cc150[0x654cc150,0x654cc150]
    Timestamp:
    LibraryObject:  Address=0x65f9cb98 HeapMask=0000-0001-0001-0000 Flags=EXS/NRC[0400] Flags2=[0000] Flags3=[0000] PublicFlags=[0000]
Based on my knowledge of Oracle internals, I supposed that the hash value should be somehow derived from the name of the object and possibly other attributes of it.
Unfortunately, I was not able to find a proper formula looking into the library cache dump (I was close, in fact, as I was combined the object name with the namespace, however, a proper formula is hard or even near to impossible to come by).
When my first attempts to solve this conundrum failed miserably, I took a break and returned to that task later on.

That time I took more systematic approach and started by unwrapping the DBMS_PIPE package. I found out that the DBMS_PIPE.CREATE_PIPE function calls the CREATEPIPE function that has a widely used INTERFACE pragma, which roughly means that the function is mapped to another C function within the Oracle kernel. The function to which CREATEPIPE should be mapped should probably be called kkxpcre based on the excellent Dennis Yurichev blog post (of course, Dennis' post was written a while ago but Oracle has not given much attention to pipes for a while and I seriously doubt that they have changed that mapping since then). All of this knowledge appears to be useless at a glance, however, it laid the groundwork for the next step.

The next step of my research started when I was using the DebugTrace program from Intel Pintools. I ran DebugTrace against the server process in which I created a new pipe named MY_PIPE that has the hash value 2243519192 which is 0x85b962d8 in hex.
Here is the relevant output of DebugTrace which I reformatted for brevity (this is the output that I obtained from Oracle 19c, I also got a 12.2 output initially that had a few minor differencies):
Call 0x000000000f7775db $ORACLE_HOME/bin/oracle:kkxpcre+0x0000000002db -> 0x000000000b032100 $ORACLE_HOME/bin/oracle:kkxpcrep(0x7f0fd3e6fe80, 0x7, ...)
| Call 0x000000000b03225b $ORACLE_HOME/bin/oracle:kkxpcrep+0x00000000015b -> 0x000000001280c720 $ORACLE_HOME/bin/oracle:kglget(0x7f0fd3f889a0, 0x7fff3aea4d50, ...)
| | Call 0x000000001280c844 $ORACLE_HOME/bin/oracle:kglget+0x000000000124 -> 0x00000000128119f0 $ORACLE_HOME/bin/oracle:kglLock(0x7f0fd3f889a0, 0x7fff3aea4d50, ...)
| | | Call 0x0000000012811b4b $ORACLE_HOME/bin/oracle:kglLock+0x00000000015b -> 0x0000000012815280 $ORACLE_HOME/bin/oracle:kglComputeHash(0x7f0fd3f889a0, 0x7fff3aea4dd0, ...)
| | | Tailcall 0x000000001281528d $ORACLE_HOME/bin/oracle:kglComputeHash+0x00000000000d -> 0x00000000128152b0 $ORACLE_HOME/bin/oracle:kglComputeHash0(0x7f0fd3f889a0, 0x7fff3aea4dd0, ...)
| | | | Call 0x0000000012815399 $ORACLE_HOME/bin/oracle:kglComputeHash0+0x0000000000e9 -> 0x00000000127dca20 $ORACLE_HOME/bin/oracle:kggmd5Update(0x7fff3aea4580, 0x7f0fd3e6fe80, ...)
| | | | | Call 0x00000000127dcad5 $ORACLE_HOME/bin/oracle:kggmd5Update+0x0000000000b5 -> 0x0000000006b74060 $ORACLE_HOME/bin/oracle:_intel_fast_memcpy(0x7fff3aea4588, 0x7f0fd3e6fe80, ...)
| | | | | Tailcall 0x0000000006b740bc $ORACLE_HOME/bin/oracle:_intel_fast_memcpy+0x00000000005c -> 0x0000000006b74030 $ORACLE_HOME/bin/oracle:_intel_fast_memcpy.P(0x7fff3aea4588, 0x7f0fd3e6fe80, ...)
| | | | | Tailcall 0x0000000006b74030 $ORACLE_HOME/bin/oracle:_intel_fast_memcpy.P -> 0x0000000006b814e0 $ORACLE_HOME/bin/oracle:__intel_ssse3_rep_memcpy(0x7fff3aea4588, 0x7f0fd3e6fe80, ...)
| | | | | Return 0x0000000006b83cfa $ORACLE_HOME/bin/oracle:__intel_ssse3_rep_memcpy+0x00000000281a returns: 0x7fff3aea4588
| | | | Return 0x00000000127dcae8 $ORACLE_HOME/bin/oracle:kggmd5Update+0x0000000000c8 returns: 0x7fff3aea4588
| | | | Call 0x000000001281545e $ORACLE_HOME/bin/oracle:kglComputeHash0+0x0000000001ae -> 0x00000000127dca20 $ORACLE_HOME/bin/oracle:kggmd5Update(0x7fff3aea4580, 0x12976914, ...)
| | | | | Call 0x00000000127dcad5 $ORACLE_HOME/bin/oracle:kggmd5Update+0x0000000000b5 -> 0x0000000006b74060 $ORACLE_HOME/bin/oracle:_intel_fast_memcpy(0x7fff3aea458f, 0x12976914, ...)
| | | | | Tailcall 0x0000000006b740bc $ORACLE_HOME/bin/oracle:_intel_fast_memcpy+0x00000000005c -> 0x0000000006b74030 $ORACLE_HOME/bin/oracle:_intel_fast_memcpy.P(0x7fff3aea458f, 0x12976914, ...)
| | | | | Tailcall 0x0000000006b74030 $ORACLE_HOME/bin/oracle:_intel_fast_memcpy.P -> 0x0000000006b814e0 $ORACLE_HOME/bin/oracle:__intel_ssse3_rep_memcpy(0x7fff3aea458f, 0x12976914, ...)
| | | | | Return 0x0000000006b83f95 $ORACLE_HOME/bin/oracle:__intel_ssse3_rep_memcpy+0x000000002ab5 returns: 0x7fff3aea458f
| | | | Return 0x00000000127dcae8 $ORACLE_HOME/bin/oracle:kggmd5Update+0x0000000000c8 returns: 0x7fff3aea458f
| | | | Call 0x000000001281546f $ORACLE_HOME/bin/oracle:kglComputeHash0+0x0000000001bf -> 0x00000000127dca20 $ORACLE_HOME/bin/oracle:kggmd5Update(0x7fff3aea4580, 0x7580764c, ...)
| | | | | Call 0x00000000127dcad5 $ORACLE_HOME/bin/oracle:kggmd5Update+0x0000000000b5 -> 0x0000000006b74060 $ORACLE_HOME/bin/oracle:_intel_fast_memcpy(0x7fff3aea4590, 0x7580764c, ...)
| | | | | Tailcall 0x0000000006b740bc $ORACLE_HOME/bin/oracle:_intel_fast_memcpy+0x00000000005c -> 0x0000000006b74030 $ORACLE_HOME/bin/oracle:_intel_fast_memcpy.P(0x7fff3aea4590, 0x7580764c, ...)
| | | | | Tailcall 0x0000000006b74030 $ORACLE_HOME/bin/oracle:_intel_fast_memcpy.P -> 0x0000000006b814e0 $ORACLE_HOME/bin/oracle:__intel_ssse3_rep_memcpy(0x7fff3aea4590, 0x7580764c, ...)
| | | | | Return 0x0000000006b83c86 $ORACLE_HOME/bin/oracle:__intel_ssse3_rep_memcpy+0x0000000027a6 returns: 0x7fff3aea4590
| | | | Return 0x00000000127dcae8 $ORACLE_HOME/bin/oracle:kggmd5Update+0x0000000000c8 returns: 0x7fff3aea4590
| | | | Call 0x0000000012815415 $ORACLE_HOME/bin/oracle:kglComputeHash0+0x000000000165 -> 0x00000000127dca20 $ORACLE_HOME/bin/oracle:kggmd5Update(0x7fff3aea4580, 0x7fff3aea45f0, ...)
| | | | | Call 0x00000000127dcad5 $ORACLE_HOME/bin/oracle:kggmd5Update+0x0000000000b5 -> 0x0000000006b74060 $ORACLE_HOME/bin/oracle:_intel_fast_memcpy(0x7fff3aea4598, 0x7fff3aea45f0, ...)
| | | | | Tailcall 0x0000000006b740bc $ORACLE_HOME/bin/oracle:_intel_fast_memcpy+0x00000000005c -> 0x0000000006b74030 $ORACLE_HOME/bin/oracle:_intel_fast_memcpy.P(0x7fff3aea4598, 0x7fff3aea45f0, ...)
| | | | | Tailcall 0x0000000006b74030 $ORACLE_HOME/bin/oracle:_intel_fast_memcpy.P -> 0x0000000006b814e0 $ORACLE_HOME/bin/oracle:__intel_ssse3_rep_memcpy(0x7fff3aea4598, 0x7fff3aea45f0, ...)
| | | | | Return 0x0000000006b83726 $ORACLE_HOME/bin/oracle:__intel_ssse3_rep_memcpy+0x000000002246 returns: 0x7fff3aea4598
| | | | Return 0x00000000127dcae8 $ORACLE_HOME/bin/oracle:kggmd5Update+0x0000000000c8 returns: 0x7fff3aea4598
| | | | Call 0x0000000012815423 $ORACLE_HOME/bin/oracle:kglComputeHash0+0x000000000173 -> 0x00000000127dc8b0 $ORACLE_HOME/bin/oracle:kggmd5Finish(0x7fff3aea4580, 0, ...)
| | | | | Call 0x00000000127dc927 $ORACLE_HOME/bin/oracle:kggmd5Finish+0x000000000077 -> 0x00000000127dca20 $ORACLE_HOME/bin/oracle:kggmd5Update(0x7fff3aea4580, 0x14aa6460, ...)
| | | | | | Call 0x00000000127dcad5 $ORACLE_HOME/bin/oracle:kggmd5Update+0x0000000000b5 -> 0x0000000006b74060 $ORACLE_HOME/bin/oracle:_intel_fast_memcpy(0x7fff3aea459c, 0x14aa6460, ...)
| | | | | | Tailcall 0x0000000006b740bc $ORACLE_HOME/bin/oracle:_intel_fast_memcpy+0x00000000005c -> 0x0000000006b74030 $ORACLE_HOME/bin/oracle:_intel_fast_memcpy.P(0x7fff3aea459c, 0x14aa6460, ...)
| | | | | | Tailcall 0x0000000006b74030 $ORACLE_HOME/bin/oracle:_intel_fast_memcpy.P -> 0x0000000006b814e0 $ORACLE_HOME/bin/oracle:__intel_ssse3_rep_memcpy(0x7fff3aea459c, 0x14aa6460, ...)
| | | | | | Return 0x0000000006b83e38 $ORACLE_HOME/bin/oracle:__intel_ssse3_rep_memcpy+0x000000002958 returns: 0x7fff3aea459c
| | | | | Return 0x00000000127dcae8 $ORACLE_HOME/bin/oracle:kggmd5Update+0x0000000000c8 returns: 0x7fff3aea459c
| | | | | Call 0x00000000127dc938 $ORACLE_HOME/bin/oracle:kggmd5Finish+0x000000000088 -> 0x00000000127dca20 $ORACLE_HOME/bin/oracle:kggmd5Update(0x7fff3aea4580, 0x7fff3aea4550, ...)
| | | | | | Call 0x00000000127dcaa4 $ORACLE_HOME/bin/oracle:kggmd5Update+0x000000000084 -> 0x0000000006b74060 $ORACLE_HOME/bin/oracle:_intel_fast_memcpy(0x7fff3aea45c0, 0x7fff3aea4550, ...)
| | | | | | Tailcall 0x0000000006b740bc $ORACLE_HOME/bin/oracle:_intel_fast_memcpy+0x00000000005c -> 0x0000000006b74030 $ORACLE_HOME/bin/oracle:_intel_fast_memcpy.P(0x7fff3aea45c0, 0x7fff3aea4550, ...)
| | | | | | Tailcall 0x0000000006b74030 $ORACLE_HOME/bin/oracle:_intel_fast_memcpy.P -> 0x0000000006b814e0 $ORACLE_HOME/bin/oracle:__intel_ssse3_rep_memcpy(0x7fff3aea45c0, 0x7fff3aea4550, ...)
| | | | | | Return 0x0000000006b83c86 $ORACLE_HOME/bin/oracle:__intel_ssse3_rep_memcpy+0x0000000027a6 returns: 0x7fff3aea45c0
| | | | | | Call 0x00000000127dcab1 $ORACLE_HOME/bin/oracle:kggmd5Update+0x000000000091 -> 0x00000000127dcba0 $ORACLE_HOME/bin/oracle:kggmd5Process(0x7fff3aea4a70, 0x7fff3aea4588, ...)
| | | | | | Return 0x00000000127dd68d $ORACLE_HOME/bin/oracle:kggmd5Process+0x000000000aed returns: 0x66ba4229
| | | | | Return 0x00000000127dcae8 $ORACLE_HOME/bin/oracle:kggmd5Update+0x0000000000c8 returns: 0x66ba4229
| | | | Return 0x00000000127dc94a $ORACLE_HOME/bin/oracle:kggmd5Finish+0x00000000009a returns: 0x66ba4229
| | | Return 0x000000001281543b $ORACLE_HOME/bin/oracle:kglComputeHash0+0x00000000018b returns: 0x85b962d8
There are several important observations that can be made about this output:
  • kkxpcre is a C function mapped to dbms_pipe.createpipe through the INTERFACE pragma which is called by dbms_pipe.create_pipe, which is the only function exposed to the public
  • kglComputeHash0 returns that hash value 0x85b962d8 that I am looking for, hence I need to look carefully at what is going on between kkxpcre and kglComputeHash0 as the hash value is somewhere between
  • The call stack is: kkxpcre->kkxpcrep->kglget->kglLock->kglComputeHash->kglComputeHash0, the latter calls kggmdUpdate multiple times, then it calls kggmd5Finish, which calls kggmd5Update twice. The last call to kggmd5Update also invokes kggmd5Process. In terms of Oracle code layers, the code can be split in the following ones:
    KKX(Programmatic interfaces to/from PL/SQL)->KGL(Library Cache)->KGG(Generic Routines)
  • Based on the fact that we call MD5 functions, the underlying alrorithm is used MD5 somehow.
I have also disassembled kglComputeHash0 to find out how exactly kggmd5Update functions are called (this is the first call):
   0x0000000012815365 <+181>:   mov    %rax,-0x58(%rbp)
   0x0000000012815369 <+185>:   movl   $0x67452301,(%rax)
   0x000000001281536f <+191>:   mov    -0x58(%rbp),%rcx
   0x0000000012815373 <+195>:   movl   $0xefcdab89,0x4(%rcx)
   0x000000001281537a <+202>:   mov    -0x58(%rbp),%r8
   0x000000001281537e <+206>:   movl   $0x98badcfe,0x8(%r8)
   0x0000000012815386 <+214>:   mov    -0x58(%rbp),%r9
   0x000000001281538a <+218>:   movl   $0x10325476,0xc(%r9)
   0x0000000012815392 <+226>:   mov    0x10(%r14),%rsi
   0x0000000012815396 <+230>:   mov    (%r14),%edx
   0x0000000012815399 <+233>:   callq  0x127dca20 <kggmd5Update>
All of those constants: 0x67452301, 0xefcdab89, 0x98badcfe, 0x10325476 - are magic initialization constants in the MD5 algorithm.

Since the algorithm is known, in order to calculate a hash value, I need to know the input values to the MD5 functions.
Thus, I setup a few breakpoints in GDB and spent a while reviewing the register values.
Finally, I came up with the following GDB breakpoints:
set pagination off

break kggmd5Update
  commands
    printf "Length: %d\n",$rdx
    x/8xc $rsi
    c
  end

break kglComputeHash
  commands
    c
  end

break kggmd5Process
  commands
    c
  end

break kggmd5Finish
  commands
    c
  end
I attached to the server process through GDB and ran the following command in SQL*Plus:
SQL> var n number
SQL> exec :n:=dbms_pipe.create_pipe('MY_PIPE')
The debugger output showed this (comments are inline):
Breakpoint 5, 0x0000000012815280 in kglComputeHash ()

Breakpoint 4, 0x00000000127dca20 in kggmd5Update ()
Length: 7
0x7f7b9304ffe0: 77 'M'  89 'Y'  95 '_'  80 'P'  73 'I'  80 'P'  69 'E'  0 '\000'
-- MY_PIPE

Breakpoint 4, 0x00000000127dca20 in kggmd5Update ()
Length: 1
0x12976914:     46 '.'  0 '\000'        0 '\000'        0 '\000'        113 'q' 109 'm' 120 'x' 113 'q'
-- "." (just a dot)

Breakpoint 4, 0x00000000127dca20 in kggmd5Update ()
Length: 8
0x7580c61c:     67 'C'  68 'D'  66 'B'  36 '$'  82 'R'  79 'O'  79 'O'  84 'T'
-- CDB$ROOT

Breakpoint 4, 0x00000000127dca20 in kggmd5Update ()
Length: 4
0x7ffd3203e070: 7 '\a'  0 '\000'        0 '\000'        0 '\000'        0 '\000'        0 '\000'        0 '\000'  0 '\000'
-- 0x07000000 or chr(7)||chr(0)||chr(0)||chr(0)

Breakpoint 7, 0x00000000127dc8b0 in kggmd5Finish ()

Breakpoint 4, 0x00000000127dca20 in kggmd5Update ()
Length: 36
0x14aa6460 <kggmd5padding>:     -128 '\200'     0 '\000'        0 '\000'        0 '\000'        0 '\000'        0 '\000'   0 '\000'        0 '\000'

Breakpoint 4, 0x00000000127dca20 in kggmd5Update ()
Length: 8
0x7ffd3203dfd0: -96 '\240'      0 '\000'        0 '\000'        0 '\000'        0 '\000'        0 '\000'        0 '\000'   0 '\000'

Breakpoint 6, 0x00000000127dcba0 in kggmd5Process ()
Let me explain what this output means. In accordance with: System V ABI AMD64, the function parameters passed as follows (page 21):
  • %rdi - first argument to functions
  • %rsi - second argument to functions
  • %rdx - third argument to functions
While I was looking at those registers, I produced a hypothesis that kggmd5Update has the signature similar to the one mentioned in RFC-1321: The MD5 Message-Digest Algorithm:
/* MD5 block update operation. Continues an MD5 message-digest
  operation, processing another message block, and updating the
  context.
 */
void MD5Update (context, input, inputLen)
MD5_CTX *context;                                        /* context */
unsigned char *input;                                /* input block */
unsigned int inputLen;                     /* length of input block */
As such, I was not really interested in the context variable - it holds the address of the context structure.
The second and third parameters, though, should hold the input string and its length, that is what I was getting in my GDB breakpoint (remember, that rsi and rdx are second and third parameters correspondingly):
break kggmd5Update
  commands
    printf "Length: %d\n",$rdx
    x/8xc $rsi
    c
  end
First three calls in the GDB output are self-explanatory: it is a string 'MY_PIPE.CDB$ROOT'. The last call requires a bit of explanation, though: what is 0x07000000? It seems to be the namespace, which is 7 for pipes (X$KGLOB.KGLHDNSP), with 3 trailing zero bytes.
I calculated MD5 hashes based on that formula and got this:
SQL> select dbms_crypto.hash(rawtohex('MY_PIPE1.CDB$ROOT'||chr(7)||chr(0)||chr(0)||chr(0)), 2) md5 from dual;

MD5
--------------------------------
9B74B01BF0191C3841474DDDC15C123A

SQL> select dbms_crypto.hash(rawtohex('MY_PIPE2.CDB$ROOT'||chr(7)||chr(0)||chr(0)||chr(0)), 2) md5 from dual;

MD5
--------------------------------
A68FE5534758A34560080107CE43300B

SQL> select dbms_crypto.hash(rawtohex('MY_PIPE.CDB$ROOT'||chr(7)||chr(0)||chr(0)||chr(0)), 2) md5 from dual;

MD5
--------------------------------
2A65FFCD69F14974563E31DAD862B985
Whereas the actual hashes were these:
SQL> select kglnaobj, kglnahsv, kglnahsh, to_char(kglnahsh, 'fm0xxxxxxx') hex_hash, kglhdnsp from x$kglob where kglnaobj in ('MY_PIPE',  'MY_PIPE1', 'MY_PIPE2');

KGLNAOBJ                       KGLNAHSV                           KGLNAHSH HEX_HASH    KGLHDNSP
------------------------------ -------------------------------- ---------- --------- ----------
MY_PIPE2                       53e58fa645a35847070108600b3043ce  187712462 0b3043ce           7
MY_PIPE1                       1bb0749b381c19f0dd4d47413a125cc1  974281921 3a125cc1           7
MY_PIPE                        cdff652a7449f169da313e5685b962d8 2243519192 85b962d8           7
Then it dawned on me that Oracle uses the same technique for these hashes as it uses for SQL_ID: Function to compute SQL_ID out of SQL_TEXT - it reverses the order of each 4 bytes. Look:
SQL> with pipes(pipe_name) as (
  2    select 'MY_PIPE' from dual union all
  3    select 'MY_PIPE1' from dual union all
  4    select 'MY_PIPE2' from dual
  5  )
  6  select pipe_name,
  7         utl_raw.concat(
  8           utl_raw.reverse(utl_raw.substr(hv, 1, 4)),
  9           utl_raw.reverse(utl_raw.substr(hv, 5, 4)),
 10           utl_raw.reverse(utl_raw.substr(hv, 9, 4)),
 11           utl_raw.reverse(utl_raw.substr(hv, 13, 4))
 12         ) ora_hash_value
 13    from (select pipe_name,
 14                 dbms_crypto.hash(rawtohex(pipe_name||'.CDB$ROOT'||chr(7)||chr(0)||chr(0)||chr(0)), 2) hv
 15            from pipes)
 16   order by pipe_name;

PIPE_NAM ORA_HASH_VALUE
-------- --------------------------------
MY_PIPE  CDFF652A7449F169DA313E5685B962D8
MY_PIPE1 1BB0749B381C19F0DD4D47413A125CC1
MY_PIPE2 53E58FA645A35847070108600B3043CE
These are exactly the values I was looking for!

tl;dr

  • The pipe full hash value can be calculated as below (where ORA_HASH_VALUE is the hash that I calculated based on the research made in this article):
    SQL> select lower(rawtohex(utl_raw.concat(
      2           utl_raw.reverse(utl_raw.substr(hv, 1, 4)),
      3           utl_raw.reverse(utl_raw.substr(hv, 5, 4)),
      4           utl_raw.reverse(utl_raw.substr(hv, 9, 4)),
      5           utl_raw.reverse(utl_raw.substr(hv, 13, 4))
      6         ))) ora_hash_value,
      7         kglnahsv, kglnahsh, hex_hash, kglhdnsp, kglhdnsd, kglnacon, kglnaown, kglnaobj
      8    from (select dbms_crypto.hash(rawtohex(kglnaobj||'.'||kglnacon||chr(kglhdnsp)||chr(0)||chr(0)||chr(0)), 2) hv,
      9                 kglnahsv, kglnahsh, to_char(kglnahsh, 'fm0xxxxxxx') hex_hash,
     10                 kglhdnsp, kglhdnsd, kglnacon, kglnaown, kglnaobj
     11            from x$kglob t
     12           where kglhdnsp = 7)
     13   order by kglnaobj
     14  /
    
    ORA_HASH_VALUE                   KGLNAHSV                           KGLNAHSH HEX_HASH    KGLHDNSP KGLHDNSD KGLNACON KGLNAOWN KGLNAOBJ
    -------------------------------- -------------------------------- ---------- --------- ---------- -------- -------- -------- --------
    cdff652a7449f169da313e5685b962d8 cdff652a7449f169da313e5685b962d8 2243519192 85b962d8           7 PIPE     CDB$ROOT          MY_PIPE
    1bb0749b381c19f0dd4d47413a125cc1 1bb0749b381c19f0dd4d47413a125cc1  974281921 3a125cc1           7 PIPE     CDB$ROOT          MY_PIPE1
    53e58fa645a35847070108600b3043ce 53e58fa645a35847070108600b3043ce  187712462 0b3043ce           7 PIPE     CDB$ROOT          MY_PIPE2
    
    1. We take: "<PIPE_NAME>.<CONTAINER_NAME>chr(7)chr(0)chr(0)chr(0)".
    2. Compute an MD5 hash of it.
    3. Then the order of each 4 bytes is reversed and the final output is assembled.
    4. If you are interested in the numeric hash value, which is X$KGLOB.KGLNAHSH, you need to take last 4 bytes of the full hash value, which is X$KGLOB.KGLNAHSV.
    5. I do not consider the non-CDB architecture due to its deprecation but the general pattern should be applicable to it as well.
  • Due to the fact that v$db_pipes does not expose the hash value, it's a good idea to create an extended version of that view including the hash value, since we now know how to calculate it (legal disclaimer: that's just my opinion). After all, Oracle has provided functions to calculate the SQL_ID. They might provide similar functions to calculate hash values one day.

воскресенье, 14 июля 2019 г.

ORA-04036 Troubleshooting: Error Stack Based Approach

A developer came to me the other day to ask me about an ORA-4036 error he encountered.
The trace file was as follows:
=======================================
PRIVATE MEMORY SUMMARY FOR THIS PROCESS
---------------------------------------
******************************************************
PRIVATE HEAP SUMMARY DUMP
1666 MB total:
  1665 MB commented, 296 KB permanent
   260 KB free (0 KB in empty extents),
    1664 MB,   1 heap:    "session heap   "            64 KB free held
------------------------------------------------------
Summary of subheaps at depth 1
1665 MB total:
  1662 MB commented, 76 KB permanent
  2973 KB free (0 KB in empty extents),
    1664 MB,   7 heaps:   "koh-kghu sessi "            2956 KB free held
------------------------------------------------------
Summary of subheaps at depth 2
1661 MB total:
  1615 MB commented, 15 KB permanent
    46 MB free (0 KB in empty extents),
    1661 MB, 41455 chunks:  "pl/sql vc2                " 46 MB free held

That is quite common and a conclusion can easily be drawn that most memory is allocated to PL/SQL collections.
The relevant incident file contained the following lines:
[TOC00004]
----- Current SQL Statement for this session (sql_id=fr9uqhy2xzj6n) -----
BEGIN pkg.fill_memory; END;
[TOC00005]
----- PL/SQL Stack -----
----- PL/SQL Call Stack -----
  object      line  object
  handle    number  name
0x6a6b4250        43  package body TC.PKG.SMALL_ALLOCATION
0x6a6b4250         8  package body TC.PKG.FILL_MEMORY
0x68f1f108         1  anonymous block
[TOC00005-END]
It can be depicted from that PL/SQL Call Stack that the actual error happened in the SMALL_ALLOCATION procedure. As you might guess, it does not allocate a lot of memory. Therefore, there is just not enough information in the trace file and the corresponding incident file to figure out those PL/SQL units that allocated the most memory. The developer was not very helpful and had no clue where the memory could be allocated from in his own code. Thankfully, he was able to provide the code that reproduced the error.

The goal of this blog post is to provide steps to troubleshoot an ORA-04036 error without modifying the source code.
Initially I tried to troubleshoot this issue dumping Error Stacks for the session running the problem code. I settled on Error Stacks because those included PL/SQL Call Stacks and I do not know any other ways to get them.
Here comes the first challenge: when do I need to gather the Error Stack? I decided to gather it when the V$PROCESS.PGA_USED_MEM goes above a certain value.
A sample script to dump the Error Stack when PGA_USED_MEM goes above 1G is below:
SQL> col paddr new_v paddr
SQL>
SQL> select value from v$diag_info where name = 'Default Trace File';

VALUE
--------------------------------------------------------------------------------
/u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_13014.trc

SQL>
SQL> select '0x'||paddr paddr
  2    from v$session
  3   where sid = sys_context('userenv', 'sid');

PADDR
------------------
0x0000000075558A80

SQL>
SQL> alter session set events -
>   'wait_event["PGA memory operation"] {gt:refn(&paddr., 8, 3728), 0x40000000}{occurence:1,1} trace("pga_used_mem=%\n", refn(&paddr., 8, 3728)) errorstack(1)';
old   1: alter session set events    'wait_event["PGA memory operation"] {gt:refn(&paddr., 8, 3728), 0x40000000}{occurence:1,1} trace("pga_used_mem=%\n", refn(&paddr., 8, 3728)) errorstack(1)'
new   1: alter session set events    'wait_event["PGA memory operation"] {gt:refn(0x0000000075558A80, 8, 3728), 0x40000000}{occurence:1,1} trace("pga_used_mem=%\n", refn(0x0000000075558A80, 8, 3728)) errorstack(1)'

Session altered.
The highlighted line requires a bit of explanation:
alter session set events -
  'wait_event["PGA memory operation"] -
   {gt:refn(0x0000000075558A80, 8, 3728), 0x40000000} -
   {occurence:1,1} -
   trace("pga_used_mem=%\n", refn(0x0000000075558A80, 8, 3728)) -
   errorstack(1)';
  • wait_event["PGA memory operation"] - I would like to execute some actions when the session wait event is PGA memory operation
  • refn(0x0000000075558A80, 8, 3728): refn can be used to peek into a memory location and dereference the value under it. Here is an excerpt from the oradebug doc event action output:
    refn
             - Dereference ptr-to-number: *(ub<numsize>*)(((ub1*)<ptr>)) + <offset>)
    
    I use the refn(v$process.addr, 8, 3728) call where 3728 is the offset of PGA_USED_MEM within the X$KSUPR structure that is behind V$PROCESS:
    SQL> select c.kqfconam, c.kqfcosiz, c.kqfcooff
      2    from x$kqfta t,
      3         x$kqfco c
      4   where t.kqftanam = 'X$KSUPR'
      5     and c.kqfcotab = t.indx
      6     and c.kqfconam = 'KSUPRPUM';
    
    KQFCONAM       KQFCOSIZ     KQFCOOFF
    ---------- ------------ ------------
    KSUPRPUM              8         3728
    
    As you might guess, 8 is the size of the value which is the second parameter in the REFN call.
  • 0x40000000 is 1G in hex.
  • {gt:refn(0x0000000075558A80, 8, 3728), 0x40000000} - that is an event filter. Here is an excerpt from the oradebug doc event filter output:
    gt                   filter to only fire an event when a > b
    
    Hence, I would like to fire my event action only when PGA_USED_MEM is above 1G.
  • {occurence:1,1} I would like to fire it only once to minimize overhead.
  • trace("pga_used_mem=%\n", refn(0x0000000075558A80, 8, 3728)) errorstack(1) - these are the actions that should be executed.
    Firstly, I am tracing the PGA_USED_MEM value. Then I am dumping the Error Stack.

After running this code, I executed the procedure causing ORA-4036 and got the following lines in the trace file:
pga_used_mem=1092512013

*** 2019-07-14T18:22:04.499962+01:00 (PDB(3))
dbkedDefDump(): Starting a non-incident diagnostic dump (flags=0x0, level=1, mask=0x0)
----- Error Stack Dump -----
<error barrier> at 0x7fff83740dd0 placed dbkda.c@296
----- Current SQL Statement for this session (sql_id=fr9uqhy2xzj6n) -----
BEGIN pkg.fill_memory; END;
----- PL/SQL Stack -----
----- PL/SQL Call Stack -----
  object      line  object
  handle    number  name
0x6a6b4250        31  package body TC.PKG.HUGE_ALLOCATION
0x6a6b4250         7  package body TC.PKG.FILL_MEMORY
0x68f1f108         1  anonymous block

Following the Error Stack dump, there was a dump for ORA-4036.
Still, there can be the case that HUGE_ALLOCATION procedure just allocated 100M out of 1G, so that the main shortcoming of this method - its granularity. For instance, I was not able to find out how to setup several Error Stacks triggering at 500M and 1G.
The package that I used in these tests is provided below:
create or replace package pkg
is
  MAX_VC_LEN constant binary_integer := 32767;
  type char_tbl_type is table of varchar2(MAX_VC_LEN);
  v_tbl char_tbl_type := char_tbl_type();
  procedure fill_memory;
  procedure tiny_allocation;
  procedure huge_allocation;
  procedure small_allocation;
end;
/
create or replace package body pkg
is
  procedure fill_memory
  is
  begin
    tiny_allocation;
    huge_allocation;
    small_allocation;
  end fill_memory;

  procedure tiny_allocation
  is
    v_start_size pls_integer := v_tbl.count;
    v_extend_size constant pls_integer := 1000;
  begin
    v_tbl.extend(v_extend_size);
    for i in 1..v_extend_size
    loop
      v_tbl(v_start_size + i) := lpad('x', MAX_VC_LEN, 'x');
    end loop;
  end tiny_allocation;

  procedure huge_allocation
  is
    v_start_size pls_integer := v_tbl.count;
    v_extend_size constant pls_integer := 38500;
  begin
    v_tbl.extend(v_extend_size);
    for i in 1..v_extend_size
    loop
      v_tbl(v_start_size + i) := lpad('x', MAX_VC_LEN, 'x');
    end loop;
  end huge_allocation;

  procedure small_allocation
  is
    v_start_size pls_integer := v_tbl.count;
    v_extend_size constant pls_integer := 3000;
  begin
    v_tbl.extend(v_extend_size);
    for i in 1..v_extend_size
    loop
      v_tbl(v_start_size + i) := lpad('x', MAX_VC_LEN, 'x');
    end loop;
  end small_allocation;
end;
/
I specifically setup those collection values to make the SMALL_ALLOCATION call produce the ORA-4036 error in my 19c instance with PGA_AGGREGATE_LIMIT=2G.

воскресенье, 7 июля 2019 г.

Lateral views and filter predicate pushdown

That's another optimizer issue I came across this week while working with developers on tuning application queries.
Let's create two tables for this demo:
SQL> create table t_parent
  2  as
  3  select level id
  4    from dual
  5    connect by level<=10;

Table created.

SQL>
SQL> alter table t_parent
  2    add constraint t_parent_pk primary key(id);

Table altered.

SQL>
SQL> create table t_child
  2  as
  3  select level parent_id, dummy a, dummy b
  4    from dual
  5    connect by level<=10;

Table created.

SQL>
SQL> alter table t_child
  2    add constraint t_child_parent_fk foreign key(parent_id) references t_parent;

Table altered.

SQL>
SQL> create index t_child_parent_fk_i on t_child(parent_id);

Index created.

The following query was run by the application (it's an oversimplified version of the actual query):
select id,
       (select count(a) from t_child where parent_id = id) a_count,
       (select count(b) from t_child where parent_id = id) b_count
  from t_parent
 where 1 = :need_to_run;
The variable NEED_TO_RUN is to define whether the actual query should be executed. The query was coming from an APEX application.
When the APEX page loads, it sets that NEED_TO_RUN variable to 0 or NULL and fires the query - it is supposed not to return anything.
Only after the user clicks on a certain tab, it leads to setting that NEED_TO_RUN variable to 1 and the query is reexecuted - this time it might return some rows.
Let's see how it works:
SQL> var need_to_run number
SQL>
SQL> select /*+ gather_plan_statistics*/
  2         id,
  3         (select count(a) from t_child where parent_id = id) a_count,
  4         (select count(b) from t_child where parent_id = id) b_count
  5    from t_parent
  6   where 1 = :need_to_run;

no rows selected

SQL>
SQL> select * from table(dbms_xplan.display_cursor( format=> 'allstats last'));

PLAN_TABLE_OUTPUT
-------------------------------------------------------------------------------------------------------------------
SQL_ID  bk2mgzbdury0m, child number 0
-------------------------------------
select /*+ gather_plan_statistics*/        id,        (select count(a)
from t_child where parent_id = id) a_count,        (select count(b)
from t_child where parent_id = id) b_count   from t_parent  where 1 =
:need_to_run

Plan hash value: 2339616900

------------------------------------------------------------------------------------------------------------
| Id  | Operation                            | Name                | Starts | E-Rows | A-Rows |   A-Time   |
------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                     |                     |      1 |        |      0 |00:00:00.01 |
|   1 |  SORT AGGREGATE                      |                     |      0 |      1 |      0 |00:00:00.01 |
|   2 |   TABLE ACCESS BY INDEX ROWID BATCHED| T_CHILD             |      0 |      1 |      0 |00:00:00.01 |
|*  3 |    INDEX RANGE SCAN                  | T_CHILD_PARENT_FK_I |      0 |      1 |      0 |00:00:00.01 |
|   4 |  SORT AGGREGATE                      |                     |      0 |      1 |      0 |00:00:00.01 |
|   5 |   TABLE ACCESS BY INDEX ROWID BATCHED| T_CHILD             |      0 |      1 |      0 |00:00:00.01 |
|*  6 |    INDEX RANGE SCAN                  | T_CHILD_PARENT_FK_I |      0 |      1 |      0 |00:00:00.01 |
|*  7 |  FILTER                              |                     |      1 |        |      0 |00:00:00.01 |
|   8 |   INDEX FULL SCAN                    | T_PARENT_PK         |      0 |     10 |      0 |00:00:00.01 |
------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   3 - access("PARENT_ID"=:B1)
   6 - access("PARENT_ID"=:B1)
   7 - filter(1=:NEED_TO_RUN)


30 rows selected.

Oracle just evaluates the filter condition in line 7 and does not go any further.
The query is in fact accesses T_CHILD table twice using the same access method, so that I suggested instead of querying it twice to query it just once.
The whole query was a little bit complex with several outer joins and a lateral view seemed to be a good fit.
The same query rewritten for using a lateral view is below:
SQL> select /*+ gather_plan_statistics*/p.id,
  2         c.a_count,
  3         c.b_count
  4    from t_parent p,
  5         lateral(
  6           select count(a) a_count,
  7                  count(b) b_count
  8             from t_child
  9            where parent_id = p.id
 10         ) c
 11   where 1 = :need_to_run;

no rows selected

SQL>
SQL> select * from table(dbms_xplan.display_cursor( format=> 'allstats last'));

PLAN_TABLE_OUTPUT
---------------------------------------------------------------------------------------------------------------------------
SQL_ID  g6pqun59pf178, child number 0
-------------------------------------
select /*+ gather_plan_statistics*/p.id,        c.a_count,
c.b_count   from t_parent p,        lateral(          select count(a)
a_count,                 count(b) b_count            from t_child
    where parent_id = p.id        ) c  where 1 = :need_to_run

Plan hash value: 1581593935

-------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                               | Name                | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
-------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                        |                     |      1 |        |      0 |00:00:00.01 |       5 |
|   1 |  NESTED LOOPS                           |                     |      1 |     10 |      0 |00:00:00.01 |       5 |
|   2 |   INDEX FULL SCAN                       | T_PARENT_PK         |      1 |     10 |     10 |00:00:00.01 |       1 |
|   3 |   VIEW                                  | VW_LAT_A18161FF     |     10 |      1 |      0 |00:00:00.01 |       4 |
|*  4 |    FILTER                               |                     |     10 |        |      0 |00:00:00.01 |       4 |
|   5 |     SORT AGGREGATE                      |                     |     10 |      1 |     10 |00:00:00.01 |       4 |
|   6 |      TABLE ACCESS BY INDEX ROWID BATCHED| T_CHILD             |     10 |      1 |     10 |00:00:00.01 |       4 |
|*  7 |       INDEX RANGE SCAN                  | T_CHILD_PARENT_FK_I |     10 |      1 |     10 |00:00:00.01 |       3 |
-------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   4 - filter(1=:NEED_TO_RUN)
   7 - access("PARENT_ID"="P"."ID")


28 rows selected.
There are a few remarkable things happened here:
  • The filter is pushed down to the lateral view
  • Both the T_PARENT_TABLE and T_CHILD table are accessed first, then the filter is evaluated
  • Even when we have that filter in line 4, why bother to run any rowsources beneath it?
In case of my real query, that was a drastic change causing a severe performance impact.

The query with a lateral view was transformed into this:
Final query after transformations:******* UNPARSED QUERY IS *******
SELECT "P"."ID" "ID","VW_LAT_A18161FF"."A_COUNT_0" "A_COUNT","VW_LAT_A18161FF"."B_COUNT_1" "B_COUNT" 
  FROM "TC"."T_PARENT" "P",
       LATERAL( (
         SELECT COUNT("T_CHILD"."A") "A_COUNT_0",COUNT("T_CHILD"."B") "B_COUNT_1" 
           FROM "TC"."T_CHILD" "T_CHILD" 
          WHERE "T_CHILD"."PARENT_ID"="P"."ID"
         HAVING 1=:B1)) "VW_LAT_A18161FF"
Hence, that filter 1 = :NEED_TO_RUN has been pushed down to that lateral view and became the HAVING 1=:B1 condition.
The solution is quite simple. The query has been rewritten like this:
select /*+ gather_plan_statistics*/p.id,
       c.a_count,
       c.b_count
  from t_parent p,
       lateral(
         select count(a) a_count,
                count(b) b_count
           from t_child
          where parent_id = p.id
       )(+) c
 where 1 = :need_to_run;
It has the following execution plan in which the filter predicate is evaluated as early as possible:
----------------------------------------------------------------------------------------------------------------
| Id  | Operation                                | Name                | Starts | E-Rows | A-Rows |   A-Time   |
----------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                         |                     |      1 |        |      0 |00:00:00.01 |
|*  1 |  FILTER                                  |                     |      1 |        |      0 |00:00:00.01 |
|   2 |   MERGE JOIN OUTER                       |                     |      0 |     10 |      0 |00:00:00.01 |
|   3 |    INDEX FULL SCAN                       | T_PARENT_PK         |      0 |     10 |      0 |00:00:00.01 |
|   4 |    BUFFER SORT                           |                     |      0 |      1 |      0 |00:00:00.01 |
|   5 |     VIEW                                 | VW_LAT_A18161FF     |      0 |      1 |      0 |00:00:00.01 |
|   6 |      SORT AGGREGATE                      |                     |      0 |      1 |      0 |00:00:00.01 |
|   7 |       TABLE ACCESS BY INDEX ROWID BATCHED| T_CHILD             |      0 |      1 |      0 |00:00:00.01 |
|*  8 |        INDEX RANGE SCAN                  | T_CHILD_PARENT_FK_I |      0 |      1 |      0 |00:00:00.01 |
----------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   1 - filter(1=:NEED_TO_RUN)
   8 - access("PARENT_ID"="P"."ID")
There is also an option to set _optimizer_filter_pushdown to false, however, we went for the first solution and replaced LATERAL(query) with LATERAL(query)(+).
That's another example when the optimizer gets overly aggressive in rewritting a query, so that in this particular case it outsmarted itself.

четверг, 13 июня 2019 г.

srvctl config database OSDBA and OSOPER groups not defined

I have recently investigated why there are some databases in my environment which are shown with empty OSDBA or OSOPER groups:
$ srvctl config database -d orcl
Database unique name: orcl
Database name: orcl
Oracle home: /u01/app/oracle/product/db_19
Oracle user: oracle
Spfile: +DATA/ORCL/PARAMETERFILE/spfile.270.1010270597
Password file:
Domain:
Start options: open
Stop options: immediate
Database role: PRIMARY
Management policy: AUTOMATIC
Disk Groups: DATA,FRA
Services:
OSDBA group:
OSOPER group:
Database instance: orcl
srvctl is a usual shell script that calls the following:
# JRE Executable and Class File Variables
JRE=${JREDIR}/bin/java
..skip..
# Run srvctl
${JRE} ${JRE_OPTIONS} -DORACLE_HOME=${ORACLE_HOME} -classpath ${CLASSPATH} ${SRVM_PROPERTY_DEFS} oracle.ops.opsctl.OPSCTLDriver "$@"
That's just a Java class call. We call oracle.ops.opsctl.OPSCTLDriver passing command-line arguments. CLASSPATH is defined as follows:
CLASSPATH=${NETCFGJAR}:${LDAPJAR}:${JREJAR}:${SRVMJAR}:${SRVMHASJAR}:${SRVMASMJAR}:\
${EONSJAR}:${SRVCTLJAR}:${GNSJAR}:${ANTLRJAR}:${CLSCEJAR}:${CHACONFIGJAR}:${JDBCJAR}:\
${MAILJAR}:${ACTIVATIONJAR}:${JWCCREDJAR}
Those jar-variables are set in the script so it's trivial to find out all classes that are used there.
I used to use JAD to decompile them but it appears to be not in vogue and not developed anymore.
Thankfully, there are a bunch of free sites that can be used as a replacement. I personally have used this one.
It is usually advised to identify the entry jar first by looking into the jar files so as to figure out where exactly OPSCTLDriver is coming from.
Not surprisingly, it is coming from ${SRVCTLJAR} which is set to ${ORACLE_HOME}/srvm/jlib/srvctl.jar.
OPSCTLDriver calls oracle.ops.opsctl.ConfigAction that does the following:
for (Database db : dblist) {
..skip..
  if ((isUnixSystem) && (!isMgmtDB)) {
    groups = db.getGroups();
    dbaGrp = groups.get("OSDBA") == null ? "" : (String)groups.get("OSDBA");
    operGrp = groups.get("OSOPER") == null ? "" : (String)groups.get("OSOPER");
  }
Hence, the groups I am interested in are from the Database class which is set in the import section: import oracle.cluster.database.Database;
That's just an interface from srvm.jar:
public abstract interface Database
  extends SoftwareModule
{
The actual implementation is this: oracle.cluster.impl.database.DatabaseImpl.
Here are how those groups are determined:
String oracleBin = getOracleHome() + File.separator + "bin";
      Trace.out("Creating OSDBAGRPUtil with path: " + oracleBin);
      OSDBAGRPUtil grpUtil = new OSDBAGRPUtil(oracleBin);
      Map<String, String> groups = grpUtil.getAdminGroups(version());
      

      ResourcePermissionsImpl perm = (ResourcePermissionsImpl)m_crsResource.getPermissions();
      String acl = perm.getAclString();
      Map<String, List<string>> aclMap = splitACL(acl);
      
      List<String> acl_groups = (List)aclMap.get(ResourceType.ACL.GROUP.toString());
      

      String dba = (String)groups.get("SYSDBA");
      String oper = (String)groups.get("SYSOPER");
      if ((!dba.isEmpty()) && (acl_groups.contains(dba.toLowerCase()))) {
        groupMap.put("OSDBA", dba);
      }
      if ((!oper.isEmpty()) && (acl_groups.contains(oper.toLowerCase()))) {
        groupMap.put("OSOPER", oper);
      }
      return groupMap;
Having applied the same technique, it's easy to find out that OSDBAGRPUtil calls ${ORACLE_HOME}/bin/osdbagrp passing either "-d" or "-o" flags depending on what group we are interested in.
In my case, those commands returned dba and oper for OSDBA and OSOPER respectively:
$ osdbagrp -d
dba
$ osdbagrp -o
oper
Hence, this part of the if statement is true: "(!dba.isEmpty())" and the dba group is not set because of: "(acl_groups.contains(dba.toLowerCase()))".
So that is something related to ACLs which is coming from "ResourcePermissionsImpl perm = (ResourcePermissionsImpl)m_crsResource.getPermissions();".
Let's use the crsctl getperm command passing the database resource to it:
$ crsctl getperm resource ora.orcl.db
Name: ora.orcl.db
owner:oracle:rwx,pgrp:asmdba:r-x,other::r--,group:oinstall:r-x,user:oracle:rwx
That looks promising - neither dba nor oper groups are set. I ran the command below to set dba group:
$ crsctl setperm resource ora.orcl.db -u group:dba:r-x
CRS-4995:  The command 'Setperm  resource' is invalid in crsctl. Use srvctl for this command.
$ crsctl setperm resource ora.orcl.db -u group:dba:r-x -unsupported
Well, that is an Oracle Restart environment, so that I added the unsupported flag.
Once it was done, the OSDBA group was properly coming back:
$ srvctl config database -d orcl
Database unique name: orcl
Database name: orcl
Oracle home: /u01/app/oracle/product/db_19
Oracle user: oracle
Spfile: +DATA/ORCL/PARAMETERFILE/spfile.270.1010270597
Password file:
Domain:
Start options: open
Stop options: immediate
Database role: PRIMARY
Management policy: AUTOMATIC
Disk Groups: DATA,FRA
Services:
OSDBA group: dba
OSOPER group:
Database instance: orcl

вторник, 11 июня 2019 г.

A case for DATAFILECOPY FORMAT

I was migrating several databases from AWS EC2 non-Nitro based instances to the Nitro-based ones when I came across one issue with Oracle Recovery Manager (RMAN). This blog post is about it.
The high-level process of the migration was as follows:
  1. Attach a new ASM diskgroup to the host that is to be migrated
  2. Make an initial level 0 copy of the database
  3. Roll forward the copy as many times as needed using an incremental level 1 backup
  4. When it's time to switch to the new server, roll forward the copy once again, switch logfile, backup all archivelogs covering the last backup, dismount the ASM diskgroup, mount it on the new server, and open the database (there are also controlfile and spfile copies as well as some extra steps specific to that environment)
I would rather use a physical standby or Golden Gate than that meticulously designed process I developed, albeit those alternatives were ruled out since they would require additional licenses.
At the end of the day, the final downtime was less than 30 minutes as almost everything was automated using Ansible.

I ran that procedure several times in non-Production instances without any issues, however, I got a missing file when I performed the same steps in the Production instance.
Here is how that happened.
The diskgroup configuration is the following:

DATA - db_create_file_dest
FRA - db_recovery_file_dest
MIGR - the transient ASM diskgroup to keep image copies

Let's setup a test tablespace:
SQL> create tablespace test_ts;

Tablespace created.
Make a copy of it:
RMAN> backup as copy incremental level 0 format '+MIGR' tablespace pdb:test_ts tag migr;

Starting backup at 10.06.2019 21:14:51
using channel ORA_DISK_1
channel ORA_DISK_1: starting datafile copy
input datafile file number=00016 name=+DATA/ORCL/8AAFC31944116B0CE0554A7F9DE2B2FD/DATAFILE/test_ts.276.1010610875
output file name=+MIGR/ORCL/8AAFC31944116B0CE0554A7F9DE2B2FD/DATAFILE/test_ts.256.1010610893 tag=MIGR RECID=6 STAMP=1010610895
channel ORA_DISK_1: datafile copy complete, elapsed time: 00:00:07
Finished backup at 10.06.2019 21:14:59
Then add a datafile to that tablespace:
SQL> alter tablespace test_ts add datafile;

Tablespace altered.
The final backup/recover block:
RMAN> run {
  backup incremental level 1 format '+MIGR' for recover of copy with tag migr tablespace pdb:test_ts;
  recover copy of tablespace pdb:test_ts with tag migr;
}2> 3> 4>

Starting backup at 10.06.2019 21:16:42
using channel ORA_DISK_1
no parent backup or copy of datafile 17 found
channel ORA_DISK_1: starting incremental level 1 datafile backup set
channel ORA_DISK_1: specifying datafile(s) in backup set
input datafile file number=00016 name=+DATA/ORCL/8AAFC31944116B0CE0554A7F9DE2B2FD/DATAFILE/test_ts.276.1010610875
channel ORA_DISK_1: starting piece 1 at 10.06.2019 21:16:42
channel ORA_DISK_1: finished piece 1 at 10.06.2019 21:16:43
piece handle=+MIGR/ORCL/8AAFC31944116B0CE0554A7F9DE2B2FD/BACKUPSET/2019_06_10/nnndn1_migr_0.258.1010611003 tag=MIGR comment=NONE
channel ORA_DISK_1: backup set complete, elapsed time: 00:00:01
channel ORA_DISK_1: starting datafile copy
input datafile file number=00017 name=+DATA/ORCL/8AAFC31944116B0CE0554A7F9DE2B2FD/DATAFILE/test_ts.277.1010610945
output file name=+FRA/ORCL/8AAFC31944116B0CE0554A7F9DE2B2FD/DATAFILE/test_ts.265.1010611003 tag=MIGR RECID=7 STAMP=1010611006
channel ORA_DISK_1: datafile copy complete, elapsed time: 00:00:03
Finished backup at 10.06.2019 21:16:46
Despite the fact that the format was set to '+MIGR', the copy of the new added datafile was put to the FRA:
RMAN> list copy tag migr;

specification does not match any control file copy in the repository
specification does not match any archived log in the repository
List of Datafile Copies
=======================

Key     File S Completion Time     Ckp SCN    Ckp Time            Sparse
------- ---- - ------------------- ---------- ------------------- ------
8       16   A 10.06.2019 21:16:47 1468031    10.06.2019 21:16:42 NO
        Name: +MIGR/ORCL/8AAFC31944116B0CE0554A7F9DE2B2FD/DATAFILE/test_ts.256.1010610893
        Tag: MIGR
        Container ID: 3, PDB Name: PDB

7       17   A 10.06.2019 21:16:46 1468032    10.06.2019 21:16:43 NO
        Name: +FRA/ORCL/8AAFC31944116B0CE0554A7F9DE2B2FD/DATAFILE/test_ts.265.1010611003
        Tag: MIGR
        Container ID: 3, PDB Name: PDB
That is pretty much the same issue that I encountered while doing a test migration of that multi-terabyte database in the Production system - a few datafiles have been added between the initial level 0 and the subsequent level 1 copies.
It is the case when the DATAFILECOPY FORMAT clause can be used:
RMAN> run {
  backup incremental level 1 
    format '+MIGR' for recover of copy with tag migr 
    datafilecopy format '+MIGR'
    tablespace pdb:test_ts;
  recover copy of tablespace pdb:test_ts with tag migr;
}2> 3> 4>

Starting backup at 10.06.2019 21:21:57
using channel ORA_DISK_1
no parent backup or copy of datafile 19 found
channel ORA_DISK_1: starting incremental level 1 datafile backup set
channel ORA_DISK_1: specifying datafile(s) in backup set
input datafile file number=00018 name=+DATA/ORCL/8AAFC31944116B0CE0554A7F9DE2B2FD/DATAFILE/test_ts.277.1010611243
channel ORA_DISK_1: starting piece 1 at 10.06.2019 21:21:57
channel ORA_DISK_1: finished piece 1 at 10.06.2019 21:21:58
piece handle=+MIGR/ORCL/8AAFC31944116B0CE0554A7F9DE2B2FD/BACKUPSET/2019_06_10/nnndn1_migr_0.259.1010611317 tag=MIGR comment=NONE
channel ORA_DISK_1: backup set complete, elapsed time: 00:00:01
channel ORA_DISK_1: starting datafile copy
input datafile file number=00019 name=+DATA/ORCL/8AAFC31944116B0CE0554A7F9DE2B2FD/DATAFILE/test_ts.276.1010611299
output file name=+MIGR/ORCL/8AAFC31944116B0CE0554A7F9DE2B2FD/DATAFILE/test_ts.260.1010611319 tag=MIGR RECID=10 STAMP=1010611321
channel ORA_DISK_1: datafile copy complete, elapsed time: 00:00:03
Finished backup at 10.06.2019 21:22:01
That's just another flexibility that Oracle provides. If you think about it, it makes complete sense - image copies and backupsets can be stored separately.
Another way to specify location for image copies in that case is an explicit channel configuration:
RMAN> run {
  # allocate as many channels as needed
  allocate channel c1 device type disk format '+MIGR';
  backup incremental level 1 for recover of copy with tag migr tablespace pdb:test_ts;
  recover copy of tablespace pdb:test_ts with tag migr;
}2> 3> 4> 5>

released channel: ORA_DISK_1
allocated channel: c1
channel c1: SID=94 device type=DISK

Starting backup at 10.06.2019 21:33:43
no parent backup or copy of datafile 21 found
channel c1: starting incremental level 1 datafile backup set
channel c1: specifying datafile(s) in backup set
input datafile file number=00020 name=+DATA/ORCL/8AAFC31944116B0CE0554A7F9DE2B2FD/DATAFILE/test_ts.276.1010611951
channel c1: starting piece 1 at 10.06.2019 21:33:44
channel c1: finished piece 1 at 10.06.2019 21:33:45
piece handle=+MIGR/ORCL/8AAFC31944116B0CE0554A7F9DE2B2FD/BACKUPSET/2019_06_10/nnndn1_migr_0.256.1010612025 tag=MIGR comment=NONE
channel c1: backup set complete, elapsed time: 00:00:01
channel c1: starting datafile copy
input datafile file number=00021 name=+DATA/ORCL/8AAFC31944116B0CE0554A7F9DE2B2FD/DATAFILE/test_ts.277.1010612011
output file name=+MIGR/ORCL/8AAFC31944116B0CE0554A7F9DE2B2FD/DATAFILE/test_ts.261.1010612025 tag=MIGR RECID=13 STAMP=1010612028
channel c1: datafile copy complete, elapsed time: 00:00:03
Finished backup at 10.06.2019 21:33:48

среда, 5 июня 2019 г.

ORA-01031 select V$RESTORE_POINT in PL/SQL

It is a well known fact that V$RESTORE_POINT requires special handling, namely the SELECT_CATALOG_ROLE should be granted to a low-privileged user trying to access this view.
I had several PL/SQL units working with V$RESTORE_POINT in a 12.1 database. Those units were owned by a user that has SELECT_CATALOG_ROLE.
Once I upgraded the database to 12.2, those units stopped working and I started getting an infamous ORA-1031 error.
This blog post is about how I fixed that issue for definer rights program units.

Here is a simple test case demonstrating the initial ORA-1031 error:
SYS@CDB$ROOT> create restore point rp_test;

Restore point created.

SYS@CDB$ROOT> alter session set container=pdb;

Session altered.

SYS@PDB> grant connect, create procedure to tc identified by tc;

Grant succeeded.

SYS@PDB> grant read on v_$restore_point to tc;

Grant succeeded.

SYS@PDB> conn tc/tc@localhost/pdb
Connected.
TC@PDB>
TC@PDB> create or replace procedure p_test
  2  is
  3  begin
  4    for test_rec in (
  5      select *
  6        from v$restore_point)
  7    loop
  8      dbms_output.put_line(test_rec.name);
  9    end loop;
 10  end;
 11  /

Procedure created.

TC@PDB>
TC@PDB> set serverout on
TC@PDB>
TC@PDB> exec p_test
BEGIN p_test; END;

*
ERROR at line 1:
ORA-01031: insufficient privileges
ORA-06512: at "TC.P_TEST", line 4
ORA-06512: at line 1

Despite the fact that the user TC does have the READ privilege on V_$RESTORE_POINT, it still is not able to access it.
Till 12.2 it was enough to grant SELECT_CATALOG_ROLE to the owner of a program unit to avoid the error:
SYS@PDB> grant select_catalog_role to tc;

Grant succeeded.

SYS@PDB> conn tc/tc@localhost/pdb
Connected.
TC@PDB>
TC@PDB> set serverout on
TC@PDB>
TC@PDB> exec p_test
RP_TEST

PL/SQL procedure successfully completed.
It is not the case anymore in 12.2 and subsequent versions which I tested: 18c and 19c.
The output from 19c is below:
SYS@PDB> grant select_catalog_role to tc;

Grant succeeded.

SYS@PDB> conn tc/tc@localhost/pdb
Connected.
SYS@PDB>
TC@PDB> set serverout on
TC@PDB>
TC@PDB> exec p_test
BEGIN p_test; END;

*
ERROR at line 1:
ORA-01031: insufficient privileges
ORA-06512: at "TC.P_TEST", line 5
ORA-06512: at "TC.P_TEST", line 5
ORA-06512: at line 1
BTW, the line 'ORA-06512: at "TC.P_TEST", line 5' is reported twice, and 19c shows a slightly different errorstack than 12.1.
The following solution works in 12.2 on:
SYS@PDB> grant select_catalog_role to procedure tc.p_test;

Grant succeeded.

SYS@PDB>
SYS@PDB> conn tc/tc@localhost/pdb
Connected.
TC@PDB>
TC@PDB> set serverout on
TC@PDB>
TC@PDB> exec p_test
RP_TEST

PL/SQL procedure successfully completed.
The need for having the SELECT_CATALOG_ROLE granted to the user in 12.1 does not make much sense as roles do not work in named PL/SQL definer rights program units. I am not talking about roles granted to PL/SQL units here.
Therefore, the "new" behavior requiring the role to be granted to PL/SQL units appears to be more proper and logical.

While working on this issue, I was tinkering with gdb a little bit in an attempt to find an explanation to that SELECT_CATALOG_ROLE requirement - that role is not coming from V$-views as it was said in the blogpost which I referred before.
It turns out that role is used in Oracle code:
(gdb) disassemble kccxrsp
Dump of assembler code for function kccxrsp:
   0x000000000a225740 <+0>:     xchg   %ax,%ax
   0x000000000a225742 <+2>:     push   %rbp
   0x000000000a225743 <+3>:     mov    %rsp,%rbp
   0x000000000a225746 <+6>:     sub    $0x60,%rsp
   0x000000000a22574a <+10>:    mov    %rbx,-0x58(%rbp)
   0x000000000a22574e <+14>:    mov    %rdx,%rbx
..skip..
   0x000000000a2257e5 <+165>:   mov    $0xdda7b48,%edi
   0x000000000a2257ea <+170>:   mov    $0x13,%esi
   0x000000000a2257ef <+175>:   callq  0x859bd90 <kzsrol>
..skip..
---Type <return> to continue, or q <return> to quit---q
Quit
(gdb) x/s 0xdda7b48
0xdda7b48:      "SELECT_CATALOG_ROLE"
GV$RESTORE_POINT is based on x$kccrsp and x$kccnrs. The former is seems to be accessed through the kccxrsp function.
kccxrsp calls kzsrol to perform extra security checks and passes SELECT_CATALOG_ROLE to it.

TL;DR: V$-views are really special views (i.e. no read consistency) and V$RESTORE_POINT has its own little peculiarity among them.
Not only does it require to have the SELECT_CATALOG_ROLE granted to a non-administrative user but also the definer rights PL/SQL unit owned by such a user should have that role granted as well.

суббота, 1 июня 2019 г.

OEM Target Version not updated after applying RU patch

After applying the 12.2.0.1.190416 Release Update (RU) patch, I noticed that the target version had not been updated:

I searched through My Oracle Support (MOS) and found a few similar issues where it was recommended to refresh the configuration of the host in question.
Thus, I performed the refresh operation for both the host configuration and the database configuration, yet the version was still the old one.

Here are the targets that are registered on the problem host:
[oraagent@oracle-sandbox bin]$ ./emctl config agent listtargets
Oracle Enterprise Manager Cloud Control 13c Release 3
Copyright (c) 1996, 2018 Oracle Corporation.  All rights reserved.
[oracle-sandbox.domain, host]
[oracle-sandbox.domain:3872, oracle_emd]
[+ASM_oracle-sandbox.domain, osm_instance]
[OraDB12Home1_2_oracle-sandbox.domain_3696, oracle_home]
[OraHome1Grid_1_oracle-sandbox.domain_6710, oracle_home]
[agent13c1_3_oracle-sandbox.domain_5948, oracle_home]
[has_oracle-sandbox.domain, has]
[OraGI12Home1_4_oracle-sandbox.domain_67, oracle_home]
[BOXCDB_oracle-sandbox.domain, oracle_database]
[BOXCDB_oracle-sandbox.domain_CDB$ROOT, oracle_pdb]
[BOXCDB_oracle-sandbox.domain_BOXPDB, oracle_pdb]
I ran the following command after which the issue was resolved:
[oraagent@oracle-sandbox bin]$ ./emctl reload agent dynamicproperties BOXCDB_oracle-sandbox.domain:oracle_database
Oracle Enterprise Manager Cloud Control 13c Release 3
Copyright (c) 1996, 2018 Oracle Corporation.  All rights reserved.
---------------------------------------------------------------
EMD recompute dynprops completed successfully
The correct version finally appeared on the database page: