On Mon, Mar 25, 2019 at 10:50:28PM -0400, Zygo Blaxell wrote: > Running balance, rsync, and dedupe, I get kernel warnings every few > minutes on 5.0.4. No warnings on 5.0.3 under similar conditions. > > Mount options are: flushoncommit,space_cache=v2,compress=zstd. > > There are two different stacks on the warnings. This one comes from > btrfs balance: [snip] Possibly unrelated, but I'm also repeatably getting this in 5.0.4 and not 5.0.3, after about 5 hours of uptime. Different processes, same kernel stack: [Mon Mar 25 23:35:17 2019] kworker/u8:4: page allocation failure: order:0, mode:0x404000(GFP_NOWAIT|__GFP_COMP), nodemask=(null),cpuset=/,mems_allowed=0 [Mon Mar 25 23:35:17 2019] CPU: 2 PID: 29518 Comm: kworker/u8:4 Tainted: G W 5.0.4-zb64-303ce93b05c9+ #1 [Mon Mar 25 23:35:17 2019] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014 [Mon Mar 25 23:35:17 2019] Workqueue: btrfs-submit btrfs_submit_helper [Mon Mar 25 23:35:17 2019] Call Trace: [Mon Mar 25 23:35:17 2019] dump_stack+0x7d/0xbb [Mon Mar 25 23:35:17 2019] warn_alloc+0x108/0x190 [Mon Mar 25 23:35:17 2019] __alloc_pages_nodemask+0x12c4/0x13f0 [Mon Mar 25 23:35:17 2019] ? rcu_read_lock_sched_held+0x68/0x70 [Mon Mar 25 23:35:17 2019] ? __update_load_avg_se+0x208/0x280 [Mon Mar 25 23:35:17 2019] cache_grow_begin+0x79/0x730 [Mon Mar 25 23:35:17 2019] ? cache_grow_begin+0x79/0x730 [Mon Mar 25 23:35:17 2019] ? ____cache_alloc_node+0x165/0x1e0 [Mon Mar 25 23:35:17 2019] fallback_alloc+0x1e4/0x280 [Mon Mar 25 23:35:17 2019] kmem_cache_alloc+0x2e9/0x310 [Mon Mar 25 23:35:17 2019] btracker_queue+0x47/0x170 [dm_cache] [Mon Mar 25 23:35:17 2019] __lookup+0x51a/0x600 [dm_cache_smq] [Mon Mar 25 23:35:17 2019] ? smq_lookup+0x37/0x7b [dm_cache_smq] [Mon Mar 25 23:35:17 2019] smq_lookup+0x5d/0x7b [dm_cache_smq] [Mon Mar 25 23:35:18 2019] map_bio.part.40+0x14d/0x5d0 [dm_cache] [Mon Mar 25 23:35:18 2019] ? bio_detain_shared+0xb3/0x120 [dm_cache] [Mon Mar 25 23:35:18 2019] cache_map+0x120/0x170 [dm_cache] [Mon Mar 25 23:35:18 2019] __map_bio+0x42/0x1f0 [dm_mod] [Mon Mar 25 23:35:18 2019] __split_and_process_non_flush+0x152/0x1e0 [dm_mod] [Mon Mar 25 23:35:18 2019] __split_and_process_bio+0xd4/0x400 [dm_mod] [Mon Mar 25 23:35:18 2019] ? lock_acquire+0xbc/0x1c0 [Mon Mar 25 23:35:18 2019] ? dm_get_live_table+0x5/0xc0 [dm_mod] [Mon Mar 25 23:35:18 2019] dm_make_request+0x4d/0x100 [dm_mod] [Mon Mar 25 23:35:18 2019] generic_make_request+0x297/0x470 [Mon Mar 25 23:35:18 2019] ? kvm_sched_clock_read+0x14/0x30 [Mon Mar 25 23:35:18 2019] ? submit_bio+0x6c/0x140 [Mon Mar 25 23:35:18 2019] submit_bio+0x6c/0x140 [Mon Mar 25 23:35:18 2019] run_scheduled_bios+0x1e6/0x500 [Mon Mar 25 23:35:18 2019] ? normal_work_helper+0x95/0x530 [Mon Mar 25 23:35:18 2019] normal_work_helper+0x95/0x530 [Mon Mar 25 23:35:18 2019] process_one_work+0x223/0x5d0 [Mon Mar 25 23:35:18 2019] worker_thread+0x4f/0x3b0 [Mon Mar 25 23:35:18 2019] kthread+0x106/0x140 [Mon Mar 25 23:35:18 2019] ? process_one_work+0x5d0/0x5d0 [Mon Mar 25 23:35:18 2019] ? kthread_park+0x90/0x90 [Mon Mar 25 23:35:18 2019] ret_from_fork+0x3a/0x50 [Mon Mar 25 23:35:18 2019] Mem-Info: [Mon Mar 25 23:35:18 2019] active_anon:195872 inactive_anon:15658 isolated_anon:0 active_file:629653 inactive_file:308914 isolated_file:0 unevictable:65536 dirty:14449 writeback:27580 unstable:0 slab_reclaimable:492522 slab_unreclaimable:94393 mapped:10915 shmem:18846 pagetables:2178 bounce:0 free:66082 free_pcp:1963 free_cma:24 [Mon Mar 25 23:35:18 2019] Node 0 active_anon:783488kB inactive_anon:62632kB active_file:2516656kB inactive_file:1235604kB unevictable:262144kB isolated(anon):0kB isolated(file):0kB mapped:43660kB dirty:57796kB writeback:110320kB shmem:75384kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 137216kB writeback_tmp:0kB unstable:0kB all_unreclaimable? no [Mon Mar 25 23:35:18 2019] Node 0 DMA free:15844kB min:132kB low:164kB high:196kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:15992kB managed:15908kB mlocked:0kB kernel_stack:0kB pagetables:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB [Mon Mar 25 23:35:18 2019] lowmem_reserve[]: 0 2939 7906 7906 7906 [Mon Mar 25 23:35:18 2019] Node 0 DMA32 free:116632kB min:81336kB low:87592kB high:93848kB active_anon:330436kB inactive_anon:31840kB active_file:531512kB inactive_file:491372kB unevictable:108544kB writepending:121984kB present:3129176kB managed:3019336kB mlocked:108544kB kernel_stack:2704kB pagetables:2944kB bounce:0kB free_pcp:3800kB local_pcp:256kB free_cma:0kB [Mon Mar 25 23:35:18 2019] lowmem_reserve[]: 0 0 4966 4966 4966 [Mon Mar 25 23:35:18 2019] Node 0 Normal free:141932kB min:42420kB low:53024kB high:63628kB active_anon:453224kB inactive_anon:30792kB active_file:1984568kB inactive_file:737244kB unevictable:153600kB writepending:46544kB present:5242880kB managed:5102032kB mlocked:153600kB kernel_stack:7020kB pagetables:5768kB bounce:0kB free_pcp:4188kB local_pcp:1700kB free_cma:96kB [Mon Mar 25 23:35:18 2019] lowmem_reserve[]: 0 0 0 0 0 [Mon Mar 25 23:35:18 2019] Node 0 DMA: 1*4kB (U) 0*8kB 0*16kB 1*32kB (U) 1*64kB (U) 1*128kB (U) 1*256kB (U) 0*512kB 1*1024kB (U) 1*2048kB (M) 3*4096kB (M) = 15844kB [Mon Mar 25 23:35:18 2019] Node 0 DMA32: 12698*4kB (UME) 6110*8kB (UME) 1087*16kB (UME) 4*32kB (M) 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 117192kB [Mon Mar 25 23:35:18 2019] Node 0 Normal: 13507*4kB (UMEHC) 8008*8kB (UMEHC) 1374*16kB (UMEH) 3*32kB (H) 4*64kB (H) 4*128kB (H) 2*256kB (H) 1*512kB (H) 0*1024kB 0*2048kB 0*4096kB = 141964kB [Mon Mar 25 23:35:18 2019] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB [Mon Mar 25 23:35:18 2019] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB [Mon Mar 25 23:35:18 2019] 955001 total pagecache pages [Mon Mar 25 23:35:18 2019] 0 pages in swap cache [Mon Mar 25 23:35:18 2019] Swap cache stats: add 0, delete 0, find 0/0 [Mon Mar 25 23:35:18 2019] Free swap = 0kB [Mon Mar 25 23:35:18 2019] Total swap = 0kB [Mon Mar 25 23:35:18 2019] 2097012 pages RAM [Mon Mar 25 23:35:18 2019] 0 pages HighMem/MovableOnly [Mon Mar 25 23:35:18 2019] 62693 pages reserved [Mon Mar 25 23:35:18 2019] 4096 pages cma reserved [Mon Mar 25 23:35:18 2019] 0 pages hwpoisoned As far as I can tell from logs of memory usage (recording memcg and MemAvail stats every second), there are gigabytes of available (clean page cache) RAM at all times during these tests.
