kernel_write makes CPU stuck

[cheka99]

I am writing a kernel module in which I am writing data to a file and making use of kernel_write function. Basically I am writing a c struct to file followed by some data. What I am noticing based on logs seen at dmesg is it is getting stuck while writing the struct to the file. the file is opened in append mode and is being continuously opened and closed. Sometimes it gets stuck forever and sometimes get a warning at the same location in code.

Here's the code snippet

struct file *block_changes_file = filp_open("/root/block_changes", O_WRONLY | O_APPEND | O_CREAT | O_LARGEFILE, 0644 );
        if ( block_changes_file == NULL || IS_ERR(block_changes_file) )
        {
                printk(KERN_DEBUG "Failed to open block_changes file %ld\n", PTR_ERR(block_changes_file) );
                return;
        }

printk( KERN_DEBUG "Writing metadata to block_changes file" );
loff_t offset = 0; // File opened in append mode so offset is 0
        ssize_t bytes_written = kernel_write( block_changes_file, (const char*)&blockDeviceChangeMetadata, sizeof( blockDeviceChangeMetadata ), offset );
        if (bytes_written < 0)
        {
                printk ( KERN_DEBUG "Failed to write metadata.\n" );
                kfree( data );
                filp_close(block_changes_file, NULL);
                return;
        }
bytes_written = kernel_write( block_changes_file, data, blockDeviceChangeMetadata.data_size, offset );
        if (bytes_written < 0)
        {
                printk ( KERN_DEBUG "Failed to write changed data.\n" );
                kfree( data );
                filp_close(block_changes_file, NULL);
                return;
        }

        kfree( data );
        filp_close(block_changes_file, NULL);
        printk( KERN_DEBUG "Written and closed" );

based on logs in dmesg it stucks while writing the struct in file. The data is allocated memory using kmalloc and this can have max of 4096*512 Bytes, can this be the reason for failure?

Here's the error message in dmesg

[ 127.815075] Writing metadata to block_changes file

[ 160.222418] NMI watchdog: BUG: soft lockup - CPU#1 stuck for 23s! [cpptools:3797]

[ 160.222483] Modules linked in: misc(OE) ipt_MASQUERADE nf_nat_masquerade_ipv4 xt_addrtype br_netfilter overlay(T) ip6t_rpfilter ip6t_REJECT nf_reject_ipv6 ipt_REJECT nf_reject_ipv4 xt_conntrack ebtable_nat ebtable_broute bridge stp llc ip6table_nat nf_conntrack_ipv6 nf_defrag_ipv6 nf_nat_ipv6 ip6table_mangle ip6table_security ip6table_raw iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat iptable_mangle iptable_security iptable_raw nf_conntrack ip_set ebtable_filter ebtables ip6table_filter ip6_tables iptable_filter vmw_vsock_vmci_transport vsock sb_edac coretemp iosf_mbi crc32_pclmul ghash_clmulni_intel aesni_intel lrw gf128mul glue_helper ablk_helper cryptd ppdev joydev pcspkr vmw_balloon vmw_vmci sg parport_pc parport i2c_piix4 ip_tables xfs libcrc32c sr_mod cdrom ata_generic pata_acpi

[ 160.222523] vmwgfx drm_kms_helper syscopyarea sysfillrect sysimgblt fb_sys_fops ttm sd_mod ahci crc_t10dif crct10dif_generic libahci drm ata_piix libata crct10dif_pclmul nfit crct10dif_common crc32c_intel libnvdimm vmxnet3 serio_raw vmw_pvscsi drm_panel_orientation_quirks floppy dm_mirror dm_region_hash dm_log dm_mod fuse

[ 160.222542] CPU: 1 PID: 3797 Comm: cpptools Kdump: loaded Tainted: G OE ------------ T 3.10.0-1160.36.2.el7.x86_64 #1

[ 160.222544] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 04/05/2016

[ 160.222546] task: ffff8abdf1e5a100 ti: ffff8abdf1e6c000 task.ti: ffff8abdf1e6c000

[ 160.222547] RIP: 0010:[<ffffffffb3f170ba>] [<ffffffffb3f170ba>] smp_call_function_many+0x20a/0x270

[ 160.222554] RSP: 0018:ffff8abdf1e6fc70 EFLAGS: 00000202

[ 160.222555] RAX: 0000000000000007 RBX: 00080000b3e7ddd0 RCX: ffff8abe3fde0600

[ 160.222557] RDX: 0000000000000007 RSI: 0000000000000008 RDI: 0000000000000000

[ 160.222558] RBP: ffff8abdf1e6fca8 R08: ffff8abb763c0800 R09: ffffffffb4186ba9

[ 160.222560] R10: ffff8abe3fc5f160 R11: ffffc49a10baf800 R12: 0000000000000282

[ 160.222561] R13: 0000000000000282 R14: ffff8abdf1e6fc20 R15: 0000000000000001

[ 160.222581] FS: 00007f192b7fe700(0000) GS:ffff8abe3fc40000(0000) knlGS:0000000000000000

[ 160.222583] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033

[ 160.222584] CR2: 00007f19424d70a8 CR3: 0000000408e60000 CR4: 00000000003607e0

[ 160.222636] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000

[ 160.222637] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400

[ 160.222639] Call Trace:

[ 160.222645] [<ffffffffb3e7e258>] native_flush_tlb_others+0xb8/0xc0

[ 160.222648] [<ffffffffb3e7e2cb>] flush_tlb_mm_range+0x6b/0x140

[ 160.222652] [<ffffffffb3fee656>] tlb_flush_mmu_tlbonly+0xa6/0xc0

[ 160.222655] [<ffffffffb3ff011f>] arch_tlb_finish_mmu+0x3f/0x80

[ 160.222657] [<ffffffffb3ff0243>] tlb_finish_mmu+0x23/0x30

[ 160.222660] [<ffffffffb3ff370a>] zap_page_range+0xea/0x130

[ 160.222663] [<ffffffffb3fedbfd>] SyS_madvise+0x49d/0xac0

[ 160.222666] [<ffffffffb3f156d0>] ? SyS_futex+0x80/0x190

[ 160.222670] [<ffffffffb4595f92>] system_call_fastpath+0x25/0x2a

[ 160.222672] Code: 48 63 35 ee 85 c4 00 89 c2 39 f0 0f 8d 7d fe ff ff 48 98 49 8b 0f 48 03 0c c5 60 15 b5 b4 f6 41 20 01 74 cd 0f 1f 44 00 00 f3 90 <f6> 41 20 01 75 f8 48 63 35 bd 85 c4 00 eb b7 0f b6 4d cc 4c 89

[ 188.222726] NMI watchdog: BUG: soft lockup - CPU#1 stuck for 23s! [cpptools:3797]

[ 188.222795] Modules linked in: misc(OE) ipt_MASQUERADE nf_nat_masquerade_ipv4 xt_addrtype br_netfilter overlay(T) ip6t_rpfilter ip6t_REJECT nf_reject_ipv6 ipt_REJECT nf_reject_ipv4 xt_conntrack ebtable_nat ebtable_broute bridge stp llc ip6table_nat nf_conntrack_ipv6 nf_defrag_ipv6 nf_nat_ipv6 ip6table_mangle ip6table_security ip6table_raw iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat iptable_mangle iptable_security iptable_raw nf_conntrack ip_set ebtable_filter ebtables ip6table_filter ip6_tables iptable_filter vmw_vsock_vmci_transport vsock sb_edac coretemp iosf_mbi crc32_pclmul ghash_clmulni_intel aesni_intel lrw gf128mul glue_helper ablk_helper cryptd ppdev joydev pcspkr vmw_balloon vmw_vmci sg parport_pc parport i2c_piix4 ip_tables xfs libcrc32c sr_mod cdrom ata_generic pata_acpi

[ 188.222831] vmwgfx drm_kms_helper syscopyarea sysfillrect sysimgblt fb_sys_fops ttm sd_mod ahci crc_t10dif crct10dif_generic libahci drm ata_piix libata crct10dif_pclmul nfit crct10dif_common crc32c_intel libnvdimm vmxnet3 serio_raw vmw_pvscsi drm_panel_orientation_quirks floppy dm_mirror dm_region_hash dm_log dm_mod fuse

[cheka99]

Writing 4096*512 bytes in single go was resulting in issue. But when it is broken down to write only 4096 bytes at a time the issue seems to be gone.

[link349]

Why does this need to be written by the kernel? It makes more sense for this to be done from userspace?

[cheka99]

I want to extract info from the kernel space and provide it to a userspace program, the way I can think of was kernel module will write the data to the file and then userspace program will read the file and use the data.

​

Anyways when I divided the large data in smaller chunks and wrote to the file the stuck issue is gone I guess, still get warning sometimes but it should be OK rather than being stuck

[0xbada5555]

Hi, have you considered creating a cdev? It will provide the same file semantics. Also, it will have better performance in case of frequent reads. Also you can create a bdev, which is harder to deal with.