xfssyncd and disk spin down

xfssyncd and disk spin down

[Petre Rodan]

[-- Attachment #1.1: Type: text/plain, Size: 3850 bytes --]


Hello,

I have a problem with a hard drive that never managed to spin down. this drive is a storage space, not a system disk, the only thing that generated writes is the nfs server that exports its contents. it has only one large xfs partition on it.

upon closer inspection it turns out that after the first Write action to that partition, an xfssyncd process continues to write to that partition each 36 seconds and it doesn't stop doing that, even if there are no more Writes from the exterior. this keeps the drive busy with varying consequences. more about that later.

I found that the only easy way to stop the xfssyncd process poking the drive is to run a `mount -o remount /mnt/space`. this will silence any internal xfs process to acessing the drive, thus allowing it to spin down and only be woken up by a NFS access.

here are some simple steps to replicate the problem:

# echo 3 > /proc/sys/vm/drop_caches # free cached fs entities 
# ( blktrace -d /dev/sdb -o - | blkparse -i - ) &
# mount -o remount /mnt/space
# find /mnt/space/ -type f > /dev/null  # generate some non-cached Read requests
# # absolutely no writes have been performed to the drive, 
# # it could spin down now if enough time would pass
# touch /mnt/space/foo
# # process 1352 will start writing to the drive at a 35-36s interval,
# # even if there has been no other write request.

  8,16   1    36591  6306.873151576  1352  A WBS 976985862 + 2 <- (8,17) 976985799
  8,16   1    36592  6306.873152998  1352  Q WBS 976985862 + 2 [xfssyncd/sdb1]
[..]
  8,16   1    36600  6342.875151286  1352  A WBS 976985864 + 2 <- (8,17) 976985801
  8,16   1    36601  6342.875152938  1352  Q WBS 976985864 + 2 [xfssyncd/sdb1]
[..]
  8,16   1    36609  6378.877225211  1352  A WBS 976985866 + 2 <- (8,17) 976985803
  8,16   1    36610  6378.877226935  1352  Q WBS 976985866 + 2 [xfssyncd/sdb1]

there was no file at or near the 976985799 inode (I presume that's an inode?)

I found that the only way to stop it is to remount the partition. I also tried sync(1), but to no avail. 

so is there an XFS option somewhere that would make the filesystem be more forgiving with the hardware beneath it? without loosing the journal of course.

I'm using a vanilla 2.6.36.2 kernel patched with grsecurity, default mkfs.xfs options, rw,nosuid,nodev,noexec,noatime,attr2,noquota mount options, and xfs_info looks like this:

meta-data=/dev/sdb1              isize=256    agcount=4, agsize=61047500 blks
         =                       sectsz=512   attr=2
data     =                       bsize=4096   blocks=244190000, imaxpct=25
         =                       sunit=0      swidth=0 blks
naming   =version 2              bsize=4096   ascii-ci=0
log      =internal               bsize=4096   blocks=32768, version=2
         =                       sectsz=512   sunit=0 blks, lazy-count=0
realtime =none                   extsz=4096   blocks=0, rtextents=0



a probably related issue is with modern Western Digital/Hitachi hard drives that use a Ramp load/unload technology that automatically parks the heads at stupidly small inactivity intervals (some small as 8 seconds), so look what happens when using such a drive and xfs:

# smartctl -a /dev/sda
[..]
Device Model:     WDC WD20EARS-00MVWB0
Serial Number:    WD-WCAZA0101731
Firmware Version: 50.0AB50
[..]
  4 Start_Stop_Count        0x0032   100   100   000    Old_age   Always       -       17
[..]
  9 Power_On_Hours          0x0032   096   096   000    Old_age   Always       -       3351
[..]
193 Load_Cycle_Count        0x0032   066   066   000    Old_age   Always       -       403405


this hard drive has exceeded it's 300k load/unload maximum from the specs in only 140 days, which means it was woken up every 30s or so. not willingly.

cheers,
peter


[-- Attachment #1.2: Type: application/pgp-signature, Size: 198 bytes --]

[-- Attachment #2: Type: text/plain, Size: 121 bytes --]

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

Re: xfssyncd and disk spin down

[Stan Hoeppner]

Petre Rodan put forth on 12/23/2010 10:55 AM:

> this hard drive has exceeded it's 300k load/unload maximum from the specs in only 140 days, which means it was woken up every 30s or so. not willingly.

Contact WD and request a warranty replacement for the drive due to
exceeding the spec'd cycle max in less than 6 months.  They may not
honor your request.  Whether they do or not, I'd replace the drive as
the mechanism obviously has too much wear on it already, and within one
year of use will have well over double the spec'd cycles.  If you
replace it with another 20EARS, replace the firmware immediately as
mentioned below to decrease the load/unload rate.  (It would be nice if
they offered the ability to disable the sleep mode totally, but then it
wouldn't be "green" pfft).

Modern drives consume so little power compared to CPUs and GPUs I can't
understand the big power save quest the HD industry has embarked upon,
especially with potential consequences to drive life you and others are
seeing.  I can understand the need WRT huge drive count enterprise near
line disk arrays, but not the average desktop or server.  And the EARS
series drives are anything but enterprise caliber.  Note the power specs
for the WD20EARS:

Current Requirements
	12 VDC
	Read/Write	296 mA
	Idle		243 mA
	Standby		3 mA
	Sleep		3 mA
	5 VDC
	Read/Write	503 mA
	Idle		172 mA
	Standby		160 mA
	Sleep		160 mA
	Power Dissipation
	Read/Write	6.00 Watts
	Idle		3.70 Watts
	Standby		0.80 Watts
	Sleep		0.80 Watts

6 watts maximum draw for read/write and 3.7 watts idle.  Sure, the sleep
mode consumes 10x less power, but when you're already at less than 4
watts idle it doesn't matter except in huge disk arrays.  For
comparison, your average dual core cpu today consumes an average of
20-50 watts or more.  Power supplies burn more wasted juice than
anything, so get a 90% efficiency PSU and disable all the power save
features of your disk drives to prolong their lifespan.

To replace the 20EARS firmware:

From:
http://community.wdc.com/t5/Desktop/Green-Caviar-High-Load-Cycle-Cout-after-short-operation-time/td-p/15731/page/2


Re: Green Caviar: High Load Cycle Count after short operation time

04-08-2010 04:03 PM

Sorry, but our agent didn't know that this policy was just changed.
Current WDIDLE3 works with the RE and GP drives listed below.

RE Drives - WD1000FYPS-01ZKB0, WD7500AYPS-01ZKB0, WD7501AYPS-01ZKB0

GP Drives - WD20EADS, WD20EARS, WD15EADS, WD15EARS, WD10EADS, WD10EARS,
WD8000AARS, WD7500AADS, WD7500AARS, WD6400AADS, WD6400AARS, WD5000AADS,
WD5000AARS

WDIDLE3

http://support.wdc.com/product/download.asp?groupid=609&sid=113&lang=en


-- 
Stan

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

Re: xfssyncd and disk spin down

[Petre Rodan]

Hello,

On Thu, Dec 23, 2010 at 01:29:14PM -0600, Stan Hoeppner wrote:
> Petre Rodan put forth on 12/23/2010 10:55 AM:
> 
> > this hard drive has exceeded it's 300k load/unload maximum from the specs in only 140 days, which means it was woken up every 30s or so. not willingly.
> 
> Contact WD and request a warranty replacement for the drive due to
> exceeding the spec'd cycle max in less than 6 months.  They may not
> honor your request.  Whether they do or not, I'd replace the drive as
> the mechanism obviously has too much wear on it already, and within one
> year of use will have well over double the spec'd cycles.  If you
> replace it with another 20EARS, replace the firmware immediately as
> mentioned below to decrease the load/unload rate.  (It would be nice if
> they offered the ability to disable the sleep mode totally, but then it
> wouldn't be "green" pfft).

thanks for your input. I did run wdidle3 on that drive two days ago stopping the nonsense.

but my original mail had a different target really. I have to recognize that I don't know much about the inner-workings of a filesystem, but I find it odd that once there is no input from the outside, a process keeps writing to the drive indefinitely. in my very narrow thinking the fact that these writes dissapear after a remount would prove their redundance.

to wrap it up, I see no logic to the above and this is why I ask the list to tell me if this is 

 a. something that can easily be fixed via an option I failed to find
 b. a critical part of xfs's internals that cannot be 'disabled' (with a short explanation)
 c. simply a bug

with the little side-story with the WD 20EARS i was just portraying where this default behaviour can get to. 
I don't usually read marketing material, but WD acknowledges that their green drives are wrecked in Linux and they simply encourage customers to change their OS. I just have to ask why have we got to get to this point.

the drive I was trying to get into standby in the first half of my mail is a different one, an enterprise ST31000340NS placed on an otherwise low power ProLiant MicroServer. Having 8W*12h*30 = 2880 Wh less to pay per hdd per month would be easily achievable if the standby mode would be reached when possible.

cheers,
peter

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

Re: xfssyncd and disk spin down

[Stan Hoeppner]

Petre Rodan put forth on 12/23/2010 3:16 PM:

> but my original mail had a different target really. I have to recognize that I don't know much about the inner-workings of a filesystem, but I find it odd that once there is no input from the outside, a process keeps writing to the drive indefinitely. in my very narrow thinking the fact that these writes dissapear after a remount would prove their redundance.

Ahh, quite right.  Sorry Petre.  This might shed some light on your
issue.  Old background thread:

http://oss.sgi.com/archives/xfs/2003-09/msg00674.html


Current documentation on this turnable knob:

http://www.mjmwired.net/kernel/Documentation/filesystems/xfs.txt

fs.xfs.xfssyncd_centisecs	(Min: 100  Default: 3000  Max: 720000)
	The interval at which the xfssyncd thread flushes metadata
	out to disk.  This thread will flush log activity out, and
	do some processing on unlinked inodes.

Maybe related or also worth mentioning:

fs.xfs.age_buffer_centisecs	(Min: 100  Default: 1500  Max: 720000)
	The age at which xfsbufd flushes dirty metadata buffers to disk.


As of 2.6.36, it looks like you can stretch this out to a more
reasonable (for your application) 12 minutes if you like.  I'm not sure
if the max value is different than 2.6.32.2 as I don't have a box or VM
available with 2.6.32.2.  Try bumping these values to 720000 and see if
that allows your disk to sleep for 12 mins.

-- 
Stan

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

Re: xfssyncd and disk spin down

[Stan Hoeppner]

Stan Hoeppner put forth on 12/23/2010 6:54 PM:

> http://www.mjmwired.net/kernel/Documentation/filesystems/xfs.txt
> 
> fs.xfs.xfssyncd_centisecs	(Min: 100  Default: 3000  Max: 720000)
> 	The interval at which the xfssyncd thread flushes metadata
> 	out to disk.  This thread will flush log activity out, and
> 	do some processing on unlinked inodes.
>
> Maybe related or also worth mentioning:
> 
> fs.xfs.age_buffer_centisecs	(Min: 100  Default: 1500  Max: 720000)
> 	The age at which xfsbufd flushes dirty metadata buffers to disk.

These can be found in /proc/sys/fs/xfs and you'd simply

~$ echo 720000 > /proc/sys/fs/xfs/xfssyncd_centisecs

to get the maximum 12 minute interval.

-- 
Stan

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

Re: xfssyncd and disk spin down

[Petre Rodan]

Hello Stan,

On Thu, Dec 23, 2010 at 06:54:19PM -0600, Stan Hoeppner wrote:
> Petre Rodan put forth on 12/23/2010 3:16 PM:
> 
> > but my original mail had a different target really. I have to recognize that I don't know much about the inner-workings of a filesystem, but I find it odd that once there is no input from the outside, a process keeps writing to the drive indefinitely. in my very narrow thinking the fact that these writes dissapear after a remount would prove their redundance.
> 
> Ahh, quite right.  Sorry Petre.  This might shed some light on your
> issue.  Old background thread:
> 
> http://oss.sgi.com/archives/xfs/2003-09/msg00674.html
> 
> Current documentation on this turnable knob:
> 
> http://www.mjmwired.net/kernel/Documentation/filesystems/xfs.txt

I appreciate your quick replies, but rest assured that I did search the archives and the documentation that came with the kernel.

I would be delighted to know the underlying reason why internal xfs processes need to flush things to the drive more than once. can't it be as easy as 

accept write command -> cache -> actual write to the hardware -> clean cache/log/dirty metadata -> sleep until next command comes (and not touch the drive in any way until then)

what am I missing in this picture? if anything needs to be flushed, why do it over and over again, once is not enough ?

what I found (see first mail from thread) is that a write to an xfs partition triggers an xfssyncd process to continually write to the drive for no apparent reason. and keeps writing at regulated intervals long after any other read or write request has been made from the outside. I left the drive untouched for 12 hours and xfssyncd was still pinging the drive. and there is no xfssyncd process pinging if I do not do initiate a write to the disk after the partition is mounted, so to me that means that xfs would function without constant writing to the underlying device.

> fs.xfs.xfssyncd_centisecs	(Min: 100  Default: 3000  Max: 720000)
> fs.xfs.age_buffer_centisecs	(Min: 100  Default: 1500  Max: 720000)

just increasing the delay until an inevitable and seemingly redundant disk write is not what I want.
I was searching for an option to make internal xfs processes not touch the drive after the buffers/log/dirty metadata have been flushed (once).

thanks,
peter

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

Re: xfssyncd and disk spin down

[Eric Sandeen]

On 12/23/10 10:55 AM, Petre Rodan wrote:
> 
> Hello,
> 
> I have a problem with a hard drive that never managed to spin down.
> this drive is a storage space, not a system disk, the only thing that
> generated writes is the nfs server that exports its contents. it has
> only one large xfs partition on it.
> 
> upon closer inspection it turns out that after the first Write action
> to that partition, an xfssyncd process continues to write to that
> partition each 36 seconds and it doesn't stop doing that, even if
> there are no more Writes from the exterior. this keeps the drive busy
> with varying consequences. more about that later.

Doesn't seem like that should happen.

> I found that the only easy way to stop the xfssyncd process poking
> the drive is to run a `mount -o remount /mnt/space`. this will
> silence any internal xfs process to acessing the drive, thus allowing
> it to spin down and only be woken up by a NFS access.
> 
> here are some simple steps to replicate the problem:
> 
> # echo 3 > /proc/sys/vm/drop_caches # free cached fs entities 
> # ( blktrace -d /dev/sdb -o - | blkparse -i - ) &
> # mount -o remount /mnt/space
> # find /mnt/space/ -type f > /dev/null  # generate some non-cached Read requests
> # # absolutely no writes have been performed to the drive, 
> # # it could spin down now if enough time would pass
> # touch /mnt/space/foo
> # # process 1352 will start writing to the drive at a 35-36s interval,
> # # even if there has been no other write request.
> 
>   8,16   1    36591  6306.873151576  1352  A WBS 976985862 + 2 <- (8,17) 976985799
>   8,16   1    36592  6306.873152998  1352  Q WBS 976985862 + 2 [xfssyncd/sdb1]
> [..]
>   8,16   1    36600  6342.875151286  1352  A WBS 976985864 + 2 <- (8,17) 976985801
>   8,16   1    36601  6342.875152938  1352  Q WBS 976985864 + 2 [xfssyncd/sdb1]
> [..]
>   8,16   1    36609  6378.877225211  1352  A WBS 976985866 + 2 <- (8,17) 976985803
>   8,16   1    36610  6378.877226935  1352  Q WBS 976985866 + 2 [xfssyncd/sdb1]
> 
> there was no file at or near the 976985799 inode (I presume that's an
> inode?)

Nope that's a sector on the drive.

> A WBS 976985862 + 2 <- (8,17) 976985799

976985799 is the sector on sdb1, mapped to 976985862 on sdb
(63 sectors in, yay dos partition tables!)

A means remapped (from sdb1 to sdb), Q means Queued.

WBS means Write/Barrier/Synchronous.

Also, you're stepping through, it looks like -
976985799, 976985801, 976985803, ....

> I found that the only way to stop it is to remount the partition. I
> also tried sync(1), but to no avail.
> 
> so is there an XFS option somewhere that would make the filesystem be
> more forgiving with the hardware beneath it? without loosing the
> journal of course.

I think we just need to figure out what's causing the writes, and
what's being written.
 
> I'm using a vanilla 2.6.36.2 kernel patched with grsecurity, default
> mkfs.xfs options, rw,nosuid,nodev,noexec,noatime,attr2,noquota mount
> options, and xfs_info looks like this:> 
> meta-data=/dev/sdb1              isize=256    agcount=4, agsize=61047500 blks
>          =                       sectsz=512   attr=2
> data     =                       bsize=4096   blocks=244190000, imaxpct=25
>          =                       sunit=0      swidth=0 blks
> naming   =version 2              bsize=4096   ascii-ci=0
> log      =internal               bsize=4096   blocks=32768, version=2
>          =                       sectsz=512   sunit=0 blks, lazy-count=0
> realtime =none                   extsz=4096   blocks=0, rtextents=0

so what is sector 976985799 on the filesystem...

An AG is 61047500 blocks long, or 488380000 sectors long.  There are 4 of them,
and the log is at the front of an AG in the middle of the fs.

So the 1st AG starts at 0, 2nd at 488380000 sectors, 3rd at 976760000 sectors.

Your writes are at 976985799-ish sectors, or 225799 sectors into the
3rd AG.  The log is 262144 sectors long.  So this looks like log writes.
Makes sense with the WBS data too.

xfssyncd forces the log, reclaims inodes, and logs a dummy transaction if needed.

On an idle fs though I wouldn't expect that we need any of this, so probably
need to dig a little to see what's going on.  I don't think you need a mount
option, I think we need an explanation and maybe a bugfix.  :)

I'll try to find time to look into it unless someone else knows what's going
on off the top of their heads.

-Eric

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

Re: xfssyncd and disk spin down

[Stan Hoeppner]

Petre Rodan put forth on 12/24/2010 12:02 AM:

>> fs.xfs.xfssyncd_centisecs	(Min: 100  Default: 3000  Max: 720000)
>> fs.xfs.age_buffer_centisecs	(Min: 100  Default: 1500  Max: 720000)
> 
> just increasing the delay until an inevitable and seemingly redundant disk write is not what I want.
> I was searching for an option to make internal xfs processes not touch the drive after the buffers/log/dirty metadata have been flushed (once).

I'm not a dev Petre but just another XFS user.  This is the best
"solution" I could come up with for your issue.  I assumed this
"unnecessary" regularly scheduled activity was a house cleaning measure
and done intentionally; didn't dawn on me that it may be a bug.

Sorry I wasn't able to fully address your issue.  If/until there is a
permanent fix for this you may want to bump this to 720000 anyway as an
interim measure, if you haven't already, as it should yield a
significantly better situation than what you have now.  You'll at least
get something like ~1400 minutes of sleep per day instead of none,
decreasing your load/unload cycles from ~2880/day to ~120/day, if my
math is correct.

-- 
Stan

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

Re: xfssyncd and disk spin down

[Eric Sandeen]

On 12/24/10 5:00 PM, Stan Hoeppner wrote:
> Petre Rodan put forth on 12/24/2010 12:02 AM:
> 
>>> fs.xfs.xfssyncd_centisecs	(Min: 100  Default: 3000  Max: 720000)
>>> fs.xfs.age_buffer_centisecs	(Min: 100  Default: 1500  Max: 720000)
>>
>> just increasing the delay until an inevitable and seemingly redundant disk write is not what I want.
>> I was searching for an option to make internal xfs processes not touch the drive after the buffers/log/dirty metadata have been flushed (once).
> 
> I'm not a dev Petre but just another XFS user.  This is the best
> "solution" I could come up with for your issue.  I assumed this
> "unnecessary" regularly scheduled activity was a house cleaning measure
> and done intentionally; didn't dawn on me that it may be a bug.
> 
> Sorry I wasn't able to fully address your issue.  If/until there is a
> permanent fix for this you may want to bump this to 720000 anyway as an
> interim measure, if you haven't already, as it should yield a
> significantly better situation than what you have now.  You'll at least
> get something like ~1400 minutes of sleep per day instead of none,
> decreasing your load/unload cycles from ~2880/day to ~120/day, if my
> math is correct.

Of course, then xfssyncd will not be doing its proper duty regularly ;)

We just need to see why it's always finding work to do when idle.

-Eric

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

Re: xfssyncd and disk spin down

[Stan Hoeppner]

Eric Sandeen put forth on 12/24/2010 9:36 PM:
> On 12/24/10 5:00 PM, Stan Hoeppner wrote:
>> Petre Rodan put forth on 12/24/2010 12:02 AM:
>>
>>>> fs.xfs.xfssyncd_centisecs	(Min: 100  Default: 3000  Max: 720000)
>>>> fs.xfs.age_buffer_centisecs	(Min: 100  Default: 1500  Max: 720000)
>>>
>>> just increasing the delay until an inevitable and seemingly redundant disk write is not what I want.
>>> I was searching for an option to make internal xfs processes not touch the drive after the buffers/log/dirty metadata have been flushed (once).
>>
>> I'm not a dev Petre but just another XFS user.  This is the best
>> "solution" I could come up with for your issue.  I assumed this
>> "unnecessary" regularly scheduled activity was a house cleaning measure
>> and done intentionally; didn't dawn on me that it may be a bug.
>>
>> Sorry I wasn't able to fully address your issue.  If/until there is a
>> permanent fix for this you may want to bump this to 720000 anyway as an
>> interim measure, if you haven't already, as it should yield a
>> significantly better situation than what you have now.  You'll at least
>> get something like ~1400 minutes of sleep per day instead of none,
>> decreasing your load/unload cycles from ~2880/day to ~120/day, if my
>> math is correct.
> 
> Of course, then xfssyncd will not be doing its proper duty regularly ;)

Sure it will.  Just not *as regularly*.  You, Dave, Alex, Christoph, or
someone made the regularity configurable didn't you? ;)

> We just need to see why it's always finding work to do when idle.

Seems like my grandmother must have been involved with the current code.
 She was always telling me "Idle hands are the Devil's work." ;)  Or,
whoever wrote the code was somehow influenced by my grandmother (his own).

-- 
Stan

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

Re: xfssyncd and disk spin down

[Petre Rodan]

[-- Attachment #1.1.1: Type: text/plain, Size: 3186 bytes --]


Hi Eric,

On Fri, Dec 24, 2010 at 12:17:54PM -0600, Eric Sandeen wrote:
> Doesn't seem like that should happen.

music to my ears :)
having this fixed would make me a happy bunny.

> >   8,16   1    36591  6306.873151576  1352  A WBS 976985862 + 2 <- (8,17) 976985799
> > 
> > there was no file at or near the 976985799 inode (I presume that's an
> > inode?)
> 
> Nope that's a sector on the drive.

great, this should make debugging easier.

> I think we just need to figure out what's causing the writes, and
> what's being written.

not sure about the first thing, but do read on for the "what's written" chapter:

# mount -o remount /dev/sdb1        # to start fresh with no xfssyncd's poking arround
# cp -r /usr/src/linux* /mnt/space  # do some writes to the drive, then let it completely unused for at least 30 minutes after the cp finished
                                    # at this point the only thing active on sdb1 is xfssyncd at 36s intervals
# bin/blk_debug.sh > /dev/shm/stdout

blk_debug.sh parses the output of blktrace, blkparse and for each line containing 'A WBS' it uses dd to save 8 sectors from sdb starting with the mapped value I get from blkparse

blktrace -d /dev/sdb -o - | blkparse -i - | while read line; do
    echo "${line}"
    grep -q 'A WBS' <<< ${line} && {
        sect=$(echo "${line}" | awk '{ print $8 }' )
        # fork a dd and let xfssyncd time to finish writing
        ( 
            sleep 20
            # force dd to read the drive, not a cache
            echo 3 > /proc/sys/vm/drop_caches
            dd if=/dev/sdb of=/dev/shm/dump_${sect} skip=${sect} bs=512 count=8 && \
            	echo "* sectors ${sect}-$((${sect}+8)) saved into dump_${sect}"
        ) &
    }

done


I thought that since xfssyncd writes to sectors in increments of 2 it would be possible to run a diff between 2 consecutive samples and get some information that may help you see something. I provide an attachment with the entire stdout, sector dumps and scripts. also available here: http://incoming.avira.com/NOSYNC/peter/xfssyncd_debug.tar.bz2

there might be a slight misalignment of a few sectors between dd's seek and where it's been told to go, look closely at the blkparse. apparently xfssyncd is not 'appending' information, it looks more like a bucketload of a similarly-looking array of data each time.

hope this helps, if there is anything amiss I could fix it and try again anytime.

> On an idle fs though I wouldn't expect that we need any of this, so probably
> need to dig a little to see what's going on.  I don't think you need a mount
> option, I think we need an explanation and maybe a bugfix.  :)
> 
> I'll try to find time to look into it unless someone else knows what's going
> on off the top of their heads.

thank you for your interest.
I'll be glad to test kernel patches against 2.6.36.2 that you might come up with.

@Stan, thanks for your input, it's nice to see friendly communities gathered arround a mailing list again.

Happy Holidays everyone.

cheers,
peter

-- 
petre rodan
<petre.rodan@simplex.ro>
Technical Manager
Simplex SRL, Bucharest

[-- Attachment #1.1.2: xfssyncd_debug.tar.bz2 --]
[-- Type: application/x-bzip2, Size: 26065 bytes --]

[-- Attachment #1.2: Type: application/pgp-signature, Size: 198 bytes --]

[-- Attachment #2: Type: text/plain, Size: 121 bytes --]

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

Re: xfssyncd and disk spin down

[Dave Chinner]

On Thu, Dec 23, 2010 at 06:55:32PM +0200, Petre Rodan wrote:
> 
> Hello,
> 
> I have a problem with a hard drive that never managed to spin
> down. this drive is a storage space, not a system disk, the only
> thing that generated writes is the nfs server that exports its
> contents. it has only one large xfs partition on it.
> 
> upon closer inspection it turns out that after the first Write
> action to that partition, an xfssyncd process continues to write
> to that partition each 36 seconds and it doesn't stop doing that,
> even if there are no more Writes from the exterior. this keeps the
> drive busy with varying consequences. more about that later.

Should be fixed in 2.6.37 by the commit:

1a387d3 xfs: dummy transactions should not dirty VFS state

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

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

Re: xfssyncd and disk spin down

[Petre Rodan]

[-- Attachment #1.1: Type: text/plain, Size: 1109 bytes --]


Hello Dave,

On Mon, Dec 27, 2010 at 01:19:04PM +1100, Dave Chinner wrote:
> On Thu, Dec 23, 2010 at 06:55:32PM +0200, Petre Rodan wrote:
> > 
> > Hello,
[..]
> > upon closer inspection it turns out that after the first Write
> > action to that partition, an xfssyncd process continues to write
> > to that partition each 36 seconds and it doesn't stop doing that,
> > even if there are no more Writes from the exterior. this keeps the
> > drive busy with varying consequences. more about that later.
> 
> Should be fixed in 2.6.37 by the commit:
> 
> 1a387d3 xfs: dummy transactions should not dirty VFS state

nice that someone else was also keen on having this bug fixed, but this particular fix is already present in 2.6.36 [1], [2]

unfortunately something is still written to the log every 36s, as per the first mail in this thread.

I guess we're getting closer.

[1] http://www.kernel.org/pub/linux/kernel/v2.6/ChangeLog-2.6.36
[2] http://git.kernel.org/?p=linux/kernel/git/stable/linux-2.6.36.y.git;a=commit;h=871eae4891a844e1fd065467b940f98dbf7aad1c


cheers,
peter


[-- Attachment #1.2: Type: application/pgp-signature, Size: 198 bytes --]

[-- Attachment #2: Type: text/plain, Size: 121 bytes --]

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

Re: xfssyncd and disk spin down

[Dave Chinner]

On Mon, Dec 27, 2010 at 08:16:29AM +0200, Petre Rodan wrote:
> 
> Hello Dave,
> 
> On Mon, Dec 27, 2010 at 01:19:04PM +1100, Dave Chinner wrote:
> > On Thu, Dec 23, 2010 at 06:55:32PM +0200, Petre Rodan wrote:
> > > 
> > > Hello,
> [..]
> > > upon closer inspection it turns out that after the first Write
> > > action to that partition, an xfssyncd process continues to write
> > > to that partition each 36 seconds and it doesn't stop doing that,
> > > even if there are no more Writes from the exterior. this keeps the
> > > drive busy with varying consequences. more about that later.
> > 
> > Should be fixed in 2.6.37 by the commit:
> > 
> > 1a387d3 xfs: dummy transactions should not dirty VFS state
> 
> nice that someone else was also keen on having this bug fixed, but this particular fix is already present in 2.6.36 [1], [2]
> 
> unfortunately something is still written to the log every 36s, as per the first mail in this thread.

Turn on the XFS tracing so we can see what is being written every
36s.  When the problem shows up:

# echo 1 > /sys/kernel/debug/tracing/events/xfs/enable
# sleep 100
# cat /sys/kernel/debug/tracing/trace > trace.out
# echo 0 > /sys/kernel/debug/tracing/events/xfs/enable

And post the trace.out file for us to look at.

Cheers,

Dave.



-- 
Dave Chinner
david@fromorbit.com

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

Re: xfssyncd and disk spin down

[Petre Rodan]

[-- Attachment #1.1.1: Type: text/plain, Size: 588 bytes --]


Hello Dave,

On Tue, Dec 28, 2010 at 01:07:50AM +1100, Dave Chinner wrote:
> Turn on the XFS tracing so we can see what is being written every
> 36s.  When the problem shows up:
> 
> # echo 1 > /sys/kernel/debug/tracing/events/xfs/enable
> # sleep 100
> # cat /sys/kernel/debug/tracing/trace > trace.out
> # echo 0 > /sys/kernel/debug/tracing/events/xfs/enable
> 
> And post the trace.out file for us to look at.

attached.

you can disregard all the lvm partitions ('dev 254:.*') since they are on a different drive, probably only 8:17 is of interest.

bye,
peter


[-- Attachment #1.1.2: trace.out.bz2 --]
[-- Type: application/x-bzip2, Size: 58764 bytes --]

[-- Attachment #1.2: Type: application/pgp-signature, Size: 198 bytes --]

[-- Attachment #2: Type: text/plain, Size: 121 bytes --]

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

Re: xfssyncd and disk spin down

[Dave Chinner]

On Mon, Dec 27, 2010 at 07:19:39PM +0200, Petre Rodan wrote:
> 
> Hello Dave,
> 
> On Tue, Dec 28, 2010 at 01:07:50AM +1100, Dave Chinner wrote:
> > Turn on the XFS tracing so we can see what is being written every
> > 36s.  When the problem shows up:
> > 
> > # echo 1 > /sys/kernel/debug/tracing/events/xfs/enable
> > # sleep 100
> > # cat /sys/kernel/debug/tracing/trace > trace.out
> > # echo 0 > /sys/kernel/debug/tracing/events/xfs/enable
> > 
> > And post the trace.out file for us to look at.
> 
> attached.
> 
> you can disregard all the lvm partitions ('dev 254:.*') since they are on a different drive, probably only 8:17 is of interest.

Ok, I can see the problem. The original patch I tested:

http://oss.sgi.com/archives/xfs/2010-08/msg00026.html

Made the log covering dummy transaction a synchronous transaction so
that the log was written and the superblock unpinned immediately to
allow the xfsbufd to write back the superblock and empty the AIL
before the next log covering check.

On review, the log covering dummy transaction got changed to an
async transaction, so the superblock buffer is not unpinned
immediately. This was the patch committed:

http://oss.sgi.com/archives/xfs/2010-08/msg00197.html

As a result, the success of log covering and idling is then
dependent on whether the log gets written to disk to unpin the
superblock buffer before the next xfssyncd run. It seems that there
is a large chance that this log write does not happen, so the
filesystem never idles correctly. I've reproduced it here, and only
in one test out of ten did the filesystem enter an idle state
correctly. I guess I was unlucky enough to hit that 1-in-10 case
when I tested the modified patch.

I'll cook up a patch to make the log covering behave like the
original patch I sent...

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

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

Re: xfssyncd and disk spin down

[Petre Rodan]

[-- Attachment #1.1.1: Type: text/plain, Size: 5808 bytes --]


hello Dave,

On Fri, Dec 31, 2010 at 11:13:23AM +1100, Dave Chinner wrote:
> On Mon, Dec 27, 2010 at 07:19:39PM +0200, Petre Rodan wrote:
> > 
> > Hello Dave,
> > 
> > On Tue, Dec 28, 2010 at 01:07:50AM +1100, Dave Chinner wrote:
> > > Turn on the XFS tracing so we can see what is being written every
> > > 36s.  When the problem shows up:
> > > 
> > > # echo 1 > /sys/kernel/debug/tracing/events/xfs/enable
> > > # sleep 100
> > > # cat /sys/kernel/debug/tracing/trace > trace.out
> > > # echo 0 > /sys/kernel/debug/tracing/events/xfs/enable
> > > 
> > > And post the trace.out file for us to look at.
> > 
> > attached.
> > 
> > you can disregard all the lvm partitions ('dev 254:.*') since they are on a different drive, probably only 8:17 is of interest.
> 
> Ok, I can see the problem. The original patch I tested:
> 
> http://oss.sgi.com/archives/xfs/2010-08/msg00026.html
> 
> Made the log covering dummy transaction a synchronous transaction so
> that the log was written and the superblock unpinned immediately to
> allow the xfsbufd to write back the superblock and empty the AIL
> before the next log covering check.
> 
> On review, the log covering dummy transaction got changed to an
> async transaction, so the superblock buffer is not unpinned
> immediately. This was the patch committed:
> 
> http://oss.sgi.com/archives/xfs/2010-08/msg00197.html
> 
> As a result, the success of log covering and idling is then
> dependent on whether the log gets written to disk to unpin the
> superblock buffer before the next xfssyncd run. It seems that there
> is a large chance that this log write does not happen, so the
> filesystem never idles correctly. I've reproduced it here, and only
> in one test out of ten did the filesystem enter an idle state
> correctly. I guess I was unlucky enough to hit that 1-in-10 case
> when I tested the modified patch.
> 
> I'll cook up a patch to make the log covering behave like the
> original patch I sent...

I presume that the new fix should be provided by "xfs: ensure log covering transactions are synchronous", so I tested 2.6.37 patched with it and then 2.6.38_rc1 that has it included.

instead of having xfssyncd write to the drive every 36s, we now have this:

  8,32   0      162   828.393976164  1413  A  WS 977599761 + 2 <- (8,33) 977597713
  8,32   0      163   828.393977820  1413  Q  WS 977599761 + 2 [xfssyncd/sdc1]
  8,32   0      167   846.401286530  1407  A   W 2048 + 1 <- (8,33) 0
  8,32   0      168   846.401288007  1407  Q   W 2048 + 1 [xfsbufd/sdc1]
  8,32   0      174   864.412155132  1413  A  WS 977599763 + 2 <- (8,33) 977597715
  8,32   0      175   864.412156637  1413  Q  WS 977599763 + 2 [xfssyncd/sdc1]
  8,32   1      240   882.467053566  1407  A   W 2048 + 1 <- (8,33) 0
  8,32   1      241   882.467055152  1407  Q   W 2048 + 1 [xfsbufd/sdc1]
  8,32   0      179   900.426084634  1413  A  WS 977599765 + 2 <- (8,33) 977597717
  8,32   0      180   900.426086076  1413  Q  WS 977599765 + 2 [xfssyncd/sdc1]
  8,32   0      185   918.457066312  1407  A   W 2048 + 1 <- (8,33) 0
  8,32   0      186   918.457068003  1407  Q   W 2048 + 1 [xfsbufd/sdc1]
  8,32   1      252   936.448120095  1413  A  WS 977599767 + 2 <- (8,33) 977597719
  8,32   1      253   936.448121740  1413  Q  WS 977599767 + 2 [xfssyncd/sdc1]
  8,32   0      192   954.447207652  1407  A   W 2048 + 1 <- (8,33) 0
  8,32   0      193   954.447209114  1407  Q   W 2048 + 1 [xfsbufd/sdc1]
  8,32   0      199   972.458423873  1413  A  WS 977599769 + 2 <- (8,33) 977597721
  8,32   0      200   972.458425189  1413  Q  WS 977599769 + 2 [xfssyncd/sdc1]
  8,32   1      266   990.457562449  1407  A   W 2048 + 1 <- (8,33) 0
  8,32   1      267   990.457563909  1407  Q   W 2048 + 1 [xfsbufd/sdc1]
  8,32   0      204  1008.476781955  1413  A  WS 977599771 + 2 <- (8,33) 977597723
  8,32   0      205  1008.476783410  1413  Q  WS 977599771 + 2 [xfssyncd/sdc1]
  8,32   1      278  1026.531988963  1407  A   W 2048 + 1 <- (8,33) 0
  8,32   1      279  1026.531990718  1407  Q   W 2048 + 1 [xfsbufd/sdc1]
  8,32   0      209  1044.491342417  1413  A  WS 977599773 + 2 <- (8,33) 977597725
  8,32   0      210  1044.491344042  1413  Q  WS 977599773 + 2 [xfssyncd/sdc1]
  8,32   0      214  1062.502603664  1407  A   W 2048 + 1 <- (8,33) 0
  8,32   0      215  1062.502605117  1407  Q   W 2048 + 1 [xfsbufd/sdc1]
  8,32   0      216  1062.502611005  1407  G   W 2048 + 1 [xfsbufd/sdc1]

in other words xfsyncd and xfsbufd now alternate at 18s intervals keeping the drive busy with nothing constructive hours after the last write to the drive.

to add to the misfortune, 'mount -o remount ' is no longer able to bring the drive to a quiet state since 2.6.37, so now the only way to achieve an idle drive is to fully umount and then remount the partition.

just for the record, this is a different drive then at the beginning of the thread, and it has these parameters:

meta-data=/dev/sdc1              isize=256    agcount=4, agsize=61047552 blks
         =                       sectsz=512   attr=2
data     =                       bsize=4096   blocks=244190208, imaxpct=25
         =                       sunit=0      swidth=0 blks
naming   =version 2              bsize=4096   ascii-ci=0
log      =internal               bsize=4096   blocks=119233, version=2
         =                       sectsz=512   sunit=0 blks, lazy-count=0
realtime =none                   extsz=4096   blocks=0, rtextents=0

attached you'll find the trace (with accesses to other drives filtered out).

cheers,
peter

> 
> Cheers,
> 
> Dave.
> -- 
> Dave Chinner
> david@fromorbit.com

-- 
petre rodan
<petre.rodan@simplex.ro>
Technical Manager
Simplex SRL, Bucharest

[-- Attachment #1.1.2: trace --]
[-- Type: text/plain, Size: 32402 bytes --]

# tracer: nop
#
#           TASK-PID    CPU#    TIMESTAMP  FUNCTION
#              | |       |          |         |
    xfsbufd/sdc1-1407  [000]  3328.516937: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  3328.516942: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  3329.715360: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  3329.715364: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  3330.913851: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  3330.913856: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  3332.112309: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  3332.112314: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  3333.310767: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  3333.310771: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  3334.509225: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  3334.509229: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  3335.707682: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  3335.707686: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  3336.906140: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  3336.906145: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  3338.104598: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  3338.104602: xfs_buf_delwri_split: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags WRITE|MAPPED|ASYNC|DONE|PAGES caller xfsbufd
    xfsbufd/sdc1-1407  [000]  3338.104605: xfs_buf_iorequest: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags WRITE|MAPPED|ASYNC|DONE|PAGES caller xfs_bdstrat_cb
    xfsbufd/sdc1-1407  [000]  3338.104606: xfs_buf_hold: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags WRITE|MAPPED|ASYNC|DONE|PAGES caller xfs_buf_iorequest
    xfsbufd/sdc1-1407  [000]  3338.104628: xfs_buf_rele: dev 8:33 bno 0x0 len 0x200 hold 4 pincount 0 lock 0 flags WRITE|MAPPED|ASYNC|DONE|PAGES caller xfs_buf_iorequest
          <idle>-0     [001]  3338.105096: xfs_buf_ioerror: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 error 0 flags WRITE|MAPPED|ASYNC|DONE|PAGES caller xfs_buf_bio_end_io
          <idle>-0     [001]  3338.105100: xfs_buf_iodone: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags WRITE|MAPPED|ASYNC|DONE|PAGES caller _xfs_buf_ioend
     kworker/1:0-2942  [001]  3338.105137: xfs_buf_rele: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|PAGES caller xfs_buf_iodone
     kworker/1:0-2942  [001]  3338.105139: xfs_buf_iodone: dev 8:33 bno 0x0 len 0x200 hold 2 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|PAGES caller xfs_buf_iodone_callbacks
     kworker/1:0-2942  [001]  3338.105141: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 2 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|PAGES caller xfs_buf_iodone_work
     kworker/1:0-2942  [001]  3338.105141: xfs_buf_rele: dev 8:33 bno 0x0 len 0x200 hold 2 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|PAGES caller xfs_buf_iodone_work
   xfssyncd/sdc1-1413  [000]  3356.093456: xfs_log_reserve: dev 8:33 type DUMMY1 t_ocnt 1 t_cnt 1 t_curr_res 2740 t_unit_res 2740 t_flags XLOG_TIC_INITED reserveq empty writeq empty grant_reserve_cycle 2 grant_reserve_bytes 428523008 grant_write_cycle 2 grant_write_bytes 428523008 curr_cycle 2 curr_block 836959 tail_cycle 2 tail_block 810683
   xfssyncd/sdc1-1413  [000]  3356.093462: xfs_log_grant_enter: dev 8:33 type DUMMY1 t_ocnt 1 t_cnt 1 t_curr_res 2740 t_unit_res 2740 t_flags XLOG_TIC_INITED reserveq empty writeq empty grant_reserve_cycle 2 grant_reserve_bytes 428523008 grant_write_cycle 2 grant_write_bytes 428523008 curr_cycle 2 curr_block 836959 tail_cycle 2 tail_block 810683
   xfssyncd/sdc1-1413  [000]  3356.093463: xfs_log_grant_exit: dev 8:33 type DUMMY1 t_ocnt 1 t_cnt 1 t_curr_res 2740 t_unit_res 2740 t_flags XLOG_TIC_INITED reserveq empty writeq empty grant_reserve_cycle 2 grant_reserve_bytes 428525748 grant_write_cycle 2 grant_write_bytes 428525748 curr_cycle 2 curr_block 836959 tail_cycle 2 tail_block 810683
   xfssyncd/sdc1-1413  [000]  3356.093465: xfs_buf_lock: dev 8:33 bno 0x0 len 0x200 hold 1 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|PAGES caller xfs_getsb
   xfssyncd/sdc1-1413  [000]  3356.093467: xfs_buf_lock_done: dev 8:33 bno 0x0 len 0x200 hold 1 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|PAGES caller xfs_getsb
   xfssyncd/sdc1-1413  [000]  3356.093468: xfs_buf_hold: dev 8:33 bno 0x0 len 0x200 hold 1 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|PAGES caller xfs_getsb
   xfssyncd/sdc1-1413  [000]  3356.093470: xfs_buf_hold: dev 8:33 bno 0x0 len 0x200 hold 2 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|PAGES caller xfs_buf_item_init
   xfssyncd/sdc1-1413  [000]  3356.093472: xfs_trans_getsb: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags |MAPPED|ASYNC|DONE|PAGES recur 0 refcount 1 bliflags  lidesc 0xffff8800dd23f8f0 liflags 
   xfssyncd/sdc1-1413  [000]  3356.093474: xfs_trans_log_buf: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags |MAPPED|ASYNC|DONE|DELWRI|PAGES recur 0 refcount 1 bliflags  lidesc 0xffff8800dd23f8f0 liflags 
   xfssyncd/sdc1-1413  [000]  3356.093477: xfs_buf_item_size: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags |MAPPED|ASYNC|DONE|DELWRI|PAGES recur 0 refcount 1 bliflags |DIRTY|LOGGED lidesc 0xffff8800dd23f8f0 liflags 
   xfssyncd/sdc1-1413  [000]  3356.093479: xfs_buf_item_format: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags |MAPPED|ASYNC|DONE|DELWRI|PAGES recur 0 refcount 1 bliflags |DIRTY|LOGGED lidesc 0xffff8800dd23f8f0 liflags 
   xfssyncd/sdc1-1413  [000]  3356.093480: xfs_buf_item_pin: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags |MAPPED|ASYNC|DONE|DELWRI|PAGES recur 0 refcount 1 bliflags |DIRTY|LOGGED lidesc 0xffff8800dd23f8f0 liflags 
   xfssyncd/sdc1-1413  [000]  3356.093487: xfs_log_done_nonperm: dev 8:33 type DUMMY1 t_ocnt 1 t_cnt 1 t_curr_res 2000 t_unit_res 2740 t_flags  reserveq empty writeq empty grant_reserve_cycle 2 grant_reserve_bytes 428525748 grant_write_cycle 2 grant_write_bytes 428525748 curr_cycle 2 curr_block 836959 tail_cycle 2 tail_block 810683
   xfssyncd/sdc1-1413  [000]  3356.093488: xfs_log_ungrant_enter: dev 8:33 type DUMMY1 t_ocnt 1 t_cnt 0 t_curr_res 2000 t_unit_res 2740 t_flags  reserveq empty writeq empty grant_reserve_cycle 2 grant_reserve_bytes 428525748 grant_write_cycle 2 grant_write_bytes 428525748 curr_cycle 2 curr_block 836959 tail_cycle 2 tail_block 810683
   xfssyncd/sdc1-1413  [000]  3356.093489: xfs_log_ungrant_sub: dev 8:33 type DUMMY1 t_ocnt 1 t_cnt 0 t_curr_res 2000 t_unit_res 2740 t_flags  reserveq empty writeq empty grant_reserve_cycle 2 grant_reserve_bytes 428525748 grant_write_cycle 2 grant_write_bytes 428525748 curr_cycle 2 curr_block 836959 tail_cycle 2 tail_block 810683
   xfssyncd/sdc1-1413  [000]  3356.093489: xfs_log_ungrant_exit: dev 8:33 type DUMMY1 t_ocnt 1 t_cnt 0 t_curr_res 2000 t_unit_res 2740 t_flags  reserveq empty writeq empty grant_reserve_cycle 2 grant_reserve_bytes 428523748 grant_write_cycle 2 grant_write_bytes 428523748 curr_cycle 2 curr_block 836959 tail_cycle 2 tail_block 810683
   xfssyncd/sdc1-1413  [000]  3356.093492: xfs_trans_commit_lsn: dev 8:33 trans 0xffff8800dd2b7ea0 commit_lsn 0x2000cc55f
   xfssyncd/sdc1-1413  [000]  3356.093495: xfs_buf_item_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 1 lock 0 flags |MAPPED|ASYNC|DONE|DELWRI|PAGES recur 0 refcount 2 bliflags |DIRTY lidesc 0x          (null) liflags 
   xfssyncd/sdc1-1413  [000]  3356.093496: xfs_buf_delwri_queue: dev 8:33 bno 0x0 len 0x200 hold 4 pincount 1 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES caller xfs_buf_unlock
   xfssyncd/sdc1-1413  [000]  3356.093501: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 4 pincount 1 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_item_unlock
   xfssyncd/sdc1-1413  [000]  3356.093502: xfs_buf_rele: dev 8:33 bno 0x0 len 0x200 hold 4 pincount 1 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_item_unlock
   xfssyncd/sdc1-1413  [000]  3356.093506: xfs_buf_iorequest: dev 8:33 bno 0x3a44f57f len 0x8000 hold 1 pincount 0 lock 0 flags WRITE|MAPPED|ASYNC|DONE|ORDERED|PAGES|RUN_QUEUES|0x2000 caller xlog_bdstrat
   xfssyncd/sdc1-1413  [000]  3356.093507: xfs_buf_hold: dev 8:33 bno 0x3a44f57f len 0x8000 hold 1 pincount 0 lock 0 flags WRITE|MAPPED|ASYNC|DONE|ORDERED|PAGES|RUN_QUEUES|0x2000 caller xfs_buf_iorequest
   xfssyncd/sdc1-1413  [000]  3356.093541: xfs_buf_rele: dev 8:33 bno 0x3a44f57f len 0x8000 hold 2 pincount 0 lock 0 flags WRITE|MAPPED|ASYNC|DONE|ORDERED|PAGES|RUN_QUEUES|0x2000 caller xfs_buf_iorequest
          <idle>-0     [001]  3356.113311: xfs_buf_ioerror: dev 8:33 bno 0x3a44f57f len 0x8000 hold 1 pincount 0 lock 0 error 0 flags WRITE|MAPPED|ASYNC|DONE|ORDERED|PAGES|RUN_QUEUES|0x2000 caller xfs_buf_bio_end_io
          <idle>-0     [001]  3356.113316: xfs_buf_iodone: dev 8:33 bno 0x3a44f57f len 0x8000 hold 1 pincount 0 lock 0 flags WRITE|MAPPED|ASYNC|DONE|ORDERED|PAGES|RUN_QUEUES|0x2000 caller _xfs_buf_ioend
     kworker/1:0-2942  [001]  3356.113359: xfs_buf_item_committed: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 1 lock 1 flags |MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q recur 0 refcount 1 bliflags |DIRTY lidesc 0x          (null) liflags 
     kworker/1:0-2942  [001]  3356.113362: xfs_buf_item_unpin: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 1 lock 1 flags |MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q recur 0 refcount 1 bliflags |DIRTY lidesc 0x          (null) liflags IN_AIL
    xfsbufd/sdc1-1407  [001]  3357.291895: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [001]  3357.291899: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [001]  3358.490410: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [001]  3358.490415: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [001]  3359.688802: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [001]  3359.688806: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [001]  3360.887269: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [001]  3360.887273: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [001]  3362.085688: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [001]  3362.085692: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [001]  3363.284175: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [001]  3363.284180: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [001]  3364.482639: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [001]  3364.482644: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [001]  3365.681096: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [001]  3365.681100: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  3366.879566: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  3366.879571: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  3368.078025: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  3368.078030: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  3369.276482: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  3369.276486: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  3370.474939: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  3370.474944: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  3371.673391: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  3371.673395: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  3372.871848: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  3372.871853: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  3374.070306: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  3374.070310: xfs_buf_delwri_split: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags WRITE|MAPPED|ASYNC|DONE|PAGES caller xfsbufd
    xfsbufd/sdc1-1407  [000]  3374.070312: xfs_buf_iorequest: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags WRITE|MAPPED|ASYNC|DONE|PAGES caller xfs_bdstrat_cb
    xfsbufd/sdc1-1407  [000]  3374.070314: xfs_buf_hold: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags WRITE|MAPPED|ASYNC|DONE|PAGES caller xfs_buf_iorequest
    xfsbufd/sdc1-1407  [000]  3374.070331: xfs_buf_rele: dev 8:33 bno 0x0 len 0x200 hold 4 pincount 0 lock 0 flags WRITE|MAPPED|ASYNC|DONE|PAGES caller xfs_buf_iorequest
          <idle>-0     [001]  3374.070797: xfs_buf_ioerror: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 error 0 flags WRITE|MAPPED|ASYNC|DONE|PAGES caller xfs_buf_bio_end_io
          <idle>-0     [001]  3374.070801: xfs_buf_iodone: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags WRITE|MAPPED|ASYNC|DONE|PAGES caller _xfs_buf_ioend
     kworker/1:0-2942  [001]  3374.070839: xfs_buf_rele: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|PAGES caller xfs_buf_iodone
     kworker/1:0-2942  [001]  3374.070841: xfs_buf_iodone: dev 8:33 bno 0x0 len 0x200 hold 2 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|PAGES caller xfs_buf_iodone_callbacks
     kworker/1:0-2942  [001]  3374.070843: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 2 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|PAGES caller xfs_buf_iodone_work
     kworker/1:0-2942  [001]  3374.070843: xfs_buf_rele: dev 8:33 bno 0x0 len 0x200 hold 2 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|PAGES caller xfs_buf_iodone_work
   xfssyncd/sdc1-1413  [000]  3392.067122: xfs_log_reserve: dev 8:33 type DUMMY1 t_ocnt 1 t_cnt 1 t_curr_res 2740 t_unit_res 2740 t_flags XLOG_TIC_INITED reserveq empty writeq empty grant_reserve_cycle 2 grant_reserve_bytes 428524032 grant_write_cycle 2 grant_write_bytes 428524032 curr_cycle 2 curr_block 836961 tail_cycle 2 tail_block 810683
   xfssyncd/sdc1-1413  [000]  3392.067127: xfs_log_grant_enter: dev 8:33 type DUMMY1 t_ocnt 1 t_cnt 1 t_curr_res 2740 t_unit_res 2740 t_flags XLOG_TIC_INITED reserveq empty writeq empty grant_reserve_cycle 2 grant_reserve_bytes 428524032 grant_write_cycle 2 grant_write_bytes 428524032 curr_cycle 2 curr_block 836961 tail_cycle 2 tail_block 810683
   xfssyncd/sdc1-1413  [000]  3392.067129: xfs_log_grant_exit: dev 8:33 type DUMMY1 t_ocnt 1 t_cnt 1 t_curr_res 2740 t_unit_res 2740 t_flags XLOG_TIC_INITED reserveq empty writeq empty grant_reserve_cycle 2 grant_reserve_bytes 428526772 grant_write_cycle 2 grant_write_bytes 428526772 curr_cycle 2 curr_block 836961 tail_cycle 2 tail_block 810683
   xfssyncd/sdc1-1413  [000]  3392.067131: xfs_buf_lock: dev 8:33 bno 0x0 len 0x200 hold 1 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|PAGES caller xfs_getsb
   xfssyncd/sdc1-1413  [000]  3392.067133: xfs_buf_lock_done: dev 8:33 bno 0x0 len 0x200 hold 1 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|PAGES caller xfs_getsb
   xfssyncd/sdc1-1413  [000]  3392.067134: xfs_buf_hold: dev 8:33 bno 0x0 len 0x200 hold 1 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|PAGES caller xfs_getsb
   xfssyncd/sdc1-1413  [000]  3392.067138: xfs_buf_hold: dev 8:33 bno 0x0 len 0x200 hold 2 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|PAGES caller xfs_buf_item_init
   xfssyncd/sdc1-1413  [000]  3392.067140: xfs_trans_getsb: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags |MAPPED|ASYNC|DONE|PAGES recur 0 refcount 1 bliflags  lidesc 0xffff8800dca401f0 liflags 
   xfssyncd/sdc1-1413  [000]  3392.067142: xfs_trans_log_buf: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags |MAPPED|ASYNC|DONE|DELWRI|PAGES recur 0 refcount 1 bliflags  lidesc 0xffff8800dca401f0 liflags 
   xfssyncd/sdc1-1413  [000]  3392.067145: xfs_buf_item_size: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags |MAPPED|ASYNC|DONE|DELWRI|PAGES recur 0 refcount 1 bliflags |DIRTY|LOGGED lidesc 0xffff8800dca401f0 liflags 
   xfssyncd/sdc1-1413  [000]  3392.067147: xfs_buf_item_format: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags |MAPPED|ASYNC|DONE|DELWRI|PAGES recur 0 refcount 1 bliflags |DIRTY|LOGGED lidesc 0xffff8800dca401f0 liflags 
   xfssyncd/sdc1-1413  [000]  3392.067148: xfs_buf_item_pin: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags |MAPPED|ASYNC|DONE|DELWRI|PAGES recur 0 refcount 1 bliflags |DIRTY|LOGGED lidesc 0xffff8800dca401f0 liflags 
   xfssyncd/sdc1-1413  [000]  3392.067154: xfs_log_done_nonperm: dev 8:33 type DUMMY1 t_ocnt 1 t_cnt 1 t_curr_res 2000 t_unit_res 2740 t_flags  reserveq empty writeq empty grant_reserve_cycle 2 grant_reserve_bytes 428526772 grant_write_cycle 2 grant_write_bytes 428526772 curr_cycle 2 curr_block 836961 tail_cycle 2 tail_block 810683
   xfssyncd/sdc1-1413  [000]  3392.067155: xfs_log_ungrant_enter: dev 8:33 type DUMMY1 t_ocnt 1 t_cnt 0 t_curr_res 2000 t_unit_res 2740 t_flags  reserveq empty writeq empty grant_reserve_cycle 2 grant_reserve_bytes 428526772 grant_write_cycle 2 grant_write_bytes 428526772 curr_cycle 2 curr_block 836961 tail_cycle 2 tail_block 810683
   xfssyncd/sdc1-1413  [000]  3392.067156: xfs_log_ungrant_sub: dev 8:33 type DUMMY1 t_ocnt 1 t_cnt 0 t_curr_res 2000 t_unit_res 2740 t_flags  reserveq empty writeq empty grant_reserve_cycle 2 grant_reserve_bytes 428526772 grant_write_cycle 2 grant_write_bytes 428526772 curr_cycle 2 curr_block 836961 tail_cycle 2 tail_block 810683
   xfssyncd/sdc1-1413  [000]  3392.067156: xfs_log_ungrant_exit: dev 8:33 type DUMMY1 t_ocnt 1 t_cnt 0 t_curr_res 2000 t_unit_res 2740 t_flags  reserveq empty writeq empty grant_reserve_cycle 2 grant_reserve_bytes 428524772 grant_write_cycle 2 grant_write_bytes 428524772 curr_cycle 2 curr_block 836961 tail_cycle 2 tail_block 810683
   xfssyncd/sdc1-1413  [000]  3392.067159: xfs_trans_commit_lsn: dev 8:33 trans 0xffff8800dca3a4c8 commit_lsn 0x2000cc561
   xfssyncd/sdc1-1413  [000]  3392.067161: xfs_buf_item_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 1 lock 0 flags |MAPPED|ASYNC|DONE|DELWRI|PAGES recur 0 refcount 2 bliflags |DIRTY lidesc 0x          (null) liflags 
   xfssyncd/sdc1-1413  [000]  3392.067163: xfs_buf_delwri_queue: dev 8:33 bno 0x0 len 0x200 hold 4 pincount 1 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES caller xfs_buf_unlock
   xfssyncd/sdc1-1413  [000]  3392.067168: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 4 pincount 1 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_item_unlock
   xfssyncd/sdc1-1413  [000]  3392.067169: xfs_buf_rele: dev 8:33 bno 0x0 len 0x200 hold 4 pincount 1 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_item_unlock
   xfssyncd/sdc1-1413  [000]  3392.067173: xfs_buf_iorequest: dev 8:33 bno 0x3a44f581 len 0x8000 hold 1 pincount 0 lock 0 flags WRITE|MAPPED|ASYNC|DONE|ORDERED|PAGES|RUN_QUEUES|0x2000 caller xlog_bdstrat
   xfssyncd/sdc1-1413  [000]  3392.067174: xfs_buf_hold: dev 8:33 bno 0x3a44f581 len 0x8000 hold 1 pincount 0 lock 0 flags WRITE|MAPPED|ASYNC|DONE|ORDERED|PAGES|RUN_QUEUES|0x2000 caller xfs_buf_iorequest
   xfssyncd/sdc1-1413  [000]  3392.067211: xfs_buf_rele: dev 8:33 bno 0x3a44f581 len 0x8000 hold 2 pincount 0 lock 0 flags WRITE|MAPPED|ASYNC|DONE|ORDERED|PAGES|RUN_QUEUES|0x2000 caller xfs_buf_iorequest
          <idle>-0     [001]  3392.084946: xfs_buf_ioerror: dev 8:33 bno 0x3a44f581 len 0x8000 hold 1 pincount 0 lock 0 error 0 flags WRITE|MAPPED|ASYNC|DONE|ORDERED|PAGES|RUN_QUEUES|0x2000 caller xfs_buf_bio_end_io
          <idle>-0     [001]  3392.084951: xfs_buf_iodone: dev 8:33 bno 0x3a44f581 len 0x8000 hold 1 pincount 0 lock 0 flags WRITE|MAPPED|ASYNC|DONE|ORDERED|PAGES|RUN_QUEUES|0x2000 caller _xfs_buf_ioend
     kworker/1:0-2942  [001]  3392.084986: xfs_buf_item_committed: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 1 lock 1 flags |MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q recur 0 refcount 1 bliflags |DIRTY lidesc 0x          (null) liflags 
     kworker/1:0-2942  [001]  3392.084989: xfs_buf_item_unpin: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 1 lock 1 flags |MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q recur 0 refcount 1 bliflags |DIRTY lidesc 0x          (null) liflags IN_AIL
    xfsbufd/sdc1-1407  [001]  3393.269554: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [001]  3393.269558: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [001]  3394.472001: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [001]  3394.472006: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [001]  3395.674456: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [001]  3395.674460: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [001]  3396.872917: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [001]  3396.872921: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  3398.071397: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  3398.071401: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  3399.269841: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  3399.269845: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  3400.468299: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  3400.468304: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  3401.666718: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  3401.666722: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  3402.865235: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  3402.865239: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  3404.063706: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  3404.063710: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  3405.262163: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  3405.262167: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  3406.460622: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  3406.460626: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  3407.659078: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  3407.659083: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  3408.857536: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  3408.857540: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  3410.055988: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  3410.055992: xfs_buf_delwri_split: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags WRITE|MAPPED|ASYNC|DONE|PAGES caller xfsbufd
    xfsbufd/sdc1-1407  [000]  3410.055995: xfs_buf_iorequest: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags WRITE|MAPPED|ASYNC|DONE|PAGES caller xfs_bdstrat_cb
    xfsbufd/sdc1-1407  [000]  3410.055996: xfs_buf_hold: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags WRITE|MAPPED|ASYNC|DONE|PAGES caller xfs_buf_iorequest
    xfsbufd/sdc1-1407  [000]  3410.056014: xfs_buf_rele: dev 8:33 bno 0x0 len 0x200 hold 4 pincount 0 lock 0 flags WRITE|MAPPED|ASYNC|DONE|PAGES caller xfs_buf_iorequest
          <idle>-0     [001]  3410.056482: xfs_buf_ioerror: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 error 0 flags WRITE|MAPPED|ASYNC|DONE|PAGES caller xfs_buf_bio_end_io
          <idle>-0     [001]  3410.056486: xfs_buf_iodone: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags WRITE|MAPPED|ASYNC|DONE|PAGES caller _xfs_buf_ioend
     kworker/1:0-2942  [001]  3410.056524: xfs_buf_rele: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|PAGES caller xfs_buf_iodone
     kworker/1:0-2942  [001]  3410.056526: xfs_buf_iodone: dev 8:33 bno 0x0 len 0x200 hold 2 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|PAGES caller xfs_buf_iodone_callbacks
     kworker/1:0-2942  [001]  3410.056527: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 2 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|PAGES caller xfs_buf_iodone_work
     kworker/1:0-2942  [001]  3410.056528: xfs_buf_rele: dev 8:33 bno 0x0 len 0x200 hold 2 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|PAGES caller xfs_buf_iodone_work

[-- Attachment #1.2: Type: application/pgp-signature, Size: 198 bytes --]

[-- Attachment #2: Type: text/plain, Size: 121 bytes --]

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

Re: xfssyncd and disk spin down

[Dave Chinner]

On Thu, Jan 20, 2011 at 12:01:43PM +0200, Petre Rodan wrote:
> On Fri, Dec 31, 2010 at 11:13:23AM +1100, Dave Chinner wrote:
> > On Mon, Dec 27, 2010 at 07:19:39PM +0200, Petre Rodan wrote:
> > > 
> > > Hello Dave,
> > > 
> > > On Tue, Dec 28, 2010 at 01:07:50AM +1100, Dave Chinner wrote:
> > > > Turn on the XFS tracing so we can see what is being written every
> > > > 36s.  When the problem shows up:
> > > > 
> > > > # echo 1 > /sys/kernel/debug/tracing/events/xfs/enable
> > > > # sleep 100
> > > > # cat /sys/kernel/debug/tracing/trace > trace.out
> > > > # echo 0 > /sys/kernel/debug/tracing/events/xfs/enable
> > > > 
> > > > And post the trace.out file for us to look at.
> > > 
> > > attached.
> > > 
> > > you can disregard all the lvm partitions ('dev 254:.*') since they are on a different drive, probably only 8:17 is of interest.
> > 
> > Ok, I can see the problem. The original patch I tested:
> > 
> > http://oss.sgi.com/archives/xfs/2010-08/msg00026.html
> > 
> > Made the log covering dummy transaction a synchronous transaction so
> > that the log was written and the superblock unpinned immediately to
> > allow the xfsbufd to write back the superblock and empty the AIL
> > before the next log covering check.
> > 
> > On review, the log covering dummy transaction got changed to an
> > async transaction, so the superblock buffer is not unpinned
> > immediately. This was the patch committed:
> > 
> > http://oss.sgi.com/archives/xfs/2010-08/msg00197.html
> > 
> > As a result, the success of log covering and idling is then
> > dependent on whether the log gets written to disk to unpin the
> > superblock buffer before the next xfssyncd run. It seems that there
> > is a large chance that this log write does not happen, so the
> > filesystem never idles correctly. I've reproduced it here, and only
> > in one test out of ten did the filesystem enter an idle state
> > correctly. I guess I was unlucky enough to hit that 1-in-10 case
> > when I tested the modified patch.
> > 
> > I'll cook up a patch to make the log covering behave like the
> > original patch I sent...
> 
> I presume that the new fix should be provided by "xfs: ensure log
> covering transactions are synchronous", so I tested 2.6.37 patched
> with it and then 2.6.38_rc1 that has it included..
> 
> instead of having xfssyncd write to the drive every 36s, we now have this:
....
> in other words xfsyncd and xfsbufd now alternate at 18s intervals
> keeping the drive busy with nothing constructive hours after the
> last write to the drive.
> 
> to add to the misfortune, 'mount -o remount ' is no longer able to
> bring the drive to a quiet state since 2.6.37, so now the only way
> to achieve an idle drive is to fully umount and then remount the
> partition.
> 
> just for the record, this is a different drive then at the
> beginning of the thread, and it has these parameters:
> 
> meta-data=/dev/sdc1              isize=256    agcount=4, agsize=61047552 blks
>          =                       sectsz=512   attr=2
> data     =                       bsize=4096   blocks=244190208, imaxpct=25
>          =                       sunit=0      swidth=0 blks
> naming   =version 2              bsize=4096   ascii-ci=0
> log      =internal               bsize=4096   blocks=119233, version=2
>          =                       sectsz=512   sunit=0 blks, lazy-count=0
                                                              ^^^^^^^^^^^^
> realtime =none                   extsz=4096   blocks=0, rtextents=0
> 
> attached you'll find the trace (with accesses to other drives filtered out).

It's something to do with lazy-count=0. I'm look into it when I get
the chance - I almost never test w/ lazy-count=0 because =1 is
the default value.

I'd recommend that you convert the fs to lazy-count=1 when you get a
chance, anyway, because of the fact it reduces the latency of
transactions significantly...

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

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

Re: xfssyncd and disk spin down

[Petre Rodan]

[-- Attachment #1.1.1: Type: text/plain, Size: 2706 bytes --]


Hello Dave,

On Thu, Jan 20, 2011 at 10:06:05PM +1100, Dave Chinner wrote:
> ....
> > in other words xfsyncd and xfsbufd now alternate at 18s intervals
> > keeping the drive busy with nothing constructive hours after the
> > last write to the drive.
[..]
> > meta-data=/dev/sdc1              isize=256    agcount=4, agsize=61047552 blks
> >          =                       sectsz=512   attr=2
> > data     =                       bsize=4096   blocks=244190208, imaxpct=25
> >          =                       sunit=0      swidth=0 blks
> > naming   =version 2              bsize=4096   ascii-ci=0
> > log      =internal               bsize=4096   blocks=119233, version=2
> >          =                       sectsz=512   sunit=0 blks, lazy-count=0
>                                                               ^^^^^^^^^^^^
> > realtime =none                   extsz=4096   blocks=0, rtextents=0
> 
> It's something to do with lazy-count=0. I'm look into it when I get
> the chance - I almost never test w/ lazy-count=0 because =1 is
> the default value.

thanks for the tip. looks like I'm using xfsprogs 3.0.3 (latest version in the gentoo stable tree) to mkfs these filesystems. can the antique version be somehow the root of the problem?

anyhow, changed it to:

meta-data=/dev/sdc1              isize=256    agcount=4, agsize=61047552 blks
         =                       sectsz=512   attr=2
data     =                       bsize=4096   blocks=244190208, imaxpct=25
         =                       sunit=0      swidth=0 blks
naming   =version 2              bsize=4096   ascii-ci=0
log      =internal               bsize=4096   blocks=119233, version=2
         =                       sectsz=512   sunit=0 blks, lazy-count=1
realtime =none                   extsz=4096   blocks=0, rtextents=0

used:
xfsprogs-3.0.3
Linux starshine 2.6.38-rc1-s001 #1 SMP Thu Jan 20 10:49:20 EET 2011 x86_64 AMD Athlon(tm) II Neo N36L Dual-Core Processor AuthenticAMD GNU/Linux
Seagate Barracuda ES.2 ST31000340NS
Hitachi HUA722020ALA330
default (for 3.0.3 xfsprogs) mkfs options, 'noatime,nodev,nosuid,noexec' as mount options.

and the behaviour did not change at all, trace attached.

it's very easy to reproduce this. all it took was

reboot
cp -a /usr/src/linux* /mnt/foo
sleep 1800
grab trace


cheers,
peter


> 
> I'd recommend that you convert the fs to lazy-count=1 when you get a
> chance, anyway, because of the fact it reduces the latency of
> transactions significantly...
> 
> Cheers,
> 
> Dave.
> -- 
> Dave Chinner
> david@fromorbit.com

-- 
petre rodan
<petre.rodan@simplex.ro>
Technical Manager
Simplex SRL, Bucharest

[-- Attachment #1.1.2: trace --]
[-- Type: text/plain, Size: 38464 bytes --]

# tracer: nop
#
#           TASK-PID    CPU#    TIMESTAMP  FUNCTION
#              | |       |          |         |
   xfssyncd/sdc1-1409  [000]  2198.419444: xfs_log_reserve: dev 8:33 type DUMMY1 t_ocnt 1 t_cnt 1 t_curr_res 2740 t_unit_res 2740 t_flags XLOG_TIC_INITED reserveq empty writeq empty grant_reserve_cycle 1 grant_reserve_bytes 45622272 grant_write_cycle 1 grant_write_bytes 45622272 curr_cycle 1 curr_block 89106 tail_cycle 1 tail_block 35956
   xfssyncd/sdc1-1409  [000]  2198.419449: xfs_log_grant_enter: dev 8:33 type DUMMY1 t_ocnt 1 t_cnt 1 t_curr_res 2740 t_unit_res 2740 t_flags XLOG_TIC_INITED reserveq empty writeq empty grant_reserve_cycle 1 grant_reserve_bytes 45622272 grant_write_cycle 1 grant_write_bytes 45622272 curr_cycle 1 curr_block 89106 tail_cycle 1 tail_block 35956
   xfssyncd/sdc1-1409  [000]  2198.419451: xfs_log_grant_exit: dev 8:33 type DUMMY1 t_ocnt 1 t_cnt 1 t_curr_res 2740 t_unit_res 2740 t_flags XLOG_TIC_INITED reserveq empty writeq empty grant_reserve_cycle 1 grant_reserve_bytes 45625012 grant_write_cycle 1 grant_write_bytes 45625012 curr_cycle 1 curr_block 89106 tail_cycle 1 tail_block 35956
   xfssyncd/sdc1-1409  [000]  2198.419453: xfs_buf_lock: dev 8:33 bno 0x0 len 0x200 hold 1 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|PAGES caller xfs_getsb
   xfssyncd/sdc1-1409  [000]  2198.419455: xfs_buf_lock_done: dev 8:33 bno 0x0 len 0x200 hold 1 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|PAGES caller xfs_getsb
   xfssyncd/sdc1-1409  [000]  2198.419456: xfs_buf_hold: dev 8:33 bno 0x0 len 0x200 hold 1 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|PAGES caller xfs_getsb
   xfssyncd/sdc1-1409  [000]  2198.419458: xfs_buf_hold: dev 8:33 bno 0x0 len 0x200 hold 2 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|PAGES caller xfs_buf_item_init
   xfssyncd/sdc1-1409  [000]  2198.419460: xfs_trans_getsb: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags |MAPPED|ASYNC|DONE|PAGES recur 0 refcount 1 bliflags  lidesc 0xffff880106b4b570 liflags 
   xfssyncd/sdc1-1409  [000]  2198.419462: xfs_trans_log_buf: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags |MAPPED|ASYNC|DONE|DELWRI|PAGES recur 0 refcount 1 bliflags  lidesc 0xffff880106b4b570 liflags 
   xfssyncd/sdc1-1409  [000]  2198.419465: xfs_buf_item_size: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags |MAPPED|ASYNC|DONE|DELWRI|PAGES recur 0 refcount 1 bliflags |DIRTY|LOGGED lidesc 0xffff880106b4b570 liflags 
   xfssyncd/sdc1-1409  [000]  2198.419467: xfs_buf_item_format: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags |MAPPED|ASYNC|DONE|DELWRI|PAGES recur 0 refcount 1 bliflags |DIRTY|LOGGED lidesc 0xffff880106b4b570 liflags 
   xfssyncd/sdc1-1409  [000]  2198.419468: xfs_buf_item_pin: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags |MAPPED|ASYNC|DONE|DELWRI|PAGES recur 0 refcount 1 bliflags |DIRTY|LOGGED lidesc 0xffff880106b4b570 liflags 
   xfssyncd/sdc1-1409  [000]  2198.419474: xfs_log_done_nonperm: dev 8:33 type DUMMY1 t_ocnt 1 t_cnt 1 t_curr_res 2000 t_unit_res 2740 t_flags  reserveq empty writeq empty grant_reserve_cycle 1 grant_reserve_bytes 45625012 grant_write_cycle 1 grant_write_bytes 45625012 curr_cycle 1 curr_block 89106 tail_cycle 1 tail_block 35956
   xfssyncd/sdc1-1409  [000]  2198.419475: xfs_log_ungrant_enter: dev 8:33 type DUMMY1 t_ocnt 1 t_cnt 0 t_curr_res 2000 t_unit_res 2740 t_flags  reserveq empty writeq empty grant_reserve_cycle 1 grant_reserve_bytes 45625012 grant_write_cycle 1 grant_write_bytes 45625012 curr_cycle 1 curr_block 89106 tail_cycle 1 tail_block 35956
   xfssyncd/sdc1-1409  [000]  2198.419476: xfs_log_ungrant_sub: dev 8:33 type DUMMY1 t_ocnt 1 t_cnt 0 t_curr_res 2000 t_unit_res 2740 t_flags  reserveq empty writeq empty grant_reserve_cycle 1 grant_reserve_bytes 45625012 grant_write_cycle 1 grant_write_bytes 45625012 curr_cycle 1 curr_block 89106 tail_cycle 1 tail_block 35956
   xfssyncd/sdc1-1409  [000]  2198.419476: xfs_log_ungrant_exit: dev 8:33 type DUMMY1 t_ocnt 1 t_cnt 0 t_curr_res 2000 t_unit_res 2740 t_flags  reserveq empty writeq empty grant_reserve_cycle 1 grant_reserve_bytes 45623012 grant_write_cycle 1 grant_write_bytes 45623012 curr_cycle 1 curr_block 89106 tail_cycle 1 tail_block 35956
   xfssyncd/sdc1-1409  [000]  2198.419479: xfs_trans_commit_lsn: dev 8:33 trans 0xffff880101c58b58 commit_lsn 0x100015c12
   xfssyncd/sdc1-1409  [000]  2198.419482: xfs_buf_item_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 1 lock 0 flags |MAPPED|ASYNC|DONE|DELWRI|PAGES recur 0 refcount 2 bliflags |DIRTY lidesc 0x          (null) liflags 
   xfssyncd/sdc1-1409  [000]  2198.419483: xfs_buf_delwri_queue: dev 8:33 bno 0x0 len 0x200 hold 4 pincount 1 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES caller xfs_buf_unlock
   xfssyncd/sdc1-1409  [000]  2198.419488: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 4 pincount 1 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_item_unlock
   xfssyncd/sdc1-1409  [000]  2198.419489: xfs_buf_rele: dev 8:33 bno 0x0 len 0x200 hold 4 pincount 1 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_item_unlock
   xfssyncd/sdc1-1409  [000]  2198.419493: xfs_buf_iorequest: dev 8:33 bno 0x3a398c32 len 0x8000 hold 1 pincount 0 lock 0 flags WRITE|MAPPED|ASYNC|DONE|ORDERED|PAGES|RUN_QUEUES|0x2000 caller xlog_bdstrat
   xfssyncd/sdc1-1409  [000]  2198.419494: xfs_buf_hold: dev 8:33 bno 0x3a398c32 len 0x8000 hold 1 pincount 0 lock 0 flags WRITE|MAPPED|ASYNC|DONE|ORDERED|PAGES|RUN_QUEUES|0x2000 caller xfs_buf_iorequest
   xfssyncd/sdc1-1409  [000]  2198.419530: xfs_buf_rele: dev 8:33 bno 0x3a398c32 len 0x8000 hold 2 pincount 0 lock 0 flags WRITE|MAPPED|ASYNC|DONE|ORDERED|PAGES|RUN_QUEUES|0x2000 caller xfs_buf_iorequest
          <idle>-0     [000]  2198.439397: xfs_buf_ioerror: dev 8:33 bno 0x3a398c32 len 0x8000 hold 1 pincount 0 lock 0 error 0 flags WRITE|MAPPED|ASYNC|DONE|ORDERED|PAGES|RUN_QUEUES|0x2000 caller xfs_buf_bio_end_io
          <idle>-0     [000]  2198.439402: xfs_buf_iodone: dev 8:33 bno 0x3a398c32 len 0x8000 hold 1 pincount 0 lock 0 flags WRITE|MAPPED|ASYNC|DONE|ORDERED|PAGES|RUN_QUEUES|0x2000 caller _xfs_buf_ioend
     kworker/0:1-10    [000]  2198.439444: xfs_buf_item_committed: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 1 lock 1 flags |MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q recur 0 refcount 1 bliflags |DIRTY lidesc 0x          (null) liflags 
     kworker/0:1-10    [000]  2198.439447: xfs_buf_item_unpin: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 1 lock 1 flags |MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q recur 0 refcount 1 bliflags |DIRTY lidesc 0x          (null) liflags IN_AIL
    xfsbufd/sdc1-1407  [001]  2199.621878: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [001]  2199.621882: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [001]  2200.824324: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [001]  2200.824329: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [001]  2202.026783: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [001]  2202.026787: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [001]  2203.229229: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [001]  2203.229233: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [001]  2204.431687: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [001]  2204.431692: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [001]  2205.634134: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [001]  2205.634139: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [001]  2206.836595: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [001]  2206.836600: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [001]  2208.039039: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [001]  2208.039044: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [001]  2209.241491: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [001]  2209.241495: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [001]  2210.443954: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [001]  2210.443959: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [001]  2211.646365: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [001]  2211.646370: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [001]  2212.844825: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [001]  2212.844830: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [001]  2214.043282: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [001]  2214.043287: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [001]  2215.241740: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [001]  2215.241745: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [001]  2216.440198: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [001]  2216.440201: xfs_buf_delwri_split: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags WRITE|MAPPED|ASYNC|DONE|PAGES caller xfsbufd
    xfsbufd/sdc1-1407  [001]  2216.440204: xfs_buf_iorequest: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags WRITE|MAPPED|ASYNC|DONE|PAGES caller xfs_bdstrat_cb
    xfsbufd/sdc1-1407  [001]  2216.440205: xfs_buf_hold: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags WRITE|MAPPED|ASYNC|DONE|PAGES caller xfs_buf_iorequest
    xfsbufd/sdc1-1407  [001]  2216.440224: xfs_buf_rele: dev 8:33 bno 0x0 len 0x200 hold 4 pincount 0 lock 0 flags WRITE|MAPPED|ASYNC|DONE|PAGES caller xfs_buf_iorequest
          <idle>-0     [001]  2216.440695: xfs_buf_ioerror: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 error 0 flags WRITE|MAPPED|ASYNC|DONE|PAGES caller xfs_buf_bio_end_io
          <idle>-0     [001]  2216.440700: xfs_buf_iodone: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags WRITE|MAPPED|ASYNC|DONE|PAGES caller _xfs_buf_ioend
     kworker/1:2-1448  [001]  2216.440737: xfs_buf_rele: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|PAGES caller xfs_buf_iodone
     kworker/1:2-1448  [001]  2216.440739: xfs_buf_iodone: dev 8:33 bno 0x0 len 0x200 hold 2 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|PAGES caller xfs_buf_iodone_callbacks
     kworker/1:2-1448  [001]  2216.440740: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 2 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|PAGES caller xfs_buf_iodone_work
     kworker/1:2-1448  [001]  2216.440741: xfs_buf_rele: dev 8:33 bno 0x0 len 0x200 hold 2 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|PAGES caller xfs_buf_iodone_work
   xfssyncd/sdc1-1409  [001]  2234.393111: xfs_log_reserve: dev 8:33 type DUMMY1 t_ocnt 1 t_cnt 1 t_curr_res 2740 t_unit_res 2740 t_flags XLOG_TIC_INITED reserveq empty writeq empty grant_reserve_cycle 1 grant_reserve_bytes 45623296 grant_write_cycle 1 grant_write_bytes 45623296 curr_cycle 1 curr_block 89108 tail_cycle 1 tail_block 35956
   xfssyncd/sdc1-1409  [001]  2234.393113: xfs_log_grant_enter: dev 8:33 type DUMMY1 t_ocnt 1 t_cnt 1 t_curr_res 2740 t_unit_res 2740 t_flags XLOG_TIC_INITED reserveq empty writeq empty grant_reserve_cycle 1 grant_reserve_bytes 45623296 grant_write_cycle 1 grant_write_bytes 45623296 curr_cycle 1 curr_block 89108 tail_cycle 1 tail_block 35956
   xfssyncd/sdc1-1409  [001]  2234.393115: xfs_log_grant_exit: dev 8:33 type DUMMY1 t_ocnt 1 t_cnt 1 t_curr_res 2740 t_unit_res 2740 t_flags XLOG_TIC_INITED reserveq empty writeq empty grant_reserve_cycle 1 grant_reserve_bytes 45626036 grant_write_cycle 1 grant_write_bytes 45626036 curr_cycle 1 curr_block 89108 tail_cycle 1 tail_block 35956
   xfssyncd/sdc1-1409  [001]  2234.393117: xfs_buf_lock: dev 8:33 bno 0x0 len 0x200 hold 1 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|PAGES caller xfs_getsb
   xfssyncd/sdc1-1409  [001]  2234.393118: xfs_buf_lock_done: dev 8:33 bno 0x0 len 0x200 hold 1 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|PAGES caller xfs_getsb
   xfssyncd/sdc1-1409  [001]  2234.393119: xfs_buf_hold: dev 8:33 bno 0x0 len 0x200 hold 1 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|PAGES caller xfs_getsb
   xfssyncd/sdc1-1409  [001]  2234.393122: xfs_buf_hold: dev 8:33 bno 0x0 len 0x200 hold 2 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|PAGES caller xfs_buf_item_init
   xfssyncd/sdc1-1409  [001]  2234.393123: xfs_trans_getsb: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags |MAPPED|ASYNC|DONE|PAGES recur 0 refcount 1 bliflags  lidesc 0xffff880101f1f370 liflags 
   xfssyncd/sdc1-1409  [001]  2234.393125: xfs_trans_log_buf: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags |MAPPED|ASYNC|DONE|DELWRI|PAGES recur 0 refcount 1 bliflags  lidesc 0xffff880101f1f370 liflags 
   xfssyncd/sdc1-1409  [001]  2234.393128: xfs_buf_item_size: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags |MAPPED|ASYNC|DONE|DELWRI|PAGES recur 0 refcount 1 bliflags |DIRTY|LOGGED lidesc 0xffff880101f1f370 liflags 
   xfssyncd/sdc1-1409  [001]  2234.393130: xfs_buf_item_format: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags |MAPPED|ASYNC|DONE|DELWRI|PAGES recur 0 refcount 1 bliflags |DIRTY|LOGGED lidesc 0xffff880101f1f370 liflags 
   xfssyncd/sdc1-1409  [001]  2234.393131: xfs_buf_item_pin: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags |MAPPED|ASYNC|DONE|DELWRI|PAGES recur 0 refcount 1 bliflags |DIRTY|LOGGED lidesc 0xffff880101f1f370 liflags 
   xfssyncd/sdc1-1409  [001]  2234.393137: xfs_log_done_nonperm: dev 8:33 type DUMMY1 t_ocnt 1 t_cnt 1 t_curr_res 2000 t_unit_res 2740 t_flags  reserveq empty writeq empty grant_reserve_cycle 1 grant_reserve_bytes 45626036 grant_write_cycle 1 grant_write_bytes 45626036 curr_cycle 1 curr_block 89108 tail_cycle 1 tail_block 35956
   xfssyncd/sdc1-1409  [001]  2234.393138: xfs_log_ungrant_enter: dev 8:33 type DUMMY1 t_ocnt 1 t_cnt 0 t_curr_res 2000 t_unit_res 2740 t_flags  reserveq empty writeq empty grant_reserve_cycle 1 grant_reserve_bytes 45626036 grant_write_cycle 1 grant_write_bytes 45626036 curr_cycle 1 curr_block 89108 tail_cycle 1 tail_block 35956
   xfssyncd/sdc1-1409  [001]  2234.393140: xfs_log_ungrant_sub: dev 8:33 type DUMMY1 t_ocnt 1 t_cnt 0 t_curr_res 2000 t_unit_res 2740 t_flags  reserveq empty writeq empty grant_reserve_cycle 1 grant_reserve_bytes 45626036 grant_write_cycle 1 grant_write_bytes 45626036 curr_cycle 1 curr_block 89108 tail_cycle 1 tail_block 35956
   xfssyncd/sdc1-1409  [001]  2234.393141: xfs_log_ungrant_exit: dev 8:33 type DUMMY1 t_ocnt 1 t_cnt 0 t_curr_res 2000 t_unit_res 2740 t_flags  reserveq empty writeq empty grant_reserve_cycle 1 grant_reserve_bytes 45624036 grant_write_cycle 1 grant_write_bytes 45624036 curr_cycle 1 curr_block 89108 tail_cycle 1 tail_block 35956
   xfssyncd/sdc1-1409  [001]  2234.393143: xfs_trans_commit_lsn: dev 8:33 trans 0xffff88011da67b58 commit_lsn 0x100015c14
   xfssyncd/sdc1-1409  [001]  2234.393146: xfs_buf_item_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 1 lock 0 flags |MAPPED|ASYNC|DONE|DELWRI|PAGES recur 0 refcount 2 bliflags |DIRTY lidesc 0x          (null) liflags 
   xfssyncd/sdc1-1409  [001]  2234.393147: xfs_buf_delwri_queue: dev 8:33 bno 0x0 len 0x200 hold 4 pincount 1 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES caller xfs_buf_unlock
   xfssyncd/sdc1-1409  [001]  2234.393152: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 4 pincount 1 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_item_unlock
   xfssyncd/sdc1-1409  [001]  2234.393153: xfs_buf_rele: dev 8:33 bno 0x0 len 0x200 hold 4 pincount 1 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_item_unlock
   xfssyncd/sdc1-1409  [001]  2234.393157: xfs_buf_iorequest: dev 8:33 bno 0x3a398c34 len 0x8000 hold 1 pincount 0 lock 0 flags WRITE|MAPPED|ASYNC|DONE|ORDERED|PAGES|RUN_QUEUES|0x2000 caller xlog_bdstrat
   xfssyncd/sdc1-1409  [001]  2234.393158: xfs_buf_hold: dev 8:33 bno 0x3a398c34 len 0x8000 hold 1 pincount 0 lock 0 flags WRITE|MAPPED|ASYNC|DONE|ORDERED|PAGES|RUN_QUEUES|0x2000 caller xfs_buf_iorequest
   xfssyncd/sdc1-1409  [001]  2234.393194: xfs_buf_rele: dev 8:33 bno 0x3a398c34 len 0x8000 hold 2 pincount 0 lock 0 flags WRITE|MAPPED|ASYNC|DONE|ORDERED|PAGES|RUN_QUEUES|0x2000 caller xfs_buf_iorequest
          <idle>-0     [001]  2234.411005: xfs_buf_ioerror: dev 8:33 bno 0x3a398c34 len 0x8000 hold 1 pincount 0 lock 0 error 0 flags WRITE|MAPPED|ASYNC|DONE|ORDERED|PAGES|RUN_QUEUES|0x2000 caller xfs_buf_bio_end_io
          <idle>-0     [001]  2234.411009: xfs_buf_iodone: dev 8:33 bno 0x3a398c34 len 0x8000 hold 1 pincount 0 lock 0 flags WRITE|MAPPED|ASYNC|DONE|ORDERED|PAGES|RUN_QUEUES|0x2000 caller _xfs_buf_ioend
     kworker/1:2-1448  [001]  2234.411044: xfs_buf_item_committed: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 1 lock 1 flags |MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q recur 0 refcount 1 bliflags |DIRTY lidesc 0x          (null) liflags 
     kworker/1:2-1448  [001]  2234.411047: xfs_buf_item_unpin: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 1 lock 1 flags |MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q recur 0 refcount 1 bliflags |DIRTY lidesc 0x          (null) liflags IN_AIL
    xfsbufd/sdc1-1407  [000]  2235.591555: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  2235.591560: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  2236.790013: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  2236.790018: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  2237.988479: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  2237.988484: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  2239.186952: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  2239.186956: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  2240.385424: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  2240.385428: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  2241.583884: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  2241.583888: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  2242.782341: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  2242.782345: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  2243.980799: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  2243.980804: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  2245.179256: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  2245.179260: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  2246.377715: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  2246.377719: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  2247.576172: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  2247.576177: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  2248.774630: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  2248.774635: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  2249.973087: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  2249.973092: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  2251.171547: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  2251.171552: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  2252.370002: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  2252.370006: xfs_buf_delwri_split: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags WRITE|MAPPED|ASYNC|DONE|PAGES caller xfsbufd
    xfsbufd/sdc1-1407  [000]  2252.370008: xfs_buf_iorequest: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags WRITE|MAPPED|ASYNC|DONE|PAGES caller xfs_bdstrat_cb
    xfsbufd/sdc1-1407  [000]  2252.370009: xfs_buf_hold: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags WRITE|MAPPED|ASYNC|DONE|PAGES caller xfs_buf_iorequest
    xfsbufd/sdc1-1407  [000]  2252.370029: xfs_buf_rele: dev 8:33 bno 0x0 len 0x200 hold 4 pincount 0 lock 0 flags WRITE|MAPPED|ASYNC|DONE|PAGES caller xfs_buf_iorequest
          <idle>-0     [001]  2252.370505: xfs_buf_ioerror: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 error 0 flags WRITE|MAPPED|ASYNC|DONE|PAGES caller xfs_buf_bio_end_io
          <idle>-0     [001]  2252.370510: xfs_buf_iodone: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags WRITE|MAPPED|ASYNC|DONE|PAGES caller _xfs_buf_ioend
     kworker/1:2-1448  [001]  2252.370547: xfs_buf_rele: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|PAGES caller xfs_buf_iodone
     kworker/1:2-1448  [001]  2252.370549: xfs_buf_iodone: dev 8:33 bno 0x0 len 0x200 hold 2 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|PAGES caller xfs_buf_iodone_callbacks
     kworker/1:2-1448  [001]  2252.370551: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 2 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|PAGES caller xfs_buf_iodone_work
     kworker/1:2-1448  [001]  2252.370551: xfs_buf_rele: dev 8:33 bno 0x0 len 0x200 hold 2 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|PAGES caller xfs_buf_iodone_work
   xfssyncd/sdc1-1409  [000]  2270.362854: xfs_log_reserve: dev 8:33 type DUMMY1 t_ocnt 1 t_cnt 1 t_curr_res 2740 t_unit_res 2740 t_flags XLOG_TIC_INITED reserveq empty writeq empty grant_reserve_cycle 1 grant_reserve_bytes 45624320 grant_write_cycle 1 grant_write_bytes 45624320 curr_cycle 1 curr_block 89110 tail_cycle 1 tail_block 35956
   xfssyncd/sdc1-1409  [000]  2270.362858: xfs_log_grant_enter: dev 8:33 type DUMMY1 t_ocnt 1 t_cnt 1 t_curr_res 2740 t_unit_res 2740 t_flags XLOG_TIC_INITED reserveq empty writeq empty grant_reserve_cycle 1 grant_reserve_bytes 45624320 grant_write_cycle 1 grant_write_bytes 45624320 curr_cycle 1 curr_block 89110 tail_cycle 1 tail_block 35956
   xfssyncd/sdc1-1409  [000]  2270.362860: xfs_log_grant_exit: dev 8:33 type DUMMY1 t_ocnt 1 t_cnt 1 t_curr_res 2740 t_unit_res 2740 t_flags XLOG_TIC_INITED reserveq empty writeq empty grant_reserve_cycle 1 grant_reserve_bytes 45627060 grant_write_cycle 1 grant_write_bytes 45627060 curr_cycle 1 curr_block 89110 tail_cycle 1 tail_block 35956
   xfssyncd/sdc1-1409  [000]  2270.362862: xfs_buf_lock: dev 8:33 bno 0x0 len 0x200 hold 1 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|PAGES caller xfs_getsb
   xfssyncd/sdc1-1409  [000]  2270.362863: xfs_buf_lock_done: dev 8:33 bno 0x0 len 0x200 hold 1 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|PAGES caller xfs_getsb
   xfssyncd/sdc1-1409  [000]  2270.362864: xfs_buf_hold: dev 8:33 bno 0x0 len 0x200 hold 1 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|PAGES caller xfs_getsb
   xfssyncd/sdc1-1409  [000]  2270.362866: xfs_buf_hold: dev 8:33 bno 0x0 len 0x200 hold 2 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|PAGES caller xfs_buf_item_init
   xfssyncd/sdc1-1409  [000]  2270.362868: xfs_trans_getsb: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags |MAPPED|ASYNC|DONE|PAGES recur 0 refcount 1 bliflags  lidesc 0xffff880106aa3350 liflags 
   xfssyncd/sdc1-1409  [000]  2270.362870: xfs_trans_log_buf: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags |MAPPED|ASYNC|DONE|DELWRI|PAGES recur 0 refcount 1 bliflags  lidesc 0xffff880106aa3350 liflags 
   xfssyncd/sdc1-1409  [000]  2270.362873: xfs_buf_item_size: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags |MAPPED|ASYNC|DONE|DELWRI|PAGES recur 0 refcount 1 bliflags |DIRTY|LOGGED lidesc 0xffff880106aa3350 liflags 
   xfssyncd/sdc1-1409  [000]  2270.362875: xfs_buf_item_format: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags |MAPPED|ASYNC|DONE|DELWRI|PAGES recur 0 refcount 1 bliflags |DIRTY|LOGGED lidesc 0xffff880106aa3350 liflags 
   xfssyncd/sdc1-1409  [000]  2270.362876: xfs_buf_item_pin: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags |MAPPED|ASYNC|DONE|DELWRI|PAGES recur 0 refcount 1 bliflags |DIRTY|LOGGED lidesc 0xffff880106aa3350 liflags 
   xfssyncd/sdc1-1409  [000]  2270.362882: xfs_log_done_nonperm: dev 8:33 type DUMMY1 t_ocnt 1 t_cnt 1 t_curr_res 2000 t_unit_res 2740 t_flags  reserveq empty writeq empty grant_reserve_cycle 1 grant_reserve_bytes 45627060 grant_write_cycle 1 grant_write_bytes 45627060 curr_cycle 1 curr_block 89110 tail_cycle 1 tail_block 35956
   xfssyncd/sdc1-1409  [000]  2270.362883: xfs_log_ungrant_enter: dev 8:33 type DUMMY1 t_ocnt 1 t_cnt 0 t_curr_res 2000 t_unit_res 2740 t_flags  reserveq empty writeq empty grant_reserve_cycle 1 grant_reserve_bytes 45627060 grant_write_cycle 1 grant_write_bytes 45627060 curr_cycle 1 curr_block 89110 tail_cycle 1 tail_block 35956
   xfssyncd/sdc1-1409  [000]  2270.362883: xfs_log_ungrant_sub: dev 8:33 type DUMMY1 t_ocnt 1 t_cnt 0 t_curr_res 2000 t_unit_res 2740 t_flags  reserveq empty writeq empty grant_reserve_cycle 1 grant_reserve_bytes 45627060 grant_write_cycle 1 grant_write_bytes 45627060 curr_cycle 1 curr_block 89110 tail_cycle 1 tail_block 35956
   xfssyncd/sdc1-1409  [000]  2270.362884: xfs_log_ungrant_exit: dev 8:33 type DUMMY1 t_ocnt 1 t_cnt 0 t_curr_res 2000 t_unit_res 2740 t_flags  reserveq empty writeq empty grant_reserve_cycle 1 grant_reserve_bytes 45625060 grant_write_cycle 1 grant_write_bytes 45625060 curr_cycle 1 curr_block 89110 tail_cycle 1 tail_block 35956
   xfssyncd/sdc1-1409  [000]  2270.362886: xfs_trans_commit_lsn: dev 8:33 trans 0xffff880101c46a40 commit_lsn 0x100015c16
   xfssyncd/sdc1-1409  [000]  2270.362889: xfs_buf_item_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 1 lock 0 flags |MAPPED|ASYNC|DONE|DELWRI|PAGES recur 0 refcount 2 bliflags |DIRTY lidesc 0x          (null) liflags 
   xfssyncd/sdc1-1409  [000]  2270.362890: xfs_buf_delwri_queue: dev 8:33 bno 0x0 len 0x200 hold 4 pincount 1 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES caller xfs_buf_unlock
   xfssyncd/sdc1-1409  [000]  2270.362897: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 4 pincount 1 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_item_unlock
   xfssyncd/sdc1-1409  [000]  2270.362898: xfs_buf_rele: dev 8:33 bno 0x0 len 0x200 hold 4 pincount 1 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_item_unlock
   xfssyncd/sdc1-1409  [000]  2270.362902: xfs_buf_iorequest: dev 8:33 bno 0x3a398c36 len 0x8000 hold 1 pincount 0 lock 0 flags WRITE|MAPPED|ASYNC|DONE|ORDERED|PAGES|RUN_QUEUES|0x2000 caller xlog_bdstrat
   xfssyncd/sdc1-1409  [000]  2270.362903: xfs_buf_hold: dev 8:33 bno 0x3a398c36 len 0x8000 hold 1 pincount 0 lock 0 flags WRITE|MAPPED|ASYNC|DONE|ORDERED|PAGES|RUN_QUEUES|0x2000 caller xfs_buf_iorequest
   xfssyncd/sdc1-1409  [000]  2270.362939: xfs_buf_rele: dev 8:33 bno 0x3a398c36 len 0x8000 hold 2 pincount 0 lock 0 flags WRITE|MAPPED|ASYNC|DONE|ORDERED|PAGES|RUN_QUEUES|0x2000 caller xfs_buf_iorequest
          <idle>-0     [001]  2270.382694: xfs_buf_ioerror: dev 8:33 bno 0x3a398c36 len 0x8000 hold 1 pincount 0 lock 0 error 0 flags WRITE|MAPPED|ASYNC|DONE|ORDERED|PAGES|RUN_QUEUES|0x2000 caller xfs_buf_bio_end_io
          <idle>-0     [001]  2270.382699: xfs_buf_iodone: dev 8:33 bno 0x3a398c36 len 0x8000 hold 1 pincount 0 lock 0 flags WRITE|MAPPED|ASYNC|DONE|ORDERED|PAGES|RUN_QUEUES|0x2000 caller _xfs_buf_ioend
     kworker/1:2-1448  [001]  2270.382741: xfs_buf_item_committed: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 1 lock 1 flags |MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q recur 0 refcount 1 bliflags |DIRTY lidesc 0x          (null) liflags 
     kworker/1:2-1448  [001]  2270.382745: xfs_buf_item_unpin: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 1 lock 1 flags |MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q recur 0 refcount 1 bliflags |DIRTY lidesc 0x          (null) liflags IN_AIL
    xfsbufd/sdc1-1407  [000]  2271.565309: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  2271.565314: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  2272.763759: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  2272.763763: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  2273.962216: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  2273.962220: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  2275.160678: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  2275.160683: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  2276.359131: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  2276.359135: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  2277.557589: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  2277.557594: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  2278.756046: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  2278.756051: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  2279.954503: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  2279.954508: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  2281.152961: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  2281.152965: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  2282.351419: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  2282.351423: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  2283.549876: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  2283.549880: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  2284.748334: xfs_buf_cond_lock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 0 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split
    xfsbufd/sdc1-1407  [000]  2284.748338: xfs_buf_unlock: dev 8:33 bno 0x0 len 0x200 hold 3 pincount 0 lock 1 flags MAPPED|ASYNC|DONE|DELWRI|PAGES|DELWRI_Q caller xfs_buf_delwri_split

[-- Attachment #1.2: Type: application/pgp-signature, Size: 198 bytes --]

[-- Attachment #2: Type: text/plain, Size: 121 bytes --]

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

Re: xfssyncd and disk spin down

[Christoph Hellwig]

On Thu, Jan 20, 2011 at 02:07:00PM +0200, Petre Rodan wrote:
> thanks for the tip. looks like I'm using xfsprogs 3.0.3 (latest version in the gentoo stable tree) to mkfs these filesystems. can the antique version be somehow the root of the problem?

Yes, lazy-count has been the default since xfsprogs 3.1.0.

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

Re: xfssyncd and disk spin down

[Dave Chinner]

On Thu, Jan 20, 2011 at 12:01:43PM +0200, Petre Rodan wrote:
> On Fri, Dec 31, 2010 at 11:13:23AM +1100, Dave Chinner wrote:
> > Ok, I can see the problem. The original patch I tested:
> > 
> > http://oss.sgi.com/archives/xfs/2010-08/msg00026.html
> > 
> > Made the log covering dummy transaction a synchronous transaction so
> > that the log was written and the superblock unpinned immediately to
> > allow the xfsbufd to write back the superblock and empty the AIL
> > before the next log covering check.
> > 
> > On review, the log covering dummy transaction got changed to an
> > async transaction, so the superblock buffer is not unpinned
> > immediately. This was the patch committed:
> > 
> > http://oss.sgi.com/archives/xfs/2010-08/msg00197.html
> > 
> > As a result, the success of log covering and idling is then
> > dependent on whether the log gets written to disk to unpin the
> > superblock buffer before the next xfssyncd run. It seems that there
> > is a large chance that this log write does not happen, so the
> > filesystem never idles correctly. I've reproduced it here, and only
> > in one test out of ten did the filesystem enter an idle state
> > correctly. I guess I was unlucky enough to hit that 1-in-10 case
> > when I tested the modified patch.
> > 
> > I'll cook up a patch to make the log covering behave like the
> > original patch I sent...
> 
> I presume that the new fix should be provided by "xfs: ensure log
> covering transactions are synchronous", so I tested 2.6.37 patched
> with it and then 2.6.38_rc1 that has it included..
.....
> in other words xfsyncd and xfsbufd now alternate at 18s intervals
> keeping the drive busy with nothing constructive hours after the
> last write to the drive.

This is a different problem, and not one I've seen before. Looking
at the traces, it appears that we have not empties the AIL. At
least, that's what I'm assuming at this point because log IO
completion is not updating log tail. When we start a log IO, we set
the log header lsn to the current head:

>    xfssyncd/sdc1-1413  [000]  3356.093456: xfs_log_reserve: dev 8:33 type DUMMY1 t_ocnt 1 t_cnt 1 t_curr_res 2740 t_unit_res 2740 t_flags XLOG_TIC_INITED reserveq empty writeq empty grant_reserve_cycle 2 grant_reserve_bytes 428523008 grant_write_cycle 2 grant_write_bytes 428523008 curr_cycle 2 curr_block 836959 tail_cycle 2 tail_block 810683

Which in this case is: curr_cycle 2 curr_block 836959

When the log IO completes, that value gets written to the
l_last_sync_lsn. When the AIL tail is removed, the tail lsn is
updated to the new tail item. If the AIL is empty, then the
l_last_sync_lsn is used. That means then next dummy transaction
made to cover the log should have the cycle/block of the above
current cycle.

Instead, what I see is that the next dummmy transaction shows:

>    xfssyncd/sdc1-1413  [000]  3392.067122: xfs_log_reserve: dev 8:33 type DUMMY1 t_ocnt 1 t_cnt 1 t_curr_res 2740 t_unit_res 2740 t_flags XLOG_TIC_INITED reserveq empty writeq empty grant_reserve_cycle 2 grant_reserve_bytes 428524032 grant_write_cycle 2 grant_write_bytes 428524032 curr_cycle 2 curr_block 836961 tail_cycle 2 tail_block 810683

The current head has moved: curr_cycle 2 curr_block 836961

But the tail hasn't: tail_cycle 2 tail_block 810683

So effectively we've got some item on the AIL that we haven't
flushed and isn't being flushed by xfssyncd. That's the problem I
need to get to the bottom of and it also explains why it's an
intermitten problem...

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

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

Re: xfssyncd and disk spin down

[Petre Rodan]

[-- Attachment #1.1: Type: text/plain, Size: 2358 bytes --]


Hello Dave,

On Fri, Jan 21, 2011 at 10:43:10AM +1100, Dave Chinner wrote:
> .....
> > in other words xfsyncd and xfsbufd now alternate at 18s intervals
> > keeping the drive busy with nothing constructive hours after the
> > last write to the drive.
> 
> This is a different problem, and not one I've seen before. Looking
> at the traces, it appears that we have not empties the AIL. At
> least, that's what I'm assuming at this point because log IO
> completion is not updating log tail. When we start a log IO, we set
> the log header lsn to the current head:
> 
> >    xfssyncd/sdc1-1413  [000]  3356.093456: xfs_log_reserve: dev 8:33 type DUMMY1 t_ocnt 1 t_cnt 1 t_curr_res 2740 t_unit_res 2740 t_flags XLOG_TIC_INITED reserveq empty writeq empty grant_reserve_cycle 2 grant_reserve_bytes 428523008 grant_write_cycle 2 grant_write_bytes 428523008 curr_cycle 2 curr_block 836959 tail_cycle 2 tail_block 810683
> 
> Which in this case is: curr_cycle 2 curr_block 836959
> 
> When the log IO completes, that value gets written to the
> l_last_sync_lsn. When the AIL tail is removed, the tail lsn is
> updated to the new tail item. If the AIL is empty, then the
> l_last_sync_lsn is used. That means then next dummy transaction
> made to cover the log should have the cycle/block of the above
> current cycle.
> 
> Instead, what I see is that the next dummmy transaction shows:
> 
> >    xfssyncd/sdc1-1413  [000]  3392.067122: xfs_log_reserve: dev 8:33 type DUMMY1 t_ocnt 1 t_cnt 1 t_curr_res 2740 t_unit_res 2740 t_flags XLOG_TIC_INITED reserveq empty writeq empty grant_reserve_cycle 2 grant_reserve_bytes 428524032 grant_write_cycle 2 grant_write_bytes 428524032 curr_cycle 2 curr_block 836961 tail_cycle 2 tail_block 810683
> 
> The current head has moved: curr_cycle 2 curr_block 836961
> 
> But the tail hasn't: tail_cycle 2 tail_block 810683
> 
> So effectively we've got some item on the AIL that we haven't
> flushed and isn't being flushed by xfssyncd. That's the problem I
> need to get to the bottom of and it also explains why it's an
> intermitten problem...

I have been watching the stream of patches that go into 2.6.38, but I probably missed the one that might be the answer to the problem above. can you please tell me which one to try, or can I help with anything?

much appreciated,
peter


[-- Attachment #1.2: Type: application/pgp-signature, Size: 198 bytes --]

[-- Attachment #2: Type: text/plain, Size: 121 bytes --]

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

Re: xfssyncd and disk spin down

[Dave Chinner]

On Thu, Feb 10, 2011 at 10:42:54PM +0200, Petre Rodan wrote:
> 
> Hello Dave,
> 
> On Fri, Jan 21, 2011 at 10:43:10AM +1100, Dave Chinner wrote:
> > .....
> > > in other words xfsyncd and xfsbufd now alternate at 18s intervals
> > > keeping the drive busy with nothing constructive hours after the
> > > last write to the drive.
> > 
> > This is a different problem, and not one I've seen before. Looking
> > at the traces, it appears that we have not empties the AIL. At
> > least, that's what I'm assuming at this point because log IO
> > completion is not updating log tail. When we start a log IO, we set
> > the log header lsn to the current head:
> > 
> > >    xfssyncd/sdc1-1413  [000]  3356.093456: xfs_log_reserve: dev 8:33 type DUMMY1 t_ocnt 1 t_cnt 1 t_curr_res 2740 t_unit_res 2740 t_flags XLOG_TIC_INITED reserveq empty writeq empty grant_reserve_cycle 2 grant_reserve_bytes 428523008 grant_write_cycle 2 grant_write_bytes 428523008 curr_cycle 2 curr_block 836959 tail_cycle 2 tail_block 810683
> > 
> > Which in this case is: curr_cycle 2 curr_block 836959
> > 
> > When the log IO completes, that value gets written to the
> > l_last_sync_lsn. When the AIL tail is removed, the tail lsn is
> > updated to the new tail item. If the AIL is empty, then the
> > l_last_sync_lsn is used. That means then next dummy transaction
> > made to cover the log should have the cycle/block of the above
> > current cycle.
> > 
> > Instead, what I see is that the next dummmy transaction shows:
> > 
> > >    xfssyncd/sdc1-1413  [000]  3392.067122: xfs_log_reserve: dev 8:33 type DUMMY1 t_ocnt 1 t_cnt 1 t_curr_res 2740 t_unit_res 2740 t_flags XLOG_TIC_INITED reserveq empty writeq empty grant_reserve_cycle 2 grant_reserve_bytes 428524032 grant_write_cycle 2 grant_write_bytes 428524032 curr_cycle 2 curr_block 836961 tail_cycle 2 tail_block 810683
> > 
> > The current head has moved: curr_cycle 2 curr_block 836961
> > 
> > But the tail hasn't: tail_cycle 2 tail_block 810683
> > 
> > So effectively we've got some item on the AIL that we haven't
> > flushed and isn't being flushed by xfssyncd. That's the problem I
> > need to get to the bottom of and it also explains why it's an
> > intermitten problem...
> 
> I have been watching the stream of patches that go into 2.6.38,
> but I probably missed the one that might be the answer to the
> problem above. can you please tell me which one to try, or can I
> help with anything?

I know what the problem is, but I haven't had time to work out of
code a fix. Been spending my time trying to work out the cause bugs
that are triggering hangs, crashes or corruptions here...

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

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

Re: xfssyncd and disk spin down

[Brian Duncan]

Dave Chinner <david <at> fromorbit.com> writes:

> 
> On Thu, Feb 10, 2011 at 10:42:54PM +0200, Petre Rodan wrote:
> > 
> > Hello Dave,
> > 
> > On Fri, Jan 21, 2011 at 10:43:10AM +1100, Dave Chinner wrote:
> > > .....
> > > > in other words xfsyncd and xfsbufd now alternate at 18s intervals
> > > > keeping the drive busy with nothing constructive hours after the
> > > > last write to the drive.
> > > 
> > > This is a different problem, and not one I've seen before. Looking
> > > at the traces, it appears that we have not empties the AIL. At
> > > least, that's what I'm assuming at this point because log IO
> > > completion is not updating log tail. When we start a log IO, we set
> > > the log header lsn to the current head:
> > > 
> > > >    xfssyncd/sdc1-1413  [000]  3356.093456: xfs_log_reserve: dev 8:33
type DUMMY1 t_ocnt 1 t_cnt 1
> t_curr_res 2740 t_unit_res 2740 t_flags XLOG_TIC_INITED reserveq empty writeq
empty
> grant_reserve_cycle 2 grant_reserve_bytes 428523008 grant_write_cycle 2
grant_write_bytes
> 428523008 curr_cycle 2 curr_block 836959 tail_cycle 2 tail_block 810683
> > > 
> > > Which in this case is: curr_cycle 2 curr_block 836959
> > > 
> > > When the log IO completes, that value gets written to the
> > > l_last_sync_lsn. When the AIL tail is removed, the tail lsn is
> > > updated to the new tail item. If the AIL is empty, then the
> > > l_last_sync_lsn is used. That means then next dummy transaction
> > > made to cover the log should have the cycle/block of the above
> > > current cycle.
> > > 
> > > Instead, what I see is that the next dummmy transaction shows:
> > > 
> > > >    xfssyncd/sdc1-1413  [000]  3392.067122: xfs_log_reserve: dev 8:33
type DUMMY1 t_ocnt 1 t_cnt 1
> t_curr_res 2740 t_unit_res 2740 t_flags XLOG_TIC_INITED reserveq empty writeq
empty
> grant_reserve_cycle 2 grant_reserve_bytes 428524032 grant_write_cycle 2
grant_write_bytes
> 428524032 curr_cycle 2 curr_block 836961 tail_cycle 2 tail_block 810683
> > > 
> > > The current head has moved: curr_cycle 2 curr_block 836961
> > > 
> > > But the tail hasn't: tail_cycle 2 tail_block 810683
> > > 
> > > So effectively we've got some item on the AIL that we haven't
> > > flushed and isn't being flushed by xfssyncd. That's the problem I
> > > need to get to the bottom of and it also explains why it's an
> > > intermitten problem...
> > 
> > I have been watching the stream of patches that go into 2.6.38,
> > but I probably missed the one that might be the answer to the
> > problem above. can you please tell me which one to try, or can I
> > help with anything?
> 
> I know what the problem is, but I haven't had time to work out of
> code a fix. Been spending my time trying to work out the cause bugs
> that are triggering hangs, crashes or corruptions here...
> 
> Cheers,
> 
> Dave.


FYI,

I found this thread after searching.. I upgraded one of my servers and
encountered this issue with XFS keeping drives from going to sleep with its
constant writing (after a copy to a volume).

I just wanted to note that I have an XFS volume that does have lazy-count set to
1 that this is occuring with, with 2.6.327. 

meta-data=/dev/sdf1              isize=256    agcount=4, agsize=122094500 blks
         =                       sectsz=512   attr=2
data     =                       bsize=4096   blocks=488378000, imaxpct=5
         =                       sunit=0      swidth=0 blks
naming   =version 2              bsize=4096   ascii-ci=0
log      =internal               bsize=4096   blocks=238465, version=2
         =                       sectsz=512   sunit=0 blks, lazy-count=1
realtime =none                   extsz=4096   blocks=0, rtextents=0

After writing any data to this drive, this would occur indefinitely:(until I
unmount and remount the drive)

[ 2839.120064] xfssyncd/sdf1(756): WRITE block 1954432155 on sdf1 (2 sectors)
[ 2869.120065] xfssyncd/sdf1(756): WRITE block 1954432157 on sdf1 (2 sectors)
[ 2899.120066] xfssyncd/sdf1(756): WRITE block 1954432159 on sdf1 (2 sectors)
[ 2929.120065] xfssyncd/sdf1(756): WRITE block 1954432161 on sdf1 (2 sectors)
[ 2959.120060] xfssyncd/sdf1(756): WRITE block 1954432163 on sdf1 (2 sectors)
[ 2989.120061] xfssyncd/sdf1(756): WRITE block 1954432165 on sdf1 (2 sectors)
[ 3019.120058] xfssyncd/sdf1(756): WRITE block 1954432167 on sdf1 (2 sectors)
[ 3049.120056] xfssyncd/sdf1(756): WRITE block 1954432169 on sdf1 (2 sectors)
[ 3079.120058] xfssyncd/sdf1(756): WRITE block 1954432171 on sdf1 (2 sectors)
[ 3109.120059] xfssyncd/sdf1(756): WRITE block 1954432173 on sdf1 (2 sectors)
[ 3139.120065] xfssyncd/sdf1(756): WRITE block 1954432175 on sdf1 (2 sectors)
[ 3169.120061] xfssyncd/sdf1(756): WRITE block 1954432177 on sdf1 (2 sectors)
[ 3199.120062] xfssyncd/sdf1(756): WRITE block 1954432179 on sdf1 (2 sectors)
[ 3229.120060] xfssyncd/sdf1(756): WRITE block 1954432181 on sdf1 (2 sectors)
[ 3259.120067] xfssyncd/sdf1(756): WRITE block 1954432183 on sdf1 (2 sectors)


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

Re: xfssyncd and disk spin down

[Brian Duncan]

> Dave Chinner <david <at> fromorbit.com> writes:
> > 
> > I know what the problem is, but I haven't had time to work out of
> > code a fix. Been spending my time trying to work out the cause bugs
> > that are triggering hangs, crashes or corruptions here...
> > 
> > Cheers,
> > 
> > Dave.
> 
> 


Can anyone please comment if this bug was ever fixed?

I have searched and see no further talk about this.

echo 720000 > /proc/sys/fs/xfs/xfssyncd_centisecs allows a drive to sleep more
often, but still is impacted by this. 

Thanks!


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

Re: xfssyncd and disk spin down

[Michael Weissenbacher]

Brian wrote:
> 
> Can anyone please comment if this bug was ever fixed?
> 
> I have searched and see no further talk about this.
> 
> echo 720000 > /proc/sys/fs/xfs/xfssyncd_centisecs allows a drive to sleep more
> often, but still is impacted by this. 
> 
> Thanks!
> 
AFAICT nothing has changed in this regard. I sill see the same behavior
with kernel 2.6.39. Thanks to this thread i found out about the problems
related to accumulating head unloads which i was able to mitigate by
setting xfssyncd_centisecs to a higher value.

cheers,
Michael

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

Re: xfssyncd and disk spin down

[Dave Chinner]

On Tue, May 31, 2011 at 05:16:29PM +0200, Michael Weissenbacher wrote:
> Brian wrote:
> > 
> > Can anyone please comment if this bug was ever fixed?
> > 
> > I have searched and see no further talk about this.
> > 
> > echo 720000 > /proc/sys/fs/xfs/xfssyncd_centisecs allows a drive to sleep more
> > often, but still is impacted by this. 
> > 
> > Thanks!
> > 
> AFAICT nothing has changed in this regard. I sill see the same behavior
> with kernel 2.6.39. Thanks to this thread i found out about the problems
> related to accumulating head unloads which i was able to mitigate by
> setting xfssyncd_centisecs to a higher value.

commit fd074841cfe01b006465fb9388091012585e8dfb
Author: Dave Chinner <dchinner@redhat.com>
Date:   Fri Apr 8 12:45:07 2011 +1000

    xfs: push the AIL from memory reclaim and periodic sync

    When we are short on memory, we want to expedite the cleaning of
    dirty objects.  Hence when we run short on memory, we need to kick
    the AIL flushing into action to clean as many dirty objects as
    quickly as possible.  To implement this, sample the lsn of the log
    item at the head of the AIL and use that as the push target for the
    AIL flush.

    Further, we keep items in the AIL that are dirty that are not
    tracked any other way, so we can get objects sitting in the AIL that
    don't get written back until the AIL is pushed. Hence to get the
    filesystem to the idle state, we might need to push the AIL to flush
    out any remaining dirty objects sitting in the AIL. This requires
    the same push mechanism as the reclaim push.

    This patch also renames xfs_trans_ail_tail() to xfs_ail_min_lsn() to
    match the new xfs_ail_max_lsn() function introduced in this patch.
    Similarly for xfs_trans_ail_push -> xfs_ail_push.

    Signed-off-by: Dave Chinner <dchinner@redhat.com>
    Reviewed-by: Alex Elder <aelder@sgi.com>

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

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

Re: xfssyncd and disk spin down

[Brian Duncan]

Thanks Dave for the confirmation that this was patched.

Can anyone confirm that this patch is working within 2.6.39?

The post above Dave's last says the bug is still present in 2.6.39 from their
own testing.. but I see in the changelog for 2.6.39 that Dave's patch/commit ID
is listed as being part of that Kernel update.  

http://www.kernel.org/pub/linux/kernel/v2.6/ChangeLog-2.6.39

Thanks




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

Re: xfssyncd and disk spin down

[Michael Weissenbacher]

Hi Brian!
> Thanks Dave for the confirmation that this was patched.
> 
> Can anyone confirm that this patch is working within 2.6.39?
> 
> The post above Dave's last says the bug is still present in 2.6.39 from their
> own testing.. but I see in the changelog for 2.6.39 that Dave's patch/commit ID
> is listed as being part of that Kernel update.  
> 
> http://www.kernel.org/pub/linux/kernel/v2.6/ChangeLog-2.6.39
> 
I can confirm that it works without problems on 2.6.39 - you can dismiss
my previous post.

hth,
Michael

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