MapCache Performance Analysis A Case Study
(Note: This work has been carried out on a development version of MapCache 1.10. Some information may be wrong on earlier releases)
[TL;DR] Here are given the available optimization options in MapCache which are relevant for this case study. Detailed descriptions and actual measures are given in the next sections.
By default, MapCache works in a single thread. When an incoming request involves fetching multiple tiles, it may be desirable to assign a thread for each tile fetch. Two configuration options exist to enable multi-threaded fetching:
-
At
<mapcache>level for fetching tiles of a map (WMS) (Configuration):<mapcache> <threaded_fetching>true</threaded_fetching>
-
At
<dimensions>level for fetching subtiles to assemble into a tile (Tileset dimensions):<dimensions> <assembly_threaded_fetching>true</assembly_threaded_fetching>
Measures given in the following sections (and carried out on the specific use case depicted below) show that multithreading at <mapcache> (or tile) level improves performances. They also show that multithreading at <dimensions> (or subtile) level actually degrades performances.
The <validate_query> element defines a query returning the list of sub-dimension entries for a given dimension value. It should be tuned so as to minimize the number of returned entries and therefore the number of subtiles to be fetched. For example to narrow query results to relevant geographical extents:
-
A
<validate_query>without geographical filter:<validate_query> SELECT subtile FROM catalog WHERE keyword LIKE "%"|| :dim ||"%" </validate_query>
-
A
<validate_query>with geographical filter:<validate_query> SELECT subtile FROM catalog WHERE keyword LIKE "%"|| :dim ||"%" AND minx <= :maxx AND maxx >= :minx AND miny <= :maxy AND maxy >= :miny </validate_query>
Other use cases may involve other narrowing filters such as date and time for instance.
By default, MapCache runs <validate_query> of second level dimensions for every requested tile of a map. When this involves slow remote PostgreSQL or ElasticSearch servers, it may be desirable to send the query only once for the whole map. A configuration option at the <dimension> level exists to enable this behaviour (Tileset dimensions):
<dimension>
<wms_querybymap>true</wms_querybymap>As obvious as it may seem, verifying that SQLite caches are configured with speed in mind may sometimes improve query performances. Adding an index can contribute to that goal, e.g.:
CREATE UNIQUE INDEX xyz ON tiles (x,y,z);#Introduction
A satellite imagery provider wants a browser to display its product catalog. Each product is an image of a small area on Earth (about 100km wide) and there are hundreds of products.
The solution is built around MapCache serving selected products through its WMS/WMTS map services. Products are preprocessed to take the form of single SQLite caches or Geopackages directly accessible by MapCache. Product selection takes place using dimension feature of those services. This is implemented with second level dimensions in MapCache, so that new products can be added without interrupting MapCache service.
In order to validate or amend various design or implementation details, a mockup of that imagery browser is created with OpenLayers. It is fed with simulated satellite image products, which are actually built from OpenStreetMap data (see MapCache mockup for detailed description and how to get/use it).
As an illustration, the following picture (downscaled here at 50%) shows a catalog displaying 400 imagery products spread over USA, Europe and Australia on a low resolution basemap.
Of course the catalog browser should be as fast as possible. But the above image takes about 5 seconds to be rendered on the mockup browser with default MapCache configuration. Worse, a WMS request of the same map needs about 7 seconds to be served.
For improving this behaviour, one first needs to understand how MapCache retrieves tiles from its caches and assemble them to produce a composite map.
The easiest way of measuring MapCache performance is to time WMS or WMTS requests from any HTTP client. This is as close as can be observed from the user perspective and their feeling about MapCache performance.
This timing feature is provided by "Developer" menu on common graphic web browsers. This is also possible on a Linux command line interface with a combination of time and curl commands, e.g.:
$ time curl -s "http://localhost:8888/world/wmts/1.0.0/world/default/GoogleMapsCompatible/0/0/0" > tile.jpg
real 0m0.078s
user 0m0.035s
sys 0m0.013s
Nevertheless, a better understanding of how MapCache works and where performance can be improved is achieved by opening the hood.
The main observation point for this analysis is the Apache log where all Apache modules, including MapCache, are able to write data. Every log line is time tagged to the microsecond and is identified by module, by log level, by process/thread ID and by client IP address, e.g.:
[Mon Jan 06 13:44:11.716120 2020] [mapcache:debug] [pid 46:tid 140338173826816] mod_mapcache.c(448): [client 172.17.0.1:51862] mapcache quick handler hook on uri /world, referer: http://localhost:8888/ol/
The log level is configured in Apache configuration file with the LogLevel keyword, e.g.:
LogLevel warn mapcache:debug
Some instrumentation is also needed in MapCache source code so that execution path can be followed and timed. The basic idea is to insert debug traces at places of interest, in particular at function beginning and end. This first example shows how to measure the overall time needed by MapCache to serve a request.
$ git diff -U1 apache/mod_mapcache.c
diff --git a/apache/mod_mapcache.c b/apache/mod_mapcache.c
index 5e5c437..b081d70 100644
--- a/apache/mod_mapcache.c
+++ b/apache/mod_mapcache.c
@@ -345,2 +345,3 @@ static int mapcache_handler(request_rec *r, mapcache_alias_entry *alias_entry) {
+ ap_log_rerror(APLOG_MARK, APLOG_DEBUG, 0, r, "MOCKUP BEGIN mapcache_handler");
//ap_log_rerror(APLOG_MARK, APLOG_DEBUG, 0, r, "mapcache dispatch %s",r->path_info);
@@ -439,2 +443,3 @@ static int mapcache_handler(request_rec *r, mapcache_alias_entry *alias_entry) {
}
+ ap_log_rerror(APLOG_MARK, APLOG_DEBUG, 0, r, "MOCKUP END mapcache_handler");
return write_http_response(apache_)ctx,http_response);
When a request is sent to MapCache, the following debug traces are written in Apache log:
[Wed Jan 15 12:17:50.503563 2020] [mapcache:debug] [pid 4323:tid 139713916184320] mod_mapcache.c(346): [client 127.0.0.1:38854] MOCKUP BEGIN mapcache_handler
[Wed Jan 15 12:17:50.704452 2020] [mapcache:debug] [pid 4323:tid 139713916184320] mod_mapcache.c(444): [client 127.0.0.1:38854] MOCKUP END mapcache_handler
A specific tool parselog.sh is provided with the mockup to make this log more readable and concise: Traces are arranged by thread, they hightlight execution call graph with appropriate indentation, and they give duration in microseconds for each BEGIN/END pair.
Thread #4323:139713916184320:0:
{'BEGIN:mapcache_handler': 200889}
{'END..:mapcache_handler': 200889}
With appropriate instrumentation, the execution path from initial request to tile retrieval can be observed. For instance, let's fetch a tile and analyze resulting Apache log:
# cp /dev/null /var/log/apache2/error.log
# curl -s "http://localhost:80/catalog/wmts/1.0.0/base/default/GoogleMapsCompatible/0/0/0" > tile.jpg
# /share/bin/parselog.py < /var/log/apache2/error.log
Thread #4322:139713776170752:0:
{'BEGIN:mapcache_handler': 37567}
{'BEGIN:mapcache_core_get_tile': 20584}
{'BEGIN:mapcache_prefetch_tiles': 326}
{'BEGIN:mapcache_tileset_tile_get': 281}
{'BEGIN:mapcache_tileset_tile_get_without_subdimensions': 240}
{'BEGIN:mapcache_cache_tile_get': 197}
{'BEGIN:_mapcache_cache_disk_get': 152}
{'END..:_mapcache_cache_disk_get': 152}
{'END..:mapcache_cache_tile_get': 197}
{'END..:mapcache_tileset_tile_get_without_subdimensions': 240}
{'END..:mapcache_tileset_tile_get': 281}
{'END..:mapcache_prefetch_tiles': 326}
{'END..:mapcache_core_get_tile': 20584}
{'END..:mapcache_handler': 37567}
Unsurprisingly, the execution path flows from the module handler down to the actual tile retrieval in a disk cache.
A map composed of 4 tiles leads to a similar execution path, only with more steps:
# cp /dev/null /var/log/apache2/error.log
# curl -s "http://localhost:80/osm?SERVICE=WMS&REQUEST=GetMap&BBOX=-20037508.342789,-20037508.342789,20037508.342789,20037508.342789&WIDTH=512&HEIGHT=512&SRS=EPSG:3857&LAYERS=wikimedia" > map.jpg
# /share/bin/parselog.py < /var/log/apache2/error.log
Thread #685:139703181362944:0:
{'BEGIN:mapcache_handler': 15355}
{'BEGIN:mapcache_core_get_map': 15318}
{'BEGIN:mapcache_assemble_maps': 9298}
{'BEGIN:mapcache_prefetch_tiles': 661}
{'BEGIN:mapcache_tileset_tile_get': 236}
{'BEGIN:mapcache_tileset_tile_get_without_subdimensions': 218}
{'BEGIN:mapcache_cache_tile_get': 193}
{'BEGIN:mapcache_cache_tile_get': 192}
{'BEGIN:_mapcache_cache_sqlite_get': 159}
{'END..:_mapcache_cache_sqlite_get': 159}
{'END..:mapcache_cache_tile_get': 193}
{'END..:mapcache_cache_tile_get': 192}
{'END..:mapcache_tileset_tile_get_without_subdimensions': 218}
{'END..:mapcache_tileset_tile_get': 236}
{'BEGIN:mapcache_tileset_tile_get': 125}
{'BEGIN:mapcache_tileset_tile_get_without_subdimensions': 109}
{'BEGIN:mapcache_cache_tile_get': 85}
{'BEGIN:mapcache_cache_tile_get': 85}
{'BEGIN:_mapcache_cache_sqlite_get': 60}
{'END..:_mapcache_cache_sqlite_get': 60}
{'END..:mapcache_cache_tile_get': 85}
{'END..:mapcache_cache_tile_get': 85}
{'END..:mapcache_tileset_tile_get_without_subdimensions': 109}
{'END..:mapcache_tileset_tile_get': 125}
{'BEGIN:mapcache_tileset_tile_get': 126}
{'BEGIN:mapcache_tileset_tile_get_without_subdimensions': 110}
{'BEGIN:mapcache_cache_tile_get': 85}
{'BEGIN:mapcache_cache_tile_get': 85}
{'BEGIN:_mapcache_cache_sqlite_get': 60}
{'END..:_mapcache_cache_sqlite_get': 60}
{'END..:mapcache_cache_tile_get': 85}
{'END..:mapcache_cache_tile_get': 85}
{'END..:mapcache_tileset_tile_get_without_subdimensions': 110}
{'END..:mapcache_tileset_tile_get': 126}
{'BEGIN:mapcache_tileset_tile_get': 121}
{'BEGIN:mapcache_tileset_tile_get_without_subdimensions': 105}
{'BEGIN:mapcache_cache_tile_get': 80}
{'BEGIN:mapcache_cache_tile_get': 79}
{'BEGIN:_mapcache_cache_sqlite_get': 54}
{'END..:_mapcache_cache_sqlite_get': 54}
{'END..:mapcache_cache_tile_get': 80}
{'END..:mapcache_cache_tile_get': 79}
{'END..:mapcache_tileset_tile_get_without_subdimensions': 105}
{'END..:mapcache_tileset_tile_get': 121}
{'END..:mapcache_prefetch_tiles': 661}
{'BEGIN:mapcache_tileset_assemble_map_tiles': 8585}
{'END..:mapcache_tileset_assemble_map_tiles': 8585}
{'END..:mapcache_assemble_maps': 9298}
{'BEGIN:_mapcache_imageio_jpeg_encode': 5971}
{'END..:_mapcache_imageio_jpeg_encode': 5971}
{'END..:mapcache_core_get_map': 15318}
{'END..:mapcache_handler': 15355}
In the previous example it is worth noting that only one thread is involved. A configuration option exists to change this behaviour (see MapCache configuration documentation):
<mapcache>
<threaded_fetching>true</threaded_fetching>When this option is enabled, each tile of a map is fetched in its own thread:
# cp /dev/null /var/log/apache2/error.log
# curl -s "http://localhost:80/osm-mt?SERVICE=WMS&REQUEST=GetMap&BBOX=-20037508.342789,-20037508.342789,20037508.342789,20037508.342789&WIDTH=512&HEIGHT=512&SRS=EPSG:3857&LAYERS=wikimedia" > map.jpg
# /share/bin/parselog.py < /var/log/apache2/error.log
Thread #2865:139904063371008:0:
{'BEGIN:_thread_get_tile': 699}
{'BEGIN:mapcache_tileset_tile_get': 680}
{'BEGIN:mapcache_tileset_tile_get_without_subdimensions': 668}
{'BEGIN:mapcache_cache_tile_get': 655}
{'BEGIN:_mapcache_cache_sqlite_get': 640}
{'END..:_mapcache_cache_sqlite_get': 640}
{'END..:mapcache_cache_tile_get': 655}
{'END..:mapcache_tileset_tile_get_without_subdimensions': 668}
{'END..:mapcache_tileset_tile_get': 680}
{'END..:_thread_get_tile': 699}
Thread #2865:139904415667968:0:
{'BEGIN:_thread_get_tile': 1264}
{'BEGIN:mapcache_tileset_tile_get': 1238}
{'BEGIN:mapcache_tileset_tile_get_without_subdimensions': 1223}
{'BEGIN:mapcache_cache_tile_get': 1209}
{'BEGIN:_mapcache_cache_sqlite_get': 1066}
{'END..:_mapcache_cache_sqlite_get': 1066}
{'END..:mapcache_cache_tile_get': 1209}
{'END..:mapcache_tileset_tile_get_without_subdimensions': 1223}
{'END..:mapcache_tileset_tile_get': 1238}
{'END..:_thread_get_tile': 1264}
Thread #2865:139904054978304:0:
{'BEGIN:_thread_get_tile': 1032}
{'BEGIN:mapcache_tileset_tile_get': 1007}
{'BEGIN:mapcache_tileset_tile_get_without_subdimensions': 995}
{'BEGIN:mapcache_cache_tile_get': 979}
{'BEGIN:_mapcache_cache_sqlite_get': 937}
{'END..:_mapcache_cache_sqlite_get': 937}
{'END..:mapcache_cache_tile_get': 979}
{'END..:mapcache_tileset_tile_get_without_subdimensions': 995}
{'END..:mapcache_tileset_tile_get': 1007}
{'END..:_thread_get_tile': 1032}
Thread #2865:139904046585600:0:
{'BEGIN:_thread_get_tile': 467}
{'BEGIN:mapcache_tileset_tile_get': 145}
{'BEGIN:mapcache_tileset_tile_get_without_subdimensions': 125}
{'BEGIN:mapcache_cache_tile_get': 111}
{'BEGIN:_mapcache_cache_sqlite_get': 96}
{'END..:_mapcache_cache_sqlite_get': 96}
{'END..:mapcache_cache_tile_get': 111}
{'END..:mapcache_tileset_tile_get_without_subdimensions': 125}
{'END..:mapcache_tileset_tile_get': 145}
{'END..:_thread_get_tile': 467}
Thread #2865:139905445218048:0:
{'BEGIN:mapcache_handler': 14401}
{'BEGIN:mapcache_prefetch_tiles': 1515}
{'END..:mapcache_prefetch_tiles': 1515}
{'END..:mapcache_handler': 14401}
In this example the request is a single tile featuring four selected products from the catalog: Everest, Aconcagua, Elbrus and Kilimanjaro.
# cp /dev/null /var/log/apache2/error.log
# curl -s "http://localhost:80/catalog?SERVICE=WMS&REQUEST=GetMap&BBOX=-20037508.342789,-20037508.342789,20037508.342789,20037508.342789&WIDTH=256&HEIGHT=256&SRS=EPSG:3857&LAYERS=base,catalog&DIM_PRODUCT=peak" > map.jpg
# /share/bin/parselog.py < /var/log/apache2/error.log
Thread #3557:140287389202176:0:
{'BEGIN:mapcache_handler': 15065}
{'BEGIN:mapcache_core_get_tile': 14960}
{'BEGIN:mapcache_prefetch_tiles': 11488}
{'BEGIN:mapcache_tileset_tile_get': 118}
{'BEGIN:mapcache_tileset_tile_get_without_subdimensions': 101}
{'BEGIN:mapcache_cache_tile_get': 78}
{'BEGIN:_mapcache_cache_disk_get': 56}
{'END..:_mapcache_cache_disk_get': 56}
{'END..:mapcache_cache_tile_get': 78}
{'END..:mapcache_tileset_tile_get_without_subdimensions': 101}
{'END..:mapcache_tileset_tile_get': 118}
{'BEGIN:mapcache_tileset_tile_get': 11345}
{'BEGIN:mapcache_tileset_tile_get_with_subdimensions': 11332}
{'BEGIN:mapcache_tileset_tile_set_get_with_subdimensions': 11308}
{'BEGIN:mapcache_dimension_get_entries_for_value': 1071}
{'END..:mapcache_dimension_get_entries_for_value': 1071}
{'BEGIN:mapcache_tileset_tile_get_without_subdimensions': 462}
{'BEGIN:mapcache_cache_tile_get': 445}
{'BEGIN:_mapcache_cache_sqlite_get': 418}
{'END..:_mapcache_cache_sqlite_get': 418}
{'END..:mapcache_cache_tile_get': 445}
{'END..:mapcache_tileset_tile_get_without_subdimensions': 462}
{'BEGIN:mapcache_tileset_tile_get_without_subdimensions': 416}
{'BEGIN:mapcache_cache_tile_get': 401}
{'BEGIN:_mapcache_cache_sqlite_get': 381}
{'END..:_mapcache_cache_sqlite_get': 381}
{'END..:mapcache_cache_tile_get': 401}
{'END..:mapcache_tileset_tile_get_without_subdimensions': 416}
{'BEGIN:mapcache_tileset_tile_get_without_subdimensions': 355}
{'BEGIN:mapcache_cache_tile_get': 334}
{'BEGIN:_mapcache_cache_sqlite_get': 314}
{'END..:_mapcache_cache_sqlite_get': 314}
{'END..:mapcache_cache_tile_get': 334}
{'END..:mapcache_tileset_tile_get_without_subdimensions': 355}
{'BEGIN:mapcache_tileset_tile_get_without_subdimensions': 333}
{'BEGIN:mapcache_cache_tile_get': 307}
{'BEGIN:_mapcache_cache_sqlite_get': 290}
{'END..:_mapcache_cache_sqlite_get': 290}
{'END..:mapcache_cache_tile_get': 307}
{'END..:mapcache_tileset_tile_get_without_subdimensions': 333}
{'END..:mapcache_tileset_tile_set_get_with_subdimensions': 11308}
{'END..:mapcache_tileset_tile_get_with_subdimensions': 11332}
{'END..:mapcache_tileset_tile_get': 11345}
{'END..:mapcache_prefetch_tiles': 11488}
{'END..:mapcache_core_get_tile': 14960}
{'END..:mapcache_handler': 15065}
From the tileset/layer point of view, two tiles are fetched (&LAYERS=base,catalog): one for the basemap and the other for the requested products in catalog (&DIM_PRODUCT=peak). This second tile is indeed composed of four subtiles, one for each product matching the dimension value (Everest, Aconcagua, Elbrus and Kilimanjaro).
Following a similar logic as for maps, one can configure MapCache to spawn a thread for every subtile to be fetched (see MapCache Tileset Dimensions Documentation.
<dimensions>
<assembly_threaded_fetching maxzoom="5">true</assembly_threaded_fetching>When this option is enabled, subtiles are fetched in their own thread.
# cp /dev/null /var/log/apache2/error.log
# curl -s "http://localhost:80/catalog-amt?SERVICE=WMS&REQUEST=GetMap&BBOX=-20037508.342789,-20037508.342789,20037508.342789,20037508.342789&WIDTH=256&HEIGHT=256&SRS=EPSG:3857&LAYERS=base,catalog&DIM_PRODUCT=peak" > map.jpg
# /share/bin/parselog.py < /var/log/apache2/error.log
Thread #74:140616306497280:0:
{'BEGIN:_thread_get_subtile': 1178}
{'BEGIN:mapcache_tileset_tile_get_without_subdimensions': 1144}
{'BEGIN:mapcache_cache_tile_get': 1123}
{'BEGIN:_mapcache_cache_sqlite_get': 1092}
{'END..:_mapcache_cache_sqlite_get': 1092}
{'END..:mapcache_cache_tile_get': 1123}
{'END..:mapcache_tileset_tile_get_without_subdimensions': 1144}
{'END..:_thread_get_subtile': 1178}
Thread #74:140615350220544:0:
{'BEGIN:_thread_get_subtile': 1038}
{'BEGIN:mapcache_tileset_tile_get_without_subdimensions': 1010}
{'BEGIN:mapcache_cache_tile_get': 989}
{'BEGIN:_mapcache_cache_sqlite_get': 949}
{'END..:_mapcache_cache_sqlite_get': 949}
{'END..:mapcache_cache_tile_get': 989}
{'END..:mapcache_tileset_tile_get_without_subdimensions': 1010}
{'END..:_thread_get_subtile': 1038}
Thread #74:140615341827840:0:
{'BEGIN:_thread_get_subtile': 1053}
{'BEGIN:mapcache_tileset_tile_get_without_subdimensions': 980}
{'BEGIN:mapcache_cache_tile_get': 957}
{'BEGIN:_mapcache_cache_sqlite_get': 931}
{'END..:_mapcache_cache_sqlite_get': 931}
{'END..:mapcache_cache_tile_get': 957}
{'END..:mapcache_tileset_tile_get_without_subdimensions': 980}
{'END..:_thread_get_subtile': 1053}
Thread #74:140615333435136:0:
{'BEGIN:_thread_get_subtile': 607}
{'BEGIN:mapcache_tileset_tile_get_without_subdimensions': 546}
{'BEGIN:mapcache_cache_tile_get': 523}
{'BEGIN:_mapcache_cache_sqlite_get': 486}
{'END..:_mapcache_cache_sqlite_get': 486}
{'END..:mapcache_cache_tile_get': 523}
{'END..:mapcache_tileset_tile_get_without_subdimensions': 546}
{'END..:_thread_get_subtile': 607}
Thread #74:140616440715008:0:
{'BEGIN:mapcache_handler': 14558}
{'BEGIN:mapcache_core_get_tile': 14514}
{'BEGIN:mapcache_prefetch_tiles': 11195}
{'BEGIN:mapcache_tileset_tile_get': 102}
{'BEGIN:mapcache_tileset_tile_get_without_subdimensions': 86}
{'BEGIN:mapcache_cache_tile_get': 68}
{'BEGIN:_mapcache_cache_disk_get': 52}
{'END..:_mapcache_cache_disk_get': 52}
{'END..:mapcache_cache_tile_get': 68}
{'END..:mapcache_tileset_tile_get_without_subdimensions': 86}
{'END..:mapcache_tileset_tile_get': 102}
{'BEGIN:mapcache_tileset_tile_get': 11070}
{'BEGIN:mapcache_tileset_tile_get_with_subdimensions': 11055}
{'BEGIN:mapcache_tileset_tile_set_get_with_subdimensions': 11024}
{'BEGIN:mapcache_dimension_get_entries_for_value': 657}
{'END..:mapcache_dimension_get_entries_for_value': 657}
{'END..:mapcache_tileset_tile_set_get_with_subdimensions': 11024}
{'END..:mapcache_tileset_tile_get_with_subdimensions': 11055}
{'END..:mapcache_tileset_tile_get': 11070}
{'END..:mapcache_prefetch_tiles': 11195}
{'END..:mapcache_core_get_tile': 14514}
{'END..:mapcache_handler': 14558}
On this specific example, no performance gain can be observed. Most of the time spent to build the map is used to decode PNG subtiles, whereas multi-threading in this case involves only fetching them, which is not as much time consuming as PNG decoding.
In this example, the request is a map composed of 4 tiles and featuring the same four products from the catalog as in the previous section: Everest, Aconcagua, Elbrus and Kilimanjaro. For clarity, single-threaded fetching is selected.
# cp /dev/null /var/log/apache2/error.log
# curl -s "http://localhost:80/catalog?SERVICE=WMS&REQUEST=GetMap&BBOX=-20037508.342789,-20037508.342789,20037508.342789,20037508.342789&WIDTH=512&HEIGHT=512&SRS=EPSG:3857&LAYERS=base,catalog&DIM_PRODUCT=peak" > map.jpg
# /share/bin/parselog.py < /var/log/apache2/error.log
Thread #74:140616449107712:0:
{'BEGIN:mapcache_handler': 115246}
{'BEGIN:mapcache_prefetch_tiles': 20978}
{'BEGIN:mapcache_tileset_tile_get': 125}
{'BEGIN:mapcache_tileset_tile_get_without_subdimensions': 108}
{'BEGIN:mapcache_cache_tile_get': 91}
{'BEGIN:_mapcache_cache_disk_get': 73}
{'END..:_mapcache_cache_disk_get': 73}
{'END..:mapcache_cache_tile_get': 91}
{'END..:mapcache_tileset_tile_get_without_subdimensions': 108}
{'END..:mapcache_tileset_tile_get': 125}
{'BEGIN:mapcache_tileset_tile_get': 98}
{'BEGIN:mapcache_tileset_tile_get_without_subdimensions': 82}
{'BEGIN:mapcache_cache_tile_get': 66}
{'BEGIN:_mapcache_cache_disk_get': 49}
{'END..:_mapcache_cache_disk_get': 49}
{'END..:mapcache_cache_tile_get': 66}
{'END..:mapcache_tileset_tile_get_without_subdimensions': 82}
{'END..:mapcache_tileset_tile_get': 98}
{'BEGIN:mapcache_tileset_tile_get': 102}
{'BEGIN:mapcache_tileset_tile_get_without_subdimensions': 86}
{'BEGIN:mapcache_cache_tile_get': 70}
{'BEGIN:_mapcache_cache_disk_get': 53}
{'END..:_mapcache_cache_disk_get': 53}
{'END..:mapcache_cache_tile_get': 70}
{'END..:mapcache_tileset_tile_get_without_subdimensions': 86}
{'END..:mapcache_tileset_tile_get': 102}
{'BEGIN:mapcache_tileset_tile_get': 93}
{'BEGIN:mapcache_tileset_tile_get_without_subdimensions': 77}
{'BEGIN:mapcache_cache_tile_get': 61}
{'BEGIN:_mapcache_cache_disk_get': 44}
{'END..:_mapcache_cache_disk_get': 44}
{'END..:mapcache_cache_tile_get': 61}
{'END..:mapcache_tileset_tile_get_without_subdimensions': 77}
{'END..:mapcache_tileset_tile_get': 93}
{'BEGIN:mapcache_tileset_tile_get': 12954}
{'BEGIN:mapcache_tileset_tile_get_with_subdimensions': 12940}
{'BEGIN:mapcache_tileset_tile_set_get_with_subdimensions': 12927}
{'BEGIN:mapcache_dimension_get_entries_for_value': 7236}
{'END..:mapcache_dimension_get_entries_for_value': 7236}
{'BEGIN:mapcache_tileset_tile_get_without_subdimensions': 1994}
{'BEGIN:mapcache_cache_tile_get': 1964}
{'BEGIN:_mapcache_cache_sqlite_get': 1935}
{'END..:_mapcache_cache_sqlite_get': 1935}
{'END..:mapcache_cache_tile_get': 1964}
{'END..:mapcache_tileset_tile_get_without_subdimensions': 1994}
{'BEGIN:mapcache_tileset_tile_get_without_subdimensions': 1707}
{'BEGIN:mapcache_cache_tile_get': 1688}
{'BEGIN:_mapcache_cache_sqlite_get': 1661}
{'END..:_mapcache_cache_sqlite_get': 1661}
{'END..:mapcache_cache_tile_get': 1688}
{'END..:mapcache_tileset_tile_get_without_subdimensions': 1707}
{'BEGIN:mapcache_tileset_tile_get_without_subdimensions': 283}
{'BEGIN:mapcache_cache_tile_get': 270}
{'BEGIN:_mapcache_cache_sqlite_get': 252}
{'END..:_mapcache_cache_sqlite_get': 252}
{'END..:mapcache_cache_tile_get': 270}
{'END..:mapcache_tileset_tile_get_without_subdimensions': 283}
{'BEGIN:mapcache_tileset_tile_get_without_subdimensions': 1614}
{'BEGIN:mapcache_cache_tile_get': 1601}
{'BEGIN:_mapcache_cache_sqlite_get': 1578}
{'END..:_mapcache_cache_sqlite_get': 1578}
{'END..:mapcache_cache_tile_get': 1601}
{'END..:mapcache_tileset_tile_get_without_subdimensions': 1614}
{'END..:mapcache_tileset_tile_set_get_with_subdimensions': 12927}
{'END..:mapcache_tileset_tile_get_with_subdimensions': 12940}
{'END..:mapcache_tileset_tile_get': 12954}
{'BEGIN:mapcache_tileset_tile_get': 2206}
{'BEGIN:mapcache_tileset_tile_get_with_subdimensions': 2187}
{'BEGIN:mapcache_tileset_tile_set_get_with_subdimensions': 2176}
{'BEGIN:mapcache_dimension_get_entries_for_value': 105}
{'END..:mapcache_dimension_get_entries_for_value': 105}
{'BEGIN:mapcache_tileset_tile_get_without_subdimensions': 223}
{'BEGIN:mapcache_cache_tile_get': 213}
{'BEGIN:_mapcache_cache_sqlite_get': 200}
{'END..:_mapcache_cache_sqlite_get': 200}
{'END..:mapcache_cache_tile_get': 213}
{'END..:mapcache_tileset_tile_get_without_subdimensions': 223}
{'BEGIN:mapcache_tileset_tile_get_without_subdimensions': 225}
{'BEGIN:mapcache_cache_tile_get': 214}
{'BEGIN:_mapcache_cache_sqlite_get': 199}
{'END..:_mapcache_cache_sqlite_get': 199}
{'END..:mapcache_cache_tile_get': 214}
{'END..:mapcache_tileset_tile_get_without_subdimensions': 225}
{'BEGIN:mapcache_tileset_tile_get_without_subdimensions': 1381}
{'BEGIN:mapcache_cache_tile_get': 1370}
{'BEGIN:_mapcache_cache_sqlite_get': 1352}
{'END..:_mapcache_cache_sqlite_get': 1352}
{'END..:mapcache_cache_tile_get': 1370}
{'END..:mapcache_tileset_tile_get_without_subdimensions': 1381}
{'BEGIN:mapcache_tileset_tile_get_without_subdimensions': 205}
{'BEGIN:mapcache_cache_tile_get': 189}
{'BEGIN:_mapcache_cache_sqlite_get': 178}
{'END..:_mapcache_cache_sqlite_get': 178}
{'END..:mapcache_cache_tile_get': 189}
{'END..:mapcache_tileset_tile_get_without_subdimensions': 205}
{'END..:mapcache_tileset_tile_set_get_with_subdimensions': 2176}
{'END..:mapcache_tileset_tile_get_with_subdimensions': 2187}
{'END..:mapcache_tileset_tile_get': 2206}
{'BEGIN:mapcache_tileset_tile_get': 786}
{'BEGIN:mapcache_tileset_tile_get_with_subdimensions': 776}
{'BEGIN:mapcache_tileset_tile_set_get_with_subdimensions': 766}
{'BEGIN:mapcache_dimension_get_entries_for_value': 87}
{'END..:mapcache_dimension_get_entries_for_value': 87}
{'BEGIN:mapcache_tileset_tile_get_without_subdimensions': 209}
{'BEGIN:mapcache_cache_tile_get': 199}
{'BEGIN:_mapcache_cache_sqlite_get': 185}
{'END..:_mapcache_cache_sqlite_get': 185}
{'END..:mapcache_cache_tile_get': 199}
{'END..:mapcache_tileset_tile_get_without_subdimensions': 209}
{'BEGIN:mapcache_tileset_tile_get_without_subdimensions': 198}
{'BEGIN:mapcache_cache_tile_get': 184}
{'BEGIN:_mapcache_cache_sqlite_get': 172}
{'END..:_mapcache_cache_sqlite_get': 172}
{'END..:mapcache_cache_tile_get': 184}
{'END..:mapcache_tileset_tile_get_without_subdimensions': 198}
{'BEGIN:mapcache_tileset_tile_get_without_subdimensions': 173}
{'BEGIN:mapcache_cache_tile_get': 163}
{'BEGIN:_mapcache_cache_sqlite_get': 152}
{'END..:_mapcache_cache_sqlite_get': 152}
{'END..:mapcache_cache_tile_get': 163}
{'END..:mapcache_tileset_tile_get_without_subdimensions': 173}
{'BEGIN:mapcache_tileset_tile_get_without_subdimensions': 53}
{'BEGIN:mapcache_cache_tile_get': 43}
{'BEGIN:_mapcache_cache_sqlite_get': 33}
{'END..:_mapcache_cache_sqlite_get': 33}
{'END..:mapcache_cache_tile_get': 43}
{'END..:mapcache_tileset_tile_get_without_subdimensions': 53}
{'END..:mapcache_tileset_tile_set_get_with_subdimensions': 766}
{'END..:mapcache_tileset_tile_get_with_subdimensions': 776}
{'END..:mapcache_tileset_tile_get': 786}
{'BEGIN:mapcache_tileset_tile_get': 4553}
{'BEGIN:mapcache_tileset_tile_get_with_subdimensions': 4537}
{'BEGIN:mapcache_tileset_tile_set_get_with_subdimensions': 4521}
{'BEGIN:mapcache_dimension_get_entries_for_value': 81}
{'END..:mapcache_dimension_get_entries_for_value': 81}
{'BEGIN:mapcache_tileset_tile_get_without_subdimensions': 54}
{'BEGIN:mapcache_cache_tile_get': 45}
{'BEGIN:_mapcache_cache_sqlite_get': 31}
{'END..:_mapcache_cache_sqlite_get': 31}
{'END..:mapcache_cache_tile_get': 45}
{'END..:mapcache_tileset_tile_get_without_subdimensions': 54}
{'BEGIN:mapcache_tileset_tile_get_without_subdimensions': 54}
{'BEGIN:mapcache_cache_tile_get': 44}
{'BEGIN:_mapcache_cache_sqlite_get': 33}
{'END..:_mapcache_cache_sqlite_get': 33}
{'END..:mapcache_cache_tile_get': 44}
{'END..:mapcache_tileset_tile_get_without_subdimensions': 54}
{'BEGIN:mapcache_tileset_tile_get_without_subdimensions': 197}
{'BEGIN:mapcache_cache_tile_get': 179}
{'BEGIN:_mapcache_cache_sqlite_get': 168}
{'END..:_mapcache_cache_sqlite_get': 168}
{'END..:mapcache_cache_tile_get': 179}
{'END..:mapcache_tileset_tile_get_without_subdimensions': 197}
{'BEGIN:mapcache_tileset_tile_get_without_subdimensions': 200}
{'BEGIN:mapcache_cache_tile_get': 191}
{'BEGIN:_mapcache_cache_sqlite_get': 181}
{'END..:_mapcache_cache_sqlite_get': 181}
{'END..:mapcache_cache_tile_get': 191}
{'END..:mapcache_tileset_tile_get_without_subdimensions': 200}
{'END..:mapcache_tileset_tile_set_get_with_subdimensions': 4521}
{'END..:mapcache_tileset_tile_get_with_subdimensions': 4537}
{'END..:mapcache_tileset_tile_get': 4553}
{'END..:mapcache_prefetch_tiles': 20978}
{'END..:mapcache_handler': 115246}
Four tiles are fetched for the basemap, then four tiles for the catalog view. Each of these four tiles is composed of four products, needing four subtiles. Two observations can be made:
-
The north western tile, depicting North America, features no requested product. But the log shows that subtiles are fetched anyway from product caches (which respond with cache misses).
-
Dimension queries are executed for every tile although result is the same for all tiles in the map.
The <validate_query> element used in this example filters products by keyword only (here: &DIM_PRODUCT=peak):
<validate_query>
SELECT subtile FROM catalog
WHERE keyword LIKE "%"|| :dim ||"%"
</validate_query>The proposed optimization is to add a filter on geographical extent: products are selected if their bounding box has a non null intersection with the tile extent:
<validate_query>
SELECT subtile FROM catalog
WHERE keyword LIKE "%"|| :dim ||"%"
AND minx <= :maxx AND maxx >= :minx
AND miny <= :maxy AND maxy >= :miny
</validate_query>A configuration option exists to query second level dimension entries once for the whole map instead of for every tile composing the map (see MapCache Tileset Dimensions Documentation):
<dimension>
<wms_querybymap>true</wms_querybymap>Although this is not demonstated here, this feature has no significant advantage on this specific use case. Second level dimensions are implemented with SQLite as dimension backend, which is a relatively fast solution. When the backend involves network operations, such as ElasticSearch or ProsgreSQL, their slow response times may be balanced by this optimization.
As mentioned earlier, in order to compare various implementation choices with respect to MapCache performance, a mockup is created inside a Docker container or a Vagrant//VirtualBox virtual machine. Actual implementation is made available in jbo-ads/mapcache-mockup GitHub repository.
$ git clone https://github/jbo-ads/mapcache-mockup.git
$ cd mapcache-mockup
$ sudo systemctl start docker
$ sudo docker build --tag mapcache .
$ sudo docker run
$ sudo docker run -dit -p 8888:80 -v $(pwd):/share --name mapcache mapcache
$ sudo docker exec -it mapcache /share/bin/setup.sh
$ sudo docker container start mapcache
$ sudo docker exec -it mapcache /share/bin/setup.sh
$ vagrant up
Open link at http://localhost:8888/ol/ when using Docker or http://localhost:8080/ol/ when using Vagrant.
-
Vagrantfile,Dockerfile: Configuration files for Vagrant and Docker respectively. -
bin/install.sh: Script for first time installation of MapCache, OpenLayers and all dependencies on virtual machine. Used byVagrantfileandDockerfile. -
bin/setup.sh: Script for setting up Apache and MapCache at each virtual machine startup. -
bin/conf-*.sh: Scripts for setting up MapCache configurations. Used bybin/setup-mapcache.sh. -
bin/build-catalog.sh: Script for generating a simulated imagery catalog containing 401 products. -
bin/genprod.sh: Script for generating a single imagery product simulation. Used bybin/build-catalog.sh. -
bin/parselog.py: Script for extracting and presenting relevant information from Apache log. -
bin/perftest.sh: Script for running performance tests. -
data/world.tgz: A low resolution basemap to be used with OpenLayers only (i.e., without MapCache) -
data/intrumentation.patch: Patch to be applied to MapCache source code in order to insert instrumentation instructions.
The mockup embeds a script, perftest.sh, for executing various performance tests and collecting time measurements. It runs in the virtual machine, not from the host machine.
Following is the command line to run the test with short description before:
-
#: Prompt for root user on the virtual machine -
nmes=100: The test is executed 100 times and a mean time is returned -
/share/bin/perftest.sh: Full path of the test script -
WMTS_1: Test category: retrieve a single tile using WMTS -
0 0 0: Zoom level, tile column, tile row -
catalog: MapCache configuration: this is the product catalog without any optimization -
base: Layer: this is the basemap.
# nmes=100 /share/bin/perftest.sh WMTS_1 0 0 0 catalog base
TYPE ZOOM MINX MINY CONFIGURATION LAYER TOTAL SERVER-SIDE TOTAL CLIENT-SIDE
WMTS_1 0 0 0 catalog base 10.251ms / 100 = .102ms 1279ms / 100 = 12.790ms
Here one can observe that, in the specific testing environment, a tile is served by MapCache in about 100µs, which represents the execution duration of mapcache_handler() top level function of MapCache module.
The execution duration of the whole curl command is about 12ms. This includes time spent in curl, in Apache and in the IP stacks of host and virtual machine.
Result is similar with WMS:
-
WMS_256: retrieve a 256x256 pixels map with WMS -
0 0 0: Zoom level, tile column, tile row of upper-left tile composing the map
# nmes=100 /share/bin/perftest.sh WMS_256 0 0 0 catalog base
TYPE ZOOM MINX MINY CONFIGURATION LAYER TOTAL SERVER-SIDE TOTAL CLIENT-SIDE
WMS_256 0 0 0 catalog base 9.818ms / 100 = .098ms 1279ms / 100 = 12.790ms
-
WMTS_16: retrieve 4x4 tiles with WMTS -
2 0 0: Zoom level, tile column, tile row of upper-left tile
# nmes=100 /share/bin/perftest.sh WMTS_16 2 0 0 catalog base
TYPE ZOOM MINX MINY CONFIGURATION LAYER TOTAL SERVER-SIDE TOTAL CLIENT-SIDE
WMTS_16 2 0 0 catalog base 3878.394ms / 100 = 38.783ms 6243ms / 100 = 62.430ms
The test sends 16 GetTile requests using curl in background ( &). The time measurement is performed between the first entering in mapcache_handler() and its last ending. Tiles are retrieved in multiple Apache processes. A detailed analysis of Apache log shows that each tile is served in about 50µs. The overhead is caused by bash attempting to launch 16 curl requests in parallel.
-
WMS_1024: retrieve a 1024x1024 pixels map with WMS -
2 0 0: Zoom level, tile column, tile row of upper-left tile composing the map
# nmes=100 /share/bin/perftest.sh WMS_1024 2 0 0 catalog base
TYPE ZOOM MINX MINY CONFIGURATION LAYER TOTAL SERVER-SIDE TOTAL CLIENT-SIDE
WMS_1024 2 0 0 catalog base 3664.914ms / 100 = 36.649ms 4926ms / 100 = 49.260ms
In WMS, a single GetMap request is sent. A detailed analysis of Apache log also shows that each tile is retrieved in about 50µs. The overhead is caused by assembling tiles to make an image and by encoding that image into JPEG.
Optimization options described in the previous sections are compared in he specifc uses case of a catalog browser. A 1024x1024 map is retrieved at various zoom levels and with various combinations of optimization options.
The first comparison demonstrates the efficiency of geographical filter. Three configurations are compared:
-
No optimization using WMS: a map is composed of 16 tiles each of which needs fetching subtiles in 400 imagrery products, i.e. 6400 subtiles are fetched (some resulting in cache miss). The whole processing takes place sequentially in only one thread.
-
No optimization using WMTS: same as above but each of the 16 tiles is processed in its own process.
-
A geographical filter is applied using WMS: some tiles need to fetch 100 subtiles, some others are empty. Counting products overlapping over multiple tiles, less than 500 subtiles are to be fetched.
The table below gives mean durations for retrieving a map under these configurations:
| Zoom | Tile coord. | No optim. (WMS) | No optim. (WMTS) | Geo. filter |
|---|---|---|---|---|
| 2 | 0, 0 | 8 s | 5 s | 500 ms |
| 3 | 0, 1 | 10 s | 5 s | 400 ms |
| 4 | 2, 4 | 11 s | 5.5 s | 300 ms |
Subsequent comparisons will only take place with geographical filter enabled on WMS.
The previous sections presented two levels of multithreading:
-
tile level multithreading: the tiles composing a map are fetched in their own threads
-
subtile level multithreading: the subtiles composing a tile are fetched in their own threads.
The table below gives mean durations for retrieving a map under these configurations
| Zoom | Tile coord. | Geo. filter | Geo + multithread tiles | Geo + Multithread Subtiles |
|---|---|---|---|---|
| 2 | 0, 0 | 500 ms | 280 ms | 540 ms |
| 3 | 0, 1 | 400 ms | 185 ms | 460 ms |
| 4 | 2, 4 | 300 ms | 160 ms | 320 ms |
| 5 | 5, 10 | 350 ms | 160 ms | 400 ms |
| 6 | 14, 22 | 360 ms | 130 ms | 300 ms |
| 7 | 29, 44 | 270 ms | 100 ms | 210 ms |
| 8 | 60, 90 | 120 ms | 60 ms | 95 ms |
| 9 | 121, 181 | 90 ms | 50 ms | 80 ms |
| 10 | 245, 366 | 120 ms | 55 ms | 95 ms |
| 11 | 493, 734 | 95 ms | 60 ms | 90 ms |
| 12 | 986, 1471 | 75 ms | 65 ms | 75 ms |
| 13 | 1971, 2945 | 75 ms | 65 ms | 70 ms |
In this specific context, subtile level multithreading shows no performance gain.