Profiling and websockets: going from 23s to 285ms

Thomas Hintz . 07/01/2016

Updated: 08/23/26 (added code samples and corrections)

(Based on a talk that got canceled on me at the last second. [slides])

This is the story of how I took websocket message processing from 23s to 285ms.

I was working on creating a web-app version of a desktop game I made ages ago and wanted to add game-state syncing between clients. I thought it could be a good chance to explore websockets since I hadn't done anything much with them before and thought maybe they would be a nice fit. The app happened to be written in CHICKEN Scheme and CHICKEN didn't have a websockets library. I took a quick look at the websockets spec and it didn't seem too difficult to implement so I started work on a CHICKEN websockets library.

Indeed, it proved relatively easy to implement, but I had a problem: message processing was horrifically slow. The test case I had chosen was to serially process and echo back 1,000 16MB text messages. My first version took 23s. It didn't actually matter for the web app I was working on, but who can live with such an inequity? Plus, I was going to publish it, and that would just make me look bad in front of all the people who ran the same benchmark. So I set out to change that.

(Note that this piece is not a "language shootout" or some other attempt to prove something is faster than something else. They is just observations on optimizing a somewhat arbitrarily chosen benchmark for the fun of it.)

I chose this test case to make measuring differences easy, and it seemed sending and receiving text messages would be a relatively common thing to do with websockets. There are, of course, a million other things that could be optimized. For the sake of this piece, I'll use the 16MB test. I also tracked smaller, more normal-sized messages, and the results scaled linearly, so the larger size is representative.

The first version took 23s and other implementations took between 400ms and 2.5s. Very embarrassing. My first goal was just to get it around 1s, which seemed reasonable enough for something I didn't really need in the first place. By the time I reached that point, though, I was too addicted and resolved to try to beat the other implementations or at least be one of the fastest.

I started out being lazy and instead of profiling I just took a couple guesses at what was causing the slowness. The few quick things I tried that seemed to me like they would be slow didn't actually seem to make much of a difference. I did observe, though, that the heap would balloon from 15MB to 1.5GB! After running the benchmark, it would drop back down to around 40MB. Therefore, it seemed obvious that too much garbage was being generated, but where? So I went "unlazy" and pulled out the profiler to find out.

As expected, a significant amount of the processing time was from the GC, about 50%. It was easy to discover from the profiler that the garbage was mostly coming from the messages being copied multiple times. After removing the unnecessary copying, the processing time was down to 2.5s. While that is fantastic, it was still too slow. Improving it further took more work.

The next suspicious thing in the profiler output seemed to be coming from a dependent library, or even the CHICKEN language runtime itself. At this point, I had only instrumented the websockets library itself and not any libraries it depended on or the language runtime. So the next step was to instrument everything else. The next round of profiling produced an interesting result; it appeared that there was a bottleneck in the language runtime itself.

It took a fair amount of effort to track down, but it turned out the method used for copying the return message to the output stream was copying it one character at a time. After patching the CHICKEN runtime to copy the whole message at once, the processing time was reduced from 2.5s to 1s.

;; original core of write-u8vector
;; loops over entire vector copying one char/byte at a time
(do ((i from (fx+ i 1)))
    ((fx>= i to))
  (##sys#write-char-0
  (integer->char (##core#inline "C_u_i_u8vector_ref" v i))
  port))

;; patched write-u8vector
;; copies the entire chunk of data in one call
(let ((len (##core#inline "C_u_i_8vector_length" v)))
  (check-range from 0 (fx+ (or to len) 1) 'write-u8vector)
  (when to (check-range to from (fx+ len 1) 'write-u8vector))
  ; using (write-string) since the "data" slot of a u8vector is
  ; represented the same as a string
  ((##sys#slot (##sys#slot port 2) 3) ; write-string
   port
   (if (and (fx= from 0) (or (not to) (fx= to len)))
     (##sys#slot v 1)
     (##sys#slot (subu8vector v from (or to len)) 1)))))

(The officially accepted patch included new tests validating the improved performance, shown below:)

16MB test case, new:
0.06s CPU time, 0.04s GC time (major), 25/2 mutations (total/tracked),
3/4 GCs (major/minor)

old (4.9.0.1):
0.63s CPU time, 0.01s GC time (major), 25 mutations, 3/4886 GCs
(major/minor)

The next bottleneck I identified and attacked was in the unmasking algorithm. Unmasking is required in the websockets spec. It is a pseudo-security mechanism that requires xor-ing the entire message.

One of my favorite features of CHICKEN is that it allows directly embedding C code. When you really want to squeeze out some extra performance, it is quite nice. Optimizing the Scheme code itself didn't improve it much, so I naturally turned to C. That allowed me to use some low-level trickery that brought the processing time from 1s down to 700ms.

;; CHICKEN Scheme foreign function call signature
;; This (and the next snippet) just get embedded right in the Scheme source
((foreign-lambda* void ((blob wsmaskkey) (size_t wslen) (scheme-pointer wsv)) ... ))

// variable names match the websockets documentation
const unsigned char* maskkey2 = wsmaskkey;
const unsigned int kd = *(unsigned int*)maskkey2;
const unsigned char* __restrict kb = maskkey2;
//
// unmask in chunks
size_t i;
for (i = wslen >> 2; i != 0; --i)
  {
    *((unsigned int*)wsv) ^= kd;
    wsv += 4;
  }
//
// unmask anything remaining
const size_t rem = wslen & 3;
for (i = 0; i < rem; ++i)
  {
    *((unsigned int*)wsv++) ^= kb[i];
  }

The next bottleneck was in UTF-8 validation. The websockets standard requires text messages to be UTF-8 validated. My original version used a parser combinator for validation, but it wasn't a speed demon. I searched the internets for a faster way to validate UTF-8. I found a number of implementations, both general and specific to existing websockets libraries. The most common one, which happened to have a compatible open-source license, was used by a number of implementations and was significantly faster than the parser combinator solution I was currently using in my implementation. But while testing it, I discovered it didn't actually validate correctly! Some of the inputs it claimed were valid were clearly not valid. I would have none of that!

I decided to go back to the correctly validating parser combinator implementation and attempt to improve that instead. I was able to make some simple performance improvements without too much difficulty, and that brought down processing time from 700ms to 400ms.

;; for example, changing this rule in the UTF-8 "1" test from:
(in (ucs-range->char-set/inclusive #x00 #x7F))
;; to:
(satisfies (lambda (c) (or (< (char->integer c) 128)
                           (and (> (char->integer c) 128)
                                (< (char->integer c) 191)))))

So now I had reached roughly the same performance as the faster implementations, but I couldn't help trying to do even better. I still kept thinking there must be a faster way to do the UTF-8 validation.

I played around with things a bit and then realized: if you only wanted to validate if a message was plain ASCII, it could be done very quickly and efficiently. This is because with a plain ASCII message, you only have to check that each value is less than 128.

So I modified the UTF-8 validation function to take advantage of this. The new algorithm would attempt to validate the message as a plain ASCII message, and if it came across a non-ASCII character, it would bail out, dropping back to the parser combinator implementation. This provided speed in the common case while retaining complete accuracy for all other cases.

With that part written in C, it was practically free and generated no garbage. This brought the test case from 400ms down to 285ms! Sure, it is cheating a bit, but if you're lucky enough to have all plain ASCII messages, then you will have even faster message processing. And, still, the worst-case performance is roughly on par with the faster implementations. So, yay, it isn't the slowest anymore!

// loop over each char and test if it is < 127 (simple ASCII)
// if it isn't, we bail and fallback to the slower
// parser-combinator UTF-8 validator
int i;
for (i = ws_utlen; i != 0; --i)
  {
    if (*((unsigned char*)ws_uts++) > 127)
      {
        C_return(0);
      }
  }
C_return(1);

Moral of the story: "don't be lazy" and start with profiling. Without that, it would be much more difficult to figure out where the bottlenecks were and to know what bottlenecks were the most significant and should be attacked first.

And lastly, feel free to cheat when you can.

Some notes

It is likely that other implementations are slower than they could be because they have extra features or have slower message processing to increase parallel processing, for instance.

I didn't test every implementation. I just grabbed some of the more popular ones.

The benchmarks are older now, around a year and it is entirely possible that implementations have gotten faster since then.

There are still a fair number of areas I've identified for improvement, but it's good enough for now.

In the final version, image size settled around 40MB.

One of my initial thoughts was to switch some things from being purely functional to being imperative since in your head you think that generating garbage is going to have worse performance. Turns out it actually slowed things down in one case. Upon further investigation, it turns out the CHICKEN compiler is better able to optimize some cases when you don't modify state and in this case it actually even generated less garbage with the functional version. Other compilers are known to do the same in certain situations. So don't guess. Test and profile.