织梦CMS - 轻松建站从此开始!

罗索实验室

当前位置: 主页 > 基础技术 > Linux开发专题 >

内存不足引起的SIGKILL:一个缓冲区不断增长问题的定位与解决

落鹤生 发布于 2013-11-05 18:14 点击:次 
新版本的录制程序终于快完工了,在添加了一个新特性“报警录制”后,就开始测试了。一开始就不顺利:程序正常运行一段时间后就会崩溃,由于程序添加了守护进程,在崩溃后会自动重启。
TAG:

新版本的录制程序终于快完工了,在添加了一个新特性“报警录制”后,就开始测试了。

一开始就不顺利:程序正常运行一段时间后就会崩溃,由于程序添加了守护进程,在崩溃后会自动重启。

因此测试得到的结果就是:程序运行一段时间后就自动重启,并不断持续;有时几个小时重启一次,有时甚至每分钟都重启。

废话少说,开始定位问题:

1.去掉自动重启功能,在gdb下运行,20多分钟后就崩溃了:

  1. 2011-10-26 17:50:22,565: INFO  : recved alarm:[10.0.60.2-1-3905]
  2. ,type:12, startTime:1319622622, recvTime:1319622622 
  3. 2011-10-26 17:50:22,628: INFO  : SetAlmStatus CHAN[1] = TRUE 
  4. 2011-10-26 17:50:22,628: INFO  : recved alarm:[10.0.60.2-1-3905]
  5. ,type:12, startTime:1319622622, recvTime:1319622622 
  6. 2011-10-26 17:50:22,962: NOTICE  : Open 
  7. file:'/figure/data/AlarmRecord/StreamTS/1-码流_魅力音 乐主路/2011-10-26/20111026175022.ts' 
  8. [Thread 0xa7db70 (LWP 6645) exited] 
  9. [Thread 0xa3cb70 (LWP 6644) exited] 
  10. [Thread 0x5cdfb70 (LWP 6643) exited] 
  11. [Thread 0x45fdb70 (LWP 6642) exited] 
  12. [Thread 0x3bfcb70 (LWP 6641) exited] 
  13. [Thread 0x240fb70 (LWP 6640) exited] 
  14. [Thread 0x52deb70 (LWP 6638) exited] 
  15. [Thread 0x1a0eb70 (LWP 6637) exited] 
  16. [Thread 0x67b7b70 (LWP 6636) exited] 
  17. [Thread 0x31fbb70 (LWP 6635) exited] 
  18. [Thread 0x956b70 (LWP 6634) exited] 
  19. [Thread 0x935b70 (LWP 6633) exited] 
  20. [Thread 0x8f4b70 (LWP 6632) exited] 
  21.   
  22. Program terminated with signal SIGKILL, Killed. 
  23. The program no longer exists. 

显示程序是收到SIGKILL退出的,bt查看调用堆栈,也是空的。

 

2.查看APUE,说SIGKILL信号是不可被捕捉的。网上资料说“In fact, the process isn't even made aware of the SIGKILL signal since the signal goes straight to the kernel init. At that point, init will stop the process. The process never gets the opportunity to catch the signal and act on it”,看样子是系统向程序发送了无法被捕捉的信号SIGKILL,然后程序就退出了。因此怀疑是程序占用的系统资源过多,导致程序被OS给干掉了。

 

3.查系统日志
既然怀疑,就要去找证据。在/var/log/message中发现如下记录:

  1. Oct 26 17:17:30 localhost kernel: Record invoked oom-killer:
  2.  gfp_mask=0x280da, order=0, oomkilladj=0 
  3. Oct 26 17:17:31 localhost kernel: Record cpuset=/ mems_allowed=0 
  4. Oct 26 17:17:31 localhost kernel: Pid: 6350, comm: Record Not tainted
  5.  2.6.31.5-127.fc12.i686.PAE #1 
  6. Oct 26 17:17:31 localhost kernel: Call Trace: 
  7. Oct 26 17:17:31 localhost kernel: [<c049d891>] oom_kill_process+0x6e/0x1f2 
  8. Oct 26 17:17:32 localhost kernel: [<c049dd4f>] ? select_bad_process+0x87/0xce 
  9. Oct 26 17:17:32 localhost kernel: [<c049de09>] __out_of_memory+0x73/0x82 
  10. Oct 26 17:17:32 localhost kernel: [<c049de7b>] out_of_memory+0x63/0x88 
  11. Oct 26 17:17:32 localhost kernel: [<c04a00aa>] __alloc_pages_nodemask+0x382/0x447 
  12. Oct 26 17:17:32 localhost kernel: [<c04af062>] alloc_pages_node.clone.0+0x16/0x18 
  13. Oct 26 17:17:32 localhost kernel: [<c04afd63>] handle_mm_fault+0x1d7/0x8f2 
  14. Oct 26 17:17:32 localhost kernel: [<c04379e3>] ? finish_task_switch+0x53/0xbf 
  15. Oct 26 17:17:32 localhost kernel: [<c077a829>] do_page_fault+0x282/0x298 
  16. Oct 26 17:17:32 localhost kernel: [<c077a5a7>] ? do_page_fault+0x0/0x298 
  17. Oct 26 17:17:32 localhost kernel: [<c0778d3b>] error_code+0x73/0x78 
  18. Oct 26 17:17:32 localhost kernel: Mem-Info: 
  19. Oct 26 17:17:32 localhost kernel: DMA per-cpu: 
  20. Oct 26 17:17:32 localhost kernel: CPU    0: hi:    0, btch:   1 usd:   0 
  21. Oct 26 17:17:32 localhost kernel: CPU    1: hi:    0, btch:   1 usd:   0 
  22. Oct 26 17:17:32 localhost kernel: Normal per-cpu: 
  23. Oct 26 17:17:32 localhost kernel: CPU    0: hi:  186, btch:  31 usd: 176 
  24. Oct 26 17:17:32 localhost kernel: CPU    1: hi:  186, btch:  31 usd: 184 
  25. Oct 26 17:17:32 localhost kernel: Active_anon:96761
  26.  active_file:752 inactive_anon:96834 
  27. Oct 26 17:17:32 localhost kernel: inactive_file:1384 unevictable:0
  28.  dirty:25 writeback:695 unstable:0 
  29. Oct 26 17:17:32 localhost kernel: free:1920
  30.  slab:5066 mapped:791 pagetables:2649 bounce:0 
  31. Oct 26 17:17:32 localhost kernel: DMA free:3328kB min:68kB low:84kB
  32.  high:100kB active_anon:2296kB inactive_anon:2420kB
  33.  active_file:204kB inactive_file:724kB unevictable:0kB 
  34.   
  35. present:15804kB pages_scanned:0 all_unreclaimable? no 
  36. Oct 26 17:17:32 localhost kernel: lowmem_reserve[]: 0 809 809 809 
  37. Oct 26 17:17:32 localhost kernel: Normal free:4352kB min:3604kB
  38.  low:4504kB high:5404kB active_anon:384748kB inactive_anon:384916kB
  39.  active_file:2804kB inactive_file:4812kB 
  40.   
  41. unevictable:0kB present:828992kB pages_scanned:2496 all_unreclaimable? no 
  42. Oct 26 17:17:32 localhost kernel: lowmem_reserve[]: 0 0 0 0 
  43. Oct 26 17:17:32 localhost kernel: DMA: 14*4kB 15*8kB 11*16kB 7*32kB
  44.  7*64kB 2*128kB 0*256kB 0*512kB 0*1024kB 1*2048kB 0*4096kB = 3328kB 
  45. Oct 26 17:17:32 localhost kernel: Normal: 598*4kB 11*8kB 1*16kB
  46.  3*32kB 3*64kB 2*128kB 1*256kB 0*512kB 1*1024kB 0*2048kB 0*4096kB = 4320kB 
  47. Oct 26 17:17:32 localhost kernel: 2902 total pagecache pages 
  48. Oct 26 17:17:32 localhost kernel: 639 pages in swap cache 
  49. Oct 26 17:17:32 localhost kernel: Swap cache stats: add 860507,
  50.  delete 859868, find 46506/63512 
  51. Oct 26 17:17:32 localhost kernel: Free swap  = 0kB 
  52. Oct 26 17:17:32 localhost kernel: Total swap = 1023992kB 
  53. Oct 26 17:17:32 localhost kernel: 212976 pages RAM 
  54. Oct 26 17:17:32 localhost kernel: 0 pages HighMem 
  55. Oct 26 17:17:32 localhost kernel: 4796 pages reserved 
  56. Oct 26 17:17:32 localhost kernel: 13599 pages shared 
  57. Oct 26 17:17:32 localhost kernel: 203455 pages non-shared 
  58. Oct 26 17:17:32 localhost kernel: Out of memory: kill
  59.  process 6338 (gdb) score 191002 or a child 
  60. Oct 26 17:17:32 localhost kernel: Killed process 6340 (Record) 

看到最后两行:

  1. kernel: Out of memory: kill process 6338 (gdb) score 191002 or a child 
  2. kernel: Killed process 6340 (Record) 

很明显:是系统内存不够,导致程序被kernel杀掉了。

具体内存使用情况,可以看到:
Normal: 598*4kB 11*8kB 1*16kB 3*32kB 3*64kB 2*128kB 1*256kB 0*512kB 1*1024kB 0*2048kB 0*4096kB = 4320kB,可用内存只有4M,
Free swap  = 0kB
Total swap = 1023992kB,交换分区页用光了
确实是没有内存可用了。

多说一句:“Record invoked oom-killer”,这里的oom-killer是“是一层保护机制,用于避免 Linux 在内存不足的时候不至于出太严重的问题,把无关紧要的进程杀掉,有些壮士断腕的意思。”更详细的参见“http://www.dbanotes.net /database/linux_outofmemory_oom_killer.html”。

 

4.问题确定了,就去查原因。

(1)首先,重现问题。

启动程序,利用系统监视器查看系统内存的使用情况:

眼睁睁的看着程序使用的内存不断增长,内存耗尽使用交换分区,最后交换分区也用光,程序直接被系统kill掉了。

 

 (2)查代码的过程不说,最后定位到问题在下面的代码:

  1. //报警录制输入 
  2. int CInputTS::AlarmInput() 
  3.     int nRet = InitTsSocket(); 
  4.     if( (nRet < 0) || (m_pPreloadBuff == NULL) || (m_pBuff == NULL)) 
  5.     { 
  6.         LOG(LOG_TYPE_ERROR, "Channel:[%d-%s]. AlarmInput().nRet = %d
  7. , m_pPreloadBuff = 0X%X, m_pBuff = 0X%X. exit", m_pChannel->m_nChannelID
  8. , m_pChannel->m_strName.c_str(), nRet, m_pPreloadBuff, m_pBuff); 
  9.         return -1;        
  10.     } 
  11.       
  12.     int         recvTime = time(NULL); 
  13.     char        TsData[TS_DATA_LEN] = {0}; 
  14.     bool        bStarted = false
  15.       
  16.     while(!m_nEndFlag) 
  17.     { 
  18.         recvTime = time(NULL); 
  19.         nRet = recvfrom(TsSock, TsData, TS_DATA_LEN, 0, NULL, NULL); 
  20.         if(nRet > 0)//收到数据 
  21.         { 
  22.             //把收到的数据压入预录缓冲区 
  23.             CPoolNode* node = m_pPreloadBuff->allocNode(); 
  24.             if(node != NULL) 
  25.             { 
  26.                 node->m_nDataLen = nRet; 
  27.                 node->ntime = recvTime; 
  28.                 memcpy(node->m_pData, TsData, node->m_nDataLen); 
  29.                 m_pPreloadBuff->push(node); 
  30.             } 
  31.             else 
  32.             { 
  33. LOG(LOG_TYPE_ERROR, "CHAN[%d-%s], m_pPreloadBuff->allocNode() failed."
  34. , m_pChannel->m_nChannelID, m_pChannel->m_strName.c_str()); 
  35.             } 
  36.   
  37.             //检查当前报警状态 
  38.             if(bStarted)//正在进行报警录制 
  39.             { 
  40.                 bStarted = m_pRecordModule->DetermineEndOutput(0, recvTime); 
  41.             } 
  42.             else 
  43.             { 
  44.                 bStarted = m_pRecordModule->DetermineStartOutput(recvTime); 
  45.                 if(!bStarted)//不需要进行报警录制 
  46.                 { 
  47.                     continue
  48.                 } 
  49.                   
  50.                 DumpPreloadBuff(); 
  51.             } 
  52.               
  53. //进行报警录制 
  54. //报警开始之后的数据压入m_pBuff(在报警持续时间内,数据同时压入m_pPreloadBuff和m_pBuff中) 
  55.             CPoolNode* buffnode = m_pBuff->allocNode(); 
  56.             if(buffnode == NULL) 
  57.             { 
  58.                 LOG_PERIOD(LOG_TYPE_ERROR
  59. "Channel:[%d-%s], AllocNode failed. Lost Data:%d bytes"
  60. m_pChannel->m_nChannelID, m_pChannel->m_strName.c_str(), nRet); 
  61.   
  62.                 usleep(50); 
  63.                 continue
  64.             } 
  65.             buffnode->m_nDataLen = nRet; 
  66.             buffnode->ntime = recvTime; 
  67.             memcpy(buffnode->m_pData, TsData, buffnode->m_nDataLen); 
  68.             m_pBuff->push(buffnode); 
  69.               
  70.             //检查预录缓冲区 
  71.             CheckPreloadBuff(recvTime); 
  72.         } 
  73.         else 
  74.         { 
  75.             LOG_PERIOD(LOG_TYPE_ERROR
  76. ,"No Input Data! Channel:[%d-%s], nRecvSize = %d, %s\n"
  77. m_pChannel->m_nChannelID, m_pChannel->m_strName.c_str(), nRet, strerror(errno)); 
  78.         } 
  79.     } 
  80.       
  81.     close(TsSock); 
  82.     return 0; 

d

 

  1. void CInputTS::CheckPreloadBuff(time_t ltime) 
  2.     if((m_pPreloadBuff == NULL) || (m_pBuff == NULL) || (m_pRecordModule == NULL)) 
  3.     { 
  4.         return
  5.     } 
  6.  
  7.     if(!m_pPreloadBuff->empty()) 
  8.     { 
  9.         CPoolNode* node = m_pPreloadBuff->front(); 
  10.         if((int)(ltime - node->ntime) >= m_nAlarmRecordTimeBefore) //超过预录时间 
  11.         { 
  12.             CPoolNode* pNode = m_pPreloadBuff->pop(); 
  13.             m_pPreloadBuff->freeNode(pNode); 
  14.         } 
  15.     } 

先解释逻辑:

(1)AlarmInput()从socket不断接收数据,首先压入预录缓冲区m_pPreloadBuff 中,这个缓冲区m_pPreloadBuff其实就是一个队列;

(2)AlarmInput()每接收到一个数据包后调用CheckPreloadBuff()检查预录缓冲区m_pPreloadBuff 队头的数据,如果超时就丢掉;

(需求说明:本段代码要求预录缓冲区中只保留指定时长的数据,超时数据就会被丢掉,这样预录缓冲区就会维持在一个稳定的长度)。

 

但在测试时发现这段代码并没有按照我们预想的方式工作,预录缓冲区m_pPreloadBuff的队列长度不断增长,最后将系统内存耗尽了

罪魁祸首在这里!

分析逻辑:每接收到一个数据包后,将其push到预录缓冲区m_pPreloadBuff 的队列中,然后调用CheckPreloadBuff()检查队头的数据,如果超时就丢掉。

正常情况下,队列中push一个数据,接着就pop一个是不会有问题的;但是在这段逻辑中:

  1. if(!bStarted)//不需要进行报警录制 
  2.   continue

程序push了数据,就直接contine返回,没有执行CheckPreloadBuff(),导致m_pPreloadBuff 中积累多个超时数据;而当下次再调用CheckPreloadBuff()时还是只检查队头的数据。这样的话,我们很可能push了10个数据,确只检查了3个队头数据,因此预录缓冲区m_pPreloadBuff就会不断增长。

 

问题定位就好解决了:每次执行CheckPreloadBuff()时不只检查队头的数据,而是检查所有数据,直到遇到没有超时的数据。

这样每次检查时就把所有超时数据一次清空了,只要CheckPreloadBuff()有机会执行,就不会让缓冲区无限增长。

 

修改如下:

  1. int CInputTS::AlarmInput() 
  2.           ... 
  3.           if(nRet > 0)//收到数据 
  4.         { 
  5.             //把收到的数据压入预录缓冲区 
  6.             CPoolNode* node = m_pPreloadBuff->allocNode(); 
  7.             if(node != NULL) 
  8.             { 
  9.                 node->m_nDataLen = nRet; 
  10.                 node->ntime = recvTime; 
  11.                 memcpy(node->m_pData, TsData, node->m_nDataLen); 
  12.                 m_pPreloadBuff->push(node); 
  13.             } 
  14.             else 
  15.             { 
  16.                 LOG(LOG_TYPE_ERROR, "CHAN[%d-%s], m_pPreloadBuff->allocNode() failed."
  17. , m_pChannel->m_nChannelID, m_pChannel->m_strName.c_str()); 
  18.             } 
  19.  
  20.            //检查预录缓冲区 
  21.          CheckPreloadBuff(recvTime); 
  22.            ... 

 

  1. void CInputTS::CheckPreloadBuff(time_t ltime) 
  2.     if((m_pPreloadBuff == NULL) || (m_pBuff == NULL) || (m_pRecordModule == NULL)) 
  3.     { 
  4.         return
  5.     } 
  6.  
  7.     /* 
  8.      * NOTICE:在每接收到一个数据包后,就调用CheckPreloadBuff检查预
  9. 录缓冲区,一次性将所有超时的预录数据全部清除 
  10.      * 必须清除所有超时预录数据,而不能只检查队头的数据;否则,一旦
  11. input和output速率不匹配,将导致预录缓冲区快速增长 
  12.      * 大量超时数据无法清除。最后程序使用的内存不断增长,耗尽了系统所
  13. 有的可用内存和交换分区,最后导致OS的oom-killer保护机制 
  14.      * 启动init进程向录制程序发送SIGKILL信号,最后录制程序退出。 
  15.      */ 
  16.     //检查预录缓冲区中的最旧数据 
  17.     while(!m_pPreloadBuff->empty()) 
  18.     { 
  19.         CPoolNode* node = m_pPreloadBuff->front();
  20. //清除所有超时数据,确保缓冲区中只保留指定时长的数据 
  21.         if((int)(ltime - node->ntime) >= m_nAlarmRecordTimeBefore)
  22. //超过预录时间 
  23.         { 
  24.             CPoolNode* pNode = m_pPreloadBuff->pop(); 
  25.             m_pPreloadBuff->freeNode(pNode); 
  26.         } 
  27.         else//后续不再处理 
  28.         { 
  29.             break
  30.         } 
  31.     } 

 

(chutianyao)
本站文章除注明转载外,均为本站原创或编译欢迎任何形式的转载,但请务必注明出处,尊重他人劳动,同学习共成长。转载请注明:文章转载自:罗索实验室 [http://www1.rosoo.net/a/201311/16807.html]
本文出处:博客园 作者:chutianyao 原文
顶一下
(0)
0%
踩一下
(0)
0%
------分隔线----------------------------
发表评论
请自觉遵守互联网相关的政策法规,严禁发布色情、暴力、反动的言论。
评价:
表情:
用户名: 验证码:点击我更换图片
栏目列表
将本文分享到微信
织梦二维码生成器
推荐内容