Page MenuHomePhabricator
Create Task
Maniphest T131894

Collect Backend-Timing in Prometheus
Closed, ResolvedPublic
Actions

Description

Per T124954#2009050 we now emit Backend-Timing on all apaches by default (apache/defaults.conf).

I propose to set up a varnishlog daemon similar to the one we have for the general traffic varnishreqstats, resourceloader varnishrls, and others.

It looks like such a daemon already exists (varnishstatsd), though I wasn't able to find its data anywhere in Graphite.

The main thing I'd like to start tracking is backend response time per data centre and varnish cluster (e.g. eqiad/text). We'll need to make sure to only count new backend requests (and not re-read the header from cached responses).

I'd be nice if we could also break down the text cluster slightly. e.g. varnish.esams.text.all but also varnish.esams.text.load_php for load.php requests. Alternatively, instead of hardcoding entry points in this daemon we could add them to varnishrls instead (and others where we specifically want them).

Details

Related Changes in Gerrit:
SubjectRepoBranchLines +/-
cache: fix varnishbackendtiming destination directoryoperations/puppetproduction+3 -2
cache: enable varnish::logging::backendtimingoperations/puppetproduction+5 -0
Backend-Timing Varnish mtail programoperations/puppetproduction+134 -1
Backend-Timing Varnish mtail programmediawiki/vagrantmaster+120 -1
Refactor varnishslowlog and varnishhospitalmediawiki/vagrantmaster+327 -124
Serve Backend-Timing headermediawiki/vagrantmaster+12 -0
Introduce mtail role and a couple of varnish mtail programsmediawiki/vagrantmaster+731 -1
varnishslowlog: add Backend-Timing D=, in secondsoperations/puppetproduction+13 -0
Customize query in gerrit

Related Objects

Event Timeline

Krinkle created this task.Apr 5 2016, 9:48 PM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptApr 5 2016, 9:48 PM
ori added subscribers: BBlack, ori.Apr 6 2016, 12:44 AM

A few months ago, we (very briefly) enabled reporting of backend latency via the stats interface in MediaWiki for all API request, and it overwhelmed the central statsd aggregator. Since API requests are a subset of app server requests, we have to imagine that naively logging every single request would be even worse.

We can work around that by sampling -- that is, reporting Backend-Timing for 1 in N requests.

This could be implemented either on the Varnishes, as a varnish-log-tailing Python script, or on the application servers themselves, by having Logster tail the Apache logs (which include the backend response time). Logster would be tailing /var/log/apache2/other_vhosts_access.log and slurping the second field (per https://wikitech.wikimedia.org/wiki/Apache_log_format).

Doing this on the Varnish layer would work, but my hunch is that it would be a bit harder to get right, because we would have to be careful not to report the value of the Backend-Timing response header on cached response objects. Some of the rennovations @BBlack has made to the response headers apparently make that easier to do than it has been in the past, but I do not have any direct experience of this.

Peter subscribed.Apr 11 2016, 5:13 PM
ori triaged this task as Medium priority.Apr 11 2016, 6:32 PM
ori moved this task from Inbox, needs triage to Backlog: Maintenance, non-prioritized on the Performance-Team board.
Aklapper added a project: Traffic.May 4 2016, 9:13 AM
Restricted Application added a project: SRE. · View Herald TranscriptMay 4 2016, 9:13 AM
Krinkle mentioned this in T135227: varnish.clients graphite metric spammed with jsessionid.May 13 2016, 1:53 PM
BBlack moved this task from Backlog to General on the Traffic board.Oct 4 2016, 1:12 PM
• Gilles claimed this task.Dec 7 2016, 6:35 PM
• Gilles raised the priority of this task from Medium to High.
• Gilles added a comment.Dec 7 2016, 10:22 PM
gilles@deployment-cache-text04:~$ sudo varnishlog -I BerespHeader:Backend-Timing -g raw
fgiunchedi subscribed.Dec 7 2016, 10:43 PM

@Gilles there's already a number of statsd/graphite python scripts in puppet that read varnish's shared memory. Could be of inspiration e.g. varnishxcache

• Gilles added a comment.Dec 7 2016, 10:45 PM

Right, I wrote/refactored some :) Do you think we should add that feature to an existing one, or write a new one? Since this will look at almost all requests.

fgiunchedi added a comment.Dec 7 2016, 11:21 PM
In T131894#2855765, @Gilles wrote:

Right, I wrote/refactored some :) Do you think we should add that feature to an existing one, or write a new one? Since this will look at almost all requests.

eheh oops! Probably different scripts depending on how --key-prefix is used for aggregation I guess, also aggregate and flush every now and then like varnishreqstats does to avoid udp-meltdown on the graphite machine.

Finally, if you go the separate script idea it'd be interesting to also include the prometheus python client (already installed on varnish machines) and see how that would look like.

Krinkle mentioned this in T164248: HTTP responses from app servers sometimes stall for >1s.May 2 2017, 6:24 AM
• Gilles moved this task from Backlog: Maintenance, non-prioritized to To-do: Goals, prioritized next 4 Quarters on the Performance-Team board.Jun 14 2017, 7:27 PM
• Gilles removed • Gilles as the assignee of this task.Jun 29 2017, 8:04 AM
• Gilles subscribed.
greg added a project: Wikimedia-Incident.Sep 20 2017, 9:33 PM
greg moved this task from Active investigation to Follow-up prevention on the Wikimedia-Incident board.
Krinkle removed a project: Varnish.Sep 20 2017, 10:03 PM
elukey subscribed.Sep 21 2017, 7:20 AM
Krinkle renamed this task from Collect Backend-Timing in Graphite to Collect Backend-Timing in Graphite (or Prometheus).Oct 11 2017, 4:58 PM
• Imarlier subscribed.Dec 4 2017, 9:30 PM
• Imarlier moved this task from To-do: Goals, prioritized next 4 Quarters to Backlog: Maintenance, non-prioritized on the Performance-Team board.Jan 18 2018, 3:44 PM
gerritbot subscribed.Mar 12 2018, 11:45 PM

Change 418603 had a related patch set uploaded (by BBlack; owner: Ema):
[operations/puppet@production] varnishslowlog: add Backend-Timing D=, in seconds

https://gerrit.wikimedia.org/r/418603

gerritbot added a project: Patch-For-Review.Mar 12 2018, 11:45 PM
gerritbot added a comment.Mar 13 2018, 11:14 AM

Change 418603 merged by BBlack:
[operations/puppet@production] varnishslowlog: add Backend-Timing D=, in seconds

https://gerrit.wikimedia.org/r/418603

• Gilles claimed this task.Apr 13 2018, 10:52 AM
• Gilles removed a project: Patch-For-Review.
gerritbot added a comment.Apr 19 2018, 11:13 AM

Change 427641 had a related patch set uploaded (by Gilles; owner: Gilles):
[mediawiki/vagrant@master] Varnish prometheus daemon for Backend-Timing

https://gerrit.wikimedia.org/r/427641

gerritbot added a project: Patch-For-Review.Apr 19 2018, 11:13 AM
gerritbot added a comment.Apr 23 2018, 8:39 AM

Change 428287 had a related patch set uploaded (by Gilles; owner: Gilles):
[mediawiki/vagrant@master] Introduce mtail role and a couple of varnish mtail programs

https://gerrit.wikimedia.org/r/428287

gerritbot added a comment.Apr 23 2018, 8:47 AM

Change 428287 merged by jenkins-bot:
[mediawiki/vagrant@master] Introduce mtail role and a couple of varnish mtail programs

https://gerrit.wikimedia.org/r/428287

gerritbot added a comment.Apr 23 2018, 8:50 AM

Change 428289 had a related patch set uploaded (by Gilles; owner: Gilles):
[mediawiki/vagrant@master] Serve Backend-Timing header

https://gerrit.wikimedia.org/r/428289

gerritbot added a comment.Apr 23 2018, 8:56 AM

Change 428289 merged by jenkins-bot:
[mediawiki/vagrant@master] Serve Backend-Timing header

https://gerrit.wikimedia.org/r/428289

gerritbot added a comment.Apr 23 2018, 9:23 AM

Change 428293 had a related patch set uploaded (by Gilles; owner: Gilles):
[mediawiki/vagrant@master] Backend-Timing Varnish mtail program

https://gerrit.wikimedia.org/r/428293

gerritbot added a comment.Apr 30 2018, 5:16 PM

Change 427641 merged by jenkins-bot:
[mediawiki/vagrant@master] Refactor varnishslowlog and varnishhospital

https://gerrit.wikimedia.org/r/427641

gerritbot added a comment.May 23 2018, 4:46 PM

Change 428293 merged by jenkins-bot:
[mediawiki/vagrant@master] Backend-Timing Varnish mtail program

https://gerrit.wikimedia.org/r/428293

gerritbot added a comment.May 24 2018, 8:06 AM

Change 434879 had a related patch set uploaded (by Gilles; owner: Gilles):
[operations/puppet@production] Backend-Timing Varnish mtail program

https://gerrit.wikimedia.org/r/434879

• Gilles renamed this task from Collect Backend-Timing in Graphite (or Prometheus) to Collect Backend-Timing in Prometheus.May 24 2018, 8:09 AM
• Imarlier moved this task from Backlog: Maintenance, non-prioritized to To-do: Goals, prioritized next 4 Quarters on the Performance-Team board.Jun 21 2018, 9:36 AM
• Gilles changed the task status from Open to Stalled.Jun 25 2018, 6:44 PM

Stuck in review since May

Krinkle moved this task from To-do: Goals, prioritized next 4 Quarters to Blocked (old) on the Performance-Team board.Jun 28 2018, 8:30 PM
• Gilles changed the task status from Stalled to Open.Oct 5 2018, 2:16 PM
gerritbot added a comment.Oct 8 2018, 9:35 AM

Change 434879 merged by Ema:
[operations/puppet@production] Backend-Timing Varnish mtail program

https://gerrit.wikimedia.org/r/434879

gerritbot added a comment.Oct 8 2018, 9:44 AM

Change 465136 had a related patch set uploaded (by Ema; owner: Ema):
[operations/puppet@production] cache: enable varnish::logging::backendtiming

https://gerrit.wikimedia.org/r/465136

gerritbot added a comment.Oct 8 2018, 1:13 PM

Change 465136 merged by Ema:
[operations/puppet@production] cache: enable varnish::logging::backendtiming

https://gerrit.wikimedia.org/r/465136

gerritbot added a comment.Oct 8 2018, 1:59 PM

Change 465170 had a related patch set uploaded (by Ema; owner: Ema):
[operations/puppet@production] cache: fix varnishbackendtiming destination directory

https://gerrit.wikimedia.org/r/465170

gerritbot added a comment.Oct 8 2018, 2:23 PM

Change 465170 merged by Ema:
[operations/puppet@production] cache: fix varnishbackendtiming destination directory

https://gerrit.wikimedia.org/r/465170

• ema subscribed.Oct 8 2018, 2:38 PM

We now expose the following metrics to Prometheus:

14:35:31 ema@cp2004.codfw.wmnet:~
$ curl -s http://localhost:3904/metrics | grep ^varnish_backend_timing
varnish_backend_timing_bucket{le="0.25",prog="varnishbackendtiming.mtail"} 36574
varnish_backend_timing_bucket{le="0.5",prog="varnishbackendtiming.mtail"} 38937
varnish_backend_timing_bucket{le="1",prog="varnishbackendtiming.mtail"} 39751
varnish_backend_timing_bucket{le="2.5",prog="varnishbackendtiming.mtail"} 40036
varnish_backend_timing_bucket{le="5",prog="varnishbackendtiming.mtail"} 40078
varnish_backend_timing_bucket{le="10",prog="varnishbackendtiming.mtail"} 40087
varnish_backend_timing_bucket{le="15",prog="varnishbackendtiming.mtail"} 40087
varnish_backend_timing_bucket{le="+Inf",prog="varnishbackendtiming.mtail"} 40088
varnish_backend_timing_bucket{le="0.05",prog="varnishbackendtiming.mtail"} 16336
varnish_backend_timing_bucket{le="0.1",prog="varnishbackendtiming.mtail"} 27889
varnish_backend_timing_bucket{le="0.025",prog="varnishbackendtiming.mtail"} 2051
varnish_backend_timing_bucket{le="0.005",prog="varnishbackendtiming.mtail"} 78
varnish_backend_timing_bucket{le="0.01",prog="varnishbackendtiming.mtail"} 78
varnish_backend_timing_sum{prog="varnishbackendtiming.mtail"} 470.54365380000104
varnish_backend_timing_count{prog="varnishbackendtiming.mtail"} 40088
• Gilles added a comment.Oct 8 2018, 3:42 PM

https://grafana.wikimedia.org/dashboard/db/apache-backend-timing getting something started there...

• Gilles closed this task as Resolved.Nov 8 2018, 10:32 AM

The basic functionality is there. If we want to iterate on that, it should be the subject of a new task.

Krinkle edited projects, added Sustainability (Incident Followup); removed Wikimedia-Incident.Apr 28 2020, 9:50 PM
Krinkle edited projects, added Wikimedia-Performance-publish; removed Patch-For-Review.Mar 30 2022, 1:49 PM
Krinkle moved this task from Untriaged to Ready for write-up on the Wikimedia-Performance-publish board.
Content licensed under Creative Commons Attribution-ShareAlike (CC BY-SA) 4.0 unless otherwise noted; code licensed under GNU General Public License (GPL) 2.0 or later and other open source licenses. By using this site, you agree to the Terms of Use, Privacy Policy, and Code of Conduct. · Wikimedia Foundation · Privacy Policy · Code of Conduct · Terms of Use · Disclaimer · CC-BY-SA · GPL · Credits