From d5bdef121aacf37a1fc0ecf957bd92c503cbadf4 Mon Sep 17 00:00:00 2001 From: Lauri Kasanen Date: Mon, 21 Sep 2020 15:51:56 +0300 Subject: [PATCH] Add support for bottleneck stats --- common/rfb/EncodeManager.cxx | 9 ++-- common/rfb/EncodeManager.h | 5 ++ common/rfb/SMsgHandler.h | 2 + common/rfb/SMsgReader.cxx | 9 ++++ common/rfb/SMsgReader.h | 1 + common/rfb/SMsgWriter.cxx | 9 ++++ common/rfb/SMsgWriter.h | 1 + common/rfb/VNCSConnectionST.cxx | 82 ++++++++++++++++++++++++++++++++- common/rfb/VNCSConnectionST.h | 14 ++++++ common/rfb/msgTypes.h | 6 +++ kasmweb/core/rfb.js | 30 ++++++++++++ 11 files changed, 164 insertions(+), 4 deletions(-) diff --git a/common/rfb/EncodeManager.cxx b/common/rfb/EncodeManager.cxx index 983be73..99c871f 100644 --- a/common/rfb/EncodeManager.cxx +++ b/common/rfb/EncodeManager.cxx @@ -356,9 +356,10 @@ void EncodeManager::doUpdate(bool allowLossy, const Region& changed_, changed = changed_; + gettimeofday(&start, NULL); + if (allowLossy && activeEncoders[encoderFullColour] == encoderTightWEBP) { const unsigned rate = 1024 * 1000 / rfb::Server::frameRate; - gettimeofday(&start, NULL); screenArea = pb->getRect().width() * pb->getRect().height(); screenArea *= 1024; @@ -401,8 +402,7 @@ void EncodeManager::doUpdate(bool allowLossy, const Region& changed_, writeSolidRects(&changed, pb); writeRects(changed, pb, - allowLossy && activeEncoders[encoderFullColour] == encoderTightWEBP ? - &start : NULL, true); + &start, true); if (!videoDetected) // In case detection happened between the calls writeRects(cursorRegion, renderedCursor); @@ -1136,6 +1136,9 @@ void EncodeManager::writeRects(const Region& changed, const PixelBuffer* pb, checkWebpFallback(start); } + if (start) + encodingTime = msSince(start); + if (webpTookTooLong) activeEncoders[encoderFullColour] = encoderTightJPEG; diff --git a/common/rfb/EncodeManager.h b/common/rfb/EncodeManager.h index 8f86292..5453bc8 100644 --- a/common/rfb/EncodeManager.h +++ b/common/rfb/EncodeManager.h @@ -68,6 +68,10 @@ namespace rfb { const RenderedCursor* renderedCursor, size_t maxUpdateSize); + unsigned getEncodingTime() const { + return encodingTime; + }; + protected: void doUpdate(bool allowLossy, const Region& changed, const Region& copied, const Point& copy_delta, @@ -177,6 +181,7 @@ namespace rfb { unsigned webpFallbackUs; unsigned webpBenchResult; bool webpTookTooLong; + unsigned encodingTime; EncCache *encCache; diff --git a/common/rfb/SMsgHandler.h b/common/rfb/SMsgHandler.h index 749f056..6d5f5a1 100644 --- a/common/rfb/SMsgHandler.h +++ b/common/rfb/SMsgHandler.h @@ -54,6 +54,8 @@ namespace rfb { virtual void enableContinuousUpdates(bool enable, int x, int y, int w, int h) = 0; + virtual void sendStats() = 0; + // InputHandler interface // The InputHandler methods will be called for the corresponding messages. diff --git a/common/rfb/SMsgReader.cxx b/common/rfb/SMsgReader.cxx index fab28c5..7550331 100644 --- a/common/rfb/SMsgReader.cxx +++ b/common/rfb/SMsgReader.cxx @@ -74,6 +74,9 @@ void SMsgReader::readMsg() case msgTypeClientFence: readFence(); break; + case msgTypeRequestStats: + readRequestStats(); + break; case msgTypeKeyEvent: readKeyEvent(); break; @@ -236,6 +239,12 @@ void SMsgReader::readClientCutText() handler->clientCutText(ca.buf, len); } +void SMsgReader::readRequestStats() +{ + is->skip(3); + handler->sendStats(); +} + void SMsgReader::readQEMUMessage() { int subType = is->readU8(); diff --git a/common/rfb/SMsgReader.h b/common/rfb/SMsgReader.h index b7acf79..ebeee84 100644 --- a/common/rfb/SMsgReader.h +++ b/common/rfb/SMsgReader.h @@ -55,6 +55,7 @@ namespace rfb { void readKeyEvent(); void readPointerEvent(); void readClientCutText(); + void readRequestStats(); void readQEMUMessage(); void readQEMUKeyEvent(); diff --git a/common/rfb/SMsgWriter.cxx b/common/rfb/SMsgWriter.cxx index 3da9413..07622fd 100644 --- a/common/rfb/SMsgWriter.cxx +++ b/common/rfb/SMsgWriter.cxx @@ -88,6 +88,15 @@ void SMsgWriter::writeServerCutText(const char* str, int len) endMsg(); } +void SMsgWriter::writeStats(const char* str, int len) +{ + startMsg(msgTypeStats); + os->pad(3); + os->writeU32(len); + os->writeBytes(str, len); + endMsg(); +} + void SMsgWriter::writeFence(rdr::U32 flags, unsigned len, const char data[]) { if (!cp->supportsFence) diff --git a/common/rfb/SMsgWriter.h b/common/rfb/SMsgWriter.h index e985941..6945ba4 100644 --- a/common/rfb/SMsgWriter.h +++ b/common/rfb/SMsgWriter.h @@ -55,6 +55,7 @@ namespace rfb { // writeBell() and writeServerCutText() do the obvious thing. void writeBell(); void writeServerCutText(const char* str, int len); + void writeStats(const char* str, int len); // writeFence() sends a new fence request or response to the client. void writeFence(rdr::U32 flags, unsigned len, const char data[]); diff --git a/common/rfb/VNCSConnectionST.cxx b/common/rfb/VNCSConnectionST.cxx index f0e5b21..61b72d7 100644 --- a/common/rfb/VNCSConnectionST.cxx +++ b/common/rfb/VNCSConnectionST.cxx @@ -53,7 +53,8 @@ VNCSConnectionST::VNCSConnectionST(VNCServerST* server_, network::Socket *s, fenceDataLen(0), fenceData(NULL), congestionTimer(this), losslessTimer(this), kbdLogTimer(this), server(server_), updates(false), updateRenderedCursor(false), removeRenderedCursor(false), - continuousUpdates(false), encodeManager(this, &server_->encCache), pointerEventTime(0), + continuousUpdates(false), encodeManager(this, &server_->encCache), + pointerEventTime(0), clientHasCursor(false), accessRights(AccessDefault), startTime(time(0)) { @@ -61,6 +62,9 @@ VNCSConnectionST::VNCSConnectionST(VNCServerST* server_, network::Socket *s, peerEndpoint.buf = sock->getPeerEndpoint(); VNCServerST::connectionsLog.write(1,"accepted: %s", peerEndpoint.buf); + memset(bstats_total, 0, sizeof(bstats_total)); + gettimeofday(&connStart, NULL); + // Configure the socket setSocketTimeouts(); lastEventTime = time(0); @@ -1037,6 +1041,14 @@ bool VNCSConnectionST::isCongested() if (eta >= 0) congestionTimer.start(eta); + if (eta > 1000 / rfb::Server::frameRate) { + struct timeval now; + gettimeofday(&now, NULL); + + bstats[BS_NET_SLOW].push_back(now); + bstats_total[BS_NET_SLOW]++; + } + return true; } @@ -1083,6 +1095,11 @@ void VNCSConnectionST::writeFramebufferUpdate() sock->cork(false); congestion.updatePosition(sock->outStream().length()); + + struct timeval now; + gettimeofday(&now, NULL); + bstats[BS_FRAME].push_back(now); + bstats_total[BS_FRAME]++; } void VNCSConnectionST::writeNoDataUpdate() @@ -1236,6 +1253,16 @@ void VNCSConnectionST::writeDataUpdate() copypassed.clear(); gettimeofday(&lastRealUpdate, NULL); losslessTimer.start(losslessThreshold); + + const unsigned ms = encodeManager.getEncodingTime(); + const unsigned limit = 1000 / rfb::Server::frameRate; + if (ms >= limit) { + bstats[BS_CPU_SLOW].push_back(lastRealUpdate); + bstats_total[BS_CPU_SLOW]++; + } else if (ms >= limit * 0.8f) { + bstats[BS_CPU_CLOSE].push_back(lastRealUpdate); + bstats_total[BS_CPU_CLOSE]++; + } } else { encodeManager.writeLosslessRefresh(req, server->getPixelBuffer(), cursor, maxUpdateSize); @@ -1265,6 +1292,59 @@ void VNCSConnectionST::screenLayoutChange(rdr::U16 reason) cp.screenLayout); } +static void pruneStatList(std::list &list, const struct timeval &now) { + std::list::iterator it; + for (it = list.begin(); it != list.end(); ) { + if ((*it).tv_sec + 60 < now.tv_sec) + it = list.erase(it); + else + it++; + } +} + +void VNCSConnectionST::sendStats() { + char buf[1024]; + struct timeval now; + + // Prune too old stats from the recent lists + gettimeofday(&now, NULL); + + pruneStatList(bstats[BS_CPU_CLOSE], now); + pruneStatList(bstats[BS_CPU_SLOW], now); + pruneStatList(bstats[BS_NET_SLOW], now); + pruneStatList(bstats[BS_FRAME], now); + + const unsigned minuteframes = bstats[BS_FRAME].size(); + + // Calculate stats + float cpu_recent = bstats[BS_CPU_SLOW].size() + bstats[BS_CPU_CLOSE].size() * 0.2f; + cpu_recent /= minuteframes; + + float cpu_total = bstats_total[BS_CPU_SLOW] + bstats_total[BS_CPU_CLOSE] * 0.2f; + cpu_total /= bstats_total[BS_FRAME]; + + float net_recent = bstats[BS_NET_SLOW].size(); + net_recent /= minuteframes; + if (net_recent > 1) + net_recent = 1; + + float net_total = bstats_total[BS_NET_SLOW]; + net_total /= bstats_total[BS_FRAME]; + if (net_total > 1) + net_total = 1; + + #define ten(x) (10 - x * 10.0f) + + sprintf(buf, "CPU: %.1f/10 recent, %.1f/10 total\n" + "Net: %.1f/10 recent, %.1f/10 total", + ten(cpu_recent), ten(cpu_total), + ten(net_recent), ten(net_total)); + + #undef ten + + vlog.info("Sending client stats:\n%s\n", buf); + writer()->writeStats(buf, strlen(buf)); +} // setCursor() is called whenever the cursor has changed shape or pixel format. // If the client supports local cursor then it will arrange for the cursor to diff --git a/common/rfb/VNCSConnectionST.h b/common/rfb/VNCSConnectionST.h index 76e00bb..76350ef 100644 --- a/common/rfb/VNCSConnectionST.h +++ b/common/rfb/VNCSConnectionST.h @@ -178,6 +178,8 @@ namespace rfb { virtual void supportsContinuousUpdates(); virtual void supportsLEDState(); + virtual void sendStats(); + // setAccessRights() allows a security package to limit the access rights // of a VNCSConnectioST to the server. These access rights are applied // such that the actual rights granted are the minimum of the server's @@ -235,6 +237,18 @@ namespace rfb { std::map pressedKeys; + enum { + BS_CPU_CLOSE, + BS_CPU_SLOW, + BS_NET_SLOW, + BS_FRAME, + + BS_NUM + }; + std::list bstats[BS_NUM]; // Bottleneck stats + rdr::U64 bstats_total[BS_NUM]; + struct timeval connStart; + time_t lastEventTime; time_t pointerEventTime; Point pointerEventPos; diff --git a/common/rfb/msgTypes.h b/common/rfb/msgTypes.h index 2240ce0..4bb4ddf 100644 --- a/common/rfb/msgTypes.h +++ b/common/rfb/msgTypes.h @@ -28,6 +28,9 @@ namespace rfb { const int msgTypeEndOfContinuousUpdates = 150; + // kasm + const int msgTypeStats = 178; + const int msgTypeServerFence = 248; // client to server @@ -42,6 +45,9 @@ namespace rfb { const int msgTypeEnableContinuousUpdates = 150; + // kasm + const int msgTypeRequestStats = 178; + const int msgTypeClientFence = 248; const int msgTypeSetDesktopSize = 251; diff --git a/kasmweb/core/rfb.js b/kasmweb/core/rfb.js index 48764c3..d625857 100644 --- a/kasmweb/core/rfb.js +++ b/kasmweb/core/rfb.js @@ -1495,6 +1495,19 @@ export default class RFB extends EventTargetMixin { return true; } + _handle_server_stats_msg() { + this._sock.rQskipBytes(3); // Padding + const length = this._sock.rQshift32(); + if (this._sock.rQwait("KASM bottleneck stats", length, 8)) { return false; } + + const text = this._sock.rQshiftStr(length); + + console.log("Received KASM bottleneck stats:"); + console.log(text); + + return true; + } + _handle_server_fence_msg() { if (this._sock.rQwait("ServerFence header", 8, 1)) { return false; } this._sock.rQskipBytes(3); // Padding @@ -1605,6 +1618,9 @@ export default class RFB extends EventTargetMixin { } return true; + case 178: // KASM bottleneck stats + return this._handle_server_stats_msg(); + case 248: // ServerFence return this._handle_server_fence_msg(); @@ -2108,6 +2124,20 @@ RFB.messages = { sock.flush(); }, + requestStats(sock) { + const buff = sock._sQ; + const offset = sock._sQlen; + + buff[offset] = 178; // msg-type + + buff[offset + 1] = 0; // padding + buff[offset + 2] = 0; // padding + buff[offset + 3] = 0; // padding + + sock._sQlen += 4; + sock.flush(); + }, + enableContinuousUpdates(sock, enable, x, y, width, height) { const buff = sock._sQ; const offset = sock._sQlen;