Time tracing setup for tracing the flow of data through AMP.

evennia/objects/objects.py

@@ -425,6 +425,9 @@ class DefaultObject(ObjectDB):
             All extra kwargs will be passed on to the protocol.
 
         """
+        from evennia.server.profiling.timetrace import timetrace
+        text = timetrace(text, "Object.msg")
+
         text = to_str(text, force_string=True) if text != None else ""
         if from_obj:
             # call hook

evennia/server/amp.py

@@ -492,6 +492,8 @@ class AMPProtocol(amp.AMP):
 
         """
         #print "msg portal->server (portal side):", sessid, msg, data
+        from evennia.server.profiling.timetrace import timetrace
+        msg = timetrace(msg, "AMP.call_remote_MsgPortal2Server")
         return self.batch_send(MsgPortal2Server, sessid,
                                msg=msg if msg is not None else "",
                                data=data)
@@ -517,6 +519,8 @@ class AMPProtocol(amp.AMP):
         batch = self.batch_recv(hashid, data, ipart, nparts)
         for (sessid, kwargs) in batch:
             #print "msg server->portal (portal side):", sessid, ret["text"], loads(ret["data"])
+            from evennia.server.profiling.timetrace import timetrace
+            kwargs["msg"] = timetrace(kwargs["msg"], "AMP.amp_msg_server2portal")
             self.factory.portal.sessions.data_out(sessid,
                                                   text=kwargs["msg"],
                                                   data=kwargs["data"])
@@ -542,6 +546,8 @@ class AMPProtocol(amp.AMP):
         batch = self.batch_recv(hashid, data, ipart, nparts)
         if batch is not None:
             for (sessid, kwargs) in batch:
+                from evennia.server.profiling.timetrace import timetrace
+                kwargs["msg"] = timetrace(kwargs["msg"], "AMP.amp_batch_server2portal")
                 self.factory.portal.sessions.data_out(sessid,
                                                       text=kwargs["msg"],
                                                       **kwargs["data"])
@@ -558,6 +564,8 @@ class AMPProtocol(amp.AMP):
             data (str, optional): Extra data.
 
         """
+        from evennia.server.profiling.timetrace import timetrace
+        msg = timetrace(msg, "AMP.call_remote_MsgServer2Portal")
         #print "msg server->portal (server side):", sessid, msg, data
         return self.batch_send(MsgServer2Portal, sessid, msg=msg, data=data)
 

evennia/server/portal/portalsessionhandler.py

@@ -366,6 +366,8 @@ class PortalSessionHandler(SessionHandler):
             Data is serialized before passed on.
 
         """
+        from evennia.server.profiling.timetrace import timetrace
+        text = timetrace(text, "portalsessionhandler.data_out")
         now = time()
         # data throttle (anti DoS measure)
         self.command_counter += 1
@@ -398,6 +400,8 @@ class PortalSessionHandler(SessionHandler):
             kwargs (any): Other data from protocol.
 
         """
+        from evennia.server.profiling.timetrace import timetrace
+        text = timetrace(text, "portalsessionhandler.data_out")
         session = self.sessions.get(sessid, None)
         if session:
             # convert oob to the generic format

evennia/server/portal/telnet.py

@@ -256,6 +256,8 @@ class TelnetProtocol(Telnet, StatefulTelnetProtocol, Session):
             kwargs (any): Options from the protocol.
 
         """
+        from evennia.server.profiling.timetrace import timetrace
+        text = timetrace(text, "telnet.data_in")
         self.sessionhandler.data_in(self, text=text, **kwargs)
 
     def data_out(self, text=None, **kwargs):
@@ -290,6 +292,8 @@ class TelnetProtocol(Telnet, StatefulTelnetProtocol, Session):
             are given.
 
         """
+        from evennia.server.profiling.timetrace import timetrace
+        text = timetrace(text, "telnet.data_out", final=True)
         try:
             text = utils.to_str(text if text else "", encoding=self.encoding)
         except Exception, e:

evennia/server/profiling/timetrace.py

@@ -0,0 +1,38 @@
+"""
+Trace a message through the messaging system
+"""
+from time import time
+
+def timetrace(message, idstring, tracemessage="TEST_MESSAGE", final=False):
+    """
+    Trace a message with time stamps.
+
+    Args:
+        message (str): The actual message coming through
+        idstring (str): An identifier string specifying where this trace is happening.
+        tracemessage (str): The start of the message to tag.
+            This message will get attached time stamp.
+        final (bool): This is the final leg in the path - include total time in message
+
+    """
+    if message.startswith(tracemessage):
+        # the message is on the form TEST_MESSAGE tlast t0
+        # where t0 is the initial starting time and last is the time
+        # saved at the last stop.
+        try:
+            prefix, tlast, t0 = message.split(None, 2)
+            tlast, t0 = float(tlast), float(t0)
+        except (IndexError, ValueError):
+            t0 = time()
+            tlast = t0
+            t1 = t0
+        else:
+            t1 = time()
+        # print to log (important!)
+        print "timetrace (%s): dT=%fs, total=%fs." % (idstring, t1-tlast, t1-t0)
+
+        if final:
+            message = "%s (total %f)" % (tracemessage, t1-t0)
+        else:
+            message = "%s %f %f" % (tracemessage, t1, t0)
+    return message

evennia/server/serversession.py

@@ -228,6 +228,9 @@ class ServerSession(Session):
             kwargs (any): Other parameters from the protocol.
 
         """
+        from evennia.server.profiling.timetrace import timetrace
+        text = timetrace(text, "ServerSession.data_in")
+
         #explicitly check for None since text can be an empty string, which is
         #also valid
         if text is not None:
@@ -260,6 +263,9 @@ class ServerSession(Session):
             kwargs (any): Other parameters to the protocol.
 
         """
+        from evennia.server.profiling.timetrace import timetrace
+        text = timetrace(text, "ServerSession.data_out")
+
         text = text if text else ""
         if _INLINEFUNC_ENABLED and not "raw" in kwargs:
             text = parse_inlinefunc(text, strip="strip_inlinefunc" in kwargs, session=self)

evennia/server/sessionhandler.py

@@ -555,6 +555,8 @@ class ServerSessionHandler(SessionHandler):
                 Useful for connection handling messages.
 
         """
+        from evennia.server.profiling.timetrace import timetrace
+        text = timetrace(text, "ServerSessionHandler.data_out")
         sessions = make_iter(session)
         session = sessions[0]
         text = text and to_str(to_unicode(text), encoding=session.encoding)
@@ -599,6 +601,8 @@ class ServerSessionHandler(SessionHandler):
             kwargs (any): Other data from protocol.
 
         """
+        from evennia.server.profiling.timetrace import timetrace
+        text = timetrace(text, "ServerSession.data_in")
         session = self.sessions.get(sessid, None)
         if session:
             text = text and to_unicode(strip_control_sequences(text), encoding=session.encoding)