xfs/277 endlessly looping in _require_xfs_io_command

HI folks,

I was wondering if anyone else had seen this problem, because it's got me absolutely stumped. One of my test VMs is having a really weird livelock in xfs/277. It's getting stuck in an endless loop burning the entire CPU in a the 277 process (i.e. running bash). What it is stuck on makes no sense to me, nor does the looping behaviour, and I can only reproduce it on this one machine.

The code in question:

        "fsmap" )
                testio=`$XFS_IO_PROG -f -c "fsmap" $testfile 2>&1`
                echo $testio | grep -q "Inappropriate ioctl" && \
                        _notrun "xfs_io $command support is missing"

Is pretty simple and obvious - not a lot to go wrong. set -x shows the last command in the output file to be the fsmap command. $test_io has about 5000 lines of output in it.

I did some testing to isolate the problem. This exits having executed the fsmap command just fine:

        "fsmap" )
                testio=`$XFS_IO_PROG -f -c "fsmap" $testfile 2>&1`
                exit

But this never exits and it starts burning down teh CPU:

        "fsmap" )
                testio=`$XFS_IO_PROG -f -c "fsmap" $testfile 2>&1`
                echo $testio
                exit

Yeah, echoing the output of the fsmap command seems to cause bash to enter an endless loop of some kind. Well, it's not endless, because every 30s or so the process dies and a new child process runs the same loop again. Attaching strace to one of these processes:

......
open(".", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 3 fstat(3, {st_mode=S_IFDIR|0755, st_size=139264, ...}) = 0

getdents(3, /* 1024 entries */, 32768)  = 32744
getdents(3, /* 1023 entries */, 32768)  = 32752
getdents(3, /* 1023 entries */, 32768)  = 32744
getdents(3, /* 1021 entries */, 32768)  = 32768
getdents(3, /* 1022 entries */, 32768)  = 32744
getdents(3, /* 1022 entries */, 32768)  = 32768
getdents(3, /* 401 entries */, 32768)   = 12840
getdents(3, /* 0 entries */, 32768)     = 0
close(3)                                = 0
open(".", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFDIR|0755, st_size=139264, ...}) = 0
getdents(3, /* 1024 entries */, 32768)  = 32744
getdents(3, /* 1023 entries */, 32768)  = 32752
getdents(3, /* 1023 entries */, 32768)  = 32744
getdents(3, /* 1021 entries */, 32768)  = 32768
getdents(3, /* 1022 entries */, 32768)  = 32744
getdents(3, /* 1022 entries */, 32768)  = 32768
getdents(3, /* 401 entries */, 32768)   = 12840
getdents(3, /* 0 entries */, 32768)     = 0
close(3)                                = 0
open(".", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFDIR|0755, st_size=139264, ...}) = 0
getdents(3, /* 1024 entries */, 32768)  = 32744
getdents(3, /* 1023 entries */, 32768)  = 32752
getdents(3, /* 1023 entries */, 32768)  = 32744
getdents(3, /* 1021 entries */, 32768)  = 32768
getdents(3, /* 1022 entries */, 32768)  = 32744
getdents(3, /* 1022 entries */, 32768)  = 32768
getdents(3, /* 401 entries */, 32768)   = 12840
getdents(3, /* 0 entries */, 32768)     = 0
close(3)                                = 0

.....

bash is running around in a tight loop running readdir() on some unknown directory over and over again. I can't work it out - this is the only machine that does it, and it I can't reproduce it outside of running xfs/277 from xfstests...

I'm outta ideas - I've got no idea what the hell is going wrong here. Anyone got any ideas?

Cheers,

Dave.

Dave Chinner
[email protected]

FWIW, the trigger for this was enabling rmap+reflink on the test device on this machine for the first time. Hence this is the first time the test has been run on that machine...

Cheers,

Dave.

Dave Chinner
[email protected]

TL;DR: this is a result of bugs in the xfstests code. "echo $var" results in $var being evaluated for glob/regex matches with files in the current working directory.

Longer: the fsmap
output contains test like [1234..5678] on every line, and there were 5,000 lines of output being generated with about 100k of characters inside [] brackets. If you run 'echo [1234]', it
does not output '[1234]' to the console - it treats [1234] as a glob and goes searching the current working directory for matches. That's where the readdir output comes from.

So:

$ echo foo [1234..5768] bar
foo 1 bar
$ ls -l |grep " 1$"
-rw-r--r-- 1 dave dave         35 Apr 14  2010 1
$

The "1" is output because it matches a file in the local directory.

and if I strace the echo command. I see:

open(".", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 3 fstat(3, {st_mode=S_IFDIR|0755, st_size=28672, ...}) = 0 getdents(3, /* 1109 entries */, 32768) = 31656
getdents(3, /* 0 entries */, 32768) = 0
close(3) = 0
write(1, "foo 1 bar\n", 10) = 10

So, that's where the readdir comes from. Doesn't explain the slowness, or why it doesn't reproduce in a interactive shell or on any other machine.

So, look at what directory it is running in ($here, the root of the xfstests installation) and now add other xfstests bugs that havei resulted in ~6500 test files being dumped in $here.

(generic/109 is one of the culprits)

Now we have ~100k characters being matched against ~6500 filenames. There's the slowness. I simply wasn't patient enough to wait for it.

One git clean -f -d later, and the test now runs and completes in 4s.

So, what's the bug in xfstests? The usual bug in shell programs:i missing variable quoting.

$ echo foo [1234..5768] bar 
foo 1 bar
$ echo "foo [1234..5768] bar"
foo [1234..5768] bar

Cheers,

Dave.

Dave Chinner
[email protected]

Oh, so it looks like you're in _require_xfs_io_command(). I was hunting around for this code in xfs/277. :P

...

Heh, that sounds pretty strange. Does your test dev have a pre-existing $testfile? Have you tried to execute the associated code in an independent bash script? E.g., I'd probably try to do something like mount your test dev then run:

	XFS_IO_PROG=...
	testfile=...

	testio=`$XFS_IO_PROG -f -c "fsmap" $testfile 2>&1`
	echo $testio

... from a separate script using hardcoded values from the xfstests environment, and see what happens..?

Brian

Oh, sorry, I forgot to paste the function name.

Nope, the test file is "$pid.xfs_io". I've got several of them in $TEST_DIR from killing tests that hung.

Yes. Doesn't fail from the command line, with unique new files or the files created from _require_xfs_io_command.

... and it doesn't fail from a #!/bin/bash script.

I can only reproduce it from running xfs/277, and only on this machine. That's what's got me stumped.

Cheers,

Dave.

Dave Chinner
[email protected]