Erlang 內存泄漏分析

隨着項目愈來愈依賴Erlang，碰到的問題也隨之增長。前段時間線上系統碰到內存高消耗問題，記錄一下troubleshooting的分析過程。線上系統用的是Erlang R16B02版本。

問題描述

有幾臺線上系統，運行一段時間，內存飆升。系統模型很簡單，有網絡鏈接，pool中找新的process進行處理。top命令觀察，發現內存都被Erlang進程給吃完了，netstat命令查看網絡鏈接數，才區區幾K。問題應該是Erlang內存泄漏了。

分析方法

Erlang系統有個好處，能夠直接進入線上系統，在生產現場分析問題。咱們系統是經過Rebar管理的，能夠用不一樣方法進入線上系統。

本機登陸
能夠直接登陸到線上機器，而後經過如下命令attach到Erlang系統裏面

$ cd /path/to/project
$ rel/xxx/bin/xxx attach
(node@host)>

經過remote shell
獲取Erlang系統的cookie

$ ps -ef |grep beam  %%找到參數 --setcookie

新開一個shell，使用一樣的cookie，不一樣的nodename

$ erl --setcookie cookiename -name test@127.0.0.1

用start remote shell進入系統

Erlang R16B02 (erts-5.10.3) [source] [64-bit] [smp:2:2] [async-threads:10] [hipe] [kernel-poll:false]

Eshell V5.10.3  (abort with ^G)
(test1@127.0.0.1)1> net_adm:ping('node@127.0.0.1').
pong
(test1@127.0.0.1)2> nodes().
['node@127.0.0.1']
(test1@127.0.0.1)3> 
User switch command
 --> h
  c [nn]            - connect to job
  i [nn]            - interrupt job
  k [nn]            - kill job
  j                 - list all jobs
  s [shell]         - start local shell
  r [node [shell]]  - start remote shell
  q                 - quit erlang
  ? | h             - this message
 --> r 'node@127.0.0.1'
 --> j
   1  {shell,start,[init]}
   2* {'node@127.0.0.1',shell,start,[]}
 --> c 2

分析流程

Erlang有不少工具，能夠分析系統信息，好比appmon，webtool。可是系統內存嚴重不足，已經沒有辦法啓動這些工具了，幸虧還有Erlang shell。

Erlang shell自帶了不少有用的命令，能夠用help()方法查看

> help().

Erlang系統內存消耗狀況

top結果顯示，是內存問題，因此第一步能夠先看看Erlang的系統內存消耗狀況

erlang:memory().

memory()能夠看到Erlang emulator分配的內存，有總的內存，atom消耗的內存，process消耗的內存等等。

Erlang process建立數量

線上系統發現主要內存消耗都在process上面，接下來要分析，是process內存泄漏了，仍是process建立數量太多致使。

> erlang:system_info(process_limit).  %%查看系統最多能建立多少process
> erlang:system_info(process_count).  %%當前系統建立了多少process

system_info()返回當前系統的一些信息，好比系統process，port的數量。執行上面命令，大吃一驚，只有2，3k的網絡鏈接，結果Erlang process已經有10多w了。系統process建立了，可是由於代碼或者其它緣由，堆積沒有釋放。

查看單個process的信息

既然是由於process由於某種緣由堆積了，只能從process裏找緣由了

先要獲取堆積process的pid

> i().  %%返回system信息
> i(0,61,886).  %% (0,61,886)是pid

看到有不少process hang在那裏，查看具體pid信息，發現message_queue有幾條消息沒有被處理。下面就用到強大的erlang:process_info()方法，它能夠獲取進程至關豐富的信息。

> erlang:process_info(pid(0,61,886), current_stacktrace).
> rp(erlang:process_info(pid(0,61,886), backtrace)).

查看進程的backtrace時，發現下面的信息

0x00007fbd6f18dbf8 Return addr 0x00007fbff201aa00 (gen_event:rpc/2 + 96)
y(0)     #Ref<0.0.2014.142287>
y(1)     infinity
y(2)     {sync_notify,{log,{lager_msg,[], ..........}}
y(3)     <0.61.886>
y(4)     <0.89.0>
y(5)     []

process在處理Erlang第三方的日誌庫lager時，hang住了。

問題緣由

查看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.

原來lager有個配置項，配置message未處理的數量，若是message堆積數超出，則會用 同步 方式處理！

當前系統打開了debug log，洪水般的log把系統給沖垮了。

老外也碰到相似問題，這個thread給咱們的分析帶來不少幫助，感謝一下。

總結

Erlang提供了豐富的工具，能夠在線進入系統，現場分析問題，這個很是有助於高效、快速的定位問題。同時，強大的Erlang OTP讓系統有更穩定的保證。咱們還會繼續挖掘Erlang，期待有更多的實踐分享。

關於做者

微博@liaolinbo，雲巴首席工程師。曾於Oracle工做。