/************************************************************************** * * * Copyright (c) International Business Machines Corp., 2005 * * * * This program is free software; you can redistribute it and/or modify * * it under the terms of the GNU General Public License as published by * * the Free Software Foundation; either version 2 of the License, or * * (at your option) any later version. * * * * This program is distributed in the hope that it will be useful, but * * WITHOUT ANY WARRANTY; without even the implied warranty of * * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the * * GNU General Public License for more details. * * * * You should have received a copy of the GNU General Public License * * along with this program; if not, write to the Free Software * * Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA 02111-1307 USA * * * * Author: Guanglei Li (guanglei@cn.ibm.com) * **************************************************************************/ /*********************************************************** * Trace the following activities of scsi layer: * * 1. I/O Entry * * 2. Issuing I/O to LLD * * 3. I/O done by LLD * * 4. I/O Complete * * * * Due to a bug for elfutils on ppc64, it failed to find * * any module debuginfo. Hien listed this as a bug in: * * * http://sourceware.org/ml/systemtap/2005-q4/msg00222.html * * * * Roland is fixing this. * ***********************************************************/ %{ #include #include #include #include #include #include %} probe addevent.scsi = addevent.scsi.ioentry, addevent.scsi.iodispatching, addevent.scsi.iodone, addevent.scsi.iocompleted { } /* mid-layer prepare a IO request */ probe addevent.scsi.ioentry = module("scsi_mod").function("scsi_prep_fn") { if(filter_by_pid() == 1 ) { log_tracedata_common(HOOKID_SCSI_IOENTRY) log_scsi_ioentry_extra($q, $req) } } /* Dispatch a command to the low-level driver. */ probe addevent.scsi.iodispatching = module("scsi_mod").function("scsi_dispatch_cmd") { if(filter_by_pid() == 1 ) { log_tracedata_common(HOOKID_SCSI_IO_TO_LLD) /* sdev_state|scsi_info|data_direction|request_buffer|request_bufflen| */ log_scsi_dispatch_extra_1($cmd) /* cmd_identifier| */ log_scsi_dispatch_extra_2($cmd) } } /* I/O is done by low-level driver*/ probe addevent.scsi.iodone = module("scsi_mod").function("scsi_done") { /* scsi timer check. We should record the hook only * when the timer is inactive. But there's a gap between * the checking and the actual calling of scsi_delete_timer. */ if(filter_by_pid() == 1 ) { if( scsi_timer_pending($cmd) == 1) { log_tracedata_common(HOOKID_SCSI_IODONE_BY_LLD) log_scsi_iodone_extra($cmd) } } } /* mid-layer processes the completed IO */ probe addevent.scsi.iocompleted = module("scsi_mod").function("scsi_io_completion") { if(filter_by_pid() == 1 ) { log_tracedata_common(HOOKID_SCSI_IOCOMP_BY_MIDLEVEL) log_scsi_iocompleted_extra($cmd, $good_bytes) } } function scsi_timer_pending:long(var:long) %{ struct scsi_cmnd *cmd = (struct scsi_cmnd *)((long)THIS->var); THIS->__retvalue = timer_pending(&cmd->eh_timeout); %} /* log the info about scsi io entry */ function log_scsi_ioentry_extra(var_q:long, var_rq:long) %{ struct request_queue *q = (struct request_queue *)((long)THIS->var_q); struct request *rq = (struct request *)((long)THIS->var_rq); struct scsi_device *sdev = (struct scsi_device *)(q->queuedata); /* major|minor|scsi_device_state| */ _stp_printf("%d|%d|%d|", rq->rq_disk->major, rq->rq_disk->first_minor, sdev->sdev_state); %} /* log the info about scsi_dispatching_cmd */ function log_scsi_dispatch_extra_1(var:long) %{ struct scsi_cmnd *cmd = (struct scsi_cmnd *)((long)THIS->var); long long scsi_info; scsi_info = ((cmd->device->host->host_no & 0xFF) << 24) | ((cmd->device->channel & 0xFF) << 16) | ((cmd->device->lun & 0xFF) << 8) | (cmd->device->id & 0xFF); /* sdev_state|scsi_info|data_direction|cmd_identifier|request_buffer|request_bufflen * * sdev_state could be: SDEV_DEL, SDEV_BLOCK or something else. * Instead of skipping SDEV_DEL & SDEV_BLOCK, I choose to log them */ _stp_printf("%d|%lld|%d|%0x|%d", cmd->device->sdev_state, scsi_info, cmd->sc_data_direction, cmd->request_buffer, cmd->request_bufflen); %} /* log the info about scsi_dispatching_cmd * * cmd_identifier| * * Now we can use cmd->serial_number as cmd identifier(still valid till * 2.6.14.2. But according to the comments of struct scsi_cmnd, it's * a better to use cmd->pid since cmd->serial_number will be killed one * day in the future * * But when scsi_dispatch_cmd is called, cmd->serial_number is still not * initialized. * For kernel >= 2.6.14, it will be set later by calling scsi_cmd_get_serial. * So I choose to record cmd->device->host->cmd_pid. But there is a gap between * the time when cmd->device->host->cmd_pid is retrieved at the beginning of * scsi_dispatch_cmd and the actual calling of scsi_cmd_get_serial. * * For kernel <=2.6.9, it will be set by a global counter. * * NOTE: The kernel version need further investigation. */ %( kernel_v >= "2.6.14" %? function log_scsi_dispatch_extra_2(var:long) %{ struct scsi_cmnd *cmd = (struct scsi_cmnd *)((long)THIS->var); long long scsi_info; _stp_printf("%d|", cmd->device->host->cmd_pid); %} %: function log_scsi_dispatch_extra_2(var:long) %{ struct scsi_cmnd *cmd = (struct scsi_cmnd *)((long)THIS->var); long long scsi_info; /* systemTap failed to access global variable. So I temporarily use 0. _stp_printf("%d|", scsi_pid); */ _stp_printf("%d|", 0); %} %) /* log the info about scsi_done */ function log_scsi_iodone_extra(var:long) %{ struct scsi_cmnd *cmd = (struct scsi_cmnd *)((long)THIS->var); long long scsi_info; scsi_info = ((cmd->device->host->host_no & 0xFF) << 24) | ((cmd->device->channel & 0xFF) << 16) | ((cmd->device->lun & 0xFF) << 8) | (cmd->device->id & 0xFF); /* scsi_info|data_direction|cmd_identifier| */ _stp_printf("%lld|%d|%d", scsi_info, cmd->sc_data_direction, cmd->pid); %} /* log the info about scsi_dispatching_cmd */ function log_scsi_iocompleted_extra(var_cmd:long, var_goodbytes:long) %{ struct scsi_cmnd *cmd = (struct scsi_cmnd *)((long)THIS->var_cmd); long long scsi_info; unsigned long goodbytes = (unsigned long)(THIS->var_goodbytes); scsi_info = ((cmd->device->host->host_no & 0xFF) << 24) | ((cmd->device->channel & 0xFF) << 16) | ((cmd->device->lun & 0xFF) << 8) | (cmd->device->id & 0xFF); /* scsi_info|data_direction|cmd_identifier|goodbytes */ _stp_printf("%lld|%d|%d|%u", scsi_info, cmd->sc_data_direction, cmd->pid, goodbytes); %}