xfs
[Top] [All Lists]

Re: XFS write cache flush policy

To: Dave Chinner <david@xxxxxxxxxxxxx>
Subject: Re: XFS write cache flush policy
From: Matthias Schniedermeyer <ms@xxxxxxx>
Date: Mon, 17 Dec 2012 00:22:51 +0100
Cc: Lin Li <sdeber@xxxxxxxxx>, Eric Sandeen <sandeen@xxxxxxxxxxx>, xfs@xxxxxxxxxxx
In-reply-to: <20121216204847.GN9806@dastard>
References: <CAA_rkDfFUmZzT_kMznsTSNVxdfqfmz=bmJ400wdBOzocgP32eA@xxxxxxxxxxxxxx> <20121208192927.GA17875@xxxxxxx> <20121210005820.GG15784@dastard> <20121210091239.GA21114@xxxxxxx> <50C64C17.9080206@xxxxxxxxxxx> <20121214111924.GA4762@xxxxxxx> <20121215221622.GF9806@dastard> <20121216103025.GA14880@xxxxxxx> <20121216111046.GA16756@xxxxxxx> <20121216204847.GN9806@dastard>
User-agent: Mutt/1.5.21 (2010-09-15)
On 17.12.2012 07:48, Dave Chinner wrote:
> On Sun, Dec 16, 2012 at 12:10:46PM +0100, Matthias Schniedermeyer wrote:
> > On 16.12.2012 11:30, Matthias Schniedermeyer wrote:
> > > On 16.12.2012 09:16, Dave Chinner wrote:
> 
> > > Partition is 100GB at the beginning of a 1,5TB SATA HDD connected by 
> > > USB3 enclosure:
> > > Machine has 4GB of memory and is running a vanilla 3.7.0 kernel.
> > > 
> > > mkfs.xfs -l size=1024b -s size=4096 /dev/sdb1
> 
> If you use the defaults, does the problem go away?

No changes.

> > > mount /dev/sdb1 /mnt
> > > mkdir /mnt/a
> > > cd /mnt/a
> > > for dat in `seq 1 40`; do dd if=/dev/zero of=$dat bs=1k count=900k ; done
> > > 
> > > Then i started a timer and waited for 5 minutes.
> > > Then i yanked out the cable, my machine was writing to the 24th file at 
> > > that point.
> > > 
> > > umount /mnt
> > > <replug cable>
> > > mount /dev/sdb1 /mnt
> > > ls -l /mnt
> > > <In words: Nothing there, not even a>
> 
> Can you provide the information I asked - what was there before the
> unmount,

With time reduced to 2 minutes and everything put in a script (see below).

After about 2 minutes:
ls -lR /mnt
/mnt:
total 0
drwxr-xr-x 2 root root 105 Dec 17 00:13 a

/mnt/a:
total 11186176
-rw-r--r-- 1 root root 943718400 Dec 17 00:11 1
-rw-r--r-- 1 root root 943718400 Dec 17 00:13 10
-rw-r--r-- 1 root root 943718400 Dec 17 00:13 11
-rw-r--r-- 1 root root 891450368 Dec 17 00:13 12
-rw-r--r-- 1 root root 943718400 Dec 17 00:11 2
-rw-r--r-- 1 root root 943718400 Dec 17 00:11 3
-rw-r--r-- 1 root root 943718400 Dec 17 00:12 4
-rw-r--r-- 1 root root 943718400 Dec 17 00:12 5
-rw-r--r-- 1 root root 943718400 Dec 17 00:12 6
-rw-r--r-- 1 root root 943718400 Dec 17 00:12 7
-rw-r--r-- 1 root root 943718400 Dec 17 00:12 8
-rw-r--r-- 1 root root 943718400 Dec 17 00:12 9

I yanked out the cable immediatly after the ls.

> what is there before recovery

xfs_logprint:
    data device: 0x811
    log device: 0x811 daddr: 104857632 length: 102400

cycle: 1        version: 2              lsn: 1,0        tail_lsn: 1,0
length of Log Record: 20        prev offset: -1         num ops: 1
uuid: b22d154a-b580-4d3a-bc09-ac0c62d39d39   format: little endian linux
h_size: 32768
----------------------------------------------------------------------------
Oper (0): tid: b0c0d0d0  len: 8  clientid: LOG  flags: UNMOUNT
Unmount filesystem

============================================================================
xfs_logprint: skipped 4096 cleared blocks in range: 2 - 4097
xfs_logprint: skipped 98302 zeroed blocks in range: 4098 - 102399
xfs_logprint: physical end of log
============================================================================
xfs_logprint: logical end of log
============================================================================


mount /dev/sdb1 /mnt -oro,norecovery
ls -lR /mnt
/mnt:
total 0

So nothing.

> what is there after recovery?

Same. Nothing.
The syslog-message the Filesystem was clean. (See below)

> And depending on what occurred, send me the log file so I
> can see what was actually supposed to be replayed by log recovery?

Regarding to the 'event trace' from your other mail, i have no idea what
or how to do that.

This is the syslog from first mount till third mount.

Start:
Dec 17 00:11:26 localhost kernel: [  204.152835] XFS (sdb1): Mounting Filesystem
Dec 17 00:11:26 localhost kernel: [  204.233355] XFS (sdb1): Ending clean mount
Dec 17 00:11:33 localhost kernel: [  211.471071] usb 3-1: reset SuperSpeed USB 
device number 2 using xhci_hcd
Dec 17 00:11:33 localhost kernel: [  211.485718] usb 3-1: Parent hub missing 
LPM exit latency info.  Power management will be impacted.
Dec 17 00:11:33 localhost kernel: [  211.488182] xhci_hcd 0000:04:00.0: xHCI 
xhci_drop_endpoint called with disabled ep ffff880113106100
Dec 17 00:11:33 localhost kernel: [  211.489358] xhci_hcd 0000:04:00.0: xHCI 
xhci_drop_endpoint called with disabled ep ffff880113106140
Dec 17 00:12:59 localhost kernel: [  296.364776] usb 3-1: reset SuperSpeed USB 
device number 2 using xhci_hcd
Dec 17 00:12:59 localhost kernel: [  296.379306] usb 3-1: Parent hub missing 
LPM exit latency info.  Power management will be impacted.
Dec 17 00:12:59 localhost kernel: [  296.381685] xhci_hcd 0000:04:00.0: xHCI 
xhci_drop_endpoint called with disabled ep ffff880113106100
Dec 17 00:12:59 localhost kernel: [  296.382906] xhci_hcd 0000:04:00.0: xHCI 
xhci_drop_endpoint called with disabled ep ffff880113106140

Disconnect:
Dec 17 00:13:28 localhost kernel: [  325.548129] usb 3-1: USB disconnect, 
device number 2
Dec 17 00:13:28 localhost kernel: [  325.549906] sd 12:0:0:0: [sdb] Unhandled 
error code
Dec 17 00:13:28 localhost kernel: [  325.551073] sd 12:0:0:0: [sdb]
Dec 17 00:13:28 localhost kernel: [  325.552230] Result: hostbyte=0x01 
driverbyte=0x00
Dec 17 00:13:28 localhost kernel: [  325.553399] sd 12:0:0:0: [sdb] CDB:
Dec 17 00:13:28 localhost kernel: [  325.554530] cdb[0]=0x2a: 2a 00 01 51 fd 98 
00 00 f0 00
Dec 17 00:13:28 localhost kernel: [  325.555708] end_request: I/O error, dev 
sdb, sector 22150552
Dec 17 00:13:28 localhost kernel: [  325.556971] sd 12:0:0:0: [sdb] Unhandled 
error code
Dec 17 00:13:28 localhost kernel: [  325.558118] sd 12:0:0:0: [sdb]
Dec 17 00:13:28 localhost kernel: [  325.559229] Result: hostbyte=0x01 
driverbyte=0x00
Dec 17 00:13:28 localhost kernel: [  325.560340] sd 12:0:0:0: [sdb] CDB:
Dec 17 00:13:28 localhost kernel: [  325.561449] cdb[0]=0x2a: 2a 00 01 51 fe 88 
00 00 f0 00
Dec 17 00:13:28 localhost kernel: [  325.562628] end_request: I/O error, dev 
sdb, sector 22150792
Dec 17 00:13:28 localhost kernel: [  325.562636] Buffer I/O error on device 
sdb1, logical block 2613279
Dec 17 00:13:28 localhost kernel: [  325.562637] lost page write due to I/O 
error on sdb1
Dec 17 00:13:28 localhost kernel: [  325.562638] Buffer I/O error on device 
sdb1, logical block 2613280
Dec 17 00:13:28 localhost kernel: [  325.562638] lost page write due to I/O 
error on sdb1
Dec 17 00:13:28 localhost kernel: [  325.562639] Buffer I/O error on device 
sdb1, logical block 2613281
Dec 17 00:13:28 localhost kernel: [  325.562639] lost page write due to I/O 
error on sdb1
Dec 17 00:13:28 localhost kernel: [  325.562640] Buffer I/O error on device 
sdb1, logical block 2613282
Dec 17 00:13:28 localhost kernel: [  325.562640] lost page write due to I/O 
error on sdb1
Dec 17 00:13:28 localhost kernel: [  325.562641] Buffer I/O error on device 
sdb1, logical block 2613283
Dec 17 00:13:28 localhost kernel: [  325.562641] lost page write due to I/O 
error on sdb1
Dec 17 00:13:28 localhost kernel: [  325.562642] Buffer I/O error on device 
sdb1, logical block 2613284
Dec 17 00:13:28 localhost kernel: [  325.562642] lost page write due to I/O 
error on sdb1
Dec 17 00:13:28 localhost kernel: [  325.562643] Buffer I/O error on device 
sdb1, logical block 2613285
Dec 17 00:13:28 localhost kernel: [  325.562643] lost page write due to I/O 
error on sdb1
Dec 17 00:13:28 localhost kernel: [  325.562644] Buffer I/O error on device 
sdb1, logical block 2613286
Dec 17 00:13:28 localhost kernel: [  325.562644] lost page write due to I/O 
error on sdb1
Dec 17 00:13:28 localhost kernel: [  325.562645] Buffer I/O error on device 
sdb1, logical block 2613287
Dec 17 00:13:28 localhost kernel: [  325.562645] lost page write due to I/O 
error on sdb1
Dec 17 00:13:28 localhost kernel: [  325.562646] Buffer I/O error on device 
sdb1, logical block 2613288
Dec 17 00:13:28 localhost kernel: [  325.562646] lost page write due to I/O 
error on sdb1
Dec 17 00:13:28 localhost kernel: [  325.647364] XFS (sdb1): metadata I/O 
error: block 0x6400022 ("xlog_iodone") error 5 numblks 64
Dec 17 00:13:28 localhost kernel: [  325.648559] XFS (sdb1): 
xfs_do_force_shutdown(0x2) called from line 1074 of file 
/xssd/usr_src/linux/fs/xfs/xfs_log.c.  Return address = 0xffffffff812a1e49
Dec 17 00:13:28 localhost kernel: [  325.649804] XFS (sdb1): Log I/O Error 
Detected.  Shutting down filesystem
Dec 17 00:13:28 localhost kernel: [  325.651037] XFS (sdb1): Please umount the 
filesystem and rectify the problem(s)
Dec 17 00:13:28 localhost kernel: [  325.652341] XFS (sdb1): xfs_log_force: 
error 5 returned.
Dec 17 00:13:28 localhost kernel: [  325.653564] XFS (sdb1): 
xfs_do_force_shutdown(0x1) called from line 1160 of file 
/xssd/usr_src/linux/fs/xfs/xfs_buf.c.  Return address = 0xffffffff8125198f
Dec 17 00:13:28 localhost kernel: [  325.937819] XFS (sdb1): xfs_log_force: 
error 5 returned.
Dec 17 00:13:28 localhost kernel: [  325.939105] XFS (sdb1): 
xfs_do_force_shutdown(0x1) called from line 1160 of file 
/xssd/usr_src/linux/fs/xfs/xfs_buf.c.  Return address = 0xffffffff8125198f
Dec 17 00:13:28 localhost kernel: [  325.940427] XFS (sdb1): xfs_log_force: 
error 5 returned.
Dec 17 00:13:28 localhost kernel: [  325.941768] XFS (sdb1): xfs_log_force: 
error 5 returned.

Reconnect:
Dec 17 00:13:41 localhost kernel: [  338.939079] usb 3-1: new SuperSpeed USB 
device number 3 using xhci_hcd
Dec 17 00:13:41 localhost kernel: [  338.953410] usb 3-1: Parent hub missing 
LPM exit latency info.  Power management will be impacted.
Dec 17 00:13:41 localhost kernel: [  338.959394] usb 3-1: New USB device found, 
idVendor=174c, idProduct=5106
Dec 17 00:13:41 localhost kernel: [  338.960791] usb 3-1: New USB device 
strings: Mfr=2, Product=3, SerialNumber=1
Dec 17 00:13:41 localhost kernel: [  338.962135] usb 3-1: Product: AS2105
Dec 17 00:13:41 localhost kernel: [  338.963470] usb 3-1: Manufacturer: ASMedia
Dec 17 00:13:41 localhost kernel: [  338.964800] usb 3-1: SerialNumber:         
    5XW02D4M
Dec 17 00:13:41 localhost kernel: [  338.966977] scsi13 : usb-storage 3-1:1.0
Dec 17 00:13:42 localhost kernel: [  339.970156] scsi 13:0:0:0: Direct-Access   
  ST315005 41AS             CC32 PQ: 0 ANSI: 5
Dec 17 00:13:42 localhost kernel: [  339.971635] sd 13:0:0:0: Attached scsi 
generic sg1 type 0
Dec 17 00:13:42 localhost kernel: [  339.973202] sd 13:0:0:0: [sdb] 2930277168 
512-byte logical blocks: (1.50 TB/1.36 TiB)
Dec 17 00:13:42 localhost kernel: [  339.975256] sd 13:0:0:0: [sdb] Write 
Protect is off
Dec 17 00:13:42 localhost kernel: [  339.976639] sd 13:0:0:0: [sdb] Mode Sense: 
23 00 00 00
Dec 17 00:13:42 localhost kernel: [  339.977358] sd 13:0:0:0: [sdb] No Caching 
mode page present
Dec 17 00:13:42 localhost kernel: [  339.978700] sd 13:0:0:0: [sdb] Assuming 
drive cache: write through
Dec 17 00:13:42 localhost kernel: [  339.981747] sd 13:0:0:0: [sdb] No Caching 
mode page present
Dec 17 00:13:42 localhost kernel: [  339.983143] sd 13:0:0:0: [sdb] Assuming 
drive cache: write through
Dec 17 00:13:42 localhost kernel: [  339.998266]  sdb: sdb1
Dec 17 00:13:42 localhost kernel: [  340.001383] sd 13:0:0:0: [sdb] No Caching 
mode page present
Dec 17 00:13:42 localhost kernel: [  340.002734] sd 13:0:0:0: [sdb] Assuming 
drive cache: write through
Dec 17 00:13:42 localhost kernel: [  340.004043] sd 13:0:0:0: [sdb] Attached 
SCSI disk

mount -oro,norecovery:
Dec 17 00:13:54 localhost kernel: [  351.902543] XFS (sdb1): Mounting 
filesystem in no-recovery mode.  Filesystem will be inconsistent.

mount:
Dec 17 00:14:02 localhost kernel: [  359.860013] XFS (sdb1): Mounting Filesystem
Dec 17 00:14:02 localhost kernel: [  359.908198] XFS (sdb1): Ending clean mount


- test.sh -
#!/bin/bash

mkfs.xfs -f /dev/sdb1
mount /dev/sdb1 /mnt
mkdir /mnt/a

(sleep 2m ; ls -lR /mnt)&

for dat in `seq 1 40`; do dd if=/dev/zero of=/mnt/a/$dat bs=1k count=900k ; done

ls -lR /mnt
umount /mnt

echo "Press Enter"
read ABC

xfs_logprint /dev/sdb1

mount /dev/sdb1 /mnt -oro,norecovery
ls -lR /mnt
umount /mnt

echo "Press Enter"
read ABC

mount /dev/sdb1 /mnt
ls -lR /mnt
umount /mnt
- test.sh -




-- 

Matthias

<Prev in Thread] Current Thread [Next in Thread>