Re: [dtn-users] DTN2 - Frequent Spinlock errors

[Nik Ansell <[e-mail]>]

Hello All,

I think I have found a fix for this, it is rather crude but seems to work
consistently well after putting my test-bed through its paces using TCPCL,
UDPCL and LTPCL.

In my testing I added some debug code to SpinLock.cc which printed the Lock
class properties to the dtnd.log file. I noticed that adding the debug code
actually caused the spinlock errors to appear less frequently. I also
noticed that when the spinlock error loop occurs, the lock_holder_name_
property of the Lock class (the thread that created the lock) was NULL. In
some cases I also received an error (ASSERTION FAILED (is_locked_by_me())
at thread/SpinLock.cc:91) - this is the check at the start of the unlock
function to ensure that a thread is not trying to unlock memory that was
locked by another thread.

The most common spin lock errors I experienced were:

sending node: OpenFdCache::unpin waiting for spinlock held by null
receiving node: BundleList::del_bundle waiting for lock held by null

I developed two changes (below) to the oasys-1.6.0 build, which resulted in
the ASSERTION FAILED error message and spin lock error message going away
and much better overall performance on my test-bed. Then of course I reran
make and make install to rebuild and install the required files.

I have never written a line of c++ code in my life, nor did I know anything
about linux spinlocks before my digging began.
Therefore I am open to any suggestions to improve the code, or to learn of
any issues I may have caused by implementing these changes. I appreciate
this will potentially impact the performance of some systems, but as the
pause only occurs while waiting to acquire a lock I suspect this will not
be too noticeable, as it yields the thread (i.e passes the context back to
the CPU) before pausing.

1. Add the following code to the start of the function, to allow locking or
unlocking when lock_holder_name_ is NULL.

Lock.h -> is_locked_by_me():

    bool is_locked_by_me()
    {

        if (lock_holder_name_ == NULL) {
        return is_locked() && true;
        }

2. Add the following 11,000 microsecond pause, if the thread is waiting to
acquire a lock:

SpinLock.cc -> SpinLock::lock():

    while (atomic_cmpxchg32(&lock_count_, 0, 1) != 0)
    {
        Thread::spin_yield();
        // 0.011 sec sleep
        usleep(11000);

Kind Regards,
Nik

On Mon, Jan 25, 2016 at 11:19 AM, Nik Ansell <[e-mail]> wrote:

> I've done some more digging and have a few observations (below), I will
> continue down this path but think I may be out of my depth already! :)
>
> 1. SpinLock.h: SpinLock::lock():
> a) The error message appearing in the log (below) has a null
> lock_holder_name_ - Does this mean the lock is invalid (i.e perhaps the
> calling thread terminated due to an exception) and can be safely released?
> fprintf(stderr, "warning: %s is waiting for spin lock held by %s, which
> has reached spin limit\n", lock_user, lock_holder_name_)
>
> b) The call to (Thread.h) Thread::spin_yield()  (which calls either
> thread_id_yield() or sched_yield() ). Is possibly failing in some cases -
> not sure how to debug this one....Has anyone any idea if I can somehow
> force the release of the lock if (as in above) lock_holder_name_ == NULL?
>
> c) The function atomic_cmpxchg32(&lock_count_,0,1) !=0 called is contained
> within several Atomic-<CPUARCH>.h files e.g. Atomic-arm.h or Atomic-x86.h -
> I am not sure how to confirm the correct header file was used during the
> build, but will try to build oasys and dtn2 again using the
> --host=arm-linux argument to configure to see if this makes a difference.
>
> 2.  I have noticed there are some locking debugging functions available
> (Thread::lock_debugger->add_lock / remove_lock) if
> the --enable_debug_locking argument is passed during the build of oasys and
> dtn2. I am considering enabling this to get some more info on the problem.
>
> Kind Regards,
> Nik
>
> On Sun, Jan 24, 2016 at 12:05 PM, Nik Ansell <[e-mail]>
> wrote:
>
>> Hello All,
>>
>> I am running some experiments to identify bundle delivery characteristics
>> of DTN2 (+LTPlib), ION and IBR-DTN on the Raspberry Pi B2. Currently I am
>> trying to identify reliable bundle delivery scenarios for all 3 DTN
>> implementations, so I can then apply certain network simulation scenarios
>> to observe how each DTN implementation and convergence layer behaves.
>>
>> The scope of my experimentation is below for info:
>>
>> ION: UDPCL, TCPCL, LTPCL
>> DTN2: UDPCL, TCLCP, LTPCL - using LTPlib
>> IBR-DTN: UDPCL, TCPCL
>>
>> I have determined reliable, repeatable scenarios for both ION and
>> IBR-DTN, however DTN2 is producing produce a number of errors when using
>> UDP, TCP or LTP. The errors also seem to appear randomly after any number
>> of for loop iterations, e.g. (5,13,50,48,95,413, 567, 988, etc etc).
>>
>> Errors that cause dtnd to use 200% CPU and stop delivering bundles:
>> warning: deliver_front is waiting for spin lock held by (null), which has
>> reached spin limit
>> warning: Bundle::del_ref is waiting for spin lock held by (null), which
>> has reached spin limit
>> warning: Bundle::is_queued_on is waiting for spin lock held by (null),
>> which has reached spin limit
>> warning: LinkBlockSet::find_blocks is waiting for spin lock held by
>> (null), which has reached spin limit
>> warning: BundleList::erase is waiting for spin lock held by (null), which
>> has reached spin limit
>> warning: Bundle::add_ref is waiting for spin lock held by (null), which
>> has reached spin limit
>> warning: ForwardingLog::get_count is waiting for spin lock held by
>> (null), which has reached spin limit
>>
>> Errors: that cause dtnd to quit:
>> LTP:ASSERTION FAILED (is_locked_by_me()) at thread/SpinLock.cc:91
>>
>> Errors that seem to loop forever but not cause dtnd to quit or use 200%
>> CPU (This error seems to happen consistently after sending 99 LTP bundles):
>> /dtn/cl/ltp/sender error] Unable to create Sender LTP Socket in 5 seconds
>> - retrying
>>
>> To send files I am calling dtnsource in a for loop as below, which allows
>> me to adjust the time between each bundle transmission, or each block of 10
>> bundle transmissions. For UDP and LTP I am using bundles of 63K, for TCP I
>> am using 1M bundles. I have tried several combinations for $WAIT (0-5
>> seconds) and $BULKWAIT (0-20 seconds), but cannot seem to find a working
>> combination.
>>
>> for ((i=1;i<=END;i++)); do
>>     echo "($COUNT) dtnsource -s dtn://tx.dtn/a -d dtn://rx.dtn/g -b $SIZE"
>>     dtnsource -s dtn://tx.dtn/a -d dtn://rx.dtn/g -b $SIZE
>>     sleep $WAIT
>>     let "COUNT++"
>>
>>     # Sleep for x secs after each 10
>>     if (( $COUNT % 10 == 0 ))
>>     then
>>     echo "Sleeping for $BULKWAIT seconds"
>>     sleep $BULKWAIT
>>     fi
>>
>> done
>>
>> The daemon is stopped and restarted after each test, I have also tried
>> deleting and recreating the berkley DB each time, but this does not seem to
>> have much effect. I have also managed to recreate some of the errors on a
>> virtual Ubuntu test-bed, specifically Bundle::del_ref.
>>
>> After reading through the oasys SpinLock::lock code, it looks like this
>> is possibly an infinite loop that tries up to 1,000,000 times to get a
>> lock, then resets the counter to zero and puts out a warning message.
>>
>> Has anyone had a similar experience or can suggest any troubleshooting
>> tips?
>> Any suggestions to workaround or fix the problem will be very gratefully
>> received!
>>
>> Kind Regards,
>> Nik
>>
>
>