Setting Boundaries<\/h1>\n
The fbt probes will be used for recording the timestamps at the beginning and the end of each stage. Therefore, the appropriate functions need to be identified. The entry probe of the first emlxs function on the stack is a good choice for recording the starting point of\u00a0a processing stage.<\/p>\n
Since scripts based on fbt trace raw kernel code, it might happen that they have to be adapted for different kernel and driver releases.<\/p>\n
Let’s\u00a0examine the\u00a0functions for each of the stages.<\/p>\n
I\/O Start<\/h2>\n
First, I’ll collect the stacks for the emlxs functions and identify the stack. The stack for I\/O will contain\u00a0some transport\u00a0functions:<\/p>\n
dtrace -n 'fbt:emlxs::entry { @[stack()] = count(); }'\r\n[...truncated...]\r\nemlxs`emlxs_sli4_bde_setup+0x233\r\nemlxs`emlxs_sli4_prep_fcp_iocb+0x10a\r\nemlxs`emlxs_send_fcp_cmd+0x137\r\nemlxs`emlxs_fca_transport+0x256\r\nfctl`fc_ulp_transport+0x22a\r\n[...truncated...]<\/code><\/pre>\nThe first emlxs function on the stack is emlxs_fca_transport:<\/p>\n
emlxs_solaris.c:\r\nemlxs_fca_transport(opaque_t fca_port_handle, fc_packet_t *pkt)<\/code><\/pre>\nThe second argument pkt is the pointer to the packet structure. The address of the buffer will be used to uniquely identify the packet while it’s traversing\u00a0different stages.<\/p>\n
Next, I’ll verify that the function executes once and only once for each I\/O by looking at the number of executions under load:<\/p>\n
dtrace -n 'fbt:emlxs::entry,fbt:fctl:fc_ulp_transport:entry { @[probefunc] = count(); }'\r\n[...truncated...]\r\nfc_ulp_transport 23316\r\n[...truncated...]\r\nemlxs_fca_transport 23316\r\n[...truncated...]\r\n<\/code><\/pre>\nSince this prerequisite is fulfilled, the entry and the return probe can be used to record the timestamp of the beginning and the end of the I\/O start stage, respectively:<\/p>\n
\/* I\/O Start Begin *\/\r\nfbt::emlxs_fca_transport:entry\r\n{\r\n self->pkt_addr = arg1 ;\r\n ts_start_begin[self->pkt_addr] = timestamp ;\r\n}\r\n\r\n\/* I\/O Start End *\/\r\nfbt::emlxs_fca_transport:return\r\n\/ self->pkt_addr \/\r\n{\r\n ts_start_end[self->pkt_addr] = timestamp ;\r\n self->pkt_addr = 0 ;\r\n}<\/code><\/pre>\nI\/O Interrupt<\/h2>\n
Second, the stack of the interrupt handler thread will be examined:<\/p>\n
[...truncated...]\r\nemlxs`emlxs_mem_put+0x9d\r\nemlxs`emlxs_sli4_free_xri+0xe1\r\nemlxs`emlxs_sli4_process_wqe_cmpl+0xff\r\nemlxs`emlxs_sli4_process_cq+0x139\r\nemlxs`emlxs_sli4_process_eq+0xda\r\nemlxs`emlxs_sli4_msi_intr+0x7f\r\napix`apix_dispatch_by_vector+0x89\r\napix`apix_dispatch_lowlevel+0x32\r\nunix`switch_sp_and_call+0x13\r\n[...truncated...]<\/code><\/pre>\nAs the processing\u00a0of the interrupt\u00a0begins with the function emlxs_sli4_msi_intr, the begin timestamp will be collected in the entry probe. However, this function doesn’t contain any obvious arguments which could identify the scsi packet. From the the previous installment<\/a> we already know that the first function on the stack which could be associated with the packet is emlxs_sli4_process_wqe_cmpl. Therefore, the start time\u00a0has to\u00a0be initialized in the entry probe of emlxs_sli4_msi_intr and then stored in the associative array within the entry probe of emlxs_sli4_process_wqe_cmpl:<\/p>\n\/* I\/O Interrupt Begin *\/\r\nfbt::emlxs_sli4_msi_intr:entry\r\n{\r\n self->start_ts_intr = timestamp ;\r\n}\r\n\r\nfbt::emlxs_sli4_process_wqe_cmpl:entry\r\n\/ self->start_ts_intr \/\r\n{\r\n self->pkt_addr \\\r\n = (int64_t)args[0]->fc_table[args[2]->RequestTag]->pkt ;\r\n ts_interrupt_begin[self->pkt_addr] = self->start_ts_intr ;\r\n}<\/code><\/pre>\nThe return probe of fbt::emlxs_sli4_process_wqe_cmpl is suitable for storing the timestamp of the end of the I\/O interrupt stage:<\/p>\n
\/* I\/O Interrupt End *\/\r\nfbt::emlxs_sli4_process_wqe_cmpl:return\r\n\/ self->pkt_addr \/\r\n{\r\n ts_interrupt_end[self->pkt_addr] = timestamp ;\r\n}\r\n<\/code><\/pre>\nI\/O Done (Completion Thread)<\/h2>\n
Again, the first thing to do is to explore the stack and find appropriate functions for storing the timestamps:<\/p>\n
[...truncated...]\r\nfcp`fcp_cmd_callback+0x72\r\nemlxs`emlxs_handle_fcp_event+0x9fa\r\nemlxs`emlxs_proc_channel_event+0x647\r\nemlxs`emlxs_proc_channel+0x62\r\nemlxs`emlxs_thread+0x169\r\nunix`thread_start+0x8\r\n[...truncated...]<\/code><\/pre>\nemlxs_thread, the first function on the stack, gets executed only during driver initialization, so its entry and return probes can’t be used for storing the timestamp information. The next choice is emlxs_proc_channel which comes immediately after:<\/p>\n
\/* I\/O Done Begin *\/\r\nfbt::emlxs_proc_channel:entry\r\n{\r\n self->start_ts = timestamp ;\r\n}<\/code><\/pre>\nThe entry probe of fcp_cmd_callback might be a good candidate for recording the end time of an I\/O done operation, because it is the first non-emlxs function on the stack. I’ll just quickly confirm that it fires once and only once for each I\/O:<\/p>\n
dtrace -n 'fbt::fcp_cmd_callback:entry,fbt:fctl:fc_ulp_transport:entry { @[probefunc] = count(); }'\r\nfcp_cmd_callback 14800\r\nfc_ulp_transport 14803<\/code><\/pre>\nBelow is the code excerpt for storing the timestamps:<\/p>\n
\/* I\/O Done End *\/\r\nfbt::fcp_cmd_callback:entry\r\n\/ ts_start_begin[arg0] && ts_interrupt_begin[arg0] && self->start_ts \/\r\n{\r\n this->ts_done_end = timestamp ;\r\n\r\n this->pkt_addr = arg0 ;\r\n this->ts_done_begin = self->start_ts ;\r\n self->start_ts = 0 ;\r\n[...truncated...]<\/code><\/pre>\nElapsed Times<\/h1>\n
The flow chart below visualizes the processing stages with the points where the timestamps are collected:<\/p>\n
![\"Emulex](\"http:\/\/nenadnoveljic.com\/blog\/wp-content\/uploads\/2016\/04\/flow-chart4.gif\")
<\/a>Emulex Flow Chart<\/p><\/div>\n
Note that the interrupt handler puts the packets onto the completion queue which is consumed by the I\/O done (completion) thread.<\/p>\n
The timestamps collected according to the flow chart above\u00a0are sufficient\u00a0for\u00a0calculating the elapsed times for each stage:<\/p>\n
duration_start = ts_start_end - ts_start_begin \r\nduration_interrupt = ts_interrupt_end - ts_interrupt_begin \r\nduration_done = ts_done_end - ts_done_begin<\/code><\/pre>\nThe total elapsed time for an I\/O is the difference between ts_done_end and ts_start_begin:<\/p>\n
duration_total = ts_done_end - ts_start_begin<\/code><\/pre>\nThe time spent waiting in the completion queue:<\/p>\n
duration_queue = ts_done_begin - ts_interrupt_end<\/code><\/pre>\nAnd now comes the most interesting part: by setting the measurement points as in the flow chart above we can calculate the total elapsed time spent in the driver code, which is the key point for analysing driver’s performance:<\/p>\n
duration_emlxs = duration_start + ts_done_end - ts_interrupt_begin<\/code><\/pre>\nMoreover, we can even calculate how much time in total was spent outside of the Solaris kernel (Emulex HBA, SAN network and SAN storage) without knowing anything about those devices:<\/p>\n
duration_external = duration_total - duration_emlxs<\/code><\/pre>\nemlxsoverhead.d<\/h1>\n
I assembled the code excerpts above into the script emlxsoverhead.d<\/a>. The script\u00a0prints the latency of each I\/O\u00a0and the durations of\u00a0all processing stages. Optionally, the threshold for displaying only longer I\/Os can be provided. For example, the following command will display only I\/Os lasting more than 1 ms:<\/p>\ndtrace -Cs emlxsoverhead.d<\/code><\/pre>\nThe script prints following data:<\/p>\n
TIMESTAMP: time when I\/O was performed \r\nTOTAL(us): I\/O latency measured on the driver \r\nEMLXS(us): overhead of the driver code \r\nI\/O START(us): duration of the I\/O start stage \r\nI\/O INTR(us): time spent in the interrupt handler \r\nQUEUE(us): time spent on the completion queue \r\nI\/O DONE: time spent on the completion thread<\/code><\/pre>\nBelow is the example output:<\/p>\n
TIMESTAMP\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 TOTAL(us) EMLXS(us) I\/O START(us)\u00a0 I\/O INTR(us)\u00a0 QUEUE(us) I\/O DONE(us)\r\n2016 Apr\u00a0 9 19:31:21 1028\u00a0\u00a0\u00a0\u00a0\u00a0 35\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 7\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 9\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 12\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 6\r\n2016 Apr\u00a0 9 19:31:21 4928\u00a0\u00a0\u00a0\u00a0\u00a0 35\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 8\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 5\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 11\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 10\r\n2016 Apr\u00a0 9 19:31:21 4721\u00a0\u00a0\u00a0\u00a0\u00a0 46\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 6\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 9\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 14\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 16\r\n<\/code><\/pre>\nIn the example above, the first I\/O took 1028 microseconds and the most of this time was spent outside\u00a0 the kernel. The longest processing step in the driver was waiting in the completion queue (12 microseconds).<\/p>\n
Longer I\/O latencies, where the most time is elapsed\u00a0in the driver code (EMLXS), are not normal and should be investigated further.<\/p>\n
Conclusion<\/h1>\n
In this installment I explained how to measure the time spent in each processing stage of the Emulex device driver and provided the script for it. In the next installment I’ll explain how I analyzed\u00a0a production problem with\u00a0a high latency.<\/p>\n","protected":false},"excerpt":{"rendered":"
The blog post describes how to measure elapsed time in the Emulex HBA driver. Continue Reading