Macroexpansions take a long time to revise

[cstjean]

My macro-heavy package worked fine with Revise 0.7.14, but takes forever with the current release. It seems to be because the macroexpansion code is interpreted.

julia> @time using Revise, ChlorineAdvisory    # already precompiled
   [R2Data Initialized. Current host : atonal]
 15.547385 seconds (21.15 M allocations: 1.126 GiB, 4.95% gc time)

... restart

julia> @time using ChlorineAdvisory   # __precompile__(false)
[ Info: Precompiling ChlorineAdvisory [376598ac-807b-11e9-2116-cd40751e1c02]
[ Info: Skipping precompilation since __precompile__(false). Importing ChlorineAdvisory [376598ac-807b-11e9-2116-cd40751e1c02].
 42.670977 seconds (71.50 M allocations: 3.675 GiB, 4.20% gc time)

... restart ...

julia> @time using Revise, ChlorineAdvisory    # __precompile__(false)
[ Info: Precompiling ChlorineAdvisory [376598ac-807b-11e9-2116-cd40751e1c02]
[ Info: Skipping precompilation since __precompile__(false). Importing ChlorineAdvisory [376598ac-807b-11e9-2116-cd40751e1c02].

... 50 minutes and counting ...

Thankfully, Julia and Unitful are more precompilable nowadays, but I still can't revise the .jl that contains the big macroexpansions. It hangs, presumably because it's macroexpanding. Wouldn't it make sense to call the compiled macroexpand? (if that is indeed the issue)

Sorry that I don't have a MWE. I'll try to get one in the following weeks.

[cstjean]

Revise@1.1.1 solves the issues. It takes ~2 seconds to revise that particular file, but that's no problem at all, and it is compatible with Julia 1.2.0. Thank you!

[timholy]

I'd rather have you on Revise 2 :smile:

Macro expansion itself is handled through lowering and has nothing to do with Revise. However, if your package does a lot of work at toplevel during module definition, Revise 2 will be slower.

The three options are:

• make the interpreter faster
• add a facility to mark code as non-revisable, e.g., @once
• further improve Revise's code-analysis to the point that it can realize that "I don't need to interpret this because there are no method definitions inside." Then it could skip your init code.

For the last one, the teh/backedges might contain a start.

[cstjean]

I made some progress! It turns out that interrupting the endless revision "fixes" Revise.

... load code, then modify the file with a long macro

julia> 1     # gets stuck in revision forever. Must be interrupted.
^C┌ Warning: Failed to revise /home/cst-jean/jdev/ChlorineAdvisory/src/RulesV2.jl: InterruptException()
└ @ Revise ~/.julia/packages/Revise/439di/src/Revise.jl:556
┌ Warning: Due to a previously reported error, the running code does not match saved version for the following files:
│   /home/cst-jean/jdev/ChlorineAdvisory/src/RulesV2.jl
└ @ Revise ~/.julia/packages/Revise/439di/src/Revise.jl:564
1

... modify file again

julia> RulesV2.foo(12)    
26              # takes less than 1 second!

This is true on v2.2.2, and on teh/backedges. And it makes sense: my macroexpanded code is just a boring list of definitions. I don't see why interpreting it should take time.

It's too bad that Revise swallows the exception and stack trace. Is there any way to avoid that behavior, to know where it's stuck?

[cstjean]

Other datapoint: if I

1. make that file almost empty
2. restart julia, reload code
3. modify file to trigger revision (which is fast)
4. put the full code in it, to trigger other revision

Then that revision (and subsequent ones) are also < 5 seconds. It's as if the very first revision of that file does something different, which takes forever.

[timholy]

I'm assuming your module is precompiled. The first revision is different: it takes an inventory of what the module contains, and then uses that to compute "diffs" with respect to the modified version. It uses the original source-text, at the time the module was precompiled, by loading a cache that's stored in the *.ji file. (For non-precompiled packages, Revise has to do the inventory when you first load the module, because without a backup copy it's too late to compute a diff if you wait for your one-and-only copy of the file to be modified.)

This analysis and diff computation is done on a file-by-file basis, analyzing only files that change. The first revision analyzes the expressions in the file and extracts signatures of all the methods. Revise then maintains a cache of expressions and the resulting signatures. Future revisions just compute all the toplevel expressions and then look for differences on an expression-level.

I'm not certain I fully understand your test, but it sounds insightful. Are you basically saying that you can get Revise through the process as long as the troublesome code is not in the module definition when the first revision is triggered? That is a little surprising.

[timholy]

Does your macro-magic result in something being written to disk? In particular, making changes to any of the dependent files?

[cstjean]

Yes, it is precompiled.

Are you basically saying that you can get Revise through the process as long as the troublesome code is not in the module definition when the first revision is triggered?

Yes.

Does your macro-magic result in something being written to disk? In particular, making changes to any of the dependent files?

No. My macroexpansion looks a bit like:

    begin
        Blah = (Advisory).R2Function(begin
                    function ##rule#683(##df#681, ##config#682; kw=1)
                        $(Expr(:meta, :noinline))
                        ... deeply nested math expression with broadcasting and closures
                     end)
        ... 50X more Blahs

Could it be having trouble with my named functions that are defined inside of an expression?

[timholy]

Are you basically saying that you can get Revise through the process as long as the troublesome code is not in the module definition when the first revision is triggered?

Yes.

Wow, that's wild. I don't have any ideas for what might cause that.

Could it be having trouble with my named functions that are defined inside of an expression?

What happens with those expressions? Do they get expanded by lowering (i.e., Julia's normal macro expansion) or by an explicit eval? If it's through lowering, I can't imagine how this is happening.

If you can share your code, even privately (tim.holy@gmail.com), I could take a look myself.

[cstjean]

Normal macroexpansion. It's quite a boring macro. It's just very long. If I chop it to just the first Blah, I don't get the issue. With all the Blahs, I waited today again 50 minutes, it just never finished.

I'll find a way to share the code, thank you for all the support!

[cstjean]

Is there an easy way that I could call the first revision on a file, something like do_first_revision(MyModule, "my_file.jl"), so that I could Ctrl-C it and see where it's stuck? Then I could print-statement into figuring out the issue.

I tried yesterday to move my named functions to the top-level. Same results.

[cstjean]

This analysis and diff computation is done on a file-by-file basis, analyzing only files that change. The first revision analyzes the expressions in the file and extracts signatures of all the methods. Revise then maintains a cache of expressions and the resulting signatures. Future revisions just compute all the toplevel expressions and then look for differences on an expression-level.

How do you deal with gensyms in the macroexpanded/lowered code, for comparison purpose? Do you put the expressions in some kind of canonical form? Are all algorithms O(N) in the size of the Expr?

[timholy]

Is there an easy way that I could call the first revision on a file

Yes. First, you should start Revise with the environment variable "JULIA_REVISE" set to "manual" (https://timholy.github.io/Revise.jl/stable/config/#Manual-revision:-JULIA_REVISE-1). Then, after using ChlorineAdvisory, grab the pkgdata for it like this (illustrated for OrderedCollections):

julia> using OrderedCollections

julia> id = Base.PkgId(OrderedCollections)
OrderedCollections [bac558e1-5e72-5ebc-8fee-abe8a469f55d]

julia> pkgdata = Revise.pkgdatas[id]
PkgData(OrderedCollections [bac558e1-5e72-5ebc-8fee-abe8a469f55d]:
  "src/OrderedCollections.jl": FileInfo(OrderedCollections=>ExprsSigs(<0 expressions>, <0 signatures>), with cachefile /home/tim/.julia/compiled/v1.3/OrderedCollections/LtT3J_tZjuv.ji)
  "src/dict_support.jl": FileInfo(OrderedCollections=>ExprsSigs(<0 expressions>, <0 signatures>), with cachefile /home/tim/.julia/compiled/v1.3/OrderedCollections/LtT3J_tZjuv.ji)
  "src/ordered_dict.jl": FileInfo(OrderedCollections=>ExprsSigs(<0 expressions>, <0 signatures>), with cachefile /home/tim/.julia/compiled/v1.3/OrderedCollections/LtT3J_tZjuv.ji)
  "src/little_dict.jl": FileInfo(OrderedCollections=>ExprsSigs(<0 expressions>, <0 signatures>), with cachefile /home/tim/.julia/compiled/v1.3/OrderedCollections/LtT3J_tZjuv.ji)
  "src/ordered_set.jl": FileInfo(OrderedCollections=>ExprsSigs(<0 expressions>, <0 signatures>), with cachefile /home/tim/.julia/compiled/v1.3/OrderedCollections/LtT3J_tZjuv.ji)
  "src/dict_sorting.jl": FileInfo(OrderedCollections=>ExprsSigs(<0 expressions>, <0 signatures>), with cachefile /home/tim/.julia/compiled/v1.3/OrderedCollections/LtT3J_tZjuv.ji)

From there, call Revise.revise_file_now(pkgdata, filename), where filename should be like "src/ordered_set.jl", a relative path and thus one of the keys for the PkgData.

EDIT: if you do this, there shouldn't be a need to make a change to the file.

How do you deal with gensyms in the macroexpanded/lowered code, for comparison purpose?

https://github.com/timholy/Revise.jl/blob/710483515fd82c4007b4e31f0c361e4914d407cd/src/relocatable_exprs.jl#L107-L110

See also the hash method that follows it.

Are all algorithms O(N) in the size of the Expr?

Should be. But if you have a distinct expressions that differ only by gensyms, I'm not sure what will happen.

[cstjean]

Ok. It's stuck in

julia> Revise.revise_file_now(pkgdata, "src/RulesV2.jl")
^CERROR: InterruptException:
Stacktrace:
 [1] Type at ./pair.jl:12 [inlined]
 [2] iterate at ./iterators.jl:238 [inlined]
 [3] iterate(::Base.Iterators.Filter{getfield(Base, Symbol("##79#80")){typeof(LoweredCodeUtils.ismethod1)},Base.Iterators.Pairs{Int64,Any,LinearIndices{1,Tuple{Base.OneTo{Int64}}},Array{Any,1}}}, ::Int64) at ./iterators.jl:432
 [4] iterate at ./generator.jl:44 [inlined]
 [5] grow_to!(::Array{Int64,1}, ::Base.Generator{Base.Iterators.Filter{getfield(Base, Symbol("##79#80")){typeof(LoweredCodeUtils.ismethod1)},Base.Iterators.Pairs{Int64,Any,LinearIndices{1,Tuple{Base.OneTo{Int64}}},Array{Any,1}}},typeof(first)}, ::Int64) at ./array.jl:697
 [6] grow_to!(::Array{Int64,1}, ::Base.Generator{Base.Iterators.Filter{getfield(Base, Symbol("##79#80")){typeof(LoweredCodeUtils.ismethod1)},Base.Iterators.Pairs{Int64,Any,LinearIndices{1,Tuple{Base.OneTo{Int64}}},Array{Any,1}}},typeof(first)}) at ./array.jl:670
 [7] collect at ./array.jl:604 [inlined]
 [8] findall at ./array.jl:1982 [inlined]
 [9] #methoddef!#3(::Bool, ::typeof(LoweredCodeUtils.methoddef!), ::Any, ::Array{Any,1}, ::JuliaInterpreter.Frame, ::Any, ::Int64) at /home/cst-jean/.julia/packages/LoweredCodeUtils/QwLdT/src/LoweredCodeUtils.jl:405
 [10] #methoddef! at ./array.jl:0 [inlined]
 [11] #methoddef!#6 at /home/cst-jean/.julia/packages/LoweredCodeUtils/QwLdT/src/LoweredCodeUtils.jl:441 [inlined]
 [12] (::getfield(LoweredCodeUtils, Symbol("#kw##methoddef!")))(::NamedTuple{(:define,),Tuple{Bool}}, ::typeof(LoweredCodeUtils.methoddef!), ::Function, ::Array{Any,1}, ::JuliaInterpreter.Frame, ::Int64) at ./none:0
 [13] #methoddef!#3(::Bool, ::typeof(LoweredCodeUtils.methoddef!), ::Any, ::Array{Any,1}, ::JuliaInterpreter.Frame, ::Any, ::Int64) at /home/cst-jean/.julia/packages/LoweredCodeUtils/QwLdT/src/LoweredCodeUtils.jl:412
 ... (the last 4 lines are repeated 9 more times)
 [50] (::getfield(LoweredCodeUtils, Symbol("#kw##methoddef!")))(::NamedTuple{(:define,),Tuple{Bool}}, ::typeof(LoweredCodeUtils.methoddef!), ::Function, ::Array{Any,1}, ::JuliaInterpreter.Frame, ::Expr, ::Int64) at ./none:0
 [51] #methods_by_execution!#14(::Bool, ::Bool, ::typeof(Revise.methods_by_execution!), ::Any, ::Revise.CodeTrackingMethodInfo, ::Dict{Module,Array{Expr,1}}, ::JuliaInterpreter.Frame) at /home/cst-jean/.julia/packages/Revise/439di/src/lowered.jl:81
 [52] #methods_by_execution! at ./none:0 [inlined]
 [53] #methods_by_execution!#9(::Bool, ::Base.Iterators.Pairs{Symbol,Bool,Tuple{Symbol},NamedTuple{(:define,),Tuple{Bool}}}, ::typeof(Revise.methods_by_execution!), ::Any, ::Revise.CodeTrackingMethodInfo, ::Dict{Module,Array{Expr,1}}, ::Module, ::Expr) at /home/cst-jean/.julia/packages/Revise/439di/src/lowered.jl:49
 [54] #methods_by_execution! at ./none:0 [inlined]
 [55] #eval_with_signatures#63(::Bool, ::Base.Iterators.Pairs{Union{},Union{},Tuple{},NamedTuple{(),Tuple{}}}, ::typeof(Revise.eval_with_signatures), ::Module, ::Expr) at /home/cst-jean/.julia/packages/Revise/439di/src/Revise.jl:353
 [56] #eval_with_signatures at /home/cst-jean/.julia/packages/Revise/439di/src/Revise.jl:0 [inlined]
 [57] #instantiate_sigs!#64(::Bool, ::Base.Iterators.Pairs{Union{},Union{},Tuple{},NamedTuple{(),Tuple{}}}, ::typeof(Revise.instantiate_sigs!), ::OrderedCollections.OrderedDict{Module,OrderedCollections.OrderedDict{Revise.RelocatableExpr,Union{Nothing, Array{Any,1}}}}) at /home/cst-jean/.julia/packages/Revise/439di/src/Revise.jl:361
 [58] instantiate_sigs! at /home/cst-jean/.julia/packages/Revise/439di/src/Revise.jl:358 [inlined]
 [59] maybe_parse_from_cache!(::Revise.PkgData, ::String) at /home/cst-jean/.julia/packages/Revise/439di/src/pkgs.jl:229
 [60] handle_deletions at /home/cst-jean/.julia/packages/Revise/439di/src/Revise.jl:480 [inlined]
 [61] revise_file_now(::Revise.PkgData, ::String) at /home/cst-jean/.julia/packages/Revise/439di/src/Revise.jl:509

Will investigate.

[cstjean]

revise_file_now returns instantaneously afterwards, which makes debugging painful (I have to restart Julia). Is there any way that I can "reset" Revise without restarting?

EDIT: got it, Revise.instantiate_sigs!(Revise.fileinfo(pkgdata, file).modexsigs) reliably hangs.

[timholy]

Ok. It's stuck in

Whoa. Reliably at this line? That's very unexpected. You might want to insert a @show frame.framecode.src.code right before that line. You'll get a lot of output, but it should (mercifully) stop right before the hang.

[timholy]

Or perhaps better do something like this:

index c1b785f..cb7ff0a 100644
--- a/src/LoweredCodeUtils.jl
+++ b/src/LoweredCodeUtils.jl
@@ -319,6 +319,8 @@ function correct_name!(@nospecialize(recurse), frame, pc, name, parentname)
     return name, pc
 end

+const thecode = Ref{Any}(nothing)
+
 """
     ret = methoddef!(recurse, signatures, frame; define=true)
     ret = methoddef!(signatures, frame; define=true)
@@ -402,6 +404,7 @@ function methoddef!(@nospecialize(recurse), signatures, frame::Frame, @nospecial
         # We can only correct one at a time, so work backwards from a non-gensymmed name
         # (https://github.com/timholy/Revise.jl/issues/290)
         pc0 = pc
+        thecode[] = frame.framecode.src.code
         idx1 = findall(ismethod1, frame.framecode.src.code)
         idx1 = idx1[idx1 .>= pc]
         hashhash = map(idx->startswith(String(pc_expr(frame, idx).args[1]), '#'), idx1)

and examine LoweredCodeUtils.thecode[] after hitting Ctrl-C.

[cstjean]

I've been running this script to pinpoint the problem:

       ENV["JULIA_REVISE"] = "manual"; using Revise, ChlorineAdvisory

       id = Base.PkgId(ChlorineAdvisory); pkgdata = Revise.pkgdatas[id]; file = "src/...";

       @eval Revise.LoweredCodeUtils function methoddef!(@nospecialize(recurse), signatures, frame::Frame, pc::Int; define=true)
           println((frame.pc, frame.framedata.callargs[1][1]))
           methoddef!(recurse, signatures, frame, pc_expr(frame, pc), pc; define=define)
       end

       Revise.revise_file_now(pkgdata, file)

I've sent part of the output to your email address (it goes forever).

[timholy]

OK, so it's somehow stuck in a cycle. I think you need to debug this at a higher level, for example put a breakpoint at the entrance to Revise.instantiate_sigs! and see what the expressions are. What you sent me looks like it has a cycle length of 8, so it shouldn't be too painful to find it.

You'll need to avoid using the interpreter for any code in the interpreter itself. (In Juno you can check the "Compiled mode" checkbox, in Debugger.jl you can use C to toggle between interpreted and compiled mode.) Don't descend any lower than necessary to see the cycling. I'm guessing somewhere between instantiate_sigs! and methoddef! you'll find it.

[cstjean]

What you sent me looks like it has a cycle length of 8, so it shouldn't be too painful to find it.

It looks acyclic to me. Eg. the pc of 584 happens only once in the entire file.

[timholy]

OK. Still, what you sent isn't enough to figure it out. You should find the rexs that instantiate_sigs! is working on easy to understand, and if you get trapped in an infinite process you'll have isolated it to a single expression. From there you could supply that expression directly to eval_with_signatures.

[cstjean]

The whole file is just one big

@def_many_rules begin
    rule1() = ...
    rule2() = ...
    ...
end

so the rex didn't tell me anything new. I'll keep looking!

[timholy]

Is it just a single frame? Is there anything that loops? (Look for :goto or :gotoifnot expressions in the frame.) If not, then pc should never decrease, and the fact that it does is the source of the bug. You could add a

pcold = pc

near the top of methods_by_execution! and then an @assert pc >= pcold somewhere.

[cstjean]

The whole thing happens within a methoddef! call, that never returns, all in the same frame. The stack traces point at line 412:

https://github.com/JuliaDebug/LoweredCodeUtils.jl/blob/4cc0d108f64ed566ac3b5b86404c83a2ea4eddb0/src/LoweredCodeUtils.jl#L400-L415

@show inside this while loop shows

frame.pc = 2281
name = Symbol("#Normal_ow¤beta_def__#265")
frame.pc = 2084
name = Symbol("#Normal_ow¤beta_def__#265")
frame.pc = 2281
name = Symbol("#Normal_ant¤beta_def__#271")
frame.pc = 1236
name = Symbol("#Normal_ad¤beta_def__#89")
frame.pc = 2281
name = Symbol("#Normal_ood¤beta_def__#133")
frame.pc = 2084
name = Symbol("#Normal_ood¤beta_def__#133")
frame.pc = 2281
name = Symbol("#Normal_lant¤beta_def__#271")
etc.

About this comment:

  # We will have to correct the name.
  # We can only correct one at a time, so work backwards from a non-gensymmed name
  # (https://github.com/timholy/Revise.jl/issues/290)

What happens if there's 60 of those gensymmed names, each of which involves a recursive call to methoddef!? I don't understand the logic enough, unfortunately.

Looking back at the list of pcs, with some clean-up and replacing of values, there's a definite pattern there, if I start from the beginning:

1
2
1
3
1
2
1
4
1
2
1
3
1
2
1
5
1
2
1
3
1
2
1
4
1
2
1
3
1
2
1
6
1
2
1
3
1
2
1
4
1
2
1
3
1
2
1
5
1
2
1
3
1
2
1
4

There's a 1 every two entries, a 2 every 4, a 3 every 8, etc. I wish I knew the name of the pattern! :slightly_smiling_face: It's like the position of the most significant digit that changed when counting in binary.

[cstjean]

@mbauman gave https://oeis.org/A001511

[timholy]

Oh dear. This won't be trivial to fix, but at least we know a lot more. Are any of these actually keyword-argument functions or are they all just gensymmed? If so you can probably circumvent the problem by naming things like this:

julia> Symbol(:prefix, gensym(:hey))
Symbol("prefix##hey#372")

[cstjean]

They're keyword-argument functions, unfortunately. But it doesn't matter, I already have a work-around. Ctrl-C during the first revision then everything is fine.