ioblame: statistical IO analyzer

RFC PATCH In review Tejun Heo 2 participants 18 messages Jan 5, 2012 – Jan 9, 2012

Subsystems (8)

Memory management Documentation x86 VFS +4 more subsystems

lore

Share & tools

lore

Tejun Heo

author

2012-01-05 23:43 UTC #0 lore raw

RFC PATCH 1/1 ioblame: statistical IO analyzer

This is re-post. The original posting was on Dec 15th but it was missing cc to LKML. I got some responses on that thread so didn't suspect LKML was missing. If you're getting it the second time. My apologies.

Stuff pointed out in the original thread are...

* Is the quick variant of backtrace gathering really necessary? - Still need to get performance numbers.

* TRACE_EVENT_CONDITION() can be used in some places. - Will be updated.

Original message follows. Thanks.

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 collects this information into histograms which is configurable from userland using debugfs interface.

For example, using ioblame, user can acquire information like "this task triggered IO with this stack trace on this file with the following offset distribution".

For more details, please read Documentation/trace/ioblame.txt, which I'll append to this message too for discussion.

This patchset contains the following 11 patches.

0001-trace_event_filter-factorize-filter-creation.patch 0002-trace_event_filter-add-trace_event_filter_-interface.patch 0003-block-block_bio_complete-tracepoint-was-missing.patch 0004-block-add-req-to-bio_-front-back-_merge-tracepoints.patch 0005-block-abstract-disk-iteration-into-disk_iter.patch 0006-writeback-move-struct-wb_writeback_work-to-writeback.patch 0007-writeback-add-more-tracepoints.patch 0008-block-add-block_touch_buffer-tracepoint.patch 0009-vfs-add-fcheck-tracepoint.patch 0010-stacktrace-implement-save_stack_trace_quick.patch 0011-block-trace-implement-ioblame-IO-statistical-analyze.patch

0001-0002 export trace_event_filter so that ioblame can use it too.

0003 adds back block_bio_complete TP invocation, which got lost somehow. This probably makes sense as fix patch for 3.2.

0004-0006 update block layer in preparation. 0005 probably makes sense as a standalone patch too.

0007-0009 add more tracepoints along the IO stack.

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

0011 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 mainline (42ebfc61cf "Merge branch 'stable...git/konrad/xen'") and perf/core (74eec26fac "perf tools: Add ability to synthesize event according to a sample").

It's also 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    |  646 ++++++
 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          |    7 
 include/linux/buffer_head.h        |    7 
 include/linux/fdtable.h            |    3 
 include/linux/fs.h                 |    3 
 include/linux/genhd.h              |   14 
 include/linux/ioblame.h            |   95 +
 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               |   11 
 kernel/trace/Makefile              |    1 
 kernel/trace/blktrace.c            |    2 
 kernel/trace/ioblame.c             | 3479 +++++++++++++++++++++++++++++++++++++
 kernel/trace/trace.h               |    6 
 kernel/trace/trace_events_filter.c |  379 ++--
 mm/page-writeback.c                |    2 
 27 files changed, 4872 insertions(+), 220 deletions(-)

Thanks.

--
tejun

ioblame - statistical IO analyzer with origin tracking

December, 2011 Tejun Heo <[email protected]>

CONTENTS

1. Introduction
2. Overall design
3. Debugfs interface
3-1. Configuration
3-2. Monitoring
3-3. Data acquisition
4. Notes
5. 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 statistical IO analyzer which can track and record origin of IOs. It keeps track of who dirtied pages and inodes, and, on an actual IO, attributes it to the originator of the IO.

The design goals of ioblame are

* Minimally invasive - Analyzer 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. Analyzer 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.

* Dynamic and customizable - There are many different aspects of IOs which can be irrelevant or interesting depending on the situation. From analysis point of view, always recording all collected data would be ideal but is very wasteful in most situations. ioblame lets users decide what information to gather so that they can acquire relevant information without wasting resources unnecessarily. ioblame also allows dynamic configuration while the analyzer is online which enables dynamic drill down of IO behaviors.

2. Overall design

ioblame tracks the following three object types.

* Role: This tracks 'who' is taking an action. Normally corresponds to a thread. Can also be specified by userland (not implemented yet).

* 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 on and the ultimate tracking unit ioblame uses. IOs are charged to and statistics are gathered by acts.

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.

After all the tracking, on each IO completion, ioblame knows the offset and size of the IO, the act to be charged, how long it took in the queue and device. From the information, ioblame produces fields which can be recorded.

All statistics are recorded in histograms, called counters, which have eight slots. Userland can specify the number of counters, IO directions to consider, what each counter records, the boundary values to decide histogram slots and optional filter for more complex filtering conditions.

All interactions including configuration and data acquisition happen via files under /sys/kernel/debug/ioblame/.

3. Debugfs interface

3-1. Configuration

* 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.

Note that reclaiming is tied to userland reading counters data. If userland doesn't read counters, reclaiming won't happen.

* nr_counters - can be changed while disabled

Specifies the number of counters. Each act will have the specified number of histograms associated with it. Individual counters can be configured using files under the counters subdirectory. Any write to this file clears all counter settings.

* counters/NR - can be changed anytime

Specifies each counter. Its format is

DIR FIELD B0 B1 B2 B3 B4 B5 B6 B7 B8

DIR is any combination of letters 'R', 'A', and 'W', each representing reads (sans readaheads), readaheads and writes.

FIELD is the field to record in histogram and one of the followings.

offset : IO offset scaled to 0-65535
size : IO size
wait_time : time spent queued in usecs
io_time : time spent on device in usecs
seek_dist : seek dist from IO completed right before, scaled to 0-65536

B[0-8] are the boundaries for the histogram. Histograms have eight slots. If (FIELD < B[0] || (B[8] != 0 && FIELD >= B[8])), it's not recorded; otherwise, FIELD is counted in the slot with enclosing boundaries. e.g. If FIELD is >= B2 and < B3, it's recorded in the second slot (slot 1).

B8 can be zero indicating no upper limit but all other boundaries must be equal to or larger than the boundary before them.

e.g. To record offsets of reads and read aheads in counter 0,

  $ echo RA offset 0 8192 16384 24576 32768 40960 49152 57344 0 > counters/0

If higher resolution than 8 slots is necessary, two counters can be used.

  $ echo RA offset 0 4096 8192 12288 16384 20480 24576 28672 32768 > counters/0
  $ echo RA offset 32768 36864 40960 45056 49152 53248 57344 61440 0 \
								   > counters/1

Writing empty string disables the counter.

  $ echo > 1
  $ cat 1
  --- disabled

* counters/NR_filter - can be changed anytime

Specifies trace event type filter for more complex conditions. For example, it allows conditions like "if IO is in the latter half of the device, size is smaller than 128k and IO time is equal to or longer than 10ms".

To record IO time in counter 0 with the above condition,

  $ echo 'offset >= 16384 && size < 131072 && io_time >= 10000' > 0_filter
  $ echo RAW io_time 10000 25000 50000 100000 500000 1000000 2500000 \
							5000000 0 > 0

Any FIELD can be used in filter specification. For more details about filter format, please read "Event filtering" section in Documentation/trace/events.txt.

Writing '0' to filter file removes the filter. Note that writing malformed filter disables the filter and reading it back afterwards returns error message explaining why parsing failed.

3-2. Monitoring (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.

* stats/cnts_nomem

How many times per-act counter allocation failed.

* stats/iolog_overflow

How many iolog entries are lost due to overflow.

3-3. Data acquisition (read only)

* iolog

iolog is primarily a debug feature and dumps IOs as they complete.

  $ cat iolog
  R 4096 @ 74208 pid-5806 (ls) dev=0x800010 ino=0x2 gen=0x0
    #39 modifier=0x0
    [ffffffff811a0696] submit_bh+0xe6/0x120
    [ffffffff811a1f56] ll_rw_block+0xa6/0xb0
    [ffffffff81239a43] ext4_bread+0x43/0x80
    [ffffffff8123f4e3] htree_dirblock_to_tree+0x33/0x190
    [ffffffff8123f79a] ext4_htree_fill_tree+0x15a/0x250
    [ffffffff8122e26e] ext4_readdir+0x10e/0x5d0
    [ffffffff811832d0] vfs_readdir+0xa0/0xc0
    [ffffffff81183450] sys_getdents+0x80/0xe0
    [ffffffff81a3c8bb] system_call_fastpath+0x16/0x1b
  W 4096 @ 0 pid-20 (sync_supers) dev=0x800010 ino=0x0 gen=0x0
    #44 modifier=0x0
    [ffffffff811a0696] submit_bh+0xe6/0x120
    [ffffffff811a371d] __sync_dirty_buffer+0x4d/0xd0
    [ffffffff811a37ae] sync_dirty_buffer+0xe/0x10
    [ffffffff81250ee8] ext4_commit_super+0x188/0x230
    [ffffffff81250fae] ext4_write_super+0x1e/0x30
    [ffffffff811738fa] sync_supers+0xfa/0x100
    [ffffffff8113d3e1] bdi_sync_supers+0x41/0x60
    [ffffffff810ad4c6] kthread+0x96/0xa0
    [ffffffff81a3dcb4] kernel_thread_helper+0x4/0x10
  W 4096 @ 8512 pid-5813 dev=0x800010 ino=0x74 gen=0x4cc12c59
    #45 modifier=0x10000002
    [ffffffff812342cb] ext4_setattr+0x25b/0x4c0
    [ffffffff8118b9ba] notify_change+0x10a/0x2b0
    [ffffffff8119ef87] utimes_common+0xd7/0x180
    [ffffffff8119f0c9] do_utimes+0x99/0xf0
    [ffffffff8119f21d] sys_utimensat+0x2d/0x90
    [ffffffff81a3c8bb] system_call_fastpath+0x16/0x1b
  ...

The first entry is 4k read at sector 74208 (unscaled) on /dev/sdb issued by ls. The second is sync_supers writing out dirty super block. The third is inode writeback from "touch FILE; sync". Note that the modifier is set (it's indicating WB_REASON_SYNC).

Here is another example from "cp FILE FILE1" and then waiting.

W 4096 @ 0 pid-20 (sync_supers) dev=0x800010 ino=0x0 gen=0x0

    #16 modifier=0x0
    [ffffffff8139cd94] submit_bio+0x74/0x100
    [ffffffff811cba3b] submit_bh+0xeb/0x130
    [ffffffff811cecd2] __sync_dirty_buffer+0x52/0xd0
    [ffffffff811ced63] sync_dirty_buffer+0x13/0x20
    [ffffffff81281fa8] ext4_commit_super+0x188/0x230
    [ffffffff81282073] ext4_write_super+0x23/0x40
    [ffffffff8119c8d2] sync_supers+0x102/0x110
    [ffffffff81162c99] bdi_sync_supers+0x49/0x60
    [ffffffff810bc216] kthread+0xb6/0xc0
    [ffffffff81ab13b4] kernel_thread_helper+0x4/0x10
  ...
  W 4096 @ 8512 pid-668 dev=0x800010 ino=0x73 gen=0x17b5119d
    #23 modifier=0x10000003
    [ffffffff811c55b0] __mark_inode_dirty+0x220/0x330
    [ffffffff811cccfb] generic_write_end+0x6b/0xa0
    [ffffffff81268b10] ext4_da_write_end+0x150/0x360
    [ffffffff811444bb] generic_file_buffered_write+0x18b/0x290
    [ffffffff81146938] __generic_file_aio_write+0x238/0x460
    [ffffffff81146bd8] generic_file_aio_write+0x78/0xf0
    [ffffffff8125ef9f] ext4_file_write+0x6f/0x2a0
    [ffffffff811997f2] do_sync_write+0xe2/0x120
    [ffffffff8119a428] vfs_write+0xc8/0x180
    [ffffffff8119a5e1] sys_write+0x51/0x90
    [ffffffff81aafe2b] system_call_fastpath+0x16/0x1b
  ...
  W 524288 @ 3276800 pid-668 dev=0x800010 ino=0x73 gen=0x17b5119d
    #25 modifier=0x10000003
    [ffffffff811cc86c] __set_page_dirty+0x4c/0xd0
    [ffffffff811cc956] mark_buffer_dirty+0x66/0xa0
    [ffffffff811cca39] __block_commit_write+0xa9/0xe0
    [ffffffff811ccc42] block_write_end+0x42/0x90
    [ffffffff811cccc3] generic_write_end+0x33/0xa0
    [ffffffff81268b10] ext4_da_write_end+0x150/0x360
    [ffffffff811444bb] generic_file_buffered_write+0x18b/0x290
    [ffffffff81146938] __generic_file_aio_write+0x238/0x460
    [ffffffff81146bd8] generic_file_aio_write+0x78/0xf0
    [ffffffff8125ef9f] ext4_file_write+0x6f/0x2a0
    [ffffffff811997f2] do_sync_write+0xe2/0x120
    [ffffffff8119a428] vfs_write+0xc8/0x180
    [ffffffff8119a5e1] sys_write+0x51/0x90
    [ffffffff81aafe2b] system_call_fastpath+0x16/0x1b

...

The first entry is ext4 marking super block dirty. After a while, periodic writeback kicks in (modifier 0x100000003) and the inode dirtied by cp is written back followed by dirty data pages.

At this point, iolog is mostly a debug feature. The output format is quite verbose and it isn't particularly performant. If necessary, it can be extended to use trace ringbuffer and grow per-cpu binary interface.

* intents

Dump of intents in Human readable form.

  $ 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.

* intents_bin

Identical to intents but in compact binary format and likely to be much more performant. Each entry in the file is in the following format as defined in include/linux/ioblame.h.

  #define IOB_INTENTS_BIN_VER	1

  /* intent modifer */
  #define IOB_MODIFIER_TYPE_SHIFT	28
  #define IOB_MODIFIER_TYPE_MASK	0xf0000000U
  #define IOB_MODIFIER_VAL_MASK		(~IOB_MODIFIER_TYPE_MASK)

  /* val contains wb_reason */
  #define IOB_MODIFIER_WB		(1 << IOB_MODIFIER_TYPE_SHIFT)

/* record struct for /sys/kernel/debug/ioblame/intents_bin */

  struct iob_intent_bin_record {
	uint16_t	len;
	uint16_t	ver;
	uint32_t	nr;
	uint32_t	modifier;
	uint32_t	__pad;
	uint64_t	trace[];

} __packed;

* counters_pipe

Dumps counters and triggers reclaim. Opening and reading this file returns counters of all acts which have been used since the last open.

Because roles and acts shouldn't be reclaimed before the updated counters are reported, reclaiming is tied to counters_pipe access. Opening counters_pipe prepares for reclaiming and closing executes it. Act reclaiming works at ttl_secs / 2 granularity. ioblame tries to stay close to the lifetime timings requested by ttl_secs but note that reclaim happens only on counters_pipe open/close.

There can only be one user of counters_pipe at any given moment; otherwise, file operations will fail and the output and reclaiming timings are undefined.

All reported histogram counters are u32 and never reset. It's the user's responsibility to calculate the delta if necessary. Note that counters_pipe reports all used acts since last open and counters are not guaranteed to have been updated - ie. there can be spurious acts in the output.

counters_pipe is seekable by act NR.

In the following example, two counters are configured - the first one counts read offsets and the second write offsets. A file is copied using dd w/ direct flags.

  $ cat counters_pipe
  pid-20 (sync_supers) int=66 dev=0x800010 ino=0x0 gen=0x0
	  0       0       0       0       0       0       0       0
	  2       0       0       0       0       0       0       0
  pid-1708 int=58 dev=0x800010 ino=0x71 gen=0x3e0d99f2
	 11       0       0       0       0       0       0       0
	  0       0       0       0       0       0       0       0
  pid-1708 int=59 dev=0x800010 ino=0x71 gen=0x3e0d99f2
	 11       0       0       0       0       0       0       0
	  0       0       0       0       0       0       0       0
  pid-1708 int=62 dev=0x800010 ino=0x2727 gen=0xf4739822
	  0       0       0       0       0       0       0       0
	 10       0       0       0       0       0       0       0
  pid-1708 int=63 dev=0x800010 ino=0x2727 gen=0xf4739822
	  0       0       0       0       0       0       0       0
	 10       0       0       0       0       0       0       0
  pid-1708 int=31 dev=0x800010 ino=0x2727 gen=0xf4739822
	  0       0       0       0       0       0       0       0
	  2       0       0       0       0       0       0       0
  pid-1708 int=65 dev=0x800010 ino=0x2727 gen=0xf4739822
	  0       0       0       0       0       0       0       0
	  1       0       0       0       0       0       0       0

pid-1708 is the dd which copied the file. The output is separated by pid-* lines and each section corresponds to single act, which has intent NR and file (dev:ino:gen) associated with it. One 8-slot histogram is printed per line in ascending order.

The filesystem is mostly empty and, from the output, both files seem to be located in the first 1/8th of the disk.

All reads happened through intent 58 and 59. From intents file, they are,

#58 modifier=0x0
[ffffffff8139d974] submit_bio+0x74/0x100 [ffffffff811d5dba] __blockdev_direct_IO+0xc2a/0x3830 [ffffffff8129fe51] ext4_ind_direct_IO+0x121/0x470 [ffffffff8126678e] ext4_direct_IO+0x23e/0x400 [ffffffff81147b05] generic_file_aio_read+0x6d5/0x760 [ffffffff81199932] do_sync_read+0xe2/0x120 [ffffffff8119a5c5] vfs_read+0xc5/0x180 [ffffffff8119a781] sys_read+0x51/0x90 [ffffffff81ab1fab] system_call_fastpath+0x16/0x1b #59 modifier=0x0
[ffffffff8139d974] submit_bio+0x74/0x100 [ffffffff811d7345] __blockdev_direct_IO+0x21b5/0x3830 [ffffffff8129fe51] ext4_ind_direct_IO+0x121/0x470 [ffffffff8126678e] ext4_direct_IO+0x23e/0x400 [ffffffff81147b05] generic_file_aio_read+0x6d5/0x760 [ffffffff81199932] do_sync_read+0xe2/0x120 [ffffffff8119a5c5] vfs_read+0xc5/0x180 [ffffffff8119a781] sys_read+0x51/0x90 [ffffffff81ab1fab] system_call_fastpath+0x16/0x1b

Except for hitting slightly different paths in __blockdev_direct_IO, they both are ext4 direct reads as expected. Writes seem more diversified and upon examination, #62 and #63 are ext4 direct writes. #31 and #65 are more interesting.

#31 modifier=0x0
[ffffffff811cd0cc] __set_page_dirty+0x4c/0xd0 [ffffffff811cd1b6] mark_buffer_dirty+0x66/0xa0 [ffffffff811cd299] __block_commit_write+0xa9/0xe0 [ffffffff811cd4a2] block_write_end+0x42/0x90 [ffffffff811cd523] generic_write_end+0x33/0xa0 [ffffffff81269720] ext4_da_write_end+0x150/0x360 [ffffffff81144878] generic_file_buffered_write+0x188/0x2b0 [ffffffff81146d18] __generic_file_aio_write+0x238/0x460 [ffffffff81146fb8] generic_file_aio_write+0x78/0xf0 [ffffffff8125fbaf] ext4_file_write+0x6f/0x2a0 [ffffffff81199812] do_sync_write+0xe2/0x120 [ffffffff8119a308] vfs_write+0xc8/0x180 [ffffffff8119a4c1] sys_write+0x51/0x90 [ffffffff81ab1fab] system_call_fastpath+0x16/0x1b

This is buffered write. It turns out the file size didn't match the specified blocksize, so dd turns off O_DIRECT for the last IO and issue buffered write for the remainder.

Note that the actual IO submission is not visible in the stack trace as the IOs are charged to the dirtying act. Actual IOs are likely to be executed from fsync(2).

#65 modifier=0x0
[ffffffff811c5e10] __mark_inode_dirty+0x220/0x330 [ffffffff81267edd] ext4_da_update_reserve_space+0x13d/0x230 [ffffffff8129006d] ext4_ext_map_blocks+0x13dd/0x1dc0 [ffffffff81268a31] ext4_map_blocks+0x1b1/0x260 [ffffffff81269c52] mpage_da_map_and_submit+0xb2/0x480 [ffffffff8126a84a] ext4_da_writepages+0x30a/0x6e0 [ffffffff8114f584] do_writepages+0x24/0x40 [ffffffff811468cb] __filemap_fdatawrite_range+0x5b/0x60 [ffffffff8114692a] filemap_write_and_wait_range+0x5a/0x80 [ffffffff8125ff64] ext4_sync_file+0x74/0x440 [ffffffff811ca31b] vfs_fsync_range+0x2b/0x40 [ffffffff811ca34c] vfs_fsync+0x1c/0x20 [ffffffff811ca58a] do_fsync+0x3a/0x60 [ffffffff811ca5e0] sys_fsync+0x10/0x20 [ffffffff81ab1fab] system_call_fastpath+0x16/0x1b

And this is dd fsync(2)ing and marking inode for writeback. As with data writeback, IO submission is not visible in the stack trace.

* counters_pipe_bin

Identical to counters_pipe but in compact binary format and likely to be much more performant. Each entry in the file is in the following format as defined in include/linux/ioblame.h.

  #define IOBC_PIPE_BIN_VER	1

/* record struct for /sys/kernel/debug/ioblame/counters_pipe_bin */

  struct iobc_pipe_bin_record {
	  uint16_t	len;
	  uint16_t	ver;
	  int32_t	id;		/* >0 pid or negated user id */
	  uint32_t	intent_nr;	/* associated intent */
	  uint32_t	dev;
	  uint64_t	ino;
	  uint32_t	gen;
	  uint32_t	__pad;
	  uint32_t	cnts[];		/* [type][slot] */

} __packed;

Note that counters_pipe and counters_pipe_bin can't be used parallelly. Only one opener is allowed across the two files at any given moment.

4. 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.

* Mechanism to specify userland role ID is not implemented yet.

5. 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.

Tejun Heo

author

2012-01-05 23:43 UTC #1 lore raw

PATCH 1/11 trace_event_filter: factorize filter creation

There are four places where new filter for a given filter string is created, which involves several different steps. This patch factors those steps into create_[system_]filter() functions which in turn make use of create_filter_{start|finish}() for common parts.

The only functional change is that if replace_filter_string() is requested and fails, creation fails without any side effect instead of being ignored.

Note that system filter is now installed after the processing is complete which makes freeing before and then restoring filter string on error unncessary.

-v2: Rebased to resolve conflict with 49aa29513e and updated both
create_filter() functions to always set *filterp instead of requiring the caller to clear it to %NULL on entry.

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

---
 kernel/trace/trace_events_filter.c |  283 ++++++++++++++++++------------------
 1 files changed, 142 insertions(+), 141 deletions(-)

kernel/trace/trace_events_filter.c +142 ~~-141~~

index f04cc31..24aee71 100644
@@ -1738,11 +1738,121 @@ static int replace_system_preds(struct event_subsystem *system,
 	return -ENOMEM;
 }
 
+static int create_filter_start(char *filter_str, bool set_str,
+			       struct filter_parse_state **psp,
+			       struct event_filter **filterp)
+{
+	struct event_filter *filter;
+	struct filter_parse_state *ps = NULL;
+	int err = 0;
+
+	WARN_ON_ONCE(*psp || *filterp);
+
+	/* allocate everything, and if any fails, free all and fail */
+	filter = __alloc_filter();
+	if (filter && set_str)
+		err = replace_filter_string(filter, filter_str);
+
+	ps = kzalloc(sizeof(*ps), GFP_KERNEL);
+
+	if (!filter || !ps || err) {
+		kfree(ps);
+		__free_filter(filter);
+		return -ENOMEM;
+	}
+
+	/* we're committed to creating a new filter */
+	*filterp = filter;
+	*psp = ps;
+
+	parse_init(ps, filter_ops, filter_str);
+	err = filter_parse(ps);
+	if (err && set_str)
+		append_filter_err(ps, filter);
+	return err;
+}
+
+static void create_filter_finish(struct filter_parse_state *ps)
+{
+	if (ps) {
+		filter_opstack_clear(ps);
+		postfix_clear(ps);
+		kfree(ps);
+	}
+}
+
+/**
+ * create_filter - create a filter for a ftrace_event_call
+ * @call: ftrace_event_call to create a filter for
+ * @filter_str: filter string
+ * @set_str: remember @filter_str and enable detailed error in filter
+ * @filterp: out param for created filter (always updated on return)
+ *
+ * Creates a filter for @call with @filter_str.  If @set_str is %true,
+ * @filter_str is copied and recorded in the new filter.
+ *
+ * On success, returns 0 and *@filterp points to the new filter.  On
+ * failure, returns -errno and *@filterp may point to %NULL or to a new
+ * filter.  In the latter case, the returned filter contains error
+ * information if @set_str is %true and the caller is responsible for
+ * freeing it.
+ */
+static int create_filter(struct ftrace_event_call *call,
+			 char *filter_str, bool set_str,
+			 struct event_filter **filterp)
+{
+	struct event_filter *filter = NULL;
+	struct filter_parse_state *ps = NULL;
+	int err;
+
+	err = create_filter_start(filter_str, set_str, &ps, &filter);
+	if (!err) {
+		err = replace_preds(call, filter, ps, filter_str, false);
+		if (err && set_str)
+			append_filter_err(ps, filter);
+	}
+	create_filter_finish(ps);
+
+	*filterp = filter;
+	return err;
+}
+
+/**
+ * create_system_filter - create a filter for an event_subsystem
+ * @system: event_subsystem to create a filter for
+ * @filter_str: filter string
+ * @filterp: out param for created filter (always updated on return)
+ *
+ * Identical to create_filter() except that it creates a subsystem filter
+ * and always remembers @filter_str.
+ */
+static int create_system_filter(struct event_subsystem *system,
+				char *filter_str, struct event_filter **filterp)
+{
+	struct event_filter *filter = NULL;
+	struct filter_parse_state *ps = NULL;
+	int err;
+
+	err = create_filter_start(filter_str, true, &ps, &filter);
+	if (!err) {
+		err = replace_system_preds(system, ps, filter_str);
+		if (!err) {
+			/* System filters just show a default message */
+			kfree(filter->filter_string);
+			filter->filter_string = NULL;
+		} else {
+			append_filter_err(ps, filter);
+		}
+	}
+	create_filter_finish(ps);
+
+	*filterp = filter;
+	return err;
+}
+
 int apply_event_filter(struct ftrace_event_call *call, char *filter_string)
 {
-	struct filter_parse_state *ps;
 	struct event_filter *filter;
-	struct event_filter *tmp;
 	int err = 0;
 
 	mutex_lock(&event_mutex);

@@ -1759,49 +1869,30 @@ int apply_event_filter(struct ftrace_event_call *call, char *filter_string)
 		goto out_unlock;
 	}
 
-	err = -ENOMEM;
-	ps = kzalloc(sizeof(*ps), GFP_KERNEL);
-	if (!ps)
-		goto out_unlock;
-
-	filter = __alloc_filter();
-	if (!filter) {
-		kfree(ps);
-		goto out_unlock;
-	}
-
-	replace_filter_string(filter, filter_string);
-
-	parse_init(ps, filter_ops, filter_string);
-	err = filter_parse(ps);
-	if (err) {
-		append_filter_err(ps, filter);
-		goto out;
-	}
+	err = create_filter(call, filter_string, true, &filter);
 
-	err = replace_preds(call, filter, ps, filter_string, false);
-	if (err) {
-		filter_disable(call);
-		append_filter_err(ps, filter);
-	} else
-		call->flags |= TRACE_EVENT_FL_FILTERED;
-out:
 	/*
 	 * Always swap the call filter with the new filter
 	 * even if there was an error. If there was an error
 	 * in the filter, we disable the filter and show the error
 	 * string
 	 */
-	tmp = call->filter;
-	rcu_assign_pointer(call->filter, filter);
-	if (tmp) {
-		/* Make sure the call is done with the filter */
-		synchronize_sched();
-		__free_filter(tmp);
+	if (filter) {
+		struct event_filter *tmp = call->filter;
+
+		if (!err)
+			call->flags |= TRACE_EVENT_FL_FILTERED;
+		else
+			filter_disable(call);
+
+		rcu_assign_pointer(call->filter, filter);
+
+		if (tmp) {
+			/* Make sure the call is done with the filter */
+			synchronize_sched();
+			__free_filter(tmp);
+		}
 	}
-	filter_opstack_clear(ps);
-	postfix_clear(ps);
-	kfree(ps);
 out_unlock:
 	mutex_unlock(&event_mutex);

@@ -1811,7 +1902,6 @@ out_unlock:
 int apply_subsystem_event_filter(struct event_subsystem *system,
 				 char *filter_string)
 {
-	struct filter_parse_state *ps;
 	struct event_filter *filter;
 	int err = 0;

@@ -1835,48 +1925,19 @@ int apply_subsystem_event_filter(struct event_subsystem *system,
 		goto out_unlock;
 	}
 
-	err = -ENOMEM;
-	ps = kzalloc(sizeof(*ps), GFP_KERNEL);
-	if (!ps)
-		goto out_unlock;
-
-	filter = __alloc_filter();
-	if (!filter)
-		goto out;
-
-	/* System filters just show a default message */
-	kfree(filter->filter_string);
-	filter->filter_string = NULL;
-
-	/*
-	 * No event actually uses the system filter
-	 * we can free it without synchronize_sched().
-	 */
-	__free_filter(system->filter);
-	system->filter = filter;
-
-	parse_init(ps, filter_ops, filter_string);
-	err = filter_parse(ps);
-	if (err)
-		goto err_filter;
-
-	err = replace_system_preds(system, ps, filter_string);
-	if (err)
-		goto err_filter;
-
-out:
-	filter_opstack_clear(ps);
-	postfix_clear(ps);
-	kfree(ps);
+	err = create_system_filter(system, filter_string, &filter);
+	if (filter) {
+		/*
+		 * No event actually uses the system filter
+		 * we can free it without synchronize_sched().
+		 */
+		__free_filter(system->filter);
+		system->filter = filter;
+	}
 out_unlock:
 	mutex_unlock(&event_mutex);
 
 	return err;
-
-err_filter:
-	replace_filter_string(filter, filter_string);
-	append_filter_err(ps, system->filter);
-	goto out;
 }
 
 #ifdef CONFIG_PERF_EVENTS

@@ -1894,7 +1955,6 @@ int ftrace_profile_set_filter(struct perf_event *event, int event_id,
 {
 	int err;
 	struct event_filter *filter;
-	struct filter_parse_state *ps;
 	struct ftrace_event_call *call;
 
 	mutex_lock(&event_mutex);

@@ -1909,33 +1969,10 @@ int ftrace_profile_set_filter(struct perf_event *event, int event_id,
 	if (event->filter)
 		goto out_unlock;
 
-	filter = __alloc_filter();
-	if (!filter) {
-		err = PTR_ERR(filter);
-		goto out_unlock;
-	}
-
-	err = -ENOMEM;
-	ps = kzalloc(sizeof(*ps), GFP_KERNEL);
-	if (!ps)
-		goto free_filter;
-
-	parse_init(ps, filter_ops, filter_str);
-	err = filter_parse(ps);
-	if (err)
-		goto free_ps;
-
-	err = replace_preds(call, filter, ps, filter_str, false);
+	err = create_filter(call, filter_str, false, &filter);
 	if (!err)
 		event->filter = filter;
-
-free_ps:
-	filter_opstack_clear(ps);
-	postfix_clear(ps);
-	kfree(ps);
-
-free_filter:
-	if (err)
+	else
 		__free_filter(filter);
 
 out_unlock:

@@ -1954,43 +1991,6 @@ out_unlock:
 #define CREATE_TRACE_POINTS
 #include "trace_events_filter_test.h"
 
-static int test_get_filter(char *filter_str, struct ftrace_event_call *call,
-			   struct event_filter **pfilter)
-{
-	struct event_filter *filter;
-	struct filter_parse_state *ps;
-	int err = -ENOMEM;
-
-	filter = __alloc_filter();
-	if (!filter)
-		goto out;
-
-	ps = kzalloc(sizeof(*ps), GFP_KERNEL);
-	if (!ps)
-		goto free_filter;
-
-	parse_init(ps, filter_ops, filter_str);
-	err = filter_parse(ps);
-	if (err)
-		goto free_ps;
-
-	err = replace_preds(call, filter, ps, filter_str, false);
-	if (!err)
-		*pfilter = filter;
-
- free_ps:
-	filter_opstack_clear(ps);
-	postfix_clear(ps);
-	kfree(ps);
-
- free_filter:
-	if (err)
-		__free_filter(filter);
-
- out:
-	return err;
-}
-
 #define DATA_REC(m, va, vb, vc, vd, ve, vf, vg, vh, nvisit) \
 { \
 	.filter = FILTER, \

@@ -2109,12 +2109,13 @@ static __init int ftrace_test_event_filter(void)
 		struct test_filter_data_t *d = &test_filter_data[i];
 		int err;
 
-		err = test_get_filter(d->filter, &event_ftrace_test_filter,
-				      &filter);
+		err = create_filter(&event_ftrace_test_filter, d->filter,
+				    false, &filter);
 		if (err) {
 			printk(KERN_INFO
 			       "Failed to get filter for '%s', err %d\n",
 			       d->filter, err);
+			__free_filter(filter);
 			break;
 		}

Signature · 1 line

1.7.3.1

Tejun Heo

author

2012-01-05 23:43 UTC #2 lore raw

PATCH 2/11 trace_event_filter: add trace_event_filter_*() interface

In reply to Tejun Heo

Trace event filter is generic enough to be useful in other use cases. This patch makes update replace_preds such that it takes field lookup function instead of struct ftrace_event_call and use it to implement trace_event_filter_create() and friends.

The fields which can be used in filter are described by list of struct ftrace_event_field's, trace_event_filter_string() can be used to access the filter string and _destroy() frees the filter.

The currently planned external user is another tracer and this is good enough but it might be a good idea to further generalize the interface if it gets used more widely.

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

---
 kernel/trace/trace.h               |    6 ++
 kernel/trace/trace_events_filter.c |  100 +++++++++++++++++++++++++++++++----
 2 files changed, 94 insertions(+), 12 deletions(-)

kernel/trace/trace.h +6 -0

index 2c26574..11c4754 100644
@@ -811,6 +811,12 @@ filter_check_discard(struct ftrace_event_call *call, void *rec,
 
 extern void trace_event_enable_cmd_record(bool enable);
 
+extern int trace_event_filter_create(struct list_head *event_fields,
+				     char *filter_str,
+				     struct event_filter **filterp);
+extern const char *trace_event_filter_string(struct event_filter *filter);
+extern void trace_event_filter_destroy(struct event_filter *filter);
+
 extern struct mutex event_mutex;
 extern struct list_head ftrace_events;

kernel/trace/trace_events_filter.c +88 ~~-12~~

151 lines not on this page · raw message

Signature · 1 line

1.7.3.1

Tejun Heo

author

2012-01-05 23:43 UTC #3 lore raw

PATCH 3/11 block: block_bio_complete tracepoint was missing

In reply to Tejun Heo

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

Signed-off-by Tejun Heo <[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

Namhyung Kim

2012-01-09 01:30 UTC #4 lore raw

Re: [PATCH 03/11] block: block_bio_complete tracepoint was missing

Quoted 13 lines · Tejun Heo

block_bio_complete tracepoint was defined but not invoked anywhere. Fix it.
Signed-off-by Tejun Heo<[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 1455

Quoted 9 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);
  	if (bio->bi_end_io)
  		bio->bi_end_io(bio, error);
  }

Hi,

Just adding the TP unconditionally will produce duplicated (in some sense) reports about the completion. For example, normal request based IO reports whole request completion prior to its bio's, and further, some of nested block IO handling routines - bounced bio and btrfs with compression, etc - call bio_endio() more than once. Also there are cases that bio fails before it's enqueued for some reason.

I have no idea about the ioblame can deal with all of such corner cases. However it might confuse blktrace somewhat, I guess.

I already posted similar patch a couple of weeks ago, but didn't receive a comment yet. [1] Please take a look this too :)

After a quick glance, the ioblame seems to carry all IO accounting info through the first bio in the request. If so, why don't you use the request structure for that?

Thanks,
Namhyung Kim

[1] https://lkml.org/lkml/2011/12/27/111

Tejun Heo

author

2012-01-09 01:49 UTC #5 lore raw

Re: [PATCH 03/11] block: block_bio_complete tracepoint was missing

Hello,

Quoted 4 lines · Namhyung Kim

Just adding the TP unconditionally will produce duplicated (in some sense) reports about the completion. For example, normal request based IO reports whole request completion prior to its bio's, and further

Request and bio completions are separate events. There's nothing wrong with reporting them separately. In fact, I think they should be reported separately.

Quoted 3 lines

, some of nested block IO handling routines - bounced bio and btrfs with compression, etc - call bio_endio() more than once. Also there are cases that bio fails before it's enqueued for some reason.

They are actually separate bio's being completed. I don't think trying to put extra semantics on TP itself is a good idea. In general, TP signals that such event happened with sufficient information and it's the consumers' responsibility to make sense of what's going on. BIO_CLONED/BOUNCED are there.

Quoted 2 lines

I have no idea about the ioblame can deal with all of such corner cases. However it might confuse blktrace somewhat, I guess.

Unless someone is doing memcpy() on bio's, ioblame should be okay. It only considers bio's which went through actual submission.

Quoted 2 lines

I already posted similar patch a couple of weeks ago, but didn't receive a comment yet. [1] Please take a look this too :)

I'll reply there but don't think imposing such extra logic on TP is a good idea.

Quoted 3 lines

After a quick glance, the ioblame seems to carry all IO accounting info through the first bio in the request. If so, why don't you use the request structure for that?

Because there are bio based drivers which don't use requests at all.

Thanks.

--
tejun

Namhyung Kim

2012-01-09 02:33 UTC #6 lore raw

Re: [PATCH 03/11] block: block_bio_complete tracepoint was missing

Hi,

Quoted 16 lines · Tejun Heo

Hello,
Quoted 4 lines · Namhyung Kim
Just adding the TP unconditionally will produce duplicated (in some sense) reports about the completion. For example, normal request based IO reports whole request completion prior to its bio's, and further
Request and bio completions are separate events. There's nothing wrong with reporting them separately. In fact, I think they should be reported separately.
Quoted 3 lines
, some of nested block IO handling routines - bounced bio and btrfs with compression, etc - call bio_endio() more than once. Also there are cases that bio fails before it's enqueued for some reason.

Quoted 5 lines

They are actually separate bio's being completed. I don't think trying to put extra semantics on TP itself is a good idea. In general, TP signals that such event happened with sufficient information and it's the consumers' responsibility to make sense of what's going on. BIO_CLONED/BOUNCED are there.

I see.

Quoted 11 lines

Quoted 2 lines
I have no idea about the ioblame can deal with all of such corner cases. However it might confuse blktrace somewhat, I guess.
Unless someone is doing memcpy() on bio's, ioblame should be okay. It only considers bio's which went through actual submission.
Quoted 2 lines
I already posted similar patch a couple of weeks ago, but didn't receive a comment yet. [1] Please take a look this too :)
I'll reply there but don't think imposing such extra logic on TP is a good idea.

I'll reply on that thread too. :)

Quoted 5 lines

Quoted 3 lines
After a quick glance, the ioblame seems to carry all IO accounting info through the first bio in the request. If so, why don't you use the request structure for that?
Because there are bio based drivers which don't use requests at all.

What I thought for such drivers was dynamic allocation in their ->make_request_fn, but because we don't have a block_bio_issue TP, Nevermind. :)

Thanks,
Namhyung Kim

Tejun Heo

author

2012-01-05 23:43 UTC #7 lore raw

PATCH 4/11 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 ea70e6c..b0b5411 100644
@@ -1180,7 +1180,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);

@@ -1203,7 +1203,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 16fc34a..7d00bcf 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-05 23:43 UTC #8 lore raw

PATCH 5/11 block: abstract disk iteration into disk_iter

In reply to Tejun Heo

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 02e9fca..aa13775 100644
@@ -41,6 +41,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

@@ -731,12 +772,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];

@@ -780,7 +820,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

@@ -788,44 +828,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);
 	}
 }

@@ -1207,12 +1241,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))

@@ -1234,7 +1268,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 6d18f35..aefa6ba 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-05 23:46 UTC #9 lore raw

PATCH 6/11 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 ac86f8b..68cba85 100644
@@ -29,24 +29,6 @@
 #include <linux/tracepoint.h>
 #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 */
-};
-
 const char *wb_reason_name[] = {
 	[WB_REASON_BACKGROUND]		= "background",
 	[WB_REASON_TRY_TO_FREE_PAGES]	= "try_to_free_pages",

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-05 23:45 UTC #10 lore raw

PATCH 7/11 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 68cba85..7d29370 100644
@@ -310,8 +310,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;
 }

@@ -392,6 +398,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);
 
 	/*

@@ -1051,8 +1059,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 50f0824..0bc5085 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-05 23:45 UTC #11 lore raw

PATCH 8/11 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 b0b5411..365ab8f 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

Tejun Heo

author

2012-01-05 23:44 UTC #12 lore raw

PATCH 9/11 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 afd0f1a..7b70a2e 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-05 23:44 UTC #13 lore raw

PATCH 10/11 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

Tejun Heo

author

2012-01-05 23:43 UTC #14 lore raw

PATCH 11/11 block, trace: implement ioblame IO statistical analyzer

In reply to Tejun Heo

Implement ioblame, which can attribute each IO to its origin and record user configurable histograms.

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 record statistics in user-configurable histograms.

ioblame aims to deliver insight into overall system IO behavior with manageable overhead. Also, to enable follow-the-breadcrumbs type investigation, a lot of information gathering configurations can be changed on the fly.

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.

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

Cc Justin TerAvest <[email protected]>

Cc Slava Pestov <[email protected]>

---
 Documentation/trace/ioblame.txt |  646 ++++++++
 include/linux/blk_types.h       |    7 +-
 include/linux/fs.h              |    3 +
 include/linux/genhd.h           |    4 +
 include/linux/ioblame.h         |   95 ++
 kernel/trace/Kconfig            |   11 +
 kernel/trace/Makefile           |    1 +
 kernel/trace/ioblame.c          | 3479 +++++++++++++++++++++++++++++++++++++++
 8 files changed, 4244 insertions(+), 2 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 +646 -0

new file mode 100644
index 0000000..4541184
@@ -0,0 +1,646 @@
+
+ioblame - statistical IO analyzer with origin tracking
+
+December, 2011		Tejun Heo <[email protected]>
+
+
+CONTENTS
+
+1. Introduction
+2. Overall design
+3. Debugfs interface
+3-1. Configuration
+3-2. Monitoring
+3-3. Data acquisition
+4. Notes
+5. 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 statistical IO analyzer which can track and record origin
+of IOs.  It keeps track of who dirtied pages and inodes, and, on an
+actual IO, attributes it to the originator of the IO.
+
+The design goals of ioblame are
+
+* Minimally invasive - Analyzer 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.  Analyzer
+  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.
+
+* Dynamic and customizable - There are many different aspects of IOs
+  which can be irrelevant or interesting depending on the situation.
+  From analysis point of view, always recording all collected data
+  would be ideal but is very wasteful in most situations.  ioblame
+  lets users decide what information to gather so that they can
+  acquire relevant information without wasting resources
+  unnecessarily.  ioblame also allows dynamic configuration while the
+  analyzer is online which enables dynamic drill down of IO behaviors.
+
+
+2. Overall design
+
+ioblame tracks the following three object types.
+
+* Role: This tracks 'who' is taking an action.  Normally corresponds
+  to a thread.  Can also be specified by userland (not implemented
+  yet).
+
+* 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 on and the ultimate tracking unit ioblame uses.  IOs are
+  charged to and statistics are gathered by acts.
+
+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.
+
+After all the tracking, on each IO completion, ioblame knows the
+offset and size of the IO, the act to be charged, how long it took in
+the queue and device.  From the information, ioblame produces fields
+which can be recorded.
+
+All statistics are recorded in histograms, called counters, which have
+eight slots.  Userland can specify the number of counters, IO
+directions to consider, what each counter records, the boundary values
+to decide histogram slots and optional filter for more complex
+filtering conditions.
+
+All interactions including configuration and data acquisition happen
+via files under /sys/kernel/debug/ioblame/.
+
+
+3. Debugfs interface
+
+3-1. Configuration
+
+* 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.
+
+  Note that reclaiming is tied to userland reading counters data.  If
+  userland doesn't read counters, reclaiming won't happen.
+
+* nr_counters			- can be changed while disabled
+
+  Specifies the number of counters.  Each act will have the specified
+  number of histograms associated with it.  Individual counters can be
+  configured using files under the counters subdirectory.  Any write
+  to this file clears all counter settings.
+
+* counters/NR			- can be changed anytime
+
+  Specifies each counter.  Its format is
+
+    DIR FIELD B0 B1 B2 B3 B4 B5 B6 B7 B8
+
+  DIR is any combination of letters 'R', 'A', and 'W', each
+  representing reads (sans readaheads), readaheads and writes.
+
+  FIELD is the field to record in histogram and one of the followings.
+
+    offset	: IO offset scaled to 0-65535
+    size	: IO size
+    wait_time	: time spent queued in usecs
+    io_time	: time spent on device in usecs
+    seek_dist	: seek dist from IO completed right before, scaled to 0-65536
+
+  B[0-8] are the boundaries for the histogram.  Histograms have eight
+  slots.  If (FIELD < B[0] || (B[8] != 0 && FIELD >= B[8])), it's not
+  recorded; otherwise, FIELD is counted in the slot with enclosing
+  boundaries.  e.g. If FIELD is >= B2 and < B3, it's recorded in the
+  second slot (slot 1).
+
+  B8 can be zero indicating no upper limit but all other boundaries
+  must be equal to or larger than the boundary before them.
+
+  e.g. To record offsets of reads and read aheads in counter 0,
+
+  $ echo RA offset 0 8192 16384 24576 32768 40960 49152 57344 0 > counters/0
+
+  If higher resolution than 8 slots is necessary, two counters can be
+  used.
+
+  $ echo RA offset 0 4096 8192 12288 16384 20480 24576 28672 32768 > counters/0
+  $ echo RA offset 32768 36864 40960 45056 49152 53248 57344 61440 0 \
+								   > counters/1
+
+  Writing empty string disables the counter.
+
+  $ echo > 1
+  $ cat 1
+  --- disabled
+
+* counters/NR_filter		- can be changed anytime
+
+  Specifies trace event type filter for more complex conditions.  For
+  example, it allows conditions like "if IO is in the latter half of
+  the device, size is smaller than 128k and IO time is equal to or
+  longer than 10ms".
+
+  To record IO time in counter 0 with the above condition,
+
+  $ echo 'offset >= 16384 && size < 131072 && io_time >= 10000' > 0_filter
+  $ echo RAW io_time 10000 25000 50000 100000 500000 1000000 2500000 \
+							5000000 0 > 0
+
+  Any FIELD can be used in filter specification.  For more details
+  about filter format, please read "Event filtering" section in
+  Documentation/trace/events.txt.
+
+  Writing '0' to filter file removes the filter.  Note that writing
+  malformed filter disables the filter and reading it back afterwards
+  returns error message explaining why parsing failed.
+
+
+3-2. Monitoring (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.
+
+* stats/cnts_nomem
+
+  How many times per-act counter allocation failed.
+
+* stats/iolog_overflow
+
+  How many iolog entries are lost due to overflow.
+
+
+3-3. Data acquisition (read only)
+
+* iolog
+
+  iolog is primarily a debug feature and dumps IOs as they complete.
+
+  $ cat iolog
+  R 4096 @ 74208 pid-5806 (ls) dev=0x800010 ino=0x2 gen=0x0
+    #39 modifier=0x0
+    [ffffffff811a0696] submit_bh+0xe6/0x120
+    [ffffffff811a1f56] ll_rw_block+0xa6/0xb0
+    [ffffffff81239a43] ext4_bread+0x43/0x80
+    [ffffffff8123f4e3] htree_dirblock_to_tree+0x33/0x190
+    [ffffffff8123f79a] ext4_htree_fill_tree+0x15a/0x250
+    [ffffffff8122e26e] ext4_readdir+0x10e/0x5d0
+    [ffffffff811832d0] vfs_readdir+0xa0/0xc0
+    [ffffffff81183450] sys_getdents+0x80/0xe0
+    [ffffffff81a3c8bb] system_call_fastpath+0x16/0x1b
+  W 4096 @ 0 pid-20 (sync_supers) dev=0x800010 ino=0x0 gen=0x0
+    #44 modifier=0x0
+    [ffffffff811a0696] submit_bh+0xe6/0x120
+    [ffffffff811a371d] __sync_dirty_buffer+0x4d/0xd0
+    [ffffffff811a37ae] sync_dirty_buffer+0xe/0x10
+    [ffffffff81250ee8] ext4_commit_super+0x188/0x230
+    [ffffffff81250fae] ext4_write_super+0x1e/0x30
+    [ffffffff811738fa] sync_supers+0xfa/0x100
+    [ffffffff8113d3e1] bdi_sync_supers+0x41/0x60
+    [ffffffff810ad4c6] kthread+0x96/0xa0
+    [ffffffff81a3dcb4] kernel_thread_helper+0x4/0x10
+  W 4096 @ 8512 pid-5813 dev=0x800010 ino=0x74 gen=0x4cc12c59
+    #45 modifier=0x10000002
+    [ffffffff812342cb] ext4_setattr+0x25b/0x4c0
+    [ffffffff8118b9ba] notify_change+0x10a/0x2b0
+    [ffffffff8119ef87] utimes_common+0xd7/0x180
+    [ffffffff8119f0c9] do_utimes+0x99/0xf0
+    [ffffffff8119f21d] sys_utimensat+0x2d/0x90
+    [ffffffff81a3c8bb] system_call_fastpath+0x16/0x1b
+  ...
+
+  The first entry is 4k read at sector 74208 (unscaled) on /dev/sdb
+  issued by ls.  The second is sync_supers writing out dirty super
+  block.  The third is inode writeback from "touch FILE; sync".  Note
+  that the modifier is set (it's indicating WB_REASON_SYNC).
+
+  Here is another example from "cp FILE FILE1" and then waiting.
+
+  W 4096 @ 0 pid-20 (sync_supers) dev=0x800010 ino=0x0 gen=0x0
+    #16 modifier=0x0
+    [ffffffff8139cd94] submit_bio+0x74/0x100
+    [ffffffff811cba3b] submit_bh+0xeb/0x130
+    [ffffffff811cecd2] __sync_dirty_buffer+0x52/0xd0
+    [ffffffff811ced63] sync_dirty_buffer+0x13/0x20
+    [ffffffff81281fa8] ext4_commit_super+0x188/0x230
+    [ffffffff81282073] ext4_write_super+0x23/0x40
+    [ffffffff8119c8d2] sync_supers+0x102/0x110
+    [ffffffff81162c99] bdi_sync_supers+0x49/0x60
+    [ffffffff810bc216] kthread+0xb6/0xc0
+    [ffffffff81ab13b4] kernel_thread_helper+0x4/0x10
+  ...
+  W 4096 @ 8512 pid-668 dev=0x800010 ino=0x73 gen=0x17b5119d
+    #23 modifier=0x10000003
+    [ffffffff811c55b0] __mark_inode_dirty+0x220/0x330
+    [ffffffff811cccfb] generic_write_end+0x6b/0xa0
+    [ffffffff81268b10] ext4_da_write_end+0x150/0x360
+    [ffffffff811444bb] generic_file_buffered_write+0x18b/0x290
+    [ffffffff81146938] __generic_file_aio_write+0x238/0x460
+    [ffffffff81146bd8] generic_file_aio_write+0x78/0xf0
+    [ffffffff8125ef9f] ext4_file_write+0x6f/0x2a0
+    [ffffffff811997f2] do_sync_write+0xe2/0x120
+    [ffffffff8119a428] vfs_write+0xc8/0x180
+    [ffffffff8119a5e1] sys_write+0x51/0x90
+    [ffffffff81aafe2b] system_call_fastpath+0x16/0x1b
+  ...
+  W 524288 @ 3276800 pid-668 dev=0x800010 ino=0x73 gen=0x17b5119d
+    #25 modifier=0x10000003
+    [ffffffff811cc86c] __set_page_dirty+0x4c/0xd0
+    [ffffffff811cc956] mark_buffer_dirty+0x66/0xa0
+    [ffffffff811cca39] __block_commit_write+0xa9/0xe0
+    [ffffffff811ccc42] block_write_end+0x42/0x90
+    [ffffffff811cccc3] generic_write_end+0x33/0xa0
+    [ffffffff81268b10] ext4_da_write_end+0x150/0x360
+    [ffffffff811444bb] generic_file_buffered_write+0x18b/0x290
+    [ffffffff81146938] __generic_file_aio_write+0x238/0x460
+    [ffffffff81146bd8] generic_file_aio_write+0x78/0xf0
+    [ffffffff8125ef9f] ext4_file_write+0x6f/0x2a0
+    [ffffffff811997f2] do_sync_write+0xe2/0x120
+    [ffffffff8119a428] vfs_write+0xc8/0x180
+    [ffffffff8119a5e1] sys_write+0x51/0x90
+    [ffffffff81aafe2b] system_call_fastpath+0x16/0x1b
+  ...
+
+  The first entry is ext4 marking super block dirty.  After a while,
+  periodic writeback kicks in (modifier 0x100000003) and the inode
+  dirtied by cp is written back followed by dirty data pages.
+
+  At this point, iolog is mostly a debug feature.  The output format
+  is quite verbose and it isn't particularly performant.  If
+  necessary, it can be extended to use trace ringbuffer and grow
+  per-cpu binary interface.
+
+* intents
+
+  Dump of intents in Human readable form.
+
+  $ 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.
+
+* intents_bin
+
+  Identical to intents but in compact binary format and likely to be
+  much more performant.  Each entry in the file is in the following
+  format as defined in include/linux/ioblame.h.
+
+  #define IOB_INTENTS_BIN_VER	1
+
+  /* intent modifer */
+  #define IOB_MODIFIER_TYPE_SHIFT	28
+  #define IOB_MODIFIER_TYPE_MASK	0xf0000000U
+  #define IOB_MODIFIER_VAL_MASK		(~IOB_MODIFIER_TYPE_MASK)
+
+  /* val contains wb_reason */
+  #define IOB_MODIFIER_WB		(1 << IOB_MODIFIER_TYPE_SHIFT)
+
+  /* record struct for /sys/kernel/debug/ioblame/intents_bin */
+  struct iob_intent_bin_record {
+	uint16_t	len;
+	uint16_t	ver;
+	uint32_t	nr;
+	uint32_t	modifier;
+	uint32_t	__pad;
+	uint64_t	trace[];
+  } __packed;
+
+* counters_pipe
+
+  Dumps counters and triggers reclaim.  Opening and reading this file
+  returns counters of all acts which have been used since the last
+  open.
+
+  Because roles and acts shouldn't be reclaimed before the updated
+  counters are reported, reclaiming is tied to counters_pipe access.
+  Opening counters_pipe prepares for reclaiming and closing executes
+  it.  Act reclaiming works at ttl_secs / 2 granularity.  ioblame
+  tries to stay close to the lifetime timings requested by ttl_secs
+  but note that reclaim happens only on counters_pipe open/close.
+
+  There can only be one user of counters_pipe at any given moment;
+  otherwise, file operations will fail and the output and reclaiming
+  timings are undefined.
+
+  All reported histogram counters are u32 and never reset.  It's the
+  user's responsibility to calculate the delta if necessary.  Note
+  that counters_pipe reports all used acts since last open and
+  counters are not guaranteed to have been updated - ie. there can be
+  spurious acts in the output.
+
+  counters_pipe is seekable by act NR.
+
+  In the following example, two counters are configured - the first
+  one counts read offsets and the second write offsets.  A file is
+  copied using dd w/ direct flags.
+
+  $ cat counters_pipe
+  pid-20 (sync_supers) int=66 dev=0x800010 ino=0x0 gen=0x0
+	  0       0       0       0       0       0       0       0
+	  2       0       0       0       0       0       0       0
+  pid-1708 int=58 dev=0x800010 ino=0x71 gen=0x3e0d99f2
+	 11       0       0       0       0       0       0       0
+	  0       0       0       0       0       0       0       0
+  pid-1708 int=59 dev=0x800010 ino=0x71 gen=0x3e0d99f2
+	 11       0       0       0       0       0       0       0
+	  0       0       0       0       0       0       0       0
+  pid-1708 int=62 dev=0x800010 ino=0x2727 gen=0xf4739822
+	  0       0       0       0       0       0       0       0
+	 10       0       0       0       0       0       0       0
+  pid-1708 int=63 dev=0x800010 ino=0x2727 gen=0xf4739822
+	  0       0       0       0       0       0       0       0
+	 10       0       0       0       0       0       0       0
+  pid-1708 int=31 dev=0x800010 ino=0x2727 gen=0xf4739822
+	  0       0       0       0       0       0       0       0
+	  2       0       0       0       0       0       0       0
+  pid-1708 int=65 dev=0x800010 ino=0x2727 gen=0xf4739822
+	  0       0       0       0       0       0       0       0
+	  1       0       0       0       0       0       0       0
+
+  pid-1708 is the dd which copied the file.  The output is separated
+  by pid-* lines and each section corresponds to single act, which has
+  intent NR and file (dev:ino:gen) associated with it.  One 8-slot
+  histogram is printed per line in ascending order.
+
+  The filesystem is mostly empty and, from the output, both files seem
+  to be located in the first 1/8th of the disk.
+
+  All reads happened through intent 58 and 59.  From intents file,
+  they are,
+
+  #58 modifier=0x0
+  [ffffffff8139d974] submit_bio+0x74/0x100
+  [ffffffff811d5dba] __blockdev_direct_IO+0xc2a/0x3830
+  [ffffffff8129fe51] ext4_ind_direct_IO+0x121/0x470
+  [ffffffff8126678e] ext4_direct_IO+0x23e/0x400
+  [ffffffff81147b05] generic_file_aio_read+0x6d5/0x760
+  [ffffffff81199932] do_sync_read+0xe2/0x120
+  [ffffffff8119a5c5] vfs_read+0xc5/0x180
+  [ffffffff8119a781] sys_read+0x51/0x90
+  [ffffffff81ab1fab] system_call_fastpath+0x16/0x1b
+  #59 modifier=0x0
+  [ffffffff8139d974] submit_bio+0x74/0x100
+  [ffffffff811d7345] __blockdev_direct_IO+0x21b5/0x3830
+  [ffffffff8129fe51] ext4_ind_direct_IO+0x121/0x470
+  [ffffffff8126678e] ext4_direct_IO+0x23e/0x400
+  [ffffffff81147b05] generic_file_aio_read+0x6d5/0x760
+  [ffffffff81199932] do_sync_read+0xe2/0x120
+  [ffffffff8119a5c5] vfs_read+0xc5/0x180
+  [ffffffff8119a781] sys_read+0x51/0x90
+  [ffffffff81ab1fab] system_call_fastpath+0x16/0x1b
+
+  Except for hitting slightly different paths in __blockdev_direct_IO,
+  they both are ext4 direct reads as expected.  Writes seem more
+  diversified and upon examination, #62 and #63 are ext4 direct
+  writes.  #31 and #65 are more interesting.
+
+  #31 modifier=0x0
+  [ffffffff811cd0cc] __set_page_dirty+0x4c/0xd0
+  [ffffffff811cd1b6] mark_buffer_dirty+0x66/0xa0
+  [ffffffff811cd299] __block_commit_write+0xa9/0xe0
+  [ffffffff811cd4a2] block_write_end+0x42/0x90
+  [ffffffff811cd523] generic_write_end+0x33/0xa0
+  [ffffffff81269720] ext4_da_write_end+0x150/0x360
+  [ffffffff81144878] generic_file_buffered_write+0x188/0x2b0
+  [ffffffff81146d18] __generic_file_aio_write+0x238/0x460
+  [ffffffff81146fb8] generic_file_aio_write+0x78/0xf0
+  [ffffffff8125fbaf] ext4_file_write+0x6f/0x2a0
+  [ffffffff81199812] do_sync_write+0xe2/0x120
+  [ffffffff8119a308] vfs_write+0xc8/0x180
+  [ffffffff8119a4c1] sys_write+0x51/0x90
+  [ffffffff81ab1fab] system_call_fastpath+0x16/0x1b
+
+  This is buffered write.  It turns out the file size didn't match the
+  specified blocksize, so dd turns off O_DIRECT for the last IO and
+  issue buffered write for the remainder.
+
+  Note that the actual IO submission is not visible in the stack trace
+  as the IOs are charged to the dirtying act.  Actual IOs are likely
+  to be executed from fsync(2).
+
+  #65 modifier=0x0
+  [ffffffff811c5e10] __mark_inode_dirty+0x220/0x330
+  [ffffffff81267edd] ext4_da_update_reserve_space+0x13d/0x230
+  [ffffffff8129006d] ext4_ext_map_blocks+0x13dd/0x1dc0
+  [ffffffff81268a31] ext4_map_blocks+0x1b1/0x260
+  [ffffffff81269c52] mpage_da_map_and_submit+0xb2/0x480
+  [ffffffff8126a84a] ext4_da_writepages+0x30a/0x6e0
+  [ffffffff8114f584] do_writepages+0x24/0x40
+  [ffffffff811468cb] __filemap_fdatawrite_range+0x5b/0x60
+  [ffffffff8114692a] filemap_write_and_wait_range+0x5a/0x80
+  [ffffffff8125ff64] ext4_sync_file+0x74/0x440
+  [ffffffff811ca31b] vfs_fsync_range+0x2b/0x40
+  [ffffffff811ca34c] vfs_fsync+0x1c/0x20
+  [ffffffff811ca58a] do_fsync+0x3a/0x60
+  [ffffffff811ca5e0] sys_fsync+0x10/0x20
+  [ffffffff81ab1fab] system_call_fastpath+0x16/0x1b
+
+  And this is dd fsync(2)ing and marking inode for writeback.  As with
+  data writeback, IO submission is not visible in the stack trace.
+
+* counters_pipe_bin
+
+  Identical to counters_pipe but in compact binary format and likely
+  to be much more performant.  Each entry in the file is in the
+  following format as defined in include/linux/ioblame.h.
+
+  #define IOBC_PIPE_BIN_VER	1
+
+  /* record struct for /sys/kernel/debug/ioblame/counters_pipe_bin */
+  struct iobc_pipe_bin_record {
+	  uint16_t	len;
+	  uint16_t	ver;
+	  int32_t	id;		/* >0 pid or negated user id */
+	  uint32_t	intent_nr;	/* associated intent */
+	  uint32_t	dev;
+	  uint64_t	ino;
+	  uint32_t	gen;
+	  uint32_t	__pad;
+	  uint32_t	cnts[];		/* [type][slot] */
+  } __packed;
+
+  Note that counters_pipe and counters_pipe_bin can't be used
+  parallelly.  Only one opener is allowed across the two files at any
+  given moment.
+
+
+4. 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.
+
+* Mechanism to specify userland role ID is not implemented yet.
+
+
+5. 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 +5 -2

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

@@ -66,10 +67,12 @@ struct bio {
 	bio_end_io_t		*bi_end_io;
 
 	void			*bi_private;
-#if defined(CONFIG_BLK_DEV_INTEGRITY)
+#ifdef 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 e0bc4ff..950b2b3 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 +4 -0

index aefa6ba..7d02c88 100644
@@ -190,6 +190,10 @@ 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;
+	u16 iob_scaled_last_sect;
+#endif
 	int node_id;
 };

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

95 lines not on this page · raw message

kernel/trace/Kconfig +11 -0

index cd31345..551d8fb 100644
@@ -368,6 +368,17 @@ 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 end-to-end IO tracer.
+
+	  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 +3479 -0

2,195 lines not on this page · raw message

The rest of this diff is not shown. View the raw message.

Signature · 1 line

1.7.3.1

Part of the diff is not shown here. View the raw message.

Namhyung Kim

2012-01-06 09:00 UTC #15 lore raw

In reply to Tejun Heo

Hi, Tejun

2012-01-06 AM 8:42, Tejun Heo Wrote:

Quoted 74 lines

This is re-post. The original posting was on Dec 15th but it was missing cc to LKML. I got some responses on that thread so didn't suspect LKML was missing. If you're getting it the second time. My apologies.
Stuff pointed out in the original thread are...
* Is the quick variant of backtrace gathering really necessary? - Still need to get performance numbers.
* TRACE_EVENT_CONDITION() can be used in some places. - Will be updated.
Original message follows. Thanks.
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 collects this information into histograms which is configurable from userland using debugfs interface.
For example, using ioblame, user can acquire information like "this task triggered IO with this stack trace on this file with the following offset distribution".
For more details, please read Documentation/trace/ioblame.txt, which I'll append to this message too for discussion.
This patchset contains the following 11 patches.
   0001-trace_event_filter-factorize-filter-creation.patch
   0002-trace_event_filter-add-trace_event_filter_-interface.patch
   0003-block-block_bio_complete-tracepoint-was-missing.patch
   0004-block-add-req-to-bio_-front-back-_merge-tracepoints.patch
   0005-block-abstract-disk-iteration-into-disk_iter.patch
   0006-writeback-move-struct-wb_writeback_work-to-writeback.patch
   0007-writeback-add-more-tracepoints.patch
   0008-block-add-block_touch_buffer-tracepoint.patch
   0009-vfs-add-fcheck-tracepoint.patch
   0010-stacktrace-implement-save_stack_trace_quick.patch
   0011-block-trace-implement-ioblame-IO-statistical-analyze.patch
0001-0002 export trace_event_filter so that ioblame can use it too.
0003 adds back block_bio_complete TP invocation, which got lost somehow. This probably makes sense as fix patch for 3.2.
0004-0006 update block layer in preparation. 0005 probably makes sense as a standalone patch too.
0007-0009 add more tracepoints along the IO stack.
0010 adds nimbler backtrace dump function as ioblame dumps stacktrace extremely frequently.
0011 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.

Quoted 8 lines

The patches are on top of mainline (42ebfc61cf "Merge branch 'stable...git/konrad/xen'") and perf/core (74eec26fac "perf tools: Add ability to synthesize event according to a sample").
It's also available in the following git branch.
git://git.kernel.org/pub/scm/linux/kernel/git/tj/misc.git review-ioblame

Very interesting. It should help analyzing and improving IO performance a lot.

BTW, it seems the ioblame based on event tracing feature, so couldn't it be implemented in userspace with the help of the tracepoints and additional information (e.g. intent, ...) you add? The perf can deal with them and extend post-processing capability easily, and also might reduce some kernel jobs, I guess.

Thanks
Namhyung Kim

Tejun Heo

author

2012-01-06 16:02 UTC #16 lore raw

Hello, Namhyung.

Quoted 5 lines · Namhyung Kim

BTW, it seems the ioblame based on event tracing feature, so couldn't it be implemented in userspace with the help of the tracepoints and additional information (e.g. intent, ...) you add? The perf can deal with them and extend post-processing capability easily, and also might reduce some kernel jobs, I guess.

Yeah, it uses tracepoints to gather information it needs, but producing relevant information (like the intent id) requires nontrivial state tracking. The point where it would make sense to push to userland is the iolog, where all the relevant information has been gathered for each IO. Currently, the export interface there is pretty dumb and slow.

Hmmm... originally, I had variable length data structure there but now it's fixed so exposing them using tracepoint shouldn't be too difficult and could actually be better (previously it didn't really fit TP and ringbuffer should be used directly). Yeah, that's a thought. Generating a TP event per IO shouldn't be taxing and it would give much better visibility to userland and we can drop the whole statics configuration and stuff. Enticing. I'll think more about it.

Thanks.

Signature · 1 line

tejun

Tejun Heo

author

2012-01-06 16:33 UTC #17 lore raw

Hello, again.

Quoted 8 lines · Tejun Heo

Hmmm... originally, I had variable length data structure there but now it's fixed so exposing them using tracepoint shouldn't be too difficult and could actually be better (previously it didn't really fit TP and ringbuffer should be used directly). Yeah, that's a thought. Generating a TP event per IO shouldn't be taxing and it would give much better visibility to userland and we can drop the whole statics configuration and stuff. Enticing. I'll think more about it.

The more I think about it, the better it seems. I ended up putting the statistics gathering inside the kernel mostly because the information I had at IO completion wasn't too fit to export to userland verbatim, but while iterating the implementation those parts got chopped (it was necessary for statistics too anyway) and now it seems I can just replace the whole thing with a single tracepoint and drop the whole configurable statistics stuff along with act and its reclaiming, and silly _bin interface. That's just sweeet. Someohw I completely missed the transition of the information available at IO completion.

I might be missing something important but will give it a shot and, if it goes as expected, post updated series soon.

Thanks a lot for bringing it up. :)

Signature · 1 line

tejun