Active Session History TECH PREVIEW

Get real-time and historical information about active sessions to analyze and troubleshoot performance issues

Active Session History (ASH) provides a current and historical view of system activity by sampling session activity in the database. A database session or connection is considered active if it is consuming CPU, or has an active RPC call that is waiting on one of the wait events.

ASH exposes session activity in the form of SQL views so that you can run analytical queries, aggregations for analysis, and troubleshoot performance issues. To run ASH, you need to enable YSQL or YCQL for their respective sessions.

Currently, ASH is available for YSQL, YCQL, and YB-TServer processes. ASH facilitates analysis by recording wait events related to YSQL, YCQL, or YB-TServer requests while they are being executed. These wait events belong to the categories including but not limited to CPU, WaitOnCondition, Network, and Disk IO.

Analyzing the wait events and wait event types lets you troubleshoot, answer the following questions, and subsequently tune performance:

  • Why is a query taking longer than usual to execute?
  • Why is a particular application slow?
  • What are the queries that are contributing significantly to database load and performance?

Configure ASH

To use ASH, enable and configure the following flags for each node of your cluster.

Flag Description
allowed_preview_flags_csv Pass the flags ysql_yb_ash_enable_infra and ysql_yb_enable_ash in this flag in CSV format.
ysql_yb_ash_enable_infra Enable or disable ASH infrastructure.
Default: false. Changing this flag requires a VM restart.
ysql_yb_enable_ash Works only in conjunction with the flag ysql_yb_ash_enable_infra. Start sampling and instrumentation (that is, periodically check and keep track) of YSQL and YCQL queries, and YB-TServer requests.
Default: false. Changing this flag doesn't require a VM restart.

Additional flags

You can also use the following flags based on your requirements.

Flag Description
ysql_yb_ash_circular_buffer_size Size (in KBs) of circular buffer where the samples are stored.
Default: 16000. Changing this flag requires a VM restart.
ysql_yb_ash_sampling_interval_ms Time (in milliseconds) duration between two sampling events (ysql, ycql, yb-tserver).
Default: 1000. Changing this flag doesn't require a VM restart.
ysql_yb_ash_sample_size Maximum number of events captured per sampling interval.
Default: 500. Changing this flag doesn't require a VM restart.

Limitations

Note that the following limitations are subject to change as the feature is in Tech Preview.

  • ASH is available per node only. Aggregations need to be done by you.
  • ASH is not available for YB-Master processes.
  • ASH is available only for foreground activities or queries from customer applications.
  • ASH does not capture start and end time of wait events.

YSQL views

ASH exposes the following views in each node to analyze and troubleshoot performance issues.

yb_active_session_history

Get information on wait events for each normalized query, YSQL, or YCQL request.

Column Type Description
root_request_id UUID A 16-byte UUID that is generated per request. Generated for queries at YSQL/YCQL layer.
rpc_request_id integer ID for internal requests, it is a monotonically increasing number for the lifetime of a YB-TServer.
wait_event_component text There are three components: YSQL, YCQL, and YB-TServer.
wait_event_class text Every wait event has a class associated with it.
wait_event text Provides insight into what the RPC is waiting on.
wait_event_type text Type of the wait event such as CPU, WaitOnCondition, Network, Disk IO, and so on.
wait_event_aux text Additional information for the wait event. For example, tablet ID for YB-TServer wait events.
top_level_node_id UUID 16-byte YB-TServer UUID of the YSQL/YCQL node where the query is being executed.
query_id bigint Query ID as seen on the /statements endpoint. This can be used to join with pg_stat_statements/ycql_stat_statements. A known constant for background activities. For example, flush is 2, compaction is 3, and so on.
ysql_session_id bigint YSQL session identifier. Zero for YCQL and background activities.
client_node_ip text Client IP for the RPC. For YSQL, it is the client node from where the query is generated. Null for background activities.
sample_weight float If in any sampling interval there are too many events, YugabyteDB only collects yb_ash_sample_size samples/events. Based on how many were sampled, weights are assigned to the collected events.

For example, if there are 200 events, but only 100 events are collected, each of the collected samples will have a weight of (200 / 100) = 2.0

Wait events

List of wait events by the following request types.

YSQL

These are only the wait events introduced by YugabyteDB, however some of the following wait events inherited from PostgreSQL might also show up in the yb_active_session_history view.

Class Wait Event Wait Event Type Wait Event Aux Description
TServer Wait StorageRead Network Waiting for a DocDB read operation
TServer Wait CatalogRead Network Waiting for a catalog read operation
TServer Wait IndexRead Network Waiting for a secondary index read operation
TServer Wait StorageFlush Network Waiting for a storage flush request
YSQLQuery QueryProcessing CPU Doing CPU work
YSQLQuery yb_ash_metadata LWLock Waiting to update ASH metadata for a query
Timeout YBTxnConflictBackoff Timeout Waiting due to conflict in DocDB

YB-TServer

Class Wait Event Wait Event Type Wait Event Aux Description
Common OnCpu_Passive CPU Waiting for a thread to pick it up
Common OnCpu_Active CPU RPC is being actively processed on a thread
Common ResponseQueued Network Waiting for response to be transferred
Tablet AcquiringLocks Lock <tablet‑id> Taking row-wise locks. May need to wait for other rpcs to release the lock.
Tablet MVCC_WaitForSafeTime Lock <tablet-id> Waiting for the SafeTime to be at least the desired read-time.
Tablet BackfillIndex_WaitForAFreeSlot Lock <tablet-id> Waiting for a slot to open if there are too many backfill requests at the same time.
Tablet CreatingNewTablet I/O <tablet-id> Creating a new tablet may involve writing metadata files, causing I/O wait.
Tablet WaitOnConflictingTxn Lock <tablet-id> Waiting for the conflicting transactions to complete.
Consensus WAL_Append I/O <tablet-id> Persisting Wal edits
Consensus WAL_Sync I/O <tablet-id> Persisting Wal edits
Consensus Raft_WaitingForReplication Network <tablet-id> Waiting for Raft replication
Consensus Raft_ApplyingEdits Lock/CPU <tablet-id> Applying the edits locally
RocksDB BlockCacheReadFromDisk I/O <tablet-id> Populating block cache from disk
RocksDB Flush I/O <tablet-id> Doing RocksDB flush
RocksDB Compaction I/O <tablet-id> Doing RocksDB compaction
RocksDB RateLimiter I/O Slow down due to rate limiter throttling access to disk

YCQL

Class Wait Event Wait Event Type Wait Event Aux Description
YCQLQuery YCQL_Parse CPU CQL call is being actively processed
YCQLQuery YCQL_Read Network <table‑id> Waiting for DocDB read operation
YCQLQuery YCQL_Write Network <table-id> Waiting for DocDB write operation
YBClient LookingUpTablet Network Looking up tablet information
YBClient YBCSyncLeaderMasterRpc Network Waiting on an RPC to the master/master-service
YBClient YBCFindMasterProxy Network Waiting on establishing the proxy to master leader

Examples

Before you start

The examples will run on any YugabyteDB universe.
To create a universe, see Set up YugabyteDB universe.

Make sure you have an active ysqlsh session (./bin/ysqlsh) to run the following examples.

Distribution of wait events for each query_id

Check the distribution of wait events for each query_id, only for the last 20 minutes.

SELECT
    query_id,
    wait_event_component,
    wait_event,
    wait_event_type,
    COUNT(*)
FROM
    yb_active_session_history
WHERE
    sample_time >= current_timestamp - interval '20 minutes'
GROUP BY
    query_id,
    wait_event_component,
    wait_event,
    wait_event_type
ORDER BY
    query_id,
    wait_event_component,
    wait_event_type;

 query_id             | wait_event_component |             wait_event             | wait_event_type | percentage
 ---------------------+----------------------+------------------------------------+-----------------+------------
 -4157456334073660389 | YSQL                 | CatalogRead                        | Network         |     3
 -1970690938654296136 | TServer              | Raft_ApplyingEdits                 | Cpu             |    54
 -1970690938654296136 | TServer              | OnCpu_Active                       | Cpu             |   107
 -1970690938654296136 | TServer              | OnCpu_Passive                      | Cpu             |   144
 -1970690938654296136 | TServer              | RocksDB_NewIterator                | DiskIO          |     6
 -1970690938654296136 | TServer              | ConflictResolution_ResolveConficts | Network         |    18
 -1970690938654296136 | TServer              | Raft_WaitingForReplication         | Network         |   194
 -1970690938654296136 | TServer              | Rpc_Done                           | WaitOnCondition |    18
 -1970690938654296136 | TServer              | MVCC_WaitForSafeTime               | WaitOnCondition |     5
 -1970690938654296136 | YSQL                 | QueryProcessing                    | Cpu             |  1023
                    0 | TServer              | OnCpu_Passive                      | Cpu             |    10
                    0 | TServer              | OnCpu_Active                       | Cpu             |     9
  6107501747146929242 | TServer              | OnCpu_Active                       | Cpu             |   208
  6107501747146929242 | TServer              | RocksDB_NewIterator                | DiskIO          |     5
  6107501747146929242 | TServer              | MVCC_WaitForSafeTime               | WaitOnCondition |    10
  6107501747146929242 | TServer              | Rpc_Done                           | WaitOnCondition |    15
  6107501747146929242 | YSQL                 | QueryProcessing                    | Cpu             |   285
  6107501747146929242 | YSQL                 | StorageRead                        | Network         |   658
  6107501747146929242 | YSQL                 | CatalogRead                        | Network         |     1

Distribution of wait events for each query

As ASH's query_id is the same as pg_stat_statement's queryid, you can join with pg_stat_statements to view the distribution of wait events for each query. This may help in finding what's wrong with a particular query, or determine where most of the time is being spent on. In this example, you can see that in YB-TServer, most of the time is spent on the wait event ConflictResolution_WaitOnConflictingTxns which suggests that there are a lot of conflicts in the DocDB storage layer.

SELECT
    SUBSTRING(query, 1, 50) AS query,
    wait_event_component,
    wait_event,
    wait_event_type,
    COUNT(*)
FROM
    yb_active_session_history
JOIN
    pg_stat_statements
ON
    query_id = queryid
WHERE
    sample_time >= current_timestamp - interval '20 minutes'
GROUP BY
    query,
    wait_event_component,
    wait_event,
    wait_event_type
ORDER BY
    query,
    wait_event_component,
    wait_event_type;

                query                          | wait_event_component |             wait_event                   | wait_event_type | percentage
-----------------------------------------------+----------------------+------------------------------------------+-----------------+------------
 UPDATE test_table set v = v + $1 where k = $2 | TServer              | OnCpu_Passive                            | Cpu             |    46
 UPDATE test_table set v = v + $1 where k = $2 | TServer              | Raft_ApplyingEdits                       | Cpu             |    34
 UPDATE test_table set v = v + $1 where k = $2 | TServer              | OnCpu_Active                             | Cpu             |    39
 UPDATE test_table set v = v + $1 where k = $2 | TServer              | RocksDB_NewIterator                      | DiskIO          |     3
 UPDATE test_table set v = v + $1 where k = $2 | TServer              | ConflictResolution_ResolveConficts       | Network         |    99
 UPDATE test_table set v = v + $1 where k = $2 | TServer              | Raft_WaitingForReplication               | Network         |    38
 UPDATE test_table set v = v + $1 where k = $2 | TServer              | ConflictResolution_WaitOnConflictingTxns | WaitOnCondition |  1359
 UPDATE test_table set v = v + $1 where k = $2 | TServer              | Rpc_Done                                 | WaitOnCondition |     5
 UPDATE test_table set v = v + $1 where k = $2 | TServer              | LockedBatchEntry_Lock                    | WaitOnCondition |   141
 UPDATE test_table set v = v + $1 where k = $2 | YSQL                 | QueryProcessing                          | Cpu             |  1929

Detect a hot shard

In this example, you can see that a particular tablet is getting a lot of requests as compared to the other tablets. The wait_event_aux field contains the tablet_id in case of YB-TServer events.

SELECT
    wait_event_aux AS tablet_id,
    COUNT(*)
FROM
    yb_active_session_history
WHERE
    wait_event_component = 'TServer' AND
    wait_event_aux IS NOT NULL
GROUP BY
    wait_event_aux
ORDER BY
    count DESC;

    tablet_id    | count
-----------------+-------
 09f26a0bb117411 | 33129
 a1d82ef77aa64a8 |  5235
 31bc90e0c59e4da |  2431
 7b49c915e7fe4f1 |  1518
 6b6a264711a84d2 |   403
 96948dbb19674cb |   338
 e112a0dd35994e5 |   320
 f901168f334f432 |   315
 bddebf9b7d9b485 |   310
 04a37ec2cecf49e |    70
 70f6e424970c44c |    66
 77bdebc4f7e3400 |    65
 b4ae6f1115fc4a9 |    63
 8674a0708cba422 |    63
 9cf4fc4a834040d |    61
 e66879054249434 |    61
 c2cfa997bf63463 |    59
 9d64f3479792499 |    58
 e70fd34078e84fe |    58
 8ea1aa0f2e4749a |    56
 b3bbaec3014f4f1 |    53
 d3bbd37828ab422 |    53
 542c6f91ff6a403 |    52
 27780cde5a1b445 |    50
 4a64a9f25e414ce |    44
 09bb0274a41146a |     5
 d58c56ce3fc7458 |     4
 0350744dad944bd |     4
 219fd39bafee44a |     3

You can join with yb_local_tablets to get more information about the table type, table_name, and partition keys. As the wait_event_aux has only the first 15 characters of the tablet_id as a string, you have to join with only the first 15 characters from yb_local_tablets.

SELECT
    tablet_id,
    table_type,
    namespace_name,
    table_name,
    partition_key_start,
    partition_key_end,
    COUNT(*)
FROM
    yb_active_session_history
JOIN
    yb_local_tablets
ON
    wait_event_aux = SUBSTRING(tablet_id, 1, 15)
GROUP BY
    tablet_id,
    table_type,
    namespace_name,
    table_name,
    partition_key_start,
    partition_key_end
ORDER BY
    table_name,
    count DESC;

            tablet_id             | table_type | namespace_name |  table_name  | partition_key_start | partition_key_end | count
----------------------------------+------------+----------------+--------------+---------------------+-------------------+-------
 09f26a0bb117411fa068df13420ea643 | YSQL       | yugabyte       | test_table   |                     | \x2aaa            | 33129
 d58c56ce3fc74584bd2eb892cea51e2a | YSQL       | yugabyte       | test_table   | \x5555              | \x8000            |    10
 0350744dad944bd9ba70c91432c5d8e2 | YSQL       | yugabyte       | test_table   | \xaaaa              | \xd555            |     9
 219fd39bafee44a59117c4089a2f71bf | YSQL       | yugabyte       | test_table   | \x2aaa              | \x5555            |     8
 09bb0274a41146abbb6fe70e41b4f3c1 | YSQL       | yugabyte       | test_table   | \xd555              |                   |     7
 a1d82ef77aa64a85987eef4aa2322c11 | System     | system         | transactions | \xf555              |                   |  7973
 31bc90e0c59e4da5b36e38e9e48554a0 | System     | system         | transactions | \x9555              | \xa000            |  5169
 7b49c915e7fe4f13afdee958028d4446 | System     | system         | transactions | \xb555              | \xc000            |  4256
 6b6a264711a84d25b3226f78b9dd4d6f | System     | system         | transactions |                     | \x0aaa            |   403
 96948dbb19674cb596c7f69177533000 | System     | system         | transactions | \x7555              | \x8000            |   338
 e112a0dd35994e5990b25c4ae8a00eb6 | System     | system         | transactions | \x5555              | \x6000            |   320
 f901168f334f43289007ee8385fedb67 | System     | system         | transactions | \x8aaa              | \x9555            |   315
 bddebf9b7d9b4858b4e502b8a1d93e01 | System     | system         | transactions | \x6aaa              | \x7555            |   310
 04a37ec2cecf49e5bdb974ee80bb5c97 | System     | system         | transactions | \x2000              | \x2aaa            |    73
 70f6e424970c44c391edbbc18225ccb0 | System     | system         | transactions | \x0aaa              | \x1555            |    69
 77bdebc4f7e340068ad3d8c6ccf74b35 | System     | system         | transactions | \xeaaa              | \xf555            |    69
 b4ae6f1115fc4a94b2d9e7aa514b5f28 | System     | system         | transactions | \xe000              | \xeaaa            |    67
 8674a0708cba4228bd1d435a642134bb | System     | system         | transactions | \xaaaa              | \xb555            |    66
 8ea1aa0f2e4749a4802986fefbf54d43 | System     | system         | transactions | \xd555              | \xe000            |    66
 e70fd34078e84fef945f28fe6b004309 | System     | system         | transactions | \x8000              | \x8aaa            |    64
 e66879054249434da01b3e7a314b983c | System     | system         | transactions | \x4000              | \x4aaa            |    63
 9d64f34797924998911922563d3ad0ec | System     | system         | transactions | \xa000              | \xaaaa            |    63
 9cf4fc4a834040df91987b26bf9831ed | System     | system         | transactions | \x4aaa              | \x5555            |    63
 c2cfa997bf634637880137870cee25a1 | System     | system         | transactions | \xcaaa              | \xd555            |    61
 d3bbd37828ab4225a68bf4dd54924138 | System     | system         | transactions | \x1555              | \x2000            |    56
 b3bbaec3014f4f1aa01e04b42c5f40c7 | System     | system         | transactions | \x3555              | \x4000            |    56
 542c6f91ff6a403399ddf46e4d5f29bb | System     | system         | transactions | \x6000              | \x6aaa            |    56
 27780cde5a1b445d83ff83c865b9bea5 | System     | system         | transactions | \xc000              | \xcaaa            |    51
 4a64a9f25e414ce7a649be2e6d24c7ee | System     | system         | transactions | \x2aaa              | \x3555            |    46

You can see that only a single tablet of the table test_table is getting most of the requests, and you have the partition range of that particular tablet.

Distribution of the type of the wait events for each component

Detect where most time is being spent to help understand if the issue is related to disk IO, network operations, waiting for a condition or lock, or intense CPU work.

SELECT
    wait_event_component,
    wait_event_type,
    COUNT(*)
FROM
    yb_active_session_history
GROUP BY
    wait_event_component,
    wait_event_type
ORDER BY
    wait_event_component,
    count;

 wait_event_component | wait_event_type | count
----------------------+-----------------+-------
 TServer              | WaitOnCondition |    47
 TServer              | Network         |   910
 TServer              | Cpu             |  2665
 TServer              | DiskIO          |  8193
 YSQL                 | LWLock          |     1
 YSQL                 | Cpu             |  1479
 YSQL                 | Network         |  4575

Detect which client/application is sending the most amount of queries

Suppose you have a rogue application which is sending a lot of queries, you can identify the application using the following example query:

SELECT
    client_node_ip,
    COUNT(*)
FROM
    yb_active_session_history
WHERE
    client_node_ip IS NOT NULL
GROUP BY
    client_node_ip;

 client_node_ip  |  count
-----------------+-------
 127.0.0.2:56471 |    92
 127.0.0.1:56473 |   106
 127.0.0.1:56477 |    91
 127.0.0.2:56481 |    51
 127.0.0.3:56475 |    53
 127.0.0.3:56485 |    18
 127.0.0.3:56479 | 10997