Help with understanding throttle.finish()

Help with understanding throttle.finish()

[Willem Jan Withagen]

Hi,

I'm running a rather simple setup on my FreeBSD port.

function TEST_simple() {
     # run the most simple config, and run a bechmark on it.
     local dir=$1

     run_mon $dir a || return 1
     run_osd $dir 0 || return 1

     #
     # default values should work
     #
     ceph tell osd.0 bench || return 1

}

This in the end crashes with:
     8059eec00 -1 FileStore: sync_entry timed out after 600 seconds.
exactly 10 minutes after startup.
This trhread does just about exactly nothing, it initialises the time, 
and then traps after 10 minutes.
# grep 8059eec00  testdir/osd-bench/osd.0.log
2016-04-28 19:51:44.444689 8059eec00 -1 FileStore: sync_entry timed out 
after 600 seconds.
2016-04-28 19:51:44.487104 8059eec00 -1 os/filestore/FileStore.cc: In 
function 'virtual void SyncEntryTimeout::finish(int)' thread 8059eec00 time

I've augmented just about every line of code in src/os/filestore/File*.cc

And I get as far as
	throttle.flush()
It seems to work the first time it gets called. That is, it returns.

However the second time is "stalls" in the call
	 throttle.put(to_put_bytes);
after a number of itterations thru the while-loop.

Below the code of Throttle::Flush and an sequence of the thread doing 
the blocking call
from the log where I've added mode debugging code.

Does anybody have a clue as to continue from here?
   Why does throttle.put not return?
   Is it just throttleing too hard and not reorganising the queue?

--WjW

Code:
std::pair<uint64_t, uint64_t> JournalThrottle::flush(uint64_t mono_id)
{
   uint64_t to_put_bytes = 0;
   uint64_t to_put_ops = 0;
   std::pair<uint64_t, uint64_t> ret;
   {
     locker l(lock);
     while (!journaled_ops.empty() &&
            journaled_ops.front().first <= mono_id) {
       to_put_bytes += journaled_ops.front().second;
       to_put_ops++;
       journaled_ops.pop_front();
     }
   }
   throttle.put(to_put_bytes);
   ret = make_pair(to_put_ops, to_put_bytes);
   return ret;
}

Thread log:
2016-04-28 19:41:43.231410 8059ec900 20 filestore(testdir/osd-bench/0) 
sync_entry(1:1) waiting for max_interval 5.000000
2016-04-28 19:41:43.231438 8059ec900 20 filestore(testdir/osd-bench/0) 
sync_entry(1:1) started at: 2016-04-28 19:41:43.231436
2016-04-28 19:41:44.395763 8059ec900 20 filestore(testdir/osd-bench/0) 
sync_entry(1:1) ended at: 2016-04-28 19:41:44.395758
2016-04-28 19:41:44.395781 8059ec900 20 filestore(testdir/osd-bench/0) 
sync_entry(1:1) waited for 1
2016-04-28 19:41:44.395789 8059ec900 20 filestore(testdir/osd-bench/0) 
sync_entry(1:1) woke after 1.164433
2016-04-28 19:41:44.395795 8059ec900 10 filestore(testdir/osd-bench/0) 
sync_entry(1:1) 3726
2016-04-28 19:41:44.395801 8059ec900 10 filestore(testdir/osd-bench/0) 
sync_entry(1:1) 3730
2016-04-28 19:41:44.395806 8059ec900 10 filestore(testdir/osd-bench/0) 
sync_entry(1:1) 3733
2016-04-28 19:41:44.400570 8059ec900 10 filestore(testdir/osd-bench/0) 
sync_entry(1:1) 3735 starting apply_manager.commit_start()
2016-04-28 19:41:44.400584 8059ec900 10 journal commit_start 
max_applied_seq 32, open_ops 0
2016-04-28 19:41:44.400588 8059ec900 10 journal commit_start blocked, 
all open_ops have completed
2016-04-28 19:41:44.400591 8059ec900 10 journal commit_start committing 
32, still blocked
2016-04-28 19:41:44.400596 8059ec900 10 journal FileJournal commit_start
2016-04-28 19:41:44.400599 8059ec900 10 journal commit_start 
FULL_NOTFULL.  All good.
2016-04-28 19:41:44.400602 8059ec900 10 journal 
apply_manager.commit_start() returning 1
2016-04-28 19:41:44.400605 8059ec900 10 filestore(testdir/osd-bench/0) 
sync_entry(1:1) 3738 done(true) apply_manager.commit_start()
2016-04-28 19:41:44.400637 8059ec900 10 filestore(testdir/osd-bench/0) 
sync_entry(1:1) 3743
2016-04-28 19:41:44.400643 8059ec900 10 filestore(testdir/osd-bench/0) 
sync_entry(1:1) 3745
2016-04-28 19:41:44.400653 8059ec900 10 filestore(testdir/osd-bench/0) 
sync_entry(1:1) 3748
2016-04-28 19:41:44.400673 8059ec900 10 filestore(testdir/osd-bench/0) 
sync_entry(1:1) 3750
2016-04-28 19:41:44.400680 8059ec900 10 filestore(testdir/osd-bench/0) 
sync_entry(1:1) 3752
2016-04-28 19:41:44.400685 8059ec900 15 filestore(testdir/osd-bench/0) 
sync_entry(1:1) committing 32
2016-04-28 19:41:44.400701 8059ec900 10 journal commit_started 
committing 32, unblocking
2016-04-28 19:41:44.400728 8059ec900 20 filestore dbobjectmap: seq is 5
2016-04-28 19:41:44.517112 8059ec900 15 
genericfilestorebackend(testdir/osd-bench/0) syncfs: doing a full sync 
(syncfs(2) if possible)
2016-04-28 19:41:45.471870 8059ec900 10 filestore(testdir/osd-bench/0) 
sync_entry(1:1) commit took 1.071257, interval was 2.240513
2016-04-28 19:41:45.471885 8059ec900 10 journal commit_finish 238 thru 
32 journal: 0x8058e5400
2016-04-28 19:41:45.473683 8059ec900 15 journal committed_thru:1804 locked.
2016-04-28 19:41:45.473697 8059ec900 10 throttle flush while 
!journaled_ops.empty()
2016-04-28 19:41:45.473701 8059ec900 10 throttle flush while 
!journaled_ops.empty()
2016-04-28 19:41:45.473705 8059ec900 10 throttle flush while 
!journaled_ops.empty()
2016-04-28 19:41:45.473707 8059ec900 10 throttle flush while 
!journaled_ops.empty()
2016-04-28 19:41:45.473710 8059ec900 10 throttle flush while 
!journaled_ops.empty()
2016-04-28 19:41:45.473747 8059ec900 10 throttle flush while 
!journaled_ops.empty()
2016-04-28 19:41:45.473750 8059ec900 10 throttle flush while 
!journaled_ops.empty()
2016-04-28 19:41:45.473753 8059ec900 10 throttle flush while 
!journaled_ops.empty()
2016-04-28 19:41:45.473756 8059ec900 10 throttle flush while 
!journaled_ops.empty()
2016-04-28 19:41:45.473758 8059ec900 10 throttle flush while 
!journaled_ops.empty()
2016-04-28 19:41:45.473761 8059ec900 10 throttle flush while 
!journaled_ops.empty()
2016-04-28 19:41:45.473763 8059ec900 10 throttle flush while 
!journaled_ops.empty()
2016-04-28 19:41:45.473767 8059ec900 10 throttle flush while 
!journaled_ops.empty()
2016-04-28 19:41:45.473772 8059ec900 10 throttle flush while 
!journaled_ops.empty()
2016-04-28 19:41:45.473775 8059ec900 10 throttle flush while 
!journaled_ops.empty()
2016-04-28 19:41:45.473777 8059ec900 10 throttle flush while 
!journaled_ops.empty()
2016-04-28 19:41:45.473779 8059ec900 10 throttle flush while 
!journaled_ops.empty()
2016-04-28 19:41:45.473781 8059ec900 10 throttle flush while 
!journaled_ops.empty()
2016-04-28 19:41:45.473784 8059ec900 10 throttle flush while 
!journaled_ops.empty()
2016-04-28 19:41:45.473786 8059ec900 10 throttle flush while 
!journaled_ops.empty()
2016-04-28 19:41:45.473788 8059ec900 10 throttle flush while 
!journaled_ops.empty()
2016-04-28 19:41:45.473797 8059ec900 10 throttle flush while 
!journaled_ops.empty()
2016-04-28 19:41:45.473800 8059ec900 10 throttle flush while 
!journaled_ops.empty()
2016-04-28 19:41:45.473803 8059ec900 10 throttle flush while 
!journaled_ops.empty()
2016-04-28 19:41:45.473806 8059ec900 10 throttle flush while 
!journaled_ops.empty()
2016-04-28 19:41:45.473809 8059ec900 10 throttle flush while 
!journaled_ops.empty()
2016-04-28 19:41:45.473811 8059ec900 10 throttle flush while 
!journaled_ops.empty()
2016-04-28 19:41:45.473814 8059ec900 10 throttle flush while 
!journaled_ops.empty()
2016-04-28 19:41:45.473817 8059ec900 10 throttle flush while 
!journaled_ops.empty()
2016-04-28 19:41:45.473819 8059ec900 10 throttle flush while 
!journaled_ops.empty()
2016-04-28 19:41:45.473822 8059ec900 10 throttle flush:63 calling 
throttle.put()

Could be due to a race condition... Re: Help with understanding throttle.finish()

[Willem Jan Withagen]

On 28-4-2016 20:15, Willem Jan Withagen wrote:
> Hi,
>
> I'm running a rather simple setup on my FreeBSD port.
>
> function TEST_simple() {
>     # run the most simple config, and run a bechmark on it.
>     local dir=$1
>
>     run_mon $dir a || return 1
>     run_osd $dir 0 || return 1
>
>     #
>     # default values should work
>     #
>     ceph tell osd.0 bench || return 1
>
> }
>
> This in the end crashes with:
>     8059eec00 -1 FileStore: sync_entry timed out after 600 seconds.
> exactly 10 minutes after startup.
> This trhread does just about exactly nothing, it initialises the time,
> and then traps after 10 minutes.
> # grep 8059eec00  testdir/osd-bench/osd.0.log
> 2016-04-28 19:51:44.444689 8059eec00 -1 FileStore: sync_entry timed out
> after 600 seconds.
> 2016-04-28 19:51:44.487104 8059eec00 -1 os/filestore/FileStore.cc: In
> function 'virtual void SyncEntryTimeout::finish(int)' thread 8059eec00 time

Haven't made much progress with this problem.
Rebases, but that does not bring any "fixes" in.

An extra measure point in time.
I've ran the OSD thru truss (aka strace in linux speak) and that does 
complete.

Now what truss/strace does it augments kernel entry and exit with 
monitoring code
and as such it can (and will change) the micro-timing. Als a consequence 
of that
it could also order the way threads interact.
It could very well be a difference between semantics in Locks/Mutexes 
between
Linux and FreeBSD, but I have not really found any suggestions to that 
regard.

The fact that with truss/strace the osd does not generate a crash,
(not even with: --filestore-commit-timeout=10)
is in indication that I could very likely be either a deadlock or other 
lock
related issue that is hiding somewhere under the lid of the OSD.

What are people using to analyze timing/locking/deadlocking issues in 
the Cephcode?

Thanx,
--WjW


> I've augmented just about every line of code in src/os/filestore/File*.cc
>
> And I get as far as
>     throttle.flush()
> It seems to work the first time it gets called. That is, it returns.
>
> However the second time is "stalls" in the call
>      throttle.put(to_put_bytes);
> after a number of itterations thru the while-loop.
>
> Below the code of Throttle::Flush and an sequence of the thread doing
> the blocking call
> from the log where I've added mode debugging code.
>
> Does anybody have a clue as to continue from here?
>   Why does throttle.put not return?
>   Is it just throttleing too hard and not reorganising the queue?
>
> --WjW
>
> Code:
> std::pair<uint64_t, uint64_t> JournalThrottle::flush(uint64_t mono_id)
> {
>   uint64_t to_put_bytes = 0;
>   uint64_t to_put_ops = 0;
>   std::pair<uint64_t, uint64_t> ret;
>   {
>     locker l(lock);
>     while (!journaled_ops.empty() &&
>            journaled_ops.front().first <= mono_id) {
>       to_put_bytes += journaled_ops.front().second;
>       to_put_ops++;
>       journaled_ops.pop_front();
>     }
>   }
>   throttle.put(to_put_bytes);
>   ret = make_pair(to_put_ops, to_put_bytes);
>   return ret;
> }
>
> Thread log:
> 2016-04-28 19:41:43.231410 8059ec900 20 filestore(testdir/osd-bench/0)
> sync_entry(1:1) waiting for max_interval 5.000000
> 2016-04-28 19:41:43.231438 8059ec900 20 filestore(testdir/osd-bench/0)
> sync_entry(1:1) started at: 2016-04-28 19:41:43.231436
> 2016-04-28 19:41:44.395763 8059ec900 20 filestore(testdir/osd-bench/0)
> sync_entry(1:1) ended at: 2016-04-28 19:41:44.395758
> 2016-04-28 19:41:44.395781 8059ec900 20 filestore(testdir/osd-bench/0)
> sync_entry(1:1) waited for 1
> 2016-04-28 19:41:44.395789 8059ec900 20 filestore(testdir/osd-bench/0)
> sync_entry(1:1) woke after 1.164433
> 2016-04-28 19:41:44.395795 8059ec900 10 filestore(testdir/osd-bench/0)
> sync_entry(1:1) 3726
> 2016-04-28 19:41:44.395801 8059ec900 10 filestore(testdir/osd-bench/0)
> sync_entry(1:1) 3730
> 2016-04-28 19:41:44.395806 8059ec900 10 filestore(testdir/osd-bench/0)
> sync_entry(1:1) 3733
> 2016-04-28 19:41:44.400570 8059ec900 10 filestore(testdir/osd-bench/0)
> sync_entry(1:1) 3735 starting apply_manager.commit_start()
> 2016-04-28 19:41:44.400584 8059ec900 10 journal commit_start
> max_applied_seq 32, open_ops 0
> 2016-04-28 19:41:44.400588 8059ec900 10 journal commit_start blocked,
> all open_ops have completed
> 2016-04-28 19:41:44.400591 8059ec900 10 journal commit_start committing
> 32, still blocked
> 2016-04-28 19:41:44.400596 8059ec900 10 journal FileJournal commit_start
> 2016-04-28 19:41:44.400599 8059ec900 10 journal commit_start
> FULL_NOTFULL.  All good.
> 2016-04-28 19:41:44.400602 8059ec900 10 journal
> apply_manager.commit_start() returning 1
> 2016-04-28 19:41:44.400605 8059ec900 10 filestore(testdir/osd-bench/0)
> sync_entry(1:1) 3738 done(true) apply_manager.commit_start()
> 2016-04-28 19:41:44.400637 8059ec900 10 filestore(testdir/osd-bench/0)
> sync_entry(1:1) 3743
> 2016-04-28 19:41:44.400643 8059ec900 10 filestore(testdir/osd-bench/0)
> sync_entry(1:1) 3745
> 2016-04-28 19:41:44.400653 8059ec900 10 filestore(testdir/osd-bench/0)
> sync_entry(1:1) 3748
> 2016-04-28 19:41:44.400673 8059ec900 10 filestore(testdir/osd-bench/0)
> sync_entry(1:1) 3750
> 2016-04-28 19:41:44.400680 8059ec900 10 filestore(testdir/osd-bench/0)
> sync_entry(1:1) 3752
> 2016-04-28 19:41:44.400685 8059ec900 15 filestore(testdir/osd-bench/0)
> sync_entry(1:1) committing 32
> 2016-04-28 19:41:44.400701 8059ec900 10 journal commit_started
> committing 32, unblocking
> 2016-04-28 19:41:44.400728 8059ec900 20 filestore dbobjectmap: seq is 5
> 2016-04-28 19:41:44.517112 8059ec900 15
> genericfilestorebackend(testdir/osd-bench/0) syncfs: doing a full sync
> (syncfs(2) if possible)
> 2016-04-28 19:41:45.471870 8059ec900 10 filestore(testdir/osd-bench/0)
> sync_entry(1:1) commit took 1.071257, interval was 2.240513
> 2016-04-28 19:41:45.471885 8059ec900 10 journal commit_finish 238 thru
> 32 journal: 0x8058e5400
> 2016-04-28 19:41:45.473683 8059ec900 15 journal committed_thru:1804 locked.
> 2016-04-28 19:41:45.473697 8059ec900 10 throttle flush while
> !journaled_ops.empty()
> 2016-04-28 19:41:45.473701 8059ec900 10 throttle flush while
> !journaled_ops.empty()
> 2016-04-28 19:41:45.473705 8059ec900 10 throttle flush while
> !journaled_ops.empty()
> 2016-04-28 19:41:45.473707 8059ec900 10 throttle flush while
> !journaled_ops.empty()
> 2016-04-28 19:41:45.473710 8059ec900 10 throttle flush while
> !journaled_ops.empty()
> 2016-04-28 19:41:45.473747 8059ec900 10 throttle flush while
> !journaled_ops.empty()
> 2016-04-28 19:41:45.473750 8059ec900 10 throttle flush while
> !journaled_ops.empty()
> 2016-04-28 19:41:45.473753 8059ec900 10 throttle flush while
> !journaled_ops.empty()
> 2016-04-28 19:41:45.473756 8059ec900 10 throttle flush while
> !journaled_ops.empty()
> 2016-04-28 19:41:45.473758 8059ec900 10 throttle flush while
> !journaled_ops.empty()
> 2016-04-28 19:41:45.473761 8059ec900 10 throttle flush while
> !journaled_ops.empty()
> 2016-04-28 19:41:45.473763 8059ec900 10 throttle flush while
> !journaled_ops.empty()
> 2016-04-28 19:41:45.473767 8059ec900 10 throttle flush while
> !journaled_ops.empty()
> 2016-04-28 19:41:45.473772 8059ec900 10 throttle flush while
> !journaled_ops.empty()
> 2016-04-28 19:41:45.473775 8059ec900 10 throttle flush while
> !journaled_ops.empty()
> 2016-04-28 19:41:45.473777 8059ec900 10 throttle flush while
> !journaled_ops.empty()
> 2016-04-28 19:41:45.473779 8059ec900 10 throttle flush while
> !journaled_ops.empty()
> 2016-04-28 19:41:45.473781 8059ec900 10 throttle flush while
> !journaled_ops.empty()
> 2016-04-28 19:41:45.473784 8059ec900 10 throttle flush while
> !journaled_ops.empty()
> 2016-04-28 19:41:45.473786 8059ec900 10 throttle flush while
> !journaled_ops.empty()
> 2016-04-28 19:41:45.473788 8059ec900 10 throttle flush while
> !journaled_ops.empty()
> 2016-04-28 19:41:45.473797 8059ec900 10 throttle flush while
> !journaled_ops.empty()
> 2016-04-28 19:41:45.473800 8059ec900 10 throttle flush while
> !journaled_ops.empty()
> 2016-04-28 19:41:45.473803 8059ec900 10 throttle flush while
> !journaled_ops.empty()
> 2016-04-28 19:41:45.473806 8059ec900 10 throttle flush while
> !journaled_ops.empty()
> 2016-04-28 19:41:45.473809 8059ec900 10 throttle flush while
> !journaled_ops.empty()
> 2016-04-28 19:41:45.473811 8059ec900 10 throttle flush while
> !journaled_ops.empty()
> 2016-04-28 19:41:45.473814 8059ec900 10 throttle flush while
> !journaled_ops.empty()
> 2016-04-28 19:41:45.473817 8059ec900 10 throttle flush while
> !journaled_ops.empty()
> 2016-04-28 19:41:45.473819 8059ec900 10 throttle flush while
> !journaled_ops.empty()
> 2016-04-28 19:41:45.473822 8059ec900 10 throttle flush:63 calling
> throttle.put()
>
> --
> To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Could be due to a race condition... Re: Help with understanding throttle.finish()

[Gregory Farnum]

On Fri, May 6, 2016 at 8:29 AM, Willem Jan Withagen <wjw@digiware.nl> wrote:
> On 28-4-2016 20:15, Willem Jan Withagen wrote:
>>
>> Hi,
>>
>> I'm running a rather simple setup on my FreeBSD port.
>>
>> function TEST_simple() {
>>     # run the most simple config, and run a bechmark on it.
>>     local dir=$1
>>
>>     run_mon $dir a || return 1
>>     run_osd $dir 0 || return 1
>>
>>     #
>>     # default values should work
>>     #
>>     ceph tell osd.0 bench || return 1
>>
>> }
>>
>> This in the end crashes with:
>>     8059eec00 -1 FileStore: sync_entry timed out after 600 seconds.
>> exactly 10 minutes after startup.
>> This trhread does just about exactly nothing, it initialises the time,
>> and then traps after 10 minutes.
>> # grep 8059eec00  testdir/osd-bench/osd.0.log
>> 2016-04-28 19:51:44.444689 8059eec00 -1 FileStore: sync_entry timed out
>> after 600 seconds.
>> 2016-04-28 19:51:44.487104 8059eec00 -1 os/filestore/FileStore.cc: In
>> function 'virtual void SyncEntryTimeout::finish(int)' thread 8059eec00
>> time
>
>
> Haven't made much progress with this problem.
> Rebases, but that does not bring any "fixes" in.
>
> An extra measure point in time.
> I've ran the OSD thru truss (aka strace in linux speak) and that does
> complete.
>
> Now what truss/strace does it augments kernel entry and exit with monitoring
> code
> and as such it can (and will change) the micro-timing. Als a consequence of
> that
> it could also order the way threads interact.
> It could very well be a difference between semantics in Locks/Mutexes
> between
> Linux and FreeBSD, but I have not really found any suggestions to that
> regard.
>
> The fact that with truss/strace the osd does not generate a crash,
> (not even with: --filestore-commit-timeout=10)
> is in indication that I could very likely be either a deadlock or other lock
> related issue that is hiding somewhere under the lid of the OSD.
>
> What are people using to analyze timing/locking/deadlocking issues in the
> Cephcode?

Our Mutex implementations have a custom lockdep built in. That should
be checking for anything using those...

But I'd be inclined to just check exactly what the thread is doing. I
think it's a lot more likely to be getting an unexpected syscall value
and just sitting still or something.
-Greg

Re: Could be due to a race condition... Re: Help with understanding throttle.finish()

[Willem Jan Withagen]

On 6-5-2016 20:41, Gregory Farnum wrote:
> On Fri, May 6, 2016 at 8:29 AM, Willem Jan Withagen <wjw@digiware.nl> wrote:
>> On 28-4-2016 20:15, Willem Jan Withagen wrote:
>>>
>>> Hi,
>>>
>>> I'm running a rather simple setup on my FreeBSD port.
>>>
>>> function TEST_simple() {
>>>     # run the most simple config, and run a bechmark on it.
>>>     local dir=$1
>>>
>>>     run_mon $dir a || return 1
>>>     run_osd $dir 0 || return 1
>>>
>>>     #
>>>     # default values should work
>>>     #
>>>     ceph tell osd.0 bench || return 1
>>>
>>> }
>>>
>>> This in the end crashes with:
>>>     8059eec00 -1 FileStore: sync_entry timed out after 600 seconds.
>>> exactly 10 minutes after startup.
>>> This trhread does just about exactly nothing, it initialises the time,
>>> and then traps after 10 minutes.
>>> # grep 8059eec00  testdir/osd-bench/osd.0.log
>>> 2016-04-28 19:51:44.444689 8059eec00 -1 FileStore: sync_entry timed out
>>> after 600 seconds.
>>> 2016-04-28 19:51:44.487104 8059eec00 -1 os/filestore/FileStore.cc: In
>>> function 'virtual void SyncEntryTimeout::finish(int)' thread 8059eec00
>>> time
>>
>>
>> Haven't made much progress with this problem.
>> Rebases, but that does not bring any "fixes" in.
>>
>> An extra measure point in time.
>> I've ran the OSD thru truss (aka strace in linux speak) and that does
>> complete.
>>
>> Now what truss/strace does it augments kernel entry and exit with monitoring
>> code
>> and as such it can (and will change) the micro-timing. Als a consequence of
>> that
>> it could also order the way threads interact.
>> It could very well be a difference between semantics in Locks/Mutexes
>> between
>> Linux and FreeBSD, but I have not really found any suggestions to that
>> regard.
>>
>> The fact that with truss/strace the osd does not generate a crash,
>> (not even with: --filestore-commit-timeout=10)
>> is in indication that I could very likely be either a deadlock or other lock
>> related issue that is hiding somewhere under the lid of the OSD.
>>
>> What are people using to analyze timing/locking/deadlocking issues in the
>> Cephcode?
> 
> Our Mutex implementations have a custom lockdep built in. That should
> be checking for anything using those...
> 
> But I'd be inclined to just check exactly what the thread is doing. I
> think it's a lot more likely to be getting an unexpected syscall value
> and just sitting still or something.

Oke, so the lockdep should at least report any created deadlocks?
Or does it even try to reverse lock-order if it sees possibilities it
would be oke to do so?

So it is very likely the second alternative I gave: Mismatching semantics.

Already had that issue with ENODATA and ENOATTR, which got also troubled
by the fact that Boost it also defines. And of course with a number that
is again different:
    boost/cerrno.hpp:#define ENODATA 9919

I've also switched on --debug-timer=20 in my tests, and I'm now
comparing the input of a "regular"run that blocks, and a trussed-run
that run to completion, so see where we do not reload the timer.
Next is then to see why.

But then my wife came home, and we sat out on the veranda with a nice
glass of Prosecco in the evening sun.... Beats thumbing trhu
Ceph-traces. 8=D
Not much time durring the weekend, so likely to be continued after the
weekend.

--WjW

Re: Could be due to a race condition... Re: Help with understanding throttle.finish()

[Willem Jan Withagen]

On 6-5-2016 23:04, Willem Jan Withagen wrote:
> On 6-5-2016 20:41, Gregory Farnum wrote:

Oke,

I'm going to need some help understanding some things...

I've taken the oversaturated test_backoff from test/common/Throttle.cc,
since that one wasn't working as well. And I suspect that it might be
for about the same/similar reason.

I start 1 putter and one getter, and with certain parameters the test
does not complete. When
    expected_throughput * put_delay_per_count ~> 10 (max_multiple??)
then the process get into a loop, I'm printing over and over:
_get_delay return r > high_threshhold (queue is full): time = 0.0172

Note that the parameters to test_backoff are:
====
//  double expected_throughput,
    500,
//  double max_multiple,
    10,
//  double put_delay_per_count,
    0.025,
====

And that loop is in BackoffThrottle::get, around line 390 (I have a lot
of extra lines for annotation and tracing.)
====
  while (((start + delay) > std::chrono::system_clock::now()) ||
         !((max == 0) || (current == 0) || ((current + c) <= max))) {
    assert(ticket == waiters.begin());
    (*ticket)->wait_until(l, start + delay);
    delay = _get_delay(c);
  }
====

The reason that this loop never completes is that it executed under the
lock in the getter thread in test/common/Throttle.cc:test_backoff where
it is executed under g.lock(). And the putter is held on the same lock,
so nothing gets in or out.... Not a deadlock, but a live-lock.

Thusfar the analysis.

Now the question(s)....
1) How do I break this livelock.
1a) Should the extra while() { wait } loop actually be in
BackoffThrottle:get without releasing the lock?

2) The thread are called getter and putter.
So I'd expect the getter to get messages from the list and the putter so
write things to the list.

Why does the getter:
	while(!stop) {
	    throttle.get(to_get);
	    in_queue.push_back(to_get)
	    assert(total <= max);
	}
And the putter:
	while(!stop) {
	    while(empty)
		wait;
	    c = in_queue.front();
	    in_queue.pop();
	    "wait time to queue some more"
	    throttle.put(c)
	}

Am I getting it wrong around, and would I not expect the
throttle.{get,put} to match the similar operations on the in_queue?

And what is this c value that we retrieve from the in_queue that is then
used to be put in the throttle???

--WjW

Re: Could be due to a race condition... Re: Help with understanding throttle.finish()

[Willem Jan Withagen]

On 9-5-2016 10:44, Willem Jan Withagen wrote:
> On 6-5-2016 23:04, Willem Jan Withagen wrote:
>> On 6-5-2016 20:41, Gregory Farnum wrote:

Hi Greg,

If you are not the one to ask about the Throttle stuff, would you know
anybody else I could ask this question.
Because the more runs I make, the more it seems like it is a livelock.

I'm now going to do the annotated runs on Linux as well, and try and
find out why it doesn't happen there.

--WjW

> Oke,
>
> I'm going to need some help understanding some things...
>
> I've taken the oversaturated test_backoff from test/common/Throttle.cc,
> since that one wasn't working as well. And I suspect that it might be
> for about the same/similar reason.
>
> I start 1 putter and one getter, and with certain parameters the test
> does not complete. When
>     expected_throughput * put_delay_per_count ~> 10 (max_multiple??)
> then the process get into a loop, I'm printing over and over:
> _get_delay return r > high_threshhold (queue is full): time = 0.0172
>
> Note that the parameters to test_backoff are:
> ====
> //  double expected_throughput,
>     500,
> //  double max_multiple,
>     10,
> //  double put_delay_per_count,
>     0.025,
> ====
>
> And that loop is in BackoffThrottle::get, around line 390 (I have a lot
> of extra lines for annotation and tracing.)
> ====
>   while (((start + delay) > std::chrono::system_clock::now()) ||
>          !((max == 0) || (current == 0) || ((current + c) <= max))) {
>     assert(ticket == waiters.begin());
>     (*ticket)->wait_until(l, start + delay);
>     delay = _get_delay(c);
>   }
> ====
>
> The reason that this loop never completes is that it executed under the
> lock in the getter thread in test/common/Throttle.cc:test_backoff where
> it is executed under g.lock(). And the putter is held on the same lock,
> so nothing gets in or out.... Not a deadlock, but a live-lock.
>
> Thusfar the analysis.
>
> Now the question(s)....
> 1) How do I break this livelock.
> 1a) Should the extra while() { wait } loop actually be in
> BackoffThrottle:get without releasing the lock?
>
> 2) The thread are called getter and putter.
> So I'd expect the getter to get messages from the list and the putter so
> write things to the list.
>
> Why does the getter:
> 	while(!stop) {
> 	    throttle.get(to_get);
> 	    in_queue.push_back(to_get)
> 	    assert(total <= max);
> 	}
> And the putter:
> 	while(!stop) {
> 	    while(empty)
> 		wait;
> 	    c = in_queue.front();
> 	    in_queue.pop();
> 	    "wait time to queue some more"
> 	    throttle.put(c)
> 	}
>
> Am I getting it wrong around, and would I not expect the
> throttle.{get,put} to match the similar operations on the in_queue?
>
> And what is this c value that we retrieve from the in_queue that is then
> used to be put in the throttle???
>
> --WjW
> --
> To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
>

Re: Could be due to a race condition... Re: Help with understanding throttle.finish()

[Gregory Farnum]

I've been busy lately. Looks like Sam wrote the BackoffThrottle; not
sure if he did the tests as well or not. Maybe check the git logs on
them. :)
-Greg

On Wed, May 11, 2016 at 2:46 AM, Willem Jan Withagen <wjw@digiware.nl> wrote:
> On 9-5-2016 10:44, Willem Jan Withagen wrote:
>>
>> On 6-5-2016 23:04, Willem Jan Withagen wrote:
>>>
>>> On 6-5-2016 20:41, Gregory Farnum wrote:
>
>
> Hi Greg,
>
> If you are not the one to ask about the Throttle stuff, would you know
> anybody else I could ask this question.
> Because the more runs I make, the more it seems like it is a livelock.
>
> I'm now going to do the annotated runs on Linux as well, and try and
> find out why it doesn't happen there.
>
> --WjW
>
>> Oke,
>>
>> I'm going to need some help understanding some things...
>>
>> I've taken the oversaturated test_backoff from test/common/Throttle.cc,
>> since that one wasn't working as well. And I suspect that it might be
>> for about the same/similar reason.
>>
>> I start 1 putter and one getter, and with certain parameters the test
>> does not complete. When
>>     expected_throughput * put_delay_per_count ~> 10 (max_multiple??)
>> then the process get into a loop, I'm printing over and over:
>> _get_delay return r > high_threshhold (queue is full): time = 0.0172
>>
>> Note that the parameters to test_backoff are:
>> ====
>> //  double expected_throughput,
>>     500,
>> //  double max_multiple,
>>     10,
>> //  double put_delay_per_count,
>>     0.025,
>> ====
>>
>> And that loop is in BackoffThrottle::get, around line 390 (I have a lot
>> of extra lines for annotation and tracing.)
>> ====
>>   while (((start + delay) > std::chrono::system_clock::now()) ||
>>          !((max == 0) || (current == 0) || ((current + c) <= max))) {
>>     assert(ticket == waiters.begin());
>>     (*ticket)->wait_until(l, start + delay);
>>     delay = _get_delay(c);
>>   }
>> ====
>>
>> The reason that this loop never completes is that it executed under the
>> lock in the getter thread in test/common/Throttle.cc:test_backoff where
>> it is executed under g.lock(). And the putter is held on the same lock,
>> so nothing gets in or out.... Not a deadlock, but a live-lock.
>>
>> Thusfar the analysis.
>>
>> Now the question(s)....
>> 1) How do I break this livelock.
>> 1a) Should the extra while() { wait } loop actually be in
>> BackoffThrottle:get without releasing the lock?
>>
>> 2) The thread are called getter and putter.
>> So I'd expect the getter to get messages from the list and the putter so
>> write things to the list.
>>
>> Why does the getter:
>>         while(!stop) {
>>             throttle.get(to_get);
>>             in_queue.push_back(to_get)
>>             assert(total <= max);
>>         }
>> And the putter:
>>         while(!stop) {
>>             while(empty)
>>                 wait;
>>             c = in_queue.front();
>>             in_queue.pop();
>>             "wait time to queue some more"
>>             throttle.put(c)
>>         }
>>
>> Am I getting it wrong around, and would I not expect the
>> throttle.{get,put} to match the similar operations on the in_queue?
>>
>> And what is this c value that we retrieve from the in_queue that is then
>> used to be put in the throttle???
>>
>> --WjW
>> --
>> To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
>> the body of a message to majordomo@vger.kernel.org
>> More majordomo info at  http://vger.kernel.org/majordomo-info.html
>>
>

Re: Could be due to a race condition... Re: Help with understanding throttle.finish()

[Willem Jan Withagen]

On 11-5-2016 15:43, Gregory Farnum wrote:
> I've been busy lately. Looks like Sam wrote the BackoffThrottle; not
> sure if he did the tests as well or not. Maybe check the git logs on
> them. :)

Well, the test is also written bij Sam.

But everything gets stuck in the loop at BackoffThrottle::get(uint64_t 
c):379 :
====
   while (((start + delay) > std::chrono::system_clock::now()) ||
          !((max == 0) || (current == 0) || ((current + c) <= max))) {
     assert(ticket == waiters.begin());
     (*ticket)->wait_until(l, start + delay);
     delay = _get_delay(c);
   }
====

And I have the feeling that the lock is not released (long enough) when
start+delay is actually in the past.
It is of course also doubtfull what is actually expected from the
wait_until function in this case???

Replacing it with
	(*ticket)->wait_for(l, delay);
Does get the BackoffThrottle.oversaturated test completed.

So would this be a appropriate modification?

--WjW

> -Greg
>
> On Wed, May 11, 2016 at 2:46 AM, Willem Jan Withagen <wjw@digiware.nl> wrote:
>> On 9-5-2016 10:44, Willem Jan Withagen wrote:
>>>
>>> On 6-5-2016 23:04, Willem Jan Withagen wrote:
>>>>
>>>> On 6-5-2016 20:41, Gregory Farnum wrote:
>>
>>
>> Hi Greg,
>>
>> If you are not the one to ask about the Throttle stuff, would you know
>> anybody else I could ask this question.
>> Because the more runs I make, the more it seems like it is a livelock.
>>
>> I'm now going to do the annotated runs on Linux as well, and try and
>> find out why it doesn't happen there.
>>
>> --WjW
>>
>>> Oke,
>>>
>>> I'm going to need some help understanding some things...
>>>
>>> I've taken the oversaturated test_backoff from test/common/Throttle.cc,
>>> since that one wasn't working as well. And I suspect that it might be
>>> for about the same/similar reason.
>>>
>>> I start 1 putter and one getter, and with certain parameters the test
>>> does not complete. When
>>>     expected_throughput * put_delay_per_count ~> 10 (max_multiple??)
>>> then the process get into a loop, I'm printing over and over:
>>> _get_delay return r > high_threshhold (queue is full): time = 0.0172
>>>
>>> Note that the parameters to test_backoff are:
>>> ====
>>> //  double expected_throughput,
>>>     500,
>>> //  double max_multiple,
>>>     10,
>>> //  double put_delay_per_count,
>>>     0.025,
>>> ====
>>>
>>> And that loop is in BackoffThrottle::get, around line 390 (I have a lot
>>> of extra lines for annotation and tracing.)
>>> ====
>>>   while (((start + delay) > std::chrono::system_clock::now()) ||
>>>          !((max == 0) || (current == 0) || ((current + c) <= max))) {
>>>     assert(ticket == waiters.begin());
>>>     (*ticket)->wait_until(l, start + delay);
>>>     delay = _get_delay(c);
>>>   }
>>> ====
>>>
>>> The reason that this loop never completes is that it executed under the
>>> lock in the getter thread in test/common/Throttle.cc:test_backoff where
>>> it is executed under g.lock(). And the putter is held on the same lock,
>>> so nothing gets in or out.... Not a deadlock, but a live-lock.
>>>
>>> Thusfar the analysis.
>>>
>>> Now the question(s)....
>>> 1) How do I break this livelock.
>>> 1a) Should the extra while() { wait } loop actually be in
>>> BackoffThrottle:get without releasing the lock?
>>>
>>> 2) The thread are called getter and putter.
>>> So I'd expect the getter to get messages from the list and the putter so
>>> write things to the list.
>>>
>>> Why does the getter:
>>>         while(!stop) {
>>>             throttle.get(to_get);
>>>             in_queue.push_back(to_get)
>>>             assert(total <= max);
>>>         }
>>> And the putter:
>>>         while(!stop) {
>>>             while(empty)
>>>                 wait;
>>>             c = in_queue.front();
>>>             in_queue.pop();
>>>             "wait time to queue some more"
>>>             throttle.put(c)
>>>         }
>>>
>>> Am I getting it wrong around, and would I not expect the
>>> throttle.{get,put} to match the similar operations on the in_queue?
>>>
>>> And what is this c value that we retrieve from the in_queue that is then
>>> used to be put in the throttle???
>>>
>>> --WjW
>>> --
>>> To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
>>> the body of a message to majordomo@vger.kernel.org
>>> More majordomo info at  http://vger.kernel.org/majordomo-info.html
>>>
>>
> --
> To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
>

Re: Could be due to a race condition... Re: Help with understanding throttle.finish()

[Samuel Just]

That sounds reasonable.
-Sam

On Thu, May 12, 2016 at 2:02 PM, Willem Jan Withagen <wjw@digiware.nl> wrote:
> On 11-5-2016 15:43, Gregory Farnum wrote:
>>
>> I've been busy lately. Looks like Sam wrote the BackoffThrottle; not
>> sure if he did the tests as well or not. Maybe check the git logs on
>> them. :)
>
>
> Well, the test is also written bij Sam.
>
> But everything gets stuck in the loop at BackoffThrottle::get(uint64_t
> c):379 :
> ====
>   while (((start + delay) > std::chrono::system_clock::now()) ||
>          !((max == 0) || (current == 0) || ((current + c) <= max))) {
>     assert(ticket == waiters.begin());
>     (*ticket)->wait_until(l, start + delay);
>     delay = _get_delay(c);
>   }
> ====
>
> And I have the feeling that the lock is not released (long enough) when
> start+delay is actually in the past.
> It is of course also doubtfull what is actually expected from the
> wait_until function in this case???
>
> Replacing it with
>         (*ticket)->wait_for(l, delay);
> Does get the BackoffThrottle.oversaturated test completed.
>
> So would this be a appropriate modification?
>
> --WjW
>
>
>> -Greg
>>
>> On Wed, May 11, 2016 at 2:46 AM, Willem Jan Withagen <wjw@digiware.nl>
>> wrote:
>>>
>>> On 9-5-2016 10:44, Willem Jan Withagen wrote:
>>>>
>>>>
>>>> On 6-5-2016 23:04, Willem Jan Withagen wrote:
>>>>>
>>>>>
>>>>> On 6-5-2016 20:41, Gregory Farnum wrote:
>>>
>>>
>>>
>>> Hi Greg,
>>>
>>> If you are not the one to ask about the Throttle stuff, would you know
>>> anybody else I could ask this question.
>>> Because the more runs I make, the more it seems like it is a livelock.
>>>
>>> I'm now going to do the annotated runs on Linux as well, and try and
>>> find out why it doesn't happen there.
>>>
>>> --WjW
>>>
>>>> Oke,
>>>>
>>>> I'm going to need some help understanding some things...
>>>>
>>>> I've taken the oversaturated test_backoff from test/common/Throttle.cc,
>>>> since that one wasn't working as well. And I suspect that it might be
>>>> for about the same/similar reason.
>>>>
>>>> I start 1 putter and one getter, and with certain parameters the test
>>>> does not complete. When
>>>>     expected_throughput * put_delay_per_count ~> 10 (max_multiple??)
>>>> then the process get into a loop, I'm printing over and over:
>>>> _get_delay return r > high_threshhold (queue is full): time = 0.0172
>>>>
>>>> Note that the parameters to test_backoff are:
>>>> ====
>>>> //  double expected_throughput,
>>>>     500,
>>>> //  double max_multiple,
>>>>     10,
>>>> //  double put_delay_per_count,
>>>>     0.025,
>>>> ====
>>>>
>>>> And that loop is in BackoffThrottle::get, around line 390 (I have a lot
>>>> of extra lines for annotation and tracing.)
>>>> ====
>>>>   while (((start + delay) > std::chrono::system_clock::now()) ||
>>>>          !((max == 0) || (current == 0) || ((current + c) <= max))) {
>>>>     assert(ticket == waiters.begin());
>>>>     (*ticket)->wait_until(l, start + delay);
>>>>     delay = _get_delay(c);
>>>>   }
>>>> ====
>>>>
>>>> The reason that this loop never completes is that it executed under the
>>>> lock in the getter thread in test/common/Throttle.cc:test_backoff where
>>>> it is executed under g.lock(). And the putter is held on the same lock,
>>>> so nothing gets in or out.... Not a deadlock, but a live-lock.
>>>>
>>>> Thusfar the analysis.
>>>>
>>>> Now the question(s)....
>>>> 1) How do I break this livelock.
>>>> 1a) Should the extra while() { wait } loop actually be in
>>>> BackoffThrottle:get without releasing the lock?
>>>>
>>>> 2) The thread are called getter and putter.
>>>> So I'd expect the getter to get messages from the list and the putter so
>>>> write things to the list.
>>>>
>>>> Why does the getter:
>>>>         while(!stop) {
>>>>             throttle.get(to_get);
>>>>             in_queue.push_back(to_get)
>>>>             assert(total <= max);
>>>>         }
>>>> And the putter:
>>>>         while(!stop) {
>>>>             while(empty)
>>>>                 wait;
>>>>             c = in_queue.front();
>>>>             in_queue.pop();
>>>>             "wait time to queue some more"
>>>>             throttle.put(c)
>>>>         }
>>>>
>>>> Am I getting it wrong around, and would I not expect the
>>>> throttle.{get,put} to match the similar operations on the in_queue?
>>>>
>>>> And what is this c value that we retrieve from the in_queue that is then
>>>> used to be put in the throttle???
>>>>
>>>> --WjW
>>>> --
>>>> To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
>>>> the body of a message to majordomo@vger.kernel.org
>>>> More majordomo info at  http://vger.kernel.org/majordomo-info.html
>>>>
>>>
>> --
>> To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
>> the body of a message to majordomo@vger.kernel.org
>> More majordomo info at  http://vger.kernel.org/majordomo-info.html
>>
>

Re: Could be due to a race condition... Re: Help with understanding throttle.finish()

[Willem Jan Withagen]

On 13-5-2016 00:22, Samuel Just wrote:
> That sounds reasonable.

And thus submit a a pull, and go thru the full QA process?

--WjW

> -Sam
> 
> On Thu, May 12, 2016 at 2:02 PM, Willem Jan Withagen <wjw@digiware.nl> wrote:
>> On 11-5-2016 15:43, Gregory Farnum wrote:
>>>
>>> I've been busy lately. Looks like Sam wrote the BackoffThrottle; not
>>> sure if he did the tests as well or not. Maybe check the git logs on
>>> them. :)
>>
>>
>> Well, the test is also written bij Sam.
>>
>> But everything gets stuck in the loop at BackoffThrottle::get(uint64_t
>> c):379 :
>> ====
>>   while (((start + delay) > std::chrono::system_clock::now()) ||
>>          !((max == 0) || (current == 0) || ((current + c) <= max))) {
>>     assert(ticket == waiters.begin());
>>     (*ticket)->wait_until(l, start + delay);
>>     delay = _get_delay(c);
>>   }
>> ====
>>
>> And I have the feeling that the lock is not released (long enough) when
>> start+delay is actually in the past.
>> It is of course also doubtfull what is actually expected from the
>> wait_until function in this case???
>>
>> Replacing it with
>>         (*ticket)->wait_for(l, delay);
>> Does get the BackoffThrottle.oversaturated test completed.
>>
>> So would this be a appropriate modification?
>>
>> --WjW
>>
>>
>>> -Greg
>>>
>>> On Wed, May 11, 2016 at 2:46 AM, Willem Jan Withagen <wjw@digiware.nl>
>>> wrote:
>>>>
>>>> On 9-5-2016 10:44, Willem Jan Withagen wrote:
>>>>>
>>>>>
>>>>> On 6-5-2016 23:04, Willem Jan Withagen wrote:
>>>>>>
>>>>>>
>>>>>> On 6-5-2016 20:41, Gregory Farnum wrote:
>>>>
>>>>
>>>>
>>>> Hi Greg,
>>>>
>>>> If you are not the one to ask about the Throttle stuff, would you know
>>>> anybody else I could ask this question.
>>>> Because the more runs I make, the more it seems like it is a livelock.
>>>>
>>>> I'm now going to do the annotated runs on Linux as well, and try and
>>>> find out why it doesn't happen there.
>>>>
>>>> --WjW
>>>>
>>>>> Oke,
>>>>>
>>>>> I'm going to need some help understanding some things...
>>>>>
>>>>> I've taken the oversaturated test_backoff from test/common/Throttle.cc,
>>>>> since that one wasn't working as well. And I suspect that it might be
>>>>> for about the same/similar reason.
>>>>>
>>>>> I start 1 putter and one getter, and with certain parameters the test
>>>>> does not complete. When
>>>>>     expected_throughput * put_delay_per_count ~> 10 (max_multiple??)
>>>>> then the process get into a loop, I'm printing over and over:
>>>>> _get_delay return r > high_threshhold (queue is full): time = 0.0172
>>>>>
>>>>> Note that the parameters to test_backoff are:
>>>>> ====
>>>>> //  double expected_throughput,
>>>>>     500,
>>>>> //  double max_multiple,
>>>>>     10,
>>>>> //  double put_delay_per_count,
>>>>>     0.025,
>>>>> ====
>>>>>
>>>>> And that loop is in BackoffThrottle::get, around line 390 (I have a lot
>>>>> of extra lines for annotation and tracing.)
>>>>> ====
>>>>>   while (((start + delay) > std::chrono::system_clock::now()) ||
>>>>>          !((max == 0) || (current == 0) || ((current + c) <= max))) {
>>>>>     assert(ticket == waiters.begin());
>>>>>     (*ticket)->wait_until(l, start + delay);
>>>>>     delay = _get_delay(c);
>>>>>   }
>>>>> ====
>>>>>
>>>>> The reason that this loop never completes is that it executed under the
>>>>> lock in the getter thread in test/common/Throttle.cc:test_backoff where
>>>>> it is executed under g.lock(). And the putter is held on the same lock,
>>>>> so nothing gets in or out.... Not a deadlock, but a live-lock.
>>>>>
>>>>> Thusfar the analysis.
>>>>>
>>>>> Now the question(s)....
>>>>> 1) How do I break this livelock.
>>>>> 1a) Should the extra while() { wait } loop actually be in
>>>>> BackoffThrottle:get without releasing the lock?
>>>>>
>>>>> 2) The thread are called getter and putter.
>>>>> So I'd expect the getter to get messages from the list and the putter so
>>>>> write things to the list.
>>>>>
>>>>> Why does the getter:
>>>>>         while(!stop) {
>>>>>             throttle.get(to_get);
>>>>>             in_queue.push_back(to_get)
>>>>>             assert(total <= max);
>>>>>         }
>>>>> And the putter:
>>>>>         while(!stop) {
>>>>>             while(empty)
>>>>>                 wait;
>>>>>             c = in_queue.front();
>>>>>             in_queue.pop();
>>>>>             "wait time to queue some more"
>>>>>             throttle.put(c)
>>>>>         }
>>>>>
>>>>> Am I getting it wrong around, and would I not expect the
>>>>> throttle.{get,put} to match the similar operations on the in_queue?
>>>>>
>>>>> And what is this c value that we retrieve from the in_queue that is then
>>>>> used to be put in the throttle???
>>>>>
>>>>> --WjW
>>>>> --
>>>>> To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
>>>>> the body of a message to majordomo@vger.kernel.org
>>>>> More majordomo info at  http://vger.kernel.org/majordomo-info.html
>>>>>
>>>>
>>> --
>>> To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
>>> the body of a message to majordomo@vger.kernel.org
>>> More majordomo info at  http://vger.kernel.org/majordomo-info.html
>>>
>>

Re: Could be due to a race condition... Re: Help with understanding throttle.finish()

[Willem Jan Withagen]

On 13-5-2016 00:22, Samuel Just wrote:
> That sounds reasonable.

Submitted in #9111

--WjW

> -Sam
> 
> On Thu, May 12, 2016 at 2:02 PM, Willem Jan Withagen <wjw@digiware.nl> wrote:
>> On 11-5-2016 15:43, Gregory Farnum wrote:
>>>
>>> I've been busy lately. Looks like Sam wrote the BackoffThrottle; not
>>> sure if he did the tests as well or not. Maybe check the git logs on
>>> them. :)
>>
>>
>> Well, the test is also written bij Sam.
>>
>> But everything gets stuck in the loop at BackoffThrottle::get(uint64_t
>> c):379 :
>> ====
>>   while (((start + delay) > std::chrono::system_clock::now()) ||
>>          !((max == 0) || (current == 0) || ((current + c) <= max))) {
>>     assert(ticket == waiters.begin());
>>     (*ticket)->wait_until(l, start + delay);
>>     delay = _get_delay(c);
>>   }
>> ====
>>
>> And I have the feeling that the lock is not released (long enough) when
>> start+delay is actually in the past.
>> It is of course also doubtfull what is actually expected from the
>> wait_until function in this case???
>>
>> Replacing it with
>>         (*ticket)->wait_for(l, delay);
>> Does get the BackoffThrottle.oversaturated test completed.
>>
>> So would this be a appropriate modification?
>>
>> --WjW
>>
>>
>>> -Greg
>>>
>>> On Wed, May 11, 2016 at 2:46 AM, Willem Jan Withagen <wjw@digiware.nl>
>>> wrote:
>>>>
>>>> On 9-5-2016 10:44, Willem Jan Withagen wrote:
>>>>>
>>>>>
>>>>> On 6-5-2016 23:04, Willem Jan Withagen wrote:
>>>>>>
>>>>>>
>>>>>> On 6-5-2016 20:41, Gregory Farnum wrote:
>>>>
>>>>
>>>>
>>>> Hi Greg,
>>>>
>>>> If you are not the one to ask about the Throttle stuff, would you know
>>>> anybody else I could ask this question.
>>>> Because the more runs I make, the more it seems like it is a livelock.
>>>>
>>>> I'm now going to do the annotated runs on Linux as well, and try and
>>>> find out why it doesn't happen there.
>>>>
>>>> --WjW
>>>>
>>>>> Oke,
>>>>>
>>>>> I'm going to need some help understanding some things...
>>>>>
>>>>> I've taken the oversaturated test_backoff from test/common/Throttle.cc,
>>>>> since that one wasn't working as well. And I suspect that it might be
>>>>> for about the same/similar reason.
>>>>>
>>>>> I start 1 putter and one getter, and with certain parameters the test
>>>>> does not complete. When
>>>>>     expected_throughput * put_delay_per_count ~> 10 (max_multiple??)
>>>>> then the process get into a loop, I'm printing over and over:
>>>>> _get_delay return r > high_threshhold (queue is full): time = 0.0172
>>>>>
>>>>> Note that the parameters to test_backoff are:
>>>>> ====
>>>>> //  double expected_throughput,
>>>>>     500,
>>>>> //  double max_multiple,
>>>>>     10,
>>>>> //  double put_delay_per_count,
>>>>>     0.025,
>>>>> ====
>>>>>
>>>>> And that loop is in BackoffThrottle::get, around line 390 (I have a lot
>>>>> of extra lines for annotation and tracing.)
>>>>> ====
>>>>>   while (((start + delay) > std::chrono::system_clock::now()) ||
>>>>>          !((max == 0) || (current == 0) || ((current + c) <= max))) {
>>>>>     assert(ticket == waiters.begin());
>>>>>     (*ticket)->wait_until(l, start + delay);
>>>>>     delay = _get_delay(c);
>>>>>   }
>>>>> ====
>>>>>
>>>>> The reason that this loop never completes is that it executed under the
>>>>> lock in the getter thread in test/common/Throttle.cc:test_backoff where
>>>>> it is executed under g.lock(). And the putter is held on the same lock,
>>>>> so nothing gets in or out.... Not a deadlock, but a live-lock.
>>>>>
>>>>> Thusfar the analysis.
>>>>>
>>>>> Now the question(s)....
>>>>> 1) How do I break this livelock.
>>>>> 1a) Should the extra while() { wait } loop actually be in
>>>>> BackoffThrottle:get without releasing the lock?
>>>>>
>>>>> 2) The thread are called getter and putter.
>>>>> So I'd expect the getter to get messages from the list and the putter so
>>>>> write things to the list.
>>>>>
>>>>> Why does the getter:
>>>>>         while(!stop) {
>>>>>             throttle.get(to_get);
>>>>>             in_queue.push_back(to_get)
>>>>>             assert(total <= max);
>>>>>         }
>>>>> And the putter:
>>>>>         while(!stop) {
>>>>>             while(empty)
>>>>>                 wait;
>>>>>             c = in_queue.front();
>>>>>             in_queue.pop();
>>>>>             "wait time to queue some more"
>>>>>             throttle.put(c)
>>>>>         }
>>>>>
>>>>> Am I getting it wrong around, and would I not expect the
>>>>> throttle.{get,put} to match the similar operations on the in_queue?
>>>>>
>>>>> And what is this c value that we retrieve from the in_queue that is then
>>>>> used to be put in the throttle???
>>>>>
>>>>> --WjW
>>>>> --
>>>>> To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
>>>>> the body of a message to majordomo@vger.kernel.org
>>>>> More majordomo info at  http://vger.kernel.org/majordomo-info.html
>>>>>
>>>>
>>> --
>>> To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
>>> the body of a message to majordomo@vger.kernel.org
>>> More majordomo info at  http://vger.kernel.org/majordomo-info.html
>>>
>>