A Brief Aside on Request Queueing

A Brief Aside on Request Queueing

03e04db3b6880c3a2f8114649312f733?s=128

John Pignata

March 13, 2013
Tweet

Transcript

  1. QUEUEING @jpignata br f REQUEST

  2. None
  3. None
  4. nginx thin load balancer

  5. nginx thin load balancer X-Request-Start: 1362955863565

  6. now = Time.now x_request_start = request.headers["HTTP_X_REQUEST_START"] queue_start = Time.at(x_request_start.to_i /

    1000) queue_time = now - queue_start
  7. nginx thin load balancer New Relic

  8. New Relic Agent ActionController::Base#process_action Rails New Relic

  9. Response Time t h e a m o u n

    t o f t i m e required to process a single request
  10. THROUGHPUT the amount of requests that can be processed within

    a unit of time
  11. ARRIVAL RATE the amount of requests that are enqueued for

    processing in a unit of time
  12. Latency the time delay prior to processing a request

  13. CONCURRENCY how many requests can be processed simultaneously

  14. require "socket" server = TCPServer.new(3000) loop do client = server.accept

    sleep 1 client.puts Time.now client.close end
  15. jp@oeuf:~$ ./tcpping.rb 1 Throughput: 0.9974 req/sec Average: 1.0023 secs Max:

    1.0023 secs Min: 1.0023 secs Total: 1.0026 secs
  16. jp@oeuf:~$ ./tcpping.rb 2 Throughput: 0.9983 req/sec Average: 1.5024 secs Max:

    2.003 secs Min: 1.0019 secs Total: 2.0033 secs
  17. jp@oeuf:~$ ./tcpping.rb 4 Throughput: 0.9982 req/sec Average: 2.5037 secs Max:

    4.0051 secs Min: 1.0025 secs Total: 4.0071 secs
  18. jp@oeuf:~$ ./tcpping.rb 25 Throughput: 0.9985 req/sec Average: 13.0168 secs Max:

    25.0288 secs Min: 1.0014 secs Total: 25.0364 secs
  19. require "java" require "socket" import "java.util.concurrent.Executors" pool = Executors.new_fixed_thread_pool(2) server

    = TCPServer.new(3000) loop do if pool.active_count < pool.maximum_pool_size client = server.accept pool.execute do sleep 1 client.puts Time.now client.close end end end
  20. jp@oeuf:~$ ./tcpping.rb 1 Throughput: 0.9881 req/sec Average: 1.0116 secs Max:

    1.0116 secs Min: 1.0116 secs Total: 1.0119 secs
  21. jp@oeuf:~$ ./tcpping.rb 2 Throughput: 1.972 req/sec Average: 1.0133 secs Max:

    1.0138 secs Min: 1.0129 secs Total: 1.014 secs
  22. jp@oeuf:~$ ./tcpping.rb 4 Throughput: 1.9858 req/sec Average: 1.5077 secs Max:

    2.0119 secs Min: 1.0042 secs Total: 2.0142 secs
  23. jp@oeuf:~$ ./tcpping.rb 25 Throughput: 1.9157 req/sec Average: 6.7896 secs Max:

    13.0433 secs Min: 1.0059 secs Total: 13.0499 secs
  24. require "java" require "socket" import "java.util.concurrent.Executors" size = ARGV[0].to_i pool

    = Executors.new_fixed_thread_pool(size) server = TCPServer.new(3000) loop do if pool.active_count < pool.maximum_pool_size client = server.accept pool.execute do sleep 1 client.puts Time.now client.close end end end
  25. jp@oeuf:~$ jruby ./thread_pool_server.rb 25

  26. jp@oeuf:~$ ./tcpping.rb 25 Throughput: 24.1932 req/sec Average: 1.023 secs Max:

    1.028 secs Min: 1.0191 secs Total: 1.0332 secs
  27. jp@oeuf:~$ ./tcpping.rb 50 Throughput: 24.6 req/sec Average: 1.5127 secs Max:

    2.0238 secs Min: 1.0056 secs Total: 2.0324 secs
  28. jp@oeuf:~$ ./tcpping.rb 100 Throughput: 24.7026 req/sec Average: 2.5089 secs Max:

    4.0256 secs Min: 1.0031 secs Total: 4.048 secs
  29. listen() Backlog

  30. socket() bind() listen() accept()

  31. int listen(int sockfd, int backlog)

  32. require "socket" server = TCPServer.new(3000) server.listen(1024) loop do client =

    server.accept sleep 1 client.puts Time.now client.close end
  33. Client Server SYN J connect called create entry on listen

    queue SYN K, ACK J+1 connect returns; client considers socket open ACK K+1 connection acceptable by server process
  34. incoming connections are enqueued and passed to accept() one at

    a time, first in, first out
  35. different application servers call accept() with different frequencies

  36. Unicorn workers each call accept() on the q u e

    u e a n d w o r k connections directly from it
  37. P u m a w i l l c a

    l l accept() and pass connections to its worker thread pool
  38. Thin, via EventMachine, will call accept() 10 times per reactor

    tick and place connections into a separate queue
  39. these backlogs could represent the majority of your request queue

    time
  40. this is generally invisible to your application as it is

    happening underneath it i n t h e k e r n e l o r application server
  41. CONCURRENCY

  42. nginx thin load balancer

  43. assuming Rack::Lock middleware; i.e., Rails’ config.threadsafe! commented out.

  44. elapsed wall clock time: 400ms thin 50ms 50ms 50ms 50ms

    50ms 50ms 50ms 50ms Request Queue Response Time + Latency 50ms 100ms 150ms 200ms 250ms 300ms 350ms 400ms
  45. elapsed wall clock time: 100MS unicorn worker 50ms 50ms 50ms

    50ms 50ms 50ms 50ms 50ms Request Queue Response Time + Latency 50ms 50ms 50ms 50ms 100ms 100ms 100ms 100ms unicorn worker unicorn worker unicorn worker
  46. RESPONSE TIME VARIANCE

  47. Rails 50ms 130ms 20ms 9.5secs 340ms 9ms 2.3secs 693ms Request

    Queue
  48. Rails 50ms 130ms 20ms 9.5secs 340ms 9ms 2.3secs 693ms Request

    Queue Response Time + Latency 50ms 180ms 200ms 9.7secs 10secs 10secs 12.3secs 13secs
  49. load balancer algorithms

  50. leastconns or bybusyness

  51. def balance(connection) instance = instances.sort_by(&:connection_count).first begin instance.connection_count += 1 instance.process(connection)

    ensure instance.connection_count -= 1 end end
  52. round-robin or least recently used

  53. def balance(connection) @processed ||= 0 instance = instances[@processed % instances.count]

    instance.process(connection) ensure @processed += 1 end
  54. Random

  55. def balance(connection) instances.sample.process(connection) end

  56. your queue distribution and worker utilization will be in large

    part dictated by the dealing strategy
  57. n o a l g o r i t h

    m w i l l compensate for an unstable distribution in response time
  58. leastconns doesn’t know that all connections aren’t equal

  59. the least recently used worker might be still processing a

    long-running request
  60. Client latency

  61. unicorn load balancer

  62. unicorn load balancer lol, edge network

  63. slow clients could cause a worker to spend time shoveling

    bytes over the wire
  64. work through a buffering intermediary to allow the worker to

    immediately flush the response and move on
  65. TODO

  66. 1. Measure from the outside in

  67. jp@oeuf:~$ ping -c 5 www.stanford.edu PING www-v6.stanford.edu (171.67.215.200): 56 data

    bytes 64 bytes from 171.67.215.200: icmp_seq=0 ttl=252 time=91.151 ms 64 bytes from 171.67.215.200: icmp_seq=1 ttl=252 time=96.684 ms 64 bytes from 171.67.215.200: icmp_seq=2 ttl=252 time=93.497 ms 64 bytes from 171.67.215.200: icmp_seq=3 ttl=252 time=96.360 ms 64 bytes from 171.67.215.200: icmp_seq=4 ttl=252 time=92.683 ms --- www-v6.stanford.edu ping statistics --- 5 packets transmitted, 5 packets received, 0.0% packet loss round-trip min/avg/max/stddev = 91.151/94.075/96.684/2.138 ms
  68. jp@oeuf:~$ time curl -s http://www.stanford.edu > /dev/null real 0m0.394s user

    0m0.007s sys 0m0.011s
  69. Synthetic transactions capture all of the latency

  70. 2. Instrument your actual queueing

  71. None
  72. # Forgive me father for I [@daveyeu] have sinned. if

    defined?(Thin) class Thin::Connection def process_with_log_connections size = backend.instance_variable_get("@connections").size Stats.measure("thin.connections", size) process_without_log_connections end alias_method_chain :process, :log_connections end end
  73. # https://gist.github.com/jpignata/5084567 class UnicornConnectionMonitor def initialize(app, options = {}) @app

    = app @statsd = options.fetch(:statsd) end def call(env) Raindrops::Linux.tcp_listener_stats(“0.0.0.0:3000”).each do |_, stats| @statsd.measure("unicorn.connections.active", stats.active) @statsd.measure("unicorn.connections.queued", stats.queued) end @app.call(env) end end
  74. 3. Provision more backends

  75. 4. USE a buffering proxy

  76. 5. SQUASH THE RESPONSE TIME OUTLIERS

  77. Rack::Timeout

  78. 6. Move toward CONCURRENT APPLICATION servers

  79. (hint: you can still use Rails)

  80. THANKS! @jpignata http://tx.pignata.com