OmniSciDB  addbbd5075
 All Classes Namespaces Files Functions Variables Typedefs Enumerations Enumerator Friends Macros Pages
QueryState.cpp
Go to the documentation of this file.
1 /*
2  * Copyright 2019 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 
27 #include <algorithm>
28 #include <iomanip>
29 #include <string_view>
30 #include <unordered_map>
31 
32 namespace query_state {
33 
34 Event::Event(char const* name, Events::iterator parent)
35  : name(name)
36  , parent(parent)
37  , thread_id(std::this_thread::get_id())
38  , started(Clock::now().time_since_epoch())
39  , stopped(Clock::duration::zero()) {}
40 
41 void Event::stop() {
42  CHECK(stopped.exchange(Clock::now().time_since_epoch()) == Clock::duration::zero())
43  << "stop() called more than once.";
44 }
45 
47  std::shared_ptr<Catalog_Namespace::SessionInfo const> const& session_info)
48  : session_info(session_info)
49  , db_name(session_info->getCatalog().getCurrentDB().dbName)
50  , user_name(session_info->get_currentUser().userName)
51  , public_session_id(session_info->get_public_session_id()) {}
52 
53 std::atomic<query_state::Id> QueryState::s_next_id{0};
54 
56  std::shared_ptr<Catalog_Namespace::SessionInfo const> const& session_info,
57  std::string query_str)
58  : id_(s_next_id++)
59  , session_data_(session_info ? boost::make_optional<SessionData>(session_info)
60  : boost::none)
61  , query_str_(std::move(query_str))
62  , logged_(false) {}
63 
65  return createQueryStateProxy(events_.end());
66 }
67 
69  return QueryStateProxy(*this, parent);
70 }
71 
72 Timer QueryState::createTimer(char const* event_name, Events::iterator parent) {
73  std::lock_guard<std::mutex> lock(events_mutex_);
74  return Timer(shared_from_this(), events_.emplace(events_.end(), event_name, parent));
75 }
76 
77 std::shared_ptr<Catalog_Namespace::SessionInfo const> QueryState::getConstSessionInfo()
78  const {
79  if (!session_data_) {
80  throw std::runtime_error("session_info_ was not set for this QueryState.");
81  }
82  if (auto retval = session_data_->session_info.lock()) {
83  return retval;
84  } else {
85  // This can happen for a query on a database that is simultaneously dropped.
86  throw std::runtime_error("session_info requested but has expired.");
87  }
88 }
89 
90 // Assumes query_state_ is not null, and events_mutex_ is locked for this.
91 void QueryState::logCallStack(std::stringstream& ss,
92  unsigned const depth,
93  Events::iterator parent) {
94  auto it = parent == events_.end() ? events_.begin() : std::next(parent);
95  for (; it != events_.end(); ++it) {
96  if (it->parent == parent) {
97  auto duration = it->duration(); // std::optional, true if event completed
98  ss << '\n'
99  << std::setw(depth << 1) << ' ' << it->name << ' ' << it->thread_id
100  << " - total time " << (duration ? *duration : -1) << " ms";
101  logCallStack(ss, depth + 1, it);
102  // If events_ is expendable, then this can be put here to speed-up large lists.
103  // it = events_.erase(it); } else { ++it; } (and remove above ++it.)
104  }
105  }
106 }
107 
108 void QueryState::logCallStack(std::stringstream& ss) {
109  std::lock_guard<std::mutex> lock(events_mutex_);
110  logCallStack(ss, 1, events_.end());
111 }
112 
113 Timer QueryStateProxy::createTimer(char const* event_name) {
114  return query_state_.createTimer(event_name, parent_);
115 }
116 
117 Timer::Timer(std::shared_ptr<QueryState>&& query_state, Events::iterator event)
118  : query_state_(std::move(query_state)), event_(event) {}
119 
121  return query_state_->createQueryStateProxy(event_);
122 }
123 
125  event_->stop();
126 }
127 
128 std::atomic<int64_t> StdLogData::s_match{0};
129 
130 std::shared_ptr<Catalog_Namespace::SessionInfo const> StdLog::getConstSessionInfo()
131  const {
132  return session_info_;
133 }
134 
135 std::shared_ptr<Catalog_Namespace::SessionInfo> StdLog::getSessionInfo() const {
136  return session_info_;
137 }
138 
140  std::string const& str;
141 };
142 
143 std::ostream& operator<<(std::ostream& os, QuoteFormatter const& quote_formatter) {
144  if (quote_formatter.str.find_first_of(" \"") == std::string::npos) {
145  return os << quote_formatter.str;
146  } else {
147  return os << std::quoted(quote_formatter.str, '"', '"');
148  }
149 }
150 
151 std::ostream& operator<<(std::ostream& os, SessionData const& session_data) {
152  return os << QuoteFormatter{session_data.db_name} << ' '
153  << QuoteFormatter{session_data.user_name} << ' '
154  << session_data.public_session_id;
155 }
156 
159 };
160 
161 std::ostream& operator<<(std::ostream& os, SessionInfoFormatter const& formatter) {
162  return os << QuoteFormatter{formatter.session_info.getCatalog().getCurrentDB().dbName}
163  << ' ' << QuoteFormatter{formatter.session_info.get_currentUser().userName}
164  << ' ' << formatter.session_info.get_public_session_id();
165 }
166 
167 // Default severity for logging stdlog_begin lines is DEBUG1.
168 // Some functions, such as sql_execute, log them at INFO level.
170  logger::Severity const defaultSeverity = logger::Severity::DEBUG1;
171  static std::unordered_map<std::string_view, logger::Severity> const map{
172  {"sql_execute", logger::Severity::INFO}};
173  auto const itr = map.find(func);
174  return itr == map.cend() ? defaultSeverity : itr->second;
175 }
176 
177 void StdLog::log(logger::Severity severity, char const* label) {
178  if (logger::fast_logging_check(severity)) {
179  std::stringstream ss;
180  ss << file_ << ':' << line_ << ' ' << label << ' ' << func_ << ' ' << match_ << ' '
181  << duration<std::chrono::milliseconds>() << ' ';
182  if (session_info_) {
183  ss << SessionInfoFormatter{*session_info_} << ' ';
184  } else if (query_state_ && query_state_->getSessionData()) {
185  ss << *query_state_->getSessionData() << ' ';
186  } else {
187  ss << " "; // 3 spaces for 3 empty strings
188  }
189  auto const& nv = name_value_pairs_;
190  if (nv.empty() && (!query_state_ || query_state_->emptyLog())) {
191  ss << ' '; // 1 space for final empty names/values arrays
192  } else {
193  // All values are logged after all names, so separate values stream is needed.
194  std::stringstream values;
195  unsigned nvalues = 0;
196  if (query_state_ && !query_state_->getQueryStr().empty()) {
197  ss << (nvalues ? ',' : '{') << std::quoted("query_str", '"', '"');
198  values << (nvalues++ ? ',' : '{')
199  << std::quoted(hide_sensitive_data_from_query(query_state_->getQueryStr()),
200  '"',
201  '"');
202  }
203  for (auto itr = nv.cbegin(); itr != nv.cend(); ++itr) {
204  ss << (nvalues ? ',' : '{') << std::quoted(*itr, '"', '"');
205  values << (nvalues++ ? ',' : '{') << std::quoted(*++itr, '"', '"');
206  }
207  ss << "} " << values.rdbuf() << '}';
208  }
209  BOOST_LOG_SEV(logger::gSeverityLogger::get(), severity) << ss.rdbuf();
210  }
211 }
212 
213 void StdLog::logCallStack(logger::Severity severity, char const* label) {
214  if (logger::fast_logging_check(severity) && query_state_) {
215  std::stringstream ss;
216  ss << file_ << ':' << line_ << ' ' << label << ' ' << func_ << ' ' << match_
217  << " total time " << duration<std::chrono::milliseconds>() << " ms";
218  query_state_->logCallStack(ss);
219  BOOST_LOG_SEV(logger::gSeverityLogger::get(), severity) << ss.rdbuf();
220  }
221 }
222 
224  log(logger::Severity::INFO, "stdlog");
225  logCallStack(logger::Severity::DEBUG1, "stacked_times");
226  if (query_state_) {
227  query_state_->setLogged(true);
228  }
229  if (session_info_) {
230  session_info_->update_last_used_time();
231  }
232 }
233 
234 void StdLog::setQueryState(std::shared_ptr<QueryState> query_state) {
235  query_state_ = std::move(query_state);
236 }
237 
239  std::shared_ptr<Catalog_Namespace::SessionInfo> session_info) {
240  session_info_ = std::move(session_info);
241 }
242 
243 } // namespace query_state
std::string const & str
Definition: QueryState.cpp:140
std::string hide_sensitive_data_from_query(std::string const &query_str)
unsigned const line_
Definition: QueryState.h:234
boost::optional< SessionData > session_data_
Definition: QueryState.h:127
std::shared_ptr< QueryState > query_state_
Definition: QueryState.h:205
std::string const file_
Definition: QueryState.h:233
void logCallStack(std::stringstream &, unsigned const depth, Events::iterator parent)
Definition: QueryState.cpp:91
QueryStateProxy createQueryStateProxy()
Definition: QueryState.cpp:64
std::string const & get_public_session_id() const
Definition: SessionInfo.h:105
Events::iterator const parent_
Definition: QueryState.h:166
void setSessionInfo(std::shared_ptr< Catalog_Namespace::SessionInfo >)
Definition: QueryState.cpp:238
Timer createTimer(char const *event_name)
Definition: QueryState.cpp:113
std::ostream & operator<<(std::ostream &os, QuoteFormatter const &quote_formatter)
Definition: QueryState.cpp:143
QueryState(std::shared_ptr< Catalog_Namespace::SessionInfo const > const &, std::string query_str)
Definition: QueryState.cpp:55
This file contains the class specification and related data structures for Catalog.
std::atomic< Clock::duration > stopped
Definition: QueryState.h:94
std::list< std::string > name_value_pairs_
Definition: QueryState.h:238
CHECK(cgen_state)
bool fast_logging_check(Channel)
Definition: Logger.h:174
const DBMetadata & getCurrentDB() const
Definition: Catalog.h:176
static logger::Severity stdlogBeginSeverity(char const *func)
Definition: QueryState.cpp:169
void setQueryState(std::shared_ptr< QueryState >)
Definition: QueryState.cpp:234
void logCallStack(logger::Severity, char const *label)
Definition: QueryState.cpp:213
std::shared_ptr< Catalog_Namespace::SessionInfo > getSessionInfo() const
Definition: QueryState.cpp:135
Catalog_Namespace::SessionInfo const & session_info
Definition: QueryState.cpp:158
Timer(std::shared_ptr< QueryState > &&, Events::iterator event)
Definition: QueryState.cpp:117
QueryStateProxy createQueryStateProxy()
Definition: QueryState.cpp:120
std::shared_ptr< Catalog_Namespace::SessionInfo > session_info_
Definition: QueryState.h:253
Event(char const *const name, Events::iterator parent)
Definition: QueryState.cpp:34
static std::atomic< int64_t > s_match
Definition: QueryState.h:232
Catalog & getCatalog() const
Definition: SessionInfo.h:90
Severity
Definition: Logger.h:73
int64_t const match_
Definition: QueryState.h:237
std::shared_ptr< QueryState > query_state_
Definition: QueryState.h:254
bool g_enable_watchdog false
Definition: Execute.cpp:71
std::mutex events_mutex_
Definition: QueryState.h:130
char const *const func_
Definition: QueryState.h:235
Events::iterator event_
Definition: QueryState.h:206
std::string public_session_id
Definition: QueryState.h:116
void log(logger::Severity, char const *label)
Definition: QueryState.cpp:177
std::shared_ptr< Catalog_Namespace::SessionInfo const > getConstSessionInfo() const
Definition: QueryState.cpp:130
std::shared_ptr< Catalog_Namespace::SessionInfo const > getConstSessionInfo() const
Definition: QueryState.cpp:77
Timer createTimer(char const *event_name, Events::iterator parent)
Definition: QueryState.cpp:72
const UserMetadata & get_currentUser() const
Definition: SessionInfo.h:93
std::chrono::steady_clock Clock
Definition: QueryState.h:82
static std::atomic< Id > s_next_id
Definition: QueryState.h:125