A Brief Aside on Request Queueing

Transcript

1. QUEUEING @jpignata br f REQUEST
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
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