Debugging with rr: Start at the End

In this second video on the rr debugger I demonstrate the technique "Start at the End". The idea is instead of starting at the beginning of the program and single stepping forward, you start at the end of the program and single step in reverse instead. This technique is very useful for scenarios where you've encountered and error and want to backtrack to find the cause of the error.

Transcript

The following transcript was automatically generated by an algorithm.

00:00 : hello there welcome to another video
00:02 : about the rr debugger uh in the first
00:05 : video about rr that i did um i
00:09 : showed you a technique that you use
00:12 : with rr i call it the backup and drill
00:16 : down
00:17 : this time i'd like to show you another
00:18 : technique that you can use
00:20 : now that you have the ability to time
00:22 : travel
00:23 : this technique is called start at the
00:26 : end
00:27 : and the idea of start at the end is
00:29 : instead of
00:31 : stepping through the program
00:35 : sort of line after line from the
00:37 : beginning
00:39 : you reverse it you you have the program
00:41 : run all the way
00:43 : to completion and starting at the end
00:46 : you've reversed that back uh to sort of
00:50 : track the calls of your issue
00:54 : usually you use this when you have an
00:56 : error or your program crashed
00:58 : i'll show you a couple of examples where
01:00 : this technique is applicable
01:02 : so i have two programs that are
01:05 : sort of uh generating a bunch of random
01:09 : people names based on a list of first
01:12 : names and a list of
01:14 : last names and it's inserting these into
01:18 : a sqlite database
01:20 : a number of times and in both of these
01:23 : programs there's an issue so let me run
01:25 : the first one this is going to be called
01:27 : secretly crash
01:30 : and as you can see there's a crash
01:31 : there's a segmentation fault
01:33 : and i remember that when i was in
01:36 : college
01:37 : a long time ago when i was programming
01:40 : in
01:40 : c i used to be frightened
01:44 : of segmentation faults and now that i'm
01:48 : coding in c again and i have access to
01:51 : the r debugger
01:53 : segmentation faults actually bring
01:56 : a certain delight to my face and i'll
01:59 : show you why
02:00 : so if you get a segmentation fault in
02:02 : your c program
02:04 : uh here is what you can do with rr to
02:07 : debug it
02:08 : we're going to record the execution of
02:11 : this program
02:12 : with rrs record mode and now we're going
02:15 : to
02:15 : replay this program using the rr
02:19 : replay mode and now we're going to start
02:22 : at the end
02:23 : which means we're going to first say
02:25 : continue which is
02:27 : the shorthand for continue is c i'm
02:30 : going to
02:30 : say continue to have the program auto
02:33 : ready
02:33 : run until completion and you can see the
02:36 : segmentation fault here
02:38 : and at this point in rr
02:42 : we can actually print out some
02:44 : information about the program
02:45 : i believe so i'm going to clear the
02:47 : screen i'm going to
02:48 : actually show the back trace of this
02:50 : program we actually
02:52 : have a line number that we can refer to
02:55 : let's see
02:56 : we're actually on line 143 in the
02:59 : program so let's go there
03:01 : so it was on this line more precisely
03:04 : where actually in the string
03:06 : land function had a segmentation vault
03:10 : now i don't think i actually have access
03:12 : to this
03:13 : source code but i i can see that on this
03:17 : line i have a call to string link
03:20 : and if string link calls a segmentation
03:23 : fault
03:24 : i should ask what is the value that i
03:27 : gave to string length
03:29 : and i actually can print that out
03:33 : but at the moment i cannot we're
03:35 : actually inside of the string length
03:37 : function
03:38 : but what we could do is come out of the
03:40 : string length function
03:42 : back into this context and the way we
03:44 : can do that is using the reverse
03:47 : finish command because rinse and main
03:50 : function here the main has called
03:52 : string length and we're inside here
03:55 : somewhere
03:57 : if we want to get back into the main
03:59 : function 143 but onto this
04:01 : one line that's calling string length we
04:04 : can say hey
04:05 : go in the reverse direction but reverse
04:08 : finish
04:09 : is as if we're finishing the function
04:11 : but we're
04:12 : going in reverse so i'm going to say
04:14 : reverse finish
04:15 : [Music]
04:17 : and now we're on line 143 again so
04:20 : we are here and we actually have access
04:23 : to all the variables in this context
04:26 : so i can answer the question i asked
04:28 : which is
04:29 : what is the value of last so i'm gonna
04:32 : use the
04:33 : p command print to show me the value of
04:36 : last and i can see that last
04:38 : is a null value is zero
04:41 : and now naturally i'm going to ask how
04:44 : did last
04:45 : get a value of zero we can
04:48 : read the code backwards to see where
04:52 : last got a value and i can see it's here
04:55 : and what's this code doing here well
04:57 : this code is
04:59 : uh calculating a random index to get the
05:02 : list of last
05:03 : names and that got us a null value
05:07 : how could that be well what is last
05:09 : names last name is
05:11 : this list and then we're calculating an
05:14 : index for last names by using the number
05:16 : of first names
05:17 : so well okay that's probably the problem
05:21 : we have a number of first names which is
05:23 : 12 and we have a number of last names
05:25 : which is 11. there's fewer last names
05:27 : than there are
05:28 : first names we can't see the actual
05:30 : index number that was calculated because
05:33 : we didn't store it in a variable
05:35 : but if we did store in a variable i mean
05:37 : i imagine that
05:39 : would be an index that's out of the
05:41 : bounds of this array
05:42 : i think the obvious fix here is
05:46 : change that to number last names
05:49 : recompile the program
05:52 : let's run this one more time
05:55 : and this time we've solved the error
05:58 : all right let's see the second example
06:00 : second example
06:01 : is not exactly a segmentation fault
06:05 : crash but uh nevertheless we get an
06:08 : error
06:10 : okay we get an error this time it's a
06:12 : database error
06:14 : to debug this again we're gonna use the
06:16 : start at the end
06:17 : strategy we're gonna say use rr record
06:24 : to record the execution of this program
06:27 : we're going to run it in replay mode now
06:29 : and when it's in replay mode at the
06:31 : beginning it pauses at the beginning of
06:33 : the
06:34 : program so i'm going to say continue or
06:36 : c
06:38 : to let it run all the way to the end and
06:40 : now we're at the end
06:41 : this scenario is slightly different from
06:43 : the
06:44 : the crash segmentation fault scenario
06:48 : because the program actually didn't
06:50 : crash but it exited with an error number
06:52 : and i'll show you what that looks like
06:54 : so if i do a back trace now i actually
06:58 : can't
06:58 : see anything but i can reverse that by
07:01 : one
07:02 : so rs for reverse step and now
07:05 : we're inside some kind of raw syscall
07:08 : code because
07:09 : i believe that we're executing the sys
07:12 : exit
07:13 : system call i'm gonna do a back trace to
07:16 : see where we are
07:17 : at so we're at a function called lip
07:21 : start main what's happening is there's
07:24 : this lip c start main function is the
07:28 : real entry point i believe this start is
07:30 : actually the real real
07:32 : entry point so what's going on is like
07:35 : that and then there's a bunch of stuff
07:37 : that happens
07:38 : i'll call this setup and then your main
07:41 : function is getting called
07:42 : and then there's a bunch of cleanup
07:44 : stuff that happens
07:46 : and where we are right now is somewhere
07:49 : inside this cleanup
07:50 : code here so what we want to do is uh
07:53 : sort of
07:54 : travel backwards in time until we
07:58 : hit this main function and we want to
08:00 : get
08:01 : at it in reverse so what we want is to
08:04 : sort of stop at the end of the main
08:07 : function
08:08 : usually i grab the line that has the
08:11 : closing curly bracket
08:12 : and i stop there so i'm gonna explicitly
08:16 : set a breakpoint there i'm gonna say
08:18 : brick in the
08:20 : uh sqlite error dot c
08:24 : and then i wanna break on line 163
08:29 : okay now that i have a breakpoint set
08:31 : here i'm gonna
08:32 : have it go in reverse um
08:36 : and that's reverse continue or rc for
08:39 : short
08:41 : and i just traveled in reverse and hit
08:44 : the last line of my main function and
08:47 : now i'm going to reverse step
08:49 : which is rn again for any of these
08:52 : commands you can type it all out
08:56 : or use the shorthand in this case rs
09:00 : actually i'll do rn our reverse next
09:04 : so here reverse next actually brought us
09:07 : to
09:08 : line 131 so let's see where that is
09:12 : so we're actually here which tells us
09:15 : that
09:17 : at this step where we're trying to bind
09:20 : an integer parameter of this insert
09:24 : database statement there was an error
09:27 : so we're able to locate the database
09:31 : procedure that produced this error
09:34 : and i don't remember what the error
09:36 : message was although i think we can
09:38 : get it i'll just go next
09:42 : now and it prints it out into the
09:44 : terminal
09:45 : it says column index out of range
09:49 : so what are we doing well we're saying
09:52 : i want to set the fifth argument
09:55 : of this prepared statement to this
09:59 : id number and it says column index out
10:02 : of range like the only index i can think
10:05 : of
10:05 : is this five let me look at what this
10:08 : insert statement is
10:10 : does it have five parameters
10:13 : no it only has three parameters
10:17 : so that's probably why the column index
10:19 : is out of bounds
10:20 : and for the next two i only have two and
10:23 : three
10:24 : so this should be index one
10:28 : because let's see if i insert into
10:31 : person values there's three value
10:33 : where's the person table defined the
10:35 : person table is defined here
10:37 : as the first one is id the second one is
10:40 : first name and the
10:41 : third one is the last name therefore the
10:44 : index should be one
10:46 : and then followed by two and then
10:48 : followed by three i know
10:49 : you might be thinking it should be zero
10:52 : but it's not zero
10:53 : i read the docs i read the sqlite docs
10:55 : and
10:56 : for parameter binding the first one is
10:58 : actually one
10:59 : so let's let's let's try this fix
11:02 : so i rebuilt it and run it and
11:06 : oh this time it says no more rows
11:10 : available i think i got past that error
11:13 : but i have another one so let's debug
11:15 : this one
11:19 : all right again i recorded the execution
11:23 : of this program and now i'm going to
11:24 : replay it
11:25 : so that i have access to time traveling
11:29 : while i'm in the debugging process so
11:31 : again
11:32 : i'm going to run the program to
11:35 : completion
11:36 : so we're now all the way at the end and
11:39 : again i'm gonna
11:40 : set a breakpoint at the end on line 163
11:46 : and then now that i've set the
11:47 : breakpoint i'm gonna reverse continue
11:52 : and then now i'm here and now i'm gonna
11:54 : revert i'm here i'm going to reverse
11:56 : that one by one backwards reverse next
12:00 : now i'm actually on 144
12:03 : i'm here so this one this
12:06 : statement caused an error what was the
12:10 : error again
12:14 : it's no more rows available
12:17 : why would no more rows be available
12:21 : let me uh search the docs for this error
12:24 : code
12:25 : there's the sqlite docs for error code
12:27 : let me search for 101
12:30 : that says sqlite done
12:34 : actually the error code is sqlite done
12:38 : ah okay this is not actually an error
12:41 : code
12:42 : because 101 means sqlite
12:45 : done so the error here is not that
12:48 : there was a database error but the error
12:52 : is
12:52 : in the usage of my sqlite three-step
12:56 : function
12:57 : in the docs it says if the sqlite
13:00 : three-step function returns
13:02 : sqlite done which is 101 the number 101
13:06 : it means that the statement has finished
13:08 : executing successfully so 101 should be
13:12 : expected the problem is
13:15 : i expected this to return a zero
13:18 : which it doesn't do even if it succeeds
13:21 : so the fix here is to change this to
13:25 : say expect the return value
13:28 : to be sqlite done compiling
13:32 : and then i will run this again
13:38 : oh i i should say if not equal
13:44 : not if equal okay and now the bug is
13:48 : fixed
13:49 : okay so that's an example of um
13:53 : this technique um start from the end i
13:56 : hope
13:56 : you enjoyed it and uh again if you
13:58 : haven't used rr
13:59 : before i hope you give it a try for one
14:02 : thing it has conquered my fear of
14:04 : segmentation fault and that should count
14:06 : for something