[mlir] debug-only=greedy-rewriter is quadratic

[silvasean]

Running this script with varying values of N produces IR like this:

module {
    func.func @foo(%arg0: i64) -> i64 {
        %c0 = arith.constant 0 : i64
        %0 = arith.addi %arg0, %arg0 : i64

%1 = arith.addi %0, %c0 : i64
%2 = arith.addi %1, %1 : i64
%3 = arith.addi %2, %c0 : i64
%4 = arith.addi %3, %3 : i64
return %4 : i64

    }
}

Every second addi is eliminated by the canonicalizer.

Running a command line like the following reveals a quadratic behavior:

time -- python /tmp/quadratic.py | mlir-opt -canonicalize -debug-only=greedy-rewriter |& cat >/dev/null

N= 2000 - 0.57s
N= 4000 - 1.76s -- ~4x higher
N= 8000 - 6.17s -- ~4x higher
N=16000 - 24.63s -- ~4x higher
N=32000 - 98.52s -- ~4x higher

If I comment out this line then the time is:

N= 32000 - 3.19
N= 64000 - 6.42 -- ~2x higher
N=128000 - 12.87 -- ~2x higher

I think one possible solution here would be to not print the %foo = since I suspect the quadratic behavior comes from numbering the SSA values -- if we want a stable identifier to refer to, we can print source locations or something. But just not printing the %foo = would be a good first step.

I ran into this during a test case reduction of pattern rewrites not converging. My test case had complex control flow and it was not easy to reduce manually, so as a first step I wanted to see what pattern was involved and which op. To do that I was going to grep the output of debug-only=greedy-rewriter, but the output was being produced so slowly that I could not even get a full dump out even after 10 minutes. After commenting out the line I mentioned above, the entire dump is produced in about 1 second. The module has about 50k ops.

[llvmbot]

@llvm/issue-subscribers-mlir

[joker-eph]

You're use-case is very likely the kind of instrumentation to be built with the "action" framework I think

[silvasean]

Thanks for the pointer. Are there any docs for how to use this in the context of the greedy pattern rewriter? I saw there was something related to pattern "tags" or something but I don't think we have that enabled in our codebase.

Also, in this case, it is not the actual outputting that is slow, but rather the quadratic time it takes to print. It would be good to fix the root cause here which is the quadratic time it takes to print the debug dump in the first place.

[joker-eph]

Do you have a suggestion on what to print for the operands numbers? They can refer to IR that is arbitrarily far.
(I don't know how much --mlir-print-local-scope can affect your timings)

[joker-eph]

Thanks for the pointer. Are there any docs for how to use this in the context of the greedy pattern rewriter? I saw there was something related to pattern "tags" or something but I don't think we have that enabled in our codebase.

Sorry, forgot to answer about this part: I'm still landing some pieces (including the doc which is missing right now), but you can catch actions generically, or specifically match what the greedy rewriter dispatches right now..... ahem, I actually hadn't landed https://reviews.llvm.org/D144816 ! I just did :)

(If you missed it, I presented this in details at an open meeting two months ago: https://discourse.llvm.org/t/open-mlir-meeting-2-23-2023-mlir-actions-tracing-and-debugging-mlir-based-compilers/68680 )

[silvasean]

Do you have a suggestion on what to print for the operands numbers? They can refer to IR that is arbitrarily far. (I don't know how much --mlir-print-local-scope can affect your timings)

Is there any particular guarantee about the operand numbering? The IR can be arbitrarily mutated by previous patterns so I don't think the numbers are actually meaningful (at least not in any easily interpretable way). So I would maybe consider just printing them as "%foo, %bar" or something.

(If you missed it, I presented this in details at an open meeting two months ago: https://discourse.llvm.org/t/open-mlir-meeting-2-23-2023-mlir-actions-tracing-and-debugging-mlir-based-compilers/68680 )

Thanks!