A lot warnings in dmesg while running thunderbird

A lot warnings in dmesg while running thunderbird

[Gabriel C]

Hi,

while running thunderbird on linux 4.6.3 and 4.7.0-rc6 ( didn't tested
other versions )
I trigger the following :


[ 6393.305675] WARNING: CPU: 6 PID: 5870 at fs/btrfs/inode.c:9306
btrfs_destroy_inode+0x22e/0x2a0 [btrfs]
[ 6393.305677] Modules linked in: fuse ufs qnx4 hfsplus hfs minix ntfs
vfat msdos fat jfs ext4 crc16 jbd2 ext2 mbcache binfmt_misc ctr ccm
af_packet xfs libcrc32c crc32c_generic amdkfd amd_iommu_v2 coretemp
radeon intel_powerclamp ttm ar
c4 kvm_intel drm_kms_helper ath9k ath9k_common ath9k_hw ath mac80211
joydev drm agpgart i2c_algo_bit fb_sys_fops syscopyarea sysfillrect
kvm sysimgblt evdev ipmi_ssif mac_hid snd_hda_codec_hdmi snd_hda_intel
snd_hda_codec snd_hda_core sn
d_hwdep iTCO_wdt cfg80211 rfkill iTCO_vendor_support ipmi_si
ipmi_msghandler irqbypass pcspkr e1000e ptp pps_core fjes tpm_infineon
button i2c_i801 ac acpi_power_meter i5500_temp hwmon i7core_edac
ioatdma acpi_cpufreq tpm_tis dca edac_co
re tpm shpchp lpc_ich i2c_core ppdev sch_fq_codel snd_seq_dummy
snd_pcm_oss snd_mixer_oss snd_pcm snd_seq_oss
[ 6393.305742]  snd_seq_midi_event snd_seq snd_seq_device snd_timer
snd soundcore lp parport_pc parport hid_logitech_hidpp hid_logitech_dj
usbhid hid btrfs xor raid6_pq uas usb_storage sd_mod uhci_hcd ahci
libahci libata megaraid_sas crc
32c_intel ehci_pci ehci_hcd usbcore scsi_mod usb_common dm_mirror
dm_region_hash dm_log dm_mod unix ipv6 autofs4 jitterentropy_rng
sha256_ssse3 sha256_generic hmac drbg ansi_cprng
[ 6393.305772] CPU: 6 PID: 5870 Comm: mozStorage #1 Tainted: G
 I     4.7.0-rc6 #1
[ 6393.305774] Hardware name: FUJITSU
PRIMERGY TX200 S5             /D2709, BIOS 6.00 Rev. 1.14.2709
     02/04/2013
[ 6393.305775]  0000000000000000 ffffffff81249333 0000000000000000
0000000000000000
[ 6393.305778]  ffffffff81058044 ffff8807e1de2480 ffff8807e152c898
ffff88083b273800
[ 6393.305780]  ffff8807e152c898 ffff88043f52edd8 ffff88083aa3b910
ffffffffa051eade
[ 6393.305783] Call Trace:
[ 6393.305791]  [<ffffffff81249333>] ? dump_stack+0x5c/0x79
[ 6393.305795]  [<ffffffff81058044>] ? __warn+0xb4/0xd0
[ 6393.305809]  [<ffffffffa051eade>] ? btrfs_destroy_inode+0x22e/0x2a0 [btrfs]
[ 6393.305814]  [<ffffffff81197451>] ? __dentry_kill+0x191/0x210
[ 6393.305816]  [<ffffffff81197632>] ? dput+0x162/0x270
[ 6393.305819]  [<ffffffff81183b8d>] ? __fput+0x11d/0x1c0
[ 6393.305824]  [<ffffffff81070ef0>] ? task_work_run+0x70/0x90
[ 6393.305827]  [<ffffffff810020db>] ? exit_to_usermode_loop+0x9b/0xa0
[ 6393.305829]  [<ffffffff81002565>] ? syscall_return_slowpath+0x45/0x50
[ 6393.305836]  [<ffffffff814972fa>] ? entry_SYSCALL_64_fastpath+0xa2/0xa4
[ 6393.305855] ---[ end trace cd086f0cb12a2d9c ]---

and after that lots:

[ 6509.253357] WARNING: CPU: 12 PID: 7271 at
fs/btrfs/extent-tree.c:4303
btrfs_free_reserved_data_space_noquota+0x68/0x80 [btrfs]
[ 6509.253359] Modules linked in: fuse ufs qnx4 hfsplus hfs minix ntfs
vfat msdos fat jfs ext4 crc16 jbd2 ext2 mbcache binfmt_misc ctr ccm
af_packet xfs libcrc32c crc32c_generic amdkfd amd_iommu_v2 coretemp
radeon intel_powerclamp ttm ar
c4 kvm_intel drm_kms_helper ath9k ath9k_common ath9k_hw ath mac80211
joydev drm agpgart i2c_algo_bit fb_sys_fops syscopyarea sysfillrect
kvm sysimgblt evdev ipmi_ssif mac_hid snd_hda_codec_hdmi snd_hda_intel
snd_hda_codec snd_hda_core sn
d_hwdep iTCO_wdt cfg80211 rfkill iTCO_vendor_support ipmi_si
ipmi_msghandler irqbypass pcspkr e1000e ptp pps_core fjes tpm_infineon
button i2c_i801 ac acpi_power_meter i5500_temp hwmon i7core_edac
ioatdma acpi_cpufreq tpm_tis dca edac_co
re tpm shpchp lpc_ich i2c_core ppdev sch_fq_codel snd_seq_dummy
snd_pcm_oss snd_mixer_oss snd_pcm snd_seq_oss
[ 6509.253420]  snd_seq_midi_event snd_seq snd_seq_device snd_timer
snd soundcore lp parport_pc parport hid_logitech_hidpp hid_logitech_dj
usbhid hid btrfs xor raid6_pq uas usb_storage sd_mod uhci_hcd ahci
libahci libata megaraid_sas crc
32c_intel ehci_pci ehci_hcd usbcore scsi_mod usb_common dm_mirror
dm_region_hash dm_log dm_mod unix ipv6 autofs4 jitterentropy_rng
sha256_ssse3 sha256_generic hmac drbg ansi_cprng
[ 6509.253450] CPU: 12 PID: 7271 Comm: systemd-journal Tainted: G
  W I     4.7.0-rc6 #1
[ 6509.253451] Hardware name: FUJITSU
PRIMERGY TX200 S5             /D2709, BIOS 6.00 Rev. 1.14.2709
     02/04/2013
[ 6509.253453]  0000000000000000 ffffffff81249333 0000000000000000
0000000000000000
[ 6509.253456]  ffffffff81058044 0000000000001000 ffff88043b720200
0000000000000fff
[ 6509.253459]  ffff88083d57990c ffff8807de10b924 0000000000001000
ffffffffa04f3b08
[ 6509.253462] Call Trace:
[ 6509.253467]  [<ffffffff81249333>] ? dump_stack+0x5c/0x79
[ 6509.253470]  [<ffffffff81058044>] ? __warn+0xb4/0xd0
[ 6509.253483]  [<ffffffffa04f3b08>] ?
btrfs_free_reserved_data_space_noquota+0x68/0x80 [btrfs]
[ 6509.253499]  [<ffffffffa050f002>] ? btrfs_clear_bit_hook+0x282/0x360 [btrfs]
[ 6509.253515]  [<ffffffffa052a900>] ? clear_state_bit+0x50/0x1c0 [btrfs]
[ 6509.253532]  [<ffffffffa052abb2>] ? __clear_extent_bit+0x142/0x3c0 [btrfs]
[ 6509.253549]  [<ffffffffa052b91b>] ?
extent_clear_unlock_delalloc+0x5b/0x220 [btrfs]
[ 6509.253560]  [<ffffffffa04e3f87>] ? btrfs_release_path+0x27/0x80 [btrfs]
[ 6509.253563]  [<ffffffff81163c1e>] ? kmem_cache_alloc+0x13e/0x150
[ 6509.253567]  [<ffffffff81199c2c>] ? igrab+0x2c/0x50
[ 6509.253583]  [<ffffffffa052789c>] ?
__btrfs_add_ordered_extent+0x20c/0x2d0 [btrfs]
[ 6509.253595]  [<ffffffffa04ec451>] ?
block_group_cache_tree_search+0xb1/0xd0 [btrfs]
[ 6509.253610]  [<ffffffffa0514e30>] ? run_delalloc_nocow+0xa60/0xba0 [btrfs]
[ 6509.253627]  [<ffffffffa0515300>] ? run_delalloc_range+0x390/0x3b0 [btrfs]
[ 6509.253630]  [<ffffffff8104e925>] ? flush_tlb_page+0x35/0x90
[ 6509.253647]  [<ffffffffa052c08b>] ?
writepage_delalloc.isra.20+0xfb/0x170 [btrfs]
[ 6509.253664]  [<ffffffffa052dbf3>] ? __extent_writepage+0xb3/0x300 [btrfs]
[ 6509.253668]  [<ffffffff81119d7a>] ? __set_page_dirty_nobuffers+0xea/0x140
[ 6509.253685]  [<ffffffffa052e07c>] ?
extent_write_cache_pages.isra.16.constprop.31+0x23c/0x350 [btrfs]
[ 6509.253702]  [<ffffffffa052f448>] ? extent_writepages+0x48/0x60 [btrfs]
[ 6509.253718]  [<ffffffffa0511310>] ? btrfs_direct_IO+0x360/0x360 [btrfs]
[ 6509.253723]  [<ffffffff8110dc32>] ? __filemap_fdatawrite_range+0xa2/0xe0
[ 6509.253739]  [<ffffffffa0523de6>] ? btrfs_fdatawrite_range+0x16/0x40 [btrfs]
[ 6509.253755]  [<ffffffffa0523e20>] ? start_ordered_ops+0x10/0x20 [btrfs]
[ 6509.253771]  [<ffffffffa0523e71>] ? btrfs_sync_file+0x41/0x360 [btrfs]
[ 6509.253775]  [<ffffffff811ad0a3>] ? do_fsync+0x33/0x60
[ 6509.253778]  [<ffffffff811ad2c7>] ? SyS_fsync+0x7/0x10
[ 6509.253782]  [<ffffffff81497272>] ? entry_SYSCALL_64_fastpath+0x1a/0xa4

...

See http://paste.opensuse.org/view/simple/86078072 and
http://paste.opensuse.org/view/simple/87276071

This is from running thunderbird just few seconds , when I let it run
for a while I have to reboot the system.

$ uname -a
Linux zwerg 4.7.0-rc6 #1 SMP PREEMPT Tue Jul 5 07:48:39 CEST 2016
x86_64 x86_64 x86_64 GNU/Linux

btrfs-progs v4.6.1

sda is HW RAID0

...

Jun 23 14:27:48 localhost kernel: scsi host0: Avago SAS based MegaRAID driver
Jun 23 14:27:48 localhost kernel: scsi 0:0:6:0: Direct-Access     ATA
    WDC WD5002ABYS-5 3B06 PQ: 0 ANSI: 5
Jun 23 14:27:48 localhost kernel: scsi 0:0:7:0: Direct-Access     ATA
    WDC WD5002ABYS-5 3B06 PQ: 0 ANSI: 5
Jun 23 14:27:48 localhost kernel: scsi 0:0:10:0: Direct-Access     ATA
     ST500NM0011      FTM6 PQ: 0 ANSI: 5
Jun 23 14:27:48 localhost kernel: scsi 0:2:0:0: Direct-Access     LSI
    MegaRAID SAS RMB 1.40 PQ: 0 ANSI: 5

...

mount | grep sda
/dev/sda1 on / type btrfs
(rw,noatime,compress=lzo,space_cache,autodefrag,subvolid=5,subvol=/)

( tested with and without compression , with just defaults the
warnings are still the same )

btrfs fi show
Label: none  uuid: 67b2e285-e331-42ad-8478-d78b17ea6970
       Total devices 1 FS bytes used 31.47GiB
       devid    1 size 1.36TiB used 37.06GiB path /dev/sda1


btrfs fi df /
Data, single: total=32.00GiB, used=30.43GiB
System, DUP: total=32.00MiB, used=16.00KiB
Metadata, DUP: total=2.50GiB, used=1.04GiB
GlobalReserve, single: total=368.00MiB, used=0.00B


Regards,

Gabriel C

Re: A lot warnings in dmesg while running thunderbird

[Chris Mason]

On 07/07/2016 06:24 AM, Gabriel C wrote:
> Hi,
>
> while running thunderbird on linux 4.6.3 and 4.7.0-rc6 ( didn't tested
> other versions )
> I trigger the following :

I definitely thought we had this fixed in v4.7-rc.  Can you easily fsck 
this filesystem?  Something strange is going on.

-chris

Re: A lot warnings in dmesg while running thunderbird

[Gabriel C]

2016-07-07 21:21 GMT+02:00 Chris Mason <clm@fb.com>:
>
>
> On 07/07/2016 06:24 AM, Gabriel C wrote:
>>
>> Hi,
>>
>> while running thunderbird on linux 4.6.3 and 4.7.0-rc6 ( didn't tested
>> other versions )
>> I trigger the following :
>
>
> I definitely thought we had this fixed in v4.7-rc.  Can you easily fsck this filesystem?  Something strange is going on.

Yes , btrfs check and btrfs check  --check-data-csum are fine , no errors found.

If you want me to test any patches let me know.


Regards,

Gabriel C

Re: A lot warnings in dmesg while running thunderbird

[Chris Mason]

On 07/08/2016 05:57 AM, Gabriel C wrote:
> 2016-07-07 21:21 GMT+02:00 Chris Mason <clm@fb.com>:
>>
>>
>> On 07/07/2016 06:24 AM, Gabriel C wrote:
>>>
>>> Hi,
>>>
>>> while running thunderbird on linux 4.6.3 and 4.7.0-rc6 ( didn't tested
>>> other versions )
>>> I trigger the following :
>>
>>
>> I definitely thought we had this fixed in v4.7-rc.  Can you easily fsck this filesystem?  Something strange is going on.
>
> Yes , btrfs check and btrfs check  --check-data-csum are fine , no errors found.
>
> If you want me to test any patches let me know.
>

Can you please try a v4.5 stable kernel?  I'm curious if this really is 
the same regression that I tried to fix in v4.7

-chris

Re: A lot warnings in dmesg while running thunderbird

[Gabriel C]

2016-07-08 14:41 GMT+02:00 Chris Mason <clm@fb.com>:
>
>
> On 07/08/2016 05:57 AM, Gabriel C wrote:
>>
>> 2016-07-07 21:21 GMT+02:00 Chris Mason <clm@fb.com>:
>>>
>>>
>>>
>>> On 07/07/2016 06:24 AM, Gabriel C wrote:
>>>>
>>>>
>>>> Hi,
>>>>
>>>> while running thunderbird on linux 4.6.3 and 4.7.0-rc6 ( didn't tested
>>>> other versions )
>>>> I trigger the following :
>>>
>>>
>>>
>>> I definitely thought we had this fixed in v4.7-rc.  Can you easily fsck
>>> this filesystem?  Something strange is going on.
>>
>>
>> Yes , btrfs check and btrfs check  --check-data-csum are fine , no errors
>> found.
>>
>> If you want me to test any patches let me know.
>>
>
> Can you please try a v4.5 stable kernel?  I'm curious if this really is the
> same regression that I tried to fix in v4.7
>

Sure , I'll test on 4.5.7 and let you know.

Re: A lot warnings in dmesg while running thunderbird

[Gabriel C]

On 08.07.2016 14:41, Chris Mason wrote:

>
>
> On 07/08/2016 05:57 AM, Gabriel C wrote:
>> 2016-07-07 21:21 GMT+02:00 Chris Mason <clm@fb.com>:
>>>
>>>
>>> On 07/07/2016 06:24 AM, Gabriel C wrote:
>>>>
>>>> Hi,
>>>>
>>>> while running thunderbird on linux 4.6.3 and 4.7.0-rc6 ( didn't tested
>>>> other versions )
>>>> I trigger the following :
>>>
>>>
>>> I definitely thought we had this fixed in v4.7-rc.  Can you easily 
>>> fsck this filesystem?  Something strange is going on.
>>
>> Yes , btrfs check and btrfs check  --check-data-csum are fine , no 
>> errors found.
>>
>> If you want me to test any patches let me know.
>>
>
> Can you please try a v4.5 stable kernel?  I'm curious if this really 
> is the same regression that I tried to fix in v4.7
>

I'm on linux 4.5.7 now and everything is fine. I'm writing this email 
from thunderbird.. which was not
possible in 4.6.3 or 4.7.-rc.

Let me know you want me to test other kernels or whatever else may help 
fixing this problem.

Regards,

Gabriel C

Re: A lot warnings in dmesg while running thunderbird

[Chris Mason]

[-- Attachment #1: Type: text/plain, Size: 1414 bytes --]



On 07/08/2016 11:02 AM, Gabriel C wrote:
> On 08.07.2016 14:41, Chris Mason wrote:
>
>>
>>
>> On 07/08/2016 05:57 AM, Gabriel C wrote:
>>> 2016-07-07 21:21 GMT+02:00 Chris Mason <clm@fb.com>:
>>>>
>>>>
>>>> On 07/07/2016 06:24 AM, Gabriel C wrote:
>>>>>
>>>>> Hi,
>>>>>
>>>>> while running thunderbird on linux 4.6.3 and 4.7.0-rc6 ( didn't tested
>>>>> other versions )
>>>>> I trigger the following :
>>>>
>>>>
>>>> I definitely thought we had this fixed in v4.7-rc.  Can you easily
>>>> fsck this filesystem?  Something strange is going on.
>>>
>>> Yes , btrfs check and btrfs check  --check-data-csum are fine , no
>>> errors found.
>>>
>>> If you want me to test any patches let me know.
>>>
>>
>> Can you please try a v4.5 stable kernel?  I'm curious if this really
>> is the same regression that I tried to fix in v4.7
>>
>
> I'm on linux 4.5.7 now and everything is fine. I'm writing this email
> from thunderbird.. which was not
> possible in 4.6.3 or 4.7.-rc.
>
> Let me know you want me to test other kernels or whatever else may help
> fixing this problem.
>

Can you please run the attached test program:

gcc -o short-write short-write.c -lpthread
./short-write some-new-file-on-btrfs

I want to see if you're triggering the same problem we've tried to fix, 
or something else.

This program will create a new file, or overwrite an existing file. 
Don't pass it something you care about ;)

-chris


[-- Attachment #2: short-write.c --]
[-- Type: text/x-csrc, Size: 1983 bytes --]

#define _FILE_OFFSET_BITS 64
#define _GNU_SOURCE

#include <stdio.h>
#include <stdlib.h>
#include <fcntl.h>
#include <string.h>
#include <unistd.h>
#include <pthread.h>
#include <sys/mman.h>

#define ROUNDS 8
#define BUFSIZE (1024 * 1024)
#define MAXSIZE (128 * 1024ULL * 1024ULL * 1024ULL)

void *dontneed(void *arg)
{
	char *p = arg;
	int ret;

	while(1) {
		ret = madvise(p, BUFSIZE/4, MADV_DONTNEED);
		if (ret) {
			perror("madvise");
			exit(1);
		}
	}
}

int main(int ac, char **av) {
	int ret;
	int fd;
	char *filename;
	unsigned long offset;
	char *buf;
	int i;
	pthread_t tid;

	if (ac != 2) {
		fprintf(stderr, "usage: short-write filename\n");
		exit(1);
	}

	buf = mmap(NULL, BUFSIZE, PROT_READ|PROT_WRITE,
		   MAP_PRIVATE|MAP_ANONYMOUS, -1, 0);
	if (buf == MAP_FAILED) {
		perror("mmap");
		exit(1);
	}
	memset(buf, 'a', BUFSIZE);
	filename = av[1];

	ret = pthread_create(&tid, NULL, dontneed, buf);
	if (ret) {
		fprintf(stderr, "error %d from pthread_create\n", ret);
		exit(1);
	}

	ret = pthread_detach(tid);
	if (ret) {
		fprintf(stderr, "pthread detach failed %d\n", ret);
		exit(1);
	}

	while (1) {
		fd = open(filename, O_RDWR | O_CREAT, 0600);
		if (fd < 0) {
			perror("open");
			exit(1);
		}

		for (i = 0; i < ROUNDS; i++) {
			int this_write = BUFSIZE;

			offset = rand() % MAXSIZE;
			ret = pwrite(fd, buf, this_write, offset);
			if (ret < 0) {
				perror("pwrite");
				exit(1);
			} else if (ret != this_write) {
				fprintf(stderr, "short write to %s offset %lu ret %d\n",
					filename, offset, ret);
				exit(1);
			}
			if (i == ROUNDS - 1) {
				ret = sync_file_range(fd, offset, 4096,
				    SYNC_FILE_RANGE_WRITE);
				if (ret < 0) {
					perror("sync_file_range");
					exit(1);
				}
			}
		}
		ret = ftruncate(fd, 0);
		if (ret < 0) {
			perror("ftruncate");
			exit(1);
		}
		ret = close(fd);
		if (ret) {
			perror("close");
			exit(1);
		}
		ret = unlink(filename);
		if (ret) {
			perror("unlink");
			exit(1);
		}

	}
	return 0;
}

Re: A lot warnings in dmesg while running thunderbird

[Adam Borowski]

On Fri, Jul 08, 2016 at 12:02:35PM -0400, Chris Mason wrote:
> On 07/08/2016 11:02 AM, Gabriel C wrote:
> > [btrfs_destroy_inode again]

> Can you please run the attached test program:
> 
> gcc -o short-write short-write.c -lpthread
> ./short-write some-new-file-on-btrfs
> 
> I want to see if you're triggering the same problem we've tried to fix, or
> something else.

Looks like same, 4.6.3:

[239214.345100] ------------[ cut here ]------------
[239214.345122] WARNING: CPU: 0 PID: 28038 at fs/btrfs/inode.c:9261 btrfs_destroy_inode+0x22b/0x2a0
[239214.345127] Modules linked in: vboxpci(O) vboxnetadp(O) vboxnetflt(O) vboxdrv(O) nls_utf8 isofs loop tun usb_storage fuse nvidia(PO)
[239214.345153] CPU: 0 PID: 28038 Comm: short-write Tainted: P           O    4.6.3-x32+ #8
[239214.345158] Hardware name: System manufacturer System Product Name/M4A77T, BIOS 2401    05/18/2011
[239214.345162]  0000000000000000 ffffffff813819b0 0000000000000000 0000000000000000
[239214.345170]  ffffffff8108ce92 0000000000000000 ffff88010c2d71c8 ffff880222670800
[239214.345177]  0000000000000000 ffff88010c2d71c8 00000000ffffff9c ffffffff812b1e0b
[239214.345183] Call Trace:
[239214.345194]  [<ffffffff813819b0>] ? dump_stack+0x46/0x66
[239214.345202]  [<ffffffff8108ce92>] ? __warn+0xe2/0x100
[239214.345209]  [<ffffffff812b1e0b>] ? btrfs_destroy_inode+0x22b/0x2a0
[239214.345216]  [<ffffffff811b93bc>] ? do_unlinkat+0x12c/0x2f0
[239214.345224]  [<ffffffff8174815f>] ? entry_SYSCALL_64_fastpath+0x17/0x93
[239214.345229] ---[ end trace ae49f2a4ae4a26ea ]---
[239214.404237] ------------[ cut here ]------------
[239214.404258] WARNING: CPU: 5 PID: 28038 at fs/btrfs/extent-tree.c:4233 btrfs_free_reserved_data_space_noquota+0x63/0x80
[239214.404262] Modules linked in: vboxpci(O) vboxnetadp(O) vboxnetflt(O) vboxdrv(O) nls_utf8 isofs loop tun usb_storage fuse nvidia(PO)
[239214.404286] CPU: 5 PID: 28038 Comm: short-write Tainted: P        W  O    4.6.3-x32+ #8
[239214.404291] Hardware name: System manufacturer System Product Name/M4A77T, BIOS 2401    05/18/2011
[239214.404295]  0000000000000000 ffffffff813819b0 0000000000000000 0000000000000000
[239214.404303]  ffffffff8108ce92 0000000000001000 ffff880229415c00 00000000037ea000
[239214.404309]  ffff8800c2ed7da0 ffff88000dd3d800 0000000000000000 ffffffff81287143
[239214.404315] Call Trace:
[239214.404325]  [<ffffffff813819b0>] ? dump_stack+0x46/0x66
[239214.404333]  [<ffffffff8108ce92>] ? __warn+0xe2/0x100
[239214.404341]  [<ffffffff81287143>] ? btrfs_free_reserved_data_space_noquota+0x63/0x80
[239214.404349]  [<ffffffff812877b1>] ? btrfs_delalloc_release_space+0x31/0x60
[239214.404356]  [<ffffffff812b4301>] ? __btrfs_buffered_write+0x591/0x680
[239214.404364]  [<ffffffff812b7802>] ? btrfs_file_write_iter+0x182/0x550
[239214.404372]  [<ffffffff811a8419>] ? __vfs_write+0xa9/0xe0
[239214.404379]  [<ffffffff811a934c>] ? vfs_write+0xac/0x1a0
[239214.404387]  [<ffffffff811aa8c8>] ? SyS_pwrite64+0x88/0xa0
[239214.404394]  [<ffffffff8174815f>] ? entry_SYSCALL_64_fastpath+0x17/0x93
[239214.404399] ---[ end trace ae49f2a4ae4a26eb ]---

... and sda1 is goes ro.
Single device, noatime,compress=lzo,ssd.

It's somewhat puzzling that back in the day applying 56244ef15 stopped this
reproducer for me, yet somehow it triggers again.

-- 
An imaginary friend squared is a real enemy.

Re: A lot warnings in dmesg while running thunderbird

[Adam Borowski]

On Fri, Jul 08, 2016 at 08:21:16PM +0200, Adam Borowski wrote:
> On Fri, Jul 08, 2016 at 12:02:35PM -0400, Chris Mason wrote:
> > On 07/08/2016 11:02 AM, Gabriel C wrote:
> > > [btrfs_destroy_inode again]
> 
> > Can you please run the attached test program:
> > 
> > gcc -o short-write short-write.c -lpthread
> > ./short-write some-new-file-on-btrfs
> > 
> > I want to see if you're triggering the same problem we've tried to fix, or
> > something else.
> 
> Looks like same, 4.6.3:
[...]
> ... and sda1 is goes ro.
> Single device, noatime,compress=lzo,ssd.
> 
> It's somewhat puzzling that back in the day applying 56244ef15 stopped this
> reproducer for me, yet somehow it triggers again.

The above on 4.6.3 triggered pretty immediately.  I then compiled fresh
4.7-rc6+ (today's Linus' master), which did trigger only after a lot of time
and effort.  First I tried on freshly formatted 2TB spinning rust, no luck.
Then on 1GB rust, almost full of a mixture of crap.  Then on my regular ssd
-- it survived an hour of so with little concurrent use, then went boom only
late of a kernel compile on that filesystem.

Same backtrace.

-- 
An imaginary friend squared is a real enemy.

Re: A lot warnings in dmesg while running thunderbird

[Duncan]

Chris Mason posted on Fri, 08 Jul 2016 12:02:35 -0400 as excerpted:

> Can you please run the attached test program:

Umm... you want him to run it on the affected 4.6.x and late 4.7-rcs, not 
on the unaffected 4.5.x, correct?

-- 
Duncan - List replies preferred.   No HTML msgs.
"Every nonfree program has a lord, a master --
and if you use the program, he is your master."  Richard Stallman

Re: A lot warnings in dmesg while running thunderbird

[Chandan Rajendra]

On Friday, July 08, 2016 12:02:35 PM Chris Mason wrote:
> 
> On 07/08/2016 11:02 AM, Gabriel C wrote:
> > On 08.07.2016 14:41, Chris Mason wrote:
> >
> >>
> >>
> >> On 07/08/2016 05:57 AM, Gabriel C wrote:
> >>> 2016-07-07 21:21 GMT+02:00 Chris Mason <clm@fb.com>:
> >>>>
> >>>>
> >>>> On 07/07/2016 06:24 AM, Gabriel C wrote:
> >>>>>
> >>>>> Hi,
> >>>>>
> >>>>> while running thunderbird on linux 4.6.3 and 4.7.0-rc6 ( didn't tested
> >>>>> other versions )
> >>>>> I trigger the following :
> >>>>
> >>>>
> >>>> I definitely thought we had this fixed in v4.7-rc.  Can you easily
> >>>> fsck this filesystem?  Something strange is going on.
> >>>
> >>> Yes , btrfs check and btrfs check  --check-data-csum are fine , no
> >>> errors found.
> >>>
> >>> If you want me to test any patches let me know.
> >>>
> >>
> >> Can you please try a v4.5 stable kernel?  I'm curious if this really
> >> is the same regression that I tried to fix in v4.7
> >>
> >
> > I'm on linux 4.5.7 now and everything is fine. I'm writing this email
> > from thunderbird.. which was not
> > possible in 4.6.3 or 4.7.-rc.
> >
> > Let me know you want me to test other kernels or whatever else may help
> > fixing this problem.
> >
> 
> Can you please run the attached test program:
> 
> gcc -o short-write short-write.c -lpthread
> ./short-write some-new-file-on-btrfs
> 
> I want to see if you're triggering the same problem we've tried to fix, 
> or something else.
>

Hi Chris,

I am able to reproduce the issue with the 'short-write' program. But before
the call trace associated with btrfs_destroy_inode(), I see the following call
trace ...

------------[ cut here ]------------
WARNING: CPU: 2 PID: 2311 at /home/chandan/repos/linux/fs/btrfs/extent-tree.c:4303 btrfs_free_reserved_data_space_noquota+0xe8/0x100
Modules linked in:
CPU: 2 PID: 2311 Comm: short-write Not tainted 4.7.0-rc6-ga99cde4 #1
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
 0000000000000000 ffff8818ceb8ba30 ffffffff8145c2a1 0000000000000000
 0000000000000000 ffff8818ceb8ba70 ffffffff81056a7c 000010cf81346936
 ffff8818bdba4800 0000000000001000 ffff8818bdd5ee00 ffff8818bf1bbd84
Call Trace:
 [<ffffffff8145c2a1>] dump_stack+0x4d/0x6c
 [<ffffffff81056a7c>] __warn+0xcc/0xf0
 [<ffffffff81056b58>] warn_slowpath_null+0x18/0x20
 [<ffffffff8134a3c8>] btrfs_free_reserved_data_space_noquota+0xe8/0x100
 [<ffffffff81368b39>] btrfs_clear_bit_hook+0x2f9/0x370
 [<ffffffff813830e5>] clear_state_bit+0x55/0x1b0
 [<ffffffff81383460>] __clear_extent_bit+0x220/0x3b0
 [<ffffffff813cb5f2>] ? __btrfs_qgroup_release_data+0x82/0x110
 [<ffffffff81383bc5>] clear_extent_bit+0x25/0x30
 [<ffffffff8136eb53>] btrfs_invalidatepage+0x273/0x2c0
 [<ffffffff81131223>] truncate_inode_page+0x83/0x90
 [<ffffffff811313da>] truncate_inode_pages_range+0x17a/0x6c0
 [<ffffffff811319c2>] truncate_pagecache+0x42/0x60
 [<ffffffff81131a0d>] truncate_setsize+0x2d/0x40
 [<ffffffff81370d7f>] btrfs_setattr+0x1ef/0x320
 [<ffffffff8119680c>] notify_change+0x1dc/0x380
 [<ffffffff811788b1>] do_truncate+0x61/0xa0
 [<ffffffff81178c09>] do_sys_ftruncate.constprop.17+0xf9/0x160
 [<ffffffff81178c99>] SyS_ftruncate+0x9/0x10
 [<ffffffff81a27d1b>] entry_SYSCALL_64_fastpath+0x13/0x8f
---[ end trace 5682b0d8e8a631ed ]---


I will continue to debug and find out the root cause.

-- 
chandan

Re: A lot warnings in dmesg while running thunderbird

[Chris Mason]

On Mon, Jul 11, 2016 at 11:28:01AM +0530, Chandan Rajendra wrote:
>On Friday, July 08, 2016 12:02:35 PM Chris Mason wrote:
>>
>> Can you please run the attached test program:
>>
>> gcc -o short-write short-write.c -lpthread
>> ./short-write some-new-file-on-btrfs
>>
>> I want to see if you're triggering the same problem we've tried to fix,
>> or something else.
>>
>
>Hi Chris,
>
>I am able to reproduce the issue with the 'short-write' program. But before
>the call trace associated with btrfs_destroy_inode(), I see the following call
>trace ...
>
>------------[ cut here ]------------
>WARNING: CPU: 2 PID: 2311 at /home/chandan/repos/linux/fs/btrfs/extent-tree.c:4303 btrfs_free_reserved_data_space_noquota+0xe8/0x100
>Modules linked in:

[ ... ]

>
>I will continue to debug and find out the root cause.

Thanks Chandan, I'm able to reproduce the same thing more easily by changing
short-write to have:

#define ROUNDS 4096

and by getting rid of the sync_file_range call.

Still nailing down where the accounting is going wrong, so any help is
appreciated.

-chris

Re: A lot warnings in dmesg while running thunderbird

[Chris Mason]

On Mon, Jul 11, 2016 at 11:28:01AM +0530, Chandan Rajendra wrote:
>Hi Chris,
>
>I am able to reproduce the issue with the 'short-write' program. But before
>the call trace associated with btrfs_destroy_inode(), I see the following call
>trace ...
>
>------------[ cut here ]------------
>WARNING: CPU: 2 PID: 2311 at /home/chandan/repos/linux/fs/btrfs/extent-tree.c:4303 btrfs_free_reserved_data_space_noquota+0xe8/0x100

[ ... ]

Ok, the problem is in how we're dealing with the offset into the sector when
we fail. The dirty_sectors variable already has this accounted in it, so
this patch fixes it for me.  I ran overnight, but I'll let it go for a few
days just to make sure:

diff --git a/fs/btrfs/file.c b/fs/btrfs/file.c
index fac9b839..5842423 100644
--- a/fs/btrfs/file.c
+++ b/fs/btrfs/file.c
@@ -1629,13 +1629,11 @@ again:
 		 * managed to copy.
 		 */
 		if (num_sectors > dirty_sectors) {
-			/*
-			 * we round down because we don't want to count
-			 * any partial blocks actually sent through the
-			 * IO machines
-			 */
-			release_bytes = round_down(release_bytes - copied,
-				      root->sectorsize);
+
+			/* release everything except the sectors we dirtied */
+			release_bytes -= dirty_sectors <<
+				root->fs_info->sb->s_blocksize_bits;
+
 			if (copied > 0) {
 				spin_lock(&BTRFS_I(inode)->lock);
 				BTRFS_I(inode)->outstanding_extents++;

Re: A lot warnings in dmesg while running thunderbird

[Gabriel C]

On 19.07.2016 13:05, Chris Mason wrote:
> On Mon, Jul 11, 2016 at 11:28:01AM +0530, Chandan Rajendra wrote:
>> Hi Chris,
>>
>> I am able to reproduce the issue with the 'short-write' program. But before
>> the call trace associated with btrfs_destroy_inode(), I see the following call
>> trace ...
>>
>> ------------[ cut here ]------------
>> WARNING: CPU: 2 PID: 2311 at /home/chandan/repos/linux/fs/btrfs/extent-tree.c:4303 btrfs_free_reserved_data_space_noquota+0xe8/0x100
> 
> [ ... ]
> 
> Ok, the problem is in how we're dealing with the offset into the sector when
> we fail. The dirty_sectors variable already has this accounted in it, so
> this patch fixes it for me.  I ran overnight, but I'll let it go for a few
> days just to make sure:
> 
> diff --git a/fs/btrfs/file.c b/fs/btrfs/file.c
> index fac9b839..5842423 100644
> --- a/fs/btrfs/file.c
> +++ b/fs/btrfs/file.c
> @@ -1629,13 +1629,11 @@ again:
>  		 * managed to copy.
>  		 */
>  		if (num_sectors > dirty_sectors) {
> -			/*
> -			 * we round down because we don't want to count
> -			 * any partial blocks actually sent through the
> -			 * IO machines
> -			 */
> -			release_bytes = round_down(release_bytes - copied,
> -				      root->sectorsize);
> +
> +			/* release everything except the sectors we dirtied */
> +			release_bytes -= dirty_sectors <<
> +				root->fs_info->sb->s_blocksize_bits;
> +
>  			if (copied > 0) {
>  				spin_lock(&BTRFS_I(inode)->lock);
>  				BTRFS_I(inode)->outstanding_extents++;
> 

Since I guess you are testing this on latest git code I started to test on latest stable.

Until now all seems file .. your test program is still running without to trigger the bug.

Also thunderbird is running without to trigger the bug.

I let it run overnight and report back.

Re: A lot warnings in dmesg while running thunderbird

[Chris Mason]

On 07/19/2016 08:11 PM, Gabriel C wrote:
>
>
> On 19.07.2016 13:05, Chris Mason wrote:
>> On Mon, Jul 11, 2016 at 11:28:01AM +0530, Chandan Rajendra wrote:
>>> Hi Chris,
>>>
>>> I am able to reproduce the issue with the 'short-write' program. But before
>>> the call trace associated with btrfs_destroy_inode(), I see the following call
>>> trace ...
>>>
>>> ------------[ cut here ]------------
>>> WARNING: CPU: 2 PID: 2311 at /home/chandan/repos/linux/fs/btrfs/extent-tree.c:4303 btrfs_free_reserved_data_space_noquota+0xe8/0x100
>>
>> [ ... ]
>>
>> Ok, the problem is in how we're dealing with the offset into the sector when
>> we fail. The dirty_sectors variable already has this accounted in it, so
>> this patch fixes it for me.  I ran overnight, but I'll let it go for a few
>> days just to make sure:
>>
>> diff --git a/fs/btrfs/file.c b/fs/btrfs/file.c
>> index fac9b839..5842423 100644
>> --- a/fs/btrfs/file.c
>> +++ b/fs/btrfs/file.c
>> @@ -1629,13 +1629,11 @@ again:
>>  		 * managed to copy.
>>  		 */
>>  		if (num_sectors > dirty_sectors) {
>> -			/*
>> -			 * we round down because we don't want to count
>> -			 * any partial blocks actually sent through the
>> -			 * IO machines
>> -			 */
>> -			release_bytes = round_down(release_bytes - copied,
>> -				      root->sectorsize);
>> +
>> +			/* release everything except the sectors we dirtied */
>> +			release_bytes -= dirty_sectors <<
>> +				root->fs_info->sb->s_blocksize_bits;
>> +
>>  			if (copied > 0) {
>>  				spin_lock(&BTRFS_I(inode)->lock);
>>  				BTRFS_I(inode)->outstanding_extents++;
>>
>
> Since I guess you are testing this on latest git code I started to test on latest stable.

Any v4.7-rc or v4.6 stable where the patch applies ;)

>
> Until now all seems file .. your test program is still running without to trigger the bug.
>
> Also thunderbird is running without to trigger the bug.
>
> I let it run overnight and report back.

Great, thanks!

-chris

Re: A lot warnings in dmesg while running thunderbird

[Gabriel C]

On 20.07.2016 15:50, Chris Mason wrote:
> 
> 
> On 07/19/2016 08:11 PM, Gabriel C wrote:
>>
>>
>> On 19.07.2016 13:05, Chris Mason wrote:
>>> On Mon, Jul 11, 2016 at 11:28:01AM +0530, Chandan Rajendra wrote:
>>>> Hi Chris,
>>>>
>>>> I am able to reproduce the issue with the 'short-write' program. But before
>>>> the call trace associated with btrfs_destroy_inode(), I see the following call
>>>> trace ...
>>>>
>>>> ------------[ cut here ]------------
>>>> WARNING: CPU: 2 PID: 2311 at /home/chandan/repos/linux/fs/btrfs/extent-tree.c:4303 btrfs_free_reserved_data_space_noquota+0xe8/0x100
>>>
>>> [ ... ]
>>>
>>> Ok, the problem is in how we're dealing with the offset into the sector when
>>> we fail. The dirty_sectors variable already has this accounted in it, so
>>> this patch fixes it for me.  I ran overnight, but I'll let it go for a few
>>> days just to make sure:
>>>
>>> diff --git a/fs/btrfs/file.c b/fs/btrfs/file.c
>>> index fac9b839..5842423 100644
>>> --- a/fs/btrfs/file.c
>>> +++ b/fs/btrfs/file.c
>>> @@ -1629,13 +1629,11 @@ again:
>>>  		 * managed to copy.
>>>  		 */
>>>  		if (num_sectors > dirty_sectors) {
>>> -			/*
>>> -			 * we round down because we don't want to count
>>> -			 * any partial blocks actually sent through the
>>> -			 * IO machines
>>> -			 */
>>> -			release_bytes = round_down(release_bytes - copied,
>>> -				      root->sectorsize);
>>> +
>>> +			/* release everything except the sectors we dirtied */
>>> +			release_bytes -= dirty_sectors <<
>>> +				root->fs_info->sb->s_blocksize_bits;
>>> +
>>>  			if (copied > 0) {
>>>  				spin_lock(&BTRFS_I(inode)->lock);
>>>  				BTRFS_I(inode)->outstanding_extents++;
>>>
>>
>> Since I guess you are testing this on latest git code I started to test on latest stable.
> 
> Any v4.7-rc or v4.6 stable where the patch applies ;)
> 
>>
>> Until now all seems file .. your test program is still running without to trigger the bug.
>>
>> Also thunderbird is running without to trigger the bug.
>>
>> I let it run overnight and report back.
> 
> Great, thanks!

After 24h of running the program and thundirbird all is still fine here.

I let it run one more day.. But looks very good.


Regards,

Gabriel

Re: A lot warnings in dmesg while running thunderbird

[Chris Mason]

On 07/20/2016 01:50 PM, Gabriel C wrote:
>
> After 24h of running the program and thundirbird all is still fine here.
>
> I let it run one more day.. But looks very good.
>

Thanks for your time in helping to track this down.  It'll go into the 
next merge window and be cc'd to stable.

-chris

Re: A lot warnings in dmesg while running thunderbird

[Gabriel C]

On 21.07.2016 14:56, Chris Mason wrote:
> On 07/20/2016 01:50 PM, Gabriel C wrote:
>>
>> After 24h of running the program and thundirbird all is still fine here.
>>
>> I let it run one more day.. But looks very good.
>>
> 
> Thanks for your time in helping to track this down.  It'll go into the 
> next merge window and be cc'd to stable.
> 

You are welcome :)

Test program was running without problems for 52h.. I think your fix is fine :)

Also feel free to add Tested-by: Gabriel Craciunescu <nix.or.die@gmail.com> to you commit.

Regrads,

Gabriel

Re: A lot warnings in dmesg while running thunderbird

[Adam Borowski]

On Thu, Jul 21, 2016 at 11:25:02PM +0200, Gabriel C wrote:
> On 21.07.2016 14:56, Chris Mason wrote:
> > On 07/20/2016 01:50 PM, Gabriel C wrote:
> >> After 24h of running the program and thundirbird all is still fine here.
> >>
> >> I let it run one more day.. But looks very good.
> >>
> > 
> > Thanks for your time in helping to track this down.  It'll go into the 
> > next merge window and be cc'd to stable.
> > 
> 
> You are welcome :)
> 
> Test program was running without problems for 52h.. I think your fix is fine :)

AOL.
I haven't tested it for as long, but had it running concurrently with some
big compiles (kernel, sbuild ie snapshot+dpkg+subv delete), cleanup of
several tens of daily snapshots, etc.

No problems.

-- 
An imaginary friend squared is a real enemy.

Re: A lot warnings in dmesg while running thunderbird

[Dave Chinner]

On Fri, Jul 08, 2016 at 12:02:35PM -0400, Chris Mason wrote:
> Can you please run the attached test program:
> 
> gcc -o short-write short-write.c -lpthread
> ./short-write some-new-file-on-btrfs

Hi Chris, this seems like a useful thing to be testing on a regular
basis - can you turn this into an xfstests regression test and
submit it?

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

Re: A lot warnings in dmesg while running thunderbird

[Chris Mason]

On 07/24/2016 08:36 PM, Dave Chinner wrote:
> On Fri, Jul 08, 2016 at 12:02:35PM -0400, Chris Mason wrote:
>> Can you please run the attached test program:
>>
>> gcc -o short-write short-write.c -lpthread
>> ./short-write some-new-file-on-btrfs
>
> Hi Chris, this seems like a useful thing to be testing on a regular
> basis - can you turn this into an xfstests regression test and
> submit it?
>

[ vacation backlog delay apologies ]

Hi Dave,

The test is just a thread constantly madvising away the memory being 
used for IO.  It would be interesting to add a --evil option to either 
xfs_io or fsx so the evil is compounded across all of the existing xfstests.

-chris

Re: A lot warnings in dmesg while running thunderbird

[Chris Mason]

On 07/07/2016 06:24 AM, Gabriel C wrote:
> Hi,
>
> while running thunderbird on linux 4.6.3 and 4.7.0-rc6 ( didn't tested
> other versions )
> I trigger the following :
>
>
> [ 6393.305675] WARNING: CPU: 6 PID: 5870 at fs/btrfs/inode.c:9306
> btrfs_destroy_inode+0x22e/0x2a0 [btrfs]

Every time I've reproduced this, I've hit a warning in extent-tree.c 
about trying to decrement bytes_may_use too far.  Then I get enospc
on every operation.

Josef fixed a few corner cases here with his new enospc changes, and I'm 
not able to trigger (yet) with those applied.  Dave Sterba has them all 
in his for-next branch:

git://git.kernel.org/pub/scm/linux/kernel/git/kdave/linux.git for-next

Can you please try that on top of v4.7-rc7

-chris

Re: A lot warnings in dmesg while running thunderbird

[Chris Mason]

On 07/15/2016 03:35 PM, Chris Mason wrote:
>
>
> On 07/07/2016 06:24 AM, Gabriel C wrote:
>> Hi,
>>
>> while running thunderbird on linux 4.6.3 and 4.7.0-rc6 ( didn't tested
>> other versions )
>> I trigger the following :
>>
>>
>> [ 6393.305675] WARNING: CPU: 6 PID: 5870 at fs/btrfs/inode.c:9306
>> btrfs_destroy_inode+0x22e/0x2a0 [btrfs]
>
> Every time I've reproduced this, I've hit a warning in extent-tree.c
> about trying to decrement bytes_may_use too far.  Then I get enospc
> on every operation.
>
> Josef fixed a few corner cases here with his new enospc changes, and I'm
> not able to trigger (yet) with those applied.  Dave Sterba has them all
> in his for-next branch:
>
> git://git.kernel.org/pub/scm/linux/kernel/git/kdave/linux.git for-next
>
> Can you please try that on top of v4.7-rc7

A few hours later and it reproduced on this kernel too.  What must be 
happening is we're freeing too many bytes from bytes_may_use.

I'll get tracing in and nail it down.

-chris