-
-
Notifications
You must be signed in to change notification settings - Fork 100
MapCache Performance Analysis A Case Study
[[TOC]]
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 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.
As an illustration, the following picture shows a catalog displaying XXX imagery products over a low resolution basemap.

Of course the catalog browser should be as fast as possible. But the above image takes about 20 seconds to be rendered on the mockup browser with default MapCache configuration. Worse, a WMS request of the same map needs YY 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 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 and 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/
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:8888/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 #4323:139712970864384:0:
{'BEGIN:mapcache_handler': 124496}
{'BEGIN:mapcache_prefetch_tiles': 90201}
{'BEGIN:mapcache_tileset_tile_get': 88432}
{'BEGIN:mapcache_tileset_tile_get_without_subdimensions': 88409}
{'BEGIN:mapcache_cache_tile_get': 88383}
{'BEGIN:_mapcache_cache_sqlite_get': 88324}
{'END..:_mapcache_cache_sqlite_get': 88324}
{'END..:mapcache_cache_tile_get': 88383}
{'END..:mapcache_tileset_tile_get_without_subdimensions': 88409}
{'END..:mapcache_tileset_tile_get': 88432}
{'BEGIN:mapcache_tileset_tile_get': 1047}
{'BEGIN:mapcache_tileset_tile_get_without_subdimensions': 1013}
{'BEGIN:mapcache_cache_tile_get': 976}
{'BEGIN:_mapcache_cache_sqlite_get': 906}
{'END..:_mapcache_cache_sqlite_get': 906}
{'END..:mapcache_cache_tile_get': 976}
{'END..:mapcache_tileset_tile_get_without_subdimensions': 1013}
{'END..:mapcache_tileset_tile_get': 1047}
{'BEGIN:mapcache_tileset_tile_get': 281}
{'BEGIN:mapcache_tileset_tile_get_without_subdimensions': 247}
{'BEGIN:mapcache_cache_tile_get': 197}
{'BEGIN:_mapcache_cache_sqlite_get': 161}
{'END..:_mapcache_cache_sqlite_get': 161}
{'END..:mapcache_cache_tile_get': 197}
{'END..:mapcache_tileset_tile_get_without_subdimensions': 247}
{'END..:mapcache_tileset_tile_get': 281}
{'BEGIN:mapcache_tileset_tile_get': 370}
{'BEGIN:mapcache_tileset_tile_get_without_subdimensions': 338}
{'BEGIN:mapcache_cache_tile_get': 306}
{'BEGIN:_mapcache_cache_sqlite_get': 268}
{'END..:_mapcache_cache_sqlite_get': 268}
{'END..:mapcache_cache_tile_get': 306}
{'END..:mapcache_tileset_tile_get_without_subdimensions': 338}
{'END..:mapcache_tileset_tile_get': 370}
{'END..:mapcache_prefetch_tiles': 90201}
{'END..:mapcache_handler': 124496}
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:
In this example the request is a single tile featuring four selected products from the catalog: Everest, Aconcagua, Elbrus and Kilimanjaro.
Following are the results of an analysis carried out in this context to observe MapCache behaviour with respect to performance. The environment used to perform time measurements and the various configuration details are then described.
(tl;dr for impatient or hurried people)
-
Disk caches are faster than SQLite caches (see: Comparing caches).
-
By default, when requesting a map (WMS), tiles are fetched sequentially. To change this behaviour, the dedicated configuration option is
<threaded_fetching>true</threaded_fetching>.
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 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
$ vagrant up
Open link at http://localhost:8888/ol/ when using Docker or http://localhost:8080/ol/ when using Vagrant.
Client-side observations include all possible delays from local system load to network speed and actual Apache/MapCache execution. This gives information on actual user feeling about MapCache performance.
On client-side, one can measure how long a tile or a map is served. This 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?SERVICE=WMTS&REQUEST=GetTile&LAYER=world&TILEMATRIXSET=GoogleMapsCompatible&TILEMATRIX=0&TILEROW=0&TILECOL=0" > tile
real 0m0.078s
user 0m0.035s
sys 0m0.013s
Server-side observations focus on actual MapCache performance and allows for identifying possible bottlenecks.
On server-side, the main observation point is the Apache error log, which is time-tagged to the microsecond. The log level is configured in Apache configuration file with the LogLevel keyword, e.g.:
LogLevel warn mapcache:debug
Apache error log can be retrieved with following commands, depending on the used container.
$ sudo docker exec -it mapcache cp /var/log/apache2/error.log /share
$ vagrant ssh -c "sudo cp /var/log/apache2/error.log /share"
Here is an example of a log entry in Apache error log:
[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/
In order to observe detailed behaviour of MapCache, one needs to insert debug traces in MapCache code put 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);
@@ -349,2 +350,3 @@ static int mapcache_handler(request_rec *r, mapcache_alias_entry *alias_entry) {
if(GC_HAS_ERROR(ctx) || !request) {
+ ap_log_rerror(APLOG_MARK, APLOG_DEBUG, 0, r, "MOCKUP END mapcache_handler ERROR");
return write_http_response(apache_ctx,
@@ -390,2 +392,3 @@ static int mapcache_handler(request_rec *r, mapcache_alias_entry *alias_entry) {
if(GC_HAS_ERROR(ctx)) {
+ ap_log_rerror(APLOG_MARK, APLOG_DEBUG, 0, r, "MOCKUP END mapcache_handler ERROR");
return write_http_response(apache_ctx, mapcache_core_respond_to_error(ctx));
@@ -436,2 +439,3 @@ static int mapcache_handler(request_rec *r, mapcache_alias_entry *alias_entry) {
if(GC_HAS_ERROR(ctx)) {
+ ap_log_rerror(APLOG_MARK, APLOG_DEBUG, 0, r, "MOCKUP END mapcache_handler ERROR");
return write_http_response(apache_ctx,
@@ -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);
With that instrumentation, a WMS request on the World at zoom level 2 gives the following (abridged) traces:
[Mon Jan 06 15:09:24.192378 2020] [...] MOCKUP BEGIN mapcache_handler
[Mon Jan 06 15:09:24.249737 2020] [...] MOCKUP END mapcache_handler
The map has been served in 57539 µs.
For this performance analysis, a satellite image catalog is simulated by creating pseudo-imagery from existing tiled data sources, e.g.:
-
OSM Tiles (Map data © by OpenStreetMap contributors, available under ODbL)
-
OSM WMS (Map data © by OpenStreetMap contributors, available under ODbL)
A simulated product is generated by following these two steps:
-
Create a detailed GeoTiff image from the source. It covers a square area of 10x10 tiles at zoom level 12, i.e. about 100km x 100km (with EPSG:3857 projection). This simulates a preprocessed picture taken from a satellite.
-
Build a tile pyramid from that image, stored in a SQLite file that can be used as a MapCache cache.
The catalog itself is implemented using a SQLite database. All product names and bounding boxes are stored in a table. This SQLite database is used as second dimension backend by MapCache.
The mockup integrates two tools in /share/bin folder of Docker container or Vagrant virtual machine:
-
genprod.shgenerates a single simulated product based on the image center coordinates and its orientation: horizontal, vertical or square. It is also able to generate multiple random products inside a given bounding box. -
build-catalog.shgenerates all products of the catalog used in this analysis.
The catalog of simulated products is composed of several product groups:
- UN cities: This group is composed of images representing cities where United Nations agencies are located, i.e., Bern, Geneva, London, Madrid, Montreal, Nairobi, New York, Paris, The Hague, Rome, Vienna and Washington DC. This group is used to show how MapCache operates to serve a map, specifically with second level dimensions.
To illustrate how MapCache operates, let's request a single tile at level 0 on the "Low resolution World" layer, which uses a disk cache, and on the "Wikimedia" layer, which uses a SQLite cache. From command line on host with mockup running in Docker container, the instruction is:
$ curl -s "http://localhost:8888/catalog/wmts/1.0.0/base/default/GoogleMapsCompatible/0/0/0" > base-0-0-0.jpg
or
$ curl -s "http://localhost:8888/osm/wmts/1.0.0/wikimedia/default/GoogleMapsCompatible/0/0/0" > wikimedia-0-0-0.png
With appropriate instrumentation in MapCache code, resulting Apache log shows the execution path from initial request to tile retrieval in both cases:
[... 16:47:37.032595 ... pid 21682:tid 140040353081088 ...] mapcache quick handler hook on uri /catalog/wmts
[... 16:47:37.032824 ... pid 21682:tid 140040353081088 ...] MOCKUP BEGIN mapcache_handler
[... 16:47:37.032854 ... pid 21682:tid 140040353081088 ...] MOCKUP BEGIN mapcache_core_get_tile
[... 16:47:37.032861 ... pid 21682:tid 140040353081088 ...] MOCKUP BEGIN mapcache_prefetch_tiles
[... 16:47:37.032870 ... pid 21682:tid 140040353081088 ...] MOCKUP BEGIN mapcache_tileset_tile_get
[... 16:47:37.032876 ... pid 21682:tid 140040353081088 ...] MOCKUP BEGIN mapcache_tileset_tile_get_without_subdimensions
[... 16:47:37.032886 ... pid 21682:tid 140040353081088 ...] MOCKUP BEGIN mapcache_cache_tile_get
[... 16:47:37.032896 ... pid 21682:tid 140040353081088 ...] MOCKUP BEGIN _mapcache_cache_disk_get
[... 16:47:37.032908 ... pid 21682:tid 140040353081088 ...] checking for tile /share/caches/world/0/0/0.jpg
[... 16:47:37.032936 ... pid 21682:tid 140040353081088 ...] MOCKUP END _mapcache_cache_disk_get
[... 16:47:37.032941 ... pid 21682:tid 140040353081088 ...] MOCKUP END mapcache_cache_tile_get
[... 16:47:37.032947 ... pid 21682:tid 140040353081088 ...] MOCKUP END mapcache_tileset_tile_get_without_subdimensions
[... 16:47:37.032952 ... pid 21682:tid 140040353081088 ...] MOCKUP END mapcache_tileset_tile_get
[... 16:47:37.032958 ... pid 21682:tid 140040353081088 ...] MOCKUP END mapcache_prefetch_tiles
[... 16:47:37.032976 ... pid 21682:tid 140040353081088 ...] MOCKUP END mapcache_core_get_tile
[... 16:47:37.032981 ... pid 21682:tid 140040353081088 ...] MOCKUP END mapcache_handler
[... 10:06:15.149617 ... pid 476:tid 139635938281216 ...] mapcache quick handler hook on uri /osm/wmts
[... 10:06:15.149828 ... pid 476:tid 139635938281216 ...] MOCKUP BEGIN mapcache_handler
[... 10:06:15.149860 ... pid 476:tid 139635938281216 ...] MOCKUP BEGIN mapcache_core_get_tile
[... 10:06:15.149866 ... pid 476:tid 139635938281216 ...] MOCKUP BEGIN mapcache_prefetch_tiles
[... 10:06:15.149880 ... pid 476:tid 139635938281216 ...] MOCKUP BEGIN mapcache_tileset_tile_get
[... 10:06:15.149887 ... pid 476:tid 139635938281216 ...] MOCKUP BEGIN mapcache_tileset_tile_get_without_subdimensions
[... 10:06:15.149896 ... pid 476:tid 139635938281216 ...] MOCKUP BEGIN mapcache_cache_tile_get
[... 10:06:15.149907 ... pid 476:tid 139635938281216 ...] MOCKUP BEGIN _mapcache_cache_sqlite_get
[... 10:06:15.150757 ... pid 476:tid 139635938281216 ...] MOCKUP END _mapcache_cache_sqlite_get
[... 10:06:15.150771 ... pid 476:tid 139635938281216 ...] MOCKUP END mapcache_cache_tile_get
[... 10:06:15.150776 ... pid 476:tid 139635938281216 ...] MOCKUP END mapcache_tileset_tile_get_without_subdimensions
[... 10:06:15.150781 ... pid 476:tid 139635938281216 ...] MOCKUP END mapcache_tileset_tile_get
[... 10:06:15.150786 ... pid 476:tid 139635938281216 ...] MOCKUP END mapcache_prefetch_tiles
[... 10:06:15.150802 ... pid 476:tid 139635938281216 ...] MOCKUP END mapcache_core_get_tile
[... 10:06:15.150807 ... pid 476:tid 139635938281216 ...] MOCKUP END mapcache_handler
Here, the WMS protocol is used to get a worldwide map at zoom level 1.
$ curl -s "http://localhost:8888/osm?SERVICE=WMS&REQUEST=GetMap&BBOX=-20037508.342789,-20037508.342789,20037508.342789,20037508.342789&WIDTH=512&HEIGHT=512&SRS=EPSG:3857&LAYERS=wikimedia" > wikimedia-1.jpg
[... 13:29:36.199004 ... pid 475:tid 139636500330240 ...] mapcache quick handler hook on uri /osm
[... 13:29:36.199088 ... pid 475:tid 139636500330240 ...] MOCKUP BEGIN mapcache_handler
[... 13:29:36.199112 ... pid 475:tid 139636500330240 ...] MOCKUP BEGIN mapcache_prefetch_tiles
[... 13:29:36.199119 ... pid 475:tid 139636500330240 ...] MOCKUP BEGIN mapcache_tileset_tile_get
[... 13:29:36.199126 ... pid 475:tid 139636500330240 ...] MOCKUP BEGIN mapcache_tileset_tile_get_without_subdimensions
[... 13:29:36.199133 ... pid 475:tid 139636500330240 ...] MOCKUP BEGIN mapcache_cache_tile_get
[... 13:29:36.199147 ... pid 475:tid 139636500330240 ...] MOCKUP BEGIN _mapcache_cache_sqlite_get
[... 13:29:36.199227 ... pid 475:tid 139636500330240 ...] MOCKUP END _mapcache_cache_sqlite_get
[... 13:29:36.199235 ... pid 475:tid 139636500330240 ...] MOCKUP END mapcache_cache_tile_get
[... 13:29:36.199242 ... pid 475:tid 139636500330240 ...] MOCKUP END mapcache_tileset_tile_get_without_subdimensions
[... 13:29:36.199256 ... pid 475:tid 139636500330240 ...] MOCKUP END mapcache_tileset_tile_get
[... 13:29:36.199267 ... pid 475:tid 139636500330240 ...] MOCKUP BEGIN mapcache_tileset_tile_get
[... 13:29:36.199297 ... pid 475:tid 139636500330240 ...] MOCKUP BEGIN mapcache_tileset_tile_get_without_subdimensions
[... 13:29:36.199305 ... pid 475:tid 139636500330240 ...] MOCKUP BEGIN mapcache_cache_tile_get
[... 13:29:36.199315 ... pid 475:tid 139636500330240 ...] MOCKUP BEGIN _mapcache_cache_sqlite_get
[... 13:29:36.199401 ... pid 475:tid 139636500330240 ...] MOCKUP END _mapcache_cache_sqlite_get
[... 13:29:36.199410 ... pid 475:tid 139636500330240 ...] MOCKUP END mapcache_cache_tile_get
[... 13:29:36.199417 ... pid 475:tid 139636500330240 ...] MOCKUP END mapcache_tileset_tile_get_without_subdimensions
[... 13:29:36.199428 ... pid 475:tid 139636500330240 ...] MOCKUP END mapcache_tileset_tile_get
[... 13:29:36.199440 ... pid 475:tid 139636500330240 ...] MOCKUP BEGIN mapcache_tileset_tile_get
[... 13:29:36.199448 ... pid 475:tid 139636500330240 ...] MOCKUP BEGIN mapcache_tileset_tile_get_without_subdimensions
[... 13:29:36.199458 ... pid 475:tid 139636500330240 ...] MOCKUP BEGIN mapcache_cache_tile_get
[... 13:29:36.199467 ... pid 475:tid 139636500330240 ...] MOCKUP BEGIN _mapcache_cache_sqlite_get
[... 13:29:36.199523 ... pid 475:tid 139636500330240 ...] MOCKUP END _mapcache_cache_sqlite_get
[... 13:29:36.199532 ... pid 475:tid 139636500330240 ...] MOCKUP END mapcache_cache_tile_get
[... 13:29:36.199544 ... pid 475:tid 139636500330240 ...] MOCKUP END mapcache_tileset_tile_get_without_subdimensions
[... 13:29:36.199557 ... pid 475:tid 139636500330240 ...] MOCKUP END mapcache_tileset_tile_get
[... 13:29:36.199566 ... pid 475:tid 139636500330240 ...] MOCKUP BEGIN mapcache_tileset_tile_get
[... 13:29:36.199574 ... pid 475:tid 139636500330240 ...] MOCKUP BEGIN mapcache_tileset_tile_get_without_subdimensions
[... 13:29:36.199582 ... pid 475:tid 139636500330240 ...] MOCKUP BEGIN mapcache_cache_tile_get
[... 13:29:36.199595 ... pid 475:tid 139636500330240 ...] MOCKUP BEGIN _mapcache_cache_sqlite_get
[... 13:29:36.199661 ... pid 475:tid 139636500330240 ...] MOCKUP END _mapcache_cache_sqlite_get
[... 13:29:36.199670 ... pid 475:tid 139636500330240 ...] MOCKUP END mapcache_cache_tile_get
[... 13:29:36.199684 ... pid 475:tid 139636500330240 ...] MOCKUP END mapcache_tileset_tile_get_without_subdimensions
[... 13:29:36.199695 ... pid 475:tid 139636500330240 ...] MOCKUP END mapcache_tileset_tile_get
[... 13:29:36.199710 ... pid 475:tid 139636500330240 ...] MOCKUP END mapcache_prefetch_tiles
[... 13:29:36.212821 ... pid 475:tid 139636500330240 ...] MOCKUP END mapcache_handler