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