概述

某客户电子发票ISMS业务程序异从2022/2/20日早上8:52分至9：07分左右使用异常，之后自动恢复正常。通过远程方式接入数据库环境进行故障排查，通过对相关日志等信息的深入分析，找出问题点并提出解决方案

告警中的表空间使用率高问题分析

1. HIS数据库节点2在问题时间段的日志信息

节点2：系统自动扩大数据文件记录

2022-02-20T08:51:50.076038+08:00

HISDB(3):Using deprecated SQLNET.ALLOWED_LOGON_VERSION parameter.

2022-02-20T08:52:12.250967+08:00

HISDB(3):Resize operation completed for file# 50, old size 1048576K, new size 1069056K

2022-02-20T08:52:12.623885+08:00

HISDB(3):Resize operation completed for file# 50, old size 1069056K, new size 1110016K

2022-02-20T08:56:42.517712+08:00

HISDB(3):Using deprecated SQLNET.ALLOWED_LOGON_VERSION parameter.

2022-02-20T08:56:42.736925+08:00

HISDB(3):Resize operation completed for file# 49, old size 1048576K, new size 1069056K

2022-02-20T08:56:42.743704+08:00

HISDB(3):Resize operation completed for file# 50, old size 1110016K, new size 1130496K

2. HIS数据库节点1在问题时间段的日志信息

节点1：9:17分人工扩大数据文件日志记录

2022-02-20T09:17:43.482573+08:00

HISDB(3): alter database datafile ‘+DATADG/CDB/HISDB/DATAFILE/isms_data01’ resize 2G

2022-02-20T09:17:43.726081+08:00

HISDB(3):Using deprecated SQLNET.ALLOWED_LOGON_VERSION parameter.

2022-02-20T09:17:44.483661+08:00

HISDB(3):Using deprecated SQLNET.ALLOWED_LOGON_VERSION parameter.

2022-02-20T09:17:44.556208+08:00

HISDB(3):Using deprecated SQLNET.ALLOWED_LOGON_VERSION parameter.

2022-02-20T09:17:45.556743+08:00

HISDB(3):Using deprecated SQLNET.ALLOWED_LOGON_VERSION parameter.

2022-02-20T09:17:45.638312+08:00

HISDB(3):Resize operation completed for file# 49, old size 1069056K, new size 2097152K

HISDB(3):Completed: alter database datafile ‘+DATADG/CDB/HISDB/DATAFILE/isms_data01’ resize 2G

2022-02-20T09:17:45.663855+08:00

HISDB(3):Using deprecated SQLNET.ALLOWED_LOGON_VERSION parameter.

2022-02-20T09:17:58.864830+08:00

HISDB(3):alter database datafile ‘+DATADG/CDB/HISDB/DATAFILE/isms_idx01’ resize 2G

2022-02-20T09:17:59.466571+08:00

HISDB(3):Using deprecated SQLNET.ALLOWED_LOGON_VERSION parameter.

2022-02-20T09:18:00.541385+08:00

3. 表空间相关属性信息

查看数据文件属性，支持自动扩展

SQL> select file_id,file_name,bytes/1024/1024 mb,AUTOEXTENSIBLE,status,maxbytes/1024/1024 from dba_data_files where tablespace_name=’ISMS_DATA’;

FILE_ID FILE_NAME MB AUT STATUS MAXBYTES/1024/1024

———- ————————————————– ———- — ——— ——————

49 +DATADG/CDB/HISDB/DATAFILE/isms_data01 2048 YES AVAILABLE 32767.9844

SQL> select file_id,file_name,bytes/1024/1024 mb,AUTOEXTENSIBLE,status,maxbytes/1024/1024 from dba_data_files where tablespace_name=’ISMS_IDX’;

FILE_ID FILE_NAME MB AUT STATUS MAXBYTES/1024/1024

———- ————————————————– ———- — ——— ——————

50 +DATADG/CDB/HISDB/DATAFILE/isms_idx01 2048 YES AVAILABLE 32767.9844

表空间使用率-2022/2/20 13:45分记录

TABLESPACE_NAME Total(M) usage_of_tablespace% left_space(M) Extent_man

—————————————- ———- ——————– ————- ———-

ISMS_IDX 2048 51 1009.125 LOCAL

ISMS_DATA 2048 49 1054 LOCAL

4. 表空间问题分析描述

微信告警的表空间问题的分析：

1.监控报警截图8:52分报ISMS_DATA及ISMS_IDX表空间使用率高，截图中数据文件大小为1GB。

2.检查表空间及数据文件的属性信息，数据文件支持自动扩大(最大32GB)。

3.查看数据库日志-节点2中，在08:52:12及08:56:42均有自动扩大的记录

4.查看数据库日志-节点1，在9:17分人工将数据文件扩大到2GB。

表空间告警问题分析总结：

由于ISMS_DATA及ISMS_IDX表空间的属性支持自动扩大(最大32GB)，告警时大小为1GB。在数据库日志中08:52:12及08:56:42均有数据库系统自动扩大空间的记录，因此不存在表空间不足导致应用程序无法使用的问题。

数据库性能分析

对数据库在问题时段段的性能进行分析，结合监控软件中的数据，可以发现当时存在较多的TX锁等待事件，对应的SQL是对应表名：ISMS.ISMS_TICKET_STOCK (TABLE)

对应语句是：

SELECT TICKET_DEPT_CODE, TICKET_DICTIONARY_CODE, TICKET_VERSION, TICKET_START_NUMBER,

TICKET_END_NUMBER, STOCK_NUMBER, UNIT_CODE, STOCK_CREATE_DATE, TICKET_STOCK_CODE

FROM ISMS_TICKET_STOCK WHERE TICKET_STOCK_CODE=:1 FOR UPDATE

SQL执行计划没有问题，查询条件的TICKET_STOCK_CODE字段是惟一属性。

1. 数据库ASH报告中的对应的行锁等待事件

2. 数据库ASH报告中的对应的锁等待SQL语句

对应的SQL语句：select * FROM ISMS_TICKET_STOCK

WHERE TICKET_STOCK_CODE=:1 FOR UPDATE

3. SQL语句执行计划等分析

SQL信息：

SQL> set linesize 180 pagesize 1800

SQL> select sql_id,PLAN_HASH_VALUE,CHILD_number,EXECUTIONS,BUFFER_GETS/EXECUTIONS,ELAPSED_TIME/EXECUTIONS/1000 from v$sql where sql_id=’7yjz8nhdaad7k’;

SQL_ID PLAN_HASH_VALUE CHILD_NUMBER EXECUTIONS BUFFER_GETS/EXECUTIONS ELAPSED_TIME/EXECUTIONS/1000

————- ————— ———— ———- ———————- —————————-

7yjz8nhdaad7k 2932473141 0 9869 10.4900193 6640.86119

SQL> col plan_table_output for a150

SQL> set long 9000

SQL> select * from table(dbms_xplan.display_cursor(‘7yjz8nhdaad7k’,0,’advanced’));

PLAN_TABLE_OUTPUT

——————————————————————————————————————————————————

SQL_ID 7yjz8nhdaad7k, child number 0

————————————-

SELECT TICKET_DEPT_CODE, TICKET_DICTIONARY_CODE, TICKET_VERSION,

TICKET_START_NUMBER, TICKET_END_NUMBER, STOCK_NUMBER, UNIT_CODE,

STOCK_CREATE_DATE, TICKET_STOCK_CODE FROM ISMS_TICKET_STOCK

WHERE TICKET_STOCK_CODE=:1 FOR UPDATE

Plan hash value: 2932473141

—————————————————————————————————–

—————————————————————————————————–

| 0 | SELECT STATEMENT | | | | 1 (100)| |

| 1 | FOR UPDATE | | | | | |

| 2 | TABLE ACCESS BY INDEX ROWID| ISMS_TICKET_STOCK | 1 | 57 | 1 (0)| 00:00:01 |

|* 3 | INDEX UNIQUE SCAN | ISMS_TICKET_STOCK_PK | 1 | | 0 (0)| |

4. SQL历史执行信息

JBOSS中间件问题排查

1. JBOSS中间件报错日志

应用程序维护人员提供的JBOSS中间件日志报错中显示的问题为不能从JBOSS中间件连接池获取链接来连上数据库：

主要报错是：

IJ000453: Unable to get managed connection for java:jboss/datasources/ISMS:

IJ000655: No managed connections available within configured blocking timeout (30000 [ms]) 这些错误说明连接池达到最大值，没有连接可用。

相关日志：

2022-02-20 08:52:30,275 ERROR [com.th.supcom.framework.dubbo.extensions.rpc.filter.ExceptionFilter] (DubboServerHandler-172.20.2.12:20880-thread-143) Got unchecked and undeclared exception which called by 172.20.2.139. service: com.th.supcom.isms.storage.stock.service.IsmsTicketStockOutService, method: eInvoiceSaveUseOfOutDocu, exception: org.springframework.jdbc.CannotGetJdbcConnectionException: Could not get JDBC Connection; nested exception is java.sql.SQLException: javax.resource.ResourceException: IJ000453: Unable to get managed connection for java:jboss/datasources/ISMS: org.springframework.jdbc.CannotGetJdbcConnectionException: Could not get JDBC Connection; nested exception is java.sql.SQLException: javax.resource.ResourceException: IJ000453: Unable to get managed connection for java:jboss/datasources/ISMS

at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:80) [spring-jdbc-3.2.13.RELEASE.jar:3.2.13.RELEASE]

at org.mybatis.spring.SqlSessionUtils.getSqlSession(SqlSessionUtils.java:116) [mybatis-spring-1.0.1.jar:1.0.1]

at org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke(SqlSessionTemplate.java:333) [mybatis-spring-1.0.1.jar:1.0.1]

at com.sun.proxy.$Proxy32.selectList(Unknown Source)

at org.mybatis.spring.SqlSessionTemplate.selectList(SqlSessionTemplate.java:189) [mybatis-spring-1.0.1.jar:1.0.1]

at org.apache.ibatis.binding.MapperMethod.executeForList(MapperMethod.java:100) [mybatis-3.0.5.jar:3.0.5]

at org.apache.ibatis.binding.MapperMethod.execute(MapperMethod.java:70) [mybatis-3.0.5.jar:3.0.5]

at org.apache.ibatis.binding.MapperProxy.invoke(MapperProxy.java:38) [mybatis-3.0.5.jar:3.0.5]

……………………

Caused by: java.sql.SQLException: javax.resource.ResourceException: IJ000453: Unable to get managed connection for java:jboss/datasources/ISMS

at org.jboss.jca.adapters.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:147) [ironjacamar-jdbc-1.0.17.Final-redhat-1.jar:1.0.17.Final-redhat-1]

at org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(DataSourceUtils.java:111) [spring-jdbc-3.2.13.RELEASE.jar:3.2.13.RELEASE]

at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:77) [spring-jdbc-3.2.13.RELEASE.jar:3.2.13.RELEASE]

… 55 more

Caused by: javax.resource.ResourceException: IJ000453: Unable to get managed connection for java:jboss/datasources/ISMS

at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.getManagedConnection(AbstractConnectionManager.java:390)

at org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl.getManagedConnection(TxConnectionManagerImpl.java:368)

at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.allocateConnection(AbstractConnectionManager.java:464)

at org.jboss.jca.adapters.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:139) [ironjacamar-jdbc-1.0.17.Final-redhat-1.jar:1.0.17.Final-redhat-1]

… 57 more

Caused by: javax.resource.ResourceException: IJ000655: No managed connections available within configured blocking timeout (30000 [ms])

6. 检查JBOSS中间件连接池的配置信息

发现最大连接池参数设置为50，即允许最多50个。

总结与后续处理建议

通过对数据库相关日志以及性能分析，对JBOSS中间件在问题时间点的报错的分析，可以得出如下信息：

1. 微信告警的表空间问题的分析：

监控报警截图8:52分报ISMS_DATA及ISMS_IDX表空间使用率高，截图中数据文件大小为1GB

检查表空间及数据文件的属性信息，数据文件支持自动扩大(最大32GB)。

查看数据库日志-节点2中，在08:52:12及08:56:42均有自动扩大的记录

查看数据库日志-节点1，在9:17分人工将数据文件扩大到2GB。

表空间告警问题分析总结：

由于ISMS_DATA及ISMS_IDX表空间的属性支持自动扩大(最大32GB)，告警时大小为1GB。在数据库日志中08:52:12及08:56:42均有自动扩大的记录，因此表空间使用率高不会导致应用程序出现无法使用问题。而当时空间使用量增加较快，说明当时应用程序对于ISMS_DATA有较多的数据写入/修改等动作。

2. 数据库性能分析锁等待的SQL语句

监控软件中显示的问题在8:52至9:07分存在较多TX锁

对应表名：ISMS用户的ISMS_TICKET_STOCK (TABLE)

对应语句是：SELECT …… FROM ISMS_TICKET_STOCK WHERE TICKET_STOCK_CODE=:1 FOR UPDATE

此SQL执行计划及执行速度没有问题，查询条件的TICKET_STOCK_CODE字段是惟一属性。SQL执行速度较慢平均需要33秒，主要是由于应用程序未及时提交事务引起的锁不释放问题。这点从3.4章节的SQLHC报告截图中可以清楚的反映出来。同时这条SQL语句的执行频率在今天上午的问题时间段也较高，达到几千次；而从数据库的历史性能数据中未显示之前有如此高的执行频率，已经将此应用程序执行SQL语句频率高的问题点交由应用软件厂商排查。

3. JBOSS中间件的问题

应用程序维护人员提供的JBOSS中间件日志报错中显示的问题为不能从JBOSS中间件连接池获取链接来连上数据库：主要报错是：

IJ000453: Unable to get managed connection for java:jboss/datasources/ISMS:

IJ000655: No managed connections available within configured blocking timeout (30000 [ms]) 这些错误说明连接池达到最大值，没有连接可用。

检查JBOSS中间件连接池相关配置，发现max-pool-size最大连接池参数设置为50，即允许最多50个。

5. 问题发生的原因

应用程序执行问题SQL的次数异常增加(基于SQL执行频率)或程序异常(基于问题SQL不释放锁)；

比平时多的并发连接导致了JBOSS连接池用满(JBOSS连接最大50)，新的应用程序进程无法从连接池分配链接；

程序报错无法连接到数据库。

6. 下一步排查及处理方向

因此，接下来需要及时排查的问题为：

20日上午问题点时应用程序执行问题SQL的次数异常增加的原因排查。
JBOSS连接池配置max-pool-size当前为50，建议增加到200.并根据后续程序运行情况及时监测、调整。

7. 后续运维建议

及时关注数据库运行状态及告警，这一点会将第三方运维人员也加入告警群组来实现更早、更及时的处理数据库告警信息。
对应用程序、中间件的各项配置，要再进行排查并结合单位实际业务需求进行调整，特别是连接数等配置，确保够用。

3.定期进行数据库、中间件、应用程序等的巡检维护、性能优化等动作，确保各项配置能够满足不断发展的业务需求。

业务暴增导致Oracle出现性能故障分析一例

概述

告警中的表空间使用率高问题分析

1. HIS数据库节点2在问题时间段的日志信息

2. HIS数据库节点1在问题时间段的日志信息

3. 表空间相关属性信息

4. 表空间问题分析描述

数据库性能分析

1. 数据库ASH报告中的对应的行锁等待事件

2. 数据库ASH报告中的对应的锁等待SQL语句

3. SQL语句执行计划等分析

4. SQL历史执行信息

JBOSS中间件问题排查

1. JBOSS中间件报错日志

6. 检查JBOSS中间件连接池的配置信息

总结与后续处理建议

1. 微信告警的表空间问题的分析：

2. 数据库性能分析锁等待的SQL语句

3. JBOSS中间件的问题

5. 问题发生的原因

6. 下一步排查及处理方向

7. 后续运维建议

Oracle 恢复工具 Mdata 5.0.1 版本发布

近期文章

分类目录

扫码关注微信公众号:Oracle运维那些事获取定期发布的数据库运维的有趣事情!

近期活动

概述

告警中的表空间使用率高问题分析

1. HIS数据库节点2在问题时间段的日志信息

2. HIS数据库节点1在问题时间段的日志信息

3. 表空间相关属性信息

4. 表空间问题分析描述

数据库性能分析

1. 数据库ASH报告中的对应的行锁等待事件

2. 数据库ASH报告中的对应的锁等待SQL语句

3. SQL语句执行计划等分析

4. SQL历史执行信息

JBOSS中间件问题排查

1. JBOSS中间件报错日志

6. 检查JBOSS中间件连接池的配置信息

总结与后续处理建议

1. 微信告警的表空间问题的分析：

2. 数据库性能分析锁等待的SQL语句

3. JBOSS中间件的问题

5. 问题发生的原因

6. 下一步排查及处理方向

7. 后续运维建议

Oracle 恢复工具 Mdata 5.0.1 版本发布

近期文章

分类目录

扫码关注微信公众号:Oracle运维那些事 获取定期发布的数据库运维的有趣事情!

近期活动

扫码关注微信公众号:Oracle运维那些事获取定期发布的数据库运维的有趣事情!