panic: sync: unlock of unlocked mutex
Han-Wen Nienhuys
I am getting aforementioned message in a multithreaded Go program.
Although I am skeptic of my own programming skills, I can't see how I
could have made this error appear:
The full trace is
runtime.panic+0xac
/usr/local/google/home/hanwen/vc/go/src/pkg/runtime/proc.c:1060
runtime.panic(0x48e290, 0xf8467c8180)
sync.*Mutex·Unlock+0x81
/usr/local/google/home/hanwen/vc/go/src/pkg/sync/mutex.go:55
sync.*Mutex·Unlock(0xf8400178e0, 0x42c45c)
sync.*RWMutex·Unlock+0x25
/usr/local/google/home/hanwen/vc/go/src/pkg/sync/rwmutex.go:75
sync.*RWMutex·Unlock(0xf8400178e0, 0xf84640ee80)
github%2ecom/hanwen/go-fuse/fuse.*FileSystemConnector·considerDropInode+0x111
/home/hanwen/vc/go-fuse/fuse/pathfilesystem.go:422
github%2ecom/hanwen/go-fuse/fuse.*FileSystemConnector·considerDropInode(0xf840030c60,
0xf84640ee80, 0xf84640ee80, 0x42db43)
which comes from
https://github.com/hanwen/go-fuse/blob/3713ef6dcdcf578e283b53bf1fc470f050bead3e/fuse/pathfilesystem.go#L422,
func (me *FileSystemConnector) considerDropInode(n *inode) {
n.mount.treeLock.Lock()
defer n.mount.treeLock.Unlock()
dropInode := n.LookupCount <= 0 && len(n.Children) == 0 &&
(n.mountPoint == nil || n.mountPoint.unmountPending) &&
n.OpenCount <= 0
if dropInode {
n.setParent(nil)
me.inodeMapMutex.Lock()
defer me.inodeMapMutex.Unlock()
me.inodeMap[n.NodeId] = nil, false // line from stacktrace.
}
}
both treeLock and inodeMapMutex are always locked using the
foo.Lock()
defer foo.Unlock()
idiom.
Any ideas on how to further troubleshoot this? The crash is not
directly reproducible, but with intensive use of the binary on a
multicore machine, it rears its head about once a day.
--
Han-Wen Nienhuys
Google Engineering Belo Horizonte
han...@google.com
Russ Cox
In this code:
func (me *FileSystemConnector) considerDropInode(n *inode) {
n.mount.treeLock.Lock()
defer n.mount.treeLock.Unlock()
dropInode := n.LookupCount <= 0 && len(n.Children) == 0 &&
(n.mountPoint == nil || n.mountPoint.unmountPending) &&
n.OpenCount <= 0
if dropInode {
n.setParent(nil)
me.inodeMapMutex.Lock()
defer me.inodeMapMutex.Unlock()
me.inodeMap[n.NodeId] = nil, false
}
}
The fact that the line number is on the map assignment is
misleading. Since an Unlock is being called, it's really just
that the function is returning and calling its deferred functions.
The line number is probably showing the last real instruction
in the function before the return.
I see two possibilities. The first is that there is a garbage collector
bug, and one of the two locks in a structure that is incorrectly
collected and then zeroed, and that's happening between the
Lock and the deferred Unlock. The second is that there is a
race in your code, and n.mount is being reassigned in another
goroutine while considerDropInode is running in this goroutine.
If that were to happen between these two lines:
n.mount.treeLock.Lock()
defer n.mount.treeLock.Unlock()
then the deferred call would unlock the wrong treeLock.
Even if your code does have this race, to see the crash
I'd expect you to be running with GOMAXPROCS > 1.
Russ
Han-Wen Nienhuys
> I am assuming you don't have 4 billion goroutines.
>
> In this code:
>
> func (me *FileSystemConnector) considerDropInode(n *inode) {
> n.mount.treeLock.Lock()
> defer n.mount.treeLock.Unlock()
>
> dropInode := n.LookupCount <= 0 && len(n.Children) == 0 &&
> (n.mountPoint == nil || n.mountPoint.unmountPending) &&
> n.OpenCount <= 0
> if dropInode {
> n.setParent(nil)
>
> me.inodeMapMutex.Lock()
> defer me.inodeMapMutex.Unlock()
> me.inodeMap[n.NodeId] = nil, false
> }
> }
>
> The fact that the line number is on the map assignment is
> misleading. Since an Unlock is being called, it's really just
> that the function is returning and calling its deferred functions.
> The line number is probably showing the last real instruction
> in the function before the return.
I figured so much. It would nice if there were a way to figure out for
which lock it is panicking, though, but I remember that inodeMapMutex
is a normal mutex, and treeLock the r/w one, so it is the treeLock
that is panicking.
> I see two possibilities. The first is that there is a garbage collector
> bug, and one of the two locks in a structure that is incorrectly
> collected and then zeroed, and that's happening between the
That doesn't seem likely as the structures containing the locks are
referenced to from many locations.
> Lock and the deferred Unlock. The second is that there is a
> race in your code, and n.mount is being reassigned in another
> goroutine while considerDropInode is running in this goroutine.
> If that were to happen between these two lines:
>
> n.mount.treeLock.Lock()
> defer n.mount.treeLock.Unlock()
>
> then the deferred call would unlock the wrong treeLock.
I considered this too, but these assignments did not happen (as they
are associated with filesystem (un)mounts, which are rare and
notable.)
There are two other fishy things; I thought it would be safe, but
maybe you can shine your light on this too:
* I use unlocked writes to this variable
however, the variable can only go from false to true, and reading
false incorrectly should not cause ill effects. (ie. eventual
consistency for the read is ok.)
Rather than using a int64 -> pointer map for decoding inode handles
given back by the kernel, I store the address directly in the int64;
since the data in the inode is constant after allocation, I don't see
a big problem with that (inconsistencies would have to survive a
garbage collection and 2 context switches), but maybe I am naive.
In any event, inconsistencies would lead to one CPU seeing the value
from when GC is finished (zeroed out, I assume), so the code would
then crash on dereferencing n.mount
I did find another race condition, but it was a case of not taking an
RLock on treeLock, so that should not cause this error message?
> Even if your code does have this race, to see the crash
> I'd expect you to be running with GOMAXPROCS > 1.
Correct. I'm running this on 6 CPUs (17 coroutines.)
>
> Russ
Russ Cox
>
> Rather than using a int64 -> pointer map for decoding inode handles
> given back by the kernel, I store the address directly in the int64;
> since the data in the inode is constant after allocation, I don't see
> a big problem with that (inconsistencies would have to survive a
> garbage collection and 2 context switches), but maybe I am naive.
Is the inode kept in some other Go variable too?
If the kernel holds the only reference to the pointer
that would obviously be a problem during a garbage
collection. At the least I think you'd want to have a
map[*inode]bool lying around just to keep them from
getting garbage collected. (At that point you might
as well have a map[int64]*inode.)
> In any event, inconsistencies would lead to one CPU seeing the value
> from when GC is finished (zeroed out, I assume), so the code would
> then crash on dereferencing n.mount
When possible, the zeroing gets delayed until the memory
is reused, so if the GC were prematurely collecting
one of your inodes, it would be likely for it to get reused
as another inode, and the time between it getting zeroed
and filled in again would probably be short. So it's entirely
possible for a dangling pointer reference to still see a
valid-looking inode, just not the one that used to be there.
> I figured so much. It would nice if there were a way to figure out for
> which lock it is panicking, though, but I remember that inodeMapMutex
> is a normal mutex, and treeLock the r/w one, so it is the treeLock
> that is panicking.
> ...
> I did find another race condition, but it was a case of not taking an
> RLock on treeLock, so that should not cause this error message?
Ah, I didn't pay enough attention before to the fact that it is
the RWMutex Unlock that is triggering the Mutex Unlock panic.
I don't see any way for use or misuse of an RWMutex to cause
this panic on the underlying Mutexes. It really sounds like
it's the garbage collection problem.
Russ
Han-Wen Nienhuys
>> * https://github.com/hanwen/go-fuse/blob/3713ef6dcdcf578e283b53bf1fc470f050bead3e/fuse/pathfilesystem.go#L398
>>
>> Rather than using a int64 -> pointer map for decoding inode handles
>> given back by the kernel, I store the address directly in the int64;
>> since the data in the inode is constant after allocation, I don't see
>> a big problem with that (inconsistencies would have to survive a
>> garbage collection and 2 context switches), but maybe I am naive.
>
> Is the inode kept in some other Go variable too?
> If the kernel holds the only reference to the pointer
> that would obviously be a problem during a garbage
> collection. At the least I think you'd want to have a
> map[*inode]bool lying around just to keep them from
> getting garbage collected. (At that point you might
> as well have a map[int64]*inode.)
There is a map[int64]*inode (inodeMap in the quoted code), which I
keep around to prevent GC from collecting the nodes. The int64 ->
pointer cast hack is to save on the map lookup and associated mutex
lock for every FUSE operation we have to dispatch.
>> In any event, inconsistencies would lead to one CPU seeing the value
>> from when GC is finished (zeroed out, I assume), so the code would
>> then crash on dereferencing n.mount
>
> When possible, the zeroing gets delayed until the memory
> is reused, so if the GC were prematurely collecting
> one of your inodes, it would be likely for it to get reused
> as another inode, and the time between it getting zeroed
> and filled in again would probably be short. So it's entirely
> possible for a dangling pointer reference to still see a
> valid-looking inode, just not the one that used to be there.
Right, except that the pointer is not dangling, as I do have an
int64-> *inode map.
I can still imagine this to lead to the following race:
* kernel issues forget on node X (*)
* Go-fuse running drops the reference to X
* Go runtime runs GC, collecting X.
* kernel issues lookup
* go-fuse allocates new inode; by chance this happens to allocate X again.
* go-fuse returns X to the kernel
* kernel issues another file operation on X, which gets scheduled on a
different CPU
* the new CPU still sees the state of time (*), leading to a crash.
For this to happen, the result from (*) would have to persist across
multiple kernel <-> go-fuse context switches and a GC. I thought
that timespan would large enough to be safe.
Also, we have only seen this in the forget operation. If it really
were an issue, forget is the least likely operation to cause this
problem.
>> I figured so much. It would nice if there were a way to figure out for
>> which lock it is panicking, though, but I remember that inodeMapMutex
>> is a normal mutex, and treeLock the r/w one, so it is the treeLock
>> that is panicking.
>> ...
>> I did find another race condition, but it was a case of not taking an
>> RLock on treeLock, so that should not cause this error message?
>
> Ah, I didn't pay enough attention before to the fact that it is
> the RWMutex Unlock that is triggering the Mutex Unlock panic.
> I don't see any way for use or misuse of an RWMutex to cause
> this panic on the underlying Mutexes. It really sounds like
> it's the garbage collection problem.
So in summary: something (most likely garbage collection) has zeroed
out what I was trying to unlock?
Is there a way to determine if this problem coincides with GC? Is
there a hook so that I can print something when we run GC ?
Russ Cox
> out what I was trying to unlock?
It sure sounds that way. I am still suspicious of this unsafe conversion.
If the kernel is out of sync, you're hosed.
The addresses on a 64-bit machine only have 48 bits of
address space anyway, so you could use the others to
sanity check what the kernel gives you, like:
type inode struct {
gen uintptr
...
}
var inodeGen struct {
sync.Mutex
v uintptr
}
func newInode() *inode {
inodeGen.Lock()
defer inodeGen.Unlock()
inodeGen.v++
return &inode{inodeGen.v}
}
func (n *inode) kernelID() uintptr {
return uintptr(unsafe.Pointer(n))>>3 | n.gen<<45
}
func kernelInode(id uintptr) *inode {
n := (*inode)(unsafe.Pointer(id<<19>>16))
if n.kernelID() != id {
panic("invalid kernel ID")
}
return n
}
> Is there a way to determine if this problem coincides with GC? Is
> there a hook so that I can print something when we run GC ?
There's an undocumented, unsupported flag that I use when
working on the garbage collector. If you set GOGCTRACE=1
then it will print a summary line after each garbage collection.
Of course you need to print other things too or else you won't
be able to tell how long ago the garbage collection was.
Russ
Han-Wen Nienhuys
>> So in summary: something (most likely garbage collection) has zeroed
>> out what I was trying to unlock?
>
> It sure sounds that way. I am still suspicious of this unsafe conversion.
> If the kernel is out of sync, you're hosed.
>
> The addresses on a 64-bit machine only have 48 bits of
> address space anyway, so you could use the others to
> sanity check what the kernel gives you, like:
Awesome. This 48-bits fact is part of a Go runtime implementation
choice, or can I rely on it for the future?
>> Is there a way to determine if this problem coincides with GC? Is
>> there a hook so that I can print something when we run GC ?
>
> There's an undocumented, unsupported flag that I use when
> working on the garbage collector. If you set GOGCTRACE=1
> then it will print a summary line after each garbage collection.
> Of course you need to print other things too or else you won't
> be able to tell how long ago the garbage collection was.
ok.
Russ Cox
>> address space anyway, so you could use the others to
>> sanity check what the kernel gives you, like:
>
> Awesome. This 48-bits fact is part of a Go runtime implementation
> choice, or can I rely on it for the future?
It's a safe bet for the immediate future.
It's a fact of the x86-64 architecture.
Growing the effective address size would
require changing the page table layout and
thus the operating system, so it is not likely
to change tomorrow, although it will probably
change eventually, once there is enough
demand for processes with 128 TB virtual
address spaces.
Also Go asks the operating system (nicely)
to use the address range 0xf800000000 to
0xfd00000000, which is well within the 48 bits
even on systems that might have bigger
addresses.
Russ
Bobby Powers
http://git.kernel.org/?p=linux/kernel/git/torvalds/linux-2.6.git;a=blob;f=Documentation/x86/x86_64/mm.txt
Bobby Powers
That makes sense, and explains why people see really large virt memory usage :)
Bobby
Kyle Lemons
foo.Lock()
defer foo.Unlock()
Han-Wen Nienhuys
>> foo.Lock()
>> defer foo.Unlock()
>
> I could be entirely off base, but have you tried:
> l := n.nmount.treeLock // similarly for the other one
> l.Lock()
> defer l.Unlock()
I will add some sugar to do
defer n.mount.treeLock.LockUnlock()
is there any reason that runtime doesn't provide anything similar by
default, btw?
> and see if that fixes anything?
> ~K
--
Rob 'Commander' Pike
On 24/06/2011, at 2:53 AM, Han-Wen Nienhuys wrote:
> On Wed, Jun 22, 2011 at 9:56 PM, Kyle Lemons <kev...@google.com> wrote:
>>> foo.Lock()
>>> defer foo.Unlock()
>>
>> I could be entirely off base, but have you tried:
>> l := n.nmount.treeLock // similarly for the other one
>> l.Lock()
>> defer l.Unlock()
>
> I will add some sugar to do
>
> defer n.mount.treeLock.LockUnlock()
I don't see how. The lock has to happen when defer executes, the unlock when the calling function returns. You can't do what I think you mean in a single niladic call.
> is there any reason that runtime doesn't provide anything similar by
> default, btw?
Similar to what?
-rob
Han-Wen Nienhuys
>>> I could be entirely off base, but have you tried:
>>> l := n.nmount.treeLock // similarly for the other one
>>> l.Lock()
>>> defer l.Unlock()
>>
>> I will add some sugar to do
>>
>> defer n.mount.treeLock.LockUnlock()
>
> I don't see how. The lock has to happen when defer executes, the unlock when the calling function returns. You can't do what I think you mean in a single niladic call.
Sorry, I meant
defer lock.LockUnlock()()
eg.
type AutoMutex struct {
sync.Mutex
}
func (me *AutoMutex) Lock() func() {
me.Mutex.Lock()
return me.Mutex.Unlock
}
(untested)
not sure how expensive a closure is, though.
David Symonds
func lock(m sync.Mutex) sync.Mutex {
m.Lock()
return m
}
func un(m sync.Mutex) {
m.Unlock()
}
and then
defer un(lock(mu))
Dave.
Han-Wen Nienhuys
>> So in summary: something (most likely garbage collection) has zeroed
>> out what I was trying to unlock?
>
> It sure sounds that way. I am still suspicious of this unsafe conversion.
> If the kernel is out of sync, you're hosed.
>
> The addresses on a 64-bit machine only have 48 bits of
> address space anyway, so you could use the others to
> sanity check what the kernel gives you, like:
Thanks, I implemented this generically
(https://github.com/hanwen/go-fuse/blob/master/fuse/handle.go).
In the process of using it, I noticed that the read of n.OpenCount was
not protected. I still don't see how that could lead to the given
message, but let's hope this was the problem.
Russ Cox
x.y.Lock()
defer x.y.Unlock()
and that is crashing because the value of x.y
changed between the two statements, then yes,
you could use a temporary variable, explicit or not,
to make sure the Lock and Unlock both operate
on the same value. But that's irrelevant.
If x.y is changing underfoot while these two lines,
then the correct execution of your program
depends on (a) whether either of them is the right
value to be passing to Lock and Unlock, and
(b) whether that value is the one you see while
running the race.
Don't worry about defer tricks. Worry about why
a value is changing while you are trying to use it.
Russ