[sqllab]More granular sqllab logging #5736
Conversation
timifasubaa
force-pushed
the
more_granular_sqllab_logging
branch
from
a5a1ce5 to
77d947b
Compare
|
|
||
|
|
||
| def upgrade(): | ||
| op.alter_column('query', 'start_running_time', nullable=False, new_column_name='time_at_db') |
There was a problem hiding this comment.
This table tends to have hanging locks and is hard to alter. I've had issue every time I've had to alter this model where it just completely lock up everything. We'd all need to schedule downtime to allow for this.
There was a problem hiding this comment.
Maybe we can use some sort of tracing instead.
There was a problem hiding this comment.
@mistercrunch Can you flesh this out a little more or provide an example? I'll be happy to investigate.
There was a problem hiding this comment.
I mean just using statsd.timing(DURATION)
timifasubaa
force-pushed
the
more_granular_sqllab_logging
branch
4 times, most recently
from
a7fc4c0 to
b389888
Compare
timifasubaa
force-pushed
the
more_granular_sqllab_logging
branch
2 times, most recently
from
f7e5a4f to
8bf7603
Compare
timifasubaa
changed the title
timifasubaa
force-pushed
the
more_granular_sqllab_logging
branch
2 times, most recently
from
f4b25d2 to
0e2af38
Compare
Codecov Report
@@ Coverage Diff @@
## master #5736 +/- ##
==========================================
- Coverage 63.75% 63.74% -0.01%
==========================================
Files 374 374
Lines 23320 23330 +10
Branches 2608 2608
==========================================
+ Hits 14867 14872 +5
- Misses 8440 8445 +5
Partials 13 13
Continue to review full report at Codecov.
|
timifasubaa
force-pushed
the
more_granular_sqllab_logging
branch
3 times, most recently
from
60c7fbb to
eeeca47
Compare
There was a problem hiding this comment.
For the statsD key it seems like they should potentially by more descriptive, i.e., start with the sqllab prefix so rather than time_pending it could be something like sqllab.query.time_pending. You can look at Datadog for examples of how other applications define their keys.
superset/sql_lab.py
Outdated
| 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('time_in_database', utils.now_as_float() - query_start_time) |
There was a problem hiding this comment.
I wonder if there's a better (more descriptive) name than time_in_database? May time_executing_query?
timifasubaa
force-pushed
the
more_granular_sqllab_logging
branch
from
eeeca47 to
ef7c4fe
Compare
|
That makes sense. I updated the names. |
timifasubaa
force-pushed
the
more_granular_sqllab_logging
branch
from
ef7c4fe to
61f63fe
Compare
timifasubaa
force-pushed
the
more_granular_sqllab_logging
branch
from
61f63fe to
2989409
Compare
* quote hive column names (apache#5368) * create db migration * use stats_logger timing * trigger build (cherry picked from commit 9a4bba4)
* quote hive column names (apache#5368) * create db migration * use stats_logger timing * trigger build
* quote hive column names (apache#5368) * create db migration * use stats_logger timing * trigger build
mistercrunch
added
🏷️ bot
This PR improves how sqllab logs its performance by logging at a more granular level primarily for asynchronous queries.
It logs the
(for asynchroous queries) time spent pending
time spent in the database
time spent writing to results_backend
time spent time spent reading from results_backend
This PR depends on #5844
@mistercrunch @john-bodley