xfs: introduce object readahead to log recovery

From: Zhi Yong Wu <[email protected]>

It can take a long time to run log recovery operation because it is
single threaded and is bound by read latency. We can find that it took most of the time to wait for the read IO to occur, so if one object readahead is introduced to log recovery, it will obviously reduce the log recovery time.

In dirty log case as below:

    data device: 0xfd10
    log device: 0xfd10 daddr: 20480032 length: 20480

    log tail: 7941 head: 11077 state: <DIRTY>

This dirty ratio is about 15%. I am trying to do tests in larger scale and dirtier filesystem environment.

Log recovery time stat:

w/o this patch w/ this patch

  real         0m1.051s             0m0.965s
  sys          0m0.033s             0m0.035s

iowait 0m1.018s 0m0.930s

fs/xfs/xfs_log_recover.c +9 -0

+STATIC void
+xlog_recover_inode_ra_pass2(
+	struct xlog                     *log,
+	struct xlog_recover_item        *item)
+{
+	xfs_inode_log_format_t	*in_f;
+	xfs_mount_t		*mp = log->l_mp;
+	int			error;
+	int			need_free = 0;

fs/xfs/xfs_log_recover.c +31 -0

+STATIC void
+xlog_recover_dquot_ra_pass2(
+	struct xlog			*log,
+	struct xlog_recover_item	*item)
+{
+	xfs_mount_t		*mp = log->l_mp;
+	xfs_buf_t		*bp;
+	struct xfs_disk_dquot	*recddq;
+	int			error;
+	xfs_dq_logformat_t	*dq_f;
+	uint			type;
+
+
+	if (mp->m_qflags == 0)
+		return;
+
+	recddq = item->ri_buf[1].i_addr;
+	if (recddq == NULL)
+		return;
+	if (item->ri_buf[1].i_len < sizeof(xfs_disk_dquot_t))
+		return;
+
+	type = recddq->d_flags & (XFS_DQ_USER | XFS_DQ_PROJ | XFS_DQ_GROUP);
+	ASSERT(type);
+	if (log->l_quotaoffs_flag & type)
+		return;
+
+	dq_f = item->ri_buf[0].i_addr;
+	ASSERT(dq_f);
+	error = xfs_qm_dqcheck(mp, recddq, dq_f->qlf_id, 0, XFS_QMOPT_DOWARN,
+			   "xlog_recover_dquot_ra_pass2 (log copy)");

STATIC int
xlog_recover_commit_pass1(

fs/xfs/xfs_log_recover.c +0 -0

 	struct xlog			*log,

@@ -3140,10 +3255,14 @@ xlog_recover_commit_pass2(
 	struct xlog			*log,
 	struct xlog_recover		*trans,

fs/xfs/xfs_log_recover.c +2 -2

 	switch (ITEM_TYPE(item)) {
 	case XFS_LI_BUF:
 		return xlog_recover_buffer_pass2(log, buffer_list, item);

@@ -3181,7 +3300,7 @@ xlog_recover_commit_trans(
 	int			pass)
 {
 	int			error = 0, error2;
-	xlog_recover_item_t	*item;
+	xlog_recover_item_t	*item, *next_item, *temp_item;
 	LIST_HEAD		(buffer_list);
 
 	hlist_del(&trans->r_list);

@@ -3190,14 +3309,18 @@ xlog_recover_commit_trans(
 	if (error)
 		return error;
 
-	list_for_each_entry(item, &trans->r_itemq, ri_list) {
+	list_for_each_entry_safe(item, temp_item, &trans->r_itemq, ri_list) {
 		switch (pass) {
 		case XLOG_RECOVER_PASS1:

Quoted 8 lines · On Thu, Jul 25, 2013 at 04:23:39PM +0800, [email protected] wrote:

From: Zhi Yong Wu <[email protected]>

It can take a long time to run log recovery operation because it is
single threaded and is bound by read latency. We can find that it took most of the time to wait for the read IO to occur, so if one object readahead is introduced to log recovery, it will obviously reduce the log recovery time.

Quoted 5 lines

In dirty log case as below:

    data device: 0xfd10
    log device: 0xfd10 daddr: 20480032 length: 20480

    log tail: 7941 head: 11077 state: <DIRTY>

That's only a small log (10MB). As I've said on irc, readahead won't

show any real difference on this and you need to be testing with large logs.

Quoted 11 lines

This dirty ratio is about 15%. I am trying to do tests in larger scale and dirtier filesystem environment.

Log recovery time stat:

w/o this patch w/ this patch

  real         0m1.051s             0m0.965s
  sys          0m0.033s             0m0.035s

iowait 0m1.018s 0m0.930s

Well, it's not made much of a difference there. That's probably within the noise of repeated log recovery runs.

My simple test is:

$ cat recovery_time.sh
#!/bin/bash

cd /home/dave/src/compilebench-0.6/

mkfs.xfs -f /dev/vdc;
mount /dev/vdc /mnt/scratch
chmod 777 /mnt/scratch;
./compilebench --no-sync -D /mnt/scratch & sleep 55 /home/dave/src/xfstests-dev/src/godown /mnt/scratch umount /mnt/scratch
xfs_logprint -t /dev/vdc |head -20
time mount /dev/vdc /mnt/scratch
umount /mnt/scratch
$

And the recovery time from this is between 15-17s:

....

    log device: 0xfd20 daddr: 107374182032 length: 4173824
                                                   ^^^^^^^ almost 2GB
        log tail: 19288 head: 264809 state: <DIRTY>
....
real    0m17.913s
user    0m0.000s
sys     0m2.381s

And runs at 3-4000 read IOPs for most of that time. It's largely IO bound, even on SSDs.

With your patch:

log tail: 35871 head: 308393 state: <DIRTY>

real    0m12.715s
user    0m0.000s
sys     0m2.247s

And it peaked at ~5000 read IOPS.

It's definitely an improvement, but there's a lot of dead time still spent waiting for IO that we should be able to remove. Let's have a look at the code...

Quoted 16 lines

fs/xfs/xfs_log_recover.c +16 -0

+STATIC void
+xlog_recover_inode_ra_pass2(
+     struct xlog                     *log,
+     struct xlog_recover_item        *item)
+{
+     xfs_inode_log_format_t  *in_f;
+     xfs_mount_t             *mp = log->l_mp;
+     int                     error;
+     int                     need_free = 0;
+
+     if (item->ri_buf[0].i_len == sizeof(xfs_inode_log_format_t)) {
+             in_f = item->ri_buf[0].i_addr;
+     } else {
+             in_f = kmem_alloc(sizeof(xfs_inode_log_format_t), KM_SLEEP);
+             need_free = 1;
+             error = xfs_inode_item_format_convert(&item->ri_buf[0], in_f);

fs/xfs/xfs_log_recover.c xlog_recover_free_trans( · line 3145

Quoted 3 lines

fs/xfs/xfs_log_recover.c +3 -0

+             if (error)
+                     goto error;
+     }

I'd just put the conversion buffer on stack and avoid the need to alloc/free memory here. There's plenty of stack space available during recovery here, so let's use it to keep the overhead of readahead down.

Quoted 39 lines

fs/xfs/xfs_log_recover.c +38 -0

+STATIC void
+xlog_recover_dquot_ra_pass2(
+     struct xlog                     *log,
+     struct xlog_recover_item        *item)
+{
+     xfs_mount_t             *mp = log->l_mp;
+     xfs_buf_t               *bp;
+     struct xfs_disk_dquot   *recddq;
+     int                     error;
+     xfs_dq_logformat_t      *dq_f;
+     uint                    type;
+
+
+     if (mp->m_qflags == 0)
+             return;
+
+     recddq = item->ri_buf[1].i_addr;
+     if (recddq == NULL)
+             return;
+     if (item->ri_buf[1].i_len < sizeof(xfs_disk_dquot_t))
+             return;
+
+     type = recddq->d_flags & (XFS_DQ_USER | XFS_DQ_PROJ | XFS_DQ_GROUP);
+     ASSERT(type);
+     if (log->l_quotaoffs_flag & type)
+             return;
+
+     dq_f = item->ri_buf[0].i_addr;
+     ASSERT(dq_f);
+     error = xfs_qm_dqcheck(mp, recddq, dq_f->qlf_id, 0, XFS_QMOPT_DOWARN,
+                        "xlog_recover_dquot_ra_pass2 (log copy)");
+     if (error)
+             return;
+     ASSERT(dq_f->qlf_len == 1);
+
+     error = xfs_trans_read_buf(mp, NULL, mp->m_ddev_targp, dq_f->qlf_blkno,
+                                XFS_FSB_TO_BB(mp, dq_f->qlf_len), 0, &bp,
+                                NULL);

fs/xfs/xfs_log_recover.c xlog_recover_free_trans( · line 3200

Quoted 3 lines

fs/xfs/xfs_log_recover.c +3 -0

+     if (!error)
+             xfs_buf_relse(bp);
+}

That's not doing readahead - that's an integrity check followed by a blocking read. Shouldn't it just be calling xfs_buf_readahead() on dq_f->qlf_blkno/dq_f->qlf_len, after checking whether it had been cancelled?

Quoted 14 lines

STATIC int
xlog_recover_commit_pass1(
struct xlog *log,

fs/xfs/xfs_log_recover.c +2 -1

@@ -3140,10 +3255,14 @@ xlog_recover_commit_pass2(
      struct xlog                     *log,
      struct xlog_recover             *trans,
      struct list_head                *buffer_list,
-     struct xlog_recover_item        *item)
+     struct xlog_recover_item        *item,
+     struct xlog_recover_item        *next_item)
 {
      trace_xfs_log_recover_item_recover(log, trans, item, XLOG_RECOVER_PASS2);
 

fs/xfs/xfs_log_recover.c xlog_recover_commit_pass2( · line 3265

Quoted 3 lines

fs/xfs/xfs_log_recover.c +3 -0

+     if (next_item)
+             xlog_recover_ra_pass2(log, next_item);
+

Ah, that explains the limited improvement - it's only doing readahead of a single item at a time. IOWs, we are completing recovery of the current object before IO completion of the next object has occurred. This generally means the read-ahead queue is

not deep enough...

Quoted 20 lines

fs/xfs/xfs_log_recover.c +2 -2

      switch (ITEM_TYPE(item)) {
      case XFS_LI_BUF:
              return xlog_recover_buffer_pass2(log, buffer_list, item);

@@ -3181,7 +3300,7 @@ xlog_recover_commit_trans(
      int                     pass)
 {
      int                     error = 0, error2;
-     xlog_recover_item_t     *item;
+     xlog_recover_item_t     *item, *next_item, *temp_item;
      LIST_HEAD               (buffer_list);
 
      hlist_del(&trans->r_list);

@@ -3190,14 +3309,18 @@ xlog_recover_commit_trans(
      if (error)
              return error;
 
-     list_for_each_entry(item, &trans->r_itemq, ri_list) {
+     list_for_each_entry_safe(item, temp_item, &trans->r_itemq, ri_list) {
              switch (pass) {
              case XLOG_RECOVER_PASS1:

fs/xfs/xfs_log_recover.c xlog_recover_commit_trans( · line 3323

Quoted 10 lines

fs/xfs/xfs_log_recover.c +5 -1

                      error = xlog_recover_commit_pass1(log, trans, item);
                      break;
              case XLOG_RECOVER_PASS2:
+                     if (&temp_item->ri_list != &trans->r_itemq)
+                             next_item = temp_item;
+                     else
+                             next_item = NULL;
                      error = xlog_recover_commit_pass2(log, trans,
-                                                       &buffer_list, item);
+                                       &buffer_list, item, next_item);

Ok, so you've based the readahead on the transaction item list having a next pointer. What I think you should do is turn this into a readahead queue by moving objects to a new list. i.e.

        list_for_each_entry_safe(item, next, &trans->r_itemq, ri_list) {

                case XLOG_RECOVER_PASS2:
                        if (ra_qdepth++ >= MAX_QDEPTH) {
                                recover_items(log, trans, &buffer_list, &ra_item_list);
                                ra_qdepth = 0;
                        } else {
                                xlog_recover_item_readahead(log, item);
                                list_move_tail(&item->ri_list, &ra_item_list);
                        }
                        break;
                ...
                }
        }
        if (!list_empty(&ra_item_list))
                recover_items(log, trans, &buffer_list, &ra_item_list);

I'd suggest that a queue depth somewhere between 10 and 100 will be necessary to keep enough IO in flight to keep the pipeline full and prevent recovery from having to wait on IO...

Cheers,

Dave.
--
Dave Chinner
[email protected]

Dave,

All comments are good to me, and will be applied to next version, thanks a lot.

Quoted 9 lines · Dave Chinner

Quoted 8 lines · On Thu, Jul 25, 2013 at 04:23:39PM +0800, [email protected] wrote:

From: Zhi Yong Wu <[email protected]>

It can take a long time to run log recovery operation because it is
single threaded and is bound by read latency. We can find that it took most of the time to wait for the read IO to occur, so if one object readahead is introduced to log recovery, it will obviously reduce the log recovery time.

Quoted 7 lines

Quoted 5 lines

In dirty log case as below:

    data device: 0xfd10
    log device: 0xfd10 daddr: 20480032 length: 20480

    log tail: 7941 head: 11077 state: <DIRTY>

That's only a small log (10MB). As I've said on irc, readahead won't

Yeah, it is one 10MB log, but how do you calculate it based on the above info?

Quoted 16 lines

And the recovery time from this is between 15-17s:

....

    log device: 0xfd20 daddr: 107374182032 length: 4173824
                                                   ^^^^^^^ almost 2GB
        log tail: 19288 head: 264809 state: <DIRTY>
....
real    0m17.913s
user    0m0.000s
sys     0m2.381s

And runs at 3-4000 read IOPs for most of that time. It's largely IO bound, even on SSDs.

With your patch:

Quoted 6 lines

log tail: 35871 head: 308393 state: <DIRTY>

real    0m12.715s
user    0m0.000s
sys     0m2.247s

And it peaked at ~5000 read IOPS.

How do you know its READ IOPS is ~5000?

Quoted 21 lines

Ok, so you've based the readahead on the transaction item list having a next pointer. What I think you should do is turn this into a readahead queue by moving objects to a new list. i.e.

        list_for_each_entry_safe(item, next, &trans->r_itemq, ri_list) {

                case XLOG_RECOVER_PASS2:
                        if (ra_qdepth++ >= MAX_QDEPTH) {
                                recover_items(log, trans, &buffer_list, &ra_item_list);
                                ra_qdepth = 0;
                        } else {
                                xlog_recover_item_readahead(log, item);
                                list_move_tail(&item->ri_list, &ra_item_list);
                        }
                        break;
                ...
                }
        }
        if (!list_empty(&ra_item_list))
                recover_items(log, trans, &buffer_list, &ra_item_list);

Quoted 3 lines

I'd suggest that a queue depth somewhere between 10 and 100 will be necessary to keep enough IO in flight to keep the pipeline full and prevent recovery from having to wait on IO...

Good suggestion, will apply it to next version, thanks.

Quoted 18 lines · Zhi Yong Wu

Dave,

All comments are good to me, and will be applied to next version, thanks a lot.

Quoted 13 lines · Dave Chinner

Quoted 12 lines · On Thu, Jul 25, 2013 at 04:23:39PM +0800, [email protected] wrote:

From: Zhi Yong Wu <[email protected]>

It can take a long time to run log recovery operation because it is
single threaded and is bound by read latency. We can find that it took most of the time to wait for the read IO to occur, so if one object readahead is introduced to log recovery, it will obviously reduce the log recovery time.

In dirty log case as below:

    data device: 0xfd10
    log device: 0xfd10 daddr: 20480032 length: 20480

Quoted 4 lines

Quoted 3 lines

Quoted 1 line

    log tail: 7941 head: 11077 state: <DIRTY>

That's only a small log (10MB). As I've said on irc, readahead won't

Yeah, it is one 10MB log, but how do you calculate it based on the above info?

length = 20480 blocks. 20480 * 512 = 10MB....

Quoted 22 lines

Quoted 22 lines

And the recovery time from this is between 15-17s:

....

    log device: 0xfd20 daddr: 107374182032 length: 4173824
                                                   ^^^^^^^ almost 2GB
        log tail: 19288 head: 264809 state: <DIRTY>
....
real    0m17.913s
user    0m0.000s
sys     0m2.381s

And runs at 3-4000 read IOPs for most of that time. It's largely IO bound, even on SSDs.

With your patch:

log tail: 35871 head: 308393 state: <DIRTY>

real    0m12.715s
user    0m0.000s
sys     0m2.247s

Quoted 2 lines

Quoted 1 line

And it peaked at ~5000 read IOPS.

How do you know its READ IOPS is ~5000?

Other monitoring. iostat can tell you this, though I use PCP...

Quoted 25 lines

Quoted 25 lines

Ok, so you've based the readahead on the transaction item list having a next pointer. What I think you should do is turn this into a readahead queue by moving objects to a new list. i.e.

        list_for_each_entry_safe(item, next, &trans->r_itemq, ri_list) {

                case XLOG_RECOVER_PASS2:
                        if (ra_qdepth++ >= MAX_QDEPTH) {
                                recover_items(log, trans, &buffer_list, &ra_item_list);
                                ra_qdepth = 0;
                        } else {
                                xlog_recover_item_readahead(log, item);
                                list_move_tail(&item->ri_list, &ra_item_list);
                        }
                        break;
                ...
                }
        }
        if (!list_empty(&ra_item_list))
                recover_items(log, trans, &buffer_list, &ra_item_list);

I'd suggest that a queue depth somewhere between 10 and 100 will be necessary to keep enough IO in flight to keep the pipeline full and prevent recovery from having to wait on IO...

Quoted 1 line

Good suggestion, will apply it to next version, thanks.

FWIW, I hacked a quick test of this into your patch here and a depth of 100 brought the reocvery time down to under 8s. For other workloads which have nothing but dirty inodes (like fsmark) a depth of 100 drops the recovery time from ~100s to ~25s, and the iop rate is peaking at well over 15,000 IOPS. So we definitely want to queue up more than a single readahead...

Cheers,

Dave.
--
Dave Chinner
[email protected]

By the way, how do you try the workload which has nothing but dirty dquote objects?

Quoted 2 lines · Zhi Yong Wu

By the way, how do you try the workload which has nothing but dirty dquote objects?

Create quota limits for non-existent users. That will allocate the dquots and dirty them.

Or if you already have a few hundred thousand dquots, just change the limits on them all to get them logged and dirty...

Cheers,

Dave.
--
Dave Chinner
[email protected]