Date: Wed, 11 Jul 2018 17:16:23 +0530 From: Steevan Rodrigues <steevanxperia@gmail.com> To: Andrew Gallatin <gallatin@cs.duke.edu> Cc: freebsd-hackers@freebsd.org Subject: Re: high CPU usage in FreeBSD for a PCIe card driver Message-ID: <CAKsGTHQ_5jVPfu-4ZdaswZSb3-=NX_%2Bskow6ZW44YuWAhtWf3w@mail.gmail.com> In-Reply-To: <2ae78782-6cca-452e-d004-3999885ae4e0@cs.duke.edu> References: <CAKsGTHR9AzX2v%2B%2BDbNCdt7RwxEfw8jKwndXzH9oxQEHvPszo%2Bw@mail.gmail.com> <a7caaecb-dd62-0c0f-e9ad-b83517bb3c7f@cs.duke.edu> <CAKsGTHRdArYrT33KR6Kx4CqwsTR5MRaC%2BTQfV7yTuQej4_eOXQ@mail.gmail.com> <2ae78782-6cca-452e-d004-3999885ae4e0@cs.duke.edu>
next in thread | previous in thread | raw e-mail | index | archive | help
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 <gallatin@cs.duke.edu>
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
>
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?CAKsGTHQ_5jVPfu-4ZdaswZSb3-=NX_%2Bskow6ZW44YuWAhtWf3w>