Tweet
Tweet

Slide 1

Slide 1 text

2015 yo Speed Science @schneems

Slide 2

Slide 2 text

What is our goal?

Slide 3

Slide 3 text

What is our goal?

Slide 4

Slide 4 text

No content

Slide 5

Slide 5 text

Slow is a bug

Slide 6

Slide 6 text

Bugs can be reproduced

Slide 7

Slide 7 text

Once reproduced we can squash

Slide 8

Slide 8 text

What is this shape?

Slide 9

Slide 9 text

No content

Slide 10

Slide 10 text

Fast Angles

Slide 11

Slide 11 text

No content

Slide 12

Slide 12 text

Square Edges

Slide 13

Slide 13 text

No content

Slide 14

Slide 14 text

Square!

Slide 15

Slide 15 text

Programming has a speed square

Slide 16

Slide 16 text

IO RAM CPU

Slide 17

Slide 17 text

Trade resources for speed

Slide 18

Slide 18 text

Likewise

Slide 19

Slide 19 text

Trade one resource for another

Slide 20

Slide 20 text

How do we make things fast?

Slide 21

Slide 21 text

Find the bottleneck

Slide 22

Slide 22 text

No content

Slide 23

Slide 23 text

We can use the scientific method!

Slide 24

Slide 24 text

No content

Slide 25

Slide 25 text

BTW

Slide 26

Slide 26 text

They Call me @Schneems

Slide 27

Slide 27 text

I Love Ruby

Slide 28

Slide 28 text

No content

Slide 29

Slide 29 text

Ruby Schneems

Slide 30

Slide 30 text

Ruby Python

Slide 31

Slide 31 text

Human.new

Slide 32

Slide 32 text

Names?

Slide 33

Slide 33 text

Girl? Boy?

Slide 34

Slide 34 text

Sudo clean up your room

Slide 35

Slide 35 text

No content

Slide 36

Slide 36 text

Booth Koichi
 Terence

Slide 37

Slide 37 text

Rails Commit Bit

Slide 38

Slide 38 text

No content

Slide 39

Slide 39 text

Once upon a time

Slide 40

Slide 40 text

There was an app

Slide 41

Slide 41 text

Downloads a large .tgz file

Slide 42

Slide 42 text

Decompres File

Slide 43

Slide 43 text

Fast?

Slide 44

Slide 44 text

Pull Faster!

Slide 45

Slide 45 text

download unzip process IO

Slide 46

Slide 46 text

download unzip process IO IO CPU

Slide 47

Slide 47 text

download unzip process IO IO CPU RAM CPU

Slide 48

Slide 48 text

Hypothesis: Not Enough CPU

Slide 49

Slide 49 text

Bring in the big guns

Slide 50

Slide 50 text

PX DYNO

Slide 51

Slide 51 text

6 GB of RAM

Slide 52

Slide 52 text

1 PX Dyno == 1 AWS instance

Slide 53

Slide 53 text

No Sharing

Slide 54

Slide 54 text

More threads == More CPU load

Slide 55

Slide 55 text

Sidekiq worker

Slide 56

Slide 56 text

config:set SIDEKIQ_CONCURRENCY = 30

Slide 57

Slide 57 text

download unzip process 30x

Slide 58

Slide 58 text

Result?

Slide 59

Slide 59 text

Faster but…

Slide 60

Slide 60 text

No content

Slide 61

Slide 61 text

Theory: Not using all available CPU

Slide 62

Slide 62 text

config:set SIDEKIQ_CONCURRENCY = 30

Slide 63

Slide 63 text

config:set SIDEKIQ_CONCURRENCY = 30 60

Slide 64

Slide 64 text

Result?

Slide 65

Slide 65 text

ER

Slide 66

Slide 66 text

No content

Slide 67

Slide 67 text

Why?

Slide 68

Slide 68 text

Not
 CPU bound

Slide 69

Slide 69 text

IO RAM CPU

Slide 70

Slide 70 text

download unzip process IO IO CPU RAM CPU

Slide 71

Slide 71 text

download unzip process IO IO CPU RAM CPU

Slide 72

Slide 72 text

download unzip process IO IO Network & Disk

Slide 73

Slide 73 text

download unzip process IO IO Network & Disk Disk

Slide 74

Slide 74 text

Theory: Network is Slow

Slide 75

Slide 75 text

Tried: Curl, Curb, Excon Typhoeus

Slide 76

Slide 76 text

What is the solution to all slow things?

Slide 77

Slide 77 text

GO

Slide 78

Slide 78 text

No content

Slide 79

Slide 79 text

Sorry GO is not the answer

Slide 80

Slide 80 text

Network IO wasn’t the problem

Slide 81

Slide 81 text

Maybe, it’s disk IO?

Slide 82

Slide 82 text

config:set SIDEKIQ_CONCURRENCY = 30

Slide 83

Slide 83 text

config:set SIDEKIQ_CONCURRENCY = 30 4

Slide 84

Slide 84 text

No content

Slide 85

Slide 85 text

The Disk was at max read/ write capacity

Slide 86

Slide 86 text

Threads were sitting idle due to disk contention

Slide 87

Slide 87 text

Ended up using 2x dynos instead

Slide 88

Slide 88 text

Moral of the story: Blindly trying things works, but it’s not very scientific

Slide 89

Slide 89 text

No content

Slide 90

Slide 90 text

No content

Slide 91

Slide 91 text

No content

Slide 92

Slide 92 text

Good Science is repeatable

Slide 93

Slide 93 text

No content

Slide 94

Slide 94 text

Not Cold Fusion

Slide 95

Slide 95 text

Not Repeatable

Slide 96

Slide 96 text

Not Good Science

Slide 97

Slide 97 text

Measure & Benchmark

Slide 98

Slide 98 text

Heroku Added Metrics

Slide 99

Slide 99 text

Speed Throughput CPU RAM

Slide 100

Slide 100 text

High Level metrics => Low level metrics

Slide 101

Slide 101 text

Reproduce the slow

Slide 102

Slide 102 text

RAM

Slide 103

Slide 103 text

Ruby is typically RAM bound

Slide 104

Slide 104 text

Ruby is a “managed” Language

Slide 105

Slide 105 text

Don’t manually allocate, use Garbage Collector instead

Slide 106

Slide 106 text

2 causes for increased memory use

Slide 107

Slide 107 text

Retained Objects 1)

Slide 108

Slide 108 text

RETAINED = [] 1.upto(100_000_000).each do |i| RETAINED << “#{i}” end

Slide 109

Slide 109 text

7.32 GB

Slide 110

Slide 110 text

WHY?

Slide 111

Slide 111 text

Memory

Slide 112

Slide 112 text

Memory Object slots

Slide 113

Slide 113 text

Memory “1” “2” “3”“4” “5” “6” “7” RETAINED = [] 1.upto(100_000_000).each do |i| RETAINED << “#{i}” end

Slide 114

Slide 114 text

Out of slots! Allocate more memory

Slide 115

Slide 115 text

Memory “1” “2” “3”“4” “5” “6” “7” “10” “8” “9” “11” “12” “13” “14”

Slide 116

Slide 116 text

Allocated Objects 1)

Slide 117

Slide 117 text

1.upto(100_000_000).each do |i| puts "#{i}" end

Slide 118

Slide 118 text

21.8 MB

Slide 119

Slide 119 text

Memory “1” “2” “3”“4” “5” “6” “7”

Slide 120

Slide 120 text

Out of slots! Run GC!

Slide 121

Slide 121 text

Memory “2” “3”“4” “5” “6” “7” 1.upto(100_000_000).each do |i| puts "#{i}" end “1”

Slide 122

Slide 122 text

Memory “2” “3”“4” “5” “6” “7” 1.upto(100_000_000).each do |i| puts "#{i}" end

Slide 123

Slide 123 text

Memory “8” “3”“4” “5” “6” “7” 1.upto(100_000_000).each do |i| puts "#{i}" end “2”

Slide 124

Slide 124 text

GC will save us!

Slide 125

Slide 125 text

def make_objects array = [] 1.upto(100_000_000).each do |i| array << "#{i}" end return nil end make_objects GC.start(full_mark: true, immediate_sweep: true)

Slide 126

Slide 126 text

def make_objects array = [] 1.upto(100_000_000).each do |i| array << "#{i}" end return nil end make_objects GC.start(full_mark: true, immediate_sweep: true)

Slide 127

Slide 127 text

def make_objects array = [] 1.upto(100_000_000).each do |i| array << "#{i}" end return nil end make_objects GC.start(full_mark: true, immediate_sweep: true)

Slide 128

Slide 128 text

Result?

Slide 129

Slide 129 text

7.32 GB

Slide 130

Slide 130 text

WAT

Slide 131

Slide 131 text

GC.start(full_mark: true, immediate_sweep: true) GC.disable # Code goes here before = GC.stat[:total_freed_objects] GC.enable GC.start(full_mark: true, immediate_sweep: true) after = GC.stat[:total_freed_objects] # => “Objects cleared by GC: 100_010_687”

Slide 132

Slide 132 text

Cannot open slots while reference exists

Slide 133

Slide 133 text

Memory “1” “2” “3”“4” “5” “6” “7” “10” “8” “9” “11” “12” “13” “14”

Slide 134

Slide 134 text

Run GC

Slide 135

Slide 135 text

Memory “1” “2” “3”“4” “5” “6” “7” “10” “8” “9” “11” “12” “13” “14”

Slide 136

Slide 136 text

Ruby NEVER releases memory

Slide 137

Slide 137 text

Memory

Slide 138

Slide 138 text

Test Everything (even these slides)

Slide 139

Slide 139 text

No content

Slide 140

Slide 140 text

How does this affect my Rails app?

Slide 141

Slide 141 text

Retained App

Slide 142

Slide 142 text

Retained Allocated App

Slide 143

Slide 143 text

Mem Usage App

Slide 144

Slide 144 text

Request Starts

Slide 145

Slide 145 text

Request Full .

Slide 146

Slide 146 text

Request Full Full ..

Slide 147

Slide 147 text

Request Full Full Full ...

Slide 148

Slide 148 text

Request Full Full Full Full ....

Slide 149

Slide 149 text

Request Full Full Full Full Full ......

Slide 150

Slide 150 text

Out of memory Full Full Full Full Full

Slide 151

Slide 151 text

Run GC, All objs needed 0_o Full Full Full Full Full

Slide 152

Slide 152 text

Allocate mem Full Full Full Full Full

Slide 153

Slide 153 text

Request Done Full Full Full Full Full ........

Slide 154

Slide 154 text

Eventually

Slide 155

Slide 155 text

GC Objs not used Full Full Full Full Full

Slide 156

Slide 156 text

GC Objs not used

Slide 157

Slide 157 text

Memory increases even without object retention

Slide 158

Slide 158 text

Object creation/ deletion takes RAM

Slide 159

Slide 159 text

Object creation/ deletion takes Time

Slide 160

Slide 160 text

Further Reading:

Slide 161

Slide 161 text

Generational GC

Slide 162

Slide 162 text

I want to share a customer story

Slide 163

Slide 163 text

One day a ticket came in

Slide 164

Slide 164 text

My app is slow

Slide 165

Slide 165 text

I checked metrics

Slide 166

Slide 166 text

No content

Slide 167

Slide 167 text

They were using too much RAM and hitting swap

Slide 168

Slide 168 text

swap

Slide 169

Slide 169 text

Why?

Slide 170

Slide 170 text

“didn’t used to happen”

Slide 171

Slide 171 text

“we didn’t change anything”

Slide 172

Slide 172 text

Hypothesis #1

Slide 173

Slide 173 text

RAM increase due to misbehaving code in a Gem

Slide 174

Slide 174 text

How do we test?

Slide 175

Slide 175 text

Boot app, hit with requests, profile memory

Slide 176

Slide 176 text

Derailed Benchmarks

Slide 177

Slide 177 text

Boot the app

Slide 178

Slide 178 text

Process a request

Slide 179

Slide 179 text

Benchmark with Memory Profiler

Slide 180

Slide 180 text

$ rake perf:mem

Slide 181

Slide 181 text

I did this in codetriage.com sent instructions to customer

Slide 182

Slide 182 text

allocated memory by gem ----------------------------------- rack-1.5.2 x 6491 actionpack-4.1.2 x 4888 hashie-3.3.1 x 4735 <============== activesupport-4.1.2 x 3292 omniauth-1.2.2 x 1387 actionview-4.1.2 x 1107 ruby-2.1.2/lib x 1097 railties-4.1.2 x 925 activerecord-4.1.2 x 440 warden-1.2.3 x 200 codetriage-test-app/app x 40 other x 40

Slide 183

Slide 183 text

Hashie is incredibly expensive

Slide 184

Slide 184 text

Lots of un- needed objects

Slide 185

Slide 185 text

Omniauth Uses Hashie

Slide 186

Slide 186 text

Mitigated in Omniauth #774

Slide 187

Slide 187 text

App still over RAM limit

Slide 188

Slide 188 text

Hypothesis #2

Slide 189

Slide 189 text

Bad gems using too much RAM at require time

Slide 190

Slide 190 text

How do we test?

Slide 191

Slide 191 text

Customer sends me their Gemfile & Gemfile.lock

Slide 192

Slide 192 text

There’s no tooling for benchmarking require memory use

Slide 193

Slide 193 text

Let’s write one!

Slide 194

Slide 194 text

Concept: measure RAM before and after require

Slide 195

Slide 195 text

Use GetProcessMem.new to measure RSS

Slide 196

Slide 196 text

Resident Set Size

Slide 197

Slide 197 text

A close-ish approximation for memory use

Slide 198

Slide 198 text

Doesn’t take into account shared memory

Slide 199

Slide 199 text

Monkey Patch Kernel.require

Slide 200

Slide 200 text

No content

Slide 201

Slide 201 text

active_record/connection_adapters/postgresql_adapter: 2.2734375 active_record/connection_adapters/postgresql_adapter: 2.2734 mb active_record/connection_adapters/postgresql/oid: 0.8555 mb will_paginate/active_record: 1.4921875 will_paginate/active_record: 1.4922 mb active_support/all: 1.01171875 active_support/all: 1.0117 mb active_support/core_ext: 0.9727 mb rack/test: 0.875 rack/test: 0.875 mb /Users/richardschneeman/Documents/projects/codetriage/app/models/user: 0.734375 /Users/richardschneeman/Documents/projects/codetriage/app/models/user: 0.7344 mb /Users/richardschneeman/Documents/projects/codetriage/app/models/repo: 0.50390625 /Users/richardschneeman/Documents/projects/codetriage/app/models/repo: 0.5039 mb new_relic/control/frameworks/rails4: 0.42578125 new_relic/control/frameworks/rails4: 0.4258 mb new_relic/control/frameworks/rails3: 0.3867 mb benchmark/ips: 0.4140625 benchmark/ips: 0.4141 mb will_paginate/view_helpers/action_view: 0.32421875 will_paginate/view_helpers/action_view: 0.3242 mb /Users/richardschneeman/Documents/projects/codetriage/app/models/issue: 0.31640625 /Users/richardschneeman/Documents/projects/codetriage/app/models/issue: 0.3164 mb /Users/richardschneeman/Documents/projects/codetriage/app/models/repo_subscription: 0.2734375 /Users/richardschneeman/.gem/ruby/2.2.1/gems/devise-3.4.1/app/mailers/devise/mailer: 0.265625 sprockets/base: 0.23046875 active_support/cache/dalli_store: 0.22265625 /Users/richardschneeman/Documents/projects/codetriage/app/models/issue_assignment: 0.18359375 /Users/richardschneeman/Documents/projects/codetriage/app/controllers/users/after_signup_controller: 0.18359375 /Users/richardschneeman/.gem/ruby/2.2.1/gems/wicked-1.0.0/app/controllers/wicked/wizard_controller: 0.1796875 /Users/richardschneeman/Documents/projects/codetriage/app/mailers/user_mailer: 0.1796875 /Users/richardschneeman/.gem/ruby/2.2.1/gems/devise-3.4.1/app/controllers/devise/ confirmations_controller: 0.17578125 /Users/richardschneeman/Documents/projects/codetriage/app/controllers/repos_controller: 0.17578125

Slide 202

Slide 202 text

active_record/connection_adapters/postgresql_adapter: 2.2734375 active_record/connection_adapters/postgresql_adapter: 2.2734 mb active_record/connection_adapters/postgresql/oid: 0.8555 mb will_paginate/active_record: 1.4921875 will_paginate/active_record: 1.4922 mb active_support/all: 1.01171875 active_support/all: 1.0117 mb active_support/core_ext: 0.9727 mb rack/test: 0.875 rack/test: 0.875 mb /Users/richardschneeman/Documents/projects/codetriage/app/models/user: 0.734375 /Users/richardschneeman/Documents/projects/codetriage/app/models/user: 0.7344 mb /Users/richardschneeman/Documents/projects/codetriage/app/models/repo: 0.50390625 /Users/richardschneeman/Documents/projects/codetriage/app/models/repo: 0.5039 mb new_relic/control/frameworks/rails4: 0.42578125 new_relic/control/frameworks/rails4: 0.4258 mb new_relic/control/frameworks/rails3: 0.3867 mb benchmark/ips: 0.4140625 benchmark/ips: 0.4141 mb will_paginate/view_helpers/action_view: 0.32421875 will_paginate/view_helpers/action_view: 0.3242 mb /Users/richardschneeman/Documents/projects/codetriage/app/models/issue: 0.31640625 /Users/richardschneeman/Documents/projects/codetriage/app/models/issue: 0.3164 mb /Users/richardschneeman/Documents/projects/codetriage/app/models/repo_subscription: 0.2734375 /Users/richardschneeman/.gem/ruby/2.2.1/gems/devise-3.4.1/app/mailers/devise/mailer: 0.265625 sprockets/base: 0.23046875 active_support/cache/dalli_store: 0.22265625 /Users/richardschneeman/Documents/projects/codetriage/app/models/issue_assignment: 0.18359375 /Users/richardschneeman/Documents/projects/codetriage/app/controllers/users/after_signup_controller: 0.18359375 /Users/richardschneeman/.gem/ruby/2.2.1/gems/wicked-1.0.0/app/controllers/wicked/wizard_controller: 0.1796875 /Users/richardschneeman/Documents/projects/codetriage/app/mailers/user_mailer: 0.1796875 /Users/richardschneeman/.gem/ruby/2.2.1/gems/devise-3.4.1/app/controllers/devise/ confirmations_controller: 0.17578125 /Users/richardschneeman/Documents/projects/codetriage/app/controllers/repos_controller: 0.17578125

Slide 203

Slide 203 text

Now we know what is using memory!

Slide 204

Slide 204 text

mail: 39.2734 mb

Slide 205

Slide 205 text

1 Gem accounts for 65% of total RAM at boot

Slide 206

Slide 206 text

Remember: We haven’t even done any work

Slide 207

Slide 207 text

Dig deeper

Slide 208

Slide 208 text

Requiring a gem requires other files.

Slide 209

Slide 209 text

We need more visibility

Slide 210

Slide 210 text

We need a tree

Slide 211

Slide 211 text

Each node can have many children

Slide 212

Slide 212 text

Each child has a cost

Slide 213

Slide 213 text

Mail mime/types mime/type mime json mail/message YAML net/smtp digest/ md5 timeout net/ protocol

Slide 214

Slide 214 text

No content

Slide 215

Slide 215 text

Sort the children by cost & print recursively

Slide 216

Slide 216 text

No content

Slide 217

Slide 217 text

Final Code

Slide 218

Slide 218 text

No content

Slide 219

Slide 219 text

No content

Slide 220

Slide 220 text

No content

Slide 221

Slide 221 text

No content

Slide 222

Slide 222 text

No content

Slide 223

Slide 223 text

No content

Slide 224

Slide 224 text

No content

Slide 225

Slide 225 text

No content

Slide 226

Slide 226 text

No content

Slide 227

Slide 227 text

Final Result

Slide 228

Slide 228 text

application: 60.8242 mb mail: 39.2734 mb mail/parsers: 19.2461 mb mail/parsers/ragel: 18.7031 mb mail/parsers/ragel/ruby: 18.6797 mb mail/parsers/ragel/ruby/machines/address_lists_machine: 7.2734 mb mail/parsers/ragel/ruby/machines/received_machine: 4.7578 mb mail/parsers/ragel/ruby/machines/envelope_from_machine: 2.2305 mb mail/parsers/ragel/ruby/machines/message_ids_machine: 1.5625 mb mail/parsers/ragel/ruby/machines/date_time_machine: 0.5977 mb mail/parsers/ragel/ruby/machines/content_disposition_machine: 0.4961 mb mail/parsers/ragel/ruby/machines/content_type_machine: 0.4648 mb mail/parsers/ragel/ruby/machines/content_location_machine: 0.3359 mb mail/parsers/ragel/ruby/machines/content_transfer_encoding_machine: 0.3281 mb mail/parsers/ragel/ruby/machines/phrase_lists_machine: 0.3086 mb mime/types: 18.4922 mb mail/field: 0.3125 mb

Slide 229

Slide 229 text

application: 60.8242 mb mail: 39.2734 mb mail/parsers: 19.2461 mb mail/parsers/ragel: 18.7031 mb mail/parsers/ragel/ruby: 18.6797 mb mail/parsers/ragel/ruby/machines/address_lists_machine: 7.2734 mb mail/parsers/ragel/ruby/machines/received_machine: 4.7578 mb mail/parsers/ragel/ruby/machines/envelope_from_machine: 2.2305 mb mail/parsers/ragel/ruby/machines/message_ids_machine: 1.5625 mb mail/parsers/ragel/ruby/machines/date_time_machine: 0.5977 mb mail/parsers/ragel/ruby/machines/content_disposition_machine: 0.4961 mb mail/parsers/ragel/ruby/machines/content_type_machine: 0.4648 mb mail/parsers/ragel/ruby/machines/content_location_machine: 0.3359 mb mail/parsers/ragel/ruby/machines/content_transfer_encoding_machine: 0.3281 mb mail/parsers/ragel/ruby/machines/phrase_lists_machine: 0.3086 mb mime/types: 18.4922 mb mail/field: 0.3125 mb

Slide 230

Slide 230 text

Opened an Issue

Slide 231

Slide 231 text

Fixed in mikel/mail #817

Slide 232

Slide 232 text

Customer’s App RAM use drops dramatically

Slide 233

Slide 233 text

No longer Swapping

Slide 234

Slide 234 text

Went from

Slide 235

Slide 235 text

No content

Slide 236

Slide 236 text

To

Slide 237

Slide 237 text

No content

Slide 238

Slide 238 text

Reproduce the slowness bug

Slide 239

Slide 239 text

Get visibility with benchmarks

Slide 240

Slide 240 text

Use Science!

Slide 241

Slide 241 text

Have you ever made a bad deploy on a Friday?

Slide 242

Slide 242 text

You try to fix it but…

Slide 243

Slide 243 text

No content

Slide 244

Slide 244 text

Your weekend

Slide 245

Slide 245 text

Co-workers weekend

Slide 246

Slide 246 text

Support’s weekend

Slide 247

Slide 247 text

Isn’t there a better way?

Slide 248

Slide 248 text

My proposal:

Slide 249

Slide 249 text

Don’t Deploy on
 Friday

Slide 250

Slide 250 text

Instead

Slide 251

Slide 251 text

Funday Friday

Slide 252

Slide 252 text

Is your app slow?

Slide 253

Slide 253 text

Funday Friday

Slide 254

Slide 254 text

Is your app disorganized ???

Slide 255

Slide 255 text

Funday Friday

Slide 256

Slide 256 text

Do you wish you had more time to refactor?

Slide 257

Slide 257 text

Funday Friday

Slide 258

Slide 258 text

Wish sponsored Open Source?

Slide 259

Slide 259 text

Guess what?

Slide 260

Slide 260 text

Your company just sponsored you!

Slide 261

Slide 261 text

Funday Friday

Slide 262

Slide 262 text

Not sold?

Slide 263

Slide 263 text

More accurate deadlines

Slide 264

Slide 264 text

Less burnout

Slide 265

Slide 265 text

Does your boss want to hire more senior developers?

Slide 266

Slide 266 text

Like the kind that refactors, makes speed improvements, and knows library internals?

Slide 267

Slide 267 text

Train up senior developers instead!

Slide 268

Slide 268 text

Funday Friday Funday Friday

Slide 269

Slide 269 text

Report on your progress to your team

Slide 270

Slide 270 text

Report to your boss

Slide 271

Slide 271 text

Report to twitter #fundayfriday

Slide 272

Slide 272 text

Get ❤️ ❤️ ❤️

Slide 273

Slide 273 text

Give ❤️ ❤️ ❤️

Slide 274

Slide 274 text

Did science build the pyramids?

Slide 275

Slide 275 text

Coincidence?

Slide 276

Slide 276 text

No content