HBase Slow Query Analysis, in depth: slow logs, the ring buffer, hbase:slowlog, scan metrics and classifying slow calls

What counts as slow: the RPC, not the query

HBase judges slowness per RPC, not per query. A Get is usually one RPC to one RegionServer. A batch of Puts is split into one Multi RPC per server. A Scan is many RPCs: each call to the server returns up to caching rows or a size limit's worth of data, and the client keeps calling until it reaches the stop row, crossing region boundaries as it goes.

So a 40-minute scan may never appear in a slow log, because each of its thousands of RPCs finished in under a second. Server-side records tell you which calls hurt the server and its other clients; client-side metrics tell you what a whole query cost.

Every RPC has two server-side durations. Queue time is how long the call waited for a free handler thread. Processing time is how long a handler spent on it. Long queue time means the server was busy with other work; long processing time means this call was expensive. Only processing time is compared with the threshold, so a call that waited long but ran fast is never recorded. Its pain shows in client latency and in the queue times of the expensive calls that were logged.

The four evidence sources

The log is always on, subject to its thresholds; the other server-side sources are off by default. Truncation is why the ring buffer was added in HBASE-22978: a slow scan's region, key range and filter tree are exactly what gets cut off.

Switching it on and choosing thresholds

Four settings control what counts as slow or large. hbase.ipc.warn.response.time defaults to 10,000 ms and hbase.ipc.warn.response.size to 100 MB. The .scan variants apply to scans and default to the same values. Any of them can be set to -1 to turn that check off.

Ten seconds hides almost everything that matters to a service with a 50 ms p99 target. Lower the general threshold to around one second so slow Gets and Multis are captured, keep scans higher so ordinary analytic scans do not flood the buffer, then enable the ring buffer and, for history, the system table. hbase.regionserver.slowlog.systable.enabled only works with the buffer enabled too.

<!-- hbase-site.xml on every RegionServer; restart required -->
<property><name>hbase.regionserver.slowlog.buffer.enabled</name><value>true</value></property>
<property><name>hbase.regionserver.slowlog.ringbuffer.size</name><value>256</value></property>
<property><name>hbase.regionserver.slowlog.systable.enabled</name><value>true</value></property>

<!-- thresholds: defaults are 10000 ms and 100 MB; scans get their own pair -->
<property><name>hbase.ipc.warn.response.time</name><value>1000</value></property>
<property><name>hbase.ipc.warn.response.time.scan</name><value>5000</value></property>
<property><name>hbase.ipc.warn.response.size</name><value>52428800</value></property>

Persistence is asynchronous. Each RegionServer queues up to 1,000 records (hbase.regionserver.slowlog.systable.queue.size) and a chore writes them to hbase:slowlog every 10 minutes by default (hbase.slowlog.systable.chore.duration). Records from the minutes before a crash, often the ones you most want, may never arrive.

Reading a record

Here is a log record for a slow scan, reformatted from the reference guide's example. The tag in brackets tells you why it was logged. operationTooSlow and operationTooLarge are used for client operations such as Get, Put and Delete, which get a detailed fingerprint of the request. responseTooSlow and responseTooLarge carry only the RPC-level fields. When both thresholds are breached, the tag depends on the version.

WARN [,queue=15,port=60020] ipc.RpcServer - (responseTooSlow):
{"call":"Scan(org.apache.hadoop.hbase.protobuf.generated.ClientProtos$ScanRequest)",
 "starttimems":1567203007549,
 "responsesize":6819737,
 "method":"Scan",
 "param":"region { type: REGION_NAME value: \"t1,\\000\\000\\215...<TRUNCATED>",
 "processingtimems":28646,
 "client":"10.253.196.215:41116",
 "queuetimems":22453,
 "class":"HRegionServer"}

• method and call: the RPC type (Scan, Get, Multi, Mutate). This is the first thing to group by.
• processingtimems and queuetimems: handler time and wait time. Here the call waited 22 seconds for a handler and then took 28 seconds to run, so this server was saturated and this scan was expensive.
• responsesize: bytes returned. Long processing time with a small response suggests the server read and threw away many rows. A large response suggests the client asked for too much.
• param: the request itself, with the region name, row range, filters, caching, max_result_size and whether blocks are cached. In the ring buffer and system table this field is complete.
• client: the caller's IP and port; group by IP, since the port changes per connection.

Records from the ring buffer and hbase:slowlog add region_name and username as separate fields, which is what makes filtering by table or user possible without parsing param.

Querying the buffer and the table

The shell reads the ring buffers of every RegionServer, or of the servers you name, and merges the results. The filter keys are REGION_NAME, TABLE_NAME, CLIENT_IP, USER and LIMIT; multiple filters are OR-ed unless you pass 'FILTER_BY_OP' => 'AND'. The get_*log_responses commands read only the in-memory buffers. For anything older, scan hbase:slowlog directly. Its row keys are ordered roughly by time, and its columns match the shell output.

# recent slow calls from every RegionServer's ring buffer
get_slowlog_responses '*', {'LIMIT' => 50}

# only one table, AND-ed with one client (the default operator is OR)
get_slowlog_responses '*', {'TABLE_NAME' => 'orders', 'CLIENT_IP' => '10.4.7.21:52781', 'FILTER_BY_OP' => 'AND'}

# calls that were logged because the response was too big
get_largelog_responses '*', {'TABLE_NAME' => 'orders'}

# history: rows are ordered roughly by time, so REVERSED returns the newest first
scan 'hbase:slowlog', {REVERSED => true, COLUMNS => ['info:method_name', 'info:processing_time', 'info:queue_time', 'info:region_name', 'info:username'], LIMIT => 100}

clear_slowlog_responses empties the buffers before a controlled reproduction.

The client's view: scan metrics

To know what a whole scan cost, enable scan metrics on the Scan and read them when you finish. The most useful ratio is rows scanned to rows returned. If the server examined 40 million rows to return 3,000, no server tuning will help; only a different key range, row key or data layout will.

Scan scan = new Scan()
    .withStartRow(Bytes.toBytes("cust#0042#"))
    .withStopRow(Bytes.toBytes("cust#0042$"))
    .setCaching(500);
scan.setScanMetricsEnabled(true);                 // off by default; costs little

long returned = 0;
try (ResultScanner rs = table.getScanner(scan)) {
  for (Result r : rs) { returned++; handle(r); }
  Map<String, Long> m = rs.getScanMetrics().getMetricsMap();
  log.info("rows returned={} scanned={} filtered={} regions={} rpcs={} bytes={} msBetweenNexts={}",
      returned, m.get("ROWS_SCANNED"), m.get("ROWS_FILTERED"), m.get("REGIONS_SCANNED"),
      m.get("RPC_CALLS"), m.get("BYTES_IN_RESULTS"), m.get("MILLIS_BETWEEN_NEXTS"));
}

ROWS_SCANNED and ROWS_FILTERED are counted on the server and returned with each RPC. REGIONS_SCANNED and RPC_CALLS show how far the scan travelled, and MILLIS_BETWEEN_NEXTS shows time spent inside the RegionServer calls. Newer releases add more counters, so check your client version's ScanMetrics class before depending on others.

Classifying a slow call by its shape

Most slow calls fall into a few shapes. Classify the call first, then pick the fix. The filters and scan settings named here are covered in HBase scans and HBase filters.

A small fingerprinting pipeline

One slow call is an anecdote; a thousand grouped by table, method and client are a diagnosis. The script below extracts the tagged JSON from RegionServer logs, derives the table from the region name, and ranks groups by total processing time, which surfaces the constant moderate query that costs more than one dramatic outlier.

import json, re, sys
from collections import defaultdict

TAG = re.compile(r"\((response|operation)Too(Slow|Large)\):\s*(\{.*\})")
groups = defaultdict(lambda: {"n": 0, "proc": [], "queue": [], "bytes": 0})

for line in sys.stdin:                         # RegionServer log lines
    m = TAG.search(line)
    if not m:
        continue
    rec = json.loads(m.group(3))
    region = re.search(r'value: \\?"([^,\\"]+),', rec.get("param", ""))
    table = region.group(1) if region else "?"
    client = rec.get("client", "?").split(":")[0]  # drop the ephemeral port
    key = (table, rec.get("method", "?"), client)
    g = groups[key]
    g["n"] += 1
    g["proc"].append(rec.get("processingtimems", 0))
    g["queue"].append(rec.get("queuetimems", 0))
    g["bytes"] += rec.get("responsesize", 0)

def p95(xs):
    xs = sorted(xs); return xs[int(0.95 * (len(xs) - 1))] if xs else 0

for key, g in sorted(groups.items(), key=lambda kv: -sum(kv[1]["proc"])):
    print(key, "calls", g["n"], "proc_p95_ms", p95(g["proc"]),
          "queue_p95_ms", p95(g["queue"]), "MB", g["bytes"] // 2**20)

The same grouping works on hbase:slowlog exports. A new group at the top is usually a new deployment or job; the client IP tells you whose.

Worked example: the 02:00 latency spike

An orders table serves a checkout API with a 40 ms p99 target. Every night from 02:00 to 02:40 the p99 exceeds 900 ms on all 12 RegionServers, with no GC pauses or compaction storm.

Step 1: capture. At the 10-second default the log is silent. The team sets hbase.ipc.warn.response.time to 500 ms and the scan threshold to 5,000 ms, and enables the ring buffer.

Step 2: group. get_slowlog_responses with TABLE_NAME => 'orders' returns about 180 Scans from one IP, an analytics host, with 4-9 seconds of processing, responses of a few kilobytes and rising queue times. The checkout Gets never appear: each runs in under 5 ms, and queue time does not count toward the threshold.

Step 3: read the param. The scans have a start row, no stop row, and a SingleColumnValueFilter on status = 'REFUNDED'. Every region of the table is scanned in parallel and nearly every row is discarded.

Step 4: confirm from the client. Rerunning the job once with scan metrics enabled shows ROWS_SCANNED of about 41 million, ROWS_FILTERED of about 41 million, 3,200 rows returned and REGIONS_SCANNED of 180. The Gets are fast once they get a handler, but they wait behind scans that hold handlers for seconds.

Step 5: fix the cause, then add protection. The job moves to an index table keyed by status#date#order_id, so it reads 3,200 rows in a bounded range. As protection against the next such job, the team separates scan and get handlers with the call-queue ratios. The next night checkout p99 stays at 38 ms.

Failure modes and trade-offs

• Thresholds set wrong. Too low, and the ring buffer overwrites itself within seconds during bursts. Too high, and you see only disasters: the 10-second default misses most user-visible slowness. Start near your SLO.
• Trusting only the log. Truncated param fields hide the key range and filter that explain a slow scan. Use the ring buffer when you need the request.
• Treating the system table as complete. The queue is bounded and the chore runs every 10 minutes, so a crash loses the last batch.
• Looking for victims in the log. Calls that only waited are never recorded. The records show the culprits; the victims show in client latency.
• Missing slow queries made of fast RPCs. A long scan in small RPCs never trips a per-RPC threshold; only client metrics find it.

What to do next

1. Lower hbase.ipc.warn.response.time to a value near your latency SLO and set a separate, higher scan threshold.
2. Enable hbase.regionserver.slowlog.buffer.enabled on every RegionServer, and the system table if you need history.
3. Practise get_slowlog_responses with TABLE_NAME, CLIENT_IP and FILTER_BY_OP before the next incident.
4. Enable scan metrics in your data-access layer and log rows scanned against rows returned for every scan.
5. Ship RegionServer logs to one place and run a fingerprinting script daily, ranked by total processing time.
6. For each top group, classify the shape, then fix the key range, row key, batch size or queue split rather than adding hardware.