Track Run History and Step Timings of a Report Job

A scheduled report job that "takes about ten minutes" usually has no record of how long it actually took last Tuesday, or which part of it has been getting slower. That missing history is what turns a slow drift into a surprise: the query that took two minutes in January takes nine by June, the job finishes after the 08:00 deadline one morning, and nobody can say when it started. The fix is cheap. Time each step of the job, write one row per step per run into a small SQLite database next to the job, and once a week turn that history into a workbook that shows failures, durations and trends. This page builds the timing wrapper, the run table and the history report, including a rule that flags runs much slower than usual. It belongs to Error Handling and Logging in Excel Automation.

Prerequisites

pip install pandas openpyxl

SQLite is part of Python's standard library. The examples use a simulated report job with four steps — extract, transform, write workbook, send — so the history can be generated for three months without waiting three months.

Step 1 — A context manager that times and records each step

import sqlite3, time, uuid
from contextlib import closing, contextmanager
from datetime import datetime, timezone

DB = "job_history.sqlite"
with closing(sqlite3.connect(DB)) as con:
    con.executescript("""
CREATE TABLE IF NOT EXISTS steps (
    run_id TEXT NOT NULL, job TEXT NOT NULL, step TEXT NOT NULL,
    started_utc TEXT NOT NULL, seconds REAL NOT NULL, ok INTEGER NOT NULL,
    rows INTEGER, error TEXT);
CREATE INDEX IF NOT EXISTS steps_job_started ON steps(job, started_utc);
""")

class Run:
    def __init__(self, job, clock=None):
        self.job, self.id = job, uuid.uuid4().hex[:12]
        self.clock = clock or (lambda: datetime.now(timezone.utc))

    @contextmanager
    def step(self, name):
        started, t0 = self.clock(), time.perf_counter()
        info = {"rows": None}
        try:
            yield info
        except Exception as e:
            self._record(name, started, time.perf_counter() - t0, False, info["rows"], f"{type(e).__name__}: {e}")
            raise
        else:
            self._record(name, started, time.perf_counter() - t0, True, info["rows"], None)

    def _record(self, name, started, seconds, ok, rows, error):
        with closing(sqlite3.connect(DB)) as c, c:      # close the file, commit the insert
            c.execute("INSERT INTO steps VALUES (?,?,?,?,?,?,?,?)",
                      (self.id, self.job, name, started.isoformat(), round(seconds, 3), int(ok), rows, error))

Each step of the job is wrapped in with run.step("extract") as s:. The context manager notes the start time, measures the elapsed time with perf_counter — a monotonic clock that is not affected by the system clock being adjusted — and writes one row when the step finishes. If the step raises, the row is still written, marked as failed with the error message, and the exception carries on to whatever error handling the job already has, so timing never hides a failure. The step can also report how many rows it handled through the yielded dictionary, which makes it possible later to tell "slower because there is more data" from "slower for no reason". Each row is written in its own short transaction, so the history survives even if the job is killed halfway through.

Step 2 — Use it in the job

import pandas as pd

def report_job(send_fails=False):
    run = Run("daily-sales")
    with run.step("extract") as s:
        df = pd.DataFrame({"region": ["N", "S"] * 5000, "revenue": range(10000)})
        s["rows"] = len(df)
    with run.step("transform") as s:
        summary = df.groupby("region", as_index=False)["revenue"].sum()
        s["rows"] = len(summary)
    with run.step("write workbook"):
        summary.to_excel("daily_sales.xlsx", index=False)
    with run.step("send"):
        if send_fails:
            raise ConnectionError("SMTP server timed out")

report_job()
try:
    report_job(send_fails=True)
except ConnectionError:
    pass
with closing(sqlite3.connect(DB)) as c:
    print(pd.read_sql("SELECT run_id, step, seconds, ok, rows, error FROM steps", c).to_string(index=False))

The job itself barely changes: each logical step sits inside a with block, and that is all. The second run fails in the send step, and the table shows exactly that — three successful steps and a failed one with the error text, all under the same run id. Steps should be the parts a person would name when describing the job, usually four to eight of them; timing every function call produces a table nobody reads. For jobs that already log to a file, as in Log Python Excel Script Output to a File, the database complements the log: the log says what happened in one run, the table says how runs compare.

Step 3 — Turn the history into runs, trends and flags

with closing(sqlite3.connect(DB)) as c:
    steps = pd.read_sql("SELECT * FROM steps WHERE job = 'daily-sales'", c)
steps["started_utc"] = pd.to_datetime(steps["started_utc"], format="ISO8601", utc=True)
runs = (steps.groupby("run_id")
             .agg(started=("started_utc", "min"), seconds=("seconds", "sum"), ok=("ok", "min"))
             .sort_values("started"))
runs["minutes"] = (runs["seconds"] / 60).round(1)

# Slow-run flag: more than 3 robust deviations above the median of the previous 20 runs
med = runs["seconds"].rolling(20, min_periods=10).median().shift()
mad = (runs["seconds"] - med).abs().rolling(20, min_periods=10).median().shift()
runs["slow"] = runs["seconds"] > med + 3 * 1.4826 * mad

by_step = steps.pivot_table(index=steps["started_utc"].dt.strftime("%Y-%m").rename("month"),
                            columns="step", values="seconds", aggfunc="median").round(0)
print(f"{len(runs)} runs, {int((runs['ok'] == 0).sum())} failed, {int(runs['slow'].sum())} flagged slow")
print(runs.loc[runs["slow"], ["started", "minutes"]].to_string())
print(by_step.to_string())

Grouping the step rows by run id gives one row per run: when it started, how long it took in total and whether every step succeeded. The slow-run flag compares each run with the twenty runs before it, using the median and the median absolute deviation rather than the mean and standard deviation, so that one very slow run does not inflate the threshold for the runs after it. The monthly median per step is the most useful table of all: it shows which step is responsible when the total grows. Here extract has grown from a median of 117 seconds in June to 328 in October while the other steps are flat, and the one flagged run — 12.1 minutes on 7 September — was a one-off spike in the transform step rather than part of the trend — the data source is growing, and that step is where optimisation effort should go before the job runs into its deadline.

Step 4 — The run-history workbook

from openpyxl import load_workbook
from openpyxl.chart import LineChart, Reference
from openpyxl.styles import PatternFill

out = "daily-sales_run_history.xlsx"
sheet_runs = runs.assign(started=runs["started"].dt.tz_convert(None),
                         status=runs["ok"].map({1: "ok", 0: "FAILED"}))[["started", "minutes", "status", "slow"]]
failures = steps.loc[steps["ok"] == 0, ["run_id", "started_utc", "step", "error"]]
failures = failures.assign(started_utc=failures["started_utc"].dt.tz_convert(None))
with pd.ExcelWriter(out, engine="openpyxl") as xw:
    sheet_runs.to_excel(xw, sheet_name="Runs")
    by_step.to_excel(xw, sheet_name="Median by step")
    failures.to_excel(xw, sheet_name="Failures", index=False)

wb = load_workbook(out)
ws = wb["Runs"]
red = PatternFill("solid", fgColor="F8CBAD")
for row in ws.iter_rows(min_row=2):
    if row[3].value == "FAILED" or row[4].value is True:
        for cell in row:
            cell.fill = red
chart = LineChart()
chart.title, chart.height, chart.width = "Run time (minutes)", 7, 18
chart.add_data(Reference(ws, min_col=3, min_row=1, max_row=ws.max_row), titles_from_data=True)
chart.set_categories(Reference(ws, min_col=2, min_row=2, max_row=ws.max_row))
chart.x_axis.number_format, chart.x_axis.delete, chart.y_axis.delete = "dd mmm", False, False
ws.add_chart(chart, "G2")
wb.save(out)
print(wb.sheetnames, "| failures:", len(failures), "| latest run:", sheet_runs["minutes"].iloc[-1], "min")

The workbook has three sheets. Runs lists every run with its start time, duration, status and slow flag, with failed and slow runs highlighted, and a line chart of run time beside it — the upward slope is obvious at a glance in a way that a list of numbers is not. Median by step is the monthly table from step 3. Failures lists each failed step with its error message, which is usually enough to see whether failures are random (a mail server timing out now and then) or have a pattern (every Monday, every month end). Time zones are removed before writing because Excel cannot store them; the times stay in UTC, which the column header should say if readers are in other zones.

What to do with the history

The history pays for itself in three ways. First, it predicts trouble: if the run time grows by a fixed amount each week, a simple straight line fitted to recent runs says when the job will cross its deadline, which is a much better conversation to have in July than on the morning in October when the report is late. Second, it points at the cause: the step table shows which step grew, and the row counts recorded with it show whether the growth is explained by more data or is a genuine slowdown. Third, it gives honest answers to questions like "how reliable is this job?" — three failed runs out of ninety is a reliability of about 97%, all three in the send step, which tells you to look at the mail server, not at the report code.

Keep the database small: a row per step per run is a few hundred bytes, so even several jobs running daily for years stay well under a few megabytes. Delete rows older than a year or two if you want, but the long history is often the most interesting part.

Common pitfalls

• Timing with time.time(). Use perf_counter; the wall clock can jump.
• Losing the record of failed steps. Write the row in the except branch, then re-raise.
• Averages for the slow flag. One huge run distorts a mean; use median and MAD.
• Timing every function. Time the four to eight steps a person would name.
• Unclosed connections. with sqlite3.connect() commits but does not close; wrap it in closing().

Conclusion

To understand how a report job behaves over time, wrap each step in a context manager that measures it with perf_counter and writes one row to SQLite, recording failures before re-raising them. Group the rows into runs, flag runs far above the recent median, take monthly medians per step to see which part is growing, and write a run-history workbook with a duration chart and a list of failures.

Frequently asked questions

How do I time each step of a Python script? Wrap each step in a context manager that records time.perf_counter() before and after and stores the difference, including when the step raises.

Where should I store job run history? A small SQLite file next to the job is enough: it needs no server, survives crashes because each row is committed, and pandas can read it directly.

How do I detect a run that was unusually slow? Compare its duration with the median of recent runs and flag it when it exceeds the median by more than about three robust standard deviations (1.4826 × MAD).

Why does sqlite3's with statement not close the connection? The connection's context manager commits or rolls back the transaction but leaves the connection open; use contextlib.closing to close it.

Related

• Up one level: Error Handling and Logging in Excel Automation — robust report jobs.
• Detect a Scheduled Report That Did Not Run — when there is no run at all.
• Retry a Failed Excel Report Job in Python — retrying failed steps.
• Send an Alert When an Excel Report Job Fails — alerting on failures.