While reading through the Apache documentation, I found a mention that disabling ExtendedStatus can speed things up by preventing gettimeofday() calls. I deal with a lot of servers that see a lot of traffic and wanted to find out what kind of gains it would give me. Strangely, I actually found that having ExtendedStatus enabled gave me lower times per strace
I setup the Apache server to only have 1 process running which would serve 5000 requests. I then had another server run 5000 requests at a time to an index.html page that just said 'test'. Since I expected the time savings to be unnoticeable on the client side, I didn't use ab or siege... I just straced the Apache process and used the -T flag to print out the times for each call:
After 25,000 traces each I got the following total times (minus 'accept()'):
There are an additional ~45,000 calls in each of the time-Extended files.
I've checked the time spent in each type of call, and with the exception of gettimeofday(), the noExtended spend more time in each call:
noExtended
Extended
Sadly, when I manually compare two requests, I'm not seeing anything obvious and even finding that the noExtend ran faster.
Anyone know why this might be happening? Do I need more datapoints to make a good comparison? 25,000 seemed quite a bit to me, but I'm no statistician.
I setup the Apache server to only have 1 process running which would serve 5000 requests. I then had another server run 5000 requests at a time to an index.html page that just said 'test'. Since I expected the time savings to be unnoticeable on the client side, I didn't use ab or siege... I just straced the Apache process and used the -T flag to print out the times for each call:
Code:
strace -T -s 500 -p `ps aux | grep httpd | grep apache | grep -v grep | awk '{print $2}'` -o time-noExtended-5000After 25,000 traces each I got the following total times (minus 'accept()'):
Code:
time-Extended-5000.1: 47.9501
time-Extended-5000.2: 47.4915
time-Extended-5000.3: 47.2623
time-Extended-5000.4: 45.5795
time-Extended-5000.5: 49.5506
Total: 237.834
Avg/5K: 47.5668
Avg/Request: 0.00951336
time-noExtended-5000.1: 53.0255
time-noExtended-5000.2: 51.8191
time-noExtended-5000.3: 47.1719
time-noExtended-5000.4: 47.1542
time-noExtended-5000.5: 45.4036
Total: 244.574
Avg/5K: 48.9149
Avg/Request: 0.00978297There are an additional ~45,000 calls in each of the time-Extended files.
I've checked the time spent in each type of call, and with the exception of gettimeofday(), the noExtended spend more time in each call:
noExtended
Code:
accept4: 133.524
brk: 9.7e-05
close: 0.674608
fcntl: 0.6055
fstat: 6e-05
getsockname: 0.159113
gettimeofday: 0.150284
lseek: 3e-05
lstat: 0.165545
mmap: 3.4e-05
munmap: 4.9e-05
open: 0.188461
poll: 49.7728
read: 0.505227
shutdown: 0.220381
stat: 0.531425
write: 0.492541
writev: 0.275038Extended
Code:
accept4: 135.276
brk: 8.5e-05
close: 0.661279
fcntl: 0.601297
fstat: 6e-05
getsockname: 0.155293
gettimeofday: 1.33585
lseek: 3.1e-05
lstat: 0.164286
mmap: 3.4e-05
munmap: 4.9e-05
open: 0.186581
poll: 43.4268
read: 0.500737
shutdown: 0.20856
stat: 0.521246
write: 0.469356
writev: 0.269018Sadly, when I manually compare two requests, I'm not seeing anything obvious and even finding that the noExtend ran faster.
Anyone know why this might be happening? Do I need more datapoints to make a good comparison? 25,000 seemed quite a bit to me, but I'm no statistician.