Re: mysqlcluster data nodes synchronization rate
Thanks Mikael.
Got few questions
I have 2 datanodes : datanode3 (id=3) , datanode4 (id=4)
Q1. what does "scanIndex abort state :3" means in the ndb_4_out.log (at datanodes) ?
@Datanode4 [id:4 Node that is RECOVERING ]-- The content of /var/lib/mysqlcluster/ndb_4_out.log
2017-04-19 08:12:30 [ndbd] INFO -- DICT : Setting FK 652 child trigger id to 272 (4294967040)
2017-04-19 08:12:30 [ndbd] INFO -- DICT : Setting FK 441 child trigger id to 180 (4294967040)
2017-04-19 08:12:30 [ndbd] INFO -- DICT : Checking FK trigger ids complete
2017-04-19 08:12:30 [ndbd] INFO -- Allocate event buffering page chunk in SUMA, 16 pages, first page ref = 2292769
2017-04-19 08:12:30 [ndbd] INFO -- Foreign key enabling Completed
2017-04-19 08:12:30 [ndbd] INFO -- NDB start phase 7 completed
2017-04-19 08:12:30 [ndbd] INFO -- Start phase 8 completed
2017-04-19 08:12:30 [ndbd] INFO -- Start phase 9 completed
2017-04-19 08:12:30 [ndbd] INFO -- Phase 9 enabled APIs to start connecting
2017-04-19 08:12:30 [ndbd] INFO -- Suma: handover waiting up to 120000ms for all subscribers to connect
2017-04-19 08:12:30 [ndbd] INFO -- Start phase 101 waiting 120s for absent subscribers to connect : 5,6,7
2017-04-19 08:12:32 [ndbd] INFO -- Suma: handover from node 3 gci: 18776154 buckets: 00000002 (2)
18776154/0 (18776153/4294967295) switchover complete bucket 1 state: 1
starting
2017-04-19 08:12:34 [ndbd] INFO -- Start phase 101 completed
2017-04-19 08:12:34 [ndbd] INFO -- Phase 101 was used by SUMA to take over responsibility for sending some of the asynchronous change events
2017-04-19 08:12:34 [ndbd] INFO -- Node started
H'004fa934 H'01400800 scanIndex_abort state: 3
H'0052ecf2 H'01800900 scanIndex_abort state: 3
H'0052ed32 H'00800900 scanIndex_abort state: 3
H'00552f0f H'01300600 scanIndex_abort state: 3
H'00553ecd H'01300600 scanIndex_abort state: 3
H'00509e2b H'00900800 scanIndex_abort state: 3
H'005559a2 H'01e00600 scanIndex_abort state: 3
H'003a1bd9 H'02b00b00 scanIndex_abort state: 3
H'00386cd1 H'00f00500 scanIndex_abort state: 3
2017-04-23 04:01:58 [ndbd] INFO -- TS_DROPPING - Neglecting to save Table: 977 Frag: 0 -
H'00499936 H'02200500 scanIndex_abort state: 3
@Datanode 3 -- [id: 3 ] The content of /var/lib/mysqlcluster/ndb_3_out.log
2017-04-19 07:22:52 [ndbd] ALERT -- Arbitration won - positive reply from node 1
2017-04-19 07:22:52 [ndbd] INFO -- NR Status: node=4,OLD=Restart completed,NEW=Node failed, fail handling ongoing
2017-04-19 07:22:52 [ndbd] INFO -- DBTC instance 0: Starting take over of node 4
execGCP_NOMORETRANS(18773327/0) c_ongoing_take_over_cnt -> seize
2017-04-19 07:22:52 [ndbd] INFO -- DBTC instance 0: Completed take over of failed node 4
completing gcp 18773327/0 in execTAKE_OVERTCCONF
2017-04-19 07:22:53 [ndbd] INFO -- Started arbitrator node 1 [ticket=63b30005bc544872]
2017-04-19 07:22:53 [ndbd] INFO -- Adjusting disk write speed bounds due to : Node restart ongoing
2017-04-19 07:22:54 [ndbd] INFO -- NR Status: node=4,OLD=Node failed, fail handling ongoing,NEW=Node failure handling complete
2017-04-19 07:22:54 [ndbd] INFO -- Node 4 has completed node fail handling
2017-04-19 07:22:54 [ndbd] INFO -- NR Status: node=4,OLD=Node failure handling complete,NEW=Allocated node id
2017-04-19 07:23:01 [ndbd] INFO -- findNeighbours from: 2248 old (left: 65535 right: 65535) new (4 4)
2017-04-19 07:23:01 [ndbd] INFO -- NR Status: node=4,OLD=Allocated node id,NEW=Included in heartbeat protocol
2017-04-19 07:23:01 [ndbd] INFO -- NR Status: node=4,OLD=Included in heartbeat protocol,NEW=NDBCNTR master permitted us
2017-04-19 07:23:02 [ndbd] INFO -- NR Status: node=4,OLD=NDBCNTR master permitted us,NEW=All nodes permitted us
2017-04-19 07:23:02 [ndbd] INFO -- NR Status: node=4,OLD=All nodes permitted us,NEW=Wait for LCP complete to copy meta data
2017-04-19 07:23:02 [ndbd] INFO -- NR Status: node=4,OLD=Wait for LCP complete to copy meta data,NEW=Copy meta data to start node
2017-04-19 07:23:27 [ndbd] INFO -- NR Status: node=4,OLD=Copy meta data to start node,NEW=Include node in LCP/GCP protocols
2017-04-19 07:23:27 [ndbd] INFO -- NR Status: node=4,OLD=Include node in LCP/GCP protocols,NEW=Restore fragments ongoing
2017-04-19 07:26:39 [ndbd] INFO -- NR Status: node=4,OLD=Restore fragments ongoing,NEW=Undo Disk data ongoing
2017-04-19 07:26:39 [ndbd] INFO -- NR Status: node=4,OLD=Undo Disk data ongoing,NEW=Execute REDO logs ongoing
2017-04-19 07:26:39 [ndbd] INFO -- NR Status: node=4,OLD=Execute REDO logs ongoing,NEW=Build indexes ongoing
2017-04-19 08:07:33 [ndbd] INFO -- NR Status: node=4,OLD=Build indexes ongoing,NEW=Synchronize start node with live nodes
2017-04-19 08:08:31 [ndbd] INFO -- NR Status: node=4,OLD=Synchronize start node with live nodes,NEW=Wait LCP to ensure durability
2017-04-19 08:12:01 [ndbd] INFO -- NR Status: node=4,OLD=Wait LCP to ensure durability,NEW=Wait handover of subscriptions
2017-04-19 08:12:01 [ndbd] INFO -- granting SumaStartMe dict lock to 4
2017-04-19 08:12:01 [ndbd] INFO -- clearing SumaStartMe dict lock for 4
2017-04-19 08:12:03 [ndbd] INFO -- granting SumaStartMe dict lock to 4
prepare to handover bucket: 1
18776154/0 (18776153/4294967295) switchover complete bucket 1 state: 2
handover
2017-04-19 08:12:05 [ndbd] INFO -- clearing SumaStartMe dict lock for 4
2017-04-19 08:12:05 [ndbd] INFO -- NR Status: node=4,OLD=Wait handover of subscriptions,NEW=Restart completed
2017-04-19 08:12:06 [ndbd] INFO -- Adjusting disk write speed bounds due to : Node restart finished
H'005206ee H'00500900 scanIndex_abort state: 3
H'004fa934 H'01400800 scanIndex_abort state: 3
H'0052ecf2 H'01800900 scanIndex_abort state: 3
H'0052ed32 H'00800900 scanIndex_abort state: 3
H'00552f0f H'01300600 scanIndex_abort state: 3
H'00553ecd H'01300600 scanIndex_abort state: 3
H'00509e2b H'00900800 scanIndex_abort state: 3
H'005559a2 H'01e00600 scanIndex_abort state: 3
H'003a1bd9 H'02b00b00 scanIndex_abort state: 3
2017-04-23 04:01:28 [ndbd] INFO -- TS_DROPPING - Neglecting to save Table: 977 Frag: 0 -
H'00499936 H'02200500 scanIndex_abort state: 3
H'004abb0d H'02200500 scanIndex_abort state: 3
H'0064cc8e H'01700800 scanIndex_abort state: 3
# ndb_mgm -e "all report memory"
Connected to Management Server at: localhost:1186
Node 3: Data usage is 19%(504393 32K pages of total 2621440)
Node 3: Index usage is 7%(75346 8K pages of total 1048608)
Node 4: Data usage is 17%(469375 32K pages of total 2621440)
Node 4: Index usage is 7%(75142 8K pages of total 1048608)
# Restart_info table contents
mysql> select * from ndbinfo.restart_info \G;
*************************** 1. row ***************************
node_id: 4
node_restart_status: Restart completed
node_restart_status_int: 19
secs_to_complete_node_failure: 1
secs_to_allocate_node_id: 0
secs_to_include_in_heartbeat_protocol: 7
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: 25
secs_starting_node_to_request_local_recovery: 0
secs_for_local_recovery: 2645
secs_restore_fragments: 192
secs_undo_disk_data: 0
secs_exec_redo_log: 0
secs_index_rebuild: 2453
secs_to_synchronize_starting_node: 57
secs_wait_lcp_for_restart: 210
secs_wait_subscription_handover: 4
total_restart_secs: 2953
Edited 4 time(s). Last edit at 04/23/2017 05:12AM by urgen sherpa.