Freitag, 15. Dezember 2017

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 😂

Donnerstag, 14. Dezember 2017

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


Dienstag, 12. Dezember 2017

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.

Mittwoch, 6. Dezember 2017

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.

Donnerstag, 16. November 2017

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. 

Donnerstag, 26. Oktober 2017

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.

Freitag, 20. Oktober 2017

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 18th and 20th 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 10th of October.
So a valid conclusion is: The content of Patch 26635880 was defined before 7th 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 ...)