Installing/updating packages are very slow
Hi,
I've got a physical machine with jessie/sid where installing/updating
a packages takes very long:
> # annotate-output strace -s 4096 -e trace=file -f -ttt -o /tmp/dpkg-debug.log apt-get install --reinstall tzdata
> 20:13:28 I: Started strace -s 4096 -e trace=file -f -ttt -o /tmp/dpkg-debug.log apt-get install --reinstall tzdata
> 20:13:28 O: Reading package lists...
> 20:13:28 O: Building dependency tree...
> 20:13:28 O: Reading state information...
> 20:13:30 O: Preconfiguring packages ...
> 20:13:30 O: 0 upgraded, 0 newly installed, 1 reinstalled, 0 to remove and 0 not upgraded.
> 20:13:30 O: Need to get 0 B/191 kB of archives.
> 20:13:30 O: After this operation, 0 B of additional disk space will be used.
> 20:13:30 O: (Reading database ... 87668 files and directories currently installed.)
> 20:13:30 O: Preparing to unpack .../tzdata_2014h-2_all.deb ...
> 20:13:30 O: Unpacking tzdata (2014h-2) over (2014h-2) ...
> 20:15:35 O: Setting up tzdata (2014h-2) ...
> 20:15:35 E:
> 20:15:35 E: Current default time zone: 'Europe/Berlin'
> 20:15:35 E: Local time is now: Wed Oct 22 20:15:35 CEST 2014.
> 20:15:35 E: Universal Time is now: Wed Oct 22 18:15:35 UTC 2014.
> 20:15:35 E: Run 'dpkg-reconfigure tzdata' if you wish to change it.
> 20:15:35 E:
> Scanning processes...
> Scanning candidates...
> Scanning kernel images...
> 20:15:37 E: Running kernel seems to be up-to-date.
> 20:15:37 E: No services need to be restarted.
> 20:15:38 I: Finished with exitcode 0
> annotate-output strace -s 4096 -e trace=file -f -ttt -o /tmp/dpkg-debug.log 2,01s user 8,64s system 8% cpu 2:09,87 total
As you can see, it is always the "Unpacking" step which is taking all the time.
Link to the created strace debug file:
https://www.dropbox.com/s/wjvlqcke9epn2wl/dpkg-debug.log-20141022.gz?dl=1
> ...
> 43274 1414001632.364669 open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 12
> 43274 1414001632.364763 open("/etc/group", O_RDONLY|O_CLOEXEC) = 12
> 43274 1414001632.364856 lstat("/usr/share/zoneinfo/right/Etc/GMT+2", {st_mode=S_IFREG|0644, st_size=626, ...}) = 0
> 43274 1414001632.364875 rmdir("/usr/share/zoneinfo/right/Etc/GMT+2.dpkg-new") = -1 ENOENT (No such file or directory)
> 43274 1414001632.364892 rmdir("/usr/share/zoneinfo/right/Etc/GMT+2.dpkg-tmp") = -1 ENOENT (No such file or directory)
> 43274 1414001632.364906 open("/usr/share/zoneinfo/right/Etc/GMT+2.dpkg-new", O_WRONLY|O_CREAT|O_EXCL, 0) = 12
> 43274 1414001632.436764 utimes("/usr/share/zoneinfo/right/Etc/GMT+2.dpkg-new", {{1414001610, 0}, {1412718680, 0}}) = 0
> 43274 1414001632.436785 link("/usr/share/zoneinfo/right/Etc/GMT+2", "/usr/share/zoneinfo/right/Etc/GMT+2.dpkg-tmp") = 0
> ...
Everything seems to be fast. Unpacking kernel sources (tar -xaf
linux-3.16.6.tar.xz) is no problem. Daily work is no problem.
But when it comes to apt/aptitude and installing/updating packages,
the system is very slow.
Any ideas/hints?
System details:
==============
HP ProLiant DL320e Gen8 v2 Server
CPU: Intel(R) Xeon(R) CPU E3-1270 v3 @ 3.50GHz
RAM: 16GB
HDD: 2x TOSHIBA MG03ACA100 in mdraid 1 setup
# uname -a
Linux web42 3.16.6-web42 #1 SMP Thu Oct 16 00:38:25 CEST 2014 x86_64 GNU/Linux
# cat /proc/mdstat
Personalities : [raid1]
md126 : active raid1 sda1[0] sdb1[1]
262080 blocks super 1.0 [2/2] [UU]
md127 : active raid1 sda2[0] sdb2[1]
976368128 blocks super 1.2 [2/2] [UU]
unused devices: <none>
# df -h
Filesystem Size Used Avail Use% Mounted on
/dev/mapper/storage-volRoot 99G 31G 63G 34% /
udev 10M 0 10M 0% /dev
tmpfs 1,6G 360K 1,6G 1% /run
tmpfs 5,0M 0 5,0M 0% /run/lock
shm 7,9G 0 7,9G 0% /run/shm
/dev/md126 244M 71M 158M 31% /boot
/dev/mapper/storage-volSrv 788G 49G 699G 7% /srv
/dev/mapper/storage-volLogs 7,8G 47M 7,3G 1% /var/log
# mount -l | grep -i root
/dev/mapper/storage-volRoot on / type ext4
(rw,relatime,nodelalloc,data=ordered) [fsRoot]
# hdparm -W /dev/sdb
/dev/sdb:
write-caching = 1 (on)
# hdparm -W /dev/sda
/dev/sda:
write-caching = 1 (on)
# hdparm -tT /dev/sda2
/dev/sda2:
Timing cached reads: 32514 MB in 2.00 seconds = 16274.80 MB/sec
Timing buffered disk reads: 456 MB in 3.01 seconds = 151.37 MB/sec
# hdparm -tT /dev/sdb2
/dev/sdb2:
Timing cached reads: 32644 MB in 2.00 seconds = 16340.78 MB/sec
Timing buffered disk reads: 432 MB in 3.01 seconds = 143.45 MB/sec
# dd if=/dev/zero of=/test.dat bs=1G count=1 oflag=direct
1+0 records in
1+0 records out
1073741824 bytes (1,1 GB) copied, 7,99894 s, 134 MB/s
# cat /sys/block/sd*/queue/scheduler
noop deadline [cfq]
noop deadline [cfq]
Thx!
--
Regards,
Igor
Reply to: