#!/usr/bin/env python3
# VICIfast Research, Report 01: The Two Bottlenecks Inside a Busy VICIdial Server
# Load rig (§7.3). FOR A THROWAWAY TEST SERVER, NOT A LIVE FLOOR. Read it before you run it.
# Splits each redirect into its stages inside Asterisk by joining the VFTR lines with the optimize AGI's and the send
# child's timing lines and Asterisk's verbose log. Skips minutes 10-11 (VICIdial's hourly flush, §8.5).
# Changes the server? No.
# vftr-an.py <asterisk messages log> <screenlog> <action_send log> <from_epoch> <to_epoch>
# Splits Asterisk's handling of each answered call's Redirect into stages, joining:
#   VFT|AGI|cid|t0|conn|sel|ins|fork|man_id|channel      (agi-VDAD_local_optimize, screenlog)
#   VFT|CHILD|man_id|Redirect|st|open|banner|ver|auth|resp (AST_send_action_child, action_send log)
#   VFTR|channel|t0|lookup|hangupcheck|goto|ack            (manager.c action_redirect, messages log)
#   Executing [8369@default:1] ... AGI("channel"          (Asterisk verbose, ms)
import collections, datetime, re, sys
msgs, screen, act, lo, hi = sys.argv[1], sys.argv[2], sys.argv[3], float(sys.argv[4]), float(sys.argv[5])
ANSI = re.compile(r'\x1b\[[0-9;]*m')
V83 = re.compile(r'^\[(\d{4}-\d\d-\d\d \d\d:\d\d:\d\d\.\d{3})\].*Executing \[8369@default:1\].*AGI\("(PJSIP/loadsink-[0-9a-f]+)"')
LEFT = re.compile(r"^\[(\d{4}-\d\d-\d\d \d\d:\d\d:\d\d\.\d{3})\].*Channel (PJSIP/loadsink-[0-9a-f]+) left 'simple_bridge'")
ts = lambda s: datetime.datetime.strptime(s, '%Y-%m-%d %H:%M:%S.%f').timestamp()
vftr, at83, left = {}, {}, {}
for line in open(msgs, errors='replace'):
    if 'VFTR|' in line:
        v = line.strip().split('VFTR|', 1)[1].split('|')
        vftr.setdefault(v[0], [float(x) for x in v[1:6]])
        continue
    line = ANSI.sub('', line)
    m = V83.match(line)
    if m:
        at83.setdefault(m[2], ts(m[1])); continue
    m = LEFT.match(line)
    if m:
        left.setdefault(m[2], ts(m[1]))
agi = {}
for line in open(screen, errors='replace'):
    line = ANSI.sub('', line)
    if line.startswith('VFT|AGI|'):
        v = line.strip().split('|')
        agi[v[8]] = {'t0': float(v[3]), 'fork': float(v[7]), 'chan': v[9]}
ch = {}
for line in open(act, errors='replace'):
    if line.startswith('VFT|CHILD|'):
        v = line.strip().split('|')
        if v[3] == 'Redirect':
            ch[v[2]] = {'auth': float(v[8]), 'resp': float(v[9])}
D = collections.defaultdict(list)
n = 0
for mid, a in agi.items():
    if not (lo <= a['t0'] < hi) or datetime.datetime.fromtimestamp(a['t0']).minute in (10, 11):
        continue
    c, r = ch.get(mid), vftr.get(a['chan'])
    if not c or not r:
        continue
    n += 1
    D['1 child logged in -> Asterisk starts Redirect'].append(r[0] - c['auth'])
    D['2 channel lookup (ast_channel_get_by_name)'].append(r[1] - r[0])
    D['3 hangup check (channel lock)'].append(r[2] - r[1])
    D['4 async goto (lock + bridge after)'].append(r[3] - r[2])
    D['5 send ack'].append(r[4] - r[3])
    D['6 ack -> child reads it'].append(c['resp'] - r[4])
    if a['chan'] in left:
        D['7 goto -> channel leaves bridge'].append(left[a['chan']] - r[3])
    if a['chan'] in at83:
        D['8 goto -> 8369 runs'].append(at83[a['chan']] - r[3])
        D['TOTAL AGI start -> 8369'].append(at83[a['chan']] - a['t0'])
q = lambda a, f: round(sorted(a)[min(len(a) - 1, int(f * len(a)))] * 1000) if a else None
print(f'joined calls: {n}')
print(f"{'stage':48s} {'n':>5s} {'p50 ms':>7s} {'p95 ms':>7s} {'max ms':>7s}")
for k in sorted(D):
    v = D[k]
    print(f'{k:48s} {len(v):5d} {q(v,.5)!s:>7s} {q(v,.95)!s:>7s} {round(max(v)*1000)!s:>7s}')