核心生产上一个严重且有趣的Bug(一)

上周,公司核心生产数据库凌晨时出现异常,一条update语句响应缓慢,严重影响了核心数据库事务交易,详情如下:

数据库架构为3节点(主库)+3节点(备库),11.2.0.4 / Linux x86-64,故障期间短为00:31-00:32,TPS:10-20左右

SS-1

SS-2

AWR前台等待事件上来看,除去resmgr:cpu quantum event平均等待216ms外,并无其他较为突出的性能问题,故障期间段ASH信息如下:SS-3

什么是resmgr:cpu quantum event?

SS-4

从该等待事件释义中可以得到信息,可得知Oracle资源管理器在调度CPU时发生的等待。说明此时刻CPU资源产生了严重的瓶颈,资源管理器该等待事件存在的意义是当resource manager控制CPU调度时,此时数据库系统活动会话对CPU资源消耗需求较大,但是Oracle要保证对应的Group得到相应的CPU资源,对使用CPU进程进行队列排队机制,进入队列wait等待再次获得CPU资源,队列中wait阶段时,产生resmgr:cpu quantum event

SS-5

当前数据库中为DEFAULT_MAINTENANCE_PLAN,故障时为周日,默认的时间窗口为:6:00 AM -02:00 AM 可以看到故障当时是与默认维护窗口相撞,很有可能,当时数据库只用到70%的 CPU资源,另外的资源需要给数据库窗口内的AUTOTASK与诊断工作使用。

但是,这并不是CPU异常的案例,CPU为故障的“果“,而非故障的“因”。

我们来观察一下故障时影响严重的UPDATE:

SS-6

这样简单的一条UPDATE,主键索引单块读的索引,用到了多少逻辑读?

SS-7

经过与应用确认,该update涉及的表,在00:30时与夜维叠加(删除该表历史数据)的情况,并且该delete并没有分批commit,但是这一条很简单的update却在TPS如此之小的系统中产生如此之高的逻辑读是不正常的,并且每日此时间点均如此,只是故障期间将此问题继续放大,从而影响了正常的应用事务:

SNAP_TIME    EXECU Buffer_get
------------ ------- -----------
2019091401 14725 390573866
2019091402 14726 660469
2019091403 8766 393670
2019091404 7676 345199
2019091405 8688 391034
2019091406 17637 792635
2019091407 30644 1499087
2019091408 27351 1326270
2019091409 23691 1157426
2019091410 29876 1468700
2019091411 32515 1011648
2019091412 33652 859803
2019091413 28575 730339
2019091414 29128 744802
2019091415 31847 814279
2019091416 27135 693792
2019091417 27567 705079
2019091418 25186 643862
2019091419 20563 526618
2019091420 17198 440889
2019091421 18520 474756
2019091422 23209 594416
2019091423 23968 613407
2019091500 20405 522333
2019091501 16863 763270508
2019091502 14423 648659
2019091503 9676 432238
2019091504 7607 341652
2019091505 8217 369355
2019091506 18917 843610
2019091507 35003 1556423
2019091508 30318 1445647
2019091509 25032 1219554
2019091510 31649 1298660
2019091511 37660 961354
2019091512 35192 899030
2019091513 33226 848933
2019091514 32219 822987
2019091515 35130 897643
2019091516 32409 828174
2019091517 31554 806062
2019091518 28859 738032
2019091519 23534 602094
2019091520 20579 527210
2019091521 18130 464671
2019091522 21368 547559
2019091523 22141 566667
2019091600 18456 473003
2019091601 14791 860699527
2019091602 14127 634711
2019091603 9372 420768
2019091604 8359 376321
2019091605 9438 425725
2019091606 20918 935854
2019091607 35694 1587935
2019091608 31569 1405709
2019091609 26052 1163785
2019091610 31770 1053068
2019091611 37821 965930
2019091612 36537 933986
2019091613 33087 845259
2019091614 31984 818287
2019091615 34778 888391
2019091616 31222 798082
2019091617 29554 756789
2019091618 27729 711844
2019091619 21492 551616
2019091620 17960 460978
2019091621 18547 475984
2019091622 22221 569415
2019091623 22477 575776
2019091700 18267 468188
2019091701 14602 1107293169
2019091702 14400 643965
2019091703 8704 391381
2019091704 7394 332559
2019091705 8611 388446
2019091706 19360 863247
2019091707 33595 1491362
2019091708 29292 1433094
2019091709 25010 1227242
2019091710 31320 1192625
2019091711 35864 916846
2019091712 34364 878031
2019091713 31227 798315
2019091714 29635 757346
2019091715 33346 851736
2019091716 29025 742234
2019091717 29252 747693
2019091718 26451 676264
2019091719 21644 554008
2019091720 18808 482085
2019091721 17493 448326
2019091722 271 6892
2019091723 22551 576743
2019091800 17500 449180
2019091801 14255 1084180569
2019091802 12789 575082
2019091803 8047 361644
2019091804 7830 352450
2019091805 8008 360110
2019091806 20397 910098
2019091807 35334 1572701
2019091808 30561 1362887
2019091809 24372 1091458
2019091810 32101 1338173
2019091811 35280 901847
2019091812 33197 849297
2019091813 32774 837996
2019091814 30861 788643
2019091815 32724 836328
2019091816 29544 754997
2019091817 29509 754502
2019091818 27233 695912
2019091819 22212 568221
2019091820 19755 506275
2019091821 19827 507710
2019091822 22747 582089
2019091823 24232 620192
2019091900 19392 497257
2019091901 16132 427594241
2019091902 13863 623091
2019091903 8112 366287
2019091904 7428 334226
2019091905 9011 405769
2019091906 19265 861495
2019091907 34533 1538314
2019091908 28125 1255957
2019091909 25178 1127288
2019091910 30769 1269378
2019091911 36759 940239
2019091912 33514 856818
2019091913 32397 828054
2019091914 31496 805195
2019091915 35976 922400
2019091916 31111 796749
2019091917 35285 903052
2019091918 28062 718088
2019091919 23037 590086
2019091920 20948 536346
2019091921 19846 509565
2019091922 23814 609102
2019091923 24562 628947
2019092000 19024 488088
2019092001 17414 926375276
2019092002 13903 658333
2019092003 8887 409751
2019092004 8117 365932
2019092005 9954 485363
2019092006 21293 990892
2019092007 34419 1541359
2019092008 31646 1056393
2019092009 27183 696162
2019092010 32263 825233
2019092011 39804 1017362
2019092012 37266 952537
2019092013 32575 832835
2019092014 32790 838854
2019092015 36864 942246
2019092016 35047 894345
2019092017 33293 851163
2019092018 29657 758549
2019092019 26323 672353
2019092020 22570 578614
2019092021 21435 548358
2019092022 25834 661508
2019092023 27143 694352
2019092100 22010 564626
2019092101 17767 874999996
2019092102 16051 750639
2019092103 10318 520331
2019092104 7732 405285
2019092105 9462 459200
2019092106 19856 1145733
2019092107 34724 1694555
2019092108 31444 1208805
2019092109 25973 665746
2019092110 32051 819722
2019092111 35725 912186
2019092112 36784 940216
2019092113 35171 899079
2019092114 32023 819183
2019092115 34471 881078
2019092116 31343 801247
2019092117 30794 787709
2019092118 28392 725468
2019092119 23985 612708
2019092120 19753 505200
2019092121 21755 556906
2019092122 23476 601464
2019092123 26443 676863
2019092200 21381 547651
2019092201 10332 2040783005
2019092203 5394 242068
2019092204 8831 424611
2019092205 9304 420205
2019092206 19472 947052
2019092207 34958 1634844
2019092208 30321 1702505
2019092209 24801 1121702
2019092210 31471 810042

SS-9

DBA_HIST_SQLSTAT视图中计算得出,此条update的平均逻辑读,结果明显不符合常理,虽然delete与update相同表存在叠加,一致读数量却异常的惊人,每日0点-1点与夜维叠加运行均造成超高逻辑读,存在一定的规律,只不过22日更为严重,使得问题爆发

经过我们与各路专家的分析得出,应该命中此BUG:

SS-10

SS-11

Space Serach Cache功能为:当请求一个Free block时,Oracle会从段头中返回给请求一个block(此block应当为空闲状态,不应该存在任何事务),但是当请求尝试去block insert或update数据时,发现该block中的没有任何free空间,不能进行正常事务请求,将该block丢弃至Space Serach Cache(PGA中),此活动会话连接生命周期内,不会重用Cache中的block。但是经过我们与业界各路专家讨论后,猜测当数据库存在delete后,Oracle认为此目前CACHE已经不再“科学”(很多块已经被删除了,应当存在大量FREE空间了),便会重建该CACHE,导致体现在updaet的逻辑读或UNDO 一致读激增(同delete涉及的表与块)。

暂时解决方法:

因涉及国庆假期临近,为保证系统的稳定运行,暂时暂停了夜维程序并且为夜维停止后造成的数据挤压扩充了一定量的存储。随后,国庆假期后,根据MOS建议:设置10019 event禁用space serach cache,重启应用服务器或数据库实例(清空PGA操作),观察update逻辑读是否所改善,本篇文章持续更新,会继续更新测试结果与此CASE的最终解决方案。