背景

某项目OIM修改密码异常的慢,修改一次密码需要耗费15分钟时间,该功能基本已不可用,通过curl工具调用OIM rest api进行修改密码也需要十几分钟的时间

curl -X PUT \
http://10.10.10.10:14000/iam/governance/selfservice/api/v1/users/61729/password \
-H 'accept-language: zh-CN,en-US;q=0.8,zh;q=0.7,zh-TW;q=0.5,zh-HK;q=0.3,en;q=0.2' \
-H 'authorization: Basic xxxxxxxxxxxxxxxxxxxxx' \
-H 'cache-control: no-cache' \
-H 'content-type: application/json' \
-H 'postman-token: e86578e5-6c12-6bd0-3304-7588cae0f60a' \
-H 'x-requested-by: xx' \
-d '{
"oldPassword": "welcome@2020",
"newPassword": "welcome@2020238",
"confirmPassword": "welcome@2020238"
}'

排查

获取源码

后台并无报错,也没相关有价值的日志,因此考虑从源码入手,api源码位于oim这个应用中,你可以登录console查看ear包路径

我们也可以在路径中找到rest api的路径

跟踪

拿到源码后,我们可以在源码中找到修改密码的代码位置:

我们需要借助arthas进行线上调试,对于性能问题的调试,可以用trace命令,trace命令跟踪每个方法的调用时长,比如我们用trace命令跟踪以上方法

[arthas@203336]$ trace oracle.iam.rest.client.services.UserOperationsImpl changeUserPassword
Press Q or Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:2) cost in 496 ms.
<code>---ts=2020-05-23 01:32:52;thread_name=[ACTIVE] ExecuteThread: '13' for queue: 'weblogic.kernel.Default (self-tuning)';id=7f;is_daemon=true;priority=5;TCCL=weblogic.utils.classloaders.ChangeAwareClassLoader@4ed99611
    </code>---[952588.584214ms] oracle.iam.rest.client.services.UserOperationsImpl:changeUserPassword()
        +---[0.030523ms] oracle.iam.rest.client.services.UserOperationsImpl:logMethodEntry() #253
        +---[0.08976ms] oracle.iam.rest.client.services.UserOperationsImpl:getStartTime() #255
        +---[0.005781ms] oracle.iam.rest.client.services.UserOperationsImpl:getOIMClient() #257
        +---[0.65122ms] oracle.iam.platform.OIMClient:getService() #258
        +---[13.405695ms] oracle.iam.passwordmgmt.api.PasswordMgmtService:validatePasswordAgainstPolicy() #259
        +---[0.01658ms] oracle.iam.passwordmgmt.vo.ValidationResult:isPasswordValid() #260
        +---[0.002193ms] oracle.iam.rest.commons.context.OIMContext:getClientContext() #262
        +---[0.700731ms] oracle.iam.rest.client.service.locators.OIMServiceFactory:getService() #262
        +---[0.002386ms] oracle.iam.rest.commons.context.OIMContext:getClientContext() #267
        +---[0.009664ms] oracle.iam.rest.commons.context.OIMClientContext:getUserLogin() #267
        +---[2.272435ms] oracle.iam.identity.usermgmt.api.UserManager:getDetails() #267
        +---[0.032742ms] oracle.iam.identity.usermgmt.vo.User:getAttribute() #269
        +---[952570.756531ms] oracle.iam.identity.usermgmt.api.UserManager:changePassword() #276
        +---[0.010663ms] oracle.iam.rest.client.services.UserOperationsImpl:captureOIMTime() #289
        ---[0.006981ms] oracle.iam.rest.client.services.UserOperationsImpl:logMethodExit() #291

可以发现在调用oracle.iam.identity.usermgmt.api.UserManager:changePassword()方法时耗时952570.756531ms,明显就是这个方法有问题,进而进一步跟踪。

你需要极大的耐心来一步步跟踪调试,因为oracle产品的栈是非常深的,一层套一层,往往可以套几十层上百层都找不到最终执行的位置,而且如果遇到第三方包你需要从oim服务器下载,具体方法是,通过arthas sc命令可以查看包路径,根据该路径把包下载下来,因为idea看代码比较方便,跟踪代码也非常方便,所以我比较推荐将jar包安装到本地仓库,在idea中引用就很容易跟踪代码。

  • 安装本地仓库示例
mvn install:install-file -Dfile="/Users/asan/Downloads/OIMServer.jar" -DgroupId=com.oracle -DartifactId=oimserver -Dversion=1.0 -Dpackaging=jar
  • 引用示例
<dependency>
    <groupId>com.oracle</groupId>
    <artifactId>rest-oig-service</artifactId>
    <version>1.0</version>
</dependency>
<dependency>
    <groupId>com.oracle</groupId>
    <artifactId>oimserver</artifactId>
    <version>1.0</version>
</dependency>
<dependency>
    <groupId>com.oracle</groupId>
    <artifactId>iam-platform-kernel</artifactId>
    <version>1.0</version>
</dependency>
<dependency>
    <groupId>com.oracle</groupId>
    <artifactId>xlDataObjects</artifactId>
    <version>1.0</version>
</dependency>
<dependency>
    <groupId>com.oracle</groupId>
    <artifactId>xlVO</artifactId>
    <version>1.0</version>
</dependency>

以上就是调试过程中用到的jar包。

调试困难的地方在于,因为调用一次就要耗费15分钟时间,也就是每调试一次就得等15分钟,效率极低,花了一天时间还是没有跟踪到最底层,但可以确认是sql引起的,却找不到是哪个sql引起,最后在包中发现一个数据库工具类com.thortech.xl.dataobj.PreparedStatementUtil,该类负责最终sql的执行,只要监控这个类的调用执行时间就能得到所有sql的执行时间,通过以下arthas命令就可以实现

watch com.thortech.xl.dataobj.PreparedStatementUtil execute "{target.m_statement,target.m_dataSetData.ioData.length}" -n 10000000

最后一个数字是代表监控的次数,如果不指定默认是100,一次修改密码数据库操作会有很多次,因此这里需要指定一个很大的数保证不退出,执行后才发现oim一次修改密码的操作涉及到上千个sql的执行(震惊),在屏幕上查看已经非常不方便,并且屏幕的显示有限,因此需要保存到文件中进行排查,默认情况下,artahs文件保存功能是关闭的,如果需要开启,需要执行以下命令

$ options save-result true
 NAME         BEFORE-VALUE  AFTER-VALUE
----------------------------------------
 save-result  false         true
Affect(row-cnt:1) cost in 3 ms.

结果会异步保存在:{user.home}/logs/arthas-cache/result.log

在日志中找到了这个sql

2020-05-23 19:16:17.936
ts=2020-05-23 19:16:17; [cost=91299.284623ms] result=@ArrayList[
    @String[select sta.sta_bucket, count(sta.sta_bucket) as bkt from osi osi, sch sch, mil mil, sta sta where osi.sch_key=sch.sch_key and osi.mil_key=mil.mil_key and sch.sch_status=sta.sta_status and mil.mil_required_complete=? and osi.orc_key=? group by sta.sta_bucket],
    @Integer[3],
]

执行时间是91299ms差不多90s,而且通过搜索发现有上百处,基本确认是该sql导致,在数据中执行,确实非常耗时。

查看执行计划

看到确实有个耗时特别严重的连接,sql涉及到四张表,各表的数据量如下

  • osi(484389)
  • sch(484389)
  • mil(412)
  • sta(12)

虽然osi和sch的数据量达到48w左右,但依然不是很大的量,另外两张表基本可以不用考虑,48w的数据量第一反应就是不大可能会有性能问题,抛开另外两张表,执行以下sql

select count(1) from osi a,sch b where a.sch_key=b.sch_key and a.orc_key=98686

速度非常快

执行以下sql

select count(1) from osi a,sch b,sta c where a.sch_key=b.sch_key and a.orc_key=98686 and b.sch_status=c.sch_status

速度又回到90s级别,差别就是加了一个只有12条数据的表,耗时就天差地别。检查了所有索引,没有配置不当的地方,数据类型也都一样不存在转换的问题。我们创建了一张和sta一摸一样的表

create table sta_bak as select * from sta

测试结果依然一样,我们创建了一张跟sch一样的表

create table sch_bak as select * from sch

速度立马上去了,到这里,你应该知道,这个不是应用的问题,应该属于oracle调优范畴内的问题,起初怀疑是高水位问题,但通过查询发现水位不是很高,确实也想不出其他可能性,目前情况是

两张48w的数据连接一张12数据量的表性能就急剧下降,对表进行重建又恢复正常。

也是运气好,在查询user_tables表的时候,想看下其他表的数据量,发现num_rows字段是空的,oracle会定期收集统计表的一些信息,比如行数,大小等信息存在表user_tables中,这张表也是oracle计算执行计划重要的参考数据,理论上安装数据库的时候会自动开启,但是看看了客户数据库,这张表统计信息都是空的,说明表分析统计功能并未开启,这也解释了为何执行计划耗时那么长,明明数据量并不是很大,联系dba,开启后恢复正常,并且系统整体性能都有所提升。开启步骤如下:

  • 检查是否开启了auto optimizer stats job
SQL> select operation_name, status from dba_autotask_operation where client_name like '%stats%';
OPERATION_NAME                                                   STATUS
---------------------------------------------------------------- --------
auto optimizer stats job                                         DISABLED
  • 如果没有开启,执行存储过程开启
BEGIN
DBMS_SCHEDULER.ENABLE(
name => '"SYS"."SATURDAY_WINDOW"');
END;
/
  • 收集统计信息
EXEC DBMS_STATS.gather_database_stats(estimate_percent=>100,cascade=>TRUE, degree=>48);

总结

  • 经验很重要,如果你知道48w的数据肯定不会造成性能问题,你就不会往sql优化方向排查。
  • 专业水平不够,需要运气来补。
Trackback

no comment untill now

Add your comment now