MySQL Forums
Forum List  »  NDB clusters

Re: mysqlcluster data nodes synchronization rate
Posted by: urgen sherpa
Date: April 22, 2017 12:40PM

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.

Options: ReplyQuote


Subject
Views
Written By
Posted
Re: mysqlcluster data nodes synchronization rate
157
April 22, 2017 12:40PM


Sorry, you can't reply to this topic. It has been closed.

Content reproduced on this site is the property of the respective copyright holders. It is not reviewed in advance by Oracle and does not necessarily represent the opinion of Oracle or any other party.