Start instrumenting existing code with state machines #678

cole-miller · 2024-08-05T03:12:15Z

This PR introduces several state machines to track and instrument the behavior of existing dqlite code. Specifically, we instrument:

Write transactions on the leader (leader__exec)
Requests to append a COMMAND entry to the raft log (raft_apply)
AppendEntries processing on the follower (replicationAppend)
Individual in-memory log entries (log.c)
Disk write requests for entries (UvAppend)
On-disk log truncation (UvTruncate)

There are lots more things we could instrument but I think this is a good starting point: it gives us enough visibility to follow a write transaction over its whole lifecycle and down to the disk I/O level, on both the follower and the leader. (A big missing piece is linking the histories across nodes; that's nontrivial because our raft messages don't include any kind of ID or room for extensibility, although we could fake something in the I/O fixture.)

The tracking of in-memory log entries is the trickiest part of this PR. I was initially uncertain whether to attach SMs to individual log entries at all, but I found this served as a convenient "hub" to connect other state machines together (e.g. bridging the raft_apply and UvAppend state machines), plus it gives a foothold for tracking how long it takes to apply each entry.

I also added state machines for the append and truncate requests in the raft I/O fixture (raft/fixture.c). This was necessary because the code in raft/replication.c now assumes that the I/O backend makes an SM available to call sm_relate with. The SMs in the fixture are not copies of the ones in the uv I/O backend, but simpler ones.

Finally, I made a few fixes and additions to the sm code.

Signed-off-by: Cole Miller <[email protected]>

This fires on all our invocations of vsnprintf, but only with clang (gcc makes an exception for variadic functions presumably for just this reason). I think the value of this lint for us is not worth its price in \#pragma verbosity. Signed-off-by: Cole Miller <[email protected]>

codecov · 2024-08-05T03:22:17Z

Codecov Report

Attention: Patch coverage is 81.85185% with 49 lines in your changes missing coverage. Please review.

Project coverage is 81.07%. Comparing base (4e328c9) to head (85e494d).
Report is 31 commits behind head on master.

Files with missing lines	Patch %	Lines
src/raft/replication.c	65.06%	22 Missing and 7 partials ⚠️
src/lib/sm.c	57.14%	0 Missing and 6 partials ⚠️
src/raft/client.c	76.19%	4 Missing and 1 partial ⚠️
src/raft/log.c	92.00%	1 Missing and 3 partials ⚠️
src/raft/fixture.c	93.18%	0 Missing and 3 partials ⚠️
src/raft/uv_truncate.c	95.23%	1 Missing ⚠️
test/raft/lib/heap.c	0.00%	0 Missing and 1 partial ⚠️

Additional details and impacted files

@@            Coverage Diff             @@
##           master     #678      +/-   ##
==========================================
+ Coverage   74.21%   81.07%   +6.86%     
==========================================
  Files         195      197       +2     
  Lines       27738    29164    +1426     
  Branches     2794     4066    +1272     
==========================================
+ Hits        20585    23644    +3059     
+ Misses       4827     3875     -952     
+ Partials     2326     1645     -681

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

Overloading the err_after_request_alloc label resulted in a potential uninitialized use of `j`. Signed-off-by: Cole Miller <[email protected]>

cole-miller · 2024-08-05T04:03:57Z

Pictures!

Leader's view of executing a write transaction in a one-node cluster (./integration-test cluster/restart):

From top to bottom, we have the leader__exec request, the raft_apply request, the new log entry, and the UvAppend request. You can see how long it took to executing the transaction initially, how long it took to write it to disk, and how long it took to apply it once committed.

Follower's view of handling an AppendEntries (./integration-test cluster/dataOnNewNode):

At the top is the main appendFollower request. Below that are 10 log entries, and at the bottom is the disk write for the entries.

Finally, a different view of AppendEntries handling on the follower's side. This one uses the fixture (./raft-core-integration-test replication/recvRollbackConfigurationToInitial), so the I/O related state machines are simpler.

Here, the follower truncated an entry from its log because of the AppendEntries. You see the appendFollower request at the top, then the truncated entry, then the disk truncate, then the two entries that were included in the AppendEntries, then the disk append. You can see that the truncate and append operations are concurrent---replicationApply doesn't wait for the former to finish before kicking off the latter (something I hadn't noticed before I put together this PR). If we used the real I/O backend and instrumented a bit more we'd see that UvTruncate sets a UvBarrier which blocks the UvAppend from running until the truncate has finished.

just-now

The patch looks good to me. Just minor changes are needed.

just-now · 2024-09-05T11:58:38Z

src/leader.c

+	EXEC_NR,
+};
+
+static const struct sm_conf exec_states[EXEC_NR] = {


just wanted to leave this code here to show that it's possible to define states in a more compact way:

#define _S(name, flags, allowed) \ [name] = { \ .flags = flags, \ .name = #name, \ .allowed = allowed \ } _S(INIT, SM_INITIAL, BITS(INIT, DONE)),

I'm not sure. I experimented with switching the state machine definitions over to this style, and it works well for some of them, but once you have more than a few allowed transitions out of some state the lines get long enough to need breaking, and at that point you're more or less back to the beginning. I've pushed a commit that rewrites the definitions in this style, let me know what you think.

Not pushing for this style, but it's my personal preference.

src/lib/sm.c

src/raft/fixture.c

src/raft/replication.c

src/raft/fixture.c

just-now · 2024-09-05T12:33:44Z

src/raft/log.c

+		if (ref == NULL && !collision) {
+			return NULL;


Initial logic looks a bit different. !collision looks to be a new element in this case.

Fixed, the two return values are unnecessarily hard to reason about so I switched to using a non-NULL sentinel for the collision case, which allows hewing more closely to the original code structure.

src/raft/replication.c

Signed-off-by: Cole Miller <[email protected]>

realloc does not promise to return NULL when the size argument is 0. Signed-off-by: Cole Miller <[email protected]>

Signed-off-by: Cole Miller <[email protected]>

just-now

Looks good to me.

just-now · 2024-09-27T09:15:56Z

src/leader.c

+	EXEC_NR,
+};
+
+static const struct sm_conf exec_states[EXEC_NR] = {


Not pushing for this style, but it's my personal preference.

just-now · 2024-09-27T09:17:48Z

src/lib/sm.c

-	m->is_locked = is_locked;
-	m->id = ++id;
-	m->pid = getpid();
+	*m = (struct sm){


This looks cool as it's easier to grep out initialization with grep "(struct sm){".

just-now · 2024-09-27T09:33:38Z

src/raft/client.c

-	if (rv != 0) {
-		goto err;
+	index = start;
+	for (unsigned i = 0; i < n; i++) {


Is the reason of removing logAppendCommands() helper is just cleaner code or I'm missing something?

It's just a cleanup, yes.

just-now · 2024-09-27T09:41:26Z

src/raft/fixture.c

-	if (n > 0) {
-		struct raft_entry *entries;
-
-		/* Create a new array of entries holding the non-truncated
-		 * entries */
-		entries = raft_malloc(n * sizeof *entries);
-		if (entries == NULL) {
-			return RAFT_NOMEM;
-		}
-		memcpy(entries, io->entries, n * sizeof *io->entries);
-
-		/* Release any truncated entry */
-		if (io->entries != NULL) {
-			size_t i;
-			for (i = n; i < io->n; i++) {
-				raft_free(io->entries[i].buf.base);
-			}
-			raft_free(io->entries);
-		}
-		io->entries = entries;
-	} else {


I see that if { } statement goes to ioFlushTruncate(). I wasn't able to identify where else {} statement goes in the new code. Could you clarify this?

…-work

Signed-off-by: Cole Miller <[email protected]>

cole-miller added 17 commits August 2, 2024 18:05

leader: Add state machine for exec requests

9f0f195

Signed-off-by: Cole Miller <[email protected]>

sm: Initialize rc field

7afa477

Signed-off-by: Cole Miller <[email protected]>

raft/client: Introduce state machine for raft_apply requests

62380b1

Signed-off-by: Cole Miller <[email protected]>

raft/log: Add state machine for active entries

5db84c2

Signed-off-by: Cole Miller <[email protected]>

raft/uv_append: Add state machine for append requests

96f9759

Signed-off-by: Cole Miller <[email protected]>

raft/replication: Create state machine to track appendFollower

05c4891

Signed-off-by: Cole Miller <[email protected]>

sm: Observe failures

65032c8

Signed-off-by: Cole Miller <[email protected]>

sm: Remove extraneous newlines

24cb351

Signed-off-by: Cole Miller <[email protected]>

sm: Support attributes

fde8bbe

Signed-off-by: Cole Miller <[email protected]>

Note number of follower append entries in an attr

51f4baa

Signed-off-by: Cole Miller <[email protected]>

Remove problematic entry-to-append on follower

ccf87e2

Signed-off-by: Cole Miller <[email protected]>

Set up I/O fixture with simple sms

be2f9d3

Signed-off-by: Cole Miller <[email protected]>

Add a state machine for truncate requests

c20e79b

Signed-off-by: Cole Miller <[email protected]>

Make the fixture's truncate method async

cb93894

Signed-off-by: Cole Miller <[email protected]>

Relate follower append to log truncation

51ee710

Signed-off-by: Cole Miller <[email protected]>

Ifdef out raft-related sm_relate for external raft builds

c90a011

Signed-off-by: Cole Miller <[email protected]>

Fix cleanup in appendLeader

fa3f0b4

Overloading the err_after_request_alloc label resulted in a potential uninitialized use of `j`. Signed-off-by: Cole Miller <[email protected]>

cole-miller requested a review from just-now August 7, 2024 11:30

cole-miller mentioned this pull request Sep 2, 2024

Fixes for sm.c #695

Merged

just-now reviewed Sep 5, 2024

View reviewed changes

cole-miller added 3 commits September 23, 2024 14:30

Address review comments

11665b2

Signed-off-by: Cole Miller <[email protected]>

Remove overzealous assert

bc7a5ec

realloc does not promise to return NULL when the size argument is 0. Signed-off-by: Cole Miller <[email protected]>

Shorten state machine declarations

2c2ce8b

Signed-off-by: Cole Miller <[email protected]>

just-now approved these changes Sep 27, 2024

View reviewed changes

cole-miller added 3 commits October 7, 2024 15:17

Merge remote-tracking branch 'canonical/master' into tx-observability…

66a2cd1

…-work

Fix

19f455b

Signed-off-by: Cole Miller <[email protected]>

Fix

633f471

Signed-off-by: Cole Miller <[email protected]>

cole-miller added 3 commits October 7, 2024 15:43

Fix CI

07ed5b9

Signed-off-by: Cole Miller <[email protected]>

Investigate

33a4a24

Signed-off-by: Cole Miller <[email protected]>

Try to appease ASan

85e494d

Signed-off-by: Cole Miller <[email protected]>

cole-miller merged commit 81eeab5 into canonical:master Oct 7, 2024
12 of 13 checks passed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Start instrumenting existing code with state machines #678

Start instrumenting existing code with state machines #678

cole-miller commented Aug 5, 2024

codecov bot commented Aug 5, 2024 •

edited

Loading

cole-miller commented Aug 5, 2024 •

edited

Loading

just-now left a comment

just-now Sep 5, 2024

cole-miller Sep 23, 2024

just-now Sep 27, 2024

just-now Sep 5, 2024

cole-miller Sep 23, 2024

just-now left a comment

just-now Sep 27, 2024

just-now Sep 27, 2024

just-now Sep 27, 2024

cole-miller Oct 1, 2024

just-now Sep 27, 2024

Start instrumenting existing code with state machines #678

Start instrumenting existing code with state machines #678

Conversation

cole-miller commented Aug 5, 2024

codecov bot commented Aug 5, 2024 • edited Loading

Codecov Report

cole-miller commented Aug 5, 2024 • edited Loading

just-now left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

just-now left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

codecov bot commented Aug 5, 2024 •

edited

Loading

cole-miller commented Aug 5, 2024 •

edited

Loading