►
Description
Walkthrough of what an strace of a typical request in Puma looks like, and a quick comparison on how Unicorn is different.
Part 1: https://www.youtube.com/watch?v=fcY5pPUq35U
Part 2: https://www.youtube.com/watch?v=tThs8QeP2qY
Part 4: https://www.youtube.com/watch?v=dgJH4wpR5OE
A
Hi,
everyone
welcome
to
another
s,
trace
video,
so
in
this
one
we're
going
to
get
into
using
s
trace
to
understand
what
unicorn
and
puma
and
rails
in
general
are
doing
when
a
request
comes
in.
So
let's
dive
in
okay.
So
here
we
have
a
13.2
instance
running
puma
and
if
we
just
look
at
yes
see,
we've
got
two
cluster
workers,
each
of
which
will
have
four
worker
threads.
That
can
each
handle
a
request
separately,
so
we
basically
have
eight
threads
total
that
can
take
a
request.
A
A
All
right
so
we're
going
to
follow
any
child
processes,
get
the
accurate
timestamp
capture
the
time
that
syscall
took
with
capital.
T
yy
is
printing
out
the
file
paths
we
capture
up
to
a
kilobyte
of
each
string
and
here's
your
output
file.
Okay,
so
we'll
kick
off
the
trace
and
we'll
pull
up
this
project,
that
is
on
local
storage,
all
right.
There
we
go,
and
so
we
can
see
we
actually
have
three
different
requests
that
came
out
from
the
performance
bar
here.
A
This,
and
so
here
this
is
kind
of
the
idle
system
and
no
traffic,
because
this
is
just
a
little
demo
instance
with
the
only
user.
A
All
right
well
here
is
the
first
interesting
line.
So
basically
right
here,
the
select
so
this
is
this
process
is
listening
on
these
two
addresses
so
get
lab.socket
and
localhost
8080
and
seeing
which
one
of
those
comes
back
first.
A
Actually
it's
listening
on
three
messages,
this
pipe
from
somewhere
that
might
be
from
its
parent
process
anyway,
so
gitlab.sockets
gonna
have
any
traffic
from
workhorse,
so
external
requests,
localhost
8080,
we'll
get
requests
from
gitlab
shell,
so
ssh
requests
that
come
in
and
some
guilty
requests
as
well.
Will
fire
off
internal
api
calls
to
make
sure
that
they're
allowed
to
do
whatever
the
request?
Is?
Okay?
So
that's
that's
just
it's!
It's
saying
either
look
for
external
requests
or
look
for
internal
requests,
whichever
one
comes
in
first
with
that
select
okay.
A
A
Here's
the
encoding
we
accept
and
so
on.
You
can
see
that
bar
enables
you
right
there,
okay
and
then
so
it's
a
total
of
16k
roughly
of
data,
so
we
only
get
the
first
k
of
that.
So
we
can't
see
the
full
request
there.
We
could
use
the
browser
tools
if
we
really
cared
about
that.
Okay,
so
unicorn
and
puma
are
essentially
single
threaded
within
the
context
of
a
given
request.
That's
not
entirely
true,
but
it's
true
enough
for
our
purposes.
A
A
Don't
I
okay,
so
this
is
a
thread
on
one
of
the
cluster
workers:
cluster
worker,
one
okay,.
A
Yeah,
okay,
so
two
two
three
okay
yeah,
so
there's
the
parent
process,
which
is
cluster
worker
one
here,
okay,
so
that's
one
of
the
threads,
not
the
the
lead
thread,
which
is
the
pid
in
ps,
okay,
and
so
actually
here
you
can
see
these
get
pid
calls
right
here.
This
is
saying:
what's
the
actual
process
id
here,
so
this
is
the
actual
thing
that
you
see
in
ps,
like
we
just
saw.
A
Okay,
true
text
is
just
synchronizing
with
other
threads
there's
a
little
skip
over
most
of
this
and
just
gets
the
interesting
parts.
So
the
first
thing
we
do
before
anything
else
happens.
Is
we
write
out
to
production.log
that
we're
starting
this
request
clock
get
time,
we'll
see
a
lot
with
puma
and
unicorn?
A
So
typically,
what
that
means
is
that
something
in
the
background
is
happening,
and
so,
when
you
see
a
long
string
of
clock
get
times,
that's
just
we're
doing
some
kind
of
processing
in
user
land,
and
we
just
need
to
know
what
time
it
is.
So
it's
really
just
we're
not
accessing
the
kernel
at
all
other
than
just
get
the
time.
So
when
you
see
a
lot
of
those
it's
kind
of
idle
within
in
terms
of
kernel,
not
in
terms
of
the
actual
worker,
it's
doing
it's
doing
something.
A
A
Okay,
so
here
we're
starting
to
query
the
database.
This
is
a
local
postgres,
so
it's
over
a
unix
socket.
If
it
were
an
external
postgres
it'd
be
over
tcp.
It
may
or
may
not
be
encrypted
at
that
point,
which
would
make
it
hard
to
read,
but
conveniently
with
local
it's
not
encrypted.
So
you
can
see
that
we're
actually
sending
select
to
postgres
and
we're
getting
back
something
it
doesn't.
We
haven't
actually
made
a
real
query
there.
As
far
as
I
can
tell
so
here
we
go.
A
I
make
our
first
query
we're
selecting
namespaces,
and
we
can
see
all
this
right
here
and
select
namespaces.
A
A
So
we
have
this
long
query
where
we're
getting
the
namespace
detail
and
then
here
you
can
see
the
response
back,
which
is
not
quite
human
readable,
since
most
of
the
data
is
binary
encoded,
but
you
can
kind
of
guess
at
what
it's
saying
and
it's
pretty
obvious
that
we
got
back
a
result
as
opposed
to
an
error
or
anything
like
that.
A
A
And
these
are
all
queries
that
I
think
are
generated
by
rails
itself:
okay,
and
I
guess
we're
getting
pretty
close,
no
okay,
yeah
all
right.
So
now,
we've
we've
found
our
route.
We
found
our
method,
so
here
we
write
out
direction.log,
here's
what
we're
doing.
A
All
right
so
here
we're
hitting
redis,
so
you
can,
when
you
see
these,
you
know
dollar
sign.
This
is
a
new
line
with
windows
index
and
then
get,
and
then
you
know
this
is
the
actual
radius
query.
We're
making
get
the
obsession
to
probably
see
this
in
performance
bar.
A
A
Maybe
not
but
yeah
you
should
be
able
to
see
most
of
those
in
performance
bar.
A
A
A
Okay,
more
reticents
make
sure
we
lose
our
connection
to
redis
briefly,
and
then
we
reconnect.
A
A
A
A
Okay,
now
we're
back
to
querying
on
namespaces
down
here
we're
just
getting
a
group
back.
A
Okay,
now
we're
seeing
if
the
cache
for
the
project
is
this
should
show
up
here.
I
think,
let's
see.
A
A
All
right
all
right,
so
here's
what
I
was
saying
about
these
stretches
of
clock
get
time.
When
you
see
this,
this
is
just
kind
of.
A
Checking
it's
doing
something
that
we
can't
see
in
s
trace
right,
because
stress
is
only
showing
us
what
happens
when
we
reach
out
to
the
world,
and
this
is
all
internal
processing.
So
it's
it's
got
some
value
back
from
redis
and
some
value
back
from
the
database
and
it's
trying
to
decide.
You
know
what
to
do
next
or
maybe
rendering
I'm
not
rendering
yet,
okay,
more
redis
queries.
A
Okay,
this
is
the
internal
ip
address,
I
think,
of
the
server,
because
it
should
be
local
storage
for
some
reason,
I'm
trying
to
connect
over
udp
and
it
doesn't
work
because
we're
not
listening
at
udp.
A
We
set
some
options
on
the
socket,
and
here
we
try
to
connect
to
that
same
ip
address.
We
saw
above
for
udp,
but
with
tcp
and
an
ipv6
format
once
again,
port
8075,
which
is
how
we
we
know
this
is
actually
gitly
all
right.
So
we
connect
and
now
we're
e-pulling
here.
So
we
try
to
connect.
It
comes
back
and
says
we're
working
on
it.
So
here
we
create
an
e-poll
on
that
which
is
basically
saying.
A
A
Okay
and
then
eventually
we
were
connected,
and
now
we
can,
we
send
a
message.
So
this
is
an
actual
giveaway
message.
Let
me
bring
this
up
at
the
top
of
the
page,
so
you
can
see
that
because
it's
grpc
we're
sending
a
http
2
request.
A
Which
is-
and
you
can
you
can
kind
of
see
here-
is
the
length
of
each
section
of
this
request.
So
most
of
this
is
in
binary
and
it's
not
really
legible,
but
some
parts
it
will
be
this
particular
request.
You
don't
see
anything
yet
that
is
very
easy
to
read.
Okay,.
A
And
it's
all
binary.
I
think
this
is
just
setting
up
the
connection
in
the
first
place.
So
when
I
said
at
the
start
of
the
video
that
unicorn
and
puma
are
single
threaded,
that's
were
reached.
The
work
isn't
enclosed
entirely
in
a
single.
You
know,
threat
of
execution.
That
is
this
is
where
it
actually
is
not
quite
true,
so
you
will
see
the
gilly
requests
go
out
on
the
main
thread
or
process
depending
on
which
boom
or
earth
guillotine,
but
then
there
are
on
both
of
them
listener.
A
A
Okay,
all
right,
so
here
we're
getting
back
an
actual
response.
A
A
A
A
Let
me
bring
that
up
to
the
top
all
right,
so
this
is
a
little
bit
easier
to
follow
along,
so
you
can
see
we're
calling
the
get
tree
entries
get
the
rpc
here
is
the
bearer
token
that
we
send
to
get
a
lead
of
authenticate
that
you
know
who
we
say
we
are
so
basically
what
we
do
is
we
take
the
current
timestamp
you
next
time
stamp
and
then
do
a
hash
of
that
against
whatever
the
secret
you
set
in
your
get,
get
that
reviews
and
that
creates
a
string
and
then
we
add
the
timestamp
to
the
end
to
say
and
here's
the
time
stamp
that
I
sent
to
make
it
easier
for
humans
to
understand.
A
What's
going
on,
okay
or
actually,
I
guess
it
also
helps
make
sure
it's
valid
either
case
here.
This
looks
like
the
correlation
id
here
session
id.
Maybe
this
is
correlation
id.
A
Deadline
type
is
regular,
so
that's
going
to
be
30
seconds.
I
think,
and
then
here
we
have
the
actual
path
down
the
hash
storage
to
that
project.
A
Here's
the
name
of
the
project
which
we
can
see.
That
should
be
it,
so
we
send
that
yeah.
Okay,
so
here
we
go.
This
is
what
I
was
talking
about.
So
on
202
243.
We
send
that
and
then
milliseconds
later
we
start
clearing
the
database
without
seemingly
never
getting
a
response
back.
But
let's
see
if
another
thread
got
it
back,
yeah,
okay,
so
20833
did
receive
a
message
back
and
it's
binary.
We
can't
really
understand
it.
A
That's
just
the
header
actually
and
then
down
here
we
get
the
full,
the
full
data
back,
okay,
so
yeah!
So
that's
those
that's
what
I
was
saying,
but
so
there's
this
this
child
thread.
That's
just
handling
gilly
requests.
Essentially,
so
let's
go
back
to
the
main
thread
now,
all
right.
Can
you
see
if
we
have
any
project
mirrors
which
are
not
notification
settings
so
things
to
keep
in
mind?
A
You
want
to
just
look
at
the
time
stamps
here
and
what
you're
looking
for
are
big
jumps,
so
keep
in
mind
that
most
syscalls
are
really
fast,
and
so
it
doesn't
really
matter
if
you
see
ten
thousand
lines
of
a
fastest
call
right
after
the
other,
because
that's
not
a
big
impact.
A
lot
of
the
times
we're
looking
for
is
one
request
that
took
five
seconds,
for
example.
A
A
We're
seeing
if
we
have
auto
devops
turned
out,
I
think
we
do,
because
I
didn't
turn
that
off
all
right.
Let
me
query
in
license.
A
Some
more
reduced
queries
so
things
that
we
that
can
commonly
cause
problems
that
are
not
immediately
obvious,
slow,
ldap
sync.
So
if
we're
waiting
on
dns
to
get
your
ldap
server
or
the
ldap
server
is
taking
a
long
time
to
get
back
to
you,
you're
not
going
to
see
that
in
the
logs
anywhere.
So
that's
something
that
s
trace
is
useful
for
and
you
can
actually
see
that
we're
getting
getting
a
dns
entry
for
ldap
we're
calling
out
to
that.
It's
taking
five
seconds
to
respond
and
that's
what
makes
everything
slow.
A
That's
one
example:
that's
happened
somewhat
often,
you
know
things
like
database
being
slower,
kiddie
being
slow.
Those
are
usually
pretty
obvious
from
the
logs
that
you
know
again.
We
log
those
durations
in
production,
json
api
json.
A
So
it's
not
going
to
be
hard
to
understand
those,
and
I
wouldn't
use
s
trace
in
general
on
those
unless
you're
trying
to
understand
something
very
specific
about
what
we're
getting
stuck
on
and
even
then
assuming
the
page
is
loading.
You
can
use
perfbar
to
really
dig
into
what's
taking
a
long
time
and
where
it's
coming
from.
A
A
A
A
Okay,
those
are
gilly
requests
this
time
we're
getting
tree
entry,
which
is,
I
believe,
gonna
tell
us
the
details
of
a
file
tree
entry-
yeah
okay,
so
this
is
probably
yeah
all
right,
so
we're
getting
readme
to
md
for
the
look
of
it
do
make
sure
you
see
the
file
name
here,
yeah
and
here's
the
file
name
down
here.
A
A
A
A
A
A
A
Yeah
all
right
and
down
here
right
out
to
production
json
the
full
details
of
the
request-
okay,
great
so
that
is
kind
of
the
lifestyle
life
cycle
of
a
standard
request
that
you'll
see
it
just
come
in
and
we'll
query
write
us
in
the
database
a
lot
we'll
make
a
few
kiddily
queries
and
we'll
spend
some
time
getting
what
time
it
is
and
then
we'll
write
out
to
the
logs
and
to
the
socket
with
the
response
we
have.
A
One
thing
one
thing
to
note
is
that
we
do
log
before
we
write
the
response,
so
it
is
every
now
and
then
possible
that
we've
logged
that
were
successful,
even
though
the
request
actually
fails.
This
happens
a
lot
when
workhorse
drops
the
connection.
So
what
will
happen
is
a
client
makes
a
connection
goes
to
workhorse
workhorse
forwards
down
to
unicorn
or
puma.
Puma
starts
the
work,
but
then
the
client
drops
the
connection.
Workhorse
then
drops
the
connection
to
get
that
socket
as
well.
So
unicorn
will
do
all
the
work.
A
Loga,
200
or
puma
logo
200
write
it
out
to
the
socket
and
then
fail
to
write
it
because
sockets
already
been
closed.
So,
in
that
case,
you've
got
three
different
response:
codes
being
logged
there,
nginx
will
log
4.99,
because
the
client
hung
up
workforce
will
log
a
502,
because
you
know
the
puma
didn't
respond
in
time
and
then
puma
itself
will
logger
200,
because,
as
far
as
it
knows,
it
succeeded
until
it
actually
tried
to
write
the
response.
A
So
that's
a
little
confusing
and
something
that
happens
fairly,
often
just
to
be
aware
of
okay,
so
that
is
again
the
the
basic
life
cycle
of
request.
Let's
actually
go
back
up
to
the
start
here,
find
that
okay,
so
with
puma
the
the
process
that
gets
the
request
in
is
usually
not
the
one
that
actually
does
all
the
work.
A
A
Yeah,
so
we've
got
two
two
four
six
and
then
two
two
four
three
so
two
or
two
four
three
doesn't
work,
but
two
or
two
four
six
actually
took
in
their
request.
You
can
see
these
are
both
threads
for
the
same
process.
So
we
basically
have.
Is
you
have
one
thread
that
just
listens
on
the
socket
and
then
accepts
the
request
as
it
comes
in,
but
it
won't
the
pid
that
accepts
the
request,
will
not
be
the
one
that
actually
does
the
work.
A
So
then
you'll
see
a
different
pid,
do
a
receive
from
and
actually
read
in
the
the
details
of
the
request
over
the
socket.
So
that's
what
you're
seeing
here
20246
says
it
actually
responds
with
the
initial
response
and
then
20243
does
the
actual
work
and
sends
back
the
the
full
response
at
the
end.
Okay,
let's
briefly
go
over
the
differences
with
unicorn,
which
are
not
very
great,
we'll
just
go
over
that
same
thing.
We
just
went
over
with
unicorn
real
quick
and
what
is
it
enable
water
enabled?
I
can't
remember
enable
okay.
A
And,
let's
load
the
page,
yeah
five,
two
all
right
I'll
give
unicorn
30
seconds
to
come
up.
I
know
this
is
the
best
part
waiting
here
for
this
to
come
up,
but
we'll
be
basically
done
once
that
comes
up.
So
if
you're,
not
interested
in
unicorn,
then
feel
free
to
stop
the
video
all
right
great.
It's
up.
A
5628
is
the
same
process
that
both
accepts
and
actually
does
all
the
work.
So
so,
like
you
mentioned
at
the
start
of
video,
puma
has
multiple
threads
per
process
and
each
one
of
those
threads
can
handle
an
image,
will
request.
Unicorn
each
process
is
kind
of
an
island.
You
know
it
isn't
one
one
main
thread
within
it,
which
is
the
work
you
know
with
the
inception,
with
the
notable
exception
of
the
grpc
list
and
threads,
but
other
than
that.
A
You
know
it's
used
one
process
doing
all
the
work
within
with
no
real
threading
involved
at
all.
So
in
this
case
you
see
that
you
know
this.
The
process
gets
it
and
the
process
then
goes
and
does
the
work
and
then.
A
Right
now,
unicorn,
and
then,
if
we
look
here
this,
the
process
id
and
mps
actually
matches
what
we
see
in
s
trace,
because
it's
the
main
the
main
thread
within
the
process.
That's
doing
all
the
work.
Okay,
so
that's
that's
the
only
real
difference
between
puma
unicorn
other
than
that.
All
the
work
you
see
within
the
s
trace
is
going
to
be
the
same
yep.
So
that
is
a
quick
summary
of
what
you
can
see
in
a
typical
rails.
Request
great
all
right
next
time,
we'll
go
over
kitty,
which
will
be
interesting
thanks.