------------------------------------------------------------ revno: 13767 revision-id: squid3@treenet.co.nz-20150303144801-h3qb4zdqjgd0e0ea parent: squid3@treenet.co.nz-20150303144557-vf3fiwfwxxs77x8e fixes bug: http://bugs.squid-cache.org/show_bug.cgi?id=2907 committer: Amos Jeffries branch nick: 3.5 timestamp: Tue 2015-03-03 06:48:01 -0800 message: Bug 2907: high CPU usage on CONNECT when using delay pools When delay pools are active on a CONNECT tunnel and the pool is drained the I/O loop cycles very often transferring 1 byte until the pool is topped-up at the end of the second. Instead of looping constantly trying to read 1 byte at a time, add an asynchronous event to wait for a few I/O cycles or until more bytes can be read. To protect against infinite loops of waiting when many tunnels are competing for the pool allowance we only delay for a limited number of loops before allowing at least 1 byte through. Also, the amount of time waited is an odd fraction of 1 second so re-tries naturally spread across any given second fairly, with connections rotating closer or further from the time when pool topup happens. That behaviour still allows some variance in service times, but overall the CPU consumption and (as a result) total proxy speed appears to be much improved. NP: Initial production testing shows a 36% RPS speed increase, with a 50% reduction in total CPU usage. ------------------------------------------------------------ # Bazaar merge directive format 2 (Bazaar 0.90) # revision_id: squid3@treenet.co.nz-20150303144801-h3qb4zdqjgd0e0ea # target_branch: http://bzr.squid-cache.org/bzr/squid3/3.5 # testament_sha1: e82f1b278f999fac8bf62523620b5e05badc5688 # timestamp: 2015-03-03 14:51:08 +0000 # source_branch: http://bzr.squid-cache.org/bzr/squid3/3.5 # base_revision_id: squid3@treenet.co.nz-20150303144557-\ # vf3fiwfwxxs77x8e # # Begin patch === modified file 'src/tunnel.cc' --- src/tunnel.cc 2015-01-13 09:13:49 +0000 +++ src/tunnel.cc 2015-03-03 14:48:01 +0000 @@ -12,6 +12,7 @@ #include "acl/FilledChecklist.h" #include "base/CbcPointer.h" #include "CachePeer.h" +#include "cbdata.h" #include "client_side.h" #include "client_side_request.h" #include "comm.h" @@ -113,7 +114,8 @@ { public: - Connection() : len (0), buf ((char *)xmalloc(SQUID_TCP_SO_RCVBUF)), size_ptr(NULL) {} + Connection() : len (0), buf ((char *)xmalloc(SQUID_TCP_SO_RCVBUF)), size_ptr(NULL), delayedLoops(0), + readPending(NULL), readPendingFunc(NULL) {} ~Connection(); @@ -135,7 +137,11 @@ int64_t *size_ptr; /* pointer to size in an ConnStateData for logging */ Comm::ConnectionPointer conn; ///< The currently connected connection. + uint8_t delayedLoops; ///< how many times a read on this connection has been postponed. + // XXX: make these an AsyncCall when event API can handle them + TunnelStateData *readPending; + EVH *readPendingFunc; private: #if USE_DELAY_POOLS @@ -206,6 +212,8 @@ static CLCB tunnelClientClosed; static CTCB tunnelTimeout; static PSC tunnelPeerSelectComplete; +static EVH tunnelDelayedClientRead; +static EVH tunnelDelayedServerRead; static void tunnelConnected(const Comm::ConnectionPointer &server, void *); static void tunnelRelayConnectRequest(const Comm::ConnectionPointer &server, void *); @@ -258,6 +266,8 @@ connectReqWriting(false) { debugs(26, 3, "TunnelStateData constructed this=" << this); + client.readPendingFunc = &tunnelDelayedClientRead; + server.readPendingFunc = &tunnelDelayedServerRead; } TunnelStateData::~TunnelStateData() @@ -271,6 +281,9 @@ TunnelStateData::Connection::~Connection() { + if (readPending) + eventDelete(readPendingFunc, readPending); + safe_free(buf); } @@ -327,6 +340,7 @@ TunnelStateData::readServer(char *buf, size_t len, Comm::Flag errcode, int xerrno) { debugs(26, 3, HERE << server.conn << ", read " << len << " bytes, err=" << errcode); + server.delayedLoops=0; /* * Bail out early on Comm::ERR_CLOSING @@ -472,6 +486,7 @@ TunnelStateData::readClient(char *buf, size_t len, Comm::Flag errcode, int xerrno) { debugs(26, 3, HERE << client.conn << ", read " << len << " bytes, err=" << errcode); + client.delayedLoops=0; /* * Bail out early on Comm::ERR_CLOSING @@ -672,13 +687,51 @@ conn->close(); } +static void +tunnelDelayedClientRead(void *data) +{ + if (!data) + return; + TunnelStateData *tunnel = static_cast(data); + if (!tunnel) + return; + tunnel->client.readPending = NULL; + static uint64_t counter=0; + debugs(26, 7, "Client read(2) delayed " << ++counter << " times"); + tunnel->copyRead(tunnel->client, TunnelStateData::ReadClient); +} + +static void +tunnelDelayedServerRead(void *data) +{ + if (!data) + return; + TunnelStateData *tunnel = static_cast(data); + if (!tunnel) + return; + tunnel->server.readPending = NULL; + static uint64_t counter=0; + debugs(26, 7, "Server read(2) delayed " << ++counter << " times"); + tunnel->copyRead(tunnel->server, TunnelStateData::ReadServer); +} + void TunnelStateData::copyRead(Connection &from, IOCB *completion) { assert(from.len == 0); + // If only the minimum permitted read size is going to be attempted + // then we schedule an event to try again in a few I/O cycles. + // Allow at least 1 byte to be read every (0.3*10) seconds. + int bw = from.bytesWanted(1, SQUID_TCP_SO_RCVBUF); + if (bw == 1 && ++from.delayedLoops < 10) { + from.readPending = this; + eventAdd("tunnelDelayedServerRead", from.readPendingFunc, from.readPending, 0.3, true); + return; + } + AsyncCall::Pointer call = commCbCall(5,4, "TunnelBlindCopyReadHandler", CommIoCbPtrFun(completion, this)); - comm_read(from.conn, from.buf, from.bytesWanted(1, SQUID_TCP_SO_RCVBUF), call); + comm_read(from.conn, from.buf, bw, call); } void