mirror of
https://github.com/scylladb/scylladb.git
synced 2026-05-12 19:02:12 +00:00
29e2dc242a
In order to improve tracing for the read path, cache is now
also actively adding basic trace information.
Example:
select * from t where token(p) >= 42 and token(p) < 112;
activity | timestamp | source | source_elapsed | client
-----------------------------------------------------------------------------------------+----------------------------+-----------+----------------+-----------
Execute CQL3 query | 2020-08-07 13:10:34.694000 | 127.0.0.1 | 0 | 127.0.0.1
Parsing a statement [shard 0] | 2020-08-07 13:10:34.694307 | 127.0.0.1 | -- | 127.0.0.1
Processing a statement [shard 0] | 2020-08-07 13:10:34.694377 | 127.0.0.1 | 70 | 127.0.0.1
read_data: querying locally [shard 0] | 2020-08-07 13:10:34.694425 | 127.0.0.1 | 118 | 127.0.0.1
Start querying token range [{42, start}, {112, start}] [shard 0] | 2020-08-07 13:10:34.694432 | 127.0.0.1 | 125 | 127.0.0.1
Creating shard reader on shard: 0 [shard 0] | 2020-08-07 13:10:34.694446 | 127.0.0.1 | 139 | 127.0.0.1
Scanning cache for range [{42, start}, {112, start}] and slice {(-inf, +inf)} [shard 0] | 2020-08-07 13:10:34.694454 | 127.0.0.1 | 147 | 127.0.0.1
Querying is done [shard 0] | 2020-08-07 13:10:34.694494 | 127.0.0.1 | 187 | 127.0.0.1
Done processing - preparing a result [shard 0] | 2020-08-07 13:10:34.694520 | 127.0.0.1 | 213 | 127.0.0.1
Request complete | 2020-08-07 13:10:34.694221 | 127.0.0.1 | 221 | 127.0.0.1
Example with cache miss:
select * from t where p = 7;
activity | timestamp | source | source_elapsed | client
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------+-----------+----------------+-----------
Execute CQL3 query | 2020-08-07 13:25:04.363000 | 127.0.0.1 | 0 | 127.0.0.1
Parsing a statement [shard 0] | 2020-08-07 13:25:04.363310 | 127.0.0.1 | -- | 127.0.0.1
Processing a statement [shard 0] | 2020-08-07 13:25:04.363384 | 127.0.0.1 | 74 | 127.0.0.1
Creating read executor for token 1634052884888577606 with all: {127.0.0.1} targets: {127.0.0.1} repair decision: NONE [shard 0] | 2020-08-07 13:25:04.363450 | 127.0.0.1 | 139 | 127.0.0.1
read_data: querying locally [shard 0] | 2020-08-07 13:25:04.363455 | 127.0.0.1 | 145 | 127.0.0.1
Start querying singular range {{1634052884888577606, pk{000400000007}}} [shard 0] | 2020-08-07 13:25:04.363461 | 127.0.0.1 | 151 | 127.0.0.1
Querying cache for range {{1634052884888577606, pk{000400000007}}} and slice {(-inf, +inf)} [shard 0] | 2020-08-07 13:25:04.363490 | 127.0.0.1 | 180 | 127.0.0.1
Range {{1634052884888577606, pk{000400000007}}} not found in cache [shard 0] | 2020-08-07 13:25:04.363494 | 127.0.0.1 | 183 | 127.0.0.1
Reading key {{1634052884888577606, pk{000400000007}}} from sstable /home/sarna/.ccm/scylla-1/node1/data/ks/t-f7b7a9b0d89f11eab650000000000000/mc-1-big-Data.db [shard 0] | 2020-08-07 13:25:04.363522 | 127.0.0.1 | 211 | 127.0.0.1
/home/sarna/.ccm/scylla-1/node1/data/ks/t-f7b7a9b0d89f11eab650000000000000/mc-1-big-Index.db: scheduling bulk DMA read of size 16 at offset 0 [shard 0] | 2020-08-07 13:25:04.363546 | 127.0.0.1 | 235 | 127.0.0.1
/home/sarna/.ccm/scylla-1/node1/data/ks/t-f7b7a9b0d89f11eab650000000000000/mc-1-big-Index.db: finished bulk DMA read of size 16 at offset 0, successfully read 16 bytes [shard 0] | 2020-08-07 13:25:04.364406 | 127.0.0.1 | 1095 | 127.0.0.1
/home/sarna/.ccm/scylla-1/node1/data/ks/t-f7b7a9b0d89f11eab650000000000000/mc-1-big-Data.db: scheduling bulk DMA read of size 56 at offset 0 [shard 0] | 2020-08-07 13:25:04.364445 | 127.0.0.1 | 1134 | 127.0.0.1
/home/sarna/.ccm/scylla-1/node1/data/ks/t-f7b7a9b0d89f11eab650000000000000/mc-1-big-Data.db: finished bulk DMA read of size 56 at offset 0, successfully read 56 bytes [shard 0] | 2020-08-07 13:25:04.364599 | 127.0.0.1 | 1288 | 127.0.0.1
Querying is done [shard 0] | 2020-08-07 13:25:04.364685 | 127.0.0.1 | 1375 | 127.0.0.1
Done processing - preparing a result [shard 0] | 2020-08-07 13:25:04.364719 | 127.0.0.1 | 1408 | 127.0.0.1
Request complete | 2020-08-07 13:25:04.364421 | 127.0.0.1 | 1421 | 127.0.0.1
Example without cache for verification:
select * from t where token(p) >= 42 and token(p) < 112 bypass cache;
activity | timestamp | source | source_elapsed | client
------------------------------------------------------------------+----------------------------+-----------+----------------+-----------
Execute CQL3 query | 2020-08-07 13:11:16.122000 | 127.0.0.1 | 0 | 127.0.0.1
Parsing a statement [shard 0] | 2020-08-07 13:11:16.122657 | 127.0.0.1 | -- | 127.0.0.1
Processing a statement [shard 0] | 2020-08-07 13:11:16.122742 | 127.0.0.1 | 85 | 127.0.0.1
read_data: querying locally [shard 0] | 2020-08-07 13:11:16.122806 | 127.0.0.1 | 149 | 127.0.0.1
Start querying token range [{42, start}, {112, start}] [shard 0] | 2020-08-07 13:11:16.122814 | 127.0.0.1 | 158 | 127.0.0.1
Creating shard reader on shard: 0 [shard 0] | 2020-08-07 13:11:16.122829 | 127.0.0.1 | 172 | 127.0.0.1
Querying is done [shard 0] | 2020-08-07 13:11:16.122895 | 127.0.0.1 | 239 | 127.0.0.1
Done processing - preparing a result [shard 0] | 2020-08-07 13:11:16.122928 | 127.0.0.1 | 271 | 127.0.0.1
Request complete | 2020-08-07 13:11:16.122280 | 127.0.0.1 | 280 | 127.0.0.1
Message-Id: <3b31584c13f23f84af35660d0aa73ba56c30cf13.1596799589.git.sarna@scylladb.com>
56 KiB
56 KiB