Slide 1
Slide 1 text
Beyond grep
Pragmatic Logging & Metrics
Hynek Schlawack
Slide 2
Slide 2 text
No content
Slide 3
Slide 3 text
ͩΩͷ΅!
@hynek
https://hynek.me
https://github.com/hynek
Slide 4
Slide 4 text
www.variomedia.de
Slide 5
Slide 5 text
ox.cx/b
Slide 6
Slide 6 text
Agenda
Slide 7
Slide 7 text
Agenda
Slide 8
Slide 8 text
Agenda
Slide 9
Slide 9 text
Agenda
Slide 10
Slide 10 text
Errors
Slide 11
Slide 11 text
Errors
Slide 12
Slide 12 text
Requirements
Slide 13
Slide 13 text
Requirements
•fast
Slide 14
Slide 14 text
Requirements
•fast
•once
Slide 15
Slide 15 text
Requirements
•fast
•once
Slide 16
Slide 16 text
Requirements
•fast
•once
•context
Slide 17
Slide 17 text
Requirements
•fast
•once
•context
Slide 18
Slide 18 text
No content
Slide 19
Slide 19 text
No content
Slide 20
Slide 20 text
No content
Slide 21
Slide 21 text
No content
Slide 22
Slide 22 text
No content
Slide 23
Slide 23 text
No content
Slide 24
Slide 24 text
No content
Slide 25
Slide 25 text
No content
Slide 26
Slide 26 text
No content
Slide 27
Slide 27 text
No content
Slide 28
Slide 28 text
Raven-Python
Slide 29
Slide 29 text
Raven-Python
Transports:
Slide 30
Slide 30 text
Raven-Python
Transports:
• gevent
Slide 31
Slide 31 text
Raven-Python
Transports:
• gevent
• aiohttp
Slide 32
Slide 32 text
Raven-Python
Transports:
• gevent
• aiohttp
• Twisted
Slide 33
Slide 33 text
Raven-Python
Transports:
• gevent
• aiohttp
• Twisted
• …8 others
Slide 34
Slide 34 text
Raven-Python
Integrations:
Transports:
• gevent
• aiohttp
• Twisted
• …8 others
Slide 35
Slide 35 text
Raven-Python
Integrations:
• logging
Transports:
• gevent
• aiohttp
• Twisted
• …8 others
Slide 36
Slide 36 text
Raven-Python
Integrations:
• logging
• Django
Transports:
• gevent
• aiohttp
• Twisted
• …8 others
Slide 37
Slide 37 text
Raven-Python
Integrations:
• logging
• Django
• WSGI
Transports:
• gevent
• aiohttp
• Twisted
• …8 others
Slide 38
Slide 38 text
Raven-Python
Integrations:
• logging
• Django
• WSGI
• …9 others
Transports:
• gevent
• aiohttp
• Twisted
• …8 others
Slide 39
Slide 39 text
Vanilla
from raven import Client
client = Client("https://yoursentry")
try:
1 / 0
except ZeroDivisionError:
client.captureException()
Slide 40
Slide 40 text
Vanilla
from raven import Client
client = Client("https://yoursentry")
try:
1 / 0
except ZeroDivisionError:
client.captureException()
Slide 41
Slide 41 text
Vanilla
from raven import Client
client = Client("https://yoursentry")
try:
1 / 0
except ZeroDivisionError:
client.captureException()
Slide 42
Slide 42 text
Vanilla
@client.capture_exceptions
def foo():
raise Exception()
Slide 43
Slide 43 text
Django
INSTALLED_APPS = (
…
"raven.contrib.django.raven_compat",
…
)
Slide 44
Slide 44 text
Progress!
Slide 45
Slide 45 text
Progress!
✓
Slide 46
Slide 46 text
Metrics
Slide 47
Slide 47 text
Metrics?
Slide 48
Slide 48 text
Metrics?
• numbers in a DB
Slide 49
Slide 49 text
Metrics?
• numbers in a DB
• guessing vs knowing
Slide 50
Slide 50 text
–D. J. Bernstein
“Measure. Don’t speculate.”
Slide 51
Slide 51 text
System Metrics vs App Metrics
• load
• network traffic
• I/O
• …
Slide 52
Slide 52 text
System Metrics vs App Metrics
• load
• network traffic
• I/O
• …
• counters
Slide 53
Slide 53 text
System Metrics vs App Metrics
• load
• network traffic
• I/O
• …
• counters
• timers
Slide 54
Slide 54 text
System Metrics vs App Metrics
• load
• network traffic
• I/O
• …
• counters
• timers
• gauges
Slide 55
Slide 55 text
System Metrics vs App Metrics
• load
• network traffic
• I/O
• …
• counters
• timers
• gauges
• …
Slide 56
Slide 56 text
Aggregation
Slide 57
Slide 57 text
Correlation
Slide 58
Slide 58 text
Math
Slide 59
Slide 59 text
Math
• # reqs / s?
Slide 60
Slide 60 text
Math
• # reqs / s?
• worst 0.01% ⟨req time⟩?
Slide 61
Slide 61 text
Math
• # reqs / s?
• worst 0.01% ⟨req time⟩?
• don’t try this alone!
Slide 62
Slide 62 text
Monitoring
Slide 63
Slide 63 text
Monitoring
• latency
Slide 64
Slide 64 text
Monitoring
• latency
• error rates
Slide 65
Slide 65 text
Monitoring
• latency
• error rates
• anomalies
Slide 66
Slide 66 text
Storage
Slide 67
Slide 67 text
Librato Metrics
Slide 68
Slide 68 text
Graphite
800 pound gorilla
Slide 69
Slide 69 text
Grafana
Slide 70
Slide 70 text
InfluxDB
Graphite++ in Go
Slide 71
Slide 71 text
InfluxDB
Graphite++ in Go
Slide 72
Slide 72 text
Prometheus
Metrics & Monitoring
Slide 73
Slide 73 text
Prometheus
Metrics & Monitoring
Slide 74
Slide 74 text
Prometheus
Metrics & Monitoring
Slide 75
Slide 75 text
Prometheus
Metrics & Monitoring
Slide 76
Slide 76 text
Prometheus
Metrics & Monitoring
Slide 77
Slide 77 text
Prometheus
Metrics & Monitoring
Slide 78
Slide 78 text
Collecting
Slide 79
Slide 79 text
Approaches
Slide 80
Slide 80 text
Approaches
1. external aggregation: StatsD, Riemann
Slide 81
Slide 81 text
Approaches
1. external aggregation: StatsD, Riemann
+ no state, simple
Slide 82
Slide 82 text
Approaches
1. external aggregation: StatsD, Riemann
+ no state, simple
– no direct introspection
Slide 83
Slide 83 text
Approaches
1. external aggregation: StatsD, Riemann
+ no state, simple
– no direct introspection
2. aggregate in-app, deliver to DB
Slide 84
Slide 84 text
Approaches
1. external aggregation: StatsD, Riemann
+ no state, simple
– no direct introspection
2. aggregate in-app, deliver to DB
+ in-app dashboard, useful in dev
Slide 85
Slide 85 text
Approaches
1. external aggregation: StatsD, Riemann
+ no state, simple
– no direct introspection
2. aggregate in-app, deliver to DB
+ in-app dashboard, useful in dev
– state w/i app
Slide 86
Slide 86 text
No content
Slide 87
Slide 87 text
(g|py)?statsd(py|-client)?
import statsd
c = statsd.StatsClient(
"statsd.local", 8125
)
Slide 88
Slide 88 text
(g|py)?statsd(py|-client)?
Slide 89
Slide 89 text
(g|py)?statsd(py|-client)?
c.incr("foo")
Slide 90
Slide 90 text
(g|py)?statsd(py|-client)?
c.incr("foo")
c.timing("stats.timed", 320)
Slide 91
Slide 91 text
Scales
from greplin import scales
from greplin.scales.meter import MeterStat
STATS = scales.collection(
"/Resource",
MeterStat("reqs"),
scales.PmfStat("request_time")
)
Slide 92
Slide 92 text
Scales
from greplin import scales
from greplin.scales.meter import MeterStat
STATS = scales.collection(
"/Resource",
MeterStat("reqs"),
scales.PmfStat("request_time")
)
Slide 93
Slide 93 text
Scales
Slide 94
Slide 94 text
Scales
STATS.reqs.mark()
Slide 95
Slide 95 text
Scales
STATS.reqs.mark()
with STATS.request_time.time():
Slide 96
Slide 96 text
Scales
STATS.reqs.mark()
with STATS.request_time.time():
do_something_expensive()
Slide 97
Slide 97 text
Dashboard
Scales
Slide 98
Slide 98 text
Dashboard
Scales
Slide 99
Slide 99 text
Dashboard
Scales
…
"request_time": {
"count": 567315293,
"99percentile": 0.10978688716888428,
"75percentile": 0.013181567192077637,
"min": 0.0002448558807373047,
"max": 30.134822130203247,
"98percentile": 0.08934824466705339,
"95percentile": 0.027234303951263434,
"median": 0.009176492691040039,
"999percentile": 0.14235656142234793,
"stddev": 0.01676855570363413,
"mean": 0.013247184020535955
},
…
Slide 100
Slide 100 text
from greplin.scales import graphite
pusher = graphite.GraphitePeriodicPusher(
"graphite.host",
2003,
period=30,
prefix="yourapp",
)
pusher.allow("**")
pusher.start()
Slide 101
Slide 101 text
Prometheus
Slide 102
Slide 102 text
Prometheus
import random, time
from prometheus_client import \
start_http_server, Summary
Slide 103
Slide 103 text
Prometheus
import random, time
from prometheus_client import \
start_http_server, Summary
FUNC_TIME = Summary(
"func_seconds", "Time spent in func")
Slide 104
Slide 104 text
Prometheus
import random, time
from prometheus_client import \
start_http_server, Summary
FUNC_TIME = Summary(
"func_seconds", "Time spent in func")
@FUNC_TIME.time()
def func(t):
time.sleep(t)
Slide 105
Slide 105 text
Prometheus
import random, time
from prometheus_client import \
start_http_server, Summary
FUNC_TIME = Summary(
"func_seconds", "Time spent in func")
@FUNC_TIME.time()
def func(t):
time.sleep(t)
if __name__ == '__main__':
start_http_server(8000)
while True:
func(random.random())
Slide 106
Slide 106 text
Prometheus
# HELP func_seconds Time spent in func
# TYPE func_seconds summary
func_seconds_count 78.0
func_seconds_sum 37.8028838634491
Slide 107
Slide 107 text
Progress!
✓
Slide 108
Slide 108 text
Progress!
✓ ✓
Slide 109
Slide 109 text
Logging
Slide 110
Slide 110 text
Splunk
Slide 111
Slide 111 text
Splunk
Slide 112
Slide 112 text
Papertrail
Slide 113
Slide 113 text
loggly
Slide 114
Slide 114 text
ELK
Elasticsearch + Logstash + Kibana
Slide 115
Slide 115 text
No content
Slide 116
Slide 116 text
No content
Slide 117
Slide 117 text
Logstash
Slide 118
Slide 118 text
Elasticsearch
Logstash
Slide 119
Slide 119 text
Elasticsearch
Logstash
Slide 120
Slide 120 text
Elasticsearch
Logstash
Kibana
Slide 121
Slide 121 text
Graylog
Slide 122
Slide 122 text
Graylog
Slide 123
Slide 123 text
Graylog
Slide 124
Slide 124 text
Graylog
Slide 125
Slide 125 text
No content
Slide 126
Slide 126 text
No content
Slide 127
Slide 127 text
Goal
@400000005270e0d604afce64 {
"event": "logged_in",
"user": "guido",
"ip": "8.8.8.8",
"referrer": "http://google.com"
}
Slide 128
Slide 128 text
Context
&
Format
Slide 129
Slide 129 text
structlog
Slide 130
Slide 130 text
BoundLogger
structlog
Slide 131
Slide 131 text
Original
Logger
BoundLogger
structlog
e.g.
logging.Logger
Slide 132
Slide 132 text
Original
Logger
BoundLogger
bind values
log.bind(key=value)
Context
structlog
Slide 133
Slide 133 text
Original
Logger
BoundLogger
bind values
log.bind(key=value)
Context
log events
log.info(event, another_key=another_value)
+
structlog
Slide 134
Slide 134 text
Original
Logger
BoundLogger
Processor 1 Processor n Return
Value
Return
Value
bind values
log.bind(key=value)
Context
log events
log.info(event, another_key=another_value)
+
structlog
Slide 135
Slide 135 text
>>> import structlog
>>> log = structlog.get_logger()
>>> log.error("ohai", why=42, wtf=True)
why=42 wtf=True event='ohai'
Slide 136
Slide 136 text
>>> import structlog
>>> log = structlog.get_logger()
>>> log.error("ohai", why=42, wtf=True)
why=42 wtf=True event='ohai'
Slide 137
Slide 137 text
>>> import structlog
>>> log = structlog.get_logger()
>>> log.error("ohai", why=42, wtf=True)
why=42 wtf=True event='ohai'
Slide 138
Slide 138 text
>>> import structlog
>>> log = structlog.get_logger()
>>> log.error("ohai", why=42, wtf=True)
why=42 wtf=True event='ohai'
Slide 139
Slide 139 text
>>> from structlog import get_logger
>>> log = get_logger()
>>> log = log.bind(user='anonymous', some_key=23)
>>> log = log.bind(user='hynek', another_key=42)
>>> log.info('user.logged_in', happy=True)
some_key=23 user='hynek' another_key=42
happy=True event='user.logged_in'
Slide 140
Slide 140 text
>>> from structlog import get_logger
>>> log = get_logger()
>>> log = log.bind(user='anonymous', some_key=23)
>>> log = log.bind(user='hynek', another_key=42)
>>> log.info('user.logged_in', happy=True)
some_key=23 user='hynek' another_key=42
happy=True event='user.logged_in'
Slide 141
Slide 141 text
>>> from structlog import get_logger
>>> log = get_logger()
>>> log = log.bind(user='anonymous', some_key=23)
>>> log = log.bind(user='hynek', another_key=42)
>>> log.info('user.logged_in', happy=True)
some_key=23 user='hynek' another_key=42
happy=True event='user.logged_in'
Slide 142
Slide 142 text
>>> from structlog import get_logger
>>> log = get_logger()
>>> log = log.bind(user='anonymous', some_key=23)
>>> log = log.bind(user='hynek', another_key=42)
>>> log.info('user.logged_in', happy=True)
some_key=23 user='hynek' another_key=42
happy=True event='user.logged_in'
Slide 143
Slide 143 text
>>> from structlog import get_logger
>>> log = get_logger()
>>> log = log.bind(user='anonymous', some_key=23)
>>> log = log.bind(user='hynek', another_key=42)
>>> log.info('user.logged_in', happy=True)
some_key=23 user='hynek' another_key=42
happy=True event='user.logged_in'
Slide 144
Slide 144 text
def view(request):
log = logger.bind(request=request)
log.info("view_rendered")
return "hello, world"
Slide 145
Slide 145 text
def view(request):
log = logger.bind(request=request)
log.info("view_rendered")
return "hello, world"
Slide 146
Slide 146 text
def view(request):
log = logger.bind(request=request)
log.info("view_rendered")
return "hello, world"
Slide 147
Slide 147 text
def request_extractor(_, __, event):
req = event.pop("request", None)
if req is not None:
event.update({
"client_addr":
req.client_addr,
"user_id":
req.authenticated_userid,
})
return event
Slide 148
Slide 148 text
def request_extractor(_, __, event):
req = event.pop("request", None)
if req is not None:
event.update({
"client_addr":
req.client_addr,
"user_id":
req.authenticated_userid,
})
return event
Slide 149
Slide 149 text
def request_extractor(_, __, event):
req = event.pop("request", None)
if req is not None:
event.update({
"client_addr":
req.client_addr,
"user_id":
req.authenticated_userid,
})
return event
Slide 150
Slide 150 text
def request_extractor(_, __, event):
req = event.pop("request", None)
if req is not None:
event.update({
"client_addr":
req.client_addr,
"user_id":
req.authenticated_userid,
})
return event
Slide 151
Slide 151 text
{"client_addr": "192.168.42.42",
"user_id": null,
"event": "view_rendered"}
Slide 152
Slide 152 text
import logging, sys
logger = logging.getLogger()
logger.addHandler(
logging.StreamHandler(
sys.stdout
)
)
Slide 153
Slide 153 text
import logging, sys
logger = logging.getLogger()
logger.addHandler(
logging.StreamHandler(
sys.stdout
)
)
Slide 154
Slide 154 text
Capture
Slide 155
Slide 155 text
Capture
• into files
Slide 156
Slide 156 text
Capture
• into files
• to syslog / a queue
Slide 157
Slide 157 text
Capture
• into files
• to syslog / a queue
• pipe into a logging agent
Slide 158
Slide 158 text
No content
Slide 159
Slide 159 text
log = log.bind(user="guido")
log.info("user.login")
Slide 160
Slide 160 text
{"event": "user.login", "user": "guido"}
log = log.bind(user="guido")
log.info("user.login")
structlog
Slide 161
Slide 161 text
{"event": "user.login", "user": "guido"}
log = log.bind(user="guido")
log.info("user.login")
structlog
stdout
logging
Slide 162
Slide 162 text
{"event": "user.login", "user": "guido"}
log = log.bind(user="guido")
log.info("user.login")
structlog
stdout
logging
/var/log/app/current
runit’s svlogd
(adds TAI64 timestamp)
Slide 163
Slide 163 text
{"event": "user.login", "user": "guido"}
log = log.bind(user="guido")
log.info("user.login")
structlog
logstash-forwarder
logstash
stdout
logging
/var/log/app/current
runit’s svlogd
(adds TAI64 timestamp)
Slide 164
Slide 164 text
{"event": "user.login", "user": "guido"}
log = log.bind(user="guido")
log.info("user.login")
structlog
logstash-forwarder
logstash
1010001101
Elasticsearch
stdout
logging
/var/log/app/current
runit’s svlogd
(adds TAI64 timestamp)
Slide 165
Slide 165 text
Progress!
✓ ✓
Slide 166
Slide 166 text
Progress!
✓ ✓ ✓
Slide 167
Slide 167 text
Wait a Minute…
Slide 168
Slide 168 text
Wait a Minute…
Slide 169
Slide 169 text
Ugh
try:
STATS.time.timing():
something()
except Exception as e:
log.error("omg", exc_info=e)
raven_client.captureError()
STATS.errors.mark()
Slide 170
Slide 170 text
Ugh
try:
STATS.time.timing():
something()
except Exception as e:
log.error("omg", exc_info=e)
raven_client.captureError()
STATS.errors.mark()
Slide 171
Slide 171 text
Awww
try:
something()
except Exception as e:
log.exception("omg")
Slide 172
Slide 172 text
Errors
Slide 173
Slide 173 text
Errors
• logging integration
Slide 174
Slide 174 text
Errors
• logging integration
• structlog
Slide 175
Slide 175 text
Errors
• logging integration
• structlog
• web apps: error views
Slide 176
Slide 176 text
Error View
@view_config(context=Exception)
def err(exc, request):
return Response(
"oops: " + raven_client.captureException()
)
Slide 177
Slide 177 text
No content
Slide 178
Slide 178 text
Metrics
measure from outside
Slide 179
Slide 179 text
WSGI Servers
Slide 180
Slide 180 text
WSGI Servers
• gunicorn: --statsd-host
Slide 181
Slide 181 text
WSGI Servers
• gunicorn: --statsd-host
• uWSGI:
Slide 182
Slide 182 text
WSGI Servers
• gunicorn: --statsd-host
• uWSGI:
• --stats-push statsd:
Slide 183
Slide 183 text
WSGI Servers
• gunicorn: --statsd-host
• uWSGI:
• --stats-push statsd:
• --carbon
Slide 184
Slide 184 text
Middleware
def timing_tween_factory(handler, registry):
def timing_tween(request):
with STATS.request_time.time():
return handler(request)
return timing_tween
Slide 185
Slide 185 text
Middleware
def timing_tween_factory(handler, registry):
def timing_tween(request):
with STATS.request_time.time():
return handler(request)
return timing_tween
Slide 186
Slide 186 text
Extract from Logs
Slide 187
Slide 187 text
Extract from Logs
logstash
Slide 188
Slide 188 text
Extract from Logs
logstash
• StatsD
Slide 189
Slide 189 text
Extract from Logs
logstash
• StatsD
• Graphite
Slide 190
Slide 190 text
Extract from Logs
logstash
• StatsD
• Graphite
• librato
Slide 191
Slide 191 text
Extract from Logs
logstash
• StatsD
• Graphite
• librato
• …
Slide 192
Slide 192 text
Extract from Logs
logstash
• StatsD
• Graphite
• librato
• …
or structlog
Slide 193
Slide 193 text
Leverage
Monitoring
Slide 194
Slide 194 text
Remaining
Slide 195
Slide 195 text
Remaining
1. measure code paths
Slide 196
Slide 196 text
Remaining
1. measure code paths
2. expose gauges
Slide 197
Slide 197 text
Summary
Slide 198
Slide 198 text
Summary
Slide 199
Slide 199 text
Summary
Slide 200
Slide 200 text
Summary
Slide 201
Slide 201 text
Summary
Slide 202
Slide 202 text
ox.cx/b
@hynek
vrmd.de