00:00:15.599
I said it once already in case I'm going to be handing out salami actually let's start doing that
00:00:22.160
now take one pass it down uh these are the ingredients like I said if you're
00:00:27.640
allergic to anything like of these then you probably don't want to eat it so
00:00:33.440
okay all right uh I have 235 slides and 45 minutes so let's
00:00:40.399
go all right um I'm not going to introduce myself no time I'm not going to tell you where I work no
00:00:47.239
time I'm insanely nervous but I can't tell you about that I don't have any time but uh there's always time for
00:00:55.559
cats I have I have a cat his name is Gorbachev puff puff thunderhorse and I like him very much uh but I didn't
00:01:02.559
realize like when I when I got a cat like I thought he would be my best friend and we'd go like bicycling stuff
00:01:09.320
together and like go to the park and swimming and all that but instead he just sleeps all the time so whenever I
00:01:15.600
take photos of him he's always just yawning like that's basically it all the
00:01:22.520
time it's kind of disappointing but I love him anyway and you can follow him on Twitter his Twitter address is gorby
00:01:30.079
puff uh so I was going to I was I titled
00:01:35.640
this talk like real time salami but um honestly like I don't get to see all of you but maybe once a year so instead
00:01:43.040
this is like my summer vacation I want to tell you guys all about the stuff that I did for the previous year we are
00:01:48.840
going to talk about salami though so don't worry uh just there will be other
00:01:54.000
things besides salami we're actually going to talk about food stuff work stuff and hacker stuff I'm still stoked
00:02:00.079
about the hacker stuff I love Ruby conf because I think this is a hacker conference um so I'm really excited to
00:02:07.159
talk about that first off is the food stuff like yesterday um kichi sang gave
00:02:12.520
a presentation and he was a professor well
00:02:28.120
butcher so we're going to talk about meat curing and the first thing uh the first thing I learned about meat curing
00:02:34.319
was that um botulism does not mean anti- robots
00:02:39.360
uh which I thought was the cause of the Great robot uprising of 1863 and it is
00:02:45.560
not Wikipedia must have its facts wrong so someone should get on that um but
00:02:51.599
actually the first thing I learned is that when you're making salami you want to use metric like please use metric and
00:02:57.800
the reason you want to do this is because like you're never working with um recipes
00:03:03.239
with a particular amount you're always working in percentages like you need to say oh I have you know so many kilos of
00:03:09.599
meat and I need to calculate like the amount of salt that goes into this into this particular mix and it's going to be
00:03:15.159
3% and calculating that crap with pounds sucks so seriously use metric when
00:03:21.159
you're doing this uh we're going to cover Hardware first like I use a wine fridge is what it looks like it's my wine fridge I cure all my Meats in the
00:03:27.879
wine fridge and the reason I do that is we need to keep control of the temperature uh the temperature needs to
00:03:33.920
stay between 60 and 70° F I know I said use metric but I'm not smart enough to
00:03:40.040
switch to Celsius uh and I use this for controlling the temperature and this is
00:03:46.640
this is actually for controlling temperature on uh kegs like Brewing stuff so people use this a lot for
00:03:52.920
making loggers if I remember correctly but it also works really well for curing salamis uh I use an ionizing humidifier
00:03:59.879
you need to control the amount of humidity that's in the that's in the box and you want to use an ionizing
00:04:05.439
humidifier because it doesn't emit any heat so it creates humidity but it's not hot we don't want our get we don't want
00:04:12.319
our box to get hot and then I'm lazy so I use a humidity controller I need to
00:04:17.799
set a particular humidity and this thing keeps the humidity in the box at that particular level and the last important
00:04:23.560
thing is fans you need to keep a good good air flow inside the box if you don't have good air flow then your Sal
00:04:29.840
will mold and that's kind of gross so the other Hardware you need is grinder a
00:04:35.880
grinder I use a kitchen aid attachment this is totally great you can use it um and it's pretty cheap the most expensive
00:04:42.840
thing I have is this uh stuffer and it's totally worth your time you don't have to get one of these uh good quality one
00:04:49.639
costs about $250 you don't have to get one but it saves you so much time and pain that it's completely worth it uh as
00:04:57.560
far as the ingredients are concerned uh it's about 80% meat so this is about an 80% pork shoulder mixture 20% fat
00:05:05.639
mixture and then we calculate the other ingredients based on uh the meat and fat
00:05:11.560
totals so we weigh those together and then figure out how much of the other
00:05:16.840
ingredients we need to add to the meat based on that weight so uh you use about
00:05:22.160
05% sugar so you take the weight multiply by 0.5% and you figure out how
00:05:27.520
much dextrose you need to add to the add to the meat and this is for the bacteria
00:05:33.280
to eat we're going to you introduce bacteria into the meat the bacteria eats the sugar and produces acid uh we also
00:05:39.639
add salt and the reason we add salt is to prevent bad bacteria from growing you need to add enough salt that bad
00:05:45.759
bacteria it inhibits the growth of bad bacteria but does not inhibit the growth of the bacteria that you inoculate the
00:05:51.600
meat with um you use pink salt cure number two which is a mixture of
00:05:57.880
nitrates and nitrites and and it's colored pink because eating this stuff can kill you so you don't want to get it
00:06:04.080
mixed up with regular table salt uh the thing is like it's about 95% salt and
00:06:10.560
about 5% nitrates and nitrites so the amount that you have to eat to kill you
00:06:15.840
is actually a lot you'd probably be like this is way too salty I can't eat this much so but still it's colored pink
00:06:22.639
because you probably don't want to eat that stuff um the other important thing is that uh this contains nitrates and
00:06:29.039
nitr the nitrates release nitrites over time and this prevents uh nitrites prevent
00:06:35.759
the growth of botulism so this is the reason we want to add this to the meat is because we don't want to have botulism in our meat also the nitrites
00:06:42.960
change the meat colors and it's pretty obvious to see like the top there is zero hours of curing and the bottom is
00:06:49.160
24 hours and you can see like it's definitely changed color between the two and then we have to calculate how much
00:06:55.080
bacteria we put into the meat and that's 0.012% bacteria which is a tiny tiny
00:07:01.400
amount I think maybe like this I I cured five kilos and I think that was something like a gram or two grams or
00:07:09.840
something like that I had to buy I had to buy this like scale that only goes up to 100 grams I totally felt like I was a
00:07:16.520
drug dealer or something buying a scale online uh now this particular bacteria
00:07:22.479
takes about 30 days to cure your meat you can buy another bacteria that takes less time uh supposedly they produce
00:07:28.840
different Flav flors I'm not sure I've never tried the short curing one I only do long cures and that's mostly because
00:07:34.840
I got shipped like I think I got a packet of bacteria that's like maybe I
00:07:41.960
don't know 50 grams which should be enough to last me for the rest of my life I think so the next thing that you
00:07:49.440
need to add are spices um like most cured meats are most
00:07:55.120
cured meats are pretty much the same uh except for the spices so so like the
00:08:01.319
meat and fat content is pretty much the same all this other stuff that we looked at is the same the only thing that
00:08:06.919
really changes is possibly you increase fat increase or decrease fat but mostly
00:08:12.159
it spices so the next thing I want to look at is the curing environment um you need to keep wind speed high for the
00:08:18.759
first three days the first three days we keep the uh we keep the temperature high
00:08:23.879
so we keep the temperature around 70° and our wine fridge stays between 55
00:08:29.440
and 65° and that kind of sucks because if you notice from my last graph we need to be at 70° which is why I have to use
00:08:36.039
that beer thing so you can either use the beer temperature controller or you
00:08:41.360
can do what I did and hack your fridge this is a little microcontroller that I've have hooked up to the fridge to
00:08:46.560
control it to be 70° uh we also keep the humidity at 90% for the first three days and then we
00:08:52.480
drop it down to 65% for the rest of the Cure you need to keep the wind speed
00:08:58.200
high during that 90% % humidity because that's really the time when bacteria are going to grow so if you see my setup
00:09:05.000
here you can see like oh and the arrows are misaligned that sucks okay I had to re I had to resize for this projector
00:09:12.279
and now the arrows are totally wrong anyway right there in the middle we have a is the temperature controller and
00:09:17.920
behind it you'll see the uh humidifier and you can see like this is a picture
00:09:23.160
from behind the box the humidifier has a tube that runs into the box and that's actually what pipes the humidity into my
00:09:29.399
box so the humidifier doesn't take up any room in the box and I want to tell you a little bit about um
00:09:35.360
addiction this is a face of an addicted cat um these boxes aren't these boxes
00:09:41.360
aren't built to have 90% humidity inside right so all all fridges have a little
00:09:47.880
drip tray in the back where when condensation when water condenses the water drips out the back and out into
00:09:54.480
your you know apartment or whatever in a little tray and then that that evapor operates but they're not built to handle
00:10:01.200
90% humidity so my little drip tray was filling up so what I did is I ran a
00:10:06.399
little pipe down to a larger container and that would start to fill up with water and I noticed that my cat was
00:10:12.480
starting to drink the water and
00:10:18.040
um my fiance says to me you know you can't he loves drinking that water it must tastes like salami and I'm like no
00:10:24.880
it can't possibly taste like salami it's it's condensed on the on the cooling
00:10:30.959
plate in the back how is it possible it will taste like salami and she kept saying to me it tastes like salami it'll
00:10:36.000
taste like salami and I'm like no no no so finally I grab a spoon I'm like
00:10:41.360
fine I'll try it try it it totally tastes like
00:10:47.880
slamy so I had to co like I had to put a cover on it and actually like tape the
00:10:53.079
cover down so that he wouldn't like lift it off and drink the salami water so uh anyway I want to talk a
00:11:00.600
little bit about safety and why this meat won't kill you um this meat stay if
00:11:06.000
any of you have been in the food service industry like me you'll know about the danger zone this meat stays in the
00:11:11.279
danger zone for a very long time so why doesn't it kill us the reason it doesn't kill us is first off we add salt and
00:11:17.839
this salt prevents bad bacterial growth so the next thing that we add is we add nitrite and this kills off
00:11:24.560
botulism but you have to be careful with the nitrite because 22 Mig per kilogram
00:11:30.000
is a lethal dose so if you weigh yourself and you multiply out 22 milligrams per kilo of your body weight
00:11:35.639
you can kill yourself with nitrite so you have to be careful uh but we use pink salt for safety it's pink pink
00:11:42.200
means safety right so the next thing that keeps us
00:11:47.320
safe is acid and this is produced by the bacteria that we introduce into the meat the meat eats the sugar the or the
00:11:53.279
bacteria eats the sugar the bacteria produces acid the acid prevents other bacterias from growing and you can
00:11:59.839
actually see this happening by measuring the pH of the meat as you go over time so what I do to check for safety of my
00:12:05.360
meat is I measure the pH I bought it this Fancy Pants pH meter and I read the
00:12:10.720
pH on it the other thing is water loss uh after about 30 days I measured about
00:12:16.600
a 45% water loss which kind of sucks because it still has the same amount of calories it's just more compact it's not
00:12:23.040
nice for somebody who's trying to watch their figure like me especially when it's sitting next to
00:12:28.079
your desk anyway so 30% minimum water loss is what you need to look for so if you're curing
00:12:34.320
meat like you can tell when it's done when you hit 30% I usually go down to 45
00:12:39.440
but since there's no water no bacteria or molds can grow after the water has exited the meat so we have shortterm
00:12:46.959
short-term safety which is our salt and nitrate medium-term safety which is the acidity of our meat and the long-term
00:12:52.040
safety which is the amount of water in the meat and the final thing is that we can introduce mold so if we're having a
00:12:57.800
mold problem we can introduce our own molds to the outside of the salami if you've been to a fancy meat place you
00:13:03.920
might have seen salami that's covered with like white stuff that is mold don't be afraid of it it actually makes the
00:13:09.760
salami taste better so now we're going to move on to work
00:13:15.720
stuff sorry so we're going to talk about I want to talk about streaming and
00:13:21.519
fermented sausages so will we're going to talk a little bit more about
00:13:26.920
salamis this is a salami party isn't
00:13:32.880
it we'll look at how to get the salami data online uh and but I also want to
00:13:38.399
show how streaming Works in rails 4 but first I want to talk about template rendering today in rails 4 specifically
00:13:44.600
like we're going to talk about template rendering but we're going to talk about it from a fairly high level I don't want
00:13:49.839
to dive into the internals today and it probably wouldn't fit on my slides
00:13:55.399
um so we're going to talk about how template rendering works and then we're going to contrast that against streaming
00:14:01.800
today template results are buffered so when you have you write out all of your Erb or your hamler or whatever all of
00:14:07.040
those results are buffered and then sent down to the client now the thing that sucks about that is that clients are
00:14:12.320
blocked where they're while they're waiting for rails to work so while you're figuring out all that template stuff calculating it putting it into
00:14:18.680
memory the client sitting there going okay cool I'm waiting around waiting around and then finally it gets some
00:14:25.000
data it can actually do some work it would be nice if we could send down some data so the browser could actually get
00:14:30.440
to work well we're doing some calculations at the same time the other thing that sucks about this type of
00:14:35.519
template rendering is that the entire page must fit in memory which means that if you have a very large page you could
00:14:40.800
have like a huge amount of memory growth with your particular process and that kind of sucks too uh the other thing is
00:14:47.800
that like we can do IO and CPU calculations in parallel even in even in
00:14:53.800
MRI so we're not going to get totally into totally into parallelism ation in
00:15:00.079
MRI today but you can actually do IO and CPU calculations at the same time so if
00:15:05.120
we can get that sort of parallelization out of our out of our Ruby process and out of our clients like what is the
00:15:11.120
point of buffering why are we buffering all this data so with that in mind this is why I created action controller live
00:15:17.880
action controller live is a module that you can mix into your controllers and get an IO type object on your response
00:15:25.279
so the way you use it is like this you mix it in and then can do stream. write and you can actually write out data and
00:15:31.480
it gets sent down to the client get it gets sent down to the client in real time uh I wanted it to act I wanted
00:15:38.240
response. stream to act like an IO object and the reason I wanted it to do
00:15:43.399
that is because I buy into the Unix philosophy which is everything as a file
00:15:49.000
so I want to treat everything as a file including my response which is why I was really set on having an an IO object in
00:15:55.680
my response so I want to look at how we actually implement this inside of rails like how do we how do we actually do
00:16:02.079
this let's dive into the internals of how action controller live Works uh we're going to look under the hood and
00:16:07.720
see how it works this is the API that we want to have like this is what we want it to look like we want to set a response status set some headers write
00:16:14.399
to our stream and close the stream off so we need to accomplish this but what we have is this this is the rack API we
00:16:21.000
have to return all of that stuff at the same time even though we want to do it we want to be able to do that peace meal
00:16:26.480
but rack wants us to return it in one One Step ideally we could calculate this stuff lazily and write it out to the
00:16:32.560
client as soon as we calculate it so the way the way that we start is we need to
00:16:37.759
wrap this with a response object wrap with a response object that looks something like this and I've actually simulated simulated rails down here at
00:16:44.959
the bottom like this is basically what happens inside of rails we set the response on the controller we call your
00:16:50.680
action on the controller and then we have to return all this data back up the back up the rack stack but the problem
00:16:57.240
here is that we're still buffering we haven't actually solved our problem you can write to the stream but the stream is still buffered so how do we solve
00:17:04.400
this we need to be able to do calculations in the controller and return back up the stack at the same
00:17:09.679
time we do that with a thread so we can say okay let's call the controller index in a thread cool so now we're
00:17:16.199
calculating the controller index in one thread but we turning up the stack in the other the problem with this is that
00:17:21.559
well maybe you didn't finish writing out the headers and it's already returned up the stack and started writing data out
00:17:27.120
to the client we're screwed what do we do we have to block we need
00:17:32.160
to block right here right there stream. we we need to block there until somebody's actually
00:17:38.919
written data out so you have to calculate all of your headers set all the headers and then as soon as you
00:17:44.600
actually want to write the body of the response then we'll say okay time to return back up the stack and start emitting data to our response the way we
00:17:51.720
do this the way that we accomplish this is we use a latch inside of the buffer we say Okay Main thread the main main
00:17:58.559
thread calls A weit and A weit puts the main thread to sleep and the main thread
00:18:04.039
just sits there until somebody calls release on the latch now when you say response. stream. right that says okay
00:18:11.880
we're now going to release the latch and once we've released the latch then the main thread comes back awake and says
00:18:18.159
okay let's return back up the stack so this way we can actually stream data out to the out to the client and not have
00:18:26.600
our headers get all messed up so this is cool but what can we do with
00:18:32.440
this like why should we be excited about this particular thing I'm excited about this from a rails internals perspective
00:18:38.960
and I'll show you why the reason the reason I'm excited is because I want to be able to do streaming Erb we can do
00:18:44.840
this today but it's kind of hacks and I'm going to show you how we can accomplish this with an IO object and
00:18:51.480
the way we can discover how to do this is if we take a look at Erb we can create a new Erb template here and we can actually look at the source of the
00:18:57.679
Erb template temp this is how you do it doc. Source will show you the show you the
00:19:03.159
source and this is what the source looks like this is our Erb template compiled down and you can see we have a string
00:19:08.480
there and we can catenate to the string and we set some encoding on it and we're done but we can actually subclass the
00:19:14.640
Erb template and set the output I the output variable to be whatever we want to and the method name to be whatever we
00:19:21.600
want to so we don't have to use concat and we don't have to use a string which means that this code will turn our Erb
00:19:27.520
template into this standard out. WR whatever right and now we're actually
00:19:33.240
writing to a stream we run this program and boom we see we see uh output on the
00:19:38.919
on standard out and the reason I like this approach is because we can say okay
00:19:45.200
well we can change the io object to anything we want as long as it quacks like an IO object which means that we
00:19:51.480
can choose streaming or buffering depending on the io object our code path stays exactly the same whereas the today
00:19:58.480
if you look at the rails code the source code today we actually have two distinct code paths one for doing our normal
00:20:04.720
template rendering and the other one for if you say like render streaming true it's like two completely different code baths if we actually had Erb templates
00:20:12.000
that did streaming we could do uh we could just make this decision based on the type of IO object that we have and
00:20:18.760
we don't have to have multiple code paths the other reason I'm excited about this is uh for use from web applications
00:20:25.880
and obvious use for this is infinite stream but I don't think that that's the most interesting use case for using uh
00:20:33.080
IO objects on the response stream I think the most interesting use case is server sent events now a server sent
00:20:39.400
event this is what a server sent event response looks like this is the like if we telled it in and took a look at the
00:20:45.360
response this is what it looks like now you can see the content type there is text event
00:20:50.440
stream and uh each chunk of the event each event has an optional name so this
00:20:56.679
one's nam's ping and then we have a data payload which can be anything but most people just do a Json encoded like
00:21:03.840
whatever just encode your stuff as Json and put that in the payload now on the client side of this we in the JavaScript
00:21:11.320
that's executed on the client side we say okay we create a new event source and this is okay the arrows off thank
00:21:16.760
you resizing awesome anyway it's there that SL control that is our Event Source
00:21:22.919
and that makes a request to the server and that's where our server andent events come from now we are list thing
00:21:28.440
for man yeah keynote W anyway so reload is
00:21:38.120
the the name of the event that we're looking for and every time we get that event this function gets executed and in
00:21:43.679
this particular case we're just reloading the web page right now with this with this JavaScript we can
00:21:50.640
actually do real-time browser communication oh my God it's too small that
00:21:56.120
sucks we'll zoom in this is a a demo of doing some real time Real Time Communication with the browser so we're
00:22:02.240
loading a page here this is our users page my users page and hopefully I'll zoom in on this please well okay yes
00:22:10.000
we're changing the file and you can see when we change the file the page gets automatically
00:22:16.640
reloaded so cool we can see that reloading and I'm a CSS master I'm
00:22:22.960
totally changing the CSS there look at these Styles beautiful
00:22:36.200
I'm going to demo here is like I'm opening up the rails console there and I'm actually creating a user I know this
00:22:42.120
is small so I'm going to describe it I create a user and you'll see when the user is created the page reloads and we
00:22:47.960
actually have a new user listed there on the page so it's automatically reloading when we mod manipulate the
00:22:54.159
database so how did this how does this magic work the Magic in this part particular
00:23:00.480
application works this way we have web server which is Puma FS events watches our file system and these are running in
00:23:06.400
the same process when FS events notices that our file system changed it it tells the browser we send a message down to
00:23:12.559
the browser the way that I did the um database manipulation side is that the
00:23:17.600
server actually starts up a drb server inside the same process as the web server our console connects to the drb
00:23:23.799
server over over a socket a well-known just some well-known port and then
00:23:29.039
anytime we make we manipulate the database we send an a message up to drb saying hey we did something and then
00:23:35.000
that sends a message down to the browser and the browser can reload so this is how we can do inprocess communication
00:23:40.919
and send events to the browser that way so I told you we would talk about salami so let's do that real time salami I've
00:23:47.480
actually built a salami monitoring system for my for my box on the left there is a beagle board on the right is
00:23:53.440
a TI Launchpad it's similar to a uh what is the other one one I can't remember
00:23:59.120
Arduino it's similar to an Arduino that actually pulls the data I have a sensor mounted Inside the Box it pulls data off
00:24:05.559
the sensor and then post to a website and I actually broadcast the data and the way that I do that is I have an
00:24:11.240
observer sitting in process I'm using a threaded web server the salami posts to the create the create action here and
00:24:19.240
then that sends a message to The Observer The Observer notifies any any browsers that are sitting on any threads
00:24:24.799
sitting on the index and they're able to update so have a message bus that's built on top of observable from standard
00:24:31.520
library and uh when a browser hits the index page we just add an observer and
00:24:37.640
every time the Observer fires that code block is executed and we add an event to the queue and then the queue is consumed
00:24:43.799
inside the main thread and that is written out to the response our publisher is much more simple our
00:24:49.080
publisher just adds our Json data onto the onto the message bus just publishes
00:24:54.480
to the message bus and then everybody else is notified and this is really really cool except that we don't have any feedback so I wanted to have
00:25:00.919
feedback and the way I did that was I integrated g- charts and S so whenever I Got a notification it would update my
00:25:06.399
chart so now we can see I have a chart of my this is like this is like my Danger Room have it on a monitor I'm
00:25:13.279
like okay what is what is the humidity of my box today that top blue line is
00:25:19.960
the humidity and the bottom red line that's actually my temperature this isn't an actual graph of my uh salami
00:25:26.440
box I was actually just blowing on it because blowing on the sensor cuz it's not like the salami box isn't actually
00:25:32.120
that interesting that graph isn't actually that fun so okay oh my God I'm only done
00:25:39.840
110 slides hacker stuff we're good I got 20 actually I got
00:25:45.559
20 minutes we're doing good okay great all right hacker stuff yes yes hacker stuff we're going to talk
00:25:53.480
about the Ruby VM so we're going to talk about the Ruby virtual machine a bit and then we're going to talk about D TR
00:25:59.120
stuff and then I think we'll finish up the Ruby virtual machine is stack
00:26:05.200
based and um any of you that have used an HP calculator like I used in high
00:26:11.480
school uh will be familiar with stack based stack based virtual machines I actually loved using an HP calculator in
00:26:17.720
school because people be like hey can I borrow your calculator and i' be like yeah totally and then they and then
00:26:24.600
they'd be like well how do you I don't understand how you add numbers that's work and I'm like well you just do two
00:26:30.600
enter five plus and they're like I have no idea have your calculator back and
00:26:35.640
I'm like oh thanks so anyway I thought that the best
00:26:41.600
way to demo a stack based virtual machine would be with postcript so uh this is the ghost script ghost
00:26:48.840
script um interactive console and go postcript is all stack based so we start
00:26:55.039
out the right hand side is our stack and the left hand side is is actually the ghost script the ghost script uh repple
00:27:00.799
so we we do two and then we hit enter and when we hit enter two is pushed onto the stack we hit three and then we hit
00:27:07.200
enter and three is pushed onto the stack and then we run add we say add and then that pops off the stack and adds those
00:27:13.399
two values together stack just displays the stack and then pop pops a value off
00:27:18.600
the stack so if we want to get actually if we actually want to get access to the
00:27:25.279
um to the bite code that's written in Ruby well we just use the Ruby VM
00:27:30.679
instruction sequence this code here we say okay this actually compiles it down so is on the left hand side is our
00:27:37.080
compiled instruction sequence and we can disassemble it by saying like puts is. dis dism and that will show us the uh
00:27:45.440
instruction sequences and I have more messed up arrows on the left side is the instruction names and on the right side
00:27:51.880
is the parameters to those instruction names but like we read those names and you're just like IM immediately you're
00:27:58.039
just thinking to yourself what does it mean and it's easy to figure out what it
00:28:03.600
means you just go into the Ruby source code and find this file insns dode it has all of the bite code written out and
00:28:11.360
documentation above each of the bite code names it's actually very simple to read you just read the doc all of them
00:28:16.840
are documented you just look for the bite code that you want to know about and then read the documentation there
00:28:22.679
and it's actually very easy to understand so the bite code that we're dealing with in this example is Trace
00:28:28.559
put object opt plus and leave uh Trace is for set Trace funk I don't know if you guys have looked at this but it's
00:28:34.519
like basically you can get events of what's happening in your machine you register a function put object just
00:28:40.480
pushes onto the stack opt plus actually does the addition and then leave leaves
00:28:46.159
that particular scope so we're going to take a slight detour a little bit of a slight detour um that may or may not be
00:28:53.440
related to what we're looking at uh we can actually Translate these to postcript
00:28:59.480
so on the left side is our function def this is postcript on the left side is our function definition on the on the
00:29:05.240
right side is the actual function code itself so we're defining Trace put object op plus and leave which means
00:29:11.120
that we Define that in ghost script and we can actually run the Ruby bite code in postcript here so that is a
00:29:18.360
translation of the Ruby bite code and we can get access to the Ruby bite code in Ruby manipulate it and then translate it
00:29:25.919
into something that we can run and post script so what does this mean 2013 print
00:29:34.159
Ruby okay I I'm telling you now 2013 print Ruby and the the thing that's
00:29:40.000
awesome about this is is massively distributed you can distribute this out to all of your printers everywhere
00:29:45.240
everywhere people will be like why can't I print anything and you'll be like listen man it's the cloud The Cloud of
00:29:50.760
printers look you don't need to print anything this is the future of distributed computing so yes exactly
00:29:57.360
take that node.js I've actually been studying nodejs lately and I discovered that the only
00:30:03.519
important languages are CC Plus+ JavaScript and postcript
00:30:08.640
fact sorry that wasn't a slight detour it was a massive detour I apologize so let's actually let's go to our actual
00:30:14.600
slight detour which is this is the actual slight
00:30:19.720
detour we can get our instruction sequences by calling 2A so this gives us this gives us access to the instruction
00:30:26.080
sequences don't read this you don't need to you can just see like here are our instruction sequences that's cool we can
00:30:31.720
do that with with that object we can eval the eval these instructions by just calling eval so that runs them and the
00:30:39.080
other thing we can do is eval there we go that runs them and the other thing we
00:30:44.480
now we can't do this we can't load instructions that sucks so we can't come up with our own we can't come up with
00:30:50.240
our own instruction sequences and load them can't do it or can we if you go
00:30:55.399
take a look at I sequence. def uh more messed up arrows anyway if you go look
00:31:00.960
at I sequence. def you'll see that there's a load that's commented out and a function pointer there I seek s. load
00:31:08.799
and we can actually get access to that via Ruby standard library with DL so
00:31:14.480
this don't read this don't bother I'm going to describe it what we do is we say okay well let's get a handle to
00:31:26.159
the those arrows were totally helpful weren't
00:31:31.519
they anyway we get a handle to the shared library and we look up that function we can get the address of the
00:31:37.000
function and we can create a pointer to that function and then we can actually call that function using ffi from Ruby
00:31:43.440
which means that we can monkey patch a load onto the instruction sequence and actually eval new instructions I'm sure
00:31:50.120
koichi is getting upset with me right now I'm sorry so now we can say like
00:31:55.200
okay let's compile some sequences and then load them and then eval them so we can actually take a sequence copy it
00:32:01.880
over to a new one and eval which means that we can go in and do manipulations on the instruction sequences and then
00:32:06.960
load them so this changes all of our this particular code changes all of our numbers to tens so we'll do all of our
00:32:13.799
calculations just all right we change it all to tens boom eval that's all we need we're done so I highly recommend this
00:32:20.799
technique for when your code is a little too readable or like when meta just
00:32:25.880
isn't meta enough and the final thing that I recommend this for is like if you really need to take your app from low
00:32:31.399
scale to rafle scale like this is this is it the other thing like this works on
00:32:36.840
every Ruby I personally guarantee it what no I am not lying I no I'm not
00:32:46.760
lying okay let's have a talk about this later okay buddy
00:32:52.559
anyway what else can we do with this those are some fun hacks but what else can we do with it we can do some micro
00:32:58.159
optimizations okay so the first thing that we can do with these micro optimizations and hopefully you guys
00:33:04.159
don't know about this I hope the first thing we can do is we can do some benchmarks so we'll have some benchmarks
00:33:09.679
like we find a slow slow bit in our code a friend of mine from GitHub says hey Aaron rails is super slow why is it slow
00:33:17.799
this thing is slow and I'm like I don't know I'll take a look at it and he sends me a test case and this is the test case that he sent me so I'm like okay let's
00:33:24.039
take a look ah the graph
00:33:40.840
useless all right one side of this graph is arrel and the other side of it is my SQL 2 and actually if we're able to look
00:33:48.200
at if we were able to look at the top of the graph the top of the graph would be active active record relation and if we
00:33:54.519
look at these we can see we're spending a lot of time in Arrow and quick like quick PSA active record
00:34:00.519
relation is not arrow and the way that the way that this works inside of active record is let's say if you do user.
00:34:06.639
star. fu. bar. count all the red objects there all those red boxes those are
00:34:11.679
active relation instances so we create new active active instance and then a SQL as and
00:34:19.639
then we actually query the database and these active record relation objects are actually trees and the is a tree so
00:34:26.679
actually building a tree to build a tree and when I realized that I was like yo
00:34:32.119
dog awesome two trees why do we have two trees if you want to know ask me later so here's this awesome graph
00:34:39.040
again anyway you saw this let's take a look at the code so I wanted to speed up the arrow code and I'm like okay well
00:34:45.520
let's take a look at it spending a lot of time in here and this is like this is a sample of the code this is what it looks like and if you look at this you
00:34:52.119
wonder like I was like well okay spending a lot of time in GC and we're actually creating an a lot of objects
00:34:57.839
here how many objects are we creating how many strings are we creating like all of you pick a number inside of
00:35:05.280
your head of how many strings we're creating I will tell you the answer here I'm not going to I'm not going to give
00:35:10.839
you a quiz like koichi's quiz it's not a trick quiz just think about it there are six Six Strings
00:35:18.760
created and those arrows are completely unhelpful but where they are created
00:35:25.720
here is this this string literal creates that string L literal the select creates a string object uh doing that middle
00:35:33.440
interpolation there that creates a string object you'll see there's a little space after the interpolation that's another string object and all
00:35:40.079
those get joined together which makes another string object uh evaluating that blank string there in the join that
00:35:46.800
creates a string object and actually joining all of them together is another string object so this function is
00:35:51.920
actually creating six string objects so if we run this if we put this into the
00:35:56.960
Ruby virtual machine compiler and look at the instruction sequences we can see okay these are the instruction sequences
00:36:02.319
this is the instruction sequence for the string literal select and we'll see that it says put string and if we go look at
00:36:07.920
the source for put string we'll eventually find that it's it calls this arbter resurrect and you can see there
00:36:14.119
it's clearly calling string Alec which is allocating a string it's easy to prove that these string literals are
00:36:20.000
actually creating new string objects we can just Loop over them and call object ID and you can see there clearly clearly
00:36:25.880
these are new new string objects all the IDS are different now if we look at the
00:36:31.119
interpolation we see this that first one there that from that's a put object and then down there we're starting to we're
00:36:37.440
starting to call a method and then you see we call put string on that space line 25 there and then we call concat
00:36:44.400
strings these arrows are probably not going to wow huh that one lined up cool
00:36:50.800
anyway so if we go look at put object we can see well it does nothing awesome
00:36:56.079
we're not creating any objects we're just putting an object onto the stack that's great so the long and short of it
00:37:03.079
is when we have an interpolation like this and these arrows don't totally suck we get a put object here put put string
00:37:10.280
here put string here and then finally it can cat string so all those strings in the middle actually create new string
00:37:17.240
objects that just get thrown away they can never be they can never be manipulated but they're just thrown away
00:37:23.359
though I have to say this I Was preparing these slides and I'm like it's not lining up I don't see like
00:37:30.880
I saw this problem before I don't I saw this problem before why isn't it happening Well turns out it is fixed in 2.0 thank you kichi son so now in 2.0
00:37:39.520
this is put object put object put object and finally a concat string so doing
00:37:45.000
string interpolation in Ruby 2.0 will only result in one string being allocated so step four I updated the
00:37:51.160
code and the way that I did this is I changed these I changed some of these string L literals to be constants and we
00:37:57.880
can do that because well we're never manipulating those constants inside that function we're never actually mutating
00:38:04.200
them and all those are just going to result in a put object we just called put object so I changed a lot of those
00:38:10.800
to be constants and then I started using string append and now our string
00:38:16.680
allocations are only there and there so we reduced it from six string allocations down to two and running this
00:38:23.079
running this particular Benchmark with rails I found that we had an 18% reduction in GC invocations and actually
00:38:29.560
an 18% reduction in GC time which is pretty nice but I have to say like
00:38:34.760
please please please please please optimize for readability first like
00:38:40.920
looking at all these shrink concatenations and these like crazy crazy like uh constants floating around
00:38:47.760
in there like you can tell it's been rawle scaled but it's totally hard to read so like find your bottlenecks read
00:38:55.920
optimize for readability first then find your bottleneck then change your code so the next thing I want to look at is dra
00:39:01.920
trce and we only have seven minutes and like 70 slides okay I need to speed up
00:39:08.040
so drace drace is a tool for monitoring monitoring our processes this is what a
00:39:13.640
d what a d probe looks like so the top there we specify the function that we
00:39:18.839
want to mon that we want to monitor that second line we specify a predicate so we can say like only monitor like only fire
00:39:25.119
this probe during these particular particular uh um I don't know in this
00:39:30.160
particular condition and we execute this decode and the Ruby probes that we have or that I have added these are too long
00:39:36.760
but I would like this is too long but I've divided them into seconds we have function probes things for things for monitoring the functions that you call
00:39:43.119
in your Ruby codes you can say like oh this method's called this method's called or returned uh object Creations
00:39:49.119
object creation probes GC actions and Ruby internal stuff so like this one's
00:39:54.640
looking at the looking at the virtual machine it's itself so I want to take this and I want to take these tools and
00:40:00.520
use them to inspect rails boot time and I have to say like there's no really incredible Revel like no revelations in
00:40:07.560
this particular section we're just going to study it I want to look at how we use D to study these and we can take this
00:40:14.280
like we're going to look at how to use D basically D trace the first thing first example
00:40:19.960
we're going to do is count the instruction sequences that are executed so this is the script that we're using this is my test script that I'm using
00:40:26.119
through out all these examples all this does is load the rails environment which means load up bundler uh initialize your
00:40:32.680
application and then we exit so all I'm really doing here is profiling app boot time uh and when we run this when we run
00:40:40.040
this decode we find out well the number one the number one op code that's being executed is the trace op code and the
00:40:45.520
trace op code is the one that does set Trace Funk and I'm like well wow that's our number one op code why don't we disable it there's a way to disable it
00:40:52.520
you can set the compile options globally on the on the Ruby virtual machine and this actually removes the trace
00:40:59.000
instructions and also this this particular function works on every Ruby guaranteed I promise it's my seal of
00:41:04.960
approval ah I resized that it says seal of approval oh well no I'm not yes you are no I'm
00:41:11.160
not so we run it again and we see the output here get local now get local is
00:41:16.280
our top one we don't have Trace anymore Trace is gone now the question is is this faster is it faster we got rid of
00:41:22.400
the trace the trace instruction and our is our app boot time faster so I took 100 samples of loading config
00:41:29.440
environment and then I did a little statistics on it and found that our meantime the top one that's our meantime
00:41:35.640
with the trace instruction and the bottom one is our meantime without the trace instruction so it looks like it
00:41:41.680
might be possibly slightly faster but then when we look at the standard deviation we see the standard deviation
00:41:47.839
is like 05 seconds right so this basically means no
00:41:53.119
it's not faster at all we didn't do anything so the top eliminating the top
00:41:58.440
instruction didn't save us any time the next thing we want to look at is well what is our favorite instruction what
00:42:03.599
instruction are we spending the most time in like where are we spending most of our time in the Ruby virtual machine
00:42:09.520
and the way we can do this is we can set up a timer in D so this top this top probe all this does is execute this code
00:42:16.400
every 5,000 Hertz so every 5,000 Hertz on your machine it does a sample this
00:42:21.720
bottom one just says okay anytime we run a ruby instruction save it off
00:42:26.880
right we just save off the Ruby instruction and then this timer this timer says what instruction was just
00:42:32.359
executed count them up so we're taking a sample we're taking a sample of the
00:42:38.079
instructions that are being run so when we look at that and we get this count this count doesn't actually really mean
00:42:43.720
anything except that they're relative to each other so we know that when we're sampling the process we're most likely
00:42:51.079
to be inside of a send instruction this actually shouldn't be surprising to you if you in koichi's talk yesterday
00:42:56.720
so if you want to look at how to find where to speed up the Ruby VM that send instruction is where we need to go if we
00:43:03.480
can speed up the send instruction then we're really going to speed up the Ruby VM and if we look at this if we looked
00:43:09.280
at the entire sample for this we would see that Trace yep the arrow is totally messed up but Trace is like way up there
00:43:14.800
at the top we're spending like basically zero time in trace the next thing I took a look at was GC time shoot three
00:43:22.240
minutes and 30 slides okay GC time we can measure GC time measure the marks
00:43:28.160
when we Mark when we sweep and then total up that time and look at the total time for our process ah man come
00:43:38.400
on so when we look at that we can see like well okay we're we're spending 24%
00:43:43.640
of our time in the garbage collector when we boot when we boot rails the next thing I went and looked at was compile
00:43:49.640
time oh all these times are going to be in Nan unless I say otherwise so then we look at compile time so so we can
00:43:56.559
monitor our compile time and this is actually parsing the code and compiling it so this is actually reading the file
00:44:02.280
turning it into and turning it into instruction sequences so that's the amount of time that's what this is measuring and when
00:44:08.480
we look at that we're spending about 21% of our time doing compilations and this is with the garbage collector disabled
00:44:14.359
because we can collect garbage during uh compile time so I disabled the GC so we're spending about 21% of our time in
00:44:21.160
compile time the next thing I want to look at is searching and what I mean by searching is when you say like require
00:44:26.440
Fu we actually have to go search okay we go search loaded features Ruby says hey
00:44:32.359
um have you required this file already if you've required it then we need to exit if you haven't required it yet then
00:44:39.760
we need to figure out where this file is so this this particular probe wraps that
00:44:45.599
function it says okay we're going to calculate how much time Ruby spends searching for your file so this this
00:44:52.680
particular one prints out the time stamp that we that we search and the amount of time that it took to search for that
00:44:57.800
particular file and the file that we were searching for so the statistics on this are when I ran when I ran this
00:45:03.920
Benchmark again with GC disabled I found that 30% of the boot time in this rails
00:45:09.520
app was just searching for files this wasn't requiring them doing gc's or anything this was literally trying to
00:45:15.920
find the files on your file system this app had what 16600 files 1650 files and if we graph
00:45:23.480
it man the graph is Tiny that sucks so that's what the graph looked like and I thought well okay maybe this is maybe
00:45:28.920
it's linear growth I don't know the I don't know the equation or I don't know the I don't know the algorithm for
00:45:35.839
finding these files and I think well maybe it's linear so I did a linear fit on this and found that well okay this is
00:45:42.359
actually what our graph looks like and these numbers are in nanoseconds right so our coefficient
00:45:49.119
there is only 174 nond so as we're going along in time we
00:45:54.440
only increase 174 NS this is basically flat that's like nothing I don't even know what 174 nond is
00:46:03.400
so crap 45 minutes but you got to see this okay bug 7158 somebody filed a bug
00:46:08.880
saying require is too slow I think it's too slow 30% of app boot should not be fire required they attached some patches
00:46:14.960
and there have been some back and forth so I decided to apply the patch and measure the amount of time I did that same test 16% of the boot time was Now
00:46:22.640
searching for files these are the gra these are grass comping them the the graph on the left hand side is our total
00:46:29.160
program time how much it took to boot the application the one on the right is how much time we were spending in search
00:46:35.520
this graph is uh the black is how much time we were spending before the patch
00:46:41.040
the green is how much time we were spending after the Patch and if we actually sort the times we can see like
00:46:46.760
the red line there at the bottom is the times after the Patch the black line is before the patch so we can actually see
00:46:52.599
a drastic difference in in the uh time it takes for searching required files now if we actually run the process
00:46:58.680
itself we can see okay this that top one took about 1.5 seconds and the bottom one took about 1.1 so we saved about4
00:47:06.040
seconds now if we combine all these graphs together we can see before that particular patch we're spending 30% of
00:47:11.440
our time finding the files the rest of our the rest of our time that 25% that could be in the Ruby virtual machine so
00:47:17.240
even though kichi did those awesome those awesome speed improvements for the virtual machine we're not seeing any of
00:47:23.319
that benefit on boot time because that percentage is so small now after this particular patch is applied we're only
00:47:29.800
spending 16% of our time in fine files so now these now during boot time those
00:47:35.000
VM optimizations actually help us so this particular ticket I love it and I hope that this patch gets
00:47:41.280
applied so I want to end this talk with some of my very favorite um yearbook
00:47:47.680
phrases stay cool never Chang but really I wanted to end this with work eat hack try Ruby 2.0 and I'll
00:48:24.640
you
