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
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
351
352
353
354
355
356
357
358
359
360
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
377
378
379
380
381
382
383
384
385
386
|
#!/usr/bin/env python
#
# Copyright (C) 2016 The Android Open Source Project
#
# Licensed under the Apache License, Version 2.0 (the "License");
# you may not use this file except in compliance with the License.
# You may obtain a copy of the License at
#
# http://www.apache.org/licenses/LICENSE-2.0
#
# Unless required by applicable law or agreed to in writing, software
# distributed under the License is distributed on an "AS IS" BASIS,
# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
# See the License for the specific language governing permissions and
# limitations under the License.
#
"""Analyze block trace"""
import collections
import os
import re
import string
import sys
# ex) <...>-52 [001] ...1 1.362574: block_bio_queue: 8,16 R 0 + 8 [kworker/u8:1]
RE_BLOCK = r'.+-([0-9]+).*\s+([0-9]+\.[0-9]+):\s+block_bio_queue:\s+([0-9]+)\,([0-9]+)\s(\S+)\s+([0-9]+)\s+\+\s+([0-9]+)\s+\[([^\]]+)'
# ex) <...>-453 [001] d..4 3.181854: sched_blocked_reason: pid=471 iowait=1 caller=__wait_on_buffer+0x24/0x2c
RE_SCHED_BLOCKED_READSON = r'.+-([0-9]+)\s+\[([0-9]+)\]\s.*\s+([0-9]+\.[0-9]+):\s+sched_blocked_reason:\spid=([0-9]+)\siowait=([01])\scaller=(\S+)'
# ex) <idle>-0 [000] d..3 3.181864: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=ueventd next_pid=471 next_prio=120
RE_SCHED_SWITCH = r'.+-([0-9]+)\s+\[([0-9]+)\]\s.*\s+([0-9]+\.[0-9]+):\s+sched_switch:\sprev_comm=(.+)\sprev_pid=([0-9]+)\sprev_prio=([0-9]+)\sprev_state=(\S+).*next_comm=(.+)\snext_pid=([0-9]+)\snext_prio=([0-9]+)'
# dev_num = major * MULTIPLIER + minor
DEV_MAJOR_MULTIPLIER = 1000
# dm access is remapped to disk access. So account differently
DM_MAJOR = 253
MAX_PROCESS_DUMP = 10
class RwEvent:
def __init__(self, block_num, start_time, size):
self.block_num = block_num
self.start_time = start_time
self.size = size
def get_string_pos(strings, string_to_find):
for i, s in enumerate(strings):
if s == string_to_find:
return i
return -1
class ProcessData:
def __init__(self, name):
self.name = name
self.reads = {} # k : dev_num, v : [] of reads
self.per_device_total_reads = {}
self.writes = {}
self.per_device_total_writes = {}
self.total_reads = 0
self.total_writes = 0
self.total_dm_reads = 0
self.total_dm_writes = 0
def add_read_event(self, major, minor, event):
devNum = major * DEV_MAJOR_MULTIPLIER + minor;
events = self.reads.get(devNum)
if not events:
events = []
self.reads[devNum] = events
self.per_device_total_reads[devNum] = 0
events.append(event)
self.total_reads += event.size
self.per_device_total_reads[devNum] += event.size
def add_write_event(self, major, minor, event):
devNum = major * DEV_MAJOR_MULTIPLIER + minor;
events = self.writes.get(devNum)
if not events:
events = []
self.writes[devNum] = events
self.per_device_total_writes[devNum] = 0
events.append(event)
self.total_writes += event.size
self.per_device_total_writes[devNum] += event.size
def add_dm_read(self, size):
self.total_dm_reads += size
def add_dm_write(self, size):
self.total_dm_writes += size
def dump(self):
print "Process,", self.name
print " total reads,", self.total_reads
print " total writes,", self.total_writes
print " total dm reads,", self.total_dm_reads
print " total dm writes,", self.total_dm_writes
print " R per device"
sorted_r = collections.OrderedDict(sorted(self.per_device_total_reads.items(), \
key = lambda item: item[1], reverse = True))
for i in range(len(sorted_r)):
dev = sorted_r.popitem(last=False)
print " ", dev[0],dev[1]
print " W per device"
sorted_w = collections.OrderedDict(sorted(self.per_device_total_writes.items(), \
key = lambda item: item[1], reverse = True))
for i in range(len(sorted_w)):
dev = sorted_w.popitem(last=False)
print " ", dev[0],dev[1]
class IoTrace:
def __init__(self):
self.ios = {} #K: process name, v:ProcessData
self.total_reads = 0
self.total_writes = 0
self.total_reads_per_device = {} #K: block num, V: total blocks
self.total_writes_per_device = {}
self.total_dm_reads = {} #K: devnum, V: blocks
self.total_dm_writes = {}
self.re_block = re.compile(RE_BLOCK)
def parse(self, l):
match = self.re_block.match(l)
if not match:
return False
try:
self.do_parse_bio_queue(l, match)
except ValueError:
print "cannot parse:", l
raise
return True
def do_parse_bio_queue(self, l, match):
pid = match.group(1)
start_time = float(match.group(2))*1000 #ms
major = int(match.group(3))
minor = int(match.group(4))
devNum = major * DEV_MAJOR_MULTIPLIER + minor;
operation = match.group(5)
block_num = int(match.group(6))
size = int(match.group(7))
process = match.group(8) + "-" + pid
event = RwEvent(block_num, start_time, size)
io = self.ios.get(process)
if not io:
io = ProcessData(process)
self.ios[process] = io
if major == DM_MAJOR:
devNum = major * DEV_MAJOR_MULTIPLIER + minor;
if 'R' in operation[0]:
if devNum not in self.total_dm_reads:
self.total_dm_reads[devNum] = 0
self.total_dm_reads[devNum] += size
io.add_dm_read(size)
elif 'W' in operation[0]:
if devNum not in self.total_dm_writes:
self.total_dm_writes[devNum] = 0
self.total_dm_writes[devNum] += size
io.add_dm_write(size)
return
if 'R' in operation[0]:
io.add_read_event(major, minor, event)
self.total_reads += size
per_device = self.total_reads_per_device.get(devNum)
if not per_device:
self.total_reads_per_device[devNum] = 0
self.total_reads_per_device[devNum] += size
elif 'W' in operation[0]:
io.add_write_event(major, minor, event)
self.total_writes += size
per_device = self.total_writes_per_device.get(devNum)
if not per_device:
self.total_writes_per_device[devNum] = 0
self.total_writes_per_device[devNum] += size
def dump(self):
print "total read blocks,", self.total_reads
print "total write blocks,", self.total_writes
print "Total DM R"
for dev,size in self.total_dm_reads.items():
print dev, size
print "Total DM W"
for dev,size in self.total_dm_writes.items():
print dev, size
print "**Process total R/W"
sorted_by_total_rw = collections.OrderedDict(sorted(self.ios.items(), \
key = lambda item: item[1].total_reads + item[1].total_writes, reverse = True))
for i in range(MAX_PROCESS_DUMP):
process = sorted_by_total_rw.popitem(last=False)
if not process:
break
process[1].dump()
print "**Process total W"
sorted_by_total_w = collections.OrderedDict(sorted(self.ios.items(), \
key = lambda item: item[1].total_writes, reverse = True))
for i in range(5):
process = sorted_by_total_w.popitem(last=False)
if not process:
break
process[1].dump()
print "**Device total R"
sorted_by_total_r = collections.OrderedDict(sorted(self.total_reads_per_device.items(), \
key = lambda item: item[1], reverse = True))
for i in range(len(sorted_by_total_r)):
dev = sorted_by_total_r.popitem(last=False)
print dev[0],dev[1]
print "**Device total W"
sorted_by_total_w = collections.OrderedDict(sorted(self.total_writes_per_device.items(), \
key = lambda item: item[1], reverse = True))
for i in range(len(sorted_by_total_w)):
dev = sorted_by_total_w.popitem(last=False)
print dev[0],dev[1]
class SchedProcess:
def __init__(self, pid):
self.pid = pid
self.name = "unknown"
self.total_execution_time = 0.0
self.total_io_wait_time = 0.0
self.total_other_wait_time = 0.0
self.waiting_calls = {} # k: waiting_call, v : waiting counter
self.io_waiting_call_times = {} # k: waiting_call, v: total wait time
self.in_iowait = False
self.last_waiting_call = None
self.last_switch_out_time = 0.0
self.last_switch_in_time = 0.0
self.last_core = -1
self.execution_time_per_core = {} # k: core, v : time
self.io_latency_histograms = {} # k : delay in ms, v : count
def handle_reason(self, current_time, iowait, waiting_call):
#if self.pid == 1232:
# print current_time, iowait, waiting_call
if iowait == 1:
self.in_iowait = True
self.last_waiting_call = waiting_call
call_counter = self.waiting_calls.get(waiting_call, 0)
call_counter += 1
self.waiting_calls[waiting_call] = call_counter
def handle_switch_out(self, current_time, out_state, priority, name, core):
#if self.pid == 1232:
# print "out", current_time, out_state
if self.name != name:
self.name = name
self.last_switch_out_time = current_time
if self.last_switch_in_time == 0.0: # switch in not recorded. ignore this one
return
execution_time = current_time - self.last_switch_in_time
self.total_execution_time += execution_time
core_execution_time = self.execution_time_per_core.get(core, 0.0)
core_execution_time += execution_time
self.execution_time_per_core[core] = core_execution_time
def handle_switch_in(self, current_time, priority, name, core):
#if self.pid == 1232:
# print "in", current_time, self.in_iowait
if self.name != name:
self.name = name
self.last_switch_in_time = current_time
if self.last_switch_out_time == 0.0: # in without out, probably 1st
self.in_iowait = False
return
wait_time = current_time - self.last_switch_out_time
if self.in_iowait:
self.total_io_wait_time += wait_time
total_waiting_call_time = self.io_waiting_call_times.get(self.last_waiting_call, 0.0)
total_waiting_call_time += wait_time
self.io_waiting_call_times[self.last_waiting_call] = total_waiting_call_time
wait_time_ms = int(wait_time*10) / 10.0 # resolution up to 0.1 ms
histogram_count = self.io_latency_histograms.get(wait_time_ms, 0)
histogram_count += 1
self.io_latency_histograms[wait_time_ms] = histogram_count
else:
self.total_other_wait_time += wait_time
self.in_iowait = False
def dump(self):
print "PID:", self.pid, " name:", self.name
print " total execution time:", self.total_execution_time,\
" io wait:", self.total_io_wait_time, " other wait:", self.total_other_wait_time
sorted_data = collections.OrderedDict(sorted(self.execution_time_per_core.items(), \
key = lambda item: item[0], reverse = False))
print " Core execution:", sorted_data
sorted_data = collections.OrderedDict(sorted(self.waiting_calls.items(), \
key = lambda item: item[1], reverse = True))
print " Wait calls:", sorted_data
sorted_data = collections.OrderedDict(sorted(self.io_waiting_call_times.items(), \
key = lambda item: item[1], reverse = True))
print " IO Wait time per wait calls:", sorted_data
sorted_data = collections.OrderedDict(sorted(self.io_latency_histograms.items(), \
key = lambda item: item[0], reverse = False))
print " Wait time histogram:", sorted_data
class SchedTrace:
def __init__(self):
self.re_switch = re.compile(RE_SCHED_SWITCH)
self.re_reason = re.compile(RE_SCHED_BLOCKED_READSON)
self.processes = {} # key: pid, v : SchedProcess
def parse(self, l):
checked_reason = False
match = self.re_switch.match(l)
if not match:
match = self.re_reason.match(l)
checked_reason = True
if not match:
return False
try:
if checked_reason:
self.do_handle_reason(l, match)
else:
self.do_handle_switch(l, match)
except ValueError:
print "cannot parse:", l
raise
return True
def do_handle_switch(self, l, match):
current_pid = int(match.group(1))
cpu_core = int(match.group(2))
current_time = float(match.group(3))*1000 #ms
out_name = match.group(4)
out_pid = int(match.group(5))
out_prio = int(match.group(6))
out_state = match.group(7)
in_name = match.group(8)
in_pid = int(match.group(9))
in_prio = int(match.group(10))
out_process = self.processes.get(out_pid)
if not out_process:
out_process = SchedProcess(out_pid)
self.processes[out_pid] = out_process
in_process = self.processes.get(in_pid)
if not in_process:
in_process = SchedProcess(in_pid)
self.processes[in_pid] = in_process
out_process.handle_switch_out(current_time, out_state, out_prio, out_name, cpu_core)
in_process.handle_switch_in(current_time, in_prio, in_name, cpu_core)
def do_handle_reason(self, l, match):
current_pid = int(match.group(1))
cpu_core = int(match.group(2))
current_time = float(match.group(3))*1000 #ms
pid = int(match.group(4))
iowait = int(match.group(5))
waiting_call = match.group(6)
process = self.processes.get(pid)
if not process:
process = SchedProcess(pid)
self.processes[pid] = process
process.handle_reason(current_time, iowait, waiting_call)
def dump(self):
sorted_by_total_execution = collections.OrderedDict(sorted(self.processes.items(), \
key = lambda item: item[1].total_io_wait_time, reverse = True))
for k, v in sorted_by_total_execution.iteritems():
if v.total_execution_time > 10.0 or v.total_io_wait_time != 0.0:
v.dump()
def main(argv):
if (len(argv) < 2):
print "check_io_trace_all.py filename"
return
filename = argv[1]
io_trace = IoTrace()
sched_trace = SchedTrace()
with open(filename) as f:
for l in f:
if io_trace.parse(l):
continue
sched_trace.parse(l)
io_trace.dump()
print "\n\n\n"
sched_trace.dump()
if __name__ == '__main__':
main(sys.argv)
|