- add round trip trace message from client and back to tell us where the bottleneck

might be when using multi-user whiteboard.

akka-bbb-apps/src/main/scala/org/bigbluebutton/core/apps/whiteboard/ClientToServerLatencyTracerMsgHdlr.scala

@@ -0,0 +1,26 @@
+package org.bigbluebutton.core.apps.whiteboard
+
+import org.bigbluebutton.common2.msgs._
+import org.bigbluebutton.core.running.{ MeetingActor, OutMsgRouter }
+
+trait ClientToServerLatencyTracerMsgHdlr {
+  this: MeetingActor =>
+
+  val outGW: OutMsgRouter
+
+  def handleClientToServerLatencyTracerMsg(msg: ClientToServerLatencyTracerMsg): Unit = {
+
+    def broadcastEvent(): Unit = {
+      val routing = Routing.addMsgToClientRouting(MessageTypes.DIRECT, props.meetingProp.intId, msg.header.userId)
+      val envelope = BbbCoreEnvelope(ServerToClientLatencyTracerMsg.NAME, routing)
+      val header = BbbClientMsgHeader(ServerToClientLatencyTracerMsg.NAME, props.meetingProp.intId, msg.header.userId)
+
+      val body = ServerToClientLatencyTracerMsgBody(msg.body.timestamp, msg.body.prettyTimestamp, msg.body.tzOffset, msg.body.senderId)
+      val event = ServerToClientLatencyTracerMsg(header, body)
+      val msgEvent = BbbCommonEnvCoreMsg(envelope, event)
+      outGW.send(msgEvent)
+    }
+
+    broadcastEvent()
+  }
+}

akka-bbb-apps/src/main/scala/org/bigbluebutton/core/pubsub/senders/ReceivedJsonMsgHandlerActor.scala

@@ -166,6 +166,9 @@ class ReceivedJsonMsgHandlerActor(
         routeGenericMsg[SendWhiteboardAnnotationPubMsg](envelope, jsonNode)
       case GetWhiteboardAnnotationsReqMsg.NAME =>
         routeGenericMsg[GetWhiteboardAnnotationsReqMsg](envelope, jsonNode)
+      case ClientToServerLatencyTracerMsg.NAME =>
+        log.info("-- trace --" + jsonNode.toString)
+        routeGenericMsg[ClientToServerLatencyTracerMsg](envelope, jsonNode)
 
       // Presentation
       case SetCurrentPresentationPubMsg.NAME =>

akka-bbb-apps/src/main/scala/org/bigbluebutton/core/running/MeetingActor.scala

@@ -3,6 +3,7 @@ package org.bigbluebutton.core.running
 import java.io.{ PrintWriter, StringWriter }
 
 import org.bigbluebutton.core.apps.users._
+import org.bigbluebutton.core.apps.whiteboard.ClientToServerLatencyTracerMsgHdlr
 import org.bigbluebutton.core.domain.{ MeetingExpiryTracker, MeetingInactivityTracker, MeetingState2x }
 import org.bigbluebutton.core.util.TimeUtil
 //import java.util.concurrent.TimeUnit
@@ -78,7 +79,8 @@ class MeetingActor(
     with SendTimeRemainingUpdateHdlr
     with SendBreakoutTimeRemainingMsgHdlr
     with ChangeLockSettingsInMeetingCmdMsgHdlr
-    with SyncGetMeetingInfoRespMsgHdlr {
+    with SyncGetMeetingInfoRespMsgHdlr
+    with ClientToServerLatencyTracerMsgHdlr {
 
   override val supervisorStrategy = OneForOneStrategy(maxNrOfRetries = 10, withinTimeRange = 1 minute) {
     case e: Exception => {
@@ -207,6 +209,7 @@ class MeetingActor(
       case m: GetWhiteboardAccessReqMsg      => handleGetWhiteboardAccessReqMsg(m)
       case m: SendWhiteboardAnnotationPubMsg => handleSendWhiteboardAnnotationPubMsg(m)
       case m: GetWhiteboardAnnotationsReqMsg => handleGetWhiteboardAnnotationsReqMsg(m)
+      case m: ClientToServerLatencyTracerMsg => handleClientToServerLatencyTracerMsg(m)
 
       // Poll
       case m: StartPollReqMsg                => handleStartPollReqMsg(m)

akka-bbb-apps/src/main/scala/org/bigbluebutton/core2/AnalyticsActor.scala

@@ -22,6 +22,11 @@ class AnalyticsActor extends Actor with ActorLogging {
     log.info(TAG + json)
   }
 
+  def traceMessage(msg: BbbCommonEnvCoreMsg): Unit = {
+    val json = JsonUtil.toJson(msg)
+    log.info(" -- trace -- " + json)
+  }
+
   def handleBbbCommonEnvCoreMsg(msg: BbbCommonEnvCoreMsg): Unit = {
 
     msg.core match {
@@ -76,6 +81,9 @@ class AnalyticsActor extends Actor with ActorLogging {
       case m: SetCurrentPresentationPubMsg => logMessage(msg)
       case m: SetCurrentPresentationEvtMsg => logMessage(msg)
 
+      case m: ClientToServerLatencyTracerMsg => traceMessage(msg)
+      case m: ServerToClientLatencyTracerMsg => traceMessage(msg)
+
       case _ => // ignore message
     }
   }

bbb-apps-common/src/main/scala/org/bigbluebutton/client/meeting/UserActor.scala

@@ -79,7 +79,7 @@ class UserActor(val userId: String,
 
 
   def handleMsgFromClientMsg(msg: MsgFromClientMsg):Unit = {
-    log.debug("Received MsgFromClientMsg " + msg)
+
 
     def convertToJsonNode(json: String): Option[JsonNode] = {
       JsonUtil.toJsonNode(json) match {
@@ -97,6 +97,10 @@ class UserActor(val userId: String,
         val routing = Routing.addMsgFromClientRouting(msgFromClient.header.meetingId, msgFromClient.header.userId)
         val envelope = new BbbCoreEnvelope(msgFromClient.header.name, routing)
 
+        if (msgFromClient.header.name == "ClientToServerLatencyTracerMsg") {
+          log.info("-- trace -- " + msg.json)
+        }
+
         for {
           jsonNode <- convertToJsonNode(msg.json)
         } yield {

bbb-common-message/src/main/scala/org/bigbluebutton/common2/msgs/WhiteboardMsgs.scala

@@ -3,6 +3,15 @@ package org.bigbluebutton.common2.msgs
 case class AnnotationVO(id: String, status: String, annotationType: String,
                         annotationInfo: scala.collection.immutable.Map[String, Any], wbId: String, userId: String, position: Int)
 
+object ClientToServerLatencyTracerMsg { val NAME = "ClientToServerLatencyTracerMsg" }
+case class ClientToServerLatencyTracerMsg(header: BbbClientMsgHeader, body: ClientToServerLatencyTracerMsgBody) extends StandardMsg
+case class ClientToServerLatencyTracerMsgBody(timestamp: Long, prettyTimestamp: String, tzOffset: Long,  senderId: String)
+
+object ServerToClientLatencyTracerMsg { val NAME = "ServerToClientLatencyTracerMsg" }
+case class ServerToClientLatencyTracerMsg(header: BbbClientMsgHeader, body: ServerToClientLatencyTracerMsgBody) extends BbbCoreMsg
+case class ServerToClientLatencyTracerMsgBody(timestamp: Long, prettyTimestamp: String, tzOffset: Long, senderId: String)
+
+
   object ClearWhiteboardEvtMsg {
     val NAME = "ClearWhiteboardEvtMsg"
   }

bigbluebutton-apps/src/main/java/org/bigbluebutton/red5/client/messaging/ConnectionInvokerService.java

@@ -59,6 +59,8 @@ public class ConnectionInvokerService implements IConnectionInvokerService {
 
   private final long SEND_TIMEOUT = 5000000000L; // 5s
 
+  private Long lastMsgLengthLog = System.currentTimeMillis();
+
   public ConnectionInvokerService() {
     messages = new LinkedBlockingQueue<ClientMessage>();
   }
@@ -74,6 +76,10 @@ public class ConnectionInvokerService implements IConnectionInvokerService {
         while (sendMessages) {
           ClientMessage message;
           try {
+            if (System.currentTimeMillis() - lastMsgLengthLog > 60000) {
+              lastMsgLengthLog = System.currentTimeMillis();
+              log.info("Message queue length = " + messages.size());
+            }
             message = messages.take();
             if (log.isTraceEnabled()) {
               log.trace("Took message from queue: " + message.getMessageName());
@@ -169,6 +175,10 @@ public class ConnectionInvokerService implements IConnectionInvokerService {
       log.trace("Handle direct message: " + msg.messageName + " msg=" + msg.json);
     }
 
+    if ("ServerToClientLatencyTracerMsg".equals(msg.messageName)) {
+      log.info("-- trace -- " + msg.json);
+    }
+
     final String connId = msg.connId;
     Runnable sender = new Runnable() {
       public void run() {

bigbluebutton-client/src/org/bigbluebutton/core/events/RoundTripLatencyReceivedEvent.as

@@ -0,0 +1,14 @@
+package org.bigbluebutton.core.events
+{
+  import flash.events.Event;
+  
+  public class RoundTripLatencyReceivedEvent extends Event
+  {
+    public static const ROUND_TRIP_LATENCY_RECEIVED: String = "round trip latency received event";
+    
+    public function RoundTripLatencyReceivedEvent()
+    {
+      super(ROUND_TRIP_LATENCY_RECEIVED, false, false);
+    }
+  }
+}

bigbluebutton-client/src/org/bigbluebutton/main/views/MainApplicationShell.mxml

@@ -82,6 +82,8 @@ with BigBlueButton; if not, see <http://www.gnu.org/licenses/>.
 		<mate:Listener type="{BBBEvent.REMOVE_GUEST_FROM_LIST}" method="removeGuestWindow" />
 		<mate:Listener type="{BBBEvent.WAITING_FOR_MODERATOR_ACCEPTANCE}" method="openWaitWindow" />
 		<mate:Listener type="{BBBEvent.RECONNECT_DISCONNECTED_EVENT}" method="closeWaitWindow"/>
+    <mate:Listener type="{RoundTripLatencyReceivedEvent.ROUND_TRIP_LATENCY_RECEIVED}" method="handleRoundTripLatencyReceivedEvent"/>
+    
 	</fx:Declarations>
 	<fx:Script>
 		<![CDATA[
@@ -119,7 +121,9 @@ with BigBlueButton; if not, see <http://www.gnu.org/licenses/>.
       import org.bigbluebutton.core.UsersUtil;
       import org.bigbluebutton.core.events.LockControlEvent;
       import org.bigbluebutton.core.events.NewGuestWaitingEvent;
+      import org.bigbluebutton.core.events.RoundTripLatencyReceivedEvent;
       import org.bigbluebutton.core.events.SwitchedLayoutEvent;
+      import org.bigbluebutton.core.model.LiveMeeting;
       import org.bigbluebutton.core.vo.LockSettingsVO;
       import org.bigbluebutton.main.events.AppVersionEvent;
       import org.bigbluebutton.main.events.BBBEvent;
@@ -735,6 +739,10 @@ with BigBlueButton; if not, see <http://www.gnu.org/licenses/>.
                 PopUpUtil.createModalPopUp(mdiCanvas, AudioSelectionWindow, true);
             }
 
+            private function handleRoundTripLatencyReceivedEvent(event: RoundTripLatencyReceivedEvent): void {
+              rttLabel.text = "RTT = " + LiveMeeting.inst().whiteboardModel.latencyInSec + "s";
+            }
+      
             private function handleWebRTCMediaRequestEvent(event:WebRTCMediaEvent):void {
                 var options:PhoneOptions = new PhoneOptions();
                 if (!options.showMicrophoneHint) return;
@@ -1052,6 +1060,11 @@ with BigBlueButton; if not, see <http://www.gnu.org/licenses/>.
 				id="copyrightLabel2" truncateToFit="true"
 				selectable="true" paddingRight="10"/>
 		<mx:Spacer width="100%" id="spacer" />
+    <mx:Label 
+      id="rttLabel"
+      text="RTT = 0ms"
+      visible="true"
+      includeInLayout="true" />
 		<mx:Label 
 				id="lblWebRTC"
 				text="{'[ '+ResourceUtil.getInstance().getString('bbb.mainshell.notification.webrtc')+' ]'}"

bigbluebutton-client/src/org/bigbluebutton/modules/whiteboard/models/WhiteboardModel.as

@@ -27,6 +27,7 @@ package org.bigbluebutton.modules.whiteboard.models
 	
 	import org.as3commons.logging.api.ILogger;
 	import org.as3commons.logging.api.getClassLogger;
+	import org.bigbluebutton.core.events.RoundTripLatencyReceivedEvent;
 	import org.bigbluebutton.modules.whiteboard.commands.GetWhiteboardShapesCommand;
 	import org.bigbluebutton.modules.whiteboard.events.WhiteboardAccessEvent;
 	import org.bigbluebutton.modules.whiteboard.events.WhiteboardCursorEvent;
@@ -39,7 +40,36 @@ package org.bigbluebutton.modules.whiteboard.models
 		
 		private var _multiUser:Boolean = false;
 
-    public var _dispatcher:Dispatcher = new Dispatcher();
+    private var _dispatcher:Dispatcher = new Dispatcher();
+    
+    private var _lastTraceSentOn: Date = new Date();
+    private var _lastTraceReceivedOn: Date = new Date();
+    private var _roundTripTime: Number = 0;
+
+    public function sentLastTrace(date: Date):void {
+      _lastTraceSentOn = date;
+    }
+    
+    public function get lastTraceSentOn(): Date {
+      return _lastTraceSentOn;
+    }
+    
+    public function set lastTraceReceivedTimestamp(ts: Number): void {
+      var tsDate: Date = new Date(ts);
+      var now: Date = new Date();
+      _roundTripTime = (now.time - tsDate.time) / 1000;
+      
+      _dispatcher.dispatchEvent(new RoundTripLatencyReceivedEvent());
+    }
+    
+    public function get latencyInSec(): Number {
+      if (_lastTraceReceivedOn.time < _lastTraceSentOn.time) {
+        var now: Date = new Date();
+        return (now.time - _lastTraceSentOn.time) / 1000;
+      } else {
+        return (_lastTraceReceivedOn.time - _lastTraceSentOn.time) / 1000;
+      }
+    }
     
 
     private function getWhiteboard(id:String, requestHistory:Boolean=true):Whiteboard {

bigbluebutton-client/src/org/bigbluebutton/modules/whiteboard/services/MessageReceiver.as

@@ -58,6 +58,9 @@ package org.bigbluebutton.modules.whiteboard.services
         case "SendCursorPositionEvtMsg":
           handleSendCursorPositionEvtMsg(message);
           break;
+        case "ServerToClientLatencyTracerMsg":
+          handleServerToClientLatencyTracerMsg(message);
+          break;
         default:
 //          LogUtil.warn("Cannot handle message [" + messageName + "]");
       }
@@ -116,5 +119,12 @@ package org.bigbluebutton.modules.whiteboard.services
       
     LiveMeeting.inst().whiteboardModel.updateCursorPosition(userId, xPercent, yPercent);
     }
+    
+    private function handleServerToClientLatencyTracerMsg(message:Object):void {
+      var userId:String = message.body.senderId as String;
+      var timestamp:Number = message.body.timestamp as Number;
+      
+      LiveMeeting.inst().whiteboardModel.lastTraceReceivedTimestamp = timestamp;
+    }
   }
 }

bigbluebutton-client/src/org/bigbluebutton/modules/whiteboard/services/MessageSender.as

@@ -23,6 +23,7 @@ package org.bigbluebutton.modules.whiteboard.services
 	import org.bigbluebutton.core.BBB;
 	import org.bigbluebutton.core.UsersUtil;
 	import org.bigbluebutton.core.managers.ConnectionManager;
+	import org.bigbluebutton.core.model.LiveMeeting;
 	import org.bigbluebutton.modules.whiteboard.events.WhiteboardAccessEvent;
 	import org.bigbluebutton.modules.whiteboard.events.WhiteboardDrawEvent;
 	
@@ -175,6 +176,37 @@ package org.bigbluebutton.modules.whiteboard.services
 				},
 				JSON.stringify(message)
 			);
+      
+      sendClientToServerLatencyTracerMsg();
+		}
+    
+    public function sendClientToServerLatencyTracerMsg():void {
+      var lastTraceSentOn: Date = LiveMeeting.inst().whiteboardModel.lastTraceSentOn;
+      var now: Date = new Date();
+      
+      if (now.time - lastTraceSentOn.time > 60000) {
+        var prettyDate: String = now.toString();
+        var ts: Number = now.time;
+        var tzOffset: Number = now.timezoneOffset;
+        
+        LiveMeeting.inst().whiteboardModel.sentLastTrace(now);
+        
+        var message:Object = {
+          header: {name: "ClientToServerLatencyTracerMsg", meetingId: UsersUtil.getInternalMeetingID(), userId: UsersUtil.getMyUserID()},
+          body: {timestamp: ts, prettyTimestamp: prettyDate, tzOffset: tzOffset, senderId: UsersUtil.getMyUserID()}
+        };
+        
+        var _nc:ConnectionManager = BBB.initConnectionManager();
+        _nc.sendMessage2x(
+          function(result:String):void { // On successful result
+            //LOGGER.debug(result);
+          },
+          function(status:String):void { // status - On error occurred
+            //LOGGER.error(status);
+          },
+          JSON.stringify(message)
+        );
+      }
     }
   }
 }