{"id":701,"date":"2016-05-16T14:15:49","date_gmt":"2016-05-16T14:15:49","guid":{"rendered":"http:\/\/nenadnoveljic.com\/blog\/?p=701"},"modified":"2018-05-17T16:13:56","modified_gmt":"2018-05-17T16:13:56","slug":"emulex-hba-driver-performance-analysis-4-case-study","status":"publish","type":"post","link":"https:\/\/nenadnoveljic.com\/blog\/emulex-hba-driver-performance-analysis-4-case-study\/","title":{"rendered":"Comparing Latency on Emulex and QLogic HBA Driver"},"content":{"rendered":"

Introduction<\/h1>\n

In the previous installment<\/a>\u00a0I provided the emlxsoverhead.d<\/a>\u00a0script for measuring overhead on the Emulex HBA and explained its internal functioning. In this installment I’ll explain how I used this script to diagnose and analyze a real-world production problem with high I\/O latency. The problem appeared on a Solaris server which is used to run a consolidated Oracle database platform, but the findings can be applied to any low latency application running on a Solaris server equipped with Emulex HBAs.<\/p>\n

Defining the Problem<\/h1>\n

Oracle database log writer process was reporting I\/O outliers longer than 500 ms several thousands times per day:<\/p>\n

Warning: log write elapsed time 836ms, size 2KB<\/code><\/pre>\n
Although the throughput was very good and “only” 0.001% of the total I\/O operations were running longer than 500 ms, in the case of the log writer of a OLTP database this is a critical problem, because commit doesn’t return until the block gets written in the file system.<\/p>\n
Firstly, I confirmed with the script\u00a0zfsslower.d<\/a> that the outliers are also seen on the file system level. Secondly, I did the same for the block devices with the script scsi.d<\/a>\u00a0. After confirming high latencies on the block devices I checked with a storage administrator\u00a0whether he was\u00a0seeing latencies on the SAN components, but there weren’t any. At this point,\u00a0I had to develop the script emlxsoverhead.d<\/a>\u00a0as I couldn’t find anything else to measure the latency on the I\/O stack layer lower than the block devices.<\/p>\n
I was able to pinpoint the problem after evaluating the output of emlxsoverhead.d<\/a>\u00a0:<\/p>\n
TIMESTAMP            TOTAL(us)<\/span>        EMLXS(us)<\/span>        I\/O START(us)    I\/O INTR(us)     QUEUE(us)<\/span>        I\/O DONE(us)     \r\n[...truncated...]\r\n2016 Apr  7 12:13:04 1238999<\/span>          1238914<\/span>          3                6                1238738<\/span>          165              \r\n2016 Apr  7 12:13:04 1238999          1238914          3                6                1238738          165              \r\n2016 Apr  7 12:13:04 1238999          1238914          3                6                1238738          165              \r\n2016 Apr  7 12:13:04 1238999          1238914          3                6                1238738          165              \r\n2016 Apr  7 12:13:04 1238999          1238914          3                6                1238738          165              \r\n2016 Apr  7 12:13:04 1238999          1238914          3                6                1238738          165              \r\n2016 Apr  7 12:13:04 1238999          1238914          3                6                1238738          165              \r\n2016 Apr  7 12:13:04 1238999          1238914          3                6                1238738          165             \r\n[...truncated...]<\/code><\/pre>\n
The column TOTAL shows\u00a0latencies of more than 1.2 seconds which\u00a0are almost entirely\u00a0due to\u00a0waiting on the\u00a0completion queue (column QUEUE). It is a paradox that the whole round trip to SAN lasted only 85 us (microseconds! , TOTAL – EMLXCS) and then the packet waited for more than 1.2 seconds on the completion queue! I suspected some serious deficiency in the device driver code and decided to pursue this further.<\/p>\n
Drilling Down<\/h1>\n
Let’s recall the model of processing in the driver I built in the previous installment<\/a>\u00a0:<\/p>\n
\"flow<\/a><\/p>\n
The question is, why some packages stay longer in the completion queue.<\/p>\n
Let’s start with examining the activity in the I\/O done thread:<\/p>\n
#!\/bin\/sbin\/dtrace\r\n\r\nfbt:::entry\r\n\/ (uintptr_t)curthread->t_startpc == (uintptr_t)&emlxs`emlxs_thread && stackdepth <= 5 \/\r\n{\r\nself->ts_started[caller,probefunc,stackdepth] = timestamp ;\r\n}\r\n\r\nfbt:::return\r\n\/ self->ts_started[caller,probefunc,stackdepth] \/\r\n{\r\n@[caller,probefunc,stackdepth] = quantize((timestamp - self->ts_started[caller,probefunc,stackdepth])\/1000000) ;\r\nself->ts_started[caller,probefunc,stackdepth] = 0 ;\r\n}\r\n\r\ntick-1s\r\n{\r\nprintf(\"\\n\\n%Y\\n\",walltimestamp);\r\nprinta(\"%a %s %d %@d\\n\",@);\r\ntrunc(@);\r\n}\r\n\r\n[...truncated...]\r\n\r\nunix`swtch+0x165 resume 4\r\nvalue\u00a0 ------------- Distribution ------------- count\r\n-1 |\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 0\r\n0 |@\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 59\r\n1 |@@\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 116\r\n2 |@@@@@\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 270\r\n4 |@@@@@@\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 353\r\n8 |@@@@@@@@@\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 505\r\n16 |@@@@@@@@\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 447\r\n32 |@@@@@@@\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 419\r\n64 |@@\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 120\r\n128 |@\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 38\r\n256 |\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 14\r\n512 |\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 1\r\n1024 |\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 0\r\n[...truncated...]<\/code><\/pre>\n
Warning: the dtrace script above causes performance overhead. Don’t run it on a production system.<\/p>\n
It can be seen, that there are outliers when executing resume<\/em> procedure lasting up to 2 seconds. resume<\/em> code is called to handle the swithing of the thread on the processor. The outliers can also be confirmed by using a less invasive script:<\/p>\n
#!\/usr\/sbin\/dtrace\r\n\r\nfbt::cv_wait:entry\r\n\/ caller >= (uintptr_t)&emlxs`emlxs_thread && caller < (uintptr_t)&emlxs`emlxs_thread+sizeof(emlxs`emlxs_thread) \/\r\n{\r\nself->cv_wait = 1 ;\r\n}\r\n\r\nfbt::resume:entry\r\n\/ self->cv_wait \/\r\n{\r\nself->ts_started[stackdepth] = timestamp ;\r\n}\r\n\r\nfbt::resume:return\r\n\/ self->ts_started[stackdepth] \/\r\n{\r\n@[\"resume(ms)\"] = quantize((timestamp - self->ts_started[stackdepth])\/1000000);\r\nself->ts_started[stackdepth] = 0 ;\r\n}\r\n\r\ntick-1s\r\n{\r\nprinta(@);\r\ntrunc(@);\r\n}\r\n\r\nresume(ms)\r\n           value  ------------- Distribution ------------- count\r\n              -1 |                                         0\r\n               0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@            11145\r\n               1 |@@@@@@@@                                 2856\r\n               2 |@@@                                      1017\r\n               4 |                                         166\r\n               8 |                                         6\r\n              16 |                                         2\r\n              32 |                                         4\r\n              64 |                                         29\r\n             128 |                                         4\r\n             256 |                                         0\r\n             512 |                                         0\r\n            1024 |                                         1\r\n            2048 |                                         0<\/code><\/pre>\n
Furthermore, the long resumes<\/em> correlate with I\/O outliers.<\/p>\n
On one server I replaced the Emulex HBA with QLogic. After doing so, the problem with the occasional slow I\/O by the oracle database log writer process was resolved!<\/p>\n
By using DTrace and looking into the source code of the Emulex driver I explored differences in the internal functioning between the both device drivers.<\/p>\n
Comparison with QLogic<\/h1>\n
Solaris Task Queues<\/h2>\n
First, I’ll take a look at the completion stack of the qlc driver:<\/p>\n
dtrace -n 'fbt:scsi::entry { @[stack()] = count() }'\r\n\r\n[...truncated...]\r\nscsi_vhci`vhci_intr+0xb6\r\nscsi`scsi_hba_pkt_comp+0x293\r\nfcp`fcp_post_callback+0x19\r\nfcp`fcp_cmd_callback+0x72\r\nqlc`qlc_completion_thread+0xa4\r\ngenunix`taskq_thread+0x27e\r\nunix`thread_start+0x8\r\n[...truncated...]<\/code><\/pre>\n
Having genunix`taskq_thread <\/em>on the stack tells us that the QLogic driver, unlike the Emulex, uses the Solaris task queues for queueing incoming packets. This can be confirmed by running the kstat<\/em> command:<\/p>\n
kstat -c taskq\r\n\r\n[...truncated...]\r\nmodule: unix\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 instance: 0\r\nname:\u00a0\u00a0 qlc_0_comp_thd\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 class:\u00a0\u00a0\u00a0 taskq\r\ncrtime\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 1453.363526517\r\nexecuted\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 0\r\nmaxtasks\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 8\r\nnactive\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 8\r\nnalloc\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 8\r\npid\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 0\r\npriority\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 99\r\nsnaptime\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 1199076.69870013\r\ntasks\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 8\r\nthreads\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 8\r\ntotaltime\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 0\r\n[...truncated...]<\/code><\/pre>\n
In the example above the maximum of 8 threads is configured, but\u00a0the kernel adjusts the number of threads dynamically depending on the workload.<\/p>\n
The interrupt thread puts the packet in the single task queue which is then asynchronously processed by the completion threads. Task queues<\/a> are built and optimized for postponing some tasks and delegating their execution to another kernel thread. The facility is typically used by drivers. Usually, the tasks are dispatched from interrupt context.<\/p>\n
On the contrary, the Emulex driver doesn’t rely on task queues. Instead, they create 8 completion queues per HBA which are implemented as circular linked lists. Each completion queue is protected by its own mutex: either an interrupt thread or a completion thread can access a queue. After the interrupt handler puts a packet on a queue it sends a signal to the corresponding completion thread by calling the function cv_signal<\/em> and supplying the reference to the conditional variable. The completion thread, which is waiting in the cv_wait,<\/em> wakes up, gets switched on the CPU, enters the mutex, and finally processes the packet. As a consequence, the time spent in resume<\/em> contributes to the overall I\/O latency.<\/p>\n
For those willing to explore the\u00a0implementation in more detail, I’m providing the references in the source code of the Emulex driver:<\/p>\n
emlxs_thread_trigger2 function is called from interrupt context:\r\nemlxs_thread_trigger2(emlxs_thread_t *ethread, void (*func) (), CHANNEL *cp)\r\n{\r\n\r\n\/*\r\n* If the thread lock can be acquired,\r\n* it is in one of these states:\r\n* 1. Thread not started.\r\n* 2. Thread asleep.\r\n* 3. Thread busy.\r\n* 4. Thread ended.\r\n*\/\r\n...\r\nmutex_enter(&ethread->lock);\r\n...\r\n...\r\nif (ethread->flags & EMLXS_THREAD_ASLEEP) {\r\ncv_signal(&ethread->cv_flag);\r\n}\r\n\r\nmutex_exit(&ethread->lock);\r\n\r\nreturn;\r\n\r\n} \/* emlxs_thread_trigger2() *\/\r\n\r\nemlxs_thread is the startigng function in the completion thread:\r\nemlxs_thread(emlxs_thread_t *ethread)\r\n{\r\n...\r\nmutex_enter(&ethread->lock);\r\nethread->flags |= EMLXS_THREAD_STARTED;\r\n\r\nwhile (!(ethread->flags & EMLXS_THREAD_KILLED)) {\r\nif (!(ethread->flags & EMLXS_THREAD_TRIGGERED)) {\r\nethread->flags |= EMLXS_THREAD_ASLEEP;\r\ncv_wait(&ethread->cv_flag, &ethread->lock);\r\n}<\/code><\/pre>\n
Thread Priorities<\/h2>\n
Besides using task queues there is another difference between both drivers which might have an impact on the process of context switching – thread priorities. From the kstat -c taskq<\/em> output in the previous section it can be seen that the completion threads are running under the priority 99. In contrast, Emulex threads are running with the lower priority 97:<\/p>\n
#!\/usr\/sbin\/dtrace -s\r\n# pragma D option quiet\r\nfbt:::entry\r\n\/ caller >= (uintptr_t)&emlxs`emlxs_thread && caller < (uintptr_t)&emlxs`emlxs_thread+sizeof(emlxs`emlxs_thread) \/\r\n{\r\nprintf(\"prio: %d\\n\",curthread->t_pri);\r\nexit(0);\r\n}\r\n\r\nprio: 97<\/code><\/pre>\n
The Emulex thread has to compete with the ZFS and lot of other kernel threads which run with higher priority (99). Unfortunately, I couldn’t find a parameter for adjusting the default priority of the Emulex completion threads.<\/p>\n
Next Steps<\/h1>\n
Replacing Emulex HBAs with Qlogic resolved the problem with the I\/O outliers.<\/p>\n
Nevertheless, we opened a service request. The Emulex development acknowledged the problem and offered us to rewrite the device driver in the following way: the completion thread will be removed and whole processing would be done in the interrupt thread. This should completely remove the latencies caused by the completion queue. However, I’m curious to see how this change will impact the kernel CPU consumption as the interrupts require spin mutex locks (the current implementation with the completion thread\u00a0uses adaptive mutex locks).<\/p>\n
Updates<\/h1>\n
18.07.2016<\/h2>\n
Oracle delivered the patch for the following bug which indeed helped to reduce the latency on the Emulex HBA driver on the busy server:<\/p>\n
Release : Solaris 11.3 SRU # 8.7.0
\nPlatform : i386
\nBug(s) addressed :
\n23075272 : emlxs completion thread model can affect performance on busy systems
\nPackage(s) included :
\npkg:\/driver\/fc\/emlxs<\/p>\n
For me it is not clear, what exactly has changed, but I can see by observing stack traces that the completion thread was not removed.<\/p>\n
Additional Information for ZFS Users<\/h1>\n
Setting user_reserve_hint_pct,<\/em> which is the default parameter for limiting ZFS ARC has a negative impact on the latencies on the HBA driver. I\u00a0elaborated on this\u00a0here<\/a> .<\/p>\n
Conclusion<\/h1>\n
The Qlogic (QLC) HBA driver has lower latencies than Emulex driver. There are two implementation differences which might explain the difference in the behavior:<\/p>\n