2016.03.04
カテゴリ： ソフト開発日誌
ubuntu 14.04 をベースに kernel 3.18.25 に差し替えて UBI/UBIFS 負荷試験をさらに続けていた。root 権限でファイル操作をする負荷を掛けていた。root 権限だと「真の」file system full まで UBIFS volume に書き込める。
file system full まで書き込む操作を繰り返しているうちに kernel は停止する。console (printk) 出力を見ていると次の 2 つの stack dump が典型的な kernel 停止直前の出力だ。
(1) UBI assert failed in wl_tree_add at 203 (pid NNNN)
(2) BUG: unable to handle kernel NULL pointer dereference at 0000000000000020
IP: [<ffffffffa0273800>] wl_tree_add+0x40/0xf0 [ubi]
(1) の wl_tree_add() で assert した stack dump( 前後の出力をすべて含む )
(2) の wl_tree_add() で NULL pointer access をした stack dump 前後の出力をすべて含む
未編集のログ出力
負荷試験に nandsim.c を改造した nandsim_prof.c を使用している。これも後で整理しようと思う。nandsim_prof.c が "[nandsim] nandsim_prof_page_progs_update: ERROR: Too many program cycles after erase. row=8192, c=4, page_prog_max=4" と出力しているので page #8192 に対して 4 回書き込みをしていることが分かる。NAND memory によっては「追い書き」(partial write) 回数制限に抵触する。
wl.c の comment に書かれたことと source code を比べてみると CONFIG_MTD_UBI_FASTMAP がまとわりついている部分に関して comment の解説が乏しいことが分かる。後付けされたような fastmap が怪しい。
drivers/mtd/Kconfig を読むと CONFIG_MTD_UBI_FASTMAP "Experimental feature" だと説明がある。default では "N" だ。ubuntu distribution ではわざわざ Y (defined) にしてある(/boot/configs-* を参照)。
CONFIG_MTD_UBI_FASTMAP を .config から外し undefined (# CONFIG_XXX ... is not set) にして同様の負荷試験をしてみる。30～60 分しか負荷試験が持たなかったのが、半日以上連続試験に耐えている。
退職前に気になっていた問題、出来ていなかった負荷試験はおおよそ終わる。仕事でさわっていた kernel の CONFIG_MTD_UBI_FASTMAP がどうなっていたかは既に記憶にない。そもそも kernel の version は近いものを選んでいて、違っている。
UBI/UBIFS 以外にも自分が担当していたコードはある。これらは機器固有のコードだ。持ち出しは出来ない。持ち出したところで試す環境と手段がない。
出来る範囲の心残りは無くなった。さあ、新しい課題を見つけよう。
file system full まで書き込む操作を繰り返しているうちに kernel は停止する。console (printk) 出力を見ていると次の 2 つの stack dump が典型的な kernel 停止直前の出力だ。
(1) UBI assert failed in wl_tree_add at 203 (pid NNNN)
(2) BUG: unable to handle kernel NULL pointer dereference at 0000000000000020
IP: [<ffffffffa0273800>] wl_tree_add+0x40/0xf0 [ubi]
(1) の wl_tree_add() で assert した stack dump( 前後の出力をすべて含む )
[ 348.007307] UBI error: __wl_get_peb: no free eraseblocks
-- snip --
[ 1177.689377] UBI error: __wl_get_peb: no free eraseblocks
[ 1179.653004] [nandsim] nandsim_prof_page_progs_update: ERROR: Too many program cycles after erase. row=8192, c=4, page_prog_max=4
[ 1179.665065] UBI assert failed in wl_tree_add at 203 (pid 2610)
[ 1179.667078] CPU: 0 PID: 2610 Comm: ubifs_bgt0_0 Not tainted 3.18.25-ubifs.ex0+ #1
[ 1179.669473] Hardware name: innotek GmbH VirtualBox/VirtualBox, BIOS VirtualBox 12/01/2006
[ 1179.672855] ffff880007521688 ffff8800073478e8 ffffffff8174af24 dead000000100100
[ 1179.675500] ffff880007520870 ffff880007347928 ffffffffa0274898 ffff880007347928
[ 1179.680248] ffff880007520870 ffff880022179480 ffff880022178000 0000000000000000
[ 1179.684895] Call Trace:
[ 1179.686543] [<ffffffff8174af24>] dump_stack+0x51/0x6d
[ 1179.689633] [<ffffffffa0274898>] wl_tree_add+0xd8/0xf0 [ubi]
[ 1179.693185] [<ffffffffa0274d03>] erase_worker+0x453/0x8a0 [ubi]
[ 1179.696695] [<ffffffffa02744a5>] do_work+0xc5/0x150 [ubi]
[ 1179.699884] [<ffffffffa0276afb>] ubi_refill_pools+0x20b/0x3c0 [ubi]
[ 1179.703683] [<ffffffffa027d219>] ubi_update_fastmap+0x39/0x10e8 [ubi]
[ 1179.707493] [<ffffffffa026eb7b>] ? ubi_next_sqnum+0x2b/0x60 [ubi]
[ 1179.711174] [<ffffffffa02761ce>] ubi_wl_get_peb+0x3e/0xc0 [ubi]
[ 1179.714612] [<ffffffffa0270518>] ubi_eba_write_leb+0x178/0x720 [ubi]
[ 1179.718360] [<ffffffffa02c976c>] ? ubifs_change_lp+0x16c/0x740 [ubifs]
[ 1179.722367] [<ffffffffa026de7b>] ubi_leb_write+0x15b/0x160 [ubi]
[ 1179.725887] [<ffffffffa02ad38e>] ubifs_leb_write+0xbe/0x150 [ubifs]
[ 1179.729564] [<ffffffffa02c115b>] ubifs_tnc_end_commit+0x35b/0x6c0 [ubifs]
[ 1179.733619] [<ffffffffa02b9f54>] do_commit+0x234/0x640 [ubifs]
[ 1179.737094] [<ffffffffa02ba652>] ubifs_bg_thread+0x1d2/0x220 [ubifs]
[ 1179.740872] [<ffffffffa02ba480>] ? ubifs_run_commit+0x120/0x120 [ubifs]
[ 1179.745527] [<ffffffff810947de>] kthread+0xee/0x110
[ 1179.748425] [<ffffffff81752130>] ? _raw_spin_unlock_irq+0x30/0x50
[ 1179.752177] [<ffffffff810946f0>] ? __init_kthread_worker+0x70/0x70
[ 1179.756077] [<ffffffff817528d8>] ret_from_fork+0x58/0x90
[ 1179.759330] [<ffffffff810946f0>] ? __init_kthread_worker+0x70/0x70
[ 1179.762768] general protection fault: 0000 [#1] SMP
[ 1179.763687] Modules linked in: deflate ubifs ubi cmdlinepart nandsim_prof nand nand_ecc nand_bch bch nand_ids mtd rpcsec_gss_krb5 nfsv4 nfsd auth_rpcgss nfs_acl nfs lockd grace sunrpc joydev binfmt_misc fscache serio_raw i2c_piix4 hid_generic usbhid psmouse hid pcnet32 mii
[ 1179.763687] CPU: 0 PID: 2610 Comm: ubifs_bgt0_0 Not tainted 3.18.25-ubifs.ex0+ #1
[ 1179.763687] Hardware name: innotek GmbH VirtualBox/VirtualBox, BIOS VirtualBox 12/01/2006
[ 1179.763687] task: ffff880006a50000 ti: ffff880007344000 task.ti: ffff880007344000
[ 1179.763687] RIP: 0010:[<ffffffffa0274800>] [<ffffffffa0274800>] wl_tree_add+0x40/0xf0 [ubi]
[ 1179.763687] RSP: 0000:ffff8800073478f8 EFLAGS: 00010286
[ 1179.763687] RAX: ffff880007520870 RBX: dead000000200200 RCX: ffff880007520878
[ 1179.763687] RDX: 0000000000000100 RSI: 0000000000000001 RDI: ffff880007347f58
[ 1179.763687] RBP: ffff880007347928 R08: 0000000000000001 R09: 0000000000000001
[ 1179.763687] R10: 0000000000000001 R11: 0000000000000001 R12: ffff880007520878
[ 1179.763687] R13: ffff880007520870 R14: ffff8800221793e8 R15: ffff880006a50000
[ 1179.763687] FS: 0000000000000000(0000) GS:ffff88002fc00000(0000) knlGS:0000000000000000
[ 1179.763687] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[ 1179.763687] CR2: 00007f9911818cd8 CR3: 0000000028734000 CR4: 00000000000006f0
[ 1179.763687] Stack:
[ 1179.763687] ffff880007347928 ffff880007520870 ffff880022179480 ffff880022178000
[ 1179.763687] 0000000000000000 ffff8800221793e8 ffff8800073479b8 ffffffffa0274d03
[ 1179.763687] ffff8800073479b8 0000000000000246 0000000000000000 ffff8800221794d0
[ 1179.763687] Call Trace:
[ 1179.763687] [<ffffffffa0274d03>] erase_worker+0x453/0x8a0 [ubi]
[ 1179.763687] [<ffffffffa02744a5>] do_work+0xc5/0x150 [ubi]
[ 1179.763687] [<ffffffffa0276afb>] ubi_refill_pools+0x20b/0x3c0 [ubi]
[ 1179.763687] [<ffffffffa027d219>] ubi_update_fastmap+0x39/0x10e8 [ubi]
[ 1179.763687] [<ffffffffa026eb7b>] ? ubi_next_sqnum+0x2b/0x60 [ubi]
[ 1179.763687] [<ffffffffa02761ce>] ubi_wl_get_peb+0x3e/0xc0 [ubi]
[ 1179.763687] [<ffffffffa0270518>] ubi_eba_write_leb+0x178/0x720 [ubi]
[ 1179.763687] [<ffffffffa02c976c>] ? ubifs_change_lp+0x16c/0x740 [ubifs]
[ 1179.763687] [<ffffffffa026de7b>] ubi_leb_write+0x15b/0x160 [ubi]
[ 1179.763687] [<ffffffffa02ad38e>] ubifs_leb_write+0xbe/0x150 [ubifs]
[ 1179.763687] [<ffffffffa02c115b>] ubifs_tnc_end_commit+0x35b/0x6c0 [ubifs]
[ 1179.763687] [<ffffffffa02b9f54>] do_commit+0x234/0x640 [ubifs]
[ 1179.763687] [<ffffffffa02ba652>] ubifs_bg_thread+0x1d2/0x220 [ubifs]
[ 1179.763687] [<ffffffffa02ba480>] ? ubifs_run_commit+0x120/0x120 [ubifs]
[ 1179.763687] [<ffffffff810947de>] kthread+0xee/0x110
[ 1179.763687] [<ffffffff81752130>] ? _raw_spin_unlock_irq+0x30/0x50
[ 1179.763687] [<ffffffff810946f0>] ? __init_kthread_worker+0x70/0x70
[ 1179.763687] [<ffffffff817528d8>] ret_from_fork+0x58/0x90
[ 1179.763687] [<ffffffff810946f0>] ? __init_kthread_worker+0x70/0x70
[ 1179.763687] Code: 90 31 c0 49 89 fd 49 89 f6 49 89 f4 65 4c 8b 3c 25 c0 b8 00 00 eb 0b 0f 1f 40 00 4c 8d 63 10 48 89 d8 49 8b 1c 24 48 85 db 74 40 <8b> 43 18 41 39 45 18 7c e7 7e 0d 4c 8d 63 08 eb e3 0f 1f 80 00
[ 1179.763687] RIP [<ffffffffa0274800>] wl_tree_add+0x40/0xf0 [ubi]
[ 1179.763687] RSP <ffff8800073478f8>
[ 1179.946401] ---[ end trace 215d3a8314753d92 ]---
-- snip --
[ 1177.689377] UBI error: __wl_get_peb: no free eraseblocks
[ 1179.653004] [nandsim] nandsim_prof_page_progs_update: ERROR: Too many program cycles after erase. row=8192, c=4, page_prog_max=4
[ 1179.665065] UBI assert failed in wl_tree_add at 203 (pid 2610)
[ 1179.667078] CPU: 0 PID: 2610 Comm: ubifs_bgt0_0 Not tainted 3.18.25-ubifs.ex0+ #1
[ 1179.669473] Hardware name: innotek GmbH VirtualBox/VirtualBox, BIOS VirtualBox 12/01/2006
[ 1179.672855] ffff880007521688 ffff8800073478e8 ffffffff8174af24 dead000000100100
[ 1179.675500] ffff880007520870 ffff880007347928 ffffffffa0274898 ffff880007347928
[ 1179.680248] ffff880007520870 ffff880022179480 ffff880022178000 0000000000000000
[ 1179.684895] Call Trace:
[ 1179.686543] [<ffffffff8174af24>] dump_stack+0x51/0x6d
[ 1179.689633] [<ffffffffa0274898>] wl_tree_add+0xd8/0xf0 [ubi]
[ 1179.693185] [<ffffffffa0274d03>] erase_worker+0x453/0x8a0 [ubi]
[ 1179.696695] [<ffffffffa02744a5>] do_work+0xc5/0x150 [ubi]
[ 1179.699884] [<ffffffffa0276afb>] ubi_refill_pools+0x20b/0x3c0 [ubi]
[ 1179.703683] [<ffffffffa027d219>] ubi_update_fastmap+0x39/0x10e8 [ubi]
[ 1179.707493] [<ffffffffa026eb7b>] ? ubi_next_sqnum+0x2b/0x60 [ubi]
[ 1179.711174] [<ffffffffa02761ce>] ubi_wl_get_peb+0x3e/0xc0 [ubi]
[ 1179.714612] [<ffffffffa0270518>] ubi_eba_write_leb+0x178/0x720 [ubi]
[ 1179.718360] [<ffffffffa02c976c>] ? ubifs_change_lp+0x16c/0x740 [ubifs]
[ 1179.722367] [<ffffffffa026de7b>] ubi_leb_write+0x15b/0x160 [ubi]
[ 1179.725887] [<ffffffffa02ad38e>] ubifs_leb_write+0xbe/0x150 [ubifs]
[ 1179.729564] [<ffffffffa02c115b>] ubifs_tnc_end_commit+0x35b/0x6c0 [ubifs]
[ 1179.733619] [<ffffffffa02b9f54>] do_commit+0x234/0x640 [ubifs]
[ 1179.737094] [<ffffffffa02ba652>] ubifs_bg_thread+0x1d2/0x220 [ubifs]
[ 1179.740872] [<ffffffffa02ba480>] ? ubifs_run_commit+0x120/0x120 [ubifs]
[ 1179.745527] [<ffffffff810947de>] kthread+0xee/0x110
[ 1179.748425] [<ffffffff81752130>] ? _raw_spin_unlock_irq+0x30/0x50
[ 1179.752177] [<ffffffff810946f0>] ? __init_kthread_worker+0x70/0x70
[ 1179.756077] [<ffffffff817528d8>] ret_from_fork+0x58/0x90
[ 1179.759330] [<ffffffff810946f0>] ? __init_kthread_worker+0x70/0x70
[ 1179.762768] general protection fault: 0000 [#1] SMP
[ 1179.763687] Modules linked in: deflate ubifs ubi cmdlinepart nandsim_prof nand nand_ecc nand_bch bch nand_ids mtd rpcsec_gss_krb5 nfsv4 nfsd auth_rpcgss nfs_acl nfs lockd grace sunrpc joydev binfmt_misc fscache serio_raw i2c_piix4 hid_generic usbhid psmouse hid pcnet32 mii
[ 1179.763687] CPU: 0 PID: 2610 Comm: ubifs_bgt0_0 Not tainted 3.18.25-ubifs.ex0+ #1
[ 1179.763687] Hardware name: innotek GmbH VirtualBox/VirtualBox, BIOS VirtualBox 12/01/2006
[ 1179.763687] task: ffff880006a50000 ti: ffff880007344000 task.ti: ffff880007344000
[ 1179.763687] RIP: 0010:[<ffffffffa0274800>] [<ffffffffa0274800>] wl_tree_add+0x40/0xf0 [ubi]
[ 1179.763687] RSP: 0000:ffff8800073478f8 EFLAGS: 00010286
[ 1179.763687] RAX: ffff880007520870 RBX: dead000000200200 RCX: ffff880007520878
[ 1179.763687] RDX: 0000000000000100 RSI: 0000000000000001 RDI: ffff880007347f58
[ 1179.763687] RBP: ffff880007347928 R08: 0000000000000001 R09: 0000000000000001
[ 1179.763687] R10: 0000000000000001 R11: 0000000000000001 R12: ffff880007520878
[ 1179.763687] R13: ffff880007520870 R14: ffff8800221793e8 R15: ffff880006a50000
[ 1179.763687] FS: 0000000000000000(0000) GS:ffff88002fc00000(0000) knlGS:0000000000000000
[ 1179.763687] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[ 1179.763687] CR2: 00007f9911818cd8 CR3: 0000000028734000 CR4: 00000000000006f0
[ 1179.763687] Stack:
[ 1179.763687] ffff880007347928 ffff880007520870 ffff880022179480 ffff880022178000
[ 1179.763687] 0000000000000000 ffff8800221793e8 ffff8800073479b8 ffffffffa0274d03
[ 1179.763687] ffff8800073479b8 0000000000000246 0000000000000000 ffff8800221794d0
[ 1179.763687] Call Trace:
[ 1179.763687] [<ffffffffa0274d03>] erase_worker+0x453/0x8a0 [ubi]
[ 1179.763687] [<ffffffffa02744a5>] do_work+0xc5/0x150 [ubi]
[ 1179.763687] [<ffffffffa0276afb>] ubi_refill_pools+0x20b/0x3c0 [ubi]
[ 1179.763687] [<ffffffffa027d219>] ubi_update_fastmap+0x39/0x10e8 [ubi]
[ 1179.763687] [<ffffffffa026eb7b>] ? ubi_next_sqnum+0x2b/0x60 [ubi]
[ 1179.763687] [<ffffffffa02761ce>] ubi_wl_get_peb+0x3e/0xc0 [ubi]
[ 1179.763687] [<ffffffffa0270518>] ubi_eba_write_leb+0x178/0x720 [ubi]
[ 1179.763687] [<ffffffffa02c976c>] ? ubifs_change_lp+0x16c/0x740 [ubifs]
[ 1179.763687] [<ffffffffa026de7b>] ubi_leb_write+0x15b/0x160 [ubi]
[ 1179.763687] [<ffffffffa02ad38e>] ubifs_leb_write+0xbe/0x150 [ubifs]
[ 1179.763687] [<ffffffffa02c115b>] ubifs_tnc_end_commit+0x35b/0x6c0 [ubifs]
[ 1179.763687] [<ffffffffa02b9f54>] do_commit+0x234/0x640 [ubifs]
[ 1179.763687] [<ffffffffa02ba652>] ubifs_bg_thread+0x1d2/0x220 [ubifs]
[ 1179.763687] [<ffffffffa02ba480>] ? ubifs_run_commit+0x120/0x120 [ubifs]
[ 1179.763687] [<ffffffff810947de>] kthread+0xee/0x110
[ 1179.763687] [<ffffffff81752130>] ? _raw_spin_unlock_irq+0x30/0x50
[ 1179.763687] [<ffffffff810946f0>] ? __init_kthread_worker+0x70/0x70
[ 1179.763687] [<ffffffff817528d8>] ret_from_fork+0x58/0x90
[ 1179.763687] [<ffffffff810946f0>] ? __init_kthread_worker+0x70/0x70
[ 1179.763687] Code: 90 31 c0 49 89 fd 49 89 f6 49 89 f4 65 4c 8b 3c 25 c0 b8 00 00 eb 0b 0f 1f 40 00 4c 8d 63 10 48 89 d8 49 8b 1c 24 48 85 db 74 40 <8b> 43 18 41 39 45 18 7c e7 7e 0d 4c 8d 63 08 eb e3 0f 1f 80 00
[ 1179.763687] RIP [<ffffffffa0274800>] wl_tree_add+0x40/0xf0 [ubi]
[ 1179.763687] RSP <ffff8800073478f8>
[ 1179.946401] ---[ end trace 215d3a8314753d92 ]---
(2) の wl_tree_add() で NULL pointer access をした stack dump 前後の出力をすべて含む
[ 454.131725] UBI error: __wl_get_peb: no free eraseblocks
-- snip --
[ 608.154458] UBI error: __wl_get_peb: no free eraseblocks
[ 620.956412] hrtimer: interrupt took 1965201 ns
-- snip --
[ 706.202702] UBI error: __wl_get_peb: no free eraseblocks
[ 707.062650] BUG: unable to handle kernel NULL pointer dereference at 0000000000000020
[ 707.063510] IP: [<ffffffffa0273800>] wl_tree_add+0x40/0xf0 [ubi]
[ 707.063510] PGD 1dc52067 PUD 16212067 PMD 0
[ 707.063510] Oops: 0000 [#1] SMP
[ 707.063510] Modules linked in: deflate ubifs ubi cmdlinepart nandsim_prof nand nand_ecc nand_bch bch nand_ids mtd rpcsec_gss_krb5 nfsv4 nfsd auth_rpcgss nfs_acl nfs lockd grace sunrpc joydev binfmt_misc fscache serio_raw i2c_piix4 hid_generic psmouse usbhid hid pcnet32 mii
[ 707.063510] CPU: 0 PID: 2422 Comm: ubi_bgt0d Not tainted 3.18.25-ubifs.ex0+ #1
[ 707.063510] Hardware name: innotek GmbH VirtualBox/VirtualBox, BIOS VirtualBox 12/01/2006
[ 707.063510] task: ffff880025092360 ti: ffff880023374000 task.ti: ffff880023374000
[ 707.063510] RIP: 0010:[<ffffffffa0273800>] [<ffffffffa0273800>] wl_tree_add+0x40/0xf0 [ubi]
[ 707.063510] RSP: 0018:ffff880023377cf8 EFLAGS: 00010202
[ 707.063510] RAX: ffff8800259a5730 RBX: 0000000000000008 RCX: ffff880022672878
[ 707.063510] RDX: 0000000000001b0d RSI: ffff8800259a5678 RDI: ffff8800226733b0
[ 707.063510] RBP: ffff880023377d28 R08: dead000000100100 R09: 0000000000000000
[ 707.063510] R10: 0000000000000000 R11: 0000000000000000 R12: ffff8800259a5740
[ 707.063510] R13: ffff8800226733b0 R14: ffff8800259a5678 R15: ffff880025092360
[ 707.063510] FS: 0000000000000000(0000) GS:ffff88002fc00000(0000) knlGS:0000000000000000
[ 707.063510] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[ 707.063510] CR2: 0000000000000020 CR3: 000000002e2bf000 CR4: 00000000000006f0
[ 707.063510] Stack:
[ 707.063510] ffff880023377d28 ffff8800226733b0 ffff8800259a5720 ffff8800259a4290
[ 707.063510] 0000000000000000 ffff8800259a5678 ffff880023377db8 ffffffffa0273d03
[ 707.063510] ffff880023377db8 0000000000000246 0000000000000000 ffff8800259a5760
[ 707.063510] Call Trace:
[ 707.063510] [<ffffffffa0273d03>] erase_worker+0x453/0x8a0 [ubi]
[ 707.063510] [<ffffffffa02734a5>] do_work+0xc5/0x150 [ubi]
[ 707.063510] [<ffffffffa02753b0>] ubi_thread+0x160/0x240 [ubi]
[ 707.063510] [<ffffffffa0275250>] ? ubi_wl_get_peb+0xc0/0xc0 [ubi]
[ 707.063510] [<ffffffff810947de>] kthread+0xee/0x110
[ 707.063510] [<ffffffff81752130>] ? _raw_spin_unlock_irq+0x30/0x50
[ 707.063510] [<ffffffff810946f0>] ? __init_kthread_worker+0x70/0x70
[ 707.063510] [<ffffffff817528d8>] ret_from_fork+0x58/0x90
[ 707.063510] [<ffffffff810946f0>] ? __init_kthread_worker+0x70/0x70
[ 707.063510] Code: 90 31 c0 49 89 fd 49 89 f6 49 89 f4 65 4c 8b 3c 25 c0 b8 00 00 eb 0b 0f 1f 40 00 4c 8d 63 10 48 89 d8 49 8b 1c 24 48 85 db 74 40 <8b> 43 18 41 39 45 18 7c e7 7e 0d 4c 8d 63 08 eb e3 0f 1f 80 00
[ 707.063510] RIP [<ffffffffa0273800>] wl_tree_add+0x40/0xf0 [ubi]
[ 707.063510] RSP <ffff880023377cf8>
[ 707.063510] CR2: 0000000000000020
[ 707.063510] ---[ end trace f74004a66509482e ]---
-- snip --
[ 608.154458] UBI error: __wl_get_peb: no free eraseblocks
[ 620.956412] hrtimer: interrupt took 1965201 ns
-- snip --
[ 706.202702] UBI error: __wl_get_peb: no free eraseblocks
[ 707.062650] BUG: unable to handle kernel NULL pointer dereference at 0000000000000020
[ 707.063510] IP: [<ffffffffa0273800>] wl_tree_add+0x40/0xf0 [ubi]
[ 707.063510] PGD 1dc52067 PUD 16212067 PMD 0
[ 707.063510] Oops: 0000 [#1] SMP
[ 707.063510] Modules linked in: deflate ubifs ubi cmdlinepart nandsim_prof nand nand_ecc nand_bch bch nand_ids mtd rpcsec_gss_krb5 nfsv4 nfsd auth_rpcgss nfs_acl nfs lockd grace sunrpc joydev binfmt_misc fscache serio_raw i2c_piix4 hid_generic psmouse usbhid hid pcnet32 mii
[ 707.063510] CPU: 0 PID: 2422 Comm: ubi_bgt0d Not tainted 3.18.25-ubifs.ex0+ #1
[ 707.063510] Hardware name: innotek GmbH VirtualBox/VirtualBox, BIOS VirtualBox 12/01/2006
[ 707.063510] task: ffff880025092360 ti: ffff880023374000 task.ti: ffff880023374000
[ 707.063510] RIP: 0010:[<ffffffffa0273800>] [<ffffffffa0273800>] wl_tree_add+0x40/0xf0 [ubi]
[ 707.063510] RSP: 0018:ffff880023377cf8 EFLAGS: 00010202
[ 707.063510] RAX: ffff8800259a5730 RBX: 0000000000000008 RCX: ffff880022672878
[ 707.063510] RDX: 0000000000001b0d RSI: ffff8800259a5678 RDI: ffff8800226733b0
[ 707.063510] RBP: ffff880023377d28 R08: dead000000100100 R09: 0000000000000000
[ 707.063510] R10: 0000000000000000 R11: 0000000000000000 R12: ffff8800259a5740
[ 707.063510] R13: ffff8800226733b0 R14: ffff8800259a5678 R15: ffff880025092360
[ 707.063510] FS: 0000000000000000(0000) GS:ffff88002fc00000(0000) knlGS:0000000000000000
[ 707.063510] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[ 707.063510] CR2: 0000000000000020 CR3: 000000002e2bf000 CR4: 00000000000006f0
[ 707.063510] Stack:
[ 707.063510] ffff880023377d28 ffff8800226733b0 ffff8800259a5720 ffff8800259a4290
[ 707.063510] 0000000000000000 ffff8800259a5678 ffff880023377db8 ffffffffa0273d03
[ 707.063510] ffff880023377db8 0000000000000246 0000000000000000 ffff8800259a5760
[ 707.063510] Call Trace:
[ 707.063510] [<ffffffffa0273d03>] erase_worker+0x453/0x8a0 [ubi]
[ 707.063510] [<ffffffffa02734a5>] do_work+0xc5/0x150 [ubi]
[ 707.063510] [<ffffffffa02753b0>] ubi_thread+0x160/0x240 [ubi]
[ 707.063510] [<ffffffffa0275250>] ? ubi_wl_get_peb+0xc0/0xc0 [ubi]
[ 707.063510] [<ffffffff810947de>] kthread+0xee/0x110
[ 707.063510] [<ffffffff81752130>] ? _raw_spin_unlock_irq+0x30/0x50
[ 707.063510] [<ffffffff810946f0>] ? __init_kthread_worker+0x70/0x70
[ 707.063510] [<ffffffff817528d8>] ret_from_fork+0x58/0x90
[ 707.063510] [<ffffffff810946f0>] ? __init_kthread_worker+0x70/0x70
[ 707.063510] Code: 90 31 c0 49 89 fd 49 89 f6 49 89 f4 65 4c 8b 3c 25 c0 b8 00 00 eb 0b 0f 1f 40 00 4c 8d 63 10 48 89 d8 49 8b 1c 24 48 85 db 74 40 <8b> 43 18 41 39 45 18 7c e7 7e 0d 4c 8d 63 08 eb e3 0f 1f 80 00
[ 707.063510] RIP [<ffffffffa0273800>] wl_tree_add+0x40/0xf0 [ubi]
[ 707.063510] RSP <ffff880023377cf8>
[ 707.063510] CR2: 0000000000000020
[ 707.063510] ---[ end trace f74004a66509482e ]---
未編集のログ出力
負荷試験に nandsim.c を改造した nandsim_prof.c を使用している。これも後で整理しようと思う。nandsim_prof.c が "[nandsim] nandsim_prof_page_progs_update: ERROR: Too many program cycles after erase. row=8192, c=4, page_prog_max=4" と出力しているので page #8192 に対して 4 回書き込みをしていることが分かる。NAND memory によっては「追い書き」(partial write) 回数制限に抵触する。
wl.c の comment に書かれたことと source code を比べてみると CONFIG_MTD_UBI_FASTMAP がまとわりついている部分に関して comment の解説が乏しいことが分かる。後付けされたような fastmap が怪しい。
drivers/mtd/Kconfig を読むと CONFIG_MTD_UBI_FASTMAP "Experimental feature" だと説明がある。default では "N" だ。ubuntu distribution ではわざわざ Y (defined) にしてある(/boot/configs-* を参照)。
CONFIG_MTD_UBI_FASTMAP を .config から外し undefined (# CONFIG_XXX ... is not set) にして同様の負荷試験をしてみる。30～60 分しか負荷試験が持たなかったのが、半日以上連続試験に耐えている。
退職前に気になっていた問題、出来ていなかった負荷試験はおおよそ終わる。仕事でさわっていた kernel の CONFIG_MTD_UBI_FASTMAP がどうなっていたかは既に記憶にない。そもそも kernel の version は近いものを選んでいて、違っている。
UBI/UBIFS 以外にも自分が担当していたコードはある。これらは機器固有のコードだ。持ち出しは出来ない。持ち出したところで試す環境と手段がない。
出来る範囲の心残りは無くなった。さあ、新しい課題を見つけよう。
お気に入りの記事を「いいね！」で応援しよう
[ソフト開発日誌] カテゴリの最新記事
-
煩わしい HTML DIV CSS ポップアップ - 操… 2024.09.22
-
HP ProBook 450 G9 UEFI を使ったメモリ診… 2024.09.22
-
HP ProBook 450 G9 RAM増設 8GiByte → 32G… 2024.09.22
【毎日開催】
15記事にいいね！で1ポイント
カレンダー
サイド自由欄
コメント新着
© Rakuten Group, Inc.
