lvmcache_page_allocation_failure.md

[Wed Mar 15 13:43:09 2023] AuxIoPool1: page allocation failure: order:0, mode:0x1000000(GFP_NOWAIT), nodemask=(null)
[Wed Mar 15 13:43:09 2023] AuxIoPool1 cpuset=/ mems_allowed=0
[Wed Mar 15 13:43:09 2023] CPU: 6 PID: 2760 Comm: AuxIoPool1 Not tainted 4.14.305-227.531.amzn2.aarch64 #1
[Wed Mar 15 13:43:09 2023] Hardware name: Amazon EC2 c6gd.2xlarge/, BIOS 1.0 11/1/2018
[Wed Mar 15 13:43:09 2023] Call trace:
[Wed Mar 15 13:43:09 2023]  dump_backtrace+0x0/0x190
[Wed Mar 15 13:43:09 2023]  show_stack+0x24/0x30
[Wed Mar 15 13:43:09 2023]  dump_stack+0x98/0xc8
[Wed Mar 15 13:43:09 2023]  warn_alloc+0x11c/0x1b4
[Wed Mar 15 13:43:09 2023]  __alloc_pages_nodemask+0xcc8/0xd48
[Wed Mar 15 13:43:09 2023]  alloc_page_interleave+0x38/0xa4
[Wed Mar 15 13:43:09 2023]  alloc_pages_current+0xd8/0xe8
[Wed Mar 15 13:43:09 2023]  allocate_slab+0x3bc/0x4f4
[Wed Mar 15 13:43:09 2023]  new_slab+0x64/0xc0
[Wed Mar 15 13:43:09 2023]  ___slab_alloc+0x410/0x5a0
[Wed Mar 15 13:43:09 2023]  __slab_alloc+0x50/0x68
[Wed Mar 15 13:43:09 2023]  kmem_cache_alloc+0x1c0/0x1f8
[Wed Mar 15 13:43:09 2023]  btracker_queue+0x38/0x174 [dm_cache]
[Wed Mar 15 13:43:09 2023]  __lookup+0x32c/0x5ac [dm_cache_smq]
[Wed Mar 15 13:43:09 2023]  smq_lookup+0x80/0x118 [dm_cache_smq]
[Wed Mar 15 13:43:09 2023]  map_bio.part.38+0x84/0x5c0 [dm_cache]
[Wed Mar 15 13:43:09 2023]  map_bio+0x7c/0x94 [dm_cache]
[Wed Mar 15 13:43:09 2023]  cache_map+0xe8/0x160 [dm_cache]
[Wed Mar 15 13:43:09 2023]  __map_bio+0xc4/0x22c [dm_mod]
[Wed Mar 15 13:43:09 2023]  __split_and_process_non_flush+0x140/0x340 [dm_mod]
[Wed Mar 15 13:43:09 2023]  __split_and_process_bio+0x128/0x26c [dm_mod]
[Wed Mar 15 13:43:09 2023]  dm_make_request+0x7c/0xdc [dm_mod]
[Wed Mar 15 13:43:09 2023]  generic_make_request+0xfc/0x290
[Wed Mar 15 13:43:09 2023]  submit_bio+0x5c/0x190
[Wed Mar 15 13:43:09 2023]  mpage_readpages+0x168/0x200
[Wed Mar 15 13:43:09 2023]  xfs_vm_readpages+0x40/0xc4
[Wed Mar 15 13:43:09 2023]  __do_page_cache_readahead+0x1c4/0x2a4
[Wed Mar 15 13:43:09 2023]  ondemand_readahead+0x148/0x2ac
[Wed Mar 15 13:43:09 2023]  page_cache_sync_readahead+0x60/0xa0
[Wed Mar 15 13:43:09 2023]  generic_file_buffered_read+0x34c/0x6d0
[Wed Mar 15 13:43:09 2023]  generic_file_read_iter+0x114/0x180
[Wed Mar 15 13:43:09 2023]  xfs_file_buffered_aio_read+0x54/0x110
[Wed Mar 15 13:43:09 2023]  xfs_file_read_iter+0xb0/0x140
[Wed Mar 15 13:43:09 2023]  __vfs_read+0x100/0x168
[Wed Mar 15 13:43:09 2023]  vfs_read+0x94/0x158
[Wed Mar 15 13:43:09 2023]  SyS_pread64+0xb4/0xd0
[Wed Mar 15 13:43:09 2023]  __sys_trace_return+0x0/0x4
[Wed Mar 15 13:43:09 2023] Mem-Info:
[Wed Mar 15 13:43:09 2023] active_anon:2112521 inactive_anon:8287 isolated_anon:0
                            active_file:635559 inactive_file:974447 isolated_file:0
                            unevictable:0 dirty:958 writeback:0 unstable:0
                            slab_reclaimable:81091 slab_unreclaimable:33511
                            mapped:32915 shmem:8324 pagetables:7644 bounce:0
                            free:26491 free_pcp:163 free_cma:7028
[Wed Mar 15 13:43:09 2023] Node 0 active_anon:8450084kB inactive_anon:33148kB active_file:2542236kB inactive_file:3897788kB unevictable:0kB isolated(anon):0kB isolated(file):0kB mapped:131660kB dirty:3832kB writeback:0kB shmem:33296kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 0kB writeback_tmp:0kB unstable:0kB all_unreclaimable? no
[Wed Mar 15 13:43:09 2023] Node 0 DMA free:62316kB min:2804kB low:3812kB high:4820kB active_anon:425620kB inactive_anon:0kB active_file:156416kB inactive_file:263624kB unevictable:0kB writepending:500kB present:1048576kB managed:1018680kB mlocked:0kB kernel_stack:0kB pagetables:696kB bounce:0kB free_pcp:116kB local_pcp:116kB free_cma:28112kB
[Wed Mar 15 13:43:09 2023] lowmem_reserve[]: 0 14815 14815
[Wed Mar 15 13:43:09 2023] Node 0 Normal free:43524kB min:42248kB low:57416kB high:72584kB active_anon:8024464kB inactive_anon:33148kB active_file:2385820kB inactive_file:3634164kB unevictable:0kB writepending:3332kB present:15433728kB managed:15170636kB mlocked:0kB kernel_stack:12032kB pagetables:29880kB bounce:0kB free_pcp:640kB local_pcp:0kB free_cma:0kB
[Wed Mar 15 13:43:09 2023] lowmem_reserve[]: 0 0 0
[Wed Mar 15 13:43:09 2023] Node 0 DMA: 3672*4kB (UMEHC) 1638*8kB (UMEHC) 756*16kB (UMEHC) 239*32kB (UMHC) 65*64kB (UMH) 30*128kB (UMH) 12*256kB (UH) 7*512kB (UH) 0*1024kB 0*2048kB 0*4096kB = 62192kB
[Wed Mar 15 13:43:09 2023] Node 0 Normal: 10461*4kB (UMH) 21*8kB (UMH) 3*16kB (UH) 8*32kB (UH) 2*64kB (H) 3*128kB (H) 2*256kB (H) 0*512kB 0*1024kB 0*2048kB 0*4096kB = 43340kB
[Wed Mar 15 13:43:09 2023] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
[Wed Mar 15 13:43:09 2023] 1615038 total pagecache pages
[Wed Mar 15 13:43:09 2023] 0 pages in swap cache
[Wed Mar 15 13:43:09 2023] Swap cache stats: add 0, delete 0, find 0/0
[Wed Mar 15 13:43:09 2023] Free swap  = 0kB
[Wed Mar 15 13:43:09 2023] Total swap = 0kB
[Wed Mar 15 13:43:09 2023] 4120576 pages RAM
[Wed Mar 15 13:43:09 2023] 0 pages HighMem/MovableOnly
[Wed Mar 15 13:43:09 2023] 73247 pages reserved
[Wed Mar 15 13:43:09 2023] 16384 pages cma reserved
[Wed Mar 15 13:43:09 2023] SLUB: Unable to allocate memory on node -1, gfp=0x1000000(GFP_NOWAIT)
[Wed Mar 15 13:43:09 2023]   cache: iommu_iova, object size: 64, buffer size: 64, default order: 0, min order: 0
[Wed Mar 15 13:43:09 2023]   node 0: slabs: 59, objs: 3776, free: 0

I'm not a kernel expert, but it appears that the kernel failed to allocate memory (kmem_cache_alloc) during an attempt to read from an XFS filesystem, which involved calls in the dm_cache module - i.e. the kernel module which implements lvmcache.

The function which made the memory allocation was btracker_queue+0x38/0x174 [dm_cache]. From uname we know the kernel is version 4.14.305-227.531.amzn2.aarch64. I don't have an immediate index of this specific Amazon version, but the vanilla kernel of that function / version can be seen at https://elixir.bootlin.com/linux/v4.14.305/source/drivers/md/dm-cache-background-tracker.c#L168 - and where it calls kmem_cache_alloc():

int btracker_queue(struct background_tracker *b,
		   struct policy_work *work,
		   struct policy_work **pwork)
{
	struct bt_work *w;
 
	if (pwork)
		*pwork = NULL;
 
	if (max_work_reached(b))
		return -ENOMEM;
 
	w = kmem_cache_alloc(b->work_cache, GFP_NOWAIT);
	if (!w)
		return -ENOMEM;
...

i.e. if kmem_cache_alloc fails then btracker_queue returns -ENOMEM. In the call-stack above, btracker_queue() is called by __lookup() via queue_promotion():

static void queue_promotion(struct smq_policy *mq, dm_oblock_t oblock,
			    struct policy_work **workp)
{
...
	e = alloc_entry(&mq->cache_alloc);
	BUG_ON(!e);
	e->pending_work = true;
	work.op = POLICY_PROMOTE;
	work.oblock = oblock;
	work.cblock = infer_cblock(mq, e);
	btracker_queue(mq->bg_work, &work, workp);
}

Note that the last line which calls btracker_queue doesn't check the return value (ENOMEM in this case). It's not clear if this is a bug, or if failure to allocate memory for a cache entry is safe to ignore. I looked at the latest version of this code on GitHub, and did spot a patch was added to improve the error checking here for kernel 4.15 (https://github.com/torvalds/linux/commit/1e72a8e809f030bd4e318a49c497ee38e47e82c1).

Between kernel 4.14 (older Amazon Linux 2) and 5.10 (newer Amazon Linux 2) the following changes exist in the dm-cache-* files:

[:~/repos/linux/drivers/md] master(+399/-789) 3m34s ± git hist v4.14..v5.10 -- dm-cache-* --tag
* 35d2835d2ac4 2020-12-01 | Revert "dm cache: fix arm link errors with inline" [Nick Desaulniers] 
* d4a512edcc65 2020-09-29 | dm: use dm_table_get_device_name() where appropriate in targets [Mike Snitzer] 
* d16ff19e69ab 2020-09-02 | dm cache metadata: Avoid returning cmd->bm wild pointer on error [Ye Bin] 
* 21cf86614504 2020-07-08 | writeback: remove bdi->congested_fn [Christoph Hellwig] 
* ed00aabd5eb9 2020-07-01 | block: rename generic_make_request to submit_bio_noacct [Christoph Hellwig] 
* 636be4241bdd 2020-03-03 | dm: bump version of core and various targets [Mike Snitzer] 
* 7cdf6a0aae1c 2020-02-27 | dm cache: fix a crash due to incorrect work item cancelling [Mikulas Patocka] 
* 26b924b93c7b 2019-11-05 | dm cache: replace spin_lock_irqsave with spin_lock_irq [Mikulas Patocka] 
* 13bd677a472d 2019-10-17 | dm cache: fix bugs when a GFP_NOWAIT allocation fails [Mikulas Patocka] 
* e28adc3bf34e 2019-04-18 | dm cache metadata: Fix loading discard bitset [Nikos Tsironis] 
* de7180ff908b 2019-03-05 | dm cache: add support for discard passdown to the origin device [Mike Snitzer] 
* 61697a6abd24 2019-02-20 | dm: eliminate 'split_discard_bios' flag from DM target interface [Mike Snitzer] 
* 687cf4412a34 2018-12-07 | dm cache metadata: verify cache has blocks in blocks_are_clean_separate_dirty() [Mike Snitzer] 
* bab5d988841e 2018-10-16 | dm: remove unnecessary unlikely() around WARN_ON_ONCE() [Igor Stoppa] 
* c7cd55504a5b 2018-10-09 | dm cache: destroy migration_cache if cache target registration failed [Shenghui Wang] 
* 5d07384a666d 2018-10-04 | dm cache: fix resize crash if user doesn't reload cache table [Mike Snitzer] 
* 4561ffca88c5 2018-10-04 | dm cache metadata: ignore hints array being too small during resize [Joe Thornber] 
* 5b1fe7bec8a8 2018-08-09 | dm cache metadata: set dirty on all cache blocks after a crash [Ilya Dryomov] 
* fd2fa9541618 2018-08-07 | dm cache metadata: save in-core policy_hint_size to on-disk superblock [Mike Snitzer] 
* 7209049d40dc 2018-07-31 | dm kcopyd: return void from dm_kcopyd_copy() [Mike Snitzer] 
* af9313c32c0f 2018-07-27 | dm cache: only allow a single io_mode cache feature to be requested [John Pittman] 
*   b08fc5277aaa 2018-06-12 | Merge tag 'overflow-v4.18-rc1-part2' of git://git.kernel.org/pub/scm/linux/kernel/git/kees/linux [Linus Torvalds] 
|\  
| * fad953ce0b22 2018-06-12 | treewide: Use array_size() in vzalloc() [Kees Cook] 
| * 42bc47b35320 2018-06-12 | treewide: Use array_size() in vmalloc() [Kees Cook] 
* | 72d711c87688 2018-06-08 | dm: adjust structure members to improve alignment [Mike Snitzer] 
|/  
*   f459c34538f5 2018-06-04 | Merge tag 'for-4.18/block-20180603' of git://git.kernel.dk/linux-block [Linus Torvalds] 
|\  
| * 6f1c819c219f 2018-05-30 | dm: convert to bioset_init()/mempool_init() [Kent Overstreet] 
* | 280884fadc5b 2018-04-30 | dm cache background tracker: fix sparse warning [Mike Snitzer] 
|/  
* 1eb5fa849f2b 2018-04-03 | dm: allow targets to return output from messages they are sent [Mike Snitzer] 
* 7e6358d244e4 2017-12-04 | dm: fix various targets to dm_register_target after module __init resources created [[email protected]] 
* ef7afb365685 2017-11-10 | dm cache: lift common migration preparation code to alloc_migration() [Mike Snitzer] 
* ede6507d67e9 2017-11-10 | dm cache: remove usused deferred_cells member from struct cache [Joe Thornber] 
* 9768a10dd35c 2017-11-10 | dm cache policy smq: allocate cache blocks in order [Joe Thornber] 
* 8ee18ede7432 2017-11-10 | dm cache policy smq: change max background work from 10240 to 4096 blocks [Joe Thornber] 
* 64748b1645b8 2017-11-10 | dm cache background tracker: limit amount of background work that may be issued at once [Joe Thornber] 
* deb71918ae29 2017-11-10 | dm cache policy smq: take origin idle status into account when queuing writebacks [Joe Thornber] 
* 1e72a8e809f0 2017-11-10 | dm cache policy smq: handle races with queuing background_work [Joe Thornber] 
* 693b960ea891 2017-11-10 | dm cache: simplify get_per_bio_data() by removing data_size argument [Mike Snitzer] 
* 9958f1d9a04e 2017-11-10 | dm cache: remove all obsolete writethrough-specific code [Mike Snitzer] 
* 2df3bae9a654 2017-11-10 | dm cache: submit writethrough writes in parallel to origin and cache [Mike Snitzer] 
* 8e3c3827776f 2017-11-10 | dm cache: pass cache structure to mode functions [Mike Snitzer] 
* d1260e2a3f85 2017-11-10 | dm cache: fix race condition in the writeback mode overwrite_bio optimisation [Joe Thornber] 
* 6bdd079610d3 2017-10-24 | dm cache: convert dm_cache_metadata.ref_count from atomic_t to refcount_t [Elena Reshetova]