Mapnik spends most of its time in font cache misses

[pnorman]

With debugging openstreetmap/mod_tile#333, I got to a Mapnik issue.

When run on OSMF servers, renderd normally consumes about 20% of CPU, regardless of load except for periods every ~8 minutes where it goes to 100% CPU and produces tiles at a normal rate. Attaching GDB when it was not producing tiles at a normal rate revealed 75% of the threads were in a mutex in mapnik::freetype_engine::create_face_impl. The one mutex in that function is for if a font file was found but is not yet in memory:

mapnik/src/font_engine_freetype.cpp

Line 376 in d69a090

std::lock_guard<std::mutex> lock(mutex_);

My reading of the function is that most of the time, the font should already be in memory and it won't hit the mutex. I don't know why this isn't happening.

The server is running the latest Mapnik release (3.1.0 (3.1.0+ds-1ubuntu2)) with OpenStreetMap Carto v5.7.0, which has a fairly long fonts list because it attempts to support all scripts.

There are some oddities I can't explain

• every 8 minutes throughput improves and Mapnik can use 100% of the CPU for about 75 seconds, followed by a partial improvement about 45 seconds later which lasts for 60 seconds. I have no idea why.

[tomhughes]

What I can say from stracing renderd is that it is constantly opening and reading the font files so the caching definitely isn't working.

Looking at the mod_tile source it will walk it's configured font directories and call freetype_engine::register_font on each font causing the faces to be registered in the global map and then when the map is loaded I believe mapnik will register them again in the local map.

I don't think that load_fonts is ever called on the map object though so we're reliant on the global cache for the font data and that doesn't appear to be thread safe - we hold the mutex while adding to it but not while doing lookups.

That said I don't see why that causes the symptoms we see - if anything I'd expect it to cause crashes!

[tomhughes]

Actually I think I see the problem - the local map is populated (but the local cache isn't as Map::load_fonts is never called) so freetype_engine::create_face_impl will find the face in the local map but not find it in the local cache and won't check the global cache but will just fall through to loading the face and trying to add it to the global cache - that will fail after the first time but we will still waste time loading it and taking the mutex.

Interestingly if the font wasn't found in the local map we would fall back to the global map and would then check the global cache, but without taking the mutex which isn't safe when multithreaded.