How can I debug mix to see where it spends time ?

[Sébastien Merle]

Hi,

I am toying with a macro heavy project, and mix test takes 15 minutes, half of that time is spent loading the test code.

How can I debug what is happening during the loading phase ?

The project in question is https://github.com/sylane/extract/tree/prototype and is about validation and conversion.

Thank you.

Regards,
Sebastien Merle.

[José Valim]

You don't want to measure Mix but just the regular Elixir code execution (loading Elixir code is just executing Elixir code). First try executing tests file by file:

    mix test path/to/test/file.exs

And see if there is one that is drastically slower than other. Then you can place around the module definition any benchmarking and profiling tool you would use on Elixir code.

If they are all equally bad, try providing a minimum case (that runs in 30 seconds, let's say), and I will gladly take a look. I have some ideas of what it may be but I want to be sure before I give any direction. For reference, a large Phoenix router could take minutes too and we optimized it to a couple seconds not long ago.

José Valim

www.plataformatec.com.br

Skype: jv.ptec

Founder and Lead Developer

--
You received this message because you are subscribed to the Google Groups "elixir-lang-talk" group.
To unsubscribe from this group and stop receiving emails from it, send an email to elixir-lang-ta...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/elixir-lang-talk/af2baa65-2a32-461c-8299-77c1a741934b%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[José Valim]

To be clear: by "loading", did you mean loading (the one that shows at the end of tests) or compilation?

José Valim

www.plataformatec.com.br

Skype: jv.ptec

Founder and Lead Developer

[Sébastien Merle]

I meant the time spent after executing mix test and before the tests are actually executed.

I found a strange behavior.
The tests uses testing macros (around 15 per modules) that uses other macros (10 macros each, for a total of 150).
This is two levels of macro expansion, and if I change this first level macros to functions the tests starts right away effectively cutting the total time by half.
I needed this first level macro so I can pass a pattern match as parameter instead of an expected value.

[José Valim]

You are probably having the same issue as Phoenix.

If you invoke too many macros that inject variables in the module body, you easily end-up with thousands of variables in the module body and the Erlang compiler down the stack is going to choke on it (they use a linear data structure, it is a story for another day).

The way we fixed this issue in Phoenix is to ensure the variables do not leak. For example, let's suppose your macro is outputing this code:

    a = do_this

    b = do_that

    c = and_that

If you make it output this code:

    (fn ->

      a = do_this

      b = do_that

      c = and_that

    end).()

The problem should disappear. If you are calling the same code multiple times with different arguments, you can even define a function once and just pass the multiple arguments. Again, that's what we did with Phoenix:

https://github.com/phoenixframework/phoenix/commit/b77681dac15ef5d282ed9b7407f918580c48537d#diff-9a7a38188e7c9b90bc973ece4f731b21R200

I hope this gives some direction. If not, please send me a command I can run in order to reproduce the issue but that doesn't take 7 minutes. :)

José Valim

www.plataformatec.com.br

Skype: jv.ptec

Founder and Lead Developer

To view this discussion on the web visit https://groups.google.com/d/msgid/elixir-lang-talk/c74c510f-164b-4253-b4aa-5af97196c029%40googlegroups.com.

[Sébastien Merle]

It was exactly this issue. just by encapsulating the generated code in functions the "loading" got 35 times faster, from 7 minutes to 12 seconds !

Thank you a lot, really good to know !