From 6f3cc77bb52349b1b88d0dd6edd2ba77141bc7f6 Mon Sep 17 00:00:00 2001 From: Vijay Pandurangan Date: Sat, 19 Nov 2011 11:30:44 -0800 Subject: [PATCH 1/4] This change stops sleekxmpp from spending huge amounts of time unnecessarily computing logging data that may never be used. This is a HUGE performance improvement; in some of my test runs, unnecessary string creation was accounting for > 60% of all CPU time. Note that using % in a string will _always_ perform the sting substitutions, because the strings are constructed before the function is called. So log.debug('%s' % expensiveoperation()) will take about the same CPU time whether or not the logging level is DEBUG or INFO. if you use , no substitutions are performed unless the string is actually logged --- conn_tests/test_pubsubjobs.py | 6 +-- conn_tests/test_pubsubserver.py | 6 +-- conn_tests/testpubsub.py | 4 +- examples/ping.py | 2 +- sleekxmpp/basexmpp.py | 8 ++-- sleekxmpp/clientxmpp.py | 2 +- sleekxmpp/features/feature_bind/bind.py | 4 +- .../features/feature_mechanisms/mechanisms.py | 2 +- sleekxmpp/plugins/gmail_notify.py | 4 +- sleekxmpp/plugins/jobs.py | 2 +- sleekxmpp/plugins/xep_0009/remote.py | 16 +++---- sleekxmpp/plugins/xep_0009/rpc.py | 8 ++-- sleekxmpp/plugins/xep_0012.py | 4 +- sleekxmpp/plugins/xep_0045.py | 4 +- sleekxmpp/plugins/xep_0050/adhoc.py | 3 +- sleekxmpp/plugins/xep_0078/legacyauth.py | 4 +- sleekxmpp/plugins/xep_0085/chat_states.py | 2 +- sleekxmpp/plugins/xep_0199/ping.py | 6 +-- sleekxmpp/plugins/xep_0224/attention.py | 2 +- sleekxmpp/stanza/rootstanza.py | 3 +- sleekxmpp/xmlstream/handler/waiter.py | 2 +- sleekxmpp/xmlstream/matcher/xmlmask.py | 3 +- sleekxmpp/xmlstream/xmlstream.py | 44 +++++++++---------- 23 files changed, 69 insertions(+), 72 deletions(-) diff --git a/conn_tests/test_pubsubjobs.py b/conn_tests/test_pubsubjobs.py index edf22cc..ec2a271 100644 --- a/conn_tests/test_pubsubjobs.py +++ b/conn_tests/test_pubsubjobs.py @@ -122,14 +122,14 @@ if __name__ == '__main__': logging.basicConfig(level=opts.loglevel, format='%(levelname)-8s %(message)s') #load xml config - logging.info("Loading config file: %s" % opts.configfile) + logging.info("Loading config file: %s" , opts.configfile) config = configparser.RawConfigParser() config.read(opts.configfile) #init - logging.info("Account 1 is %s" % config.get('account1', 'jid')) + logging.info("Account 1 is %s" , config.get('account1', 'jid')) xmpp1 = TestClient(config.get('account1','jid'), config.get('account1','pass')) - logging.info("Account 2 is %s" % config.get('account2', 'jid')) + logging.info("Account 2 is %s" , config.get('account2', 'jid')) xmpp2 = TestClient(config.get('account2','jid'), config.get('account2','pass')) xmpp1.registerPlugin('xep_0004') diff --git a/conn_tests/test_pubsubserver.py b/conn_tests/test_pubsubserver.py index 15635b4..aae77dd 100644 --- a/conn_tests/test_pubsubserver.py +++ b/conn_tests/test_pubsubserver.py @@ -186,14 +186,14 @@ if __name__ == '__main__': logging.basicConfig(level=opts.loglevel, format='%(levelname)-8s %(message)s') #load xml config - logging.info("Loading config file: %s" % opts.configfile) + logging.info("Loading config file: %s" , opts.configfile) config = configparser.RawConfigParser() config.read(opts.configfile) #init - logging.info("Account 1 is %s" % config.get('account1', 'jid')) + logging.info("Account 1 is %s" , config.get('account1', 'jid')) xmpp1 = TestClient(config.get('account1','jid'), config.get('account1','pass')) - logging.info("Account 2 is %s" % config.get('account2', 'jid')) + logging.info("Account 2 is %s" , config.get('account2', 'jid')) xmpp2 = TestClient(config.get('account2','jid'), config.get('account2','pass')) xmpp1.registerPlugin('xep_0004') diff --git a/conn_tests/testpubsub.py b/conn_tests/testpubsub.py index 3aa7200..0f46524 100755 --- a/conn_tests/testpubsub.py +++ b/conn_tests/testpubsub.py @@ -329,11 +329,11 @@ if __name__ == '__main__': logging.basicConfig(level=opts.loglevel, format='%(levelname)-8s %(message)s') #load xml config - logging.info("Loading config file: %s" % opts.configfile) + logging.info("Loading config file: %s" , opts.configfile) config = ET.parse(os.path.expanduser(opts.configfile)).find('auth') #init - logging.info("Logging in as %s" % config.attrib['jid']) + logging.info("Logging in as %s" , config.attrib['jid']) plugin_config = {} diff --git a/examples/ping.py b/examples/ping.py index 68772e6..fcf75a0 100755 --- a/examples/ping.py +++ b/examples/ping.py @@ -72,7 +72,7 @@ class PingTest(sleekxmpp.ClientXMPP): self.disconnect() sys.exit(1) else: - logging.info("Success! RTT: %s" % str(result)) + logging.info("Success! RTT: %s" , str(result)) self.disconnect() diff --git a/sleekxmpp/basexmpp.py b/sleekxmpp/basexmpp.py index 8f11eef..24a7c38 100644 --- a/sleekxmpp/basexmpp.py +++ b/sleekxmpp/basexmpp.py @@ -246,7 +246,7 @@ class BaseXMPP(XMLStream): spec = "(RFC-%s) " % self.plugin[plugin].rfc desc = (spec, self.plugin[plugin].description) - log.debug("Loaded Plugin %s%s" % desc) + log.debug("Loaded Plugin %s%s" , desc) except: log.exception("Unable to load plugin: %s", plugin) @@ -282,7 +282,7 @@ class BaseXMPP(XMLStream): if key in self.plugin: return self.plugin[key] else: - log.warning("""Plugin "%s" is not loaded.""" % key) + log.warning("""Plugin "%s" is not loaded.""" , key) return False def get(self, key, default): @@ -679,7 +679,7 @@ class BaseXMPP(XMLStream): def set_jid(self, jid): """Rip a JID apart and claim it as our own.""" - log.debug("setting jid to %s" % jid) + log.debug("setting jid to %s" , jid) self.boundjid.full = jid def getjidresource(self, fulljid): @@ -795,7 +795,7 @@ class BaseXMPP(XMLStream): log.warning('You should catch IqError exceptions') elif isinstance(exception, IqTimeout): iq = exception.iq - log.error('Request timed out: %s' % iq) + log.error('Request timed out: %s' , iq) log.warning('You should catch IqTimeout exceptions') else: log.exception(exception) diff --git a/sleekxmpp/clientxmpp.py b/sleekxmpp/clientxmpp.py index fb3551f..0635472 100644 --- a/sleekxmpp/clientxmpp.py +++ b/sleekxmpp/clientxmpp.py @@ -164,7 +164,7 @@ class ClientXMPP(BaseXMPP): address = (answer.target.to_text()[:-1], answer.port) answers.append((address, answer.priority, answer.weight)) except (dns.resolver.NXDOMAIN, dns.resolver.NoAnswer): - log.warning("No SRV records for %s" % domain) + log.warning("No SRV records for %s" , domain) answers = super(ClientXMPP, self).get_dns_records(domain, port) except dns.exception.Timeout: log.warning("DNS resolution timed out " + \ diff --git a/sleekxmpp/features/feature_bind/bind.py b/sleekxmpp/features/feature_bind/bind.py index de03192..ac3f447 100644 --- a/sleekxmpp/features/feature_bind/bind.py +++ b/sleekxmpp/features/feature_bind/bind.py @@ -42,7 +42,7 @@ class feature_bind(base_plugin): Arguments: features -- The stream features stanza. """ - log.debug("Requesting resource: %s" % self.xmpp.boundjid.resource) + log.debug("Requesting resource: %s" , self.xmpp.boundjid.resource) iq = self.xmpp.Iq() iq['type'] = 'set' iq.enable('bind') @@ -55,7 +55,7 @@ class feature_bind(base_plugin): self.xmpp.features.add('bind') - log.info("Node set to: %s" % self.xmpp.boundjid.full) + log.info("Node set to: %s" , self.xmpp.boundjid.full) if 'session' not in features['features']: log.debug("Established Session") diff --git a/sleekxmpp/features/feature_mechanisms/mechanisms.py b/sleekxmpp/features/feature_mechanisms/mechanisms.py index a6cff0a..5e5f0cd 100644 --- a/sleekxmpp/features/feature_mechanisms/mechanisms.py +++ b/sleekxmpp/features/feature_mechanisms/mechanisms.py @@ -123,7 +123,7 @@ class feature_mechanisms(base_plugin): def _handle_fail(self, stanza): """SASL authentication failed. Disconnect and shutdown.""" - log.info("Authentication failed: %s" % stanza['condition']) + log.info("Authentication failed: %s" , stanza['condition']) self.xmpp.event("failed_auth", stanza, direct=True) self.xmpp.disconnect() return True diff --git a/sleekxmpp/plugins/gmail_notify.py b/sleekxmpp/plugins/gmail_notify.py index 9a94a41..f6391ac 100644 --- a/sleekxmpp/plugins/gmail_notify.py +++ b/sleekxmpp/plugins/gmail_notify.py @@ -121,7 +121,7 @@ class gmail_notify(base.base_plugin): def handle_gmail(self, iq): mailbox = iq['mailbox'] approx = ' approximately' if mailbox['estimated'] else '' - log.info('Gmail: Received%s %s emails' % (approx, mailbox['total-matched'])) + log.info('Gmail: Received%s %s emails' , approx, mailbox['total-matched']) self.last_result_time = mailbox['result-time'] self.xmpp.event('gmail_messages', iq) @@ -140,7 +140,7 @@ class gmail_notify(base.base_plugin): if query is None: log.info("Gmail: Checking for new emails") else: - log.info('Gmail: Searching for emails matching: "%s"' % query) + log.info('Gmail: Searching for emails matching: "%s"' , query) iq = self.xmpp.Iq() iq['type'] = 'get' iq['to'] = self.xmpp.boundjid.bare diff --git a/sleekxmpp/plugins/jobs.py b/sleekxmpp/plugins/jobs.py index 0f1f7fb..5ccfe27 100644 --- a/sleekxmpp/plugins/jobs.py +++ b/sleekxmpp/plugins/jobs.py @@ -43,7 +43,7 @@ class jobs(base.base_plugin): iq['psstate']['payload'] = state result = iq.send() if result is None or type(result) == bool or result['type'] != 'result': - log.error("Unable to change %s:%s to %s" % (node, jobid, state)) + log.error("Unable to change %s:%s to %s" , node, jobid, state) return False return True diff --git a/sleekxmpp/plugins/xep_0009/remote.py b/sleekxmpp/plugins/xep_0009/remote.py index 3cc0f52..6ca42d0 100644 --- a/sleekxmpp/plugins/xep_0009/remote.py +++ b/sleekxmpp/plugins/xep_0009/remote.py @@ -20,7 +20,7 @@ log = logging.getLogger(__name__) def _intercept(method, name, public): def _resolver(instance, *args, **kwargs): - log.debug("Locally calling %s.%s with arguments %s." % (instance.FQN(), method.__name__, args)) + log.debug("Locally calling %s.%s with arguments %s." , instance.FQN(), method.__name__, args) try: value = method(instance, *args, **kwargs) if value == NotImplemented: @@ -381,7 +381,7 @@ class Proxy(Endpoint): try: if attribute._rpc: def _remote_call(*args, **kwargs): - log.debug("Remotely calling '%s.%s' with arguments %s." % (self._endpoint.FQN(), attribute._rpc_name, args)) + log.debug("Remotely calling '%s.%s' with arguments %s." , self._endpoint.FQN(), attribute._rpc_name, args) return self._endpoint.session._call_remote(self._endpoint.target_jid, "%s.%s" % (self._endpoint.FQN(), attribute._rpc_name), self._callback, *args, **kwargs) return _remote_call except: @@ -449,7 +449,7 @@ class RemoteSession(object): self._event.wait() def _notify(self, event): - log.debug("RPC Session as %s started." % self._client.boundjid.full) + log.debug("RPC Session as %s started." , self._client.boundjid.full) self._client.sendPresence() self._event.set() pass @@ -461,7 +461,7 @@ class RemoteSession(object): if name is None: name = method.__name__ key = "%s.%s" % (endpoint, name) - log.debug("Registering call handler for %s (%s)." % (key, method)) + log.debug("Registering call handler for %s (%s)." , key, method) with self._lock: if key in self._entries: raise KeyError("A handler for %s has already been regisered!" % endpoint) @@ -469,7 +469,7 @@ class RemoteSession(object): return key def _register_acl(self, endpoint, acl): - log.debug("Registering ACL %s for endpoint %s." % (repr(acl), endpoint)) + log.debug("Registering ACL %s for endpoint %s." , repr(acl), endpoint) with self._lock: self._acls[endpoint] = acl @@ -562,7 +562,7 @@ class RemoteSession(object): iq.send() return future.get_value(30) else: - log.debug("[RemoteSession] _call_remote %s" % callback) + log.debug("[RemoteSession] _call_remote %s" , callback) self._register_callback(pid, callback) iq.send() @@ -601,11 +601,11 @@ class RemoteSession(object): error.send() except Exception as e: if isinstance(e, KeyError): - log.error("No handler available for %s!" % pmethod) + log.error("No handler available for %s!" , pmethod) error = self._client.plugin['xep_0009']._item_not_found(iq) else: traceback.print_exc(file=sys.stderr) - log.error("An unexpected problem occurred invoking method %s!" % pmethod) + log.error("An unexpected problem occurred invoking method %s!" , pmethod) error = self._client.plugin['xep_0009']._undefined_condition(iq) #! print "[REMOTE.PY] _handle_remote_procedure_call AN ERROR SHOULD BE SENT NOW %s " % e error.send() diff --git a/sleekxmpp/plugins/xep_0009/rpc.py b/sleekxmpp/plugins/xep_0009/rpc.py index fc306d3..7f15051 100644 --- a/sleekxmpp/plugins/xep_0009/rpc.py +++ b/sleekxmpp/plugins/xep_0009/rpc.py @@ -128,22 +128,22 @@ class xep_0009(base.base_plugin): def _handle_method_call(self, iq): type = iq['type'] if type == 'set': - log.debug("Incoming Jabber-RPC call from %s" % iq['from']) + log.debug("Incoming Jabber-RPC call from %s" , iq['from']) self.xmpp.event('jabber_rpc_method_call', iq) else: if type == 'error' and ['rpc_query'] is None: self.handle_error(iq) else: - log.debug("Incoming Jabber-RPC error from %s" % iq['from']) + log.debug("Incoming Jabber-RPC error from %s" , iq['from']) self.xmpp.event('jabber_rpc_error', iq) def _handle_method_response(self, iq): if iq['rpc_query']['method_response']['fault'] is not None: - log.debug("Incoming Jabber-RPC fault from %s" % iq['from']) + log.debug("Incoming Jabber-RPC fault from %s" , iq['from']) #self._on_jabber_rpc_method_fault(iq) self.xmpp.event('jabber_rpc_method_fault', iq) else: - log.debug("Incoming Jabber-RPC response from %s" % iq['from']) + log.debug("Incoming Jabber-RPC response from %s" , iq['from']) self.xmpp.event('jabber_rpc_method_response', iq) def _handle_error(self, iq): diff --git a/sleekxmpp/plugins/xep_0012.py b/sleekxmpp/plugins/xep_0012.py index 8fe818b..e865cf1 100644 --- a/sleekxmpp/plugins/xep_0012.py +++ b/sleekxmpp/plugins/xep_0012.py @@ -71,10 +71,10 @@ class xep_0012(base.base_plugin): def handle_last_activity_query(self, iq): if iq['type'] == 'get': - log.debug("Last activity requested by %s" % iq['from']) + log.debug("Last activity requested by %s" , iq['from']) self.xmpp.event('last_activity_request', iq) elif iq['type'] == 'result': - log.debug("Last activity result from %s" % iq['from']) + log.debug("Last activity result from %s" , iq['from']) self.xmpp.event('last_activity', iq) def handle_last_activity(self, iq): diff --git a/sleekxmpp/plugins/xep_0045.py b/sleekxmpp/plugins/xep_0045.py index 45f1611..c037297 100644 --- a/sleekxmpp/plugins/xep_0045.py +++ b/sleekxmpp/plugins/xep_0045.py @@ -127,7 +127,7 @@ class xep_0045(base.base_plugin): def handle_groupchat_invite(self, inv): """ Handle an invite into a muc. """ - logging.debug("MUC invite to %s from %s: %s" % (inv['from'], inv["from"], inv)) + logging.debug("MUC invite to %s from %s: %s" , inv['from'], inv["from"], inv) if inv['from'] not in self.rooms.keys(): self.xmpp.event("groupchat_invite", inv) @@ -149,7 +149,7 @@ class xep_0045(base.base_plugin): if entry['nick'] not in self.rooms[entry['room']]: got_online = True self.rooms[entry['room']][entry['nick']] = entry - log.debug("MUC presence from %s/%s : %s" % (entry['room'],entry['nick'], entry)) + log.debug("MUC presence from %s/%s : %s" , entry['room'],entry['nick'], entry) self.xmpp.event("groupchat_presence", pr) self.xmpp.event("muc::%s::presence" % entry['room'], pr) if got_offline: diff --git a/sleekxmpp/plugins/xep_0050/adhoc.py b/sleekxmpp/plugins/xep_0050/adhoc.py index 5095f87..7cfaa0e 100644 --- a/sleekxmpp/plugins/xep_0050/adhoc.py +++ b/sleekxmpp/plugins/xep_0050/adhoc.py @@ -211,8 +211,7 @@ class xep_0050(base_plugin): key = (iq['to'].full, node) name, handler = self.commands.get(key, ('Not found', None)) if not handler: - log.debug('Command not found: %s, %s' % (key, self.commands)) - + log.debug('Command not found: %s, %s' , key, self.commands) initial_session = {'id': sessionid, 'from': iq['from'], 'to': iq['to'], diff --git a/sleekxmpp/plugins/xep_0078/legacyauth.py b/sleekxmpp/plugins/xep_0078/legacyauth.py index edb8f31..4963446 100644 --- a/sleekxmpp/plugins/xep_0078/legacyauth.py +++ b/sleekxmpp/plugins/xep_0078/legacyauth.py @@ -60,12 +60,12 @@ class xep_0078(base_plugin): try: resp = iq.send(now=True) except IqError: - log.info("Authentication failed: %s" % resp['error']['condition']) + log.info("Authentication failed: %s" , resp['error']['condition']) self.xmpp.event('failed_auth', direct=True) self.xmpp.disconnect() return True except IqTimeout: - log.info("Authentication failed: %s" % 'timeout') + log.info("Authentication failed: %s" , 'timeout') self.xmpp.event('failed_auth', direct=True) self.xmpp.disconnect() return True diff --git a/sleekxmpp/plugins/xep_0085/chat_states.py b/sleekxmpp/plugins/xep_0085/chat_states.py index 4fb21ba..d0a05cc 100644 --- a/sleekxmpp/plugins/xep_0085/chat_states.py +++ b/sleekxmpp/plugins/xep_0085/chat_states.py @@ -45,5 +45,5 @@ class xep_0085(base_plugin): def _handle_chat_state(self, msg): state = msg['chat_state'] - log.debug("Chat State: %s, %s" % (state, msg['from'].jid)) + log.debug("Chat State: %s, %s" , state, msg['from'].jid) self.xmpp.event('chatstate_%s' % state, msg) diff --git a/sleekxmpp/plugins/xep_0199/ping.py b/sleekxmpp/plugins/xep_0199/ping.py index de7f568..f8ae401 100644 --- a/sleekxmpp/plugins/xep_0199/ping.py +++ b/sleekxmpp/plugins/xep_0199/ping.py @@ -118,7 +118,7 @@ class xep_0199(base_plugin): Arguments: iq -- The ping request. """ - log.debug("Pinged by %s" % iq['from']) + log.debug("Pinged by %s" , iq['from']) iq.reply().send() def send_ping(self, jid, timeout=None, errorfalse=False, @@ -141,7 +141,7 @@ class xep_0199(base_plugin): is received. Useful in conjunction with the option block=False. """ - log.debug("Pinging %s" % jid) + log.debug("Pinging %s" , jid) if timeout is None: timeout = self.timeout @@ -167,7 +167,7 @@ class xep_0199(base_plugin): if not block: return None - log.debug("Pong: %s %f" % (jid, delay)) + log.debug("Pong: %s %f" , jid, delay) return delay diff --git a/sleekxmpp/plugins/xep_0224/attention.py b/sleekxmpp/plugins/xep_0224/attention.py index 41d7a0f..4c03f6a 100644 --- a/sleekxmpp/plugins/xep_0224/attention.py +++ b/sleekxmpp/plugins/xep_0224/attention.py @@ -68,5 +68,5 @@ class xep_0224(base_plugin): Arguments: msg -- A message stanza with an attention element. """ - log.debug("Received attention request from: %s" % msg['from']) + log.debug("Received attention request from: %s" , msg['from']) self.xmpp.event('attention', msg) diff --git a/sleekxmpp/stanza/rootstanza.py b/sleekxmpp/stanza/rootstanza.py index 470a122..2ac47d8 100644 --- a/sleekxmpp/stanza/rootstanza.py +++ b/sleekxmpp/stanza/rootstanza.py @@ -80,8 +80,7 @@ class RootStanza(StanzaBase): self['error']['type'] = 'cancel' self.send() # log the error - log.exception('Error handling {%s}%s stanza' % - (self.namespace, self.name)) + log.exception('Error handling {%s}%s stanza' , self.namespace, self.name) # Finally raise the exception to a global exception handler self.stream.exception(e) diff --git a/sleekxmpp/xmlstream/handler/waiter.py b/sleekxmpp/xmlstream/handler/waiter.py index 25dc161..c3d0a4e 100644 --- a/sleekxmpp/xmlstream/handler/waiter.py +++ b/sleekxmpp/xmlstream/handler/waiter.py @@ -91,7 +91,7 @@ class Waiter(BaseHandler): stanza = self._payload.get(True, timeout) except queue.Empty: stanza = False - log.warning("Timed out waiting for %s" % self.name) + log.warning("Timed out waiting for %s" , self.name) self.stream().remove_handler(self.name) return stanza diff --git a/sleekxmpp/xmlstream/matcher/xmlmask.py b/sleekxmpp/xmlstream/matcher/xmlmask.py index 53ccc9b..cd35043 100644 --- a/sleekxmpp/xmlstream/matcher/xmlmask.py +++ b/sleekxmpp/xmlstream/matcher/xmlmask.py @@ -102,8 +102,7 @@ class MatchXMLMask(MatcherBase): try: mask = ET.fromstring(mask) except ExpatError: - log.warning("Expat error: %s\nIn parsing: %s" % ('', mask)) - + log.warning("Expat error: %s\nIn parsing: %s" , '', mask) if not use_ns: # Compare the element without using namespaces. source_tag = source.tag.split('}', 1)[-1] diff --git a/sleekxmpp/xmlstream/xmlstream.py b/sleekxmpp/xmlstream/xmlstream.py index b6d013b..7b941bf 100644 --- a/sleekxmpp/xmlstream/xmlstream.py +++ b/sleekxmpp/xmlstream/xmlstream.py @@ -362,7 +362,7 @@ class XMLStream(object): else: delay = min(self.reconnect_delay * 2, self.reconnect_max_delay) delay = random.normalvariate(delay, delay * 0.1) - log.debug('Waiting %s seconds before connecting.' % delay) + log.debug('Waiting %s seconds before connecting.' , delay) time.sleep(delay) if self.use_proxy: @@ -391,7 +391,7 @@ class XMLStream(object): try: if not self.use_proxy: - log.debug("Connecting to %s:%s" % self.address) + log.debug("Connecting to %s:%s" , self.address) self.socket.connect(self.address) self.set_socket(self.socket, ignore=True) @@ -435,18 +435,18 @@ class XMLStream(object): headers = '\r\n'.join(headers) + '\r\n\r\n' try: - log.debug("Connecting to proxy: %s:%s" % address) + log.debug("Connecting to proxy: %s:%s" , address) self.socket.connect(address) self.send_raw(headers, now=True) resp = '' while '\r\n\r\n' not in resp: resp += self.socket.recv(1024).decode('utf-8') - log.debug('RECV: %s' % resp) + log.debug('RECV: %s' , resp) lines = resp.split('\r\n') if '200' not in lines[0]: self.event('proxy_error', resp) - log.error('Proxy Error: %s' % lines[0]) + log.error('Proxy Error: %s' , lines[0]) return False # Proxy connection established, continue connecting @@ -510,7 +510,7 @@ class XMLStream(object): # Wait for confirmation that the stream was # closed in the other direction. self.auto_reconnect = reconnect - log.debug('Waiting for %s from server' % self.stream_footer) + log.debug('Waiting for %s from server' , self.stream_footer) self.stream_end_event.wait(4) if not self.auto_reconnect: self.stop.set() @@ -601,7 +601,7 @@ class XMLStream(object): """ if self.ssl_support: log.info("Negotiating TLS") - log.info("Using SSL version: %s" % str(self.ssl_version)) + log.info("Using SSL version: %s" , str(self.ssl_version)) if self.ca_certs is None: cert_policy = ssl.CERT_NONE else: @@ -759,7 +759,7 @@ class XMLStream(object): try: answers = resolver.query(domain, dns.rdatatype.A) except (dns.resolver.NXDOMAIN, dns.resolver.NoAnswer): - log.warning("No A records for %s" % domain) + log.warning("No A records for %s" , domain) return [((domain, port), 0, 0)] except dns.exception.Timeout: log.warning("DNS resolution timed out " + \ @@ -808,7 +808,7 @@ class XMLStream(object): if self.dns_answers[0] == address: break self.dns_answers.pop(idx) - log.debug("Trying to connect to %s:%s" % address) + log.debug("Trying to connect to %s:%s" , address) return address def add_event_handler(self, name, pointer, @@ -879,7 +879,7 @@ class XMLStream(object): handler[0](copy.copy(data)) except Exception as e: error_msg = 'Error processing event handler: %s' - log.exception(error_msg % str(handler[0])) + log.exception(error_msg , str(handler[0])) if hasattr(data, 'exception'): data.exception(e) else: @@ -994,7 +994,7 @@ class XMLStream(object): Defaults to self.auto_reconnect. """ if now: - log.debug("SEND (IMMED): %s" % data) + log.debug("SEND (IMMED): %s" , data) try: data = data.encode('utf-8') total = len(data) @@ -1004,10 +1004,10 @@ class XMLStream(object): sent += self.socket.send(data[sent:]) count += 1 if count > 1: - log.debug('SENT: %d chunks' % count) + log.debug('SENT: %d chunks' , count) except Socket.error as serr: self.event('socket_error', serr) - log.warning("Failed to send %s" % data) + log.warning("Failed to send %s" , data) if reconnect is None: reconnect = self.auto_reconnect self.disconnect(reconnect) @@ -1187,7 +1187,7 @@ class XMLStream(object): Arguments: xml -- The XML stanza to analyze. """ - log.debug("RECV: %s" % tostring(xml, + log.debug("RECV: %s" , tostring(xml, xmlns=self.default_ns, stream=self)) # Apply any preprocessing filters. @@ -1232,7 +1232,7 @@ class XMLStream(object): func(*args) except Exception as e: error_msg = 'Error processing event handler: %s' - log.exception(error_msg % str(func)) + log.exception(error_msg , str(func)) if hasattr(orig, 'exception'): orig.exception(e) else: @@ -1267,12 +1267,12 @@ class XMLStream(object): handler.run(args[0]) except Exception as e: error_msg = 'Error processing stream handler: %s' - log.exception(error_msg % handler.name) + log.exception(error_msg , handler.name) orig.exception(e) elif etype == 'schedule': name = args[1] try: - log.debug('Scheduled event: %s: %s' % (name, args[0])) + log.debug('Scheduled event: %s: %s' , name, args[0]) handler(*args[0]) except Exception as e: log.exception('Error processing scheduled task') @@ -1291,7 +1291,7 @@ class XMLStream(object): func(*args) except Exception as e: error_msg = 'Error processing event handler: %s' - log.exception(error_msg % str(func)) + log.exception(error_msg , str(func)) if hasattr(orig, 'exception'): orig.exception(e) else: @@ -1324,7 +1324,7 @@ class XMLStream(object): data = self.send_queue.get(True, 1) except queue.Empty: continue - log.debug("SEND: %s" % data) + log.debug("SEND: %s" , data) try: enc_data = data.encode('utf-8') total = len(enc_data) @@ -1334,15 +1334,15 @@ class XMLStream(object): sent += self.socket.send(enc_data[sent:]) count += 1 if count > 1: - log.debug('SENT: %d chunks' % count) + log.debug('SENT: %d chunks' , count) self.send_queue.task_done() except Socket.error as serr: self.event('socket_error', serr) - log.warning("Failed to send %s" % data) + log.warning("Failed to send %s" , data) self.__failed_send_stanza = data self.disconnect(self.auto_reconnect) except Exception as ex: - log.exception('Unexpected error in send thread: %s' % ex) + log.exception('Unexpected error in send thread: %s' , ex) self.exception(ex) if not self.stop.is_set(): self.disconnect(self.auto_reconnect) From 48af3d33226a8f432b50e3ff9b54c59c2d9e4cda Mon Sep 17 00:00:00 2001 From: Vijay Pandurangan Date: Sat, 19 Nov 2011 15:59:38 -0800 Subject: [PATCH 2/4] remove unnecessary copies when only one handler matches. This was taking up ~ 15% of CPU on moderate load. --- sleekxmpp/basexmpp.py | 2 +- sleekxmpp/xmlstream/xmlstream.py | 39 ++++++++++++++++++-------------- 2 files changed, 23 insertions(+), 18 deletions(-) diff --git a/sleekxmpp/basexmpp.py b/sleekxmpp/basexmpp.py index 24a7c38..aa82dd0 100644 --- a/sleekxmpp/basexmpp.py +++ b/sleekxmpp/basexmpp.py @@ -246,7 +246,7 @@ class BaseXMPP(XMLStream): spec = "(RFC-%s) " % self.plugin[plugin].rfc desc = (spec, self.plugin[plugin].description) - log.debug("Loaded Plugin %s%s" , desc) + log.debug("Loaded Plugin %s" , desc) except: log.exception("Unable to load plugin: %s", plugin) diff --git a/sleekxmpp/xmlstream/xmlstream.py b/sleekxmpp/xmlstream/xmlstream.py index 7b941bf..1453a2a 100644 --- a/sleekxmpp/xmlstream/xmlstream.py +++ b/sleekxmpp/xmlstream/xmlstream.py @@ -873,20 +873,25 @@ class XMLStream(object): event queue. All event handlers will run in the same thread. """ - for handler in self.__event_handlers.get(name, []): + handlers = self.__event_handlers.get(name, []) + for handler in handlers: + #TODO: Data should not be copied, but should be read only, + # but this might break current code so it's left for future. + + out_data = copy.copy(data) if len(handlers) > 1 else data + old_exception = getattr(data, 'exception', None) if direct: try: - handler[0](copy.copy(data)) + handler[0](out_data) except Exception as e: error_msg = 'Error processing event handler: %s' log.exception(error_msg , str(handler[0])) - if hasattr(data, 'exception'): - data.exception(e) + if old_exception: + old_exception(e) else: self.exception(e) else: - self.event_queue.put(('event', handler, copy.copy(data))) - + self.event_queue.put(('event', handler, out_data)) if handler[2]: # If the handler is disposable, we will go ahead and # remove it now instead of waiting for it to be @@ -1201,17 +1206,17 @@ class XMLStream(object): # to run "in stream" will be executed immediately; the rest will # be queued. unhandled = True - for handler in self.__handlers: - if handler.match(stanza): - stanza_copy = copy.copy(stanza) - handler.prerun(stanza_copy) - self.event_queue.put(('stanza', handler, stanza_copy)) - try: - if handler.check_delete(): - self.__handlers.remove(handler) - except: - pass # not thread safe - unhandled = False + matched_handlers = filter(lambda h: h.match(stanza), self.__handlers) + for handler in matched_handlers: + stanza_copy = copy.copy(stanza) if len(matched_handlers) > 1 else stanza + handler.prerun(stanza_copy) + self.event_queue.put(('stanza', handler, stanza_copy)) + try: + if handler.check_delete(): + self.__handlers.remove(handler) + except: + pass # not thread safe + unhandled = False # Some stanzas require responses, such as Iq queries. A default # handler will be executed immediately for this case. From 2332970cf282d76cd5e2ac80e86ab987671486b4 Mon Sep 17 00:00:00 2001 From: Vijay Pandurangan Date: Sat, 19 Nov 2011 16:02:41 -0800 Subject: [PATCH 3/4] elide unnecessary copy --- sleekxmpp/xmlstream/xmlstream.py | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/sleekxmpp/xmlstream/xmlstream.py b/sleekxmpp/xmlstream/xmlstream.py index 1453a2a..dcbb8eb 100644 --- a/sleekxmpp/xmlstream/xmlstream.py +++ b/sleekxmpp/xmlstream/xmlstream.py @@ -1232,7 +1232,8 @@ class XMLStream(object): func -- The event handler to execute. args -- Arguments to the event handler. """ - orig = copy.copy(args[0]) + # this is always already copied before this is invoked + orig = args[0] try: func(*args) except Exception as e: From e3b9d5abbf8e825e6359f457b50fc51db44869ad Mon Sep 17 00:00:00 2001 From: Vijay Pandurangan Date: Sat, 19 Nov 2011 16:03:17 -0800 Subject: [PATCH 4/4] double copy --- sleekxmpp/xmlstream/xmlstream.py | 1 - 1 file changed, 1 deletion(-) diff --git a/sleekxmpp/xmlstream/xmlstream.py b/sleekxmpp/xmlstream/xmlstream.py index dcbb8eb..e437415 100644 --- a/sleekxmpp/xmlstream/xmlstream.py +++ b/sleekxmpp/xmlstream/xmlstream.py @@ -1285,7 +1285,6 @@ class XMLStream(object): self.exception(e) elif etype == 'event': func, threaded, disposable = handler - orig = copy.copy(args[0]) try: if threaded: x = threading.Thread(