and welcome back everyone
we have our next talk right now by
yarkov which is called making swiss
cheese of ticket sales and as we were
just talking before uh in the green room
uh clearly the abstract has has done its
job because lots of people are
interested in this talk including me so
without further ado
yakov take it away
thank you
hello everyone and shana tevan happy new
year and special hello to our live chat
today i'm yakov and in my day job i'm a
senior software developer at weistec
global where we build software that acts
as the operating system for global
logistics
at other times i swap the shipping
containers for docker containers and act
as the systems administrator for smash
the sydney manga and anime show where we
host an annual convention for all things
anime and manga at least in years where
there isn't an active pandemic
like most conventions we sell tickets to
the event if you want to get in you need
to buy a ticket a ticket gets you a
badge and a badge gets you in the door
we sell tickets in two ways at the door
on the day of the event or online
beforehand at a slight discount and this
year online sales were quite a bit
harder than it might sound
we've done this many times before in
years past in on our current soft
current software stack we've done it
twice in 2019 we sold tickets redeemed
tickets and had a whole convention as
usual
in 2020 we sold tickets and
we then had to postpone the convention
but our launch of ticket sales did go
off without a hitch
this year for our 2021 flagship event we
opened ticket pre-sales at 10 a.m on
sunday the 2nd of may 2021
that morning well it started for me
pretty much like any other i got up i
got dressed i did the morning prayers
perhaps i should have prayed a little
bit harder that everything here would go
to plan and then i logged onto slack and
onto our ticketing website just to keep
an eye on things and to watch the ticket
sales start to roll in
as the clock ticked over to 10 am i
refreshed the page expecting to see our
list of tickets for sale go from nothing
to our three regular online items plus
the early bird special that was
available at the time
instead all i got was a loading spinner
and reports started coming in that it
wasn't just me
two minutes later the main smash
wordpress website was down too
by 10 pass we're in full battle stations
mode trying to figure out what on earth
was bringing our websites down
some users even reported seeing sql
related errors on the front end and
that's usually never a good sign
40 minutes later at 10 50 am we thought
we identified the problem and deployed a
mitigation
but that didn't help
eventually at 11 40 am we decided to
pull the plug having only managed to
sell one
single ticket
in our first hundred minutes
over the next 20 minutes we discovered
that our panic button didn't quite work
in the current circumstances and we had
to manually push out a new build of the
website with that panic mode hard coded
to on
and yet somehow
ticket sales started flowing through
from that point onwards we spent the
rest of the afternoon identifying
inconsistencies in the data from those
sales such as users who had paid but
whose payment hadn't been recorded in
the system or users had been double or
triple charged in fact one order had
been charged 12 times over the poor
fellow
we added missing links into data and
issued appropriate refunds and i went to
bed that night very confused
so what on earth went wrong here
before we get to that let's set the
scene
smash has been running for over 10 years
i first found out about it in 2018 and
shortly joined staff as the new systems
administrator and second in command of
it
for the it team that was a very
transitional year with the existing
staff leaving and handing over to us
newcomers everything that they had built
the old systems were a mixture of
appliances and frameworks and languages
and some strange disparate microservices
the ticketing system alone was four or
five different services some written
ruby and others in go
it was designed many years earlier for
different requirements and constraints
for a very different environment that
what than what we now faced and where we
wanted to go with the i.t systems
for example it was designed to run
ticket redemption to particular ticket
redemption at the convention center
that's where you scan everyone in
completely offline
but this meant we would never be able to
do online ticket sales during the event
and it made it very hard to try and set
up mobile handheld scanners that would
work outside over 4g or lte
among the many changes we made was with
the blessing of the old guard building a
brand new ticketing system now we
couldn't find any existing open source
or low-cost solution that would do it we
needed so again we wrote our own from
scratch
smash is entirely driven by volunteers
so neither stack that volunteers would
be able to get the hang of quickly so we
chose a javascript typescript stack
we used react.js for the front-end
node.js and express.js for the back-end
and mysql for data persistence since we
already had mysql infrastructure for our
wordpress sites including things like
automatic backups and i didn't want to
have to manage two database stacks
to host the sites we decided to use
kubernetes mostly because i wanted to
learn kubernetes but also because it
made a bunch of things really easy words
that may never be said again as it's
gotten more complex such as pushing out
updates the software managing secrets
automatically managing nginx and let's
encrypt certificates and it let us
establish a really solid infrastructure
as code foundation
and in the long run it has been a lot
easier than manually configuring a
handful of eps boxes
so this is our rough architecture for
the ticketing system
requests to slash api go to the node.js
backend which talks in mysql instance
which is then backed by persistent disk
all other requests go to a tiny nginx
container that serves up the static
front end if we add in the wordpress
site and then account for replicas this
is basically what our setup looked like
at the time
and this setup served us nicely through
2019 in fact we built the system all
throughout all through 2019
in a very just in time approach you
might even call it agile
but for example when we launched ticket
sales that first year we hadn't finished
the code to generate pdfs for tickets or
receipts so he later had to backfill all
those orders by generating those pdfs
and sending out their emails once the
code was ready
another example is the ticket redemption
code which was only finalized and
deployed to production
the night before exhibitor setup day
when we had to scan in all the
exhibitors
but it worked and it held and we ran a
convention that weekend including a
concert with almost no technical issues
throughout 2020 and early 2021 we built
some new features refactored the code
updated npm packages and had our very
short-lived 2020 ticket sales
but there were no major changes from the
2019 code base or architecture
so how come in 2021
this system fell flat on its face
there are many different models that you
can use to analyze risk and accidents
and the swiss cheese model is used in
the aviation industry and it's one of my
favorites because it is so often
accurate
the model works roughly like this
for any event that you don't want to
happen
there are a bunch of different barriers
that contribute towards protection
each of them are ultimately fallible but
in different ways
for that event to then occur multiple
barriers have to be individually
breached if any single one of these
barriers holds up then the event usually
some kind of accident or disaster is
still prevented
the more barriers that were breached the
closer you've come to total disaster
over at the snake oil academy track they
would probably call this defense in
depth but here we're not trying to fend
off an attacker we're just trying to
protect ourselves from failure
for a worked example let's look briefly
at u.s airways flight 1549 the infamous
hudson river ditching
big content warning on this one if
you're not comfortable come back in
about two minutes
for the rest of you i'm going to assume
that by now you've heard about what
happened because it's pretty famous at
this point
and that whole series of events really
should not have occurred
for a start the aircraft encountered
birds technically geese on takeoff
engines are designed to withstand
ingesting birds in fact during testing
they fire frozen birds at engines from a
cannon
according to the official ntsb
investigation report though if a bird
enters the engine near the outer edges
it'll most likely strike only the fan
blades continue along the bypass duct
and get ejected out the back probably
dead possibly cooked
but because it hit the inner part of the
engine it got ingested into the core
even then a twin-engine aircraft like
that can still fly including a full
takeoff with only one working engine
we have some basic redundancy that's
great
but unfortunately in this case birds
took out both engines
even then an aircraft can still glide
for quite some time so if you ask a
pilot they will probably call it falling
slowly rather than gliding regardless
they hadn't gotten high enough yet i
didn't have very far to glide definitely
not far enough to a runway
and so on and so forth
different layers of protection
redundancy or resiliency each one
breached until they had no choice but to
crash into the hudson river
fortunately in this case there were
still laser protection that held up the
pilots used their train to ditch the
aircraft without crashing it and
destroying it
the flight crew evacuated everyone
before the plane sank
and the planes were equipped with life
rafts so people actually had somewhere
to go
in this case it wasn't a total disaster
and a good amount of those cheese layers
still held up
but in the days that followed the 2nd of
may 2021 i was strongly reminded of this
model as we work through different
problems in our ticketing system
none of which alone could be pinpointed
as the singular cause of our failed
ticketing sales launch
but all of all whom could have helped
prevent or mitigate it
the first issue that we managed to
identify and fix was that the main
wordpress site went down
it shared a database server with a
ticketing system and whilst we hadn't
had a single problem with it in previous
years even on the day of convention with
people hammering the schedule
all we could see was the generic error
message error establishing the database
connection
i suspected this was due to a mixture of
increased load on the main site and on
the ticketing site at the same time
i went digging and quickly discovered
that the default connection limit in my
sequel is 151 concurrent connections
i've no idea why they picked that number
perhaps whoever came up with it as a fan
of the original pokemon games
in any event we increased the connection
limit to 500 and that particular problem
went away
unfortunately we were still seeing
errors on the ticketing system the most
common one we saw in server logs was a
connects timeout error timeout acquiring
a connection the pool is probably full
are you missing a dog transacting call
the way that most database client
software works is that they don't create
a new sql connection every time they
need one these get pulled when you
request one you either take one from the
pool
or get handed back a brand new one
that's up to the pool to decide and when
you're done you hand it back to the pool
and it either scrubs it for reuse later
or drops it entirely again that's up to
the pool to decide
in this case i believe the error message
is technically wrong and it means the
pool is probably empty that is all the
connections that it has have already
been handed out and it's not going to
create another new one for you
the first thing we did was go looking
for any places in the code where we were
requesting a connection but not handing
it back
and we found exactly zero instances of
that the code was doing the right thing
so the next question is how big is this
pool exactly
we did some initial digging and found
buried away in the documentation that
according to the default settings the
pool has a minimum of two connections
available
and a maximum of 10.
we had two servers and hundreds of users
so we likely needed far more than 20
concurrent connections
we increased the connection pool limits
deployed it to production and
still no improvement
at this point we decide to push the
panic button and put the site into
maintenance mode this is a special mode
where users can't really do anything and
it's designed for shutting down the site
to perform maintenance such as moving
between servers rebuilding the cluster
or some kind of urgent database
operation
in our case we just wanted to pull the
plug so we could start seeing what
actually happened
unfortunately the site was under such
heavy load that we couldn't even get
into the admin settings and save our
changes
i manually flip the switch in the
database table i need to then discover
that the website couldn't even load the
settings of value due to the site
crawling so slowly
we ended up going into the code base and
changing the client site is maintenance
mode function to simply return true and
deploy that straight to production
so by now we should have no users and be
able to begin a thorough investigation
but strangely this is when orders kept
coming into the system
these were hitting the payment processor
and our emailing provider
and now that we had no new no new users
coming through the system we were
actually somehow selling tickets
the system was slowly working through a
backlog
i suspected this was a backlog of users
who already started the ticket flow or
they were spamming the refresh button
towards the end at that point the is
maintenance mode function is no longer
checked
but as these orders started coming
through we started getting complaints to
customer service that some customers had
been double charged
we spent some time looking through the
orders and cross-referencing them with
the payment provider and discovered two
surprising things
one is some customers had indeed been
double charged for their order
as they must have been submitting the
order form multiple times and retrying
on hera
we refunded these extra orders and we
cancelled the duplicate tickets
we hypothesized based on screenshots had
been sent that what must have happened
happened is customers submitted their
order which took so long that the nginx
ingers controller which was running on
basically default settings
gave up after 60 seconds and returned to
http http 504 gateway timeout error
but node.js and express.js continued
handling the requests and ultimately
fulfilled the order
the user never saw that so when they saw
the 504 error they simply resubmitted
the order not realizing that they were
now submitting a second order
or a third
of that one person number 12.
to fix this we increase the proxy read
timeout value to a larger value than the
actual application server would take so
that the application would time out or
fail before nginx gave up on the request
that should also help to reduce our load
because if each user is making multiple
requests then our effective user count
and therefore our load is significantly
larger it's multiple times what it
should be
but even more strangely surprising thing
number two was that some customers
experienced the exact opposite case
they'd been charged for their order they
had no corresponding ticket in our
system
there is logically no way this should be
able to happen because the way the code
was structured is
we create a payment record
then we uh call out to the payment
processors api and then we update the
payment record with the result of the
api calls there should be a payment
record there at all times
we went digging through the code and
discovered a horrible mistake
the code that created the payment record
and the code that called out to the
payment processing api were both in the
same database transaction
if the container gets shut down in the
middle for example when a new image is
deployed then the payment record doesn't
actually get saved to the database
this could also explain our problem
overall if the payment processor takes a
significant amount of time then we hold
our transactions open
and exhaust the connection pool
that's it there's our smoking gun
everyone can go home
clearly not there's still 15 minutes
left in this talk
since we no longer had any real
customers online at this point we pushed
the fix to staging and ran a synthetic
load test talking to the payment
processor's testing api to ensure that
we don't spend or take any real money
waiting with baited breath we ran our
test script and
it still failed spectacularly
whilst this was clearly a problem it
couldn't be the problem
so at this point we were pretty much
lost we knew that we had a problem
we knew that it was likely related to
the sql database since we had wordpress
and connects both complaining about sql
connections and we knew that it was
induced by a massive load of customers
trying to buy tickets
but we had no clue what was really wrong
as far as diagnosing optimizing sql goes
this is something that i've seen before
many times at work
and when i get stuck we have some very
good dbas that i can always turn to for
help
but i didn't have that here
and i couldn't even turn to my usual
tools that i use at work
at work we rely on microsoft sql server
and the best tool by far for initial
investigation is a microsoft sql
profiler
this is a wonderful tool that can show
you live every sql command being
executed who ran them how long they took
what machine it came from so on and so
forth
normally i would look here for
long-running queries or blocked queries
and start to unravel the mess
but i actually could not find any
equivalent tooling for my sequel
the only option left was to instrument
the application itself
fortunately and well what got us into
this mess is this is our own application
and not a third-party proprietary one so
we could do this fairly easily
we did two things here one is we added a
warning if a transaction takes too long
too long an arbitrary amount of time to
run
and two is we ran the application in
development mode with an environment
variable set so that the orm would print
out every sql query it ran as it ran it
we ran a few test orders in development
we sat down looked through these queries
and we noticed a few interesting things
firstly each http request to order some
tickets had about five or six
transactions running
this highly increases the chance of
failure when the connection pool is
exhausted once a request gets that first
connection there is no guarantee that
the connection pool will give it the
second one it needs or the third
or the fourth
and so on
we consolidated some of these
transactions together and managed to
bring it down to three
secondly we noticed a lot of extra
queries that we didn't need
often when we created or updated a row
the rm would subsequently select that
row again but we never did anything with
a new result
we changed a few method calls and those
select queries disappeared
thirdly we noticed a few of them were
select for update which locks the row
this was by design as we keep track of
how many sales each item or bundle has
definitions an item is an individual
thing such as a sunday pass
a bundle is a collection of items such
as a weekend ticket which would contain
both a saturday pass and a sunday pass
this is so we can limit cert
certain purchases for example our
discounted early bird bundle was limited
to the first 500 people
and in 2019 when we held the annie song
concert the hall only has a certain
number of seats we can't oversell that
or some people would have no edit set
this year we also have things like you
know square meter per person capacity
limits to worry about but we haven't
programmed any of that into the system
the row locking is only supposed to be
very brief we lock the rows only for a
very small period when we create the
pending order and increment the counts
for the relevant items
if the order processing fails we lock
again briefly and decrement the counts
we don't keep it locked for a long time
but
if we did this would also explain a
large amount of the performance problems
with the row locked during an order
somebody loading the home page can't
even load the list of things available
for sale as we can't determine if
something is out of stock or not while
it's locked
technically we don't even know if it
exists since the definition of the item
and the quantity are stored in the same
table in the same row
since we don't have hard limits this
year we checked with the executive team
to see if we need to stick to the hard
limit spec we had in 2019 or if we can
disable the row locks and maybe just go
over a little bit
they gave us a go ahead we disabled the
row locking we ran the test script again
and
this time it actually helped a little
bit
but each request was still far too slow
and after a minute everything started
timing out again
now at this time while the team was
digging through sql i decided to look at
a different problem
something we noticed while rebooting
containers and deploying new ones during
the ticket launch was that the server
side container image was taking about
three to five minutes from the time the
container started until the time that it
started listing for http requests on the
tcp port
i ripped in a javascript expert from
work to give me the rundown on how to do
some basic performance analysis and
debugging with node.js and he showed me
how to connect the chrome developer
tools to a node.js application
from there i extrapolated a bit and by
exposing the correct port number through
docker i managed to attach the chrome
devtools dev tools to node.js inside the
docker image
strangely while stepping through it on
my macbook the performance problem just
seemed to be in importing types
so i did some
some chin scratching i did some thinking
i did a lot of googling and discovered
there's an open issue on github that
docker for mac is just apparently really
really slow at file system operations
and clearly that's not our production
problem as azure kubernetes does not run
on mac os
so the next steps i took to debug this
was to create a new linux virtual
machine i used ubuntu because it's an
ancient african word for slightly easier
than debian i installed that on my
windows workstation pc installed docker
in there and started to debug from there
when running docker on linux our
container started up pretty much
instantly and it listened on port 3000
immediately
no performance problem to be seen
whatsoever
but like one of the main selling points
for containerization is that you have a
perfect reproducibility as you have the
same container image on all your systems
the only thing that's different is
hardware performance characteristics the
network
and the underlying linux kernel
and i didn't think any of those were
relevant here
so i went digging through our kubernetes
yaml for any major differences and came
across this fun block that i'd written a
long time ago and mostly forgotten
back after the 2019 convention while we
were downscaling everything back to
minimal business as usual operations the
yama linton visual studio code suggested
had resource limits and after reading
through the docs i thought well that
sounds like a really really good idea
resource limits sound good so i added
some limits based on the peak usage we'd
observed during the convention that year
i recreated the container image on my
ubuntu vm but this time limited the cpu
to just a quarter of a cpu core
and would you believe it
the image took three minutes to start up
this immediately threw a new light on
the whole situation
was it possible that our sequel after
all was perfectly fine but we were just
cpu constrained
after all during the 2019 ticket sales
we hadn't written the pdf generation
code
and the 2020 ticket sales were quite
lackluster due to the looming pandemic
and just general uncertainty
we commented out the function call to
generate the ticket pdf and attach it to
the email we push a new code to staging
only we re-ran the load test script and
bang all our requests will handle
lightning fast no performance problems
whatsoever
unfortunately we can't actually ship
these changes as people need their
ticket pdfs if they're going to attend
the convention that's the whole point of
buying the ticket
increasing the amount of cpu allocate
the container as well isn't hugely
beneficial we can go from 25 up to 100
and handle maybe four times as many
requests if it scales linearly
but any more than a single vcpu call
won't help as node.js is famously single
threaded
it's not going to farm out different
incoming requests to different cpu cores
by itself
in fact if you google how do i make
node.js use more cpu the top
stackoverflow answer is run multiple
copies of it duh
so we would somehow need to offload the
pdf generation another way
now that we figured out the technical
side we still have the human side to
understand
why did we have so many users trying to
buy tickets we had never seen this level
of demand before
i don't know for certain but i have two
hypotheses
the first is due to covert in 2020 there
were almost no events due to the
pandemic and the lockdowns there was no
smash no oops
there was no smash no supernova no oz
comic-con and no pax australia
it's quite possible that people were
just hungry for their cultural events
after a year of deprivation
the second hypothesis is due to
marketing
our early bird special was limited to
500 tickets but it seems at least a few
people misinterpreted the social media
posts and thought there were only 500
tickets to the event in total
some critical thinking might just that
downscaling the event that much isn't
really financially feasible
but you can just get up early and smash
the five button be one of those lucky
people
so now with all that information gleaned
from our investigation and the fixes we
put into place
we can now explain the original events
on the 2nd of may in its entirety
due to a huge amount of demand after a
year of cancelled events and possibly
fed by marketing miscommunication we had
way more users trying to order tickets
than in previous years
as the first orders started coming
through they held open sql transactions
which prevented subsequent requests or
request continuations from obtaining the
connection they needed
when we restarted and deployed new
backend images this interrupted a couple
requests inside the dodgy payments
transaction so that payment was never
recorded
pdf generation used up the full cpu
allocation so incoming requests were
added to the backlog
the server did not have enough cpu to
process this and definitely not its 25
cpu with three out of four hands tied
behind its back
and so after 60 seconds engine x gave up
on the request but no js continued to
process it
when users got gateway timeout errors
they retried which only further added to
the backlog
and after a certain point new requests
would always time out before they could
be handled by node.js since the backlog
was so large
none of these alone can be pinpointed as
the course of the outage
but our cheese had some pretty big holes
this all went down on sunday and the
investigation ran for several more days
but we needed to have ticket sales
operational again by thursday
for thursday we made several key changes
to our best to avoid repeat of the crash
on the application side we had fixed the
open transactions
and consolidated a few more requests
into fewer transactions
we removed sql queries from the code
that we didn't need and we disabled the
row locking
we also increased the connection pool
size
we also plan to offload pdf generation
to some azure functions view aws folk
think lambdas but obviously we wouldn't
have that ready by thursday
on the operations side we'd increase the
mysql connection limit we'd increase the
cpu limits for the server containers
from 25 of a cpu core to 95 of a cpu
core and we added an additional server
for a total of almost six times as much
cpu capacity as previously
the last change we made was to human
factors instead of hyping everyone up
again for a rush unlimited ticket sales
we changed the terms so anyone could
purchase a discounted weekend ticket
across a 10-hour window from 2pm until
midnight
and then we opened that window a few
minutes early to deal with any
over-eager customers
thursday's ticket sales were an absolute
success
not only did we manage our pre-sales
without crashing again we set a new
internal record for the number of
pre-sales tickets sold in a single day
unfortunately due to the delta outbreak
across new south wales and australia
we had to postpone the event four weeks
ago through to 2022.
however the lessons we learned here are
quite valuable and i share them with you
all today in the hope that they won't be
repeated frequently
the key things i took away from this
were to load test regularly
if you don't think you need a load test
for the event do it again anyway and
make sure the test is harder than you
think you'll encounter in production
you also need to understand profiling
tools before you urgently need them
we need to make sure to correctly deal
with timeouts and request cancellation
something that very often goes
overlooked in application development
to make sure that any panic buttons are
actually disaster proof and will work in
an emergency
and mostly
not to perform any cpu intensive work in
a single threaded web application
that's literally just asking for trouble
thank you
thanks jakov that was
an excellent talk and yes lots of great
lessons there about how to respond to
various kinds of oops
so i'm sure that everyone enjoyed that
talk i've seen a lot of really positive
comments there in the chat um now i
don't see any other questions
um but if you would like to hang out i
know you've been in the chat already
yakov so uh if people do have questions
and want to ask you about anything about
this what you've learned about how to
instrument my mysql um if you've
actually i have a question have you
managed to find any profiling tools for
mysql that would be useful i still
haven't if anybody knows of something
that does what we need there i would
absolutely love to know please drop me a
tweet or an email that's elephant
mind boggling i i recall having to do
this with other database systems many
many years ago when i was technical
and yeah not having that would be
horrendous
um thank you yakov once again for giving
a great talk and uh for everyone else
we're going to take a bit of a break uh
and we'll be back in a few minutes uh
about 15 minutes from now let's see
we're scheduled to be about 11 o'clock
so you've got 15 minutes before our next
talk with amit sahar which is called
planning for failure using chaos
engineering um so we've just had a talk
on how to fix things that went broken
but they got broken by accident now
we're going to break them on purpose
we'll see you all back here in about 15
minutes