%% Generated by Sphinx.
\def\sphinxdocclass{report}
\documentclass[a5paper,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}{4}
\setcounter{secnumdepth}{4}


\title{Wide event observability prototype report}
\date{Dec 03, 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}}
\index{observability@\spxentry{observability}}\ignorespaces 
\sphinxAtStartPar
These are notes about my current iteration of a Parsl and Academy \sphinxstyleemphasis{observability} prototype. It is intended to help with plugin style integration between those two components and an open collection of friends including Globus Compute, Diaspora and Chronolog.

\sphinxAtStartPar
As an abstract concept: “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}). In the context of this project, it means outputting enough information about the system to understand why bugs happen in the system.

\sphinxAtStartPar
There is plenty to read about Observability on the web: google around for more info.

\sphinxAtStartPar
This is often neglected as part of the core functionality of a research prototype, as demonstrations are run in controlled environments with the original authors both ready to respond to the slightest problem with copious time, and ready to restart everything from scratch repeatedly until the desired outcome is achieved.

\sphinxAtStartPar
As soon as that prototype is forced into production, those two properties evaporate and the need for observability manifests: both users and legacy developers need to understand what is happening in this suddenly wider and more hostile world.

\sphinxAtStartPar
In the Parsl world that exists now as two separate systems: Log files and Parsl Monitoring. This report will explore ways in which they can be usefully unified and extended.

\index{DESC@\spxentry{DESC}}\index{CZI@\spxentry{CZI}}\index{NSF@\spxentry{NSF}}\ignorespaces 
\sphinxAtStartPar
This project builds on experiences debugging Parsl within the DESC project, as well as work sponsored by NSF and CZI understanding pluggability and code maturity as they affect architectural decisions. As a concurrent activiy, I have used some of this experience to push changes into the Academy codebase to support its move towards production.

\sphinxAtStartPar
A distant vision is a project\sphinxhyphen{}wide or personal\sphinxhyphen{}space\sphinxhyphen{}wide observability system \textendash{}  but it is important to acknowledge that this is a distant and vague vision, and that actually what I want to happen is stuff on the scale of weeks to months that is usable on that timescale, with others left to take up that distant vision if desired.

\sphinxAtStartPar
This report attempts to describe abstract concepts but ground them in practice
and concrete code\sphinxhyphen{}driven examples. This report also tries to give open
questions and opportunities that might be interesting for other people to work
on.

\sphinxAtStartPar
How to try this out? Because I want you to try this out. It’s in my
Parsl \sphinxcode{\sphinxupquote{benc\sphinxhyphen{}observability}} branch. I will try to label use cases as
expected to work or not, and in what context. There will also be some
academy\sphinxhyphen{}related stuff in that branch, with the intention that it moves
elsewhere as productionised.


\section{What exists in Parsl now?}
\label{\detokenize{index:what-exists-in-parsl-now}}
\sphinxAtStartPar
Parsl has two observability approaches: file\sphinxhyphen{}based logging and Parsl Monitoring.

\sphinxAtStartPar
File based logging is very loosely structured. Log lines are intended for direct human consumption, with minimal automated processing: for example, “grepping the logs”. Within Parsl there is a variety of log formats, usually depending on the component which generated the log. Logs are directed to a filesystem accessible by the particular component, which in practice they are especially awkward without a shared file system. It is easy to add a new log line, by writing what is effectively a glorified \sphinxcode{\sphinxupquote{print}} statement.

\index{Parsl monitoring@\spxentry{Parsl monitoring}!database manager@\spxentry{database manager}}\ignorespaces 
\sphinxAtStartPar
Parsl Monitoring generates monitoring events that are not intended to be seen by humans. Instead they are conveyed to a Monitoring Database Manager which munges them into a relational schema. This schema is then typically accessed by users via futher processing for pre\sphinxhyphen{}prepared visualization or ad\sphinxhyphen{}hoc queries designed by data\sphinxhyphen{}science aware power users. These monitoring events can be conveyed by a pluggable interface, for example over the network, and in contrast to the logging approach above, distributed filesystem access (in the broadest sense) is not required. The strict SQL schema makes the data model extremely hard to extend ad\sphinxhyphen{}hoc.

\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
This report builds on both of these approaches. I’ll talk about more details in later sections.


\section{Diagram}
\label{\detokenize{index:diagram}}
\sphinxAtStartPar
of the components/flow.

\sphinxAtStartPar
to distinguish the pieces of my work, and also to distinguish the pieces of what might be substituted where.

\sphinxAtStartPar
specific emphasis that this is common techniques, not a single implementation or protocol standards or single anything.

\begin{sphinxVerbatim}[commandchars=\\\{\}]
\PYG{n}{Python} \PYG{n}{logger}
  \PYG{n}{API}   \PYG{o}{\PYGZhy{}}\PYG{o}{\PYGZhy{}}\PYG{o}{\PYGZhy{}}\PYG{o}{\PYGZhy{}}\PYG{o}{\PYGZgt{}} \PYG{n}{JSON} \PYG{n}{structured} \PYG{n}{logs} \PYGZbs{}
                                   \PYG{o}{|}\PYG{o}{\PYGZhy{}}\PYG{o}{\PYGZhy{}}\PYG{o}{\PYGZgt{}} \PYG{n}{log} \PYG{n}{movement} \PYG{o}{\PYGZhy{}}\PYG{o}{\PYGZhy{}}\PYG{o}{\PYGZgt{}} \PYG{n}{Python}\PYG{o}{\PYGZhy{}}\PYG{n}{based} \PYG{n}{query} \PYG{n}{model}             \PYG{o}{\PYGZhy{}}\PYG{o}{\PYGZhy{}}\PYG{o}{\PYGZgt{}} \PYG{n}{graphs}\PYG{o}{/}\PYG{n}{reports}
        \PYG{n}{non}\PYG{o}{\PYGZhy{}}\PYG{n}{JSON} \PYG{n}{structured} \PYG{n}{logs}   \PYG{o}{/}    \PYG{n}{to} \PYG{n}{one} \PYG{n}{place}     \PYG{o}{\PYGZhy{}}\PYG{o}{\PYGZhy{}}\PYG{o}{\PYGZgt{}} \PYG{n}{post} \PYG{n}{facto} \PYG{n}{schema} \PYG{n}{normalisation}
        \PYG{p}{(}\PYG{n}{eg}\PYG{o}{.} \PYG{n}{WQ}\PYG{p}{,} \PYG{n}{Parsl} \PYG{n}{monitoring}\PYG{p}{)}  \PYG{n}{classically} \PYG{n}{files}\PYG{p}{,}          \PYG{o}{\PYGZhy{}}\PYG{o}{\PYGZhy{}}\PYG{o}{\PYGZgt{}} \PYG{n}{data}\PYG{o}{\PYGZhy{}}\PYG{n}{structure} \PYG{n}{based} \PYG{n}{queries}
                                    \PYG{n}{but} \PYG{n}{eg} \PYG{n}{ryan}\PYG{o}{/}\PYG{n}{kafka}
                                           \PYG{n}{logan} \PYG{n}{demo}\PYG{o}{/}\PYG{n}{agent} \PYG{n}{polling}
\end{sphinxVerbatim}


\section{Concept: Universal personal logging}
\label{\detokenize{index:concept-universal-personal-logging}}
\sphinxAtStartPar
Imagine \sphinxstyleemphasis{all} of my academy/globus endpoint/parsl/application runs going into a single log space. permanently. no matter what the project, location, etc.

\sphinxAtStartPar
heres a logging use case/notion: universal personal log.  all my GC endpoints, parsl runs, academy runs, application submits, go into a single log space that has everything I am running everywhere in the science cloud, by default \sphinxhyphen{} eg. identified by my globus credential ID.  no separation whatsoever. no project distinction, etc.

\sphinxAtStartPar
what does that look like to work with on the query side. what does that look like to query?


\section{Target audience}
\label{\detokenize{index:target-audience}}
\sphinxAtStartPar
This project is mainly aimed at systems integrators and application builders who are expecting to perform serious debugging and profiling work at a deep technical level. It should support other use\sphinxhyphen{}cases such as management\sphinxhyphen{}friendly dashboards.

\sphinxAtStartPar
These users will often have integrated several research\sphinxhyphen{}quality projects: for example, Academy submitting into Globus Compute. As systems integrators and application builders, they aren’t directly interested in the borders these individual projects have built around themselves, but want to understand (for example) where their simulation task is inside the whole ad\sphinxhyphen{}hoc stack. This mirrors the microcosm of Parsl existing as a pile of configurable and pluggable compponents, each with their own observability options.

\sphinxAtStartPar
Many of the target audience do not, in my experience, come asking directly for observability as a feature. Instead they come with questions such as “Parsl is slow \sphinxhyphen{} how can I make it faster?”. Without understanding the statement “Parsl is slow” (which as often as not turns out to be “my application code is slow”), it is hard to make progress on “how can I make it faster?”


\section{Modularity}
\label{\detokenize{index:modularity}}
\sphinxAtStartPar
This report emphasises modularity as a core tenet, to the extent that a single product codebase is not particularly an end goal.


\subsection{Modularity as a requirement for a rich research landscape}
\label{\detokenize{index:modularity-as-a-requirement-for-a-rich-research-landscape}}
\sphinxAtStartPar
A “rich research landscape” means many components, each with competing priorities for productionworthiness vs research. TODO: cite the work done as part of NSF/CZI sustainability grants about recognising the difference between goals rather than ignoring them.

\sphinxAtStartPar
Expecting a single observability system to provide all needs is unlikely to succeed in such a varied research\sphinxhyphen{}style environment: while some users are tolerant of appalling code quality in exchange for interesting research results, those same users require production quality from other components in the same stack; and those tolerances vary with every use case.


\subsection{Hourglass model with several waists}
\label{\detokenize{index:hourglass-model-with-several-waists}}
\sphinxAtStartPar
the hourglass model is intended to provide a small number of plugin/intergration points
in the same way that the Internet Protocol does for applications/application protocols vs networking technologies (for example, HTTP over mobile phone network vs telnet over ARPANET is then sufficient integration to run without more work: telnet over mobile phone, HTTP over arpanet)

\sphinxAtStartPar
The hourglass waists are:

\index{Python@\spxentry{Python}!logging@\spxentry{logging}}\index{C programming language@\spxentry{C programming language}}\index{Programming languages@\spxentry{Programming languages}!C@\spxentry{C}}\ignorespaces \begin{itemize}
\item {} 
\sphinxAtStartPar
python \sphinxcode{\sphinxupquote{logging}} system: any Python code can send log messages to the built\sphinxhyphen{}in \sphinxcode{\sphinxupquote{logging}} system and any Python code can register to receive any log messages. This can support components that live in the Python ecosystem. That includes enough of the current ecosystem to consider specially, but not enough to be universal: for example, when running task through Parsl’s Work Queue executor, a substantial piece of execution happens in code written in the C programming language.

\item {} 
\sphinxAtStartPar
JSON records: a second point of modularity is representing observability information as JSON objects. This is flexible data format which complements the Python code approach of the previous waist. Often observability information which cannot flow through the Python \sphinxcode{\sphinxupquote{logging}} API can flow as JSON records.

\end{itemize}


\section{High level structure of this project}
\label{\detokenize{index:high-level-structure-of-this-project}}
\sphinxAtStartPar
This report breaks observability into four rough parts:
\begin{itemize}
\item {} 
\sphinxAtStartPar
A data model of wide event records: {\hyperref[\detokenize{index:datamodel}]{\sphinxcrossref{\DUrole{std,std-ref}{The data model}}}}

\item {} 
\sphinxAtStartPar
Creating wide records: {\hyperref[\detokenize{index:creating}]{\sphinxcrossref{\DUrole{std,std-ref}{Generating wide records}}}}

\item {} 
\sphinxAtStartPar
Moving those event records around: {\hyperref[\detokenize{index:moving}]{\sphinxcrossref{\DUrole{std,std-ref}{Moving wide records around}}}}

\item {} 
\sphinxAtStartPar
Analysing those records: {\hyperref[\detokenize{index:analysing}]{\sphinxcrossref{\DUrole{std,std-ref}{Analysing wide records}}}}

\end{itemize}


\chapter{The data model}
\label{\detokenize{index:the-data-model}}\label{\detokenize{index:datamodel}}

\section{Introduction to wide events}
\label{\detokenize{index:introduction-to-wide-events}}
\sphinxAtStartPar
as JSON objects, as Python LogRecords, as roughly isomorphic structures

\sphinxAtStartPar
wide in the style of denormalised data warehouses, rather than heavily normalised like more traditional relational model.

\sphinxAtStartPar
they should be wide and flat: do not create elaborate object graphs. key/value, with values being simple.

\sphinxAtStartPar
is often ad\sphinxhyphen{}hoc: people are writing code to run tasks, not building data models represent the observable state of their tasks. so don’t bake that into the system too much, and expect to be flexible.


\section{What exists now: Parsl python logs vs Parsl monitoring records}
\label{\detokenize{index:what-exists-now-parsl-python-logs-vs-parsl-monitoring-records}}
\sphinxAtStartPar
Especially for this chapter, how both of those can be embedded as wide events

\sphinxAtStartPar
Parsl monitoring structured records are equally valid examples of existing structured records, alongside with equal value to logging as differently structured records.

\sphinxAtStartPar
Original Parsl 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
often want to debug/profile whats happening \sphinxstyleemphasis{inside parsl} rather
than \sphinxstyleemphasis{inside the user workflow} \sphinxhyphen{} and the distinction between the two is often unclear.


\section{Optional and missing data in observability}
\label{\detokenize{index:optional-and-missing-data-in-observability}}\label{\detokenize{index:partialdata}}
\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. Or in Academy, the hosted HTTP exchange.

\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.

\sphinxAtStartPar
This optionality aligns with different components adding their own logs, if they happen to be there.

\sphinxAtStartPar
Adding (or removing) a log field is a lightweight operation


\section{Data types}
\label{\detokenize{index:data-types}}
\sphinxAtStartPar
data types don’t matter much for human observation. but for machine processing they do. so this section has some relevance when thinking about the Analysis section later.

\sphinxAtStartPar
Both JSON and Python representation can support a range of types. But richer data types can exist. What’s interesting for analysis is primarily relations like equality and ordering, which are implicitly not string\sphinxhyphen{}like in a lot of cases. For example:
\begin{itemize}
\item {} 
\sphinxAtStartPar
string vs int: ‘0’ vs 0 as a Parsl task ID. Even Parsl source code is not entirely clear on when a task ID is a string and when it is an int, I think. Normalisation example: “03” vs “3”. Rundir IDs are usually at least 3 digits long. Is rundir “000” the same as rundir 0?

\item {} 
\sphinxAtStartPar
UUID as 128 bit number, vs UUID as a case\sphinxhyphen{}sensitive/padding\sphinxhyphen{}sensitive ASCII/UTF\sphinxhyphen{}8 string. uuids should be used \sphinxstyleemphasis{more} in this work \sphinxhyphen{} they were invented for the purpose of this kind of distributed identification \sphinxurl{https://en.wikipedia.org/wiki/Universally\_unique\_identifier\#History} \sphinxurl{https://www.rfc-editor.org/rfc/rfc9562.html}  Normalisation example of string form: case differences.

\item {} 
\sphinxAtStartPar
ordinal relations of text\sphinxhyphen{}named log levels (WARN, WARNING, INFO, ERROR, …) in various enumerations (although for querying an overarching schema is maybe possible for read\sphinxhyphen{}only ordering use)

\end{itemize}

\sphinxAtStartPar
Whats the right canonicalisation attitude here? open question for me.

\sphinxAtStartPar
Cannot expect emitters to conform to some defined canonical form.

\sphinxAtStartPar
perhaps I should use rewrite\_by\_lambda(logs, keyname, lambda) to change known fields into a suitable object representation: int for some task IDs, UUIDs, log levels? then the type system deals with it? some of those could happen in the importers, some in the query, as its modular. I already do a rewrite to shift the created time down to 0 base, in one of my plots. So the notion is there already.


\section{Distributed state machines \sphinxhyphen{} parsl issue \#4021}
\label{\detokenize{index:distributed-state-machines-parsl-issue-4021}}
\sphinxAtStartPar
“distributed” state machines are hard. see parsl\sphinxhyphen{}visualize bug \#4021 for an example.

\sphinxAtStartPar
don’t try to make the data model force this. the events happen when they happen. handle it on the query/processing side: you make whatever sense of it that you can. it’s not the job of the recording side to force a model that isn’t true.

\sphinxAtStartPar
for example, in the context of \#4021, we might want to project some external opinion that running should “override” launched for a task, that isn’t reflected in the emitting code/emitting event model at all, based on an artifical “force to single thread” concept of task execution.
in the same vein, the \#4021 suspect tasks have \sphinxstyleemphasis{negative} time in launched state. which sounds very weird for a non\sphinxhyphen{}distributed state machine model.

\sphinxAtStartPar
or we might only want to visualize the running/end of running times and forget overlaying any other state model onto things: the running and running\_ended times should at least be consistent wrt each other as they happen to come from a single threaded bit of code.

\sphinxAtStartPar
see also that the parsl TaskRecord never records a state of running or running\_ended. despite it being a valid state. this already only exists elsewhere in the system as a reconstructed state machine \sphinxhyphen{} not a real single\sphinxhyphen{}threaded/non\sphinxhyphen{}distributed state machine. so parsl monitoring is already a demonstration of the violation of this model.


\section{commercial observability vendors}
\label{\detokenize{index:commercial-observability-vendors}}
\index{Cloudwatch@\spxentry{Cloudwatch}}\index{Honeycomb@\spxentry{Honeycomb}}\ignorespaces 
\sphinxAtStartPar
honeycomb, or built into AWS as cloudwatch

\sphinxAtStartPar
more ad\sphinxhyphen{}hoc construction, less buy in from components, rather than all working together to build a single platform, which is often how the commercial observability usecases are described.

\index{OpenTelemetry@\spxentry{OpenTelemetry}}\ignorespaces 
\sphinxAtStartPar
OpenTelemetry as a standard. How does this related to that standard?

\sphinxAtStartPar
TODO: maybe opentelemetry is better in {\hyperref[\detokenize{index:moving}]{\sphinxcrossref{\DUrole{std,std-ref}{Moving wide records around}}}}


\section{The argument for templating log messages}
\label{\detokenize{index:the-argument-for-templating-log-messages}}
\sphinxAtStartPar
previous argument: avoids string interpolation if message will be
discarded.

\sphinxAtStartPar
new argument: we can use the template to find “the same” log message
even when its interpolations vary.

\sphinxAtStartPar
advanced level question:
when a task changes state, should the template be interpolated or
not with the state names? because in my example query, it is relevant
to see those changes \sphinxstyleemphasis{not} as templated away.


\section{Objects and spans}
\label{\detokenize{index:objects-and-spans}}
\sphinxAtStartPar
it is a “thing we want to talk about”, as a very weak notion.

\sphinxAtStartPar
weak notion of “object” but it does exist: for example, logs that are about a particular Parsl task, or a particular HTEX worker, or a particular batch job.

\sphinxAtStartPar
multi\sphinxhyphen{}attribute keys \sphinxhyphen{} sometimes hierarchical but that isn’t required.

\sphinxAtStartPar
eg. contrasting parsl task IDs vs parsl checkpoint IDs: in parsl checkpoint world, tasks are identified by their hashsum. there might be many tasks that run to compute that result. when working cross\sphinxhyphen{}dfk checkpointing, the cross\sphinxhyphen{}dfk sort\sphinxhyphen{}of\sphinxhyphen{}task ID is that hash sum, in the sense of correlating tasks that are elided due to memoization with their original exec\_done task in another run.  (so hashsum is one form of task ID,  parsl\_dfk/parsl\_task\_id is another \sphinxhyphen{} both legitimate but both different)

\sphinxAtStartPar
cross\sphinxhyphen{}ref “span” concept from other places in more broad Observability.

\index{Entity component system@\spxentry{Entity component system}}\ignorespaces 
\sphinxAtStartPar
Compare with \sphinxurl{https://en.wikipedia.org/wiki/Entity\_component\_system} which has identified entities, where the entity only has identity and no other substance, along with components as “characterising an entity as having a partcular aspect” and the “system” which deals with all the entities having particular components. This fits the partial data model fairly well, I think: the notion of identifying entities, without those entities having any further structure; and then the data you might expect to find about certain entities being orthogonal to that.


\section{Entity keys}
\label{\detokenize{index:entity-keys}}
\sphinxAtStartPar
This is probably the fundamental problem of JOIN here, compared to traditional observability which passes request IDs around up front.

\sphinxAtStartPar
In a traditional distributed object model system, you would use something like UUIDs everywhere. However, this observability work is not observing a traditional distributed object model system.

\sphinxAtStartPar
note that in parsl some IDs are deliberately not known across the system at runtime because it would be expensive to correlate them in realtime, and that is not necessary for the executing\sphinxhyphen{}tasks part of Parsl, even though its necessary for the understanding\sphinxhyphen{}how\sphinxhyphen{}that\sphinxhyphen{}task\sphinxhyphen{}was\sphinxhyphen{}executed section.


\section{Other components}
\label{\detokenize{index:other-components}}
\sphinxAtStartPar
rewrite this to not be parsl\sphinxhyphen{}centric but instead talk about integrating “objects” from different components even though those components are not strongly aware of each other. wq vs parsl task id is a nice example: regularly used, but log files are different formats, identifier space is different, cardinality of tasks is different: one parsl task != one wq task.

\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.

\index{ZMQ@\spxentry{ZMQ}}\ignorespaces 
\sphinxAtStartPar
ZMQ generates log messages which have been useful sometimes
and these could be gatewayed into observability.

\sphinxAtStartPar
inherently chaotic research prototypes can benefit from observability \sphinxhyphen{} as part of building and debugging them, rather than a post\sphinxhyphen{}completion 2nd generation feature \sphinxhyphen{} but that is impeded by requiring a strict sql\sphinxhyphen{}like data model to exist, when the research prototype is not ready for that. (see attitude that monitoring is something aimed at “users” later on, not something that is aimed at “developers” understanding the behaviour of what they have created)

\sphinxAtStartPar
“user” applications adding their own events, and expecting those events to be correlatable with everything else that is happening, is part of the model: just as we might expect Globus Compute endpoint logs to be correlatable with parsl htex logs, even though Globus Compute is a “mere” user of Parsl, not a “real part” of Parsl.

\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. even though someone needs to know what their structure is.

\sphinxAtStartPar
to that end, there is no core schema, either formal or informal.

\sphinxAtStartPar
observability records do not even need to have a timestamp, in the sense of a log message. for example, see relations imported from a relational database into observability records, in parsl monitoring import (crossref usecase about plotting from monitoring database)

\sphinxAtStartPar
Parsl contains two “mini\sphinxhyphen{}workflow\sphinxhyphen{}systems” on top of core Parsl: parsl\sphinxhyphen{}perf and pytest tests. It could be interesting to illustrate how those fit in without being a core part of Parsl observability.

\sphinxAtStartPar
Parsl monitoring visualisation and Parsl logging are both completely unaware of the application level structure of the mini\sphinxhyphen{}workflows run by parsl\sphinxhyphen{}perf and pytest, beyond what is expressed to the DFK as DAG fragments: there’s nothing to separate out parsl\sphinxhyphen{}perf iterations, or pytest tests.

\sphinxAtStartPar
In the context of pytest, see: {\hyperref[\detokenize{index:pytest-observes-logs}]{\sphinxcrossref{\DUrole{std,std-ref}{Adventure: pytest observing interchange variables}}}}

\index{colmena@\spxentry{colmena}}\ignorespaces 
\sphinxAtStartPar
Colmena


\chapter{Generating wide records}
\label{\detokenize{index:generating-wide-records}}\label{\detokenize{index:creating}}

\section{What exists now}
\label{\detokenize{index:what-exists-now}}

\subsection{Parsl}
\label{\detokenize{index:parsl}}
\sphinxAtStartPar
Parsl generates a lot of observability\sphinxhyphen{}style events, but spread across many different formats.

\sphinxAtStartPar
Parsl logs \sphinxhyphen{} not well structured, for example overlapping DFKs are not well
represented, and actions to do with different tasks can be interleaved without
being clearly separated/identified.
Globus Compute deliberately makes them even less structured, by jumbling up
the file\sphinxhyphen{}based logs of multiple runs into one directory

\sphinxAtStartPar
Parsl monitoring \sphinxhyphen{} well structured but very hard to modify. It is easy to
query for questions that it can answer, and hard to use for anything more.
Users are generally interested in using it when they discover it, but it
suffers from a history of being built as student demo projects dropped into
production. An example of a question it cannot answer: What is the
\sphinxcode{\sphinxupquote{parsl\_resource\_specification}} for a task?

\index{Work Queue@\spxentry{Work Queue}}\ignorespaces 
\sphinxAtStartPar
Work Queue Logs \sphinxhyphen{} well structured. Ignored by Parsl monitoring. Hard to
correlate with monitoring.db: Work Queue uses work queue task IDs, but
Parsl Monitoring uses Parsl Task and Try IDs. Correlating those is a
motivating use case for this Observabilty projected. {[}TODO: make that
correlation as an explicit use\sphinxhyphen{}case section, explaining what needs to change,
how it is done manually now{]}


\subsection{Academy}
\label{\detokenize{index:academy}}
\sphinxAtStartPar
As a more in\sphinxhyphen{}development project, it is much better placed to make observability
records from the start as a first\sphinxhyphen{}order production feature.


\section{New Python Code for log generation}
\label{\detokenize{index:new-python-code-for-log-generation}}
\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.

\sphinxAtStartPar
TODO: describe academy style that I tried out in PR \#NNN:

\begin{sphinxVerbatim}[commandchars=\\\{\}]
\PYG{n}{extra}\PYG{o}{=}\PYG{n}{myobj}\PYG{o}{.}\PYG{n}{log\PYGZus{}extra}\PYG{p}{(}\PYG{p}{)} \PYG{o}{|} \PYG{p}{\PYGZob{}} \PYG{l+s+s2}{\PYGZdq{}}\PYG{l+s+s2}{some}\PYG{l+s+s2}{\PYGZdq{}}\PYG{p}{:} \PYG{l+s+s2}{\PYGZdq{}}\PYG{l+s+s2}{more}\PYG{l+s+s2}{\PYGZdq{}} \PYG{p}{\PYGZcb{}}
\end{sphinxVerbatim}

\sphinxAtStartPar
Parsl config hook for arbitrary log initialization \sphinxhyphen{} actually it can do “anything” at process init and maybe that’s interesting from a different perspective (because its a callback/plugin), but from the perspective of this report I don’t care about non\sphinxhyphen{}log uses.

\sphinxAtStartPar
Be aware that there are non\sphinxhyphen{}Python bits of code generating various logs. Work Queue (still structured) logs are one example. The output from batch command submit scripts are another less structured one that looks much more like a traditional chaotic output file.


\subsection{Python API on logging side}
\label{\detokenize{index:python-api-on-logging-side}}
\sphinxAtStartPar
Use Python\sphinxhyphen{}provided logger interface, with Python\sphinxhyphen{}provided \sphinxcode{\sphinxupquote{\textasciigrave{}extra\textasciigrave{}}} API.

\sphinxAtStartPar
per\sphinxhyphen{}class “log extras” method that generates an \sphinxcode{\sphinxupquote{extra}} dict about this object.
that pushes on (like \sphinxcode{\sphinxupquote{repr}}) it being the responsibility of the object to describe itself,
rather than being someone elses responsibility.


\subsection{anonymous/temporary identified python objects}
\label{\detokenize{index:anonymous-temporary-identified-python-objects}}
\sphinxAtStartPar
python objects don’t have a global\sphinxhyphen{}over\sphinxhyphen{}time ID. id() exists but it is reused over time so awkward to use over a whole series of logs. so some objects should get a uuid “just” for observability \sphinxhyphen{} UUIDs were invented for this.

\sphinxAtStartPar
likewise e.g. gc endpoints don’t have a DFK ID, but endpoint id/executor/block 0 isn’t a global\sphinxhyphen{}over\sphinxhyphen{}time ID: there’s a new block 0 at every restart? or is there a unique UEP ID each time that is enough? I don’t think so because i see overlapping block\sphinxhyphen{}0 entries.

\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.


\subsection{Contributed: Modifying academy to generate wide events}
\label{\detokenize{index:contributed-modifying-academy-to-generate-wide-events}}
\sphinxAtStartPar
summarise the PRs I merged already

\sphinxAtStartPar
cross\sphinxhyphen{}ref event graph in analysis section as something enabled by this


\section{Translating non\sphinxhyphen{}wide\sphinxhyphen{}event sources}
\label{\detokenize{index:translating-non-wide-event-sources}}
\sphinxAtStartPar
Part of this modularity work is that some modules produce event\sphinxhyphen{}like information that looks superficially very different but that can be understood through the lens of structured event records.


\subsection{Using Parsl monitoring events as wide logs}
\label{\detokenize{index:using-parsl-monitoring-events-as-wide-logs}}
\sphinxAtStartPar
two approaches:

\sphinxAtStartPar
monitoring.json: abandons the SQL database component of conventional Parsl monitoring and instead writes each monitoring message out to a json file, giving an event stream.

\sphinxAtStartPar
replay\sphinxhyphen{}monitoring.db: turns a monitoring.db file into events. the status, resource and block tables already looks like an event stream. This gives an easy way to take existing runs and turn them into event streams without needing to opt\sphinxhyphen{}in to any of the other JSON logging, or changing anything at all at runtime: anything new is entirely post\sphinxhyphen{}facto. which fits the general concept of doing things post\sphinxhyphen{}facto in parsl observability.

\sphinxAtStartPar
the infrastructure for this already exists, which means that the query side of this project can be used without modification of the execution\sphinxhyphen{}side Parsl environment.

\sphinxAtStartPar
see earlier use case on priority visualization


\subsection{Using Work Queue \sphinxstyleliteralintitle{\sphinxupquote{transaction\_log}} as a wide log source}
\label{\detokenize{index:using-work-queue-transaction-log-as-a-wide-log-source}}
\index{Work Queue@\spxentry{Work Queue}}\ignorespaces 
\sphinxAtStartPar
this is a core part of seeing beyond the pure\sphinxhyphen{}Parsl code. it’s well structured but not JSON. translation into JSON is mostly syntactic. and can be done line\sphinxhyphen{}by\sphinxhyphen{}line, aka streaming.

\sphinxAtStartPar
TODO: example log line

\sphinxAtStartPar
note that work queue task IDs are not Parsl task IDs: data from the monitoring database cannot be correlated with data from the work queue transaction log! (without further help from the parsl JSON log files…)


\section{Adventure: adding observability to a prototype: idris2interchange}
\label{\detokenize{index:adventure-adding-observability-to-a-prototype-idris2interchange}}
\index{idris2@\spxentry{idris2}}\index{High Throughput Executor@\spxentry{High Throughput Executor}!interchange@\spxentry{interchange}}\index{Adventure@\spxentry{Adventure}!Adding observability to the idris2 interchange@\spxentry{Adding observability to the idris2 interchange}}\index{Programming languages@\spxentry{Programming languages}!idris2@\spxentry{idris2}}\ignorespaces 
\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
idris2interchange \sphinxhyphen{} i want to debug stuff, not be told by the observability system HAHA we don’t support your prototyping. in some sense thats exactly the time I \sphinxstyleemphasis{need} the observability system to be helping me. not later on when it all works.

\sphinxAtStartPar
idris2interchange project is not aimed at producing production code. \sphinxstyleemphasis{ever}. in that sense it is very similar to some student projects that interact with parsl.

\sphinxAtStartPar
mini\sphinxhyphen{}journal: what did i have to do to support idris2 logging?
* make log records JSON format instead of textual \sphinxhyphen{} prior format was timestamp / string. theres a json library but to start with this records are so simple i’ll template them in.
* also already had a simple log\sphinxhyphen{}of\sphinxhyphen{}value mechanism in there already which readily translates to logging a template, a full message, and the value as separate fields.

\sphinxAtStartPar
now there are json records going to the console. I don’t trust the string escaping, but i’ll deal with that ad\sphinxhyphen{}hoc. but also: needs to go to a file; if i want it to interact with other log files, I need some common keys. htex\_task\_id is the obvious one there for task correlation. manager ID is another.

\sphinxAtStartPar
To go to a file: lazy redirect of stdout to idris2interchange.log. This could be done more seriously to avoid random prints going to the file but this is a prototype so I don’t care.

\index{tool@\spxentry{tool}!jq@\spxentry{jq}}\ignorespaces 
\sphinxAtStartPar
Run it through \sphinxtitleref{jq} for basic validation and haha its broken. I got confused about JSON quotes vs Python style quotes. Various iterations of \sphinxtitleref{jq} vs formatting fixes to work towards \sphinxtitleref{jq} believing this is valid.

\sphinxAtStartPar
That log escaping, which i implemented pretty quickly, seems to make logging extremely slow \sphinxhyphen{} especially outputting the pickle stack which is actually quite a big representation when it has a manager registration with all my installed python packages in there. but hey thats what log levels/log optionality is for.

\sphinxAtStartPar
Let’s do some scripting to figure out which of these lines is so expensive \sphinxhyphen{} based on line length. one line is 49kb long! (its repeating the full pickled task state rather than a task id!). and similar with manager IDs. but this is probably the sort of changes I’ll be needing to make to tie stuff in with other log files anyway.

\sphinxAtStartPar
This log volume has been a problem for me elsewhere, even without structured logging, filling up eg my root filesystem with docker stdout logs.

\sphinxAtStartPar
Now back to \sphinxcode{\sphinxupquote{jq}} validation…

\sphinxAtStartPar
if i get that done… look for every logv call and report each one and how many times it logged a value.
this is in the direction of logging metrics, without actually being that.

\sphinxAtStartPar
a pytest run now give 92000 idris2interchange log lines.

\sphinxAtStartPar
and now jq accepts it all.

\sphinxAtStartPar
so lets see if parsl.obserability.load\_jsons can load it. it can, without further change.

\sphinxAtStartPar
logs that have a v:

\sphinxAtStartPar
Next step is to figure out how task processing can be annotated to fit into the general task flow findcommon style output. Let’s start with a single line such as this without trying to add any broader context.

\sphinxAtStartPar
Make a new logv that lets the v field be named. That allows a single association to be made. which is ok for this stage.

\sphinxAtStartPar
First lets format that task ID properly, without ‘PickleInteger’ in the value.

\sphinxAtStartPar
so now log records look like this:

\sphinxAtStartPar
which I hope is enough to align with the rest of findcommon.

\sphinxAtStartPar
So add in an import for this log into getlogs and try it out:

\sphinxAtStartPar
and there it is.

\sphinxAtStartPar
Next, I’d like to get more in here. Specifically of interest for observability development is I’d like to get an event for the point where a task message is received \sphinxhyphen{} even though at that point, its the beginning of a span that we won’t know the task identity for until much later when the payload has been depickled and the task\_id extracted.

\sphinxAtStartPar
The approach is probably something like a two parter:
\sphinxhyphen{} make some span concept that has identities for all of its messages
\sphinxhyphen{} tie that span to a task ID so that all its lines can get an htex\_task\_id widened on

\sphinxAtStartPar
This is an example of sending a join back in time. and an example of having to have the definition \sphinxstyleemphasis{somewhere} that these things are related \sphinxhyphen{} but that it doesn’t have to be in the logging code where we prefer to be fast and stateless. Also a library call that finds an htex task id on any record of a group and widens out all the others to have the same id: look for “these keys” in groups identified by “these keys” and make them global.
(\sphinxcode{\sphinxupquote{\textasciigrave{}widen\_implication\textasciigrave{}}} or  some functional\sphinxhyphen{}dependency related name?). in this case, for the interchange log file, \sphinxcode{\sphinxupquote{\textasciigrave{}submit\_pass\_id\textasciigrave{}}} =\textgreater{} \sphinxcode{\sphinxupquote{\textasciigrave{}htex\_task\_id\textasciigrave{}}}, or if doing so at a higher level \sphinxcode{\sphinxupquote{\textasciigrave{}(dfk,executor,submit\_pass\_id)=\textgreater{}htex\_task\_id\textasciigrave{}}}

\sphinxAtStartPar
TODO: show task1 output before join. then implement join and show task1 output with the rest of the decode span in there \sphinxhyphen{} the deserialisation of the task and execution of the matchmaker is shown now.

\sphinxAtStartPar
TODO: add in result handling span in the same way.

\sphinxAtStartPar
widening submit\_pass\_id using key implication widening after loading/processing all the logs normally, which is what I’d expect if adding in ad\sphinxhyphen{}hoc hack stuff outside of the core parsl log loaders… has revealed some fixpoint related stuff: widening to htex\_task\_id which is the actual known ID isn’t sufficient because the widening of htex\_task\_id to parsl\_task\_id already happened. I can widen to parsl\_task\_id OK because that implication has happened on the two log lines that already have an htex task ID. Is that ok in general? do I need fixpoints in general? something to keep an eye on. I think: as long as there is one record to convey the join as having happened, then a subsequent join can flesh that out. but if the join involves facts that aren’t represented incrementally like that, then no. probably I can contrive some examples.


\section{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


\section{Idea: Parsl resource monitoring on a host\sphinxhyphen{}wide basis}
\label{\detokenize{index:idea-parsl-resource-monitoring-on-a-host-wide-basis}}
\index{idea@\spxentry{idea}!host\sphinxhyphen{}wide monitoring@\spxentry{host\sphinxhyphen{}wide monitoring}}\ignorespaces 
\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:
what exists there that could be imported? Likewise, host\sphinxhyphen{}wide stuff doesn’t fit well into the current Parsl Monitoring model but might fit better into an observability model.


\section{Idea: worker node dmesg}
\label{\detokenize{index:idea-worker-node-dmesg}}
\index{idea@\spxentry{idea}!kernel events@\spxentry{kernel events}}\index{OOM Killer@\spxentry{OOM Killer}}\index{dmesg@\spxentry{dmesg}}\ignorespaces 
\sphinxAtStartPar
especially for catching OOM Killer and other interesting kernel events that affect processes without giving user\sphinxhyphen{}expected stack traces.

\sphinxAtStartPar
Is dmesg available to users on Aurora worker nodes?

\sphinxAtStartPar
\sphinxcode{\sphinxupquote{mesg}} already outputs JSON, if run with the right parameter.

\sphinxAtStartPar
That should be an hour to prototype alongside workers. Cross reference host\sphinxhyphen{}wide process monitoring as thematically related.


\section{Idea: automatic instrumentation}
\label{\detokenize{index:idea-automatic-instrumentation}}
\index{OpenTelemetry@\spxentry{OpenTelemetry}}\index{idea@\spxentry{idea}!automatic instrumentation@\spxentry{automatic instrumentation}}\ignorespaces 
\sphinxAtStartPar
Projects like OpenTelemetry offer automatic instrumentation. that would be interesting to experiment with here.


\chapter{Moving wide records around}
\label{\detokenize{index:moving-wide-records-around}}\label{\detokenize{index:moving}}
\sphinxAtStartPar
Events are generated in various places (for example, in application code running on HPC cluster worker nodes) and usually the user wants them somewhere else \sphinxhyphen{} for some kind of analysis, in the broad sense ({\hyperref[\detokenize{index:analysing}]{\sphinxcrossref{\DUrole{std,std-ref}{Analysing wide records}}}}).

\sphinxAtStartPar
Concrete mechanisms for moving events 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 and this work should facilitate that rather than being prescriptive.

\sphinxAtStartPar
This chapter talks about different mechanisms that are on offer, and about how configuration might work. It tries to stay away from implementing much new mechanism, but rather tries to focus on integration of what already exists.


\section{Comparison to Parsl logging}
\label{\detokenize{index:comparison-to-parsl-logging}}
\sphinxAtStartPar
also followed by Academy at time of writing

\sphinxAtStartPar
expectation is you send your debugging expert a tarball of logs for them to pore over \sphinxhyphen{} this is extremely asynchronous but a very effective way of moving those records around. it has relatively low effect on performance behaviour: get the logs onto some filesystem while the performance\sphinxhyphen{}critical bit is running, move them from there later on.
\begin{itemize}
\item {} 
\sphinxAtStartPar
poring 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
async movement is much easier than synchronous/realtime movement


\section{Comparison to Parsl Monitoring}
\label{\detokenize{index:comparison-to-parsl-monitoring}}
\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
pluggable radios \sphinxhyphen{} inspiring following configurability model

\sphinxAtStartPar
Radios that exist currently: (TODO: upsides, downsides)
\begin{itemize}
\item {} 
\sphinxAtStartPar
UDP: sends UDP packets at submit side. UDP is unreliable. So events \sphinxstyleemphasis{do} get lost. I think the assumption at implementation time was that UDP packet loss is just some thing your professor tells you about, but clearly doesn’t happen.

\item {} 
\sphinxAtStartPar
filesystem: needs a shared filesystem. One file = one monitoring event. If your filesystem is slow, which it often is, this is slow too.

\item {} 
\sphinxAtStartPar
HTEX: the most efficient, but only works with the High Throughput Executor. Uses the existing HTEX result channel to send back monitoring events.

\item {} 
\sphinxAtStartPar
ZMQ: This is over TCP. Like UDP radio, needs to be able to connect to the submit side. Probably better than UDP, although there’s a TCP and ZMQ session initialization needed at the start of every task, because this radio does not persist connections across tasks. Unlike UDP, on the submit side, is yet another per\sphinxhyphen{}worker file descriptor use, I think, which is a serious scalability limitation.

\item {} 
\sphinxAtStartPar
Python multiprocessing: for sending monitoring events within the same cluster of Python \sphinxtitleref{multiprocessing} proceses: roughly the set of processes that were forked locally by the submit script using \sphinxtitleref{multiprocessing}, so in htex: not the workers and not the interchange.

\end{itemize}

\sphinxAtStartPar
None of these are suitable for cloud\sphinxhyphen{}style environments where there is neither a shared filesystem or clean IP network. So I also prototyped an Academy radio for use with GC+Parsl \sphinxhyphen{} although I would rather use something like Octopus or Chronolog.


\section{Python Configurability}
\label{\detokenize{index:python-configurability}}
\index{Configurability@\spxentry{Configurability}}\index{Python@\spxentry{Python}!Configurability@\spxentry{Configurability}}\ignorespaces 
\sphinxAtStartPar
A soft start in Parsl 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.

\sphinxAtStartPar
The current parsl stuff is not set up for arbitrary log
configuration outside of the submit\sphinxhyphen{}side process: for example,
the worker helpers don’t do any log config at all and rely
on their enclosing per\sphinxhyphen{}executor environments to do it, which
i think some do not.

\sphinxAtStartPar
htex interchange and worker logs have a hardcoded log config
with a single debug boolean.

\sphinxAtStartPar
I’d like to do something a bit more flexible than adding more
parameters, that reflect that in the future people might want
to configure their handlers differently rather than using the
JSONHandler.

\index{Chronolog@\spxentry{Chronolog}}\ignorespaces 
\sphinxAtStartPar
eg. chronolog. pytest metrics observation in other section.

\sphinxAtStartPar
see Parsl monitoring radios configuration model. start prototyping that. note that it doesn’t magically make arbitrary components that aren’t compliant+Python redirectable. but thats fine in the modular approach.

\sphinxAtStartPar
see the existing initialize\_logging which allows arbitrary user configurability at the submit\sphinxhyphen{}process side, by getting parsl completely out of the way and allowing the user to run whatever code they want.


\section{Adventure: Wide records stored as JSON in files}
\label{\detokenize{index:adventure-wide-records-stored-as-json-in-files}}
\sphinxAtStartPar
This prototype stores Parsl logs that have been sent into the Python \sphinxcode{\sphinxupquote{logging}} system as JSON objects, one per line.

\sphinxAtStartPar
This is one of the initial usecases for above configurability.

\sphinxAtStartPar
This was implemented is a straightforward Python logging \sphinxtitleref{Handler} similar to the existing log handlers, the difference being how the output line is formatted.

\sphinxAtStartPar
The files are then moveable using traditional means: for exmaple, the classic “send me a tarball of your run directory”.


\section{Moving in realtime}
\label{\detokenize{index:moving-in-realtime}}
\sphinxAtStartPar
What does realtime mean in this case? mostly a case of what do the ultimate consumers need, rather than any strong technical definition at this stage.

\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.

\sphinxAtStartPar
Parsl already moves some event stuff around the network in realtime: that is the purpose of the monitoring radio system.

\sphinxAtStartPar
following two sections, octopus and chronolog, will talk about doing that.

\sphinxAtStartPar
My initial log\sphinxhyphen{}related work was post\sphinxhyphen{}facto: copy log files around. but there are plenty of mechanisms that should be able to deliver and analyse live, eg built around Diaspora Octopus


\section{Adventure: Diaspora Octopus}
\label{\detokenize{index:adventure-diaspora-octopus}}
\index{Diaspora@\spxentry{Diaspora}!Octopus@\spxentry{Octopus}}\index{Octopus@\spxentry{Octopus}}\index{Kafka@\spxentry{Kafka}}\index{Globus Hosted Services@\spxentry{Globus Hosted Services}!Diaspora@\spxentry{Diaspora}}\ignorespaces 
\sphinxAtStartPar
This is an obvious follow\sphinxhyphen{}on to file\sphinxhyphen{}based JSON logs: the developers still kinda exist, and are friendly.

\index{people@\spxentry{people}!Ryan@\spxentry{Ryan}}\index{people@\spxentry{people}!Haochen@\spxentry{Haochen}}\ignorespaces 
\sphinxAtStartPar
with Ryan and Haochen

\sphinxAtStartPar
This turned into a monster debugging and restructuring session around Octopus reliability.

\sphinxAtStartPar
Ryan has a specific use case he’s trying to implement, that I am helping him with:
\begin{quote}

\sphinxAtStartPar
i mostly want to know when my agents perform their loop so i can hackily use this as a heartbeat to determine if my agents alive, and, when the agent decides to call the llm, i want to know the outcome of that call

\begin{flushright}
---Ryan, on Slack
\end{flushright}
\end{quote}


\section{Idea: Chronolog}
\label{\detokenize{index:idea-chronolog}}
\index{Chronolog@\spxentry{Chronolog}}\index{people@\spxentry{people}!Nishchay@\spxentry{Nishchay}}\index{idea@\spxentry{idea}!Chronolog@\spxentry{Chronolog}}\ignorespaces 
\sphinxAtStartPar
Nishchay did some stuff here. I don’t know what the state is.

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


\section{Adventure: pytest observing interchange variables}
\label{\detokenize{index:adventure-pytest-observing-interchange-variables}}\label{\detokenize{index:pytest-observes-logs}}
\index{pytest@\spxentry{pytest}}\index{Python@\spxentry{Python}!pytest@\spxentry{pytest}}\ignorespaces 
\sphinxAtStartPar
pytest htex task priority test wants to wait for interchange
to have all the submitted tasks \sphinxhyphen{} which happens asynchronously
to submit calls returning. it does that by logfile parsing.
how does that fit into this observability story: there’s a
metric in my prototype for this value (which I used in one
of the other use cases here).

\sphinxAtStartPar
Can do this by re\sphinxhyphen{}parsing the interchange log value. also
could (with suitable configuration) attach a “pytest can
see only metrics” log writer that runs over a unix socket?
in some sense, injecting the relevant observability path
into the interchange code as a configured log handler. that
gives some motivation for the configurability section.

\sphinxAtStartPar
Also attaching a JSON log file to the interchange, and having a tail reader of that. also needs special configuration of interchange I think.


\section{Adventure: Academy agents can report their own relevant logs via action}
\label{\detokenize{index:adventure-academy-agents-can-report-their-own-relevant-logs-via-action}}
\sphinxAtStartPar
A prototype I made for Logan, and also showed to Ryan.

\sphinxAtStartPar
This ties in with Ryan’s Diaspora use case for examining what individual agents are up to.


\chapter{Analysing wide records}
\label{\detokenize{index:analysing-wide-records}}\label{\detokenize{index:analysing}}
\sphinxAtStartPar
At small enough scale, which is actually quite a large number of tasks, given the volumes of data involved, parsing logs into a Python session and using standard Python tools like list comprehensions is a legitimate way to analyse things \sphinxhyphen{} rather than treating this approach as something awkwardly shameful that will be replaced by The Real Thing later. This is especially appealing to Parsl users who tend to be Python data science literate anyway.

\sphinxAtStartPar
That isn’t the only approach and this is also modular: you get the records and can analyse them using whatever tools you personally find appropriate.


\section{Adventure: All events for a task, in two aspects/presentations}
\label{\detokenize{index:adventure-all-events-for-a-task-in-two-aspects-presentations}}
\index{aspect@\spxentry{aspect}}\index{presentation@\spxentry{presentation}}\ignorespaces 
\sphinxAtStartPar
TODO: move this from elsewhere, tidyup/modularise the code so it is presentable as a good first example.
Show what it looks like: with monitoring.db import only; with full observability prototype.

\sphinxAtStartPar
emphasise: the first one is available now without needing to modify Parsl core.

\sphinxAtStartPar
emphasise: the same analytics code gives different results without needing much modification, given different \sphinxstyleemphasis{aspects} / \sphinxstyleemphasis{presentations} of the same run \sphinxhyphen{} see {\hyperref[\detokenize{index:partialdata}]{\sphinxcrossref{\DUrole{std,std-ref}{Optional and missing data in observability}}}}

\sphinxAtStartPar
emphasise: integration: there are resource records for tasks via monitoring, and htex internals via JSON logs: neither is a superset of the other.


\subsection{Task events from the monitoring.db presentation}
\label{\detokenize{index:task-events-from-the-monitoring-db-presentation}}
\sphinxAtStartPar
Import the monitoring.db created by unmodified master Parsl, and see how many event records there are:

\begin{sphinxVerbatim}[commandchars=\\\{\}]
\PYG{g+gp}{\PYGZgt{}\PYGZgt{}\PYGZgt{} }\PYG{k+kn}{from} \PYG{n+nn}{parsl}\PYG{n+nn}{.}\PYG{n+nn}{observability}\PYG{n+nn}{.}\PYG{n+nn}{import\PYGZus{}monitoring\PYGZus{}db} \PYG{k+kn}{import} \PYG{n}{import\PYGZus{}db}
\PYG{g+gp}{\PYGZgt{}\PYGZgt{}\PYGZgt{} }\PYG{n}{l}\PYG{o}{=}\PYG{n}{import\PYGZus{}db}\PYG{p}{(}\PYG{l+s+s2}{\PYGZdq{}}\PYG{l+s+s2}{runinfo/monitoring.db}\PYG{l+s+s2}{\PYGZdq{}}\PYG{p}{)}
\PYG{g+gp}{\PYGZgt{}\PYGZgt{}\PYGZgt{} }\PYG{n+nb}{len}\PYG{p}{(}\PYG{n}{l}\PYG{p}{)}
\PYG{g+go}{14596}
\end{sphinxVerbatim}

\sphinxAtStartPar
Here’s an example event record:

\begin{sphinxVerbatim}[commandchars=\\\{\}]
\PYG{g+gp}{\PYGZgt{}\PYGZgt{}\PYGZgt{} }\PYG{n}{l}\PYG{p}{[}\PYG{l+m+mi}{0}\PYG{p}{]}
\PYG{g+go}{\PYGZob{}\PYGZsq{}parsl\PYGZus{}dfk\PYGZsq{}: \PYGZsq{}a08cc383\PYGZhy{}927a\PYGZhy{}4ce8\PYGZhy{}926b\PYGZhy{}f31e52e6edc2\PYGZsq{}, \PYGZsq{}parsl\PYGZus{}task\PYGZus{}id\PYGZsq{}: 0, \PYGZsq{}parsl\PYGZus{}try\PYGZus{}id\PYGZsq{}: 0, \PYGZsq{}parsl\PYGZus{}task\PYGZus{}status\PYGZsq{}: \PYGZsq{}pending\PYGZsq{}, \PYGZsq{}created\PYGZsq{}: 1764589563.205463\PYGZcb{}}
\end{sphinxVerbatim}

\sphinxAtStartPar
Now identify all the tasks, keyed hierarchically by DFK ID and task number:

\begin{sphinxVerbatim}[commandchars=\\\{\}]
\PYG{g+gp}{\PYGZgt{}\PYGZgt{}\PYGZgt{} }\PYG{n}{tasks} \PYG{o}{=} \PYG{p}{\PYGZob{}} \PYG{p}{(}\PYG{n}{event}\PYG{p}{[}\PYG{l+s+s1}{\PYGZsq{}}\PYG{l+s+s1}{parsl\PYGZus{}dfk}\PYG{l+s+s1}{\PYGZsq{}}\PYG{p}{]}\PYG{p}{,} \PYG{n}{event}\PYG{p}{[}\PYG{l+s+s1}{\PYGZsq{}}\PYG{l+s+s1}{parsl\PYGZus{}task\PYGZus{}id}\PYG{l+s+s1}{\PYGZsq{}}\PYG{p}{]}\PYG{p}{)} \PYG{k}{for} \PYG{n}{event} \PYG{o+ow}{in} \PYG{n}{l} \PYG{k}{if} \PYG{l+s+s1}{\PYGZsq{}}\PYG{l+s+s1}{parsl\PYGZus{}dfk}\PYG{l+s+s1}{\PYGZsq{}} \PYG{o+ow}{in} \PYG{n}{event} \PYG{o+ow}{and} \PYG{l+s+s1}{\PYGZsq{}}\PYG{l+s+s1}{parsl\PYGZus{}task\PYGZus{}id}\PYG{l+s+s1}{\PYGZsq{}} \PYG{o+ow}{in} \PYG{n}{event} \PYG{p}{\PYGZcb{}}
\PYG{g+gp}{\PYGZgt{}\PYGZgt{}\PYGZgt{} }\PYG{n+nb}{len}\PYG{p}{(}\PYG{n}{tasks}\PYG{p}{)}
\PYG{g+go}{2432}
\end{sphinxVerbatim}

\sphinxAtStartPar
and pick one randomly:

\begin{sphinxVerbatim}[commandchars=\\\{\}]
\PYG{g+gp}{\PYGZgt{}\PYGZgt{}\PYGZgt{} }\PYG{k+kn}{import} \PYG{n+nn}{random}
\PYG{g+gp}{\PYGZgt{}\PYGZgt{}\PYGZgt{} }\PYG{n}{random}\PYG{o}{.}\PYG{n}{choice}\PYG{p}{(}\PYG{n+nb}{list}\PYG{p}{(}\PYG{n}{tasks}\PYG{p}{)}\PYG{p}{)}
\PYG{g+go}{(\PYGZsq{}a08cc383\PYGZhy{}927a\PYGZhy{}4ce8\PYGZhy{}926b\PYGZhy{}f31e52e6edc2\PYGZsq{}, 72)}
\end{sphinxVerbatim}

\sphinxAtStartPar
That’s task 72 of run \sphinxcode{\sphinxupquote{a08cc383\sphinxhyphen{}927a\sphinxhyphen{}4ce8\sphinxhyphen{}926b\sphinxhyphen{}f31e52e6edc2}}.

\sphinxAtStartPar
Now pick out all the records that are labelled as part of that task, and print them nicely:

\begin{sphinxVerbatim}[commandchars=\\\{\}]
\PYG{g+gp}{\PYGZgt{}\PYGZgt{}\PYGZgt{} }\PYG{n}{events} \PYG{o}{=} \PYG{p}{[}\PYG{n}{event} \PYG{k}{for} \PYG{n}{event} \PYG{o+ow}{in} \PYG{n}{l} \PYG{k}{if} \PYG{n}{event}\PYG{o}{.}\PYG{n}{get}\PYG{p}{(}\PYG{l+s+s1}{\PYGZsq{}}\PYG{l+s+s1}{parsl\PYGZus{}dfk}\PYG{l+s+s1}{\PYGZsq{}}\PYG{p}{,} \PYG{k+kc}{None}\PYG{p}{)} \PYG{o}{==} \PYG{l+s+s1}{\PYGZsq{}}\PYG{l+s+s1}{a08cc383\PYGZhy{}927a\PYGZhy{}4ce8\PYGZhy{}926b\PYGZhy{}f31e52e6edc2}\PYG{l+s+s1}{\PYGZsq{}} \PYG{o+ow}{and} \PYG{n}{event}\PYG{o}{.}\PYG{n}{get}\PYG{p}{(}\PYG{l+s+s1}{\PYGZsq{}}\PYG{l+s+s1}{parsl\PYGZus{}task\PYGZus{}id}\PYG{l+s+s1}{\PYGZsq{}}\PYG{p}{,} \PYG{k+kc}{None}\PYG{p}{)} \PYG{o}{==} \PYG{l+m+mi}{72}\PYG{p}{]}


\PYG{g+gp}{\PYGZgt{}\PYGZgt{}\PYGZgt{} }\PYG{k}{for} \PYG{n}{event} \PYG{o+ow}{in} \PYG{n+nb}{sorted}\PYG{p}{(}\PYG{n}{events}\PYG{p}{,} \PYG{n}{key}\PYG{o}{=}\PYG{k}{lambda} \PYG{n}{event}\PYG{p}{:} \PYG{n+nb}{float}\PYG{p}{(}\PYG{n}{event}\PYG{p}{[}\PYG{l+s+s1}{\PYGZsq{}}\PYG{l+s+s1}{created}\PYG{l+s+s1}{\PYGZsq{}}\PYG{p}{]}\PYG{p}{)}\PYG{p}{)}\PYG{p}{:} \PYG{n+nb}{print}\PYG{p}{(}\PYG{n}{event}\PYG{p}{)}
\PYG{g+gp}{...}
\PYG{g+go}{\PYGZob{}\PYGZsq{}parsl\PYGZus{}dfk\PYGZsq{}: \PYGZsq{}a08cc383\PYGZhy{}927a\PYGZhy{}4ce8\PYGZhy{}926b\PYGZhy{}f31e52e6edc2\PYGZsq{}, \PYGZsq{}parsl\PYGZus{}task\PYGZus{}id\PYGZsq{}: 72, \PYGZsq{}parsl\PYGZus{}try\PYGZus{}id\PYGZsq{}: 0, \PYGZsq{}parsl\PYGZus{}task\PYGZus{}status\PYGZsq{}: \PYGZsq{}pending\PYGZsq{}, \PYGZsq{}created\PYGZsq{}: 1764589576.775231\PYGZcb{}}
\PYG{g+go}{\PYGZob{}\PYGZsq{}parsl\PYGZus{}dfk\PYGZsq{}: \PYGZsq{}a08cc383\PYGZhy{}927a\PYGZhy{}4ce8\PYGZhy{}926b\PYGZhy{}f31e52e6edc2\PYGZsq{}, \PYGZsq{}parsl\PYGZus{}task\PYGZus{}id\PYGZsq{}: 72, \PYGZsq{}parsl\PYGZus{}try\PYGZus{}id\PYGZsq{}: 0, \PYGZsq{}parsl\PYGZus{}task\PYGZus{}status\PYGZsq{}: \PYGZsq{}launched\PYGZsq{}, \PYGZsq{}created\PYGZsq{}: 1764589577.435498\PYGZcb{}}
\PYG{g+go}{\PYGZob{}\PYGZsq{}parsl\PYGZus{}dfk\PYGZsq{}: \PYGZsq{}a08cc383\PYGZhy{}927a\PYGZhy{}4ce8\PYGZhy{}926b\PYGZhy{}f31e52e6edc2\PYGZsq{}, \PYGZsq{}parsl\PYGZus{}task\PYGZus{}id\PYGZsq{}: 72, \PYGZsq{}parsl\PYGZus{}try\PYGZus{}id\PYGZsq{}: 0, \PYGZsq{}parsl\PYGZus{}task\PYGZus{}status\PYGZsq{}: \PYGZsq{}running\PYGZsq{}, \PYGZsq{}created\PYGZsq{}: 1764589577.472009\PYGZcb{}}
\PYG{g+go}{\PYGZob{}\PYGZsq{}parsl\PYGZus{}try\PYGZus{}id\PYGZsq{}: 0, \PYGZsq{}parsl\PYGZus{}task\PYGZus{}id\PYGZsq{}: 72, \PYGZsq{}parsl\PYGZus{}dfk\PYGZsq{}: \PYGZsq{}a08cc383\PYGZhy{}927a\PYGZhy{}4ce8\PYGZhy{}926b\PYGZhy{}f31e52e6edc2\PYGZsq{}, \PYGZsq{}created\PYGZsq{}: 1764589577.514019, \PYGZsq{}resource\PYGZus{}monitoring\PYGZus{}interval\PYGZsq{}: 1.0, \PYGZsq{}psutil\PYGZus{}process\PYGZus{}pid\PYGZsq{}: 10680, \PYGZsq{}psutil\PYGZus{}process\PYGZus{}memory\PYGZus{}percent\PYGZsq{}: 1.2360561455881223, \PYGZsq{}psutil\PYGZus{}process\PYGZus{}children\PYGZus{}count\PYGZsq{}: 1.0, \PYGZsq{}psutil\PYGZus{}process\PYGZus{}time\PYGZus{}user\PYGZsq{}: 1.26, \PYGZsq{}psutil\PYGZus{}process\PYGZus{}time\PYGZus{}system\PYGZsq{}: 0.21000000000000002, \PYGZsq{}psutil\PYGZus{}process\PYGZus{}memory\PYGZus{}virtual\PYGZsq{}: 416145408.0, \PYGZsq{}psutil\PYGZus{}process\PYGZus{}memory\PYGZus{}resident\PYGZsq{}: 203653120.0, \PYGZsq{}psutil\PYGZus{}process\PYGZus{}disk\PYGZus{}read\PYGZsq{}: 32585809.0, \PYGZsq{}psutil\PYGZus{}process\PYGZus{}disk\PYGZus{}write\PYGZsq{}: 20895.0, \PYGZsq{}psutil\PYGZus{}process\PYGZus{}status\PYGZsq{}: \PYGZsq{}sleeping\PYGZsq{}, \PYGZsq{}psutil\PYGZus{}cpu\PYGZus{}num\PYGZsq{}: \PYGZsq{}3\PYGZsq{}, \PYGZsq{}psutil\PYGZus{}process\PYGZus{}num\PYGZus{}ctx\PYGZus{}switches\PYGZus{}voluntary\PYGZsq{}: 59.0, \PYGZsq{}psutil\PYGZus{}process\PYGZus{}num\PYGZus{}ctx\PYGZus{}switches\PYGZus{}involuntary\PYGZsq{}: 396.0\PYGZcb{}}
\PYG{g+go}{\PYGZob{}\PYGZsq{}parsl\PYGZus{}try\PYGZus{}id\PYGZsq{}: 0, \PYGZsq{}parsl\PYGZus{}task\PYGZus{}id\PYGZsq{}: 72, \PYGZsq{}parsl\PYGZus{}dfk\PYGZsq{}: \PYGZsq{}a08cc383\PYGZhy{}927a\PYGZhy{}4ce8\PYGZhy{}926b\PYGZhy{}f31e52e6edc2\PYGZsq{}, \PYGZsq{}created\PYGZsq{}: 1764589577.566039, \PYGZsq{}resource\PYGZus{}monitoring\PYGZus{}interval\PYGZsq{}: 1.0, \PYGZsq{}psutil\PYGZus{}process\PYGZus{}pid\PYGZsq{}: 10680, \PYGZsq{}psutil\PYGZus{}process\PYGZus{}memory\PYGZus{}percent\PYGZsq{}: 1.2366030730861701, \PYGZsq{}psutil\PYGZus{}process\PYGZus{}children\PYGZus{}count\PYGZsq{}: 1.0, \PYGZsq{}psutil\PYGZus{}process\PYGZus{}time\PYGZus{}user\PYGZsq{}: 1.28, \PYGZsq{}psutil\PYGZus{}process\PYGZus{}time\PYGZus{}system\PYGZsq{}: 0.22, \PYGZsq{}psutil\PYGZus{}process\PYGZus{}memory\PYGZus{}virtual\PYGZsq{}: 416145408.0, \PYGZsq{}psutil\PYGZus{}process\PYGZus{}memory\PYGZus{}resident\PYGZsq{}: 203661312.0, \PYGZsq{}psutil\PYGZus{}process\PYGZus{}disk\PYGZus{}read\PYGZsq{}: 32995622.0, \PYGZsq{}psutil\PYGZus{}process\PYGZus{}disk\PYGZus{}write\PYGZsq{}: 26441.0, \PYGZsq{}psutil\PYGZus{}process\PYGZus{}status\PYGZsq{}: \PYGZsq{}sleeping\PYGZsq{}, \PYGZsq{}psutil\PYGZus{}cpu\PYGZus{}num\PYGZsq{}: \PYGZsq{}3\PYGZsq{}, \PYGZsq{}psutil\PYGZus{}process\PYGZus{}num\PYGZus{}ctx\PYGZus{}switches\PYGZus{}voluntary\PYGZsq{}: 69.0, \PYGZsq{}psutil\PYGZus{}process\PYGZus{}num\PYGZus{}ctx\PYGZus{}switches\PYGZus{}involuntary\PYGZsq{}: 454.0\PYGZcb{}}
\PYG{g+go}{\PYGZob{}\PYGZsq{}parsl\PYGZus{}try\PYGZus{}id\PYGZsq{}: 0, \PYGZsq{}parsl\PYGZus{}task\PYGZus{}id\PYGZsq{}: 72, \PYGZsq{}parsl\PYGZus{}dfk\PYGZsq{}: \PYGZsq{}a08cc383\PYGZhy{}927a\PYGZhy{}4ce8\PYGZhy{}926b\PYGZhy{}f31e52e6edc2\PYGZsq{}, \PYGZsq{}created\PYGZsq{}: 1764589577.600372, \PYGZsq{}resource\PYGZus{}monitoring\PYGZus{}interval\PYGZsq{}: 1.0, \PYGZsq{}psutil\PYGZus{}process\PYGZus{}pid\PYGZsq{}: 10680, \PYGZsq{}psutil\PYGZus{}process\PYGZus{}memory\PYGZus{}percent\PYGZsq{}: 1.2366030730861701, \PYGZsq{}psutil\PYGZus{}process\PYGZus{}children\PYGZus{}count\PYGZsq{}: 1.0, \PYGZsq{}psutil\PYGZus{}process\PYGZus{}time\PYGZus{}user\PYGZsq{}: 1.3, \PYGZsq{}psutil\PYGZus{}process\PYGZus{}time\PYGZus{}system\PYGZsq{}: 0.23, \PYGZsq{}psutil\PYGZus{}process\PYGZus{}memory\PYGZus{}virtual\PYGZsq{}: 416145408.0, \PYGZsq{}psutil\PYGZus{}process\PYGZus{}memory\PYGZus{}resident\PYGZsq{}: 203444224.0, \PYGZsq{}psutil\PYGZus{}process\PYGZus{}disk\PYGZus{}read\PYGZsq{}: 33404930.0, \PYGZsq{}psutil\PYGZus{}process\PYGZus{}disk\PYGZus{}write\PYGZsq{}: 33922.0, \PYGZsq{}psutil\PYGZus{}process\PYGZus{}status\PYGZsq{}: \PYGZsq{}sleeping\PYGZsq{}, \PYGZsq{}psutil\PYGZus{}cpu\PYGZus{}num\PYGZsq{}: \PYGZsq{}3\PYGZsq{}, \PYGZsq{}psutil\PYGZus{}process\PYGZus{}num\PYGZus{}ctx\PYGZus{}switches\PYGZus{}voluntary\PYGZsq{}: 74.0, \PYGZsq{}psutil\PYGZus{}process\PYGZus{}num\PYGZus{}ctx\PYGZus{}switches\PYGZus{}involuntary\PYGZsq{}: 465.0\PYGZcb{}}
\PYG{g+go}{\PYGZob{}\PYGZsq{}parsl\PYGZus{}dfk\PYGZsq{}: \PYGZsq{}a08cc383\PYGZhy{}927a\PYGZhy{}4ce8\PYGZhy{}926b\PYGZhy{}f31e52e6edc2\PYGZsq{}, \PYGZsq{}parsl\PYGZus{}task\PYGZus{}id\PYGZsq{}: 72, \PYGZsq{}parsl\PYGZus{}try\PYGZus{}id\PYGZsq{}: 0, \PYGZsq{}parsl\PYGZus{}task\PYGZus{}status\PYGZsq{}: \PYGZsq{}running\PYGZus{}ended\PYGZsq{}, \PYGZsq{}created\PYGZsq{}: 1764589577.646802\PYGZcb{}}
\PYG{g+go}{\PYGZob{}\PYGZsq{}parsl\PYGZus{}dfk\PYGZsq{}: \PYGZsq{}a08cc383\PYGZhy{}927a\PYGZhy{}4ce8\PYGZhy{}926b\PYGZhy{}f31e52e6edc2\PYGZsq{}, \PYGZsq{}parsl\PYGZus{}task\PYGZus{}id\PYGZsq{}: 72, \PYGZsq{}parsl\PYGZus{}try\PYGZus{}id\PYGZsq{}: 0, \PYGZsq{}parsl\PYGZus{}task\PYGZus{}status\PYGZsq{}: \PYGZsq{}exec\PYGZus{}done\PYGZsq{}, \PYGZsq{}created\PYGZsq{}: 1764589577.671692\PYGZcb{}}
\end{sphinxVerbatim}

\sphinxAtStartPar
So what comes out is some records which reflect the change in the task status as seen by the monitoring system (Which includes \sphinxcode{\sphinxupquote{running}} and \sphinxcode{\sphinxupquote{running\_ended}} status that isn’t known to the DFK) and while the task is running, some resource monitoring records.

\sphinxAtStartPar
This is basically a reformatting of records you could get by running SQL queries against \sphinxcode{\sphinxupquote{monitoring.db}}, which is unsurprising: the only data source used was that database file.


\subsection{Task events from a JSON logging presentation}
\label{\detokenize{index:task-events-from-a-json-logging-presentation}}
\sphinxAtStartPar
I’m going to look at that same task (task 72 of run \sphinxcode{\sphinxupquote{a08cc383\sphinxhyphen{}927a\sphinxhyphen{}4ce8\sphinxhyphen{}926b\sphinxhyphen{}f31e52e6edc2}}) from the perspective of JSON logs now \textendash{} Parsl modified to output richer log files in JSON format with more machine readable metadata. TODO: reference the relevant generating events section.

\sphinxAtStartPar
All I am going to change is the importer command. I’m going to use the same selector and printing code shown above. So what we should get is a different \sphinxstyleemphasis{presentation} or \sphinxstyleemphasis{aspect} of the same task.


\section{Adventure: The minimal change necessary to get htex task logs into the above task trace}
\label{\detokenize{index:adventure-the-minimal-change-necessary-to-get-htex-task-logs-into-the-above-task-trace}}
\sphinxAtStartPar
This is probably one log line? To perform the join between IDs? Plus JSON logs.

\sphinxAtStartPar
TODO: present the changes I’ve done, but minimised to only this one change.


\section{Adventure: blog: Visualization for task prioritisation}
\label{\detokenize{index:adventure-blog-visualization-for-task-prioritisation}}
\sphinxAtStartPar
(two graphs that are already in parsl\sphinxhyphen{}visualize but probably\sphinxhyphen{}buggy \sphinxhyphen{} see \#4021)

\sphinxAtStartPar
this uses replay\sphinxhyphen{}monitoring.db approach with no runtime changes. because the work I did there was in parsl master, but I want to do custom visualizations.

\sphinxAtStartPar
{[}TODO: link to blog post{]}

\sphinxAtStartPar
work towards a second blog post here. now most of the mechanics are worked out.

\sphinxAtStartPar
Step 2 of that: This was a second requirement on prioritisation from DESC.

\sphinxAtStartPar
use an A\sphinxhyphen{}\textgreater{}B1/B2\sphinxhyphen{}\textgreater{}C three step diamond\sphinxhyphen{}dag because its a bit less trivial.

\sphinxAtStartPar
visualization of task types for jim’s follow on question: how can we adapt step 1 to colour by app name? It’s not well presented in parsl\sphinxhyphen{}visualize because that focuses on state transitions rather than on app identity as the primary colour\sphinxhyphen{}key.

\sphinxAtStartPar
Visualisation also coloured by task\sphinxhyphen{}chain/task\sphinxhyphen{}cluster to show a cluster based visualization.

\sphinxAtStartPar
priority modes: natural (submit\sphinxhyphen{}to\sphinxhyphen{}htex order, “as unblocked” order), random (priority=random.random()), chain priority by chain depth, chain priority by cluster. the last two should be “the same” in plot 4 i hope. unclear what random mode will do, if anything? i guess get more later\sphinxhyphen{}unlocked tasks randomly in there? random is always interesting to me as pushing things away from degenerate cases \sphinxhyphen{} i this case “Cs run last”

\sphinxAtStartPar
plot 1: task run/running\_ended individual tasks, coloured by parsl app name

\sphinxAtStartPar
plot 2: tasks of each of two kinds, coloured by parsl app name

\sphinxAtStartPar
plot 3: tasks running by type, with no priority, with two different priority schemes.

\sphinxAtStartPar
plot 4: Visualisation of end\sphinxhyphen{}result completed \sphinxhyphen{} i.e. how many C tasks have completed over time, ignoring everything else about the inside. with prioritisation and with my two prioritisation schemes.

\sphinxAtStartPar
Plot 4 should be the top level plot set \sphinxhyphen{} because it an example “goal” of the prioritisation, I think. (might be because you want results sooner, might be because C completing means you can delete a load of intermediate temporary data sooner).

\sphinxAtStartPar
From an observability perspective: the task chain identity is not known to Parsl. this is additional metadata, that in observability concepts, is added on by a “higher level system” and joined on at analysis time. the application knows about it, and the querier knows about it. none of the intermediate execution or observability infrastructure knows about it.
\begin{enumerate}
\sphinxsetlistlabels{\arabic}{enumi}{enumii}{}{.}%
\item {} 
\sphinxAtStartPar
the status table rerun gives runtimes for plotting based on Parsl level dfk/task/try but doesn’t give any metadata about those. such as app name. in SQL this is added on as a JOIN, and so it is here too \sphinxhyphen{} rerun the tasks table as a sequence of log records \sphinxhyphen{} note that they don’t have a notion of “created” here because they are records but aren’t from a point in time, instead an already aggregated set of information. don’t let that scare you. observability records don’t have to look like the output of a printf!

\end{enumerate}


\section{Task flow logs through the whole system}
\label{\detokenize{index:task-flow-logs-through-the-whole-system}}
\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.


\section{Algebra of rearranging and querying wide events}
\label{\detokenize{index:algebra-of-rearranging-and-querying-wide-events}}
\sphinxAtStartPar
These are some of the standard patterns I’ve found useful enough and straightforward to turn into library functions in the \sphinxtitleref{parsl.observabilty} module.

\sphinxAtStartPar
look at relational algebra for phrasing and concepts


\subsection{functorial}
\label{\detokenize{index:functorial}}
\sphinxAtStartPar
These operations are \sphinxstyleemphasis{functorial} in the sense that they operate on individual event records without regard for the context those records are in.

\sphinxAtStartPar
Widening

\sphinxAtStartPar
widen\sphinxhyphen{}by\sphinxhyphen{}constant: if we import a new log file but we know its broader context some other way, perhaps because it came from a known directory inside a parsl rundir (eg work queue’s )

\sphinxAtStartPar
relabelling \sphinxhyphen{} to make names align from multiple sources, or to add distinction from multiple sources


\subsection{non\sphinxhyphen{}functorial}
\label{\detokenize{index:non-functorial}}
\sphinxAtStartPar
These operations are \sphinxstyleemphasis{not functorial}. For example, widening\sphinxhyphen{}by\sphinxhyphen{}implication copies information between event records that are somehow grouped into a collection together, so cannot be implemented on a record\sphinxhyphen{}by\sphinxhyphen{}record basis.

\sphinxAtStartPar
post\sphinxhyphen{}facto relationship establishment using grouping and key implication

\sphinxAtStartPar
used where you might use a \sphinxcode{\sphinxupquote{JOIN}} in SQL.

\index{relational algebra@\spxentry{relational algebra}}\ignorespaces 
\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

\sphinxAtStartPar
joins can send info back in time: if we have a span but don’t know which parsl task it belongs to at the start, only later, we can use joins to bring that information from the future.


\subsubsection{keys imply key operator}
\label{\detokenize{index:keys-imply-key-operator}}
\sphinxAtStartPar
{[}l\_keys{]} implies {[}r\_key{]} over {[}collection{]}:
\begin{itemize}
\item {} 
\sphinxAtStartPar
if any log selected by l\_keys contains an r\_key, that r\_key is unique (auto\sphinxhyphen{}check\sphinxhyphen{}that) and should be attached to every log record selected by l\_keys. Use case: widening the task reception span in idris2interchange to be labelled with htex\_task\_id

\item {} 
\sphinxAtStartPar
this is functional dependency: \sphinxurl{https://en.wikipedia.org/wiki/Functional\_dependency}

\end{itemize}

\sphinxAtStartPar
fixpoint notions that might need to be incorporated into the query model in Python code (so that a fixpoint can be converged to across non\sphinxhyphen{}local widening queries \sphinxhyphen{} see idris2interchange usecase notes)

\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.


\section{Adventure: Browser UI}
\label{\detokenize{index:adventure-browser-ui}}
\index{web browser@\spxentry{web browser}}\ignorespaces 
\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”)

\sphinxAtStartPar
But the parsl\sphinxhyphen{}visualize UI is so limited, it only has a handful of graphs to recreate. And some of them do not make sense to me so I would not recreate them.

\sphinxAtStartPar
I am not super excited about building UIs but it would probably be interesting to build something simple that can do a few queries and graphs to demonstrate log analysis in clickable form.

\sphinxAtStartPar
And then I could put in the analyses I have made (other graphs/reports) too, and also have it work with academy logs right away. and be ready to pull in other JSON log files as a more advanced implementation motivating JSON/wide events.

\sphinxAtStartPar
Use python and matplotlib, no web\sphinxhyphen{}specific stuff, to promote people who have done local scripting putting new plots into the UI, and promote using the graph code from the visualiser in own local scripting.

\sphinxAtStartPar
Make it able to address a whole collection of monitoring.db runs at once \sphinxhyphen{} not only one chosen workflow.

\sphinxAtStartPar
Use a parsl\sphinxhyphen{}aware list of quasi\sphinxhyphen{}hierarchical key names to drive narrow\sphinxhyphen{}down UI:

\sphinxAtStartPar
eg: pick dfk.   pick: parsl task, parsl try,   or  executor, then executor task, or executor then block then task.

\sphinxAtStartPar
htex instance/block/manager/worker/htex\_task

\sphinxAtStartPar
htex instance/block/manager/worker is an execution location \sphinxhyphen{} how an htex instance is identified is different between real Parsl and GC: in real parsl, its a dfk id/executor label.

\sphinxAtStartPar
are all graphs relevant for all key selections? or should eg. a block duration/count graph only appear in certain situations? eg if we’ve focused on one task\sphinxhyphen{}try, does that mean… no block status info and so no block graph? graphs could be enabled by: “if you see records like this, this graph is relevant”. That would allow eg. enabling htex or WQ specific plots if we see (with more merged info) some htex or WQ specific data. If we only see academy or GC logs, should only report about them.

\sphinxAtStartPar
Recreate block vs task count graph from Matthews paper.

\sphinxAtStartPar
Aim for first iteration to work against current monitoring.db format so it can be tried out in a separate install against production runs, distinct from all other observability work. Exensibility there right from the start to allow that to extend for importing new data and plugging in plots and reports about new data.

\sphinxAtStartPar
two obvious non\sphinxhyphen{}monitoring.db extensions: what’s happening with managers in blocks. whats happening with work queue. these are both executor specific, and don’t fit the monitoring.db schema so well. so clear demos of what could be done better.


\subsection{Idea: Streaming\sphinxhyphen{}fold web UI}
\label{\detokenize{index:idea-streaming-fold-web-ui}}
\index{idea@\spxentry{idea}!streaming\sphinxhyphen{}fold web UI@\spxentry{streaming\sphinxhyphen{}fold web UI}}\ignorespaces 
\sphinxAtStartPar
what operators can be build with a streaming\sphinxhyphen{}fold? to give live updates as logs come in.
(eg tail from a filesystem in the simplest case)

\sphinxAtStartPar
joins are the hard bit there, I think \sphinxhyphen{} but a fundep operator is at least constrained in its behaviour: cache keyed\sphinxhyphen{}but\sphinxhyphen{}unjoined blocks, if we see a key record, emit the whole block and forget it.

\sphinxAtStartPar
spend 1 day prototyping this.

\sphinxAtStartPar
counters, lists, a few graph types, drop downs/select fields


\section{python side query model}
\label{\detokenize{index:python-side-query-model}}
\sphinxAtStartPar
log entries by reference (in lists and dicts). deliberately mutating the only copy of a log record, stored across multiple structs, is a feature not a bug. lets us select and modify and then return to the original structure. avoids copying the actual log records ever (except when explicit) and instead deal in object references.

\sphinxAtStartPar
use comprehension\sphinxhyphen{}style query notation to be reminiscent of other query languages.


\section{academy visualization}
\label{\detokenize{index:academy-visualization}}
\sphinxAtStartPar
message diagram \sphinxhyphen{} include here \sphinxhyphen{} for multi agent generator
example I made for Logan.


\section{HTEX vs WQ questions}
\label{\detokenize{index:htex-vs-wq-questions}}
\sphinxAtStartPar
Some questions don’t make sense outside of the fixed worker count model.
That is the htex tradition, but htex MPI mode has moved away from that
with tasks able to request arbitrary amounts of some resource (mpi ranks) and
WQ is heavily built around that too \sphinxhyphen{} DESC applications commonly use memory
rather than core count as their resource constrained on a node. It is a
feature, not a bug, that these features are different across executors.


\section{Other record storage systems}
\label{\detokenize{index:other-record-storage-systems}}
\index{SQLite@\spxentry{SQLite}}\ignorespaces 
\sphinxAtStartPar
SQLite \sphinxhyphen{} I experimented with this as part of my earlier DNPC work, using SQL as a query language over JSON records.


\section{type checking event schemas}
\label{\detokenize{index:type-checking-event-schemas}}
\sphinxAtStartPar
there is no observability schema overall, but individual components will have definitions which may be formal or informal. so it might be useful to be able to perform type checking on output records.

\sphinxAtStartPar
there can be type\sphinxhyphen{}checking/linting gradual type check of emitted events though:
a couple of places:
\begin{itemize}
\item {} 
\sphinxAtStartPar
generate the extras by helper functions that force the record have certain fields (which should be referred to in the generating logs section)

\item {} 
\sphinxAtStartPar
linting rules about x implies y, that can be regarded as hard type checking rules or soft rules depending on how you invoke such a tool

\end{itemize}


\section{Writing out JSON events (or other formats) after performing query work}
\label{\detokenize{index:writing-out-json-events-or-other-formats-after-performing-query-work}}
\sphinxAtStartPar
because maybe you’ve got somewhere better to process these results than the Python runtime.

\sphinxAtStartPar
or maybe you processed them somewhere that wasn’t python and now want them in Python. JSON as the interface layer.


\chapter{Adventure: Academy vs Globus Compute}
\label{\detokenize{index:adventure-academy-vs-globus-compute}}
\sphinxAtStartPar
This isn’t well documented in general and I feel like logging is especially neglected (although only part of the complexity here: code deployment is another part.) So I will work on bashing the two together with a hostile commentary.


\section{getting started}
\label{\detokenize{index:getting-started}}
\sphinxAtStartPar
Built \sphinxcode{\sphinxupquote{cloudlump}} docker image for me to run locally to keep my deployments isolated from each other and from my home directory, to force me to be a bit more explicit about how to get things to work.

\sphinxAtStartPar
This is enough to start a GC endpoint in one container and then run \sphinxcode{\sphinxupquote{assert gcs.Executor().submit(abs, \sphinxhyphen{}7).result() == 7}}

\begin{sphinxVerbatim}[commandchars=\\\{\}]
\PYG{g+gp}{\PYGZgt{}\PYGZgt{}\PYGZgt{} }\PYG{k+kn}{import} \PYG{n+nn}{globus\PYGZus{}compute\PYGZus{}sdk} \PYG{k}{as} \PYG{n+nn}{s}
\PYG{g+gp}{\PYGZgt{}\PYGZgt{}\PYGZgt{} }\PYG{n}{e}\PYG{o}{=}\PYG{n}{s}\PYG{o}{.}\PYG{n}{Executor}\PYG{p}{(}\PYG{n}{endpoint\PYGZus{}id}\PYG{o}{=}\PYG{l+s+s1}{\PYGZsq{}}\PYG{l+s+s1}{5c7202b5\PYGZhy{}d022\PYGZhy{}4534\PYGZhy{}a399\PYGZhy{}21d4356129be}\PYG{l+s+s1}{\PYGZsq{}}\PYG{p}{)}
\PYG{g+gp}{\PYGZgt{}\PYGZgt{}\PYGZgt{} }\PYG{c+c1}{\PYGZsh{} authorization happens here}
\PYG{g+gp}{\PYGZgt{}\PYGZgt{}\PYGZgt{} }\PYG{k}{assert} \PYG{n}{e}\PYG{o}{.}\PYG{n}{submit}\PYG{p}{(}\PYG{n+nb}{abs}\PYG{p}{,} \PYG{o}{\PYGZhy{}}\PYG{l+m+mi}{7}\PYG{p}{)}\PYG{o}{.}\PYG{n}{result}\PYG{p}{(}\PYG{p}{)} \PYG{o}{==} \PYG{l+m+mi}{7}
\end{sphinxVerbatim}

\sphinxAtStartPar
In this environment, the only task reference is in \sphinxcode{\sphinxupquote{\textasciitilde{}/.globus\_compute/uep.5c7202b5\sphinxhyphen{}d022\sphinxhyphen{}4534\sphinxhyphen{}a399\sphinxhyphen{}21d4356129be.bac77271\sphinxhyphen{}9a60\sphinxhyphen{}cad7\sphinxhyphen{}c4e9\sphinxhyphen{}0eb689ddf4d1/GlobusComputeEngine\sphinxhyphen{}HighThroughputExecutor/block\sphinxhyphen{}0/beb8bc8bb003/worker\_0.log}} using htex task numbers. This is not correlated with anything visible on the submit side \textendash{} which is a UUID globus compute task ID:

\begin{sphinxVerbatim}[commandchars=\\\{\}]
\PYG{g+gp}{\PYGZgt{}\PYGZgt{}\PYGZgt{} }\PYG{n}{f}\PYG{o}{=}\PYG{n}{e}\PYG{o}{.}\PYG{n}{submit}\PYG{p}{(}\PYG{n+nb}{abs}\PYG{p}{,} \PYG{o}{\PYGZhy{}}\PYG{l+m+mi}{8}\PYG{p}{)}
\PYG{g+gp}{\PYGZgt{}\PYGZgt{}\PYGZgt{} }\PYG{n}{f}\PYG{o}{.}\PYG{n}{task\PYGZus{}id}
\PYG{g+go}{\PYGZsq{}8b3da38f\PYGZhy{}f889\PYGZhy{}4ae1\PYGZhy{}8d31\PYGZhy{}68ff2f830876\PYGZsq{}}
\end{sphinxVerbatim}

\sphinxAtStartPar
Suggestion: how to correlate GC task IDs with htex task IDs. Note that htex task IDs are not unique within the endpoint directory because multiple HTEXs (over time) log into the same directory.

\sphinxAtStartPar
block IDs are also not unique because of the above log directory conflation.

\sphinxAtStartPar
Parsl work with extra debug info is likely to give more task information here, but all stil correlated by htex task ID, which as mentioned above, is not even unique within an endpoint.


\section{Launching an academy agent}
\label{\detokenize{index:launching-an-academy-agent}}
\sphinxAtStartPar
There are no academy agents defined by default in an Academy install. If I manually define one in my submit container (in a disposable place, not shared), what happens when I try to launch it?

\sphinxAtStartPar
This works to a remote endpoint, from one cloudlump container to another, which surprises me a bit because the MyAgent code must be being conveyed by some bowels of GC serialization…

\begin{sphinxVerbatim}[commandchars=\\\{\}]
\PYG{k+kn}{import} \PYG{n+nn}{asyncio}
\PYG{k+kn}{import} \PYG{n+nn}{globus\PYGZus{}compute\PYGZus{}sdk} \PYG{k}{as} \PYG{n+nn}{gc}
\PYG{k+kn}{import} \PYG{n+nn}{academy}\PYG{n+nn}{.}\PYG{n+nn}{agent} \PYG{k}{as} \PYG{n+nn}{aa}
\PYG{k+kn}{import} \PYG{n+nn}{academy}\PYG{n+nn}{.}\PYG{n+nn}{manager} \PYG{k}{as} \PYG{n+nn}{am}
\PYG{k+kn}{import} \PYG{n+nn}{academy}\PYG{n+nn}{.}\PYG{n+nn}{exchange} \PYG{k}{as} \PYG{n+nn}{ae}
\PYG{k+kn}{import} \PYG{n+nn}{concurrent}\PYG{n+nn}{.}\PYG{n+nn}{futures} \PYG{k}{as} \PYG{n+nn}{cf}

\PYG{n+nb}{print}\PYG{p}{(}\PYG{l+s+s2}{\PYGZdq{}}\PYG{l+s+s2}{importing myagent main}\PYG{l+s+s2}{\PYGZdq{}}\PYG{p}{)}

\PYG{k}{class} \PYG{n+nc}{MyAgent}\PYG{p}{(}\PYG{n}{aa}\PYG{o}{.}\PYG{n}{Agent}\PYG{p}{)}\PYG{p}{:}
  \PYG{n+nd}{@aa}\PYG{o}{.}\PYG{n}{action}
  \PYG{k}{async} \PYG{k}{def} \PYG{n+nf}{seven}\PYG{p}{(}\PYG{n+nb+bp}{self}\PYG{p}{)}\PYG{p}{:}
      \PYG{n+nb}{print}\PYG{p}{(}\PYG{l+s+sa}{f}\PYG{l+s+s2}{\PYGZdq{}}\PYG{l+s+s2}{something for stdout from MyAgent }\PYG{l+s+si}{\PYGZob{}}\PYG{n+nb+bp}{self}\PYG{l+s+si}{!r\PYGZcb{}}\PYG{l+s+s2}{\PYGZdq{}}\PYG{p}{)}
      \PYG{k+kn}{import} \PYG{n+nn}{os}
      \PYG{k}{return} \PYG{p}{(}\PYG{l+m+mi}{7}\PYG{p}{,} \PYG{n}{os}\PYG{o}{.}\PYG{n}{getpid}\PYG{p}{(}\PYG{p}{)}\PYG{p}{,} \PYG{n}{os}\PYG{o}{.}\PYG{n}{uname}\PYG{p}{(}\PYG{p}{)}\PYG{p}{)}

\PYG{k}{if} \PYG{n+nv+vm}{\PYGZus{}\PYGZus{}name\PYGZus{}\PYGZus{}} \PYG{o}{==} \PYG{l+s+s2}{\PYGZdq{}}\PYG{l+s+s2}{\PYGZus{}\PYGZus{}main\PYGZus{}\PYGZus{}}\PYG{l+s+s2}{\PYGZdq{}}\PYG{p}{:}

  \PYG{k}{async} \PYG{k}{def} \PYG{n+nf}{main}\PYG{p}{(}\PYG{p}{)}\PYG{p}{:}
      \PYG{c+c1}{\PYGZsh{} async with await am.Manager.from\PYGZus{}exchange\PYGZus{}factory(factory=ae.HttpExchangeFactory(auth\PYGZus{}method=\PYGZsq{}globus\PYGZsq{}, url=\PYGZdq{}https://exchange.academy\PYGZhy{}agents.org\PYGZdq{}), executors = cf.ProcessPoolExecutor()) as m:}
      \PYG{k}{async} \PYG{k}{with} \PYG{k}{await} \PYG{n}{am}\PYG{o}{.}\PYG{n}{Manager}\PYG{o}{.}\PYG{n}{from\PYGZus{}exchange\PYGZus{}factory}\PYG{p}{(}\PYG{n}{factory}\PYG{o}{=}\PYG{n}{ae}\PYG{o}{.}\PYG{n}{HttpExchangeFactory}\PYG{p}{(}\PYG{n}{auth\PYGZus{}method}\PYG{o}{=}\PYG{l+s+s1}{\PYGZsq{}}\PYG{l+s+s1}{globus}\PYG{l+s+s1}{\PYGZsq{}}\PYG{p}{,} \PYG{n}{url}\PYG{o}{=}\PYG{l+s+s2}{\PYGZdq{}}\PYG{l+s+s2}{https://exchange.academy\PYGZhy{}agents.org}\PYG{l+s+s2}{\PYGZdq{}}\PYG{p}{)}\PYG{p}{,} \PYG{n}{executors} \PYG{o}{=} \PYG{n}{gc}\PYG{o}{.}\PYG{n}{Executor}\PYG{p}{(}\PYG{n}{endpoint\PYGZus{}id}\PYG{o}{=}\PYG{l+s+s1}{\PYGZsq{}}\PYG{l+s+s1}{5c7202b5\PYGZhy{}d022\PYGZhy{}4534\PYGZhy{}a399\PYGZhy{}21d4356129be}\PYG{l+s+s1}{\PYGZsq{}}\PYG{p}{)}\PYG{p}{)} \PYG{k}{as} \PYG{n}{m}\PYG{p}{:}
          \PYG{n+nb}{print}\PYG{p}{(}\PYG{l+s+sa}{f}\PYG{l+s+s2}{\PYGZdq{}}\PYG{l+s+s2}{with manager }\PYG{l+s+si}{\PYGZob{}}\PYG{n}{m}\PYG{l+s+si}{\PYGZcb{}}\PYG{l+s+s2}{\PYGZdq{}}\PYG{p}{)}
          \PYG{n}{h} \PYG{o}{=} \PYG{k}{await} \PYG{n}{m}\PYG{o}{.}\PYG{n}{launch}\PYG{p}{(}\PYG{n}{MyAgent}\PYG{p}{(}\PYG{p}{)}\PYG{p}{)}
          \PYG{n+nb}{print}\PYG{p}{(}\PYG{l+s+sa}{f}\PYG{l+s+s2}{\PYGZdq{}}\PYG{l+s+s2}{launched agent with handle }\PYG{l+s+si}{\PYGZob{}}\PYG{n}{h}\PYG{l+s+si}{\PYGZcb{}}\PYG{l+s+s2}{\PYGZdq{}}\PYG{p}{)}
          \PYG{n}{s} \PYG{o}{=} \PYG{k}{await} \PYG{n}{h}\PYG{o}{.}\PYG{n}{seven}\PYG{p}{(}\PYG{p}{)}
          \PYG{n+nb}{print}\PYG{p}{(}\PYG{l+s+sa}{f}\PYG{l+s+s2}{\PYGZdq{}}\PYG{l+s+s2}{agent seven result is }\PYG{l+s+si}{\PYGZob{}}\PYG{n}{s}\PYG{l+s+si}{\PYGZcb{}}\PYG{l+s+s2}{\PYGZdq{}}\PYG{p}{)}
          \PYG{k}{assert} \PYG{n}{s}\PYG{p}{[}\PYG{l+m+mi}{0}\PYG{p}{]} \PYG{o}{==} \PYG{l+m+mi}{7}

  \PYG{n}{asyncio}\PYG{o}{.}\PYG{n}{run}\PYG{p}{(}\PYG{n}{main}\PYG{p}{(}\PYG{p}{)}\PYG{p}{)}
\end{sphinxVerbatim}

\sphinxAtStartPar
but if I put the agent in its own agentcode.py module, then I get a remote deserialization error:

\begin{sphinxVerbatim}[commandchars=\\\{\}]
\PYG{o}{.}\PYG{o}{.}\PYG{o}{.}
\PYG{n}{File} \PYG{l+s+s2}{\PYGZdq{}}\PYG{l+s+s2}{/venv/lib/python3.13/site\PYGZhy{}packages/dill/\PYGZus{}dill.py}\PYG{l+s+s2}{\PYGZdq{}}\PYG{p}{,} \PYG{n}{line} \PYG{l+m+mi}{452}\PYG{p}{,} \PYG{o+ow}{in} \PYG{n}{load}
   \PYG{n}{obj} \PYG{o}{=} \PYG{n}{StockUnpickler}\PYG{o}{.}\PYG{n}{load}\PYG{p}{(}\PYG{n+nb+bp}{self}\PYG{p}{)}
\PYG{n}{File} \PYG{l+s+s2}{\PYGZdq{}}\PYG{l+s+s2}{/venv/lib/python3.13/site\PYGZhy{}packages/dill/\PYGZus{}dill.py}\PYG{l+s+s2}{\PYGZdq{}}\PYG{p}{,} \PYG{n}{line} \PYG{l+m+mi}{442}\PYG{p}{,} \PYG{o+ow}{in} \PYG{n}{find\PYGZus{}class}
   \PYG{k}{return} \PYG{n}{StockUnpickler}\PYG{o}{.}\PYG{n}{find\PYGZus{}class}\PYG{p}{(}\PYG{n+nb+bp}{self}\PYG{p}{,} \PYG{n}{module}\PYG{p}{,} \PYG{n}{name}\PYG{p}{)}
          \PYG{o}{\PYGZti{}}\PYG{o}{\PYGZti{}}\PYG{o}{\PYGZti{}}\PYG{o}{\PYGZti{}}\PYG{o}{\PYGZti{}}\PYG{o}{\PYGZti{}}\PYG{o}{\PYGZti{}}\PYG{o}{\PYGZti{}}\PYG{o}{\PYGZti{}}\PYG{o}{\PYGZti{}}\PYG{o}{\PYGZti{}}\PYG{o}{\PYGZti{}}\PYG{o}{\PYGZti{}}\PYG{o}{\PYGZti{}}\PYG{o}{\PYGZti{}}\PYG{o}{\PYGZti{}}\PYG{o}{\PYGZti{}}\PYG{o}{\PYGZti{}}\PYG{o}{\PYGZti{}}\PYG{o}{\PYGZti{}}\PYG{o}{\PYGZti{}}\PYG{o}{\PYGZti{}}\PYG{o}{\PYGZti{}}\PYG{o}{\PYGZti{}}\PYG{o}{\PYGZti{}}\PYG{o}{\PYGZca{}}\PYG{o}{\PYGZca{}}\PYG{o}{\PYGZca{}}\PYG{o}{\PYGZca{}}\PYG{o}{\PYGZca{}}\PYG{o}{\PYGZca{}}\PYG{o}{\PYGZca{}}\PYG{o}{\PYGZca{}}\PYG{o}{\PYGZca{}}\PYG{o}{\PYGZca{}}\PYG{o}{\PYGZca{}}\PYG{o}{\PYGZca{}}\PYG{o}{\PYGZca{}}\PYG{o}{\PYGZca{}}\PYG{o}{\PYGZca{}}\PYG{o}{\PYGZca{}}\PYG{o}{\PYGZca{}}\PYG{o}{\PYGZca{}}\PYG{o}{\PYGZca{}}\PYG{o}{\PYGZca{}}
\PYG{n+ne}{ModuleNotFoundError}\PYG{p}{:} \PYG{n}{No} \PYG{n}{module} \PYG{n}{named} \PYG{l+s+s1}{\PYGZsq{}}\PYG{l+s+s1}{agentcode}\PYG{l+s+s1}{\PYGZsq{}}
\end{sphinxVerbatim}

\sphinxAtStartPar
which is consistent: in the first example, dill is used to convey the definitions; in the second case, pickle thinks it can do an \sphinxcode{\sphinxupquote{import}} and so never gets to the point of dill conveying the definitions.


\section{Looking at GC\sphinxhyphen{}endpoint\sphinxhyphen{}side academy logs}
\label{\detokenize{index:looking-at-gc-endpoint-side-academy-logs}}
\sphinxAtStartPar
For example, I want to see the agent action invocations. There are two paths here I might expect:
\begin{itemize}
\item {} 
\sphinxAtStartPar
some kind of endpoint/worker level as the academy docs suggest running as a worker initialization in the process worker pool. GC workers (and indeed, HTEX workers) don’t have a configuration interface that supports that well, although in pure this observability project is working towards that \textendash{} see the configurability section nearer the start. I might expect that as part of general observability of \sphinxstyleemphasis{the whole system} rather than hoping that the \sphinxstyleemphasis{other components} are themselves separately debuggable.

\end{itemize}

\sphinxAtStartPar
agent\sphinxhyphen{}level log routing: start something at agent start, shut it down at agent end. There are two existing approaches:
\begin{itemize}
\item {} 
\sphinxAtStartPar
I’ve prototyped making agents able to capture “their own” logs and report them via an agent action. I prototyped this with Logan, and mentioned it elsewhere in this report.

\item {} 
\sphinxAtStartPar
Alok added an initialize logging feature to manager launching of agents to insert a log file capture. There is no facility there for conveying the log file anywhere else.

\end{itemize}

\sphinxAtStartPar
These different approaches are not contradictory: the Python logging mechanism can cope with multiple log handlers.

\sphinxAtStartPar
A goal: I want to look at agent activity \sphinxhyphen{} logs or visualization? \sphinxhyphen{} of stuff on the submit side and the remote side.

\sphinxAtStartPar
For example: I want to run my fibonacci agent test and see the agent logging its internal state as it changes, as well as seeing the client reporting what it sees.

\sphinxAtStartPar
I should be able to use multiple approaches to demonstrate how these events can be retrieved and give the same (or similar) output on the analysis side, and the differences in characteristics of the approach would be interesting to comment on \sphinxhyphen{} with the logging and analysis code the same for all event\sphinxhyphen{}movement approaches.

\sphinxAtStartPar
Academy manager has an option to initialize remote logging at start of agent execution \textendash{} that’s one of two remote logging hooks that exists already (the other is on user\sphinxhyphen{}side in agent startup). so lets see how they compare. the main questions: how much ahead\sphinxhyphen{}of\sphinxhyphen{}startup logging do I get from one but not the other? how much do I want my own free\sphinxhyphen{}coding configurability? e.g. for formatting or octopus\sphinxhyphen{}style?

\sphinxAtStartPar
eg. manager.launch(init\_logging) wants to only run once, even though it has logfiles and log levels specified per\sphinxhyphen{}agent. that’s a process vs “entity” inconsistency to think about. also doesn’t have an extralog specifier. rather than wiring in yet another one, look at my more general log configuration.

\sphinxAtStartPar
This doesn’t having configurable format, and it captures bits of logs from other stuff (such as the parsl worker\_log entries). which is desirable sometimes, but perhaps more on an endpoint\sphinxhyphen{}wide basis.

\sphinxAtStartPar
It looks like it also doesn’t \sphinxstyleemphasis{deinitialize} logging \sphinxhyphen{} because its a hack scoped around the process, rather than a principled log bracketing.

\sphinxAtStartPar
Now look at if I make the agent initialize its own logging\sphinxhyphen{} especially addressing the rough edges about: deinitialization, parameterisation.


\chapter{The rest}
\label{\detokenize{index:the-rest}}

\section{Debugging monitoring performance as part of developing this prototype}
\label{\detokenize{index: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.


\section{See also}
\label{\detokenize{index:see-also}}
\index{NetLogger@\spxentry{NetLogger}}\ignorespaces 
\sphinxAtStartPar
NetLogger  \sphinxhyphen{} \sphinxurl{https://dst.lbl.gov/publications/NetLogger.tech-report.pdf}

\index{dnpc@\spxentry{dnpc}}\ignorespaces 
\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.

\index{syslog@\spxentry{syslog}}\ignorespaces 
\sphinxAtStartPar
syslog, systemd logging, linux kernel ringbuffer/dmesg

\index{XML@\spxentry{XML}}\ignorespaces 
\sphinxAtStartPar
buneman xml keys (mentioned above, c.2000)

\sphinxAtStartPar
microsoft power bi: As a simple example of how do we get this data into something actually novel for academia. Dashboard friendly.


\section{wheres the bottleneck \sphinxhyphen{} visualization}
\label{\detokenize{index:wheres-the-bottleneck-visualization}}
\sphinxAtStartPar
based on template analysis \sphinxhyphen{} but could be based on anything
that can be grouped and identified.


\section{Review of changes made so far to Parsl and Academy}
\label{\detokenize{index:review-of-changes-made-so-far-to-parsl-and-academy}}
\sphinxAtStartPar
This should be part of understanding what sort of code changes I am proposing.


\section{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
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.


\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, greg, logan

\sphinxAtStartPar
diaspora: Ryan, Haochen

\sphinxAtStartPar
parsl: matthew



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