Bug 1259171 - [RHEL.7.2] got stack trace when test ksm serial splitting and merging
[RHEL.7.2] got stack trace when test ksm serial splitting and merging
Status: ASSIGNED
Product: Red Hat Enterprise Linux 7
Classification: Red Hat
Component: qemu-kvm-rhev (Show other bugs)
7.2
Unspecified Unspecified
medium Severity medium
: rc
: ---
Assigned To: Andrea Arcangeli
Yumei Huang
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2015-09-02 02:38 EDT by Yang Meng
Modified: 2017-09-27 23:42 EDT (History)
11 users (show)

See Also:
Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed:
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)

  None (edit)
Description Yang Meng 2015-09-02 02:38:44 EDT
Description of problem:

guest got stack trace when run autotest script to test ksm serial splitting and merging

Version-Release number of selected component (if applicable):

host kernel:
kernel-3.10.0-310.el7.x86_64
qemu:qemu-kvm-rhev-2.3.0-21.el7.x86_64

guest kernel:
kernel-3.10.0-306.el7.x86_64

How reproducible:


Steps to Reproduce:

run autotest script ksm_serial, autotest will boot up 4 guests.

Actual results:
one guest got call trace:

2015-08-31 19:51:37: [ 5544.443056] Call Trace:
2015-08-31 19:51:37: [ 5544.443056]  [<ffffffff811c5f89>] migrate_pages+0x1e9/0x790
2015-08-31 19:51:37: [ 5544.443056]  [<ffffffff8118d120>] ? isolate_freepages_block+0x380/0x380
2015-08-31 19:51:37: [ 5544.443056]  [<ffffffff8118e119>] compact_zone+0x299/0x400
2015-08-31 19:51:37: [ 5544.443056]  [<ffffffff8118e31c>] compact_zone_order+0x9c/0xf0
2015-08-31 19:51:37: [ 5544.443056]  [<ffffffff8118e6d1>] try_to_compact_pages+0x121/0x1a0
2015-08-31 19:51:37: [ 5544.443056]  [<ffffffff8162e218>] __alloc_pages_direct_compact+0xac/0x196
2015-08-31 19:51:37: [ 5544.443056]  [<ffffffff811723a8>] __alloc_pages_nodemask+0x788/0xb90
2015-08-31 19:51:37: [ 5544.443056]  [<ffffffff811b665a>] alloc_pages_vma+0x9a/0x140
2015-08-31 19:51:37: [ 5544.443056]  [<ffffffff811cb093>] do_huge_pmd_anonymous_page+0x123/0x510
2015-08-31 19:51:37: [ 5544.443056]  [<ffffffff81195b38>] handle_mm_fault+0x1a8/0xf30
2015-08-31 19:51:37: [ 5544.443056]  [<ffffffff8163ea42>] __do_page_fault+0x152/0x420
2015-08-31 19:51:37: [ 5544.443056]  [<ffffffff81186909>] ? vm_mmap_pgoff+0xb9/0xe0
2015-08-31 19:51:37: [ 5544.443056]  [<ffffffff8163edd3>] trace_do_page_fault+0x43/0x110
2015-08-31 19:51:37: [ 5544.443056]  [<ffffffff8163e4f9>] do_async_page_fault+0x29/0xe0
2015-08-31 19:51:37: [ 5544.443056]  [<ffffffff8163b078>] async_page_fault+0x28/0x30
2015-08-31 19:51:37: [ 5544.443056] Code: ff ff 07 00 77 46 4c 89 e2 48 c1 ea 16 48 8b 14 d5 80 77 ed 81 48 85 d2 74 32 83 e0 7f 48 c1 e0 05 48 01 d0 74 26 f6 00 02 74 21 <49> 8b 45 00 48 89 c2 48 c1 e8 29 48 c1 ea 36 25 00 18 00 00 48

another guest got stack trace too:


2015-08-31 19:29:09: [ 4336.736054] Stack:
2015-08-31 19:29:09: [ 4336.736054]  ffffffff81166f9a 00000003ba85b000 ffff880af2e87d60 ffffffff81168c5f
2015-08-31 19:29:09: [ 4336.736054]  ffff880af2e87d08 ffff880af2e87e70 00000003ba85b000 0000000000001000
2015-08-31 19:29:09: [ 4336.736054]  ffff880032b8d080 ffff880af2e87fd8 00000000fa259f00 0000000000000000
2015-08-31 19:29:09: [ 4336.736054] Call Trace:
2015-08-31 19:29:09: [ 4336.736054]  [<ffffffff81166f9a>] ? iov_iter_copy_from_user_atomic+0x6a/0xa0
2015-08-31 19:29:09: [ 4336.736054]  [<ffffffff81168c5f>] generic_file_buffered_write+0x14f/0x290
2015-08-31 19:29:09: [ 4336.736054]  [<ffffffff8116a155>] __generic_file_aio_write+0x1d5/0x3e0
2015-08-31 19:29:09: [ 4336.736054]  [<ffffffff8116a3bd>] generic_file_aio_write+0x5d/0xc0
2015-08-31 19:29:09: [ 4336.736054]  [<ffffffff811dcb1d>] do_sync_write+0x8d/0xd0
2015-08-31 19:29:09: [ 4336.736054]  [<ffffffff811dd33d>] vfs_write+0xbd/0x1e0
2015-08-31 19:29:09: [ 4336.736054]  [<ffffffff811ddddf>] SyS_write+0x7f/0xe0
2015-08-31 19:29:09: [ 4336.736054]  [<ffffffff81643509>] system_call_fastpath+0x16/0x1b
2015-08-31 19:29:09: [ 4336.736054] Code: 74 30 83 fa 08 72 27 89 f9 83 e1 07 74 15 83 e9 08 f7 d9 29 ca 8a 06 88 07 48 ff c6 48 ff c7 ff c9 75 f2 89 d1 c1 e9 03 83 e2 07 <f3> 48 a5 89 d1 f3 a4 31 c0 66 66 90 c3 0f 1f 00 66 66 90 21 d2

Expected results:

no error .

Additional info:

1) host cpu:

processor	: 31
vendor_id	: AuthenticAMD
cpu family	: 21
model		: 1
model name	: AMD Opteron(TM) Processor 6272                 
stepping	: 2
microcode	: 0x600063d
cpu MHz		: 2100.007
cache size	: 2048 KB
physical id	: 1
siblings	: 16
core id		: 7
cpu cores	: 8
apicid		: 79
initial apicid	: 47
fpu		: yes
fpu_exception	: yes
cpuid level	: 13
wp		: yes
flags		: fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush mmx fxsr sse sse2 ht syscall nx mmxext fxsr_opt pdpe1gb rdtscp lm constant_tsc rep_good nopl nonstop_tsc extd_apicid amd_dcm aperfmperf pni pclmulqdq monitor ssse3 cx16 sse4_1 sse4_2 popcnt aes xsave avx lahf_lm cmp_legacy svm extapic cr8_legacy abm sse4a misalignsse 3dnowprefetch osvw ibs xop skinit wdt lwp fma4 nodeid_msr topoext perfctr_core perfctr_nb arat cpb hw_pstate npt lbrv svm_lock nrip_save tsc_scale vmcb_clean flushbyasid decodeassists pausefilter pfthreshold
Comment 2 Andrea Arcangeli 2015-09-09 15:58:27 EDT
Hello,

this seems to crash in the page migration code of the host kernel (guest is irrelevant for this bug).

If KSM is into the equation and the page migration otherwise works fine (NUMA balancing and memory compaction are the two main users of page migration) this could mean something's wrong in the migration of KSM pages.

Unfortunately both stack traces are truncated so it's uncertain if it's really the migration of KSM pages that tripped on a bug, so above I'm guessing.

To proceed with proper debugging:

1) could you retrieve a full log? Before the Call Trace: and Stack: lines there's other useful information. Perhaps it's still in /var/log.

2) is a kernel crash dump available with kexec? could you reproduce with that enabled?

3) does it go away if you run the below commands shortly after boot before running the testcase?

    echo NO_NUMA > /sys/kernel/debug/sched_features
    echo never > /sys/kernel/mm/transparent_hugepage/defrag
    echo 1000000000 > /sys/kernel/mm/transparent_hugepage/khugepaged/scan_sleep_millisecs

Ignore if the first command fails if the host is not NUMA.

The point 3) really intends to disable page migration, but there's no global tweak to disable it, and no global tweak to disable compaction either. Even after point 3) is applied, drivers will still invoke compaction at will, so the crash may still happen even after point 3) sometime, but it should happen less frequently if page migration of KSM pages is the problem.
Comment 3 Karen Noel 2015-09-15 17:27:55 EDT
Andrea, This looks very ugly. I can't tell how often this happens. We don't want these messages filling up the logs. Do you know the cause? 

You said "crash" but this looks like just a backtrace. You said host, but Yang Meng said the BT was in the guest. Which is it?

Yang Meng, What is the qemu-kvm command line? Is there NUMA set up in the guests? Thanks!
Comment 4 Andrea Arcangeli 2015-09-15 17:54:02 EDT
I think I confused them for host stack traces because I wouldn't have expected KSM to be able to destabilize the guest like this and the main problem is still that they're truncated and we don't know if it's a crash or just a warning, could be a VM_BUG_ON a WARN_ON or an harmless guest softlockup induced by a host inefficiency.

They are definitely guest stacktraces (like the first comment correctly said), because do_async_page_fault is in one of them.

The header above that stack trace would tell it. We need the full logs.

Considering the other KSM bug I've been working on, I wonder if the host tried to migrate a KSM page and these are harmless guest softlockups that happened because KSM in the host computed for too long while trying to migrate a KSM page. I assume KSM has been running in the host only, if yes, I still think the bug is unlikely in the guest, but we need the full logs around the stacktraces to make progress on this one.
Comment 5 Yang Meng 2015-09-15 21:34:24 EDT
(In reply to Karen Noel from comment #3)
> Andrea, This looks very ugly. I can't tell how often this happens. We don't
> want these messages filling up the logs. Do you know the cause? 
> 
> You said "crash" but this looks like just a backtrace. You said host, but
> Yang Meng said the BT was in the guest. Which is it?
> 
> Yang Meng, What is the qemu-kvm command line? Is there NUMA set up in the
> guests? Thanks!

hi, numa didn't set up ,and the following is the commandline:


/usr/libexec/qemu-kvm \
    -S  \
    -name 'virt-tests-vm1'  \
    -sandbox off  \
    -machine pc  \
    -nodefaults  \
    -vga cirrus  \
    -chardev socket,id=qmp_id_qmpmonitor1,path=/tmp/monitor-qmpmonitor1-20150831-181355-S3Y85kan,server,nowait \
    -mon chardev=qmp_id_qmpmonitor1,mode=control  \
    -chardev socket,id=qmp_id_catch_monitor,path=/tmp/monitor-catch_monitor-20150831-181355-S3Y85kan,server,nowait \
    -mon chardev=qmp_id_catch_monitor,mode=control \
    -device pvpanic,ioport=0x505,id=idRGYTYM  \
    -chardev socket,id=serial_id_serial0,path=/tmp/serial-serial0-20150831-181355-S3Y85kan,server,nowait \
    -device isa-serial,chardev=serial_id_serial0  \
    -chardev socket,id=seabioslog_id_20150831-181355-S3Y85kan,path=/tmp/seabios-20150831-181355-S3Y85kan,server,nowait \
    -device isa-debugcon,chardev=seabioslog_id_20150831-181355-S3Y85kan,iobase=0x402 \
    -device ich9-usb-uhci1,id=usb1,bus=pci.0,addr=03 \
    -drive id=drive_image1,if=none,cache=none,snapshot=on,aio=native,format=qcow2,file=/home/autotest-devel/client/tests/virt/shared/data/images/RHEL-Server-7.2-64.qcow2 \
    -device ide-hd,id=image1,drive=drive_image1,bus=ide.0,unit=0 \
    -device e1000,mac=9a:18:19:1a:1b:1c,id=idB5ehSJ,netdev=idvI6NWv,bus=pci.0,addr=04  \
    -netdev tap,id=idvI6NWv,fd=21  \
    -m 44958  \
    -smp 16,maxcpus=16,cores=8,threads=1,sockets=2  \
    -cpu 'Opteron_G4',+kvm_pv_unhalt \
    -device usb-tablet,id=usb-tablet1,bus=usb1.0,port=1  \
    -vnc :0  \
    -rtc base=utc,clock=host,driftfix=slew  \
    -boot order=cdn,once=c,menu=off,strict=off   \
    -pidfile /tmp/virt-tests-vm1-20150831-181352-bHLc.pid \
    -enable-kvm
Comment 6 Andrea Arcangeli 2015-09-16 09:13:09 EDT
Hello Yang,

which other lines are in /var/log just before/around 19:51:37? and 19:29:09?
Comment 7 Yang Meng 2015-09-17 03:53:48 EDT
(In reply to Andrea Arcangeli from comment #6)
> Hello Yang,
> 
> which other lines are in /var/log just before/around 19:51:37? and 19:29:09?

Hi Andrea,
    the log is not got from /var/log ,it's just the log generated by autotest script, do you need the full log of autotest ?
Comment 8 Andrea Arcangeli 2015-09-17 08:49:50 EDT
If the guest images aren't wiped out automatically after the autotest script run, you could try to restsart the guest and try to grab those logs from `journalctl` or /var/log/. If those two fragments are the only thing that gets logged into the autotest log, there shall be more kernel messages before those Stack/Call trace lines into /var/log or journalctl. If there aren't other kernel messages in the autotest logs I probably don't need the full log of autotest, other kernel messages would have the exact same timestamp: 2015-08-31 19:29:09 and 2015-08-31 19:51:37. If there are other lines with those two timestamps I need those yes.

Thank you.

Note You need to log in before you can comment on or make changes to this bug.