From owner-freebsd-stable@freebsd.org Mon Sep 26 12:05:01 2016 Return-Path: Delivered-To: freebsd-stable@mailman.ysv.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:1900:2254:206a::19:1]) by mailman.ysv.freebsd.org (Postfix) with ESMTP id DA721BEA866 for ; Mon, 26 Sep 2016 12:05:01 +0000 (UTC) (envelope-from slw@zxy.spb.ru) Received: from zxy.spb.ru (zxy.spb.ru [195.70.199.98]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (Client did not present a certificate) by mx1.freebsd.org (Postfix) with ESMTPS id 9C24A19C; Mon, 26 Sep 2016 12:05:01 +0000 (UTC) (envelope-from slw@zxy.spb.ru) Received: from slw by zxy.spb.ru with local (Exim 4.86 (FreeBSD)) (envelope-from ) id 1boUeY-0006QB-J2; Mon, 26 Sep 2016 15:04:58 +0300 Date: Mon, 26 Sep 2016 15:04:58 +0300 From: Slawa Olhovchenkov To: Julien Charbon Cc: Konstantin Belousov , freebsd-stable@FreeBSD.org, hiren panchasara Subject: Re: 11.0 stuck on high network load Message-ID: <20160926120458.GK2840@zxy.spb.ru> References: <20160920202633.GQ2840@zxy.spb.ru> <20160921195155.GW2840@zxy.spb.ru> <20160922095331.GB2840@zxy.spb.ru> <67862b33-63c0-2f23-d254-5ddc55dbb554@freebsd.org> <20160922102045.GC2840@zxy.spb.ru> <20160923191656.GF2840@zxy.spb.ru> <20160925185815.GA6177@zxy.spb.ru> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: User-Agent: Mutt/1.5.24 (2015-08-30) X-SA-Exim-Connect-IP: X-SA-Exim-Mail-From: slw@zxy.spb.ru X-SA-Exim-Scanned: No (on zxy.spb.ru); SAEximRunCond expanded to false X-BeenThere: freebsd-stable@freebsd.org X-Mailman-Version: 2.1.23 Precedence: list List-Id: Production branch of FreeBSD source code List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Mon, 26 Sep 2016 12:05:01 -0000 On Mon, Sep 26, 2016 at 10:51:07AM +0200, Julien Charbon wrote: > > 1049 kqread - I 145:58.35 nginx: worker process (nginx) > > 1050 kqread - I 136:33.36 nginx: worker process (nginx) > > 1051 kqread - I 140:59.73 nginx: worker process (nginx) > > 1052 kqread - I 137:18.12 nginx: worker process (nginx) > > > > pid 1046 is nginx running on CPU0 (affinity mask set). > > > > # procstat -k -k 1046 > > PID TID COMM TDNAME KSTACK > > 1046 100686 nginx - mi_switch+0xd2 critical_exit+0x7e lapic_handle_timer+0xb1 Xtimerint+0x8c __mtx_lock_sleep+0x168 zone_fetch_slab+0x47 zone_import+0x52 zone_alloc_item+0x36 keg_alloc_slab+0x63 keg_fetch_slab+0x16e zone_fetch_slab+0x6e zone_import+0x52 uma_zalloc_arg+0x36e m_getm2+0x14f m_uiotombuf+0x64 sosend_generic+0x356 soo_write+0x42 dofilewrite+0x87 > > > > Tracing command nginx pid 1046 tid 100686 td 0xfffff8014485f500 > > sched_switch() at 0xffffffff804c956d = sched_switch+0x6ad/frame 0xfffffe20216992a0 /usr/src/sys/kern/sched_ule.c:1973 > > mi_switch() at 0xffffffff804a8d92 = mi_switch+0xd2/frame 0xfffffe20216992d0 /usr/src/sys/kern/kern_synch.c:465 > > critical_exit() at 0xffffffff804a6bee = critical_exit+0x7e/frame 0xfffffe20216992f0 /usr/src/sys/kern/kern_switch.c:219 > > lapic_handle_timer() at 0xffffffff80771701 = lapic_handle_timer+0xb1/frame 0xfffffe2021699330 /usr/src/sys/x86/x86/local_apic.c:1185 > > Xtimerint() at 0xffffffff806cbbcc = Xtimerint+0x8c/frame 0xfffffe2021699330 /usr/src/sys/amd64/amd64/apic_vector.S:135 > > --- interrupt, rip = 0xffffffff804de424, rsp = 0xfffffe2021699400, rbp = 0xfffffe2021699420 --- > > lock_delay() at 0xffffffff804de424 = lock_delay+0x54/frame 0xfffffe2021699420 /usr/src/sys/kern/subr_lock.c:127 > > __mtx_lock_sleep() at 0xffffffff80484dc8 = __mtx_lock_sleep+0x168/frame 0xfffffe20216994a0 /usr/src/sys/kern/kern_mutex.c:512 > > zone_fetch_slab() at 0xffffffff806a4257 = zone_fetch_slab+0x47/frame 0xfffffe20216994e0 /usr/src/sys/vm/uma_core.c:2378 > > zone_import() at 0xffffffff806a4312 = zone_import+0x52/frame 0xfffffe2021699530 /usr/src/sys/vm/uma_core.c:2501 > > zone_alloc_item() at 0xffffffff806a0986 = zone_alloc_item+0x36/frame 0xfffffe2021699570 /usr/src/sys/vm/uma_core.c:2591 > > keg_alloc_slab() at 0xffffffff806a2463 = keg_alloc_slab+0x63/frame 0xfffffe20216995d0 /usr/src/sys/vm/uma_core.c:965 > > keg_fetch_slab() at 0xffffffff806a48ce = keg_fetch_slab+0x16e/frame 0xfffffe2021699620 /usr/src/sys/vm/uma_core.c:2349 > > zone_fetch_slab() at 0xffffffff806a427e = zone_fetch_slab+0x6e/frame 0xfffffe2021699660 /usr/src/sys/vm/uma_core.c:2375 > > zone_import() at 0xffffffff806a4312 = zone_import+0x52/frame 0xfffffe20216996b0 /usr/src/sys/vm/uma_core.c:2501 > > uma_zalloc_arg() at 0xffffffff806a147e = uma_zalloc_arg+0x36e/frame 0xfffffe2021699720 /usr/src/sys/vm/uma_core.c:2531 > > m_getm2() at 0xffffffff8048231f = m_getm2+0x14f/frame 0xfffffe2021699790 /usr/src/sys/kern/kern_mbuf.c:830 > > m_uiotombuf() at 0xffffffff80516044 = m_uiotombuf+0x64/frame 0xfffffe20216997e0 /usr/src/sys/kern/uipc_mbuf.c:1535 > > sosend_generic() at 0xffffffff8051ce56 = sosend_generic+0x356/frame 0xfffffe20216998a0 > > soo_write() at 0xffffffff804fd872 = soo_write+0x42/frame 0xfffffe20216998d0 > > dofilewrite() at 0xffffffff804f5c97 = dofilewrite+0x87/frame 0xfffffe2021699920 > > kern_writev() at 0xffffffff804f5978 = kern_writev+0x68/frame 0xfffffe2021699970 > > sys_writev() at 0xffffffff804f5be6 = sys_writev+0x36/frame 0xfffffe20216999a0 > > amd64_syscall() at 0xffffffff806e4051 = amd64_syscall+0x2c1/frame 0xfffffe2021699ab0 > > Xfast_syscall() at 0xffffffff806cb2bb = Xfast_syscall+0xfb/frame 0xfffffe2021699ab0 > > --- syscall (121, FreeBSD ELF64, sys_writev), rip = 0x8019cc6ba, rsp = 0x7fffffffd688, rbp = 0x7fffffffd6c0 --- > > This call stack is quite interesting: > 1: A process is calling writev() > 2: Kernel calls sosend_generic() that starts allocating memory > 3: This allocation is then interrupted by the timer interrupt handler > [that could actually trigger tcp_tw_2msl_scan(reuse=0)] > 4: The timer interrupt handler seems to wait on sched_switch() No, this is more interesting: double call (recuersion) to zone_import()! > And fun fact: When sosend_generic() calls m_uiotombuf() it does not > hold INP_WLOCK yet... Yes, is not INP_WLOCK related, this is like next error.