[LU-93] Kernel panic caused by Lustre 1.8.5/1.8.6 on RH6 (patchless client) Created: 23/Feb/11  Updated: 28/Jun/11  Resolved: 01/Jun/11

Status: Resolved
Project: Lustre
Component/s: None
Affects Version/s: Lustre 1.8.6
Fix Version/s: None

Type: Bug Priority: Blocker
Reporter: Michael Hebensteit (Inactive) Assignee: Lai Siyao
Resolution: Fixed Votes: 0
Labels: None
Environment:

RH6, recompiled kernel, OFED 1.5.3 RC3/4/5 (bug does not depend on OFED version)


Attachments: Text File lustre.patch    
Issue Links:
Related
is related to LU-339 add configure check for MS_HAS_NEW_AO... Resolved
Severity: 4
Epic: client, patchless_client
Rank (Obsolete): 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

{ 0x0000000000036d20 <+0>: push %rbp 0x0000000000036d21 <+1>: mov %rsp,%rbp 0x0000000000036d24 <+4>: sub $0x40,%rsp 0x0000000000036d28 <+8>: callq 0x36d2d <llap_cast_private+13> 539 struct ll_async_page *llap = (struct ll_async_page *)page_private(page); 0x0000000000036d2d <+13>: mov 0x10(%rdi),%rax 540 541 LASSERTF(llap == NULL || llap->llap_magic == LLAP_MAGIC, 0x0000000000036d31 <+17>: test %rax,%rax 0x0000000000036d34 <+20>: jne 0x36d38 <llap_cast_private+24> 0x0000000000036d38 <+24>: mov (%rax),%edx 0x0000000000036d3a <+26>: cmp $0x5e30621,%edx 0x0000000000036d40 <+32>: je 0x36d36 <llap_cast_private+22> 0x0000000000036d42 <+34>: mov %edx,0x28(%rsp) 0x0000000000036d46 <+38>: mov %rax,0x20(%rsp) 0x0000000000036d4b <+43>: mov $0x40000,%edx 0x0000000000036d50 <+48>: mov %rdi,0x18(%rsp) 0x0000000000036d55 <+53>: mov $0x80,%esi 0x0000000000036d5a <+58>: xor %edi,%edi 0x0000000000036d5c <+60>: mov $0x21f,%r9d 0x0000000000036d62 <+66>: mov $0x0,%r8 0x0000000000036d69 <+73>: mov $0x0,%rcx 0x0000000000036d70 <+80>: xor %eax,%eax 0x0000000000036d72 <+82>: movl $0x5e30621,0x30(%rsp) 0x0000000000036d7a <+90>: movq $0x0,0x10(%rsp) 0x0000000000036d83 <+99>: movq $0x0,0x8(%rsp) 0x0000000000036d8c <+108>: movq $0x0,(%rsp) 0x0000000000036d94 <+116>: callq 0x36d99 <llap_cast_private+121> 0x0000000000036d99 <+121>: mov $0x21f,%edx 0x0000000000036d9e <+126>: mov $0x0,%rsi 0x0000000000036da5 <+133>: mov $0x0,%rdi 0x0000000000036dac <+140>: callq 0x36db1 0x0000000000036db1: data32 data32 data32 data32 data32 nopw %cs:0x0(%rax,%rax,1) 542 "page %p private %lu gave magic %d which != %d\n", 543 page, page_private(page), llap->llap_magic, LLAP_MAGIC); 544 545 return llap; 546 }

0x0000000000036d36 <+22>: leaveq
0x0000000000036d37 <+23>: retq

End of assembler dump.



 Comments   
Comment by Michael Hebensteit (Inactive) [ 23/Feb/11 ]
inserting a lot of conditional printk statements (checking if page->private is equal to 2) I got the following result:

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 addres of the page structure). So the same page that later causes the trouble has been released once.

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 (never before)


#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;
        migratetype = get_pageblock_migratetype(page);
        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);
}



Read-ahead
-> grab_cache_page_nowait()
        -> find_get_page()
                Success, but page->private == 2

 llap = llap_from_page_with_lockh(page, LLAP_ORIGIN_READAHEAD, &lockh, flags);
 -> cast_private
        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


Speculation: Could there be a race condition? Something like a read process on CPU A grabbing the page while it is still being "freed"?
Nevertheless sometimes a call to find_get_page(mapping, index) returns a valid page with same address, and naturally page->private is STILL ==2
Comment by Michael Hebensteit (Inactive) [ 23/Feb/11 ]

first crashdumpfile uploaded
/uploads/LU-93/vmcore1

second file in progress

Comment by Michael Hebensteit (Inactive) [ 24/Feb/11 ]
the first upload might not have include everything necessary - specifically I did not have a vmlinux anymore - so I recompiled the kernel/OFED/Lustre, recreated the crashes - and here you go. Note - vmcore4 is incomplete, use vmcore4_try2; vmcore3 and vmcore4 are 2 crashes observed on the same kernel

ftp> cd LU-93
250 Directory successfully changed.
ftp> dir
200 PORT command successful. Consider using PASV.
150 Here comes the directory listing.
-rw-r--r--    1 123      114       2226496 Feb 24 08:46 System.map-2.6.32-71.14.1.el6.x86_64.crt.debug
-rw-r--r--    1 123      114          5070 Feb 24 08:46 et06_201102231954.log
-rw-r--r--    1 123      114          4992 Feb 24 08:46 et06_201102232023.log
-rw-r--r--    1 123      114       8975635 Feb 24 08:47 initramfs-2.6.32-71.14.1.el6.x86_64.crt.debug.img
-rw-r--r--    1 123      114       4592694 Feb 24 08:47 initrd-2.6.32-71.14.1.el6.x86_64.crt.debugkdump.img
-rw-r--r--    1 123      114      155613481 Feb 24 08:54 linux-2.6.32-71.14.1.el6.x86_64.crt.debug.tgz
-rw-r--r--    1 123      114       3523116 Feb 24 08:54 lustre-1.8.5-2.6.32_71.14.1.el6.x86_64.crt.debug_201102231933.x86_64.rpm
-rw-r--r--    1 123      114       7614664 Feb 24 08:54 lustre-debuginfo-1.8.5-2.6.32_71.14.1.el6.x86_64.crt.debug_201102231933.x86_64.rpm
-rw-r--r--    1 123      114         39056 Feb 24 08:54 lustre-iokit-1.2-201102231934.noarch.rpm
-rw-r--r--    1 123      114      11542584 Feb 24 08:55 lustre-modules-1.8.5-2.6.32_71.14.1.el6.x86_64.crt.debug_201102231933.x86_64.rpm
-rw-r--r--    1 123      114       3909728 Feb 24 08:55 lustre-source-1.8.5-2.6.32_71.14.1.el6.x86_64.crt.debug_201102231933.x86_64.rpm
-rw-r--r--    1 123      114       2876788 Feb 24 08:55 lustre-tests-1.8.5-2.6.32_71.14.1.el6.x86_64.crt.debug_201102231933.x86_64.rpm
-rw-r--r--    1 123      114      36536375 Feb 24 08:57 lustre.1.8.5.tgz
-rw-r--r--    1 123      114      380339516 Feb 24 09:15 modules.2.6.32-71.14.1.el6.x86_64.crt.debug.tgz
-rw-r--r--    1 123      114      1661148251 Feb 23 16:53 vmcore1
-rw-r--r--    1 123      114      1835102847 Feb 23 19:39 vmcore2
-rw-r--r--    1 123      114      2334515256 Feb 24 11:26 vmcore3
-rw-r--r--    1 123      114      148038120 Feb 24 13:29 vmcore4
-rw-r--r--    1 123      114      1057381374 Feb 24 14:59 vmcore4_try2
-rw-r--r--    1 123      114      123037042 Feb 24 13:18 vmlinux
-rw-r--r--    1 123      114      287984166 Feb 24 13:09 vmlinux.o
-rw-r--r--    1 123      114       3820416 Feb 24 13:09 vmlinuz-2.6.32-71.14.1.el6.x86_64.crt.debug
Comment by Robert Read (Inactive) [ 25/Feb/11 ]

Michael - jira tip: the little screen icon to the right of the comment edit window will switch to preview mode, and I think the {noformat} block command is probably what you were looking for.

Comment by Michael Hebensteit (Inactive) [ 25/Feb/11 ]

thanks, that works - but I can not edit the original entry
could we have a quick phone call?

thanks
Michael

Comment by Peter Jones [ 07/Mar/11 ]

Lai

Could you please work on this?

Thanks

Peter

Comment by Lai Siyao [ 08/Mar/11 ]

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.

Comment by Michael Hebensteit (Inactive) [ 08/Mar/11 ]
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

Comment by Michael Hebensteit (Inactive) [ 08/Mar/11 ]
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);
}


Comment by Michael Hebensteit (Inactive) [ 08/Mar/11 ]

Patch used to compile Lustre 1.8.5 on RH6

Comment by Lai Siyao [ 08/Mar/11 ]

Michael, the patch of patchless client against 1.8.6 is at http://review.whamcloud.com/#change,282.

Comment by Lai Siyao [ 09/Mar/11 ]

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.

Comment by Lai Siyao [ 09/Mar/11 ]

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.

Comment by Michael Hebensteit (Inactive) [ 09/Mar/11 ]
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
> > 
> > 


Comment by Johann Lombardi (Inactive) [ 10/Mar/11 ]

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.

Comment by Lai Siyao [ 10/Mar/11 ]

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
  }
}
Comment by Lai Siyao [ 10/Mar/11 ]

Michael, as you pointed out, page->private is borrowed to store migratetype (the value might be 2) in free_hot_cold_page() in RH6, though this is suspicious, I can't imagine a free page but still in page cache (which may trigger panic not so hard, and not limited to RH6 either).

I will wait for the latest test result; or after you get more direct evidence of the above scenario.

Comment by Lai Siyao [ 10/Mar/11 ]

Work done for this issue in my side (16 hours total):

  • analyzed RH6 kernel page allocation/free code path changes against RH5 kernel.
  • reviewed lustre page free allocation/free code path.
  • analyzed vmcore and test logs.
Comment by Peter Jones [ 14/Mar/11 ]

update from Michael

"thanks for the excellent work so far

Lai - can you please answer the following question: based on your professional experience, with the data we have so far - how likely are the following scenarios:

a) it's a bug in the Redhat Linux kernel
b) it's a bug in Lustre
c) it's a hardware/BIOS related bug
d) it's something completely different

could you assign probabilities to those 4 option (they should add up to 100%) - my own asessment would currently be:

1% it's a bug in the Redhat Linux kernel
4% it's a bug in Lustre
90% it's a hardware/BIOS related bug
5% it's something completely different

for the next steps I need to do some preparation first

a) create a new image based on RH6.1 and start exhaustive test procedure to see if the error creeps up again
b) create 2 systems based on RH5, one with 1.6.7.2, one with 1.8.2 to show performance problems

so there is no need for a meeting today
"

Comment by Peter Jones [ 14/Mar/11 ]

Michael

I spoke with Johann Lombardi who was the tech lead for 1.6.x and 1.8.x for many years and he agrees with your rough probabilities based upon the information presently available

Regards

Peter

Comment by Johann Lombardi (Inactive) [ 16/Mar/11 ]

Another customer hit the same bug with lustre 2.0. See LU-130.
Michael, could you please tell us what BIOS version has fixed the problem for you?

Comment by Michael Hebensteit (Inactive) [ 16/Mar/11 ]

commented in the 130 thread

Comment by Sebastien Buisson (Inactive) [ 24/Mar/11 ]

Hi,

Michael I have a question for you. At Bull we are trying to identify which microcode can solve this issue. For our MESCA machines we are testing a new BIOS that integrates the microcode update codename M04206E6_00000008.
Do you think you could retrieve the microcode revision brought by the BIOS update of your SuperMicro machines? That would be very helpful for us!

People from the Kernel Team here at Bull pointed us a kernel bug that is fixed in 2.6.32 vanilla and RHEL6.1 beta, dealing with TLB entries:
https://patchwork.kernel.org/patch/564801/
Do you think it could be related to the present bug, and fix this issue?

TIA,
Sebastien.

Comment by Michael Hebensteit (Inactive) [ 24/Mar/11 ]

it would fit the circumstances where/when it happened - but in my case a BIOS upgrade fixed it. This would rather speak against it.

Comment by Michael Hebensteit (Inactive) [ 24/Mar/11 ]

do you have a good way to retrieve this number? otherwise here from our Linux output:

From dmesg on et66, intel-ucode/06-2c-02

microcode: CPU23 sig=0x206c2, pf=0x1, revision=0x13
platform microcode: firmware: requesting intel-ucode/06-2c-02

Comment by Michael Hebensteit (Inactive) [ 24/Mar/11 ]

the BIOS used came from http://www.supermicro.com/support/bios/
File: X8DTN1.zip

Comment by Patrick Valentin (Inactive) [ 25/Mar/11 ]

If "dmidecode" command is available, you can run it with the following parameters to print BIOS information:

dmidecode -t0 -t1
Comment by Michael Hebensteit (Inactive) [ 25/Mar/11 ]
# dmidecode 2.10
SMBIOS 2.6 present.

Handle 0x0000, DMI type 0, 24 bytes
BIOS Information
        Vendor: American Megatrends Inc.
        Version: 080016
        Release Date: 02/11/2011
        Address: 0xF0000
        Runtime Size: 64 kB
        ROM Size: 4096 kB
        Characteristics:
                ISA is supported
                PCI is supported
                PNP is supported
                BIOS is upgradeable
                BIOS shadowing is allowed
                ESCD support is available
                Boot from CD is supported
                Selectable boot is supported
                BIOS ROM is socketed
                EDD is supported
                5.25"/1.2 MB floppy services are supported (int 13h)
                3.5"/720 kB floppy services are supported (int 13h)
                3.5"/2.88 MB floppy services are supported (int 13h)
                Print screen service is supported (int 5h)
                8042 keyboard services are supported (int 9h)
                Serial services are supported (int 14h)
                Printer services are supported (int 17h)
                CGA/mono video services are supported (int 10h)
                ACPI is supported
                USB legacy is supported
                LS-120 boot is supported
                ATAPI Zip drive boot is supported
                BIOS boot specification is supported
                Targeted content distribution is supported
        BIOS Revision: 8.16

Handle 0x0001, DMI type 1, 27 bytes
System Information
        Manufacturer: Supermicro
        Product Name: X8DTN
        Version: 1234567890
        Serial Number: 1234567890
        UUID: 54443858-4E54-3000-48F4-003048F40FA6
        Wake-up Type: Power Switch
        SKU Number: 1234567890
        Family: Server

Comment by Peter Jones [ 01/Jun/11 ]

This work is now complete

Generated at Sat Feb 10 01:03:41 UTC 2024 using Jira 9.4.14#940014-sha1:734e6822bbf0d45eff9af51f82432957f73aa32c.