Skip to content

Node Start Log#

While a data node starts, it writes lines tagged [NODE-START] to its node log. These lines describe every start as the same 16 numbered steps. Each line says which step the node is in and what it is doing, and steps that take a long time report their progress, or what they are waiting for, at a fixed interval. A single search for [NODE-START] in the node log shows how far a start has come, how much is left, and whether a quiet period is work or a stall.

The [NODE-START] lines are written in addition to the other node log lines described in Cluster log and node logs; they do not replace them.

Line format#

The examples on this page show only the time of day of each node log line, and leave out the date and the [ndbd] INFO prefix.

13:19:18  [NODE-START] step 8/16 (restore) started
13:51:07  [NODE-START] step 8/16 sub-step 2/2 (restore: restore fragments from LCP) progress: LDM(5): restored 5/6 assigned fragments, 469696 row operations so far, 469696 row operations/s, elapsed=1s
09:42:03  [NODE-START] step 8/16 (restore) completed: LDM(5): 5 fragments, 23225 row operations, elapsed=0s
09:42:03  [NODE-START] step 8/16 (restore) completed: all 8 LDMs, elapsed=0s
09:42:03  [NODE-START] step 4/16 (redo-init) skipped (node restart)
08:39:25  [NODE-START] step 13/16 sub-step 1/1 (wait-lcp: wait for LCP) waiting: master node 3 has not yet completed a local checkpoint that includes this node, LCP 28 is running with this node, elapsed=2s

  • step N/16 is the position among the 16 steps. The numbers are the same for every type of start, so step 10 is always the execution of the REDO log.

  • sub-step M/T names the part of the step that is running. Some sub-steps print a started line and a completed line, others print only the completed line.

  • The verb is one of started, progress, waiting, completed and skipped. A progress line carries counters that move, such as MBytes, fragments, pages, table objects or rows, with a rate and an estimate of the remaining time where the total is known. A waiting line states the condition that is not met yet and names the node it waits for. It repeats with the same text until the condition is met.

  • elapsed= on a step line counts from the start of the step. On a sub-step line it counts from the start of the sub-step, so the completed line of a sub-step gives the duration of that sub-step.

  • Steps 4, 6, 8, 9, 10 and 11 run in the LDM threads. Each LDM thread prints its own completed line, marked LDM(N), and one node-wide line closes the step, for example all 8 LDMs, all 4 LDMs holding the 4 REDO log parts when only the LDM threads that own a REDO log part take part, or no fragments to restore on this node.

  • Once the master has decided the type of start, a plan: line lists the steps that this type of start skips. Each skipped step also prints a skipped line at the point where it would have run, so the log always counts from 1 to 16.

  • Lines that start with [NODE-START] [assist node N] describe work that this node does for the start of node N, see The master’s side of a node restart.

  • Lines that start with [NODE-START] waiting: have no step number. They report waits at the points where all nodes of an initial start or a system restart synchronize, which can span several steps.

  • A start that ends successfully prints [NODE-START] completed: <start type> finished, total elapsed=Ns. A start that is aborted by an error prints [NODE-START] failed: instead. The last started line above it names the step that was running.

Progress and waiting lines are printed by a timer, not by the work itself. If a step stops making progress, the timer keeps printing the same counters with a growing elapsed time, so a stall shows in the log without other tools.

The 16 steps#

The table shows which steps each type of start runs.

Step Name What happens Initial start System restart Node restart Initial node restart
1 init Process start, memory allocation, configuration read into the blocks yes yes yes yes
2 join Find the president, join the heartbeat protocol yes yes yes yes
3 admission The master accepts the start and decides its type yes yes yes yes
4 redo-init Create and initialize the REDO log files yes yes
5 start-perm Get permission to start from the master yes yes
6 redo-prepare Read the REDO log page headers yes yes
7 metadata Schema and table distribution, read from disk or copied from the master yes yes yes
8 restore Restore the fragments from the local checkpoint, or copy them from the live nodes when the node starts empty yes yes yes, as a copy
9 undo-dd Apply the disk data UNDO log, scan the tablespaces yes yes
10 redo-exec Execute the REDO log yes yes
11 index-rebuild Rebuild the ordered indexes yes yes yes
12 synchronize Copy the changes made since the checkpoint from the live nodes, then enable REDO logging only if a node needs a take-over yes yes
13 wait-lcp Wait for a local checkpoint that makes the node recoverable yes yes yes yes
14 activate Start the global checkpoint protocol, enable foreign keys yes yes yes yes
15 handover Take over the event subscriptions yes yes
16 barrier Wait for the other restarting nodes yes yes

The plan: line names the type of start in plain words and the steps that it skips:

09:42:03  [NODE-START] plan: node restart (this node rejoins, keeping its data), executing 15/16 steps (skipping: 4 redo-init)
13:18:53  [NODE-START] plan: initial node restart (this node rejoins empty, data copied from live nodes), executing 13/16 steps (skipping: 6 redo-prepare, 9 undo-dd, 10 redo-exec)
08:25:12  [NODE-START] plan: system restart (all nodes recover together from disk), executing 12/16 steps (skipping: 4 redo-init, 5 start-perm, 15 handover, 16 barrier); 12 synchronize only if a take-over is needed

The steps cover the same ground as the phases described in Startup Phases. The node log shows which step is running and how far it has come while the start is going on. For node restarts, the ndbinfo table restart_info records how long each phase took, see Monitoring Restarts.

Where the lines go#

The node log gets all [NODE-START] lines: the boundaries of steps and sub-steps, and the progress and waiting lines.

The cluster log gets only a few of them, each prefixed with the node id as Node N::

  • The plan: line.

  • The final [NODE-START] completed: <start type> finished line.

  • Waiting lines, once the step or the wait has lasted 60 seconds. The first one is written at the first report after 60 seconds, then the current line is written again every 600 seconds while the wait goes on. This applies to the waits of steps 2, 3, 5, 7, 12, 13, 14, 15 and 16 and to the waits between steps; in step 7 of a node restart or an initial node restart it also applies to the progress line that shows the schema being processed. The lines of steps 1, 4, 6, 8, 9, 10 and 11 and the [assist node N] lines stay in the node log.

A start that goes well therefore adds two lines to the cluster log, and a start that is stuck in a wait shows up there after a minute. The per-step started, completed and skipped lines stay in the node log; the cluster log keeps its Start phase N completed lines as coarse progress markers.

The failed: line is written to the node log only. In the cluster log the lines about a failed start stop at the last line that reached it, and the lines of the management server about the node going down follow.

The data node configuration parameter NodeStartLogReportFrequency sets the interval of the progress and waiting lines in seconds. The default is 15. With 0, only the boundary lines are written: no progress or waiting lines appear in the node log, and no waiting lines reach the cluster log. The plan: and final completed lines still reach the cluster log. With a value above 60, the first waiting line in the cluster log comes at the first report after 60 seconds. The waiting line of the angel process in step 1 always uses an interval of 15 seconds, because the angel waits before the configuration is known.

Useful searches in a node log:

grep '\[NODE-START\]' ndb_3_out.log            # the whole start
grep '\[NODE-START\] step' ndb_3_out.log       # only the steps of this node
grep '\[NODE-START\] step 10/' ndb_3_out.log   # one step with its sub-steps
grep 'assist node 3' ndb_2_out.log             # what node 2 did for the start of node 3
grep '\[NODE-START\] waiting' ndb_3_out.log    # waits between steps
grep '\[NODE-START\] failed' ndb_3_out.log     # a start that did not finish

Examples#

Node restart#

A node restart of node 3, which keeps its data. The lines of the LDM threads are shortened to those of LDM 5. In the log every LDM thread prints its own completed line, and these lines can interleave with the started line of the next step because the threads run in parallel.

09:42:00  [NODE-START] step 1/16 (init) started
09:42:00  [NODE-START] step 1/16 sub-step 1/4 (init: fetch configuration) completed, elapsed=0s
09:42:00  [NODE-START] step 1/16 sub-step 2/4 (init: allocate memory pools) completed, elapsed=0s
09:42:00  [NODE-START] step 1/16 sub-step 3/4 (init: start transporters and service threads) completed, elapsed=0s
09:42:00  [NODE-START] step 1/16 sub-step 4/4 (init: read configuration into blocks) started
09:42:02  [NODE-START] step 1/16 sub-step 4/4 (init: read configuration into blocks) completed, elapsed=2s
09:42:02  [NODE-START] step 1/16 (init) completed, elapsed=2s
09:42:02  [NODE-START] step 2/16 (join) started
09:42:02  [NODE-START] step 2/16 sub-step 1/3 (join: check local sysfile) completed: newest GCI on disk: 13, elapsed=0s
09:42:03  [NODE-START] step 2/16 sub-step 2/3 (join: president discovery/election) completed: president is node 2, elapsed=0s
09:42:03  [NODE-START] step 2/16 (join) completed: included in heartbeat protocol, president node 2, elapsed=0s
09:42:03  [NODE-START] step 3/16 (admission) started: asking master node 2 to accept our start
09:42:03  [NODE-START] step 3/16 (admission) completed: start type: node restart, master node 2, elapsed=0s
09:42:03  [NODE-START] plan: node restart (this node rejoins, keeping its data), executing 15/16 steps (skipping: 4 redo-init)
09:42:03  [NODE-START] step 4/16 (redo-init) skipped (node restart)
09:42:03  [NODE-START] step 5/16 (start-perm) started: requesting start permission from master node 2
09:42:03  [NODE-START] step 5/16 (start-perm) completed: permission granted by master node 2, 0 retries, elapsed=0s
09:42:03  [NODE-START] step 6/16 (redo-prepare) started
09:42:03  [NODE-START] step 7/16 (metadata) started: metadata is copied to us by master node 2
09:42:03  [NODE-START] step 6/16 (redo-prepare) completed: all 4 LDMs holding the 4 REDO log parts, elapsed=0s
09:42:03  [NODE-START] step 7/16 (metadata) completed: metadata copied by master node 2, elapsed=0s
09:42:03  [NODE-START] step 8/16 (restore) started
09:42:03  [NODE-START] step 8/16 (restore) completed: LDM(5): 5 fragments, 23225 row operations, elapsed=0s
          ...
09:42:03  [NODE-START] step 8/16 (restore) completed: all 8 LDMs, elapsed=0s
09:42:03  [NODE-START] step 9/16 (undo-dd) started
09:42:03  [NODE-START] step 9/16 sub-step 1/4 (undo-dd: find UNDO log head) completed: LGMAN: UNDO log head located, 32768 pages in the log, elapsed=0s
09:42:03  [NODE-START] step 9/16 sub-step 2/4 (undo-dd: apply UNDO log) completed: LGMAN: applied 1 pages, 1 records, elapsed=0s
09:42:03  [NODE-START] step 9/16 sub-step 3/4 (undo-dd: flush page cache) completed: LGMAN: page cache flushed, elapsed=0s
09:42:03  [NODE-START] step 9/16 sub-step 4/4 (undo-dd: scan tablespace extents) completed: scanned 1 datafiles, elapsed=0s
09:42:03  [NODE-START] step 9/16 (undo-dd) completed: all 8 LDMs, elapsed=0s
09:42:03  [NODE-START] step 10/16 (redo-exec) started
09:42:04  [NODE-START] step 10/16 sub-step 1/2 (redo-exec: execute REDO log) completed: LDM(5): 4 rounds executed, elapsed=1s
09:42:05  [NODE-START] step 10/16 sub-step 2/2 (redo-exec: relocate REDO head and invalidate tail) completed: LDM(5): REDO head relocated, log tail invalidated, elapsed=0s
          ...
09:42:05  [NODE-START] step 10/16 (redo-exec) completed: all 8 LDMs, elapsed=1s
09:42:05  [NODE-START] step 11/16 (index-rebuild) started: 7 ordered indexes
09:42:05  [NODE-START] step 11/16 (index-rebuild) completed: LDM(5): 7 ordered indexes, 406968 rows scanned, elapsed=0s
          ...
09:42:05  [NODE-START] step 11/16 (index-rebuild) completed: all 8 LDMs, elapsed=0s
09:42:05  [NODE-START] step 12/16 (synchronize) started
09:42:05  [NODE-START] step 12/16 sub-step 1/3 (synchronize: start take-over threads) completed: take-over accepted by master node 2, 16 copy threads, elapsed=0s
09:42:05  [NODE-START] step 12/16 sub-step 2/3 (synchronize: copy fragments from live nodes) started: copying 72 fragments from live nodes (all fragment replicas of this node, ordered indexes included)
09:42:05  [NODE-START] step 12/16 sub-step 2/3 (synchronize: copy fragments from live nodes) completed: 72 fragments copied from live nodes (all fragment replicas of this node, ordered indexes included), 102434 row operations received, elapsed=0s
09:42:05  [NODE-START] step 12/16 sub-step 3/3 (synchronize: enable REDO logging) started: enabling REDO logging on the copied fragments
09:42:06  [NODE-START] step 12/16 sub-step 3/3 (synchronize: enable REDO logging) completed: REDO logging enabled on 44 of the 72 copied fragments, the rest are ordered indexes or unlogged tables and need none, elapsed=0s
09:42:06  [NODE-START] step 12/16 (synchronize) completed: 72 fragments copied, REDO logging enabled, elapsed=0s
09:42:06  [NODE-START] step 13/16 (wait-lcp) started: an LCP driven by master node 2 must include this node before it is recoverable
09:42:10  [NODE-START] step 13/16 (wait-lcp) completed: LCP id 5, driven by master node 2, elapsed=4s
09:42:10  [NODE-START] step 14/16 (activate) started
09:42:10  [NODE-START] step 14/16 sub-step 1/1 (activate: enable foreign keys) completed: 0 foreign keys enabled, elapsed=0s
09:42:12  [NODE-START] step 14/16 (activate) completed, elapsed=1s
09:42:12  [NODE-START] step 15/16 (handover) started
09:42:13  [NODE-START] step 15/16 sub-step 1/2 (handover: wait for subscribers to connect) completed: 1 subscriber node connected, elapsed=0s
09:42:13  [NODE-START] step 15/16 sub-step 2/2 (handover: take over subscription buckets) started: acquiring the DICT lock, then taking over the subscription buckets
09:42:13  [NODE-START] step 15/16 sub-step 2/2 (handover: take over subscription buckets) progress: handover of the subscription buckets requested from nodes 2 at GCI 26, elapsed=0s
09:42:18  [NODE-START] step 15/16 sub-step 2/2 (handover: take over subscription buckets) completed: subscription buckets taken over at GCI 26, elapsed=5s
09:42:18  [NODE-START] step 15/16 (handover) completed: subscription buckets taken over at GCI 26, elapsed=6s
09:42:18  [NODE-START] step 16/16 (barrier) started
09:42:18  [NODE-START] step 16/16 (barrier) completed: all restarting nodes have recovered, elapsed=0s
09:42:18  [NODE-START] completed: node restart finished, total elapsed=18s

The boundary lines name the node that does the work: the master that copied the metadata, the master that drove the local checkpoint, and the GCI at which the event subscriptions changed hands.

The master’s side of a node restart#

Work that a node does for the start of another node is marked with [assist node N]. In the node log of the master, the restart above looks like this:

09:42:03  [NODE-START] [assist node 3] step 7/16 sub-step 1/4 (metadata: pause LCP) started: pause LCP / lock fragment info
09:42:03  [NODE-START] [assist node 3] step 7/16 sub-step 1/4 (metadata: pause LCP) completed: fragment info locked, LCP paused, elapsed=0s
09:42:03  [NODE-START] [assist node 3] step 7/16 sub-step 2/4 (metadata: copy distribution information) started: 18 table objects (tables, unique index tables and ordered indexes) to copy
09:42:03  [NODE-START] [assist node 3] step 7/16 sub-step 2/4 (metadata: copy distribution information) completed: 18 table objects copied, elapsed=0s
09:42:03  [NODE-START] [assist node 3] step 7/16 sub-step 3/4 (metadata: copy dictionary information) started: DICT copies the schema
09:42:03  [NODE-START] [assist node 3] step 7/16 sub-step 3/4 (metadata: copy dictionary information) completed: schema copied, elapsed=0s
09:42:03  [NODE-START] [assist node 3] step 7/16 sub-step 4/4 (metadata: include node in protocols) started: including the node in the GCP and LCP protocols on all nodes at the next GCP boundary
09:42:03  [NODE-START] [assist node 3] step 7/16 sub-step 4/4 (metadata: include node in protocols) completed: node included in the protocols on all nodes, elapsed=0s

The counts are table objects: the tables, their unique index tables and their ordered indexes. With a larger schema, 970 table objects in this example, the step takes longer, and the lines show where the time goes. The master copies the distribution information first and then hands the schema to DICT:

08:34:06  [NODE-START] [assist node 3] step 7/16 sub-step 2/4 (metadata: copy distribution information) started: 970 table objects (tables, unique index tables and ordered indexes) to copy
08:34:11  [NODE-START] [assist node 3] step 7/16 sub-step 2/4 (metadata: copy distribution information) completed: 970 table objects copied, elapsed=4s
08:34:11  [NODE-START] [assist node 3] step 7/16 sub-step 3/4 (metadata: copy dictionary information) started: DICT copies the schema
08:34:22  [NODE-START] [assist node 3] step 7/16 sub-step 3/4 (metadata: copy dictionary information) completed: schema copied, elapsed=10s

Meanwhile the starting node reports, once per report interval, that it waits for the master, and then reports how far DICT has come with the copied schema:

08:38:44  [NODE-START] step 7/16 (metadata) started: metadata is copied to us by master node 3
08:38:45  [NODE-START] step 7/16 (metadata) waiting: master node 3 has not copied the metadata to us yet, elapsed=1s
          ...
08:38:52  [NODE-START] step 7/16 (metadata) waiting: master node 3 has not copied the metadata to us yet, elapsed=8s
08:38:53  [NODE-START] step 7/16 sub-step 3/4 (metadata: copy dictionary information) progress: DICT is processing the schema copied from master node 3: pass 17/24, schema object 23/23, elapsed=9s
08:38:54  [NODE-START] step 7/16 (metadata) completed: metadata copied by master node 3, elapsed=9s

When two nodes restart at the same time, the master admits one of them at a time. The node that has to wait reports it for as long as the wait lasts:

13:31:34  [NODE-START] step 3/16 (admission) started: asking master node 2 to accept our start
13:31:35  [NODE-START] step 3/16 sub-step 1/1 (admission: request start permission) waiting: master node 2 has not yet granted our start, elapsed=1s
          ...
13:32:38  [NODE-START] step 3/16 sub-step 1/1 (admission: request start permission) waiting: master node 2 has not yet granted our start, elapsed=64s
13:32:39  [NODE-START] step 3/16 (admission) completed: start type: node restart, master node 2, elapsed=65s

Initial node restart#

In an initial node restart the node starts empty. It first creates its REDO log files:

13:18:54  [NODE-START] step 4/16 sub-step 1/1 (redo-init: create and initialize REDO log files) progress: LDM(1): initialized 256/4096 MBytes (6%), 8/128 files, elapsed=1s
13:18:55  [NODE-START] step 4/16 sub-step 1/1 (redo-init: create and initialize REDO log files) progress: LDM(1): initialized 480/4096 MBytes (11%), 15/128 files, elapsed=2s
          ...
13:19:17  [NODE-START] step 4/16 (redo-init) completed: all 4 LDMs holding the 4 REDO log parts, elapsed=23s

Before the master grants the start permission, the live nodes invalidate the old local checkpoints of the node. Each live node reports this in its own node log:

13:19:17  [NODE-START] [assist node 3] step 5/16 sub-step 2/2 (start-perm: start permission handshake) started: invalidating this node's old LCPs before its start permission is granted
13:19:17  [NODE-START] [assist node 3] step 5/16 sub-step 2/2 (start-perm: start permission handshake) completed: old LCPs invalidated, elapsed=0s

Step 8 copies every fragment from the live nodes. Steps 6, 9 and 10 are skipped because there is no old data to recover.

13:19:18  [NODE-START] step 8/16 (restore) started
13:19:18  [NODE-START] step 8/16 (restore) completed: LDM(5): 5 fragments copied from live nodes, 135660 row operations, elapsed=0s
          ...
13:19:18  [NODE-START] step 8/16 (restore) completed: all 8 LDMs, elapsed=0s

Data node without a node group#

A data node without a node group holds no data. Its start runs the same steps, and the steps that have nothing to do say so. In step 15 the node waits for subscribing API nodes and MySQL servers to connect. This wait is limited by RestartSubscriberConnectTimeout, 2 minutes by default, see Advanced Configuration. In this example no MySQL server connected to the node, so the wait lasted the full 2 minutes.

08:39:23  [NODE-START] step 8/16 (restore) started
08:39:23  [NODE-START] step 8/16 (restore) completed: no fragments to copy to this node, elapsed=0s
08:39:23  [NODE-START] step 12/16 sub-step 2/3 (synchronize: copy fragments from live nodes) completed: 0 fragments copied from live nodes (all fragment replicas of this node, ordered indexes included), 0 row operations received, elapsed=0s
08:39:23  [NODE-START] step 12/16 (synchronize) completed: 0 fragments copied, REDO logging enabled, elapsed=0s
08:39:23  [NODE-START] step 13/16 (wait-lcp) started: an LCP driven by master node 3 must include this node before it is recoverable
08:39:24  [NODE-START] step 13/16 sub-step 1/1 (wait-lcp: wait for LCP) waiting: master node 3 has not yet completed a local checkpoint that includes this node, waiting for the next LCP to start, elapsed=1s
08:39:25  [NODE-START] step 13/16 sub-step 1/1 (wait-lcp: wait for LCP) waiting: master node 3 has not yet completed a local checkpoint that includes this node, LCP 28 is running with this node, elapsed=2s
          ...
08:39:28  [NODE-START] step 13/16 (wait-lcp) completed: LCP id 28, driven by master node 3, elapsed=5s
08:39:28  [NODE-START] step 15/16 (handover) started
08:39:29  [NODE-START] step 15/16 sub-step 1/2 (handover: wait for subscribers to connect) waiting: not every subscriber node has connected to this node yet, elapsed=1s
          ...
08:41:28  [NODE-START] step 15/16 sub-step 1/2 (handover: wait for subscribers to connect) completed: 0 subscriber nodes connected, elapsed=120s
08:41:28  [NODE-START] step 15/16 sub-step 2/2 (handover: take over subscription buckets) completed: no subscription buckets to take over, this node has no node group, elapsed=0s
08:41:28  [NODE-START] step 15/16 (handover) completed: no subscription buckets to take over, this node has no node group, elapsed=120s

Data node that cannot find its peers#

In the join step the node reports what it waits for and which nodes have refused it so far. Here node 2 starts before node 3, wins the election of the president and then waits to include node 3:

13:50:57  [NODE-START] step 2/16 (join) started
13:50:57  [NODE-START] step 2/16 sub-step 1/3 (join: check local sysfile) completed: newest GCI on disk: 185, elapsed=0s
13:51:00  [NODE-START] step 2/16 sub-step 2/3 (join: president discovery/election) waiting: no president elected, connected data nodes [none], not connected [3], elapsed=2s
13:51:01  [NODE-START] step 2/16 sub-step 2/3 (join: president discovery/election) completed: won election, we are the president, elapsed=3s
13:51:02  [NODE-START] step 2/16 sub-step 3/3 (join: node inclusion protocol) waiting: we are the president, waiting to include the co-starting nodes 3 (CM_ADD), elapsed=4s
13:51:03  [NODE-START] step 2/16 sub-step 3/3 (join: node inclusion protocol) waiting: we are the president, waiting to include the co-starting nodes 3 (CM_ADD), elapsed=5s
13:51:04  [NODE-START] step 2/16 (join) completed: included in heartbeat protocol, president node 2, elapsed=6s

not connected [3] shows the cause: there is no transporter connection to node 3 yet. If another node refused this node, the waiting line ends with last refusal: node N and the reason. Waiting lines of other steps report, in the same way, a node id that the management server does not hand out, a refused start permission with the reason of the refusal, or a schema lock held by a running schema change.

System restart#

In a system restart all nodes start together from disk. The master reads and distributes the metadata and drives the first local checkpoint, and the other nodes report these steps as done by the master. Steps 6 and 7 begin together. In this example each REDO log file took three seconds to close, and step 6 reports this while it waits. In the node log of the master:

08:25:17  [NODE-START] step 6/16 (redo-prepare) started
08:25:17  [NODE-START] step 7/16 (metadata) started: this node is the master, it reads and distributes the metadata once all nodes reach this point
08:25:17  [NODE-START] step 7/16 sub-step 1/2 (metadata: synchronize sysfile) started: restarting cluster to GCI 60854, synchronizing the sysfile with all nodes
08:25:17  [NODE-START] step 7/16 sub-step 1/2 (metadata: synchronize sysfile) completed: sysfile synchronized, elapsed=0s
08:25:17  [NODE-START] step 7/16 sub-step 2/2 (metadata: restore the schema and distribute the tables) started: DICT restores the schema from disk while each table's distribution is read and sent to all nodes
08:25:18  [NODE-START] step 6/16 sub-step 1/1 (redo-prepare: read REDO log page headers) waiting: LDM(1): reading REDO log page headers, part 0 closing file 2, elapsed=1s
08:25:19  [NODE-START] step 7/16 sub-step 2/2 (metadata: restore the schema and distribute the tables) completed: schema restored from disk, 24 table objects read and distributed to all nodes, elapsed=1s
08:25:19  [NODE-START] step 7/16 (metadata) completed: 24 table objects read and distributed to all nodes, elapsed=1s
08:25:19  [NODE-START] step 6/16 sub-step 1/1 (redo-prepare: read REDO log page headers) waiting: LDM(1): reading REDO log page headers, part 0 closing file 2, elapsed=2s
08:25:20  [NODE-START] step 6/16 (redo-prepare) completed: LDM(1), elapsed=3s
          ...
08:25:20  [NODE-START] step 6/16 (redo-prepare) completed: all 4 LDMs holding the 4 REDO log parts, elapsed=3s
          ...
08:25:42  [NODE-START] waiting: local recovery of this node is complete, waiting for nodes 3 to complete theirs (START_RECCONF), elapsed=1s
08:25:44  [NODE-START] step 12/16 (synchronize) skipped: no take-over required
08:25:44  [NODE-START] step 13/16 (wait-lcp) started: LCP id 41
08:25:44  [NODE-START] step 13/16 (wait-lcp) completed: LCP id 41, elapsed=0s
08:25:44  [NODE-START] step 14/16 (activate) started
08:25:44  [NODE-START] step 14/16 sub-step 1/2 (activate: start GCP) completed: global checkpoint protocol running, elapsed=0s
08:25:44  [NODE-START] step 14/16 sub-step 2/2 (activate: enable foreign keys) completed: 0 foreign keys enabled, elapsed=0s
08:25:44  [NODE-START] step 14/16 (activate) completed, elapsed=0s

On the other nodes the same steps are reported as done by the master:

09:39:43  [NODE-START] step 7/16 (metadata) started: master node 2 reads and distributes the metadata
09:39:53  [NODE-START] step 7/16 sub-step 1/2 (metadata: synchronize sysfile) completed: sysfile synchronized by master node 2, elapsed=10s
09:39:54  [NODE-START] step 7/16 sub-step 2/2 (metadata: restore the schema and distribute the tables) started: receiving the table objects from master node 2
09:39:55  [NODE-START] step 7/16 sub-step 2/2 (metadata: restore the schema and distribute the tables) completed: received 24 table objects from master node 2, elapsed=1s
09:39:55  [NODE-START] step 7/16 (metadata) completed: metadata distributed by master node 2, elapsed=11s
          ...
09:40:18  [NODE-START] step 12/16 (synchronize) skipped: no take-over of this node
09:40:18  [NODE-START] step 13/16 (wait-lcp) started: master node 2 drives the first local checkpoint, this node waits for it at NDB start phase 5 wait point
09:40:18  [NODE-START] step 13/16 (wait-lcp) completed: first local checkpoint completed, driven by master node 2, elapsed=0s
09:40:18  [NODE-START] step 14/16 sub-step 1/2 (activate: start GCP) completed: global checkpoint protocol started by master node 2, elapsed=0s

Waiting for other nodes#

In an initial start or a system restart the nodes synchronize at several points, and one slow node holds up the others. These waits are reported as well. Here node 3 has finished its local recovery first and waits at the wait point of NDB start phase 4 for the master to release it:

08:25:19  [NODE-START] waiting: NDB start phase 4 wait point, master node 2 releases it once every node has completed its local recovery (steps 7-11), elapsed=1s
          ...
08:25:42  [NODE-START] waiting: NDB start phase 4 wait point, master node 2 releases it once every node has completed its local recovery (steps 7-11), elapsed=24s

The master in turn names the nodes it still waits for, so the slow node can be found in the node log of the master.

When two nodes restart at the same time, the node that finishes first waits at the restart barrier until the other node has recovered, see RestartBarrierTimeout in Advanced Configuration:

13:34:03  [NODE-START] step 16/16 (barrier) started
13:34:05  [NODE-START] step 16/16 sub-step 1/1 (barrier: wait at restart barrier) waiting: other restarting nodes have not completed their recovery, elapsed=1s
          ...
13:35:14  [NODE-START] step 16/16 (barrier) completed: all restarting nodes have recovered, elapsed=71s

Progress of long steps#

Every step that can take minutes prints a progress line per report interval, counted in the unit that matters for the step. The following lines come from several starts:

13:51:08  [NODE-START] step 8/16 sub-step 2/2 (restore: restore fragments from LCP) progress: LDM(5): restored 5/6 assigned fragments, 856887 row operations so far, 428443 row operations/s, elapsed=2s
10:48:15  [NODE-START] step 9/16 sub-step 2/4 (undo-dd: apply UNDO log) completed: LGMAN: applied 2936 pages, 389349 records, elapsed=4s
14:41:46  [NODE-START] step 11/16 sub-step 1/1 (index-rebuild: rebuild ordered indexes) progress: LDM(5): rebuilt 7/12 ordered indexes, rows scanned 740792/7757933 (9%), 740792 rows/s, ~9s left; index 25: 0/1 fragments done, 1 building, elapsed=1s
08:24:01  [NODE-START] step 12/16 sub-step 2/3 (synchronize: copy fragments from live nodes) started: copying 3880 fragments from live nodes (all fragment replicas of this node, ordered indexes included)
08:24:02  [NODE-START] step 12/16 sub-step 2/3 (synchronize: copy fragments from live nodes) progress: copied 2691/3880 fragments from live nodes, 2691 fragments/s, ~0s left, 78123 row operations received so far, 78123 row operations/s, elapsed=1s

An LDM thread that has no part in a step says so instead of repeating a counter that does not move. An LDM thread that has finished its part of a REDO execution round names what it waits for:

13:38:59  [NODE-START] step 10/16 sub-step 1/2 (redo-exec: execute REDO log) progress: LDM(5): round 1/4, no REDO log part on this LDM (the rounds follow the LDMs that own log parts), elapsed=1s
10:48:17  [NODE-START] step 10/16 sub-step 1/2 (redo-exec: execute REDO log) waiting: LDM(1): round 1/4, part 0 done, this LDM has finished the round, waiting for 2 other node(s) to complete it, elapsed=17s

Step 12 has a wait that can look like a stall. Before REDO logging is enabled on the copied fragments, every LDM thread takes a local checkpoint of them. With 1800 tables this checkpoint took about half a minute in the following example, and the waiting line counts the LDM threads that have finished:

13:33:52  [NODE-START] step 12/16 sub-step 3/3 (synchronize: enable REDO logging) started: enabling REDO logging on the copied fragments
13:33:53  [NODE-START] step 12/16 sub-step 3/3 (synchronize: enable REDO logging) waiting: the copied fragments are being checkpointed locally before REDO logging is enabled, 0/8 LDMs done, elapsed=0s
          ...
13:34:24  [NODE-START] step 12/16 sub-step 3/3 (synchronize: enable REDO logging) waiting: the copied fragments are being checkpointed locally before REDO logging is enabled, 6/8 LDMs done, elapsed=31s

When the sub-step completes, its line explains why the number of fragments with REDO logging is lower than the number of copied fragments:

14:06:23  [NODE-START] step 12/16 sub-step 3/3 (synchronize: enable REDO logging) completed: REDO logging enabled on 1852 of the 3904 copied fragments, the rest are ordered indexes or unlogged tables and need none, elapsed=8s

Failed start#

When the angel process cannot get a node id from the management server, it reports the wait and then the failure:

13:47:50  [NODE-START] step 1/16 sub-step 1/4 (init: fetch configuration) waiting: angel: no node id from the management server after 6 attempts, last error: Could not alloc node id at 127.0.0.1:1186: Id 3 already allocated by another node., elapsed=15s
13:48:05  [NODE-START] failed: angel could not allocate a node id: Error: Could not alloc node id at 127.0.0.1:1186: Id 3 already allocated by another node.

When the node goes down later in the start, the failed: line follows the error messages, and the last started line above it names the step that was running. In the following example StartFailureTimeout is set to 600000 (10 minutes), and the node waits in step 5 for a schema change on the master to finish:

10:00:04  [NODE-START] step 5/16 (start-perm) started: requesting start permission from master node 2
10:00:19  [NODE-START] step 5/16 sub-step 1/2 (start-perm: acquire DICT lock) waiting: master node 2 has not granted the DICT lock yet, a schema operation may be in progress, elapsed=15s
          ...
10:09:49  [NODE-START] step 5/16 sub-step 1/2 (start-perm: acquire DICT lock) waiting: master node 2 has not granted the DICT lock yet, a schema operation may be in progress, elapsed=585s
10:10:00  [NODE-START] failed: node start aborted, error 6100, Total restart time too long, consider increasing StartFailureTimeout or investigate error(s) on other node(s): Shutting down node as total restart time exceeds  StartFailureTimeout as set in config file  600000

Both failed: lines are written to the node log only.

Progress and waiting lines by step#

A step can take a long time for two reasons. A work step takes long because its duration grows with the data: the size of the REDO log, the number of fragments and rows, or the size of the schema. Such a step prints progress lines with counters that move. A wait step takes long only when another node or another step holds it up. Such a step prints waiting lines that name the condition that is not met yet.

Work steps#

Step What the progress line reports
1 init touched X/Y MBytes (P%) while memory pools larger than 128 MBytes are allocated and touched
4 redo-init Per LDM thread: initialized X/Y MBytes (P%), X/Y files
6 redo-prepare Per LDM thread and REDO log part: the file being read and the MByte position in it, or that the part opens or closes a file
7 metadata On the starting node, the restart pass and schema object of DICT; on the master, as an assist line, copied X/Y table objects; in a system restart, the table objects distributed by the master or received by the other nodes
8 restore Per LDM thread: restored X/Y assigned fragments, N row operations so far, R row operations/s, or copied when the node starts empty
9 undo-dd The position while LGMAN locates the UNDO log head, then applied X/Y pages, N records, LSN L, then scanned N datafiles
10 redo-exec Per LDM thread: round R/4, with part N at file F MB M for each REDO log part, or part N done
11 index-rebuild Per LDM thread: rebuilt X/Y ordered indexes, rows scanned X/Y (P%), the rate and the estimated time left, and the fragments of the index that is being built
12 synchronize copied X/Y fragments from live nodes with the rate and the estimated time left, and the row operations received so far; in sub-step 3, the fragments with REDO logging enabled
15 handover handover of the subscription buckets requested from nodes N at GCI G

Wait steps#

Step What the waiting line names
1 init The angel cannot get a node id: the number of attempts and the error of the management server
2 join The connected and the not connected data nodes, and the last node that refused this node, with the reason; later, the co-starting nodes that are not included yet
3 admission The master that has not granted the start; on the master of a cluster start, the nodes that have not asked to start and the data nodes that are not in the cluster
5 start-perm A DICT lock that the master has not granted because a schema change is running, or the number of refused permission requests with the last refusal
6 redo-prepare A REDO log part that waits for the file system to open or close a file
7 metadata The master that has not copied the metadata yet; on the master, the fragment info lock or LCP pause that is still pending
8 restore, 9 undo-dd An LDM thread that has finished its part and waits for the other LDM threads, or for the disk data recovery
10 redo-exec An LDM thread that has finished a round and waits for other nodes or LDM threads to finish it
12 synchronize The master that has not accepted the take-over; in sub-step 3, the local checkpoint of the copied fragments
13 wait-lcp The local checkpoint that must include this node, and whether it is running or not started yet
14 activate The nodes that have not completed NDB start phase 6 or 7, or the enabling of foreign keys
15 handover The subscriber nodes that have not connected, or the bucket switchover that is not confirmed by every node
16 barrier The other restarting nodes that have not completed their recovery

In addition, the waiting lines without a step number report the start phase barriers and wait points of an initial start or a system restart, and name the master or the nodes that the node waits for.

Most progress and waiting lines come from a timer, as described in Line format. The UNDO log lines of LGMAN, the tablespace scan of TSMAN, the table objects received in a system restart and the memory touch of step 1 are printed by the work itself, so they stop when the work stops. During step 9 the waiting lines of the LDM threads show that the node is still running.

Reading tips#

  • Lines from different threads interleave. Each LDM thread prints its own completed line for steps 4, 6, 8, 9, 10 and 11, and the node-wide completed line closes the step. The first thread to finish can print the started line of the next step while other threads are still completing. Within one thread the order is strict.

  • Steps 6 and 7 begin together in a node restart and a system restart: the REDO log page headers are read while the metadata arrives.

  • A skipped line is not an error. It marks a step that this type of start does not need, at the place where it would have run.

  • The numbers of a progress line change from one line to the next. A waiting line repeats the same text with a growing elapsed time. Several waiting lines with the same text mean that the step is stuck on the condition that the text names.

  • Search for assist node N in the node logs of the other data nodes, in particular the master, to see their part of the start of node N.