Tx-Stats
Background
Accruing a set of datoms to transact to a database value can require, for each datom, resolving its entity ID, checking a unique value, and generating a composite tuple. Transactions can also express sets of datoms via transaction function shorthands, which must be expanded to primitive list forms. Each redundant datom (about existing entities) is eliminated, and novel datoms may generate a corresponding retraction. Together, these tasks can take time because they need to read information from the given database value.
Problem
To design and maintain high performance systems, it is important to understand the fine-grained costs of applying each transaction. io-stats measures the index reads for transaction processing, i.e. the physical effects, but it is difficult to reason backwards from the effects to their semantic cause.
Approach: Tx Stats
Datomic logs a :tx-stats map for every transaction. This map contains metrics describing the work performed to accrue a set of datoms, including counts of datoms and processing durations.
Tx-Stats does not include metrics about making a transaction durable, e.g. writing it to the log.
Everything about tx-stats is alpha and subject to change in future releases.
2024-06-01 05:16:29.440 INFO default datomic.transaction - {:tid 178, :txid #uuid "665aae9f-b8b5-4eb2-a3a2-0871c520bdac", :datom-count 108, :apply-msec 1.63, :io-stats {:api :tx-with, :io-context :my-barrel/tx, :api-ms 1.61, :reads {:avet 80, :aevt 57, :eavt 3, :dir 96, :ocache 236}}, :pid 43974, :event :tx/process, :msec 23.9, :t 33278227008, :tx-stats {:dedup-tx-ms 0.15, :tx-fn-ms 0.0, :dedup-pf-ms 0.3, :comp-tx-ms 0.0, :dup-datoms 16, :res-pf-ms 0.45, :ucheck-ct 2, :considered-datoms 127, :comp-ct 0, :ucheck-tx-ms 0.02, :ucheck-pf-ms 0.02, :dedup-ct 19, :comp-pf-ms 0.0, :res-tx-ms 0.34, :res-ct 26}}
In Cloud, tx-stats appear under the “TxStats” key of the “TxSucceeded” message, with all keys converted to CloudWatch JSON Pascal case conventions, e.g.:
{ "Msg": "TxSucceeded", "DbId": "7e29bec5-a1fe-4f8f-b46e-60ebd30acf1f", "T": 1007523406, "IoStats": { "IoContext": "MyAppTransaction", "Api": "TxWith", "ApiMs": 3.75, "Reads": { "Avet": 10, "InflightLookupMs": 2.02, "Aevt": 3, "Ocache": 13 } }, "TxStats": { "DedupTxMs": 0.14, "TxFnMs": 0.0, "DedupPfMs": 0.37, "CompTxMs": 0.0, "DupDatoms": 2, "ResPfMs": 4.24, "UcheckCt": 2, "ConsideredDatoms": 65, "CompCt": 0, "UcheckTxMs": 0.02, "UcheckPfMs": 0.04, "DedupCt": 8, "CompPfMs": 0.0, "ResTxMs": 2.32, "ResCt": 17 }, "Type": "Event", "Tid": 559, "Timestamp": 1717466409767 }
The Tx-Stats Map
The tx-stats map can have at least the following keys:
Key | Semantic | Unit |
---|---|---|
:res-ct | number of datoms considered having :db.unique/identity attributes | datoms |
:res-pf-ms | sum of time spent prefetching the resolution of unique identities | millis |
:res-tx-ms | sum of time spent on transaction thread resolving unique identities | millis |
:comp-ct | number of datoms with composite tuple attrs generated | datoms |
:comp-pf-ms | sum of time spent prefetching the constituents of composite tuples | millis |
:comp-tx-ms | sum of time spent on transaction thread looking up the constituents of composite tuples | millis |
:dedup-ct | number of datoms that needed to be checked for redundancy | datoms |
:dedup-pf-ms | sum of time spent prefetching redundancy checks | millis |
:dedup-tx-ms | sum of time spent on transaction thread checking redundancy | millis |
:ucheck-ct | number of datoms with whose values need to be checked for uniqueness | datoms |
:ucheck-pf-ms | sum of time spent prefetching uniqueness checks | millis |
:ucheck-tx-ms | sum of time spent on transaction thread checking uniqueness | millis |
:tx-fn-ms | sum of time spent expanding transaction fns | millis |
:dup-datoms | number of datoms redundant with the db-before | datoms |
:considered-datoms | number of datoms considered in transaction | datoms |
The tx-stats map is open to extension at any time, and you may see additional keys not documented here.