Practical Debugging

RailsConf 2017: Practical Debugging by Kevin Deisz

People give ruby a bad reputation for speed, efficiency, weak typing, etc. But one of the biggest benefits of an interpreted language is the ability to debug and introspect quickly without compilation. Oftentimes developers reach for heavy-handed libraries to debug their application when they could just as easily get the information they need by using tools they already have.

In this talk you will learn practical techniques to make debugging easier. You will see how simple techniques from the ruby standard library can greatly increase your ability to keep your codebase clean and bug-free.

RailsConf 2017

00:00:00.760 [Music]
00:00:12.259 okay so it's 4:30 so we're gonna get started so hi this is practical
00:00:19.380 debugging if you're here for some of the things then I'm sorry but you're going
00:00:24.869 to learn how to debug so debugging in Ruby it's fun it's a fun
00:00:30.000 thing this is what happened to get stacktrace you get a stack trace and what do you do I ask my co-workers and
00:00:36.420 this is the best response that I got usually cursed audibly frightening my
00:00:42.270 co-workers that was the best I got and then there was silence in the flacc channel for like a solid two days and
00:00:49.520 then someone asked about like I don't know something else completely different and I think this is actually a kind of a
00:00:57.570 good reason for this talk people don't
00:01:02.640 know how to debug in Ruby they they pull in tools they pull in all kinds of
00:01:08.040 dependencies they pull in all kinds of things that they usually don't need you
00:01:13.049 you get what you need when you download Ruby so standard practice when you have
00:01:20.460 a question about what to do what do you do your main calm and you ask what would suck overflow do this is stack overflow
00:01:27.840 different development or hashtag WWSD and stack overflows has to do two things
00:01:33.869 it says to use pry and it says to use by bug stack overflow really like to
00:01:40.619 suggest using these tools they suggest it all the time use pry use probably use
00:01:46.740 pry especially like this one that says use IRB and in the first comment is
00:01:51.780 prize more efficient than IRB because I guess I don't know all the story at the
00:01:59.700 end of the day people want bug-free code they don't care how it got that way you could you could use I don't care it
00:02:06.990 doesn't matter and you don't get style point in debugging but this one is
00:02:12.090 actually really hard for me I live and die by my winter I don't know
00:02:17.909 if you guys are like that not a lot of people tend to be but I just love clean
00:02:23.129 efficient syntax I really don't care if it's functioning correctly I want to look good just wanted to look good and
00:02:29.750 so I have problems because when I'm debugging all that code is going away
00:02:35.459 and you have the freedom to say it it doesn't matter just delete the code it's going to go away anyway and so you
00:02:41.879 can do all kinds of crazy stuff and so you have to get over yourself you have
00:02:47.849 to get over the fact that the codes going away you can do whatever you want my point in giving this talk my whole
00:02:54.239 thing is that the Ruby standard library has every tool you need to debug effectively you have pry you can use
00:03:01.590 price I don't care if you use probably feel free it's wonderful on the other side of that there are tools that are
00:03:07.409 available to you that are criminally underused and so I'm going to walk you through a couple of those the point of
00:03:13.019 this talk is not to give you every single possible tool to solve every single possible problem the point of
00:03:18.540 this talk is to give you a diving board is to just show you the places where you
00:03:24.540 can start your journey through debugging these processes and to walk you through
00:03:30.840 a couple of the tools that I use pre standard pretty pretty often to solve
00:03:36.030 these problems so first question you ask yourself oh I'm sorry
00:03:41.220 backing up I needed an example application just to debug over the course of this talk so I wrote a little
00:03:47.720 minesweeper is that one familiar with minesweeper Yes No maybe okay I'm going
00:03:53.489 to show it to you live demo time so [Music]
00:03:59.329 here's minesweeper it's it's in Ruby can
00:04:05.190 everyone see that kind of maybe and you like click right and then you can tell them where the mines are and if you
00:04:12.239 click a bad mine then you lose it says you lose and then you can do the same
00:04:17.940 thing I allowed you to specify the width and the height and the number of mine so this only has one so you should you
00:04:24.930 should be fine and then
00:04:34.470 thank you thanks for coming yeah okay let's try that again yeah we
00:04:42.280 click and then it says you win there we go much better okay what are the odds
00:04:49.990 right what are the odds could never tell no way to tell
00:04:55.180 so this talk goes pretty quickly it has a lot of code examples and I'm going to run through them pretty quickly don't
00:05:01.840 panic all of the examples are up on the github repo that I'll give you the link afterwards so you pay attention now and
00:05:08.620 you can go back and redo all of them and it gives you tons and tons of links and tons into the Preferences so don't start
00:05:14.860 scrambling but I am going to go to the event examples too quickly so first question you asked what kind of problem
00:05:20.229 are you solving I'm going to define three kinds of problems that we're going to work through the first is going to be
00:05:25.300 an interface problem second is going to be a state problem there is gonna be a flow problem so interface problems first kind of
00:05:32.440 problems interface problems occur when you don't understand the dependent structure of methods or constants
00:05:38.430 methods have structure they have a return value that is a type they have or
00:05:43.870 sometimes multiple types they have parameters they have the order of those parameters they have the types of those parameters all things like that
00:05:49.960 constants have methods defined on them they have a ancestry they have descendants they have all kinds of
00:05:56.110 things so interface problems occur when you don't understand the dependence structure of methods or constants you
00:06:02.530 have to know these things in your code you're making certain assumptions every time you call a function or reference a
00:06:07.810 concept to that matter interface problems answer questions like why is this thing nil right this is like the most common thing that I find undefined
00:06:15.250 method blah blah blah or nil so we're going to fall walk through that why can't I call the methods that I want
00:06:21.340 well the constants I can reference what can this object see in view and oh god oh god what is this gem even doing and
00:06:27.970 in true millennial fashion I can't eat them so first question why is this thing
00:06:33.310 now so we're in the mind super code we get this no implicit conversion from nil
00:06:39.190 to integer right here so let's go into this code a little bit the error is on this line and
00:06:47.259 it says no 1 plus a conversion from nil and to integer so neighbor is nil
00:06:52.729 because it's trying to coerce that and into an integer that can reference inside of the array and so we say okay
00:06:59.539 neighbor is nil so neighbor is an element of neighbors why is neighbors have nil in it we go to this neighbors
00:07:05.930 for neighbors fours to find here neighbors for called index for and index score is defined here and pretty quickly
00:07:12.710 you can see the problem it's that giant return nil if statement and you know
00:07:19.820 while this is a little bit contrived the neighbors for method assumed that
00:07:24.949 integers were being returned the index for method does not have that signature
00:07:30.520 now in Ruby we get def in other languages you might have option in toward optional inter maybe int or
00:07:37.130 whatever int in this case you get def that is what you get and it's on you the
00:07:43.729 onus is on you to take care of this type signature and it's implicit it's not
00:07:49.460 there you are trading this up you get to say death and you don't care what gets returned in most cases this is wonderful
00:07:56.539 this is quick this is very very fast this gets you to mark it and then later down the road you know like a year you
00:08:03.560 get a honey badger because you didn't take care of the whole type signature so in this case that's actually pretty easy
00:08:09.470 we had dot compact there it gets rid all the nails and everything's great so basically if anything is ever nailed
00:08:15.320 it's add to compact your client total lie moving right along why can't I call the
00:08:22.460 method that I want let's see we get this error and we get this and this is our
00:08:28.639 clue rescue and method missing you might also get undefined method either one
00:08:33.919 this tells you okay we're trying to call something that doesn't exist so let's go
00:08:39.169 to the first line of the stack trace that we control we go to the board we get this build status label method this
00:08:44.990 is where our error is coming from we have that a door reader there and we're like hey we should be able to call this thing because it exists right so what we
00:08:53.630 going to do so we're add some debugging method some debugging code are we going here and we're going
00:08:59.210 to call the methods method this can give you an array of symbols that's going to tell you everything you can possibly call we're going to print that out with
00:09:05.330 P P is a great method it's effectively this but instead this right it's puts
00:09:11.270 inspect but instead of okay you got it we're going to exit immediately you want to keep the feedback loops as quick as
00:09:17.300 possible right you don't want your application just keep running just get the information you need immediately and finally we're going to grep through the
00:09:23.720 methods and try to find the method that we need and we're just going to output that all to the terminal so running that code we get this the first array is
00:09:30.500 array where we were looking for the thing and second ray is all the methods obviously we didn't write all these methods so clearly the scope inside of
00:09:37.820 that block has changed we go back to our code to get dirty our debugging information and we can find out that in
00:09:43.820 fact self has changed in this block that kind of makes sense it could have include in by the fact that text and grid are not message that we've actually
00:09:49.460 defined we take this lexical scope inside of Ruby has reference to local
00:09:56.120 variables when the block was defined so we take that text mind Minds left and column span width about the local
00:10:02.420 variables and everybody's happy now this example thing to remember we use the
00:10:08.330 methods method right found everything we need real quick good debugging excellent moving on what are the constants like in
00:10:14.720 reference this one is kind of fun because people at people tend to forget
00:10:22.580 that constant lookup is not the same as ancestry inside of Ruby it's they're
00:10:28.610 different things so let's look at this example let's say we refactored our cells that have different hierarchy and
00:10:35.150 we decided okay we're going to have these cell mine and the cell neighbor and this cell empty and they're all going to take care of their own needs
00:10:41.240 and whatever in this case we think this is great and we go and we run the code
00:10:47.210 and we say oh I'll initialize constant mind super base to go back into our code and the tool that we're going to reach
00:10:52.940 for this time is module dot nesting module dot nesting is a method that's going to tell you exactly what
00:10:59.480 namespaces you have access to within this current lexical scope so if you run this code where I can get minesweeper
00:11:05.660 and that's all we're going to get or go back into this code what this is saying is that we only have reference to
00:11:12.760 the top-level constants which can be always reference and the constants directly defined underneath the module
00:11:19.220 namespace so in this case you go to that first definition class cell mind
00:11:24.470 descends from base base is not mine super base base is mine super cell base right so we do a little bit of
00:11:30.800 refactoring we move these guys on in move that up run it again and you get
00:11:36.080 mine super cell and minesweeper right so you can see from this code how you can
00:11:41.390 now access the base class and the other definitions that things good so what can
00:11:48.740 this object see and do this one's fun so there's all kinds of introspection tools that are relatively available to you
00:11:56.020 this is just something that's a couple lines of code to tell you every single constant that's finding a project right
00:12:02.450 we do a couple things so we can print out the name of the constant we can look at the constants write constants is a
00:12:07.820 method that's defined on constants on modules for that matter we can iterate through them and we can call constant
00:12:14.210 get to get something by a symbol it will give us an object we can then iterate through that recursively and get all of
00:12:19.490 our information and we run it on our project it's pretty boring it tells you
00:12:24.740 three constants but you know you can do things like run it on active record and get every single active record constant
00:12:29.750 there is probably not immediately avail what the value of this is but being able
00:12:36.500 to iterate through constants very quickly is very very useful especially when you're dealing with reloading like
00:12:43.280 hot reloading with rails and something hasn't been loaded sync STI where you want to iterate over the descendant
00:12:49.250 classes and not all of them have been loaded this is very very useful for that kind of debugging we can also find out
00:12:55.910 everything that we can call on an object so you can list its instance methods right this right here this instance
00:13:02.660 method function is going to give us an array of all the of symbols that represent those methods and they can use
00:13:08.570 even we don't even have to load up code we can do this on the command line right that - I is going to add the Lib
00:13:14.450 directory to our auto load path or to the load path for Ruby the R is going to require it - EE is going to evaluate it
00:13:21.080 and we get all this goodness we can do the same thing for instance methods that are just defined on this class and not inherited
00:13:27.330 same thing for private instance methods and the same thing for private in some instance methods that are justified on this class all this information is
00:13:33.960 available to you from the command line it's like 40 lines worth of typing 40
00:13:39.630 characters worth of typing try to get that with other languages it's not the easiest right this is quick
00:13:45.960 introspection and this is some of the fastest feedback loop you're going to get finally we get to my favorite oh god
00:13:53.339 oh god what is this gem even doing let's say we get this this error message
00:13:59.220 ambiguous option column never mind the fact that you probably can spell but
00:14:04.620 we're going to go with this example for a minute let's go to so we what we could do we
00:14:11.010 could go to the code from our side we can also go to the code from the
00:14:16.350 vendored gem side so we're going to do that so first line we control we go in
00:14:21.750 and we find out okay this is actually calling if you remember from the lexical scope example earlier the TK little grid
00:14:27.300 method so to go into our command line we say all right let's get that TK method
00:14:32.670 grid and then let's get the source location source location method instance
00:14:39.360 method that will give you back a method object the method objects then has metadata that on it that you can get
00:14:45.420 right source location is going to tell you okay this is the exact file on your system where this where this function is
00:14:52.020 defined and this is the exact line inside of that file so you can go quickly and find it we find okay well
00:14:59.910 looks this is this is defined here this is calling out to the TK grid method so
00:15:06.000 let's go and get that repeat the process only difference here is that it's not an instance method it's a class methods we
00:15:11.820 use the method method instead of the instance method method or you're tired of hearing me say method yes and we can
00:15:17.459 repeat the same process you can go into the code we see okay this is what it's actually doing right try to do this with
00:15:23.880 a jar enjoy yourself this is we know that the error comes from this line and
00:15:30.000 we know that params is being passed into this so let's just go ahead and print out params and hopefully at this point it's now
00:15:37.390 become evidence that column is misspelled and you can go into your code and fix the bug yeah at the end of the
00:15:46.720 day when you're done messing with all of your vendor gem you don't want to leave them in that state bundle exec gem
00:15:52.390 pristine will restore that to the state that when you downloaded the gem originally you can also do dash dash all
00:15:58.900 and now over just clean your whole your whole jump file so lessons learned from
00:16:06.790 interface problems account for every return type you don't have a compiler
00:16:11.830 you don't have something telling you okay this can return these kinds of types and you need to go one by one and
00:16:18.370 take care of them there are no sealed traits here right account for constant method lookup you need to make sure that
00:16:24.970 you know what lexical scope you're in you need to know make sure that you know what you can reference on the other side
00:16:30.580 of that take advantage of constant method introspection you have these tools at your fingertips you can use
00:16:35.680 these very quickly and when you don't use them you're giving up one of the greatest assets you have for having
00:16:41.170 chosen Ruby as your language of choice and finally take advantage of the fact that gems aren't byte code right they're
00:16:47.470 not they're not compiled you can do anything you want to them you can go and delete files and see what happens if
00:16:53.920 nothing else you can use them as an educational opportunity just to go in see what kind of problems they were solving and to see how they solve those
00:16:59.920 problems and you know I mean this is one of the best ways to learn Ruby you have all those files already downloaded to
00:17:05.350 your systems they're right there it's great so use them state problems so
00:17:18.540 state problems state problems occur when the assumptions you made about the current state of the program are
00:17:24.280 incorrect that might seem overly generically broad but what I'm basically saying here is
00:17:30.040 that the internal state of every object in your system that's living and breathing inside of your memory as it's
00:17:36.640 been allocated what assumptions are you making at each point in code that may not be correct they answer questions
00:17:43.630 like how does this value change at this point what has been initialized at this point and how many objects are allocated in
00:17:50.450 this method or within this lexical scope so first one how does this value change
00:17:56.330 at this point we go into this code we say ok button dot text is changing and let's say it's changing to something
00:18:02.029 that we don't like it's changing to some I don't know foo bar or something that we that we don't know why we can go in
00:18:08.419 and figure out exactly what's happening very very quickly and we're going to add some introspection code here to figure
00:18:13.580 out exactly how so we're going to use the instance variables method that goes and lists an array of symbols again
00:18:20.690 defining every single instance method that's been initialized on this object we can then map over that and use
00:18:26.629 instance variable get to get the value we can then create a hash out of that and put it out to the command-line and
00:18:31.970 finally we can get the current state of the text in the new state of the text and get all that information when we run
00:18:39.710 it we get a hash with the keys seeing the instance stars the value seeing the
00:18:46.999 actual value of those and the state being outputted well this may seem relatively trivial just to get this
00:18:53.509 information that was like six lines of code to tell you exactly the state of your object and it was painless to put
00:19:00.649 in right I use two methods that I had to know about instance methods and instance
00:19:06.200 variables and instance variable get that kind of information is relatively easy
00:19:11.570 to remember right you don't need to think about some kind of introspection API with multiple objects and try to use
00:19:18.440 some kind of compiler macro to try to get your information available to you this is very very quick what has been
00:19:26.600 initialized at this point similar to the last one let's say we get undefined method count for nil class we go into
00:19:34.190 our our code and we see all right cells is nil why is cells nil it could be nil for two
00:19:40.009 reasons one we forgot to initialize it or it wasn't yet initialized at this point two it was it was already
00:19:46.909 initialized and it got mutated somehow and now it's nil either way doesn't
00:19:52.340 really matter for state problems we're just interested in finding out exactly the current state of this code so we go
00:19:58.070 in and they can use binding dot IRB might look similar to binding dot pry
00:20:03.279 it's very similar it's like the same thing except it doesn't have like the LS
00:20:08.859 so the CD or all the stuff that makes you treat objects like file systems that are kind of funny this is brand-new and
00:20:15.489 Ruby too for if you're not using Rufio for you should use Ruby too for so first
00:20:21.609 off let's talk about binding binding is inside the current lexical scope of any kind of block inside of Ruby it's going
00:20:28.029 to tell you the table of local variables and the call stack as well as a couple
00:20:33.249 other utilities I'm not gonna mention IRB right is what happens when you're
00:20:39.159 getting the repple for really so when you require IRB IRB adds an IRB method
00:20:44.739 to the binding class which will then drop you in so if you go and you run this code let's make that a little shorter it's going to drop you into this
00:20:52.690 IRB this IRB console right at that point in code you can introspect on the
00:20:58.269 instance variables you can determine that in fact cells is nil and we're going to go and complete this whole
00:21:03.609 debugging example in a minute but suffice to say at this point you can use
00:21:08.710 binding the IRB to get all of that information very quickly how many objects are allocated at this point so I
00:21:14.950 wasn't going to include this example just because it's such a minimal touch on GC but I'm going to do it anyway just
00:21:22.809 because it's good to know that you have these tools available to you I by no means claim to be a GC expert there are
00:21:29.229 so many people more qualified to speak about this but I'm going to just kind of give you the beginner's guide to what
00:21:36.309 you need to know so let's say we have this code and status thought text is
00:21:42.489 getting updated and we've determined through massive amounts of profiling on our part that this method is slow we
00:21:49.659 don't know why it's slow and so we're going to do a little bit of profiling on
00:21:54.759 our own for just this specific method so we're going to create a board now before I add the rest of the code to this slide
00:22:01.299 remember what I said earlier that you don't get style points and debugging this is going to be egregiously bad code
00:22:07.389 that you should never use okay so we're going to create a board and I don't want to deal with the TK status the TK label
00:22:14.200 so I'm just going to create destruct and instant evil that in there then I'm gonna create some cells and all
00:22:19.690 the cells need TK button so I'm going to create some buttons you see what this is going doesn't mess Afflick hurt your
00:22:26.920 eyes a little bit right I mean you're just like doing bad things to Ruby but it's okay we're going to delete it all we're going to find out exactly what's
00:22:33.190 going on so let's add some code we're going to say okay GC this is your window into the garbage
00:22:38.290 collector this is going to tell you what it's thinking about what it's measuring what it what it has done and everything
00:22:45.640 the stat method is going to give us back a hash that's going to give us the current state of the garbage collector the total allocated objects key within
00:22:54.640 that hash is going to tell us exactly what we've how many objects have been allocated and finally if we look at this
00:23:01.600 code we're going to run update status 10,000 times and see what happens if we run this code we get 70,000 won so
00:23:10.090 thinking about if we ran this thing ten thousand times so seven objects are being allocated per method call we go
00:23:17.830 back into our code and this is the block because we were controlling for that inside of the code this is the two lines
00:23:23.950 that get executed so you can do a couple things here and I'm going to put this little caveat out here normally this
00:23:30.100 kind of like intense GC optimization memory optimization is not useful you have bigger fish to fry
00:23:38.140 right if your page is taking three seconds to load this is not going to help that being said it's a good example
00:23:44.950 and it's let's say this is like the most critical path like you have to know how many mines are left at all times like
00:23:51.610 just ten million clients connecting and they have to know I guess you can do this
00:23:57.570 so we can say okay we don't need to select and then count we can just count and we don't need to do string
00:24:05.220 concatenation we can just ring interpolation we fix that we've run it again we get 50,000 won we deleted two
00:24:11.470 objects that's a very minimal GC example it's just to show you that right GC you
00:24:18.610 have that kind of introspection available to you at any given time lessons learned some state problems take
00:24:24.940 advantage of Ruby's quick feedback loops and flexibility I instance eval status and that button in
00:24:31.330 there and they were just structs and it didn't matter because it's not checking the API it's not checking what you
00:24:38.109 conform to it's not checking that you have some kind of marker interface or protocol saying okay these objects can be substituted for these other objects
00:24:44.619 and your ability to see into your program state at any point in is one of your strongest tools in debugging right
00:24:50.919 you can go into your code and run this at any point you can put it into your code anywhere inside of your whole
00:24:56.409 application you can get this information quickly so slow problems our last class
00:25:05.769 of problem these the most serious ones these are the ones that you hit in production these the ones that honeybadger sends you an email at 3 a.m.
00:25:13.200 flow problems occur when you don't know how the rig interpret or got to or left of location and code in its associated
00:25:19.210 state it's a bit of a mouthful what is that basically saying when you have your
00:25:24.249 application code and you say ok at this line specifically I have an error and I have no idea what's going on you need to
00:25:31.269 know how it got there where it's going the objects inside of that state where they came from where they're going so it
00:25:37.330 answers questions like how did the interpreter get here where do the interpret go from here where is this
00:25:42.489 object how does this object get here where is the subject being mutated and finally where does this instance variable get set right these are all
00:25:49.929 temporal problems these are having to do with over the course of a longer period of time so they're necessarily a little
00:25:56.320 bit harder how do you interpreter get here fortunately this one is pretty easy to solve if you look at this code we say
00:26:01.539 okay it says we win but maybe we got the logic wrong and says we went after the first click we can find out how to do
00:26:08.529 that really quickly we can say ok puts caller callers and method from kernel it's going to tell you the stack trace
00:26:13.539 up to this point we go when we run this code and it gives us all this it tells
00:26:18.759 the whole back trace that's great that's pretty good but it's kind of frustrating
00:26:24.609 because now we have all this codes that we don't want to look at any more because we still have all of the
00:26:30.489 external gem let's get that out of there real quick back trace cleaner without pulling in the third-party gem regex
00:26:39.610 this is a new regex it creates a regex from the current working directory from
00:26:44.860 the directory in which this file is defined and we can grep through color
00:26:50.020 like that pretty effective back trace cleaner we go and read on it and we get that those are just the lines in our
00:26:56.080 code the executed to get to this point right it created it mine Super Start was
00:27:01.120 called that called board start that called that created cells the cells
00:27:06.460 called toggle mine that called update and everything but that's our back trace
00:27:11.580 where does the interpreter go from here this is where we start to pull out the whammer's this section is a little bit
00:27:16.840 harder so we have to pull out the bigger tools so this is our very start and say
00:27:21.940 okay from the very beginning we want to know everything we don't know anything about this code base we just want to see where it goes
00:27:27.540 trace points our friend trace point is a module that will walk you it's a window
00:27:34.630 into what the interpreter is seeing right it's actually technically a wrapper around the set trace funcly'
00:27:41.650 from kernel which is a little more functional so this is like an object-oriented way of looking at that
00:27:48.090 so that's the trace point the new call is going to say okay every single time a
00:27:53.800 ruby function is called execute this block and give us this TP object that TP
00:27:58.990 object has certain metadata on it like pass and line number if we go and run this code and finally we'll enable it
00:28:05.050 we're going around this code to get all of this information right we can walk through line by line as this thing is
00:28:10.330 going again we want to clean that up just a little bit so let's go and add an if statement that says basically the
00:28:16.390 same thing as we did last time we go and we've run that code again and it says exactly the lines of code that we've
00:28:22.210 defined that it's going to walk through all right this is quick information to get and it's just going to show you exactly every single line that you
00:28:28.900 control that you can change that has executed already how did this object get
00:28:34.600 here another hammer we're going to bust out will say we have this args of arm
00:28:41.410 sorry args of button and that's an instance variable that's going to we're going to set enough coming in we have no
00:28:47.080 idea where it came from that's our object space so object space is a window into the
00:28:54.630 Ruby heap it's a window into what's been allocated and actually it also allows
00:29:00.420 you to access when these things get de-allocated a couple of things you can
00:29:05.670 do with this and what we're going to do real quickly that little section in the bottom right has to be required that's
00:29:11.340 the only reason I put it at the bottom you have to require that first to make sure the object space knows to start tracing allocations because obviously
00:29:16.830 you don't want to trace that in production but case you can go allocation source file an allocation source line and we can put that
00:29:22.680 information out and we can find exactly the lining code where this object was created we go and rerun that they get
00:29:29.970 bored RB 949 we go and we find out okay this is exactly where it's allocated right you can go anywhere in code find
00:29:38.100 out where all those objects came from and now on the other side of that where's the subject being mutated we
00:29:44.310 have an object in code we know exactly where it came from we can now find the entire lifecycle where is the subject
00:29:51.330 being mutated in the easiest way it's actually surprisingly simple so undefined method click for nil class
00:29:57.210 let's go in and say okay we have these cells we know they were initialized
00:30:02.850 correctly and one of them is nil why are they no so we go here and clearly
00:30:08.850 something is mutating this cells array something is mutating it over the course of it going from its birth to where we
00:30:16.920 are trying to access it so that frees cells up freeze is going to say okay
00:30:23.700 anytime this array would be modified throw an error and immediately when run
00:30:29.970 that instead of getting undefined method click for nil class which is several lines deep we get can't modify frozen
00:30:36.240 array board RB line 32 we go and we see okay
00:30:41.540 somebody was reading that bang methods are more performant they got really
00:30:47.610 excited and they said okay we're always going to use bang methods that's bad and
00:30:54.870 it can be refactored to do this cells no longer gets modified and everybody's happy finally last example now this last
00:31:02.910 example is a the trickiest one so stick with me when does this instance variable get set
00:31:10.940 undefined method count for nil class we go into our code this is the previous example we said we were going to finish
00:31:16.470 right this is where we left the code now the problem here is that cells should be
00:31:21.929 set but it's not so let's make it set
00:31:27.960 and we're going to assume that the developer who did this was not an idiot by the way it's just a good sumption to
00:31:34.650 make in general the guy who the guy or girl who made this was not an idiot and
00:31:39.960 this code should have worked they were assuming that cells was initialized so let's go in okay we run it and it says
00:31:47.340 zero minds left but the program run this is good it means that we can you know keep working we go back into our code we
00:31:54.419 say okay now we need to find the line of code in this file where this instance variable would have been set so that we
00:32:01.049 can change build status label to be after that so let's bust out our old
00:32:06.150 front trace point this is getting complicated but it's not as bad as it
00:32:13.799 looks first of all this is going to give us this block these this TP object at every
00:32:21.990 single time the interpreter hits a new lining code and it's going to enable it then it's going to say for if some
00:32:30.270 condition that will go through put out the path that you're at and the line
00:32:35.940 number minus one the reason we're saying line number minus one is because we're going to try to create an if statement
00:32:41.520 that says okay if cells changed then the
00:32:46.830 previous line must have changed it first part of the if statement are we within
00:32:52.470 the same file this might not be relevant but for us it's easy because it's an instance variable and assuming you are
00:33:00.659 not setting instance variables on objects from other classes don't ever do that we can't assume it's in within this
00:33:07.559 file next TP bind evil self class equals
00:33:14.039 equals self that class what the heck am i doing there so binding evil right when you're within
00:33:21.960 the trace point block when you have the TP object you have access to the binding at that point in code you can access all
00:33:29.130 the variables that that binding could have seen and you can just call eval on it remember how you don't call eval in
00:33:36.180 production please don't call eval in production you can do that in debugging you don't get sell point to debugging it's going to go away anyway so the
00:33:44.580 point of this line is because earlier remember we had that lexical scope issue where we're inside of that block that's
00:33:50.190 still inside this file so we need to make sure we're still evaluating within that code within this class and finally
00:33:56.310 this is the money one we're going to create a local variable that we're going to have access to within this block and
00:34:01.710 we're going to say TPA binding that eval the instance variable sells not equal to
00:34:07.020 cells that is to say if this instance variable changed then we want to know
00:34:13.830 about it and we want to immediately exit and that's going to give us the information so we run it and that's what
00:34:20.850 we get we get the line of code and we get the file in which that instance variable change it tells us one line if
00:34:29.250 we go back to this code this is nine lines of code nine lines of code to
00:34:37.190 attach to the Ruby interpreter walk it through every single line that it
00:34:42.510 evaluates evaluate an instance variable and tell you exactly when these things changed you go in and it turns out this
00:34:51.240 is a relatively easy fix this is the line we want to change and we do that and everything's fixed so lessons
00:35:00.780 learned some slow problems for large projects requires effort to follow the flow this is just a thing with larger
00:35:06.750 projects it's going to be harder to walk through the sack race you know you're going to have thousands
00:35:13.320 and thousands of lines so you need to be very very careful about how you clean it and how you walk it through on the other
00:35:18.990 side for new projects stock traces are easy to generate and follow a point in saying this is it's going to be easy at
00:35:25.200 the offset we know this from Rails right we have generators we have quick and easy
00:35:30.210 fifteen minute blog tutorials it will get you up to speed very very quickly it only becomes hard down the road so all
00:35:38.700 that is to say we're taking some trade-offs when we use Ruby and we debug in Ruby we're trailing from we're trading
00:35:45.150 compiler niceties for intersection right compilers will tell you when you haven't taken account for every single type that
00:35:51.960 can be returned from a function on the other side of that Ruby is going to give you the ability to introspect on any
00:35:57.690 point in code every single variable every single constant every single state of anything that's going on and that
00:36:02.880 information is available to you very quickly if you don't use that as a tool in your debugging then you're giving up
00:36:08.970 one of the best advantages of using Ruby we're trading out-of-the-box speed for flexibility right if we had taken the
00:36:16.500 out-of-the-box speed then we would not have been able to take that you know status struct and stick it in for a TK
00:36:24.060 label we wouldn't have been able to trade those things out because the compiler will yell at you it will say no
00:36:30.359 I need to ensure that everything is correct before I run and finally we're
00:36:35.520 trading maintenance cost for start-up cost this is for flow problems this is for when you're trading off the fact
00:36:41.190 that it's going to be very easy to get to market to ship this to production and down the road it's going to be a little
00:36:47.280 bit harder to maintain in other words these are interface problems for you
00:36:53.190 know the compiler versus the introspection for out-of-the-box seed versus flexibility they're state
00:36:58.260 problems and maintenance cost for start-up costs these are flow so the next time someone comes up to you and
00:37:03.270 says you know Ruby's dead don't use Ruby you can say you know actually you know
00:37:09.780 I'm going to go ship my app to production and I sleep fine and enjoy your type safety good night anyway thank
00:37:16.500 you [Applause]