First, I ran into a neat little issue on FreshBooks’ production servers last week involving the table cache and an O(n) algorithm for selecting a table to close. I wrote up a little explanation over on the FreshBooks blog that you might find interesting if you find any of this interesting. The short version is that if you’re going to be running with a full table cache and still opening tables regularly, you’ll be better off with a much smaller table cache, because finding the least-recently-used table to close is big-O of the size of the table cache. Smaller table cache = fewer tables to determine the LRU.

And then last night, out of the blue, a web forum about tinwhistles that I host hit a wall. About 8:30, my mostly-idle Linode went heavily IO-bound — as in one of the four CPUs spinning in diskwait all the time. What had originally been complex but fast (and common) queries were suddenly taking minutes and minutes to run: things like “get a list of topics in a forum”, and especially “get a list of posts for a forum’s RSS feed”.

There’s a lot of EXPLAIN output here, so I’d better put this behind a cut.

I took a look at the RSS feed query, which seemed the worst not only because it took a long time — 600+ seconds — but because it read-locked every important table in the database. Here’s the query, a big inner join:

SELECT t.topic_title, t.topic_last_post_id, t.forum_id,
    f.forum_name, p.post_time, pt.post_text, pt.bbcode_uid,
    u.username, u.user_id
FROM phpbb_topics t, phpbb_posts p, phpbb_posts_text pt,
    phpbb_users u, phpbb_forums f
WHERE t.topic_status != 1
  AND p.post_id = t.topic_last_post_id
  AND pt.post_id = p.post_id
  AND u.user_id = p.poster_id
  AND t.forum_id = f.forum_id
ORDER BY t.topic_last_post_id DESC
LIMIT 0, 15;

Here’s the mk-visual-explain output. I’ve replaced the table aliases with readable things:

Filesort
+- TEMPORARY
   table          temporary(forums,topics,posttext,posts,users)
   +- JOIN
      +- Bookmark lookup
      |  +- Table
      |  |  table          users
      |  |  possible_keys  PRIMARY
      |  +- Unique index lookup
      |     key            users->PRIMARY
      |     possible_keys  PRIMARY
      |     key_len        3
      |     ref            chiffbb.posts.poster_id
      |     rows           1
      +- JOIN
         +- Bookmark lookup
         |  +- Table
         |  |  table          posts
         |  |  possible_keys  PRIMARY,poster_id
         |  +- Unique index lookup
         |     key            posts->PRIMARY
         |     possible_keys  PRIMARY,poster_id
         |     key_len        3
         |     ref            chiffbb.topics.topic_last_post_id
         |     rows           1
         +- JOIN
            +- Bookmark lookup
            |  +- Table
            |  |  table          posttext
            |  |  possible_keys  PRIMARY
            |  +- Unique index lookup
            |     key            posttext->PRIMARY
            |     possible_keys  PRIMARY
            |     key_len        3
            |     ref            chiffbb.topics.topic_last_post_id
            |     rows           1
            +- JOIN
               +- Filter with WHERE
               |  +- Bookmark lookup
               |     +- Table
               |     |  table          topics
               |     |  possible_keys  forum_id,topic_status,topic_last_post_id
               |     +- Index lookup
               |        key            topics->forum_id
               |        possible_keys  forum_id,topic_status,topic_last_post_id
               |        key_len        2
               |        ref            chiffbb.forums.forum_id
               |        rows           2579
               +- Table scan
                  rows           23
                  +- Table
                     table          forums
                     possible_keys  PRIMARY

See that temporary table at the top that gets used in a filesort? Well…

The whole thing was multiple joins which were then ORDERed and LIMITed. So that meant that it had to find all posts to the forum, ever, and shove them in a temporary table, sort that, and take the 15 most recent posts.

“All posts to the forum, ever” is about 500MB of data. That made the temporary table big enough to go to disk. So every time this query ran and couldn’t be answered from the query cache, it had to write that 500MB file. And the cached query was invalidated whenever someone posted to the forum, which is pretty often.

The problem in this case wasn’t (entirely) the SQL. MySQL was optimizing the query poorly because the key distribution statistics were off. An ANALYZE TABLE on the affected tables fixed that, and gave us:

JOIN
+- Bookmark lookup
|  +- Table
|  |  table          forums
|  |  possible_keys  PRIMARY
|  +- Unique index lookup
|     key            forum->PRIMARY
|     possible_keys  PRIMARY
|     key_len        2
|     ref            chiffbb.topics.forum_id
|     rows           1
+- JOIN
   +- Bookmark lookup
   |  +- Table
   |  |  table          users
   |  |  possible_keys  PRIMARY
   |  +- Unique index lookup
   |     key            users->PRIMARY
   |     possible_keys  PRIMARY
   |     key_len        3
   |     ref            chiffbb.posts.poster_id
   |     rows           1
   +- JOIN
      +- Bookmark lookup
      |  +- Table
      |  |  table          posttext
      |  |  possible_keys  PRIMARY
      |  +- Unique index lookup
      |     key            posttext->PRIMARY
      |     possible_keys  PRIMARY
      |     key_len        3
      |     ref            chiffbb.posttext.post_id
      |     rows           1
      +- JOIN
         +- Bookmark lookup
         |  +- Table
         |  |  table          posts
         |  |  possible_keys  PRIMARY,poster_id
         |  +- Unique index lookup
         |     key            posts->PRIMARY
         |     possible_keys  PRIMARY,poster_id
         |     key_len        3
         |     ref            chiffbb.topics.topic_last_post_id
         |     rows           1
         +- Filesort
            +- Filter with WHERE
               +- Bookmark lookup
                  +- Table
                  |  table          topics
                  |  possible_keys  forum_id,topic_status,topic_last_post_id
                  +- Index range scan
                     key            topics->topic_status
                     possible_keys  forum_id,topic_status,topic_last_post_id
                     key_len        1
                     rows           57912

There’s still a filesort, but it’s now a filesort of a single 57k-row table that’s already been filtered. That table is about 5MB, and fits in tmp_table_size, so doesn’t go to disk. The joins all stack, and the ORDER BY just follows that one-table filesort. The query takes about 0.15s now, or about 4000x as fast.

Incidentally, it can still be improved: that “filter with WHERE” is because of the “WHERE t.topic_status != 1” in the query, and that means “where the topic is not locked”. The idea was that locked topics aren’t going to appear in the last-15-posts anyhow, so may as well exclude them. But if they’re not going to appear because of the sorting, and since you’re sorting anyhow, unless there are a LOT of locked posts that doesn’t matter. Taking out that restriction gets us:

JOIN
+- Bookmark lookup
|  +- Table
|  |  table          users
|  |  possible_keys  PRIMARY
|  +- Unique index lookup
|     key            users->PRIMARY
|     possible_keys  PRIMARY
|     key_len        3
|     ref            chiffbb.posts.poster_id
|     rows           1
+- JOIN
   +- Bookmark lookup
   |  +- Table
   |  |  table          posts
   |  |  possible_keys  PRIMARY,poster_id
   |  +- Unique index lookup
   |     key            posts->PRIMARY
   |     possible_keys  PRIMARY,poster_id
   |     key_len        3
   |     ref            chiffbb.topics.topic_last_post_id
   |     rows           1
   +- JOIN
      +- Bookmark lookup
      |  +- Table
      |  |  table          posttext
      |  |  possible_keys  PRIMARY
      |  +- Unique index lookup
      |     key            posttext->PRIMARY
      |     possible_keys  PRIMARY
      |     key_len        3
      |     ref            chiffbb.topics.topic_last_post_id
      |     rows           1
      +- JOIN
         +- Bookmark lookup
         |  +- Table
         |  |  table          forums
         |  |  possible_keys  PRIMARY
         |  +- Unique index lookup
         |     key            forums->PRIMARY
         |     possible_keys  PRIMARY
         |     key_len        2
         |     ref            chiffbb.t.forum_id
         |     rows           1
         +- Bookmark lookup
            +- Table
            |  table          topics
            |  possible_keys  forum_id,topic_last_post_id
            +- Index scan
               key            topics->topic_last_post_id
               possible_keys  forum_id,topic_last_post_id
               key_len        3
               rows           59900

And with that there isn’t even a filesort and the query finishes in <0.01 seconds, 60000x as fast as the original problem and 15x as fast as the post-ANALYZE optimization. Nice.

We moved the printer across the room, and following that it wouldn’t print; it’d just sit there at “Printing…”, and the client print progress thing would stay at 0%… until you disconnected the network cable. Then it’d print whatever you’d sent. Weirder still, the same thing would happen with internal print jobs. Print a configuration page? “Printing…” until you disconnect the network cable.

It was still under warranty, so I gave Dell a call. He walked through some obvious things, and then had me flash the firmware on the printer — oops, wait, that’s over the network. Ok, bring the printer over to my desk and… you need Windows to flash it? Ok, over to Levi’s desk, and flash it. No problem. Plug it back in; no luck.

So the Dell guy gives up, they’re just going to send us another printer. Great! But it took a while to figure out whether or not it was in stock, but while it was waiting, a page came out.

Wait, what?

And then, five minutes later, another page. Now, “takes five minutes to print a page” is a very different problem than before! But at this point the replacement printer was being dispatched and the Dell guy didn’t want to do more troubleshooting. But once I got off the phone, I did, and I’m glad.

The first thing I noticed is that the switch lights were blinking like crazy. I tracked that back through two more switches to our Samba server. Aha! Run tcpdump there, and:

14:06:13.459933 IP 192.168.1.151.137 > 192.168.1.150.137: NBT UDP PACKET(137):
REGISTRATION; REQUEST; UNICAST
14:06:13.459933 IP 192.168.1.150.137 > 192.168.1.151.137: NBT UDP PACKET(137):
REGISTRATION; NEGATIVE; RESPONSE; UNICAST
14:06:13.463931 IP 192.168.1.151.137 > 192.168.1.150.137: NBT UDP PACKET(137):
REGISTRATION; REQUEST; UNICAST
14:06:13.463931 IP 192.168.1.150.137 > 192.168.1.151.137: NBT UDP PACKET(137):
REGISTRATION; NEGATIVE; RESPONSE; UNICAST

And as you can see on the timestamps there, both ends were talking as fast as they can — the printer sending NBT registration requests, and the Samba server sending errors back, over and over, hundreds of times per second. Tell the printer to forget about its Samba server, and voila, printing’s back to normal.

So what happened? As best as I can tell, one of two things: Either moving the printer made it get a DHCP configuration for the first time in over a month, since we rolled out a new DHCP server in the meantime; or it’s been slow all along, and moving it to the same switch as the Samba server, instead of two switches away, made it marginally busier, enough for it to not print at all instead of just printing slowly.

Still, I could think of better things to have spent an afternoon on.

Checking out their machines showed that their DNS server addresses were being changed to an address on the wrong subnet, and their domain being changed to “mshome.net”. That last part’s a red flag: the thing that does that is Windows’ Internet Connection Sharing, which means someone had that enabled on an interface and we basically had a rogue DHCP server.

Rogue DHCP servers are a pain to track down because without a monitoring port on the switch, all you have to go by is broadcast traffic, and then all you get is the address the DHCP server thinks it’s at — which, we know, is on the wrong subnet anyhow — and its MAC address. And we’re a small shop but we still don’t have a handy list of MAC addresses lying around. I did know that the MAC address’s vendor ID was Dell.

So the first thing I did when I found the problem was to check the MAC addresses of all of the wired and wireless interfaces of the Dell computers in the office, and none of them matched! I puzzled over this for a while, had people double-check, and eventually something clicked and Saul remembered that Sunir had enabled ICS during their road trip.

I took a second look at Saul’s laptop, and there was the MAC address — on a disabled wireless broadband interface. Turns out that if you have ICS on, the DHCP server keeps running even when the shared network interface is down. Disable it, problem went away.

But the strange part was that Saul’s been back for a week and the problem just came up today.

I scratched my head about that for a bit and then it hit me: before today, the switch in the wiring closet was in the Linksys router that also served DHCP:

[client]----[switch + dhcp server]----[saul's PC]

After today, both Saul’s network segment and the new DHCP server were both connected to a separate switch:

[client]-----------[switch]-----------[saul's PC]

                       |

                       |

                 [dhcp server]

DHCP is designed to handle multiple (cooperating) DHCP servers on a segment; when a client sends a request, any DHCP servers can respond, and the client chooses one of the responses and informs the DHCP server that sent it that it will use that one. The usual client implementation is to accept the first response.

So before today, a client on one segment would make a DHCP request, but the legitimate DHCP server (at the switch) would be located one Ethernet segment closer to the client than the rogue DHCP server, so it would always win. As of today, the legitimate DHCP server was now the same distance from the client as the rogue one, so part of the time it’d lose, which is exactly what was happening — not every DHCP lease was broken, just the occasional one.

Sometimes it’s easy to forget that actual electrons need to move around for this stuff to work — which in turn reminded me of Trey Harris’s 500-mile email.

But a single ADSL link is a little bit fragile. If it’s down for a day, that’s a day without access to our servers at Rackspace, our tech support email, our marketing reports, everything. Everyone might as well go home save for one person to answer the phones, not that that person can do much when people call.

So in case the DSL line goes down, we’ve got a backup connection using Rogers’ WiMax^? network which they call “Portable Internet“. It’s portable in the sense of the old “portable computers”, in that the router/radio we have is a wall-powered RSU that acts as an Ethernet bridge; there’s also a PC card^? version which would provide a real mobile everywhere-in-the-city network.

Unfortunately it’s a bit slow, especially for the price: $49.95/mo gets you 1.5Mbps down and 256kbps up, or $24.95/mo for 256kbps down and 64kbps (!?) up. I’m not quite sure why it’s as slow as it is, since the real-world maximums for WiMax are in the 10Mbps range, but speed tests confirm that it’s right where they say it is.

But it works! I wanted to have some idea of how it worked before we needed to use it, so I brought the RSU home tonight, and I’m connected to it now. In the window I get five bars of signal, although five feet inside our plaster walls that’s down to one or two bars, although a weak signal seems to affect latency more than speed. And it couldn’t be much easier — plug the laptop into the RSU’s ethernet jack and it grabs a DHCP lease and it’s online.

The speed will make it a bit painful if we ever have to rely on it to get the office connected, but it’ll be a lot less painful than falling off the net completely, and a lot more straightforward than provisioning some sort of permanent redundancy to our little office. (And with a new box arriving early next week to be put to use as a Linux-based firewall and router, I think I might look into automating failover, too. Incidentally, on that subject, I’m torn between trying IPCop and just going with a straight CentOS install and managing iptables and so on by hand. Thoughts?)

I forgot that I wouldn’t have a router right away, so I ended up getting a Speedtouch 516 DSL modem configured as a bridge, so I’m using Windows’ own PPPOE client until the move.

Next up is VOIP. I’m leaning towards Unlimitel because Babytel never replied to my email sent to their support address (pilot error: sent to .com instead of .ca), but there’s still a little shopping to do there. New blog theme/approach coming soon too, although that’s just fitting in the quiet moments of which there have been few lately.

Work is going awesome. I’m moving support over to RT any day now, have a huge set of projects and to-dos to drill through, and have really been given pretty much full ownership over my areas of responsibility already. (And everyone’s so great to work with!)

Off to Dan’s tonight for pizza, beer and conversation. (We tried this last week but I made it a block before I decided it was time to take a rain check and get the car in for a brake job right away. I lucked out in that a great garage happens to be exactly one block away from me, and Frank at Master Mechanic on Dupont and Concord took it in on no notice and did good work at a good price, which was nice considering I needed a garage on short notice in a strange city.)

Movers are scheduled: pack on the 25th, load on the 28th, unload a couple of days later. Final stretch!

I seem to have slept through the period around 2004 to 2006 where USENIX nearly got rid of SAGE, and then didn’t, and then some people who wanted SAGE to be rid of USENIX formed LOPSA, and so on.

But I was all set to get a SAGE membership and now I’m not sure if I want a LOPSA membership instead, or as well, or something.

So, uh, tell me what to do.

[photo by flickr user “tracer”]

Perhaps I was onto something when I concluded that there was little to no Internet industry left in Ottawa, and that it was concentrated in Toronto.

Perhaps.

(Of course, if you have DSL advice for me and I forgot to email you, I’m accepting it here too!)

Work continues to go well. Tomorrow’s the release of a new version of FreshBooks. It’s really too early for me to be involved hands-on in a new release, but I’ll at least get to see the procedure. I also took a few photos of the office. A bit of a difference from before, eh?

Other than actual work time, I’m pretty much ready for these two “advance weeks” to end. I need to get Christmas over with so I can concentrate on the move. Things have been fine here, but I’m just ready to head home for a bit, and then to head over to new-home here. Driving has been a real pain with the big snowfall, since I still don’t entirely know my way around, roads are about half a lane narrower, and parking has been up at the air both at the apartment and at work because of snow everywhere. Once I get into the new apartment and start doing public transportation pretty much everywhere I think that’ll improve a bit.

Thursday night’s the office Christmas party, which should be fun. That forces my hand on shopping: I must pick up something silly for the gift “exchange” by tomorrow night, so I’ll brave heading downtown then. (Downtown should be easy — walk over to Yonge and Eglinton, subway down to Queen. But everything’s just a little disorienting because of the snow and the busy-ness.)

Four (maybe three!) sleeps until I see Candice again, though! Yay!

I’m in Toronto! I got here on Saturday morning with Candice. We spent the weekend seeing apartments — 6 or 8 on Saturday, and then two on Sunday, staying at the Holiday Inn on Bloor at St. George. Most of the apartments we looked at on Saturday were roughly along St. Clair around Avenue or Yonge. We found some, and nearly went for one that would have stretched our budget quite a bit — until we saw this!

So Sunday we started out a little discouraged. And then we saw The Apartment, which I’ll talk about in a second, and then another one that was just as cute but up at St. Clair and Dufferin which was deemed too far away from the subway. We went out for dinner for Candice’s birthday to Coco Lezzone in Little Italy, which was good but not spectacular. (We’d forgotten to account for the difficulty in finding good dining on Sunday night here.) And then before we went to bed Sunday night I emailed about The Apartment.

Let’s talk about The Apartment for a moment: tonight I signed our lease! We now have an apartment (well, for January 1, but I have the keys) on Delaware Avenue, just west of Ossington and just south of Dupont. It’s right near here.

It’s a cute, medium-sized 1-bedroom on the main floor of a house, with hardwood floors, glass block walls, a giant kitchen, and a freakin’ backyard. How great is that? It’s two blocks from Ossington station, and not far from the Dufferin bus that will take me straight to the door at work. The photo of the house at right is linked to a Flickr set of the apartment, as yanked from the Craigslist ad that we found it with.The only downside: street parking, but there seems to be lots of room on that block alone whenever I’m over there.

Anyhow, back to the timeline: On Monday morning, I left the hotel and drove straight to FreshBooks World Headquarters, up on Dufferin just a bit south of Lawrence. The first day was a little bit hairy — not quite sure what I was expected to do, my manager was in interviews for most of the morning, I was stumbling around OS X for the first time ever, I was thinking about missing Candice, and I hadn’t yet seen the place I would be living for the next two weeks! But even then it was fine. Day Two felt like a “first day”, though, so the hairiness is irrelevant now. Days three and four had me doing a bunch of email support (best way to learn the product!) and finding my way around a bit more, and things are coming together pretty well.

I think it’s going to be a blast there. My coworkers are smart and a lot of fun and we seem to have much in common, and everyone, employees and customers, are really excited about the software. I’ll have plenty of interesting projects once I get up to speed on the sysadmin side, and I’ll have my fingers in a bit of the dev side as well from the sounds of things.

(I should’ve taken some pictures of the office. Drat. Also, I like OS X a lot, and need to find a way to get Candice and I MacBooks.)

Let’s see, what else? Until the new year I’m staying in Mike McDerment’s place, near Eglinton and Mt. Pleasant. Easy drive in, apartment to myself, lots around it. I’m driving back to Ottawa every weekend, and am going to be there over the holiday perineum, to see Candice and help pack up the apartment. Went over to Dan‘s to have a couple beers Tuesday night, was nice to socialize a bit, but found out just before I left that there was no beer — so went around the corner from Mike’s to the Granite Brewpub, who offer growlers of their beers to go. Their Peculier was just right.

All in all things have been overwhelming and exhausting and awesome.

However, today I left my gloves at the Future Bakery (at which I had their all-day breakfast for dinner tonight, $7 for omelet, toast, home fries, fruit, and coffee). Oh, well. Can’t have everything go right, I guess!

As of December 10th I’ll be the Network Operations Manager at FreshBooks, the company I mentioned previously. They’re a little startup in Toronto whose product is a Web-based invoicing and time-tracking application, directed primarily at freelancers, creatives, and small businesses. It’s a nice, clean, well-thought-out SaaS app, with a third-party developers’ API, Basecamp integration and more. (You can sign up for a free account which will be loaded with test data if you want to take a look, which I encourage you to do!)

The interview last Monday went really well — it basically turned into a two-hour chat between me, Levi the CIO, and developers Ben and Justin. I like to think the fit seemed pretty obvious to everyone, but it definitely did to me. I’ll primarily be responsible for their application architecture, the server-and-database-side half of things that isn’t developing the program itself, but there’ll be development and customer-facing bits to it as well. I’m really looking forward to going back to a startup. They’ve got about a dozen people right now all in one loft-style office, which is even smaller than e-smith was when I joined them.

And yes, Toronto — which means we’ll be moving in the new year. I’m going to be living out of the CEO’s unused apartment for December, and then hopefully we’ll have found an apartment up there for Jan 1, at which point I’ll be living there with minimal furniture until Candice joins me at the beginning of February. It’ll be a crazy couple of months, but we’re pretty excited — no, really excited — about how it’ll all turn out!

But it was an even bigger surprise to see what they’re looking for — outside of a couple of “I could learn that really fast” bits, it’s practically a description of exactly what I found myself specializing in at e-smith and Mitel. (The only thing that would make it completely uncanny is if it involved email and spam too, but you can’t have everything.)

“Unfortunately”, they’ve also put a $1000 referral bounty on it as of last Friday, so I suspect it just got a lot more competitive. But we’ll see what happens! I was half-tempted to put “Sysadmin sale! Save $1000” in the subject of the cover letter email, but it’s possible to be a bit too lighthearted, even when dealing with these guys.

I’m starting to think that trip last month was a good idea.