Skip to content

Monitoring Restarts#

There is an ndbinfo table called restart_info that records how long each of the 18 phases of a restart take. This can be used for debugging restarts and for understanding how to improve restart times.

Let’s say we have just started a new cluster with one node group and a replication factor of two. We therefore have two data nodes.

After the initial cluster start, the table is empty:

mysql> USE ndbinfo;
mysql> SELECT * FROM restart_info;
Empty set (0.01 sec)

Now we stop one data node and check the table again after a few seconds:

mysql> SELECT * FROM restart_info \G
*************************** 1. row ***************************
                                     node_id: 2
                         node_restart_status: Node failure handling complete
                     node_restart_status_int: 3
               secs_to_complete_node_failure: 0
                    secs_to_allocate_node_id: 0
       secs_to_include_in_heartbeat_protocol: 0
          secs_until_wait_for_ndbcntr_master: 0
                secs_wait_for_ndbcntr_master: 0
                 secs_to_get_start_permitted: 0
     secs_to_wait_for_lcp_for_copy_meta_data: 0
                      secs_to_copy_meta_data: 0
                        secs_to_include_node: 0
secs_starting_node_to_request_local_recovery: 0
                     secs_for_local_recovery: 0
                      secs_restore_fragments: 0
                         secs_undo_disk_data: 0
                          secs_exec_redo_log: 0
                          secs_index_rebuild: 0
           secs_to_synchronize_starting_node: 0
                   secs_wait_lcp_for_restart: 0
             secs_wait_subscription_handover: 0
                          total_restart_secs: 0
1 row in set (0.01 sec)

As one can see, one of the first phases of the restart is complete: we have completed Node failure handling.

Now, we restart the data node again and check the table after a few seconds:

mysql> SELECT * FROM restart_info \G
*************************** 1. row ***************************
                                        node_id: 2
                            node_restart_status: Wait LCP to ensure durability
                        node_restart_status_int: 17
                secs_to_complete_node_failure: 0
                    secs_to_allocate_node_id: 57
        secs_to_include_in_heartbeat_protocol: 2
            secs_until_wait_for_ndbcntr_master: 0
                secs_wait_for_ndbcntr_master: 0
                    secs_to_get_start_permitted: 0
        secs_to_wait_for_lcp_for_copy_meta_data: 0
                        secs_to_copy_meta_data: 0
                        secs_to_include_node: 3
secs_starting_node_to_request_local_recovery: 0
                        secs_for_local_recovery: 0
                        secs_restore_fragments: 0
                            secs_undo_disk_data: 0
                            secs_exec_redo_log: 0
                            secs_index_rebuild: 0
            secs_to_synchronize_starting_node: 0
                    secs_wait_lcp_for_restart: 0
                secs_wait_subscription_handover: 0
                            total_restart_secs: 0
1 row in set (0.00 sec)

Running the distributed local checkpoint is one of the last phases as shown previously, and is required to be able to recover the latest data from the new node.

To make sure that the restart has completed, we check one last time and see this confirmed:

mysql> SELECT * FROM restart_info \G
*************************** 1. row ***************************
                                        node_id: 2
                            node_restart_status: Restart completed
                        node_restart_status_int: 19
                secs_to_complete_node_failure: 0
                    secs_to_allocate_node_id: 57
        secs_to_include_in_heartbeat_protocol: 2
            secs_until_wait_for_ndbcntr_master: 0
                secs_wait_for_ndbcntr_master: 0
                    secs_to_get_start_permitted: 0
        secs_to_wait_for_lcp_for_copy_meta_data: 0
                        secs_to_copy_meta_data: 0
                        secs_to_include_node: 3
secs_starting_node_to_request_local_recovery: 0
                        secs_for_local_recovery: 0
                        secs_restore_fragments: 0
                            secs_undo_disk_data: 0
                            secs_exec_redo_log: 0
                            secs_index_rebuild: 0
            secs_to_synchronize_starting_node: 0
                    secs_wait_lcp_for_restart: 4
                secs_wait_subscription_handover: 8
                            total_restart_secs: 77
1 row in set (0.01 sec)

When reading the secs columns, keep in mind that we did not load the database with any data, so the restart was particularly fast.

The Node Start Log#

The node log of a starting data node describes the start in lines that begin with [NODE-START]. Every start is described as the same 16 steps: init, join, admission, redo-init, start-perm, redo-prepare, metadata, restore, undo-dd, redo-exec, index-rebuild, synchronize, wait-lcp, activate, handover and barrier. The first line is the plan, which names the type of start and the steps it skips. Each step logs when it starts and when it completes, a skipped step logs that it is skipped, and the last line gives the total time of the start:

[NODE-START] plan: node restart (this node rejoins, keeping its data),
             executing 15/16 steps (skipping: 4 redo-init)
[NODE-START] step 4/16 (redo-init) skipped (node restart)
[NODE-START] step 8/16 (restore) completed, elapsed=312s
[NODE-START] completed: node restart finished, total elapsed=420s

While a step runs or waits, progress lines are written every NodeStartLogReportFrequency seconds, 15 by default. The cluster log gets the plan line, the last line, and a waiting line when a step has waited for more than 60 seconds, repeated every 10 minutes. To follow a start, search the node log for [NODE-START].

The chapter Node Start Log describes all [NODE-START] lines, the steps of each type of start and the lines that reach the cluster log, with examples.