Bug: a macro never hit recursion limit, `cargo build` run... forever!

[limira]

I know what is my mistake, but I think there is a bug in Rust!
Edit: We just need a better help from the compiler to easily spot out mistake like this.

Edit: the problem seems just involve only the first rule. So the new minimal buggy code is:

macro_rules! there_is_a_bug {
    ( $id:ident: $($tail:tt)* ) => {
        there_is_a_bug! { $($tail:tt)* } // I dit it wrong here `:tt`
    };
}
fn main() {
    there_is_a_bug! { something: more {} }
}

cargo build will run forever! (well, I just wait for it for about ten minutes!)

rustup show
stable-x86_64-unknown-linux-gnu (default)
rustc 1.27.0 (3eda71b00 2018-06-19)

[jonas-schievink]

there_is_a_bug! { $($tail:tt)* } will triple the size of $tail on each invocation, you might be hitting exponential blowup here which the recursion limit can't catch.

[limira]

... I think I could just partially understand what you say! My impression is that the macro-expansion go depth-first, so I think it should hit recursion limit very soon.

I tried with trace_macros!(true); but cargo build just keep running without any output. In the actual code, which is much bigger than there_is_a_bug!, it is really hard to find where cause the problem because the compiler is unable to help in this case!

[ExpHP]

So, expansion does go depth first. What's blowing up is the argument list:

there_is_a_bug! { }
// expands to 
there_is_a_bug! { :tt }
// expands to 
there_is_a_bug! { : :tt tt :tt }
// expands to 
there_is_a_bug! { : :tt : :tt tt :tt tt :tt : :tt tt:tt }
// ...

In order to emit a recursion error here without first blowing the heap, I guess it would have to produce the inner token stream lazily. I'm not sure how much this could impact performance?

I tried with trace_macros!(true); but cargo build just keep running without any output.

Arrhhh! :) The old trace_macros circa 1.0 could have helped here (the one which simply dumped the invocations directly to stdout, as opposed to the new one which goes through the diagnostic APIs).

[limira]

Oh, thank you very much! What is still remain as a question for me is that: why the memory usage increase so slow!? When run cargo build the minimal code above, I open System monitor and watch rustc. I expect that its memory usage must increase drastically, but in contrast to my expectation, it increase... slowly. But I am glad that it does not eat out all my memory, because when my system (Fedora 27) is out of memory I don't know what to do except cutting it power.

[ExpHP]

What is still remain as a question for me is that: why the memory usage increase so slow!?

This is an interesting question, so I tried taking a look into it using perf. Unfortunately there isn't much I can say with any confidence!

amateur hour theatre: `perf` edition

perf stat shows:

 Performance counter stats for 'rustc src/main.rs':

    30,455,642,992      instructions              #    0.61  insn per cycle           (50.05%)
    50,185,555,208      cycles                                                        (29.97%)
    17,998,100,630      L1-dcache-loads                                               (39.92%)
       610,971,632      L1-dcache-load-misses     #    3.39% of all L1-dcache hits    (49.93%)
        77,208,094      dTLB-load-misses                                              (49.93%)
     1,831,023,187      cache-references                                              (39.98%)
     5,621,259,040      branch-instructions                                           (50.00%)
         9,967,961      branch-misses             #    0.18% of all branches          (50.05%)
     8,744,794,469      L1-icache-loads                                               (40.08%)
        59,622,536      L1-icache-misses          #    0.68% of all L1-icache hits    (40.04%)

3.3% cache misses sounds like maybe a lot for what is mostly a bunch of similar code running without allocating memory at a fast rate; but I'm not sure.

---

The three hottest functions identified by a basic perf record are:

% samples  object      demangled name
47.93%    libsyntax   <Vec<T> as Clone>::clone
24.47%    libsyntax   <Vec<T> as Drop>::drop
16.79%    libsyntax   <Option<&'a T>>::cloned

What are the Ts? Well, to be honest, I don't know. Looking at the disassembly output my best guess is that in all three cases, T is ext::tt::macro_parser::NamedMatch.

Aside: I see calls to a function called <Span as Clone>::clone@plt, which point to this funny looking stub in the .plt section. It's hard for me to understand why <Span as Clone>::clone has any presence in an optimized binary!

---

What's calling those three functions so often?

Unfortunately, perf record -g is giving me useless callstacks with no information, even on an (optimized) compiler built with debug info. That said, there aren't very many clones in macro_parser.rs. One thing does stand out to me which is

impl<'a> MatcherPos<'a> {                                                                           
    /// Add `m` as a named match for the `idx`-th metavar.                                          
    fn push_match(&mut self, idx: usize, m: NamedMatch) {                                           
        let matches = Rc::make_mut(&mut self.matches[idx]);                                         
        matches.push(m);                                                                            
    }                                                                                               
}

which potentially clones a Vec<NamedMatch> (in Rc::make_mut) just to push a single item. However I can't find any "smoking gun" evidence that this is the problem.

[ExpHP]

By the way, when I mentioned "the old trace_macros," this is actually a thing you can do:

rustup toolchain add 1.5.0
cargo +1.5.0 build

If your crate begins with

#![feature(trace_macros)]
trace_macros!(true);

then it will do the tracing to stdout, even though #![feature] isn't supposed to work on stable compilers. (what happens is that macro expansion occurs before the compiler checks whether you are actually allowed to use #[feature] flags!)

[ExpHP]

One last thing: Here's a flamegraph generated from a stage 1 debug compiler. This is a non-optimized compiler since the optimized debug compiler was producing callstacks that provided zero context for any of the functions of intrest (the second item in the callstack was <unknown> at some raw address).

Flamegraph: perf.svg.gz

It suggests the following:

• As I suspected, push_match is frequently being called in places where it must perform an O(n) clone (34661 samples for Vec::clone) just to push a single item onto a vec (46 samples for Vec::push).
• macro_parser::parse very frequently drops an ArrayVec<MatcherPos> which requires several layers of deinitialization code to decrement refcounts in NamedMatches.

What I do not know, however, is whether these are performance bugs that can be fixed, or if they are concessions that were made in favor of optimizing hotter codepaths.

[limira]

By the way, when I mentioned "the old trace_macros," this is actually a thing you can do

Thanks for the info! Maybe the current trace_macros!(true); need to be improved to help cases like this without having to go back time.

[ExpHP]

I'm going to create a separate issue for the lack of trace_macros! output, so that this issue can be about the performance of this macro's expansion (which I think ought to hit some sort of error more quickly)

[ExpHP]

(I think this should be tagged with I-slow or something similar, can anyone add that?)