HTTP请求监控响应时间

嗨，开发者们！

今天我想谈谈一个让我感到困难的话题。我相信你们中的很多人一定已经遇到过这种情况（所谓的“瓶颈”）。由于这是一个广泛的主题，因此本文将仅重点关注识别可能导致缓慢问题的传入 HTTP 请求。我还将向您提供我开发的一个小工具来帮助识别它们。

我们的软件变得越来越复杂，处理来自不同来源的大量请求，无论是前端还是第三方后端应用程序。为了确保最佳性能，必须有一个能够记录一些关键测量的日志系统，例如响应时间、global引用的数量以及每个 HTTP 响应执行的代码行数。作为工作的一部分，我参与了 EMR 软件的开发以及事件分析。由于用户负载主要来自 HTTP 请求（REST API 或 CSP 应用程序），因此在发生普遍缓慢问题时进行此类测量的需求变得显而易见。

响应时间指标

评估应用程序性能最相关的元素之一是响应时间。每个请求都必须在合理的时间内得到答复，以提供令人满意的用户体验。这就是为什么通过记录每个请求的响应时间，日志系统可以帮助我们识别不良性能。我们还可以使用此信息来查明哪些 API 或 CSP 比其他 API 或 CSP 慢，以便对其进行优化，从而提高应用程序的整体执行速度。

global编号参考

虽然响应时间是一个关键特性，但我们也不应忽视global引用的数量。我们应该记住，磁盘访问通常也是一项耗费大量执行时间的操作。不过，IRIS 缓存的效率可以掩盖这个问题。我的意思是，如果同时访问许多global
缓存引用，响应时间会很出色。不过，只要我们访问的数据来自缓存之外，性能就会大幅下降。换句话说，在一个同时发出多个请求的系统中，过度使用磁盘访问会导致速度明显变慢。通过日志系统对每个请求的global
访问引用进行测量，我们还可以发现过度占用资源的 HTTP 请求。发现这些问题后，开发人员就可以进行修改，以尽量减少这种访问（通过添加索引、优化 SQL 查询、改变逻辑等）

执行的代码行数

计算每个请求执行的代码行数可以让我们衡量所执行操作的复杂性和规模。该指标帮助我们识别运行过多行代码的查询，这可能表明需要优化的代码片段。大多数情况下，问题在于global引用的数量。然而，如果代码的复杂部分仅是对内存数据的操作而很少访问数据库，则此测量将可以突出显示它（例如，如果存在循环问题）。

异常检测

系统日志还可用于检测响应查询性能中的异常情况。通过记录这些测量结果，您可以识别异常请求。例如，如果通常运行速度很快的查询突然开始花费更长的时间或过度访问磁盘，这可能意味着存在需要立即关注的潜在问题（例如，应用程序更新后响应时间增加）。请记住，早期异常检测有助于我们快速解决性能问题并确保良好的用户体验。

网络计时记录器软件包

最近，我为社区开发了一个小工具，允许我们记录所有传入的 HTTP 请求。如果您有兴趣，可以在 Open Exchange 上找到它。该工具特别记录了本文中讨论的关键指标：执行的代码行数、global引用数和响应时间。它还记录有关调用者的一些信息，这些信息可以在调试时派上用场：

• 日期和时间。
• 用户已登录。
• 呼叫者的 IP 地址。
• 网址。
• 执行命名空间。
• 应用程序网络。
• 页面名称（如果适用）。
• 不带参数的 URL。

 

除此之外，它还提供将自定义指标与 SAM（“/api/monitor”）集成的功能，这可以让您将它们合并到Prom etheus 中并使用 Grafana 制作仪表板。

每个 Web 应用程序、页面或路由（如果是 REST 应用程序）每天以及每刻钟都会聚合一系列数据：

• 总点击数：收到的请求数。
• 总时间：所有请求的累积响应时间。
• 最大计时：最慢的响应时间。
• 平均时间：平均响应时间。

相同的指标也可用于global引用和执行的代码行。

                                                             

下面您可以看到在 Web 应用程序“ /api/monitor/” 和“ /csp/sys/exp/” 上启用指标的示例：

 webmeasure_average_gloref{id= "/api/monitor/" } 903.5227272727272727 webmeasure_average_gloref{id= "/api/monitor/metrics" } 903.5227272727272727 webmeasure_average_gloref{id= "/csp/sys/exp/" } 1853.6875 webmeasure_average_gloref{id= "/csp/sys/exp/%CSP.Broker.cls" } 1242.933333333333333 webmeasure_average_gloref{id= "/csp/sys/exp/%CSP.UI.Portal.SQL.Home.zen" } 11015 webmeasure_average_gloref_current_quarter{id= "/api/monitor/" } 903.5227272727272727 webmeasure_average_gloref_current_quarter{id= "/api/monitor/metrics" } 903.5227272727272727 webmeasure_average_gloref_current_quarter{id= "/csp/sys/exp/" } 1853.6875 webmeasure_average_gloref_current_quarter{id= "/csp/sys/exp/%CSP.Broker.cls" } 1242.933333333333333 webmeasure_average_gloref_current_quarter{id= "/csp/sys/exp/%CSP.UI.Portal.SQL.Home.zen" } 11015 webmeasure_average_lines{id= "/api/monitor/" } 29365.5 webmeasure_average_lines{id= "/api/monitor/metrics" } 29365.5 webmeasure_average_lines{id= "/csp/sys/exp/" } 19415.5 webmeasure_average_lines{id= "/csp/sys/exp/%CSP.Broker.cls" } 11570.73333333333333 webmeasure_average_lines{id= "/csp/sys/exp/%CSP.UI.Portal.SQL.Home.zen" } 137087 webmeasure_average_lines_current_quarter{id= "/api/monitor/" } 29365.5 webmeasure_average_lines_current_quarter{id= "/api/monitor/metrics" } 29365.5 webmeasure_average_lines_current_quarter{id= "/csp/sys/exp/" } 19415.5 webmeasure_average_lines_current_quarter{id= "/csp/sys/exp/%CSP.Broker.cls" } 11570.73333333333333 webmeasure_average_lines_current_quarter{id= "/csp/sys/exp/%CSP.UI.Portal.SQL.Home.zen" } 137087 webmeasure_average_timing_in_ms{id= "/api/monitor/" } 27.27256818181818182 webmeasure_average_timing_in_ms{id= "/api/monitor/metrics" } 27.27256818181818182 webmeasure_average_timing_in_ms{id= "/csp/sys/exp/" } 16.6 webmeasure_average_timing_in_ms{id= "/csp/sys/exp/%CSP.Broker.cls" } 9.94633333333333333 webmeasure_average_timing_in_ms{id= "/csp/sys/exp/%CSP.UI.Portal.SQL.Home.zen" } 116.405 webmeasure_average_timing_in_ms_current_quarter{id= "/api/monitor/" } 27.27256818181818182 webmeasure_average_timing_in_ms_current_quarter{id= "/api/monitor/metrics" } 27.27256818181818182 webmeasure_average_timing_in_ms_current_quarter{id= "/csp/sys/exp/" } 16.6 webmeasure_average_timing_in_ms_current_quarter{id= "/csp/sys/exp/%CSP.Broker.cls" } 9.94633333333333333 webmeasure_average_timing_in_ms_current_quarter{id= "/csp/sys/exp/%CSP.UI.Portal.SQL.Home.zen" } 116.405 webmeasure_max_lines{id= "/api/monitor/" } 29498 webmeasure_max_lines{id= "/api/monitor/metrics" } 29498 webmeasure_max_lines{id= "/csp/sys/exp/" } 137087 webmeasure_max_lines{id= "/csp/sys/exp/%CSP.Broker.cls" } 45208 webmeasure_max_lines{id= "/csp/sys/exp/%CSP.UI.Portal.SQL.Home.zen" } 137087 webmeasure_max_lines_current_quarter{id= "/api/monitor/" } 29498 webmeasure_max_lines_current_quarter{id= "/api/monitor/metrics" } 29498 webmeasure_max_lines_current_quarter{id= "/csp/sys/exp/" } 137087 webmeasure_max_lines_current_quarter{id= "/csp/sys/exp/%CSP.Broker.cls" } 45208 webmeasure_max_lines_current_quarter{id= "/csp/sys/exp/%CSP.UI.Portal.SQL.Home.zen" } 137087 webmeasure_max_timing{id= "/api/monitor/" } 40.783 webmeasure_max_timing{id= "/api/monitor/metrics" } 40.783 webmeasure_max_timing{id= "/csp/sys/exp/" } 116.405 webmeasure_max_timing{id= "/csp/sys/exp/%CSP.Broker.cls" } 66.458 webmeasure_max_timing{id= "/csp/sys/exp/%CSP.UI.Portal.SQL.Home.zen" } 116.405 webmeasure_max_timing_current_quarter{id= "/api/monitor/" } 40.783 webmeasure_max_timing_current_quarter{id= "/api/monitor/metrics" } 40.783 webmeasure_max_timing_current_quarter{id= "/csp/sys/exp/" } 116.405 webmeasure_max_timing_current_quarter{id= "/csp/sys/exp/%CSP.Broker.cls" } 66.458 webmeasure_max_timing_current_quarter{id= "/csp/sys/exp/%CSP.UI.Portal.SQL.Home.zen" } 116.405 webmeasure_total_gloref{id= "/api/monitor/" } 39755 webmeasure_total_gloref{id= "/api/monitor/metrics" } 39755 webmeasure_total_gloref{id= "/csp/sys/exp/" } 29659 webmeasure_total_gloref{id= "/csp/sys/exp/%CSP.Broker.cls" } 18644 webmeasure_total_gloref{id= "/csp/sys/exp/%CSP.UI.Portal.SQL.Home.zen" } 11015 webmeasure_total_gloref_current_quarter{id= "/api/monitor/" } 39755 webmeasure_total_gloref_current_quarter{id= "/api/monitor/metrics" } 39755 webmeasure_total_gloref_current_quarter{id= "/csp/sys/exp/" } 29659 webmeasure_total_gloref_current_quarter{id= "/csp/sys/exp/%CSP.Broker.cls" } 18644 webmeasure_total_gloref_current_quarter{id= "/csp/sys/exp/%CSP.UI.Portal.SQL.Home.zen" } 11015 webmeasure_total_hit{id= "/api/monitor/" } 44 webmeasure_total_hit{id= "/api/monitor/metrics" } 44 webmeasure_total_hit{id= "/csp/sys/exp/" } 16 webmeasure_total_hit{id= "/csp/sys/exp/%CSP.Broker.cls" } 15 webmeasure_total_hit{id= "/csp/sys/exp/%CSP.UI.Portal.SQL.Home.zen" } 1 webmeasure_total_hit_current_quarter{id= "/api/monitor/" } 44 webmeasure_total_hit_current_quarter{id= "/api/monitor/metrics" } 44 webmeasure_total_hit_current_quarter{id= "/csp/sys/exp/" } 16 webmeasure_total_hit_current_quarter{id= "/csp/sys/exp/%CSP.Broker.cls" } 15 webmeasure_total_hit_current_quarter{id= "/csp/sys/exp/%CSP.UI.Portal.SQL.Home.zen" } 1 webmeasure_total_lines{id= "/api/monitor/" } 1292082 webmeasure_total_lines{id= "/api/monitor/metrics" } 1292082 webmeasure_total_lines{id= "/csp/sys/exp/" } 310648 webmeasure_total_lines{id= "/csp/sys/exp/%CSP.Broker.cls" } 173561 webmeasure_total_lines{id= "/csp/sys/exp/%CSP.UI.Portal.SQL.Home.zen" } 137087 webmeasure_total_lines_current_quarter{id= "/api/monitor/" } 1292082 webmeasure_total_lines_current_quarter{id= "/api/monitor/metrics" } 1292082 webmeasure_total_lines_current_quarter{id= "/csp/sys/exp/" } 310648 webmeasure_total_lines_current_quarter{id= "/csp/sys/exp/%CSP.Broker.cls" } 173561 webmeasure_total_lines_current_quarter{id= "/csp/sys/exp/%CSP.UI.Portal.SQL.Home.zen" } 137087 webmeasure_total_timing_in_ms{id= "/api/monitor/" } 1199.993 webmeasure_total_timing_in_ms{id= "/api/monitor/metrics" } 1199.993 webmeasure_total_timing_in_ms{id= "/csp/sys/exp/" } 265.6 webmeasure_total_timing_in_ms{id= "/csp/sys/exp/%CSP.Broker.cls" } 149.195 webmeasure_total_timing_in_ms{id= "/csp/sys/exp/%CSP.UI.Portal.SQL.Home.zen" } 116.405 webmeasure_total_timing_in_ms_current_quarter{id= "/api/monitor/" } 1199.993 webmeasure_total_timing_in_ms_current_quarter{id= "/api/monitor/metrics" } 1199.993 webmeasure_total_timing_in_ms_current_quarter{id= "/csp/sys/exp/" } 265.6 webmeasure_total_timing_in_ms_current_quarter{id= "/csp/sys/exp/%CSP.Broker.cls" } 149.195 webmeasure_total_timing_in_ms_current_quarter{id= "/csp/sys/exp/%CSP.UI.Portal.SQL.Home.zen" } 116.405

您可能已经注意到，上面说明的指标非常通用。我强烈鼓励您扩展您的指标并使它们个性化。正确监控您的应用程序是必要的。

使用 ZPM 安装

如果您想要进行测试安装，并且您是 Docker 用户，我建议您查看本节以获取一些实用信息，然后继续进行下一个。容器构建脚本化以自动配置环境。

安装是通过 ZPM 完成的。只需转到 IRIS 终端并执行以下操作：

 zpm "install web-timing-logger”

安装后，您需要初始化设置，因此只需运行：

 Do ##class (dc.webtiming.Config).Initialize()

默认情况下，HTTP 请求日志和指标不活动。要启用它们，请执行以下步骤：

 Do ##class (dc.webtiming.Config).SetLogEnabled( 1 ) Do ##class (dc.webtiming.Config).SetMetricsEnabled( 1 )

为了让 SAM (“/api/monitor”) 公开自定义指标，您不仅必须向 Web 应用程序 /API/monitor 添加角色，还必须在 SYS.Monitor.SAM.Config 中注册一个类，因此运行以下命令：

 Do ##class (dc.webtiming.Config).ConfigureAPIMonitor()

如果您想在不同命名空间中运行的多个 Web 应用程序中使用此实用程序，则映射包“dc.webtiming”以及“%ALL”中的全局​​变量“dc.webtiming*”至关重要。为了避免手动执行此操作，请使用下面指定的方法：

 Do ##class (dc.webtiming.Config).AddToPercentAllNS()

所有上述操作都可以使用以下命令在一行中执行：

 Do ##class (dc.webtiming.Config).DefaultSetup()

使用 Docker 安装

Docker 的开始是经典的。克隆存储库并启动容器：

 git clone https://github.com/lscalese/iris-web-timing-logger.git docker-compose up -d

在网络应用程序上激活

现在我们已经配置了系统，还需要解决一个重要的细节，以便您能够记录测量结果。要了解您需要做什么，您应该了解系统如何工作。为了触发测量和记录，web-timing-logger 使用事件“OnStartRequest”和“OnEndRequest”。这些事件在类“dc.webtiming.CSPSessionEvents”中实现，该类是“%CSP.SessionEvents”的子类。因此，每个 Web 应用程序都必须配置事件类“dc.webtiming.CSPSessionEvents”。

 

如果您的 Web 应用程序已经在使用另一个事件类，请不要担心！只需将以下调用添加到此类：

在OnStartRequest方法中：

 Do ##class (dc.webtiming.Events).OnStart()

在 OnEndRequest 方法中：

 Do ##class (dc.webtiming.Events).OnEnd()

这将为您现有的事件类添加测量和记录功能。

对您想要测量的所有 Web 应用程序执行此配置。

在这种情况下，您有一个空系统并且只想进行一些测试，请使用 /API/monitor 应用程序上的配置。由于对指标的访问是通过 HTTP 调用建立的，因此也可以对它们进行测量以生成日志。因此，只需打开浏览器并多次访问页面http://localhost:49165/api/monitor/metrics（根据您的端口号进行调整）。您会注意到指标“webmeasure”已启用，并且表“dc_webtiming_log.Request”填充了来自 HTTP 请求的数据：

 SELECT * FROM dc_webtiming_log.Request

尽管 Web-timing-logger 可以轻松识别 Web 应用程序中有问题的入口点，但它无法提供有关导致问题的代码特定部分的精确信息。一旦确定了入口点，您就可以使用其他工具，例如 Dmitry Maslennikov 开发的OEX ZProfile 。它可以对正在执行的代码进行深入分析。在这里查看一篇专门的文章。

好了，这就是今天的全部内容。当然，我们还可以在“web-timing-logger”上解决其他问题，例如清理日志、Grafana 仪表板示例，甚至一些有趣的 SQL 查询。我希望您喜欢这篇文章，它将为您提供监控应用程序的想法。如果你有兴趣的话我可能会写续集。

再见！