Rack timings

client.rb

require 'socket'

socket = TCPSocket.open('localhost', 9292)

puts "Sending headers at #{Time.now.strftime('%T.%L')}"

socket.puts <<~REQUEST
POST / HTTP/1.1\r
Host: localhost:9292\r
Accept: */*\r
Content-Length: 3\r
Content-Type: application/x-www-form-urlencoded\r
\r
REQUEST

sleep 1
puts "Sending at #{Time.now.strftime('%T.%L')}"
socket.puts "."
sleep 1
socket.puts "."
puts "Finished at #{Time.now.strftime('%T.%L')}"

socket.close

links.md

https://github.com/newrelic/rpm/blob/master/lib/new_relic/agent/instrumentation/middleware_tracing.rb#L83-L106

result.txt

$ rackup server.ru
Starting at 17:49:14.062
Finished at 17:49:14.062
::1 - - [11/Oct/2017:17:49:14 +1300] "POST / HTTP/1.1" 200 - 0.0007

$ ruby client.rb
Sending headers at 17:49:12.059
Sending at 17:49:13.060
Finished at 17:49:14.061

server.rb

class Middleware
  def initialize(app)
    @app = app
  end

  def call(env)
    puts "Starting at #{Time.now.strftime('%T.%L')}"
    result = @app.call(env)
    puts "Finished at #{Time.now.strftime('%T.%L')}"
    result
  end
end

use Middleware

run -> (_) { [200, {}, ['OK']] }