OmniSciDB  d2f719934e
 All Classes Namespaces Files Functions Variables Typedefs Enumerations Enumerator Friends Macros Groups Pages
QueryState.cpp
Go to the documentation of this file.
1 /*
2  * Copyright 2021 OmniSci, Inc.
3  *
4  * Licensed under the Apache License, Version 2.0 (the "License");
5  * you may not use this file except in compliance with the License.
6  * You may obtain a copy of the License at
7  *
8  * http://www.apache.org/licenses/LICENSE-2.0
9  *
10  * Unless required by applicable law or agreed to in writing, software
11  * distributed under the License is distributed on an "AS IS" BASIS,
12  * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13  * See the License for the specific language governing permissions and
14  * limitations under the License.
15  */
16 
17 /*
18  * File: QueryState.cpp
19  * Author: matt.pulver@omnisci.com
20  *
21  */
22 
23 #include "QueryState.h"
24 #include "Catalog/Catalog.h"
25 #include "Catalog/SessionInfo.h"
26 #include "Shared/nvtx_helpers.h"
27 #include "Shared/toString.h"
28 
29 #include <algorithm>
30 #include <iomanip>
31 #include <string_view>
32 #include <unordered_map>
33 
34 #include "boost/log/common.hpp"
35 
36 namespace logger {
37 using SeverityLogger = boost::log::sources::severity_logger_mt<Severity>;
38 BOOST_LOG_GLOBAL_LOGGER(gSeverityLogger, SeverityLogger)
39 } // namespace logger
40 
41 namespace query_state {
42 
43 Event::Event(char const* name, Events::iterator parent)
44  : name(name)
45  , parent(parent)
46  , thread_id(std::this_thread::get_id())
47  , started(Clock::now().time_since_epoch())
48  , stopped(Clock::duration::zero()) {}
49 
50 void Event::stop() {
51  CHECK(stopped.exchange(Clock::now().time_since_epoch()) == Clock::duration::zero())
52  << "stop() called more than once.";
53 }
54 
56  std::shared_ptr<Catalog_Namespace::SessionInfo const> const& session_info)
57  : session_info(session_info)
58  , db_name(session_info->getCatalog().getCurrentDB().dbName)
59  , user_name(session_info->get_currentUser().userLoggable())
60  , public_session_id(session_info->get_public_session_id()) {}
61 
62 // The id to be given to the next QueryState.
63 std::atomic<logger::QueryId> QueryState::s_next_id{1};
64 
66  std::shared_ptr<Catalog_Namespace::SessionInfo const> const& session_info,
67  std::string query_str)
68  : id_(s_next_id++)
69  , session_data_(session_info ? boost::make_optional<SessionData>(session_info)
70  : boost::none)
71  , query_str_(std::move(query_str))
72  , logged_(false)
73  , submitted_(::toString(std::chrono::system_clock::now())) {}
74 
76  return createQueryStateProxy(events_.end());
77 }
78 
80  return QueryStateProxy(*this, parent);
81 }
82 
83 Timer QueryState::createTimer(char const* event_name, Events::iterator parent) {
84  std::lock_guard<std::mutex> lock(events_mutex_);
85  return Timer(shared_from_this(), events_.emplace(events_.end(), event_name, parent));
86 }
87 
88 std::shared_ptr<Catalog_Namespace::SessionInfo const> QueryState::getConstSessionInfo()
89  const {
90  if (!session_data_) {
91  throw std::runtime_error("session_info_ was not set for this QueryState.");
92  }
93  if (auto retval = session_data_->session_info.lock()) {
94  return retval;
95  } else {
96  // This can happen for a query on a database that is simultaneously dropped.
97  throw std::runtime_error("session_info requested but has expired.");
98  }
99 }
100 
101 void QueryState::setQuerySubmittedTime(const std::string& t) {
102  std::lock_guard<std::mutex> lock(events_mutex_);
103  submitted_ = t;
104 }
105 const std::string QueryState::getQuerySubmittedTime() const {
106  std::lock_guard<std::mutex> lock(events_mutex_);
107  return submitted_;
108 }
109 
110 // Changes g_query_id to id_ only if it was previously 0. Otherwise no effect.
113 }
114 
115 // Assumes query_state_ is not null, and events_mutex_ is locked for this.
116 void QueryState::logCallStack(std::stringstream& ss,
117  unsigned const depth,
118  Events::iterator parent) {
119  auto it = parent == events_.end() ? events_.begin() : std::next(parent);
120  for (; it != events_.end(); ++it) {
121  if (it->parent == parent) {
122  auto duration = it->duration(); // std::optional, true if event completed
123  ss << '\n'
124  << std::setw(depth << 1) << ' ' << it->name << ' ' << it->thread_id
125  << " - total time " << (duration ? *duration : -1) << " ms";
126  logCallStack(ss, depth + 1, it);
127  // If events_ is expendable, then this can be put here to speed-up large lists.
128  // it = events_.erase(it); } else { ++it; } (and remove above ++it.)
129  }
130  }
131 }
132 
133 void QueryState::logCallStack(std::stringstream& ss) {
134  std::lock_guard<std::mutex> lock(events_mutex_);
135  logCallStack(ss, 1, events_.end());
136 }
137 
138 Timer QueryStateProxy::createTimer(char const* event_name) {
139  return query_state_.createTimer(event_name, parent_);
140 }
141 
142 Timer::Timer(std::shared_ptr<QueryState>&& query_state, Events::iterator event)
143  : query_state_(std::move(query_state)), event_(event) {
146 }
147 
149  return query_state_->createQueryStateProxy(event_);
150 }
151 
153  event_->stop();
155 }
156 
157 std::atomic<int64_t> StdLogData::s_match{0};
158 
159 std::shared_ptr<Catalog_Namespace::SessionInfo const> StdLog::getConstSessionInfo()
160  const {
161  return session_info_;
162 }
163 
164 std::shared_ptr<Catalog_Namespace::SessionInfo> StdLog::getSessionInfo() const {
165  return session_info_;
166 }
167 
169  std::string const& str;
170 };
171 
172 std::ostream& operator<<(std::ostream& os, QuoteFormatter const& quote_formatter) {
173  if (quote_formatter.str.find_first_of(" \"") == std::string::npos) {
174  return os << quote_formatter.str;
175  } else {
176  return os << std::quoted(quote_formatter.str, '"', '"');
177  }
178 }
179 
180 std::ostream& operator<<(std::ostream& os, SessionData const& session_data) {
181  return os << QuoteFormatter{session_data.db_name} << ' '
182  << QuoteFormatter{session_data.user_name} << ' '
183  << session_data.public_session_id;
184 }
185 
188 };
189 
190 std::ostream& operator<<(std::ostream& os, SessionInfoFormatter const& formatter) {
191  return os << QuoteFormatter{formatter.session_info.getCatalog().getCurrentDB().dbName}
192  << ' '
194  << ' ' << formatter.session_info.get_public_session_id();
195 }
196 
197 // Default severity for logging stdlog_begin lines is DEBUG1.
198 // Some functions, such as sql_execute, log them at INFO level.
200  logger::Severity const defaultSeverity = logger::Severity::DEBUG1;
201  static std::unordered_map<std::string_view, logger::Severity> const map{
202  {"connect", logger::Severity::INFO},
203  {"disconnect", logger::Severity::INFO},
204  {"switch_database", logger::Severity::INFO},
205  {"clone_session", logger::Severity::INFO},
206  {"get_tables_meta", logger::Severity::INFO},
207  {"get_table_details", logger::Severity::INFO},
208  {"sql_execute", logger::Severity::INFO},
209  {"sql_execute_df", logger::Severity::INFO},
210  {"sql_execute_gdf", logger::Severity::INFO},
211  {"sql_validate", logger::Severity::INFO},
212  {"render_vega", logger::Severity::INFO},
213  {"get_result_row_for_pixel", logger::Severity::INFO},
214  {"check_table_consistency", logger::Severity::INFO},
215  {"start_query", logger::Severity::INFO},
216  {"execute_query_step", logger::Severity::INFO},
217  {"broadcast_serialized_rows", logger::Severity::INFO},
218  {"start_render_query", logger::Severity::INFO},
219  {"execute_next_render_step", logger::Severity::INFO}};
220  auto const itr = map.find(func);
221  return itr == map.cend() ? defaultSeverity : itr->second;
222 }
223 
224 void StdLog::log(logger::Severity severity, char const* label) {
225  if (logger::fast_logging_check(severity)) {
226  std::stringstream ss;
227  ss << logger::query_id() << ' ' << logger::thread_id() << ' ' << file_ << ':' << line_
228  << ' ' << label << ' ' << func_ << ' ' << match_ << ' '
229  << duration<std::chrono::milliseconds>() << ' ';
230  if (session_info_) {
231  ss << SessionInfoFormatter{*session_info_} << ' ';
232  } else if (query_state_ && query_state_->getSessionData()) {
233  ss << *query_state_->getSessionData() << ' ';
234  } else {
235  ss << " "; // 3 spaces for 3 empty strings
236  }
237  auto const& nv = name_value_pairs_;
238  if (nv.empty() && (!query_state_ || query_state_->emptyLog())) {
239  ss << ' '; // 1 space for final empty names/values arrays
240  } else {
241  // All values are logged after all names, so separate values stream is needed.
242  std::stringstream values;
243  unsigned nvalues = 0;
244  if (query_state_ && !query_state_->getQueryStr().empty()) {
245  ss << (nvalues ? ',' : '{') << std::quoted("query_str", '"', '"');
246  values << (nvalues++ ? ',' : '{')
247  << std::quoted(hide_sensitive_data_from_query(query_state_->getQueryStr()),
248  '"',
249  '"');
250  }
251  for (auto itr = nv.cbegin(); itr != nv.cend(); ++itr) {
252  ss << (nvalues ? ',' : '{') << std::quoted(*itr, '"', '"');
253  values << (nvalues++ ? ',' : '{') << std::quoted(*++itr, '"', '"');
254  }
255  ss << "} " << values.rdbuf() << '}';
256  }
257  BOOST_LOG_SEV(logger::gSeverityLogger::get(), severity) << ss.rdbuf();
258  }
259 }
260 
261 void StdLog::logCallStack(logger::Severity severity, char const* label) {
262  if (logger::fast_logging_check(severity) && query_state_) {
263  std::stringstream ss;
264  ss << file_ << ':' << line_ << ' ' << label << ' ' << func_ << ' ' << match_
265  << " total time " << duration<std::chrono::milliseconds>() << " ms";
266  query_state_->logCallStack(ss);
267  BOOST_LOG_SEV(logger::gSeverityLogger::get(), severity) << ss.rdbuf();
268  }
269 }
270 
272  log(logger::Severity::INFO, "stdlog");
273  logCallStack(logger::Severity::DEBUG1, "stacked_times");
274  if (query_state_) {
275  query_state_->setLogged(true);
276  }
277  if (session_info_) {
278  session_info_->update_last_used_time();
279  }
280 }
281 
282 void StdLog::setQueryState(std::shared_ptr<QueryState> query_state) {
283  query_state_ = std::move(query_state);
284 }
285 
287  std::shared_ptr<Catalog_Namespace::SessionInfo> session_info) {
288  session_info_ = std::move(session_info);
289 }
290 
291 } // namespace query_state
std::string const & str
Definition: QueryState.cpp:169
QidScopeGuard set_thread_local_query_id(QueryId const query_id)
Definition: Logger.cpp:483
std::string hide_sensitive_data_from_query(std::string const &query_str)
unsigned const line_
Definition: QueryState.h:244
boost::optional< SessionData > session_data_
Definition: QueryState.h:131
std::shared_ptr< QueryState > query_state_
Definition: QueryState.h:215
std::string const file_
Definition: QueryState.h:243
void logCallStack(std::stringstream &, unsigned const depth, Events::iterator parent)
Definition: QueryState.cpp:116
QueryStateProxy createQueryStateProxy()
Definition: QueryState.cpp:75
std::string toString(const ExtArgumentType &sig_type)
std::string const & get_public_session_id() const
Definition: SessionInfo.h:85
logger::QueryId const id_
Definition: QueryState.h:130
Events::iterator const parent_
Definition: QueryState.h:175
void omnisci_range_pop()
string name
Definition: setup.in.py:72
void setQuerySubmittedTime(const std::string &t)
Definition: QueryState.cpp:101
void setSessionInfo(std::shared_ptr< Catalog_Namespace::SessionInfo >)
Definition: QueryState.cpp:286
Timer createTimer(char const *event_name)
Definition: QueryState.cpp:138
std::ostream & operator<<(std::ostream &os, QuoteFormatter const &quote_formatter)
Definition: QueryState.cpp:172
logger::QidScopeGuard setThreadLocalQueryId() const
Definition: QueryState.cpp:111
QueryState(std::shared_ptr< Catalog_Namespace::SessionInfo const > const &, std::string query_str)
Definition: QueryState.cpp:65
void omnisci_range_push(Category c, const char *name, const char *file)
This file contains the class specification and related data structures for Catalog.
std::atomic< Clock::duration > stopped
Definition: QueryState.h:98
std::list< std::string > name_value_pairs_
Definition: QueryState.h:248
std::string submitted_
Definition: QueryState.h:136
bool fast_logging_check(Channel)
Definition: Logger.h:185
const DBMetadata & getCurrentDB() const
Definition: Catalog.h:225
static logger::Severity stdlogBeginSeverity(char const *func)
Definition: QueryState.cpp:199
void setQueryState(std::shared_ptr< QueryState >)
Definition: QueryState.cpp:282
void logCallStack(logger::Severity, char const *label)
Definition: QueryState.cpp:261
std::shared_ptr< Catalog_Namespace::SessionInfo > getSessionInfo() const
Definition: QueryState.cpp:164
Catalog_Namespace::SessionInfo const & session_info
Definition: QueryState.cpp:187
Timer(std::shared_ptr< QueryState > &&, Events::iterator event)
Definition: QueryState.cpp:142
QueryStateProxy createQueryStateProxy()
Definition: QueryState.cpp:148
boost::log::sources::severity_logger_mt< Severity > SeverityLogger
Definition: Logger.cpp:57
std::shared_ptr< Catalog_Namespace::SessionInfo > session_info_
Definition: QueryState.h:263
Event(char const *const name, Events::iterator parent)
Definition: QueryState.cpp:43
static std::atomic< int64_t > s_match
Definition: QueryState.h:242
Catalog & getCatalog() const
Definition: SessionInfo.h:67
Severity
Definition: Logger.h:89
int64_t const match_
Definition: QueryState.h:247
std::shared_ptr< QueryState > query_state_
Definition: QueryState.h:264
ThreadId thread_id()
Definition: Logger.cpp:816
static std::atomic< logger::QueryId > s_next_id
Definition: QueryState.h:129
bool g_enable_watchdog false
Definition: Execute.cpp:76
#define CHECK(condition)
Definition: Logger.h:211
QueryId query_id()
Definition: Logger.cpp:469
char * t
std::mutex events_mutex_
Definition: QueryState.h:134
char const *const func_
Definition: QueryState.h:245
Events::iterator event_
Definition: QueryState.h:216
std::string public_session_id
Definition: QueryState.h:120
void log(logger::Severity, char const *label)
Definition: QueryState.cpp:224
std::shared_ptr< Catalog_Namespace::SessionInfo const > getConstSessionInfo() const
Definition: QueryState.cpp:159
std::string userLoggable() const
Definition: SysCatalog.cpp:127
std::shared_ptr< Catalog_Namespace::SessionInfo const > getConstSessionInfo() const
Definition: QueryState.cpp:88
Timer createTimer(char const *event_name, Events::iterator parent)
Definition: QueryState.cpp:83
const UserMetadata & get_currentUser() const
Definition: SessionInfo.h:73
std::chrono::steady_clock Clock
Definition: QueryState.h:87
const std::string getQuerySubmittedTime() const
Definition: QueryState.cpp:105