Cthulhu.jl
Cthulhu.jl copied to clipboard
JuliaDebug
Limit printing of Consts
julia> using TimerOutputs
julia> @descend scoped() do
end^C
julia> @descend scoped(svar => 2) do
svar[2]
end^C
(TimerOutputs) pkg> free TimerOutputs^C
julia> function f()
@timeit Timer begin
@timeit Timer begin
end
end
end
f (generic function with 1 method)
julia> @descend f()
ERROR: LoadError: UndefVarError: `@descend` not defined
in expression starting at REPL[3]:1
julia> using Cthulhu
julia> @descend f()
f() @ Main REPL[2]:1
1 function f()::Core.Const(nothing)
2 @timeit Timer begin
3 @timeit Timer begin
4 end
5 end
6 end
Select a call to descend into or ↩ to ascend. [q]uit. [b]ookmark.
Toggles: [w]arn, [h]ide type-stable statements, [t]ype annotations, [s]yntax highlight for Source/LLVM/Native.
Show: [S]ource code, [A]ST, [T]yped code, [L]LVM IR, [N]ative code
Actions: [E]dit source code, [R]evise and redisplay
• %3 = getindex(::ScopedValues.ScopedValue{TimerOutput})::TimerOutput
%4 = TimerOutput(::String,::TimerOutput)::…
%5 = = < semi-concrete eval > Pair(::ScopedValue{…},::TimerOutput{…})::…
%6 = < constprop > scoped(::#1#3{…},::Pair{…},::Tuple)::Core.Const(nothing)
↩
julia> f()
julia> @descend f()
f() @ Main REPL[2]:1
1 function f()::Core.Const(nothing)
2 @timeit Timer begin
3 @timeit Timer begin
4 end
5 end
6 end
Select a call to descend into or ↩ to ascend. [q]uit. [b]ookmark.
Toggles: [w]arn, [h]ide type-stable statements, [t]ype annotations, [s]yntax highlight for Source/LLVM/Native.
Show: [S]ource code, [A]ST, [T]yped code, [L]LVM IR, [N]ative code
Actions: [E]dit source code, [R]evise and redisplay
• %3 = getindex(::ScopedValues.ScopedValue{TimerOutput})::TimerOutput
%4 = TimerOutput(::String,::TimerOutput)::Core.PartialStruct(TimerOutput, Any[String, TimerOutput, Union{Nothing, TimerOutputs.TimeData}, TimerOutputs.LList{TimerOutput}])
%5 = = < semi-concrete eval > Pair(::ScopedValue{…},::TimerOutput{…})::…
%6 = < constprop > scoped(::#1#3{…},::Pair{…},::Tuple)::Core.Const(nothing)
↩
f() @ Main REPL[2]:1
∘ ── %0 = invoke f()::Core.Const(nothing)
2 1 ── %1 = %new(Main.:(var"#1#3"))::Core.Const(var"#1#3"()) │╻ macro expansion
└─── %2 = $(Expr(:foreigncall, :(:jl_get_current_task), Ref{Task}, svec(), 0, :(:ccall)))::Task ││╻╷╷╷ getindex
2 ── nothing::Nothing │
3 ── nothing::Nothing │
4 ── %5 = Base.getfield(%2, :logstate)::Any │││╻ current_scope
└─── goto #5 ││││┃││ current_logger
5 ── %7 = (%5 === Base.CoreLogging.nothing)::Bool │││││╻ current_logstate
│ %8 = Core.Intrinsics.not_int(%7)::Bool ││││││
└─── goto #7 if not %8 ││││││
6 ── goto #8 ││││││
7 ── %11 = Base.CoreLogging._global_logstate::Any ││││││
8 ┄─ %12 = φ (#6 => %5, #7 => %11)::Any ││││││
│ Core.typeassert(%12, Base.CoreLogging.LogState)::Base.CoreLogging.LogState ││││││
│ %14 = π (%12, Base.CoreLogging.LogState) ││││││
└─── goto #9 ││││││
9 ── %16 = Base.getfield(%14, :logger)::Base.CoreLogging.AbstractLogger │││││╻ getproperty
└─── goto #10 │││││
10 ─ %18 = (%16 isa ScopedValues.ScopePayloadLogger)::Bool │││╻ current_scope
└─── goto #12 if not %18 ││││
11 ─ %20 = π (%16, ScopedValues.ScopePayloadLogger) ││││
│ %21 = Base.getfield(%20, :scope)::ScopedValues.Scope ││││╻ getproperty
└─── goto #13 ││││
12 ─ goto #13 ││││
13 ┄ %24 = φ (#11 => %21, #12 => ScopedValues.nothing)::Union{Nothing, ScopedValues.Scope} │││
14 ┄ %25 = φ (#13 => %24, #18 => %39)::Union{Nothing, ScopedValues.Scope} │││
│ %26 = (%25 === ScopedValues.nothing)::Bool │││
│ %27 = Core.Intrinsics.not_int(%26)::Bool │││
└─── goto #19 if not %27 │││
15 ─ %29 = π (%25, ScopedValues.Scope) │││
│ %30 = Base.getfield(%29, :key)::ScopedValues.ScopedValue │││╻ getproperty
│ %31 = (%30 === ScopedValues.ScopedValue{TimerOutput}( ──────────────────────────────────────────────────────────────────── │││
Time Allocations
─────────────────────── ────────────────────────
Total measured: 9.35ms 14.0KiB
Section ncalls time %tot avg alloc %tot avg
────────────────────────────────────────────────────────────────────
Timer 1 9.35ms 100.0% 9.35ms 14.0KiB 100.0% 14.0KiB
Timer 1 1.95μs 0.0% 1.95μs 0.00B 0.0% 0.00B
────────────────────────────────────────────────────────────────────))::Bool
└─── goto #18 if not %31 │││
16 ─ %33 = π (%25, ScopedValues.Scope) │││
│ %34 = Base.getfield(%33, :value)::Any │││╻ getproperty
│ Core.typeassert(%34, TimerOutput)::TimerOutput │││
└─── %36 = π (%34, TimerOutput) │││
17 ─ goto #21 │││
18 ─ %38 = π (%25, ScopedValues.Scope) │││
│ %39 = Base.getfield(%38, :parent)::Union{Nothing, ScopedValues.Scope} │││╻ getproperty
└─── goto #14 ││╻ getindex
19 ─ %41 = Base.getfield(ScopedValues.ScopedValue{TimerOutput}( ──────────────────────────────────────────────────────────────────── │││╻ getproperty
Time Allocations
─────────────────────── ────────────────────────
Total measured: 9.35ms 14.0KiB
Section ncalls time %tot avg alloc %tot avg
────────────────────────────────────────────────────────────────────
Timer 1 9.35ms 100.0% 9.35ms 14.0KiB 100.0% 14.0KiB
Timer 1 1.95μs 0.0% 1.95μs 0.00B 0.0% 0.00B
────────────────────────────────────────────────────────────────────), :initial_value)::TimerOutput
20 ─ goto #21 │││
21 ┄ %43 = φ (#17 => %36, #20 => %41)::TimerOutput ││
│ %44 = %new(TimerOutputs.LList{TimerOutput})::TimerOutputs.LList{TimerOutput} │││╻ LList
│ %45 = TimerOutputs.nothing::Core.Const(nothing) │││
└─── %46 = %new(TimerOutputs.TimerOutput, "Timer", %43, %45, %44)::Core.PartialStruct(TimerOutput, Any[String, TimerOutput, Union{Nothing, TimerOutputs.TimeData}, TimerOutputs.LList{TimerOutput}]) │││╻ TimerOutput
22 ─ nothing::Nothing │
23 ─ goto #24 ││╻ Pair
24 ─ %49 = $(Expr(:foreigncall, :(:jl_get_current_task), Ref{Task}, svec(), 0, :(:ccall)))::Task │││╻╷╷╷ current_scope
25 ─ nothing::Nothing │
26 ─ nothing::Nothing │
27 ─ %52 = Base.getfield(%49, :logstate)::Any ││││╻ current_logger
└─── goto #28 │││││┃│ current_logstate
28 ─ %54 = (%52 === Base.CoreLogging.nothing)::Bool │││││╻ current_logstate
│ %55 = Core.Intrinsics.not_int(%54)::Bool ││││││
└─── goto #30 if not %55 ││││││
29 ─ goto #31 ││││││
30 ─ %58 = Base.CoreLogging._global_logstate::Any ││││││
31 ┄ %59 = φ (#29 => %52, #30 => %58)::Any ││││││
│ Core.typeassert(%59, Base.CoreLogging.LogState)::Base.CoreLogging.LogState ││││││
│ %61 = π (%59, Base.CoreLogging.LogState) ││││││
└─── goto #32 ││││││
32 ─ %63 = Base.getfield(%61, :logger)::Base.CoreLogging.AbstractLogger │││││╻ getproperty
└─── goto #33 │││││
33 ─ %65 = (%63 isa ScopedValues.ScopePayloadLogger)::Bool │││╻ current_scope
└─── goto #35 if not %65 ││││
34 ─ %67 = π (%63, ScopedValues.ScopePayloadLogger) ││││
│ %68 = Base.getfield(%67, :scope)::ScopedValues.Scope ││││╻ getproperty
└─── goto #36 ││││
35 ─ goto #36 ││││
36 ┄ %71 = φ (#34 => false, #35 => true)::Bool │││
│ %72 = φ (#34 => true, #35 => false)::Bool │││
│ %73 = φ (#34 => %68, #35 => ScopedValues.nothing)::Union{Nothing, ScopedValues.Scope} │││
└─── goto #37 │││╻╷ iterate
37 ─ goto #38 ││││┃ iterate
38 ─ goto #39 ││││
39 ─ goto #40 ││││
40 ─ goto #41 ││││
41 ─ nothing::Nothing │
42 ─ goto #43 ││││
43 ─ goto #49 if not %71 │││
44 ─ %82 = π (%73, Nothing) │││
45 ─ nothing::Nothing │
46 ─ nothing::Nothing │
47 ─ %85 = %new(ScopedValues.Scope, %82, ScopedValues.ScopedValue{TimerOutput}( ──────────────────────────────────────────────────────────────────── │││╻ Scope
Time Allocations
─────────────────────── ────────────────────────
Total measured: 9.35ms 14.0KiB
Section ncalls time %tot avg alloc %tot avg
────────────────────────────────────────────────────────────────────
Timer 1 9.35ms 100.0% 9.35ms 14.0KiB 100.0% 14.0KiB
Timer 1 1.95μs 0.0% 1.95μs 0.00B 0.0% 0.00B
────────────────────────────────────────────────────────────────────), %46)::Core.PartialStruct(ScopedValues.Scope, Any[Core.Const(nothing), Core.Const(ScopedValues.ScopedValue{TimerOutput}( ────────────────────────────────────────────────────────────────────
Time Allocations
─────────────────────── ────────────────────────
Total measured: 9.35ms 14.0KiB
Section ncalls time %tot avg alloc %tot avg
────────────────────────────────────────────────────────────────────
Timer 1 9.35ms 100.0% 9.35ms 14.0KiB 100.0% 14.0KiB
Timer 1 1.95μs 0.0% 1.95μs 0.00B 0.0% 0.00B
────────────────────────────────────────────────────────────────────)), Core.PartialStruct(TimerOutput, Any[String, TimerOutput, Union{Nothing, TimerOutputs.TimeData}, TimerOutputs.LList{TimerOutput}])])
└─── goto #48 ││││
48 ─ goto #56 │││
49 ─ goto #55 if not %72 │││
50 ─ %89 = π (%73, ScopedValues.Scope) │││
51 ─ nothing::Nothing │
52 ─ nothing::Nothing │
53 ─ %92 = %new(ScopedValues.Scope, %89, ScopedValues.ScopedValue{TimerOutput}( ──────────────────────────────────────────────────────────────────── │││╻ Scope
Time Allocations
─────────────────────── ────────────────────────
Total measured: 9.35ms 14.0KiB
Section ncalls time %tot avg alloc %tot avg
────────────────────────────────────────────────────────────────────
Timer 1 9.35ms 100.0% 9.35ms 14.0KiB 100.0% 14.0KiB
Timer 1 1.95μs 0.0% 1.95μs 0.00B 0.0% 0.00B
────────────────────────────────────────────────────────────────────), %46)::Core.PartialStruct(ScopedValues.Scope, Any[ScopedValues.Scope, Core.Const(ScopedValues.ScopedValue{TimerOutput}( ────────────────────────────────────────────────────────────────────
Time Allocations
─────────────────────── ────────────────────────
Total measured: 9.35ms 14.0KiB
Section ncalls time %tot avg alloc %tot avg
────────────────────────────────────────────────────────────────────
Timer 1 9.35ms 100.0% 9.35ms 14.0KiB 100.0% 14.0KiB
Timer 1 1.95μs 0.0% 1.95μs 0.00B 0.0% 0.00B
────────────────────────────────────────────────────────────────────)), Core.PartialStruct(TimerOutput, Any[String, TimerOutput, Union{Nothing, TimerOutputs.TimeData}, TimerOutputs.LList{TimerOutput}])])
└─── goto #54 ││││
54 ─ goto #56 │││
55 ─ Core.throw(ErrorException("fatal error in type inference (type bound)"))::Union{} │││
└─── unreachable │││
56 ┄ %97 = φ (#48 => %85, #54 => %92)::Core.PartialStruct(ScopedValues.Scope, Any[Union{Nothing, ScopedValues.Scope}, Core.Const(ScopedValues.ScopedValue{TimerOutput}( ──────────────────────────────────────────────────────────────────── │││
Time Allocations
─────────────────────── ────────────────────────
Total measured: 9.35ms 14.0KiB
Section ncalls time %tot avg alloc %tot avg
────────────────────────────────────────────────────────────────────
Timer 1 9.35ms 100.0% 9.35ms 14.0KiB 100.0% 14.0KiB
Timer 1 1.95μs 0.0% 1.95μs 0.00B 0.0% 0.00B
────────────────────────────────────────────────────────────────────)), Core.PartialStruct(TimerOutput, Any[String, TimerOutput, Union{Nothing, TimerOutputs.TimeData}, TimerOutputs.LList{TimerOutput}])])
57 ─ %98 = %new(ScopedValues.var"#1#2"{var"#1#3"}, %1)::Core.Const(ScopedValues.var"#1#2"{var"#1#3"}(var"#1#3"())) │││
└─── %99 = $(Expr(:foreigncall, :(:jl_get_current_task), Ref{Task}, svec(), 0, :(:ccall)))::Task ││││╻╷╷╷ current_logger
58 ─ nothing::Nothing │
59 ─ nothing::Nothing │
60 ─ %102 = Base.getfield(%99, :logstate)::Any │││││╻ current_logger
└─── goto #61 ││││││┃│ current_logstate
61 ─ %104 = (%102 === Base.CoreLogging.nothing)::Bool ││││││╻ current_logstate
│ %105 = Core.Intrinsics.not_int(%104)::Bool │││││││
└─── goto #63 if not %105 │││││││
62 ─ goto #64 │││││││
63 ─ %108 = Base.CoreLogging._global_logstate::Any │││││││
64 ┄ %109 = φ (#62 => %102, #63 => %108)::Any │││││││
│ Core.typeassert(%109, Base.CoreLogging.LogState)::Base.CoreLogging.LogState │││││││
│ %111 = π (%109, Base.CoreLogging.LogState) │││││││
└─── goto #65 │││││││
65 ─ %113 = Base.getfield(%111, :logger)::Base.CoreLogging.AbstractLogger ││││││╻ getproperty
└─── goto #66 ││││││
66 ─ %115 = (%113 isa ScopedValues.ScopePayloadLogger)::Bool ││││╻ current_logger
└─── goto #68 if not %115 │││││
67 ─ %117 = π (%113, ScopedValues.ScopePayloadLogger) │││││
│ %118 = Base.getfield(%117, :logger)::Base.CoreLogging.AbstractLogger │││││╻ getproperty
└─── goto #69 │││││
68 ─ goto #69 │││││
69 ┄ %121 = φ (#67 => %118, #68 => %113)::Base.CoreLogging.AbstractLogger ││││
│ %122 = %new(ScopedValues.ScopePayloadLogger, %121, %97)::Core.PartialStruct(ScopedValues.ScopePayloadLogger, Any[Base.CoreLogging.AbstractLogger, Core.PartialStruct(ScopedValues.Scope, Any[Union{Nothing, ScopedValues.Scope}, Core.Const(ScopedValues.ScopedValue{TimerOutput}( ────────────────────────────────────────────────────────────────────
Time Allocations
─────────────────────── ────────────────────────
Total measured: 9.35ms 14.0KiB
Section ncalls time %tot avg alloc %tot avg
────────────────────────────────────────────────────────────────────
Timer 1 9.35ms 100.0% 9.35ms 14.0KiB 100.0% 14.0KiB
Timer 1 1.95μs 0.0% 1.95μs 0.00B 0.0% 0.00B
────────────────────────────────────────────────────────────────────)), Core.PartialStruct(TimerOutput, Any[String, TimerOutput, Union{Nothing, TimerOutputs.TimeData}, TimerOutputs.LList{TimerOutput}])])])
│ %123 = invoke Base.CoreLogging.min_enabled_level(%122::ScopedValues.ScopePayloadLogger)::Any │││││╻╷ LogState
│ Core.typeassert(%123, Base.CoreLogging.LogLevel)::Base.CoreLogging.LogLevel ││││││┃ _invoked_min_enabled_level
│ %125 = π (%123, Base.CoreLogging.LogLevel) │││││││
│ %126 = %new(Base.CoreLogging.LogState, %125, %122)::Core.PartialStruct(Base.CoreLogging.LogState, Any[Base.CoreLogging.LogLevel, Core.PartialStruct(ScopedValues.ScopePayloadLogger, Any[Base.CoreLogging.AbstractLogger, Core.PartialStruct(ScopedValues.Scope, Any[Union{Nothing, ScopedValues.Scope}, Core.Const(ScopedValues.ScopedValue{TimerOutput}( ────────────────────────────────────────────────────────────────────
Time Allocations
─────────────────────── ────────────────────────
Total measured: 9.35ms 14.0KiB
Section ncalls time %tot avg alloc %tot avg
────────────────────────────────────────────────────────────────────
Timer 1 9.35ms 100.0% 9.35ms 14.0KiB 100.0% 14.0KiB
Timer 1 1.95μs 0.0% 1.95μs 0.00B 0.0% 0.00B
────────────────────────────────────────────────────────────────────)), Core.PartialStruct(TimerOutput, Any[String, TimerOutput, Union{Nothing, TimerOutputs.TimeData}, TimerOutputs.LList{TimerOutput}])])])])
│ %127 = invoke Base.CoreLogging.with_logstate(%98::Function, %126::Any)::Core.Const(nothing) │││││
└─── goto #70 ││││
70 ─ goto #71 │││
71 ─ return %127 │
Select a call to descend into or ↩ to ascend. [q]uit. [b]ookmark.
Toggles: [w]arn, [h]ide type-stable statements, [t]ype annotations, [s]yntax highlight for Source/LLVM/Native, [o]ptimize, [d]ebuginfo, [r]emarks, [e]ffects, [i]nlining costs.
Show: [S]ource code, [A]ST, [T]yped code, [L]LVM IR, [N]ative code
Actions: [E]dit source code, [R]evise and redisplay
Advanced: dump [P]arams cache.
• %123 = invoke < min_enabled_level(::ScopePayloadLogger{…},::Tuple)::Any >
%127 = < constprop > with_logstate(::#1#2{…},::LogState{…})::Core.Const(nothing)
↩
Are you wanting to call attention to the display of the timer tables? Does this only happen in [T]yped code?
Arguably this is mostly TimerOutput's fault for printing multiple lines in its 2 argument show method. That's generally what methods in Base expect at least
Probably both should be fixed---printing a huge matrix even as a single line wouldn't be good, either.
Well I don't think I haver ever written a show method correctly. Maybe the docs have improved since last I read them?
Our IR printing does need to be robust w.r.t to users doing stupid things.
I'm not sure there's a hard-and-fast rule about multiline, but anything that prints as a pretty table is definitely something that should be reserved for MIME("text/plain") variants.