https://github.com/torvalds/linux
Revision 9230a0b65b47fe6856c4468ec0175c4987e5bede authored by Dave Chinner on 20 November 2018, 06:50:08 UTC, committed by Darrick J. Wong on 21 November 2018, 18:10:53 UTC
Long saga. There have been days spent following this through dead end
after dead end in multi-GB event traces. This morning, after writing
a trace-cmd wrapper that enabled me to be more selective about XFS
trace points, I discovered that I could get just enough essential
tracepoints enabled that there was a 50:50 chance the fsx config
would fail at ~115k ops. If it didn't fail at op 115547, I stopped
fsx at op 115548 anyway.

That gave me two traces - one where the problem manifested, and one
where it didn't. After refining the traces to have the necessary
information, I found that in the failing case there was a real
extent in the COW fork compared to an unwritten extent in the
working case.

Walking back through the two traces to the point where the CWO fork
extents actually diverged, I found that the bad case had an extra
unwritten extent in it. This is likely because the bug it led me to
had triggered multiple times in those 115k ops, leaving stray
COW extents around. What I saw was a COW delalloc conversion to an
unwritten extent (as they should always be through
xfs_iomap_write_allocate()) resulted in a /written extent/:

xfs_writepage:        dev 259:0 ino 0x83 pgoff 0x17000 size 0x79a00 offset 0 length 0
xfs_iext_remove:      dev 259:0 ino 0x83 state RC|LF|RF|COW cur 0xffff888247b899c0/2 offset 32 block 152 count 20 flag 1 caller xfs_bmap_add_extent_delay_real
xfs_bmap_pre_update:  dev 259:0 ino 0x83 state RC|LF|RF|COW cur 0xffff888247b899c0/1 offset 1 block 4503599627239429 count 31 flag 0 caller xfs_bmap_add_extent_delay_real
xfs_bmap_post_update: dev 259:0 ino 0x83 state RC|LF|RF|COW cur 0xffff888247b899c0/1 offset 1 block 121 count 51 flag 0 caller xfs_bmap_add_ex

Basically, Cow fork before:

	0 1            32          52
	+H+DDDDDDDDDDDD+UUUUUUUUUUU+
	   PREV		RIGHT

COW delalloc conversion allocates:

	  1	       32
	  +uuuuuuuuuuuu+
	  NEW

And the result according to the xfs_bmap_post_update trace was:

	0 1            32          52
	+H+wwwwwwwwwwwwwwwwwwwwwwww+
	   PREV

Which is clearly wrong - it should be a merged unwritten extent,
not an unwritten extent.

That lead me to look at the LEFT_FILLING|RIGHT_FILLING|RIGHT_CONTIG
case in xfs_bmap_add_extent_delay_real(), and sure enough, there's
the bug.

It takes the old delalloc extent (PREV) and adds the length of the
RIGHT extent to it, takes the start block from NEW, removes the
RIGHT extent and then updates PREV with the new extent.

What it fails to do is update PREV.br_state. For delalloc, this is
always XFS_EXT_NORM, while in this case we are converting the
delayed allocation to unwritten, so it needs to be updated to
XFS_EXT_UNWRITTEN. This LF|RF|RC case does not do this, and so
the resultant extent is always written.

And that's the bug I've been chasing for a week - a bmap btree bug,
not a reflink/dedupe/copy_file_range bug, but a BMBT bug introduced
with the recent in core extent tree scalability enhancements.

Signed-off-by: Dave Chinner <dchinner@redhat.com>
Reviewed-by: Christoph Hellwig <hch@lst.de>
Reviewed-by: Darrick J. Wong <darrick.wong@oracle.com>
Signed-off-by: Darrick J. Wong <darrick.wong@oracle.com>
1 parent 2c30717
Raw File
Tip revision: 9230a0b65b47fe6856c4468ec0175c4987e5bede authored by Dave Chinner on 20 November 2018, 06:50:08 UTC
xfs: delalloc -> unwritten COW fork allocation can go wrong
Tip revision: 9230a0b
test_printf.c
/*
 * Test cases for printf facility.
 */

#define pr_fmt(fmt) KBUILD_MODNAME ": " fmt

#include <linux/init.h>
#include <linux/kernel.h>
#include <linux/module.h>
#include <linux/printk.h>
#include <linux/random.h>
#include <linux/slab.h>
#include <linux/string.h>

#include <linux/bitmap.h>
#include <linux/dcache.h>
#include <linux/socket.h>
#include <linux/in.h>

#include <linux/gfp.h>
#include <linux/mm.h>

#define BUF_SIZE 256
#define PAD_SIZE 16
#define FILL_CHAR '$'

static unsigned total_tests __initdata;
static unsigned failed_tests __initdata;
static char *test_buffer __initdata;
static char *alloced_buffer __initdata;

static int __printf(4, 0) __init
do_test(int bufsize, const char *expect, int elen,
	const char *fmt, va_list ap)
{
	va_list aq;
	int ret, written;

	total_tests++;

	memset(alloced_buffer, FILL_CHAR, BUF_SIZE + 2*PAD_SIZE);
	va_copy(aq, ap);
	ret = vsnprintf(test_buffer, bufsize, fmt, aq);
	va_end(aq);

	if (ret != elen) {
		pr_warn("vsnprintf(buf, %d, \"%s\", ...) returned %d, expected %d\n",
			bufsize, fmt, ret, elen);
		return 1;
	}

	if (memchr_inv(alloced_buffer, FILL_CHAR, PAD_SIZE)) {
		pr_warn("vsnprintf(buf, %d, \"%s\", ...) wrote before buffer\n", bufsize, fmt);
		return 1;
	}

	if (!bufsize) {
		if (memchr_inv(test_buffer, FILL_CHAR, BUF_SIZE + PAD_SIZE)) {
			pr_warn("vsnprintf(buf, 0, \"%s\", ...) wrote to buffer\n",
				fmt);
			return 1;
		}
		return 0;
	}

	written = min(bufsize-1, elen);
	if (test_buffer[written]) {
		pr_warn("vsnprintf(buf, %d, \"%s\", ...) did not nul-terminate buffer\n",
			bufsize, fmt);
		return 1;
	}

	if (memchr_inv(test_buffer + written + 1, FILL_CHAR, BUF_SIZE + PAD_SIZE - (written + 1))) {
		pr_warn("vsnprintf(buf, %d, \"%s\", ...) wrote beyond the nul-terminator\n",
			bufsize, fmt);
		return 1;
	}

	if (memcmp(test_buffer, expect, written)) {
		pr_warn("vsnprintf(buf, %d, \"%s\", ...) wrote '%s', expected '%.*s'\n",
			bufsize, fmt, test_buffer, written, expect);
		return 1;
	}
	return 0;
}

static void __printf(3, 4) __init
__test(const char *expect, int elen, const char *fmt, ...)
{
	va_list ap;
	int rand;
	char *p;

	if (elen >= BUF_SIZE) {
		pr_err("error in test suite: expected output length %d too long. Format was '%s'.\n",
		       elen, fmt);
		failed_tests++;
		return;
	}

	va_start(ap, fmt);

	/*
	 * Every fmt+args is subjected to four tests: Three where we
	 * tell vsnprintf varying buffer sizes (plenty, not quite
	 * enough and 0), and then we also test that kvasprintf would
	 * be able to print it as expected.
	 */
	failed_tests += do_test(BUF_SIZE, expect, elen, fmt, ap);
	rand = 1 + prandom_u32_max(elen+1);
	/* Since elen < BUF_SIZE, we have 1 <= rand <= BUF_SIZE. */
	failed_tests += do_test(rand, expect, elen, fmt, ap);
	failed_tests += do_test(0, expect, elen, fmt, ap);

	p = kvasprintf(GFP_KERNEL, fmt, ap);
	if (p) {
		total_tests++;
		if (memcmp(p, expect, elen+1)) {
			pr_warn("kvasprintf(..., \"%s\", ...) returned '%s', expected '%s'\n",
				fmt, p, expect);
			failed_tests++;
		}
		kfree(p);
	}
	va_end(ap);
}

#define test(expect, fmt, ...)					\
	__test(expect, strlen(expect), fmt, ##__VA_ARGS__)

static void __init
test_basic(void)
{
	/* Work around annoying "warning: zero-length gnu_printf format string". */
	char nul = '\0';

	test("", &nul);
	test("100%", "100%%");
	test("xxx%yyy", "xxx%cyyy", '%');
	__test("xxx\0yyy", 7, "xxx%cyyy", '\0');
}

static void __init
test_number(void)
{
	test("0x1234abcd  ", "%#-12x", 0x1234abcd);
	test("  0x1234abcd", "%#12x", 0x1234abcd);
	test("0|001| 12|+123| 1234|-123|-1234", "%d|%03d|%3d|%+d|% d|%+d|% d", 0, 1, 12, 123, 1234, -123, -1234);
	test("0|1|1|128|255", "%hhu|%hhu|%hhu|%hhu|%hhu", 0, 1, 257, 128, -1);
	test("0|1|1|-128|-1", "%hhd|%hhd|%hhd|%hhd|%hhd", 0, 1, 257, 128, -1);
	test("2015122420151225", "%ho%ho%#ho", 1037, 5282, -11627);
	/*
	 * POSIX/C99: »The result of converting zero with an explicit
	 * precision of zero shall be no characters.« Hence the output
	 * from the below test should really be "00|0||| ". However,
	 * the kernel's printf also produces a single 0 in that
	 * case. This test case simply documents the current
	 * behaviour.
	 */
	test("00|0|0|0|0", "%.2d|%.1d|%.0d|%.*d|%1.0d", 0, 0, 0, 0, 0, 0);
#ifndef __CHAR_UNSIGNED__
	{
		/*
		 * Passing a 'char' to a %02x specifier doesn't do
		 * what was presumably the intention when char is
		 * signed and the value is negative. One must either &
		 * with 0xff or cast to u8.
		 */
		char val = -16;
		test("0xfffffff0|0xf0|0xf0", "%#02x|%#02x|%#02x", val, val & 0xff, (u8)val);
	}
#endif
}

static void __init
test_string(void)
{
	test("", "%s%.0s", "", "123");
	test("ABCD|abc|123", "%s|%.3s|%.*s", "ABCD", "abcdef", 3, "123456");
	test("1  |  2|3  |  4|5  ", "%-3s|%3s|%-*s|%*s|%*s", "1", "2", 3, "3", 3, "4", -3, "5");
	test("1234      ", "%-10.4s", "123456");
	test("      1234", "%10.4s", "123456");
	/*
	 * POSIX and C99 say that a negative precision (which is only
	 * possible to pass via a * argument) should be treated as if
	 * the precision wasn't present, and that if the precision is
	 * omitted (as in %.s), the precision should be taken to be
	 * 0. However, the kernel's printf behave exactly opposite,
	 * treating a negative precision as 0 and treating an omitted
	 * precision specifier as if no precision was given.
	 *
	 * These test cases document the current behaviour; should
	 * anyone ever feel the need to follow the standards more
	 * closely, this can be revisited.
	 */
	test("    ", "%4.*s", -5, "123456");
	test("123456", "%.s", "123456");
	test("a||", "%.s|%.0s|%.*s", "a", "b", 0, "c");
	test("a  |   |   ", "%-3.s|%-3.0s|%-3.*s", "a", "b", 0, "c");
}

#define PLAIN_BUF_SIZE 64	/* leave some space so we don't oops */

#if BITS_PER_LONG == 64

#define PTR_WIDTH 16
#define PTR ((void *)0xffff0123456789abUL)
#define PTR_STR "ffff0123456789ab"
#define PTR_VAL_NO_CRNG "(____ptrval____)"
#define ZEROS "00000000"	/* hex 32 zero bits */

static int __init
plain_format(void)
{
	char buf[PLAIN_BUF_SIZE];
	int nchars;

	nchars = snprintf(buf, PLAIN_BUF_SIZE, "%p", PTR);

	if (nchars != PTR_WIDTH)
		return -1;

	if (strncmp(buf, PTR_VAL_NO_CRNG, PTR_WIDTH) == 0) {
		pr_warn("crng possibly not yet initialized. plain 'p' buffer contains \"%s\"",
			PTR_VAL_NO_CRNG);
		return 0;
	}

	if (strncmp(buf, ZEROS, strlen(ZEROS)) != 0)
		return -1;

	return 0;
}

#else

#define PTR_WIDTH 8
#define PTR ((void *)0x456789ab)
#define PTR_STR "456789ab"
#define PTR_VAL_NO_CRNG "(ptrval)"

static int __init
plain_format(void)
{
	/* Format is implicitly tested for 32 bit machines by plain_hash() */
	return 0;
}

#endif	/* BITS_PER_LONG == 64 */

static int __init
plain_hash(void)
{
	char buf[PLAIN_BUF_SIZE];
	int nchars;

	nchars = snprintf(buf, PLAIN_BUF_SIZE, "%p", PTR);

	if (nchars != PTR_WIDTH)
		return -1;

	if (strncmp(buf, PTR_VAL_NO_CRNG, PTR_WIDTH) == 0) {
		pr_warn("crng possibly not yet initialized. plain 'p' buffer contains \"%s\"",
			PTR_VAL_NO_CRNG);
		return 0;
	}

	if (strncmp(buf, PTR_STR, PTR_WIDTH) == 0)
		return -1;

	return 0;
}

/*
 * We can't use test() to test %p because we don't know what output to expect
 * after an address is hashed.
 */
static void __init
plain(void)
{
	int err;

	err = plain_hash();
	if (err) {
		pr_warn("plain 'p' does not appear to be hashed\n");
		failed_tests++;
		return;
	}

	err = plain_format();
	if (err) {
		pr_warn("hashing plain 'p' has unexpected format\n");
		failed_tests++;
	}
}

static void __init
symbol_ptr(void)
{
}

static void __init
kernel_ptr(void)
{
	/* We can't test this without access to kptr_restrict. */
}

static void __init
struct_resource(void)
{
}

static void __init
addr(void)
{
}

static void __init
escaped_str(void)
{
}

static void __init
hex_string(void)
{
	const char buf[3] = {0xc0, 0xff, 0xee};

	test("c0 ff ee|c0:ff:ee|c0-ff-ee|c0ffee",
	     "%3ph|%3phC|%3phD|%3phN", buf, buf, buf, buf);
	test("c0 ff ee|c0:ff:ee|c0-ff-ee|c0ffee",
	     "%*ph|%*phC|%*phD|%*phN", 3, buf, 3, buf, 3, buf, 3, buf);
}

static void __init
mac(void)
{
	const u8 addr[6] = {0x2d, 0x48, 0xd6, 0xfc, 0x7a, 0x05};

	test("2d:48:d6:fc:7a:05", "%pM", addr);
	test("05:7a:fc:d6:48:2d", "%pMR", addr);
	test("2d-48-d6-fc-7a-05", "%pMF", addr);
	test("2d48d6fc7a05", "%pm", addr);
	test("057afcd6482d", "%pmR", addr);
}

static void __init
ip4(void)
{
	struct sockaddr_in sa;

	sa.sin_family = AF_INET;
	sa.sin_port = cpu_to_be16(12345);
	sa.sin_addr.s_addr = cpu_to_be32(0x7f000001);

	test("127.000.000.001|127.0.0.1", "%pi4|%pI4", &sa.sin_addr, &sa.sin_addr);
	test("127.000.000.001|127.0.0.1", "%piS|%pIS", &sa, &sa);
	sa.sin_addr.s_addr = cpu_to_be32(0x01020304);
	test("001.002.003.004:12345|1.2.3.4:12345", "%piSp|%pISp", &sa, &sa);
}

static void __init
ip6(void)
{
}

static void __init
ip(void)
{
	ip4();
	ip6();
}

static void __init
uuid(void)
{
	const char uuid[16] = {0x0, 0x1, 0x2, 0x3, 0x4, 0x5, 0x6, 0x7,
			       0x8, 0x9, 0xa, 0xb, 0xc, 0xd, 0xe, 0xf};

	test("00010203-0405-0607-0809-0a0b0c0d0e0f", "%pUb", uuid);
	test("00010203-0405-0607-0809-0A0B0C0D0E0F", "%pUB", uuid);
	test("03020100-0504-0706-0809-0a0b0c0d0e0f", "%pUl", uuid);
	test("03020100-0504-0706-0809-0A0B0C0D0E0F", "%pUL", uuid);
}

static struct dentry test_dentry[4] __initdata = {
	{ .d_parent = &test_dentry[0],
	  .d_name = QSTR_INIT(test_dentry[0].d_iname, 3),
	  .d_iname = "foo" },
	{ .d_parent = &test_dentry[0],
	  .d_name = QSTR_INIT(test_dentry[1].d_iname, 5),
	  .d_iname = "bravo" },
	{ .d_parent = &test_dentry[1],
	  .d_name = QSTR_INIT(test_dentry[2].d_iname, 4),
	  .d_iname = "alfa" },
	{ .d_parent = &test_dentry[2],
	  .d_name = QSTR_INIT(test_dentry[3].d_iname, 5),
	  .d_iname = "romeo" },
};

static void __init
dentry(void)
{
	test("foo", "%pd", &test_dentry[0]);
	test("foo", "%pd2", &test_dentry[0]);

	test("romeo", "%pd", &test_dentry[3]);
	test("alfa/romeo", "%pd2", &test_dentry[3]);
	test("bravo/alfa/romeo", "%pd3", &test_dentry[3]);
	test("/bravo/alfa/romeo", "%pd4", &test_dentry[3]);
	test("/bravo/alfa", "%pd4", &test_dentry[2]);

	test("bravo/alfa  |bravo/alfa  ", "%-12pd2|%*pd2", &test_dentry[2], -12, &test_dentry[2]);
	test("  bravo/alfa|  bravo/alfa", "%12pd2|%*pd2", &test_dentry[2], 12, &test_dentry[2]);
}

static void __init
struct_va_format(void)
{
}

static void __init
struct_clk(void)
{
}

static void __init
large_bitmap(void)
{
	const int nbits = 1 << 16;
	unsigned long *bits = kcalloc(BITS_TO_LONGS(nbits), sizeof(long), GFP_KERNEL);
	if (!bits)
		return;

	bitmap_set(bits, 1, 20);
	bitmap_set(bits, 60000, 15);
	test("1-20,60000-60014", "%*pbl", nbits, bits);
	kfree(bits);
}

static void __init
bitmap(void)
{
	DECLARE_BITMAP(bits, 20);
	const int primes[] = {2,3,5,7,11,13,17,19};
	int i;

	bitmap_zero(bits, 20);
	test("00000|00000", "%20pb|%*pb", bits, 20, bits);
	test("|", "%20pbl|%*pbl", bits, 20, bits);

	for (i = 0; i < ARRAY_SIZE(primes); ++i)
		set_bit(primes[i], bits);
	test("a28ac|a28ac", "%20pb|%*pb", bits, 20, bits);
	test("2-3,5,7,11,13,17,19|2-3,5,7,11,13,17,19", "%20pbl|%*pbl", bits, 20, bits);

	bitmap_fill(bits, 20);
	test("fffff|fffff", "%20pb|%*pb", bits, 20, bits);
	test("0-19|0-19", "%20pbl|%*pbl", bits, 20, bits);

	large_bitmap();
}

static void __init
netdev_features(void)
{
}

static void __init
flags(void)
{
	unsigned long flags;
	gfp_t gfp;
	char *cmp_buffer;

	flags = 0;
	test("", "%pGp", &flags);

	/* Page flags should filter the zone id */
	flags = 1UL << NR_PAGEFLAGS;
	test("", "%pGp", &flags);

	flags |= 1UL << PG_uptodate | 1UL << PG_dirty | 1UL << PG_lru
		| 1UL << PG_active | 1UL << PG_swapbacked;
	test("uptodate|dirty|lru|active|swapbacked", "%pGp", &flags);


	flags = VM_READ | VM_EXEC | VM_MAYREAD | VM_MAYWRITE | VM_MAYEXEC
			| VM_DENYWRITE;
	test("read|exec|mayread|maywrite|mayexec|denywrite", "%pGv", &flags);

	gfp = GFP_TRANSHUGE;
	test("GFP_TRANSHUGE", "%pGg", &gfp);

	gfp = GFP_ATOMIC|__GFP_DMA;
	test("GFP_ATOMIC|GFP_DMA", "%pGg", &gfp);

	gfp = __GFP_ATOMIC;
	test("__GFP_ATOMIC", "%pGg", &gfp);

	cmp_buffer = kmalloc(BUF_SIZE, GFP_KERNEL);
	if (!cmp_buffer)
		return;

	/* Any flags not translated by the table should remain numeric */
	gfp = ~__GFP_BITS_MASK;
	snprintf(cmp_buffer, BUF_SIZE, "%#lx", (unsigned long) gfp);
	test(cmp_buffer, "%pGg", &gfp);

	snprintf(cmp_buffer, BUF_SIZE, "__GFP_ATOMIC|%#lx",
							(unsigned long) gfp);
	gfp |= __GFP_ATOMIC;
	test(cmp_buffer, "%pGg", &gfp);

	kfree(cmp_buffer);
}

static void __init
test_pointer(void)
{
	plain();
	symbol_ptr();
	kernel_ptr();
	struct_resource();
	addr();
	escaped_str();
	hex_string();
	mac();
	ip();
	uuid();
	dentry();
	struct_va_format();
	struct_clk();
	bitmap();
	netdev_features();
	flags();
}

static int __init
test_printf_init(void)
{
	alloced_buffer = kmalloc(BUF_SIZE + 2*PAD_SIZE, GFP_KERNEL);
	if (!alloced_buffer)
		return -ENOMEM;
	test_buffer = alloced_buffer + PAD_SIZE;

	test_basic();
	test_number();
	test_string();
	test_pointer();

	kfree(alloced_buffer);

	if (failed_tests == 0)
		pr_info("all %u tests passed\n", total_tests);
	else
		pr_warn("failed %u out of %u tests\n", failed_tests, total_tests);

	return failed_tests ? -EINVAL : 0;
}

module_init(test_printf_init);

MODULE_AUTHOR("Rasmus Villemoes <linux@rasmusvillemoes.dk>");
MODULE_LICENSE("GPL");
back to top