Details
-
Bug
-
Resolution: Fixed
-
Blocker
-
None
-
Lustre 1.8.6
-
None
-
RH6, recompiled kernel, OFED 1.5.3 RC3/4/5 (bug does not depend on OFED version)
-
4
-
8549
Description
bug already described in https://bugzilla.redhat.com/show_bug.cgi?id=678175
Lustre 1.8.5 works without problems in RH5. Switching to RH6 I get Kernel Panic
errors halting the system. As far as I can tell this happens only if Read and
Writes calls are used at the same time. Using 12 threads Read or 12 threads
Writing has not caused this issue to appear. Note - it's not possible to
completely reproduce this issue. Sometimes the error happens after 2min,
sometimes it takes 15min. So I'm pretty sure this is a race condition.
The Kernel Panic happens in conjunction with the "page" structure. Lustre uses
"page->private" to store a pointer to private information. Sometimes this value
- which obviously should be either NULL or a pointer to a valid Kernel address
- is set to "2". This disables all checks in Lustre for "page->private ==
NULL", and a subsequent access "page->private->ll_magic" causes the panic. I
probably could set "page->private" to NULL in such a case, but that would only
hide the sympton, not remedy the root cause and thereby most likley introduce a
new error.
From the Kernel traces I was able to recreate the callpath:
llap_cast_private+0x18/0xa0
llap_from_page_with_lockh.clone.8+0x1484/0x1cf0 [lustre]
(inline: ll_readahead_page)
(inline: ll_readahead_pages)
ll_readahead+0xf59/0x1ca0 [lustre]
ll_readpage+0x29b/0x2270 [lustre]
generic_file_aio_read+0x1f0/0x730
ll_file_aio_read+0xcd6/0x2720 [lustre]
ll_file_read+0xd0/0xf0 [lustre]
vfs_read+0xb5/0x1a0
sys_read+0x51/0x90
system_call_fastpath+0x16/0x1b
tracing back the origins of page->private==2 lead me to the call
page = grab_cache_page_nowait(mapping, index);
This function returns sometimes page->private is already set to "2". From what
I could see in the Lustre sources "page->private" is always treated to store a
pointer into kernel space. It is therefore very unlikely that Lustre causes
this error itself, especially as the code works on RH5
This leads me to the following questions:
a) If the page was not in the cache and has been freshly allocated - should
page->private be 0? Cause it looks to me it this is not always the case. The
page->private==2 error is already present when the function returns.
b) Is there a simple way to distinguish between a page freshly allocated and
one already residing in the page cache?
I attached a sosreport as well
thanks
Michael
############################################################################
############################################################################
[root@et06 crt]# uname -r
2.6.32-71.14.1.el6.x86_64.crt
############################################################################
A typical panic originally looked like:
############################################################################
BUG: unable to handle kernel NULL pointer dereference at 0000000000000002
IP: [<ffffffffa0889d08>] llap_cast_private+0x18/0xa0 [lustre]
PGD 32d72a067 PUD 330da0067 PMD 0
Oops: 0000 1 SMP
last sysfs file: /sys/module/ipv6/initstate
CPU 20
Modules linked in: mgc(U) lustre(U) lov(U) mdc(U) lquota(U) osc(U) ko2iblnd(U)
ptlrpc(U) obdclass(U) lnet(U) lvfs(U) libcfs(U) nfs lockd fscache nfs_acl
auth_rpcgss acpi_cpufreq freq_table sunrpc rdma_ucm(U) ib_sdp(U) rdma_cm(U)
iw_cm(U) ib_addr(U) ib_ipoib(U) ib_cm(U) ib_sa(U) ipv6 ib_uverbs(U) ib_umad(U)
mlx4_ib(U) ib_mad(U) ib_core(U) mlx4_core(U) ext2 dm_mirror dm_region_hash
dm_log dm_mod radeon ttm drm_kms_helper drm i2c_algo_bit serio_raw i2c_i801
i2c_core sg iTCO_wdt iTCO_vendor_support pata_jmicron i7core_edac edac_core
shpchp igb dca ext3 jbd mbcache sr_mod cdrom sd_mod crc_t10dif usb_storage ahci
ata_generic pata_acpi [last unloaded: cpufreq_ondemand]
Modules linked in: mgc(U) lustre(U) lov(U) mdc(U) lquota(U) osc(U) ko2iblnd(U)
ptlrpc(U) obdclass(U) lnet(U) lvfs(U) libcfs(U) nfs lockd fscache nfs_acl
auth_rpcgss acpi_cpufreq freq_table sunrpc rdma_ucm(U) ib_sdp(U) rdma_cm(U)
iw_cm(U) ib_addr(U) ib_ipoib(U) ib_cm(U) ib_sa(U) ipv6 ib_uverbs(U) ib_umad(U)
mlx4_ib(U) ib_mad(U) ib_core(U) mlx4_core(U) ext2 dm_mirror dm_region_hash
dm_log dm_mod radeon ttm drm_kms_helper drm i2c_algo_bit serio_raw i2c_i801
i2c_core sg iTCO_wdt iTCO_vendor_support pata_jmicron i7core_edac edac_core
shpchp igb dca ext3 jbd mbcache sr_mod cdrom sd_mod crc_t10dif usb_storage ahci
ata_generic pata_acpi [last unloaded: cpufreq_ondemand]
Pid: 3477, comm: bonnie Not tainted 2.6.32-71.14.1.el6.x86_64.crt #1 X8DTN
RIP: 0010:[<ffffffffa0889d08>] [<ffffffffa0889d08>]
llap_cast_private+0x18/0xa0 [lustre]
RSP: 0018:ffff880553371748 EFLAGS: 00010202
RAX: 0000000000000002 RBX: ffff880264d18000 RCX: ffff88009e7487e8
RDX: ffff8805533719a8 RSI: 0000000000000002 RDI: ffffea0002988c48
RBP: ffff880553371788 R08: 0000000000000002 R09: ffffea0002988c50
R10: ffff8805fe3b43c0 R11: 0000000000000010 R12: ffff88032f6e2df0
R13: ffffea0002988c48 R14: ffff88032f6e2cd0 R15: ffff88032fca8800
FS: 00002b219d82fb20(0000) GS:ffff88034ad00000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
CR2: 0000000000000002 CR3: 000000032d7ae000 CR4: 00000000000006e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Process bonnie (pid: 3477, threadinfo ffff880553370000, task ffff8805761f54a0)
Stack:
000000003f818000 ffffea0002988c10 ffff8805533717b8 ffffffffa05cbaef
<0> ffff88062f0a2200 0000000000000000 ffff880553371798 ffff88062f0a2200
<0> ffff880553371868 ffffffffa088e921 ffff880553371818 ffffffffa0648daa
Call Trace:
[<ffffffffa05cbaef>] ? class_handle2object+0x8f/0x1c0 [obdclass]
[<ffffffffa088e921>] llap_from_page_with_lockh.clone.8+0xa1/0x1120 [lustre]
[<ffffffffa0648daa>] ? ldlm_lock_decref_internal+0xba/0x880 [ptlrpc]
[<ffffffffa0645bbf>] ? __ldlm_handle2lock+0x9f/0x3d0 [ptlrpc]
[<ffffffffa088d961>] ? ll_issue_page_read+0x131/0x420 [lustre]
[<ffffffff8110c07e>] ? find_get_page+0x1e/0xa0
[<ffffffffa0891869>] ll_readahead+0xf59/0x1ca0 [lustre]
[<ffffffffa0643651>] ? ldlm_lock_add_to_lru_nolock+0x51/0xe0 [ptlrpc]
[<ffffffffa0643879>] ? ldlm_lock_add_to_lru+0x49/0x110 [ptlrpc]
[<ffffffffa088eb21>] ? llap_from_page_with_lockh.clone.8+0x2a1/0x1120 [lustre]
[<ffffffffa0894475>] ll_readpage+0x165/0x1da0 [lustre]
[<ffffffffa0643984>] ? ldlm_lock_remove_from_lru+0x44/0x110 [ptlrpc]
[<ffffffffa0643bb2>] ? ldlm_lock_fast_match+0xc2/0x130 [ptlrpc]
[<ffffffff812637ed>] ? copy_user_generic_string+0x2d/0x40
[<ffffffff8110d3e0>] generic_file_aio_read+0x1f0/0x730
[<ffffffffa086ee8c>] ll_file_aio_read+0xc8c/0x2610 [lustre]
[<ffffffffa08708e0>] ll_file_read+0xd0/0xf0 [lustre]
[<ffffffff81091de0>] ? autoremove_wake_function+0x0/0x40
[<ffffffff811ffb76>] ? security_file_permission+0x16/0x20
[<ffffffff8116cf7d>] ? rw_verify_area+0x5d/0xc0
[<ffffffff8116d905>] vfs_read+0xb5/0x1a0
[<ffffffff8116da41>] sys_read+0x51/0x90
[<ffffffff81013172>] system_call_fastpath+0x16/0x1b
Code: ff ff 90 4c 8b 5d c8 4d 29 f3 4c 03 5d c0 e9 d3 fe ff ff 55 48 89 e5 48
83 ec 40 0f 1f 44 00 00 48 8b 47 10 48 85 c0 75 02 c9 c3 <8b> 10 81 fa 21 06 e3
05 74 f4 89 54 24 28 48 89 44 24 20 ba 00
RIP [<ffffffffa0889d08>] llap_cast_private+0x18/0xa0 [lustre]
RSP <ffff880553371748>
CR2: 0000000000000002
--[ end trace 2a22ba0ec9d8ad43 ]--
Kernel panic - not syncing: Fatal exception
Pid: 3477, comm: bonnie Tainted: G D ----------------
2.6.32-71.14.1.el6.x86_64.crt #1
Call Trace:
[<ffffffff814c8183>] panic+0x78/0x137
[<ffffffff814cc254>] oops_end+0xe4/0x100
Feb 4 10:56:01 [<ffffffff8104651b>] no_context+0xfb/0x260
et06 kernel: BUG [<ffffffff810467a5>] __bad_area_nosemaphore+0x125/0x1e0
: unable to hand [<ffffffff810468ce>] bad_area+0x4e/0x60
le kernel NULL p [<ffffffff814cdda0>] do_page_fault+0x390/0x3a0
ointer dereferen [<ffffffff814cb5a5>] page_fault+0x25/0x30
ce at 0000000000 [<ffffffffa0889d08>] ? llap_cast_private+0x18/0xa0 [lustre]
000002
Feb 4 10 [<ffffffffa05cbaef>] ? class_handle2object+0x8f/0x1c0 [obdclass]
:56:01 et06 kern [<ffffffffa088e921>]
llap_from_page_with_lockh.clone.8+0xa1/0x1120 [lustre]
el: BUG: unable [<ffffffffa0648daa>] ? ldlm_lock_decref_internal+0xba/0x880
[ptlrpc]
to handle kernel [<ffffffffa0645bbf>] ? __ldlm_handle2lock+0x9f/0x3d0 [ptlrpc]
NULL pointer de [<ffffffffa088d961>] ? ll_issue_page_read+0x131/0x420 [lustre]
reference at 000 [<ffffffff8110c07e>] ? find_get_page+0x1e/0xa0
0000000000002
Fe [<ffffffffa0891869>] ll_readahead+0xf59/0x1ca0 [lustre]
b 4 10:56:01 et [<ffffffffa0643651>] ? ldlm_lock_add_to_lru_nolock+0x51/0xe0
[ptlrpc]
06 kernel: IP: [ [<ffffffffa0643879>] ? ldlm_lock_add_to_lru+0x49/0x110
[ptlrpc]
<ffffffffa0889d0 [<ffffffffa088eb21>] ?
llap_from_page_with_lockh.clone.8+0x2a1/0x1120 [lustre]
8>] llap_cast_pr [<ffffffffa0894475>] ll_readpage+0x165/0x1da0 [lustre]
ivate+0x18/0xa0 [<ffffffffa0643984>] ? ldlm_lock_remove_from_lru+0x44/0x110
[ptlrpc]
[lustre]
Feb 4 [<ffffffffa0643bb2>] ? ldlm_lock_fast_match+0xc2/0x130 [ptlrpc]
10:56:01 et06 ke [<ffffffff812637ed>] ? copy_user_generic_string+0x2d/0x40
rnel: IP: [<ffff [<ffffffff8110d3e0>] generic_file_aio_read+0x1f0/0x730
ffffa0889d08>] l [<ffffffffa086ee8c>] ll_file_aio_read+0xc8c/0x2610 [lustre]
lap_cast_private [<ffffffffa08708e0>] ll_file_read+0xd0/0xf0 [lustre]
+0x18/0xa0 [lust [<ffffffff81091de0>] ? autoremove_wake_function+0x0/0x40
re]
Feb 4 10:56 [<ffffffff811ffb76>] ? security_file_permission+0x16/0x20
:01 et06 kernel: [<ffffffff8116cf7d>] ? rw_verify_area+0x5d/0xc0
PGD 32d72a067 P [<ffffffff8116d905>] vfs_read+0xb5/0x1a0
UD 330da0067 PMD [<ffffffff8116da41>] sys_read+0x51/0x90
0
Feb 4 10:56 [<ffffffff81013172>] system_call_fastpath+0x16/0x1b
:01 et06 kernel:panic occurred, switching back to text console
###########################################################################
############################################################################
[root@et06 crt]# modinfo lustre
filename:
/lib/modules/2.6.32-71.14.1.el6.x86_64.crt/updates/kernel/fs/lustre/lustre.ko
license: GPL
description: Lustre Lite Client File System
author: Sun Microsystems, Inc. <http://www.lustre.org/>
srcversion: 83AC865556E2AE50715D831
depends: obdclass,mdc,ptlrpc,libcfs,lvfs,lov,osc,lnet
vermagic: 2.6.32-71.14.1.el6.x86_64.crt SMP mod_unload modversions
[root@et06 crt]# gdb
/lib/modules/2.6.32-71.14.1.el6.x86_64.crt/updates/kernel/fs/lustre/lustre.ko
...
Reading symbols from
/lib/modules/2.6.32-71.14.1.el6.x86_64.crt/updates/kernel/fs/lustre/lustre.ko...done.
(gdb) disassemble /m *(llap_cast_private+0x18/0xa0)
Dump of assembler code for function llap_cast_private:
538
0x0000000000036d36 <+22>: leaveq
0x0000000000036d37 <+23>: retq
End of assembler dump.
Attachments
Issue Links
- is related to
-
-
- Resolved
-
- Trackbacks
-
![[Confluence: Engineering]](/images/icons/generic_link_16.png "[Confluence: Engineering]")
Lustre 1.8.x known issues tracker
While testing against Lustre b18 branch, we would hit known bugs which were already reported in Lustre Bugzilla https://bugzilla.lustre.org/. In order to move away from relying on Bugzilla, we would create a JIRA
Activity
For the record, another customer also reported some weird assertion failures (although not the
same assertion as in this bug) with the SLES11 SP1 kernel. Somehow PG_locked was cleared
behind our back. Surprisingly, it also turned out to be a BIOS issue.
Unfortunately, the bugzilla ticket (i.e. bug 23880) is private.
Note: at this point it is NOT clear if this is a Lustre bug or root caused by a hardware/BIOS problem. Fact is, an upgrade of BIOS greatly reduced the frequency of the kernel panic. Another indicator for hardware problem is, that on a different platform the error could not be reproduced even after 10days of testing.
Current hypothesis: a page is cached by the kernel; multiple times "unlock_page()" is acting on this page while page->private is already equal to "2". When a "ll_readpage()" is called on this page, this leads to kernel panic.
The only function found so far within this contexts that sets page->private is free_hot_page. In some cases via inserting printk statements it was possible to show, that the Lustre function page_cache_release (which calls free_hot_page) had acted on the same page that later caused the panic (see below for example).
Tasks after meeting 2011-03-09:
1) verify if panic is a Software or a Hardware problem:
a) analyze the code paths - is it possible due to a race condition to execute free_hot_page() but keep the page in the page-cache?
b) analyze code path - is it possible that re-using a page does not clear "page->private" correctly?
2) Performance hit:
c) reproduce at Whamcloud single client performance. Intel reaches (writing with dd a single 50GB file) 1.3GB/s; client is NHM/WSM (2.8GHz-3GHz), RH 5.4, Lustre 1.6.7; Server is Lustre 1.8.1 (or 1.6X on different system, but dd performance remains identical). No checksums
3) next meeting via Skype - Thursday 2011-03-10 evening PST
> > LDEBUGZ0064: ffffea00014f57c8 Lustre/llap_shrink_cache_internal after calling page_cache_release)
> > ...
> > LDEBUGMM:26 ffffea00014f57c8 Kernel:mm/filemap.c, find_get_page()
> > LDEBUGMM:27 ffffea00014f57c8
> > LDEBUGMM:28 ffffea00014f57c8
> > LDEBUGZ0175: ffffea00014f57c8 copy of grab_cache_page_nowait(); copied to my lustre code and modified to differentiate between "page found in cache" and "new page created")
> > LDEBUGLe: ffffea00014f57c8 Lustre: Read-ahead function after grab_cache_page returns
> > LDEBUGLi: ffffea00014f57c8
> > LDEBUGA1: ffffea00014f57c8 Lustre: llap_from_page_with_lockh()
> >
> > first item is the location, second part is page (aka the kernel address of the page structure). So the same page that later causes the trouble has been released once. let's go over the code parts in detail:
> >
> > as part of shrinking an Lustre internal cache in llap_shrink_cache_internal Lustre calls
> >
> > unlock_page(page);
> > page_cache_release(page);
> >
> > ll_pglist_cpu_lock(sbi, cpu);
> >
> > After page_cache_release (location LDEBUGZ0064) the pointer page->private==2. page cache release is a simple #define, leading to free_hot_cold_page(). I guess at the lines marked with XX page->private is set to 2:
> >
> >
> > #define page_cache_release(page) __free_pages(page, 0)
> >
> > void __free_pages(struct page *page, unsigned int order)
> > {
> > if (put_page_testzero(page)) {
> > trace_mm_page_free_direct(page, order);
> > if (order == 0)
> > free_hot_page(page);
> > else
> > __free_pages_ok(page, order);
> > }
> > }
> >
> > void free_hot_page(struct page *page)
> > {
> > trace_mm_page_free_direct(page, 0);
> > free_hot_cold_page(page, 0);
> > }
> >
> > static void free_hot_cold_page(struct page *page, int cold)
> > {
> > struct zone *zone = page_zone(page);
> > struct per_cpu_pages *pcp;
> > unsigned long flags;
> > int migratetype;
> > int wasMlocked = __TestClearPageMlocked(page);
> >
> > kmemcheck_free_shadow(page, 0);
> >
> > if (PageAnon(page))
> > page->mapping = NULL;
> > if (free_pages_check(page))
> > return;
> >
> > if (!PageHighMem(page)) {
> > debug_check_no_locks_freed(page_address(page), PAGE_SIZE);
> > debug_check_no_obj_freed(page_address(page), PAGE_SIZE);
> > }
> > arch_free_page(page, 0);
> > kernel_map_pages(page, 1, 0);
> >
> > pcp = &zone_pcp(zone, get_cpu())->pcp;
> > XX migratetype = get_pageblock_migratetype(page);
> > XX set_page_private(page, migratetype);
> > local_irq_save(flags);
> > if (unlikely(wasMlocked))
> > free_page_mlock(page);
> > __count_vm_event(PGFREE);
> >
> > /*
> > * We only track unmovable, reclaimable and movable on pcp lists.
> > * Free ISOLATE pages back to the allocator because they are being
> > * offlined but treat RESERVE as movable pages so we can get those
> > * areas back if necessary. Otherwise, we may have to free
> > * excessively into the page allocator
> > */
> > if (migratetype >= MIGRATE_PCPTYPES) {
> > if (unlikely(migratetype == MIGRATE_ISOLATE)) {
> > free_one_page(zone, page, 0, migratetype);
> > goto out;
> > }
> > migratetype = MIGRATE_MOVABLE;
> > }
> >
> > if (cold)
> > list_add_tail(&page->lru, &pcp->lists[migratetype]);
> > else
> > list_add(&page->lru, &pcp->lists[migratetype]);
> > pcp->count++;
> > if (pcp->count >= pcp->high) {
> > free_pcppages_bulk(zone, pcp->batch, pcp);
> > pcp->count -= pcp->batch;
> > }
> >
> > out:
> > local_irq_restore(flags);
> > put_cpu();
> >
> >
> > /*
> > * Drop a ref, return true if the refcount fell to zero (the page has no users)
> > */
> > static inline int put_page_testzero(struct page *page)
> > {
> > VM_BUG_ON(atomic_read(&page->_count) == 0);
> > return atomic_dec_and_test(&page->_count);
> > }
> >
> > /*
> > * Try to grab a ref unless the page has a refcount of zero, return false if
> > * that is the case.
> > */
> > static inline int get_page_unless_zero(struct page *page)
> > {
> > return atomic_inc_not_zero(&page->_count);
> > }
> >
> >
> > The Lustre part follows this calling structure:
> >
> > read_page (called by kernel via standard address_space operations)
> > -> Read-ahead
> > -> grab_cache_page_nowait()
> > -> find_get_page() (success, page is in page cache but page->private == 2)
> >
> > llap = llap_from_page_with_lockh(page, LLAP_ORIGIN_READAHEAD, &lockh, flags);
> > -> cast_private (tries to dereference page->private->llap_magic)
> > PANIC
> >
> >
> >
> > struct page * grab_cache_page_nowait(struct address_space *mapping, pgoff_t index)
> > {
> > struct page *page = find_get_page(mapping, index);
> >
> > if (page) {
> > if (trylock_page(page))
> > return page;
> >
> > page_cache_release(page);
> > return NULL;
> > }
> > page = __page_cache_alloc(mapping_gfp_mask(mapping) & ~__GFP_FS);
> > if (page && add_to_page_cache_lru(page, mapping, index, GFP_NOFS)) {
> > page_cache_release(page);
> > page = NULL;
> > }
> > return page;
> > }
> >
> > struct page *find_get_page(struct address_space *mapping, pgoff_t offset)
> > {
> > void **pagep;
> > struct page *page;
> >
> > rcu_read_lock();
> > repeat:
> > page = NULL;
> > pagep = radix_tree_lookup_slot(&mapping->page_tree, offset);
> > if (pagep) {
> > page = radix_tree_deref_slot(pagep);
> > if (unlikely(!page || page == RADIX_TREE_RETRY))
> > goto repeat;
> >
> > # AT THIS point page->private is already ==2
> >
> >
Michael, you can checkout 1.8.6 code with this:
git clone git://git.whamcloud.com/fs/lustre-release.git
and then you can apply patch the rhel6.
for redhat bugzilla comment 8, that piece of code is called in ll_removepage(), and this function is called in
.commit_write (ll_commit_write)
.invalidatepage (ll_invalidatepage)
.releasepage (ll_releasepage)
while all these functions require page locked before entering, so the comment just explains this.
for redhat bugzilla comment 11, I have explained above: page_cache_release is not redefined for linux kernel, that definition is for liblustre.
I created a special kernel with a lot of "if(page->private==2){printk "LDEBUG##";} statementents. This test showed quite a few occurrences of this error long before the panic. So the pages where in page cache, but most likely got reclaimed before they were used.
first appearance of any page->private == 2:
LDEBUGMN16 ffffea000b20de88 __set_page_dirty_nobuffers()
LDEBUGMM18 ffffea000b20de88 2 2 ffff88062f139511 40000000100059 unlock_page()
LDEBUGMM14 ffffea000b20de88 2 2 ffff88062f139511 40000000100058 page_waitqueue()
LDEBUGMM13 ffffea000b20de88 2 2 ffff88062f139511 40000000100058 page_waitqueue()
LDEBUGMM19 ffffea000b20de88 2 2 ffff88062f139511 40000000100058 unlock_page()
LDEBUGMQ20 ffffea000b20de88 lru_cache_add_lru()
LDEBUGMQ18 ffffea000b20de88 __lru_cache_add() ;
LDEBUGMQ19 ffffea000b20de88 __lru_cache_add() ;
LDEBUGMQ21 ffffea000b20de88 lru_cache_add_lru()
LDEBUGMQ08a ffffea000b20de88 put_page()
… Many more examples of same block
First appearance of page->private == 2 actually leading to panic
LDEBUGMM18 ffffea0015a228d8 2 2 ffff880630f1ba30 c000000000000d unlock_page()
LDEBUGMM14 ffffea0015a228d8 2 2 ffff880630f1ba30 c000000000000c page_waitqueue()
LDEBUGMM13 ffffea0015a228d8 2 2 ffff880630f1ba30 c000000000000c page_waitqueue()
LDEBUGMM19 ffffea0015a228d8 2 2 ffff880630f1ba30 c000000000000c unlock_page()
..
.. repeated number of times
..
LDEBUGMM26 ffffea0015a10888 2 1 ffff880630f1ba30 c0000000000020 find_get_page()
LDEBUGMM27 ffffea0015a10888 2 2 ffff880630f1ba30 c0000000000020 find_get_page()
LDEBUGMM28 ffffea0015a10888 2 2 ffff880630f1ba30 c0000000000020 find_get_page()
LDEBUGMM36 ffffea0015a10888 2 2 ffff880630f1ba30 c0000000000020 do_generic_file_read()
LDEBUGMM42 ffffea0015a10888 2 2 ffff880630f1ba30 c0000000000021 do_generic_file_read()
LDEBUGMM43 ffffea0015a10888 2 2 ffff880630f1ba30 c0000000000021 do_generic_file_read()
LDEBUGB1a: ffffea0015a10888 2 2 ffff880630f1ba30 c0000000000021 lustre/rw.c/ll_readpage()
Kernel code with my printk:
#define MYDEBUG(A) if(page && page->private==2){printk("LDEBUGMM:"A" %lx %lx %d %lx %lx\n",(long int) page,(long int)page->private, page_count(page), (long int) page->mapping, page->flags);}
### mm/page-writeback.c
int __set_page_dirty_nobuffers(struct page *page)
{
if (!TestSetPageDirty(page)) {
struct address_space *mapping = page_mapping(page);
struct address_space *mapping2;
MYDEBUG("LDEBUGMN16");
if (!mapping)
return 1;
spin_lock_irq(&mapping->tree_lock);
mapping2 = page_mapping(page);
if (mapping2) { /* Race with truncate? */
BUG_ON(mapping2 != mapping);
WARN_ON_ONCE(!PagePrivate(page) && !PageUptodate(page));
account_page_dirtied(page, mapping);
radix_tree_tag_set(&mapping->page_tree,
page_index(page), PAGECACHE_TAG_DIRTY);
}
spin_unlock_irq(&mapping->tree_lock);
MYDEBUG("LDEBUGMN17");
if (mapping->host) {
/* !PageAnon && !swapper_space */
__mark_inode_dirty(mapping->host, I_DIRTY_PAGES);
}
return 1;
}
return 0;
}
### mm/filemap.c
void unlock_page(struct page *page)
{
MYDEBUGDS("LDEBUGMM18");
VM_BUG_ON(!PageLocked(page));
clear_bit_unlock(PG_locked, &page->flags);
smp_mb__after_clear_bit();
wake_up_page(page, PG_locked);
MYDEBUG("LDEBUGMM19");
}
static wait_queue_head_t *page_waitqueue(struct page *page)
{
const struct zone *zone = page_zone(page);
MYDEBUG("LDEBUGMM13");
return &zone->wait_table[hash_ptr(page, zone->wait_table_bits)];
}
static inline void wake_up_page(struct page *page, int bit)
{
MYDEBUG("LDEBUGMM14");
__wake_up_bit(page_waitqueue(page), &page->flags, bit);
}
struct page *find_get_page(struct address_space *mapping, pgoff_t offset)
{
void **pagep;
struct page *page;
rcu_read_lock();
repeat:
page = NULL;
pagep = radix_tree_lookup_slot(&mapping->page_tree, offset);
if (pagep) {
page = radix_tree_deref_slot(pagep);
if (unlikely(!page || page == RADIX_TREE_RETRY))
goto repeat;
MYDEBUG("LDEBUGMM 26");
if (!page_cache_get_speculative(page))
goto repeat;
MYDEBUG("LDEBUGMM27");
/*
* Has the page moved?
* This is part of the lockless pagecache protocol. See
* include/linux/pagemap.h for details.
*/
if (unlikely(page != *pagep)) {
page_cache_release(page);
goto repeat;
}
}
rcu_read_unlock();
MYDEBUG("LDEBUGMM28");
return page;
}
static void do_generic_file_read(struct file *filp, loff_t *ppos,
read_descriptor_t *desc, read_actor_t actor)
{
struct address_space *mapping = filp->f_mapping;
struct inode *inode = mapping->host;
struct file_ra_state *ra = &filp->f_ra;
pgoff_t index;
pgoff_t last_index;
pgoff_t prev_index;
unsigned long offset; /* offset into pagecache page */
unsigned int prev_offset;
int error;
index = *ppos >> PAGE_CACHE_SHIFT;
prev_index = ra->prev_pos >> PAGE_CACHE_SHIFT;
prev_offset = ra->prev_pos & (PAGE_CACHE_SIZE-1);
last_index = (*ppos + desc->count + PAGE_CACHE_SIZE-1) >> PAGE_CACHE_SHIFT;
offset = *ppos & ~PAGE_CACHE_MASK;
for (;;) {
struct page *page;
pgoff_t end_index;
loff_t isize;
unsigned long nr, ret;
cond_resched();
find_page:
page = find_get_page(mapping, index);
if (!page) {
page_cache_sync_readahead(mapping,
ra, filp,
index, last_index - index);
page = find_get_page(mapping, index);
if (unlikely(page == NULL))
goto no_cached_page;
}
MYDEBUG("LDEBUGMM36");
if (PageReadahead(page)) {
page_cache_async_readahead(mapping,
ra, filp, page,
index, last_index - index);
MYDEBUG("LDEBUGMM37");
}
if (!PageUptodate(page)) {
if (inode->i_blkbits == PAGE_CACHE_SHIFT ||
!mapping->a_ops->is_partially_uptodate)
goto page_not_up_to_date;
if (!trylock_page(page))
goto page_not_up_to_date;
if (!mapping->a_ops->is_partially_uptodate(page,
desc, offset))
goto page_not_up_to_date_locked;
MYDEBUG(“LDEBUGMM38");
unlock_page(page);
}
page_ok:
/*
* i_size must be checked after we know the page is Uptodate.
*
* Checking i_size after the check allows us to calculate
* the correct value for "nr", which means the zero-filled
* part of the page is not copied back to userspace (unless
* another truncate extends the file - this is desired though).
*/
MYDEBUG("LDEBUGMM39");
isize = i_size_read(inode);
end_index = (isize - 1) >> PAGE_CACHE_SHIFT;
if (unlikely(!isize || index > end_index)) {
page_cache_release(page);
goto out;
}
/* nr is the maximum number of bytes to copy from this page */
nr = PAGE_CACHE_SIZE;
if (index == end_index) {
nr = ((isize - 1) & ~PAGE_CACHE_MASK) + 1;
if (nr <= offset) {
page_cache_release(page);
goto out;
}
}
nr = nr - offset;
/* If users can be writing to this page using arbitrary
* virtual addresses, take care about potential aliasing
* before reading the page on the kernel side.
*/
if (mapping_writably_mapped(mapping))
flush_dcache_page(page);
MYDEBUG("LDEBUGMM40");
/*
* When a sequential read accesses a page several times,
* only mark it as accessed the first time.
*/
if (prev_index != index || offset != prev_offset)
mark_page_accessed(page);
prev_index = index;
/*
* Ok, we have the page, and it's up-to-date, so
* now we can copy it to user space...
*
* The actor routine returns how many bytes were actually used..
* NOTE! This may not be the same as how much of a user buffer
* we filled up (we may be padding etc), so we can only update
* "pos" here (the actor routine has to update the user buffer
* pointers and the remaining count).
*/
ret = actor(desc, page, offset, nr);
offset += ret;
index += offset >> PAGE_CACHE_SHIFT;
offset &= ~PAGE_CACHE_MASK;
prev_offset = offset;
MYDEBUG("LDEBUGMM41");
page_cache_release(page);
if (ret == nr && desc->count)
continue;
goto out;
page_not_up_to_date:
/* Get exclusive access to the page ... */
error = lock_page_killable(page);
if (unlikely(error))
goto readpage_error;
MYDEBUG("LDEBUGMM42");
page_not_up_to_date_locked:
/* Did it get truncated before we got the lock? */
if (!page->mapping) {
unlock_page(page);
page_cache_release(page);
continue;
}
/* Did somebody else fill it already? */
if (PageUptodate(page)) {
unlock_page(page);
goto page_ok;
}
readpage:
/*
* A previous I/O error may have been due to temporary
* failures, eg. multipath errors.
* PG_error will be set again if readpage fails.
*/
MYDEBUG("LDEBUGMM43");
ClearPageError(page);
/* Start the actual read. The read will unlock the page. */
error = mapping->a_ops->readpage(filp, page);
MYDEBUG("LDEBUGMM44");
if (unlikely(error)) {
if (error == AOP_TRUNCATED_PAGE) {
page_cache_release(page);
goto find_page;
}
goto readpage_error;
}
if (!PageUptodate(page)) {
MYDEBUG("LDEBUGMM45");
error = lock_page_killable(page);
if (unlikely(error))
goto readpage_error;
if (!PageUptodate(page)) {
if (page->mapping == NULL) {
/*
* invalidate_inode_pages got it
*/
unlock_page(page);
page_cache_release(page);
goto find_page;
}
MYDEBUG("LDEBUGMM46");
unlock_page(page);
shrink_readahead_size_eio(filp, ra);
error = -EIO;
goto readpage_error;
}
MYDEBUG("LDEBUGMM47");
unlock_page(page);
}
goto page_ok;
readpage_error:
/* UHHUH! A synchronous read error occurred. Report it */
desc->error = error;
page_cache_release(page);
goto out;
no_cached_page:
/*
* Ok, it wasn't cached, so we need to create a new
* page..
*/
page = page_cache_alloc_cold(mapping);
if (!page) {
desc->error = -ENOMEM;
goto out;
}
error = add_to_page_cache_lru(page, mapping,
index, GFP_KERNEL);
if (error) {
page_cache_release(page);
if (error == -EEXIST)
goto find_page;
desc->error = error;
goto out;
}
goto readpage;
MYDEBUG("LDEBUGMM48");
}
out:
ra->prev_pos = prev_index;
ra->prev_pos <<= PAGE_CACHE_SHIFT;
ra->prev_pos |= prev_offset;
*ppos = ((loff_t)index << PAGE_CACHE_SHIFT) + offset;
file_accessed(filp);
}
### mm/swap.c
void __lru_cache_add(struct page *page, enum lru_list lru)
{
struct pagevec *pvec = &get_cpu_var(lru_add_pvecs)[lru];
MYDEBUG("LDEBUGMQ18");
page_cache_get(page);
if (!pagevec_add(pvec, page))
____pagevec_lru_add(pvec, lru);
put_cpu_var(lru_add_pvecs);
MYDEBUG("LDEBUGMQ19");
}
/**
* lru_cache_add_lru - add a page to a page list
* @page: the page to be added to the LRU.
* @lru: the LRU list to which the page is added.
*/
void lru_cache_add_lru(struct page *page, enum lru_list lru)
{
MYDEBUG("LDEBUGMQ20");
if (PageActive(page)) {
VM_BUG_ON(PageUnevictable(page));
ClearPageActive(page);
} else if (PageUnevictable(page)) {
VM_BUG_ON(PageActive(page));
ClearPageUnevictable(page);
}
VM_BUG_ON(PageLRU(page) || PageActive(page) || PageUnevictable(page));
__lru_cache_add(page, lru);
MYDEBUG("LDEBUGMQ21");
}
void put_page(struct page *page)
{
MYDEBUG("LDEBUGMQ08a");
if (unlikely(PageCompound(page)))
put_compound_page(page);
else if (put_page_testzero(page))
__put_single_page(page);
}
I'm already a step further in this - that's why I wanted a telephone meeting before you go hunting :) The crash happened when running multiple Bonnies ate the same time (I've seen it happenening with as low as 4, but mostly I experienced it with 12 bonnie threads per server, aka one per CPU; each command was "bonnie -d $DIR -s 2000 -v 16 -y", $DIR set differently for every process). This bug might be influenced by a BIOS bug. I had this problem only with a specific Supermicro Westmere platform and specific BIOS version. After upgrading the BIOS the panic occurred not so often - specifically in one week of testing it happened only once. Unfortunately at that time the kernel was not set up to create a crash dump, but I have the output below. In one week testing with 2 Intel Whitebox servers I did not have any crash. At this point I'd suggest to focus on the following: a) you take a close look at my patch and see if there is room to improve it b) take a look at the Redhat site (link at top of LU-93 description) - especially at the end - are the findings there correct? c) did anyone @Whamcloud try to port 1.8.5 to RH6? What was their result? d) we previously used 1.6.7.1 clients; with the new client I see reduced write performance (writing 50GB file 1.1 GB/s instead of 1.3 GB/s; same backend - a 1.8.1 server; in both cases checksums are OFF) I will try to get another crash dump - but as long as it's not happening hunting it down might proof to be impossible Regards Michael LDEBUG2: ffffea000aac8438 2 BUG: unable to handle kernel NULL pointer dereference at 0000000000000002 IP: [<ffffffffa0896d47>] llap_cast_private+0x57/0xe0 [lustre] PGD 62fbe9067 PUD 51c03c067 PMD 0 Oops: 0000 [#1] SMP last sysfs file: /sys/module/ipv6/initstate CPU 12 Modules linked in: mgc(U) lustre(U) lov(U) mdc(U) lquota(U) osc(U) ko2iblnd(U) ptlrpc(U) obdclass(U) lnet(U) lvfs(U) libcfs(U) nfs lockd fscache nfs_acl auth_rpcgss acpi_cpufreq freq_table sunrpc rdma_ucm(U) ib_sdp(U) rdma_cm(U) iw_cm(U) ib_addr(U) ib_ipoib(U) ib_cm(U) ib_sa(U) ipv6 ib_uverbs(U) ib_umad(U) mlx4_ib(U) ib_mad(U) ib_core(U) mlx4_core(U) ext2 dm_mirror dm_region_hash dm_log dm_mod serio_raw i2c_i801 sg iTCO_wdt iTCO_vendor_support ioatdma i7core_edac edac_core shpchp igb dca ext3 jbd mbcache sd_mod crc_t10dif sr_mod cdrom usb_storage ahci pata_acpi ata_generic pata_jmicron radeon ttm drm_kms_helper drm i2c_algo_bit i2c_core [last unloaded: ipmi_msghandler] Modules linked in: mgc(U) lustre(U) lov(U) mdc(U) lquota(U) osc(U) ko2iblnd(U) ptlrpc(U) obdclass(U) lnet(U) lvfs(U) libcfs(U) nfs lockd fscache nfs_acl auth_rpcgss acpi_cpufreq freq_table sunrpc rdma_ucm(U) ib_sdp(U) rdma_cm(U) iw_cm(U) ib_addr(U) ib_ipoib(U) ib_cm(U) ib_sa(U) ipv6 ib_uverbs(U) ib_umad(U) mlx4_ib(U) ib_mad(U) ib_core(U) mlx4_core(U) ext2 dm_mirror dm_region_hash dm_log dm_mod serio_raw i2c_i801 sg iTCO_wdt iTCO_vendor_support ioatdma i7core_edac edac_core shpchp igb dca ext3 jbd mbcache sd_mod crc_t10dif sr_mod cdrom usb_storage ahci pata_acpi ata_generic pata_jmicron radeon ttm drm_kms_helper drm i2c_algo_bit i2c_core [last unloaded: ipmi_msghandler] Pid: 30539, comm: bonnie Not tainted 2.6.32-71.18.1.el6.crt.1.x86_64 #3 X8DTN RIP: 0010:[<ffffffffa0896d47>] [<ffffffffa0896d47>] llap_cast_private+0x57/0xe0 [lustre] RSP: 0018:ffff880125659738 EFLAGS: 00010202 RAX: 0000000000000022 RBX: 0000000000000002 RCX: 00000000000040b3 RDX: 0000000000000000 RSI: 0000000000000046 RDI: 0000000000000246 RBP: ffff880125659788 R08: ffffffff818a7da0 R09: 0000000000000000 R10: 0000000000000000 R11: 0000000000000000 R12: ffffea000aac8438 R13: ffffea000aac8438 R14: ffff8802fcd99210 R15: ffff88031b690600 FS: 00002adadaebbb20(0000) GS:ffff8800282c0000(0000) knlGS:0000000000000000 CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b CR2: 0000000000000002 CR3: 000000062ebf8000 CR4: 00000000000006e0 DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400 Process bonnie (pid: 30539, threadinfo ffff880125658000, task ffff880233dae100) Stack: ffff8801256597c8 ffffffffa08270f8 ffff880100000000 ffffffffa0808c1f <0> 0000000000000000 ffff880300001000 000000001500e000 000000001500efff <0> ffff88031b684000 ffff8802fcd99330 ffff880125659868 ffffffffa089b961 Call Trace: [<ffffffffa08270f8>] ? lov_stripe_size+0x248/0x3b0 [lov] [<ffffffffa0808c1f>] ? lov_queue_group_io+0x14f/0x490 [lov] [<ffffffffa089b961>] llap_from_page_with_lockh.clone.8+0xa1/0x1120 [lustre] [<ffffffffa0827527>] ? lov_merge_lvb+0xb7/0x240 [lov] [<ffffffffa0826cce>] ? lov_stripe_offset+0x28e/0x340 [lov] [<ffffffff8110c0be>] ? find_get_page+0x1e/0xa0 [<ffffffffa089ec89>] ll_readahead+0xf59/0x1ca0 [lustre] [<ffffffffa0808c1f>] ? lov_queue_group_io+0x14f/0x490 [lov] [<ffffffffa08a2663>] ll_readpage+0x1313/0x1dd0 [lustre] [<ffffffffa0650984>] ? ldlm_lock_remove_from_lru+0x44/0x110 [ptlrpc] [<ffffffffa0650bb2>] ? ldlm_lock_fast_match+0xc2/0x130 [ptlrpc] [<ffffffff81263a4d>] ? copy_user_generic_string+0x2d/0x40 [<ffffffff8110d420>] generic_file_aio_read+0x1f0/0x730 [<ffffffffa087be8c>] ll_file_aio_read+0xc8c/0x2610 [lustre] [<ffffffffa087b201>] ? ll_file_aio_read+0x1/0x2610 [lustre] [<ffffffffa087d8e0>] ll_file_read+0xd0/0xf0 [lustre] [<ffffffff81091df0>] ? autoremove_wake_function+0x0/0x40 [<ffffffff811ffdd6>] ? security_file_permission+0x16/0x20 [<ffffffff8116d13d>] ? rw_verify_area+0x5d/0xc0 [<ffffffff8116dac5>] vfs_read+0xb5/0x1a0 [<ffffffff8116dc01>] sys_read+0x51/0x90 [<ffffffff81013172>] system_call_fastpath+0x16/0x1b Code: c2 76 12 48 85 db 75 23 48 89 d8 4c 8b 65 f8 48 8b 5d f0 c9 c3 48 89 fe 48 89 da 48 c7 c7 2c 45 8c a0 31 c0 e8 54 17 c3 e0 eb d8 <8b> 03 3d 21 06 e3 05 74 d4 89 44 24 28 49 8b 44 24 10 ba 00 00 RIP [<ffffffffa0896d47>] llap_cast_private+0x57/0xe0 [lustre] RSP <ffff880125659738> CR2: 0000000000000002 ---[ end trace 84b72bca9b7c4710 ]--- Kernel panic - not syncing: Fatal exception Pid: 30539, comm: bonnie Tainted: G D ---------------- 2.6.32-71.18.1.el6.crt.1.x86_64 #3 Call Trace: [<ffffffff814c83da>] panic+0x78/0x137 [<ffffffff814cc4a4>] oops_end+0xe4/0x100 [<ffffffff8104652b>] no_context+0xfb/0x260 [<ffffffff810467b5>] __bad_area_nosemaphore+0x125/0x1e0 [<ffffffff810468de>] bad_area+0x4e/0x60 [<ffffffff8106c621>] ? vprintk+0x1d1/0x4f0 [<ffffffff814cdff0>] do_page_fault+0x390/0x3a0 [<ffffffff814cb7f5>] page_fault+0x25/0x30 [<ffffffffa0896d47>] ? llap_cast_private+0x57/0xe0 [lustre] [<ffffffffa0896d45>] ? llap_cast_private+0x55/0xe0 [lustre] [<ffffffffa08270f8>] ? lov_stripe_size+0x248/0x3b0 [lov] [<ffffffffa0808c1f>] ? lov_queue_group_io+0x14f/0x490 [lov] [<ffffffffa089b961>] llap_from_page_with_lockh.clone.8+0xa1/0x1120 [lustre] [<ffffffffa0827527>] ? lov_merge_lvb+0xb7/0x240 [lov] [<ffffffffa0826cce>] ? lov_stripe_offset+0x28e/0x340 [lov] [<ffffffff8110c0be>] ? find_get_page+0x1e/0xa0 [<ffffffffa089ec89>] ll_readahead+0xf59/0x1ca0 [lustre] [<ffffffffa0808c1f>] ? lov_queue_group_io+0x14f/0x490 [lov] [<ffffffffa08a2663>] ll_readpage+0x1313/0x1dd0 [lustre] [<ffffffffa0650984>] ? ldlm_lock_remove_from_lru+0x44/0x110 [ptlrpc] [<ffffffffa0650bb2>] ? ldlm_lock_fast_match+0xc2/0x130 [ptlrpc] [<ffffffff81263a4d>] ? copy_user_generic_string+0x2d/0x40 [<ffffffff8110d420>] generic_file_aio_read+0x1f0/0x730 [<ffffffffa087be8c>] ll_file_aio_read+0xc8c/0x2610 [lustre] [<ffffffffa087b201>] ? ll_file_aio_read+0x1/0x2610 [lustre] [<ffffffffa087d8e0>] ll_file_read+0xd0/0xf0 [lustre] [<ffffffff81091df0>] ? autoremove_wake_function+0x0/0x40 [<ffffffff811ffdd6>] ? security_file_permission+0x16/0x20 [<ffffffff8116d13d>] ? rw_verify_area+0x5d/0xc0 [<ffffffff8116dac5>] vfs_read+0xb5/0x1a0 [<ffffffff8116dc01>] sys_read+0x51/0x90 [<ffffffff81013172>] system_call_fastpath+0x16/0x1b panic occurred, switching back to text console ~. [terminated ipmitool] [mhebenst@endeavour3 ~]$ exit
Michael, your investigation into this issue is quite helpful, I agree that it's suspicious that page->private turns into 2 after page_cache_release.
And you may misunderstand that page_cache_release is not redefined in linux kernel,
#define page_cache_release(page) __free_pages(page, 0)
is for liblustre only (in user space).
I couldn't reproduce this panic in my local test environment, could you tell me how you ran 'bonnie' to trigger this?
BTW, if you'd help, could you dump page->flags also in your printk statements, it may help.
dump bad page info:
crash> struct page ffffea000b1d09a8 struct page { flags = 18014398509482017, _count = { counter = 2 }, { _mapcount = { counter = -1 }, { inuse = 65535, objects = 65535 } }, { { private = 2, mapping = 0xffff88062f1cea70 }, ptl = { raw_lock = { slock = 2 } }, slab = 0x2, first_page = 0x2 }, { index = 379628, freelist = 0x5caec }, lru = { next = 0xffffea000b1d0a08, prev = 0xffffea000b1d0998 } }