Apache BookKeeper Observability — Part 4— Read USE Metrics
Based on BookKeeper 4.14 as configured for Apache Pulsar.
In the previous two posts we looked at how to diagnose bottlenecks in the write path. In this post we’ll start doing the same for the read path by focusing on the USE metrics. In the subsequent post we’ll cover all the metrics in detail and also how to diagnose read cache thrashing.
It is recommended to have read BookKeeper Internals Part 3 as it describes the inner workings of the DbLedgerStorage component.
Time Utilization
Time utilization is the calculation of time spent doing something per second. So if a thread spends 500ms per second doing work then it is at 50% utilization. We can measure time utilization in different places to discover whether there is a bottleneck or not.
Read Threads
Reads are entirely executed within the read threads and each read thread executes each read synchronously and serially. This makes time utilization a meaningful metric for reads (and much less complicated than the write threads). Once a thread reaches 100% time utilization it is unlikely it can do much more work and has reached its max read throughput capacity.
sum(irate(bookkeeper_server_BookieReadThreadPool_task_execution_sum[1m])) by (pod)
This Grafana panel is from a bookie that has 8 read threads (the default) and an ever increasing read load until it reaches its read capacity. We see that it reaches 8 seconds time spent per second which means 100% utilization on all threads.
The inconvenient thing about this method of measuring utilization is that you must know the number of threads, else the number of seconds is not meaningful.
NOTE! For these task execution metrics you must set the
enableTaskExecutionStatsconfig to true.
DbLedgerStorage
All file IO in BookKeeper is synchronous and also for each read thread it is serial. We can measure the time that read threads spend in DbLedgerStorage using the read latency metrics which have a sum metric.
sum(irate(bookie_read_entry_sum[1m])) by (pod)
In this example we see that the time spent in DbLedgerStorage matches almost perfectly the time spent by the read threads as a whole. This might not always be the case as there can be times that sending the responses back to the clients takes significant time when the network is the bottleneck, in those cases the time spent in DbLedgerStorage will be lower than in the read threads.
Saturation
Saturation of the read-path comes down to read thread pool task queue sizes (as described in part 1). If DbLedgerStorage cannot perform reads fast enough the read thread pool tasks queue starts filling up until they reach capacity.
Task queue length (repeat for each thread in the pool): sum(bookkeeper_server_BookieReadThreadPool_queue_0) by (pod)
p99 request queue time: sum(bookkeeper_server_BookieReadThreadPool_task_queued{success=”true”, quantile=”0.99"}) by (pod)
In this example we see that the queue lengths get higher and higher, corresponding to the utilization of the read threads. The amount of time that requests spent stuck in these queues goes up dramatically in the end.
The inconvenient things about the read thread task queue length metrics is that the thread ordinal is part of the metric name. This can make it a little more complex in terms of creating dashboards. Likewise, the thread pool queue time is aggregated across all threads so we cannot drill down and see if one thread in particular is saturated.
Summary
These utilization and saturation metrics should be one of the first things you check when investigating problems with read performance. In our simple examples the signals were about as strong as they get that the read-path was overloaded.
If you see high utilization and saturation of reads it’s time to figure out what is causing the problem. It could simply be under-provisioning for the load, or in less common cases it could be a case of read cache thrashing. There are of course your system metrics (CPU, memory, disk utilization/saturation) which are out-of-scope for this series, but can be vitally important for diagnosing performance issues.
In the next post we’ll look at all the DbLedgerStorage read metrics available as well as the metrics blindspots. We’ll also explain how to detect cache thrashing or rule it out as a cause for your read performance issues.
Series links:
