Remove blocking barrier distinctions #446

MathieuBordere · 2023-06-27T13:35:41Z

This is a draft PR that implements the approach to remove the (non)blocking barrier distinction discussed in #444

I believe @cole-miller is not a huge fan of the approach. Alternatives would be:

new segment format that encodes the index explicitly (more risky, think about downgrading raft versions, also need to be able to still handle old format segments)
run a barrier on the first snapshot only, this carries a performance penalty as new writes will be blocked during the snapshot.
...

codecov · 2023-06-27T13:41:32Z

Codecov Report

Merging #446 (17b8f17) into master (a40e849) will decrease coverage by 0.14%.
The diff coverage is 58.53%.

@@            Coverage Diff             @@
##           master     #446      +/-   ##
==========================================
- Coverage   76.73%   76.60%   -0.14%     
==========================================
  Files          51       51              
  Lines        9597     9616      +19     
  Branches     2443     2456      +13     
==========================================
+ Hits         7364     7366       +2     
- Misses       1159     1166       +7     
- Partials     1074     1084      +10

Impacted Files	Coverage Δ
src/client.c	`60.78% <0.00%> (-0.24%)`	⬇️
src/membership.c	`72.84% <0.00%> (-1.99%)`	⬇️
src/replication.c	`69.14% <0.00%> (-0.25%)`	⬇️
src/start.c	`62.16% <0.00%> (-1.15%)`	⬇️
src/uv_finalize.c	`65.88% <ø> (-0.40%)`	⬇️
src/uv_prepare.c	`78.10% <ø> (-0.13%)`	⬇️
src/uv_truncate.c	`55.55% <ø> (-0.38%)`	⬇️
src/uv_snapshot.c	`55.21% <53.84%> (-0.37%)`	⬇️
src/uv_append.c	`85.12% <91.66%> (+0.36%)`	⬆️
src/uv.c	`76.59% <100.00%> (+0.25%)`	⬆️

... and 1 file with indirect coverage changes

cole-miller · 2023-06-27T13:44:53Z

I believe @cole-miller is not a huge fan of the approach.

I actually don't mind it! Given the constraints it seems like a nice solution to me.

MathieuBordere · 2023-06-27T14:23:03Z

Jepsen doesn't seem extremely happy https://github.com/canonical/jepsen.dqlite/actions/runs/5390663924/jobs/9786357309, taking a look before removing draft.

MathieuBordere · 2023-06-28T09:12:38Z

Investigating the failures, it looks like raft has trouble decoding a configuration found in the raft log when taking a snapshot. All of the occurrences follow a truncation of the log though. I'm suspecting that removing the barrier before taking the snapshot, together with the truncation - that in turn also requires a barrier - has some unanticipated interaction.

freeekanayaka · 2023-06-28T09:35:10Z

src/uv_snapshot.c

+    /* The next entry in the first open segment will come after the snapshot
+     * entries. */
+    if (put->trailing == 0 && uv->prepare_next_counter == 0) {
+        uv->prepare_next_counter = 1;


It might be unrelated to the Jenkins failures, but after a very quick look at the PR's diff I noticed this change, and I'm not entirely sure it's enough. Could it be that there is a ready but yet unused open-0 open segment that will be the one used after the snapshot is installed?

Just throwing it there in case it help, didn't really look much.

freeekanayaka · 2023-06-28T09:36:35Z

Investigating the failures, it looks like raft has trouble decoding a configuration found in the raft log when taking a snapshot. All of the occurrences follow a truncation of the log though. I'm suspecting that removing the barrier before taking the snapshot, together with the truncation - that in turn also requires a barrier - has some unanticipated interaction.

Perhaps it'd be a good idea to attach to this PR the Jepsen's artifacts containing the logs of one the failing tests, for future reference (since they'll get deleted at some point).

MathieuBordere · 2023-06-28T12:58:18Z

Perhaps it'd be a good idea to attach to this PR the Jepsen's artifacts containing the logs of one the failing tests, for future reference (since they'll get deleted at some point).

If it's a real bug in the current implementation, maybe (probably) it's just a bug in this PR, attaching anyway for completeness.

What is fishy

LIBRAFT   1687943975883340965 src/replication.c:1018 log mismatch -> truncate (4353)                                                                          |    latency-raw.png
LIBRAFT   1687943975883346565 src/membership.c:187 roll back membership                                                                                       |    rate.png
LIBRAFT   1687943975883353165 src/membership.c:69 fetch committed configuration at 4808

So the node decides to truncate to index 4353, but index 4808 is supposed to be committed, that should not be possible.

and later (probably) trying to decode a non-configuration entry as a configuration entry.

LIBRAFT   1687943987751192578 src/membership.c:69 fetch committed configuration at 4808                                                                       
LIBRAFT   1687943987751194978 src/membership.c:72 configuration found in log.                                                                                 
0x7f4759461600 configurationAdd                                                                                                                               
        src/configuration.c:131                                                                                                                               
0x7f4759461dea configurationDecode                                                                                                                            
        src/configuration.c:363                                                                                                                               
0x7f475946cdab takeSnapshot                                                                                                                                   
        src/replication.c:1587                                                                                                                                
0x7f475946cdab replicationApply                                                                                                                               
        src/replication.c:1679                                                                                                                                
0x7f475946e732 replicationUpdate                                                                                                                              
        src/replication.c:762                                                                                                                                 
0x7f475946954e recvAppendEntriesResult                                                                                                                        
        src/recv_append_entries_result.c:65                                                                                                                   
0x7f4759468644 recvMessage                                                                                                                                    
        src/recv.c:36                                                                                                                                         
0x7f4759468644 recvCb                                                                                                                                         
        src/recv.c:103                                                                                                                                        
0x7f475947cbcb uvFireRecvCb                                                                                                                                   
        src/uv_recv.c:190                                                                                                                                     
0x7f475947d117 uvServerReadCb                                                                                                                                 
        src/uv_recv.c:302                                                                                                                                     
0x7f47594f6ba0 ???                                                                                                                                            
        ???:0                                                                                                                                                 
0x7f47594f76d7 ???                                                                                                                                            
        ???:0                                                                                                                                                 
0x7f47594fcb7f ???                                                                                                                                            
        ???:0                                                                                                                                                 
0x7f47594ec84b ???                                                                                                                                            
        ???:0                                                                                                                                                 
0x7f47598467cf taskRun                                                                                                                                        
        src/server.c:732                                                                                                                                      
0x7f47598467cf taskStart                                                                                                                                      
        src/server.c:772                                                                                                                                      
0x7f47598b3608 ???                                                                                                                                            
        ???:0                                                                                                                                                 
0x7f475962c132 ???                                                                                                                                            
        ???:0
0xffffffffffffffff ???
        ???:0
//TODO HERE
app: src/configuration.c:131: configurationAdd: Assertion `id != 0' failed.

jepsen-data-bank-stop-failure.zip

MathieuBordere · 2023-06-28T14:13:09Z

My gut feeling is that due to the issue in #435 (where a second barrier callback doesn't fire when all active segments are involved in a barrier), the log truncation didn't happen when a snapshot barrier was active covering up an issue that is being exposed now. But still investigating.

freeekanayaka · 2023-06-28T15:00:44Z

My gut feeling is that due to the issue in #435 (where a second barrier callback doesn't fire when all active segments are involved in a barrier), the log truncation didn't happen when a snapshot barrier was active covering up an issue that is being exposed now. But still investigating.

Could well be, but if that's the case, I'm wondering why such a bug was not surfaced by Jepsen also before the non-blocking barrier code was put in place. Or maybe our Jepsen suite is doing more nasty tests now that it was not doing before. Or we simply didn't examine some Jepsen failures before?

Anyway, logs should indeed shed some light on this.

MathieuBordere · 2023-06-28T15:02:24Z

My gut feeling is that due to the issue in #435 (where a second barrier callback doesn't fire when all active segments are involved in a barrier), the log truncation didn't happen when a snapshot barrier was active covering up an issue that is being exposed now. But still investigating.

Could well be, but if that's the case, I'm wondering why such a bug was not surfaced by Jepsen also before the non-blocking barrier code was put in place. Or maybe our Jepsen suite is doing more nasty tests now that it was not doing before. Or we simply didn't examine some Jepsen failures before?

Anyway, logs should indeed shed some light on this.

yeah, I'm a bit reasoning instinctively here, trying to gather proof now :-)

Signed-off-by: Mathieu Borderé <mathieu.bordere@canonical.com>

MathieuBordere · 2023-06-30T11:41:01Z

What seems to happen is the following:

Jepsen has a snapshot trailing of 1024 and snapshot threshold of 128.

Node takes snapshot at 2454

LIBRAFT   1688115651332445058 src/replication.c:1582 take snapshot at 2454

Data folder contains segment 0000000000000001-0000000000001408 and open-1 containing 1K+ entries.

After the snapshot completes, the log is truncated, but only the closed segment is removed (it contains older entries then the trailing cut off 1430), the open segment, that was not closed, because we don't fire a barrier anymore before the snapshot, is left as-is.

Next time we restart, raft sees the open segment, no closed segments and the snapshot and erroneously puts all entries in the open segment after the snapshot leading to data corruption.

Will try to investigate what we can do, an explicit start index in an open segment sure sounds nice ... it just too tricky without it. Leaving the barrier before taking a snapshot and living with the extra complexity is an easier, and already tested option too...

edit: Or we could say, "Always leave at least the last closed segment", but then what's the point of the trailing parameter, it gets a bit fuzzy then.

MathieuBordere · 2023-06-30T12:38:31Z

edit: Or we could say, "Always leave at least the last closed segment", but then what's the point of the trailing parameter, it gets a bit fuzzy then.

I could live with this by the way, I'd rather have this than the blocking / non-blocking barrier stuff.

@cole-miller @freeekanayaka What do you think?

MathieuBordere · 2023-06-30T12:55:46Z

Also, like @cole-miller mentioned, the introduction of open-0 will also break a raft downgrade, so we could just as well move to a new segment format with an explicit start index.

MathieuBordere · 2023-06-30T13:00:49Z

I'm going to revisit this with the insights from this exercise and live with the blocking / non-blocking distinction for now.

freeekanayaka reviewed Jun 28, 2023

View reviewed changes

Mathieu Borderé added 6 commits June 29, 2023 11:34

uv barrier: remove blocking / non-blocking distinction.

3db92f4

Signed-off-by: Mathieu Borderé <mathieu.bordere@canonical.com>

uv: Segment open-0 indicates start index 1.

6bd25eb

Signed-off-by: Mathieu Borderé <mathieu.bordere@canonical.com>

uv segment: Can't assume counter > 0 anymore.

e22d629

Signed-off-by: Mathieu Borderé <mathieu.bordere@canonical.com>

debugging

48a6471

debug

72c963b

more debug logs

6b9ce19

MathieuBordere force-pushed the remove-blocking branch from 5db80f7 to 6b9ce19 Compare June 29, 2023 09:34

assert barrier has attached

17b8f17

cole-miller mentioned this pull request Jun 29, 2023

Don't run the project tests after all canonical/jepsen.dqlite#116

Merged

MathieuBordere closed this Jun 30, 2023

MathieuBordere mentioned this pull request Jul 7, 2023

tackle open segment start index ambiguity canonical/dqlite#578

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Remove blocking barrier distinctions #446

Remove blocking barrier distinctions #446

MathieuBordere commented Jun 27, 2023

codecov bot commented Jun 27, 2023 •

edited

Loading

cole-miller commented Jun 27, 2023

MathieuBordere commented Jun 27, 2023

MathieuBordere commented Jun 28, 2023

freeekanayaka Jun 28, 2023

freeekanayaka commented Jun 28, 2023

MathieuBordere commented Jun 28, 2023 •

edited

Loading

MathieuBordere commented Jun 28, 2023 •

edited

Loading

freeekanayaka commented Jun 28, 2023

MathieuBordere commented Jun 28, 2023 •

edited

Loading

MathieuBordere commented Jun 30, 2023 •

edited

Loading

MathieuBordere commented Jun 30, 2023 •

edited

Loading

MathieuBordere commented Jun 30, 2023 •

edited

Loading

MathieuBordere commented Jun 30, 2023

Remove blocking barrier distinctions #446

Remove blocking barrier distinctions #446

Conversation

MathieuBordere commented Jun 27, 2023

codecov bot commented Jun 27, 2023 • edited Loading

Codecov Report

cole-miller commented Jun 27, 2023

MathieuBordere commented Jun 27, 2023

MathieuBordere commented Jun 28, 2023

freeekanayaka Jun 28, 2023

Choose a reason for hiding this comment

freeekanayaka commented Jun 28, 2023

MathieuBordere commented Jun 28, 2023 • edited Loading

MathieuBordere commented Jun 28, 2023 • edited Loading

freeekanayaka commented Jun 28, 2023

MathieuBordere commented Jun 28, 2023 • edited Loading

MathieuBordere commented Jun 30, 2023 • edited Loading

MathieuBordere commented Jun 30, 2023 • edited Loading

MathieuBordere commented Jun 30, 2023 • edited Loading

MathieuBordere commented Jun 30, 2023

codecov bot commented Jun 27, 2023 •

edited

Loading

MathieuBordere commented Jun 28, 2023 •

edited

Loading

MathieuBordere commented Jun 28, 2023 •

edited

Loading

MathieuBordere commented Jun 28, 2023 •

edited

Loading

MathieuBordere commented Jun 30, 2023 •

edited

Loading

MathieuBordere commented Jun 30, 2023 •

edited

Loading

MathieuBordere commented Jun 30, 2023 •

edited

Loading