Let's Talk about Performance! (2)

We talk about performance again! We follow up on the previous week's plan to speed up the "recreate" program. Short version: it worked as predicted! Long version: watch the video. The Stackoverflow answer written by Mike Dunlavey that was cited can be found here: https://stackoverflow.com/a/1796715/5304

Transcript

The following transcript was automatically generated by an algorithm.

00:01 : like uh i shared some performance
00:03 : numbers
00:04 : and it was something like you know that
00:08 : i had a job the total
00:11 : time it took to run that job was 33
00:14 : seconds
00:15 : this this was the script to recreate the
00:18 : past dates of the program
00:20 : um and then i think we determined that
00:25 : about eighty percent of that
00:29 : oh well about twenty percent
00:34 : uh i'll do it twenty percent
00:37 : was uh spent in doing
00:41 : database stuff okay and then there's
00:43 : about
00:44 : eighty percent that's
00:47 : uh i'll just call it other stuff
00:51 : okay other stuff which includes parsing
00:58 : parsing and other processing
01:02 : but essentially it's it's mostly python
01:06 : do it
01:06 : doing its work with just
01:11 : you know statements loops and data
01:15 : structure
01:15 : stuff um so
01:19 : the plan was i'm gonna rewrite this
01:21 : whole thing in
01:22 : c uh and i already i already found that
01:26 : if i
01:27 : rewrote the parsing just the parsing
01:29 : part in c
01:31 : i could get like a 30 times
01:35 : 30 time speed increase
01:38 : um so so my thought was
01:42 : well if if just the parsing i can get a
01:45 : 30
01:46 : 30 x increase i can probably expect
01:51 : all of this stuff to get a 30
01:54 : times increase which which will probably
01:57 : shrink it very substantially we'll
02:00 : probably shrink it down to
02:02 : about here right okay yeah
02:05 : and then have so after this 30
02:08 : like i'm gonna this this eighty percent
02:12 : is gonna be one thirtieth the size
02:15 : of what it used to be which is gonna be
02:18 : like this
02:18 : tiny slice here so we're gonna end up
02:21 : with this
02:22 : i sort of expect the database part won't
02:26 : uh be improved because the database part
02:29 : is actually calling into the sqlite
02:31 : driver
02:32 : which itself is implemented in c in a
02:35 : low level way
02:37 : so i don't really expect that to improve
02:41 : so i expect the end result to be
02:45 : to be this portion here
02:48 : and when i did the calculations
02:51 : if i calculated that way i would end up
02:54 : getting
02:54 : uh like uh close total wise
02:58 : out of this 33 seconds i would be down
03:02 : to like eight seconds
03:06 : which which is about about five times
03:09 : better okay overall
03:12 : um and so so i rewrote the thing
03:16 : in c uh it took a lot of learning on my
03:20 : part
03:21 : there's a lot of love things about c
03:24 : that i learned so yeah basically
03:28 : we were here uh we i my prediction
03:32 : was i'm gonna get to about five times
03:36 : faster than the previous version than
03:38 : the python version
03:40 : and after i did enough work with the c
03:43 : version
03:43 : to be able to do a direct comparison it
03:46 : was
03:47 : more or less right there about a
03:50 : slightly faster than five times
03:52 : actually okay and then um
03:56 : and then oh i will show you some numbers
04:11 : are we
04:16 : oh okay i have a few
04:22 : oh okay i'll talk about that one later
04:28 : okay this was this was it so i ran
04:32 : this i did a calculate the fibonacci
04:35 : number for
04:36 : the 25th fibonacci number
04:40 : it was a simple program that just had a
04:42 : lot of
04:43 : execution in it um so on linux
04:47 : i was down to 4.6 seconds
04:51 : with the with the old python version it
04:54 : took 48 seconds
04:56 : the newer python version it took 44
04:58 : seconds
04:59 : so it's roughly 10 times
05:03 : improvement oh um initially it was five
05:06 : times improvement
05:08 : and then i found that the database was
05:10 : ticking most of the time
05:12 : after that and then i actually optimized
05:14 : the database part a little bit
05:16 : uh by using various sqlite tuning
05:21 : tuning parameters um just tweaking
05:24 : things here and there
05:25 : to try to get it to go faster okay and
05:28 : at the end
05:30 : what i ended up with is just to
05:33 : have all of the insert statements go in
05:36 : in the same transaction
05:38 : okay that that ended up being the
05:40 : fastest
05:41 : and then with with fewest configuration
05:45 : changes
05:46 : so it's just that way right now so
05:50 : so the loop that
05:54 : um
05:58 : so here it just says begin transaction
06:01 : and then this while loop does all the
06:04 : event processing one after another line
06:08 : by line
06:08 : and then just end transaction and that's
06:11 : that ended up being the most performant
06:14 : i i played with a bunch of these other
06:16 : settings
06:17 : which i found online that you can do
06:20 : these things
06:21 : and some of them did give me a benefit
06:24 : but at the end it was like this is all i
06:27 : needed
06:28 : so so these are commented out right now
06:31 : um but yeah so basically
06:34 : after that kind of performance tuning
06:36 : for the sequel light i was able to get
06:39 : 10 10 times improvement
06:42 : uh i did a i did a test on linux and i
06:45 : did a test
06:46 : on uh mac this is on mac
06:50 : the mac was actually more dramatic i i
06:53 : was down to 3.8 seconds and the python
06:56 : was
06:56 : took a whole minute to do it
07:00 : um
07:04 : yeah what else did i want to say
07:07 : um
07:12 : oh one one thing that i learned
07:15 : i don't know maybe we should wait until
07:17 : next time because we're
07:18 : kind of getting the end of the
07:22 : of our time um i found this
07:25 : um statistical sampling
07:29 : way of doing profiling which you didn't
07:32 : really need a
07:34 : profiler to do you can just kind of
07:36 : manually do
07:37 : and that's how i found that uh
07:42 : that's that's how i determined that the
07:44 : database was
07:46 : taking the most of the time like after
07:49 : this sampling method i found that
07:52 : 70 of the rough this is random
07:55 : probabilistic
07:56 : but i did 20 trials
08:00 : and 14 of them was
08:03 : in the database transaction phase
08:06 : so it's in the database and then a
08:09 : couple of other ones are still in the
08:11 : sqlite driver
08:12 : even though it wasn't the transaction
08:14 : phase this is
08:15 : before i did the performance tweaking
08:18 : and then after the performance tweaking
08:20 : i did the same thing
08:22 : uh after the performance tweaking i did
08:26 : the same thing
08:27 : and i i did 20 samples
08:31 : and then most of them were doing
08:35 : even though we don't no longer have uh
08:37 : database transaction stuff
08:39 : inside the samples because i only have
08:42 : one transaction and the transaction is
08:45 : finished at the very end
08:47 : but i still have most a lot of things
08:49 : going on in the database
08:51 : i mean in the sqlite driver so this is
08:54 : all sqlite driver stuff
08:58 : so that's how i was able to determine
09:01 : um that most of the time is being spent
09:05 : in the in the database still
09:09 : so so how did you create this report
09:12 : how do i create this report um okay
09:16 : um so
09:20 : so i actually went googling
09:23 : um c profilers
09:27 : and uh recommendations for i found this
09:30 : strict stack overflow question
09:33 : called recommendations for c profilers
09:36 : and then some of them gave me the
09:38 : recommendations one is called
09:40 : g proof the other one is call grind and
09:43 : k
09:44 : cash grind which is part of val grind
09:47 : which i've been using for finding memory
09:50 : leaks
09:51 : and memory usage problems which is
09:53 : extremely good for that
09:55 : so i did try both of them but i didn't
09:58 : have a good luck with either one
10:01 : just because of different reasons like
10:03 : the g proof
10:04 : gave me some very weird numbers
10:07 : so i didn't trust it and maybe i'm not
10:10 : using it right
10:11 : or it has a bug on my system or whatever
10:15 : and then this call grinding it required
10:18 : a gui that only works on linux
10:20 : and i have a linux computer but i don't
10:22 : have a gui for my linux computer because
10:25 : it's in the cloud
10:27 : um but then i read this guy's
10:30 : answer and this is so funny because this
10:33 : guy is like
10:34 : you don't need a profiler here's what
10:38 : you do
10:38 : and then like he's basically like
10:40 : extremely enthusiastic
10:42 : about his methodology for performance
10:45 : profiling
10:47 : and he explains the whole thing uh in a
10:50 : series of
10:51 : stack overflow answers
10:55 : like historically he has written so many
10:58 : of these
10:59 : that he just links to them now and so
11:02 : this is like a summary post
11:04 : and so i just read through his stuff
11:07 : read through
11:08 : a few of his stack overflow answers
11:11 : and he even in one case he made a video
11:15 : showing how you would do it so basically
11:17 : this is what you do
11:18 : um you run the job uh it has to be a job
11:22 : that's
11:22 : kind of long running and and the way i
11:25 : made that is
11:26 : i just gave it so much data that it
11:28 : necessarily has to be long running
11:30 : right so um so if i do this
11:37 : for example i run that on this log
11:40 : it'll be a very long running process and
11:43 : then what i do is
11:44 : run it into the debugger
11:48 : run it inside the debugger and then i'm
11:50 : gonna uh
11:51 : use the r command to get it to run and
11:54 : now it's running and then
11:56 : while it's running i'm gonna just
11:58 : interrupt it
12:00 : uh by hitting ctrl c
12:03 : okay and now it's i just stopped the
12:05 : program
12:07 : at whatever point in time it was at
12:11 : well i press ctrl c and at this point
12:14 : i'm actually
12:14 : paused inside the program and i can do a
12:18 : stack trace by using the bt
12:21 : command which stands for back trace and
12:24 : now i have the stack trace of the
12:26 : program
12:27 : at wherever i stopped it
12:30 : okay and so so you just so this is a
12:33 : sample
12:34 : so this is a sample now and uh
12:38 : and the theory is uh if
12:41 : the slower parts of the program are more
12:44 : likely
12:45 : for me to stop inside of right
12:49 : what okay okay does that make sense
12:53 : like if if if there's a fast part
12:56 : of the program it's very unlikely that
12:59 : if i just randomly stop you
13:01 : it's going to be in the very fast part
13:03 : because that just went by really fast
13:05 : but if it's a the program is spending a
13:08 : lot of time in its slow parts
13:10 : i stop it it just has a higher
13:13 : probability of stopping at the lower
13:15 : part
13:15 : the slow parts the slower the part is
13:18 : the higher probability i'm going to stop
13:21 : in the inside there
13:24 : okay so that's the theory so i just do
13:26 : this
13:27 : like several times i did it 20 times
13:30 : okay and then i ended up with this
13:34 : report so
13:35 : sample one i was there
13:38 : you can see the entire stack trace which
13:40 : is really nice because like
13:42 : a lot of this i wrote right and this is
13:44 : mostly my code
13:46 : until we get into the sqlite driver
13:48 : that's not my code anymore but i can
13:51 : sort of i can you know get i can
13:54 : understand the context basically
13:56 : so so i had 20 of these samples and i
14:00 : looked through each
14:01 : and i just categorize them in the way
14:04 : that makes sense for me
14:05 : so i summarize them further here
14:09 : so here like five of the 20 times
14:13 : i landed on this exact same line okay
14:17 : uh one of the 10 20 times i landed on
14:20 : this line and then 6 out of 20 i landed
14:23 : on this line
14:25 : so you can get an overview of what
14:27 : happened and obviously the ones where it
14:30 : kept land on that same line
14:33 : several times well yeah that's probably
14:35 : a
14:37 : bottleneck or something or it's just
14:39 : happening a lot
14:40 : in the program but but at a higher level
14:44 : view though
14:45 : i further categorize this to
14:49 : uh like if you look at this line of code
14:52 : that's inside the sequel light driver
14:54 : that's inside the sequel light driver
14:56 : that's inside the c cooler driver
14:58 : i determined that 80 of my samples
15:02 : at the code was spending time inside the
15:04 : sqlite driver
15:06 : and uh three times out of 20
15:10 : it was not inside of the sequel light
15:12 : driver
15:13 : two times out of 20 it was inside the ut
15:17 : hash library which is the
15:19 : hash table library that i'm using a c
15:22 : does not have built-in hash tables so i
15:24 : had to grab a library
15:26 : so that i have hash tables um
15:30 : so so there's 10 that might the hash
15:33 : table
15:33 : might be responsible for but the 85
15:38 : is more or less is uh that the database
15:42 : driver
15:42 : is responsible for okay and
15:45 : obviously this is not super accurate
15:48 : because i only it's a random
15:51 : statistically based thing i only took
15:54 : 20 samples but uh obviously if you did
15:57 : this 100 times
15:58 : you will get more accurate answers but i
16:01 : think
16:02 : more or less you can see the big picture
16:04 : from
16:05 : just that many yeah exactly
16:08 : yeah i like this mess this is great
16:11 : yeah i like it too because it's very uh
16:14 : very basic you don't you don't need a
16:17 : lot of fancy tooling to do this you can
16:19 : just do it yourself
16:21 : and i can i can see it wouldn't be very
16:23 : hard to
16:24 : automate this process yeah exactly
16:28 : yeah okay