bahman/scylla
1
0
Fork 0
Code Issues Pull Requests Actions 3 Packages Projects Releases Wiki Activity

Merge 'Extend query tracing information' from Michał Jadwiszczak

Browse Source 
This little patch adds:
- authenticated user to "Processing a statement" tracing log
- name of a semaphore to reader concurrency semaphore logs

The purpose of this patch is to be able to verify parts of query execution to track down issues with service levels.

```
cassandra@cqlsh> select * from ks1.t where a = 1;

 a | b
---+---

(0 rows)

Tracing session: ea7e5ce0-b9f5-11ee-b123-b0816809f2c0

 activity                                                                                                                                     | timestamp                  | source    | source_elapsed | client
----------------------------------------------------------------------------------------------------------------------------------------------+----------------------------+-----------+----------------+-----------
                                                                                                                           Execute CQL3 query | 2024-01-23 14:47:14.734000 | 127.0.0.1 |              0 | 127.0.0.1
                                                                                                         Parsing a statement [shard 1/sl:sl1] | 2024-01-23 14:47:14.734126 | 127.0.0.1 |              3 | 127.0.0.1
                                                                    Processing a statement for authenticated user: cassandra [shard 1/sl:sl1] | 2024-01-23 14:47:14.734279 | 127.0.0.1 |            156 | 127.0.0.1
      Creating read executor for token -4069959284402364209 with all: {127.0.0.2} targets: {127.0.0.2} repair decision: NONE [shard 1/sl:sl1] | 2024-01-23 14:47:14.737348 | 127.0.0.1 |           3225 | 127.0.0.1
   Creating never_speculating_read_executor - speculative retry is disabled or there are no extra replicas to speculate with [shard 1/sl:sl1] | 2024-01-23 14:47:14.737351 | 127.0.0.1 |           3228 | 127.0.0.1
                                                                                  read_data: sending a message to /127.0.0.2 [shard 1/sl:sl1] | 2024-01-23 14:47:14.737358 | 127.0.0.1 |           3236 | 127.0.0.1
                                                                                 read_data: message received from /127.0.0.1 [shard 1/sl:sl1] | 2024-01-23 14:47:14.737593 | 127.0.0.2 |             16 | 127.0.0.1
                                                        Start querying singular range {{-4069959284402364209, 000400000001}} [shard 0/sl:sl1] | 2024-01-23 14:47:14.737676 | 127.0.0.2 |             24 | 127.0.0.1
                                                                  [reader concurrency semaphore sl:sl1] admitted immediately [shard 0/sl:sl1] | 2024-01-23 14:47:14.737684 | 127.0.0.2 |             31 | 127.0.0.1
                                                                        [reader concurrency semaphore sl:sl1] executing read [shard 0/sl:sl1] | 2024-01-23 14:47:14.737688 | 127.0.0.2 |             35 | 127.0.0.1
                                    Querying cache for range {{-4069959284402364209, 000400000001}} and slice {(-inf, +inf)} [shard 0/sl:sl1] | 2024-01-23 14:47:14.737715 | 127.0.0.2 |             63 | 127.0.0.1
 Page stats: 0 partition(s), 0 static row(s) (0 live, 0 dead), 0 clustering row(s) (0 live, 0 dead) and 0 range tombstone(s) [shard 0/sl:sl1] | 2024-01-23 14:47:14.737724 | 127.0.0.2 |             72 | 127.0.0.1
                                                                                                            Querying is done [shard 0/sl:sl1] | 2024-01-23 14:47:14.737731 | 127.0.0.2 |             79 | 127.0.0.1
                                                                read_data handling is done, sending a response to /127.0.0.1 [shard 1/sl:sl1] | 2024-01-23 14:47:14.738321 | 127.0.0.2 |            743 | 127.0.0.1
                                                                                     read_data: got response from /127.0.0.2 [shard 1/sl:sl1] | 2024-01-23 14:47:14.739148 | 127.0.0.1 |           5026 | 127.0.0.1
                                                                                        Done processing - preparing a result [shard 1/sl:sl1] | 2024-01-23 14:47:14.739196 | 127.0.0.1 |           5074 | 127.0.0.1
                                                                                                                             Request complete | 2024-01-23 14:47:14.739087 | 127.0.0.1 |           5087 | 127.0.0.1

```

Closes scylladb/scylladb#16920

* github.com:scylladb/scylladb:
  reader_concurrency_semaphore: add name of semaphore in tracing messages
  cql3:query_processor: add logged user to query tracing info
This commit is contained in:
Botond Dénes
2024-01-23 16:06:16 +02:00
parent f15880dc48 49544c47a1
commit e79ea91990
2 changed files with 6 additions and 5 deletions
Download Patch File Download Diff File Expand all files Collapse all files

3
cql3/query_processor.cc
View File

@@ -576,7 +576,8 @@ query_processor::execute_direct_without_checking_exception_message(const sstring
if (!queryState.getClientState().isInternal)
metrics.regularStatementsExecuted.inc();
#endif
tracing::trace(query_state.get_trace_state(), "Processing a statement");
auto user = query_state.get_client_state().user();
tracing::trace(query_state.get_trace_state(), "Processing a statement for authenticated user: {}", user ? (user->name ? *user->name : "anonymous") : "no user authenticated");
return execute_maybe_with_guard(query_state, std::move(statement), options, &query_processor::do_execute_direct, std::move(warnings));
}

8
reader_concurrency_semaphore.cc
View File

@@ -919,7 +919,7 @@ future<> reader_concurrency_semaphore::execution_loop() noexcept {
permit.on_executing();
auto e = std::move(permit.aux_data());
tracing::trace(permit.trace_state(), "[reader concurrency semaphore] executing read");
tracing::trace(permit.trace_state(), "[reader concurrency semaphore {}] executing read", _name);
try {
e.func(reader_permit(permit.shared_from_this())).forward_to(std::move(e.pr));
@@ -1201,7 +1201,7 @@ void reader_concurrency_semaphore::do_detach_inactive_reader(reader_permit::impl
ir.ttl_timer.cancel();
ir.detach();
ir.reader.permit()->on_evicted();
tracing::trace(permit.trace_state(), "[reader_concurrency_semaphore] evicted, reason: {}", reason);
tracing::trace(permit.trace_state(), "[reader_concurrency_semaphore {}] evicted, reason: {}", _name, reason);
try {
if (ir.notify_handler) {
ir.notify_handler(reason);
@@ -1379,7 +1379,7 @@ future<> reader_concurrency_semaphore::do_wait_admission(reader_permit::impl& pe
const auto [admit, why] = can_admit_read(permit);
++(_stats.*stats_table[static_cast<int>(why)]);
tracing::trace(permit.trace_state(), "[reader concurrency semaphore] {}", result_as_string[static_cast<int>(why)]);
tracing::trace(permit.trace_state(), "[reader concurrency semaphore {}] {}", _name, result_as_string[static_cast<int>(why)]);
if (admit != can_admit::yes || !_wait_list.empty()) {
auto fut = enqueue_waiter(permit, wait_on::admission);
if (admit == can_admit::yes && !_wait_list.empty()) {
@@ -1390,7 +1390,7 @@ future<> reader_concurrency_semaphore::do_wait_admission(reader_permit::impl& pe
maybe_dump_reader_permit_diagnostics(*this, "semaphore could admit new reads yet there are waiters");
maybe_admit_waiters();
} else if (admit == can_admit::maybe) {
tracing::trace(permit.trace_state(), "[reader concurrency semaphore] evicting inactive reads in the background to free up resources");
tracing::trace(permit.trace_state(), "[reader concurrency semaphore {}] evicting inactive reads in the background to free up resources", _name);
++_stats.reads_queued_with_eviction;
evict_readers_in_background();
}