0.7.0 crashing with multiple "rm -rf"s running?

[jafo]

I deployed a new server and put 0.7.0 on it, and twice I've run into
issues with zfs-fuse dieing when I have multiple "rm -rf" processes
running in the same directory. Today, for example, in one process I
was doing a "rsync -av --remove-source-files src /dest", then in
another I ran "find src -depth -exec rmdir '{}' +" to copy over files
and then remove empty directories as the copy was going...

An earlier instance I think was literally an "rm -rf" from two
different processes in the same directory.

Before I spend too much time trying to replicate this, I wanted to see
if there were any thoughts about this or it was a known issue.

My plan is to set up a test system and see if I can come up with
something that replicates this in a reasonable time. It's always
happened after quite a lot of data copying has occurred, then I do
some removes, so a test system would allow me to see if I can
replicate it shortly after starting zfs-fuse.

My environment, for completeness, is: Scientific Linux 6 (RHEL clone),
64-bit, 8GB RAM, 4x 3TB drives, 8GB RAM, Intel (not ARM :-). I
believe I've had it happen both with and without the ZIL and L2ARC on
SSD (Intel X-25E).

Oh, while I'm mentioning it, I've found that you can get the 32GB
Intel X-25E drives on ebay fairly cheap, around $100 -- they'd
normally be $375 new. It certainly does seem to help with dedup, but
it's still a real system killer...

Sean

[Emmanuel Anne]

Unknown but interesting if you can reproduce it.

> --
> To post to this group, send email to zfs-...@googlegroups.com
> To visit our Web site, click on http://zfs-fuse.net/

[jafo]

On Jul 21, 5:07 am, Emmanuel Anne <emmanuel.a...@gmail.com> wrote:
> Unknown but interesting if you can reproduce it.

I've finally gotten a test system set up and was able to reproduce it
with no problems. Here's what I did:

The system is Ubuntu Natty 64-bit. I downloaded the 0.7.0 tar-file,
built, and installed. For the zfsrc, I used the stock one, unchanged.

I created a 5-drive raidz1 of /dev/sd[abcdf]2

I ran "zfsstress" on it for around 12 hours, creating 120GB worth of
files.

I killed zfsstress, and went into the directory it created. I did
"mkdir foo; mv * foo".

Then I ran: "rm -rf foo& rm -rf foo& rm -rf foo& rm -rf foo &".

It removed around 20GB worth of files, and then reported "Transport
endpoint is not connected".

At this point the zfs-fuse daemon is dead.

I was able to restart zfs-fuse, and I'm starting another run, but at
the moment it looks pretty easy to reproduce. Sorry it took so long,
I was out on vacation and needed to get a test box set up to run the
testing on.

I did bring back up that file-system and run 2 simultaneous "rm -rf"s
on it, and that completed quickly and without zfs-fuse dieing, but
note that there were a bunch of snapshots so I think no data was
actually removed.

I'll continue to play with the test box some. Running zfsstress is
probably overkill, in particular the snapshot and remove files
portions could probably be removed so it's just creating files. The
situations where I was running into problems were just copies of other
systems I had backed up to the ZFS system. I accidentally ran
multiple "rm -rf" commands in the same directory, and that's how I
initially saw it.

I'm going to try something simpler than zfsstress and see if that
produces the issue as well.

Sean

[sgheeren]

On 08/29/2011 04:15 PM, jafo wrote:
> but
> note that there were a bunch of snapshots so I think no data was
> actually removed.

not on the DMU, but on the ZPL yes, inodes are dropped. I suspect any
unreliability to be in the fuse area, not DMU (or can you reproduce this
on Solaris?)

was there a bug reported here (http://zfs-fuse.net/issues)?

[sgheeren]

On 08/29/2011 04:15 PM, jafo wrote:

> I'm going to try something simpler than zfsstress and see if that
> produces the issue as well.
>

I hope this is not some ploy to get me to accidentally wreck a system by
doing one too manty 'rm -rf' hehe

It hasn't happened for a loooooong time so... statistically speaking
it's bound to happen soon

[jafo]

On Aug 29, 11:11 am, sgheeren <sghee...@hotmail.com> wrote:
> I hope this is not some ploy to get me to accidentally wreck a system by
> doing one too manty 'rm -rf' hehe

I don't think so, but here's a small update. Today I ran this script
and also crashed zfs-fuse:

zfs create data/test; for (( i=0; i<100; i++ )); do echo copy $i;
mkdir /data/test/copy-$i; cp -ax / /data/test/copy-$i/; done; ( rm -
rf /data/test/*& rm -rf /data/test/*& rm -rf /data/test/*& rm -rf /
data/test/*& )

In other words, create a zfs, make 100 copies of the root file-system
on it, then run 4 "rm -rf"s on that in parallel. It printed out, at
the end:

rm: cannot remove `/data/test/copy-97/usr/share/pixmaps': Transport
endpoint is not connected
rm: fts_read failed: Transport endpoint is not connected

When I restarted zfs-fuse, and re-mounted the file-systems, what was
left in there was copy-96 through copy-99. For me, the root file-
system is 1.1GB, a basic Ubuntu 64-bit install with tools to build
zfs...

I figure I'll probably try a few more runs of this to make sure it's
reliably reproducable and get some more information on whether it
happens in the same places or different places.

To answer your question about whether it happens on Solaris: I don't
know, I don't have a Solaris box to try it on. I could see about
setting one up if that's an important data-point to have. I'd
probably want to try a latest copy of one of your git repos first
though, if there's likely to be any changes there. I'd also likely
want to try the "maintenance release" I saw when I looked at the
download page yesterday (I used the 0.7.0 since that was what I had
used on the system I initially noticed this on).

Thoughts?

Thanks,
Sean

[Seth Heeren]

> I don't know, I don't have a Solaris box to try it on. I could see about
> setting one up if that's an important data-point to have.

Don't bother, I have one up and running :)

> I'd also likely want to try the "maintenance release"

I don't quite remember whether there were changes in this area after
0.7.0; by all means, do try testing though.

Maint is always recommended (also for packaging); That said, it is not
going to help in this area: http://gitweb.zfs-fuse.net/?p=official;a=log;h=refs/heads/maint;hp=refs/heads/master

[Emmanuel Anne]

It reminds me of some comments in zfs_operations.c about special error cases where inodes had already been deleted. Maybe it's related to that ?

In this case it's either an assertion failure (or a VERIFY failure), or a thread creation error (very unlikely here).

To be sure you should run the zfs-fuse daemon from gdb :

build with scons debug=2

then gdb zfs-fuse

and run -n

then try to reproduce your crash, you'll see where the daemon ends in gdb.

I won't try to fix it as it is now, too long to reproduce, I don't have that much time now (and that much motivation).

2011/8/30 jafo <jaf...@gmail.com>

--
To post to this group, send email to zfs-...@googlegroups.com
To visit our Web site, click on http://zfs-fuse.net/

--
my zfs-fuse git repository : http://rainemu.swishparty.co.uk/cgi-bin/gitweb.cgi?p=zfs;a=summary

[Seth Heeren]

> It reminds me of some comments in zfs_operations.c about special error cases

me too. It'll be good that we have more of a method to reproduce this.
I'd look at issues #43/#45

Possibly the (less than optimal?) fix has to be reconsidered

Emmanuel Anne schreef:

[Seth Heeren]

> It reminds me of some comments in zfs_operations.c about special error cases

me too. It'll be good that we have more of a method to reproduce this.
I'd look at issues #43/#45

Possibly the (less than optimal?) fix has to be reconsidered

Emmanuel Anne schreef:

[jafo]

I'm definitely able to reproduce it with that script. I've grabbed
the maintenance release, built it with debug=2, and am running it
under gdb and doing another run of my script. I also re-created the
pool. Hopefully in a few hours I'll know the status of that run.

Thanks,
Sean

[jafo]

> build with scons debug=2
> then gdb zfs-fuse
> and run -n
> then try to reproduce your crash, you'll see where the daemon ends in gdb.

I've built the maintenance release, built with debug=2, and run it
under
gdb. Here's what it reports:

[... lots of New Thread messages above here ...]
[New Thread 0x7fffb8377700 (LWP 10893)]
mount request: "data", "/data", "0", ""
[New Thread 0x7fffba5a3700 (LWP 10897)]
mounting /data
detected: default_permissions
Adding filesystem 2 at mntpoint /data
mount request: "data/test", "/data/test", "0", ""
[New Thread 0x7fffb7375700 (LWP 10908)]
mounting /data/test
detected: default_permissions
Adding filesystem 3 at mntpoint /data/test
[Thread 0x7ffff6031700 (LWP 10589) exited]
[Thread 0x7ffff5830700 (LWP 10590) exited]
[Thread 0x7ffff502f700 (LWP 10591) exited]
[Thread 0x7ffff482e700 (LWP 10592) exited]
zfs-fuse: lib/libzpool/zfs_znode.c:1119: zfs_znode_free: Assertion
`((zp)->z_vnode)->v_count == 0' failed.

Program received signal SIGABRT, Aborted.
[Switching to Thread 0x7fffe6013700 (LWP 10619)]
0x00007ffff6a73d05 in raise () from /lib/x86_64-linux-gnu/libc.so.6
(gdb)

Looks indeed like an assertion, and is related to the inodes (is
"znode" the
zfs equivalent of inode?). Looks like a race where it's getting
decremented twice by "unlink()" calls from different processes.

In this case, I'm running 4 simultaneous "rm -rf" runs, and have a
quad
core CPU. I'd guess that this issue probably can't be reproduced on a
single-CPU system.

Thoughts?

Thanks,
Sean

[Hannes Landeholm]

Ouch, a text box parallelization problem. Accessing the same memory
(inodes in this case) from multiple threads without any locking in
place is not a good idea.

~Hannes

[sgheeren]

Yep it's a bug.

We've had prior symptoms with multiple deletes before (#45, #108, and possibly tangentially other issues that I had forgotten about).

Anyway, this reproduces it on my machine in average 1 minute:

time while touch /tmp/tanq/$RANDOM.{a..z}{a..z}; do rm -f /tmp/tanq/*& done

[sgheeren]

Hannes, what's that? Is there no locking? That's _bad_ ! (Hint: I'm
quite sure there is locking)

Assuming you've found the cause, I'd appreciate if you can share it. I
currently haven't the time to go actively debug it.

Cheers,
Seth

[Emmanuel Anne]

I just lost 1 hour trying to reproduce this crash with your piece of script -> no luck at all.
Tried on my normal pool first (half mirror), then created a raidz1 from 3 disk images, then tried without the buffers for small io, then without xattrs.
Then tried to change the script to produce more output on disk.
Anyway to make it short it never crashed (and I have run this script for at least 5 minutes each time).

Well my version of zfs_operations.c is now very different from the one in maint, which makes running diff between the 2 quite hard.
Anyway I won't look again at this until someone can propose an easy script like this one which can crash my version, eventually give the parameters you used (cache, type of pool, xattrs, buffers...).
Actually I still have it running in the background while typing this mail, as you can see it still doesn't crash !

2011/8/31 sgheeren <sghe...@hotmail.com>

--
To post to this group, send email to zfs-...@googlegroups.com
To visit our Web site, click on http://zfs-fuse.net/

[Emmanuel Anne]

By the way, the fact that it doesn't crash for me might very well be because of this commit :

commit 627f7b3f5a2ae2ac9bcd3de34cfce9aad1397946
Author: Sam Falkner <Sam.F...@Sun.COM>
Date:   Sun Aug 15 18:24:50 2010 +0200

    hg commit 12413:6894240 zfs has a partially deleted file

Didn't investigate very far, but from the output of gdb it looks like an internal zfs problem, something which should be fixed by sun, and this commit is not in the maint branch (although it's more than 1 year old now).

2011/8/31 Emmanuel Anne <emmanu...@gmail.com>

[sgheeren]

On 08/31/2011 11:30 AM, Emmanuel Anne wrote:
> hg commit 12413:6894240 zfs has a partially deleted file

Thx for the heads up. Will look into that tonite

[jafo]

> -> no luck at all.

Interesting. I'm pulling your branch from
http://rainemu.swishparty.co.uk/git/zfs and will try running that.

Some additional information: The run I did last night under gdb, I ran
with
200 copies of the root file-system instead of 100. This try hit the
assertion in the deletion of the first copy, where previously it has
died
in the deletion of the 97-th or so copy. I find this curious, I was
kind
of expecting it to either die at the 97th ish deletion, or the 293-rd
ish
deletion, not the first...

Running my script for 5 minutes isn't likely to show a problem, as it
spends the first, say, hour creating the data-set, and the next 20
minutes
deleting it. I haven't honestly timed it, I just start a run and then
go
off and do something else and check on it later in the day.

If you have a specific set of code you'd like me to try, or a series
of
specific sets of code, feel free to hand them off to me, and I'll run
them
however you like and send the results back as they come in.

Sorry I keep coming up with these tests that take so long to run -- at
least this is better than my last issue which took days of running to
re-create. :-)

Sean

[sgheeren]

On 08/31/2011 08:28 PM, jafo wrote:
> I find this curious, I was
> kind
> of expecting it to either die at the 97th ish deletion, or the 293-rd
> ish
> deletion, not the first...

Me too. Thanks for mentioning it. It jsut might not be a race pur sang,
but rather a (race?) condition that can leave stale inode state hanging
around. That could explain the first action tripping over that wire.

> Sorry I keep coming up with these tests that take so long to run -- at
> least this is better than my last issue which took days of running to
> re-create. :-)

No problem. I have a fast machine and installed Wormhole 5D :)

[Emmanuel Anne]

Normally you can't guess when this kind of problem happens, it's about locks, sometimes it passes, and sometimes it doesn't. You just raise the probability in some situations.

2011/8/31 sgheeren <sghe...@hotmail.com>

--
To post to this group, send email to zfs-...@googlegroups.com
To visit our Web site, click on http://zfs-fuse.net/

[jafo]

I ran it with the branch of yours that I mentioned before, and it
didn't
crash. It did produce the following output during the "rm" phase,
which is
likely to be expected:

rm: fts_read failed: No such file or directoryrm:
fts_read failed: No such file or directory
rm: fts_read failed: No such file or directory

It took 4 hours to build the directory structure (I went with 200
again), I
didn't time the rm.

What shall I try now? Is there a patch you'd like me to revert and
try
running with that removed, or some sort of a bisect? I may need some
git
pointers on how to get to that point though.

In the mean time I'm going to run another pass with this version, just
to make sure it's happy.

Thanks,
Sean

[Emmanuel Anne]

Well well, I am pretty sure this is fixed already, don't bother to find which patch does the job, it's patch from sun anyway.

All this is because there is a set of patches which has been stuck in unstable for much too long, but it's because Seth doesn't have enough time for this, and I don't want to be in charge of any official version with some package maintenance, etc...

Oh well, I guess soon or later these patches will be merged and the packages updated.

Thanks for the amazing time you spent on it anyway !

2011/9/1 jafo <jaf...@gmail.com>

--

To post to this group, send email to zfs-...@googlegroups.com
To visit our Web site, click on http://zfs-fuse.net/

[sgheeren]

On 09/01/2011 11:41 PM, Emmanuel Anne wrote:

Well well, I am pretty sure this is fixed already, don't bother to find which patch does the job, it's patch from sun anyway.

Emmanuel, there is lots of other stuff to. This is arguably a good thing. But it is also the thing that is making it a lot more work to review/merge.

All this is because there is a set of patches which has been stuck in unstable for much too long, but

Sorry to spoil it... I just tested it: rainemu/master on 64-bit  also failed all but immediately (half a minute) for me using the same test:

time while touch $(eval echo /tmp/tanq/$RANDOM.{$(seq -s, 1 100)}); do rm -f /tmp/tanq/*& done

[....]
rm: [2]-  Exit 1                  rm -f /tmp/tanq/*
cannot remove `/tmp/tanq/4986.84': Transport endpoint is not connected
rm: cannot remove `/tmp/tanq/4986.85'
real    0m34.537s
user    0m0.520s
: Transport endpoint is not connectedsys    0m0.860s

This was with: commit 2f697ca8602f, debug=1, optim=-O2, gcc 4.5.1,

PS. it seems like it may be necessary to 'hide' the terminal (or redirect output alltogether), as I have watched a run of 2m46s just while writing this email. That run only aborted when I opened another terminal tab. I assume this could be because of buffered IO to the X terminal on stderr (delaying the execution of the bash loop).

So, a more foolproof recipe for failure might be

time (while touch $(eval echo /tmp/tanq/$RANDOM.{$(seq -s, 1 100)}); do rm -f /tmp/tanq/*& done; wait) 2>&1 | tail

PS2. nevermind: an extra test run with that modified command line aborted after 2m28s:

touch: cannot touch `/tmp/tanq/20847.98': Transport endpoint is not connected
touch: cannot touch `/tmp/tanq/20847.99': Transport endpoint is not connected
touch: cannot touch `/tmp/tanq/20847.100': Transport endpoint is not connected

real    2m28.608s
user    0m2.770s
sys    0m3.640s

So I guess all that is really happening is: I have a fast machine (Intel(R) Core(TM)2 Quad CPU Q9550 @ 2.83GHz) and I run zfs-fuse backed on tmpfs for tests like these.

Now, it is high time for bed because I'll have to go work in 5 hours from now :_)

it's because Seth doesn't have enough time for this, and I don't want to be in charge of any official version with some package maintenance, etc...

Apparently, I don't have time, but you are in a hurry. Equal handicaps if you ask me :)

Thanks for the amazing time you spent on it anyway !

+1 from me, Sean

Seth

[sgheeren]

On 09/01/2011 11:41 PM, Emmanuel Anne wrote:

What shall I try now?  Is there a patch you'd like me to revert and
try
running with that removed, or some sort of a bisect?  I may need some
git
pointers on how to get to that point though.

The only interesting bisect point I can come up with now is ea6df50db0b4cfc167925ed452d2840b14ecb103^ or before;

That is the only related change I can think of right now. I think I prefer to find some time to actually debug things

(note that I need to cherry-pick the fix for issue #52 (3c64b73851) in order to compile it on natty with gcc 4.5.1)

[jafo]

> > Thanks for the amazing time you spent on it anyway !
> +1 from me, Sean

Thanks. :-)

So, I did a second run as I mentioned above, and it has aborted with
what
looks like another assertion but it seems to be in a fairly similar
portion of the code-path, probably also in the upstream ZFS code:

zfs-fuse/zfs_dir.c:674: zfs_rmnode: Assertion `0 ==
zap_remove_int(zfsvfs->z_os, zfsvfs->z_unlinkedobj, zp->z_id, tx) (0x0
== 0x2)` failed.

It's not really a big deal for me, I just noticed it during some work
on
one of my ZFS volumes and wanted to make sure it got reproduced and
documented to the extent I can. Should I create a bug with this
information in it, for either zfs-fuse or upstream ZFS itself?

Is there anything else I should run tests on?

Thanks,
Sean

[sgheeren]

On 09/02/2011 06:53 AM, jafo wrote:
> run as I mentioned above
erm... perhaps you can state exactly what you did? I haven't got much
clue as I think both me and Emmanuel have been sending multiple posts :)

Thanks

[sgheeren]

On 09/02/2011 01:55 AM, sgheeren wrote:

On 09/01/2011 11:41 PM, Emmanuel Anne wrote:

What shall I try now?  Is there a patch you'd like me to revert and
try
running with that removed, or some sort of a bisect?  I may need some
git
pointers on how to get to that point though.

The only interesting bisect point I can come up with now is ea6df50db0b4cfc167925ed452d2840b14ecb103^ or before;

That is the only related change I can think of right now. I think I prefer to find some time to actually debug things

Well - blimey.
I have run the before (50a6f36) and after (ea6df50) commits with the same flags and the following test load:

scons -C src/ debug=1 optim=-O2
time (while touch $(eval echo /tmp/tanq/$RANDOM.{$(seq -s, 1 $((2+$RANDOM/100)))}); do rm -f /tmp/tanq/*& done; wait)

It crashed 'soon' with ea6df50: 4m58s [1]. **However**, with the 'before' version (50a6f36), I couldn't make it fail.
I decided to leave it running all day _even with assertions enabled_, and a slightly more randomized load [1]:

scons -C src/ debug=1 optim=-O2
time (while touch $(eval echo /tmp/tanq/$RANDOM.{$(seq -s, 1 $((2+$RANDOM/100)))}); do rm -f /tmp/tanq/*& done; wait)

Well what dya know: it ran all day without a hitch, see this line from htop:

  PID USER     NLWP PRI  NI  VIRT   RES   SHR S CPU% MEM%   TIME+  Command
22011 root      109  20   0 1225M  148M  1908 S 111.  1.9 13h54:58 /home/sehe/custom/_ZFS/src/zfs-fuse/zfs-fuse --no-kstat-mount

It seems my intuition about this commit was just about right (I mentioned that particular fix from #43 a few days ago!). Now, jafo, have you been able to test with that (admittedly old) version? I'll have to go back to analyzing issue #43 to see what problem it solved. I do remember it being a long and complicated merge, and I'm not quite sure what will come of it.

I do feel that we might need to revert that particular merge, as, though it did fix that issue, it strikes me as interesting enough that there have since been several (other) instabilities around deleted files. I'd really want to know more about the history of this code. I might go visit the BSD/Solaris codes to see the most current state of affairs.

Oh well, at least we have some solid pointers now: the probable introduction of _this_ problem, and a quick and easy method to reproduce it.

Cheers,
Seth


[1] output:

touch: cannot touch `/tmp/tanq/23733.98': Transport endpoint is not connected
touch: cannot touch `/tmp/tanq/23733.99': Transport endpoint is not connected
touch: cannot touch `/tmp/tanq/23733.100': Transport endpoint is not connected

real    4m58.076s
user    0m5.780s
sys    0m8.430s

[2] pretty way to monitor that:

watch -n .1 ls /tmp/tanq -C

[sgheeren]

On 09/02/2011 11:56 PM, sgheeren wrote:

I decided to leave it running all day _even with assertions enabled_, and a slightly more randomized load [1]:

scons -C src/ debug=1 optim=-O2

I meant to show that I used debug=2 for the whole day (~14h) stress test. Copy/paste error!

[Emmanuel Anne]

Assuming the bug is still here (and apparently it is), then the only possiblity seems to be to add a new lock in the unlink function in zfs_operations.c, because messing with the forest of zfs specific locks would really be crazy. But if you really want to try that, go ahead, fixing it this way shouldn't be too hard, even if it won't be the most efficient way.

I'd say weather is way too warm for me to do that now, maybe I'll take another look in a few days.

2011/9/2 sgheeren <sghe...@hotmail.com>

--

To post to this group, send email to zfs-...@googlegroups.com
To visit our Web site, click on http://zfs-fuse.net/

[sgheeren]

On 09/03/2011 12:45 AM, Emmanuel Anne wrote:
>
> Assuming the bug is still here (and apparently it is), then the only
> possiblity seems to be to add a new lock in the unlink function in
> zfs_operations.c, because messing with the forest of zfs specific
> locks would really be crazy. But if you really want to try that, go
> ahead, fixing it this way shouldn't be too hard, even if it won't be
> the most efficient way.
> I'd say weather is way too warm for me to do that now, maybe I'll take
> another look in a few days.

I wasn't thinking about adding any locking really. I was thinking about
finding the cause. Then fix it :)

[Emmanuel Anne]

Ah so you finally found a version which never crashes then ?
Well for now I still wasn't able to crash mine.
Currently testing with your lastest bit of script on a raidz disk image (3 disk images actually), and it runs like a charm.
If there is really a bug around here, the less I can say is that it's not easy to at least reproduce.
Oh well, I'll leave the script running while I go and take a shower, but if I can't reproduce it at all here, I'll just give it up completely.

Did you at least try to just do some testing in C instead of a shell script ?
The advantage a C test is that you have a finer granularity, you can have a few children processes (or threads) synchronized to run exactly a the same time a serie of unlink commands, probably much more efficient to track a bug here if there is one (still never saw it so far !).

2011/9/3 sgheeren <sghe...@hotmail.com>

--
To post to this group, send email to zfs-...@googlegroups.com
To visit our Web site, click on http://zfs-fuse.net/

[sgheeren]

On 09/04/2011 11:24 AM, Emmanuel Anne wrote:
> Currently testing with your lastest bit of script on a raidz disk
> image (3 disk images actually), and it runs like a charm.
> If there is really a bug around here, the less I can say is that it's
> not easy to at least reproduce.

What are your specs/OS details out of curiosity? I might be able to
leverage the information

Please include

uname -a
cat /proc/cpuinfo

libc version
compilation flags
zfsrc

Also of note are pool options. I run a vanilla pool (no pool/fs options,
no zfsrc and just a stripe). As you know I can reproduce it in under 5
minutes at will. I'll try on another box or two for kicks.

[Emmanuel Anne]

Let's play this game then... :

2011/9/4 sgheeren <sghe...@hotmail.com>

On 09/04/2011 11:24 AM, Emmanuel Anne wrote:
> Currently testing with your lastest bit of script on a raidz disk
> image (3 disk images actually), and it runs like a charm.
> If there is really a bug around here, the less I can say is that it's
> not easy to at least reproduce.

What are your specs/OS details out of curiosity? I might be able to
leverage the information

Please include


uname -a

 Linux athlon64 3.0.0 #29 SMP PREEMPT Sun Jul 31 10:27:43 CEST 2011 x86_64 GNU/Linux

cat /proc/cpuinfo

processor    : 0
vendor_id    : AuthenticAMD
cpu family    : 16
model        : 5
model name    : AMD Athlon(tm) II X4 630 Processor
stepping    : 2
cpu MHz        : 800.000
cache size    : 512 KB
physical id    : 0
siblings    : 4
core id        : 0
cpu cores    : 4
apicid        : 0
initial apicid    : 0
fpu        : yes
fpu_exception    : yes
cpuid level    : 5
wp        : yes
flags        : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush mmx fxsr sse sse2 ht syscall nx mmxext fxsr_opt pdpe1gb rdtscp lm 3dnowext 3dnow constant_tsc rep_good nopl nonstop_tsc extd_apicid pni monitor cx16 popcnt lahf_lm cmp_legacy svm extapic cr8_legacy abm sse4a misalignsse 3dnowprefetch osvw ibs skinit wdt npt lbrv svm_lock nrip_save
bogomips    : 5588.25
TLB size    : 1024 4K pages
clflush size    : 64
cache_alignment    : 64
address sizes    : 48 bits physical, 48 bits virtual
power management: ts ttp tm stc 100mhzsteps hwpstate

(x4), I won't copy the same info for cpus 1 to 3.
 

libc version

2.13-7 debian testing
 

compilation flags

scons debug=2
 

zfsrc

 vdev-cache-size = 10
max-arc-size = 400
fuse-attr-timeout = 3600
fuse-entry-timeout = 3600
fuse-mount-options = default_permissions,nonempty
stack-size = 32
no-kstat-mount

Also of note are pool options. I run a vanilla pool (no pool/fs options,
no zfsrc and just a stripe). As you know I can reproduce it in under 5
minutes at will. I'll try on another box or two for kicks.

It's a vanilla pool as well created from 3 disk images :
dd if=/dev/zero of=d1 bs=1M count=100
same thing for d2 and d3
and then zpool create raid raidz d1 d2 d3
and it's the master branch of my repository.

run with the patch_debug to be able to run this while the normal zfs-fuse daemon is running. Also tested it with the normal zfs-fuse daemon before, but since I thought thie time it would crash, I prefered a separated daemon with a separate pool... but it didn't crash.

I am starting it again now, maybe I'll have more luck this time ! ;-)

[Emmanuel Anne]

Errr, it didn't crash in 1 hour and 30 minutes. I stop it here for this time !

2011/9/4 Emmanuel Anne <emmanu...@gmail.com>

[sgheeren]

On 09/04/2011 09:52 PM, Emmanuel Anne wrote:
> Errr, it didn't crash in 1 hour and 30 minutes. I stop it here for
> this time !

just for checks: revision is 2f697ca8602f47fbd0d832d92e338b3a1edd9d60 ?

[sgheeren]

On 09/04/2011 08:30 PM, Emmanuel Anne wrote:
> Let's play this game then... :

ermm... what game; but thanks for the answers

Pretty much equivalent of what I'm testing with, but

1. you might have larger thread stacks (need to check) and
2. I'm running on tmpfs
3. I'm not using raidz (or any redundancy, for that matter)

The timings might just be a tad slower for you, lowering the odds of
seeing this?

[Emmanuel Anne]

Yes it's this revision.
Restarted on tmpfs then, with a simple pool on 1 disk image, no redundancy, but I believe a slow access would make this crash more likely to happen (because slow unlink -> more chances of contention).
Anyway so far no crash.

And it's a kind of game of mouse and cat. The mouse is this bug... !

2011/9/4 sgheeren <sghe...@hotmail.com>

--
To post to this group, send email to zfs-...@googlegroups.com
To visit our Web site, click on http://zfs-fuse.net/

[sgheeren]

On 09/04/2011 08:18 PM, sgheeren wrote:

I'll try on another box or two for kicks.

I just did.

============ VPS one (linode) ===================

Linux li68-156 2.6.39.1-linode34 #1 SMP Tue Jun 21 10:29:24 EDT 2011 i686 i686 i386 GNU/Linux
Ubuntu 11.04
CPU: 4x Xeon L5420@ 2.50GHz
rainemu/master 2f697ca Replace remount by drop_caches (on rollback)
debug=2 optim=-O2
'real' disk, no tmpfs, stripe only

It failed under 1 second with an assertion:

#4  0x0816dba6 in sa_lookup (hdl=0x0, attr=9, buf=0x9db1d0a8, buflen=8) at lib/libzpool/sa.c:1436
#5  0x0806c3d9 in zfs_rmnode (zp=0x8429ce68) at zfs-fuse/zfs_dir.c:625
#6  0x08150a9b in zfs_zinactive (zp=0x8429ce68) at lib/libzpool/zfs_znode.c:1332
#7  0x0808ca7d in zfs_inactive (vp=0xb7c19ca0, cr=0x8236e7c, ct=0x0) at zfs-fuse/zfs_vnops.c:4325
#8  0x081a052f in fop_inactive (vp=0xb7c19ca0, cr=0x8236e7c, ct=0x0) at lib/libsolkerncompat/vnode.c:910
#9  0x0819fe0f in vn_rele (vp=0xb7c19ca0) at lib/libsolkerncompat/vnode.c:652
#10 0x0809039e in zfsfuse_getattr (req=0x8245440, ino=806, fi=0x0) at zfs-fuse/zfs_operations.c:334
#11 0xb7fa0e86 in ?? () from /lib/libfuse.so.2
#12 0xb7f9f728 in ?? () from /lib/libfuse.so.2
#13 0xb7fa3526 in fuse_session_process () from /lib/libfuse.so.2
#14 0x0808e4e1 in zfsfuse_listener_loop (arg=0x0) at zfs-fuse/fuse_listener.c:297
#15 0xb7fbce99 in start_thread () from /lib/i386-linux-gnu/libpthread.so.0
#16 0xb7d4073e in clone () from /lib/i386-linux-gnu/libc.so.6

With debug=1, a SIGSEGV takes about equally as long and takes place at the same site:#0  0xb7fbf33d in pthread_mutex_lock () from /lib/i386-linux-gnu/libpthread.so.0

#1  0x08124475 in mutex_enter (mp=0x0) at lib/libsolkerncompat/mutex.c:63
#2  0x081093d2 in sa_lookup (hdl=0x0, attr=9, buf=0xafb400b0, buflen=8) at lib/libzpool/sa.c:1437
#3  0x0806a46d in zfs_rmnode (zp=0x7aa6cb88) at zfs-fuse/zfs_dir.c:625
#4  0x0808175f in zfs_inactive (vp=0xb7c341f8, cr=0x81a7918, ct=0x0) at zfs-fuse/zfs_vnops.c:4325
#5  0x0812c18e in fop_inactive (vp=0xb7c341f8) at lib/libsolkerncompat/vnode.c:910
#6  vn_rele (vp=0xb7c341f8) at lib/libsolkerncompat/vnode.c:652
#7  0x08088d20 in zfsfuse_getattr (req=0x81b11c0, ino=260, fi=0x0) at zfs-fuse/zfs_operations.c:334
#8  0xb7fa0e86 in ?? () from /lib/libfuse.so.2
#9  0xb7f9f728 in ?? () from /lib/libfuse.so.2
#10 0xb7fa3526 in fuse_session_process () from /lib/libfuse.so.2
#11 0x080839d8 in zfsfuse_listener_loop (arg=0x0) at zfs-fuse/fuse_listener.c:297
#12 0xb7fbce99 in start_thread () from /lib/i386-linux-gnu/libpthread.so.0

Same crash with raidz (2 devs), raidz2 (3 vdevs)

Will post other VPS findings soon

[Emmanuel Anne]

Well obviously if I can't reproduce it, I can't fix it. You'll be on your own on this one then unless you find a way for me to do it !

I'd say you should try with exactly the same zfsrc though, especially if you didn't use any zfsrc as you said the 1st time. The cache configuration might matter.

2011/9/4 sgheeren <sghe...@hotmail.com>

--

To post to this group, send email to zfs-...@googlegroups.com
To visit our Web site, click on http://zfs-fuse.net/

[Emmanuel Anne]

And indeed when I removed my zfsrc I was able to reproduce the crash, after 1 minute 9 seconds though, not immediate.
It seems to be really hard one... !

2011/9/4 Emmanuel Anne <emmanu...@gmail.com>

Well obviously if I can't reproduce it, I can't fix it. You'll be on your own on this one then unless you find a way for me to do it !

[sgheeren]

On 09/04/2011 11:57 PM, Emmanuel Anne wrote:
> The cache configuration might matter
That's the one.

Adding a meager '-a 0.00000001' to the command line seems to inhibit the
problem. That explains why you don't see it. I'd still like to go the
real cause, but meanwhile I suppose -a 0.00000001 should be an
acceptable workaround.

I'll leave it running for a good few hours to see (statistically) how
big of an improvement of the error rate this is.

[Emmanuel Anne]

Yeah a really tricky one to fix then, there might be a problem in the way the locking is done in some functions from zfs_operations.c which are not called so often when this cache is enabled.

2011/9/5 sgheeren <sghe...@hotmail.com>

--
To post to this group, send email to zfs-...@googlegroups.com
To visit our Web site, click on http://zfs-fuse.net/

[sgheeren]

On 09/05/2011 12:27 AM, Emmanuel Anne wrote:
> Yeah a really tricky one to fix then, there might be a problem in the
> way the locking is done in some functions from zfs_operations.c which
> are not called so often when this cache is enabled.

my thought exactly. Moreover, it appears to be something that was
introduced in commit ea6df50db0b4cfc167925ed452d2840b14ecb103

[Emmanuel Anne]

Well, you found everything then, I guess you just didn't have enough free time to finish it, so here are the results :

it produces this one line patch :

--- start ---

diff --git a/src/zfs-fuse/zfs_operations.c b/src/zfs-fuse/zfs_operations.c

index e446c73..032b9cf 100644

--- a/src/zfs-fuse/zfs_operations.c

+++ b/src/zfs-fuse/zfs_operations.c

@@ -1925,7 +1925,7 @@ static void zfsfuse_access(fuse_req_t req, fuse_ino_t ino, int mask)

 

        znode_t *znode;

 

-       error = zfs_zget(zfsvfs, ino, &znode, B_TRUE);

+       error = zfs_zget(zfsvfs, ino, &znode, B_FALSE);

        if(error) {

                ZFS_EXIT(zfsvfs);

                /* If the inode we are trying to get was recently deleted

--- end ---

I tested both issue 43 and 45, without any zfsrc file to be sure, and they work as expected with this patch applied.

Now I am not even sure this  ea6df50db0b4cfc167925ed452d2840b14ecb103 commit is still relevant (there were a lot of changes since then in the snapshot/rollback logic), I wanted to try a revert on it to be sure, but it produces a lot of errors. It's not hard to revert it manually though if you are really curious, I might do that later to be sure.

You might want to test this on your system because it seems to reproduce this crash much faster than mine, but for mine with this 1 line patch applied and no zfsrc it's impossible to crash zfs-fuse with your piece of script.

2011/9/5 sgheeren <sghe...@hotmail.com>

--

To post to this group, send email to zfs-...@googlegroups.com
To visit our Web site, click on http://zfs-fuse.net/

[Emmanuel Anne]

And it crashed just after posting this mail, 6 minutes !

So it produces this 2 lines patch then, need to remove also the line in zfsfuse_setattr.

(diff attached).

I made a few more tests as well :

issue 43 can't seem to be reproduced anymore at all, as I said the logic of snapshot/rollback changed a lot.

But issue 45 can be reproduced if you revert a few more zfs_zget lines.

I'd say there might be a better solution than these zfs_zget lines though, this is clearly related to cache (fstat is stat by a file descriptor, the idea is that as long as the file descriptor remains opened, the data remains in the cache). But oh well, the -a variable takes a timeout, and here it would be a cache which expires only when the file handle is closed, which would be tricky.

So it's probably better to leave it like this, issue 43 and 45 both work here, and your script doesn't crash anything even without zfsrc so everyone is happy.

2011/9/5 Emmanuel Anne <emmanu...@gmail.com>

[sgheeren]

On 09/05/2011 07:38 AM, Emmanuel Anne wrote:
> as I said the logic of snapshot/rollback changed a lot.

yeah you just merged the fix using drop_caches :)

[sgheeren]

On 09/05/2011 07:38 AM, Emmanuel Anne wrote:

> (diff attached).
will read tonite

[sgheeren]

On 09/05/2011 07:38 AM, Emmanuel Anne wrote:

> I'd say there might be a better solution than these zfs_zget lines
> though, this is clearly related to cache (fstat is stat by a file
> descriptor, the idea is that as long as the file descriptor remains
> opened, the data remains in the cache).

precisely.