Random Sample-Based Profiling with Mike Dunlavey

I learned a very cool technique for profiling my application recently for performance tuning from a post on Stackoverflow. It can be used for most programming languages, does not require any special tools, and is more intuitive to use that many profilers that give you a summary view of some sort. I hunted down the author of that SO post - Mike Dunlavey, and had a nice chat with him. Enjoy! Mike's Stackoverflow post can be found here: https://stackoverflow.com/a/1796715/5304. He also published a paper on it, which can be found here: https://www.cs.tufts.edu/~nr/cs257/archive/mike-dunlavey/performance.pdf.

Transcript

The following transcript was automatically generated by an algorithm.

00:00 : hi this is toby and in this video i'm
00:02 : going to talk to
00:03 : mike dunlevy mike went to mit
00:07 : in the 60s the ai lab in the 70s and he
00:10 : taught at boston college in the early
00:12 : 80s
00:12 : and then he did a few decades of
00:14 : consulting with
00:15 : software startups and then he developed
00:18 : some software for the pharmaceutical
00:20 : industry as well
00:21 : he is currently retired the way i
00:24 : learned about mike
00:25 : is through this mind-blowing stack
00:27 : overflow post
00:28 : where he taught me about this very
00:31 : simple yet effective
00:33 : technique for profiling your software
00:35 : application
00:36 : without using any special tools and
00:38 : that's what we're going to be talking
00:40 : about
00:40 : i hope you have good questions because
00:43 : uh
00:44 : uh my mind is blank
00:48 : well um i just found your pillow very
00:51 : fascinating
00:52 : like i'm gonna share my screen so i can
00:54 : show
00:55 : how i learned about you and your work i
00:58 : was working on
00:59 : improving the performance of a python
01:02 : program and i
01:03 : came to the realization that 80 of the
01:06 : time it was python that was slow so i
01:08 : rewrote the program in c
01:11 : and then and then because i'm in a
01:14 : different language now i no longer had
01:16 : access
01:17 : to the same profiler i was using python
01:19 : so i was doing some research
01:22 : about how to profile c programs i ran
01:24 : across this
01:25 : stack overflow question and i was like
01:28 : what do people use in c for profiling i
01:31 : haven't done
01:32 : c in such a long time um
01:35 : and then so i got an answer that use g
01:38 : proof
01:38 : use call grind i was like yeah those
01:41 : make sense and then there's your
01:43 : answer it says basically you don't need
01:46 : a profiler
01:47 : you can just do it yourself you wrote a
01:50 : lot
01:51 : so i read through it and you had
01:53 : actually multiple posts
01:56 : on stack overflow on multiple
01:59 : occasions where people asked a similar
02:01 : question
02:02 : right so um can you talk a little bit
02:05 : about
02:05 : how these posts came about oh gosh
02:10 : well i got in a mode of um
02:13 : uh trying to tell people about this
02:16 : and you know it goes way back what 10
02:18 : years
02:20 : yeah you actually wrote a paper about it
02:23 : and i i love more than one
02:25 : uh yeah more than one paper
02:28 : uh and papers on other subjects as well
02:32 : but it's like you know i realized when i
02:34 : was teaching that
02:36 : um students basically believe they're
02:39 : professors which is natural
02:42 : but the professors don't know this and
02:45 : so
02:46 : there we are you know and there's all
02:48 : this there's all this uh
02:51 : history of g prof and everything if you
02:55 : look in the history of the g prof it was
02:58 : never really intended for what
03:01 : people think it's good for
03:05 : and including what professors think it's
03:07 : good for
03:08 : so so there you go one thing about your
03:11 : method that
03:12 : i would say there's very little to it
03:15 : like there's
03:15 : very little to understand it's not like
03:18 : there's multiple things to unpack
03:21 : it's very easy to understand when you
03:23 : actually do it
03:24 : it's quite easy to do even though it
03:27 : might be slightly tedious
03:29 : it's it's so simple that i almost feel
03:32 : like
03:32 : i should already know this i feel like
03:36 : once i once i've learned it i feel like
03:40 : i should already know this and i almost
03:42 : want to convince myself
03:44 : that in fact i did already know this and
03:46 : this guy is just
03:47 : trying to con me into thinking you know
03:50 : he this is a new thing but
03:54 : but i don't think that's obviously not
03:56 : true it feels like it's
03:58 : it's almost strange to me that i have
04:00 : not learned this
04:01 : earlier in my career what
04:04 : what do you make of that well
04:07 : programmers have teachers
04:10 : and they and they learn what the
04:11 : teachers know
04:13 : and the thing is very few teachers
04:17 : have had much real experience
04:21 : what i found was that there were other
04:23 : people in the world who
04:24 : who knew that technique um
04:28 : but they didn't think
04:31 : they thought everybody knew it or they
04:33 : didn't it didn't bother them that
04:35 : other people didn't know it so what's
04:38 : the big deal
04:39 : yeah but perhaps those practitioners
04:41 : that are doing this
04:43 : they are not uh making it known i didn't
04:46 : think it was that big a deal myself
04:48 : um because i just thought of it as
04:52 : one tool in the toolbox for doing all
04:55 : kinds
04:56 : of problems go ahead and mind if i try
04:58 : to
04:59 : demonstrate you can do this in a variety
05:02 : of languages
05:04 : i'll try a python one
05:07 : okay so this is a python program it's
05:09 : running a long job if i just kill it
05:11 : with ctrl c it prints a
05:15 : call stack or the
05:18 : stack trace or the back trace yeah
05:21 : various different terminologies for the
05:23 : same thing
05:24 : so this shows me basically
05:28 : exactly what point in the algorithm
05:32 : the program was what line of code it was
05:35 : and
05:35 : within that line of code within which
05:38 : function call it was
05:39 : and the whole chain of function calls um
05:43 : that's on the stack at that point so
05:46 : it's
05:46 : good question which is which is the
05:48 : innermost and which is the outermost
05:51 : the bottom is the innermost and the top
05:54 : is the outermost
05:56 : this is the main function which is the
05:58 : output oh yeah yeah yeah yeah
06:00 : one one reason i thought your method is
06:02 : so
06:03 : uh so obvious retrospectively
06:07 : is that with a lot of programming
06:10 : languages
06:11 : python is one of them i automatically
06:13 : get this stack trace
06:15 : when the program is interrupted for any
06:18 : reason
06:19 : but basically your technique is like you
06:22 : do this once
06:23 : to capture a stack trace and then you
06:26 : would
06:27 : you would like i i put it in like a text
06:30 : file just a normal text file
06:32 : and then i'll say hey this was sample
06:35 : one
06:36 : and then i do this again
06:40 : and then you you the the thing is when
06:42 : you
06:43 : you when you hit the interrupt the
06:44 : control c
06:46 : that's happening at a random time the
06:49 : program is just type tight looping and
06:52 : then
06:53 : and then so when you when you interrupt
06:56 : it
06:56 : like it could be at any moment in time
06:58 : it's completely random
07:00 : it's right complete by chance where
07:03 : the execution happens to be at that
07:06 : point in time
07:07 : yeah so that's a random sampling method
07:11 : uh so the fact that the last time
07:14 : i interrupted it it was at this
07:18 : parsing function and it was calling this
07:21 : eval
07:22 : eval is like a python core library
07:26 : it evolves as python expression actually
07:29 : and then this time i got the exact same
07:31 : thing
07:32 : yeah um that's by chance but also not so
07:35 : much by chance
07:38 : well that you can conclude from that
07:40 : that it's spending
07:45 : almost all of its time doing that
07:48 : yeah the parsing appears to be slow
07:51 : which is what i
07:52 : also found uh using other methods so
07:55 : this is totally consistent
07:57 : with what i know and now the third
08:00 : sample
08:00 : it's actually doing a database insertion
08:05 : so maybe another part of the program
08:07 : that's slow is when it has to do some
08:09 : database work
08:11 : and then this is a different place as
08:14 : well
08:15 : this is this is just oh okay so two out
08:18 : of four times it was doing that
08:20 : uh parsing yup two out of four times
08:24 : it was doing a parsing and then uh
08:27 : and then one time was database
08:31 : and then another time this is get type
08:33 : by value
08:35 : um i think get type by value
08:38 : just a couple of if statements and maybe
08:41 : a dictionary lookup or something like
08:43 : that
08:44 : and then and then another another thing
08:47 : for parsing so the parsing
08:48 : is definitely looking like it's one of
08:51 : the culprits
08:53 : the parsing um hey there uh this is toby
08:56 : interjecting from the future because we
08:59 : didn't go through an end-to-end process
09:01 : of using mike's method in the video i
09:04 : kind of want to show you
09:05 : what the end result might look like this
09:08 : is
09:08 : an actual report that i hand made
09:12 : using a simple text file
09:15 : i did this on the c version of my
09:17 : recreate program
09:18 : first i took 20 stack traces
09:22 : as we've shown in the video and
09:25 : each one i just pasted into this text
09:28 : file and you can see
09:30 : there's 20 of them after i've done that
09:32 : i went through each one
09:33 : and then categorize them usually by
09:37 : the line of code that is
09:40 : the deepest one in the stack trace that
09:43 : is still
09:44 : inside my code not in the library code
09:47 : so in this one for example is
09:49 : recreate1121
09:52 : which happened quite often actually and
09:54 : once i find that line of code i
09:56 : actually paste the source code here as
09:58 : well so that i can see
09:59 : what that line of code is and after i
10:03 : sort of categorized them and tallied the
10:05 : numbers
10:06 : i found that actually 14 out of 20
10:09 : of my samples the code was actually
10:12 : spending
10:13 : within this line the database driver is
10:15 : committing a
10:16 : transaction the remaining 30 percent is
10:19 : spent
10:20 : in this process event function which
10:22 : then i further broke down into these
10:25 : four distinct lines but two of these
10:28 : distinct lines
10:29 : are also code inside the database driver
10:33 : thus if i add these two together with
10:36 : these 14
10:37 : i can conclude that about eighty percent
10:40 : of the time
10:42 : the program was spending inside the
10:44 : database driver
10:45 : that's what i want to say now i'll let
10:46 : you get back to the interview
10:48 : one of the things that you said in
10:51 : in your post in your paper is that
10:54 : this method uh when compared to
10:58 : a typical profiler which actually i'll
11:01 : try to run a typical profiler for python
11:06 : c profile
11:10 : oh except that i'm gonna have to
11:13 : ah okay that's good enough i interrupted
11:15 : it and it did it
11:17 : yes i didn't want to have to wait too
11:19 : long so typical profiler would give you
11:21 : output
11:22 : like this
11:26 : and you can and you can sort tell it to
11:29 : sort this table of data
11:33 : based on one of the statistics like so
11:36 : you can
11:36 : sort it either by cumulative time
11:40 : or total time whereas cumulative time
11:42 : would be
11:43 : the amount of time it took to execute
11:47 : this entire function
11:49 : whereas the total time would be the
11:51 : amount of time it took to execute this
11:53 : function
11:54 : minus the amount of time its
11:57 : child function calls took so it would
12:00 : the total time would be more like a
12:02 : representation of how much time
12:05 : you know was spent just inside the
12:07 : function
12:08 : itself not its child calls um
12:12 : you use one or the other depending on
12:14 : sort of what you're trying to
12:15 : do so let's let's let's do do cumulative
12:19 : time first
12:21 : so this is like saying
12:24 : the top cumulative time is the built-in
12:28 : exec function in python
12:32 : and this is the main module
12:35 : you'd be surprised if that didn't
12:37 : accumulate account for all the time
12:40 : yeah yeah it's just like python doing
12:42 : everything
12:43 : and then this is my main function yeah
12:45 : that it should take up a lot of
12:47 : time and then the parse is
12:51 : is up there so that's we kind of already
12:55 : know that the parsing
12:56 : is up there and then we have processing
12:59 : commands
13:00 : is also kind of up there um
13:03 : with with this one it there's a lot of
13:06 : statistics
13:07 : and and it kind of flattens it out
13:11 : and then sorts it in the table um
13:14 : whereas with this one where we took the
13:16 : samples by hand
13:18 : what i find myself doing is um
13:22 : is i after i take these samples i go
13:25 : back
13:26 : and look at each stack trace and i
13:29 : categorize it
13:30 : in a way that makes sense for me
13:33 : because i i wrote the code i have a good
13:36 : understanding of what the code is trying
13:38 : to do
13:40 : so i i'm looking at this code and i i
13:43 : look at the entire stack trace and i
13:45 : like well this is parsing
13:48 : right i will just very automatically
13:51 : lump it
13:51 : into a part that's meaningful to me
13:54 : which is
13:55 : the that's the parsing part so i
13:57 : probably just
13:59 : the point is that you're getting line
14:01 : number information out of this
14:04 : whereas the you you tend not to get line
14:06 : number information out of
14:08 : profilers i mean some do
14:12 : and and the other thing you're getting
14:13 : is is um
14:15 : you're getting it on wall clock time
14:17 : which means that
14:18 : you can tell when it's doing um input or
14:22 : output whereas
14:23 : with most profilers just do cpu time
14:27 : so it could be spending nine tenths of
14:30 : its time
14:31 : reading and you would never know it
14:34 : oh i see what you're saying i think if
14:36 : it were doing
14:37 : io time it would probably count towards
14:41 : the total time
14:42 : for the function that's one of the
14:45 : things you need to understand about any
14:47 : profiler is
14:48 : does it does it work on on wall clock
14:51 : time or on
14:52 : cpu time many of them assume that
14:55 : well i o time is stuff that you can't do
14:58 : anything about
14:59 : so why bother profiling it the thing is
15:02 : you might be spending nearly all of your
15:05 : time doing io
15:07 : and the profiler would never see it if
15:09 : you got a big program
15:11 : you know it could be doing io that
15:14 : doesn't really serve any purpose
15:17 : and you'd like to know that
15:20 : one problem that i kind of ran into when
15:23 : i was using this
15:24 : profiler in python it's all the
15:26 : functions
15:27 : in my program and i wasn't sure which
15:30 : functions were overlapping with
15:34 : which other functions i wanted to get a
15:36 : big picture of hey which is the part
15:38 : that's slow is it the database
15:40 : operations that are slow i wanted to
15:43 : sort of like um
15:44 : section my program off into these top
15:47 : level chunks
15:48 : and then be able to say hey this chunk
15:50 : is 40
15:52 : or something and that trunk maybe is 60
15:54 : i wanted to be able to do that
15:56 : it wasn't that straightforward for me
15:59 : looking at this
16:00 : table to to get that information out
16:03 : okay
16:03 : let me you hit a general point there
16:08 : one of the things that people are taught
16:10 : is to think of
16:11 : of a particular part of the program as
16:14 : being
16:16 : the bottleneck or the thing that takes
16:19 : time
16:20 : whereas if you look at uh stack shots
16:24 : what it's telling you is why the time is
16:26 : being spent
16:27 : not where i mean it tells you where the
16:30 : time is being spent
16:31 : but much more important is is why the
16:34 : time is being spent
16:36 : and if you know why then you can tell
16:39 : if you need to do it or not yeah that's
16:42 : there that's
16:42 : a an important distinction from just
16:45 : saying oh
16:46 : it's in the fubar function yeah yeah
16:49 : that is
16:50 : very true like to to sort of work around
16:53 : this limitation of reading
16:55 : this data i said i have a top level
16:58 : parsing function
16:59 : that is gonna contain all of the stuff
17:02 : that's dealing with the parsing so if i
17:04 : look at this line
17:06 : then i know more or less that that
17:10 : time is responsible for all of the
17:12 : parsing
17:13 : and that should be non-overlapping with
17:15 : the rest of the program
17:17 : i added a process command function that
17:20 : wraps most of the rest of the processing
17:23 : outside of the parse line
17:25 : just so that i have can have the report
17:27 : tell me
17:29 : hey this is the processing part of the
17:31 : program
17:32 : and that's the total tally of that but
17:35 : then later on i
17:36 : realized that even though it wasn't a
17:38 : lot of time
17:40 : spent in there there is one edge case
17:42 : where the processing command is calling
17:44 : the parsing too
17:46 : and that just throws the numbers off so
17:49 : you know that's sort of the disadvantage
17:52 : of this
17:52 : flattened chart like this i've looked at
17:55 : many profilers and
17:58 : they all do something screwy somewhere
18:00 : and
18:01 : uh but at all but in in every case
18:05 : the the problem is in the summaries
18:08 : um the problem is that they summarize
18:11 : and
18:11 : in the process of of doing the summary
18:14 : they throw away the information that
18:16 : actually tells you what they need to
18:17 : know
18:18 : actually there's an interesting profiler
18:21 : that is
18:22 : commonly used in the javascript
18:24 : community i would like to show it to you
18:27 : and see what you think of it um so it's
18:30 : it's a tool inside of chrome so if you
18:32 : go to the perform
18:34 : let's do it on the stack overflow site
18:37 : so i'm gonna record and then i'm gonna
18:40 : load the site
18:44 : and then when it's done loading i'm
18:45 : gonna stop recording
18:48 : that's good because i'm a bit of a
18:49 : newbie to uh javascript
18:52 : um i'm a newbie to see okay
18:55 : there's not a lot of javascript
18:57 : execution happening
18:58 : until the very end so
19:01 : uh so like all of this white space means
19:05 : no cpu usage uh this little
19:09 : this ladder part at the very end which
19:11 : you can zoom in
19:13 : there's some cpu usage and what you see
19:16 : here is a what they call it a flame
19:18 : chart
19:19 : oh yeah each each rectangle
19:23 : here is a stack
19:26 : it's a stack on the stack frame and then
19:29 : you can zoom in
19:30 : uh i think you can like pinch pinch to
19:33 : zoom
19:35 : like these very very thin lines they're
19:38 : just very thin
19:39 : rectangles and you can actually zoom in
19:42 : so much
19:43 : that you can see the function name
19:47 : you can think you want to know i'll tell
19:48 : you what's wrong with flame graphs
19:51 : okay yeah okay
19:54 : there can be a function whose
19:57 : whose elapsed time is very short
20:01 : but which is called in a thousand places
20:05 : and if there's a performance bug in that
20:08 : routine you'll never see it on a flame
20:11 : chart
20:12 : because the little boxes of where that
20:15 : function is called
20:16 : are sprinkled all over the place
20:20 : whereas with if you look at call stacks
20:23 : during that time
20:24 : you know that function will show up the
20:28 : percentage of time that it occupies
20:30 : got it yeah yeah i have seen
20:34 : situations similar to that when i when
20:36 : i'm debugging javascript
20:38 : large javascript applications most of
20:40 : the time it's like
20:41 : oh there's this really long rectangle
20:45 : and that's obvious and then i just zoom
20:48 : in
20:49 : and the reason it's long is because of
20:51 : all this stuff underneath it
20:52 : yep there's all the stuff underneath it
20:54 : but once in a while
20:56 : i have a situation where there's a lot
20:59 : of
20:59 : asynchronous events getting put on
21:02 : the queue to be executed later
21:05 : and that is actually taking a huge
21:08 : performance hit the
21:09 : number of little tasks to be
21:13 : put on the queue is so great that
21:16 : instead of getting one
21:17 : long rectangle you have millions of
21:21 : tiny slices tiny lines that are sort of
21:25 : sprinkled over a area
21:28 : and that's that's sort of the something
21:31 : you're talking about
21:32 : kind of matches that profile i call it
21:34 : hiding
21:35 : um performance problems have
21:38 : all kinds of ways to hide from you and
21:42 : you can you can think they're in a flame
21:45 : graph
21:46 : they're hiding from you they're all
21:48 : kinds of you know hot pants
21:50 : they can hide from you when i uh when i
21:52 : share your
21:53 : technique with my wife uh
21:56 : one thing she said was that well isn't
21:59 : that kind of
22:00 : tedious to do like you you probably
22:02 : don't want to do this by hand
22:04 : if a large part of your job has this
22:07 : kind of work
22:07 : in it what what do you think i have a
22:10 : standard answer to that
22:11 : yeah which is while you're trying to
22:14 : figure out
22:15 : how to work the profiler and what the
22:17 : limitations of the profiler are
22:19 : you can already finish the job with
22:23 : with the debugger and and
22:26 : part of the the reason for saying it
22:28 : would be tedious
22:30 : is thinking you need lots of samples you
22:32 : don't
22:34 : mm-hmm how many samples do you normally
22:36 : do
22:37 : ten and twenty times yeah that's you you
22:41 : wrote that in your post and that i
22:42 : followed that advice so i did
22:44 : i did 10 and then i thought oh i can do
22:47 : some more i did 20. the thing is
22:49 : the thing is if if you've got a bug
22:52 : that's worth fixing
22:53 : it takes enough time that you'll see it
22:55 : in a small number of samples
23:00 : yeah yeah yeah i think that the way you
23:02 : laid it out in your paper is really
23:04 : instructive you said like if there's a
23:07 : problem
23:08 : but let's say it's a you later on said
23:11 : it's
23:11 : maybe we should call it an opportunity
23:14 : but
23:15 : in either in either way you can think of
23:17 : it as
23:18 : well there's a section of of your
23:20 : program that's
23:21 : taking some percentage of time that
23:24 : percentage is
23:26 : related to how probable it is that
23:29 : you're going to be stopped
23:31 : inside yeah section of the code you not
23:34 : only got to know
23:35 : what what percentage of time it takes
23:37 : but whether it's necessary
23:39 : yes and then that's the context the
23:41 : programmer
23:42 : had and only the programmer can tell if
23:45 : it's necessary like if it spends a lot
23:47 : of time
23:48 : say writing a log file and then nobody
23:50 : reads it
23:51 : you'd say well why bother i mean i knew
23:53 : from
23:54 : simulating clinical trials that they
23:56 : have such a they have a thing called
23:59 : they call it alpha and beta okay but
24:02 : what that is
24:02 : is the probability of getting a false
24:05 : positive
24:06 : versus the probability of getting a
24:08 : false negative
24:09 : a false positive is if you say the drug
24:13 : works when it doesn't
24:14 : a false negative is if the drug
24:17 : does work but your trial doesn't
24:20 : know it and the the thing is
24:23 : when you're doing performance tuning
24:26 : a false positive is where you identify a
24:28 : problem that's not really a problem
24:31 : false negative is where there is a
24:33 : problem there and you don't see it
24:36 : and that that is the remarkable thing
24:40 : you can have one you can have one bug
24:43 : that's taking half of the time
24:45 : and you can have another bug that's
24:46 : taking a quarter of the time
24:48 : and you can have another bug that's
24:50 : taking 1 8 of the time
24:52 : and if you fix all three of those if you
24:54 : find them
24:55 : you're eight times faster but if you
24:58 : miss
24:58 : any one you're nowhere near eight times
25:01 : faster
25:02 : and uh if any one of those hides from
25:05 : you
25:07 : producing a false negative you're not
25:09 : gonna get it
25:10 : and also if you get the one that's
25:14 : 1 8 of the time that's not nearly as
25:17 : good as if you get the one that's
25:19 : half of the time yeah exactly if you if
25:22 : you get the 1 8 of the time but you
25:24 : don't get the one half or the one
25:26 : quarter of the time
25:27 : your speed up you say yippee i gained 15
25:31 : whoa who cares yep so that's
25:34 : that's the problem with profilers is is
25:37 : that
25:38 : real problems hide from them they give
25:40 : you false negatives