You are not logged in.

#1 2011-10-05 22:25:25

RetroX
Member
Registered: 2009-10-17
Posts: 106

[solved] Mount/unmount extremely slow (relatively)

When I first installed my system, mounting and unmounting took a relatively unnoticeable amount of time.  Now, mounting a single volume takes about a minute or more per volume, even for tmpfs volumes.  I don't seem to see any other performance problems with my system other than this.

The change happened rather suddenly after I shredded a partition on my drive with one run of bytes (the overall size was about 100 GiB, but I've written several times that onto my drive).  If it makes any difference, the partition was the one that's right to the left of my root partition, but I doubt that anything flowed over.  The disk seems to be operating fine, and when I mount from live CDs, it takes the normal time.

Has anyone ever experienced this kind of problem before?  Do you know what I can do to fix it without reinstalling my system?  I tried reinstalling both the linux and util-linux packages, but that didn't seem to help.


EDIT: Problem's been solved.  To fix:
- Downgrade to util-linux 2.20-2.
- Save everything that you're working on.
- Run the following:
# echo 1 > /proc/sys/kernel/sysrq
# rm -rf /etc/mtab*
- Hold Alt + SysRq and then type out REISUB to reboot.

Last edited by RetroX (2011-10-08 19:09:26)

Offline

#2 2011-10-06 05:57:06

bernarcher
Forum Fellow
From: Germany
Registered: 2009-02-17
Posts: 2,281

Re: [solved] Mount/unmount extremely slow (relatively)

Not sure if it really helps but have you tried reformatting this partition?


To know or not to know ...
... the questions remain forever.

Offline

#3 2011-10-06 12:15:58

splondike
Member
Registered: 2008-10-19
Posts: 16

Re: [solved] Mount/unmount extremely slow (relatively)

I'm not sure I'm knowledgeable enough to help too much, but you might like to have a look at the strace command to debug this. It lets you see what calls a program makes to the kernel. You can compare its output on your arch system to what your live CD gives you.

Mounting an ext2 disk on my machine produces this summary (the -c option).  I got fairly varied output each time I ran the command, but hopefully yours is more consistent.

$ strace -c mount /dev/sdb2 /mnt/Backup/
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
100.00    0.000018           1        18           mmap2
  0.00    0.000000           0       101           read
  0.00    0.000000           0         4           write
  0.00    0.000000           0        20         6 open
  0.00    0.000000           0        14           close
  0.00    0.000000           0         1           execve
  0.00    0.000000           0         3           time
  0.00    0.000000           0         1         1 mount
  0.00    0.000000           0         1         1 access
  0.00    0.000000           0         3           brk
  0.00    0.000000           0         2         1 ioctl
  0.00    0.000000           0         1           umask
  0.00    0.000000           0        11        10 readlink
  0.00    0.000000           0         5           munmap
  0.00    0.000000           0         1           uname
  0.00    0.000000           0         7           mprotect
  0.00    0.000000           0        91           _llseek
  0.00    0.000000           0         2           prctl
  0.00    0.000000           0         2           rt_sigprocmask
  0.00    0.000000           0         5         3 stat64
  0.00    0.000000           0         2           lstat64
  0.00    0.000000           0        11           fstat64
  0.00    0.000000           0         3           getuid32
  0.00    0.000000           0         2           getgid32
  0.00    0.000000           0         3           geteuid32
  0.00    0.000000           0         2           getegid32
  0.00    0.000000           0         1           set_thread_area
  0.00    0.000000           0         1           fadvise64_64
  0.00    0.000000           0         1           fstatat64
------ ----------- ----------- --------- --------- ----------------
100.00    0.000018                   319        22 total

The summary is probably more interesting initially, but the full dump may be useful later (replace -c with -C for the the full dump combined with the summary).

Edit:
Another similar program you might like to look at is ltrace, which shows library calls (this article put me onto it).

$ ltrace -c mount /dev/sdb2 /mnt/Backup 
% time     seconds  usecs/call     calls      function
------ ----------- ----------- --------- --------------------
 48.11    0.046996       46996         1 blkid_do_safeprobe
 22.59    0.022073          49       445 strlen
 15.04    0.014694          28       507 strncmp
  3.45    0.003375        3375         1 mount
  2.37    0.002319        2319         1 blkid_probe_set_device
  2.10    0.002048        2048         1 mnt_update_table
  1.21    0.001181        1181         1 blkid_free_probe
  1.01    0.000989          26        37 __strdup
  0.39    0.000383         383         1 mnt_update_set_fs
  0.39    0.000382          76         5 __xstat64
  0.37    0.000358         358         1 setlocale
  0.29    0.000287          26        11 free
  0.28    0.000278         139         2 open64
  0.25    0.000247         123         2 close
  0.20    0.000198          49         4 readlink
  0.19    0.000181          25         7 __errno_location
  0.14    0.000136         136         1 blkid_evaluate_spec
  0.11    0.000109          27         4 strchr
  0.11    0.000108          27         4 strtok
  0.11    0.000104          26         4 sigdelset
  0.10    0.000097          48         2 sigprocmask
  0.09    0.000085          28         3 __snprintf_chk
  0.08    0.000080          26         3 strrchr
  0.07    0.000065          65         1 access
  0.06    0.000060          30         2 sigfillset
  0.06    0.000054          54         1 __lxstat64
  0.05    0.000051          51         1 getuid
  0.05    0.000050          50         1 mnt_fs_set_options
  0.05    0.000049          49         1 umask
  0.05    0.000047          47         1 geteuid
  0.05    0.000047          47         1 blkid_new_probe
  0.04    0.000040          40         1 blkid_probe_lookup_value
  0.04    0.000039          39         1 blkid_probe_set_superblocks_flags
  0.04    0.000037          37         1 blkid_probe_enable_superblocks
  0.04    0.000036          36         1 mnt_new_fs
  0.04    0.000035          35         1 getopt_long
  0.03    0.000034          34         1 mnt_init_debug
  0.03    0.000034          34         1 mnt_fs_set_source
  0.03    0.000033          33         1 bindtextdomain
  0.03    0.000032          32         1 mnt_fs_set_fstype
  0.03    0.000032          32         1 mnt_free_update
  0.03    0.000031          31         1 mnt_new_update
  0.03    0.000031          31         1 textdomain
  0.03    0.000030          30         1 malloc
  0.03    0.000030          30         1 __cxa_atexit
  0.03    0.000029          29         1 mnt_free_fs
  0.03    0.000028          28         1 mnt_fs_set_target
  0.03    0.000028          28         1 mnt_update_get_mflags
------ ----------- ----------- --------- --------------------
100.00    0.097690                  1074 total

Last edited by splondike (2011-10-06 12:21:07)

Offline

#4 2011-10-06 20:07:49

RetroX
Member
Registered: 2009-10-17
Posts: 106

Re: [solved] Mount/unmount extremely slow (relatively)

bernarcher: I don't think that that will help, because the file system is sound.  It applies to RAM disks, to, and nothing but mount seems to be affected.  Plus, I'd rather not have to install unless my system is completely broken; at this point, it's not really worth reinstalling for a minor inconvenience that could possibly be fixable.


splondike: When mounting an ext4 volume, I get:

$ sudo strace -c mount /media/stuff
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 64.04    0.043333           8      5619           nanosleep
 34.48    0.023331       23331         1           mount
  0.95    0.000640           0      5633           close
  0.17    0.000113           0      5620      5620 link
  0.12    0.000078           0     11238           alarm
  0.11    0.000076           0      5634         1 open
  0.10    0.000066           0     11238           rt_sigaction
  0.04    0.000030           0      5619           fcntl
  0.00    0.000000           0        98           read
  0.00    0.000000           0        10         6 stat
  0.00    0.000000           0         9           fstat
  0.00    0.000000           0         2           lstat
  0.00    0.000000           0        91           lseek
  0.00    0.000000           0        17           mmap
  0.00    0.000000           0        10           mprotect
  0.00    0.000000           0         3           munmap
  0.00    0.000000           0         3           brk
  0.00    0.000000           0         4           rt_sigprocmask
  0.00    0.000000           0         2         1 ioctl
  0.00    0.000000           0         2         1 access
  0.00    0.000000           0         1           getpid
  0.00    0.000000           0         1           execve
  0.00    0.000000           0         1           uname
  0.00    0.000000           0         1           unlink
  0.00    0.000000           0        10         8 readlink
  0.00    0.000000           0         3           umask
  0.00    0.000000           0         3           getuid
  0.00    0.000000           0         2           getgid
  0.00    0.000000           0         3           geteuid
  0.00    0.000000           0         2           getegid
  0.00    0.000000           0         2           prctl
  0.00    0.000000           0         1           arch_prctl
  0.00    0.000000           0         1           fadvise64
  0.00    0.000000           0         1           newfstatat
------ ----------- ----------- --------- --------- ----------------
100.00    0.067667                 50885      5637 total

Obviously, there are more calls here than in yours, but I think that it's simply due to the fact that it's ext4 instead of ext2.  The abundance of sleep calls is also a bit disconcerting.  The fact that the time is off is unsettling, though, especially:

# time umount /media/stuff
real	0m29.284s
user	0m0.010s
sys	0m0.080s

# time mount /media/stuff
real	0m29.353s
user	0m0.017s
sys	0m0.103s

(note that strace took the same amount of time, but didn't actually display it)

So, the mount time isn't really what's wrong, but the shell?  I just tried reinstalling bash and it didn't seem to do anything.  I thought that the real time was just the user and system time added together, but it doesn't seem to be that way.

Offline

#5 2011-10-08 02:54:24

splondike
Member
Registered: 2008-10-19
Posts: 16

Re: [solved] Mount/unmount extremely slow (relatively)

That's quite a different output to mine. I mounted and unmounted my ext4 home partition from single user mode within arch and got the following:

Mount:

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
100.00    0.016665       16665         1           mount
  0.00    0.000000           0        10           read
  0.00    0.000000           0         1           write
  0.00    0.000000           0        15           open
  0.00    0.000000           0        15           close
  0.00    0.000000           0         1           link
  0.00    0.000000           0         4         2 unlink
  0.00    0.000000           0         1           execve
  0.00    0.000000           0         1           getpid
  0.00    0.000000           0         2         1 access
  0.00    0.000000           0         1           rename
  0.00    0.000000           0         3           brk
  0.00    0.000000           0         3           umask
  0.00    0.000000           0         2           gettimeofday
  0.00    0.000000           0         9         7 readlink
  0.00    0.000000           0         6           munmap
  0.00    0.000000           0         1           fchmod
  0.00    0.000000           0         7           mprotect
  0.00    0.000000           0         1           _llseek
  0.00    0.000000           0         1           prctl
  0.00    0.000000           0         4           rt_sigprocmask
  0.00    0.000000           0        19           mmap2
  0.00    0.000000           0         9         6 stat64
  0.00    0.000000           0         2           lstat64
  0.00    0.000000           0        11           fstat64
  0.00    0.000000           0         2           getuid32
  0.00    0.000000           0         1           getgid32
  0.00    0.000000           0         2           geteuid32
  0.00    0.000000           0         1           getegid32
  0.00    0.000000           0         1           fchown32
  0.00    0.000000           0         2           fcntl64
  0.00    0.000000           0         1           set_thread_area
------ ----------- ----------- --------- --------- ----------------
100.00    0.016665                   140        16 total

Unmount:

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
  -nan    0.000000           0         8           read
  -nan    0.000000           0         1           write
  -nan    0.000000           0        12           open
  -nan    0.000000           0        12           close
  -nan    0.000000           0         1           link
  -nan    0.000000           0         4         2 unlink
  -nan    0.000000           0         1           execve
  -nan    0.000000           0         1           getpid
  -nan    0.000000           0         1           oldumount
  -nan    0.000000           0         1         1 access
  -nan    0.000000           0         1           rename
  -nan    0.000000           0         3           brk
  -nan    0.000000           0         1           umask
  -nan    0.000000           0         2           gettimeofday
  -nan    0.000000           0         1         1 readlink
  -nan    0.000000           0         4           munmap
  -nan    0.000000           0         1           fchmod
  -nan    0.000000           0         7           mprotect
  -nan    0.000000           0         1           _llseek
  -nan    0.000000           0         2           prctl
  -nan    0.000000           0         4           rt_sigprocmask
  -nan    0.000000           0        17           mmap2
  -nan    0.000000           0         3         1 stat64
  -nan    0.000000           0         2           lstat64
  -nan    0.000000           0         9           fstat64
  -nan    0.000000           0         3           getuid32
  -nan    0.000000           0         2           getgid32
  -nan    0.000000           0         3           geteuid32
  -nan    0.000000           0         2           getegid32
  -nan    0.000000           0         1           fchown32
  -nan    0.000000           0         2           fcntl64
  -nan    0.000000           0         1           set_thread_area
------ ----------- ----------- --------- --------- ----------------
100.00    0.000000                   114         5 total

Far fewer syscalls in my output, and quite different ones too. I also note that the 'link' syscall in your output error-ed out every time. If you run it now with the -C option and -o <dump-file> options, then have a look in the output for the link calls, they should tell you why they're failing.

I notice my *stat commands are suffixed with 64 and yours aren't. I'm running a 32 bit machine, what architecture is yours? Also, what kernel version are you running (mine's 3.0) and what's the content of your /etc/fstab?

Offline

#6 2011-10-08 11:48:01

nob.dir
Member
Registered: 2011-10-08
Posts: 16

Re: [solved] Mount/unmount extremely slow (relatively)

Hi,

The problem is the util-linux package in version 2.20-3. I downgraded to 2.20-2 version, and it goes well now.
I added the bug(#26337): https://bugs.archlinux.org/task/26337.

nob.dir

Offline

#7 2011-10-08 19:09:07

RetroX
Member
Registered: 2009-10-17
Posts: 106

Re: [solved] Mount/unmount extremely slow (relatively)

nob.dir: Thank you so much.  That did the trick; I posted exactly what I did in the first post so that people can figure out how to solve this if they happen to have it.

splondike: I'm running x86_64 right now.  It's using the stat64 calls to emulate 64-bit so that your hardware isn't limited to 4 GiB in certain cases; they're just native in 64-bit.  I'm also using linux 3.0.6 and my fstab is a cluttery mess. tongue

Offline

#8 2011-10-09 11:04:47

splondike
Member
Registered: 2008-10-19
Posts: 16

Re: [solved] Mount/unmount extremely slow (relatively)

nob.dir swings in to save the day with his first post smile. Thanks for the explanation about the *64 calls.

Offline

#9 2011-10-22 09:20:55

atomisirsi
Member
Registered: 2011-03-18
Posts: 2

Re: [solved] Mount/unmount extremely slow (relatively)

Did anybody test the behaviour with latest util-linux 2.20.1?

PS: Thanks for your solution, nob.dir! This problem was really annoying.

Offline

#10 2011-10-22 16:23:17

falconindy
Developer
From: New York, USA
Registered: 2009-10-22
Posts: 4,111
Website

Re: [solved] Mount/unmount extremely slow (relatively)

atomisirsi wrote:

Did anybody test the behaviour with latest util-linux 2.20.1?

PS: Thanks for your solution, nob.dir! This problem was really annoying.

If you read the bug report, you'll see that the fix isn't related to util-linux.

Offline

Board footer

Powered by FluxBB