Skip to end of metadata
Go to start of metadata

SAP® MaxDB - Database Start


This section describes the steps of a SAP MaxDB database restart which are logged in the KnlMsg & KnlMsg.old files.

Moderator: Birgit Malik

WIKI Space Editor: Thiago Lüttig


This section explains the different messages logged in file KnlMsg (knldiag)  during the database start. Most examples on the following pages are from a database of version 7.9. The procedure is mostly similar in older versions, although  less messages might be logged and the order of the entries in KnlMsg might be different. If an example is from an older version this is explicitly mentioned.

Details Starting Database into ADMIN

Version Information

In between you'll see the version information of the database kernel and the runtime. An additional important information for the support is which kernel is started - slow: debug-kernel or fast which is the kernel which is in use in production environment.
Example:


RTEKernel     14:  Kernel version: Kernel    7.9.08   Build 037-013-000-000     
RTEKernel     15:  Runtime version: W64/AMD64 7.9.08   Build 037-013-000-000 
RTEKernel     20:  Version: FAST

 back to top

Backup of Diagnostic Files & Database Parameter Setting

In the first step the database parameters are read: in the beginning the RUNDIRECTORY, in which file KnlMsg (knldiag) will be created, and the TASKCLUSTER, which defines the process structure of the kernel; both are very important for the database start. As of database version 7.6.00 all database parameters are logged in KnlMsg ((knldiag) and as of database version 7.9 those database parameters which have been modified by the administrators are marked with (U).
If the last stop of the database was not performed with a normal shutdown (DBM command db_offline) but e.g. because the database crashed or because the server was rebooted the DIAGHISTORY will be written. First of all during the next restart file KnlMsg (knldiag) is copied to KnlMsg.old ( knldiag.old) then the new KnlMsg (knldiag) is opened. In KnlMsg it is logged that all diagnostic files are copied to DIAGHISTORY.

Example:

:
2015-12-28 15:13:41     RTE        20237:  Start dumping all kernel parameters - (U) user modified, (D) user modified and deprecated
2015-12-28 15:13:41     RunTime       15:    ( )  AbortHandlingMode=BacktraceOnly
2015-12-28 15:13:41     RunTime       15:    ( )  AdditionalLogQueueIOLimitation=0
2015-12-28 15:13:41     RunTime       15:    ( )  AllocatorRegistryCheckLevel=OFF
2015-12-28 15:13:41     RunTime       15:    ( )  AllowAuthentication=
2015-12-28 15:13:41     RunTime       15:    ( )  AutoLogBackupSize=85333
2015-12-28 15:13:41     RunTime       15:    ( )  BacktraceOnError=0
2015-12-28 15:13:41     RunTime       15:    ( )  BridgeCommunicationTimeout=600
2015-12-28 15:13:41     RunTime       15:    ( )  BridgeType=NONE
2015-12-28 15:13:41     RunTime       15:    (U)  CacheMemorySize=512896
2015-12-28 15:13:41     RunTime       15:    ( )  CallStackLevel=0
2015-12-28 15:13:41     RunTime       15:    ( )  CAT_CACHE_SUPPLY=21376
:
2015-12-28 15:13:41     RTE        20239:    Dump of all kernel parameters done

 back to top

TASKCLUSTER

The TASKCLUSTER is logged in file KnlMsg (knldiag) and specifies the structure of the database kernel. The number of tasks does not specify how many tasks will actually be created of each task type but how many tasks of which type can run in one User Kernel Thread (UKT). Additionally it is logged how many tasks of each type are actually created. tw: trace writer, lw: log writer, plw: parallel log writer, ut: utility task, SV: server tasks, fs: floating tasks, gc: garbage collector tasks, ti: timer task, us: user tasks.

Example:

2016-01-21 10:02:36     TCLUSTER   19692:  tw;lw;ut;2000*sv;10*fs;10*gc;ti;1*plw,15*us;equalize
2016-01-21 10:02:36     TCLUSTER   19693:  number of 'PLW':   0
2016-01-21 10:02:36     TCLUSTER   19693:  number of ' US':  30
2016-01-21 10:02:36     TCLUSTER   19693:  number of ' SV':  50
2016-01-21 10:02:36     TCLUSTER   19693:  number of ' FS':   8
2016-01-21 10:02:36     TCLUSTER   19693:  number of ' GC':   2
2016-01-21 10:02:36     TCLUSTER   19692:  Total Number of TaskSchedulers 9
2016-01-21 10:02:36     TCLUSTER   19692:  Number of TaskSchedulers with User Tasks 2
:
2016-01-21 10:02:36    RTETask 40: UKT_CPU_RELATIONSHIP set to NONE, no explicit CPU affinity set

back to top

Memory Allocation Limit

As of database version 7.5.00 it is logged whether the amount of memory which the database is allowed to allocate is limited. It is also logged if the system page cache is disabled. Both would differ from the DEFAULT and should be checked. Disabling the system page cache can for example cause massive performance problems.

 2016-01-21 10:02:36 RTE 20224: System page cache usage enabled

back to top

Server and Database Information

The next part shows some information regarding the starting database. This includes e.g. the database name, the server name, the process ID, the number of processors and the available memory.
Example:

2016-01-21 10:02:36     RTEKernel     13:  Starting kernel for database 'MU790819'
2016-01-21 10:02:36     RTEKernel     14:  Kernel version: Kernel    7.9.08   Build 037-013-000-000
2016-01-21 10:02:36     RTEKernel     15:  Runtime version: W64/AMD64 7.9.08   Build 037-013-000-000
2016-01-21 10:02:36     RTEKernel     20:  Version: FAST
2016-01-21 10:02:36     RTEKernel     17:  Node name: BERD31645738A.emea.global.corp.sap
2016-01-21 10:02:36     RTEKernel     19:  64BIT Kernel
2016-01-21 10:02:36     RTEKernel     23:  Current directory: C:\sapdb\data\wrk\MU790819
2016-01-21 10:02:36     RTEKernel    123:  Minimum thread stack size: 0 bytes
2016-01-21 10:02:36     RTEKernel     21:  Machine: AMD64 level 6 revision 3a09
2016-01-21 10:02:36     RTEKernel     22:  Processors: 1 (logical: 8, cores: 4)
2016-01-21 10:02:36     RTEKernel    122:   - logical CPU 0: physical ID 0, core ID 0
2016-01-21 10:02:36     RTEKernel    122:   - logical CPU 1: physical ID 0, core ID 0
2016-01-21 10:02:36     RTEKernel    122:   - logical CPU 2: physical ID 0, core ID 1
2016-01-21 10:02:36     RTEKernel    122:   - logical CPU 3: physical ID 0, core ID 1
2016-01-21 10:02:36     RTEKernel    122:   - logical CPU 4: physical ID 0, core ID 2
2016-01-21 10:02:36     RTEKernel    122:   - logical CPU 5: physical ID 0, core ID 2
2016-01-21 10:02:36     RTEKernel    122:   - logical CPU 6: physical ID 0, core ID 3
2016-01-21 10:02:36     RTEKernel    122:   - logical CPU 7: physical ID 0, core ID 3
2016-01-21 10:02:36     INFO       19771:           Process ID:                8596
2016-01-21 10:02:36     INFO       19773:           Date:                      2016-01-21
2016-01-21 10:02:36     INFO       19772:           Owner:                     'SYSTEM'
2016-01-21 10:02:36     INFO       19772:           Computer:                  'BERD31645738A'
2016-01-21 10:02:36     INFO       19772:           Domain:                    'emea.global.corp.sap'
2016-01-21 10:02:36     INFO       19774:           Product suite:             'Terminal Server'
2016-01-21 10:02:36     INFO       19776:           Max virtual memory:        8388607 MB
2016-01-21 10:02:36     INFO       19777:           Total physical memory:     8109 MB
2016-01-21 10:02:36     INFO       19778:           Available physical memory: 5288 MB

back to top

I/O Buffer Cache

As of database version 7.5.00 it is logged how many pages are allocated for the I/O buffer cache.

 2016-01-21 10:02:36 RTEKernel 30: I/O buffer cache: 20010 pages allocated

back to top

Eventing

You can configure that events (like DB Full, error occured, ...) are logged and added to the event queue. Event tasks can read the event queue and this would allow database studio to display such events. However, in database versions < 7.5.00 the eventing is rarely used. 
As of database version 7.5.00 the SAP MaxDB eventing can be configured easier with DBM server and it might be used more often. Then you will see in KnlMsg that an event buffer was created, how many entries fit into that buffer and how many event tasks were created.
Example:

2016-01-21 09:51:14     RTEKernel    126:  No event file configured, suppressing output of events
2016-01-21 09:51:14     EVENTING   19812:  Eventbuffer 150 events 8 tasks

 back to top

Starting Threads

Now the state of the COM trace is logged and the different threads are started. All actions so far were done by the coordinator thread. For each thread which is now started its TID is logged. Besides the special threads at least the user kernel threads (UKTs) are started (for trace writer TW, log writer lw, utility task ut, server tasks sv,... and user tasks US).

Example:

Thread     0x2B10 Task      -  2016-01-21 10:02:36     RTEKernel    126:  No event file configured, suppressing output of events
Thread     0x2B10 Task      -  2016-01-21 10:02:36     EVENTING   19812:  Eventbuffer 150 events 8 tasks 
Thread     0x24E8 Task      -  2016-01-21 10:02:36     THREAD     19688:  CLOCK thread started 
Thread     0x2750 Task      -  2016-01-21 10:02:37     THREAD     19688:  TIMER thread started 
Thread     0x2A18 Task      -  2016-01-21 10:02:37     RTE        20217:  CONSOLE thread started 
Thread     0x2F40 Task      -  2016-01-21 10:02:37     RTE        20217:  Requestor thread started 
Thread     0x2F88 Task      -  2016-01-21 10:02:37     RTEThread     12:  The thread Requestor_MU790819 has started 
Thread     0x2F08 Task      -  2016-01-21 10:02:37     RTEThread     12:  The thread LegacyRequestor has started 
Thread     0x2B10 Task      -  2016-01-21 10:02:37     TRACE_IO   19831:  Configured _MAX_MESSAGE_FILES:0 
Thread     0x2B10 Task      -  2016-01-21 10:02:37     TRACE_IO   19832:  Disabled: No TraceMessagefiles wanted
:
Thread      0x878 Task      -  2016-01-21 10:02:37     RTETask       37:  UKT1 started 
Thread     0x1CF8 Task      -  2016-01-21 10:02:37     RTETask       37:  UKT2 started 
Thread     0x2BAC Task      -  2016-01-21 10:02:37     RTETask       37:  UKT3 started 
Thread     0x2BF8 Task      -  2016-01-21 10:02:37     RTETask       37:  UKT4 started 
Thread     0x3310 Task      -  2016-01-21 10:02:37     RTETask       37:  UKT5 started 
Thread      0xF44 Task      -  2016-01-21 10:02:37     RTETask       37:  UKT6 started 
Thread      0x744 Task      -  2016-01-21 10:02:37     RTETask       37:  UKT7 started 
Thread     0x3120 Task      -  2016-01-21 10:02:37     RTETask       37:  UKT8 started 
Thread     0x2DB8 Task      -  2016-01-21 10:02:37     RTETask       37:  UKT9 started

back to top

Attaching knltrace

Then the UKT containing the user tasks formats and attaches the knltrace.
Example:

2016-01-21 10:02:37     RTEIO        112:  Medium C:\sapdb\data\wrk\MU790819\knltrace was opened for WRITE as medium number 1
2016-01-21 10:02:37     RTEIO         71:  Formatting of volume TRACE_VOLUME_001 from page 1 (8192) to page 11570 (94781440) started
2016-01-21 10:02:37     RTEIO         74:  Formatting of volume TRACE_VOLUME_001 in progress, 11569 pages to format
2016-01-21 10:02:39     RTEIO         76:  Formatting of volume TRACE_VOLUME_001 done
2016-01-21 10:02:39     RTEIO        114:  Medium C:\sapdb\data\wrk\MU790819\knltrace with medium number 1 was closed
2016-01-21 10:02:39     RTEIO         10:  Volume TRACE_VOLUME_001 is assigned to volume number 1
2016-01-21 10:02:39     RTEIO          8:  Volume TRACE_VOLUME_001 on knltrace was attached

back to top

Allocation of Memory (DYNPOOL,DYNDATA)

Memory for SHARED DYNDATA and SHARED DYNPOOL. DYNDATA and DYNPOOL are two memory pools from which later on different memory allocations are served. DYNDATA is a memory area suited for I/O from which the memory is allocated page-wise. DYNPOOL is an area from which memory is allocated byte-wise.

Example:

 

2016-01-21 10:02:39     dynpool       54003: DATACACHE MANAGER :        5504
2016-01-21 10:02:39     dynDATA    54003:  DYND_K57_KB_PAGES      :        11
2016-01-21 10:02:39     SrvTasks            9:  Available Servertasks:                   50
2016-01-21 10:02:39     dynpool      54003:  HIST_DIR  item size    :                    8
2016-01-21 10:02:39     dynpool      54003:  HIST_DIR  num items    :                  2
2016-01-21 10:02:39     dynpool      54003:  DYNP_B930_HIST_DIR     :           16

 

back to top

Starting Server Tasks

After the different memory allocations took place the server tasks are started.

Example:

2016-01-21 10:02:40     SrvTasks      31:  Permanently reserved 16 servertasks for 'Backup / Restore'.
2016-01-21 10:02:40     SrvTasks      31:  Permanently reserved 2 servertasks for 'Backup / Restore'.
2016-01-21 10:02:40     SrvTasks      31:  Permanently reserved 1 servertasks for 'Savepoint'.
2016-01-21 10:02:40     SrvTasks      31:  Permanently reserved 1 servertasks for 'Data cache I/O acknowledgment'.
2016-01-21 10:02:40     SrvTasks      31:  Permanently reserved 1 servertasks for 'Data cache replacement I/O'.
2016-01-21 10:02:40     SrvTasks      31:  Permanently reserved 1 servertasks for 'Volume resize acknowledgement'.

 back to top

Initialization Completed

As of database version 7.6.00 it is logged when the kernel initialization - which must run in single task mode - is finished.
Example version 7.9

 2016-01-21 10:02:40 RTETask 18: Kernel initialization done                         
                     DESCRIPTION:
                     The initialization of the Kernel components has finished. All special tasks are started now.
2016-01-21 10:02:40 RunTime        3:  State changed from STARTING to ADMIN


back to top

SERVERDB is Ready

When message DBSTATE SERVERDB is ready is logged in KnlMsg, the database is in operational state ADMIN and all user tasks as well as the utility task are in state connect wait.
Example:

 2016-01-21 10:02:42 STATE 19601: SERVERDB is ready 


back to top

Details Starting Database into ONLINE

Automatic Restart

Windows: is the kernel service configured with automatic start the database is started automatically into ONLINE mode.

2005-03-30 10:46:21      0x4E0       221     RTE Database tries automatic restart
...
2005-03-30 10:46:44      0x6EC       222     RTE Database automatic restart reported ok

 back to top

Connect

For the start from state ADMIN to state ONLINE first of all a user task (version < 7.6 : the utility task) performs a connect. The database manager performs several actions if this is configured accordingly - e.g. activating the database trace or the eventing. These actions are executed by a user Task  (in versions < 7.6 by the utility task)  and they are encapsulated - i.e. for each action a connect with a usertask is executed and it is released afterwards. 
Example:

2016-01-21 10:02:42     CONNECT    19633:  Connect req. (MU790819, T95, ..... Node:'....', PID: 11880)

 back to top

Attaching volumes

Next the volumes are attached in the configured order (parameter file). First the converter is stored on the data volumes, then DATA_VOLUME_0001, then DATA_VOLUME0_002, ... , and lastly the log volumes. After the first data volume was opened the restart record is read. When the volumes are opened several checks are performed. This includes that the RTE (Runtime Environment) checks its ‚Magic Page'.
In version 7.3.00 the sum of the single data volume size is compared with the value from the restart record. Are these values not the same, the restart is aborted. That way it is prevented that the database is started with wrong volumes. However, when the volumes are replaced with other volumes of the same size, this was not recognized. This size entry in the restart record exists specifically for that comparison.
This check does not exist anymore as of version 7.4. As of version 7.4. there is a so called IO manager info page on each volume, which contains the following information:

  • Capacity
  • logical ID
  • previous logical ID
  • next logical ID
  • Bad flag (specifies if the volume must not be opened anymore because of an error)
  • ResetBadFlagCount (specifies how often the bad flag was reset using a specific command)
  • db_ident (from the point in time ot the init config)

    With this information it can be easier identified if the correct volumes were attached. Using previous and next logical ID it can also be clarified if the volumes are still attached in the original order and if volumes are missing. This is important as on the converter pages the position of data pages is stored as ‚page xyz on DEVNO n, offset abc'. If two volumes were switched DEVNO n specifies a different volume and the data cannot be found anymore. The IO manager info page has to be newly created during the migration from version 7.3.00 to 7.4.x (or higher). This happens during the inplace migration. Log volumes additionally contain a log info page, which contains the current db_ident among other things. All these checks are only visible in KnlMsg/knldiag if an error occured. Normally only messages regarding the attaching of volumes and starting of I/O threads are logged.
    Example:

    2016-01-21 10:02:43     RTEIO         10:  Volume DATA_VOLUME_0001 is assigned to volume number 2 
    2016-01-21 10:02:43     RTEIO          8:  Volume DATA_VOLUME_0001 on MUT_DATA_1 was attached 
    2016-01-21 10:02:43     RTEIO         10:  Volume DATA_VOLUME_0002 is assigned to volume number 3 
    2016-01-21 10:02:43     RTEIO          8:  Volume DATA_VOLUME_0002 on MUT_DATA_2 was attached 
    2016-01-21 10:02:43     RTEIO         10:  Volume DATA_VOLUME_0003 is assigned to volume number 4 
    2016-01-21 10:02:43     RTEIO          8:  Volume DATA_VOLUME_0003 on MUT_DATA_3 was attached 
    2016-01-21 10:02:43     RTEIO         10:  Volume DATA_VOLUME_0004 is assigned to volume number 5 
    2016-01-21 10:02:43     RTEIO          8:  Volume DATA_VOLUME_0004 on MUT_DATA_4 was attached 
    2016-01-21 10:02:43     RTEIO         10:  Volume LOG_VOLUME_001 is assigned to volume number 6 
    2016-01-21 10:02:43     RTEIO          8:  Volume LOG_VOLUME_001 on MUT_LOG_1 was attached 
    2016-01-21 10:02:43     RTEIO         10:  Volume LOG_VOLUME_002 is assigned to volume number 7 
    2016-01-21 10:02:43     RTEIO          8:  Volume LOG_VOLUME_002 on MUT_LOG_2 was attached 
    2016-01-21 10:02:43     RTEIO         10:  Volume LOG_VOLUME_003 is assigned to volume number 8 
    2016-01-21 10:02:43     RTEIO          8:  Volume LOG_VOLUME_003 on MUT_LOG_3 was attached


    back to top

    Read converter

    In the next step the converter cache and the FBM (free block manager) are created and the converter is read.
    Example:

    2016-01-21 10:02:43	Converter  20054:  Start read tenant with partition ID 0 and converter version: 116
    2016-01-21 10:02:43     DATA       12345:  Start of FBM section list construction
    2016-01-21 10:02:43     DATA 	   12345: End of FBM section list construction
    2016-01-21 10:02:43     Converter  20055:  Stop read converter, 25 pages read with 25 io calls
    

    As of version 7.5.00 a snapshot might exist in the database. In that case additionally the snapshot converter has to be read during the database start.
    Example version 7.6.00:

    2005-04-12 16:37:56      0x834        22 Pager    Start Read Snapshot Converter
    2005-04-12 16:37:56      0x834        18 Pager    Stop Read Converter, Pages: 24 IO: 24
    

     back to top

DATA CACHE

Then the data cache is created. As many memory chunks are allocated as specified with parameter DataCacheStripes (_DATA_CACHE_RGNS). The size of each critical region is:

  • versions < 7.4.00: DATA_CACHE/_DATA_CACHE_RGNS. The result is rounded off - therefore not exactly as much memory as specified with DATA_CACHE is allocated.
  • As of version 7.4.00: (CACHE_SIZE - converter cache)/_DATA_CACHE_RGNS.

  • As of version 7.7.03: (CacheSize - converter cache) / DataCacheStripes.

 Example: In this example 16 critical regions are created, each with a size of 128 pages.

2016-01-21 10:02:43     DataCache     19:  Begin restart  
2016-01-21 10:02:43     dynpool    54003:  DATACACHE STRIPES      :     16  
2016-01-21 10:02:43     dynpool    54003:  DATACACHE HASH LIST    :2553088  
2016-01-21 10:02:43     dynpool    54003:  DATACACHE head item siz:     16  
2016-01-21 10:02:43     dynpool    54003:  DATACACHE IO CHAINS    :      1 
2016-01-21 10:02:43     dynpool    54003:  DATACACHE io chain size:     56  
2016-01-21 10:02:43     dynpool    54003:  DATACACHE CONTROLBLOCKS:2545664  
2016-01-21 10:02:43     dynpool    54003:  DATACACHE cblock size  :    128  
2016-01-21 10:02:43     KernelDBE_ 20005:  data cache size reach about 20 percent of configured size  
2016-01-21 10:02:43     KernelDBE_ 20005:  data cache size reach about 30 percent of configured size  
2016-01-21 10:02:43     KernelDBE_ 20005:  data cache size reach about 40 percent of configured size  
2016-01-21 10:02:43     KernelDBE_ 20005:  data cache size reach about 50 percent of configured size  
2016-01-21 10:02:43     KernelDBE_ 20005:  data cache size reach about 60 percent of configured size  
2016-01-21 10:02:43     KernelDBE_ 20005:  data cache size reach about 70 percent of configured size  
2016-01-21 10:02:43     KernelDBE_ 20005:  data cache size reach about 80 percent of configured size  
2016-01-21 10:02:43     KernelDBE_ 20005:  data cache size reach about 90 percent of configured size  
2016-01-21 10:02:43     KernelDBE_ 20005:  data cache size reach about 95 percent of configured size  
2016-01-21 10:02:43     KernelDBE_ 20005:  data cache size reach about 99 percent of configured size  
2016-01-21 10:02:43     dynpool    54003:  DYNP_B20_DATACACHE     :5257856  
2016-01-21 10:02:43     dynDATA    54003:  DYND_B20_DATACACHE     :  19888  
2016-01-21 10:02:43     DataCache     20:  End restart 

 back to top 

Restart FileDir

After the data cache was created first the LOB (Blob) file directory followed by the file diretory is started. During file directory read the structure of the tree is checked (no further checks are executed). Possible errors are: No converter entry, Bad data page and invalid leaf structure. When the file directory is read also the number of bad indexes is determined. If there are any corrupted indexes the number is logged. As of version 7.6.00 a start and a stop message of the file directory reading is logged as well as a message regarding the reading of the LOB file directory:

2016-01-21 10:02:43     B*TREE     53000:  LOB file directory restart successful 
2016-01-21 10:02:43     FileDir        7:  File directory restarting 
2016-01-21 10:02:43     FileDir       56:  File Directory for tenant with partition-ID 0 restarting 
2016-01-21 10:02:43     FileDir       57:  File directory restart for tenant with partition-id 0 completed 
2016-01-21 10:02:43     FileDir        8:  File directory restart completed

 back to top

History

The number of history files is checked for liveCache instances as of version 7.4.00 - as of version 7.6.00 this is also done for OLTP instances. It is logged how many history files are found and how many should exist. If a backup was restored or parameter MAXUSERTASKS changed, superfluous history files might exist. In that case these superfluous history files are immediately deleted including their history.
In the following example 10 history files were found and (10) should actually exist in the current configuration.

2016-01-21 10:02:43      0x874        20 Log      History: 10 (10) files existing
2016-01-21 10:02:43      0x874        23 Log      History: all history files registered, GC is ready


back to top

Object file directory

For liveCache instances also the object file directory is initialized (in memory representation of the OMS container file directory). Messages are only logged when errors occur. Possible errors are inconsistencies in the file directory. Example: a VarObject container has 4 different continuation containers specified on its root page but not all of them are accessible. Or: a KeyedObjectContainer has 16 KeyPartitions specified but not all of them are accessible.

back to top

OMS container migration

For a liveCache instance a migration of the OMS container follows, if necessary. No messages are logged in KnlMsg.

  • For all liveCache instances created with a version < 7.2.05 Build 03 the FileId of the containers is migrated during the first start with a version 7.4.x. In the older versions value 0 was entered as ObjContainer-FileID for key inversions, now value 1 or 16 (number of key partitions) is entered.
  • For all liveCache instances created with a version < 7.4.02 Build 04 a migration is required during the first start with a version >= 7.4.02 Build 04.

back to top

Log area

Next the log area is checkedby reading the log info page.
In versions < 7.6.00 this is done with single I/O by the utility task, so message ‚Single I/O attach' can be found in knldiag - the logged TID is the ID of the UKT containing the utility task.
As of version 7.6.00 this is done by a user task. In regular intervals the log info page is written to offset 0 (as of version 7.4.00) respectively 2 (version 7.3.00) of the log volume. It contains information about the available log information in the cyclically overwritten log area. If the log info page contains the information that the log is initialized, no further checks are performed. Otherwise the first log page (the page behind the log info page) and the last log page (last offset) are read. Afterwards some specific pages are searched to make sure the log fits to the data volumes. For these pages the log info page contains the logical ID (in version 7.3.00 LPNO, as of version 7.4.00 IO sequence) and the offset at which this page should be stored. First the last known log page is searched (LastKnown). If further log pages are found behind that, all further log pages are read to find the current last page.
In version 7.3.00 these pages are read in blocks - _MULT_IO_BLOCK_CNT pages are read together.
As of version 7.4.00 the pages are read sequentially. Behind the last page the oldest page (FirstKnown) is searched. Normally it should be directly the next page. Then the position of the first not saved log page is searched (FirstNotSaved). When the last savepoint stored in the restart record is found in the log (from there on all log entries have to be redone during the restart), the DB identier from the restart record is compared with the DB identifier from the log info page. Only if all of these checks were successful, the restart can continue. If log information has to be redone, the first and the last log page are logged in knldiag as well as REDO messages. These messages indicate how many log pages are already redone.
More messages about the logging are logged in KnlMsg. The number of configured log queues and the used flush mode are logged. This is „MinimizeSpace" in the following example and means that one offset might be written several times. „OldestNotSaved" is logged together with the IO sequence and the offset, also the oldest log page (FirstKnown) as well as the first and the last log position needed for the restart. „last-redo-read" provides a short information about the last redone log entry

2016-01-21 10:02:43     Log           27:  Logpartition #1: Has 2 queues, the flushmode is MaximizeSafety, the state is Okay 
2016-01-21 10:02:43     Log           28:  Logpartition #1: The oldest not saved logpage is located at offset 134, iosequence=171000 2016-01-21 10:02:43     Log           26:  Logpartition #1: The oldest known logpage is located at offset 1007, iosequence=162880 2016-01-21 10:02:43     Log           29:  Logpartition #1: The result of the restart is Ok 
2016-01-21 10:02:43     Log           30:  The restart-savepoint is located on partition 1, offset = 1006, iosequence = 171872 
2016-01-21 10:02:43     Log           31:  The youngest known logpage is located on partition 1 offset = 1006, IOsequence = 171872 2016-01-21 10:02:43     Rst           11:  664 redo transactions readable and 14 redo tasks available. 
                                           DESCRIPTION: It may not be a problem if fewer redo tasks are available for a restart 
                                           than user tasks are possible. However if it is a problem, 
                                           then the parameter MAXSERVERTASKS must be increased. 
                                           ACTION: The parameter MAXSERVERTASKS should be increased.
                                           If the problem remains then contact development support. 
2016-01-21 10:02:43     Restart    20004:  recovering log from logarea starting with IOSeq: '171872' 
2016-01-21 10:02:43     Log        20033:  normal end of log found at off 1006 lastseq 171872. 
2016-01-21 10:02:43     Log        20004:  last-redo-read#1:TR281474976710655(120)[171872]@p1:1006'SavepointEntry':20160121:100222 
: 
2016-01-21 10:02:43     Rst            5:  RedoControl: End of redo processing 
2016-01-21 10:02:43     Rst            4:  RedoControl: RedoTasks: 14 , MaxRedoTrans: 664 
2016-01-21 10:02:43     Rst            6:  RedoControl: EndOfLogReached: true, RedoIsAborted: false, RedoProcessingDisabled: false 
:  
2016-01-21 10:02:43     Rst           12:  RedoControl: redo reader T0 wait reason:  isNotWaiting, waiting redo executer:  0 
2016-01-21 10:02:43     Rst            8:  RedoControl: Transactions processed: 0 (0)

back to top

Start garbage collectors

Afterwards the garbage collectors are started for a liveCache instance (as of version 7.6 also for OLTP instances) to remove possibly existing history.

2016-01-21 10:02:43     OBJECT     53000:  Restarted Garbage coll: 0

back to top

Restart savepoint

When all log information was redone a savepoint is triggered. As of version 7.4. the reason for a savepoint is logged in KnlMsg. In this case you can see that the savepoint was triggered because the restart was finished. As of version 7.5.00 additionally a message is logged that the REDO LOG was finished.


2016-01-21 10:02:43     Savepoint      1:  Savepoint (Restart) with ID 123 started
2016-01-21 10:02:43     DataCache     12:  Savepoint (phase 1): Start write data
2016-01-21 10:02:43     DataCache     13:  Savepoint (phase 1): Stop write data, 0 pages written with 0 io calls
2016-01-21 10:02:43     DataCache     12:  Savepoint (phase 2): Start write data
2016-01-21 10:02:43     DataCache     13:  Savepoint (phase 2): Stop write data, 0 pages written with 0 io calls
2016-01-21 10:02:43     DataCache      4:  Mark data pages for savepoint (prepare phase)
2016-01-21 10:02:43     DataCache     12:  Savepoint (phase 3): Start write data
2016-01-21 10:02:43     DataCache     13:  Savepoint (phase 3): Stop write data, 3 pages written with 1 io calls
2016-01-21 10:02:43     Converter  20047:  Savepoint (phase 3): Start write converter
2016-01-21 10:02:43     Converter  20048:  Savepoint (phase 3): Stop write converter, 8 pages written with 8 io calls
2016-01-21 10:02:43     DataCache      3:  Savepoint with ID 123 completed
2016-01-21 10:02:43     Admin      20037:  Kernel state: 'REDO LOG' finished

 back to top 

Migration of undo and redo files

When a database is started the first time with a version >= 7.4.02. Build 05 a migration of the undo and redo log files is done. This is necessary as in versions <= 7.4.02 Build 03 the root ID in these files might be incorrect. In KnlMsg message ‚History: waiting for removal of complete history' is logged then. Afterwards you'll have to wait until the garbage collectors removed all history pages. This might take a lot of time as in older versions the history was not removed in a timely manner.

back to top

Prefetching of OMS data

For a liveCache instance now the prefetching of OMS data is started. No messages are logged for that in KnlMsg.

back to top

Volume Balance

If the data volumes filling level differs from each other as of Version 7.8 the volume balancing is now triggered. 

2016-01-21 10:02:43     IOMan         60:  Volume balance not started (reason: no blocks to balance)


back to top

System Trigger

Last step before the database is in online mode the system trigger which is necessary for Queryrewrite is loaded.

2016-01-21 10:02:43     TRIGGER    51261:  system trigger started,TRIGGERNAME=READ_QUERY_REWRITE_RULES         
2016-01-21 10:02:43     TRIGGER    51261:  system trigger completed,RETURNCODE=0

back to top

ONLINE state reached

When the database was successfully started a message is logged that the database is in state ONLINE now. Prefetching is not necessarily finished at that time. As of version 7.5.00 it is logged how much physical memory is currently used by the database.

2016-01-21 10:02:43     RunTime        3:  State changed from ADMIN to ONLINE 
2016-01-21 10:02:43     RTE        20221:  Used physical memory 391 MByte 
2016-01-21 10:02:43     Admin      20039:  Kernel state: 'ONLINE' reached

 back to top

AUTOSAVE log

If the AUTOSAVE LOG was activated before the database was shut down it is re-activated by the Database Manager. In versions < 7.5.00 this is done by the utility task - so a connect of that task is logged again. As of version 7.5.00 a user task might be used for activating the AUTOSAVE LOG, so a connect of a user task might be logged in knlMsg.

2016-01-21 10:02:43     0x628     19633 CONNECT  Connect req. (T5, Node:'', PID:1972)
2016-01-21 10:02:43     0x628     52104 AUTOSAVE standby mode on
2016-01-21 10:02:43     0x628     19651 CONNECT  Connection released, T5

  back to top

Details Additional Useful Information

When is the DB identifier changed

 The db_ident is changed when an action is performed which deleted log entries. In that case the log history is interrupted and a complete backup has to be performed again. Such actions are:

  • Init Config (Instance Install) with restore
  • Restart until
  • Restore until
  • Changing the log mode to AUTO OVERWRITE
  • CLEAR LOG
  • SET LOG WRITER OFF (as of version 7.4)

back to top