Merge pull request #513 from JuliaParallel/jps/docs-graphvizext

logging/viz: Some fixes, and more docstrings

Author: jpsamaroo

docs/Project.toml

@@ -1,7 +1,10 @@
 [deps]
 Dagger = "d58978e5-989f-55fb-8d15-ea34adc7bf54"
 DaggerWebDash = "cfc5aa84-1a2a-41ab-b391-ede92ecae40c"
+DataFrames = "a93c6f00-e57d-5684-b7b6-d8193f3e46c0"
 Documenter = "e30172f5-a6a5-5a46-863b-614d45cd2de4"
+GraphViz = "f526b714-d49f-11e8-06ff-31ed36ee7ee0"
+Plots = "91a5bcdd-55d7-5caf-9e0b-520d859cae80"
 TimespanLogging = "a526e669-04d3-4846-9525-c66122c55f63"
 
 [compat]

docs/make.jl

@@ -1,9 +1,11 @@
-using Dagger, TimespanLogging, DaggerWebDash
+using Dagger, TimespanLogging, DaggerWebDash, GraphViz, Plots, DataFrames
+const GraphVizExt = something(Base.get_extension(Dagger, :GraphVizExt))
+const PlotsExt = something(Base.get_extension(Dagger, :PlotsExt))
 using Documenter
 import Documenter.Remotes: GitHub
 
 makedocs(;
-    modules = [Dagger, TimespanLogging, DaggerWebDash],
+    modules = [Dagger, TimespanLogging, DaggerWebDash, GraphVizExt, PlotsExt],
     authors = "JuliaParallel and contributors",
     repo = GitHub("JuliaParallel", "Dagger.jl"),
     sitename = "Dagger.jl",

docs/src/api-timespanlogging/functions.md

@@ -12,7 +12,6 @@ Pages = ["functions.md"]
 timespan_start
 timespan_finish
 get_logs!
-make_timespan
 ```
 
 ## Logging Metric Functions

docs/src/api-timespanlogging/types.md

@@ -14,11 +14,6 @@ LocalEventLog
 NoOpLog
 ```
 
-## Event Types
-```@docs
-Event
-```
-
 ## Built-in Event Types
 ```@docs
 Events.CoreMetrics
@@ -31,4 +26,3 @@ Events.EventSaturation
 Events.DebugMetrics
 Events.LogWindow
 ```
-```

docs/src/logging-visualization.md

@@ -15,8 +15,7 @@ by libraries or directly by the user, using multiple dispatch on
 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}())`).
+(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

ext/GraphVizExt.jl

@@ -9,7 +9,7 @@ end
 import Dagger
 import Dagger: EagerThunk, Chunk, Processor
 import Dagger.TimespanLogging: Timespan
-import Graphs: SimpleDiGraph, add_edge!, add_vertex!, inneighbors, outneighbors, vertices, is_directed, edges, nv
+import Graphs: SimpleDiGraph, add_edge!, add_vertex!, inneighbors, outneighbors, vertices, is_directed, edges, nv, src, dst
 
 function pretty_time(t; digits=3)
     r(t) = round(t; digits)
@@ -23,6 +23,23 @@ function pretty_time(t; digits=3)
         "$(r(t)) ns"
     end
 end
+
+"""
+    Dagger.render_logs(logs::Dict, ::Val{:graphviz}; disconnected=false,
+                       color_by=:fn, layout_engine="dot",
+                       times::Bool=true, times_digits::Integer=3)
+
+Render a graph of the task dependencies and data dependencies in `logs` using GraphViz.
+
+Requires the following events enabled in `enable_logging!`: `taskdeps`, `tasknames`, `taskargs`, `taskargmoves`
+
+Options:
+- `disconnected`: If `true`, render disconnected vertices (tasks or arguments without upstream/downstream dependencies)
+- `color_by`: How to color tasks; if `:fn`, then color by unique function name, if `:proc`, then color by unique processor
+- `layout_engine`: The layout engine to use for GraphViz
+- `times`: If `true`, annotate each task with its start and finish times
+- `times_digits`: Number of digits to display in the time annotations
+"""
 function Dagger.render_logs(logs::Dict, ::Val{:graphviz}; disconnected=false,
                             color_by=:fn, layout_engine="dot",
                             times::Bool=true, times_digits::Integer=3)

ext/PlotsExt.jl

@@ -67,6 +67,11 @@ end
 
 # Implementation adapted from:
 # https://discourse.julialang.org/t/how-to-make-a-gantt-plot-with-plots-jl/95165/7
+"""
+    Dagger.render_logs(logs::Dict, ::Val{:plots_gantt}; kwargs...)
+
+Render a Gantt chart of task execution in `logs` using Plots. `kwargs` are passed to `plot` directly.
+"""
 function Dagger.render_logs(logs::Dict, ::Val{:plots_gantt}; kwargs...)
     df = logs_to_df(logs)
 

src/sch/dynamic.jl

@@ -7,6 +7,7 @@ struct ThunkID
     ref::Union{DRef,Nothing}
 end
 ThunkID(id::Int) = ThunkID(id, nothing)
+Dagger.istask(::ThunkID) = true
 
 "A handle to the scheduler, used by dynamic thunks."
 struct SchedulerHandle

src/utils/logging-events.jl

@@ -181,20 +181,27 @@ Records the dependencies of each submitted task.
 """
 struct TaskDependencies end
 function (::TaskDependencies)(ev::Event{:start})
-    if ev.category == :add_thunk
-        deps = Int[]
-        for dep in get(Set, ev.timeline.options, :syncdeps)
+    local deps_tids::Vector{Int}
+    function get_deps!(deps)
+        for dep in deps
             dep = Dagger.unwrap_weak_checked(dep)
             if dep isa Dagger.Thunk || dep isa Dagger.Sch.ThunkID
-                push!(deps, dep.id)
-            elseif dep isa Dagger.EagerThunk
-                # FIXME: Get TID
-                #push!(deps, dep.uid)
+                push!(deps_tids, dep.id)
+            elseif dep isa Dagger.EagerThunk && myid() == 1
+                tid = lock(Dagger.Sch.EAGER_ID_MAP) do id_map
+                    id_map[dep.uid]
+                end
+                push!(deps_tids, tid)
             else
                 @warn "Unexpected dependency type: $dep"
             end
         end
-        return ev.id.thunk_id => deps
+    end
+    if ev.category == :add_thunk
+        deps_tids = Int[]
+        get_deps!(Iterators.filter(Dagger.istask, Iterators.map(last, ev.timeline.args)))
+        get_deps!(get(Set, ev.timeline.options, :syncdeps))
+        return ev.id.thunk_id => deps_tids
     end
     return
 end

src/utils/logging.jl

@@ -1,5 +1,19 @@
 # Logging utilities
 
+"""
+    enable_logging!(;kwargs...)
+
+Enables logging globally for all workers. Certain core events are always enabled by this call, but additional ones may be specified via `kwargs`.
+
+Extra events:
+- `metrics::Bool`: Enables various utilization and allocation metrics
+- `timeline::Bool`: Enables raw "timeline" values, which are event-specific; not recommended except for debugging
+- `tasknames::Bool`: Enables generating unique task names for each task
+- `taskdeps::Bool`: Enables reporting of upstream task dependencies (as task IDs) for each task argument
+- `taskargs::Bool`: Enables reporting of upstream non-task dependencies (as `objectid` hash) for each task argument
+- `taskargmoves::Bool`: Enables reporting of copies of upstream dependencies (as original and copy `objectid` hashes) for each task argument
+- `profile::Bool`: Enables profiling of task execution; not currently recommended, as it adds significant overhead
+"""
 function enable_logging!(;metrics::Bool=true,
                           timeline::Bool=false,
                           tasknames::Bool=true,
@@ -37,13 +51,30 @@ function enable_logging!(;metrics::Bool=true,
         ml[:psat] = Dagger.Events.ProcessorSaturation()
     end
     Dagger.Sch.eager_context().log_sink = ml
+    return
 end
+
+"""
+    disable_logging!()
+
+Disables logging previously enabled with `enable_logging!`.
+"""
 function disable_logging!()
     Dagger.Sch.eager_context().log_sink = TimespanLogging.NoOpLog()
+    return
 end
-function fetch_logs!()
-    return TimespanLogging.get_logs!(Dagger.Sch.eager_context())
-end
+
+"""
+    fetch_logs!() -> Dict{Int, Dict{Symbol, Vector}}
+
+Fetches and returns the currently-accumulated logs for each worker. Each entry
+of the outer `Dict` is keyed on worker ID, so `logs[1]` are the logs for worker
+`1`.
+
+Consider using `show_logs` or `render_logs` to generate a renderable display of
+these logs.
+"""
+fetch_logs!() = TimespanLogging.get_logs!(Dagger.Sch.eager_context())
 
 function logs_event_pairs(f, logs::Dict)
     running_events = Dict{Tuple,Int}()