OmniSciDB  a987f07e93
 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 2022 HEAVY.AI, 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 
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 
63  std::shared_ptr<Catalog_Namespace::SessionInfo const> const& session_info,
64  std::string query_str)
65  : session_data_(session_info ? boost::make_optional<SessionData>(session_info)
66  : boost::none)
67  , query_str_(std::move(query_str))
68  , logged_(false)
69  , submitted_(::toString(std::chrono::system_clock::now())) {}
70 
72  return createQueryStateProxy(events_.end());
73 }
74 
76  return QueryStateProxy(*this, parent);
77 }
78 
79 Timer QueryState::createTimer(char const* event_name, Events::iterator parent) {
80  std::lock_guard<std::mutex> lock(events_mutex_);
81  return Timer(shared_from_this(), events_.emplace(events_.end(), event_name, parent));
82 }
83 
84 std::shared_ptr<Catalog_Namespace::SessionInfo const> QueryState::getConstSessionInfo()
85  const {
86  if (!session_data_) {
87  throw std::runtime_error("session_info_ was not set for this QueryState.");
88  }
89  if (auto retval = session_data_->session_info.lock()) {
90  return retval;
91  } else {
92  // This can happen for a query on a database that is simultaneously dropped.
93  throw std::runtime_error("session_info requested but has expired.");
94  }
95 }
96 
97 void QueryState::setQuerySubmittedTime(const std::string& t) {
98  std::lock_guard<std::mutex> lock(events_mutex_);
99  submitted_ = t;
100 }
101 const std::string QueryState::getQuerySubmittedTime() const {
102  std::lock_guard<std::mutex> lock(events_mutex_);
103  return submitted_;
104 }
105 
106 // Assumes query_state_ is not null, and events_mutex_ is locked for this.
107 void QueryState::logCallStack(std::stringstream& ss,
108  unsigned const depth,
109  Events::iterator parent) {
110  auto it = parent == events_.end() ? events_.begin() : std::next(parent);
111  for (; it != events_.end(); ++it) {
112  if (it->parent == parent) {
113  auto duration = it->duration(); // std::optional, true if event completed
114  ss << '\n'
115  << std::setw(depth << 1) << ' ' << it->name << ' ' << it->thread_id
116  << " - total time " << (duration ? *duration : -1) << " ms";
117  logCallStack(ss, depth + 1, it);
118  // If events_ is expendable, then this can be put here to speed-up large lists.
119  // it = events_.erase(it); } else { ++it; } (and remove above ++it.)
120  }
121  }
122 }
123 
124 void QueryState::logCallStack(std::stringstream& ss) {
125  std::lock_guard<std::mutex> lock(events_mutex_);
126  logCallStack(ss, 1, events_.end());
127 }
128 
129 Timer QueryStateProxy::createTimer(char const* event_name) {
130  return query_state_.createTimer(event_name, parent_);
131 }
132 
133 Timer::Timer(std::shared_ptr<QueryState>&& query_state, Events::iterator event)
134  : query_state_(std::move(query_state)), event_(event) {
137 }
138 
140  return query_state_->createQueryStateProxy(event_);
141 }
142 
144  event_->stop();
146 }
147 
148 std::atomic<int64_t> StdLogData::s_match{0};
149 
150 std::shared_ptr<Catalog_Namespace::SessionInfo const> StdLog::getConstSessionInfo()
151  const {
152  return session_info_;
153 }
154 
155 std::shared_ptr<Catalog_Namespace::SessionInfo> StdLog::getSessionInfo() const {
156  return session_info_;
157 }
158 
160  std::string const& str;
161 };
162 
163 std::ostream& operator<<(std::ostream& os, QuoteFormatter const& quote_formatter) {
164  if (quote_formatter.str.find_first_of(" \"") == std::string::npos) {
165  return os << quote_formatter.str;
166  } else {
167  return os << std::quoted(quote_formatter.str, '"', '"');
168  }
169 }
170 
171 std::ostream& operator<<(std::ostream& os, SessionData const& session_data) {
172  return os << QuoteFormatter{session_data.db_name} << ' '
173  << QuoteFormatter{session_data.user_name} << ' '
174  << session_data.public_session_id;
175 }
176 
179 };
180 
181 std::ostream& operator<<(std::ostream& os, SessionInfoFormatter const& formatter) {
182  return os << QuoteFormatter{formatter.session_info.getCatalog().getCurrentDB().dbName}
183  << ' '
185  << ' ' << formatter.session_info.get_public_session_id();
186 }
187 
188 // Default severity for logging stdlog_begin lines is DEBUG1.
189 // Some functions, such as sql_execute, log them at INFO level.
191  logger::Severity const defaultSeverity = logger::Severity::DEBUG1;
192  static std::unordered_map<std::string_view, logger::Severity> const map{
193  {"connect", logger::Severity::INFO},
194  {"disconnect", logger::Severity::INFO},
195  {"switch_database", logger::Severity::INFO},
196  {"clone_session", logger::Severity::INFO},
197  {"get_tables_meta", logger::Severity::INFO},
198  {"get_table_details", logger::Severity::INFO},
199  {"sql_execute", logger::Severity::INFO},
200  {"sql_execute_df", logger::Severity::INFO},
201  {"sql_execute_gdf", logger::Severity::INFO},
202  {"sql_validate", logger::Severity::INFO},
203  {"render_vega", logger::Severity::INFO},
204  {"get_result_row_for_pixel", logger::Severity::INFO},
205  {"check_table_consistency", logger::Severity::INFO},
206  {"start_query", logger::Severity::INFO},
207  {"execute_query_step", logger::Severity::INFO},
208  {"broadcast_serialized_rows", logger::Severity::INFO},
209  {"start_render_query", logger::Severity::INFO},
210  {"execute_next_render_step", logger::Severity::INFO}};
211  auto const itr = map.find(func);
212  return itr == map.cend() ? defaultSeverity : itr->second;
213 }
214 
215 void StdLog::log(logger::Severity severity, char const* label) {
216  if (logger::fast_logging_check(severity)) {
217  std::stringstream ss;
219  ss << tlids.request_id_ << ' ' << tlids.thread_id_ << ' ' << file_ << ':' << line_
220  << ' ' << label << ' ' << func_ << ' ' << match_ << ' '
221  << duration<std::chrono::milliseconds>() << ' ';
222  if (session_info_) {
223  ss << SessionInfoFormatter{*session_info_} << ' ';
224  } else if (query_state_ && query_state_->getSessionData()) {
225  ss << *query_state_->getSessionData() << ' ';
226  } else {
227  ss << " "; // 3 spaces for 3 empty strings
228  }
229  auto const& nv = name_value_pairs_;
230  if (nv.empty() && (!query_state_ || query_state_->emptyLog())) {
231  ss << ' '; // 1 space for final empty names/values arrays
232  } else {
233  // All values are logged after all names, so separate values stream is needed.
234  std::stringstream values;
235  unsigned nvalues = 0;
236  if (query_state_ && !query_state_->getQueryStr().empty()) {
237  ss << (nvalues ? ',' : '{') << std::quoted("query_str", '"', '"');
238  values << (nvalues++ ? ',' : '{')
239  << std::quoted(hide_sensitive_data_from_query(query_state_->getQueryStr()),
240  '"',
241  '"');
242  }
243  for (auto itr = nv.cbegin(); itr != nv.cend(); ++itr) {
244  ss << (nvalues ? ',' : '{') << std::quoted(*itr, '"', '"');
245  values << (nvalues++ ? ',' : '{') << std::quoted(*++itr, '"', '"');
246  }
247  ss << "} " << values.rdbuf() << '}';
248  }
249  BOOST_LOG_SEV(logger::gSeverityLogger::get(), severity) << ss.rdbuf();
250  }
251 }
252 
253 void StdLog::logCallStack(logger::Severity severity, char const* label) {
254  if (logger::fast_logging_check(severity) && query_state_) {
255  std::stringstream ss;
257  ss << tlids.request_id_ << ' ' << tlids.thread_id_ << ' ' << file_ << ':' << line_
258  << ' ' << label << ' ' << func_ << ' ' << match_ << " total time "
259  << duration<std::chrono::milliseconds>() << " ms";
260  query_state_->logCallStack(ss);
261  BOOST_LOG_SEV(logger::gSeverityLogger::get(), severity) << ss.rdbuf();
262  }
263 }
264 
266  log(logger::Severity::INFO, "stdlog");
267  logCallStack(logger::Severity::DEBUG1, "stacked_times");
268  if (query_state_) {
269  query_state_->setLogged(true);
270  }
271  if (session_info_) {
272  session_info_->update_last_used_time();
273  }
274 }
275 
276 void StdLog::setQueryState(std::shared_ptr<QueryState> query_state) {
277  query_state_ = std::move(query_state);
278 }
279 
281  std::shared_ptr<Catalog_Namespace::SessionInfo> session_info) {
282  session_info_ = std::move(session_info);
283 }
284 
285 } // namespace query_state
std::string const & str
Definition: QueryState.cpp:160
std::string hide_sensitive_data_from_query(std::string const &query_str)
unsigned const line_
Definition: QueryState.h:243
boost::optional< SessionData > session_data_
Definition: QueryState.h:134
std::shared_ptr< QueryState > query_state_
Definition: QueryState.h:214
std::string const file_
Definition: QueryState.h:242
void logCallStack(std::stringstream &, unsigned const depth, Events::iterator parent)
Definition: QueryState.cpp:107
QueryStateProxy createQueryStateProxy()
Definition: QueryState.cpp:71
std::string const & get_public_session_id() const
Definition: SessionInfo.h:101
Events::iterator const parent_
Definition: QueryState.h:175
void omnisci_range_pop()
RequestId request_id_
Definition: Logger.h:135
void setQuerySubmittedTime(const std::string &t)
Definition: QueryState.cpp:97
void setSessionInfo(std::shared_ptr< Catalog_Namespace::SessionInfo >)
Definition: QueryState.cpp:280
Timer createTimer(char const *event_name)
Definition: QueryState.cpp:129
std::ostream & operator<<(std::ostream &os, QuoteFormatter const &quote_formatter)
Definition: QueryState.cpp:163
QueryState(std::shared_ptr< Catalog_Namespace::SessionInfo const > const &, std::string query_str)
Definition: QueryState.cpp:62
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:103
std::list< std::string > name_value_pairs_
Definition: QueryState.h:247
std::string submitted_
Definition: QueryState.h:139
bool fast_logging_check(Channel)
Definition: Logger.h:263
const DBMetadata & getCurrentDB() const
Definition: Catalog.h:248
static logger::Severity stdlogBeginSeverity(char const *func)
Definition: QueryState.cpp:190
void setQueryState(std::shared_ptr< QueryState >)
Definition: QueryState.cpp:276
void logCallStack(logger::Severity, char const *label)
Definition: QueryState.cpp:253
std::shared_ptr< Catalog_Namespace::SessionInfo > getSessionInfo() const
Definition: QueryState.cpp:155
Catalog_Namespace::SessionInfo const & session_info
Definition: QueryState.cpp:178
Timer(std::shared_ptr< QueryState > &&, Events::iterator event)
Definition: QueryState.cpp:133
std::string toString(const ExecutorDeviceType &device_type)
QueryStateProxy createQueryStateProxy()
Definition: QueryState.cpp:139
boost::log::sources::severity_logger_mt< Severity > SeverityLogger
Definition: Logger.cpp:58
std::shared_ptr< Catalog_Namespace::SessionInfo > session_info_
Definition: QueryState.h:262
Event(char const *const name, Events::iterator parent)
Definition: QueryState.cpp:43
static std::atomic< int64_t > s_match
Definition: QueryState.h:241
Catalog & getCatalog() const
Definition: SessionInfo.h:75
Severity
Definition: Logger.h:101
int64_t const match_
Definition: QueryState.h:246
std::shared_ptr< QueryState > query_state_
Definition: QueryState.h:263
ThreadId thread_id()
Definition: Logger.cpp:870
bool g_enable_watchdog false
Definition: Execute.cpp:79
#define CHECK(condition)
Definition: Logger.h:289
std::mutex events_mutex_
Definition: QueryState.h:137
char const *const func_
Definition: QueryState.h:244
Events::iterator event_
Definition: QueryState.h:215
std::string public_session_id
Definition: QueryState.h:125
void log(logger::Severity, char const *label)
Definition: QueryState.cpp:215
ThreadId thread_id_
Definition: Logger.h:136
string name
Definition: setup.in.py:72
std::shared_ptr< Catalog_Namespace::SessionInfo const > getConstSessionInfo() const
Definition: QueryState.cpp:150
std::string userLoggable() const
Definition: SysCatalog.cpp:158
std::shared_ptr< Catalog_Namespace::SessionInfo const > getConstSessionInfo() const
Definition: QueryState.cpp:84
Timer createTimer(char const *event_name, Events::iterator parent)
Definition: QueryState.cpp:79
const UserMetadata & get_currentUser() const
Definition: SessionInfo.h:88
ThreadLocalIds thread_local_ids()
Definition: Logger.cpp:873
std::chrono::steady_clock Clock
Definition: QueryState.h:92
const std::string getQuerySubmittedTime() const
Definition: QueryState.cpp:101