log bytes recv/sent per command #6589

jonasschnelli commented at 3:12 PM on August 25, 2015: contributor

Not sure if we want to have this is master.

This adds a sent/recv byte counter per command to each CNode. It is a waste product of some statistics gathering during finding a strategy for throttling nodes without affecting the overall quality of the network.

I think throttling the block response to a node with a height < self.height - 288 (TBD) would be a good approach. Nodes in initial sync might need longer to catch up if they are connected to throttled nodes only. Initial sync is a one time process and is therefore (maybe) be not very time critical.

Example:

    "bytessent_per_cmd": {
      "addr": 30003,
      "block": 28981980,
      "getheaders": 9682,
      "headers": 82,
      "inv": 30843,
      "ping": 48,
      "pong": 40,
      "tx": 97400,
      "verack": 0,
      "version": 103
    },
    "bytesrecv_per_cmd": {
      "getaddr": 0,
      "getdata": 11935,
      "getheaders": 997,
      "headers": 1458027,
      "ping": 40,
      "pong": 40,
      "reject": 230,
      "verack": 0,
      "version": 102
    }

in src/net.cpp:None in cb3efd97eb outdated

2173 | @@ -2171,7 +2174,7 @@ void CNode::AbortMessage() UNLOCK_FUNCTION(cs_vSend)
2174 |      LogPrint("net", "(aborted)\n");
2175 |  }
2176 |  
2177 | -void CNode::EndMessage() UNLOCK_FUNCTION(cs_vSend)
2178 | +void CNode::EndMessage(const char* pszCommand) UNLOCK_FUNCTION(cs_vSend)

sipa commented at 8:44 PM on August 25, 2015:

Any reason not to use const std::string& ?

jonasschnelli commented at 12:00 PM on August 26, 2015:

CNode::BeginMessage() also uses const char* (https://github.com/bitcoin/bitcoin/blob/master/src/net.h#L499). EndMessage() is always called over PushMessage(const char* pszCommand, const T1& a1, ...). Not sure if it would make sense to cast/transform to a std::string.

sipa commented at 7:06 PM on August 26, 2015:

ok

laanwj commented at 9:05 AM on December 4, 2015:

Right, I agree with @sipa that I prefer std::string, but yes for that to have any effect whatsoever that'd require switching that entire call chain to std::string and that is out of the scope of this pull.

paveljanik commented at 12:39 PM on December 5, 2015:

On the other hand, we are already changing EndMessage() here, so it could be done in one step, together.

jonasschnelli commented at 12:42 PM on December 5, 2015:

I think it's to invasive for a little logging feature. It would basically require to change all PushMessage(...) then BeginMessage() and EndMessage() function. An either conversion of CMessageHeader (that it accepts std::string) or some conversions to c-strings in the mentioned functions. IMO, it's not worth changing this.

paveljanik commented at 12:48 PM on December 5, 2015:

Agreed.

in src/net.cpp:None in cb3efd97eb outdated

 612 | @@ -613,7 +613,9 @@ void CNode::copyStats(CNodeStats &stats)
 613 |      X(fInbound);
 614 |      X(nStartingHeight);
 615 |      X(nSendBytes);
 616 | +    X(mSendBytesPerCmd);

sipa commented at 8:45 PM on August 25, 2015:

I don't care about following the original variable naming style, but if you do, the prefix for maps is map* not m*.

in src/net.cpp:None in cb3efd97eb outdated

2196 | @@ -2194,6 +2197,9 @@ void CNode::EndMessage() UNLOCK_FUNCTION(cs_vSend)
2197 |      unsigned int nSize = ssSend.size() - CMessageHeader::HEADER_SIZE;
2198 |      WriteLE32((uint8_t*)&ssSend[CMessageHeader::MESSAGE_SIZE_OFFSET], nSize);
2199 |  
2200 | +    //log total amount of bytes per command
2201 | +    mSendBytesPerCmd[std::string(pszCommand)]+=nSize;

sipa commented at 8:47 PM on August 25, 2015:

Spaces around the operator?

sipa commented at 8:48 PM on August 25, 2015: member

Concept ACK, I think this is useful.

jonasschnelli force-pushed on Aug 26, 2015

jonasschnelli commented at 12:06 PM on August 26, 2015: contributor

Thanks @sipa for reviewing! Fixed nits. Added bytessent_per_cmd and bytesrecv_per_cmd to getpeersinfo help.

sipa commented at 4:40 PM on August 26, 2015: member

I haven't checked the code for this, but we should make sure this only accounts for incoming messages of a known type. Otherwise you introduce a memory DoS attack by allowing the sender to construct an arbitrarily-sized map.

jonasschnelli commented at 4:50 PM on August 26, 2015: contributor

@sipa: good point! Will address it soon.

theuni commented at 6:47 PM on August 26, 2015: member

These maps will need locking

Edit: I take that back. It looks like the cs_vNodes in CopyNodeStats is enough. Might want to make CNode::mapSendBytesPerCmd / CNode::mapRecvBytesPerCmd private though, so nobody's tempted to use them directly.

jonasschnelli force-pushed on Aug 27, 2015

jonasschnelli commented at 7:09 AM on August 27, 2015: contributor

@theuni: Right. I was aware of the locking and did come to the conclusion that both new maps are protected by cs_vSend and cs_vRecvMsg.

Moved the maps to the private section.

jonasschnelli commented at 1:21 PM on August 27, 2015: contributor

Added memory DOS prevention by filtering valid commands.

laanwj added the label P2P on Sep 4, 2015

in src/net.cpp:None in e332924936 outdated

 675 | @@ -667,6 +676,19 @@ bool CNode::ReceiveMsgBytes(const char *pch, unsigned int nBytes)
 676 |          nBytes -= handled;
 677 |  
 678 |          if (msg.complete()) {
 679 | +
 680 | +            //store received bytes per command
 681 | +            //to prevent a memory DOS, only allow valid commands
 682 | +            std::string command(msg.hdr.pchCommand);
 683 | +            for (unsigned int i = 0; i < sizeof(logAllowIncommingCmds)/sizeof(logAllowIncommingCmds[0]); i++)

sdaftuar commented at 1:57 PM on September 10, 2015:

Since this is a map lookup, can we just initialize the map once with entries for each valid string, and then do a find() here?

jonasschnelli commented at 1:59 PM on September 10, 2015:

Yes. Would be possible. I somehow searched for a solution that doesn't require initialization. Do you think the map.find() would be faster or just less code?

sdaftuar commented at 2:05 PM on September 10, 2015:

Mostly I was thinking less code/easier to read (though it would be faster too, since we have to do a find() anyway).

laanwj commented at 1:25 PM on December 3, 2015:

C++11 to the rescue:

const static std::set<std::string> logAllowIncommingCmds = {
    "version", "verack", "addr", "inv", "getdata",
    "getblocks", "getheaders", "tx", "headers", "block",
    "getaddr", "mempool", "ping", "pong", "alert",
    "filterload", "filteradd", "filterclear", "reject"
};

    if (logAllowIncomingCmds.count(command))
        mapRecvBytesPerCmd[command] += msg.hdr.nMessageSize;

jgarzik commented at 9:48 AM on October 1, 2015: contributor

ut ACK - this actually recreates a change I wrote a long time ago (first version of getpeerinfo did this)

dcousens commented at 11:30 PM on October 4, 2015: contributor

concept ACK

edit: is it worth persisting this to storage?

jonasschnelli force-pushed on Dec 3, 2015

jonasschnelli commented at 4:12 PM on December 3, 2015: contributor

IMO for (unsigned int i = 0; i < sizeof(logAllowIncommingCmds)/sizeof(logAllowIncommingCmds[0]); i++) is fine until we switch over to C++11. @dcousens: not sure if disk persistence would make sense here. I'd like to extend this up to the GUI layer to have a better network/bandwidth graph that could also generate and show data when it's not opened, though, this PR does not include time based data logging.

jonasschnelli force-pushed on Dec 3, 2015

jonasschnelli commented at 8:08 AM on December 4, 2015: contributor

Passed Travis now. Would be nice if someone can test this.

laanwj commented at 9:05 AM on December 4, 2015: member

Going to test this

in src/net.cpp:None in 6fef53a4d1 outdated

 690 | @@ -682,6 +691,19 @@ bool CNode::ReceiveMsgBytes(const char *pch, unsigned int nBytes)
 691 |          nBytes -= handled;
 692 |  
 693 |          if (msg.complete()) {
 694 | +
 695 | +            //store received bytes per command
 696 | +            //to prevent a memory DOS, only allow valid commands
 697 | +            std::string command(msg.hdr.pchCommand);
 698 | +            for (unsigned int i = 0; i < sizeof(logAllowIncomingCmds)/sizeof(logAllowIncomingCmds[0]); i++)

laanwj commented at 9:10 AM on December 4, 2015:

I've thought of - what I think is an even better solution - as it doesn't require recourse to anything besides the map itself: prepopulate the mapRecvBytesPerCmd. At initialization:

    for (unsigned int i = 0; i < sizeof(logAllowIncomingCmds)/sizeof(logAllowIncomingCmds[0]); i++)
        mapRecvBytesPerCmd[logAllowIncomingCmds[i]] = 0;

Then only increase if the item exists, e.g.

    mapCmdSize_t::iterator i = mapRecvBytesPerCmd.find(msg.hdr.pchCommand);
    if (i != mapRecvBytesPerCmd.end())
        i->second += msg.hdr.nMessageSize;

in src/net.h:None in 6fef53a4d1 outdated

 199 | @@ -199,7 +200,9 @@ class CNodeStats
 200 |      bool fInbound;
 201 |      int nStartingHeight;
 202 |      uint64_t nSendBytes;
 203 | +    mapCmdSize_t mapSendBytesPerCmd;

laanwj commented at 9:12 AM on December 4, 2015:

Nit: don't use _t for the type name.

I've learned recently (think I heard it from @gmaxwell) that this is reserved by the C standard for system types
We don't use this convention for any of our own types

What about just CommandSizeMap?

jonasschnelli commented at 9:32 AM on December 4, 2015: contributor

@laanwj: I like your map.find approach. Implemented (squash-me commit) and renamed POSIX reserved *_t type.

in src/rpcnet.cpp:None in ff1865280d outdated

 179 | +        }
 180 | +        obj.push_back(Pair("bytessent_per_cmd", sendPerCmd));
 181 | +
 182 | +        UniValue recvPerCmd(UniValue::VOBJ);
 183 | +        BOOST_FOREACH( const mapCmdSize::value_type &i, stats.mapRecvBytesPerCmd) {
 184 | +            recvPerCmd.push_back(Pair(i.first, i.second));

laanwj commented at 9:37 AM on December 4, 2015:

If we want we could hide the entries with i.second==0 here.

jonasschnelli commented at 9:48 AM on December 4, 2015:

I also though about that, but I think the null entries are better instead of hiding. It result in more controllable parsing.

laanwj commented at 10:12 AM on December 4, 2015:

Why would this result in more controllable parsing? The zeros don't mean anything. The only reason those entries are there in the first place is our 'ignore unknown command' implementation detail.

laanwj commented at 10:13 AM on December 4, 2015:

Otherwise, to be consistent, if you really want an overview of all possible messages, we want zero entries for mapSendBytesPerCmd too (this will require an array of all messages we can potentially send).

jonasschnelli commented at 10:14 AM on December 4, 2015:

I though if someone writes a statistics fronted that uses the RPC as data-source it would complicate things (a little bit) because you don't have a full list of available commands at the beginning. But no strong opinion. I think the drawback right now is a relatively big response.

laanwj commented at 10:19 AM on December 4, 2015:

OK i agree. If you want to know eg. the set of commands that is not considered *other*. OK I don't care deeply about this, fine to leave it as-is, but I expect more people to comment on this. Empty rows just look unnecessary, and it's repeated for every peer.

laanwj commented at 9:38 AM on December 4, 2015: member

Minimally-tested ACK, I like this functionality a lot

laanwj commented at 9:39 AM on December 4, 2015: member

Speaking of which, why is verack accounted for 0 bytes? I guess we don't include the message header in the size? I think it should.

    "bytessent_per_cmd": {
      "addr": 31,
      "getheaders": 997,
      "inv": 9043,
      "ping": 16,
      "verack": 0,
      "version": 115
    },

jonasschnelli commented at 9:41 AM on December 4, 2015: contributor

Correct. Right now only the message size counts... so your right. This needs to be fixed, otherwise we are not really counting net bytes. Working on it.

laanwj commented at 9:41 AM on December 4, 2015: member

It's a fixed number per packet, so should be straightforward enough :)

jonasschnelli force-pushed on Dec 4, 2015

jonasschnelli commented at 9:58 AM on December 4, 2015: contributor

Added the header size to the bytes addition. Squashed to one commit.

jonasschnelli commented at 10:12 AM on December 4, 2015: contributor

Implemented @laanwj idea. Added a category "*unknown*" to aggregate bytes of received command that are not known. This could help identifying misbehaving nodes.

in src/net.cpp:None in ec623914da outdated

 683 | @@ -682,6 +684,15 @@ bool CNode::ReceiveMsgBytes(const char *pch, unsigned int nBytes)
 684 |          nBytes -= handled;
 685 |  
 686 |          if (msg.complete()) {
 687 | +
 688 | +            //store received bytes per command
 689 | +            //to prevent a memory DOS, only allow valid commands
 690 | +            mapCmdSize::iterator i = mapRecvBytesPerCmd.find(msg.hdr.pchCommand);
 691 | +            if (i != mapRecvBytesPerCmd.end())

laanwj commented at 10:16 AM on December 4, 2015:

or

mapCmdSize::iterator i = mapRecvBytesPerCmd.find(msg.hdr.pchCommand);
if (i == mapRecvBytesPerCmd.end())
    i = mapRecvBytesPerCmd.find("*other*");
i->second += msg.hdr.nMessageSize + CMessageHeader::HEADER_SIZE;

:-) (make sure *other* is prepopulated as 0)

jonasschnelli force-pushed on Dec 4, 2015

jonasschnelli commented at 10:40 AM on December 4, 2015: contributor

Added a commit that hides 0 entries in getpeerinfo.

laanwj commented at 11:51 AM on December 4, 2015: member

@jonasschnelli This currently runs into an assert, as mapRecvBytesPerCmd[NET_COMMAND_OTHER] doesn't exist

jonasschnelli force-pushed on Dec 4, 2015

jonasschnelli commented at 12:20 PM on December 4, 2015: contributor

@jonasschnelli This currently runs into an assert, as mapRecvBytesPerCmd[NET_COMMAND_OTHER] doesn't exist

Just fixed this over a force push. I forgot to initialize the map entry.

in src/net.cpp:None in 9f523a67f1 outdated

  66 | @@ -67,6 +67,15 @@ namespace {
  67 |      };
  68 |  }
  69 |  
  70 | +//immutable thread safe array of allowed commands for logging inbound traffic
  71 | +const static std::string logAllowIncomingCmds[] = {
  72 | +    "version", "verack", "addr", "inv", "getdata",
  73 | +    "getblocks", "getheaders", "tx", "headers", "block",
  74 | +    "getaddr", "mempool", "ping", "pong", "alert",
  75 | +    "filterload", "filteradd", "filterclear", "reject"};

laanwj commented at 8:03 AM on December 5, 2015:

I noticed some *other* in the stats from normal Bitcoin Core client, so I checked all uses of PushMessage: These need to be added: , "merkleblock", "notfound"

laanwj commented at 8:17 AM on December 5, 2015: member

Small conceptual nit: In contrast to client-server protocols in a P2P protocol there are no 'commands', just 'messages' (there is no hierarchy and both sides use the same language). The distinction seems only a technicality, but some confusion stems from this - for example when people propose new add messages which have a mandatory response, thinking of it as a command/response protocol. I know we get this naming wrong in some places in the source code too so it's no big deal there... but e.g. in the UI we may want to get this right :-)

laanwj commented at 8:21 AM on December 5, 2015: member

This works great though. ACK after adding the two missing message types.

jonasschnelli commented at 12:32 PM on December 5, 2015: contributor

Pushed two commits: -> Add "merkleblock" and "notfound" to the list of accepted commands for logging. -> Reword the variables, comments and help-text to reflect "message command"'s instead of just just "command".

paveljanik commented at 12:46 PM on December 5, 2015: contributor

@jonasschnelli To be consistent, please also change recvPerCmd.

jonasschnelli force-pushed on Dec 5, 2015

jonasschnelli commented at 12:48 PM on December 5, 2015: contributor

@paveljanik: Thanks of the review! Change and force pushed the last commit.

paveljanik commented at 12:52 PM on December 5, 2015: contributor

ACK This is very useful, thanks for it!

in src/rpcnet.cpp:None in b86e8c390b outdated

 110 | @@ -111,6 +111,14 @@ UniValue getpeerinfo(const UniValue& params, bool fHelp)
 111 |              "       n,                        (numeric) The heights of blocks we're currently asking from this peer\n"
 112 |              "       ...\n"
 113 |              "    ]\n"
 114 | +            "    \"bytessent_per_msg\": {\n"
 115 | +            "       \"addr\": n,             (numeric) The total bytes sent aggregated by message command\n"
 116 | +            "       ...\n"
 117 | +            "    }\n"
 118 | +            "    \"bytesrecv_per_msg\": {\n"
 119 | +            "       \"addr\": n,             (numeric) The total bytes received aggregated by message command\n"

MarcoFalke commented at 2:26 PM on December 5, 2015:

Nit: Not sure if "message command" is a proper word? What about "message type" or even just "message"?

laanwj commented at 12:08 PM on December 7, 2015:

My vote goes for "Message type" too

jonasschnelli commented at 12:26 PM on December 7, 2015:

Agreed. Changed to "message type" (amend force push last commit).

GIJensen commented at 6:35 PM on December 5, 2015: none

ACK

in src/rpcnet.cpp:None in b86e8c390b outdated

 179 | +                sendPerMsgCmd.push_back(Pair(i.first, i.second));
 180 | +        }
 181 | +        obj.push_back(Pair("bytessent_per_msg", sendPerMsgCmd));
 182 | +
 183 | +        UniValue recvPerCmd(UniValue::VOBJ);
 184 | +        BOOST_FOREACH( const mapMsgCmdSize::value_type &i, stats.mapRecvBytesPerMsgCmd) {

GIJensen commented at 9:40 PM on December 5, 2015:

nit: I believe these should read "BOOST_FOREACH(const mapMsgSize..." (No space between "(" and "const")

in src/net.h:None in b86e8c390b outdated

 181 | @@ -182,6 +182,7 @@ struct LocalServiceInfo {
 182 |  
 183 |  extern CCriticalSection cs_mapLocalHost;
 184 |  extern std::map<CNetAddr, LocalServiceInfo> mapLocalHost;
 185 | +typedef std::map<std::string, uint64_t > mapMsgCmdSize; //command, total bytes

paveljanik commented at 9:43 PM on December 5, 2015:

Space after uint64_t

jonasschnelli commented at 8:07 AM on December 7, 2015: contributor

Fixed minor code style issues (three unnecessary spaces).

jonasschnelli force-pushed on Dec 7, 2015

laanwj commented at 12:29 PM on December 7, 2015: member

Will merge after squash and travis OK

log bytes recv/sent per command ca188c629e

jonasschnelli force-pushed on Dec 7, 2015

jonasschnelli commented at 12:33 PM on December 7, 2015: contributor

Squashed.

laanwj merged this on Dec 7, 2015

laanwj closed this on Dec 7, 2015

laanwj referenced this in commit dc0305d15a on Dec 7, 2015

laanwj referenced this in commit 2e0c022542 on Dec 7, 2015

laanwj referenced this in commit 465511fc5f on Dec 7, 2015

laanwj referenced this in commit e3bc5e0e92 on Dec 7, 2015

GIJensen referenced this in commit d61826a11e on Dec 23, 2015

in src/net.cpp:None in ca188c629e

2502 | @@ -2480,6 +2503,9 @@ void CNode::EndMessage() UNLOCK_FUNCTION(cs_vSend)
2503 |      unsigned int nSize = ssSend.size() - CMessageHeader::HEADER_SIZE;
2504 |      WriteLE32((uint8_t*)&ssSend[CMessageHeader::MESSAGE_SIZE_OFFSET], nSize);
2505 |  
2506 | +    //log total amount of bytes per command
2507 | +    mapSendBytesPerMsgCmd[std::string(pszCommand)] += nSize + CMessageHeader::HEADER_SIZE;

rebroad commented at 6:33 AM on October 16, 2016:

why not put ssSend.size() into a variable and use that?

rebroad commented at 6:38 AM on October 16, 2016: contributor

Is anyone using this functionality? If so, can uses be documented somewhere?

MarcoFalke commented at 9:19 AM on October 16, 2016: member

@rebroad I think the goal was to find out what msg consumes the most bytes.

OlegGirko referenced this in commit 14c4e9aae6 on Jun 26, 2017

UdjinM6 referenced this in commit a443d4e2d0 on Jun 29, 2017

lateminer referenced this in commit 0b00741a03 on Oct 18, 2018

random-zebra referenced this in commit cbd9271afb on Sep 7, 2020

DrahtBot locked this on Sep 8, 2021