regression: statfs() takes a long time on VFAT without "usefree"

[komputes]

We will be comparing load time for a disk (USB or SD) in Jaunty vs. Karmic to demonstrate that in karmic nautilus takes a long time before displaying its contents.

This is essentially bug 133567, which is back in Karmic.

Steps to reproduce:

Need Materials: Jaunty CD, Karmic CD, stopwatch. it is good to gave a large usb drive (160GB, 1TB etc) and a smaller usb drive (8GB, 16GB) and make sure they are full of files,.

1) In Jaunty, plug in a 8GB and time how long it takes to mount & show contents.
2) In Karmic, plug in a 8GB and time how long it takes to mount & show contents.
3) In Jaunty, plug in a 1TB and time how long it takes to mount & show contents.
4) In Karmic, plug in a 1TB and time how long it takes to mount & show contents.

Result: Mounting a disk in karmic takes much longer than in jaunty. In karmic, the larger the drive the longer the wait time before being able to see the contents. During this wait, there is no progress bar displayed. If a user clicks on the drive again to have it mount, they will get an unusual (un-human-friendly) error. See attachment for error.

Expected: Newer version of ubuntu should improve performance instead of making basic functionality slower and introduce new errors.

[komputes (komputes)]

With the latest updates, instead of showing the user some indication of progress, the authentication window stays open until it can mount the drive. The same error shows up if the user tried to "quicken" the process by going into nautilus and mounting the drive from the side panel, or by mounting it through Places > DriveName

[Martin Pitt (pitti)]

Note to myself:This reminds me of the "usefree" hack we had to do in hardy. Either this is back (and it's just nautilus which is slow to scan the drive), or the mount itself really takes that long. Should be easy to tell apart by ls -l /media/<label>/ right after mounting.

[Martin Pitt (pitti)]

I updated the desscription accordingly. This is essentially bug 133567. The actual mounting is quick, and you can use "ls /media/mystuff/ to browse the device, but nautilus takes so long because it does statfs() to find out some metadata, such as remaining free space.

This can be tested easily with mounting a large VFAT drive, and doing "df -h" and "ls -l /media/mystuff". The ls will work instantly, while the df() hangs a long time. (Over a minute for my 500 GB drive).

[Martin Pitt (pitti)]

I also confirmed that mounting vfat with the "usefree" option works fine.

We introduced the "usefree" workaround in gutsy, and dropped it again in hardy, since the kernel was fixed to not take ages to scan the disk without "usefree" any more. This worked until 2.6.28 in Jaunty, and regressed in 2.6.31 in Karmic again.

Kernel team, should I add the "usefree" workaround to the default vfat mount option in dk-disks, or do you think it's easy and desirable to fix that in the kernel proper?

[Martin Pitt (pitti)]

Since this is a major regression, I want to either fix (linux) or workaround (dk-disks mount option) this for the final release.

Kernel team, please feel free to "wontfix" the linux task for karmic if it isn't feasible to fix this properly in karmic. (Then we'll get the "floating" task back for lucid and later).

[Martin Pitt (pitti)]

Michael Biebl, do you get the same effect in sid with 2.6.30? Want me to commit the "usefree" workaround to Debian as well, or should I keep it as an Ubuntu specific patch?

[Andy Whitcroft (apw)]

@pitti -- that original fix in 2.6.28 timeframe appears to have been adding readahead to FAT chain scanning in fat_count_free_clusters() in the commit below:

  commit 9f966be8996f2829406324c68e4c67c2d64d864b
  Author: OGAWA Hirofumi <email address hidden>
  Date: Tue Jan 8 15:32:41 2008 -0800

    fat: optimize fat_count_free_clusters()

That change does not appear to have been undone specifically still appearing in the Karmic kernel.

Doing a quick test here with a 500GB USB drive I am not seeing any particularly spectacularly huge delay (this is with 2.6.31-13.43-generic):

    # echo 3 >/proc/sys/vm/drop_caches
    # mount /dev/sdc1 /mnt; time df -h
    [...]
    /dev/sdc1 459G 45G 391G 11% /mnt

    real 0m0.012s
    user 0m0.004s
    sys 0m0.000s

[Andy Whitcroft (apw)]

@pitti -- could you paste up your steps to reproduce by if they differ from mine.

[Martin Pitt (pitti)]

Sure. First, I disabled dk-disks to turn off all automount magic:

# killall devkit-disks-daemon
# chmod 0 /usr/lib/devicekit-disks/devkit-disks-daemon

Now, mount my removable USB HD:

# echo 3 >/proc/sys/vm/drop_caches
# mount /dev/sdb1 /mnt; time df -h
[...]
/dev/sdb1 233G 226G 7,5G 97% /mnt

real 1m16.649s
user 0m0.000s
sys 0m1.050s

It works fine with usefree:

# mount -o usefree /dev/sdb1 /mnt; time df -h
[...]
/dev/sdb1 233G 226G 7,5G 97% /mnt

real 0m0.005s
user 0m0.010s
sys 0m0.000s

And strace shows that it's statfs:

# mount /dev/sdb1 /mnt; strace -vtt df -h
[...]
12:15:12.103174 statfs("/home/martin/.gv
f_files=0, f_ffree=0, f_fsid={0, 0}, f_n
12:15:12.103312 statfs("/mnt",

... long pause here, with

root 21844 2.9 0.0 5536 940 pts/5 D+ 12:15 0:01 df -h

(deep kernel sleep)

and a minute later it finishes:

12:15:12.103312 statfs("/mnt", {f_type="MSDOS_SUPER_MAGIC", f_bsize=16384, f_blocks=15254800, f_bfree=486982, f_bavail=486982, f_files=0, f_ffree=0, f_fsid={2065, 0}, f_namelen=260, f_frsize=16384}) = 0
12:16:26.772458 write(1, "/dev/sdb1 233G 226G"..., 49/dev/sdb1 233G 226G 7,5G 97% /mnt

[Martin Pitt (pitti)]

I have an amd64 installation, not sure whether this matters.

[Martin Pitt (pitti)]

Oh, and just for completeness:

$ cat /proc/version_signature
Ubuntu 2.6.31-13.44-generic

(but it has happened for months already, it's not something recent)

[Andy Whitcroft (apw)]

@pitti -- thanks, my results were user error. picked the wrong disk out of my stash.

[Andy Whitcroft (apw)]

Ok after much debugging it appears there is a bug

[Andy Whitcroft (apw)]

Ok after much debugging it appears there is a bug in the elevator affecting the merging of read-ahead requests. This is exposed horribly by the sequential scan of the FAT as required to calculate the current free information for a FAT filesystem on first mount. I think we have it nailed and have produced some test kernels with the fix. If you could test those and report back here that would be very useful. Kernels will be at the URL below shortly:

    http://people.canonical.com/~apw/lp444915-karmic/

[Martin Pitt (pitti)]

Andy Whitcroft [2009-10-13 10:39 -0000]:
> Ok after much debugging it appears there is a bug

Andy, if it's something trivial, I think it'd be better to fix it in
the kernel. But as I said, I'm happy to add the usefree workaround if
it's not practical to fix this in the next week.

Thanks!

Martin
--
Martin Pitt | http://www.piware.de
Ubuntu Developer (www.ubuntu.com) | Debian Developer (www.debian.org)

[Martin Pitt (pitti)]

Works wonderfully, thank you!

[Martin Pitt (pitti)]

Since this is being fixed in the kernel, it looks like we won't need the usefree hack.

[Andy Whitcroft (apw)]

The fix appears 'obvious' so I think we can get it into the kernel. Submitted to the list for approval.

[Launchpad Janitor (janitor)]

This bug was fixed in the package linux - 2.6.31-14.46

---------------
linux (2.6.31-14.46) karmic; urgency=low

  [ Andy Whitcroft ]

  * reinstate armel.mk with no flavours
    - LP: #449637
  * [Upstream] elevator: fix fastfail checks to allow merge of readahead
    requests
    - LP: #444915
  * [Upstream] block: silently error unsupported empty barriers too
    - LP: #420423

  [ John Johansen ]

  * SAUCE: AppArmor: Fix mediation of "deleted" paths
    - LP: #415632

  [ Tim Gardner ]

  * [Config] CONFIG_X86_MCE
    https://lists.ubuntu.com/archives/kernel-team/2009-October/007584.html
  * Revert "appletalk: Fix skb leak when ipddp interface is not loaded,
    CVE-2009-2903" - Use patch from 2.6.31.4 which is slightly different.

  [ Upstream Kernel Changes ]

  * x86: fix csum_ipv6_magic asm memory clobber
  * tty: Avoid dropping ldisc_mutex over hangup tty re-initialization
  * x86: Don't leak 64-bit kernel register values to 32-bit processes
  * tracing: correct module boundaries for ftrace_release
  * ftrace: check for failure for all conversions
  * futex: fix requeue_pi key imbalance
  * futex: Move exit_pi_state() call to release_mm()
  * futex: Nullify robust lists after cleanup
  * futex: Fix locking imbalance
  * NOHZ: update idle state also when NOHZ is inactive
  * ima: ecryptfs fix imbalance message
  * libata: fix incorrect link online check during probe
  * sound: via82xx: move DXS volume controls to PCM interface
  * ASoC: WM8350 capture PGA mutes are inverted
  * KVM: Prevent overflow in KVM_GET_SUPPORTED_CPUID
  * KVM: VMX: flush TLB with INVEPT on cpu migration
  * KVM: fix LAPIC timer period overflow
  * KVM: SVM: Fix tsc offset adjustment when running nested
  * KVM: SVM: Handle tsc in svm_get_msr/svm_set_msr correctly
  * net: Fix wrong sizeof
  * mm: add_to_swap_cache() must not sleep
  * sis5513: fix PIO setup for ATAPI devices
  * PIT fixes to unbreak suspend/resume (bug #14222)
  * IMA: open new file for read
  * ACPI: Clarify resource conflict message
  * ACPI: fix Compaq Evo N800c (Pentium 4m) boot hang regression
  * net: restore tx timestamping for accelerated vlans
  * net: unix: fix sending fds in multiple buffers
  * tun: Return -EINVAL if neither IFF_TUN nor IFF_TAP is set.
  * tcp: fix CONFIG_TCP_MD5SIG + CONFIG_PREEMPT timer BUG()
  * net: Fix sock_wfree() race
  * smsc95xx: fix transmission where ZLP is expected
  * sky2: Set SKY2_HW_RAM_BUFFER in sky2_init
  * appletalk: Fix skb leak when ipddp interface is not loaded
  * ax25: Fix possible oops in ax25_make_new
  * ax25: Fix SIOCAX25GETINFO ioctl
  * sit: fix off-by-one in ipip6_tunnel_get_prl
  * Linux 2.6.31.4
  * drm/i915: Fix FDI M/N setting according with correct color depth
    - LP: #416792

 -- Andy Whitcroft <email address hidden> Tue, 13 Oct 2009 12:06:59 +0100