CODEWITHSUNDEEP
cassandratracedatastax
Rajib Deb
Rajib Deb

Reputation: 1774

Query tracing in Cassandra

Since, I could not find a query explain type of feature, I wrote the below python program to list the different phases the query is going through. While I am able to get the various phases and steps, it is not giving me the time spent in each phase/step. Is there a way to print the time as well

qlist = qf.read_query_file("query.txt")
for query in qlist:
    rows = session.execute(query, trace=True)
    trace = rows.get_query_trace()   
    duration = rows.get_query_trace().duration.total_seconds()
    print('----------------------------------------')
    print("Query Name:{query}, Duration:{duration}".format(query=query,duration=duration))
    for event in trace.events:
        print(event)
    print('------------------------------------------')

The output is as shown below

Query Name:select * from iris_with_id, Duration:0.006939
Parsing select * from iris_with_id on xx.xxx.xxx.x[Native-Transport-Requests-1] at 2022-01-13 03:05:34.544000
Preparing statement on xx.xxx.xxx.x[Native-Transport-Requests-1] at 2022-01-13 03:05:34.544000
reading digest from /xx.xxx.xxx.x on xx.xxx.xxx.x[Native-Transport-Requests-1] at 2022-01-13 03:05:34.544000
Executing single-partition query on roles on xx.xxx.xxx.x[ReadStage-2] at 2022-01-13 03:05:34.545000

Upvotes: 0

Views: 566

Answers (1)

Erick Ramirez
Erick Ramirez

Reputation: 16303

A Python app is probably a little overkill.

You can trace a query in cqlsh using the TRACING command:

cqlsh> TRACING ON;

You can then see all the stages of the execution including the elapsed time for each stage:

cqlsh> SELECT * FROM community.users_by_email WHERE email = '[email protected]';

 email                   | colour | name
-------------------------+--------+-------
 [email protected] |    red | Alice

(1 rows)

Tracing session: 4ed2b930-74dd-11ec-afd3-85873f459502

 activity                                                                                                                                   | timestamp                  | source       | source_elapsed | client
--------------------------------------------------------------------------------------------------------------------------------------------+----------------------------+--------------+----------------+-----------------------------------------
                                                                                                                         Execute CQL3 query | 2022-01-14 01:57:20.068000 | 172.28.223.3 |              0 | fa5f:ba11:8ac8:4fe7:a863:8df7:5cf2:7efd
                                               Parsing SELECT * FROM users_by_email WHERE email = '[email protected]'; [CoreThread-9] | 2022-01-14 01:57:20.070000 | 172.28.223.3 |           1831 | fa5f:ba11:8ac8:4fe7:a863:8df7:5cf2:7efd
                                                                                                         Preparing statement [CoreThread-9] | 2022-01-14 01:57:20.071000 | 172.28.223.3 |           2656 | fa5f:ba11:8ac8:4fe7:a863:8df7:5cf2:7efd
                                                                                          Reading data from [/172.28.128.3] [CoreThread-11] | 2022-01-14 01:57:20.071000 | 172.28.223.3 |           3526 | fa5f:ba11:8ac8:4fe7:a863:8df7:5cf2:7efd
                                                                                       Reading digests from [/172.28.237.4] [CoreThread-11] | 2022-01-14 01:57:20.072000 | 172.28.223.3 |           3887 | fa5f:ba11:8ac8:4fe7:a863:8df7:5cf2:7efd
                                                          Sending READS.SINGLE_READ message to /172.28.128.3, size=190 bytes [CoreThread-4] | 2022-01-14 01:57:20.072000 | 172.28.223.3 |           4235 | fa5f:ba11:8ac8:4fe7:a863:8df7:5cf2:7efd
                                                          Sending READS.SINGLE_READ message to /172.28.237.4, size=191 bytes [CoreThread-2] | 2022-01-14 01:57:20.072000 | 172.28.223.3 |           4340 | fa5f:ba11:8ac8:4fe7:a863:8df7:5cf2:7efd
                                                                       READS.SINGLE_READ message received from /172.28.223.3 [CoreThread-4] | 2022-01-14 01:57:20.076000 | 172.28.128.3 |            434 | fa5f:ba11:8ac8:4fe7:a863:8df7:5cf2:7efd
 Merged data from memtables and 3 sstables during single-partition query on users_by_email for key '[email protected]' [CoreThread-4] | 2022-01-14 01:57:20.077000 | 172.28.128.3 |           3167 | fa5f:ba11:8ac8:4fe7:a863:8df7:5cf2:7efd
                                                                       READS.SINGLE_READ message received from /172.28.223.3 [CoreThread-5] | 2022-01-14 01:57:20.077000 | 172.28.237.4 |            461 | fa5f:ba11:8ac8:4fe7:a863:8df7:5cf2:7efd
                                                                                       Read 1 live rows and 0 tombstone ones [CoreThread-4] | 2022-01-14 01:57:20.078000 | 172.28.128.3 |           3354 | fa5f:ba11:8ac8:4fe7:a863:8df7:5cf2:7efd
 Merged data from memtables and 3 sstables during single-partition query on users_by_email for key '[email protected]' [CoreThread-5] | 2022-01-14 01:57:20.078000 | 172.28.237.4 |           3322 | fa5f:ba11:8ac8:4fe7:a863:8df7:5cf2:7efd
                                                                       Enqueuing READS.SINGLE_READ response to /172.28.128.3 [CoreThread-4] | 2022-01-14 01:57:20.078000 | 172.28.128.3 |           3487 | fa5f:ba11:8ac8:4fe7:a863:8df7:5cf2:7efd
                                                                                       Read 1 live rows and 0 tombstone ones [CoreThread-5] | 2022-01-14 01:57:20.078000 | 172.28.237.4 |           3510 | fa5f:ba11:8ac8:4fe7:a863:8df7:5cf2:7efd
                                                          Sending READS.SINGLE_READ message to /172.28.223.3, size=169 bytes [CoreThread-7] | 2022-01-14 01:57:20.078000 | 172.28.128.3 |           3846 | fa5f:ba11:8ac8:4fe7:a863:8df7:5cf2:7efd
                                                                       Enqueuing READS.SINGLE_READ response to /172.28.237.4 [CoreThread-5] | 2022-01-14 01:57:20.078000 | 172.28.237.4 |           3634 | fa5f:ba11:8ac8:4fe7:a863:8df7:5cf2:7efd
                                                          Sending READS.SINGLE_READ message to /172.28.223.3, size=131 bytes [CoreThread-0] | 2022-01-14 01:57:20.078000 | 172.28.237.4 |           4012 | fa5f:ba11:8ac8:4fe7:a863:8df7:5cf2:7efd
                                                                       READS.SINGLE_READ message received from /172.28.128.3 [CoreThread-7] | 2022-01-14 01:57:20.082000 | 172.28.223.3 |          14426 | fa5f:ba11:8ac8:4fe7:a863:8df7:5cf2:7efd
                                                                                     Processing response from /172.28.128.3 [CoreThread-11] | 2022-01-14 01:57:20.082000 | 172.28.223.3 |          14792 | fa5f:ba11:8ac8:4fe7:a863:8df7:5cf2:7efd
                                                                       READS.SINGLE_READ message received from /172.28.237.4 [CoreThread-8] | 2022-01-14 01:57:20.082000 | 172.28.223.3 |          14914 | fa5f:ba11:8ac8:4fe7:a863:8df7:5cf2:7efd
                                                                                     Processing response from /172.28.237.4 [CoreThread-11] | 2022-01-14 01:57:20.083000 | 172.28.223.3 |          15165 | fa5f:ba11:8ac8:4fe7:a863:8df7:5cf2:7efd
                                                                                                                           Request complete | 2022-01-14 01:57:20.085874 | 172.28.223.3 |          17874 | fa5f:ba11:8ac8:4fe7:a863:8df7:5cf2:7efd

Upvotes: 1

Related Questions