p2p liveness checking

[pmesnier]

Relates to #291. Add a new pair of messages to the net plugin that carry the current time as a payload. These messages could be used for liveness checking in the case of peers that are non-producing full nodes. The two messages, Ping and Pong, may work for detecting clock skew but I'm not certain that will be particularly accurate when dealing with varying levels of network latency introduced by the use asynch messaging. Perhaps sending a second round of messages that carry the result of timing the send of the first message.

[pmesnier]

Let's also add fields to the handshake message to make it effectively a "ping" as well. Note that each side will independently send a handshake message at connection start time. To make latency measurement work, we'll have to make the peer answer a handshake with a "pong" message.

[jgiszczak]

Debugging is ongoing.

[jgiszczak]

Packets are transmitted and received and processed and... something is slightly tangled in the processing of each peer's timestamps, so the numbers make no sense. I just have to work through it.

[jgiszczak]

Processing is working. Currently attempting to explain unusually high measured latency.

[jgiszczak]

Modifying start_read_message to use async_read_some instead of async_read reduces measured latency from 20 ms to 12 ms.

[pmesnier]

That's interesting. Can you remind me the branch you are using for this work?
I'd like to see how you are caching partial messages. In fact, on TAO we found amazing speedup using application level buffer management.

[jgiszczak]

The branch name is p2p-liveness-checking-395, but I haven't pushed it yet. It still contains C-isms that have to be eradicated. The relevant method is small enough though.

    void read_pending( connection_ptr c ) {
      c->socket->async_read_some(boost::asio::buffer(c->pending_message_buffer.data() + c->pending_message_offset,
                                 c->pending_message_size),
          [this,c]( boost::system::error_code ec, std::size_t bytes_transferred)
    {
          if(!ec) {
            c->message_size += bytes_transferred;
            try {
              auto msg = fc::raw::unpack<net_message>( c->pending_message_buffer );
              c->pending_message_offset = 0; // no unpack exception, so we have a whole msg
              precache pc( c );
              msg.visit (pc);
              start_read_message( c );

              msgHandler m(*this, c);
              msg.visit(m);
              return;
            } catch ( const fc::exception& ) {
              c->pending_message_offset += bytes_transferred;
              read_pending( c );
            }
          } else {
            elog( "Error reading message from connection: ${m}", ("m", ec.message() ) );
          }
        });
    }

This is a substitute for start_reading_pending_buffer(), invoked in the same location and manner as that method, in start_read_message(). It depends on a new member, size_t pending_message_offset{0}; added to the connection class.

[jgiszczak]

After correcting my math, here's what clock offsets look like:

Using async_read is indistinguishable from async_read_some on an unloaded system.

For posterity, the plot comes from outputting the clockoffset with dlog() as:

1011483ms thread-0   net_plugin.cpp:813            handle_message       ] Clock offset is 21413.00000000000000000ns (21.41300000000000026us)

then running:

grep "Clock offset" stderr.txt | tr -d '()' | awk '{print $10}' | gnuplot -p -e "set title 'Clock Offset'; set ylabel '{/Symbol m}s'; set grid xtics ytics; plot '<cat' title '' with lines"

in the data directories produced by launcher.

[jgiszczak]

Rebased and reconstructed to mesh well with branch p2p-sync-slow-peers and pushed.

[pmesnier]

closing, feature merged into master