# HG changeset patch # User David Douard # Date 1430753863 -7200 # Node ID ee21c559f94fcee4e8ecf0876bde566943cf4454 # Parent 62251bfdfd7977836d7a07f5f2f84894740044d9 implement a simple statsd logger (closes #5488711) and add a few timing probes on: - etwist.server.CubicWebRootResource.render_request() - server.querier.QuerierHelper.execute() - server.sources.native.NativeSQLSource: - sqlexec() - compile_rql() - authenticate() - doexec() - doexecmany() as well as a pair of counters on server.querier.QuerierHelper cache (hit/miss). diff -r 62251bfdfd79 -r ee21c559f94f cwconfig.py --- a/cwconfig.py Wed Jul 01 21:00:13 2015 +0200 +++ b/cwconfig.py Mon May 04 17:37:43 2015 +0200 @@ -843,6 +843,13 @@ 'help': 'file where output logs should be written', 'group': 'main', 'level': 2, }), + ('statsd-endpoint', + {'type' : 'string', + 'default': '', + 'help': 'UDP address of the statsd endpoint; it must be formatted' + 'like :; disabled is unset.', + 'group': 'main', 'level': 2, + }), # email configuration ('smtp-host', {'type' : 'string', @@ -971,7 +978,7 @@ if logfile.endswith('.log'): logfile = logfile[:-4] return logfile + '.stats' - + def default_pid_file(self): """return default path to the pid file of the instance'server""" if self.mode == 'system': @@ -1121,6 +1128,17 @@ logconfig = join(self.apphome, 'logging.conf') if exists(logconfig): logging.config.fileConfig(logconfig) + # set the statsd address, if any + if self.get('statsd-endpoint'): + try: + address, port = self.get('statsd-endpoint').split(':') + port = int(port) + except: + self.error('statsd-endpoint: invalid address format ({}); ' + 'it should be "ip:port"'.format(self.get('statsd-endpoint'))) + else: + import statsd_logger + statsd_logger.setup('cubicweb.%s' % self.appid, (address, port)) def available_languages(self, *args): """return available translation for an instance, by looking for diff -r 62251bfdfd79 -r ee21c559f94f etwist/server.py --- a/etwist/server.py Wed Jul 01 21:00:13 2015 +0200 +++ b/etwist/server.py Mon May 04 17:37:43 2015 +0200 @@ -24,6 +24,7 @@ import threading from urlparse import urlsplit, urlunsplit from cgi import FieldStorage, parse_header +from cubicweb.statsd_logger import statsd_timeit from twisted.internet import reactor, task, threads from twisted.web import http, server @@ -103,6 +104,7 @@ deferred = threads.deferToThread(self.render_request, request) return NOT_DONE_YET + @statsd_timeit def render_request(self, request): try: # processing HUGE files (hundred of megabytes) in http.processReceived diff -r 62251bfdfd79 -r ee21c559f94f server/querier.py --- a/server/querier.py Wed Jul 01 21:00:13 2015 +0200 +++ b/server/querier.py Mon May 04 17:37:43 2015 +0200 @@ -37,6 +37,7 @@ from cubicweb.server.ssplanner import READ_ONLY_RTYPES, add_types_restriction from cubicweb.server.edition import EditedEntity from cubicweb.server.ssplanner import SSPlanner +from cubicweb.statsd_logger import statsd_timeit, statsd_c ETYPE_PYOBJ_MAP[Binary] = 'Bytes' @@ -516,6 +517,7 @@ return InsertPlan(self, rqlst, args, cnx) return ExecutionPlan(self, rqlst, args, cnx) + @statsd_timeit def execute(self, cnx, rql, args=None, build_descr=True): """execute a rql query, return resulting rows and their description in a `ResultSet` object @@ -558,8 +560,10 @@ return empty_rset(rql, args) rqlst = self._rql_cache[cachekey] self.cache_hit += 1 + statsd_c('cache_hit') except KeyError: self.cache_miss += 1 + statsd_c('cache_miss') rqlst = self.parse(rql) try: # compute solutions for rqlst and return named args in query diff -r 62251bfdfd79 -r ee21c559f94f server/sources/native.py --- a/server/sources/native.py Wed Jul 01 21:00:13 2015 +0200 +++ b/server/sources/native.py Mon May 04 17:37:43 2015 +0200 @@ -60,6 +60,7 @@ from cubicweb.server.edition import EditedEntity from cubicweb.server.sources import AbstractSource, dbg_st_search, dbg_results from cubicweb.server.sources.rql2sql import SQLGenerator +from cubicweb.statsd_logger import statsd_timeit ATTR_MAP = {} @@ -376,6 +377,7 @@ self._cache.pop('Any X WHERE X eid %s' % eid, None) self._cache.pop('Any %s' % eid, None) + @statsd_timeit def sqlexec(self, cnx, sql, args=None): """execute the query and return its result""" return self.process_result(self.doexec(cnx, sql, args)) @@ -480,6 +482,7 @@ # ISource interface ####################################################### + @statsd_timeit def compile_rql(self, rql, sols): rqlst = self.repo.vreg.rqlhelper.parse(rql) rqlst.restricted_vars = () @@ -517,6 +520,7 @@ # can't claim not supporting a relation return True #not rtype == 'content_for' + @statsd_timeit def authenticate(self, cnx, login, **kwargs): """return CWUser eid for the given login and other authentication information found in kwargs, else raise `AuthenticationError` @@ -687,6 +691,7 @@ sql = self.sqlgen.delete('%s_relation' % rtype, attrs) self.doexec(cnx, sql, attrs) + @statsd_timeit def doexec(self, cnx, query, args=None, rollback=True): """Execute a query. it's a function just so that it shows up in profiling @@ -746,6 +751,7 @@ raise return cursor + @statsd_timeit def doexecmany(self, cnx, query, args): """Execute a query. it's a function just so that it shows up in profiling diff -r 62251bfdfd79 -r ee21c559f94f statsd_logger.py --- /dev/null Thu Jan 01 00:00:00 1970 +0000 +++ b/statsd_logger.py Mon May 04 17:37:43 2015 +0200 @@ -0,0 +1,126 @@ +# copyright 2015 LOGILAB S.A. (Paris, FRANCE), all rights reserved. +# contact http://www.logilab.fr/ -- mailto:contact@logilab.fr +# +# This file is part of CubicWeb. +# +# CubicWeb is free software: you can redistribute it and/or modify it under the +# terms of the GNU Lesser General Public License as published by the Free +# Software Foundation, either version 2.1 of the License, or (at your option) +# any later version. +# +# CubicWeb is distributed in the hope that it will be useful, but WITHOUT +# ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or FITNESS +# FOR A PARTICULAR PURPOSE. See the GNU Lesser General Public License for more +# details. +# +# You should have received a copy of the GNU Lesser General Public License along +# with CubicWeb. If not, see . + +"""Simple statsd_ logger for cubicweb. + +This module is meant to be configured by setting a couple of global variables: + +- ``bucket`` global variable will be used as statsd bucket in every +statsd_ UDP sent packet. + +`- `address`` is a pair (IP, port) specifying the address of the +statsd_ server + + +There are 3 kinds of statds_ message:: + +- ``statsd_c(context, n)`` is a simple function to send statsd_ + counter-type of messages like:: + + .:|c\n + +- ``statsd_g(context, value)`` to send statsd_ gauge-type of messages + like:: + + .:|g\n + +- ``statsd_t(context, ms)`` to send statsd_ time-type of messages + like:: + + .:|ms\n + +There is also a decorator (``statsd_timeit``) that may be used to +measure and send to the statsd_ server the time passed in a function +or a method and the number of calls. It will send a message like:: + + .:|ms\n.:1|c\n + + +.. _statsd: https://github.com/etsy/statsd + +""" + +__docformat__ = "restructuredtext en" + +import time +import socket + +_bucket = 'cubicweb' +_address = None +_socket = None + + +def setup(bucket, address): + """Configure the statsd endpoint + + :param bucket: the name of the statsd bucket that will be used to + build messages. + + :param address: the UDP endpoint of the statsd server. Must a + couple (ip, port). + """ + global _bucket, _address, _socket + _bucket, _address = bucket, address + _socket = socket.socket(socket.AF_INET, socket.SOCK_DGRAM) + + +def statsd_c(context, n=1): + if _address is not None: + _socket.sendto('{0}.{1}:{2}|c\n'.format(_bucket, context, n), _address) + + +def statsd_g(context, value): + if _address is not None: + _socket.sendto('{0}.{1}:{2}|g\n'.format(_bucket, context, value), _address) + + +def statsd_t(context, value): + if _address is not None: + _socket.sendto('{0}.{1}:{2:.4f}|ms\n'.format(_bucket, context, value), _address) + + +class statsd_timeit(object): + __slots__ = ('callable',) + + def __init__(self, callableobj): + self.callable = callableobj + + @property + def __doc__(self): + return self.callable.__doc__ + @property + def __name__(self): + return self.callable.__name__ + + def __call__(self, *args, **kw): + if _address is None: + return self.callable(*args, **kw) + t0 = time.time() + try: + return self.callable(*args, **kw) + finally: + dt = 1000*(time.time()-t0) + msg = '{0}.{1}:{2:.4f}|ms\n{0}.{1}:1|c\n'.format(_bucket, self.__name__, dt) + _socket.sendto(msg, _address) + + def __get__(self, obj, objtype): + """Support instance methods.""" + if obj is None: # class method or some already wrapped method + return self + import functools + return functools.partial(self.__call__, obj)