Lesson 27: Performance Optimization

The metrics from lesson 26 show when the server is busy, not which code is responsible. Lesson 13 predicted that chat_registry would become a queue, because every lookup passes through one process. We’ll measure that claim before fixing it.

Measure First

timer:tc/3 runs a function and returns {Microseconds, Result}. timer:tc/1 does the same for a fun. timer:tc(chat_registry, lookup, [<<"user_42">>]) returned {10,{ok,<0.139.0>}} here, then 6 microseconds on the next try.

A single run says little. The number jumps around with scheduling and garbage collection, and one idle caller is not a load. Run many iterations, and run them from a compiled module. Code typed into the shell is interpreted. A loop of 100,000 lookups written as a shell fun took 162 ms here, and 122 ms in a module.

The benchmark registers fake users, then starts processes that all look up random names at the same time.

Create src/chat_bench.erl:

-module(chat_bench).
-export([populate/1, lookups/2]).

populate(N) ->
    [begin
         Pid = spawn(fun() -> receive stop -> ok end end),
         ok = chat_registry:register_user(name(I), Pid)
     end || I <- lists:seq(1, N)],
    ok.

lookups(Procs, PerProc) ->
    Users = length(chat_registry:list_users()),
    Parent = self(),
    Worker = fun() ->
        receive go -> ok end,
        [{ok, _} = chat_registry:lookup(name(rand:uniform(Users)))
         || _ <- lists:seq(1, PerProc)],
        Parent ! {done, self()}
    end,
    Pids = [spawn_link(Worker) || _ <- lists:seq(1, Procs)],
    {Micros, ok} = timer:tc(fun() ->
        [Pid ! go || Pid <- Pids],
        [receive {done, Pid} -> ok end || Pid <- Pids],
        ok
    end),
    #{millis => Micros div 1000,
      per_second => Procs * PerProc * 1000000 div Micros}.

name(I) ->
    <<"user_", (integer_to_binary(I))/binary>>.

The workers wait for go, so spawning is not measured. Here is the gen_server registry with 10,000 users on an 8-core laptop.

1> chat_bench:populate(10000).
ok
2> chat_bench:lookups(1, 100000).
#{millis => 118,per_second => 843276}
3> chat_bench:lookups(8, 100000).
#{millis => 1176,per_second => 680220}

One caller gets about 840,000 lookups per second. Eight callers on eight cores get fewer. Flat throughput is the signature of a serial bottleneck. Each lookup is a message to the registry and a reply back, and the registry handles one message at a time.

broadcast/1 makes it worse, because it loops over all users inside that same process. eprof traces the processes you name and reports time per function.

4> eprof:start(), eprof:start_profiling([chat_registry]).
profiling
5> chat_registry:broadcast(#{type => system, text => <<"hello">>}).
ok
6> sys:get_state(chat_registry), eprof:stop_profiling().
profiling_stopped
7> eprof:analyze(total).
FUNCTION                              CALLS        %   TIME  [uS / CALLS]
--------                              -----  -------   ----  [----------]
chat_registry:'-send_all/2-fun-0-'/3  10000    83.96  12988  [      1.30]
------------------------------------  -----  -------  -----  [----------]
Total:                                30068  100.00%  15469  [      0.51]

The output is trimmed to the last rows. broadcast/1 is a cast, so the call in prompt 6 waits until the registry has worked through it. The fun that sends to each pid takes 84% of the time. Without the profiler the broadcast still takes 12 ms, and every lookup in the system waits that long.

ETS

An ETS table is an in-memory store for tuples that lives outside any process heap. The process that creates it owns it, and the table is destroyed when its owner exits. One element of each tuple is the key, the first by default. In a set table every key occurs once.

1> T = ets:new(users, [set]).
#Ref<0.1207811973.3318611973.79226>
2> ets:insert(T, {<<"alice">>, online}).
true
3> ets:lookup(T, <<"alice">>).
[{<<"alice">>,online}]
4> ets:lookup(T, <<"bob">>).
[]
5> ets:insert_new(T, {<<"alice">>, away}).
false
6> ets:tab2list(T).
[{<<"alice">>,online}]

ets:lookup/2 returns a list, because other table types allow several tuples per key. ets:insert/2 overwrites an existing key, and ets:delete/2 removes one. ets:insert_new/2 refuses and returns false, which is “check, then insert” as one atomic step.

Three options of ets:new/2 matter for the registry.

• named_table lets any process use the table by name.
• protected is the default access mode. Every process can read, only the owner can write.
• {read_concurrency, true} tunes the table’s locks for many simultaneous readers and few writers.

The New Registry

The gen_server stays. It owns the table, holds the monitors and performs every write, so two people still cannot get the same name. lookup/1, list_users/0 and broadcast/1 no longer send it anything. They read the table in the calling process. The client API is unchanged.

Update src/chat_registry.erl:

-module(chat_registry).
-behaviour(gen_server).

-export([start_link/0, register_user/2, unregister_user/1, lookup/1, list_users/0]).
-export([broadcast/1]).
-export([init/1, handle_call/3, handle_cast/2, handle_info/2]).

-define(TABLE, chat_registry).

%%% Writes go through the server

start_link() ->
    gen_server:start_link({local, ?MODULE}, ?MODULE, [], []).

register_user(Username, Pid) ->
    gen_server:call(?MODULE, {register, Username, Pid}).

unregister_user(Username) ->
    gen_server:call(?MODULE, {unregister, Username}).

%%% Reads run in the calling process

lookup(Username) ->
    case ets:lookup(?TABLE, Username) of
        [{Username, Pid}] -> {ok, Pid};
        [] -> {error, not_found}
    end.

list_users() ->
    lists:sort([Name || {Name, _Pid} <- ets:tab2list(?TABLE)]).

broadcast(Event) ->
    ets:foldl(fun({_Name, Pid}, ok) -> Pid ! {chat_event, Event}, ok end, ok, ?TABLE).

%%% Callbacks. The state maps a monitor reference to a username.

init([]) ->
    ?TABLE = ets:new(?TABLE, [set, named_table, protected, {read_concurrency, true}]),
    {ok, #{}}.

handle_call({register, Username, Pid}, _From, Refs) ->
    case ets:insert_new(?TABLE, {Username, Pid}) of
        true ->
            Ref = monitor(process, Pid),
            {reply, ok, Refs#{Ref => Username}};
        false ->
            {reply, {error, username_taken}, Refs}
    end;
handle_call({unregister, Username}, _From, Refs) ->
    ets:delete(?TABLE, Username),
    case [Ref || Ref := Name <- Refs, Name =:= Username] of
        [Ref] ->
            demonitor(Ref, [flush]),
            {reply, ok, maps:remove(Ref, Refs)};
        [] ->
            {reply, ok, Refs}
    end.

handle_cast(_Msg, Refs) ->
    {noreply, Refs}.

handle_info({'DOWN', Ref, process, _Pid, _Reason}, Refs) ->
    case maps:take(Ref, Refs) of
        {Name, Rest} ->
            ets:delete(?TABLE, Name),
            broadcast(#{type => system, text => <<Name/binary, " disconnected">>}),
            {noreply, Rest};
        error ->
            {noreply, Refs}
    end;
handle_info(_Msg, Refs) ->
    {noreply, Refs}.

The -spec lines are unchanged and omitted. The table holds {Username, Pid} tuples. The state is now keyed by monitor reference, so the common 'DOWN' path is one maps:take/2. The rare manual unregister scans the map with a map comprehension (Key := Value <- Map). ets:foldl/3 visits every tuple without building a list first. The same benchmark again, after populate(10000).

2> chat_bench:lookups(1, 100000).
#{millis => 18,per_second => 5465376}
3> chat_bench:lookups(8, 100000).
#{millis => 44,per_second => 18159119}

A single caller is six times faster because the round trip is gone. Eight callers reach 18 million lookups per second, 26 times the old figure, because the cores no longer wait for each other.

What It Costs

Reads can be stale. A lookup used to queue behind the 'DOWN' message of a dead user. Now it can run before the registry has handled that message and return a dead pid. A loop over lesson 23’s dead_user_is_removed/0 saw the dead user in 134 of 20,000 runs. Sending to a dead pid is harmless, so the server does not care. The test does. Make any call to the registry before the assertion. It queues behind 'DOWN'.

%% In test/chat_registry_tests.erl, dead_user_is_removed/0
    _ = sys:get_state(chat_registry),
    ?assertEqual({error, not_found}, chat_registry:lookup(<<"alice">>)).

With that line rebar3 eunit passes every time. The other two tests pass unchanged.

The table dies with its owner. If the registry crashes, the supervisor restarts it and init/1 creates an empty table. Live connections are missing from it until they log in again. The map version lost its state the same way. Until the restart, ets:lookup/2 raises badarg.

Reads copy. ETS data lives outside the process heaps, so ets:lookup/2 copies the tuple to the caller. For a name and a pid that is cheap. For big tuples read in bulk it is not.

Smaller Savings

iolists. <<Header/binary, Payload/binary>> allocates a new binary and copies the payload. [Header, Payload] is a two-element list that points at both. gen_tcp:send/2 accepts either, which is why chat_ws:encode_frame/1 returns iodata. We measured 100,000 frames in a compiled module. With a 60,000 byte payload, concatenation took 96 ms and the iolist 0.5 ms. Never call iolist_to_binary/1 on the way to a socket. A related saving is to encode a room message once instead of once per member. Measure before you bother. Encoding a short message 10,000 times took 4.2 ms here, spread over all connection processes. Exercise 3 builds it anyway.

Hibernation. Most connections are idle most of the time. A gen_server callback can return {noreply, State, hibernate}. The process then garbage collects, shrinks its heap and sleeps until the next message. Doing that after every message wastes CPU. The hibernate_after start option does it only after a quiet period.

%% In src/chat_connection.erl
start_link(Socket) ->
    gen_server:start_link(?MODULE, Socket, [{hibernate_after, 5000}]).

process_info(Conn, memory) from lesson 26 shows the effect on a connection that logged in and sent 20 messages. Right after the traffic it reports 12,112 bytes. Six seconds later it reports 1,656. That is 10 KB per idle connection, or 1 GB for 100,000 of them. Without the option the process stayed at 13,984 bytes.

Exercises

Exercise 1: Count Without Copying

Add chat_registry:count/0. ets:info(Table, size) returns the number of tuples without reading them.

% chat_bench:populate(500).
% chat_registry:count().  => 500

Exercise 2: Benchmark the Broadcast

Add chat_bench:broadcast/1, which broadcasts N events and returns the total time in milliseconds. Run chat_bench:lookups(8, 100000) from a second process at the same time and compare both registry versions.

% chat_bench:broadcast(100).
% Expected with the ETS registry: lookup throughput barely changes

Exercise 3: Encode Once

In chat_room, encode the frame once with chat_ws:encode_frame({text, json:encode(Event)}) and send {chat_frame, Frame} to the members. Add a handle_info/2 clause to chat_connection that passes the iodata to gen_tcp:send/2. History must still hold the event maps.

%% In src/chat_connection.erl
handle_info({chat_frame, Frame}, State) ->
    % send Frame on the socket
    {noreply, State};

Key Takeaways

• Measure before changing code. Use timer:tc over many iterations in a compiled module, never a single run in the shell
• Flat throughput under more callers means a serial bottleneck
• ETS tables hold tuples outside process heaps, belong to one process and vanish when it exits
• protected plus read_concurrency gives one writer and many parallel readers, which suits a registry
• Keep writes in the owner process so check-then-insert stays serialized. ets:insert_new/2 does it in one step
• Direct reads can be stale for a moment, so every reader must tolerate that
• iolists and hibernate_after save copying and idle memory

Interactive Koans