Take a warm baseline, then re-request with one variable removed at a time: the storage reference system removes reprojection, a trivial style removes rendering, a hits-only query removes transfer. The differences between successive timings attribute the total. This works from outside the service, needs no JVM agent, and gives you the one number worth having — which stage to fix.
Server logs record that a GetMap took 1.8 seconds. They do not record whether it waited 1.5 seconds for a free renderer and rendered in 300 milliseconds, or started immediately and spent 1.7 seconds scanning a table without a spatial index. Those have entirely different fixes, and the log line looks identical.
Attaching a profiler to the JVM gives a precise answer and is frequently unavailable — production access is restricted, the overhead is unacceptable, or the service is MapServer and there is no JVM at all. Differential timing from outside needs nothing but the ability to make requests, and it is accurate enough to choose between the five stages, which is all the decision requires.
from __future__ import annotations
import statistics
import time
from dataclasses import dataclass, field
import requests
@dataclass
class Timing:
label: str
samples: list[float] = field(default_factory=list)
def add(self, seconds: float) -> None:
self.samples.append(seconds)
@property
def p50(self) -> float:
return statistics.median(self.samples) if self.samples else float("nan")
@property
def ms(self) -> float:
return self.p50 * 1000
@dataclass
class Profile:
baseline: Timing
stages: dict[str, float] # stage -> milliseconds attributed
def report(self) -> str:
lines = [f"baseline p50 {self.baseline.ms:.0f} ms"]
accounted = 0.0
for stage, ms in sorted(self.stages.items(), key=lambda kv: -kv[1]):
share = 100 * ms / self.baseline.ms if self.baseline.ms else 0
accounted += ms
lines.append(f" {stage:<14} {ms:7.0f} ms {share:5.1f}%")
remainder = self.baseline.ms - accounted
lines.append(f" {'unattributed':<14} {remainder:7.0f} ms "
f"{100 * remainder / self.baseline.ms:5.1f}%")
return "\n".join(lines)
def _time(session: requests.Session, url: str, params: dict[str, str],
repeats: int, label: str) -> Timing:
timing = Timing(label)
for _ in range(repeats):
started = time.perf_counter()
resp = session.get(url, params=params, timeout=180)
resp.raise_for_status()
resp.content
timing.add(time.perf_counter() - started)
return timing
def profile_getmap(base: str, layer: str, bbox: str, storage_crs: str,
request_crs: str = "EPSG:3857", trivial_style: str = "polygon",
width: int = 512, repeats: int = 15) -> Profile:
"""Attribute a GetMap by subtracting one variable at a time.
Each variant differs from the baseline in exactly one respect, so the
difference in median duration is that variable's contribution. Medians,
not means: one garbage collection pause should not move the answer.
"""
session = requests.Session()
url = f"{base.rstrip('/')}/wms"
common = {"SERVICE": "WMS", "VERSION": "1.3.0", "REQUEST": "GetMap",
"LAYERS": layer, "BBOX": bbox, "WIDTH": str(width),
"HEIGHT": str(width), "FORMAT": "image/png", "STYLES": ""}
baseline = _time(session, url, common | {"CRS": request_crs},
repeats, "baseline")
# Same everything, but no reprojection: ask for the storage CRS. The
# bbox must be in that CRS too, so this needs a transformed box.
native = _time(session, url,
common | {"CRS": storage_crs, "BBOX": _reproject_bbox(
bbox, request_crs, storage_crs)},
repeats, "native crs")
# Same everything, but a style with one rule and no labels.
simple = _time(session, url,
common | {"CRS": request_crs, "STYLES": trivial_style},
repeats, "trivial style")
# Encoding: JPEG skips PNG's compression pass entirely.
jpeg = _time(session, url,
common | {"CRS": request_crs, "FORMAT": "image/jpeg"},
repeats, "jpeg")
stages = {
"reprojection": max(0.0, baseline.ms - native.ms),
"rendering": max(0.0, baseline.ms - simple.ms),
"encoding": max(0.0, baseline.ms - jpeg.ms),
}
return Profile(baseline, stages)
def _reproject_bbox(bbox: str, source: str, target: str) -> str:
from pyproj import Transformer
west, south, east, north = (float(v) for v in bbox.split(","))
transformer = Transformer.from_crs(source, target, always_xy=True)
x0, y0 = transformer.transform(west, south)
x1, y1 = transformer.transform(east, north)
return f"{min(x0, x1)},{min(y0, y1)},{max(x0, x1)},{max(y0, y1)}"
def queue_wait(base: str, layer: str, bbox: str, concurrency: int = 8,
repeats: int = 40) -> float:
"""Milliseconds of the median request spent waiting for a free worker.
The difference between serial and concurrent median latency is queue
wait, because nothing else about the request changed.
"""
from concurrent.futures import ThreadPoolExecutor
session = requests.Session()
session.mount("http://", requests.adapters.HTTPAdapter(
pool_connections=concurrency, pool_maxsize=concurrency))
url = f"{base.rstrip('/')}/wms"
params = {"SERVICE": "WMS", "VERSION": "1.3.0", "REQUEST": "GetMap",
"LAYERS": layer, "STYLES": "", "CRS": "EPSG:3857", "BBOX": bbox,
"WIDTH": "512", "HEIGHT": "512", "FORMAT": "image/png"}
serial = _time(session, url, params, repeats // 4, "serial")
parallel = Timing("parallel")
def one(_):
started = time.perf_counter()
session.get(url, params=params, timeout=180).content
parallel.add(time.perf_counter() - started)
with ThreadPoolExecutor(max_workers=concurrency) as pool:
list(pool.map(one, range(repeats)))
return max(0.0, parallel.ms - serial.ms)
One variable per variant. The whole method rests on each request differing from the baseline in exactly one respect. Requesting the storage reference system also requires transforming the bounding box, which is why _reproject_bbox exists — asking for the native system with a Web Mercator box would change the extent as well and make the difference meaningless.
Medians, not means. A single garbage collection pause during a fifteen-sample run moves a mean substantially and a median not at all. Since the whole method is built on comparing durations, that robustness is what makes small differences trustworthy.
Subtractions can overlap. Rendering and reprojection are not perfectly independent — a trivial style also draws fewer vertices, so it slightly reduces the reprojection work too. The attribution is therefore approximate, and the unattributed line in the report is where that slack shows. For choosing which stage to work on, approximate is entirely sufficient.
Queue wait is measured differently. It is not a property of one request but of the system under load, so it comes from the difference between serial and concurrent median latency. A large queue wait means the thread pool is too small or something downstream is serialising.
Run it against a slow layer and read the attribution:
profile = profile_getmap(base, "cadastre:parcels",
"949000,6002000,952000,6005000",
storage_crs="EPSG:2056")
print(profile.report())
print(f"queue wait at 8x: {queue_wait(base, 'cadastre:parcels', bbox):.0f} ms")
baseline p50 1842 ms
rendering 1290 ms 70.0%
reprojection 284 ms 15.4%
encoding 61 ms 3.3%
unattributed 207 ms 11.2%
queue wait at 8x: 34 ms
Rendering at seventy per cent with negligible queue wait is an unambiguous answer: the thread pool is fine and the style or the geometry is the problem. Confirm it against the database before changing anything:
EXPLAIN (ANALYZE, BUFFERS)
SELECT geom FROM cadastre.parcels
WHERE geom && ST_MakeEnvelope(2683000, 1247000, 2686000, 1250000, 2056);
A cold cache dwarfs everything. The first request against a layer pays for connection establishment, a query plan, and possibly the operating system reading pages from disk. Discarding the first few samples, or timing only after a warm-up loop, is essential — otherwise the profile measures start-up rather than steady state.
The trivial style must genuinely be trivial. A “simple” style that still labels every feature removes almost none of the rendering cost, because label placement is iterative and conflict-resolved and is frequently the dominant term. Use a single-rule polygon or line style with no TextSymbolizer at all — the SLD debugging guide covers reading a style to know what it does.
JPEG changes more than encoding. It also drops the alpha channel, so the comparison is slightly generous to the encoding stage. It is still the cleanest available lever, and encoding is rarely the answer anyway — if it comes out large, the request is probably enormous and the size cap is the real fix.
Profile against production-shaped data. A staging database with a thousand parcels renders instantly regardless of how bad the style is. The attribution is only meaningful against a dataset of realistic size and geometry complexity, which is one of the reasons environment parity matters for performance work and not only for correctness.
Do, when you can — it gives a precise call-level answer. Differential timing exists for the common case where you cannot: restricted production access, unacceptable overhead, or a MapServer stack with no JVM. It is accurate enough to pick between five stages, which is the decision you are actually making.
Fifteen after a warm-up is usually enough to separate stages that differ by tens of per cent, which is the resolution the decision needs. If two stages come out within a few per cent of each other, the honest conclusion is that neither dominates rather than that more samples would settle it.
Usually that the stages overlap more than the subtraction assumes, or that something not covered by the variants is significant — authentication, a proxy hop, or the data fetch itself, which this method does not isolate directly. A remainder above about a quarter is worth investigating with an EXPLAIN on the underlying query.
The method transfers directly with different variables. For WFS, propertyName isolates attribute serialisation and resultType=hits isolates transfer entirely. For WCS, scalefactor isolates resampling and rangesubset isolates band handling. The principle is unchanged: one variable per variant, medians, and a warm cache.
Back to Performance Tuning for OGC Service Backends
Related