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