crash hunting: threading bug fix proposal
sgheeren
------- summary
The attached patch fixes for me: daemon/userland crash, daemon deadlock,
spurious 'Bad address' messages (i.e. , problems under heavy load). Now
read on for the cautions (I'm basing this fix on educated guesses).
Still, the results are pretty ok, for me!
------- /summary
I may be onto an important stability issue - that people have been
reporting in various forms:
1. under stress,
1.1 userland tools may
(a) hang
(b) crash
(c) abort with a message saying
Out of memory
Bad address
'no datasets available'
1.2 zfs-fuse daemon my crash (especially in debug=2 since some
asserts catch inconsistent state) due to either asserts broken or the
ioctl handler experiencing a SIGPIPE (generic sockets error getting
translated into EFAULT -> "Bad address" on zfsfuse_socket.c (see xcopyin
and xcopyout).
I have been able to reproduce all the scenarios listed up till here. I
have been revisiting old stability threads and some issues.
Possibly related issues are:
1. helgrind reporting lots of ominous (false) problems in zfs-fuse
2. destroying datasets may hang/crash during zfs send
3. scrub may behave erratically during other operations (even on
other pools)
I currently have a fix that WorksForMe(tm) and is excruciatingly simple.
It appeared to me many issues were converging on the
zfsfuse_socket.c/zfs-fuse/cmd_listener.c implementation. I noticed that
cur_fd is a static, implying that it's use will be synchronized (see
mainly cmd_ioctl_req). However I have not been able to find proof of
this. In fact, I suspect that the fuse model used to be singlethreaded,
but may have been switched to multi-threading[1].
My entire fix consists of using GNU C builtin concept of thread-local
storage (see attached patch).
Now it is something of a tentative. I personally do not know what cur_fd
is supposed to be. I'm guessing it it matching up a fuse session to
libzfs socket connections (but I might be entirely off here).
*****
REQUEST FOR REVIEW: I'd really appreciate if someone with at least a bit
more libfuse-fu (Riccardo Correia? Are you there) than me, could
validate my thinking here?
Also, can anybody shed light on whether it is ok to use the
(non-portable) __thread declaration specifier in zfs-fuse codebase?
*****
I _have_ established:
- cur_fd is not a fixed value especially under heavy load it easily
switches between some 5 different values.
- I think I remember cmd_ioctl_req is getting 'called-back' from
fuse_session_process which is explicitely _not locked_ under mutex
(mtx). This is definitely not occurring on a single thread.
***** RESULTS:
I went from not being able to sustain a bonnie++ run with default
settings (on a new, default pool) with another terminal running zpool
iostat -v 1 for more than 10 seconds without resulting in:
1. zpool segfaulting
2. zfs-fuse daemon left being deadlocked or crashed
After applying the fix, the bonnie test+zpool iostat have been running
ever since I started typing this post (20 minutes+). It is currently at
the 'Reading with getc()...' stage. I'll let you know my further results.
PS. I'm going to consolidate these findings in a google-document later.
I will enumerate all referenced threads on the user list and the related
issues. I think this might be the stability fix we were looking for so
long now.
Ok, social time (weekend) now, so I'll simply press the send button NOW
[1] the support for multithreading inside libfuse is much debated, see
the fuse dev list
Ricardo M. Correia
In my original zfs-fuse code (and I suspect the current one as well,
unless you significantly changed it), cur_fd is *the* file descriptor
(yes, the only one) that the zfs-fuse daemon has for communication
between itself and libzfs (used by zpool and zfs).
This means that it's impossible to have 2 zpool/zfs commands (which
communicate with the zfs-fuse daemon) running at the same time, i.e.,
they will be serialized such that the second command will appear to
block/hang.
When I was working on porting Lustre to userspace and to ZFS, I
completely reimplemented this code such that it would allow an unlimited
number of concurrent zpool/zfs commands, but I never got the change to
merge this code into zfs-fuse as there were significant differences in
both code bases and I just didn't have enough time.
As for your fix, I don't believe that is the correct solution.. :-)
With your fix, each zfs-fuse thread will maintain its own file
descriptor for communication with libzfs.. and this is OK if you could
guarantee that any part of the ZFS code which reads or writes into the
file descriptor (i.e. any part of the ZFS code which uses
xcopyin()/xcopyout()/copyinstr()) runs in the same thread context as the
thread that received the socket connection, which may or may not be true
in the current implementation, but that is certainly not the expectation
of the underlying Solaris/ZFS implementation.
In other words, it should be possible for the ZFS code to do
xcopyin()/xcopyout()/copyinstr() from a thread different than the thread
which received the socket connection, but I think that won't work with
your fix.
If you could guarantee that this never happens, by checking the code and
by adding some additional VERIFY() statements which made sure that
you're communicating with the right process, then it should be OK to do
what you did. But if you don't add this additional verification, you'll
run the risk of getting strange and subtle errors due to doing
xcopyin()/xcopyout() to a different zfs/zpool process than what the ZFS
code intended...
HTH,
Ricardo
Ricardo M. Correia
Now that I think of it, in the Solaris ZFS implementation I think it's
only possible for the kernel thread context which received the ioctl()
call to do any copyin()/copyout().
So I *think* your fix should be safe. That said, I don't understand how
it fixes any of the problems you mentioned.
Anyway, I guess the next step would be to implement multi-threaded
ioctl() handling in zfs-fuse/cmd_listener.c. Note that this is
completely independent from the libfuse event loop, which should already
be multi-threaded.
This event loop (listener_loop()) only exists for ioctl() call emulation
and for mount requests from the zfs command, i.e., it's strictly for
handling any communication between zpool/zfs/libzfs and zfs-fuse.
HTH,
Ricardo
sgheeren
Hi sghereen,
I have taken some more time to give the code another look.
To make things as easy as possible, I went back to your version 0.5.0 just so we both know what we are looking at.
I could not reproduce 'my favourite' crashes[1] with your 0.5.0 version. So I'm currently trying to bisect where the problem got introduced. [3]
I hope you don't mind if I want to discuss a little more. I'll do my very best to keep it brief.
In my original zfs-fuse code (and I suspect the current one as well, unless you significantly changed it), cur_fd is *the* file descriptor (yes, the only one) that the zfs-fuse daemon has for communication between itself and libzfs (used by zpool and zfs).
Aren't you perhaps confusing
*ioctl_fd (the _listening_ socket, which _is_ the only one indeed)
and
cur_fd (the accepted connection) <-- accept(*ioctl_fd)
If I'm not making sense, I'm happy to elaborate.
If you just meant that cur_fd should not change in the context of a single request, see below.
(1) as mentioned, under load many different values cur_fd occur;
(2) the only two places where cur_fd is being written to are inside cmd_ioctl_req:
44 static int cmd_ioctl_req(int sock, zfsfuse_cmd_t *cmd)(3) the assertion VERIFY(cur_fd >= 0) was being failed, e.g.
45 {
46 dev_t dev = {0};
47
48 cur_fd = sock;
49 int ioctl_ret = zfsdev_ioctl(dev, cmd->cmd_u.ioctl_req.cmd, (uintptr_t) cmd->cmd_u.ioctl_req.arg, 0, NULL, NULL);
50 cur_fd = -1;
51
52 return zfsfuse_socket_ioctl_write(sock, ioctl_ret);
53 }
/* This should catch stray xcopyout()s in the code.. */
VERIFY(cur_fd >= 0);
Now this _wasn't_ the case of stray xcopyout()s because cmd_ioctl_req was found on the stack in all cases. This must mean that the calls are not on a single thread [2].
My attempts to _prove_ this failed to date, gdb is not happy about so many threads and helgrind produced less than usable results, to to say :)
Now, the corroborating evidence is strong, in the fact that changing the curr_fd to a thread-local removed the reproducible crashes from 0.6.0.
If you have any more thoughts after reading this background, I'd be happy to know. Otherwise, you can just await my bisection results...
Regards,
Seth Heeren
------------- [1] I could _not_ reproduce the bonnie++ -d /tank & zpool iostat -v 1 crash under 60s with zfs-fuse-0.5.0 In fact I let the bonnie++ benchmark run. Writing is _so much slower_ (1/3rd) that I suppose the timing is incomparable. [2] or the memory location of cur_fd is being clobbered externally. The code doesn't show aliasing so this could only happen with uninitialized pointers or buffer overruns. Not likely without other symptoms? [3] I have a feeling that the fuse 26 upgrade is gonna be it. That introduced 'channels' (which I don't know much about)
Emmanuel Anne
1st, thanks for the info about __thread, I didn't know that, it could be usefull.
So what you very short patch does is that it makes the variable local to each thread. The immediate question which comes out of it is : are you 100% sure that there are no cases where the reply comes from a thread different from the one which received the request ? I'd say it's unlikely, but I can't be sure at 100% on my side, and even Ricardo has doubts apparently !
My fix of this problem is in commit 67aca02eef8de9364be19e8a4f8cfa210bfd7910
git log -p 67aca02eef8de9364be19e8a4f8cfa210bfd7910 -1 to have a look at it.
What it does is to comment out entierly the reply in the middle of zfs_write which seems to come from nowhere.
At the very beginning when we got the code from Ricardo, this particular piece of code was not even testing cur_fd so it crashed because most of the time it tried to write to a null socket (or a closed one).
So the 1st fix was to just test cur_fd to be sure it was opened before executing this code.
But in fact in linux this code should NEVER be executed, it has nothing to do here.
The comments from sun say :
/*
* If dmu_assign_arcbuf() is expected to execute with minimum
* overhead loan an arc buffer and copy user data to it before
* we enter a txg. This avoids holding a txg forever while we
* pagefault on a hanging NFS server mapping.
*/
I didn't understand everything here, but a pagefault ?
The thing to understand is that this bug occurs if you get a request from fuse and at the same time an ioctl from the listener_loop, it's not 2 ioctls from listener_loop at the same time.
So well I'd say your code probably works everywhere even if I can't be sure of it, because it's very unlikely that a thread calling zfs_write will have cur_fd initialised. But I prefer to address the problem directly, and disable this piece of code for my peace of mind... !
--
To post to this group, send email to zfs-...@googlegroups.com
To visit our Web site, click on http://zfs-fuse.net/
--
zfs-fuse git repository : http://rainemu.swishparty.co.uk/cgi-bin/gitweb.cgi?p=zfs;a=summary
sgheeren
Yes it's normal that you can't reproduce it with 0.5.0, this bug is from the june 2009 version (the tar.gz that Ricardo posted on the list and that I took as a base when I started to use zfs-fuse !).
1st, thanks for the info about __thread, I didn't know that, it could be usefull.
So what you very short patch does is that it makes the variable local to each thread. The immediate question which comes out of it is : are you 100% sure that there are no cases where the reply comes from a thread different from the one which received the request ? I'd say it's unlikely, but I can't be sure at 100% on my side, and even Ricardo has doubts apparently !
Also the code evidence (see my reply to Ricardo) is quite overwhelming. The way cmd_ioctl_req sets/unsets the cur_fd var pretty much tells the whole story.
My fix of this problem is in commit 67aca02eef8de9364be19e8a4f8cfa210bfd7910
git log -p 67aca02eef8de9364be19e8a4f8cfa210bfd7910 -1 to have a look at it.
What it does is to comment out entierly the reply in the middle of zfs_write which seems to come from nowhere.
At the very beginning when we got the code from Ricardo, this particular piece of code was not even testing cur_fd so it crashed because most of the time it tried to write to a null socket (or a closed one).
So the 1st fix was to just test cur_fd to be sure it was opened before executing this code.
But in fact in linux this code should NEVER be executed, it has nothing to do here.
The comments from sun say :
/*
* If dmu_assign_arcbuf() is expected to execute with minimum
* overhead loan an arc buffer and copy user data to it before
* we enter a txg. This avoids holding a txg forever while we
* pagefault on a hanging NFS server mapping.
*/
I didn't understand everything here, but a pagefault ?
The thing to understand is that this bug occurs if you get a request from fuse and at the same time an ioctl from the listener_loop, it's not 2 ioctls from listener_loop at the same time.
So well I'd say your code probably works everywhere even if I can't be sure of it, because it's very unlikely that a thread calling zfs_write will have cur_fd initialised. But I prefer to address the problem directly, and disable this piece of code for my peace of mind... !
sgheeren
My bonnie++ runs till the very end with 'bonnie++ -d /tank & zpool iostat -v 1' on release 0.6.0 + cherry-pick 67aca02e
Now, what to do. I actually prefer 'my kind of fix' as quite frankly I hate to see 'disabling for the moment', 'can safely be removed', 'should never run on linux' etc. all the time.
I don't believe it is that simple. Tomorrow, we will hit the deadlock that this early-out response was designed to fix. I don't believe in throwing away the smart logic because our command listener wasn't designed as flexible[1] as ZFS's.
Now, that is strongly worded, but there is truth in there. I'd await my further bisection 0.5.0..0.6.0 and perhaps any word from Ricardo.
Truly,
Seth
[1] robust, if I may whisper it
Ricardo M. Correia
> Ricardo M. Correia wrote:
> > Hi sghereen,
> >
> Great to hear from you, Ricardo! I appreciate you taking the time to
> answer my question.
I'm glad to help :)
> I have taken some more time to give the code another look.
> To make things as easy as possible, I went back to your version 0.5.0
> just so we both know what we are looking at.
> I could not reproduce 'my favourite' crashes[1] with your 0.5.0
> version. So I'm currently trying to bisect where the problem got
> introduced. [3]
Sounds good.
> I hope you don't mind if I want to discuss a little more. I'll do my
> very best to keep it brief.
> > In my original zfs-fuse code (and I suspect the current one as well,
> > unless you significantly changed it), cur_fd is *the* file descriptor
> > (yes, the only one) that the zfs-fuse daemon has for communication
> > between itself and libzfs (used by zpool and zfs).
> >
> What I've found is that cur_fd is accepting all kinds of different
> values.
>
> Aren't you perhaps confusing
> *ioctl_fd (the _listening_ socket, which _is_ the only one
> indeed)
> and
> cur_fd (the accepted connection) <-- accept(*ioctl_fd)
>
> If I'm not making sense, I'm happy to elaborate.
> If you just meant that cur_fd should not change in the context of a
> single request, see below.
Yes, I meant that any point in time, there could be only one open file
descriptor being used to communicate between zfs-fuse and the zpool/zfs
commands. Sorry if I wasn't clear the first time.
And yes, the actual file descriptor is created/closed when a socket is
accepted/closed, therefore the cur_fd variable changes when such events
happen. It should only change inside cmd_ioctl_req().
That is expected iff new zpool/zfs commands are being executed in the
background (at least, with my latest code, because I have no idea what
was committed in the newest zfs-fuse code).
> (2) the only two places where cur_fd is being written to are inside
> cmd_ioctl_req:
> 44 static int cmd_ioctl_req(int sock, zfsfuse_cmd_t *cmd)
> 45 {
> 46 dev_t dev = {0};
> 47
> 48 cur_fd = sock;
> 49 int ioctl_ret = zfsdev_ioctl(dev,
> cmd->cmd_u.ioctl_req.cmd, (uintptr_t)
> cmd->cmd_u.ioctl_req.arg, 0, NULL, NULL);
> 50 cur_fd = -1;
> 51
> 52 return zfsfuse_socket_ioctl_write(sock, ioctl_ret);
> 53 }
Right.
> (3) the assertion VERIFY(cur_fd >= 0) was being failed, e.g.
>
> /* This should catch stray xcopyout()s in the code.. */
> VERIFY(cur_fd >= 0);
>
Was that failing with my latest code? If so, that would be unexpected.
> Now this _wasn't_ the case of stray xcopyout()s because cmd_ioctl_req
> was found on the stack in all cases. This must mean that the calls are
> not on a single thread [2].
Am I correct in assuming that this only happens in the latest zfs-fuse
code? Did anyone add multi-threaded ioctl handling to zfs-fuse?
Was zfsdev_ioctl() also in the stack trace?
> My attempts to _prove_ this failed to date, gdb is not happy about so
> many threads and helgrind produced less than usable results, to to
> say :)
Assuming there's no multi-threading ioctl handler, and assuming
zfsdev_ioctl() was in the stack trace, have you tried to run zfs-fuse
under valgrind to see if there are any buffer overflows or similar
errors?
> Now, the corroborating evidence is strong, in the fact that changing
> the curr_fd to a thread-local removed the reproducible crashes from
> 0.6.0.
Although that fixes the symptoms, it would be good to find out the cause
of the errors.
> If you have any more thoughts after reading this background, I'd be
> happy to know. Otherwise, you can just await my bisection results...
HTH,
Ricardo
>
> Regards,
> Seth Heeren
> -------------
>
> [1] I could _not_ reproduce the bonnie++ -d /tank & zpool iostat -v 1 crash under 60s with zfs-fuse-0.5.0
> In fact I let the bonnie++ benchmark run. Writing is _so much slower_ (1/3rd) that I suppose the timing is incomparable.
>
> [2] or the memory location of cur_fd is being clobbered externally. The code doesn't show aliasing so this could only happen with uninitialized pointers or buffer overruns. Not likely without other symptoms?
> [3] I have a feeling that the fuse 26 upgrade is gonna be it. That introduced 'channels' (which I don't know much about)
>
sgheeren
Assuming there's no multi-threading ioctl handler, and assuming zfsdev_ioctl() was in the stack trace, have you tried to run zfs-fuse
under valgrind to see if there are any buffer overflows or similar errors?
Now, the corroborating evidence is strong, in the fact that changing the curr_fd to a thread-local removed the reproducible crashes from 0.6.0.Although that fixes the symptoms, it would be good to find out the cause of the errors.
I'd venture the guess that the corresponding command loop/dispatcher on Solaris is actually thread safe in a way similar to my __thread-local fix [ the disabled seciton is active on onnv ]. I think I'll investigate a bit there.
# git whatchanged -1 67aca02ee --patch-with-stat
commit 67aca02eef8de9364be19e8a4f8cfa210bfd7910
Author: Emmanuel Anne <emmanu...@gmail.com>
Date: Sat Nov 28 12:03:34 2009 +0100
Disable a dangerous uiocopy in the middle of zfs_write
This uiocopy sends unrequested data to an ioctl socket, which can have
disastrous consequences (desync of sockets, buffers overwrites...).
It's a point which works clearly differently in opensolaris, but it seems
we can safety disable it for now. This fixes the bug where running a zfs
and a zpool command during io operations returned an error (which could
be a very dangerous error !!!).
---
src/zfs-fuse/zfs_vnops.c | 7 +++++++
1 files changed, 7 insertions(+), 0 deletions(-)
diff --git a/src/zfs-fuse/zfs_vnops.c b/src/zfs-fuse/zfs_vnops.c
index 69f9cb3..6ca83e3 100644
--- a/src/zfs-fuse/zfs_vnops.c
+++ b/src/zfs-fuse/zfs_vnops.c
@@ -707,6 +707,12 @@ again:
break;
}
+#if 0
+/* zfs-fuse : well there is a serious problem here.
+Using uiocopy right here sends the result to a socket which asked for an ioctl but
+never asked for anything about arc.
+There is clearly a difference here with opensolaris.
+All I can hope is that we can simply disable this code without risk */
/*
* If dmu_assign_arcbuf() is expected to execute with minimum
* overhead loan an arc buffer and copy user data to it before
}
ASSERT(cbytes == max_blksz);
}
+#endif
/*
* Start a transaction.
[1] national witticism :_)
HTHPS. HTH = Hope that helps? or HTH = Happy to help?
Cheers,
Seth
Rudd-O
Ricardo M. Correia
> I might have overlooked a thread there since Emmanuel found a spurious
> uiocopy...
Ah, that explains a lot. uiocopy() was introduced as part of a zero-copy
implementation added to ZFS. Since in zfs-fuse we don't run the ZFS code
in kernel space, that function needs special care, just like uiomove(),
copyin(), etc.
> Well, it appears that Emmanuel has already cornered the cause of the
> error. With his patch (below) _instead of mine_ I also stop getting
> the most obvious reproducible case. As you can see his patch is
> actually the same question-mark upside down [1] "All I can hope is
> that we can simply disable this code without risk".
Yes, it's safe to disable that code. But if you make uiocopy() work
correctly, everything should also work fine, and it should prevent
similar bugs in the future (e.g. if there are new callers of uiocopy()).
Specifically, here's what needs to happen:
1) Inside uiocopy(), if uio->uio_segflg is UIO_USERSPACE or
UIO_USERISPACE, then xcopyout_nta()/xcopyin_nta() should call into
zfs-fuse's xcopyin() and xcopyout() implementations (which communicate
with the "userspace" process, i.e. the zpool and zfs commands, via the
UNIX socket). For example, we can do this by simply defining the
xcopyout_nta symbol to xcopyout.
2) Inside uiocopy(), if uio->uio_segflg is UIO_SYSSPACE, then
kcopy_nta() should call into memmove() (a #define is probably enough).
3) When zfs-fuse calls zfs_write() (via VOP_WRITE() in zfsfuse_write()),
we must make sure that the uio_segflg field of zfs_write()'s 'uio'
argument is UIO_SYSSPACE (not UIO_USERSPACE like in the Solaris/ZFS
implementation).
This difference is because the source buffer of zfs_write() actually
lives in the zfs-fuse address space, as opposed to the address space of
the application which wrote data, because before we call zfs_write() we
are copying the data to be written into the zfs-fuse process through
libfuse.
And now that I looked into zfsfuse_write() (of my own zfs-fuse code),
the uio.uio_io_segflg is correctly being set to UIO_SYSSPACE, so this
shouldn't be the problem.
> I'd venture the guess that the corresponding command loop/dispatcher
> on Solaris is actually thread safe in a way similar to my
> __thread-local fix [ the disabled seciton is active on onnv ].
There isn't a command loop/dispatcher in Solaris, the zpool/zfs
processes simply issue ioctl() calls to the kernel.
However, since zfs-fuse doesn't run in the kernel, we need to emulate
those ioctl() calls, hence the command loop/dispatcher.
> > HTH
> PS. HTH = Hope that helps? or HTH = Happy to help?
Hope that helps ;)
sgheeren
On Ter, 2010-01-26 at 19:13 +0100, sgheeren wrote:I might have overlooked a thread there since Emmanuel found a spurious uiocopy...Ah, that explains a lot. uiocopy() was introduced as part of a zero-copy implementation added to ZFS. Since in zfs-fuse we don't run the ZFS code in kernel space, that function needs special care, just like uiomove(), copyin(), etc.Well, it appears that Emmanuel has already cornered the cause of the error. With his patch (below) _instead of mine_ I also stop getting the most obvious reproducible case. As you can see his patch is actually the same question-mark upside down [1] "All I can hope is that we can simply disable this code without risk".Yes, it's safe to disable that code. But if you make uiocopy() work correctly, everything should also work fine, and it should prevent similar bugs in the future (e.g. if there are new callers of uiocopy()).
Specifically, here's what needs to happen: 1) Inside uiocopy(), if uio->uio_segflg is UIO_USERSPACE or UIO_USERISPACE, then xcopyout_nta()/xcopyin_nta() should call into zfs-fuse's xcopyin() and xcopyout() implementations (which communicate with the "userspace" process, i.e. the zpool and zfs commands, via the UNIX socket). For example, we can do this by simply defining the xcopyout_nta symbol to xcopyout. 2) Inside uiocopy(), if uio->uio_segflg is UIO_SYSSPACE, then kcopy_nta() should call into memmove() (a #define is probably enough). 3) When zfs-fuse calls zfs_write() (via VOP_WRITE() in zfsfuse_write()), we must make sure that the uio_segflg field of zfs_write()'s 'uio' argument is UIO_SYSSPACE (not UIO_USERSPACE like in the Solaris/ZFS implementation). This difference is because the source buffer of zfs_write() actually lives in the zfs-fuse address space, as opposed to the address space of the application which wrote data, because before we call zfs_write() we are copying the data to be written into the zfs-fuse process through libfuse. And now that I looked into zfsfuse_write() (of my own zfs-fuse code), the uio.uio_io_segflg is correctly being set to UIO_SYSSPACE, so this shouldn't be the problem.
I'm not grokking yet (how can things depend on conditions, _yet_ you suggest we could probably get the result by simple #defines? I must have a look to see what the code looks like to see why that makes sense.
Today I'm very tired, and I won't even try.
I'd venture the guess that the corresponding command loop/dispatcher on Solaris is actually thread safe in a way similar to my __thread-local fix [ the disabled seciton is active on onnv ].There isn't a command loop/dispatcher in Solaris, the zpool/zfs processes simply issue ioctl() calls to the kernel. However, since zfs-fuse doesn't run in the kernel, we need to emulate those ioctl() calls, hence the command loop/dispatcher.
I'll sleep on it.
HTHPS. HTH = Hope that helps? or HTH = Happy to help?Hope that helps ;)