core: added more accurate time measurements

configs/gunicorn_config.py

@@ -1,154 +1,154 b''
 """
 gunicorn config extension and hooks. Sets additional configuration that is
 available post the .ini config.
 
 - workers = ${cpu_number}
 - threads = 1
 - proc_name = ${gunicorn_proc_name}
 - worker_class = sync
 - worker_connections = 10
 - max_requests = 1000
 - max_requests_jitter = 30
 - timeout = 21600
 
 """
 
 import multiprocessing
 import sys
 import time
 import datetime
 import threading
 import traceback
 from gunicorn.glogging import Logger
 
 
 # GLOBAL
 errorlog = '-'
 accesslog = '-'
 loglevel = 'debug'
 
 # SECURITY
 
 # The maximum size of HTTP request line in bytes.
 # 0 for unlimited
 limit_request_line = 0
 
 # Limit the number of HTTP headers fields in a request.
 # By default this value is 100 and can’t be larger than 32768.
 limit_request_fields = 10240
 
 # Limit the allowed size of an HTTP request header field.
 # Value is a positive number or 0.
 # Setting it to 0 will allow unlimited header field sizes.
 limit_request_field_size = 0
 
 
 # Timeout for graceful workers restart.
 # After receiving a restart signal, workers have this much time to finish
 # serving requests. Workers still alive after the timeout (starting from the
 # receipt of the restart signal) are force killed.
 graceful_timeout = 30
 
 
 # The number of seconds to wait for requests on a Keep-Alive connection.
 # Generally set in the 1-5 seconds range.
 keepalive = 2
 
 
 # SERVER MECHANICS
 # None == system temp dir
 # worker_tmp_dir is recommended to be set to some tmpfs
 worker_tmp_dir = None
 tmp_upload_dir = None
 
 # Custom log format
 access_log_format = (
     '%(t)s [%(p)-8s] GNCRN %(h)-15s rqt:%(L)s %(s)s %(b)-6s "%(m)s:%(U)s %(q)s" usr:%(u)s "%(f)s" "%(a)s"')
 
 # self adjust workers based on CPU count
 # workers = multiprocessing.cpu_count() * 2 + 1
 
 
 def post_fork(server, worker):
     server.log.info("[<%-10s>] WORKER spawned", worker.pid)
 
 
 def pre_fork(server, worker):
     pass
 
 
 def pre_exec(server):
     server.log.info("Forked child, re-executing.")
 
 
 def on_starting(server):
     server.log.info("Server is starting.")
 
 
 def when_ready(server):
     server.log.info("Server is ready. Spawning workers")
 
 
 def on_reload(server):
     pass
 
 
 def worker_int(worker):
     worker.log.info("[<%-10s>] worker received INT or QUIT signal", worker.pid)
 
     # get traceback info, on worker crash
     id2name = dict([(th.ident, th.name) for th in threading.enumerate()])
     code = []
     for thread_id, stack in sys._current_frames().items():
         code.append(
             "\n# Thread: %s(%d)" % (id2name.get(thread_id, ""), thread_id))
         for fname, lineno, name, line in traceback.extract_stack(stack):
             code.append('File: "%s", line %d, in %s' % (fname, lineno, name))
             if line:
                 code.append("  %s" % (line.strip()))
     worker.log.debug("\n".join(code))
 
 
 def worker_abort(worker):
     worker.log.info("[<%-10s>] worker received SIGABRT signal", worker.pid)
 
 
 def worker_exit(server, worker):
     worker.log.info("[<%-10s>] worker exit", worker.pid)
 
 
 def child_exit(server, worker):
     worker.log.info("[<%-10s>] worker child exit", worker.pid)
 
 
 def pre_request(worker, req):
     worker.start_time = time.time()
     worker.log.debug(
         "GNCRN PRE  WORKER [cnt:%s]: %s %s", worker.nr, req.method, req.path)
 
 
 def post_request(worker, req, environ, resp):
     total_time = time.time() - worker.start_time
     worker.log.debug(
-        "GNCRN POST WORKER [cnt:%s]: %s %s resp: %s, Load Time: %.3fs",
+        "GNCRN POST WORKER [cnt:%s]: %s %s resp: %s, Load Time: %.4fs",
         worker.nr, req.method, req.path, resp.status_code, total_time)
 
 
 class RhodeCodeLogger(Logger):
     """
     Custom Logger that allows some customization that gunicorn doesn't allow
     """
 
     datefmt = r"%Y-%m-%d %H:%M:%S"
 
     def __init__(self, cfg):
         Logger.__init__(self, cfg)
 
     def now(self):
         """ return date in RhodeCode Log format """
         now = time.time()
         msecs = int((now - long(now)) * 1000)
         return time.strftime(self.datefmt, time.localtime(now)) + '.{0:03d}'.format(msecs)
 
 
 logger_class = RhodeCodeLogger

vcsserver/tweens.py

@@ -1,58 +1,58 b''
 # RhodeCode VCSServer provides access to different vcs backends via network.
 # Copyright (C) 2014-2019 RhodeCode GmbH
 #
 # This program is free software; you can redistribute it and/or modify
 # it under the terms of the GNU General Public License as published by
 # the Free Software Foundation; either version 3 of the License, or
 # (at your option) any later version.
 #
 # This program 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 General Public License for more details.
 #
 # You should have received a copy of the GNU General Public License
 # along with this program; if not, write to the Free Software Foundation,
 # Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301  USA
 
 
 
 import time
 import logging
 
 
 from vcsserver.utils import safe_str
 
 
 log = logging.getLogger(__name__)
 
 
 def get_access_path(request):
     environ = request.environ
     return environ.get('PATH_INFO')
 
 
 class RequestWrapperTween(object):
     def __init__(self, handler, registry):
         self.handler = handler
         self.registry = registry
 
         # one-time configuration code goes here
 
     def __call__(self, request):
         start = time.time()
         try:
             response = self.handler(request)
         finally:
             end = time.time()
 
-            log.info('IP: %s Request to path: `%s` time: %.3fs',
+            log.info('IP: %s Request to path: `%s` time: %.4fs',
                      '127.0.0.1', safe_str(get_access_path(request)), end - start)
 
         return response
 
 
 def includeme(config):
     config.add_tween(
         'vcsserver.tweens.RequestWrapperTween',
     )