Full Query Logging

Apache Cassandra 4.0 adds a new highly performant feature that supports live query logging (CASSANDRA-13983). FQL is safe for production use, with configurable limits to heap memory and disk space to prevent out-of-memory errors. This feature is useful for live traffic capture, as well as traffic replay. The tool provided can be used for both debugging query traffic and migration. New nodetool options are also added to enable, disable or reset FQL, as well as a new tool to read and replay the binary logs. The full query logging (FQL) capability uses Chronicle-Queue to rotate a log of queries. Full query logs will be referred to as logs for the remainder of the page.

Some of the features of FQL are:

  • The impact on query latency is reduced by asynchronous single-thread log entry writes to disk.

  • Heap memory usage is bounded by a weighted queue, with configurable maximum weight sitting in front of logging thread.

  • If the weighted queue is full, producers can be blocked or samples can be dropped.

  • Disk utilization is bounded by a configurable size, deleting old log segments once the limit is reached.

  • A flexible schema binary format, Chronicle-Wire, for on-disk serialization that can skip unrecognized fields, add new ones, and omit old ones.

  • Can be enabled, disabled, or reset (to delete on-disk data) using the JMX tool, nodetool.

  • Can configure the settings in either the cassandra.yaml file or by using nodetool.

  • Introduces new fqltool that currently can Dump the binary logs to a readable format. Other options are Replay and Compare.

FQL logs all successful Cassandra Query Language (CQL) requests, both events that modify the data and those that query. While audit logs also include CQL requests, FQL logs only the CQL request. This difference means that FQL can be used to replay or compare logs, which audit logging cannot. FQL is useful for debugging, performance benchmarking, testing and auditing CQL queries, while audit logs are useful for compliance.

In performance testing, FQL appears to have little or no overhead in WRITE only workloads, and a minor overhead in MIXED workload.

Query information logged

The query log contains:

  • all queries invoked

  • approximate time they were invoked

  • any parameters necessary to bind wildcard values

  • all query options

The logger writes single or batched CQL queries after they finish, so only successfully completed queries are logged. Failed or timed-out queries are not logged. Different data is logged, depending on the type of query.

A single CQL query log entry contains:

  • query - CQL query text

  • queryOptions - Options associated with the query invocation

  • queryState - Timestamp state associated with the query invocation

  • queryTimeMillis - Approximate time in milliseconds since the epoch since the query was invoked

A batch CQL query log entry contains:

  • queries - CQL text of the queries

  • queryOptions - Options associated with the query invocation

  • queryState - Timestamp state associated with the query invocation

  • batchTimeMillis - Approximate time in milliseconds since the epoch since the batch was invoked

  • type - The type of the batch

  • values - Values to bind to as parameters for the queries

Because FQL is backed by Binlog, the performance and footprint are predictable, with minimal impact on log record producers. Performance safety prevents the producers from overloading the log, using a weighted queue to drop records if the logging falls behind. Single-thread asynchronous writing produces the logs. Chronicle-Queue provides an easy method of rolling the logs.

Logging information logged

FQL also tracks information about the stored log files:

  • Stored log files that are added and their storage impact. Deletes them if over storage limit.

  • The log files in Chronicle-Queue that have already rolled

  • The number of bytes in the log files that have already rolled

Logging sequence

The logger follows a well-defined sequence of events:

  1. The consumer thread that writes log records is started. This action can occur only once.

  2. The consumer thread offers a record to the log. If the in-memory queue is full, the record will be dropped and offer returns a false value.

  3. If accepted, the record is entered into the log. If the in-memory queue is full, the putting thread will be blocked until there is space or it is interrupted.

  4. The buffers are cleaned up at thread exit. Finalization will check again, to ensure there are no stragglers in the queue.

  5. The consumer thread is stopped. It can be called multiple times.

Using FQL

To use FQL, two actions must be completed. FQL must be configured using either the cassandra.yaml file or nodetool, and logging must be enabled using nodetool enablefullquerylog. With either method, at a minimum, the path to the log directory must be specified. Both actions are completed on a per-node basis. Full query logs are generated on each enabled node, so logs on each node will have that node’s queries.

Configuring FQL in cassandra.yaml

The cassandra.yaml file can be used to configure FQL before enabling the feature with nodetool.

The file includes the following options that can be uncommented for use:

  1. # default options for full query logging - these can be overridden from command line
  2. # when executing nodetool enablefullquerylog
  3. #full_query_logging_options:
  4.    # log_dir:
  5.    # roll_cycle: HOURLY
  6.    # block: true
  7.    # max_queue_weight: 268435456 # 256 MiB
  8.    # max_log_size: 17179869184 # 16 GiB
  9.    # archive command is "/path/to/script.sh %path" where %path is replaced with the file being rolled:
  10.    # archive_command:
  11.    # max_archive_retries: 10

log_dir

To write logs, an existing directory must be set in log_dir.

The directory must have appropriate permissions set to allow reading, writing, and executing. Logging will recursively delete the directory contents as needed. Do not place links in this directory to other sections of the filesystem. For example, log_dir: /tmp/cassandrafullquerylog.

roll_cycle

The roll_cycle defines the frequency with which the log segments are rolled. Supported values are HOURLY (default), MINUTELY, and DAILY. For example: roll_cycle: DAILY

block

The block option specifies whether FQL should block writing or drop log records if FQL falls behind. Supported boolean values are true (default) or false. For example: block: false to drop records

max_queue_weight

The max_queue_weight option sets the maximum weight of in-memory queue for records waiting to be written to the file before blocking or dropping. The option must be set to a positive value. The default value is 268435456, or 256 MiB. For example, to change the default: max_queue_weight: 134217728 # 128 MiB

max_log_size

The max_log_size option sets the maximum size of the rolled files to retain on disk before deleting the oldest file. The option must be set to a positive value. The default is 17179869184, or 16 GiB. For example, to change the default: max_log_size: 34359738368 # 32 GiB

archive_command

The archive_command option sets the user-defined archive script to execute on rolled log files. When not defined, files are deleted, with the default "" which then maps to org.apache.cassandra.utils.binlog.DeletingArchiver. For example: archive_command: /usr/local/bin/archiveit.sh %path # %path is the file being rolled

max_archive_retries

The max_archive_retries option sets the max number of retries of failed archive commands. The default is 10. For example: max_archive_retries: 10

FQL can also be configured using nodetool when enabling the feature, and will override any values set in the cassandra.yaml file, as discussed in the next section.

Enabling FQL

FQL is enabled on a per-node basis using the nodetool enablefullquerylog command. At a minimum, the path to the logging directory must be defined, if log_dir is not set in the cassandra.yaml file.

The syntax of the nodetool enablefullquerylog command has all the same options that can be set in the cassandra.yaml file. In addition, nodetool has options to set which host and port to run the command on, and username and password if the command requires authentication.

  1.   nodetool [(-h <host> | --host <host>)] [(-p <port> | --port <port>)]
  2.  [(-pp | --print-port)] [(-pw <password> | --password <password>)]
  3.  [(-pwf <passwordFilePath> | --password-file <passwordFilePath>)]
  4.  [(-u <username> | --username <username>)] enablefullquerylog
  5.  [--archive-command <archive_command>] [--blocking]
  6.  [--max-archive-retries <archive_retries>]
  7.  [--max-log-size <max_log_size>] [--max-queue-weight <max_queue_weight>]
  8.  [--path <path>] [--roll-cycle <roll_cycle>]
  10.  OPTIONS
  11.    --archive-command <archive_command>
  12.   Command that will handle archiving rolled full query log files.
  13.   Format is "/path/to/script.sh %path" where %path will be replaced
  14.   with the file to archive
  16.    --blocking
  17.   If the queue is full whether to block producers or drop samples.
  19.    -h <host>, --host <host>
  20.   Node hostname or ip address
  22.    --max-archive-retries <archive_retries>
  23.   Max number of archive retries.
  25.    --max-log-size <max_log_size>
  26.   How many bytes of log data to store before dropping segments. Might
  27.   not be respected if a log file hasn't rolled so it can be deleted.
  29.    --max-queue-weight <max_queue_weight>
  30.   Maximum number of bytes of query data to queue to disk before
  31.   blocking or dropping samples.
  33.    -p <port>, --port <port>
  34.   Remote jmx agent port number
  36.    --path <path>
  37.   Path to store the full query log at. Will have it's contents
  38.   recursively deleted.
  40.    -pp, --print-port
  41.   Operate in 4.0 mode with hosts disambiguated by port number
  43.    -pw <password>, --password <password>
  44.   Remote jmx agent password
  46.    -pwf <passwordFilePath>, --password-file <passwordFilePath>
  47.   Path to the JMX password file
  49.    --roll-cycle <roll_cycle>
  50.   How often to roll the log file (MINUTELY, HOURLY, DAILY).
  52.    -u <username>, --username <username>
  53.   Remote jmx agent username

To enable FQL, run the following command on each node in the cluster on which you want to enable logging:

  1. $ nodetool enablefullquerylog --path /tmp/cassandrafullquerylog

Disabling or resetting FQL

Use the nodetool disablefullquerylog to disable logging. Use nodetool resetfullquerylog to stop FQL and clear the log files in the configured directory. IMPORTANT: Using nodetool resetfullquerylog will delete the log files! Do not use this command unless you need to delete all log files.

fqltool

The fqltool command is used to view (dump), replay, or compare logs. fqltool dump converts the binary log files into human-readable format; only the log directory must be supplied as a command-line option.

fqltool replay (CASSANDRA-14618) enables replay of logs. The command can run from a different machine or cluster for testing, debugging, or performance benchmarking. The command can also be used to recreate a dropped database object. Use fqltool replay to record and compare different runs of production traffic against different versions/configurations of Cassandra or different clusters. Another use is to gather logs from several machines and replay them in “order” by the timestamps recorded.

The syntax of fqltool replay is:

  1.   fqltool replay [--keyspace <keyspace>] [--results <results>]
  2.  [--store-queries <store_queries>] --target <target>... [--] <path1>
  3.  [<path2>...<pathN>]
  5.  OPTIONS
  6.    --keyspace <keyspace>
  7.   Only replay queries against this keyspace and queries without
  8.   keyspace set.
  10.    --results <results>
  11.   Where to store the results of the queries, this should be a
  12.   directory. Leave this option out to avoid storing results.
  14.    --store-queries <store_queries>
  15.   Path to store the queries executed. Stores queries in the same order
  16.   as the result sets are in the result files. Requires --results
  18.    --target <target>
  19.   Hosts to replay the logs to, can be repeated to replay to more
  20.   hosts.
  22.    --
  23.   This option can be used to separate command-line options from the
  24.   list of argument, (useful when arguments might be mistaken for
  25.   command-line options
  27.    <path1> [<path2>...<pathN>]
  28.   Paths containing the FQ logs to replay.

fqltool compare (CASSANDRA-14619) compares result files generated by fqltool replay. The command uses recorded runs from fqltool replay and compareslog, outputting any differences (potentially all queries). It also stores each row as a separate chronicle document to avoid reading the entire result from in-memory when comparing.

The syntax of fqltool compare is:

  1.    fqltool compare --queries <queries> [--] <path1> [<path2>...<pathN>]
  3.  OPTIONS
  4.    --queries <queries>
  5.   Directory to read the queries from. It is produced by the fqltool
  6.   replay --store-queries option.
  8.    --
  9.   This option can be used to separate command-line options from the
  10.   list of argument, (useful when arguments might be mistaken for
  11.   command-line options
  13.    <path1> [<path2>...<pathN>]
  14.   Directories containing result files to compare.

The comparison sets the following marks:

  • Mark the beginning of a query set:
  1.   version: int16
  2.   type: column_definitions
  3.   column_count: int32;
  4.   column_definition: text, text
  5.   column_definition: text, text
  6.   ....
  • Mark a failed query set:
  1.   version: int16
  2.   type: query_failed
  3.   message: text
  • Mark a row set:
  1.   version: int16
  2.   type: row
  3.   row_column_count: int32
  4.   column: bytes
  • Mark the end of a result set:
  1.   version: int16
  2.   type: end_resultset

Example

  1. To demonstrate FQL, first configure and enable FQL on a node in your cluster:
  1. $ nodetool enablefullquerylog --path /tmp/cassandrafullquerylog
  1. Now create a demo keyspace and table and insert some data using cqlsh:
  1.  cqlsh> CREATE KEYSPACE querylogkeyspace
  2.    ... WITH replication = {'class': 'SimpleStrategy', 'replication_factor' : 1};
  3.  cqlsh> USE querylogkeyspace;
  4.  cqlsh:querylogkeyspace> CREATE TABLE t (
  5.  ...id int,
  6.  ...k int,
  7.  ...v text,
  8.  ...PRIMARY KEY (id)
  9.  ... );
  10.  cqlsh:querylogkeyspace> INSERT INTO t (id, k, v) VALUES (0, 0, 'val0');
  11.  cqlsh:querylogkeyspace> INSERT INTO t (id, k, v) VALUES (0, 1, 'val1');
  1. Then check that the data is inserted:
  1.  cqlsh:querylogkeyspace> SELECT * FROM t;
  3.  id | k | v
  4.  ----+---+------
  5.   0 | 1 | val1
  7.  (1 rows)
  1. Use the fqltool dump command to view the logs.
  1. $ fqltool dump /tmp/cassandrafullquerylog

This command will return a readable version of the log. Here is a partial sample of the log for the commands in this demo:

  1. WARN  [main] 2019-08-02 03:07:53,635 Slf4jExceptionHandler.java:42 - Using Pauser.sleepy() as not enough processors, have 2, needs 8+
  2.       Type: single-query
  3.       Query start time: 1564708322030
  4.       Protocol version: 4
  5.       Generated timestamp:-9223372036854775808
  6.       Generated nowInSeconds:1564708322
  7.       Query: SELECT * FROM system.peers
  8.       Values:
  10.       Type: single-query
  11.       Query start time: 1564708322054
  12.       Protocol version: 4
  13.       Generated timestamp:-9223372036854775808
  14.       Generated nowInSeconds:1564708322
  15.       Query: SELECT * FROM system.local WHERE key='local'
  16.       Values:
  18.       Type: single-query
  19.       Query start time: 1564708322109
  20.       Protocol version: 4
  21.       Generated timestamp:-9223372036854775808
  22.       Generated nowInSeconds:1564708322
  23.       Query: SELECT * FROM system_schema.keyspaces
  24.       Values:
  26.       Type: single-query
  27.       Query start time: 1564708322116
  28.       Protocol version: 4
  29.       Generated timestamp:-9223372036854775808
  30.       Generated nowInSeconds:1564708322
  31.       Query: SELECT * FROM system_schema.tables
  32.       Values:
  34.       Type: single-query
  35.       Query start time: 1564708322139
  36.       Protocol version: 4
  37.       Generated timestamp:-9223372036854775808
  38.       Generated nowInSeconds:1564708322
  39.       Query: SELECT * FROM system_schema.columns
  40.       Values:
  42.       Type: single-query
  43.       Query start time: 1564708322142
  44.       Protocol version: 4
  45.       Generated timestamp:-9223372036854775808
  46.       Generated nowInSeconds:1564708322
  47.       Query: SELECT * FROM system_schema.functions
  48.       Values:
  50.       Type: single-query
  51.       Query start time: 1564708322141
  52.       Protocol version: 4
  53.       Generated timestamp:-9223372036854775808
  54.       Generated nowInSeconds:1564708322
  55.       Query: SELECT * FROM system_schema.aggregates
  56.       Values:
  58.       Type: single-query
  59.       Query start time: 1564708322143
  60.       Protocol version: 4
  61.       Generated timestamp:-9223372036854775808
  62.       Generated nowInSeconds:1564708322
  63.       Query: SELECT * FROM system_schema.types
  64.       Values:
  66.       Type: single-query
  67.       Query start time: 1564708322144
  68.       Protocol version: 4
  69.       Generated timestamp:-9223372036854775808
  70.       Generated nowInSeconds:1564708322
  71.       Query: SELECT * FROM system_schema.indexes
  72.       Values:
  74.       Type: single-query
  75.       Query start time: 1564708322145
  76.       Protocol version: 4
  77.       Generated timestamp:-9223372036854775808
  78.       Generated nowInSeconds:1564708322
  79.       Query: SELECT * FROM system_schema.views
  80.       Values:
  82.       Type: single-query
  83.       Query start time: 1564708345408
  84.       Protocol version: 4
  85.       Generated timestamp:-9223372036854775808
  86.       Generated nowInSeconds:-2147483648
  87.       Query: CREATE KEYSPACE querylogkeyspace
  88.       WITH replication = {'class': 'SimpleStrategy', 'replication_factor' : 1};
  89.       Values:
  91.       Type: single-query
  92.       Query start time: 1564708360873
  93.       Protocol version: 4
  94.       Generated timestamp:-9223372036854775808
  95.       Generated nowInSeconds:-2147483648
  96.       Query: USE querylogkeyspace;
  97.       Values:
  99.       Type: single-query
  100.       Query start time: 1564708360874
  101.       Protocol version: 4
  102.       Generated timestamp:-9223372036854775808
  103.       Generated nowInSeconds:-2147483648
  104.       Query: USE "querylogkeyspace"
  105.       Values:
  107.       Type: single-query
  108.       Query start time: 1564708378837
  109.       Protocol version: 4
  110.       Generated timestamp:-9223372036854775808
  111.       Generated nowInSeconds:-2147483648
  112.       Query: CREATE TABLE t (
  113.           id int,
  114.           k int,
  115.           v text,
  116.           PRIMARY KEY (id)
  117.       );
  118.       Values:
  120.       Type: single-query
  121.       Query start time: 1564708379247
  122.       Protocol version: 4
  123.       Generated timestamp:-9223372036854775808
  124.       Generated nowInSeconds:1564708379
  125.       Query: SELECT * FROM system_schema.tables WHERE keyspace_name = 'querylogkeyspace' AND table_name = 't'
  126.       Values:
  128.       Type: single-query
  129.       Query start time: 1564708397144
  130.       Protocol version: 4
  131.       Generated timestamp:-9223372036854775808
  132.       Generated nowInSeconds:1564708397
  133.       Query: INSERT INTO t (id, k, v) VALUES (0, 0, 'val0');
  134.       Values:
  136.       Type: single-query
  137.       Query start time: 1564708434782
  138.       Protocol version: 4
  139.       Generated timestamp:-9223372036854775808
  140.       Generated nowInSeconds:1564708434
  141.       Query: SELECT * FROM t;
  142.       Values:
  1. To demonstrate fqltool replay, first drop the keyspace.
  1. cqlsh:querylogkeyspace> DROP KEYSPACE querylogkeyspace;
  1. Now run fqltool replay specifying the directories in which to store the results of the queries and the list of queries run, respectively, in --results and --store-queries:
  1. $ fqltool replay \
  2. --keyspace querylogkeyspace --results /cassandra/fql/logs/results/replay \
  3. --store-queries /cassandra/fql/logs/queries/replay \
  4. -- target 3.91.56.164 \
  5. /tmp/cassandrafullquerylog

The --results and --store-queries directories are optional, but if --store-queries is set, then --results must also be set. The --target specifies the node on which to replay to logs.

  1. Check that the keyspace was replayed and exists again using the DESCRIBE KEYSPACES command:
  1.  cqlsh:querylogkeyspace> DESC KEYSPACES;
  3.  system_schema  system  system_distributed  system_virtual_schema
  4.  system_auth    querylogkeyspace  system_traces  system_views