From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from mail-lf0-f46.google.com ([209.85.215.46]:48791 "EHLO mail-lf0-f46.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S932334AbdJZTBg (ORCPT ); Thu, 26 Oct 2017 15:01:36 -0400 Received: by mail-lf0-f46.google.com with SMTP id a69so4887374lfe.5 for ; Thu, 26 Oct 2017 12:01:36 -0700 (PDT) MIME-Version: 1.0 From: Guillaume Bouchard Date: Thu, 26 Oct 2017 21:01:33 +0200 Message-ID: Subject: brtfs BUG and erroneous IO To: "linux-btrfs@vger.kernel.org" Content-Type: text/plain; charset="UTF-8" Sender: linux-btrfs-owner@vger.kernel.org List-ID: Hi. I have a btrfs filesystem on linux 4.13.9 mounted with this options: /dev/sda3 on / type btrfs (rw,relatime,ssd,space_cache,subvolid=5,subvol=/) /dev/sda3 on /nix/store type btrfs (ro,relatime,ssd,space_cache,subvolid=5,subvol=/nix/store) (on nixos-17.09). I had the same issues with linux 4.9, the default kernel of my distribution. I have a "BUG" wich appears in /dev/kmsg, short version (full version at the end of the email): $ cat /dev/kmsg | grep BUG 2,1019,15265010400,-;kernel BUG at /tmp/nix-build-linux-4.13.9.drv-0/linux-4.13.9/fs/btrfs/inode.c:5815! 1,1065,15265079807,-;BUG: unable to handle kernel paging request at fffffffeff840020 This "BUG" appears when I try to "du -sh ." in my /home, it immediately results in a segmentation fault. This fails reliably. However if I'm running again du -sh ., I have different possible behaviors, including the correct one, a total freeze of the system for an undefined amount of time or a freeze of the command. When the command freeze, there is no solution to kill it. It sometimes appears in ps as Zombie or as uninterruptible sleep. When it is zombie, it is impossible to reap it (even init cannot do it). I observed the same issue with many other command, with similar behaviors. "cd", "rm", "chromium", ... It usually ends with dozens of "defunct" processes, a system progressively blocked and a reboot. Note that it does not appears with a simple "find" in my home directory, so I suppose that it is only triggered by commands which are doing more than a simple directory listing. I think it happen on "cd" too because my shell is reading for VCS informations on the current directory. I also observed that some directory are triggering the issue when some others are not. If I "strace" the "du -sh ." command, the last lines before the segmentation fault are: fstatfs(8, {f_type=BTRFS_SUPER_MAGIC, f_bsize=4096, f_blocks=105154001, f_bfree=45472674, f_bavail=45061125, f_files=0, f_ffree=0, f_fsid={val=[73204674, 1138503007]}, f_namelen=255, f_frsize=4096, f_flags=ST_VALID|ST_RELATIME}) = 0 brk(0x1112000) = 0x1112000 sysinfo({uptime=1293, loads=[20192, 15904, 12416], totalram=33640140800, freeram=31046250496, sharedram=15400960, bufferram=2162688, totalswap=38654701568, freeswap=38654701568, procs=533, totalhigh=0, freehigh=0, mem_unit=1}) = 0 newfstatat(8, "60cadaa98932a732_0", ) = ? +++ killed by SIGSEGV +++ [1] 2387 segmentation fault strace du -sh so it faults inside a newfstatat, which confirms my hypothesis that it is more than just listing the directory content. Someone (sorry, I forgot name) on irc suggested that I may have a corrupted data or metadata and that it may be possible to fix it using the usual process (fsck and perhaps a scrub / defrag / trim of the disk). However he also says that corrupted data should fail more gracefully and that I'll help the development of btrfs by reporting the bug before any attempt to fix the corruption. Thank you Now the FULL LOG, starting from the first BUG event. 4,964,55824786,-;------------[ cut here ]------------ 2,965,55824789,-;kernel BUG at /tmp/nix-build-linux-4.13.9.drv-0/linux-4.13.9/fs/btrfs/inode.c:5815! 4,966,55824794,-;invalid opcode: 0000 [#1] SMP 4,967,55824795,-;Modules linked in: fuse af_packet msr snd_hda_codec_hdmi snd_hda_codec_realtek snd_hda_codec_generic iptable_nat nf_nat_ipv4 nf_nat nf_conntrack_ipv6 nf_defrag_ipv6 nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack nf_conntrack libcrc32c ip6t_rpfilter ipt_rpfilter ip6table_raw iptable_raw xt_pkttype nf_log_ipv6 nf_log_ipv4 nf_log_common xt_LOG xt_tcpudp ip6table_filter ip6_tables edac_core iptable_filter x86_pkg_temp_thermal intel_powerclamp coretemp crct10dif_pclmul crc32_pclmul ghash_clmulni_intel pcbc uvcvideo snd_usb_audio videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 snd_hda_intel videobuf2_core mousedev aesni_intel snd_usbmidi_lib snd_hda_codec nvidia_drm(PO) snd_rawmidi drm_kms_helper aes_x86_64 input_leds uas joydev led_class crypto_simd videodev snd_seq_device evdev usb_storage 4,968,55824820,c; glue_helper usblp snd_hda_core iTCO_wdt cryptd efi_pstore mxm_wmi mac_hid e1000e drm snd_hwdep pstore tpm_tis snd_pcm mei_me agpgart snd_timer fb_sys_fops intel_cstate tpm_tis_core syscopyarea snd sysfillrect intel_uncore sysimgblt ptp intel_rapl_perf mei soundcore efivars pps_core lpc_ich tpm shpchp nvidia_modeset(PO) nvidia_uvm(PO) nvidia(PO) wmi i2c_core arc4 ecb ppp_mppe ppp_generic slhc button atkbd libps2 loop cpufreq_ondemand vboxnetflt(O) vboxnetadp(O) vboxdrv(O) kvm_intel kvm irqbypass efivarfs ip_tables x_tables ipv6 crc_ccitt autofs4 hid_generic usbhid hid sd_mod ahci xhci_pci libahci xhci_hcd ehci_pci ehci_hcd libata usbcore scsi_mod usb_common serio rtc_cmos dm_mod dax crc32c_generic crc32c_intel btrfs xor raid6_pq 4,969,55824851,-;CPU: 7 PID: 3264 Comm: du Tainted: P O 4.13.9 #1-NixOS 4,970,55824852,-;Hardware name: MSI MS-7885/X99A RAIDER (MS-7885), BIOS P.50 07/19/2016 4,971,55824854,-;task: ffff98425bc69b80 task.stack: ffffaa9589564000 4,972,55824873,-;RIP: 0010:btrfs_lookup_dentry+0x384/0x490 [btrfs] 4,973,55824874,-;RSP: 0018:ffffaa9589567b40 EFLAGS: 00010293 4,974,55824876,-;RAX: 0000000000000081 RBX: ffff9842330cd6e8 RCX: 0000000000003d7b 4,975,55824877,-;RDX: 0000000000003d7a RSI: ffff98435f3e3ae0 RDI: ffffe6b3a25974c0 4,976,55824879,-;RBP: ffffaa9589567bb8 R08: 0000000000023ae0 R09: ffffffffc028aa76 4,977,55824880,-;R10: 0000000000001000 R11: 0000000000000003 R12: ffff984235b7cd80 4,978,55824881,-;R13: ffff9843580bc000 R14: ffff9843565d3d90 R15: 0000000000003fd0 4,979,55824883,-;FS: 00007fbcf3bc8700(0000) GS:ffff98435f3c0000(0000) knlGS:0000000000000000 4,980,55824884,-;CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 4,981,55824885,-;CR2: 0000000001d2c000 CR3: 00000007deb98000 CR4: 00000000003406e0 4,982,55824886,-;DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 4,983,55824888,-;DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400 4,984,55824888,-;Call Trace: 4,985,55824899,-; btrfs_lookup+0x12/0x40 [btrfs] 4,986,55824903,-; lookup_slow+0x96/0x140 4,987,55824905,-; walk_component+0x19a/0x330 4,988,55824907,-; ? path_init+0x174/0x300 4,989,55824909,-; path_lookupat+0x64/0x1f0 4,990,55824912,-; filename_lookup+0xa9/0x170 4,991,55824915,-; ? mem_cgroup_commit_charge+0x82/0x530 4,992,55824918,-; ? kmem_cache_alloc+0x146/0x1a0 4,993,55824920,-; ? getname_flags+0x4f/0x1f0 4,994,55824922,-; user_path_at_empty+0x36/0x40 4,995,55824924,-; ? user_path_at_empty+0x36/0x40 4,996,55824926,-; vfs_statx+0x67/0xc0 4,997,55824928,-; SYSC_newfstatat+0x26/0x50 4,998,55824930,-; ? __do_page_fault+0x25e/0x4c0 4,999,55824932,-; SyS_newfstatat+0xe/0x10 4,1000,55824935,-; entry_SYSCALL_64_fastpath+0x1a/0xa5 4,1001,55824937,-;RIP: 0033:0x7fbcf2eb4aea 4,1002,55824938,-;RSP: 002b:00007ffeadbc6da8 EFLAGS: 00000246 ORIG_RAX: 0000000000000106 4,1003,55824940,-;RAX: ffffffffffffffda RBX: 0000000000001897 RCX: 00007fbcf2eb4aea 4,1004,55824941,-;RDX: 0000000001942b88 RSI: 0000000001942c18 RDI: 0000000000000008 4,1005,55824942,-;RBP: 0000000000000044 R08: 0000000000000100 R09: 0000000000018981 4,1006,55824943,-;R10: 0000000000000100 R11: 0000000000000246 R12: 0000000001d13548 4,1007,55824944,-;R13: 0000000001d13768 R14: 00000000004c2cf0 R15: 0000000001d2c000 4,1008,55824946,-;Code: b8 fe ff ff ff e9 0f fe ff ff 48 8b 53 40 e9 cb fe ff ff 48 8b 7b 28 48 8b 55 a0 48 8d 75 ae 31 c9 e8 01 f1 ff ff e9 38 fe ff ff <0f> 0b 48 8b 7b 28 e8 a1 a4 55 c8 48 85 c0 48 89 c3 0f 84 d3 00 1,1009,55824976,-;RIP: btrfs_lookup_dentry+0x384/0x490 [btrfs] RSP: ffffaa9589567b40 4,1010,55824978,-;---[ end trace 2f2cf349eabc236c ]--- 1,1011,55891936,-;BUG: unable to handle kernel paging request at fffffffeff800030 1,1012,55891941,-;IP: 0xfffffffeee3ae1fd 4,1013,55891942,-;PGD 5ab40c067 4,1014,55891942,-;P4D 5ab40c067 4,1015,55891943,-;PUD 0 4,1016,55891943,-; 4,1017,55891945,-;Oops: 0000 [#2] SMP 4,1018,55891946,-;Modules linked in: fuse af_packet msr snd_hda_codec_hdmi snd_hda_codec_realtek snd_hda_codec_generic iptable_nat nf_nat_ipv4 nf_nat nf_conntrack_ipv6 nf_defrag_ipv6 nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack nf_conntrack libcrc32c ip6t_rpfilter ipt_rpfilter ip6table_raw iptable_raw xt_pkttype nf_log_ipv6 nf_log_ipv4 nf_log_common xt_LOG xt_tcpudp ip6table_filter ip6_tables edac_core iptable_filter x86_pkg_temp_thermal intel_powerclamp coretemp crct10dif_pclmul crc32_pclmul ghash_clmulni_intel pcbc uvcvideo snd_usb_audio videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 snd_hda_intel videobuf2_core mousedev aesni_intel snd_usbmidi_lib snd_hda_codec nvidia_drm(PO) snd_rawmidi drm_kms_helper aes_x86_64 input_leds uas joydev led_class crypto_simd videodev snd_seq_device evdev usb_storage 4,1019,55891969,c; glue_helper usblp snd_hda_core iTCO_wdt cryptd efi_pstore mxm_wmi mac_hid e1000e drm snd_hwdep pstore tpm_tis snd_pcm mei_me agpgart snd_timer fb_sys_fops intel_cstate tpm_tis_core syscopyarea snd sysfillrect intel_uncore sysimgblt ptp intel_rapl_perf mei soundcore efivars pps_core lpc_ich tpm shpchp nvidia_modeset(PO) nvidia_uvm(PO) nvidia(PO) wmi i2c_core arc4 ecb ppp_mppe ppp_generic slhc button atkbd libps2 loop cpufreq_ondemand vboxnetflt(O) vboxnetadp(O) vboxdrv(O) kvm_intel kvm irqbypass efivarfs ip_tables x_tables ipv6 crc_ccitt autofs4 hid_generic usbhid hid sd_mod ahci xhci_pci libahci xhci_hcd ehci_pci ehci_hcd libata usbcore scsi_mod usb_common serio rtc_cmos dm_mod dax crc32c_generic crc32c_intel btrfs xor raid6_pq 4,1020,55892001,-;CPU: 7 PID: 102 Comm: kworker/7:1 Tainted: P D O 4.13.9 #1-NixOS 4,1021,55892001,-;Hardware name: MSI MS-7885/X99A RAIDER (MS-7885), BIOS P.50 07/19/2016 4,1022,55892004,-;Workqueue: events efivar_update_sysfs_entries [efivars] 4,1023,55892005,-;task: ffff984359680000 task.stack: ffffaa9583f04000 4,1024,55892006,-;RIP: 0010:0xfffffffeee3ae1fd 4,1025,55892007,-;RSP: 0018:ffffaa9583f07b08 EFLAGS: 00010246 4,1026,55892008,-;RAX: 0000000000000007 RBX: ffffaa9583f07c18 RCX: fffffffeff84005f 4,1027,55892009,-;RDX: 0000000000000020 RSI: fffffffeff840000 RDI: fffffffeee3b2698 4,1028,55892010,-;RBP: ffff9843564c5800 R08: 0000000000000007 R09: 0000000000000000 4,1029,55892010,-;R10: fffffffeff800000 R11: 0000000000040000 R12: ffffaa9583f07db8 4,1030,55892011,-;R13: 0000000000000040 R14: 8000000000000015 R15: 0000000000000282 4,1031,55892012,-;FS: 0000000000000000(0000) GS:ffff98435f3c0000(0000) knlGS:0000000000000000 4,1032,55892013,-;CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 4,1033,55892014,-;CR2: fffffffeff800030 CR3: 00000005ab409000 CR4: 00000000003406e0 4,1034,55892015,-;DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 4,1035,55892015,-;DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400 4,1036,55892016,-;Call Trace: 4,1037,55892020,-; ? find_busiest_group+0x10b/0x960 4,1038,55892022,-; ? efi_call+0x58/0x90 4,1039,55892025,-; ? virt_efi_get_next_variable+0x7d/0x130 4,1040,55892027,-; ? efivar_init+0x13e/0x3d0 4,1041,55892029,-; ? efivar_release+0x20/0x20 [efivars] 4,1042,55892031,-; ? __slab_alloc+0x20/0x40 4,1043,55892033,-; ? __switch_to+0x202/0x460 4,1044,55892035,-; ? efivar_update_sysfs_entries+0x29/0x70 [efivars] 4,1045,55892036,-; ? efivar_update_sysfs_entries+0x29/0x70 [efivars] 4,1046,55892038,-; ? process_one_work+0x1e9/0x410 4,1047,55892039,-; ? worker_thread+0x4b/0x410 4,1048,55892040,-; ? kthread+0x109/0x140 4,1049,55892042,-; ? process_one_work+0x410/0x410 4,1050,55892043,-; ? kthread_create_on_node+0x40/0x40 4,1051,55892045,-; ? ret_from_fork+0x25/0x30 4,1052,55892046,-;Code: 10 17 eb 03 49 8b c9 ba 20 00 00 00 49 3b c9 75 05 44 8a c2 eb 0f 8a 01 f6 d0 44 0f b6 c0 41 3a c1 44 0f 44 c2 4d 39 5a 20 75 0c <41> 0f b7 42 30 4a 8d 4c 10 17 eb 03 49 8b c9 49 3b c9 74 0f 8a 1,1053,55892062,-;RIP: 0xfffffffeee3ae1fd RSP: ffffaa9583f07b08 4,1054,55892062,-;CR2: fffffffeff800030 4,1055,55892063,-;---[ end trace 2f2cf349eabc236d ]--- 4,1056,57108566,-;------------[ cut here ]------------ 4,1057,57108573,-;WARNING: CPU: 7 PID: 262 at /tmp/nix-build-linux-4.13.9.drv-0/linux-4.13.9/arch/x86/kernel/fpu/core.c:46 __kernel_fpu_begin+0xa4/0xb0 4,1058,57108574,-;Modules linked in: fuse af_packet msr snd_hda_codec_hdmi snd_hda_codec_realtek snd_hda_codec_generic iptable_nat nf_nat_ipv4 nf_nat nf_conntrack_ipv6 nf_defrag_ipv6 nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack nf_conntrack libcrc32c ip6t_rpfilter ipt_rpfilter ip6table_raw iptable_raw xt_pkttype nf_log_ipv6 nf_log_ipv4 nf_log_common xt_LOG xt_tcpudp ip6table_filter ip6_tables edac_core iptable_filter x86_pkg_temp_thermal intel_powerclamp coretemp crct10dif_pclmul crc32_pclmul ghash_clmulni_intel pcbc uvcvideo snd_usb_audio videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 snd_hda_intel videobuf2_core mousedev aesni_intel snd_usbmidi_lib snd_hda_codec nvidia_drm(PO) snd_rawmidi drm_kms_helper aes_x86_64 input_leds uas joydev led_class crypto_simd videodev snd_seq_device evdev usb_storage 4,1059,57108597,c; glue_helper usblp snd_hda_core iTCO_wdt cryptd efi_pstore mxm_wmi mac_hid e1000e drm snd_hwdep pstore tpm_tis snd_pcm mei_me agpgart snd_timer fb_sys_fops intel_cstate tpm_tis_core syscopyarea snd sysfillrect intel_uncore sysimgblt ptp intel_rapl_perf mei soundcore efivars pps_core lpc_ich tpm shpchp nvidia_modeset(PO) nvidia_uvm(PO) nvidia(PO) wmi i2c_core arc4 ecb ppp_mppe ppp_generic slhc button atkbd libps2 loop cpufreq_ondemand vboxnetflt(O) vboxnetadp(O) vboxdrv(O) kvm_intel kvm irqbypass efivarfs ip_tables x_tables ipv6 crc_ccitt autofs4 hid_generic usbhid hid sd_mod ahci xhci_pci libahci xhci_hcd ehci_pci ehci_hcd libata usbcore scsi_mod usb_common serio rtc_cmos dm_mod dax crc32c_generic crc32c_intel btrfs xor raid6_pq 4,1060,57108628,-;CPU: 7 PID: 262 Comm: kworker/u25:0 Tainted: P D O 4.13.9 #1-NixOS 4,1061,57108629,-;Hardware name: MSI MS-7885/X99A RAIDER (MS-7885), BIOS P.50 07/19/2016 4,1062,57108647,-;Workqueue: btrfs-worker-high btrfs_worker_helper [btrfs] 4,1063,57108648,-;task: ffff9843596cd280 task.stack: ffffaa9584050000 4,1064,57108650,-;RIP: 0010:__kernel_fpu_begin+0xa4/0xb0 4,1065,57108651,-;RSP: 0018:ffffaa9584053c28 EFLAGS: 00010202 4,1066,57108652,-;RAX: 0000000080000001 RBX: 0000000000001000 RCX: ffff9843596cd280 4,1067,57108653,-;RDX: 0000000000000000 RSI: ffff98422eba8000 RDI: ffffaa9584053cd0 4,1068,57108654,-;RBP: ffffaa9584053c28 R08: 0000000000000000 R09: 0000000000001000 4,1069,57108655,-;R10: 0000000000000001 R11: ffff984233947f80 R12: ffffaa9584053cd0 4,1070,57108655,-;R13: ffff98422eba8000 R14: ffff98422eba8000 R15: ffffffffc03a6050 4,1071,57108656,-;FS: 0000000000000000(0000) GS:ffff98435f3c0000(0000) knlGS:0000000000000000 4,1072,57108657,-;CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 4,1073,57108658,-;CR2: 00000c0aa4045000 CR3: 00000005ab409000 CR4: 00000000003406e0 4,1074,57108659,-;DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 4,1075,57108660,-;DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400 4,1076,57108660,-;Call Trace: 4,1077,57108663,-; kernel_fpu_begin+0xe/0x10 4,1078,57108665,-; crc32c_pcl_intel_update+0x84/0xb0 [crc32c_intel] 4,1079,57108668,-; crypto_shash_update+0x3f/0x110 4,1080,57108669,-; ? wake_up_process+0x15/0x20 4,1081,57108676,-; btrfs_crc32c+0x6e/0xa0 [btrfs] 4,1082,57108682,-; btrfs_csum_data+0x16/0x20 [btrfs] 4,1083,57108688,-; btrfs_csum_one_bio+0x214/0x490 [btrfs] 4,1084,57108694,-; ? __btree_submit_bio_start+0x20/0x20 [btrfs] 4,1085,57108700,-; __btrfs_submit_bio_start+0x12/0x20 [btrfs] 4,1086,57108705,-; run_one_async_start+0x23/0x30 [btrfs] 4,1087,57108712,-; btrfs_scrubparity_helper+0xc8/0x2e0 [btrfs] 4,1088,57108719,-; btrfs_worker_helper+0xe/0x10 [btrfs] 4,1089,57108721,-; process_one_work+0x1e9/0x410 4,1090,57108722,-; worker_thread+0x4b/0x410 4,1091,57108724,-; kthread+0x109/0x140 4,1092,57108725,-; ? process_one_work+0x410/0x410 4,1093,57108737,-; ? kthread_create_on_node+0x40/0x40 4,1094,57108740,-; ret_from_fork+0x25/0x30 4,1095,57108741,-;Code: 80 0a 00 00 85 c0 74 27 b8 ff ff ff ff 89 c2 48 0f ae 37 31 c0 85 c0 74 d7 0f ff 5d c3 0f ff eb a7 48 0f ae 81 80 0a 00 00 5d c3 <0f> ff eb a4 0f ff eb d5 0f 1f 40 00 0f 1f 44 00 00 55 48 89 e5 4,1096,57108777,-;---[ end trace 2f2cf349eabc236e ]---