[Linux-cachefs] Issues

[Edward "Koko" Konetzko]

David Howells wrote:
> "Edward \"Koko\" Konetzko" <konetzed at quixoticagony.com> wrote:
>
>   
>> I cleared the cache rebooted using the 2.6.30-rc6 kernel, output of
>> /proc/.../stats is below.
>>     
>
> Can you see if the problem happens with a copy of just a single small file
> from that set?  If so, can you try copying just that single file after doing:
>
> 	echo 65535 >/sys/module/fscache/parameters/debug
> 	echo 255 >/sys/module/cachefiles/parameters/debug
>
> and capturing the messages dumped into dmesg?
>
> David
>   
Could not get to reproduce with a single small file or even a single 
file that was about 300 MB.  I did run the same test of coping over the 
kernel tree and got this debug output.  Hopefully this is what you are 
looking for.

[kslowd] - kill object OBJ1c816
[kslowd] <== cachefiles_put_object()
[kslowd] ==> cachefiles_drop_object({OBJ1c815,2})
[kslowd] <== cachefiles_drop_object()
[kslowd] ==> cachefiles_put_object({OBJ1c815,2})
[kslowd] <== cachefiles_put_object()
[kslowd] ==> cachefiles_put_object({OBJ1c815,1})
[kslowd] - kill object OBJ1c815
[kslowd] <== cachefiles_put_object()
[kslowd] ==> cachefiles_drop_object({OBJ1c814,2})
[kslowd] <== cachefiles_drop_object()
[kslowd] ==> cachefiles_put_object({OBJ1c814,2})
[kslowd] <== cachefiles_put_object()
[kslowd] ==> cachefiles_put_object({OBJ1c814,1})
[kslowd] - kill object OBJ1c814
[kslowd] <== cachefiles_put_object()
[kslowd] ==> cachefiles_drop_object({OBJ1c813,2})
[kslowd] <== cachefiles_drop_object()
[kslowd] ==> cachefiles_put_object({OBJ1c813,2})
[kslowd] <== cachefiles_put_object()
[kslowd] ==> cachefiles_put_object({OBJ1c813,1})
[kslowd] - kill object OBJ1c813
[kslowd] <== cachefiles_put_object()
[cp    ] ==> cachefiles_alloc_object({dm-0},ffff88003ec78c90,)
[cp    ] ==> cachefiles_cook_key(,22)
[cp    ] max: 45
[cp    ] acc: 010014
[cp    ] acc: 010000
[cp    ] acc: 00fd00
[cp    ] acc: e5c100
[cp    ] acc: e30068
[cp    ] acc: 007ce8
[cp    ] acc: 2ebf52
[cp    ] acc: 00001a
[cp    ] <== cachefiles_cook_key() = ffff88001e945680 38
[cp    ] <== cachefiles_alloc_object() = ffff880019468580 [ffff88002e488a60]
[cp    ] ==> cachefiles_grab_object({OBJ208dd,1})
[kslowd] ==> cachefiles_lookup_object({OBJ208dd})
[kslowd] ==> cachefiles_walk_to_object({ffff88003c94c8c0},, at c1,)
[kslowd] lookup '@c1'
[kslowd] next -> ffff88003f5bfcc0 positive
[kslowd] advance
[kslowd] lookup 'Ek0g000g00Qf004sVE1MUEP70iZHbq000'
[kslowd] next -> ffff88003c941600 positive
[kslowd] validate 'Ek0g000g00Qf004sVE1MUEP70iZHbq000'
[kslowd] ==> cachefiles_check_object_xattr(ffff880019468580,#49)
[kslowd] checkaux NFS.fh #48
[kslowd] <== cachefiles_check_object_xattr() = 0
[kslowd] ==> cachefiles_mark_object_active(,ffff880019468580)
[kslowd] <== cachefiles_mark_object_active()
[kslowd] === OBTAINED_OBJECT ===
[kslowd] <== cachefiles_walk_to_object() = 0 [9202802]
[kslowd] ==> cachefiles_attr_changed({OBJ208dd},[12222])
[cp    ] ==> cachefiles_read_or_alloc_pages({OBJ208dd,1},,3,,)
[cp    ] 2 -> 8d0e8d
[cp    ] 1 -> 8d0e8c
[cp    ] 0 -> 8d0e8b
[cp    ] ==> cachefiles_read_backing_file()
[cp    ] read back ffffe20000716ce0{0,1}
[cp    ] - new ffffe200007c35b8
[cp    ] - monitor add
[cp    ] read back ffffe2000074cd28{1,1}
[cp    ] - new ffffe200006851a8
[cp    ] - monitor add
[cp    ] read back ffffe200003a4030{2,1}
[cp    ] - present ffffe200006fa810
[cp    ] - not ready ffffe200006fa810{100000000000801}
[cp    ] - monitor add
[cp    ] out
[cp    ] <== cachefiles_read_backing_file() = 0
[cp    ] <== cachefiles_read_or_alloc_pages() = 0 [nr=0 empty]
[kslowd] ==> cachefiles_read_waiter({2},3,0,{ffffe200006fa810,0})
[kslowd] --- monitor ffffe200006fa810 100000000000810 ---
Pid: 6131, comm: kslowd Not tainted 2.6.30-rc6 #1
Call Trace:
 [<ffffffffa027cc6e>] ? cachefiles_read_waiter+0xd9/0x147 [cachefiles]
 [<ffffffff8022bb3b>] ? __wake_up_common+0x3f/0x71
 [<ffffffff8022cbb2>] ? __wake_up+0x30/0x44
 [<ffffffff8024a3fb>] ? __wake_up_bit+0x28/0x2d
 [<ffffffffa003a793>] ? ext3_truncate+0x4d7/0x8ed [ext3]
 [<ffffffff802c827a>] ? __getblk+0x25/0x209
 [<ffffffff802c827a>] ? __getblk+0x25/0x209
 [<ffffffff802915c9>] ? unmap_mapping_range+0x59/0x1ff
 [<ffffffff8022cbb2>] ? __wake_up+0x30/0x44
 [<ffffffff80293550>] ? vmtruncate+0xc2/0xe2
 [<ffffffff802bd67b>] ? inode_setattr+0x22/0x10a
 [<ffffffffa003baa5>] ? ext3_setattr+0x17b/0x1e6 [ext3]
 [<ffffffff802bd8e9>] ? notify_change+0x186/0x2c9
 [<ffffffffa02789de>] ? cachefiles_attr_changed+0x133/0x1cd [cachefiles]
 [<ffffffff8024a411>] ? wake_up_bit+0x11/0x22
 [<ffffffffa0278f7f>] ? cachefiles_lookup_object+0xcf/0x12a [cachefiles]
 [<ffffffffa0269165>] ? fscache_lookup_object+0x110/0x122 [fscache]
 [<ffffffffa026989a>] ? fscache_object_slow_work_execute+0x567/0x65f 
[fscache]
 [<ffffffff8027e102>] ? slow_work_thread+0x285/0x43a
 [<ffffffff8024a422>] ? autoremove_wake_function+0x0/0x2e
 [<ffffffff8027de7d>] ? slow_work_thread+0x0/0x43a
 [<ffffffff8024a2f3>] ? kthread+0x54/0x81
 [<ffffffff8020c93a>] ? child_rip+0xa/0x20
 [<ffffffff8024a29f>] ? kthread+0x0/0x81
 [<ffffffff8020c930>] ? child_rip+0x0/0x20
[kslowd] <== cachefiles_attr_changed() = 0
[kslowd] <== cachefiles_lookup_object() [0]
[kslowd] ==> cachefiles_lookup_complete({OBJ208dd,ffff88002e488a60})
[kslowd] ==> cachefiles_put_object({OBJ208dd,2})
[kslowd] <== cachefiles_put_object()
[events] ==> cachefiles_read_copier({ino=9202802})
[events] - copy {2}
CacheFiles: I/O Error: Readpage failed on backing file 100000000000810
FS-Cache: Cache cachefiles stopped due to I/O error
[events] <== cachefiles_read_copier()
[syslog] ==> cachefiles_read_waiter({0},3,0,{ffffe200007c35b8,0})
[syslog] --- monitor ffffe200007c35b8 100000000020028 ---
[syslog] ==> cachefiles_read_waiter({1},3,0,{ffffe200006851a8,0})
[syslog] --- monitor ffffe200006851a8 100000000020028 ---
[events] ==> cachefiles_read_copier({ino=9202802})
[events] - copy {0}
[events] - copy {1}
[events] <== cachefiles_read_copier()