boost::this_thread::sleep either returns instantaneously or spins

[Jamie Allsop]

From the docs I'd expect to be able to write this:

std::cout
    << "Time Before Sleep: "
    << boost::posix_time::microsec_clock::local_time()
    << std::endl;

boost::this_thread::sleep( boost::posix_time::seconds(10) );

std::cout
    << "Time After Sleep : "
    << boost::posix_time::microsec_clock::local_time()
    << std::endl;

and have the 'this' thread sleep for approximately 10 seconds. Instead sleep returns instantaneously:

Time Before Sleep: 2010-Dec-25 01:38:50.949160000
Time After Sleep : 2010-Dec-25 01:38:50.949436000

I've tried this with boost 1.45 and boost 1.43 using gcc 4.4 on debian x86_64. This used to work for me on 32-bit debian unstable using gcc 4.3.

In addition to sleep returning instantaneously (happens every time) I have observed with more complex scenarios involving multiple threads sleep enter a busy spin, never returning (process needs killed). I am trying to create a minimal test case for this.

Rather obviously the code where this hits is here in source:/boost/tags/release/Boost_1_45_0/libs/thread/src/pthread/thread.cpp

        void sleep(const system_time& st)
        {
            detail::thread_data_base* const thread_info=detail::get_current_thread_data();
        
            if(thread_info)
            {
                unique_lock<mutex> lk(thread_info->sleep_mutex);
                while(thread_info->sleep_condition.timed_wait(lk,st));
            }
            else
            {
                xtime const xt=get_xtime(st);
            
                for (int foo=0; foo < 5; ++foo)
                {
#   if defined(BOOST_HAS_PTHREAD_DELAY_NP)
                    timespec ts;
                    to_timespec_duration(xt, ts);
                    BOOST_VERIFY(!pthread_delay_np(&ts));
#   elif defined(BOOST_HAS_NANOSLEEP)
                    timespec ts;
                    to_timespec_duration(xt, ts);
                
                    //  nanosleep takes a timespec that is an offset, not
                    //  an absolute time.
                    nanosleep(&ts, 0);
#   else
                    mutex mx;
                    mutex::scoped_lock lock(mx);
                    condition cond;
                    cond.timed_wait(lock, xt);
#   endif
                    xtime cur;
                    xtime_get(&cur, TIME_UTC);
                    if (xtime_cmp(xt, cur) <= 0)
                        return;
                }
            }
        }

Specifically something appears to go wrong here:

            if(thread_info)
            {
                unique_lock<mutex> lk(thread_info->sleep_mutex);
                while(thread_info->sleep_condition.timed_wait(lk,st));
            }

I came across this while writing a test for something else and so have not been able to follow up in any more detail yet at this time.

[Jamie Allsop <ja11sop@…>]

When I see the 'spinning' I can grab the following back trace - which doesn't say much but points to the issue being in the timed_wait(), see frame 3.

#0  0x00007ffff7bcbf05 in __pthread_mutex_lock (mutex=0xcf8d00) at pthread_mutex_lock.c:61
#1  0x00000000008bc1c5 in boost::mutex::lock (this=0xcf8d00)
    at /thirdparty/boost/boost_1_45/source/boost/thread/pthread/mutex.hpp:52
#2  0x00000000009d3d76 in boost::unique_lock<boost::mutex>::lock() ()
#3  0x00000000009f3bf9 in boost::condition_variable::timed_wait(boost::unique_lock<boost::mutex>&, boost::posix_time::ptime const&) ()
#4  0x00000000009f2b86 in boost::this_thread::sleep(boost::posix_time::ptime const&) ()
#5  0x00000000008e68a1 in boost::this_thread::sleep<boost::posix_time::seconds> (rel_time=...)
    at /thirdparty/boost/boost_1_45/source/boost/thread/pthread/thread_data.hpp:138

I still don't have a small enough test case to post but thought at least the back trace would help. To summarise then it seems that there is an issue with the timed_wait(). Either I see it return immediately or spin.

It should also be noted that the call to boost::this_thread::sleep() occurs once only in a single thread, in my case the main thread.

[Jamie Allsop <ja11sop@…>]

I should add here that I tried this with a debug build of boost thread and could not get any better back trace. I also suspect this is a 64-bit only problem since others have reported no issues on 32-bit builds.

[Anthony Williams]

I cannot reproduce this problem on 64-bit Ubuntu 10.10

[anonymous]

Similar problem was described here ​http://lists.boost.org/boost-users/2010/10/63635.php I can reproduce it easily on Linux.

[Jamie Allsop <ja11sop@…>]

Can you be more specific about how you reproduce this on Linux? What compile flags you use and on what distribution and architecture? I think this ticket clearly needs re-opened.

[storm@…]

I see the same exact problem on ubuntu 32bit, on virtualbox (mac host), but it happens ONLY when I run the program in gdb.

Spawning 4 thread, each one cycling and sleeping for up to one second between any cycle, I always get 1 or 2 threads that never exit from the sleep.

Part of code:

	...
	cout << "Updater started with id " << boost::this_thread::get_id() << endl;

	while (true) {

		/* do things */
		// Throttle
		elapsed = boost::posix_time::microsec_clock::universal_time() - this->last_update;
		sleep_for = interval - elapsed;
		cout << boost::this_thread::get_id() << " sleeping for " << sleep_for << endl;
		boost::this_thread::sleep(sleep_for);
		cout << boost::this_thread::get_id() << " sleeped for " << sleep_for << endl;
	}
	...

I get on console:

Updater started with id 0x8090198
Updater started with id 0x8090810
0x8090198 sleeping for 0x8090810 sleeping for 00:00:00.998689
00:00:00.997377
Updater started with id 0x8090fb0
0x8090fb0 sleeping for 00:00:00.998187
Updater started with id 0x8091378
0x8091378 sleeping for 00:00:00.998543
0x8090198 sleeped for 00:00:00.997377
0x8090198 sleeping for 00:00:00.999980
0x8090810 sleeped for 00:00:00.998689
0x8090810 sleeping for 00:00:00.999979
0x8091378 sleeped for 00:00:00.998543
0x8091378 sleeping for 00:00:00.999979
0x8090198 sleeped for 00:00:00.999980
0x8090198 sleeping for 00:00:00.999948
0x8090810 sleeped for 00:00:00.999979
0x8090810 sleeping for 00:00:00.999951
0x8091378 sleeped for 00:00:00.999979
0x8091378 sleeping for 00:00:00.999958

( 0x8090fb0 is blocked )

[anonymous]

I think this thread: ​http://lists.boost.org/boost-users/2011/07/69287.php may also describe behaviour that is indirectly related to this issue.