Recently, I had to investigate a “performance issue” a customer was having with one of their web services.
To make it simple, the service is a REST API to get information about points of interest. The response is quite large (hundreds of KBs) but nothing exceptional.
Several clients can perform multiple requests for the same POI, and the response for a single POI is almost the same: it varies a little over time with real time updates (traffic, info, last minute additions or cancellations) but it is roughly the same. So, the code was already doing the right thing, and cached the answer for each POI.
Well.. more or less the right thing. For a single POI, with ~1000 sub-items, the response time for the first request was ~39 seconds. Subsequent requests required half a second, so the caching was working.
The API is for consumption by a service, so there is no need to be “responsive” (as in “users will need quick feedback or they will walk away”), but still: 39 seconds!
The API is implemented in Java (JAX-RS + JPA to be precise), so armed with the profiler of choice (VisualVM) I started hunting for hot spots. Here is a list of DOs and DON’Ts I compiled while investigating and fixing the issues which can came handy. The list is not tied to Java, it is very general!
DO instrument your code with Log calls with timings at enter/exit of “hot” functions.
DO it at a logging level you can leave on in production (e.g.: INFO. But then leave INFO on!)
If you didn’t do that… you don’t have times :( But you need timing to see where you need to improve, so DO use a profiler!
DON’T just go for the function you believe is the slowest: a profiler trace may surprise you.
DO use a profile with instrumentation, not with sampling. In my experience, sampling is never precise enough.
When you have found your hot spots, DO move all costly, repeated operations you find to a place where they are done once (a constructor or initialization method). In this case, the offender was an innocent looking Config.get(“db.name”) method. Just to get the DB name from a config class. Which ended up opening a property file, reading it, parsing it every time. The method was doing a lot under the hood, but would you have looked at it without the hint from a profiler? See the previous point :)
DO cache data that does not change, if you are reading it from a DB or web service. Cache on the output is the basics, but it is often not nearly enough. You have to avoid multiple lookups for the same resource inside a single request!
DON’T do a DB (or even a cache!) lookup if you can find another way to get the same information, even when you need to re-compute a result (i.e. spend CPU time). In this service, each POI sub-item could be categorized in one of two classes using some of its attributes. The old implementation used a subset of attributes that needed to be checked with a DB lookup; I changed it to use a different set of attributes that needed a (simple) computation.
DO load the cache in bulk for small-ish sets of data. In this service, each string which contained information to be displayed to the user was looked up in a DB of “special cases” using complex fallback rules, each time generating a less refined query (up to 4). If nothing was found (~80% of the times), a default string was loaded from a Web Service. This operation alone accounted for 10 seconds, or 25% of the total time. The “not default” DB contains just around 4k items; a bulk query for all the rows requires only 100ms, can be easily stored in memory, and doing the filtering and matching in memory costs just a few ms more.
DO use simple libraries: communication with other Web Services was done using a very easy to use but quite heavy library (Jersey + Jackson for JSON deserialization). I switched to a custom client written with OkHttp and GSON, and the net save was 4 whole seconds.
DO enable compression on the result (if the user agent says it supports compression - most do!)
DO minimize copy and allocations: in this case (but this advice applies to Java in general), I used streams instead of lists whenever possible, down to the response buffer.
DON’T use the DB, especially NOT the same DB you use for you primary data, to store “logs”. In this case, it was access logs for rate limiting. A client hitting the service hard could consume a lot of resources just to generate a 429 Too Many Requests response.
Recording such an event to your primary DB is the perfect opportunity for a DoS attack.
Remember the times?
39 seconds for the first request
0.5 seconds for subsequent request son the same object
1 second for the first request
50 milliseconds (0.05 seconds) for subsequent requests on the same object
It is more than an order of magnitude. I’m quite happy, and so was the customer! The time can be brought time even further by ditching the ORM framework (JPA in this case) and going for native (JDBC) queries, changing some algorithms, using a different exchange format (e.g. protobuf instead of JSON), but with increasing effort and diminishing results. And for this customer, the result was already more than they asked for.