It's not how good your app is, its' how good you want it to be - RubyConf Brazil

Travis CI is a distributed continuous integration system running over 7,000 tests daily. For us to get a true insight into what is going on behind the scenes we have had to come a long way by integrating and building both tools and libraries so that Travis and its many parts are not just a black box of information.

Reading logs and using NewRelic is not new, but far from enough, especially when it comes to apps which are composed of many smaller apps, like Travis. How do you track and visualize requests being processed by multiple services? How do you silence verbose logs while not losing the core of the message? And how do you aggregate, visualize and share metrics?

A lot of how we track, manage, and visualize what is going on in Travis has been created as a set of internal tools and by using a range of awesome services, but core to a lot of this is ActiveSupport Notifications and Travis Instrumentation.

This session will give insight to how Travis is composed and connected, as well as shedding light on how simple it can be to gain more visibility into even a complex, distributed system like Travis, as well as your applications too.

Transcript

1. IT’S NOT HOW GOOD YOUR APP IS, IT’S HOW GOOD YOU WANT IT TO BE
2. Josh
3. Josh Kalderimis
4. @j2h
5. github.com/joshk
8. #38ish
10. Wellington
12. NEW ZEALAND
19. Amsterdam
24. but now...
29. before we get going...
32. -35°
33. -35° WAT!!
34. Desconstruindo Travis
35. Desconstruindo Travis
36. LOGGING
37. METRICS
38. MONITORING
39. part theory
40. part code
41. part internal tools
42. part mustache
43. ?
48. IT’S NOT HOW GOOD YOUR APP IS, IT’S HOW GOOD YOU WANT IT TO BE
51. 1,000,000,000 rps
52. newrelic, airbrake, errbit, exception notifier, metriks, statsd, graphite, and librato
53. internal tools
54. services are your friends
56. Travis CI
57. Travis CI Distributed, continuous integration for the open-source community
58. we run your tests for you!
59. free
60. open source
61. another piece of infrastructure!
62. we are for builds what RubyGems is for libraries
63. 19,300+ projects
64. 7,000+ builds a day
65. 496,068 build requests
66. 1,459,846 total test runs
67. 11+ languages
69. started for fun
70. instant
71. live
72. modern
73. hackable
74. little did you know...
75. Travis united us
78. 2011 - 02 - 05
79. sven mustache pic
80. sven mustache pic @svenfuchs
84. BUT
85. NO MORE MUSTACHE
86. INSTEAD
87. SAY HELLO TO THE ONSIE!
90. FOCUS JOSH!!!
91. Travis Architecture
96. mini S.O.A.
97. we share resources
98. 4 deployable apps
99. 4 different environments
100. staging production Org :
101. staging production Org : staging production Pro :
102. 16 different deployments
103. measuring and monitoring is a challenge
104. but all the more important
106. LOGGING
107. simple
108. concise
109. Started GET "/" for 127.0.0.1 at 2012-03-10 14:28:14 +0100 Processing by HomeController#index as HTML Rendered text template within layouts/application (0.0ms) Rendered layouts/_assets.html.erb (2.0ms) Rendered layouts/_top.html.erb (2.6ms) Rendered layouts/_about.html.erb (0.3ms) Rendered layouts/_google_analytics.html.erb (0.4ms) Completed 200 OK in 79ms (Views: 78.8ms | ActiveRecord: 0.0ms)
110. one line
111. Request Type
112. Request Type URL
113. Request Type URL Format
114. Request Type URL Format Action
115. Request Type URL Format Action Status
116. Request Type URL Format Action Status Total Duration
117. Request Type URL Format Action Status Total Duration View Duration
118. Request Type URL Format Action Status Total Duration View Duration DB Duration
119. GET /jobs/833552.json format=json action=jobs#show status=200 duration=58.33 view=40.43 db=15.26
120. GET /jobs/833552.json format=json action=jobs#show status=200 duration=58.33 view=40.43 db=15.26
121. one line
122. https://github.com/roidrage/lograge
123. non web apps?
124. use different log levels
125. debug
126. info
127. error
128. DEBUG LOTS
129. info a bit
130. error exceptions
131. LOG ALL THE THINGS @marcelokanzaki
132. Travis Hub
133. 1,100 rpm
134. Build Finished
135. Notifications
136. in background threads
137. E [githubcommitstatus] Could not update the PR status on https://api.github.com/repo d18173d510eadf063917db62956f25edab9f70c1 (the server responded with status 404: 40 I Travis::Task::GithubCommitStatus#run for #<Build id=2277110> I Travis::Event::Handler::GithubCommitStatus#notify(build:finished) for #<Build id=22 I Travis::Hub::Handler::Job#update for #<Job id="2277119"> I Travis::Task::Pusher#run for #<Job id=2277152> I Travis::Event::Handler::Pusher#notify(job:test:finished) for #<Job::Test id=2277152> I Travis::Task::Pusher#run for #<Build id=2277146> I Travis::Event::Handler::Pusher#notify(build:finished) for #<Build id=2277146> I Travis::Event::Handler::Email#notify(build:finished) for #<Build id=2277146> I Travis::Event::Handler::Irc#notify(build:finished) for #<Build id=2277146> I Travis::Event::Handler::Webhook#notify(build:finished) for #<Build id=2277146> I Travis::Event::Handler::Campfire#notify(build:finished) for #<Build id=2277146> I [github] Successfully commented on https://api.github.com/repos/mozilla/browserid I Travis::Task::Github#run for #<Build id=2277146> I Travis::Event::Handler::Github#notify(build:finished) for #<Build id=2277146> I Travis::Task::GithubCommitStatus#run for #<Build id=2277146>
138. E [githubcommitstatus] Could not update the PR status on https://api.github.com/repo d18173d510eadf063917db62956f25edab9f70c1 (the server responded with status 404: 40 I Travis::Task::GithubCommitStatus#run for #<Build id=2277110> I Travis::Event::Handler::GithubCommitStatus#notify(build:finished) for #<Build id=22 I Travis::Hub::Handler::Job#update for #<Job id="2277119"> I Travis::Task::Pusher#run for #<Job id=2277152> I Travis::Event::Handler::Pusher#notify(job:test:finished) for #<Job::Test id=2277152> I Travis::Task::Pusher#run for #<Build id=2277146> I Travis::Event::Handler::Pusher#notify(build:finished) for #<Build id=2277146> I Travis::Event::Handler::Email#notify(build:finished) for #<Build id=2277146> I Travis::Event::Handler::Irc#notify(build:finished) for #<Build id=2277146> I Travis::Event::Handler::Webhook#notify(build:finished) for #<Build id=2277146> I Travis::Event::Handler::Campfire#notify(build:finished) for #<Build id=2277146> I [github] Successfully commented on https://api.github.com/repos/mozilla/browserid I Travis::Task::Github#run for #<Build id=2277146> I Travis::Event::Handler::Github#notify(build:finished) for #<Build id=2277146> I Travis::Task::GithubCommitStatus#run for #<Build id=2277146>
139. I Travis::Event::Handler::Irc #notify(build:finished) for #<Build id=2277146>
140. I [class] [method + extra info] for #<[model] id=[id]>
141. E [class] (error message)
142. Travis Worker
143. 5 VMs per worker
144. 5 jobs per worker
145. goal is different
146. easy to see what’s going on
147. live
148. I [ruby-2:worker] starting job slug:Nedomas/ta id:2277524 I [ruby-2:build:remote] about to run I [ruby-2:worker:virtual_box] ruby-2 started with process id : 5772 I [ruby-2:shell:session] starting ssh session to 127.0.0.1:2222 ... I [ruby-2:build:job:test:ruby] about to run I [ruby-2:build:job:test:ruby] about to perform I [ruby-2:build:job:test:ruby] about to chdir I [ruby-2:build:job:test:ruby] about to export I [ruby-2:build:job:test:ruby] about to checkout I [ruby-2:build:job:test:ruby] about to setup I [ruby-2:build:job:test:ruby] about to run_command(:install, "bundle i
149. a more verbose form of info
150. I [ruby-2:worker] starting job slug:Nedomas/ta id:2277524 I [ruby-2:build:remote] about to run I [ruby-2:worker:virtual_box] ruby-2 started with process id : 5772 I [ruby-2:shell:session] starting ssh session to 127.0.0.1:2222 ... I [ruby-2:build:job:test:ruby] about to run I [ruby-2:build:job:test:ruby] about to perform I [ruby-2:build:job:test:ruby] about to chdir I [ruby-2:build:job:test:ruby] about to export I [ruby-2:build:job:test:ruby] about to checkout I [ruby-2:build:job:test:ruby] about to setup I [ruby-2:build:job:test:ruby] about to run_command(:install, "bundle i ruby-2
151. tail -f log/worker.log | grep "\[ruby-2:"
152. we can improve it further!
153. CONSOLIDATE ALL THE LOGGING @marcelokanzaki
154. rsync to a single server
155. Graylog2 (http://graylog2.org)
156. ruby / java elasticsearch
157. papertrail (http://papertrailapp.com)
159. archiving notifications webhooks
160. we <3 papertrail
162. EXCEPTIONS
163. checking logs for errors is no fun
164. use an exception app or service or lib
165. exception_notifier (https://github.com/smartinez87/exception_notification)
166. airbrake (http://airbrake.io)
167. errbit (http://github.com/errbit/errbit)
168. haystack
172. errors as a todo list
173. errors as a todo list
174. errors as a natural part of our app
175. don’t ignore them
176. but don’t fret over them either
177. your customer
178. support emails
179. teh twitters
180. users are a great notification system
181. METRICS
184. NewRelic is powerful
187. AMQP subscriptions
188. using NewRelic for messaging?
189. WAT!!
190. def handle .... end new_relic :handle
191. proxy
192. controller instrumentation
193. trace
196. NewRelic isn’t just for web apps
197. METRICS
198. collecting
199. sending collecting
200. aggregating collecting sending
201. visualizing aggregating sending collecting
202. Collecting
203. alias_method
204. wraps methods
205. times them
206. and sends the data to NewRelic
207. ActiveSupport Notifications
208. ActiveSupport Notifications
209. ActiveSupport Notifications
210. publish `events`
211. instrument `code`
212. subscribe to both
213. one event type
214. multiple using a regex
215. publish one time events
216. instrument yield a block and time it
218. we use it to publish three events
219. received
220. completed
221. failed
222. meta programming
223. def handle .... end instrument :handle
224. ActiveSupport Notifications is metrics agnostic
225. it’s general purpose
226. it’s all about the subscriber
227. Sending and Aggregating
228. statsd
229. statsd http://github.com/etsy/statsd
230. node.js
231. udp
232. pusher.received:1|c
233. pusher.completed:320|ms
234. echo "pusher.completed:320|ms" | nc server port
235. statsd-ruby
236. statsd = Statsd.new(host, port)
237. statsd.increment 'pusher' statsd.timing 'pusher', 320
238. 155 lines of code
239. metriksd
240. Eric Lindvall (Papertrail)
241. ruby eventmachine
242. metriks
243. counter = Metriks.counter('pusher') counter.increment
244. timer = Metriks.timer('pusher') timer.time do work end
245. part aggregator, part sender
246. reporters
247. logs
248. 2012-08-30T13:19:00+00:00 app[web.1]: metriks: time=1346332740 name=active_record.reads type=timer count=161949 one_minute_rate=19.766511278513352 five_minute_rate=14.933384246388295 fifteen_minute_rate=14.305129976012195 mean_rate=14.150840349575361 min=0.001665 max=29831.347368 mean=39.30880807099759 stddev=163468.0162387811 median=1.565408 95th_percentile=91.46994964999998
249. AS Notifications Metriks
250. a quick way to get started
251. chokes up our logs with metrics
252. AS Notifications Metriks ?
253. Vizualising
254. graphite (http://graphite.wikidot.com/)
256. librato (https://metrics.librato.com/metrics)
261. tasseo (https://github.com/obfuscurity/tasseo)
263. AS Notifications Metriks Webhook App
264. AS Notifications Metriks Webhook App collecting aggregating & sending aggregating & sending visualizing
265. we can do better!
266. metriksd_reporter and metriksd
267. AS Notifications Metriks Metriksd collecting aggregating & sending sending visualizing
268. Internal Tools
269. Travis Admin
270. sinatra
271. bootstrap
272. @konstantinhaase
274. http://github.com/rkh/gh
276. EVENT MONITOR
278. @drogus
279. Ember.js
280. Redis Pub/Sub
285. Travis Instrumentation
286. ActiveSupport Notifications
287. travis/support
288. open source the Event Monitor?
289. IT’S NOT HOW GOOD YOUR APP IS, IT’S HOW GOOD YOU WANT IT TO BE
292. 1,000,000,000 rps
293. newrelic, papertrail, metriks, and librato
294. internal tools
295. services are your friends
296. @travisci irc.freenode.net#travis http://github.com/travis-ci
299. THANK YOU
300. Questions?