{"id":482,"date":"2018-09-04T14:37:07","date_gmt":"2018-09-04T09:37:07","guid":{"rendered":"http:\/\/library.brown.edu\/DigitalTechnologies\/?p=482"},"modified":"2021-02-02T02:54:26","modified_gmt":"2021-02-01T21:54:26","slug":"monitoring-passengers-requests-in-queue-over-time","status":"publish","type":"post","link":"https:\/\/library.brown.edu\/create\/digitaltechnologies\/monitoring-passengers-requests-in-queue-over-time\/","title":{"rendered":"Monitoring Passenger’s Requests in Queue over time"},"content":{"rendered":"

As I mentioned in a previous post<\/a> we use Phusion Passenger as the application server to host our Ruby applications. A while ago upon the recommendation of my coworker Ben Cail<\/a> I created a cron job that calls passenger-status every 5 minutes to log the status of Passenger in our servers.\u00a0 Below is a sample of the passenger-status<\/a> output:<\/p>\n

Version : 5.1.12\nDate : Mon Jul 30 10:42:54 -0400 2018\nInstance: 8x6dq9uX (Apache\/2.2.15 (Unix) DAV\/2 Phusion_Passenger\/5.1.12)\n\n----------- General information -----------\nMax pool size : 6\nApp groups : 1\nProcesses : 6\nRequests in top-level queue : 0\n\n----------- Application groups -----------\n\/path\/to\/our\/app:\nApp root: \/path\/to\/our\/app\nRequests in queue: 3<\/strong>\n* PID: 43810 Sessions: 1 Processed: 20472 Uptime: 1d 7h 31m 25s\nCPU: 0% Memory : 249M Last used: 1s ag\n* PID: 2628 Sessions: 1 Processed: 1059 Uptime: 4h 34m 39s\nCPU: 0% Memory : 138M Last used: 1s ago\n* PID: 2838 Sessions: 1 Processed: 634 Uptime: 4h 30m 47s\nCPU: 0% Memory : 134M Last used: 1s ago\n* PID: 16836 Sessions: 1 Processed: 262 Uptime: 2h 14m 46s\nCPU: 0% Memory : 160M Last used: 1s ago\n* PID: 27431 Sessions: 1 Processed: 49 Uptime: 25m 27s\nCPU: 0% Memory : 119M Last used: 0s ago\n* PID: 27476 Sessions: 1 Processed: 37 Uptime: 25m 0s\nCPU: 0% Memory : 117M Last used: 0s ago<\/pre>\n
Our cron job to log this information over time is something like this:<\/p>\n
\/path\/to\/.gem\/gems\/passenger-5.1.12\/bin\/passenger-status >> .\/logs\/passenger_status.log<\/pre>\n
Last week we had some issues in which our production server was experiencing short outages. Upon review we noticed that we were having a unusual amount of traffic coming to our server (most of it from crawlers submitting bad requests.) One of the tools that we used to validate the status of our server was the passenger_status.log<\/strong> file created via the aforementioned cron job.<\/p>\n
The key piece of information that we use is the “Requests in queue” value highlighted above. We parsed this value of out the passenger_status.log<\/strong> file to see how it changed in the last 30 days. The result showed that although we have had a couple of outages recently the number of “requests in queue” dramatically increased about two weeks ago and it had stayed high ever since.<\/p>\n
The graph below shows what we found. Notice how after August 19th the value of “requests in queue” has been constantly high, whereas before August 19th it was almost always zero or below 10.<\/p>\n
\"Request<\/a><\/p>\n
We looked closely to our Apache and Rails logs and determined the traffic that was causing the problem. We took a few steps to handle it and now our servers are behaving as normal again. Notice how we are back to zero requests in queue on August 31st in the graph above.<\/p>\n
The Ruby code that we use to parse our passenger_status.log<\/strong> file is pretty simple, it just grabs the line with the date and the line with the number of requests in queue, parses their values, and outputs the result to a tab delimited file that then we can use to create a graph in Excel or RAWGraphs<\/a>. Below is the Ruby code:<\/p>\n
require \"date\"\n\nlog_file = \"passenger_status.log\"\nexcel_date = true\n\ndef date_from_line(line, excel_date)\n  index = line.index(\":\")\n  return nil if index == nil\n  date_as_text = line[index+2..-1].strip # Thu Aug 30 14:00:01 -0400 2018\n  datetime = DateTime.parse(date_as_text).to_s # 2018-08-30T14:00:01-04:00\n  if excel_date\n    return datetime[0..9] + \" \" + datetime[11..15] # 2018-08-30 14:00\n  end\n  datetime\nend\n\ndef count_from_line(line)\n  return line.gsub(\"Requests in queue:\", \"\").to_i\nend\n\nputs \"timestamp\\trequest_in_queue\"\ndate = \"N\/A\"\nFile.readlines(log_file).each do |line|\n  if line.start_with?(\"Date \")\n    date = date_from_line(line, excel_date)\n  elsif line.include?(\"Requests in queue:\")\n    request_count = count_from_line(line)\n    puts \"\\\"#{date}\\\"\\t#{request_count}\"\n  end\nend<\/pre>\n
In this particular case the number of requests in queue was caused by bad\/unwanted traffic. If the increase in traffic had been legitimate we would have taken a different route, like adding more processes to our Passenger instance to handle the traffic.<\/p>\n","protected":false},"excerpt":{"rendered":"
As I mentioned in a previous post we use Phusion Passenger as the application server to host our Ruby applications. A while ago upon the recommendation of my coworker Ben Cail I created a cron job that calls passenger-status every 5 minutes to log the status of Passenger in our servers.\u00a0 Below is a sample … Continue reading Monitoring Passenger’s Requests in Queue over time<\/span><\/a><\/p>\n","protected":false},"author":115,"featured_media":0,"comment_status":"closed","ping_status":"open","sticky":false,"template":"","format":"standard","meta":{"footnotes":""},"categories":[3,6,10,14],"tags":[],"class_list":["post-482","post","type-post","status-publish","format-standard","hentry","category-blacklight","category-josiah","category-programming","category-web"],"_links":{"self":[{"href":"https:\/\/library.brown.edu\/create\/digitaltechnologies\/wp-json\/wp\/v2\/posts\/482","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/library.brown.edu\/create\/digitaltechnologies\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/library.brown.edu\/create\/digitaltechnologies\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/library.brown.edu\/create\/digitaltechnologies\/wp-json\/wp\/v2\/users\/115"}],"replies":[{"embeddable":true,"href":"https:\/\/library.brown.edu\/create\/digitaltechnologies\/wp-json\/wp\/v2\/comments?post=482"}],"version-history":[{"count":1,"href":"https:\/\/library.brown.edu\/create\/digitaltechnologies\/wp-json\/wp\/v2\/posts\/482\/revisions"}],"predecessor-version":[{"id":620,"href":"https:\/\/library.brown.edu\/create\/digitaltechnologies\/wp-json\/wp\/v2\/posts\/482\/revisions\/620"}],"wp:attachment":[{"href":"https:\/\/library.brown.edu\/create\/digitaltechnologies\/wp-json\/wp\/v2\/media?parent=482"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/library.brown.edu\/create\/digitaltechnologies\/wp-json\/wp\/v2\/categories?post=482"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/library.brown.edu\/create\/digitaltechnologies\/wp-json\/wp\/v2\/tags?post=482"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}