1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
|
// Copyright (C) 2005, 2006 IBM Corp.
//
// This file is part of systemtap, and is free software. You can
// redistribute it and/or modify it under the terms of the GNU General
// Public License (GPL); either version 2, or (at your option) any
// later version
/***********************************************************
* 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 *
* *
***********************************************************/
%{
#include <linux/types.h>
#include <scsi/scsi_cmnd.h>
#include <scsi/scsi_device.h>
#include <scsi/scsi_host.h>
#include <linux/timer.h>
#include <linux/blkdev.h>
%}
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
= scsi.ioentry
{
log_scsi_ioentry(HOOKID_SCSI_IOENTRY, $q, $req)
}
/* Dispatch a command to the low-level driver. */
probe addevent.scsi.iodispatching
= scsi.iodispatching
{
log_scsi_dispatch(HOOKID_SCSI_IO_TO_LLD, $cmd)
}
/* I/O is done by low-level driver*/
probe addevent.scsi.iodone
= scsi.iodone
{
/* 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( scsi_timer_pending($cmd) == 1) {
log_scsi_iodone_extra(HOOKID_SCSI_IODONE_BY_LLD, $cmd)
}
}
/* mid-layer processes the completed IO */
probe addevent.scsi.iocompleted
= scsi.iocompleted
{
log_scsi_iocompleted(HOOKID_SCSI_IOCOMP_BY_MIDLEVEL, $cmd, $good_bytes)
}
/* log the info about scsi io entry */
function log_scsi_ioentry(var_id:long, 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|
*/
_lket_trace(_GROUP_SCSI, THIS->var_id, "%1b%1b%1b", (_FMT_)rq->rq_disk->major,
(_FMT_)rq->rq_disk->first_minor, (_FMT_)sdev->sdev_state);
%}
/* log the info about scsi_dispatching_cmd
*
*
* Now we can use cmd->serial_number as cmd identifier
* 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.12, 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.
*/
/* sdev_state|scsi_info|data_direction|request_buffer|request_bufflen|cmd_identifier| */
%( kernel_v >= "2.6.12" %?
function log_scsi_dispatch(var_id:long, var:long)
%{
struct scsi_cmnd *cmd = (struct scsi_cmnd *)((long)THIS->var);
int 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
*/
_lket_trace(_GROUP_SCSI, THIS->var_id, "%1b%4b%1b%8b%4b%8b",
(_FMT_)cmd->device->sdev_state, (_FMT_)scsi_info,
(_FMT_)cmd->sc_data_direction, (int64_t)((long)cmd->request_buffer),
(_FMT_)cmd->request_bufflen, (int64_t)cmd->device->host->cmd_pid);
%}
%:
function log_scsi_dispatch(var_id:long, var:long)
%{
struct scsi_cmnd *cmd = (struct scsi_cmnd *)((long)THIS->var);
int 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
*/
/* systemTap failed to access global variable. So I temporarily use 0.
_stp_printf("%d|", scsi_pid);
*/
_lket_trace(_GROUP_SCSI, THIS->var_id, "%1b%4b%1b%8b%4b%8b",
(_FMT_)cmd->device->sdev_state, (_FMT_)scsi_info,
(_FMT_)cmd->sc_data_direction, (int64_t)((long)cmd->request_buffer),
(_FMT_)cmd->request_bufflen, (int64_t)0);
%}
%)
/* log the info about scsi_done */
function log_scsi_iodone_extra(var_id:long, var:long)
%{
struct scsi_cmnd *cmd = (struct scsi_cmnd *)((long)THIS->var);
int 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| */
_lket_trace(_GROUP_SCSI, THIS->var_id, "%4b%1b%8b", (_FMT_)scsi_info,
(_FMT_)cmd->sc_data_direction, (int64_t)cmd->pid);
%}
/* log the info about scsi_dispatching_cmd */
function log_scsi_iocompleted(var_id:long, var_cmd:long, var_goodbytes:long)
%{
struct scsi_cmnd *cmd = (struct scsi_cmnd *)((long)THIS->var_cmd);
int 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 */
_lket_trace(_GROUP_SCSI, THIS->var_id, "%4b%1b%8b%4b", (_FMT_)scsi_info,
(_FMT_)cmd->sc_data_direction, (int64_t)cmd->pid, (_FMT_)goodbytes);
%}
|
