In the previous\u00a0installment<\/a>\u00a0I described how to measure end-to-end latency on the HBA device driver. In this article I’ll explore the workflow within the Emulex HBA driver code. Since I couldn’t find any documentation on Internet I used DTrace and the driver’s source code to figure this out.<\/p>\n First, the call stacks will be collected to get an initial idea about the packet\u00a0processing workflow\u00a0in the code. In the previous post<\/a>\u00a0we learned which modules participate in the I\/O processing (emlxs, fbt and fcp):<\/p>\n Three different types of stack can be identified for processing the following stages of the I\/O life-cycle: I\/O start, I\/O done and I\/O interrupt handling.<\/p>\n The I\/O start stack can be recognized by the functions like scsi_transport and scsi_start:<\/p>\n The I\/O done stack can be recognized by the functions *destroy_pkt and\u00a0*uninit_packet:<\/p>\n The interrupt handler can be recognized by the function switch_sp_and_call which is the solaris Kernel function for dispatching interrupts (see this blog post by Saurabh Mishra<\/a>):<\/p>\n The first Emulex device driver’s function on the stack is emlxs_sli4_msi_intr, which should be the interrupt handler. According to the manual\u00a0Writing Device Drivers for Oracle\u00ae Solaris 11.2<\/a> , the device driver’s interrupt handler must be registered in the driver’s attach entry point. This can be confirmed by looking into the source code:<\/p>\n The following model\u00a0of the workflow can be deduced from the findings above:<\/p>\n I\/O start ->\u00a0I\/O interrupt handler -> I\/O complete<\/p>\n As for the next step, we will build a DTrace script to verify this assumption. The DTrace script will follow a single packet through the hba driver’s execution workflow. To be able to do this, we have to identify one function on each stack which fullfils the following requirements: The same is required for the I\/O interrupt stack. First, it makes sense to find out which functions on the I\/O interrupt stack get executed for each I\/O . This can be done by counting function calls and comparing them with the number of exections of fc_ emlxs_sli4_process_wqe_cmpl is the first function on the stack which executes for each I\/O operation. At the first glance,\u00a0it’s arguments don’t look promising:<\/p>\n I’ll examine the first couple of lines in the source code:<\/p>\n cq is some structure that gets passed to the function\u00a0for each I\/O. It contains emlxs_buf_t *sbp Bingo! The buffer variable contains the reference to the scsi packet variable which can be used as the key for the associative arrays which store the timing information when the packet gets processed\u00a0in\u00a0\u00a0different threads. By looking at the code above, we can deduce how to dereference the pointer to pkt in the DTrace entry probe of the emlxs_sli4_process_wqe_cmpl function:<\/p>\n Now, all the information is there to build the emlxssnoop.d script which will be used to verify the assumption about the packet flow I made previously:<\/p>\n By running the script with the command below, we get the timestamp at each processing stage for each packet in the output file emlxssnoop.log:<\/p>\n We can pick any buffer (for example 67553736358984) and then sort the output on the timestamp to see that the packet flows through the driver code in the assumed order:<\/p>\n In this installment we learned which threads participate in the processing of packets and in which order they process them: start, interrupt and done. I offered the method for testing the model. By doing so, the foundation is laid for further exploring of the\u00a0internal functioning of the Emulex driver.<\/p>\n In the next blog post, I’ll describe the methodology and provide the scripts for measuring the elapsed time per packet\u00a0during different stages of the I\/O, which is the key point for\u00a0analysing the driver performance.<\/p>\n Stay tuned!<\/p>\n","protected":false},"excerpt":{"rendered":" The blog post describes how to explore the SCSI packet flow through different processing stages in the Emulex HBA driver. Continue Reading Stack Fishing<\/h1>\n
dtrace -n 'fbt:emlxs::entry,fbt:scsi::entry,fbt:fctl::entry,fbt:fcp::entry { @[stack()] = count(); }'<\/code><\/pre>\nI\/O Start Stack<\/h2>\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\nfcp`fcp_transport+0x27\r\nfcp`fcp_scsi_start<\/span>+0x149\r\nscsi`scsi_transport<\/span>+0x233\r\nscsi_vhci`vhci_scsi_start+0x45d\r\nscsi`scsi_transport<\/span>+0x2b2\r\nsd`sd_start_cmds+0x34f\r\nsd`sd_core_iostart+0x186\r\nsd`sd_mapblockaddr_iostart+0x1ef\r\nsd`sd_xbuf_strategy+0x4e\r\nsd`xbuf_iostart+0x1e2\r\nsd`ddi_xbuf_qstrategy+0xd7\r\nsd`sdstrategy+0x175\r\ngenunix`bdev_strategy+0x66\r\ngenunix`ldi_strategy+0x56\r\nzfs`vdev_disk_strategy+0x158\r\n[...truncated...]<\/code><\/pre>\nI\/O Done Stack<\/h2>\n
[...truncated...]\r\nfctl`fc_ulp_uninit_packet<\/span>+0x2f\r\nfcp`fcp_pkt_teardown+0x8b\r\nscsi`scsi_cache_destroy_pkt<\/span>+0x46\r\nscsi`scsi_destroy_pkt<\/span>+0x21\r\nscsi_vhci`vhci_scsi_destroy_pkt<\/span>+0x2f\r\nscsi`scsi_destroy_pkt<\/span>+0x21\r\nsd`sd_destroypkt_for_buf+0x20\r\nsd`sd_return_command+0x17c\r\nsd`sdintr+0x584\r\nscsi`scsi_hba_pkt_comp+0x293\r\nscsi_vhci`vhci_intr+0x7df\r\nscsi`scsi_hba_pkt_comp+0x293\r\nfcp`fcp_post_callback+0x19\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>\nInterrupt Stack<\/h2>\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<\/span>+0x7f\r\napix`apix_dispatch_by_vector+0x89\r\napix`apix_dispatch_lowlevel+0x32\r\nunix`switch_sp_and_call<\/span>+0x13\r\n[...truncated...]<\/code><\/pre>\nemlxs_hba.c:\r\nemlxs_msi_add(emlxs_hba_t *hba)\r\n{\r\n[...truncated...]\r\n ret =\r\n ddi_intr_add_handler(htable[i], EMLXS_SLI_MSI_INTR,\r\n (char *)hba, (char *)((unsigned long)i));\r\n[...truncated...]\r\n\r\nemlxs_fc.h:\r\n#define EMLXS_INTR_ADD(_hba) emlxs_msi_add(_hba)\r\n#define EMLXS_SLI_MSI_INTR (hba->sli_api.sli_msi_intr)\r\n#define\u00a0\u00a0\u00a0\u00a0\u00a0 EMLXS_SLI_ONLINE\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0(hba->sli_api.sli_online)\r\n\r\nemlxs_sli4.c:\r\nemlxs_sli4_online(emlxs_hba_t *hba)\r\n{\r\n...\r\n...\r\nif (EMLXS_INTR_ADD(hba) != DDI_SUCCESS) {\r\n...\r\n\r\nemlxs_sli_api_t emlxs_sli4_api = {\r\n...\r\n emlxs_sli4_online,\r\n...\r\n emlxs_sli4_msi_intr,\r\n...};\r\n\r\nemlxs_hba.c:\r\nhba->sli_api = emlxs_sli4_api;\r\n<\/code><\/pre>\nWorkflow<\/h1>\n
\n– the packet can be unambigously identified by one of the arguments,
\n– the function gets executed once and only once for each I\/O operation.
\nFor the IO start and stop stacks these functions and arguments have already been identified in the previous blog post<\/a> (I’ve chosen the address of the pkt variable as\u00a0the key for the associative arrays used to track the packet across different threads):<\/p>\nfctl.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)<\/code><\/pre>\ndtrace -n 'fbt:emlxs::entry,fbt:fctl:fc_ulp_transport:entry { @[probefunc] = count(); }'\r\n[...truncated...]\r\nemlxs_sli4_free_xri 39334\r\n[...truncated...]\r\nemlxs_sli4_process_wqe_cmpl 39334<\/span>\r\n[...truncated...]\r\nfc_ulp_transport 39334<\/span>\r\n[...truncated...]\r\nemlxs_mem_put 39340\r\n[...truncated...]\r\nemlxs_sli4_cqid_to_index 39828\r\nemlxs_sli4_msi_intr 39828\r\nemlxs_sli4_process_cq 39828\r\nemlxs_sli4_process_eq 39828\r\n[...truncated...]\r\n<\/code><\/pre>\nemlxs_sli4.c: \r\nemlxs_sli4_process_wqe_cmpl(emlxs_hba_t *hba, CQ_DESC_t *cq, CQE_CmplWQ_t *cqe)<\/code><\/pre>\n emlxs_buf_t *sbp;\r\n[...truncated...]\r\n request_tag = cqe->RequestTag;\r\n[...truncated...]\r\n sbp = hba->fc_table[request_tag];\r\n<\/code><\/pre>\n
\nwhich looks like the buffer which is likely to remain the same during the entire life-cycle of the packet. Let’s examine the structure of this buffer:<\/p>\nemlxs_fc.h\r\n[...truncated...]\r\ntypedef struct emlxs_buf\r\n{\r\n fc_packet_t *pkt; \/* scsi_pkt reference *\/\r\n[...truncated...]<\/code><\/pre>\n(int64_t)args[0]->fc_table[args[2]->RequestTag]->pkt<\/code><\/pre>\n#!\/usr\/sbin\/dtrace -Cs\r\n\r\n\/* emlxssnoop.d *\/\r\n\r\n#pragma D option quiet\r\n\u00a0\r\n#define PRINT_PKT(pkt,milestone) \\\r\n\u00a0 printf(\"%d %-18d %-15s %-15s \\n\",timestamp,pkt,milestone,probefunc)\r\n\u00a0\r\nfbt::fc_ulp_transport:entry\r\n{\r\n\u00a0 PRINT_PKT(arg1,\"START\");\r\n}\r\n\u00a0\r\nfbt::emlxs_sli4_process_wqe_cmpl:entry\r\n{\r\n\u00a0 PRINT_PKT((int64_t)args[0]->fc_table[args[2]->RequestTag]->pkt,\"INTERRUPT\");\r\n}\r\n\u00a0\r\nfbt::fc_ulp_uninit_packet:entry\r\n{\r\n\u00a0 PRINT_PKT(arg1,\"DONE\");\r\n}<\/code><\/pre>\ndtrace -Cs emlxssnoop.d > emlxssnoop.log<\/code><\/pre>\ngrep 67553736358984 emlxssnoop.log | sort \r\n[...truncated...]\r\n26733383288531382 -67553736358984 START fc_ulp_transport\r\n26733383294539371 -67553736358984 INTERRUPT emlxs_sli4_process_wqe_cmpl\r\n26733383294605233 -67553736358984 DONE fc_ulp_uninit_packet\r\n<\/span>26733383479942799 -67553736358984 START fc_ulp_transport\r\n26733383480366376 -67553736358984 INTERRUPT emlxs_sli4_process_wqe_cmpl\r\n26733383480393173 -67553736358984 DONE fc_ulp_uninit_packet<\/span>\r\n26733383491508798 -67553736358984 START fc_ulp_transport\r\n26733383491570635 -67553736358984 INTERRUPT emlxs_sli4_process_wqe_cmpl\r\n26733383491623284 -67553736358984 DONE fc_ulp_uninit_packet\r\n<\/span>[...truncated...]<\/code><\/pre>\nConclusion<\/h1>\n