Sampling query profiler

Elena Dvoryadkina

To introspect query performance in ADQM, you can run a sampling query profiler. For example, it can help you to find source code routines that are most frequently called during a query execution, or trace the CPU and real time spent, including idle time.

Enable query profiler

  1. On the ADQMDB service’s configuration page of the ADCM interface, enable the Show advanced option, navigate to the Log settings section, and activate the trace_log setting to run the query profiler so that it can start collecting stack traces and saving them in the trace_log system table. In the same section, configure parameters of the trace_log table:

    • Database — name of a database where the table should be stored;

    • Flush interval, milliseconds — interval for flushing data from the memory buffer to the table (in milliseconds);

    • TTL, days — lifetime of rows in the table (in days).

    Click Save and execute the Reconfig and restart action for the ADQMDB service to save the configuration changes and restart the service.

    NOTE

    • A partitioning key for the trace_log table is automatically set to the event_date column — date at the moment of sampling. See the trace_log article of the ClickHouse documentation for more details on table columns.

    • Data in the trace_log table is valid only for a running server. After a server restart, ADQM does not clean up the table and all the stored virtual memory address may become invalid.

  2. Use the query_profiler_real_time_period_ns and query_profiler_cpu_time_period_ns parameters to configure the real-clock and CPU-clock timers, which determine how often the query profiler should sample stack traces and send them to the trace_log table.

     
    By default, both timers are set to one sample per second. This sampling frequency allows collecting enough information about an ADQM cluster without affecting the performance of ADQM servers. If you need to profile each query individually, try to use higher sampling frequency — for example, 100 times per second:

    SET query_profiler_real_time_period_ns=10000000;
    SET query_profiler_cpu_time_period_ns=10000000;

    Collecting stack traces with a frequency higher than a few thousand samples per second is usually not possible.

Analyze profiler reports

  1. Install the adqm-clickhouse-debuginfo package.

  2. Enable introspection functions for query profiling (for security reasons, introspection functions are disabled by default):

    SET allow_introspection_functions = 1;

  3. Use introspection functions to analyze the trace_log table — see the next section for examples on how to do this.

Introspection functions

This section describes functions that can be used to introspect the ELF and DWARF formats for query profiling.

Presets for running examples

  1. Before you reproduce examples of using introspection functions, make sure you have the adqm-clickhouse-debuginfo package installed and the allow_introspection_functions setting enabled.

  2. In the examples below, introspection functions analyze the first stack trace instance from the trace_log table. The following query returns the first row of this table:

    SELECT * FROM system.trace_log LIMIT 1 FORMAT Vertical;
    Row 1:
──────
event_date:              2023-09-04
event_time:              2023-09-04 10:18:01
event_time_microseconds: 2023-09-04 10:18:01.858935
timestamp_ns:            1693822681858935963
revision:                54472
trace_type:              Memory
thread_id:               11216
query_id:                7b53b488-6e38-495a-ab63-e0ed985bf2de
trace:                   [282096402,282019952,282019801,282176985,373506363,387689543,282729773,282744526,140712295374501,140712292395789]
size:                    8760
event:
increment:               0

    The trace field contains the stack trace at the moment of sampling. Each element of the array is a virtual memory address inside an ADQM server process. Introspection functions can be applied to a single address or to the whole stack trace.

addressToLine

The addressToLine function converts a virtual memory address inside an ADQM server process to a filename and a line number in ADQM source code.

Function syntax:

addressToLine(<address_of_binary_instruction>)

where <address_of_binary_instruction> is an address of an instruction in a running process (a value of the UInt64 type).

The function returns a String value:

  • Name of a source code file and a line number in that file, delimited by a colon.

  • Name of a binary, if the function could not find the debug information.

  • Empty string, if the passed address is not valid.

Example

  1. Get a source code file name and a line number for a single address:

    SELECT addressToLine(282096402::UInt64);

    In the function execution result, ./build/src/Common/StackTrace.cpp is the file name and 287 is the line number:

    ┌─addressToLine(CAST('282096402', 'UInt64'))─┐
│ ./build/src/Common/StackTrace.cpp:287      │
└────────────────────────────────────────────┘

  2. Apply the function to the whole stack trace, using the arrayMap function to process each individual element of the trace array by the addressToLine function:

    SELECT arrayStringConcat(arrayMap(x -> addressToLine(x), trace), '\n') AS trace_source_code_lines
FROM system.trace_log
LIMIT 1
FORMAT Vertical;
    Row 1:
──────
trace_source_code_lines: ./build/src/Common/StackTrace.cpp:287
./build/src/Common/MemoryTracker.cpp:202
./build/src/Common/MemoryTracker.cpp:338
./build/src/Common/ThreadStatus.cpp:185
./build/contrib/llvm-project/libcxx/include/__memory/unique_ptr.h:302
./build/contrib/llvm-project/libcxx/include/__memory/shared_ptr.h:701
./build/base/base/wide_integer_impl.h:789
./build/contrib/llvm-project/libcxx/include/__memory/unique_ptr.h:302
/usr/lib64/libpthread-2.17.so
/usr/lib64/libc-2.17.so

addressToLineWithInlines

The addressToLineWithInlines function is similar to addressToLine, but returns an array with all inline functions (so it evaluates more slowly).

Function syntax:

addressToLineWithInlines(<address_of_binary_instruction>)

where <address_of_binary_instruction> is an address of an instruction in a running process (a value of the UInt64 type).

The function returns an array of String values:

  • Array where the first element contains a name of a source code file and a line number in that file (delimited by a colon), and other elements include information on inline functions — source code filename, line number, and function name.

  • Array with a single element that is a binary name, if the function could not find the debug information.

  • Empty array, if the passed address is not valid.

Example

  1. Apply the function to a single address:

    SELECT addressToLineWithInlines(373506363::UInt64) FORMAT Vertical;
    Row 1:
──────
addressToLineWithInlines(CAST('373506363', 'UInt64')): ['./build/src/Interpreters/ThreadStatusExt.cpp:185','./build/contrib/llvm-project/libcxx/include/__memory/unique_ptr.h:302:std::__1::unique_ptr<DB::QueryProfilerReal, std::__1::default_delete<DB::QueryProfilerReal>>::reset[abi:v15000](DB::QueryProfilerReal*)','./build/src/Interpreters/ThreadStatusExt.cpp:415:DB::ThreadStatus::finalizeQueryProfiler()']

  2. Apply the function to the whole stack trace, using the arrayJoin function that splits an array into rows:

    SELECT address, addressToLineWithInlines(arrayJoin(trace) AS address)
FROM system.trace_log
WHERE query_id = '7b53b488-6e38-495a-ab63-e0ed985bf2de'
FORMAT Vertical;
    Row 1:
──────
address:                                    282096402
addressToLineWithInlines(arrayJoin(trace)): ['./build/src/Common/StackTrace.cpp:287']

Row 2:
──────
address:                                    282019952
addressToLineWithInlines(arrayJoin(trace)): ['./build/src/Common/MemoryTracker.cpp:202']

Row 3:
──────
address:                                    282019801
addressToLineWithInlines(arrayJoin(trace)): ['./build/src/Common/MemoryTracker.cpp:338']

Row 4:
──────
address:                                    282176985
addressToLineWithInlines(arrayJoin(trace)): ['./build/src/Common/ThreadStatus.cpp:185']

Row 5:
──────
address:                                    373506363
addressToLineWithInlines(arrayJoin(trace)): ['./build/src/Interpreters/ThreadStatusExt.cpp:185','./build/contrib/llvm-project/libcxx/include/__memory/unique_ptr.h:302:std::__1::unique_ptr<DB::QueryProfilerReal, std::__1::default_delete<DB::QueryProfilerReal>>::reset[abi:v15000](DB::QueryProfilerReal*)','./build/src/Interpreters/ThreadStatusExt.cpp:415:DB::ThreadStatus::finalizeQueryProfiler()']

...

addressToSymbol

The addressToSymbol function converts a virtual memory address inside an ADQM server process to a symbol from an object file.

Function syntax:

addressToSymbol(<address_of_binary_instruction>)

where <address_of_binary_instruction> is an address of an instruction in a running process (a value of the UInt64 type).

The function returns a String value:

  • Symbol from an object file.

  • Empty string, if the passed address is not valid.

Example

  1. Get a symbol for a single address:

    SELECT addressToSymbol(282096402::UInt64);
    ┌─addressToSymbol(CAST('282096402', 'UInt64'))─┐
│ _ZN10StackTrace10tryCaptureEv                │
└──────────────────────────────────────────────┘

  2. Apply the function to the whole stack trace, using the arrayMap function to process each individual element of the trace array by the addressToSymbol function:

    SELECT arrayStringConcat(arrayMap(x -> addressToSymbol(x), trace), '\n') AS trace_symbols
FROM system.trace_log
LIMIT 1
FORMAT Vertical;
    Row 1:
──────
trace_symbols: _ZN10StackTrace10tryCaptureEv
_ZN13MemoryTracker9allocImplElbPS_
_ZN13MemoryTracker9allocImplElbPS_
_ZN2DB12ThreadStatus20flushUntrackedMemoryEv
_ZN2DB12ThreadStatus15detachFromGroupEv
_ZNSt3__110__function16__policy_invokerIFvvEE11__call_implINS0_20__default_alloc_funcIZN24ThreadFromGlobalPoolImplILb1EEC1IZN2DB28PullingAsyncPipelineExecutor4pullERNS9_5ChunkEmE3$_0JEEEOT_DpOT0_EUlvE_S2_EEEEvPKNS0_16__policy_storageE
_ZN14ThreadPoolImplINSt3__16threadEE6workerENS0_15__list_iteratorIS1_PvEE
_ZNSt3__114__thread_proxyB6v15000INS_5tupleIJNS_10unique_ptrINS_15__thread_structENS_14default_deleteIS3_EEEEZN14ThreadPoolImplINS_6threadEE12scheduleImplIvEET_NS_8functionIFvvEEElNS_8optionalImEEbEUlvE0_EEEEEPvSJ_
start_thread
__clone

demangle

The demangle function converts a symbol that you can get using the addressToSymbol function into a C++ function name.

Function syntax:

demangle(<symbol>)

where <symbol> is a symbol from an object file (a value of the String type).

The function returns a String value:

  • C++ function name.

  • Empty string, if the passed symbol is not valid.

Example

  1. Get a function name for a single address:

    SELECT demangle(addressToSymbol(282096402::UInt64));
    ┌─demangle(addressToSymbol(CAST('282096402', 'UInt64')))─┐
│ StackTrace::tryCapture()                               │
└────────────────────────────────────────────────────────┘

  2. Apply the function to the whole stack trace, using the arrayMap function to process each individual element of the trace array by the demangle function:

    SELECT arrayStringConcat(arrayMap(x -> demangle(addressToSymbol(x)), trace), '\n') AS trace_functions
FROM system.trace_log
LIMIT 1
FORMAT Vertical;
    Row 1:
──────
trace_functions: StackTrace::tryCapture()
MemoryTracker::allocImpl(long, bool, MemoryTracker*)
MemoryTracker::allocImpl(long, bool, MemoryTracker*)
DB::ThreadStatus::flushUntrackedMemory()
DB::ThreadStatus::detachFromGroup()
void std::__1::__function::__policy_invoker<void ()>::__call_impl<std::__1::__function::__default_alloc_func<ThreadFromGlobalPoolImpl<true>::ThreadFromGlobalPoolImpl<DB::PullingAsyncPipelineExecutor::pull(DB::Chunk&, unsigned long)::$_0>(DB::PullingAsyncPipelineExecutor::pull(DB::Chunk&, unsigned long)::$_0&&)::'lambda'(), void ()>>(std::__1::__function::__policy_storage const*)
ThreadPoolImpl<std::__1::thread>::worker(std::__1::__list_iterator<std::__1::thread, void*>)
void* std::__1::__thread_proxy[abi:v15000]<std::__1::tuple<std::__1::unique_ptr<std::__1::__thread_struct, std::__1::default_delete<std::__1::__thread_struct>>, void ThreadPoolImpl<std::__1::thread>::scheduleImpl<void>(std::__1::function<void ()>, long, std::__1::optional<unsigned long>, bool)::'lambda0'()>>(void*)
start_thread
__clone

tid

The tid function returns id of a thread, in which the current Block is processed.

Function syntax:

tid()

The function returns a value of the Uint64 type.

Example
SELECT tid();
┌─tid()─┐
│ 10959 │
└───────┘

logTrace

The logTrace function sends a trace log message to a server log for each Block.

Function syntax:

logTrace('<message>')

where <message> is a message that is emitted to a server log (a String value).

The function always returns 0.

Example
SELECT logTrace('logTrace message');
┌─logTrace('logTrace message')─┐
│                            0 │
└──────────────────────────────┘
Found a mistake? Seleсt text and press Ctrl+Enter to report it