Oct18

Slow queries logging in Scylla

Subscribe to Our Blog

Motivation

Many times in real life installations, one of the most important parameters of the system is the longest response time. Naturally, the shorter, the better. Therefore capturing the request that took a long time and understanding why it took it so long is a very critical and challenging task. Slow query tracing to the rescue!

Example

One of the common problems of ill-formed queries is that a query has to get to the remote Data Center in order to achieve a required consistency level.

Let’s see how Slow Query Logging is going to help us catch such problems.

Let’s create a clear cluster in an Amazon AWS environment with 3 Nodes in a us-east time zone and 3 in us-west time zone. We will use Ec2MultiRegionSnitch for simplicity:

Then lets create a keyspace and a table for the demonstration. We’ll run cqlsh here and after from a Node with an address 50.19.22.61:

Let’s add a row to it:

Let’s enable the Slow Query Logging:

Now let’s read the row above with the “bad” consistency level: QUORUM

Now let’s stop the Slow Query Logging:

Let’s see if we have anything in the system_traces.node_slow_log:

Gotcha!!!
Now let’s check what actually had happen there. Let’s see the corresponding records in system_traces.sessions and system_traces.events tables:

If we look at the traces above we may immediately see that one of the targets of this query is a Node 54.67.34.6 from the remote DC. We see then that 50.19.22.61 (our Coordinator from us-east DC) sends a digest request to 54.67.34.6 from us-west and it takes 211375us till the response arrives.

That was clearly a reason why that query was so slow. – Problem found!

A fix for this problem may be choosing a different CL, e.g. LOCAL_QUORUM.

If we run all the steps above but choose a consistency level LOCAL_QUORUM instead of QUORUM we will notice that there wouldn’t be any new entry added to the system_traces.node_slow_log and that’s why:

1243us!!! As you may see – it’s an absolutely different story!.. 😉

Final notes

Unlike other databases, we have decided not to hold back such an important functionality and to provide this in our open source version. Query trace is a basic feature, almost as queries themselves. Additionally, we went all-in and we trace not just the culprit query but all of the intermediate timing traces which help to realize why the query is slow. It’s not enough to have a separate detailed- trace mechanism. In many cases, the same query execution is not going to reproduce the long latency that was caused the query to be recorded as slow in the first place. Therefore we trace both the query and its execution trace.

This, of course, doesn’t come for free.
On AWS cluster with 3 c3.8xlarge Nodes when a Slow Query Logging was enabled with a really huge threshold the throughout in a standard cassandra-stress read test behaved as follows (number of threads was controlled with a `-rate threads=N parameter):

  • for a single thread test dropped 0.5%: from 903.2 to 898.6 ops/sec
  • for 250 threads test dropped 5.09%: from 116314.13 to 110390.63 ops/sec
  • for 500 threads test dropped 17.6%: from 176246.63 to 145297.75 ops/sec

The latency wasn’t influenced at all: 1.1 ms (measured in a single thread test).

Naturally, the more loaded CPU-wise the system is, the heavier is a penalty for extra CPU the Slow Query Logging requires.

So, although the feature is disabled by default, it’s quite safe to enable it on systems where each shard is not more than 50%-60% loaded (use scyllatop "*reactor*load*" to verify that).

node_slow_log table schema

Below is a description of system_traces.node_slow_log schema and its columns.

Columns description

  • start_time and date: time when the query has began
  • node_ip: Address of a Coordinator Node
  • shard: shard ID on a Coordinator, where the query has been handled
  • command: the query command, e.g. select * from my_ks.my_cf
  • duration: the duration of a query handling in microseconds
  • parameters: query parameters like a parameters column in a system_traces.sessions table
  • session_id: the corresponding Tracing session ID
  • source_ip: Address of a Client that sent this query
  • table_names: a list of tables used for this query, where applicable
  • username: a user name used for authentication with this query

How to enable and configure

By default slow query logging is disabled.
There is a REST API that allows configuring and querying the current configuration of this feature.
To set the parameters run:

curl -X POST --header "Content-Type: application/json" --header "Accept: application/json" "http://<Node's address>:10000/storage_service/slow_query?enable=<true|false>&ttl=<in seconds>&threshold=<threshold in microseconds>"

e.g. in order to enable the feature on a Node with an address 127.0.0.1, set the ttl to 86000s and a threshold to 10000us:

curl -X POST --header "Content-Type: application/json" --header "Accept: application/json" "http://127.0.0.1:10000/storage_service/slow_query?enable=true&ttl=86000&threshold=10000"

To get the current configuration run:

curl -X GET --header "Content-Type: application/json" --header "Accept: application/json" "http://<Node's address>:10000/storage_service/slow_query"

e.g. after the POST command above the query result will look as below:

$ curl -X GET --header "Content-Type: application/json" --header "Accept: application/json" "http://127.0.0.1:10000/storage_service/slow_query"
{"threshold": 10000, "enable": true, "ttl": 86000}

$

Vlad ZolotarovAbout Vlad Zolotarov

Vlad specializes in networking, mostly L2. He has worked at on projects for Mellanox, the bnx2x Linux device driver for Broadcom, and on the ScaleMP Virtual Device System for network interfaces. Vlad studied at the Israel Institute of Technology (Technion) and holds a B.Sc. in Computer Science.


Tags: cql, deep-dive, monitoring, tracing