Re: witness found wanting (was Re: LORs in ipfilter)

On 2004-12-26 18:22, Darren Reed <darrenr_at_hub.freebsd.org> wrote:
>In some mail from Giorgos Keramidas, sie said:
>> The locking changes of ipfilter have introduced a few LORs, which
>> became visible right after the build fixes committed by Scott.
>> Here are the ones I've seen so far.
>>
>>: lock order reversal
>>: 1st 0xc072d0a0 ifnet (ifnet) _at_ /usr/src/sys/contrib/ipfilter/netinet/fil.c:2146
>>: 2nd 0xc06f9380 ipf IP NAT rwlock (ipf IP NAT rwlock) _at_ /usr/src/sys/contrib/ipfilter/netinet/ip_nat.c:2836
>>: KDB: stack backtrace:
>>: kdb_backtrace(0,ffffffff,c0708df8,c07083f8,c06d9aac) at kdb_backtrace+0x29
>>: witness_checkorder(c06f9380,9,c0676e6c,b14) at witness_checkorder+0x54c
>>: _sx_xlock(c06f9380,c0676e6c,b14,3,c1e9a000) at _sx_xlock+0x50
>>: ip_natsync(c1e9a000,0,d95f9c84,c0448dd9,0) at ip_natsync+0x20
>>: frsync(0,c04f7994,c1d55fac,0,c068949f) at frsync+0x2e
>>: iplioctl(c1e98b00,80047249,c1fa09e0,3,c1fba450) at iplioctl+0x551
>>: devfs_ioctl_f(c1ff1d48,80047249,c1fa09e0,c1d67d80,c1fba450) at devfs_ioctl_f+0x87
>>: ioctl(c1fba450,d95f9d14,3,1,246) at ioctl+0x370
>>: syscall(2f,2f,2f,280556c0,bfbfeed4) at syscall+0x213
>>: Xint0x80_syscall() at Xint0x80_syscall+0x1f
>>: --- syscall (54, FreeBSD ELF32, ioctl), eip = 0x280c67e7, esp = 0xbfbfea7c, ebp = 0xbfbfea98 ---
>
> What exactly is it complaining about ?
>
> The first two LORs in your email are similar - threads that start in
> a system call, filter through to the ipfilter code that acquires an
> sx lock after the system has acquireqd a mutex.  In neither case does
> the mutex provide any protection against what is being achieved by
> getting the sx lock.

Hi Darren,

I modified subr_witness.c here to print the w_level of each lock when a
reversal is reported to see if that was the cause of the warning:

: lock order reversal
: 1st 0xc06fa1c0 [12] ipf IP state rwlock (ipf IP state rwlock) _at_ /usr/src/sys/contrib/ipfilter/netinet/ip_state.c:793
: 2nd 0xc072df00 [11] ifnet (ifnet) _at_ /usr/src/sys/net/if.c:1068
: KDB: stack backtrace:
: kdb_backtrace(0,ffffffff,c0709258,c0709c58,c06d947c) at kdb_backtrace+0x29
: witness_checkorder(c072df00,9,c069674f,42c) at witness_checkorder+0x559
: _mtx_lock_flags(c072df00,0,c069674f,42c,2) at _mtx_lock_flags+0x5b
: ifunit(c1d644dc,da7dda2c,c1d64400,5006,da7dd9f8) at ifunit+0x1e
: fr_stinsert(c1d64400,1,0,0,0) at fr_stinsert+0x67
: fr_addstate(c1f992c4,da7dda2c,0,0) at fr_addstate+0x5f7
: fr_check(c1f992c4,14,c1e93014,1,da7ddad4) at fr_check+0x7cc
: fr_check_wrapper(0,da7ddad4,c1e93014,2,c2101bf4) at fr_check_wrapper+0x2a
: pfil_run_hooks(c0730440,da7ddb48,c1e93014,2,c2101bf4) at pfil_run_hooks+0xbd
: ip_output(c1f99200,0,da7ddb14,0,0) at ip_output+0x57e
: udp_output(c2101bf4,c1f99200,c1e893f0,0,c2015450) at udp_output+0x47d
: udp_send(c20ff3cc,0,c1f99200,c1e893f0,0) at udp_send+0x1a
: sosend(c20ff3cc,c1e893f0,da7ddc4c,c1f99200,0) at sosend+0x70f
: kern_sendit(c2015450,16,da7ddcc4,0,0) at kern_sendit+0x104
: sendit(c2015450,16,da7ddcc4,0,c1e598b0) at sendit+0x159
: sendmsg(c2015450,da7ddd14,3,0,282) at sendmsg+0x5a
: syscall(2f,2f,2f,1,82cb12c) at syscall+0x213
: Xint0x80_syscall() at Xint0x80_syscall+0x1f
: --- syscall (28, FreeBSD ELF32, sendmsg), eip = 0x28322a27, esp = 0xbfaed73c, ebp = 0xbfaed8b8 ---

Note the [12] and [11] after the lock pointer.  This is, as far as I can
tell by reading the witness_checkorder() function, the cause of the
warning.

I've already emailed John Baldwin, asking him how witness levels are
assigned.  It's a holiday season though, so I'm not sure if he will have
the time to reply for a few days.

> > Converting the sx locks used by ipfilter to mutexes fixed these LORs but
> > introduced a new one, which I'm not sure how to fix:
>
> Which is surprising because it doesn't really fix the problem, in my
> eyes, it just highlights the above weakness/bug in the witness code.
>
> It also seriously degrades the performance of ipfilter on an smp system.
> That this sort of change makes the witness code silent is further
> evidence that it is not really doing its job.

Is this performance hit FreeBSD specific?  I saw in ip_compat.h that on
__sgi systems mutexes are used instead of rwlocks.

Giorgos