Small @rustlang debugging story... I work on a paragliding flight book website ( https://flugbuech.bargen.dev/ ). The project is written with Rocket, data is in PostgreSQL/PostGIS. The main idea is that pilots upload flight tracklog in IGC format to add flight log entries. (1/n)

When using the website myself, I noticed that the flight list was getting slower and slower. I assumed a typical SQL issue (n+1 query, or the like) and turned on the Postgres slow query log. However, very few queries, and no slow queries >100ms. The request was taking >1s though.

Ok, this is strange. Apparently the problem is on the Rust side? I thought Rust was lightning fast?!

Let's profile! I enabled debug symbols for the release build and started the server in release mode using valgrind+callgrind, followed by the slow HTTP request.

The resulting file can be analyzed with kcachegrind. Its output is a bit difficult to parse, but I could definitely see that a lot of time was spent inside the Tera templating engine, and some Serde serialization stuff. Maybe a performance bug in the template engine?

First, let's ensure that the rendering is indeed the culprit. In the source code that returns the template + the context, I replaced the list of flights with an empty vector. This worked, the request was now really fast again!

So somehow serializing the flights seems to be really slow. But why? Maybe I have some fields with custom serialization in that struct, which are implemented inefficiently?

Let's look at the "Flight" struct, which is a Diesel model.

So, first of all, no custom types in the fields. Some integers, some datetimes, some strings. Nothing here looks fishy. I was very confused.

However, then I noticed the "igc" field. This field holds binary data from the user file upload ("bytea" in Postgres).

The size of such an IGC file (essentially a signed GPS tracklog with some metadata, generated by your flight computer) can be several 100 kilobytes, or even a few megabytes in size. And suddenly I understood what the problem was...

When the context is sent to the template engine, everything is first serialized to a JSON-like representation using Serde. I never use this "igc" field in my templates. However, it is present in the data being serialized. And because Tera allows live-reloading of templates...

...all data must be serialized, no matter whether the fields are currently used in the template or not. This means that every flight in-memory representation contained a potentially multi-megabyte JSON byte array. Of course this must be slow, lots of allocations and copying!

To verify that serializing the "igc" field is indeed the root cause, I temporarily set the value of the "igc" field to "None" for every flight. And – lo and behold – I was back at <100ms request times!

Morale of the story: Even with a fast programming language like Rust, allocating and copying lots of data can be slow. When serializing objects for consumption in your templates, it's probably best to use a dedicated struct which only contains the fields needed.

Furthermore, large binary data should probably be moved to either a dedicated database table, or to the file system. For simplicity reasons, I'll probably choose the former.

(fin)