high CPU usage in FreeBSD for a PCIe card driver

[Steevan Rodrigues]

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 at 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
>