Snowball board freeze issue is observed while running a simple kernel module which does 'vmalloc' and 'vfree' in a loop.
This freeze is caught while running the powertop which does mmap and munmap of perf events (achieved using vmalloc and vfree). To debug and reproduce issue, simple kernel module is written.
Test kernel module source file is attached.
void vm_test(int count)
{
int i;
void* buf;
for(i=0; i<count; i++)
{
printk(KERN_EMERG "Iteration(%d)", i);
buf = vmalloc_user((nr_pages * PAGE_SIZE));
if(!buf){
printk(KERN_EMERG "Failed to allocate memory");
return;
}
printk("%s buf:0x%08x\n",__FUNCTION__,(unsigned int)buf);
vfree(buf);
}
printk(KERN_EMERG "Successfully run the test\n");
}
Output log:
---------------
root@linaro-ubuntu-desktop:~/mmap_test# insmod vm.ko
[27455.185516] vm: module license 'unspecified' taints kernel.
[27455.191406] Disabling lock debugging due to kernel taint
[27455.199035] loaded vmalloc module
[27455.203155] Iteration(0)vm_test buf:0xf6174000
[27455.213043] Iteration(1)vm_test buf:0xf6504000
[27455.219055] Iteration(2)vm_test buf:0xf6588000
[27455.225463] Iteration(3)vm_test buf:0xf660c000
[27455.230926] Iteration(4)vm_test buf:0xf6690000
[27455.236206] Iteration(5)vm_test buf:0xf6714000
[27455.241699] Iteration(6)vm_test buf:0xf6798000
[27455.246978] Iteration(7)vm_test buf:0xf681c000
[27455.252380] Iteration(8)vm_test buf:0xf68a0000
[27455.257629] Iteration(9)vm_test buf:0xf6924000
[27455.263183] Iteration(10)vm_test buf:0xf69a8000
[27455.268524] Iteration(11)vm_test buf:0xf6a2c000
[27455.274047] Iteration(12)vm_test buf:0xf6ab0000
[27455.279357] Iteration(13)vm_test buf:0xf6b34000
[27455.284912] Iteration(14)vm_test buf:0xf6bb8000
[27455.290344] Iteration(15)vm_test buf:0xf6c3c000
[27455.295684] Iteration(16)vm_test buf:0xf6cc0000
[27455.301177] Iteration(17)vm_test buf:0xf6d44000
[27455.306518] Iteration(18)vm_test buf:0xf6dc8000
[27455.311920] Iteration(19)vm_test buf:0xf6e4c000
[27455.317260] Iteration(20)vm_test buf:0xf6ed0000
[27455.322814] Iteration(21)vm_test buf:0xf6f54000
[27455.328124] Iteration(22)vm_test buf:0xf6fd8000
[27455.333618] Iteration(23)vm_test buf:0xf705c000
[27455.338928] Iteration(24)vm_test buf:0xf70e0000
[27455.344451] Iteration(25)vm_test buf:0xf7164000
[27455.349761] Iteration(26)vm_test buf:0xf71e8000
[27455.355224] Iteration(27)vm_test buf:0xf726c000
[27455.360687] Iteration(28)vm_test buf:0xf72f0000
[27455.366027] Iteration(29)vm_test buf:0xf7374000
[27455.371398] Iteration(30)vm_test buf:0xf73f8000
[27455.376739] Iteration(31)vm_test buf:0xf747c000
[27455.382232] Iteration(32)vm_test buf:0xf7500000
[27455.387542] Iteration(33)vm_test buf:0xf7584000
[27455.393005] Iteration(34)vm_test buf:0xf7608000
[27455.398315] Iteration(35)vm_test buf:0xf768c000
[27455.403839] Iteration(36)vm_test buf:0xf7710000
[27455.409149] Iteration(37)vm_test buf:0xf7794000
[27455.414611] Iteration(38)vm_test buf:0xf7818000
[27455.420135] Iteration(39)vm_test buf:0xf789c000
[27455.425201] Iteration(40)vm_test buf:0xf7920000
[27455.430267] Iteration(41)vm_test buf:0xf79a4000
[27455.435333] Iteration(42)vm_test buf:0xf7a28000
[27455.440490] Iteration(43)vm_test buf:0xf7aac000
[27455.445526] Iteration(44)vm_test buf:0xf7b30000
[27455.450592] Iteration(45)vm_test buf:0xf7bb4000
[27455.455657] Iteration(46)vm_test buf:0xf7c38000
[27455.460815] Iteration(47)vm_test buf:0xf7cbc000
[27455.465850] Iteration(48)vm_test buf:0xf7d40000
[27455.470916] Iteration(49)vm_test buf:0xf7dc4000
[27455.475952] Iteration(50)vm_test buf:0xf7e48000
[27455.481109] Iteration(51)vm_test buf:0xf7ecc000
[27455.486145] Iteration(52)vm_test buf:0xf7f50000
[27455.491241] Iteration(53)
[27455.494110] ------------[ cut here ]------------
[27455.498901] WARNING: at /home/rvenka00/penguin/linaro/pmwg/kernel/snowball/ubuntu/mm/vmalloc.c:106 vmap_page_range_noflush+0x188/0x1d4()
[27455.511291] Modules linked in: vm(P+) g_multi
[27455.515716] [<c0016b10>] (unwind_backtrace+0x0/0x144) from [<c05bfa60>] (dump_stack+0x20/0x24)
[27455.524444] [<c05bfa60>] (dump_stack+0x20/0x24) from [<c002b440>] (warn_slowpath_common+0x5c/0x74)
[27455.533477] [<c002b440>] (warn_slowpath_common+0x5c/0x74) from [<c002b484>] (warn_slowpath_null+0x2c/0x34)
[27455.543243] [<c002b484>] (warn_slowpath_null+0x2c/0x34) from [<c00e982c>] (vmap_page_range_noflush+0x188/0x1d4)
[27455.553375] [<c00e982c>] (vmap_page_range_noflush+0x188/0x1d4) from [<c00e9e70>] (map_vm_area+0x3c/0x8c)
[27455.562957] [<c00e9e70>] (map_vm_area+0x3c/0x8c) from [<c00ea9c8>] (__vmalloc_node_range+0x10c/0x1e8)
[27455.572235] [<c00ea9c8>] (__vmalloc_node_range+0x10c/0x1e8) from [<c00eaaf0>] (__vmalloc_node+0x4c/0x54)
[27455.581787] [<c00eaaf0>] (__vmalloc_node+0x4c/0x54) from [<c00eacf8>] (vmalloc_user+0x3c/0x64)
[27455.590454] [<c00eacf8>] (vmalloc_user+0x3c/0x64) from [<bf01e050>] (vm_test+0x50/0x90 [vm])
[27455.598907] [<bf01e050>] (vm_test+0x50/0x90 [vm]) from [<bf020020>] (vm_init+0x20/0x30 [vm])
[27455.607452] [<bf020020>] (vm_init+0x20/0x30 [vm]) from [<c000872c>] (do_one_initcall+0x128/0x190)
[27455.616394] [<c000872c>] (do_one_initcall+0x128/0x190) from [<c007f1bc>] (sys_init_module+0x112c/0x1dfc)
[27455.625976] [<c007f1bc>] (sys_init_module+0x112c/0x1dfc) from [<c000fa40>] (ret_fast_syscall+0x0/0x30)
[27455.635314] ---[ end trace f699ab9e0736ea39 ]---
[27455.640014] vmalloc: allocation failure, allocated 524288 of 528384 bytes
[27455.646789] insmod: page allocation failure: order:0, mode:0x80d2
[27455.652954] [<c0016b10>] (unwind_backtrace+0x0/0x144) from [<c05bfa60>] (dump_stack+0x20/0x24)
[27455.661651] [<c05bfa60>] (dump_stack+0x20/0x24) from [<c00c2e04>] (warn_alloc_failed+0xd0/0x128)
[27455.670562] [<c00c2e04>] (warn_alloc_failed+0xd0/0x128) from [<c00eaa64>] (__vmalloc_node_range+0x1a8/0x1e8)
[27455.680480] [<c00eaa64>] (__vmalloc_node_range+0x1a8/0x1e8) from [<c00eaaf0>] (__vmalloc_node+0x4c/0x54)
[27455.690002] [<c00eaaf0>] (__vmalloc_node+0x4c/0x54) from [<c00eacf8>] (vmalloc_user+0x3c/0x64)
[27455.698638] [<c00eacf8>] (vmalloc_user+0x3c/0x64) from [<bf01e050>] (vm_test+0x50/0x90 [vm])
[27455.707153] [<bf01e050>] (vm_test+0x50/0x90 [vm]) from [<bf020020>] (vm_init+0x20/0x30 [vm])
[27455.715667] [<bf020020>] (vm_init+0x20/0x30 [vm]) from [<c000872c>] (do_one_initcall+0x128/0x190)
[27455.724639] [<c000872c>] (do_one_initcall+0x128/0x190) from [<c007f1bc>] (sys_init_module+0x112c/0x1dfc)
[27455.734161] [<c007f1bc>] (sys_init_module+0x112c/0x1dfc) from [<c000fa40>] (ret_fast_syscall+0x0/0x30)
[27455.743560] Mem-info:
[27455.745819] Normal per-cpu:
[27455.748626] CPU 0: hi: 186, btch: 31 usd: 176
[27455.753448] CPU 1: hi: 186, btch: 31 usd: 16
[27455.758239] HighMem per-cpu:
[27455.761199] CPU 0: hi: 42, btch: 7 usd: 37
[27455.765991] CPU 1: hi: 42, btch: 7 usd: 34
[27455.770812] active_anon:10392 inactive_anon:139 isolated_anon:0
[27455.770812] active_file:61329 inactive_file:38480 isolated_file:0
[27455.770843] unevictable:0 dirty:1 writeback:0 unstable:0
[27455.770843] free:70260 slab_reclaimable:9105 slab_unreclaimable:1545
[27455.770843] mapped:2468 shmem:154 pagetables:187 bounce:0
[27455.800323] Normal free:280344kB min:8192kB low:10240kB high:12288kB active_anon:4792kB inactive_anon:8kB active_file:155392kB inactive_file:112240kB unevictable:0kB isolated(ano
n):0kB isolated(file):0kB present:632112kB mlocked:0kB dirty:4kB writeback:0kB mapped:72kB shmem:24kB slab_reclaimable:36420kB slab_unreclaimable:6180kB kernel_stack:1296kB pagetabl
es:748kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
[27455.839660] lowmem_reserve[]: 0 1317 1317
[27455.843780] HighMem free:696kB min:164kB low:708kB high:1256kB active_anon:36772kB inactive_anon:544kB active_file:89924kB inactive_file:41680kB unevictable:0kB isolated(anon):0k
B isolated(file):0kB present:168656kB mlocked:0kB dirty:0kB writeback:0kB mapped:9784kB shmem:588kB slab_reclaimable:0kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:0kB unsta
ble:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
[27455.881896] lowmem_reserve[]: 0 0 0
[27455.885406] Normal: 178*4kB 786*8kB 356*16kB 820*32kB 538*64kB 221*128kB 72*256kB 61*512kB 16*1024kB 9*2048kB 5*4096kB 9*8192kB = 280344kB
[27455.897949] HighMem: 30*4kB 18*8kB 15*16kB 2*32kB 2*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB 0*8192kB = 696kB
[27455.909301] 99977 total pagecache pages
[27455.925933] 202240 pages of RAM
[27455.929077] 70881 free pages
[27455.932067] 5315 reserved pages
[27455.935211] 10643 slab pages
[27455.938079] 59348 pages shared
[27455.941284] 0 pages swap cached
[27455.944519] Failed to allocate memory
Analysis:
When we run the test for first time, we are not getting any crash/errors.
But when we run the test the second time (always at second time) we get a crash (100 percent reproducible).
Debugging the issue, revealed, that, We always, get an invalid page table map failure, for certain virtual address. And allocation of pages happens in this virtual address range, only when we run the test for the second time.
Debug-log-snippet:
[ 220.349884] SIZE:528384 VSTART:3967811584 VEND:4278190080 FVC-in START:4160749568 END:4161277952
[ 220.360321] Nr_pages: 128 array_size: 512"
The above log snippet show, the virtual address from START:4160749568 END:4161277952, is choosen by the vmalloc to create 128 pages.(as per the userspace program)
It is at this address range , the invalid pte entry exists.
[ 156.906188] pte:3963600896:0, addr:4160749568
[ 156.911895] pte:3963600900:0, addr:4160753664
[ 156.916290] pte:3963600904:0, addr:4160757760
[ 156.920684] pte:3963600908:0, addr:4160761856
[ 156.925018] pte:3963600912:0, addr:4160765952
[ 156.929443] pte:3963600916:0, addr:4160770048
[ 156.933807] pte:3963600920:0, addr:4160774144
[ 156.938140] pte:3963600924:
Here, the pte value becomes 2147513939, instead of valid pte value of zero. For the virtual address 4160778240.
It is at this address mapping we always get an invalid pte error. (!pte_none(*pte))
Although the VMALLOC START AND END is in the range of 3967811584 to 4278190080 [ 0xec800000 - 0xff000000 ( 296 MB)], certain virtual address which exists with in this range, seems to have invalid pte entry.
Analysis is in progress.
Comments are welcome.