Skip site navigation (1)Skip section navigation (2)
Date:      Fri, 29 Feb 2008 12:29:35 +0100
From:      matthew <matthew@matthew.sk>
To:        Kris Kennaway <kris@FreeBSD.org>
Cc:        freebsd-net@freebsd.org, freebsd-ipfw@FreeBSD.org
Subject:   Re: Lock order reversals with dummynet (Re: FreeBSD 7.0 Beta, RC, RELEASE (amd64) freezes with dummynet enabled)
Message-ID:  <47C7EC9F.4070403@matthew.sk>
In-Reply-To: <47C7E068.5040208@FreeBSD.org>
References:  <47C5753A.8010806@matthew.sk> <47C57D01.8070007@FreeBSD.org> <47C7BB11.9020604@matthew.sk> <47C7E068.5040208@FreeBSD.org>

next in thread | previous in thread | raw e-mail | index | archive | help
I have some more tests, but always the same.


Here is the top output, that i see last on terminal:


65 processes: 4 running, 144 sleeping, 17 waiting
CPU states:  0.0% user,  0.0% nice, 29.9% system,  7.8% interrupt, 62.3% 
idle
Mem: 46M Active, 522M Inact, 350M Wired, 10M Cache, 109M Buf, 35M Free
Swap: 2048M Total, 228K Used, 2048M Free

  PID USERNAME  THR PRI NICE   SIZE    RES STATE  C   TIME   WCPU COMMAND
   12 root        1 171 ki31     0K    16K RUN    0 692:10 61.96% idle: cpu0
   11 root        1 171 ki31     0K    16K RUN    1 804:37 51.51% idle: cpu1
   13 root        1 -44    -     0K    16K WAIT   0 325:41 13.18% swi1: net
   42 root        1 -68    -     0K    16K -      0  12:26 12.74% dummynet
72368 ftp         1   4    0 10832K  2080K RUN    0   4:05 10.01% vsftpd
74488 ftp         1   4    0 10832K  2080K zfs:(& 0   0:31  9.62% vsftpd
73690 ftp         1   8    0 10832K  2072K nanslp 0   1:43  8.64% vsftpd
74752 ftp         1   8    0 10832K  2068K nanslp 1   0:09  6.06% vsftpd
74811 ftp         1   8    0 10832K  2072K nanslp 1   0:03  3.79% vsftpd
74869 ftp         1   4    0 10832K  2056K sbwait 1   0:00  3.39% vsftpd


As you can see, there is no high load, enought free memory and CPUs are 
relative idle.



This is the output from nload -o 250000:

Device em0 [10.252.2.3] (1/1):
============================================================================================================================================
Incoming:










 ..    .| .|.  .   .. .  ||...|....            .........| 
.                           .   ..   Curr: 2519.37 kBit/s
####|||######.######################           ############...  ..... 
..||...  .|. ##|#|####.  Avg: 2831.76 kBit/s
####################################|# .. |. | 
######################|#######||##############  Min: 141.74 kBit/s
#########################################.##.#|##############################################  
Max: 6586.57 kBit/s
#############################################################################################  
Ttl: 542932224.00 MByte
Outgoing:




                                                                                      
.
 ..     #  ..  .    .    ##.. ....                  . . 
#                           . #   .#
 ##    ## ###  #  .##.|| #########||           
|###|#####..                        |#.#.#|##
####||.######.######################           ############...  |   .  
..# .|   |. #########.
####################################           ###############.####|# 
####|##  ###|##########
####################################.#    .  . 
##############################||##############
###################################### || ## # 
##############################################  Curr: 127802.60 kBit/s
######################################|## ## 
#|##############################################  Avg: 144300.05 kBit/s
#########################################|###################################################  
Min: 3339.92 kBit/s
#############################################################################################  
Max: 292397.75 kBit/s
#############################################################################################  
Ttl: 14977425408.00 MByte 


There is no rapid change of bw or anything.



Kris Kennaway wrote:

> Adding back the mailing list so others can help.
>
> matthew wrote:
>> Kris Kennaway wrote:
>>
>>> matthew wrote:
>>>> I have posted before that i have a stability issue with the 7.0 branch
>>>> on my servers. Tested on BETA2,BETA4,RC1,RC2,RELEASE
>>>>
>>>> The original thread and my post with details is at:
>>>> http://unix.derkeiler.com/Mailing-Lists/FreeBSD/current/2007-12/msg00674.html 
>>>>
>>>>
>>>> I was waiting for the 7.0-RELEASE, updated the whole servers, and
>>>> enabled dummynet again, but it always freezes after some minutes, 100%
>>>> reproducible.
>>>>
>>>> I tested it also on a HP 140 G3 1U server, where 6.3 has absolutely no
>>>> problems, but the 7.0 branch keeps freezing.
>>>>
>>>> Again, if it helps to solve this bug, i can rebuild the kernel with
>>>> debug symbols a take some screenshots :)
>>>
>>> Please follow the steps at
>>>
>>> http://www.freebsd.org/doc/en_US.ISO8859-1/books/developers-handbook/kerneldebug.html 
>>>
>>>
>>> Kris
>>> _______________________________________________
>> I added to the kernel these options:
>> makeoptions     DEBUG=-g                # Build kernel with gdb(1) 
>> debug symbols
>> options         INVARIANTS
>> options         INVARIANT_SUPPORT
>> options         WITNESS
>> options         DEBUG_LOCKS
>> options         DEBUG_VFS_LOCKS
>> options         DIAGNOSTIC
>> options         KDB
>> options         DDB
>> options         GDB
>> options         SOCKBUF_DEBUG
>>
>> But still, the server freezes withoutany debug message,
>
> And you can't break to DDB?  It is expected you will have to when you 
> encounter a deadlock.
No, i am unable to do anything, no input from keyboard, the only one 
thing thats work, is to change the num lock indicator on the keyboard :)
>
> > panic whatever,
>> but at leasts it dumps the crash kernel to /var/crash, but the debug 
>> looks like this:
>
> Dumping is an activity the occurs after panicking, so if you have a 
> dump then you must have a panic.
>> root@hanka:/usr/src/sys/amd64/compile/HANKA-debug# kgdb kernel.debug 
>> /var/crash/vmcore.0
>> [GDB will not be able to debug user-mode threads: 
>> /usr/lib/libthread_db.so: Undefined symbol "ps_pglobal_lookup"]
>> GNU gdb 6.1.1 [FreeBSD]
>> Copyright 2004 Free Software Foundation, Inc.
>> GDB is free software, covered by the GNU General Public License, and 
>> you are
>> welcome to change it and/or distribute copies of it under certain 
>> conditions.
>> Type "show copying" to see the conditions.
>> There is absolutely no warranty for GDB.  Type "show warranty" for 
>> details.
>> This GDB was configured as "amd64-marcel-freebsd".
>> Cannot access memory at address 0x57
>> (kgdb) backtrace
>> #0  0x0000000000000000 in ?? ()
>> Cannot access memory at address 0x0
>> (kgdb)                                   I have some debug messages 
>> at boot time:
>
> This usually means you are not running the dump against the 
> kernel.debug corresponding exactly to the kernel that crashed.  
> Probably the dump you found was old.
>
Yes, i think it is possible that it is the previous kernel, without the 
debug options.
>> Feb 28 17:01:29 hanka lock order reversal:
>> Feb 28 17:01:29 hanka 1st 0xffffffff80b0e1e8 PFil hook read/write 
>> mutex (PFil hook read/write mutex) @ net/pfil.c:73
>> Feb 28 17:01:29 hanka 2nd 0xffffffff80b0f8e8 udp (udp) @ 
>> /usr/src/sys/modules/pf/../../contrib/pf/net/pf.c:2970
>> Feb 28 17:01:29 hanka KDB: stack backtrace:
>> Feb 28 17:01:29 hanka db_trace_self_wrapper() at 
>> db_trace_self_wrapper+0x2a
>> Feb 28 17:01:29 hanka witness_checkorder() at witness_checkorder+0x605
>> Feb 28 17:01:29 hanka _mtx_lock_flags() at _mtx_lock_flags+0x75
>> Feb 28 17:01:29 hanka pf_socket_lookup() at pf_socket_lookup+0x241
>> Feb 28 17:01:29 hanka pf_test_udp() at pf_test_udp+0x890
>> Feb 28 17:01:29 hanka pf_test() at pf_test+0xeb2
>> Feb 28 17:01:29 hanka pf_check_in() at pf_check_in+0x2b
>> Feb 28 17:01:29 hanka pfil_run_hooks() at pfil_run_hooks+0xbc
>> Feb 28 17:01:29 hanka ip_input() at ip_input+0x2c4
>> Feb 28 17:01:29 hanka ether_demux() at ether_demux+0x1d9
>> Feb 28 17:01:29 hanka ether_input() at ether_input+0x19d
>> Feb 28 17:01:29 hanka ether_demux() at ether_demux+0xe9
>> Feb 28 17:01:29 hanka ether_input() at ether_input+0x19d
>> Feb 28 17:01:29 hanka em_rxeof() at em_rxeof+0x1ca
>> Feb 28 17:01:29 hanka em_poll() at em_poll+0x6f
>> Feb 28 17:01:29 hanka netisr_poll() at netisr_poll+0x87
>> Feb 28 17:01:29 hanka swi_net() at swi_net+0xea
>> Feb 28 17:01:29 hanka ithread_loop() at ithread_loop+0xda
>> Feb 28 17:01:29 hanka fork_exit() at fork_exit+0x12a
>> Feb 28 17:01:29 hanka fork_trampoline() at fork_trampoline+0xe
>> Feb 28 17:01:29 hanka --- trap 0, rip = 0, rsp = 0xffffffff9feead30, 
>> rbp = 0 ---
>
>
>> Feb 28 17:01:29 hanka lock order reversal:
>> Feb 28 17:01:29 hanka 1st 0xffffff0001237430 em0 (EM Core Lock) @ 
>> dev/em/if_em.c:1416
>> Feb 28 17:01:29 hanka 2nd 0xffffffff80b0f8e8 udp (udp) @ 
>> netinet/udp_usrreq.c:385
>> Feb 28 17:01:29 hanka KDB: stack backtrace:
>> Feb 28 17:01:29 hanka db_trace_self_wrapper() at 
>> db_trace_self_wrapper+0x2a
>> Feb 28 17:01:29 hanka witness_checkorder() at witness_checkorder+0x605
>> Feb 28 17:01:29 hanka _mtx_lock_flags() at _mtx_lock_flags+0x75
>> Feb 28 17:01:29 hanka udp_input() at udp_input+0x1a4
>> Feb 28 17:01:29 hanka ip_input() at ip_input+0xc0
>> Feb 28 17:01:29 hanka ether_demux() at ether_demux+0x1d9
>> Feb 28 17:01:29 hanka ether_input() at ether_input+0x19d
>> Feb 28 17:01:29 hanka ether_demux() at ether_demux+0xe9
>> Feb 28 17:01:29 hanka ether_input() at ether_input+0x19d
>> Feb 28 17:01:29 hanka em_rxeof() at em_rxeof+0x1ca
>> Feb 28 17:01:29 hanka em_poll() at em_poll+0x6f
>> Feb 28 17:01:29 hanka netisr_poll() at netisr_poll+0x87
>> Feb 28 17:01:29 hanka swi_net() at swi_net+0xea
>> Feb 28 17:01:29 hanka ithread_loop() at ithread_loop+0xda
>> Feb 28 17:01:29 hanka fork_exit() at fork_exit+0x12a
>> Feb 28 17:01:29 hanka fork_trampoline() at fork_trampoline+0xe
>> Feb 28 17:01:29 hanka --- trap 0, rip = 0, rsp = 0xffffffff9feead30, 
>> rbp = 0 ---
>
>
>> Feb 28 17:01:29 hanka xinetd[1356]: xinetd Version 2.3.14 started 
>> with libwrap loadavg options compiled in.
>> Feb 28 17:01:29 hanka xinetd[1356]: Started working: 1 available service
>> Feb 28 17:01:33 hanka lock order reversal:
>> Feb 28 17:01:33 hanka 1st 0xffffff00042f5b10 inp (tcpinp) @ 
>> netinet/tcp_usrreq.c:781
>> Feb 28 17:01:33 hanka 2nd 0xffffffff80b0e1e8 PFil hook read/write 
>> mutex (PFil hook read/write mutex) @ net/pfil.c:73
>> Feb 28 17:01:33 hanka KDB: stack backtrace:
>> Feb 28 17:01:33 hanka db_trace_self_wrapper() at 
>> db_trace_self_wrapper+0x2a
>> Feb 28 17:01:33 hanka witness_checkorder() at witness_checkorder+0x605
>> Feb 28 17:01:33 hanka _rw_rlock() at _rw_rlock+0x5b
>> Feb 28 17:01:33 hanka pfil_run_hooks() at pfil_run_hooks+0x44
>> Feb 28 17:01:33 hanka ip_output() at ip_output+0x38e
>> Feb 28 17:01:33 hanka tcp_output() at tcp_output+0xacd
>> Feb 28 17:01:33 hanka tcp_usr_send() at tcp_usr_send+0x272
>> Feb 28 17:01:33 hanka sosend_generic() at sosend_generic+0x347
>> Feb 28 17:01:33 hanka soo_write() at soo_write+0x38
>> Feb 28 17:01:33 hanka dofilewrite() at dofilewrite+0x85
>> Feb 28 17:01:33 hanka kern_writev() at
>> Feb 28 17:01:33 hanka kern_writev+0x4c
>> Feb 28 17:01:33 hanka write() at write+0x54
>> Feb 28 17:01:33 hanka syscall() at syscall+0x1f6
>> Feb 28 17:01:33 hanka Xfast_syscall() at Xfast_syscall+0xab
>> Feb 28 17:01:33 hanka --- syscall (4, FreeBSD ELF64, write), rip = 
>> 0x800e1fd3c, rsp = 0x7fffffffea88, rbp = 0x16 ---
>
>
>> Feb 28 17:03:54 hanka lock order reversal:
>> Feb 28 17:03:54 hanka 1st 0xffffffff80b0f308 tcp (tcp) @ 
>> netinet/tcp_input.c:400
>> Feb 28 17:03:54 hanka 2nd 0xffffffff80b0e1e8 PFil hook read/write 
>> mutex (PFil hook read/write mutex) @ net/pfil.c:73
>> Feb 28 17:03:54 hanka KDB: stack backtrace:
>> Feb 28 17:03:54 hanka db_trace_self_wrapper() at 
>> db_trace_self_wrapper+0x2a
>> Feb 28 17:03:54 hanka witness_checkorder() at witness_checkorder+0x605
>> Feb 28 17:03:54 hanka _rw_rlock() at _rw_rlock+0x5b
>> Feb 28 17:03:54 hanka pfil_run_hooks() at pfil_run_hooks+0x44
>> Feb 28 17:03:54 hanka ip_output() at ip_output+0x38e
>> Feb 28 17:03:54 hanka tcp_respond() at tcp_respond+0x2d5
>> Feb 28 17:03:54 hanka tcp_dropwithreset() at tcp_dropwithreset+0x131
>> Feb 28 17:03:54 hanka tcp_input() at tcp_input+0x6d0
>> Feb 28 17:03:54 hanka ip_input() at ip_input+0xc0
>> Feb 28 17:03:54 hanka ether_demux() at ether_demux+0x1d9
>> Feb 28 17:03:54 hanka ether_input() at ether_input+0x19d
>> Feb 28 17:03:54 hanka em_rxeof() at em_rxeof+0x1ca
>> Feb 28 17:03:54 hanka em_poll() at em_poll+0x6f
>> Feb 28 17:03:54 hanka netisr_poll() at netisr_poll+0x87
>> Feb 28 17:03:54 hanka swi_net() at swi_net+0xea
>> Feb 28 17:03:54 hanka ithread_loop() at ithread_loop+0xda
>> Feb 28 17:03:54 hanka fork_exit() at fork_exit+0x12a
>> Feb 28 17:03:54 hanka fork_trampoline() at fork_trampoline+0xe
>> Feb 28 17:03:54 hanka --- trap 0, rip = 0, rsp = 0xffffffff9feead30, 
>> rbp = 0 ---
>
>
>> Feb 28 17:23:36 hanka lock order reversal:
>> Feb 28 17:23:36 hanka 1st 0xffffffff810f9ef0 tcp_sc_head 
>> (tcp_sc_head) @ netinet/tcp_syncache.c:477
>> Feb 28 17:23:36 hanka 2nd 0xffffffff80b0e1e8 PFil hook read/write 
>> mutex (PFil hook read/write mutex) @ net/pfil.c:73
>> Feb 28 17:23:36 hanka KDB: stack backtrace:
>> Feb 28 17:23:36 hanka db_trace_self_wrapper() at 
>> db_trace_self_wrapper+0x2a
>> Feb 28 17:23:36 hanka witness_checkorder() at witness_checkorder+0x605
>> Feb 28 17:23:36 hanka _rw_rlock() at _rw_rlock+0x5b
>> Feb 28 17:23:36 hanka pfil_run_hooks() at pfil_run_hooks+0x44
>> Feb 28 17:23:36 hanka ip_output() at ip_output+0x38e
>> Feb 28 17:23:36 hanka syncache_respond() at syncache_respond+0x32a
>> Feb 28 17:23:36 hanka syncache_add() at syncache_add+0x206
>> Feb 28 17:23:36 hanka tcp_input() at tcp_input+0xa77
>> Feb 28 17:23:36 hanka ip_input() at ip_input+0xc0
>> Feb 28 17:23:36 hanka ether_demux() at ether_demux+0x1d9
>> Feb 28 17:23:36 hanka ether_input() at ether_input+0x19d
>> Feb 28 17:23:36 hanka em_rxeof() at em_rxeof+0x1ca
>> Feb 28 17:23:36 hanka em_poll() at em_poll+0x6f
>> Feb 28 17:23:36 hanka netisr_poll() at netisr_poll+0x87
>> Feb 28 17:23:36 hanka swi_net() at swi_net+0xea
>> Feb 28 17:23:36 hanka ithread_loop() at ithread_loop+0xda
>> Feb 28 17:23:36 hanka fork_exit() at fork_exit+0x12a
>> Feb 28 17:23:36 hanka fork_trampoline() at fork_trampoline+0xe
>> Feb 28 17:23:36 hanka --- trap 0, rip = 0, rsp = 0xffffffff9feead30, 
>> rbp = 0 ---
>
> These look useful and should point to the problem.  It is also 
> probably related to something in your script:
>
>> I tried it with pf disabled, only running ipfw without dummynet, 
>> everything is ok.
>> I tried it witout pf disabled, running ipfw with dummynet queue for 
>> small traffic, everything is ok.
>> I tried it with/without pf disabled, running ipfw with dummynet queue 
>> for hight traffic >100Mbit/s, the box freezes, everytime, after 
>> enabling rules with the dummynet queue, after some second or few 
>> minutes, maybe depending on the high traffic.
>>
>> The shaper script:
>> # SHAPER
>> IPFW_PIPE_DOWNLOAD=1
>> IPFW_PIPE_UPLOAD=11
>> IPFW_QUEUE_DOWNLOAD=1
>> IPFW_QUEUE_UPLOAD=11
>>
>> DOWNLOAD_ROOT="450Mbit/s"
>> UPLOAD_ROOT="450Mbit/s"
>> SHAPER_BUCKETS="1024"
>>
>> IPFW_SHAPER_ROOT=1000
>>
>> $CMD pipe $IPFW_PIPE_DOWNLOAD config bw $DOWNLOAD_ROOT buckets 
>> $SHAPER_BUCKETS
>> $CMD pipe $IPFW_PIPE_UPLOAD config bw $UPLOAD_ROOT buckets 
>> $SHAPER_BUCKETS
>>
>> $CMD queue $IPFW_QUEUE_DOWNLOAD config pipe $IPFW_PIPE_DOWNLOAD 
>> buckets $SHAPER_BUCKETS mask dst-ip 0xFFFFFFFF
>> $CMD queue $IPFW_QUEUE_UPLOAD config pipe $IPFW_PIPE_UPLOAD buckets 
>> $SHAPER_BUCKETS mask src-ip 0xFFFFFFFF
>>
>> $CMD delete $IPFW_SHAPER_ROOT
>> $CMD $IPFW_SHAPER_ROOT add queue $IPFW_QUEUE_DOWNLOAD ip from me to 
>> any out  // Share download
>> $CMD $IPFW_SHAPER_ROOT add queue $IPFW_QUEUE_UPLOAD ip from any to me 
>> in // Share upload
>
> Thanks for the information.
>
> Kris

I hope i can help to solve this problem.

Matthew




Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?47C7EC9F.4070403>