Appendix B. Tracing execution

The --trace option can be used to create a trace of the execution of a pipeline. If the --trace-documents option is used, a copy of every document that flows through the pipeline will be saved.

Trace documents are in the “https://xmlcalabash.com/ns/trace” namespace.

The traces are divided by threads (at the moment, there’s only one thread). Within each thread, each step is recorded along with details about its execution. There are two logical views of the trace: execution order and execution structure. The step start tags are in execution order, earlier steps precede later ones. The hierarchical structure of steps is also significant. Compound steps are nested according to how they were executed.

Documents also appear in execution order, and in execution order within the steps. Their position in the hierarchy is not (especially) significant. Just because a document appears as a child of a particular step does not imply that the parent step generated. The source and target of each document is explicitly identified with the document.

The trace vocabulary

<t:trace>
    t:thread+
</t:trace>

A trace consists of one or more threads of execution.

Threads

<t:thread
  id = long>
    (t:step |
     t:document)+
</t:thread>

A thread has an id (it’s runtime thread id) and one or more steps. It may incidentally have document children as well.

Steps

<t:step
  id = string
  name = string
  type = EQName
  start-time = dateTime
  duration-ms = long>
    (t:step |
     t:document)*
</t:step>

Each step has several attributes:

id

An id; this is a unique ID for this instantiation of this step. (In recursive pipelines, the same step may be instantiated more than once.)

name

A name; this is derived from the step’s name in the pipeline, if it has one.

type

The step type. User-defined pipelines appear in the trace with the type p:declare-step. That represents the invocation of their subpipeline.

start-time

The start time; this is the “wall-clock” time when execution of this step began.

duration-ms

How long the step executed. This is a value in milliseconds.

A compound step will contain the execution traces for the steps it contains. It may also include documents.

Documents

<t:document
  id = long
  content-type? = string>
    (t:from,
     t:to,
     t:location?)
</t:document>

Each document has an id. This is a unique id for this document. Documents are immutable, so if the same document is passed between multiple steps, it will appear in multiple document elements.

If the document has a content type, that’s also recorded.

If the --trace-documents option is used, each document will also have a location element.

From

<t:from
  id = string
  port = string />

Identifies the step that the produced the document, by id and port name.

To

<t:to
  id = string
  port = string />

Identifies the step that received the document by, id and port name.

Location

<t:location
  filename = string />

Identifies the filename where the document has been stored.