[Bleep]y Error Messages

[Bleep]y Error Messages.
(My daughters might read this blog, so I need to keep it G audience.)

I encountered yet another useless error message today.

Not that I've blogged before about this, but any developer, any user has experienced this, so I mean yet another useless error message from the corpus of all useless error messages inflicted upon any user anywhere, any time.

And they are legion.

So I won't point out the specific vendor/software/whatever.  I'll just rant about what makes a GOOD error message.

Are you smarter than a 5^th grader?

Maybe it was just my school, but we learned the basic Journalism/Essay rules in 5^th grade:

• Who
• What
• Where
• When
• Why

5^th Grade. Five Ws.

Let's apply this to Error Messages:

WHO

Exactly WHO is throwing this error message at me?
For some kind of device, like coffee maker, router, car, ok, this should be obvious.
Maybe.
Some routers have mini-web-servers built in, so maybe not...
Maybe the coffee-maker has different components.
Certainly today's cars are complicated enough.
At any rate, all the software/hardware involved should identify WHO they are in the error message:

• OS Error: Permission Denied.
• MySQL  Error: Permission Denied.
• PHP Error: Permission Denied.
• XYZ (application) Error: Permission Denied.

Every one of those would require radically different approaches to diagnose and correct.

If you, the software/hardware developer are bubbling up or passing on error messages, or to be kosher to an end user, suppressing the error message in favor of a "Something Went Wrong" error message, and logging the real message somewhere for Developers to look at, you still can at least tell the end user WHO is throwing the error message.

Even if you want to hide the inner implementation (E.g. particular Database vendor), at least tell me it's a database error that went wrong!

As a user, I can make an educated guess what course of action to take, or whom to contact within your/my/our organization.

And if the error message is for a Developer or needn't be masked for Security, I need to know who is throwing the error message.

Today's systems are too complex and too many error messages are being passed through, with all context lost.

 WHAT

What exactly went wrong? I need context. I'm not knee-deep into your code, hardware, architecture. I need enough context that I can figure out what actually happened, from Square One of knowledge.

All too often you find an error message that makes zero sense to anybody not intimately familiar with the software.

WHERE

I don't need just filename, I need the line number.
I don't need just filename, I need the full path.
In all probability, whatever you choose for a filename is going to be used by somebody else as well.
Let me know exactly where the error originates.
Is it configuration?  Business logic? Resources?

WHEN

I can read the calendar and a clock, so if the error is in real-time, I don't mean that.
Even for an asynchronous error  generated/read, I still need...
When did this error occur relative to what the software was trying to do.
Was it reading the disk, writing to RAM, reading an RSS feed, or trying to feed the pigeons.
I can't begin to diagnose what went wrong with whatever you were doing if I don't know when it happened, relative to your workflow.

WHY

Why are we here? Not in a philosophical sense,  but why is this an error in the first place? Why do you need whatever you need to carry on what you are doing? Maybe your idea of the one true source of what you need doesn't match mine. Perhaps I can provide an alternate source.

And a bonus one:

WHAT NEXT?

If you're going to tell me something went wrong, you probably have a pretty good idea what I should do to correct it. So why not tell me what to do next, or at least list some actions that will probably be useful.
Whether I have to sacrifice a rubber chicken or poke a voodoo doll or tighten the wing nut, let me know.  Odds are you already know what I need to do.  Tell me. Don't make me spend an hour googling and researching all about your software/hardware/whatever to find out I only have to turn the amp up to 11.
Give me very specific instructions. If it's really long and complicated, give me the references I need to get the instructions.  Preferably multiple references.  I may not have the user manual.  I may not have Internet access. Don't tell me of only one of the two resources. List both.

Maybe I'm just getting too old and turning into a grumpy old man. But I'm very weary of spending my time researching your error messages because you can't communicate. For the same effort, word-count, whatever, except possible thought on your part, you can give me a better error message.

Maybe you think I'm being lazy.
Maybe you think I should just shut up and take it, just like everybody else.

Maybe you think I'm asking to be spoon-fed everything.

After 20+ years of software development, I've served my time reading [bleep]y error messages and trying to make some sense of them.

What we have here is a failure to communicate.

It's not me.

PHP Caches (APC et al)

I occasionally still see people referencing ancient misinformation that various PHP bytecode caches are giving huge performance boosts by caching the bytecode so the PHP bytecode parser/compiler doesn't have to do the monumental task of reading PHP source and converting it into bytecode to be run by the Zend Engine.

Nothing could be further from the truth.

Okay, there is one tiny bit of truth in there.

The php process/program/runtime, without a bytecode cache, is in fact a JIT parser/compiler to a bytecode, which is then run by the Zend Engine.


Amd. okay, the various caches all cache the bytecode as part of the process of gaining huge performance boosts for most PHP web applications.

So that's two tiny bits of truth in a monumentally flawed statement.


But the significant boost is not from bypassing the parser/compiler.

APC and other caching mechanisms save a great deal of time by not hitting the hard disk to load the script, but keeping it in RAM, if possible. Hard disks are slow.  RAM is fast.

The bytecode is saved in cache instead of source, which does bypass the PHP parser/compiler.

But that's just "gravy"

Compare two following psuedo code samples that describe the difference the APC (or other cache) makes:

Code Listing #1

//save hitting the hard disk
if ( $source_code = in_cache($path) ){
  //got the source code from cache, do nothing
}
else{
  //file_get_contents = super-duper slow!!!
  $source_code = file_get_contents($path);
}
$bytecode = zend_parse($source_code);
zend_execute($bytecode);

//Code Listing #2

//save hitting the hard disk
//and a small bonus, cache the bytecode, not source:
if ( $bytecode = in_cache($path) ){
  //got the bytecode from cache, do nothing
}
else{
  //file_get_contents = super-duper slow!!!
  $source_code = file_get_contents($path);
  $bytecode = zend_parse($source_code);
}
zend_execute($bytecode);

As you can see, both code listings bypass the hard drive access which is super-duper slow.

But the second one also bypasses the PHP parser/compiler, simply because it's such a trivial difference, just moving one single line of code into the conditional, to cache $bytecode versus $source_code.

The savings from parsing is chump change compared to disk I/O.

It's also trivial chump change to implement.

But every ounce counts, so all the "bytecode caching" (sic) mechanisms do it this way.

They should all really be called "RAM caching, with bytecode gravy" or even "RAM caching" and just ignore the minimal difference between source versus bytecode.

I'm sure this post is going to make all the caching implementers run out and change their documentation etc. :-)

Well, at least you now understand what "bytecode cache" really means. I'll call it a "win".

Rebuild theme registry on every page.

Rebuild theme registry on every page.

During theme development, it can be very useful to continuously rebuild the theme registry. WARNING: this is a huge performance penalty and must be turned off on production websites.

The last couple weeks, I have found out the hard way exactly what this is talking about... :-(

You probably won't really notice it on page load, unless your site is high traffic.

But even a LOW traffic site, with MySQL replication set up, your MASTER hard drive is going to fill up very quickly.

We were generating 4.4G per day on a low-traffic site.

This is because re-building the theme registry on every page deletes all the {variables} and the whole theme registry and then re-INSERTs them all on every page hit.

Just flipping that off on ONE low-traffic site brought disk usage down to 400M per day.

When keeping several days' worth of mysql binary logs, that difference adds up quickly.

Note that only SOME themes even have such a checkbox in their "Configuration" panel. The most notable one (that I know of) is Zen or any theme built on Zen.

Drupal 6 Performance, Part 3

After weeks of no problems in STAGING and loadtests looking great, it turns out there's just one teensy little flaw in caching Drupal pages longer than a couple days...

Drupal nukes the CSS/JS optimized/consolidated temp files every couple days.

So the monitoring sees a nice valid HTML from an HTTP 200, but humans see a theme-less site.

Worse, the thing corrects itself somehow, or our guys jump on it and flush the cache, and it's all good...

For a couple days.

Rinse, repeat.

Digging into the Drupal caching source code even deeper, and I'm convinced: This things wasn't architected; It just grew.

It's a spaghetti code mess.

I defy any Drupal core dev to correctly describe the caching "architecture" of D6 pages, CSS, JS, blocks, views, etc in any coherent way.

I officially give up now.

When the VP of Marketing complains the site is slow, I'll just say "Yes, it is. That's Drupal."

We'll have to spider the silly thing after every cron job, actually, instead of doing that. Which sucks, but there it is.

Drupal 6 Performance, Part 2

First, I was wrong.

I was wrong on two points.

Number 1 Mistake:

I thought that there would be a slow query in the mysql slow query log that, with an index, would magically make Drupal 6 faster.

There wasn't.

There were a few slow queries, but they had perfectly good indexes, and they were slow, as far as I can tell from the symptoms, due to thread contention, as described here:
Facebook Doubles MySQL Throughput with PMP

Unfortunately, there are three problems with the solution there.
1) It would take me forever to figure out what those guys are really doing
2) We'd never be able to run un-approved MySQL patches like that
3) There's no way my VP of Marketing is pounding our server hard enough for this to be the problem I'm trying to solve.

So as much as I'd love to dive in and follow in Domas' and Mark's footsteps, that's not going to happen.

Number 2 Mistake:

In my previous article, I stated that I had attempted to eliminate some obvious candidates, and one of those was:
"It only fails after a cache flush? No."

I was wrong.

So very very wrong.

I had eliminated the manual cache flushes done by our team as a source of the problem.

What I didn't know was that Drupal 6 (and 7) has a brain-dead hard-wired notion that a "Page" in cache_page should be flushed every time cron runs.

Yes, there is a setting for cache_lifetime on your admin "Performance" page, but page_set_cache ignores that silly little administrative option.
(What actually honors that setting is perhaps an even more interesting architectural decision than flushing the Page cache every cron run.)

This is apparently a known issue as described here:
Drupals cron kills you

Note that a couple high-profile Drupal community members who should know better make blatantly wrong statements in the Comments.

I have broken the rules and patched Drupal core, and probably broken polls (we don't use them).

In your includes/common.inc file, you can apply a patch like this:

cat common.inc.patch_cache_page_honor_cache_lifetime 
--- common.inc.original 2011-09-13 09:37:30.000000000 -0500
+++ common.inc  2011-09-13 09:39:04.000000000 -0500
@@ -2701,7 +2701,7 @@
         $data = gzencode($data, 9, FORCE_GZIP);
       }
       ob_end_flush();
-      cache_set($base_root . request_uri(), $data, 'cache_page', CACHE_TEMPORARY, drupal_get_headers());
+      cache_set($base_root . request_uri(), $data, 'cache_page', variable_get('cache_lifetime', CACHE_TEMPORARY), drupal_get_headers());
     }
   }
 }

Our Drupal pages now are cached honoring the cache_lifetime setting in Performance (as I expected for the past 18+ months) and we got consistent 100 requests per second across 15 multisites in loadtests last night, as we should.

I probably should have run more nights of loadtests before posting this, but I wanted to get this typed up while it was fresh, and, really, now that I know what's going on, I'm pretty confident of this solution.

Actually, I might just change that again to CACHE_PERMANENT, as caching a page only for a day when they change very seldom is just silly. But that's probably just us. Most Drupal users probably expect the behaviour of the patch above, based on the UI.

Here's one site's zoomed in graph comparing the 13th (with Drupal pages at 0 for failing to respond at all to 90% of my ab -n 1000 -c 100) but on the 14th, similar pages get ~100 requests per second.

Note that the highest peaks in the above graph are static images and JS/CSS files, not Drupal pages.

I'm expecting my loadtest graphs to get much smoother now, with no 0s littered everywhere.