内存飙高之导出功能
15:08 运营反馈,系统卡顿.
短暂分析之后, 暂时无果, 让运维把容器重启.
查看GC情况
在运营反馈问题之前, 系统已经出现异常近50分钟. 系统一直在MajorGC, 且GC时间达到分钟级.
从侧面反映, 团队对服务健康监控做的不到位.
查看堆情况
新生代和老年代使用内存都明显在增长. 新生代内存增长1G左右, 在7分钟之内老年代内存增长5G左右.
查看耗时长的请求
请求耗时长, 未必表明异常情况是由该耗时久的请求导致. 可疑对象可能是消费MQ, 也可能是定时任务等.
已知系统出现问题, 但当时没有触发OOM, 没有堆转储文件产生, 容器也被手动重启. 如何找到问题所在?
一个小时过去了
既然内存飙高, 因数据引起, 将目光转移到查询数据库. 业务代码查询数据库使用P6Spy会打印SQL语句, 因此查询内存突然飙高的时间范围内产生的SQL语句, 是否存在查询数据量大的SQL或者长事务等.
查询关键字: p6spy:logSQL-60
如上, 查询页面展示的结果, SQL语句很相似, 而且有traceId相同的情况. 继续查询该traceId.
当时在分析这块日志的时候花费了好几分钟, 才找到认为可疑地方.
事后对系统增加了访问记录, 所有访问系统的请求(包括浏览器HTTP,OPEN_FEIGN,MQ等)都会被记录下来.
如上, 同一个traceId, 有4.78万条日志, 而且4.78万条日志里打印的SQL也很相似. 感觉即将找到问题所在了^v^.
查询该traceId最开始打印的日志.
如上, 该SQL执行会返回56188条记录. 根据对业务的理解和日志打印的情况, 代码定位到Excel导出功能.
前端页面有分页查询销售单出库列表的功能, 同时支持将查询出来的列表数据导出到Excel中. 而之前的开发人员, 导出功能复用了分页逻辑, 只是将分页条件的LIMIT设置成Integer.MAX_VALUE, 上图的日志SQL也有所体现. 导致查询出5万+数据, 业务代码又对查询出来的结果进行循环遍历, 致使事务耗时久, 从数据库查询到的数据一直存放在新生代, 近7分钟后进入老年代, 触发MajorGC, GC时间达到分钟级, STW, 最终导致服务无法响应外部的HTTP请求.
暂时修改业务代码, 限制导出的数据条数在3000以内. 长远规划的话, 可以搭建一个专为导出功能的服务, 避免影响正常业务功能.
分析问题的角度 :
1.JVM (虚拟内存大小 + committed内存大小 + 已使用内存大小)
2.阿里云日志或观测云日志等日志系统, 正常业务,同一个链路ID的日志有十几条或几十条. 出问题的链路,大概率同一个链路ID的日志条数达到万条
3.访问系统的操作日志表 根据JVM出现问题的时间范围查询操作日志表,找到可疑操作 案例
4.访问普罗米修斯查看HTTP响应时间,找到可疑请求
5.分析堆转储文件(如果有条件得到) Histogram / Java Basics -> Unreachable Objects Histogram
扩展:
1.将56188条记录从MySQL返回给服务程序, 这么大的数据量也能传送成功?
线上数据库设置 max_allowed_packet = 1G , 默认是4M
链接: MySQL官方解读max_allowed_packet
2.如何计算SELECT查询返回的数据大小? 或如何计算表中行记录的大小?
3.基于此次事件, 增加服务健康检查(/actuator/health)和长事务检查, 一旦发现异常, 及时钉钉提醒.
15:08 运营反馈,系统卡顿.
短暂分析之后, 暂时无果, 让运维把容器重启.
查看GC情况
在运营反馈问题之前, 系统已经出现异常近50分钟. 系统一直在MajorGC, 且GC时间达到分钟级.
从侧面反映, 团队对服务健康监控做的不到位.
查看堆情况
新生代和老年代使用内存都明显在增长. 新生代内存增长1G左右, 在7分钟之内老年代内存增长5G左右.
查看耗时长的请求
请求耗时长, 未必表明异常情况是由该耗时久的请求导致. 可疑对象可能是消费MQ, 也可能是定时任务等.
已知系统出现问题, 但当时没有触发OOM, 没有堆转储文件产生, 容器也被手动重启. 如何找到问题所在?
一个小时过去了
既然内存飙高, 因数据引起, 将目光转移到查询数据库. 业务代码查询数据库使用P6Spy会打印SQL语句, 因此查询内存突然飙高的时间范围内产生的SQL语句, 是否存在查询数据量大的SQL或者长事务等.
查询关键字: p6spy:logSQL-60
如上, 查询页面展示的结果, SQL语句很相似, 而且有traceId相同的情况. 继续查询该traceId.
当时在分析这块日志的时候花费了好几分钟, 才找到认为可疑地方.
事后对系统增加了访问记录, 所有访问系统的请求(包括浏览器HTTP,OPEN_FEIGN,MQ等)都会被记录下来.
-- 操作记录表
CREATE TABLE `operation_record` (
`record_id` bigint NOT NULL COMMENT '主键',
`enterprise_id` bigint DEFAULT NULL COMMENT '企业ID',
`account_id` bigint DEFAULT NULL COMMENT '操作人ID',
`user_name` varchar(32) CHARACTER SET utf8mb4 COLLATE utf8mb4_general_ci DEFAULT NULL COMMENT '操作人名称',
`real_name` varchar(32) CHARACTER SET utf8mb4 COLLATE utf8mb4_general_ci DEFAULT NULL COMMENT '操作人名称',
`handle_status` tinyint DEFAULT '1' COMMENT '处理状态. 1:成功 2:失败',
`handle_status_desc` char(2) COLLATE utf8mb4_general_ci DEFAULT '成功' COMMENT '处理状态. 1:成功 2:失败',
`header` varchar(1000) CHARACTER SET utf8mb4 COLLATE utf8mb4_general_ci DEFAULT NULL COMMENT '操作请求头',
`in_body` longtext CHARACTER SET utf8mb4 COLLATE utf8mb4_general_ci COMMENT '操作请求内容',
`out_body` longtext CHARACTER SET utf8mb4 COLLATE utf8mb4_general_ci COMMENT '操作响应内容',
`business_no` varchar(32) CHARACTER SET utf8mb4 COLLATE utf8mb4_general_ci DEFAULT NULL COMMENT '业务单号',
`business_id` bigint DEFAULT NULL COMMENT '业务ID',
`message_id` varchar(40) CHARACTER SET utf8mb4 COLLATE utf8mb4_general_ci DEFAULT NULL COMMENT 'MQ消息ID',
`service_name` varchar(32) CHARACTER SET utf8mb4 COLLATE utf8mb4_general_ci DEFAULT NULL COMMENT '服务名称',
`module_name` varchar(32) CHARACTER SET utf8mb4 COLLATE utf8mb4_general_ci DEFAULT NULL COMMENT '模块名称',
`method` varchar(128) CHARACTER SET utf8mb4 COLLATE utf8mb4_general_ci DEFAULT NULL COMMENT '接口名称',
`remark` varchar(128) CHARACTER SET utf8mb4 COLLATE utf8mb4_general_ci DEFAULT NULL COMMENT '功能描述',
`desc` varchar(256) CHARACTER SET utf8mb4 COLLATE utf8mb4_general_ci DEFAULT NULL COMMENT '描述信息',
`source_type` int unsigned NOT NULL COMMENT '来源方式类型',
`source_name` varchar(32) CHARACTER SET utf8mb4 COLLATE utf8mb4_general_ci DEFAULT NULL COMMENT '来源方式名称',
`user_agent` varchar(1024) CHARACTER SET utf8mb4 COLLATE utf8mb4_general_ci DEFAULT NULL COMMENT 'User-Agent',
`domain` varchar(128) CHARACTER SET utf8mb4 COLLATE utf8mb4_general_ci DEFAULT NULL COMMENT '域名',
`source_ip` varchar(32) CHARACTER SET utf8mb4 COLLATE utf8mb4_general_ci DEFAULT NULL COMMENT '来源IP',
`handle_ip` varchar(32) CHARACTER SET utf8mb4 COLLATE utf8mb4_general_ci DEFAULT NULL COMMENT '事件处理节点的IP',
`trace_id` varchar(64) CHARACTER SET utf8mb4 COLLATE utf8mb4_general_ci DEFAULT NULL COMMENT '观测云traceId',
`create_time` datetime(3) NOT NULL COMMENT '创建时间',
`update_time` datetime(3) NOT NULL COMMENT '修改时间',
PRIMARY KEY (`record_id`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_general_ci ROW_FORMAT=DYNAMIC COMMENT='操作记录表' ;
如上, 同一个traceId, 有4.78万条日志, 而且4.78万条日志里打印的SQL也很相似. 感觉即将找到问题所在了^v^.
查询该traceId最开始打印的日志.
如上, 该SQL执行会返回56188条记录. 根据对业务的理解和日志打印的情况, 代码定位到Excel导出功能.
前端页面有分页查询销售单出库列表的功能, 同时支持将查询出来的列表数据导出到Excel中. 而之前的开发人员, 导出功能复用了分页逻辑, 只是将分页条件的LIMIT设置成Integer.MAX_VALUE, 上图的日志SQL也有所体现. 导致查询出5万+数据, 业务代码又对查询出来的结果进行循环遍历, 致使事务耗时久, 从数据库查询到的数据一直存放在新生代, 近7分钟后进入老年代, 触发MajorGC, GC时间达到分钟级, STW, 最终导致服务无法响应外部的HTTP请求.
暂时修改业务代码, 限制导出的数据条数在3000以内. 长远规划的话, 可以搭建一个专为导出功能的服务, 避免影响正常业务功能.
分析问题的角度 :
1.JVM (虚拟内存大小 + committed内存大小 + 已使用内存大小)
2.阿里云日志或观测云日志等日志系统, 正常业务,同一个链路ID的日志有十几条或几十条. 出问题的链路,大概率同一个链路ID的日志条数达到万条
3.访问系统的操作日志表 根据JVM出现问题的时间范围查询操作日志表,找到可疑操作 案例
4.访问普罗米修斯查看HTTP响应时间,找到可疑请求
5.分析堆转储文件(如果有条件得到) Histogram / Java Basics -> Unreachable Objects Histogram
扩展:
1.将56188条记录从MySQL返回给服务程序, 这么大的数据量也能传送成功?
-- 数据包最大值
show variables like 'max_allowed_packet';
线上数据库设置 max_allowed_packet = 1G , 默认是4M
链接: MySQL官方解读max_allowed_packet
2.如何计算SELECT查询返回的数据大小? 或如何计算表中行记录的大小?
3.基于此次事件, 增加服务健康检查(/actuator/health)和长事务检查, 一旦发现异常, 及时钉钉提醒.
-- 长事务检查
SELECT
now()- t.trx_started AS `事务持续时间`,
t.*
FROM
information_schema.innodb_trx t;