From b01c01ee25c39075b2f965ea891430d5747e0af4 Mon Sep 17 00:00:00 2001 From: timifasubaa <30888507+timifasubaa@users.noreply.github.com> Date: Tue, 11 Sep 2018 08:52:37 -0700 Subject: [PATCH 1/3] [sqllab]More granular sqllab logging (#5736) * quote hive column names (#5368) * create db migration * use stats_logger timing * trigger build (cherry picked from commit 9a4bba485afb422734b13ffad991475f51291e99) --- superset/sql_lab.py | 26 ++++++++++++++++++-------- superset/views/core.py | 8 +++++++- 2 files changed, 25 insertions(+), 9 deletions(-) diff --git a/superset/sql_lab.py b/superset/sql_lab.py index 97dc32685c7a4..1da46e952f1ec 100644 --- a/superset/sql_lab.py +++ b/superset/sql_lab.py @@ -120,14 +120,14 @@ def convert_results_to_df(cursor_description, data): @celery_app.task(bind=True, soft_time_limit=SQLLAB_TIMEOUT) def get_sql_results( ctask, query_id, rendered_query, return_results=True, store_results=False, - user_name=None): + user_name=None, start_time=None): """Executes the sql query returns the results.""" with session_scope(not ctask.request.called_directly) as session: try: return execute_sql( ctask, query_id, rendered_query, return_results, store_results, user_name, - session=session) + session=session, start_time=start_time) except Exception as e: logging.exception(e) stats_logger.incr('error_sqllab_unhandled') @@ -141,10 +141,13 @@ def get_sql_results( def execute_sql( ctask, query_id, rendered_query, return_results=True, store_results=False, - user_name=None, session=None, + user_name=None, session=None, start_time=None, ): """Executes the sql query returns the results.""" - + if store_results: + # only asynchronous queries + stats_logger.timing( + 'sqllab.query.time_pending', utils.now_as_float() - start_time) query = get_query(query_id, session) payload = dict(query_id=query_id) @@ -215,11 +218,15 @@ def handle_error(msg): cursor = conn.cursor() logging.info('Running query: \n{}'.format(executed_sql)) logging.info(query.executed_sql) - db_engine_spec.execute(cursor, query.executed_sql, async=True) + query_start_time = utils.now_as_float() + db_engine_spec.execute(cursor, query.executed_sql, async_=True) logging.info('Handling cursor') db_engine_spec.handle_cursor(cursor, query, session) logging.info('Fetching data: {}'.format(query.to_dict())) data = db_engine_spec.fetch_data(cursor, query.limit) + stats_logger.timing( + 'sqllab.query.time_executing_query', + utils.now_as_float() - query_start_time) except SoftTimeLimitExceeded as e: logging.exception(e) if conn is not None: @@ -269,14 +276,17 @@ def handle_error(msg): if store_results: key = '{}'.format(uuid.uuid4()) logging.info('Storing results in results backend, key: {}'.format(key)) - json_payload = json.dumps(payload, default=utils.json_iso_dttm_ser) + write_to_results_backend_start = utils.now_as_float() + json_payload = json.dumps( + payload, default=utils.json_iso_dttm_ser, ignore_nan=True) cache_timeout = database.cache_timeout if cache_timeout is None: cache_timeout = config.get('CACHE_DEFAULT_TIMEOUT', 0) results_backend.set(key, utils.zlib_compress(json_payload), cache_timeout) query.results_key = key - query.end_result_backend_time = utils.now_as_float() - + stats_logger.timing( + 'sqllab.query.results_backend_write', + utils.now_as_float() - write_to_results_backend_start) session.merge(query) session.commit() diff --git a/superset/views/core.py b/superset/views/core.py index 3a78dab8cbf4e..a565e8a330434 100755 --- a/superset/views/core.py +++ b/superset/views/core.py @@ -2367,7 +2367,12 @@ def results(self, key): if not results_backend: return json_error_response("Results backend isn't configured") + read_from_results_backend_start = utils.now_as_float() blob = results_backend.get(key) + stats_logger.timing( + 'sqllab.query.results_backend_read', + read_from_results_backend_start - utils.now_as_float(), + ) if not blob: return json_error_response( 'Data could not be retrieved. ' @@ -2483,7 +2488,8 @@ def sql_json(self): rendered_query, return_results=False, store_results=not query.select_as_cta, - user_name=g.user.username) + user_name=g.user.username, + start_time=utils.now_as_float()) except Exception as e: logging.exception(e) msg = ( From a9077a92d6c97aefff0126dc951b47b9cba52aac Mon Sep 17 00:00:00 2001 From: timifasubaa <30888507+timifasubaa@users.noreply.github.com> Date: Tue, 11 Sep 2018 16:18:14 -0700 Subject: [PATCH 2/3] make access request open new tab (#5859) * make access request open new tab * trigger build (cherry picked from commit 01212c3755ba0368ed04e3126268571165639469) --- superset/assets/src/components/StackTraceMessage.jsx | 8 +++++++- 1 file changed, 7 insertions(+), 1 deletion(-) diff --git a/superset/assets/src/components/StackTraceMessage.jsx b/superset/assets/src/components/StackTraceMessage.jsx index 71b0972c25580..9253108d28602 100644 --- a/superset/assets/src/components/StackTraceMessage.jsx +++ b/superset/assets/src/components/StackTraceMessage.jsx @@ -38,7 +38,13 @@ class StackTraceMessage extends React.PureComponent { > {this.props.message} {this.hasLink() && - (Request Access) + + (Request Access) + } {this.hasTrace() && From 0cfc08eb5b9f342a4b01a7fb49b6ecee80ab3968 Mon Sep 17 00:00:00 2001 From: timifasubaa <30888507+timifasubaa@users.noreply.github.com> Date: Tue, 11 Sep 2018 17:23:44 -0700 Subject: [PATCH 3/3] fix sqllab logging (#5862) (cherry picked from commit c82cea3c8d0bc612501adfeaecca0ad3bf25fe1e) --- superset/sql_lab.py | 4 ++-- superset/views/core.py | 2 +- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/superset/sql_lab.py b/superset/sql_lab.py index 1da46e952f1ec..a8122478fa91f 100644 --- a/superset/sql_lab.py +++ b/superset/sql_lab.py @@ -144,7 +144,7 @@ def execute_sql( user_name=None, session=None, start_time=None, ): """Executes the sql query returns the results.""" - if store_results: + if store_results and start_time: # only asynchronous queries stats_logger.timing( 'sqllab.query.time_pending', utils.now_as_float() - start_time) @@ -219,7 +219,7 @@ def handle_error(msg): logging.info('Running query: \n{}'.format(executed_sql)) logging.info(query.executed_sql) query_start_time = utils.now_as_float() - db_engine_spec.execute(cursor, query.executed_sql, async_=True) + db_engine_spec.execute(cursor, query.executed_sql, async=True) logging.info('Handling cursor') db_engine_spec.handle_cursor(cursor, query, session) logging.info('Fetching data: {}'.format(query.to_dict())) diff --git a/superset/views/core.py b/superset/views/core.py index a565e8a330434..819fb9281682d 100755 --- a/superset/views/core.py +++ b/superset/views/core.py @@ -2371,7 +2371,7 @@ def results(self, key): blob = results_backend.get(key) stats_logger.timing( 'sqllab.query.results_backend_read', - read_from_results_backend_start - utils.now_as_float(), + utils.now_as_float() - read_from_results_backend_start, ) if not blob: return json_error_response(