Log long-running and long-waiting CpuBoundWork tasks

lib/base/io-engine.cpp

@@ -21,6 +21,8 @@ CpuBoundWork::CpuBoundWork(boost::asio::yield_context yc)
 {
 	auto& ioEngine (IoEngine::Get());
 
+	TimeoutLog logIfSlow (LogWarning, "IoEngine", "Waited long for CPU-bound work slot");
+
 	for (;;) {
 		auto availableSlots (ioEngine.m_CpuBoundSemaphore.fetch_sub(1));
 

lib/base/logger.hpp

@@ -106,6 +106,8 @@ class Logger : public ObjectImpl<Logger>
 	static Atomic<LogSeverity> m_MinLogSeverity;
 };
 
+class TimeoutLog;
+
 class Log
 {
 public:
@@ -132,6 +134,8 @@ class Log
 	String m_Facility;
 	std::ostringstream m_Buffer;
 	bool m_IsNoOp;
+
+	friend class TimeoutLog;
 };
 
 extern template Log& Log::operator<<(const Value&);
@@ -144,6 +148,34 @@ extern template Log& Log::operator<<(const unsigned long&);
 extern template Log& Log::operator<<(const long&);
 extern template Log& Log::operator<<(const double&);
 
+// Logs a message only if a timeout has passed. Useful for logging warnings only if operations take unexpectedly long.
+class TimeoutLog : public Log
+{
+public:
+	TimeoutLog(LogSeverity severity, String facility, const String& message)
+	: Log(severity, facility, message),
+	  m_Start(std::chrono::steady_clock::now())
+	{}
+
+	TimeoutLog(LogSeverity severity, String facility)
+	: Log(severity, facility),
+	  m_Start(std::chrono::steady_clock::now())
+	{}
+
+	~TimeoutLog()
+	{
+		auto duration = std::chrono::steady_clock::now() - m_Start;
+		if (duration >= std::chrono::seconds(5)) {
+			*this << " (" << std::chrono::duration_cast<std::chrono::milliseconds>(duration).count() << "ms)";
+		} else {
+			m_IsNoOp = true;
+		}
+	}
+
+private:
+	std::chrono::steady_clock::time_point m_Start;
+};
+
 }
 
 #endif /* LOGGER_H */

lib/remote/httpserverconnection.cpp

@@ -337,6 +337,7 @@ bool EnsureValidBody(
 	boost::beast::http::parser<true, boost::beast::http::string_body>& parser,
 	ApiUser::Ptr& authenticatedUser,
 	boost::beast::http::response<boost::beast::http::string_body>& response,
+	HttpServerConnection& server,
 	bool& shuttingDown,
 	boost::asio::yield_context& yc
 )
@@ -349,6 +350,8 @@ bool EnsureValidBody(
 
 		if (permissions) {
 			CpuBoundWork evalPermissions (yc);
+			TimeoutLog logIfSlow (LogWarning, "HttpServerConnection");
+			logIfSlow << "Evaluating permissions for " << server.m_PeerAddress << " took long";
 
 			ObjectLock olock(permissions);
 
@@ -437,6 +440,8 @@ bool ProcessRequest(
 
 	try {
 		CpuBoundWork handlingRequest (yc);
+		TimeoutLog logIfSlow (LogWarning, "HttpServerConnection");
+		logIfSlow << "Handling request from " << server.m_PeerAddress << " took long";
 
 		HttpHandler::ProcessRequest(stream, authenticatedUser, request, response, yc, server);
 	} catch (const std::exception& ex) {
@@ -544,7 +549,7 @@ void HttpServerConnection::ProcessMessages(boost::asio::yield_context yc)
 				break;
 			}
 
-			if (!EnsureValidBody(*m_Stream, buf, parser, authenticatedUser, response, m_ShuttingDown, yc)) {
+			if (!EnsureValidBody(*m_Stream, buf, parser, authenticatedUser, response, *this, m_ShuttingDown, yc)) {
 				break;
 			}
 

lib/remote/httpserverconnection.hpp

@@ -37,7 +37,9 @@ class HttpServerConnection final : public Object
 	ApiUser::Ptr m_ApiUser;
 	Shared<AsioTlsStream>::Ptr m_Stream;
 	double m_Seen;
+public:
 	String m_PeerAddress;
+private:
 	boost::asio::io_context::strand m_IoStrand;
 	bool m_ShuttingDown;
 	bool m_HasStartedStreaming;

lib/remote/jsonrpcconnection.cpp

@@ -79,6 +79,8 @@ void JsonRpcConnection::HandleIncomingMessages(boost::asio::yield_context yc)
 
 		try {
 			CpuBoundWork handleMessage (yc);
+			TimeoutLog logIfSlow (LogWarning, "JsonRpcConnection");
+			logIfSlow << "Handling message from " << m_Identity << " took long";
 
 			MessageHandler(message);