def after_request(response):
for query in get_debug_queries():
if query.duration >= current_app.config['FLASKY_SLOW_DB_QUERY_TIME']:
current_app.logger.warning(
'Slow query:%s\nParameters:%s\nDuration:%fs\nContext:%s\n'
%(query.statement,query.parameters,query.duration,query.context))
return response
def after_request(response):
for query in get_debug_queries():
current_app.logger.warning(
'Slow query: %s\nParameters: %s\nDuration: %fs\nContext: %s\n'
% (query.statement, query.parameters, query.duration,
query.context))
return response
def wrapper(*args, **kw):
try:
result = func(*args, **kw)
# record the slow sql execution
for query in get_debug_queries():
if query.duration >= current_app.config[
'FLASK_SLOW_DB_QUERY_TIMEOUT']:
logging.warning(
'Slow query: {}\nParameters: {}\nDuration: {} seconds\nContext: {}\n'
.format(query.statement, query.parameters,
query.duration, query.context))
except SQLAlchemyError:
logging.exception("Exception found in {}".format(func.__name__))
subject = "Exception found in {}".format(func.__name__)
db.session.rollback()
# get the exception logs
body = str("\n".join(traceback.format_tb(sys.exc_info()[2])))
from app.util.common import send_mail
send_mail(subject, body)
result = make_response("SQL Error", 500)
finally:
db.session.remove()
return result
def query_profiler(response):
for q in get_debug_queries():
if q.duration >= app.config['BLUELOG_SLOW_QUERY_THRESHOLD']:
app.logger.warning(
'Slow query: Duration: %fs\n Context: %s\nQuery: %s\n ' %
(q.duration, q.context, q.statement))
return response
def after_request(response):
for query in get_debug_queries():
if query.duration >= current_app.config['FLASKY_SLOW_DB_QUERY_TIME']:
current_app.logger.warning('树懒查询: %s\n参数: %s\n耗时: %fs\n上下文: %s\n' %
(query.statement, query.parameters,
query.duration, query.context))
return response
def get_debug_queries_summary(debug_queries=None, collapse_whitespace=True, collapse_select_clauses=False):
"""Generate a summary of the SQL queries gathered by Flask-SQLAlchemy during the course of this request."""
if debug_queries is None:
debug_queries = get_debug_queries()
r = []
total_duration = 0
for i, q in enumerate(sorted(debug_queries, key=lambda x: x.start_time)):
total_duration += q.duration
# Clean up query statement and substitute parameters
stmt, params = format_query_statement(
q.statement,
q.parameters,
collapse_whitespace=collapse_whitespace,
collapse_select_clauses=collapse_select_clauses)
# Construct the output buffer
b = [u'-' * 80, u"Query #{}:".format(i + 1), u'> ' + stmt]
if params:
b.append(u"Params: {}".format(params))
if q.context and q.context != '<unknown>':
b.append(u"Context: {}".format(q.context))
b.append(u"Duration: {}".format(q.duration))
r.append(u'\n'.join(b))
summary = [
u"{border}\nQuery Summary\n{border}".format(border=(u'=' * 80)),
u"Num Queries: {}".format(len(r)),
u"Total Duration: {}".format(total_duration)
]
return u'\n'.join(summary) + u'\n' + u'\n'.join(r)
def after_quest(response):
for query in get_debug_queries():
if query.duration >= current_app_config['FLASKY_SLOW_DB_QUERY_TIME']:
current_app.logger.warning(
'Slow query: %s\nParameters: %s\nDuration: %fs\nnContext: %s\n' %
(query.statement, query.parameters, query.duration,
query.context))
def after_request(response):
for query in get_debug_queries():
if query.duration >= current_app.config['FLASKY_SLOW_DB_QUERY_TIME']:
current_app.logger.warning(
f'Slow query: {query.statement}\nParameters: {query.parameters}\n'
f'Duration: {query.duration}s\nContext: {query.context}\n')
return response
def sql_log():
info = get_debug_queries()
for i in info:
print('\n--------\n')
print('Query: ', i.statement, i.parameters)
print('Execute time: ', i.duration)
print('\n--------\n')
def debug_teardown_request(exception):
"""Log slow responses and queries."""
url = request.url
response_time = time.time() - g.start
if response_time >= 0.1:
msg = '{url} - slow response ({response_time:.2f} seconds)'
print(colored(msg.format(url=url, response_time=response_time), 'yellow'))
total_query_time = 0
queries = defaultdict(lambda: [0, 0])
for q in get_debug_queries():
queries[q.statement][0] += 1 # number of time query run
queries[q.statement][1] += q.duration # total time for query
total_query_time += q.duration # total time for all queries
# Queries taking longer than 0.1 seconds (slowest first)
queries = [(k, v[0], v[1]) for k, v in queries.items()]
queries = [x for x in queries if x[2] >= 0.1]
queries.sort(key=lambda x: x[1], reverse=True)
for query, times_run, query_time in queries:
if times_run > 1:
message = '{url} - slow query ({query_time:.2f} seconds over {times_run} calls) - {query}'
else:
message = '{url} - slow query ({query_time:.2f} seconds) - {query}'
print(colored(message.format(url=url, query=query, times_run=times_run, query_time=query_time), 'yellow'))
def after_request(response):
for query in get_debug_queries():
if query.duration >= current_app.config["FLASKY_SLOW_DB_QUERY_TIME"]:
current_app.logger.warning(
"Slow query: %s\nParameters: %s\nDuration: %f\nContext: %s\n" %
(query.statement, query.parameters, query.duration,
query.context))
return response
def after_request(response):
for query in get_debug_queries():
if query.duration >= current_app.config["MYP_SLOW_DB_QUERY_TIME"]:
print(
f"SLOWER {query.statement, query.parameters, query.duration, query.context}"
)
return response
def get_slow_query(response):
for query in get_debug_queries():
if query.duration >= current_app.config['FLASKY_SLOW_DB_QUERY_TIME']:
current_app.logger.warning(
"Slow query:%s\n,Parameters:%s\n,Duration:%s\n,Context:%s" %
(query.statement, query.parameters, query.duration,
query.context))
return response
def after_request(response):
if app.debug:
for query in get_debug_queries():
print(
"Query: %s\n\tParameters: %s\n\tDuration: %fs\n\tContext: %s\n"
% (query.statement, query.parameters, query.duration,
query.context))
return response
def after_request(response):
for query in get_debug_queries():
if query.duration >= 0.5:
print(
'Slow query: %s\nParemeters:%s\nDuration:%fs\nContext: %s\n' %
query.statment, query.parameters, query.duration,
query.context)
return response
def after_request(response):
for query in get_debug_queries():
if query.duration >= current_app.config["DB_SLOW_QUERY_TIME"]:
current_app.logger.warning(f"Slow query: {query.statement}\n"
f"Parameters: {query.parameters}\n"
f"Duration: {query.duration}\n"
f"Context: {query.context}")
return response
def add_header(response):
if 'Content-Type' in response.headers and\
'/css' in response.content_type:
response.cache_control.max_age = 2592000
if app.config['DEBUG_QUERY']:
for l in get_debug_queries():
print(l)
return response
def query_profiler(response):
for q in get_debug_queries():
if q.duration >= current_app.config['BLUELOG_SLOW_QUERY_THRESHOLD']:
print('Slow query:Duration :%fs\n Context:%s\nQuery:%s\n' %
(q.duration, q.context, q.statement))
# 下边打log会报错
# app.logger.debug('duration=get_debug_queries')
return response
def _print_debug_queries():
print('=========================================')
print('========== DEBUG QUERIES ================')
print('=========================================')
print(get_debug_queries())
print('=========================================')
print('========== END OF QUERIES ===============')
print('=========================================')
def after_request(response):
for query in get_debug_queries():
if query.duration >= app.config["DATABASE_QUERY_TIMEOUT"]:
app.logger.warn(f"Context: {query.context}\n"
f"SLOW QUERY: {query.statement}\n"
f"Parameters: {query.parameters}\n"
f"Duration: {query.duration}")
return response
def after_request(response):
for query in get_debug_queries():
if query.duration >= current_app.config['BLOG_SLOW_DB_QUERY_TIME']:
current_app.logger.warning(
'Slow query:{}\nParameter:{}\nDuration:{}s\nContext:{}\n'.
format(query.statement, query.parameters, query.duration,
query.context))
return response
def after_request(response):
for query in get_debug_queries():
if query.duration >= app.config.get('DATABASE_QUERY_TIMEOUT', 10):
app.logger.warning(
"SLOW QUERY: {}\nParameters: {}\nDuration: {}s\nContext: {}\n".
format(query.statement, query.parameters, query.duration,
query.context))
return response
def after_request(response):
for query in get_debug_queries():
if query.duration >= current_app.config['FLASKY_SLOW_DB_QUERY_TIME']:
slow_log = 'Slow query: %s\nParameters: %s\nDuration: %fs\nContext: %s\n' \
% (query.statement, query.parameters, query.duration, query.context)
current_app.logger.warning(slow_log)
slow_query_log.warning(slow_log)
return response
def query_profiler(response):
for query in get_debug_queries():
if query.duration >= app.config['FLASK_SLOW_DB_QUERY_TIME']:
current_app.logger.warning(
'Slow query: %s\nParameters: %s\nDuration: %fs\nContext: %s\n'
% (query.statement, query.parameters, query.duration, query.context)
)
return response
def after_request(response):
for query in get_debug_queries():
if query.duration >= 0.5:
current_app.logger.warning(
'Slow query: %s\nParameters: %s\nDuration: %fs\nContext: %s\n'
% (query.statement, query.parameters, query.duration,
query.context))
return response
def get_num_queries(datastore):
""" Return # of queries executed during test.
return None if datastore doesn't support this.
"""
if is_sqlalchemy(datastore):
from flask_sqlalchemy import get_debug_queries
return len(get_debug_queries())
return None
def after_request(response):
for query in get_debug_queries():
if query.duration >= current_app.config['YYSDATA_SLOW_DB_QUERY_TIME']:
current_app.logger.warning(
'show query: %s\nParameters: %s\nDuration: %fs\nContext: %s\n'
% (query.statment, query.parameters, query.duration,
query.context))
return response
def after_request(response):
for query in get_debug_queries():
if query.duration >= app.config['DATABASE_QUERY_TIMEOUT']:
app.logger.warning(
"SLOW QUERY: %s\nParameters: %s\nDuration: %fs\nContext: %s\n" %
(query.statement, query.parameters, query.duration, query.context)
)
return response
def after_request(resp):
if app.config.get('SQLALCHEMY_RECORD_QUERIES'):
with open("/home/ben/sql", "a+") as f:
f.write("=========\n{}:\n\n".format(request.url))
for q in get_debug_queries():
f.write("{}\n\n".format(q))
f.write("=========\n\n")
return resp
def after_request_func(response):
for query in get_debug_queries():
if query.duration >= app.config['FLASKY_DB_QUERY_TIMEOUT']:
print(
'Slow query:%s ,Parameters:%s, Duration:%fs, Context:%s\n'
% (query.statement, query.parameters, query.duration,
query.context)) # 打印超时sql执行信息
return response
def after_request(response):
'''Log queries that are slower than a configured threshold.'''
for query in get_debug_queries():
if query.duration >= current_app.config['FLASKY_SLOW_DB_QUERY_TIME']:
current_app.logger.warning(
'Slow query: %s\nParameters: %s\nDuration: %fs\nContext: %s\n' %
(query.statement, query.parameters, query.duration, query.context))
return response
def after_request(response):
for query in get_debug_queries():
if query.duration >= DATABASE_QUERY_TIMEOUT:
app.logger.warning(
"SLOW QUERY: %s\nParameters: %s\nDuration: %fs\nContext: %s\n"
% (query.statement, query.parameters, query.duration,
query.context))
return response
def product_top_twenty():
query = u"SELECT [Hour],COUNT(*) AS [Quantity] FROM [Order] GROUP BY [Hour] ORDER BY [Quantity] DESC"
product_top_twenty_results = db.session.query(
QuantityByHour).from_statement(text(query)).all()
query_stat = flask_sqlalchemy.get_debug_queries()[0]
return render_template('product_top_twenty.html',
product_top_twenty=product_top_twenty_results,
query_stat=query_stat)
def after_request(response):
for query in get_debug_queries():
if query.duration >= current_app.config['FLASKY_SLOW_DB_QUERY_TIME']:
print(
"Slow query: %s\nParameters: %s\nDuration: %fs\nContext: %s\n"
% query.statement, query.parameter, query.duration,
query.context)
return response
def after_request(response):
for query in get_debug_queries():
if query.duration >= app.config['DATABASE_QUERY_TIMEOUT']:
app.logger.warn(
('\nContext:{}\nSLOW QUERY: {}\nParameters: {}\n'
'Duration: {}\n').format(query.context, query.statement,
query.parameters, query.duration))
return response
def after_request(response):
for query in get_debug_queries():
if query.duration >= current_app.config['APP_SLOW_DB_QUERY_TIME']:
current_app.logger.warning(
'Slow query: {}\nParameters: {}\nDuration: {}\n'
'Context: {}\n'.format(query.statement, query.parameters,
query.duration, query.context)
)
return response
def after_request(resp):
for query in get_debug_queries():
# print query.duration
if query.duration >= current_app.config["SLOW_DB_QUERY_TIME"]:
current_app.logger.warning(
"Slow query: %s\nParameters: %s\nDuration, %fs\nContext: %s\n"
% (query.statement, query.parameters, query.duration, query.context)
)
return resp
def after_request(response): # hook into 'after request' allowing us to send to statsd
if app.config['SQLALCHEMY_RECORD_QUERIES']:
queries = get_debug_queries()
for query in queries:
context=query.context.replace(':','_')
print context
duration = query.duration * 1000 #convert to ms
app.stats_client.timing('thermos.queries,context={},path={}'.format(context,request.path),duration)
print (query.duration)
return response
def query_log(resp):
if app.config['SQLALCHEMY_RECORD_QUERIES'] == False:
pass
for query in get_debug_queries():
if query.duration >= app.config['DB_QUERY_TIMEOUT']:
sql_logger.warn(
('Context:{}\nSLOW QUERY: {}\nParameters: {}\n'
'Duration: {}\n').format(query.context, query.statement,
query.parameters, query.duration))
return resp
def after_request(response):
response.headers.add('Access-Control-Allow-Origin', '*')
response.headers.add('Access-Control-Allow-Headers', 'Content-Type,Authorization')
response.headers.add('Access-Control-Allow-Methods', 'GET,PUT,POST,DELETE')
for query in get_debug_queries():
if query.duration >= config.DATABASE_QUERY_TIMEOUT:
json_api.logger.warning(
'SLOW QUERY: %s\nParameters: %s\nDuration: %fs\nContext: %s\n'.format(
query.statement, query.parameters, query.duration, query.context))
return response
def profile_sqlalchemy_queries(resp):
queries = get_debug_queries()
logger.info('SQLAlchemy sql quantity: %d', len(queries))
logger.info('SQLAlchemy total elapsed: %.4f ms', sum(q.duration * 1000.0 for q in queries))
for query in queries:
logger.info('%s %s %.4f "%s" "%s"',
query.start_time,
query.end_time,
query.duration * 1000.0,
query.statement,
query.parameters,)
return resp
def after_request(response):
"""
get_debug_queries() 函数返回一个列表,其元素是请求中执行的查询
遍历 get_debug_queries() 函数获取的列表,把持续时间比设定阈值长的查询写入日志。
写入的日志被设为“警告”等级。如果换成“错误”等级,发 现缓慢的查询时还会发送电子邮件。
"""
for query in get_debug_queries():
if query.duration >= current_app.config['FLASKY_SLOW_DB_QUERY_TIME']:
current_app.logger.warning(
'Slow query: %s\nParameters: %s\nDuration: %fs\nContext: %s\n'
% (query.statement, query.parameters, query.duration, query.context))
return response
def __exit__(self, exc_type, exc_value, traceback):
db.engine.echo = self.echo
if exc_type is not None:
return
from flask_sqlalchemy import get_debug_queries
executed = len(get_debug_queries()) - self.start
self.testcase.assertEqual(
executed, self.num, "%d queries executed, %d expected" % (
executed, self.num
)
)
def after_request(response):
"""
记录数据库查询缓慢的条目
:param response:
:return:
"""
for query in get_debug_queries():
if query.duration >= current_app.config['FLASKY_SLOW_DB_QUERY_TIME']: # 将查询时间大于默认阈值条目记录
current_app.logger.waring(
'Slow query: %s\nParameters: %s\nDuration: %fs\nContext: %s\n'
% (query.statement, query.parameters, query.duration,
query.context))
return response
def slow_query(resp, *args, **kws):
query = False
if not query:
return resp
for query in get_debug_queries():
if query.duration >= current_app.config['DATABASE_QUERY_TIMEOUT']:
current_app.logger.warn(
'Context:{}\nSLOW QUERY: {}\nParameters: {}\n'
'Duration: {}\n'.format(
query.context, query.statement,
query.parameters, query.duration))
return resp
def test_query_recording(self):
with self.app.test_request_context():
todo = self.Todo("Test 1", "test")
self.db.session.add(todo)
self.db.session.commit()
queries = fsa.get_debug_queries()
self.assertEqual(len(queries), 1)
query = queries[0]
self.assertTrue("insert into" in query.statement.lower())
self.assertEqual(query.parameters[0], "Test 1")
self.assertEqual(query.parameters[1], "test")
self.assertTrue("test_sqlalchemy.py" in query.context)
self.assertTrue("test_query_recording" in query.context)
def test_query_recording(self):
with self.app.test_request_context():
todo = self.Todo('Test 1', 'test')
self.db.session.add(todo)
self.db.session.commit()
queries = sqlalchemy.get_debug_queries()
self.assertEqual(len(queries), 1)
query = queries[0]
self.assertTrue('insert into' in query.statement.lower())
self.assertEqual(query.parameters[0], 'Test 1')
self.assertEqual(query.parameters[1], 'test')
self.assertTrue('test_sqlalchemy.py' in query.context)
self.assertTrue('test_query_recording' in query.context)
def log_request_end(response):
"""
Write out a log entry for the request.
:param response: Flask response object
:return: Flask response
"""
if "request_id" in g:
response.headers["X-Correlation-Id"] = g.request_id
if request.path == "/favicon.ico":
return response
elif request.path.startswith("/healthcheck"):
return response
elif request.path.startswith("/static"):
return response
response_time_in_ms = 0
if "start" in g:
response_time = time.perf_counter() - g.start
response_time_in_ms = int(response_time * 1000)
params = {
"method": request.method,
"duration": response_time_in_ms,
"path": request.path,
"ip": request.headers.get("X-Forwarded-For", request.remote_addr),
"status": response.status_code,
"host": request.host.split(":", 1)[0],
}
app.logger.info(
"REQUEST: method=%(method)s path=%(path)s status=%(status)s duration=%(duration)sms ip=%(ip)s",
params,
)
if app.config.get("SQLALCHEMY_RECORD_QUERIES", False):
for query in get_debug_queries():
if query.duration >= app.config.get("DATABASE_QUERY_TIMEOUT", 2):
app.logger.warning(
"Slow Query: %s\nParameters: %s\nDuration: %fs\nContext: %s\n"
% (
query.statement,
query.parameters,
query.duration,
query.context,
)
)
return response
def log_queries():
total_duration = 0.0
queries_count = 0
chromelogger.group("SQL Queries")
for q in get_debug_queries():
total_duration += q.duration
queries_count += 1
chromelogger.info(q.statement % q.parameters)
chromelogger.info("Runtime: {:.2f}ms".format(1000 * q.duration))
chromelogger.info("{} queries executed in {:.2f}ms.".format(queries_count, total_duration*1000))
chromelogger.group_end("SQL Queries")
def log_queries_count(response):
if flask.request.method not in ['GET', 'HEAD']:
# We did most optimizations for read only endpoints
# TODO migrations: improve optimization and remove this if
return response
queries = get_debug_queries()
max_query_time = max([q.duration for q in queries] or [0])
if len(queries) > 15:
logger.warn("Too many queries done (%s) in endpoint %s. "
"Maximum query time: %.2f",
len(queries), flask.request.endpoint, max_query_time)
# from collections import Counter
# print '\n\n\n'.join(
# map(str,Counter(q.statement for q in queries).most_common()))
return response
def report_slow_queries(response):
"""Log slow database queries
This will only function if BOTH values are set in the config:
DATABASE_QUERY_TIMEOUT = 0.5 # threshold in seconds
SQLALCHEMY_RECORD_QUERIES = True
"""
threshold = current_app.config.get('DATABASE_QUERY_TIMEOUT')
if threshold:
for query in get_debug_queries():
if query.duration >= threshold:
current_app.logger.warning(
"SLOW QUERY: {0.statement}\n"
"Duration: {0.duration:.4f} seconds\n"
"Parameters: {0.parameters}\n"
"Context: {0.context}".format(query))
return response
def sql_debug(response):
queries = list(get_debug_queries())
query_str = ''
total_duration = 0.0
for q in queries:
total_duration += q.duration
stmt = str(q.statement % q.parameters).replace('\n', '\n ')
query_str += 'Query: {0}\nDuration: {1}ms\n\n'.format(stmt, round(q.duration * 1000, 2))
print ('=' * 80)
print (' SQL Queries - {number} Queries Executed in {period}ms'.format(
number=len(queries),
period=round(total_duration * 1000, 2)))
print ('=' * 80)
print (query_str.rstrip('\n'))
print ('=' * 80 + '\n')
return response
def after_request(response):
for query in get_debug_queries():
if query.duration >= app.config['DATABASE_QUERY_TIMEOUT']:
app.logger.warning(
"SLOW QUERY: %s\nParameters: %s\nDuration: %fs\nContext: %s\n" %
(query.statement, query.parameters, query.duration,
query.context))
db.session.rollback()
url = request.url
if ('.css' in url or '.js' in url or '.svg' in url or '.png' in url or
'.gif' in url) :
# Flasks adds to the header `Vary: cookie` meaning the client should
# re-download the asset if the cookie changed. If you look at the Flask
# source code that comes next after the below return, it will add
# `Vary: cookie` if and only if session.accessed is true.
flask_session.accessed = False
return response
def test_query_recording(app, db, Todo):
with app.test_request_context():
todo = Todo('Test 1', 'test')
db.session.add(todo)
db.session.flush()
todo.done = True
db.session.commit()
queries = fsa.get_debug_queries()
assert len(queries) == 2
query = queries[0]
assert 'insert into' in query.statement.lower()
assert query.parameters[0] == 'Test 1'
assert query.parameters[1] == 'test'
assert 'test_basic_app.py' in query.context
assert 'test_query_recording' in query.context
query = queries[1]
assert 'update' in query.statement.lower()
assert query.parameters[0] == 1
assert query.parameters[1] == 1
def get_queries():
if get_debug_queries:
return get_debug_queries()
else:
return []
def after_request(response):
for query in get_debug_queries():
if query.duration >= current_app.config['SLOW_DB_QUERY_TIME']:
current_app.logger.warning(u'慢查询：%s\n参数：%s\n持续时间：%s\n位置：%s\n' %(query.statement, query.parameters, query.duration, query.context))
return response
def print_queries():
for query in get_debug_queries():
print((query.statement, query.parameters))
def __enter__(self):
from flask_sqlalchemy import get_debug_queries
self.start = len(get_debug_queries())
self.echo = db.engine.echo
db.engine.echo = True