Macro to provide timing for a function call - handle any signature

Questions / Help
,
1

I’m working on a macro to support automatic timing for functions.
If I have this - say:

def double(x) do
  x + x
end

I would like to be able to change it to this on a needs basis:

def_timed double(x) do
  x + x
end

I’ve got the basics of a macro written that can handle this:

defmodule Cw.Utilities.Timing.DefTimed do
  defmacro def_timed({name, _meta, args} = _ast, do: body) do
    arg_vars = Enum.map(args, fn {arg_name, _, _} -> arg_name end)

    quote do
      def unquote(name)(unquote_splicing(args)) do
        Timer.wrap_timed(
          fn unquote_splicing(arg_vars) -> unquote(body) end,
          [unquote_splicing(arg_vars)],
          unquote(name)
        )
      end
    end
  end
end

defmodule Timer do
  def wrap_timed(fun, args, name) do
    start_time = System.monotonic_time(:millisecond)
    result = apply(fun, args)
    end_time = System.monotonic_time(:millisecond)

    IO.puts("""
    [TIMED] Function: #{name}
    [TIMED] Arguments: #{inspect(args)}
    [TIMED] Execution time: #{end_time - start_time} ms
    """)

    result
  end
end

This works fine for functions with simple signatures as above.
But it doesn’t work when the signatures includes keyword-list, optionals, guards or pattern-matching.

I sense, that this must be a solved problem, but I cannot find anything online to demonstrate how to do it.
I’m looking for help to work it out.

NOTE: One of my colleagues have just pointed out, that macros should only be used sparingly (Meta-programming anti-patterns — Elixir v1.18.2).
My use-case strikes me as being pretty perfect for a macro, as adding and removing instrumentation would be a breeze (good luck to me :smiley: )
Is there a better - and equally straight forward - way for me to achieve what I’m trying to do ?

2

A very simple question: what does the expanded macro code look like? This might help understanding what is going on. Btw I don’t know. :wink:

3

Thanks for your interest and attempt to help :slight_smile:

Doing this for the above example: quoted |> Macro.expand(__ENV__) |> Macro.to_string |> IO.puts
I get:

def double(x) do
  Timer.wrap_timed(
    fn x -> x + x end,
    [x],
    :double
  )
end

The problem I have does not immediately relate to the generated AST.
Rather it relates to the first parameter to the macro: {name, _meta, args} = _ast

The args is a representation of the formal arguments to the function (including simple arguments, keylist, optionals, guards and pattern-matches), but in a form that cannot immediately be unquoted back into a form that is syntactically correct in the context of an Elixir function-definition.

Rather it contains a bunch of meta-data scattered out through the structure. So, what I’ve been looking for - specifically - is a robust way to transform args to a syntactically valid form.
However, I recognise, that I may be attacking the problem the wrong way, so I attempted to state the problem in a form that was open to other solutions.

4

I’m honestly don’t think this is a solved problem largely for the reasons you note: the forms the AST can take are quite varied. While Elixir does give you the ability to manipulate AST directly, it doesn’t give you many nice helpers like Macro.find_the_do_block_in_this_ast/1.

(I’m speculating here, but I imagine it’s because the AST is an implementation detail subject to change.)

My personal experience with writing macros is that you’re on your own somewhat. The Meta-Programming chapters of the docs are quite good. But for specific applications, you often need to dig in and see what the expressions you plan to work with happen to come out as in AST form.

Note: another snag you’ll hit is that there are other blocks that come after the do block:

def reciprocal(x) when is_integer(x) do
  1 / x
rescue
  ArithmeticError -> :infinity
end
2 Likes
5

This is very helpful information. Thank you.

I will abandon the project and find a more appropriate way to arrive at my destination.
Thanks again :slight_smile:

6

Couldn’t you just re-use the function signature as-is and then wrap the body in an anonymous function and simply close over the arguments?

Like:

def double(x) do
  Timer.wrap_timed(fn ->
    x + x
  end)
end

BTW you should look into :timer.tc/1.

1 Like
7

Just to clarify: I think the approach will work once you cover all the edge cases. I was mostly pushing back on this:

However I agree with @garrison. For most instances when I’ve needed to time functions, it was either for a one time thing or as part of a benchmarking effort.

1 Like
8

Looking back at my reply I now see it was ambiguous, so just to clarify: the snippet I posted was meant to be the macro output. I was suggesting it would be easier to write a macro which makes no attempt to pass its arguments through the anonymous function and instead just closes over them.

Then the “edge cases” shouldn’t be so hard as the final “def” call will be almost exactly the same as your “deftimed” except you just wrap a bit of the AST in a fn -> unquote(...) end block.

I do agree the use-case here is a bit strange but sometimes people do things just to experiment so I won’t judge :slight_smile:

1 Like
9

Ah got it. Yeah agreed a closure would probably be easier to implement since you can just change :def_timer to :def and wrap the do block. (I think there is still the edge case of the after block but no one uses those so who cares. :stuck_out_tongue:)

1 Like
10

Honestly I forgot def even supported more blocks, I don’t think I’ve ever seen any of them used.

Another approach would be to mangle the function name and then generate another one which wraps it with the Timer call. Stack traces would be ugly, though.

1 Like
11

The tricky part is that a function doesn’t even need to name its arguments if it pattern-matches on them, for instance:

def foo([a | _], %{wat: b}) do
  ...
end

Replacing def with def_timed:

def_timed foo([a | _], %{wat: b}) do
  ...
end

could expand to something like:

def foo(arg1, arg2) do
  Timer.wrap_timed(
    &untimed_foo/2,
    [arg1, arg2],
    :foo
  )
end

def untimed_foo([a | _], %{wat: b}) do
  ...
end

untimed_foo would use the original args AST unaltered, while the code generated in foo only cares about length(args).

Supporting default args directly in def_timed would be a lot of extra hassle, but using a do-less def would let you avoid that:

def timed_thing_with_defaults(x, y \\ 1, z \\ 2)
def_timed timed_thing_with_defaults(x, y, z) do
  ...
end
2 Likes
12

Checkout Elixir function decorators — decorator v1.4.0 which implements a module attribute based decorator pattern.

The main code for defining decorators is here: decorator/lib/decorator/decorate.ex at master · arjan/decorator · GitHub

4 Likes
13

I wonder if I am missing something here. Whatever solution you end up with, this:

…should be replaced with this:

{micros_elapsed, return_value} = :timer.tc(fn -> apply(fun, args) end)

And I see that @garrison and @billylanchantin already beat me to it.

14

Mandatory link in every Macro topic: The Erlangelist - Understanding macros, part 1

While searching for it I landed on part 6 just to learn me something about AST context which I solved in a pull request less elegantly. “Just in time” they call it :wink:

Read all 6 blog posts and the answer will be in one of them. Guaranteed.

15

Now the other mandatory thing: what do you want to accomplish?

You started by stating what you want the code to be able to, but what do you want with that data? Maybe we can find another solution getting you the same data/analysis.

16

:slight_smile: Thanks a lot for all your lovely contributions.
I’ll look through it all when I have a bit of time.

My aim @BartOtten is to work out why a particular action, that our users are doing, is timing out. It is critical to solve this problem, as it prevents our users from doing much meaningful work in our system.

It only happens in production. I’ve done significant investigations already (such as analysing the SQL-executions in an attempt to spot poor performance - which has yielded very little), and decided my next step should be to time the call-sequence in the application to narrow down where the problem is occuring.

My colleague already has a solution to time functions, but it struck me as useful only if you want to time little parts of the application. In my use-case, I really need to instrument the entire call-sequence, as I literally have no idea where the problem is coming from, and as it is expensive to repeatedly hotfix the production system.

Maybe there are tools out there which does this at a snap of my fingers - I don’t know.

The functional decomposition of the application is deep rather than flat (please don’t comment on that :smiley: :smiley: ), so I thought it would be helpful with an instrumentation mechanism that is really easy to apply. It would benefit the PR-review for the hotfix(es) to be able to easily see, that functionality has not been altered by applying timing code. Hence the idea of using a macro that substitutes def with def_timed - really easy to see in the PRs

Are you with me ?

17

This is great. Using @decorator looks helpful. I will have a dig into this.

18

I see your point. Trying to come up with less invasive solutions to find the issue.

  1. Have you tried to connect erlang Observer to the production machine? It gathers statistics about your runtime (memory usage, function reductions etc)

In a BEAM application, you can potentially have millions of processes running at the same time. In order to ensure that each process gets (roughly) equal share of the available CPU(s), the VM counts reductions. One reduction is essentially equivalent to one function call.

  1. How about erlang tracer or Tracer? Tracing is very powerful (and overlooked) in the BEAM! https://medium.com/hackernoon/a-guide-to-tracing-in-elixir-53b1afb996de
1 Like
19

Very helpful suggestions.
I will look into both.

20

Going in that direction maybe you can figure out the issue in dev with tools like The eflambe application which produces a flamegraph which you can inspect

1 Like