新版本的錄制程序終於快完工了，在添加了一個新特性“報警錄制”后，就開始測試了。
一開始就不順利：程序正常運行一段時間后就會崩潰，由於程序添加了守護進程，在崩潰后會自動重啟。
因此測試得到的結果就是：程序運行一段時間后就自動重啟，並不斷持續；有時幾個小時重啟一次，有時甚至每分鍾都重啟。
廢話少說，開始定位問題：
1.去掉自動重啟功能，在gdb下運行，20多分鍾后就崩潰了：
2011-10-26 17:50:22,565: INFO : recved alarm:[10.0.60.2-1-3905],type:12, startTime:1319622622, recvTime:1319622622
2011-10-26 17:50:22,628: INFO : SetAlmStatus CHAN[1] = TRUE
2011-10-26 17:50:22,628: INFO : recved alarm:[10.0.60.2-1-3905],type:12, startTime:1319622622, recvTime:1319622622
2011-10-26 17:50:22,962: NOTICE : Open file:'/figure/data/AlarmRecord/StreamTS/1-碼流_魅力音 樂主路/2011-10-26/20111026175022.ts'
[Thread 0xa7db70 (LWP 6645) exited]
[Thread 0xa3cb70 (LWP 6644) exited]
[Thread 0x5cdfb70 (LWP 6643) exited]
[Thread 0x45fdb70 (LWP 6642) exited]
[Thread 0x3bfcb70 (LWP 6641) exited]
[Thread 0x240fb70 (LWP 6640) exited]
[Thread 0x52deb70 (LWP 6638) exited]
[Thread 0x1a0eb70 (LWP 6637) exited]
[Thread 0x67b7b70 (LWP 6636) exited]
[Thread 0x31fbb70 (LWP 6635) exited]
[Thread 0x956b70 (LWP 6634) exited]
[Thread 0x935b70 (LWP 6633) exited]
[Thread 0x8f4b70 (LWP 6632) exited]
Program terminated with signal SIGKILL, Killed.
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中發現如下記錄:
Oct 26 17:17:30 localhost kernel: Record invoked oom-killer: gfp_mask=0x280da, order=0, oomkilladj=0
Oct 26 17:17:31 localhost kernel: Record cpuset=/ mems_allowed=0
Oct 26 17:17:31 localhost kernel: Pid: 6350, comm: Record Not tainted 2.6.31.5-127.fc12.i686.PAE #1
Oct 26 17:17:31 localhost kernel: Call Trace:
Oct 26 17:17:31 localhost kernel: [<c049d891>] oom_kill_process+0x6e/0x1f2
Oct 26 17:17:32 localhost kernel: [<c049dd4f>] ? select_bad_process+0x87/0xce
Oct 26 17:17:32 localhost kernel: [<c049de09>] __out_of_memory+0x73/0x82
Oct 26 17:17:32 localhost kernel: [<c049de7b>] out_of_memory+0x63/0x88
Oct 26 17:17:32 localhost kernel: [<c04a00aa>] __alloc_pages_nodemask+0x382/0x447
Oct 26 17:17:32 localhost kernel: [<c04af062>] alloc_pages_node.clone.0+0x16/0x18
Oct 26 17:17:32 localhost kernel: [<c04afd63>] handle_mm_fault+0x1d7/0x8f2
Oct 26 17:17:32 localhost kernel: [<c04379e3>] ? finish_task_switch+0x53/0xbf
Oct 26 17:17:32 localhost kernel: [<c077a829>] do_page_fault+0x282/0x298
Oct 26 17:17:32 localhost kernel: [<c077a5a7>] ? do_page_fault+0x0/0x298
Oct 26 17:17:32 localhost kernel: [<c0778d3b>] error_code+0x73/0x78
Oct 26 17:17:32 localhost kernel: Mem-Info:
Oct 26 17:17:32 localhost kernel: DMA per-cpu:
Oct 26 17:17:32 localhost kernel: CPU 0: hi: 0, btch: 1 usd: 0
Oct 26 17:17:32 localhost kernel: CPU 1: hi: 0, btch: 1 usd: 0
Oct 26 17:17:32 localhost kernel: Normal per-cpu:
Oct 26 17:17:32 localhost kernel: CPU 0: hi: 186, btch: 31 usd: 176
Oct 26 17:17:32 localhost kernel: CPU 1: hi: 186, btch: 31 usd: 184
Oct 26 17:17:32 localhost kernel: Active_anon:96761 active_file:752 inactive_anon:96834
Oct 26 17:17:32 localhost kernel: inactive_file:1384 unevictable:0 dirty:25 writeback:695 unstable:0
Oct 26 17:17:32 localhost kernel: free:1920 slab:5066 mapped:791 pagetables:2649 bounce:0
Oct 26 17:17:32 localhost kernel: DMA free:3328kB min:68kB low:84kB high:100kB active_anon:2296kB inactive_anon:2420kB active_file:204kB inactive_file:724kB unevictable:0kB
present:15804kB pages_scanned:0 all_unreclaimable? no
Oct 26 17:17:32 localhost kernel: lowmem_reserve[]: 0 809 809 809
Oct 26 17:17:32 localhost kernel: Normal free:4352kB min:3604kB low:4504kB high:5404kB active_anon:384748kB inactive_anon:384916kB active_file:2804kB inactive_file:4812kB
unevictable:0kB present:828992kB pages_scanned:2496 all_unreclaimable? no
Oct 26 17:17:32 localhost kernel: lowmem_reserve[]: 0 0 0 0
Oct 26 17:17:32 localhost kernel: DMA: 14*4kB 15*8kB 11*16kB 7*32kB 7*64kB 2*128kB 0*256kB 0*512kB 0*1024kB 1*2048kB 0*4096kB = 3328kB
Oct 26 17:17:32 localhost 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
Oct 26 17:17:32 localhost kernel: 2902 total pagecache pages
Oct 26 17:17:32 localhost kernel: 639 pages in swap cache
Oct 26 17:17:32 localhost kernel: Swap cache stats: add 860507, delete 859868, find 46506/63512
Oct 26 17:17:32 localhost kernel: Free swap = 0kB
Oct 26 17:17:32 localhost kernel: Total swap = 1023992kB
Oct 26 17:17:32 localhost kernel: 212976 pages RAM
Oct 26 17:17:32 localhost kernel: 0 pages HighMem
Oct 26 17:17:32 localhost kernel: 4796 pages reserved
Oct 26 17:17:32 localhost kernel: 13599 pages shared
Oct 26 17:17:32 localhost kernel: 203455 pages non-shared
Oct 26 17:17:32 localhost kernel: Out of memory: kill process 6338 (gdb) score 191002 or a child
Oct 26 17:17:32 localhost kernel: Killed process 6340 (Record)
看到最后兩行：
kernel: Out of memory: kill process 6338 (gdb) score 191002 or a child
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）查代碼的過程不說，最后定位到問題在下面的代碼：
//報警錄制輸入
int CInputTS::AlarmInput()
{
int nRet = InitTsSocket();
if( (nRet < 0) || (m_pPreloadBuff == NULL) || (m_pBuff == NULL))
{
LOG(LOG_TYPE_ERROR, "Channel:[%d-%s]. AlarmInput().nRet = %d, m_pPreloadBuff = 0X%X, m_pBuff = 0X%X. exit", m_pChannel->m_nChannelID, m_pChannel->m_strName.c_str(), nRet, m_pPreloadBuff, m_pBuff);
return -1;
}
int recvTime = time(NULL);
char TsData[TS_DATA_LEN] = {0};
bool bStarted = false;
while(!m_nEndFlag)
{
recvTime = time(NULL);
nRet = recvfrom(TsSock, TsData, TS_DATA_LEN, 0, NULL, NULL);
if(nRet > 0)//收到數據
{
//把收到的數據壓入預錄緩沖區
CPoolNode* node = m_pPreloadBuff->allocNode();
if(node != NULL)
{
node->m_nDataLen = nRet;
node->ntime = recvTime;
memcpy(node->m_pData, TsData, node->m_nDataLen);
m_pPreloadBuff->push(node);
}
else
{
LOG(LOG_TYPE_ERROR, "CHAN[%d-%s], m_pPreloadBuff->allocNode() failed.", m_pChannel->m_nChannelID, m_pChannel->m_strName.c_str());
}
//檢查當前報警狀態
if(bStarted)//正在進行報警錄制
{
bStarted = m_pRecordModule->DetermineEndOutput(0, recvTime);
}
else
{
bStarted = m_pRecordModule->DetermineStartOutput(recvTime);
if(!bStarted)//不需要進行報警錄制
{
continue;
}
DumpPreloadBuff();
}
//進行報警錄制
//報警開始之后的數據壓入m_pBuff(在報警持續時間內，數據同時壓入m_pPreloadBuff和m_pBuff中)
CPoolNode* buffnode = m_pBuff->allocNode();
if(buffnode == NULL)
{
LOG_PERIOD(LOG_TYPE_ERROR, "Channel:[%d-%s], AllocNode failed. Lost Data:%d bytes",
m_pChannel->m_nChannelID, m_pChannel->m_strName.c_str(), nRet);
usleep(50);
continue;
}
buffnode->m_nDataLen = nRet;
buffnode->ntime = recvTime;
memcpy(buffnode->m_pData, TsData, buffnode->m_nDataLen);
m_pBuff->push(buffnode);
//檢查預錄緩沖區
CheckPreloadBuff(recvTime);
}
else
{
LOG_PERIOD(LOG_TYPE_ERROR,"No Input Data! Channel:[%d-%s], nRecvSize = %d, %s\n",
m_pChannel->m_nChannelID, m_pChannel->m_strName.c_str(), nRet, strerror(errno));
}
}
close(TsSock);
return 0;
}
1 void CInputTS::CheckPreloadBuff(time_t ltime)
2 {
3 if((m_pPreloadBuff == NULL) || (m_pBuff == NULL) || (m_pRecordModule == NULL))
4 {
5 return;
6 }
7
8 if(!m_pPreloadBuff->empty())
9 {
10 CPoolNode* node = m_pPreloadBuff->front();
11 if((int)(ltime - node->ntime) >= m_nAlarmRecordTimeBefore) //超過預錄時間
12 {
13 CPoolNode* pNode = m_pPreloadBuff->pop();
14 m_pPreloadBuff->freeNode(pNode);
15 }
16 }
17 }
先解釋邏輯：
（1）AlarmInput()從socket不斷接收數據，首先壓入預錄緩沖區m_pPreloadBuff 中，這個緩沖區m_pPreloadBuff其實就是一個隊列；
（2）AlarmInput()每接收到一個數據包后調用CheckPreloadBuff()檢查預錄緩沖區m_pPreloadBuff 隊頭的數據，如果超時就丟掉；
（需求說明：本段代碼要求預錄緩沖區中只保留指定時長的數據，超時數據就會被丟掉，這樣預錄緩沖區就會維持在一個穩定的長度）。
但在測試時發現這段代碼並沒有按照我們預想的方式工作，預錄緩沖區m_pPreloadBuff的隊列長度不斷增長，最后將系統內存耗盡了！
罪魁禍首在這里！
分析邏輯：每接收到一個數據包后，將其push到預錄緩沖區m_pPreloadBuff 的隊列中，然后調用CheckPreloadBuff()檢查隊頭的數據，如果超時就丟掉。
正常情況下，隊列中push一個數據，接着就pop一個是不會有問題的；但是在這段邏輯中：
if(!bStarted)//不需要進行報警錄制
{
continue;
}
程序push了數據，就直接contine返回，沒有執行CheckPreloadBuff()，導致m_pPreloadBuff 中積累多個超時數據；而當下次再調用CheckPreloadBuff()時還是只檢查隊頭的數據。這樣的話，我們很可能push了10個數據，確只檢查了3個隊頭數據，因此預錄緩沖區m_pPreloadBuff就會不斷增長。
問題定位就好解決了：每次執行CheckPreloadBuff()時不只檢查隊頭的數據，而是檢查所有數據，直到遇到沒有超時的數據。
這樣每次檢查時就把所有超時數據一次清空了，只要CheckPreloadBuff()有機會執行，就不會讓緩沖區無限增長。
修改如下：
1 int CInputTS::AlarmInput()
2 {
3 ...
4 if(nRet > 0)//收到數據
5 {
6 //把收到的數據壓入預錄緩沖區
7 CPoolNode* node = m_pPreloadBuff->allocNode();
8 if(node != NULL)
9 {
10 node->m_nDataLen = nRet;
11 node->ntime = recvTime;
12 memcpy(node->m_pData, TsData, node->m_nDataLen);
13 m_pPreloadBuff->push(node);
14 }
15 else
16 {
17 LOG(LOG_TYPE_ERROR, "CHAN[%d-%s], m_pPreloadBuff->allocNode() failed.", m_pChannel->m_nChannelID, m_pChannel->m_strName.c_str());
18 }
19
20 //檢查預錄緩沖區
21 CheckPreloadBuff(recvTime);
22 ...
23 }
1 void CInputTS::CheckPreloadBuff(time_t ltime)
2 {
3 if((m_pPreloadBuff == NULL) || (m_pBuff == NULL) || (m_pRecordModule == NULL))
4 {
5 return;
6 }
7
8 /*
9 * NOTICE:在每接收到一個數據包后，就調用CheckPreloadBuff檢查預錄緩沖區，一次性將所有超時的預錄數據全部清除
10 * 必須清除所有超時預錄數據，而不能只檢查隊頭的數據；否則，一旦input和output速率不匹配，將導致預錄緩沖區快速增長
11 * 大量超時數據無法清除。最后程序使用的內存不斷增長，耗盡了系統所有的可用內存和交換分區，最后導致OS的oom-killer保護機制
12 * 啟動init進程向錄制程序發送SIGKILL信號，最后錄制程序退出。
13 */
14 //檢查預錄緩沖區中的最舊數據
15 while(!m_pPreloadBuff->empty())
16 {
17 CPoolNode* node = m_pPreloadBuff->front();//清除所有超時數據,確保緩沖區中只保留指定時長的數據
18 if((int)(ltime - node->ntime) >= m_nAlarmRecordTimeBefore) //超過預錄時間
19 {
20 CPoolNode* pNode = m_pPreloadBuff->pop();
21 m_pPreloadBuff->freeNode(pNode);
22 }
23 else//后續不再處理
24 {
25 break;
26 }
27 }