Joseph Kain bio photo

Joseph Kain

Professional Software Engineer learning Elixir.

Twitter LinkedIn Github

Over the last few weeks I’ve been writing a series on Optimizing Elixir code for my Game of Life. Actaully, so far I’ve only written about tools - available profiling tools and tools I’mbuilding for Comparing Benchmark Results Its time to finally start applying these tools and optmizing the code!

Integrate bmark

The first thing I did was to replace the lifebench and lifebench.cmp tasks with my standalone bmark tool. lifebench and bmark are similar but I’ve made a few improvements to the reporting in bmark that I want to incorporate. I added bmark to my mix.exs file. At the moment it refernces it via local path but once I fix up a few remaining issues I’ll put it on github.

I added a bmark based benchmark using the existing Profile module. For new code I would forgoe the Profile module and write the benchmarking code directly in the _bmark.ex file. Here’s my bmark:

defmodule LifeBench do
  use Bmark

  bmark :glider do

After writing this I uncovered the first of several bugs in bmark. Its good to run it through a somewhat realistic case like my Game of Life. A GenServer call times out because the benchmark takes too long to run. After a quick fix I run into the second bug: I need to create a directory named results to store the results file. If the directory doesn’t exist the benchmark is run but the results are lost. Another quick fix and I’m on my way.


Now that I have bmark ready I can start measuring. I want to measure in the production environment so I start by setting

export MIX_ENV=prod

in my shell. You can assume I’m running production from now on.

I collect baseline results by running mix bmark


I want to save these in a base directory. Hmm, I need to manually copy results to base. I’ll need to do this copy everytime. For the moment I choose to do this manually, but I’ll want to automate this soon as it will be tedious and prone to error.

Consolidating Protocols in Elixir

Serveral weeks ago Johan Wärlander suggested that I consolidate the protocols used in my Game of Life implementation in order to reduce time spent in functions like ‘Elixir.Code’,’ensure_compiled?’. He points out that protocol consolidation should be a part of preparing an Elixir application for a production release. Before Johan’s comment I hadn’t heard of protocol consolidation so I read up a bit on it. José Valim’s,in a github issue, described the process in terms of generating fast dispatches (without lookups) when all protocol implementations are known. This works well in the case of packaging a release. The protocol compilation can be invoked by mix as

$ mix compile.protocols

which writes out new binary files containing the consolidated protocols. But, this requires that the application be run as

$ elixir -pa _build/MIX_ENV/consolidated -S mix run

to set the loadpath to include the consolidated protocol files. I consolidated protocols and reran the benchmark:

lifebench.glider.results:  lifebench.glider.results:
15050451                   14887006
15282246                   15028554
15095683                   14762181
15049299                   14905275
15292709                   14577768
15018099                   14883831
15009078                   14795362
15266227                   14897746
15146941                   14763634
15111238                   14904190

15132197.1 -> 14840554.7 (-1.93%) with p < 0.0005
t = 5.60108220481427, 18 degrees of freedom

Another problem with bmark: I use the basename of the results files for the header in the report. But, in my setup with separate resluts directories the files have the same name and so I can’t tell the two columns apart. Another fix to bmark and I have:

base/lifebench.glider.results:  consolidate/lifebench.glider.results:
15050451                        14887006
15282246                        15028554
15095683                        14762181
15049299                        14905275
15292709                        14577768
15018099                        14883831
15009078                        14795362
15266227                        14897746
15146941                        14763634
15111238                        14904190

15132197.1 -> 14840554.7 (-1.93%) with p < 0.0005
t = 5.60108220481427, 18 degrees of freedom

Ok, so the report looks nice and this is a performance win! Protocol consolidation has lowered the run time by almost 2%.

Going forward I need to continue to run with protocol consolidation, but this isn’t a code change so it doesn’t “stick”. I need to make sure that I

  1. Remember to compile the protocols before each profile run
  2. Remember to run with the right command line to enable the use of the consolidated protocols.

This is a lot to remember, I better right myself a script to do it.


if [ -z "$1" ]; then
  echo "Usage <name>"
  exit -1

export MIX_ENV=prod
mkdir -p results
mix compile
mix compile.protocols
elixir -pa _build/prod/consolidated/ -S mix bmark
mv results $1

I also decided to go ahead and save the results directory based on a command line argument. And I set the production environment in the script just in case I start a new shell and forget to set MIX_ENV. With my new script ready I can move ahead to the next optimization.

Count Live Neighbors

Next we profile with ExProf:

FUNCTION                                           CALLS      %      TIME  [uS / CALLS]
--------                                           -----    ---      ----  [----------]
'Elixir.Access':get/2                             419073   0.53     85973  [      0.21]
'Elixir.Enumerable.List':reduce/3                 657360   0.54     86879  [      0.13]
'Elixir.Access':'impl_for!'/1                     419073   0.57     91691  [      0.22]
'Elixir.Life':'-list_of_neighbors/3-fun-0-'/6     369765   0.60     96884  [      0.26]
code_server:call/2                                419077   1.59    256773  [      0.61]
maps:put/3                                         49302  12.09   1949883  [     39.55]
'Elixir.Access':impl_for/1                        419073  14.65   2363776  [      5.64]
maps:find/2                                       419067  63.10  10178202  [     24.29]

I see that the profile hasn’t really changed that much. There is probably less runtime compilatilation but I still see time spent in maps:find/2. My first question is what is maps:find/2? It comes from Erlang, but when is it used? As a guess, I look at Elixir.Access for Map and find the get function. The get function is what is used to implement the [] operator on Map (or anything that implements the Access protocol). I see that Elixir.Access.get for Map calls :maps.find(key, map) to do the Map lookup. So, we know that we are spending our time looking up values from Maps.

Also, I see 'Elixir.Life':'-list_of_neighbors/3-fun-0-'/6 in the profile which I know is part of count_live_neighbors/3 and I know that this path does a lot of map lookups. I decied to try optmizing this code a little. In hindsight the optimizations I tried didn’t make sense, but I’ll show them here and show how the bmark.cmp process can give a more formal way of making the determination - remember that code performance can often be hard to predict or reason about without hard information.

Looking at list_of_neighbors/3 I wonder how fast the for comprehension is. I could try rewriting the function using a module constant instead of generating the dx, dy values with the comprehension.

I rewrote this:

defp list_of_neighbors(x, y, board) do
  for dx <- [-1, 0, 1], dy <- [-1, 0, 1], {dx, dy} != {0, 0}, do: board[{x + dx, y + dy}]


@deltas [
  {-1, -1}, { 0, -1}, { 1, -1},
  {-1,  0},           { 1,  0},
  {-1,  1}, { 0,  1}, { 1,  1}

defp list_of_neighbors(x, y, board) do
  for dx <- [-1, 0, 1], dy <- [-1, 0, 1], {dx, dy} != {0, 0}, do: board[{x + dx, y + dy}], fn ({dx, dy}) -> board[{x + dx, y + dy}] end)

and then measured the results

consolidate/lifebench.glider.results:  precomputed/lifebench.glider.results:
14887006                               14642711
15028554                               14897523
14762181                               14698632
14905275                               14978539
14577768                               14775842
14883831                               14751767
14795362                               14859778
14897746                               14872981
14763634                               14648105
14904190                               14634486

14840554.7 -> 14776036.4 (-0.44%) with p < 1
t = 1.1845853684535732, 18 degrees of freedom

Sadly, this is not a win. I decided to take this one step further and try to reduce the work in count_live_neighbors/3 by taking the several pipeline steps and combining them into a single fold operation. I started with:

defp count_live_neighbors(x, y, board) do
  list_of_neighbors(x, y, board)
  |> Enum.sum

defp list_of_neighbors(x, y, board) do, fn ({dx, dy}) -> board[{x + dx, y + dy}] end)

and rewrote it as:

defp count_live_neighbors(x, y, board) do
  List.foldl(@deltas, 0, fn ({dx, dy}, acc) -> 
    acc + (board[{x + dx, y + dy}] |> state_as_int)

I measured again:

consolidate/lifebench.glider.results:  foldl/lifebench.glider.results:
14887006                               14742553
15028554                               14879462
14762181                               14712122
14905275                               14925838
14577768                               14772430
14883831                               14604655
14795362                               14682689
14897746                               14799597
14763634                               14634907
14904190                               14979943

14840554.7 -> 14773419.6 (-0.45%) with p < 1
t = 1.220154927852377, 18 degrees of freedom

But still no win. Was it right to push through the first failed optimization this way? I think it was, sometimes it can lead to better ideas or a code structure that lends itself to furhter optmization. But in this case it just didn’t pay off. I discarded these changes.

As I said, in hindsight the optimizations I tried didn’t make sense. This is because I didn’t change the number of calls to maps:find/2 which clearly dominates the profile. Instead, I was only channging the stucture of the code around these calls. But, I find that kind of insight hard to see at the onset.

Concurrent Computation

Elixir is all about concurrency so I had been itching to try out a parallel version. I was pretty confident that a concurrent version would see a benefit from parallel execution on my 4 core system. But, I had wanted to save this optmization until the end. I didn’t envision changing too much in converting to a concurrent version and wanted to make sure I was starting with the best version of the base code.

My version of The Game of Life has a Board module and that module has a map function which I use to apply updates to each cell in the game. Building a concurrent version of the Game of Life was simple matter of changing into a parallel map. Here’s the original version:

def map(board, f) do
  |> Map.keys
  |> (key) -> { key, f.(key, board[key]) } end)
  |> List.foldr(, fn ({key, value}, acc) -> Map.put(acc, key, value) end)

The board itself is stored as a map and I use the existing by creating a List of all keys in my map. Then map over the list and then consolidate the results back into a new Map using List.foldr I wrote up a naive concurrent version stating a process for each invocation of the function f:

def map(board, f) do
  |> Map.keys
  |> pmap(fn (key) -> { key, f.(key, board[key]) } end)
  |> List.foldr(, fn ({key, value}, acc) -> Map.put(acc, key, value) end)

def pmap(list, f) do
  |> (elem) -> Task.async(fn -> f.(elem) end) end)
  |> (task) -> Task.await(task) end)

Here I’ve replaced the use of with my own pmap function that uses Task.async to run each function invocation in a separate process.

consolidate/lifebench.glider.results:  naive-pmap/lifebench.glider.results:
14887006                               26889439
15028554                               27339230
14762181                               27067765
14905275                               27026322
14577768                               26777941
14883831                               27135888
14795362                               26867260
14897746                               27028423
14763634                               27354742
14904190                               26881294

14840554.7 -> 27036830.4 (+82.18%) with p < 0.0005
t = 167.14386999331413, 18 degrees of freedom

This is a huge loss! Process creation in Erlang is supposed to be cheap but based on the results I think that the balance of work between the function f and the process creation in Task.async is off. That f which would be Life.apply_rules/3 does very little work compared to Task.async. While in the absolute Task.async may be cheap it is relatively expensive and the cost outweights the benefit.

But, still a concurrent version should be able to win. I try restructuring a bit and do the pmap in chunks of 8:

  def pmap(list, f) do
    |> Enum.chunk(8, 8, [])
    |> Enum.flat_map(fn (chunk) ->
      |> (elem) -> Task.async(fn -> f.(elem) end) end)
      |> (task) -> Task.await(task) end)
consolidate/lifebench.glider.results:  chunk-pmap/lifebench.glider.results:
14887006                               24274268
15028554                               24563751
14762181                               24492221
14905275                               24516553
14577768                               24335224
14883831                               24158102
14795362                               24357174
14897746                               24213098
14763634                               24466586
14904190                               24289248

14840554.7 -> 24366622.5 (+64.19%) with p < 0.0005
t = 163.96384320448385, 18 degrees of freedom

This looks like it is slightly less of a huge loss than the previous version. Which I think means I still don’t have the balance right. So I increase the chunk size to 128:

consolidate/lifebench.glider.results:  chunk-128-pmap/lifebench.glider.results:
14887006                               6426990
15028554                               6416149
14762181                               6507946
14905275                               6453309
14577768                               6491314
14883831                               6405073
14795362                               6504260
14897746                               6449789
14763634                               6532929
14904190                               6509800

14840554.7 -> 6469755.9 (-56.41%) with p < 0.0005
t = 203.48398714422547, 18 degrees of freedom

And finally we have our win!

Next steps

First of all, there are a few more things I want to clean up in bmark. I’m thining that bmark should handle the protocol consolidation for the user. It doesn’t make sense to have to do this manually, though perhaps this could be controlled by a configuration option. There are also some other larger ideas that I will discuss in a future post.

Next week, I plan to continue with the profiling and optimization process.