From owner-freebsd-stable@FreeBSD.ORG Thu Jul 18 05:18:00 2013 Return-Path: Delivered-To: freebsd-stable@freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [8.8.178.115]) by hub.freebsd.org (Postfix) with ESMTP id A248EE27 for ; Thu, 18 Jul 2013 05:18:00 +0000 (UTC) (envelope-from rmtodd@servalan.servalan.com) Received: from ln.servalan.com (unknown [IPv6:2600:3c00::f03c:91ff:fe96:62f5]) by mx1.freebsd.org (Postfix) with ESMTP id 7DC126A0 for ; Thu, 18 Jul 2013 05:18:00 +0000 (UTC) DKIM-Signature: v=1; a=rsa-sha256; q=dns/txt; c=relaxed/relaxed; d=servalan.com; s=rsadkim; h=Content-Type:MIME-Version:Message-ID:In-Reply-To:Date:From:References:Subject:To; bh=Lx7oVFmn5o7gbfUyrvgcZa8JJNkyJm3YtKTwO8o1yKk=; b=oV0m9uc7sbqlOnXRkIcq2XtbxBWFIL+F05/Quvr9vixr3D+ZlMzHxjgthnrrWWg7nAwkiLYlQbGFpLAkSgUaBNh1N1h59LeKqNnOI7RWrwfmIDpZ+qbOB3+nTZCQ4NRDJac6AOCuSdK6xuIuqcKXT3JsBajnLkWvelr7905YTvA=; Received: from uucp by ln.servalan.com with local-rmail (Exim 4.71) (envelope-from ) id 1UzgbH-0007pF-SW for freebsd-stable@freebsd.org; Thu, 18 Jul 2013 00:17:59 -0500 Received: from rmtodd by servalan.servalan.com with local (Exim 4.80.1 (FreeBSD)) (envelope-from ) id 1UzgXG-000HZw-5c; Thu, 18 Jul 2013 00:13:50 -0500 To: hartzell@alerce.com, freebsd-stable@freebsd.org Subject: Re: Help with filing a [maybe] ZFS/mmap bug. References: <20967.760.95825.310085@gargle.gargle.HOWL> From: Richard Todd Date: Thu, 18 Jul 2013 00:13:49 -0500 In-Reply-To: <20967.760.95825.310085@gargle.gargle.HOWL> (George Hartzell's message of "Wed, 17 Jul 2013 13:47:52 -0700") Message-ID: User-Agent: Gnus/5.1008 (Gnus v5.10.8) XEmacs/21.5-b28 (berkeley-unix) MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii X-BeenThere: freebsd-stable@freebsd.org X-Mailman-Version: 2.1.14 Precedence: list List-Id: Production branch of FreeBSD source code List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Thu, 18 Jul 2013 05:18:00 -0000 George Hartzell writes: > Hi All, > > I have what I think is a ZFS related bug. Unfortunately my simplest > test case is a bit cumbersome and I haven't definitively proven that > the problem is ZFS related. > I'm hoping for some feedback on how to move forward. > > Quick background: I rip my CD's using grip and produce flac files. I > tag the music using Musicbrainz' Picard and transcode it to mp3's > within Picard using a plugin that I wrote. Picard is a python based > app and uses the Mutagen library to tag files. [summary: Picard seems to trigger an mmap consistency bug in ZFS]. Aw, crud. I ran into what may be this same issue a few years ago, under almost identical circumstances (picard with Ogg files instead of flac), but never got around to writing up a proper mailinglist post on it. I *thought* it had been fixed some time back, though I'm not entirely sure because I've been running with my local patch to py-mutagen to disable its mmap() usage. Anyway, here's what I recall from when I was trying to track this down way back when: 1) Your suspicions are right, it's definitely a ZFS/mmap interaction bug. UFS filesystems didn't show the bug. 2) It's triggered by the insert_bytes or delete_bytes function in py-mutagen. 3) As long as the in-memory version of that chunk of the file stuck around in memory, the file read OK, but the data on disk was corrupt, so if that data got evicted from cache and had to be reread, or if you forced the cache data to be disposed of by unmounting and remounting the FS, you would see a corrupt file. (Rebooting, of course, would also allow the corrupted file data to become visible again.) I'll attach my patch to disable py-mutagen's mmap usage in insert/delete_bytes below. Try it and see if it makes the corruption problems go away. If so, that narrows your search down to those two routines in py-mutagen and what they're doing. I *had* what at the time I recall was a simple C++ test program that managed to trigger the bug more-or-less reliably. Unfortunately, it doesn't look like my test case still works, i.e., the test program doesn't seem to trigger the bug either on the 10-CURRENT box or RELENG-9 VM I'm trying them on now. As I recall, the bug's presence was dependent on fairly picky details on what exact offsets were used on the mmap()s and the write()s, so it may be that different offsets from what I tried will still show the bug. Anyway, what I'd suggest is the following: see if my patch for py-mutagen disabling the mmap() in those two functions lets you run picard reliably. If so, then the issue is triggered by one or both of those two routines; hack them to print out the exact offsets used on each call and use that to try and code up a simple C++ test case. Here's the py-mutagen patch: --- mutagen/_util.py.orig 2008-06-01 01:33:00.000000000 -0500 +++ mutagen/_util.py 2009-04-11 18:16:53.363758128 -0500 @@ -213,12 +213,6 @@ fobj.write('\x00' * size) fobj.flush() try: - try: - import mmap - map = mmap.mmap(fobj.fileno(), filesize + size) - try: map.move(offset + size, offset, movesize) - finally: map.close() - except (ValueError, EnvironmentError, ImportError): # handle broken mmap scenarios locked = lock(fobj) fobj.truncate(filesize) @@ -272,17 +266,11 @@ try: if movesize > 0: fobj.flush() - try: - import mmap - map = mmap.mmap(fobj.fileno(), filesize) - try: map.move(offset, offset + size, movesize) - finally: map.close() - except (ValueError, EnvironmentError, ImportError): - # handle broken mmap scenarios - locked = lock(fobj) - fobj.seek(offset + size) - buf = fobj.read(BUFFER_SIZE) - while buf: + # handle broken mmap scenarios + locked = lock(fobj) + fobj.seek(offset + size) + buf = fobj.read(BUFFER_SIZE) + while buf: fobj.seek(offset) fobj.write(buf) offset += len(buf) and here's my test case: # This is a shell archive. Save it in a file, remove anything before # this line, and then unpack it by entering "sh file". Note, it may # create directories; files and directories will be owned by you and # have default permissions. # # This archive contains: # # gen4.cpp # test4.sh # echo x - gen4.cpp sed 's/^X//' >gen4.cpp << 'END-of-gen4.cpp' X/* X** Program to create a file of data and do some mmap()ing writes to it. X*/ X X#include X#include X#include X#include X#include X#include X#include X#include X X/* Insert size bytes (zeros) into file at offset */ Xvoid Xinsert_bytes(int fd, unsigned int size, unsigned int offset) X{ X unsigned int filesize = lseek(fd, (off_t)0, SEEK_END); X unsigned int movesize = filesize - offset; X X char *buf = new char[size]; X for (unsigned int i = 0 ; i < size ; ++i) { X buf[i] = '\0'; X } X write(fd, buf, size); X X char *addr = (char *) mmap((void *)NULL, filesize+size, PROT_READ|PROT_WRITE, MAP_SHARED, fd, offset); X memmove(addr+size, addr, movesize); X if (munmap(addr, filesize+size)) { X perror("munmap"); X } X} X X/* Delete size bytes (zeros) from file at offset */ Xvoid Xdelete_bytes(int fd, unsigned int size, unsigned int offset) X{ X unsigned int filesize = lseek(fd, (off_t)0, SEEK_END); X unsigned int movesize = filesize - offset - size; X X char *addr = (char *) mmap((void *)NULL, filesize, PROT_READ|PROT_WRITE, MAP_SHARED, fd, offset); X memmove(addr, addr+size, movesize); X if (munmap(addr, filesize)) { X perror("munmap"); X } X ftruncate(fd, filesize - size); X} X X X X/* Usage: gen1 filename number-of-seconds */ Xint Xmain(int argc, char **argv) X{ X char *fname = argv[1]; X FILE *f = fopen(fname, "w"); X X unsigned int size = 1024; X X for (unsigned int i = 0 ; i < size ; ++i) { X char c = i & 0xff; X fwrite((void *)&c, 1, 1, f); X } X X fclose(f); X X int fd = open(fname, O_RDWR); X X unsigned int S1 = atoi(argv[2]); X#define O1 0 X insert_bytes(fd, S1, O1); X X (void) lseek(fd, (off_t) O1, SEEK_SET); X X#define S2 1 X#define O2 (O1+S1) X X delete_bytes(fd, S2, O2); X X exit(0); X} END-of-gen4.cpp echo x - test4.sh sed 's/^X//' >test4.sh << 'END-of-test4.sh' X#!/bin/sh X# Set the following variables appropriately X# ZFSFS name of your ZFS filesystem to test X# ZFSMP mount point of your ZFS filesystem to test X# ZFSDIR a writable dir somewhere under ZFSMP X# UFSDIR a writable dir somewhere on a UFS filesystem X# Script takes one argument, S1, a number of bytes. X XZFSFS=u1 XZFSMP=/u1 XZFSDIR=/u1/tmp XUFSDIR=/var/tmp X XNAME=$ZFSDIR/foo1 XS1=$1 Xrm $NAME X./gen4 $NAME $S1 Xmd5 $NAME Xcp $NAME $UFSDIR/before Xls -l $NAME Xsudo umount $ZFSMP Xsudo mount -t zfs $ZFSFS $ZFSMP Xmd5 $NAME Xls -l $NAME Xcp $NAME $UFSDIR/after Xcmp -l $UFSDIR/before $UFSDIR/after END-of-test4.sh exit