berxblog: 2017

2017-12-15

don't look to close, it might change the results

We all know, if we try to look to close on some details, the results we get may change from the original observation.
This is also sometimes true for Oracle Trace events:
During analyses of a query with XMLTYPE which fails with ORA-12850 (in a 4 node RAC DB), Oracle Support asked for some trace files. the query itself is something like

SELECT XMLTYPE(
CURSOR( SELECT ...
FROM gv$lock l
JOIN gv$session s
... ) )

and the original error is

ORA-19202: Error occurred in XML processing 
ORA-12850: Could not allocate slaves on all specified instances: 4 needed, 1 allocated 
ORA-06512: at "SYS.XMLTYPE", line 343 
ORA-06512: at line 1

But with a specific trace event:

alter session set events 'trace [SQL_Compiler.*] disk highest';

the error changes to

ORA-19202: Error occurred in XML processing 
ORA-00918: column ambiguously defined 
ORA-06512: at "SYS.XMLTYPE", line 343 
ORA-06512: at line 1

As there are 2 different Errors now Oracle Support has more to analyze 😂

2017-12-14

oratop with TFA 12.2.1.3.0

We are facing an issue where Oracles Trace File Analyzer creates high load on some servers.
During the discussion with Oracle Support I installed the latest version of TFA which is 12.2.1.3.0 right now.
With this version, oratop - which oracle calls

oratop is a utility similar to the unix OS utility top which gives a overview of database performance and can be used in combination with top to get a more complete overview of system performance

did not work as expected but quit with

Oratop successfully tested. 
ohome /appl/oracle/product/rdbms_12102_Oct17BPJa 
ouser oracle 
osid TTT0091 
db_running 1 
running_local 1 
oversion 12.1.0.2.0

After another SR , it was clear to be Bug 27103547 - ORATOP DOES NOT WORK IN TFA 12.2.1.3.0
The solution is simple:
In $GRID_HOME/tfa/`hostname`/tfa_home/bin/common/tfactlshare.pm
edit somewhere around line 9010

# Farm called 
if ( $tcase ) { 
if ( length $ohome && length $ouser && length $osid && 
$db_running && length $oversion ) { 
print "Oratop successfully tested.\n"; 
print "ohome $ohome\n"; 
print "ouser $ouser\n"; 
print "osid $osid\n"; 
print "db_running $db_running\n"; 
print "running_local $running_local\n"; 
print "oversion $oversion\n"; 
# exit 0; 
} else { 
print "Oratop failed.\n"; 
print "ohome $ohome\n"; 
print "ouser $ouser\n"; 
print "osid $osid\n"; 
print "db_running $db_running\n"; 
print "running_local $running_local\n"; 
print "oversion $oversion\n"; 
exit 1; 
} 
} # end if $tcase

So the exit 0; is not executed anymore.

Now oratop works as expected - even with TFA 12.2.1.3.0

Update: 18-Dec-2017
A new version 12.2.1.3.1 is available - this Bug is fixed there.
thank you Sandesh Rao for informing me.

@martinberx the oratop issue which was in TFA 12.1.2.3.0 has been fixed in 12.1.2.3.1 which was just released , thanks for pointing it out
— Sandesh Rao (@sandeshr) December 17, 2017

2017-12-12

manage ORACLE_HOMEs and patches in a centralised way

Managing many ORACLE_HOMEs in a complex environment can be tricky, especially when questions about their patches & bugs or comparisons should be done.

It's required to understand the different types of patches available. This can be (according to the documentation & my interpretation). Especially the differences between SYSTEM PATCH (in our case only Bundle Patches), COMPOSITE and SINGLETON patches, and BUGs - of course.

A way to handle all the information is to use the details provided by opatch and the patches, store them in some tables and afterwards query them.

For ORACLE_HOME related information, all the information required can be generated by a simple opatch command:

${ORACLE_HOME}/OPatch/opatch lsinventory -bugs_fixed -xml ${bugs_fixed_file}

This then needs to be uploaded into a table. For this purpose we use a SQLcl inspired by Kris Rices SQLcl examples.

${SQLCL} "${conn_string}" << EOF
script
var fileName="${bugs_fixed_file}";
var theBlob = conn.createBlob();
var outBlob = theBlob.setBinaryStream(1);
var path = java.nio.file.FileSystems.getDefault().getPath(fileName);
theBlob.setBytes(1, java.nio.file.Files.readAllBytes(path));
// ctx.write("length: " + theBlob.length());
var HashMap = Java.type("java.util.HashMap");
bind_map = new HashMap();
bind_map.put("theblob", theBlob);
bind_map.put("name", "${name}");
bind_map.put("version", "${version}");
try {
var retval = util.execute("insert into oh_registry (name, version, bugs_fixed) values (:name, :version, blob2clob(:theblob))", bind_map);
// ctx.write(retval + "\n");
}
catch (e) {
ctx.write("\n\n ERROR:" + e + "\n\n");
}
sqlcl.setStmt("select name, version, dbms_lob.getlength(bugs_fixed) from oh_registry where name='${name}'");
sqlcl.run();
/
commit;
exit
EOF

(blob2clob is just a wrapper for DBMS_LOB.CONVERTTOCLOB)

With this information from several ORACLE_HOMEs, fancy stuff is possible with simple xml queries:

Which patches are different between 2 ORACLE_HOMEs?

select
    sub1.patchid as OH1
    , sub2.patchid as OH2
    , NVL2(sub1.patchid
         , NVL(sub1.patchdescription , 
                 (SELECT md.DESCRIPTION 
                  FROM ORACLE_PATCHES_MANUALDESC md
                  WHERE md.patchnum = sub1.patchid) 
              )
         , NVL(sub2.patchdescription ,
                 (SELECT md.DESCRIPTION 
                  FROM ORACLE_PATCHES_MANUALDESC md
                  WHERE md.patchnum = sub2.patchid)          
               )
          )
      description
from
    (select
        xml1.patchid
        , nvl(xml1.patchdescription, (select description from oracle_patches where patchnum=xml1.patchid)) patchdescription
    from
       oh_registry
       , XMLTable(
                '/InventoryInstance/patches/patch' PASSING xmltype(bugs_fixed) 
                COLUMNS  
                        patchID number path 'patchID'
                        , patchDescription varchar2(64) path 'patchDescription'
                ) xml1
    where 
        name='${home1}') sub1
    full outer join
    (select
        xml2.patchid 
        , nvl(xml2.patchdescription, (select description from oracle_patches where patchnum=xml2.patchid)) patchdescription
    from
       oh_registry
       , XMLTable(
                '/InventoryInstance/patches/patch' PASSING xmltype(bugs_fixed) 
                COLUMNS  
                        patchID number path 'patchID'
                        , patchDescription varchar2(64) path 'patchDescription'
                ) xml2
    where 
        name='${home2}') sub2 on (sub1.patchid = sub2.patchid)
where
    (sub1.patchid is null
    or sub2.patchid is null) or ( ${full_precidate} != 0)
order by
    sub1.patchid
    , sub2.patchid
;

which can show results like

rdbms_12102_Oct17BPJa_beta2 rdbms_12102_Oct17BPJa_beta5 DESCRIPTION
--------------------------- --------------------------- -------------------------------------------------------------------------------------
                   19450139                             KN LNX PERFORMANCE ISSUE WHEN RUNNING GATHER TABLE STATS WITH INCREMENTAL STATS
                                               21385422 12C DB ORA-46264 DURING DBMS_AUDIT_MGMT OPERATION
                                               26988490 MERGE REQUEST ON TOP OF DATABASE BP 12.1.0.2.171017 FOR BUGS 19450139 20807398

So between these 2 ORACLE_HOMEs, 1 patch disappeared and 2 new came in.

A similar query can provide the delta of BUGs:
select

sub1.bug as OH1
    , sub2.bug as OH2
    , case 
        when sub1.bug is null then sub2.description
        else sub1.description
    end description
from
    (select
        xml1.bug 
        , xml1.description 
    from
       oh_registry
       , XMLTable(
                '//bug' PASSING xmltype(bugs_fixed)
                COLUMNS
                        bug number path '@id'
                        , description varchar(64) path 'description'
                ) xml1
    where
        name='${home1}') sub1
    full outer join
    (select
        xml2.bug 
        , xml2.description
    from
       oh_registry
       , XMLTable(
                '//bug' PASSING xmltype(bugs_fixed)
                COLUMNS
                        bug number path '@id'
                        , description varchar(64) path 'description'
                ) xml2
    where
        name='${home2}') sub2 on (sub1.bug = sub2.bug)
where
    ( sub1.bug is null
    or sub2.bug is null ) or ( ${full_precidate} != 0)
order by
    sub1.bug
    , sub2.bug
;

rdbms_12102_Oct17BPJa_beta2 rdbms_12102_Oct17BPJa_beta5 DESCRIPTION
--------------------------- --------------------------- ----------------------------------------------------------------
                                               20807398 ORA-00600 [KGL-HASH-COLLISION] WITH FIX TO BUG 20465582
                                               21385422 12C DB ORA-46264 DURING DBMS_AUDIT_MGMT OPERATION
                                               21529241 DBMS_STATS ORA-06502  PL/SQL  NUMERIC OR VALUE ERROR

This shows quite good the difference between BUGs and Patches.

Also to query all ORACLE_HOMEs which contain a specific BUG is possible:
Inthis case, I'm querying for Bug:22652097

WITH dim_1
AS (SELECT name as OH_NAME, 
                xml1.patchid,
                Nvl(xml1.patchdescription, (SELECT description
                                            FROM   oracle_patches_manualdesc
                                            WHERE  patchnum = xml1.patchid))
                   patchdescription,
                bugs
         FROM   oh_registry,
                XMLTABLE( '/InventoryInstance/patches/patch' passing xmltype(bugs_fixed)
                COLUMNS
                    patchid NUMBER path 'patchID'
                  , bugs xmltype path 'bugs'
                  , patchdescription
                VARCHAR2(64) path 'patchDescription' ) xml1
--         WHERE  name = 'ebs_rdbms_12102_Apr17b_1'
         )
SELECT dim_1.OH_NAME as NAME,
       patchid,
       patchdescription,
       bug,
       bugdescription
FROM   dim_1,
       XMLTABLE( '//bug' passing bugs COLUMNS
           bug NUMBER path '@id'
         , bugdescription VARCHAR(64) path 'description' 
               )
WHERE bug= to_number('${bug}')
ORDER  BY dim_1.OH_NAME,
          patchid,
          bug;

NAME                                PATCHID PATCHDESCRIPTION                                                        BUG BUGDESCRIPTION
-------------------------------- ---------- ---------------------------------------------------------------- ---------- ----------------------------------------------------------------
rdbms_12102_Apr17BPJa              25929584 MERGE REQUEST ON TOP OF DATABASE BP 12.1.0.2.170418 FOR BUGS 186   22652097 PROVIDE SEPARATE CONTROLS FOR ADAPTIVE PLANS AND ADAPTIVE STATIS
rdbms_12102_Apr17BPJb              25929584 MERGE REQUEST ON TOP OF DATABASE BP 12.1.0.2.170418 FOR BUGS 186   22652097 PROVIDE SEPARATE CONTROLS FOR ADAPTIVE PLANS AND ADAPTIVE STATIS
rdbms_12102_Apr17BPJc              25929584 MERGE REQUEST ON TOP OF DATABASE BP 12.1.0.2.170418 FOR BUGS 186   22652097 PROVIDE SEPARATE CONTROLS FOR ADAPTIVE PLANS AND ADAPTIVE STATIS
rdbms_12102_Apr17BPJd              25929584 MERGE REQUEST ON TOP OF DATABASE BP 12.1.0.2.170418 FOR BUGS 186   22652097 PROVIDE SEPARATE CONTROLS FOR ADAPTIVE PLANS AND ADAPTIVE STATIS
rdbms_12102_Aug17BPJa_beta2        27011973 MERGE REQUEST ON TOP OF DATABASE BP 12.1.0.2.170718 FOR BUGS 261   22652097 PROVIDE SEPARATE CONTROLS FOR ADAPTIVE PLANS AND ADAPTIVE STATIS
rdbms_12102_Jan17BPJa              25635590 MERGE REQUEST ON TOP OF DATABASE BP 12.1.0.2.170117 FOR BUGS 189   22652097 PROVIDE SEPARATE CONTROLS FOR ADAPTIVE PLANS AND ADAPTIVE STATIS
rdbms_12102_Oct17BPJa              26717470 Database Bundle Patch : 12.1.0.2.171017 (26717470)                 22652097 PROVIDE SEPARATE CONTROLS FOR ADAPTIVE PLANS AND ADAPTIVE STATIS
rdbms_12102_Oct17BPJa_beta1        26717470 Database Bundle Patch : 12.1.0.2.171017 (26717470)                 22652097 PROVIDE SEPARATE CONTROLS FOR ADAPTIVE PLANS AND ADAPTIVE STATIS
rdbms_12102_Oct17BPJa_beta2        26717470 Database Bundle Patch : 12.1.0.2.171017 (26717470)                 22652097 PROVIDE SEPARATE CONTROLS FOR ADAPTIVE PLANS AND ADAPTIVE STATIS
rdbms_12102_Oct17BPJa_beta3        26717470 Database Bundle Patch : 12.1.0.2.171017 (26717470)                 22652097 PROVIDE SEPARATE CONTROLS FOR ADAPTIVE PLANS AND ADAPTIVE STATIS
rdbms_12102_Oct17BPJa_beta4        26717470 Database Bundle Patch : 12.1.0.2.171017 (26717470)                 22652097 PROVIDE SEPARATE CONTROLS FOR ADAPTIVE PLANS AND ADAPTIVE STATIS
rdbms_12102_Oct17BPJa_beta5        26717470 Database Bundle Patch : 12.1.0.2.171017 (26717470)                 22652097 PROVIDE SEPARATE CONTROLS FOR ADAPTIVE PLANS AND ADAPTIVE STATIS
rdbms_12102_Oct17BPJb_beta1        26717470 Database Bundle Patch : 12.1.0.2.171017 (26717470)                 22652097 PROVIDE SEPARATE CONTROLS FOR ADAPTIVE PLANS AND ADAPTIVE STATIS

So a lot of useful queries can be done when information regarding ORACLE_HOMEs is stored in a RDBMS.

Similar things can be done for patches as well. patches contain a lot of useful information. Those are stored in inventory.xml, actions.xml and if they exist in bundle.xml, and any README* files. If these files are loaded into tables similar to the method shown above, they can be used to generate even more insight. Some care must be taken as SYSTEM and COMPOSITE patches contain other patches which must be processed as well (together with their dependencies). We normalized the xml files to several tables during the load for easier/faster queries.

It's possible to search for all patches which will fix a given bug:

BUGNUM DESCRIPTION
---------- -----------------------------------------------------------------------------
  22652097 PROVIDE SEPARATE CONTROLS FOR ADAPTIVE PLANS AND ADAPTIVE STATISTICS FEATURES

single patches

  PATCHNUM DESCRIPTION
---------- ------------------------------------------------------------------------------
  26886035 MERGE REQUEST ON TOP OF DATABASE BP 12.1.0.2.170418 FOR BUGS 21156276 22652097
  27011973 MERGE REQUEST ON TOP OF DATABASE BP 12.1.0.2.170718 FOR BUGS 26165305 19450139
  25304579
  26022324
  26166813
  26816088
  25929584 MERGE REQUEST ON TOP OF DATABASE BP 12.1.0.2.170418 FOR BUGS 18650065 18961555
  26165162
  22652097 PROVIDE SEPARATE CONTROLS FOR ADAPTIVE PLANS AND ADAPTIVE STATISTICS FEATURES
  25635590 MERGE REQUEST ON TOP OF DATABASE BP 12.1.0.2.170117 FOR BUGS 18961555 19450139
  26165461
  26757390
  26898071 MERGE REQUEST ON TOP OF DATABASE BP 12.1.0.2.170718 FOR BUGS 21156276 22652097
  26717470 Database Bundle Patch : 12.1.0.2.171017 (26717470)

14 rows selected.

composite patches

  PATCHNUM DESCRIPTION
---------- ----------------------------------------------------------------------------------
  26717470 Database Bundle Patch : 12.1.0.2.171017 (26717470)

bundle patches

  PATCHNUM DESCRIPTION
---------- ----------------------------------------------------------------------------------
  26635880 OracleÂ® Database Patch 26635880 - Database Proactive Bundle Patch 12.1.0.2.171017

Or the difference between 2 merge patches:

26886035_BUGS 25929584_BUGS BUG_DESCRIPTION
------------- ------------- -------------------------------------------------------------------------------
     21156276               ORA-00600   [QESDPSIGERROR], [ADAPTIVE JOIN RESOLUTION FAILED], [394]
                   18961555 STATIC PL/SQL BASELINE REPRODUCTION BROKEN BY FIX 18020394
                   19450139 KN LNX PERFORMANCE ISSUE WHEN RUNNING GATHER TABLE STATS WITH INCREMENTAL STATS
                   20508819 WRONG RESULTS OR ORA-7445 WHEN _OPTIMIZER_AGGR_GROUPBY_ELIM=TRUE
                   20807398 ORA-00600 [KGL-HASH-COLLISION] WITH FIX TO BUG 20465582
                   21529241 DBMS_STATS ORA-06502  PL/SQL  NUMERIC OR VALUE ERROR
                   21826068 WRONG RESULTS STILL WHEN _OPTIMIZER_AGGR_GROUPBY_ELIM=TRUE
                   22324460 ORA-600 QKSANGETTEXTSTR 1 AND CORRUPT PLANS WITH SPM
                   22913528 WRONG RESULTS WITH PARTITION PRUNING AND MIN/MAX SCANS
                   18650065 WRONG RESULTS ON QUERY WITH SUBQUERY USING OR EXISTS
                   21171382 AUTO DOP COMPUTES A HIGH DOP UNNECESSARILY

Using the available information about ORACLE_HOMEs and Patches together it's even possible to check if a patch can be applied to an ORACLE_HOME, or where they conflict.

...
conflicts on:

ACTION          ARGUMENTS
--------------- ----------------------------------------------------------------------------------------------------
copy            %ORACLE_HOME%/rdbms/admin/prvtbpw.plb

1 row selected.

conflict details:

PATCHDESC                                          ACTION          ARGUMENTS
-------------------------------------------------- --------------- --------------------------------------------------
20925154 - ORA-39126  WORKER UNEXPECTED FATAL ERRO copy            %ORACLE_HOME%/rdbms/admin/prvtbpw.plb
25740076 -                                         copy            %ORACLE_HOME%/rdbms/admin/prvtbpw.plb

2 rows selected.

In this case the Patch:25740076 with

<oracle .rdbms.dbscripts="" opt_req="O" version="12.1.0.2.0">
  <copy file_name="rdbms/admin/prvtbpm.plb" name="prvtbpm.plb" path="%ORACLE_HOME%/rdbms/admin">
  <copy file_name="rdbms/admin/prvtkupc.plb" name="prvtkupc.plb" path="%ORACLE_HOME%/rdbms/admin">
  <copy file_name="rdbms/admin/prvtbpw.plb" name="prvtbpw.plb" path="%ORACLE_HOME%/rdbms/admin">

conflicts with the ORACLE_HOME which contains
<patchid>25740076</patchid>
whith

<patchactions>
  <patchaction><archive name="libserver12.a" object_name="lib/libserver12.a/kupv.o" path="%ORACLE_HOME%/lib"></archive></patchaction>
  <patchaction><make change_dir="%ORACLE_HOME%/rdbms/lib" make_file="ins_rdbms.mk" make_target="ioracle"></make></patchaction>
  <patchaction><copy file_name="rdbms/admin/prvtbpm.plb" name="prvtbpm.plb" path="%ORACLE_HOME%/rdbms/admin"></copy></patchaction>
  <patchaction><copy file_name="rdbms/admin/prvtkupc.plb" name="prvtkupc.plb" path="%ORACLE_HOME%/rdbms/admin"></copy></patchaction>
  <patchaction><copy file_name="rdbms/admin/prvtbpw.plb" name="prvtbpw.plb" path="%ORACLE_HOME%/rdbms/admin"></copy></patchaction>
...

My Oracle Support comes to the same conclusion in it's tool to check for conflicts.

2017-12-06

I went to a conference - and all I can post about is this picture

I was on DOAG and UKOUG conferences this year and hold some presentations there.
Of course I attended even more presentations and learned a lot of new things.
But I did not blog about it for some good reasons:
The presentations I attended are done already. Which means the presenters did a lot of research and put it all into great presentations and abstracts - so why should I create a weak copy of their work?

Beside these presentations I had a lot of talks to several people. We shared war stories, created concepts for new solutions over a beer and also discussed hidden, or at least not so well known "features". I took notes for some of these discussions for later analysis.
But these notes contains this important reminder: !no Blog!
That's there for a good reason: We shared information in mutual private trust. There are often details about things (ideas, concepts, tools, features, ...) which are not complete yet, or never will be. Or only applicable in this very specific situation, but not used without proper care. Or many other good reasons.
And this is the real value for going to conferences! These discussions beside and after the presentations.
It's NOT the hunt for hidden information in general, but the possibility to get open minded conversations off the records.
It was great to meet all the old and new friends. I love this community where you are seen as a valuable member based on your contribution; questions are always accepted and not marked as "dumb" or "silly". And even (and special) in disagreement the discussions are on highest technical level, but never personal.

Writing that I have to thank DOAG and UKOUG for their great work running these conferences.

2017-11-16

Backup stalled due to ASM rebalance stuck

I hit an issue where a full backup took much longer than normal.
In this case there was no alarm yet as no threshold was reached. But I worked on the DB for some other reason and out of a habit I most often start a ASH viewer whenever I work on a system - even if I only check data, it's worth to have an eye on the system.
In this case I saw some top session in waits 'ASM file metadata operation' & 'KSV master wait'.
It wasn't my query session (so I didn't break anything) but some RMAN worker processes.

That's worth to investigate. After some research (Google & MetaLink) I saw some links between ASM rebalance and 'ASM file metadata operation'.

Checking the ASM instance, there was really a ASM rebalance ongoing, but no progress (no change in v$asm_operation.SOFAR over some minutes). It was initiated the other evening by a colleague which added a disk to the DG. I agree with Kevin this is a bad habit, but in this environment it's not enough pain (and multiple teams involved) to re-work all the processes. The RBAL process was waiting in 'enq: RB - contention'.

As ASM rebalance can be stopped or re-started wit othe rpriority easily, I gave this a chance and run ALTER DISKGROUP dg REBALANCE POWER 2 - the power is not important here, ony to stop the current (stalled) rebalance and issue another.

The ASH viewer immediately showed the uncommon waits disappear and in RMAN logs I saw ordinary progress immediately.

To be honest I did not much analysis here, so it might be worth to do better, but in this case it was sufficient and the issue solved even before there was an alarm regarding the blocked backup.

Once again, ASH (and my curiosity) helped solving the issue.

2017-10-26

prelink makes instance unusable

I spent a recent night hunting an issue which was non trivial to detect.
On a 4 node cluster 2 nodes got Linux patches and were rebooted. This was done after 10pm for minimal business impact. (The application is written by Oracle - so it's not fully TAF aware).
The DBs started fine, all services were available.
At 3:50 in the morning I got a call some processes show strange errors.
As I connected to the Server, the Instance shows running proceses. But I could not connect to the instance:
With proper environment variables, the errors were:

sqlplus system/xxx

SQL*Plus: Release 11.2.0.4.0 Production on Thu Oct 19 03:58:52 2017

Copyright (c) 1982, 2013, Oracle.  All rights reserved.

Enter password:
ERROR:
ORA-01034: ORACLE not available
ORA-27123: unable to attach to shared memory segment
Linux-x86_64 Error: 22: Invalid argument
Additional information: 25
Additional information: 323780623
Additional information: -1610612736
Process ID: 0
Session ID: 0 Serial number: 0

Enter user-name:
ERROR:
ORA-01017: invalid username/password; logon denied

and

sqlplus system/xxx

SQL*Plus: Release 11.2.0.4.0 Production on Thu Oct 19 03:59:33 2017

Copyright (c) 1982, 2013, Oracle.  All rights reserved.

Connected to an idle instance.

SQL>

So it seems it's related to shared memory.

First checks showed there are enough hugepages configured and available, ipcs lists them correct.

in alert.log I found entries like

Thu Oct 19 03:34:41 2017
Process q003 died, see its trace file
Thu Oct 19 03:35:40 2017
Process W000 died, see its trace file
Process W000 died, see its trace file
Process W000 died, see its trace file
Thu Oct 19 03:35:52 2017
Process W000 died, see its trace file
Process W000 died, see its trace file
Thu Oct 19 03:35:57 2017
Process m000 died, see its trace file
Process W000 died, see its trace file
Thu Oct 19 03:36:04 2017

and

Thu Oct 19 04:00:02 2017
Process J000 died, see its trace file
kkjcre1p: unable to spawn jobq slave process
Errors in file /...diag.../trace/INST_NAME_cjq0_61788.trc:
Process W000 died, see its trace file
Thu Oct 19 04:00:04 2017

this contains

*** 2017-10-19 04:00:02.536
*** SESSION ID:(631.21) 2017-10-19 04:00:02.536
*** CLIENT ID:() 2017-10-19 04:00:02.536
*** SERVICE NAME:(SYS$BACKGROUND) 2017-10-19 04:00:02.536
*** MODULE NAME:() 2017-10-19 04:00:02.536
*** ACTION NAME:() 2017-10-19 04:00:02.536

Process J000 is dead (pid=119122 req_ver=453 cur_ver=453 state=KSOSP_SPAWNED).

*** 2017-10-19 04:00:09.545
Process J000 is dead (pid=119264 req_ver=456 cur_ver=456 state=KSOSP_SPAWNED).

*** 2017-10-19 04:00:12.539
Process J000 is dead (pid=119278 req_ver=25 cur_ver=25 state=KSOSP_SPAWNED).

With all this information (and some search effort) the best match I found is Connected to an idle instance, while database instance is running (Process J000 died, see its trace file kkjcre1p: unable to spawn jobq slave process ) (Doc ID 1578491.1).

But why is prelink doing such bad things?

Some information about the memory structure of the running instance and new started process, together with a good old strace will shed some light:

first of all the /proc/<pid>/maps content of the running smon (any process attached to the instance would do):

00400000-0bdbb000 r-xp 00000000 fd:ac 4730278                            /O_H/bin/oracle
0bfba000-0c1b4000 rw-p 0b9ba000 fd:ac 4730278                            /O_H/bin/oracle
0c1b4000-0c20b000 rw-p 00000000 00:00 0
0c89b000-0c8fe000 rw-p 00000000 00:00 0                                  [heap]
60000000-a0000000 rw-s 00000000 00:0c 323747854                          /SYSV00000000 (deleted)
a0000000-3260000000 rw-s 00000000 00:0c 323780623                        /SYSV00000000 (deleted)
3260000000-3260200000 rw-s 00000000 00:0c 323813392                      /SYSV6a4ae364 (deleted)
3c2ee00000-3c2ee01000 r-xp 00000000 fd:01 1625                           /lib64/libaio.so.1.0.1
3c2ee01000-3c2f000000 ---p 00001000 fd:01 1625                           /lib64/libaio.so.1.0.1
3c2f000000-3c2f001000 rw-p 00000000 fd:01 1625                           /lib64/libaio.so.1.0.1
7feb42051000-7feb42061000 rw-p 00000000 00:05 4603                       /dev/zero
7feb42061000-7feb42071000 rw-p 00000000 00:05 4603                       /dev/zero
7feb42071000-7feb42081000 rw-p 00000000 00:05 4603                       /dev/zero
7feb42081000-7feb42091000 rw-p 00000000 00:05 4603                       /dev/zero
7feb42091000-7feb420a1000 rw-p 00000000 00:05 4603                       /dev/zero
...
7feb42750000-7feb42751000 rw-p 0007f000 00:05 4603                       /dev/zero
7feb42751000-7feb42891000 rw-p 00000000 00:00 0
7feb42891000-7feb4289d000 r-xp 00000000 fd:01 3650                       /lib64/libnss_files-2.12.so
7feb4289d000-7feb42a9c000 ---p 0000c000 fd:01 3650                       /lib64/libnss_files-2.12.so
7feb42a9c000-7feb42a9d000 r--p 0000b000 fd:01 3650                       /lib64/libnss_files-2.12.so
7feb42a9d000-7feb42a9e000 rw-p 0000c000 fd:01 3650                       /lib64/libnss_files-2.12.so
7feb42a9e000-7feb42b9e000 rw-p 00000000 00:00 0
7feb42b9e000-7feb42ba8000 r-xp 00000000 fd:a4 2880                       /usr/lib64/libnuma.so.1 (deleted)
7feb42ba8000-7feb42da8000 ---p 0000a000 fd:a4 2880                       /usr/lib64/libnuma.so.1 (deleted)
7feb42da8000-7feb42da9000 rw-p 0000a000 fd:a4 2880                       /usr/lib64/libnuma.so.1 (deleted)
7feb42da9000-7feb42f33000 r-xp 00000000 fd:01 118                        /lib64/libc-2.12.so (deleted)
7feb42f33000-7feb43133000 ---p 0018a000 fd:01 118                        /lib64/libc-2.12.so (deleted)
7feb43133000-7feb43137000 r--p 0018a000 fd:01 118                        /lib64/libc-2.12.so (deleted)
7feb43137000-7feb43139000 rw-p 0018e000 fd:01 118                        /lib64/libc-2.12.so (deleted)
7feb43139000-7feb4313d000 rw-p 00000000 00:00 0
7feb4313d000-7feb43153000 r-xp 00000000 fd:01 3646                       /lib64/libnsl-2.12.so (deleted)
7feb43153000-7feb43352000 ---p 00016000 fd:01 3646                       /lib64/libnsl-2.12.so (deleted)
7feb43352000-7feb43353000 r--p 00015000 fd:01 3646                       /lib64/libnsl-2.12.so (deleted)
7feb43353000-7feb43354000 rw-p 00016000 fd:01 3646                       /lib64/libnsl-2.12.so (deleted)
7feb43354000-7feb43356000 rw-p 00000000 00:00 0
7feb43356000-7feb4336d000 r-xp 00000000 fd:01 142                        /lib64/libpthread-2.12.so.#prelink#.O7kB09 (deleted)
7feb4336d000-7feb4356d000 ---p 00017000 fd:01 142                        /lib64/libpthread-2.12.so.#prelink#.O7kB09 (deleted)
7feb4356d000-7feb4356e000 r--p 00017000 fd:01 142                        /lib64/libpthread-2.12.so.#prelink#.O7kB09 (deleted)
7feb4356e000-7feb4356f000 rw-p 00018000 fd:01 142                        /lib64/libpthread-2.12.so.#prelink#.O7kB09 (deleted)
7feb4356f000-7feb43573000 rw-p 00000000 00:00 0
7feb43573000-7feb435f6000 r-xp 00000000 fd:01 3644                       /lib64/libm-2.12.so (deleted)
7feb435f6000-7feb437f5000 ---p 00083000 fd:01 3644                       /lib64/libm-2.12.so (deleted)
7feb437f5000-7feb437f6000 r--p 00082000 fd:01 3644                       /lib64/libm-2.12.so (deleted)
7feb437f6000-7feb437f7000 rw-p 00083000 fd:01 3644                       /lib64/libm-2.12.so (deleted)
7feb437f7000-7feb437f9000 r-xp 00000000 fd:01 3642                       /lib64/libdl-2.12.so (deleted)
7feb437f9000-7feb439f9000 ---p 00002000 fd:01 3642                       /lib64/libdl-2.12.so (deleted)
7feb439f9000-7feb439fa000 r--p 00002000 fd:01 3642                       /lib64/libdl-2.12.so (deleted)
7feb439fa000-7feb439fb000 rw-p 00003000 fd:01 3642                       /lib64/libdl-2.12.so (deleted)
7feb439fb000-7feb43a07000 r-xp 00000000 fd:ac 4593158                    /O_H/lib/libocrutl11.so
7feb43a07000-7feb43b06000 ---p 0000c000 fd:ac 4593158                    /O_H/lib/libocrutl11.so
...

Here we see at the top 3 shared memory segments (bold) - the one with id 323780623 will be of special interest.

As I try to attach a new process (sqlplus) to the instance, strace shows me

...
9134  shmat(323780623, 0xa0000000, 0)   = -1 EINVAL (Invalid argument)
9134  shmctl(323780623, IPC_STAT, 0x7fffc48703c8) = 0
9134  shmat(323780623, 0, 0)            = 0x2aaaaac00000
9134  shmdt(0x2aaaaac00000)             = 0
9134  uname({sys="Linux", node="av3l291p", ...}) = 0
9134  times({tms_utime=0, tms_stime=1, tms_cutime=0, tms_cstime=0}) = 432291212
9134  times({tms_utime=0, tms_stime=1, tms_cutime=0, tms_cstime=0}) = 432291212
9134  stat("/O_H/rdbms/log", {st_mode=S_IFDIR|0755, st_size=503808, ...}) = 0
9134  stat("/O_H/rdbms/log/ebssip021_ora_9134.trc", 0x7fffc486c810) = -1 ENOENT (No such file or directory)
9134  open("/O_H/rdbms/log/ebssip021_ora_9134.trc", O_WRONLY|O_CREAT|O_TRUNC, 0660) = 4
9134  lstat("/O_H/rdbms/log/ebssip021_ora_9134.trc", {st_mode=S_IFREG|0640, st_size=0, ...}) = 0
...

Its a nice habit to write a trace file in such a situation. Oracle Trace Files are often great. In this case, it contains (beside many other things) information about the shared memory segments:

*********************** Dumping ipcs output ********************
------ Shared Memory Segments --------
key        shmid      owner      perms      bytes      nattch     status
0x00000000 260440066  oracle     600        4096       0
0x00000000 260472835  oracle     600        4096       0
0x2bac4398 260505604  oracle     600        24576      95
0x00000000 320405509  oracle     640        67108864   85
0x00000000 320438278  oracle     640        10670309376 85
0xa6f47cf8 320471047  oracle     640        2097152    85
0x00000000 323485704  oracle     640        33554432   94
0x00000000 323551241  oracle     640        16777216   146
0x00000000 323584010  oracle     640        1056964608 146
0x8015f33c 323616779  oracle     640        2097152    146
0x00000000 323649548  oracle     640        2113929216 94
0xb047bb08 323682317  oracle     640        2097152    94
0x00000000 323747854  oracle     640        1073741824 76
0x00000000 323780623  oracle     640        213674622976 75
0x6a4ae364 323813392  oracle     640        2097152    76
0x00000000 326828049  oracle     640        50331648   128
0x00000000 326860818  oracle     640        5318377472 128
0x3df7a980 326893587  oracle     640        2097152    128

and the process map:

******************* Dumping process map ****************
00400000-0bdbb000 r-xp 00000000 fd:ac 4730278                            /O_H/bin/oracle
0bfba000-0c1b4000 rw-p 0b9ba000 fd:ac 4730278                            /O_H/bin/oracle
0c1b4000-0c20b000 rw-p 00000000 00:00 0
0d2c4000-0d309000 rw-p 00000000 00:00 0                                  [heap]
60000000-a0000000 rw-s 00000000 00:0c 323747854                          /SYSV00000000 (deleted)
324e000000-324e020000 r-xp 00000000 fd:01 119                            /lib64/ld-2.12.so
324e220000-324e221000 r--p 00020000 fd:01 119                            /lib64/ld-2.12.so
324e221000-324e222000 rw-p 00021000 fd:01 119                            /lib64/ld-2.12.so
324e222000-324e223000 rw-p 00000000 00:00 0
324e400000-324e58a000 r-xp 00000000 fd:01 120                            /lib64/libc-2.12.so
324e58a000-324e78a000 ---p 0018a000 fd:01 120                            /lib64/libc-2.12.so
324e78a000-324e78e000 r--p 0018a000 fd:01 120                            /lib64/libc-2.12.so
324e78e000-324e790000 rw-p 0018e000 fd:01 120                            /lib64/libc-2.12.so

My sqlplus process tried to attach the shared memory segment 323780623 at address 0xa0000000 ( shmat(323780623, 0xa0000000, 0) ) but it failed (-1 EINVAL).
The reason for the failure is the alredy linked library /lib64/ld-2.12.so at address 324e000000 (and some others as well).

But why is it so important to have this shared memory at the specific address? As strace shows, it was able to map it on some other address without any issue ( shmat(323780623, 0, 0 = 0x2aaaaac00000 ).

But Oracle requires the shared memory segments mapped at the same address for all processes of an instance. It uses the direct memory address to access all it's memory structures. E.g. when querying saddr or paddr from v$session, these are the real addresses.
So if you map a shared memory process with your own binary at the same address, you can access the memory structures direct using these addresses.

So what bad did prelink make to the system?

The Linux server was patched at about midnight. A lot of new RPMs were installed and the server rebooted. Clusterware started and fine and int started all instances.
But sometime close to 03:34 prelink was started, it did a lot of work with all the new libraries and created a new /etc/prelink.cache file, so all new started binaries loads their libraries according to this file. In my case the shared memory segment could not be loaded at the specific address anymore - so the Instance was still healthy, but no new process could attach anymore.

My solution was to kill the instance and restart it.
Generally I recommend to disable prelink on Linux hosts running Oracle database.

Oracle also recommends doing so.

2017-10-20

Oracle Bundle Patches - release timing

I have to invest much of my time (at work) into Oracle and managing of patches, merge patches, patch requests and similar things.
At this task I identified an interesting (but probably worthless) information:
It seems a Bundle Patch (for Version 12.1) is defined approximately (at least) 40 days before it's released.
At least the 12.1.0.1.171017 BP follows this rule.

I have requested a lot of one-off and merge patches on top of 12.1.0.2.171017BP over the last days. In the picture you can see 2 requests with date of 18^th and 20^th Oct. Others with Requested "Not Specified" are delivered already.
But there are some in the list with 7th and 8th of September. As my "Associated Request" ID is increasingit's shown I requested them in order (and without time machine) - all of them were requests based on Database Proactive Bundle Patch 12.1.0.2.171017 Patch 26635880 which was nit GA before 10^th of October.
So a valid conclusion is: The content of Patch 26635880 was defined before 7^th of September.
At about 7th and 8th September many merge request were raised internally - by whatever mechanism they were chosen.
Many of them were available when Patch 26635880 was available - others still pending. (Maybe they wait for more customers to request - like a kind of vote - but that's pure guessing).
Is this information of any value?
At a first sign no. As a customer still we don't know which patches will be fixed in an upcoming BundlePatch/RCU.
But if we are really demanding, we can start approx. 40 days early to force Support / Presales / Account Manager to make sure a patch for a given bug is available within next PSU/RCU.

So, if it's really urgent, don't wait until mid of January 2018 - start in early December to request your merge patches on top of 12.1.0.2.18.01.16 (or 12.2 ...)

2017-09-25

digging into mrskew internals

I'm spending some time working with Method-Rs trace file analyzer mrskew.
As the requirements are beyond simple analyses (here an example about the uncommon things to do) I'm consulting the documentation and all available information in detail. After many readings I started to take this part of the documentation serious:

EXPRESSIONS
Wherever mrskew requires an expression (such as in --group and --where option arguments), you may use any valid Perl expression consisting of:
Perl operators
Operators such as or xor and not , = ?: || && | ^ < > <= >= lt gt le ge == != <=> eq ne cmp + - . * / % =~ !~ ! ~ ** ...and so on. See http://perldoc.perl.org/perlop.html for details.
Perl builtin functions
Functions such as lc uc s/// int join split sprintf substr ...and so on. See http://perldoc.perl.org/perlfunc.html for details.
File::Basename functions
The functions fileparse, basename, and dirname. See http://perldoc.perl.org/File/Basename.html for details.
mrskew expression variables
Any of the variable names described in "EXPRESSION VARIABLES".
For more information about Perl expression syntax, see http://perldoc.perl.org/perl.html#Tutorials.

It's written "any valid Perl expression" and Jeff showed me a very clever example on StackOverflow. But that's not the end, it raised some questions:
Where in the work of mrskew is the specific expression executed?
What's the order of these expressions?
Can they interact?

A small testcase can answer some of these questions.

I used a very simple artificial tracefile:

Oracle Release 11.2
PARSING IN CURSOR #1 len=20 dep=0 uid=7 oct=6 lid=7 tim=2 hv=1 ad='1' sqlid='A'
insert
END OF STMT

EXEC #1:c=1,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=3,tim=100
EXEC #1:c=2,e=4,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=6,tim=400

a small rc file (rc file is used here to store parameters whenever it's boring to type them on command line):

--init='
 my $trace_string = "trace: ";
 my $test_string;
    sub xfrm {
   if ($_[0] eq "where0") {
     $test_string = $test_string . "x";}
   if ($_[0] eq "where1") {
     $test_string =~ s/x/u/g ;}  
      $trace_string = $trace_string . "$_[0]" . "{ $test_string } " . "[$line] -> ";
   
   if ($_[0] eq "group") {
     return $trace_string;}
  else {
    return $_[1]}
    }
'

this uses the --init parameter:

--init=stringExecute string, which must contain syntactically correct Perl code, before beginning file processing. The default value is --init=''.

There I'm setting 2 variables which will be used later.
Also a function xfrm is defined. Depending of the 1st parameter it does different things, always it extends the variable $trace_string with some additional parameters. When the 1st parameter is "group", this $trace_string is returned - my dirty hack for a print of a debug value.

Checking the manpage where an expression ls allowed for a parameter gives me this execution:
(slightly modified for better readability

mrskew --rc martin3.rc  \
  --select='xfrm( "select", 1)' \
  --where0='xfrm( "where0", 1)==1' \
  --where1='xfrm( "where1", 1)==1' \
  --group='xfrm( "group",1)' \
  berx2.trc

The idea is simple: wherever a expression is allowed, my generic function xfrm is called with the name of the mrskew-parameter as it's 1st parameter.

It's result provides some interesting insights:

Summary information by file (modified)
mrskew --rc martin3.rc  --select='xfrm( "select", 1)' --where0='xfrm( "where0", 1)==1' --where1='xfrm( "where1", 1)==1' --group='xfrm( "group",1)' berx2.trc "D:\TEMP\berx2.trc"
Run began 2017-09-25T09:54:40, lasted 0,445000 seconds

input files:
 'D:\TEMP\berx2.trc'

where expression:
 ((xfrm( "where0", 1)==1) and (xfrm( "where1", 1)==1)) and ($nam=~/(?^:(?i).+)/)

group expression:
 xfrm( "group",1)

matched call names:
 'EXEC'

'xfrm( "group",1)'                                                                                                                                                                                                                                                                                                 'xfrm( "select", 1)'       %  CALLS      MEAN       MIN       MAX
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------  --------------------  ------  -----  --------  --------  --------
trace: where0{ x } [1] -> where1{ u } [1] -> where0{ ux } [4] -> where1{ uu } [4] -> where0{ uux } [5] -> where1{ uuu } [5] -> where0{ uuux } [6] -> where1{ uuuu } [6] -> select{ uuuu } [6] -> group{ uuuu } [6] ->                                                                                                          1.000000   50.0%      1  1.000000  1.000000  1.000000
trace: where0{ x } [1] -> where1{ u } [1] -> where0{ ux } [4] -> where1{ uu } [4] -> where0{ uux } [5] -> where1{ uuu } [5] -> where0{ uuux } [6] -> where1{ uuuu } [6] -> select{ uuuu } [6] -> group{ uuuu } [6] -> where0{ uuuux } [7] -> where1{ uuuuu } [7] -> select{ uuuuu } [7] -> group{ uuuuu } [7] ->               1.000000   50.0%      1  1.000000  1.000000  1.000000
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------  --------------------  ------  -----  --------  --------  --------
TOTAL (2)                                                                                                                                                                                                                                                                                                                      2.000000  100.0%      2  1.000000  1.000000  1.000000
mrskew: file 'berx2.trc' does not exist

As the $trace_string is quite long I cut it down into pieces and my interpretation:

trace: where0{ x } [1] -> where1{ u } [1] ->

where0 is called before where1
where1 can modify a variable set by where0 (the x becomes an u).

where0{ ux } [4] -> where1{ uu } [4] -> where0{ uux } [5] -> where1{ uuu } [5] ->

where0 and where1 are NOT used in lines 2 & 3 of the trace file (PARSING IN CURSOR and the insert statement)

where0{ uuux } [6] -> where1{ uuuu } [6] -> select{ uuuu } [6] -> group{ uuuu } [6] ->

in line 6 (EXEC) where0, where1, select and group functions are used (in that order)

where0{ uuuux } [7] -> where1{ uuuuu } [7] -> select{ uuuuu } [7] -> group{ uuuuu } [7] ->

the same is true for line 7.

There is probably more to identify as my simplified tracefile did not show all possible lines and their combination. But the possibility to run code inside mrskew at different positions, and even manipulate some values is shown. Even manipulating mrskews own variables might be of some interest, but it must be identified first where/when they are set and changed. This is open for the readers exercise, the method is shown here :-)

2017-09-12

wrong permission on shm kills JAVA_JIT

We found a lot of trace files from several DBs on one of our DB Servers.
They look like:

*********_ora_26444.trc or *********_m000_5598.trc

*** 2017-09-08 15:11:29.181
*** SESSION ID:(632.5995) 2017-09-08 15:11:29.181
*** CLIENT ID:(SYSADMIN) 2017-09-08 15:11:29.181
*** SERVICE NAME:(****_****) 2017-09-08 15:11:29.181
*** MODULE NAME:(*::***:******.****.***.****.******) 2017-09-08 15:11:29.181
*** ACTION NAME:(/) 2017-09-08 15:11:29.181

peshmmap_Create_Memory_Map:
Map_Length = 4096
Map_Protection = 7
Flags = 1
File_Offset = 0
mmap failed with error 1
error message:Operation not permitted

*** 2017-09-08 15:11:29.181
Exception [type: SIGSEGV, Address not mapped to object] [ADDR:0x0] [PC:0x33BEF41, ioc_pin_shared_executable_object()+1509] [flags: 0x0, count: 1]
DDE: Problem Key 'ORA 7445 [ioc_pin_shared_executable_object()+1509]' was flood controlled (0x6) (incident: 61088)
ORA-07445: exception encountered: core dump [ioc_pin_shared_executable_object()+1509] [SIGSEGV] [ADDR:0x0] [PC:0x33BEF41] [Address not mapped to object] []
ssexhd: crashing the process...
Shadow_Core_Dump = PARTIAL
ksdbgcra: writing core file to directory '/***/diag/rdbms/***/***/cdump'

A quick search on MOS (and a opened SR) showedd as top result Ora‑7445 [Ioc_pin_shared_executable_object()] (Doc ID 1316906.1)

But the suggestions there did not solve the issue. (and we could not set java_jit_enabled = false due to application requirements).

But the Note was good enough to make me search more regarding /dev/shm, mmap and Operation not permitted. This led to Shared executable memory on StackExchange. Again not a perfect fit, but it makes enough sense to guess:
with java_jit_enabled, the m000 process is doing the compilation (in time). To let the server process execute the compiled code, it's put ~~into shared memory~~ in a /tmp/ file and mapped in the private memory [ 2019-11-15 - fixed based on a comment by Nenad Noveljic ].
This shared memory must be executable, otherwise the server process can not use it. So the memory is mapped with PROT_EXEC.
I checked on the affected host, if there is a reason against this:

> mount|grep shm    
tmpfs on /dev/shm type tmpfs (rw,nosuid,nodev,noexec,seclabel)

noexec prevents shared memory to be executed, so the memory mapping fails.

It's stated in Oracle Database Preinstallation Tasks
rw and execute permissions must be set, but noexec and nosuid must not be set.

this was changed after the DBs were installed. Probably for good intentions but with bad effects.

With the proper changes of the mount options, the test statement

SELECT dbms_java.longname('TEST') long_name FROM  dual;

completes without any error.

SecureFile LOB - managing free blocks

This blog post continues with all the objects and settings from SecureFile LOB - the empty table, SecureFile LOB - the 1st insert SecureFile LOB - the 1st update and SecureFile LOB - more inserts.

It starts with some inserts:

insert into berx.TEST_BLOBS
select 4, comments, file_content
from berx.source_blobs
where id=4;

commit;

insert into berx.TEST_BLOBS
select 5, comments, file_content
from berx.source_blobs
where id=1; 

insert into berx.TEST_BLOBS
select 6, comments, file_content
from berx.source_blobs
where id=4; 

insert into berx.TEST_BLOBS
select 7, comments, file_content
from berx.source_blobs
where id=1; 

insert into berx.TEST_BLOBS
select 8, comments, file_content
from berx.source_blobs
where id=4;

insert into berx.TEST_BLOBS
select 9, comments, file_content
from berx.source_blobs
where id=1; 

insert into berx.TEST_BLOBS
select 10, comments, file_content
from berx.source_blobs
where id=4; 

commit;

This leads to 10 lines with 10 LOBs. The LOBs are 1 or 2 blocks in size.

The LOBMAP summary of the rows and LOBs is this:

1 11.1 kB AABu7gAAEAAA+N7AAA

ROWID   = AABu7gAAEAAA+N7AAA
ROWNUM  = 1
LOBID   = 00000001000099BF531D
EXTENT# = 0
rdba   = 17032588 - 0x  103e58c
Block  = 255372
nblks  = 2
offset = 0
length = 11389

2 2-byte AABu7gAAEAAA+N/AAA

ROWID   = AABu7gAAEAAA+N/AAA
ROWNUM  = 2
LOBID   = 00000001000099BF67D1
EXTENT# = 0
rdba   = 17032590 - 0x  103e58e
Block  = 255374
nblks  = 1
offset = 0
length = 2

3 close to 4 kB AABu7gAAEAAA+N/AAB

ROWID   = AABu7gAAEAAA+N/AAB
ROWNUM  = 3
LOBID   = 00000001000099C090E3
EXTENT# = 0
rdba   = 17032587 - 0x  103e58b
Block  = 255371
nblks  = 1
offset = 0
length = 4038

4 11.1 kB AABu7gAAEAAA+N9AAA

ROWID   = AABu7gAAEAAA+N9AAA
ROWNUM  = 4
LOBID   = 00000001000099C56EFB
EXTENT# = 0
rdba   = 17032591 - 0x  103e58f
Block  = 255375
nblks  = 1
offset = 0
length = 8060
---
ROWID   = AABu7gAAEAAA+N9AAA
ROWNUM  = 5
LOBID   = 00000001000099C56EFB
EXTENT# = 1
rdba   = 17033787 - 0x  103ea3b
Block  = 256571
nblks  = 1
offset = 8060
length = 3329

This one is somehow special, as the LOB is 11kB in size, so it requires 2 blocks.
These 2 blocks are spread over 2 tablespace extents (and 2 LOB extents also).
In this case space optimization won against avoiding fragmentation.

5 1-byte AABu7gAAEAAA+N/AAC

ROWID   = AABu7gAAEAAA+N/AAC
ROWNUM  = 6
LOBID   = 00000001000099C633A9
EXTENT# = 0
rdba   = 17033788 - 0x  103ea3c
Block  = 256572
nblks  = 1
offset = 0
length = 1

6 11.1 kB AABu7gAAEAAA+N/AAD

ROWID   = AABu7gAAEAAA+N/AAD
ROWNUM  = 7
LOBID   = 00000001000099C633AA
EXTENT# = 0
rdba   = 17033789 - 0x  103ea3d
Block  = 256573
nblks  = 2
offset = 0
length = 11389

7 1-byte AABu7gAAEAAA+N/AAE

ROWNUM  = 8
LOBID   = 00000001000099C633AB
EXTENT# = 0
rdba   = 17033791 - 0x  103ea3f
Block  = 256575
nblks  = 1
offset = 0
length = 1

8 11.1 kB AABu7gAAEAAA+N/AAF

ROWNUM  = 9
LOBID   = 00000001000099C633AC
EXTENT# = 0
rdba   = 17033792 - 0x  103ea40
Block  = 256576
nblks  = 2
offset = 0
length = 11389

9 1-byte AABu7gAAEAAA+N/AAG

ROWNUM  = 10
LOBID   = 00000001000099C633AD
EXTENT# = 0
rdba   = 17033794 - 0x  103ea42
Block  = 256578
nblks  = 1
offset = 0
length = 1

10 11.1 kB AABu7gAAEAAA+N/AAH

ROWID   = AABu7gAAEAAA+N/AAH
ROWNUM  = 11
LOBID   = 00000001000099C633AE
EXTENT# = 0
rdba   = 17033795 - 0x  103ea43
Block  = 256579
nblks  = 2
offset = 0
length = 11389

After row 4s commit, the NGLOB: Persistent Undo block changed:

Persistent Undo information

after row 4th commit

Block dump from disk:
buffer tsn: 4 rdba: 0x0103ea05 (4/256517)
scn: 0xa9d.9b8d2fe9 seq: 0x01 flg: 0x04 tail: 0x2fe94001
frmt: 0x02 chkval: 0x39b1 type: 0x40=NGLOB: Persistent Undo
Hex dump of block: st=0, typ_found=1
Dump of memory from 0x00007FDB0460C800 to 0x00007FDB0460E800
...
  Dump of Persistent Undo Block
  --------------------------------------------------------
 Inst: 1 Objd:454499 Inc:3472328295419215872 SyncTime:4126781815622353101 Flag:0x1
 Total: 2 LoadTime:1505116365 Opcode:1 Xid: 0x01b4.014.00002aca
  --------------------------------------------------------
Chunk: dba: 0x103ea3b: len: 1: Xid:  0x01b4.00d.00002abc: Scn: 2717.-1685245975: Flag: IN USE: FBR: False
Chunk: dba: 0x103ea3c: len: 68: Xid:  0x0000.000.00000000: Scn: 2708.1852084450: Flag: FREE: FBR: False

Block 0x103ea3b is marked as IN USE. This is the 2nd block from the LOB just inserted.
The remaining blocks in this LOB extent are marked as FREE.

After the other 6 inserts, some meta information changed again:

Persistent Undo information

after row 10th commit

Block dump from disk:
buffer tsn: 4 rdba: 0x0103ea05 (4/256517)
scn: 0xa9d.9d4b7340 seq: 0x01 flg: 0x04 tail: 0x73404001
frmt: 0x02 chkval: 0x5850 type: 0x40=NGLOB: Persistent Undo
Hex dump of block: st=0, typ_found=1
Dump of memory from 0x00007F880DC72800 to 0x00007F880DC74800
...
  Dump of Persistent Undo Block
  --------------------------------------------------------
 Inst: 1 Objd:454499 Inc:3472328295419215872 SyncTime:3473457525430831671 Flag:0x1
 Total: 5 LoadTime:1505118775 Opcode:1 Xid: 0x01af.000.00003334
  --------------------------------------------------------
Chunk: dba: 0x103ea3c: len: 1: Xid:  0x01af.021.00003338: Scn: 2717.-1655999709: Flag: IN USE: FBR: False
Chunk: dba: 0x103ea3d: len: 2: Xid:  0x01af.021.00003338: Scn: 2717.-1655999697: Flag: IN USE: FBR: False
Chunk: dba: 0x103ea3f: len: 4: Xid:  0x01af.021.00003338: Scn: 2717.-1655999697: Flag: IN USE: FBR: False
Chunk: dba: 0x103ea43: len: 8: Xid:  0x01af.021.00003338: Scn: 2717.-1655999680: Flag: IN USE: FBR: False
Chunk: dba: 0x103ea4b: len: 53: Xid:  0x0000.000.00000000: Scn: 2708.1852084450: Flag: FREE: FBR: False

There are several Persistent Undo Chunks now, with size of 1, 2, 4, 8 as IN USE and 53 FREE.
The LOBs from this insert are in the Chunks with len: 1, 2,4 and partially 8. To reflect the Chunk starting at 0x103ea43 with len: 8 is only partially filled (2 blocks for LOBID: 00000001000099C633AE) another structure is changed:

Hash Bucket - Range: 32k to 64k

Block dump from disk:
buffer tsn: 4 rdba: 0x0103e585 (4/255365)
scn: 0xa9d.9d4b7347 seq: 0x02 flg: 0x04 tail: 0x73473d02
frmt: 0x02 chkval: 0xdefc type: 0x3d=NGLOB: Hash Bucket
Hex dump of block: st=0, typ_found=1
Dump of memory from 0x00007F880DC72800 to 0x00007F880DC74800
...
  Dump of Hash Bucket Block
  --------------------------------------------------------
Hash Bucket Header Dump
Range: 32k to 64k
Inst:1 Flag:5 Total:0 FSG_COUNT:0 OBJD:454499 Inc:0
Self Descriptive
 fsg_count:0
Head:0x 0x00000000  Tail:0x 0x00000000
 Opcdode:0 Locker Xid: 0x0000.000.00000000
Fsbdba: 0x0    Fbrdba: 0x0
Head Cache Entries
-------------------
-------------------
Tail Cache Entries
-------------------
-------------------
Free Space Chunk Summary
Inst:1 Minc:0 Maxc:0 Count:1 Tot:6 MAXC:1
CFS Chunk List
--------------
Chunk:0 DBA: 0x0103ea45 Len:6 Xid: 0x01af.021.00003338 Ctime:0
Scn: 0x0000.00000000

This CFS Chunk list points to a chunk of 6 blocks (Len: 6) (size: 48k) starting with DBA: 0x103ea45 as free.

Here some meta information about used and unused blocks is stored in NGLOB: Persistent Undo and NGLOB: Hash Bucket blocks. It's also shown LOBs can be split up to fit into the first space available (against filling continuous blocks / least count of extents to avoid fragmentation).

2017-09-04

SecureFile LOB - more inserts

This blog post continues with all the objects and settings from SecureFile LOB - the empty table, SecureFile LOB - the 1st insert and SecureFile LOB - the 1st update.

The next insert is a small LOB with 2 bytes again:

insert into berx.TEST_BLOBS
select 2, comments, file_content
from berx.source_blobs
where id=2; 
--2 byte

The table row points to a new block in the LOB segment:

ROWID   = AABu7gAAEAAA+N/AAA
ROWNUM  = 1
LOBID   = 00000001000099BF67D1
EXTENT# = 0
HOLE?   = n
Superchunk cont? = n
Overallocation  = n
rdba   = 17032590 - 0x  103E58E
File   = 4
Block  = 255374
nblks  = 1
offset = 0
length = 2
---

It's the 4th trans data block:

Block dump from disk:
buffer tsn: 4 rdba: 0x0103e58e (4/255374)
scn: 0xa9c.b1d49a00 seq: 0x02 flg: 0x04 tail: 0x9a000602
frmt: 0x02 chkval: 0x4617 type: 0x06=trans data
Hex dump of block: st=0, typ_found=1
Dump of memory from 0x00007FDC9B903800 to 0x00007FDC9B905800
7FDC9B903800 0000A206 0103E58E B1D49A00 04020A9C  [................]
...
Block header dump:  0x0103e58e
 Object id on Block? Y
 seg/obj: 0x6ef63  csc: 0xa9c.b1d49a00  itc: 1  flg: E  typ: 5 - LOCAL LOBS
     fsl: 0  fnx: 0xffffffff ver: 0x01

 Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x01b0.011.000210a9  0x00000000.0000.00  -B--    0  fsc 0x0000.00000000
========
bdba    [0x0103e58e]
kdlich  [0x7fdc9b90384c 56]
  flg0  0x20 [ver=0 typ=data lock=n]
  flg1  0x00
  scn   0x0a9c.b1d49a00
  lid   00000001000099bf67d1
  rid   0x00000000.0000
kdlidh  [0x7fdc9b903864 24]
  flg2  0x00 [ver=0 lid=short-rowid hash=n cmap=n pfill=n]
  flg3  0x00
  pskip 0
  sskip 0
  hash  0000000000000000000000000000000000000000
  hwm   2
  spr   0
  data  [0x7fdc9b903880 52 8060]
41 42 00 6f 00 74 00 68 00 65 00 72 00 5f 00 78 00 6d 00 6c 00 3e 00 3c 00 69

The structure is well known already, lid is equal to LOBID, hwm is 2 bytes and the content is 0x41 0x42 which is A B.

There is no change in any of the Hash Bucket blocks (neither UFS nor CFS).

the 2nd insert is

insert into berx.TEST_BLOBS
select 3, comments, file_content
from berx.source_blobs
where id=3; 
--4 kbyte

Again only 1 block.

ROWID   = AABu7gAAEAAA+N/AAB
ROWNUM  = 1
LOBID   = 00000001000099C090E3
EXTENT# = 0
HOLE?   = n
Superchunk cont? = n
Overallocation  = n
rdba   = 17032587 - 0x  103E58B
File   = 4
Block  = 255371
nblks  = 1
offset = 0
length = 4038
---

the LOB is now stored in 0x0103e58b - the 1st trans data block. It was used at the 1st insert, but not in use anymore since the 1st update - since then it was on the UFS list.

buffer tsn: 4 rdba: 0x0103e58b (4/255371)
scn: 0xa9c.b1d52068 seq: 0x02 flg: 0x04 tail: 0x20680602
frmt: 0x02 chkval: 0x7711 type: 0x06=trans data
Hex dump of block: st=0, typ_found=1
Dump of memory from 0x00007FF37EF64800 to 0x00007FF37EF66800
7FF37EF64800 0000A206 0103E58B B1D52068 04020A9C  [........h ......]
7FF37EF64810 00007711 00000005 0006EF63 B1D52068  [.w......c...h ..]
7FF37EF64820 00000A9C 00220001 FFFFFFFF 001D01A9  [......".........]
7FF37EF64830 00001782 00000000 00000000 00004000  [.............@..]
7FF37EF64840 00000000 00000000 00000000 B1D52068  [............h ..]
7FF37EF64850 00200A9C 01000000 C0990000 0000E390  [.. .............]
7FF37EF64860 00000000 00000000 00000000 00000000  [................]
7FF37EF64870 00000000 00000000 00000000 00000FC6  [................]
7FF37EF64880 6C636564 0D657261 2020200A 20202020  [declare..       ]
7FF37EF64890 44495220 20202020 574F5220 0D3B4449  [ RID     ROWID;.]
...
Block header dump:  0x0103e58b
 Object id on Block? Y
 seg/obj: 0x6ef63  csc: 0xa9c.b1d52068  itc: 1  flg: E  typ: 5 - LOCAL LOBS
     fsl: 0  fnx: 0xffffffff ver: 0x01

 Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x01a9.01d.00001782  0x00000000.0000.00  -B--    0  fsc 0x0000.00000000
========
bdba    [0x0103e58b]
kdlich  [0x7ff37ef6484c 56]
  flg0  0x20 [ver=0 typ=data lock=n]
  flg1  0x00
  scn   0x0a9c.b1d52068
  lid   00000001000099c090e3
  rid   0x00000000.0000
kdlidh  [0x7ff37ef64864 24]
  flg2  0x00 [ver=0 lid=short-rowid hash=n cmap=n pfill=n]
  flg3  0x00
  pskip 0
  sskip 0
  hash  0000000000000000000000000000000000000000
  hwm   4038
  spr   0
  data  [0x7ff37ef64880 52 8060]

Also, nothing fancy here. Everything as expected.

There is another block of interest, the UFS Hash Bucket which UFS List points to this block. It did NOT change and still contains block 0x0103e58b:

Block dump from disk:
buffer tsn: 4 rdba: 0x0103e583 (4/255363)
scn: 0xa9c.916207e5 seq: 0x01 flg: 0x04 tail: 0x07e53d01
frmt: 0x02 chkval: 0xa4e3 type: 0x3d=NGLOB: Hash Bucket
Hex dump of block: st=0, typ_found=1
Dump of memory from 0x00007FF37EF64800 to 0x00007FF37EF66800
...
  Dump of Hash Bucket Block
  --------------------------------------------------------
Hash Bucket Header Dump
Inst:1 Flag:6 Total:0 FSG_COUNT:0 OBJD:454499 Inc:0
Self Descriptive
 fsg_count:0
Head:0x 0x00000000  Tail:0x 0x00000000
 Opcdode:3 Locker Xid: 0x01b0.019.00020f35
Fsbdba: 0x0    Fbrdba: 0x0
Head Cache Entries
-------------------
-------------------
Tail Cache Entries
-------------------
-------------------
Free Space Chunk Summary
Inst:0 Minc:0 Maxc:0 Count:0 Tot:0 MAXC:1
UFS List
--------------
Deleted - Chunk:0 DBA: 0x0103e58b Len:140681653780481 Xid: 0x01b0.019.00020f35 Ctime:1504343585
Scn: 0x0a9c.9062fe3c
  --------------------------------------------------------

this looks confusing: How can a block which is in use be present in a Free Space list?
My assumption here: as the blocks SCN (0x0a9c.b1d52068) is higher than the UFS entry SCN (0x0a9c.9062fe3c), I'd claim the UFS entry outdated and a cleanup will happen when there is a need to write this Hash Bucket block.

2017-09-02

SecureFile LOB - the 1st update

This blog post continues with all the objects and settings from SecureFile LOB - the empty table and SecureFile LOB - the 1st insert.

the statement is quite easy:

update berx.TEST_BLOBS
set (comments, file_content) = 
(select comments, file_content
from berx.source_blobs
where id=4)
;

The new CLOB is about 11.1 kb in size - so it will require more than 1 block.

Fortunately the number of extents did not change.

New information needs to be gathered again:

ALTER SESSION SET TRACEFILE_IDENTIFIER = "UPDATE_PRE_BLOB";  
alter system dump datafile 4 block min 255360 block max 255375;


ALTER SESSION SET TRACEFILE_IDENTIFIER = "UPDATE_PRE_EXT2";  
alter system dump datafile 4 block min 256512 block max 257023;

@LOBMAP.sql (row 1)

System altered.

SQL> ROWID = AABu7gAAEAAA+N7AAA
ROWNUM  = 1
LOBID   = 00000001000099BF531D
EXTENT# = 0
HOLE?   = n
Superchunk cont? = n
Overallocation  = n
rdba   = 17032588 - 0x  103E58C
File   = 4
Block  = 255372
nblks  = 2
offset = 0
length = 11389
---

The LOBID changed. So the lob (for the same row) is in another location now.

In the 2nd extent, as far as I can judge, did not change.

In the 1st extend, some things changed (obviously, somewhere the LOB needs to be stored).

NGLOB: Segment Header stays the same.
all the NGLOB: Hash Bucket blocks stays the same. (that confuses me as I expected at least one of them to change)
Also block 0x0103e58b (trans data) - the one which holds the previous LOB is exactly the same (!)

The new trans data blocks

1st block:

buffer tsn: 4 rdba: 0x0103e58c (4/255372)
scn: 0xa9c.9062fe3c seq: 0x02 flg: 0x04 tail: 0xfe3c0602
frmt: 0x02 chkval: 0xba2b type: 0x06=trans data
Hex dump of block: st=0, typ_found=1
Dump of memory from 0x00007F98ED985E00 to 0x00007F98ED987E00
7F98ED985E00 0000A206 0103E58C 9062FE3C 04020A9C  [........<.b.....]
7F98ED985E10 0000BA2B 00000005 0006EF63 9062FE3C  [+.......c...<.b.]
7F98ED985E20 00000A9C 00220001 FFFFFFFF 001901B0  [......".........]
7F98ED985E30 00020F33 00000000 00000000 00004000  [3............@..]
7F98ED985E40 00000000 00000000 00000000 9062FE3C  [............<.b.]
7F98ED985E50 00200A9C 01000000 BF990000 00001D53  [.. .........S...]
7F98ED985E60 00000000 00000000 00000000 00000000  [................]
7F98ED985E70 00000000 00000000 00000000 00001F7C  [............|...]
7F98ED985E80 70747468 2F2F3A73 616E6F6A 6E616874  [https://jonathan]
7F98ED985E90 6977656C 6F772E73 72706472 2E737365  [lewis.wordpress.]
7F98ED985EA0 2F6D6F63 35313032 2F31302F 6C2F3132  [com/2015/01/21/l]
7F98ED985EB0 732D626F 65636170 0D0A0D2F 6572630A  [ob-space/....cre]
...
Block header dump:  0x0103e58c
 Object id on Block? Y
 seg/obj: 0x6ef63  csc: 0xa9c.9062fe3c  itc: 1  flg: E  typ: 5 - LOCAL LOBS
     fsl: 0  fnx: 0xffffffff ver: 0x01

 Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x01b0.019.00020f33  0x00000000.0000.00  -B--    0  fsc 0x0000.00000000
========
bdba    [0x0103e58c]
kdlich  [0x7f98ed985e4c 56]
  flg0  0x20 [ver=0 typ=data lock=n]
  flg1  0x00
  scn   0x0a9c.9062fe3c
  lid   00000001000099bf531d
  rid   0x00000000.0000
kdlidh  [0x7f98ed985e64 24]
  flg2  0x00 [ver=0 lid=short-rowid hash=n cmap=n pfill=n]
  flg3  0x00
  pskip 0
  sskip 0
  hash  0000000000000000000000000000000000000000
  hwm   8060
  spr   0
  data  [0x7f98ed985e80 52 8060]
68 74 74 70 73 3a 2f 2f 6a 6f 6e 61 74 68 61 6e 6c 65 77 69 73 2e 77 6f 72 64
70 72 65 73 73 2e 63 6f 6d 2f 32 30 31 35 2f 30 31 2f 32 31 2f 6c 6f 62 2d 73
70 61 63 65 2f 0d 0a 0d 0a 63 72 65 61 74 65 20 74 61 62 6c 65 20 74 65 73 74
...

It is the rdba as described in the lob extent map above and references the lid == LOBID. Also the content is correct (this file is an early copy of my scratchpad to this topic). The hwm is 8060 which is smaller as the length of the LOB (11389).
Also nblks is 2, the next block is of some interest as well.

2nd block:

Block dump from disk:
buffer tsn: 4 rdba: 0x0103e58d (4/255373)
scn: 0xa9c.9062fe3c seq: 0x02 flg: 0x04 tail: 0xfe3c0602
frmt: 0x02 chkval: 0xb95a type: 0x06=trans data
Hex dump of block: st=0, typ_found=1
Dump of memory from 0x00007F98ED985E00 to 0x00007F98ED987E00
...
Block header dump:  0x0103e58d
 Object id on Block? Y
 seg/obj: 0x6ef63  csc: 0xa9c.9062fe3c  itc: 1  flg: E  typ: 5 - LOCAL LOBS
     fsl: 0  fnx: 0xffffffff ver: 0x01

 Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x01b0.019.00020f33  0x00000000.0000.00  -B--    0  fsc 0x0000.00000000
========
bdba    [0x0103e58d]
kdlich  [0x7f98ed985e4c 56]
  flg0  0x20 [ver=0 typ=data lock=n]
  flg1  0x00
  scn   0x0a9c.9062fe3c
  lid   00000001000099bf531d
  rid   0x00000000.0000
kdlidh  [0x7f98ed985e64 24]
  flg2  0x00 [ver=0 lid=short-rowid hash=n cmap=n pfill=n]
  flg3  0x00
  pskip 0
  sskip 0
  hash  0000000000000000000000000000000000000000
  hwm   3329
  spr   0
  data  [0x7f98ed985e80 52 8060]

This block contains the remaining part of the LOB. hwm shows it contains the remaining bytes.

The new LOB is present in the LOB segment, the old one is still present - exactly as I'd expect as UNDO is handled as copy on write in LOBs. It's only confusing to see no indication (visible to me) that block 0x0103e58b is old and not used anymore.

After some time, (but no activity on the DB) block dumps are created again:

ALTER SESSION SET TRACEFILE_IDENTIFIER = "UPDATE_COM_LONGTIME_BLOB";  
alter system dump datafile 4 block min 255360 block max 255375;

ALTER SESSION SET TRACEFILE_IDENTIFIER = "UPDATE_COM_LONGTIME_EXT2";  
alter system dump datafile 4 block min 256512 block max 257023;

Now there is an interesting change:

2nd NGLOB: Hash Bucket

(part of UFS)

Block dump from disk:
buffer tsn: 4 rdba: 0x0103e583 (4/255363)
scn: 0xa9c.916207e5 seq: 0x01 flg: 0x04 tail: 0x07e53d01
frmt: 0x02 chkval: 0xa4e3 type: 0x3d=NGLOB: Hash Bucket
Hex dump of block: st=0, typ_found=1
Dump of memory from 0x00007F9AFDEAE800 to 0x00007F9AFDEB0800
...
  Dump of Hash Bucket Block
  --------------------------------------------------------
Hash Bucket Header Dump
Inst:1 Flag:6 Total:0 FSG_COUNT:0 OBJD:454499 Inc:0
Self Descriptive
 fsg_count:0
Head:0x 0x00000000  Tail:0x 0x00000000
 Opcdode:3 Locker Xid: 0x01b0.019.00020f35
Fsbdba: 0x0    Fbrdba: 0x0
Head Cache Entries
-------------------
-------------------
Tail Cache Entries
-------------------
-------------------
Free Space Chunk Summary
Inst:0 Minc:0 Maxc:0 Count:0 Tot:0 MAXC:1
UFS List
--------------
Deleted - Chunk:0 DBA: 0x0103e58b Len:140299401691137 Xid: 0x01b0.019.00020f35 Ctime:1504343585
Scn: 0x0a9c.9062fe3c
  --------------------------------------------------------

No clue why this block changed in between.
Ctime: is epoc for GMT: Saturday, September 2, 2017 9:13:05 AM (when the update was done) and Scn: is the exact SCN when the new LOB was written.

Now it makes some sense, but it's unclear what changed the block between the 2 dumps.

2017-09-01

SecureFile LOB - move online in 12.2

Today we had a "new features in 12.2" workshop. Thank you Mathias Zarick for this great event.
One of the new features was Online Table Move. But the doc was quite unspecific if this also includes LOBs:

Nonpartitioned tables can be moved as an online operation without blocking any concurrent DML operations. A table move operation now also supports automatic index maintenance as part of the move.
Data maintenance on nonpartitioned tables does not require any maintenance window since it does not impact any DML or query operation.

So it's worth a test-case in my 12.2 sandbox:

There are 2 tables (test_blobs and test_blobs2) of this structure:

create table test_blobs (
        id              number(5),
  comments        varchar2(80),
        file_content    blob
) 
SEGMENT CREATION IMMEDIATE 
NOCOMPRESS 
NOPARALLEL 
TABLESPACE  USERS
lob (file_content) store as SECUREFILE(
        disable storage in row
        chunk 16K
        tablespace users
)
;

test_blobs2 has 2 rows (id 1 & 2) with different blobs.

Session 1:

20:58:57 SQL> update test_blobs set file_content=(select file_content from test_blobs2 where id=1);                                                                                                                     

1 row updated.

Session 2:

20:58:58 SQL>                                                                                                                                                                                                           
                                                                                                                                                                                                                        
ALTER TABLE test_blobs MOVE LOB(file_content) 
20:59:09 SQL> 20:59:09   2    STORE AS ( TABLESPACE users2) online;

Session 1:

20:59:10 SQL> commit;                                                                                                                                                                                                   

Commit complete.

Session 2:

Table altered.
                                                                                                                                                
20:59:18 SQL>

Here the ALTER TABLE ... MOVE LOB ... STORA AS (TABLESPACE ...) ONLINE works.
That's very good news!

The Segment is really there:

21:02:33 SQL> select segment_name, tablespace_name from dba_segments where owner='BERX' and segment_name in                                                                                                             
21:02:34   2  (select segment_name from dba_lobs where table_name='TEST_BLOBS' and column_name='FILE_CONTENT');                                                                                                         

SEGMENT_NAME                             TABLESPACE_NAME
---------------------------------------- ------------------------------
SYS_LOB0000058821C00003$$                USERS2

And the move just waited until the row lock completed.

I really would like to have this feature in 12.1, but it's good to know it will come to my DBs some-when in the future.

2017-08-31

SecureFile LOB - the 1st insert

This blog post continues with all the objects and settings from SecureFile LOB - the empty table.

The insert of one row with a small (1byte) LOB increases the complexity.
berx.source_blobs contains some BLOBs of different size.

insert into berx.TEST_BLOBS
select 1, comments, file_content
from berx.source_blobs
where id=1; --1 byte

commit;

we have a new extent now

col owner for A10  
col segment_name for A30
select owner, segment_name, file_id, block_id, blocks
from dba_extents  
where owner='BERX'
  and segment_name='SYS_LOB0000454368C00003$$';

OWNER      SEGMENT_NAME                      FILE_ID   BLOCK_ID     BLOCKS
---------- ------------------------------ ---------- ---------- ----------
BERX       SYS_LOB0000454368C00003$$               4     255360         16
BERX       SYS_LOB0000454368C00003$$               4     256512        128

The new extent has some new blocks:

ALTER SESSION SET TRACEFILE_IDENTIFIER = "ONE_BLOB_EXT2";  
alter system dump datafile 4 block min 256512 block max 257023;

grep -E 'Block dump from disk|buffer tsn|frmt' ONE_BLOB_EXT2.trc 
Block dump from disk:
buffer tsn: 4 rdba: 0x0103ea00 (4/256512)
frmt: 0x02 chkval: 0xf2bc type: 0x45=NGLOB: Lob Extent Header
Block dump from disk:
buffer tsn: 4 rdba: 0x0103ea01 (4/256513)
frmt: 0x02 chkval: 0x6d43 type: 0x3e=NGLOB: Committed Free Space
Block dump from disk:
buffer tsn: 4 rdba: 0x0103ea02 (4/256514)
frmt: 0x02 chkval: 0x6d41 type: 0x3e=NGLOB: Committed Free Space
Block dump from disk:
buffer tsn: 4 rdba: 0x0103ea03 (4/256515)
frmt: 0x02 chkval: 0x6d40 type: 0x3e=NGLOB: Committed Free Space
Block dump from disk:
buffer tsn: 4 rdba: 0x0103ea04 (4/256516)
frmt: 0x02 chkval: 0x6d47 type: 0x3e=NGLOB: Committed Free Space
Block dump from disk:
buffer tsn: 4 rdba: 0x0103ea05 (4/256517)
frmt: 0x02 chkval: 0xc593 type: 0x40=NGLOB: Persistent Undo
Block dump from disk:
buffer tsn: 4 rdba: 0x0103ea06 (4/256518)
frmt: 0x02 chkval: 0x641e type: 0x40=NGLOB: Persistent Undo
Block dump from disk:
... more Persistent Undo blocks ...
Block dump from disk:
buffer tsn: 4 rdba: 0x0103ea37 (4/256567)
frmt: 0x02 chkval: 0x6ae3 type: 0x06=trans data
Block dump from disk:
buffer tsn: 4 rdba: 0x0103ea38 (4/256568)
frmt: 0x02 chkval: 0x09a4 type: 0x06=trans data
Block dump from disk:
buffer tsn: 4 rdba: 0x0103ea39 (4/256569)
frmt: 0x02 chkval: 0xcef1 type: 0x06=trans data
Block dump from disk:
buffer tsn: 4 rdba: 0x0103ea3a (4/256570)
frmt: 0x02 chkval: 0x2928 type: 0x06=trans data
... many more trans data blocks ...
Block dump from disk:
buffer tsn: 4 rdba: 0x0103ea80 (4/256640)
frmt: 0x02 chkval: 0x6bb3 type: 0x45=NGLOB: Lob Extent Header
... many more trans data blocks ...
Block dump from disk:
buffer tsn: 4 rdba: 0x0103eb00 (4/256768)
frmt: 0x02 chkval: 0x6a33 type: 0x45=NGLOB: Lob Extent Header
... many more trans data blocks ...
Block dump from disk:
buffer tsn: 4 rdba: 0x0103eb80 (4/256896)
frmt: 0x02 chkval: 0x6ab3 type: 0x45=NGLOB: Lob Extent Header
... many more trans data blocks ...

1st NGLOB: Lob Extent Header

Block dump from disk:
buffer tsn: 4 rdba: 0x0103ea00 (4/256512)
scn: 0xa9c.1f0271f4 seq: 0x02 flg: 0x04 tail: 0x71f44502
frmt: 0x02 chkval: 0xf2bc type: 0x45=NGLOB: Lob Extent Header
Hex dump of block: st=0, typ_found=1
Dump of memory from 0x00007FDC79DC4800 to 0x00007FDC79DC6800
...
  Dump of Extent Header Block
  --------------------------------------------------------
  sdba: 0x0103ea01 len:127 flag:0x0 synctime:1504000457 updtime:1504000457
  objd:454499 inc:0 total:1 opcode:0 xid: 0x0000.000.00000000
  entry 0: sdba: 0x0103ea01 len:127 fdba: 0x00000000
  --------------------------------------------------------

In comparison to the Lob Extent Header of 1st extent this one has sdba: 0x0103ea01 - this points direct to the next block. But it's not of type 0x06=trans data but 0x3e=NGLOB: Committed Free Space. len:127 makes sense, as the next block (after 128 == 0x80) is again 0x45=NGLOB: Lob Extent Header. There is no data yet.

1st NGLOB: Committed Free Space

Block dump from disk:
buffer tsn: 4 rdba: 0x0103ea01 (4/256513)
scn: 0xa9c.1f0271f4 seq: 0x02 flg: 0x04 tail: 0x71f43e02
frmt: 0x02 chkval: 0x6d43 type: 0x3e=NGLOB: Committed Free Space
Hex dump of block: st=0, typ_found=1
Dump of memory from 0x00007FDC79DC4800 to 0x00007FDC79DC6800
...
  Dump of NGLOB: Uncommitted Free Space Block
  --------------------------------------------------------
FSB Header
--------------
objd:454499 inc:0 hdba:  0x0103e582 Rng:-1
 prev:  0x0103ea01  next:  0x0103ea01  edba:  0x0103ea00  head:  0x0103ea01
 Xid: 0x0000.000.00000000 Op:0
--------------
Free Space Chunk Summary
Inst:1 Minc:0 Maxc:0 Count:0 Tot:0 MAXC:0
UFS List
--------------

hba: points back to 0x0103e582 - the 1st NGLOB: Hash Bucket of UFS. prev:, next: and head: is the block itself.
The block seems empty.

2nd NGLOB: Committed Free Space

Block dump from disk:
buffer tsn: 4 rdba: 0x0103ea02 (4/256514)
scn: 0xa9c.1f0271f8 seq: 0x01 flg: 0x04 tail: 0x71f83e01
frmt: 0x02 chkval: 0x6d41 type: 0x3e=NGLOB: Committed Free Space
Hex dump of block: st=0, typ_found=1
Dump of memory from 0x00007FDC79DC4800 to 0x00007FDC79DC6800
...
  Dump of NGLOB: Uncommitted Free Space Block
  --------------------------------------------------------
FSB Header
--------------
objd:454499 inc:0 hdba:  0x0103e582 Rng:-1
 prev:  0x00000000  next:  0x00000000  edba:  0x0103ea00  head:  0x0103ea01
 Xid: 0x0000.000.00000000 Op:0
--------------
Free Space Chunk Summary
Inst:1 Minc:0 Maxc:0 Count:0 Tot:0 MAXC:0
UFS List
--------------

Is similar to previous block, prev: and next: are empty.

The next 2 Committed Free Space blocks are identical.

1st NGLOB: Persistent Undo

Block dump from disk:
buffer tsn: 4 rdba: 0x0103ea05 (4/256517)
scn: 0xa9c.1f027207 seq: 0x05 flg: 0x04 tail: 0x72074005
frmt: 0x02 chkval: 0xc593 type: 0x40=NGLOB: Persistent Undo
Hex dump of block: st=0, typ_found=1
Dump of memory from 0x00007FDC79DC4800 to 0x00007FDC79DC6800
...
  Dump of Persistent Undo Block
  --------------------------------------------------------
 Inst: 1 Objd:454499 Inc:3472328295419215872 SyncTime:3976733684276738505 Flag:0x1
 Total: 1 LoadTime:1504000457 Opcode:1 Xid: 0x01b3.01d.00002ca6
  --------------------------------------------------------
Chunk: dba: 0x103ea37: len: 73: Xid:  0x0000.000.00000000: Scn: 2708.1852084450: Flag: FREE: FBR: False

Unfortunately I don't know anything about this block, yet. LoadTime seems to be epoc again.

2nd NGLOB: Persistent UNDO

Block dump from disk:
buffer tsn: 4 rdba: 0x0103ea06 (4/256518)
scn: 0xa9c.1f027209 seq: 0x01 flg: 0x04 tail: 0x72094001
frmt: 0x02 chkval: 0x641e type: 0x40=NGLOB: Persistent Undo
Hex dump of block: st=0, typ_found=1
Dump of memory from 0x00007FDC79DC4800 to 0x00007FDC79DC6800
7FDC79DC4800 0000A240 0103EA06 1F027209 04010A9C  [@........r......]
7FDC79DC4810 0000641E 00000002 00000001 59A539C9  [.d...........9.Y]
7FDC79DC4820 00000000 59A539C9 00000005 00000001  [.....9.Y........]
7FDC79DC4830 00000001 001D01B3 00002CA6 0006EF63  [.........,..c...]
7FDC79DC4840 00000000 00000000 00000000 00000000  [................]
        Repeat 15 times
7FDC79DC4940 00000000 0103E58B 00000000 00000001  [................]
7FDC79DC4950 000301B3 00002C9B 1F027209 00000A9C  [.....,...r......]
7FDC79DC4960 00000002 0103E58C 00000000 00000004  [................]
7FDC79DC4970 00000000 00000000 6E6490E2 00000A94  [..........dn....]
7FDC79DC4980 00000000 00000000 00000000 00000000  [................]
        Repeat 486 times
7FDC79DC67F0 00000000 00000000 00000000 72094001  [.............@.r]
  Dump of Persistent Undo Block
  --------------------------------------------------------
 Inst: 1 Objd:454499 Inc:3472328295419215872 SyncTime:4120848872352594377 Flag:0x1
 Total: 2 LoadTime:1504000457 Opcode:1 Xid: 0x01b3.01d.00002ca6
  --------------------------------------------------------
Chunk: dba: 0x103e58b: len: 1: Xid:  0x01b3.003.00002c9b: Scn: 2716.520253961: Flag: IN USE: FBR: False
Chunk: dba: 0x103e58c: len: 4: Xid:  0x0000.000.00000000: Scn: 2708.1852084450: Flag: FREE: FBR: False

There are 50 such blocks - all looking similar, just no Chunk: dba: entries. This matches the PUA Batchsize: 50 from 1st extents NGLOB: Segment Header.

The trans data blocks are equal to the empty blocks in 1st extent.

The other NGLOB: Lob Extent Header have a sdba: which points to their following block and a len:127 - so they describe the next bunch of trans data blocks.

It's unclear why this extent is required right now as it does not hold any valuable data.
My assumption is the transaction (INSERT) I did - Every transaction on a LOB might require a NGLOB: Persistent Undo (even there is nothing to store in case of an insert). In the 2nd NGLOB: Persistent Undo in memory dump there I can see 0103E58B - the rba of 1st trans data.

Back to the insert:

To get some more information about a specific LOB I have a small script LOBMAP.sql
It gets the INODE of a LOB using DBMS_LOBUTIL.GETINODE. With this INODE it loops through all extents of this LOB, gets additional information with DBMS_LOBUTIL.GETLOBMAP and prints it.
In this context the extent is a chunk inside the LOB storage, not an extend (as in DBA_EXTENTS).

As DBMS_LOBUTIL is not documented, other sources are useful.

The LOB in the table is quite small, so there is only 1 LOB extent:

ROWID   = AABu7gAAEAAA+N7AAA
ROWNUM  = 1
LOBID   = 00000001000099BF1091
EXTENT# = 0
HOLE?   = n
Superchunk cont? = n
Overallocation  = n
rdba   = 17032587 - 0x  103E58B
File   = 4
Block  = 255371
nblks  = 1
offset = 0
length = 1
---

ROWID and ROWNUM are information about the table row - they are more a reference to the row than a property of the LOB. The LOBID uniquely identifies the LOB. EXTENT# is the number of (LOB) extent - in case the LOB does not fit in a single extent. rdba points to the block where this extent starts. the length is 1 - as it's a 1 byte BLOB.

The blocks in the first extent changed as follows.

ALTER SESSION SET TRACEFILE_IDENTIFIER = "ONE_BLOB";  
alter system dump datafile 4 block min 255360 block max 255375;

The NGLOB: Lob Extent Header did not change.

NGLOB: Segment Header

is different than before:

Block dump from disk:
buffer tsn: 4 rdba: 0x0103e581 (4/255361)
scn: 0xa9c.1f027207 seq: 0x01 flg: 0x04 tail: 0x72073f01
frmt: 0x02 chkval: 0x3306 type: 0x3f=NGLOB: Segment Header
Hex dump of block: st=0, typ_found=1
...
NGLOB Segment Header
  Extent Control Header
  -----------------------------------------------------------------
  Extent Header:: spare1: 0      spare2: 0      #extents: 2      #blocks: 144
                  last map  0x00000000  #maps: 0      offset: 8168
      Highwater::  0x0103ea80  ext#: 1      blk#: 128    ext size: 128
  #blocks in seg. hdr's freelists: 0
  #blocks below: 144
  mapblk  0x00000000  offset: 1
                   Unlocked
     Map Header:: next  0x00000000  #extents: 2    obj#: 454499 flag: 0x40000000
  Extent Map
  -----------------------------------------------------------------
   0x0103e580  length: 16
   0x0103ea00  length: 128

  ---------------
CFS hbbcnt:7 hbbmx:7 Mxrng:7 UFS hbbcnt:2 PUA cnt:1 Flag:2
Segment Stats
-------------
Retention: -1
Free Space: 133
PUA Batchsize: 50
UFS Array
---------
DBA: 0x0103e582 Inst:1
DBA: 0x0103e583 Inst:1
Ufs off:152 sz:512
CFS Array
---------
Range: 0 DBA: 0x0103e584
Range: 1 DBA: 0x0103e585
Range: 2 DBA: 0x0103e586
Range: 3 DBA: 0x0103e587
Range: 4 DBA: 0x0103e588
Range: 5 DBA: 0x0103e589
Range: 6 DBA: 0x0103e58a
Cfs off:664 sz:576
PUA Array
---------
DBA: 0x0103ea05 Inst:1
pua off:1240 sz:8
  --------------------------------------------------------

Of course scn: changed. seq: changed from 0x04 to 0x01 ( it's the 1st change in this scn). #extents: and #blocks: changed to reflect the new extent.
Highwater:: now points to the 2nd NGLOB: Lob Extent Header in 2nd extent. #blocks below: changed from 16 to 144. There is a 2nd entry in Extent Map now. PUA cnt: is 1 - so there is 1 Undo Array available.
In the PUA Array there is the 1st NGLOB: Persistent Undo referenced.

NGLOB: Hash Bucket

Block dump from disk:
buffer tsn: 4 rdba: 0x0103e582 (4/255362)
scn: 0xa9c.1f027204 seq: 0x02 flg: 0x04 tail: 0x72043d02
frmt: 0x02 chkval: 0x4368 type: 0x3d=NGLOB: Hash Bucket
Hex dump of block: st=0, typ_found=1
Dump of memory from 0x00007F381BADB800 to 0x00007F381BADD800
...
  Dump of Hash Bucket Block
  --------------------------------------------------------
Hash Bucket Header Dump
Inst:1 Flag:2 Total:0 FSG_COUNT:1 OBJD:454499 Inc:0
 fsg_count:1
Head:0x 0x0103ea01  Tail:0x 0x0103ea01
 Opcdode:1 Locker Xid: 0x01b3.008.00002c95
Fsbdba: 0x103ea01    Fbrdba: 0x0
Head Cache Entries
-------------------
Head: 0 fsg_db:  0x0103ea01
-------------------
Tail Cache Entries
-------------------
Tail: 0 fsg_db:  0x0103ea01
-------------------
Free Space Chunk Summary
Inst:0 Minc:0 Maxc:0 Count:0 Tot:0 MAXC:0
UFS List
--------------
  --------------------------------------------------------

In comparison to previous block, Flag: changed from 6 to 2. (for whatever reason)
FSG_COUNT: increased from 0 to 1. Not sure what FSG stands for, but it seems to be related to Free Space [whatever?]. Opcdode: increased from 0 to 1 and Xid: does contain a real transaction ID now. Fsbdba: and the Head Cache Entries points to the 1st NGLOB: Committed Free Space of 2nd extent (which pointed to this block as well).
Still the UFS List is empty.

All the other NGLOB: Hash Buckets - both IFS and CFS - are equal to before.

trans data

the block with the LOB of the 1st row:

Block dump from disk:
buffer tsn: 4 rdba: 0x0103e58b (4/255371)
scn: 0xa9c.1f027209 seq: 0x02 flg: 0x04 tail: 0x72090602
frmt: 0x02 chkval: 0x1e84 type: 0x06=trans data
Hex dump of block: st=0, typ_found=1
Dump of memory from 0x00007F381BADB800 to 0x00007F381BADD800
7F381BADB800 0000A206 0103E58B 1F027209 04020A9C  [.........r......]
7F381BADB810 00001E84 00000005 0006EF63 1F027209  [........c....r..]
7F381BADB820 00000A9C 00220001 FFFFFFFF 000301B3  [......".........]
7F381BADB830 00002C9B 00000000 00000000 00004000  [.,...........@..]
7F381BADB840 00000000 00000000 00000000 1F027209  [.............r..]
7F381BADB850 00200A9C 01000000 BF990000 00009110  [.. .............]
7F381BADB860 00000000 00000000 00000000 00000000  [................]
7F381BADB870 00000000 00000000 00000000 00000001  [................]
7F381BADB880 85ED8C41 1A98D5F8 34C25268 EE84234D  [A.......hR.4M#..]
7F381BADB890 215E09F4 85AA94A7 5B51EEDA D1D0A149  [..^!......Q[I...]
...
7F381BADD7F0 291DF1A5 CEEDA316 EE84DB30 72090602  [...)....0......r]
Block header dump:  0x0103e58b
 Object id on Block? Y
 seg/obj: 0x6ef63  csc: 0xa9c.1f027209  itc: 1  flg: E  typ: 5 - LOCAL LOBS
     fsl: 0  fnx: 0xffffffff ver: 0x01

 Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x01b3.003.00002c9b  0x00000000.0000.00  -B--    0  fsc 0x0000.00000000
========
bdba    [0x0103e58b]
kdlich  [0x7f381badb84c 56]
  flg0  0x20 [ver=0 typ=data lock=n]
  flg1  0x00
  scn   0x0a9c.1f027209
  lid   00000001000099bf1091
  rid   0x00000000.0000
kdlidh  [0x7f381badb864 24]
  flg2  0x00 [ver=0 lid=short-rowid hash=n cmap=n pfill=n]
  flg3  0x00
  pskip 0
  sskip 0
  hash  0000000000000000000000000000000000000000
  hwm   1
  spr   0
  data  [0x7f381badb880 52 8060]
41 8c ed 85 f8 d5 98 1a 68 52 c2 34 4d 23 84 ee f4 09 5e 21 a7 94 aa 85 da ee
51 5b 49 a1 d0 d1 38 e1 62 9d a1 8b 29 31 c7 c5 d6 d8 48 c3 2f 66 09 15 3a 8c
...

In this block, in the header csc:, Xid and scn changed. The hwm is 1 now (was 8060 before).
The 1st byte of data is 41 - ASCII for A - that's the content of my 1 byte file.
This block really contains the LOB. lid has the same value (just lowercase) as LOBID in the table row - so it's an indirect pointer back to the row it belongs to.

Unfortunately I did not find any indication which shows the block is used now (in comparison to previous dump) - any hint is very welcome!