From: Thomas Markwalder Date: Fri, 17 Sep 2021 17:47:13 +0000 (-0400) Subject: [#2085] Emit a warning when HTTP queue grows X-Git-Tag: Kea-2.0.0~69 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=a538631f7371f1bac5f225e980127fb301175c2b;p=thirdparty%2Fkea.git [#2085] Emit a warning when HTTP queue grows src/lib/http/client.cc ConnectionPool::Destination::pushRequest() - emits a warning if the queue size has exceeded its threshold src/lib/http/http_messages.mes HTTP_CLIENT_QUEUE_SIZE_GROWING - new log message --- diff --git a/ChangeLog b/ChangeLog index 4a543ea43b..6de3a1de42 100644 --- a/ChangeLog +++ b/ChangeLog @@ -1,3 +1,8 @@ +1948. [func] tmark + HTTP library will now emit a warning log when the queue of + pending client requests for a given URL exceeds a threshold. + (Gitlab #2085) + 1947. [bug] marcin Corrected a bug in the High Availablity hooks library that could cause a standby server not to synchronize its lease database diff --git a/src/lib/http/client.cc b/src/lib/http/client.cc index cfbf663096..e844c58d21 100644 --- a/src/lib/http/client.cc +++ b/src/lib/http/client.cc @@ -14,6 +14,7 @@ #include #include #include +#include #include #include @@ -34,6 +35,8 @@ using namespace isc; using namespace isc::asiolink; using namespace isc::http; using namespace isc::util; +using namespace boost::posix_time; + namespace ph = std::placeholders; namespace { @@ -805,6 +808,11 @@ private: /// @brief Encapsulates connections and requests for a given URL class Destination { public: + /// @brief Number of queued requests allowed without warnings being emitted. + const size_t QUEUE_SIZE_THRESHOLD = 2048; + /// @brief Interval between queue size warnings. + const int QUEUE_WARN_SECS = 5; + /// @brief Constructor /// /// @param url server URL of this destination @@ -813,7 +821,8 @@ private: /// allowed for in the list URL Destination(Url url, TlsContextPtr tls_context, size_t max_connections) : url_(url), tls_context_(tls_context), - max_connections_(max_connections), connections_(), queue_() { + max_connections_(max_connections), connections_(), queue_(), + last_queue_warn_time_(min_date_time), last_queue_size_(0) { } /// @brief Destructor @@ -976,9 +985,28 @@ private: /// @brief Adds a request to the end of the request queue. /// + /// If the size of the queue exceeds a threhsold and appears + /// to be growing it will emit a warning log. + /// /// @param desc RequestDescriptor to queue. void pushRequest(RequestDescriptor desc) { queue_.push(desc); + size_t size = queue_.size(); + // If the queue size is larger than the threshold and growing, issue a + // periodic warning. + if ((size > QUEUE_SIZE_THRESHOLD) && (size > last_queue_size_)) { + ptime now = microsec_clock::universal_time(); + if ((now - last_queue_warn_time_) > seconds(QUEUE_WARN_SECS)) { + LOG_WARN(http_logger, HTTP_CLIENT_QUEUE_SIZE_GROWING) + .arg(url_.toText()) + .arg(size); + // Remember the last time we warned. + last_queue_warn_time_ = now; + } + } + + // Remember the previous size. + last_queue_size_ = size; } /// @brief Removes a request from the front of the request queue. @@ -1009,6 +1037,12 @@ private: /// @brief Holds the queue of request for this destination. std::queue queue_; + + /// @brief Time the last queue size warning was issued. + ptime last_queue_warn_time_; + + /// @brief Size of the queue after last push. + size_t last_queue_size_; }; /// @brief Pointer to a Destination. diff --git a/src/lib/http/http_messages.cc b/src/lib/http/http_messages.cc index dc24176ead..292d2d85d9 100644 --- a/src/lib/http/http_messages.cc +++ b/src/lib/http/http_messages.cc @@ -13,6 +13,7 @@ extern const isc::log::MessageID HTTP_BAD_CLIENT_REQUEST_RECEIVED_DETAILS = "HTT extern const isc::log::MessageID HTTP_BAD_SERVER_RESPONSE_RECEIVED = "HTTP_BAD_SERVER_RESPONSE_RECEIVED"; extern const isc::log::MessageID HTTP_BAD_SERVER_RESPONSE_RECEIVED_DETAILS = "HTTP_BAD_SERVER_RESPONSE_RECEIVED_DETAILS"; extern const isc::log::MessageID HTTP_CLIENT_MT_STARTED = "HTTP_CLIENT_MT_STARTED"; +extern const isc::log::MessageID HTTP_CLIENT_QUEUE_SIZE_GROWING = "HTTP_CLIENT_QUEUE_SIZE_GROWING"; extern const isc::log::MessageID HTTP_CLIENT_REQUEST_RECEIVED = "HTTP_CLIENT_REQUEST_RECEIVED"; extern const isc::log::MessageID HTTP_CLIENT_REQUEST_RECEIVED_DETAILS = "HTTP_CLIENT_REQUEST_RECEIVED_DETAILS"; extern const isc::log::MessageID HTTP_CLIENT_REQUEST_SEND = "HTTP_CLIENT_REQUEST_SEND"; @@ -46,6 +47,7 @@ const char* values[] = { "HTTP_BAD_SERVER_RESPONSE_RECEIVED", "bad response received when communicating with %1: %2", "HTTP_BAD_SERVER_RESPONSE_RECEIVED_DETAILS", "detailed information about bad response received from %1:\n%2", "HTTP_CLIENT_MT_STARTED", "HttpClient has been started in multi-threaded mode running %1 threads", + "HTTP_CLIENT_QUEUE_SIZE_GROWING", "queue for URL: %1, now has %2 entries and may be growing too quickly", "HTTP_CLIENT_REQUEST_RECEIVED", "received HTTP request from %1", "HTTP_CLIENT_REQUEST_RECEIVED_DETAILS", "detailed information about well-formed request received from %1:\n%2", "HTTP_CLIENT_REQUEST_SEND", "sending HTTP request %1 to %2", diff --git a/src/lib/http/http_messages.h b/src/lib/http/http_messages.h index d24a6ce4fd..4ac303081b 100644 --- a/src/lib/http/http_messages.h +++ b/src/lib/http/http_messages.h @@ -14,6 +14,7 @@ extern const isc::log::MessageID HTTP_BAD_CLIENT_REQUEST_RECEIVED_DETAILS; extern const isc::log::MessageID HTTP_BAD_SERVER_RESPONSE_RECEIVED; extern const isc::log::MessageID HTTP_BAD_SERVER_RESPONSE_RECEIVED_DETAILS; extern const isc::log::MessageID HTTP_CLIENT_MT_STARTED; +extern const isc::log::MessageID HTTP_CLIENT_QUEUE_SIZE_GROWING; extern const isc::log::MessageID HTTP_CLIENT_REQUEST_RECEIVED; extern const isc::log::MessageID HTTP_CLIENT_REQUEST_RECEIVED_DETAILS; extern const isc::log::MessageID HTTP_CLIENT_REQUEST_SEND; diff --git a/src/lib/http/http_messages.mes b/src/lib/http/http_messages.mes index 7683162ab3..5d2b50771f 100644 --- a/src/lib/http/http_messages.mes +++ b/src/lib/http/http_messages.mes @@ -38,6 +38,15 @@ from the server. The first argument specifies an URL of the server. The second argument provides a response in the textual format. The request is truncated by the logger if it is too large to be printed. +% HTTP_CLIENT_QUEUE_SIZE_GROWING queue for URL: %1, now has %2 entries and may be growing too quickly +This warning message is issued when the queue of pending requests for the +given URL appears to be growing more quickly than the requests can be handled. +It will be emitted periodically as long as the queue size continues to grow. +This may occur with a surge of client traffic creating a momemntary backlog +which then subsides as the surge subsides. If it happens continually then +it most likely indicates a deployment configuration that cannot sustain the +client load. + % HTTP_CLIENT_MT_STARTED HttpClient has been started in multi-threaded mode running %1 threads This debug message is issued when a multi-threaded HTTP client instance has been created. The argument specifies the maximum number of threads.