An Interesting Bug

I tell the story of an interesting bug I encountered while working on a scroll view widget, how I used the time-traveling debugger to tackle it, and the lessons I learned.

Transcript

The following transcript was automatically generated by an algorithm.

00:00 : hi this is toby uh and i want to share
00:02 : with you
00:03 : a bug that i encountered um as i was
00:06 : working
00:07 : on the ui framework since i'm working on
00:10 : a debugger
00:11 : i've been paying more attention into how
00:14 : i debug
00:15 : while i was doing my work in this case
00:18 : the ui work that i've been doing
00:20 : and one of the goals of that is to just
00:22 : have a sort of
00:24 : real world test case scenario for the
00:27 : debugger as in
00:29 : if i'm going to program something
00:31 : complicated
00:32 : i for sure will run into some
00:34 : interesting books
00:36 : and i can put my debugger against those
00:39 : books and see how
00:40 : well it fares so anyway one scenario
00:44 : came up
00:45 : and i want to show you what the bug was
00:47 : okay so this is the scroll view
00:49 : component
00:49 : um you can use the mouse wheel to scroll
00:53 : up and down in my case i'm on a mac and
00:55 : i'm using the trackpad to screw this
00:59 : guy up and down and this is the bug you
01:02 : you're seeing it right now actually and
01:04 : it seems to trigger when i
01:06 : just send it lots and lots of scroll
01:09 : events
01:09 : as in i'm scrolling the thing really
01:11 : really damn fast
01:14 : so the error that came was
01:18 : this index l range this an input is a
01:21 : string
01:22 : and i'm indexing into index four
01:25 : and that's out of range natural thing to
01:28 : ask is
01:28 : like what what is an input let's see
01:31 : that
01:32 : right so let's see that
01:38 : and at the moment um this actually takes
01:41 : a while
01:42 : there was a lot of event for the program
01:44 : to process
01:46 : generating quite a large uh log file
01:49 : so here i'm back at the scene sort of
01:53 : of when the error happened and i can see
01:55 : the value of
01:57 : the variable so let's scroll to an input
02:01 : now so an input is this
02:04 : string and this is a control code that
02:08 : we're trying to parse
02:09 : a control code is the way in which the
02:12 : terminal is sending me these scroll
02:14 : events
02:15 : the control codes or the control
02:17 : sequences usually start with a control
02:19 : character which is this
02:21 : slash x1b thing and then it comes
02:24 : with some data and i guess this case
02:27 : an input doesn't have the
02:31 : number of characters than i that i would
02:33 : expect
02:35 : uh at first i just thought aha that's
02:38 : weird and if it is
02:41 : in indeed that it's possible for the
02:45 : terminal to send me these incomplete
02:47 : inputs
02:47 : i guess i'll have to like error check
02:50 : that
02:50 : and ignore them or something and
02:52 : initially that's what i did
02:54 : but then i had second thoughts and i
02:57 : thought to dig deeper
02:59 : and uh i went back in here and i stepped
03:02 : backwards in time
03:09 : it's going back to the top of the while
03:11 : loop and then when i keep going
03:13 : it's actually going again i can actually
03:16 : see
03:17 : an input is getting longer or longer and
03:19 : what is actually going on
03:21 : is there could be actually be a variable
03:24 : number of
03:26 : events here encoded and i i can actually
03:29 : see
03:30 : three of them repeated here one
03:33 : two and three and um so
03:36 : this while loop strap is actually to go
03:39 : through all of them
03:40 : and parse them so uh one of the things
03:44 : that i remember when it was the first
03:46 : time i was debugging this
03:48 : problem is actually you notice when
03:51 : initially i was scrolling down i
03:53 : encountered tons of
03:54 : these wheel down events here
03:58 : um i just noticed that even though that
04:00 : was not
04:01 : what i was hunting for holy moly there's
04:04 : a whole bunch of
04:05 : wheeled down events and i'm not
04:07 : expecting to see that many events
04:09 : usually
04:10 : usually i expect there to be like one or
04:13 : two
04:14 : events at most so seeing this many
04:18 : um raise some questions so one thing i
04:21 : can do is like
04:22 : how big was an input really because this
04:26 : is an input can can be variable length
04:30 : and then this this while loop breaks it
04:33 : down so i can
04:34 : uh go back in time until i hit the
04:37 : beginning of this function when i just
04:39 : enter the function
04:40 : i do that via right mouse click on this
04:44 : line
04:45 : so i've done that i go back and i look
04:48 : at
04:48 : an input and i can see
04:51 : it's really really quite long and that
04:55 : is why uh i had
04:58 : lots and lots of mouse wheel events
05:01 : that's interesting so i mean that that's
05:03 : just something i
05:04 : would never have expected i i
05:07 : because from what i've seen in the past
05:10 : i this
05:11 : input is at most one or two events long
05:14 : and here i'm getting tons of them so
05:17 : another question that
05:18 : arise in my head was hey well if this is
05:22 : so long is it always this long
05:25 : so i can go back in time again and
05:28 : uh sort of rewind back to the previous
05:31 : time
05:32 : that this function was called so i click
05:35 : and i look at how long that one was
05:38 : and it was also quite long i do it again
05:46 : and i i i rewind back several
05:49 : times and at one point i got an
05:52 : input that was actually short and this
05:54 : is closer to what i was expecting
05:57 : so this gets me thinking i'm i'm
06:00 : starting like a theory is starting to
06:02 : form in my head right it seems like
06:05 : the length of this input string
06:09 : is at some point it's
06:13 : relatively short and then at later time
06:17 : it's getting longer and longer and
06:20 : i'm getting the hint that the
06:23 : number of events is over flooding the
06:26 : program
06:27 : the program isn't able to handle
06:31 : the amount of events that are coming in
06:34 : in my scroll view basically every time
06:37 : there's a
06:38 : wheel wheel event i'm going to have to
06:41 : perform a repaint and this repaint
06:44 : is the potentially expensive operation
06:48 : so if i have tons of wheel
06:51 : events that means i'm gonna have to call
06:54 : repaint hundreds of times
06:55 : and the repaint operation is the thing
06:58 : that
06:59 : potentially can be expensive so
07:03 : the fix i came up with was i'm going to
07:06 : coalesce
07:07 : the wheel vents many of them into a
07:10 : single one and the way i'll do that is i
07:12 : make a dictionary
07:14 : and i'm going to uniquely key this
07:16 : dictionary based on
07:17 : the attributes of the event i added a
07:20 : added an attribute to the event called
07:22 : amount
07:22 : i'm just going to even increase that
07:24 : number so that the application
07:26 : it only gets one event instead of 100
07:28 : events
07:29 : but you'll get this amount uh parameter
07:32 : to tell it how much to scroll up and
07:35 : therefore how much uh within the view to
07:38 : shift
07:38 : up or down so this was the idea
07:42 : and it worked out quite well so so i ran
07:45 : this
07:46 : again after this fix
07:49 : and now it doesn't matter that i i try
07:52 : to scroll
07:53 : really really fast and uh
07:56 : i i don't encounter a debug anymore so
07:59 : one thing
07:59 : that i wanted to see with the fixed
08:01 : version if i went back into the function
08:04 : i looked at the input would i get a
08:08 : long input and or if my hypothesis is
08:11 : correct then i should get a
08:12 : fairly short input so i jump into the
08:15 : end of the
08:16 : program and i'm actually just going to
08:18 : find that line
08:20 : in the event processing which is here
08:23 : jump back in time into here
08:25 : but i think i need to go backwards into
08:27 : it okay there we are
08:29 : and now i'm going to go back and time
08:31 : into here this is the queue this is the
08:33 : q
08:33 : key that i type to end the program but
08:36 : i'm going to go backwards further
08:38 : so here are the view the wheel events
08:41 : there are actually three of them this
08:43 : time
08:43 : i go back again three
08:46 : three now this time we have more
08:50 : four as i have more
08:54 : and yeah so it looks like it's not
08:57 : one or two but it's more like three to
09:00 : five of these
09:01 : per per call into this uh function
09:05 : so it looks like we're doing good but
09:08 : um i still want a better
09:11 : picture i want to be able to visualize
09:14 : better what's actually happening like
09:17 : me sort of clicking through this is
09:20 : a very manual and tedious process what i
09:24 : would like to be able to do is
09:25 : automate this and we can in this case
09:28 : all we need is a sql query
09:30 : to query out all the times that
09:33 : the code reached this point and then i
09:36 : want to see
09:37 : what was the input in there at that
09:40 : point in time
09:41 : and print it all out so i came up with
09:42 : the sql query that does that
09:45 : i want to compare it when i run it on
09:48 : the
09:48 : version of the database that had the bug
09:51 : in it versus the version that does not
09:52 : have the bug in it
09:54 : so let's do the version that has the bug
09:56 : in it first
09:58 : and then i execute the query here
10:02 : okay so this is what we get basically
10:05 : in the problematic program
10:09 : it hit this line 14 13 times
10:13 : and this is the length of the
10:16 : the input variable
10:19 : uh for each of those times and this is
10:22 : the actual value
10:24 : of that variable for those times so you
10:27 : can see
10:28 : sort of like a historical um
10:32 : summary of all the times that the
10:34 : program reached
10:36 : this line and also
10:39 : a printout of what that variable was at
10:42 : that point in time
10:44 : and the length of the input so we can
10:46 : clearly see that
10:47 : the length of the string is getting
10:50 : worse and worse anyway i pasted this
10:54 : data or this summary into a file
10:57 : i called it problem plot the problem
11:00 : version we had 9 18
11:02 : 18 and then and then i jumped to 3 000
11:06 : or something and then i
11:07 : have the whole line here you can sort of
11:10 : imagine this
11:11 : as a bar graph if you will we could have
11:14 : put this
11:14 : into excel and plot it into these bars
11:17 : and but you can sort of imagine this
11:21 : as these long bars except these really
11:23 : long ones are getting wrapped
11:25 : so this is the version that had the
11:27 : problem in it the one that was fixed
11:29 : it looked like this so sometimes
11:32 : the input was longer sometimes it was
11:35 : shorter
11:36 : but we're sort of sustaining uh when
11:39 : it goes up and down but we're never
11:42 : going
11:44 : to the point of no return uh and the
11:46 : longest one
11:47 : in here is probably this one i'm
11:50 : shrinking the
11:51 : font size so that you can see the big
11:54 : picture but the
11:55 : longest one is 387
11:59 : characters long or bites long there's
12:02 : this one
12:03 : um that's still a lot of scroll events
12:06 : but
12:06 : i think uh coalescing the events into
12:09 : one
12:10 : help the performance in this case
12:14 : i want to summarize some lessons that i
12:18 : think i have learned from this
12:20 : experience number one
12:21 : is i was able to go back to the scene of
12:23 : the crime
12:24 : and have a look around um when i when i
12:27 : saw
12:28 : that very very long list of wheel down
12:31 : events
12:32 : i i didn't really pay attention to
12:35 : initially but like i
12:36 : caught that out of the corner of my eye
12:39 : if you didn't
12:40 : have the ability to step back
12:43 : into all that programming context you
12:46 : might not have looked around and if if
12:48 : you were to do
12:48 : print debugging then you would only
12:51 : print the things
12:52 : that you thought were the culprit and
12:55 : you might have missed out on
12:56 : some other things that you didn't think
12:58 : to look the second thing
13:00 : is take one thing plot it over time
13:04 : which is what we did with the variable
13:07 : here
13:08 : it take hey there's an input i want to
13:11 : plot this
13:11 : over time i want to know what this input
13:14 : was
13:14 : over the lifetime of this whole program
13:18 : the concept is extremely powerful
13:20 : and in my case i was able to like whip
13:22 : up a sql query
13:24 : in a quick and dirty and hacky way uh
13:27 : i i think something like this could be
13:29 : built in as a feature
13:31 : to a time traveling debugger and it
13:33 : could potentially be
13:35 : very useful i also think that um as a
13:37 : developer
13:38 : if you know some sql you can definitely
13:40 : get in here
13:41 : and write some sql and get the answer
13:44 : you need so yeah so that's the story
13:46 : that i wanted to share with you