Performance issue with MAPNIK_LOG #1175

Closed
springmeyer opened this Issue Apr 12, 2012 · 10 comments

2 participants

@springmeyer
Mapnik member

/cc @kunitoki

In a multithreaded rendering scenario (common with mod_tile/renderd and tilemill) we have to completely avoid using formatting c++ strings due to locale locking. See #1055 for more detail.

The recent logging framework introduces a problem. We previously had some std::clog printing for key failures that should not throw like when loading images or svg. Now if Mapnik is built without ENABLE_LOG these warning do not show up. So, I figured we should then try enabling logging by default and look for performance problems (4d4316f).

Here is the first, and it is major. When parsing wkb there is a single debug statement which is causing a slowdown in rendering even though absolutely no output is happening to the console.

This statement is absolutely killing performance, accounting for 98% of wkb total parsing time, with 25% being taken up with mapnik::detail::base_log, 23% with wkb_geometry_type_string and the remainder spent in string alloc/dealloc.

Here is the locale locking details for base_log:

@springmeyer
Mapnik member

more trouble. Even with ENABLE_LOG=False, the compiler is NOT optimizing out the MAPNIK_LOG_DEBUG line in wkb.cpp and therefore wkb_geometry_type_string is still killing perf. There are pages and pages of this:

@kunitoki
Mapnik member

yeah i see. let me some time to settle this. the compiler will optimize this out if there is no function call that feed the ostream, so yes definately we need to protect those outputs with ifdefs. but piping string and variables to the output will be optimized.

another thing is have MAPNIK_ERROR_LOG and fatal reach output even if enable log is disabled. will take care of this.

@kunitoki
Mapnik member

Check if d717c71 fixes the issue. Now you don't need to define MAPNIK_LOG when building in release mode, but errors and fatals still gets printed out (unless you specify none as severity).

@springmeyer springmeyer added a commit that referenced this issue Apr 12, 2012
@springmeyer springmeyer make a non-existant marker file a MAPNIK_LOG_ERROR not MAPNIK_LOG_WAR…
…N so that the message shows up even if MAPNIK_LOG is off - refs #1175
c50c401
@springmeyer
Mapnik member

great, appears to work - I'm seeing MAPNIK_ERROR_LOG now. Will post back when I have a chance to look at performance more.

@kunitoki
Mapnik member

btw. looking at the old code, the wkb debug output was commented out even in debug mode (probably a debug output used when developing it only).

@springmeyer
Mapnik member

just found another one: a902a08#include/mapnik/font_engine_freetype.hpp

Previously we would output nothing in non-debug. Now we output (and lock) for ever character of every text string for a fallback font that is not found. This turns a 2 second map render into 13 seconds. Its interesting because I think it points to potentially other bugs. Anyway, the fix is easy, just wrapping in MAPNIK_LOG, which I will do shortly.

@kunitoki
Mapnik member

ok. i thought that one was a error that needed to be reported even in release mode. try changing it to use MAPNIK_LOG_DEBUG and check if font_face.get_name is const... it will be enough to be optimized.

btw one of the problem i had with mapnik in production was exactly this... all the important errors and reports was eliminated, so i needed a 2 step test every time things doesn't work: recompile in debug, test, fix, recompile in release

@springmeyer
Mapnik member

this did expose a fontset bug, which took the remainder of my day to figure out. I will push tomorrow when I have a chance. great that this churn from logging is helping uncover things like this. thx

@springmeyer
Mapnik member

fontset bug fixed in #1182, so now this problem should never occur and should only be printed in full debug mode - fix for that coming next.

@springmeyer
Mapnik member

I've see no further major perf regressions related to this and no other bugs that its has unconvered, so I'm happy with where we are at now. Thanks @kunitoki! Closing.

@springmeyer springmeyer closed this Jul 6, 2012
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment