Apache Redirect testing
Folks who are work with Apache HTTPD for any amount of time have probably noticed it has a number of different methods for implementing URL Redirection. Each one has a different set of options and capabilities, but those extra features come at a performance cost.
I’ve built a small experiment to evaluate the performance of the four major options for URL Redirect:
- Baseline (no redirect, raw serving of a simple 8-byte file)
- Redirect
- RedirectMatch
- RewriteRule
- RewriteMap + RewriteRule
There are certainly a few other methods, and variations on the four above, but these are the most common approaches I am aware of. If you’ve spent any time in IRC asking for help on #httpd about rewrites, the most common response is to use RedirectMatch. This got me thinking: is RedirectMatch the most effective method, since there are so many to choose from? Hence, this small experiment was born.
It turns out, RedirectMatch is a really great performing option for folks, given that they implement in their server config directly. Resist the temptation to implement via .htaccess files using AllowOverride. That is a surefire way to stomp your site performance, and has been covered by the fine folks at Apache HTTPD.
Our test setup is quite simple:
32-bit VM running on a 3.2ghz Intel Core 2 Duo / E6750, acting as both the server and the client. I assume this not a major issue, we are not testing raw performance, just relative performance against itself.
Server version: Apache/2.2.24 (Unix)
Server built: Apr 4 2013 20:32:29
Server’s Module Magic Number: 20051115:31
Server loaded: APR 1.4.6, APR-Util 1.4.1
Compiled using: APR 1.4.6, APR-Util 1.4.1
Architecture: 32-bit
Server MPM: Worker
threaded: yes (fixed thread count)
forked: yes (variable process count
This is compiled freshly from source with the following configure flags:
$ ./configure –enable-rewrite –prefix=/home/www/apache22 –with-included-apr –with-mpm=worker
Our test strategy will go as such:
Client
ApacheBench running 20,000 requests with only 1 connection, using KeepAlive, grabbing a small URL and getting served a redirect. This reduces the overhead of dealing with socket startup/shutdown, and focuses just purely on the rule matching capability. ab Flags used in all my tests:
$ ab -k -c 1 -n 20000 “http://localhost:10000/test/10000”
Server
HTTPD Setup:
ServerRoot “/home/www/apache22”
ServerName netflows.no-life.com
Listen 10000
DocumentRoot “/home/www/apache22/htdocs”
<Directory />
Options FollowSymLinks
AllowOverride None
Order deny,allow
Deny from all
</Directory>
<Directory “/home/www/apache22/htdocs”>
Options None
AllowOverride None
Order allow,deny
Allow from all
</Directory>
DefaultType text/plain
As you can see, no frills here. We have a test/10000 file out in our htdocs folder with the contents of “success”, though technically this is irrelevant: we are not testing the file serving. We are only testing the REDIRECT generation (which does not serve the file).
I reran these test several times, and the results were consistent.
The results:
| Test: | Baseline (Serve a file) | 10000 Redirect Entries | 10000 RedirectMatch Entries | 10000 RewriteRule Entries | 10000 RewriteMap Entries |
| Time per request (ms): | 0.102 | 0.161 | 0.067 | 1.359 | 0.088 |
Summary
RedirectMatch is indeed the fastest performer, followed closely by RewriteMap. RewriteRule is almost 20x slower.
Avoid RewriteRule, unless complexity requires it!
Warning: Tangential topic below!
Confused how these redirects are faster than Baseline test? I was too!
Then it hit me: baseline is serving the file, which has to make several syscalls to the filesystem. Redirects only serve the HTTP 301 or 302 response (no file access).
Compare the following Baseline vs RedirectMatch straces:
Baseline (serving the file):
[pid 12966] futex(0x85723bc, FUTEX_WAKE_PRIVATE, 1) = 0
[pid 12966] getsockname(9, {sa_family=AF_INET6, sin6_port=htons(10000), inet_pton(AF_INET6, “::1”, &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, [28]) = 0
[pid 12966] fcntl64(9, F_GETFL) = 0x2 (flags O_RDWR)
[pid 12966] fcntl64(9, F_SETFL, O_RDWR|O_NONBLOCK) = 0
[pid 12966] read(9, “GET /test.html HTTP/1.1\r\nUser-Ag”…, 8000) = 177
[pid 12966] gettimeofday({1405781496, 804325}, NULL) = 0
[pid 12966] stat64(“/home/www/apache22/htdocs/test.html”, {st_mode=S_IFREG|0664, st_size=8, …}) = 0
[pid 12966] lstat64(“/home/www/apache22/htdocs/test.html”, {st_mode=S_IFREG|0664, st_size=8, …}) = 0
[pid 12966] open(“/home/www/apache22/htdocs/test.html”, O_RDONLY|O_LARGEFILE|O_CLOEXEC) = 10
[pid 12966] open(“/etc/localtime”, O_RDONLY) = 11
[pid 12966] fstat64(11, {st_mode=S_IFREG|0644, st_size=3519, …}) = 0
[pid 12966] fstat64(11, {st_mode=S_IFREG|0644, st_size=3519, …}) = 0
[pid 12966] mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb77e5000
[pid 12966] read(11, “TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\4\0\0\0\4\0\0\0\0″…, 4096) = 3519
[pid 12966] _llseek(11, -24, [3495], SEEK_CUR) = 0
[pid 12966] read(11, “\nEST5EDT,M3.2.0,M11.1.0\n”, 4096) = 24
[pid 12966] close(11) = 0
[pid 12966] munmap(0xb77e5000, 4096) = 0
[pid 12966] mmap2(NULL, 8, PROT_READ, MAP_SHARED, 10, 0) = 0xb77e5000
[pid 12966] read(9, 0xb6c05788, 8000) = -1 EAGAIN (Resource temporarily unavailable)
[pid 12966] writev(9, [{“HTTP/1.1 200 OK\r\nDate: Sat, 19 J”…, 230}, {“success\n”, 8}], 2) = 238
[pid 12966] munmap(0xb77e5000, 8) = 0
[pid 12966] close(10) = 0
[pid 12966] poll([{fd=9, events=POLLIN}], 1, 5000) = 1 ([{fd=9, revents=POLLIN}])
[pid 12966] read(9, “”, 8000) = 0
[pid 12966] gettimeofday({1405781496, 808164}, NULL) = 0
[pid 12966] shutdown(9, 1 /* send */) = 0
[pid 12966] poll([{fd=9, events=POLLIN}], 1, 2000) = 1 ([{fd=9, revents=POLLIN|POLLHUP}])
[pid 12966] read(9, “”, 512) = 0
[pid 12966] close(9) = 0
[pid 12966] futex(0x85723f0, FUTEX_WAIT_PRIVATE, 27, NULL <unfinished …>
RedirectMatch:
[pid 13069] futex(0x91b0414, FUTEX_WAKE_PRIVATE, 1) = 0
[pid 13069] getsockname(7, {sa_family=AF_INET6, sin6_port=htons(10000), inet_pton(AF_INET6, “::1”, &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, [28]) = 0
[pid 13069] fcntl64(7, F_GETFL) = 0x2 (flags O_RDWR)
[pid 13069] fcntl64(7, F_SETFL, O_RDWR|O_NONBLOCK) = 0
[pid 13069] read(7, “GET /test/1.html HTTP/1.1\r\nUser-“…, 8000) = 179
[pid 13069] gettimeofday({1405781627, 250348}, NULL) = 0
[pid 13069] gettimeofday({1405781627, 250886}, NULL) = 0
[pid 13069] open(“/etc/localtime”, O_RDONLY) = 10
[pid 13069] fstat64(10, {st_mode=S_IFREG|0644, st_size=3519, …}) = 0
[pid 13069] fstat64(10, {st_mode=S_IFREG|0644, st_size=3519, …}) = 0
[pid 13069] mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7892000
[pid 13069] read(10, “TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\4\0\0\0\4\0\0\0\0″…, 4096) = 3519
[pid 13069] _llseek(10, -24, [3495], SEEK_CUR) = 0
[pid 13069] read(10, “\nEST5EDT,M3.2.0,M11.1.0\n”, 4096) = 24
[pid 13069] close(10) = 0
[pid 13069] munmap(0xb7892000, 4096) = 0
[pid 13069] write(2, “[Sat Jul 19 10:53:47 2014] [debu”…, 182) = 182
[pid 13069] read(7, 0xb6d05788, 8000) = -1 EAGAIN (Resource temporarily unavailable)
[pid 13069] writev(7, [{“HTTP/1.1 301 Moved Permanently\r\n”…, 211}, {“<!DOCTYPE HTML PUBLIC \”-//IETF//”…, 240}], 2) = 451
[pid 13069] poll([{fd=7, events=POLLIN}], 1, 5000) = 1 ([{fd=7, revents=POLLIN}])
[pid 13069] read(7, “”, 8000) = 0
[pid 13069] gettimeofday({1405781627, 254729}, NULL) = 0
[pid 13069] shutdown(7, 1 /* send */) = 0
[pid 13069] poll([{fd=7, events=POLLIN}], 1, 2000) = 1 ([{fd=7, revents=POLLIN|POLLHUP}])
[pid 13069] read(7, “”, 512) = 0
[pid 13069] close(7) = 0
[pid 13069] futex(0x91b0448, FUTEX_WAIT_PRIVATE, 27, NULL <unfinished …>
If you noticed, serving the baseline file took five additional syscalls. They are as below:
First httpd performs a stat64 the file to make sure it’s a “regular” file (essentially, that it exists):
[pid 12966] stat64(“/home/www/apache22/htdocs/test.html”, {st_mode=S_IFREG|0664, st_size=8, …}) = 0
Next,httpd performs lstat64 to see if the file is a symbolic link:
[pid 12966] lstat64(“/home/www/apache22/htdocs/test.html”, {st_mode=S_IFREG|0664, st_size=8, …}) = 0
Once we have enough information, HTTPD will attempt to open a file descriptor (which gets assigned to FD 10)
[pid 12966] open(“/home/www/apache22/htdocs/test.html”, O_RDONLY|O_LARGEFILE|O_CLOEXEC) = 10
Now, Apache can mmap2 the file, copying it’s contents to memory for httpd to read directly.
[pid 12966] mmap2(NULL, 8, PROT_READ, MAP_SHARED, 10, 0) = 0xb77e5000
And finally, close the file descriptor.
[pid 12966] close(10) = 0
All of this takes significantly more time, since we’re performing filesystem operations (stats/open/read/close). Contrast with RedirectMatch, which can operate without touching any files.
Reverse Proxies and the gremlins within
I stumbled into a quirk with apache and mod_proxy, and our sm_module (CA’s Siteminder agent), and thought it might be of use to others.
Basic Setup
CA Siteminder protected website, reverse proxied (mod_proxy) to a Java Servlet Web Application built on Tomcat.
Tomcat is front-ended by hardware load balancer.
Pretty standard, just handling regular J2EE web traffic. It looks something like this (horizontal lines represent firewalls, but that is mostly irrelevant to the discussion. We will assume they are functioning as expected).
For those not familiar with Siteminder, it’s a Web Access Management platform, that amongst other things, provides authorization and authentication. This design generally provides a layer of insulation from our internal applications. Think of it as a second or third layer of defense, beyond the Firewalls and IPS. Most folks in an enterprise would find this somewhat typical, though the tech stack may vary.
Our Problem
All our HTTP connections for users are humming along splendidly, but occasionally when a user POSTs some large data payloads (PDF’s in this case), the user gets the dreaded “HTTP 502 Bad Gateway” from Apache HTTPD.
Application team reports these requests are not even making it to the application server. That’s pretty unusual: typically HTTP 502 Bad Gateway stems from a timeout or bad response from the back-end. In those cases, the request is making its way to the application server, it just doesn’t respond appropriately. So immediately, I’m suspicious.
Initial Investigations
As I mentioned, the first assumption is the request takes too long to respond within the proxy timeout, or is just not returning a value at all.
The first thing we do is try the same request against the Tomcat instance directly†.
POST /abcdef/servlet
<40MB of post payload>
And 25-30 seconds later, I get a successful response:
HTTP 200 OK
So that is surprising: the application server happily responds with success, and no obvious timeout (25-30 sec is just time spent uploading).
I make the assumption the application itself is having no problems handling the request/payload, and no strange idle timeout is occurring.
Proceeding up the infrastructure, I try the same request against the hardware load balancer. Sure enough, success again.
Next, we try the request against the Apache Proxy. Ah ha! Problem reoccurs. However, we still don’t have answers. We just know it’s somewhere starting at Apache. Now, we must dig into the capture to see if anything uncommon is happening.
† This can be done by capturing the original attempt with CharlesProxy, Fiddler2, BurpSuite, or whatever proxy/logging tool floats your boat. If you debug web issues frequently and are not familiar with any of these tools, I highly recommend you try them out and find what is right for you.Capturing the behavior
Fortunately, the behavior was easily reproducible by end users, and ourselves. So I fire up tcpdump and set to monitoring the backend connection between the Apache proxy and the application server (since this is the place where we suspect trouble).
Sure enough, we quickly reproduce the issue. I quickly jump into WireShark, and am following the TCP connection.
An interesting pattern appears:
User is establishing HTTP/1.1 Keep-Alive connection, no problem. I see the previous conversation, going back and forth between the Proxy and the Application Servers load balanced IP. After exactly 20 seconds, the Application server sends a FIN to hang up the connection (from the Tomcat side!?).
It turns out, Tomcat had it’s HTTP connector connectionTimeout set to 20000 milliseconds (default configuration). If the request doesn’t make it to Tomcat, it initiates a socket shutdown (FIN). Problem is, Apache still has some POST data buffering up, and is ready to dump it off to the connection pool. It seems as if Apache allocates the backend connection first, then once the payload is finished buffering from the end-user, it delivers it to the backend. Our issue is, if the 40MB file takes several minutes to upload, Tomcat would close down the proxied connection before completing!
The cause
So, this configuration is slightly unusual from your typical mod_proxy + Tomcat setup. We run the siteminder webagent as mentioned, and we use load balancers for distributing load, not mod_jk or mod_proxy_ajp. As far as we can tell, the siteminder webagent attempts to do some inspection of the POST payload, which prevents flushing from that bucket to the proxy bucket. Deeper analysis and debugging of the apache process and the modules would be required to confirm this. For us, the urgency was to resolve the issue for the application.
The solution
We increased the HTTP connector “connectionTimeout” value to match the Apache HTTPD ProxyTimeout value. Now, Tomcat will keep the connection open as long as HTTPD might have, which should allow Apache HTTPD to close down backend connections as it sees fit. Ideally, the backend HTTP connector timeout should be just a hair longer, to make sure the right order of closing, but so far we must have been lucky.
Future tips
Always pay attention to these timeouts, especially when they happen consistently: the 20 second disconnection that was observed was the key to finding a solution. Often times, when you are able to reproduce the problem reliably, and the duration of the timeout is some very round number like 15, 30, 60, 180 seconds, there is some hardcoded default value just waiting to bite you.
The science of Network Troubleshooting
Stumbled upon this great link on troubleshooting from NANOG mailing lists, and had to pass it on to anybody who hasn’t read it, especially the incident with Mary. Brings me back to the tech support days.
http://packetlife.net/blog/2010/mar/10/the-science-of-network-troubleshooting/
NetCat cheatsheet
Excellent cheatsheet of netcat uses.
http://h.ackack.net/cheat-sheets/netcat
In: linux, tools · Tagged with: netcat
Linux Debugging tools
A couple tools any Linux user should know about, and their frequent uses:
The essentials which I won’t cover:
ls, grep, sed, awk, cat, less, head, tail, ..
I’m sure there are others. These should automatically just be extensions of your brain — you need to be intimately familiar with them to be productive on a command line. If you aren’t, I suggest you search around the net, there are thousands of tutorials to bring you up to speed on each one individually, and then you can progress to chaining them together.
On to the real meat of this post:
netstat
This really should be included above, but it does have some special uses for application debugging. Useful flags:
netstat -anlp | grep PID
nc
Netcat has become the multi-tool of connection testing, for what we used to use “telnet” to establish simple tcp outbound connections, nc can now provide that, plus a listening mode to receive incoming connections. This is especially useful for validating firewall configurations before your applications ever get installed. Plus, combining nc with chained commands such as tar or gzip can make for some very quick file transfer mechanisms (bypassing ssh/scp’s performance limitations). Common uses:
nc host port — Connect outbound to a host:port
nc -l 8080 — Listen for a connection on 8080 and exit when closed.
lsof
Handy way to list the open files/handles/sockets from a process. Common flags:
lsof -nPp PID
strace
Awesome utility to monitor the system calls an application makes. Having problems debugging an app that doesn’t seem to read your configs? Or hangs every 30 seconds? Fire up strace and attach to the pid, to find out that it’s reading the wrong path, or connecting to a downed service! Want to find the longest or most frequent running system calls? No problem! The volume of info and ease of use strace provides makes it an essential part of your toolkit. Common flags:
strace -cp PID
Will give you a nice table that counts the syscalls and sorts them, as well as the time spent executing.
strace -ttTp PID
Spits out the timing down to the microsecond of system calls.
Add -f to follow forked processes as well (handy for things like apache pre-fork, or any similar threaded/forking application). Make sure to use -o FILE to write out your output, it can move pretty quick!
gdb
The glorious debugger. If you are here, it’s probably because you have a poorly behaving app, that is core dumping. strace can only go so far.. you want to find the problem code, and kick it back to the developers. GDB will help here. We can attach to a process (which will pause it), then continue the process, and have the application perform whatever causes the core dump. At that point, GDB should spit back the problem line, and hopefully provide you a window into the problem. Common use:
gdb [binary name] [PID]
Issue “c” to continue the app. Generate your problem/seg fault, and observe the console output.
Beej has a pretty slick guide to gdb: http://beej.us/guide/bggdb/
In: linux, tools, troubleshooting · Tagged with: tools linux
Blag this!
Just getting started.. hold on to your hats.