Add support for bottleneck stats

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, true);
-               &start : NULL, 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;
 

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;
 

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.
 

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();

common/rfb/SMsgReader.h

@@ -55,6 +55,7 @@ namespace rfb {
     void readKeyEvent();
     void readPointerEvent();
     void readClientCutText();
+    void readRequestStats();
 
     void readQEMUMessage();
     void readQEMUKeyEvent();

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)

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[]);

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<struct timeval> &list, const struct timeval &now) {
+  std::list<struct timeval>::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

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<rdr::U32, rdr::U32> pressedKeys;
 
+    enum {
+        BS_CPU_CLOSE,
+        BS_CPU_SLOW,
+        BS_NET_SLOW,
+        BS_FRAME,
+
+        BS_NUM
+    };
+    std::list<struct timeval> bstats[BS_NUM]; // Bottleneck stats
+    rdr::U64 bstats_total[BS_NUM];
+    struct timeval connStart;
+
     time_t lastEventTime;
     time_t pointerEventTime;
     Point pointerEventPos;

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;

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;