Re: [dpdk-dev] [PATCH v2 00/15] Unit tests fixes for CI

[David Marchand <david.marchand@redhat.com>]

On Tue, Jul 9, 2019 at 5:50 PM Michael Santana Francisco <
msantana@redhat.com> wrote:

> On 7/1/19 2:07 PM, Michael Santana Francisco wrote:
> >>
> >>
> >> On Mon, Jul 1, 2019 at 6:04 PM Aaron Conole <aconole@redhat.com> wrote:
> >>>>> - rwlock_autotest and hash_readwrite_lf_autotest are taking a little
> more
> >>>>>    than 10s,
> >>> Occasionally the distributor test times out as well.  I've moved them
> as
> >>> part of a separate patch, that I'll post along with a bigger series to
> >>> enable the unit tests under travis.  Michael and I are leaning toward
> >>> introducing a new variable called RUN_TESTS which will do the docs and
> >>> unit testing since those combined would add quite a bit to the
> execution
> >>> time of each job (and feel free to bike shed the name, since the
> patches
> >>> aren't final).
> >>
> >> Seeing how the distributor autotest usually takes less than a second to
> complete, this sounds like a bug.
> >> I don't think I caught this so far.
> > So I actually ran into the distributor test timing out. I agree with
> > David in that it is a bug with the test. Looking at the logs that test
> > normally finishes in less than 1/2 a second, so running to 10 seconds
> > and timing out is a big jump in run time. I ran into the issue where
> > it timedout, so I restarted the job and it finished no problem.
> > The test fails every so often for no good reason and the logs[1] dont
> > really say much. I speculate that it is waiting for a resource to
> > become available or in the worse case a deadlock. Seeing that it only
> > fails every so often and it passes when restarted I don't think it's a
> > big deal, nevertheless it's worth investing time figuring out what's
> > wrong
> >
> > [1] https://api.travis-ci.com/v3/job/212335916/log.txt
>
> I investigated a little bit on this this test. CC'd David Hunt,
>
> I was able to reproduce the problem on v19.08-rc1 with:
>
> `while sudo sh -c "echo 'distributor_autotest' |
> ./build/app/test/dpdk-test"; do :; done`
>
> It runs a couple of times fine showing output and showing progress, but
> then at some point after a couple of seconds it just stops - no longer
> getting any output. It just sits there with no further output. I let it
> sit there for a whole minute and nothing happens. So I attach gdb to try
> to figure out what is happening. One thread seems to be stuck on a while
> loop, see lib/librte_distributor/rte_distributor.c:310.
>
> I looked at the assembly code (layout asm, ni) and I saw these four
> lines below (which correspond to the while loop) being executed
> repeatedly and indefinitely. It looks like this thread is waiting for
> the variable bufptr64[0] to change state.
>
> 0xa064d0 <release+32>   pause
> 0xa064d2 <release+34>   mov    0x3840(%rdx),%rax
> 0xa064d9 <release+41>   test   $0x1,%al
> 0xa064db <release+43>   je     0xa064d0 <release+32>
>
>
> While the first thread is waiting on bufptr64[0] to change state, there
> is another thread that is also stuck on another while loop on
> lib/librte_distributor/rte_distributor.c:53. It seems that this thread
> is stuck waiting for retptr64 to change state. Corresponding assembly
> being executed indefinitely:
>
> 0xa06de0 <rte_distributor_request_pkt_v1705+592> mov    0x38c0(%r8),%rax
> 0xa06de7 <rte_distributor_request_pkt_v1705+599> test   $0x1,%al
> 0xa06de9 <rte_distributor_request_pkt_v1705+601> je     0xa06bbd
> <rte_distributor_request_pkt_v1705+45>
> 0xa06def <rte_distributor_request_pkt_v1705+607>        nop
> 0xa06df0 <rte_distributor_request_pkt_v1705+608> pause
> 0xa06df2 <rte_distributor_request_pkt_v1705+610> rdtsc
> 0xa06df4 <rte_distributor_request_pkt_v1705+612> mov    %rdx,%r10
> 0xa06df7 <rte_distributor_request_pkt_v1705+615> shl    $0x20,%r10
> 0xa06dfb <rte_distributor_request_pkt_v1705+619> mov    %eax,%eax
> 0xa06dfd <rte_distributor_request_pkt_v1705+621> or     %r10,%rax
> 0xa06e00 <rte_distributor_request_pkt_v1705+624> lea    0x64(%rax),%r10
> 0xa06e04 <rte_distributor_request_pkt_v1705+628> jmp    0xa06e12
> <rte_distributor_request_pkt_v1705+642>
> 0xa06e06 <rte_distributor_request_pkt_v1705+630> nopw
> %cs:0x0(%rax,%rax,1)
> 0xa06e10 <rte_distributor_request_pkt_v1705+640> pause
> 0xa06e12 <rte_distributor_request_pkt_v1705+642> rdtsc
> 0xa06e14 <rte_distributor_request_pkt_v1705+644> shl    $0x20,%rdx
> 0xa06e18 <rte_distributor_request_pkt_v1705+648> mov    %eax,%eax
> 0xa06e1a <rte_distributor_request_pkt_v1705+650> or     %rdx,%rax
> 0xa06e1d <rte_distributor_request_pkt_v1705+653> cmp    %rax,%r10
> 0xa06e20 <rte_distributor_request_pkt_v1705+656> ja     0xa06e10
> <rte_distributor_request_pkt_v1705+640>
> 0xa06e22 <rte_distributor_request_pkt_v1705+658> jmp    0xa06de0
> <rte_distributor_request_pkt_v1705+592>
>
>
> My guess is that these threads are interdependent, so one thread is
> waiting for the other thread to change the state of the control
> variable. I can't say for sure if this is what is happening or why the
> these variables don't change state, so I would like ask someone who is
> more familiar with this particular code to take a look
>

Ah cool, thanks for the analysis.
Can you create a bz with this description and assign it to the
librte_distributor maintainer?


-- 
David Marchand