diff --git a/configure_logger.py b/configure_logger.py index 0fb62a0..c8acb22 100644 --- a/configure_logger.py +++ b/configure_logger.py @@ -2,6 +2,8 @@ from enum import Enum from typing import Literal +_PROFILE_FORMAT = "%(message)s" + class LogLevel(Enum): DEBUG = logging.DEBUG @@ -31,34 +33,22 @@ def from_string(cls, level_str: str) -> Enum: def configure_logger( name: str, - level: int = logging.DEBUG, # Use int type hint here + level: int = logging.DEBUG, format: str = "%(asctime)s - %(name)s - %(levelname)s - %(message)s", handler_type: Literal["console", "file"] = "console", log_file: str = "tfbpmodeling.log", ) -> logging.Logger: """ - Configures a logger. - - :param name: Name of the logger - :type name: str - :param level: Logging level, must be one of logging.DEBUG, - logging.INFO, logging.WARNING, logging.ERROR - :type level: int - :param format: Logging format - :type format: str - :param handler_type: Type of handler, either 'console' or 'file' - :type handler_type: Literal["console", "file"] - :param log_file: Path to log file, required if handler_type is 'file'. - Default is 'tfbpmodeling.log' - :type log_file: str - - :return: Configured logger + Configure a logger with a single handler. + + :param name: Logger name. + :param level: Logging level (``logging.DEBUG``, ``logging.INFO``, etc.). + :param format: Log record format string. + :param handler_type: Destination — ``"console"`` or ``"file"``. + :param log_file: Path used when ``handler_type="file"``. + :returns: Configured logger. :rtype: logging.Logger - - :raises ValueError: If any of the parameters have invalid datatypes - - example usage: - >>> logger = configure_logger("my_logger", level=logging.INFO) + :raises ValueError: If any parameter is invalid. """ if not isinstance(name, str): @@ -69,7 +59,7 @@ def configure_logger( raise ValueError("Invalid logging level") if not isinstance(format, str): raise ValueError("format must be a string") - if handler_type not in ["console", "file"]: + if handler_type not in ("console", "file"): raise ValueError("handler_type must be 'console' or 'file'") if handler_type == "file" and not log_file: raise ValueError("log_file must be specified for file handler") @@ -77,22 +67,52 @@ def configure_logger( logger = logging.getLogger(name) logger.setLevel(level) - # Remove all handlers associated with the logger object to avoid duplicate logs - for handler in logger.handlers[:]: - logger.removeHandler(handler) + # Remove existing handlers to avoid duplicates on re-configuration. + for h in logger.handlers[:]: + logger.removeHandler(h) if handler_type == "console": - handler = logging.StreamHandler() - elif handler_type == "file": - if not log_file: - raise ValueError("log_file must be specified for file handler") - handler = logging.FileHandler(log_file) + handler: logging.Handler = logging.StreamHandler() else: - raise ValueError("Invalid handler_type. Must be 'console' or 'file'.") + handler = logging.FileHandler(log_file) handler.setLevel(level) - formatter = logging.Formatter(format) - handler.setFormatter(formatter) + handler.setFormatter(logging.Formatter(format)) logger.addHandler(handler) return logger + + +def configure_profile_logger( + handler_type: Literal["console", "file"] = "console", + level: int = logging.DEBUG, + log_file: str = "tfbpshiny_profile.log", + enabled: bool = True, +) -> logging.Logger: + """ + Configure and return the ``"profiler"`` logger for timing instrumentation. + + The profiler logger uses a bare ``%(message)s`` format because all + structure is embedded in the message by + :func:`tfbpshiny.utils.profiler.profile_span`. + It never propagates to the root or ``"shiny"`` logger. + + :param handler_type: Destination for profile records — ``"console"`` or ``"file"``. + :param level: Log level; ignored (set to ``CRITICAL``) when ``enabled=False``. + :param log_file: Path used when ``handler_type="file"``. + :param enabled: When ``False``, silences the logger by setting its level + to ``CRITICAL``. + :returns: Configured ``"profiler"`` logger. + :rtype: logging.Logger + + """ + effective_level = level if enabled else logging.CRITICAL + logger = configure_logger( + "profiler", + level=effective_level, + format=_PROFILE_FORMAT, + handler_type=handler_type, + log_file=log_file, + ) + logger.propagate = False + return logger diff --git a/docs/development.md b/docs/development.md index a0a02f3..ca330d6 100644 --- a/docs/development.md +++ b/docs/development.md @@ -45,4 +45,25 @@ callbacks are necessary, then either a different plotting library or a custom implementation of some sort will likely be necessary. Would be nice to explore other options, including custom implementations of plots using d3 and then creating the shiny widget manually. With AI, that might be more achievable (for me at least) -than it would be otherwise b/c we can give the AI the docs for all three as context. \ No newline at end of file +than it would be otherwise b/c we can give the AI the docs for all three as context. + +There is both a general log and profiling log + +Both loggers write to stdout/stderr, Docker's awslogs driver captures everything into the shinyapp stream under /tfbpshiny/production. To later separate PROFILE lines from main log lines when parsing: + +```{python} +import pandas as pd + +df = pd.read_csv("exported.log", sep="|", header=None, skipinitialspace=True, + names=["marker","timestamp","elapsed_s","op","module","dataset","context"]) +profile = df[df["marker"].str.strip() == "PROFILE"] +``` + + +Or in CloudWatch Logs Insights: + +```{raw} +fields @timestamp, @message +| filter @message like /^PROFILE/ +| parse @message "PROFILE | * | * | * | * | * | *" as timestamp, elapsed_s, op, module, dataset, context +``` \ No newline at end of file diff --git a/production.yml b/production.yml index ede0f0d..2585d92 100644 --- a/production.yml +++ b/production.yml @@ -12,6 +12,8 @@ services: - HF_HOME=/hf-cache - HF_TOKEN - DOCKER_ENV + - TFBPSHINY_LOG_HANDLER=console + - TFBPSHINY_PROFILE_HANDLER=console volumes: - hf_cache:/hf-cache expose: @@ -61,8 +63,8 @@ services: logging: driver: awslogs options: - awslogs-group: /tfbpshiny/production - awslogs-region: us-east-1 + awslogs-group: /tfbpshiny/production/traefik + awslogs-region: us-east-2 awslogs-stream: traefik awslogs-create-group: "true" restart: unless-stopped diff --git a/terraform/cloudwatch.tf b/terraform/cloudwatch.tf new file mode 100644 index 0000000..1b79dde --- /dev/null +++ b/terraform/cloudwatch.tf @@ -0,0 +1,226 @@ +# NOTE! THIS isn't working to create the dashboard. But I could paste in queries +# by hand to each panel and that did work so the logging is producing correct +# values + +locals { + log_group_app = "/tfbpshiny/production" + log_group_traefik = "/tfbpshiny/production/traefik" + namespace = "TFBPShiny" +} + +# --------------------------------------------------------------------------- +# Log groups +# --------------------------------------------------------------------------- +# Declaring these explicitly so Terraform owns retention/lifecycle. If either +# already exists in the account, import it with: +# terraform import aws_cloudwatch_log_group.app /tfbpshiny/production +# terraform import aws_cloudwatch_log_group.traefik /tfbpshiny/production/traefik + +resource "aws_cloudwatch_log_group" "app" { + name = local.log_group_app + retention_in_days = 30 +} + +resource "aws_cloudwatch_log_group" "traefik" { + name = local.log_group_traefik + retention_in_days = 14 +} + +# --------------------------------------------------------------------------- +# Metric filters — JSON format, no tokenization ambiguity +# --------------------------------------------------------------------------- +# Records emitted by the app are single-line JSON objects: +# PROFILE: {"event":"PROFILE","ts":"...","elapsed_s":0.1234,"op":"...","module":"...","dataset":"...","context":"...","session_id":"..."} +# SESSION: {"event":"SESSION","ts":"...","lifecycle":"START"|"END","session_id":"..."} +# +# CloudWatch JSON metric filters match on field values and extract numeric +# fields directly, with no whitespace-tokenization issues. +# +# default_value is intentionally omitted on latency filters. Setting it to 0 +# would drag the average toward zero during quiet periods and suppress alarms. + +resource "aws_cloudwatch_log_metric_filter" "profile_latency" { + name = "tfbpshiny-profile-latency" + log_group_name = aws_cloudwatch_log_group.app.name + pattern = "{ $.event = \"PROFILE\" }" + + metric_transformation { + name = "ProfileLatencySeconds" + namespace = local.namespace + value = "$.elapsed_s" + unit = "Seconds" + } +} + +# Narrow filter for vdb.query only — drives the latency alarm. +resource "aws_cloudwatch_log_metric_filter" "vdb_query_latency" { + name = "tfbpshiny-vdb-query-latency" + log_group_name = aws_cloudwatch_log_group.app.name + pattern = "{ $.event = \"PROFILE\" && $.op = \"vdb.query\" }" + + metric_transformation { + name = "VdbQueryLatencySeconds" + namespace = local.namespace + value = "$.elapsed_s" + unit = "Seconds" + } +} + +# Counts SESSION START records — one per new user connection. +resource "aws_cloudwatch_log_metric_filter" "session_start" { + name = "tfbpshiny-session-start" + log_group_name = aws_cloudwatch_log_group.app.name + pattern = "{ $.event = \"SESSION\" && $.lifecycle = \"START\" }" + + metric_transformation { + name = "SessionStart" + namespace = local.namespace + value = "1" + default_value = 0 + unit = "Count" + } +} + +# --------------------------------------------------------------------------- +# Alarms +# --------------------------------------------------------------------------- +# Raise threshold while the app is known to be slow; lower toward 2-5 s +# once query performance improves. +resource "aws_cloudwatch_metric_alarm" "high_vdb_query_latency" { + alarm_name = "tfbpshiny-high-vdb-query-latency" + alarm_description = "Avg vdb.query latency > 30 s over 15 min — investigate query bottlenecks." + namespace = local.namespace + metric_name = "VdbQueryLatencySeconds" + statistic = "Average" + period = 300 + evaluation_periods = 3 + datapoints_to_alarm = 3 + threshold = 30 + comparison_operator = "GreaterThanThreshold" + treat_missing_data = "notBreaching" +} + +resource "aws_cloudwatch_metric_alarm" "high_session_count" { + alarm_name = "tfbpshiny-high-session-count" + alarm_description = "More than 20 new sessions in 5 min — unexpected traffic spike." + namespace = local.namespace + metric_name = "SessionStart" + statistic = "Sum" + period = 300 + evaluation_periods = 1 + threshold = 20 + comparison_operator = "GreaterThanThreshold" + treat_missing_data = "notBreaching" +} + +# --------------------------------------------------------------------------- +# Dashboard +# --------------------------------------------------------------------------- +# Logs Insights auto-discovers JSON fields, so no parse directive needed. +# Queries filter on $.event to separate PROFILE from SESSION records. + +resource "aws_cloudwatch_dashboard" "tfbpshiny" { + dashboard_name = "tfbpshiny-production" + dashboard_body = jsonencode({ + widgets = [ + { + type = "log" + x = 0 + y = 0 + width = 24 + height = 6 + properties = { + title = "Avg and max latency by operation" + region = var.aws_region + view = "table" + logGroupNames = [local.log_group_app] + queryString = <<-EOT + fields @timestamp, op, module, dataset, context, elapsed_s + | filter event = "PROFILE" + | stats avg(elapsed_s) as avg_s, max(elapsed_s) as max_s, count() as n by op, module, context + | sort avg_s desc + EOT + } + }, + { + type = "log" + x = 0 + y = 6 + width = 12 + height = 6 + properties = { + title = "Sessions started (5-min bins)" + region = var.aws_region + view = "timeSeries" + logGroupNames = [local.log_group_app] + queryString = <<-EOT + fields @timestamp, session_id + | filter event = "SESSION" and lifecycle = "START" + | stats count(*) as sessions_started by bin(5m) + | sort @timestamp asc + EOT + } + }, + { + type = "log" + x = 12 + y = 6 + width = 12 + height = 6 + properties = { + title = "Unique visitors per day" + region = var.aws_region + view = "bar" + logGroupNames = [local.log_group_app] + queryString = <<-EOT + fields @timestamp, session_id + | filter event = "SESSION" and lifecycle = "START" + | stats count_distinct(session_id) as unique_visitors by bin(1d) + | sort @timestamp asc + EOT + } + }, + { + type = "log" + x = 0 + y = 12 + width = 24 + height = 6 + properties = { + title = "Latency by operation over time (5-min bins)" + region = var.aws_region + view = "timeSeries" + logGroupNames = [local.log_group_app] + queryString = <<-EOT + fields @timestamp, op, elapsed_s + | filter event = "PROFILE" + | stats avg(elapsed_s) as avg_s by bin(5m), op + | sort @timestamp asc + EOT + } + }, + { + type = "alarm" + x = 0 + y = 18 + width = 12 + height = 3 + properties = { + title = "vdb.query latency alarm" + alarms = [aws_cloudwatch_metric_alarm.high_vdb_query_latency.arn] + } + }, + { + type = "alarm" + x = 12 + y = 18 + width = 12 + height = 3 + properties = { + title = "High session count alarm" + alarms = [aws_cloudwatch_metric_alarm.high_session_count.arn] + } + }, + ] + }) +} diff --git a/terraform/main.tf b/terraform/main.tf index 7c841aa..20cf7e6 100644 --- a/terraform/main.tf +++ b/terraform/main.tf @@ -102,6 +102,16 @@ resource "aws_instance" "tfbpshiny" { user_data = file("${path.module}/user_data.sh") + # NOTE: ami and user_data are pinned via ignore_changes. This means that + # if the Amazon Linux 2023 AMI is updated or user_data.sh is modified, + # terraform apply will NOT replace the instance. This is intentional — + # both changes force instance termination, which would take down production. + # To deploy a new AMI or updated user_data, terminate the instance manually, + # remove this lifecycle block, and run terraform apply to reprovision. + lifecycle { + ignore_changes = [ami, user_data] + } + tags = { Name = "tfbpshiny-production" } diff --git a/tfbpshiny/__main__.py b/tfbpshiny/__main__.py index 3b4e78c..cb16872 100644 --- a/tfbpshiny/__main__.py +++ b/tfbpshiny/__main__.py @@ -38,6 +38,18 @@ def make_parser() -> argparse.ArgumentParser: choices=["console", "file"], help="Set log handler type", ) + parser.add_argument( + "--profile-handler", + type=str, + default="console", + choices=["console", "file"], + help="Handler for the profiler logger", + ) + parser.add_argument( + "--no-profile", + action="store_true", + help="Disable the profiler logger entirely", + ) subparsers = parser.add_subparsers(dest="command", required=True) @@ -78,6 +90,8 @@ def main() -> None: # convert to int when configuring the logger os.environ["TFBPSHINY_LOG_LEVEL"] = str(log_level.value) os.environ["TFBPSHINY_LOG_HANDLER"] = args.log_handler + os.environ["TFBPSHINY_PROFILE_HANDLER"] = args.profile_handler + os.environ["TFBPSHINY_PROFILE_ENABLED"] = "0" if args.no_profile else "1" args.func(args) diff --git a/tfbpshiny/app.py b/tfbpshiny/app.py index ae5ca4e..ad690cf 100644 --- a/tfbpshiny/app.py +++ b/tfbpshiny/app.py @@ -9,7 +9,7 @@ from dotenv import load_dotenv from shiny import App, reactive, render, ui -from configure_logger import configure_logger +from configure_logger import configure_logger, configure_profile_logger from tfbpshiny.components import github_badge, nav_button from tfbpshiny.modules.binding.server import ( binding_sidebar_server, @@ -41,6 +41,7 @@ selection_matrix_ui, selection_sidebar_ui, ) +from tfbpshiny.utils.profiler import log_session_event from tfbpshiny.utils.vdb_init import initialize_data if not os.getenv("DOCKER_ENV"): @@ -60,6 +61,14 @@ log_file=log_file, ) +profile_logger = configure_profile_logger( + handler_type=cast( + Literal["console", "file"], + os.getenv("TFBPSHINY_PROFILE_HANDLER", "console"), + ), + enabled=os.getenv("TFBPSHINY_PROFILE_ENABLED", "1") == "1", +) + # instantiate the virtualDB and compute app-level dataset metadata virtualdb_config = os.getenv( @@ -67,7 +76,9 @@ ) hf_token: str | None = os.getenv("HF_TOKEN") logger.info(f"Loading VirtualDB with config: {virtualdb_config}") -vdb, app_datasets = initialize_data(virtualdb_config, hf_token) +vdb, app_datasets = initialize_data( + virtualdb_config, hf_token, profile_logger=profile_logger +) app_ui = ui.page_fillable( ui.include_css((Path(__file__).parent / "app.css").resolve()), @@ -100,6 +111,10 @@ def app_server(input: Any, output: Any, session: Any) -> None: """Create shared reactive state and call all module servers.""" + sid: str = session.id + log_session_event(profile_logger, "START", sid) + session.on_ended(lambda: log_session_event(profile_logger, "END", sid)) + # this stores the name of the currently active module, ie # "home", "selection", "binding", "perturbation", or "comparison" active_module: reactive.Value[str] = reactive.value("home") @@ -121,6 +136,8 @@ def app_server(input: Any, output: Any, session: Any) -> None: dataset_filters=dataset_filters, vdb=vdb, logger=logger, + profile_logger=profile_logger, + session_id=sid, ) corr_type, col_preference = binding_sidebar_server( @@ -139,6 +156,8 @@ def app_server(input: Any, output: Any, session: Any) -> None: vdb=vdb, app_datasets=app_datasets, logger=logger, + profile_logger=profile_logger, + session_id=sid, ) corr_type_p, col_preference_p = perturbation_sidebar_server( @@ -157,6 +176,8 @@ def app_server(input: Any, output: Any, session: Any) -> None: vdb=vdb, app_datasets=app_datasets, logger=logger, + profile_logger=profile_logger, + session_id=sid, ) top_n, effect_threshold, pvalue_threshold, facet_by = comparison_sidebar_server( @@ -177,6 +198,8 @@ def app_server(input: Any, output: Any, session: Any) -> None: facet_by=facet_by, vdb=vdb, logger=logger, + profile_logger=profile_logger, + session_id=sid, ) # set the active module when a nav button is clicked diff --git a/tfbpshiny/modules/binding/server/workspace.py b/tfbpshiny/modules/binding/server/workspace.py index c31f727..4d6f5d3 100644 --- a/tfbpshiny/modules/binding/server/workspace.py +++ b/tfbpshiny/modules/binding/server/workspace.py @@ -17,6 +17,7 @@ get_measurement_column, regulator_scatter_sql, ) +from tfbpshiny.utils.profiler import profile_span from tfbpshiny.utils.sample_conditions import fetch_sample_condition_map from tfbpshiny.utils.vdb_init import AppDatasets, get_regulator_display_name @@ -33,6 +34,8 @@ def binding_workspace_server( vdb: VirtualDB, app_datasets: AppDatasets, logger: Logger, + profile_logger: Logger, + session_id: str = "", ) -> None: """ Render the binding correlation rows: pairwise distributions @@ -139,17 +142,25 @@ def _all_corr_data() -> dict[tuple[str, str], pd.DataFrame]: logger.debug( f"Correlating {db_a}({col_a}) vs {db_b}({col_b}) ({method})" ) - result[(db_a, db_b)] = corr_pair_sql( - vdb, - db_a, - col_a, - filters.get(db_a), - db_b, - col_b, - filters.get(db_b), - method, - prefix=f"p{i}_", - ) + with profile_span( + profile_logger, + "vdb.query", + module="binding", + dataset=f"{db_a}x{db_b}", + context="_all_corr_data", + session_id=session_id, + ): + result[(db_a, db_b)] = corr_pair_sql( + vdb, + db_a, + col_a, + filters.get(db_a), + db_b, + col_b, + filters.get(db_b), + method, + prefix=f"p{i}_", + ) except Exception as exc: logger.error( f"Failed to correlate {db_a} vs {db_b}: {exc}", exc_info=True @@ -305,14 +316,17 @@ def distributions_plot() -> ui.Tag: " });" "})();" ) - return ui.HTML( - to_html( - fig, - include_plotlyjs="cdn", - full_html=False, - post_script=post_script, + with profile_span( + profile_logger, + "plot.build", + module="binding", + context="distributions_plot", + session_id=session_id, + ): + html = to_html( + fig, include_plotlyjs="cdn", full_html=False, post_script=post_script ) - ) + return ui.HTML(html) @render.ui def regulator_selector() -> ui.Tag: @@ -441,7 +455,14 @@ def _strip_reg(f: dict | None) -> dict | None: reg, idx, ) - merged = vdb.query(scatter_sql, **scatter_params) + with profile_span( + profile_logger, + "vdb.query", + module="binding", + context="scatter", + session_id=session_id, + ): + merged = vdb.query(scatter_sql, **scatter_params) logger.debug( f"scatter {db_a}/{db_b} reg={reg!r} " f"rows={len(merged)} fa={fa!r} fb={fb!r}" @@ -503,9 +524,17 @@ def _strip_reg(f: dict | None) -> dict | None: width=400, height=400, ) + with profile_span( + profile_logger, + "plot.build", + module="binding", + context="regulator_plot", + session_id=session_id, + ): + plot_html = to_html(fig, include_plotlyjs=False, full_html=False) plot_divs.append( ui.div( - ui.HTML(to_html(fig, include_plotlyjs=False, full_html=False)), + ui.HTML(plot_html), style="flex: 0 0 auto;", ) ) diff --git a/tfbpshiny/modules/comparison/server/workspace.py b/tfbpshiny/modules/comparison/server/workspace.py index f71eb0a..28e0c8d 100644 --- a/tfbpshiny/modules/comparison/server/workspace.py +++ b/tfbpshiny/modules/comparison/server/workspace.py @@ -20,6 +20,7 @@ PERTURBATION_LABEL_MAP, topn_responsive_ratio, ) +from tfbpshiny.utils.profiler import profile_span from tfbpshiny.utils.vdb_init import get_regulator_display_name # color palettes @@ -70,6 +71,8 @@ def comparison_workspace_server( facet_by: Callable[[], str], vdb: VirtualDB, logger: Logger, + profile_logger: Logger, + session_id: str = "", ) -> None: """Render the Top-N by Binding workspace plot.""" @@ -133,19 +136,27 @@ def _topn_data() -> pd.DataFrame: p_filters = ( None if p_cfg.get("hackett_time_filter") else filters.get(p_db) ) - result = topn_responsive_ratio( - vdb=vdb, - binding_view=b_db, - perturbation_view=p_db, - top_n=n, - effect_threshold=eff, - pvalue_threshold=pval, - binding_filters=filters.get(b_db), - perturbation_filters=p_filters, - param_prefix=f"{b_db}_{p_db}", - **b_cfg, - **p_cfg, - ) + with profile_span( + profile_logger, + "vdb.query", + module="comparison", + dataset=f"{b_db}x{p_db}", + context="_topn_data", + session_id=session_id, + ): + result = topn_responsive_ratio( + vdb=vdb, + binding_view=b_db, + perturbation_view=p_db, + top_n=n, + effect_threshold=eff, + pvalue_threshold=pval, + binding_filters=filters.get(b_db), + perturbation_filters=p_filters, + param_prefix=f"{b_db}_{p_db}", + **b_cfg, + **p_cfg, + ) assert isinstance(result, pd.DataFrame) result["binding_source"] = b_label result["perturbation_source"] = p_label @@ -162,7 +173,14 @@ def _topn_data() -> pd.DataFrame: if not results: return pd.DataFrame() - out = pd.concat(results, ignore_index=True) + with profile_span( + profile_logger, + "df.concat", + module="comparison", + context="_topn_data", + session_id=session_id, + ): + out = pd.concat(results, ignore_index=True) out["percent_responsive"] = out["responsive_ratio"] * 100 return out @@ -268,7 +286,15 @@ def topn_plot() -> ui.Tag: legend_title=legend_title, margin=dict(l=50, r=20, t=80, b=30), ) - return ui.HTML(to_html(fig, include_plotlyjs="cdn", full_html=False)) + with profile_span( + profile_logger, + "plot.build", + module="comparison", + context="topn_plot", + session_id=session_id, + ): + html = to_html(fig, include_plotlyjs="cdn", full_html=False) + return ui.HTML(html) __all__ = ["comparison_workspace_server"] diff --git a/tfbpshiny/modules/perturbation/server/workspace.py b/tfbpshiny/modules/perturbation/server/workspace.py index 927c984..e7f9baa 100644 --- a/tfbpshiny/modules/perturbation/server/workspace.py +++ b/tfbpshiny/modules/perturbation/server/workspace.py @@ -17,6 +17,7 @@ get_measurement_column, regulator_scatter_sql, ) +from tfbpshiny.utils.profiler import profile_span from tfbpshiny.utils.sample_conditions import fetch_sample_condition_map from tfbpshiny.utils.vdb_init import AppDatasets, get_regulator_display_name @@ -33,6 +34,8 @@ def perturbation_workspace_server( vdb: VirtualDB, app_datasets: AppDatasets, logger: Logger, + profile_logger: Logger, + session_id: str = "", ) -> None: """ Render the perturbation correlation rows: pairwise distributions @@ -137,17 +140,25 @@ def _all_corr_data() -> dict[tuple[str, str], pd.DataFrame]: logger.debug( f"Correlating {db_a}({col_a}) vs {db_b}({col_b}) ({method})" ) - result[(db_a, db_b)] = corr_pair_sql( - vdb, - db_a, - col_a, - filters.get(db_a), - db_b, - col_b, - filters.get(db_b), - method, - prefix=f"p{i}_", - ) + with profile_span( + profile_logger, + "vdb.query", + module="perturbation", + dataset=f"{db_a}x{db_b}", + context="_all_corr_data", + session_id=session_id, + ): + result[(db_a, db_b)] = corr_pair_sql( + vdb, + db_a, + col_a, + filters.get(db_a), + db_b, + col_b, + filters.get(db_b), + method, + prefix=f"p{i}_", + ) except Exception as exc: logger.error( f"Failed to correlate {db_a} vs {db_b}: {exc}", exc_info=True @@ -303,14 +314,20 @@ def distributions_plot() -> ui.Tag: " });" "})();" ) - return ui.HTML( - to_html( + with profile_span( + profile_logger, + "plot.build", + module="perturbation", + context="distributions_plot", + session_id=session_id, + ): + html = to_html( fig, include_plotlyjs="cdn", full_html=False, post_script=post_script, ) - ) + return ui.HTML(html) @render.ui def regulator_selector() -> ui.Tag: @@ -439,7 +456,14 @@ def _strip_reg(f: dict | None) -> dict | None: reg, idx, ) - merged = vdb.query(scatter_sql, **scatter_params) + with profile_span( + profile_logger, + "vdb.query", + module="perturbation", + context="scatter", + session_id=session_id, + ): + merged = vdb.query(scatter_sql, **scatter_params) logger.debug( f"scatter {db_a}/{db_b} reg={reg!r} " f"rows={len(merged)} fa={fa!r} fb={fb!r}" @@ -501,9 +525,17 @@ def _strip_reg(f: dict | None) -> dict | None: width=400, height=400, ) + with profile_span( + profile_logger, + "plot.build", + module="perturbation", + context="regulator_plot", + session_id=session_id, + ): + plot_html = to_html(fig, include_plotlyjs=False, full_html=False) plot_divs.append( ui.div( - ui.HTML(to_html(fig, include_plotlyjs=False, full_html=False)), + ui.HTML(plot_html), style="flex: 0 0 auto;", ) ) diff --git a/tfbpshiny/modules/select_datasets/server/workspace.py b/tfbpshiny/modules/select_datasets/server/workspace.py index 90042e8..14e05b4 100644 --- a/tfbpshiny/modules/select_datasets/server/workspace.py +++ b/tfbpshiny/modules/select_datasets/server/workspace.py @@ -24,6 +24,7 @@ diagonal_cell_modal_ui, off_diagonal_cell_modal_ui, ) +from tfbpshiny.utils.profiler import profile_span from tfbpshiny.utils.ratelimit import debounce from tfbpshiny.utils.vdb_init import HIDDEN_FILTER_FIELDS @@ -38,6 +39,8 @@ def select_datasets_workspace_server( dataset_filters: reactive.Value[dict[str, Any]], vdb: VirtualDB, logger: Logger, + profile_logger: Logger, + session_id: str = "", ) -> None: """Render the sample-count matrix for all active datasets.""" @@ -83,12 +86,28 @@ def _matrix_data() -> dict[str, Any]: db_filters = filters.get(db_name) sql, params = regulator_locus_tags_query(db_name, db_filters) - reg_df = vdb.query(sql, **params) + with profile_span( + profile_logger, + "vdb.query", + module="select_datasets", + dataset=db_name, + context="_matrix_data", + session_id=session_id, + ): + reg_df = vdb.query(sql, **params) regulators = set(reg_df["regulator_locus_tag"].dropna().astype(str)) regulator_sets[db_name] = regulators sql, params = sample_count_query(db_name, db_filters) - n_samples = int(vdb.query(sql, **params).iloc[0, 0]) + with profile_span( + profile_logger, + "vdb.query", + module="select_datasets", + dataset=db_name, + context="_matrix_data", + session_id=session_id, + ): + n_samples = int(vdb.query(sql, **params).iloc[0, 0]) diagonal[db_name] = {"regulators": len(regulators), "samples": n_samples} @@ -105,8 +124,24 @@ def _matrix_data() -> dict[str, Any]: sql_b, params_b = sample_count_query( db_b, filters.get(db_b), restrict_to_regulators=common_list ) - n_a = int(vdb.query(sql_a, **params_a).iloc[0, 0]) - n_b = int(vdb.query(sql_b, **params_b).iloc[0, 0]) + with profile_span( + profile_logger, + "vdb.query", + module="select_datasets", + dataset=f"{db_a}x{db_b}", + context="_matrix_data", + session_id=session_id, + ): + n_a = int(vdb.query(sql_a, **params_a).iloc[0, 0]) + with profile_span( + profile_logger, + "vdb.query", + module="select_datasets", + dataset=f"{db_a}x{db_b}", + context="_matrix_data", + session_id=session_id, + ): + n_b = int(vdb.query(sql_b, **params_b).iloc[0, 0]) cross_dataset[(db_a, db_b)] = { "common_regulators": len(common), diff --git a/tfbpshiny/utils/profiler.py b/tfbpshiny/utils/profiler.py new file mode 100644 index 0000000..fa971c3 --- /dev/null +++ b/tfbpshiny/utils/profiler.py @@ -0,0 +1,89 @@ +"""Timing context manager for the profiler logger.""" + +from __future__ import annotations + +import json +import time +from collections.abc import Generator +from contextlib import contextmanager +from datetime import datetime, timezone +from logging import Logger + + +@contextmanager +def profile_span( + logger: Logger, + op: str, + module: str = "", + dataset: str = "", + context: str = "", + session_id: str = "", +) -> Generator[None]: + """ + Time a block of code and emit one structured JSON record to *logger*. + + Each record has the following keys:: + + {"event": "PROFILE", "ts": "...", "elapsed_s": 0.1234, + "op": "...", "module": "...", "dataset": "...", + "context": "...", "session_id": "..."} + + :param logger: The ``"profiler"`` logger. + :param op: Operation label, e.g. ``"vdb.query"`` or ``"plot.build"``. + :param module: Shiny module name, e.g. ``"binding"``. Empty for init-time spans. + :param dataset: Dataset(s) involved, e.g. ``"harbison"`` or ``"harbisонxrossi"``. + :param context: Function or plot name providing location, e.g. ``"_all_corr_data"``. + :param session_id: Shiny session ID, used to correlate spans and count concurrent + users. Empty for init-time spans that run outside a session. + + """ + t0 = time.perf_counter() + try: + yield + finally: + elapsed = time.perf_counter() - t0 + ts = datetime.now(timezone.utc).isoformat(timespec="milliseconds") + logger.debug( + json.dumps( + { + "event": "PROFILE", + "ts": ts, + "elapsed_s": round(elapsed, 4), + "op": op, + "module": module, + "dataset": dataset, + "context": context, + "session_id": session_id, + } + ) + ) + + +def log_session_event(logger: Logger, event: str, session_id: str) -> None: + """ + Emit a session lifecycle record to *logger*. + + Each record has the following keys:: + + {"event": "SESSION", "ts": "...", + "lifecycle": "START"|"END", "session_id": "..."} + + :param logger: The ``"profiler"`` logger. + :param event: ``"START"`` or ``"END"``. + :param session_id: Shiny session ID. + + """ + ts = datetime.now(timezone.utc).isoformat(timespec="milliseconds") + logger.debug( + json.dumps( + { + "event": "SESSION", + "ts": ts, + "lifecycle": event, + "session_id": session_id, + } + ) + ) + + +__all__ = ["profile_span", "log_session_event"] diff --git a/tfbpshiny/utils/vdb_init.py b/tfbpshiny/utils/vdb_init.py index de62974..e177be1 100644 --- a/tfbpshiny/utils/vdb_init.py +++ b/tfbpshiny/utils/vdb_init.py @@ -2,11 +2,15 @@ from __future__ import annotations +import logging from dataclasses import dataclass +from logging import Logger import pandas as pd from labretriever import VirtualDB +from tfbpshiny.utils.profiler import profile_span + # Metadata fields to suppress from the filter UI, keyed by db_name. # Use "*" for fields hidden across all datasets; use the db_name key for # dataset-specific exclusions. The effective hidden set for a given dataset @@ -140,7 +144,9 @@ def _filter_hackett_views(vdb: VirtualDB) -> None: ) -def ensure_hackett_analysis_set(vdb: VirtualDB) -> None: +def ensure_hackett_analysis_set( + vdb: VirtualDB, profile_logger: Logger | None = None +) -> None: """ Build the ``hackett_analysis_set`` table and permanently filter the ``hackett_meta`` and ``hackett`` views to include only those samples. @@ -148,9 +154,12 @@ def ensure_hackett_analysis_set(vdb: VirtualDB) -> None: Safe to call multiple times; uses ``CREATE OR REPLACE``. :param vdb: The application VirtualDB instance. + :param profile_logger: Optional profiler logger; timing is skipped when ``None``. """ - vdb._conn.execute(_HACKETT_ANALYSIS_SET_SQL) + _pl = profile_logger or logging.getLogger("profiler") + with profile_span(_pl, "init.hackett_set"): + vdb._conn.execute(_HACKETT_ANALYSIS_SET_SQL) _filter_hackett_views(vdb) @@ -174,7 +183,9 @@ def ensure_hackett_analysis_set(vdb: VirtualDB) -> None: """ -def _build_regulator_display_names(vdb: VirtualDB) -> None: +def _build_regulator_display_names( + vdb: VirtualDB, profile_logger: Logger | None = None +) -> None: """ Build the ``regulator_display_names`` DuckDB table from all dataset meta views. @@ -184,6 +195,7 @@ def _build_regulator_display_names(vdb: VirtualDB) -> None: non-empty symbol different from the tag is present; otherwise it equals the tag. :param vdb: The application VirtualDB instance. + :param profile_logger: Optional profiler logger; timing is skipped when ``None``. """ db_names = [ @@ -201,12 +213,15 @@ def _build_regulator_display_names(vdb: VirtualDB) -> None: table=_REGULATOR_DISPLAY_NAME_TABLE, union_sql=union_sql, ) - vdb._conn.execute(sql) + _pl = profile_logger or logging.getLogger("profiler") + with profile_span(_pl, "init.regulator_table"): + vdb._conn.execute(sql) def get_regulator_display_name( vdb: VirtualDB, locus_tags: list[str] | None = None, + profile_logger: Logger | None = None, ) -> pd.DataFrame: """ Return a DataFrame of regulator display names from the pre-built lookup table. @@ -219,13 +234,22 @@ def get_regulator_display_name( :rtype: pandas.DataFrame """ - if locus_tags is None: - return vdb._conn.execute(f"SELECT * FROM {_REGULATOR_DISPLAY_NAME_TABLE}").df() - return vdb._conn.execute( - f"SELECT * FROM {_REGULATOR_DISPLAY_NAME_TABLE} " - f"WHERE regulator_locus_tag = ANY(?)", - [locus_tags], - ).df() + _pl = profile_logger or logging.getLogger("profiler") + with profile_span( + _pl, + "vdb.execute", + dataset=_REGULATOR_DISPLAY_NAME_TABLE, + context="get_regulator_display_name", + ): + if locus_tags is None: + return vdb._conn.execute( + f"SELECT * FROM {_REGULATOR_DISPLAY_NAME_TABLE}" + ).df() + return vdb._conn.execute( + f"SELECT * FROM {_REGULATOR_DISPLAY_NAME_TABLE} " + f"WHERE regulator_locus_tag = ANY(?)", + [locus_tags], + ).df() @dataclass @@ -252,19 +276,21 @@ class AppDatasets: def initialize_data( virtualdb_config: str, hf_token: str | None = None, + profile_logger: Logger | None = None, ) -> tuple[VirtualDB, AppDatasets]: """ Construct the VirtualDB, run one-time setup, and compute app-level dataset metadata. :param virtualdb_config: Path to the VirtualDB YAML config file. :param hf_token: Optional HuggingFace token for private repo access. + :param profile_logger: Optional profiler logger for timing instrumentation. :returns: Tuple of ``(vdb, app_datasets)``. :rtype: tuple[VirtualDB, AppDatasets] """ vdb = VirtualDB(virtualdb_config, token=hf_token) - ensure_hackett_analysis_set(vdb) - _build_regulator_display_names(vdb) + ensure_hackett_analysis_set(vdb, profile_logger=profile_logger) + _build_regulator_display_names(vdb, profile_logger=profile_logger) condition_cols: dict[str, list[str]] = {} upstream_cols: dict[str, list[str]] = {}