sapcontrol -nr 00 -function StopSystem
sapcontrol -nr 00 -function StartSystem
HANA Database is not coming online and we see that Index Server is Initializing and we waited for 25 mins and no luck
3. We see that HANA trying to recovery and but not coming online.
We have seen this type of behavior earlier but not same errors, restarting HANA helped to resolve the issue. We restarted HANA again and to see where it helps, but still “HANA Index Server is Initializing” and the log stopped at below error and no further update..
After reviewing the logs I see that many errors are DEVIATING the problem and it looks like issue with log segment. Normally you will see this behavior when your log file system is full or backup backup file system is full.
I have verified all locations and everything looks good except log backup location. When I am trying to list or view the log backups it just hung, I see that there is some issue with backup location.
We have unmounted and remounted back and also renamed old backup location and created new. When I look into the logs I see that HANA coming online..
As you see below log HANA was just hanging and after fixing issue immediately HANA coming online.
Note that during HANA index server initialization, it needs all required resources for rollback,recovery,backup..etc. But log backup mount point was timing out and not accessible from HANA side which is causing the issue.
sapcontrol -nr 00 -function StartSystem
HANA Database is not coming online and we see that Index Server is Initializing and we waited for 25 mins and no luck
$ sapcontrol -nr 00 -function
GetProcessList
11.12.2017 08:29:31
GetProcessList
OK
name, description, dispstatus,
textstatus, starttime, elapsedtime, pid
hdbdaemon, HDB Daemon, GREEN,
Running, 2017 12 04 21:58:59, 154:30:32, 5259
hdbcompileserver, HDB
Compileserver, GREEN, Running, 2017 12 04 21:59:31, 154:30:00, 5490
hdbindexserver, HDB Indexserver,
YELLOW, Initializing, 2017 12 04 21:59:33, 154:29:58, 5528
hdbnameserver, HDB Nameserver,
GREEN, Running, 2017 12 04 21:59:03, 154:30:28, 5283
hdbpreprocessor, HDB
Preprocessor, YELLOW, Initializing, 2017 12 04 21:59:31, 154:30:00, 5492
hdbwebdispatcher, HDB Web
Dispatcher, YELLOW, Running, 2017 12 04 22:37:54, 153:51:37, 11186
hdbxsengine, HDB XSEngine, YELLOW,
Initializing, 2017 12 04 21:59:33, 154:29:58, 5530
In meanwhile when I look into the logs I see below errors
1. HANA OUT OF MEMORY, that is expected
In meanwhile when I look into the logs I see below errors
1. HANA OUT OF MEMORY, that is expected
indexserver_scllpa0000012.30003.rtedump.20171204-173900.014195.compositelimit_oom.trc
Composite limit violation (OUT OF MEMORY)
occurred.
2. This below error is new and not seen in HANA logs before
Unknown pending
exception
Throw location
of the exception unknown
[4216]{-1}[-1/-1]
2017-12-04 19:58:44.751308 d Crypto
RootKeyStoreAccessorBase.cpp(00093) : Caught
RootKeyStoreRecordNotFoundException reading SSFS version
/usr/sap/HANADBX/SYS/global/hdb/security/ssfs:HDB_SERVER/PERSISTENCE/ROOTKEY/VERSION
[4216]{-1}[-1/-1]
2017-12-04 19:58:44.751320 a Crypto
RootKeyStoreAccessorBase.cpp(00072) : ExcExit time_t
Crypto::SecureStore::RootKeyAccess::RootKeyStoreAccessorBase::readValueForContentKey(const
string&, Crypto::Buffer&)(1596usec)
exception 1: no.301103
(Crypto/Ssfs/RootKeyAccess/RawAccess/RawRootKeyStoreReaderWriter.cpp:52)
RawRootKeyStoreReader::read: SSFS-4218:
Record with key "HDB_SERVER/PERSISTENCE/ROOTKEY/VERSION" not found in
secure storage <-- SSFS-4215: Data file
"/usr/sap/HANADBX/SYS/global/hdb/security/ssfs/SSFS_HANADBX.DAT"
exists, but does not contain the requested entry
exception throw
location:
1: 0x00007fd869fe4721 in
Crypto::SecureStore::RootKeyAccess::RawAccess::RawRootKeyStoreReader::read(Crypto::Buffer&)+0x40
at RawRootKeyStoreReaderWriter.cpp:86 (libhdbbasement.so)
2: 0x00007fd869fe2f06 in Crypto::SecureStore::RootKeyAccess::RawAccess::RawRootKeyStore<false,
false>::read(ltt::basic_string<char, ltt::char_traits<char> >
const&, ltt::basic_string<char,
[4216]{-1}[-1/-1]
2017-12-04 19:59:59.100341 i Logger
PersistenceManagerImpl.cpp(06361) : Starting log replay at position
0x2b6f7dd9d02
[4216]{-1}[-1/-1]
2017-12-04 19:59:59.100362 i Logger
RecoveryHandlerImpl.cpp(01681) : Triggering recovery of remaining log
[4216]{-1}[-1/-1]
2017-12-04 19:59:59.100399 i Logger
RecoveryHandlerImpl.cpp(01741) : Finishing log recovery, waiting for
in-process and in-load segments
[4607]{-1}[-1/-1]
2017-12-04 19:59:59.100685 i Logger
PersistenceManagerImpl.cpp(05084) : Found savepoint 253169 log record
[4607]{-1}[-1/-1]
2017-12-04 19:59:59.143111 i Logger
RecoveryHandlerImpl.cpp(02271) : Log recovery cannot expect any more
data at position 0x2b6f7decec0, load states:
-
LogPartition[/hana/log/HANADBX/mnt00001/hdb00004/:0]: #segments 0/1 processed,
1/1 loaded, 1 total, last loaded
LogSegment[0:0x2b6f7dd6d80/Writing,ts=2017-12-04
19:55:56.333631][GUID=5575D4BD-004F-20171119-045408-3E00001BA3/PrevGUID=5575D4BD-004F-20171119-045408-3E00001BA2/PersGUID=47A64522-004F-20150528-232756-3C50000001/RestoreGUID=74736948-6469-7547-0000-002000000000]
[4607]{-1}[-1/-1] 2017-12-04 19:59:59.143164 i
Logger
RecoveryHandlerImpl.cpp(02553) : Recovery finished at log position
0x2b6f7decec0
[4597]{-1}[-1/-1] 2017-12-04 19:59:59.582532 i
Logger
RecoveryHandlerImpl.cpp(03921) : Signaling finish wait barrier
[4216]{-1}[-1/-1] 2017-12-04 19:59:59.586365 i
Logger LogSegment.cpp(00672) :
Closing open log segments after log recovery completed at position
0x2b6f7decec0
[4216]{-1}[-1/-1] 2017-12-04 19:59:59.586411 i
Logger LogSegment.cpp(00760) : Closing open
on-disk segment
LogSegment[0/18:0x2b6f7dd6d80-0x2b6f7decec0(0x585000B)/GUID=5575D4BD-004F-20171119-045408-3E00001BA3/PrevGUID=5575D4BD-004F-20171119-045408-3E00001BA2,TS=2017-12-04
19:55:56.333631,Hole=0x2b6f7dd6d80/Writing/0x0]@0x00007f43f1a385c0 after log
recovery completed at position 0x2b6f7decec0
[4216]{-1}[-1/-1] 2017-12-04 19:59:59.587204 i
Logger LoggerImpl.cpp(01468) :
Replayed 5009280B (4MB) of log in 1.522 seconds; 3.13877MB/s; max known
TID=379629377
[4216]{-1}[-1/-1] 2017-12-04 19:59:59.587299 i
Logger LoggerImpl.cpp(01064) :
Starting logger with 8 log buffers per partition, 1024KB each, segment size
1024MB, log mode normal
[4511]{-1}[-1/-1] 2017-12-04 20:00:39.628427 i
Logger
RecoveryHandlerImpl.cpp(00701) : Termination of indoubt transactions.
(raw page size in bytes to be still rolled back 136717467648 or garbage
collected 0)
[4512]{-1}[-1/-1]
2017-12-04 20:01:29.664585 i Logger
RecoveryHandlerImpl.cpp(00701) : Termination of indoubt transactions.
(raw page size in bytes to be still rolled back 133028642816 or garbage
collected 0)
[4216]{-1}[-1/-1]
2017-12-04 19:59:05.121382 i Logger
LoggerImpl.cpp(00525) : Setting log segment
backup timeout to 900s, original value was 0s
[4216]{-1}[-1/-1]
2017-12-04 19:59:05.190851 i PersistenceManag PersistenceManagerImpl.cpp(05984)
: BACKUP DATA seems to have been executed, database should be recoverable from
backup
[4216]{-1}[-1/-1]
2017-12-04 19:59:05.190879 i Logger
PersistenceManagerImpl.cpp(06226) : Deactivating REDO logging for log
replay
[4216]{-1}[-1/-1]
2017-12-04 19:59:05.190881 i Logger
PersistenceManagerImpl.cpp(06237) : Start termination of rollback(s)
open in restart/backup savepoint
[4216]{-1}[-1/-1]
2017-12-04 19:59:32.523954 i Logger
PersistenceManagerImpl.cpp(06245) : Termination of rollback(s) open in
restart/backup savepoint finished in 27.2676 seconds;
[4607]{-1}[-1/-1]
2017-12-04 19:59:59.143164 i Logger
RecoveryHandlerImpl.cpp(02553) : Recovery finished at log position
0x2b6f7decec0
[4597]{-1}[-1/-1]
2017-12-04 19:59:59.582532 i Logger
RecoveryHandlerImpl.cpp(03921) : Signaling finish wait barrier
[4216]{-1}[-1/-1]
2017-12-04 19:59:59.586365 i Logger
LogSegment.cpp(00672) : Closing open log segments after log recovery
completed at position 0x2b6f7decec0
[4216]{-1}[-1/-1]
2017-12-04 19:59:59.586411 i Logger
LogSegment.cpp(00760) : Closing open on-disk segment
LogSegment[0/18:0x2b6f7dd6d80-0x2b6f7decec0(0x585000B)/GUID=5575D4BD-004F-20171119-045408-3E00001BA3/PrevGUID=5575D4BD-004F-20171119-045408-3E00001BA2,TS=2017-12-04
19:55:56.333631,Hole=0x2b6f7dd6d80/Writing/0x0]@0x00007f43f1a385c0 after log
recovery completed at position 0x2b6f7decec0
[4216]{-1}[-1/-1]
2017-12-04 19:59:59.587204 i Logger
LoggerImpl.cpp(01468) : Replayed 5009280B (4MB) of log in 1.522 seconds;
3.13877MB/s; max known TID=379629377
[4216]{-1}[-1/-1]
2017-12-04 19:59:59.587299 i Logger
LoggerImpl.cpp(01064) : Starting logger with 8 log buffers per
partition, 1024KB each, segment size 1024MB, log mode normal
[4511]{-1}[-1/-1]
2017-12-04 20:00:39.628427 i Logger
RecoveryHandlerImpl.cpp(00701) : Termination of indoubt transactions.
(raw page size in bytes to be still rolled back 136717467648 or garbage
collected 0)
[4607]{-1}[-1/-1]
2017-12-04 19:59:59.143164 i Logger
RecoveryHandlerImpl.cpp(02553) : Recovery
finished at log position 0x2b6f7decec0
[4597]{-1}[-1/-1]
2017-12-04 19:59:59.582532 i Logger
RecoveryHandlerImpl.cpp(03921) : Signaling
finish wait barrier
After reviewing the logs I see that many errors are DEVIATING the problem and it looks like issue with log segment. Normally you will see this behavior when your log file system is full or backup backup file system is full.
I have verified all locations and everything looks good except log backup location. When I am trying to list or view the log backups it just hung, I see that there is some issue with backup location.
We have unmounted and remounted back and also renamed old backup location and created new. When I look into the logs I see that HANA coming online..
As you see below log HANA was just hanging and after fixing issue immediately HANA coming online.
[5699]{-1}[-1/-1] 2017-12-04 22:07:28.699548 i Basis Helper.cpp(00514) : Using 'x64_64 ABI unwind' for stack tracing
[5576]{-1}[-1/-1] 2017-12-04 22:37:20.216535 i Logger LogSegment.cpp(00672) : Closing open log segments after log recovery completed at position 0x2b6f7decf00
[5576]{-1}[-1/-1] 2017-12-04 22:37:20.216830 i Logger LogSegment.cpp(00760) : Closing open on-disk segment LogSegment[0/32:0x2b6f7decec0-
