ioblame: IO tracer with origin tracking

RFC PATCH Superseded Tejun Heo 7 participants 37 messages Jan 10, 2012 – Jan 17, 2012

Subsystems (8)

Memory management Documentation x86 VFS +4 more subsystems

lore

Share & tools

lore

Tejun Heo

author

2012-01-10 18:28 UTC #0 lore raw

RFC PATCH 1/1 ioblame: IO tracer with origin tracking

Hello, guys.

Even with blktrace and tracepoints, getting insight into the IOs going on a system is very challenging. A lot of IO operations happen long after the action which triggered the IO finished and the overall asynchronous nature of IO operations make it difficult to trace back the origin of a given IO.

ioblame is an attempt at providing better visibility into overall IO behavior. ioblame hooks into various tracepoints and tries to determine who caused any given IO how and charges the IO accordingly.

On each IO completion, ioblame knows who to charge the IO (task), how the IO got triggered (stack trace at the point of triggering, be it page, inode dirtying or direct IO issue) and various information about the IO itself (offset, size, how long it took and so on). ioblame exports this information via ioblame:ioblame_io tracepoint.

For more details, please read Documentation/trace/ioblame.txt.

Changes from the last take[L] are,

* Per Namhyung's suggestion, in-kernel statistics gathering stripped out. All information is now exported through a tracepoint per each IO. This makes a lot of stuff unnecessary and over 1500 lines of code have been removed.

* block_bio_complete tracepoint patch will result in duplicate BLK_TA_COMPLETE notifications. Namhyung is working on proper solution. For now, SOB is removed from the patch.

* Trace filter is no longer used and patches dropped from the series.

* Rebased on top of v3.2.

This patchset contains the following 9 patches.

0001-block-abstract-disk-iteration-into-disk_iter.patch 0002-block-block_bio_complete-tracepoint-was-missing.patch 0003-block-add-req-to-bio_-front-back-_merge-tracepoints.patch 0004-writeback-move-struct-wb_writeback_work-to-writeback.patch 0005-writeback-add-more-tracepoints.patch 0006-block-add-block_touch_buffer-tracepoint.patch 0007-vfs-add-fcheck-tracepoint.patch 0008-stacktrace-implement-save_stack_trace_quick.patch 0009-block-trace-implement-ioblame-IO-tracer-with-origin-.patch

0001-0004 update block layer in preparation.

0005-0007 add more tracepoints along the IO stack.

0008 adds nimbler backtrace dump function as ioblame dumps stacktrace extremely frequently.

0009 implements ioblame.

This is still in early stage and I haven't done much performance analysis yet. Tentative testing shows it adds ~20% CPU overhead when used on memory backed loopback device.

The patches are on top of v3.2 and available in the following git branch.

git://git.kernel.org/pub/scm/linux/kernel/git/tj/misc.git review-ioblame

diffstat follows.

 Documentation/trace/ioblame.txt   |  476 +++++++
 arch/x86/include/asm/stacktrace.h |    2 
 arch/x86/kernel/stacktrace.c      |   40 
 block/blk-core.c                  |    5 
 block/genhd.c                     |   98 +
 fs/bio.c                          |    3 
 fs/fs-writeback.c                 |   34 
 fs/super.c                        |    2 
 include/linux/blk_types.h         |    4 
 include/linux/buffer_head.h       |    7 
 include/linux/fdtable.h           |    3 
 include/linux/fs.h                |    3 
 include/linux/genhd.h             |   13 
 include/linux/ioblame.h           |   72 +
 include/linux/stacktrace.h        |    6 
 include/linux/writeback.h         |   18 
 include/trace/events/block.h      |   70 -
 include/trace/events/vfs.h        |   40 
 include/trace/events/writeback.h  |  113 +
 kernel/stacktrace.c               |    6 
 kernel/trace/Kconfig              |   12 
 kernel/trace/Makefile             |    1 
 kernel/trace/blktrace.c           |    2 
 kernel/trace/ioblame.c            | 2279 ++++++++++++++++++++++++++++++++++++++
 mm/page-writeback.c               |    2 
 25 files changed, 3244 insertions(+), 67 deletions(-)

Thanks.

--
tejun

[L] http://thread.gmane.org/gmane.linux.kernel/1235937

Tejun Heo

author

2012-01-10 18:28 UTC #1 lore raw

PATCH 1/9 block: abstract disk iteration into disk_iter

Instead of using class_dev_iter directly, abstract disk iteration into disk_iter and helpers which are exported. This simplifies the callers a bit and allows external users to iterate over disks.

Signed-off-by Tejun Heo <[email protected]>

---
 block/genhd.c         |   98 +++++++++++++++++++++++++++++++++----------------
 include/linux/genhd.h |   10 ++++-
 2 files changed, 75 insertions(+), 33 deletions(-)

block/genhd.c +66 ~~-32~~

index 83e7c04..7c811ff 100644
@@ -40,6 +40,47 @@ static void disk_del_events(struct gendisk *disk);
 static void disk_release_events(struct gendisk *disk);
 
 /**
+ * disk_iter_init - initialize disk iterator
+ * @diter: iterator to initialize
+ *
+ * Initialize @diter so that it iterates over all disks
+ */
+void disk_iter_init(struct disk_iter *diter)
+{
+	class_dev_iter_init(&diter->cdev_iter, &block_class, NULL, &disk_type);
+}
+EXPORT_SYMBOL_GPL(disk_iter_init);
+
+/**
+ * disk_iter_next - proceed iterator to the next disk and return it
+ * @diter: iterator to proceed
+ *
+ * Proceed @diter to the next disk and return it.
+ */
+struct gendisk *disk_iter_next(struct disk_iter *diter)
+{
+	struct device *dev;
+
+	dev = class_dev_iter_next(&diter->cdev_iter);
+	if (dev)
+		return dev_to_disk(dev);
+	return NULL;
+}
+EXPORT_SYMBOL_GPL(disk_iter_next);
+
+/**
+ * disk_iter_exit - finish up disk iteration
+ * @diter: iter to exit
+ *
+ * Called when iteration is over.  Cleans up @diter.
+ */
+void disk_iter_exit(struct disk_iter *diter)
+{
+	class_dev_iter_exit(&diter->cdev_iter);
+}
+EXPORT_SYMBOL_GPL(disk_iter_exit);
+
+/**
  * disk_get_part - get partition
  * @disk: disk to look partition from
  * @partno: partition number

@@ -730,12 +771,11 @@ EXPORT_SYMBOL(bdget_disk);
  */
 void __init printk_all_partitions(void)
 {
-	struct class_dev_iter iter;
-	struct device *dev;
+	struct disk_iter diter;
+	struct gendisk *disk;
 
-	class_dev_iter_init(&iter, &block_class, NULL, &disk_type);
-	while ((dev = class_dev_iter_next(&iter))) {
-		struct gendisk *disk = dev_to_disk(dev);
+	disk_iter_init(&diter);
+	while ((disk = disk_iter_next(&diter))) {
 		struct disk_part_iter piter;
 		struct hd_struct *part;
 		char name_buf[BDEVNAME_SIZE];

@@ -779,7 +819,7 @@ void __init printk_all_partitions(void)
 		}
 		disk_part_iter_exit(&piter);
 	}
-	class_dev_iter_exit(&iter);
+	disk_iter_exit(&diter);
 }
 
 #ifdef CONFIG_PROC_FS

@@ -787,44 +827,38 @@ void __init printk_all_partitions(void)
 static void *disk_seqf_start(struct seq_file *seqf, loff_t *pos)
 {
 	loff_t skip = *pos;
-	struct class_dev_iter *iter;
-	struct device *dev;
+	struct disk_iter *diter;
+	struct gendisk *disk;
 
-	iter = kmalloc(sizeof(*iter), GFP_KERNEL);
-	if (!iter)
+	diter = kmalloc(sizeof(*diter), GFP_KERNEL);
+	if (!diter)
 		return ERR_PTR(-ENOMEM);
 
-	seqf->private = iter;
-	class_dev_iter_init(iter, &block_class, NULL, &disk_type);
+	seqf->private = diter;
+	disk_iter_init(diter);
 	do {
-		dev = class_dev_iter_next(iter);
-		if (!dev)
+		disk = disk_iter_next(diter);
+		if (!disk)
 			return NULL;
 	} while (skip--);
 
-	return dev_to_disk(dev);
+	return disk;
 }
 
 static void *disk_seqf_next(struct seq_file *seqf, void *v, loff_t *pos)
 {
-	struct device *dev;
-
 	(*pos)++;
-	dev = class_dev_iter_next(seqf->private);
-	if (dev)
-		return dev_to_disk(dev);
-
-	return NULL;
+	return disk_iter_next(seqf->private);
 }
 
 static void disk_seqf_stop(struct seq_file *seqf, void *v)
 {
-	struct class_dev_iter *iter = seqf->private;
+	struct disk_iter *diter = seqf->private;
 
 	/* stop is called even after start failed :-( */
-	if (iter) {
-		class_dev_iter_exit(iter);
-		kfree(iter);
+	if (diter) {
+		disk_iter_exit(diter);
+		kfree(diter);
 	}
 }

@@ -1206,12 +1240,12 @@ module_init(proc_genhd_init);
 dev_t blk_lookup_devt(const char *name, int partno)
 {
 	dev_t devt = MKDEV(0, 0);
-	struct class_dev_iter iter;
-	struct device *dev;
+	struct disk_iter diter;
+	struct gendisk *disk;
 
-	class_dev_iter_init(&iter, &block_class, NULL, &disk_type);
-	while ((dev = class_dev_iter_next(&iter))) {
-		struct gendisk *disk = dev_to_disk(dev);
+	disk_iter_init(&diter);
+	while ((disk = disk_iter_next(&diter))) {
+		struct device *dev = disk_to_dev(disk);
 		struct hd_struct *part;
 
 		if (strcmp(dev_name(dev), name))

@@ -1233,7 +1267,7 @@ dev_t blk_lookup_devt(const char *name, int partno)
 		}
 		disk_put_part(part);
 	}
-	class_dev_iter_exit(&iter);
+	disk_iter_exit(&diter);
 	return devt;
 }
 EXPORT_SYMBOL(blk_lookup_devt);

include/linux/genhd.h +9 -1

index fe23ee7..9d0e0b5 100644
@@ -260,8 +260,16 @@ static inline void disk_put_part(struct hd_struct *part)
 }
 
 /*
- * Smarter partition iterator without context limits.
+ * Smarter disk and partition iterators without context limits.
  */
+struct disk_iter {
+	struct class_dev_iter	cdev_iter;
+};
+
+extern void disk_iter_init(struct disk_iter *diter);
+extern struct gendisk *disk_iter_next(struct disk_iter *diter);
+extern void disk_iter_exit(struct disk_iter *diter);
+
 #define DISK_PITER_REVERSE	(1 << 0) /* iterate in the reverse direction */
 #define DISK_PITER_INCL_EMPTY	(1 << 1) /* include 0-sized parts */
 #define DISK_PITER_INCL_PART0	(1 << 2) /* include partition 0 */

Signature · 1 line

1.7.3.1

Tejun Heo

author

2012-01-10 18:28 UTC #2 lore raw

PATCH 2/9 block: block_bio_complete tracepoint was missing

In reply to Tejun Heo

block_bio_complete tracepoint was defined but not invoked anywhere. Fix it.

-tj: This will generate duplicate BLK_TA_COMPLETEs. Namhyung is
working on proper solution.

DO_NOT_APPLY
Cc: Namhyung Kim <[email protected]>

---
 fs/bio.c |    3 +++
 1 files changed, 3 insertions(+), 0 deletions(-)

fs/bio.c +3 -0

index b1fe82c..96548da 100644
@@ -1447,6 +1447,9 @@ void bio_endio(struct bio *bio, int error)
 	else if (!test_bit(BIO_UPTODATE, &bio->bi_flags))
 		error = -EIO;
 
+	if (bio->bi_bdev)
+		trace_block_bio_complete(bdev_get_queue(bio->bi_bdev),
+					 bio, error);
 	if (bio->bi_end_io)
 		bio->bi_end_io(bio, error);
 }

Signature · 1 line

1.7.3.1

Steven Rostedt

maintainer

2012-01-11 17:25 UTC #3 lore raw

Re: [PATCH 2/9] block: block_bio_complete tracepoint was missing

Quoted 17 lines · Tejun Heo

block_bio_complete tracepoint was defined but not invoked anywhere. Fix it.
-tj: This will generate duplicate BLK_TA_COMPLETEs. Namhyung is
working on proper solution.
DO_NOT_APPLY
Cc: Namhyung Kim <[email protected]>
---
 fs/bio.c |    3 +++
 1 files changed, 3 insertions(+), 0 deletions(-)
fs/bio.c +0 -0
index b1fe82c..96548da 100644

fs/bio.c void bio_endio(struct bio *bio, int error) · line 1452

Quoted 6 lines

fs/bio.c +3 -0

@@ -1447,6 +1447,9 @@ void bio_endio(struct bio *bio, int error)
 	else if (!test_bit(BIO_UPTODATE, &bio->bi_flags))
 		error = -EIO;
 
+	if (bio->bi_bdev)
+		trace_block_bio_complete(bdev_get_queue(bio->bi_bdev),
+					 bio, error);

I thought I commented before about using TRACE_EVENT_CONDITIONAL() here. To remove that open coded branch.

-- Steve

Quoted 3 lines

fs/bio.c +0 -0

 	if (bio->bi_end_io)
 		bio->bi_end_io(bio, error);
 }

Tejun Heo

author

2012-01-11 17:30 UTC #4 lore raw

Re: [PATCH 2/9] block: block_bio_complete tracepoint was missing

Hello,

Quoted 21 lines · Steven Rostedt

Quoted 20 lines · Tejun Heo
block_bio_complete tracepoint was defined but not invoked anywhere. Fix it.
-tj: This will generate duplicate BLK_TA_COMPLETEs. Namhyung is
working on proper solution.
DO_NOT_APPLY
Cc: Namhyung Kim <[email protected]>
---
 fs/bio.c |    3 +++
 1 files changed, 3 insertions(+), 0 deletions(-)
fs/bio.c +0 -0
index b1fe82c..96548da 100644
@@ -1447,6 +1447,9 @@ void bio_endio(struct bio *bio, int error)
 	else if (!test_bit(BIO_UPTODATE, &bio->bi_flags))
 		error = -EIO;
 

Quoted 6 lines

fs/bio.c void bio_endio(struct bio *bio, int error) · line 1452
Quoted 3 lines
fs/bio.c +3 -0
+	if (bio->bi_bdev)
+		trace_block_bio_complete(bdev_get_queue(bio->bi_bdev),
+					 bio, error);
I thought I commented before about using TRACE_EVENT_CONDITIONAL() here. To remove that open coded branch.

Yeah but this particular patch is dead now so it's a bit pointless. ioblame:ioblame_io uses it FWIW. Namhyung, can you please consider using TRACE_EVENT_CONDITION() for you patches if applicable?

Thanks.

Signature · 1 line

tejun

Namhyung Kim

2012-01-12 00:24 UTC #5 lore raw

Re: [PATCH 2/9] block: block_bio_complete tracepoint was missing

Quoted 31 lines · Tejun Heo

Hello,
Quoted 21 lines · Steven Rostedt
Quoted 20 lines · Tejun Heo
block_bio_complete tracepoint was defined but not invoked anywhere. Fix it.
-tj: This will generate duplicate BLK_TA_COMPLETEs. Namhyung is
working on proper solution.
DO_NOT_APPLY
Cc: Namhyung Kim<[email protected]>
---
  fs/bio.c |    3 +++
  1 files changed, 3 insertions(+), 0 deletions(-)
fs/bio.c +0 -0
index b1fe82c..96548da 100644
@@ -1447,6 +1447,9 @@ void bio_endio(struct bio *bio, int error)
  	else if (!test_bit(BIO_UPTODATE,&bio->bi_flags))
  		error = -EIO;
 
Quoted 6 lines
fs/bio.c void bio_endio(struct bio *bio, int error) · line 1452
Quoted 3 lines
fs/bio.c +3 -0
+	if (bio->bi_bdev)
+		trace_block_bio_complete(bdev_get_queue(bio->bi_bdev),
+					 bio, error);
I thought I commented before about using TRACE_EVENT_CONDITIONAL() here. To remove that open coded branch.

Quoted 6 lines

Yeah but this particular patch is dead now so it's a bit pointless. ioblame:ioblame_io uses it FWIW. Namhyung, can you please consider using TRACE_EVENT_CONDITION() for you patches if applicable?
Thanks.

Sure, I'll apply it.

Thanks,
Namhyung Kim

Tejun Heo

author

2012-01-10 18:30 UTC #6 lore raw

PATCH 3/9 block: add @req to bio_{front|back}_merge tracepoints

In reply to Tejun Heo

bio_{front|back}_merge tracepoints report a bio merging into an existing request but didn't specify which request the bio is being merged into. Add @req to it. This makes it impossible to share the event template with block_bio_queue - split it out.

@req isn't used or exported to userland at this point and there is no userland visible behavior change. Later changes will make use of the extra parameter.

Signed-off-by Tejun Heo <[email protected]>

---
 block/blk-core.c             |    4 +-
 include/trace/events/block.h |   45 +++++++++++++++++++++++++++++++----------
 kernel/trace/blktrace.c      |    2 +
 3 files changed, 38 insertions(+), 13 deletions(-)

block/blk-core.c +2 -2

index 15de223..dd45d6e 100644
@@ -1179,7 +1179,7 @@ static bool bio_attempt_back_merge(struct request_queue *q, struct request *req,
 	if (!ll_back_merge_fn(q, req, bio))
 		return false;
 
-	trace_block_bio_backmerge(q, bio);
+	trace_block_bio_backmerge(q, req, bio);
 
 	if ((req->cmd_flags & REQ_FAILFAST_MASK) != ff)
 		blk_rq_set_mixed_merge(req);

@@ -1202,7 +1202,7 @@ static bool bio_attempt_front_merge(struct request_queue *q,
 	if (!ll_front_merge_fn(q, req, bio))
 		return false;
 
-	trace_block_bio_frontmerge(q, bio);
+	trace_block_bio_frontmerge(q, req, bio);
 
 	if ((req->cmd_flags & REQ_FAILFAST_MASK) != ff)
 		blk_rq_set_mixed_merge(req);

include/trace/events/block.h +34 ~~-11~~

87 lines not on this page · raw message

kernel/trace/blktrace.c +2 -0

index cdea7b5..c1c8c97 100644
@@ -797,6 +797,7 @@ static void blk_add_trace_bio_complete(void *ignore,
 
 static void blk_add_trace_bio_backmerge(void *ignore,
 					struct request_queue *q,
+					struct request *rq,
 					struct bio *bio)
 {
 	blk_add_trace_bio(q, bio, BLK_TA_BACKMERGE, 0);

@@ -804,6 +805,7 @@ static void blk_add_trace_bio_backmerge(void *ignore,
 
 static void blk_add_trace_bio_frontmerge(void *ignore,
 					 struct request_queue *q,
+					 struct request *rq,
 					 struct bio *bio)
 {
 	blk_add_trace_bio(q, bio, BLK_TA_FRONTMERGE, 0);

Signature · 1 line

1.7.3.1

Tejun Heo

author

2012-01-10 18:28 UTC #7 lore raw

PATCH 4/9 writeback: move struct wb_writeback_work to writeback.h

In reply to Tejun Heo

Move definition of struct wb_writeback_work from fs/fs-writeback.c to include/linux/writeback.h. This is to allow accessing fields from writeback tracepoint probes which live outside fs-writeback.c.

Signed-off-by Tejun Heo <[email protected]>

---
 fs/fs-writeback.c         |   18 ------------------
 include/linux/writeback.h |   18 ++++++++++++++++++
 2 files changed, 18 insertions(+), 18 deletions(-)

fs/fs-writeback.c +0 ~~-18~~

index e295150..a97cb49 100644
@@ -29,24 +29,6 @@
 #include "internal.h"
 
 /*
- * Passed into wb_writeback(), essentially a subset of writeback_control
- */
-struct wb_writeback_work {
-	long nr_pages;
-	struct super_block *sb;
-	unsigned long *older_than_this;
-	enum writeback_sync_modes sync_mode;
-	unsigned int tagged_writepages:1;
-	unsigned int for_kupdate:1;
-	unsigned int range_cyclic:1;
-	unsigned int for_background:1;
-	enum wb_reason reason;		/* why was writeback initiated? */
-
-	struct list_head list;		/* pending work list */
-	struct completion *done;	/* set if the caller waits */
-};
-
-/*
  * Include the creation of the trace points after defining the
  * wb_writeback_work structure so that the definition remains local to this
  * file.

include/linux/writeback.h +18 -0

index a378c29..10d22d1 100644
@@ -82,6 +82,24 @@ struct writeback_control {
 };
 
 /*
+ * Passed into wb_writeback(), essentially a subset of writeback_control
+ */
+struct wb_writeback_work {
+	long nr_pages;
+	struct super_block *sb;
+	unsigned long *older_than_this;
+	enum writeback_sync_modes sync_mode;
+	unsigned int tagged_writepages:1;
+	unsigned int for_kupdate:1;
+	unsigned int range_cyclic:1;
+	unsigned int for_background:1;
+	enum wb_reason reason;		/* why was writeback initiated? */
+
+	struct list_head list;		/* pending work list */
+	struct completion *done;	/* set if the caller waits */
+};
+
+/*
  * fs/fs-writeback.c
  */	
 struct bdi_writeback;

Signature · 1 line

1.7.3.1

Tejun Heo

author

2012-01-10 18:28 UTC #8 lore raw

PATCH 5/9 writeback: add more tracepoints

In reply to Tejun Heo

Add tracepoints for page dirtying, writeback_single_inode start, inode dirtying and writeback. For the latter two inode events, a pair of events are defined to denote start and end of the operations (the starting one has _start suffix and the one w/o suffix happens after the operation is complete). These inode ops are FS specific and can be non-trivial and having enclosing tracepoints is useful for external tracers.

This is part of tracepoint additions to improve visiblity into dirtying / writeback operations for io tracer and userland.

Signed-off-by Tejun Heo <[email protected]>

---
 fs/fs-writeback.c                |   16 +++++-
 include/trace/events/writeback.h |  113 ++++++++++++++++++++++++++++++++++++++
 mm/page-writeback.c              |    2 +
 3 files changed, 129 insertions(+), 2 deletions(-)

fs/fs-writeback.c +14 -2

index a97cb49..ace4a45 100644
@@ -298,8 +298,14 @@ static void queue_io(struct bdi_writeback *wb, struct wb_writeback_work *work)
 
 static int write_inode(struct inode *inode, struct writeback_control *wbc)
 {
-	if (inode->i_sb->s_op->write_inode && !is_bad_inode(inode))
-		return inode->i_sb->s_op->write_inode(inode, wbc);
+	int ret;
+
+	if (inode->i_sb->s_op->write_inode && !is_bad_inode(inode)) {
+		trace_writeback_write_inode_start(inode, wbc);
+		ret = inode->i_sb->s_op->write_inode(inode, wbc);
+		trace_writeback_write_inode(inode, wbc);
+		return ret;
+	}
 	return 0;
 }

@@ -380,6 +386,8 @@ writeback_single_inode(struct inode *inode, struct bdi_writeback *wb,
 	spin_unlock(&inode->i_lock);
 	spin_unlock(&wb->list_lock);
 
+	trace_writeback_single_inode_start(inode, wbc, nr_to_write);
+
 	ret = do_writepages(mapping, wbc);
 
 	/*

@@ -1037,8 +1045,12 @@ void __mark_inode_dirty(struct inode *inode, int flags)
 	 * dirty the inode itself
 	 */
 	if (flags & (I_DIRTY_SYNC | I_DIRTY_DATASYNC)) {
+		trace_writeback_dirty_inode_start(inode, flags);
+
 		if (sb->s_op->dirty_inode)
 			sb->s_op->dirty_inode(inode, flags);
+
+		trace_writeback_dirty_inode(inode, flags);
 	}
 
 	/*

include/trace/events/writeback.h +113 -0

125 lines not on this page · raw message

mm/page-writeback.c +2 -0

index 8616ef3..4cf8c6d9 100644
@@ -1735,6 +1735,8 @@ int __set_page_dirty_no_writeback(struct page *page)
  */
 void account_page_dirtied(struct page *page, struct address_space *mapping)
 {
+	trace_writeback_dirty_page(page, mapping);
+
 	if (mapping_cap_account_dirty(mapping)) {
 		__inc_zone_page_state(page, NR_FILE_DIRTY);
 		__inc_zone_page_state(page, NR_DIRTIED);

Signature · 1 line

1.7.3.1

Tejun Heo

author

2012-01-10 18:29 UTC #9 lore raw

PATCH 6/9 block: add block_touch_buffer tracepoint

In reply to Tejun Heo

Add block_touch_buffer tracepoint which gets triggered on touch_buffer().

Because touch_buffer() is defined as macro in linux/buffer_head.h, this creates circular dependency between linux/buffer_head.h and events/block.h. As event header needs buffer_head details only when the tracepoints are actually created (CREATE_TRACE_POINTS is defined), this can be easily solved by including buffer_head.h before setting CREATE_TRACE_POINTS and including the event header to create tracepoints.

This is part of tracepoint additions to improve visiblity into dirtying / writeback operations for io tracer and userland.

Signed-off-by Tejun Heo <[email protected]>

---
 block/blk-core.c             |    1 +
 include/linux/buffer_head.h  |    7 ++++++-
 include/trace/events/block.h |   25 +++++++++++++++++++++++++
 3 files changed, 32 insertions(+), 1 deletions(-)

block/blk-core.c +1 -0

index dd45d6e..8f59db3 100644
@@ -29,6 +29,7 @@
 #include <linux/fault-inject.h>
 #include <linux/list_sort.h>
 #include <linux/delay.h>
+#include <linux/buffer_head.h>
 
 #define CREATE_TRACE_POINTS
 #include <trace/events/block.h>

include/linux/buffer_head.h +6 -1

index 458f497..245caed 100644
@@ -13,6 +13,7 @@
 #include <linux/pagemap.h>
 #include <linux/wait.h>
 #include <linux/atomic.h>
+#include <trace/events/block.h>
 
 #ifdef CONFIG_BLOCK

@@ -126,7 +127,11 @@ BUFFER_FNS(Write_EIO, write_io_error)
 BUFFER_FNS(Unwritten, unwritten)
 
 #define bh_offset(bh)		((unsigned long)(bh)->b_data & ~PAGE_MASK)
-#define touch_buffer(bh)	mark_page_accessed(bh->b_page)
+
+#define touch_buffer(bh)	do {				\
+		trace_block_touch_buffer(bh);			\
+		mark_page_accessed(bh->b_page);			\
+	} while (0)
 
 /* If we *know* page->private refers to buffer_heads */
 #define page_buffers(page)					\

include/trace/events/block.h +25 -0

index 983f8a8..4fcc09d 100644
@@ -6,10 +6,35 @@
 
 #include <linux/blktrace_api.h>
 #include <linux/blkdev.h>
+#include <linux/buffer_head.h>
 #include <linux/tracepoint.h>
 
 #define RWBS_LEN	8
 
+TRACE_EVENT(block_touch_buffer,
+
+	TP_PROTO(struct buffer_head *bh),
+
+	TP_ARGS(bh),
+
+	TP_STRUCT__entry (
+		__field(  dev_t,	dev			)
+		__field(  sector_t,	sector			)
+		__field(  size_t,	size			)
+	),
+
+	TP_fast_assign(
+		__entry->dev		= bh->b_bdev->bd_dev;
+		__entry->sector		= bh->b_blocknr;
+		__entry->size		= bh->b_size;
+	),
+
+	TP_printk("%d,%d get_bh sector=%llu size=%zu",
+		MAJOR(__entry->dev), MINOR(__entry->dev),
+		(unsigned long long)__entry->sector, __entry->size
+	)
+);
+
 DECLARE_EVENT_CLASS(block_rq_with_error,
 
 	TP_PROTO(struct request_queue *q, struct request *rq),

Signature · 1 line

1.7.3.1

Steven Rostedt

maintainer

2012-01-11 17:42 UTC #10 lore raw

Re: [PATCH 6/9] block: add block_touch_buffer tracepoint

include/linux/buffer_head.h line 16

Quoted 12 lines · Tejun Heo

#define CREATE_TRACE_POINTS
#include <trace/events/block.h>
include/linux/buffer_head.h +1 -0
index 458f497..245caed 100644
@@ -13,6 +13,7 @@
 #include <linux/pagemap.h>
 #include <linux/wait.h>
 #include <linux/atomic.h>
+#include <trace/events/block.h>

trace/events/x.h in a header can cause issue if this header is ever included in another trace/events/x.h header. I think I'll need to write a patch that allows this, but it wont be pretty.

-- Steve

Tejun Heo

author

2012-01-11 17:58 UTC #11 lore raw

Re: [PATCH 6/9] block: add block_touch_buffer tracepoint

Quoted 17 lines · Steven Rostedt

include/linux/buffer_head.h line 16
Quoted 12 lines · Tejun Heo
#define CREATE_TRACE_POINTS
#include <trace/events/block.h>
include/linux/buffer_head.h +1 -0
index 458f497..245caed 100644
@@ -13,6 +13,7 @@
 #include <linux/pagemap.h>
 #include <linux/wait.h>
 #include <linux/atomic.h>
+#include <trace/events/block.h>
trace/events/x.h in a header can cause issue if this header is ever included in another trace/events/x.h header. I think I'll need to write a patch that allows this, but it wont be pretty.

Hmmm... I see. I'll make touch_buffer() a function.

Thanks.

Signature · 1 line

tejun

Tejun Heo

author

2012-01-10 18:28 UTC #12 lore raw

PATCH 7/9 vfs: add fcheck tracepoint

In reply to Tejun Heo

All file accesses from userland go through fcheck to map fd to struct file, making it a very good location for peeking at what files userland is accessing. Add a tracepoint there.

This is part of tracepoint additions to improve visiblity into dirtying / writeback operations for io tracer and userland.

Signed-off-by Tejun Heo <[email protected]>

---
 fs/super.c                 |    2 ++
 include/linux/fdtable.h    |    3 +++
 include/trace/events/vfs.h |   40 ++++++++++++++++++++++++++++++++++++++++
 3 files changed, 45 insertions(+), 0 deletions(-)
 create mode 100644 include/trace/events/vfs.h

fs/super.c +2 -0

index de41e1e..3055f32 100644
@@ -34,6 +34,8 @@
 #include <linux/cleancache.h>
 #include "internal.h"
 
+#define CREATE_TRACE_POINTS
+#include <trace/events/vfs.h>
 
 LIST_HEAD(super_blocks);
 DEFINE_SPINLOCK(sb_lock);

include/linux/fdtable.h +3 -0

index 82163c4..72df04b 100644
@@ -12,6 +12,7 @@
 #include <linux/types.h>
 #include <linux/init.h>
 #include <linux/fs.h>
+#include <trace/events/vfs.h>
 
 #include <linux/atomic.h>

@@ -87,6 +88,8 @@ static inline struct file * fcheck_files(struct files_struct *files, unsigned in
 
 	if (fd < fdt->max_fds)
 		file = rcu_dereference_check_fdtable(files, fdt->fd[fd]);
+
+	trace_vfs_fcheck(files, fd, file);
 	return file;
 }

include/trace/events/vfs.h new file +40 -0

new file mode 100644
index 0000000..9a9bae4
@@ -0,0 +1,40 @@
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM vfs
+
+#if !defined(_TRACE_VFS_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_VFS_H
+
+#include <linux/tracepoint.h>
+#include <linux/fs.h>
+
+TRACE_EVENT(vfs_fcheck,
+
+	TP_PROTO(struct files_struct *files, unsigned int fd,
+		 struct file *file),
+
+	TP_ARGS(files, fd, file),
+
+	TP_STRUCT__entry(
+		__field(unsigned int,	fd)
+		__field(umode_t,	mode)
+		__field(dev_t,		dev)
+		__field(ino_t,		ino)
+	),
+
+	TP_fast_assign(
+		__entry->fd = fd;
+		__entry->mode = file ? file->f_path.dentry->d_inode->i_mode : 0;
+		__entry->dev = file ? file->f_path.dentry->d_inode->i_sb->s_dev : 0;
+		__entry->ino = file ? file->f_path.dentry->d_inode->i_ino : 0;
+	),
+
+	TP_printk("fd %u mode 0x%x dev %d,%d ino %lu",
+		  __entry->fd, __entry->mode,
+		  MAJOR(__entry->dev), MINOR(__entry->dev),
+		  (unsigned long)__entry->ino)
+);
+
+#endif /* _TRACE_VFS_H */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>

Signature · 1 line

1.7.3.1

Tejun Heo

author

2012-01-10 18:29 UTC #13 lore raw

PATCH 8/9 stacktrace: implement save_stack_trace_quick()

In reply to Tejun Heo

Implement save_stack_trace_quick() which only considers the usual contexts (ie. thread and irq) and doesn't handle links between different contexts - if %current is in irq context, only backtrace in the irq stack is considered.

This is subset of dump_trace() done in much simpler way. It's intended to be used in hot paths where the overhead of dump_trace() can be too heavy.

Signed-off-by Tejun Heo <[email protected]>

Cc Ingo Molnar <[email protected]>

Cc "H. Peter Anvin" <[email protected]>

---
 arch/x86/include/asm/stacktrace.h |    2 +
 arch/x86/kernel/stacktrace.c      |   40 +++++++++++++++++++++++++++++++++++++
 include/linux/stacktrace.h        |    6 +++++
 kernel/stacktrace.c               |    6 +++++
 4 files changed, 54 insertions(+), 0 deletions(-)

arch/x86/include/asm/stacktrace.h +2 -0

index 70bbe39..06bbdfc 100644
@@ -50,9 +50,11 @@ void dump_trace(struct task_struct *tsk, struct pt_regs *regs,
 #ifdef CONFIG_X86_32
 #define STACKSLOTS_PER_LINE 8
 #define get_bp(bp) asm("movl %%ebp, %0" : "=r" (bp) :)
+#define get_irq_stack_end()	0
 #else
 #define STACKSLOTS_PER_LINE 4
 #define get_bp(bp) asm("movq %%rbp, %0" : "=r" (bp) :)
+#define get_irq_stack_end()	(unsigned long)this_cpu_read(irq_stack_ptr)
 #endif
 
 #ifdef CONFIG_FRAME_POINTER

arch/x86/kernel/stacktrace.c +40 -0

index fdd0c64..f53ec547 100644
@@ -81,6 +81,46 @@ void save_stack_trace_tsk(struct task_struct *tsk, struct stack_trace *trace)
 }
 EXPORT_SYMBOL_GPL(save_stack_trace_tsk);
 
+#ifdef CONFIG_FRAME_POINTER
+void save_stack_trace_quick(struct stack_trace *trace)
+{
+	const unsigned long stk_sz = THREAD_SIZE - sizeof(struct stack_frame);
+	unsigned long tstk = (unsigned long)current_thread_info();
+	unsigned long istk = get_irq_stack_end();
+	unsigned long last_bp = 0;
+	unsigned long bp, stk;
+
+	get_bp(bp);
+
+	if (bp > tstk && bp <= tstk + stk_sz)
+		stk = tstk;
+	else if (istk && (bp > istk && bp <= stk_sz))
+		stk = istk;
+	else
+		goto out;
+
+	while (bp > last_bp && bp <= stk + stk_sz) {
+		struct stack_frame *frame = (struct stack_frame *)bp;
+		unsigned long ret_addr = frame->return_address;
+
+		if (!trace->skip) {
+			if (trace->nr_entries >= trace->max_entries)
+				return;
+			trace->entries[trace->nr_entries++] = ret_addr;
+		} else {
+			trace->skip--;
+		}
+
+		last_bp = bp;
+		bp = (unsigned long)frame->next_frame;
+	}
+out:
+	if (trace->nr_entries < trace->max_entries)
+		trace->entries[trace->nr_entries++] = ULONG_MAX;
+}
+EXPORT_SYMBOL_GPL(save_stack_trace_quick);
+#endif
+
 /* Userspace stacktrace - based on kernel/trace/trace_sysprof.c */
 
 struct stack_frame_user {

include/linux/stacktrace.h +6 -0

index 115b570..d5b16c4 100644
@@ -19,6 +19,12 @@ extern void save_stack_trace_regs(struct pt_regs *regs,
 extern void save_stack_trace_tsk(struct task_struct *tsk,
 				struct stack_trace *trace);
 
+/*
+ * Saves only trace from the current context.  Doesn't handle exception
+ * stacks or verify text address.
+ */
+extern void save_stack_trace_quick(struct stack_trace *trace);
+
 extern void print_stack_trace(struct stack_trace *trace, int spaces);
 
 #ifdef CONFIG_USER_STACKTRACE_SUPPORT

kernel/stacktrace.c +6 -0

index 00fe55c..4760949 100644
@@ -31,6 +31,12 @@ EXPORT_SYMBOL_GPL(print_stack_trace);
  * (whenever this facility is utilized - for example by procfs):
  */
 __weak void
+save_stack_trace_quick(struct stack_trace *trace)
+{
+	WARN_ONCE(1, KERN_INFO "save_stack_trace_quick() not implemented yet.\n");
+}
+
+__weak void
 save_stack_trace_tsk(struct task_struct *tsk, struct stack_trace *trace)
 {
 	WARN_ONCE(1, KERN_INFO "save_stack_trace_tsk() not implemented yet.\n");

Signature · 1 line

1.7.3.1

Frederic Weisbecker

2012-01-11 16:26 UTC #14 lore raw

Re: [PATCH 8/9] stacktrace: implement save_stack_trace_quick()

Quoted 4 lines · Tejun Heo

Implement save_stack_trace_quick() which only considers the usual contexts (ie. thread and irq) and doesn't handle links between different contexts - if %current is in irq context, only backtrace in the irq stack is considered.

The thing I don't like is the duplication that involves not only on stack unwinding but also on the safety checks.

What about making struct stacktrace_ops::stack() return a value that either stops or continue the trace? In your case EOE/EOI would be the triggering condition.

Filtering stack contexts might in fact be a desirable generic feature overall.

At least in perf we could be interested in filtering kernel/user contexts. And in your case in stopping after the first context. I also don't know if we will be interested in filtering irq/exception/process stacks in the future but I prefer to ensure we have a flexible enough interface to allow that.

So it may be a good idea to reuse the exisiting code for your needs like a stack() return value as above. And if the post processing will be done from userspace (which I really hope) then extend the ftrace/perf interface to allow your quick filtering, something that can be later extended to allow more finegrained stacktrace filtering.

Quoted 3 lines

This is subset of dump_trace() done in much simpler way. It's intended to be used in hot paths where the overhead of dump_trace() can be too heavy.

Is it? Have you found a measurable impact (outside the fact you record only one stack).

Thanks.

Tejun Heo

author

2012-01-11 16:38 UTC #15 lore raw

Re: [PATCH 8/9] stacktrace: implement save_stack_trace_quick()

Hello, Frederic.

Quoted 8 lines · Frederic Weisbecker

Quoted 4 lines · Tejun Heo
Implement save_stack_trace_quick() which only considers the usual contexts (ie. thread and irq) and doesn't handle links between different contexts - if %current is in irq context, only backtrace in the irq stack is considered.
The thing I don't like is the duplication that involves not only on stack unwinding but also on the safety checks.

I'm not entirely convinced that this is necessary or we can just add more features to the existing backtrace facility (and maybe make that more efficient) and be done with it.

Quoted 6 lines

Quoted 3 lines
This is subset of dump_trace() done in much simpler way. It's intended to be used in hot paths where the overhead of dump_trace() can be too heavy.
Is it? Have you found a measurable impact (outside the fact you record only one stack).

As I wrote in the head message, I haven't done comparative test yet but in the preliminary tests the CPU overhead against memory backed device is quite visible (roughly ~20%), so I expect it to matter. Note that testing against memory backed device is actually relevant, on faster SSDs, CPU is already a bottleneck.

It would be best if we can extend the existing one to cover all the cases with acceptable overhead. I needed to write this minimal version anyway for comparison so it's posted together but no matter how it turns out switching them isn't difficult.

Thanks.

Signature · 1 line

tejun

Tejun Heo

author

2012-01-11 17:37 UTC #16 lore raw

Re: [PATCH 8/9] stacktrace: implement save_stack_trace_quick()

Hello,

Quoted 4 lines · Tejun Heo

It would be best if we can extend the existing one to cover all the cases with acceptable overhead. I needed to write this minimal version anyway for comparison so it's posted together but no matter how it turns out switching them isn't difficult.

To add a bit, it would probably be better to restructure backtrace code such that the common code provides discrete steps for backtracing (maybe somewhat like iterators) and interface functions assembling what they need. Such structure would be much more malleable for various purposes.

Thanks.

Signature · 1 line

tejun

Frederic Weisbecker

2012-01-17 02:22 UTC #17 lore raw

Re: [PATCH 8/9] stacktrace: implement save_stack_trace_quick()

In reply to Tejun Heo

Quoted 9 lines · Tejun Heo

Hello, Frederic.
Quoted 6 lines · Frederic Weisbecker
Quoted 4 lines · Tejun Heo
Implement save_stack_trace_quick() which only considers the usual contexts (ie. thread and irq) and doesn't handle links between different contexts - if %current is in irq context, only backtrace in the irq stack is considered.

Quoted 6 lines

Quoted 2 lines
The thing I don't like is the duplication that involves not only on stack unwinding but also on the safety checks.
I'm not entirely convinced that this is necessary or we can just add more features to the existing backtrace facility (and maybe make that more efficient) and be done with it.

Yeah probably we can do that.

Quoted 14 lines

Quoted 7 lines
Quoted 4 lines
This is subset of dump_trace() done in much simpler way. It's intended to be used in hot paths where the overhead of dump_trace() can be too heavy.
Is it? Have you found a measurable impact (outside the fact you record only one stack).
As I wrote in the head message, I haven't done comparative test yet but in the preliminary tests the CPU overhead against memory backed device is quite visible (roughly ~20%), so I expect it to matter. Note that testing against memory backed device is actually relevant, on faster SSDs, CPU is already a bottleneck.

Quoted 4 lines

It would be best if we can extend the existing one to cover all the cases with acceptable overhead. I needed to write this minimal version anyway for comparison so it's posted together but no matter how it turns out switching them isn't difficult.

Right. So there are two major differences that may affect performances between save_stack_trace() and save_stack_trace_quick():

- save_stack_trace() does a full walk through the stack, but it rejects unreliable entries. So to begin with, it should use print_context_stack_bp() that does a frame pointer walk only (in CONFIG_FRAME_POINTER case).

- It links between stacks. Doing the ->stack() that returns a value should help in this regard.

- And dump_stack() does various more checks, perhaps we can simplify it a bit.

Tejun Heo

author

2012-01-10 18:29 UTC #18 lore raw

PATCH 9/9 block, trace: implement ioblame - IO tracer with origin tracking

In reply to Tejun Heo

Implement ioblame, which can attribute each IO to its origin and export the information using a tracepoint.

Operations which may eventually cause IOs and IO operations themselves are identified and tracked primarily by their stack traces along with the task and the target file (dev:ino:gen). On each IO completion, ioblame knows why that specific IO happened and exports the information via ioblame:ioblame_io tracepoint.

While ioblame adds fields to a few fs and block layer objects, all logic is well insulated inside ioblame proper and all hooking goes through well defined tracepoints and doesn't add any significant maintenance overhead.

For details, please read Documentation/trace/ioblame.txt.

-v2: Namhyung pointed out that all the information available at IO
completion can be exported via tracepoint and letting userland do whatever it wants to do with that would be better. Stripped out in-kernel statistics gathering.

Now that everything is exported through tracepoint, iolog and counters_pipe[_pipe] are unnecessary. Removed. intents_bin too is removed.

As data collection no longer requires polling, ioblame/intents is updated to generate inotify IN_MODIFY event after a new intent is created.

Signed-off-by Tejun Heo <[email protected]>

Cc Namhyung Kim <[email protected]>

Cc Justin TerAvest <[email protected]>

Cc Slava Pestov <[email protected]>

Cc David Sharp <[email protected]>

Cc Jim Winget <[email protected]>

---
 Documentation/trace/ioblame.txt |  476 ++++++++
 include/linux/blk_types.h       |    4 +
 include/linux/fs.h              |    3 +
 include/linux/genhd.h           |    3 +
 include/linux/ioblame.h         |   72 ++
 kernel/trace/Kconfig            |   12 +
 kernel/trace/Makefile           |    1 +
 kernel/trace/ioblame.c          | 2279 +++++++++++++++++++++++++++++++++++++++
 8 files changed, 2850 insertions(+), 0 deletions(-)
 create mode 100644 Documentation/trace/ioblame.txt
 create mode 100644 include/linux/ioblame.h
 create mode 100644 kernel/trace/ioblame.c

Documentation/trace/ioblame.txt new file +476 -0

new file mode 100644
index 0000000..cd72f29
@@ -0,0 +1,476 @@
+
+ioblame - IO tracer with origin tracking
+
+December, 2011		Tejun Heo <[email protected]>
+
+
+CONTENTS
+
+1. Introduction
+2. Overall design
+3. Debugfs interface
+3-1. Configuration
+3-2. Stats and intents
+4. Trace examples
+5. Notes
+6. Overheads
+
+
+1. Introduction
+
+In many workloads, IO throughput and latency have large effect on
+overall performance; however, due to the complexity and asynchronous
+nature, it is very difficult to characterize what's going on.
+blktrace and various tracepoints provide visibility into individual IO
+operations but it is still extremely difficult to trace back to the
+origin of those IO operations.
+
+ioblame is IO tracer which tracks origin of each IO.  It keeps track
+of who dirtied pages and inodes, and, on an actual IO, attributes it
+to the originator of the IO.  All the information ioblame collects is
+exported via ioblame:ioblame_io tracepoint on each IO completion.
+
+The design goals of ioblame are
+
+* Minimally invasive - Tracer shouldn't be invasive.  Except for
+  adding some fields to mostly block layer data structures for
+  tracking, ioblame gathers all information through well defined
+  tracepoints and all tracking logic is contained in ioblame proper.
+
+* Generic and detailed - There are many different IO paths and
+  filesystems which also go through changes regularly.  Tracer should
+  be able to report detailed enough result covering most cases without
+  requiring frequent adaptation.  ioblame uses stack trace at key
+  points combined information from generic layers to categorize IOs.
+  This gives detailed enough information into varying IO paths without
+  requiring specific adaptations.
+
+* Low overhead - Overhead both in terms of memory and processor cycles
+  should be low enough so that the analyzer can be used in IO-heavy
+  production environments.  ioblame keeps hot data structures compact
+  and mostly read-only and avoids synchronization on hot paths by
+  using RCU and taking advantage of the fact that statistics doesn't
+  have to be completely accurate.
+
+
+2. Overall design
+
+ioblame tracks the following three object types.
+
+* Role: This tracks 'who' is taking an action.  Corresponds to a
+  thread.
+
+* Intent: Stack trace + modifier.  An intent groups actions of the
+  same type.  As the name suggests, modifier modifies the intent and
+  there can be multiple intents with the same stack trace but
+  different modifiers.  Currently, only writeback modifiers are
+  implemented which denote why the writeback action is occurring -
+  ie. wb_reason.
+
+* Act: This is combination of role, intent and the inode being
+  operated.  This is not visible to userland and used internally to
+  track dirtier and its intent in compact form.
+
+ioblame uses the same indexing data structure for all three types of
+objects.  Objects are never linked directly using pointers and every
+access goes through the index.  This allows avoiding expensive strict
+object lifetime management.  Objects are located either by its content
+via hash table or id which contains generation number.
+
+To attribute data writebacks to the originator, ioblame maintains a
+table indexed by page frame number which keeps track of which act
+dirtied which pages.  For each IO, the target pages are looked up in
+the table and the dirtying act is charged for the IO.  Note that,
+currently, each IO is charged as whole to a single act - e.g. all of
+an IO for writeback encompassing multiple dirtiers will be charged to
+the first found dirtying act.  This simplifies data collection and
+reporting while not losing too much information - writebacks tend to
+be naturally grouped and IOPS (IO operations per second) are often
+more significant than length of each IO.
+
+inode writeback tracking is more involved as different filesystems
+handle metadata updates and writebacks differently.  ioblame uses
+per-inode and buffer_head operation tracking to identify inode
+writebacks to the originator.
+
+On each IO completion, ioblame knows the offset and size of the IO,
+who's responsible and its intent, how long it took in the queue and
+the target file.  This information is reported via ioblame:ioblame_io
+tracepoint.
+
+Except for the tracepoint, all interactions happen using files under
+/sys/kernel/debug/ioblame/.
+
+
+3. Debugfs interface
+
+3-1. Configuration
+
+* enable			- can be changed anytime
+
+  Master enable.  Write [Yy1] to enable, [Nn0] to disable.
+
+* devs				- can be changed anytime
+
+  Specifies the devices ioblame is enabled for.  ioblame will only
+  track operations on devices which are explicitly enabled in this
+  file.
+
+  It accepts white space separated list of MAJ:MINs or block device
+  names with optional preceding '!' for negation.  Opening with
+  O_TRUNC clears all existing entries.  For example,
+
+  $ echo sda sdb > devs		# disables all devices and then enable sd[ab]
+  $ echo sdc >> devs		# sd[abc] enabled
+  $ echo !8:0 >> devs		# sd[bc] enabled
+  $ cat devs
+  8:16 sdb
+  8:32 sdc
+
+* max_{role|intent|act}s	- can be changed while disabled
+
+  Specifies the maximum number of each object type.  If the number of
+  certain object type exceeds the limit, IOs will be attributed to
+  special NOMEM object.
+
+* ttl_secs			- can be changed anytime
+
+  Specifies TTL of roles and acts.  Roles are reclaimed after at least
+  TTL has passed after the matching thread has exited or execed and
+  assumed another tid.  Acts are reclaimed after being unused for at
+  least TTL.
+
+
+3-2. Stats and intents (read only)
+
+* nr_{roles|intents|acts}
+
+  Returns the number of objects of the type.  The number of roles and
+  acts can decrease after reclaiming but nr_intents only increases
+  while ioblame is enabled.
+
+* stats/idx_nomem
+
+  How many times role, intent or act creation failed because memory
+  allocation failed while extending index to accomodate new object.
+
+* stats/idx_nospc
+
+  How many times role, intent or act creation failed because limit
+  specified by {role|intent|act}_max is reached.
+
+* stats/node_nomem
+
+  How many times role, intent or act creation failed to allocate.
+
+* stats/pgtree_nomem
+
+  How many times page tree, which maps page frame number to dirtying
+  act, failed to expand due to memory allocation failure.
+
+* intents
+
+  Dump of intents.
+
+  $ cat intents
+  #0 modifier=0x0
+  #1 modifier=0x0
+  #2 modifier=0x0
+  [ffffffff81189a6a] file_update_time+0xca/0x150
+  [ffffffff81122030] __generic_file_aio_write+0x200/0x460
+  [ffffffff81122301] generic_file_aio_write+0x71/0xe0
+  [ffffffff8122ea94] ext4_file_write+0x64/0x280
+  [ffffffff811b5d24] aio_rw_vect_retry+0x74/0x1d0
+  [ffffffff811b7401] aio_run_iocb+0x61/0x190
+  [ffffffff811b81c8] do_io_submit+0x648/0xaf0
+  [ffffffff811b867b] sys_io_submit+0xb/0x10
+  [ffffffff81a3c8bb] system_call_fastpath+0x16/0x1b
+  #3 modifier=0x0
+  [ffffffff811aaf2e] __blockdev_direct_IO+0x1f1e/0x37c0
+  [ffffffff812353b2] ext4_direct_IO+0x1b2/0x3f0
+  [ffffffff81121d6a] generic_file_direct_write+0xba/0x180
+  [ffffffff8112210b] __generic_file_aio_write+0x2db/0x460
+  [ffffffff81122301] generic_file_aio_write+0x71/0xe0
+  [ffffffff8122ea94] ext4_file_write+0x64/0x280
+  [ffffffff811b5d24] aio_rw_vect_retry+0x74/0x1d0
+  [ffffffff811b7401] aio_run_iocb+0x61/0x190
+  [ffffffff811b81c8] do_io_submit+0x648/0xaf0
+  [ffffffff811b867b] sys_io_submit+0xb/0x10
+  [ffffffff81a3c8bb] system_call_fastpath+0x16/0x1b
+  #4 modifier=0x0
+  [ffffffff811aaf2e] __blockdev_direct_IO+0x1f1e/0x37c0
+  [ffffffff8126da71] ext4_ind_direct_IO+0x121/0x460
+  [ffffffff81235436] ext4_direct_IO+0x236/0x3f0
+  [ffffffff81122db2] generic_file_aio_read+0x6b2/0x740
+  ...
+
+  The # prefixed number is the NR of the intent used to link intent
+  from stastics.  Modifier and stack trace follow.  The first two
+  entries are special - 0 is nomem intent and 1 is lost intent.  The
+  former is used when an intent can't be created because allocation
+  failed or intent_max is reached.  The latter is used when reclaiming
+  resulted in loss of tracking info and the IO can't be reported
+  exactly.
+
+  This file can be seeked by intent NR.  ie. seeking to 3 and reading
+  will return intent #3 and after.  Because intents are never
+  destroyed while ioblame is enabled, this allows userland tool to
+  discover new intents since last reading.  Seeking to the number of
+  currently known intents and reading returns only the newly created
+  intents.
+
+  At least one inotify IN_MODIFY event is generated after a new intent
+  is created.
+
+
+4. Trace examples
+
+All information ioblame gathers is available through
+ioblame:ioblame_io tracing event.  The outputs in the following
+examples are reformatted and annoated.
+
+4-1. ls, touch and sync - on an ext4 FS w/o journal
+
+- sector=69896 size=4096 rw=META|PRIO wait_nsec=45244 io_nsec=11263878
+  pid=952 intent=8 dev=8:17 ino=2 gen=0
+
+  pid 952 (ls) issues 4k META|PRIO read on /dev/sdb1's root directory
+  with intent 8 to read directory entries.
+
+  #8 modifier=0x0
+  [ffffffff813981b8] generic_make_request+0x18/0x100
+  [ffffffff81398314] submit_bio+0x74/0x100
+  [ffffffff811c6b9b] submit_bh+0xeb/0x130
+  [ffffffff811c851e] ll_rw_block+0xae/0xb0
+  [ffffffff81265703] ext4_bread+0x43/0x80
+  [ffffffff8126b458] htree_dirblock_to_tree+0x38/0x190
+  [ffffffff8126b655] ext4_htree_fill_tree+0xa5/0x260
+  [ffffffff81259c76] ext4_readdir+0x116/0x5e0
+  [ffffffff811a7ec0] vfs_readdir+0xb0/0xd0
+  [ffffffff811a8049] sys_getdents+0x89/0xf0
+  [ffffffff81aaca6b] system_call_fastpath+0x16/0x1b
+
+- sector=4232 size=4096 rw= wait_nsec=69052 io_nsec=475710
+  pid=953 intent=14 dev=8:16 ino=0 gen=0
+
+  pid 953 (touch) issues 4k read with intent 14 during open(2).
+
+  #14 modifier=0x0
+  [ffffffff813981b8] generic_make_request+0x18/0x100
+  [ffffffff81398314] submit_bio+0x74/0x100
+  [ffffffff811c6b9b] submit_bh+0xeb/0x130
+  [ffffffff811c8425] bh_submit_read+0x35/0x80
+  [ffffffff8125b29b] ext4_read_inode_bitmap+0x18b/0x3f0
+  [ffffffff8125bf85] ext4_new_inode+0x355/0x10b0
+  [ffffffff81269a7a] ext4_create+0x9a/0x120
+  [ffffffff811a366c] vfs_create+0x8c/0xe0
+  [ffffffff811a4616] do_last+0x776/0x8e0
+  [ffffffff811a4858] path_openat+0xd8/0x410
+  [ffffffff811a4ca9] do_filp_open+0x49/0xa0
+  [ffffffff811926a7] do_sys_open+0x107/0x1e0
+  [ffffffff811927c0] sys_open+0x20/0x30
+  [ffffffff81aaca6b] system_call_fastpath+0x16/0x1b
+
+- sector=4360 size=4096 rw=WRITE wait_nsec=28998035 io_nsec=768370
+  pid=953 intent=11 dev=8:17 ino=14 gen=3151897938
+
+  touch dirtied inode 14 and the following sync forces writeback.
+  The IO is attributed to the dirtier.  Note the non-zero modifier is
+  indicating WB_REASON_SYNC.
+
+  #11 modifier=0x10000002
+  [ffffffff811c0710] __mark_inode_dirty+0x220/0x330
+  [ffffffff8125feeb] ext4_setattr+0x26b/0x4d0
+  [ffffffff811b0f2a] notify_change+0x10a/0x2b0
+  [ffffffff811c52de] utimes_common+0xde/0x190
+  [ffffffff811c5431] do_utimes+0xa1/0xf0
+  [ffffffff811c55a6] sys_utimensat+0x36/0xb0
+  [ffffffff81aaca6b] system_call_fastpath+0x16/0x1b
+
+
+4-2. copying a 1M file from another filesystem and waiting a bit
+
+- sector=2056 size=4096 rw=WRITE wait_nsec=151425 io_nsec=584466
+  pid=1004 intent=24 dev=8:16 ino=0 gen=0
+
+  flush-8:16 starting writeback w/ WB_REASON_BACKGROUND.  This
+  repeats a couple times.
+
+  #24 modifier=0x10000000
+  [ffffffff813981b8] generic_make_request+0x18/0x100
+  [ffffffff81398314] submit_bio+0x74/0x100
+  [ffffffff811c6b9b] submit_bh+0xeb/0x130
+  [ffffffff811ca410] __block_write_full_page+0x210/0x3b0
+  [ffffffff811ca6a0] block_write_full_page_endio+0xf0/0x140
+  [ffffffff811ca705] block_write_full_page+0x15/0x20
+  [ffffffff811ce438] blkdev_writepage+0x18/0x20
+  [ffffffff81148f1a] __writepage+0x1a/0x50
+  [ffffffff81149ae6] write_cache_pages+0x206/0x4f0
+  [ffffffff81149e24] generic_writepages+0x54/0x80
+  [ffffffff81149e74] do_writepages+0x24/0x40
+  [ffffffff811bf301] writeback_single_inode+0x1a1/0x600
+  [ffffffff811c01db] writeback_sb_inodes+0x1ab/0x280
+  [ffffffff811c0b8e] __writeback_inodes_wb+0x9e/0xd0
+  [ffffffff811c0ea3] wb_writeback+0x243/0x3a0
+  [ffffffff811c115a] wb_do_writeback+0x15a/0x2b0
+  [ffffffff811c138a] bdi_writeback_thread+0xda/0x330
+  [ffffffff810bc286] kthread+0xb6/0xc0
+  [ffffffff81aadff4] kernel_thread_helper+0x4/0x10
+
+- sector=4360 size=4096 rw=WRITE wait_nsec=781396 io_nsec=894147
+  pid=1017 intent=25 dev=8:17 ino=12 gen=3151897939
+
+  Writeback got to inode 12 which was created and written to by cp.
+  This is inode writeback.
+
+  #25 modifier=0x10000000
+  [ffffffff811c0710] __mark_inode_dirty+0x220/0x330
+  [ffffffff811c7e5b] generic_write_end+0x6b/0xa0
+  [ffffffff8126191a] ext4_da_write_end+0xfa/0x350
+  [ffffffff8113f168] generic_file_buffered_write+0x188/0x2b0
+  [ffffffff81141608] __generic_file_aio_write+0x238/0x460
+  [ffffffff811418a8] generic_file_aio_write+0x78/0xf0
+  [ffffffff8125a4cf] ext4_file_write+0x6f/0x2a0
+  [ffffffff81194112] do_sync_write+0xe2/0x120
+  [ffffffff81194c08] vfs_write+0xc8/0x180
+  [ffffffff81194dc1] sys_write+0x51/0x90
+  [ffffffff81aaca6b] system_call_fastpath+0x16/0x1b
+
+- sector=268288 size=524288 rw=WRITE wait_nsec=461543 io_nsec=3180190
+  pid=1017 intent=27 dev=8:17 ino=12 gen=3151897939
+
+  The first half of data.
+
+  #27 modifier=0x10000000
+  [ffffffff811c79cc] __set_page_dirty+0x4c/0xd0
+  [ffffffff811c7ab6] mark_buffer_dirty+0x66/0xa0
+  [ffffffff811c7b99] __block_commit_write+0xa9/0xe0
+  [ffffffff811c7da2] block_write_end+0x42/0x90
+  [ffffffff811c7e23] generic_write_end+0x33/0xa0
+  [ffffffff8126191a] ext4_da_write_end+0xfa/0x350
+  [ffffffff8113f168] generic_file_buffered_write+0x188/0x2b0
+  [ffffffff81141608] __generic_file_aio_write+0x238/0x460
+  [ffffffff811418a8] generic_file_aio_write+0x78/0xf0
+  [ffffffff8125a4cf] ext4_file_write+0x6f/0x2a0
+  [ffffffff81194112] do_sync_write+0xe2/0x120
+  [ffffffff81194c08] vfs_write+0xc8/0x180
+  [ffffffff81194dc1] sys_write+0x51/0x90
+  [ffffffff81aaca6b] system_call_fastpath+0x16/0x1b
+
+- sector=269312 size=524288 rw=WRITE wait_nsec=364198 io_nsec=5667553
+  pid=1017 intent=27 dev=8:17 ino=12 gen=3151897939
+
+  And the second half.
+
+
+4-3. dd if=/dev/zero of=testfile bs=128k count=4 oflag=direct
+
+- sector=266496 size=131072 rw=WRITE|SYNC wait_nsec=48180 io_nsec=1066758
+  pid=1042 intent=34 dev=8:17 ino=12 gen=3151897940
+
+  First chunk.
+
+  #34 modifier=0x0
+  [ffffffff813981b8] generic_make_request+0x18/0x100
+  [ffffffff81398314] submit_bio+0x74/0x100
+  [ffffffff811d1c45] __blockdev_direct_IO+0x21b5/0x3830
+  [ffffffff8129a7a1] ext4_ind_direct_IO+0x121/0x470
+  [ffffffff812612ee] ext4_direct_IO+0x23e/0x400
+  [ffffffff81141308] generic_file_direct_write+0xc8/0x190
+  [ffffffff811416ab] __generic_file_aio_write+0x2db/0x460
+  [ffffffff811418a8] generic_file_aio_write+0x78/0xf0
+  [ffffffff8125a4cf] ext4_file_write+0x6f/0x2a0
+  [ffffffff81194112] do_sync_write+0xe2/0x120
+  [ffffffff81194c08] vfs_write+0xc8/0x180
+  [ffffffff81194dc1] sys_write+0x51/0x90
+  [ffffffff81aaca6b] system_call_fastpath+0x16/0x1b
+
+- sector=266752 size=131072 rw=WRITE|SYNC wait_nsec=15155 io_nsec=1086987
+  pid=1042 intent=34 dev=8:17 ino=12 gen=3151897940
+
+  Second.
+
+- sector=267008 size=131072 rw=WRITE|SYNC wait_nsec=22694 io_nsec=1092836
+  pid=1042 intent=34 dev=8:17 ino=12 gen=3151897940
+
+  Third.
+
+- sector=267264 size=131072 rw=WRITE|SYNC wait_nsec=15852 io_nsec=1021868
+  pid=1042 intent=34 dev=8:17 ino=12 gen=3151897940
+
+  Fourth.
+
+...
+
+- sector=4360 size=4096 rw=WRITE wait_nsec=1378342 io_nsec=828771
+  pid=1042 intent=35 dev=8:17 ino=12 gen=3151897940
+
+  After a while, inode is written back with WB_REASON_PERIODIC.
+
+  #35 modifier=0x10000003
+  [ffffffff811c0710] __mark_inode_dirty+0x220/0x330
+  [ffffffff8129611a] ext4_mb_new_blocks+0xea/0x5a0
+  [ffffffff8128b22e] ext4_ext_map_blocks+0x1c0e/0x1d80
+  [ffffffff812638d1] ext4_map_blocks+0x1b1/0x260
+  [ffffffff81263a28] _ext4_get_block+0xa8/0x160
+  [ffffffff81263b46] ext4_get_block+0x16/0x20
+  [ffffffff811d0460] __blockdev_direct_IO+0x9d0/0x3830
+  [ffffffff8129a7a1] ext4_ind_direct_IO+0x121/0x470
+  [ffffffff812612ee] ext4_direct_IO+0x23e/0x400
+  [ffffffff81141308] generic_file_direct_write+0xc8/0x190
+  [ffffffff811416ab] __generic_file_aio_write+0x2db/0x460
+  [ffffffff811418a8] generic_file_aio_write+0x78/0xf0
+  [ffffffff8125a4cf] ext4_file_write+0x6f/0x2a0
+  [ffffffff81194112] do_sync_write+0xe2/0x120
+  [ffffffff81194c08] vfs_write+0xc8/0x180
+  [ffffffff81194dc1] sys_write+0x51/0x90
+  [ffffffff81aaca6b] system_call_fastpath+0x16/0x1b
+
+
+5. Notes
+
+* By the time ioblame reports IOs or counters, the task which gets
+  charged might have already exited and this is why ioblame prints
+  task command in some reports but not in others.  Userland tool is
+  advised to use combination of live task listing and process
+  accounting to match pid's to commands.
+
+* dev:ino:gen can be mapped to filename without scanning the whole
+  filesystem by constructing FS-specific filehandle, opening it with
+  open_by_handle_at(2) and then readlink(2)ing /proc/self/FD.  This
+  will return full path as long as the dentry is in cache, which is
+  likely if data acquisition and mapping don't happen too long after
+  IOs.
+
+* At this point, it's mostly tested with ext4 w/o journal.  Metadata
+  dirtier tracking w/ journal needs improvements.
+
+
+6. Overheads
+
+On x86_64, role is 104 bytes, intent 32 + 8 * stack_depth and act 72
+bytes.  Intents are allocated using kzalloc() and there shouldn't be
+too many of them.  Both roles and acts have their own kmem_cache and
+can be monitored via /proc/slabinfo.
+
+Each counter occupy 32 * nr_counters and is aligned to cacheline.
+Counters are allocated only as necessary.  iob_counters kmem_cache is
+dynamically created on enable.
+
+The size of page frame number -> dirtier mapping table is proportional
+to the amount of available physical memory.  If max_acts <= 65536,
+2bytes are used per PAGE_SIZE.  With 4k page, at most ~0.049% can be
+used.  If max_acts > 65536, 4bytes are used doubling the percentage to
+~0.098%.  The table also grows dynamically.
+
+There are also indexing data structures used - hash tables, id[ra]s
+and a radix tree.  There are three hash tables, each sized according
+to max_{roles|intents|acts}.  The maximum memory usage by hash tables
+is sizeof(void *) * (max_roles + max_intents + max_acts).  Memory used
+by other indexing structures should be negligible.
+
+Preliminary tests w/ fio ssd-test on loopback device on tmpfs, which
+is purely CPU cycle bound, shows ~20% throughput hit.
+
+*** TODO: add performance testing results and explain involved CPU
+    overheads.

include/linux/blk_types.h +4 -0

index 4053cbd..2ee4e3b 100644
@@ -8,6 +8,7 @@
 #ifdef CONFIG_BLOCK
 
 #include <linux/types.h>
+#include <linux/ioblame.h>
 
 struct bio_set;
 struct bio;

@@ -69,6 +70,9 @@ struct bio {
 #if defined(CONFIG_BLK_DEV_INTEGRITY)
 	struct bio_integrity_payload *bi_integrity;  /* data integrity */
 #endif
+#if defined(CONFIG_IO_BLAME) || defined(CONFIG_IO_BLAME_MODULE)
+	struct iob_io_info	bi_iob_info;
+#endif
 
 	bio_destructor_t	*bi_destructor;	/* destructor */

include/linux/fs.h +3 -0

index 7aacf31..7a43f9a 100644
@@ -835,6 +835,9 @@ struct inode {
 	atomic_t		i_readcount; /* struct files open RO */
 #endif
 	void			*i_private; /* fs or device private pointer */
+#if defined(CONFIG_IO_BLAME) || defined(CONFIG_IO_BLAME_MODULE)
+	union iob_id		i_iob_act;
+#endif
 };
 
 static inline int inode_unhashed(struct inode *inode)

include/linux/genhd.h +3 -0

index 9d0e0b5..237db65 100644
@@ -190,6 +190,9 @@ struct gendisk {
 #ifdef  CONFIG_BLK_DEV_INTEGRITY
 	struct blk_integrity *integrity;
 #endif
+#if defined(CONFIG_IO_BLAME) || defined(CONFIG_IO_BLAME_MODULE)
+	bool iob_enabled;
+#endif
 	int node_id;
 };

include/linux/ioblame.h new file +72 -0

72 lines not on this page · raw message

kernel/trace/Kconfig +12 -0

index cd31345..ccc7c12 100644
@@ -368,6 +368,18 @@ config BLK_DEV_IO_TRACE
 
 	  If unsure, say N.
 
+config IO_BLAME
+	tristate "Enable io-blame tracer"
+	depends on SYSFS
+	depends on BLOCK
+	select TRACEPOINTS
+	select STACKTRACE
+	help
+	  Say Y here if you want to enable IO tracer with dirtier
+	  tracking.  See Documentation/trace/ioblame.txt.
+
+	  If unsure, say N.
+
 config KPROBE_EVENT
 	depends on KPROBES
 	depends on HAVE_REGS_AND_STACK_ACCESS_API

kernel/trace/Makefile +1 -0

index 5f39a07..408cd1a 100644
@@ -46,6 +46,7 @@ obj-$(CONFIG_BLK_DEV_IO_TRACE) += blktrace.o
 ifeq ($(CONFIG_BLOCK),y)
 obj-$(CONFIG_EVENT_TRACING) += blktrace.o
 endif
+obj-$(CONFIG_IO_BLAME) += ioblame.o
 obj-$(CONFIG_EVENT_TRACING) += trace_events.o
 obj-$(CONFIG_EVENT_TRACING) += trace_export.o
 obj-$(CONFIG_FTRACE_SYSCALLS) += trace_syscalls.o

kernel/trace/ioblame.c new file +2279 -0

2,279 lines not on this page · raw message

Signature · 1 line

1.7.3.1

Chanho Park

2012-01-11 00:25 UTC #19 lore raw

RE: [PATCH 9/9] block, trace: implement ioblame - IO tracer with origin tracking

Hello,

kernel/trace/ioblame.c line 308

Quoted 2 lines

kernel/trace/ioblame.c new file +2 -0
+#define CREATE_TRACE_POINTS
+#include <trace/events/ioblame.h>

I can't find it from patchset. So when compiling, I've got below error.

CC kernel/trace/power-traces.o
kernel/trace/ioblame.c:308: fatal error: trace/events/ioblame.h: No such file or directory
compilation terminated.
make[2]: *** [kernel/trace/ioblame.o] Error 1
make[2]: *** Waiting for unfinished jobs....

Are you forgot to attach it or just only RFC?

Best regards,
Chanho Park

Tejun Heo

author

2012-01-11 01:05 UTC #20 lore raw

Re: [PATCH 9/9] block, trace: implement ioblame - IO tracer with origin tracking

Hello,

Quoted 5 lines · Chanho Park

kernel/trace/ioblame.c line 308
Quoted 2 lines
kernel/trace/ioblame.c new file +2 -0
+#define CREATE_TRACE_POINTS
+#include <trace/events/ioblame.h>
I can't find it from patchset. So when compiling, I've got below error.

Quoted 8 lines

CC kernel/trace/power-traces.o kernel/trace/ioblame.c:308: fatal error: trace/events/ioblame.h: No such file or directory
compilation terminated.
make[2]: *** [kernel/trace/ioblame.o] Error 1
make[2]: *** Waiting for unfinished jobs....
Are you forgot to attach it or just only RFC?

Eh... crap. That's me forgetting to do quilt add. :( I'll resend shortly.

Thanks.

Signature · 1 line

tejun

Tejun Heo

author

2012-01-11 01:32 UTC #21 lore raw

PATCH RESEND 9/9 block, trace: implement ioblame - IO tracer with origin tracking

In reply to Tejun Heo

Implement ioblame, which can attribute each IO to its origin and export the information using a tracepoint.

For details, please read Documentation/trace/ioblame.txt.

Now that everything is exported through tracepoint, iolog and counters_pipe[_pipe] are unnecessary. Removed. intents_bin too is removed.

As data collection no longer requires polling, ioblame/intents is updated to generate inotify IN_MODIFY event after a new intent is created.

Signed-off-by Tejun Heo <[email protected]>

Cc Namhyung Kim <[email protected]>

Cc Justin TerAvest <[email protected]>

Cc Slava Pestov <[email protected]>

Cc David Sharp <[email protected]>

Cc Jim Winget <[email protected]>

---
include/trace/events/ioblame.h was missing from the patch. git branch also updated.

Thanks.

 Documentation/trace/ioblame.txt |  476 ++++++++
 include/linux/blk_types.h       |    4 +
 include/linux/fs.h              |    3 +
 include/linux/genhd.h           |    3 +
 include/linux/ioblame.h         |   72 ++
 include/trace/events/ioblame.h  |   94 ++
 kernel/trace/Kconfig            |   12 +
 kernel/trace/Makefile           |    1 +
 kernel/trace/ioblame.c          | 2279 +++++++++++++++++++++++++++++++++++++++
 9 files changed, 2944 insertions(+), 0 deletions(-)
 create mode 100644 Documentation/trace/ioblame.txt
 create mode 100644 include/linux/ioblame.h
 create mode 100644 include/trace/events/ioblame.h
 create mode 100644 kernel/trace/ioblame.c

Documentation/trace/ioblame.txt new file +476 -0

new file mode 100644
index 0000000..cd72f29
@@ -0,0 +1,476 @@
+
+ioblame - IO tracer with origin tracking
+
+December, 2011		Tejun Heo <[email protected]>
+
+
+CONTENTS
+
+1. Introduction
+2. Overall design
+3. Debugfs interface
+3-1. Configuration
+3-2. Stats and intents
+4. Trace examples
+5. Notes
+6. Overheads
+
+
+1. Introduction
+
+In many workloads, IO throughput and latency have large effect on
+overall performance; however, due to the complexity and asynchronous
+nature, it is very difficult to characterize what's going on.
+blktrace and various tracepoints provide visibility into individual IO
+operations but it is still extremely difficult to trace back to the
+origin of those IO operations.
+
+ioblame is IO tracer which tracks origin of each IO.  It keeps track
+of who dirtied pages and inodes, and, on an actual IO, attributes it
+to the originator of the IO.  All the information ioblame collects is
+exported via ioblame:ioblame_io tracepoint on each IO completion.
+
+The design goals of ioblame are
+
+* Minimally invasive - Tracer shouldn't be invasive.  Except for
+  adding some fields to mostly block layer data structures for
+  tracking, ioblame gathers all information through well defined
+  tracepoints and all tracking logic is contained in ioblame proper.
+
+* Generic and detailed - There are many different IO paths and
+  filesystems which also go through changes regularly.  Tracer should
+  be able to report detailed enough result covering most cases without
+  requiring frequent adaptation.  ioblame uses stack trace at key
+  points combined information from generic layers to categorize IOs.
+  This gives detailed enough information into varying IO paths without
+  requiring specific adaptations.
+
+* Low overhead - Overhead both in terms of memory and processor cycles
+  should be low enough so that the analyzer can be used in IO-heavy
+  production environments.  ioblame keeps hot data structures compact
+  and mostly read-only and avoids synchronization on hot paths by
+  using RCU and taking advantage of the fact that statistics doesn't
+  have to be completely accurate.
+
+
+2. Overall design
+
+ioblame tracks the following three object types.
+
+* Role: This tracks 'who' is taking an action.  Corresponds to a
+  thread.
+
+* Intent: Stack trace + modifier.  An intent groups actions of the
+  same type.  As the name suggests, modifier modifies the intent and
+  there can be multiple intents with the same stack trace but
+  different modifiers.  Currently, only writeback modifiers are
+  implemented which denote why the writeback action is occurring -
+  ie. wb_reason.
+
+* Act: This is combination of role, intent and the inode being
+  operated.  This is not visible to userland and used internally to
+  track dirtier and its intent in compact form.
+
+ioblame uses the same indexing data structure for all three types of
+objects.  Objects are never linked directly using pointers and every
+access goes through the index.  This allows avoiding expensive strict
+object lifetime management.  Objects are located either by its content
+via hash table or id which contains generation number.
+
+To attribute data writebacks to the originator, ioblame maintains a
+table indexed by page frame number which keeps track of which act
+dirtied which pages.  For each IO, the target pages are looked up in
+the table and the dirtying act is charged for the IO.  Note that,
+currently, each IO is charged as whole to a single act - e.g. all of
+an IO for writeback encompassing multiple dirtiers will be charged to
+the first found dirtying act.  This simplifies data collection and
+reporting while not losing too much information - writebacks tend to
+be naturally grouped and IOPS (IO operations per second) are often
+more significant than length of each IO.
+
+inode writeback tracking is more involved as different filesystems
+handle metadata updates and writebacks differently.  ioblame uses
+per-inode and buffer_head operation tracking to identify inode
+writebacks to the originator.
+
+On each IO completion, ioblame knows the offset and size of the IO,
+who's responsible and its intent, how long it took in the queue and
+the target file.  This information is reported via ioblame:ioblame_io
+tracepoint.
+
+Except for the tracepoint, all interactions happen using files under
+/sys/kernel/debug/ioblame/.
+
+
+3. Debugfs interface
+
+3-1. Configuration
+
+* enable			- can be changed anytime
+
+  Master enable.  Write [Yy1] to enable, [Nn0] to disable.
+
+* devs				- can be changed anytime
+
+  Specifies the devices ioblame is enabled for.  ioblame will only
+  track operations on devices which are explicitly enabled in this
+  file.
+
+  It accepts white space separated list of MAJ:MINs or block device
+  names with optional preceding '!' for negation.  Opening with
+  O_TRUNC clears all existing entries.  For example,
+
+  $ echo sda sdb > devs		# disables all devices and then enable sd[ab]
+  $ echo sdc >> devs		# sd[abc] enabled
+  $ echo !8:0 >> devs		# sd[bc] enabled
+  $ cat devs
+  8:16 sdb
+  8:32 sdc
+
+* max_{role|intent|act}s	- can be changed while disabled
+
+  Specifies the maximum number of each object type.  If the number of
+  certain object type exceeds the limit, IOs will be attributed to
+  special NOMEM object.
+
+* ttl_secs			- can be changed anytime
+
+  Specifies TTL of roles and acts.  Roles are reclaimed after at least
+  TTL has passed after the matching thread has exited or execed and
+  assumed another tid.  Acts are reclaimed after being unused for at
+  least TTL.
+
+
+3-2. Stats and intents (read only)
+
+* nr_{roles|intents|acts}
+
+  Returns the number of objects of the type.  The number of roles and
+  acts can decrease after reclaiming but nr_intents only increases
+  while ioblame is enabled.
+
+* stats/idx_nomem
+
+  How many times role, intent or act creation failed because memory
+  allocation failed while extending index to accomodate new object.
+
+* stats/idx_nospc
+
+  How many times role, intent or act creation failed because limit
+  specified by {role|intent|act}_max is reached.
+
+* stats/node_nomem
+
+  How many times role, intent or act creation failed to allocate.
+
+* stats/pgtree_nomem
+
+  How many times page tree, which maps page frame number to dirtying
+  act, failed to expand due to memory allocation failure.
+
+* intents
+
+  Dump of intents.
+
+  $ cat intents
+  #0 modifier=0x0
+  #1 modifier=0x0
+  #2 modifier=0x0
+  [ffffffff81189a6a] file_update_time+0xca/0x150
+  [ffffffff81122030] __generic_file_aio_write+0x200/0x460
+  [ffffffff81122301] generic_file_aio_write+0x71/0xe0
+  [ffffffff8122ea94] ext4_file_write+0x64/0x280
+  [ffffffff811b5d24] aio_rw_vect_retry+0x74/0x1d0
+  [ffffffff811b7401] aio_run_iocb+0x61/0x190
+  [ffffffff811b81c8] do_io_submit+0x648/0xaf0
+  [ffffffff811b867b] sys_io_submit+0xb/0x10
+  [ffffffff81a3c8bb] system_call_fastpath+0x16/0x1b
+  #3 modifier=0x0
+  [ffffffff811aaf2e] __blockdev_direct_IO+0x1f1e/0x37c0
+  [ffffffff812353b2] ext4_direct_IO+0x1b2/0x3f0
+  [ffffffff81121d6a] generic_file_direct_write+0xba/0x180
+  [ffffffff8112210b] __generic_file_aio_write+0x2db/0x460
+  [ffffffff81122301] generic_file_aio_write+0x71/0xe0
+  [ffffffff8122ea94] ext4_file_write+0x64/0x280
+  [ffffffff811b5d24] aio_rw_vect_retry+0x74/0x1d0
+  [ffffffff811b7401] aio_run_iocb+0x61/0x190
+  [ffffffff811b81c8] do_io_submit+0x648/0xaf0
+  [ffffffff811b867b] sys_io_submit+0xb/0x10
+  [ffffffff81a3c8bb] system_call_fastpath+0x16/0x1b
+  #4 modifier=0x0
+  [ffffffff811aaf2e] __blockdev_direct_IO+0x1f1e/0x37c0
+  [ffffffff8126da71] ext4_ind_direct_IO+0x121/0x460
+  [ffffffff81235436] ext4_direct_IO+0x236/0x3f0
+  [ffffffff81122db2] generic_file_aio_read+0x6b2/0x740
+  ...
+
+  The # prefixed number is the NR of the intent used to link intent
+  from stastics.  Modifier and stack trace follow.  The first two
+  entries are special - 0 is nomem intent and 1 is lost intent.  The
+  former is used when an intent can't be created because allocation
+  failed or intent_max is reached.  The latter is used when reclaiming
+  resulted in loss of tracking info and the IO can't be reported
+  exactly.
+
+  This file can be seeked by intent NR.  ie. seeking to 3 and reading
+  will return intent #3 and after.  Because intents are never
+  destroyed while ioblame is enabled, this allows userland tool to
+  discover new intents since last reading.  Seeking to the number of
+  currently known intents and reading returns only the newly created
+  intents.
+
+  At least one inotify IN_MODIFY event is generated after a new intent
+  is created.
+
+
+4. Trace examples
+
+All information ioblame gathers is available through
+ioblame:ioblame_io tracing event.  The outputs in the following
+examples are reformatted and annoated.
+
+4-1. ls, touch and sync - on an ext4 FS w/o journal
+
+- sector=69896 size=4096 rw=META|PRIO wait_nsec=45244 io_nsec=11263878
+  pid=952 intent=8 dev=8:17 ino=2 gen=0
+
+  pid 952 (ls) issues 4k META|PRIO read on /dev/sdb1's root directory
+  with intent 8 to read directory entries.
+
+  #8 modifier=0x0
+  [ffffffff813981b8] generic_make_request+0x18/0x100
+  [ffffffff81398314] submit_bio+0x74/0x100
+  [ffffffff811c6b9b] submit_bh+0xeb/0x130
+  [ffffffff811c851e] ll_rw_block+0xae/0xb0
+  [ffffffff81265703] ext4_bread+0x43/0x80
+  [ffffffff8126b458] htree_dirblock_to_tree+0x38/0x190
+  [ffffffff8126b655] ext4_htree_fill_tree+0xa5/0x260
+  [ffffffff81259c76] ext4_readdir+0x116/0x5e0
+  [ffffffff811a7ec0] vfs_readdir+0xb0/0xd0
+  [ffffffff811a8049] sys_getdents+0x89/0xf0
+  [ffffffff81aaca6b] system_call_fastpath+0x16/0x1b
+
+- sector=4232 size=4096 rw= wait_nsec=69052 io_nsec=475710
+  pid=953 intent=14 dev=8:16 ino=0 gen=0
+
+  pid 953 (touch) issues 4k read with intent 14 during open(2).
+
+  #14 modifier=0x0
+  [ffffffff813981b8] generic_make_request+0x18/0x100
+  [ffffffff81398314] submit_bio+0x74/0x100
+  [ffffffff811c6b9b] submit_bh+0xeb/0x130
+  [ffffffff811c8425] bh_submit_read+0x35/0x80
+  [ffffffff8125b29b] ext4_read_inode_bitmap+0x18b/0x3f0
+  [ffffffff8125bf85] ext4_new_inode+0x355/0x10b0
+  [ffffffff81269a7a] ext4_create+0x9a/0x120
+  [ffffffff811a366c] vfs_create+0x8c/0xe0
+  [ffffffff811a4616] do_last+0x776/0x8e0
+  [ffffffff811a4858] path_openat+0xd8/0x410
+  [ffffffff811a4ca9] do_filp_open+0x49/0xa0
+  [ffffffff811926a7] do_sys_open+0x107/0x1e0
+  [ffffffff811927c0] sys_open+0x20/0x30
+  [ffffffff81aaca6b] system_call_fastpath+0x16/0x1b
+
+- sector=4360 size=4096 rw=WRITE wait_nsec=28998035 io_nsec=768370
+  pid=953 intent=11 dev=8:17 ino=14 gen=3151897938
+
+  touch dirtied inode 14 and the following sync forces writeback.
+  The IO is attributed to the dirtier.  Note the non-zero modifier is
+  indicating WB_REASON_SYNC.
+
+  #11 modifier=0x10000002
+  [ffffffff811c0710] __mark_inode_dirty+0x220/0x330
+  [ffffffff8125feeb] ext4_setattr+0x26b/0x4d0
+  [ffffffff811b0f2a] notify_change+0x10a/0x2b0
+  [ffffffff811c52de] utimes_common+0xde/0x190
+  [ffffffff811c5431] do_utimes+0xa1/0xf0
+  [ffffffff811c55a6] sys_utimensat+0x36/0xb0
+  [ffffffff81aaca6b] system_call_fastpath+0x16/0x1b
+
+
+4-2. copying a 1M file from another filesystem and waiting a bit
+
+- sector=2056 size=4096 rw=WRITE wait_nsec=151425 io_nsec=584466
+  pid=1004 intent=24 dev=8:16 ino=0 gen=0
+
+  flush-8:16 starting writeback w/ WB_REASON_BACKGROUND.  This
+  repeats a couple times.
+
+  #24 modifier=0x10000000
+  [ffffffff813981b8] generic_make_request+0x18/0x100
+  [ffffffff81398314] submit_bio+0x74/0x100
+  [ffffffff811c6b9b] submit_bh+0xeb/0x130
+  [ffffffff811ca410] __block_write_full_page+0x210/0x3b0
+  [ffffffff811ca6a0] block_write_full_page_endio+0xf0/0x140
+  [ffffffff811ca705] block_write_full_page+0x15/0x20
+  [ffffffff811ce438] blkdev_writepage+0x18/0x20
+  [ffffffff81148f1a] __writepage+0x1a/0x50
+  [ffffffff81149ae6] write_cache_pages+0x206/0x4f0
+  [ffffffff81149e24] generic_writepages+0x54/0x80
+  [ffffffff81149e74] do_writepages+0x24/0x40
+  [ffffffff811bf301] writeback_single_inode+0x1a1/0x600
+  [ffffffff811c01db] writeback_sb_inodes+0x1ab/0x280
+  [ffffffff811c0b8e] __writeback_inodes_wb+0x9e/0xd0
+  [ffffffff811c0ea3] wb_writeback+0x243/0x3a0
+  [ffffffff811c115a] wb_do_writeback+0x15a/0x2b0
+  [ffffffff811c138a] bdi_writeback_thread+0xda/0x330
+  [ffffffff810bc286] kthread+0xb6/0xc0
+  [ffffffff81aadff4] kernel_thread_helper+0x4/0x10
+
+- sector=4360 size=4096 rw=WRITE wait_nsec=781396 io_nsec=894147
+  pid=1017 intent=25 dev=8:17 ino=12 gen=3151897939
+
+  Writeback got to inode 12 which was created and written to by cp.
+  This is inode writeback.
+
+  #25 modifier=0x10000000
+  [ffffffff811c0710] __mark_inode_dirty+0x220/0x330
+  [ffffffff811c7e5b] generic_write_end+0x6b/0xa0
+  [ffffffff8126191a] ext4_da_write_end+0xfa/0x350
+  [ffffffff8113f168] generic_file_buffered_write+0x188/0x2b0
+  [ffffffff81141608] __generic_file_aio_write+0x238/0x460
+  [ffffffff811418a8] generic_file_aio_write+0x78/0xf0
+  [ffffffff8125a4cf] ext4_file_write+0x6f/0x2a0
+  [ffffffff81194112] do_sync_write+0xe2/0x120
+  [ffffffff81194c08] vfs_write+0xc8/0x180
+  [ffffffff81194dc1] sys_write+0x51/0x90
+  [ffffffff81aaca6b] system_call_fastpath+0x16/0x1b
+
+- sector=268288 size=524288 rw=WRITE wait_nsec=461543 io_nsec=3180190
+  pid=1017 intent=27 dev=8:17 ino=12 gen=3151897939
+
+  The first half of data.
+
+  #27 modifier=0x10000000
+  [ffffffff811c79cc] __set_page_dirty+0x4c/0xd0
+  [ffffffff811c7ab6] mark_buffer_dirty+0x66/0xa0
+  [ffffffff811c7b99] __block_commit_write+0xa9/0xe0
+  [ffffffff811c7da2] block_write_end+0x42/0x90
+  [ffffffff811c7e23] generic_write_end+0x33/0xa0
+  [ffffffff8126191a] ext4_da_write_end+0xfa/0x350
+  [ffffffff8113f168] generic_file_buffered_write+0x188/0x2b0
+  [ffffffff81141608] __generic_file_aio_write+0x238/0x460
+  [ffffffff811418a8] generic_file_aio_write+0x78/0xf0
+  [ffffffff8125a4cf] ext4_file_write+0x6f/0x2a0
+  [ffffffff81194112] do_sync_write+0xe2/0x120
+  [ffffffff81194c08] vfs_write+0xc8/0x180
+  [ffffffff81194dc1] sys_write+0x51/0x90
+  [ffffffff81aaca6b] system_call_fastpath+0x16/0x1b
+
+- sector=269312 size=524288 rw=WRITE wait_nsec=364198 io_nsec=5667553
+  pid=1017 intent=27 dev=8:17 ino=12 gen=3151897939
+
+  And the second half.
+
+
+4-3. dd if=/dev/zero of=testfile bs=128k count=4 oflag=direct
+
+- sector=266496 size=131072 rw=WRITE|SYNC wait_nsec=48180 io_nsec=1066758
+  pid=1042 intent=34 dev=8:17 ino=12 gen=3151897940
+
+  First chunk.
+
+  #34 modifier=0x0
+  [ffffffff813981b8] generic_make_request+0x18/0x100
+  [ffffffff81398314] submit_bio+0x74/0x100
+  [ffffffff811d1c45] __blockdev_direct_IO+0x21b5/0x3830
+  [ffffffff8129a7a1] ext4_ind_direct_IO+0x121/0x470
+  [ffffffff812612ee] ext4_direct_IO+0x23e/0x400
+  [ffffffff81141308] generic_file_direct_write+0xc8/0x190
+  [ffffffff811416ab] __generic_file_aio_write+0x2db/0x460
+  [ffffffff811418a8] generic_file_aio_write+0x78/0xf0
+  [ffffffff8125a4cf] ext4_file_write+0x6f/0x2a0
+  [ffffffff81194112] do_sync_write+0xe2/0x120
+  [ffffffff81194c08] vfs_write+0xc8/0x180
+  [ffffffff81194dc1] sys_write+0x51/0x90
+  [ffffffff81aaca6b] system_call_fastpath+0x16/0x1b
+
+- sector=266752 size=131072 rw=WRITE|SYNC wait_nsec=15155 io_nsec=1086987
+  pid=1042 intent=34 dev=8:17 ino=12 gen=3151897940
+
+  Second.
+
+- sector=267008 size=131072 rw=WRITE|SYNC wait_nsec=22694 io_nsec=1092836
+  pid=1042 intent=34 dev=8:17 ino=12 gen=3151897940
+
+  Third.
+
+- sector=267264 size=131072 rw=WRITE|SYNC wait_nsec=15852 io_nsec=1021868
+  pid=1042 intent=34 dev=8:17 ino=12 gen=3151897940
+
+  Fourth.
+
+...
+
+- sector=4360 size=4096 rw=WRITE wait_nsec=1378342 io_nsec=828771
+  pid=1042 intent=35 dev=8:17 ino=12 gen=3151897940
+
+  After a while, inode is written back with WB_REASON_PERIODIC.
+
+  #35 modifier=0x10000003
+  [ffffffff811c0710] __mark_inode_dirty+0x220/0x330
+  [ffffffff8129611a] ext4_mb_new_blocks+0xea/0x5a0
+  [ffffffff8128b22e] ext4_ext_map_blocks+0x1c0e/0x1d80
+  [ffffffff812638d1] ext4_map_blocks+0x1b1/0x260
+  [ffffffff81263a28] _ext4_get_block+0xa8/0x160
+  [ffffffff81263b46] ext4_get_block+0x16/0x20
+  [ffffffff811d0460] __blockdev_direct_IO+0x9d0/0x3830
+  [ffffffff8129a7a1] ext4_ind_direct_IO+0x121/0x470
+  [ffffffff812612ee] ext4_direct_IO+0x23e/0x400
+  [ffffffff81141308] generic_file_direct_write+0xc8/0x190
+  [ffffffff811416ab] __generic_file_aio_write+0x2db/0x460
+  [ffffffff811418a8] generic_file_aio_write+0x78/0xf0
+  [ffffffff8125a4cf] ext4_file_write+0x6f/0x2a0
+  [ffffffff81194112] do_sync_write+0xe2/0x120
+  [ffffffff81194c08] vfs_write+0xc8/0x180
+  [ffffffff81194dc1] sys_write+0x51/0x90
+  [ffffffff81aaca6b] system_call_fastpath+0x16/0x1b
+
+
+5. Notes
+
+* By the time ioblame reports IOs or counters, the task which gets
+  charged might have already exited and this is why ioblame prints
+  task command in some reports but not in others.  Userland tool is
+  advised to use combination of live task listing and process
+  accounting to match pid's to commands.
+
+* dev:ino:gen can be mapped to filename without scanning the whole
+  filesystem by constructing FS-specific filehandle, opening it with
+  open_by_handle_at(2) and then readlink(2)ing /proc/self/FD.  This
+  will return full path as long as the dentry is in cache, which is
+  likely if data acquisition and mapping don't happen too long after
+  IOs.
+
+* At this point, it's mostly tested with ext4 w/o journal.  Metadata
+  dirtier tracking w/ journal needs improvements.
+
+
+6. Overheads
+
+On x86_64, role is 104 bytes, intent 32 + 8 * stack_depth and act 72
+bytes.  Intents are allocated using kzalloc() and there shouldn't be
+too many of them.  Both roles and acts have their own kmem_cache and
+can be monitored via /proc/slabinfo.
+
+Each counter occupy 32 * nr_counters and is aligned to cacheline.
+Counters are allocated only as necessary.  iob_counters kmem_cache is
+dynamically created on enable.
+
+The size of page frame number -> dirtier mapping table is proportional
+to the amount of available physical memory.  If max_acts <= 65536,
+2bytes are used per PAGE_SIZE.  With 4k page, at most ~0.049% can be
+used.  If max_acts > 65536, 4bytes are used doubling the percentage to
+~0.098%.  The table also grows dynamically.
+
+There are also indexing data structures used - hash tables, id[ra]s
+and a radix tree.  There are three hash tables, each sized according
+to max_{roles|intents|acts}.  The maximum memory usage by hash tables
+is sizeof(void *) * (max_roles + max_intents + max_acts).  Memory used
+by other indexing structures should be negligible.
+
+Preliminary tests w/ fio ssd-test on loopback device on tmpfs, which
+is purely CPU cycle bound, shows ~20% throughput hit.
+
+*** TODO: add performance testing results and explain involved CPU
+    overheads.

include/linux/blk_types.h +4 -0

index 4053cbd..2ee4e3b 100644
@@ -8,6 +8,7 @@
 #ifdef CONFIG_BLOCK
 
 #include <linux/types.h>
+#include <linux/ioblame.h>
 
 struct bio_set;
 struct bio;

@@ -69,6 +70,9 @@ struct bio {
 #if defined(CONFIG_BLK_DEV_INTEGRITY)
 	struct bio_integrity_payload *bi_integrity;  /* data integrity */
 #endif
+#if defined(CONFIG_IO_BLAME) || defined(CONFIG_IO_BLAME_MODULE)
+	struct iob_io_info	bi_iob_info;
+#endif
 
 	bio_destructor_t	*bi_destructor;	/* destructor */

include/linux/fs.h +3 -0

index 7aacf31..7a43f9a 100644
@@ -835,6 +835,9 @@ struct inode {
 	atomic_t		i_readcount; /* struct files open RO */
 #endif
 	void			*i_private; /* fs or device private pointer */
+#if defined(CONFIG_IO_BLAME) || defined(CONFIG_IO_BLAME_MODULE)
+	union iob_id		i_iob_act;
+#endif
 };
 
 static inline int inode_unhashed(struct inode *inode)

include/linux/genhd.h +3 -0

index 9d0e0b5..237db65 100644
@@ -190,6 +190,9 @@ struct gendisk {
 #ifdef  CONFIG_BLK_DEV_INTEGRITY
 	struct blk_integrity *integrity;
 #endif
+#if defined(CONFIG_IO_BLAME) || defined(CONFIG_IO_BLAME_MODULE)
+	bool iob_enabled;
+#endif
 	int node_id;
 };

include/linux/ioblame.h new file +72 -0

72 lines not on this page · raw message

include/trace/events/ioblame.h new file +94 -0

94 lines not on this page · raw message

kernel/trace/Kconfig +12 -0

index cd31345..ccc7c12 100644
@@ -368,6 +368,18 @@ config BLK_DEV_IO_TRACE
 
 	  If unsure, say N.
 
+config IO_BLAME
+	tristate "Enable io-blame tracer"
+	depends on SYSFS
+	depends on BLOCK
+	select TRACEPOINTS
+	select STACKTRACE
+	help
+	  Say Y here if you want to enable IO tracer with dirtier
+	  tracking.  See Documentation/trace/ioblame.txt.
+
+	  If unsure, say N.
+
 config KPROBE_EVENT
 	depends on KPROBES
 	depends on HAVE_REGS_AND_STACK_ACCESS_API

kernel/trace/Makefile +1 -0

index 5f39a07..408cd1a 100644
@@ -46,6 +46,7 @@ obj-$(CONFIG_BLK_DEV_IO_TRACE) += blktrace.o
 ifeq ($(CONFIG_BLOCK),y)
 obj-$(CONFIG_EVENT_TRACING) += blktrace.o
 endif
+obj-$(CONFIG_IO_BLAME) += ioblame.o
 obj-$(CONFIG_EVENT_TRACING) += trace_events.o
 obj-$(CONFIG_EVENT_TRACING) += trace_export.o
 obj-$(CONFIG_FTRACE_SYSCALLS) += trace_syscalls.o

kernel/trace/ioblame.c new file +2279 -0

2,279 lines not on this page · raw message

Signature · 1 line

1.7.3.1

Namhyung Kim

2012-01-11 06:15 UTC #22 lore raw

Re: [PATCH RESEND 9/9] block, trace: implement ioblame - IO tracer with origin tracking

Quoted 21 lines · Tejun Heo

Implement ioblame, which can attribute each IO to its origin and export the information using a tracepoint.
Operations which may eventually cause IOs and IO operations themselves are identified and tracked primarily by their stack traces along with the task and the target file (dev:ino:gen). On each IO completion, ioblame knows why that specific IO happened and exports the information via ioblame:ioblame_io tracepoint.
While ioblame adds fields to a few fs and block layer objects, all logic is well insulated inside ioblame proper and all hooking goes through well defined tracepoints and doesn't add any significant maintenance overhead.
For details, please read Documentation/trace/ioblame.txt.
-v2: Namhyung pointed out that all the information available at IO
completion can be exported via tracepoint and letting userland do whatever it wants to do with that would be better. Stripped out in-kernel statistics gathering.

Quoted 8 lines

Now that everything is exported through tracepoint, iolog and counters_pipe[_pipe] are unnecessary. Removed. intents_bin too is removed.
As data collection no longer requires polling, ioblame/intents is updated to generate inotify IN_MODIFY event after a new intent is created.

Hi Tejun,

How about adding another tracepoint for intent creation to provide raw data as well, somewhere in iob_get_intent() or iob_intent_create() maybe? It can be useful to get those data for further processing IMHO.

Thanks,
Namhyung Kim

Tejun Heo

author

2012-01-11 17:06 UTC #23 lore raw

Re: [PATCH RESEND 9/9] block, trace: implement ioblame - IO tracer with origin tracking

Hello,

Quoted 4 lines · Namhyung Kim

How about adding another tracepoint for intent creation to provide raw data as well, somewhere in iob_get_intent() or iob_intent_create() maybe? It can be useful to get those data for further processing IMHO.

While I don't particularly object to that, information and notification (via inotify) for that is already available via ioblame/intents file which we need regardless of the new tracepoint, so it's kinda redundant, isn't it?

Thanks.

Signature · 1 line

tejun

Namhyung Kim

2012-01-12 01:05 UTC #24 lore raw

Re: [PATCH RESEND 9/9] block, trace: implement ioblame - IO tracer with origin tracking

Hi,

Quoted 8 lines · Tejun Heo

Hello,
Quoted 4 lines · Namhyung Kim
How about adding another tracepoint for intent creation to provide raw data as well, somewhere in iob_get_intent() or iob_intent_create() maybe? It can be useful to get those data for further processing IMHO.

Quoted 7 lines

While I don't particularly object to that, information and notification (via inotify) for that is already available via ioblame/intents file which we need regardless of the new tracepoint, so it's kinda redundant, isn't it?
Thanks.

Yes. But that's a text-based so it might fit better to simple use cases. If we need further post processing based on intents, it could be better off having binary interface IMHO. And since we already use tracepoints anyway, wouldn't it be good to avoid adding another layer of interface or complexity?

Thanks,
Namhyung Kim

Tejun Heo

author

2012-01-12 01:14 UTC #25 lore raw

Re: [PATCH RESEND 9/9] block, trace: implement ioblame - IO tracer with origin tracking

Hello,

Quoted 5 lines · Namhyung Kim

Yes. But that's a text-based so it might fit better to simple use cases. If we need further post processing based on intents, it could be better off having binary interface IMHO. And since we already use tracepoints anyway, wouldn't it be good to avoid adding another layer of interface or complexity?

The thing is that all entries are needed for any post processing, not only the new ones. To use TP, either there needs to be special "trigger the TP for all existing entries" switch somewhere or ioblame/intents file needs to be read for existing entries. Even then, TPs aren't guaranteed to be reliable. There's no way to detect overflow and re-emit the event. It just isn't the right interface. The previous version had intents_bin file in binary format but given that there aren't too many of intents, binary interface didn't seem necessary and ripped it out. Adding it back isn't difficult at all but I'm not sure that's a good idea. It's not like parsing the intents file is difficult.

Thanks.

Signature · 1 line

tejun

Namhyung Kim

2012-01-12 01:35 UTC #26 lore raw

Re: [PATCH RESEND 9/9] block, trace: implement ioblame - IO tracer with origin tracking

Hello,

Quoted 21 lines · Tejun Heo

Hello,
Quoted 5 lines · Namhyung Kim
Yes. But that's a text-based so it might fit better to simple use cases. If we need further post processing based on intents, it could be better off having binary interface IMHO. And since we already use tracepoints anyway, wouldn't it be good to avoid adding another layer of interface or complexity?
The thing is that all entries are needed for any post processing, not only the new ones. To use TP, either there needs to be special "trigger the TP for all existing entries" switch somewhere or ioblame/intents file needs to be read for existing entries. Even then, TPs aren't guaranteed to be reliable. There's no way to detect overflow and re-emit the event. It just isn't the right interface. The previous version had intents_bin file in binary format but given that there aren't too many of intents, binary interface didn't seem necessary and ripped it out. Adding it back isn't difficult at all but I'm not sure that's a good idea. It's not like parsing the intents file is difficult.

Quoted 2 lines

Thanks.

Why do we need to trigger the TP for existing ones as we keep each entry at its creation? Maybe I'm missing something?

Thanks,
Namhyung Kim

Tejun Heo

author

2012-01-12 01:37 UTC #27 lore raw

Re: [PATCH RESEND 9/9] block, trace: implement ioblame - IO tracer with origin tracking

Hello,

Quoted 2 lines · Namhyung Kim

Why do we need to trigger the TP for existing ones as we keep each entry at its creation? Maybe I'm missing something?

If a userland program starts to watch the TP after some intents are created, how is it gonna find out the existing ones?

Signature · 1 line

tejun

Namhyung Kim

2012-01-12 01:41 UTC #28 lore raw

Re: [PATCH RESEND 9/9] block, trace: implement ioblame - IO tracer with origin tracking

Quoted 9 lines · Tejun Heo

Hello,
Quoted 2 lines · Namhyung Kim
Why do we need to trigger the TP for existing ones as we keep each entry at its creation? Maybe I'm missing something?
If a userland program starts to watch the TP after some intents are created, how is it gonna find out the existing ones?

Hi,

OK, but that can be controlled from userspace, I guess? Do we have to care about that?

Thanks,
Namhyung Kim

Namhyung Kim

2012-01-12 01:41 UTC #29 lore raw

Re: [PATCH RESEND 9/9] block, trace: implement ioblame - IO tracer with origin tracking

In reply to Tejun Heo

Quoted 9 lines · Tejun Heo

Hello,
Quoted 2 lines · Namhyung Kim
Why do we need to trigger the TP for existing ones as we keep each entry at its creation? Maybe I'm missing something?
If a userland program starts to watch the TP after some intents are created, how is it gonna find out the existing ones?

Hi,

OK, but that can be controlled from userspace, I guess? Do we have to care about that?

Thanks,
Namhyung Kim

Tejun Heo

author

2012-01-12 01:44 UTC #30 lore raw

Re: [PATCH RESEND 9/9] block, trace: implement ioblame - IO tracer with origin tracking

Quoted 2 lines · Namhyung Kim

OK, but that can be controlled from userspace, I guess? Do we have to care about that?

Otherwise, it's gonna be a pretty silly interface. If you want to watch the TP, you have to restart the whole thing which also implies intent number would change. And there still is the problem of losing new intent events due to overflow. It just isn't the right interface for the task.

Signature · 1 line

tejun

Namhyung Kim

2012-01-12 02:19 UTC #31 lore raw

Re: [PATCH RESEND 9/9] block, trace: implement ioblame - IO tracer with origin tracking

Quoted 10 lines · Tejun Heo

Quoted 2 lines · Namhyung Kim
OK, but that can be controlled from userspace, I guess? Do we have to care about that?
Otherwise, it's gonna be a pretty silly interface. If you want to watch the TP, you have to restart the whole thing which also implies intent number would change. And there still is the problem of losing new intent events due to overflow. It just isn't the right interface for the task.

I understood it's unreliable. BTW I think that sane userland tool must start both of ioblame_io and ioblame_create_intent, say, TPs at once - prior to triggering ioblame/enable, obviously. The ioblame/intents can be used as a backup just in case.

Thanks,
Namhyung Kim

Tejun Heo

author

2012-01-12 02:24 UTC #32 lore raw

Re: [PATCH RESEND 9/9] block, trace: implement ioblame - IO tracer with origin tracking

Hello,

Quoted 4 lines · Namhyung Kim

I understood it's unreliable. BTW I think that sane userland tool must start both of ioblame_io and ioblame_create_intent, say, TPs at once - prior to triggering ioblame/enable, obviously. The ioblame/intents can be used as a backup just in case.

So, regardless of create_intent TP, the tool has to have code to read ioblame/intents, right? I just don't see what the benefit of having an extra interface which can't even be used by itself would be.

Thanks.

Signature · 1 line

tejun

Tejun Heo

author

2012-01-11 18:08 UTC #33 lore raw

Re: [PATCH RESEND 9/9] block, trace: implement ioblame - IO tracer with origin tracking

In reply to Tejun Heo

Quoted 21 lines · Tejun Heo

Implement ioblame, which can attribute each IO to its origin and export the information using a tracepoint.
Operations which may eventually cause IOs and IO operations themselves are identified and tracked primarily by their stack traces along with the task and the target file (dev:ino:gen). On each IO completion, ioblame knows why that specific IO happened and exports the information via ioblame:ioblame_io tracepoint.
While ioblame adds fields to a few fs and block layer objects, all logic is well insulated inside ioblame proper and all hooking goes through well defined tracepoints and doesn't add any significant maintenance overhead.
For details, please read Documentation/trace/ioblame.txt.
-v2: Namhyung pointed out that all the information available at IO
completion can be exported via tracepoint and letting userland do whatever it wants to do with that would be better. Stripped out in-kernel statistics gathering.

Quoted 7 lines

Now that everything is exported through tracepoint, iolog and counters_pipe[_pipe] are unnecessary. Removed. intents_bin too is removed.
As data collection no longer requires polling, ioblame/intents is updated to generate inotify IN_MODIFY event after a new intent is created.

One planned update is exporting issuer and dirtier separately. Currently dirtier, if exists, simply overrides issuer as it wasn't useful for in-kernel statistics anyway. With that gone, I think it makes much more sense to expose both of them.

Thanks.

Signature · 1 line

tejun

Frederic Weisbecker

2012-01-11 14:40 UTC #34 lore raw

In reply to Tejun Heo

Hi Tejun,

Quoted 83 lines · Tejun Heo

Hello, guys.
Even with blktrace and tracepoints, getting insight into the IOs going on a system is very challenging. A lot of IO operations happen long after the action which triggered the IO finished and the overall asynchronous nature of IO operations make it difficult to trace back the origin of a given IO.
ioblame is an attempt at providing better visibility into overall IO behavior. ioblame hooks into various tracepoints and tries to determine who caused any given IO how and charges the IO accordingly.
On each IO completion, ioblame knows who to charge the IO (task), how the IO got triggered (stack trace at the point of triggering, be it page, inode dirtying or direct IO issue) and various information about the IO itself (offset, size, how long it took and so on). ioblame exports this information via ioblame:ioblame_io tracepoint.
For more details, please read Documentation/trace/ioblame.txt.
Changes from the last take[L] are,
* Per Namhyung's suggestion, in-kernel statistics gathering stripped out. All information is now exported through a tracepoint per each IO. This makes a lot of stuff unnecessary and over 1500 lines of code have been removed.
* block_bio_complete tracepoint patch will result in duplicate BLK_TA_COMPLETE notifications. Namhyung is working on proper solution. For now, SOB is removed from the patch.
* Trace filter is no longer used and patches dropped from the series.
* Rebased on top of v3.2.
This patchset contains the following 9 patches.
0001-block-abstract-disk-iteration-into-disk_iter.patch 0002-block-block_bio_complete-tracepoint-was-missing.patch 0003-block-add-req-to-bio_-front-back-_merge-tracepoints.patch 0004-writeback-move-struct-wb_writeback_work-to-writeback.patch 0005-writeback-add-more-tracepoints.patch 0006-block-add-block_touch_buffer-tracepoint.patch 0007-vfs-add-fcheck-tracepoint.patch 0008-stacktrace-implement-save_stack_trace_quick.patch 0009-block-trace-implement-ioblame-IO-tracer-with-origin-.patch
0001-0004 update block layer in preparation.
0005-0007 add more tracepoints along the IO stack.
0008 adds nimbler backtrace dump function as ioblame dumps stacktrace extremely frequently.
0009 implements ioblame.
This is still in early stage and I haven't done much performance analysis yet. Tentative testing shows it adds ~20% CPU overhead when used on memory backed loopback device.
The patches are on top of v3.2 and available in the following git branch.
git://git.kernel.org/pub/scm/linux/kernel/git/tj/misc.git review-ioblame
diffstat follows.
 Documentation/trace/ioblame.txt   |  476 +++++++
 arch/x86/include/asm/stacktrace.h |    2 
 arch/x86/kernel/stacktrace.c      |   40 
 block/blk-core.c                  |    5 
 block/genhd.c                     |   98 +
 fs/bio.c                          |    3 
 fs/fs-writeback.c                 |   34 
 fs/super.c                        |    2 
 include/linux/blk_types.h         |    4 
 include/linux/buffer_head.h       |    7 
 include/linux/fdtable.h           |    3 
 include/linux/fs.h                |    3 
 include/linux/genhd.h             |   13 
 include/linux/ioblame.h           |   72 +
 include/linux/stacktrace.h        |    6 
 include/linux/writeback.h         |   18 

Quoted 8 lines

 include/trace/events/block.h      |   70 -
 include/trace/events/vfs.h        |   40 
 include/trace/events/writeback.h  |  113 +
 kernel/stacktrace.c               |    6 
 kernel/trace/Kconfig              |   12 
 kernel/trace/Makefile             |    1 
 kernel/trace/blktrace.c           |    2 
 kernel/trace/ioblame.c            | 2279 ++++++++++++++++++++++++++++++++++++++

I think this has been asked before. So sorry for asking twice.

But I'm wondering why the post processing is made from the kernel. Do you think it would be possible to pull that out in userspace. We have some nice scripting framework for post processing of trace events in perf tools for example.

If it's not possible please tell us why. We really would like to avoid adding such a big piece of code in the tracing subsystem if possible.

Thanks.

Quoted 9 lines

 mm/page-writeback.c               |    2 
 25 files changed, 3244 insertions(+), 67 deletions(-)
Thanks.
--
tejun
[L] http://thread.gmane.org/gmane.linux.kernel/1235937

Tejun Heo

author

2012-01-11 17:03 UTC #35 lore raw

Hello, Frederic.

Quoted 1 line · Frederic Weisbecker

I think this has been asked before. So sorry for asking twice.

I thought Namhyung was primarily asking about stat gathering which is chopped now.

Quoted 6 lines

But I'm wondering why the post processing is made from the kernel. Do you think it would be possible to pull that out in userspace. We have some nice scripting framework for post processing of trace events in perf tools for example.
If it's not possible please tell us why. We really would like to avoid adding such a big piece of code in the tracing subsystem if possible.

I suppose you're talking about the state tracking by post-processing, right?

* ioblame tracks stack trace for each dirtying operation. If we don't want further state tracking in kernel, we would have to exort the whole stack trace on each dirtying operation which can be high frequency. Also, is there an efficient way to export variable length data via TPs? If so, it can be somewhat better but still not very good.

* Even if we track dirtying state in userland, when an io is issued, it needs to be mapped back to the dirtying actions. If the dirtier state is in userland, we have to export all physaddrs of pages in the IO so that userland can match them up and clear dirtied states. Again, the same problem.

* As implemented, most of state tracking should be fairly stable and shouldn't require much modification as code base evolves but it's still trying to extract pretty high level semantics from disjoint events across multiple layers. It's reasonable to expect future changes would require updates to how those semantics are established. Exporting higher level semantics, we don't get tied to keeping the relevant raw tracepoints and, more importantly, their exact interactions stable.

* It isn't trivial but still pretty straight-forward. Most of what it does is abbreviating strack trace to an identifier (which BTW could be useful for other tracing purposes and may be worthwhile to generalize) and tracking page and inode dirtiers using those identifiers. It stays mostly out of the way and doesn't noticeably harm maintainability. It fits the role of in-kernel tracers - building information from domain knowledge and states and exporting to userland in sensible form.

Thanks.

Signature · 1 line

tejun

David Sharp

2012-01-11 22:46 UTC #36 lore raw

Quoted 18 lines · Tejun Heo

Hello, Frederic.
Quoted 1 line · Frederic Weisbecker
I think this has been asked before. So sorry for asking twice.
I thought Namhyung was primarily asking about stat gathering which is chopped now.
Quoted 6 lines
But I'm wondering why the post processing is made from the kernel. Do you think it would be possible to pull that out in userspace. We have some nice scripting framework for post processing of trace events in perf tools for example.
If it's not possible please tell us why. We really would like to avoid adding such a big piece of code in the tracing subsystem if possible.
I suppose you're talking about the state tracking by post-processing, right?

Quoted 6 lines

* ioblame tracks stack trace for each dirtying operation. If we don't want further state tracking in kernel, we would have to exort the whole stack trace on each dirtying operation which can be high frequency. Also, is there an efficient way to export variable length data via TPs? If so, it can be somewhat better but still not very good.

See __dynamic_array. It imposes a 4-byte overhead to store the offset and length of data within the trace event.

That said, I'm always very wary of adding large amounts of data to tracepoints, especially if they are high frequency, as that just leads to faster ring buffer exhaustion.

Quoted 29 lines

* Even if we track dirtying state in userland, when an io is issued, it needs to be mapped back to the dirtying actions. If the dirtier state is in userland, we have to export all physaddrs of pages in the IO so that userland can match them up and clear dirtied states. Again, the same problem.
* As implemented, most of state tracking should be fairly stable and shouldn't require much modification as code base evolves but it's still trying to extract pretty high level semantics from disjoint events across multiple layers. It's reasonable to expect future changes would require updates to how those semantics are established. Exporting higher level semantics, we don't get tied to keeping the relevant raw tracepoints and, more importantly, their exact interactions stable.
* It isn't trivial but still pretty straight-forward. Most of what it does is abbreviating strack trace to an identifier (which BTW could be useful for other tracing purposes and may be worthwhile to generalize) and tracking page and inode dirtiers using those identifiers. It stays mostly out of the way and doesn't noticeably harm maintainability. It fits the role of in-kernel tracers - building information from domain knowledge and states and exporting to userland in sensible form.
Thanks.
--
tejun