Skip to content

Commit 18c1e44

Browse files
anirbanr-fbfacebook-github-bot
authored andcommitted
TraceID support in MySQLD
Summary: Enables traces to be passed in as query attributes by clients and traces (instruction costs) to be collected on server side. Reviewed By: abhinav04sharma Differential Revision: D6393858 fbshipit-source-id: c8c1c96
1 parent 5c0a0ae commit 18c1e44

9 files changed

+324
-3
lines changed

mysql-test/r/slow_log_extra_big.result

+5
Original file line numberDiff line numberDiff line change
@@ -21,6 +21,10 @@ count(*)
2121
select count(*) from big_table_slow where id < 100000;
2222
count(*)
2323
20000
24+
set session long_query_time = 10000;
25+
select count(*) from big_table_slow where id >10000;
26+
count(*)
27+
15000
2428
# Cleanup
2529
SET GLOBAL innodb_file_format = "Barracuda";
2630
set global slow_query_log_file = @my_slow_logname;
@@ -39,5 +43,6 @@ Rows_sent Rows_examined Errno Killed Bytes_received Bytes_sent Read_first Read_l
3943
1 1 0 0 0 314 0 0 1 0 0 0 0 0 0 0 0 0 0 0 0
4044
1 15000 0 0 0 67 0 0 1 15000 0 0 0 0 0 0 0 0 0 0 0
4145
1 20000 0 0 0 67 1 0 1 20000 0 0 0 0 0 0 0 0 0 0 0
46+
1 15000 0 0 0 67 0 0 1 15000 0 0 0 0 0 0 0 0 0 0 0
4247
if the following is not 1 you need to adjust the file_lines_count variable
4348
1

mysql-test/t/slow_log_extra_big.test

+8-1
Original file line numberDiff line numberDiff line change
@@ -58,8 +58,14 @@ select count(*) from big_table_slow where id >10000;
5858

5959
select count(*) from big_table_slow where id < 100000;
6060

61+
connect (con2, localhost,root,,);
62+
set session long_query_time = 10000;
63+
query_attrs_add traceid foobar;
64+
select count(*) from big_table_slow where id >10000;
65+
query_attrs_delete traceid;
66+
6167
# Wait for all output lines to show up in the slow log file
62-
let $file_lines_count= 6;
68+
let $file_lines_count= 7;
6369
let $file_lines_pattern= ^# Query_time;
6470
let $file_lines_filename=
6571
$MYSQLTEST_VARDIR/mysqld.1/data/slow_log_extra_big-slow.log;
@@ -72,6 +78,7 @@ eval SET GLOBAL innodb_file_format = \"$file_format_save\";
7278
set global slow_query_log_file = @my_slow_logname;
7379
set global long_query_time=@my_long_query_time;
7480

81+
disconnect con2;
7582
disconnect con1;
7683
disconnect con;
7784
let $count_sessions= 1;

sql/CMakeLists.txt

+1-1
Original file line numberDiff line numberDiff line change
@@ -257,7 +257,7 @@ ADD_DEPENDENCIES(sql GenServerSource)
257257
ADD_DEPENDENCIES(sql GenDigestServerSource)
258258
DTRACE_INSTRUMENT(sql)
259259
TARGET_LINK_LIBRARIES(sql ${MYSQLD_STATIC_PLUGIN_LIBS}
260-
mysys mysys_ssl dbug strings vio regex
260+
mysys mysys_ssl dbug strings vio regex utils
261261
${LIBWRAP} ${LIBCRYPT} ${LIBDL}
262262
${SSL_LIBRARIES})
263263

sql/log.cc

+7
Original file line numberDiff line numberDiff line change
@@ -2190,6 +2190,7 @@ bool MYSQL_QUERY_LOG::write(THD *thd, time_t current_time,
21902190
thd->status_var.read_time)));
21912191
}
21922192

2193+
bool tid_present = !(thd->trace_id.empty());
21932194
mysql_mutex_lock(&LOCK_log);
21942195

21952196
if (is_open())
@@ -2245,6 +2246,7 @@ bool MYSQL_QUERY_LOG::write(THD *thd, time_t current_time,
22452246
" Tmp_table_bytes_written: %lu"
22462247
" Start: %s End: %s"
22472248
" Reads: %lu Read_time: %s"
2249+
" Trace_Id: %s Instruction_Cost: %lu"
22482250
" Semisync_ack_time: %s Engine_commit_time: %s\n",
22492251
query_time_buff, lock_time_buff,
22502252
(ulong) thd->get_sent_row_count(),
@@ -2292,6 +2294,8 @@ bool MYSQL_QUERY_LOG::write(THD *thd, time_t current_time,
22922294
(ulong) (thd->status_var.read_requests -
22932295
query_start->read_requests),
22942296
read_time_buff,
2297+
(tid_present ? thd->trace_id.c_str() : "NA"),
2298+
(tid_present ? thd->pc_val : 0),
22952299
semisync_ack_time_buff,
22962300
engine_commit_time_buff) == (uint) -1)
22972301
tmp_errno=errno;
@@ -2314,6 +2318,7 @@ bool MYSQL_QUERY_LOG::write(THD *thd, time_t current_time,
23142318
" Tmp_table_bytes_written: %lu"
23152319
" Start: %s End: %s"
23162320
" Reads: %lu Read_time: %s"
2321+
" Trace_Id: %s Instruction_Cost: %lu"
23172322
" Semisync_ack_time: %s Engine_commit_time: %s\n",
23182323
query_time_buff, lock_time_buff,
23192324
(ulong) thd->get_sent_row_count(),
@@ -2342,6 +2347,8 @@ bool MYSQL_QUERY_LOG::write(THD *thd, time_t current_time,
23422347
start_time_buff, end_time_buff,
23432348
(ulong) thd->status_var.read_requests,
23442349
read_time_buff,
2350+
(tid_present ? thd->trace_id.c_str() : "NA"),
2351+
(tid_present ? thd->pc_val : 0),
23452352
semisync_ack_time_buff,
23462353
engine_commit_time_buff) == (uint) -1)
23472354
tmp_errno=errno;

sql/sql_class.h

+8
Original file line numberDiff line numberDiff line change
@@ -109,6 +109,10 @@ class User_level_lock;
109109
class user_var_entry;
110110
class ExecutionContextImpl;
111111

112+
namespace utils {
113+
class PerfCounter;
114+
}
115+
112116
class Srv_session;
113117

114118
struct st_thd_timer;
@@ -4541,6 +4545,7 @@ class THD :public MDL_context_owner,
45414545
{
45424546
query_attrs_string= CSET_STRING();
45434547
query_attrs_map.clear();
4548+
trace_id.clear();
45444549
}
45454550
inline char *query_attrs() const { return query_attrs_string.str(); }
45464551
inline uint32 query_attrs_length() const
@@ -4739,6 +4744,9 @@ class THD :public MDL_context_owner,
47394744

47404745
public:
47414746
DB_STATS *db_stats;
4747+
std::shared_ptr<utils::PerfCounter> query_perf;
4748+
std::string trace_id;
4749+
uint64_t pc_val;
47424750
};
47434751

47444752
/*

sql/sql_parse.cc

+35-1
Original file line numberDiff line numberDiff line change
@@ -120,6 +120,10 @@
120120
#include "sql_parse_com_rpc.h" // handle_com_rpc, srv_session_end_statement
121121
#include "srv_session.h"
122122

123+
#ifndef EMBEDDED_LIBRARY
124+
#include "perf_counters.h"
125+
#endif
126+
123127
#ifdef HAVE_JEMALLOC
124128
#ifndef EMBEDDED_LIBRARY
125129
#include <jemalloc/jemalloc.h>
@@ -1543,6 +1547,12 @@ static bool set_session_db_helper(THD *thd, const LEX_STRING *new_db)
15431547
return true;
15441548
}
15451549

1550+
#ifndef EMBEDDED_LIBRARY
1551+
static std::string perf_counter_factory_name("simple");
1552+
static std::shared_ptr<utils::PerfCounterFactory> pc_factory=
1553+
utils::PerfCounterFactory::getFactory(perf_counter_factory_name);
1554+
#endif
1555+
15461556
/**
15471557
Perform one connection-level (COM_XXXX) command.
15481558
@@ -1580,6 +1590,23 @@ bool dispatch_command(enum enum_server_command command, THD *thd, char* packet,
15801590
DBUG_ENTER("dispatch_command");
15811591
DBUG_PRINT("info",("packet: '%*.s'; command: %d", packet_length, packet, command));
15821592

1593+
#ifndef EMBEDDED_LIBRARY
1594+
// do collection of samples for passed in "traceid"
1595+
std::string traceId;
1596+
std::unordered_map<std::string, std::string>::const_iterator tid_iter;
1597+
if (!thd->query_attrs_map.empty() &&
1598+
(tid_iter= thd->query_attrs_map.find("traceid")) !=
1599+
thd->query_attrs_map.end()) {
1600+
thd->trace_id = tid_iter->second;
1601+
if (!thd->query_perf) {
1602+
thd->query_perf= pc_factory->makeSharedPerfCounter(
1603+
utils::PerfCounterMode::PCM_THREAD,
1604+
utils::PerfCounterType::PCT_INSTRUCTIONS);
1605+
}
1606+
thd->query_perf->start();
1607+
}
1608+
#endif
1609+
15831610
if (opt_log_slow_extra)
15841611
{
15851612
query_start_status_ptr= &query_start_status;
@@ -2343,6 +2370,12 @@ bool dispatch_command(enum enum_server_command command, THD *thd, char* packet,
23432370
thd->get_stmt_da()->sql_errno() : 0,
23442371
command_name[command].str);
23452372

2373+
#ifndef EMBEDDED_LIBRARY
2374+
if (!thd->trace_id.empty()) {
2375+
thd->pc_val= thd->query_perf->getAndStop();
2376+
}
2377+
#endif
2378+
23462379
log_slow_statement(thd, query_start_status_ptr);
23472380

23482381
THD_STAGE_INFO(thd, stage_cleaning_up);
@@ -2458,7 +2491,8 @@ bool log_slow_applicable(THD *thd)
24582491
thd->variables.min_examined_row_limit)) ||
24592492
(thd->variables.slow_log_if_rows_examined_exceed > 0 &&
24602493
thd->get_examined_row_count() >
2461-
thd->variables.slow_log_if_rows_examined_exceed);
2494+
thd->variables.slow_log_if_rows_examined_exceed) ||
2495+
!thd->trace_id.empty();
24622496
bool suppress_logging= log_throttle_qni.log(thd, warn_no_index);
24632497

24642498
if (!suppress_logging && log_this_query)

utils/CMakeLists.txt

+9
Original file line numberDiff line numberDiff line change
@@ -16,3 +16,12 @@
1616

1717
INCLUDE_DIRECTORIES(${CMAKE_SOURCE_DIR}/include
1818
${CMAKE_SOURCE_DIR}/mysys ${CMAKE_SOURCE_DIR}/utils)
19+
20+
SET(UTILS_SOURCES perf_counters.cc)
21+
22+
ADD_CONVENIENCE_LIBRARY(utils ${UTILS_SOURCES})
23+
24+
IF(MSVC)
25+
INSTALL_DEBUG_TARGET(utilscpp DESTINATION ${INSTALL_LIBDIR}/debug)
26+
ENDIF()
27+

utils/perf_counters.cc

+187
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,187 @@
1+
// Copyright 2004-present Facebook. All Rights Reserved.
2+
#include <memory>
3+
#include <cassert>
4+
#include "perf_counters.h"
5+
6+
#if FB_DYNO
7+
#include <dyno_counters.h>
8+
#endif
9+
10+
#include <ctime>
11+
12+
#define diff_timespec(TS1, TS2) \
13+
((TS1.tv_sec - TS2.tv_sec) * 1000000000ULL + TS1.tv_nsec - TS2.tv_nsec)
14+
15+
////////////////////////////////////////////////////////////////////////////////
16+
namespace utils {
17+
18+
template <class T> using unique_ptr = std::unique_ptr<T>;
19+
20+
class SimplePerfCounterFactory : public PerfCounterFactory {
21+
22+
std::shared_ptr<PerfCounter> makeSharedPerfCounter(
23+
PerfCounterMode mode, PerfCounterType c_type) override;
24+
25+
std::unique_ptr<PerfCounter> makePerfCounter(
26+
PerfCounterMode mode, PerfCounterType c_type) override;
27+
};
28+
29+
class ThreadPerfCounterImpl : public PerfCounter {
30+
private:
31+
PerfCounterType _counter_type;
32+
timespec _time_beg;
33+
bool _started;
34+
35+
uint64_t get_impl(timespec *time_cur);
36+
37+
public:
38+
explicit ThreadPerfCounterImpl(PerfCounterType counterType)
39+
: _counter_type(counterType), _started(false) { }
40+
41+
void start() override;
42+
void stop() override { _started= false; }
43+
uint64_t get() override {
44+
timespec time_cur;
45+
uint64_t diff_cost= get_impl(&time_cur);
46+
return diff_cost;
47+
}
48+
49+
uint64_t getAndRestart() override {
50+
timespec time_cur;
51+
uint64_t diff_cost= get_impl(&time_cur);
52+
_time_beg= time_cur;
53+
_started= true;
54+
return diff_cost;
55+
}
56+
uint64_t getAndStop() override {
57+
uint64_t diff_cost= get();
58+
_started= false;
59+
return diff_cost;
60+
}
61+
float getMultiplexFactor() override { return 1.0; }
62+
};
63+
64+
void ThreadPerfCounterImpl::start() {
65+
int cpu_res= clock_gettime(CLOCK_THREAD_CPUTIME_ID, &_time_beg);
66+
_started= (cpu_res == 0);
67+
}
68+
69+
uint64_t ThreadPerfCounterImpl::get_impl(timespec *time_cur) {
70+
if (!_started)
71+
return 0;
72+
73+
int cpu_cur= clock_gettime(CLOCK_THREAD_CPUTIME_ID, time_cur);
74+
if (cpu_cur != 0)
75+
return 0;
76+
77+
uint64_t diff_ns= diff_timespec((*time_cur), _time_beg);
78+
// assuming 2.4 GHz.
79+
return ((diff_ns * 1.0) / 0.41666);
80+
}
81+
82+
class ProcessPerfCounterImpl : public PerfCounter {
83+
public:
84+
explicit ProcessPerfCounterImpl(PerfCounterType counterType) {}
85+
86+
void start() override { }
87+
void stop() override { }
88+
uint64_t get() override { return 0; }
89+
uint64_t getAndRestart() override { return 0; }
90+
uint64_t getAndStop() override { return 0; }
91+
float getMultiplexFactor() override { return 1.0; }
92+
};
93+
94+
template <PerfCounterMode> struct CounterModeToType;
95+
96+
template <> struct CounterModeToType<PerfCounterMode::PCM_THREAD> {
97+
using type = ThreadPerfCounterImpl;
98+
};
99+
100+
template <> struct CounterModeToType<PerfCounterMode::PCM_PROCESS> {
101+
using type = ProcessPerfCounterImpl;
102+
};
103+
104+
template <class T> using unique_ptr = std::unique_ptr<T>;
105+
106+
template <template <typename> class T, class D, class... Args>
107+
struct PerfCounterMaker;
108+
109+
template <class D, class... Args>
110+
struct PerfCounterMaker<std::shared_ptr, D, Args...> {
111+
static std::shared_ptr<D> make(Args&&... args) {
112+
return std::make_shared<D>(std::forward<Args>(args)...);
113+
}
114+
};
115+
116+
template <class D, class... Args>
117+
struct PerfCounterMaker<unique_ptr, D, Args...> {
118+
static std::unique_ptr<D> make(Args&&... args) {
119+
return std::unique_ptr<D>(new D(std::forward<Args>(args)...));
120+
}
121+
};
122+
123+
template <template <typename> class T, PerfCounterMode mode, class... Args>
124+
T<PerfCounter> makePerfCounterBase(PerfCounterType counterType,
125+
Args&&... args) {
126+
return PerfCounterMaker<T, typename CounterModeToType<mode>::type,
127+
PerfCounterType, Args...>::make(std::forward<PerfCounterType>(counterType),
128+
std::forward<Args>(args)...);
129+
}
130+
131+
template <PerfCounterMode mode, class... Args>
132+
std::shared_ptr<PerfCounter> makeSharedPerfCounter(
133+
PerfCounterType counterType, Args&&... args) {
134+
return makePerfCounterBase<std::shared_ptr, mode, Args...>(
135+
counterType, std::forward<Args>(args)...);
136+
}
137+
138+
template <PerfCounterMode mode, class... Args>
139+
std::unique_ptr<PerfCounter> makePerfCounter(PerfCounterType counterType,
140+
Args&&... args) {
141+
return makePerfCounterBase<unique_ptr, mode, Args...>(
142+
counterType, std::forward<Args>(args)...);
143+
}
144+
145+
std::shared_ptr<PerfCounter> SimplePerfCounterFactory::makeSharedPerfCounter(
146+
PerfCounterMode mode, PerfCounterType c_type) {
147+
switch (mode) {
148+
case PerfCounterMode::PCM_THREAD :
149+
return utils::makeSharedPerfCounter<PerfCounterMode::PCM_THREAD>(c_type);
150+
case PerfCounterMode::PCM_PROCESS :
151+
return utils::makeSharedPerfCounter<PerfCounterMode::PCM_PROCESS>(c_type);
152+
default:
153+
assert(0);
154+
}
155+
return nullptr;
156+
}
157+
158+
std::unique_ptr<PerfCounter> SimplePerfCounterFactory::makePerfCounter(
159+
PerfCounterMode mode, PerfCounterType c_type) {
160+
switch (mode) {
161+
case PerfCounterMode::PCM_THREAD :
162+
return utils::makePerfCounter<PerfCounterMode::PCM_THREAD>(c_type);
163+
case PerfCounterMode::PCM_PROCESS :
164+
return utils::makePerfCounter<PerfCounterMode::PCM_PROCESS>(c_type);
165+
default:
166+
assert(0);
167+
}
168+
return nullptr;
169+
}
170+
171+
std::shared_ptr<PerfCounterFactory>
172+
PerfCounterFactory::getFactory(const std::string& factory_name) {
173+
174+
#if FB_DYNO
175+
// this should bleed into FB code and FB libraries
176+
if (factory_name == "dyno") {
177+
return DynoPerfCounterFactory();
178+
}
179+
#endif
180+
181+
if (factory_name == "simple") {
182+
return std::shared_ptr<PerfCounterFactory>(new SimplePerfCounterFactory);
183+
}
184+
return nullptr;
185+
}
186+
187+
}

0 commit comments

Comments
 (0)