Skip to content

Posts tagged ‘19c’

Database Instance 19c Crashes Intermittently

Oracle Database – Enterprise Edition – Version 19.3.0.0.0 to 19.6.0.0.0 [Release 19]
All Platforms

SYMPTOMS

+ This is an Oracle Database 19.3.0.0 on Microsoft Windows 2016 (64-bit). But this problem can occur on any platform for DB version from 19.3 to 19.6.

+ Intermittently, the instance crashes when it archives to the FRA which is configured on a SAN storage. But these are not necessary key factors either.

+ There is no good reason from the DB side for such a crash. There is no clue either from the DB logs why such crashes occurred….
2019-11-22T01:13:52.348399+00:00
ARC2 (PID:4572): Archived Log entry 1425 added for T-1.S-1438 ID 0x58ee09d8
LAD:1
2019-11-22T01:15:17.173560+00:00
Warning: VKTM detected a forward time drift.
Please see the VKTM trace file for more details:
..\trace\<sid>_vktm_796.trc
2019-11-22T01:25:33.718455+00:00
Starting ORACLE instance (normal) (OS id: 17956)

2019-11-25T12:00:51.401991+00:00
ARC3 (PID:18228): Archived Log entry 1704 added for T-1.S-1717 ID 0x58ee09d8
LAD:1
2019-11-25T12:16:59.974303+00:00
Warning: VKTM detected a forward time drift.
Please see the VKTM trace file for more details:
..\trace\<sid>_vktm_21108.trc
2019-11-25T12:20:47.426580+00:00
Starting ORACLE instance (normal) (OS id: 10268)

2019-12-10T06:45:34.380138+00:00
ARC3 (PID:24552): Archived Log entry 2918 added for T-1.S-2931 ID 0x58ee09d8
LAD:1
2019-12-10T06:52:06.575056+00:00
Resize operation completed for file# 3, old size 20869120K, new size
20879360K
2019-12-10T06:53:09.482879+00:00
Warning: VKTM detected a forward time drift.
Please see the VKTM trace file for more details:
..\trace\<sid>_vktm_24308.trc
2019-12-10T07:11:23.052682+00:00
Starting ORACLE instance (normal) (OS id: 19608)

2019-12-13T06:37:30.555846+00:00
ARC1 (PID:23204): Archived Log entry 3145 added for T-1.S-3158 ID 0x58ee09d8
LAD:1
2019-12-13T06:39:26.398601+00:00
<pdb_name>(3):TABLE SYS.WRI$_OPTSTAT_HISTHEAD_HISTORY: ADDED INTERVAL PARTITION
SYS_P921 (43811) VALUES LESS THAN (TO_DATE(‘ 2019-12-14 00:00:00’,
‘SYYYY-MM-DD HH24:MI:SS’, ‘NLS_CALENDAR=GREGORIAN’))
2019-12-13T06:48:17.595483+00:00
Warning: VKTM detected a forward time drift.
Please see the VKTM trace file for more details:
..\trace\<sid>_vktm_21892.trc
2019-12-13T06:56:24.219627+00:00
Starting ORACLE instance (normal) (OS id: 12156)

2019-12-17T11:12:04.311930+00:00
ARC1 (PID:22684): Archived Log entry 3416 added for T-1.S-3429 ID 0x58ee09d8
LAD:1
2019-12-17T11:16:07.008944+00:00
Warning: VKTM detected a forward time drift.
Please see the VKTM trace file for more details:
..\trace\<sid>_vktm_16824.trc
2019-12-17T11:18:25.927836+00:00
Starting ORACLE instance (normal) (OS id: 24632)

2019-12-19T16:49:17.207714+00:00
ALTER SYSTEM SET _disable_highres_ticks=FALSE SCOPE=SPFILE;
2019-12-19T16:49:17.238967+00:00
ALTER SYSTEM SET _timer_precision=500 SCOPE=SPFILE;
2019-12-19T16:49:20.817415+00:00
ALTER SYSTEM SET event=’10795 trace name context forever, level 2′
SCOPE=SPFILE;

2019-12-20T17:01:04.687429+00:00
NET (PID:25104): Archived Log entry 3627 added for T-1.S-3640 ID 0x58ee09d8
LAD:1
2019-12-20T17:33:01.355689+00:00
Resize operation completed for file# 3, old size 22558720K, new size
22568960K
2019-12-20T17:41:55.185792+00:00
Warning: VKTM detected a forward time drift.
Please see the VKTM trace file for more details:
..\trace\<sid>_vktm_12128.trc
2019-12-20T17:51:37.338467+00:00
Starting ORACLE instance (normal) (OS id: 9472)

_disable_highres_ticks = FALSE
_timer_precision = 500
event = “10795 trace name context forever, level 2”

2020-01-04T07:07:02.971105+00:00
ARC0 (PID:5404): Archived Log entry 4468 added for T-1.S-4481 ID 0x58ee09d8
LAD:1
2020-01-04T07:50:00.791072+00:00
Resize operation completed for file# 3, old size 24872960K, new size
24883200K
2020-01-04T08:00:13.906056+00:00
Thread 1 advanced to log sequence 4483 (LGWR switch)
Current log# 3 seq# 4483 mem# 0: ..\<SID>\REDO03A.LOG
Current log# 3 seq# 4483 mem# 1: ..\<SID>\REDO03B.LOG
2020-01-04T08:00:16.171956+00:00
ARC1 (PID:19276): Archived Log entry 4469 added for T-1.S-4482 ID 0x58ee09d8
LAD:1
2020-01-04T08:37:08.530619+00:00
Starting ORACLE instance (normal) (OS id: 19372)

2020-01-06T13:43:32.621640+00:00
ARC0 (PID:5500): Archived Log entry 4603 added for T-1.S-4616 ID 0x58ee09d8
LAD:1
2020-01-06T14:10:47.771835+00:00
Resize operation completed for file# 3, old size 25200640K, new size
25210880K
2020-01-06T14:50:42.867598+00:00
Starting ORACLE instance (normal) (OS id: 2988)

2020-01-06T17:09:17.660728+00:00
ARC1 (PID:22160): Archived Log entry 4606 added for T-1.S-4619 ID 0x58ee09d8
LAD:1
2020-01-06T17:10:07.791962+00:00
Starting ORACLE instance (normal) (OS id: 13320)

2020-01-10T17:01:01.363704+00:00
NET (PID:17724): Archived Log entry 4877 added for T-1.S-4890 ID 0x58ee09d8
LAD:1
2020-01-10T17:15:02.907458+00:00
Resize operation completed for file# 3, old size 25856000K, new size
25866240K
2020-01-10T18:25:26.947274+00:00
Starting ORACLE instance (normal) (OS id: 24016)

+ On Windows platforms, the ORACLE.exe keeps crashing with no errors in the alert log but in Windows event viewer you can always see the following exception:Exception code: 0xc0000409
Fault offset: 0x000000000fc7ff20

 + On Unix based platforms, the ORA-07445 [kwqbmspqueue] error is raised in the alert log file indicating such an overflow. Top call stack may include:.. <- kwqbmspqueue <- kwqbmspmain_switch <- kwqbmspmain <- kwqmnslv <- kwsbsmspm <- kwsbgcbkms <- ksvrdp_int <- ..

CHANGES

Upgrade to 19c

CAUSE

Bug 30777036 – 19c Database Instance Crashes Intermittently

Base Bug 29920804 Getting ora-7445 [kwqbmspqueue()+278] [sigsegv] every minute since upgraded from 18c to 19
 
This base bug affects DB version 19.3, 19.4, 19.5, 19.6 on any platform. So, it is not port specific. It can happen on any platform.

SOLUTION

Please apply the fix for Bug 29920804. This fix is included in 19.7.0.0.200414DBRU onward. For previous releases, please raise an One/Off Backport request.

19c:SRVCTL status service fails with Java.lang.NullPointerException

Oracle Database – Enterprise Edition – Version 19.3.0.0.0 and later
Information in this document applies to any platform.

SYMPTOMS

The following errors occur while running srvctl status service command.

[oracle@<db_name> ~]$ srvctl status service -d <dbservice_name>
Exception in thread “main” java.lang.NullPointerException
at oracle.ops.opsctl.StatusAction.internalExecuteService(StatusAction.java:2038)
at oracle.ops.opsctl.StatusAction.executeSIHAService(StatusAction.java:1652)
at oracle.ops.opsctl.Action.executeSIHA(Action.java:443)
at oracle.ops.opsctl.OPSCTLDriver.execute(OPSCTLDriver.java:537)
at oracle.ops.opsctl.OPSCTLDriver.main(OPSCTLDriver.java:25) 

[oracle@<db_name> ~]$ srvctl status database -d <db_name>
Database is running.

[oracle@<db_name> ~]$ srvctl config database -d <db_name>
Database unique name: <db_name>
Database name: <db_name>
Oracle home: <rdbms_home>/product/12.2.0.3/db_1
Oracle user: oracle
Spfile: +<diskgroup_name>/<db_name>/spfile<dba_name>.ora
Password file:
Domain: <domain_name>
Start options: open
Stop options: immediate
Database role: PRIMARY
Management policy: AUTOMATIC
Disk Groups: +<diskgroup_name1>,+<diskgroup_name2>
Services:<db_service>
OSDBA group:
OSOPER group:
Database instance: <db_name>

[oracle@<db_name> ~]$ srvctl config service -d <dbservice_name>
Service name:<dbservice_name>
Cardinality: SINGLETON
Service role: PRIMARY
Management policy: AUTOMATIC
DTP transaction: false
AQ HA notifications: false
Global: false
Commit Outcome: false
Failover type:
Failover method:
Failover retries:
Failover delay:
Failover restore: NONE
Connection Load Balancing Goal: LONG
Runtime Load Balancing Goal: NONE
TAF policy specification: NONE
Edition:
Pluggable database name:
Hub service:
Maximum lag time: ANY
SQL Translation Profile:
Retention: 86400 seconds
Replay Initiation Time: 300 seconds
Drain timeout:
Stop option:
Session State Consistency: DYNAMIC
GSM Flags: 0
Service is enabled
Service uses Java: false

 srvm.trc[main] [ 2019-05-22 11:17:58.926 EDT ] [EntityOperations.isEntityRegisteredCRSD:367] entity: ora.<db_name>.<service_name>.svc, type: 1, registered: true
[main] [ 2019-05-22 11:17:58.926 EDT ] [CRSCache.getAttributesFromCRS:155] CRS: name: ora.<db_name>.<service_name>.svc, type 1, node: null
[main] [ 2019-05-22 11:17:58.926 EDT ] [CRSCache.getAttributesFromCRS:156] attrs: [SERVER_POOLS, CARDINALITY, USR_ORA_DISCONNECT, ROLE, MANAGEMENT_POLICY, DTP, AQ_HA_NOTIFICATION, COMMIT_OUTCOME, FAILOVER_TYPE, FAILOVER_METHOD, FAILOVER_RETRIES, FAILOVER_RESTORE, TAF_FAILOVER_DELAY, CLB_GOAL, RLB_GOAL, GLOBAL, MAX_LAG_TIME, RETENTION, REPLAY_INITIATION_TIME, SESSION_STATE_CONSISTENCY, SERVICE_NAME_PQ, SERVICE_TYPE, GSM_FLAGS, TABLE_FAMILY_ID, DRAIN_TIMEOUT, STOP_OPTION, CSS_CRITICAL, TAF_POLICY, EDITION, PLUGGABLE_DATABASE, HUB_SERVICE, MAX_LAG_TIME, SQL_TRANSLATION_PROFILE, ACTIONS, ACTIVE_PLACEMENT]
[main] [ 2019-05-22 11:17:58.989 EDT ] [CRSCache.getAttributesFromCRS:163] CRS: [<ACTIONS:isJavaService,group:”dba”,user:”oracle” rf_action,group:”dba”,user:”oracle”>, <ACTIVE_PLACEMENT:0>, <AQ_HA_NOTIFICATION:0>, <CARDINALITY:1>, <CLB_GOAL:LONG>, <COMMIT_OUTCOME:0>, <CSS_CRITICAL:no>, <DRAIN_TIMEOUT:>, <DTP:0>, <EDITION:>, <FAILOVER_METHOD:>, <FAILOVER_RESTORE:NONE>, <FAILOVER_RETRIES:>, <FAILOVER_TYPE:>, <GLOBAL:false>, <GSM_FLAGS:0>, <HUB_SERVICE:>, <MANAGEMENT_POLICY:AUTOMATIC>, <MAX_LAG_TIME:ANY>, <PLUGGABLE_DATABASE:>, <REPLAY_INITIATION_TIME:300>, <RETENTION:86400>, <RLB_GOAL:NONE>, <ROLE:PRIMARY>, <SERVER_POOLS:>, <SERVICE_NAME_PQ:>, <SERVICE_TYPE:MAIN>, <SESSION_STATE_CONSISTENCY:DYNAMIC>, <SQL_TRANSLATION_PROFILE:>, <STOP_OPTION:>, <TABLE_FAMILY_ID:>, <TAF_FAILOVER_DELAY:>, <TAF_POLICY:NONE>, <USR_ORA_DISCONNECT:false>]
[main] [ 2019-05-22 11:17:58.990 EDT ] [ServiceArgs.setServiceType:230] set serviceType to MAIN
[main] [ 2019-05-22 11:17:58.990 EDT ] [ServiceArgs.setServiceType:230] set serviceType to MAIN
[main] [ 2019-05-22 11:17:58.990 EDT ] [CRSCache.getAttributesFromCRS:155] CRS: name: ora.<db_name>.<service_name>.svc, type 1, node: null
[main] [ 2019-05-22 11:17:58.990 EDT ] [CRSCache.getAttributesFromCRS:156] attrs: [SERVER_POOLS]
[main] [ 2019-05-22 11:17:59.007 EDT ] [CRSCache.getAttributesFromCRS:163] CRS: [<SERVER_POOLS:>]
[main] [ 2019-05-22 11:17:59.007 EDT ] [ServiceImpl.getServiceCardinality:3425] value of SERVER_POOLS attr :
[main] [ 2019-05-22 11:17:59.007 EDT ] [CRSCache.getAttributesFromCRS:155] CRS: name: ora.<db_name>.<service_name>.svc, type 1, node: null
[main] [ 2019-05-22 11:17:59.007 EDT ] [CRSCache.getAttributesFromCRS:156] attrs: [CARDINALITY]
[main] [ 2019-05-22 11:17:59.027 EDT ] [CRSCache.getAttributesFromCRS:163] CRS: [<CARDINALITY:1>]
[main] [ 2019-05-22 11:17:59.027 EDT ] [ServiceImpl.getServiceCardinality:3435] value of CARDINALITY attr : 1
[main] [ 2019-05-22 11:17:59.027 EDT ] [ServiceImpl.getServiceCardinality:3462] this is a SIHA service
[main] [ 2019-05-22 11:17:59.029 EDT ] [CRSCache.getAttributesFromCache:229] CRS cache: ora.<db_name>.db [<DATABASE_TYPE:SINGLE>]
[main] [ 2019-05-22 11:17:59.029 EDT ] [CRSCache.getAttributesFromCRS:155] CRS: name: ora.<db_name>.db, type 1, node: null
[main] [ 2019-05-22 11:17:59.029 EDT ] [CRSCache.getAttributesFromCRS:156] attrs: [HOSTING_MEMBERS]
[main] [ 2019-05-22 11:17:59.046 EDT ] [CRSCache.getAttributesFromCRS:163] CRS: [<HOSTING_MEMBERS:>]
[main] [ 2019-05-22 11:17:59.046 EDT ] [CRSCache.getAttributesFromCRS:155] CRS: name: ora.<db_name>.db, type 1, node: null
[main] [ 2019-05-22 11:17:59.046 EDT ] [CRSCache.getAttributesFromCRS:156] attrs: [SERVER_POOLS]
[main] [ 2019-05-22 11:17:59.068 EDT ] [CRSCache.getAttributesFromCRS:163] CRS: [<SERVER_POOLS:>]
Exception in thread “main”
java.lang.NullPointerException
at oracle.ops.opsctl.StatusAction.internalExecuteService(StatusAction.java:2038)
at oracle.ops.opsctl.StatusAction.executeSIHAService(StatusAction.java:1652)
at oracle.ops.opsctl.Action.executeSIHA(Action.java:443)
at oracle.ops.opsctl.OPSCTLDriver.execute(OPSCTLDriver.java:537)
at oracle.ops.opsctl.OPSCTLDriver.main(OPSCTLDriver.java:252)
[Thread-1] [ 2019-05-22 11:17:59.069 EDT ] [InnerInterruptHandler.run:116] Running the shutdown hook
[Thread-1] [ 2019-05-22 11:17:59.069 EDT ] [InnerInterruptHandler.run:120] Calling Interrupt handler….ctrlCHandler
[Thread-1] [ 2019-05-22 11:17:59.069 EDT ] [CommandLineParser.<init>:506] Is this a cluster? : false
[Thread-1] [ 2019-05-22 11:17:59.070 EDT ] [OPSCTLDriver.ctrlCHandler:306] Stopped srvctl execution
[Thread-1] [ 2019-05-22 11:17:59.070 EDT ] [OPSCTLDriver.ctrlCHandler:307] Invoking interrupt handler
[Thread-1] [ 2019-05-22 11:17:59.070 EDT ] [CmdOptVals.isOptionSet:1076] Calling isOptionSet for verbose
[Thread-1] [ 2019-05-22 11:17:59.070 EDT ] [OptVal.isSet:155] m_value is null
[Thread-1] [ 2019-05-22 11:17:59.070 EDT ] [SRVCTLHandler.getMethodName:122] getMethodName: Method Name = status_service_Handler
[Thread-1] [ 2019-05-22 11:17:59.070 EDT ] [SRVCTLHandler.invokeCtrlCHandler:230] Interrupt handler method status_service_Handler
[Thread-1] [ 2019-05-22 11:17:59.070 EDT ] [SRVCTLHandler.invokeCtrlCHandler:231] Interrupt handler class oracle.ops.opsctl.StatusAction
[Thread-1] [ 2019-05-22 11:17:59.071 EDT ] [SRVCTLHandler.invokeCtrlCHandler:244] oracle.ops.opsctl.StatusAction.status_service_Handler()
java.lang.Class.getMethod(Class.java:1786)
oracle.ops.opsctl.SRVCTLHandler.invokeCtrlCHandler(SRVCTLHandler.java:234)
oracle.ops.opsctl.OPSCTLDriver.ctrlCHandler(OPSCTLDriver.java:308)
sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
java.lang.reflect.Method.invoke(Method.java:498)
oracle.cluster.common.InnerInterruptHandler.run(InterruptHandler.java:123)
[Thread-1] [ 2019-05-22 11:17:59.086 EDT ] [OPSCTLDriver.ctrlCHandler:311] PRCG-1036 : Internal error.
oracle.ops.opsctl.SRVCTLHandler.invokeCtrlCHandler(SRVCTLHandler.java:245)
oracle.ops.opsctl.OPSCTLDriver.ctrlCHandler(OPSCTLDriver.java:308)
sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
java.lang.reflect.Method.invoke(Method.java:498)
oracle.cluster.common.InnerInterruptHandler.run(InterruptHandler.java:123)

CAUSE

Due to bug 29839229
 

SOLUTION

As workaround,

srvctl status service -d <dbname> -s <service_name>

Bug 29839229 fixed in a 20.1 version, request/apply patch 29839229 for your platform/version

%d bloggers like this: