Discussion:
bcache and memory at boot. Bug?
Josep Lladonosa
2014-02-08 08:53:19 UTC
Permalink
Hello,

I am using bcache in my laptop (RAM 32 GiB). I have been using it
perfectly for a month. ext4 + bcache.

Yesterday, system did not want do to a normal startup. Messages where
from udev out of memory (and udevadm killed?) and system was not
mounting / (/dev/bcache0).

After verifying/trying some things I found that:

bcache tries to prepare /dev/bcache0 but something happens (udev
related?) and the caching device is slave of it. If bcache can go on,
then prepares /dev/bcache1 with the same caching device and the
backing device.

# ls /sys/block/bcache?/slaves
/sys/block/bcache0/slaves:
sda1

/sys/block/bcache1/slaves:
sda1 sdb7

# cat /sys/block/bcache?/stat
418 0 3344 0 0 0 0
0 0 0 0
137372 0 2151740 456928 2476 0 138440
46252 0 0 0


so mounting /dev/bcache1 allows normal startup, but with something
messed up, I guess.

I got two ways for booting:

1) If I boot with only 16 GiB of RAM, it runs O.K. (physically only 16
GiB or with boot parameter mem=16G - mem=17G also boots; mem=20G does
not boot well)

2) booting with /dev/bcache1 as the root filesystem.

In this second case, I can see dmesg, so here it goes:

[ 3.619572] bcache: bch_journal_replay() journal replay done, 754
keys in 46 entries, seq 443121
[ 6.746571] bcache-register invoked oom-killer: gfp_mask=0x82d2,
order=0, oom_score_adj=0
[ 6.746575] bcache-register cpuset=/ mems_allowed=0
[ 6.746578] CPU: 1 PID: 296 Comm: bcache-register Not tainted 3.12.9 #1
[ 6.746580] Hardware name: Micro-Star International Co., Ltd.
GT60/MS-16F3, BIOS E16F3IMS.10U 01/21/2013
[ 6.746581] 0000ebc8000000e3 ffffffff8137e021 ffff8800371ab0c0
ffffffff8137c481
[ 6.746584] ffffffff8138110e ffffffff8138038b 0000000000000020
ffffffff810363f2
[ 6.746587] ffffffff81099f9b ffff880803afa040 ffffffff814fb060
0000000000000000
[ 6.746589] Call Trace:
[ 6.746596] [<ffffffff8137e021>] ? dump_stack+0x41/0x51
[ 6.746599] [<ffffffff8137c481>] ? dump_header+0x70/0x1a2
[ 6.746601] [<ffffffff8138110e>] ? _cond_resched+0x5/0x14
[ 6.746604] [<ffffffff8138038b>] ? mutex_lock+0x9/0x25
[ 6.746608] [<ffffffff810363f2>] ? put_online_cpus+0x1e/0x64
[ 6.746612] [<ffffffff81099f9b>] ? rcu_oom_notify+0xc0/0xd2
[ 6.746614] [<ffffffff810bee32>] ? oom_kill_process+0x6f/0x2c0
[ 6.746616] [<ffffffff810bf590>] ? out_of_memory+0x3d8/0x3f1
[ 6.746619] [<ffffffff810c365d>] ? __alloc_pages_nodemask+0x64e/0x7d0
[ 6.746624] [<ffffffff810f0f15>] ? alloc_pages_current+0xef/0x109
[ 6.746627] [<ffffffff810e70aa>] ? __vmalloc_node_range+0x143/0x1de
[ 6.746635] [<ffffffffa01d7d1c>] ? bcache_device_init+0x81/0x241 [bcache]
[ 6.746637] [<ffffffff810e7171>] ? __vmalloc_node+0x2c/0x31
[ 6.746642] [<ffffffffa01d7d1c>] ? bcache_device_init+0x81/0x241 [bcache]
[ 6.746645] [<ffffffff810e71ab>] ? vzalloc+0x21/0x22
[ 6.746649] [<ffffffffa01d7d1c>] ? bcache_device_init+0x81/0x241 [bcache]
[ 6.746653] [<ffffffffa01d805e>] ? flash_dev_run+0x7d/0x12b [bcache]
[ 6.746658] [<ffffffffa01d988b>] ? run_cache_set+0x5c4/0x695 [bcache]
[ 6.746664] [<ffffffffa01dae47>] ? register_bcache+0x10a0/0x12d9 [bcache]
[ 6.746666] [<ffffffff810f0f15>] ? alloc_pages_current+0xef/0x109
[ 6.746670] [<ffffffff81159855>] ? sysfs_write_file+0xcf/0x103
[ 6.746674] [<ffffffff81106a23>] ? vfs_write+0xa8/0x10b
[ 6.746677] [<ffffffff8110705e>] ? SyS_write+0x41/0x74
[ 6.746680] [<ffffffff81386ca2>] ? system_call_fastpath+0x16/0x1b
[ 6.746682] Mem-Info:
[ 6.746683] Node 0 DMA per-cpu:
[ 6.746685] CPU 0: hi: 0, btch: 1 usd: 0
[ 6.746686] CPU 1: hi: 0, btch: 1 usd: 0
[ 6.746687] CPU 2: hi: 0, btch: 1 usd: 0
[ 6.746688] CPU 3: hi: 0, btch: 1 usd: 0
[ 6.746689] CPU 4: hi: 0, btch: 1 usd: 0
[ 6.746691] CPU 5: hi: 0, btch: 1 usd: 0
[ 6.746692] CPU 6: hi: 0, btch: 1 usd: 0
[ 6.746693] CPU 7: hi: 0, btch: 1 usd: 0
[ 6.746694] Node 0 DMA32 per-cpu:
[ 6.746695] CPU 0: hi: 186, btch: 31 usd: 157
[ 6.746697] CPU 1: hi: 186, btch: 31 usd: 94
[ 6.746698] CPU 2: hi: 186, btch: 31 usd: 96
[ 6.746699] CPU 3: hi: 186, btch: 31 usd: 81
[ 6.746700] CPU 4: hi: 186, btch: 31 usd: 169
[ 6.746701] CPU 5: hi: 186, btch: 31 usd: 50
[ 6.746702] CPU 6: hi: 186, btch: 31 usd: 40
[ 6.746704] CPU 7: hi: 186, btch: 31 usd: 84
[ 6.746704] Node 0 Normal per-cpu:
[ 6.746706] CPU 0: hi: 186, btch: 31 usd: 108
[ 6.746707] CPU 1: hi: 186, btch: 31 usd: 112
[ 6.746708] CPU 2: hi: 186, btch: 31 usd: 127
[ 6.746709] CPU 3: hi: 186, btch: 31 usd: 176
[ 6.746710] CPU 4: hi: 186, btch: 31 usd: 166
[ 6.746711] CPU 5: hi: 186, btch: 31 usd: 169
[ 6.746712] CPU 6: hi: 186, btch: 31 usd: 117
[ 6.746714] CPU 7: hi: 186, btch: 31 usd: 174
[ 6.746717] active_anon:2478 inactive_anon:19 isolated_anon:0
[ 6.746717] active_file:364 inactive_file:271 isolated_file:0
[ 6.746717] unevictable:10512 dirty:0 writeback:0 unstable:0
[ 6.746717] free:51389 slab_reclaimable:1259 slab_unreclaimable:3625
[ 6.746717] mapped:328 shmem:32 pagetables:490 bounce:0
[ 6.746717] free_cma:0
[ 6.746720] Node 0 DMA free:15896kB min:32kB low:40kB high:48kB
active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB
unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15984kB
managed:15900kB mlocked:0kB dirty:0kB writeback:0kB mapped:0kB
shmem:0kB slab_reclaimable:0kB slab_unreclaimable:4kB kernel_stack:0kB
pagetables:0kB unstable:0kB bounce:0kB free_cma:0kB writeback_tmp:0kB
pages_scanned:0 all_unreclaimable? yes
[ 6.746725] lowmem_reserve[]: 0 3146 32125 32125
[ 6.746727] Node 0 DMA32 free:123128kB min:6616kB low:8268kB
high:9924kB active_anon:1508kB inactive_anon:0kB active_file:0kB
inactive_file:0kB unevictable:0kB isolated(anon):0kB
isolated(file):0kB present:3296400kB managed:3224152kB mlocked:0kB
dirty:0kB writeback:0kB mapped:4kB shmem:12kB slab_reclaimable:192kB
slab_unreclaimable:556kB kernel_stack:24kB pagetables:144kB
unstable:0kB bounce:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:0
all_unreclaimable? yes
[ 6.746732] lowmem_reserve[]: 0 0 28978 28978
[ 6.746734] Node 0 Normal free:66532kB min:60932kB low:76164kB
high:91396kB active_anon:8404kB inactive_anon:76kB active_file:1084kB
inactive_file:1084kB unevictable:42632kB isolated(anon):0kB
isolated(file):0kB present:30136320kB managed:29673756kB mlocked:0kB
dirty:0kB writeback:0kB mapped:1308kB shmem:116kB
slab_reclaimable:4844kB slab_unreclaimable:13940kB kernel_stack:1088kB
pagetables:1816kB unstable:0kB bounce:0kB free_cma:0kB
writeback_tmp:0kB pages_scanned:192 all_unreclaimable? no
[ 6.746739] lowmem_reserve[]: 0 0 0 0
[ 6.746741] Node 0 DMA: 0*4kB 1*8kB (U) 1*16kB (U) 0*32kB 2*64kB
(U) 1*128kB (U) 1*256kB (U) 0*512kB 1*1024kB (U) 1*2048kB (R) 3*4096kB
(M) = 15896kB
[ 6.746750] Node 0 DMA32: 2*4kB (EM) 4*8kB (UEM) 1*16kB (U) 2*32kB
(E) 2*64kB (UM) 2*128kB (UM) 3*256kB (U) 6*512kB (UM) 6*1024kB (EM)
7*2048kB (UEMR) 24*4096kB (MR) = 123128kB
[ 6.746759] Node 0 Normal: 7*4kB (M) 15*8kB (UEM) 14*16kB (UM)
11*32kB (UEM) 3*64kB (UM) 1*128kB (M) 6*256kB (UE) 4*512kB (UEM)
4*1024kB (UM) 3*2048kB (UEM) 13*4096kB (MR) = 68116kB
[ 6.746770] Node 0 hugepages_total=0 hugepages_free=0
hugepages_surp=0 hugepages_size=2048kB
[ 6.746771] 11149 total pagecache pages
[ 6.746773] 0 pages in swap cache
[ 6.746774] Swap cache stats: add 0, delete 0, find 0/0
[ 6.746775] Free swap = 0kB
[ 6.746776] Total swap = 0kB
[ 6.814488] 8386047 pages RAM
[ 6.814490] 157595 pages reserved
[ 6.814491] 4560 pages shared
[ 6.814492] 8169064 pages non-shared
[ 6.814493] [ pid ] uid tgid total_vm rss nr_ptes swapents
oom_score_adj name
[ 6.814501] [ 90] 0 90 1202 159 8 0
0 udev
[ 6.814503] [ 92] 0 92 6261 340 17 0
-1000 systemd-udevd
[ 6.814505] [ 94] 0 94 6162 214 17 0
0 systemd-udevd
[ 6.814507] [ 96] 0 96 6228 238 17 0
0 systemd-udevd
[ 6.814508] [ 97] 0 97 6228 257 17 0
0 systemd-udevd
[ 6.814510] [ 99] 0 99 6228 238 17 0
0 systemd-udevd
[ 6.814512] [ 100] 0 100 6228 259 17 0
0 systemd-udevd
[ 6.814514] [ 101] 0 101 6228 258 17 0
0 systemd-udevd
[ 6.814516] [ 103] 0 103 6228 229 17 0
0 systemd-udevd
[ 6.814517] [ 105] 0 105 6228 222 17 0
0 systemd-udevd
[ 6.814519] [ 106] 0 106 6228 223 17 0
0 systemd-udevd
[ 6.814521] [ 107] 0 107 6228 232 17 0
0 systemd-udevd
[ 6.814523] [ 112] 0 112 6228 244 17 0
0 systemd-udevd
[ 6.814525] [ 113] 0 113 6228 244 17 0
0 systemd-udevd
[ 6.814526] [ 116] 0 116 6228 235 17 0
0 systemd-udevd
[ 6.814528] [ 117] 0 117 6228 241 17 0
0 systemd-udevd
[ 6.814530] [ 119] 0 119 5931 241 17 0
0 udevadm
[ 6.814532] [ 120] 0 120 6228 235 17 0
0 systemd-udevd
[ 6.814534] [ 121] 0 121 6228 235 17 0
0 systemd-udevd
[ 6.814535] [ 123] 0 123 6228 236 17 0
0 systemd-udevd
[ 6.814537] [ 126] 0 126 6228 236 17 0
0 systemd-udevd
[ 6.814539] [ 127] 0 127 6228 236 17 0
0 systemd-udevd
[ 6.814541] [ 129] 0 129 6228 236 17 0
0 systemd-udevd
[ 6.814542] [ 130] 0 130 6228 236 17 0
0 systemd-udevd
[ 6.814544] [ 133] 0 133 6228 236 17 0
0 systemd-udevd
[ 6.814546] [ 137] 0 137 6228 242 17 0
0 systemd-udevd
[ 6.814548] [ 139] 0 139 6228 243 17 0
0 systemd-udevd
[ 6.814552] [ 296] 0 296 1202 160 8 0
0 bcache-register
[ 6.814554] [ 319] 0 319 1202 160 8 0
0 bcache-register
[ 6.814556] Out of memory: Kill process 90 (udev) score 0 or sacrifice child
[ 6.814612] Killed process 119 (udevadm) total-vm:23724kB,
anon-rss:204kB, file-rss:760kB
[ 6.823222] bcache-register invoked oom-killer: gfp_mask=0x82d2,
order=0, oom_score_adj=0
[ 6.823226] bcache-register cpuset=/ mems_allowed=0
[ 6.823229] CPU: 1 PID: 296 Comm: bcache-register Not tainted 3.12.9 #1



Thanks,
Josep


--
--
Salutacions...Josep
--



--
--
Salutacions...Josep
--
Gabriel de Perthuis
2014-02-10 11:40:29 UTC
Permalink
> Hello,
>
> I am using bcache in my laptop (RAM 32 GiB). I have been using it
> perfectly for a month. ext4 + bcache.
>
> Yesterday, system did not want do to a normal startup. Messages where
> from udev out of memory (and udevadm killed?) and system was not
> mounting / (/dev/bcache0).
>
> [ 6.823222] bcache-register invoked oom-killer: gfp_mask=0x82d2,
> order=0, oom_score_adj=0

Build your kernel with CONFIG_COMPACTION. I've added it to the FAQ:
http://bcache.evilpiepirate.org/~kent/bcache/FAQ/
Josep Lladonosa
2014-02-10 13:15:14 UTC
Permalink
On 10 February 2014 12:40, Gabriel de Perthuis <***@gmail.com> wrote:
>> Hello,
>>
>> I am using bcache in my laptop (RAM 32 GiB). I have been using it
>> perfectly for a month. ext4 + bcache.
>>
>> Yesterday, system did not want do to a normal startup. Messages where
>> from udev out of memory (and udevadm killed?) and system was not
>> mounting / (/dev/bcache0).
>>
>> [ 6.823222] bcache-register invoked oom-killer: gfp_mask=0x82d2,
>> order=0, oom_score_adj=0
>
> Build your kernel with CONFIG_COMPACTION. I've added it to the FAQ:
> http://bcache.evilpiepirate.org/~kent/bcache/FAQ/


Hello Gabriel,

Thanks for your reply.

My .config file has already:
...
CONFIG_COMPACTION=y
...

I have been digging around to find information and sometimes bugs come
related to unsigned variables and their operations when storing large
numbers (reserved memory?). Kernel is 64 bits. Memory is 32 GiB.
Perhaps it could happen that the allocated memory is not totally
freed.

When kernel has been able to boot with 32 GiB (having bcache0 messed
up and bcache1 mountable), it seems that bcache has more than 16 GiB
allocated and kept.

-Free memory with kernel 3.11.0-rc7 with 32GiB and bcache0 (halved?)
and bcache1 (mounted)

$ head -2 /proc/meminfo
MemTotal: 32913872 kB
MemFree: 12376640 kB


- Free memory with kernel 3.12.9 with mem=16G and bcache0 (mounted)

$ head -2 /proc/meminfo
MemTotal: 15602144 kB
MemFree: 14005372 kB



>
>
> --
> To unsubscribe from this list: send the line "unsubscribe linux-bcache" in
> the body of a message to ***@vger.kernel.org
> More majordomo info at http://vger.kernel.org/majordomo-info.html



--
--
Salutacions...Josep
--
Kent Overstreet
2014-02-10 22:46:48 UTC
Permalink
On Mon, Feb 10, 2014 at 02:15:14PM +0100, Josep Lladonosa wrote:
> On 10 February 2014 12:40, Gabriel de Perthuis <***@gmail.com> wrote:
> >> Hello,
> >>
> >> I am using bcache in my laptop (RAM 32 GiB). I have been using it
> >> perfectly for a month. ext4 + bcache.
> >>
> >> Yesterday, system did not want do to a normal startup. Messages where
> >> from udev out of memory (and udevadm killed?) and system was not
> >> mounting / (/dev/bcache0).
> >>
> >> [ 6.823222] bcache-register invoked oom-killer: gfp_mask=0x82d2,
> >> order=0, oom_score_adj=0
> >
> > Build your kernel with CONFIG_COMPACTION. I've added it to the FAQ:
> > http://bcache.evilpiepirate.org/~kent/bcache/FAQ/
>
>
> Hello Gabriel,
>
> Thanks for your reply.
>
> My .config file has already:
> ...
> CONFIG_COMPACTION=y

I looked at the allocations done in bcache_device_init(), those aren't high
order page allocations (they're vmalloc allocations) so compaction won't help
here.

> ...
>
> I have been digging around to find information and sometimes bugs come
> related to unsigned variables and their operations when storing large
> numbers (reserved memory?). Kernel is 64 bits. Memory is 32 GiB.
> Perhaps it could happen that the allocated memory is not totally
> freed.
>
> When kernel has been able to boot with 32 GiB (having bcache0 messed
> up and bcache1 mountable), it seems that bcache has more than 16 GiB
> allocated and kept.

Woah, really? If so that's bad - I don't see how that follows (or am I
misreading) from your numbers, can you show a before and after when you bring
bcache up?

>
> -Free memory with kernel 3.11.0-rc7 with 32GiB and bcache0 (halved?)
> and bcache1 (mounted)
>
> $ head -2 /proc/meminfo
> MemTotal: 32913872 kB
> MemFree: 12376640 kB
>
>
> - Free memory with kernel 3.12.9 with mem=16G and bcache0 (mounted)
>
> $ head -2 /proc/meminfo
> MemTotal: 15602144 kB
> MemFree: 14005372 kB
>
>
>
> >
> >
> > --
> > To unsubscribe from this list: send the line "unsubscribe linux-bcache" in
> > the body of a message to ***@vger.kernel.org
> > More majordomo info at http://vger.kernel.org/majordomo-info.html
>
>
>
> --
> --
> Salutacions...Josep
> --
> --
> To unsubscribe from this list: send the line "unsubscribe linux-bcache" in
> the body of a message to ***@vger.kernel.org
> More majordomo info at http://vger.kernel.org/majordomo-info.html
Josep Lladonosa
2014-02-11 10:56:49 UTC
Permalink
On 10 February 2014 23:46, Kent Overstreet <***@daterainc.com> wrote:
> On Mon, Feb 10, 2014 at 02:15:14PM +0100, Josep Lladonosa wrote:
>> On 10 February 2014 12:40, Gabriel de Perthuis <***@gmail.com> wrote:
>> >> Hello,
>> >>
>> >> I am using bcache in my laptop (RAM 32 GiB). I have been using it
>> >> perfectly for a month. ext4 + bcache.
>> >>
>> >> Yesterday, system did not want do to a normal startup. Messages where
>> >> from udev out of memory (and udevadm killed?) and system was not
>> >> mounting / (/dev/bcache0).
>> >>
>> >> [ 6.823222] bcache-register invoked oom-killer: gfp_mask=0x82d2,
>> >> order=0, oom_score_adj=0
>> >
>> > Build your kernel with CONFIG_COMPACTION. I've added it to the FAQ:
>> > http://bcache.evilpiepirate.org/~kent/bcache/FAQ/
>>
>>
>> Hello Gabriel,
>>
>> Thanks for your reply.
>>
>> My .config file has already:
>> ...
>> CONFIG_COMPACTION=y
>
> I looked at the allocations done in bcache_device_init(), those aren't high
> order page allocations (they're vmalloc allocations) so compaction won't help
> here.
>
>> ...
>>
>> I have been digging around to find information and sometimes bugs come
>> related to unsigned variables and their operations when storing large
>> numbers (reserved memory?). Kernel is 64 bits. Memory is 32 GiB.
>> Perhaps it could happen that the allocated memory is not totally
>> freed.
>>
>> When kernel has been able to boot with 32 GiB (having bcache0 messed
>> up and bcache1 mountable), it seems that bcache has more than 16 GiB
>> allocated and kept.
>
> Woah, really? If so that's bad - I don't see how that follows (or am I
> misreading) from your numbers, can you show a before and after when you bring
> bcache up?

What I have done is:

- boot computer in Debian (kernel&bcache-tools ready) from an USB with
the caching device unplugged and backing plugged. Booting O.K. with 32
GiB of RAM.
- plug caching device to external SATA. Bcache detects it, but...
- bcache0 and bcache1 are shown (I could do a fast "ls" for /sys/block).
- After some seconds, system freezes.


I could detach cahing device and remake it and see if the same happens
again, but anyway the cause of this behaviour will still be there.

Josep

>
>>
>> -Free memory with kernel 3.11.0-rc7 with 32GiB and bcache0 (halved?)
>> and bcache1 (mounted)
>>
>> $ head -2 /proc/meminfo
>> MemTotal: 32913872 kB
>> MemFree: 12376640 kB
>>
>>
>> - Free memory with kernel 3.12.9 with mem=16G and bcache0 (mounted)
>>
>> $ head -2 /proc/meminfo
>> MemTotal: 15602144 kB
>> MemFree: 14005372 kB
>>
>>
>>
>> >
>> >
>> > --
>> > To unsubscribe from this list: send the line "unsubscribe linux-bcache" in
>> > the body of a message to ***@vger.kernel.org
>> > More majordomo info at http://vger.kernel.org/majordomo-info.html
>>
>>
>>
>> --
>> --
>> Salutacions...Josep
>> --
>> --
>> To unsubscribe from this list: send the line "unsubscribe linux-bcache" in
>> the body of a message to ***@vger.kernel.org
>> More majordomo info at http://vger.kernel.org/majordomo-info.html



--
--
Salutacions...Josep
--
Josep Lladonosa
2014-02-26 16:03:26 UTC
Permalink
Hello,

I forward some information wich was missing in the list. After this I
write another message with some (good news for me and) information
about things that I have found.

Josep

---------- Forwarded message ----------
From: Josep Lladonosa <***@gmail.com>
Date: 11 February 2014 17:39
Subject: Re: bcache and memory at boot. Bug?
To: matthew patton <***@yahoo.com>


On 11 February 2014 12:23, matthew patton <***@yahoo.com> wrote:
>
>
> >>> -Free memory with kernel 3.11.0-rc7 with 32GiB and bcache0 (halved?)
>>>> and bcache1 (mounted)
>>>>
>>>> $ head -2 /proc/meminfo
>>>> MemTotal: 32913872 kB
>>>> MemFree: 12376640 kB
>>>>
>>>>
>>>> - Free memory with kernel 3.12.9 with mem=16G and bcache0 (mounted)
>>>>
>>>> $ head -2 /proc/meminfo
>>>> MemTotal: 15602144 kB
>>>> MemFree: 14005372 kB
>
>
> too many variables. Boot the same box with the SAME kernel, just twiddle how much ram is visible via the GRUB commandline. ... try with mem=16G and other values like 12G, 24G or 31G

O.K. Here you are:

With kernel 3.13.2:

mem=2G ---> boots O.K. (/dev/bcache0).
mem=4G ---> Out of memory. (initramfs appears with bcache0 and
bcache1 for only one caching device. bcache1 has the two correct
slaves).
mem=8G ---> bcache-register killed. Kernel panic.
mem=16G --> Out of memory (initramfs appears with bcache0 to bcache7
for only one caching device. bcache7 has the two correct slaves).
mem=20G --> Out of memory (no initramfs prompt appearing).
mem=24G --> Out of memory (initramfs appears with bcache0 to bcache9
for only one caching device. bcache9 has the two correct slaves).

(the more RAM is given to box, the more messages about out of memory you get.

Kernel 3.12.9

Command line: BOOT_IMAGE=/vmlinuz-3.12.9 root=/dev/bcache0 ro
"acpi_osi=!Windows 2012" quiet mem=16G intel_pstate=disable
pcie_aspm=force i915.i915_enable_rc6=1 i915.i915_enable_fbc=1
i915.lvds_downclock=1 rcutree.rcu_idle_gp_delay=1

(changing mem kernel boot parameter):

mem=12G ---> boots O.K. (/dev/bcache0).
mem=14G ---> boots O.K. (/dev/bcache0).
mem=16G ---> boots O.K. (/dev/bcache0).
mem=17G ---> boots O.K. (/dev/bcache0).
mem=18G ---> boots O.K. (/dev/bcache0).
mem=20G ---> Kernel panic.
mem=24G ---> Kernel panic.
mem=32G ---> Out of memory. (initramfs appears with bcache0 and
bcache1 for only one caching device. bcache1 has the two correct
slaves).


With kernel 3.12.9, When booting, with udev info in /var/log/messages,
there are memory allocation failure for bcache-register messages:


Feb 11 17:22:10 minijep kernel: [ 3.099025] bio: create slab <bio-1> at 1
Feb 11 17:22:10 minijep kernel: [ 3.452716] bcache:
bch_journal_replay() journal replay done, 575 keys in 49 entries, seq
573572
Feb 11 17:22:10 minijep kernel: [ 3.452777] vmalloc: allocation
failure: 19327352836 bytes
Feb 11 17:22:10 minijep kernel: [ 3.452780] bcache-register: page
allocation failure: order:0, mode:0x80d2
Feb 11 17:22:10 minijep kernel: [ 3.452783] CPU: 0 PID: 298 Comm:
bcache-register Not tainted 3.12.9 #1
Feb 11 17:22:10 minijep kernel: [ 3.452784] Hardware name:
Micro-Star International Co., Ltd. GT60/MS-16F3, BIOS E16F3IMS.10U
01/21/2013
Feb 11 17:22:10 minijep kernel: [ 3.452786] 0000f72000000083
ffffffff8137e021 0000000000000001 ffffffff810c0864
Feb 11 17:22:10 minijep kernel: [ 3.452789] ffffffff814fdf94
ffff880036f65b70 0000000000000018 ffff880036f65be8
Feb 11 17:22:10 minijep kernel: [ 3.452792] ffff880036f65b88
ffff880036fc8b20 0000000000000000 0000000000000003
Feb 11 17:22:10 minijep kernel: [ 3.452795] Call Trace:
Feb 11 17:22:10 minijep kernel: [ 3.452804] [<ffffffff8137e021>] ?
dump_stack+0x41/0x51
Feb 11 17:22:10 minijep kernel: [ 3.452808] [<ffffffff810c0864>] ?
warn_alloc_failed+0x118/0x12c
Feb 11 17:22:10 minijep kernel: [ 3.452814] [<ffffffff810e7134>] ?
__vmalloc_node_range+0x1cd/0x1de
Feb 11 17:22:10 minijep kernel: [ 3.452817] [<ffffffff810e7171>] ?
__vmalloc_node+0x2c/0x31
Feb 11 17:22:10 minijep kernel: [ 3.452827] [<ffffffffa01ebd1c>] ?
bcache_device_init+0x81/0x241 [bcache]
Feb 11 17:22:10 minijep kernel: [ 3.452832] [<ffffffff810e71ab>] ?
vzalloc+0x21/0x22
Feb 11 17:22:10 minijep kernel: [ 3.452839] [<ffffffffa01ebd1c>] ?
bcache_device_init+0x81/0x241 [bcache]
Feb 11 17:22:10 minijep kernel: [ 3.452845] [<ffffffffa01ec05e>] ?
flash_dev_run+0x7d/0x12b [bcache]
Feb 11 17:22:10 minijep kernel: [ 3.452854] [<ffffffffa01ed88b>] ?
run_cache_set+0x5c4/0x695 [bcache]
Feb 11 17:22:10 minijep kernel: [ 3.452859] [<ffffffffa01eee47>] ?
register_bcache+0x10a0/0x12d9 [bcache]
Feb 11 17:22:10 minijep kernel: [ 3.452863] [<ffffffff810f0f15>] ?
alloc_pages_current+0xef/0x109
Feb 11 17:22:10 minijep kernel: [ 3.452867] [<ffffffff81159855>] ?
sysfs_write_file+0xcf/0x103
Feb 11 17:22:10 minijep kernel: [ 3.452871] [<ffffffff81106a23>] ?
vfs_write+0xa8/0x10b
Feb 11 17:22:10 minijep kernel: [ 3.452874] [<ffffffff8110705e>] ?
SyS_write+0x41/0x74
Feb 11 17:22:10 minijep kernel: [ 3.452878] [<ffffffff81386ca2>] ?
system_call_fastpath+0x16/0x1b
Feb 11 17:22:10 minijep kernel: [ 3.452880] Mem-Info:
Feb 11 17:22:10 minijep kernel: [ 3.452881] Node 0 DMA per-cpu:
Feb 11 17:22:10 minijep kernel: [ 3.452883] CPU 0: hi: 0,
btch: 1 usd: 0
Feb 11 17:22:10 minijep kernel: [ 3.452884] CPU 1: hi: 0,
btch: 1 usd: 0
Feb 11 17:22:10 minijep kernel: [ 3.452886] CPU 2: hi: 0,
btch: 1 usd: 0
Feb 11 17:22:10 minijep kernel: [ 3.452887] CPU 3: hi: 0,
btch: 1 usd: 0
Feb 11 17:22:10 minijep kernel: [ 3.452888] CPU 4: hi: 0,
btch: 1 usd: 0
Feb 11 17:22:10 minijep kernel: [ 3.452889] CPU 5: hi: 0,
btch: 1 usd: 0
Feb 11 17:22:10 minijep kernel: [ 3.452890] CPU 6: hi: 0,
btch: 1 usd: 0
Feb 11 17:22:10 minijep kernel: [ 3.452892] CPU 7: hi: 0,
btch: 1 usd: 0


--
--
Salutacions...Josep
--


--
--
Salutacions...Josep
--
Josep Lladonosa
2014-02-26 16:38:22 UTC
Permalink
Hi again,


I have been "walking" around the code in order to debug.

Now, with kernels 3.13.3, 3.13.2 and 3.12.9 I can boot /dev/bcache0 as
the root system with all RAM available (32 GiB) with a small
modification (one line) in super.c into flash_devs_run().

To recapitulate, my system has sda partitioned with fdisk; sdb is GPT
partitioned. Cache device is /dev/sda. Backed device is another
partition in /dev/sdb. I am using a proportionally big partition for
the cache device (211551921 blocks) and perhaps some code would have
failed with these numbers.

What have I found?
Cache device has 4096 nr_uuids and some of them have an incorrect
value of "sectors". Incorrect values all of them have a value higher
than 0x9000000000000000, so I applied a "filter" in order not to run
the uuids (that avoids the try to allocate such huge quantity of RAM).

Some sample lines from /var/log/messages:
----------------------------------------
(...)
Feb 26 14:10:08 minijep kernel: [ 3.589559] bcache:
flash_devs_run() P00: flash_dev_run: uuids[875] u: ffff88080129b580,
u->sectors: 9000000002800000
Feb 26 14:10:08 minijep kernel: [ 3.589561] bcache:
flash_devs_run() P00: flash_dev_run: uuids[876] u: ffff88080129b600,
u->sectors: 16112800
Feb 26 14:10:08 minijep kernel: [ 3.589562] bcache:
flash_devs_run() P00: flash_dev_run: uuids[877] u: ffff88080129b680,
u->sectors: 41ab21000
Feb 26 14:10:08 minijep kernel: [ 3.589563] bcache:
flash_devs_run() P00: flash_dev_run: uuids[878] u: ffff88080129b700,
u->sectors: 9000000000800000
Feb 26 14:10:08 minijep kernel: [ 3.589565] bcache:
flash_devs_run() P00: flash_dev_run: uuids[879] u: ffff88080129b780,
u->sectors: 16112a40
Feb 26 14:10:08 minijep kernel: [ 3.589566] bcache:
flash_devs_run() P00: flash_dev_run: uuids[880] u: ffff88080129b800,
u->sectors: 41f8dd800
Feb 26 14:10:08 minijep kernel: [ 3.589567] bcache:
flash_devs_run() P00: flash_dev_run: uuids[881] u: ffff88080129b880,
u->sectors: 9000000002000000
Feb 26 14:10:08 minijep kernel: [ 3.589569] bcache:
flash_devs_run() P00: flash_dev_run: uuids[882] u: ffff88080129b900,
u->sectors: 16112c58
Feb 26 14:10:08 minijep kernel: [ 3.589570] bcache:
flash_devs_run() P00: flash_dev_run: uuids[883] u: ffff88080129b980,
u->sectors: 42ab53800
Feb 26 14:10:08 minijep kernel: [ 3.589572] bcache:
flash_devs_run() P00: flash_dev_run: uuids[884] u: ffff88080129ba00,
u->sectors: 9000000000800000
Feb 26 14:10:08 minijep kernel: [ 3.589573] bcache:
flash_devs_run() P00: flash_dev_run: uuids[885] u: ffff88080129ba80,
u->sectors: 16112eb8
Feb 26 14:10:08 minijep kernel: [ 3.589574] bcache:
flash_devs_run() P00: flash_dev_run: uuids[886] u: ffff88080129bb00,
u->sectors: 431732000
Feb 26 14:10:08 minijep kernel: [ 3.589576] bcache:
flash_devs_run() P00: flash_dev_run: uuids[887] u: ffff88080129bb80,
u->sectors: 9000000000800000
Feb 26 14:10:08 minijep kernel: [ 3.589577] bcache:
flash_devs_run() P00: flash_dev_run: uuids[888] u: ffff88080129bc00,
u->sectors: 16118250
Feb 26 14:10:08 minijep kernel: [ 3.589578] bcache:
flash_devs_run() P00: flash_dev_run: uuids[889] u: ffff88080129bc80,
u->sectors: c014a000
Feb 26 14:10:08 minijep kernel: [ 3.589580] bcache:
flash_devs_run() P00: flash_dev_run: uuids[890] u: ffff88080129bd00,
u->sectors: 9000000000800000
Feb 26 14:10:08 minijep kernel: [ 3.589581] bcache:
flash_devs_run() P00: flash_dev_run: uuids[891] u: ffff88080129bd80,
u->sectors: 24bb8960
Feb 26 14:10:08 minijep kernel: [ 3.589582] bcache:
flash_devs_run() P00: flash_dev_run: uuids[892] u: ffff88080129be00,
u->sectors: 162c74800
Feb 26 14:10:08 minijep kernel: [ 3.589584] bcache:
flash_devs_run() P00: flash_dev_run: uuids[893] u: ffff88080129be80,
u->sectors: 9000000001800000
Feb 26 14:10:08 minijep kernel: [ 3.589585] bcache:
flash_devs_run() P00: flash_dev_run: uuids[894] u: ffff88080129bf00,
u->sectors: 24bb8a00
Feb 26 14:10:08 minijep kernel: [ 3.589586] bcache:
flash_devs_run() P00: flash_dev_run: uuids[895] u: ffff88080129bf80,
u->sectors: 162c8e000
(...)
Feb 26 14:10:08 minijep kernel: [ 3.593789] bcache:
flash_devs_run() P00: flash_dev_run: uuids[4093] u: ffff8808012ffe80,
u->sectors: 0
Feb 26 14:10:08 minijep kernel: [ 3.593791] bcache:
flash_devs_run() P00: flash_dev_run: uuids[4094] u: ffff8808012fff00,
u->sectors: 0
Feb 26 14:10:08 minijep kernel: [ 3.593792] bcache:
flash_devs_run() P00: flash_dev_run: uuids[4095] u: ffff8808012fff80,
u->sectors: 0
Feb 26 14:10:08 minijep kernel: [ 3.593794] bcache:
register_cache() registered cache device sda1
(...)
Feb 26 14:10:08 minijep kernel: [ 5.781599] [drm] Enabling RC6
states: RC6 on, RC6p off, RC6pp off
Feb 26 14:10:08 minijep kernel: [ 35.627315] Adding 32225276k swap
on /dev/sdb6. Priority:-1 extents:1 across:32225276k
(...)
-----------------------------------------


The change to super.c (pr_info() call is for logging and next if is my
salvation ;-):


static int flash_devs_run(struct cache_set *c)
{
int ret = 0;
struct uuid_entry *u;
_debug_show_uuids_of_cache_set(9999,c);
for (u = c->uuids;
u < c->uuids + c->nr_uuids && !ret;
u++)
{
pr_info("P00: flash_dev_run: uuids[%d] u: %p, u->sectors:
%llx", u-c->uuids, u, u->sectors);
if (u->sectors < 0x9000000000000000)
if (UUID_FLASH_ONLY(u))
ret = flash_dev_run(c, u);
}


return ret;
}


In order to log that large number of lines I boot with kernel
parameter: log_buf_len=10M

I would like to add that booting the system spends (I think that
waiting for something) some time to boot, but it could be another
thing (look at last lines of previous /var/log/messages).

As you have seen this is a "trick" to bypass something wich is going
wrong. My question is:

- where is "sectors" field of each uuids struct filled? Is the value
read from the cache device?

I guess that something could happen (or have happened) in some
conversion (int/long instead of unsigned long) or in addressing to
memory and a pointer which modified something which it should not.

I would like to know what happens in order to avoid the use of the
filtering line for big numbers in sectors field as I guess that
something else should be verified...

Josep

On 26 February 2014 17:03, Josep Lladonosa <***@gmail.com> wrote:
> Hello,
>
> I forward some information wich was missing in the list. After this I
> write another message with some (good news for me and) information
> about things that I have found.
>
> Josep
>
> ---------- Forwarded message ----------
> From: Josep Lladonosa <***@gmail.com>
> Date: 11 February 2014 17:39
> Subject: Re: bcache and memory at boot. Bug?
> To: matthew patton <***@yahoo.com>
>
>
> On 11 February 2014 12:23, matthew patton <***@yahoo.com> wrote:
>>
>>
>> >>> -Free memory with kernel 3.11.0-rc7 with 32GiB and bcache0 (halved?)
>>>>> and bcache1 (mounted)
>>>>>
>>>>> $ head -2 /proc/meminfo
>>>>> MemTotal: 32913872 kB
>>>>> MemFree: 12376640 kB
>>>>>
>>>>>
>>>>> - Free memory with kernel 3.12.9 with mem=16G and bcache0 (mounted)
>>>>>
>>>>> $ head -2 /proc/meminfo
>>>>> MemTotal: 15602144 kB
>>>>> MemFree: 14005372 kB
>>
>>
>> too many variables. Boot the same box with the SAME kernel, just twiddle how much ram is visible via the GRUB commandline. ... try with mem=16G and other values like 12G, 24G or 31G
>
> O.K. Here you are:
>
> With kernel 3.13.2:
>
> mem=2G ---> boots O.K. (/dev/bcache0).
> mem=4G ---> Out of memory. (initramfs appears with bcache0 and
> bcache1 for only one caching device. bcache1 has the two correct
> slaves).
> mem=8G ---> bcache-register killed. Kernel panic.
> mem=16G --> Out of memory (initramfs appears with bcache0 to bcache7
> for only one caching device. bcache7 has the two correct slaves).
> mem=20G --> Out of memory (no initramfs prompt appearing).
> mem=24G --> Out of memory (initramfs appears with bcache0 to bcache9
> for only one caching device. bcache9 has the two correct slaves).
>
> (the more RAM is given to box, the more messages about out of memory you get.
>
> Kernel 3.12.9
>
> Command line: BOOT_IMAGE=/vmlinuz-3.12.9 root=/dev/bcache0 ro
> "acpi_osi=!Windows 2012" quiet mem=16G intel_pstate=disable
> pcie_aspm=force i915.i915_enable_rc6=1 i915.i915_enable_fbc=1
> i915.lvds_downclock=1 rcutree.rcu_idle_gp_delay=1
>
> (changing mem kernel boot parameter):
>
> mem=12G ---> boots O.K. (/dev/bcache0).
> mem=14G ---> boots O.K. (/dev/bcache0).
> mem=16G ---> boots O.K. (/dev/bcache0).
> mem=17G ---> boots O.K. (/dev/bcache0).
> mem=18G ---> boots O.K. (/dev/bcache0).
> mem=20G ---> Kernel panic.
> mem=24G ---> Kernel panic.
> mem=32G ---> Out of memory. (initramfs appears with bcache0 and
> bcache1 for only one caching device. bcache1 has the two correct
> slaves).
>
>
> With kernel 3.12.9, When booting, with udev info in /var/log/messages,
> there are memory allocation failure for bcache-register messages:
>
>
> Feb 11 17:22:10 minijep kernel: [ 3.099025] bio: create slab <bio-1> at 1
> Feb 11 17:22:10 minijep kernel: [ 3.452716] bcache:
> bch_journal_replay() journal replay done, 575 keys in 49 entries, seq
> 573572
> Feb 11 17:22:10 minijep kernel: [ 3.452777] vmalloc: allocation
> failure: 19327352836 bytes
> Feb 11 17:22:10 minijep kernel: [ 3.452780] bcache-register: page
> allocation failure: order:0, mode:0x80d2
> Feb 11 17:22:10 minijep kernel: [ 3.452783] CPU: 0 PID: 298 Comm:
> bcache-register Not tainted 3.12.9 #1
> Feb 11 17:22:10 minijep kernel: [ 3.452784] Hardware name:
> Micro-Star International Co., Ltd. GT60/MS-16F3, BIOS E16F3IMS.10U
> 01/21/2013
> Feb 11 17:22:10 minijep kernel: [ 3.452786] 0000f72000000083
> ffffffff8137e021 0000000000000001 ffffffff810c0864
> Feb 11 17:22:10 minijep kernel: [ 3.452789] ffffffff814fdf94
> ffff880036f65b70 0000000000000018 ffff880036f65be8
> Feb 11 17:22:10 minijep kernel: [ 3.452792] ffff880036f65b88
> ffff880036fc8b20 0000000000000000 0000000000000003
> Feb 11 17:22:10 minijep kernel: [ 3.452795] Call Trace:
> Feb 11 17:22:10 minijep kernel: [ 3.452804] [<ffffffff8137e021>] ?
> dump_stack+0x41/0x51
> Feb 11 17:22:10 minijep kernel: [ 3.452808] [<ffffffff810c0864>] ?
> warn_alloc_failed+0x118/0x12c
> Feb 11 17:22:10 minijep kernel: [ 3.452814] [<ffffffff810e7134>] ?
> __vmalloc_node_range+0x1cd/0x1de
> Feb 11 17:22:10 minijep kernel: [ 3.452817] [<ffffffff810e7171>] ?
> __vmalloc_node+0x2c/0x31
> Feb 11 17:22:10 minijep kernel: [ 3.452827] [<ffffffffa01ebd1c>] ?
> bcache_device_init+0x81/0x241 [bcache]
> Feb 11 17:22:10 minijep kernel: [ 3.452832] [<ffffffff810e71ab>] ?
> vzalloc+0x21/0x22
> Feb 11 17:22:10 minijep kernel: [ 3.452839] [<ffffffffa01ebd1c>] ?
> bcache_device_init+0x81/0x241 [bcache]
> Feb 11 17:22:10 minijep kernel: [ 3.452845] [<ffffffffa01ec05e>] ?
> flash_dev_run+0x7d/0x12b [bcache]
> Feb 11 17:22:10 minijep kernel: [ 3.452854] [<ffffffffa01ed88b>] ?
> run_cache_set+0x5c4/0x695 [bcache]
> Feb 11 17:22:10 minijep kernel: [ 3.452859] [<ffffffffa01eee47>] ?
> register_bcache+0x10a0/0x12d9 [bcache]
> Feb 11 17:22:10 minijep kernel: [ 3.452863] [<ffffffff810f0f15>] ?
> alloc_pages_current+0xef/0x109
> Feb 11 17:22:10 minijep kernel: [ 3.452867] [<ffffffff81159855>] ?
> sysfs_write_file+0xcf/0x103
> Feb 11 17:22:10 minijep kernel: [ 3.452871] [<ffffffff81106a23>] ?
> vfs_write+0xa8/0x10b
> Feb 11 17:22:10 minijep kernel: [ 3.452874] [<ffffffff8110705e>] ?
> SyS_write+0x41/0x74
> Feb 11 17:22:10 minijep kernel: [ 3.452878] [<ffffffff81386ca2>] ?
> system_call_fastpath+0x16/0x1b
> Feb 11 17:22:10 minijep kernel: [ 3.452880] Mem-Info:
> Feb 11 17:22:10 minijep kernel: [ 3.452881] Node 0 DMA per-cpu:
> Feb 11 17:22:10 minijep kernel: [ 3.452883] CPU 0: hi: 0,
> btch: 1 usd: 0
> Feb 11 17:22:10 minijep kernel: [ 3.452884] CPU 1: hi: 0,
> btch: 1 usd: 0
> Feb 11 17:22:10 minijep kernel: [ 3.452886] CPU 2: hi: 0,
> btch: 1 usd: 0
> Feb 11 17:22:10 minijep kernel: [ 3.452887] CPU 3: hi: 0,
> btch: 1 usd: 0
> Feb 11 17:22:10 minijep kernel: [ 3.452888] CPU 4: hi: 0,
> btch: 1 usd: 0
> Feb 11 17:22:10 minijep kernel: [ 3.452889] CPU 5: hi: 0,
> btch: 1 usd: 0
> Feb 11 17:22:10 minijep kernel: [ 3.452890] CPU 6: hi: 0,
> btch: 1 usd: 0
> Feb 11 17:22:10 minijep kernel: [ 3.452892] CPU 7: hi: 0,
> btch: 1 usd: 0
>
>
> --
> --
> Salutacions...Josep
> --
>
>
> --
> --
> Salutacions...Josep
> --



--
--
Salutacions...Josep
--
Loading...