Troubleshoot I/O & Wait Latency with OraLatencyMap and PyLatencyMap

TL;DR: When your database “feels slow,” metrics are key for investigations, however relying on averages may mislead you. That's when wait latency histograms and heat map visualization can help you understand where and how wait time is spent and fix what actually matters.

---

I recently chased an Oracle performance issue where most reads were sub-millisecond (cache), but a thin band around ~10 ms (spindles) dominated total wait time. Classic bimodal latency: the fast band looked fine in averages, yet the rare slow band owned the delay.

To investigate, and prove it, I refreshed two of my old tools:

• OraLatencyMap (SQL*Plus script): samples Oracle’s microsecond wait-event histograms and renders two terminal heat maps with wait event latency details over time

• PyLatencyMap (Python): a general latency heat-map visualizer that reads record-oriented histogram streams from Oracle scripts, BPF/bcc, SystemTap, DTrace, trace files, etc.

Both now have fresh releases with minor refactors and dependency checks.

---

Why heat maps for wait latency?

Latency data naturally forms histograms (bucketed counts by latency). That’s a 2D view. But performance evolves over time, adding a third dimension (latency × time × magnitude). A heat map projects this 3D story onto your terminal so you can spot patterns at a glance.

Why two heat maps?

• Frequency heat map answers: Are many calls slow? (events/sec)

• Intensity heat map answers: Are a few slow calls consuming most time? (time/sec)

In my case, frequency showed a bright <1 ms band (healthy) while intensity lit up at ~10 ms (spindles). Rare tail, real culprit.

Reading the canvas

• Y-axis = latency buckets (displayed in ms).

• X-axis = time, newest at the right.

• Top = Frequency (events/sec). Bottom = Intensity (time/sec).

Look for bands (stable tiers), streaks (bursts), and hot tails (small but expensive).

Example output from OraLatencyMap v1.3

This example shows the latency heatmap measured and displayed with OraLatencyMap for the db file sequential read event.
The system is experiencing a bimodal latency distribution, indicating two distinct latency patterns:

• Reads from fast storage (SSD) with latency < 1 ms (visible in the Frequency Heatmap, blue area).
• Reads from slower storage (spinning disks) with latency ≈ 10 ms (visible in the Intensity Heatmap, yellow-red areas).

---

Quick starts

Oracle (OraLatencyMap)

OraLatencyMap  is a command-line script/widget for Oracle databases. 

Prerequisites
• SQL*Plus
• Privileges: SELECT on GV$EVENT_HISTOGRAM_MICRO and EXECUTE on DBMS_LOCK

Basic usage
SQL> @OraLatencyMap
SQL> @OraLatencyMap 3 "db file sequential read"  --sample single-block reads every 3s
SQL> @OraLatencyMap 5 "log file sync" -- check commit stalls / commit latency

Tip: Quote event names exactly as shown (including spaces).

Advanced driver (more control)
Syntax:
@OraLatencyMap_advanced <interval_s> "<event_name>" <bins> <columns> "<where_clause>"

Example (focus on single-block reads, 5s sampling, 11 bins, 100 columns, only inst_id=1):
SQL> @OraLatencyMap_advanced 5 "db file sequential read" 11 100 "and inst_id=1"

Parameter notes
• <interval_s> — sampling interval in seconds
• <event_name> — Oracle wait event to analyze (quoted)
• <bins> — number of latency buckets
• <columns> — width (time axis) of the heat map
• <where_clause> — optional extra filter (e.g., RAC: and inst_id=1)

Which wait events to start with?
• db file sequential read — typical for random single-block I/O; good starting point for read latency issues.
• log file sync — measures commit latency; use when users report slow commits.

Requirements: SQL*Plus; SELECT on GV$EVENT_HISTOGRAM_MICRO and EXECUTE on DBMS_LOCK..

---

Linux & everything else (PyLatencyMap)

PyLatencyMap is a tool running in Python. It is a terminal-based visualizer for latency histograms. It’s intended to help with performance tuning and troubleshooting. It renders two scrolling heat maps—Frequency and Intensity—so you can see how latency distributions evolve over time. Works from the command line and plays nicely with sources that output latency histograms (Oracle wait histograms, BPF/bcc, DTrace, SystemTap, tracefiles, etc.).

Install:

pip install PyLatencyMap
latencymap --help   # or: python -m LatencyMap --help

Replay sample data:

cat SampleData/example_latency_data.txt | latencymap
# slower playback:
cat SampleData/example_latency_data.txt | latencymap --screen_delay=0.2

Use it live with your sources (examples):

# Oracle microsecond histograms → heat maps
sqlplus -S / as sysdba \
  @Event_histograms_oracle/ora_latency_micro.sql "db file sequential read" 3 \
| latencymap

# Use it with System Instrumentation (BPF)
# Measure Linux block I/O with BCC (run as root and need bcc to be installed)
python -u BPF-bcc/pylatencymap-biolatency.py -QT 3 100 | latencymap

🎬 Demo video: 

---

What’s new

• OraLatencyMap v1.3 – updated to use GV$EVENT_HISTOGRAM_MICRO by default, small refactors.

• PyLatencyMap v1.3 – cleaner CLI, better record parsing, examples refreshed (Oracle, BPF/bcc, SystemTap, DTrace).

---

When to reach for which

• Suspect Oracle waits? Start with OraLatencyMap on db file sequential read or log file sync.

• Need cross-stack visibility (OS/storage/trace)? Use PyLatencyMap and feed it histograms from your favorite tracer.

---

See it, prove it, and fix it

Bottom line: If you only look at averages, you may miss complex behaviors like multimodal I/O (fast I/O with a slow tail). Heat maps also show you the time evolution of the latency patterns. With two small tools and two heat maps, you can see it, prove it, and fix it.

• OraLatencyMap (README, scripts, examples)

• PyLatencyMap (README, scripts, examples) + PyLatencyMap on PyPI

Linux BPF/bcc for Oracle Tracing

Topic: In this post you will find a short discussion and pointers to the code of a few sample scripts that I have written using Linux BPF/bcc and uprobes for Oracle tracing.

Previous work and motivations

Tools for dynamic tracing are very useful for troubleshooting and internals investigations of Oracle workloads. Dynamic tracing probes on the OS/kernel, can be used to measure the details for I/O latency for example. Moreover probes on the Oracle userspace functions can be be used to complement Oracle instrumentation and probe deeper into the internals of the Oracle engine, when needed. For example in a work done in collaboration with Frits Hoogland we have investigated how to link Oracle wait event interface with tools able to probe the userspace, such as gdb and dynamic tracing tools as DTrace, SystemTap and Perf. More details and examples on this topic can be found in previous work: Modern Linux Tools for Oracle Troubleshooting (presentation at UKOUG Tech14), Life of an Oracle I/O: Tracing Logical and Physical I/O with SystemTap, Linux Perf Probes for Oracle Tracing, Flame Graphs for Oracle.


What's new with BPF/bcc

BPF together with his frontend bcc are new and exciting technologies in the Linux dynamic tracing ecosystem. If you are not familiar with them, you can get up to speed using the excellent material in Brendan Gregg's blog. While the tools are still in development as I write this, a large amount of important features are already available starting from kernel 4.5, notably the support for uprobes that I have used in the scripts discussed later in this post.

I have started experimenting with porting a few probes for the Oracle userspace that I had written using SystemTap and discussed in this blog. While the language/syntax is completely different between SystemTap and BPF/bcc, porting the probes has turned out to be relatively straightforward. The work has been made substantially easier by the availability of a large selection of well-written and documented scripts in the tools directory of bcc. At present writing BPF/bcc scripts is a mixture of coding in Python and C, which feels to me both familiar and at the same time strangely low-level compared to the more mature environments for example of DTrace and SystemTap.

The example scripts that I have written using BPF/bcc are on Github. Here is a list with comments:

Script name	Short description
ora_sqlparse_trace.py	Tracing of Oracle SQL parsing. This script traces SQL hard parsing on Oracle binaries hooking on the Oracle function "opiprs" and reads from function arguments (CPU registers) and from process memory.
ora_wait_trace.py	Tracing of Oracle wait events. This script traces Oracle sessions by hooking on the functions "kskthewt" and "kews_update_wait_time" and reads from function arguments (CPU registers).
ora_logicalIO_histogram.py	Logical IO latency histograms. This script measures the latency between call and return time for the Oracle function "kcbgtcr", which is an important part of the logical IO processing for consistent reads.
ora_wait_histogram.py	Wait event latency histograms. This script traces Oracle sessions by hooking on the functions "kskthewt" and "kews_update_wait_time" and reads from function arguments (CPU registers). BPF computes the latency histogram for the wait events and the script prints the values on stdout.

An example of the usage of ora_wait_histogram.py to measure and display wait event latency:

# stdbuf -oL ./ora_wait_histogram.py 10 10|sed -e 's/event# = /event#=/g' -f eventsname.sed
Start tracing oracle wait events... Hit Ctrl-C to end.

event=db file sequential read
     wait time, microsec : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 0        |                                        |
         4 -> 7          : 0        |                                        |
         8 -> 15         : 0        |                                        |
        16 -> 31         : 0        |                                        |
        32 -> 63         : 0        |                                        |
        64 -> 127        : 25       |                                        |
       128 -> 255        : 24521    |********************                    |
       256 -> 511        : 46788    |****************************************|
       512 -> 1023       : 12169    |**********                              |
      1024 -> 2047       : 1132     |                                        |
      2048 -> 4095       : 660      |                                        |
      4096 -> 8191       : 248      |                                        |
      8192 -> 16383      : 29       |                                        |


Latency heat maps to display histograms collected with BPF/bcc

PyLatencyMap is a command-line tool for visualizing latency histograms using heat maps on terminal graphics, using ANSI escape codes. PyLatencyMap can be used to investigate I/O performance for random I/O, especially suited for the cases of multiple modes of response time from the storage (SSD cache, HDD, latency outliers). The original idea for PyLatencyMap comes from the work of Brendan Gregg on latency heat maps. I have added to the PyLatencyMap repository a modified version of the biolatency.py script to measure I/O latency histograms: this is the link to the script pylatencymap_biolatency.py and an example of heat maps generated with PyLatencyMap with the script Example11_BPF-bcc_blockIO_latency.sh:

The test workload has been generated using Kevin Closson's SLOB. Additional references with a more detailed discussion of the topic of testing Oracle I/O with SLOB and measuring latency heat maps are:
Heat Map Visualization of I/O Latency with SystemTap and PyLatencyMap and OraLatencyMap v1.1 and Testing I/O with SLOB 2.


Notes on the test environment

The scripts discussed in this post have been developed on Fedora 24 (alpha) running Linux kernel version 4.6 (using the rawhide kernel) and have been tested on workloads generated using Oracle version 11.2.0.4. This is not an Oracle-supported configuration and  the scripts are intended mainly as a demonstration of the technology and for learning purposes.
Here are some pointers on the steps I used to setup a lab environment for testing:

• Download Fedora server from https://getfedora.org/en/server/ (version 24 beta, as I write this).
• Installed Fedora, for example on a VM with VirtualBox
• Run "sudo dnf update" to get the latest kernel and packages
• Get kernel-devel with "sudo dnf install kernel-devel"
• Follow the installation instructions for bcc on Fedora from https://github.com/iovisor/bcc/blob/master/INSTALL.md

Note in particular the step for configuring the rawhide kernel, probably a good choice when testing BPF, as new features are being added on a regular basis as I write this:

# sudo dnf config-manager --add-repo=http://alt.fedoraproject.org/pub/alt/rawhide-kernel-nodebug/fedora-rawhide-kernel-nodebug.repo

# sudo dnf update

Additional pointers and recipes on how to install Oracle 11.2 on Fedora can be found on Tim Hall's website at: https://oracle-base.com/articles/11g/articles-11g

Conclusions

BPF with its bcc frontend are new and powerful tools for dynamic tracing for Linux. A discussion of the merits and shortfalls of BPF/bcc vs other existing solutions in the Linux dynamic tracing ecosystem is beyond the scope of this post. What you can find in this post are a few example scripts that I have written for tracing Oracle using BPF/bcc and uprobes and an additional script for integrating BPF/bcc with PyLatencyMap, which provides visualization as heat maps of the histograms generated using BPF/bcc.
Although the BPF/bcc environment is currently under evolution, it appears already a very useful addition to the toolbox for troubleshooting and performance investigations of Linux workloads. A set of example scripts/tools that come with the bcc repository are of great help for getting started both with using BPF/bcc and with writing new scripts. BPF/bcc can only run on relatively new kernels (as I write this, I have tested the scripts discussed in this post on kernel version 4.6) and this is an obstacle for its adoption in many environments, at least in the short term.

Note added, February 2019: Red Hat and Oracle Linux 7.6 have backported BPF and can run bcc scripts (yum install bcc*). I have updated the script repository accordingly, see https://github.com/LucaCanali/Linux_tracing_scripts/tree/master/BPF-bcc_Userspace_Oracle


Credits and acknowledgements

Many of the original ideas and tools discussed here are inspired or directly derived from the awesome published work of Brendan Gregg.
Many thanks also to the development teams of BPF and bcc for providing and supporting this new powerful tools. In particular thanks to Brenden Blanco for his work on uprobes for bcc and for his support on issue #478.
The work of investigating Oracle userspace with dynamic tracing tools has been done in collaboration with Frits Hoogland.