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

From: Nik Ansell <[email-masked]>
Date: Sun, 24 Jan 2016 12:05:17 +0400

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

---

From: Nik Ansell <[email-masked]>
Date: Mon, 25 Jan 2016 11:19:20 +0400

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 <[email-masked]> wrote:

> warning: Bundle::del_ref 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: Bundle::add_ref is waiting for spin lock held by (null), which
> has reached spin limit
> 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
>

---

From: Nik Ansell <[email-masked]>
Date: Wed, 27 Jan 2016 19:34:40 +0400

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 <[email-masked]> wrote:

> fprintf(stderr, "warning: %s is waiting for spin lock held by %s, which
> has reached spin limit\n", lock_user, lock_holder_name_)
>
>> 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).
>>
>> warning: ForwardingLog::get_count is waiting for spin lock held by
>> 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.
>>