Achim Gratz wrote:
Achim Gratz writes:
I've switched chrooting off as an experiment, lets see if the boot times go back to something halfway sane (it's an old machine, so that'll still be some time).
That didn't change things. To make sure things are clean, I de- and reinstalled ntp The first two starts (i.e. the one while booting and the next one from a root shell) of service ntp will take over two minutes with lots of disk activity (like it's seeking through lots of directories) and from then on it's down to a few seconds cold cache and under two seconds warm. If I then thrash the cache again by runing a find somewhere else on the disk, the startup time goes back to around two minutes. So somehow starting ntp is triggering a lot of stats and directory traversals, but I don't quite see where.
I thought about your prob... and thought it "shouldn't" be hard to tell ... going through.. strace and adding... then I realized... it might be a bit more complicated than some might like.. Attached is shell & perl script that should tell you what system calls are taking up the most time, with highest cumulative times at the top... By default it will show the top 20 lines. Make sure whatever you time doesn't go into background daemon mode and never exits -- or the command won't terminate (it does follow children). It will dump a trace file in /tmp so it can read it in and tally the results. If you don't want it when you are done, feel free to delete it (/tmp/timings.{txt,cmd}) 'wheretime' -- where is the time going? example:
wheretime "gvim -c q" generating timings for gvim -c q... 1.55sec 0.11usr 0.38sys (31.70% cpu) 0.235206 [pid 94759]access("/usr/share/fonts/TTF/ 0.121237 [pid 94759]open("/usr/share/locale/local 0.119617 [pid 94759]access("/usr/share/fonts/TTF/ 0.119050 [pid 94759]brk(0x17c2000) = 0x17c2000 0.099169 brk(0x230c000) = 0x230c000 0.075638 brk(0x1962000) = 0x1962000 0.028015 [pid 94759]recvfrom(5, ""..., 4096, 0, N 0.025954 [pid 94759]stat("/usr/share/fonts/baekmu 0.021227 [pid 94759]recvfrom(5, 0x1638df4, 4096, 0.018889 [pid 94759]poll([...], 1, 4294967295) =
----------- It's a rough tool but it might help you narrow down where the activity is taking place. The numbers in the column are in seconds / same call... I,e. any call w/same params is summed w/other calls of same params... children are listed as [pid xxx]and there commands... To change the number of lines displayed, put it as another param on the cmdline... (don't forget quotes around the input command)... (gvim -c q sees how fast gvim loads and where it spends time.) like: law> wheretime "gvim -c q" 30 generating timings for gvim -c q... 1.54sec 0.12usr 0.36sys (31.98% cpu) 0.235588 [pid 95675]access("/usr/share/fonts/TTF/ 0.121255 [pid 95675]open("/usr/share/locale/local 0.119125 [pid 95675]brk(0x28f6000) = 0x28f6000 0.119075 [pid 95675]access("/usr/share/fonts/TTF/ 0.098136 brk(0x3440000) = 0x3440000 0.072332 brk(0x2a96000) = 0x2a96000 0.026680 [pid 95675]stat("/usr/share/fonts/baekmu 0.023179 [pid 95675]recvfrom(5, ""..., 4096, 0, N 0.021721 [pid 95675]recvfrom(5, 0x276cdf4, 4096, 0.019983 [pid 95675]poll([...], 1, 4294967295) = 0.018202 [pid 95675]close(3) = 0 0.015783 [pid 95675]stat("/usr/share/fonts/new", 0.013872 exit_group(0) = ? 0.013137 [pid 95675]stat("/usr/share/fonts/OTF/co 0.013011 read(3, "", 262144) = 0 0.011248 [pid 95675]stat("/usr/share/fonts/TTF/ka 0.010954 close(3) = 0 0.010867 [pid 95675]poll([...], 2, 0) = 0 (Timeou 0.009741 [pid 95675]read(11, ""..., 8192) = 8192 0.008310 [pid 95675]munmap(0x7f598060e000, 398521 0.007350 openat(AT_FDCWD, "/home/law/.vim/compile 0.007157 [pid 95675]brk(0x2938000) = 0x2938000 0.006779 read(6, "", 262144) = 0 0.006668 [pid 95675]brk(0x2958000) = 0x2958000 0.006654 [pid 95675]fstatfs(3, {f_type=0x58465342 0.006460 [pid 95675]read(8, "", 8192) = 0 0.005972 read(3, ""..., 832) = 832 0.005547 [pid 95675]brk(0x2978000) = 0x2978000 0.005107 recvfrom(5, 0x276cdf4, 4096, 0, 0, 0) = 0.004956 [pid 95675]brk(0x2917000) = 0x2917000 (hope it works for you! ;-)) #!/bin/bash # by Linda A. Walsh (c) 2014 -- free for use to nice people! # (not guaranteed to do anything useful)... p=$0 cmd="/bin/sleep 1.5" lines=10 if [[ $# -lt 1 ]]; then echo "wheretime \"cmd [flags]\" [opt#lines]" echo " - w/cmd+flags in quotes -- to time cmd & flags" echo "using default test \"$cmd\" $lines" else cmd="$1" shift fi if [[ $# ]]; then if [[ $1 =~ ^[0-9]+$ ]]; then lines=$1; fi fi #testing #if [[ $p -nt /tmp/timings.txt || # /tmp/timings.cmd -nt /tmp/timings.txt ]]; then rm -f /tmp/timings.{cmd,txt} #fi read last < <(if [[ -e /tmp/timings.cmd ]]; then cat /tmp/timings.cmd; else echo ""; fi) TIMEFORMAT="%2Rsec %2Uusr %2Ssys (%P%% cpu)" if [[ $last != $cmd ]]; then echo "generating timings for $cmd..." echo "$cmd" >/tmp/timings.cmd time strace -s 0 -r -qq -f $cmd >& /tmp/timings.txt fi prog=' ##!/usr/bin/perl;use warnings;use strict;use P; my ($val, $calls)=(0,{}); my $lines=15; if ($#ARGV>=0) { $lines=$ARGV[0] if $ARGV[0] =~ /^\d+$/; shift; } while(<>) { chomp; if (m{((?:\[pid\s\d+\])?)\s*([\d\.]+)\s(\S+.*)$}){ my ($pid,$time,$call)=($1, $2, $3); $call=($pid||"").$call; if (ref $calls->{$call}) { $calls->{$call}[0]=$calls->{$call}[0]+$time; #P "cc1=%s", $calls->{$call} } else { $calls->{$call}=[$time, $call]; } } } my @scalls = sort { my ($ca, $cb) = @{$calls}{$a,$b}; $cb->[0] <=> $ca->[0] || $ca->[1] cmp $cb->[1] } keys %$calls; my $i; for ($i=0; $i<$lines; ++$i) { my $sc=$scalls[$i]; printf " %11.6f %.40s\n", @{$calls->{$sc}}[0,1]; } # vim: ts=2 sw=2 ' perl -e "$prog" "$lines" </tmp/timings.txt # vim: ts=2 sw=2