GeezerVison is showing github.com — bcc/tools/ext4slower.py at master · CentUser/bcc

Expand file tree

ext4slower.py

Copy path

More file actions

Latest commit

History

executable file

347 lines (299 loc) · 9.44 KB

ext4slower.py

Copy path

File metadata and controls

executable file

347 lines (299 loc) · 9.44 KB

Raw

Copy raw file

Download raw file

Open symbols panel

Edit and raw actions

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

#!/usr/bin/python

# @lint-avoid-python-3-compatibility-imports

# ext4slower Trace slow ext4 operations.

# For Linux, uses BCC, eBPF.

# USAGE: ext4slower [-h] [-j] [-p PID] [min_ms]

# This script traces common ext4 file operations: reads, writes, opens, and

# syncs. It measures the time spent in these operations, and prints details

# for each that exceeded a threshold.

# WARNING: This adds low-overhead instrumentation to these ext4 operations,

# including reads and writes from the file system cache. Such reads and writes

# can be very frequent (depending on the workload; eg, 1M/sec), at which

# point the overhead of this tool (even if it prints no "slower" events) can

# begin to become significant.

# By default, a minimum millisecond threshold of 10 is used.

# Licensed under the Apache License, Version 2.0 (the "License")

# 11-Feb-2016 Brendan Gregg Created this.

# 15-Oct-2016 Dina Goldshtein -p to filter by process ID.

from __future__ import print_function

from bcc import BPF

import argparse

from time import strftime

import ctypes as ct

# symbols

kallsyms = "/proc/kallsyms"

# arguments

examples = """examples:

./ext4slower # trace operations slower than 10 ms (default)

./ext4slower 1 # trace operations slower than 1 ms

./ext4slower -j 1 # ... 1 ms, parsable output (csv)

./ext4slower 0 # trace all operations (warning: verbose)

./ext4slower -p 185 # trace PID 185 only

"""

parser = argparse.ArgumentParser(

description="Trace common ext4 file operations slower than a threshold",

formatter_class=argparse.RawDescriptionHelpFormatter,

epilog=examples)

parser.add_argument("-j", "--csv", action="store_true",

help="just print fields: comma-separated values")

parser.add_argument("-p", "--pid",

help="trace this PID only")

parser.add_argument("min_ms", nargs="?", default='10',

help="minimum I/O duration to trace, in ms (default 10)")

parser.add_argument("--ebpf", action="store_true",

help=argparse.SUPPRESS)

args = parser.parse_args()

min_ms = int(args.min_ms)

pid = args.pid

csv = args.csv

debug = 0

# define BPF program

bpf_text = """

#include <uapi/linux/ptrace.h>

#include <linux/fs.h>

#include <linux/sched.h>

#include <linux/dcache.h>

// XXX: switch these to char's when supported

#define TRACE_READ 0

#define TRACE_WRITE 1

#define TRACE_OPEN 2

#define TRACE_FSYNC 3

struct val_t {

u64 ts;

u64 offset;

struct file *fp;

};

struct data_t {

// XXX: switch some to u32's when supported

u64 ts_us;

u64 type;

u64 size;

u64 offset;

u64 delta_us;

u64 pid;

char task[TASK_COMM_LEN];

char file[DNAME_INLINE_LEN];

};

BPF_HASH(entryinfo, u64, struct val_t);

BPF_PERF_OUTPUT(events);

// Store timestamp and size on entry

// The current ext4 (Linux 4.5) uses generic_file_read_iter(), instead of it's

// own function, for reads. So we need to trace that and then filter on ext4,

// which I do by checking file->f_op.

int trace_read_entry(struct pt_regs *ctx, struct kiocb *iocb)

{

u64 id = bpf_get_current_pid_tgid();

u32 pid = id >> 32; // PID is higher part

if (FILTER_PID)

return 0;

// ext4 filter on file->f_op == ext4_file_operations

struct file *fp = iocb->ki_filp;

if ((u64)fp->f_op != EXT4_FILE_OPERATIONS)

return 0;

// store filep and timestamp by id

struct val_t val = {};

val.ts = bpf_ktime_get_ns();

val.fp = fp;

val.offset = iocb->ki_pos;

if (val.fp)

entryinfo.update(&id, &val);

return 0;

}

// ext4_file_write_iter():

int trace_write_entry(struct pt_regs *ctx, struct kiocb *iocb)

{

u64 id = bpf_get_current_pid_tgid();

u32 pid = id >> 32; // PID is higher part

if (FILTER_PID)

return 0;

// store filep and timestamp by id

struct val_t val = {};

val.ts = bpf_ktime_get_ns();

val.fp = iocb->ki_filp;

val.offset = iocb->ki_pos;

if (val.fp)

entryinfo.update(&id, &val);

return 0;

}

// ext4_file_open():

int trace_open_entry(struct pt_regs *ctx, struct inode *inode,

struct file *file)

{

u64 id = bpf_get_current_pid_tgid();

u32 pid = id >> 32; // PID is higher part

if (FILTER_PID)

return 0;

// store filep and timestamp by id

struct val_t val = {};

val.ts = bpf_ktime_get_ns();

val.fp = file;

val.offset = 0;

if (val.fp)

entryinfo.update(&id, &val);

return 0;

}

// ext4_sync_file():

int trace_fsync_entry(struct pt_regs *ctx, struct file *file)

{

u64 id = bpf_get_current_pid_tgid();

u32 pid = id >> 32; // PID is higher part

if (FILTER_PID)

return 0;

// store filep and timestamp by id

struct val_t val = {};

val.ts = bpf_ktime_get_ns();

val.fp = file;

val.offset = 0;

if (val.fp)

entryinfo.update(&id, &val);

return 0;

}

// Output

static int trace_return(struct pt_regs *ctx, int type)

{

struct val_t *valp;

u64 id = bpf_get_current_pid_tgid();

u32 pid = id >> 32; // PID is higher part

valp = entryinfo.lookup(&id);

if (valp == 0) {

// missed tracing issue or filtered

return 0;

}

// calculate delta

u64 ts = bpf_ktime_get_ns();

u64 delta_us = (ts - valp->ts) / 1000;

entryinfo.delete(&id);

if (FILTER_US)

return 0;

// populate output struct

u32 size = PT_REGS_RC(ctx);

struct data_t data = {.type = type, .size = size, .delta_us = delta_us,

.pid = pid};

data.ts_us = ts / 1000;

data.offset = valp->offset;

bpf_get_current_comm(&data.task, sizeof(data.task));

// workaround (rewriter should handle file to d_name in one step):

struct dentry *de = NULL;

struct qstr qs = {};

de = valp->fp->f_path.dentry;

qs = de->d_name;

if (qs.len == 0)

return 0;

bpf_probe_read(&data.file, sizeof(data.file), (void *)qs.name);

// output

events.perf_submit(ctx, &data, sizeof(data));

return 0;

}

int trace_read_return(struct pt_regs *ctx)

{

return trace_return(ctx, TRACE_READ);

}

int trace_write_return(struct pt_regs *ctx)

{

return trace_return(ctx, TRACE_WRITE);

}

int trace_open_return(struct pt_regs *ctx)

{

return trace_return(ctx, TRACE_OPEN);

}

int trace_fsync_return(struct pt_regs *ctx)

{

return trace_return(ctx, TRACE_FSYNC);

}

"""

# code replacements

with open(kallsyms) as syms:

ops = ''

for line in syms:

(addr, size, name) = line.rstrip().split(" ", 2)

name = name.split("\t")[0]

if name == "ext4_file_operations":

ops = "0x" + addr

break

if ops == '':

print("ERROR: no ext4_file_operations in /proc/kallsyms. Exiting.")

print("HINT: the kernel should be built with CONFIG_KALLSYMS_ALL.")

exit()

bpf_text = bpf_text.replace('EXT4_FILE_OPERATIONS', ops)

if min_ms == 0:

bpf_text = bpf_text.replace('FILTER_US', '0')

else:

bpf_text = bpf_text.replace('FILTER_US',

'delta_us <= %s' % str(min_ms * 1000))

if args.pid:

bpf_text = bpf_text.replace('FILTER_PID', 'pid != %s' % pid)

else:

bpf_text = bpf_text.replace('FILTER_PID', '0')

if debug or args.ebpf:

print(bpf_text)

if args.ebpf:

exit()

# kernel->user event data: struct data_t

DNAME_INLINE_LEN = 32 # linux/dcache.h

TASK_COMM_LEN = 16 # linux/sched.h

class Data(ct.Structure):

_fields_ = [

("ts_us", ct.c_ulonglong),

("type", ct.c_ulonglong),

("size", ct.c_ulonglong),

("offset", ct.c_ulonglong),

("delta_us", ct.c_ulonglong),

("pid", ct.c_ulonglong),

("task", ct.c_char * TASK_COMM_LEN),

("file", ct.c_char * DNAME_INLINE_LEN)

]

# process event

def print_event(cpu, data, size):

event = ct.cast(data, ct.POINTER(Data)).contents

type = 'R'

if event.type == 1:

type = 'W'

elif event.type == 2:

type = 'O'

elif event.type == 3:

type = 'S'

if (csv):

print("%d,%s,%d,%s,%d,%d,%d,%s" % (

event.ts_us, event.task.decode(), event.pid, type, event.size,

event.offset, event.delta_us, event.file.decode()))

return

print("%-8s %-14.14s %-6s %1s %-7s %-8d %7.2f %s" % (strftime("%H:%M:%S"),

event.task.decode(), event.pid, type, event.size, event.offset / 1024,

float(event.delta_us) / 1000, event.file.decode()))

# initialize BPF

b = BPF(text=bpf_text)

# Common file functions. See earlier comment about generic_file_read_iter().

b.attach_kprobe(event="generic_file_read_iter", fn_name="trace_read_entry")

b.attach_kprobe(event="ext4_file_write_iter", fn_name="trace_write_entry")

b.attach_kprobe(event="ext4_file_open", fn_name="trace_open_entry")

b.attach_kprobe(event="ext4_sync_file", fn_name="trace_fsync_entry")

b.attach_kretprobe(event="generic_file_read_iter", fn_name="trace_read_return")

b.attach_kretprobe(event="ext4_file_write_iter", fn_name="trace_write_return")

b.attach_kretprobe(event="ext4_file_open", fn_name="trace_open_return")

b.attach_kretprobe(event="ext4_sync_file", fn_name="trace_fsync_return")

# header

if (csv):

print("ENDTIME_us,TASK,PID,TYPE,BYTES,OFFSET_b,LATENCY_us,FILE")

else:

if min_ms == 0:

print("Tracing ext4 operations")

else:

print("Tracing ext4 operations slower than %d ms" % min_ms)

print("%-8s %-14s %-6s %1s %-7s %-8s %7s %s" % ("TIME", "COMM", "PID", "T",

"BYTES", "OFF_KB", "LAT(ms)", "FILENAME"))

# read events

b["events"].open_perf_buffer(print_event, page_cnt=64)

while 1:

b.perf_buffer_poll()