From c4502377fde3c867add0c82297cbb05b2f0c9da6 Mon Sep 17 00:00:00 2001 From: Max Date: Fri, 21 Dec 2018 13:36:36 +0100 Subject: [PATCH] ctrl2cgi: account wait and http times separately Save and propagate separate timestamp for HTTP request duration to distinguish between time spent waiting on connection limit availability from actual http request time. Change-Id: I14d1db5206864ac9ab7c64f96f67139113ab3fcf Related: SYS#4399 --- scripts/ctrl2cgi.py | 17 +++++++++++++---- 1 file changed, 13 insertions(+), 4 deletions(-) diff --git a/scripts/ctrl2cgi.py b/scripts/ctrl2cgi.py index 28a7c3b..3226c1d 100755 --- a/scripts/ctrl2cgi.py +++ b/scripts/ctrl2cgi.py @@ -22,7 +22,7 @@ */ """ -__version__ = "0.0.8" # bump this on every non-trivial change +__version__ = "0.0.9" # bump this on every non-trivial change import argparse, os, logging, logging.handlers, datetime import hashlib @@ -39,13 +39,22 @@ from osmopy.osmo_ipa import Ctrl # we don't support older versions of TwistedIPA module assert V(twisted_ipa_version) > V('0.4') +def log_duration(log, bid, ts, ts_http): + """ + Log human-readable duration from timestamps + """ + base = datetime.datetime.now() + delta_t = datetime.timedelta(seconds = (base - ts).total_seconds()) + delta_h = datetime.timedelta(seconds = (base - ts_http).total_seconds()) + delta_w = delta_t - delta_h + log.debug('Request for BSC %s took %s total (%s wait, %s http)' % (bid, delta_t, delta_w, delta_h)) -def handle_reply(ts, bid, f, log, resp): +def handle_reply(ts, ts_http, bid, f, log, resp): """ Reply handler: process raw CGI server response, function f to run for each command """ decoded = json.loads(resp.decode('utf-8')) - log.debug('request for BSC %s took %d seconds' % (bid, (datetime.datetime.now() - ts).total_seconds())) + log_duration(log, bid, ts, ts_http) comm_proc(decoded.get('commands'), bid, f, log) def gen_hash(params, skey): @@ -63,7 +72,7 @@ def gen_hash(params, skey): def make_async_req(ts, dst, par, f_write, f_log, tout): d = post(dst, par, timeout=tout) - d.addCallback(collect, partial(handle_reply, ts, par['bsc_id'], f_write, f_log)) # treq's collect helper is handy to get all reply content at once + d.addCallback(collect, partial(handle_reply, ts, datetime.datetime.now(), par['bsc_id'], f_write, f_log)) d.addErrback(lambda e: f_log.critical("HTTP POST error %s while trying to register BSC %s on %s (timeout %d)" % (repr(e), par['bsc_id'], dst, tout))) # handle HTTP errors return d