Bad page state Aug 26, 2009

이러니 Linus에게 반하지 않을 수 밖에.

문제는 8월 초로 거슬러 올라간다.

Title : Bad page state (was Re: Linux 2.6.31-rc7)

8월 1일

Greetings;

2.6.31-rc5 rebooted to before amanda ran last night. The amanda run looks ok,
but I had also plugged in an empty 8GB usb key so I did a quick dmesg to see
where it was, and found this at the end of the dmesg report:

[ 7423.221754] BUG: Bad page state in process tar pfn:a1293
[ 7423.221760] page:c28fc260 flags:80004000 count:0 mapcount:0 mapping:(null)
index:0
[ 7423.221764] Pid: 19211, comm: tar Not tainted 2.6.31-rc5 #1
[ 7423.221766] Call Trace:
[ 7423.221774] [] ? printk+0x23/0x40
[ 7423.221780] [] bad_page+0xcf/0x150
[ 7423.221784] [] get_page_from_freelist+0x37d/0x480
[ 7423.221788] [] ? add_to_page_cache_lru+0x84/0x90
[ 7423.221791] [] __alloc_pages_nodemask+0xdf/0x520
[ 7423.221795] [] __do_page_cache_readahead+0x104/0x220
[ 7423.221798] [] ra_submit+0x34/0x50
[ 7423.221801] [] ondemand_readahead+0x120/0x240
[ 7423.221804] [] page_cache_async_readahead+0x9c/0xb0
[ 7423.221807] [] generic_file_aio_read+0x33c/0x6a0
[ 7423.221830] [] do_sync_read+0xe9/0x140
[ 7423.221835] [] ? autoremove_wake_function+0x0/0x60
[ 7423.221839] [] ? security_file_permission+0x1e/0x40
[ 7423.221842] [] ? rw_verify_area+0x60/0xe0
[ 7423.221845] [] vfs_read+0xb7/0x180
[ 7423.221848] [] ? do_sync_read+0x0/0x140
[ 7423.221850] [] sys_read+0x58/0xa0
[ 7423.221854] [] sysenter_do_call+0x12/0x22
[ 7423.221856] Disabling lock debugging due to kernel taint

The machine seems 100% so far. This kernel was built without that patch that
would make an oom more verbose. htop looks ok, as does slabtop.

Where should I take this?

위와 같은 BUG reporting이 올라왔다.
또한 8월 21일, 다시 한번 비슷한 문제가 같은 사람(Gene)에 의해 보고 되었다.

Aug 21 22:37:47 coyote kernel: [ 1030.152737] BUG: Bad page state in process lzma pfn:a1093
Aug 21 22:37:47 coyote kernel: [ 1030.152743] page:c28fc260 flags:80004000 count:0 mapcount:0 mapping:(null) index:0
Aug 21 22:37:47 coyote kernel: [ 1030.152747] Pid: 17927, comm: lzma Not tainted 2.6.31-rc7 #1
Aug 21 22:37:47 coyote kernel: [ 1030.152750] Call Trace:
Aug 21 22:37:47 coyote kernel: [ 1030.152758] [] ? printk+0x23/0x40
Aug 21 22:37:47 coyote kernel: [ 1030.152763] [] bad_page+0xcf/0x150
Aug 21 22:37:47 coyote kernel: [ 1030.152767] [] get_page_from_freelist+0x37d/0x480
Aug 21 22:37:47 coyote kernel: [ 1030.152771] [] __alloc_pages_nodemask+0xdf/0x520
Aug 21 22:37:47 coyote kernel: [ 1030.152775] [] handle_mm_fault+0x4a9/0x9f0
Aug 21 22:37:47 coyote kernel: [ 1030.152780] [] do_page_fault+0x141/0x290
Aug 21 22:37:47 coyote kernel: [ 1030.152784] [] ? do_page_fault+0x0/0x290
Aug 21 22:37:47 coyote kernel: [ 1030.152787] [] error_code+0x73/0x78
Aug 21 22:37:47 coyote kernel: [ 1030.152789] Disabling lock debugging due to kernel taint

bad_page는 사실 커널에서 거의 볼 수 없는 문제이다.
왜냐하면 mm guy들이 패치를 할 때 굉장히 꼼꼼히 챙기는 부분이기 때문이다.
그럼에도 불구하고 발생했다.

먼저 Linus가 의심한 것은 Wu의 20a0307c0396c2edb651401d2f2db193dda2f3c9 이 패치이다.
이 패치는 /proc/pagemap을 Huge Page까지 확장하기 위한 단순한 변경이었다.
그러므로 그리 가능성이 그리 크지 않아 보였다.

barrios를 비롯한 다른 mm guy들도 그 문제에 대해서
별 다른 언급을 하지 않았다. 그랬던 이유는 특별히 의심가는
부분을 생각할 수 없었기 때문이다.

하지만 Linus는 그 문제에 대해서 꾸준히 관심을 가지고
개인적으로 Gene에게 메일을 더 보내 여러 테스트를 요구한 것으로 보인다.

Gene가 보내온 또 다른 Oops.

Aug 22 22:29:07 coyote kernel: [ 2449.053652] BUG: Bad page state in process python pfn:a0e93
Aug 22 22:29:07 coyote kernel: [ 2449.053658] page:c28fc260 flags:80004000 count:0 mapcount:0 mapping:(null) index:0
Aug 22 22:29:07 coyote kernel: [ 2449.053662] Pid: 4818, comm: python Not tainted 2.6.31-rc7 #3
Aug 22 22:29:07 coyote kernel: [ 2449.053664] Call Trace:
Aug 22 22:29:07 coyote kernel: [ 2449.053672] [] ? printk+0x23/0x40
Aug 22 22:29:07 coyote kernel: [ 2449.053678] [] bad_page+0xcf/0x150
Aug 22 22:29:07 coyote kernel: [ 2449.053682] [] get_page_from_freelist+0x37d/0x480
Aug 22 22:29:07 coyote kernel: [ 2449.053686] [] __alloc_pages_nodemask+0xdf/0x520
Aug 22 22:29:07 coyote kernel: [ 2449.053691] [] handle_mm_fault+0x4a9/0x9f0
Aug 22 22:29:07 coyote kernel: [ 2449.053695] [] ? tick_dev_program_event+0x43/0xf0
Aug 22 22:29:07 coyote kernel: [ 2449.053699] [] ? tick_program_event+0x36/0x60
Aug 22 22:29:07 coyote kernel: [ 2449.053703] [] do_page_fault+0x141/0x290
Aug 22 22:29:07 coyote kernel: [ 2449.053707] [] ? do_page_fault+0x0/0x290
Aug 22 22:29:07 coyote kernel: [ 2449.053710] [] error_code+0x73/0x78
Aug 22 22:29:07 coyote kernel: [ 2449.053712] Disabling lock debugging due to kernel taint

결국, 8월 24일 Linus는 문제를 찾아냈다.

"It's not a kernel BUG!"

그것을 어떻게 알 수 있었을까?
위의 3 Oops를 보면 모두 bad page에서 detection된 것을 알 수 있다.
아주 운이 좋은 경우이다. bad page의 detection은 flag값을
통해 detect 되었음을 알 수 있다.

flag값의 0x4000의 bit이 set되어져 있었기 때문에 bad_page가
호출된 경우이다. 또한 3경우 모든 page의 가상 주소는 c28fc260이다.
즉, x86의 경우 28fc260의 물리 주소에서 문제가 발생하였다는 것이다.
왜 그렇게 생각할 수 있을까?

그럼 생각해보자. 모두 다른 경로를 통해 Oops가 발생하였지만,
희안하게도 Oops를 발생시켰던 곳은 28fc260 번지이고 모든
경우 flag 값이 같다. 즉, 0x4000이 set되어져 있다. PFN은
달라질 수 있다. 왜냐하면 pfn을 계산하기 위한
mem_map을 할당하는 위치가 booting 중 timing에따라 또는
kernel configuration에 따라 달라질 수 있기 때문이다.

하지만 barrios의 생각은 아무래도 booting 중 타이밍
문제보다는 kernel configuration이 틀려지지 않는 한 잘
바뀌지 않을 것 같다. kernel configuration 중에서도
bootmem allocator에 영향을 주는 경우에 한해서 그 값이
달라질 수 있을 것이다.


또한 flag는 page descriptor의 첫번째 멤버이다. 위에서 본 것 처럼
모든 error는 flag값에 의해 발생하였다. 그렇다는 얘기는 28fc260의
물리 메모리에 문제가 있다는 것을 의미할 수 있다. 그러므로 이 문제는
운이 좋게 mem_map이 할당된 메모리의 일부가 깨졌기 때문에 또한 해당
page가 사용중이 아니며 buddy에 free page로 존재하고 있었기 때문에
쉽게(?) 문제를 찾을 수 있는 경우이다. memory corruption이 다른 메모리
번지 였다면 시스템이 runtime에 random하게 crash되는 현상이 발생하였을
것이다.

현재 Linus는 문제가 28fc260의 bad memory로 인해 발생한 것이
거의 틀림 없다고 보고 있으며 Gene 또한 memory test로 인해
memory에 문제가 있음을 확인하였다.