On Mon, Feb 14, 2011 at 10:29 AM, Matt [off-list ref] wrote:

On Mon, Feb 14, 2011 at 1:24 AM, Matt [off-list ref] wrote:

quoted

On Mon, Feb 14, 2011 at 12:08 AM, Matt [off-list ref] wrote:

quoted

On Wed, Feb 9, 2011 at 1:03 AM, Dan Magenheimer
[off-list ref] wrote:
[snip]

quoted

If I've missed anything important, please let me know!

Thanks again!
Dan

Hi Dan,

thank you so much for answering my email in such detail !

I shall pick up on that mail in my next email sending to the mailing list :)


currently I've got a problem with btrfs which seems to get triggered
by cleancache get-operations:


Feb 14 00:37:19 lupus kernel: [ 2831.297377] device fsid
354120c992a00761-5fa07d400126a895 devid 1 transid 7
/dev/mapper/portage
Feb 14 00:37:19 lupus kernel: [ 2831.297698] btrfs: enabling disk space caching
Feb 14 00:37:19 lupus kernel: [ 2831.297700] btrfs: force lzo compression
Feb 14 00:37:19 lupus kernel: [ 2831.315844] zcache: created ephemeral
tmem pool, id=3
Feb 14 00:39:20 lupus kernel: [ 2951.853188] BUG: unable to handle
kernel paging request at 0000000001400050
Feb 14 00:39:20 lupus kernel: [ 2951.853219] IP: [<ffffffff8133ef1b>]
btrfs_encode_fh+0x2b/0x120
Feb 14 00:39:20 lupus kernel: [ 2951.853242] PGD 0
Feb 14 00:39:20 lupus kernel: [ 2951.853251] Oops: 0000 [#1] PREEMPT SMP
Feb 14 00:39:20 lupus kernel: [ 2951.853275] last sysfs file:
/sys/devices/platform/coretemp.3/temp1_input
Feb 14 00:39:20 lupus kernel: [ 2951.853295] CPU 4
Feb 14 00:39:20 lupus kernel: [ 2951.853303] Modules linked in: radeon
ttm drm_kms_helper cfbcopyarea cfbimgblt cfbfillrect ipt_REJECT
ipt_LOG xt_limit xt_tcpudp xt_state nf_nat_irc nf_conntrack_irc
nf_nat_ftp nf_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_conntrack_ftp
iptable_filter ipt_addrtype xt_DSCP xt_dscp xt_iprange ip_tables
ip6table_filter xt_NFQUEUE xt_owner xt_hashlimit xt_conntrack xt_mark
xt_multiport xt_connmark nf_conntrack xt_string ip6_tables x_tables
it87 hwmon_vid coretemp snd_seq_dummy snd_seq_oss snd_seq_midi_event
snd_seq snd_seq_device snd_pcm_oss snd_mixer_oss snd_hda_codec_hdmi
snd_hda_codec_realtek snd_hda_intel snd_hda_codec snd_hwdep snd_pcm
snd_timer snd soundcore i2c_i801 wmi e1000e shpchp snd_page_alloc
libphy e1000 scsi_wait_scan sl811_hcd ohci_hcd ssb usb_storage
ehci_hcd [last unloaded: tg3]
Feb 14 00:39:20 lupus kernel: [ 2951.853682]
Feb 14 00:39:20 lupus kernel: [ 2951.853690] Pid: 11394, comm:
btrfs-transacti Not tainted 2.6.37-plus_v16_zcache #4 FMP55/ipower
G3710
Feb 14 00:39:20 lupus kernel: [ 2951.853725] RIP:
0010:[<ffffffff8133ef1b>]  [<ffffffff8133ef1b>]
btrfs_encode_fh+0x2b/0x120
Feb 14 00:39:20 lupus kernel: [ 2951.853751] RSP:
0018:ffff880129a11b00  EFLAGS: 00010246
Feb 14 00:39:20 lupus kernel: [ 2951.853767] RAX: 00000000000000ff
RBX: ffff88014a1ce628 RCX: 0000000000000000
Feb 14 00:39:20 lupus kernel: [ 2951.853788] RDX: ffff880129a11b3c
RSI: ffff880129a11b70 RDI: 0000000000000006
Feb 14 00:39:20 lupus kernel: [ 2951.853808] RBP: 0000000001400000
R08: ffffffff8133eef0 R09: ffff880129a11c68
Feb 14 00:39:20 lupus kernel: [ 2951.853829] R10: 0000000000000001
R11: 0000000000000001 R12: ffff88014a1ce780
Feb 14 00:39:20 lupus kernel: [ 2951.853849] R13: ffff88021fefc000
R14: ffff88021fef9000 R15: 0000000000000000
Feb 14 00:39:20 lupus kernel: [ 2951.853870] FS:
0000000000000000(0000) GS:ffff8800bf500000(0000)
knlGS:0000000000000000
Feb 14 00:39:20 lupus kernel: [ 2951.853894] CS:  0010 DS: 0000 ES:
0000 CR0: 000000008005003b
Feb 14 00:39:20 lupus kernel: [ 2951.853911] CR2: 0000000001400050
CR3: 0000000001c27000 CR4: 00000000000006e0
Feb 14 00:39:20 lupus kernel: [ 2951.853932] DR0: 0000000000000000
DR1: 0000000000000000 DR2: 0000000000000000
Feb 14 00:39:20 lupus kernel: [ 2951.853952] DR3: 0000000000000000
DR6: 00000000ffff0ff0 DR7: 0000000000000400
Feb 14 00:39:20 lupus kernel: [ 2951.853973] Process btrfs-transacti
(pid: 11394, threadinfo ffff880129a10000, task ffff880202e4ac40)
Feb 14 00:39:20 lupus kernel: [ 2951.853999] Stack:
Feb 14 00:39:20 lupus kernel: [ 2951.854006]  ffff880129a11b50
ffff880000000003 ffff88003c60a098 0000000000000003
Feb 14 00:39:20 lupus kernel: [ 2951.854035]  ffffffffffffffff
ffffffff810e6aaa 0000000000000000 0000000602e4ac40
Feb 14 00:39:20 lupus kernel: [ 2951.854063]  ffffffff8133e3f0
ffffffff810e6cee 0000000000001000 0000000000000000
Feb 14 00:39:20 lupus kernel: [ 2951.854092] Call Trace:
Feb 14 00:39:20 lupus kernel: [ 2951.854103]  [<ffffffff810e6aaa>] ?
cleancache_get_key+0x4a/0x60
Feb 14 00:39:20 lupus kernel: [ 2951.854122]  [<ffffffff8133e3f0>] ?
btrfs_wake_function+0x0/0x20
Feb 14 00:39:20 lupus kernel: [ 2951.854140]  [<ffffffff810e6cee>] ?
__cleancache_flush_inode+0x3e/0x70
Feb 14 00:39:20 lupus kernel: [ 2951.854161]  [<ffffffff810b34d2>] ?
truncate_inode_pages_range+0x42/0x440
Feb 14 00:39:20 lupus kernel: [ 2951.854182]  [<ffffffff812f115e>] ?
btrfs_search_slot+0x89e/0xa00
Feb 14 00:39:20 lupus kernel: [ 2951.854201]  [<ffffffff810c3a45>] ?
unmap_mapping_range+0xc5/0x2a0
Feb 14 00:39:20 lupus kernel: [ 2951.854220]  [<ffffffff810b3930>] ?
truncate_pagecache+0x40/0x70
Feb 14 00:39:20 lupus kernel: [ 2951.854240]  [<ffffffff813458b1>] ?
btrfs_truncate_free_space_cache+0x81/0xe0
Feb 14 00:39:20 lupus kernel: [ 2951.854261]  [<ffffffff812fce15>] ?
btrfs_write_dirty_block_groups+0x245/0x500
Feb 14 00:39:20 lupus kernel: [ 2951.854283]  [<ffffffff812fcb6a>] ?
btrfs_run_delayed_refs+0x1ba/0x220
Feb 14 00:39:20 lupus kernel: [ 2951.854304]  [<ffffffff8130afff>] ?
commit_cowonly_roots+0xff/0x1d0
Feb 14 00:39:20 lupus kernel: [ 2951.854323]  [<ffffffff8130c583>] ?
btrfs_commit_transaction+0x363/0x760
Feb 14 00:39:20 lupus kernel: [ 2951.854344]  [<ffffffff81067ea0>] ?
autoremove_wake_function+0x0/0x30
Feb 14 00:39:20 lupus kernel: [ 2951.854364]  [<ffffffff81305bc3>] ?
transaction_kthread+0x283/0x2a0
Feb 14 00:39:20 lupus kernel: [ 2951.854383]  [<ffffffff81305940>] ?
transaction_kthread+0x0/0x2a0
Feb 14 00:39:20 lupus kernel: [ 2951.854401]  [<ffffffff81305940>] ?
transaction_kthread+0x0/0x2a0
Feb 14 00:39:20 lupus kernel: [ 2951.854420]  [<ffffffff81067a16>] ?
kthread+0x96/0xa0
Feb 14 00:39:20 lupus kernel: [ 2951.854437]  [<ffffffff81003514>] ?
kernel_thread_helper+0x4/0x10
Feb 14 00:39:20 lupus kernel: [ 2951.854455]  [<ffffffff81067980>] ?
kthread+0x0/0xa0
Feb 14 00:39:20 lupus kernel: [ 2951.854471]  [<ffffffff81003510>] ?
kernel_thread_helper+0x0/0x10
Feb 14 00:39:20 lupus kernel: [ 2951.854488] Code: 55 b8 ff 00 00 00
53 48 89 fb 48 83 ec 18 48 8b 6f 10 8b 3a 83 ff 04 0f 86 d5 00 00 00
85 c9 0f 95 c1 83 ff 07 0f 86 d5 00 00 00 <48> 8b 45 50 bf 05 00 00 00
48 89 06 84 c9 48 8b 85 68 fe ff ff
Feb 14 00:39:20 lupus kernel: [ 2951.854742] RIP  [<ffffffff8133ef1b>]
btrfs_encode_fh+0x2b/0x120
Feb 14 00:39:20 lupus kernel: [ 2951.854762]  RSP <ffff880129a11b00>
Feb 14 00:39:20 lupus kernel: [ 2951.854773] CR2: 0000000001400050
Feb 14 00:39:20 lupus kernel: [ 2951.860906] ---[ end trace
f831c5ceeaa49287 ]---

in my case I had compress-force with lzo and disk_cache enabled


another user of the kernel I'm currently running has had the same
problem with zcache
(http://forums.gentoo.org/viewtopic-p-6571799.html#6571799)

(looks like in his case compression and any other fancy additional
features weren't enabled)


changes made by this kernel or patchset to btrfs are from
* io-less dirty throttling patchset (44 patches)
* zcache V2 ("[PATCH] staging: zcache: fix memory leak" should be
applied in both cases)
* PATCH] fix (latent?) memory corruption in btrfs_encode_fh()
* btrfs-unstable changes to state of
3a90983dbdcb2f4f48c0d771d8e5b4d88f27fae6 (so practically equals btrfs
from 2.6.38-rc4+)

I haven't tried downgrading to vanilla 2.6.37 with zcache only, yet,

but kind of upgraded btrfs to the latest state of the btrfs-unstable
repository (http://git.eu.kernel.org/?p=linux/kernel/git/mason/btrfs-unstable.git;a=summary)
namely 3a90983dbdcb2f4f48c0d771d8e5b4d88f27fae6

this also didn't help and seemed to produce the same error-message

so to summarize:

1) error message appearing with all 4 patchsets applied changing
btrfs-code and compress-force=lzo and disk_cache enabled

2) error message appearing with default mount-options and btrfs from
2.6.37 and changes for zcache & io-less dirty throttling patchset
applied (first 2 patch(sets)) from list)


in my case I tried to extract / play back a 1.7 GiB tarball of my
portage-directory (lots of small files and some tar.bzip2 archives)
via pbzip2 or 7z when the error happened and the message was shown

Due to KMS sound (webradio streaming) was still running but I couldn't
continue work (X switching to kernel output) so I did the magic sysrq
combo (reisub)


Does that BUG message ring a bell for anyone ?

(if I should leave out anyone from the CC in the next emails or
future, please holler - I don't want to spam your inboxes)

Thanks

Matt

OK,

here's the output of a kernel -

staying as close to vanilla (2.6.37) as the current situation allows
(only including some corruption or leak fixes for zram & zcache and
"zram_xvmalloc: 64K page fixes and optimizations" (and 2 reiserfs
fixes)):

so in total the following patches are included in this new kernel
(2.6.37-zcache):

zram changes:
1 zram: Fix sparse warning 'Using plain integer as NULL pointer'
2 [PATCH] zram: fix data corruption issue
3 [PATCH 0/7][v2] zram_xvmalloc: 64K page fixes and optimizations

zcache:
1 zcache-linux-2.6.37-110205
2 [PATCH] staging: zcache: fix memory leak
3 [PATCH] zcache: Fix build error when sysfs is not defined

reiserfs:
1 [PATCH] reiserfs: Make sure va_end() is always called after
2 [patch] reiserfs: potential ERR_PTR dereference


the same procedure:

trying to extract the mentioned portage-tarball:

time (7z e -so -tbzip2 -mmt=5 /system/portage_backup_022011.tbz2 | tar
-xp -C /usr/gentoo/)


this hopefully should make it easier to track down the problem:


Feb 14 01:59:59 lupus kernel: [  364.777143] device fsid
684a4213565dd3fe-ca991821badc2aac devid 1 transid 7
/dev/mapper/portage
Feb 14 01:59:59 lupus kernel: [  364.844994] zcache: created ephemeral
tmem pool, id=2
Feb 14 02:02:49 lupus kernel: [  534.577573] BUG: unable to handle
kernel paging request at 0000000037610050
Feb 14 02:02:49 lupus kernel: [  534.577605] IP: [<ffffffff81338cbb>]
btrfs_encode_fh+0x2b/0x110
Feb 14 02:02:49 lupus kernel: [  534.577630] PGD 0
Feb 14 02:02:49 lupus kernel: [  534.577640] Oops: 0000 [#1] PREEMPT SMP
Feb 14 02:02:49 lupus kernel: [  534.577665] last sysfs file:
/sys/devices/system/cpu/cpu7/cache/index2/shared_cpu_map
Feb 14 02:02:49 lupus kernel: [  534.577693] CPU 5
Feb 14 02:02:49 lupus kernel: [  534.577701] Modules linked in: radeon
ttm drm_kms_helper cfbcopyarea cfbimgblt cfbfillrect ipt_REJECT
ipt_LOG xt_limit xt_tcpudp xt_state nf_nat_irc nf_conntrack_irc
nf_nat_ftp nf_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_conntrack_ftp
iptable_filter ipt_addrtype xt_DSCP xt_dscp xt_iprange ip_tables
ip6table_filter xt_NFQUEUE xt_owner xt_hashlimit xt_conntrack xt_mark
xt_multiport xt_connmark nf_conntrack xt_string ip6_tables x_tables
it87 hwmon_vid coretemp snd_seq_dummy snd_seq_oss snd_seq_midi_event
snd_seq snd_seq_device snd_pcm_oss snd_mixer_oss snd_hda_codec_hdmi
snd_hda_codec_realtek snd_hda_intel snd_hda_codec snd_hwdep snd_pcm
snd_timer snd e1000e soundcore i2c_i801 shpchp snd_page_alloc wmi
libphy e1000 scsi_wait_scan sl811_hcd ohci_hcd ssb usb_storage
ehci_hcd [last unloaded: tg3]
Feb 14 02:02:49 lupus kernel: [  534.578114]
Feb 14 02:02:49 lupus kernel: [  534.578124] Pid: 8285, comm: tar Not
tainted 2.6.37-zcache #2 FMP55/ipower G3710
Feb 14 02:02:49 lupus kernel: [  534.578146] RIP:
0010:[<ffffffff81338cbb>]  [<ffffffff81338cbb>]
btrfs_encode_fh+0x2b/0x110
Feb 14 02:02:49 lupus kernel: [  534.578172] RSP:
0018:ffff88023ea9dcc8  EFLAGS: 00010246
Feb 14 02:02:49 lupus kernel: [  534.578189] RAX: 00000000000000ff
RBX: ffff8800b8643228 RCX: 0000000000000000
Feb 14 02:02:49 lupus kernel: [  534.578210] RDX: ffff88023ea9dd04
RSI: ffff88023ea9dd38 RDI: 0000000000000006
Feb 14 02:02:49 lupus kernel: [  534.578230] RBP: 0000000037610000
R08: ffffffff81338c90 R09: 0000000000000000
Feb 14 02:02:49 lupus kernel: [  534.578251] R10: 0000000000000019
R11: 0000000000000001 R12: ffff8800b8643380
Feb 14 02:02:49 lupus kernel: [  534.578272] R13: ffff8800b8643258
R14: 00007fff806f1f00 R15: 0000000000000000
Feb 14 02:02:49 lupus kernel: [  534.578293] FS:
00007f823d7ed700(0000) GS:ffff8800bf540000(0000)
knlGS:0000000000000000
Feb 14 02:02:49 lupus kernel: [  534.578317] CS:  0010 DS: 0000 ES:
0000 CR0: 0000000080050033
Feb 14 02:02:49 lupus kernel: [  534.578334] CR2: 0000000037610050
CR3: 000000023dcef000 CR4: 00000000000006e0
Feb 14 02:02:49 lupus kernel: [  534.578356] DR0: 0000000000000000
DR1: 0000000000000000 DR2: 0000000000000000
Feb 14 02:02:49 lupus kernel: [  534.578377] DR3: 0000000000000000
DR6: 00000000ffff0ff0 DR7: 0000000000000400
Feb 14 02:02:49 lupus kernel: [  534.578398] Process tar (pid: 8285,
threadinfo ffff88023ea9c000, task ffff88023e8b9d40)
Feb 14 02:02:49 lupus kernel: [  534.578421] Stack:
Feb 14 02:02:49 lupus kernel: [  534.578428]  000000013d096000
ffff88023ed84800 ffff88023ea9c000 0000000000000002
Feb 14 02:02:49 lupus kernel: [  534.578458]  ffffffffffffffff
ffffffff810e3b1a 0000000000000001 000000061e1d5240
Feb 14 02:02:49 lupus kernel: [  534.578486]  fffffffffffffffb
ffffffff810e3d5e ffff88010f383000 0000001ab86cb908
Feb 14 02:02:49 lupus kernel: [  534.578514] Call Trace:
Feb 14 02:02:49 lupus kernel: [  534.578525]  [<ffffffff810e3b1a>] ?
cleancache_get_key+0x4a/0x60
Feb 14 02:02:49 lupus kernel: [  534.578544]  [<ffffffff810e3d5e>] ?
__cleancache_flush_inode+0x3e/0x70
Feb 14 02:02:49 lupus kernel: [  534.578565]  [<ffffffff810b0ed2>] ?
truncate_inode_pages_range+0x42/0x440
Feb 14 02:02:49 lupus kernel: [  534.578586]  [<ffffffff81338451>] ?
btrfs_tree_unlock+0x41/0x50
Feb 14 02:02:49 lupus kernel: [  534.578605]  [<ffffffff812e4ed5>] ?
btrfs_release_path+0x15/0x70
Feb 14 02:02:49 lupus kernel: [  534.578624]  [<ffffffff8130bf29>] ?
btrfs_run_delayed_iputs+0x49/0x120
Feb 14 02:02:49 lupus kernel: [  534.578644]  [<ffffffff813107e7>] ?
btrfs_evict_inode+0x27/0x1e0
Feb 14 02:02:49 lupus kernel: [  534.578663]  [<ffffffff810fc3aa>] ?
evict+0x1a/0xa0
Feb 14 02:02:49 lupus kernel: [  534.578678]  [<ffffffff810fc6bd>] ?
iput+0x1cd/0x2b0
Feb 14 02:02:49 lupus kernel: [  534.578694]  [<ffffffff810f266f>] ?
do_unlinkat+0x12f/0x1d0
Feb 14 02:02:49 lupus kernel: [  534.578712]  [<ffffffff810027bb>] ?
system_call_fastpath+0x16/0x1b
Feb 14 02:02:49 lupus kernel: [  534.578730] Code: 55 b8 ff 00 00 00
53 48 89 fb 48 83 ec 18 48 8b 6f 10 8b 3a 83 ff 04 0f 86 d5 00 00 00
85 c9 0f 95 c1 83 ff 07 0f 86 d5 00 00 00 <48> 8b 45 50 bf 05 00 00 00
48 89 06 84 c9 48 8b 85 68 fe ff ff
Feb 14 02:02:49 lupus kernel: [  534.578986] RIP  [<ffffffff81338cbb>]
btrfs_encode_fh+0x2b/0x110
Feb 14 02:02:49 lupus kernel: [  534.579081]  RSP <ffff88023ea9dcc8>
Feb 14 02:02:49 lupus kernel: [  534.579093] CR2: 0000000037610050
Feb 14 02:02:49 lupus kernel: [  534.587513] ---[ end trace
c596b12e66c0b360 ]---


for reference I've pasted it to pastebin.com:

"2.6.37_zcache_V2.patch"
http://pastebin.com/cVSkwQ6M





after the reboot I had forgotten to not mount the btrfs volume and it
threw a similar error-message again and remounted several partitions
read-only (including the system partition)
the partition with btrfs (/usr/gentoo) couldn't be unmounted since the
umount process kind of hang

so here's the error message after a reboot (might not be accurate or
kind of "skewed" since other patches are included (io-less dirty
throttling, PATCH] fix (latent?) memory corruption in
btrfs_encode_fh() and latest changes for btrfs)) but might help to get
some more evidence:


Feb 14 02:05:46 lupus kernel: [   63.922648] device fsid
684a4213565dd3fe-ca991821badc2aac devid 1 transid 13
/dev/mapper/portage
Feb 14 02:05:46 lupus kernel: [   64.047118] btrfs: unlinked 1 orphans
Feb 14 02:05:46 lupus kernel: [   64.051956] zcache: created ephemeral
tmem pool, id=3
Feb 14 02:05:48 lupus kernel: [   65.801364] hub 2-1:1.0: hub_suspend
Feb 14 02:05:48 lupus kernel: [   65.801376] usb 2-1: unlink
qh256-0001/ffff88023fefd180 start 1 [1/0 us]
Feb 14 02:05:48 lupus kernel: [   65.801559] usb 2-1: usb auto-suspend
Feb 14 02:05:50 lupus kernel: [   67.797929] hub 2-0:1.0: hub_suspend
Feb 14 02:05:50 lupus kernel: [   67.797939] usb usb2: bus auto-suspend
Feb 14 02:05:50 lupus kernel: [   67.797942] ehci_hcd 0000:00:1d.0:
suspend root hub
Feb 14 02:05:52 lupus kernel: [   70.050493] BUG: unable to handle
kernel paging request at 0000030341ed0050
Feb 14 02:05:52 lupus kernel: [   70.050670] IP: [<ffffffff8133ef1b>]
btrfs_encode_fh+0x2b/0x120
Feb 14 02:05:52 lupus kernel: [   70.050807] PGD 0
Feb 14 02:05:52 lupus kernel: [   70.050929] Oops: 0000 [#1] PREEMPT SMP
Feb 14 02:05:52 lupus kernel: [   70.051223] last sysfs file:
/sys/module/pcie_aspm/parameters/policy
Feb 14 02:05:52 lupus kernel: [   70.051365] CPU 6
Feb 14 02:05:52 lupus kernel: [   70.051411] Modules linked in:
ipt_REJECT ipt_LOG xt_limit xt_tcpudp xt_state nf_nat_irc
nf_conntrack_irc nf_nat_ftp nf_nat nf_conntrack_ipv4 nf_defrag_ipv4
nf_conntrack_ftp iptable_filter ipt_addrtype xt_DSCP xt_dscp
xt_iprange ip_tables ip6table_filter xt_NFQUEUE xt_owner xt_hashlimit
xt_conntrack xt_mark xt_multiport xt_connmark nf_conntrack xt_string
ip6_tables x_tables it87 hwmon_vid coretemp snd_seq_dummy snd_seq_oss
snd_seq_midi_event snd_seq snd_seq_device snd_pcm_oss snd_mixer_oss
snd_hda_codec_hdmi snd_hda_codec_realtek snd_hda_intel snd_hda_codec
snd_hwdep snd_pcm snd_timer snd i2c_i801 soundcore wmi shpchp e1000e
snd_page_alloc libphy e1000 scsi_wait_scan sl811_hcd ohci_hcd ssb
usb_storage ehci_hcd [last unloaded: tg3]
Feb 14 02:05:52 lupus kernel: [   70.054694]
Feb 14 02:05:52 lupus kernel: [   70.054776] Pid: 7962, comm: umount
Not tainted 2.6.37-plus_v16_zcache #4 FMP55/ipower G3710
Feb 14 02:05:52 lupus kernel: [   70.054912] RIP:
0010:[<ffffffff8133ef1b>]  [<ffffffff8133ef1b>]
btrfs_encode_fh+0x2b/0x120
Feb 14 02:05:52 lupus kernel: [   70.055084] RSP:
0018:ffff88023c77d6f8  EFLAGS: 00010246
Feb 14 02:05:52 lupus kernel: [   70.055173] RAX: 00000000000000ff
RBX: ffff88023cde0168 RCX: 0000000000000000
Feb 14 02:05:52 lupus kernel: [   70.055265] RDX: ffff88023c77d734
RSI: ffff88023c77d768 RDI: 0000000000000006
Feb 14 02:05:52 lupus kernel: [   70.055357] RBP: 0000030341ed0000
R08: ffffffff8133eef0 R09: ffff88023c77d8d8
Feb 14 02:05:52 lupus kernel: [   70.055448] R10: 0000000000000003
R11: 0000000000000001 R12: 00000000ffffffff
Feb 14 02:05:52 lupus kernel: [   70.055540] R13: ffff88023cde0030
R14: ffffea0007dd39f0 R15: 0000000000000001
Feb 14 02:05:52 lupus kernel: [   70.055633] FS:
00007fb1cad04760(0000) GS:ffff8800bf580000(0000)
knlGS:0000000000000000
Feb 14 02:05:52 lupus kernel: [   70.055762] CS:  0010 DS: 0000 ES:
0000 CR0: 000000008005003b
Feb 14 02:05:52 lupus kernel: [   70.055851] CR2: 0000030341ed0050
CR3: 000000023c7d5000 CR4: 00000000000006e0
Feb 14 02:05:52 lupus kernel: [   70.055943] DR0: 0000000000000000
DR1: 0000000000000000 DR2: 0000000000000000
Feb 14 02:05:52 lupus kernel: [   70.056035] DR3: 0000000000000000
DR6: 00000000ffff0ff0 DR7: 0000000000000400
Feb 14 02:05:52 lupus kernel: [   70.056128] Process umount (pid:
7962, threadinfo ffff88023c77c000, task ffff88023c7a4260)
Feb 14 02:05:52 lupus kernel: [   70.056257] Stack:
Feb 14 02:05:52 lupus kernel: [   70.056338]  0000000000000000
0000000000000002 ffff880200000000 0000000000000003
Feb 14 02:05:52 lupus kernel: [   70.056630]  ffffea0007dd39f0
ffffffff810e6aaa ffff880200000041 0000000600000246
Feb 14 02:05:52 lupus kernel: [   70.056922]  ffff88023cdcd300
ffffffff810e6b3a 0000000000000001 ffffffff8132bb7c
Feb 14 02:05:52 lupus kernel: [   70.057213] Call Trace:
Feb 14 02:05:52 lupus kernel: [   70.057301]  [<ffffffff810e6aaa>] ?
cleancache_get_key+0x4a/0x60
Feb 14 02:05:52 lupus kernel: [   70.057393]  [<ffffffff810e6b3a>] ?
__cleancache_get_page+0x7a/0xd0
Feb 14 02:05:52 lupus kernel: [   70.057487]  [<ffffffff8132bb7c>] ?
merge_state+0x7c/0x150
Feb 14 02:05:52 lupus kernel: [   70.057579]  [<ffffffff8132e4de>] ?
__extent_read_full_page+0x52e/0x710
Feb 14 02:05:52 lupus kernel: [   70.057673]  [<ffffffff813bdea4>] ?
rb_insert_color+0xa4/0x140
Feb 14 02:05:52 lupus kernel: [   70.057766]  [<ffffffff8134b0b6>] ?
tree_insert+0x86/0x1e0
Feb 14 02:05:52 lupus kernel: [   70.057859]  [<ffffffff81058c73>] ?
lock_timer_base.clone.22+0x33/0x70
Feb 14 02:05:52 lupus kernel: [   70.058004]  [<ffffffff81305060>] ?
btree_get_extent+0x0/0x1c0
Feb 14 02:05:52 lupus kernel: [   70.058097]  [<ffffffff81330b21>] ?
read_extent_buffer_pages+0x2d1/0x470
Feb 14 02:05:52 lupus kernel: [   70.058191]  [<ffffffff81305060>] ?
btree_get_extent+0x0/0x1c0
Feb 14 02:05:52 lupus kernel: [   70.058283]  [<ffffffff8130674d>] ?
btree_read_extent_buffer_pages.clone.65+0x4d/0xa0
Feb 14 02:05:52 lupus kernel: [   70.058415]  [<ffffffff813076f9>] ?
read_tree_block+0x39/0x60
Feb 14 02:05:52 lupus kernel: [   70.058508]  [<ffffffff812ed5e6>] ?
read_block_for_search.clone.40+0x116/0x410
Feb 14 02:05:52 lupus kernel: [   70.058638]  [<ffffffff812eb228>] ?
btrfs_cow_block+0x118/0x2b0
Feb 14 02:05:52 lupus kernel: [   70.058731]  [<ffffffff812f0bc7>] ?
btrfs_search_slot+0x307/0xa00
Feb 14 02:05:52 lupus kernel: [   70.058823]  [<ffffffff812f6b18>] ?
lookup_inline_extent_backref+0x98/0x4a0
Feb 14 02:05:52 lupus kernel: [   70.058919]  [<ffffffff810e33d7>] ?
kmem_cache_alloc+0x87/0xa0
Feb 14 02:05:52 lupus kernel: [   70.059032]  [<ffffffff812f891c>] ?
__btrfs_free_extent+0xcc/0x6f0
Feb 14 02:05:52 lupus kernel: [   70.059125]  [<ffffffff812fc4cf>] ?
run_clustered_refs+0x39f/0x880
Feb 14 02:05:52 lupus kernel: [   70.059220]  [<ffffffff810b1f98>] ?
pagevec_lookup_tag+0x18/0x20
Feb 14 02:05:52 lupus kernel: [   70.059312]  [<ffffffff810a7c81>] ?
filemap_fdatawait_range+0x91/0x180
Feb 14 02:05:52 lupus kernel: [   70.059405]  [<ffffffff812fca77>] ?
btrfs_run_delayed_refs+0xc7/0x220
Feb 14 02:05:52 lupus kernel: [   70.059498]  [<ffffffff8130c29c>] ?
btrfs_commit_transaction+0x7c/0x760
Feb 14 02:05:52 lupus kernel: [   70.059591]  [<ffffffff81067ea0>] ?
autoremove_wake_function+0x0/0x30
Feb 14 02:05:52 lupus kernel: [   70.059683]  [<ffffffff8130cdef>] ?
start_transaction+0x1bf/0x270
Feb 14 02:05:52 lupus kernel: [   70.059775]  [<ffffffff8110e96a>] ?
__sync_filesystem+0x5a/0x90
Feb 14 02:05:52 lupus kernel: [   70.059867]  [<ffffffff810eae8d>] ?
generic_shutdown_super+0x2d/0x100
Feb 14 02:05:52 lupus kernel: [   70.059960]  [<ffffffff810eafb9>] ?
kill_anon_super+0x9/0x50
Feb 14 02:05:52 lupus kernel: [   70.060051]  [<ffffffff810eb266>] ?
deactivate_locked_super+0x26/0x80
Feb 14 02:05:52 lupus kernel: [   70.060144]  [<ffffffff811043ea>] ?
sys_umount+0x7a/0x390
Feb 14 02:05:52 lupus kernel: [   70.060235]  [<ffffffff810027bb>] ?
system_call_fastpath+0x16/0x1b
Feb 14 02:05:52 lupus kernel: [   70.060325] Code: 55 b8 ff 00 00 00
53 48 89 fb 48 83 ec 18 48 8b 6f 10 8b 3a 83 ff 04 0f 86 d5 00 00 00
85 c9 0f 95 c1 83 ff 07 0f 86 d5 00 00 00 <48> 8b 45 50 bf 05 00 00 00
48 89 06 84 c9 48 8b 85 68 fe ff ff
Feb 14 02:05:52 lupus kernel: [   70.063170] RIP  [<ffffffff8133ef1b>]
btrfs_encode_fh+0x2b/0x120
Feb 14 02:05:52 lupus kernel: [   70.063302]  RSP <ffff88023c77d6f8>
Feb 14 02:05:52 lupus kernel: [   70.063386] CR2: 0000030341ed0050
Feb 14 02:05:52 lupus kernel: [   70.063528] ---[ end trace
3313552d105b1535 ]---
Feb 14 02:06:16 lupus kernel: [   93.961960] BUG: unable to handle
kernel paging request at 0000030341ed0050
Feb 14 02:06:16 lupus kernel: [   93.962171] IP: [<ffffffff8133ef1b>]
btrfs_encode_fh+0x2b/0x120
Feb 14 02:06:16 lupus kernel: [   93.962307] PGD 0
Feb 14 02:06:16 lupus kernel: [   93.962430] Oops: 0000 [#2] PREEMPT SMP
Feb 14 02:06:16 lupus kernel: [   93.962637] last sysfs file:
/sys/devices/system/cpu/cpu7/cache/index2/shared_cpu_map
Feb 14 02:06:16 lupus kernel: [   93.962766] CPU 5
Feb 14 02:06:16 lupus kernel: [   93.962812] Modules linked in:
ipt_REJECT ipt_LOG xt_limit xt_tcpudp xt_state nf_nat_irc
nf_conntrack_irc nf_nat_ftp nf_nat nf_conntrack_ipv4 nf_defrag_ipv4
nf_conntrack_ftp iptable_filter ipt_addrtype xt_DSCP xt_dscp
xt_iprange ip_tables ip6table_filter xt_NFQUEUE xt_owner xt_hashlimit
xt_conntrack xt_mark xt_multiport xt_connmark nf_conntrack xt_string
ip6_tables x_tables it87 hwmon_vid coretemp snd_seq_dummy snd_seq_oss
snd_seq_midi_event snd_seq snd_seq_device snd_pcm_oss snd_mixer_oss
snd_hda_codec_hdmi snd_hda_codec_realtek snd_hda_intel snd_hda_codec
snd_hwdep snd_pcm snd_timer snd i2c_i801 soundcore wmi shpchp e1000e
snd_page_alloc libphy e1000 scsi_wait_scan sl811_hcd ohci_hcd ssb
usb_storage ehci_hcd [last unloaded: tg3]
Feb 14 02:06:16 lupus kernel: [   93.966044]
Feb 14 02:06:16 lupus kernel: [   93.966127] Pid: 7915, comm:
btrfs-transacti Tainted: G      D     2.6.37-plus_v16_zcache #4
FMP55/ipower G3710
Feb 14 02:06:16 lupus kernel: [   93.966266] RIP:
0010:[<ffffffff8133ef1b>]  [<ffffffff8133ef1b>]
btrfs_encode_fh+0x2b/0x120
Feb 14 02:06:16 lupus kernel: [   93.966440] RSP:
0018:ffff88023c63b6e0  EFLAGS: 00010246
Feb 14 02:06:16 lupus kernel: [   93.966528] RAX: 00000000000000ff
RBX: ffff88023cde0168 RCX: 0000000000000000
Feb 14 02:06:16 lupus kernel: [   93.966620] RDX: ffff88023c63b71c
RSI: ffff88023c63b750 RDI: 0000000000000006
Feb 14 02:06:16 lupus kernel: [   93.966713] RBP: 0000030341ed0000
R08: ffffffff8133eef0 R09: ffff88023c63b8c0
Feb 14 02:06:16 lupus kernel: [   93.966805] R10: 0000000000000003
R11: 0000000000000001 R12: 00000000ffffffff
Feb 14 02:06:16 lupus kernel: [   93.966897] R13: ffff88023cde0030
R14: ffffea0007d59bc8 R15: 0000000000000001
Feb 14 02:06:16 lupus kernel: [   93.966990] FS:
0000000000000000(0000) GS:ffff8800bf540000(0000)
knlGS:0000000000000000
Feb 14 02:06:16 lupus kernel: [   93.967120] CS:  0010 DS: 0000 ES:
0000 CR0: 000000008005003b
Feb 14 02:06:16 lupus kernel: [   93.967209] CR2: 0000030341ed0050
CR3: 0000000001c27000 CR4: 00000000000006e0
Feb 14 02:06:16 lupus kernel: [   93.967302] DR0: 0000000000000000
DR1: 0000000000000000 DR2: 0000000000000000
Feb 14 02:06:16 lupus kernel: [   93.967394] DR3: 0000000000000000
DR6: 00000000ffff0ff0 DR7: 0000000000000400
Feb 14 02:06:16 lupus kernel: [   93.967500] Process btrfs-transacti
(pid: 7915, threadinfo ffff88023c63a000, task ffff88023c7a1620)
Feb 14 02:06:16 lupus kernel: [   93.967630] Stack:
Feb 14 02:06:16 lupus kernel: [   93.967711]  0000000000000000
0000000000000002 0000000000000000 0000000000000003
Feb 14 02:06:16 lupus kernel: [   93.968057]  ffffea0007d59bc8
ffffffff810e6aaa 0000000000000041 0000000600000002
Feb 14 02:06:16 lupus kernel: [   93.968348]  0000000000000000
ffffffff810e6b3a 0000000000000001 ffffffff00000001
Feb 14 02:06:16 lupus kernel: [   93.968639] Call Trace:
Feb 14 02:06:16 lupus kernel: [   93.968728]  [<ffffffff810e6aaa>] ?
cleancache_get_key+0x4a/0x60
Feb 14 02:06:16 lupus kernel: [   93.968820]  [<ffffffff810e6b3a>] ?
__cleancache_get_page+0x7a/0xd0
Feb 14 02:06:16 lupus kernel: [   93.968914]  [<ffffffff8132e4de>] ?
__extent_read_full_page+0x52e/0x710
Feb 14 02:06:16 lupus kernel: [   93.969008]  [<ffffffff812f3f93>] ?
update_reserved_bytes+0xb3/0x140
Feb 14 02:06:16 lupus kernel: [   93.969102]  [<ffffffff81305060>] ?
btree_get_extent+0x0/0x1c0
Feb 14 02:06:16 lupus kernel: [   93.969193]  [<ffffffff8132bb7c>] ?
merge_state+0x7c/0x150
Feb 14 02:06:16 lupus kernel: [   93.969285]  [<ffffffff81330b21>] ?
read_extent_buffer_pages+0x2d1/0x470
Feb 14 02:06:16 lupus kernel: [   93.969378]  [<ffffffff81305060>] ?
btree_get_extent+0x0/0x1c0
Feb 14 02:06:16 lupus kernel: [   93.969470]  [<ffffffff8130674d>] ?
btree_read_extent_buffer_pages.clone.65+0x4d/0xa0
Feb 14 02:06:16 lupus kernel: [   93.969602]  [<ffffffff813076f9>] ?
read_tree_block+0x39/0x60
Feb 14 02:06:16 lupus kernel: [   93.969694]  [<ffffffff812ed5e6>] ?
read_block_for_search.clone.40+0x116/0x410
Feb 14 02:06:16 lupus kernel: [   93.969878]  [<ffffffff812f0bc7>] ?
btrfs_search_slot+0x307/0xa00
Feb 14 02:06:16 lupus kernel: [   93.969970]  [<ffffffff812f6b18>] ?
lookup_inline_extent_backref+0x98/0x4a0
Feb 14 02:06:16 lupus kernel: [   93.970065]  [<ffffffff810e33d7>] ?
kmem_cache_alloc+0x87/0xa0
Feb 14 02:06:16 lupus kernel: [   93.970157]  [<ffffffff812f891c>] ?
__btrfs_free_extent+0xcc/0x6f0
Feb 14 02:06:16 lupus kernel: [   93.970249]  [<ffffffff812f8434>] ?
update_block_group.clone.62+0xc4/0x280
Feb 14 02:06:16 lupus kernel: [   93.970343]  [<ffffffff812fc4cf>] ?
run_clustered_refs+0x39f/0x880
Feb 14 02:06:16 lupus kernel: [   93.970436]  [<ffffffff812fca77>] ?
btrfs_run_delayed_refs+0xc7/0x220
Feb 14 02:06:16 lupus kernel: [   93.970529]  [<ffffffff810e15f9>] ?
new_slab+0x169/0x1f0
Feb 14 02:06:16 lupus kernel: [   93.970619]  [<ffffffff8130c29c>] ?
btrfs_commit_transaction+0x7c/0x760
Feb 14 02:06:16 lupus kernel: [   93.970713]  [<ffffffff81067ea0>] ?
autoremove_wake_function+0x0/0x30
Feb 14 02:06:16 lupus kernel: [   93.970806]  [<ffffffff81305bc3>] ?
transaction_kthread+0x283/0x2a0
Feb 14 02:06:16 lupus kernel: [   93.970898]  [<ffffffff81305940>] ?
transaction_kthread+0x0/0x2a0
Feb 14 02:06:16 lupus kernel: [   93.970990]  [<ffffffff81305940>] ?
transaction_kthread+0x0/0x2a0
Feb 14 02:06:16 lupus kernel: [   93.971083]  [<ffffffff81067a16>] ?
kthread+0x96/0xa0
Feb 14 02:06:16 lupus kernel: [   93.971174]  [<ffffffff81003514>] ?
kernel_thread_helper+0x4/0x10
Feb 14 02:06:16 lupus kernel: [   93.971266]  [<ffffffff81067980>] ?
kthread+0x0/0xa0
Feb 14 02:06:16 lupus kernel: [   93.971355]  [<ffffffff81003510>] ?
kernel_thread_helper+0x0/0x10
Feb 14 02:06:16 lupus kernel: [   93.971444] Code: 55 b8 ff 00 00 00
53 48 89 fb 48 83 ec 18 48 8b 6f 10 8b 3a 83 ff 04 0f 86 d5 00 00 00
85 c9 0f 95 c1 83 ff 07 0f 86 d5 00 00 00 <48> 8b 45 50 bf 05 00 00 00
48 89 06 84 c9 48 8b 85 68 fe ff ff
Feb 14 02:06:16 lupus kernel: [   93.974280] RIP  [<ffffffff8133ef1b>]
btrfs_encode_fh+0x2b/0x120
Feb 14 02:06:16 lupus kernel: [   93.974412]  RSP <ffff88023c63b6e0>
Feb 14 02:06:16 lupus kernel: [   93.974497] CR2: 0000030341ed0050
Feb 14 02:06:16 lupus kernel: [   93.974599] ---[ end trace
3313552d105b1536 ]---
Feb 14 02:07:04 lupus kernel: [  141.906124] zcache: destroyed pool id=2
Feb 14 02:07:17 lupus kernel: [  154.783358] SysRq : Keyboard mode set
to system default
Feb 14 02:07:18 lupus kernel: [  155.486147] SysRq : Terminate All Tasks


That's all for now

Thanks & Regards

Matt

(leaving out several folks from the CC to avoid spamming - if I left
out someone wrongfully please re-add)

running an addr2line reveals:


addr2line -e /usr/src/linux-2.6.37_vanilla/vmlinux -i ffffffff81338cbb
export.c:0


hope that helps


Regards

Matt

Just my guessing. I might be wrong.

__cleancache_flush_inode calls cleancache_get_key with cleancache_filekey.
cleancache_file_key's size is just 6 * u32.
cleancache_get_key calls btrfs_encode_fh with the key.
but btrfs_encode_fh does typecasting the key to btrfs_fid which is
bigger size than cleancache_filekey's one so it should not access
fields beyond cleancache_get_key.

I think some file systems use extend fid so in there, this problem can
happen. I don't know why we can't find it earlier. Maybe Dan and
others test it for a long time.

Am I missing something?



-- 
Kind regards,
Minchan Kim

--
To unsubscribe, send a message with 'unsubscribe linux-mm' in
the body to majordomo@kvack.org.  For more info on Linux MM,
see: http://www.linux-mm.org/ .
Fight unfair telecom internet charges in Canada: sign http://stopthemeter.ca/
Don't email: <a href=mailto:"dont@kvack.org"> email@kvack.org </a>