From f3edbc3950fe52369d4a0aabafaf3d09db5a9b7c Mon Sep 17 00:00:00 2001 From: Mark Nazzaro Date: Thu, 6 Jun 2024 15:55:27 -0400 Subject: [PATCH 1/9] Going to test this out --- arxiv/db/__init__.py | 20 ++++++++++++++++---- 1 file changed, 16 insertions(+), 4 deletions(-) diff --git a/arxiv/db/__init__.py b/arxiv/db/__init__.py index d5126b64..d2831ad4 100644 --- a/arxiv/db/__init__.py +++ b/arxiv/db/__init__.py @@ -32,16 +32,16 @@ with transaction() as session: session.add(...) """ -from typing import Optional import logging +from datetime import datetime from contextlib import contextmanager from flask.globals import app_ctx from flask import has_app_context -from sqlalchemy import create_engine, MetaData, String +from sqlalchemy import create_engine, MetaData +from sqlalchemy.event import listens_for from sqlalchemy.orm import sessionmaker, scoped_session, DeclarativeBase -from sqlalchemy.engine.interfaces import IsolationLevel from ..config import settings @@ -96,4 +96,16 @@ def transaction (): db.rollback() finally: if not in_flask: - db.close() \ No newline at end of file + db.close() + +@listens_for(engine, "before_cursor_execute") +def _record_query_start (conn, cursor, statement, parameters, context, executemany): + conn.info["query_start"] = datetime.now() + +@listens_for(engine, "after_cursor_execute") +def _calculate_query_run_time (conn, cursor, statement, parameters, context, executemany): + if conn.info.get('query_start'): + secs = (datetime.now() - conn.info['query_start']).seconds + logger.error(f"TESTING TESTING with {secs} seconds") + if secs > 10: + logger.warning(f"This query:\n{str(statement)}\ntook {secs} seconds") From 30e90747fc49793267b51659e781b06d9f5f3fde Mon Sep 17 00:00:00 2001 From: Mark Nazzaro Date: Thu, 6 Jun 2024 16:07:52 -0400 Subject: [PATCH 2/9] More logging --- arxiv/db/__init__.py | 11 ++++++----- 1 file changed, 6 insertions(+), 5 deletions(-) diff --git a/arxiv/db/__init__.py b/arxiv/db/__init__.py index d2831ad4..81a2eb8a 100644 --- a/arxiv/db/__init__.py +++ b/arxiv/db/__init__.py @@ -100,12 +100,13 @@ def transaction (): @listens_for(engine, "before_cursor_execute") def _record_query_start (conn, cursor, statement, parameters, context, executemany): - conn.info["query_start"] = datetime.now() + conn.info['query_start'] = datetime.now() @listens_for(engine, "after_cursor_execute") def _calculate_query_run_time (conn, cursor, statement, parameters, context, executemany): if conn.info.get('query_start'): - secs = (datetime.now() - conn.info['query_start']).seconds - logger.error(f"TESTING TESTING with {secs} seconds") - if secs > 10: - logger.warning(f"This query:\n{str(statement)}\ntook {secs} seconds") + a = datetime.now() + delta = (a - conn.info['query_start']) + logger.error(f"TESTING TESTING: now = {a}, query_start = {conn.info['query_start']}, delta: {delta.seconds} seconds / {delta.microseconds} microsecs") + if delta.seconds > 0.01: + logger.warning(f"This query:\n{str(statement)}\ntook {delta.seconds} seconds") From 6b5a66b1ac9ac63945383a958d5ffc6bbe83ddf6 Mon Sep 17 00:00:00 2001 From: Mark Nazzaro Date: Thu, 6 Jun 2024 16:22:36 -0400 Subject: [PATCH 3/9] Ok this is good --- arxiv/db/__init__.py | 10 ++++------ 1 file changed, 4 insertions(+), 6 deletions(-) diff --git a/arxiv/db/__init__.py b/arxiv/db/__init__.py index 81a2eb8a..c15c207f 100644 --- a/arxiv/db/__init__.py +++ b/arxiv/db/__init__.py @@ -33,7 +33,7 @@ session.add(...) """ import logging -from datetime import datetime +from datetime import datetime, timedelta from contextlib import contextmanager from flask.globals import app_ctx @@ -105,8 +105,6 @@ def _record_query_start (conn, cursor, statement, parameters, context, executema @listens_for(engine, "after_cursor_execute") def _calculate_query_run_time (conn, cursor, statement, parameters, context, executemany): if conn.info.get('query_start'): - a = datetime.now() - delta = (a - conn.info['query_start']) - logger.error(f"TESTING TESTING: now = {a}, query_start = {conn.info['query_start']}, delta: {delta.seconds} seconds / {delta.microseconds} microsecs") - if delta.seconds > 0.01: - logger.warning(f"This query:\n{str(statement)}\ntook {delta.seconds} seconds") + delta: timedelta = (datetime.now() - conn.info['query_start']) + if delta.seconds > 8: + logger.warning(f"This query:\n{str(statement)}\ntook {delta.seconds+(delta.microseconds/1000000)} seconds") From 921219323ea0f8d922d04d179007c48b5434a55b Mon Sep 17 00:00:00 2001 From: Mark Nazzaro Date: Thu, 6 Jun 2024 16:28:28 -0400 Subject: [PATCH 4/9] This is just for testing --- arxiv/db/__init__.py | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/arxiv/db/__init__.py b/arxiv/db/__init__.py index c15c207f..ca1fac97 100644 --- a/arxiv/db/__init__.py +++ b/arxiv/db/__init__.py @@ -106,5 +106,4 @@ def _record_query_start (conn, cursor, statement, parameters, context, executema def _calculate_query_run_time (conn, cursor, statement, parameters, context, executemany): if conn.info.get('query_start'): delta: timedelta = (datetime.now() - conn.info['query_start']) - if delta.seconds > 8: - logger.warning(f"This query:\n{str(statement)}\ntook {delta.seconds+(delta.microseconds/1000000)} seconds") + logger.warning(f"This query:\n{str(statement)}\ntook {delta.seconds+(delta.microseconds/1000000)} seconds") From cd6ba92a44fd1cd2ac8d6e6512156201c6686d8f Mon Sep 17 00:00:00 2001 From: Mark Nazzaro Date: Thu, 6 Jun 2024 16:32:00 -0400 Subject: [PATCH 5/9] This one is good --- arxiv/db/__init__.py | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/arxiv/db/__init__.py b/arxiv/db/__init__.py index ca1fac97..c15c207f 100644 --- a/arxiv/db/__init__.py +++ b/arxiv/db/__init__.py @@ -106,4 +106,5 @@ def _record_query_start (conn, cursor, statement, parameters, context, executema def _calculate_query_run_time (conn, cursor, statement, parameters, context, executemany): if conn.info.get('query_start'): delta: timedelta = (datetime.now() - conn.info['query_start']) - logger.warning(f"This query:\n{str(statement)}\ntook {delta.seconds+(delta.microseconds/1000000)} seconds") + if delta.seconds > 8: + logger.warning(f"This query:\n{str(statement)}\ntook {delta.seconds+(delta.microseconds/1000000)} seconds") From dfe47999182ee20fc30faa3640ea374ef9264db6 Mon Sep 17 00:00:00 2001 From: Mark Nazzaro Date: Fri, 7 Jun 2024 10:20:16 -0400 Subject: [PATCH 6/9] Write as structured log --- arxiv/db/__init__.py | 9 +++++++-- 1 file changed, 7 insertions(+), 2 deletions(-) diff --git a/arxiv/db/__init__.py b/arxiv/db/__init__.py index c15c207f..d87e9e71 100644 --- a/arxiv/db/__init__.py +++ b/arxiv/db/__init__.py @@ -106,5 +106,10 @@ def _record_query_start (conn, cursor, statement, parameters, context, executema def _calculate_query_run_time (conn, cursor, statement, parameters, context, executemany): if conn.info.get('query_start'): delta: timedelta = (datetime.now() - conn.info['query_start']) - if delta.seconds > 8: - logger.warning(f"This query:\n{str(statement)}\ntook {delta.seconds+(delta.microseconds/1000000)} seconds") + if delta.microseconds > 250000: + log = dict( + severity="WARNING", + message=f"Long query took {delta.seconds+(delta.microseconds/1000000)} seconds", + query=str(statement) + ) + print (log) From 1819d5fa7a43fe80a1138dbc33eda3d6b28d7a38 Mon Sep 17 00:00:00 2001 From: Mark Nazzaro Date: Fri, 7 Jun 2024 10:28:54 -0400 Subject: [PATCH 7/9] Need to json.dumps. Also reduce time since it's so rare --- arxiv/db/__init__.py | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/arxiv/db/__init__.py b/arxiv/db/__init__.py index d87e9e71..2d78ab4d 100644 --- a/arxiv/db/__init__.py +++ b/arxiv/db/__init__.py @@ -33,6 +33,7 @@ session.add(...) """ import logging +import json from datetime import datetime, timedelta from contextlib import contextmanager @@ -109,7 +110,8 @@ def _calculate_query_run_time (conn, cursor, statement, parameters, context, exe if delta.microseconds > 250000: log = dict( severity="WARNING", - message=f"Long query took {delta.seconds+(delta.microseconds/1000000)} seconds", + message=f"Long query took", + length=delta.seconds+(delta.microseconds/1000000), query=str(statement) ) - print (log) + print (json.dumps(log)) From 81bfd3447a2f61874eab74a50cf903c019e04275 Mon Sep 17 00:00:00 2001 From: Mark Nazzaro Date: Fri, 7 Jun 2024 10:34:33 -0400 Subject: [PATCH 8/9] Ok this is better --- arxiv/db/__init__.py | 15 ++++++++++++--- 1 file changed, 12 insertions(+), 3 deletions(-) diff --git a/arxiv/db/__init__.py b/arxiv/db/__init__.py index 2d78ab4d..bc95a9f4 100644 --- a/arxiv/db/__init__.py +++ b/arxiv/db/__init__.py @@ -107,11 +107,20 @@ def _record_query_start (conn, cursor, statement, parameters, context, executema def _calculate_query_run_time (conn, cursor, statement, parameters, context, executemany): if conn.info.get('query_start'): delta: timedelta = (datetime.now() - conn.info['query_start']) - if delta.microseconds > 250000: + query_time = delta.seconds+(delta.microseconds/1000000) + if query_time > 0.2 and query_time < 8: + log = dict( + severity="INFO", + message=f"Slightly long query", + query_seconds=query_time, + query=str(statement) + ) + print (json.dumps(log)) + elif query_time >= 8: log = dict( severity="WARNING", - message=f"Long query took", - length=delta.seconds+(delta.microseconds/1000000), + message=f"Very long query", + query_seconds=query_time, query=str(statement) ) print (json.dumps(log)) From eb02993dcaa493a3225048882f1a7ff6c94dabda Mon Sep 17 00:00:00 2001 From: Mark Nazzaro Date: Fri, 7 Jun 2024 10:50:56 -0400 Subject: [PATCH 9/9] Put inside other function so it's optional for base users --- arxiv/db/__init__.py | 52 +++++++++++++++++++++++--------------------- 1 file changed, 27 insertions(+), 25 deletions(-) diff --git a/arxiv/db/__init__.py b/arxiv/db/__init__.py index bc95a9f4..05763471 100644 --- a/arxiv/db/__init__.py +++ b/arxiv/db/__init__.py @@ -99,28 +99,30 @@ def transaction (): if not in_flask: db.close() -@listens_for(engine, "before_cursor_execute") -def _record_query_start (conn, cursor, statement, parameters, context, executemany): - conn.info['query_start'] = datetime.now() - -@listens_for(engine, "after_cursor_execute") -def _calculate_query_run_time (conn, cursor, statement, parameters, context, executemany): - if conn.info.get('query_start'): - delta: timedelta = (datetime.now() - conn.info['query_start']) - query_time = delta.seconds+(delta.microseconds/1000000) - if query_time > 0.2 and query_time < 8: - log = dict( - severity="INFO", - message=f"Slightly long query", - query_seconds=query_time, - query=str(statement) - ) - print (json.dumps(log)) - elif query_time >= 8: - log = dict( - severity="WARNING", - message=f"Very long query", - query_seconds=query_time, - query=str(statement) - ) - print (json.dumps(log)) + +def config_query_timing( slightly_long_sec: float, long_sec: float): + @listens_for(engine, "before_cursor_execute") + def _record_query_start (conn, cursor, statement, parameters, context, executemany): + conn.info['query_start'] = datetime.now() + + @listens_for(engine, "after_cursor_execute") + def _calculate_query_run_time (conn, cursor, statement, parameters, context, executemany): + if conn.info.get('query_start'): + delta: timedelta = (datetime.now() - conn.info['query_start']) + query_time = delta.seconds+(delta.microseconds/1000000) + if query_time > slightly_long_sec and query_time < long_sec: + log = dict( + severity="INFO", + message=f"Slightly long query", + query_seconds=query_time, + query=str(statement) + ) + print (json.dumps(log)) + elif query_time >= long_sec: + log = dict( + severity="WARNING", + message=f"Very long query", + query_seconds=query_time, + query=str(statement) + ) + print (json.dumps(log))