10.6 Futures Tracing
Parallelism with Futures in The Racket Guide introduces the future visualizer.
| (require future-visualizer/trace) |
The futures trace module exposes low-level information about the execution of parallel programs written using future.
syntax
(trace-futures e ...)
procedure
(trace-futures-thunk thunk) → (listof indexed-future-event?)
thunk : (-> any)
This program:
(require racket/future future-visualizer/trace) (trace-futures (let ([f (future (lambda () ...))]) ... (touch f)))
Is equivalent to:
(require racket/future future-visualizer/trace) (start-future-tracing!) (let ([f (future (lambda () ...))]) ... (touch f)) (stop-future-tracing!) (timeline-events)
procedure
procedure
procedure
The stop-future-tracing! procedure must be used to indicate the end of code the programmer wishes to trace. Tracing works by simply using a log receiver to record all future-related log events; this procedure logs a special message that is well-known to the log receiver to mean ’stop recording’.
The timeline-events procedure returns the program trace as a list of indexed-future-event structures.
struct
(struct indexed-future-event (index event) #:extra-constructor-name make-indexed-future-event) index : exact-nonnegative-integer? event : future-event?
10.6.1 Future Performance Logging
Racket traces use logging (see Logging) extensively to report information about how futures are evaluated. Logging output is useful for debugging the performance of programs that use futures.
Though textual log output can be viewed directly (or retrieved in code via trace-futures), it is much easier to use the graphical profiler tool provided by future-visualizer.
In addition to its string message, each event logged for a future has a data value that is an instance of a future-event prefab structure:
struct
(struct future-event ( future-id proc-id action time-id prim-name user-data) #:extra-constructor-name make-future-event #:prefab) future-id : (or exact-nonnegative-integer? #f) proc-id : exact-nonnegative-integer? action : symbol? time-id : real? prim-name : (or symbol? #f) user-data : (or #f symbol? exact-nonnegative-integer?)
The future-id field is an exact integer that identifies a future, or it is #f when action is 'missing. The future-id field is particularly useful for correlating logged events.
The proc-id fields is an exact, non-negative integer that identifies a parallel process. Process 0 is the main Racket process, where all expressions other than future thunks evaluate.
The time-id field is an inexact number that represents time in the same way as current-inexact-milliseconds.
The action field is a symbol:
'create: a future was created.
'complete: a future’s thunk evaluated successfully, so that touch will produce a value for the future immediately.
'start-work and 'end-work: a particular process started and ended working on a particular future.
'start-0-work: like 'start-work, but for a future thunk that for some structural reason could not be started in a process other than 0 (e.g., the thunk requires too much local storage to start).
'start-overflow-work: like 'start-work, where the future thunk’s work was previously stopped due to an internal stack overflow.
'sync: blocking (processes other than 0) or initiation of handing (process 0) for an “unsafe” operation in a future thunk’s evaluation; the operation must run in process 0.
'block: like 'sync, but for a part of evaluation that must be delayed until the future is touched, because the evaluation may depend on the current continuation.
'touch (never in process 0): like 'sync or 'block, but for a touch operation within a future thunk.
'overflow (never in process 0): like 'sync or 'block, but for the case that a process encountered an internal stack overflow while evaluating a future thunk.
'result or 'abort: waiting or handling for 'sync, 'block, or 'touch ended with a value or an error, respectively.
'suspend (never in process 0): a process blocked by 'sync, 'block, or 'touch abandoned evaluation of a future; some other process may pick up the future later.
'touch-pause and 'touch-resume (in process 0, only): waiting in touch for a future whose thunk is being evaluated in another process.
'missing: one or more events for the process were lost due to internal buffer limits before they could be reported, and the time-id field reports an upper limit on the time of the missing events; this kind of event is rare.
Assuming no 'missing events, then 'start-work, 'start-0-work, 'start-overflow-work is always paired with 'end-work; 'sync, 'block, and 'touch are always paired with 'result, 'abort, or 'suspend; and 'touch-pause is always paired with 'touch-resume.
In process 0, some event pairs can be nested within other event pairs: 'sync, 'block, or 'touch with 'result or 'abort; and 'touch-pause with 'touch-resume.
An 'block in process 0 is generated when an unsafe operation is handled. This type of event will contain a symbol in the unsafe-op-name field that is the name of the operation. In all other cases, this field contains #f.
The prim-name field will always be #f unless the event occurred on process 0 and its action is either 'block or 'sync. If these conditions are met, prim-name will contain the name of the Racket primitive which required the future to synchronize with the runtime thread (represented as a symbol).
The user-data field may take on a number of different values depending on both the action and prim-name fields:
'touch on process 0: contains the integer ID of the future being touched.
'sync and prim-name = |allocate memory|: The size (in bytes) of the requested allocation.
'sync and prim-name = jit_on_demand: The runtime thread is performing a JIT compilation on behalf of the future future-id. The field contains the name of the function being JIT compiled (as a symbol).
'create: A new future was created. The field contains the integer ID of the newly created future.