／＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊
＊ 版權(quán)聲明
＊ 本文為本人原創(chuàng)，本人擁有此文的版權(quán)。鑒于本人持續(xù)受益于開源軟件社區(qū)，
＊ 本人聲明：任何個人及團(tuán)體均可不受限制的轉(zhuǎn)載和復(fù)制本文，無論是否用于盈利
＊ 之目的，但必須在轉(zhuǎn)載及復(fù)制時同時保留本版權(quán)聲明，否則為侵權(quán)行為，本人保
＊ 留追究相應(yīng)法律責(zé)任之權(quán)利。
＊ speng2005@gmail.com
＊ 2007-12
＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊／
近日在使用ACE進(jìn)行開發(fā)的工作中遇到一個導(dǎo)致程序崩潰的問題。我們是在Linux平臺上使用ACE 5.5.1以及g++ 4.1.2進(jìn)行開發(fā)的。
問題是這樣的：我們的程序中有多個線程并發(fā)調(diào)用ACE_Log_Msg::log（）方法進(jìn)行日志輸出操作，這些日志將被輸出到同一個位于本地磁盤上的日志文件中。但為防止日志文件長度增長過大，我們使用了ACE_Logging_Strategy類來進(jìn)行定時的日志文件大小檢查和文件切換。這種方式在一般情況下運(yùn)行良好，但是在大規(guī)模壓力測試中，程序常常因訪問非法內(nèi)存而崩潰。發(fā)生崩潰時的調(diào)用棧總是這樣的：
(gdb) bt#0 0xb7c1bb4a in memcpy () from /lib/tls/i686/cmov/libc.so.6#1 0xb7d9c006 in std::basic_streambuf<char, std::char_traits<char> >::xsputn () from /usr/lib/libstdc++.so.6#2 0xb7d66d59 in std::basic_filebuf<char, std::char_traits<char> >::xsputn () from /usr/lib/libstdc++.so.6#3 0xb7d911df in std::operator<< <std::char_traits<char> > () from /usr/lib/libstdc++.so.6#4 0xb7ed8f15 in ACE_Log_Record::print (this=0x2befe228, host_name=0x0, verbose_flag=4, s=@0x80521c8) at Log_Record.cpp:302#5 0xb7ed70a6 in ACE_Log_Msg::log (this=0x8588a58, log_record=@0x2befe228, suppress_stderr=0) at Log_Msg.cpp:2197#6 0xb7ed749b in ACE_Log_Msg::log (this=0x8588a58, format_str=0xb7f9ef3d "", log_priority=LM_TRACE, argp=0xb7f9ef3c "") at Log_Msg.cpp:2047#7 0xb7ed8055 in ACE_Log_Msg::log (this=0x8588a58, log_priority=LM_TRACE, format_str=0xb7f9ef2a "%*s(%t) leaving %s") at Log_Msg.cpp:961#8 0xb7f9d9b3 in ~JAWS_Trace (this=0x2befe338) at Trace.cpp:139#9 0xb70ff7b3 in StorageWriteState::service (this=0x85aaa28, ec=0x291b4d70, data=0x291b4d70) at StorageWriteState.cpp:63#10 0xb7f94739 in JAWS_Protocol_Handler::service (this=0x291b4d70) at Protocol_Handler.cpp:38#11 0xb7f86e0e in JAWS_Concurrency_Impl::svc (this=0x8057a34) at Concurrency.cpp:38#12 0xb7f1c794 in ACE_Task_Base::svc_run (args=0x8057a34) at Task.cpp:258#13 0xb7f1d108 in ACE_Thread_Adapter::invoke_i (this=0x8057ca8) at Thread_Adapter.cpp:151#14 0xb7f1d2d6 in ACE_Thread_Adapter::invoke (this=0x8057ca8) at Thread_Adapter.cpp:95#15 0xb7eb0c51 in ace_thread_adapter (args=0x8057ca8) at Base_Thread_Adapter.cpp:137#16 0xb7e04240 in start_thread () from /lib/tls/i686/cmov/libpthread.so.0#17 0xb7c7a4ae in clone () from /lib/tls/i686/cmov/libc.so.6 因為多次崩潰的調(diào)用棧都一樣，這說明這個問題是一個比較確定的可再現(xiàn)bug，這為找到問題原因并最后解決提供了有利條件。
問題出現(xiàn)后，我們首先定位問題的原因與應(yīng)用程序的日志輸出有關(guān)系。經(jīng)過代碼復(fù)查，沒有發(fā)現(xiàn)這方面的任何問題。接下來，我們只好懷疑ACE的日志相關(guān)類的源碼存在問題。我們又徹底閱讀了與日志輸出有關(guān)的類的源代碼：ACE_Log_Msg，ACE_Log_Record，ACE_Logging_Strategy，包括
ACE_Logging_Strategy::handle_timeout（）方法的實(shí)現(xiàn)代碼，重點(diǎn)關(guān)注代碼中關(guān)于內(nèi)存操作和多線程安全互斥的操作，依然沒有發(fā)現(xiàn)可疑的地方。這下問題就復(fù)雜了，總不能懷疑C++標(biāo)準(zhǔn)庫的流類庫有問題吧？這不太可能，但是問題的直接爆發(fā)點(diǎn)是出在C++標(biāo)準(zhǔn)庫里的，所以只能從標(biāo)準(zhǔn)庫出發(fā)尋找線索。有過一定程序開發(fā)尤其是c/c++程序開發(fā)經(jīng)驗的人都知道，一些復(fù)雜問題直接暴露出來的現(xiàn)象都是問題的表象，根本的原因可能跟表象差的很遠(yuǎn)，但是順著表象提供的線索去尋找根源畢竟是解決問題的正道。于是我們開始從程序崩潰點(diǎn)尋找問題的癥結(jié)。
首先，我們分析程序為什么在調(diào)用memcpy（）這個標(biāo)準(zhǔn)c的庫函數(shù)時發(fā)生崩潰的。沒有源代碼，怎么分析？學(xué)一點(diǎn)匯編語言的基礎(chǔ)知識吧，這是對一個資深程序員的必要的技術(shù)要求。在gdb里使用如下命令：
(gdb) set disassembly-flavor intel(gdb) disassgdb就給出了memcpy（）函數(shù)的匯編指令：
Dump of assembler code for function memcpy:0xb7c1bb30 <memcpy+0>: mov ecx,DWORD PTR [esp+12]0xb7c1bb34 <memcpy+4>: mov eax,edi0xb7c1bb36 <memcpy+6>: mov edi,DWORD PTR [esp+4]0xb7c1bb3a <memcpy+10>: mov edx,esi0xb7c1bb3c <memcpy+12>: mov esi,DWORD PTR [esp+8]0xb7c1bb40 <memcpy+16>: cld 0xb7c1bb41 <memcpy+17>: shr ecx,10xb7c1bb43 <memcpy+19>: jae 0xb7c1bb46 <memcpy+22>0xb7c1bb45 <memcpy+21>: movs BYTE PTR es:[edi],BYTE PTR ds:[esi]0xb7c1bb46 <memcpy+22>: shr ecx,10xb7c1bb48 <memcpy+24>: jae 0xb7c1bb4c <memcpy+28>0xb7c1bb4a <memcpy+26>: movs WORD PTR es:[edi],WORD PTR ds:[esi]0xb7c1bb4c <memcpy+28>: rep movs DWORD PTR es:[edi],DWORD PTR ds:[esi]0xb7c1bb4e <memcpy+30>: mov edi,eax0xb7c1bb50 <memcpy+32>: mov esi,edx0xb7c1bb52 <memcpy+34>: mov eax,DWORD PTR [esp+4]0xb7c1bb56 <memcpy+38>: ret再使用如下命令：
(gdb) p $eipgdb就打印出：
$1 = (void (*)(void)) 0xb7c1bb4a <memcpy+26>這就是gdb精確地告訴我們程序是在執(zhí)行“movs WORD PTR es:[edi],WORD PTR ds:[esi]”指令時發(fā)生了錯誤，操作系統(tǒng)產(chǎn)生了“signal 11, Segmentation fault”信號，也就是說程序訪問了非法的內(nèi)存地址。我們觀察movs指令，很有可能edi寄存器中的地址是非法的，于是在gdb中輸入命令：
(gdb) p/x $edigdb就打印出：
$2 = 0x0這就證明的確是因為edi寄存器被賦予了NULL指針導(dǎo)致問題的出現(xiàn)的。有經(jīng)驗的程序員立刻可以意識到進(jìn)一步的問題癥結(jié)是調(diào)用棧中的上層函數(shù)向memcpy（）傳遞了錯誤的目標(biāo)地址參數(shù)進(jìn)而導(dǎo)致程序崩潰的。觀察調(diào)用棧，位于memcpy（）之上的3層函數(shù)都是C++標(biāo)準(zhǔn)庫的流操作。我想絕大多數(shù)程序員都是只知道怎么正確使用標(biāo)準(zhǔn)流類庫，而未研究過其是如何實(shí)現(xiàn)的吧？我們也是。但如果要解決問題，就必須弄清楚其內(nèi)部實(shí)現(xiàn)。好在標(biāo)準(zhǔn)流類庫都是模板實(shí)現(xiàn)，有源碼可讀。不讀不知道，標(biāo)準(zhǔn)流類庫的實(shí)現(xiàn)代碼還是很復(fù)雜的，晦澀難懂。可是我們也不是無目的的閱讀全部代碼，我們的近期目標(biāo)是找到傳遞給memcpy（）的指針是從哪來的，以及這個地址是如何被設(shè)成NULL的。我們找到最直接調(diào)用memcpy（）的C++標(biāo)準(zhǔn)庫源碼（看起來在這里我只寫了一句話，但是的確費(fèi)了很多腦細(xì)胞才確定這里的源代碼跟調(diào)用棧里顯示的那些被調(diào)用的函數(shù)是同一個版本的，確定這一點(diǎn)很重要）：
template<typename _CharT, typename _Traits>streamsizebasic_streambuf<_CharT, _Traits>::xsputn(const char_type* __s, streamsize __n){ streamsize __ret = 0; while (__ret < __n) { const streamsize __buf_len = this->epptr() - this->pptr(); if (__buf_len) { const streamsize __remaining = __n - __ret; const streamsize __len = std::min(__buf_len, __remaining); traits_type::copy(this->pptr(), __s, __len); __ret += __len; __s += __len; this->pbump(__len); } if (__ret < __n) { int_type __c = this->overflow(traits_type::to_int_type(*__s)); if (!traits_type::eq_int_type(__c, traits_type::eof())) { ++__ret; ++__s; } else break; } } return __ret;} 上面紅色顯示的部分就是對memcpy（）函數(shù)的調(diào)用語句。根據(jù)前面的分析，我們知道出問題的時候“
this->pptr()”必然返回了NULL，所以memcpy（）執(zhí)行時才會出錯。“this->pptr()”是內(nèi)聯(lián)方法：
char_type* pptr() const { return _M_out_cur; }這也就是說出問題的時候basic_streambuf<>對象的
_M_out_cur成員被設(shè)成了NULL，所以才會引發(fā)連鎖反應(yīng)。似乎我們快要找到問題根源了，但是，問題沒這么簡單。因為我們分析了上面的basic_streambuf<>::xsputn（）源碼，發(fā)現(xiàn)只有__buf_len大于0的時候程序才可能會走到memcpy（）函數(shù)調(diào)用中，而在我們的程序出問題的時候，“this->epptr()”居然返回的也是NULL！
“this->epptr()”也是內(nèi)聯(lián)方法：
char_type* epptr() const { return _M_out_end; }這也就是說出問題的時候basic_streambuf<>對象的
_M_out_end成員也被設(shè)成了NULL。這個時候計算得到的__buf_len值應(yīng)該等于0，但程序怎么會進(jìn)入到對memcpy（）函數(shù)的調(diào)用中呢？對此我們百思不得其解，但有一個信念：CPU保證會按程序的機(jī)器指令代碼行事，不會亂來的
。于是，
我們分析在我們的應(yīng)用程序是多線程的情形下，合理解釋只能是：當(dāng)前線程執(zhí)行到__buf_len的計算的代碼時返回的長度還是大于0的，于是會有后來的對
memcpy（）的調(diào)用；而同時可能有另外一個未做多線程同步的線程卻修改了“this->pptr()”及“this->epptr()
”對應(yīng)的指針值為NULL，這樣當(dāng)前線程執(zhí)行到memcpy（）時就會出錯。分析到此，我們又有了新方向。下一步的目標(biāo)就是確定哪個線程中的什么地方的代碼有可能會將basic_streambuf<>對象的
_M_out_cur成員及_M_out_end成員設(shè)成NULL。說起來容易做起來難啊！我們閱讀了大量源代碼，隱約發(fā)現(xiàn)有數(shù)個地方可能會修改_M_out_cur成員值為NULL，但細(xì)細(xì)推敲起來都不應(yīng)該導(dǎo)致出現(xiàn)上述問題。我們陷入僵局了。
所以我這里再次強(qiáng)調(diào)，一個資深的c/c++程序員應(yīng)該懂得一些匯編語言的基礎(chǔ)知識并掌握至少一個匯編調(diào)試器的使用技巧。在這里，gdb就夠用了。因為gdb支持“內(nèi)存讀寫斷點(diǎn)”的設(shè)置。內(nèi)存讀寫斷點(diǎn)是CPU為調(diào)試軟件設(shè)置的專用中斷器，它能夠監(jiān)視指定的內(nèi)存段范圍內(nèi)是否有內(nèi)存讀，或內(nèi)存寫，或內(nèi)存讀寫操作，如果有則產(chǎn)生中斷，并由調(diào)試器接管程序的執(zhí)行。在gdb里就可以設(shè)置這樣的斷點(diǎn)來監(jiān)視basic_streambuf<>對象的
_M_out_cur成員的值何時被修改，從而使我們知道在哪個線程執(zhí)行到哪個函數(shù)時修改了_M_out_cur成員的值，以便我們分析導(dǎo)致程序崩潰問題的根源。但困難在于，設(shè)置這樣的斷點(diǎn)時需要指定一個內(nèi)存地址，也就是我們要監(jiān)視的basic_streambuf<>對象的
_M_out_cur成員的內(nèi)存地址，這個如何確定呢?
還是匯編！在我們的應(yīng)用程序中，尋找_M_out_cur成員的內(nèi)存地址的思路是這樣的：我們觀察前面給出的調(diào)用棧，可以看到在第4層函數(shù)ACE_Log_Record::print()中的最后一個參數(shù)的是"s=@0x80521c8"，結(jié)合ACE源碼知道參數(shù)s的類型是ostream<> &，這其實(shí)就是告訴我們一個ostream<>對象的地址在0x80521c8。
而實(shí)際上這個ostream<>對象的子類型就是ofstream<>，也就是說在我們的應(yīng)用程序中多個線程操作著地址在0x80521c8的同一個ofstream<>對象進(jìn)行日志輸出操作
。閱讀C++標(biāo)準(zhǔn)庫源碼我們知道，如果知道了一個ofstream<>對象的首地址，就可以計算其_M_filebuf對象成員的首地址，該成員的類型為basic_filebuf<>；知道了一個basic_filebuf<>對象的首地址，就可以知道其繼承自基類basic_streambuf<>的
M_out_cur成員的地址了。這些地址的計算都是根據(jù)一個原理：對象的每個成員的首地址相對于該對象的首地址的偏移量是一個在編譯期就確定的常量，對象的首地址加上這個特定的偏移量而得到的值就是對應(yīng)成員的首地址。那么這些偏移量具體數(shù)值如何知道？匯編吧！我們寫了一個簡單的測試程序?qū)ｉT用于獲取我們所關(guān)心的兩個偏移量的數(shù)值。測試程序是這樣的：
#include <iostream>
#include <fstream>
using namespace std;
void work(ostream & s)
{
cout<<"pos="<<s.tellp()<<endl;
s<<"hello,world!"<<endl;
cout<<"pos="<<s.tellp()<<endl;
return;
}
int main()
{
ofstream out;
out.open("123.txt");
if( !out.is_open() )
{
cout<<"open file failed!"<<endl;
return 0;
}
work(out);
return 0;
}
經(jīng)過一翻外科手術(shù)式的剖析，我們找到了這兩個偏移量的數(shù)值（雖然這里只寫了一句話，但這絕不僅僅是一句話），并且弄清楚了一個ofstream<>對象的各個成員在內(nèi)存中的布局（僅在g++ 4.1.2編譯的目標(biāo)代碼中進(jìn)行了驗證）。如果一個ofstream<>對象的首地址在0x8049240，則此對象的內(nèi)存布局為：
address : hex value dump0x8049240 : 0xb7f6a9cc 0xb7f6aac8 0x0804a170 0x0804a1700x8049250 : 0x0804a170 0x00000000 0x00000000 0x000000000x8049260 : 0xb7f6dbbc 0x00000000 0x00000000 0x000000000x8049270 : 0x00000000 0x00000000 0x00000000 0x0804a0080x8049280 : 0x00000001 0x00000030 0x00000000 0x000000000x8049290 : 0x00000000 0x00000000 0x00000000 0x000000000x80492a0 : 0x0804a170 0x00002000 0x00000001 0x000000000x80492b0 : 0x00000000 0x00000000 0xb7f6df88 0x000000000x80492c0 : 0x00000000 0x00000000 0x00000000 0xb7f6a9e00x80492d0 : 0x00000006 0x00000000 0x00001002 0x000000000x80492e0 : 0x00000000 0x00000000 0x00000000 0x000000000x80492f0 : 0x00000000 0x00000000 0x00000000 0x000000000x8049300 : 0x00000000 0x00000000 0x00000000 0x000000000x8049310 : 0x00000000 0x00000000 0x00000000 0x000000000x8049320 : 0x00000000 0x00000000 0x00000000 0x000000000x8049330 : 0x00000008 0x080492f0 0xb7f6dbbc 0x000000000x8049340 : 0x00000000 0x08049244 0xb7f6dd40 0xb7f6df800x8049350 : 0xb7f6df78 0x00000000 0x00000000 0x00000000
..................在上面，我們知道
從0xb7f6aac8開始的內(nèi)存就是ofstream<>對象所聚合的basic_filebuf<>對象成員_M_filebuf的內(nèi)存映像；而
0x00000000就是該_M_filebuf對象的
M_out_cur成員的內(nèi)存映像，也就是說我們可以直接根據(jù)ofstream<>對象的首地址然后加上偏移量0x18而得到
M_out_cur成員的內(nèi)存地址。關(guān)于ofstream<>對象及basic_filebuf<>對象在內(nèi)存中的布局我們還研究了更多的東西。例如，
0xb7f6a9cc所指向的地址就是ofstream<>類的虛擬函數(shù)表的首地址；
0xb7f6aac8所指向的地址就是basic_filebuf<>類的虛擬函數(shù)表的首地址；
0x00000030就是basic_filebuf<>類的_M_mode成員的值，其值等價于(ios_base::out | ios_base::trunc)；
0x0804a170所指向的地址就是basic_filebuf<>對象內(nèi)部的一個真正內(nèi)部緩沖區(qū)的首地址，對應(yīng)于該對象的_M_buf成員；
0x00002000則指出這個緩沖區(qū)的長度是8192字節(jié)，對應(yīng)于該對象的_M_buf_size成員。
有了上面得到的內(nèi)存地址計算方法，下一步就是在我們的應(yīng)用程序中獲得ofstream<>對象的首地址了。這有很多方法，我們可以直接在gdb中找到ACE_Log_Msg::log（）方法的源碼并設(shè)置斷點(diǎn)，然后啟動程序，待斷點(diǎn)激活后，在gdb中打印調(diào)用棧而取得ofstream<>對象的首地址。這里我們使用了另外一種方法：我們根據(jù)前面給出的調(diào)用棧中的第1層的函數(shù)返回地址
0xb7d9c006，在gdb中進(jìn)行反匯編：
(gdb) disass 0xb7d9c006Dump of assembler code for function _ZNSt15basic_streambufIcSt11char_traitsIcEE6xsputnEPKci:0xb7d9bfa0 <_ZNSt15basic_streambufIcSt11char_traitsIcEE6xsputnEPKci+0>: push ebp0xb7d9bfa1 <_ZNSt15basic_streambufIcSt11char_traitsIcEE6xsputnEPKci+1>: mov ebp,esp0xb7d9bfa3 <_ZNSt15basic_streambufIcSt11char_traitsIcEE6xsputnEPKci+3>: push edi0xb7d9bfa4 <_ZNSt15basic_streambufIcSt11char_traitsIcEE6xsputnEPKci+4>: push esi0xb7d9bfa5 <_ZNSt15basic_streambufIcSt11char_traitsIcEE6xsputnEPKci+5>: push ebx0xb7d9bfa6 <_ZNSt15basic_streambufIcSt11char_traitsIcEE6xsputnEPKci+6>: sub esp,0x2c0xb7d9bfa9 <_ZNSt15basic_streambufIcSt11char_traitsIcEE6xsputnEPKci+9>: mov eax,DWORD PTR [ebp+16]......我們可以看到，gdb打印出了調(diào)用棧中第1層的函數(shù)的C++名稱經(jīng)過編碼后所對應(yīng)的C名稱字符串為“_ZNSt15basic_streambufIcSt11char_traitsIcEE6xsputnEPKci”，這個C名稱與其對應(yīng)的C++名稱“
std::basic_streambuf<char, std::char_traits<char> >::xsputn”是等價的。接下來，我們啟動一個新的gdb程序，并在gdb中加載應(yīng)用程序文件，在啟動應(yīng)用程序運(yùn)行之前，先設(shè)置斷點(diǎn)：
(gdb) break _ZNSt15basic_streambufIcSt11char_traitsIcEE6xsputnEPKci這就是要在前述的調(diào)用棧的第1層函數(shù)入口處設(shè)置斷點(diǎn)。然后我們啟動應(yīng)用程序的執(zhí)行并激活日志輸出操作，當(dāng)?shù)谝粭l日志輸出時，剛才所設(shè)斷點(diǎn)就激活了，gdb將中斷程序的執(zhí)行，此時我們打印調(diào)用棧，gdb將輸出與前述類似的調(diào)用棧，此時我們可以輕松地從調(diào)用棧中取得ofstream<>對象的首地址。我們將這個地址加上偏移量0x18，就得到了我們要監(jiān)視的內(nèi)存地址。在我們的應(yīng)用程序中計算得到的地址是0x80521e0。
有了要監(jiān)視的內(nèi)存地址以后，我們就可以在gdb里設(shè)置“內(nèi)存寫”斷點(diǎn)了，輸入如下命令：
(gdb) watch *(int *)0x80521e0Hardware watchpoint 1: *(int *) 134554080這表明一個“內(nèi)存寫”斷點(diǎn)設(shè)置成功。接下來讓gdb執(zhí)行c命令繼續(xù)執(zhí)行應(yīng)用程序，就可以開始監(jiān)視basic_filebuf<>對象的
M_out_cur成員何時被修改成NULL了。當(dāng)斷點(diǎn)激活時，gdb打印：Hardware watchpoint 3: *(int *) 134554080
Old value = 134555784
New value = 0
0xb7ce3088 in std::basic_filebuf<char, std::char_traits<char> >::_M_seek () from /usr/lib/libstdc++.so.6
此時打印調(diào)用棧，gdb顯示：
(gdb) bt
#0 0xb7ce3088 in std::basic_filebuf<char, std::char_traits<char> >::_M_seek () from /usr/lib/libstdc++.so.6
#1 0xb7ce4e2a in std::basic_filebuf<char, std::char_traits<char> >::seekoff () from /usr/lib/libstdc++.so.6
#2 0xb7d0be5d in std::ostream::tellp () from /usr/lib/libstdc++.so.6
#3 0xb7e560a4 in ACE_Logging_Strategy::handle_timeout (this=0xb7f24ac0) at Logging_Strategy.cpp:404
#4 0xb7e24cb1 in ACE_Event_Handler_Handle_Timeout_Upcall<ACE_Recursive_Thread_Mutex>::timeout (this=0x80515d0,
timer_queue=@0x8051528, event_handler=0xb7f24ac0, act=0x0, recurring_timer=1, cur_time=@0x2ccff2e8)
at /data/jinwei/svn_root/ireport/common/ace/ACE_wrappers/ace/Timer_Queue_T.cpp:408
#5 0xb7e4220d in ACE_Dev_Poll_Reactor::dispatch_timer_handler (this=0x8051470, guard=@0x2ccff394)
at /data/jinwei/svn_root/ireport/common/ace/ACE_wrappers/ace/Timer_Queue_T.inl:170
#6 0xb7e4492c in ACE_Dev_Poll_Reactor::dispatch (this=0x8051470, guard=@0x2ccff394) at Dev_Poll_Reactor.cpp:1230
#7 0xb7e44a56 in ACE_Dev_Poll_Reactor::handle_events_i (this=0x8051470, max_wait_time=0x0, guard=@0x2ccff394)
at Dev_Poll_Reactor.cpp:1211
#8 0xb7e44b21 in ACE_Dev_Poll_Reactor::handle_events (this=0x8051470, max_wait_time=0x0) at Dev_Poll_Reactor.cpp:1166
#9 0xb7e82f02 in ACE_Reactor::run_reactor_event_loop (this=0x80518f0, eh=0) at Reactor.cpp:233
#10 0xb7f0dbe7 in JAWS_Event_Dispatcher::JAWS_Event_Dispatcher_Reactor_Event_Loop () at Event_Dispatcher.cpp:32
#11 0xb7e99108 in ACE_Thread_Adapter::invoke_i (this=0x85b3918) at Thread_Adapter.cpp:151
#12 0xb7e992d6 in ACE_Thread_Adapter::invoke (this=0x85b3918) at Thread_Adapter.cpp:95
#13 0xb7e2cc51 in ace_thread_adapter (args=0x85b3918) at Base_Thread_Adapter.cpp:137
#14 0xb7d80240 in start_thread () from /lib/tls/i686/cmov/libpthread.so.0
#15 0xb7bf64ae in clone () from /lib/tls/i686/cmov/libc.so.6
此時，我們終于有了重大發(fā)現(xiàn)！原來ACE_Logging_Strategy::handle_timeout（）方法中執(zhí)行了如下代碼：
int
ACE_Logging_Strategy::handle_timeout (const ACE_Time_Value &,
const void *)
{
#if defined (ACE_LACKS_IOSTREAM_TOTALLY)
if ((size_t) ACE_OS::ftell (this->log_msg_->msg_ostream ()) > this->max_size_)
#else
if ((size_t) this->log_msg_->msg_ostream ()->tellp () > this->max_size_)
#endif /* ACE_LACKS_IOSTREAM_TOTALLY */
{
// Lock out any other logging.
if (this->log_msg_->acquire ())
ACE_ERROR_RETURN ((LM_ERROR,
ACE_LIB_TEXT ("Cannot acquire lock!")),
-1);
.....
}
.....
}
可以看到，對ostream<>::tellp()方法的調(diào)用居然會導(dǎo)致ofstream<>對象內(nèi)部的basic_streambuf<>對象成員的
M_out_cur成員的值被修改
為NULL！而ACE_Logging_Strategy::handle_timeout（）方法在調(diào)用ostream<>::tellp()方法時居然沒有先獲得鎖！知道這個根本原因了，問題就好解決了，至于如何修改
ACE_Logging_Strategy::handle_timeout（）的代碼，明眼人一看便知了。我們修改代碼后并進(jìn)行了長期的壓力測試的驗證，最后確認(rèn)了這就是問題的根源。
這個問題被解決后，我們查看了ACE最新版本5.6.2中的代碼，發(fā)現(xiàn)源碼中仍然存在此問題。于是我們給ACE開發(fā)社區(qū)發(fā)了一個帖子：
A bug about ACE_Logging_Strategy 來報告這個ACE中的bug，算是為ACE開發(fā)社區(qū)做個貢獻(xiàn)吧。
細(xì)細(xì)推敲起來，開發(fā)ACE的大牛們?yōu)槭裁磿高@種有點(diǎn)低級的錯誤呢？而且這么長時間都沒有發(fā)現(xiàn)這個問題？也許他們沒有進(jìn)行過像我們這么大壓力的長期測試吧？也許他們也和我們當(dāng)初所認(rèn)為的一樣，以為ostream<>::tellp()即便不是一個const方法，也應(yīng)該是個“準(zhǔn)”const方法吧？然而事實(shí)卻并非如此。其實(shí)從C++程序員的角度來說，我們的確需要一個const版本的ostream<>::tellp()接口，不知道將來C++標(biāo)準(zhǔn)會不會在這個問題上有所改變。對于這個訴求，不只我們有，這里也有:
why is ostream::tellp not const。