OmniSciDB  d2f719934e
 All Classes Namespaces Files Functions Variables Typedefs Enumerations Enumerator Friends Macros Groups Pages
QueryState.h
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.h
19  * Author: matt.pulver@omnisci.com
20  *
21  */
22 
23 #ifndef OMNISCI_THRIFTHANDLER_QUERYSTATE_H
24 #define OMNISCI_THRIFTHANDLER_QUERYSTATE_H
25 
26 #include "Logger/Logger.h"
27 #include "Shared/StringTransform.h"
28 
29 #include <boost/circular_buffer.hpp>
30 #include <boost/filesystem.hpp>
31 #include <boost/noncopyable.hpp>
32 #include <boost/optional.hpp>
33 #include <boost/preprocessor.hpp>
34 
35 #include <atomic>
36 #include <chrono>
37 #include <list>
38 #include <memory>
39 #include <mutex>
40 #include <sstream>
41 #include <string>
42 #include <thread>
43 
44 /* See docs/QueryState.md for documentation.
45  *
46  * Outline:
47  * - Consolidate information about current and past queries.
48  * - DEPRECATION NOTICE:
49  * Timer and Event-related logic is replaced by logger::DebugTimer.
50  * For adding new timings, please see Logger.h instead.
51  * - Time and record code blocks, and save to stdlog.
52  *
53  * Classes:
54  * - StdLog - logs to DEBUG1 on construction, INFO on destruction.
55  * - QueryState - hold info on the evolution of a query.
56  * - QueryStateProxy - Light-weight QueryState wrapper to track Timer/Event nesting.
57  * - Timer - Created by QueryStateProxy to log function/block lifetime.
58  *
59  * Basic API Usage:
60  * - auto stdlog = STDLOG() // May include session_info, name/value pairs.
61  * - auto query_state = query_states_.create(get_session_ptr(session), query_str);
62  * - stdlog.setQueryState(query_state); // Log query_state when stdlog destructs.
63  * - auto query_state_proxy = query_state.createQueryStateProxy();
64  * - auto timer = query_state_proxy.createTimer(__func__);
65  */
66 
67 /* Notes:
68  * - QueryStates holds many QueryState instances.
69  * - QueryState holds many Event instances.
70  * - QueryState and QueryStateProxy can create Timers.
71  * - QueryState and Timer can create QueryStateProxies.
72  * - Timers and Events are one-to-one.
73  * - When StdLog destructs, it logs all of the associated QueryState's Events.
74  *
75  * Q: Why are logger::QueryId and related items defined in logger instead of query_state?
76  * A: Logger needs to log the query_id in each log line.
77  * Rather than #include "QueryState.h", which would create a circular dependency,
78  * defining QueryId in Logger minimizes the coupling between Logger and QueryState.
79  */
80 
81 namespace Catalog_Namespace {
82 class SessionInfo;
83 }
84 
85 namespace query_state {
86 
87 using Clock = std::chrono::steady_clock;
88 
89 struct Event;
90 using Events = std::list<Event>;
91 
92 struct Event {
93  char const* const name;
94  Events::iterator const parent; // events_.end() = top level query_state
95  std::thread::id const thread_id;
96  Clock::duration const started;
97  // duration is used instead of time_point since it is trivially copyable for atomic.
98  std::atomic<Clock::duration> stopped;
99  Event(char const* const name, Events::iterator parent);
100  template <typename Units = std::chrono::milliseconds>
101  boost::optional<typename Units::rep> duration() const {
102  auto const stop_time = stopped.load();
103  return boost::make_optional(
104  stop_time != Clock::duration::zero(),
105  std::chrono::duration_cast<Units>(stop_time - started).count());
106  }
107  void stop();
108 };
109 
110 using EventFunction = std::function<void(Event const&)>;
111 
112 class QueryStateProxy;
113 class QueryStates;
114 
115 // SessionInfo can expire, so data is copied while available.
116 struct SessionData {
117  std::weak_ptr<Catalog_Namespace::SessionInfo const> session_info;
118  std::string db_name;
119  std::string user_name;
120  std::string public_session_id;
121 
122  SessionData() = default;
123  SessionData(std::shared_ptr<Catalog_Namespace::SessionInfo const> const&);
124 };
125 
126 class Timer;
127 
128 class QueryState : public std::enable_shared_from_this<QueryState> {
129  static std::atomic<logger::QueryId> s_next_id;
131  boost::optional<SessionData> session_data_;
132  std::string const query_str_;
134  mutable std::mutex events_mutex_;
135  std::atomic<bool> logged_;
136  std::string submitted_;
137  void logCallStack(std::stringstream&, unsigned const depth, Events::iterator parent);
138 
139  // Only shared_ptr instances are allowed due to call to shared_from_this().
140  QueryState(std::shared_ptr<Catalog_Namespace::SessionInfo const> const&,
141  std::string query_str);
142 
143  public:
144  template <typename... ARGS>
145  static std::shared_ptr<QueryState> create(ARGS&&... args) {
146  // Trick to call std::make_shared with private constructors.
147  struct EnableMakeShared : public QueryState {
148  EnableMakeShared(ARGS&&... args) : QueryState(std::forward<ARGS>(args)...) {}
149  };
150  return std::make_shared<EnableMakeShared>(std::forward<ARGS>(args)...);
151  }
153  QueryStateProxy createQueryStateProxy(Events::iterator parent);
154  Timer createTimer(char const* event_name, Events::iterator parent);
155  inline bool emptyLog() const { return events_.empty() && query_str_.empty(); }
156  inline logger::QueryId getId() const { return id_; }
157  inline std::string const& getQueryStr() const { return query_str_; }
158  // Will throw exception if session_data_.session_info.expired().
159  std::shared_ptr<Catalog_Namespace::SessionInfo const> getConstSessionInfo() const;
160  boost::optional<SessionData> const& getSessionData() const { return session_data_; }
161  inline bool isLogged() const { return logged_.load(); }
162  void logCallStack(std::stringstream&);
163  // Set logger::g_query_id based on id_ member variable.
165  void setQuerySubmittedTime(const std::string& t);
166  const std::string getQuerySubmittedTime() const;
167  inline void setLogged(bool logged) { logged_.store(logged); }
168  friend class QueryStates;
169 };
170 
171 // Light-weight class used as intermediary between Timer objects spawning child Timers.
172 // Assumes lifetime is less than original QueryState.
175  Events::iterator const parent_;
176 
177  public:
178  QueryStateProxy(QueryState& query_state, Events::iterator parent)
179  : query_state_(query_state), parent_(parent) {}
180  Timer createTimer(char const* event_name);
182  const QueryState& getConstQueryState() const { return query_state_; }
183 };
184 
185 // At this point it is not clear how long we want to keep completed queries.
186 // The data structure and lifetime are not currently settled upon.
187 class QueryStates {
188  using CircleBuffer = boost::circular_buffer<std::shared_ptr<QueryState>>;
189  // constexpr size_t MAX_SIZE_BEFORE_OVERWRITE = 128; // C++17
191  std::mutex circle_mutex_;
192 
193  public:
194  template <typename... ARGS>
195  CircleBuffer::value_type create(ARGS&&... args) {
196  std::lock_guard<std::mutex> lock(circle_mutex_);
197  /* Logic for ensuring QueryState objects are logged before deleting them.
198  if (circle_buffer_.full() && !circle_buffer_.front()->isLogged()) {
199  constexpr size_t MAX_SIZE_BEFORE_OVERWRITE = 128;
200  if (circle_buffer_.size() < MAX_SIZE_BEFORE_OVERWRITE) {
201  circle_buffer_.set_capacity(2 * circle_buffer_.capacity());
202  } else {
203  LOG(ERROR) << "QueryStates is holding " << circle_buffer_.size()
204  << " queries but the oldest query_state has not completed
205  logging.";
206  }
207  }
208  */
209  circle_buffer_.push_back(QueryState::create(std::forward<ARGS>(args)...));
210  return circle_buffer_.back();
211  }
212 };
213 
214 class Timer {
215  std::shared_ptr<QueryState> query_state_;
216  Events::iterator event_; // = pointer into QueryState::events_
217 
218  public:
219  Timer(std::shared_ptr<QueryState>&&, Events::iterator event);
220  Timer(Timer const&) = delete;
221  Timer& operator=(Timer const&) = delete;
222  Timer(Timer&&) = default;
223  Timer& operator=(Timer&&) = default;
224  ~Timer();
226 };
227 
228 // Log Format:
229 // YYYY-MM-DDTHH:MM::SS.FFFFFF [S] [pid] [file]:[line] [label] [func] [match] [dur_ms]
230 // [dbname] [user] [pubsessid] {[names]} {[values]}
231 // Call at both beginning(label="stdlog_begin") and end(label="stdlog") of Thrift call,
232 // with dur_ms = current age of StdLog object in milliseconds.
233 // stdlog_begin is logged at DEBUG1 level, stdlog is logged at INFO level.
234 // All remaining optional parameters are name,value pairs that will be included in log.
235 #define STDLOG(...) \
236  BOOST_PP_IF(BOOST_PP_IS_EMPTY(__VA_ARGS__), \
237  query_state::StdLog(__FILE__, __LINE__, __func__), \
238  query_state::StdLog(__FILE__, __LINE__, __func__, __VA_ARGS__))
239 
240 class StdLogData {
241  protected:
242  static std::atomic<int64_t> s_match;
243  std::string const file_;
244  unsigned const line_;
245  char const* const func_;
246  Clock::time_point const start_;
247  int64_t const match_; // Unique to each begin/end pair to match them together.
248  std::list<std::string> name_value_pairs_;
249  template <typename... Pairs>
250  StdLogData(char const* file, unsigned line, char const* func, Pairs&&... pairs)
251  : file_(boost::filesystem::path(file).filename().string())
252  , line_(line)
253  , func_(func)
254  , start_(Clock::now())
255  , match_(s_match++)
256  , name_value_pairs_{to_string(std::forward<Pairs>(pairs))...} {
257  static_assert(sizeof...(Pairs) % 2 == 0,
258  "StdLogData() requires an even number of name/value parameters.");
259  }
260 };
261 
262 class StdLog : public StdLogData {
263  std::shared_ptr<Catalog_Namespace::SessionInfo> session_info_;
264  std::shared_ptr<QueryState> query_state_;
265  void log(logger::Severity, char const* label);
266  void logCallStack(logger::Severity, char const* label);
267  static logger::Severity stdlogBeginSeverity(char const* func);
268 
269  public:
270  template <typename... Pairs>
271  StdLog(char const* file,
272  unsigned line,
273  char const* func,
274  std::shared_ptr<Catalog_Namespace::SessionInfo> session_info,
275  Pairs&&... pairs)
276  : StdLogData(file, line, func, std::forward<Pairs>(pairs)...)
277  , session_info_(std::move(session_info)) {
278  log(stdlogBeginSeverity(func), "stdlog_begin");
279  }
280 
281  template <typename... Pairs>
282  StdLog(char const* file,
283  unsigned line,
284  char const* func,
285  std::shared_ptr<Catalog_Namespace::SessionInfo> session_info,
286  std::shared_ptr<QueryState> query_state,
287  Pairs&&... pairs)
288  : StdLogData(file, line, func, std::forward<Pairs>(pairs)...)
289  , session_info_(std::move(session_info))
290  , query_state_(std::move(query_state)) {
291  log(stdlogBeginSeverity(func), "stdlog_begin");
292  }
293 
294  template <typename... Pairs>
295  StdLog(char const* file,
296  unsigned line,
297  char const* func,
298  std::shared_ptr<QueryState> query_state,
299  Pairs&&... pairs)
300  : StdLogData(file, line, func, std::forward<Pairs>(pairs)...)
301  , query_state_(std::move(query_state)) {
302  log(stdlogBeginSeverity(func), "stdlog_begin");
303  }
304  template <typename... Pairs>
305  StdLog(char const* file, unsigned line, char const* func, Pairs&&... pairs)
306  : StdLogData(file, line, func, std::forward<Pairs>(pairs)...) {
307  log(stdlogBeginSeverity(func), "stdlog_begin");
308  }
309  StdLog(StdLog const&) = delete;
310  StdLog(StdLog&&) = default;
311  ~StdLog();
312  template <typename... Pairs>
313  void appendNameValuePairs(Pairs&&... pairs) {
314  static_assert(sizeof...(Pairs) % 2 == 0,
315  "appendNameValuePairs() requires an even number of parameters.");
316  name_value_pairs_.splice(name_value_pairs_.cend(),
317  {to_string(std::forward<Pairs>(pairs))...});
318  }
319  template <typename Units = std::chrono::milliseconds>
320  typename Units::rep duration() const {
321  return std::chrono::duration_cast<Units>(Clock::now() - start_).count();
322  }
323  std::shared_ptr<Catalog_Namespace::SessionInfo const> getConstSessionInfo() const;
324  std::shared_ptr<Catalog_Namespace::SessionInfo> getSessionInfo() const;
325  void setQueryState(std::shared_ptr<QueryState>);
326  void setSessionInfo(std::shared_ptr<Catalog_Namespace::SessionInfo>);
327 };
328 
329 } // namespace query_state
330 
331 #endif // OMNISCI_THRIFTHANDLER_QUERYSTATE_H
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
boost::optional< SessionData > const & getSessionData() const
Definition: QueryState.h:160
const QueryState & getConstQueryState() const
Definition: QueryState.h:182
std::string const & getQueryStr() const
Definition: QueryState.h:157
logger::QueryId const id_
Definition: QueryState.h:130
Events::iterator const parent_
Definition: QueryState.h:175
Clock::duration const started
Definition: QueryState.h:96
static std::shared_ptr< QueryState > create(ARGS &&...args)
Definition: QueryState.h:145
void setQuerySubmittedTime(const std::string &t)
Definition: QueryState.cpp:101
Timer & operator=(Timer const &)=delete
CircleBuffer::value_type create(ARGS &&...args)
Definition: QueryState.h:195
Events::iterator const parent
Definition: QueryState.h:94
void setSessionInfo(std::shared_ptr< Catalog_Namespace::SessionInfo >)
Definition: QueryState.cpp:286
Timer createTimer(char const *event_name)
Definition: QueryState.cpp:138
std::string to_string(char const *&&v)
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
Units::rep duration() const
Definition: QueryState.h:320
uint64_t QueryId
Definition: Logger.h:324
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
StdLogData(char const *file, unsigned line, char const *func, Pairs &&...pairs)
Definition: QueryState.h:250
logger::QueryId getId() const
Definition: QueryState.h:156
void setLogged(bool logged)
Definition: QueryState.h:167
boost::circular_buffer< std::shared_ptr< QueryState >> CircleBuffer
Definition: QueryState.h:188
std::string const query_str_
Definition: QueryState.h:132
static logger::Severity stdlogBeginSeverity(char const *func)
Definition: QueryState.cpp:199
QueryState & getQueryState()
Definition: QueryState.h:181
void setQueryState(std::shared_ptr< QueryState >)
Definition: QueryState.cpp:282
int count
StdLog(char const *file, unsigned line, char const *func, std::shared_ptr< Catalog_Namespace::SessionInfo > session_info, Pairs &&...pairs)
Definition: QueryState.h:271
void logCallStack(logger::Severity, char const *label)
Definition: QueryState.cpp:261
std::shared_ptr< Catalog_Namespace::SessionInfo > getSessionInfo() const
Definition: QueryState.cpp:164
QueryStateProxy(QueryState &query_state, Events::iterator parent)
Definition: QueryState.h:178
std::thread::id const thread_id
Definition: QueryState.h:95
Timer(std::shared_ptr< QueryState > &&, Events::iterator event)
Definition: QueryState.cpp:142
StdLog(char const *file, unsigned line, char const *func, std::shared_ptr< QueryState > query_state, Pairs &&...pairs)
Definition: QueryState.h:295
QueryStateProxy createQueryStateProxy()
Definition: QueryState.cpp:148
std::shared_ptr< Catalog_Namespace::SessionInfo > session_info_
Definition: QueryState.h:263
std::weak_ptr< Catalog_Namespace::SessionInfo const > session_info
Definition: QueryState.h:117
std::list< Event > Events
Definition: QueryState.h:90
Event(char const *const name, Events::iterator parent)
Definition: QueryState.cpp:43
void appendNameValuePairs(Pairs &&...pairs)
Definition: QueryState.h:313
static std::atomic< int64_t > s_match
Definition: QueryState.h:242
tuple line
Definition: parse_ast.py:10
Severity
Definition: Logger.h:89
boost::optional< typename Units::rep > duration() const
Definition: QueryState.h:101
int64_t const match_
Definition: QueryState.h:247
std::shared_ptr< QueryState > query_state_
Definition: QueryState.h:264
static std::atomic< logger::QueryId > s_next_id
Definition: QueryState.h:129
Clock::time_point const start_
Definition: QueryState.h:246
std::function< void(Event const &)> EventFunction
Definition: QueryState.h:110
StdLog(char const *file, unsigned line, char const *func, std::shared_ptr< Catalog_Namespace::SessionInfo > session_info, std::shared_ptr< QueryState > query_state, Pairs &&...pairs)
Definition: QueryState.h:282
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
StdLog(char const *file, unsigned line, char const *func, Pairs &&...pairs)
Definition: QueryState.h:305
std::string public_session_id
Definition: QueryState.h:120
bool emptyLog() const
Definition: QueryState.h:155
void log(logger::Severity, char const *label)
Definition: QueryState.cpp:224
std::shared_ptr< Catalog_Namespace::SessionInfo const > getConstSessionInfo() const
Definition: QueryState.cpp:159
CircleBuffer circle_buffer_
Definition: QueryState.h:190
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
std::chrono::steady_clock Clock
Definition: QueryState.h:87
const std::string getQuerySubmittedTime() const
Definition: QueryState.cpp:105
std::atomic< bool > logged_
Definition: QueryState.h:135
char const *const name
Definition: QueryState.h:93
bool isLogged() const
Definition: QueryState.h:161