--- Begin Message ---
- To: submit@bugs.debian.org
- Subject: udev-udeb: Very slow installation in Squeeze caused by udevadm settle
- From: Petter Reinholdtsen <pere@hungry.com>
- Date: Sat, 19 Jun 2010 12:00:06 +0200
- Message-id: <2fl1vc3jqah.fsf@login2.uio.no>
Package: udev-udeb
Version: 157-1
Severity: important
User: debian-edu@lists.debian.org
UserTags: debian-edu
Since some days ago, the debian-installer run in Squeeze is very slow
some times. Looking at the process list, I was able to trace it to
the calls to 'udevadm settle' being done several times during
installation. For example removing lvm partitions currently take 3
minutes _each_ because of this.
I did an strace of such udevadm run to try to figure out what is going
on. Here is the full strace log:
execve("/sbin/udevadm", ["udevadm", "settle"], [/* 14 vars */]) = 0
brk(0) = 0x8fa0000
access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
mmap2(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb8095000
access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/lib/tls/i686/sse2/cmov/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory)
stat64("/lib/tls/i686/sse2/cmov", 0xbfcedf4c) = -1 ENOENT (No such file or directory)
open("/lib/tls/i686/sse2/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory)
stat64("/lib/tls/i686/sse2", 0xbfcedf4c) = -1 ENOENT (No such file or directory)
open("/lib/tls/i686/cmov/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory)
stat64("/lib/tls/i686/cmov", 0xbfcedf4c) = -1 ENOENT (No such file or directory)
open("/lib/tls/i686/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory)
stat64("/lib/tls/i686", 0xbfcedf4c) = -1 ENOENT (No such file or directory)
open("/lib/tls/sse2/cmov/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory)
stat64("/lib/tls/sse2/cmov", 0xbfcedf4c) = -1 ENOENT (No such file or directory)
open("/lib/tls/sse2/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory)
stat64("/lib/tls/sse2", 0xbfcedf4c) = -1 ENOENT (No such file or directory)
open("/lib/tls/cmov/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory)
stat64("/lib/tls/cmov", 0xbfcedf4c) = -1 ENOENT (No such file or directory)
open("/lib/tls/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory)
stat64("/lib/tls", 0xbfcedf4c) = -1 ENOENT (No such file or directory)
open("/lib/i686/sse2/cmov/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory)
stat64("/lib/i686/sse2/cmov", 0xbfcedf4c) = -1 ENOENT (No such file or directory)
open("/lib/i686/sse2/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory)
stat64("/lib/i686/sse2", 0xbfcedf4c) = -1 ENOENT (No such file or directory)
open("/lib/i686/cmov/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory)
stat64("/lib/i686/cmov", 0xbfcedf4c) = -1 ENOENT (No such file or directory)
open("/lib/i686/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory)
stat64("/lib/i686", 0xbfcedf4c) = -1 ENOENT (No such file or directory)
open("/lib/sse2/cmov/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory)
stat64("/lib/sse2/cmov", 0xbfcedf4c) = -1 ENOENT (No such file or directory)
open("/lib/sse2/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory)
stat64("/lib/sse2", 0xbfcedf4c) = -1 ENOENT (No such file or directory)
open("/lib/cmov/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory)
stat64("/lib/cmov", 0xbfcedf4c) = -1 ENOENT (No such file or directory)
open("/lib/libc.so.6", O_RDONLY) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\320m\1\0004\0\0\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=1315008, ...}) = 0
mmap2(NULL, 1325384, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb7f51000
mmap2(0xb808f000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x13d) = 0xb808f000
mmap2(0xb8092000, 10568, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xb8092000
close(3) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7f50000
set_thread_area({entry_number:-1 -> 6, base_addr:0xb7f508d0, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1}) = 0
mprotect(0xb808f000, 8192, PROT_READ) = 0
mprotect(0xb80b3000, 4096, PROT_READ) = 0
brk(0) = 0x8fa0000
brk(0x8fc1000) = 0x8fc1000
open("/etc/udev/udev.conf", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=15, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7f4f000
read(3, "udev_log=\"err\"\n", 4096) = 15
read(3, "", 4096) = 0
close(3) = 0
munmap(0xb7f4f000, 4096) = 0
rt_sigaction(SIGALRM, {0x8051df8, [], 0}, NULL, 8) = 0
rt_sigaction(SIGUSR1, {0x8051df8, [], 0}, NULL, 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [USR1 ALRM], NULL, 8) = 0
alarm(180) = 0
getuid32() = 0
socket(PF_FILE, SOCK_DGRAM, 0) = 3
rt_sigprocmask(SIG_BLOCK, [USR1 ALRM], [], 8) = 0
sendto(3, "udev-157\0\0\0\0\0\0\0\0\352\35\255\336\7\0\0\0\0\0\0\0\0\0\0\0"..., 280, 0, {sa_family=AF_FILE, path=@"/org/kernel/udev/udevd"}, 25) = 280
rt_sigsuspend([]) = ? ERESTARTNOHAND (To be restarted)
--- SIGALRM (Alarm clock) @ 0 (0) ---
sigreturn() = ? (mask now [USR1 ALRM])
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
close(3) = 0
open("/dev/.udev/queue.bin", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=2030, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7f4f000
read(3, "5\"\0\0\0\0\0\0006\"\0\0\0\0\0\0\33\0/devices/virtu"..., 4096) = 2030
read(3, "", 4096) = 0
open("/sys/kernel/uevent_seqnum", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = 4
read(4, "8798\n", 32) = 5
close(4) = 0
close(3) = 0
munmap(0xb7f4f000, 4096) = 0
open("/dev/.udev/queue.bin", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=2030, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7f4f000
read(3, "5\"\0\0\0\0\0\0006\"\0\0\0\0\0\0\33\0/devices/virtu"..., 4096) = 2030
read(3, "", 4096) = 0
close(3) = 0
munmap(0xb7f4f000, 4096) = 0
exit_group(0) = ?
The process hang after the sendto() call and the rt_sigsuspend() call,
and time out with SIGALRM after what I suspect is 3 minutes.
Here is a fragment from the installation syslog showing the effect of
these slow calls:
Jun 19 00:38:18 partman: Found volume group "vg_system" using metadata type lvm2
Jun 19 00:38:19 partman-lvm: 9 logical volume(s) in volume group "vg_system" now active
Jun 19 00:44:22 partman-lvm: /dev/cdrom: open failed: Read-only file system
Jun 19 00:44:22 partman-lvm: Logical volume "opt" successfully removed
Jun 19 00:47:22 partman-lvm: /dev/cdrom: open failed: Read-only file system
Jun 19 00:47:22 partman-lvm: Logical volume "root" successfully removed
Jun 19 00:50:22 partman-lvm: /dev/cdrom: open failed: Read-only file system
Jun 19 00:50:22 partman-lvm: Logical volume "skole+backup" successfully removed
Jun 19 00:53:23 partman-lvm: /dev/cdrom: open failed: Read-only file system
Jun 19 00:53:23 partman-lvm: Logical volume "skole+tjener+home0" successfully removed
Jun 19 00:56:23 partman-lvm: /dev/cdrom: open failed: Read-only file system
Jun 19 00:56:23 partman-lvm: Logical volume "swap_1" successfully removed
Jun 19 00:59:23 partman-lvm: /dev/cdrom: open failed: Read-only file system
Jun 19 00:59:23 partman-lvm: Logical volume "usr" successfully removed
Jun 19 01:02:23 partman-lvm: /dev/cdrom: open failed: Read-only file system
Jun 19 01:02:23 partman-lvm: Logical volume "var" successfully removed
Jun 19 01:05:23 partman-lvm: /dev/cdrom: open failed: Read-only file system
Jun 19 01:05:23 partman-lvm: Logical volume "var+opt+ltsp+swapfiles" successfully removed
Jun 19 01:08:23 partman-lvm: /dev/cdrom: open failed: Read-only file system
Jun 19 01:08:23 partman-lvm: Logical volume "var+spool+squid" successfully removed
Jun 19 01:08:23 partman-lvm: 0 logical volume(s) in volume group "vg_system" now active
Jun 19 01:11:23 partman-lvm: Volume group "vg_system" successfully removed
Notice how there is a 3 minutes delay between each removal.
Any ideas how to debug or fix this?
Setting severity to important as this affect debian-installer badly
without breaking the installation completely.
Happy hacking,
--
Petter Reinholdtsen
--- End Message ---