Performance Measurement

notes.md

Notes on Performance Measurement

• Measurement of interest: The response time of the 99%ile under normal load (which tends to be a relatively low load for the time being)

• Difference in terminology:

  • Me

    ------------------ RESPONSE TIME ---------------------------------
    --------- LATENCY ---------------------
    
    | Waiting to be served                | Being served             |
    

  • People in the performance community

    ------------------------------------ LATENCY ---------------------
    
    | Waiting to be served                | Being served             |
    

• Tools:

  • https://github.com/mcollina/autocannon
    • Load generator
      • Issues a bunch of HTTP requests
    • Measures response time & throughput
    • What’s happening?
    • The information I present to other people
  • https://github.com/davidmarkclements/0x
    • Profiler
      • Samples the call stack periodically
    • Measures where the application is spending time
    • Why is something happening?
    • The information I use to improve the application
    • A convenience on top of Node.js’s --prof that draws Flame Graphs

• Coordinated omission

  • It’s a defect in the model used to simulate the real-world use of the application
  • Difference in terminology:
    • Me: Serial / Parallel
    • People in the community: Closed loop / Open loop
  • The load generator must not adapt to what’s happening
    • In particular, it must not send fewer requests because the server is slow to respond
  • It’s an issue when measuring response time & throughput, but it isn’t a big issue when profiling the application.
    • Except if you’re trying to understand the application’s behavior under stress.
  • Measure response time & throughput under normal conditions because that’s what’s more common, not under heavy load because that’s when you’d be scaling up anyway.

• Other tools

  • Suffer from coordinated omission

    • ApacheBench
      • Comes with macOS
      • ab -t 30 -n 50000 -c 1000 "https://try.courselore.org/"
    • https://github.com/wg/wrk

  • https://github.com/giltene/wrk2: First to identify and fix coordinated omission

  • https://github.com/tsenart/vegeta: Similar to autocannon in scope, but in Go.

  • https://github.com/alexfernandez/loadtest: Another Node.js tool in the same space

  • https://k6.io

    • In Go.
    • Much bigger in scope.
    • Useful for whole workflows in the application (virtual users, transactional) & continued measurements (think unit tests but for performance)

  • https://www.artillery.io/

    • Much bigger in scope.
    • Useful for whole workflows in the application (virtual users, transactional) & continued measurements (think unit tests but for performance)

  • Linux’s perf, and macOS’s DTrace:

    • Lower level, more difficult to setup, may not give the best insight for JavaScript

• TIP: autocannon: Use --latency with if there are millions of requests.

• Preliminary results:

  • Caddy is about double the speed of Express.
  • The overhead of instrumenting with 0x isn’t significant.

Measurements

CADDY

$ npx autocannon http://127.0.0.1:4001
Running 10s test @ http://127.0.0.1:4001
10 connections


┌─────────┬──────┬──────┬───────┬──────┬─────────┬─────────┬───────┐
│ Stat    │ 2.5% │ 50%  │ 97.5% │ 99%  │ Avg     │ Stdev   │ Max   │
├─────────┼──────┼──────┼───────┼──────┼─────────┼─────────┼───────┤
│ Latency │ 0 ms │ 0 ms │ 0 ms  │ 0 ms │ 0.01 ms │ 0.19 ms │ 19 ms │
└─────────┴──────┴──────┴───────┴──────┴─────────┴─────────┴───────┘
┌───────────┬─────────┬─────────┬─────────┬─────────┬──────────┬─────────┬─────────┐
│ Stat      │ 1%      │ 2.5%    │ 50%     │ 97.5%   │ Avg      │ Stdev   │ Min     │
├───────────┼─────────┼─────────┼─────────┼─────────┼──────────┼─────────┼─────────┤
│ Req/Sec   │ 45055   │ 45055   │ 46655   │ 50431   │ 47326.55 │ 1620.49 │ 45039   │
├───────────┼─────────┼─────────┼─────────┼─────────┼──────────┼─────────┼─────────┤
│ Bytes/Sec │ 10.3 MB │ 10.3 MB │ 10.6 MB │ 11.5 MB │ 10.8 MB  │ 369 kB  │ 10.3 MB │
└───────────┴─────────┴─────────┴─────────┴─────────┴──────────┴─────────┴─────────┘

Req/Bytes counts sampled once per second.
# of samples: 11

521k requests in 11.01s, 119 MB read


———

EXPRESS

$ npx autocannon http://127.0.0.1:4002
Running 10s test @ http://127.0.0.1:4002
10 connections


┌─────────┬──────┬──────┬───────┬──────┬─────────┬─────────┬───────┐
│ Stat    │ 2.5% │ 50%  │ 97.5% │ 99%  │ Avg     │ Stdev   │ Max   │
├─────────┼──────┼──────┼───────┼──────┼─────────┼─────────┼───────┤
│ Latency │ 0 ms │ 0 ms │ 1 ms  │ 1 ms │ 0.04 ms │ 0.24 ms │ 18 ms │
└─────────┴──────┴──────┴───────┴──────┴─────────┴─────────┴───────┘
┌───────────┬─────────┬─────────┬─────────┬─────────┬─────────┬────────┬─────────┐
│ Stat      │ 1%      │ 2.5%    │ 50%     │ 97.5%   │ Avg     │ Stdev  │ Min     │
├───────────┼─────────┼─────────┼─────────┼─────────┼─────────┼────────┼─────────┤
│ Req/Sec   │ 16591   │ 16591   │ 20815   │ 21039   │ 19925.1 │ 1409.7 │ 16576   │
├───────────┼─────────┼─────────┼─────────┼─────────┼─────────┼────────┼─────────┤
│ Bytes/Sec │ 3.95 MB │ 3.95 MB │ 4.95 MB │ 5.01 MB │ 4.74 MB │ 336 kB │ 3.95 MB │
└───────────┴─────────┴─────────┴─────────┴─────────┴─────────┴────────┴─────────┘

Req/Bytes counts sampled once per second.
# of samples: 11

219k requests in 11.01s, 52.2 MB read


————

EXPRESS + 0x

$ npx autocannon http://127.0.0.1:4002
Running 10s test @ http://127.0.0.1:4002
10 connections


┌─────────┬──────┬──────┬───────┬──────┬─────────┬─────────┬───────┐
│ Stat    │ 2.5% │ 50%  │ 97.5% │ 99%  │ Avg     │ Stdev   │ Max   │
├─────────┼──────┼──────┼───────┼──────┼─────────┼─────────┼───────┤
│ Latency │ 0 ms │ 0 ms │ 1 ms  │ 1 ms │ 0.04 ms │ 0.29 ms │ 18 ms │
└─────────┴──────┴──────┴───────┴──────┴─────────┴─────────┴───────┘
┌───────────┬─────────┬─────────┬─────────┬─────────┬─────────┬─────────┬─────────┐
│ Stat      │ 1%      │ 2.5%    │ 50%     │ 97.5%   │ Avg     │ Stdev   │ Min     │
├───────────┼─────────┼─────────┼─────────┼─────────┼─────────┼─────────┼─────────┤
│ Req/Sec   │ 14439   │ 14439   │ 20319   │ 20447   │ 19730.8 │ 1766.65 │ 14435   │
├───────────┼─────────┼─────────┼─────────┼─────────┼─────────┼─────────┼─────────┤
│ Bytes/Sec │ 3.44 MB │ 3.44 MB │ 4.84 MB │ 4.87 MB │ 4.7 MB  │ 421 kB  │ 3.44 MB │
└───────────┴─────────┴─────────┴─────────┴─────────┴─────────┴─────────┴─────────┘

Req/Bytes counts sampled once per second.
# of samples: 10

197k requests in 10s, 47 MB read

Measurement Techniques

• Tracing:

  • Knowing step-by-step the paths taken in the code during runtime
  • Super precise
  • Only practical for short periods
  • Interferes with the subject of the measurement too much

• Logging:

  • A sort of refined tracing which only includes the most relevant events.

• Profiling:

  • Periodically sampling the stack.
  • Less precise
  • Practical for longer periods
  • Minimal impact on the subject of the measurement

• In reality, people use some of these terms interchangeably.

Concurrency & etc.

• Concurrency: Competing for resources, for example, CPU

• Parallel: Happening at the same time

• Note that all parallel programs are concurrent, but not all concurrent programs are parallel—they could be sharing slices of CPU time.

• Green Threads:

  • Threads managed by the virtual machine or interpreter.
  • Same CPU
  • Shared memory
  • May not exist in Node.js (it isn’t clear if Node.js’s worker threads are green threads or regular threads), but exists in Go, Lua, and so forth.

• Threads:

  • May run in different CPUs
  • Shared memory
  • Backed by the operating system
  • Relatively more expensive to create
  • I suppose Node.js’s worker threads are regular threads
    • Recommended for CPU-intensive tasks
    • This means await may make sense for CPU-intensive tasks

• Processes:

  • May run in different CPUs
  • Different memories
  • Backed by the operating system
  • Even more expensive to create, and in terms of memory