Print Friendly, PDF & Email

 
SYMPTOMS

During a PSU patch’s post steps, I had an unusual error that was intermittent. Sometimes the post step script completed successfully without any errors and sometimes it failed. I tried many workarounds but none of them helped me out.

For instance, when I executed post step of the patch 31103343 “Loading Modified SQL Files into the Database”

cd $ORACLE_HOME/rdbms/admin
sqlplus /nolog
SQL> CONNECT / AS SYSDBA
SQL> STARTUP
SQL> @catbundle.sql psu apply
SQL> QUIT

 
The @catbundle.sql script sometimes failed with the following error

DROP JAVA DATA "SYS"."LocaleData_da_DK"
DROP JAVA DATA "SYS"."LocaleData_coll_es_HN"
DROP JAVA DATA "SYS"."LocaleData_es_HN"
DROP JAVA DATA "SYS"."prv//////ENOJBBPFAAAAAAAA"
DROP JAVA DATA "SYS"."prv//////MDDMJLJNAAAAAAAA"
DROP JAVA DATA "SYS"."prv//////NAPLGELEAAAAAAAA"
DROP JAVA DATA "SYS"."prv//////IEIJPIEBAAAAAAAA"
DROP JAVA DATA "SYS"."prv//////CLENFDMLAAAAAAAA"
DROP JAVA DATA "SYS"."prv//////IHLOPGIJAAAAAAAA"
DROP JAVA DATA "SYS"."prv//////MGBCBOLLAAAAAAAA"
DROP JAVA DATA "SYS"."prv//////HHPHKFCGAAAAAAAA"
DROP JAVA DATA "SYS"."prv//////OKMOMHMBAAAAAAAA"
DROP JAVA DATA "SYS"."prv//////DNLOIFJFAAAAAAAA"
DROP JAVA DATA "SYS"."prv//////KGLNECFEAAAAAAAA"
DROP JAVA DATA "SYS"."prv//////DDJCFKNKAAAAAAAA"
DROP JAVA DATA "SYS"."prv//////FOPOCDCGAAAAAAAA"
DROP JAVA DATA "SYS"."prv//////JJNALOPFAAAAAAAA"
DROP JAVA DATA "SYS"."prv//////IOLBDJNCAAAAAAAA"
DROP JAVA DATA "SYS"."prv//////IIBABFJEAAAAAAAA"
DROP JAVA DATA "SYS"."prv//////BCIHDMKEAAAAAAAA"
DROP JAVA DATA "SYS"."prv//////IBPLEBPAAAAAAAAA"
DROP JAVA DATA "SYS"."prv//////EFOLNLBEAAAAAAAA"
DROP JAVA DATA "SYS"."prv//////JKBIENDKAAAAAAAA"
DROP JAVA DATA "SYS"."prv//////HPNCBMNLAAAAAAAA"
DROP JAVA DATA "SYS"."prv//////HNGLLGBAAAAAAAAA"
DROP JAVA DATA "SYS"."prv//////PEACEFDBAAAAAAAA"
DROP JAVA DATA "SYS"."prv//////KPKNOAIAAAAAAAAA"
DROP JAVA DATA "SYS"."JAVA$POLICY$SHARED$00000015"
DROP JAVA DATA "SYS"."JAVA$POLICY$SHARED$00000016"
DROP JAVA DATA "SYS"."JAVA$POLICY$SHARED$00000017"
DROP JAVA DATA "SYS"."JAVA$POLICY$SHARED$00000018"
DROP JAVA DATA "SYS"."JAVA$POLICY$SHARED$00000019"
DROP JAVA DATA "SYS"."prv//////DGFFDEIKAAAAAAAA"
delete from java$policy$shared$table
BEGIN
*
ERROR at line 1:
ORA-29516: Aurora assertion failure: Assertion failure at eox.c:359
Uncaught exception Root of all Java exceptions: java.lang.NoClassDefFoundError
sun/misc/Hashing
ORA-06512: at line 25

SQL> 
SQL> 
SQL> commit;

Commit complete.

SQL> 
SQL> 
SQL> -- bug 25649873 create a policy SRO
SQL> 
SQL> @@jvmsec6
SQL> -- Create the table now to avoid creation of a lot of
SQL> -- unneccessary shared objects by the above grant_permissions,
SQL> -- and redundantly grant something to cause creation of a shared object.
SQL> call initjvmaux.create_if_not_present('
  2  create table java$policy$shared$table (version number)
  3  ');

create table java$policy$shared$table (version number)


Call completed.

SQL> 
SQL> call dbms_java.grant_permission('PUBLIC', 'SYS:oracle.aurora.security.JServerPermission', 'DUMMY', '');
call dbms_java.grant_permission('PUBLIC', 'SYS:oracle.aurora.security.JServerPermission', 'DUMMY', '')
     *
ERROR at line 1:
ORA-29516: Aurora assertion failure: Assertion failure at eox.c:359
Uncaught exception Root of all Java exceptions: java.lang.NoClassDefFoundError
sun/misc/Hashing
ORA-06512: at "SYS.DBMS_JAVA", line 793


SQL> call dbms_java.revoke_permission('PUBLIC', 'SYS:oracle.aurora.security.JServerPermission', 'DUMMY', '');
call dbms_java.revoke_permission('PUBLIC', 'SYS:oracle.aurora.security.JServerPermission', 'DUMMY', '')
     *
ERROR at line 1:
ORA-29516: Aurora assertion failure: Assertion failure at eox.c:359
Uncaught exception Root of all Java exceptions: java.lang.NoClassDefFoundError
sun/misc/Hashing
ORA-06512: at "SYS.DBMS_JAVA", line 819

SQL> 
SQL> commit;

Commit complete.

SQL> 
SQL> 
SQL> 
SQL> PROMPT Processing Oracle Text...
Processing Oracle Text...
SQL> ALTER SESSION SET current_schema = CTXSYS;

 
The failed part of the catbundle.sql script belonged to the following part of the scipt code

SQL> BEGIN
  2
  3    :jvmversion := 'NONE';
  4    :jitstate := 'FALSE';
  5    SELECT value INTO :jitstate FROM v$parameter WHERE name='java_jit_enabled';
  6    select nvl((SELECT name FROM obj$ WHERE name like 'JAVA$CBRLS%' and type#=30 and owner#=0), 'NONE') into :jvmversion from dual;
  7    select to_char((select startup_time from v$instance),'DD-MON-YYYY HH24:MI:SS') INTO :dbtime from dual;
  8    select to_char
  9           ((select nvl((SELECT MTIME FROM obj$ WHERE name like 'JAVA$CBRLS%' and type#=30 and owner#=0),to_date('01-JAN-0001','DD-MON-YYYY'))
 10           from dual),'DD-MON-YYYY HH24:MI:SS') INTO :cjstime from dual;
 11
 12
 13    EXECUTE IMMEDIATE 'alter system set java_jit_enabled = false';
 14
 15
 16    IF ((not(:jvmaction = 'APPLY' and :jvmversion = 'JAVA$CBRLS$11.2.0.4.200714'))
 17       and (not(:jvmaction = 'ROLLBACK' and
 18       :jvmversion != 'JAVA$CBRLS$11.2.0.4.200714'))) and
 19       (to_date(:cjstime,'DD-MON-YYYY HH24:MI:SS') = to_date ('01-JAN-0001','DD-MON-YYYY HH24:MI:SS')
 20       or to_date(:dbtime,'DD-MON-YYYY HH24:MI:SS') > to_date(:cjstime,'DD-MON-YYYY HH24:MI:SS')) THEN
 21
 22      initjvmaux.drop_sros();
 23
 24
 25      EXECUTE IMMEDIATE 'create or replace java system';
 26
 27      update dependency$
 28        set p_timestamp=(select stime from obj$ where obj#=p_obj#)
 29        where (select stime from obj$ where obj#=p_obj#)!=p_timestamp and
 30              (select type# from obj$ where obj#=p_obj#)=29  and
 31              (select owner# from obj$ where obj#=p_obj#)=0;
 32
 33
 34  -- Check the validity of JAVAVM and let the registry be updated accordingly.
 35
 36      initjvmaux.validate_javavm;
 37
 38  -- Add a row in registry$history to indicate this script was run.
 39
 40      EXECUTE IMMEDIATE 'insert into registry$history
 41                         (action_time, action, namespace, version, id, comments)
 42                         values(SYSTIMESTAMP, ''jvmpsu.sql'', ''SERVER'',
 43                                ''11.2.0.4.200714OJVMPSU'', 0, ''RAN jvmpsu.sql'')';
 44
 45    END IF;
 46
 47    EXECUTE IMMEDIATE 'alter system set java_jit_enabled = ' || :jitstate;
 48
 49  END;
 50  /

 
All Java components were in the VALID state.

set pages 999
set lines 300 
col COMP_ID for a10 
col COMP_NAME for a35
col VERSION for a15 
col PROCEDURE for a45
col OTHER_SCHEMAS for a25
col STATUS for a10
col CONTROL for a15 
col SCHEMA for a15 
col MODIFIED for a20

select comp_id,comp_name,version,status,modified,schema,procedure from dba_registry
where upper(comp_name) like '%JAVA%';

COMP_ID    COMP_NAME                           VERSION         STATUS     MODIFIED             SCHEMA          PROCEDURE
---------- ----------------------------------- --------------- ---------- -------------------- --------------- ---------------------------------------------
JAVAVM     JServer JAVA Virtual Machine        11.2.0.4.0      VALID      28-OCT-2020 21:28:28 SYS             INITJVMAUX.VALIDATE_JAVAVM
CATJAVA    Oracle Database Java Packages       11.2.0.4.0      VALID      28-OCT-2020 21:28:28 SYS             DBMS_REGISTRY_SYS.VALIDATE_CATJAVA

 
Increasing the java pool size as mentioned in Doc ID 2185332.1 before the script execution had no effect

 
 
ROOT CAUSE
 
Looking into the problem, I discovered that after the database had been started a lot of jobs started right after the database. Running jobs consumed lots of memory in the SGA. And if the post step script was run while the jobs were executing the script failed every time.

With the following query, I found out that there were many active sessions in the database after it was started. It was strange as it was the maintenance window for applying the PSU patch and there should be no user sessions at all. It turned out that all active sessions were Oracle jobs (see PROGRAM column) that were started right after the database was OPEN.

COL SID FOR 99999
COL USERNAME FOR A10 
COL STATUS FOR A10
COL SQL_ID FOR A15
COL EVENT FOR A35
COL ELAPSED_SECONDS FOR 999999
COL MODULE FOR A15
COL PROGRAM FOR A15
SET LINES 300
SET PAGES 999
SELECT SID,
       SERIAL#,
       USERNAME,
       SQL_ID,
       STATUS,
       EVENT,
       LAST_CALL_ET ELAPSED_SECONDS,
       SUBSTR(MODULE,1,15) MODULE,
       SUBSTR(PROGRAM,-15) PROGRAM
FROM
       V$SESSION
WHERE
       USERNAME IS NOT NULL
ORDER BY LAST_CALL_ET;

   SID    SERIAL# USERNAME   SQL_ID          STATUS     EVENT                               ELAPSED_SECONDS MODULE          PROGRAM
------ ---------- ---------- --------------- ---------- ----------------------------------- --------------- --------------- ---------------
   387          7 SYS        bf8szb5c6cffw   ACTIVE     SQL*Net message to client                         0 sqlplus@s001tst .local (TNS V1-
   776        189 POSC       avcp8cxpdwjut   ACTIVE     buffer busy waits                                34                 ur.local (J014)
  1552        121 POSC       3tpdp8s33jhqp   ACTIVE     buffer busy waits                                76                 ur.local (J022)
  1930        133 MES_WEB    1g7hn33utrqaw   ACTIVE     buffer busy waits                               138                 ur.local (J001)
  1177         63 POSC       b0ks42hvpk9d2   ACTIVE     buffer busy waits                               149                 ur.local (J000)
  1161        113 POSC       2qq5h4u4ms5zk   ACTIVE     buffer busy waits                               277                 ur.local (J012)
     8         51 POSC       a5a94fbxt61z2   ACTIVE     buffer busy waits                               278                 ur.local (J006)
   791         37 POSC       a5a94fbxt61z2   ACTIVE     buffer busy waits                               278                 ur.local (J019)
   391        151 POSC       a5a94fbxt61z2   ACTIVE     buffer busy waits                               279                 ur.local (J003)
  1945        155 POSC       a5a94fbxt61z2   ACTIVE     buffer busy waits                               429                 ur.local (J017)
   401         47 POSC       a5a94fbxt61z2   ACTIVE     buffer busy waits                               541                 ur.local (J009)
  1926          5 RWC        a9g4k0980a5b6   ACTIVE     latch free                                     1018 DBMS_SCHEDULER  ur.local (J007)
     4          7 RWC        a9g4k0980a5b6   ACTIVE     latch: cache buffers chains                    1019 DBMS_SCHEDULER  ur.local (J002)
     6          9 RWC        a9g4k0980a5b6   ACTIVE     latch free                                     1019 DBMS_SCHEDULER  ur.local (J008)
  1934          9 RWC        a9g4k0980a5b6   ACTIVE     latch: cache buffers chains                    1019 DBMS_SCHEDULER  ur.local (J031)
    14         11 RWC        a9g4k0980a5b6   ACTIVE     latch: cache buffers chains                    1020 DBMS_SCHEDULER  ur.local (J032)
  1558          3 RWC        a9g4k0980a5b6   ACTIVE     latch free                                     1025 DBMS_SCHEDULER  ur.local (J048)
  1163         11 RWC        a9g4k0980a5b6   ACTIVE     latch free                                     1027 DBMS_SCHEDULER  ur.local (J011)
  1938          3 RWC        a9g4k0980a5b6   ACTIVE     latch: cache buffers chains                    1029 DBMS_SCHEDULER  ur.local (J043)
    10         13 RWC        a9g4k0980a5b6   ACTIVE     latch: cache buffers chains                    1032 DBMS_SCHEDULER  ur.local (J020)
   395          5 RWC        a9g4k0980a5b6   ACTIVE     latch: cache buffers chains                    1032 DBMS_SCHEDULER  ur.local (J015)
  1928          9 RWC        a9g4k0980a5b6   ACTIVE     latch: cache buffers chains                    1035 DBMS_SCHEDULER  ur.local (J013)
   778         17 RWC        a9g4k0980a5b6   ACTIVE     latch free                                     1035 DBMS_SCHEDULER  ur.local (J010)
  1940          1 POSC       c8hbs4fc84rda   ACTIVE     enq: TX - row lock contention                  1035                 ur.local (J049)
  1173          1 POSC       c8hbs4fc84rda   ACTIVE     enq: TX - row lock contention                  1036                 ur.local (J041)
  1556          1 POSC       2qq5h4u4ms5zk   ACTIVE     buffer busy waits                              1036                 ur.local (J042)
  1550         11 POSC       a5a94fbxt61z2   ACTIVE     local write wait                               1036                 ur.local (J024)
   405          1 POSC       a5a94fbxt61z2   ACTIVE     buffer busy waits                              1036                 ur.local (J045)
   780          7 PERFSTAT   2tx2sr9upcpqb   ACTIVE     db file sequential read                        1037                 ur.local (J016)
  1554          3 POSC       20s4ppqvh5pt0   ACTIVE     latch free                                     1037                 ur.local (J036)
   399          3 POSC       c8hbs4fc84rda   ACTIVE     enq: TX - row lock contention                  1037                 ur.local (J027)
  1932          5 POSC       c8hbs4fc84rda   ACTIVE     enq: TX - row lock contention                  1037                 ur.local (J025)

32 rows selected.

 
A user created lots of jobs that execute ‘heavy’ queries continuously. The queries loaded the database and the post step script failed because of it. For instance, most of the jobs are started every 30 minutes

SQL> select job,NEXT_DATE,INTERVAL from dba_jobs where INTERVAL like '%/1440%' and broken='N';

       JOB NEXT_DATE          INTERVAL
---------- ------------------ --------------------------------------------------
      4002 21-OCT-20          sysdate + 10/1440
      2264 21-OCT-20          SYSDATE+3/1440
      2204 21-OCT-20          TRUNC(SYSDATE,'HH')+120/1440
      1766 21-OCT-20          SYSDATE+30/1440
      1964 21-OCT-20          SYSDATE+2/1440
      1485 21-OCT-20          SYSDATE+30/1440
      1484 21-OCT-20          SYSDATE+30/1440
      1424 21-OCT-20          SYSDATE+30/1440
      1444 21-OCT-20          SYSDATE+30/1440
       501 21-OCT-20          SYSDATE+30/1440
       499 21-OCT-20          SYSDATE+30/1440
       500 21-OCT-20          SYSDATE+30/1440
       502 21-OCT-20          SYSDATE+30/1440
       503 21-OCT-20          SYSDATE+30/1440
       505 21-OCT-20          SYSDATE+30/1440
       507 21-OCT-20          SYSDATE+30/1440
       509 21-OCT-20          SYSDATE+30/1440
       583 21-OCT-20          SYSDATE+10/1440
       343 21-OCT-20          SYSDATE+30/1440
       244 21-OCT-20          SYSDATE+30/1440
       247 21-OCT-20          SYSDATE+30/1440
       248 21-OCT-20          SYSDATE+30/1440
       563 21-OCT-20          SYSDATE+30/1440
       267 21-OCT-20          SYSDATE+30/1440
       268 21-OCT-20          SYSDATE+30/1440
       269 21-OCT-20          SYSDATE+30/1440
       965 21-OCT-20          SYSDATE+30/1440
       404 21-OCT-20          SYSDATE+30/1440
       428 21-OCT-20          SYSDATE+30/1440
       406 21-OCT-20          SYSDATE+30/1440
       445 21-OCT-20          SYSDATE+30/1440
      1124 21-OCT-20          SYSDATE+3/1440
      1086 21-OCT-20          SYSDATE + 1/1440
      1185 21-OCT-20          SYSDATE+30/1440
      1225 21-OCT-20          SYSDATE+30/1440
      1286 21-OCT-20          SYSDATE+30/1440
        23 21-OCT-20          SYSDATE+30/1440
        33 21-OCT-20          SYSDATE+30/1440
        83 21-OCT-20          SYSDATE+10/1440
       204 21-OCT-20          SYSDATE+15/1440
       303 21-OCT-20          SYSDATE+60/1440
       344 21-OCT-20          SYSDATE+30/1440
       463 21-OCT-20          SYSDATE+120/1440
       484 01-NOV-20          TRUNC(LAST_DAY(SYSDATE)) + 1 + 8/24 + 30/1440
       544 21-OCT-20          sysdate+5/1440
       546 21-OCT-20          sysdate+20/1440
       731 21-OCT-20          (SYSDATE+1/1440)
       827 21-OCT-20          (SYSDATE+60/1440)
       866 21-OCT-20          SYSDATE+1/1440
       895 01-JAN-21          ADD_MONTHS(TRUNC(SYSDATE,'yyyy'),12)+1/1440

50 rows selected.

 
However when I disabled the job_queue_processes parameter and restarted the database (it’s ok as it was performed in the maintenance window) so no jobs were running the script completed successfully.

SQL> show parameter job_

NAME                                 TYPE                              VALUE
------------------------------------ --------------------------------- ------------------------------
job_queue_processes                  integer                           1000

SQL> alter system set job_queue_processes=0;

System altered.

SQL> show parameter job_

NAME                                 TYPE                              VALUE
------------------------------------ --------------------------------- ------------------------------
job_queue_processes                  integer                           0
cd $ORACLE_HOME/rdbms/admin
sqlplus /nolog
SQL> CONNECT / AS SYSDBA
SQL> STARTUP
SQL> @catbundle.sql psu apply
SQL> QUIT

 
When the post step script finished successfully the job_queue_processes parameter was reverted back to its original value.

SQL> alter system set job_queue_processes=1000;

System altered.

 
 
REFERENCES
 
ORA-29516: Aurora Assertion Failure Eox.c:359 Java.lang.ExceptionInInitializerError (Doc ID 2185332.1)

 
 

Version  : 18:07 05.11.2020
Database : 11.2.0.4.0 (OJVM and PSU JULY 2020)