坏盘导致IO hang问题分析（续）

发表于 | 分类于 |

经过前面的分析测试，使用fio直接测试裸盘（direct=1）的时候，将后端设备suspend住后，fio的IO hang的时间跟前面计算的一致；但是当在虚拟机里对这块盘做了文件系统，然后fio测试文件系统（direct=1）的时候，将后端设备suspend住后，fio的IO hang的时间多了20~30s。

初步分析

一开始怀疑是由于虚拟机这层的作用，因此还调整过KVM使用的盘的缓存策略（none、writethrough、directsync），同样的测试，仍然是IO hang比预期的多20~30s。

打开iscsi session debug开关，开启scsi error和timeout的日志，然后分析这样测试过程中的日志信息。下面截取部分日志，发现有3个时间点：16:45:21、16:45:31、16:45:41比较奇怪，没有连续的日志，都有10s的空白期。而且从16:45:41到16:45:51后，就是”Device offlined - not ready after error recovery”，而之前从裸盘上测试时是没有这几次10s的空白期，而且是I/O error，而不是device offlined后再I/O error。

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
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
Feb  9 16:45:01 10-180-0-37 bash: HISTORY: PID=17516 UID=2010 sudo dmsetup suspend /dev/mapper/chunk_ebsdisk01_a551bcbe-a6c_1_1
...........
Feb  9 16:45:02 10-180-0-37 kernel: [3820717.924401]  session50: iscsi_eh_cmd_timed_out scsi cmd ffff881e3dd21780 timedout
Feb  9 16:45:02 10-180-0-37 kernel: [3820717.924415]  session50: iscsi_eh_cmd_timed_out return timer reset
.......
Feb  9 16:45:04 10-180-0-37 kernel: [3820719.927424]  session50: iscsi_eh_cmd_timed_out scsi cmd ffff881e3dd21780 timedout
Feb  9 16:45:04 10-180-0-37 kernel: [3820719.927434]  session50: iscsi_eh_cmd_timed_out return nh
Feb  9 16:45:04 10-180-0-37 kernel: [3820719.927437] Waking error handler thread
Feb  9 16:45:04 10-180-0-37 kernel: [3820719.927446] Error handler scsi_eh_50 waking up
Feb  9 16:45:04 10-180-0-37 kernel: [3820719.927620] sd 50:0:0:11: scsi_eh_prt_fail_stats: cmds failed: 0, cancel: 1
Feb  9 16:45:04 10-180-0-37 kernel: [3820719.927627] Total of 1 commands on 1 devices require eh work
Feb  9 16:45:04 10-180-0-37 kernel: [3820719.927629] scsi_eh_50: aborting cmd:0xffff881e3dd21780
Feb  9 16:45:04 10-180-0-37 kernel: [3820719.927632]  session50: iscsi_eh_abort aborting sc ffff881e3dd21780
Feb  9 16:45:04 10-180-0-37 kernel: [3820719.927635]  session50: iscsi_eh_abort aborting [sc ffff881e3dd21780 itt 0x35]
Feb  9 16:45:04 10-180-0-37 kernel: [3820719.927641]  session50: iscsi_exec_task_mgmt_fn tmf set timeout
Feb  9 16:45:04 10-180-0-37 kernel: [3820719.927688] iscsi_trgt: Abort Task (01) issued on tid:2000 lun:11 by sid:7881300190757376 (Function Complete)
Feb  9 16:45:04 10-180-0-37 kernel: [3820719.927726]  session50: iscsi_eh_abort abort success [sc ffff881e3dd21780 itt 0x35]
Feb  9 16:45:04 10-180-0-37 kernel: [3820719.927784] scsi_eh_done scmd: ffff881e3dd21780 result: 0
Feb  9 16:45:04 10-180-0-37 kernel: [3820719.927791] scsi_send_eh_cmnd: scmd: ffff881e3dd21780, timeleft: 2500
Feb  9 16:45:04 10-180-0-37 kernel: [3820719.927793] scsi_send_eh_cmnd: scsi_eh_completed_normally 2002
Feb  9 16:45:04 10-180-0-37 kernel: [3820719.927796] scsi_eh_tur: scmd ffff881e3dd21780 rtn 2002
Feb  9 16:45:04 10-180-0-37 kernel: [3820719.927798] scsi_eh_50: flush retry cmd: ffff881e3dd21780
Feb  9 16:45:04 10-180-0-37 kernel: [3820719.927963] scsi_restart_operations: waking up host to restart
Feb  9 16:45:04 10-180-0-37 kernel: [3820719.928153] Error handler scsi_eh_50 sleeping
.............
Feb  9 16:45:06 10-180-0-37 kernel: [3820721.746537]  session50: iscsi_eh_cmd_timed_out scsi cmd ffff881e3dd21780 timedout
Feb  9 16:45:06 10-180-0-37 kernel: [3820721.746553]  session50: iscsi_eh_cmd_timed_out return timer reset
...................
Feb  9 16:45:08 10-180-0-37 kernel: [3820723.745561]  session50: iscsi_eh_cmd_timed_out scsi cmd ffff881e3dd21780 timedout
Feb  9 16:45:08 10-180-0-37 kernel: [3820723.745574]  session50: iscsi_eh_cmd_timed_out return nh
Feb  9 16:45:08 10-180-0-37 kernel: [3820723.745577]  session50: iscsi_eh_cmd_timed_out scsi cmd ffff881e57fee080 timedout
Feb  9 16:45:08 10-180-0-37 kernel: [3820723.745585]  session50: iscsi_eh_cmd_timed_out return timer reset
................
Feb  9 16:45:10 10-180-0-37 kernel: [3820725.744585]  session50: iscsi_eh_cmd_timed_out scsi cmd ffff881e57fee080 timedout
Feb  9 16:45:10 10-180-0-37 kernel: [3820725.744598]  session50: iscsi_eh_cmd_timed_out return nh
Feb  9 16:45:10 10-180-0-37 kernel: [3820725.744602] Waking error handler thread
Feb  9 16:45:10 10-180-0-37 kernel: [3820725.744606] Error handler scsi_eh_50 waking up
Feb  9 16:45:10 10-180-0-37 kernel: [3820725.744785] sd 50:0:0:11: scsi_eh_prt_fail_stats: cmds failed: 0, cancel: 2
Feb  9 16:45:10 10-180-0-37 kernel: [3820725.744791] Total of 2 commands on 1 devices require eh work
Feb  9 16:45:10 10-180-0-37 kernel: [3820725.744793] scsi_eh_50: aborting cmd:0xffff881e3dd21780
Feb  9 16:45:10 10-180-0-37 kernel: [3820725.744796]  session50: iscsi_eh_abort aborting sc ffff881e3dd21780
Feb  9 16:45:10 10-180-0-37 kernel: [3820725.744799]  session50: iscsi_eh_abort aborting [sc ffff881e3dd21780 itt 0x2d]
Feb  9 16:45:10 10-180-0-37 kernel: [3820725.744806]  session50: iscsi_exec_task_mgmt_fn tmf set timeout
Feb  9 16:45:10 10-180-0-37 kernel: [3820725.744855] iscsi_trgt: Abort Task (01) issued on tid:2000 lun:11 by sid:7881300190757376 (Function Complete)
Feb  9 16:45:10 10-180-0-37 kernel: [3820725.744902]  session50: iscsi_eh_abort abort success [sc ffff881e3dd21780 itt 0x2d]
Feb  9 16:45:10 10-180-0-37 kernel: [3820725.744904] scsi_eh_50: aborting cmd:0xffff881e57fee080
Feb  9 16:45:10 10-180-0-37 kernel: [3820725.744906]  session50: iscsi_eh_abort aborting sc ffff881e57fee080
Feb  9 16:45:10 10-180-0-37 kernel: [3820725.744908]  session50: iscsi_eh_abort aborting [sc ffff881e57fee080 itt 0x36]
Feb  9 16:45:10 10-180-0-37 kernel: [3820725.744916]  session50: iscsi_exec_task_mgmt_fn tmf set timeout
Feb  9 16:45:10 10-180-0-37 kernel: [3820725.744936] iscsi_trgt: Abort Task (01) issued on tid:2000 lun:11 by sid:7881300190757376 (Function Complete)
Feb  9 16:45:10 10-180-0-37 kernel: [3820725.744959]  session50: iscsi_eh_abort abort success [sc ffff881e57fee080 itt 0x36]
Feb  9 16:45:10 10-180-0-37 kernel: [3820725.745033] scsi_eh_done scmd: ffff881e3dd21780 result: 0
Feb  9 16:45:10 10-180-0-37 kernel: [3820725.745040] scsi_send_eh_cmnd: scmd: ffff881e3dd21780, timeleft: 2500
Feb  9 16:45:10 10-180-0-37 kernel: [3820725.745042] scsi_send_eh_cmnd: scsi_eh_completed_normally 2002
Feb  9 16:45:10 10-180-0-37 kernel: [3820725.745045] scsi_eh_tur: scmd ffff881e3dd21780 rtn 2002
Feb  9 16:45:10 10-180-0-37 kernel: [3820725.745046] scsi_eh_50: flush retry cmd: ffff881e3dd21780
Feb  9 16:45:10 10-180-0-37 kernel: [3820725.745054] scsi_eh_50: flush retry cmd: ffff881e57fee080
Feb  9 16:45:10 10-180-0-37 kernel: [3820725.745214] scsi_restart_operations: waking up host to restart
Feb  9 16:45:10 10-180-0-37 kernel: [3820725.745404] Error handler scsi_eh_50 sleeping
Feb  9 16:45:11 10-180-0-37 kernel: [3820727.007961]  session50: iscsi_eh_cmd_timed_out scsi cmd ffff881e57fee080 timedout
Feb  9 16:45:11 10-180-0-37 kernel: [3820727.007978]  session50: iscsi_eh_cmd_timed_out return timer reset
Feb  9 16:45:11 10-180-0-37 kernel: [3820727.007981]  session50: iscsi_eh_cmd_timed_out scsi cmd ffff881e3dd21780 timedout
Feb  9 16:45:11 10-180-0-37 kernel: [3820727.007984]  session50: iscsi_eh_cmd_timed_out return timer reset
.................
Feb  9 16:45:13 10-180-0-37 kernel: [3820729.006987]  session50: iscsi_eh_cmd_timed_out scsi cmd ffff881e57fee080 timedout
Feb  9 16:45:13 10-180-0-37 kernel: [3820729.007000]  session50: iscsi_eh_cmd_timed_out return nh
Feb  9 16:45:13 10-180-0-37 kernel: [3820729.007004]  session50: iscsi_eh_cmd_timed_out scsi cmd ffff881e3dd21780 timedout
Feb  9 16:45:13 10-180-0-37 kernel: [3820729.007006]  session50: iscsi_eh_cmd_timed_out return nh
Feb  9 16:45:13 10-180-0-37 kernel: [3820729.007010] Waking error handler thread
Feb  9 16:45:13 10-180-0-37 kernel: [3820729.007015] Error handler scsi_eh_50 waking up
Feb  9 16:45:13 10-180-0-37 kernel: [3820729.007194] sd 50:0:0:11: scsi_eh_prt_fail_stats: cmds failed: 0, cancel: 2
Feb  9 16:45:13 10-180-0-37 kernel: [3820729.007201] Total of 2 commands on 1 devices require eh work
Feb  9 16:45:13 10-180-0-37 kernel: [3820729.007203] scsi_eh_50: aborting cmd:0xffff881e57fee080
Feb  9 16:45:13 10-180-0-37 kernel: [3820729.007206]  session50: iscsi_eh_abort aborting sc ffff881e57fee080
Feb  9 16:45:13 10-180-0-37 kernel: [3820729.007208]  session50: iscsi_eh_abort aborting [sc ffff881e57fee080 itt 0x3a]
Feb  9 16:45:13 10-180-0-37 kernel: [3820729.007215]  session50: iscsi_exec_task_mgmt_fn tmf set timeout
Feb  9 16:45:13 10-180-0-37 kernel: [3820729.007264] iscsi_trgt: Abort Task (01) issued on tid:2000 lun:11 by sid:7881300190757376 (Function Complete)
Feb  9 16:45:13 10-180-0-37 kernel: [3820729.007304]  session50: iscsi_eh_abort abort success [sc ffff881e57fee080 itt 0x3a]
Feb  9 16:45:13 10-180-0-37 kernel: [3820729.007306] scsi_eh_50: aborting cmd:0xffff881e3dd21780
Feb  9 16:45:13 10-180-0-37 kernel: [3820729.007308]  session50: iscsi_eh_abort aborting sc ffff881e3dd21780
Feb  9 16:45:13 10-180-0-37 kernel: [3820729.007310]  session50: iscsi_eh_abort aborting [sc ffff881e3dd21780 itt 0x40]
Feb  9 16:45:13 10-180-0-37 kernel: [3820729.007317]  session50: iscsi_exec_task_mgmt_fn tmf set timeout
Feb  9 16:45:13 10-180-0-37 kernel: [3820729.007340] iscsi_trgt: Abort Task (01) issued on tid:2000 lun:11 by sid:7881300190757376 (Function Complete)
Feb  9 16:45:13 10-180-0-37 kernel: [3820729.007359]  session50: iscsi_eh_abort abort success [sc ffff881e3dd21780 itt 0x40]
Feb  9 16:45:13 10-180-0-37 kernel: [3820729.007428] scsi_eh_done scmd: ffff881e57fee080 result: 0
Feb  9 16:45:13 10-180-0-37 kernel: [3820729.007435] scsi_send_eh_cmnd: scmd: ffff881e57fee080, timeleft: 2500
Feb  9 16:45:13 10-180-0-37 kernel: [3820729.007437] scsi_send_eh_cmnd: scsi_eh_completed_normally 2002
Feb  9 16:45:13 10-180-0-37 kernel: [3820729.007440] scsi_eh_tur: scmd ffff881e57fee080 rtn 2002
Feb  9 16:45:13 10-180-0-37 kernel: [3820729.007442] scsi_eh_50: flush retry cmd: ffff881e57fee080
Feb  9 16:45:13 10-180-0-37 kernel: [3820729.007449] scsi_eh_50: flush retry cmd: ffff881e3dd21780
Feb  9 16:45:13 10-180-0-37 kernel: [3820729.007610] scsi_restart_operations: waking up host to restart
Feb  9 16:45:13 10-180-0-37 kernel: [3820729.007801] Error handler scsi_eh_50 sleeping
..............
Feb  9 16:45:15 10-180-0-37 kernel: [3820730.982019]  session50: iscsi_eh_cmd_timed_out scsi cmd ffff881e3dd21780 timedout
Feb  9 16:45:15 10-180-0-37 kernel: [3820730.982037]  session50: iscsi_eh_cmd_timed_out return timer reset
Feb  9 16:45:15 10-180-0-37 kernel: [3820730.982040]  session50: iscsi_eh_cmd_timed_out scsi cmd ffff881e57fee080 timedout
Feb  9 16:45:15 10-180-0-37 kernel: [3820730.982043]  session50: iscsi_eh_cmd_timed_out return timer reset
Feb  9 16:45:17 10-180-0-37 kernel: [3820732.981042]  session50: iscsi_eh_cmd_timed_out scsi cmd ffff881e3dd21780 timedout
Feb  9 16:45:17 10-180-0-37 kernel: [3820732.981055]  session50: iscsi_eh_cmd_timed_out return nh
Feb  9 16:45:17 10-180-0-37 kernel: [3820732.981060]  session50: iscsi_eh_cmd_timed_out scsi cmd ffff881e57fee080 timedout
Feb  9 16:45:17 10-180-0-37 kernel: [3820732.981062]  session50: iscsi_eh_cmd_timed_out return nh
Feb  9 16:45:17 10-180-0-37 kernel: [3820732.981066] Waking error handler thread
Feb  9 16:45:17 10-180-0-37 kernel: [3820732.981069] Error handler scsi_eh_50 waking up
Feb  9 16:45:17 10-180-0-37 kernel: [3820732.981246] sd 50:0:0:11: scsi_eh_prt_fail_stats: cmds failed: 0, cancel: 2
Feb  9 16:45:17 10-180-0-37 kernel: [3820732.981253] Total of 2 commands on 1 devices require eh work
Feb  9 16:45:17 10-180-0-37 kernel: [3820732.981255] scsi_eh_50: aborting cmd:0xffff881e3dd21780
Feb  9 16:45:17 10-180-0-37 kernel: [3820732.981258]  session50: iscsi_eh_abort aborting sc ffff881e3dd21780
Feb  9 16:45:17 10-180-0-37 kernel: [3820732.981260]  session50: iscsi_eh_abort aborting [sc ffff881e3dd21780 itt 0x3e]
Feb  9 16:45:17 10-180-0-37 kernel: [3820732.981267]  session50: iscsi_exec_task_mgmt_fn tmf set timeout
Feb  9 16:45:17 10-180-0-37 kernel: [3820732.981322] iscsi_trgt: Abort Task (01) issued on tid:2000 lun:11 by sid:7881300190757376 (Function Complete)
Feb  9 16:45:17 10-180-0-37 kernel: [3820732.981365]  session50: iscsi_eh_abort abort success [sc ffff881e3dd21780 itt 0x3e]
Feb  9 16:45:17 10-180-0-37 kernel: [3820732.981368] scsi_eh_50: aborting cmd:0xffff881e57fee080
Feb  9 16:45:17 10-180-0-37 kernel: [3820732.981370]  session50: iscsi_eh_abort aborting sc ffff881e57fee080
Feb  9 16:45:17 10-180-0-37 kernel: [3820732.981373]  session50: iscsi_eh_abort aborting [sc ffff881e57fee080 itt 0x3b]
Feb  9 16:45:17 10-180-0-37 kernel: [3820732.981393]  session50: iscsi_exec_task_mgmt_fn tmf set timeout
Feb  9 16:45:17 10-180-0-37 kernel: [3820732.981420] iscsi_trgt: Abort Task (01) issued on tid:2000 lun:11 by sid:7881300190757376 (Function Complete)
Feb  9 16:45:17 10-180-0-37 kernel: [3820732.981439]  session50: iscsi_eh_abort abort success [sc ffff881e57fee080 itt 0x3b]
Feb  9 16:45:17 10-180-0-37 kernel: [3820732.981510] scsi_eh_done scmd: ffff881e3dd21780 result: 0
Feb  9 16:45:17 10-180-0-37 kernel: [3820732.981520] scsi_send_eh_cmnd: scmd: ffff881e3dd21780, timeleft: 2500
Feb  9 16:45:17 10-180-0-37 kernel: [3820732.981523] scsi_send_eh_cmnd: scsi_eh_completed_normally 2002
Feb  9 16:45:17 10-180-0-37 kernel: [3820732.981526] scsi_eh_tur: scmd ffff881e3dd21780 rtn 2002
Feb  9 16:45:17 10-180-0-37 kernel: [3820732.981529] scsi_eh_50: flush retry cmd: ffff881e3dd21780
Feb  9 16:45:17 10-180-0-37 kernel: [3820732.981537] scsi_eh_50: flush retry cmd: ffff881e57fee080
Feb  9 16:45:17 10-180-0-37 kernel: [3820732.981702] scsi_restart_operations: waking up host to restart
Feb  9 16:45:17 10-180-0-37 kernel: [3820732.981894] Error handler scsi_eh_50 sleeping
...............
Feb  9 16:45:19 10-180-0-37 kernel: [3820734.836136]  session50: iscsi_eh_cmd_timed_out scsi cmd ffff881e57fee080 timedout
Feb  9 16:45:19 10-180-0-37 kernel: [3820734.836155]  session50: iscsi_eh_cmd_timed_out return timer reset
Feb  9 16:45:19 10-180-0-37 kernel: [3820734.836158]  session50: iscsi_eh_cmd_timed_out scsi cmd ffff881e3dd21780 timedout
Feb  9 16:45:19 10-180-0-37 kernel: [3820734.836160]  session50: iscsi_eh_cmd_timed_out return timer reset
................
Feb  9 16:45:21 10-180-0-37 kernel: [3820736.835160]  session50: iscsi_eh_cmd_timed_out scsi cmd ffff881e57fee080 timedout
Feb  9 16:45:21 10-180-0-37 kernel: [3820736.835174]  session50: iscsi_eh_cmd_timed_out return nh
Feb  9 16:45:21 10-180-0-37 kernel: [3820736.835178]  session50: iscsi_eh_cmd_timed_out scsi cmd ffff881e3dd21780 timedout
Feb  9 16:45:21 10-180-0-37 kernel: [3820736.835180]  session50: iscsi_eh_cmd_timed_out return nh
Feb  9 16:45:21 10-180-0-37 kernel: [3820736.835184] Waking error handler thread
Feb  9 16:45:21 10-180-0-37 kernel: [3820736.835188] Error handler scsi_eh_50 waking up
Feb  9 16:45:21 10-180-0-37 kernel: [3820736.835374] sd 50:0:0:11: scsi_eh_prt_fail_stats: cmds failed: 0, cancel: 2
Feb  9 16:45:21 10-180-0-37 kernel: [3820736.835381] Total of 2 commands on 1 devices require eh work
Feb  9 16:45:21 10-180-0-37 kernel: [3820736.835383] scsi_eh_50: aborting cmd:0xffff881e57fee080
Feb  9 16:45:21 10-180-0-37 kernel: [3820736.835386]  session50: iscsi_eh_abort aborting sc ffff881e57fee080
Feb  9 16:45:21 10-180-0-37 kernel: [3820736.835388]  session50: iscsi_eh_abort aborting [sc ffff881e57fee080 itt 0x47]
Feb  9 16:45:21 10-180-0-37 kernel: [3820736.835394]  session50: iscsi_exec_task_mgmt_fn tmf set timeout
Feb  9 16:45:21 10-180-0-37 kernel: [3820736.835438] iscsi_trgt: Abort Task (01) issued on tid:2000 lun:11 by sid:7881300190757376 (Function Complete)
Feb  9 16:45:21 10-180-0-37 kernel: [3820736.835474]  session50: iscsi_eh_abort abort success [sc ffff881e57fee080 itt 0x47]
Feb  9 16:45:21 10-180-0-37 kernel: [3820736.835476] scsi_eh_50: aborting cmd:0xffff881e3dd21780
Feb  9 16:45:21 10-180-0-37 kernel: [3820736.835478]  session50: iscsi_eh_abort aborting sc ffff881e3dd21780
Feb  9 16:45:21 10-180-0-37 kernel: [3820736.835480]  session50: iscsi_eh_abort aborting [sc ffff881e3dd21780 itt 0x48]
Feb  9 16:45:21 10-180-0-37 kernel: [3820736.835484]  session50: iscsi_exec_task_mgmt_fn tmf set timeout
Feb  9 16:45:21 10-180-0-37 kernel: [3820736.835501] iscsi_trgt: Abort Task (01) issued on tid:2000 lun:11 by sid:7881300190757376 (Function Complete)
Feb  9 16:45:21 10-180-0-37 kernel: [3820736.835520]  session50: iscsi_eh_abort abort success [sc ffff881e3dd21780 itt 0x48]
.............从这里开始就是等了差不多10s，然后执行了下面的逻辑
Feb  9 16:45:31 10-180-0-37 kernel: [3820746.830267] scsi_send_eh_cmnd: scmd: ffff881e57fee080, timeleft: 0
Feb  9 16:45:31 10-180-0-37 kernel: [3820746.830274]  session50: iscsi_eh_abort aborting sc ffff881e57fee080
Feb  9 16:45:31 10-180-0-37 kernel: [3820746.830277]  session50: iscsi_eh_abort aborting [sc ffff881e57fee080 itt 0x42]
Feb  9 16:45:31 10-180-0-37 kernel: [3820746.830283]  session50: iscsi_exec_task_mgmt_fn tmf set timeout
Feb  9 16:45:31 10-180-0-37 kernel: [3820746.830325] iscsi_trgt: Abort Task (01) issued on tid:2000 lun:11 by sid:7881300190757376 (Function Complete)
Feb  9 16:45:31 10-180-0-37 kernel: [3820746.830364] scsi_eh_done scmd: ffff881e57fee080 result: 50000
Feb  9 16:45:31 10-180-0-37 kernel: [3820746.830367]  session50: iscsi_eh_abort abort success [sc ffff881e57fee080 itt 0x42]
Feb  9 16:45:31 10-180-0-37 kernel: [3820746.830371] scsi_eh_tur: scmd ffff881e57fee080 rtn 2003
Feb  9 16:45:31 10-180-0-37 kernel: [3820746.830696] scsi_eh_50: Sending BDR sdev: 0xffff88329ad78800
Feb  9 16:45:31 10-180-0-37 kernel: [3820746.830698]  session50: iscsi_eh_device_reset LU Reset [sc ffff881e57fee080 lun 11]
Feb  9 16:45:31 10-180-0-37 kernel: [3820746.830702]  session50: iscsi_exec_task_mgmt_fn tmf set timeout
Feb  9 16:45:31 10-180-0-37 kernel: [3820746.830728] iscsi_trgt: Logical Unit Reset (05) issued on tid:2000 lun:11 by sid:7881300190757376 (Function Complete)
Feb  9 16:45:31 10-180-0-37 kernel: [3820746.830754]  session50: iscsi_eh_device_reset dev reset result = SUCCESS
..........又等10s
Feb  9 16:45:41 10-180-0-37 kernel: [3820756.825380] scsi_send_eh_cmnd: scmd: ffff881e57fee080, timeleft: 0
Feb  9 16:45:41 10-180-0-37 kernel: [3820756.825387]  session50: iscsi_eh_abort aborting sc ffff881e57fee080
Feb  9 16:45:41 10-180-0-37 kernel: [3820756.825390]  session50: iscsi_eh_abort aborting [sc ffff881e57fee080 itt 0x4e]
Feb  9 16:45:41 10-180-0-37 kernel: [3820756.825397]  session50: iscsi_exec_task_mgmt_fn tmf set timeout
Feb  9 16:45:41 10-180-0-37 kernel: [3820756.825441] iscsi_trgt: Abort Task (01) issued on tid:2000 lun:11 by sid:7881300190757376 (Function Complete)
Feb  9 16:45:41 10-180-0-37 kernel: [3820756.825475] scsi_eh_done scmd: ffff881e57fee080 result: 50000
Feb  9 16:45:41 10-180-0-37 kernel: [3820756.825479]  session50: iscsi_eh_abort abort success [sc ffff881e57fee080 itt 0x4e]
Feb  9 16:45:41 10-180-0-37 kernel: [3820756.825482] scsi_eh_tur: scmd ffff881e57fee080 rtn 2003
Feb  9 16:45:41 10-180-0-37 kernel: [3820756.825497] scsi_eh_50: Sending target reset to target 0
Feb  9 16:45:41 10-180-0-37 kernel: [3820756.825500]  session50: iscsi_eh_target_reset tgt Reset [sc ffff881e57fee080 tgt iqn.com.netease:ebsdisk01.8.0.0]
Feb  9 16:45:41 10-180-0-37 kernel: [3820756.825504]  session50: iscsi_exec_task_mgmt_fn tmf set timeout
Feb  9 16:45:41 10-180-0-37 kernel: [3820756.825534] iscsi_trgt: Target Warm Reset (06) issued on tid:2000 lun:0 by sid:7881300190757376 (Function Complete)
Feb  9 16:45:41 10-180-0-37 kernel: [3820756.825561]  session50: iscsi_eh_target_reset tgt iqn.com.netease:ebsdisk01.8.0.0 reset result = SUCCESS
.............再等10s，然后从下面的日志来看是Device offlined后再出现I/O error，而不是先出现I/O error再Device offlined，这里比较奇怪
Feb  9 16:45:51 10-180-0-37 kernel: [3820766.820489] scsi_send_eh_cmnd: scmd: ffff881e57fee080, timeleft: 0
Feb  9 16:45:51 10-180-0-37 kernel: [3820766.820495]  session50: iscsi_eh_abort aborting sc ffff881e57fee080
Feb  9 16:45:51 10-180-0-37 kernel: [3820766.820498]  session50: iscsi_eh_abort aborting [sc ffff881e57fee080 itt 0x55]
Feb  9 16:45:51 10-180-0-37 kernel: [3820766.820504]  session50: iscsi_exec_task_mgmt_fn tmf set timeout
Feb  9 16:45:51 10-180-0-37 kernel: [3820766.820546] iscsi_trgt: Abort Task (01) issued on tid:2000 lun:11 by sid:7881300190757376 (Function Complete)
Feb  9 16:45:51 10-180-0-37 kernel: [3820766.820584] scsi_eh_done scmd: ffff881e57fee080 result: 50000
Feb  9 16:45:51 10-180-0-37 kernel: [3820766.820587]  session50: iscsi_eh_abort abort success [sc ffff881e57fee080 itt 0x55]
Feb  9 16:45:51 10-180-0-37 kernel: [3820766.820590] scsi_eh_tur: scmd ffff881e57fee080 rtn 2003
Feb  9 16:45:51 10-180-0-37 kernel: [3820766.820593] scsi_eh_50: Sending BRST chan: 0
Feb  9 16:45:51 10-180-0-37 kernel: [3820766.820594] scsi_try_bus_reset: Snd Bus RST
Feb  9 16:45:51 10-180-0-37 kernel: [3820766.820596] scsi_eh_50: BRST failed chan: 0
Feb  9 16:45:51 10-180-0-37 kernel: [3820766.820597] scsi_eh_50: Sending HRST
Feb  9 16:45:51 10-180-0-37 kernel: [3820766.820599] scsi_try_host_reset: Snd Host RST
Feb  9 16:45:51 10-180-0-37 kernel: [3820766.820600] scsi_eh_50: HRST failed
Feb  9 16:45:51 10-180-0-37 kernel: [3820766.820603] sd 50:0:0:11: Device offlined - not ready after error recovery
Feb  9 16:45:51 10-180-0-37 kernel: [3820766.820606] sd 50:0:0:11: Device offlined - not ready after error recovery
Feb  9 16:45:51 10-180-0-37 kernel: [3820766.820607] scsi_eh_50: flush finish cmd: ffff881e57fee080
Feb  9 16:45:51 10-180-0-37 kernel: [3820766.820617] sd 50:0:0:11: [sdat] Unhandled error code
Feb  9 16:45:51 10-180-0-37 kernel: [3820766.820619] sd 50:0:0:11: [sdat]
Feb  9 16:45:51 10-180-0-37 kernel: [3820766.820621] Result: hostbyte=DID_ABORT driverbyte=DRIVER_OK
Feb  9 16:45:51 10-180-0-37 kernel: [3820766.820623] sd 50:0:0:11: [sdat] CDB:
Feb  9 16:45:51 10-180-0-37 kernel: [3820766.820625] Write(10): 2a 00 00 85 31 80 00 00 10 00
Feb  9 16:45:51 10-180-0-37 kernel: [3820766.820633] end_request: I/O error, dev sdat, sector 8728960
Feb  9 16:45:51 10-180-0-37 kernel: [3820766.827377] md/raid1:md388713: Disk failure on sdat, disabling device.
Feb  9 16:45:51 10-180-0-37 kernel: [3820766.827377] md/raid1:md388713: Operation continuing on 1 devices.
Feb  9 16:45:51 10-180-0-37 kernel: [3820766.827381] scsi_eh_50: flush finish cmd: ffff881e3dd21780
Feb  9 16:45:51 10-180-0-37 kernel: [3820766.827386] sd 50:0:0:11: [sdat] Unhandled error code
Feb  9 16:45:51 10-180-0-37 kernel: [3820766.827387] sd 50:0:0:11: [sdat]
Feb  9 16:45:51 10-180-0-37 kernel: [3820766.827388] Result: hostbyte=DID_ABORT driverbyte=DRIVER_OK
Feb  9 16:45:51 10-180-0-37 kernel: [3820766.827389] sd 50:0:0:11: [sdat] CDB:
Feb  9 16:45:51 10-180-0-37 kernel: [3820766.827393] Write(10): 2a 00 00 0f 42 80 00 00 80 00
Feb  9 16:45:51 10-180-0-37 kernel: [3820766.827394] end_request: I/O error, dev sdat, sector 1000064
Feb  9 16:45:51 10-180-0-37 kernel: [3820766.827570] scsi_restart_operations: waking up host to restart
Feb  9 16:45:51 10-180-0-37 kernel: [3820766.827760] Error handler scsi_eh_50 sleeping
Feb  9 16:45:51 10-180-0-37 kernel: [3820766.848214] RAID1 conf printout:
Feb  9 16:45:51 10-180-0-37 kernel: [3820766.848217]  --- wd:1 rd:2
Feb  9 16:45:51 10-180-0-37 kernel: [3820766.848220]  disk 0, wo:0, o:1, dev:sdv
Feb  9 16:45:51 10-180-0-37 kernel: [3820766.848221]  disk 1, wo:1, o:0, dev:sdat
Feb  9 16:45:51 10-180-0-37 kernel: [3820766.881950] RAID1 conf printout:
Feb  9 16:45:51 10-180-0-37 kernel: [3820766.881953]  --- wd:1 rd:2
Feb  9 16:45:51 10-180-0-37 kernel: [3820766.881956]  disk 0, wo:0, o:1, dev:sdv

另外从scsi cmd的日志信息来看，超时重试处理的有2个请求（一个是lba=1000064 txlen=128的，另外一个是lba=912384 txlen=128的请求），并且从重试次数上来看，并没有完全走完5次重试，从上面的日志来看应该是device offlined后就没有继续重试了。

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
        <...>-68191 [024] .... 3820716.789544: scsi_dispatch_cmd_start: host_no=50 channel=0 id=0 lun=11 data_sgl=16 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(WRITE_10 lba=912384 txlen=128 protect=0 raw=2a 00 00 0d ec 00 00 00 80 00)
        <...>-68375 [020] .... 3820716.814538: scsi_dispatch_cmd_start: host_no=50 channel=0 id=0 lun=11 data_sgl=16 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(WRITE_10 lba=1000064 txlen=128 protect=0 raw=2a 00 00 0f 42 80 00 00 80 00)
       <idle>-0     [012] d.s. 3820717.924396: scsi_dispatch_cmd_timeout: host_no=50 channel=0 id=0 lun=11 data_sgl=16 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(WRITE_10 protect=0 raw=2a 00 00 0f 42 80 00 00 80 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD)
       <idle>-0     [012] dNs. 3820719.927417: scsi_dispatch_cmd_timeout: host_no=50 channel=0 id=0 lun=11 data_sgl=16 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(WRITE_10 lba=1000064 txlen=128 protect=0 raw=2a 00 00 0f 42 80 00 00 80 00) result=(driver=DRIVER_OK host=DID_TIME_OUT message=COMMAND_COMPLETE status=SAM_STAT_GOOD)
kworker/27:1H-799   [027] .... 3820719.931530: scsi_dispatch_cmd_start: host_no=50 channel=0 id=0 lun=11 data_sgl=16 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(WRITE_10 lba=1000064 txlen=128 protect=0 raw=2a 00 00 0f 42 80 00 00 80 00)
       <idle>-0     [027] dNs. 3820721.746530: scsi_dispatch_cmd_timeout: host_no=50 channel=0 id=0 lun=11 data_sgl=16 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(WRITE_10 lba=1000064 txlen=128 protect=0 raw=2a 00 00 0f 42 80 00 00 80 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD)
        <...>-68191 [024] .... 3820721.896068: scsi_dispatch_cmd_start: host_no=50 channel=0 id=0 lun=11 data_sgl=2 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(WRITE_10 lba=8728960 txlen=16 protect=0 raw=2a 00 00 85 31 80 00 00 10 00)
       <idle>-0     [027] dNs. 3820723.745553: scsi_dispatch_cmd_timeout: host_no=50 channel=0 id=0 lun=11 data_sgl=16 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(WRITE_10 lba=1000064 txlen=128 protect=0 raw=2a 00 00 0f 42 80 00 00 80 00) result=(driver=DRIVER_OK host=DID_TIME_OUT message=COMMAND_COMPLETE status=SAM_STAT_GOOD)
       <idle>-0     [027] dNs. 3820723.745577: scsi_dispatch_cmd_timeout: host_no=50 channel=0 id=0 lun=11 data_sgl=2 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(WRITE_10 lba=8728960 txlen=16 protect=0 raw=2a 00 00 85 31 80 00 00 10 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD)
       <idle>-0     [027] dNs. 3820725.744576: scsi_dispatch_cmd_timeout: host_no=50 channel=0 id=0 lun=11 data_sgl=2 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(WRITE_10 lba=8728960 txlen=16 protect=0 raw=2a 00 00 85 31 80 00 00 10 00) result=(driver=DRIVER_OK host=DID_TIME_OUT message=COMMAND_COMPLETE status=SAM_STAT_GOOD)
 kworker/5:1H-801   [005] .... 3820725.748667: scsi_dispatch_cmd_start: host_no=50 channel=0 id=0 lun=11 data_sgl=2 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(WRITE_10 lba=8728960 txlen=16 protect=0 raw=2a 00 00 85 31 80 00 00 10 00)
 kworker/5:1H-801   [005] .... 3820725.748672: scsi_dispatch_cmd_start: host_no=50 channel=0 id=0 lun=11 data_sgl=16 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(WRITE_10 lba=1000064 txlen=128 protect=0 raw=2a 00 00 0f 42 80 00 00 80 00)
       <idle>-0     [005] dNs. 3820727.007955: scsi_dispatch_cmd_timeout: host_no=50 channel=0 id=0 lun=11 data_sgl=2 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(WRITE_10 lba=8728960 txlen=16 protect=0 raw=2a 00 00 85 31 80 00 00 10 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD)
       <idle>-0     [005] dNs. 3820727.007980: scsi_dispatch_cmd_timeout: host_no=50 channel=0 id=0 lun=11 data_sgl=16 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(WRITE_10 lba=1000064 txlen=128 protect=0 raw=2a 00 00 0f 42 80 00 00 80 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD)
       <idle>-0     [005] dNs. 3820729.006980: scsi_dispatch_cmd_timeout: host_no=50 channel=0 id=0 lun=11 data_sgl=2 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(WRITE_10 lba=8728960 txlen=16 protect=0 raw=2a 00 00 85 31 80 00 00 10 00) result=(driver=DRIVER_OK host=DID_TIME_OUT message=COMMAND_COMPLETE status=SAM_STAT_GOOD)
       <idle>-0     [005] dNs. 3820729.007003: scsi_dispatch_cmd_timeout: host_no=50 channel=0 id=0 lun=11 data_sgl=16 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(WRITE_10 lba=1000064 txlen=128 protect=0 raw=2a 00 00 0f 42 80 00 00 80 00) result=(driver=DRIVER_OK host=DID_TIME_OUT message=COMMAND_COMPLETE status=SAM_STAT_GOOD)
 kworker/7:1H-1265  [007] .... 3820729.011093: scsi_dispatch_cmd_start: host_no=50 channel=0 id=0 lun=11 data_sgl=16 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(WRITE_10 lba=1000064 txlen=128 protect=0 raw=2a 00 00 0f 42 80 00 00 80 00)
 kworker/7:1H-1265  [007] .... 3820729.011097: scsi_dispatch_cmd_start: host_no=50 channel=0 id=0 lun=11 data_sgl=2 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(WRITE_10 lba=8728960 txlen=16 protect=0 raw=2a 00 00 85 31 80 00 00 10 00)
        <...>-72525 [007] d.s. 3820730.982012: scsi_dispatch_cmd_timeout: host_no=50 channel=0 id=0 lun=11 data_sgl=16 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(WRITE_10 lba=1000064 txlen=128 protect=0 raw=2a 00 00 0f 42 80 00 00 80 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD)
        <...>-72525 [007] d.s. 3820730.982039: scsi_dispatch_cmd_timeout: host_no=50 channel=0 id=0 lun=11 data_sgl=2 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(WRITE_10 lba=8728960 txlen=16 protect=0 raw=2a 00 00 85 31 80 00 00 10 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD)
        <...>-108306 [007] d.s. 3820732.981033: scsi_dispatch_cmd_timeout: host_no=50 channel=0 id=0 lun=11 data_sgl=16 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(WRITE_10 lba=1000064 txlen=128 protect=0 raw=2a 00 00 0f 42 80 00 00 80 00) result=(driver=DRIVER_OK host=DID_TIME_OUT message=COMMAND_COMPLETE status=SAM_STAT_GOOD)
        <...>-108306 [007] d.s. 3820732.981059: scsi_dispatch_cmd_timeout: host_no=50 channel=0 id=0 lun=11 data_sgl=2 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(WRITE_10 lba=8728960 txlen=16 protect=0 raw=2a 00 00 85 31 80 00 00 10 00) result=(driver=DRIVER_OK host=DID_TIME_OUT message=COMMAND_COMPLETE status=SAM_STAT_GOOD)
kworker/19:1H-2058  [019] .... 3820732.985038: scsi_dispatch_cmd_start: host_no=50 channel=0 id=0 lun=11 data_sgl=2 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(WRITE_10 lba=8728960 txlen=16 protect=0 raw=2a 00 00 85 31 80 00 00 10 00)
kworker/19:1H-2058  [019] .... 3820732.985044: scsi_dispatch_cmd_start: host_no=50 channel=0 id=0 lun=11 data_sgl=16 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(WRITE_10 lba=1000064 txlen=128 protect=0 raw=2a 00 00 0f 42 80 00 00 80 00)
       <idle>-0     [019] dNs. 3820734.836127: scsi_dispatch_cmd_timeout: host_no=50 channel=0 id=0 lun=11 data_sgl=2 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(WRITE_10 lba=8728960 txlen=16 protect=0 raw=2a 00 00 85 31 80 00 00 10 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD)
       <idle>-0     [019] dNs. 3820734.836157: scsi_dispatch_cmd_timeout: host_no=50 channel=0 id=0 lun=11 data_sgl=16 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(WRITE_10 lba=1000064 txlen=128 protect=0 raw=2a 00 00 0f 42 80 00 00 80 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD)
       <idle>-0     [019] dNs. 3820736.835151: scsi_dispatch_cmd_timeout: host_no=50 channel=0 id=0 lun=11 data_sgl=2 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(WRITE_10 lba=8728960 txlen=16 protect=0 raw=2a 00 00 85 31 80 00 00 10 00) result=(driver=DRIVER_OK host=DID_TIME_OUT message=COMMAND_COMPLETE status=SAM_STAT_GOOD)
       <idle>-0     [019] dNs. 3820736.835177: scsi_dispatch_cmd_timeout: host_no=50 channel=0 id=0 lun=11 data_sgl=16 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(WRITE_10 lba=1000064 txlen=128 protect=0 raw=2a 00 00 0f 42 80 00 00 80 00) result=(driver=DRIVER_OK host=DID_TIME_OUT message=COMMAND_COMPLETE status=SAM_STAT_GOOD)

多3次10s的分析

既然日志分析来看没有完成标准的5次超时重试，那说明在中间某个阶段进入到其他流程导致多了3次10s的超时。为了分析这个过程中到底发生了什么，就只能通过阅读linux内核里scsi error handle这部分代码，根据日志信息来进行分析，并且对比裸盘fio测试过程中的日志信息发现：从文件系统fio测试时IO hang过程中的日志里，某一次iscsi abort success后就等了10s，而裸盘测试时是iscsi abort success后紧跟着scsi_eh_done函数的调用，说明问题有可能出在这里。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
**从文件系统fio测试时的日志**
Feb  9 16:45:21 10-180-0-37 kernel: [3820736.835478]  session50: iscsi_eh_abort aborting sc ffff881e3dd21780
Feb  9 16:45:21 10-180-0-37 kernel: [3820736.835480]  session50: iscsi_eh_abort aborting [sc ffff881e3dd21780 itt 0x48]
Feb  9 16:45:21 10-180-0-37 kernel: [3820736.835484]  session50: iscsi_exec_task_mgmt_fn tmf set timeout
Feb  9 16:45:21 10-180-0-37 kernel: [3820736.835501] iscsi_trgt: Abort Task (01) issued on tid:2000 lun:11 by sid:7881300190757376 (Function Complete)
Feb  9 16:45:21 10-180-0-37 kernel: [3820736.835520]  session50: iscsi_eh_abort abort success [sc ffff881e3dd21780 itt 0x48]
.............从这里开始就是等了差不多10s
Feb  9 16:45:31 10-180-0-37 kernel: [3820746.830267] scsi_send_eh_cmnd: scmd: ffff881e57fee080, timeleft: 0
Feb  9 16:45:31 10-180-0-37 kernel: [3820746.830274]  session50: iscsi_eh_abort aborting sc ffff881e57fee080
Feb  9 16:45:31 10-180-0-37 kernel: [3820746.830277]  session50: iscsi_eh_abort aborting [sc ffff881e57fee080 itt 0x42]
Feb  9 16:45:31 10-180-0-37 kernel: [3820746.830283]  session50: iscsi_exec_task_mgmt_fn tmf set timeout

**裸盘fio测试时的日志**
Feb 10 09:49:33 10-180-0-37 kernel: [3882158.817537]  session52: iscsi_eh_abort aborting sc ffff884d6f25c180
Feb 10 09:49:33 10-180-0-37 kernel: [3882158.817539]  session52: iscsi_eh_abort aborting [sc ffff884d6f25c180 itt 0x23]
Feb 10 09:49:33 10-180-0-37 kernel: [3882158.817544]  session52: iscsi_exec_task_mgmt_fn tmf set timeout
Feb 10 09:49:33 10-180-0-37 kernel: [3882158.817584] iscsi_trgt: Abort Task (01) issued on tid:2000 lun:11 by sid:9007200131154432 (Function Complete)
Feb 10 09:49:33 10-180-0-37 kernel: [3882158.817616]  session52: iscsi_eh_abort abort success [sc ffff884d6f25c180 itt 0x23]
..........这里是紧接着调用了scsi_eh_done函数
Feb 10 09:49:33 10-180-0-37 kernel: [3882158.817669] scsi_eh_done scmd: ffff884d6f25c180 result: 0
Feb 10 09:49:33 10-180-0-37 kernel: [3882158.817674] scsi_send_eh_cmnd: scmd: ffff884d6f25c180, timeleft: 2500
Feb 10 09:49:33 10-180-0-37 kernel: [3882158.817676] scsi_send_eh_cmnd: scsi_eh_completed_normally 2002
Feb 10 09:49:33 10-180-0-37 kernel: [3882158.817679] scsi_eh_tur: scmd ffff884d6f25c180 rtn 2002
Feb 10 09:49:33 10-180-0-37 kernel: [3882158.817681] scsi_eh_52: flush finish cmd: ffff884d6f25c180

并且找到这10s等待前后的日志，发现打印了一句”scsi_send_eh_cmnd: scmd: ffff881e57fee080, timeleft: 0”，找到代码里的这个函数scsi_send_eh_cmnd，确实发现有个timeout的地方：不过一处是queuecommand失败后每次sleep一点时间然后重试，另外一处是queuecommand成功后wait_for_completion_timeout等待cmd完成。并且传入scsi_send_eh_cmnd的参数里的timeout就是SENSE_TIMEOUT（刚好是10*HZ）。后来确认当前使用的内核版本3.10.45里这个值是写死的，而高一点的内核（如3.14.57）这个值就是可配置的参数eh_timeout。

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
static int scsi_send_eh_cmnd(struct scsi_cmnd *scmd, unsigned char *cmnd,
			     int cmnd_size, int timeout, unsigned sense_bytes)
{
	struct scsi_device *sdev = scmd->device;
	struct Scsi_Host *shost = sdev->host;
	DECLARE_COMPLETION_ONSTACK(done);
	unsigned long timeleft = timeout;
	struct scsi_eh_save ses;
	const unsigned long stall_for = msecs_to_jiffies(100);
	int rtn;

retry:
	scsi_eh_prep_cmnd(scmd, &ses, cmnd, cmnd_size, sense_bytes);
	shost->eh_action = &done;

	scsi_log_send(scmd);
	scmd->scsi_done = scsi_eh_done;
	rtn = shost->hostt->queuecommand(shost, scmd);
	if (rtn) {
		if (timeleft > stall_for) {
			scsi_eh_restore_cmnd(scmd, &ses);
			timeleft -= stall_for;
			msleep(jiffies_to_msecs(stall_for));
			goto retry;
		}
		/* signal not to enter either branch of the if () below */
		timeleft = 0;
		rtn = NEEDS_RETRY;
	} else {
		timeleft = wait_for_completion_timeout(&done, timeout);
	}

	shost->eh_action = NULL;

	scsi_log_completion(scmd, rtn);
    // 这里打印的日志
	SCSI_LOG_ERROR_RECOVERY(3,
		printk("%s: scmd: %p, timeleft: %ld\n",
			__func__, scmd, timeleft));
	..........

有了这个线索，就需要重现出来确认，但是因为是内核代码，不可能直接去打印日志重编译内核，因此祭出神器systemtap，在关键函数调用地方打印信息。下面是重现测试过程中systemtap打印的相关日志，可以看到确实是在wait_for_completion_timeout这里等了10s。同样的在裸盘fio测试过程中systemtap抓取就发现wait_for_completion_timeout没有等。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
Fri Feb 10 09:12:55 2017, iscsi_queuecommand call: host_no=56, channel=0, lun=11, dev_id=0, scmd:0xffff880ec9618380
Fri Feb 10 09:12:55 2017, iscsi_queuecommand return: host_no=56, channel=0, lun=11, dev_id=0, scmd:0xffff880ec9618380, return=0
Fri Feb 10 09:12:55 2017, iscsi_queuecommand call: host_no=56, channel=0, lun=11, dev_id=0, scmd:0xffff8821a2794080
Fri Feb 10 09:12:55 2017, iscsi_queuecommand return: host_no=56, channel=0, lun=11, dev_id=0, scmd:0xffff8821a2794080, return=0
Fri Feb 10 09:12:59 2017, scsi_send_eh_cmnd enter: host_no=56, channel=0, lun=11, dev_id=0, scmd:0xffff880ec9618380, sense_timeout:2500
Fri Feb 10 09:12:59 2017, iscsi_queuecommand call: host_no=56, channel=0, lun=11, dev_id=0, scmd:0xffff880ec9618380
Fri Feb 10 09:12:59 2017, iscsi_queuecommand return: host_no=56, channel=0, lun=11, dev_id=0, scmd:0xffff880ec9618380, return=0
Fri Feb 10 09:12:59 2017, wait_for_completion_timeout
Fri Feb 10 09:13:09 2017, scsi_send_eh_cmnd return: host_no=56, channel=0, lun=11, dev_id=0, scmd:0xffff880ec9618380, sense_timeout:2500

Fri Feb 10 09:13:09 2017, scsi_send_eh_cmnd enter: host_no=56, channel=0, lun=11, dev_id=0, scmd:0xffff880ec9618380, sense_timeout:2500
Fri Feb 10 09:13:09 2017, iscsi_queuecommand call: host_no=56, channel=0, lun=11, dev_id=0, scmd:0xffff880ec9618380
Fri Feb 10 09:13:09 2017, iscsi_queuecommand return: host_no=56, channel=0, lun=11, dev_id=0, scmd:0xffff880ec9618380, return=0
Fri Feb 10 09:13:09 2017, wait_for_completion_timeout
Fri Feb 10 09:13:19 2017, scsi_send_eh_cmnd return: host_no=56, channel=0, lun=11, dev_id=0, scmd:0xffff880ec9618380, sense_timeout:2500

Fri Feb 10 09:13:19 2017, scsi_send_eh_cmnd enter: host_no=56, channel=0, lun=11, dev_id=0, scmd:0xffff880ec9618380, sense_timeout:2500
Fri Feb 10 09:13:19 2017, iscsi_queuecommand call: host_no=56, channel=0, lun=11, dev_id=0, scmd:0xffff880ec9618380
Fri Feb 10 09:13:19 2017, iscsi_queuecommand return: host_no=56, channel=0, lun=11, dev_id=0, scmd:0xffff880ec9618380, return=0
Fri Feb 10 09:13:19 2017, wait_for_completion_timeout
Fri Feb 10 09:13:29 2017, scsi_send_eh_cmnd return: host_no=56, channel=0, lun=11, dev_id=0, scmd:0xffff880ec9618380, sense_timeout:2500

结合内核代码分析，在scsi_eh_abort_cmds–>scsi_eh_test_devices–>scsi_eh_tur–>scsi_send_eh_cmnd的调用路径下，当scsi_send_eh_cmnd超时返回FAILED，从而进入到scsi_eh_ready_devs的处理流程。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
static void scsi_unjam_host(struct Scsi_Host *shost)
{
	unsigned long flags;
	LIST_HEAD(eh_work_q);
	LIST_HEAD(eh_done_q);

	spin_lock_irqsave(shost->host_lock, flags);
	list_splice_init(&shost->eh_cmd_q, &eh_work_q);
	spin_unlock_irqrestore(shost->host_lock, flags);

	SCSI_LOG_ERROR_RECOVERY(1, scsi_eh_prt_fail_stats(shost, &eh_work_q));

	if (!scsi_eh_get_sense(&eh_work_q, &eh_done_q))
		if (!scsi_eh_abort_cmds(&eh_work_q, &eh_done_q))
			scsi_eh_ready_devs(shost, &eh_work_q, &eh_done_q);

	scsi_eh_flush_done_q(&eh_done_q);
}

在scsi_eh_ready_devs里，就会相继调用scsi_eh_bus_device_reset，scsi_eh_target_reset，scsi_eh_bus_reset等，就在scsi_eh_bus_device_reset和scsi_eh_target_reset里最终都会调用到scsi_eh_tur–>scsi_send_eh_cmnd的逻辑，并且各自又等待了10s，并且最后走到了scsi_eh_offline_sdevs将设备离线，从而总的导致了3次10s的超时，与上面的日志吻合。

1
2
3
4
5
6
7
8
9
10
11
12
void scsi_eh_ready_devs(struct Scsi_Host *shost,
			struct list_head *work_q,
			struct list_head *done_q)
{
	if (!scsi_eh_stu(shost, work_q, done_q))
		if (!scsi_eh_bus_device_reset(shost, work_q, done_q))
			if (!scsi_eh_target_reset(shost, work_q, done_q))
				if (!scsi_eh_bus_reset(shost, work_q, done_q))
					if (!scsi_eh_host_reset(work_q, done_q))
						scsi_eh_offline_sdevs(work_q,
								      done_q);
}

为什么发送的TUR(TEST UNIT READY)命令会超时

网络包分析

为了分析为什么scsi_send_eh_cmnd发送TUR指令到target去处理会超时，首先想到的就是抓包分析，对比2种情况下（裸盘测试和从文件系统上测试）的包处理有什么不同。
1）裸盘测试过程中，tcpdump抓取包，然后使用wireshark分析
error-disk-cause-iohang2
2）从文件系统上去测试过程中，tcpdump抓取包，通过wireshark分析
error-disk-cause-iohang2
从上面两图的对比就可以发现，当从文件系统测试过程中某个时候开始initiator发送给target的TUR消息没有收到响应，既然没有响应，那就说明target端处理上有问题导致没有回包。

iscsitarget端分析

iscsitarget默认情况下只有error的日志，比较少，不便于分析问题，因此针对TEST UNIT READY指令的处理地方加上debug日志，然后重新编译模块，并且开启iscsitarget自带的debug日志。

1
sudo insmod iscsi_trgt.ko debug_enable_flags=255

然后再次从文件系统层面测试来重现，重点关注target端的日志

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
Feb 15 15:38:41 10-165-160-13 kernel: [2243339.970923] iscsi_trgt: Abort Task (01) issued on tid:1000 lun:0 by sid:281475098149376 (Function Complete)
Feb 15 15:38:41 10-165-160-13 kernel: [2243339.970935] iscsi_trgt: write_data(347) 0x10000073d0200:0: 48(48)
Feb 15 15:38:41 10-165-160-13 kernel: [2243339.971091] iscsi_trgt: Abort Task (01) issued on tid:1000 lun:0 by sid:281475098149376 (Function Complete)
Feb 15 15:38:41 10-165-160-13 kernel: [2243339.971098] iscsi_trgt: write_data(347) 0x10000073d0200:0: 48(48)
Feb 15 15:38:41 10-165-160-13 kernel: [2243339.971232] iscsi_trgt: scsi_cmnd_start(996) 6a000030 0 TEST_UNIT_READY
Feb 15 15:38:41 10-165-160-13 kernel: [2243339.971517] iscsi_trgt: disk_execute_cmnd(638) disk_execute_cmnd 6a000030 0 TEST_UNIT_READY
Feb 15 15:38:41 10-165-160-13 kernel: [2243339.971859] iscsi_trgt: write_data(347) 0x10000073d0200:0: 48(48)
Feb 15 15:38:42 10-165-160-13 kernel: [2243340.978354] iscsi_trgt: write_data(347) 0x10000073d0200:0: 48(48)
Feb 15 15:38:44 10-165-160-13 kernel: [2243342.981374] iscsi_trgt: Abort Task (01) issued on tid:1000 lun:0 by sid:281475098149376 (Function Complete)
Feb 15 15:38:44 10-165-160-13 kernel: [2243342.981385] iscsi_trgt: write_data(347) 0x10000073d0200:0: 48(48)
Feb 15 15:38:44 10-165-160-13 kernel: [2243342.981489] iscsi_trgt: Abort Task (01) issued on tid:1000 lun:0 by sid:281475098149376 (Function Complete)
Feb 15 15:38:44 10-165-160-13 kernel: [2243342.981496] iscsi_trgt: write_data(347) 0x10000073d0200:0: 48(48)
Feb 15 15:38:44 10-165-160-13 kernel: [2243342.981621] iscsi_trgt: scsi_cmnd_start(996) 74000030 0 TEST_UNIT_READY
Feb 15 15:38:44 10-165-160-13 kernel: [2243342.981914] iscsi_trgt: disk_execute_cmnd(638) disk_execute_cmnd 74000030 0 TEST_UNIT_READY
Feb 15 15:38:44 10-165-160-13 kernel: [2243342.982256] iscsi_trgt: write_data(347) 0x10000073d0200:0: 48(48)
Feb 15 15:38:46 10-165-160-13 kernel: [2243344.980338] iscsi_trgt: write_data(347) 0x10000073d0200:0: 48(48)
Feb 15 15:38:48 10-165-160-13 kernel: [2243346.979438] iscsi_trgt: Abort Task (01) issued on tid:1000 lun:0 by sid:281475098149376 (Function Complete)
Feb 15 15:38:48 10-165-160-13 kernel: [2243346.979451] iscsi_trgt: write_data(347) 0x10000073d0200:0: 48(48)
Feb 15 15:38:48 10-165-160-13 kernel: [2243346.979570] iscsi_trgt: Abort Task (01) issued on tid:1000 lun:0 by sid:281475098149376 (Function Complete)
Feb 15 15:38:48 10-165-160-13 kernel: [2243346.979578] iscsi_trgt: write_data(347) 0x10000073d0200:0: 48(48)
Feb 15 15:38:48 10-165-160-13 kernel: [2243346.979702] iscsi_trgt: scsi_cmnd_start(996) 7a000030 0 TEST_UNIT_READY
Feb 15 15:38:48 10-165-160-13 kernel: [2243346.979987] iscsi_trgt: disk_execute_cmnd(638) disk_execute_cmnd 7a000030 0 TEST_UNIT_READY
Feb 15 15:38:48 10-165-160-13 kernel: [2243346.980318] iscsi_trgt: write_data(347) 0x10000073d0200:0: 48(48)
Feb 15 15:38:50 10-165-160-13 kernel: [2243348.978415] iscsi_trgt: write_data(347) 0x10000073d0200:0: 48(48)
Feb 15 15:38:52 10-165-160-13 kernel: [2243350.977497] iscsi_trgt: Abort Task (01) issued on tid:1000 lun:0 by sid:281475098149376 (Function Complete)
Feb 15 15:38:52 10-165-160-13 kernel: [2243350.977511] iscsi_trgt: write_data(347) 0x10000073d0200:0: 48(48)
Feb 15 15:38:52 10-165-160-13 kernel: [2243350.977628] iscsi_trgt: Abort Task (01) issued on tid:1000 lun:0 by sid:281475098149376 (Function Complete)
Feb 15 15:38:52 10-165-160-13 kernel: [2243350.977635] iscsi_trgt: write_data(347) 0x10000073d0200:0: 48(48)
Feb 15 15:38:52 10-165-160-13 kernel: [2243350.977766] iscsi_trgt: scsi_cmnd_start(996) 79000030 0 TEST_UNIT_READY
###########这里发的TEST_UNIT_READY没有接下去调用disk_execute_cmnd
Feb 15 15:38:57 10-165-160-13 kernel: [2243355.978980] iscsi_trgt: write_data(347) 0x10000073d0200:0: 48(48)
Feb 15 15:39:02 10-165-160-13 kernel: [2243360.972560] iscsi_trgt: Abort Task (01) issued on tid:1000 lun:0 by sid:281475098149376 (Function Complete)
Feb 15 15:39:02 10-165-160-13 kernel: [2243360.972571] iscsi_trgt: write_data(347) 0x10000073d0200:0: 48(48)
Feb 15 15:39:02 10-165-160-13 kernel: [2243360.972741] iscsi_trgt: Logical Unit Reset (05) issued on tid:1000 lun:0 by sid:281475098149376 (Function Complete)
Feb 15 15:39:02 10-165-160-13 kernel: [2243360.972748] iscsi_trgt: write_data(347) 0x10000073d0200:0: 48(48)
Feb 15 15:39:02 10-165-160-13 kernel: [2243360.972887] iscsi_trgt: scsi_cmnd_start(996) 2000030 0 TEST_UNIT_READY
###########这里发的TEST_UNIT_READY没有接下去调用disk_execute_cmnd
Feb 15 15:39:07 10-165-160-13 kernel: [2243365.982080] iscsi_trgt: write_data(347) 0x10000073d0200:0: 48(48)
Feb 15 15:39:12 10-165-160-13 kernel: [2243370.967665] iscsi_trgt: Abort Task (01) issued on tid:1000 lun:0 by sid:281475098149376 (Function Complete)
Feb 15 15:39:12 10-165-160-13 kernel: [2243370.967680] iscsi_trgt: write_data(347) 0x10000073d0200:0: 48(48)
Feb 15 15:39:12 10-165-160-13 kernel: [2243370.967849] iscsi_trgt: Target Warm Reset (06) issued on tid:1000 lun:0 by sid:281475098149376 (Function Complete)
Feb 15 15:39:12 10-165-160-13 kernel: [2243370.967857] iscsi_trgt: write_data(347) 0x10000073d0200:0: 48(48)
Feb 15 15:39:12 10-165-160-13 kernel: [2243370.968009] iscsi_trgt: scsi_cmnd_start(996) 1000030 0 TEST_UNIT_READY
###########这里发的TEST_UNIT_READY没有接下去调用disk_execute_cmnd
Feb 15 15:39:17 10-165-160-13 kernel: [2243375.981201] iscsi_trgt: write_data(347) 0x10000073d0200:0: 48(48)
Feb 15 15:39:22 10-165-160-13 kernel: [2243380.962731] iscsi_trgt: Abort Task (01) issued on tid:1000 lun:0 by sid:281475098149376 (Function Complete)
Feb 15 15:39:22 10-165-160-13 kernel: [2243380.962743] iscsi_trgt: write_data(347) 0x10000073d0200:0: 48(48)

这里日志还不够详细，再针对性的把cmnd处理过程中的相关信息都打印出来。

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
Feb 15 17:40:47 10-165-160-13 kernel: [2250662.387487] iscsi_trgt: do_recv(144) 48
Feb 15 17:40:47 10-165-160-13 kernel: [2250662.387489] iscsi_trgt: cmnd_insert_hash(641) ffff885f5a75a830:b0000054
Feb 15 17:40:47 10-165-160-13 kernel: [2250662.387492] iscsi_trgt: check_cmd_sn(567) cmd_sn(10417) exp_cmd_sn(10417) max_cmd_sn(10449)
Feb 15 17:40:47 10-165-160-13 kernel: [2250662.387494] iscsi_trgt: update_stat_sn(551) 1,350
Feb 15 17:40:47 10-165-160-13 kernel: [2250662.387495] iscsi_trgt: scsi_cmnd_start(982) scsi command: 00
Feb 15 17:40:47 10-165-160-13 kernel: [2250662.387498] iscsi_trgt: scsi_cmnd_start(1007) 540000b0 0 TEST_UNIT_READY
Feb 15 17:40:47 10-165-160-13 kernel: [2250662.394591] iscsi_trgt: cmnd_rx_end(1970) ffff885f5a75a830:1
Feb 15 17:40:47 10-165-160-13 kernel: [2250662.394593] iscsi_trgt: iscsi_session_push_cmnd(1865) ffff885f5a75a830:1 10417,10417
Feb 15 17:40:47 10-165-160-13 kernel: [2250662.394595] iscsi_trgt: iscsi_cmnd_exec(1620) ffff885f5a75a830,1,10417
Feb 15 17:40:47 10-165-160-13 kernel: [2250662.394597] iscsi_trgt: iscsi_scsi_queuecmnd(64) ffff885f5a75a830
Feb 15 17:40:47 10-165-160-13 kernel: [2250662.394600] iscsi_trgt: iscsi_scsi_queuecmnd(76) iscsi_scsi_queuecmnd queue_lock aquired, 540000b0 0
Feb 15 17:40:47 10-165-160-13 kernel: [2250662.401931] iscsi_trgt: wthread_queue(35) wthread_queue put cmnd:ffff885f5a75a830 to work_queue, 540000b0 0
Feb 15 17:40:47 10-165-160-13 kernel: [2250662.409500] iscsi_trgt: iscsi_scsi_queuecmnd(95) iscsi_scsi_queuecmnd device queue cmnd:ffff885f5a75a830, 540000b0 0
Feb 15 17:40:47 10-165-160-13 kernel: [2250662.409540] iscsi_trgt: get_ready_cmnd(53) get_ready_cmnd get cmnd:ffff885f5a75a830 to work_queue, 540000b0 0
Feb 15 17:40:47 10-165-160-13 kernel: [2250662.409543] iscsi_trgt: disk_execute_cmnd(638) disk_execute_cmnd 540000b0 0 TEST_UNIT_READY
Feb 15 17:40:47 10-165-160-13 kernel: [2250662.409546] iscsi_trgt: cmnd_alloc(180) ffff882f2ea0a000:ffff885f889e8488
Feb 15 17:40:47 10-165-160-13 kernel: [2250662.409549] iscsi_trgt: iscsi_cmnds_init_write(221) ffff885f889e8488:21
Feb 15 17:40:47 10-165-160-13 kernel: [2250662.433261] iscsi_trgt: cmnd_tx_start(1735) ffff885f889e8488:21
Feb 15 17:40:47 10-165-160-13 kernel: [2250662.433268] iscsi_trgt: write_data(347) 0x10000073d0200:0: 48(48)
Feb 15 17:40:47 10-165-160-13 kernel: [2250662.433270] iscsi_trgt: cmnd_tx_end(1810) ffff885f889e8488:21
Feb 15 17:40:47 10-165-160-13 kernel: [2250662.433275] iscsi_trgt: cmnd_release(1693) cmnd_release cmnd:ffff885f889e8488, 21 4 0
Feb 15 17:40:47 10-165-160-13 kernel: [2250662.441226] iscsi_trgt: iscsi_cmnd_remove(441) ffff885f889e8488
Feb 15 17:40:47 10-165-160-13 kernel: [2250662.441229] iscsi_trgt: cmnd_release(1693) cmnd_release cmnd:ffff885f5a75a830, 1 24b 0
Feb 15 17:40:47 10-165-160-13 kernel: [2250662.448959] iscsi_trgt: iscsi_cmnd_remove(441) ffff885f5a75a830
Feb 15 17:40:47 10-165-160-13 kernel: [2250662.448963] iscsi_trgt: cmnd_alloc(180) ffff882f2ea0a000:ffff885f5a75a830
.............下面3次是TEST_UNIT_READY请求没能正常处理的日志
Feb 15 17:40:51 10-165-160-13 kernel: [2250666.385455] iscsi_trgt: do_recv(144) 48
Feb 15 17:40:51 10-165-160-13 kernel: [2250666.385457] iscsi_trgt: cmnd_insert_hash(641) ffff885f88a4f120:b000005d
Feb 15 17:40:51 10-165-160-13 kernel: [2250666.385460] iscsi_trgt: check_cmd_sn(567) cmd_sn(10420) exp_cmd_sn(10420) max_cmd_sn(10452)
Feb 15 17:40:51 10-165-160-13 kernel: [2250666.385461] iscsi_trgt: update_stat_sn(551) 1,354
Feb 15 17:40:51 10-165-160-13 kernel: [2250666.385463] iscsi_trgt: scsi_cmnd_start(982) scsi command: 00
Feb 15 17:40:51 10-165-160-13 kernel: [2250666.385466] iscsi_trgt: scsi_cmnd_start(1007) 5d0000b0 0 TEST_UNIT_READY
Feb 15 17:40:51 10-165-160-13 kernel: [2250666.392490] iscsi_trgt: cmnd_rx_end(1970) ffff885f88a4f120:1
Feb 15 17:40:51 10-165-160-13 kernel: [2250666.392493] iscsi_trgt: iscsi_session_push_cmnd(1865) ffff885f88a4f120:1 10420,10420
Feb 15 17:40:51 10-165-160-13 kernel: [2250666.392495] iscsi_trgt: iscsi_cmnd_exec(1620) ffff885f88a4f120,1,10420
Feb 15 17:40:51 10-165-160-13 kernel: [2250666.392496] iscsi_trgt: iscsi_scsi_queuecmnd(64) ffff885f88a4f120
Feb 15 17:40:51 10-165-160-13 kernel: [2250666.392499] iscsi_trgt: iscsi_scsi_queuecmnd(76) iscsi_scsi_queuecmnd queue_lock aquired, 5d0000b0 0
Feb 15 17:40:51 10-165-160-13 kernel: [2250666.399778] iscsi_trgt: wthread_queue(35) wthread_queue put cmnd:ffff885f88a4f120 to work_queue, 5d0000b0 0
Feb 15 17:40:51 10-165-160-13 kernel: [2250666.407283] iscsi_trgt: iscsi_scsi_queuecmnd(95) iscsi_scsi_queuecmnd device queue cmnd:ffff885f88a4f120, 5d0000b0 0
Feb 15 17:40:56 10-165-160-13 kernel: [2250671.370526] iscsi_trgt: cmnd_alloc(180) ffff882f2ea0a000:ffff885f88a4f258
..............
Feb 15 17:41:01 10-165-160-13 kernel: [2250676.393762] iscsi_trgt: do_recv(144) 48
Feb 15 17:41:01 10-165-160-13 kernel: [2250676.393764] iscsi_trgt: cmnd_insert_hash(641) ffff885f88a4f258:b0000056
Feb 15 17:41:01 10-165-160-13 kernel: [2250676.393766] iscsi_trgt: check_cmd_sn(567) cmd_sn(10421) exp_cmd_sn(10421) max_cmd_sn(10453)
Feb 15 17:41:01 10-165-160-13 kernel: [2250676.393768] iscsi_trgt: update_stat_sn(551) 1,357
Feb 15 17:41:01 10-165-160-13 kernel: [2250676.393770] iscsi_trgt: scsi_cmnd_start(982) scsi command: 00
Feb 15 17:41:01 10-165-160-13 kernel: [2250676.393772] iscsi_trgt: scsi_cmnd_start(1007) 560000b0 0 TEST_UNIT_READY
Feb 15 17:41:01 10-165-160-13 kernel: [2250676.400617] iscsi_trgt: cmnd_rx_end(1970) ffff885f88a4f258:1
Feb 15 17:41:01 10-165-160-13 kernel: [2250676.400619] iscsi_trgt: iscsi_session_push_cmnd(1865) ffff885f88a4f258:1 10421,10421
Feb 15 17:41:01 10-165-160-13 kernel: [2250676.400621] iscsi_trgt: iscsi_cmnd_exec(1620) ffff885f88a4f258,1,10421
Feb 15 17:41:01 10-165-160-13 kernel: [2250676.400623] iscsi_trgt: iscsi_scsi_queuecmnd(64) ffff885f88a4f258
Feb 15 17:41:01 10-165-160-13 kernel: [2250676.400625] iscsi_trgt: iscsi_scsi_queuecmnd(76) iscsi_scsi_queuecmnd queue_lock aquired, 560000b0 0
Feb 15 17:41:01 10-165-160-13 kernel: [2250676.407563] iscsi_trgt: wthread_queue(35) wthread_queue put cmnd:ffff885f88a4f258 to work_queue, 560000b0 0
Feb 15 17:41:01 10-165-160-13 kernel: [2250676.414738] iscsi_trgt: iscsi_scsi_queuecmnd(95) iscsi_scsi_queuecmnd device queue cmnd:ffff885f88a4f258, 560000b0 0
Feb 15 17:41:06 10-165-160-13 kernel: [2250681.389629] iscsi_trgt: cmnd_alloc(180) ffff882f2ea0a000:ffff885f88a4f390
...............
Feb 15 17:41:11 10-165-160-13 kernel: [2250686.401385] iscsi_trgt: do_recv(144) 48
Feb 15 17:41:11 10-165-160-13 kernel: [2250686.401387] iscsi_trgt: cmnd_insert_hash(641) ffff885f88a4f390:b0000068
Feb 15 17:41:11 10-165-160-13 kernel: [2250686.401389] iscsi_trgt: check_cmd_sn(567) cmd_sn(10422) exp_cmd_sn(10422) max_cmd_sn(10454)
Feb 15 17:41:11 10-165-160-13 kernel: [2250686.401391] iscsi_trgt: update_stat_sn(551) 1,35a
Feb 15 17:41:11 10-165-160-13 kernel: [2250686.401393] iscsi_trgt: scsi_cmnd_start(982) scsi command: 00
Feb 15 17:41:11 10-165-160-13 kernel: [2250686.401395] iscsi_trgt: scsi_cmnd_start(1007) 680000b0 0 TEST_UNIT_READY
Feb 15 17:41:11 10-165-160-13 kernel: [2250686.408639] iscsi_trgt: cmnd_rx_end(1970) ffff885f88a4f390:1
Feb 15 17:41:11 10-165-160-13 kernel: [2250686.408641] iscsi_trgt: iscsi_session_push_cmnd(1865) ffff885f88a4f390:1 10422,10422
Feb 15 17:41:11 10-165-160-13 kernel: [2250686.408643] iscsi_trgt: iscsi_cmnd_exec(1620) ffff885f88a4f390,1,10422
Feb 15 17:41:11 10-165-160-13 kernel: [2250686.408645] iscsi_trgt: iscsi_scsi_queuecmnd(64) ffff885f88a4f390
Feb 15 17:41:11 10-165-160-13 kernel: [2250686.408647] iscsi_trgt: iscsi_scsi_queuecmnd(76) iscsi_scsi_queuecmnd queue_lock aquired, 680000b0 0
Feb 15 17:41:11 10-165-160-13 kernel: [2250686.415920] iscsi_trgt: wthread_queue(35) wthread_queue put cmnd:ffff885f88a4f390 to work_queue, 680000b0 0
Feb 15 17:41:11 10-165-160-13 kernel: [2250686.423196] iscsi_trgt: iscsi_scsi_queuecmnd(95) iscsi_scsi_queuecmnd device queue cmnd:ffff885f88a4f390, 680000b0 0
Feb 15 17:41:16 10-165-160-13 kernel: [2250691.384730] iscsi_trgt: cmnd_alloc(180) ffff882f2ea0a000:ffff885f88a4f4c8
...........

通过日志并结合iscsitarget的源码可以发现，TEST_UNIT_READY请求发送到target后，由target的网络线程进行包解析等处理后，调用wthread_queue将cmnd放到target的work_queue里，然后调用wake_up()去唤醒target的IO线程去进行处理。正常情况下IO线程被唤醒后从work_queue里取cmnd，然后调用disk_execute_cmnd进行处理。但是从上面日志里的后3次TEST UNIT READY请求处理过程中发现当把cmnd放到work_queue后调用wake_up()后，并没有IO线程处理的日志了。

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
// 将cmnd放到work_queue并wake_up的函数
void wthread_queue(struct iscsi_cmnd *cmnd)
{
	struct worker_thread_info *info = cmnd->conn->session->target->wthread_info;

	if (!list_empty(&cmnd->list)) {
		struct iscsi_scsi_cmd_hdr *req = cmnd_hdr(cmnd);
		eprintk("%x %p %x %x %x %x %lx %x\n",
			cmnd_itt(cmnd), req, req->opcode, req->scb[0], cmnd->pdu.datasize,
			be32_to_cpu(req->data_length), cmnd->flags, req->flags);

		if (cmnd->lun)
			eprintk("%u\n", cmnd->lun->lun);
		assert(list_empty(&cmnd->list));
	}

	spin_lock(&info->wthread_lock);
	// for debug
	struct iscsi_scsi_cmd_hdr *req = cmnd_hdr(cmnd);
	if (req->scb[0] == TEST_UNIT_READY)
		eprintk("wthread_queue put cmnd:%p to work_queue, %x %x\n", cmnd, cmnd_itt(cmnd), req->scb[0]);
	list_add_tail(&cmnd->list, &info->work_queue);
	spin_unlock(&info->wthread_lock);

	atomic_inc(&cmnd->conn->nr_busy_cmnds);

	wake_up(&info->wthread_sleep);
}

// target的IO处理线程
static int worker_thread(void *arg)
{
	struct worker_thread *wt = (struct worker_thread *) arg;
	struct worker_thread_info *info = wt->w_info;
	struct iscsi_cmnd *cmnd;
	struct iscsi_conn *conn;
	DECLARE_WAITQUEUE(wait, current);

	get_io_context(GFP_KERNEL, -1);

	if (!current->io_context)
		eprintk("%s\n", "Failed to get IO context");
	else if (info->wthread_ioc)
		copy_io_context(&current->io_context, &info->wthread_ioc);
	else
		info->wthread_ioc = current->io_context;

	add_wait_queue(&info->wthread_sleep, &wait);

	__set_current_state(TASK_RUNNING);
	do {
		while (!list_empty(&info->work_queue) &&
		       (cmnd = get_ready_cmnd(info))) {
			conn = cmnd->conn;
			if (cmnd_tmfabort(cmnd))
				cmnd_release(cmnd, 1);
			else
				cmnd_execute(cmnd);
			assert(conn);
			atomic_dec(&conn->nr_busy_cmnds);
		}

		set_current_state(TASK_INTERRUPTIBLE);
		if (list_empty(&info->work_queue))
			schedule();
        // 如果被唤醒，应该会打印下面这条日志
		eprintk("worker_thread:%d, waked up to running\n", current->pid);
		__set_current_state(TASK_RUNNING);
	} while (!kthread_should_stop());

	remove_wait_queue(&info->wthread_sleep, &wait);

	if (current->io_context) {
		struct io_context *ioc = current->io_context;

		task_lock(current);
		current->io_context = NULL;
		task_unlock(current);

		put_io_context(ioc);
	}

	return 0;
}

这说明target的IO线程没有被成功唤醒，困扰了一会，经内核的同事提醒去观察这些IO线程那段时间的状态(cat /proc//status)，看看voluntary_ctxt_switches（线程主动切换）和nonvoluntary_ctxt_switches（线程被动切换）这两项有没有增加。因此写了个脚本每隔1s cat一下这些线程的状态。

1
for i in {1..3600};do for j in {81994..82001};do date >> istiod_$j.txt; sudo cat /proc/$j/status >> istiod_$j.txt;done;sleep 1s;done

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
线程状态
Thu Feb 16 09:35:10 CST 2017
Name:   istiod0
State:  D (disk sleep)
Tgid:   58434
Pid:    58434
PPid:   2
TracerPid:      0
Uid:    0       0       0       0
Gid:    0       0       0       0
FDSize: 64
Groups:
Threads:        1
SigQ:   1/3099088
SigPnd: 0000000000000000
ShdPnd: 0000000000000000
SigBlk: 0000000000000000
SigIgn: ffffffffffffffff
SigCgt: 0000000000000000
CapInh: 0000000000000000
CapPrm: 0000001fffffffff
CapEff: 0000001fffffffff
CapBnd: 0000001fffffffff
Seccomp:        0
Cpus_allowed:   ffff,ffffffff,ffffffff,ffffffff,ffffffff
Cpus_allowed_list:      0-143
Mems_allowed:   00000000,00000003
Mems_allowed_list:      0-1
voluntary_ctxt_switches:        6172
nonvoluntary_ctxt_switches:     196
**********持续10s状态和switches都没变，6172和196**********
Thu Feb 16 09:35:20 CST 2017
Name:   istiod0
State:  D (disk sleep)
Tgid:   58434
Pid:    58434
PPid:   2
TracerPid:      0
Uid:    0       0       0       0
Gid:    0       0       0       0
FDSize: 64
Groups:
Threads:        1
SigQ:   1/3099088
SigPnd: 0000000000000000
ShdPnd: 0000000000000000
SigBlk: 0000000000000000
SigIgn: ffffffffffffffff
SigCgt: 0000000000000000
CapInh: 0000000000000000
CapPrm: 0000001fffffffff
CapEff: 0000001fffffffff
CapBnd: 0000001fffffffff
Seccomp:        0
Cpus_allowed:   ffff,ffffffff,ffffffff,ffffffff,ffffffff
Cpus_allowed_list:      0-143
Mems_allowed:   00000000,00000003
Mems_allowed_list:      0-1
voluntary_ctxt_switches:        6173
nonvoluntary_ctxt_switches:     196
************持续10s状态和switches都没变，6173和196***************
Thu Feb 16 09:35:30 CST 2017
Name:   istiod0
State:  D (disk sleep)
Tgid:   58434
Pid:    58434
PPid:   2
TracerPid:      0
Uid:    0       0       0       0
Gid:    0       0       0       0
FDSize: 64
Groups:
Threads:        1
SigQ:   1/3099088
SigPnd: 0000000000000000
ShdPnd: 0000000000000000
SigBlk: 0000000000000000
SigIgn: ffffffffffffffff
SigCgt: 0000000000000000
CapInh: 0000000000000000
CapPrm: 0000001fffffffff
CapEff: 0000001fffffffff
CapBnd: 0000001fffffffff
Seccomp:        0
Cpus_allowed:   ffff,ffffffff,ffffffff,ffffffff,ffffffff
Cpus_allowed_list:      0-143
Mems_allowed:   00000000,00000003
Mems_allowed_list:      0-1
voluntary_ctxt_switches:        6174
nonvoluntary_ctxt_switches:     196

从状态上看，确实异常情况下，对应的IO线程的ctxt_switches都没有变化，并且线程状态处于D(disk sleep)状态，处于D状态的内核线程都是UNINTERRUPTIBLE的，无法唤醒的。

为了对比，在裸盘测试过程中也抓取了这些IO线程的状态，结果发现过程中有些IO线程处于D状态，但是还有处于S状态的线程，因此可以唤醒来进行处理。

为了进一步确认问题，将target的IO线程改成1个（默认每个target是1个网络线程，8个IO线程），使用以下命令可以修改。

1
sudo ietadm --op update --tid=<tid> --params=Wthreads=<N>

然后再分别裸盘测试和文件系统上测试，这次发现裸盘测试时fio也是多hang了3次10s的时间，并且target的那个IO线程是处于D状态的。

至此，基本可以确认是由于从文件系统测试时多余的sync IO导致target的IO线程都D状态因此无法继续处理TEST UNIT READY请求从而导致initiator端iscsi设备TUR请求超时。

既然是文件系统多的sync IO导致，那么有没有可能减少异常情况下发到target的IO呢？
1）一种尝试是调整文件系统的flush时间(/proc/sys/vm/dirty_expire_centisecs)，减小刷脏页的时间间隔，结果测试后没有效果；

2）另外一种是调整这个iscsi设备的queue_depth(/sys/block/sds/device/queue_depth)，对于iscsi设备默认的queue_depth=32，那么可以将这个调小比如调整到1，测试确认当这个值调小后，target默认8个IO线程的时候，从文件系统去fio测试，结果没有多出30s的io hang时间。说明这个调整是有效果的，但是考虑到queue_depth调小后会影响IO性能（因为当io队列达到这个值后直接在设备层面就阻止将后续io放入队列了），因此换个角度去调大后端target的IO线程。

3）那target的IO线程调整到多少合适了，经过测试调整成大于queue_depth时没有多余的30s hang，但是调整到32或者30，有的时候不会多，有的时候也是会多30s，因此保险起见，调大成略大于queue_depth，比如设置成40。不过每个target的IO线程都改成40会导致内核资源的增加（这点还能接受），另外可能会影响性能，因为每个target的IO线程是共用一个队列，通过spin_lock来获取队列的访问，因此测试时需要重点关注性能会不会有所影响，锁的竞争的cpu是否增加等。

附录

排查问题过程中分析的scsi error handler部分处理逻辑

详细的可以结合Documentation about scsi_cmnd lifecycle和内核源码来看

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
scsi_error_handler()
|
+->scsi_unjam_host()
   |
   +->scsi_eh_get_sense()
   |
   +->scsi_eh_abort_cmds()
   |  |
   |  +->rtn=scsi_try_to_abort_cmd()
   |  |  |
   |  |  +->hostt->eh_abort_handler,iscsi对应的是iscsi_eh_abort
   |  +->if rtn == FAST_IO_FAIL, call scsi_eh_finish_cmd() to put cmd to done_q,
   |  |     else move scmd to check_list
   |  +->scsi_eh_test_devices()
   |     |
   |     +->finish_cmds = !scsi_device_online(scmd->device) ||
   |        (try_stu && !scsi_eh_try_stu(scmd) &&
   |        !scsi_eh_tur(scmd)) ||
   |        !scsi_eh_tur(scmd);
   |        我们的场景下try_stu=0,因此调用的scsi_eh_tur()
   |        |
   |        +->scsi_send_eh_cmnd(,,SENSE_TIMEOUT)
   |           |
   |           +->rtn=shost->hostt->queuecommand(), here is iscsi_queuecommand()
   |           +->wait_for_completion_timeout(,,timeout), here wait timeout=SENSE_TIMEOUT=10s
   |           +->if timeleft==0 && !rtn, call scsi_abort_eh_cmnd()
   |
   +->scsi_eh_ready_devs()
   |   (when scsi_eh_abort_cmds() return false then call scsi_eh_ready_devs())
   |  |
   |  +->scsi_eh_stu()
   |  +->scsi_eh_bus_device_reset()
   |  |  |
   |  |  +->scsi_try_bus_device_reset()
   |  |  +->scsi_eh_tur()
   |  |     |
   |  |     +->scsi_send_eh_cmnd(,,SENSE_TIMEOUT)
   |  |        |
   |  |        +->scsi_queuecommand()
   |  |        +->wait_for_completion_timeout(,,timeout), here wait timeout=SENSE_TIMEOUT=10s
   |  |        +->scsi_abort_eh_cmnd()
   |  |
   |  +->scsi_eh_target_reset()
   |  |  |
   |  |  +->scsi_try_target_reset()
   |  |  +->scsi_eh_test_devices()
   |  |     |
   |  |     +->scsi_eh_tur()
   |  |        |
   |  |        +->scsi_send_eh_cmnd(,,SENSE_TIMEOUT)
   |  |           |
   |  |           +->scsi_queuecommand()
   |  |           +->wait_for_completion_timeout(,,timeout), here wait timeout=SENSE_TIMEOUT=10s
   |  |           +->scsi_abort_eh_cmnd()
   |  +->scsi_eh_bus_reset()
   |  |  |
   |  |  +->scsi_try_bus_reset()
   |  |  +->scsi_eh_test_devices()
   |  |
   |  +->scsi_eh_host_reset()
   |  |  |
   |  |  +->scsi_try_host_reset()
   |  |  +->scsi_eh_test_devices()
   |  |
   |  +->scsi_eh_offline_sdevs()
   |
   +->scsi_eh_flush_done_q()
     (For all the EH commands on the done_q, either requeue them to retry(via
      scsi_queue_insert()) if eligible, or finish them up to block layer
      (via scsi_finish_command())

systemtap脚本

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
%{
#include <linux/types.h>
#include <scsi/scsi_cmnd.h>
#include <scsi/scsi_device.h>
#include <scsi/scsi_host.h>
#include <scsi/scsi_cmnd.h>
#include <linux/timer.h>
#include <linux/blkdev.h>
%}

probe module("scsi_mod").function("scsi_send_eh_cmnd").call {
	host_no = $scmd->device->host->host_no
	channel = $scmd->device->channel
	lun = $scmd->device->lun
	dev_id = $scmd->device->id
	/*print_backtrace()*/
	printf("%s, scsi_send_eh_cmnd enter: host_no=%d, channel=%d, lun=%d, dev_id=%d, scmd:%p, sense_timeout:%d\n", ctime(gettimeofday_s()), host_no, channel, lun, dev_id, $scmd, $timeout)
}

probe module("scsi_mod").function("scsi_send_eh_cmnd").return {
	host_no = $scmd->device->host->host_no
	channel = $scmd->device->channel
	lun = $scmd->device->lun
	dev_id = $scmd->device->id
	printf("%s, scsi_send_eh_cmnd return: host_no=%d, channel=%d, lun=%d, dev_id=%d, scmd:%p, sense_timeout:%d, return:%d\n\n", ctime(gettimeofday_s()), host_no, channel, lun, dev_id, $scmd, $timeout, $return)
}

probe module("libiscsi").function("iscsi_queuecommand").call {
	host_no = $sc->device->host->host_no
	channel = $sc->device->channel
	lun = $sc->device->lun
	dev_id = $sc->device->id
	if (host_no == 62 && channel == 0 && lun == 11 && dev_id == 0) {
		/*print_backtrace()*/
		printf("%s, iscsi_queuecommand call: host_no=%d, channel=%d, lun=%d, dev_id=%d, scmd:%p\n", ctime(gettimeofday_s()), host_no, channel, lun, dev_id, $sc)
	}	
}

probe module("libiscsi").function("iscsi_queuecommand").return {
	host_no = $sc->device->host->host_no
	channel = $sc->device->channel
	lun = $sc->device->lun
	dev_id = $sc->device->id
	if (host_no == 62 && channel == 0 && lun == 11 && dev_id == 0) {
		printf("%s, iscsi_queuecommand return: host_no=%d, channel=%d, lun=%d, dev_id=%d, scmd:%p, return=%d\n", ctime(gettimeofday_s()), host_no, channel, lun, dev_id, $sc, $return)
	}	
}

probe module("scsi_mod").function("scsi_dispatch_cmd") {
	host_no = $cmd->device->host->host_no
	channel = $cmd->device->channel
	lun = $cmd->device->lun
	dev_id = $cmd->device->id
	if (host_no == 62 && channel == 0 && lun == 11 && dev_id == 0) {
		printf("%s, scsi_dispatch_cmd: host_no=%d, channel=%d, lun=%d, dev_id=%d, cmd:%p\n", ctime(gettimeofday_s()), host_no, channel, lun, dev_id, $cmd)
	}
}
probe module("scsi_mod").function("scsi_times_out") {
	printf("%s, scsi_times_out: scmd:%p\n", ctime(gettimeofday_s()), $req->special)	
}

probe kernel.function("wait_for_completion_timeout") {
	printf("%s, wait_for_completion_timeout\n", ctime(gettimeofday_s()))
}

probe module("scsi_mod").function("scsi_eh_test_devices").call {
	/*print_backtrace()*/
	printf("%s, scsi_eh_test_devices call: try_stu=%d\n", ctime(gettimeofday_s()), $try_stu)
}
probe module("scsi_mod").function("scsi_eh_test_devices").return {
	printf("%s, scsi_eh_test_devices return=%d : try_stu=%d\n", ctime(gettimeofday_s()), $return, $try_stu)
}

probe module("scsi_mod").function("scsi_eh_abort_cmds") {
	printf("%s, scsi_eh_abort_cmds\n", ctime(gettimeofday_s()))
}

probe module("scsi_mod").function("scsi_eh_bus_device_reset") {
	printf("%s, scsi_eh_bus_device_reset\n", ctime(gettimeofday_s()))
}

probe module("scsi_mod").function("scsi_eh_target_reset") {
	printf("%s, scsi_eh_target_reset\n", ctime(gettimeofday_s()))
}

probe module("scsi_mod").function("scsi_eh_host_reset") {
	printf("%s, scsi_eh_host_reset\n", ctime(gettimeofday_s()))
}

probe module("scsi_mod").function("scsi_eh_bus_reset") {
	printf("%s, scsi_eh_bus_reset\n", ctime(gettimeofday_s()))
}

probe module("scsi_mod").function("scsi_eh_try_stu").call {
	printf("%s, scsi_eh_try_stu call, scmd: %p\n", ctime(gettimeofday_s()), $scmd)
}
probe module("scsi_mod").function("scsi_eh_try_stu").return {
	printf("%s, scsi_eh_try_stu return, scmd: %p\n", ctime(gettimeofday_s()), $scmd)
}

probe module("scsi_mod").function("scsi_eh_tur").call {
	printf("%s, scsi_eh_tur call, scmd: %p\n", ctime(gettimeofday_s()), $scmd)
}
probe module("scsi_mod").function("scsi_eh_tur").return {
	printf("%s, scsi_eh_tur return=%d, scmd: %p\n", ctime(gettimeofday_s()), $return, $scmd)
}

probe module("scsi_mod").function("scsi_eh_stu") {
	printf("%s, scsi_eh_stu\n", ctime(gettimeofday_s()))
}

执行脚本的命令

1
sudo stap -g --all-modules scsi.stp