Joyent

DTrace, MySQL, Ganglia, and Digging for Solutions

I stay generic when blogging, but I had an interesting problem today that I thought I’d share. I’ve got a Ganglia rollout thats constantly growing. Some time ago Gmetad start struggling to keep up and would report nodes down (oddly, if you refreshed the page over and over you’d see the number of nodes roll up and down, 8 down, 7, 6, 4, 2, 0, 8…). The temporary fix was to simply reduce the number of monitored clusters. But this irritated me because gmetad really is pretty light on CPU and memory usage… Ganglia is synonimous with “scale”, so why won’t it scale?

# iostat -xn sd3 1
                    extended device statistics              
    r/s    w/s   kr/s   kw/s wait actv wsvc_t asvc_t  %w  %b device
   92.1  158.2 5460.8 2075.6  0.0  9.8    0.0   39.0   0  71 sd3
                    extended device statistics              
    r/s    w/s   kr/s   kw/s wait actv wsvc_t asvc_t  %w  %b device
  207.0  244.8 12990.2  509.0  0.0 15.2    0.0   33.5   0 100 sd3
                    extended device statistics              
    r/s    w/s   kr/s   kw/s wait actv wsvc_t asvc_t  %w  %b device
   64.0  330.8 4076.2 1083.7  0.0 19.2    0.0   48.7   0 100 sd3

I had noticed via iostat that disk IO was excessive for what the system was doing. Thats were I started. I could write some D script to explore, but Brendan Gregg’s DTrace Toolkit already contains useful scripts like iotop and iosnoop, so decided to save some time and use those. Here’s a snapshot from iotop:

2008 Apr 23 21:48:47,  load: 0.32,  disk_r:  34909 KB,  disk_w:  20108 KB

  UID    PID   PPID CMD              DEVICE  MAJ MIN D            BYTES
    0      3      0 fsflush          sd3      31 192 W           744448
  100  24277  24180 mysqld           sd3      31 196 W          3801088
  100  24277  24180 mysqld           sd3      31 196 R          4358144
    0      0      0 sched            sd3      31 196 W         16045056
    0      0      0 sched            sd3      31 196 R         31389188

MySQL is doing a lot more IO than it ought to be. I know that Zabbix is using MySQL but I’ve got several other apps that may be using it as well, so I’ll keep that on my hit list. The “sched” IO is actually cache flushing, typically from the ZFS ARC (ZFS’s buffers). So I need to look at what MySQL is doing and then at file IO but this time at the POSIX layer so that I can see which files are being touched.

MySQL first… I like my my_qcache.d script because I can see queries, execution time, and whether or not its being served from the query cache (Qcache). Here is the script:

#!/usr/sbin/dtrace -s
/* 
 *   Query Cache Viewer; benr@joyent.com
 */ 
#pragma D option quiet

BEGIN
{ 
        printf("Waiting for queries... hit ^c to quit.n");
}
pid$target:mysqld:*dispatch_command*:entry
{
        self->query = copyinstr(arg2);
        self->start = timestamp;
}
pid$target:mysqld:*send_result_to_client*:entry
{
        self->cache = "Yes";
}
pid$target:mysqld:*do_select*:entry
{
        self->cache = "No";
}
pid$target:mysqld:*dispatch_command*:return
{
        this->end = timestamp;
        this->elapsed = (this->end - self->start)/1000000;
        printf("From Query Cache?: %s in %d ms t| Query: %sn", self->cache, this->elapsed, self->query);
        self->start = 0;
        self->query = 0;        
}

Here is a sample of what I got…

$ ./my_qcache.d -p `pgrep -x mysqld`
Waiting for queries... hit ^c to quit.
From Query Cache?: Yes in 0 ms  | Query: begin;
From Query Cache?: No in 0 ms   | Query: select httptestid,name,applicationid,nextcheck,status,delay,macros,agent from httptest where status=0 and nextcheck<=1208987526 and mod(httptestid,5)=1 and  httptestid>=100000000000000*0 and httptestid<=(100000000000000*0+99999999999999) 
From Query Cache?: No in 0 ms   | Query: select httptestid,name,applicationid,nextcheck,status,delay,macros,agent from httptest where status=0 and nextcheck<=1208987526 and mod(httptestid,5)=0 and  httptestid>=100000000000000*0 and httptestid<=(100000000000000*0+99999999999999) 
From Query Cache?: No in 0 ms   | Query: select httptestid,name,applicationid,nextcheck,status,delay,macros,agent from httptest where status=0 and nextcheck<=1208987526 and mod(httptestid,5)=3 and  httptestid>=100000000000000*0 and httptestid<=(100000000000000*0+99999999999999) 
From Query Cache?: Yes in 0 ms  | Query: select count(*),min(nextcheck) from httptest t where t.status=0 and mod(t.httptestid,5)=3 and  t.httptestid>=100000000000000*0 and t.httptestid<=(100000000000000*0+99999999999999) 
From Query Cache?: Yes in 0 ms  | Query: select count(*),min(nextcheck) from httptest t where t.status=0 and mod(t.httptestid,5)=1 and  t.httptestid>=100000000000000*0 and t.httptestid<=(100000000000000*0+99999999999999) 
From Query Cache?: Yes in 0 ms  | Query: update items set nextcheck=1208988127, lastclock=1208987527 where itemid=20837
From Query Cache?: Yes in 10 ms         | Query: commit;

After looking at queries fly by its clear that all this is happening by Zabbix. A lot of data is being written, thats gonna happen, but there is also a lot of disk read that calls for some tuning. I’ll set that aside for now and given that Zabbix is an auxilary monitoring solution I’ll just shut it down for now to concentrate on Ganglia. After shutting down Zabbix I check the MySQL query activity again:

root@ev2-admin tmp$ ./my_qcache.d -p `pgrep -x mysqld`
Waiting for queries... hit ^c to quit.                
^C          

Ok, MySQL is quiet. Now I can dig into Ganglia without auxiliary noise.

I looked back at iostat and things didn’t look drastically different. How can this be? For a second I though that perhaps that Ganglia might simply be running out of File Descriptors, perhaps its opening lots of files (RRDs in this case) simultaneously and thats my cap? So I’ll check the resource controls (rctl’s) with a sepecial eye on the FD limit:

# prctl -i process `pgrep gmetad`
NAME    PRIVILEGE       VALUE    FLAG   ACTION                       RECIPIENT
...
process.max-file-descriptor
        basic             256       -   deny                             12528
        privileged      65.5K       -   deny                                 -
        system          2.15G     max   deny                                 -
...

So the “basic” limit is still in place limiting the process to 256 (POSIX standard) limit. The “recipient” is the PID, not a counter. Now, I can increase that threshold or simply dump the “basic” limit to allow the full “privileged” limit, but do I need to? Using pfiles I’ll check the number of open file descriptors… I run it over a couple times to see how much the number is changing over time:

# pfiles `pgrep gmetad`
12528:  /opt/ganglia/sbin/gmetad
  Current rlimit: 256 file descriptors
   0: S_IFREG mode:0444 dev:278,4 ino:5705 uid:60001 gid:0 size:336
      O_RDONLY
      /proc/12528/psinfo
   1: S_IFSOCK mode:0666 dev:283,0 ino:8706 uid:0 gid:0 size:0
      O_RDWR
        SOCK_STREAM
        SO_REUSEADDR,SO_KEEPALIVE,SO_SNDBUF(49152),SO_RCVBUF(49152)
        sockname: AF_INET 0.0.0.0  port: 8651
   2: S_IFSOCK mode:0666 dev:283,0 ino:57377 uid:0 gid:0 size:0
      O_RDWR
        SOCK_STREAM
        SO_REUSEADDR,SO_KEEPALIVE,SO_SNDBUF(49152),SO_RCVBUF(49152)
        sockname: AF_INET 0.0.0.0  port: 8652
   3: S_IFDOOR mode:0444 dev:286,0 ino:35 uid:0 gid:0 size:0
      O_RDONLY|O_LARGEFILE FD_CLOEXEC  door to nscd[24142]
      /var/run/name_service_door

Well, ok, so clearly the number of file descriptors isn’t the issue…. but just in case I wanted to rule out the issue completely. While I could use DTrace, this isn’t a production impacting application so I did a quick naughty look with truss:

# truss -p  `pgrep gmetad`
...
/125:   mkdir("/opt/ganglia/data/xxxxxxxxx", 0755)     Err#17 EEXIST
/125:   mkdir("/opt/ganglia/data/xxxxxxxxx/yyyyyyyyyyy", 0755) Err#17 EEXIST
/125:   xstat(2, "/opt/ganglia/data/xxxxxxxxx/yyyyyyyyyyy/load_fifteen.rrd", 0xF6F3B874) = 0
/125:   open64("/opt/ganglia/data/xxxxxxxxx/yyyyyyyyyyy/load_fifteen.rrd", O_RDWR) = 7
/125:   fstat64(7, 0xF6F3B200)                          = 0
/125:   fstat64(7, 0xF6F3B130)                          = 0
/125:   ioctl(7, TCGETA, 0xF6F3B1CC)                    Err#25 ENOTTY
/125:   read(7, " R R D? 0 0 0 3????".., 4096)     = 4096
/125:   llseek(7, 0, SEEK_CUR)                          = 4096
/125:   lseek(7, 0, SEEK_END)                           = 12112
/125:   llseek(7, 0, SEEK_CUR)                          = 12112
/125:   llseek(7, 0, SEEK_CUR)                          = 12112
/125:   lseek(7, 1312, SEEK_SET)                        = 1312
/125:   fcntl(7, F_SETLK64, 0xF6F3B314)                 = 0
/125:   mmap64(0x00000000, 12112, PROT_READ|PROT_WRITE, MAP_SHARED, 7, 0) = 0xF6B30000
/125:   munmap(0xF6B30000, 12112)                       = 0
/125:   llseek(7, 0, SEEK_CUR)                          = 1312
/125:   lseek(7, 772, SEEK_SET)                         = 772
/125:   write(7, "9DCC0F H???? 1 . 5 5".., 540)     = 540
/125:   close(7)                                        = 0
/125:   mkdir("/opt/ganglia/data/xxxxxxxxx", 0755)     Err#17 EEXIST
/125:   mkdir("/opt/ganglia/data/xxxxxxxxx/yyyyyyyyyyy", 0755) Err#17 EEXIST
/125:   xstat(2, "/opt/ganglia/data/xxxxxxxxx/yyyyyyyyyyy/proc_total.rrd", 0xF6F3B874) = 0
/125:   open64("/opt/ganglia/data/xxxxxxxxx/yyyyyyyyyyy/proc_total.rrd", O_RDWR) = 7
/125:   fstat64(7, 0xF6F3B200)                          = 0
/125:   fstat64(7, 0xF6F3B130)                          = 0
/125:   ioctl(7, TCGETA, 0xF6F3B1CC)                    Err#25 ENOTTY
/125:   read(7, " R R D? 0 0 0 3????".., 4096)     = 4096
/125:   llseek(7, 0, SEEK_CUR)                          = 4096
/125:   lseek(7, 0, SEEK_END)                           = 12112
^C/125: ioctl(7, TCGETA, 0xF6F3B1CC)                    Err#25 ENOTTY
...

So its doing a lot of IO and its happening sequentially. A file is opened, worked on, closed, next… so clearly this shows that file descriptor limits are not an issue here.

Truss is a quick and dirty tool, but I want a little more percision. Lets try something out of Brendan’s bag of tricks:

$ ./fsrw.d  
Event            Device RW     Size Offset Path
sc-read               .  R     4096      0 /zones/z000000AA/root/opt/ganglia/data/xxxxxxxx/yyyyyyyyyyyy/.disk_total.rrd.Imbi4x
  fop_read            .  R     4096      0 /zones/z000000AA/root/opt/ganglia/data/xxxxxxxx/yyyyyyyyyyyy/.disk_total.rrd.Imbi4x
sc-write              .  W      540      0 /zones/z000000AA/root/opt/ganglia/data/xxxxxxxx/yyyyyyyyyyyy/.disk_total.rrd.Imbi4x
  fop_write           .  W      540      0 /zones/z000000AA/root/opt/ganglia/data/xxxxxxxx/yyyyyyyyyyyy/.disk_total.rrd.Imbi4x
sc-read               .  R     4096      0 /zones/z000000AA/root/opt/ganglia/data/xxxxxxxx/yyyyyyyyyyyy/.cpu_speed.rrd.Dmbi4x
  fop_read            .  R     4096      0 /zones/z000000AA/root/opt/ganglia/data/xxxxxxxx/yyyyyyyyyyyy/.cpu_speed.rrd.Dmbi4x
sc-write              .  W      540      0 /zones/z000000AA/root/opt/ganglia/data/xxxxxxxx/yyyyyyyyyyyy/.cpu_speed.rrd.Dmbi4x
  fop_write           .  W      540      0 /zones/z000000AA/root/opt/ganglia/data/xxxxxxxx/yyyyyyyyyyyy/.cpu_speed.rrd.Dmbi4x

So fsrw.d from the DTrace Toolkit spits lines flying by… we’re doing a lot more IO that I realized and we’re doing it small chunks. Looking back at my iostat output from earlier I notice that the number of ops shown was low, but we’re doing a ton of IO… ZFS is clearly doing a good job of grouping and caching IO for me. The disk just can’t seem to keep up, and I’ve still got more than half of my Ganglia nodes unmonitored meaning that I need to at least double the IO load to solve my problem.

Lets look at that iostat output again:

   r/s    w/s   kr/s   kw/s wait actv wsvc_t asvc_t  %w  %b device
   ...
   92.1  158.2 5460.8 2075.6  0.0  9.8    0.0   39.0   0  71 sd3
  207.0  244.8 12990.2  509.0  0.0 15.2    0.0   33.5   0 100 sd3
   64.0  330.8 4076.2 1083.7  0.0 19.2    0.0   48.7   0 100 sd3

These are 1 second intervals. The throughput is low, the IO size (kw/s divided by w/s) isn’t terrible, but my asvc_t (average service time in ms) is higher than I’d expect on local 10K SAS drives, combined with the 100% busy. Combine those two facts, 100% busy and asvc_t thats significantly higher than average latency (~10ms) on the drive and I know that the drive is moving that disk head way more than it should, we’re dealing with a lot of scattered blocks on disk clearly. I could use DTrace to look at the LBA on IO’s but I don’t think I need to go that far. The problem is clear, the disk just can’t keep up with the flood of IO from Ganglia. Normally this is where I’d go looking for a new RAID controller or tuning any kernel parameter I can find… but we’re not talking about a lot of data here, these are RRD files, the total size of my Ganglia data/ directory is less than 50MB!

One way to solve this problem would be to get a really big RAID controller, but thats expensive. Besides, how does it really speed things up? Caches! Well, hell, I’ve already got a lot of free memory on this system and I’m not dealing with gigs of data… why not just store Ganglia data file in system memory? If I did that I’d provide more IO speed to Ganglia than it could exceed and free up my disks to do something more useful.

Enter tmpfs. Rather than code some nifty caching mechanism into gmetad, I could just mount a tmpfs segment as its data directory. Seems silly at first, but it would be fast and looking at Web 2.0 scalability apps like Varnish, Memcached, etc, they’ll store anything in memory… why not this? So the only trick is sync’ing the data in memory to disk periodically in case of a crash.

So I wrote up a startup wrapper for gmetad (which is invoked as an SMF method) that looks like this:

#!/usr/bin/bash
## SMF Start method for Gmetad
## -benr

if ( mount | grep "/opt/ganglia/data on swap" >/dev/null )
then
         echo "Tmpfs already mounted."
else
         echo "Mounting tmpfs..."
         chown nobody /opt/ganglia/data
         mount -F tmpfs -o size=100m,noxattr swap /opt/ganglia/data
fi

## Now sync the data in if its empty:

if [ -d /opt/ganglia/data/__SummaryInfo__/ ]
then
         echo "Cache primed, ready to start."
         chown -R nobody /opt/ganglia/data
else
         echo "Priming the cache..."
         /opt/csw/bin/rsync -at /opt/ganglia/data-disk/ /opt/ganglia/data/
         chown -R nobody /opt/ganglia/data
fi

## Finally, start ganglia:
/opt/ganglia/sbin/gmetad

Now I just add a cronjob to rsync the tmpfs data every 5 minutes:

# Sync gmetad ram-disk to physical-disk
#
5,10,15,20,25,30,35,40,45,50,55,0 * * * * /opt/csw/bin/rsync -at /opt/ganglia/data/ /opt/ganglia/data-disk/

After about 20 minutes of tinkering I get things right, stop and restart Ganglia, but this time with all the clusters enabled. To my delight the disk was getting a much needed vacation, the system performance was smoothed significantly because the IO system wasn’t busy all the time, Ganglia was working perfectly and faster than ever, and on top of it all I’ve increased the life of my disk because it’s not pounding the heads 24 hours a day.

After sharing my solution a bit I found that a lot of people are using tmpfs for RDD storage for the same reason I am. Wish they’d told me before. :)

We’ve seen here how powerful the observability capabilities of Solaris are, how DTrace helped us to understand both IO activity and even peek into a MySQL database, how iostat helped us understand what my hard drives were doing as well as how truss, rctls and the Solaris ptools (pfiles in this case) helped us investigate and rule out some hutches along the way. Furthermore, we’ve seen how we can exploit ‘tmpfs’ to trade a little memory for some big wins in terms of both longevity and performance, without having to write a line of code, just a couple of commands in a shell script combined with a cron job.

Solaris for the win. ;)

Fatboy Ambien: The Manhattan

The official Joyeur bourbon is Woodford Reserve (though we like Booker’s for cask strength), and after a long day chatting about the future of the western web, we like to sit back and enjoy a nice Manhattan. Here’s what you’ll need:

• Woodford Reserve (or Booker’s, if Monday was really tough) kentucky bourbon
• Martini and Rossi sweet vermouth (aka “Rosso”)
• Angostura bitters
• Maraschino cherries with stems
• Fresh store-bought ice
• A cocktail strainer

Fill a tumbler with store-bought ice. Why store-bought ice? Because if you use ice from the ice maker in your freezer, it is probably covered with dust (yes!) and/or smells like the tuna steaks you shoved in the ice box last summer swearing a better diet. Store-bought ice is pure.

Shake some Angostura bitters over the ice. Our preference is for four to five shakes. Just cover the top of the ice. Then, in the glass, you’ll want to fill it with one-third for the sweet vermouth, and two-thirds for the Woodford Reserve bourbon. You can experiment with the proportions. Stir the drink with a large spoon. Never shake. This isn’t a vodka martini.

Find a nice, generous martini glass. Some people like their Manhattan over ice. They’re cutting the alcohol of the bourbon with the melting ice water. We prefer to cut the alcohol of the bourbon with the sweet vermouth. Place a couple of the cherries into the glass then strain the drink into the glass. Your drink should have a rich, beautiful brown, liquid caramel color. Nice.

click for larger version

Cheers.

FAQ:

Q: Why doesn’t sheet I’mean tha iznt you want a big mac burger?

A: Please drink responsibly.

Pepperiness

As long as Martha Stewart and that bam guy aren’t involved, I’ll watch pretty much any cooking show, and, to the irritation of my girlfriend, who has a steel trap memory and can’t be bothered to sit through anything more than once, I’ll watch pretty much any cooking show again and again until whatever method or recipe is shoehorned in nice and tight. Then I’ll rush to the store, find half the required ingredients and improvise the rest, cook, eat, conclude that it didn’t go all that well, and then never make the same thing again.

I’m just as compulsive with books about food (as opposed to cookbooks; recipes are lame documentation), albeit with less of the Must Make That Now urge. Elizabeth David, Margaret Visser, MFK Fisher: love them all, and the current size of my gut is a pretty good indication I should get back to reading something a little less decadent. Or something. Anyway. Here’s a strong strong recommendation for this Summer’s Heat, by Granta founding editor Bill Buford. Through the careful, gentlemanly prose you’d expect from someone who’s edited basically every significant writer of the past twenty years, the book serves up (shaddup) three interlocked narratives: about working from the bottom up in a cramped and hot New York restaurant kitchen while the celebrity chef/owner gabbles about out in the dining room; about the overwhelming desire of celebrity chef/owners to criticise and insult the competition to its face; and also about Buford’s own pilgrimages to spend months and even years learning at the side of various masters: of pasta, of polenta, of meat.

The meat passage, in which Buford spends a long and gruelling time with a larger than life Italian butcher, is I suppose the best and most memorable part of the book. Interesting also to note that the American edition, unlike its UK counterpart, refers rather preciously in its subtitle to the Tuscan with whom Buford apprentices as ‘Dante-Quoting’. On the British jacket he’s merely a ‘Butcher’, the Dante namecheck being a tad twee for them, one surmises. Thing is, apparently Dario Cecchini does quote Dante quite a lot, such as on the Sunday morning when Buford first shows up to learn the craft: he walks in to find the place packed, Mozart blaring out of the shop stereo, people sloshing glasses of red wine and cramming their faces full of white foam (raw pork fat) on bread, while the enormous Cecchini stands above them, calling out greatest-hit cantos from The Divine Comedy.

It’s after a lot of contemplation about muscle and sinew you are provided with one of the few intact ‘recipes’ for a single dish in the book. Simplicity itself: put a shank of beef in a dutch oven with a bottle of wine, salt, and a small mountain (okay, four heaping tablespoons) of fresh ground black pepper, and put it in a low oven for TWELVE HOURS (it’s worth repeating that, in the book anyway, and pardon my Italian, this is officially referred to as ‘cooking the shit out of the fucker’). Dish it up with some crusty bread, a glass of wine, and wait for the peppery tears to flow. Just had it at lunch, and I’m telling you that’s some good stew. May actually cook it again.

A brief geeking interlude: A real mixed grill

I ate a thing called a mixed grill lately.

It was at a bar (or rather an Irish Pub) in San Francisco called Fiddler’s Green which is really the other place one can seem to buy a pint of Smithwicks and oddly enough it seems to be owned and operated by actual Irish people.

So deciding to also get something to eat, I see a “Ploughman’s Mixed Grill” on the menu and considering that it included

• Charbroiled pork chops,
• Irish bacon,
• Sausages,
• Black and white pudding,
• Grilled tomato,
• Sauteed onions,
• Baked beans
• Mashed potatoes

And

• 2 fried eggs.

How can a fat boy say “No” to that?

Cheesesteak

In the hierarchy of sandwich greatness these come in second, holding steady beneath turkey/stuffing/gravy/cranberry on brown, and just above lox/cream cheese/capers/red onion on a bagel. All three do well on the comfort food scale, but a cheesesteak trumps all when it comes to sheer sin.

Note that none of the following is particularly conducive to vigorous health or low blood pressure (though Hoffman keeps trying to tell me that sodium intake has nothing to do with hypertension compared, say, to an utter dearth of exercise, ahem) but good heavens does it hit the spot for Sunday lunch or movie night. Guaranteed to win over pouty French teenagers every time, but that’s more my problem than yours.

You will need:

• fresh, crusty and rather dense hoagie-style rolls
• some nicely marbled rib-eye steak(s)
• green and red peppers
• red onion
• Cheez Whiz or sliced provolone, or both

A sharp slicing blade is crucial here, so wrap up all your dull battered knives in newspaper and head down to your local wingnut hunting & fishing & ammo shop, where Cletis or Earl or whoever will be happy to grind back a bitter-sharp edge for a nominal fee. Don’t try to sharpen on a whetstone or with a honing steel, because you’ll just make it worse. (Do of course use a steel once your knives are sharp: two or three light strokes every time you’re going to cut.)

As you get going, think in terms of extreme temperatures: very cold meat and very hot metal. Put the steak(s) in the freezer for at least an hour before doing any slicing, otherwise they’ll have too much give and you won’t get proper, consistent thinness. As to the cooking surface, it’s important to have high heat that won’t dissipate when frying. A non-stick pan therefore, no matter how fancy, won’t do the job. You want a nice big cast-iron skillet on the stove, rendered so hot that you’re kind of afraid to stand near it.

Cut off and discard the top and bottom of the peppers, slice through the resulting cylinder once, lay the halves flat skin-side down, and remove the nasty white ribs from the pepper flesh with your knife. Slice into quarter inch thick sticks and put in a bowl.

Peel and trim the onions, cut in half pole-to-pole, lay flat then slice equator-to-centre at quarter inch increments. Toss with the peppers in the bowl with a good pour of vegetable oil and a big pinch of salt and pepper.

Slice the slightly frozen steak against the grain as thinly as possible, strew the meat in a single layer across the cutting board, and sprinkle on about twice as much salt as that with which you’d ordinarily be comfortable.

Put the vegetables into the very, very hot skillet and begin agitating at once, using tongs to dislodge anything that sticks. After 30 seconds or so, alternate agitation with stillness, so the vegetables have a chance to get a little brown. When everything has started to soften, throw in a splash of water (or better yet, strong beef stock), and once this has evaporated, dump everything onto a plate and set aside.

Once more ensure the skillet is unreasonably hot and fry the sliced beef in batches. Distribute in a single layer and do not disturb for at least thirty seconds so some browning can happen, then agitate quickly before scooping everything onto a plate. If the pieces of meat are overcrowded, steam won’t be able to escape and you’ll end up trying to fry in a puddle. Don’t do it. Each batch shouldn’t take more than about 45 seconds. Combine everything back in the pan, check for salt and pepper, and let heat through.

And then, darling one, this is important: you’re going to have to fry the bread. Get another pan medium-hot, slice open the rolls, spread with butter and lay butter-side down until nice and brown and just barely crispy.

Slap in some cheese or cheez, and rather a lot of the good stuff from the pan, roll up tight in tinfoil, pile up on a tray, and deliver to the cheering hordes.

Tortilla Soup

While St Patrick’s day gets all the attention in the United States, St Joseph’s day, March 19, which is very popular in Mexico and the rest of Latin America (among other places), offers many more opportunities for culinary adventure. And yes, I sat with some of the Joyent team last Friday the 17th to eat cabbage and corn beef, so I know what I’m talking about.

Here’s a standard dish to start off a large celebration like St Joseph’s: tortilla soup.

You’ll need:

For soup:

• Olive oil
• Medium brown onion chopped
• Tomato paste
• Chili powder
• Chicken broth
• Cilantro (2-3 stems)
• Boneless chicken breasts
• Black beans
• Fresh or frozen corn

Chop onion and saute in two tablespoons of hot olive oil until soft in the soup pot. Add tablespoon of tomato paste and one tablespoon of chili powder and saute a few minutes more. Add one quart of chicken broth and cilantro stems (2-3), bring to a boil stirring often. Cube the two chicken breasts, add chicken to the soup, and cook for about 5 minutes until chicken is done. Soup should come back to a boil. Add one can of rinsed beans and one cup of corn. Stir. Bring back to a boil then reduce to a simmer. You should be able to prepare this soup in the time it takes to drink one Spaten Optimator at a gentlemanly pace. You’re ready to serve the soup.

For garnishes:

• Queso fresco (can substitute crumbled feta)
• Chopped tomato
• Chopped cilantro
• Diced avocado
• Crushed tortilla chips
• Limes

Serve each garnish in a ramequin or small bowl.

Serve the soup in a generous bowl since you’ll be adding the fresh garnishes to the soup at the table.

Happy feast.

(via Maria Young)

Nachos

I cringe when a plate of nachos arrives at the table piled high to the sky with ground beef, olives (black and green), scallions (some of them decorative), salsa, sour cream (mounds of sour cream), all constructed, like a Jesuit church in late 16th century Rome, on a bed and foundation of the fountain and source of the eponymous dish itself: the chip, the nacho. It is a blasphemy. Most “nachos” sold in the bag are like comparing wonder bread to a baguette. Why start there? There is a simple way, beginning with the real thing, a deep fried corn tortilla, to make a wonderful treat.

You will need:

• Corn tortillas
• Oil
• Sturdy pan
• Deep bowl
• Paper towels
• Tongs
• Salt
• Refried beans
• Sharp cheddar cheese
• Jalapeno pepper slices, pickled

Take a bag of plain corn tortillas. Cut them into quarter sections, like a pizza. Take the pan, add some oil into the pan. Enough so that you can deep fry the tortilla wedges. Bring the oil to 400 degrees fahrenheit. Fry the tortilla wedges a few at a time in the hot oil. Don’t let the wedges overlap. You’ll want some tongs to turn the wedges over to cook the other side. Remove them from the oil onto paper towels to soak up excess oil. Then put the wedges into a deep bowl and add salt to taste. I prefer larger crystal salt for better flavor. Toss the nachos (=fried wedges) and the salt.

Heat the refried beans either on the stove or in the microwave oven. The beans are ready when they are the consistency of loose, well, paste. Taking a broad butter knife, spread refried beans, like butter, over one side of each nacho. Place the nacho individually onto a cookie sheet. When all the nachos have been spread with refried beans and placed onto a cook sheet, slice a thin piece of cheddar cheese and cover each nacho with the cheese. On top of each piece of cheese, place a single jalapeno slice.

Set your oven to a low broil. When the oven is fully heated, place the cookie sheets with the nachos into the oven until the cheese is just melted. Be careful not to over cook. Pull the nachos from the oven and enjoy with a simple beverage like a Spaten Optimator.

FAQ:

1) How long should I leave the wedges in the hot oil? Answer: drop them into the oil, take a swig of beer, turn them over, take a swig of beer, pull them out.
2) Should I use cilantro? Answer: no. But you could drizzle fresh lime juice onto the finished nachos.
3) Why deep fry the nachos? Isn’t that very unhealthy? Answer: no it is not. Why? Because we are deep frying at 400 degrees fahrenheit. So only the flavor of the oil gets absorbed. Trust me.
4) Should I use pre-sliced cheddar? Answer: we don’t like pre-sliced cheddar. There’s nothing like using the cheese slicer on skin already raw from the deep frying.