Drupal 6 Performance

There are a lot of things I like about Drupal.

Performance, however, is not one of them.

Yes, I turned caching on.
Yes, CSS and JS Optimization are on.
Yes, I used YSlow.
Yes, the GA code is at the bottom.
Yes, the images are small.
Yes, our custom HTML templates validate.
Yes, I have fought off the business unit's demands to install modules recommended by SEO "experts" (cough, cough) which are completely inapplicable to our situation. (Example: When all your content is input by staff, you really don't need that spam detector in the cloud service module. If our staff start putting in Viagra ads, we'll just fire them.)

And, yes, I have a problem.

Well, several problems, actually, but if the preceding example didn't already clue you in that the business process is quite disfunctional, and that was only the tip of the iceberg, you haven't worked for enough large corporations, and there is nowhere near enough room in this blog post to pull that iceberg into view. I'll get back on focus now.

Here's the thing: Most of the time, Drupal is hitting its built-in cache with an indexed query of the entire HTML page for an anonymous user.
This is, naturally, quite acceptable, as it simply bootstraps a few too many PHP files (minor annoyance) and runs a single indexed query on a URL->HTML relationship and spits out the page and exits.

Unfortunately, my performance "pre-emptive monitoring. quasi-loadtest, and let's make sure none of these sites will make PRODUCTION fall over, and let's catch when the Drupal guy didn't turn caching on" ad hoc process, indicates that occasionally, some URL is performing abysmally [viz].

I am not an expert in testing, nor Drupal, nor mysql. But I have spent 25+ years specializing in PHP applications, so know a little bit about all those things. If my methodology is a bit "off", I am pretty confident the results are still "close enough".

Specifics:

I have 15 multisites same-codebase different-database D6 sites on a STAGING box, where business units QA (sort of) and approve (or not, or shouldn't have but did) before launch to PRODUCTION. Staging is a 2-tier setup, with 1 www node and 1 mysql node. We're running stock RHEL plus EPEL builds for the most part. PHP 5.3, MySQL 5.1. If you've done Drupal multisite, I haven't done anything particularly weird or interesting here.

There are also a couple "baseline" sites, with just static HTML pages, "phpinfo();", and a "mysql_connect(); mysql_query('select version');" for comparison purposes with the real sites, just so I know that there's nothing inherently wrong with Apache, PHP, nor PHP-to-mysql.

At night, while real people sleep, I spider each site on a configurable schedule, mostly weekly, and store all the URLs in a flat file per site. In addition, every 5 minutes, an ab loadtest fires for the "next" site in a queue for a randomly-selected URL from that site:

ab -n 1000 -c 100 $random_url_here


Some of the URLs are images. Some are CSS/JS. Some are actual Drupal nodes.

I record the ab result files, prepending a line to tell me which URL was requested.

I also log the requests per second in a database table, counting a big fat 0 for any errors I can detect. For example, if there were any non-2xx HTTP response codes, it's counted a complete failure in my book. If any of the 1000 requests never came back, again, big fat 0. (This is where testing experts are probably crying in their coffee. Sorry.)

I have some kludgy-hand made PHP|GD graphs.
(Yes, I'm old-school and can visualize and draw a halfway decent graph in PHP code faster than I can fight your fancy new-fangled tools to get a really nice graph. Sorry.)

Here is what a sample site graph looks like:

(The density on the left is because I used to run the loadtests all day every day, but scaled back to night-time in the middle of this process. Yes, testing experts everywhere are crying in their coffee. Sorry.)

First thing to look at is the bottom center stats min/avg/max: 0/265/1010
That means this site is getting a very acceptable "average" 265 requests per second across all the ab runs you see in the graph.
And that 1010 means that one URL excelled and had 1,010 requests per second in an ab run.
Alas, there is a 0 for that min, and that's the problem.

In fact, looking at the green lines of the graph itself, you see a fair number of 0 data points.

I won't bore you with hundreds of ab text outputs, nor the tedious process of matching them up with the dots on the graph, but here's the basic trend:
Static CSS/JS and even images come in first place with the peaks in the hundreds of requests per second.
Most Drupal URLs come in acceptable levels around 100 requests per second.
Occasional Drupal URLs just plain bomb out with, for example, only 8 successful requests, and 992 failures and get the big fat 0.

I have also attempted to eliminate the following:

• The same URL fails all the time? No.
• It only fails after a cache flush? No.
• It only fails when a loadtest runs so long it concurs with another? No, I added code to insure only one loadtest at a time. (Testing experts crying over coffee. Sorry.)
• Only certain sites? No.
• MySQL hasn't been tuned? No. We tuned it.
• APC isn't working? No. It's fine.
• Uncached Drupal performance isn't that bad. Yes. It is. I measured it with the same (sloppy) metrics above. A simple minimal setup with stock D6 and a few pages / modules falls over after 8 requests in heavy load, without caching.

So my theory, and I admit it's not really proven, since I don't have the mad Drupal skillz to log the info to prove it, is that the setting in Performance "Minimum cache lifetime: <none>" does not, in fact, keep URLs in the cache indefinitely, and something in Drupal purges them, for reasons beyond my ken.

NOTE:
These are brochureware sites with a hundred nodes each, and a couple webforms. There are the usual Drupal modules one would expect for that. Plus all the modules I was forced to add that they never actually figure out how to configure and use that the SEO "experts" (cough, cough) told them they need.

A lot of Drupal experts have recommended PressFlow and varnish and so on. We are considering that. But even a drop-in replacement isn't that easy to manage when we are rapid-fire launching a new multisite each week. We simply don't have the bandwidth for that right now.

And, ultimately, I find it offensive that uncached Drupal falls over after 8 requests on a 2-tier php/mysql 6G RAM setup. (Assuming my theory is correct.)

It's like somebody bolted a billboard to the back of our Maserati.

Then tossed some kind of broadcast instant replay device named "cache" in front of the billboard to mask the problem.

And are now recommeding another broadcast replay device in front of the "cache" called "varnish".

So am I just going to whine about it? No. I'm going to start analyzing queries in log_slow_queries from MySQL and whatever else I can find, and try to see if I can add some indexes to make uncached Drupal reasonably performant.

Of course, real Drupal developers are all madly coding Drupal 8, since Drupal 7 was released a few months ago, and Drupal 6, to them, is just not worth patching, so my efforts will probably be largely irrelevant to the Drupal community at large. Sorry.

You'll have to wait for the next blog post to see if that succeeds or not. I may even have to eat some crow if I can't make any improvement at all.

Again, I do like a lot of things about Drupal. Performance, however, and the architecture to make it performant, is not one of them.

Xdebug and RHEL 5.7

Much ado and misinformation about how to really profile or performance analyze PHP is all over the Internet.

Rebuffs also exist to much of that misinformation all over the Internet.

How to actually really set yourself up to properly profile PHP, not so much...

So, here's an attempt to provide a step-by-step process, at least for RHEL 5.7

If you run something else, you'll have to improvise a bit.

It's not like I really picked RHEL, so that probably deserves some background...

I'm mostly an old school compile from source guy for Apache, MySQL and PHP to get what I want.

I used to use RedHat/Fedora for the base Linux / desktop, and then download source for Apache, PHP, MySQL.

I switched to gentoo a few years ago, and admit I pretty much fail to update very often, but whatever.

I only have to maintain a handful of boxes, and update when there is a real need.

In my workplace, the sysadmin is a stock RHEL guy, but then he has to maintain hundreds of servers with puppet and monitor them with Nagios and...

Well, let's just say I completely understand that need.

And he HAS opened up to Dag's repos and a UIC or ULC or somesuch to get something I needed.

Alas, when you want to do serious debugging, profiling, or performance analysis, that's not good enough.

So I recently embarked on a task to build a "debug" desktop with the following goals:

• have debug builds of php, apache, and mysql
• have xdebug
• have kCacheGrind / valgrind / callgrind to visualize bottlenecks
• this box is used for debug build, nothing else, no other users but me
• stray no further from our stock build than I have to

Of course, just installing the GUI is a pretty far straying, and I let RHEL push me into gnome rather than KDE. Not sure that was wise, but there it is.

Still, I tried to have minimal impact on the build.

Testing Experts/Pundits:
Note that I'll exit X windows once I'm ready to really test, and then fire it up again to examine the results. If having the X binaries on the box screws up my tests, so be it. I'm already replacing the REAL binaries of the code with these debug-enhanced ones anyway, so at that level, it's not "the same" anyway. Having a separate desktop with all these tools on it just didn't seem practical in my case. Your needs may vary.

I first attempted to get the debug builds of at least PHP, and hopefully Apache and MySQL, just in case.

Everything seemed to work with yum, but I spun my wheels for hours checking phpinfo() configure line for --disable-debug and trusting its output about debug build.

It turns out that the RHEL debug builds are actually not built into the same binary files that ./configure --enable-debug would do. Instead, the debugging symbols are installed in separate binaries in /usr/lib/debug, and tools like gdb and strace and the all-important (to me) "httpd -X" just "know" to look in there and load those debug symbols in on top of the non-debug binaries in the usual places.

That kind of blew my mind, but whatever, you know?

And why the httpd startup scripts and PHP don't know to look there is beyond me, but I suppose if I really need to force them to do it, I could find a way... I doubt I'll need that, as you'll see shortly.

Anyway, in order to actually get these debug builds, you have to do something like this:

yum install --enable-repo=rhel-debuginfo httpd-debuginfo mysql-debuginfo php53-debuginfo

Note that this installs only the debugging symbol binaries into /usr/lib/debug. If you actually want to install the software itself, you still need to do these if you didn't already:

yum install httpd mysql php53


You also want to install valgrind, which basically allows you to run your binaries under debugging conditions with a whole suite of tools. We'll look at just one tool, callgrind, because a) it's the only one I know so far and b) it's the one that makes pretty pictures that make it blindingly obvious where your bottlenecks are in your code.

yum install valgrind


Just to be sure you installed Apache and PHP, set up your usual PHP script for testing purposes:

echo "<?php phpinfo();?>" > /var/www/html/index.php

(Or edit /var/www/html/index.php with your favorite editor.)

Surf to http://localhost/ and see the PHP status page with lots of blue tables telling you everything you ever needed to know about your PHP install.

Now to prove you can generate a callgrind script, to generate a visual representation of where your code spends all its time:

/etc/init.d/httpd stop
valgrind --tool=callgrind --dump-instr=yes -v /usr/sbin/httpd -X

(Someday, RHEL will catch up to the rest of the world and that httpd will change to apache or apache2...)

Note that you are now running a single httpd instance/child/thread with debugging on full blast, instead of your usual high-performance httpd process.

You definitely do not want to do this on a production box, or even a shared dev box.

You need to be doing this on a sandbox all your own.
Really.
If you can't figure out why, stop reading now and go do something else.

Now, reload that phpinfo page in your browser.

Finally, kill that httpd process. Open another shell and do:

killall -9 httpd
callgrind_control -k

If you kill the process, and it's built up a HUGE file of data, it just dies before it writes the data. Don't do that.

Back in the shell where you did that valgrind command, it will have exited. It will also have dumped a file whose name starts with callgrind.out. and ends with the PID (process ID) of the httpd process that was started.

You can just safely assume it's a random number, if you are not familiar with process IDs. Actually, if you're not familiar with process IDs, this article is way too advanced for you. Oh well.

You can open that file up in an editor if you like.

It won't make much sense, really, but it's kind of cool to see it.

Don't change anything in that file, for goodness' sake. We've worked very hard to build it.

Since you can't read the silly thing, let's install some software that can: kCacheGrind:

yum install kdesdk

Don't ask me how you're supposed to figure out that kCacheGrind comes as a part of the KDE SDK tool-suite. I used Google. A lot.

Now you can run that tool to see how phpinfo() spends all its time:

kcachegrind callgrind.out.*

You have to do this in the same shell/directory where you did the valgrind, just in case you didn't figure that out on your own.

You ought to see something not unlike this:

Whoa!
What's all that, you ask?

Focus on the big splotches of color. The bigger the rectangle, the more time PHP spent in that function.

As you can see, PHP spent a lot of time calling various _dl_* functions, presumably loading up code binaries, or double-secret internal functions you should ignore for now.

But you can also see a big chunk for good old strlen

Now, obviously, you are not likely to jump in and edit PHP's strlen function and make it faster, but the point is that you now know where PHP is spending all its time in your PHP script.

Of course, with phpinfo() as the only function call, that's pretty boring.

Install your favorite framework or large application project (Drupal, WordPress, Zend Framework) or your own home-brew MVC, and load a few test pages.

Heck, just copy a whole site that you think is "too slow" onto this box in /var/www/html/ and fire it up and find out!

But wait, you say, I'm just a PHP developer. I'm not going to be re-writing PHP internals!

Well, guess what?

This genius Derick Rethans has a tool called Xdebug that you can use to do this same thing for your PHP code.

You'll have to compile it from source, because there are no packages for Xdebug yet.

Or use PECL, if you've managed to install that.

I have not installed PECL yet, so I just downloaded the "source" and did the usual:

./configure
make
make install


Oh yeah. Something should be said here about libedit if you want readline-like abilities in the debugclient.

I pretty much said "Meh." and went on with life, once I realized that I'd have to fight RHEL for another hour or two to get that.

If you need that feature in our PHP debugger, you're on your own. Sorry.

Now, add a few settings anywhere you like in /etc/php.ini:

; Added xdebug settings
zend_extension="/root/installers/xdebug-2.1.2/modules/xdebug.so"

; Disallow usage of @ to suppress errors
xdebug.scream = 1

; Turn on profiling
xdebug.profiler_enable = 1

; Dump the enormous files here
xdebug.profiler_output_dir = "/tmp/xdebug"


And, so apache can dump the files there a couple shell commands:

mkdir /tmp/xdebug
chown apache /tmp/xdebug
chmod 775 /tmp/xdebug


You have to restart apache for the php.ini changes to take effect:

/etc/init.d/httpd restart

Oh. It wasn't started because we killed it and ran it with valgrind before.
Oh well.

Anyway, reload your phpinfo() page (or other) from http://localhost/index.php

Now go look in your /tmp/xdebug directory for some callgrind.out.* files, and load them up into kCacheGrind.

Voila! You now know where your PHP code is spending all its time, just by looking for the "big" rectangles.

kCacheGrind has a zillion options and tools to slice and dice your data, and different ways to show it off.

It also can export the pretty pictures, if you have graphviz and kghostview.

GraphViz is pretty easy. Snag the repo definitions from GraphViz RHEL Repo and put it in /etc/yum.repos.d/graphviz-rhel.repo file.


yum install graphviz


Finding kGhostView was quite frustrating. It seems like RHEL is intent on stamping out KDE, and kGhostView in particular since 2002 or so. I found all kinds of rpms from that era, and not much after.

So we turn to our friends at EPEL, and use their rpm which installs and maintains their repo definitions into /etc/yum.repos.d. Did you follow that?

Just download the appropriate rpm from here:
EPEL rpm to expand yum

Now at this point, with EPEL installed, I pretty much opened myself up to straying very far from RHEL, but all I want is kghostview so kCacheGrind can export pretty images:

yum install kghostview


Woof.


I'm pondering if I should now uninstall the EPEL stuff, just to stay on the straight and narrow, and let kghostview lag, or try to remember to only use EPEL in dire circumstances...

Well, anyway, you probably don't care about that bit.

You now should have a very powerful tool suite to really find the bottlenecks in your PHP code, instead of trying some Voodoo Analysis to "optimize" things like changing all "" to '' or using a single (un-indexed) query instead of two (indexed) queries, because running more queries is slower, or...

I know, I promised not to go there in the first paragraph, so I'll shut up now.

Brain Surgery

On August 31, 2010, I went into brain surgery.

This is a "delayed" blog post about that.

It got rather long, I'm afraid, which is why it took so long to get up here...

Plus I've been kind of busy until now, where I have a 2-week lull between post-op and Radiation.

But people seem more interested in the actual surgery than anything else, so here is a play-by-play of what I remember from it.


The day started early, with a 5:45am arrival for a brain-mapping GPS MRI scan
and 7:30 surgery. I had been warned I might lose my hands for a week, as they were probably going to "nudge" my motor strip in that area when they cut out the tumor.

After they put all those circular markers on my head, they scanned me, and then I guess dumped a map of my brain to the surgeon's computer.

I was then wheeled into Pre-op which is a fancy word for hallway with curtains.
Felt kind of like being in the wings of a particularly clean Theatre stage for any
Old Troopers. I guess it makes sense for resource management, but it sure doesn't seem very nice. I was lucky not to be too back-logged I guess. I imagine on a bad day, you could end up waiting there for hours and hours.

Dr James P. Chandler

Then started the introductions. I had already met the surgeon Dr Chandler, but was introduced to at least three anesthesiologist including Dr. Koht and his two assistants, and the Chief Resident, Ryan Halpin, who turned out was my "coach" for the surgery (viz) and he seemed to be the one watching the heart and other squiggly lines monitor that I could also see. Though I daresay there were many others monitoring all kinds of stuff I never even saw.

I think I got re-introduced to some doctors/nurses, and I'm told surgery started 2 hours late, but I didn't notice, so maybe that was their plan... Just keep me trying to remember names and faces and distract me :-)

Anyway, they wheeled me in, hooked up an IV or two, and conked me out. They apparently locked down my head and connected some plumbing then, for which I'm quite thankful I was not awake. That probably seems normal enough for any surgery. Then they woke me up, still on the table!

They had me move my fingers around and monitored stuff on their computers to make sure things looked right. They cut open my scalp and chopped a hole in my skull. Did I mention I was still awake?!

So then I presume he moved the protective water balloon brain sac aside, and went in through the vein above that red arrow, or moved some brain bits aside...

Then they had me touch each finger to my thumb and said they were getting signals on that.

Then he hooked up a wire to my brain and made a nerve in my right wrist  twitch at 60 Hz and asked "Can you feel that?" Surreal!

If you've ever gotten a light tremor from house current running through you for a few seconds, it was just like that.  Only direct from my brain. And on purpose.

They also confirmed on some med computer that they were seeing the same signal.

Repeated the process, for my right ankle. Then the left ankle. Each time they asked me "Can you feel that?", and confirmed signal with each other.

They didn't do my left wrist, which was disconcerting, but I'm not sure I was able to voice that concern well.

Then they warned me that they were going to do a few more that I wouldn't feel.

There's not supposed to be any nerves inside the brain, but I WAS able to sense each probe in turn as a sort of cool prick. I told them all about it, apparently in more detail than they required: I believe this was the first time they politely told me to be quiet and focus on taking nice deep breaths.

That would be Dr. Ryan Halpin, the "coach" and I have to say he has the patience of a saint. He managed to put up with me and keep me on task while I was halfway zonked out, which is a miracle.

They ran through all the signals again, confirming I could feel the nerve twitching at 60Hz and seeing the signals on their computers. Apparently "measure twice, cut once" applies to brain surgery as well as lumber.

Come to think of it, counting up MRIs (regular, functional, spectroscopic, and mapping) as well as CT scans and the probes, it was more like "measure 10X, cut once." Same principle at least, but I suppose a factor of 10 for Brain Surgery makes sense.  I mean, tossing a 2x4 out is one thing... :-)

Then Dr Chandler cut out the actual tumor. I think this may have been another time I was politely told to shut up and breathe. It seemed like the actual tumor removal only took 10 minutes, but my time sense wasn't exactly perfect, eh?

Finally they started putting things back together. There's a chunk of skull held in by titanium plates and screws (Looking for a pic of these). No MRI or airport restrictions on those, which is nice.

There is apparently some glue in there holding something together as well.  I wonder if they have a $10,000 hot glue gun just like my $20 one at home, or if it's some kind of packet like a condiment they use.

Then the scalp was stapled shut, as you can see to the right:
I kind of expected some stitches, but if I have any, I sure can't find them, even now that the staples are out.


At some point the doc asked for a 1x3, but the nurse only had a 2x2. They went back and forth a few times on that, which was disconcerting. I mean, who cares about the shape of the scar or whatever, but the wrong size screws or plate inside?... I didn't know exactly what stage of re-assembly we were in, so I tried to make a joke about lumber, but it fell flat. Oh well. Tough crowd I guess.

(Weeks later I found out it was just a gauze swab to wipe out some blood or something. Whew!)

They also didn't like when I broke into a song lyric with a trigger word/phrase somebody said; which anybody who knows me is a habit of mine. Guess I don't sing any better while in "twilight" anesthesia. But I only did that once, so that's not so bad! A musician friend of mine tells me she had the whole operating room staff singing with her. That was definitely one of the times I was politely told to shut up and breathe deeply.

Then they wheeled me out to post-op (read: hallway curtains) where I spent 2 hours needing to be there, and six more hanging around waiting for a room, thanks to construction... I've got a few pithy comments about post-op and a certain nurse, but will save those as I've already made this quite long.

Anyway, that's all the bits I can remember from nearly 3 hours of brain surgery. I apologize if it's out of order, or I've managed to completely mess up what they did. All I know is, it was surreal, but they got the tumor out, and over-delivered as my hands worked just fine, albeit with a bit of tingling and numbness now and then. I'm calling it a "win"

Honestly, the only things I could have asked for:

• Advance notice that my main job would be deep breathing.  They had described the finger / nerve twitching process in advance. But perhaps the breathing thing is case-by-case. I probably could have kept more quiet and done more breathing if they had.
• Check that left wrist, or tell me we don't need to.
• Let me know what is going on when the doc asks for a 1x3 and they ain't got it, so I'm not worried about it.

Considering everything else going on, these seem awfully petty!

Brain Surgery Staples Removed

I got my staples removed yesterday, so here's what it looks like today...

So, what I've got going for me:
I'm relatively young, in good health other than this cancer in my brain, and a wild guess estimate is 90% of it was in the tumor they already took out.
I've got just about the most supportive family, friends, and workplace anybody could ask for.

On the downside, if you lump me in with males up to age 90 with brain cancer, my "live expectancy" is a couple years...

 But, hey, let's Do The Math:

A guy 90 years old, already has not much more on "life expectancy"...  There's no numbers I can find breaking it down by decade or anything,  so let's assume it's some kind of curve, and I'm on the right end of the curve.

It blew up fast, over the course of a couple months or even weeks, so there was not much more that could have been done for "early detection".

The docs have caught it in time to get 90% out already, and will radiate and chemo the other 10%.  It will try to grow back, but we'll MRI it every couple months and catch it and chemo it some more, beating it back into submission.  So we have a game plan to keep this under control indefinitely.

Do I expect to make it to 70+, like my dad, as I once did?

No, not really.  I'll give it my best shot though!

Maybe I'll only hit 65, like my Mom.  Still not a bad run.

So what's my "life expectancy"?  I expect to get as much out of it as I can for as long as I can, same as anybody else!

Brain Tumor Pathology

Tumor w/ Surrounding "Bad Stuff" in active tissue

Brain Tumor Pathology
(translated from Medical to English)

Malignant.
Grade 4 (worst)
The surgeon got the main tumor out.
But it's guaranteed to have a splatter effect of Bad Stuff mixed in surrounding brain tissue.
Aggressive radiation/chemo (6wks/6months respectively) will maybe beat it back.
Then, ongoing maintenance of MRI scans every couple months, and chemo when more tumors appear, for life.

I guess that's not as bad as the old school movie "Go home and die" answer, but I think these days it's about as bad as it gets folks...

On the other hand, the oncologist said that the odds of hearing benign were in the realm of "case study in a journal".  I do wish they had just told me that weeks ago. I've been living with a false hope of hearing "benign" and on the hook of not knowing for weeks... Oh well.

I'm staying as positive as I can, but I'm in for a rough ride, and that's the breaks.

Thanks for all your prayers, support, and donations.

I'll try to post more on Friday 9/10. Tomorrow 9/9 is a CT scan with some kind of plastic fencing mask to map where the tumor used to be married with the old MRIs to program the linear accelerator for the radiation treatment.  Or, at least, that's my layman's understanding of what the doctor said...

I think I get my staples out of my scalp tomorrow too.  That's good, as the changing Autumn weather is making them hot/cold expand/contract in an annoying way. That probably sounds silly/petty in the grand scheme of things, but there it is.

Anyway, expect silence Thursday 9/9 from me, almost for sure.  I don't think they let me use my laptop from inside a CT scanner :-)

I also want to thank my employer, Rasmussen who have bent over backwards throughout this ordeal to keep me "employed" and "current" in insurance coverage. I don't know what I'd do without them. If you are looking for a good place to work in the online education industry, check out the openings and tell them I sent you:
Rasmussen Employment Opportunities
They've done right by me, that's for sure!