Snowball: Board freeze with vmalloc and vfree

[Rajagopal Venkat]

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

[Ramesh Chandrasekaran (ramesh-chandrasekaran)]

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:2147513939, addr:4160778240

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.

[Ramesh Chandrasekaran (ramesh-chandrasekaran)]

Analysis update:

It seems, the virtual address range issued by the alloc_vmap_area for the 128 pages, seems to be already mapped by iotable.

/proc/vmallocinfo revealed.

0xf8007000-0xf8008000 4096 iotable_init+0x0/0xbc phys=80007000 ioremap
0xf800e000-0xf800f000 4096 iotable_init+0x0/0xbc phys=8000e000 ioremap
0xf800f000-0xf8010000 4096 iotable_init+0x0/0xbc phys=8000f000 ioremap

and /proc/iomem revealed,

80007000-80007fff : uart2
  80007000-80007fff : uart-pl011
8000e000-8000e07f : gpio.2
  8000e000-8000e07f : gpio.2
8000e080-8000e0ff : gpio.3
  8000e080-8000e0ff : gpio.3
8000e100-8000e17f : gpio.4
  8000e100-8000e17f : gpio.4
8000e180-8000e1ff : gpio.5
  8000e180-8000e1ff : gpio.5
80118000-80118fff : sdi1
  80118000-80118fff : mmci-pl18x
80128000-80128fff : nmk-i2c.2
  80128000-80128fff : nmk-i2cI/O region

So, here the virtual address "4160778240 (0xf8007000)" whose pte entry is failing, in vmalloc_user function, seems
to be already, mapped by iotable_init for uart2, gpio.2 peripherals.
So, the vmalloc algorithm, gives a virtual address range which seems to be already mapped by iotable_init. This seems to be bit odd.

Analysis in progress.
Comments are welcome

[Ramesh Chandrasekaran (ramesh-chandrasekaran)]

Cause of the bug:
The flags for the vmap_area is not set properly while initializing the vmlist, vmalloc_init() in mm/vmallo.c This leads, to freeing of statically mapped memory(before the mapping is removed), by ioremap because tmp->flags has VM_IOREMAP set.
This makes vmalloc/ioremap calls to fail, because it is allocating one of the freed virtual address ranges that aren't unmapped.
This is the scenario, that is reproduced in the bug's test case, where we get an address range, which is already static-mapped by the Iotable.

The fix is available in the latest kernel, as well as in the internal branch, which sets the flags correctly.

Fix in latest kernel: commit-msg: fix faulty initialization in vmalloc_init()

This fixed the bug.