However, if you do the analysis down the I\/O stack and still\u00a0observe a high latency on block devices, this article might apply to your problem.\u00a0 In\u00a0today’s blog post\u00a0I will explain how to measure the end-to-end latency on the HBA driver.<\/p>\n
SDT DTrace Probes<\/h1>\n
First, I looked if there are any existing\u00a0DTrace providers<\/a> for the HBA drivers, but I couldn’t find any.<\/p>\n As the next best choice, I\u00a0looked for sdt (Statically Defined Tracing) providers, but no luck there as well:<\/p>\n Note: emlxs is the name of the Emulex driver.<\/p>\n Since the driver code has not been instrumented with the SDT probes,\u00a0the Function Boundary Tracing provider (fbt) has to be used. As the fbt provider\u00a0traces the execution of\u00a0raw kernel code, DTrace scripts that are based on it, may break between kernel and driver releases.<\/p>\n As for the next step, the driver functions\u00a0that\u00a0initiate I\/O operations have to be identified. Therefore, I’ll collect the call stacks when any of the Emulex driver functions are being executed:<\/p>\n I eyeballed the collected stack backtraces to identify the stack which initiates the transfer:<\/p>\n The stack was easily identified because it contains calls to the scsi_transport function. fctl`fc_ulp_transport is the first Solaris HBA generic driver function on the stack before the first emlxs call. Therefore, I’ll consider using the return boundary of this function for recording the I\/O start operations.<\/p>\n The stack above cannot be used for identifying the complete stack of the I\/O done event, becuse the functions will be called in the reversed order, namely the emulex functions first and than the generic ones. However, we can use the I\/O start stack for identifying the module names of the functions which process the I\/O and then\u00a0collect stacks backtraces of all the functions involved in the I\/O operation:<\/p>\n Obviously, the functions destroying the packet\u00a0complete the IO:<\/p>\n The function fctl`fc_ulp_uninit_packet is close to the emulex driver functions on the I\/O completion stack, so it could be used for marking the end of the I\/O operation.<\/p>\n Let’s\u00a0check whether the number of the executions of the functions, that\u00a0have been\u00a0picked for measuring starting and finishing point of a single IO, match:<\/p>\n The output has confirmed that the number of executions of fctl`fc_ulp_uninit_packet and fctl`fc_ulp_transport are 22356 and 23358 respectively, which corresponds to the number of the I\/O operations during the observed time period. The small difference is attributable to two in-flight I\/O operations\u00a0that have not been finished yet, in the moment the count script was interrupted. Because of the multipathing (scsi_vhci) the scsi functions will be called twice.<\/p>\n A little difficulty in associating the I\/O start of a given paket with its I\/O done event is caused by the fact that I\/O start and I\/O done are not performed\u00a0within the\u00a0same thread. For the sake of efficiency, the thread gets off the CPU after an I\/O\u00a0was submitted. After receiving the data from storage, the\u00a0HBA device\u00a0sends an interrupt which afterwards get handled by another thread. As a consequence, the start time must be stored in an associative array instead in a thread variable. Thus, we need to find a unique key to access the start time once the I\/O gets finished. An appropriate key\u00a0can be identified by examining the function arguments of the both functions:<\/p>\n The second argument, the address of the packet variable (pkt),\u00a0is unlikely\u00a0to change\u00a0during the whole life-cycle of the I\/O. Based on this assumption, I wrote the following dtrace script for measuring the latency on\u00a0the HBA driver:<\/p>\n hbalatency.d can be\u00a0verified by \u00a0scsi.d<\/a> .<\/p>\n Note: I changed the time units from ns to ms in scsi.d. The following\u00a0functional diagram\u00a0can be deduced from the collected stacks:<\/p>\n It should be kept in mind that\u00a0 the end-to-end\u00a0latency measured on the HBA device driver also contains round-trips to\u00a0storage.<\/p>\n In today’s blog post\u00a0I scratched the surface of the Emulex\u00a0HBA driver and\u00a0built\u00a0the script for measuring the latency on it. In the next installments I’ll\u00a0dig into the driver’s internals and provide DTrace scripts for instrumenting different parts of the processing chain.<\/p>\n","protected":false},"excerpt":{"rendered":" The blog post describes how to measure latency on Emulex HBA driver. Continue Reading dtrace -ln 'sdt:::' | grep emlxs<\/code><\/pre>\nStack Fishing for I\/O Start<\/h1>\n
dtrace -n 'fbt:emlxs::entry { @[stack()] = count(); }'<\/code><\/pre>\n\r\n[...truncated...]\r\n emlxs`emlxs_sli4_prep_fcp_iocb+0xda\r\n emlxs`emlxs_send_fcp_cmd+0x137\r\n emlxs`emlxs_fca_transport+0x256\r\n fctl`fc_ulp_transport<\/span>+0x22a\r\n fcp`fcp_transport+0x27\r\n fcp`fcp_scsi_start+0x149\r\n scsi`scsi_transport+0x233\r\n scsi_vhci`vhci_scsi_start+0x45d\r\n scsi`scsi_transport+0x2b2\r\n sd`sd_start_cmds+0x34f\r\n sd`sd_core_iostart+0x186\r\n sd`sd_mapblockaddr_iostart+0x1ef\r\n sd`sd_xbuf_strategy+0x4e\r\n sd`xbuf_iostart+0x1e2\r\n sd`ddi_xbuf_qstrategy+0xd7\r\n sd`sdstrategy+0x175\r\n genunix`bdev_strategy+0x66\r\n genunix`ldi_strategy+0x56\r\n zfs`vdev_disk_strategy+0x158\r\n zfs`vdev_disk_io_start+0x10c\r\n[...truncated...]\r\n<\/code><\/pre>\nStack Fishing for I\/O Done<\/h1>\n
dtrace -n 'fbt:emlxs::entry,fbt:scsi::entry,fbt:fctl::entry,fbt:fcp::entry { @[stack()] = count(); }'<\/code><\/pre>\n[...truncated...]\r\nfctl`fc_ulp_uninit_packet<\/span>+0x2f\r\n\tfcp`fcp_pkt_teardown+0x8b\r\n\tscsi`scsi_cache_destroy_pkt+0x46\r\n\tscsi`scsi_destroy_pkt+0x21\r\n\tscsi_vhci`vhci_intr+0x7af\r\n\tscsi`scsi_hba_pkt_comp+0x293\r\n\tfcp`fcp_post_callback+0x19\r\n\tfcp`fcp_cmd_callback+0x72\r\n\temlxs`emlxs_handle_fcp_event+0x9fa\r\n\temlxs`emlxs_proc_channel_event+0x647\r\n\temlxs`emlxs_proc_channel+0x62\r\n\temlxs`emlxs_thread+0x169\r\n\tunix`thread_start+0x8\r\n[...truncated...]\r\n<\/code><\/pre>\nCross-Checking by Counting Functions Calls<\/h1>\n
dtrace -n 'fbt:emlxs::entry,fbt:scsi::entry,fbt:fctl::entry,fbt:fcp::entry { @[probefunc] = count(); }'\r\n[...truncated...]\r\n emlxs_fca_pkt_init 22356\r\n emlxs_fca_pkt_uninit 22356\r\n fc_ulp_init_packet 22356\r\n fc_ulp_uninit_packet 22356\r\n<\/span> fcp_pkt_setup 22356\r\n fcp_pkt_teardown 22356\r\n emlxs_CQE_to_IOCB 22358\r\n emlxs_check_dma 22358\r\n emlxs_fca_transport 22358\r\n emlxs_handle_fcp_event 22358\r\n emlxs_initialize_pkt 22358\r\n emlxs_msiid_to_chan 22358\r\n emlxs_node_find_did 22358\r\n emlxs_proc_channel_event 22358\r\n emlxs_select_fcp_channel 22358\r\n emlxs_select_msiid 22358\r\n emlxs_send_fcp_cmd 22358\r\n emlxs_sli4_alloc_xri 22358\r\n emlxs_sli4_bde_setup 22358\r\n emlxs_sli4_free_xri 22358\r\n emlxs_sli4_prep_fcp_iocb 22358\r\n emlxs_sli4_process_wqe_cmpl 22358\r\n emlxs_sli4_write_wqdb 22358\r\n emlxs_unswap_pkt 22358\r\n emlxs_update_sd_bucket 22358\r\n fc_ulp_transport 22358<\/span>\r\n fcp_cmd_callback 22358\r\n fcp_complete_pkt 22358\r\n fcp_post_callback 22358\r\n fcp_prepare_pkt 22358\r\n fcp_reconfig_wait 22358\r\n fcp_scsi_start 22358\r\n fcp_transport 22358\r\n emlxs_mem_get 22362\r\n emlxs_mem_pool_get 22362\r\n emlxs_mem_pool_put 22362\r\n emlxs_mem_put 22362\r\n scsi_cache_destroy_pkt 22640\r\n scsi_cache_dmafree_attr 22640\r\n scsi_hba_pkt_alloc 22640\r\n scsi_hba_pkt_free 22640\r\n scsi_cache_init_pkt 22642\r\n emlxs_sli4_cqid_to_index 22920\r\n emlxs_sli4_msi_intr 22920\r\n emlxs_sli4_process_cq 22920\r\n emlxs_sli4_process_eq 22920\r\n scsi_pkt2bp 39577\r\n emlxs_swap_fcp_pkt 44716\r\n emlxs_tx_get 44948\r\n emlxs_sli4_issue_iocb_cmd 44983\r\n scsi_destroy_pkt 45280\r\n scsi_init_pkt 45282\r\n scsi_hba_pkt_comp 45286<\/span>\r\n scsi_transport 45286\r\n emlxs_sli4_write_cqdb 45840\r\n[...truncated...]\r\n<\/code><\/pre>\n
\nIt can also be seen that some of the the scsi functions get executed twice as many. The script scsicmds.d<\/a> helps to clarify this phenomenon:<\/p>\n[...truncated...]\r\n fp synchronize_cache 8712\r\n scsi_vhci synchronize_cache 8712\r\n fp read(10) 14558\r\n scsi_vhci read(10) 14586\r\n fp write(10) 21197\r\n scsi_vhci write(10) 21886\r\n<\/code><\/pre>\nPairing\u00a0I\/O Start\u00a0with I\/O Done<\/h1>\n
fctl.c:fc_ulp_transport(opaque_t port_handle, fc_packet_t *pkt)\r\nfctl.c:fc_ulp_uninit_packet(opaque_t port_handle, fc_packet_t *pkt)\r\n<\/code><\/pre>\n#!\/usr\/sbin\/dtrace -s\r\n\r\n\/* hbalatency.d *\/\r\n\r\nfbt::fc_ulp_transport:entry\r\n{\r\n start_time[arg1] = timestamp ;\r\n}\r\n\r\nfbt::fc_ulp_uninit_packet:entry\r\n\/ start_time[arg1] \/\r\n{\r\n this->diff = (timestamp - start_time[arg1])\/1000000 ;\r\n @[\"latency (ms)\"] = quantize(this->diff) ;\r\n start_time[arg1] = 0 ;\r\n}\r\n<\/code><\/pre>\nVerification<\/h1>\n
dtrace -qCs scsi.d -D QUIET -D PERF_REPORT \r\n scsi_vhci 0\r\n value ------------- Distribution ------------- count \r\n -1 | 0 \r\n 0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 368543 \r\n 1 |@@ 16447 \r\n 2 |@ 8801 \r\n 4 |@ 12638 \r\n 8 |@ 10302 \r\n 16 | 2190 \r\n 32 | 306 \r\n 64 | 87 \r\n 128 | 2 \r\n 256 | 0 \r\n\r\ndtrace -s hba_latency.d\r\n latency (ms) \r\n value ------------- Distribution ------------- count \r\n -1 | 0 \r\n 0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 356419 \r\n 1 |@@ 15541 \r\n 2 |@ 8432 \r\n 4 |@ 12351 \r\n 8 |@ 10079 \r\n 16 | 2081 \r\n 32 | 292 \r\n 64 | 70 \r\n 128 | 2 \r\n 256 | 0 \r\n\r\n<\/code><\/pre>\n
\nIt seems to be a pretty good match. The minor differencies are attributable to very small delay in starting and initializing the script.<\/p>\nWhat\u00a0Do We\u00a0Measure?<\/h1>\n
![\"hba_stack\"](\"http:\/\/nenadnoveljic.com\/blog\/wp-content\/uploads\/2016\/04\/hba_stack.gif\")
<\/a><\/p>\nConclusion<\/h1>\n