From owner-freebsd-hackers@freebsd.org Wed Jul 11 11:46:25 2018 Return-Path: Delivered-To: freebsd-hackers@mailman.ysv.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2610:1c1:1:606c::19:1]) by mailman.ysv.freebsd.org (Postfix) with ESMTP id 4EA19103142B for ; Wed, 11 Jul 2018 11:46:25 +0000 (UTC) (envelope-from steevanxperia@gmail.com) Received: from mail-oi0-x243.google.com (mail-oi0-x243.google.com [IPv6:2607:f8b0:4003:c06::243]) (using TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)) (Client CN "smtp.gmail.com", Issuer "Google Internet Authority G2" (verified OK)) by mx1.freebsd.org (Postfix) with ESMTPS id D3AD38CFFB for ; Wed, 11 Jul 2018 11:46:24 +0000 (UTC) (envelope-from steevanxperia@gmail.com) Received: by mail-oi0-x243.google.com with SMTP id s198-v6so48649264oih.11 for ; Wed, 11 Jul 2018 04:46:24 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=mime-version:in-reply-to:references:from:date:message-id:subject:to :cc; bh=U73PWFzQC6kvM0wNVb7Y6t8LAqfzOfqqSbyTwENndjQ=; b=RytkGMiFv8vuYTxqkC1hmzVeX7qh2cqywzGnNk+vvzS5G/gRrBaWXAVzvlvS9/fSgb ly7fp7C4jkCt8iUKedjCXkIccpeAkGeD132HklAVk6zlJiQImwuQcNithy4BtCXyWkHR dXsQv2Y6x0ALTUJJz7BURTuZHljlhUTfRNAirXZ0pWK4j8+VRppmmlU5Uxj4fBkai8C7 r3HCudcDVEKyIcI8s3ALPDajY4pZwRHul+7OtMOJXG2fWdLiI5jYOSCCdidy9SMpauQk CzXMdCtEYqKtOnaSz1XiTnuooyG1pvaRcJuBz5OY6+wxPf/Zoez60ky1d+u4ogBb3Ikp 6A4g== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:mime-version:in-reply-to:references:from:date :message-id:subject:to:cc; bh=U73PWFzQC6kvM0wNVb7Y6t8LAqfzOfqqSbyTwENndjQ=; b=Wb1NYsMQVjx59qdRd0oqEK4VwH4cWmLq09WLWVVfJIK4xrGnchuTbn/ss6dF/qRdBj FiD31nFhVTDnl6Dc5fjjph80dVwcSz2qzPdHxB+xZ4TQsu9DSySz78/Ai275vs3MXnfb jM5mmBxo9KY3blIoqcR+nhKXLsyCO0DJqTADrKD1Q6bHdiolYcTYeV3PEzJAPu5qwkJQ DELanFEj8vQ9iD4XEC6LS5c+teszXZLnEHRvZT5hcPrjaxFIuZ5D795hGVdBWrwVUNvt BvU2D45eeCaywSbLGcC+4L2zTdV09yPteWUsk595CdS/mfYf1feyvvn1PNzerC+jftCf gtbA== X-Gm-Message-State: APt69E14dFssKOozILLIWQPEWj3vusgq+2rcV1bax7qH/g/HU1LcpMm8 DZuFUT7rCMTx60IgA+jGLfp2Y3qerusqbEorhI0EXw== X-Google-Smtp-Source: AAOMgpeDzrZzrc2m2Lr4pwSL0nc5QILy9P1XM7fVrcESryhthBfIIsE+eviP44yd9Pu/rhaxvQnQB5pA0ksDkSXkHy0= X-Received: by 2002:aca:a806:: with SMTP id r6-v6mr33301100oie.213.1531309583832; Wed, 11 Jul 2018 04:46:23 -0700 (PDT) MIME-Version: 1.0 Received: by 2002:ac9:5bd6:0:0:0:0:0 with HTTP; Wed, 11 Jul 2018 04:46:23 -0700 (PDT) In-Reply-To: <2ae78782-6cca-452e-d004-3999885ae4e0@cs.duke.edu> References: <2ae78782-6cca-452e-d004-3999885ae4e0@cs.duke.edu> From: Steevan Rodrigues Date: Wed, 11 Jul 2018 17:16:23 +0530 Message-ID: Subject: Re: high CPU usage in FreeBSD for a PCIe card driver To: Andrew Gallatin Cc: freebsd-hackers@freebsd.org Content-Type: text/plain; charset="UTF-8" X-Content-Filtered-By: Mailman/MimeDel 2.1.27 X-BeenThere: freebsd-hackers@freebsd.org X-Mailman-Version: 2.1.27 Precedence: list List-Id: Technical Discussions relating to FreeBSD List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Wed, 11 Jul 2018 11:46:25 -0000 Hello Andrew, Sorry to bother you. I am working on this problem again after a break of few days. I ran following command to get lock statistics when I run my userspace application on a 12 core 24 thread server PC. >From this data below to looks like my driver is causing a contention on a kernel lock (pmap ). Am I right ? lockstat -x aggsize=4m -D 20 sleep 10 Adaptive mutex spin: 1122679 events in 10.013 seconds (112121 events/sec) Count indv cuml rcnt nsec Lock Caller ------------------------------------------------------------------------------- 1089662 97% 97% 0.00 65375 pmap pmap_extract+0x1d2 31805 3% 100% 0.00 14881 cdev devvn_refthread+0x142 651 0% 100% 0.00 180642 umtxql umtxq_sleep+0x1f5 254 0% 100% 0.00 30212 umtxql __umtx_op_sem2_wake+0x3b6 68 0% 100% 0.00 14218 umtxql umtxq_busy+0x17e 63 0% 100% 0.00 3441 umtxql __umtx_op_sem2_wake+0x410 59 0% 100% 0.00 1067 swi taskqueue_enqueue+0xba 42 0% 100% 0.00 1632 swi taskqueue_run_locked+0x4f 21 0% 100% 0.00 65453 umtxql do_lock_umutex+0x5ec 13 0% 100% 0.00 3693 umtxql do_sem2_wait+0x948 8 0% 100% 0.00 49129 USB device mutex usb_callback_proc+0x114 7 0% 100% 0.00 2248 swi taskqueue_run+0x117 5 0% 100% 0.00 11294 umtxql do_lock_umutex+0x632 5 0% 100% 0.00 67423 umtxql _sleep+0x2e4 3 0% 100% 0.00 697 umtxql do_cv_wait+0x619 3 0% 100% 0.00 58600 Giant _cv_wait+0x1d1 2 0% 100% 0.00 21866 umtxql __umtx_op_wake2_umutex+0x419 2 0% 100% 0.00 6097 cdev count_dev+0xe 2 0% 100% 0.00 4695 cdev vputx+0xe0 1 0% 100% 0.00 754 umtxql do_unlock_umutex+0x1027 ------------------------------------------------------------------------------- Adaptive mutex block: 10182 events in 10.013 seconds (1017 events/sec) Count indv cuml rcnt nsec Lock Caller ------------------------------------------------------------------------------- 9590 94% 94% 0.00 283901 pmap pmap_extract+0x1d2 570 6% 100% 0.00 280204 cdev devvn_refthread+0x142 13 0% 100% 0.00 36414 umtxql umtxq_sleep+0x1f5 8 0% 100% 0.00 156849 umtxql __umtx_op_sem2_wake+0x3b6 1 0% 100% 0.00 169422 cdev vputx+0xe0 ------------------------------------------------------------------------------- Spin lock spin: 683399 events in 10.013 seconds (68250 events/sec) Count indv cuml rcnt nsec Lock Caller ------------------------------------------------------------------------------- 466417 68% 68% 0.00 137603 sleepq chain MXD_ioctlFifoGetData.constprop.27+0x309 117135 17% 85% 0.00 64922 sleepq chain MXD_kUsrPutData2Fifo+0xff 16013 2% 88% 0.00 107380 turnstile chain turnstile_trywait+0x85 11157 2% 89% 0.00 9110 mos.memLock MXD_mosMemFree+0x2d 9534 1% 91% 0.00 4598 spinlock MXD_mosPerCpuCacheMemFree+0x5f 7084 1% 92% 0.00 6277 turnstile lock turnstile_trywait+0x16b 6689 1% 93% 0.00 5404 mos.memLock MXD_mosMemAlloc+0xcd 4298 1% 93% 0.00 15026 ACPI lock (0xfffff800086c0c00) AcpiOsAcquireLock+0x80 2201 0% 94% 0.00 17123 turnstile chain __mtx_unlock_sleep+0x5d 1420 0% 94% 0.00 4821 sleepq chain wakeup+0xf 1152 0% 94% 0.00 1353 spinlock MXD_mosPerCpuCacheMemAlloc+0x3a 1087 0% 94% 0.00 4561 turnstile lock turnstile_lookup+0xa3 959 0% 94% 0.00 6673 sched lock 20 sched_add+0xe5 901 0% 95% 0.00 7814 sched lock 18 sched_add+0xe5 884 0% 95% 0.00 7031 sched lock 22 sched_add+0xe5 881 0% 95% 0.00 7597 sched lock 14 sched_add+0xe5 879 0% 95% 0.00 6127 sched lock 23 sched_add+0xe5 867 0% 95% 0.00 7511 sched lock 1 sched_add+0xe5 862 0% 95% 0.00 6403 sched lock 15 sched_add+0xe5 856 0% 95% 0.00 9624 sched lock 2 sched_add+0xe5 ------------------------------------------------------------------------------- Thanks Steevan On Thu, Jun 28, 2018 at 10:17 PM, Andrew Gallatin wrote: > On 06/28/18 12:44, Steevan Rodrigues wrote: > > Thank you so much for the suggestions . I will use these commands. > > Yes, I am already working on to identify lock contentions. > > > > Re-built FreeBSD kernel by enabling lock profiling and now I am able to > > see some issues with contention. > > > > Thanks > > Steevan > > > You need-not rebuild freebsd. lockstat is based on dtrace.. > > The lock profiling you're referring to is a different mechanism. > > Drew >