Re: [Linux-v4.6-rc1] ext4: WARNING: CPU: 2 PID: 2692 at kernel/locking/lockdep.c:2017 __lock_acquire+0x180e/0x2260

[Sedat Dilek <sedat.dilek@gmail.com>]

On Sun, Mar 27, 2016 at 10:59 PM, Sedat Dilek <sedat.dilek@gmail.com> wrote:
> On Sun, Mar 27, 2016 at 10:48 PM, Peter Zijlstra <peterz@infradead.org> wrote:
>> On Sun, Mar 27, 2016 at 05:03:44AM -0700, Linus Torvalds wrote:
>>> Anyway, I don't think that DEBUG_LOCKS_WARN_ON() in
>>>
>>>   kernel/locking/lockdep.c:2017 __lock_acquire
>>>
>>> would be an ext4 issue, it looks more like an internal lockdep issue.
>>>
>>> Adding in the lockdep people, who will set me right.
>>
>> You are right; this is lockdep running into a hash collision; which is a
>> new DEBUG_LOCKDEP test. See 9e4e7554e755 ("locking/lockdep: Detect
>> chain_key collisions").
>
> [1] says...
>
> "Also tested with lockdep's test suite after applying the patch:
>
> [ 0.000000] Good, all 253 testcases passed! |"
>
> Where can I find this "lockdep's test suite"?
>
> When is that checking below done or what causes this?
>
> $ grep -i lock dmesg_4.6.0-rc1-1-iniza-small.txt | grep -i dep
> [    0.000000]  RCU lockdep checking is enabled.
> [    0.000000] Lock dependency validator: Copyright (c) 2006 Red Hat,
> Inc., Ingo Molnar
> [    0.000000] ... MAX_LOCKDEP_SUBCLASSES:  8
> [    0.000000] ... MAX_LOCK_DEPTH:          48
> [    0.000000] ... MAX_LOCKDEP_KEYS:        8191
> [    0.000000] ... MAX_LOCKDEP_ENTRIES:     32768
> [    0.000000] ... MAX_LOCKDEP_CHAINS:      65536
> [    0.000000]  memory used by lock dependency info: 8159 kB
> [   77.403391] WARNING: CPU: 2 PID: 2692 at
> kernel/locking/lockdep.c:2017 __lock_acquire+0x180e/0x2260
> [   77.403394] DEBUG_LOCKS_WARN_ON(chain->depth != curr->lockdep_depth
> - (i - 1))
>
> - Sedat -
>
> [1] http://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/commit/?id=9e4e7554e755

Hmm. I had several problems...

[ Building liblockdep ]

$ cd $BUILD_DIR

$ LC_ALL=C make -C tools/ liblockdep
make: Entering directory `/home/wearefam/src/linux-kernel/linux/tools'
  DESCEND  lib/lockdep
make[1]: Entering directory
`/home/wearefam/src/linux-kernel/linux/tools/lib/lockdep'
  CC       common.o
  CC       lockdep.o
  CC       preload.o
  CC       rbtree.o
  LD       liblockdep-in.o
  LD       liblockdep.a
  LD       liblockdep.so.4.6.0-rc1
make[1]: Leaving directory
`/home/wearefam/src/linux-kernel/linux/tools/lib/lockdep'
make: Leaving directory `/home/wearefam/src/linux-kernel/linux/tools'

[ run_tests.sh fails due to unsupported 'basename -s' ]

$ LC_ALL=C basename --version
basename (GNU coreutils) 8.13
Copyright (C) 2011 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>.
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.

Written by David MacKenzie.

$ cd tools/lib/lockdep/

$ LC_ALL=C ./run_tests.sh
basename: invalid option -- 's'
Try `basename --help' for more information.
... timeout: failed to run command `./tests/': Permission denied
FAILED!
rm: cannot remove `tests/': Is a directory
basename: invalid option -- 's'
Try `basename --help' for more information.
... timeout: failed to run command `./tests/': Permission denied
FAILED!
rm: cannot remove `tests/': Is a directory
basename: invalid option -- 's'
Try `basename --help' for more information.
... timeout: failed to run command `./tests/': Permission denied
FAILED!
rm: cannot remove `tests/': Is a directory
basename: invalid option -- 's'
Try `basename --help' for more information.
... timeout: failed to run command `./tests/': Permission denied
FAILED!
rm: cannot remove `tests/': Is a directory
basename: invalid option -- 's'
Try `basename --help' for more information.
... timeout: failed to run command `./tests/': Permission denied
FAILED!
rm: cannot remove `tests/': Is a directory
basename: invalid option -- 's'
Try `basename --help' for more information.
... timeout: failed to run command `./tests/': Permission denied
FAILED!
rm: cannot remove `tests/': Is a directory
basename: invalid option -- 's'
Try `basename --help' for more information.
... timeout: failed to run command `./tests/': Permission denied
FAILED!
rm: cannot remove `tests/': Is a directory
basename: invalid option -- 's'
Try `basename --help' for more information.
... timeout: failed to run command `./tests/': Permission denied
FAILED!
rm: cannot remove `tests/': Is a directory
basename: invalid option -- 's'
Try `basename --help' for more information.
... timeout: failed to run command `./tests/': Permission denied
FAILED!
rm: cannot remove `tests/': Is a directory
basename: invalid option -- 's'
Try `basename --help' for more information.
... timeout: failed to run command `./tests/': Permission denied
FAILED!
rm: cannot remove `tests/': Is a directory
basename: invalid option -- 's'
Try `basename --help' for more information.
... timeout: failed to run command `./tests/': Permission denied
FAILED!
rm: cannot remove `tests/': Is a directory
basename: invalid option -- 's'
Try `basename --help' for more information.
(PRELOAD) ... ./lockdep: line 3: ./tests/: Is a directory
FAILED!
rm: cannot remove `tests/': Is a directory
basename: invalid option -- 's'
Try `basename --help' for more information.
(PRELOAD) ... ./lockdep: line 3: ./tests/: Is a directory
FAILED!
rm: cannot remove `tests/': Is a directory
basename: invalid option -- 's'
Try `basename --help' for more information.
(PRELOAD) ... ./lockdep: line 3: ./tests/: Is a directory
FAILED!
rm: cannot remove `tests/': Is a directory
basename: invalid option -- 's'
Try `basename --help' for more information.
(PRELOAD) ... ./lockdep: line 3: ./tests/: Is a directory
FAILED!
rm: cannot remove `tests/': Is a directory
basename: invalid option -- 's'
Try `basename --help' for more information.
(PRELOAD) ... ./lockdep: line 3: ./tests/: Is a directory
FAILED!
rm: cannot remove `tests/': Is a directory
basename: invalid option -- 's'
Try `basename --help' for more information.
(PRELOAD) ... ./lockdep: line 3: ./tests/: Is a directory
FAILED!
rm: cannot remove `tests/': Is a directory
basename: invalid option -- 's'
Try `basename --help' for more information.
(PRELOAD) ... ./lockdep: line 3: ./tests/: Is a directory
FAILED!
rm: cannot remove `tests/': Is a directory
basename: invalid option -- 's'
Try `basename --help' for more information.
(PRELOAD) ... ./lockdep: line 3: ./tests/: Is a directory
FAILED!
rm: cannot remove `tests/': Is a directory
basename: invalid option -- 's'
Try `basename --help' for more information.
(PRELOAD) ... ./lockdep: line 3: ./tests/: Is a directory
FAILED!
rm: cannot remove `tests/': Is a directory
basename: invalid option -- 's'
Try `basename --help' for more information.
(PRELOAD) ... ./lockdep: line 3: ./tests/: Is a directory
FAILED!
rm: cannot remove `tests/': Is a directory
basename: invalid option -- 's'
Try `basename --help' for more information.
(PRELOAD) ... ./lockdep: line 3: ./tests/: Is a directory
FAILED!
rm: cannot remove `tests/': Is a directory

[ Patching run_tests.sh (liblockdep) ]

--- a/tools/lib/lockdep/run_tests.sh
+++ b/tools/lib/lockdep/run_tests.sh
@@ -3,7 +3,7 @@
 make &> /dev/null

 for i in `ls tests/*.c`; do
-       testname=$(basename -s .c "$i")
+       testname=$(basename "$i" .c)
        gcc -o tests/$testname -pthread -lpthread $i liblockdep.a
-Iinclude -D__USE_LIBLOCKDEP &> /dev/null
        echo -ne "$testname... "
        if [ $(timeout 1 ./tests/$testname | wc -l) -gt 0 ]; then
@@ -11,11 +11,13 @@ for i in `ls tests/*.c`; do
        else
                echo "FAILED!"
        fi
-       rm tests/$testname
+       if [ -f "tests/$testname" ]; then
+               rm -v -f tests/$testname
+       fi
 done

 for i in `ls tests/*.c`; do
-       testname=$(basename -s .c "$i")
+       testname=$(basename "$i" .c)
        gcc -o tests/$testname -pthread -lpthread -Iinclude $i &> /dev/null
        echo -ne "(PRELOAD) $testname... "
        if [ $(timeout 1 ./lockdep ./tests/$testname | wc -l) -gt 0 ]; then
@@ -23,5 +25,7 @@ for i in `ls tests/*.c`; do
        else
                echo "FAILED!"
        fi
-       rm tests/$testname
+       if [ -f "tests/$testname" ]; then
+               rm -v -f tests/$testname
+       fi
 done

...then I get...

$ LC_ALL=C ./run_tests.sh
AA... PASSED!
removed `tests/AA'
ABA... PASSED!
removed `tests/ABA'
ABBA... PASSED!
removed `tests/ABBA'
ABBA_2threads... PASSED!
removed `tests/ABBA_2threads'
ABBCCA... PASSED!
removed `tests/ABBCCA'
ABBCCDDA... PASSED!
removed `tests/ABBCCDDA'
ABCABC... PASSED!
removed `tests/ABCABC'
ABCDBCDA... PASSED!
removed `tests/ABCDBCDA'
ABCDBDDA... PASSED!
removed `tests/ABCDBDDA'
WW... PASSED!
removed `tests/WW'
unlock_balance... PASSED!
removed `tests/unlock_balance'
(PRELOAD) AA... PASSED!
removed `tests/AA'
(PRELOAD) ABA... PASSED!
removed `tests/ABA'
(PRELOAD) ABBA... PASSED!
removed `tests/ABBA'
(PRELOAD) ABBA_2threads... PASSED!
removed `tests/ABBA_2threads'
(PRELOAD) ABBCCA... PASSED!
removed `tests/ABBCCA'
(PRELOAD) ABBCCDDA... PASSED!
removed `tests/ABBCCDDA'
(PRELOAD) ABCABC... PASSED!
removed `tests/ABCABC'
(PRELOAD) ABCDBCDA... PASSED!
removed `tests/ABCDBCDA'
(PRELOAD) ABCDBDDA... PASSED!
removed `tests/ABCDBDDA'
(PRELOAD) WW... PASSED!
removed `tests/WW'
(PRELOAD) unlock_balance... PASSED!
removed `tests/unlock_balance'

BTW, how did you test to get "[ 0.000000] Good, all 253 testcases passed!" from?

In my dmesg I see...

[ 3249.552034] show_signal_msg: 189 callbacks suppressed
[ 3249.552042] liblockdep.so[15757]: segfault at 1 ip 0000000000000001
sp 00007ffe82f88078 error 14 in
liblockdep.so.4.6.0-rc1[5578fbdbd000+c000]

Hmm, Hmm, Hmm.

Empty head,
- Sedat -