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)
[[TOC]]
(TL;DR for hurried or impatient people)
Single-threaded, multi-threaded
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):<mapcache> <threaded_fetching>true</threaded_fetching>
-
At
<dimensions>level for fetching subtiles to assemble into a tile:<dimensions> <assembly_threaded_fetching>true</assembly_threaded_fetching>
Narrowing subtile selection for second level dimension
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 extends:
-
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>
Requesting second level dimension entries at tile or at map level
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:
<dimension>
<wms_querybymap>true</wms_querybymap>Checking indexes of SQLite caches
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);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 (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 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: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 #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}
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:
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}
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-amt?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:
<dimension>
<wms_querybymap>true</querybymap>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