Io-Stats

Any application or task has a working set of data. Where that data is located/cached is an important part of architecting a system; a well-architected system has to plan for moving through tiers of cache. Otherwise, applications will encounter unexpected and dramatically different performance when data accesses spill over to the next tier. In Datomic, this can happen when there is too much reliance on increasing the first tier object cache (an in-memory cache of Java objects) to handle the entire working set.

To plan for moving through tiers of cache, developers need to understand the capacity and latency of each tier. Then for a given API call, they need to know where (in which tier) data is coming from, what part of the application called the API, and why the API needs that particular data.

In Datomic Pro, the transactor uses indexes to enforce invariants, e.g. AVET for uniqueness checks, and AEVT for cardinality and redundancy elimination. The query engine chooses a suitable index sort for each relational clause. These operations nest – both transactions and queries can call other queries and so on.

Before io-stats, Datomic APIs did not provide direct access to I/O information, forcing developers to reason backward from downstream effects, e.g. inferring that a query is spilling into the next cache tier when it performs very differently from other superficially similar queries.

Io-stats summarizes the input and output (I/O) associated with a Datomic API call. Io-stats allows you to analyze where data is coming from, providing counts and latencies for index segments accessed from each tier. Io-stats shows what API call was made, and supports a user-provided io-context to distinguish different operations. And finally, io-stats provides some help with why, telling you the count of each different index sort order (:aevt/:avet/:eavt/:vaet).

Io-stats are reported as a Clojure map, described in detail below. Io-stats are logged automatically for transactions, and you can explicitly request io-stats be returned from various transaction and query APIs.

Datomic logs an io-stats map for every transaction. In Datomic Pro, io-stats are logged under the :tx/process :event, as shown below:

2022-03-29 23:16:26.567 INFO  default    datomic.transaction - {:tid 115,
:txid #uuid "6243cb8a-2b3c-4031-a4cd-8c7df49e3981",
:datom-count 1, :apply-msec 4.71, :pid 76957,
:io-stats {:api :tx, :api-ms 5 :reads {:ocache 2}},
:event :tx/process, :msec 16.0, :t 1008}

In Cloud, io-stats are logged under the “TxSucceeded” message, with all keys converted to CloudWatch JSON Pascal case conventions, e.g.:

{
    "Msg": "TxSucceeded",
    "DbId": "5644c1a8-aedc-44c6-9e70-1b9a3b035326",
    "T": 6,
    "IoStats": {
	"IoContext": "DbTx",
	"Api": "TxWith",
	"ApiMs": 4.86,
	"Reads": {
	    "Avet": 2,
	    "Aevt": 3,
	    "ValcacheDirectMs": 0.14,
	    "Ocache": 5,
	    "ValcacheDirect": 2
	}
    },
    "Type": "Event",
    "Tid": 249,
    "Timestamp": 1665667355838
}

You can search for io-stats in the Cloudwatch console with e.g. {$.Msg=”TxSucceeded”}.

Note that transaction logging correlates io-stats with transaction t. Given t, you can use the log API to query the datoms produced by the transaction.

You can request that io-stats be included in the map returned from transact by adding :io-context as a trailing arg to transact:

(d/transact conn {:tx-data [...] :io-context :tx/example})

=> ;; tx result will include :io-stats key

The query, qseq, pull, and pull-many APIs all include arities that allow you to pass :io-context, a qualified keyword that you can use to distinguish different domain operations. When you pass :io-context, Datomic will return a map with :ret (the query result) and :io-stats (an io-stats map).

For example, the following query includes :io-context:

(d/q {:query '[:find (count ?a)
                   :in $ ?aname
                   :where [?a :artist/name ?aname]]
          :args [db "The Beatles"]
          :io-context :artist/by-name})

{:io-stats {:io-context :artist/by-name,
            :api :query,
            :api-ms 105.08,
            :reads {:dir 1,
                    :avet 2,
                    :valcache-direct 2,
                    :efs 2,
                    :efs-ms 26.27,
                    :valcache 2,
                    :dir-load 1,
                    :valcache-ms 50.57,
                    :avet-load 2,
                    :ocache 2}},
 :ret [[1]]}

The io-stats for a top-level API include the total I/O for all nested calls. Often, you will also want to know the io-stats breakdown for nested calls, if any. For example, when tuning the performance of a transaction function that issues two queries, you could focus your efforts if you knew from nested io-stats that one of the queries dominates overall performance.

When nested API calls have an :io-context, the io-stats for nested calls are aggregated by :io-context under the :nested key. For example, imagine that a transaction with :io-context of :transfer/funds calls a query with :io-context of :transfer/check-balance twice and a query with :transfer/check-auth once. The transaction returns (and logs) an io-stats map with the following shape:

{:io-context :transfer/funds
 :reads ;; totals for entire tx
 :nested
 {:transfer/check-balance
  ;; io-stats map that sums across 2 calls to check-balance
  :transfer/check-auth
  ;; io-stats map of the one call to check-auth
  }}

The io-stats map can have at least the following keys at the top level:

The io-stats map and its submaps are open to extension at any time, and you may see additional keys not documented here.

To get the most benefit from io-stats, you should look at them under realistic load, either from production logs or from simulated load in a test environment. Realistic load is important because io-stats depend not just on the API and database but also on the current state of the caches and indexes, as described below.

The tx-with time reported by io-stats is only one component of the total transaction time experienced by a caller, which is the sum of:

• Interprocess communication time if requesting and transacting processes are not the same (e.g. Datomic Pro peers and transactors)
• Time queued on the transacting process
• The io-stats tx-with time (applying the transaction, enforcing invariants)
• Storage write time

To measure total transaction time, time calls to transact from Datomic peers or clients.

The transactor time includes everything that can be measured from the transacting process, i.e. everything except interprocess communication. The Datomic Pro transactor logs this time under the :msec key of the :tx/process event.

The tx-with time reported by transaction io-stats isolates the time actually spent processing the transaction. Note that if you improve the tx-with time for a transaction, you also improve the transactor time for any other concurrent transactions enqueued behind it.

The different measures of transaction time are summarized in the table below: