More refined time tracing. It seems the AMP connection is really the bottleneck.

evennia/server/amp.py

@@ -355,6 +355,17 @@ class AMPProtocol(amp.AMP):
                 as batch parts get sent (or fails).
 
         """
+        now = time()
+        batch = dumps([(sessid, kwargs)])
+        hashid = "%s-%s" % (id(batch), now)
+        deferreds = [self.callRemote(command,
+                               hashid=hashid,
+                               data=batch,
+                               ipart=0,
+                               nparts=1).addErrback(self.errback, command.key)]
+        return deferreds
+
+
         global _SENDBATCH
 
         if command:
@@ -472,6 +483,8 @@ class AMPProtocol(amp.AMP):
         batch = self.batch_recv(hashid, data, ipart, nparts)
         for (sessid, kwargs) in batch:
             #print "msg portal -> server (server side):", sessid, msg, loads(ret["data"])
+            from evennia.server.profiling.timetrace import timetrace
+            kwargs["msg"] = timetrace(kwargs["msg"], "AMP.amp_msg_portal2server")
             self.factory.server.sessions.data_in(sessid,
                                              text=kwargs["msg"],
                                              data=kwargs["data"])
@@ -496,7 +509,7 @@ class AMPProtocol(amp.AMP):
         msg = timetrace(msg, "AMP.call_remote_MsgPortal2Server")
         return self.batch_send(MsgPortal2Server, sessid,
                                msg=msg if msg is not None else "",
-                               data=data)
+                               data=data, force_send=True)
 
     # Server -> Portal message
 

evennia/server/portal/telnet.py

@@ -163,7 +163,6 @@ class TelnetProtocol(Telnet, StatefulTelnetProtocol, Session):
             parsed data directly to self.data_in.
 
         """
-
         if data and data[0] == IAC or self.iaw_mode:
             try:
                 #print "IAC mode"

evennia/server/profiling/timetrace.py

@@ -29,7 +29,7 @@ def timetrace(message, idstring, tracemessage="TEST_MESSAGE", final=False):
         else:
             t1 = time()
         # print to log (important!)
-        print "timetrace (%s): dT=%fs, total=%fs." % (idstring, t1-tlast, t1-t0)
+        print "** timetrace (%s): dT=%fs, total=%fs." % (idstring, t1-tlast, t1-t0)
 
         if final:
             message = "%s (total %f)" % (tracemessage, t1-t0)

evennia/server/sessionhandler.py

@@ -602,7 +602,7 @@ class ServerSessionHandler(SessionHandler):
 
         """
         from evennia.server.profiling.timetrace import timetrace
-        text = timetrace(text, "ServerSession.data_in")
+        text = timetrace(text, "ServerSessionHandler.data_in")
         session = self.sessions.get(sessid, None)
         if session:
             text = text and to_unicode(strip_control_sequences(text), encoding=session.encoding)