`
robbin
  • 浏览: 4797526 次
  • 性别: Icon_minigender_1
  • 来自: 上海
博客专栏
377a9ecd-1ea1-34ac-9530-9daa53bb2a7b
robbin谈管理
浏览量：135643
社区版块
存档分类
最新评论

监视Rails进程内存泄漏的技巧

    博客分类：
  • Ruby
RailsRubyLinuxDebianF#
阅读更多
Rails应用比较容易遇到的两类性能问题：一类是Rails执行很慢，CPU消耗过高；另一类是Rails进程内存泄漏。解决这两类问题都需要你首先能够精确定位出现问题的代码，然后才知道如何对症下药。

一、如何监控Rails进程的执行性能

定位消耗CPU高，执行速度缓慢的Rails代码，是相当容易的事情，仅仅需要你对production.log做一点统计分析，抽取出来执行时间最长的请求，问题就昭然若揭了。由于production.log对Rails请求的执行时间做了详细的统计，例如： 

Completed in 0.00693 (144 reqs/sec) | Rendering: 0.00489 (70%) | DB: 0.00000 (0%) | 200 OK [http://www.iteye.com/]
Completed in 0.17238 (5 reqs/sec) | Rendering: 0.10011 (58%) | DB: 0.06244 (36%) | 200 OK [http://www.iteye.com/topic/49441?page=7]
Completed in 0.20508 (4 reqs/sec) | Rendering: 0.19373 (94%) | DB: 0.00645 (3%) | 200 OK [http://www.iteye.com/news/1586]


所以我们只需要写一行shell命令，就搞定了！他把最耗时的前500个请求筛选出来，保存到timing.log里面。 

grep "200 OK" production.log | awk '{print "ALL: " $3 "  View: " $8 " DB: " $12 "  URL: " $17 }' \
| sort -r | head -n 500 > timing.log


排序好的结果例如： 

ALL: 5.51774  View: 5.38277 DB: 0.13338  URL: [http://www.iteye.com/wiki/topic/131966]
ALL: 5.51316  View: 5.31300 DB: 0.19400  URL: [http://www.iteye.com/wiki/topic/145383]
ALL: 5.51311  View: 5.39321 DB: 0.11234  URL: [http://www.iteye.com/wiki/topic/160370]
ALL: 5.51135  View: 5.37604 DB: 0.12652  URL: [http://www.iteye.com/wiki/topic/233365]
ALL: 5.49881  View: 5.35998 DB: 0.10637  URL: [http://www.iteye.com/wiki/topic/265217]


哪些请求执行的慢，一目了然。 当然除此之外，我们还可以实时监控，在top监视窗口显示Rails当前正在执行的请求URL。

二、如何监控Rails进程的内存泄漏

监控CPU是很容易的事情，但要监控Rails进程的内存泄漏，却非常困难，原因在于production.log里面并没有记录进程的内存变化状况，甚至你找不到任何ruby API可以用来直接查询到进程使用的物理内存。实际上，要获取一个进程的物理内存是一个平台相关的操作，每个操作系统都会自己特定的API，并不通用，即使用C语言来编码，也不是一件容易的事情。

不过对于Linux操作系统来说，我们有一个捷径可以获取进程的内存状况。Linux的/proc文件系统是内核的映象，/proc/进程pid/status 文件记录了这个进程的状态信息，例如： 
Name:   dispatch.fcgi
State:  S (sleeping)
SleepAVG:       135%
Tgid:   26645
Pid:    26645
PPid:   1
TracerPid:      0
Uid:    1002    1002    1002    1002
Gid:    100     100     100     100
FDSize: 64
Groups: 14 16 17 33 100 
VmSize:   245680 kB
VmLck:         0 kB
VmRSS:    209104 kB
VmData:   205116 kB
VmStk:       824 kB
VmExe:       764 kB
VmLib:      4220 kB
Threads:        1
SigPnd: 0000000000000000
ShdPnd: 0000000000000000
SigBlk: 0000000000000000
SigIgn: 0000000000001000
SigCgt: 0000000002006e47
CapInh: 0000000000000000
CapPrm: 0000000000000000
CapEff: 0000000000000000


注意第14行VmRSS，记录了该进程使用的常驻物理内存(Residence)，这个就是该进程实际占用的物理内存了。因此只要我们读取该文件第14行，就可以得到内存信息。

所以我们的任务变成了：在Rails处理请求之前记录内存，等Rails处理完请求之后，再记录内存，计算内存的变化状况，写入到production.log里面去。完成这个工作，只需要我们在Rails应用的app/controllers/application.rb里面添加几行代码： 

  around_filter :record_memory
  def record_memory
    process_status = File.open("/proc/#{Process.pid}/status")
    13.times { process_status.gets }
    rss_before_action = process_status.gets.split[1].to_i
    process_status.close
    yield
    process_status = File.open("/proc/#{Process.pid}/status")
    13.times { process_status.gets }
    rss_after_action = process_status.gets.split[1].to_i
    process_status.close
    logger.info("CONSUME MEMORY: #{rss_after_action - rss_before_action} \
KB\tNow: #{rss_after_action} KB\t#{request.url}")
  end


我们定义了一个AroundFilter，记录一下处理请求前后的内存变化。有了这个信息，我们接下来的事情就简单了，只需要从production.log里面抽取出来这行log，进行统计分析就可以了，这也仅仅只需要一行shell就搞定了： 

grep "CONSUME MEMORY" production.log | grep -v "CONSUME MEMORY: 0" |  \
 grep -v "CONSUME MEMORY: -" |  awk '{print $3 "\t" $6 "\t" $8 }' | sort -r -n | \
 head -n 500 > memory.log


抽取内存记录，去掉内存没有增加，去掉内存减少(发生了GC)的请求，然后对那些处理请求之后内存上升的记录进行排序，取出来前500条记录保存到memory.log里面，结果如下所示： 

增加数 内存占用    请求URL
-----------------------------------------------
9528  175264  http://www.iteye.com/topic/304594
9524  129512  http://knityster.iteye.com/blog/172990
9496  147544  http://www.iteye.com/forums/
9492  197800  http://duyiwuer.iteye.com/rss
9452  146668  http://www.iteye.com/forums
9452  133844  http://wildlife.iteye.com/blog/47693
9440  157824  http://www.iteye.com/rss/blogs
9424  204664  http://www.iteye.com/wiki/topic/251964
9384  142200  http://towerhe.iteye.com/blog/93704
9380  165372  http://www.iteye.com/wiki/topic/77434
9368  207460  http://superleo.iteye.com/rss


第一列是访问了一个请求以后，Rails进程的内存上升了9MB多，第二列是处理完请求，Rails进程当前实际占了170多MB内存，第三列是处理了什么请求。

根据这个统计结果，你可以很容易找出那些造成你Rails进程内存泄漏的罪魁祸首，哪些请求一访问你的Rails进程内存就飚升已经是一目了然的事情了，这是不是很简单？事实上通过这个办法，JavaEye仅用了半个多小时，就解决了曾经困扰了半年多的内存泄漏问题，办法虽土，却很有效！
分享到：
| ruby MBARI大补丁性能评测报告
评论
14 楼 鹤惊昆仑 2009-11-04  
2005年出版的《Python Cookbook, 2nd Edition》Recipe 8.2. Measuring Memory Usage on Linux 也是这个思路。
13 楼 QuakeWang 2009-10-10  
今天发现一个更简单的获取内存使用的方法： 
memory_usage = `ps -o rss= -p #{$$}`.to_i

这里的$$是ruby进程的pid
12 楼 wakuwaku 2009-01-12  
好像GOD就是干这个事情得

11 楼 jiachengxi38 2009-01-08  
是的，那日也来尝试一下，我的centos也是第16行，自己也小写了一个循环的shell，定期检测一下。
10 楼 QuakeWang 2009-01-07  
magicgod 写道
在debian系下的status，第16行才是RSS

所以要改为这样： 
15.times { process_status.gets }


可能其他linux也有不同，事先人工查看一下。


可以用正则匹配VmRSS这一行 , Robbin这个16.times也太偷懒了，呵呵
9 楼 magicgod 2009-01-06  
另外如果自己改了production.log的格式，那么要注意数好列数，以空格为分隔，不要完全照抄这个shell，里面的列数是写死的，要照实际列数来改一下。

缺省情况下可以照抄。

附上我写的几个简单的shell, 只是略微包装了一下。另外我的日志里的列数是不同的，不要照抄。
没有写死日志名，运行的时候要跟一个参数<log filename>。

memory.sh: 
if [ -z $1 ] ;then
  echo "usage: memory.sh <log filename>"
else
  grep "CONSUME MEMORY" $1 | grep -v "CONSUME MEMORY: 0" |  grep -v "CONSUME MEMORY: -" |  awk '{print $10 "\t" $13 "\t" $15 }' | sort -r -n |  head -n 500 > memory.log   

  head memory.log
fi


timing.sh: 
if [ -z $1 ] ;then
  echo "usage: timing.sh <log filename>"
else

  grep "200 OK" $1 | awk '{print "ALL: " $10 "  View: " $15 " DB: " $19 "  URL: " $24 }'  | sort -r | head -n 500 > timing.log  

  head timing.log
fi

8 楼 magicgod 2009-01-06  
在debian系下的status，第16行才是RSS

所以要改为这样： 
15.times { process_status.gets }


可能其他linux也有不同，事先人工查看一下。
7 楼 robbin 2009-01-05  
frozentree 写道
一个CAP任务，做类似的事情。好处是可以在多个Server上跑。

task :fdr, :roles=>:app do
    # ignore lines like CACHE (0.000000) - vermeer
    run <<-CMD
      cd #{deploy_to}/current;
      echo -----------------------------------------------------;
      echo TOP TWENTY UUID WITH REQUEST;
      echo -----------------------------------------------------;
      cat log/production.log | grep UUID | sed '/CACHE (0.000000)/d' | sed 's/.[0-9]* [a-z]* .*/\1/' | awk -F ' UID:.* user_id:' '{print $1 $2}' > tmp.uuid;
      uniq -w 42 -dc tmp.uuid dangers.uuid;
      sort -n -r dangers.uuid | head -20;
      rm -f tmp.uuid;
      rm -f dangers.uuid;
      echo -----------------------------------------------------;
      echo TOP TWENTY COMPLETED LONG TIMES REQUEST;
      echo -----------------------------------------------------;
      cat log/production.log | grep 'Completed in ' | awk -F 'Completed in ' '{print $2}' | cut -d ' ' -f1 > tmp.times;
      sort -n -r tmp.times | head -20 > dangers.times;
      while read line;
      do
        cat log/production.log | grep \"Completed in $line\" | awk -F '(' '{print $1}' | sed 's/ UID:.* user_id://g';
      done < dangers.times;
      rm -f tmp.times;
      rm -f dangers.times;
      cd #{deploy_to}/current;
      echo -----------------------------------------------------;
      echo COUNT OF LINE WITHOUT UUID;
      echo -----------------------------------------------------;
      cat log/production.log | grep "UUID: UID: user_id: " > uuid.times;
      echo "Count:"`wc -l uuid.times | cut -d ' ' -f1`;
      rm -f uuid.times;
    CMD
  end


你这个根本就监控不了内存。 要在多个Server上面跑，用Shell照应可以，而且比你这个脚本还要简单的多，还是一行shell搞定，用不着这么四五十行代码。
6 楼 seemoon 2009-01-05  
轻巧地解决，很草根，很强
5 楼 frozentree 2009-01-05  
一个CAP任务，做类似的事情。好处是可以在多个Server上跑。

task :fdr, :roles=>:app do
    # ignore lines like CACHE (0.000000) - vermeer
    run <<-CMD
      cd #{deploy_to}/current;
      echo -----------------------------------------------------;
      echo TOP TWENTY UUID WITH REQUEST;
      echo -----------------------------------------------------;
      cat log/production.log | grep UUID | sed '/CACHE (0.000000)/d' | sed 's/.[0-9]* [a-z]* .*/\1/' | awk -F ' UID:.* user_id:' '{print $1 $2}' > tmp.uuid;
      uniq -w 42 -dc tmp.uuid dangers.uuid;
      sort -n -r dangers.uuid | head -20;
      rm -f tmp.uuid;
      rm -f dangers.uuid;
      echo -----------------------------------------------------;
      echo TOP TWENTY COMPLETED LONG TIMES REQUEST;
      echo -----------------------------------------------------;
      cat log/production.log | grep 'Completed in ' | awk -F 'Completed in ' '{print $2}' | cut -d ' ' -f1 > tmp.times;
      sort -n -r tmp.times | head -20 > dangers.times;
      while read line;
      do
        cat log/production.log | grep \"Completed in $line\" | awk -F '(' '{print $1}' | sed 's/ UID:.* user_id://g';
      done < dangers.times;
      rm -f tmp.times;
      rm -f dangers.times;
      cd #{deploy_to}/current;
      echo -----------------------------------------------------;
      echo COUNT OF LINE WITHOUT UUID;
      echo -----------------------------------------------------;
      cat log/production.log | grep "UUID: UID: user_id: " > uuid.times;
      echo "Count:"`wc -l uuid.times | cut -d ' ' -f1`;
      rm -f uuid.times;
    CMD
  end
4 楼 xhanxhanxhan 2009-01-04  
学习了。LINUX 监控内存确实方便。
3 楼 rain2005 2008-12-31  
robbin对Linux好精通啊，尤其是shell.
2 楼 holin 2008-12-31  
赞。
也要尝试一下
1 楼 yb31 2008-12-30  
  好实用.收藏先
如果最后的javaeye内存泄漏的bug点能够详细一点或者另开一篇详解就好了.
发表评论

您还没有登录,请您登录后再发表评论

相关推荐

Magicbox
Global site tag (gtag.js) - Google Analytics