Re: [CFT] SIFTR - Statistical Information For TCP Research: Uncle Lawrence needs YOU!

From: Lawrence Stewart <lstewart_at_freebsd.org>
Date: Mon, 21 Jun 2010 00:09:13 +1000
On 06/20/10 23:15, Fabian Keil wrote:
> Lawrence Stewart<lstewart_at_freebsd.org>  wrote:
>
>> On 06/20/10 22:28, Fabian Keil wrote:
>>> Lawrence Stewart<lstewart_at_freebsd.org>   wrote:
>>>
>>>> On 06/20/10 21:15, Fabian Keil wrote:
>>>>> Lawrence Stewart<lstewart_at_freebsd.org>    wrote:
>>>>>
>>>>>> On 06/20/10 03:58, Fabian Keil wrote:
>>>>>>> Lawrence Stewart<lstewart_at_freebsd.org>     wrote:
>>>>>>>
>>>>>>>> On 06/13/10 18:12, Lawrence Stewart wrote:
>>>>>>>
>>>>>>>>> The time has come to solicit some external testing for my SIFTR tool.
>>>>>>>>> I'm hoping to commit it within a week or so unless problems are discovered.
>>>>>>>
>>>>>>>>> I'm interested in all feedback and reports of success/failure, along
>>>>>>>>> with details of the architecture tested and number of CPUs if you would
>>>>>>>>> be so kind.
>>>>>>>
>>>>>>> I got the following hand-transcribed panic maybe a second after
>>>>>>> sysctl net.inet.siftr.enabled=1
>>>>>>>
>>>>>>> Fatal trap 12: page fault while in kernel mode
>>>>>>> cpuid = 1; apic id = 01
>>>>>>> [...]
>>>>>>> current process = 12 (swi4: clock)
>>>>>>> [ thread pid 12 tid 100006 ]
>>>>>>> Stopped at	siftr_chkpkt+0xd0:	addq	$0x1,0x8(%r14)
>>>>>>> db>     where
>>>>>>> Tracing pid 12 tid 100006 td 0xffffff00034037e0
>>>>>>> siftr_chkpt() at siftr_chkpkt+0xd0
>>>>>>> pfil_run_hooks() at pfil_run_hooks+0xb4
>>>>>>> ip_output() at ip_output+0x382
>>>>>>> tcp_output() tcp_output+0xa41
>>>>>>> tcp_timer_rexmt() at tcp_timer_rexmt+0x251
>>>>>>> softclock() at softclock+0x291
>>>>>>> intr_event_execute_handlers() at intr_event_execute_handlers+0x66
>>>>>>> ithread_loop at ithread_loop+0x8e
>>>>>>> fork_exit() at fork_exit+0x112
>>>>>>> fork_trampoline() at fork_trampoline+0xe
>>>>>>> --- trap 0, rip = 0, rsp = 0xffffff800003ad30, rbp = 0 ---
>>>>>>
>>>>>> So I've tracked down the line of code where the page fault is occurring:
>>>>>>
>>>>>>             if (dir == PFIL_IN)
>>>>>>                     ss->n_in++;
>>>>>>             else
>>>>>>                     ss->n_out++;
>>>>>>
>>>>>> ss is a DPCPU (dynamic per-cpu) variable used to keep a set of stats
>>>>>> per-cpu and is initialised at the start of the function like so:
>>>>>>
>>>>>>             ss = DPCPU_PTR(ss);
>>>>>>
>>>>>> So for ss to be NULL, that implies DPCPU_PTR() is returning NULL on your
>>>>>> machine. I know very little about the inner workings of the DPCPU_*
>>>>>> macros, but I'm pretty sure the way I use them in SIFTR is correct or at
>>>>>> least as intended.
>>>>>
>>>>> siftr_chkpkt() passes ss to siftr_chkreinject() before dereferencing
>>>>> it itself. I think if ss was NULL, the panic should already occur in
>>>>> siftr_chkreinject().
>>>>
>>>> Yes but siftr_chkreinject() only dereferences ss in the exceptional case
>>>> of a malloc failure or duplicate pkt. It's unlikely either case happens
>>>> for you and so wouldn't trigger the panic.
>>>>
>>>>> To be sure I added:
>>>>>
>>>>> diff --git a/sys/netinet/siftr.c b/sys/netinet/siftr.c
>>>>> index 8bc3498..b9fdfe4 100644
>>>>> --- a/sys/netinet/siftr.c
>>>>> +++ b/sys/netinet/siftr.c
>>>>> _at__at_ -788,6 +788,16 _at__at_ siftr_chkpkt(void *arg, struct mbuf **m, struct ifnet *ifp, int dir,
>>>>>            if (siftr_chkreinject(*m, dir, ss))
>>>>>                    goto ret;
>>>>>
>>>>> +       if (ss == NULL) {
>>>>> +           printf("ss is NULL");
>>>>> +           ss = DPCPU_PTR(ss);
>>>>> +           if (ss == NULL) {
>>>>> +              printf("ss is still NULL");
>>>>> +              goto ret;
>>>>> +           }
>>>>> +        }
>>>>> +
>>>>> +
>>>>>            if (dir == PFIL_IN)
>>>>>                    ss->n_in++;
>>>>>            else
>>>>>
>>>>> which doesn't seem to affect the problem.
>>>>
>>>> As in it still panics and the "ss is NULL" message is not printed? I
>>>> would have expected to at least see "ss is NULL" printed if my
>>>> hypothesis was correct... hmm.
>>>
>>> Yes, it still panics, but no message is printed.
>>
>> It was just pointed out to me that ss doesn't have to be NULL in order
>> to cause the page fault (duh). It could also just be a garbage ptr which
>> is why your print statement isn't firing.
>>
>> Can you trigger the panic again and look for some information along the
>> lines of "fault virtual address = ..." as part of the panic info.
>> Knowing the faulting address would be useful and may help further diagnosis.
>
> Fatal trap 12: page fault while in kernel mode
> cpuid = 1; apic id = 01
> fault virtual address	= 0xffffff7f808f9de8
> fault code		= supervisor write data, page not present
> instruction pointer	= 0x20:0xffffffff8241f800
> stack pointer		= 0x28:0xffffff800003a7d0
> frame pointer		= 0x28:0xffffff800003a840
> code segment		= base 0x0, limit 0xfffff, type 0x1b
> 			= DPL 0, pres 1, long 1, def32 0, gran 1
> processor eflags	= interrupt enabled, resume, IOPL = 0

None of this looks too crazy, but at least one person I've been chatting 
to about this thinks the faulting address doesn't look quite right for a 
DPCPU variable.

Can you please get the following additional info from DDB:

show reg
show dpcpu_offset
p/x pcpu_entry_modspace

And can you also please identify the upstream FreeBSD revision number 
your kernel source is based on (as opposed to the GIT rev) so we can 
make sure we're looking at the same base sources you're running.

> current process = 12 (swi4: clock)
> [ thread pid 12 tid 100006 ]
> Stopped at	siftr_chkpkt+0xd0:	addq	$0x1,0x8(%r14)
> db>  where
> Tracing pid 12 tid 100006 td 0xffffff00034037e0
> siftr_chkpt() at siftr_chkpkt+0xd0
> pfil_run_hooks() at pfil_run_hooks+0xb4
> ip_output() at ip_output+0x382
> tcp_output() tcp_output+0xa41
> tcp_timer_rexmt() at tcp_timer_rexmt+0x251
> softclock() at softclock+0x291
> intr_event_execute_handlers() at intr_event_execute_handlers+0x66
> ithread_loop at ithread_loop+0x8e
> fork_exit() at fork_exit+0x112
> fork_trampoline() at fork_trampoline+0xe
> --- trap 0, rip = 0, rsp = 0xffffff800003ad30, rbp = 0 ---
>
>>>>>> Could you please go ahead and retest using a GENERIC kernel and see if
>>>>>> you can reproduce? There could be something in your custom kernel
>>>>>> causing the offsets or linker set magic used by the DPCPU bits to break
>>>>>> which in turn is triggering this panic in SIFTR.
>>>>>
>>>>> I'll retry without pf first, and with GENERIC afterwards.
>>>>
>>>> Sounds good, thanks.
>>>
>>> Taking pf (and altq) out of the picture doesn't seem to make
>>> a difference.
>>
>> Wouldn't have expected it to. Will be very curious to know if the panic
>> is triggered in GENERIC.
>
> It's not. I, too, get pfil.c related LORs though:

Ok good to know. Can you please share your kernel config that panics and 
the modules you have loaded at the time of the panic? If we could 
whittle your config down to something that's close to GENERIC and still 
panics, that would obviously be useful to eliminate some variables.

The pfil related LORs are fine and can be ignored in this case.

> lock order reversal:
>   1st 0xffffffff80e5c568 PFil hook read/write mutex (PFil hook read/write mutex) _at_ /usr/src/sys/net/pfil.c:77
>   2nd 0xffffffff80e5dd68 udp (udp) _at_ /usr/src/sys/modules/pf/../../contrib/pf/net/pf.c:3035
> KDB: stack backtrace:
> db_trace_self_wrapper() at db_trace_self_wrapper+0x2a
> _witness_debugger() at _witness_debugger+0x2e
> witness_checkorder() at witness_checkorder+0x81e
> _rw_rlock() at _rw_rlock+0x5f
> pf_socket_lookup() at pf_socket_lookup+0x1c5
> pf_test_udp() at pf_test_udp+0x8b0
> pf_test() at pf_test+0x1089
> pf_check_in() at pf_check_in+0x39
> pfil_run_hooks() at pfil_run_hooks+0xcf
> ip_input() at ip_input+0x2ae
> swi_net() at swi_net+0x151
> intr_event_execute_handlers() at intr_event_execute_handlers+0x66
> ithread_loop() at ithread_loop+0xb2
> fork_exit() at fork_exit+0x12a
> fork_trampoline() at fork_trampoline+0xe
> --- trap 0, rip = 0, rsp = 0xffffff8000044d30, rbp = 0 ---
> lock order reversal:
>   1st 0xffffffff80e5c568 PFil hook read/write mutex (PFil hook read/write mutex) _at_ /usr/src/sys/net/pfil.c:77
>   2nd 0xffffffff80e5d788 tcp (tcp) _at_ /usr/src/sys/modules/siftr/../../netinet/siftr.c:698
> KDB: stack backtrace:
> db_trace_self_wrapper() at db_trace_self_wrapper+0x2a
> _witness_debugger() at _witness_debugger+0x2e
> witness_checkorder() at witness_checkorder+0x81e
> _rw_rlock() at _rw_rlock+0x5f
> siftr_chkpkt() at siftr_chkpkt+0x3c4
> pfil_run_hooks() at pfil_run_hooks+0xcf
> ip_input() at ip_input+0x2ae
> swi_net() at swi_net+0x151
> intr_event_execute_handlers() at intr_event_execute_handlers+0x66
> ithread_loop() at ithread_loop+0xb2
> fork_exit() at fork_exit+0x12a
> fork_trampoline() at fork_trampoline+0xe
> --- trap 0, rip = 0, rsp = 0xffffff8000044d30, rbp = 0 ---
>
> My custom kernel normally doesn't have INVARIANTS and WITNESS
> enabled, so I'll try to enable them next.

INVARIANTS and INVARIANT_SUPPORT are the import ones. I don't think 
WITNESS will help us diagnose this particular problem.

Cheers,
Lawrence
Received on Sun Jun 20 2010 - 12:09:17 UTC

This archive was generated by hypermail 2.4.0 : Wed May 19 2021 - 11:40:04 UTC