hazardfn
Use of "inspect" in log messages
Just wanted to throw a quick question out there regarding ‘inspect’ in Elixir – for a while we were using it in our logs to print out different structures.
We then got round to doing performance testing on our project and noticed it was incredibly slow, we ran :eprof and almost all the percentage of time was spent in some whitespace_removal function and we had no idea why.
Eventually we decided logging was to blame as it’s really the only place we use strings, we played around a bit then once we removed inspect we went (as an example of just how slow it was) from processing around 300 messages a sec to 1000.
Before (Slow):
Logger.info(“Payload received: #{inspect pl}”)
After (Much faster):
Logger.info([“Payload received: “, pl])
My question is, were we using inspect wrong? Is it a kind of debugging function not to be used in production code?
I am also wondering why inspect feels it had to do all this extra processing when the second alternative I showed is much faster?
Hopefully this post also helps those struggling with performance without any idea why ![]()
Marked As Solved
josevalim
So inspect is going to check a data structure and represent as accurately as possible using Elixir syntax. This means that, if you have a binary, it will check if it is valid utf-8 codepoints, and then format it, looking for escape characters, quotes, etc. There is a chance inspect could be made faster for binaries, I don’t remember anyone particularly optimizing it, but in your case, no work will always be faster than doing any work, and if you already have a binary, you can just log the binary as is with a list.
Actually, I would say inspecting a json blob will actually make things worse, because instead of seeing {"foo": "bar"}, you will now see "{\"foo\": \"bar\"}".
Others have touched important points that arise when measuring code. For example, if you are measuring Elixir scripts, there is no protocol consolidation and that takes the hit. And I would like to add one other tip. If your log call needs to do a good amount of work, pass it an anonymous function:
Logger.info(fn -> “Payload received: #{inspect pl}” end)
The anonymous function will only be invoked if you are interested in the log level. This is specially important for info and debug messages.
Also Liked
josevalim
The first two are now 2.5 times faster on master. The third one no longer exists. ![]()
hazardfn
I might give master a try for curiosities sake later. I forgot to mention for clarities sake it was in those 3 calls (printable?, escape and append) where much of the time was being chewed up.
Thanks for all the help and advice everyone! The elixir forum does not disappoint!
belaustegui
In the After, you are using a IOList instead of a string.
This article has a good explanation on why it is faster: https://www.bignerdranch.com/blog/elixir-and-io-lists-part-1-building-output-efficiently/
Popular in Discussions
Other popular topics
Categories:
Sub Categories:
Forums
Popular Tags
- #ecto
- #liveview
- #troubleshooting
- #learning-elixir
- #deployment
- #library
- #erlang
- #testing
- #genserver
- #mix
- #absinthe
- #remote-other
- #otp
- #plug
- #how-to-question
- #macros
- #postgres
- #channels
- #elixirconf
- #exunit
- #discussion
- #code-sync
- #javascript
- #podcasts
- #onsite
- #dialyzer
- #docker
- #authentication
- #umbrella
- #full-time-contract
- #podcasts-by-brainlid
- #ecto-query
- #elixir-ls
- #phoenix_html
- #iex
- #blog-post
- #graphql
- #genstage
- #ai
- #websockets
- #supervisor
- #advent-of-code
- #elixirconf-us
- #distillery
- #processes
- #forms
- #api
- #metaprogramming
- #security
- #performance









