Possible g++ optimization bug?

[jaj2276]

Hi,

This is going to be a LONG post.

First some particulars:

CentOS release 6.6 (Final)
g++ (GCC) 4.4.7 20120313 (Red Hat 4.4.7-11)

We're seeing an issue that when viewing inside of gdb, makes me think the compiler is doing something wrong. The weird thing is this "something wrong" happens very infrequently which usually leads me to the conclusion that it's something in the code.

Basically we use this third-party software that delivers us an object. Inside the object is an ID that we then use as an index into an array. On our initial callback, the object has a valid id. When we pass the object (via reference) to another method, the object will very infrequently have a bad id.

Without further ado, the relevant code:

// We have a function pointer that will point to templated member function
class Foo
{
...
    template<uint16_t NBookDepth>
    inline void process(const SourceObject&);

private:
    void (Foo::*processFP)(const SourceObject&);
}

// This function gets called on initialization and we set our function pointer
// to the templated process() method using 5.
469 void Foo::updateFunctionPointers()
470 {
471     switch(_iMaxBookLevels)
472     {
473         ... source deleted
489         case 5:
490             ...
491             processFP = &Foo::process<5>;
492             break;
493         ... source deleted

// This is our callback from 3rd-party software
165 void Foo::onData( const SourceObject& bookSource )
166 {
167     ... deleted source
179 
180     (this->*this->processFP)(bookSource);
181 }

// this is the method that is pointed to by the function pointer
220 template<uint16_t NBookDepth>
221 void Foo::process(const SourceObject& bookSource)
222 {
223     const InstrumentID instr = bookSource.getInstrumentId();
224     ... source deleted ...
230         updateBook<NBookDepth>( instr, dataObj, true);

// this is the method that goes boom as instr is way outside of our array
242 template<uint16_t NBookDepth>
243 void Foo::updateBook( const InstrumentID& instr, const ThirdPartyObj& dataObj, bool bIsBid  )
244 {
264             ... source deleted ...
265             pDest = &_dataBlock.data_block.prices[instr][iLoop];
266             ... source deleted ...
271                 long someVar = pDest->price;

Now we get to the gdb info:

gdb) bt
#0  0x0000003eaee32925 in raise (sig=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:64
#1  0x0000003eaee34105 in abort () at abort.c:92
#2  0x00007fe73db6e155 in os::abort(bool) () from /opt/jdk1.7.0_45/jre/lib/amd64/server/libjvm.so
#3  0x00007fe73dced087 in VMError::report_and_die() () from /opt/jdk1.7.0_45/jre/lib/amd64/server/libjvm.so
#4  0x00007fe73db72adf in JVM_handle_linux_signal () from /opt/jdk1.7.0_45/jre/lib/amd64/server/libjvm.so
#5  0x00007fe73e42948b in citp_signal_run_app_handler (sig=<value optimized out>, info=<value optimized out>, context=<value optimized out>) at ../../../../../src/lib/transport/ip/signal.c:89
#6  0x00007fe73e4299b8 in citp_signal_run_now (signum=11, info=0x7fe6817e5bb0, context=0x7fe6817e5a80) at ../../../../../src/lib/transport/ip/signal.c:200
#7  citp_signal_intercept_3 (signum=11, info=0x7fe6817e5bb0, context=0x7fe6817e5a80) at ../../../../../src/lib/transport/ip/signal.c:231
#8  <signal handler called>
#9  NameSpace::Foo::updateBook<5u> (this=0x7fe73a658390, instr=@0x7fe6817e613c, bookData=..., bIsBid=true) at Source.cpp:271
#10 0x00007fe681a62626 in NameSpace::Foo::process<5u> (this=0x7fe73a658390, bookSource=<value optimized out>) at Source.cpp:230
#11 0x00007fe681a5c0c1 in NameSpace::Foo::onData (this=0x7fe73a658390, bookSource=...) at Foo.cpp:180

(gdb) frame 11
#11 0x00007fe681a5c0c1 in NameSpace::Foo::onData (this=0x7fe73a658390, bookSource=...) at Source.cpp:180
(gdb) print bookSource
$1 = (
    const std::map<int, NameSpace::Foo::SourceObj*, std::less<int>, std::allocator<std::pair<int const, NameSpace::Foo::SourceObj*> > >::SourceObj &) @0x7fe73a9d72d0: {<NameSpace3::BookSource<int, gsc_data_venue_e>> = {m_bookSourceManager = @0x7fe7386a3430, m_instrumentId = 14573, m_venueId = XXX_XXX, m_handle = 14247}, m_listener = @0x7fe73a658390, 
  m_notifyLevels = 5, m_started = true}
(gdb) info reg
rax            0x7fe55b196010   140623052627984
rbx            0x7fe73a658390   140631093904272
rcx            0x1779a6deb98    1613203631000
rdx            0x7fe6817e6070   140627991748720
rsi            0x7fe6817e613c   140627991748924
rdi            0x7fe73a658390   140631093904272
rbp            0x7fe73a9d72d0   0x7fe73a9d72d0
rsp            0x7fe6817e6170   0x7fe6817e6170
r8             0x0      0
r9             0x7fe6817e6070   140627991748720
r10            0x602788af       1613203631
r11            0x1779a6deb98    1613203631000
r12            0x7fe73868cac0   140631060564672
r13            0x38ed   14573
r14            0x0      0
r15            0x3      3
rip            0x7fe681a5c0c1   0x7fe681a5c0c1 <NameSpace::Foo::onData(std::map<int, NameSpace::Foo::SourceObject*, std::less<int>, std::allocator<std::pair<int const, NameSpace::Foo::SourceObject*> > >::SourceObject const&)+81>
eflags         0x202    [ IF ]
cs             0x33     51
ss             0x2b     43
ds             0x0      0
es             0x0      0
fs             0x0      0
gs             0x0      0


(gdb) frame 10
#10 0x00007fe681a62626 in NameSpace::Foo::process<5u> (this=0x7fe73a658390, bookSource=<value optimized out>) at Source.cpp:230
230     in Source.cpp

(gdb) print bookSource
$2 = <value optimized out>

(gdb) info locals
instr = 1613203631
... other local vars deleted ...

(gdb) info reg
rax            0x7fe55b196010   140623052627984
rbx            0x7fe73a658390   140631093904272
rcx            0x1779a6deb98    1613203631000
rdx            0x7fe6817e6070   140627991748720
rsi            0x7fe6817e613c   140627991748924
rdi            0x7fe73a658390   140631093904272
rbp            0x7fe6817e60d0   0x7fe6817e60d0
rsp            0x7fe6817e6070   0x7fe6817e6070
r8             0x0      0
r9             0x7fe6817e6070   140627991748720
r10            0x602788af       1613203631
r11            0x1779a6deb98    1613203631000
r12            0x7fe73a658390   140631093904272
r13            0x7fe6817e613c   140627991748924
r14            0x0      0
r15            0x3      3
rip            0x7fe681a62626   0x7fe681a62626 <NameSpace::Foo::processQuotes<5u>(std::map<int, NameSpace::Foo::SourceObj*, std::less<int>, std::allocator<std::pair<int const, NameSpace::Foo::SourceObj*> > >::SourceObj const&)+102>
eflags         0x202    [ IF ]
cs             0x33     51
ss             0x2b     43
ds             0x0      0
es             0x0      0
fs             0x0      0
gs             0x0      0

[jaj2276]

Apologies for the formatting, I'll edit the post to try and format it correctly.

Here are the questions:

In frame 11, which is the 3rd party calling our callback, if I print out the argument bookSource, I can clearly see that the instrument id is 14573 (this is m_instrumentId). I can even see that value in register r13.

In frame 10, which is simply the method that is called from within onData and takes a reference to that same bookSource object, the argument bookSource has been optimized away.

Question #1: Is there any way to inspect bookSource?

Within frame 10, we create a local variable called instr and call bookSource.getInstrumentId(). This getter method is defined in the header and simply returns m_instrumentId. At this point, the value is 1613203631 which is the invalid value. Furthermore, that same value is contained in register r10 (in both frame 10 and frame 11).

Question #2: Is there any way to figure out how we're getting this invalid value? This happens maybe once out of 4 million calls so I know the code "works."

Let me know if there's any information I can provide. The only thing I can think of is to maybe change the signature of the function pointer to take both a SourceObj reference and an InstrumentID value (which is simply an int32_t) and see if that solves the problem.

I really want to inspect bookSource once we're in frame 10 to see if it contains a good value for m_instrumentId or of it's value has been corrupted somehow.

[Peter87]

I don't think there is a way to read a value when gdb says it has been optimized out because it means the value doesn't exist in the program. You could try turning off compiler optimizations but that might not trigger the bug.

Is this callback function called from another thread? If there are more than one thread running at the same time you need to synchronize the threads properly.

[jaj2276]

Pretty much everywhere I've read that asks about optimized variables states that you can't inspect the variables in gdb. I thought I'd ask again just in case something has changed. I'm afraid to compile without optimizations because this is pretty important (and oft-called) code. Significant delays due to no optimizations would be quite harmful.

No thread synchronization issues are in play (at least in our code). We're using the 3rd party software as required and introduce no additional threads.

Thanks for your answers.