diff --git a/evennia/objects/objects.py b/evennia/objects/objects.py index 7d58309fe..d095e3b15 100644 --- a/evennia/objects/objects.py +++ b/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 diff --git a/evennia/server/amp.py b/evennia/server/amp.py index 2840b3036..c47b705f6 100644 --- a/evennia/server/amp.py +++ b/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) diff --git a/evennia/server/portal/portalsessionhandler.py b/evennia/server/portal/portalsessionhandler.py index ee8f434e5..57fdb7292 100644 --- a/evennia/server/portal/portalsessionhandler.py +++ b/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 diff --git a/evennia/server/portal/telnet.py b/evennia/server/portal/telnet.py index 48246f60b..4960bd475 100644 --- a/evennia/server/portal/telnet.py +++ b/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: diff --git a/evennia/server/profiling/timetrace.py b/evennia/server/profiling/timetrace.py new file mode 100644 index 000000000..8f4b7141d --- /dev/null +++ b/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 diff --git a/evennia/server/serversession.py b/evennia/server/serversession.py index efe6811fc..6bb5a2bbd 100644 --- a/evennia/server/serversession.py +++ b/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) diff --git a/evennia/server/sessionhandler.py b/evennia/server/sessionhandler.py index f1b809cdd..315a7dd42 100644 --- a/evennia/server/sessionhandler.py +++ b/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)