logging: Make IDs consistent, add helpers and visualization utils

Makes the :id field consistent (NamedTuple or nothing)
Adds enable/disable logging helpers and log fetch helper
Adds MultiEventLog events to collect task dependency info
Adds utility for creating digraph from task dependency log info
Adds interface for IO-based and display-based DAG rendering
Add new GraphViz-based DAG renderer
Add new Plots-based Gantt chart renderer
Remove Context's log_file infrastructure
Switches GraphViz rendering to use Pkg extensions

Author: jpsamaroo

Diff for: Project.toml

@@ -37,10 +37,19 @@ StatsBase = "0.28, 0.29, 0.30, 0.31, 0.32, 0.33, 0.34"
 TimespanLogging = "0.1"
 julia = "1.8"
 
+[extensions]
+GraphVizSimpleExt = "Colors"
+GraphVizExt = "GraphViz"
+PlotsExt = ["DataFrames", "Plots"]
+
 [extras]
 Colors = "5ae59095-9a9b-59fe-a467-6f913c188581"
-Pkg = "44cfe95a-1eb2-52ea-b672-e2afdf69b78f"
-Test = "8dfed614-e22c-5e08-85e1-65c5234f0b40"
+DataFrames = "a93c6f00-e57d-5684-b7b6-d8193f3e46c0"
+GraphViz = "f526b714-d49f-11e8-06ff-31ed36ee7ee0"
+Plots = "91a5bcdd-55d7-5caf-9e0b-520d859cae80"
 
-[targets]
-test = ["Colors", "Pkg", "Test"]
+[weakdeps]
+Colors = "5ae59095-9a9b-59fe-a467-6f913c188581"
+DataFrames = "a93c6f00-e57d-5684-b7b6-d8193f3e46c0"
+GraphViz = "f526b714-d49f-11e8-06ff-31ed36ee7ee0"
+Plots = "91a5bcdd-55d7-5caf-9e0b-520d859cae80"

Diff for: benchmarks/benchmark.jl

@@ -18,7 +18,6 @@ Environment Variables:
 - BENCHMARK_VISUALIZE - Whether to run the `visualize.jl` script on the output results. May be any value that can parse as a `Bool`.
 - BENCHMARK_RENDER - Which rendering mode to use. May be "live" to use the old (and soon to be removed) web renderer, "webdash" to use the DaggerWebDash renderer, or "offline" to use the old (and soon to be removed) offline renderer. The default of "" disables rendering.
 - BENCHMARK_LIVE_PORT - Which port to use for web rendering. Defaults to port 8000.
-- BENCHMARK_GRAPH - Whether to use dotviz graph rendering. Only useable if using "live" or "offline" rendering methods. Defaults to off, and may be any value that can parse as a `Bool`.
 - BENCHMARK_PROFILE - Whether to enable real-time profiling. Defaults to off, and may be any value with parses as a `Bool`. Currently experimental and very, very slow.
 - BENCHMARK_SAVE_LOGS - Whether to save logs collected at runtime to the output file. Defaults to off, and may be any value that can parse as a `Bool`.
 
@@ -123,10 +122,6 @@ end
 const RENDERS = Dict{Int,Dict}()
 const live_port = parse(Int, get(ENV, "BENCHMARK_LIVE_PORT", "8000"))
 
-const graph = parse(Bool, get(ENV, "BENCHMARK_GRAPH", "0"))
-if graph && render == "webdash"
-    @warn "BENCHMARK_GRAPH=1 is not compatible with BENCHMARK_RENDER=webdash; disabling graphing"
-end
 const profile = parse(Bool, get(ENV, "BENCHMARK_PROFILE", "0"))
 const savelogs = if parse(Bool, get(ENV, "BENCHMARK_SAVE_LOGS", "0"))
     if render == "live " || render == "offline"
@@ -155,9 +150,6 @@ function main()
     opts = (;profile=profile)
     if render == "live"
         opts = merge(opts, (;log_sink=LocalEventLog()))
-        if graph
-            opts = merge(opts, (;log_file=output_prefix*".dot"))
-        end
     elseif render == "webdash" || savelogs
         ml = TimespanLogging.MultiEventLog()
         ml[:core] = TimespanLogging.Events.CoreMetrics()

Diff for: docs/make.jl

@@ -25,9 +25,12 @@ makedocs(;
         "Task Queues" => "task-queues.md",
         "Datadeps" => "datadeps.md",
         "Option Propagation" => "propagation.md",
-        "Logging and Graphing" => "logging.md",
+        "Logging and Visualization" => [
+            "Logging: Basics" => "logging.md",
+            "Logging: Visualization" => "logging-visualization.md",
+            "Logging: Advanced" => "logging-advanced.md",
+        ],
         "Checkpointing" => "checkpointing.md",
-        "Scheduler Visualization" => "scheduler-visualization.md",
         "Benchmarking" => "benchmarking.md",
         "Dynamic Scheduler Control" => "dynamic.md",
         "Scheduler Internals" => "scheduler-internals.md",

Diff for: docs/src/logging-advanced.md

@@ -0,0 +1,56 @@
+# Logging: Advanced Details
+
+## MultiEventLog
+
+The `MultiEventLog` is intended to be configurable to exclude unnecessary
+information, and to include any built-in or user-defined metrics. It stores a
+set of "sub-log" streams internally, appending a single element to each of them
+when an event is generated. This element can be called a "sub-event" (to
+distinguish it from the higher-level "event" that Dagger creates), and is
+created by a "consumer". A consumer is a function or callable struct that, when
+called with the `Event` object generated by TimespanLogging, returns a sub-event
+characterizing whatever information the consumer represents. For example, the
+`Dagger.Events.BytesAllocd` consumer calculates the total bytes allocated and
+live at any given time within Dagger, and returns the current value when
+called. Let's construct one:
+
+```julia
+ctx = Dagger.Sch.eager_context()
+ml = TimespanLogging.MultiEventLog()
+
+# Add the BytesAllocd consumer to the log as `:bytes`
+ml[:bytes] = Dagger.Events.BytesAllocd()
+
+ctx.log_sink = ml
+```
+
+As we can see above, each consumer gets a unique name as a `Symbol` that
+identifies it. Now that the log sink is attached with a consumer, we can
+execute some Dagger tasks, and then collect the sub-events generated by
+`BytesAllocd`:
+
+```julia
+# Allocates memory for their results
+t1 = Dagger.@spawn 3*4
+fetch(Dagger.@spawn 1+t1)
+log = Dagger.fetch_logs!(ctx)[1] # Get the logs for worker 1
+@show log[:bytes]
+```
+
+!!! note
+    `TimespanLogging.get_logs!` clears out the event logs, so that old events
+    don't mix with new ones from future DAGs.
+
+You'll then see that some number of bytes are allocated and then freed during
+the process of executing and completing those tasks.
+
+There are a variety of other consumers built-in to TimespanLogging and Dagger,
+under the `TimespanLogging.Events` and `Dagger.Events` modules, respectively;
+see [Dagger Types](@ref) and [TimespanLogging Types](@ref) for details.
+
+The `MultiEventLog` also has a mechanism to call a set of functions, called
+"aggregators", after all consumers have been executed, and are passed the full
+set of log streams as a `Dict{Symbol,Vector{Any}}`. The only one currently
+shipped with TimespanLogging directly is the `LogWindow`, and DaggerWebDash.jl
+has the `TableStorage` which integrates with it; see
+[DaggerWebDash Types](@ref) for details.

Diff for: docs/src/scheduler-visualization.md renamed to docs/src/logging-visualization.md

@@ -1,12 +1,42 @@
-# Scheduler Visualization with DaggerWebDash
+# Logs Visualization
+
+To make Dagger's logging facilities useful without having to write custom code,
+Dagger has built-in and easily accessible logs visualization capabilities.
+Currently, there are two general mechanisms to visualize logs:
+`show_logs`/`render_logs`, and `MultiEventLog` consumers.
+
+The former (`show_logs`/`render_logs`) renders a logs `Dict` (acquired from
+`fetch_logs!`) either to an `IO` (via `show_logs`) or by returning a renderable
+object (via `render_logs`). This system is designed for rendering a single
+snapshot of logs into one or a few renderable objects, and is easily extensible
+by libraries or directly by the user, using multiple dispatch on
+`show_logs(io::IO, logs::Dict, ::Val{mode})` and
+`render_logs(logs::Dict, ::Val{mode})`, where `mode` is a unique `Symbol`
+identifying the rendering mode to use. From the user's perspective, `show_logs`
+and `render_logs` take not a `Val` but a raw `Symbol`, which will be internally
+converted to a `Val` for dispatch purposes
+(i.e. `render_logs(logs::Dict, :myrenderer)` -> 
+`render_logs(logs, Val{:myrenderer}())`).
+
+Built-in rendering support exists for:
+- `render_logs(logs, :graphviz)` to generate a graph diagram of executed tasks and their dependencies
+- `render_logs(logs, :plots_gantt)` to generate a Gantt chart of task execution across all processors
+
+The latter (`MultiEventLog`) allows for continuously rendering logs as they're
+generated, permitting real-time visualization of Dagger's operations. This
+logic is utilized in `DaggerWebDash`, which provides a web-based dashboard for
+visualizing Dagger's operations as a real-time Gantt chart and set of plots for
+various system metrics (CPU usage, memory usage, worker utilization, etc.).
+
+## Visualization with DaggerWebDash
 
 When working with Dagger, especially when working with its scheduler, it can be
-helpful to visualize what Dagger is doing internally. To assist with this, a
-web dashboard is available in the DaggerWebDash.jl package. This web dashboard
-uses a web server running within each Dagger worker, along with event logging
-information, to expose details about the scheduler. Information like worker and
-processor saturation, memory allocations, profiling traces, and much more are
-available in easy-to-interpret plots.
+helpful to visualize what Dagger is doing internally in near-real-time. To
+assist with this, a web dashboard is available in the DaggerWebDash.jl package.
+This web dashboard uses a web server running within each Dagger worker, along
+with event logging information, to expose details about the scheduler.
+Information like worker and processor saturation, memory allocations, profiling
+traces, and much more are available in easy-to-interpret plots.
 
 Using the dashboard is relatively simple and straightforward; if you run
 Dagger's benchmarking script, it's enabled for you automatically if the

Diff for: docs/src/logging.md

@@ -5,126 +5,31 @@ actions it does, such as moving data between workers or executing thunks, and
 tracks how much time and memory allocations these operations consume, among
 other things. It does it through the `TimespanLogging.jl` package (which used
 to be directly integrated into Dagger). Saving this information somewhere
-accessible is disabled by default, but it's quite easy to turn it on, by
-setting a "log sink" in the `Context` being used, as `ctx.log_sink`. A variety
-of log sinks are built-in to TimespanLogging; the `NoOpLog` is the default log
-sink when one isn't explicitly specified, and disables logging entirely (to
-minimize overhead). There are currently two other log sinks of interest; the
-first and newer of the two is the `MultiEventLog`, which generates multiple
-independent log streams, one per "consumer" (details in the next section). The
-second and older sink is the `LocalEventLog`, which is explained later in this
-document. Most users are recommended to use the `MultiEventLog` since it's far
-more flexible and extensible, and is more performant in general.
-
-## MultiEventLog
-
-The `MultiEventLog` is intended to be configurable to exclude unnecessary
-information, and to include any built-in or user-defined metrics. It stores a
-set of "sub-log" streams internally, appending a single element to each of them
-when an event is generated. This element can be called a "sub-event" (to
-distinguish it from the higher-level "event" that Dagger creates), and is
-created by a "consumer". A consumer is a function or callable struct that, when
-called with the `Event` object generated by TimespanLogging, returns a sub-event
-characterizing whatever information the consumer represents. For example, the
-`Dagger.Events.BytesAllocd` consumer calculates the total bytes allocated and
-live at any given time within Dagger, and returns the current value when
-called. Let's construct one:
-
-```julia
-ctx = Context()
-ml = TimespanLogging.MultiEventLog()
-
-# Add the BytesAllocd consumer to the log as `:bytes`
-ml[:bytes] = Dagger.Events.BytesAllocd()
-
-ctx.log_sink = ml
-```
-
-As we can see above, each consumer gets a unique name as a `Symbol` that
-identifies it. Now that the log sink is attached with a consumer, we can
-execute some Dagger tasks, and then collect the sub-events generated by
-`BytesAllocd`:
-
-```julia
-# Using the lazy API, for explanatory purposes
-collect(ctx, delayed(+)(1, delayed(*)(3, 4))) # Allocates 8 bytes
-log = TimspanLogging.get_logs!(ctx)[1] # Get the logs for worker 1
-@show log[:bytes]
-```
-
-You'll then see that 8 bytes are allocated and then freed during the process of
-executing and completing those tasks.
-
-Note that the `MultiEventLog` can also be used perfectly well when using
-Dagger's eager API:
-
-```julia
-ctx = Dagger.Sch.eager_context()
-ctx.log_sink = ml
-
-a = Dagger.@spawn 3*4
-Dagger.@spawn 1+a
-```
-
-There are a variety of other consumers built-in to TimespanLogging and Dagger,
-under the `TimespanLogging.Events` and `Dagger.Events` modules, respectively;
-see [Dagger Types](@ref) and [TimespanLogging Types](@ref) for details.
-
-The `MultiEventLog` also has a mechanism to call a set of functions, called
-"aggregators", after all consumers have been executed, and are passed the full
-set of log streams as a `Dict{Symbol,Vector{Any}}`. The only one currently
-shipped with TimespanLogging directly is the `LogWindow`, and DaggerWebDash.jl
-has the `TableStorage` which integrates with it; see
-[DaggerWebDash Types](@ref) for details.
-
-## LocalEventLog
-
-The `LocalEventLog` is generally only useful when you want combined events
-(event start and finish combined as a single unit), and only care about a few
-simple built-in generated events. Let's attach one to our context:
-
-```julia
-ctx = Context()
-log = TimespanLogging.LocalEventLog()
-ctx.log_sink = log
-```
-
-Now anytime `ctx` is used as the context for a scheduler, the scheduler will
-log events into `log`.
-
-Once sufficient data has been accumulated into a `LocalEventLog`, it can be
-gathered to a single host via `TimespanLogging.get_logs!(log)`. The result is a
-`Vector` of `TimespanLogging.Timespan` objects, which describe some metadata
-about an operation that occured and the scheduler logged. These events may be
-introspected directly, or may also be rendered to a DOT-format string:
-
-```julia
-logs = TimespanLogging.get_logs!(log)
-str = Dagger.show_plan(logs)
-```
-
-`Dagger.show_plan` can also be called as `Dagger.show_plan(io::IO, logs)` to
-write the graph to a file or other `IO` object. The string generated by this
-function may be passed to an external tool like `Graphviz` for rendering. Note
-that this method doesn't display input arguments to the DAG (non-`Thunk`s);
-you can call `Dagger.show_plan(logs, thunk)`, where `thunk` is the output
-`Thunk` of the DAG, to render argument nodes.
-
-!!! note
-    `TimespanLogging.get_logs!` clears out the event logs, so that old events
-    don't mix with new ones from future DAGs.
-
-As a convenience, it's possible to set `ctx.log_file` to the path to an output
-file, and then calls to `compute(ctx, ...)`/`collect(ctx, ...)` will
-automatically write the graph in DOT format to that path. There is also a
-benefit to this approach over manual calls to `get_logs!` and `show_plan`: DAGs
-which aren't `Thunk`s (such as operations on the `Dagger.DArray`) will be
-properly rendered with input arguments (which normally aren't rendered because
-a `Thunk` is dynamically generated from such operations by Dagger before
-scheduling).
-
-## FilterLog
-
-The `FilterLog` exists to allow writing events to a user-defined location (such
-as a database, file, or network socket). It is not currently tested or
-documented.
+accessible is disabled by default, but it's quite easy to turn it on, through
+two mechanisms.
+
+The first is `Dagger.enable_logging!`, which provides an easy-to-use interface
+to both enable and configure logging. The defaults are usually sufficient for
+most users, but can be tweaked with keyword arguments.
+
+The second is done by setting a "log sink" in the Dagger `Context` being used,
+as `ctx.log_sink`. These log sinks drive how Dagger's logging behaves, and are
+configurable by the user, without the need to tweak any of Dagger's internal
+code.
+
+A variety of log sinks are built-in to TimespanLogging; the `NoOpLog` is the
+default log sink when one isn't explicitly specified, and disables logging
+entirely (to minimize overhead). There are currently two other log sinks of
+interest; the first and newer of the two is the `MultiEventLog`, which
+generates multiple independent log streams, one per "consumer" (details in the
+next section). This is the log sink that `enable_logging!` uses, as it's easily
+the most flexible. The second and older sink is the `LocalEventLog`, which is
+explained later in this document. Most users are recommended to use the
+`MultiEventLog` (ideally via `enable_logging!`) since it's far more flexible
+and extensible, and is more performant in general.
+
+Log sinks are explained in detail in [Logging: Advanced](@ref); however, if
+using `enable_logging!`, everything is already configured for you. Then, all
+you need to do is call `Dagger.fetch_logs!()` to get the logs for all workers
+as a `Dict`. A variety of tools can operate on these logs, including
+visualization through `show_logs` and `render_logs`.