Subject: LFS trouble
To: None <current-users@netbsd.org>
From: Sverre Froyen <sverre@viewmark.com>
List: current-users
Date: 09/18/2006 11:26:09
Hi,

This morning, again, LFS appeared to acting up.  One process (kontact) was 
using about 25% of the cpu and its state (from top) was alternating between 
lfs_io<somthing> (I think) and lfs <something> (I thought that I had been 
able to save the output from top in an ffs file, so I did not write it down).  
In addition, iostat was showing a steady disk transfer rate of 6 MB/s and I 
could hear the disk seeking.  kontact could not be killed (even with -9) and 
the halt (and reboot) command had no effect.  Any command that accessed an 
lfs file system would hang (other commands seemed OK).

System is 4.99.1 i386, GENERIC_LAPTOP + acpi, Thinkpad T42.

Ideas anyone?

Sverre

# fsck -yf /home

** /dev/rwd0j
** Newer checkpoint verified, recovered 0 seconds of data
** Last Mounted on /home
** Phase 0 - Check Inode Free List
FREE LIST HEAD IN SUPERBLOCK SHOULD BE 54143 (WAS 71541)

FIX? yes

** Phase 1 - Check Blocks and Sizes
INCORRECT BLOCK COUNT I=55100 (183 SHOULD BE 136)
CORRECT? yes

** Phase 2 - Check Pathnames
** Phase 3 - Check Connectivity
** Phase 4 - Check Reference Counts
** Phase 5 - Check Segment Block Accounting
SEGMENT 7137 CLAIMS 7168 BYTES BUT HAS 0 (HIGH BY 7168)

FIX? yes

SEGMENT 7615 CLAIMS 5120 BYTES BUT HAS 0 (HIGH BY 5120)

FIX? yes

SEGMENT 8505 CLAIMS 153600 BYTES BUT HAS 146432 (HIGH BY 7168)

FIX? yes

DMETA GIVEN AS 528332, SHOULD BE 134135

FIX? yes

AVAIL GIVEN AS 1725720, SHOULD BE 2117984

FIX? yes

NCLEAN GIVEN AS 1920, SHOULD BE 2303

FIX? yes

BFREE GIVEN AS 3752197, SHOULD BE BETWEEN 4123773 AND 4168924

FIX? yes

** Phase 6 - Roll Forward

ROLL FORWARD? yes

** Phase 6b - Recheck Segment Block Accounting
DMETA GIVEN AS 134137, SHOULD BE 134241

FIX? yes

AVAIL GIVEN AS 2117950, SHOULD BE 2115902

FIX? yes

NCLEAN GIVEN AS 2303, SHOULD BE 2301

FIX? yes

** Phase 6c - Recheck Inode Free List
71804 files, 4886204 used, 4146346 free

WRITE CHANGES TO DISK? yes

WRITING CHANGES TO DISK

UPDATE SUPERBLOCKS? yes

The situation this morning has similarities to one that happened about 10 days 
ago when lfs_cleanerd appeared to be looping.  That time too disk IO was 
continuous at about 6 MB/s with lots of disk noise.  Here's the start of the 
lfs_cleanerd output from that event:

# lfs_cleanerd -d -r 1 -b -n 4 /home
lfs_cleanerd[2398]: /home: attaching cleaner
lfs_cleanerd[2398]: /home: bfree = 4067337, avail = 1996648, clean = 2184/9401
lfs_cleanerd[2398]: /home: resized buffer hash from 4 to 256
lfs_cleanerd[2398]: /home: cleaning with goal 4194304 bytes (2184 segs clean, 
6299 cleanable)
lfs_cleanerd[2398]: /home: cleaning with goal 4194304 bytes (2184 segs clean, 
6299 cleanable)
lfs_cleanerd[2398]: /home: add seg 5794 prio 550071422 containing 7168 bytes
lfs_cleanerd[2398]: /home: add seg 8455 prio 468770330 containing 7168 bytes
lfs_cleanerd[2398]: /home: add seg 1417 prio 437477789 containing 7168 bytes
lfs_cleanerd[2398]: /home: add seg 8028 prio 401232073 containing 7168 bytes
lfs_cleanerd[2398]: /home: add seg 5881 prio 333274357 containing 7168 bytes
lfs_cleanerd[2398]: increasing number of segment buffers to 5
lfs_cleanerd[2398]: /home: add seg 6464 prio 319787845 containing 7168 bytes
lfs_cleanerd[2398]: increasing number of segment buffers to 6
lfs_cleanerd[2398]: /home: add seg 6619 prio 317810505 containing 7168 bytes
lfs_cleanerd[2398]: increasing number of segment buffers to 7
lfs_cleanerd[2398]: /home: add seg 7039 prio 314049484 containing 7168 bytes
lfs_cleanerd[2398]: increasing number of segment buffers to 8
lfs_cleanerd[2398]: /home: add seg 9252 prio 278421807 containing 7168 bytes
lfs_cleanerd[2398]: increasing number of segment buffers to 9
lfs_cleanerd[2398]: /home: add seg 6228 prio 251448910 containing 7168 bytes
lfs_cleanerd[2398]: increasing number of segment buffers to 10
lfs_cleanerd[2398]: /home: add seg 7189 prio 234773088 containing 7168 bytes
lfs_cleanerd[2398]: increasing number of segment buffers to 11
lfs_cleanerd[2398]: /home: add seg 8776 prio 209591191 containing 7168 bytes
lfs_cleanerd[2398]: increasing number of segment buffers to 12
lfs_cleanerd[2398]: /home: add seg 5228 prio 190500887 containing 7168 bytes
lfs_cleanerd[2398]: increasing number of segment buffers to 13
lfs_cleanerd[2398]: /home: add seg 6004 prio 185242413 containing 7168 bytes
lfs_cleanerd[2398]: increasing number of segment buffers to 14
lfs_cleanerd[2398]: /home: add seg 6821 prio 170908957 containing 7168 bytes
lfs_cleanerd[2398]: increasing number of segment buffers to 15
lfs_cleanerd[2398]: /home: add seg 7561 prio 161436940 containing 7168 bytes
lfs_cleanerd[2398]: increasing number of segment buffers to 16
lfs_cleanerd[2398]: /home: add seg 5160 prio 127189174 containing 7168 bytes
lfs_cleanerd[2398]: increasing number of segment buffers to 17
lfs_cleanerd[2398]: /home: no blocks to clean in 17 cleanable segments
lfs_cleanerd[2398]: bytes read:      17833984
lfs_cleanerd[2398]: bytes written:     0
lfs_cleanerd[2398]: segments cleaned:  17
lfs_cleanerd[2398]: error segments:    0
lfs_cleanerd[2398]: utilization total: 0
lfs_cleanerd[2398]: utilization sos:   0
lfs_cleanerd[2398]: utilization avg:   0.00
lfs_cleanerd[2398]: utilization sdev:   0.000000
lfs_cleanerd[2398]: /home: bfree = 4067337, avail = 1996648, clean = 2184/9401
lfs_cleanerd[2398]: /home: cleaning with goal 4194304 bytes (2184 segs clean, 
6299 cleanable)
lfs_cleanerd[2398]: /home: cleaning with goal 4194304 bytes (2184 segs clean, 
6299 cleanable)
lfs_cleanerd[2398]: /home: add seg 5794 prio 550071669 containing 7168 bytes
lfs_cleanerd[2398]: /home: add seg 8455 prio 468770579 containing 7168 bytes
...