bcache strange behaviour in write back mode

Hi all,

We've seen strange behaviour in bcache mode in current bcache-testing branch with Possible allocator fix:

Once I start writing data with "dd if=/dev/zero of=/dev/bcache0 bs=4k count=10000 oflag=sync", all SSDs in the Pool go close to 100% util and I see about 3600 writes/second in iostat for each disk in the pool, BUT no data written in means of throughput.

Then after some seconds (the flush interval of bcache) I see the flush of the writeback and also data written to the pool SSDs which looks pretty much like reordering and merging happened for that data.

bcache-3.2 does not have such problem.
only bcache(master) and bcache-testing have such problem.

What's the possible reason?

Regards,
Jack
--
To unsubscribe from this list: send the line "unsubscribe linux-bcache" in the body of a message to [email protected] More majordomo info at http://vger.kernel.org/majordomo-info.html

Hi all,

We've seen strange behaviour in bcache mode in current bcache-testing branch with Possible allocator fix:

Once I start writing data with "dd if=/dev/zero of=/dev/bcache0 bs=4k count=10000 oflag=sync", all SSDs in the Pool go close to 100% util and I see about 3600 writes/second in iostat for each disk in the pool, BUT no data written in means of throughput.

Then after some seconds (the flush interval of bcache) I see the flush of the writeback and also data written to the pool SSDs which looks pretty much like reordering and merging happened for that data.

bcache-3.2 does not have such problem.
only bcache(master) and bcache-testing have such problem.

What's the possible reason?

Regards,
Jack

I revert this commit:

drivers/md/bcache/request.c +7 -1

index e5ff12e..2f36743 100644
@@ -489,6 +489,12 @@ static void bch_insert_data_loop(struct closure *cl)
                bch_queue_gc(op->c);
        }
 
+       /*
+        * Journal writes are marked REQ_FLUSH; if the original write was a
+        * flush, it'll wait on the journal write.
+        */
+       bio->bi_rw &= ~(REQ_FLUSH|REQ_FUA);
+
        do {
                unsigned i;
                struct bkey *k;

@@ -716,7 +722,7 @@ static struct search *search_alloc(struct bio *bio,
 struct bcache_device *d)
        s->task                 = current;
        s->orig_bio             = bio;
        s->write                = (bio->bi_rw & REQ_WRITE) != 0;
-       s->op.flush_journal     = (bio->bi_rw & REQ_FLUSH) != 0;
+       s->op.flush_journal     = (bio->bi_rw & (REQ_FLUSH|REQ_FUA)) != 0;
        s->op.skip              = (bio->bi_rw & REQ_DISCARD) != 0;
        s->recoverable          = 1;

        s->start_time           = jiffies;

drivers/md/bcache/super.c +2 -0

index 6817ea4..0932580 100644
@@ -766,6 +766,8 @@ static int bcache_device_init(struct bcache_device
 *d, unsigned block_size)
        set_bit(QUEUE_FLAG_NONROT,      &d->disk->queue->queue_flags);
        set_bit(QUEUE_FLAG_DISCARD,     &d->disk->queue->queue_flags);
 
+       blk_queue_flush(q, REQ_FLUSH|REQ_FUA);
+
        return 0;
 }

the strange behaviour is gone. And I checked the bcache-testing, it does not contain that commit any more, maybe I'm lost in the git tree update. Anyway, thanks Kent for your kindly support.

Jack

Quoted 14 lines · Jack Wang

Hi all,

We've seen strange behaviour in bcache mode in current bcache-testing branch with Possible allocator fix:

Once I start writing data with "dd if=/dev/zero of=/dev/bcache0 bs=4k count=10000 oflag=sync", all SSDs in the Pool go close to 100% util and I see about 3600 writes/second in iostat for each disk in the pool, BUT no data written in means of throughput.

Then after some seconds (the flush interval of bcache) I see the flush of the writeback and also data written to the pool SSDs which looks pretty much like reordering and merging happened for that data.

Quoted 8 lines

bcache-3.2 does not have such problem.
only bcache(master) and bcache-testing have such problem.

What's the possible reason?

Regards,
Jack

--
To unsubscribe from this list: send the line "unsubscribe linux-bcache" in the body of a message to [email protected] More majordomo info at http://vger.kernel.org/majordomo-info.html

Ah, you would've been running an old version of the bcache-testing branch...

Someone else bisected a different bug to that commit, so that one's staying in the dev branch for now.

I just pushed the allocator fix to the bcache-for-upstream branch, can you give that a try?

Quoted 77 lines

I revert this commit:

drivers/md/bcache/request.c +7 -1

index e5ff12e..2f36743 100644
@@ -489,6 +489,12 @@ static void bch_insert_data_loop(struct closure *cl)
                bch_queue_gc(op->c);
        }
 
+       /*
+        * Journal writes are marked REQ_FLUSH; if the original write was a
+        * flush, it'll wait on the journal write.
+        */
+       bio->bi_rw &= ~(REQ_FLUSH|REQ_FUA);
+
        do {
                unsigned i;
                struct bkey *k;

@@ -716,7 +722,7 @@ static struct search *search_alloc(struct bio *bio,
 struct bcache_device *d)
        s->task                 = current;
        s->orig_bio             = bio;
        s->write                = (bio->bi_rw & REQ_WRITE) != 0;
-       s->op.flush_journal     = (bio->bi_rw & REQ_FLUSH) != 0;
+       s->op.flush_journal     = (bio->bi_rw & (REQ_FLUSH|REQ_FUA)) != 0;
        s->op.skip              = (bio->bi_rw & REQ_DISCARD) != 0;
        s->recoverable          = 1;

        s->start_time           = jiffies;

drivers/md/bcache/super.c +2 -0

index 6817ea4..0932580 100644
@@ -766,6 +766,8 @@ static int bcache_device_init(struct bcache_device
 *d, unsigned block_size)
        set_bit(QUEUE_FLAG_NONROT,      &d->disk->queue->queue_flags);
        set_bit(QUEUE_FLAG_DISCARD,     &d->disk->queue->queue_flags);
 
+       blk_queue_flush(q, REQ_FLUSH|REQ_FUA);
+
        return 0;
 }

the strange behaviour is gone. And I checked the bcache-testing, it does not contain that commit any more, maybe I'm lost in the git tree update. Anyway, thanks Kent for your kindly support.

Jack

Quoted 14 lines · Jack Wang

Hi all,

We've seen strange behaviour in bcache mode in current bcache-testing branch with Possible allocator fix:

Once I start writing data with "dd if=/dev/zero of=/dev/bcache0 bs=4k count=10000 oflag=sync", all SSDs in the Pool go close to 100% util and I see about 3600 writes/second in iostat for each disk in the pool, BUT no data written in means of throughput.

Then after some seconds (the flush interval of bcache) I see the flush of the writeback and also data written to the pool SSDs which looks pretty much like reordering and merging happened for that data.

Quoted 8 lines

bcache-3.2 does not have such problem.
only bcache(master) and bcache-testing have such problem.

What's the possible reason?

Regards,
Jack

--
To unsubscribe from this list: send the line "unsubscribe linux-bcache" in the body of a message to [email protected] More majordomo info at http://vger.kernel.org/majordomo-info.html

So you can easily reproduce this? If so, that's _awesome_ news - would you be willing to try out a debug kernel with some tracing stuff added? Maybe we can finally nail this.

On Mon, Apr 22, 2013 at 12:15 PM, Jack Wang <[email protected] <mailto:[email protected]>> wrote:

Hi all,

We've seen strange behaviour in bcache mode in current bcache-testing branch with Possible allocator fix:

Once I start writing data with "dd if=/dev/zero of=/dev/bcache0 bs=4k count=10000 oflag=sync", all SSDs in the Pool go close to 100% util and I see about 3600 writes/second in iostat for each disk in the pool, BUT no data written in means of throughput.

Then after some seconds (the flush interval of bcache) I see the flush of the writeback and also data written to the pool SSDs which looks pretty much like reordering and merging happened for that data.

bcache-3.2 does not have such problem.
only bcache(master) and bcache-testing have such problem.

What's the possible reason?

Regards,
Jack
--
To unsubscribe from this list: send the line "unsubscribe linux-bcache" in
the body of a message to [email protected] <mailto:[email protected]> More majordomo info at http://vger.kernel.org/majordomo-info.html

Thanks for reply, Kent, two of my colleagues saw this behaviour, so I think we can reproduce this.
If you could give me more detailed guide to narrow it down, I can try it on my side.

Quoted 4 lines · Jack Wang

Thanks for reply, Kent, two of my colleagues saw this behaviour, so I think we can reproduce this.
If you could give me more detailed guide to narrow it down, I can try it on my side.

So, my current hypothesis is that the problem is the allocator spinning, and the IO is from it continually rewriting prios/gens.

But I'm still not sure what's causing the allocator to spin, that's what the last patch was supposed to fix.

Can you see if you can reproduce it with this patch, and then tell me what shows up in the dmesg log? I expect you'll get a _lot_ of output - flip timestamps on in your kernel config, if they're not already on. Thanks!

commit 60a09d37d301f88dd0f0f413408821a067966d1a

Author: Kent Overstreet <[email protected]>
Date:   Mon Apr 22 14:49:33 2013 -0700

bcache: Allocator debug patch

drivers/md/bcache/alloc.c +9 -2

index 2879487..37c22c6 100644
@@ -393,12 +393,15 @@ void bch_allocator_thread(struct closure *cl)
 				allocator_wait(ca, !list_empty(&ca->discards));
 				do_discard(ca, bucket);
 			} else {
-				fifo_push(&ca->free, bucket);
+				BUG_ON(!fifo_push(&ca->free, bucket));
 				closure_wake_up(&ca->set->bucket_wait);
 			}
 		}
 
 		allocator_wait(ca, ca->set->gc_mark_valid);
+
+		printk(KERN_DEBUG "bcache: invalidating buckets: free_inc %zu/%zu\n",
+		       fifo_used(&ca->free_inc), ca->free_inc.size);
 		invalidate_buckets(ca);
 
 		allocator_wait(ca, !atomic_read(&ca->set->prio_blocked) ||

@@ -407,8 +410,12 @@ void bch_allocator_thread(struct closure *cl)
 		if (CACHE_SYNC(&ca->set->sb) &&
 		    (!fifo_empty(&ca->free_inc) ||
 		     ca->need_save_prio > 64)) {
+			printk(KERN_DEBUG "bcache: writing prios: free_inc %zu/%zu\n",
+			       fifo_used(&ca->free_inc), ca->free_inc.size);
 			bch_prio_write(ca);
-		}
+		} else
+			printk(KERN_DEBUG "bcache: not writing prios: free_inc %zu/%zu\n",
+			       fifo_used(&ca->free_inc), ca->free_inc.size);
 	}
 }
 

Hi Kent,

After some test, we saw log in dmesg like below:

[ 1505.282400] bcache: bch_allocator_thread() bcache: invalidating
buckets: free_inc 0/127
[ 1505.285843] bcache: bch_allocator_thread() bcache: not writing prios:
free_inc 0/127
[ 1508.005957] bcache: bch_allocator_thread() bcache: invalidating
buckets: free_inc 0/127
[ 1508.009357] bcache: bch_allocator_thread() bcache: not writing prios:
free_inc 0/127
[ 1512.493609] bcache: bch_allocator_thread() bcache: invalidating
buckets: free_inc 0/127
[ 1512.497070] bcache: bch_allocator_thread() bcache: not writing prios:

free_inc 0/127

Does this show some clue to you?

Regards,
Jack

Quoted 58 lines · Kent Overstreet

Quoted 4 lines · Jack Wang

Thanks for reply, Kent, two of my colleagues saw this behaviour, so I think we can reproduce this.
If you could give me more detailed guide to narrow it down, I can try it on my side.

So, my current hypothesis is that the problem is the allocator spinning, and the IO is from it continually rewriting prios/gens.

But I'm still not sure what's causing the allocator to spin, that's what the last patch was supposed to fix.

Can you see if you can reproduce it with this patch, and then tell me what shows up in the dmesg log? I expect you'll get a _lot_ of output - flip timestamps on in your kernel config, if they're not already on. Thanks!

commit 60a09d37d301f88dd0f0f413408821a067966d1a

Author: Kent Overstreet <[email protected]>
Date:   Mon Apr 22 14:49:33 2013 -0700

bcache: Allocator debug patch

drivers/md/bcache/alloc.c +9 -2

index 2879487..37c22c6 100644
@@ -393,12 +393,15 @@ void bch_allocator_thread(struct closure *cl)
                              allocator_wait(ca, !list_empty(&ca->discards));
                              do_discard(ca, bucket);
                      } else {
-                             fifo_push(&ca->free, bucket);
+                             BUG_ON(!fifo_push(&ca->free, bucket));
                              closure_wake_up(&ca->set->bucket_wait);
                      }
              }
 
              allocator_wait(ca, ca->set->gc_mark_valid);
+
+             printk(KERN_DEBUG "bcache: invalidating buckets: free_inc %zu/%zu\n",
+                    fifo_used(&ca->free_inc), ca->free_inc.size);
              invalidate_buckets(ca);
 
              allocator_wait(ca, !atomic_read(&ca->set->prio_blocked) ||

@@ -407,8 +410,12 @@ void bch_allocator_thread(struct closure *cl)
              if (CACHE_SYNC(&ca->set->sb) &&
                  (!fifo_empty(&ca->free_inc) ||
                   ca->need_save_prio > 64)) {
+                     printk(KERN_DEBUG "bcache: writing prios: free_inc %zu/%zu\n",
+                            fifo_used(&ca->free_inc), ca->free_inc.size);
                      bch_prio_write(ca);
-             }
+             } else
+                     printk(KERN_DEBUG "bcache: not writing prios: free_inc %zu/%zu\n",
+                            fifo_used(&ca->free_inc), ca->free_inc.size);
      }
 }
 

Well _that_ interesting, the implication is that garbage collection is getting stuck somehow and unable to finish.

I'll probably have another debug patch for you later today.

Quoted 84 lines

Hi Kent,

After some test, we saw log in dmesg like below:

[ 1505.282400] bcache: bch_allocator_thread() bcache: invalidating
buckets: free_inc 0/127
[ 1505.285843] bcache: bch_allocator_thread() bcache: not writing prios:
free_inc 0/127
[ 1508.005957] bcache: bch_allocator_thread() bcache: invalidating
buckets: free_inc 0/127
[ 1508.009357] bcache: bch_allocator_thread() bcache: not writing prios:
free_inc 0/127
[ 1512.493609] bcache: bch_allocator_thread() bcache: invalidating
buckets: free_inc 0/127
[ 1512.497070] bcache: bch_allocator_thread() bcache: not writing prios:

free_inc 0/127

Does this show some clue to you?

Regards,
Jack

Quoted 58 lines · Kent Overstreet

Quoted 4 lines · Jack Wang

Thanks for reply, Kent, two of my colleagues saw this behaviour, so I think we can reproduce this.
If you could give me more detailed guide to narrow it down, I can try it on my side.

So, my current hypothesis is that the problem is the allocator spinning, and the IO is from it continually rewriting prios/gens.

But I'm still not sure what's causing the allocator to spin, that's what the last patch was supposed to fix.

Can you see if you can reproduce it with this patch, and then tell me what shows up in the dmesg log? I expect you'll get a _lot_ of output - flip timestamps on in your kernel config, if they're not already on. Thanks!

commit 60a09d37d301f88dd0f0f413408821a067966d1a

Author: Kent Overstreet <[email protected]>
Date:   Mon Apr 22 14:49:33 2013 -0700

bcache: Allocator debug patch

drivers/md/bcache/alloc.c +9 -2

index 2879487..37c22c6 100644
@@ -393,12 +393,15 @@ void bch_allocator_thread(struct closure *cl)
                              allocator_wait(ca, !list_empty(&ca->discards));
                              do_discard(ca, bucket);
                      } else {
-                             fifo_push(&ca->free, bucket);
+                             BUG_ON(!fifo_push(&ca->free, bucket));
                              closure_wake_up(&ca->set->bucket_wait);
                      }
              }
 
              allocator_wait(ca, ca->set->gc_mark_valid);
+
+             printk(KERN_DEBUG "bcache: invalidating buckets: free_inc %zu/%zu\n",
+                    fifo_used(&ca->free_inc), ca->free_inc.size);
              invalidate_buckets(ca);
 
              allocator_wait(ca, !atomic_read(&ca->set->prio_blocked) ||

@@ -407,8 +410,12 @@ void bch_allocator_thread(struct closure *cl)
              if (CACHE_SYNC(&ca->set->sb) &&
                  (!fifo_empty(&ca->free_inc) ||
                   ca->need_save_prio > 64)) {
+                     printk(KERN_DEBUG "bcache: writing prios: free_inc %zu/%zu\n",
+                            fifo_used(&ca->free_inc), ca->free_inc.size);
                      bch_prio_write(ca);
-             }
+             } else
+                     printk(KERN_DEBUG "bcache: not writing prios: free_inc %zu/%zu\n",
+                            fifo_used(&ca->free_inc), ca->free_inc.size);
      }
 }