／＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊
＊ 版權(quán)聲明
＊ 本文為本人原創(chuàng)，本人擁有此文的版權(quán)。鑒于本人持續(xù)受益于開源軟件社區(qū)，
＊ 本人聲明：任何個(gè)人及團(tuán)體均可不受限制的轉(zhuǎn)載和復(fù)制本文，無(wú)論是否用于盈利
＊ 之目的，但必須在轉(zhuǎn)載及復(fù)制時(shí)同時(shí)保留本版權(quán)聲明，否則為侵權(quán)行為，本人保
＊ 留追究相應(yīng)法律責(zé)任之權(quán)利。
＊ speng2005@gmail.com
＊ 2007-12
＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊／
近日在使用ACE進(jìn)行開發(fā)的工作中遇到一個(gè)導(dǎo)致程序崩潰的問(wèn)題。我們是在Linux平臺(tái)上使用ACE 5.5.1以及g++ 4.1.2進(jìn)行開發(fā)的。
問(wèn)題是這樣的：我們的程序中有多個(gè)線程并發(fā)調(diào)用ACE_Log_Msg::log（）方法進(jìn)行日志輸出操作，這些日志將被輸出到同一個(gè)位于本地磁盤上的日志文件中。但為防止日志文件長(zhǎng)度增長(zhǎng)過(guò)大，我們使用了ACE_Logging_Strategy類來(lái)進(jìn)行定時(shí)的日志文件大小檢查和文件切換。這種方式在一般情況下運(yùn)行良好，但是在大規(guī)模壓力測(cè)試中，程序常常因訪問(wèn)非法內(nèi)存而崩潰。發(fā)生崩潰時(shí)的調(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 因?yàn)槎啻伪罎⒌恼{(diào)用棧都一樣，這說(shuō)明這個(gè)問(wèn)題是一個(gè)比較確定的可再現(xiàn)bug，這為找到問(wèn)題原因并最后解決提供了有利條件。
問(wèn)題出現(xiàn)后，我們首先定位問(wèn)題的原因與應(yīng)用程序的日志輸出有關(guān)系。經(jīng)過(guò)代碼復(fù)查，沒(méi)有發(fā)現(xiàn)這方面的任何問(wèn)題。接下來(lái)，我們只好懷疑ACE的日志相關(guān)類的源碼存在問(wè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)存操作和多線程安全互斥的操作，依然沒(méi)有發(fā)現(xiàn)可疑的地方。這下問(wèn)題就復(fù)雜了，總不能懷疑C++標(biāo)準(zhǔn)庫(kù)的流類庫(kù)有問(wèn)題吧？這不太可能，但是問(wèn)題的直接爆發(fā)點(diǎn)是出在C++標(biāo)準(zhǔn)庫(kù)里的，所以只能從標(biāo)準(zhǔn)庫(kù)出發(fā)尋找線索。有過(guò)一定程序開發(fā)尤其是c/c++程序開發(fā)經(jīng)驗(yàn)的人都知道，一些復(fù)雜問(wèn)題直接暴露出來(lái)的現(xiàn)象都是問(wèn)題的表象，根本的原因可能跟表象差的很遠(yuǎn)，但是順著表象提供的線索去尋找根源畢竟是解決問(wèn)題的正道。于是我們開始從程序崩潰點(diǎn)尋找問(wèn)題的癥結(jié)。
首先，我們分析程序?yàn)槭裁丛谡{(diào)用memcpy（）這個(gè)標(biāo)準(zhǔn)c的庫(kù)函數(shù)時(shí)發(fā)生崩潰的。沒(méi)有源代碼，怎么分析？學(xué)一點(diǎn)匯編語(yǔ)言的基礎(chǔ)知識(shí)吧，這是對(duì)一個(gè)資深程序員的必要的技術(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]”指令時(shí)發(fā)生了錯(cuò)誤，操作系統(tǒng)產(chǎn)生了“signal 11, Segmentation fault”信號(hào)，也就是說(shuō)程序訪問(wèn)了非法的內(nèi)存地址。我們觀察movs指令，很有可能edi寄存器中的地址是非法的，于是在gdb中輸入命令：
(gdb) p/x $edigdb就打印出：
$2 = 0x0這就證明的確是因?yàn)閑di寄存器被賦予了NULL指針導(dǎo)致問(wèn)題的出現(xiàn)的。有經(jīng)驗(yàn)的程序員立刻可以意識(shí)到進(jìn)一步的問(wèn)題癥結(jié)是調(diào)用棧中的上層函數(shù)向memcpy（）傳遞了錯(cuò)誤的目標(biāo)地址參數(shù)進(jìn)而導(dǎo)致程序崩潰的。觀察調(diào)用棧，位于memcpy（）之上的3層函數(shù)都是C++標(biāo)準(zhǔn)庫(kù)的流操作。我想絕大多數(shù)程序員都是只知道怎么正確使用標(biāo)準(zhǔn)流類庫(kù)，而未研究過(guò)其是如何實(shí)現(xiàn)的吧？我們也是。但如果要解決問(wèn)題，就必須弄清楚其內(nèi)部實(shí)現(xiàn)。好在標(biāo)準(zhǔn)流類庫(kù)都是模板實(shí)現(xiàn)，有源碼可讀。不讀不知道，標(biāo)準(zhǔn)流類庫(kù)的實(shí)現(xiàn)代碼還是很復(fù)雜的，晦澀難懂。可是我們也不是無(wú)目的的閱讀全部代碼，我們的近期目標(biāo)是找到傳遞給memcpy（）的指針是從哪來(lái)的，以及這個(gè)地址是如何被設(shè)成NULL的。我們找到最直接調(diào)用memcpy（）的C++標(biāo)準(zhǔn)庫(kù)源碼（看起來(lái)在這里我只寫了一句話，但是的確費(fèi)了很多腦細(xì)胞才確定這里的源代碼跟調(diào)用棧里顯示的那些被調(diào)用的函數(shù)是同一個(gè)版本的，確定這一點(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;} 上面紅色顯示的部分就是對(duì)memcpy（）函數(shù)的調(diào)用語(yǔ)句。根據(jù)前面的分析，我們知道出問(wèn)題的時(shí)候“
this->pptr()”必然返回了NULL，所以memcpy（）執(zhí)行時(shí)才會(huì)出錯(cuò)。“this->pptr()”是內(nèi)聯(lián)方法：
char_type* pptr() const { return _M_out_cur; }這也就是說(shuō)出問(wèn)題的時(shí)候basic_streambuf<>對(duì)象的
_M_out_cur成員被設(shè)成了NULL，所以才會(huì)引發(fā)連鎖反應(yīng)。似乎我們快要找到問(wèn)題根源了，但是，問(wèn)題沒(méi)這么簡(jiǎn)單。因?yàn)槲覀兎治隽松厦娴?/span>basic_streambuf<>::xsputn（）源碼，發(fā)現(xiàn)只有__buf_len大于0的時(shí)候程序才可能會(huì)走到memcpy（）函數(shù)調(diào)用中，而在我們的程序出問(wèn)題的時(shí)候，“this->epptr()”居然返回的也是NULL！“this->epptr()”也是內(nèi)聯(lián)方法：
char_type* epptr() const { return _M_out_end; }
這也就是說(shuō)出問(wèn)題的時(shí)候basic_streambuf<>對(duì)象的_M_out_end成員也被設(shè)成了NULL。這個(gè)時(shí)候計(jì)算得到的__buf_len值應(yīng)該等于0，但程序怎么會(huì)進(jìn)入到對(duì)memcpy（）函數(shù)的調(diào)用中呢？對(duì)此我們百思不得其解，但有一個(gè)信念：CPU保證會(huì)按程序的機(jī)器指令代碼行事，不會(huì)亂來(lái)的。于是，我們分析在我們的應(yīng)用程序是多線程的情形下，合理解釋只能是：當(dāng)前線程執(zhí)行到__buf_len的計(jì)算的代碼時(shí)返回的長(zhǎng)度還是大于0的，于是會(huì)有后來(lái)的對(duì)memcpy（）的調(diào)用；而同時(shí)可能有另外一個(gè)未做多線程同步的線程卻修改了“this->pptr()”及“this->epptr()”對(duì)應(yīng)的指針值為NULL，這樣當(dāng)前線程執(zhí)行到memcpy（）時(shí)就會(huì)出錯(cuò)。分析到此，我們又有了新方向。下一步的目標(biāo)就是確定哪個(gè)線程中的什么地方的代碼有可能會(huì)將basic_streambuf<>對(duì)象的_M_out_cur成員及_M_out_end成員設(shè)成NULL。說(shuō)起來(lái)容易做起來(lái)難啊！我們閱讀了大量源代碼，隱約發(fā)現(xiàn)有數(shù)個(gè)地方可能會(huì)修改_M_out_cur成員值為NULL，但細(xì)細(xì)推敲起來(lái)都不應(yīng)該導(dǎo)致出現(xiàn)上述問(wèn)題。我們陷入僵局了。
所以我這里再次強(qiáng)調(diào)，一個(gè)資深的c/c++程序員應(yīng)該懂得一些匯編語(yǔ)言的基礎(chǔ)知識(shí)并掌握至少一個(gè)匯編調(diào)試器的使用技巧。在這里，gdb就夠用了。因?yàn)間db支持“內(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)來(lái)監(jiān)視basic_streambuf<>對(duì)象的_M_out_cur成員的值何時(shí)被修改，從而使我們知道在哪個(gè)線程執(zhí)行到哪個(gè)函數(shù)時(shí)修改了_M_out_cur成員的值，以便我們分析導(dǎo)致程序崩潰問(wèn)題的根源。但困難在于，設(shè)置這樣的斷點(diǎn)時(shí)需要指定一個(gè)內(nèi)存地址，也就是我們要監(jiān)視的basic_streambuf<>對(duì)象的_M_out_cur成員的內(nèi)存地址，這個(gè)如何確定呢?
還是匯編！在我們的應(yīng)用程序中，尋找_M_out_cur成員的內(nèi)存地址的思路是這樣的：我們觀察前面給出的調(diào)用棧，可以看到在第4層函數(shù)ACE_Log_Record::print()中的最后一個(gè)參數(shù)的是"s=@0x80521c8"，結(jié)合ACE源碼知道參數(shù)s的類型是ostream<> &，這其實(shí)就是告訴我們一個(gè)ostream<>對(duì)象的地址在0x80521c8。而實(shí)際上這個(gè)ostream<>對(duì)象的子類型就是ofstream<>，也就是說(shuō)在我們的應(yīng)用程序中多個(gè)線程操作著地址在0x80521c8的同一個(gè)ofstream<>對(duì)象進(jìn)行日志輸出操作。閱讀C++標(biāo)準(zhǔn)庫(kù)源碼我們知道，如果知道了一個(gè)ofstream<>對(duì)象的首地址，就可以計(jì)算其_M_filebuf對(duì)象成員的首地址，該成員的類型為basic_filebuf<>；知道了一個(gè)basic_filebuf<>對(duì)象的首地址，就可以知道其繼承自基類basic_streambuf<>的M_out_cur成員的地址了。這些地址的計(jì)算都是根據(jù)一個(gè)原理：對(duì)象的每個(gè)成員的首地址相對(duì)于該對(duì)象的首地址的偏移量是一個(gè)在編譯期就確定的常量，對(duì)象的首地址加上這個(gè)特定的偏移量而得到的值就是對(duì)應(yīng)成員的首地址。那么這些偏移量具體數(shù)值如何知道？匯編吧！我們寫了一個(gè)簡(jiǎn)單的測(cè)試程序?qū)ｉT用于獲取我們所關(guān)心的兩個(gè)偏移量的數(shù)值。測(cè)試程序是這樣的：
#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)過(guò)一翻外科手術(shù)式的剖析，我們找到了這兩個(gè)偏移量的數(shù)值（雖然這里只寫了一句話，但這絕不僅僅是一句話），并且弄清楚了一個(gè)ofstream<>對(duì)象的各個(gè)成員在內(nèi)存中的布局（僅在g++ 4.1.2編譯的目標(biāo)代碼中進(jìn)行了驗(yàn)證）。如果一個(gè)ofstream<>對(duì)象的首地址在0x8049240，則此對(duì)象的內(nèi)存布局為：
address : hex value dump
0x8049240 : 0xb7f6a9cc 0xb7f6aac8 0x0804a170 0x0804a170
0x8049250 : 0x0804a170 0x00000000 0x00000000 0x00000000
0x8049260 : 0xb7f6dbbc 0x00000000 0x00000000 0x00000000
0x8049270 : 0x00000000 0x00000000 0x00000000 0x0804a008
0x8049280 : 0x00000001 0x00000030 0x00000000 0x00000000
0x8049290 : 0x00000000 0x00000000 0x00000000 0x00000000
0x80492a0 : 0x0804a170 0x00002000 0x00000001 0x00000000
0x80492b0 : 0x00000000 0x00000000 0xb7f6df88 0x00000000
0x80492c0 : 0x00000000 0x00000000 0x00000000 0xb7f6a9e0
0x80492d0 : 0x00000006 0x00000000 0x00001002 0x00000000
0x80492e0 : 0x00000000 0x00000000 0x00000000 0x00000000
0x80492f0 : 0x00000000 0x00000000 0x00000000 0x00000000
0x8049300 : 0x00000000 0x00000000 0x00000000 0x00000000
0x8049310 : 0x00000000 0x00000000 0x00000000 0x00000000
0x8049320 : 0x00000000 0x00000000 0x00000000 0x00000000
0x8049330 : 0x00000008 0x080492f0 0xb7f6dbbc 0x00000000
0x8049340 : 0x00000000 0x08049244 0xb7f6dd40 0xb7f6df80
0x8049350 : 0xb7f6df78 0x00000000 0x00000000 0x00000000
..................
在上面，我們知道從0xb7f6aac8開始的內(nèi)存就是ofstream<>對(duì)象所聚合的basic_filebuf<>對(duì)象成員_M_filebuf的內(nèi)存映像；而0x00000000就是該_M_filebuf對(duì)象的M_out_cur成員的內(nèi)存映像，也就是說(shuō)我們可以直接根據(jù)ofstream<>對(duì)象的首地址然后加上偏移量0x18而得到M_out_cur成員的內(nèi)存地址。關(guān)于ofstream<>對(duì)象及basic_filebuf<>對(duì)象在內(nèi)存中的布局我們還研究了更多的東西。例如，0xb7f6a9cc所指向的地址就是ofstream<>類的虛擬函數(shù)表的首地址；0xb7f6aac8所指向的地址就是basic_filebuf<>類的虛擬函數(shù)表的首地址；0x00000030就是basic_filebuf<>類的_M_mode成員的值，其值等價(jià)于(ios_base::out | ios_base::trunc)；0x0804a170所指向的地址就是basic_filebuf<>對(duì)象內(nèi)部的一個(gè)真正內(nèi)部緩沖區(qū)的首地址，對(duì)應(yīng)于該對(duì)象的_M_buf成員；0x00002000則指出這個(gè)緩沖區(qū)的長(zhǎng)度是8192字節(jié)，對(duì)應(yīng)于該對(duì)象的_M_buf_size成員。
有了上面得到的內(nèi)存地址計(jì)算方法，下一步就是在我們的應(yīng)用程序中獲得ofstream<>對(duì)象的首地址了。這有很多方法，我們可以直接在gdb中找到ACE_Log_Msg::log（）方法的源碼并設(shè)置斷點(diǎn)，然后啟動(dòng)程序，待斷點(diǎn)激活后，在gdb中打印調(diào)用棧而取得ofstream<>對(duì)象的首地址。這里我們使用了另外一種方法：我們根據(jù)前面給出的調(diào)用棧中的第1層的函數(shù)返回地址0xb7d9c006，在gdb中進(jìn)行反匯編：
(gdb) disass 0xb7d9c006
Dump of assembler code for function _ZNSt15basic_streambufIcSt11char_traitsIcEE6xsputnEPKci:
0xb7d9bfa0 <_ZNSt15basic_streambufIcSt11char_traitsIcEE6xsputnEPKci+0>: push ebp
0xb7d9bfa1 <_ZNSt15basic_streambufIcSt11char_traitsIcEE6xsputnEPKci+1>: mov ebp,esp
0xb7d9bfa3 <_ZNSt15basic_streambufIcSt11char_traitsIcEE6xsputnEPKci+3>: push edi
0xb7d9bfa4 <_ZNSt15basic_streambufIcSt11char_traitsIcEE6xsputnEPKci+4>: push esi
0xb7d9bfa5 <_ZNSt15basic_streambufIcSt11char_traitsIcEE6xsputnEPKci+5>: push ebx
0xb7d9bfa6 <_ZNSt15basic_streambufIcSt11char_traitsIcEE6xsputnEPKci+6>: sub esp,0x2c
0xb7d9bfa9 <_ZNSt15basic_streambufIcSt11char_traitsIcEE6xsputnEPKci+9>: mov eax,DWORD PTR [ebp+16]
......
我們可以看到，gdb打印出了調(diào)用棧中第1層的函數(shù)的C++名稱經(jīng)過(guò)編碼后所對(duì)應(yīng)的C名稱字符串為“_ZNSt15basic_streambufIcSt11char_traitsIcEE6xsputnEPKci”，這個(gè)C名稱與其對(duì)應(yīng)的C++名稱“std::basic_streambuf<char, std::char_traits<char> >::xsputn”是等價(jià)的。接下來(lái)，我們啟動(dòng)一個(gè)新的gdb程序，并在gdb中加載應(yīng)用程序文件，在啟動(dòng)應(yīng)用程序運(yùn)行之前，先設(shè)置斷點(diǎn)：
(gdb) break _ZNSt15basic_streambufIcSt11char_traitsIcEE6xsputnEPKci
這就是要在前述的調(diào)用棧的第1層函數(shù)入口處設(shè)置斷點(diǎn)。然后我們啟動(dòng)應(yīng)用程序的執(zhí)行并激活日志輸出操作，當(dāng)?shù)谝粭l日志輸出時(shí)，剛才所設(shè)斷點(diǎn)就激活了，gdb將中斷程序的執(zhí)行，此時(shí)我們打印調(diào)用棧，gdb將輸出與前述類似的調(diào)用棧，此時(shí)我們可以輕松地從調(diào)用棧中取得ofstream<>對(duì)象的首地址。我們將這個(gè)地址加上偏移量0x18，就得到了我們要監(jiān)視的內(nèi)存地址。在我們的應(yīng)用程序中計(jì)算得到的地址是0x80521e0。
有了要監(jiān)視的內(nèi)存地址以后，我們就可以在gdb里設(shè)置“內(nèi)存寫”斷點(diǎn)了，輸入如下命令：
(gdb) watch *(int *)0x80521e0
Hardware watchpoint 1: *(int *) 134554080
這表明一個(gè)“內(nèi)存寫”斷點(diǎn)設(shè)置成功。接下來(lái)讓gdb執(zhí)行c命令繼續(xù)執(zhí)行應(yīng)用程序，就可以開始監(jiān)視basic_filebuf<>對(duì)象的M_out_cur成員何時(shí)被修改成NULL了。當(dāng)斷點(diǎn)激活時(shí)，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
此時(shí)打印調(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
此時(shí)，我們終于有了重大發(fā)現(xiàn)！原來(lái)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);
.....
}
.....
}
可以看到，對(duì)ostream<>::tellp()方法的調(diào)用居然會(huì)導(dǎo)致ofstream<>對(duì)象內(nèi)部的basic_streambuf<>對(duì)象成員的M_out_cur成員的值被修改為NULL！而ACE_Logging_Strategy::handle_timeout（）方法在調(diào)用ostream<>::tellp()方法時(shí)居然沒(méi)有先獲得鎖！知道這個(gè)根本原因了，問(wèn)題就好解決了，至于如何修改ACE_Logging_Strategy::handle_timeout（）的代碼，明眼人一看便知了。我們修改代碼后并進(jìn)行了長(zhǎng)期的壓力測(cè)試的驗(yàn)證，最后確認(rèn)了這就是問(wèn)題的根源。
這個(gè)問(wèn)題被解決后，我們查看了ACE最新版本5.6.2中的代碼，發(fā)現(xiàn)源碼中仍然存在此問(wèn)題。于是我們給ACE開發(fā)社區(qū)發(fā)了一個(gè)帖子：A bug about ACE_Logging_Strategy 來(lái)報(bào)告這個(gè)ACE中的bug，算是為ACE開發(fā)社區(qū)做個(gè)貢獻(xiàn)吧。
細(xì)細(xì)推敲起來(lái)，開發(fā)ACE的大牛們?yōu)槭裁磿?huì)犯這種有點(diǎn)低級(jí)的錯(cuò)誤呢？而且這么長(zhǎng)時(shí)間都沒(méi)有發(fā)現(xiàn)這個(gè)問(wèn)題？也許他們沒(méi)有進(jìn)行過(guò)像我們這么大壓力的長(zhǎng)期測(cè)試吧？也許他們也和我們當(dāng)初所認(rèn)為的一樣，以為ostream<>::tellp()即便不是一個(gè)const方法，也應(yīng)該是個(gè)“準(zhǔn)”const方法吧？然而事實(shí)卻并非如此。其實(shí)從C++程序員的角度來(lái)說(shuō)，我們的確需要一個(gè)const版本的ostream<>::tellp()接口，不知道將來(lái)C++標(biāo)準(zhǔn)會(huì)不會(huì)在這個(gè)問(wèn)題上有所改變。對(duì)于這個(gè)訴求，不只我們有，這里也有: why is ostream::tellp not const。