'active txn count during cleanout', part I

I was going to write a blog post about some peculiar side effects you can get into with the delayed block cleanout when running parallel DML but soon discovered that the entry became so big that I've decided to split it up into a series of more manageable posts.

For a good background on various themes of block cleanout check out Clean it up by Jonathan Lewis.

Active transactions, consistent reads and table scans

First I'm going to show you some interesting observations about what happens when you're trying to select from the block which has an outstanding open transaction in it. Let's create a test table with one row and update it leaving the transaction open. I'm using 11.2.0.4 here:

SQL> create table test (n number, m number);
 
Table created
 
SQL> insert into test values (1, 1);
 
1 row inserted
 
SQL> commit;
 
Commit complete

SQL> select dbms_rowid.rowid_relative_fno(rowid) file#,
  2    dbms_rowid.rowid_block_number(rowid) block#
  3    from test;
 
     FILE#     BLOCK#
---------- ----------
         4        134
 
SQL> update test set n=n;
 
1 row updated

If we were to look into the buffer headers view (x$bh) we would find the following:

     FILE#     DBABLK STATE CR_SCN_BAS CR_SCN_WRP
---------- ---------- ----- ---------- ----------
         4        134 xcur           0          0
         4        134 cur       595913          0

Now lets select from this table in a different session while checking couple stats at the same time:

NAME                                                                  VALUE
---------------------------------------------------------------- ----------
immediate (CR) block cleanout applications                                0
active txn count during cleanout                                          0
 
SQL> select  * from test;
 
         N          M
---------- ----------
         1          1
 
NAME                                                                  VALUE
---------------------------------------------------------------- ----------
immediate (CR) block cleanout applications                                1
active txn count during cleanout                                          1
 
SQL> select  * from test;
 
         N          M
---------- ----------
         1          1
 
NAME                                                                  VALUE
---------------------------------------------------------------- ----------
immediate (CR) block cleanout applications                                2
active txn count during cleanout                                          2
 
SQL> select  * from test;
 
         N          M
---------- ----------
         1          1

NAME                                                                  VALUE
---------------------------------------------------------------- ----------
immediate (CR) block cleanout applications                                3
active txn count during cleanout                                          3

The first thing worth mentioning is that both immediate (CR) block cleanout applications and active txn count during cleanout statistics increment every time we execute the select. Immediate (CR) block cleanout applications indicates that the session is performing delayed block cleanout while doing the consistent read (CR). Active txn count during cleanout indicates how many currently active transactions the cleanout process encountered in each block. From one perspective this makes sense -- when our select reads the block and discovers that there are open transactions it may not know whether these transactions are currently active or the block indeed requires a cleanout. However, something interesting happened when we look into x$bh again:

     FILE#     DBABLK STATE CR_SCN_BAS CR_SCN_WRP
---------- ---------- ----- ---------- ----------
         4        134 xcur           0          0
         4        134 cur       595913          0
         4        134 cur       595922          0
         4        134 cur       595926          0
         4        134 cur       595940          0

Clearly each subsequent select generated a new consistent read version of the block at a different SCN. Indeed, if we were to dump the table's block before and after the last select here is what we would find:

Before:

buffer tsn: 4 rdba: 0x01000086 (4/134)
scn: 0x0000.000917d6 seq: 0x01 flg: 0x04 tail: 0x17d60601
frmt: 0x02 chkval: 0xf347 type: 0x06=trans data
...
Block header dump:  0x01000086
 Object id on Block? Y
 seg/obj: 0x113da  csc: 0x00.917d6  itc: 2  flg: E  typ: 1 - DATA
     brn: 0  bdba: 0x1000080 ver: 0x01 opc: 0
     inc: 0  exflg: 0

 Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x0002.01f.00000242  0x00c0c19c.0035.19  C---    0  scn 0x0000.00090e7e
0x02   0x0008.00b.00000241  0x00c00989.0039.38  ----    1  fsc 0x0000.00000000

After:

buffer tsn: 4 rdba: 0x01000086 (4/134)
scn: 0x0000.000917e4 seq: 0x01 flg: 0x04 tail: 0x17e40601
frmt: 0x02 chkval: 0xf375 type: 0x06=trans data
...
Block header dump:  0x01000086
 Object id on Block? Y
 seg/obj: 0x113da  csc: 0x00.917e4  itc: 2  flg: E  typ: 1 - DATA
     brn: 0  bdba: 0x1000080 ver: 0x01 opc: 0
     inc: 0  exflg: 0

 Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x0002.01f.00000242  0x00c0c19c.0035.19  C---    0  scn 0x0000.00090e7e
0x02   0x0008.00b.00000241  0x00c00989.0039.38  ----    1  fsc 0x0000.00000000

Notice that cleanout scn (cscn) is different and the block got updated with the same scn as well. As you probably have guessed by now, each select generates a block cleanout redo record too:

REDO RECORD - Thread:1 RBA: 0x00000c.00035faf.0010 LEN: 0x006c VLD: 0x05
SCN: 0x0000.000917e4 SUBSCN:  1 01/28/2014 00:16:44
(LWN RBA: 0x00000c.00035faf.0010 LEN: 0001 NST: 0001 SCN: 0x0000.000917e4)
CHANGE #1 TYP:0 CLS:1 AFN:4 DBA:0x01000086 OBJ:70618 SCN:0x0000.000917d6 SEQ:1 OP:4.1 ENC:0 RBL:0
Block cleanout record, scn:  0x0000.000917e4 ver: 0x01 opt: 0x01, entries follow...

From another perspective why even bother doing any of this? It almost looks like the cleanout code is moving along in tiding up the block, updates scn plus cscn and then discovers that there is really nothing to cleanup because the other transaction is still active. But it did changes to the current version of the block by now which then results in proliferation of CR copies from the selects and increased redo generation from the (essentially) shell block cleanout records. There is going to be more interesting details worth mentioning in the next post.

crsd.bin core dumps

Core dump issues sometimes can be notoriously difficult to troubleshoot. I've got a call this morning from one of my customers saying that after a power outage Grid Infrastructure is not able to fully come up on some nodes on their Exadata cluster. After further examining the situation it turned out that crsd.bin binary is simply core dumping upon start up.

Troubleshooting Grid Infrastructure startup issues when nothing is core dumping sometimes could be a chore so what could be more fun when it's not able to fully start due to a major daemon core dumping?

One of the useful things to do when a binary core dumps is to get a stack trace to see which function raised the exception (you can examine the core file the gdb, for example, in order to do that). Let's see what the stack trace holds for us:

Core was generated by `/u01/app/11.2.0.3/grid/bin/crsd.bin reboot'.
Program terminated with signal 6, Aborted.
#0  0x0000003ea3e30285 in raise () from /lib64/libc.so.6
(gdb) bt
#0  0x0000003ea3e30285 in raise () from /lib64/libc.so.6
#1  0x0000003ea3e31d30 in abort () from /lib64/libc.so.6
#2  0x0000003ea56bed94 in __gnu_cxx::__verbose_terminate_handler() ()
   from /usr/lib64/libstdc++.so.6
#3  0x0000003ea56bce46 in ?? () from /usr/lib64/libstdc++.so.6
#4  0x0000003ea56bce73 in std::terminate() () from /usr/lib64/libstdc++.so.6
#5  0x0000003ea56bcef9 in __cxa_rethrow () from /usr/lib64/libstdc++.so.6
#6  0x0000000000df8672 in Acl::Acl (this=0x4556d440, domain=..., resource=...,
    aclString=..., useOcr=true, $U7=,
    $U8=, $U9=,
    $V0=, $V1=) at acl.cpp:120
#6  0x0000000000df8672 in Acl::Acl (this=0x4556d440, domain=..., resource=...,
    aclString=..., useOcr=true, $U7=,
    $U8=, $U9=,
    $V0=, $V1=) at acl.cpp:120
#7  0x0000000000df879c in Acl::_ZN3CAA3AclC1ERKSsS2_S2_b (this=0x4556d440,
    $U7=, $U8=,
    $U9=, $V0=,
    $V1=)
#8  0x0000000000a4d81e in SrvResource::initUserId (this=0x7f15803d7550,
    $1=) at clsAgfwSrvResource.cpp:204

We can see that the source of the exception is in the Acl::Acl which is then propagated through the standard libraries. Moreover, function SrvResource::initUserId appears in the stack trace as well, which makes you wonder whether there is some issue with some of the resource's Access Control List, in particular with it's user id setting.

Armed with that knowledge you can now sift through the Grind Infrastructure logs in a much more effective way because these logs are notoriously big and "chatty" (I think my worst nightmare is when the database alert log will become like GI alert log thereby making it much less useful). And there we have it:

Exception: ACL entry creation failed for: owner:ggate:rwx

Turned out the nodes which were core dumping were recently added to the cluster and the user ggate, which is the owner of the GoldenGate resource, simply did not exist on these nodes. Apparently that was enough to cause crsd.bin core dumps. Yikes!