xlog_space_left: head behind tail

xlog_space_left: head behind tail

[Jan Kara]

  Hello,

  when I run:
while true; do ~/tests/xfstests-dev/ltp/fsstress -d /mnt -n 10000 -p 4; done

and in parallel

while true; do ./fsfreeze /mnt; sync; ./fsfreeze -u /mnt; sleep 3; done

where fsfreeze is a small utility freezing and unfreezing filesystem. I get
warnings like:
[ 2029.103193] XFS (vdb1): xlog_space_left: head behind tail
[ 2029.103195]   tail_cycle = 10, tail_bytes = 6036480
[ 2029.103197]   GH   cycle = 10, GH   bytes = 6035728
[ 2029.103218] XFS (vdb1): xlog_space_left: head behind tail
[ 2029.103219]   tail_cycle = 10, tail_bytes = 6036480
[ 2029.103220]   GH   cycle = 10, GH   bytes = 6035728
[ 2033.269796] XFS (vdb1): xlog_space_left: head behind tail
[ 2033.269800]   tail_cycle = 10, tail_bytes = 6400512
[ 2033.269803]   GH   cycle = 10, GH   bytes = 6399752
[ 2033.269830] XFS (vdb1): xlog_space_left: head behind tail
[ 2033.269835]   tail_cycle = 10, tail_bytes = 6400512
[ 2033.269838]   GH   cycle = 10, GH   bytes = 6399752
[ 2033.269847] XFS (vdb1): xlog_space_left: head behind tail
[ 2033.269850]   tail_cycle = 10, tail_bytes = 6400512
[ 2033.269852]   GH   cycle = 10, GH   bytes = 6399752
[ 2033.269892] XFS (vdb1): xlog_space_left: head behind tail
[ 2033.269894]   tail_cycle = 10, tail_bytes = 6400512
[ 2033.269896]   GH   cycle = 10, GH   bytes = 6399752
[ 2033.269915] XFS (vdb1): xlog_space_left: head behind tail
[ 2033.269918]   tail_cycle = 10, tail_bytes = 6400512
[ 2033.269920]   GH   cycle = 10, GH   bytes = 6399752

They usually start to appear like 20 minutes after starting the tests and
when they start to appear they happen every couple of seconds (as you can
see from the timestamps). Is it a real problem or just annoyance?

								Honza
-- 
Jan Kara <jack@suse.cz>
SUSE Labs, CR

_______________________________________________
xfs mailing list
xfs@oss.sgi.com
http://oss.sgi.com/mailman/listinfo/xfs

Re: xlog_space_left: head behind tail

[Jan Kara]

On Thu 23-02-12 11:48:53, Jan Kara wrote:
>   Hello,
> 
>   when I run:
> while true; do ~/tests/xfstests-dev/ltp/fsstress -d /mnt -n 10000 -p 4; done
> 
> and in parallel
> 
> while true; do ./fsfreeze /mnt; sync; ./fsfreeze -u /mnt; sleep 3; done
> 
> where fsfreeze is a small utility freezing and unfreezing filesystem. I get
> warnings like:
  BTW, the first message is:
[ 1626.278347] XFS (vdb1): xlog_space_left: head behind tail
[ 1626.278349]   tail_cycle = 7, tail_bytes = 12907008
[ 1626.278351]   GH   cycle = 7, GH   bytes = 12907000

								Honza

> [ 2029.103193] XFS (vdb1): xlog_space_left: head behind tail
> [ 2029.103195]   tail_cycle = 10, tail_bytes = 6036480
> [ 2029.103197]   GH   cycle = 10, GH   bytes = 6035728
> [ 2029.103218] XFS (vdb1): xlog_space_left: head behind tail
> [ 2029.103219]   tail_cycle = 10, tail_bytes = 6036480
> [ 2029.103220]   GH   cycle = 10, GH   bytes = 6035728
> [ 2033.269796] XFS (vdb1): xlog_space_left: head behind tail
> [ 2033.269800]   tail_cycle = 10, tail_bytes = 6400512
> [ 2033.269803]   GH   cycle = 10, GH   bytes = 6399752
> [ 2033.269830] XFS (vdb1): xlog_space_left: head behind tail
> [ 2033.269835]   tail_cycle = 10, tail_bytes = 6400512
> [ 2033.269838]   GH   cycle = 10, GH   bytes = 6399752
> [ 2033.269847] XFS (vdb1): xlog_space_left: head behind tail
> [ 2033.269850]   tail_cycle = 10, tail_bytes = 6400512
> [ 2033.269852]   GH   cycle = 10, GH   bytes = 6399752
> [ 2033.269892] XFS (vdb1): xlog_space_left: head behind tail
> [ 2033.269894]   tail_cycle = 10, tail_bytes = 6400512
> [ 2033.269896]   GH   cycle = 10, GH   bytes = 6399752
> [ 2033.269915] XFS (vdb1): xlog_space_left: head behind tail
> [ 2033.269918]   tail_cycle = 10, tail_bytes = 6400512
> [ 2033.269920]   GH   cycle = 10, GH   bytes = 6399752
> 
> They usually start to appear like 20 minutes after starting the tests and
> when they start to appear they happen every couple of seconds (as you can
> see from the timestamps). Is it a real problem or just annoyance?
> 
> 								Honza
> -- 
> Jan Kara <jack@suse.cz>
> SUSE Labs, CR
-- 
Jan Kara <jack@suse.cz>
SUSE Labs, CR

_______________________________________________
xfs mailing list
xfs@oss.sgi.com
http://oss.sgi.com/mailman/listinfo/xfs

Re: xlog_space_left: head behind tail

[Dave Chinner]

On Thu, Feb 23, 2012 at 11:54:18AM +0100, Jan Kara wrote:
> On Thu 23-02-12 11:48:53, Jan Kara wrote:
> >   Hello,
> > 
> >   when I run:
> > while true; do ~/tests/xfstests-dev/ltp/fsstress -d /mnt -n 10000 -p 4; done
> > 
> > and in parallel
> > 
> > while true; do ./fsfreeze /mnt; sync; ./fsfreeze -u /mnt; sleep 3; done
> > 
> > where fsfreeze is a small utility freezing and unfreezing filesystem.

Ah, the world has been reinvented again:

$ xfs_io -x -c "help freeze" -c "help thaw"
freeze -- freeze filesystem of current file
thaw -- unfreeze filesystem of current file

> > I get
> > warnings like:
>   BTW, the first message is:
> [ 1626.278347] XFS (vdb1): xlog_space_left: head behind tail
> [ 1626.278349]   tail_cycle = 7, tail_bytes = 12907008
> [ 1626.278351]   GH   cycle = 7, GH   bytes = 12907000

So out by 8 bytes.

This is indicative of a transaction reservation accounting error or
a race condition in updating the grant heads during transaction
reservation/completion.

> > [ 2029.103193] XFS (vdb1): xlog_space_left: head behind tail
> > [ 2029.103195]   tail_cycle = 10, tail_bytes = 6036480
> > [ 2029.103197]   GH   cycle = 10, GH   bytes = 6035728

and 400s later is it out by 752 bytes

> > [ 2029.103218] XFS (vdb1): xlog_space_left: head behind tail
> > [ 2029.103219]   tail_cycle = 10, tail_bytes = 6036480
> > [ 2029.103220]   GH   cycle = 10, GH   bytes = 6035728
> > [ 2033.269796] XFS (vdb1): xlog_space_left: head behind tail
> > [ 2033.269800]   tail_cycle = 10, tail_bytes = 6400512
> > [ 2033.269803]   GH   cycle = 10, GH   bytes = 6399752

And 4s later (a single freeze) it is out by 760 bytes.

Ok, so that looks like a 8 byte accounting leak rather than a race
that is occurring. Given that it has been roughly 400s since the
first report, and you're running a freeze roughly every 4s, that's
100 freezes, and that's roughly 800 bytes which is in the ballpark
for 8 bytes a freeze being leaked.

I'll look into it further.

> Is it a real problem or just annoyance?

Real problem, but something rather unlikely to be tripped over in
the real world....

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

_______________________________________________
xfs mailing list
xfs@oss.sgi.com
http://oss.sgi.com/mailman/listinfo/xfs