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 :stuck_out_tongue:

5 Likes

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/

1 Like

How large is the payload datastructure?

1 Like

Yeah, and I think example only works when “pl” is a string already. I wonder if something like that is also slow or more performant than first example, @hazardfn ?

Logger.info([“Payload received: “, inspect(pl)])
1 Like

@benwilson512 it’s a mid-sized JSON blob.

@belaustegui Thanks for the link - but it also appears as if inspect is doing some other manipulation under the hood like normalising, formatting, removing whitespace etc. Based on the function names in our eperf log at least. I suppose what I am getting at is, our “slow” example shouldn’t be AS slow as it was and might have been a performance hit we were willing to take for cleaner looking code (I quite like the #{inspect pl} “sugar”).

@hubertlepicki I can try that and let you know in a minute :slight_smile:

1 Like

I’m assuming you’re running on a relatively modern elixir version? Some of the earlier versions required a manual step to consolidate protocols and if forgotten, protocol based functions were exceptionally slow (inspect is one such function).

1 Like

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.

8 Likes

:timer.tc(fn() -> Logger.info(["payload: ", inspect(pl)]) end)

First Run: 1158
Second Run: 703

:timer.tc(fn() -> Logger.info(["payload: ", pl]) end)

First Run: 293
Second Run: 172

:timer.tc(fn() -> Logger.info("payload: #{inspect pl}") end)

First Run: 900
Second Run: 1267

Not the most concrete performance analysis you will ever see but highlights the clear differences - we had inspect all over the place in our logs using method 3 which had a very negative cumulative effect.

@hubertlepicki yours seemed to be a little more performant (again this performance analysis is hardly concrete) but still nowhere close to IOLists.

@benwilson512 I am running on 1.3.3 w/ erl 19.0.3

Inspect seems to make calls to printable? BitString.escape and BitString.append which the second method avoids.

@josevalim’s explanation as I am writing this hits the nail on the head and yes inspect did output lots of escape chars which was ugly - an optimisation might be nice as I feel inspect looks nicer in the code but it’s purely an aesthetic thing :stuck_out_tongue:.

P.S. Thanks a lot for the Logger tip had no idea this was a possibility and is certainly something we should be doing!

1 Like

The first two are now 2.5 times faster on master. The third one no longer exists. :slight_smile:

2 Likes

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!

2 Likes