Hi All,
I hit the below crashed when doing memory related tests[1] on s390x:
--------------- snip ---------------------
� 15929.351639¨ � <000000000021c0a6>¨ shrink_inactive_list+0x1c6/0x56c
� 15929.351647¨ � <000000000021c69e>¨ shrink_lruvec+0x252/0x56c
� 15929.351654¨ � <000000000021ca44>¨ shrink_zone+0x8c/0x1bc
� 15929.351662¨ � <000000000021d080>¨ balance_pgdat+0x50c/0x658
� 15929.351671¨ � <000000000021d318>¨ kswapd+0x14c/0x470
� 15929.351680¨ � <0000000000158292>¨ kthread+0xda/0xe4
� 15929.351690¨ � <000000000062a5de>¨ kernel_thread_starter+0x6/0xc
� 15929.351700¨ � <000000000062a5d8>¨ kernel_thread_starter+0x0/0xc
� 16109.346061¨ INFO: rcu_sched self-detected stall on CPU { 0} (t=24006 jiffies
g=89766 c=89765 q=10544)
� 16109.346101¨ CPU: 0 Tainted: G D 3.9.0-rc6+ #1
� 16109.346106¨ Process kswapd0 (pid: 28, task: 000000003b2a0000, ksp: 000000003b
2ab8c0)
� 16109.346110¨ 000000000001bb60 000000000001bb70 0000000000000002 0000000
000000000
000000000001bc00 000000000001bb78 000000000001bb78 00000000001009ca
0000000000000000 0000000000002930 000000000000000a 000000000000000a
000000000001bbc0 000000000001bb60 0000000000000000 0000000000000000
000000000063bb18 00000000001009ca 000000000001bb60 000000000001bbb0
� 16109.346170¨ Call Trace:
� 16109.346179¨ (� <0000000000100920>¨ show_trace+0x128/0x12c)
� 16109.346195¨ � <00000000001cd320>¨ rcu_check_callbacks+0x458/0xccc
� 16109.346209¨ � <0000000000140f2e>¨ update_process_times+0x4a/0x74
� 16109.346222¨ � <0000000000199452>¨ tick_sched_handle.isra.12+0x5e/0x70
� 16109.346235¨ � <00000000001995aa>¨ tick_sched_timer+0x6a/0x98
� 16109.346247¨ � <000000000015c1ea>¨ __run_hrtimer+0x8e/0x200
� 16109.346381¨ � <000000000015d1b2>¨ hrtimer_interrupt+0x212/0x2b0
� 16109.346385¨ � <00000000001040f6>¨ clock_comparator_work+0x4a/0x54
� 16109.346390¨ � <000000000010d658>¨ do_extint+0x158/0x15c
� 16109.346396¨ � <000000000062aa24>¨ ext_skip+0x38/0x3c
� 16109.346404¨ � <00000000001153c8>¨ smp_yield_cpu+0x44/0x48
� 16109.346412¨ (� <000003d10051aec0>¨ 0x3d10051aec0)
� 16109.346457¨ � <000000000024206a>¨ __page_check_address+0x16a/0x170
� 16109.346466¨ � <00000000002423a2>¨ page_referenced_one+0x3e/0xa0
� 16109.346501¨ � <000000000024427c>¨ page_referenced+0x32c/0x41c
� 16109.346510¨ � <000000000021b1dc>¨ shrink_page_list+0x380/0xb9c
� 16109.346521¨ � <000000000021c0a6>¨ shrink_inactive_list+0x1c6/0x56c
� 16109.346532¨ � <000000000021c69e>¨ shrink_lruvec+0x252/0x56c
� 16109.346542¨ � <000000000021ca44>¨ shrink_zone+0x8c/0x1bc
� 16109.346553¨ � <000000000021d080>¨ balance_pgdat+0x50c/0x658
� 16109.346564¨ � <000000000021d318>¨ kswapd+0x14c/0x470
� 16109.346576¨ � <0000000000158292>¨ kthread+0xda/0xe4
� 16109.346656¨ � <000000000062a5de>¨ kernel_thread_starter+0x6/0xc
� 16109.346682¨ � <000000000062a5d8>¨ kernel_thread_starter+0x0/0xc
[-- MARK -- Fri Apr 12 06:15:00 2013]
� 16289.386061¨ INFO: rcu_sched self-detected stall on CPU { 0} (t=42010 jiffies
g=89766 c=89765 q=10627)
-------------- snip ----------------------
The testing system has 1Gb RAM, kernel is new latest mainline.
please let me know if you need any more info.
[1] reproducer is come from LTP: https://github.com/linux-test-project/ltp/blob/master/testcases/kernel/mem/mtest06/mmap2.c
and execute it using this command: `./mmap2 -x 0.002 -a -p`
--
Thanks,
Zhouping
On Sun, Apr 14, 2013 at 11:28:40PM -0400, Zhouping Liu wrote:
> Hi All,
>
> I hit the below crashed when doing memory related tests[1] on s390x:
>
> --------------- snip ---------------------
> � 15929.351639¨ � <000000000021c0a6>¨ shrink_inactive_list+0x1c6/0x56c
> � 15929.351647¨ � <000000000021c69e>¨ shrink_lruvec+0x252/0x56c
> � 15929.351654¨ � <000000000021ca44>¨ shrink_zone+0x8c/0x1bc
> � 15929.351662¨ � <000000000021d080>¨ balance_pgdat+0x50c/0x658
> � 15929.351671¨ � <000000000021d318>¨ kswapd+0x14c/0x470
> � 15929.351680¨ � <0000000000158292>¨ kthread+0xda/0xe4
> � 15929.351690¨ � <000000000062a5de>¨ kernel_thread_starter+0x6/0xc
> � 15929.351700¨ � <000000000062a5d8>¨ kernel_thread_starter+0x0/0xc
> � 16109.346061¨ INFO: rcu_sched self-detected stall on CPU { 0} (t=24006 jiffies
> g=89766 c=89765 q=10544)
> � 16109.346101¨ CPU: 0 Tainted: G D 3.9.0-rc6+ #1
> � 16109.346106¨ Process kswapd0 (pid: 28, task: 000000003b2a0000, ksp: 000000003b
> 2ab8c0)
> � 16109.346110¨ 000000000001bb60 000000000001bb70 0000000000000002 0000000
> 000000000
> 000000000001bc00 000000000001bb78 000000000001bb78 00000000001009ca
> 0000000000000000 0000000000002930 000000000000000a 000000000000000a
> 000000000001bbc0 000000000001bb60 0000000000000000 0000000000000000
> 000000000063bb18 00000000001009ca 000000000001bb60 000000000001bbb0
> � 16109.346170¨ Call Trace:
> � 16109.346179¨ (� <0000000000100920>¨ show_trace+0x128/0x12c)
> � 16109.346195¨ � <00000000001cd320>¨ rcu_check_callbacks+0x458/0xccc
> � 16109.346209¨ � <0000000000140f2e>¨ update_process_times+0x4a/0x74
> � 16109.346222¨ � <0000000000199452>¨ tick_sched_handle.isra.12+0x5e/0x70
> � 16109.346235¨ � <00000000001995aa>¨ tick_sched_timer+0x6a/0x98
> � 16109.346247¨ � <000000000015c1ea>¨ __run_hrtimer+0x8e/0x200
> � 16109.346381¨ � <000000000015d1b2>¨ hrtimer_interrupt+0x212/0x2b0
> � 16109.346385¨ � <00000000001040f6>¨ clock_comparator_work+0x4a/0x54
> � 16109.346390¨ � <000000000010d658>¨ do_extint+0x158/0x15c
> � 16109.346396¨ � <000000000062aa24>¨ ext_skip+0x38/0x3c
> � 16109.346404¨ � <00000000001153c8>¨ smp_yield_cpu+0x44/0x48
> � 16109.346412¨ (� <000003d10051aec0>¨ 0x3d10051aec0)
> � 16109.346457¨ � <000000000024206a>¨ __page_check_address+0x16a/0x170
> � 16109.346466¨ � <00000000002423a2>¨ page_referenced_one+0x3e/0xa0
> � 16109.346501¨ � <000000000024427c>¨ page_referenced+0x32c/0x41c
> � 16109.346510¨ � <000000000021b1dc>¨ shrink_page_list+0x380/0xb9c
> � 16109.346521¨ � <000000000021c0a6>¨ shrink_inactive_list+0x1c6/0x56c
> � 16109.346532¨ � <000000000021c69e>¨ shrink_lruvec+0x252/0x56c
> � 16109.346542¨ � <000000000021ca44>¨ shrink_zone+0x8c/0x1bc
> � 16109.346553¨ � <000000000021d080>¨ balance_pgdat+0x50c/0x658
> � 16109.346564¨ � <000000000021d318>¨ kswapd+0x14c/0x470
> � 16109.346576¨ � <0000000000158292>¨ kthread+0xda/0xe4
> � 16109.346656¨ � <000000000062a5de>¨ kernel_thread_starter+0x6/0xc
> � 16109.346682¨ � <000000000062a5d8>¨ kernel_thread_starter+0x0/0xc
> [-- MARK -- Fri Apr 12 06:15:00 2013]
> � 16289.386061¨ INFO: rcu_sched self-detected stall on CPU { 0} (t=42010 jiffies
> g=89766 c=89765 q=10627)
Did the system really crash or did you just see the rcu related warning(s)?
On 04/15/2013 01:56 PM, Heiko Carstens wrote:
> On Sun, Apr 14, 2013 at 11:28:40PM -0400, Zhouping Liu wrote:
>> Hi All,
>>
>> I hit the below crashed when doing memory related tests[1] on s390x:
>>
>> --------------- snip ---------------------
>> � 15929.351639¨ � <000000000021c0a6>¨ shrink_inactive_list+0x1c6/0x56c
>> � 15929.351647¨ � <000000000021c69e>¨ shrink_lruvec+0x252/0x56c
>> � 15929.351654¨ � <000000000021ca44>¨ shrink_zone+0x8c/0x1bc
>> � 15929.351662¨ � <000000000021d080>¨ balance_pgdat+0x50c/0x658
>> � 15929.351671¨ � <000000000021d318>¨ kswapd+0x14c/0x470
>> � 15929.351680¨ � <0000000000158292>¨ kthread+0xda/0xe4
>> � 15929.351690¨ � <000000000062a5de>¨ kernel_thread_starter+0x6/0xc
>> � 15929.351700¨ � <000000000062a5d8>¨ kernel_thread_starter+0x0/0xc
>> � 16109.346061¨ INFO: rcu_sched self-detected stall on CPU { 0} (t=24006 jiffies
>> g=89766 c=89765 q=10544)
>> � 16109.346101¨ CPU: 0 Tainted: G D 3.9.0-rc6+ #1
>> � 16109.346106¨ Process kswapd0 (pid: 28, task: 000000003b2a0000, ksp: 000000003b
>> 2ab8c0)
>> � 16109.346110¨ 000000000001bb60 000000000001bb70 0000000000000002 0000000
>> 000000000
>> 000000000001bc00 000000000001bb78 000000000001bb78 00000000001009ca
>> 0000000000000000 0000000000002930 000000000000000a 000000000000000a
>> 000000000001bbc0 000000000001bb60 0000000000000000 0000000000000000
>> 000000000063bb18 00000000001009ca 000000000001bb60 000000000001bbb0
>> � 16109.346170¨ Call Trace:
>> � 16109.346179¨ (� <0000000000100920>¨ show_trace+0x128/0x12c)
>> � 16109.346195¨ � <00000000001cd320>¨ rcu_check_callbacks+0x458/0xccc
>> � 16109.346209¨ � <0000000000140f2e>¨ update_process_times+0x4a/0x74
>> � 16109.346222¨ � <0000000000199452>¨ tick_sched_handle.isra.12+0x5e/0x70
>> � 16109.346235¨ � <00000000001995aa>¨ tick_sched_timer+0x6a/0x98
>> � 16109.346247¨ � <000000000015c1ea>¨ __run_hrtimer+0x8e/0x200
>> � 16109.346381¨ � <000000000015d1b2>¨ hrtimer_interrupt+0x212/0x2b0
>> � 16109.346385¨ � <00000000001040f6>¨ clock_comparator_work+0x4a/0x54
>> � 16109.346390¨ � <000000000010d658>¨ do_extint+0x158/0x15c
>> � 16109.346396¨ � <000000000062aa24>¨ ext_skip+0x38/0x3c
>> � 16109.346404¨ � <00000000001153c8>¨ smp_yield_cpu+0x44/0x48
>> � 16109.346412¨ (� <000003d10051aec0>¨ 0x3d10051aec0)
>> � 16109.346457¨ � <000000000024206a>¨ __page_check_address+0x16a/0x170
>> � 16109.346466¨ � <00000000002423a2>¨ page_referenced_one+0x3e/0xa0
>> � 16109.346501¨ � <000000000024427c>¨ page_referenced+0x32c/0x41c
>> � 16109.346510¨ � <000000000021b1dc>¨ shrink_page_list+0x380/0xb9c
>> � 16109.346521¨ � <000000000021c0a6>¨ shrink_inactive_list+0x1c6/0x56c
>> � 16109.346532¨ � <000000000021c69e>¨ shrink_lruvec+0x252/0x56c
>> � 16109.346542¨ � <000000000021ca44>¨ shrink_zone+0x8c/0x1bc
>> � 16109.346553¨ � <000000000021d080>¨ balance_pgdat+0x50c/0x658
>> � 16109.346564¨ � <000000000021d318>¨ kswapd+0x14c/0x470
>> � 16109.346576¨ � <0000000000158292>¨ kthread+0xda/0xe4
>> � 16109.346656¨ � <000000000062a5de>¨ kernel_thread_starter+0x6/0xc
>> � 16109.346682¨ � <000000000062a5d8>¨ kernel_thread_starter+0x0/0xc
>> [-- MARK -- Fri Apr 12 06:15:00 2013]
>> � 16289.386061¨ INFO: rcu_sched self-detected stall on CPU { 0} (t=42010 jiffies
>> g=89766 c=89765 q=10627)
> Did the system really crash or did you just see the rcu related warning(s)?
I just check it again, actually at first the system didn't really crash,
but the system is very slow in response.
and the reproducer process can't be killed, after I did some common
actions such as 'ls' 'vim' etc, the system
seemed to be really crashed, no any response.
also in the previous testing, I can remember that the system would be no
any response for a long time, just only
repeatedly print out the such above 'Call Trace' into console.
Thanks,
Zhouping
On Mon, Apr 15, 2013 at 02:16:55PM +0800, Zhouping Liu wrote:
> On 04/15/2013 01:56 PM, Heiko Carstens wrote:
> >On Sun, Apr 14, 2013 at 11:28:40PM -0400, Zhouping Liu wrote:
> >>� 16109.346170¨ Call Trace:
> >>� 16109.346179¨ (� <0000000000100920>¨ show_trace+0x128/0x12c)
> >>� 16109.346195¨ � <00000000001cd320>¨ rcu_check_callbacks+0x458/0xccc
> >>� 16109.346209¨ � <0000000000140f2e>¨ update_process_times+0x4a/0x74
> >>� 16109.346222¨ � <0000000000199452>¨ tick_sched_handle.isra.12+0x5e/0x70
> >>� 16109.346235¨ � <00000000001995aa>¨ tick_sched_timer+0x6a/0x98
> >>� 16109.346247¨ � <000000000015c1ea>¨ __run_hrtimer+0x8e/0x200
> >>� 16109.346381¨ � <000000000015d1b2>¨ hrtimer_interrupt+0x212/0x2b0
> >>� 16109.346385¨ � <00000000001040f6>¨ clock_comparator_work+0x4a/0x54
> >>� 16109.346390¨ � <000000000010d658>¨ do_extint+0x158/0x15c
> >>� 16109.346396¨ � <000000000062aa24>¨ ext_skip+0x38/0x3c
> >>� 16109.346404¨ � <00000000001153c8>¨ smp_yield_cpu+0x44/0x48
> >>� 16109.346412¨ (� <000003d10051aec0>¨ 0x3d10051aec0)
> >>� 16109.346457¨ � <000000000024206a>¨ __page_check_address+0x16a/0x170
> >>� 16109.346466¨ � <00000000002423a2>¨ page_referenced_one+0x3e/0xa0
> >>� 16109.346501¨ � <000000000024427c>¨ page_referenced+0x32c/0x41c
> >>� 16109.346510¨ � <000000000021b1dc>¨ shrink_page_list+0x380/0xb9c
> >>� 16109.346521¨ � <000000000021c0a6>¨ shrink_inactive_list+0x1c6/0x56c
> >>� 16109.346532¨ � <000000000021c69e>¨ shrink_lruvec+0x252/0x56c
> >>� 16109.346542¨ � <000000000021ca44>¨ shrink_zone+0x8c/0x1bc
> >>� 16109.346553¨ � <000000000021d080>¨ balance_pgdat+0x50c/0x658
> >>� 16109.346564¨ � <000000000021d318>¨ kswapd+0x14c/0x470
> >>� 16109.346576¨ � <0000000000158292>¨ kthread+0xda/0xe4
> >>� 16109.346656¨ � <000000000062a5de>¨ kernel_thread_starter+0x6/0xc
> >>� 16109.346682¨ � <000000000062a5d8>¨ kernel_thread_starter+0x0/0xc
> >>[-- MARK -- Fri Apr 12 06:15:00 2013]
> >>� 16289.386061¨ INFO: rcu_sched self-detected stall on CPU { 0} (t=42010 jiffies
> >> g=89766 c=89765 q=10627)
> >Did the system really crash or did you just see the rcu related warning(s)?
>
> I just check it again, actually at first the system didn't really
> crash, but the system is very slow in response.
> and the reproducer process can't be killed, after I did some common
> actions such as 'ls' 'vim' etc, the system
> seemed to be really crashed, no any response.
>
> also in the previous testing, I can remember that the system would
> be no any response for a long time, just only
> repeatedly print out the such above 'Call Trace' into console.
Ok, thanks.
Just a couple of more questions: did you see this also on other archs, or just
s390 (if you tried other platforms at all).
If you have some time, could you please repeat your test with the kernel
command line option " user_mode=home "?
As far as I can tell there was only one s390 patch merged that was
mmap related: 486c0a0bc80d370471b21662bf03f04fbb37cdc6 "s390/mm: Fix crst
upgrade of mmap with MAP_FIXED".
Even though I don't think it explains the bug you've seen it might be worth
to try to revert it.
And at last, can you share your kernel config?
Thanks,
Heiko
Hi Heiko,
On 04/16/2013 03:50 PM, Heiko Carstens wrote:
> On Mon, Apr 15, 2013 at 02:16:55PM +0800, Zhouping Liu wrote:
>> On 04/15/2013 01:56 PM, Heiko Carstens wrote:
>>> On Sun, Apr 14, 2013 at 11:28:40PM -0400, Zhouping Liu wrote:
>>>> � 16109.346170¨ Call Trace:
>>>> � 16109.346179¨ (� <0000000000100920>¨ show_trace+0x128/0x12c)
>>>> � 16109.346195¨ � <00000000001cd320>¨ rcu_check_callbacks+0x458/0xccc
>>>> � 16109.346209¨ � <0000000000140f2e>¨ update_process_times+0x4a/0x74
>>>> � 16109.346222¨ � <0000000000199452>¨ tick_sched_handle.isra.12+0x5e/0x70
>>>> � 16109.346235¨ � <00000000001995aa>¨ tick_sched_timer+0x6a/0x98
>>>> � 16109.346247¨ � <000000000015c1ea>¨ __run_hrtimer+0x8e/0x200
>>>> � 16109.346381¨ � <000000000015d1b2>¨ hrtimer_interrupt+0x212/0x2b0
>>>> � 16109.346385¨ � <00000000001040f6>¨ clock_comparator_work+0x4a/0x54
>>>> � 16109.346390¨ � <000000000010d658>¨ do_extint+0x158/0x15c
>>>> � 16109.346396¨ � <000000000062aa24>¨ ext_skip+0x38/0x3c
>>>> � 16109.346404¨ � <00000000001153c8>¨ smp_yield_cpu+0x44/0x48
>>>> � 16109.346412¨ (� <000003d10051aec0>¨ 0x3d10051aec0)
>>>> � 16109.346457¨ � <000000000024206a>¨ __page_check_address+0x16a/0x170
>>>> � 16109.346466¨ � <00000000002423a2>¨ page_referenced_one+0x3e/0xa0
>>>> � 16109.346501¨ � <000000000024427c>¨ page_referenced+0x32c/0x41c
>>>> � 16109.346510¨ � <000000000021b1dc>¨ shrink_page_list+0x380/0xb9c
>>>> � 16109.346521¨ � <000000000021c0a6>¨ shrink_inactive_list+0x1c6/0x56c
>>>> � 16109.346532¨ � <000000000021c69e>¨ shrink_lruvec+0x252/0x56c
>>>> � 16109.346542¨ � <000000000021ca44>¨ shrink_zone+0x8c/0x1bc
>>>> � 16109.346553¨ � <000000000021d080>¨ balance_pgdat+0x50c/0x658
>>>> � 16109.346564¨ � <000000000021d318>¨ kswapd+0x14c/0x470
>>>> � 16109.346576¨ � <0000000000158292>¨ kthread+0xda/0xe4
>>>> � 16109.346656¨ � <000000000062a5de>¨ kernel_thread_starter+0x6/0xc
>>>> � 16109.346682¨ � <000000000062a5d8>¨ kernel_thread_starter+0x0/0xc
>>>> [-- MARK -- Fri Apr 12 06:15:00 2013]
>>>> � 16289.386061¨ INFO: rcu_sched self-detected stall on CPU { 0} (t=42010 jiffies
>>>> g=89766 c=89765 q=10627)
>>> Did the system really crash or did you just see the rcu related warning(s)?
>> I just check it again, actually at first the system didn't really
>> crash, but the system is very slow in response.
>> and the reproducer process can't be killed, after I did some common
>> actions such as 'ls' 'vim' etc, the system
>> seemed to be really crashed, no any response.
>>
>> also in the previous testing, I can remember that the system would
>> be no any response for a long time, just only
>> repeatedly print out the such above 'Call Trace' into console.
> Ok, thanks.
> Just a couple of more questions: did you see this also on other archs, or just
> s390 (if you tried other platforms at all).
>
> If you have some time, could you please repeat your test with the kernel
> command line option " user_mode=home "?
What's the meaning of this command line? I can't find it in
Documentation/kernel-parameters.txt/
>
> As far as I can tell there was only one s390 patch merged that was
> mmap related: 486c0a0bc80d370471b21662bf03f04fbb37cdc6 "s390/mm: Fix crst
> upgrade of mmap with MAP_FIXED".
> Even though I don't think it explains the bug you've seen it might be worth
> to try to revert it.
>
> And at last, can you share your kernel config?
>
> Thanks,
> Heiko
>
> --
> To unsubscribe, send a message with 'unsubscribe linux-mm' in
> the body to [email protected]. For more info on Linux MM,
> see: http://www.linux-mm.org/ .
> Don't email: <a href=mailto:"[email protected]"> [email protected] </a>
On Tue, Apr 16, 2013 at 03:56:59PM +0800, Simon Jeons wrote:
> Hi Heiko,
> >If you have some time, could you please repeat your test with the kernel
> >command line option " user_mode=home "?
>
> What's the meaning of this command line? I can't find it in
> Documentation/kernel-parameters.txt/
It switches the architectural address space where kernel and user space
reside in.
We only recently switched the default address space for user space from
home space to primary space, since that's needed for kvm.
The user space runs in home space mode will be removed in the future; we
keep it currently as fallback, just in case something breaks.
On 04/16/2013 03:50 PM, Heiko Carstens wrote:
> On Mon, Apr 15, 2013 at 02:16:55PM +0800, Zhouping Liu wrote:
>> On 04/15/2013 01:56 PM, Heiko Carstens wrote:
>>> On Sun, Apr 14, 2013 at 11:28:40PM -0400, Zhouping Liu wrote:
>>>> � 16109.346170¨ Call Trace:
>>>> � 16109.346179¨ (� <0000000000100920>¨ show_trace+0x128/0x12c)
>>>> � 16109.346195¨ � <00000000001cd320>¨ rcu_check_callbacks+0x458/0xccc
>>>> � 16109.346209¨ � <0000000000140f2e>¨ update_process_times+0x4a/0x74
>>>> � 16109.346222¨ � <0000000000199452>¨ tick_sched_handle.isra.12+0x5e/0x70
>>>> � 16109.346235¨ � <00000000001995aa>¨ tick_sched_timer+0x6a/0x98
>>>> � 16109.346247¨ � <000000000015c1ea>¨ __run_hrtimer+0x8e/0x200
>>>> � 16109.346381¨ � <000000000015d1b2>¨ hrtimer_interrupt+0x212/0x2b0
>>>> � 16109.346385¨ � <00000000001040f6>¨ clock_comparator_work+0x4a/0x54
>>>> � 16109.346390¨ � <000000000010d658>¨ do_extint+0x158/0x15c
>>>> � 16109.346396¨ � <000000000062aa24>¨ ext_skip+0x38/0x3c
>>>> � 16109.346404¨ � <00000000001153c8>¨ smp_yield_cpu+0x44/0x48
>>>> � 16109.346412¨ (� <000003d10051aec0>¨ 0x3d10051aec0)
>>>> � 16109.346457¨ � <000000000024206a>¨ __page_check_address+0x16a/0x170
>>>> � 16109.346466¨ � <00000000002423a2>¨ page_referenced_one+0x3e/0xa0
>>>> � 16109.346501¨ � <000000000024427c>¨ page_referenced+0x32c/0x41c
>>>> � 16109.346510¨ � <000000000021b1dc>¨ shrink_page_list+0x380/0xb9c
>>>> � 16109.346521¨ � <000000000021c0a6>¨ shrink_inactive_list+0x1c6/0x56c
>>>> � 16109.346532¨ � <000000000021c69e>¨ shrink_lruvec+0x252/0x56c
>>>> � 16109.346542¨ � <000000000021ca44>¨ shrink_zone+0x8c/0x1bc
>>>> � 16109.346553¨ � <000000000021d080>¨ balance_pgdat+0x50c/0x658
>>>> � 16109.346564¨ � <000000000021d318>¨ kswapd+0x14c/0x470
>>>> � 16109.346576¨ � <0000000000158292>¨ kthread+0xda/0xe4
>>>> � 16109.346656¨ � <000000000062a5de>¨ kernel_thread_starter+0x6/0xc
>>>> � 16109.346682¨ � <000000000062a5d8>¨ kernel_thread_starter+0x0/0xc
>>>> [-- MARK -- Fri Apr 12 06:15:00 2013]
>>>> � 16289.386061¨ INFO: rcu_sched self-detected stall on CPU { 0} (t=42010 jiffies
>>>> g=89766 c=89765 q=10627)
>>> Did the system really crash or did you just see the rcu related warning(s)?
>> I just check it again, actually at first the system didn't really
>> crash, but the system is very slow in response.
>> and the reproducer process can't be killed, after I did some common
>> actions such as 'ls' 'vim' etc, the system
>> seemed to be really crashed, no any response.
>>
>> also in the previous testing, I can remember that the system would
>> be no any response for a long time, just only
>> repeatedly print out the such above 'Call Trace' into console.
> Ok, thanks.
> Just a couple of more questions: did you see this also on other archs, or just
> s390 (if you tried other platforms at all).
Didn't meet the issue on other arches, just only on s390x, I will check
further on other arches.
>
> If you have some time, could you please repeat your test with the kernel
> command line option " user_mode=home "?
Sure, but the testing machine is not in my hand now, I will test it ASAP
when I get it, also I'll
try it on other s390x machine.
>
> As far as I can tell there was only one s390 patch merged that was
> mmap related: 486c0a0bc80d370471b21662bf03f04fbb37cdc6 "s390/mm: Fix crst
> upgrade of mmap with MAP_FIXED".
> Even though I don't think it explains the bug you've seen it might be worth
> to try to revert it.
OK, I'll try it later.
>
> And at last, can you share your kernel config?
Of course.
Thanks,
Zhouping
>
> Thanks,
> Heiko
>
Hello Heiko,
----- Original Message -----
> From: "Heiko Carstens" <[email protected]>
> To: "Zhouping Liu" <[email protected]>
> Cc: [email protected], "LKML" <[email protected]>, "caiqian" <[email protected]>, "Caspar Zhang"
> <[email protected]>, "Martin Schwidefsky" <[email protected]>
> Sent: Tuesday, April 16, 2013 3:50:47 PM
> Subject: Re: [BUG][s390x] mm: system crashed
>
> On Mon, Apr 15, 2013 at 02:16:55PM +0800, Zhouping Liu wrote:
> > On 04/15/2013 01:56 PM, Heiko Carstens wrote:
> > >On Sun, Apr 14, 2013 at 11:28:40PM -0400, Zhouping Liu wrote:
> > >>� 16109.346170¨ Call Trace:
> > >>� 16109.346179¨ (� <0000000000100920>¨ show_trace+0x128/0x12c)
> > >>� 16109.346195¨ � <00000000001cd320>¨ rcu_check_callbacks+0x458/0xccc
> > >>� 16109.346209¨ � <0000000000140f2e>¨ update_process_times+0x4a/0x74
> > >>� 16109.346222¨ � <0000000000199452>¨
> > >>tick_sched_handle.isra.12+0x5e/0x70
> > >>� 16109.346235¨ � <00000000001995aa>¨ tick_sched_timer+0x6a/0x98
> > >>� 16109.346247¨ � <000000000015c1ea>¨ __run_hrtimer+0x8e/0x200
> > >>� 16109.346381¨ � <000000000015d1b2>¨ hrtimer_interrupt+0x212/0x2b0
> > >>� 16109.346385¨ � <00000000001040f6>¨ clock_comparator_work+0x4a/0x54
> > >>� 16109.346390¨ � <000000000010d658>¨ do_extint+0x158/0x15c
> > >>� 16109.346396¨ � <000000000062aa24>¨ ext_skip+0x38/0x3c
> > >>� 16109.346404¨ � <00000000001153c8>¨ smp_yield_cpu+0x44/0x48
> > >>� 16109.346412¨ (� <000003d10051aec0>¨ 0x3d10051aec0)
> > >>� 16109.346457¨ � <000000000024206a>¨ __page_check_address+0x16a/0x170
> > >>� 16109.346466¨ � <00000000002423a2>¨ page_referenced_one+0x3e/0xa0
> > >>� 16109.346501¨ � <000000000024427c>¨ page_referenced+0x32c/0x41c
> > >>� 16109.346510¨ � <000000000021b1dc>¨ shrink_page_list+0x380/0xb9c
> > >>� 16109.346521¨ � <000000000021c0a6>¨ shrink_inactive_list+0x1c6/0x56c
> > >>� 16109.346532¨ � <000000000021c69e>¨ shrink_lruvec+0x252/0x56c
> > >>� 16109.346542¨ � <000000000021ca44>¨ shrink_zone+0x8c/0x1bc
> > >>� 16109.346553¨ � <000000000021d080>¨ balance_pgdat+0x50c/0x658
> > >>� 16109.346564¨ � <000000000021d318>¨ kswapd+0x14c/0x470
> > >>� 16109.346576¨ � <0000000000158292>¨ kthread+0xda/0xe4
> > >>� 16109.346656¨ � <000000000062a5de>¨ kernel_thread_starter+0x6/0xc
> > >>� 16109.346682¨ � <000000000062a5d8>¨ kernel_thread_starter+0x0/0xc
> > >>[-- MARK -- Fri Apr 12 06:15:00 2013]
> > >>� 16289.386061¨ INFO: rcu_sched self-detected stall on CPU { 0} (t=42010
> > >>jiffies
> > >> g=89766 c=89765 q=10627)
> > >Did the system really crash or did you just see the rcu related
> > >warning(s)?
> >
> > I just check it again, actually at first the system didn't really
> > crash, but the system is very slow in response.
> > and the reproducer process can't be killed, after I did some common
> > actions such as 'ls' 'vim' etc, the system
> > seemed to be really crashed, no any response.
> >
> > also in the previous testing, I can remember that the system would
> > be no any response for a long time, just only
> > repeatedly print out the such above 'Call Trace' into console.
>
> Ok, thanks.
> Just a couple of more questions: did you see this also on other archs, or
> just
> s390 (if you tried other platforms at all).
>
> If you have some time, could you please repeat your test with the kernel
> command line option " user_mode=home "?
I tested the system with the kernel parameter, but the issue still appeared,
I just to say it takes longer time to reproduce the issue than the before.
>
> As far as I can tell there was only one s390 patch merged that was
> mmap related: 486c0a0bc80d370471b21662bf03f04fbb37cdc6 "s390/mm: Fix crst
> upgrade of mmap with MAP_FIXED".
also I tested the revert commit, unluckily, the same issue as the before.
--
Thanks,
Zhouping
On Thu, Apr 18, 2013 at 02:27:45AM -0400, Zhouping Liu wrote:
> Hello Heiko,
> > If you have some time, could you please repeat your test with the kernel
> > command line option " user_mode=home "?
>
> I tested the system with the kernel parameter, but the issue still appeared,
> I just to say it takes longer time to reproduce the issue than the before.
>
> >
> > As far as I can tell there was only one s390 patch merged that was
> > mmap related: 486c0a0bc80d370471b21662bf03f04fbb37cdc6 "s390/mm: Fix crst
> > upgrade of mmap with MAP_FIXED".
>
> also I tested the revert commit, unluckily, the same issue as the before.
Ok, thanks for verifying! I'll look into it; hopefully I can reproduce it
here as well.
Thanks!
On Thu, Apr 18, 2013 at 09:13:03AM +0200, Heiko Carstens wrote:
> Ok, thanks for verifying! I'll look into it; hopefully I can reproduce it
> here as well.
That seems to be a common code bug. I can easily trigger the VM_BUG_ON()
below (when I force the system to swap):
[ 48.347963] ------------[ cut here ]------------
[ 48.347972] kernel BUG at mm/memcontrol.c:3994!
[ 48.348012] illegal operation: 0001 [#1] SMP
[ 48.348015] Modules linked in:
[ 48.348017] CPU: 1 Not tainted 3.9.0-rc8+ #38
[ 48.348020] Process mmap2 (pid: 635, task: 0000000029476100, ksp: 000000002e91b938)
[ 48.348022] Krnl PSW : 0704f00180000000 000000000026552c (__mem_cgroup_uncharge_common+0x2c4/0x33c)
[ 48.348032] R:0 T:1 IO:1 EX:1 Key:0 M:1 W:0 P:0 AS:3 CC:3 PM:0 EA:3
Krnl GPRS: 0000000000000008 0000000000000009 000003d1002a9200 0000000000000000
[ 48.348039] 0000000000000000 00000000006812d8 000003ffdf339000 00000000321a6f98
[ 48.348043] 000003fffce11000 0000000000000000 0000000000000001 000003d1002a9200
[ 48.348046] 0000000000000001 0000000000681b88 000000002e91bc18 000000002e91bbd0
[ 48.348057] Krnl Code: 000000000026551e: c0e5fffaa2a1 brasl %r14,1b9a60
0000000000265524: a7f4ff7d brc 15,26541e
#0000000000265528: a7f40001 brc 15,26552a
>000000000026552c: e3c0b8200124 stg %r12,6176(%r11)
0000000000265532: a7f4ff57 brc 15,2653e0
0000000000265536: e310b8280104 lg %r1,6184(%r11)
000000000026553c: a71b0001 aghi %r1,1
0000000000265540: e310b8280124 stg %r1,6184(%r11)
[ 48.348099] Call Trace:
[ 48.348100] ([<000003d1002a91c0>] 0x3d1002a91c0)
[ 48.348102] [<00000000002404aa>] page_remove_rmap+0xf2/0x16c
[ 48.348106] [<0000000000232dc8>] unmap_single_vma+0x494/0x7d8
[ 48.348107] [<0000000000233ac0>] unmap_vmas+0x50/0x74
[ 48.348109] [<00000000002396ec>] unmap_region+0x9c/0x110
[ 48.348110] [<000000000023bd18>] do_munmap+0x284/0x470
[ 48.348111] [<000000000023bf56>] vm_munmap+0x52/0x70
[ 48.348113] [<000000000023cf32>] SyS_munmap+0x3a/0x4c
[ 48.348114] [<0000000000665e14>] sysc_noemu+0x22/0x28
[ 48.348118] [<000003fffcf187b2>] 0x3fffcf187b2
[ 48.348119] Last Breaking-Event-Address:
[ 48.348120] [<0000000000265528>] __mem_cgroup_uncharge_common+0x2c0/0x33c
Looking at the code, the code flow is:
page_remove_rmap() -> mem_cgroup_uncharge_page() -> __mem_cgroup_uncharge_common()
Note that in mem_cgroup_uncharge_page() the page in question passed the check:
[...]
if (PageSwapCache(page))
return;
[...]
and just a couple of instructions later the VM_BUG_ON() within
__mem_cgroup_uncharge_common() triggers:
[...]
if (mem_cgroup_disabled())
return NULL;
VM_BUG_ON(PageSwapCache(page));
[...]
Which means that another cpu changed the pageflags concurrently. In fact,
looking at the dump a different cpu is indeed busy with running kswapd.
So.. this seems to be somewhat broken. Anyone familiar with memcontrol?
On Wed 24-04-13 12:42:55, Heiko Carstens wrote:
> On Thu, Apr 18, 2013 at 09:13:03AM +0200, Heiko Carstens wrote:
> > Ok, thanks for verifying! I'll look into it; hopefully I can reproduce it
> > here as well.
>
> That seems to be a common code bug. I can easily trigger the VM_BUG_ON()
> below (when I force the system to swap):
>
> [ 48.347963] ------------[ cut here ]------------
> [ 48.347972] kernel BUG at mm/memcontrol.c:3994!
> [ 48.348012] illegal operation: 0001 [#1] SMP
> [ 48.348015] Modules linked in:
> [ 48.348017] CPU: 1 Not tainted 3.9.0-rc8+ #38
> [ 48.348020] Process mmap2 (pid: 635, task: 0000000029476100, ksp: 000000002e91b938)
> [ 48.348022] Krnl PSW : 0704f00180000000 000000000026552c (__mem_cgroup_uncharge_common+0x2c4/0x33c)
> [ 48.348032] R:0 T:1 IO:1 EX:1 Key:0 M:1 W:0 P:0 AS:3 CC:3 PM:0 EA:3
> Krnl GPRS: 0000000000000008 0000000000000009 000003d1002a9200 0000000000000000
> [ 48.348039] 0000000000000000 00000000006812d8 000003ffdf339000 00000000321a6f98
> [ 48.348043] 000003fffce11000 0000000000000000 0000000000000001 000003d1002a9200
> [ 48.348046] 0000000000000001 0000000000681b88 000000002e91bc18 000000002e91bbd0
> [ 48.348057] Krnl Code: 000000000026551e: c0e5fffaa2a1 brasl %r14,1b9a60
> 0000000000265524: a7f4ff7d brc 15,26541e
> #0000000000265528: a7f40001 brc 15,26552a
> >000000000026552c: e3c0b8200124 stg %r12,6176(%r11)
> 0000000000265532: a7f4ff57 brc 15,2653e0
> 0000000000265536: e310b8280104 lg %r1,6184(%r11)
> 000000000026553c: a71b0001 aghi %r1,1
> 0000000000265540: e310b8280124 stg %r1,6184(%r11)
> [ 48.348099] Call Trace:
> [ 48.348100] ([<000003d1002a91c0>] 0x3d1002a91c0)
> [ 48.348102] [<00000000002404aa>] page_remove_rmap+0xf2/0x16c
> [ 48.348106] [<0000000000232dc8>] unmap_single_vma+0x494/0x7d8
> [ 48.348107] [<0000000000233ac0>] unmap_vmas+0x50/0x74
> [ 48.348109] [<00000000002396ec>] unmap_region+0x9c/0x110
> [ 48.348110] [<000000000023bd18>] do_munmap+0x284/0x470
> [ 48.348111] [<000000000023bf56>] vm_munmap+0x52/0x70
> [ 48.348113] [<000000000023cf32>] SyS_munmap+0x3a/0x4c
> [ 48.348114] [<0000000000665e14>] sysc_noemu+0x22/0x28
> [ 48.348118] [<000003fffcf187b2>] 0x3fffcf187b2
> [ 48.348119] Last Breaking-Event-Address:
> [ 48.348120] [<0000000000265528>] __mem_cgroup_uncharge_common+0x2c0/0x33c
>
> Looking at the code, the code flow is:
>
> page_remove_rmap() -> mem_cgroup_uncharge_page() -> __mem_cgroup_uncharge_common()
>
> Note that in mem_cgroup_uncharge_page() the page in question passed the check:
>
> [...]
> if (PageSwapCache(page))
> return;
> [...]
>
> and just a couple of instructions later the VM_BUG_ON() within
> __mem_cgroup_uncharge_common() triggers:
>
> [...]
> if (mem_cgroup_disabled())
> return NULL;
>
> VM_BUG_ON(PageSwapCache(page));
> [...]
>
> Which means that another cpu changed the pageflags concurrently. In fact,
> looking at the dump a different cpu is indeed busy with running kswapd.
Hmm, maybe I am missing something but it really looks like we can race
here. Reclaim path takes the page lock while zap_pte takes page table
lock so nothing prevents them from racing here:
shrink_page_list zap_pte_range
trylock_page pte_offset_map_lock
add_to_swap page_remove_rmap
/* Page can be still mapped */
add_to_swap_cache atomic_add_negative(_mapcount)
__add_to_swap_cache mem_cgroup_uncharge_page
(PageSwapCache(page)) && return
SetPageSwapCache
__mem_cgroup_uncharge_common
VM_BUG_ON(PageSwapCache(page))
Maybe not many people run with CONFIG_DEBUG_VM enabled these days so we
do not this more often (even me testing configs are not consistent in
that regards and only few have it on). The only thing that changed in
this area recently is 0c59b89c which made the test VM_BUG_ON rather then
simple return in 3.6
And maybe the BUG_ON is too harsh as CgroupUsed should guarantee that
the uncharge will eventually go away. What do you think Johannes?
> So.. this seems to be somewhat broken. Anyone familiar with memcontrol?
--
Michal Hocko
SUSE Labs
On Wed, Apr 24, 2013 at 03:18:51PM +0200, Michal Hocko wrote:
> On Wed 24-04-13 12:42:55, Heiko Carstens wrote:
> > On Thu, Apr 18, 2013 at 09:13:03AM +0200, Heiko Carstens wrote:
> > > Ok, thanks for verifying! I'll look into it; hopefully I can reproduce it
> > > here as well.
> >
> > That seems to be a common code bug. I can easily trigger the VM_BUG_ON()
> > below (when I force the system to swap):
> >
> > [ 48.347963] ------------[ cut here ]------------
> > [ 48.347972] kernel BUG at mm/memcontrol.c:3994!
> > [ 48.348012] illegal operation: 0001 [#1] SMP
> > [ 48.348015] Modules linked in:
> > [ 48.348017] CPU: 1 Not tainted 3.9.0-rc8+ #38
> > [ 48.348020] Process mmap2 (pid: 635, task: 0000000029476100, ksp: 000000002e91b938)
> > [ 48.348022] Krnl PSW : 0704f00180000000 000000000026552c (__mem_cgroup_uncharge_common+0x2c4/0x33c)
> > [ 48.348032] R:0 T:1 IO:1 EX:1 Key:0 M:1 W:0 P:0 AS:3 CC:3 PM:0 EA:3
> > Krnl GPRS: 0000000000000008 0000000000000009 000003d1002a9200 0000000000000000
> > [ 48.348039] 0000000000000000 00000000006812d8 000003ffdf339000 00000000321a6f98
> > [ 48.348043] 000003fffce11000 0000000000000000 0000000000000001 000003d1002a9200
> > [ 48.348046] 0000000000000001 0000000000681b88 000000002e91bc18 000000002e91bbd0
> > [ 48.348057] Krnl Code: 000000000026551e: c0e5fffaa2a1 brasl %r14,1b9a60
> > 0000000000265524: a7f4ff7d brc 15,26541e
> > #0000000000265528: a7f40001 brc 15,26552a
> > >000000000026552c: e3c0b8200124 stg %r12,6176(%r11)
> > 0000000000265532: a7f4ff57 brc 15,2653e0
> > 0000000000265536: e310b8280104 lg %r1,6184(%r11)
> > 000000000026553c: a71b0001 aghi %r1,1
> > 0000000000265540: e310b8280124 stg %r1,6184(%r11)
> > [ 48.348099] Call Trace:
> > [ 48.348100] ([<000003d1002a91c0>] 0x3d1002a91c0)
> > [ 48.348102] [<00000000002404aa>] page_remove_rmap+0xf2/0x16c
> > [ 48.348106] [<0000000000232dc8>] unmap_single_vma+0x494/0x7d8
> > [ 48.348107] [<0000000000233ac0>] unmap_vmas+0x50/0x74
> > [ 48.348109] [<00000000002396ec>] unmap_region+0x9c/0x110
> > [ 48.348110] [<000000000023bd18>] do_munmap+0x284/0x470
> > [ 48.348111] [<000000000023bf56>] vm_munmap+0x52/0x70
> > [ 48.348113] [<000000000023cf32>] SyS_munmap+0x3a/0x4c
> > [ 48.348114] [<0000000000665e14>] sysc_noemu+0x22/0x28
> > [ 48.348118] [<000003fffcf187b2>] 0x3fffcf187b2
> > [ 48.348119] Last Breaking-Event-Address:
> > [ 48.348120] [<0000000000265528>] __mem_cgroup_uncharge_common+0x2c0/0x33c
> >
> > Looking at the code, the code flow is:
> >
> > page_remove_rmap() -> mem_cgroup_uncharge_page() -> __mem_cgroup_uncharge_common()
> >
> > Note that in mem_cgroup_uncharge_page() the page in question passed the check:
> >
> > [...]
> > if (PageSwapCache(page))
> > return;
> > [...]
> >
> > and just a couple of instructions later the VM_BUG_ON() within
> > __mem_cgroup_uncharge_common() triggers:
> >
> > [...]
> > if (mem_cgroup_disabled())
> > return NULL;
> >
> > VM_BUG_ON(PageSwapCache(page));
> > [...]
> >
> > Which means that another cpu changed the pageflags concurrently. In fact,
> > looking at the dump a different cpu is indeed busy with running kswapd.
>
> Hmm, maybe I am missing something but it really looks like we can race
> here. Reclaim path takes the page lock while zap_pte takes page table
> lock so nothing prevents them from racing here:
> shrink_page_list zap_pte_range
> trylock_page pte_offset_map_lock
> add_to_swap page_remove_rmap
> /* Page can be still mapped */
> add_to_swap_cache atomic_add_negative(_mapcount)
> __add_to_swap_cache mem_cgroup_uncharge_page
> (PageSwapCache(page)) && return
> SetPageSwapCache
> __mem_cgroup_uncharge_common
> VM_BUG_ON(PageSwapCache(page))
>
> Maybe not many people run with CONFIG_DEBUG_VM enabled these days so we
> do not this more often (even me testing configs are not consistent in
> that regards and only few have it on). The only thing that changed in
> this area recently is 0c59b89c which made the test VM_BUG_ON rather then
> simple return in 3.6
> And maybe the BUG_ON is too harsh as CgroupUsed should guarantee that
> the uncharge will eventually go away. What do you think Johannes?
Interesting. We need to ensure there is ordering between setting
PG_swapcache and installing swap entries because I think we are the
only ones looking at PG_swapcache without the page lock held. So we
don't have a safe way to check for PG_swapcache but if we get it
wrong, we may steal an uncharge that uncharge_swapcache() should be
doing instead and that means we mess up the swap statistics
accounting.
So how can we, without holding the page lock, either safely back off
from a page in swapcache or make sure we do the swap statistics
accounting when uncharging a swapcache page from the final unmap?
On Wed, 24 Apr 2013, Johannes Weiner wrote:
> On Wed, Apr 24, 2013 at 03:18:51PM +0200, Michal Hocko wrote:
> > On Wed 24-04-13 12:42:55, Heiko Carstens wrote:
> > > On Thu, Apr 18, 2013 at 09:13:03AM +0200, Heiko Carstens wrote:
> > > > Ok, thanks for verifying! I'll look into it; hopefully I can reproduce it
> > > > here as well.
> > >
> > > That seems to be a common code bug. I can easily trigger the VM_BUG_ON()
> > > below (when I force the system to swap):
> > >
> > > [ 48.347963] ------------[ cut here ]------------
> > > [ 48.347972] kernel BUG at mm/memcontrol.c:3994!
> > > [ 48.348012] illegal operation: 0001 [#1] SMP
> > > [ 48.348015] Modules linked in:
> > > [ 48.348017] CPU: 1 Not tainted 3.9.0-rc8+ #38
> > > [ 48.348020] Process mmap2 (pid: 635, task: 0000000029476100, ksp: 000000002e91b938)
> > > [ 48.348022] Krnl PSW : 0704f00180000000 000000000026552c (__mem_cgroup_uncharge_common+0x2c4/0x33c)
> > > [ 48.348032] R:0 T:1 IO:1 EX:1 Key:0 M:1 W:0 P:0 AS:3 CC:3 PM:0 EA:3
> > > Krnl GPRS: 0000000000000008 0000000000000009 000003d1002a9200 0000000000000000
> > > [ 48.348039] 0000000000000000 00000000006812d8 000003ffdf339000 00000000321a6f98
> > > [ 48.348043] 000003fffce11000 0000000000000000 0000000000000001 000003d1002a9200
> > > [ 48.348046] 0000000000000001 0000000000681b88 000000002e91bc18 000000002e91bbd0
> > > [ 48.348057] Krnl Code: 000000000026551e: c0e5fffaa2a1 brasl %r14,1b9a60
> > > 0000000000265524: a7f4ff7d brc 15,26541e
> > > #0000000000265528: a7f40001 brc 15,26552a
> > > >000000000026552c: e3c0b8200124 stg %r12,6176(%r11)
> > > 0000000000265532: a7f4ff57 brc 15,2653e0
> > > 0000000000265536: e310b8280104 lg %r1,6184(%r11)
> > > 000000000026553c: a71b0001 aghi %r1,1
> > > 0000000000265540: e310b8280124 stg %r1,6184(%r11)
> > > [ 48.348099] Call Trace:
> > > [ 48.348100] ([<000003d1002a91c0>] 0x3d1002a91c0)
> > > [ 48.348102] [<00000000002404aa>] page_remove_rmap+0xf2/0x16c
> > > [ 48.348106] [<0000000000232dc8>] unmap_single_vma+0x494/0x7d8
> > > [ 48.348107] [<0000000000233ac0>] unmap_vmas+0x50/0x74
> > > [ 48.348109] [<00000000002396ec>] unmap_region+0x9c/0x110
> > > [ 48.348110] [<000000000023bd18>] do_munmap+0x284/0x470
> > > [ 48.348111] [<000000000023bf56>] vm_munmap+0x52/0x70
> > > [ 48.348113] [<000000000023cf32>] SyS_munmap+0x3a/0x4c
> > > [ 48.348114] [<0000000000665e14>] sysc_noemu+0x22/0x28
> > > [ 48.348118] [<000003fffcf187b2>] 0x3fffcf187b2
> > > [ 48.348119] Last Breaking-Event-Address:
> > > [ 48.348120] [<0000000000265528>] __mem_cgroup_uncharge_common+0x2c0/0x33c
> > >
> > > Looking at the code, the code flow is:
> > >
> > > page_remove_rmap() -> mem_cgroup_uncharge_page() -> __mem_cgroup_uncharge_common()
> > >
> > > Note that in mem_cgroup_uncharge_page() the page in question passed the check:
> > >
> > > [...]
> > > if (PageSwapCache(page))
> > > return;
> > > [...]
> > >
> > > and just a couple of instructions later the VM_BUG_ON() within
> > > __mem_cgroup_uncharge_common() triggers:
> > >
> > > [...]
> > > if (mem_cgroup_disabled())
> > > return NULL;
> > >
> > > VM_BUG_ON(PageSwapCache(page));
> > > [...]
> > >
> > > Which means that another cpu changed the pageflags concurrently. In fact,
> > > looking at the dump a different cpu is indeed busy with running kswapd.
> >
> > Hmm, maybe I am missing something but it really looks like we can race
> > here. Reclaim path takes the page lock while zap_pte takes page table
> > lock so nothing prevents them from racing here:
> > shrink_page_list zap_pte_range
> > trylock_page pte_offset_map_lock
> > add_to_swap page_remove_rmap
> > /* Page can be still mapped */
> > add_to_swap_cache atomic_add_negative(_mapcount)
> > __add_to_swap_cache mem_cgroup_uncharge_page
> > (PageSwapCache(page)) && return
> > SetPageSwapCache
> > __mem_cgroup_uncharge_common
> > VM_BUG_ON(PageSwapCache(page))
> >
> > Maybe not many people run with CONFIG_DEBUG_VM enabled these days so we
> > do not this more often (even me testing configs are not consistent in
> > that regards and only few have it on). The only thing that changed in
> > this area recently is 0c59b89c which made the test VM_BUG_ON rather then
> > simple return in 3.6
> > And maybe the BUG_ON is too harsh as CgroupUsed should guarantee that
> > the uncharge will eventually go away. What do you think Johannes?
>
> Interesting. We need to ensure there is ordering between setting
> PG_swapcache and installing swap entries because I think we are the
> only ones looking at PG_swapcache without the page lock held. So we
> don't have a safe way to check for PG_swapcache but if we get it
> wrong, we may steal an uncharge that uncharge_swapcache() should be
> doing instead and that means we mess up the swap statistics
> accounting.
>
> So how can we, without holding the page lock, either safely back off
> from a page in swapcache or make sure we do the swap statistics
> accounting when uncharging a swapcache page from the final unmap?
Awkward.
I agree that the actual memcg uncharging should be okay, but the memsw
swap stats will go wrong (doesn't matter toooo much), and mem_cgroup_put
get missed (leaking a struct mem_cgroup).
I confess to having seen this myself, just once, on x86_64 3.8-rc6-mm1
plus some patches I was testing; but I never got back to look into it.
I wonder if something gone into 3.9 has changed the timing to make it
more easily reproduced now; but the underlying problem has been there
a long time - long before your VM_BUG_ON was there to expose it.
For now I guess the best is just to remove the VM_BUG_ON, or restore
it to a (usually redundant) return NULL, and live with the old leak.
But the real fix... I fear it may involve adding another PageCgroup
flag, just for memsw, to ensure that its counts are kept in balance
even when SwapCache races cause what's been charged in one way to
get uncharged in an unexpected way.
All those PageSwapCache and page_mapped tests are suspect: I expect
most will turn out to be okay, one way or another, but they are
suspicious and deserve audit.
(But I won't be working on this myself, sorry.)
Hugh
On Wed, Apr 24, 2013 at 08:50:01PM -0700, Hugh Dickins wrote:
> On Wed, 24 Apr 2013, Johannes Weiner wrote:
> > On Wed, Apr 24, 2013 at 03:18:51PM +0200, Michal Hocko wrote:
> > > On Wed 24-04-13 12:42:55, Heiko Carstens wrote:
> > > > On Thu, Apr 18, 2013 at 09:13:03AM +0200, Heiko Carstens wrote:
> > > > > Ok, thanks for verifying! I'll look into it; hopefully I can reproduce it
> > > > > here as well.
> > > >
> > > > That seems to be a common code bug. I can easily trigger the VM_BUG_ON()
> > > > below (when I force the system to swap):
> > > >
> > > > [ 48.347963] ------------[ cut here ]------------
> > > > [ 48.347972] kernel BUG at mm/memcontrol.c:3994!
> > > > [ 48.348012] illegal operation: 0001 [#1] SMP
> > > > [ 48.348015] Modules linked in:
> > > > [ 48.348017] CPU: 1 Not tainted 3.9.0-rc8+ #38
> > > > [ 48.348020] Process mmap2 (pid: 635, task: 0000000029476100, ksp: 000000002e91b938)
> > > > [ 48.348022] Krnl PSW : 0704f00180000000 000000000026552c (__mem_cgroup_uncharge_common+0x2c4/0x33c)
> > > > [ 48.348032] R:0 T:1 IO:1 EX:1 Key:0 M:1 W:0 P:0 AS:3 CC:3 PM:0 EA:3
> > > > Krnl GPRS: 0000000000000008 0000000000000009 000003d1002a9200 0000000000000000
> > > > [ 48.348039] 0000000000000000 00000000006812d8 000003ffdf339000 00000000321a6f98
> > > > [ 48.348043] 000003fffce11000 0000000000000000 0000000000000001 000003d1002a9200
> > > > [ 48.348046] 0000000000000001 0000000000681b88 000000002e91bc18 000000002e91bbd0
> > > > [ 48.348057] Krnl Code: 000000000026551e: c0e5fffaa2a1 brasl %r14,1b9a60
> > > > 0000000000265524: a7f4ff7d brc 15,26541e
> > > > #0000000000265528: a7f40001 brc 15,26552a
> > > > >000000000026552c: e3c0b8200124 stg %r12,6176(%r11)
> > > > 0000000000265532: a7f4ff57 brc 15,2653e0
> > > > 0000000000265536: e310b8280104 lg %r1,6184(%r11)
> > > > 000000000026553c: a71b0001 aghi %r1,1
> > > > 0000000000265540: e310b8280124 stg %r1,6184(%r11)
> > > > [ 48.348099] Call Trace:
> > > > [ 48.348100] ([<000003d1002a91c0>] 0x3d1002a91c0)
> > > > [ 48.348102] [<00000000002404aa>] page_remove_rmap+0xf2/0x16c
> > > > [ 48.348106] [<0000000000232dc8>] unmap_single_vma+0x494/0x7d8
> > > > [ 48.348107] [<0000000000233ac0>] unmap_vmas+0x50/0x74
> > > > [ 48.348109] [<00000000002396ec>] unmap_region+0x9c/0x110
> > > > [ 48.348110] [<000000000023bd18>] do_munmap+0x284/0x470
> > > > [ 48.348111] [<000000000023bf56>] vm_munmap+0x52/0x70
> > > > [ 48.348113] [<000000000023cf32>] SyS_munmap+0x3a/0x4c
> > > > [ 48.348114] [<0000000000665e14>] sysc_noemu+0x22/0x28
> > > > [ 48.348118] [<000003fffcf187b2>] 0x3fffcf187b2
> > > > [ 48.348119] Last Breaking-Event-Address:
> > > > [ 48.348120] [<0000000000265528>] __mem_cgroup_uncharge_common+0x2c0/0x33c
> > > >
> > > > Looking at the code, the code flow is:
> > > >
> > > > page_remove_rmap() -> mem_cgroup_uncharge_page() -> __mem_cgroup_uncharge_common()
> > > >
> > > > Note that in mem_cgroup_uncharge_page() the page in question passed the check:
> > > >
> > > > [...]
> > > > if (PageSwapCache(page))
> > > > return;
> > > > [...]
> > > >
> > > > and just a couple of instructions later the VM_BUG_ON() within
> > > > __mem_cgroup_uncharge_common() triggers:
> > > >
> > > > [...]
> > > > if (mem_cgroup_disabled())
> > > > return NULL;
> > > >
> > > > VM_BUG_ON(PageSwapCache(page));
> > > > [...]
> > > >
> > > > Which means that another cpu changed the pageflags concurrently. In fact,
> > > > looking at the dump a different cpu is indeed busy with running kswapd.
> > >
> > > Hmm, maybe I am missing something but it really looks like we can race
> > > here. Reclaim path takes the page lock while zap_pte takes page table
> > > lock so nothing prevents them from racing here:
> > > shrink_page_list zap_pte_range
> > > trylock_page pte_offset_map_lock
> > > add_to_swap page_remove_rmap
> > > /* Page can be still mapped */
> > > add_to_swap_cache atomic_add_negative(_mapcount)
> > > __add_to_swap_cache mem_cgroup_uncharge_page
> > > (PageSwapCache(page)) && return
> > > SetPageSwapCache
> > > __mem_cgroup_uncharge_common
> > > VM_BUG_ON(PageSwapCache(page))
> > >
> > > Maybe not many people run with CONFIG_DEBUG_VM enabled these days so we
> > > do not this more often (even me testing configs are not consistent in
> > > that regards and only few have it on). The only thing that changed in
> > > this area recently is 0c59b89c which made the test VM_BUG_ON rather then
> > > simple return in 3.6
> > > And maybe the BUG_ON is too harsh as CgroupUsed should guarantee that
> > > the uncharge will eventually go away. What do you think Johannes?
> >
> > Interesting. We need to ensure there is ordering between setting
> > PG_swapcache and installing swap entries because I think we are the
> > only ones looking at PG_swapcache without the page lock held. So we
> > don't have a safe way to check for PG_swapcache but if we get it
> > wrong, we may steal an uncharge that uncharge_swapcache() should be
> > doing instead and that means we mess up the swap statistics
> > accounting.
> >
> > So how can we, without holding the page lock, either safely back off
> > from a page in swapcache or make sure we do the swap statistics
> > accounting when uncharging a swapcache page from the final unmap?
>
> Awkward.
>
> I agree that the actual memcg uncharging should be okay, but the memsw
> swap stats will go wrong (doesn't matter toooo much), and mem_cgroup_put
> get missed (leaking a struct mem_cgroup).
Ok, so I just went over this again. For the swapout path the memsw
uncharge is deferred, but if we "steal" this uncharge from the swap
code, we actually do uncharge memsw in mem_cgroup_do_uncharge(), so we
may prematurely unaccount the swap page, but we never leak a charge.
Good.
Because of this stealing, we also don't do the following:
if (do_swap_account && ctype == MEM_CGROUP_CHARGE_TYPE_SWAPOUT) {
mem_cgroup_swap_statistics(memcg, true);
mem_cgroup_get(memcg);
}
I.e. it does not matter that mem_cgroup_uncharge_swap() doesn't do the
put, we are also not doing the get. We should not leak references.
So the only thing that I can see go wrong is that we may have a
swapped out page that is not charged to memsw and not accounted as
MEM_CGROUP_STAT_SWAP. But I don't know how likely that is, because we
check for PG_swapcache in this uncharge path after the last pte is
torn down, so even though the page is put on swap cache, it probably
won't be swapped. It would require that the PG_swapcache setting
would become visible only after the page has been added to the swap
cache AND rmap has established at least one swap pte for us to
uncharge a page that actually continues to be used. And that's a bit
of a stretch, I think.
Did I miss something? If not, I'll just send a patch that removes the
VM_BUG_ON() and adds a comment describing the scenarios and a note
that we may want to fix this in the future.
Thanks!
On Tue, 30 Apr 2013, Johannes Weiner wrote:
> On Wed, Apr 24, 2013 at 08:50:01PM -0700, Hugh Dickins wrote:
> > On Wed, 24 Apr 2013, Johannes Weiner wrote:
> > > On Wed, Apr 24, 2013 at 03:18:51PM +0200, Michal Hocko wrote:
> > > > On Wed 24-04-13 12:42:55, Heiko Carstens wrote:
> > > > > On Thu, Apr 18, 2013 at 09:13:03AM +0200, Heiko Carstens wrote:
> > > > >
> > > > > [ 48.347963] ------------[ cut here ]------------
> > > > > [ 48.347972] kernel BUG at mm/memcontrol.c:3994!
> > > > > __mem_cgroup_uncharge_common() triggers:
> > > > >
> > > > > [...]
> > > > > if (mem_cgroup_disabled())
> > > > > return NULL;
> > > > >
> > > > > VM_BUG_ON(PageSwapCache(page));
> > > > > [...]
> >
> > I agree that the actual memcg uncharging should be okay, but the memsw
> > swap stats will go wrong (doesn't matter toooo much), and mem_cgroup_put
> > get missed (leaking a struct mem_cgroup).
>
> Ok, so I just went over this again. For the swapout path the memsw
> uncharge is deferred, but if we "steal" this uncharge from the swap
> code, we actually do uncharge memsw in mem_cgroup_do_uncharge(), so we
> may prematurely unaccount the swap page, but we never leak a charge.
> Good.
>
> Because of this stealing, we also don't do the following:
>
> if (do_swap_account && ctype == MEM_CGROUP_CHARGE_TYPE_SWAPOUT) {
> mem_cgroup_swap_statistics(memcg, true);
> mem_cgroup_get(memcg);
> }
>
> I.e. it does not matter that mem_cgroup_uncharge_swap() doesn't do the
> put, we are also not doing the get. We should not leak references.
>
> So the only thing that I can see go wrong is that we may have a
> swapped out page that is not charged to memsw and not accounted as
> MEM_CGROUP_STAT_SWAP. But I don't know how likely that is, because we
> check for PG_swapcache in this uncharge path after the last pte is
> torn down, so even though the page is put on swap cache, it probably
> won't be swapped. It would require that the PG_swapcache setting
> would become visible only after the page has been added to the swap
> cache AND rmap has established at least one swap pte for us to
> uncharge a page that actually continues to be used. And that's a bit
> of a stretch, I think.
Sorry, our minds seem to work in different ways,
I understood very little of what you wrote above :-(
But once I try to disprove you with a counter-example, I seem to
arrive at the same conclusion as you have (well, I haven't quite
arrived there yet, but cannot give it any more time).
Looking at it from my point of view, I concentrate on the racy
if (PageSwapCache(page))
return;
__mem_cgroup_uncharge_common(page, MEM_CGROUP_CHARGE_TYPE_ANON, false);
in mem_cgroup_uncharge_page().
Now, that may or may not catch the case where last reference to page
is unmapped at the same time as the page is added to swap: but being
a MEM_CGROUP_CHARGE_TYPE_ANON call, it does not interfere with the
memsw stats and get/put at all, those remain in balance.
And mem_cgroup_uncharge_swap() has all along been prepared to get
a zero id from swap_cgroup_record(), if a SwapCache page should be
uncharged when it was never quite charged as such.
Yes, we may occasionally fail to charge a SwapCache page as such
if its final unmap from userspace races with its being added to swap;
but it's heading towards swap_writepage()'s try_to_free_swap() anyway,
so I don't think that's anything to worry about.
(If I had time to stop and read through that, I'd probably find it
just as hard to understand as what you wrote!)
>
> Did I miss something? If not, I'll just send a patch that removes the
> VM_BUG_ON() and adds a comment describing the scenarios and a note
> that we may want to fix this in the future.
I don't think you missed something. Yes, please just send Linus and
Andrew a patch to remove the VM_BUG_ON() (with Cc stable tag), I now
agree that's all that's really needed - thanks.
Hugh
On Wed, May 01, 2013 at 08:28:30AM -0700, Hugh Dickins wrote:
> On Tue, 30 Apr 2013, Johannes Weiner wrote:
> > On Wed, Apr 24, 2013 at 08:50:01PM -0700, Hugh Dickins wrote:
> > > On Wed, 24 Apr 2013, Johannes Weiner wrote:
> > > > On Wed, Apr 24, 2013 at 03:18:51PM +0200, Michal Hocko wrote:
> > > > > On Wed 24-04-13 12:42:55, Heiko Carstens wrote:
> > > > > > On Thu, Apr 18, 2013 at 09:13:03AM +0200, Heiko Carstens wrote:
> > > > > >
> > > > > > [ 48.347963] ------------[ cut here ]------------
> > > > > > [ 48.347972] kernel BUG at mm/memcontrol.c:3994!
> > > > > > __mem_cgroup_uncharge_common() triggers:
> > > > > >
> > > > > > [...]
> > > > > > if (mem_cgroup_disabled())
> > > > > > return NULL;
> > > > > >
> > > > > > VM_BUG_ON(PageSwapCache(page));
> > > > > > [...]
> > >
> > > I agree that the actual memcg uncharging should be okay, but the memsw
> > > swap stats will go wrong (doesn't matter toooo much), and mem_cgroup_put
> > > get missed (leaking a struct mem_cgroup).
> >
> > Ok, so I just went over this again. For the swapout path the memsw
> > uncharge is deferred, but if we "steal" this uncharge from the swap
> > code, we actually do uncharge memsw in mem_cgroup_do_uncharge(), so we
> > may prematurely unaccount the swap page, but we never leak a charge.
> > Good.
> >
> > Because of this stealing, we also don't do the following:
> >
> > if (do_swap_account && ctype == MEM_CGROUP_CHARGE_TYPE_SWAPOUT) {
> > mem_cgroup_swap_statistics(memcg, true);
> > mem_cgroup_get(memcg);
> > }
> >
> > I.e. it does not matter that mem_cgroup_uncharge_swap() doesn't do the
> > put, we are also not doing the get. We should not leak references.
> >
> > So the only thing that I can see go wrong is that we may have a
> > swapped out page that is not charged to memsw and not accounted as
> > MEM_CGROUP_STAT_SWAP. But I don't know how likely that is, because we
> > check for PG_swapcache in this uncharge path after the last pte is
> > torn down, so even though the page is put on swap cache, it probably
> > won't be swapped. It would require that the PG_swapcache setting
> > would become visible only after the page has been added to the swap
> > cache AND rmap has established at least one swap pte for us to
> > uncharge a page that actually continues to be used. And that's a bit
> > of a stretch, I think.
>
> Sorry, our minds seem to work in different ways,
> I understood very little of what you wrote above :-(
>
> But once I try to disprove you with a counter-example, I seem to
> arrive at the same conclusion as you have (well, I haven't quite
> arrived there yet, but cannot give it any more time).
I might be losing my mind. But since you are reaching the same
conclusion, and I see the same mental milestones in your thought
process described below, it's more likely that I suck at describing my
train of thought coherently. Or the third possibility: we're both
losing it!
> Looking at it from my point of view, I concentrate on the racy
> if (PageSwapCache(page))
> return;
> __mem_cgroup_uncharge_common(page, MEM_CGROUP_CHARGE_TYPE_ANON, false);
> in mem_cgroup_uncharge_page().
>
> Now, that may or may not catch the case where last reference to page
> is unmapped at the same time as the page is added to swap: but being
> a MEM_CGROUP_CHARGE_TYPE_ANON call, it does not interfere with the
> memsw stats and get/put at all, those remain in balance.
Yes, exactly.
> And mem_cgroup_uncharge_swap() has all along been prepared to get
> a zero id from swap_cgroup_record(), if a SwapCache page should be
> uncharged when it was never quite charged as such.
>
> Yes, we may occasionally fail to charge a SwapCache page as such
> if its final unmap from userspace races with its being added to swap;
> but it's heading towards swap_writepage()'s try_to_free_swap() anyway,
> so I don't think that's anything to worry about.
Agreed as well. If there are no pte references to the swap slot, it
will be freed either way. I didn't even think of the
try_to_free_swap() in the writeout call, but was looking at the
__remove_mapping later on in reclaim that will do a swapcache_free().
The only case I was worried about is the following:
#0 #1
page_remove_rmap() shrink_page_list()
if --page->mapcount == 0: add_to_swap()
mem_cgroup_uncharge_page() __add_to_swap_cache()
if PageSwapCache: SetPageSwapCache()
return try_to_unmap()
__mem_cgroup_uncharge_common() for each pte:
install swp_entry_t
page->mapcount--
Looking at #1, I don't see anything that would force concurrent
threads to observe SetSwapCache ordered against the page->mapcount--.
My concern was that if those get reordered, #0 may see page->mapcount
== 1 AND !PageSwapcache, and then go ahead and uncharge the page while
there is actually a swp_entry_t pointing to it. The page will be a
proper long-term swap page without being charged as such.
> (If I had time to stop and read through that, I'd probably find it
> just as hard to understand as what you wrote!)
>
> >
> > Did I miss something? If not, I'll just send a patch that removes the
> > VM_BUG_ON() and adds a comment describing the scenarios and a note
> > that we may want to fix this in the future.
>
> I don't think you missed something. Yes, please just send Linus and
> Andrew a patch to remove the VM_BUG_ON() (with Cc stable tag), I now
> agree that's all that's really needed - thanks.
Will do, thanks for taking them time to think through it again, even
after failing to decipher my ramblings...
Johannes