| <div role="region" aria-label="Skip to main content"><a class="skipToContent_fXgn" href="#docusaurus_skipToContent_fallback">Skip to main content</a></div><nav aria-label="Main" class="navbar navbar--fixed-top"><div class="navbar__inner"><div class="navbar__items"><button aria-label="Toggle navigation bar" aria-expanded="false" class="navbar__toggle clean-btn" type="button"><svg width="30" height="30" viewBox="0 0 30 30" aria-hidden="true"><path stroke="currentColor" stroke-linecap="round" stroke-miterlimit="10" stroke-width="2" d="M4 7h22M4 15h22M4 23h22"></path></svg></button><a class="navbar__brand" href="/"><div class="navbar__logo"><img src="/img/bk-logo.svg" alt="Apache Bookkeeper" class="themedImage_ToTc themedImage--light_HNdA"><img src="/img/bk-logo.svg" alt="Apache Bookkeeper" class="themedImage_ToTc themedImage--dark_i4oU"></div><b class="navbar__title text--truncate">Apache BookKeeper</b></a><a class="navbar__item navbar__link" href="/docs/overview/">Documentation</a><div class="navbar__item dropdown dropdown--hoverable"><a href="#" aria-haspopup="true" aria-expanded="false" role="button" class="navbar__link">Community</a><ul class="dropdown__menu"><li><a class="dropdown__link" href="/community/mailing-lists">Mailing lists</a></li><li><a class="dropdown__link" href="/community/slack">Slack</a></li><li><a href="https://github.com/apache/bookkeeper/issues" target="_blank" rel="noopener noreferrer" class="dropdown__link">Github issues<svg width="12" height="12" aria-hidden="true" viewBox="0 0 24 24" class="iconExternalLink_nPIU"><path fill="currentColor" d="M21 13v10h-21v-19h12v2h-10v15h17v-8h2zm3-12h-10.988l4.035 4-6.977 7.07 2.828 2.828 6.977-7.07 4.125 4.172v-11z"></path></svg></a></li><li><a class="dropdown__link" href="/community/releases">Release management</a></li><li><a class="dropdown__link" href="/community/meeting">Community meetings</a></li><li><a class="dropdown__link" href="/community/contributing">Contribution guide</a></li><li><a class="dropdown__link" href="/community/coding-guide">Coding guide</a></li><li><a class="dropdown__link" href="/community/testing">Testing guide</a></li><li><a class="dropdown__link" href="/community/issue-report">Issue report guide</a></li><li><a class="dropdown__link" href="/community/release-guide">Release guide</a></li><li><a class="dropdown__link" href="/community/presentations">Presentations</a></li><li><a class="dropdown__link" href="/community/bookkeeper-proposals">BookKeeper proposals (BP)</a></li></ul></div><div class="navbar__item dropdown dropdown--hoverable"><a href="#" aria-haspopup="true" aria-expanded="false" role="button" class="navbar__link">Project</a><ul class="dropdown__menu"><li><a class="dropdown__link" href="/project/who">Who are we?</a></li><li><a class="dropdown__link" href="/project/bylaws">Bylaws</a></li><li><a href="https://apache.org/licenses" target="_blank" rel="noopener noreferrer" class="dropdown__link">License<svg width="12" height="12" aria-hidden="true" viewBox="0 0 24 24" class="iconExternalLink_nPIU"><path fill="currentColor" d="M21 13v10h-21v-19h12v2h-10v15h17v-8h2zm3-12h-10.988l4.035 4-6.977 7.07 2.828 2.828 6.977-7.07 4.125 4.172v-11z"></path></svg></a></li><li><a class="dropdown__link" href="/project/privacy">Privacy policy</a></li><li><a href="https://www.apache.org/foundation/sponsorship.html" target="_blank" rel="noopener noreferrer" class="dropdown__link">Sponsorship<svg width="12" height="12" aria-hidden="true" viewBox="0 0 24 24" class="iconExternalLink_nPIU"><path fill="currentColor" d="M21 13v10h-21v-19h12v2h-10v15h17v-8h2zm3-12h-10.988l4.035 4-6.977 7.07 2.828 2.828 6.977-7.07 4.125 4.172v-11z"></path></svg></a></li><li><a href="https://www.apache.org/foundation/thanks.html" target="_blank" rel="noopener noreferrer" class="dropdown__link">Thanks<svg width="12" height="12" aria-hidden="true" viewBox="0 0 24 24" class="iconExternalLink_nPIU"><path fill="currentColor" d="M21 13v10h-21v-19h12v2h-10v15h17v-8h2zm3-12h-10.988l4.035 4-6.977 7.07 2.828 2.828 6.977-7.07 4.125 4.172v-11z"></path></svg></a></li></ul></div></div><div class="navbar__items navbar__items--right"><div class="navbar__item dropdown dropdown--hoverable dropdown--right"><a class="navbar__link" aria-haspopup="true" aria-expanded="false" role="button" href="/docs/overview/">4.16.5</a><ul class="dropdown__menu"><li><a class="dropdown__link" href="/docs/next/overview/">Next</a></li><li><a class="dropdown__link" href="/docs/overview/">4.16.5</a></li><li><a class="dropdown__link" href="/docs/4.15.5/overview/">4.15.5</a></li><li><a class="dropdown__link" href="/docs/4.14.8/overview/">4.14.8</a></li><li><a class="dropdown__link" href="/docs/4.13.0/overview/">4.13.0</a></li><li><a class="dropdown__link" href="/docs/4.12.1/overview/">4.12.1</a></li><li><a class="dropdown__link" href="/docs/4.11.1/overview/">4.11.1</a></li><li><a class="dropdown__link" href="/docs/4.10.0/overview/">4.10.0</a></li><li><a class="dropdown__link" href="/docs/4.9.2/overview/">4.9.2</a></li><li><a class="dropdown__link" href="/docs/4.8.2/overview/">4.8.2</a></li><li><a class="dropdown__link" href="/docs/4.7.3/overview/">4.7.3</a></li><li><a class="dropdown__link" href="/docs/4.6.2/overview/">4.6.2</a></li><li><a class="dropdown__link" href="/docs/4.5.1/overview/">4.5.1</a></li></ul></div><a class="navbar__item navbar__link" href="/releases">Download</a><div class="toggle_vylO colorModeToggle_DEke"><button class="clean-btn toggleButton_gllP toggleButtonDisabled_aARS" type="button" disabled="" title="Switch between dark and light mode (currently light mode)" aria-label="Switch between dark and light mode (currently light mode)" aria-live="polite"><svg viewBox="0 0 24 24" width="24" height="24" class="lightToggleIcon_pyhR"><path fill="currentColor" d="M12,9c1.65,0,3,1.35,3,3s-1.35,3-3,3s-3-1.35-3-3S10.35,9,12,9 M12,7c-2.76,0-5,2.24-5,5s2.24,5,5,5s5-2.24,5-5 S14.76,7,12,7L12,7z M2,13l2,0c0.55,0,1-0.45,1-1s-0.45-1-1-1l-2,0c-0.55,0-1,0.45-1,1S1.45,13,2,13z M20,13l2,0c0.55,0,1-0.45,1-1 s-0.45-1-1-1l-2,0c-0.55,0-1,0.45-1,1S19.45,13,20,13z M11,2v2c0,0.55,0.45,1,1,1s1-0.45,1-1V2c0-0.55-0.45-1-1-1S11,1.45,11,2z M11,20v2c0,0.55,0.45,1,1,1s1-0.45,1-1v-2c0-0.55-0.45-1-1-1C11.45,19,11,19.45,11,20z M5.99,4.58c-0.39-0.39-1.03-0.39-1.41,0 c-0.39,0.39-0.39,1.03,0,1.41l1.06,1.06c0.39,0.39,1.03,0.39,1.41,0s0.39-1.03,0-1.41L5.99,4.58z M18.36,16.95 c-0.39-0.39-1.03-0.39-1.41,0c-0.39,0.39-0.39,1.03,0,1.41l1.06,1.06c0.39,0.39,1.03,0.39,1.41,0c0.39-0.39,0.39-1.03,0-1.41 L18.36,16.95z M19.42,5.99c0.39-0.39,0.39-1.03,0-1.41c-0.39-0.39-1.03-0.39-1.41,0l-1.06,1.06c-0.39,0.39-0.39,1.03,0,1.41 s1.03,0.39,1.41,0L19.42,5.99z M7.05,18.36c0.39-0.39,0.39-1.03,0-1.41c-0.39-0.39-1.03-0.39-1.41,0l-1.06,1.06 c-0.39,0.39-0.39,1.03,0,1.41s1.03,0.39,1.41,0L7.05,18.36z"></path></svg><svg viewBox="0 0 24 24" width="24" height="24" class="darkToggleIcon_wfgR"><path fill="currentColor" d="M9.37,5.51C9.19,6.15,9.1,6.82,9.1,7.5c0,4.08,3.32,7.4,7.4,7.4c0.68,0,1.35-0.09,1.99-0.27C17.45,17.19,14.93,19,12,19 c-3.86,0-7-3.14-7-7C5,9.07,6.81,6.55,9.37,5.51z M12,3c-4.97,0-9,4.03-9,9s4.03,9,9,9s9-4.03,9-9c0-0.46-0.04-0.92-0.1-1.36 c-0.98,1.37-2.58,2.26-4.4,2.26c-2.98,0-5.4-2.42-5.4-5.4c0-1.81,0.89-3.42,2.26-4.4C12.92,3.04,12.46,3,12,3L12,3z"></path></svg></button></div><div class="searchBox_ZlJk"></div></div></div><div role="presentation" class="navbar-sidebar__backdrop"></div></nav><div id="docusaurus_skipToContent_fallback" class="main-wrapper mainWrapper_z2l0"><main class="container container--fluid margin-vert--lg"><div class="row mdxPageWrapper_j9I6"><div class="col col--8"><article><h1>BP-44: USE metrics</h1><h3 class="anchor anchorWithStickyNavbar_LWe7" id="motivation">Motivation<a href="#motivation" class="hash-link" aria-label="Direct link to Motivation" title="Direct link to Motivation"></a></h3><p>Based on our experience (at Splunk) running many BookKeeper clusters in production, from very small to very large deployments (in terms of number of bookies, size of VMs and load) we have identified a number of short-comings with the current BookKeeper metrics that make it harder than it should be to identify bottlenecks in performance. The <a href="https://www.brendangregg.com/usemethod.html" target="_blank" rel="noopener noreferrer">USE method</a> (Utilization, Saturation, Errors) is an effective strategy for diagnosing where bottlenecks in a system lie but the current metrics do not always expose metrics related to utilization and saturation. Also, even if you have a good mental model for how BookKeeper works internally, there are blindspots in the metrics that make it difficult to know what is happening at times.</p><p>Finally, many of the metrics are aggregated, such as journal and DbLedgerStorage. When these components are configured with multiple directories, it is currently not possible to inspect the metrics of only a single journal or DbLedgerStorage instance. One bad volume can be hard to identify.</p><p>This BP proposes a number of improvements to help identify performance issues in production. The objective is for a human operator to rapidly see where a bottleneck exists and where it exists by using utilization and saturation metrics.</p><h4 class="anchor anchorWithStickyNavbar_LWe7" id="utilization">Utilization<a href="#utilization" class="hash-link" aria-label="Direct link to Utilization" title="Direct link to Utilization"></a></h4><p>Ultimately all work in a bookie is performed by threads. Some operations are performed by only a single thread while others are spread out over multiple threads. Some threads play a core role in the critical path of reads and writes and when fully utilized indicate a bottleneck. We propose that each thread reports the time that it is busy which will allow time utilization to be calculated. Because all file i/o is synchronous, thread utilization is a very close approximation of resource utilization for a bookie. For a thread whose sole role is file i/o, if it is 100% utilized then it can take little to no more work.</p><p>For example, if the Force Write thread is reporting 100% time utilization we’ll know that it has become a bottleneck and to look further into the force write metrics.</p><p>Likewise, some operations are in the critical path that are executed across multiple threads. For example, with DbLedgerStorage, flushes are in the critical path for writes and the work is performed across at least two threads (Sync thread, DbStorage thread). Knowing the time utilization of the Sync Thread and the DbStorage thread is useful, but knowing the time utilization of flushes as a whole (regardless of thread) is even more useful in this particular case. Once flushes are being performed 100% of the time we know that we have a write bottleneck in DbLedgerStorage.</p><p>So utilization metrics of both threads and operations can be extremely useful and often combining the two give even more insight.</p><h4 class="anchor anchorWithStickyNavbar_LWe7" id="saturation">Saturation<a href="#saturation" class="hash-link" aria-label="Direct link to Saturation" title="Direct link to Saturation"></a></h4><p>Metrics that indicate saturation are things like rejected requests, full queues/caches. We need to ensure that there are no blindspots for saturation metrics.</p><p>Once we start getting saturation indicators we have strong signals of a bottleneck existing. It may be a high level metric (rejected requests) which only tells us we have a problem, or a component level metric (journal queue length) that tells us the locality of a bottleneck. We also need to know things like the queue size bounds in order to detect when a component is fully saturated, so emitting metrics for certain configurations is useful.</p><h4 class="anchor anchorWithStickyNavbar_LWe7" id="component-and-thread-labels">Component and Thread Labels<a href="#component-and-thread-labels" class="hash-link" aria-label="Direct link to Component and Thread Labels" title="Direct link to Component and Thread Labels"></a></h4><p>Work is parallelized by thread pools and by using multiple directories that allow for multiple journal instances and multiple ledger storage instances. We have seen in production cases where a single bad volume has a large negative impact on BookKeeper performance. Being able to pick apart metrics by the thread and component instance can be extremely helpful in diagnosing issues that only affect one journal/ledger storage instance or a subset of threads.</p><h4 class="anchor anchorWithStickyNavbar_LWe7" id="sub-operation-time">Sub-Operation Time<a href="#sub-operation-time" class="hash-link" aria-label="Direct link to Sub-Operation Time" title="Direct link to Sub-Operation Time"></a></h4><p>In some cases a single operation can consist of multiple smaller operations. For example, a DbLedgerStorage flush involves flushing two RocksDB instances and entry log files. The only way to currently confirm whether RocksDB has gotten into a bad state is by profiling on the machine/pod.</p><p>Adding extra metrics to cover sub-operations can help to diagnose or rule-out an issue quickly.</p><h4 class="anchor anchorWithStickyNavbar_LWe7" id="read-cache-thrashing">Read Cache Thrashing<a href="#read-cache-thrashing" class="hash-link" aria-label="Direct link to Read Cache Thrashing" title="Direct link to Read Cache Thrashing"></a></h4><p>Read cache thrashing can have a huge negative impact on bookie performance. We have most of the metrics already for detecting when it happens except for one problem: we don’t report read and write cache hits/misses separately.</p><p>When we separate out cache hits/misses, we can start calculating the actual read cache hit-to-miss rate and compare that to the readahead batch sizes and calculate that the miss rate is too high (indicating thrashing).</p><h3 class="anchor anchorWithStickyNavbar_LWe7" id="the-current-state-of-affairs">The Current State of Affairs<a href="#the-current-state-of-affairs" class="hash-link" aria-label="Direct link to The Current State of Affairs" title="Direct link to The Current State of Affairs"></a></h3><h4 class="anchor anchorWithStickyNavbar_LWe7" id="utilization-1">Utilization<a href="#utilization-1" class="hash-link" aria-label="Direct link to Utilization" title="Direct link to Utilization"></a></h4><p>The OpsStatsLogger gives us visibility into some time utilization metrics by using the “_sum” suffix metric for latency based OpStatsLogger metrics. We can’t see the utilization of each thread, just the thread pool as a whole. Knowing the number of threads in the pool allows us to calculate the % time utilization (given that each cluster may have a different size of thread pool this is inconvenient).</p><p>Operations such as journal flushes, journal force writes and DbLedgerStorage already record latencies with OpStatsLoggers which allows us to calculate utilization of IO operations as long as we know the number of journal/ledger storage directories (again, inconvenient).</p><p>Blindspots:</p><ul><li>Write/read/high priority thread pool</li><li>Utilization of each thread</li><li>Journal<ul><li>Drill-down by journal instance</li><li>Utilization of the threads (they do other work such as taking work from queues and placing work on queues)</li></ul></li><li>Ledger Storage<ul><li>Drill-down by ledger storage instance</li><li>Where is time spent on reads? Locations index, read from entry log, readahead?</li><li>Where is time spent on flushes? Ledger index, locations index, entry log files?</li></ul></li></ul><h4 class="anchor anchorWithStickyNavbar_LWe7" id="saturation-1">Saturation<a href="#saturation-1" class="hash-link" aria-label="Direct link to Saturation" title="Direct link to Saturation"></a></h4><p>There are some existing indicators of saturation, such as the thread pool task queue lengths, journal queue length, force write queue length, DbLedgerStorage rejected writes. But there are some blindspots:</p><ul><li>Requests rejected due to full thread pool task queues are logged as request failures. More helpful is a specific metric for rejected read and write requests</li><li>Queue lengths are in aggregate, need to be able to drill-down by thread/journal/ledger storage instance.</li><li>We don’t have metrics for things like maximum queue/cache sizes so we can’t calculate when a queue or a cache is full.</li><li>Netty can become saturated, tracking the number of unwritable channels, bytes for unwritable can help diagnose Netty saturation</li></ul><h3 class="anchor anchorWithStickyNavbar_LWe7" id="public-interfaces">Public Interfaces<a href="#public-interfaces" class="hash-link" aria-label="Direct link to Public Interfaces" title="Direct link to Public Interfaces"></a></h3><p>N/A</p><h3 class="anchor anchorWithStickyNavbar_LWe7" id="proposed-changes">Proposed Changes<a href="#proposed-changes" class="hash-link" aria-label="Direct link to Proposed Changes" title="Direct link to Proposed Changes"></a></h3><h4 class="anchor anchorWithStickyNavbar_LWe7" id="thread-scoped-opstatslogger-and-counter">Thread scoped OpStatsLogger and Counter<a href="#thread-scoped-opstatslogger-and-counter" class="hash-link" aria-label="Direct link to Thread scoped OpStatsLogger and Counter" title="Direct link to Thread scoped OpStatsLogger and Counter"></a></h4><p>Add a new “thread scoped” variant of the OpStatsLogger and the Counter where each adds labels:</p><ul><li>threadPool (or just the thread name for lone threads such as a journal thread)</li><li>thread (the thread ordinal, for example a read thread pool with four threads, they are numbers 0-3)</li></ul><p>The following methods are added to the StatsLogger interface:</p><div class="codeBlockContainer_Ckt0 theme-code-block" style="--prism-color:#393A34;--prism-background-color:#f6f8fa"><div class="codeBlockContent_biex"><pre tabindex="0" class="prism-code language-text codeBlock_bY9V thin-scrollbar"><code class="codeBlockLines_e6Vv"><span class="token-line" style="color:#393A34"><span class="token plain">OpStatsLogger getThreadScopedOpStatsLogger(String name)</span><br></span><span class="token-line" style="color:#393A34"><span class="token plain">Counter getThreadScopedCounter(String name)</span><br></span></code></pre><div class="buttonGroup__atx"><button type="button" aria-label="Copy code to clipboard" title="Copy" class="clean-btn"><span class="copyButtonIcons_eSgA" aria-hidden="true"><svg class="copyButtonIcon_y97N" viewBox="0 0 24 24"><path d="M19,21H8V7H19M19,5H8A2,2 0 0,0 6,7V21A2,2 0 0,0 8,23H19A2,2 0 0,0 21,21V7A2,2 0 0,0 19,5M16,1H4A2,2 0 0,0 2,3V17H4V3H16V1Z"></path></svg><svg class="copyButtonSuccessIcon_LjdS" viewBox="0 0 24 24"><path d="M21,7L9,19L3.5,13.5L4.91,12.09L9,16.17L19.59,5.59L21,7Z"></path></svg></span></button></div></div></div><p>The OpStatsLogger and Counter interfaces remain unchanged.</p><p>For each thread that mutates a thread scoped OpStatsLogger, internally it will end up registering one OpStatsLogger per thread. For example, with four read threads, then the following metrics for successful task executions would be created:</p><div class="codeBlockContainer_Ckt0 theme-code-block" style="--prism-color:#393A34;--prism-background-color:#f6f8fa"><div class="codeBlockContent_biex"><pre tabindex="0" class="prism-code language-text codeBlock_bY9V thin-scrollbar"><code class="codeBlockLines_e6Vv"><span class="token-line" style="color:#393A34"><span class="token plain">bookkeeper_server_BookieReadThreadPool_task_execution_sum{success="true", thread="0", threadPool="BookieReadThreadPool"}</span><br></span><span class="token-line" style="color:#393A34"><span class="token plain">bookkeeper_server_BookieReadThreadPool_task_execution_sum{success="true", thread="1", threadPool="BookieReadThreadPool"}</span><br></span><span class="token-line" style="color:#393A34"><span class="token plain">bookkeeper_server_BookieReadThreadPool_task_execution_sum{success="true", thread="2", threadPool="BookieReadThreadPool"}</span><br></span><span class="token-line" style="color:#393A34"><span class="token plain">bookkeeper_server_BookieReadThreadPool_task_execution_sum{success="true", thread="3", threadPool="BookieReadThreadPool"}</span><br></span></code></pre><div class="buttonGroup__atx"><button type="button" aria-label="Copy code to clipboard" title="Copy" class="clean-btn"><span class="copyButtonIcons_eSgA" aria-hidden="true"><svg class="copyButtonIcon_y97N" viewBox="0 0 24 24"><path d="M19,21H8V7H19M19,5H8A2,2 0 0,0 6,7V21A2,2 0 0,0 8,23H19A2,2 0 0,0 21,21V7A2,2 0 0,0 19,5M16,1H4A2,2 0 0,0 2,3V17H4V3H16V1Z"></path></svg><svg class="copyButtonSuccessIcon_LjdS" viewBox="0 0 24 24"><path d="M21,7L9,19L3.5,13.5L4.91,12.09L9,16.17L19.59,5.59L21,7Z"></path></svg></span></button></div></div></div><p>In order for thread scoped metrics to know which thread pool and thread ordinal the metrics of each thread should be labelled with, a thread registry is maintained. After each thread is started, the first work it performs is registering itself with a thread registry object that maps thread id -> {threadPool, thread}. In some cases this work can be performed outside of the thread itself, such as in a thread factory.</p><p>Each thread scoped metric registers per-thread metrics lazily. For example, when a thread scoped counter is incremented by a given thread, the first time that occurs on that given thread the thread labels are retrieved from the thread registry and a counter for that thread is created with the right labels and registered with the provider. In the case that the calling thread is unregistered, a default metric is used. Per thread OpStatsLoggers/Counters are not visible externally and are stored inside the thread scoped metric using a thread-local variable.</p><p>With these new variants, we can now replace calls to <code>getCounter</code> with <code>getThreadScopedCounter</code> and <code>getOpsStatsLogger</code> with <code>getThreadScopedOpsStatsLogger</code> for the metrics where we want to be able to drill down by thread pool and thread.</p><h4 class="anchor anchorWithStickyNavbar_LWe7" id="how-to-report-time-spent-for-utilization-calculation">How to Report Time Spent (For utilization calculation)<a href="#how-to-report-time-spent-for-utilization-calculation" class="hash-link" aria-label="Direct link to How to Report Time Spent (For utilization calculation)" title="Direct link to How to Report Time Spent (For utilization calculation)"></a></h4><p>We want to be able to report time spent by each thread as a whole, but also on operations and sub-operations. The simplest way to do this is simply measure elapsed time by taking a System.nanoTime() before the work and then logging the elapsed time via an OpStatsLogger or a Counter.</p><p>One challenge regarding this simple method is when operations take a long time, like a journal fsync or a ledger flush on a heavily overloaded bookie. Long execution times can cause per second calculations to go to 0 then to spike to very high levels (above 100% utilization). This can be mitigated by using larger windows (like 1 minute windows rather than 1 second windows) and heavily loaded systems don’t tend to fluctuate too much from second to second.</p><h5 class="anchor anchorWithStickyNavbar_LWe7" id="discarded-time-measurement-alternatives">Discarded time measurement alternatives:<a href="#discarded-time-measurement-alternatives" class="hash-link" aria-label="Direct link to Discarded time measurement alternatives:" title="Direct link to Discarded time measurement alternatives:"></a></h5><p>Use a sampling technique: too costly and complex. |
