You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@pegasus.apache.org by GitBox <gi...@apache.org> on 2021/06/16 08:48:37 UTC
[GitHub] [incubator-pegasus] Shuo-Jia opened a new issue #764: duplicating&learngin(3/4): plog in `/learn` path of learning may be lost at start copy plog process when duplicating
Shuo-Jia opened a new issue #764:
URL: https://github.com/apache/incubator-pegasus/issues/764
## Bug Report
when I fix `reset_from` bug in testing https://github.com/XiaoMi/rdsn/pull/845, I found the `learn plog` may be incomplete.
for duplicating, if some log hasn't been confirmed, it will be reserve and send the `potential secondary`, the case which is named `step back` and the log learned of `potential secondary` in `/learn` path will be moved and replace`/plog`path file in https://github.com/XiaoMi/rdsn/blob/v2.2/src/replica/replica_learn.cpp#L1526. However, the `reset_from` is mot been implemented correctly, https://github.com/XiaoMi/rdsn/pull/845 is resolve the case. but the follow log show the log learned may be incomplete to start at the source(learnee node).
**Learnee:**
Learnee receve learn request and find should step back("last_max_decree(9217992) vs learn_start_decree(7255649)" in log, learn_start_decree step back to be equal with last confirmed decree for duplicating), and plog file selected is index 292("learned files count 1 (292 => 292)" in log)
```
D2021-06-11 15:40:06.539 (1623397206539476516 119869) replica.replica17.0400d3f800032c69: mutation_log.cpp:1148:get_learn_state(): gpid(265.18) get_learn_state returns false, private logs count 73 (220 => 292), learned files count 1 (292 => 292): learned_file_start_offset(8504932039) >= valid_start_offset(8504932039) && last_max_decree(9217992) > 0 && last_max_decree(9217992) < learn_start_decree(7255649)
D2021-06-11 15:40:06.539 (1623397206539545453 119869) replica.replica17.0400d3f800032c69: replica_learn.cpp:482:on_learn(): 265.18@10.132.5.5:32801: on_learn[0000006c00000002]: learner = 10.132.5.21:32801, choose to learn private logs, because learn_start_decree steps back for duplication
```
the index 292 log infomation(size=33MB):
```
mi mi 33M 6月 11 17:21 log.292.8504932039
```
context as follow, that is to say, the start decree is 9217993, but not 7255649
```
mutation: gpid=265.18, ballot=106, decree=9217993, timestamp=2021-06-11 15:39:42.084, last_committed_decree=9217992
```
**Learnee:**
Learnee receved the response and start copy remote plog file
```
D2021-06-11 15:40:06.540 (1623397206540251920 51589) replica.replica17.0405001100000283: replica_learn.cpp:601:on_learn_reply(): 265.18@10.132.5.21:32801: on_learn_reply_start=>jiashuo_debug[0000006c00000002]: learnee = 10.132.5.5:32801, learn_duration = 0 ms, response_err = ERR_OK, remote_committed_decree = 9220655, prepare_start_decree = -1, learn_type = replication::learn_type::LT_LOG, learned_buffer_size = 5828, learned_file_count = 1, to_decree_included = 9220655, learn_start_decree = 7255649[9217971], current_learning_status = replication::learner_status::LearningWithoutPrepare
D2021-06-11 15:40:06.565 (1623397206565705781 51624) replica.rep_long2.0405001100000285: replica_learn.cpp:1065:on_copy_remote_state_completed(): 265.18@10.132.5.21:32801: on_copy_remote_state_completed[0000006c00000002]: learnee = 10.132.5.5:32801, learn_duration = 26 ms, copy remote state done, err = ERR_OK, copy_file_count = 1, copy_file_size = 3501690, copy_time_used = 20 ms, local_committed_decree = 9217971, app_committed_decree = 9217971, app_durable_decree = 9217971, prepare_start_decree = -1, current_learning_status = replication::learner_status::LearningWithoutPrepare
```
the file size info is(file size only has 3.4MB(same with result of log, that is "copy_file_size = 3501690")):
```
mi mi 3.4M 6月 11 15:51 log.292.8504932039
```
file context is:
```
mutation: gpid=265.18, ballot=106, decree=9217993, timestamp=2021-06-11 15:39:42.084, last_committed_decree=9217992
```
**That is to say**
* the plog selected whic need learned start decree is not equal or less `true start_decree of duplicating`
* learnee's log send remote, but learner receved file size is not equal with origin file
so when replay the log, it will core dump for mutaion loss:
```
E2021-06-11 15:40:06.588 (1623397206588520392 51624) replica.rep_long2.0405001100000285: replica_learn.cpp:1617:apply_learned_state_from_private_log(): [265.18@10.132.5.21:32801] repaly_before=>jiashuo_debug: step back=true, last_commit_decree=9217971, dup=true
D2021-06-11 15:40:06.588 (1623397206588854941 51624) replica.rep_long2.0405001100000285: mutation_log_replay.cpp:36:replay(): start to replay mutation log /home/work/ssd10/pegasus/c4tst-tune/replica/reps/265.18.pegasus/plog/log.292.8504932039, offset = [8504932039, 8508433729), size = 3501690
F2021-06-11 15:40:06.589 (1623397206589160526 51624) replica.rep_long2.0405001100000285: prepare_list.cpp:155:commit(): assertion expression: mu != nullptr && mu->is_logged()
F2021-06-11 15:40:06.589 (1623397206589180244 51624) replica.rep_long2.0405001100000285: prepare_list.cpp:155:commit(): [265.18@10.132.5.21:32801] mutation 9217972 is missing in prepare list
```
I don't know this bug whether caused only by learn or cause by duplicating, mark it and test later
### Vresion
https://github.com/apache/incubator-pegasus/tree/v2.2.0-RC0
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@pegasus.apache.org
For additional commands, e-mail: dev-help@pegasus.apache.org