%% Generated by Sphinx.
\def\sphinxdocclass{report}
\documentclass[letterpaper,10pt,english]{sphinxmanual}
\ifdefined\pdfpxdimen
   \let\sphinxpxdimen\pdfpxdimen\else\newdimen\sphinxpxdimen
\fi \sphinxpxdimen=.75bp\relax
\ifdefined\pdfimageresolution
    \pdfimageresolution= \numexpr \dimexpr1in\relax/\sphinxpxdimen\relax
\fi
%% let collapsible pdf bookmarks panel have high depth per default
\PassOptionsToPackage{bookmarksdepth=5}{hyperref}

\PassOptionsToPackage{booktabs}{sphinx}
\PassOptionsToPackage{colorrows}{sphinx}

\PassOptionsToPackage{warn}{textcomp}
\usepackage[utf8]{inputenc}
\ifdefined\DeclareUnicodeCharacter
% support both utf8 and utf8x syntaxes
  \ifdefined\DeclareUnicodeCharacterAsOptional
    \def\sphinxDUC#1{\DeclareUnicodeCharacter{"#1}}
  \else
    \let\sphinxDUC\DeclareUnicodeCharacter
  \fi
  \sphinxDUC{00A0}{\nobreakspace}
  \sphinxDUC{2500}{\sphinxunichar{2500}}
  \sphinxDUC{2502}{\sphinxunichar{2502}}
  \sphinxDUC{2514}{\sphinxunichar{2514}}
  \sphinxDUC{251C}{\sphinxunichar{251C}}
  \sphinxDUC{2572}{\textbackslash}
\fi
\usepackage{cmap}
\usepackage[T1]{fontenc}
\usepackage{amsmath,amssymb,amstext}
\usepackage{babel}



\usepackage{tgtermes}
\usepackage{tgheros}
\renewcommand{\ttdefault}{txtt}



\usepackage[Bjarne]{fncychap}
\usepackage{sphinx}

\fvset{fontsize=auto}
\usepackage{geometry}


% Include hyperref last.
\usepackage{hyperref}
% Fix anchor placement for figures with captions.
\usepackage{hypcap}% it must be loaded after hyperref.
% Set up styles of URL: it should be placed after hyperref.
\urlstyle{same}

\addto\captionsenglish{\renewcommand{\contentsname}{Contents:}}

\usepackage{sphinxmessages}
\setcounter{tocdepth}{1}



\title{Parsl wide event observability prototype report}
\date{Oct 28, 2025}
\release{}
\author{Ben Clifford}
\newcommand{\sphinxlogo}{\vbox{}}
\renewcommand{\releasename}{}
\makeindex
\begin{document}

\ifdefined\shorthandoff
  \ifnum\catcode`\=\string=\active\shorthandoff{=}\fi
  \ifnum\catcode`\"=\active\shorthandoff{"}\fi
\fi

\pagestyle{empty}
\sphinxmaketitle
\pagestyle{plain}
\sphinxtableofcontents
\pagestyle{normal}
\phantomsection\label{\detokenize{index::doc}}



\chapter{Introduction}
\label{\detokenize{index:introduction}}
\sphinxAtStartPar
These are notes about my current iteration of observability.

\sphinxAtStartPar
Somewhere be clear that this is in two related parts:
\begin{itemize}
\item {} 
\sphinxAtStartPar
emitting wide records from Parsl Python code

\item {} 
\sphinxAtStartPar
ingesting and analysing records, including wide ones,
from many sources

\end{itemize}


\chapter{What is observability, in the Parsl context}
\label{\detokenize{index:what-is-observability-in-the-parsl-context}}
\sphinxAtStartPar
“Observability is a measure of how well internal states of a system can be inferred from knowledge of its external outputs.”
(\sphinxurl{https://en.wikipedia.org/wiki/Observability})

\sphinxAtStartPar
how can we tell whats going on inside a Parsl run by what we can see externally? how can we expose more “stuff”?

\sphinxAtStartPar
abstract notion, but in Parsl that is about: logging; Parsl monitoring.

\sphinxAtStartPar
and this prototype is about doing that “better”


\chapter{A motivating use case}
\label{\detokenize{index:a-motivating-use-case}}
\sphinxAtStartPar
Here’s a use case that is hard with what exists in master\sphinxhyphen{}branch Parsl right now.

\sphinxAtStartPar
I want to know, for a particular arbitrary task, the timings of the task as it is submitted by the user workflow, flows through the DFK, into the htex interchange, worker pool, executes on an htex worker, and flows back to the user, with the timing of each step.

\sphinxAtStartPar
What exists in master Parsl right now is some information in monitoring, and some information in log files. The monitoring information is focused on the high level task model, not what is happening inside Parsl to run that high level model. Logs as they exist now are extremely ad\sphinxhyphen{}hoc, spread around in at least 4 different places, and poorly integrated: for example, log messages sometimes do not contain context about which task they refer to, do not represent that context uniformly (e.g. in a greppable way) and are ambiguous about context (e.g. some places refer to task 1, the DFK\sphinxhyphen{}level task 1, and some places refer to task 1, the HTEX\sphinxhyphen{}level task 1, which could be something completely different).

\sphinxAtStartPar
As a contrast, an example output of this prototype (as of 2025\sphinxhyphen{}10\sphinxhyphen{}26) is:

\begin{sphinxVerbatim}[commandchars=\\\{\}]
=== About task 358 ===
2025\PYGZhy{}10\PYGZhy{}26 10:29:46.467298 MainThread@117098 Task 358: will be sent to executor htex\PYGZus{}Local (parsl.log)
2025\PYGZhy{}10\PYGZhy{}26 10:29:46.467412 MainThread@117098 Task 358: Adding output dependencies (parsl.log)
2025\PYGZhy{}10\PYGZhy{}26 10:29:46.467484 MainThread@117098 Task 358: Added output dependencies (parsl.log)
2025\PYGZhy{}10\PYGZhy{}26 10:29:46.467550 MainThread@117098 Task 358: Gathering dependencies: start (parsl.log)
2025\PYGZhy{}10\PYGZhy{}26 10:29:46.467620 MainThread@117098 Task 358: Gathering dependencies: end (parsl.log)
2025\PYGZhy{}10\PYGZhy{}26 10:29:46.467685 MainThread@117098 Task 358: submitted for App random\PYGZus{}uuid, not waiting on any dependency (parsl.log)
2025\PYGZhy{}10\PYGZhy{}26 10:29:46.467752 MainThread@117098 Task 358: has AppFuture: \PYGZlt{}AppFuture at 0x7f8bc1aed730 state=pending\PYGZgt{} (parsl.log)
2025\PYGZhy{}10\PYGZhy{}26 10:29:46.467818 MainThread@117098 Task 358: initializing state to pending (parsl.log)
2025\PYGZhy{}10\PYGZhy{}26 10:29:46.469992 Task\PYGZhy{}Launch\PYGZus{}0@117098 Task 358: changing state from pending to launched (parsl.log)
2025\PYGZhy{}10\PYGZhy{}26 10:29:46.470113 Task\PYGZhy{}Launch\PYGZus{}0@117098 Task 358: try 0 launched on executor htex\PYGZus{}Local with executor id 340 (parsl.log)
2025\PYGZhy{}10\PYGZhy{}26 10:29:46.470240 Task\PYGZhy{}Launch\PYGZus{}0@117098 Task 358: Standard out will not be redirected. (parsl.log)
2025\PYGZhy{}10\PYGZhy{}26 10:29:46.470310 Task\PYGZhy{}Launch\PYGZus{}0@117098 Task 358: Standard error will not be redirected. (parsl.log)
2025\PYGZhy{}10\PYGZhy{}26 10:29:46.470336 MainThread@117129 HTEX task 340: putting onto pending\PYGZus{}task\PYGZus{}queue (interchange log)
2025\PYGZhy{}10\PYGZhy{}26 10:29:46.470404 MainThread@117129 HTEX task 340: fetched task (interchange log)
2025\PYGZhy{}10\PYGZhy{}26 10:29:46.470815 Interchange\PYGZhy{}Communicator@117144 Putting HTEX task 340 into scheduler (Pool manager log)
2025\PYGZhy{}10\PYGZhy{}26 10:29:46.471166 MainThread@117162 HTEX task 340: received executor task (Pool worker log)
2025\PYGZhy{}10\PYGZhy{}26 10:29:46.492449 MainThread@117162 HTEX task 340: Completed task (Pool worker log)
2025\PYGZhy{}10\PYGZhy{}26 10:29:46.492742 MainThread@117162 HTEX task 340: All processing finished for task (Pool worker log)
2025\PYGZhy{}10\PYGZhy{}26 10:29:46.493508 MainThread@117129 HTEX task 340: Manager b\PYGZsq{}4f65802901c6\PYGZsq{}: Removing task from manager (interchange log)
2025\PYGZhy{}10\PYGZhy{}26 10:29:46.493948 HTEX\PYGZhy{}Result\PYGZhy{}Queue\PYGZhy{}Thread@117098 Task 358: changing state from launched to exec\PYGZus{}done (parsl.log)
2025\PYGZhy{}10\PYGZhy{}26 10:29:46.494729 HTEX\PYGZhy{}Result\PYGZhy{}Queue\PYGZhy{}Thread@117098 Task 358: Standard out will not be redirected. (parsl.log)
2025\PYGZhy{}10\PYGZhy{}26 10:29:46.494905 HTEX\PYGZhy{}Result\PYGZhy{}Queue\PYGZhy{}Thread@117098 Task 358: Standard error will not be redirected. (parsl.log)
\end{sphinxVerbatim}

\sphinxAtStartPar
This integrates four log files and two task identifier systems into a single sequence of events.


\chapter{case study 2}
\label{\detokenize{index:case-study-2}}
\sphinxAtStartPar
Debugging monitoring performance as part of developing this prototype.

\sphinxAtStartPar
findcommon tool \sphinxhyphen{} finds common task sequence for templated logs and outputs their sequence, like this:

\sphinxAtStartPar
First run parsl\sphinxhyphen{}perf like this:

\begin{sphinxVerbatim}[commandchars=\\\{\}]
parsl\PYGZhy{}perf \PYGZhy{}\PYGZhy{}config parsl/tests/configs/htex\PYGZus{}local.py

[...]

==== Iteration 3 ====
Will run 58179 tasks to target 120 seconds runtime
Submitting tasks / invoking apps
All 58179 tasks submitted ... waiting for completion
Submission took 103.880 seconds = 560.059 tasks/second
Runtime: actual 137.225s vs target 120s
Tasks per second: 423.967
Tests complete \PYGZhy{} leaving DFK block
\end{sphinxVerbatim}

\sphinxAtStartPar
which executes a total around 60000 tasks.

\sphinxAtStartPar
First, note that this prototype benchmarks on my laptop significantly slower than the contemperaneous master branch, at .

\sphinxAtStartPar
That’s perhaps unsurprising: this benchmark is incredibly log sensistive, as my previous posts have noted \sphinxhyphen{} TODO: link to blog post and to R\sphinxhyphen{}performance report) \sphinxhyphen{} around 900 tasks per second on a 120 second benchmark. And this prototype adds a lot of log output. Part of the path to productionisation would be understanding and constraining this.

\sphinxAtStartPar
From that output above, it is clear that the submission loop is taking a long time: 100 seconds. With about 35 seconds of execution happening afterwards. The Parsl core should be able to process task submissions much faster than 560 tasks per seconds. So what’s taking up time there?

\sphinxAtStartPar
Run findcommon (a could\sphinxhyphen{}be\sphinxhyphen{}modular\sphinxhyphen{}but\sphinxhyphen{}isn’t helper from this observability prototype) on the result:

\begin{sphinxVerbatim}[commandchars=\\\{\}]
0.0: Task \PYGZpc{}s: will be sent to executor htex\PYGZus{}local
0.00023320618468031343: Task \PYGZpc{}s: Adding output dependencies
0.0004515730863634116: Task \PYGZpc{}s: Added output dependencies
0.000672943356177761: Task \PYGZpc{}s: Gathering dependencies: start
0.0008952160973877195: Task \PYGZpc{}s: Gathering dependencies: end
0.0011054732824941516: Task \PYGZpc{}s: submitted for App app, not waiting on any dependency
0.001316777690507145: Task \PYGZpc{}s: has AppFuture: \PYGZpc{}s
0.0015680651123983979: Task \PYGZpc{}s: initializing state to pending
23.684763520758917: HTEX task \PYGZpc{}s: putting onto pending\PYGZus{}task\PYGZus{}queue
23.68483662049256: HTEX task \PYGZpc{}s: fetched task
23.684863335335613: Task \PYGZpc{}s: changing state from pending to launched
23.6850573607536: Task \PYGZpc{}s: try \PYGZpc{}s launched on executor \PYGZpc{}s with executor id \PYGZpc{}s
23.685248910492184: Task \PYGZpc{}s: Standard out will not be redirected.
23.685424046734745: Task \PYGZpc{}s: Standard error will not be redirected.
23.686276226995773: Putting HTEX task \PYGZpc{}s into scheduler
23.686777094898495: HTEX task \PYGZpc{}s: received executor task
23.687025900194147: HTEX task \PYGZpc{}s: Completed task
23.687268549254735: HTEX task \PYGZpc{}s: All processing finished for task
23.687837933843614: HTEX task \PYGZpc{}s: Manager \PYGZpc{}r: Removing task from manager
23.688483699079185: Task \PYGZpc{}s: changing state from launched to exec\PYGZus{}done
\end{sphinxVerbatim}

\sphinxAtStartPar
In this stylised synthetic task trace, a task takes an average of 23 seconds to go from the first event (choosing executor) to the final mark as done. That’s fairly consistent with the parsl\sphinxhyphen{}perf output \sphinxhyphen{} I would expect the average here to be around half the time of parsl\sphinxhyphen{}perf’s submission time to completion time (30 seconds).

\sphinxAtStartPar
What’s useful with findcommon’s output is that it shows the insides of Parsl’s working in more depth: 20 states instead of parsl\sphinxhyphen{}perf’s start, submitted, end. And the potential exists to calculate other statistics on these events.

\sphinxAtStartPar
So in this average case, there’s something slow happening between setting the task to pending, and then the task “simultaneously” being marked as launched on the submit side and the interchange receiving it and placing it in the pending task queue.

\sphinxAtStartPar
That’s a bit surprising \sphinxhyphen{} tasks are meant to accumulate in the interchange, not before the interchange.

\sphinxAtStartPar
So let’s perform some deeper investigations \textendash{} observability is for Serious Investigators and so it is fine to be hacking on the Parsl source code to understand this more. (by hacking, I mean making temporary changes for the investigation that likely will be thrown away rather than integrated into master).

\sphinxAtStartPar
Let’s flesh out the whole submission process with some more log lines. On the DFK side, that’s pretty straightforward: the observability prototype has a per\sphinxhyphen{}task logger which, if you have the task record, will attach log messages to the task.

\sphinxAtStartPar
For example, here’s the changes to add a log around the first call to launch\_if\_ready, which is probably the call that is launching the task.

\begin{sphinxVerbatim}[commandchars=\\\{\}]
+  task\PYGZus{}logger.debug(\PYGZdq{}TMP: dependencies added, calling launch\PYGZus{}if\PYGZus{}ready\PYGZdq{})
   self.launch\PYGZus{}if\PYGZus{}ready(task\PYGZus{}record)
+  task\PYGZus{}logger.debug(\PYGZdq{}TMP: launch\PYGZus{}if\PYGZus{}ready returned\PYGZdq{})
\end{sphinxVerbatim}

\sphinxAtStartPar
My suspicion is that this is around the htex submission queues, with a secondary submission around the launch executor, so to start with I’m going to add more logging around that.

\sphinxAtStartPar
Then rerun parsl\sphinxhyphen{}perf and findcommon, without modifying either, and it turns out to be that secondary submission, the launch executor:

\begin{sphinxVerbatim}[commandchars=\\\{\}]
0.0020453477688227: Task \PYGZpc{}s: TMP: submitted into launch pool executor
0.002256870306434224: Task \PYGZpc{}s: TMP: launch\PYGZus{}if\PYGZus{}ready returned
14.073021359217009: Task \PYGZpc{}s: TMP: before submitter lock
[...]
14.078550367412324: Task \PYGZpc{}s: changing state from launched to exec\PYGZus{}done
\end{sphinxVerbatim}

\sphinxAtStartPar
Don’t worry too much about the final time (14s) changing from 23s in the earlier run \textendash{} that’s a characteristic of parsl\sphinxhyphen{}perf batch sizes that I’m working on in another branch.

\sphinxAtStartPar
If that’s the case, I’d expect the thread pool executor, previously much faster than htex, to show similar characteristics:

\sphinxAtStartPar
surprisingly, though although the throughput is not much much higher… the trace looks very different timewise. the bulk of the time here still happens at the same place, there isn’t so much waiting there \sphinxhyphen{} less than a second on average. That’s possibly because the executor can get through tasks much faster so the queue doesn’t build up so much?

\begin{sphinxVerbatim}[commandchars=\\\{\}]
==== Iteration 2 ====
Will run 68976 tasks to target 120 seconds runtime
Submitting tasks / invoking apps
All 68976 tasks submitted ... waiting for completion
Submission took 117.915 seconds = 584.965 tasks/second
Runtime: actual 118.417s vs target 120s
Tasks per second: 582.485
\end{sphinxVerbatim}

\begin{sphinxVerbatim}[commandchars=\\\{\}]
0.0: Task \PYGZpc{}s: will be sent to executor threads
0.00014157412110423425: Task \PYGZpc{}s: Adding output dependencies
0.0002898652725047201: Task \PYGZpc{}s: Added output dependencies
0.000425118042214259: Task \PYGZpc{}s: Gathering dependencies: start
0.0005696294991521399: Task \PYGZpc{}s: Gathering dependencies: end
0.0006999648174108608: Task \PYGZpc{}s: submitted for App app, not waiting on any dependency
0.0008433702196425292: Task \PYGZpc{}s: has AppFuture: \PYGZpc{}s
0.0010710284919573986: Task \PYGZpc{}s: initializing state to pending
0.0011652027385929428: Task \PYGZpc{}s: TMP: dependencies added, calling launch\PYGZus{}if\PYGZus{}ready
0.0012973675719411494: Task \PYGZpc{}s: submitting into launch pool executor
0.0014397921284467212: Task \PYGZpc{}s: submitted into launch pool executor
0.0015767665501452072: Task \PYGZpc{}s: TMP: launch\PYGZus{}if\PYGZus{}ready returned
0.3143575128217656: Task \PYGZpc{}s: before submitter lock
0.31448896150771743: Task \PYGZpc{}s: after submitter lock, before executor.submit
0.3146383380777917: Task \PYGZpc{}s: after before executor.submit
0.3147926810507091: Task \PYGZpc{}s: changing state from pending to launched
0.3149239369413048: Task \PYGZpc{}s: try 0 launched on executor threads
0.31504996538376506: Task \PYGZpc{}s: Standard out will not be redirected.
0.31504996538376506: Task \PYGZpc{}s: Standard out will not be redirected.
0.3151759985402679: Task \PYGZpc{}s: Standard error will not be redirected.
0.3151759985402679: Task \PYGZpc{}s: Standard error will not be redirected.
0.315319734920821: Task \PYGZpc{}s: changing state from launched to exec\PYGZus{}done
\end{sphinxVerbatim}

\sphinxAtStartPar
So maybe I can do some graphing of events to give more insight than these averages are showing. A favourite of mine from previous monitoring work is how many tasks are in each state at each moment in time. I’ll have to implement that for this observability prototype, because it’s not done already, but once it’s done it should be reusable. and it should share most infrastructure with \sphinxtitleref{findcommon}. Especially relevant is discovering where bottlenecks are: it looks like this is a parsl\sphinxhyphen{}affecting performance regression that might be keeping workers idle. For example, we could ask: does the interchange have “enough” tasks at all times to keep dispatching. With 8 cores on my laptop, I’d like it to have at least 8 tasks or so inside htex at any one time, but this looks like it might not be true. Hopefully graphing will reveal more. It’s also important to note that this findcommon output shows latency, not throughput \textendash{} though high latency at particular points is an indication of throughput problems.

\sphinxAtStartPar
Or, I can look at how many tasks are in the interchange over time: there either is, or straightforwardly can be, a log line for that. That will fit a different model to the above log lines which are per\sphinxhyphen{}task. Instead they’re a metric on the state of one thing only: the interchange. of which there is only one, at least for the purposes of this investigation.

\sphinxAtStartPar
Add a new log line like this into the interchange at a suitable point (after task queueing, for example):

\begin{sphinxVerbatim}[commandchars=\\\{\}]
+  ql = len(self.pending\PYGZus{}task\PYGZus{}queue)
+  logger.info(f\PYGZdq{}TMP: there are \PYGZob{}ql\PYGZcb{} tasks in the pending task queue\PYGZdq{}, extra=\PYGZob{}\PYGZdq{}metric\PYGZdq{}: \PYGZdq{}pending\PYGZus{}task\PYGZus{}queue\PYGZus{}length\PYGZdq{}, \PYGZdq{}queued\PYGZus{}tasks\PYGZdq{}: ql\PYGZcb{})
\end{sphinxVerbatim}

\sphinxAtStartPar
Now can either look through the logs by hand to manually see the value. Or extract it programmatically and plot it with matplotlib, in an ad\sphinxhyphen{}hoc script:

\begin{sphinxVerbatim}[commandchars=\\\{\}]
\PYG{k+kn}{import} \PYG{n+nn}{matplotlib}\PYG{n+nn}{.}\PYG{n+nn}{pyplot} \PYG{k}{as} \PYG{n+nn}{plt}
\PYG{k+kn}{from} \PYG{n+nn}{parsl}\PYG{n+nn}{.}\PYG{n+nn}{observability}\PYG{n+nn}{.}\PYG{n+nn}{getlogs} \PYG{k+kn}{import} \PYG{n}{getlogs}

\PYG{n}{logs} \PYG{o}{=} \PYG{n}{getlogs}\PYG{p}{(}\PYG{p}{)}

\PYG{c+c1}{\PYGZsh{} looking for these logs:}
\PYG{c+c1}{\PYGZsh{} \PYGZdq{}metric\PYGZdq{}: \PYGZdq{}pending\PYGZus{}task\PYGZus{}queue\PYGZus{}length\PYGZdq{}, \PYGZdq{}queued\PYGZus{}tasks\PYGZdq{}: ql\PYGZcb{})}

\PYG{n}{metrics} \PYG{o}{=} \PYG{p}{[}\PYG{p}{(}\PYG{n+nb}{float}\PYG{p}{(}\PYG{n}{l}\PYG{p}{[}\PYG{l+s+s1}{\PYGZsq{}}\PYG{l+s+s1}{created}\PYG{l+s+s1}{\PYGZsq{}}\PYG{p}{]}\PYG{p}{)}\PYG{p}{,} \PYG{n+nb}{int}\PYG{p}{(}\PYG{n}{l}\PYG{p}{[}\PYG{l+s+s1}{\PYGZsq{}}\PYG{l+s+s1}{queued\PYGZus{}tasks}\PYG{l+s+s1}{\PYGZsq{}}\PYG{p}{]}\PYG{p}{)}\PYG{p}{)}
           \PYG{k}{for} \PYG{n}{l} \PYG{o+ow}{in} \PYG{n}{logs}
           \PYG{k}{if}  \PYG{l+s+s1}{\PYGZsq{}}\PYG{l+s+s1}{metric}\PYG{l+s+s1}{\PYGZsq{}} \PYG{o+ow}{in} \PYG{n}{l}
           \PYG{o+ow}{and} \PYG{n}{l}\PYG{p}{[}\PYG{l+s+s1}{\PYGZsq{}}\PYG{l+s+s1}{metric}\PYG{l+s+s1}{\PYGZsq{}}\PYG{p}{]} \PYG{o}{==} \PYG{l+s+s2}{\PYGZdq{}}\PYG{l+s+s2}{pending\PYGZus{}task\PYGZus{}queue\PYGZus{}length}\PYG{l+s+s2}{\PYGZdq{}}
          \PYG{p}{]}


\PYG{n}{plt}\PYG{o}{.}\PYG{n}{scatter}\PYG{p}{(}\PYG{n}{x}\PYG{o}{=}\PYG{p}{[}\PYG{n}{m}\PYG{p}{[}\PYG{l+m+mi}{0}\PYG{p}{]} \PYG{k}{for} \PYG{n}{m} \PYG{o+ow}{in} \PYG{n}{metrics}\PYG{p}{]}\PYG{p}{,}
            \PYG{n}{y}\PYG{o}{=}\PYG{p}{[}\PYG{n}{m}\PYG{p}{[}\PYG{l+m+mi}{1}\PYG{p}{]} \PYG{k}{for} \PYG{n}{m} \PYG{o+ow}{in} \PYG{n}{metrics}\PYG{p}{]}\PYG{p}{)}

\PYG{n}{plt}\PYG{o}{.}\PYG{n}{show}\PYG{p}{(}\PYG{p}{)}
\end{sphinxVerbatim}

\sphinxAtStartPar
and indeed that shows that the interchange queue length almost never goes above length 1, and never above length 10.

\sphinxAtStartPar
That’s enough for now, but it’s a usecase that shows partially understanding throughput: we can see from this observability data that the conceptual 50000 task queue that begins in parsl\sphinxhyphen{}perf as a \sphinxtitleref{for}\sphinxhyphen{}loop doesn’t progress fast enough to the interchange internal queue, and so probably performance effort should probably be focused on understanding and improving the code path around launch and getting into the interchange queue. With an almost empty interchange queue, anything happening on the worker side is probably not too relevant, at least for that parsl\sphinxhyphen{}perf use case.

\sphinxAtStartPar
This “understand the queue lengths (or implicit queue lengths) towards execution” investigation style has been useful in understanding Parsl performance limitations in the past.


\chapter{Configurability}
\label{\detokenize{index:configurability}}
\sphinxAtStartPar
A soft start is to let people opt into observability style logs \sphinxhyphen{} with most performance hit coming from turning on json output, i think, it doesn’t matter performance\sphinxhyphen{}wise too much about adding in the extra stuff on log calls.


\chapter{Relation to monitoring and logging systems}
\label{\detokenize{index:relation-to-monitoring-and-logging-systems}}
\sphinxAtStartPar
Parsl uses python’s logging module. Parsl has its own monitoring system. This work builds on both of those, but changes how thye are used significantly.


\chapter{Why observability? vs monitoring}
\label{\detokenize{index:why-observability-vs-monitoring}}
\sphinxAtStartPar
Original monitoring prototype was focused on what is happening
with Parsl user level concepts: tasks, blocks for example
as they move through simple states. Anything deeper is part
of the idea of “Parsl makes it so you don’t have to think
about anything happening inside”. Which is not how things are
in reality: neither for code reliabilty or for performance.

\sphinxAtStartPar
Parsl Monitoring is too strict in a couple of ways:

\sphinxAtStartPar
The data model is fairly hard\sphinxhyphen{}coded into the architecture:
specific SQL schema, specific message formats and specific
places where those messages are sent.

\sphinxAtStartPar
The transmission model is real\sphinxhyphen{}time. Even with recent radio
plugins, the assumption is still that messages will arrive
soon after being sent.

\sphinxAtStartPar
The almost\sphinxhyphen{}real\sphinxhyphen{}time data transmisison model is especially
awkward when combined with SQL: distributed system events
will arrive at different times or in the original UDP model
perhaps not at all, and the “first” message that
creates a task (for the purposes of the database) might arrive
after some secondary data that requires that primary key to
exist. yes, it’s nice for the SQL database to follow foreign
key rules, especially when looking at the data “afterwards”
but that’s not realistic for distributed unreliable events.

\sphinxAtStartPar
Contrast this to:
\begin{itemize}
\item {} 
\sphinxAtStartPar
arbitrary logs that may be different for different kinds
of execution \sphinxhyphen{} for example, different executor implementations

\item {} 
\sphinxAtStartPar
pouring over these logs “later” \sphinxhyphen{} there’s no need for those
logs to accumulate in real time in one place for post\sphinxhyphen{}facto
analysis. And in practice, when doing log analysis rather
than monitoring analysis, “send me a tarball of your runinfo”
is a standard technique.

\end{itemize}

\sphinxAtStartPar
Parsl Monitoring is not well suited to adding in new ad\sphinxhyphen{}hoc
events, perhaps just for one off debugging cases that will be
thrown away: schema modifications in both SQL and in message
tasks, and rearranging code to accomodate that is a serious
business. Contrast logging: there’s always a logger in any
part of Parsl, and you can \sphinxcode{\sphinxupquote{logger.debug("hello")}} pretty
much anywhere.

\sphinxAtStartPar
Parsl Monitoring was also implemented with a fixed queries
/ dashboard mindset: one set of views that is expected to be
sufficient. As time has shown, people like to make other
outputs from this data.

\sphinxAtStartPar
want to debug/profile whats happening \sphinxstyleemphasis{inside parsl} rather
than \sphinxstyleemphasis{inside the user workflow}.


\chapter{Other components}
\label{\detokenize{index:other-components}}
\sphinxAtStartPar
Some components aren’t Parsl\sphinxhyphen{}aware: for example work queue
has no notion of a Parsl task ID. and it runs its own
logging system, that is not Python, and so not amenable to
Python monitoring radios.

\sphinxAtStartPar
Another example: swap out interchange impl for a different
one with a different internal model: a schema of events for
task progress through the original interchange doesn’t
necessarily work for some other implementation.

\sphinxAtStartPar
ZMQ generates log messages which have been useful sometimes
and these could be gatewayed into observability.

\sphinxAtStartPar
Lots of different identifier spaces, loosely structured,
not necessarily hierarchical: for example, an htex task
is not necessarily “inside” a Parsl task, as htex can be
used outside of a Parsl DFK (which is where the notion of
Parsl task lives). An htex task often runs in a unix process
but that process also runs many htex tasks, and an htex task
also has extent outside of that worker process: there’s no
containment relationship either way.


\chapter{Optional pieces of observability}
\label{\detokenize{index:optional-pieces-of-observability}}
\sphinxAtStartPar
log levels \sphinxhyphen{} INFO vs DEBUG

\sphinxAtStartPar
missing log files \sphinxhyphen{} eg. start with parsl.log, add in more
files for more detail

\sphinxAtStartPar
security \sphinxhyphen{} not so much the Parsl core use case, but eg
GC executor vs GC endpoint logs vs GC central services have
different security properties.

\sphinxAtStartPar
The observability approach needs to accomodate that, for
any/all reasons, some events won’t be there. There can’t be
a “complete set of events” to complain about being incomplete.

\sphinxAtStartPar
less data, well the reports in whatever form are less
informative, to the extent that the lack of data makes them
so.


\chapter{Scope for other hacking}
\label{\detokenize{index:scope-for-other-hacking}}
\sphinxAtStartPar
should be easy to add other events \sphinxhyphen{} the core observability
model shouldn’t be prescriptive about what events exist,
what they look like.

\sphinxAtStartPar
should be easy to use them in analysis

\sphinxAtStartPar
should be easy to import some other event stream, in whatever
format

\sphinxAtStartPar
notions of moving logs around to a place of analysis should
not be baked into the architecture. realtime options, file
based options, … \sphinxhyphen{} that is an area for experimentation
(see Chronolog) and this work should facilitate that rather
than being prescriptive

\sphinxAtStartPar
storage and query of logs is also an area for experimentation.
there are lots of hosted commercial services. lots of small
scale stuff:

\sphinxAtStartPar
eg. at small enough scale, parsing logs into a
python session and using e.g. set and list comprehensions is
a legitimate way to analyse things (rather than something
awkwardly shameful that will be replaced by The Real Thing
later) \sphinxhyphen{} especially given Parsl users general exposure to
data science in Python.

\sphinxAtStartPar
Ignore Parsl Monitoring per\sphinxhyphen{}task resource monitoring and
do something else that generates similar observability
records. This was always some disappointment with getting
WQ resource monitoring into the Parsl monitoring database.

\sphinxAtStartPar
Inside Python parts of Parsl, this data \sphinxstyleemphasis{is} available
in realtime at the point of logging as it goes to whatever
LogHandler is running in each python process. that isn’t
true in general on the “event model” side of things, though.


\chapter{Target audience}
\label{\detokenize{index:target-audience}}
\sphinxAtStartPar
serious debugger/profiler people

\sphinxAtStartPar
not management\sphinxhyphen{}dashboard types \sphinxhyphen{} although management
dashboards absolutely should be creatable with this
observability data.


\chapter{Build your own stack}
\label{\detokenize{index:build-your-own-stack}}
\sphinxAtStartPar
Lots of observability commentary online talks as if you are
building your entire stack, to the extent that you care about
observability. Parsl is much more a pile of configurable
components stuck together, all with their own different
options for observability/logging/monitoring, and without
easy ability for someone to add a consistent model throughout
the entire stack of code.


\chapter{Algebra of merging logs}
\label{\detokenize{index:algebra-of-merging-logs}}
\sphinxAtStartPar
widening

\sphinxAtStartPar
joining

\sphinxAtStartPar
post\sphinxhyphen{}facto relationship establishment

\sphinxAtStartPar
relabelling

\sphinxAtStartPar
look at relational algebra for phrasing and concepts

\sphinxAtStartPar
notion of identity and key\sphinxhyphen{}sequences:
eg. parsl\_dfk/parsl\_task\_id is a globally
unique identifier for a parsl task across time and space,
and so is parsl\_dfk/executor\_label/block\_number or
parsl\_dfk/executor\_label/manager\_id/worker\_number
\textendash{} although manager ID is also (in short form) globally
unique.
this is distinct from the hierarchical relations between
entities \sphinxhyphen{} although hierarchical identity keys will often
line up with execution hierarchy.

\sphinxAtStartPar
peter buneman XML keys stuff did nested sequences of keys
for identifying xml fragments, c. year 2000


\chapter{Who wants this?}
\label{\detokenize{index:who-wants-this}}
\sphinxAtStartPar
At least me.

\sphinxAtStartPar
Many users don’t come explicitly asking for monitoring\sphinxhyphen{}style
information but do ask how to understand whats going on
inside. And then are excited to use monitoring when it
exists.


\chapter{Browser UI}
\label{\detokenize{index:browser-ui}}
\sphinxAtStartPar
what might a browser UI look like for this?

\sphinxAtStartPar
compare parsl\sphinxhyphen{}visualize. compare scrolling through logs,
but with some more interactivity (eg. click / choose
“show me logs from same dfk/task\_id”)


\chapter{Performance measurement of patch stack on 2025\sphinxhyphen{}10\sphinxhyphen{}27}
\label{\detokenize{index:performance-measurement-of-patch-stack-on-2025-10-27}}
\begin{sphinxVerbatim}[commandchars=\\\{\}]
\PYG{n}{pip} \PYG{n}{install} \PYG{o}{\PYGZhy{}}\PYG{n}{e} \PYG{o}{.} \PYG{o}{\PYGZam{}}\PYG{o}{\PYGZam{}} \PYG{n}{parsl}\PYG{o}{\PYGZhy{}}\PYG{n}{perf} \PYG{o}{\PYGZhy{}}\PYG{o}{\PYGZhy{}}\PYG{n}{config} \PYG{n}{parsl}\PYG{o}{/}\PYG{n}{tests}\PYG{o}{/}\PYG{n}{configs}\PYG{o}{/}\PYG{n}{htex\PYGZus{}local}\PYG{o}{.}\PYG{n}{py} \PYG{o}{\PYGZhy{}}\PYG{o}{\PYGZhy{}}\PYG{n}{iterate}\PYG{o}{=}\PYG{l+m+mi}{1}\PYG{p}{,}\PYG{l+m+mi}{1}\PYG{p}{,}\PYG{l+m+mi}{1}\PYG{p}{,}\PYG{l+m+mi}{10000}
\end{sphinxVerbatim}

\sphinxAtStartPar
Running parsl\sphinxhyphen{}perf with constant block sizes (to avoid
queue length speed changes):

\sphinxAtStartPar
master branch (165fdc5bf663ab7fd0d3ea7c2d8d177b02d731c5) 1139 tps

\sphinxAtStartPar
more\sphinxhyphen{}task\sphinxhyphen{}tied\sphinxhyphen{}logs: 1024
\begin{description}
\sphinxlineitem{json\sphinxhyphen{}wide\sphinxhyphen{}log\sphinxhyphen{}records: 537}\begin{itemize}
\item {} 
\sphinxAtStartPar
but without initializing the JSONHandler: 1122

\end{itemize}

\end{description}

\sphinxAtStartPar
end of branch with all changes up to now: 385


\chapter{Applying this approach for academy}
\label{\detokenize{index:applying-this-approach-for-academy}}
\sphinxAtStartPar
As an extreme “data might not be there” \textendash{} perhaps Parsl
isn’t there at all. What does this code and these techniques
look like applied to a similar but very different codebase,
Academy, which doesn’t have any distributed monitoring at
all at the moment. There are \textasciitilde{}100 log lines in the
academy codebase right now. How much can this be converted
in a few hours, and then analysed in similar ways?

\sphinxAtStartPar
The point here being both considering this as a real
logging direction for academy, and as a proof\sphinxhyphen{}of\sphinxhyphen{}generality
beyond Parsl.

\sphinxAtStartPar
thoughts:

\sphinxAtStartPar
repr\sphinxhyphen{}of\sphinxhyphen{}ID\sphinxhyphen{}object might not be the correct format for logging:
I want stuff that is nice strings for values, but repr
(although it is a string) is more designed to look like a
python code fragment rather than the core value of an object.
Maybe \sphinxcode{\sphinxupquote{str}} is better, and maybe some other way of
representing the ID is better? The point is to have values
that work well in aggregate, database style analysis, not
easy on the human eye.

\sphinxAtStartPar
academy logging so far focused on looking pretty on the
console: eg ANSI colour \sphinxhyphen{} that’s at the opposite end of the
spectrum to what this observability project is trying to log.

\sphinxAtStartPar
rule of thumb for initial conversion: whatever is substituted
into the human message should be added as an extras field.

\sphinxAtStartPar
other components this might be applied to: Globus Compute.
Various related workflow systems that sit on top of Parsl.


\chapter{See also}
\label{\detokenize{index:see-also}}
\sphinxAtStartPar
netlogger

\sphinxAtStartPar
my dnpc work, an earlier iteration of this. more focused on human log parsing and so very fragile in the face of improving log messages, and not enough context in the human component.

\sphinxAtStartPar
chronolog \sphinxurl{https://grc.iit.edu/research/projects/chronolog/}

\sphinxAtStartPar
syslog


\chapter{In\sphinxhyphen{}parsl Python coding}
\label{\detokenize{index:in-parsl-python-coding}}
\sphinxAtStartPar
Acknowledging observability as a first\sphinxhyphen{}order feature means
we can make big changes to code.

\sphinxAtStartPar
Every log message needs to be visited to add context. In
many places a bunch of that context can be added by helpers:
for example, in my prototype, some module level loggers are
replaced by object\sphinxhyphen{}level loggers: there is a per\sphinxhyphen{}task
logger (actually LoggerAdapter) in the TaskRecord, and
logging to that automatically adds on relevant DFK and task
metadata: at most log sites, the change to add that metadata
is to switch from invoking methods on the module\sphinxhyphen{}level logger
object, invoking them on the new task\sphinxhyphen{}level logger instead.

\sphinxAtStartPar
Some log lines bracket an operation, and to help with that,
my prototype introduces a LexicalSpan context manager which
can be used as part of a \sphinxtitleref{with} block to identify the span
of work starting and ending.

\sphinxAtStartPar
Move away from forming ad\sphinxhyphen{}hoc string templates and make
log calls look more machine\sphinxhyphen{}readable. This is somewhat
stylistic: with task ID automatically logged, there is no
need to substitute in task ID in some arbitrary subset of
task\sphinxhyphen{}related logs.


\chapter{Acknowledgements}
\label{\detokenize{index:acknowledgements}}
\sphinxAtStartPar
chronolog: nishchay, inna

\sphinxAtStartPar
desc: esp david adams, tom glanzman, jim chiang

\sphinxAtStartPar
uiuc: ved

\sphinxAtStartPar
gc: kevin

\sphinxAtStartPar
academy: alok


\chapter{Indices and tables}
\label{\detokenize{index:indices-and-tables}}\begin{itemize}
\item {} 
\sphinxAtStartPar
\DUrole{xref,std,std-ref}{genindex}

\item {} 
\sphinxAtStartPar
\DUrole{xref,std,std-ref}{modindex}

\item {} 
\sphinxAtStartPar
\DUrole{xref,std,std-ref}{search}

\end{itemize}



\renewcommand{\indexname}{Index}
\printindex
\end{document}