Make background writeback not suck

Hi,

Since the dawn of time, our background buffered writeback has sucked. When we do background buffered writeback, it should have little impact on foreground activity. That's the definition of background activity... But for as long as I can remember, heavy buffered writers have not behaved like that. For instance, if I do something like this:

$ dd if=/dev/zero of=foo bs=1M count=10k

on my laptop, and then try and start chrome, it basically won't start before the buffered writeback is done. Or, for server oriented workloads, where installation of a big RPM (or similar) adversely impacts database reads or sync writes. When that happens, I get people yelling at me.

I have posted plenty of results previously, I'll keep it shorter this time. Here's a run on my laptop, using read-to-pipe-async for reading a 5g file, and rewriting it.

4.6-rc3:

$ t/read-to-pipe-async -f ~/5g > 5g-new

Latency percentiles (usec) (READERS)

	50.0000th: 2
	75.0000th: 3
	90.0000th: 5
	95.0000th: 7
	99.0000th: 43
	99.5000th: 77
	99.9000th: 9008
	99.9900th: 91008
	99.9990th: 286208
	99.9999th: 347648
	Over=1251, min=0, max=358081
Latency percentiles (usec) (WRITERS)
	50.0000th: 4
	75.0000th: 8
	90.0000th: 13
	95.0000th: 15
	99.0000th: 32
	99.5000th: 43
	99.9000th: 81
	99.9900th: 2372
	99.9990th: 104320
	99.9999th: 349696
	Over=63, min=1, max=358321

Read rate (KB/sec) : 91859
Write rate (KB/sec): 91859

4.6-rc3 + wb-buf-throttle

Latency percentiles (usec) (READERS)

	50.0000th: 2
	75.0000th: 3
	90.0000th: 5
	95.0000th: 8
	99.0000th: 48
	99.5000th: 79
	99.9000th: 5304
	99.9900th: 22496
	99.9990th: 29408
	99.9999th: 33728
	Over=860, min=0, max=37599
Latency percentiles (usec) (WRITERS)
	50.0000th: 4
	75.0000th: 9
	90.0000th: 14
	95.0000th: 16
	99.0000th: 34
	99.5000th: 45
	99.9000th: 87
	99.9900th: 1342
	99.9990th: 13648
	99.9999th: 21280
	Over=29, min=1, max=30457

Read rate (KB/sec) : 95832
Write rate (KB/sec): 95832

Better throughput and tighter latencies, for both reads and writes. That's hard not to like.

The above was the why. The how is basically throttling background writeback. We still want to issue big writes from the vm side of things, so we get nice and big extents on the file system end. But we don't need to flood the device with THOUSANDS of requests for background writeback. For most devices, we don't need a whole lot to get decent throughput.

This adds some simple blk-wb code that keeps limits how much buffered writeback we keep in flight on the device end. It's all about managing the queues on the hardware side. The big change in this version is that it should be pretty much auto-tuning - you no longer have to set a given percentage of writeback bandwidth. I've implemented something similar to CoDel to manage the writeback queue. See the last patch for a full description, but the tldr is that we monitor min latencies over a window of time, and scale up/down the queue based on that. This needs a minimum of tunables, and it stays out of the way, if your device is fast enough. There's a single tunable now, wb_last_usec, that simply sets this latency target. Most people won't have to touch this, it'll work pretty well just being in the ballpark.

I welcome testing. If you are sick of Linux bogging down when buffered writes are happening, then this is for you, laptop or server. The patchset is fully stable, I have not observed problems. It passes full xfstest runs, and a variety of benchmarks as well. It works equally well on blk-mq/scsi-mq, and "classic" setups.

You can also find this in a branch in the block git repo:

git://git.kernel.dk/linux-block.git wb-buf-throttle

Note that I rebase this branch when I collapse patches. The wb-buf-throttle-v4 will remain the same as this version. I've folded the device write cache changes into my 4.7 branches, so they are not a part of this posting. Get the full wb-buf-throttle branch, or apply the patches here on top of my for-next. A full patch against Linus' current tree can also be downloaded here:

http://brick.kernel.dk/snaps/wb-buf-throttle-v4.patch

Changes since v3

- Re-do the mm/ writheback parts. Add REQ_BG for background writes, and don't overload the wbc 'reason' for writeback decisions.
- Add tracking for when apps are sleeping waiting for a page to complete.
- Change wbc_to_write() to wbc_to_write_cmd().
- Use atomic_t for the balance_dirty_pages() sleep count.
- Add a basic scalable block stats tracking framework.
- Rewrite blk-wb core as described above, to dynamically adapt. This is a big change, see the last patch for a full description of it.
- Add tracing to blk-wb, instead of using debug printk's.
- Rebased to 4.6-rc3 (ish)

Changes since v2

- Switch from wb_depth to wb_percent, as that's an easier tunable.
- Add the patch to track device depth on the block layer side.
- Cleanup the limiting code.
- Don't use a fixed limit in the wb wait, since it can change between wakeups.
- Minor tweaks, fixups, cleanups.

Changes since v1

- Drop sync() WB_SYNC_NONE -> WB_SYNC_ALL change
- wb_start_writeback() fills in background/reclaim/sync info in the writeback work, based on writeback reason.
- Use WRITE_SYNC for reclaim/sync IO
- Split balance_dirty_pages() sleep change into separate patch
- Drop get_request() u64 flag change, set the bit on the request directly after-the-fact.
- Fix wrong sysfs return value
- Various small cleanups

 Documentation/block/queue-sysfs.txt             |    9 
 Documentation/block/writeback_cache_control.txt |    4 
 arch/um/drivers/ubd_kern.c                      |    2 
 block/Makefile                                  |    2 
 block/blk-core.c                                |   22 +
 block/blk-flush.c                               |   11 
 block/blk-mq-sysfs.c                            |   47 ++
 block/blk-mq.c                                  |   45 ++
 block/blk-mq.h                                  |    3 
 block/blk-settings.c                            |   58 +-
 block/blk-stat.c                                |  184 ++++++++
 block/blk-stat.h                                |   17 
 block/blk-sysfs.c                               |  122 +++++
 block/blk-wb.c                                  |  495 ++++++++++++++++++++++++
 block/blk-wb.h                                  |   42 ++
 drivers/block/drbd/drbd_main.c                  |    2 
 drivers/block/loop.c                            |    2 
 drivers/block/mtip32xx/mtip32xx.c               |    6 
 drivers/block/nbd.c                             |    4 
 drivers/block/osdblk.c                          |    2 
 drivers/block/ps3disk.c                         |    2 
 drivers/block/skd_main.c                        |    2 
 drivers/block/virtio_blk.c                      |    6 
 drivers/block/xen-blkback/xenbus.c              |    2 
 drivers/block/xen-blkfront.c                    |    3 
 drivers/ide/ide-disk.c                          |    6 
 drivers/md/bcache/super.c                       |    2 
 drivers/md/dm-table.c                           |   20 
 drivers/md/md.c                                 |    2 
 drivers/md/raid5-cache.c                        |    3 
 drivers/mmc/card/block.c                        |    2 
 drivers/mtd/mtd_blkdevs.c                       |    2 
 drivers/nvme/host/core.c                        |    7 
 drivers/scsi/scsi.c                             |    3 
 drivers/scsi/sd.c                               |    8 
 drivers/target/target_core_iblock.c             |    6 
 fs/block_dev.c                                  |    2 
 fs/buffer.c                                     |    2 
 fs/f2fs/data.c                                  |    2 
 fs/f2fs/node.c                                  |    2 
 fs/gfs2/meta_io.c                               |    3 
 fs/mpage.c                                      |    9 
 fs/xfs/xfs_aops.c                               |    2 
 include/linux/backing-dev-defs.h                |    2 
 include/linux/blk_types.h                       |   14 
 include/linux/blkdev.h                          |   27 +
 include/linux/fs.h                              |    4 
 include/linux/writeback.h                       |   10 
 include/trace/events/block.h                    |   98 ++++
 mm/backing-dev.c                                |    1 
 mm/filemap.c                                    |   42 +-
 mm/page-writeback.c                             |    2 
 52 files changed, 1281 insertions(+), 96 deletions(-)

Jens Axboe

This adds a new request flag, REQ_BG, that callers can use to tell the block layer that this is background (non-urgent) IO.

---
 include/linux/blk_types.h | 4 +++-
 include/linux/fs.h        | 4 ++++
 2 files changed, 7 insertions(+), 1 deletion(-)

index 86a38ea1823f..223012451c7a 100644
@@ -161,6 +161,7 @@ enum rq_flag_bits {
 	__REQ_INTEGRITY,	/* I/O includes block integrity payload */
 	__REQ_FUA,		/* forced unit access */
 	__REQ_FLUSH,		/* request for cache flush */
+	__REQ_BG,		/* background activity */
 
 	/* bio only flags */
 	__REQ_RAHEAD,		/* read ahead, can fail anytime */

@@ -208,7 +209,7 @@ enum rq_flag_bits {
 #define REQ_COMMON_MASK \
 	(REQ_WRITE | REQ_FAILFAST_MASK | REQ_SYNC | REQ_META | REQ_PRIO | \
 	 REQ_DISCARD | REQ_WRITE_SAME | REQ_NOIDLE | REQ_FLUSH | REQ_FUA | \
-	 REQ_SECURE | REQ_INTEGRITY)
+	 REQ_SECURE | REQ_INTEGRITY | REQ_BG)
 #define REQ_CLONE_MASK		REQ_COMMON_MASK
 
 #define BIO_NO_ADVANCE_ITER_MASK	(REQ_DISCARD|REQ_WRITE_SAME)

@@ -235,6 +236,7 @@ enum rq_flag_bits {
 #define REQ_COPY_USER		(1ULL << __REQ_COPY_USER)
 #define REQ_FLUSH		(1ULL << __REQ_FLUSH)
 #define REQ_FLUSH_SEQ		(1ULL << __REQ_FLUSH_SEQ)
+#define REQ_BG			(1ULL << __REQ_BG)
 #define REQ_IO_STAT		(1ULL << __REQ_IO_STAT)
 #define REQ_MIXED_MERGE		(1ULL << __REQ_MIXED_MERGE)
 #define REQ_SECURE		(1ULL << __REQ_SECURE)

index 70e61b58baaf..bb8f951cc619 100644
@@ -192,6 +192,9 @@ typedef void (dax_iodone_t)(struct buffer_head *bh_map, int uptodate);
  * WRITE_FLUSH_FUA	Combination of WRITE_FLUSH and FUA. The IO is preceded
  *			by a cache flush and data is guaranteed to be on
  *			non-volatile media on completion.
+ * WRITE_BG		Background write. This is for background activity like
+ *			the periodic flush and background threshold writeback
+ *
  *
  */
 #define RW_MASK			REQ_WRITE

@@ -207,6 +210,7 @@ typedef void (dax_iodone_t)(struct buffer_head *bh_map, int uptodate);
 #define WRITE_FLUSH		(WRITE | REQ_SYNC | REQ_NOIDLE | REQ_FLUSH)
 #define WRITE_FUA		(WRITE | REQ_SYNC | REQ_NOIDLE | REQ_FUA)
 #define WRITE_FLUSH_FUA		(WRITE | REQ_SYNC | REQ_NOIDLE | REQ_FLUSH | REQ_FUA)
+#define WRITE_BG		(WRITE | REQ_NOIDLE | REQ_BG)
 
 /*
  * Attribute flags.  These should be or-ed together to figure out what

2.8.0.rc4.6.g7e4ba36

Add wbc_to_write_cmd(), which returns the write type to use, based on a struct writeback_control. No functional changes in this patch, but it prepares us for factoring other wbc fields for write type.

---
 fs/block_dev.c            | 2 +-
 fs/buffer.c               | 2 +-
 fs/f2fs/data.c            | 2 +-
 fs/f2fs/node.c            | 2 +-
 fs/gfs2/meta_io.c         | 3 +--
 fs/mpage.c                | 9 ++++-----
 fs/xfs/xfs_aops.c         | 2 +-
 include/linux/writeback.h | 8 ++++++++
 8 files changed, 18 insertions(+), 12 deletions(-)

index 20a2c02b77c4..8662da6aa07c 100644
@@ -432,7 +432,7 @@ int bdev_write_page(struct block_device *bdev, sector_t sector,
 			struct page *page, struct writeback_control *wbc)
 {
 	int result;
-	int rw = (wbc->sync_mode == WB_SYNC_ALL) ? WRITE_SYNC : WRITE;
+	int rw = wbc_to_write_cmd(wbc);
 	const struct block_device_operations *ops = bdev->bd_disk->fops;
 
 	if (!ops->rw_page || bdev_get_integrity(bdev))

index af0d9a82a8ed..46763c58e786 100644
@@ -1697,7 +1697,7 @@ static int __block_write_full_page(struct inode *inode, struct page *page,
 	struct buffer_head *bh, *head;
 	unsigned int blocksize, bbits;
 	int nr_underway = 0;
-	int write_op = (wbc->sync_mode == WB_SYNC_ALL ? WRITE_SYNC : WRITE);
+	int write_op = wbc_to_write_cmd(wbc);
 
 	head = create_page_buffers(page, inode,
 					(1 << BH_Dirty)|(1 << BH_Uptodate));

index 5dafb9cef12e..e4e81ce663c5 100644
@@ -1153,7 +1153,7 @@ static int f2fs_write_data_page(struct page *page,
 	struct f2fs_io_info fio = {
 		.sbi = sbi,
 		.type = DATA,
-		.rw = (wbc->sync_mode == WB_SYNC_ALL) ? WRITE_SYNC : WRITE,
+		.rw = wbc_to_write_cmd(wbc),
 		.page = page,
 		.encrypted_page = NULL,
 	};

index 1a33de9d84b1..3b377258dc09 100644
@@ -1397,7 +1397,7 @@ static int f2fs_write_node_page(struct page *page,
 	struct f2fs_io_info fio = {
 		.sbi = sbi,
 		.type = NODE,
-		.rw = (wbc->sync_mode == WB_SYNC_ALL) ? WRITE_SYNC : WRITE,
+		.rw = wbc_to_write_cmd(wbc),
 		.page = page,
 		.encrypted_page = NULL,
 	};

index 0448524c11bc..3fdfa3848f18 100644
@@ -37,8 +37,7 @@ static int gfs2_aspace_writepage(struct page *page, struct writeback_control *wb
 {
 	struct buffer_head *bh, *head;
 	int nr_underway = 0;
-	int write_op = REQ_META | REQ_PRIO |
-		(wbc->sync_mode == WB_SYNC_ALL ? WRITE_SYNC : WRITE);
+	int write_op = REQ_META | REQ_PRIO | wbc_to_write_cmd(wbc);
 
 	BUG_ON(!PageLocked(page));
 	BUG_ON(!page_has_buffers(page));

index eedc644b78d7..bcbdb61b24f1 100644
@@ -486,7 +486,6 @@ static int __mpage_writepage(struct page *page, struct writeback_control *wbc,
 	struct buffer_head map_bh;
 	loff_t i_size = i_size_read(inode);
 	int ret = 0;
-	int wr = (wbc->sync_mode == WB_SYNC_ALL ?  WRITE_SYNC : WRITE);
 
 	if (page_has_buffers(page)) {
 		struct buffer_head *head = page_buffers(page);

@@ -595,7 +594,7 @@ page_is_mapped:
 	 * This page will go to BIO.  Do we need to send this BIO off first?
 	 */
 	if (bio && mpd->last_block_in_bio != blocks[0] - 1)
-		bio = mpage_bio_submit(wr, bio);
+		bio = mpage_bio_submit(wbc_to_write_cmd(wbc), bio);
 
 alloc_new:
 	if (bio == NULL) {

@@ -622,7 +621,7 @@ alloc_new:
 	wbc_account_io(wbc, page, PAGE_SIZE);
 	length = first_unmapped << blkbits;
 	if (bio_add_page(bio, page, length, 0) < length) {
-		bio = mpage_bio_submit(wr, bio);
+		bio = mpage_bio_submit(wbc_to_write_cmd(wbc), bio);
 		goto alloc_new;
 	}
 

@@ -632,7 +631,7 @@ alloc_new:
 	set_page_writeback(page);
 	unlock_page(page);
 	if (boundary || (first_unmapped != blocks_per_page)) {
-		bio = mpage_bio_submit(wr, bio);
+		bio = mpage_bio_submit(wbc_to_write_cmd(wbc), bio);
 		if (boundary_block) {
 			write_boundary_block(boundary_bdev,
 					boundary_block, 1 << blkbits);

@@ -644,7 +643,7 @@ alloc_new:
 
 confused:
 	if (bio)
-		bio = mpage_bio_submit(wr, bio);
+		bio = mpage_bio_submit(wbc_to_write_cmd(wbc), bio);
 
 	if (mpd->use_writepage) {
 		ret = mapping->a_ops->writepage(page, wbc);

index e49b2406d15d..e6c721f4153b 100644
@@ -393,7 +393,7 @@ xfs_submit_ioend_bio(
 	atomic_inc(&ioend->io_remaining);
 	bio->bi_private = ioend;
 	bio->bi_end_io = xfs_end_bio;
-	submit_bio(wbc->sync_mode == WB_SYNC_ALL ? WRITE_SYNC : WRITE, bio);
+	submit_bio(wbc_to_write_cmd(wbc), bio);
 }
 
 STATIC struct bio *

index d0b5ca5d4e08..aa66fa05ff0d 100644
@@ -100,6 +100,14 @@ struct writeback_control {
 #endif
 };
 
+static inline int wbc_to_write_cmd(struct writeback_control *wbc)
+{
+	if (wbc->sync_mode == WB_SYNC_ALL)
+		return WRITE_SYNC;
+
+	return WRITE;
+}
+
 /*
  * A wb_domain represents a domain that wb's (bdi_writeback's) belong to
  * and are measured against each other in.  There always is one global

2.8.0.rc4.6.g7e4ba36

Looks good. You can add:

Honza

Jan Kara <[email protected]>
SUSE Labs, CR

Thanks Jan, added!

Jens Axboe

If we're doing background type writes, then use the appropriate write command for that.

---
 include/linux/writeback.h | 2 ++
 1 file changed, 2 insertions(+)

index aa66fa05ff0d..6e4a35acaa3e 100644
@@ -104,6 +104,8 @@ static inline int wbc_to_write_cmd(struct writeback_control *wbc)
 {
 	if (wbc->sync_mode == WB_SYNC_ALL)
 		return WRITE_SYNC;
+	else if (wbc->for_kupdate || wbc->for_background)
+		return WRITE_BG;
 
 	return WRITE;
 }

2.8.0.rc4.6.g7e4ba36

Note in the bdi_writeback structure if a task is currently being limited in balance_dirty_pages(), waiting for writeback to proceed.

---
 include/linux/backing-dev-defs.h | 2 ++
 mm/backing-dev.c                 | 1 +
 mm/page-writeback.c              | 2 ++
 3 files changed, 5 insertions(+)

index 3f103076d0bf..1212c374b928 100644
@@ -116,6 +116,8 @@ struct bdi_writeback {
 	struct list_head work_list;
 	struct delayed_work dwork;	/* work item used for writeback */
 
+	atomic_t dirty_sleeping;	/* waiting on dirty limit exceeded */
+
 	struct list_head bdi_node;	/* anchored at bdi->wb_list */
 
 #ifdef CONFIG_CGROUP_WRITEBACK

index 0c6317b7db38..41db7dff11d0 100644
@@ -310,6 +310,7 @@ static int wb_init(struct bdi_writeback *wb, struct backing_dev_info *bdi,
 	spin_lock_init(&wb->work_lock);
 	INIT_LIST_HEAD(&wb->work_list);
 	INIT_DELAYED_WORK(&wb->dwork, wb_workfn);
+	atomic_set(&wb->dirty_sleeping, 0);
 
 	wb->congested = wb_congested_get_create(bdi, blkcg_id, gfp);
 	if (!wb->congested)

index 999792d35ccc..028a3d4d7129 100644
@@ -1746,7 +1746,9 @@ pause:
 					  pause,
 					  start_time);
 		__set_current_state(TASK_KILLABLE);
+		atomic_inc(&wb->dirty_sleeping);
 		io_schedule_timeout(pause);
+		atomic_dec(&wb->dirty_sleeping);
 
 		current->dirty_paused_when = now + pause;
 		current->nr_dirtied = 0;

2.8.0.rc4.6.g7e4ba36

If we end up waiting on a page that is dirty or marked writeback, then increment the corresponding bdi_writeback counter.

---
 mm/filemap.c | 42 +++++++++++++++++++++++++++++++++++++++---
 1 file changed, 39 insertions(+), 3 deletions(-)

index f2479af09da9..a8854a083b71 100644
@@ -764,37 +764,73 @@ wait_queue_head_t *page_waitqueue(struct page *page)
 }
 EXPORT_SYMBOL(page_waitqueue);
 
+static bool inc_dirty_wait(struct page *page)
+{
+	if (!page->mapping || !PageDirty(page) || !PageWriteback(page))
+		return false;
+	else {
+		struct bdi_writeback *wb = inode_to_wb(page->mapping->host);
+
+		atomic_inc(&wb->dirty_sleeping);
+		return true;
+	}
+}
+
+static void dec_dirty_wait(struct page *page)
+{
+	struct bdi_writeback *wb = inode_to_wb(page->mapping->host);
+
+	atomic_dec(&wb->dirty_sleeping);
+}
+
 void wait_on_page_bit(struct page *page, int bit_nr)
 {
 	DEFINE_WAIT_BIT(wait, &page->flags, bit_nr);
 
-	if (test_bit(bit_nr, &page->flags))
+	if (test_bit(bit_nr, &page->flags)) {
+		bool did_inc = inc_dirty_wait(page);
 		__wait_on_bit(page_waitqueue(page), &wait, bit_wait_io,
 							TASK_UNINTERRUPTIBLE);
+		if (did_inc)
+			dec_dirty_wait(page);
+	}
 }
 EXPORT_SYMBOL(wait_on_page_bit);
 
 int wait_on_page_bit_killable(struct page *page, int bit_nr)
 {
 	DEFINE_WAIT_BIT(wait, &page->flags, bit_nr);
+	bool did_inc;
+	int ret;
 
 	if (!test_bit(bit_nr, &page->flags))
 		return 0;
 
-	return __wait_on_bit(page_waitqueue(page), &wait,
+	did_inc = inc_dirty_wait(page);
+	ret = __wait_on_bit(page_waitqueue(page), &wait,
 			     bit_wait_io, TASK_KILLABLE);
+	if (did_inc)
+		dec_dirty_wait(page);
+	return ret;
 }
 
 int wait_on_page_bit_killable_timeout(struct page *page,
 				       int bit_nr, unsigned long timeout)
 {
 	DEFINE_WAIT_BIT(wait, &page->flags, bit_nr);
+	bool did_inc;
+	int ret;
 
 	wait.key.timeout = jiffies + timeout;
 	if (!test_bit(bit_nr, &page->flags))
 		return 0;
-	return __wait_on_bit(page_waitqueue(page), &wait,
+
+	did_inc = inc_dirty_wait(page);
+	ret = __wait_on_bit(page_waitqueue(page), &wait,
 			     bit_wait_io_timeout, TASK_KILLABLE);
+	if (did_inc)
+		dec_dirty_wait(page);
+	return ret;
 }
 EXPORT_SYMBOL_GPL(wait_on_page_bit_killable_timeout);
 

2.8.0.rc4.6.g7e4ba36

For blk-mq, ->nr_requests does track queue depth, at least at init time. But for the older queue paths, it's simply a soft setting. On top of that, it's generally larger than the hardware setting on purpose, to allow backup of requests for merging.

Fill a hole in struct request with a 'queue_depth' member, that drivers can call to more closely inform the block layer of the real queue depth.

---
 block/blk-settings.c   | 12 ++++++++++++
 drivers/scsi/scsi.c    |  3 +++
 include/linux/blkdev.h | 11 +++++++++++
 3 files changed, 26 insertions(+)

index f679ae122843..f7e122e717e8 100644
@@ -832,6 +832,18 @@ void blk_queue_flush_queueable(struct request_queue *q, bool queueable)
 EXPORT_SYMBOL_GPL(blk_queue_flush_queueable);
 
 /**
+ * blk_set_queue_depth - tell the block layer about the device queue depth
+ * @q:		the request queue for the device
+ * @depth:		queue depth
+ *
+ */
+void blk_set_queue_depth(struct request_queue *q, unsigned int depth)
+{
+	q->queue_depth = depth;
+}
+EXPORT_SYMBOL(blk_set_queue_depth);
+
+/**
  * blk_queue_write_cache - configure queue's write cache
  * @q:		the request queue for the device
  * @wc:		write back cache on or off

index 1deb6adc411f..75455d4dab68 100644
@@ -621,6 +621,9 @@ int scsi_change_queue_depth(struct scsi_device *sdev, int depth)
 		wmb();
 	}
 
+	if (sdev->request_queue)
+		blk_set_queue_depth(sdev->request_queue, depth);
+
 	return sdev->queue_depth;
 }
 EXPORT_SYMBOL(scsi_change_queue_depth);

index fc1894996b12..eee94bd6de52 100644
@@ -315,6 +315,8 @@ struct request_queue {
 	struct blk_mq_ctx __percpu	*queue_ctx;
 	unsigned int		nr_queues;
 
+	unsigned int		queue_depth;
+
 	/* hw dispatch queues */
 	struct blk_mq_hw_ctx	**queue_hw_ctx;
 	unsigned int		nr_hw_queues;

@@ -681,6 +683,14 @@ static inline bool blk_write_same_mergeable(struct bio *a, struct bio *b)
 	return false;
 }
 
+static inline unsigned int blk_queue_depth(struct request_queue *q)
+{
+	if (q->queue_depth)
+		return q->queue_depth;
+
+	return q->nr_requests;
+}
+
 /*
  * q->prep_rq_fn return values
  */

@@ -984,6 +994,7 @@ extern void blk_limits_io_min(struct queue_limits *limits, unsigned int min);
 extern void blk_queue_io_min(struct request_queue *q, unsigned int min);
 extern void blk_limits_io_opt(struct queue_limits *limits, unsigned int opt);
 extern void blk_queue_io_opt(struct request_queue *q, unsigned int opt);
+extern void blk_set_queue_depth(struct request_queue *q, unsigned int depth);
 extern void blk_set_default_limits(struct queue_limits *lim);
 extern void blk_set_stacking_limits(struct queue_limits *lim);
 extern int blk_stack_limits(struct queue_limits *t, struct queue_limits *b,

2.8.0.rc4.6.g7e4ba36

For legacy block, we simply track them in the request queue. For blk-mq, we track them on a per-sw queue basis, which we can then sum up through the hardware queues and finally to a per device state.

The stats are tracked in, roughly, 0.1s interval windows.

Add sysfs files to display the stats.

---
 block/Makefile            |   2 +-
 block/blk-core.c          |   4 +
 block/blk-mq-sysfs.c      |  47 ++++++++++++
 block/blk-mq.c            |  14 ++++
 block/blk-mq.h            |   3 +
 block/blk-stat.c          | 184 ++++++++++++++++++++++++++++++++++++++++++++++
 block/blk-stat.h          |  17 +++++
 block/blk-sysfs.c         |  26 +++++++
 include/linux/blk_types.h |   8 ++
 include/linux/blkdev.h    |   4 +
 10 files changed, 308 insertions(+), 1 deletion(-)
 create mode 100644 block/blk-stat.c
 create mode 100644 block/blk-stat.h

index 9eda2322b2d4..3446e0472df0 100644
@@ -5,7 +5,7 @@
 obj-$(CONFIG_BLOCK) := bio.o elevator.o blk-core.o blk-tag.o blk-sysfs.o \
 			blk-flush.o blk-settings.o blk-ioc.o blk-map.o \
 			blk-exec.o blk-merge.o blk-softirq.o blk-timeout.o \
-			blk-lib.o blk-mq.o blk-mq-tag.o \
+			blk-lib.o blk-mq.o blk-mq-tag.o blk-stat.o \
 			blk-mq-sysfs.o blk-mq-cpu.o blk-mq-cpumap.o ioctl.o \
 			genhd.o scsi_ioctl.o partition-generic.o ioprio.o \
 			badblocks.o partitions/

index 74c16fd8995d..40b57bf4852c 100644
@@ -2514,6 +2514,8 @@ void blk_start_request(struct request *req)
 {
 	blk_dequeue_request(req);
 
+	req->issue_time = ktime_to_ns(ktime_get());
+
 	/*
 	 * We are now handing the request to the hardware, initialize
 	 * resid_len to full count and add the timeout handler.

@@ -2581,6 +2583,8 @@ bool blk_update_request(struct request *req, int error, unsigned int nr_bytes)
 
 	trace_block_rq_complete(req->q, req, nr_bytes);
 
+	blk_stat_add(&req->q->rq_stats[rq_data_dir(req)], req);
+
 	if (!req->bio)
 		return false;
 

index 1699baf39b78..71b4a13fbf94 100644
@@ -29,6 +29,7 @@
 #include "blk.h"
 #include "blk-mq.h"
 #include "blk-mq-tag.h"
+#include "blk-stat.h"
 
 static DEFINE_MUTEX(all_q_mutex);
 static LIST_HEAD(all_q_list);

@@ -356,10 +357,19 @@ static void blk_mq_ipi_complete_request(struct request *rq)
 	put_cpu();
 }
 
+static void blk_mq_stat_add(struct request *rq)
+{
+	struct blk_rq_stat *stat = &rq->mq_ctx->stat[rq_data_dir(rq)];
+
+	blk_stat_add(stat, rq);
+}
+
 static void __blk_mq_complete_request(struct request *rq)
 {
 	struct request_queue *q = rq->q;
 
+	blk_mq_stat_add(rq);
+
 	if (!q->softirq_done_fn)
 		blk_mq_end_request(rq, rq->errors);
 	else

@@ -403,6 +413,8 @@ void blk_mq_start_request(struct request *rq)
 	if (unlikely(blk_bidi_rq(rq)))
 		rq->next_rq->resid_len = blk_rq_bytes(rq->next_rq);
 
+	rq->issue_time = ktime_to_ns(ktime_get());
+
 	blk_add_timer(rq);
 
 	/*

@@ -1761,6 +1773,8 @@ static void blk_mq_init_cpu_queues(struct request_queue *q,
 		spin_lock_init(&__ctx->lock);
 		INIT_LIST_HEAD(&__ctx->rq_list);
 		__ctx->queue = q;
+		blk_stat_init(&__ctx->stat[0]);
+		blk_stat_init(&__ctx->stat[1]);
 
 		/* If the cpu isn't online, the cpu is mapped to first hctx */
 		if (!cpu_online(i))

index 9087b11037b7..e107f700ff17 100644
@@ -1,6 +1,8 @@
 #ifndef INT_BLK_MQ_H
 #define INT_BLK_MQ_H
 
+#include "blk-stat.h"
+
 struct blk_mq_tag_set;
 
 struct blk_mq_ctx {

@@ -20,6 +22,7 @@ struct blk_mq_ctx {
 
 	/* incremented at completion time */
 	unsigned long		____cacheline_aligned_in_smp rq_completed[2];
+	struct blk_rq_stat	stat[2];
 
 	struct request_queue	*queue;
 	struct kobject		kobj;

new file mode 100644
index 000000000000..d77548dbf196
@@ -0,0 +1,17 @@
+#ifndef BLK_STAT_H
+#define BLK_STAT_H
+
+/*
+ * ~0.13s window as a power-of-2 (2^27 nsecs)
+ */
+#define BLK_STAT_NSEC	134217728ULL
+#define BLK_STAT_MASK	~(BLK_STAT_NSEC - 1)
+
+void blk_stat_add(struct blk_rq_stat *, struct request *);
+void blk_hctx_stat_get(struct blk_mq_hw_ctx *, struct blk_rq_stat *);
+void blk_queue_stat_get(struct request_queue *, struct blk_rq_stat *);
+void blk_stat_clear(struct request_queue *q);
+void blk_stat_init(struct blk_rq_stat *);
+void blk_stat_sum(struct blk_rq_stat *, struct blk_rq_stat *);
+
+#endif

index 99205965f559..6e516cc0d3d0 100644
@@ -379,6 +379,26 @@ static ssize_t queue_wc_store(struct request_queue *q, const char *page,
 	return count;
 }
 
+static ssize_t print_stat(char *page, struct blk_rq_stat *stat, const char *pre)
+{
+	return sprintf(page, "%s samples=%llu, mean=%lld, min=%lld, max=%lld\n",
+			pre, (long long) stat->nr_samples,
+			(long long) stat->mean, (long long) stat->min,
+			(long long) stat->max);
+}
+
+static ssize_t queue_stats_show(struct request_queue *q, char *page)
+{
+	struct blk_rq_stat stat[2];
+	ssize_t ret;
+
+	blk_queue_stat_get(q, stat);
+
+	ret = print_stat(page, &stat[0], "read :");
+	ret += print_stat(page + ret, &stat[1], "write:");
+	return ret;
+}
+
 static struct queue_sysfs_entry queue_requests_entry = {
 	.attr = {.name = "nr_requests", .mode = S_IRUGO | S_IWUSR },
 	.show = queue_requests_show,

@@ -516,6 +536,11 @@ static struct queue_sysfs_entry queue_wc_entry = {
 	.store = queue_wc_store,
 };
 
+static struct queue_sysfs_entry queue_stats_entry = {
+	.attr = {.name = "stats", .mode = S_IRUGO },
+	.show = queue_stats_show,
+};
+
 static struct attribute *default_attrs[] = {
 	&queue_requests_entry.attr,
 	&queue_ra_entry.attr,

@@ -542,6 +567,7 @@ static struct attribute *default_attrs[] = {
 	&queue_random_entry.attr,
 	&queue_poll_entry.attr,
 	&queue_wc_entry.attr,
+	&queue_stats_entry.attr,
 	NULL,
 };
 

index 223012451c7a..2b4414fb4d8e 100644
@@ -268,4 +268,12 @@ static inline unsigned int blk_qc_t_to_tag(blk_qc_t cookie)
 	return cookie & ((1u << BLK_QC_T_SHIFT) - 1);
 }
 
+struct blk_rq_stat {
+	s64 mean;
+	u64 min;
+	u64 max;
+	s64 nr_samples;
+	s64 time;
+};
+
 #endif /* __LINUX_BLK_TYPES_H */

index eee94bd6de52..87f6703ced71 100644
@@ -153,6 +153,7 @@ struct request {
 	struct gendisk *rq_disk;
 	struct hd_struct *part;
 	unsigned long start_time;
+	s64 issue_time;
 #ifdef CONFIG_BLK_CGROUP
 	struct request_list *rl;		/* rl this rq is alloced from */
 	unsigned long long start_time_ns;

@@ -402,6 +403,9 @@ struct request_queue {
 
 	unsigned int		nr_sorted;
 	unsigned int		in_flight[2];
+
+	struct blk_rq_stat	rq_stats[2];
+
 	/*
 	 * Number of active block driver functions for which blk_drain_queue()
 	 * must wait. Must be incremented around functions that unlock the

2.8.0.rc4.6.g7e4ba36

Test patch that throttles buffered writeback to make it a lot more smooth, and has way less impact on other system activity. Background writeback should be, by definition, background activity. The fact that we flush huge bundles of it at the time means that it potentially has heavy impacts on foreground workloads, which isn't ideal. We can't easily limit the sizes of writes that we do, since that would impact file system layout in the presence of delayed allocation. So just throttle back buffered writeback, unless someone is waiting for it.

The algorithm for when to throttle takes its inspiration in the CoDel networking scheduling algorithm. Like CoDel, blk-wb monitors the minimum latencies of requests over a window of time. In that window of time, if the minimum latency of any request exceeds a given target, then a scale count is incremented and the queue depth is shrunk. The next monitoring window is shrunk accordingly. Unlike CoDel, if we hit a window that exhibits good behavior, then we simply increment the scale count and re-calculate the limits for that scale value. This prevents us from oscillating between a close-to-ideal value and max all the time, instead remaining in the windows where we get good behavior.

The patch registers two sysfs entries. The first one, 'wb_lat_usec', sets the latency target for the window. It defaults to 2 msec for non-rotational storage, and 75 msec for rotational storage. Setting this value to '0' disables blk-wb.

The second entry, 'wb_stats', is a debug entry, that simply shows the current internal state of the throttling machine:

$ cat /sys/block/nvme0n1/queue/wb_stats
background=16, normal=32, max=64, inflight=0, wait=0, bdp_wait=0

'background' denotes how many requests we will allow in-flight for idle background buffered writeback, 'normal' for higher priority writeback, and 'max' for when it's urgent we clean pages.

'inflight' shows how many requests are currently in-flight for buffered writeback, 'wait' shows if anyone is currently waiting for access, and 'bdp_wait' shows if someone is currently throttled on this device in balance_dirty_pages().

blk-wb also registers a few trace events, that can be used to monitor the state changes:

block_wb_lat: Latency 2446318

block_wb_stat: read lat: mean=2446318, min=2446318, max=2446318, samples=1,

               write lat: mean=518866, min=15522, max=5330353, samples=57

block_wb_step: step down: step=1, background=8, normal=16, max=32

'block_wb_lat' logs a violation in sync issue latency, 'block_wb_stat' logs a window violation of latencies and dumps the stats that lead to that, and finally, 'block_wb_stat' logs a step up/down and the new limits associated with that state.

---
 block/Makefile               |   2 +-
 block/blk-core.c             |  15 ++
 block/blk-mq.c               |  31 ++-
 block/blk-settings.c         |   4 +
 block/blk-sysfs.c            |  57 +++++
 block/blk-wb.c               | 495 +++++++++++++++++++++++++++++++++++++++++++
 block/blk-wb.h               |  42 ++++
 include/linux/blk_types.h    |   2 +
 include/linux/blkdev.h       |   3 +
 include/trace/events/block.h |  98 +++++++++
 10 files changed, 746 insertions(+), 3 deletions(-)
 create mode 100644 block/blk-wb.c
 create mode 100644 block/blk-wb.h

index 3446e0472df0..7e4be7a56a59 100644
@@ -5,7 +5,7 @@
 obj-$(CONFIG_BLOCK) := bio.o elevator.o blk-core.o blk-tag.o blk-sysfs.o \
 			blk-flush.o blk-settings.o blk-ioc.o blk-map.o \
 			blk-exec.o blk-merge.o blk-softirq.o blk-timeout.o \
-			blk-lib.o blk-mq.o blk-mq-tag.o blk-stat.o \
+			blk-lib.o blk-mq.o blk-mq-tag.o blk-stat.o blk-wb.o \
 			blk-mq-sysfs.o blk-mq-cpu.o blk-mq-cpumap.o ioctl.o \
 			genhd.o scsi_ioctl.o partition-generic.o ioprio.o \
 			badblocks.o partitions/

index 40b57bf4852c..d941f69dfb4b 100644
@@ -39,6 +39,7 @@
 
 #include "blk.h"
 #include "blk-mq.h"
+#include "blk-wb.h"
 
 EXPORT_TRACEPOINT_SYMBOL_GPL(block_bio_remap);
 EXPORT_TRACEPOINT_SYMBOL_GPL(block_rq_remap);

@@ -880,6 +881,7 @@ blk_init_allocated_queue(struct request_queue *q, request_fn_proc *rfn,
 
 fail:
 	blk_free_flush_queue(q->fq);
+	blk_wb_exit(q);
 	return NULL;
 }
 EXPORT_SYMBOL(blk_init_allocated_queue);

@@ -1395,6 +1397,7 @@ void blk_requeue_request(struct request_queue *q, struct request *rq)
 	blk_delete_timer(rq);
 	blk_clear_rq_complete(rq);
 	trace_block_rq_requeue(q, rq);
+	blk_wb_requeue(q->rq_wb, rq);
 
 	if (rq->cmd_flags & REQ_QUEUED)
 		blk_queue_end_tag(q, rq);

@@ -1485,6 +1488,8 @@ void __blk_put_request(struct request_queue *q, struct request *req)
 	/* this is a bio leak */
 	WARN_ON(req->bio != NULL);
 
+	blk_wb_done(q->rq_wb, req);
+
 	/*
 	 * Request may not have originated from ll_rw_blk. if not,
 	 * it didn't come out of our reserved rq pools

@@ -1714,6 +1719,7 @@ static blk_qc_t blk_queue_bio(struct request_queue *q, struct bio *bio)
 	int el_ret, rw_flags, where = ELEVATOR_INSERT_SORT;
 	struct request *req;
 	unsigned int request_count = 0;
+	bool wb_acct;
 
 	/*
 	 * low level driver can indicate that it wants pages above a

@@ -1766,6 +1772,8 @@ static blk_qc_t blk_queue_bio(struct request_queue *q, struct bio *bio)
 	}
 
 get_rq:
+	wb_acct = blk_wb_wait(q->rq_wb, bio, q->queue_lock);
+
 	/*
 	 * This sync check and mask will be re-done in init_request_from_bio(),
 	 * but we need to set it earlier to expose the sync flag to the

@@ -1781,11 +1789,16 @@ get_rq:
 	 */
 	req = get_request(q, rw_flags, bio, GFP_NOIO);
 	if (IS_ERR(req)) {
+		if (wb_acct)
+			__blk_wb_done(q->rq_wb);
 		bio->bi_error = PTR_ERR(req);
 		bio_endio(bio);
 		goto out_unlock;
 	}
 
+	if (wb_acct)
+		req->cmd_flags |= REQ_BUF_INFLIGHT;
+
 	/*
 	 * After dropping the lock and possibly sleeping here, our request
 	 * may now be mergeable after it had proven unmergeable (above).

@@ -2515,6 +2528,7 @@ void blk_start_request(struct request *req)
 	blk_dequeue_request(req);
 
 	req->issue_time = ktime_to_ns(ktime_get());
+	blk_wb_issue(req->q->rq_wb, req);
 
 	/*
 	 * We are now handing the request to the hardware, initialize

@@ -2751,6 +2765,7 @@ void blk_finish_request(struct request *req, int error)
 		blk_unprep_request(req);
 
 	blk_account_io_done(req);
+	blk_wb_done(req->q->rq_wb, req);
 
 	if (req->end_io)
 		req->end_io(req, error);

index 71b4a13fbf94..c0c5207fe7fd 100644
@@ -30,6 +30,7 @@
 #include "blk-mq.h"
 #include "blk-mq-tag.h"
 #include "blk-stat.h"
+#include "blk-wb.h"
 
 static DEFINE_MUTEX(all_q_mutex);
 static LIST_HEAD(all_q_list);

@@ -275,6 +276,9 @@ static void __blk_mq_free_request(struct blk_mq_hw_ctx *hctx,
 
 	if (rq->cmd_flags & REQ_MQ_INFLIGHT)
 		atomic_dec(&hctx->nr_active);
+
+	blk_wb_done(q->rq_wb, rq);
+
 	rq->cmd_flags = 0;
 
 	clear_bit(REQ_ATOM_STARTED, &rq->atomic_flags);

@@ -305,6 +309,7 @@ EXPORT_SYMBOL_GPL(blk_mq_free_request);
 inline void __blk_mq_end_request(struct request *rq, int error)
 {
 	blk_account_io_done(rq);
+	blk_wb_done(rq->q->rq_wb, rq);
 
 	if (rq->end_io) {
 		rq->end_io(rq, error);

@@ -414,6 +419,7 @@ void blk_mq_start_request(struct request *rq)
 		rq->next_rq->resid_len = blk_rq_bytes(rq->next_rq);
 
 	rq->issue_time = ktime_to_ns(ktime_get());
+	blk_wb_issue(q->rq_wb, rq);
 
 	blk_add_timer(rq);
 

@@ -450,6 +456,7 @@ static void __blk_mq_requeue_request(struct request *rq)
 	struct request_queue *q = rq->q;
 
 	trace_block_rq_requeue(q, rq);
+	blk_wb_requeue(q->rq_wb, rq);
 
 	if (test_and_clear_bit(REQ_ATOM_STARTED, &rq->atomic_flags)) {
 		if (q->dma_drain_size && blk_rq_bytes(rq))

@@ -1265,6 +1272,7 @@ static blk_qc_t blk_mq_make_request(struct request_queue *q, struct bio *bio)
 	struct blk_plug *plug;
 	struct request *same_queue_rq = NULL;
 	blk_qc_t cookie;
+	bool wb_acct;
 
 	blk_queue_bounce(q, &bio);
 

@@ -1282,9 +1290,17 @@ static blk_qc_t blk_mq_make_request(struct request_queue *q, struct bio *bio)
 	} else
 		request_count = blk_plug_queued_count(q);
 
+	wb_acct = blk_wb_wait(q->rq_wb, bio, NULL);
+
 	rq = blk_mq_map_request(q, bio, &data);
-	if (unlikely(!rq))
+	if (unlikely(!rq)) {
+		if (wb_acct)
+			__blk_wb_done(q->rq_wb);
 		return BLK_QC_T_NONE;
+	}
+
+	if (wb_acct)
+		rq->cmd_flags |= REQ_BUF_INFLIGHT;
 
 	cookie = blk_tag_to_qc_t(rq->tag, data.hctx->queue_num);
 

@@ -1361,6 +1377,7 @@ static blk_qc_t blk_sq_make_request(struct request_queue *q, struct bio *bio)
 	struct blk_map_ctx data;
 	struct request *rq;
 	blk_qc_t cookie;
+	bool wb_acct;
 
 	blk_queue_bounce(q, &bio);
 

@@ -1375,9 +1392,17 @@ static blk_qc_t blk_sq_make_request(struct request_queue *q, struct bio *bio)
 	    blk_attempt_plug_merge(q, bio, &request_count, NULL))
 		return BLK_QC_T_NONE;
 
+	wb_acct = blk_wb_wait(q->rq_wb, bio, NULL);
+
 	rq = blk_mq_map_request(q, bio, &data);
-	if (unlikely(!rq))
+	if (unlikely(!rq)) {
+		if (wb_acct)
+			__blk_wb_done(q->rq_wb);
 		return BLK_QC_T_NONE;
+	}
+
+	if (wb_acct)
+		rq->cmd_flags |= REQ_BUF_INFLIGHT;
 
 	cookie = blk_tag_to_qc_t(rq->tag, data.hctx->queue_num);
 

@@ -2111,6 +2136,8 @@ void blk_mq_free_queue(struct request_queue *q)
 	list_del_init(&q->all_q_node);
 	mutex_unlock(&all_q_mutex);
 
+	blk_wb_exit(q);
+
 	blk_mq_del_queue_tag_set(q);
 
 	blk_mq_exit_hw_queues(q, set, set->nr_hw_queues);

index f7e122e717e8..84bcfc22e020 100644
@@ -13,6 +13,7 @@
 #include <linux/gfp.h>
 
 #include "blk.h"
+#include "blk-wb.h"
 
 unsigned long blk_max_low_pfn;
 EXPORT_SYMBOL(blk_max_low_pfn);

@@ -840,6 +841,9 @@ EXPORT_SYMBOL_GPL(blk_queue_flush_queueable);
 void blk_set_queue_depth(struct request_queue *q, unsigned int depth)
 {
 	q->queue_depth = depth;
+
+	if (q->rq_wb)
+		blk_wb_update_limits(q->rq_wb);
 }
 EXPORT_SYMBOL(blk_set_queue_depth);
 

index 2b4414fb4d8e..c41f8a303804 100644
@@ -189,6 +189,7 @@ enum rq_flag_bits {
 	__REQ_PM,		/* runtime pm request */
 	__REQ_HASHED,		/* on IO scheduler merge hash */
 	__REQ_MQ_INFLIGHT,	/* track inflight for MQ */
+	__REQ_BUF_INFLIGHT,	/* track inflight for buffered */
 	__REQ_NR_BITS,		/* stops here */
 };
 

@@ -243,6 +244,7 @@ enum rq_flag_bits {
 #define REQ_PM			(1ULL << __REQ_PM)
 #define REQ_HASHED		(1ULL << __REQ_HASHED)
 #define REQ_MQ_INFLIGHT		(1ULL << __REQ_MQ_INFLIGHT)
+#define REQ_BUF_INFLIGHT	(1ULL << __REQ_BUF_INFLIGHT)
 
 typedef unsigned int blk_qc_t;
 #define BLK_QC_T_NONE	-1U

index 87f6703ced71..230c55dc95ae 100644
@@ -37,6 +37,7 @@ struct bsg_job;
 struct blkcg_gq;
 struct blk_flush_queue;
 struct pr_ops;
+struct rq_wb;
 
 #define BLKDEV_MIN_RQ	4
 #define BLKDEV_MAX_RQ	128	/* Default maximum */

@@ -291,6 +292,8 @@ struct request_queue {
 	int			nr_rqs[2];	/* # allocated [a]sync rqs */
 	int			nr_rqs_elvpriv;	/* # allocated rqs w/ elvpriv */
 
+	struct rq_wb		*rq_wb;
+
 	/*
 	 * If blkcg is not used, @q->root_rl serves all requests.  If blkcg
 	 * is used, root blkg allocates from @q->root_rl and all other

2.8.0.rc4.6.g7e4ba36

Yeah, that was a mistake, the current version has it fixed. It was inadvertently added when I discovered that the flush request didn't work properly. Now it just duplicates the call inside the check for if it has an ->end_io() defined, since we don't use the normal path for that.

Jens Axboe

Hi Jens,

I have checked the wb-buf-throttle branch in your block git repo. I am not sure it is the completed version. Seems only the problem is fixed in blk-mq.c. The function blk_wb_done() still would be executed twice in blk-core.c. (the functions blk_finish_request() and __blk_put_request())
Maybe we can add a flag to mark whether blk_wb_done() has been done or not.

Regards
Kaixu Xia

Good catch, looks like I did only patch up the mq bits. It's still not perfect, since we could potentially double account a request that has a private end_io(), if it was allocated through the normal block rq allocator. It'll skew the unrelated-io-timestamp a bit, but it's not a big deal. The count for inflight will be consistent, which is the important part.

We currently have just 1 bit to tell if the request is tracked or not, so we don't know if it was tracked but already seen.

I'll fix up the blk-core part to be identical to the blk-mq fix.

Jens Axboe

Hi Jens,

I am testing current linux-block.git#wb-buf-throttle on top of Linux v4.6-rc5 here on my Ubuntu/precise AMD64.
( Was installed as a WUBI "test" system - "testing" since April 2012 :-) .)

Here are some numbers:

# df -T | egrep  'sda|loop'
/dev/sda2      fuseblk  465546236 210981868 254564368   46% /host
/dev/loop0     ext4      17753424  15586612   1241936   93% /

# egrep 'sda|loop|ext4' /etc/fstab
/host/ubuntu/disks/root.disk    /               ext4
loop,errors=remount-ro  0       1
/host/ubuntu/disks/swap.disk    none            swap    loop,sw
         0       0

( Not sure why I cannot do a find on /sys/block/ .)

# find /sys/devices/ -name '*wb_stat*' | egrep 'loop0|sda'
/sys/devices/pci0000:00/0000:00:1f.2/ata1/host0/target0:0:0/0:0:0:0/block/sda/queue/wb_stats
/sys/devices/virtual/block/loop0/queue/wb_stats

# find /sys/devices/ -name '*wb_lat*' | egrep 'loop0|sda'
/sys/devices/pci0000:00/0000:00:1f.2/ata1/host0/target0:0:0/0:0:0:0/block/sda/queue/wb_lat_usec
/sys/devices/virtual/block/loop0/queue/wb_lat_usec

# cat /sys/devices/pci0000:00/0000:00:1f.2/ata1/host0/target0:0:0/0:0:0:0/block/sda/queue/wb_stats
/sys/devices/pci0000:00/0000:00:1f.2/ata1/host0/target0:0:0/0:0:0:0/block/sda/queue/wb_lat_usec
background=8, normal=16, max=31, inflight=0, wait=0, bdp_wait=0
75000

# cat /sys/devices/virtual/block/loop0/queue/wb_stats
/sys/devices/virtual/block/loop0/queue/wb_lat_usec
background=16, normal=32, max=64, inflight=0, wait=0, bdp_wait=0
75000

Questions...

Planning a v5?
Will this go to Linux v4.7 or later?
How should someone test?

Documentation...

Can you add some more docs about getting infos (see above cat#s etc.) below Documentation/ directory?
( Talking about the stuff you have embedded in the commit-messages. )

Unfortunately, I have no more data-volume (using Mobile Broadband Network @ 56kBps), so I cannot send you my dmesg, linux-config and patchset.

Regards,
- Sedat -

[    0.000000] Linux version 4.6.0-rc5-9-iniza-small ([email protected]@fambox) (gcc version 4.9.2 (Ubuntu 4.9.2-0ubuntu1~12.04) ) #1 SMP Tue Apr 26 00:42:31 CEST 2016
[    0.000000] Command line: BOOT_IMAGE=/boot/vmlinuz-4.6.0-rc5-9-iniza-small root=UUID=001AADA61AAD9964 loop=/ubuntu/disks/root.disk ro
[    0.000000] KERNEL supported cpus:
[    0.000000]   Intel GenuineIntel
[    0.000000]   AMD AuthenticAMD
[    0.000000]   Centaur CentaurHauls
[    0.000000] Disabled fast string operations
[    0.000000] x86/fpu: xstate_offset[2]:  576, xstate_sizes[2]:  256
[    0.000000] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers'
[    0.000000] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers'
[    0.000000] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers'
[    0.000000] x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'standard' format.
[    0.000000] x86/fpu: Using 'eager' FPU context switches.
[    0.000000] e820: BIOS-provided physical RAM map:
[    0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009d7ff] usable
[    0.000000] BIOS-e820: [mem 0x000000000009d800-0x000000000009ffff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000000e0000-0x00000000000fffff] reserved
[    0.000000] BIOS-e820: [mem 0x0000000000100000-0x000000001fffffff] usable
[    0.000000] BIOS-e820: [mem 0x0000000020000000-0x00000000201fffff] reserved
[    0.000000] BIOS-e820: [mem 0x0000000020200000-0x000000003fffffff] usable
[    0.000000] BIOS-e820: [mem 0x0000000040000000-0x00000000401fffff] reserved
[    0.000000] BIOS-e820: [mem 0x0000000040200000-0x00000000d9c9efff] usable
[    0.000000] BIOS-e820: [mem 0x00000000d9c9f000-0x00000000dae7efff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000dae7f000-0x00000000daf9efff] ACPI NVS
[    0.000000] BIOS-e820: [mem 0x00000000daf9f000-0x00000000daffefff] ACPI data
[    0.000000] BIOS-e820: [mem 0x00000000dafff000-0x00000000daffffff] usable
[    0.000000] BIOS-e820: [mem 0x00000000db000000-0x00000000df9fffff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000f8000000-0x00000000fbffffff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000fec00000-0x00000000fec00fff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000fed08000-0x00000000fed08fff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000fed10000-0x00000000fed19fff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000fed1c000-0x00000000fed1ffff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000fee00000-0x00000000fee00fff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000ffd80000-0x00000000ffffffff] reserved
[    0.000000] BIOS-e820: [mem 0x0000000100000000-0x000000011fdfffff] usable
[    0.000000] NX (Execute Disable) protection: active
[    0.000000] SMBIOS 2.6 present.
[    0.000000] DMI: SAMSUNG ELECTRONICS CO., LTD. 530U3BI/530U4BI/530U4BH/530U3BI/530U4BI/530U4BH, BIOS 13XK 03/28/2013
[    0.000000] e820: update [mem 0x00000000-0x00000fff] usable ==> reserved
[    0.000000] e820: remove [mem 0x000a0000-0x000fffff] usable
[    0.000000] e820: last_pfn = 0x11fe00 max_arch_pfn = 0x400000000
[    0.000000] MTRR default type: uncachable
[    0.000000] MTRR fixed ranges enabled:
[    0.000000]   00000-9FFFF write-back
[    0.000000]   A0000-BFFFF uncachable
[    0.000000]   C0000-FFFFF write-protect
[    0.000000] MTRR variable ranges enabled:
[    0.000000]   0 base 000000000 mask F80000000 write-back
[    0.000000]   1 base 080000000 mask FC0000000 write-back
[    0.000000]   2 base 0C0000000 mask FE0000000 write-back
[    0.000000]   3 base 0DC000000 mask FFC000000 uncachable
[    0.000000]   4 base 0DB000000 mask FFF000000 uncachable
[    0.000000]   5 base 100000000 mask FE0000000 write-back
[    0.000000]   6 base 11FE00000 mask FFFE00000 uncachable
[    0.000000]   7 base 0FFC00000 mask FFFC00000 write-protect
[    0.000000]   8 disabled
[    0.000000]   9 disabled
[    0.000000] x86/PAT: Configuration [0-7]: WB  WC  UC- UC  WB  WC  UC- WT  
[    0.000000] e820: last_pfn = 0xdb000 max_arch_pfn = 0x400000000
[    0.000000] found SMP MP-table at [mem 0x000f00e0-0x000f00ef] mapped at [ffff8800000f00e0]
[    0.000000] Scanning 1 areas for low memory corruption
[    0.000000] Base memory trampoline at [ffff880000097000] 97000 size 24576
[    0.000000] reserving inaccessible SNB gfx pages
[    0.000000] BRK [0x02e9b000, 0x02e9bfff] PGTABLE
[    0.000000] BRK [0x02e9c000, 0x02e9cfff] PGTABLE
[    0.000000] BRK [0x02e9d000, 0x02e9dfff] PGTABLE
[    0.000000] BRK [0x02e9e000, 0x02e9efff] PGTABLE
[    0.000000] BRK [0x02e9f000, 0x02e9ffff] PGTABLE
[    0.000000] BRK [0x02ea0000, 0x02ea0fff] PGTABLE
[    0.000000] RAMDISK: [mem 0x378f6000-0x37c72fff]
[    0.000000] ACPI: Early table checksum verification disabled
[    0.000000] ACPI: RSDP 0x00000000000F0100 000024 (v02 SECCSD)
[    0.000000] ACPI: XSDT 0x00000000DAFFE170 00008C (v01 SECCSD LH43STAR 00000002 PTEC 00000002)
[    0.000000] ACPI: FACP 0x00000000DAFEF000 00010C (v05 SECCSD LH43STAR 00000002 PTL  00000002)
[    0.000000] ACPI: DSDT 0x00000000DAFF2000 0083AC (v02 SECCSD SNB-CPT  00000000 INTL 20061109)
[    0.000000] ACPI: FACS 0x00000000DAF47000 000040
[    0.000000] ACPI: SLIC 0x00000000DAFFD000 000176 (v01 SECCSD LH43STAR 00000002 PTEC 00000001)
[    0.000000] ACPI: SSDT 0x00000000DAFFB000 001068 (v01 SECCSD PtidDevc 00001000 INTL 20061109)
[    0.000000] ACPI: ASF! 0x00000000DAFF1000 0000A5 (v32 SECCSD LH43STAR 00000002 PTL  00000002)
[    0.000000] ACPI: HPET 0x00000000DAFEE000 000038 (v01 SECCSD LH43STAR 00000002 PTL  00000002)
[    0.000000] ACPI: APIC 0x00000000DAFED000 000098 (v03 SECCSD LH43STAR 00000002 PTL  00000002)
[    0.000000] ACPI: MCFG 0x00000000DAFEC000 00003C (v01 SECCSD LH43STAR 00000002 PTL  00000002)
[    0.000000] ACPI: SSDT 0x00000000DAFEB000 000804 (v01 PmRef  Cpu0Ist  00003000 INTL 20061109)
[    0.000000] ACPI: SSDT 0x00000000DAFEA000 000996 (v01 PmRef  CpuPm    00003000 INTL 20061109)
[    0.000000] ACPI: UEFI 0x00000000DAFE9000 00003E (v01 SECCSD LH43STAR 00000002 PTL  00000002)
[    0.000000] ACPI: UEFI 0x00000000DAFE8000 000042 (v01 PTL    COMBUF   00000001 PTL  00000001)
[    0.000000] ACPI: UEFI 0x00000000DAFE7000 00026A (v01 SECCSD LH43STAR 00000002 PTL  00000002)
[    0.000000] ACPI: SSDT 0x00000000DAFE6000 0000D0 (v01 Iffs   IffsAsl  00003000 INTL 20061109)
[    0.000000] ACPI: Local APIC address 0xfee00000
[    0.000000] No NUMA configuration found
[    0.000000] Faking a node at [mem 0x0000000000000000-0x000000011fdfffff]
[    0.000000] NODE_DATA(0) allocated [mem 0x11fdf8000-0x11fdfcfff]
[    0.000000] Zone ranges:
[    0.000000]   DMA      [mem 0x0000000000001000-0x0000000000ffffff]
[    0.000000]   DMA32    [mem 0x0000000001000000-0x00000000ffffffff]
[    0.000000]   Normal   [mem 0x0000000100000000-0x000000011fdfffff]
[    0.000000] Movable zone start for each node
[    0.000000] Early memory node ranges
[    0.000000]   node   0: [mem 0x0000000000001000-0x000000000009cfff]
[    0.000000]   node   0: [mem 0x0000000000100000-0x000000001fffffff]
[    0.000000]   node   0: [mem 0x0000000020200000-0x000000003fffffff]
[    0.000000]   node   0: [mem 0x0000000040200000-0x00000000d9c9efff]
[    0.000000]   node   0: [mem 0x00000000dafff000-0x00000000daffffff]
[    0.000000]   node   0: [mem 0x0000000100000000-0x000000011fdfffff]
[    0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x000000011fdfffff]
[    0.000000] On node 0 totalpages: 1021500
[    0.000000]   DMA zone: 64 pages used for memmap
[    0.000000]   DMA zone: 156 pages reserved
[    0.000000]   DMA zone: 3996 pages, LIFO batch:0
[    0.000000]   DMA32 zone: 13859 pages used for memmap
[    0.000000]   DMA32 zone: 886944 pages, LIFO batch:31
[    0.000000]   Normal zone: 2040 pages used for memmap
[    0.000000]   Normal zone: 130560 pages, LIFO batch:31
[    0.000000] Reserving Intel graphics stolen memory at 0xdba00000-0xdf9fffff
[    0.000000] ACPI: PM-Timer IO Port: 0x408
[    0.000000] ACPI: Local APIC address 0xfee00000
[    0.000000] ACPI: LAPIC_NMI (acpi_id[0x00] high edge lint[0x1])
[    0.000000] ACPI: LAPIC_NMI (acpi_id[0x01] high edge lint[0x1])
[    0.000000] IOAPIC[0]: apic_id 14, version 32, address 0xfec00000, GSI 0-23
[    0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl)
[    0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level)
[    0.000000] ACPI: IRQ0 used by override.
[    0.000000] ACPI: IRQ9 used by override.
[    0.000000] Using ACPI (MADT) for SMP configuration information
[    0.000000] ACPI: HPET id: 0x8086a301 base: 0xfed00000
[    0.000000] smpboot: Allowing 8 CPUs, 4 hotplug CPUs
[    0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff]
[    0.000000] PM: Registered nosave memory: [mem 0x0009d000-0x0009dfff]
[    0.000000] PM: Registered nosave memory: [mem 0x0009e000-0x0009ffff]
[    0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000dffff]
[    0.000000] PM: Registered nosave memory: [mem 0x000e0000-0x000fffff]
[    0.000000] PM: Registered nosave memory: [mem 0x20000000-0x201fffff]
[    0.000000] PM: Registered nosave memory: [mem 0x40000000-0x401fffff]
[    0.000000] PM: Registered nosave memory: [mem 0xd9c9f000-0xdae7efff]
[    0.000000] PM: Registered nosave memory: [mem 0xdae7f000-0xdaf9efff]
[    0.000000] PM: Registered nosave memory: [mem 0xdaf9f000-0xdaffefff]
[    0.000000] PM: Registered nosave memory: [mem 0xdb000000-0xdf9fffff]
[    0.000000] PM: Registered nosave memory: [mem 0xdfa00000-0xf7ffffff]
[    0.000000] PM: Registered nosave memory: [mem 0xf8000000-0xfbffffff]
[    0.000000] PM: Registered nosave memory: [mem 0xfc000000-0xfebfffff]
[    0.000000] PM: Registered nosave memory: [mem 0xfec00000-0xfec00fff]
[    0.000000] PM: Registered nosave memory: [mem 0xfec01000-0xfed07fff]
[    0.000000] PM: Registered nosave memory: [mem 0xfed08000-0xfed08fff]
[    0.000000] PM: Registered nosave memory: [mem 0xfed09000-0xfed0ffff]
[    0.000000] PM: Registered nosave memory: [mem 0xfed10000-0xfed19fff]
[    0.000000] PM: Registered nosave memory: [mem 0xfed1a000-0xfed1bfff]
[    0.000000] PM: Registered nosave memory: [mem 0xfed1c000-0xfed1ffff]
[    0.000000] PM: Registered nosave memory: [mem 0xfed20000-0xfedfffff]
[    0.000000] PM: Registered nosave memory: [mem 0xfee00000-0xfee00fff]
[    0.000000] PM: Registered nosave memory: [mem 0xfee01000-0xffd7ffff]
[    0.000000] PM: Registered nosave memory: [mem 0xffd80000-0xffffffff]
[    0.000000] e820: [mem 0xdfa00000-0xf7ffffff] available for PCI devices
[    0.000000] Booting paravirtualized kernel on bare hardware
[    0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645519600211568 ns
[    0.000000] setup_percpu: NR_CPUS:256 nr_cpumask_bits:256 nr_cpu_ids:8 nr_node_ids:1
[    0.000000] percpu: Embedded 34 pages/cpu @ffff88011fa00000 s102280 r8192 d28792 u262144
[    0.000000] pcpu-alloc: s102280 r8192 d28792 u262144 alloc=1*2097152
[    0.000000] pcpu-alloc: [0] 0 1 2 3 4 5 6 7 
[    0.000000] Built 1 zonelists in Node order, mobility grouping on.  Total pages: 1005381
[    0.000000] Policy zone: Normal
[    0.000000] Kernel command line: BOOT_IMAGE=/boot/vmlinuz-4.6.0-rc5-9-iniza-small root=UUID=001AADA61AAD9964 loop=/ubuntu/disks/root.disk ro
[    0.000000] PID hash table entries: 4096 (order: 3, 32768 bytes)
[    0.000000] Calgary: detecting Calgary via BIOS EBDA area
[    0.000000] Calgary: Unable to locate Rio Grande table in EBDA - bailing!
[    0.000000] Memory: 3916904K/4086000K available (8353K kernel code, 1433K rwdata, 3324K rodata, 1456K init, 14072K bss, 169096K reserved, 0K cma-reserved)
[    0.000000] Running RCU self tests
[    0.000000] Hierarchical RCU implementation.
[    0.000000] 	RCU lockdep checking is enabled.
[    0.000000] 	Build-time adjustment of leaf fanout to 64.
[    0.000000] 	RCU restricting CPUs from NR_CPUS=256 to nr_cpu_ids=8.
[    0.000000] RCU: Adjusting geometry for rcu_fanout_leaf=64, nr_cpu_ids=8
[    0.000000] NR_IRQS:16640 nr_irqs:488 16
[    0.000000] Console: colour dummy device 80x25
[    0.000000] console [tty0] enabled
[    0.000000] Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo Molnar
[    0.000000] ... MAX_LOCKDEP_SUBCLASSES:  8
[    0.000000] ... MAX_LOCK_DEPTH:          48
[    0.000000] ... MAX_LOCKDEP_KEYS:        8191
[    0.000000] ... CLASSHASH_SIZE:          4096
[    0.000000] ... MAX_LOCKDEP_ENTRIES:     32768
[    0.000000] ... MAX_LOCKDEP_CHAINS:      65536
[    0.000000] ... CHAINHASH_SIZE:          32768
[    0.000000]  memory used by lock dependency info: 8159 kB
[    0.000000]  per task-struct memory footprint: 1920 bytes
[    0.000000] ------------------------
[    0.000000] | Locking API testsuite:
[    0.000000] ----------------------------------------------------------------------------
[    0.000000]                                  | spin |wlock |rlock |mutex | wsem | rsem |
[    0.000000]   --------------------------------------------------------------------------
[    0.000000]                      A-A deadlock:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.000000]                  A-B-B-A deadlock:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.000000]              A-B-B-C-C-A deadlock:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.000000]              A-B-C-A-B-C deadlock:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.000000]          A-B-B-C-C-D-D-A deadlock:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.000000]          A-B-C-D-B-D-D-A deadlock:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.000000]          A-B-C-D-B-C-D-A deadlock:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.000000]                     double unlock:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.000000]                   initialize held:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.000000]                  bad unlock order:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.000000]   --------------------------------------------------------------------------
[    0.000000]               recursive read-lock:             |  ok  |             |  ok  |
[    0.000000]            recursive read-lock #2:             |  ok  |             |  ok  |
[    0.000000]             mixed read-write-lock:             |  ok  |             |  ok  |
[    0.000000]             mixed write-read-lock:             |  ok  |             |  ok  |
[    0.000000]   --------------------------------------------------------------------------
[    0.000000]      hard-irqs-on + irq-safe-A/12:  ok  |  ok  |  ok  |
[    0.000000]      soft-irqs-on + irq-safe-A/12:  ok  |  ok  |  ok  |
[    0.000000]      hard-irqs-on + irq-safe-A/21:  ok  |  ok  |  ok  |
[    0.000000]      soft-irqs-on + irq-safe-A/21:  ok  |  ok  |  ok  |
[    0.000000]        sirq-safe-A => hirqs-on/12:  ok  |  ok  |  ok  |
[    0.000000]        sirq-safe-A => hirqs-on/21:  ok  |  ok  |  ok  |
[    0.000000]          hard-safe-A + irqs-on/12:  ok  |  ok  |  ok  |
[    0.000000]          soft-safe-A + irqs-on/12:  ok  |  ok  |  ok  |
[    0.000000]          hard-safe-A + irqs-on/21:  ok  |  ok  |  ok  |
[    0.000000]          soft-safe-A + irqs-on/21:  ok  |  ok  |  ok  |
[    0.000000]     hard-safe-A + unsafe-B #1/123:  ok  |  ok  |  ok  |
[    0.000000]     soft-safe-A + unsafe-B #1/123:  ok  |  ok  |  ok  |
[    0.000000]     hard-safe-A + unsafe-B #1/132:  ok  |  ok  |  ok  |
[    0.000000]     soft-safe-A + unsafe-B #1/132:  ok  |  ok  |  ok  |
[    0.000000]     hard-safe-A + unsafe-B #1/213:  ok  |  ok  |  ok  |
[    0.000000]     soft-safe-A + unsafe-B #1/213:  ok  |  ok  |  ok  |
[    0.000000]     hard-safe-A + unsafe-B #1/231:  ok  |  ok  |  ok  |
[    0.000000]     soft-safe-A + unsafe-B #1/231:  ok  |  ok  |  ok  |
[    0.000000]     hard-safe-A + unsafe-B #1/312:  ok  |  ok  |  ok  |
[    0.000000]     soft-safe-A + unsafe-B #1/312:  ok  |  ok  |  ok  |
[    0.000000]     hard-safe-A + unsafe-B #1/321:  ok  |  ok  |  ok  |
[    0.000000]     soft-safe-A + unsafe-B #1/321:  ok  |  ok  |  ok  |
[    0.000000]     hard-safe-A + unsafe-B #2/123:  ok  |  ok  |  ok  |
[    0.000000]     soft-safe-A + unsafe-B #2/123:  ok  |  ok  |  ok  |
[    0.000000]     hard-safe-A + unsafe-B #2/132:  ok  |  ok  |  ok  |
[    0.000000]     soft-safe-A + unsafe-B #2/132:  ok  |  ok  |  ok  |
[    0.000000]     hard-safe-A + unsafe-B #2/213:  ok  |  ok  |  ok  |
[    0.000000]     soft-safe-A + unsafe-B #2/213:  ok  |  ok  |  ok  |
[    0.000000]     hard-safe-A + unsafe-B #2/231:  ok  |  ok  |  ok  |
[    0.000000]     soft-safe-A + unsafe-B #2/231:  ok  |  ok  |  ok  |
[    0.000000]     hard-safe-A + unsafe-B #2/312:  ok  |  ok  |  ok  |
[    0.000000]     soft-safe-A + unsafe-B #2/312:  ok  |  ok  |  ok  |
[    0.000000]     hard-safe-A + unsafe-B #2/321:  ok  |  ok  |  ok  |
[    0.000000]     soft-safe-A + unsafe-B #2/321:  ok  |  ok  |  ok  |
[    0.000000]       hard-irq lock-inversion/123:  ok  |  ok  |  ok  |
[    0.000000]       soft-irq lock-inversion/123:  ok  |  ok  |  ok  |
[    0.000000]       hard-irq lock-inversion/132:  ok  |  ok  |  ok  |
[    0.000000]       soft-irq lock-inversion/132:  ok  |  ok  |  ok  |
[    0.000000]       hard-irq lock-inversion/213:  ok  |  ok  |  ok  |
[    0.000000]       soft-irq lock-inversion/213:  ok  |  ok  |  ok  |
[    0.000000]       hard-irq lock-inversion/231:  ok  |  ok  |  ok  |
[    0.000000]       soft-irq lock-inversion/231:  ok  |  ok  |  ok  |
[    0.000000]       hard-irq lock-inversion/312:  ok  |  ok  |  ok  |
[    0.000000]       soft-irq lock-inversion/312:  ok  |  ok  |  ok  |
[    0.000000]       hard-irq lock-inversion/321:  ok  |  ok  |  ok  |
[    0.000000]       soft-irq lock-inversion/321:  ok  |  ok  |  ok  |
[    0.000000]       hard-irq read-recursion/123:  ok  |
[    0.000000]       soft-irq read-recursion/123:  ok  |
[    0.000000]       hard-irq read-recursion/132:  ok  |
[    0.000000]       soft-irq read-recursion/132:  ok  |
[    0.000000]       hard-irq read-recursion/213:  ok  |
[    0.000000]       soft-irq read-recursion/213:  ok  |
[    0.000000]       hard-irq read-recursion/231:  ok  |
[    0.000000]       soft-irq read-recursion/231:  ok  |
[    0.000000]       hard-irq read-recursion/312:  ok  |
[    0.000000]       soft-irq read-recursion/312:  ok  |
[    0.000000]       hard-irq read-recursion/321:  ok  |
[    0.000000]       soft-irq read-recursion/321:  ok  |
[    0.000000]   --------------------------------------------------------------------------
[    0.000000]   | Wound/wait tests |
[    0.000000]   ---------------------
[    0.000000]                   ww api failures:  ok  |  ok  |  ok  |
[    0.000000]                ww contexts mixing:  ok  |  ok  |
[    0.000000]              finishing ww context:  ok  |  ok  |  ok  |  ok  |
[    0.000000]                locking mismatches:  ok  |  ok  |  ok  |
[    0.000000]                  EDEADLK handling:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.000000]            spinlock nest unlocked:  ok  |
[    0.000000]   -----------------------------------------------------
[    0.000000]                                  |block | try  |context|
[    0.000000]   -----------------------------------------------------
[    0.000000]                           context:  ok  |  ok  |  ok  |
[    0.000000]                               try:  ok  |  ok  |  ok  |
[    0.000000]                             block:  ok  |  ok  |  ok  |
[    0.000000]                          spinlock:  ok  |  ok  |  ok  |
[    0.000000] -------------------------------------------------------
[    0.000000] Good, all 253 testcases passed! |
[    0.000000] ---------------------------------
[    0.000000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 133484882848 ns
[    0.000000] hpet clockevent registered
[    0.000000] tsc: Fast TSC calibration using PIT
[    0.000000] tsc: Detected 1596.337 MHz processor
[    0.000095] Calibrating delay loop (skipped), value calculated using timer frequency.. 3192.67 BogoMIPS (lpj=6385348)
[    0.000108] pid_max: default: 32768 minimum: 301
[    0.000149] ACPI: Core revision 20160318
[    0.000440] Security Framework initialized
[    0.000447] Yama: becoming mindful.
[    0.000480] AppArmor: AppArmor initialized
[    0.000949] Dentry cache hash table entries: 524288 (order: 10, 4194304 bytes)
[    0.002050] Inode-cache hash table entries: 262144 (order: 9, 2097152 bytes)
[    0.002531] Mount-cache hash table entries: 8192 (order: 4, 65536 bytes)
[    0.002547] Mountpoint-cache hash table entries: 8192 (order: 4, 65536 bytes)
[    0.003906] Disabled fast string operations
[    0.003916] CPU: Physical Processor ID: 0
[    0.003922] CPU: Processor Core ID: 0
[    0.003931] ENERGY_PERF_BIAS: Set to 'normal', was 'performance'
[    0.003937] ENERGY_PERF_BIAS: View and update with x86_energy_perf_policy(8)
[    0.003945] mce: CPU supports 7 MCE banks
[    0.003981] CPU0: Thermal monitoring enabled (TM1)
[    0.004001] process: using mwait in idle threads
[    0.004010] Last level iTLB entries: 4KB 512, 2MB 8, 4MB 8
[    0.004016] Last level dTLB entries: 4KB 512, 2MB 32, 4MB 32, 1GB 0
[    0.004682] Freeing SMP alternatives memory: 28K (ffffffff820d4000 - ffffffff820db000)
[    0.018167] ftrace: allocating 30204 entries in 118 pages
[    0.035399] smpboot: Max logical packages: 4
[    0.035409] smpboot: APIC(0) Converting physical 0 to logical package 0
[    0.035497] x2apic: IRQ remapping doesn't support X2APIC mode
[    0.036121] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1
[    0.075819] TSC deadline timer enabled
[    0.075825] smpboot: CPU0: Intel(R) Core(TM) i5-2467M CPU @ 1.60GHz (family: 0x6, model: 0x2a, stepping: 0x7)
[    0.075851] Performance Events: PEBS fmt1+, 16-deep LBR, SandyBridge events, full-width counters, Intel PMU driver.
[    0.075895] ... version:                3
[    0.075900] ... bit width:              48
[    0.075905] ... generic registers:      4
[    0.075910] ... value mask:             0000ffffffffffff
[    0.075916] ... max period:             0000ffffffffffff
[    0.075921] ... fixed-purpose events:   3
[    0.075926] ... event mask:             000000070000000f
[    0.077731] NMI watchdog: enabled on all CPUs, permanently consumes one hw-PMU counter.
[    0.078616] x86: Booting SMP configuration:
[    0.078624] .... node  #0, CPUs:      #1
[    0.078966] Disabled fast string operations
[    0.158892]  #2<6>[    0.159202] Disabled fast string operations
[    0.239242]  #3
[    0.239242] Disabled fast string operations
[    0.318499] x86: Booted up 1 node, 4 CPUs
[    0.318517] smpboot: Total of 4 processors activated (12786.53 BogoMIPS)
[    0.323505] devtmpfs: initialized
[    0.323860] x86/mm: Memory block size: 128MB
[    0.328908] evm: security.selinux
[    0.328915] evm: security.SMACK64
[    0.328920] evm: security.capability
[    0.329109] PM: Registering ACPI NVS region [mem 0xdae7f000-0xdaf9efff] (1179648 bytes)
[    0.329535] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns
[    0.331142] NET: Registered protocol family 16
[    0.342454] cpuidle: using governor ladder
[    0.358405] cpuidle: using governor menu
[    0.358628] ACPI: bus type PCI registered
[    0.358995] PCI: MMCONFIG for domain 0000 [bus 00-3f] at [mem 0xf8000000-0xfbffffff] (base 0xf8000000)
[    0.359007] PCI: MMCONFIG at [mem 0xf8000000-0xfbffffff] reserved in E820
[    0.359023] PCI: Using configuration type 1 for base access
[    0.359077] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on
[    0.374946] HugeTLB registered 2 MB page size, pre-allocated 0 pages
[    0.376335] ACPI: Added _OSI(Module Device)
[    0.376344] ACPI: Added _OSI(Processor Device)
[    0.376350] ACPI: Added _OSI(3.0 _SCP Extensions)
[    0.376356] ACPI: Added _OSI(Processor Aggregator Device)
[    0.393441] ACPI: Executed 1 blocks of module-level executable AML code
[    0.402279] ACPI: 5 ACPI AML tables successfully acquired and loaded
[    0.402287] 
[    0.420558] [Firmware Bug]: ACPI: BIOS _OSI(Linux) query ignored
[    0.422664] ACPI: Dynamic OEM Table Load:
[    0.422694] ACPI: SSDT 0xFFFF88011A05D000 000688 (v01 PmRef  Cpu0Cst  00003001 INTL 20061109)
[    0.425351] ACPI: Dynamic OEM Table Load:
[    0.425378] ACPI: SSDT 0xFFFF88011A057000 000303 (v01 PmRef  ApIst    00003000 INTL 20061109)
[    0.427837] ACPI: Dynamic OEM Table Load:
[    0.427864] ACPI: SSDT 0xFFFF88011A7D2A00 000119 (v01 PmRef  ApCst    00003000 INTL 20061109)
[    0.431997] ACPI: Interpreter enabled
[    0.432072] ACPI: (supports S0 S1 S3 S4 S5)
[    0.432078] ACPI: Using IOAPIC for interrupt routing
[    0.432167] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug
[    0.458652] ACPI: Power Resource [FN00] (off)
[    0.459159] ACPI: Power Resource [FN01] (off)
[    0.459561] ACPI: Power Resource [FN02] (off)
[    0.459960] ACPI: Power Resource [FN03] (off)
[    0.460361] ACPI: Power Resource [FN04] (off)
[    0.463189] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-3e])
[    0.463204] acpi PNP0A08:00: _OSC: OS supports [ExtendedConfig ASPM ClockPM Segments MSI]
[    0.463996] \_SB_.PCI0 (33DB4D5B-1FF7-401C-9657-7441C03DD766): _OSC invalid UUID
[    0.463999] _OSC request data: 1 1f 0
[    0.464005] acpi PNP0A08:00: _OSC failed (AE_ERROR); disabling ASPM
[    0.465097] PCI host bridge to bus 0000:00
[    0.465106] pci_bus 0000:00: root bus resource [io  0x0000-0x0cf7 window]
[    0.465114] pci_bus 0000:00: root bus resource [io  0x0d00-0xffff window]
[    0.465121] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window]
[    0.465131] pci_bus 0000:00: root bus resource [mem 0xdfa00000-0xfeafffff window]
[    0.465141] pci_bus 0000:00: root bus resource [mem 0xfed40000-0xfed44fff window]
[    0.465151] pci_bus 0000:00: root bus resource [bus 00-3e]
[    0.465238] pci 0000:00:00.0: [8086:0104] type 00 class 0x060000
[    0.465697] pci 0000:00:02.0: [8086:0116] type 00 class 0x030000
[    0.465717] pci 0000:00:02.0: reg 0x10: [mem 0xf0000000-0xf03fffff 64bit]
[    0.465730] pci 0000:00:02.0: reg 0x18: [mem 0xe0000000-0xefffffff 64bit pref]
[    0.465739] pci 0000:00:02.0: reg 0x20: [io  0x3000-0x303f]
[    0.466235] pci 0000:00:16.0: [8086:1c3a] type 00 class 0x078000
[    0.466276] pci 0000:00:16.0: reg 0x10: [mem 0xf0705000-0xf070500f 64bit]
[    0.466429] pci 0000:00:16.0: PME# supported from D0 D3hot D3cold
[    0.466843] pci 0000:00:1a.0: [8086:1c2d] type 00 class 0x0c0320
[    0.466878] pci 0000:00:1a.0: reg 0x10: [mem 0xf070a000-0xf070a3ff]
[    0.467052] pci 0000:00:1a.0: PME# supported from D0 D3hot D3cold
[    0.467416] pci 0000:00:1b.0: [8086:1c20] type 00 class 0x040300
[    0.467454] pci 0000:00:1b.0: reg 0x10: [mem 0xf0700000-0xf0703fff 64bit]
[    0.467632] pci 0000:00:1b.0: PME# supported from D0 D3hot D3cold
[    0.467853] pci 0000:00:1b.0: System wakeup disabled by ACPI
[    0.468042] pci 0000:00:1c.0: [8086:1c10] type 01 class 0x060400
[    0.468212] pci 0000:00:1c.0: PME# supported from D0 D3hot D3cold
[    0.468408] pci 0000:00:1c.0: System wakeup disabled by ACPI
[    0.468600] pci 0000:00:1c.3: [8086:1c16] type 01 class 0x060400
[    0.468770] pci 0000:00:1c.3: PME# supported from D0 D3hot D3cold
[    0.468967] pci 0000:00:1c.3: System wakeup disabled by ACPI
[    0.469154] pci 0000:00:1c.4: [8086:1c18] type 01 class 0x060400
[    0.469331] pci 0000:00:1c.4: PME# supported from D0 D3hot D3cold
[    0.469716] pci 0000:00:1d.0: [8086:1c26] type 00 class 0x0c0320
[    0.469751] pci 0000:00:1d.0: reg 0x10: [mem 0xf0709000-0xf07093ff]
[    0.469925] pci 0000:00:1d.0: PME# supported from D0 D3hot D3cold
[    0.470282] pci 0000:00:1f.0: [8086:1c49] type 00 class 0x060100
[    0.470808] pci 0000:00:1f.2: [8086:1c03] type 00 class 0x010601
[    0.470845] pci 0000:00:1f.2: reg 0x10: [io  0x3088-0x308f]
[    0.470863] pci 0000:00:1f.2: reg 0x14: [io  0x3094-0x3097]
[    0.470880] pci 0000:00:1f.2: reg 0x18: [io  0x3080-0x3087]
[    0.470898] pci 0000:00:1f.2: reg 0x1c: [io  0x3090-0x3093]
[    0.470915] pci 0000:00:1f.2: reg 0x20: [io  0x3060-0x307f]
[    0.470932] pci 0000:00:1f.2: reg 0x24: [mem 0xf0708000-0xf07087ff]
[    0.471040] pci 0000:00:1f.2: PME# supported from D3hot
[    0.471392] pci 0000:00:1f.3: [8086:1c22] type 00 class 0x0c0500
[    0.471425] pci 0000:00:1f.3: reg 0x10: [mem 0xf0704000-0xf07040ff 64bit]
[    0.471473] pci 0000:00:1f.3: reg 0x20: [io  0xefa0-0xefbf]
[    0.472217] pci 0000:01:00.0: [8086:0091] type 00 class 0x028000
[    0.472608] pci 0000:01:00.0: reg 0x10: [mem 0xf0600000-0xf0601fff 64bit]
[    0.474457] pci 0000:01:00.0: PME# supported from D0 D3hot D3cold
[    0.474895] pci 0000:01:00.0: System wakeup disabled by ACPI
[    0.482914] pci 0000:00:1c.0: PCI bridge to [bus 01]
[    0.482930] pci 0000:00:1c.0:   bridge window [mem 0xf0600000-0xf06fffff]
[    0.483159] pci 0000:02:00.0: [10ec:8168] type 00 class 0x020000
[    0.483254] pci 0000:02:00.0: reg 0x10: [io  0x2000-0x20ff]
[    0.483393] pci 0000:02:00.0: reg 0x18: [mem 0xf0404000-0xf0404fff 64bit pref]
[    0.483480] pci 0000:02:00.0: reg 0x20: [mem 0xf0400000-0xf0403fff 64bit pref]
[    0.483949] pci 0000:02:00.0: supports D1 D2
[    0.483951] pci 0000:02:00.0: PME# supported from D0 D1 D2 D3hot D3cold
[    0.484160] pci 0000:02:00.0: System wakeup disabled by ACPI
[    0.490838] pci 0000:00:1c.3: PCI bridge to [bus 02]
[    0.490850] pci 0000:00:1c.3:   bridge window [io  0x2000-0x2fff]
[    0.490865] pci 0000:00:1c.3:   bridge window [mem 0xf0400000-0xf04fffff 64bit pref]
[    0.491066] pci 0000:03:00.0: [1b21:1042] type 00 class 0x0c0330
[    0.491117] pci 0000:03:00.0: reg 0x10: [mem 0xf0500000-0xf0507fff 64bit]
[    0.491400] pci 0000:03:00.0: PME# supported from D3hot D3cold
[    0.491732] pci 0000:00:1c.4: PCI bridge to [bus 03]
[    0.491748] pci 0000:00:1c.4:   bridge window [mem 0xf0500000-0xf05fffff]
[    0.494723] ACPI: PCI Interrupt Link [LNKA] (IRQs 1 3 4 5 6 10 *11 12 14 15)
[    0.494957] ACPI: PCI Interrupt Link [LNKB] (IRQs 1 3 4 5 6 10 11 12 14 15) *0, disabled.
[    0.495182] ACPI: PCI Interrupt Link [LNKC] (IRQs 1 3 4 5 6 *10 11 12 14 15)
[    0.495401] ACPI: PCI Interrupt Link [LNKD] (IRQs 1 3 4 5 6 *10 11 12 14 15)
[    0.495619] ACPI: PCI Interrupt Link [LNKE] (IRQs 1 3 4 5 6 10 11 12 14 15) *9
[    0.495838] ACPI: PCI Interrupt Link [LNKF] (IRQs 1 3 4 5 6 10 11 12 14 15) *0, disabled.
[    0.496071] ACPI: PCI Interrupt Link [LNKG] (IRQs 1 3 4 5 6 10 *11 12 14 15)
[    0.496289] ACPI: PCI Interrupt Link [LNKH] (IRQs 1 3 4 5 6 10 11 12 14 15) *9
[    0.497634] ACPI: Enabled 4 GPEs in block 00 to 3F
[    0.497845] ACPI : EC: GPE = 0x17, I/O: command/status = 0x66, data = 0x62
[    0.497863] ACPI : EC: EC started
[    0.535559] ACPI : EC: 0 stale EC events cleared
[    0.536348] vgaarb: setting as boot device: PCI:0000:00:02.0
[    0.536356] vgaarb: device added: PCI:0000:00:02.0,decodes=io+mem,owns=io+mem,locks=none
[    0.536374] vgaarb: loaded
[    0.536379] vgaarb: bridge control possible 0000:00:02.0
[    0.537195] SCSI subsystem initialized
[    0.537384] libata version 3.00 loaded.
[    0.537497] ACPI: bus type USB registered
[    0.537583] usbcore: registered new interface driver usbfs
[    0.537632] usbcore: registered new interface driver hub
[    0.537723] usbcore: registered new device driver usb
[    0.538246] PCI: Using ACPI for IRQ routing
[    0.541964] PCI: pci_cache_line_size set to 64 bytes
[    0.542100] e820: reserve RAM buffer [mem 0x0009d800-0x0009ffff]
[    0.542109] e820: reserve RAM buffer [mem 0xd9c9f000-0xdbffffff]
[    0.542112] e820: reserve RAM buffer [mem 0xdb000000-0xdbffffff]
[    0.542115] e820: reserve RAM buffer [mem 0x11fe00000-0x11fffffff]
[    0.542975] NetLabel: Initializing
[    0.542982] NetLabel:  domain hash size = 128
[    0.542987] NetLabel:  protocols = UNLABELED CIPSOv4
[    0.543049] NetLabel:  unlabeled traffic allowed by default
[    0.543392] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0, 0, 0, 0, 0, 0
[    0.543407] hpet0: 8 comparators, 64-bit 14.318180 MHz counter
[    0.546507] clocksource: Switched to clocksource hpet
[    0.595361] VFS: Disk quotas dquot_6.6.0
[    0.595418] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
[    0.596038] AppArmor: AppArmor Filesystem Enabled
[    0.596301] pnp: PnP ACPI init
[    0.597030] system 00:00: [io  0x0680-0x069f] has been reserved
[    0.597040] system 00:00: [io  0x1000-0x100f] has been reserved
[    0.597048] system 00:00: [io  0x5000-0x5003] has been reserved
[    0.597056] system 00:00: [io  0xffff] has been reserved
[    0.597065] system 00:00: [io  0x0400-0x0453] could not be reserved
[    0.597073] system 00:00: [io  0x0458-0x047f] has been reserved
[    0.597081] system 00:00: [io  0x0500-0x057f] has been reserved
[    0.597089] system 00:00: [io  0x0a00-0x0a0f] has been reserved
[    0.597096] system 00:00: [io  0x164e-0x164f] has been reserved
[    0.597105] system 00:00: [io  0x5000-0x500f] could not be reserved
[    0.597145] system 00:00: Plug and Play ACPI device, IDs PNP0c02 (active)
[    0.597255] pnp 00:01: Plug and Play ACPI device, IDs PNP0b00 (active)
[    0.597461] system 00:02: [io  0x0454-0x0457] has been reserved
[    0.597475] system 00:02: Plug and Play ACPI device, IDs INT3f0d PNP0c02 (active)
[    0.597598] pnp 00:03: Plug and Play ACPI device, IDs PNP0303 (active)
[    0.597755] pnp 00:04: Plug and Play ACPI device, IDs ETD0b00 SYN0002 PNP0f13 (active)
[    0.598304] system 00:05: [mem 0xfed1c000-0xfed1ffff] has been reserved
[    0.598314] system 00:05: [mem 0xfed10000-0xfed17fff] has been reserved
[    0.598323] system 00:05: [mem 0xfed18000-0xfed18fff] has been reserved
[    0.598331] system 00:05: [mem 0xfed19000-0xfed19fff] has been reserved
[    0.598339] system 00:05: [mem 0xf8000000-0xfbffffff] has been reserved
[    0.598348] system 00:05: [mem 0xfed20000-0xfed3ffff] has been reserved
[    0.598356] system 00:05: [mem 0xfed90000-0xfed93fff] has been reserved
[    0.598364] system 00:05: [mem 0xfed45000-0xfed8ffff] has been reserved
[    0.598373] system 00:05: [mem 0xff000000-0xffffffff] could not be reserved
[    0.598382] system 00:05: [mem 0xfee00000-0xfeefffff] could not be reserved
[    0.598395] system 00:05: Plug and Play ACPI device, IDs PNP0c02 (active)
[    0.599525] system 00:06: Plug and Play ACPI device, IDs PNP0c01 (active)
[    0.599594] pnp: PnP ACPI: found 7 devices
[    0.611998] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns
[    0.612066] pci 0000:00:1c.0: PCI bridge to [bus 01]
[    0.612080] pci 0000:00:1c.0:   bridge window [mem 0xf0600000-0xf06fffff]
[    0.612101] pci 0000:00:1c.3: PCI bridge to [bus 02]
[    0.612109] pci 0000:00:1c.3:   bridge window [io  0x2000-0x2fff]
[    0.612126] pci 0000:00:1c.3:   bridge window [mem 0xf0400000-0xf04fffff 64bit pref]
[    0.612144] pci 0000:00:1c.4: PCI bridge to [bus 03]
[    0.612157] pci 0000:00:1c.4:   bridge window [mem 0xf0500000-0xf05fffff]
[    0.612178] pci_bus 0000:00: resource 4 [io  0x0000-0x0cf7 window]
[    0.612180] pci_bus 0000:00: resource 5 [io  0x0d00-0xffff window]
[    0.612182] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window]
[    0.612184] pci_bus 0000:00: resource 7 [mem 0xdfa00000-0xfeafffff window]
[    0.612186] pci_bus 0000:00: resource 8 [mem 0xfed40000-0xfed44fff window]
[    0.612188] pci_bus 0000:01: resource 1 [mem 0xf0600000-0xf06fffff]
[    0.612191] pci_bus 0000:02: resource 0 [io  0x2000-0x2fff]
[    0.612193] pci_bus 0000:02: resource 2 [mem 0xf0400000-0xf04fffff 64bit pref]
[    0.612195] pci_bus 0000:03: resource 1 [mem 0xf0500000-0xf05fffff]
[    0.612365] NET: Registered protocol family 2
[    0.612942] TCP established hash table entries: 32768 (order: 6, 262144 bytes)
[    0.613243] TCP bind hash table entries: 32768 (order: 9, 2097152 bytes)
[    0.615729] TCP: Hash tables configured (established 32768 bind 32768)
[    0.615867] UDP hash table entries: 2048 (order: 6, 327680 bytes)
[    0.616226] UDP-Lite hash table entries: 2048 (order: 6, 327680 bytes)
[    0.616852] NET: Registered protocol family 1
[    0.616891] pci 0000:00:02.0: Video device with shadowed ROM at [mem 0x000c0000-0x000dffff]
[    0.618928] PCI: CLS 64 bytes, default 64
[    0.619204] Trying to unpack rootfs image as initramfs...
[    0.706294] Freeing initrd memory: 3572K (ffff8800378f6000 - ffff880037c73000)
[    0.706317] PCI-DMA: Using software bounce buffering for IO (SWIOTLB)
[    0.706324] software IO TLB [mem 0xd5c9f000-0xd9c9f000] (64MB) mapped at [ffff8800d5c9f000-ffff8800d9c9efff]
[    0.706645] RAPL PMU: API unit is 2^-32 Joules, 3 fixed counters, 163840 ms ovfl timer
[    0.706656] RAPL PMU: hw unit of domain pp0-core 2^-16 Joules
[    0.706661] RAPL PMU: hw unit of domain package 2^-16 Joules
[    0.706667] RAPL PMU: hw unit of domain pp1-gpu 2^-16 Joules
[    0.707014] Scanning for low memory corruption every 60 seconds
[    0.708650] futex hash table entries: 2048 (order: 6, 262144 bytes)
[    0.708871] audit: initializing netlink subsys (disabled)
[    0.708958] audit: type=2000 audit(1461653196.692:1): initialized
[    0.710595] Initialise system trusted keyring
[    0.711097] workingset: timestamp_bits=38 max_order=20 bucket_order=0
[    0.712393] fuse init (API version 7.24)
[    0.715032] Key type asymmetric registered
[    0.715059] Asymmetric key parser 'x509' registered
[    0.715125] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 250)
[    0.715299] io scheduler noop registered
[    0.715311] io scheduler deadline registered (default)
[    0.715381] io scheduler cfq registered
[    0.715389] start plist test
[    0.718038] end plist test
[    0.719469] pci_hotplug: PCI Hot Plug PCI Core version: 0.5
[    0.719500] pciehp: PCI Express Hot Plug Controller Driver version: 0.4
[    0.719775] intel_idle: MWAIT substates: 0x21120
[    0.719777] intel_idle: v0.4.1 model 0x2A
[    0.720845] intel_idle: lapic_timer_reliable_states 0xffffffff
[    0.721329] ACPI: AC Adapter [ADP1] (on-line)
[    0.721633] input: Lid Switch as /devices/LNXSYSTM:00/LNXSYBUS:00/PNP0C0D:00/input/input0
[    0.721693] ACPI: Lid Switch [LID0]
[    0.721872] input: Power Button as /devices/LNXSYSTM:00/LNXSYBUS:00/PNP0C0C:00/input/input1
[    0.721922] ACPI: Power Button [PWRB]
[    0.722103] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input2
[    0.722117] ACPI: Power Button [PWRF]
[    0.726475] thermal LNXTHERM:00: registered as thermal_zone0
[    0.726492] ACPI: Thermal Zone [TZ00] (41 C)
[    0.727446] thermal LNXTHERM:01: registered as thermal_zone1
[    0.727453] ACPI: Thermal Zone [TZ01] (30 C)
[    0.727594] GHES: HEST is not enabled!
[    0.727971] Serial: 8250/16550 driver, 32 ports, IRQ sharing enabled
[    0.736585] ACPI: Battery Slot [BAT1] (battery present)
[    0.736854] Linux agpgart interface v0.103
[    0.750288] brd: module loaded
[    0.757109] loop: module loaded
[    0.762574] ahci 0000:00:1f.2: version 3.0
[    0.763117] ahci 0000:00:1f.2: SSS flag set, parallel bus scan disabled
[    0.773373] ahci 0000:00:1f.2: AHCI 0001.0300 32 slots 6 ports 6 Gbps 0x1b impl SATA mode
[    0.773387] ahci 0000:00:1f.2: flags: 64bit ncq sntf ilck stag pm led clo pio slum part ems sxs apst 
[    0.797491] scsi host0: ahci
[    0.798183] scsi host1: ahci
[    0.798721] scsi host2: ahci
[    0.799264] scsi host3: ahci
[    0.799751] scsi host4: ahci
[    0.800206] scsi host5: ahci
[    0.800450] ata1: SATA max UDMA/133 abar m2048@0xf0708000 port 0xf0708100 irq 25
[    0.800461] ata2: SATA max UDMA/133 abar m2048@0xf0708000 port 0xf0708180 irq 25
[    0.800470] ata3: DUMMY
[    0.800476] ata4: SATA max UDMA/133 abar m2048@0xf0708000 port 0xf0708280 irq 25
[    0.800486] ata5: SATA max UDMA/133 abar m2048@0xf0708000 port 0xf0708300 irq 25
[    0.800494] ata6: DUMMY
[    0.802486] libphy: Fixed MDIO Bus: probed
[    0.803009] tun: Universal TUN/TAP device driver, 1.6
[    0.803016] tun: (C) 1999-2004 Max Krasnyansky <[email protected]>
[    0.803246] PPP generic driver version 2.4.2
[    0.803445] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[    0.803455] ehci-pci: EHCI PCI platform driver
[    0.803906] ehci-pci 0000:00:1a.0: EHCI Host Controller
[    0.804079] ehci-pci 0000:00:1a.0: new USB bus registered, assigned bus number 1
[    0.804157] ehci-pci 0000:00:1a.0: debug port 2
[    0.808134] ehci-pci 0000:00:1a.0: cache line size of 64 is not supported
[    0.808199] ehci-pci 0000:00:1a.0: irq 16, io mem 0xf070a000
[    0.818599] ehci-pci 0000:00:1a.0: USB 2.0 started, EHCI 1.00
[    0.818938] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
[    0.818945] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    0.818953] usb usb1: Product: EHCI Host Controller
[    0.818958] usb usb1: Manufacturer: Linux 4.6.0-rc5-9-iniza-small ehci_hcd
[    0.818964] usb usb1: SerialNumber: 0000:00:1a.0
[    0.819976] hub 1-0:1.0: USB hub found
[    0.820034] hub 1-0:1.0: 2 ports detected
[    0.821391] ehci-pci 0000:00:1d.0: EHCI Host Controller
[    0.821415] ehci-pci 0000:00:1d.0: new USB bus registered, assigned bus number 2
[    0.821442] ehci-pci 0000:00:1d.0: debug port 2
[    0.825347] ehci-pci 0000:00:1d.0: cache line size of 64 is not supported
[    0.825382] ehci-pci 0000:00:1d.0: irq 23, io mem 0xf0709000
[    0.834674] ehci-pci 0000:00:1d.0: USB 2.0 started, EHCI 1.00
[    0.834863] usb usb2: New USB device found, idVendor=1d6b, idProduct=0002
[    0.834870] usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    0.834879] usb usb2: Product: EHCI Host Controller
[    0.834884] usb usb2: Manufacturer: Linux 4.6.0-rc5-9-iniza-small ehci_hcd
[    0.834890] usb usb2: SerialNumber: 0000:00:1d.0
[    0.835560] hub 2-0:1.0: USB hub found
[    0.835590] hub 2-0:1.0: 2 ports detected
[    0.836117] ehci-platform: EHCI generic platform driver
[    0.836175] ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver
[    0.836199] ohci-pci: OHCI PCI platform driver
[    0.836244] ohci-platform: OHCI generic platform driver
[    0.836279] uhci_hcd: USB Universal Host Controller Interface driver
[    0.836549] xhci_hcd 0000:03:00.0: xHCI Host Controller
[    0.836579] xhci_hcd 0000:03:00.0: new USB bus registered, assigned bus number 3
[    0.841069] xhci_hcd 0000:03:00.0: hcc params 0x0200f180 hci version 0x96 quirks 0x00080000
[    0.841577] usb usb3: New USB device found, idVendor=1d6b, idProduct=0002
[    0.841584] usb usb3: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    0.841592] usb usb3: Product: xHCI Host Controller
[    0.841597] usb usb3: Manufacturer: Linux 4.6.0-rc5-9-iniza-small xhci-hcd
[    0.841603] usb usb3: SerialNumber: 0000:03:00.0
[    0.842203] hub 3-0:1.0: USB hub found
[    0.842290] hub 3-0:1.0: 2 ports detected
[    0.842798] xhci_hcd 0000:03:00.0: xHCI Host Controller
[    0.842816] xhci_hcd 0000:03:00.0: new USB bus registered, assigned bus number 4
[    0.842918] usb usb4: We don't know the algorithms for LPM for this host, disabling LPM.
[    0.843022] usb usb4: New USB device found, idVendor=1d6b, idProduct=0003
[    0.843029] usb usb4: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    0.843037] usb usb4: Product: xHCI Host Controller
[    0.843042] usb usb4: Manufacturer: Linux 4.6.0-rc5-9-iniza-small xhci-hcd
[    0.843047] usb usb4: SerialNumber: 0000:03:00.0
[    0.843695] hub 4-0:1.0: USB hub found
[    0.843741] hub 4-0:1.0: 2 ports detected
[    0.844368] i8042: PNP: PS/2 Controller [PNP0303:PS2K,PNP0f13:EPAD] at 0x60,0x64 irq 1,12
[    0.850410] serio: i8042 KBD port at 0x60,0x64 irq 1
[    0.850459] serio: i8042 AUX port at 0x60,0x64 irq 12
[    0.851419] mousedev: PS/2 mouse device common for all mice
[    0.852936] rtc_cmos 00:01: rtc core: registered rtc_cmos as rtc0
[    0.852984] rtc_cmos 00:01: alarms up to one month, y3k, 242 bytes nvram, hpet irqs
[    0.853152] device-mapper: uevent: version 1.0.3
[    0.853423] device-mapper: ioctl: 4.34.0-ioctl (2015-10-28) initialised: [email protected]
[    0.853480] intel_pstate: Intel P-state driver initializing
[    0.859215] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input3
[    0.898715] ledtrig-cpu: registered to indicate activity on CPUs
[    0.899107] NET: Registered protocol family 10
[    0.899984] NET: Registered protocol family 17
[    0.900022] Key type dns_resolver registered
[    0.900957] microcode: CPU0 sig=0x206a7, pf=0x10, revision=0x28
[    0.900992] microcode: CPU1 sig=0x206a7, pf=0x10, revision=0x28
[    0.901032] microcode: CPU2 sig=0x206a7, pf=0x10, revision=0x28
[    0.901061] microcode: CPU3 sig=0x206a7, pf=0x10, revision=0x28
[    0.901315] microcode: Microcode Update Driver: v2.01 <[email protected]>, Peter Oruba
[    0.902202] registered taskstats version 1
[    0.902223] Loading compiled-in X.509 certificates
[    0.911045] Loaded X.509 cert 'Build time autogenerated kernel key: d861534734a1854c045ffb7a95ace7fffd94d654'
[    0.915481] Key type trusted registered
[    0.924508] Key type encrypted registered
[    0.924527] AppArmor: AppArmor sha1 policy hashing enabled
[    0.924536] evm: HMAC attrs: 0x1
[    0.925601] rtc_cmos 00:01: setting system clock to 2016-04-26 06:46:37 UTC (1461653197)
[    0.925790] BIOS EDD facility v0.16 2004-Jun-25, 0 devices found
[    0.925797] EDD information not available.
[    1.106577] ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
[    1.107897] ata1.00: ATA-8: Hitachi HTS545050A7E380, GG2OA6C0, max UDMA/133
[    1.107917] ata1.00: 976773168 sectors, multi 16: LBA48 NCQ (depth 31/32), AA
[    1.109298] ata1.00: configured for UDMA/133
[    1.110392] scsi 0:0:0:0: Direct-Access     ATA      Hitachi HTS54505 A6C0 PQ: 0 ANSI: 5
[    1.130679] usb 1-1: new high-speed USB device number 2 using ehci-pci
[    1.139744] sd 0:0:0:0: [sda] 976773168 512-byte logical blocks: (500 GB/466 GiB)
[    1.139759] sd 0:0:0:0: [sda] 4096-byte physical blocks
[    1.140045] sd 0:0:0:0: [sda] Write Protect is off
[    1.140056] sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
[    1.140158] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[    1.140220] sd 0:0:0:0: Attached scsi generic sg0 type 0
[    1.146556] usb 2-1: new high-speed USB device number 2 using ehci-pci
[    1.183176]  sda: sda1 sda2 sda3
[    1.184906] sd 0:0:0:0: [sda] Attached SCSI disk
[    1.263063] usb 1-1: New USB device found, idVendor=8087, idProduct=0024
[    1.263073] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    1.264012] hub 1-1:1.0: USB hub found
[    1.264144] hub 1-1:1.0: 6 ports detected
[    1.279434] usb 2-1: New USB device found, idVendor=8087, idProduct=0024
[    1.279445] usb 2-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    1.280208] hub 2-1:1.0: USB hub found
[    1.280348] hub 2-1:1.0: 6 ports detected
[    1.451544] ata2: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
[    1.452456] ata2.00: ATA-8: SanDisk iSSD P4 16GB, SSD 9.14, max UDMA/133
[    1.452486] ata2.00: 31277232 sectors, multi 1: LBA48 
[    1.453231] ata2.00: configured for UDMA/133
[    1.453870] scsi 1:0:0:0: Direct-Access     ATA      SanDisk iSSD P4  9.14 PQ: 0 ANSI: 5
[    1.475310] sd 1:0:0:0: [sdb] 31277232 512-byte logical blocks: (16.0 GB/14.9 GiB)
[    1.475463] sd 1:0:0:0: Attached scsi generic sg1 type 0
[    1.475487] sd 1:0:0:0: [sdb] Write Protect is off
[    1.475495] sd 1:0:0:0: [sdb] Mode Sense: 00 3a 00 00
[    1.475543] sd 1:0:0:0: [sdb] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[    1.476841]  sdb: sdb1 sdb2
[    1.478016] sd 1:0:0:0: [sdb] Attached SCSI disk
[    1.538689] usb 1-1.4: new high-speed USB device number 3 using ehci-pci
[    1.554693] usb 2-1.4: new low-speed USB device number 3 using ehci-pci
[    1.653727] usb 2-1.4: New USB device found, idVendor=046d, idProduct=c00e
[    1.653738] usb 2-1.4: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[    1.653746] usb 2-1.4: Product: USB-PS/2 Optical Mouse
[    1.653751] usb 2-1.4: Manufacturer: Logitech
[    1.706803] tsc: Refined TSC clocksource calibration: 1596.374 MHz
[    1.706815] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x1702c3a922f, max_idle_ns: 440795242034 ns
[    1.726671] usb 2-1.5: new full-speed USB device number 4 using ehci-pci
[    1.782646] ata4: SATA link down (SStatus 0 SControl 300)
[    1.791615] usb 1-1.4: New USB device found, idVendor=2232, idProduct=1018
[    1.791627] usb 1-1.4: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[    1.791635] usb 1-1.4: Product: WebCam SC-13HDL11431N
[    1.791641] usb 1-1.4: Manufacturer: 123
[    1.824114] usb 2-1.5: New USB device found, idVendor=8086, idProduct=0189
[    1.824126] usb 2-1.5: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    2.090874] ata5: SATA link down (SStatus 0 SControl 300)
[    2.092706] Freeing unused kernel memory: 1456K (ffffffff81f68000 - ffffffff820d4000)
[    2.092718] Write protecting the kernel read-only data: 14336k
[    2.094207] Freeing unused kernel memory: 1872K (ffff88000182c000 - ffff880001a00000)
[    2.096748] Freeing unused kernel memory: 772K (ffff880001d3f000 - ffff880001e00000)
[    2.133531] udevd[171]: starting version 175
[    2.460775] r8169 Gigabit Ethernet driver 2.3LK-NAPI loaded
[    2.460812] r8169 0000:02:00.0: can't disable ASPM; OS doesn't have ASPM control
[    2.465543] r8169 0000:02:00.0 eth0: RTL8168evl/8111evl at 0xffffc900009a2000, e8:03:9a:36:17:a9, XID 0c900800 IRQ 31
[    2.465566] r8169 0000:02:00.0 eth0: jumbo features [frames: 9200 bytes, tx checksumming: ko]
[    2.468598] usbcore: registered new interface driver usbhid
[    2.468608] usbhid: USB HID core driver
[    2.560401] input: Logitech USB-PS/2 Optical Mouse as /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.4/2-1.4:1.0/0003:046D:C00E.0001/input/input5
[    2.561004] hid-generic 0003:046D:C00E.0001: input: USB HID v1.10 Mouse [Logitech USB-PS/2 Optical Mouse] on usb-0000:00:1d.0-1.4/input0
[    2.707045] clocksource: Switched to clocksource tsc
[    3.192471] EXT4-fs (loop0): mounted filesystem with ordered data mode. Opts: (null)
[    3.968851] random: nonblocking pool is initialized
[    4.078747] usb 1-1.2: new high-speed USB device number 4 using ehci-pci
[    4.173715] usb 1-1.2: New USB device found, idVendor=12d1, idProduct=1446
[    4.173744] usb 1-1.2: New USB device strings: Mfr=3, Product=2, SerialNumber=0
[    4.173768] usb 1-1.2: Product: HUAWEI Mobile
[    4.173788] usb 1-1.2: Manufacturer: HUAWEI Technology
[    5.233759] init: ureadahead main process (447) terminated with status 5
[    9.520995] Adding 262140k swap on /host/ubuntu/disks/swap.disk.  Priority:-1 extents:1 across:262140k FS
[    9.802737] EXT4-fs (loop0): re-mounted. Opts: errors=remount-ro
[    9.958344] udevd[673]: starting version 175
[   11.301775] lp: driver loaded but no devices found
[   13.234998] wmi: Mapper loaded
[   13.486741] ACPI Warning: SystemIO range 0x0000000000000428-0x000000000000042F conflicts with OpRegion 0x0000000000000400-0x000000000000047F (\PMIO) (20160318/utaddress-255)
[   13.486755] ACPI: If an ACPI driver is available for this device, you should use it instead of the native driver
[   13.486764] ACPI Warning: SystemIO range 0x0000000000000540-0x000000000000054F conflicts with OpRegion 0x0000000000000500-0x0000000000000563 (\GPIO) (20160318/utaddress-255)
[   13.486772] ACPI: If an ACPI driver is available for this device, you should use it instead of the native driver
[   13.486777] ACPI Warning: SystemIO range 0x0000000000000530-0x000000000000053F conflicts with OpRegion 0x0000000000000500-0x0000000000000563 (\GPIO) (20160318/utaddress-255)
[   13.486785] ACPI: If an ACPI driver is available for this device, you should use it instead of the native driver
[   13.486789] ACPI Warning: SystemIO range 0x0000000000000500-0x000000000000052F conflicts with OpRegion 0x0000000000000500-0x0000000000000563 (\GPIO) (20160318/utaddress-255)
[   13.486854] ACPI: If an ACPI driver is available for this device, you should use it instead of the native driver
[   13.486860] lpc_ich: Resource conflict(s) found affecting gpio_ich
[   13.603702] samsung_laptop: detected SABI interface: SwSmi@
[   13.657970] [drm] Initialized drm 1.1.0 20060810
[   14.324047] Bluetooth: Core ver 2.21
[   14.324188] NET: Registered protocol family 31
[   14.324192] Bluetooth: HCI device and connection manager initialized
[   14.324266] Bluetooth: HCI socket layer initialized
[   14.324278] Bluetooth: L2CAP socket layer initialized
[   14.324371] Bluetooth: SCO socket layer initialized
[   14.428872] Intel(R) Wireless WiFi driver for Linux
[   14.428987] Copyright(c) 2003- 2015 Intel Corporation
[   14.429630] iwlwifi 0000:01:00.0: can't disable ASPM; OS doesn't have ASPM control
[   15.029046] usbcore: registered new interface driver btusb
[   15.036811] psmouse serio1: elantech: assuming hardware version 3 (with firmware version 0x450f00)
[   15.050571] ppdev: user-space parallel port driver
[   15.051991] psmouse serio1: elantech: Synaptics capabilities query result 0x08, 0x17, 0x0c.
[   15.066872] psmouse serio1: elantech: Elan sample query result 03, 3f, 86
[   15.074966] usb-storage 1-1.2:1.0: USB Mass Storage device detected
[   15.076218] scsi host6: usb-storage 1-1.2:1.0
[   15.076840] usb-storage 1-1.2:1.1: USB Mass Storage device detected
[   15.077333] scsi host7: usb-storage 1-1.2:1.1
[   15.078208] usbcore: registered new interface driver usb-storage
[   15.084400] Linux video capture interface: v2.00
[   15.143961] input: ETPS/2 Elantech Touchpad as /devices/platform/i8042/serio1/input/input6
[   15.822054] iwlwifi 0000:01:00.0: loaded firmware version 18.168.6.1 op_mode iwldvm
[   16.077446] scsi 6:0:0:0: CD-ROM            HUAWEI   Mass Storage     2.31 PQ: 0 ANSI: 2
[   16.077589] scsi 7:0:0:0: Direct-Access     HUAWEI   SD Storage       2.31 PQ: 0 ANSI: 2
[   16.080899] sd 7:0:0:0: Attached scsi generic sg2 type 0
[   16.089803] sr 6:0:0:0: [sr0] scsi-1 drive
[   16.089810] cdrom: Uniform CD-ROM driver Revision: 3.20
[   16.092910] sr 6:0:0:0: Attached scsi CD-ROM sr0
[   16.093652] sr 6:0:0:0: Attached scsi generic sg3 type 5
[   16.093852] sd 7:0:0:0: [sdc] Attached SCSI removable disk
[   16.098691] snd_hda_codec_realtek hdaudioC0D0: autoconfig for ALC269VC: line_outs=1 (0x14/0x0/0x0/0x0/0x0) type:speaker
[   16.098699] snd_hda_codec_realtek hdaudioC0D0:    speaker_outs=0 (0x0/0x0/0x0/0x0/0x0)
[   16.098704] snd_hda_codec_realtek hdaudioC0D0:    hp_outs=1 (0x15/0x0/0x0/0x0/0x0)
[   16.098708] snd_hda_codec_realtek hdaudioC0D0:    mono: mono_out=0x0
[   16.098711] snd_hda_codec_realtek hdaudioC0D0:    inputs:
[   16.098718] snd_hda_codec_realtek hdaudioC0D0:      Internal Mic=0x19
[   16.098724] snd_hda_codec_realtek hdaudioC0D0:      Mic=0x18
[   16.228504] input: HDA Intel PCH Mic as /devices/pci0000:00/0000:00:1b.0/sound/card0/input7
[   16.229540] input: HDA Intel PCH Headphone as /devices/pci0000:00/0000:00:1b.0/sound/card0/input8
[   16.230588] input: HDA Intel PCH HDMI/DP,pcm=3 as /devices/pci0000:00/0000:00:1b.0/sound/card0/input9
[   16.341062] uvcvideo: Found UVC 1.00 device WebCam SC-13HDL11431N (2232:1018)
[   16.360895] input: WebCam SC-13HDL11431N as /devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.4/1-1.4:1.0/input/input10
[   16.361394] usbcore: registered new interface driver uvcvideo
[   16.361398] USB Video Class driver (1.1.1)
[   16.456974] [drm] Memory usable by graphics device = 2048M
[   16.457042] [drm] Replacing VGA console driver
[   16.463191] [drm] Supports vblank timestamp caching Rev 2 (21.10.2013).
[   16.463195] [drm] Driver supports precise vblank timestamp query.
[   16.465692] vgaarb: device changed decodes: PCI:0000:00:02.0,olddecodes=io+mem,decodes=io+mem:owns=io+mem
[   16.488311] ACPI: Video Device [GFX0] (multi-head: yes  rom: no  post: no)
[   16.489520] input: Video Bus as /devices/LNXSYSTM:00/LNXSYBUS:00/PNP0A08:00/LNXVIDEO:00/input/input11
[   16.490730] [drm] Initialized i915 1.6.0 20160229 for 0000:00:02.0 on minor 0
[   16.625594] fbcon: inteldrmfb (fb0) is primary device
[   16.787948] Bluetooth: RFCOMM TTY layer initialized
[   16.787962] Bluetooth: RFCOMM socket layer initialized
[   16.787979] Bluetooth: RFCOMM ver 1.11
[   16.845188] iwlwifi 0000:01:00.0: CONFIG_IWLWIFI_DEBUG disabled
[   16.845190] iwlwifi 0000:01:00.0: CONFIG_IWLWIFI_DEBUGFS enabled
[   16.845191] iwlwifi 0000:01:00.0: CONFIG_IWLWIFI_DEVICE_TRACING enabled
[   16.845193] iwlwifi 0000:01:00.0: Detected Intel(R) Centrino(R) Advanced-N 6230 AGN, REV=0xB0
[   16.845650] iwlwifi 0000:01:00.0: L1 Enabled - LTR Disabled
[   16.925609] Bluetooth: BNEP (Ethernet Emulation) ver 1.3
[   16.925611] Bluetooth: BNEP filters: protocol multicast
[   16.925624] Bluetooth: BNEP socket layer initialized
[   16.979892] ieee80211 phy0: Selected rate control algorithm 'iwl-agn-rs'
[   17.412274] audit: type=1400 audit(1461646013.981:2): apparmor="STATUS" operation="profile_load" name="/sbin/dhclient" pid=1078 comm="apparmor_parser"
[   17.412282] audit: type=1400 audit(1461646013.981:3): apparmor="STATUS" operation="profile_load" name="/usr/lib/NetworkManager/nm-dhcp-client.action" pid=1078 comm="apparmor_parser"
[   17.412288] audit: type=1400 audit(1461646013.981:4): apparmor="STATUS" operation="profile_load" name="/usr/lib/connman/scripts/dhclient-script" pid=1078 comm="apparmor_parser"
[   17.412432] audit: type=1400 audit(1461646013.981:5): apparmor="STATUS" operation="profile_replace" name="/sbin/dhclient" pid=1179 comm="apparmor_parser"
[   17.412446] audit: type=1400 audit(1461646013.981:6): apparmor="STATUS" operation="profile_replace" name="/usr/lib/NetworkManager/nm-dhcp-client.action" pid=1179 comm="apparmor_parser"
[   17.412453] audit: type=1400 audit(1461646013.981:7): apparmor="STATUS" operation="profile_replace" name="/usr/lib/connman/scripts/dhclient-script" pid=1179 comm="apparmor_parser"
[   17.412607] audit: type=1400 audit(1461646013.981:8): apparmor="STATUS" operation="profile_replace" name="/sbin/dhclient" pid=1081 comm="apparmor_parser"
[   17.412619] audit: type=1400 audit(1461646013.981:9): apparmor="STATUS" operation="profile_replace" name="/usr/lib/NetworkManager/nm-dhcp-client.action" pid=1081 comm="apparmor_parser"
[   17.412630] audit: type=1400 audit(1461646013.981:10): apparmor="STATUS" operation="profile_replace" name="/usr/lib/connman/scripts/dhclient-script" pid=1081 comm="apparmor_parser"
[   17.412919] audit: type=1400 audit(1461646013.981:11): apparmor="STATUS" operation="profile_replace" name="/usr/lib/NetworkManager/nm-dhcp-client.action" pid=1078 comm="apparmor_parser"
[   17.705774] usb 1-1.2: USB disconnect, device number 4
[   17.823281] Console: switching to colour frame buffer device 170x48
[   17.827518] i915 0000:00:02.0: fb0: inteldrmfb frame buffer device
[   18.989028] init: failsafe main process (1206) killed by TERM signal
[   21.743105] usb 1-1.2: new high-speed USB device number 5 using ehci-pci
[   21.838119] usb 1-1.2: New USB device found, idVendor=12d1, idProduct=1436
[   21.838132] usb 1-1.2: New USB device strings: Mfr=4, Product=3, SerialNumber=0
[   21.838138] usb 1-1.2: Product: HUAWEI Mobile
[   21.838143] usb 1-1.2: Manufacturer: HUAWEI Technology
[   21.841299] usb-storage 1-1.2:1.0: USB Mass Storage device detected
[   21.842269] usb-storage 1-1.2:1.1: USB Mass Storage device detected
[   21.842779] usb-storage 1-1.2:1.2: USB Mass Storage device detected
[   21.843396] usb-storage 1-1.2:1.3: USB Mass Storage device detected
[   21.843997] usb-storage 1-1.2:1.4: USB Mass Storage device detected
[   21.846697] usb-storage 1-1.2:1.5: USB Mass Storage device detected
[   21.847676] scsi host6: usb-storage 1-1.2:1.5
[   21.848551] usb-storage 1-1.2:1.6: USB Mass Storage device detected
[   21.850839] scsi host7: usb-storage 1-1.2:1.6
[   21.941149] usbcore: registered new interface driver usbserial
[   21.988426] cdc_ether 1-1.2:1.1 wwan0: register 'cdc_ether' at usb-0000:00:1a.0-1.2, Mobile Broadband Network Device, 02:50:f3:00:00:00
[   21.988545] usbcore: registered new interface driver cdc_ether
[   22.075501] usbcore: registered new interface driver option
[   22.077446] usbserial: USB Serial support registered for GSM modem (1-port)
[   22.077907] option 1-1.2:1.0: GSM modem (1-port) converter detected
[   22.079051] usb 1-1.2: GSM modem (1-port) converter now attached to ttyUSB0
[   22.079371] option 1-1.2:1.3: GSM modem (1-port) converter detected
[   22.079929] usb 1-1.2: GSM modem (1-port) converter now attached to ttyUSB1
[   22.080012] option 1-1.2:1.4: GSM modem (1-port) converter detected
[   22.080714] usb 1-1.2: GSM modem (1-port) converter now attached to ttyUSB2
[   22.849175] scsi 6:0:0:0: CD-ROM            HUAWEI   Mass Storage     2.31 PQ: 0 ANSI: 2
[   22.855174] scsi 7:0:0:0: Direct-Access     HUAWEI   SD Storage       2.31 PQ: 0 ANSI: 2
[   22.856014] sr 6:0:0:0: [sr0] scsi-1 drive
[   22.857352] sr 6:0:0:0: Attached scsi CD-ROM sr0
[   22.857830] sr 6:0:0:0: Attached scsi generic sg2 type 5
[   22.860370] sd 7:0:0:0: Attached scsi generic sg3 type 0
[   22.876032] sd 7:0:0:0: [sdc] Attached SCSI removable disk
[   23.997272] r8169 0000:02:00.0 eth0: link down
[   23.997351] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
[   63.421056] PPP BSD Compression module registered
[   63.519522] PPP Deflate Compression module registered
[   64.316684] usb 2-1.5: USB disconnect, device number 4
[  110.920308] blk_update_request: I/O error, dev loop0, sector 6246736
[  111.156119] blk_update_request: I/O error, dev loop0, sector 6246688
[  111.158772] blk_update_request: I/O error, dev loop0, sector 6246712
[  111.174718] blk_update_request: I/O error, dev loop0, sector 2593256
[  111.175120] blk_update_request: I/O error, dev loop0, sector 6246760
[  111.246473] blk_update_request: I/O error, dev loop0, sector 6246664

Great! Thanks for testing.

What kind of device is sda?

Probably the symlinks that confuse it.

Yes, I'll post a v5 today or something like that. Functionally not a huge amount of changes, but it does have a few important bug fixes that make it perform better. The biggest part is making it generic, so it can be plugged into NFS as well, for instance.

Probably a bit too tight for 4.7, but one can always hope. 4.8 is probably a more realistic target.

Testing is really having some readers while you have writes going on. One example is doing something that reads while you have a dd writing to your device. Or interactive feel while installing a lot of packages, which tends to generate a ton of writes as well.

If you are so inclined, I'd encourage you to test the v5 I'll post later today. I've run that through the paces on various devices.

Yeah, I'll do that, it is a bit light right now. It'll be in the next release.

Jens Axboe