[Boost-users] boost asio: Crash on timer.expires_from_now only with specific MSVC settings (whole program optimization)

Subject: [Boost-users] boost asio: Crash on timer.expires_from_now only with specific MSVC settings (whole program optimization)
From: Florian Burkart (florian.burkart_at_[hidden])
Date: 2011-12-12 09:49:01

Hi,

I am currently struggling with a crash that I find very hard to isolate.
Please see attached three classes I am using (the one not included is
FlamTimeMillis, but that is basically just my own time class).

In any case, LiveTimer works absolutely fine in my unit tests. It works
absolutely fine in both debug and regular release versions. However, when
compiled under msvc with compile options /Ox /Oi /Ot /GL and linked with
/LTCG (e.g. whole program optimization), it crashes. But only in my main
program, and not in any test I try to create. But in the main program, it
consistently crashes.

According to the logs, it crashes between 3 and 4, e.g. the log looks like
this:

IN: : LiveTimer: RegisterTimedCallback 2011-12-12 07:02:00.000000: Locked
mutex.
IN: : LiveTimer: Expires from now -22405.5 A: 2011-12-12 07:02:00.000000 B:
2011-12-12 13:15:25.489000 C: -2.24055e+007
IN: : 1
IN: : 2
IN: : 3

This happens on the very first call to RegisterTimedCallback. Judging from
it, it looks like it crashes
on timer.expires_from_now(boost::posix_time::seconds((long)secondsToElapse)).
I checked that I am in the correct LiveTimer, and that LiveTimer still
exists. I tried loading the dump file into WinDbg, and I get the following
output:

XCEPTION_RECORD:  ffffffff -- (.exr 0xffffffffffffffff)
ExceptionAddress: 77b68da9 (ntdll!RtlpWaitOnCriticalSection+0x000000bd)
   ExceptionCode: c0000005 (Access violation)
  ExceptionFlags: 00000000
NumberParameters: 2
   Parameter[0]: 00000001
   Parameter[1]: 00000114
Attempt to write to address 00000114

PROCESS_NAME:  Test.exe

ERROR_CODE: (NTSTATUS) 0xc0000005 - The instruction at 0x%08lx referenced
memory at 0x%08lx. The memory could not be %s.

EXCEPTION_CODE: (NTSTATUS) 0xc0000005 - The instruction at 0x%08lx
referenced memory at 0x%08lx. The memory could not be %s.

EXCEPTION_PARAMETER1:  00000001

EXCEPTION_PARAMETER2:  00000114

WRITE_ADDRESS:  00000114

FOLLOWUP_IP:
Test!boost::asio::detail::win_iocp_io_service::cancel_timer<boost::asio::time_traits<boost::posix_time::ptime>
>+4c [c:\program files
(x86)\boost_1_47_0\boost\asio\detail\impl\win_iocp_io_service.hpp @ 117]
0139784c b001            mov     al,1

MOD_LIST: <ANALYSIS/>

NTGLOBALFLAG:  0

APPLICATION_VERIFIER_FLAGS:  0

FAULTING_THREAD:  000029b8

BUGCHECK_STR:
 APPLICATION_FAULT_NULL_CLASS_PTR_DEREFERENCE_INVALID_POINTER_WRITE

PRIMARY_PROBLEM_CLASS:  NULL_CLASS_PTR_DEREFERENCE

DEFAULT_BUCKET_ID:  NULL_CLASS_PTR_DEREFERENCE

LAST_CONTROL_TRANSFER:  from 77b68cb8 to 77b68da9

STACK_TEXT:
0032ec44 77b68cb8 00000000 00000000 00000000
ntdll!RtlpWaitOnCriticalSection+0xbd
0032ec6c 0139784c 00953408 654f7f27 0032ecf0
ntdll!RtlEnterCriticalSection+0x150
0032ecac 0139e79a 0095015c 0032f93c ffffffff
Test!boost::asio::detail::win_iocp_io_service::cancel_timer<boost::asio::time_traits<boost::posix_time::ptime>
>+0x4c [c:\program files
(x86)\boost_1_47_0\boost\asio\detail\impl\win_iocp_io_service.hpp @ 117]
0032ecdc 013d9d20 0095015c 0032ed38 00000000
Test!boost::asio::detail::deadline_timer_service<boost::asio::time_traits<boost::posix_time::ptime>
>::expires_from_now+0x6a [c:\program files
(x86)\boost_1_47_0\boost\asio\detail\deadline_timer_service.hpp @ 159]
0032ecfc 013d948f 0032ed28 654f7e57 0095716c
Test!boost::asio::basic_deadline_timer<boost::posix_time::ptime,boost::asio::time_traits<boost::posix_time::ptime>,boost::asio::deadline_timer_service<boost::posix_time::ptime,boost::asio::time_traits<boost::posix_time::ptime>
> >::expires_from_now+0x30 [c:\program files
(x86)\boost_1_47_0\boost\asio\basic_deadline_timer.hpp @ 411]
0032ede0 013b1840 0032f900 00950188 0094f970
Test!Flam::Live::LiveTimer::EnqueueTimedCallback+0x33f
[c:\users\florian\documents\liveenvv1\trunk\flamlib\live\livetimer.cpp @ 55]

STACK_COMMAND:  ~0s; .ecxr ; kb

FAULTING_SOURCE_CODE:
   113:   // If the service has been shut down we silently ignore the
cancellation.
   114:   if (::InterlockedExchangeAdd(&shutdown_, 0) != 0)
   115:     return 0;
   116:
>  117:   mutex::scoped_lock lock(dispatch_mutex_);
   118:   op_queue<win_iocp_operation> ops;
   119:   std::size_t n = queue.cancel_timer(timer, ops, max_cancelled);
   120:   post_deferred_completions(ops);
   121:   return n;
   122: }

SYMBOL_STACK_INDEX:  2

SYMBOL_NAME:
 Test!boost::asio::detail::win_iocp_io_service::cancel_timer<boost::asio::time_traits<boost::posix_time::ptime>
>+4c

The source quoted is from
\boost_1_47_0\boost\asio\detail\impl\win_iocp_io_service.hpp.

Despite the fact that I can't isolate the error, everything I look at
points to a problem somewhere within boost asio, or me not using asio
correctly. Anyone any suggestions as to where to go from here? Would be
much appreciated. What looks a bit suspicious to me (but that might be
entirely wrong), is the line "// If the service has been shut down we
silently ignore the cancellation.," because the error happens after the
return statement linked to that comment was apparently not executed, and
the service has actually been shut down.

P.S. I know that I don't need to manage the queue myself and could just let
asio handle it, however, eventually I would like to manage the queue more
(e.g. edit some timers, cancel others, so I'd prefer to stick to a single
timer and manage the queue myself).