HH-22544 implement profiler embedded in frontik

debian/install

@@ -1,2 +1,3 @@
 production/frontik.cfg /etc/frontik
 frontik/debug.xsl /usr/lib/frontik/
+frontik/profiler.xsl /usr/lib/frontik/

frontik/debug.xsl

@@ -275,6 +275,7 @@
 
     <xsl:template match="log" mode="css">
         <style>
+            body { margin: 0 10px; }
             body, pre{
                 font-family:Arial;
             }

frontik/frontik_logging.py

@@ -1,9 +1,11 @@
 # -*- coding: utf-8 -*-
-import json
+from collections import namedtuple
 import logging
 from logging.handlers import SysLogHandler
 import weakref
 import time
+from lxml import etree
+from lxml.builder import E
 import tornado.options
 
 log = logging.getLogger('frontik.handler')
@@ -58,47 +60,54 @@ def format(self, record):
 
 
 class PageLogger(logging.LoggerAdapter):
-    def __init__(self, handler, logger_name, page, zero_time):
+
+    Stage = namedtuple('Stage', ['name', 'start', 'delta'])
+
+    def __init__(self, handler, logger_name, page):
 
         class Logger4Adapter(logging.Logger):
             def handle(self, record):
                 logging.Logger.handle(self, record)
                 log.handle(record)
 
         self.handler_ref = weakref.ref(handler)
+        self.handler_started = self.handler_ref().handler_started
         logging.LoggerAdapter.__init__(self, Logger4Adapter('frontik.handler'),
             dict(request_id=logger_name, page=page, handler=self.handler_ref().__module__))
 
-        self._time = zero_time
+        self._time = self.handler_started
         self.stages = []
         self.page = page
-        #backcompatibility with logger
+        # backcompatibility with logger
         self.warn = self.warning
         self.addHandler = self.logger.addHandler
 
-    def stage_tag(self, stage):
-        self._stage_tag(stage, (time.time() - self._time) * 1000)
+    def stage_tag(self, stage_name):
+        zero_time = self.handler_started
+        self._stage_tag(PageLogger.Stage(stage_name, self._time - zero_time, time.time() - self._time))
         self._time = time.time()
-        self.debug('Stage: {stage}'.format(stage=stage))
-
-    def _stage_tag(self, stage, time_delta):
-        self.stages.append((stage, time_delta))
+        self.debug('Stage: {stage}'.format(stage=stage_name))
 
-    def stage_tag_backdate(self, stage, time_delta):
-        self._stage_tag(stage, time_delta)
+    def _stage_tag(self, stage):
+        self.stages.append(stage)
 
     def process_stages(self, status_code):
-        self._stage_tag('total', (time.time() - self.handler_ref().handler_started) * 1000)
+        self._stage_tag(PageLogger.Stage('total', 0, time.time() - self.handler_started))
 
-        stages_format = ' '.join(['{0}:{1:.2f}ms'.format(k, v) for k, v in self.stages])
-        stages_monik_format = ' '.join(['{0}={1:.2f}'.format(k, v) for k, v in self.stages])
+        format_f = lambda x: ' '.join([x.format(name=s.name, delta=1000*s.delta) for s in self.stages])
+        stages_format = format_f('{name}:{delta:.2f}ms')
+        stages_monik_format = format_f('{name}={delta:.2f}')
 
         self.debug('Stages for {0} : {1}'.format(self.page, stages_format))
         self.info('Monik-stages {0!r} : {1} code={2}'.format(self.handler_ref(), stages_monik_format, status_code),
             extra={'_monik': True})
 
-    def stages_to_json(self):
-        return json.dumps(self.stages).replace('"', '\'')
+    def stages_to_xml(self):
+        round_f = lambda x: '%.2f' % round(1000 * x, 2)
+        stages = etree.Element('stages')
+        for stage in self.stages:
+            stages.append(E.stage(name=stage.name, start=round_f(stage.start), delta=round_f(stage.delta)))
+        return stages
 
     def process(self, msg, kwargs):
         if "extra" in kwargs:

frontik/handler.py

@@ -23,7 +23,7 @@
 import frontik.jobs
 import frontik.handler_xml
 import frontik.handler_whc_limit
-import frontik.handler_xml_debug
+import frontik.handler_debug
 import frontik.future as future
 
 def _parse_response_smth(response, logger = frontik_logging.log, parser=None, type=None):
@@ -113,7 +113,7 @@ def __init__(self, application, request, ph_globals=None, **kwargs):
         self.name = self.__class__.__name__
         self.request_id = request.headers.get('X-Request-Id', str(stats.next_request_id()))
         logger_name = '.'.join(filter(None, [self.request_id, getattr(ph_globals.config, 'app_name', None)]))
-        self.log = frontik_logging.PageLogger(self, logger_name, request.path or request.uri, self.handler_started)
+        self.log = frontik_logging.PageLogger(self, logger_name, request.path or request.uri)
 
         tornado.web.RequestHandler.__init__(self, application, request, logger = self.log, **kwargs)
 
@@ -130,7 +130,7 @@ def __repr__(self):
 
     def prepare(self):
         self.whc_limit = frontik.handler_whc_limit.PageHandlerWHCLimit(self)
-        self.debug = frontik.handler_xml_debug.PageHandlerDebug(self)
+        self.debug = frontik.handler_debug.PageHandlerDebug(self)
         self.log.info('page module: %s', self.__module__)
 
         self.xml = frontik.handler_xml.PageHandlerXML(self)
@@ -163,7 +163,7 @@ def require_debug_access(self, login = None, passwd = None):
                 raise HTTPError(401, headers={'WWW-Authenticate': 'Basic realm="Secure Area"'})
 
     def get_error_html(self, status_code, **kwargs):
-        if self._prepared and self.debug.debug_mode.logging:
+        if self._prepared and self.debug.debug_mode.write_debug:
             debug_is_finished = not self.debug.debug_mode.inherited
             return self.debug.get_debug_page(status_code, self._headers, finish_debug=debug_is_finished)
         else:
@@ -248,15 +248,20 @@ def finish(self, chunk = None):
                 self.set_header('Content-Type', 'text/html')
 
             res = self.debug.get_debug_page(self._status_code, response_headers, original_response)
+            self._write_buffer = []
             self._status_code = 200
-
-        elif hasattr(self, 'debug') and self.debug.debug_mode.profile:
-            buffer = ''.join(self._write_buffer) + (chunk if chunk is not None else '')
-            res = buffer.replace("'%PROFILER_STAGES%'", self.log.stages_to_json())
-
         else:
             res = chunk
 
+        if hasattr(self, 'debug') and self.debug.debug_mode.profile:
+            profiler_document = self.debug.get_profiler_template()
+            if profiler_document is not None:
+                match = tornado.options.options.debug_profiler_tag
+                buffer = ''.join(self._write_buffer) + (res if res is not None else '')
+                res = buffer.replace(match, profiler_document)
+                self._write_buffer = []
+                self.log.debug('Profiler component added before %s tag' % match)
+
         tornado.web.RequestHandler.finish(self, res)
 
     def get_page(self):

frontik/handler_xml_debug.py → frontik/handler_debug.py

@@ -175,31 +175,36 @@ class PageHandlerDebug(object):
 
     class DebugMode(object):
         def __init__(self, handler):
-            debug_param = frontik.util.get_cookie_or_url_param_value(handler, 'debug')
+            debug_value = frontik.util.get_cookie_or_url_param_value(handler, 'debug')
+            debug_params = None if debug_value is None else debug_value.split(',')
+            has_debug_enable_param = debug_params is not None and filter(lambda x: x != 'profile', debug_params)
+
             self.inherited = handler.request.headers.get(frontik.handler.PageHandler.INHERIT_DEBUG_HEADER_NAME)
-            self.profile = debug_param == 'profile'
+            self.profile = debug_params is not None and 'profile' in debug_params
 
-            if (debug_param is not None or self.inherited) and not self.profile:
+            if has_debug_enable_param or self.inherited:
                 self.enabled = True
-                self.return_response = debug_param == 'pass' or self.inherited
+                self.return_response = (debug_params is not None and 'pass' in debug_params) or self.inherited
                 self.pass_further = self.return_response
             else:
                 self.enabled = False
                 self.return_response = False
                 self.pass_further = False
 
-            self.logging = tornado.options.options.debug or self.enabled
+            self.write_debug = tornado.options.options.debug or self.enabled or self.profile
 
 
     def __init__(self, handler):
         self.handler = weakref.proxy(handler)
         self.debug_mode = PageHandlerDebug.DebugMode(self.handler)
 
+        if self.debug_mode.enabled or self.debug_mode.profile:
+            self.handler.require_debug_access()
+
         if self.debug_mode.enabled:
-            handler.require_debug_access()
-            handler.log.debug('debug mode is on')
+            self.handler.log.debug('debug mode is on')
 
-        if self.debug_mode.logging:
+        if self.debug_mode.write_debug:
             self.debug_log_handler = DebugPageHandler()
             self.handler.log.addHandler(self.debug_log_handler)
             self.handler.log.debug('using debug mode logging')
@@ -210,6 +215,26 @@ def __init__(self, handler):
         if self.debug_mode.return_response:
             self.handler.log.debug('debug mode will be passed to all frontik apps requested (debug=pass)')
 
+        if self.debug_mode.profile:
+            self.profiler_options = {
+                'warning-value': tornado.options.options.debug_profiler_warning_value,
+                'critical-value': tornado.options.options.debug_profiler_critical_value
+            }
+
+    def get_profiler_template(self):
+        try:
+            with open(tornado.options.options.debug_profiler_xsl) as xsl_file:
+                tranform = etree.XSLT(etree.XML(xsl_file.read()))
+
+            profiler_xml = etree.Element('profiler')
+            profiler_xml.append(self.handler.log.stages_to_xml())
+            profiler_xml.append(frontik.xml_util.dict_to_xml(self.profiler_options, 'options'))
+            return str(tranform(profiler_xml))
+
+        except Exception, e:
+            self.handler.log.exception('XSLT profiler file error')
+            return None
+
     def get_debug_page(self, status_code, response_headers, original_response=None, finish_debug=True):
         if finish_debug:
             debug_log_data = self.debug_log_handler.log_data
@@ -239,9 +264,8 @@ def get_debug_page(self, status_code, response_headers, original_response=None,
         can_apply_xsl_or_500 = self.handler.xml.apply_xsl or not self.debug_mode.enabled
         if can_apply_xsl_or_500 and not self.debug_mode.inherited:
             try:
-                xsl_file = open(tornado.options.options.debug_xsl)
-                tranform = etree.XSLT(etree.XML(xsl_file.read()))
-                xsl_file.close()
+                with open(tornado.options.options.debug_xsl) as xsl_file:
+                    tranform = etree.XSLT(etree.XML(xsl_file.read()))
                 log_document = str(tranform(debug_log_data))
                 self.handler.set_header('Content-Type', 'text/html; charset=UTF-8')
             except Exception, e:

frontik/options.py

@@ -17,6 +17,11 @@
 tornado.options.define('debug_password', None, str)
 tornado.options.define('debug_xsl', '/usr/lib/frontik/debug.xsl', str)
 
+tornado.options.define('debug_profiler_tag', '</body>', str)
+tornado.options.define('debug_profiler_xsl', '/usr/lib/frontik/profiler.xsl', str)
+tornado.options.define('debug_profiler_warning_value', 200, int)
+tornado.options.define('debug_profiler_critical_value', 500, int)
+
 tornado.options.define('timeout_multiplier', 1.0, float)
 
 tornado.options.define('executor_pool_size', 1, int)