One alpha node begin to dropAll when there are some normal mutations

hhtlxhhxy · January 17, 2019, 11:14am

The cluster information:

Dgraph version : v1.0.12-rc3
Commit SHA-1 : a136935d
Commit timestamp : 2019-01-14 10:49:15 -0800
Branch : HEAD
Go version : go1.11.1

When I run some mutations , one alpha node begin to drop all , the log as below:

I0117 18:43:25.255325   51782 node.go:83] Rolling up Time elapsed: 48s, bytes sent: 1.5 GB, speed: 32 MB/sec
I0117 18:43:26.255528   51782 node.go:83] Rolling up Time elapsed: 49s, bytes sent: 1.5 GB, speed: 31 MB/sec
I0117 18:43:27.255141   51782 node.go:83] Rolling up Time elapsed: 50s, bytes sent: 1.5 GB, speed: 30 MB/sec
I0117 18:43:28.256443   51782 node.go:83] Rolling up Time elapsed: 51s, bytes sent: 1.5 GB, speed: 30 MB/sec
I0117 18:43:29.261949   51782 node.go:83] Rolling up Time elapsed: 52s, bytes sent: 1.5 GB, speed: 29 MB/sec
W0117 18:43:29.617632   51782 node.go:85] A tick missed to fire. Node blocks too long!
W0117 18:43:29.636037   51782 node.go:85] A tick missed to fire. Node blocks too long!
W0117 18:43:29.655565   51782 node.go:85] A tick missed to fire. Node blocks too long!
W0117 18:43:29.677275   51782 node.go:85] A tick missed to fire. Node blocks too long!
W0117 18:43:29.696275   51782 node.go:85] A tick missed to fire. Node blocks too long!
W0117 18:43:29.716762   51782 node.go:85] A tick missed to fire. Node blocks too long!
W0117 18:43:29.737030   51782 node.go:85] A tick missed to fire. Node blocks too long!
W0117 18:43:29.757016   51782 node.go:85] A tick missed to fire. Node blocks too long!
W0117 18:43:29.776362   51782 node.go:85] A tick missed to fire. Node blocks too long!
W0117 18:43:29.796335   51782 node.go:85] A tick missed to fire. Node blocks too long!
W0117 18:43:29.816601   51782 node.go:85] A tick missed to fire. Node blocks too long!
W0117 18:43:29.835369   51782 node.go:85] A tick missed to fire. Node blocks too long!
W0117 18:43:29.856466   51782 node.go:85] A tick missed to fire. Node blocks too long!
W0117 18:43:29.879775   51782 node.go:85] A tick missed to fire. Node blocks too long!
W0117 18:43:29.899026   51782 node.go:85] A tick missed to fire. Node blocks too long!
I0117 18:43:29.913135   51782 node.go:83] 2 is starting a new election at term 26
E0117 18:43:29.912904   51782 pool.go:204] Echo error from 10.237.7.232:7083. Err: rpc error: code = DeadlineExceeded desc = context deadline exceeded
I0117 18:43:36.870724   51782 node.go:83] Rolling up Time elapsed: 59s, bytes sent: 1.5 GB, speed: 26 MB/sec
W0117 18:43:36.870738   51782 node.go:85] A tick missed to fire. Node blocks too long!
W0117 18:43:36.980496   51782 node.go:85] A tick missed to fire. Node blocks too long!
E0117 18:43:36.869804   51782 pool.go:204] Echo error from 10.237.7.231:7083. Err: rpc error: code = DeadlineExceeded desc = context deadline exceeded
I0117 18:43:36.955531   51782 pool.go:215] Connection established with 10.237.7.231:5080
I0117 18:43:36.871312   51782 pool.go:215] Connection established with 10.237.7.232:7083
I0117 18:43:36.870410   51782 node.go:83] 2 became pre-candidate at term 26
I0117 18:43:36.980899   51782 node.go:83] 2 received MsgPreVoteResp from 2 at term 26
I0117 18:43:36.985357   51782 node.go:83] 2 [logterm: 26, index: 16572] sent MsgPreVote request to 1 at term 26
I0117 18:43:36.985396   51782 pool.go:215] Connection established with 10.237.7.231:7083
I0117 18:43:36.985646   51782 node.go:83] 2 [logterm: 26, index: 16572] sent MsgPreVote request to 3 at term 26
I0117 18:43:36.990598   51782 node.go:83] 2 became follower at term 26
I0117 18:43:36.996777   51782 node.go:83] 2 [commit: 16572, lastindex: 16572, lastterm: 26] starts to restore snapshot [index: 16573, term: 26]
I0117 18:43:36.996795   51782 node.go:83] log [committed=16572, applied=16572, unstable.offset=16573, len(unstable.Entries)=0] starts to restore snapshot [index: 16573, term: 26]
I0117 18:43:36.998700   51782 node.go:83] 2 restored progress of 1 [next = 16574, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I0117 18:43:36.998732   51782 node.go:83] 2 restored progress of 2 [next = 16574, match = 16573, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I0117 18:43:36.998747   51782 node.go:83] 2 restored progress of 3 [next = 16574, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I0117 18:43:37.003189   51782 node.go:83] Rolling up Created batch of size: 6.1 MB in 261.718µs.
I0117 18:43:36.998758   51782 node.go:83] 2 [commit: 16573] restored snapshot [index: 16573, term: 26]
I0117 18:43:37.010417   51782 draft.go:659] Waiting for applyCh to become empty by reaching 16572 before retrieving snapshot
I0117 18:43:37.010484   51782 draft.go:664] ---> SNAPSHOT: {Context:id:3 group:1 addr:"10.237.7.232:7083"  Index:16573 ReadTs:16296 Done:false XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}. Group 1 from node id 3
I0117 18:43:37.027829   51782 node.go:83] Rolling up Created batch of size: 18 MB in 179.782µs.
I0117 18:43:37.028945   51782 node.go:83] DropAll called. Blocking writes...
I0117 18:43:37.105268   51782 node.go:83] Rolling up Created batch of size: 8.5 MB in 81.807µs.
E0117 18:43:37.109182   51782 writer.go:51] TxnWriter got error during callback: Writes are blocked, possibly due to DropAll or Close
E0117 18:43:37.109216   51782 writer.go:51] TxnWriter got error during callback: Writes are blocked, possibly due to DropAll or Close

MichelDiz · January 17, 2019, 3:53pm

Hey Haitao,
Thanks for your report.

Can you make a clone of your data and update to latest? keep the original files safe.
Also make sure the a file called “.lock” are deleted when you update it.

PS; But anyway, fill up an issue with more details, and maybe provide a copy of your /p files to be investigated if so.

dmai · January 17, 2019, 9:41pm

When an Alpha receives a snaphot, it does a DropAll of its current data before receiving a fresh copy of the current state. This is normal and expected for snapshot retrievals.

hhtlxhhxy · January 18, 2019, 2:40am

Hi Dmai, thanks for your reply.
I do not think dropping all data is a good way when an alpha receives a snaphot because I have 1.4T data in p/ dir.It will take a long time to finish the copy.It takes nearly 12 hours.Here is the log:

I0118 06:13:26.335837   51782 node.go:83] All tables consolidated into one level. Flattening done.
I0118 06:13:26.346576   51782 snapshot.go:88] Snapshot writes DONE. Sending ACK
I0118 06:13:26.347284   51782 snapshot.go:93] Populated snapshot with 4580515595 keys.
I0118 06:13:31.894588   51782 draft.go:668] ---> Retrieve snapshot: OK.
I0118 06:13:31.894609   51782 draft.go:674] ---> SNAPSHOT: {Context:id:3 group:1 addr:"10.237.7.232:7083"  Index:16573 ReadTs:16296 Done:false XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}. Group 1. DONE.
I0118 06:13:31.968160   51782 draft.go:305] Skipping snapshot at 16573, because found one at 16573
I0118 06:13:43.781520   51782 node.go:83] 2 [commit: 16575, lastindex: 16575, lastterm: 26] starts to restore snapshot [index: 29075, term: 26]
I0118 06:13:43.781691   51782 node.go:83] log [committed=16575, applied=16575, unstable.offset=16576, len(unstable.Entries)=0] starts to restore snapshot [index: 29075, term: 26]
I0118 06:13:43.781842   51782 node.go:83] 2 restored progress of 1 [next = 29076, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I0118 06:13:43.781881   51782 node.go:83] 2 restored progress of 2 [next = 29076, match = 29075, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I0118 06:13:43.781892   51782 node.go:83] 2 restored progress of 3 [next = 29076, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I0118 06:13:43.781902   51782 node.go:83] 2 [commit: 29075] restored snapshot [index: 29075, term: 26]
I0118 06:13:43.781953   51782 draft.go:659] Waiting for applyCh to become empty by reaching 16575 before retrieving snapshot
I0118 06:13:43.781970   51782 draft.go:664] ---> SNAPSHOT: {Context:id:3 group:1 addr:"10.237.7.232:7083"  Index:29075 ReadTs:28621 Done:false XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}. Group 1 from node id 3
I0118 06:13:43.782336   51782 node.go:83] DropAll called. Blocking writes...
I0118 06:13:43.782489   51782 node.go:83] Writes flushed. Stopping compactions now...
I0118 06:13:43.782510   51782 node.go:83] Compactions stopped. Dropping all SSTables...
I0118 06:15:23.875847   51782 node.go:83] Deleted 12050 SSTables. Now deleting value logs...
I0118 06:15:23.976029   51782 node.go:83] No active value log iterators. Deleting value logs...
I0118 06:16:03.954484   51782 node.go:83] Value logs deleted. Creating value log file: 0
I0118 06:16:03.971712   51782 node.go:83] Deleted 8021 value log files. DropAll done.
I0118 06:16:03.971728   51782 node.go:83] Resuming writes
E0118 06:16:05.546690   51782 pool.go:204] Echo error from 10.237.7.232:7083. Err: rpc error: code = DeadlineExceeded desc = context deadline exceeded
I0118 06:16:08.164507   51782 pool.go:215] Connection established with 10.237.7.232:7083
I0118 06:16:09.819097   51782 node.go:83] Storing value log head: {Fid:0 Len:42 Offset:116599681}
I0118 06:16:12.319242   51782 node.go:83] Storing value log head: {Fid:0 Len:42 Offset:367790103}
I0118 06:16:13.689825   51782 node.go:83] Storing value log head: {Fid:1 Len:42 Offset:88852128}

the snapshot 16573 writes done , but during the time, the mutations keep running. So the alpha node receive another snapshot 29075 , and dropAll again.

And another suggestion, when I check the log, I can not find the code location via log.
For example:
[node.go:83] 2 restored progress of 3, but node.go line 83 is

func (rl *ToGlog) Infof(format string, v ...interface{})    { glog.Infof(format, v...) }

I think the node.go 83 is not helpful at all.

mrjn · January 18, 2019, 3:07am

The problem is not that we drop all the data in p directory, its that the datasize is a lot to transfer.

I’d suggest breaking it up into more groups, so you’re not running the entire dataset from one server (or a big chunk of it anyway). That’d also allow the datasets to be split up, and snapshot copying to succeed quickly.

hhtlxhhxy · January 18, 2019, 3:16am

Thanks for your quick reply.
I have a question, what causes the alpha node receive a snapshot, too many different data between the alpha node , so that trigger the snaphot?

mrjn · January 18, 2019, 3:21am

If the Alpha follower falls behind the leader (Raft logs), beyond leader’s latest snapshot – then the leader sends a snapshot to the follower (asks the follower to get a snapshot).

hhtlxhhxy · January 18, 2019, 3:36am

e…I don’t understand your mean clearly.Can you show me an example?Thank you very much.

mrjn · January 18, 2019, 4:04am

You’d have to understand how log replication works in Raft to understand my comment above.

You can see this: Raft to generally understand how Raft works.

Essentially, what I’m saying is, there’s update log replication which happens between leader and followers. At the same time, there’s also log truncation that happens at the leader. If leader’s log was truncated, and follower was still behind at that time (because it has fallen behind), then the follower would get the snapshot of the data from the leader.

If you don’t want these snapshot copies to happen, you could bring down your --replication flag to 1. That way, there’d only be one copy of data per Alpha group.

hhtlxhhxy · January 18, 2019, 4:11am

I read some documents about RAFT.I have understand what your mean.
And I found the alpha node lost leader before the DropAll, here

I0117 18:15:05.059846   51782 draft.go:350] List rollup at Ts 15905: OK.
E0117 18:16:40.221325   51782 pool.go:204] Echo error from 10.237.7.231:7083. Err: rpc error: code = DeadlineExceeded desc = context deadline exceeded
I0117 18:16:42.136764   51782 node.go:83] 2 [logterm: 25, index: 16229, vote: 1] cast MsgPreVote for 3 [logterm: 25, index: 16229] at term 25
I0117 18:16:42.138664   51782 node.go:83] 2 [term: 25] received a MsgVote message with higher term from 3 [term: 26]
I0117 18:16:42.138779   51782 node.go:83] 2 became follower at term 26
I0117 18:16:42.138962   51782 node.go:83] 2 [logterm: 25, index: 16229, vote: 0] cast MsgVote for 3 [logterm: 25, index: 16229] at term 26
I0117 18:16:42.138979   51782 node.go:83] raft.node: 2 lost leader 1 at term 26
I0117 18:16:42.140959   51782 node.go:83] raft.node: 2 elected leader 3 at term 26
E0117 18:16:42.555560   51782 draft.go:443] Lastcommit 15910 > current 15363. This would cause some commits to be lost.
I0117 18:16:53.148472   51782 pool.go:215] Connection established with 10.237.7.231:7083
I0117 18:16:53.350948   51782 node.go:83] 2 [term: 26] ignored a MsgHeartbeat message with lower term from 1 [term: 25]
I0117 18:16:53.350983   51782 node.go:83] 2 [term: 26] ignored a MsgHeartbeat message with lower term from 1 [term: 25]
I0117 18:16:53.351004   51782 node.go:83] 2 [term: 26] ignored a MsgHeartbeat message with lower term from 1 [term: 25]
I0117 18:16:53.351023   51782 node.go:83] 2 [term: 26] ignored a MsgHeartbeat message with lower term from 1 [term: 25]

3 became 2 's leader, and after a few minutes

I0117 18:43:29.913135   51782 node.go:83] 2 is starting a new election at term 26
E0117 18:43:29.912904   51782 pool.go:204] Echo error from 10.237.7.232:7083. Err: rpc error: code = DeadlineExceeded desc = context deadline exceeded
I0117 18:43:36.870724   51782 node.go:83] Rolling up Time elapsed: 59s, bytes sent: 1.5 GB, speed: 26 MB/sec
W0117 18:43:36.870738   51782 node.go:85] A tick missed to fire. Node blocks too long!
W0117 18:43:36.980496   51782 node.go:85] A tick missed to fire. Node blocks too long!
E0117 18:43:36.869804   51782 pool.go:204] Echo error from 10.237.7.231:7083. Err: rpc error: code = DeadlineExceeded desc = context deadline exceeded
I0117 18:43:36.955531   51782 pool.go:215] Connection established with 10.237.7.231:5080
I0117 18:43:36.871312   51782 pool.go:215] Connection established with 10.237.7.232:7083
I0117 18:43:36.870410   51782 node.go:83] 2 became pre-candidate at term 26
I0117 18:43:36.980899   51782 node.go:83] 2 received MsgPreVoteResp from 2 at term 26
I0117 18:43:36.985357   51782 node.go:83] 2 [logterm: 26, index: 16572] sent MsgPreVote request to 1 at term 26
I0117 18:43:36.985396   51782 pool.go:215] Connection established with 10.237.7.231:7083
I0117 18:43:36.985646   51782 node.go:83] 2 [logterm: 26, index: 16572] sent MsgPreVote request to 3 at term 26
I0117 18:43:36.990598   51782 node.go:83] 2 became follower at term 26

I think the RAFT is not stable because of the network.Thank you very much!

system · February 17, 2019, 4:11am

This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.

Topic		Replies	Views
Connections to all alphas started timing out around same moment Dgraph kind:question , dgraph , priority:p1 , area:crash , area:operations	2	875	December 2, 2019
Dgraph Alpha restart Dgraph dgraph	0	420	May 8, 2023
Error: A tick missed to fire. Node blocks too long!. How to resolve? Dgraph kind:question , dgraph	5	1113	January 18, 2022
Issue with Dgraph 1.0.7 Dgraph	3	509	October 11, 2018
Active Mutations stuck forever Dgraph	6	1224	July 8, 2020

One alpha node begin to dropAll when there are some normal mutations

Related topics