LogCabin.appendEntry(3, "Server Stats")

Page Trail: [[ LogCabin.appendEntry(3, "Server Stats") ]]
2015-01-19 21:02 | raft logcabin

This is the third in a series of blog posts detailing the ongoing development of LogCabin. This entry describes a new tool to extract information from LogCabin servers and a tricky bug that occurred when unregistering handlers from the event loop.

Server Stats

Nate Hardt has been integrating and testing LogCabin into Scale's software stack, and he's run into a few issues lately that were needlessly time-consuming to diagnose. Some of the problems were silly, like when one test stopped the LogCabin daemon and it was never restarted for the next test. Still, even this was one hard to spot, since LogCabin had no tooling for diagnostics.

To make our lives easier, we wanted a tool that would go collect information that might be useful about each server's internals, then report it back in a nice way.

The first step was to collect some statistics into a Protocol Buffer, and have servers dump these out to their debug logs. They now do this periodically (defaulting to once per minute) and also upon the SIGUSR1 signal. Protocol Buffers are nice for this sort of thing, since we anticipate the number of stats to grow over time, and not every tool needs to understand each stat.

Here's an example of the raw output (using the Protocol Buffers text format):

server_id: 1
address: "192.168.2.1:61023"
start_at: 1421726306722327036
end_at: 1421726306722407779
raft {
  current_term: 39
  state: LEADER
  commit_index: 135
  last_log_index: 135
  leader_id: 1
  voted_for: 1
  start_election_at: 9223372036854775807
  withhold_votes_until: 9223372036854775807
  last_snapshot_index: 123
  last_snapshot_bytes: 1207
  log_start_index: 124
  log_bytes: 11019
  peer {
    server_id: 1
    old_member: true
    new_member: false
    staging_member: false
    last_synced_index: 135
  }
  peer {
    server_id: 2
    old_member: true
    new_member: false
    staging_member: false
    request_vote_done: true
    have_vote: true
    force_heartbeat: false
    next_index: 136
    last_agree_index: 135
    is_caught_up: true
    next_heartbeat_at: 1421726306777304527
    backoff_until: 1421726273743534090
  }
  peer {
    server_id: 3
    old_member: true
    new_member: false
    staging_member: false
    request_vote_done: false
    have_vote: false
    force_heartbeat: false
    next_index: 136
    last_agree_index: 135
    is_caught_up: true
    next_heartbeat_at: 1421726306779778550
    backoff_until: 1421726273643086864
  }
  peer {
    server_id: 4
    old_member: true
    new_member: false
    staging_member: false
    request_vote_done: false
    have_vote: false
    force_heartbeat: false
    next_index: 136
    last_agree_index: 135
    is_caught_up: true
    next_heartbeat_at: 1421726306781546795
    backoff_until: 1421726270475566462
  }
  peer {
    server_id: 5
    old_member: true
    new_member: false
    staging_member: false
    request_vote_done: true
    have_vote: true
    force_heartbeat: false
    next_index: 136
    last_agree_index: 135
    is_caught_up: true
    next_heartbeat_at: 1421726306783424837
    backoff_until: 1421726273743630864
  }
}

The second step was to go collect all this information with a new RPC, named getServerStats(). This RPC is different from existing ones in that it's not destined for the cluster leader. That's because we want statistics from every individual server, and they need to be collected even if the cluster has no leader. The client library had to be refactored a little bit as a result, so that the event loop and TCP connection rate-limiting mechanism are available outside of Client::LeaderRPC. A new client binary called ServerStats invokes the RPC and prints out the results.

Finally, the scripts/serverstats.py script understands the meaning of the ServerStats fields, and it tries to present something a little nicer for human consumption. Some of the fields in the raw output (like nanoseconds since the Unix epoch) are not easy for humans, so the script translates those to more meaningful formats. It also uses colors to highlight interesting things, and it'll output a warning if the cluster has no leader (more warnings to come in the future).

Here's an example of the serverstats.py output for the same server as above:

Server 1 at 192.168.2.1:61023:
  Leader at term 39
  Snapshot covers entries 1 through 123 (1207 bytes)
  Log covers entries 124 through 135 (11019 bytes)
  All log entries committed
  All log entries flushed to disk
  Voted for server 1
  Withholding votes for +infinity
  Configuration: [1, 2, 3, 4, 5]
  Peer 2 (old/curr):
    Next index: 136
    Match index: 135
    Next heartbeat in +54.897 ms
  Peer 3 (old/curr):
    Next index: 136
    Match index: 135
    Next heartbeat in +57.371 ms
  Peer 4 (old/curr):
    Next index: 136
    Match index: 135
    Next heartbeat in +59.139 ms
  Peer 5 (old/curr):
    Next index: 136
    Match index: 135
    Next heartbeat in +61.017 ms
  Stats collected at 2015-01-19 19:58:26.722
  Took 0.081 ms to generate stats

The ServerStats structure will need to include much more information to be comprehensive, but it's probably easier to do that over time than all at once. It currently includes just the state that was easily available in the Raft module. There's also room for improvement on formatting the information nicely and highlighting problems. Still, it's a useful tool already, and it's a good starting point for further iteration.

DumpTree

It's also important to be able to see what a LogCabin state machine is storing in its Tree structure. I created a simple client called DumpTree to recursively list out the values for each key. This will only work for small state machines with human-readable values, but it's so much better than not being able to see inside at all or writing a new C++ client every time.

Event Loop Crashes

Nate kept running into crashes like this one, which came with pretty mysterious error messages:

pure virtual method called
terminate called without an active exception
Program received signal SIGABRT, Aborted.

After seeing a few of these with similar stack traces, we took a closer look and found the problem. It's subtle but worth discussing.

LogCabin has a set of classes that wrap epoll and provide an event loop. Event::File used to be an abstract base class that would register a file descriptor with the event loop and arrange for the event loop thread to call a virtual handleFileEvent() method appropriately. The destructor on File would first interrupt the event loop thread, then unregister the file handler.

RPC::ReceiveSocket is one example of a class that derives from Event::File, representing the receiving end of a TCP connection. When ReceiveSocket is destroyed, C++ calls its destructor, starts to destroy the ReceiveSocket members, probably scribbles on the vtable, and only then does it call the destructor on the base class, Event::File. If the event loop thread called handleFileEvent at this point (just before the Event::File destructor), the process would crash.

The desired behavior is to run through the shutdown procedure for Event::File first, interrupting the event loop thread and unregistering the file handler. Only then would it be safe to start destroying the ReceiveSocket.

One way to achieve this behavior is to require all classes that derive from Event::File to call a shutdown method on Event::File as the first step in their destructors. However, this approach would be error-prone: if someone forgot to call this method in any one class, they might get crashes, either now or anytime in the future.

Instead, the approach I implemented split Event::File into two classes: one to provide a handler, and a second one, called a Monitor, to register the handler with the event loop. The lifetime of the handler must extend beyond that of the monitor; thus, the monitor's destructor will interrupt the event loop and unregister the handler before the handler begins to be destroyed. This is relatively easy for users of these classes to get right: they generally declare a monitor following a handler in the same object or scope. The monitor's constructor needs a reference to the handler, so it's hard to declare these variables backwards. And if someone forgets to create a monitor altogether, their handler will never fire, so they will probably notice in testing.

Next

Scale is in the middle of an office move that's making some of the development and test clusters unavailable, so it's probably a good time to work through some of the issue backlog next. Thanks to Scale Computing for supporting this work. And congrats to Nate on his first two pull requests (#79 and #81).