I don’t know if that would work for you (I’ve seen it being used in knutin/elli), but if all of your work is done in a single process, you can put timings into the process dictionary:
defp t(key) do
:erlang.put({:time, key}, :os.timestamp())
end
and call it in different places inside the same process
t(:start_request)
# request something
t(:done_requesting)
t(:start_parsing_body)
# parse body
t(:done_parsing_body)
and then collect the timings at some point later (you would need to be in the same process though).
Enum.flat_map(:erlang.get(), fn
{{:time, event} = key, time} ->
:erlang.erase(key)
[{event, time}]
_ ->
[]
end)
which would return something like
timings = [start_request: {1518, 275996, 334820}, done_requesting: {1518, 276000, 54915}]
and you can calculate diffs with :timer.now_diff/2
start_request = timings[:start_request]
done_requesting = timings[:done_requesting]
:timer.now_diff(done_requesting, start_request)
#=> 3720095 (microseconds)
You might want to read Two frequently used system calls are ~77% slower on AWS EC2 if you are on xen. I think beam uses these calls if it is compiled with --enable-gettimeofday-as-os-system-time
and erl_xcomp_clock_gettime_cpu_time
set to yes
, but I might be wrong.