Topfew Fun

This was a long weekend in Canada; since I’m unemployed and have no workaday cares, I should have plenty of time to do family stuff. And I did. But I also got interested in a small programming problem and, over the course of the weekend, built a tiny tool called topfew. It does a thing you can already do, only faster, which is what I wanted. But I remain puzzled.

[To those who are interested in Amazon or politics or photography, feel free to skip this. I’ll come back to those things.]

What it does · Back in 2016 I tweeted Hello "sort | uniq -c | sort -rn | head" my old friend, and got a few smiles. If you feed that incantation a large number of lines of text it produces a short list showing which among them appear most often, and how many times each of those appears.

It’s a beautiful expression of the old Unix craft of building simple tools that you can combine to produce surprising and useful results. But when the data gets big, it can also be damn slow. I have a little script on the ongoing Web server that uses this technique to tell me which of my pieces are most popular, and how many times each of those was read.

In the last couple of weeks, my logfiles have gotten really big, and so my script has gotten really slow. As in, it takes the best part of a minute to run and, while it’s running, it sucks the life out that poor little machine.

It turns out to be a pretty common problem. Anyone who’s operating an online service finds themselves processing logfiles to diagnose problems or weirdness, and you regularly need to answer questions like “who are the top requestors?” and “what are the most common API calls?”

What it is · Topfew is a simple-minded little Go program, less than 500 lines of code and almost half of that tests. If you have an Apache server log named access_log, and you wanted to find out what the top twelve IP addresses were hitting your server hardest, you could say:

awk '{print $1}' access_log | sort | uniq -c | sort -rn | head -12

With topfew, you’d say:

tf -fields 1 -few 12 access_log (“tf” is short for “topfew”.)

The two would produce almost the same output, except for topfew would be faster. How much faster? Well, that’s complicated (see below)… but really quite a bit.

I don’t think there’s anything terribly clever about it; My bet is that if you asked a dozen senior developers to write this, they’d all end up with nearly identical approaches, and they’d all be pretty fast. Anyhow, as the links here make obvious, it’s on GitHub. If anyone out there needs such a thing and hasn’t written their own in a weekend project, feel free to use and improve.

Since I haven’t done a Go project from scratch in a long time, I’m not only out of practice but out of touch with current best practices, so it’s probably egregiously unidiomatic in lots of ways. Oh well.

How fast? · Well, that’s interesting. I ran a few tests on my Mac and it was many many times faster than the sort/uniq incantation, so I smiled. I thought “Let’s try bigger data!” and built a Linux version (saying GOOS=linux go build still feels like living in the future to me), hopped over to my Web server, and ran exactly those queries from the last section on a recent Apache logfile (8,699,657 lines, 2.18G). Topfew was faster, but not many times faster like on my Mac. So I ran it on the Mac too. Here’s a summary of the results. All the times are in seconds.

	cp time	sort/uniq time	topfew time	speedup net of I/O
Linux	17.29	37.66	26.75	2.15x
Mac	1.40	137.46	8.81	18.36x

The first column (“cp time”) is the number of seconds it takes to copy the big file from one directory to another. The last column is produced by subtracting the “cp” time from each of the other two, leaving something like the amount of extra latency introduced by the computing in excess of the time spent just copying data, then comparing the results.

Anyhow, those are some puzzling numbers. Stray thoughts and observations that I’m not going to dignify with the term “hypotheses”:

1. The Mac has a damn fast SSD.

2. The Linux box’s disk is sluggish.

3. Perhaps the basic tools like sort and uniq are surprisingly fast on Linux or the Go runtime is surprisingly slow. Or, you know, the mirror image of that statement.

4. The sort/uniq incantation is inherently parallel while topfew is 100% single-threaded. Maybe the Mac is dumb about scheduling processes in a shell pipeline across its eight cores?

Giggling · I broke out the Go profiler (Go is batteries-included in ways that other popular languages just aren’t) and ran that command against the Apache logfile again. I was poking around the output and Lauren said “I hope you’re laughing at the computer, not at me talking to the cat.”

The profiler claimed that 73% of the time was spent in syscall.syscall reading the input data, and the first trace of actual application code was 2.27% of the time being spent in the regexp library doing field splitting (on \s+).

The core code that actually accumulates counts for keys was consuming 1.54% of the elapsed time, and 93% of that was updating the total in a map[string]uint64.

Next steps? · I’m probably curious enough to poke around a little more. And maybe someone reading this will kindly explain to me in words of one syllable what’s going on here. But anyhow, the tool is useful enough as it is to save me a noticeable amount of time.

---

---

Contributions