Erlang tool -- lager overload protection

log 这个事, 说大不大说小又不小. 大点的, 可以用scribe flume 这样的系统去做, 小点的, 也就打印一个调试信息而已. 在Erlang 中, log 这事情确实比较伤, error_logger 是个单点, io:format 容易导致节点崩溃. 在开源社区, lager 算是使用比较广泛的一个, 然而, 同样不能完全避免单点的问题. 因为在lager 中, lager_event 作为 core, 是单个进程存在的.

dispatch_log(Severity, Metadata, Format, Args, Size) when is_atom(Severity)->
    SeverityAsInt=lager_util:level_to_num(Severity),
    case {whereis(lager_event), lager_config:get(loglevel, {?LOG_NONE, []})} of
        {undefined, _} ->
            {error, lager_not_running};
        {Pid, {Level, Traces}} when (Level band SeverityAsInt) /= 0 orelse Traces /= [] ->
            do_log(Severity, Metadata, Format, Args, Size, SeverityAsInt, Level, Traces, Pid);
        _ ->
            ok
    end.

也就是在lager 中, 所有的log 都需要经过 lager_event 进程.

但是在lager 中, 有过载保护机制.

Prior to lager 2.0, the gen_event at the core of lager operated purely in synchronous mode. Asynchronous mode is faster, but has no protection against message queue overload. In lager 2.0, the gen_event takes a hybrid approach. it polls its own mailbox size and toggles the messaging between synchronous and asynchronous depending on mailbox size.

{async_threshold, 20},
{async_threshold_window, 5}

This will use async messaging until the mailbox exceeds 20 messages, at which point synchronous messaging will be used, and switch back to asynchronous, when size reduces to 20 - 5 = 15.

If you wish to disable this behaviour, simply set it to undefined. It defaults to a low number to prevent the mailbox growing rapidly beyond the limit and causing problems. In general, lager should process messages as fast as they come in, so getting 20 behind should be relatively exceptional anyway.

If you want to limit the number of messages per second allowed from error_logger, which is a good idea if you want to weather a flood of messages when lots of related processes crash, you can set a limit:

{error_logger_hwm, 50}

It is probably best to keep this number small.

简单点说就是, 相比较同步模式, 异步模式很快, 但是容易导致lager_event 单进程 message_queue 过大. 再且, 若设计使用不当, 导致lager_event 进程 large_heap 使整个VM崩溃也是分分钟的事.

现在, lager 采用的是hybrid 的方式, 也就是当lager_event 的message_queue_len 小于某个值时, 采用异步模式; 若message_queue_len 大于某个值, 就是用同步的方式. 很好理解, 继续瞧瞧内部的怎么实现的:

1, lager_backend_throttle 的启动

lager_backend_throttle 进程在lager_app 模块的start/2 启动, 也就是整个lager application 启动的时候.

        {ok, Threshold} when is_integer(Threshold), Threshold >= 0 ->
            DefWindow = erlang:trunc(Threshold * 0.2), % maybe 0?
            ThresholdWindow =
                case application:get_env(lager, async_threshold_window) of
                    undefined ->
                        DefWindow;
                    {ok, Window} when is_integer(Window), Window < Threshold, Window >= 0 ->
                        Window;
                    {ok, BadWindow} ->
                        error_logger:error_msg(
                          "Invalid value for 'async_threshold_window': ~p~n", [BadWindow]),
                        throw({error, bad_config})
                end,
            _ = supervisor:start_child(lager_handler_watcher_sup,
                                       [lager_event, lager_backend_throttle, [Threshold, ThresholdWindow]]),
            ok;

简单易懂的代码,就不需要过多的解释了.

2, lager_backend_throttle 的作用

lager_backend_throttle 是 lager_event event server 中的一个handler , 会处理 message-tag 为log 的所有event, 但仅仅是全量接受而已, 不做实际的log 处理.

handle_event({log, _Message},State) ->
    {message_queue_len, Len} = erlang:process_info(self(), message_queue_len),
    case {Len > State#state.hwm, Len < State#state.window_min, State#state.async} of
        {true, _, true} ->
            %% need to flip to sync mode
            lager_config:set(async, false),
            {ok, State#state{async=false}};
        {_, true, false} ->
            %% need to flip to async mode
            lager_config:set(async, true),
            {ok, State#state{async=true}};
        _ ->
            %% nothing needs to change
            {ok, State}
    end;

在接收到 message-tag 为 log 的 event 后, 通过process_info/2 函数获取当前的message_queue_len, 然后切换 async 模式.

3, async 模式的影响

async sync 模式会在message_queue_len 增大/降低过程中切换, 最终会对log 的notify 方式产生不同的影响.

do_log(Severity, Metadata, Format, Args, Size, SeverityAsInt, LevelThreshold, TraceFilters, Pid) when is_atom(Severity) ->
    Destinations = case TraceFilters of
        [] ->
            [];
        _ ->
            lager_util:check_traces(Metadata,SeverityAsInt,TraceFilters,[])
    end,
    case (LevelThreshold band SeverityAsInt) /= 0 orelse Destinations /= [] of
        true ->
            Msg = case Args of
                A when is_list(A) ->
                    safe_format_chop(Format,Args,Size);
                _ ->
                    Format
            end,
            LagerMsg = lager_msg:new(Msg,
                Severity, Metadata, Destinations),
            case lager_config:get(async, false) of
                true ->
                    gen_event:notify(Pid, {log, LagerMsg});
                false ->
                    gen_event:sync_notify(Pid, {log, LagerMsg})
            end;
        false ->
            ok
    end.

在async 为 true 的情况下, 使用 gen_event:notify(异步方式) 将log 交给lager_event 进程, async 为false 的情况下, 则使用gen_event:sync_notify(同步方式)将 log 交给 lager_event 进程.

notify/sync_notify

1, notify

notify 是用户进程将Event 组装成 message-tag 为 notify 的消息, 通过erlang:send/2 方式发给 event 进程(在lager 中也就是lager_event), 然后在event 进程中依次执行 handlers 中的handle_event callback 函数. 

server_update(Handler1, Func, Event, SName) ->
    Mod1 = Handler1#handler.module,
    State = Handler1#handler.state,
    case catch Mod1:Func(Event, State) of
        {ok, State1} -> 
            {ok, Handler1#handler{state = State1}};
        {ok, State1, hibernate} -> 
            {hibernate, Handler1#handler{state = State1}};
        {swap_handler, Args1, State1, Handler2, Args2} ->
            do_swap(Mod1, Handler1, Args1, State1, Handler2, Args2, SName);
        remove_handler ->
            do_terminate(Mod1, Handler1, remove_handler, State,
                 remove, SName, normal),
            no;
        Other ->
            do_terminate(Mod1, Handler1, {error, Other}, State,
                 Event, SName, crash),
            no
    end.

2, sync_notify

sync_notify 是用户进程通过gen:call/4 函数调用event 进程, 消息的message-tag 为sync_notify. event 进程同样是依次执行handlers 中的handle_event callback 函数, 不同的是, 还会向用户进程reply 消息(ok).

highwatermark

在lager 中, error_logger_lager_h 作为 error_logger 的一个 handler, 主要用来限制每秒 from error_logger 的 message 数量.

同样是在lager application 启动的时候, 在start/2 中调用启动. 

在每次接收到event 时, 就会执行check_hwm/1 函数:

check_hwm(State = #state{hwm = Hwm, lasttime = Last, dropped = Drop}) ->
    %% are we still in the same second?
    {M, S, _} = Now = os:timestamp(),
    case Last of
        {M, S, _} ->
            %% still in same second, but have exceeded the high water mark
            NewDrops = discard_messages(Now, 0),
            {false, State#state{dropped=Drop+NewDrops}};
        _ ->
            %% different second, reset all counters and allow it
            case Drop > 0 of
                true ->
                    ?LOGFMT(warning, self(), "lager_error_logger_h dropped ~p messages in the last second that exceeded the limit of ~p messages/sec",
                        [Drop, Hwm]);
                false ->
                    ok
            end,
            {true, State#state{dropped = 0, mps=1, lasttime = Now}}
    end.

总结:

1, sync 模式速度慢, async 速度快, 但是不利于稳定系统的负载;

2, log 这事说大不大, 说小真不小; 本地的log 也就是用来调试和debug 来用, 正经的还是应该使用外部的日志系统;

3, 认真了解application 的每一个参数, 对于参数的设定才更有把握.