teems/plot_traces

#!/usr/bin/env python3

# Plot the network traces output when TRACE_SOCKIO is set to 1
# ("make TRACE_SOCKIO=1" to build in this configuration)

# Args: log_directory

# Outputs trace.tex (and the files pdflatex builds, including the target
# trace.pdf) into the log directory


import glob
import math
import os
import re
import sys

if len(sys.argv) != 2:
    print(f"Usage: {sys.argv[0]} log_directory", file=sys.stderr)
    sys.exit(1)

# This will throw an exception if the directory does not exist
os.chdir(sys.argv[1])

nodelogs = glob.glob("s*.log")
nodelogs.sort(key=lambda filename : int(filename[1:-4]))

# Pass 1: For each sender and receiver, make a list of each message
# queued from that sender to receiver, noting its queue start time,
# queue end time, size, and type.  Also gather all timestamp labels for
# each node

queued_messages = {}
labels = {}
min_ts = None
max_ts = None

for nodelog in nodelogs:
    node = nodelog[:-4]
    labels[node] = []
    with open(nodelog) as logf:
        queueing = {}
        for logline in logf:
            logline = logline.rstrip()
            if matches := re.match(
                    r'(\d+\.\d+): RTE queueing (\d+) bytes to (\S+)',
                    logline):
                [ts, size, recv] = matches.groups()
                assert(recv not in queueing)
                tsf = float(ts)
                queueing[recv] = \
                    { 'queue_start': tsf, 'size': size }
                if min_ts is None or min_ts > tsf:
                    min_ts = tsf
            elif matches := re.match(
                    r'(\d+\.\d+): RTE queued (\d+) bytes to (\S+)',
                    logline):
                [ts, size, recv] = matches.groups()
                assert(recv in queueing)
                assert(queueing[recv]['size'] == size)
                if (node, recv) not in queued_messages:
                    queued_messages[(node, recv)] = []
                msg = {
                    'queue_start': queueing[recv]['queue_start'],
                    'queue_end': float(ts),
                    'size': size,
                    'type': 'RTE',
                }
                queued_messages[(node, recv)].append(msg)
                del queueing[recv]
            elif matches := re.match(
                    r'(\d+\.\d+): Epoch \d+ (start|complete)',
                    logline):
                [ts, typ] = matches.groups()
                tsf = float(ts)
                if typ == 'start':
                    typ = 'S'
                elif typ == 'complete':
                    typ = 'F'
                labels[node].append((tsf, typ))
                if min_ts is None or min_ts > tsf:
                    min_ts = tsf
                if max_ts is None or max_ts < tsf:
                    max_ts = tsf
            elif matches := re.match(
                    r'(\d+\.\d+): Round (.*) complete',
                    logline):
                [ts, rnd] = matches.groups()
                tsf = float(ts)
                if rnd == '11':
                    rnd = 'A'
                elif rnd == '12':
                    rnd = 'B'
                elif rnd == '13':
                    rnd = 'C'
                labels[node].append((tsf, rnd))
                if max_ts is None or max_ts < tsf:
                    max_ts = tsf
            elif matches := re.match(
                    r'(\d+\.\d+): (Begin|End) Waksman networks precompute',
                    logline):
                [ts, typ] = matches.groups()
                tsf = float(ts)
                if typ == 'Begin':
                    typ = 'P'
                elif typ == 'End':
                    typ = 'W'
                labels[node].append((tsf, typ))
                if min_ts is None or min_ts > tsf:
                    min_ts = tsf
                if max_ts is None or max_ts < tsf:
                    max_ts = tsf
            elif matches := re.match(
                    r'(\d+\.\d+): Begin ingestion',
                    logline):
                [ts] = matches.groups()
                tsf = float(ts)
                labels[node].append((tsf, 'i'))
                if max_ts is None or max_ts < tsf:
                    max_ts = tsf
            elif matches := re.match(
                    r'(\d+\.\d+): End ingestion of \d+ messages',
                    logline):
                [ts] = matches.groups()
                tsf = float(ts)
                labels[node].append((tsf, 'I'))
                if max_ts is None or max_ts < tsf:
                    max_ts = tsf

# Pass 2: For each sender and receiver, note the receive start time and
# receive end time for each message in the queued_messages list

messages = {}

for nodelog in nodelogs:
    node = nodelog[:-4]
    with open(nodelog) as logf:
        receiving = {}
        for logline in logf:
            logline = logline.rstrip()
            if matches := re.match(
                    r'(\d+\.\d+): RTE receiving (\d+) bytes from (\S+)',
                    logline):
                [ts, size, snd] = matches.groups()
                assert(snd not in receiving)
                receiving[snd] = \
                    { 'recv_start': float(ts), 'size': size }
            elif matches := re.match(
                    r'(\d+\.\d+): RTE received (\d+) bytes from (\S+)',
                    logline):
                [ts, size, snd] = matches.groups()
                assert(snd in receiving)
                assert(receiving[snd]['size'] == size)
                assert(queued_messages[(snd, node)][0]['size'] == size)
                tsf = float(ts)
                if (snd, node) not in messages:
                    messages[(snd, node)] = []
                msg = queued_messages[(snd, node)].pop(0)
                msg['recv_start'] = receiving[snd]['recv_start']
                msg['recv_end'] = tsf
                if max_ts is None or max_ts < tsf:
                    max_ts = tsf
                messages[(snd, node)].append(msg)
                del receiving[snd]

# Write a latex file that draws the messages

# ((max_ts-min_ts)*timescale) must be at most 570

# Timescale (cm per second)
timescale = min(570/(max_ts-min_ts), 2)

# Nodescale (cm between nodes)
nodescale = 1

# Seconds between time label ticks
time_tick = math.ceil(1/timescale)

with open("trace.tex", "w") as tf:
    print(r'''\documentclass{article}
\usepackage[paperwidth=%fcm,paperheight=%fcm,margin=1cm]{geometry}
\usepackage{tikz}
\usepackage{times}
\setlength\parindent{0pt}
\pagestyle{empty}
\begin{document}
\begin{tikzpicture}''' % (((max_ts-min_ts)*timescale)+2.5,
        (len(nodelogs)+1)*nodescale+2.5), file=tf)

    nodenum = 0
    nodepos = {}

    print(r'''\draw[thick] (0,0) -- ++(%lf,0);''' %
        ((max_ts-min_ts)*timescale), file=tf)
    ts=0
    while ts<(max_ts-min_ts):
        print(r'''\draw [thick] (%lf,.1) node [anchor=south] { %s } -- ++(0,-.1);''' %
            (ts*timescale, str(ts)), file=tf)
        ts+=time_tick

    for nodelog in nodelogs:
        node = nodelog[:-4]
        nodenum += 1
        nodepos[node] = -nodenum * nodescale
        print(r'''\node [anchor=east] at (0,%lf) { %s };
\draw[thick] (0,%lf) -- ++(%lf,0);''' %
            (nodepos[node], node, nodepos[node],
            (max_ts-min_ts)*timescale), file=tf)

    for (snd,recv) in messages:
        for msg in messages[(snd,recv)]:
            print(r'''%% %s %s %s %lf %lf %lf %lf''' % (snd, recv,
                msg['size'], msg['queue_start'], msg['queue_end'],
                msg['recv_start'], msg['recv_end']), file=tf)
            print(r'''\fill [fill=%s,fill opacity=.2] (%lf,%lf) --
            (%lf,%lf) -- (%lf,%lf) -- (%lf,%lf) -- cycle;''' %
                ('black',
                (msg['queue_start']-min_ts)*timescale, nodepos[snd],
                (msg['queue_end']-min_ts)*timescale, nodepos[snd],
                (msg['recv_end']-min_ts)*timescale, nodepos[recv],
                (msg['recv_start']-min_ts)*timescale, nodepos[recv]),
                file=tf)

    for node in labels:
        for (ts,label) in labels[node]:
            print(r'''%% %lf''' % ts, file=tf)
            print(r'''\draw [thick] (%lf,%lf) node [anchor=south] { %s } -- ++(0,-.1);''' %
                ((ts-min_ts)*timescale, nodepos[node]+.1, label),
                file=tf)

    print(r'''\end{tikzpicture}
\end{document}''', file=tf)

os.system("pdflatex trace")