xfssyncd and disk spin down

DISCUSSION Petre Rodan 7 participants 29 messages Dec 23, 2010 – Jul 11, 2011

Share & tools

Petre Rodan

author

2010-12-23 16:55 UTC #0 lore raw

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

_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs

Stan Hoeppner

2010-12-23 19:27 UTC #1 lore raw

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

Quoted 1 line

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

Signature · 6 lines

Stan

_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs

Petre Rodan

author

2010-12-23 21:16 UTC #2 lore raw

Hello,

Quoted 4 lines · Stan Hoeppner

Petre Rodan put forth on 12/23/2010 10:55 AM:
Quoted 1 line
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.

Quoted 9 lines

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
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs

Stan Hoeppner

2010-12-24 00:52 UTC #3 lore raw

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

Quoted 1 line

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.

Signature · 6 lines

Stan

_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs

Stan Hoeppner

2010-12-24 05:13 UTC #4 lore raw

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

Quoted 11 lines

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.

Signature · 6 lines

Stan

_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs

Petre Rodan

author

2010-12-24 06:02 UTC #5 lore raw

In reply to Stan Hoeppner

Hello Stan,

Quoted 4 lines · Stan Hoeppner

Petre Rodan put forth on 12/23/2010 3:16 PM:
Quoted 1 line
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.

Quoted 8 lines

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.

Quoted 2 lines

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
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs

Stan Hoeppner

2010-12-24 22:58 UTC #6 lore raw

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

Quoted 5 lines

Quoted 2 lines
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.

Signature · 6 lines

Stan

_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs

Eric Sandeen

2010-12-25 03:34 UTC #7 lore raw

Quoted 13 lines · Stan Hoeppner

Petre Rodan put forth on 12/24/2010 12:02 AM:
Quoted 5 lines
Quoted 2 lines
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.

Quoted 7 lines

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
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs

Stan Hoeppner

2010-12-25 04:30 UTC #8 lore raw

Eric Sandeen put forth on 12/24/2010 9:36 PM:

Quoted 22 lines · Stan Hoeppner

Quoted 13 lines
Petre Rodan put forth on 12/24/2010 12:02 AM:
Quoted 5 lines
Quoted 2 lines
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.
Quoted 7 lines
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.

Quoted 1 line

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? ;)

Quoted 1 line

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).

Signature · 6 lines

Stan

_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs

Eric Sandeen

2010-12-24 18:15 UTC #9 lore raw

In reply to Petre Rodan

Quoted 8 lines · Petre Rodan

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.

Quoted 5 lines

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.

Quoted 26 lines

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]

Quoted 2 lines

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

Nope that's a sector on the drive.

Quoted 1 line

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, ....

Quoted 6 lines

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.

Quoted 11 lines

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
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs

Petre Rodan

author

2010-12-25 12:06 UTC #10 lore raw

Hi Eric,

Quoted 1 line · Eric Sandeen

Doesn't seem like that should happen.

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

Quoted 6 lines

Quoted 4 lines
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.

Quoted 2 lines

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.

Quoted 6 lines

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

Signature · 4 lines

petre rodan
<[email protected]>
Technical Manager
Simplex SRL, Bucharest

_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs

Dave Chinner

2010-12-27 02:17 UTC #11 lore raw

In reply to Petre Rodan

Quoted 8 lines · Petre Rodan

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.

Quoted 5 lines

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.

Signature · 7 lines

Dave Chinner
[email protected]

_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs

Petre Rodan

author

2010-12-27 06:13 UTC #12 lore raw

Hello Dave,

Quoted 3 lines · Dave Chinner

Quoted 2 lines · Petre Rodan
Hello,

[..]

Quoted 9 lines

Quoted 5 lines
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

_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs

Dave Chinner

2010-12-27 14:06 UTC #13 lore raw

Quoted 14 lines · Petre Rodan

Hello Dave,
Quoted 3 lines · Dave Chinner
Quoted 2 lines · Petre Rodan
Hello,
[..]
Quoted 6 lines
Quoted 5 lines
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.

Quoted 7 lines

Quoted 3 lines
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.

Signature · 7 lines

Dave Chinner
[email protected]

_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs

Petre Rodan

author

2010-12-27 17:16 UTC #14 lore raw

Hello Dave,

Quoted 9 lines · Dave Chinner

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

_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs

Dave Chinner

2010-12-31 00:11 UTC #15 lore raw

Quoted 12 lines · Petre Rodan

Hello Dave,
Quoted 8 lines · Dave Chinner
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

Quoted 5 lines

Quoted 1 line
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.

Signature · 7 lines

Dave Chinner
[email protected]

_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs

Petre Rodan

author

2011-01-20 10:01 UTC #16 lore raw

hello Dave,

Quoted 43 lines · Dave Chinner

Quoted 12 lines · Petre Rodan
Hello Dave,
Quoted 8 lines · Dave Chinner
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
Quoted 5 lines
Quoted 1 line
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.

Quoted 2 lines

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

Quoted 7 lines

Cheers,
Dave.
Signature · 2 lines
Dave Chinner
[email protected]

Signature · 4 lines

petre rodan
<[email protected]>
Technical Manager
Simplex SRL, Bucharest

# 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

_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs

Dave Chinner

2011-01-20 11:03 UTC #17 lore raw

Quoted 52 lines · Petre Rodan

Quoted 43 lines · Dave Chinner
Quoted 12 lines · Petre Rodan
Hello Dave,
Quoted 8 lines · Dave Chinner
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
Quoted 5 lines
Quoted 1 line
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.
Quoted 2 lines
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:

....

Quoted 12 lines

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:

Quoted 7 lines

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

                                                              ^^^^^^^^^^^^

Quoted 3 lines

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.

Signature · 7 lines

Dave Chinner
[email protected]

_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs

Petre Rodan

author

2011-01-20 12:06 UTC #18 lore raw

Hello Dave,

Quoted 4 lines · Dave Chinner

....
Quoted 3 lines
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.

[..]

Quoted 7 lines

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

Quoted 6 lines

                                                              ^^^^^^^^^^^^
Quoted 1 line
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

Quoted 11 lines

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.
Signature · 2 lines
Dave Chinner
[email protected]

Signature · 4 lines

petre rodan
<[email protected]>
Technical Manager
Simplex SRL, Bucharest

# 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

_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs

Christoph Hellwig

2011-01-20 13:22 UTC #19 lore raw

Quoted 1 line · Petre Rodan

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
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs

Dave Chinner

2011-01-20 23:41 UTC #20 lore raw

In reply to Petre Rodan

Quoted 31 lines · Petre Rodan

Quoted 24 lines · Dave Chinner
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.
Quoted 2 lines
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..

.....

Quoted 3 lines

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:

Quoted 1 line

   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:

Quoted 1 line

   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.

Signature · 7 lines

Dave Chinner
[email protected]

_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs

Petre Rodan

author

2011-02-10 20:42 UTC #21 lore raw

Hello Dave,

Quoted 26 lines · Dave Chinner

.....
Quoted 3 lines
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:
Quoted 1 line
   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:
Quoted 1 line
   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

Quoted 8 lines

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

_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs

Dave Chinner

2011-02-10 22:16 UTC #22 lore raw

Quoted 39 lines · Petre Rodan

Hello Dave,
Quoted 26 lines · Dave Chinner
.....
Quoted 3 lines
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:
Quoted 1 line
   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:
Quoted 1 line
   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
Quoted 8 lines
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...

Quoted 4 lines

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.

Signature · 7 lines

Dave Chinner
[email protected]

_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs

Brian Duncan

2011-02-14 18:07 UTC #23 lore raw

Quoted 11 lines · Dave Chinner <david <at> fromorbit.com> writes:

Quoted 9 lines · Petre Rodan
Hello Dave,
Quoted 5 lines · Dave Chinner
.....
Quoted 3 lines
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.

Quoted 7 lines

Quoted 7 lines
Quoted 7 lines
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:
Quoted 1 line
   xfssyncd/sdc1-1413  [000]  3356.093456: xfs_log_reserve: dev 8:33

type DUMMY1 t_ocnt 1 t_cnt 1

Quoted 1 line

t_curr_res 2740 t_unit_res 2740 t_flags XLOG_TIC_INITED reserveq empty writeq

empty

Quoted 1 line

grant_reserve_cycle 2 grant_reserve_bytes 428523008 grant_write_cycle 2

grant_write_bytes

Quoted 14 lines

428523008 curr_cycle 2 curr_block 836959 tail_cycle 2 tail_block 810683
Quoted 13 lines
Quoted 13 lines
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:
Quoted 1 line
   xfssyncd/sdc1-1413  [000]  3392.067122: xfs_log_reserve: dev 8:33

type DUMMY1 t_ocnt 1 t_cnt 1

Quoted 1 line

t_curr_res 2740 t_unit_res 2740 t_flags XLOG_TIC_INITED reserveq empty writeq

empty

Quoted 1 line

grant_reserve_cycle 2 grant_reserve_bytes 428524032 grant_write_cycle 2

grant_write_bytes

Quoted 16 lines

428524032 curr_cycle 2 curr_block 836961 tail_cycle 2 tail_block 810683
Quoted 10 lines
Quoted 9 lines
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...
Quoted 4 lines
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?

Quoted 7 lines

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
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs

Brian Duncan

2011-05-31 14:41 UTC #24 lore raw

Quoted 11 lines

Quoted 8 lines · 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
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs

Michael Weissenbacher

2011-05-31 15:16 UTC #25 lore raw

Quoted 10 lines · Brian

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
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs

Dave Chinner

Reviewed-by Alex Elder

2011-06-01 23:37 UTC #26 lore raw

Quoted 9 lines · Michael Weissenbacher

Quoted 8 lines · Brian
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.

Quoted 6 lines

Quoted 2 lines
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 <[email protected]>
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 <[email protected]>

Reviewed-by Alex Elder <[email protected]>

Cheers,

Dave.

Signature · 7 lines

Dave Chinner
[email protected]

_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs

Brian Duncan

2011-07-11 04:03 UTC #27 lore raw

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
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs

Michael Weissenbacher

2011-07-11 14:34 UTC #28 lore raw

Hi Brian!

Quoted 10 lines

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
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs