[Catalyst] Resolving performance issues.
Bill Moseley
moseley at hank.org
Tue Apr 25 22:28:14 CEST 2006
On Tue, Apr 25, 2006 at 12:21:53PM -0700, Len Jaffe wrote:
> You need a way to take the network latency out of your
> tests. One admittedly dumb way is to run traceroute
> while running yur tests, and subtract the network
> latency. I said it was dumb.
Both tests were done on the local machines using the Catalyst test
server connecting to localhost. So probably not that much latency
involved.
Both with up-to-date versions of the application and
Catalyst. May be some differences is other modules, as it's
perl 5.8.4 compared to my dev machine 5.8.8.
Here's system call times on the dev machine for a simple (single
database) request
$ time GET http://localhost:3000/test.html > /dev/null
real 0m0.556s
user 0m0.223s
sys 0m0.024s
>% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
29.25 0.001434 717 2 send
20.36 0.000998 48 21 9 stat64
20.30 0.000995 995 1 accept
10.61 0.000520 4 130 read
5.79 0.000284 17 17 write
3.28 0.000161 20 8 close
2.57 0.000126 25 5 open
2.49 0.000122 4 34 time
0.78 0.000038 3 11 fcntl64
0.75 0.000037 4 10 rt_sigprocmask
0.73 0.000036 18 2 socket
0.47 0.000023 5 5 3 ioctl
0.39 0.000019 10 2 munmap
0.39 0.000019 10 2 recv
0.35 0.000017 9 2 mmap2
0.29 0.000014 7 2 poll
0.24 0.000012 4 3 fstat64
0.20 0.000010 3 3 rt_sigaction
0.16 0.000008 4 2 alarm
0.16 0.000008 8 1 flock
0.16 0.000008 8 1 getpeername
0.10 0.000005 2 3 2 _llseek
0.08 0.000004 2 2 gettimeofday
0.08 0.000004 4 1 getsockname
------ ----------- ----------- --------- --------- ----------------
100.00 0.004902 270 14 total
Now the same requst on Dreamhost:
$ time GET http://localhost:3000/test.html > /dev/null
real 0m1.730s
user 0m1.050s
sys 0m0.090s
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
31.35 0.009970 9970 1 accept
21.89 0.006963 3482 2 send
16.18 0.005146 271 19 write
9.70 0.003085 24 130 read
8.87 0.002820 141 20 9 stat64
3.08 0.000981 164 6 open
2.10 0.000668 20 34 time
1.21 0.000386 43 9 close
0.90 0.000287 21 14 fcntl64
0.84 0.000267 38 7 rt_sigaction
0.61 0.000194 32 6 old_mmap
0.59 0.000188 31 6 munmap
0.54 0.000172 86 2 2 connect
0.37 0.000118 20 6 fstat64
0.35 0.000112 56 2 socket
0.27 0.000085 14 6 rt_sigprocmask
0.24 0.000075 38 2 poll
0.23 0.000073 18 4 alarm
0.22 0.000069 35 2 recv
0.10 0.000032 16 2 2 _llseek
0.09 0.000029 15 2 2 ioctl
0.08 0.000027 14 2 umask
0.08 0.000025 25 1 getsockname
0.06 0.000019 10 2 gettimeofday
0.04 0.000013 13 1 getpeername
------ ----------- ----------- --------- --------- ----------------
100.00 0.031804 288 15 total
> If dreamhost is a slower processor, on a more loaded
> host, with significantly higher network latency, then
> that really explains is.
Yep.
>
> Is your dream host app CGI, while the dev app uses the
> dev server? That could be a factor.
I would hope it would be faster than CGI. They are both running the
test server doing a single concurrent request. I didn't want to
include Apache/FastCGI in the mix.
I could profile the application, but at this point I'm looking more
for reasons why the machine is just slow. Maybe it's just slow.
The more database intensive query returns this on dreamhost.
Looks to me like the machine just has too many tasks running
with the big difference between real and system time. I suppose slow
disks could be part of that.
$ time GET http://localhost:3000/workshop > /dev/null
real 0m4.607s
user 0m0.990s
sys 0m0.090s
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
43.99 0.057930 460 126 send
16.34 0.021518 171 126 poll
13.44 0.017699 69 255 rt_sigaction
7.57 0.009970 9970 1 accept
6.90 0.009093 505 18 write
3.20 0.004208 33 126 recv
2.05 0.002696 21 131 read
1.49 0.001962 78 25 10 stat64
1.35 0.001784 119 15 fcntl64
1.12 0.001476 20 75 time
0.74 0.000971 139 7 open
0.46 0.000600 60 10 close
0.34 0.000450 75 6 old_mmap
0.25 0.000335 42 8 brk
0.15 0.000202 34 6 munmap
0.13 0.000172 86 2 2 connect
0.12 0.000164 41 4 alarm
0.09 0.000116 58 2 socket
0.08 0.000102 13 8 fstat64
0.05 0.000065 11 6 rt_sigprocmask
0.03 0.000045 15 3 2 _llseek
0.03 0.000042 14 3 3 ioctl
0.02 0.000032 16 2 gettimeofday
0.02 0.000031 31 1 getpeername
0.02 0.000028 14 2 umask
0.01 0.000012 12 1 getsockname
------ ----------- ----------- --------- --------- ----------------
100.00 0.131703 969 17 total
--
Bill Moseley
moseley at hank.org
More information about the Catalyst
mailing list