Re: [PATCH V2 0/3] drivers/staging: zcache: dynamic page cache/swap compression

[Minchan Kim <minchan.kim@gmail.com>]

On Mon, Feb 14, 2011 at 10:29 AM, Matt <jackdachef@gmail.com> wrote:
> On Mon, Feb 14, 2011 at 1:24 AM, Matt <jackdachef@gmail.com> wrote:
>> On Mon, Feb 14, 2011 at 12:08 AM, Matt <jackdachef@gmail.com> wrote:
>>> On Wed, Feb 9, 2011 at 1:03 AM, Dan Magenheimer
>>> <dan.magenheimer@oracle.com> wrote:
>>> [snip]
>>>>
>>>> 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