A funny bug with Visual Studio 2012
A few months ago, I was working on a project of which the architecture looks like :
APP ( running on tablet/mobile ) instructs the Device (has internet access capability) to do some job.
All APP and Devices register to a local service Router (actually two Router instances to avoid single point of failure) which runs on local PC.
The Router routes commands and responses between the APPs and Devices, and also collects debug logs from Device.
(Actually this design did not go into production as we switched to a full cloud based solution and thus the local Router node was no longer necessary)
At first, When I did a few times (or just one time) of testing with Router release build, I noticed a few times of more logs (logs from Device) than the debug build. I did not go into it.
One day when I did a demo test to a colleague of another team, some previously sent command was resent to the the Device, which caused the chaos of the processing (besides massive log volume). Time to get to the bottom of it.
I disabled the trace of the Device, and saw all previously sent commands got resent together with the current command,
i.e. When the Nth command was sent from APP to the Router, (N-1) previously messages got replay. Looks like all messages keeps cached in the Router and does not get deleted.
What’s weird is, this problem does not exist in the debug build, which I mostly tested on.
After adding some logs, I saw one std::stringstream data variable does not delete the already processed messages and the size kept growing.
In the release build, the code block enclosed in the if condition ( if( last_pos != std::string::npos ) ) , which deletes already processed messages, does not get execute at all (the code has been simplified to illustrate the bug only):
------------------------------------------------------
string buffer("header");
size_t start = 0;
size_t pos = buffer.find( 'e' );
size_t last_pos = std::string::npos;
while( pos != std::string::npos )
{
pos += 1;
last_pos = pos;
start = pos;
pos = buffer.find( 'e' , start);
}
if( last_pos != std::string::npos )
{
/// deletes already processed messages from the std::stringstream data variable
------------------------------------------------------
A little bit unbelievable that the code in release build gets logically wrong behaviour, while debug build not.
Looking at the disassembly, it explains.
Disassembly of release build:
------------------------------------------------------
size_t last_pos = std::string::npos;
while( pos != std::string::npos )
012E135A cmp eax,0FFFFFFFFh
012E135D jne wmain+90h (012E1300h)
last_pos = pos;
012E135F mov dword ptr [esp+14h],eax
}
if( last_pos != std::string::npos )
012E1363 cmp eax,eax
012E1365 je wmain+105h (012E1375h)
{
cout << "It compiles correctly! last_pos="<<last_pos << endl;
---------------------------------------------------------
Looks like the Visual Studio 2012 compiler thought last_pos always equals to pos , thus eliminate last_pos to reduce redundancy. While pos is always std:: string::npos when getting out of the while loop, so the if condition is always not satisfied.
When I disable the optimization (the optimization of release build was set to Maximize Speed (/O2) by default, for debug build the optimization is disabled by default), the code generated looks good (last_pos and pos are distinct).
It looks like it’s a bug with Visual Studio 2012’s code optimization, setting the Optimization to Disabled (/Od) or Minimize Size (/O1) can work around it.
BTW. I did a quick test with VS2010, it does not has this problem.
I reported the bug to Microsoft and it had been confirmed by Microsoft Visual C++ Team. It would be fixed in VS 2013 RTM:
http://connect.microsoft.com/VisualStudio/feedback/details/796248/a-bug-with-c-compiler-optimization-while-loop-visual-studio-2012