Hi Eric, We built a kernel with the 3 patches applied and I still got the box to lock up. I don't have any of the traces any more. Also I'm wondering what is the best way to get these? When this happens my machine completely locks up so can't grab anything from dmesg. Let me know what you want me to grab and I'll crash it again. Regards, Richard On 10 March 2016 at 14:34, Eric Wheeler <bcache@xxxxxxxxxxxxxxxxxx> wrote: > Hi Richard, Marc, > >>>> [290623.673871] bcache-register: page allocation failure: order:7, mode:0x24080c0 > > Do you still have the backtraces that show the function call stack for > errors that look like this? > %s: page allocation failure: order:%d, mode:0x%x > > Please send as many relevant OOM failure traces that you can. I would > like to see which memory allocation(s) are failing and if they are always > the same stack trace. > > In the example above, order 7 means 2^7 of 4k pages, so it means the > kernel can't find 512k of contiguous memory that can be allocated. > > It looks like the OOM is triggered in bch_cache_set_alloc, but might be > cache_alloc too. I'm not sure if an alternate allocation mechanism can be > used safely, but thats what I want to look into. > > Thanks! > > -Eric > > -- > Eric Wheeler > > On Wed, 9 Mar 2016, Eric Wheeler wrote: > >> On Wed, 9 Mar 2016, Richard Bade wrote: >> >> > Hi Guys, >> > I've also seen this issue when registering a device. >> > [Fri Feb 5 14:06:59 2016] bcache: register_cache() error opening >> > dm-6: cannot allocate memory >> > >> > For me the situation happens because I'm running Ceph OSD's on the >> > host. These are using all the available memory and for some reason the >> > register cannot allocate memory. >> > I've reproduced this several times, but basically if I register on a >> > system that has been up for a while and therefore using all it's RAM >> > this will happen. >> > Here's two specific time's it's happened: >> > when creating using "make-bcache --cache /dev/vg-raid0/lv-ceph_j19 >> > --bdev /dev/sdf1". It failed due to xfs still remaining on /dev/sdf1. >> >> Do you get a kernel failure, or is it just make-bcache being safe? >> >> > Then run wipefs and "make-bcache --cache /dev/vg-raid0/lv-ceph_j19 >> > --bdev /dev/sdf1" again. CRASH. >> >> make-bcache will auto register. (Maybe there's an option to stop that, >> I've not looked.) >> >> > when manually creating a cache device using "make-bcache --cache >> > /dev/vg-raid0/lv-bcache". The cache set didn't show up in >> > /sys/fs/bcache. echo "/dev/vg-raid0/lv-bcache" > >> > /sys/fs/bcache/register. CRASH. >> > I was able to work around this issue by stopping the osd's before >> > registering and therefore freeing up memory. >> >> I would be curious if setting /proc/sys/vm/min_free_kbytes to 256*1024 >> fixes that. >> >> > Because I am able to reproduce this relatively easily, I'm happy to >> > test any patches. >> >> Yes, thank you, please do: >> >> Try the three patches at the top of these two branches and see if you >> crash. I'm hoping it fails gracefully on OOM: >> >> https://bitbucket.org/ewheelerinc/linux/branch/v4.5-rc6-bcache-fixes >> commits 84a2edd, a704484 >> https://bitbucket.org/ewheelerinc/linux/branch/v4.5-rc7-bcache-fixes >> commit 87264e9 >> >> If it stops crashing, then maybe we can work out a way to allocate memory >> such that it succeeds. Please send any dmesg output. >> >> -Eric >> >> > Apart from the register crash, the cache sets have been up and stable >> > for over 1 month. >> > >> > Regards, >> > Richard >> > >> > On Mon, 7 Mar 2016, Marc MERLIN wrote: >> > >> > > I started a btrfs copy from a bcached device to another one (both are in >> > > the 5 to 15TB range). >> > > A minute later, my system that had been up for several days, crashed. >> > > >> > > Ultimately, it crashed on this: >> > > bcache: register_cache() error opening sdl2: cannot allocate memory >> > > BUG: unable to handle kernel NULL pointer dereference at 00000000000009b8 >> > > IP: [<ffffffffc0516e8d>] cache_set_flush+0x102/0x15c [bcache] >> > >> > Strange about memory allocation issues. Do you have >> > /proc/sys/vm/min_free_kbytes set to something like $((256*1024)) ? Is this >> > a multi-socket machine with all memory plugged into only one CPU? >> > >> > I'm curious though, why was registration called a second time? Was the >> > drive external? Could udev be re-registering the device? >> > >> > You might find where the registration is being done and prevent it from >> > running automatically. At least that might solve the re-registration >> > problem. >> > >> > As for the memory allocation issue, the backtrace indicates that this is a >> > registration-time problem, not a runtime issue. I'm guessing it is one of >> > the threads attempting to proceed after a memory allocation error similar >> > to the writeback thread issue you had last time which was fixed by adding >> > some locking around the initialization. >> > >> > I'll look and see if I can come up with a reasonable patch to cleanup the >> > allocator or gc thread under OOM conditions at registration time. >> > >> > -Eric >> > >> > > >> > > I'm not sure why it tried to register sdl2 then when it was already >> > > registered from boot. Did it time out and had to be registered again? >> > > >> > > At this point, things with bcache have been bad enough, that I'm >> > > considering removing it. My system has been very unstable with it :( >> > > Or maybe I can just remove the caching devices, leave the backing ones, >> > > and run without cache for now, giving me the option to re-add the cache later. >> > > >> > > I actually just added 16GB of RAM to the server after adding bcache, and >> > > clearly going from 8 to 24GB made no difference. I'm wondering if there >> > > is a memory leak somewhere? >> > > >> > > Just before the system crashed, memory looked like this, which isn't bad: >> > > total used free shared buffers cached >> > > Mem: 24392440 24241440 151000 0 88 20116748 >> > > -/+ buffers/cache: 4124604 20267836 >> > > Swap: 15616764 244452 15372312 >> > > >> > > I'm using btrfs on top of dmcrypt on top of bcache. >> > > btrfs on top of dmcrypt was stable, I had been using it for years. Adding bcache is what >> > > caused all my recent problems to start. >> > > >> > > Any ideas? >> > > >> > > Thanks, >> > > Marc >> > > >> > > >> > > [290569.458707] Process accounting resumed >> > > [290623.673871] bcache-register: page allocation failure: order:7, mode:0x24080c0 >> > > [290623.697143] CPU: 0 PID: 1284 Comm: bcache-register Tainted: G W 4.4.2-amd64-i915-volpreempt-20160214bc3 #5 >> > > [290623.732143] Hardware name: System manufacturer System Product Name/P8H67-M PRO, BIOS 3904 04/27/2013 >> > > [290623.762428] 0000000000000000 ffff88001df7bb08 ffffffff8134ae0a 0000000000000001 >> > > [290623.787470] ffff88001df7bba0 ffffffff81124ab6 024080c01df7bc44 024080c000000040 >> > > [290623.811775] 0000000700000001 0000000000000007 0000000000000007 0000000000000040 >> > > [290623.836443] Call Trace: >> > > [290623.846280] [<ffffffff8134ae0a>] dump_stack+0x44/0x55 >> > > [290623.864123] [<ffffffff81124ab6>] warn_alloc_failed+0x114/0x12c >> > > [290623.883425] [<ffffffff811274b8>] __alloc_pages_nodemask+0x7cb/0x84c >> > > [290623.904159] [<ffffffff8107df80>] ? try_to_wake_up+0x1d9/0x1eb >> > > [290623.923173] [<ffffffff8115f6d7>] alloc_pages_current+0xa9/0xcd >> > > [290623.942435] [<ffffffff8112377e>] __get_free_pages+0xe/0x3c >> > > [290623.960621] [<ffffffffc05192f0>] bch_cache_set_alloc+0x3c7/0x479 [bcache] >> > > [290623.983825] [<ffffffffc051a5e3>] register_bcache+0x1241/0x1452 [bcache] >> > > [290624.005456] [<ffffffff8134c853>] kobj_attr_store+0x10/0x1a >> > > [290624.023729] [<ffffffff811df9df>] sysfs_kf_write+0x39/0x3b >> > > [290624.041739] [<ffffffff811df2e1>] kernfs_fop_write+0xed/0x130 >> > > [290624.060394] [<ffffffff8117d97d>] __vfs_write+0x26/0xa5 >> > > [290624.077452] [<ffffffff810b2969>] ? current_kernel_time64+0x10/0x36 >> > > [290624.097921] [<ffffffff812d6050>] ? security_file_permission+0x3b/0x42 >> > > [290624.119197] [<ffffffff810915ea>] ? percpu_down_read+0x12/0x41 >> > > [290624.138945] [<ffffffff8117fb61>] ? __sb_start_write+0x2b/0x48 >> > > [290624.158291] [<ffffffff8117dfe8>] vfs_write+0x9d/0xe8 >> > > [290624.174919] [<ffffffff8117e7bd>] SyS_write+0x4d/0x78 >> > > [290624.191455] [<ffffffff810039c3>] do_fast_syscall_32+0xb3/0xf3 >> > > [290624.210331] [<ffffffff816e3e32>] sysenter_flags_fixed+0x8/0x12 >> > > [290624.229355] Mem-Info: >> > > [290624.237432] active_anon:607145 inactive_anon:208571 isolated_anon:0 >> > > [290624.237432] active_file:2103407 inactive_file:1565209 isolated_file:0 >> > > [290624.237432] unevictable:1307 dirty:188846 writeback:138775 unstable:0 >> > > [290624.237432] slab_reclaimable:180112 slab_unreclaimable:73373 >> > > [290624.237432] mapped:419640 shmem:466581 pagetables:5778 bounce:0 >> > > [290624.237432] free:988612 free_pcp:2130 free_cma:14 >> > > [290624.351715] Node 0 DMA free:15884kB min:12kB low:12kB high:16kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15976kB managed:15892kB mlocked:0kB dirty:0kB writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:0kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:0kB unstable:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? yes >> > > [290624.483875] lowmem_reserve[]: 0 3201 23800 23800 >> > > [290624.500998] Node 0 DMA32 free:581000kB min:2648kB low:3308kB high:3972kB active_anon:229220kB inactive_anon:248156kB active_file:1102468kB inactive_file:832264kB unevictable:948kB isolated(anon):0kB isolated(file):68kB present:3362068kB managed:3283032kB mlocked:68719477684kB dirty:94316kB writeback:65996kB mapped:253400kB shmem:282168kB slab_reclaimable:96344kB slab_unreclaimable:41308kB kernel_stack:2480kB pagetables:2952kB unstable:0kB bounce:0kB free_pcp:4008kB local_pcp:140kB free_cma:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no >> > > [290624.655741] lowmem_reserve[]: 0 0 20599 20599 >> > > [290624.674232] Node 0 Normal free:3368136kB min:17048kB low:21308kB high:25572kB active_anon:2203780kB inactive_anon:586104kB active_file:7311280kB inactive_file:5430068kB unevictable:4280kB isolated(anon):0kB isolated(file):0kB present:21485568kB managed:21093516kB mlocked:481036341432kB dirty:662172kB writeback:472472kB mapped:1425288kB shmem:1584132kB slab_reclaimable:624104kB slab_unreclaimable:251680kB kernel_stack:11696kB pagetables:20180kB unstable:0kB bounce:0kB free_pcp:4304kB local_pcp:588kB free_cma:56kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no >> > > [290624.834378] lowmem_reserve[]: 0 0 0 0 >> > > [290624.848459] Node 0 DMA: 1*4kB (U) 1*8kB (U) 0*16kB 0*32kB 2*64kB (U) 1*128kB (U) 1*256kB (U) 0*512kB 1*1024kB (U) 1*2048kB (M) 3*4096kB (M) = 15884kB >> > > [290624.895688] Node 0 DMA32: 30635*4kB (UME) 23925*8kB (UME) 7478*16kB (UME) 2420*32kB (UME) 794*64kB (UME) 139*128kB (UME) 10*256kB (UM) 0*512kB 0*1024kB 0*2048kB 0*4096kB = 582196kB >> > > [290624.947950] Node 0 Normal: 241499*4kB (UME) 161875*8kB (UME) 33424*16kB (UME) 10915*32kB (UME) 2795*64kB (UME) 334*128kB (UME) 15*256kB (UM) 0*512kB 0*1024kB 0*2048kB 0*4096kB = 3370532kB >> > > [290625.003724] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB >> > > [290625.030463] 4142937 total pagecache pages >> > > [290625.043969] 5782 pages in swap cache >> > > [290625.056118] Swap cache stats: add 102837, delete 97055, find 627323/635133 >> > > [290625.078329] Free swap = 15372324kB >> > > [290625.090190] Total swap = 15616764kB >> > > [290625.102186] 6215903 pages RAM >> > > [290625.112399] 0 pages HighMem/MovableOnly >> > > [290625.125747] 117793 pages reserved >> > > [290625.137495] 4096 pages cma reserved >> > > [290625.149199] 0 pages hwpoisoned >> > > [290625.159961] bcache: register_cache() error opening sdl2: cannot allocate memory >> > > [290625.183410] BUG: unable to handle kernel NULL pointer dereference at 00000000000009b8 >> > > [290625.208648] IP: [<ffffffffc0516e8d>] cache_set_flush+0x102/0x15c [bcache] >> > > [290625.230734] PGD 0 >> > > [290625.238446] Oops: 0000 [#1] SMP >> > > [290625.249857] Modules linked in: udp_diag tcp_diag inet_diag veth ip6table_filter ip6_tables ebtable_nat ebtables ppdev lp xt_addrtype tun bridge stp llc autofs4 softdog binfmt_misc ftdi_sio nfsd nfs_acl auth_rpcgss nfs fscache lockd grace sunrpc ipt_REJECT nf_reject_ipv4 xt_conntrack xt_mark xt_nat xt_tcpudp nf_log_ipv4 nf_log_common xt_LOG iptable_mangle iptable_filter bcache lm85 hwmon_vid pl2303 iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 ip_tables nf_conntrack_ftp ipt_MASQUERADE x_tables nf_nat_masquerade_ipv4 nf_nat nf_conntrack sg st snd_pcm_oss snd_mixer_oss kvm_intel snd_hda_codec_realtek snd_hda_codec_generic snd_opl3_synth kvm snd_seq_midi_emul snd_hda_intel snd_cmipci gameport snd_hda_codec snd_opl3_lib snd_mpu401_uart snd_seq_midi irqbypass snd_seq_midi_event snd_seq snd_hda_core snd_hwdep snd_rawmidi asix coretemp eeepc_wmi tpm_infineon rc_ati_x10 snd_pcm libphy snd_seq_device asus_wmi snd_timer sparse_keymap rfkill intel_rapl 8250_fintek at > i_ >> re >> > mo >> > > te usbnet tpm_tis snd rc_core battery tpm evdev iosf_mbi wmi pcspkr input_leds intel_powerclamp parport_pc processor i2c_i801 xhci_pci x86_pkg_temp_thermal usbserial soundcore parport xhci_hcd lpc_ich e1000e ptp pps_core fuse raid456 multipath mmc_block mmc_core dm_snapshot dm_bufio dm_mirror dm_region_hash dm_log dm_crypt dm_mod async_raid6_recov async_pq async_xor async_memcpy async_tx blowfish_x86_64 blowfish_common ecb xts ansi_cprng drbg aesni_intel ablk_helper lrw gf128mul glue_helper aes_x86_64 crct10dif_pclmul crc32_pclmul crc32c_intel r8169 ehci_pci fjes ehci_hcd thermal mii sata_mv fan cryptd usbcore usb_common sata_sil24 [last unloaded: ftdi_sio] >> > > [290625.713109] CPU: 0 PID: 25842 Comm: kworker/0:0 Tainted: G W 4.4.2-amd64-i915-volpreempt-20160214bc3 #5 >> > > [290625.747597] Hardware name: System manufacturer System Product Name/P8H67-M PRO, BIOS 3904 04/27/2013 >> > > [290625.776918] Workqueue: events cache_set_flush [bcache] >> > > [290625.794260] task: ffff880467caa0c0 ti: ffff8805af184000 task.ti: ffff8805af184000 >> > > [290625.818544] RIP: 0010:[<ffffffffc0516e8d>] [<ffffffffc0516e8d>] cache_set_flush+0x102/0x15c [bcache] >> > > [290625.848082] RSP: 0018:ffff8805af187e10 EFLAGS: 00010202 >> > > [290625.866890] RAX: 0000000000000001 RBX: ffff880153a40ce8 RCX: 0000000000000282 >> > > [290625.891136] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000000 >> > > [290625.914365] RBP: ffff8805af187e30 R08: 00000000000000fa R09: ffffe8ffffc01900 >> > > [290625.937588] R10: ffff880088430838 R11: ffff880088430838 R12: 0000000000000000 >> > > [290625.960781] R13: ffff880153a40de8 R14: 0000000000000000 R15: ffffe8ffffc01900 >> > > [290625.983951] FS: 0000000000000000(0000) GS:ffff88061e200000(0000) knlGS:0000000000000000 >> > > [290626.010918] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 >> > > [290626.030800] CR2: 00000000000009b8 CR3: 0000000001e0a000 CR4: 00000000001406f0 >> > > [290626.053914] Stack: >> > > [290626.061687] ffff8805d6183280 ffff88061e216040 ffff880153a40ce8 0000000000000000 >> > > [290626.085725] ffff8805af187e78 ffffffff81070fcf ffff8805d61832b0 000000001e216058 >> > > [290626.110510] ffff8805d6183280 ffff88061e216040 ffff8805d61832b0 ffff88061e216058 >> > > [290626.135329] Call Trace: >> > > [290626.145108] [<ffffffff81070fcf>] process_one_work+0x15b/0x260 >> > > [290626.164241] [<ffffffff81071574>] worker_thread+0x1f0/0x29d >> > > [290626.182561] [<ffffffff81071384>] ? rescuer_thread+0x281/0x281 >> > > [290626.201721] [<ffffffff810758e9>] kthread+0xa5/0xad >> > > [290626.217966] [<ffffffff81075844>] ? kthread_parkme+0x24/0x24 >> > > [290626.236505] [<ffffffff816e1c0f>] ret_from_fork+0x3f/0x70 >> > > [290626.255052] [<ffffffff81075844>] ? kthread_parkme+0x24/0x24 >> > > [290626.274460] Code: 89 1c c1 4d 8b a4 24 f0 01 00 00 49 81 ec f0 01 00 00 eb b4 45 31 e4 0f b7 83 4c f7 ff ff 4a 8b 94 e3 58 ff ff ff 44 39 e0 76 16 <48> 8b ba b8 09 00 00 48 85 ff 74 05 e8 61 e8 b5 c0 49 ff c4 eb >> > > [290626.337443] RIP [<ffffffffc0516e8d>] cache_set_flush+0x102/0x15c [bcache] >> > > [290626.359833] RSP <ffff8805af187e10> >> > > [290626.372050] CR2: 00000000000009b8 >> > > [290626.383646] ---[ end trace f97d88b8bb456800 ]--- >> > > [290626.399977] Kernel panic - not syncing: Fatal exception >> > > [290626.418169] Kernel Offset: disabled >> > > [290626.430278] Rebooting in 20 seconds.. >> > > [290646.378903] ACPI MEMORY or I/O RESET_REG. >> > > -- >> > > "A mouse is a device used to point at the xterm you want to type in" - A.S.R. >> > > Microsoft is to operating systems .... >> > > .... what McDonalds is to gourmet cooking >> > > Home page: http://marc.merlins.org/ | PGP 1024R/763BE901 >> > > -- >> > > To unsubscribe from this list: send the line "unsubscribe linux-bcache" in >> > > the body of a message to majordomo@xxxxxxxxxxxxxxx >> > > More majordomo info at http://vger.kernel.org/majordomo-info.html >> > > >> > -- >> > To unsubscribe from this list: send the line "unsubscribe linux-bcache" in >> > the body of a message to majordomo@xxxxxxxxxxxxxxx >> > More majordomo info at http://vger.kernel.org/majordomo-info.html >> > -- >> > To unsubscribe from this list: send the line "unsubscribe linux-bcache" in >> > the body of a message to majordomo@xxxxxxxxxxxxxxx >> > More majordomo info at http://vger.kernel.org/majordomo-info.html >> > >> -- >> To unsubscribe from this list: send the line "unsubscribe linux-bcache" in >> the body of a message to majordomo@xxxxxxxxxxxxxxx >> More majordomo info at http://vger.kernel.org/majordomo-info.html >> -- To unsubscribe from this list: send the line "unsubscribe linux-bcache" in the body of a message to majordomo@xxxxxxxxxxxxxxx More majordomo info at http://vger.kernel.org/majordomo-info.html
