Tweet
Tweet

Slide 1

Slide 1 text

https://flic.kr/p/8RePxD Peeking Into Ruby Tracing Running Code @jasonrclark http://github.com/jasonrclark/ peeking_into_ruby

Slide 2

Slide 2 text

https://flic.kr/p/aVcE68 rbtrace 2 strace tcpdump

Slide 3

Slide 3 text

https://flic.kr/p/8Kj2EC Dig Deeper. 3

Slide 4

Slide 4 text

The Case of The Missing Config File. 4

Slide 5

Slide 5 text

5 https://flic.kr/p/pGP9hG

Slide 6

Slide 6 text

6 https://flic.kr/p/tRhQNP

Slide 7

Slide 7 text

7 https://flic.kr/p/shT4Lr

Slide 8

Slide 8 text

8 $ ./data_streamer ******************************** Loading data stream processor Requiring top_secret gem... ******************************** Hmmm, that's not how I should be configured -- Carl

Slide 9

Slide 9 text

9 https://flic.kr/p/eimYHo

Slide 10

Slide 10 text

https://flic.kr/p/aVcE68 strace 10

Slide 11

Slide 11 text

11 $ strace ./data_streamer

Slide 12

Slide 12 text

No content

Slide 13

Slide 13 text

ETOOMUCHOUTPUT 13

Slide 14

Slide 14 text

execve("/bin/echo", ["echo", "boo"], [/* 14 vars */]) = brk(0) = 0x20f0000 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3 fstat(3, {st_mode=S_IFREG|0644, st_size=30820, ...}) = mmap(NULL, 30820, PROT_READ, MAP_PRIVATE, 3, 0) = close(3) = 0 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No open("/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOE read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0 \34\2\0\0\0\0\0"..., 832) = 832 fstat(3, {st_mode=S_IFREG|0755, st_size=1729984, ...}) mmap(NULL, 3836448, PROT_READ|PROT_EXEC, MAP_PRIVATE|MA mprotect(0x7f676f4e1000, 2097152, PROT_NONE) = 0

Slide 15

Slide 15 text

15 open(“/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3

Slide 16

Slide 16 text

16 open(“/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3

Slide 17

Slide 17 text

17 open(“/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3

Slide 18

Slide 18 text

18 open(“/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3

Slide 19

Slide 19 text

A Brief Interlude. 19

Slide 20

Slide 20 text

20 Kernel User

Slide 21

Slide 21 text

21 https://flic.kr/p/5J1zrp

Slide 22

Slide 22 text

22 https://flic.kr/p/4L4zvH

Slide 23

Slide 23 text

23 Kernel User syscalls

Slide 24

Slide 24 text

exec fork exit 24 open read write close

Slide 25

Slide 25 text

25 $ man open 2

Slide 26

Slide 26 text

OPEN(2) Linux Programmer's Manual NAME open, openat - open and possibly create a file SYNOPSIS #include #include #include int open(const char *pathname, int flags); int open(const char *pathname, int flags); DESCRIPTION Given a pathname for a file, open() returns a file descriptor, a small, nonnegative integer for use i subsequent system calls (read(2), write(2), lseek( fcntl(2), etc.). The file descriptor returned by successful call will be the lowest-numbered file descriptor not currently open for the process.

Slide 27

Slide 27 text

27 Kernel User syscalls strace

Slide 28

Slide 28 text

https://flic.kr/p/8Kj2EC Look For Landmarks. 28

Slide 29

Slide 29 text

29 $ ./data_streamer ******************************** Loading data stream processor Requiring top_secret gem... ******************************** Hmmm, that's not how I should be configured -- Carl

Slide 30

Slide 30 text

30 getcwd("/usr/src/app", 4096) = 13 lstat("/usr", {st_mode=S_IFDIR|0755, lstat("/usr/src", {st_mode=S_IFDIR|0755, lstat("/usr/src/app", {st_mode=S_IFDIR|0755, lstat("/usr/src/app/missing_config", {st_mo getcwd("/usr/src/app", 4096) = 13 write(1,"****************************"..., 50*****************************) = 50 write(1,"\n", 1) = 1 write(1,"Loading data stream processor", 29Loading data stream processor) = 29 fstat(7, {st_mode=S_IFREG|0644, st_size=127, close(7) = 0 getuid() = 0 geteuid() = 0 getgid() = 0 getegid() = 0

Slide 31

Slide 31 text

31 fstat(7, {st_mode=S_IFREG|0644, st_size=12 ioctl(7, SNDCTL_TMR_TIMEBASE or SNDRV_TIMER_-1 ENOTTY (Inappropriate read(7, "begin\n File.read(\”/usr/local/sl read(7, "", 8192) = 0 close(7) = 0 lstat("/usr", {st_mode=S_IFDIR|0755, st_size= lstat("/usr/src", {st_mode=S_IFDIR|0755, st write(1, "Hmmm, that's not how I"..., 51Hmmm, that's not how I...) = 51 write(1, "\n", 1) = 1 rt_sigaction(SIGINT, {SIG_IGN, [], SA_RESTO rt_sigaction(SIGINT, {SIG_DFL, [],SA_RESTO write(4, "!", 1) = 1 munmap(0x7fdaf91a4000, 1052672) = 0 exit_group(666) = ? +++ exited with 154 +++

Slide 32

Slide 32 text

32 open(“/usr/local/slurp.confi”, O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)

Slide 33

Slide 33 text

33 open(“/usr/local/slurp.confi”, O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)

Slide 34

Slide 34 text

slurp.confi? 34

Slide 35

Slide 35 text

Resources 35 Julia Evans: blog and zine http://jvns.ca/blog/categories/strace/ James Golick: How to Debug Anything https://www.youtube.com/watch?v=VV7b7fs4VI8

Slide 36

Slide 36 text

The Case of The Unused Method 36

Slide 37

Slide 37 text

… Or Was It? 37

Slide 38

Slide 38 text

38 https://flic.kr/p/dmb7sW

Slide 39

Slide 39 text

39 https://flic.kr/p/a4VW2z

Slide 40

Slide 40 text

40 add_method_tracer

Slide 41

Slide 41 text

41 https://flic.kr/p/3LP9cm

Slide 42

Slide 42 text

https://flic.kr/p/8Kj2EC Proper Preparation. 42

Slide 43

Slide 43 text

https://flic.kr/p/aVcE68 rbtrace 43

Slide 44

Slide 44 text

44 Ruby VM Our Code rbtrace

Slide 45

Slide 45 text

45 $ rbtrace --methods puts --exec ./script.rb puts puts ...

Slide 46

Slide 46 text

46 # code.rb require ‘rbtrace’ $ ruby code.rb & $ rbtrace -p PID --methods puts puts puts

Slide 47

Slide 47 text

47 $ rbtrace -p PID --methods Custom#goo > custom_goo.log

Slide 48

Slide 48 text

48 ls -la custom_goo.log -rw-r--r-- 1 0 Sep 30 22:12 goo.log

Slide 49

Slide 49 text

The Case of The Occasional Lag 49

Slide 50

Slide 50 text

50 Heartbeats Received background job starts

Slide 51

Slide 51 text

https://flic.kr/p/aVcE68 rbtrace 51

Slide 52

Slide 52 text

52 $ rbtrace -p PID --gc -t 05:54:28.10610 Running background job 05:54:28.11113 garbage_collect 05:54:28.56664 garbage_collect 05:54:33.72790 garbage_collect

Slide 53

Slide 53 text

53

Slide 54

Slide 54 text

Resources 54 Aman Gupta: github https://github.com/tmm1/rbtrace Justin Weiss: How to Debug Ruby Performance Problems in Production http://www.justinweiss.com/blog/2015/04/06/how-to- debug-ruby-performance-problems-in-production/

Slide 55

Slide 55 text

The Case of The Delicate Negotiations 55

Slide 56

Slide 56 text

56 https://flic.kr/p/d8Kvyo

Slide 57

Slide 57 text

57 url = "https://www.google.com/" uri = URI.parse(url) response = Net::HTTP.get_response(uri) ... response = Net::HTTP.get_response(uri)

Slide 58

Slide 58 text

58 url = "https://www.google.com/" uri = URI.parse(url) conn = Net::HTTP.new(uri.host, uri.port) conn.use_ssl = true conn.keep_alive_timeout = 60 conn.start request = Net::HTTP::Get.new('/') response = conn.request(request) ... response = conn.request(request)

Slide 59

Slide 59 text

59 url = "https://www.google.com/" uri = URI.parse(url) conn = Net::HTTP.new(uri.host, uri.port) conn.use_ssl = true conn.keep_alive_timeout = 60 conn.start request = Net::HTTP::Get.new('/') response = conn.request(request) ... response = conn.request(request)

Slide 60

Slide 60 text

60 url = "https://www.google.com/" uri = URI.parse(url) conn = Net::HTTP.new(uri.host, uri.port) conn.use_ssl = true conn.keep_alive_timeout = 60 conn.start request = Net::HTTP::Get.new('/') response = conn.request(request) ... response = conn.request(request)

Slide 61

Slide 61 text

https://flic.kr/p/aVcE68 tcpdump 61

Slide 62

Slide 62 text

62 Network Stack Our Code tcpdump

Slide 63

Slide 63 text

https://flic.kr/p/8Kj2EC Find Boundaries. 63

Slide 64

Slide 64 text

64 Network Stack Our Code Kernel

Slide 65

Slide 65 text

65 $ tcpdump

Slide 66

Slide 66 text

66 17:29:36.569760 IP a6a0111ae486.38923 > nuq05s02-in- f16.1e100.net.https: Flags [S], seq 290609768, win 29200, options [mss 1460,sackOK,TS val 486029 ecr 0,nop,wscale 7], length 0 17:29:36.595921 IP nuq05s02-in-f16.1e100.net.https > a6a0111ae486.38923: Flags [S.], seq 651712001, ack 290609769, win 65535, options [mss 1460], length 0 17:29:36.595996 IP a6a0111ae486.38923 > nuq05s02-in- f16.1e100.net.https: Flags [.], ack 1, win 29200, length 0 17:29:36.596658 IP a6a0111ae486.38923 > nuq05s02-in- f16.1e100.net.https: Flags [P.], seq 1:251, ack 1, win 29200, length 250 17:29:36.596937 IP nuq05s02-in-f16.1e100.net.https > a6a0111ae486.38923: Flags [.], ack 251, win 65535, length 0

Slide 67

Slide 67 text

ETOOMUCHOUTPUT 67

Slide 68

Slide 68 text

68 17:29:36.569760 IP a6a0111ae486.38923 > nuq05s02-in- f16.1e100.net.https: Flags [S], seq 290609768, win 29200, options [mss 1460,sackOK,TS val 486029 ecr 0,nop,wscale 7], length 0 17:29:36.595921 IP nuq05s02-in-f16.1e100.net.https > a6a0111ae486.38923: Flags [S.], seq 651712001, ack 290609769, win 65535, options [mss 1460], length 0 17:29:36.595996 IP a6a0111ae486.38923 > nuq05s02-in- f16.1e100.net.https: Flags [.], ack 1, win 29200, length 0 17:29:36.596658 IP a6a0111ae486.38923 > nuq05s02-in- f16.1e100.net.https: Flags [P.], seq 1:251, ack 1, win 29200, length 250 17:29:36.596937 IP nuq05s02-in-f16.1e100.net.https > a6a0111ae486.38923: Flags [.], ack 251, win 65535, length 0

Slide 69

Slide 69 text

69 17:29:36.569760 IP a6a0111ae486.38923 > nuq05s02-in-f16.1e100.net.https: Flags [S], seq 290609768, win 29200, options [mss 1460,sackOK,TS val 486029 ecr 0,nop,wscale 7], length 0

Slide 70

Slide 70 text

70 17:29:36.569760 IP a6a0111ae486.38923 > nuq05s02-in-f16.1e100.net.https: Flags [S], seq 290609768, win 29200, options [mss 1460,sackOK,TS val 486029 ecr 0,nop,wscale 7], length 0

Slide 71

Slide 71 text

71 17:29:36.569760 IP a6a0111ae486.38923 > nuq05s02-in-f16.1e100.net.https: Flags [S], seq 290609768, win 29200, options [mss 1460,sackOK,TS val 486029 ecr 0,nop,wscale 7], length 0 a6a0111ae486.38923 == me nuq05s02-in-f16.1e100.net.https == google

Slide 72

Slide 72 text

72 17:29:36.569760 IP a6a0111ae486.38923 > nuq05s02-in-f16.1e100.net.https: Flags [S], seq 290609768, win 29200, options [mss 1460,sackOK,TS val 486029 ecr 0,nop,wscale 7], length 0

Slide 73

Slide 73 text

73 Flags [S] - SYN (Start Connection) [.] - No Flag Set [P] - PSH (Push Data) [F] - FIN (Finish Connection)

Slide 74

Slide 74 text

74 17:29:36.569760 IP a6a0111ae486.38923 > nuq05s02-in-f16.1e100.net.https: Flags [S], seq 290609768, win 29200, options [mss 1460,sackOK,TS val 486029 ecr 0,nop,wscale 7], length 0

Slide 75

Slide 75 text

75 url = "https://www.google.com/" uri = URI.parse(url) response = Net::HTTP.get_response(uri)

Slide 76

Slide 76 text

76 17:29:36 IP me > google: Flags [S], seq 290609768, win 17:29:36 IP google > me: Flags [S.], seq 651712001, ac 17:29:36 IP me > google: Flags [.], ack 1, win 29200, 17:29:36 IP me > google: Flags [P.], seq 1:251, ack 1, 17:29:36 IP google > me: Flags [.], ack 251, win 65535 17:29:36 IP google > me: Flags [P.], seq 1:1289, ack 2 17:29:36 IP me > google: Flags [.], ack 1289, win 3091 17:29:36 IP google > me: Flags [P.], seq 1289:2577, ac … 24 times 17:29:36 IP google > me: Flags [.], seq 10110:11530, a 17:29:36 IP me > google: Flags [.], ack 11530, win 568 17:29:36 IP google > me: Flags [P.], seq 11530:12169, 17:29:36 IP me > google: Flags [P.], seq 535:566, ack 17:29:36 IP me > google: Flags [F.], seq 566, ack 1216 17:29:36 IP google > me: Flags [.], ack 566, win 65535 17:29:36 IP google > me: Flags [.], ack 567, win 65535 17:29:36 IP google > me: Flags [F.], seq 12169, ack 56 17:29:36 IP me > google: Flags [.], ack 12170, win 596

Slide 77

Slide 77 text

77 17:29:36 IP me > google: Flags [S], seq 290609768, win 17:29:36 IP google > me: Flags [S.], seq 651712001, ac 17:29:36 IP me > google: Flags [.], ack 1, win 29200, 17:29:36 IP me > google: Flags [P.], seq 1:251, ack 1, 17:29:36 IP google > me: Flags [.], ack 251, win 65535 17:29:36 IP google > me: Flags [P.], seq 1:1289, ack 2 17:29:36 IP me > google: Flags [.], ack 1289, win 3091 17:29:36 IP google > me: Flags [P.], seq 1289:2577, ac … 24 times 17:29:36 IP google > me: Flags [.], seq 10110:11530, a 17:29:36 IP me > google: Flags [.], ack 11530, win 568 17:29:36 IP google > me: Flags [P.], seq 11530:12169, 17:29:36 IP me > google: Flags [P.], seq 535:566, ack 17:29:36 IP me > google: Flags [F.], seq 566, ack 1216 17:29:36 IP google > me: Flags [.], ack 566, win 65535 17:29:36 IP google > me: Flags [.], ack 567, win 65535 17:29:36 IP google > me: Flags [F.], seq 12169, ack 56 17:29:36 IP me > google: Flags [.], ack 12170, win 596

Slide 78

Slide 78 text

78 17:29:36 IP me > google: Flags [S], seq 290609768, win 17:29:36 IP google > me: Flags [S.], seq 651712001, ac 17:29:36 IP me > google: Flags [.], ack 1, win 29200, 17:29:36 IP me > google: Flags [P.], seq 1:251, ack 1, 17:29:36 IP google > me: Flags [.], ack 251, win 65535 17:29:36 IP google > me: Flags [P.], seq 1:1289, ack 2 17:29:36 IP me > google: Flags [.], ack 1289, win 3091 17:29:36 IP google > me: Flags [P.], seq 1289:2577, ac … 24 times 17:29:36 IP google > me: Flags [.], seq 10110:11530, a 17:29:36 IP me > google: Flags [.], ack 11530, win 568 17:29:36 IP google > me: Flags [P.], seq 11530:12169, 17:29:36 IP me > google: Flags [P.], seq 535:566, ack 17:29:36 IP me > google: Flags [F.], seq 566, ack 1216 17:29:36 IP google > me: Flags [.], ack 566, win 65535 17:29:36 IP google > me: Flags [.], ack 567, win 65535 17:29:36 IP google > me: Flags [F.], seq 12169, ack 56 17:29:36 IP me > google: Flags [.], ack 12170, win 596

Slide 79

Slide 79 text

79 17:29:36 IP me > google: Flags [S], seq 290609768, win 17:29:36 IP google > me: Flags [S.], seq 651712001, ac 17:29:36 IP me > google: Flags [.], ack 1, win 29200, 17:29:36 IP me > google: Flags [P.], seq 1:251, ack 1, 17:29:36 IP google > me: Flags [.], ack 251, win 65535 17:29:36 IP google > me: Flags [P.], seq 1:1289, ack 2 17:29:36 IP me > google: Flags [.], ack 1289, win 3091 17:29:36 IP google > me: Flags [P.], seq 1289:2577, ac … 24 times 17:29:36 IP google > me: Flags [.], seq 10110:11530, a 17:29:36 IP me > google: Flags [.], ack 11530, win 568 17:29:36 IP google > me: Flags [P.], seq 11530:12169, 17:29:36 IP me > google: Flags [P.], seq 535:566, ack 17:29:36 IP me > google: Flags [F.], seq 566, ack 1216 17:29:36 IP google > me: Flags [.], ack 566, win 65535 17:29:36 IP google > me: Flags [.], ack 567, win 65535 17:29:36 IP google > me: Flags [F.], seq 12169, ack 56 17:29:36 IP me > google: Flags [.], ack 12170, win 596

Slide 80

Slide 80 text

80 url = "https://www.google.com/" uri = URI.parse(url) conn = Net::HTTP.new(uri.host, uri.port) conn.use_ssl = true conn.keep_alive_timeout = 60 conn.start request = Net::HTTP::Get.new('/') response = conn.request(request) ... response = conn.request(request)

Slide 81

Slide 81 text

81 17:58:12 IP me > google: Flags [S], seq 290609768, win 17:58:12 IP google > me: Flags [S.], seq 651712001, ac 17:58:12 IP me > google: Flags [.], ack 1, win 29200, 17:58:12 IP me > google: Flags [P.], seq 1:251, ack 1, 17:58:12 IP google > me: Flags [.], ack 251, win 65535 17:58:12 IP google > me: Flags [P.], seq 1:1289, ack 2 17:58:12 IP me > google: Flags [.], ack 1289, win 3091 17:58:12 IP google > me: Flags [P.], seq 1289:2577, ac … 24 times 17:58:12 IP google > me: Flags [.], seq 10110:11530, a 17:58:12 IP me > google: Flags [.], ack 11530, win 568 17:58:12 IP google > me: Flags [P.], seq 11530:12169, 17:58:12 IP me > google: Flags [P.], seq 535:566, ack 17:58:12 IP me > google: Flags [.], ack 12170, win 596 No Flags [F]!

Slide 82

Slide 82 text

82 17:48:18 IP me > google: Flags [P.], seq 693:851, ack 17:48:18 IP google > me: Flags [.], ack 851, win 65535 17:48:18 IP google > me: Flags [P.], seq 20688:21976, 17:48:18 IP me > google: Flags [.], ack 21976, win 653 17:48:18 IP google > me: Flags [.], seq 21976:23396, a 17:48:18 IP me > google: Flags [.], ack 23396, win 653 17:48:18 IP google > me: Flags [.], seq 23396:24816, a 17:48:18 IP me > google: Flags [.], ack 24816, win 653 17:48:18 IP google > me: Flags [P.], seq 24816:25840, 17:48:18 IP me > google: Flags [.], ack 25840, win 653 17:48:18 IP google > me: Flags [.], seq 25840:27260, a 17:48:18 IP me > google: Flags [.], ack 27260, win 653 17:48:18 IP google > me: Flags [.], seq 27260:28680, a 17:48:18 IP me > google: Flags [.], ack 28680, win 653 17:48:18 IP google > me: Flags [P.], seq 28680:29109, 17:48:18 IP me > google: Flags [.], ack 29109, win 653

Slide 83

Slide 83 text

83 17:48:18 IP me > google: Flags [P.], seq 693:851, ack 17:48:18 IP google > me: Flags [.], ack 851, win 65535 17:48:18 IP google > me: Flags [P.], seq 20688:21976, 17:48:18 IP me > google: Flags [.], ack 21976, win 653 17:48:18 IP google > me: Flags [.], seq 21976:23396, a 17:48:18 IP me > google: Flags [.], ack 23396, win 653 17:48:18 IP google > me: Flags [.], seq 23396:24816, a 17:48:18 IP me > google: Flags [.], ack 24816, win 653 17:48:18 IP google > me: Flags [P.], seq 24816:25840, 17:48:18 IP me > google: Flags [.], ack 25840, win 653 17:48:18 IP google > me: Flags [.], seq 25840:27260, a 17:48:18 IP me > google: Flags [.], ack 27260, win 653 17:48:18 IP google > me: Flags [.], seq 27260:28680, a 17:48:18 IP me > google: Flags [.], ack 28680, win 653 17:48:18 IP google > me: Flags [P.], seq 28680:29109, 17:48:18 IP me > google: Flags [.], ack 29109, win 653 ~15 packets No New Connection

Slide 84

Slide 84 text

84

Slide 85

Slide 85 text

Resources 85 Benjamin Cane: A Quick and Practical Reference for tcpdump http://bencane.com/2014/10/13/quick-and-practical- reference-for-tcpdump/ Jonan Scheffler: Lifecycle of a Web Request https://www.youtube.com/watch?v=U-4md8lYosk

Slide 86

Slide 86 text

86 https://flic.kr/p/ahkHU8

Slide 87

Slide 87 text

https://flic.kr/p/aVcE68 rbtrace 87 strace tcpdump

Slide 88

Slide 88 text

https://flic.kr/p/8Kj2EC Dig Deeper. 88

Slide 89

Slide 89 text

https://flic.kr/p/8Kj2EC Look For Landmarks. 89

Slide 90

Slide 90 text

https://flic.kr/p/8Kj2EC Proper Preparations. 90

Slide 91

Slide 91 text

https://flic.kr/p/8Kj2EC Find Boundaries. 91

Slide 92

Slide 92 text

Case Closed! 92 https://github.com/jasonrclark/ peeking_into_ruby @jasonrclark