/************************************
* 版权声明
* 本文为本人原创,本人拥有此文的版权。鉴于本人持续受益于开源软件社区,
* 本人声明:任何个人及团体均可不受限制的转载和复制本文,无论是否用于盈利
* 之目的,但必须在转载及复制时同时保留本版权声明,否则为侵权行为,本人保
* 留追究相应法律责任之权利。
* speng2005@gmail.com
* 2007-12
************************************/
近日在使用ACE进行开发的工作中遇到一个导致程序崩溃的问题。我们是在Linux平台上使用ACE 5.5.1以及g++ 4.1.2进行开发的。
问题是这样的:我们的程序中有多个线程并发调用ACE_Log_Msg::log()方法进行日志输出操作,这些日志将被输出到同一个位于本地磁盘上的日志文件中。但为防止日志文件长度增长过大,我们使用了ACE_Logging_Strategy类来进行定时的日志文件大小检查和文件切换。这种方式在一般情况下运行良好,但是在大规模压力测试中,程序常常因访问非法内存而崩溃。发生崩溃时的调用栈总是这样的:
(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 因为多次崩溃的调用栈都一样,这说明这个问题是一个比较确定的可再现bug,这为找到问题原因并最后解决提供了有利条件。
问题出现后,我们首先定位问题的原因与应用程序的日志输出有关系。经过代码复查,没有发现这方面的任何问题。接下来,我们只好怀疑ACE的日志相关类的源码存在问题。我们又彻底阅读了与日志输出有关的类的源代码:ACE_Log_Msg,ACE_Log_Record,ACE_Logging_Strategy,包括
ACE_Logging_Strategy::handle_timeout()方法的实现代码,重点关注代码中关于内存操作和多线程安全互斥的操作,依然没有发现可疑的地方。这下问题就复杂了,总不能怀疑C++标准库的流类库有问题吧?这不太可能,但是问题的直接爆发点是出在C++标准库里的,所以只能从标准库出发寻找线索。有过一定程序开发尤其是c/c++程序开发经验的人都知道,一些复杂问题直接暴露出来的现象都是问题的表象,根本的原因可能跟表象差的很远,但是顺着表象提供的线索去寻找根源毕竟是解决问题的正道。于是我们开始从程序崩溃点寻找问题的症结。
首先,我们分析程序为什么在调用memcpy()这个标准c的库函数时发生崩溃的。没有源代码,怎么分析?学一点汇编语言的基础知识吧,这是对一个资深程序员的必要的技术要求。在gdb里使用如下命令:
(gdb) set disassembly-flavor intel(gdb) disassgdb就给出了memcpy()函数的汇编指令:
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精确地告诉我们程序是在执行“movs WORD PTR es:[edi],WORD PTR ds:[esi]”指令时发生了错误,操作系统产生了“signal 11, Segmentation fault”信号,也就是说程序访问了非法的内存地址。我们观察movs指令,很有可能edi寄存器中的地址是非法的,于是在gdb中输入命令:
(gdb) p/x $edigdb就打印出:
$2 = 0x0这就证明的确是因为edi寄存器被赋予了NULL指针导致问题的出现的。有经验的程序员立刻可以意识到进一步的问题症结是调用栈中的上层函数向memcpy()传递了错误的目标地址参数进而导致程序崩溃的。观察调用栈,位于memcpy()之上的3层函数都是C++标准库的流操作。我想绝大多数程序员都是只知道怎么正确使用标准流类库,而未研究过其是如何实现的吧?我们也是。但如果要解决问题,就必须弄清楚其内部实现。好在标准流类库都是模板实现,有源码可读。不读不知道,标准流类库的实现代码还是很复杂的,晦涩难懂。可是我们也不是无目的的阅读全部代码,我们的近期目标是找到传递给memcpy()的指针是从哪来的,以及这个地址是如何被设成NULL的。我们找到最直接调用memcpy()的C++标准库源码(看起来在这里我只写了一句话,但是的确费了很多脑细胞才确定这里的源代码跟调用栈里显示的那些被调用的函数是同一个版本的,确定这一点很重要):
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()函数的调用语句。根据前面的分析,我们知道出问题的时候“
this->pptr()”必然返回了NULL,所以memcpy()执行时才会出错。“this->pptr()”是内联方法:
char_type* pptr() const { return _M_out_cur; }这也就是说出问题的时候basic_streambuf<>对象的
_M_out_cur成员被设成了NULL,所以才会引发连锁反应。似乎我们快要找到问题根源了,但是,问题没这么简单。因为我们分析了上面的basic_streambuf<>::xsputn()源码,发现只有__buf_len大于0的时候程序才可能会走到memcpy()函数调用中,而在我们的程序出问题的时候,“this->epptr()”居然返回的也是NULL!
“this->epptr()”也是内联方法:
char_type* epptr() const { return _M_out_end; }这也就是说出问题的时候basic_streambuf<>对象的
_M_out_end成员也被设成了NULL。这个时候计算得到的__buf_len值应该等于0,但程序怎么会进入到对memcpy()函数的调用中呢?对此我们百思不得其解,但有一个信念:CPU保证会按程序的机器指令代码行事,不会乱来的
。于是,
我们分析在我们的应用程序是多线程的情形下,合理解释只能是:当前线程执行到__buf_len的计算的代码时返回的长度还是大于0的,于是会有后来的对
memcpy()的调用;而同时可能有另外一个未做多线程同步的线程却修改了“this->pptr()”及“this->epptr()
”对应的指针值为NULL,这样当前线程执行到memcpy()时就会出错。分析到此,我们又有了新方向。下一步的目标就是确定哪个线程中的什么地方的代码有可能会将basic_streambuf<>对象的
_M_out_cur成员及_M_out_end成员设成NULL。说起来容易做起来难啊!我们阅读了大量源代码,隐约发现有数个地方可能会修改_M_out_cur成员值为NULL,但细细推敲起来都不应该导致出现上述问题。我们陷入僵局了。
所以我这里再次强调,一个资深的c/c++程序员应该懂得一些汇编语言的基础知识并掌握至少一个汇编调试器的使用技巧。在这里,gdb就够用了。因为gdb支持“内存读写断点”的设置。内存读写断点是CPU为调试软件设置的专用中断器,它能够监视指定的内存段范围内是否有内存读,或内存写,或内存读写操作,如果有则产生中断,并由调试器接管程序的执行。在gdb里就可以设置这样的断点来监视basic_streambuf<>对象的
_M_out_cur成员的值何时被修改,从而使我们知道在哪个线程执行到哪个函数时修改了_M_out_cur成员的值,以便我们分析导致程序崩溃问题的根源。但困难在于,设置这样的断点时需要指定一个内存地址,也就是我们要监视的basic_streambuf<>对象的
_M_out_cur成员的内存地址,这个如何确定呢?
还是汇编!在我们的应用程序中,寻找_M_out_cur成员的内存地址的思路是这样的:我们观察前面给出的调用栈,可以看到在第4层函数ACE_Log_Record::print()中的最后一个参数的是"s=@0x80521c8",结合ACE源码知道参数s的类型是ostream<> &,这其实就是告诉我们一个ostream<>对象的地址在0x80521c8。
而实际上这个ostream<>对象的子类型就是ofstream<>,也就是说在我们的应用程序中多个线程操作着地址在0x80521c8的同一个ofstream<>对象进行日志输出操作
。阅读C++标准库源码我们知道,如果知道了一个ofstream<>对象的首地址,就可以计算其_M_filebuf对象成员的首地址,该成员的类型为basic_filebuf<>;知道了一个basic_filebuf<>对象的首地址,就可以知道其继承自基类basic_streambuf<>的
M_out_cur成员的地址了。这些地址的计算都是根据一个原理:对象的每个成员的首地址相对于该对象的首地址的偏移量是一个在编译期就确定的常量,对象的首地址加上这个特定的偏移量而得到的值就是对应成员的首地址。那么这些偏移量具体数值如何知道?汇编吧!我们写了一个简单的测试程序专门用于获取我们所关心的两个偏移量的数值。测试程序是这样的:
#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;
}
经过一翻外科手术式的剖析,我们找到了这两个偏移量的数值(虽然这里只写了一句话,但这绝不仅仅是一句话),并且弄清楚了一个ofstream<>对象的各个成员在内存中的布局(仅在g++ 4.1.2编译的目标代码中进行了验证)。如果一个ofstream<>对象的首地址在0x8049240,则此对象的内存布局为:
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开始的内存就是ofstream<>对象所聚合的basic_filebuf<>对象成员_M_filebuf的内存映像;而
0x00000000就是该_M_filebuf对象的
M_out_cur成员的内存映像,也就是说我们可以直接根据ofstream<>对象的首地址然后加上偏移量0x18而得到
M_out_cur成员的内存地址。关于ofstream<>对象及basic_filebuf<>对象在内存中的布局我们还研究了更多的东西。例如,
0xb7f6a9cc所指向的地址就是ofstream<>类的虚拟函数表的首地址;
0xb7f6aac8所指向的地址就是basic_filebuf<>类的虚拟函数表的首地址;
0x00000030就是basic_filebuf<>类的_M_mode成员的值,其值等价于(ios_base::out | ios_base::trunc);
0x0804a170所指向的地址就是basic_filebuf<>对象内部的一个真正内部缓冲区的首地址,对应于该对象的_M_buf成员;
0x00002000则指出这个缓冲区的长度是8192字节,对应于该对象的_M_buf_size成员。
有了上面得到的内存地址计算方法,下一步就是在我们的应用程序中获得ofstream<>对象的首地址了。这有很多方法,我们可以直接在gdb中找到ACE_Log_Msg::log()方法的源码并设置断点,然后启动程序,待断点激活后,在gdb中打印调用栈而取得ofstream<>对象的首地址。这里我们使用了另外一种方法:我们根据前面给出的调用栈中的第1层的函数返回地址
0xb7d9c006,在gdb中进行反汇编:
(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打印出了调用栈中第1层的函数的C++名称经过编码后所对应的C名称字符串为“_ZNSt15basic_streambufIcSt11char_traitsIcEE6xsputnEPKci”,这个C名称与其对应的C++名称“
std::basic_streambuf<char, std::char_traits<char> >::xsputn”是等价的。接下来,我们启动一个新的gdb程序,并在gdb中加载应用程序文件,在启动应用程序运行之前,先设置断点:
(gdb) break _ZNSt15basic_streambufIcSt11char_traitsIcEE6xsputnEPKci这就是要在前述的调用栈的第1层函数入口处设置断点。然后我们启动应用程序的执行并激活日志输出操作,当第一条日志输出时,刚才所设断点就激活了,gdb将中断程序的执行,此时我们打印调用栈,gdb将输出与前述类似的调用栈,此时我们可以轻松地从调用栈中取得ofstream<>对象的首地址。我们将这个地址加上偏移量0x18,就得到了我们要监视的内存地址。在我们的应用程序中计算得到的地址是0x80521e0。
有了要监视的内存地址以后,我们就可以在gdb里设置“内存写”断点了,输入如下命令:
(gdb) watch *(int *)0x80521e0Hardware watchpoint 1: *(int *) 134554080这表明一个“内存写”断点设置成功。接下来让gdb执行c命令继续执行应用程序,就可以开始监视basic_filebuf<>对象的
M_out_cur成员何时被修改成NULL了。当断点激活时,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
此时打印调用栈,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
此时,我们终于有了重大发现!原来ACE_Logging_Strategy::handle_timeout()方法中执行了如下代码:
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()方法的调用居然会导致ofstream<>对象内部的basic_streambuf<>对象成员的
M_out_cur成员的值被修改
为NULL!而ACE_Logging_Strategy::handle_timeout()方法在调用ostream<>::tellp()方法时居然没有先获得锁!知道这个根本原因了,问题就好解决了,至于如何修改
ACE_Logging_Strategy::handle_timeout()的代码,明眼人一看便知了。我们修改代码后并进行了长期的压力测试的验证,最后确认了这就是问题的根源。
这个问题被解决后,我们查看了ACE最新版本5.6.2中的代码,发现源码中仍然存在此问题。于是我们给ACE开发社区发了一个帖子:
A bug about ACE_Logging_Strategy 来报告这个ACE中的bug,算是为ACE开发社区做个贡献吧。
细细推敲起来,开发ACE的大牛们为什么会犯这种有点低级的错误呢?而且这么长时间都没有发现这个问题?也许他们没有进行过像我们这么大压力的长期测试吧?也许他们也和我们当初所认为的一样,以为ostream<>::tellp()即便不是一个const方法,也应该是个“准”const方法吧?然而事实却并非如此。其实从C++程序员的角度来说,我们的确需要一个const版本的ostream<>::tellp()接口,不知道将来C++标准会不会在这个问题上有所改变。对于这个诉求,不只我们有,这里也有:
why is ostream::tellp not const。