暂无图片
暂无图片
1
暂无图片
暂无图片
暂无图片

Oracle insert逻辑读很高

原创 small_A 2020-11-24
772

某客户CPU暴增,且居高不下,通过gv$session发现一条insert造成大量的阻塞和等待,产生大量row chache lock、gc buffer busy acquire、read by other session等待。
通过row cache lock 等待的p1参数发现了大量的内存字典争用,问题点一定在这条SQL。

SQL> select parameter,gets,getmisses,MODIFICATIONS from v$rowcache where cache#=8
  2  ;

PARAMETER			       GETS  GETMISSES MODIFICATIONS
-------------------------------- ---------- ---------- -------------
dc_objects			 4094971122  267859504	   178935525
dc_object_grants		   14043535	111310		   0

查看SQL的执行信息:

SQL> @show_sql_stat.sql
Please enter the SQL_ID
gcwv8p1fhdq5y
Please enter the number of days before now for the BEGIN time
You can also enter n/24 for n hours before. Leave blank for 10 day before.
2

FLAG		   SNAP_ID    INST_ID	     PHV      EXECS	 READS	READS_PER	GETS   GETS_PER ROWS_PROCESSED	 ROWS_PER    ELAP_MS ELAP_PER_MS
--------------- ---------- ---------- ---------- ---------- ---------- ---------- ---------- ---------- -------------- ---------- ---------- -----------
16 10:00--11:00      42582	    1	       0      76177	125003 1.64095462    2516837 33.0393295 	 75312 .988644867 166019.923  2.17939697
16 11:00--12:00      42583	    1	       0      76369	116383 1.52395606    2528546 33.1095864 	 75572 .989563828 144544.053  1.89270585
16 12:00--13:00      42584	    1	       0      76806	130401 1.69779705    2562643 33.3651407 	 76087 .990638752 164757.422  2.14511135
16 13:00--14:00      42585	    1	       0      81768	138151 1.68954848    2712295 33.1706169 	 80901	.98939683 173485.561  2.12168038
16 14:00--15:00      42586	    1	       0      85599	140392 1.64011262    2843482 33.2186357 	 84579 .988083973 181246.597  2.11739152
16 15:00--16:00      42587	    1	       0      81204	135980 1.67454805    2700746 33.2587804 	 80342 .989384759 176946.616  2.17903818
16 16:00--17:00      42588	    1	       0      83322	148783 1.78563885    2777046 33.3290848 	 82466 .989726603 184043.691  2.20882469
16 17:00--18:00      42589	    1	       0      85418	147565 1.72756328    2831110 33.1441851 	 83420 .976609146 170502.746  1.99609855
==故障点==
16 18:00--19:00      42590	    2	       0      33332	190275 5.70847834  645854058 19376.3968 	 33298 .998979959  125881486  3776.59564
16 18:00--19:00      42590	    1	       0      36410	184902 5.07833013 1006132369 27633.4076 	 35895 .985855534  200037232	5494.019
16 19:00--20:00      42591	    1	       0      35535	336318 9.46441537 1697043717  47756.964 	 35253 .992064162  377126688  10612.8236
16 19:00--20:00      42591	    2	       0      50064	440842 8.80556887  686566330  13713.773 	 49821 .995146213  231919377  4632.45799
16 20:00--21:00      42592	    1	       0      27949    1172217 41.9412859 1460965664 52272.5559 	 27685 .990554224  194523801  6959.95568
16 20:00--21:00      42592	    2	       0      53479	336143 6.28551394	   0	      0 	 53114 .993174891   90139026  1685.50321
16 21:00--22:00      42593	    2	       0      29409	152829 5.19667449   12646129 430.008807 	 29265	.99510354 80984250.2  2753.72336
16 21:00--22:00      42593	    1	       0      49896	186091 3.72957752	   0	      0 	 49285 .987754529  157968653  3165.95825
16 22:00--23:00      42594	    2	       0      12981	202766 15.6202142  533337869 41086.0387 	 12756 .982666975  122982690  9474.05359
16 22:00--23:00      42594	    1	       0      36640    1696828 46.3108079  179624240  4902.4083 	 36432 .994323144  296228442  8084.83739
16 23:00--00:00      42595	    2	       0      17020	159116 9.34876616 2499583592 146861.551 	 16931 .994770858 61505400.7  3613.71332
16 23:00--00:00      42595	    1	       0      44648    1521072 34.0680882 1397284446 31295.5663 	 44311	.99245207  129625711  2903.28147
17 00:00--01:00      42596	    1	       0      22612	208794 9.23376968 1263948900 55897.2625 	 22301 .986246241  198296480  8769.52413
17 00:00--01:00      42596	    2	       0      40059	215890 5.38930078	   0	      0 	 39116 .976459722  117270283  2927.43911
17 01:00--02:00      42597	    2	       0      25935	440991 17.0037016 2278553369 87856.3088 	 25495 .983034509 13939109.9  537.463271
17 01:00--02:00      42597	    1	       0      89672	 84012 .936881078  687759735 7669.72673 	 88935 .991781158   25419993  283.477484
17 02:00--03:00      42598	    1	       0      80526	 68779	.85412165	   0	      0 	 79371 .985656806 20952841.6  260.199707
17 02:00--03:00      42598	    2	       0      26005	 39114 1.50409537	   0	      0 	 25942 .997577389 6151055.74   236.53358
17 03:00--04:00      42599	    1	       0      67907	126845 1.86792231	   0	      0 	 67310 .991208565 15298949.8  225.292676
17 03:00--04:00      42599	    2	       0      33695	103120 3.06039472 2393851734 71044.7168 	 33593 .996972845 13063994.7  387.713155
17 04:00--05:00      42600	    2	       0      18725	233086 12.4478505  436491535 23310.6294 	 18283 .976395194 25373479.5  1355.05898
17 04:00--05:00      42600	    1	       0      65799	181021 2.75112084	   0	      0 	 65339 .993009012 40465816.8  614.991365
17 05:00--06:00      42601	    2	       0      11586	240541 20.7613499	7590 .655100984 	 11518 .994130848 41397299.9  3573.04505
17 05:00--06:00      42601	    1	       0      22702	379459 16.7147828 1845086167 81274.1682 	 22586 .994890318  123387696  5435.10248
17 06:00--07:00      42602	    2	       0      24660	 30402 1.23284672     824610 33.4391727 	 24578 .996674777  59451.063  2.41082981
17 06:00--07:00      42602	    1	       0      54276	 59060 1.08814209    1802838 33.2161176 	 53579 .987158228 102683.106  1.89186945
17 07:00--08:00      42603	    1	       0      56152	 78166 1.39204303    1846615 32.8860058 	 55077 .980855535 107619.737  1.91657888
17 08:00--09:00      42604	    1	       0      60410	 95884 1.58722066    2000044 33.1078298 	 58735 .972272803 139223.025  2.30463541
17 09:00--10:00      42605	    1	       0      20664	225686 10.9216996 1596009173 77236.2163 	 20453 .989789005   49919182	2415.756
17 09:00--10:00      42605	    2	       0      12895	123104 9.54664599 1280456496 99298.6813 	 12852 .996665374 47878880.4  3712.98026
17 10:00--11:00      42606	    1	       0      56935	190870 3.35241943  944151041 16582.9637 	 56347 .989672433 79803601.1  1401.66156
17 10:00--11:00      42606	    2	       0      25459	116877 4.59079304     307005 12.0588004 	 25212 .990298126   68514250   2691.1603
17 11:00--12:00      42607	    1	       0      75261	111094 1.47611645    2502787 33.2547667 	 74431 .988971712 180128.502  2.39338438
17 12:00--13:00      42608	    1	       0      69754	120863	1.7327035    2315879 33.2006623 	 68897 .987713966  156938.37  2.24988345
17 13:00--14:00      42609	    1	       0      69707	124773 1.78996371    2311681 33.1628244 	 68819 .987260964 159559.819  2.28900712
17 14:00--15:00      42610	    1	       0      73647	125412 1.70287995    2431715 33.0185208 	 72747 .987779543 157285.696   2.1356701
17 15:00--16:00      42611	    1	       0      72567	129561 1.78539832    2413645 33.2609175 	 71789 .989278873 187017.111   2.5771647
17 16:00--17:00      42612	    1	       0      87512	163638 1.86989213    2909814 33.2504571 	 86715 .990892678 228838.456  2.61493802
17 17:00--18:00      42613	    1	       0      84382	156810 1.85833472    2807071 33.2662298 	 83693 .991834751 191470.648   2.2690935
17 18:00--19:00      42614	    1	       0      84219	176364 2.09411178    2810751 33.3743098 	 83623 .992923212 200487.836  2.38055351
17 19:00--20:00      42615	    1	       0      54877	302464 5.51167156  140953874  2568.5419 	 54519	.99347632  133354886   2430.0688
17 19:00--20:00      42615	    2	       0      31188	252938 8.11010645  415985747 13338.0065 	 31080	.99653713 79596641.4	2552.156
17 20:00--21:00      42616	    1	       0      11772	209886 17.8292559 1580145597 134229.154 	 11502	.97706422  466474416  39625.7574
17 20:00--21:00      42616	    2	       0      17498	347563 19.8630129 3580654333 204632.206 	 17312 .989370214  254167800  14525.5343
17 21:00--21:59      42617	    1	       0      14982	521349	34.798358 1371981896 91575.3502 	 14651 .977906822  554649850   37021.082
17 21:00--22:00      42617	    2	       0      30800	539276	17.508961  189274471 6145.27503 	 30513 .990681818  299654078  9729.02849
17 21:59--22:14      42618	    1	       0       1392	 48057 34.5237069  616293579  442739.64 	  1302 .935344828  166429947  119561.744
17 22:00--22:14      42618	    2	       0       2205	 82004 37.1900227	   0	      0 	  2160 .979591837 98064534.1  44473.7116
17 22:14--23:00      42619	    1	       0       6599	263876 39.9872708	   0	      0 	  6310 .956205486  380374046  57641.1647
17 22:14--23:00      42619	    2	       0      16574	351473	21.206287  422350538 25482.7162 	 16312 .984192108  191863168  11576.1535
17 23:00--00:00      42620	    1	       0      36251	388343 10.7126148	   0	      0 	 35712 .985131445  305173147  8418.33733
17 23:00--00:00      42620	    2	       0      14982	393738 26.2807369 2285262790 152533.893 	 14857 .991656655  134609365  8984.73933
18 00:00--01:00      42621	    1	       0      19041	408934 21.4764981 1758998008 92379.4973 	 18876 .991334489  221780708  11647.5347
18 00:00--01:00      42621	    2	       0       9854	329540	33.442257 1519726968 154224.373 	  9765 .990968135 72614441.3	7369.032
18 01:00--02:00      42622	    1	       0      68056	394564 5.79763724  613421951 9013.48817 	 67997 .999133067 88688145.8  1303.16424
18 01:00--02:00      42622	    2	       0	744	202795 272.573925 2122661498 2853039.65 	   728 .978494624   23596154  31715.2607
18 02:00--03:00      42623	    2	       0	916	 14849 16.2106987  550376095 600847.265 	   910 .993449782 2805087.49  3062.32259
18 02:00--03:00      42623	    1	       0     119607	122053 1.02045031  312546333 2613.11071 	118906 .994139139 23330388.6  195.058722
18 03:00--04:00      42624	    2	       0       1026	 50928 49.6374269	7484 7.29434698 	  1009 .983430799 8345535.12  8134.04982
18 03:00--04:00      42624	    1	       0     117650	 73245 .622566936	   0	      0 	116983 .994330642 33865909.7  287.853036
18 04:00--05:00      42625	    2	       0      14185	367793 25.9283045 3005147110 211853.867 	 14116 .995135707  147676423  10410.7453
18 04:00--05:00      42625	    1	       0      21548	393375 18.2557546 3766604182  174800.64 	 21377 .992064229  323745614  15024.3927
18 05:00--06:00      42626	    2	       0       8124	656939 80.8639833 1388760375 170945.393 	  7989	.98338257  259037373  31885.4472
18 05:00--06:00      42626	    1	       0       4658	549477 117.964148 1844574220 396001.335 	  4387 .941820524  512543711  110035.146
18 06:00--07:00      42627	    2	       0       1314	 64384 48.9984779  151351041 115183.441 	  1312	.99847793 806270.204  613.599851
18 06:00--07:00      42627	    1	       0      93960	 66428 .706981694  293322596 3121.78157 	 93579 .995945083 1612609.57  17.1627243
18 07:00--08:00      42628	    2	       0	278	 56861 204.535971 1135925463 4086062.82 	   262 .942446043 5614457.83  20195.8915
18 07:00--08:00      42628	    1	       0      28062	187738 6.69011475 1030093418 36707.7692 	 27979 .997042264 25981007.1  925.843031
18 08:00--09:00      42629	    1	       0      29772	 91957 3.08870751    5398670 181.333804 	 29766 .999798468 19793324.5  664.830193
18 08:00--09:00      42629	    2	       0	258	 11675	45.251938  985440327 3819536.15 	   258		1 4807218.54	18632.63
GV$			 0	    1	       0     186850	399297 2.13699224 1330015328 7118.09113 	186354 .997345464   47472687  254.068434
GV$			 0	    2	       0      29265	229685 7.84845378  441583753 15089.1424 	 29002 .991013156  116494318  3980.67034
GV$			 0	    2	       0       1928	133274 69.1255187 2272719648  1178796.5 	  1910	 .9906639   11228276  5823.79459

从17日18:00开始正常执行的SQL逻辑读暴增,接下来查看SQL文本
INSERT INTO TFA_XXXXXXXXX
(ack_flag,
…内容过多省略…
vendor_type)
VALUES
(:V1,
…内容过多省略…
:V225)

SQL> select owner,trigger_name,trigger_type,table_owner,table_name from dba_triggers where table_name=‘TFA_XXXXXXXXX’;

no rows selected

Elapsed: 00:00:00.14
简单的insert,表中没有触发器,逻辑读一度达到20万,场面有点尴尬,继续查看awr
image.png
从TOPSQL中发现了排在第二的都是delete recyclebin$,而且逻辑读很高占比大道了95%

image.png
对应的SQL文本是
delete from RecycleBin$ where bo=:1
delete from RecycleBin$ where purgeobj=:1
继续看delete的执行情况

SQL> @show_sql_stat.sql
Please enter the SQL_ID
b52m6vduutr8j
Please enter the number of days before now for the BEGIN time
You can also enter n/24 for n hours before. Leave blank for 10 day before.
7
old  15:  where sql_id='&&sql_id'
new  15:  where sql_id='b52m6vduutr8j'
old  38:	     and sht.begin_interval_time>= sysdate-&days
new  38:	     and sht.begin_interval_time>= sysdate-7
old  39:	     and sta.sql_id='&&sql_id'
new  39:	     and sta.sql_id='b52m6vduutr8j'

FLAG		   SNAP_ID    INST_ID	     PHV      EXECS	 READS	READS_PER	GETS   GETS_PER ROWS_PROCESSED	 ROWS_PER    ELAP_MS ELAP_PER_MS
--------------- ---------- ---------- ---------- ---------- ---------- ---------- ---------- ---------- -------------- ---------- ---------- -----------
16 10:00--11:00      42582	    1  716146596       1288	    13 .010093168  117222832 91011.5155 	   543 .421583851 368215.197  285.881364
16 11:00--12:00      42583	    1  716146596	399	    10 .025062657   36343798  91087.213 	   356 .892230576 110850.223  277.820108
16 11:00--12:00      42583	    2  716146596	925	   236 .255135135   84250803 91081.9492 	   357 .385945946  267302.21  288.975362
16 12:00--13:00      42584	    1  716146596       2058	 26739 12.9927114  187024696 90876.9174 	   718	.34888241 561991.244  273.076406
16 12:00--13:00      42584	    2  716146596	450	     2 .004444444   40985470 91078.8222 	    67 .148888889 125206.512  278.236693
16 13:00--14:00      42585	    1  716146596       1483	   222 .149696561  135108259 91104.6925 	   616 .415374241 412096.854  277.880549
16 13:00--14:00      42585	    2  716146596	888	     3 .003378378   80817926 91011.1779 	   258 .290540541 249587.491  281.066994
16 14:00--15:00      42586	    2  716146596       1319	     3	.00227445  119951380 90941.1524 	   234 .177407127 386486.315  293.014644
16 14:00--15:00      42586	    1  716146596       1496	    13	.00868984  136157979 91014.6918 	   609 .407085561 411022.678  274.747779
16 15:00--16:00      42587	    1  716146596       1037	   483 .465766635   94635927 91259.3317 	   593 .571841851 287550.366  277.290613
16 15:00--16:00      42587	    2  716146596       1095	     3 .002739726   99731981 91079.4347 	   235 .214611872 333513.058  304.578135
16 16:00--17:00      42588	    1  716146596	367	     3 .008174387   33428246  91085.139 	   268 .730245232 109332.528  297.908796
16 16:00--17:00      42588	    2  716146596       1764	 45603 25.8520408  159621362 90488.3005 	   515 .291950113 530314.172  300.631617
16 17:00--18:00      42589	    1  716146596       1125	    12 .010666667  102623636 91221.0098 	   444 .394666667 307828.649  273.625466
16 17:00--18:00      42589	    2  716146596       1702	    28 .016451234  154762424 90929.7438 	   376 .220916569 493462.625  289.931037
==故障点==
16 18:00--19:00      42590	    1  716146596     159825	 82967 .519111528 1310669994 8200.65693 	   393 .002458939  137380687  859.569446
16 18:00--19:00      42590	    2  716146596     112235	 80726 .719258698 1278883211 11394.6916 	  1593 .014193433 67786614.5   603.97037
16 19:00--20:00      42591	    2  716146596     186744	226641 1.21364542	   0	      0 	  2189 .011721929  129961005  695.931354
16 19:00--20:00      42591	    1  716146596     300218	198697 .661842395  659596002 2197.05681 	   501 .001668787  262591816   874.67046
16 20:00--21:00      42592	    2  716146596      88764	155246 1.74897481	   0	      0 	  1679 .018915326 40671109.1   458.19374
16 20:00--21:00      42592	    1  716146596     226914	722417 3.18365989	   0	      0 	  1483 .006535516  133327999  587.570615
16 21:00--22:00      42593	    1  716146596     197939	 71796 .362717807  336776381 1701.41499 	   626	.00316259  108631591  548.813479
16 21:00--22:00      42593	    2  716146596      95967	 54107 .563808392   57373637 597.847562 	  1946 .020277804 36321673.3  378.480866
16 22:00--23:00      42594	    1  716146596     242637    1277937 5.26686779	   0	      0 	  1082 .004459336  193196923  796.238511
16 22:00--23:00      42594	    2  716146596     107305	106327 .990885793  948535834 8839.62382 	  1537 .014323657 56548732.5  526.990657
16 23:00--00:00      42595	    2  716146596      55205	 84523 1.53107508  630946913 11429.1624 	   888	 .0160855 33240554.4  602.129416
16 23:00--00:00      42595	    1  716146596     128425	862611 6.71684641 2908108919 22644.4144 	  1646 .012816819 77960194.5  607.048429
17 00:00--01:00      42596	    1  716146596     165560	122537 .740136506	   0	      0 	  2045 .012352017  134263734  810.967224
17 00:00--01:00      42596	    2  716146596      90179	134152 1.48761907	   0	      0 	  1277 .014160725 60267130.4  668.305597
17 01:00--02:00      42597	    1  716146596      31514	 12191 .386843942 2899753683  92014.777 	  1576	.05000952 10026166.2  318.149591
17 01:00--02:00      42597	    2  716146596      16670	286613 17.1933413 1497849856 89853.0208 	   595 .035692861 7292665.14  437.472414
17 02:00--03:00      42598	    2  716146596      10659	  5955 .558682803  962820549 90329.3507 	   471	.04418801 3590051.37  336.809398
17 02:00--03:00      42598	    1  716146596      27684	 17698	.63928623	   0	      0 	  2237 .080804797 8462597.98  305.685522
17 03:00--04:00      42599	    2  716146596      19741	 47883 2.42556102	   0	      0 	   367	.01859075 7553627.96  382.636541
17 03:00--04:00      42599	    1  716146596      19277	 61523 3.19152358 1792912170  93007.842 	  1237 .064169736 7393380.11  383.533751
17 04:00--05:00      42600	    2  716146596      46440	165994 3.57437554	   0	      0 	   727 .015654608 20009276.7  430.862978
17 04:00--05:00      42600	    1  716146596      52820	 61089 1.15655055  583351143 11044.1337 	  3083 .058368042 17225931.4  326.125168
17 05:00--06:00      42601	    2  716146596      65164	121358 1.86234731 1583453249 24299.5097 	  1546 .023724756 26334019.4  404.119136
17 05:00--06:00      42601	    1  716146596     163112	167302 1.02568787	   0	      0 	  1857 .011384815 68020215.5  417.015397
17 06:00--07:00      42602	    1  716146596      91912	 47639 .518310993	   0	      0 	  1526 .016602837   38672457  420.755255
17 06:00--07:00      42602	    2  716146596      18879	 21021	1.1134594	   0	      0 	  1482 .078499921 6663590.38  352.963101
17 07:00--08:00      42603	    1  716146596       2841	 23427 8.24604013  258505658 90991.0799 	  1015 .357268567 761030.214  267.874063
17 08:00--09:00      42604	    2  716146596	292	     0		0   26594690 91077.7055 	    18 .061643836  81271.498  278.327048
17 08:00--09:00      42604	    1  716146596       1133	    10 .008826125  103056680 90959.1174 	   380 .335392763 303539.965  267.908177
17 09:00--10:00      42605	    1  716146596      45759	131882	2.8820997	   0	      0 	   777 .016980266   25488481  557.015691
17 09:00--10:00      42605	    2  716146596      49286	 70132 1.42295987  111191557  2256.0475 	   362 .007344885 33670968.4  683.175109
17 10:00--11:00      42606	    2  716146596      72029	 50597 .702453179 2115731292 29373.3259 	   537	.00745533 47465507.9  658.977743
17 10:00--11:00      42606	    1  716146596      76768	 54733	.71296634 2570062177 33478.3006 	  1965 .025596603 40807120.1  531.564195
17 11:00--12:00      42607	    1  716146596	962	 17329 18.0135135   87636874 91098.6216 	   452	.46985447  265400.52  275.884116
17 12:00--13:00      42608	    1  716146596	264	     4 .015151515   24045928 91083.0606 	   137 .518939394   74569.85  282.461553
17 13:00--14:00      42609	    1  716146596	304	     9 .029605263   27689683 91084.4836 	   194 .638157895  87070.018  286.414533
17 14:00--15:00      42610	    1  716146596	361	     7 .019390582   32880941 91082.9391 	   169 .468144044  98089.056  271.714837
17 16:00--17:00      42612	    2  716146596       1907	 24063 12.6182486  173641632 91054.8673 	   421	 .2207656 570762.693  299.298738
17 16:00--17:00      42612	    1  716146596       1442	    12 .008321775  131445218 91154.7975 	   527 .365464632 414307.063  287.314191
17 17:00--18:00      42613	    1  716146596	743	     9 .012113055   67765485 91205.2288 	   354 .476446837 208900.793  281.158537
17 17:00--18:00      42613	    2  716146596       1664	    29 .017427885  151821069 91238.6232 	   309 .185697115 501979.109  301.670138
17 18:00--19:00      42614	    2  716146596	443	     5 .011286682   40349549 91082.5034 	   213 .480812641 122754.071  277.097226
17 19:00--20:00      42615	    2  716146596      71196	133855 1.88009158 2062210340 28965.2556 	   743	.01043598 42745375.7  600.390129
17 19:00--20:00      42615	    1  716146596     115267	124662 1.08150642 1546274378 13414.7187 	   212 .001839208 89174487.1  773.634146
17 20:00--21:00      42616	    1  716146596     320847	136716 .426109641 2447288385 7627.58693 	     1 3.1168E-06  321900744  1003.28426
17 20:00--21:00      42616	    2  716146596     240198	210179 .875023939    1210715 5.04048743 	  1920 .007993405  135898435  565.776712
17 21:00--21:59      42617	    1  716146596     308486	361579	1.1721083	   0	      0 	    59 .000191257  382531521  1240.02879
17 21:00--22:00      42617	    2  716146596     219392	345481 1.57472014	   0	      0 	  1814 .008268305  168008972  765.793522
17 21:59--22:14      42618	    1  716146596      77813	 31451 .404186961 2570474763 33034.0016 	    21 .000269878  114401465  1470.21018
17 22:00--22:14      42618	    2  716146596      53058	 59564 1.12262053  493132476 9294.21531 	   492 .009272871 48738424.9  918.587677
17 22:14--23:00      42619	    2  716146596     144273	235759 1.63411726	   0	      0 	  1344 .009315672 96418053.8  668.302827
17 22:14--23:00      42619	    1  716146596     221411	181288 .818784975	   0	      0 	   142 .000641341  264532026  1194.75557
17 23:00--00:00      42620	    2  716146596     120079	246643 2.05400611 2204032162 18354.8511 	  2190 .018237993 67316233.9  560.599554
17 23:00--00:00      42620	    1  716146596     247058	234371 .948647686  342824933 1387.62935 	   440 .001780958  205261646  830.823719
18 00:00--01:00      42621	    1  716146596     250600	273046 1.08956903  885160327 3532.16411 	  1017	.00405826  148156640   591.20766
18 00:00--01:00      42621	    2  716146596      78057	223765 2.86668716	   0	      0 	  2187 .028017987 36759602.8  470.932816
18 01:00--02:00      42622	    2  716146596      31214	 88950 2.84968283	   0	      0 	   989 .031684501 11767602.6  376.997583
18 01:00--02:00      42622	    1  716146596     117582	146094 1.24248609	   0	      0 	  2427 .020640914 44953800.7  382.318729
18 02:00--03:00      42623	    2  716146596       6091	 38195	6.2707273  557931354 91599.3029 	   739 .121326547 1936443.18  317.918762
18 02:00--03:00      42623	    1  716146596      31710	 16966 .535036266 2892901491  91229.943 	  1634 .051529486 11129636.2  350.981903
18 03:00--04:00      42624	    2  716146596      11228	 34462 3.06929106 1025445923 91329.3483 	   986 .087816174 3902760.15  347.591749
18 03:00--04:00      42624	    1  716146596      44298	 21892 .494198384 3980316228 89853.1814 	   674 .015215134 21607655.3  487.779478
18 04:00--05:00      42625	    1  716146596     318089	280954 .883255944	   0	      0 	   302	.00094942  228973892   719.84222
18 04:00--05:00      42625	    2  716146596     134051	231918 1.73007288	   0	      0 	  2149 .016031212 68587750.3  511.654149
18 05:00--06:00      42626	    1  716146596     294244	392129 1.33266609  293475419 997.387947 	   206 .000700099  360397027  1224.82371
18 05:00--06:00      42626	    2  716146596     197673	457128 2.31254648  332059089 1679.84039 	  2249 .011377376  146516697  741.207432
18 06:00--07:00      42627	    2  716146596	976	  2604 2.66803279   89465742 91665.7193 	    62	.06352459 339355.755  347.700569
18 06:00--07:00      42627	    1  716146596      66407	127358 1.91783999 1613159420 24292.0087 	  1131 .017031337 53426789.1  804.535502
18 07:00--08:00      42628	    2  716146596      13510	 35759 2.64685418 1232079281 91197.5782 	  1201 .088897113 4512922.82   334.04314
18 07:00--08:00      42628	    1  716146596      40087	 66357 1.65532467	   0	      0 	  2639 .065831816 14149097.8  352.959756
18 08:00--09:00      42629	    2  716146596       7240	  5313 .733839779  659737307 91123.9374 	   554 .076519337 2375372.36  328.090105
18 08:00--09:00      42629	    1  716146596      33641	 29573 .879076127	   0	      0 	  1967 .058470319 10991121.7  326.718043
18 09:00--10:00      42630	    1  716146596       2996	    44 .014686248  272788169 91050.7907 	   470 .156875834 821568.234  274.221707

好像接近问题本质了,在同样时间点delete from recyclebin$ 语句的执行次数和逻辑读暴增,逻辑读达9w,那么回收站怎么就有那么高逻辑读呢,从执行计划发现,RECYCLEBIN$使用全表扫描,且回收站达到700多MB


Plan hash value: 716146596

------------------------------------------------------------------------------------------
| Id  | Operation                  | Name        | Rows  | Bytes | Cost (%CPU)| Time     |
------------------------------------------------------------------------------------------
|   0 | DELETE STATEMENT           |             |       |       |   611 (100)|          |
|   1 |  DELETE                    | RECYCLEBIN$ |       |       |            |          |
|   2 |   TABLE ACCESS STORAGE FULL| RECYCLEBIN$ |     1 |    19 |   611   (1)| 00:00:08 |
------------------------------------------------------------------------------------------



SQL> 
SQL> select owner,segment_name,segment_type,sum(bytes)/1024/1024 MB from dba_segments where owner='SYS' and segment_name ='RECYCLEBIN$'  group by owner,segment_name,segment_type;

OWNER			       SEGMENT_NAME									 SEGMENT_TYPE		    MB
------------------------------ --------------------------------------------------------------------------------- ------------------ ----------
SYS			       RECYCLEBIN$									 TABLE			   716

那么一直delete recyclebin$一定是表空间不够用了,继续查看表所在的表空间,


SQL>select table_owner,table_name,partition_name,tablespace_name ,to_char(last_analyzed,'yyyy-mm-dd hh24:mi:ss') from dba_tab_partitions where table_name ='TFA_XXXXXXXXX'   and table_owner='XXUSER'
  2  ;

TABLE_OWNER		       TABLE_NAME		      PARTITION_NAME		     TABLESPACE_NAME		    TO_CHAR(LAST_ANALYZ
------------------------------ ------------------------------ ------------------------------ ------------------------------ -------------------
XXUSER			       TFA_XXXXXXXXX		      PART20200815		     TBS_FM_XXXXXXXS		    2020-11-08 22:33:21
XXUSER			       TFA_XXXXXXXXX		      PART20200816		     TBS_FM_XXXXXXXS		    2020-11-08 22:35:02
XXUSER			       TFA_XXXXXXXXX		      PART20200817		     TBS_FM_XXXXXXXS		    2020-11-08 22:36:19
XXUSER			       TFA_XXXXXXXXX		      PART20200818		     TBS_FM_XXXXXXXS		    2020-11-08 22:37:35
XXUSER			       TFA_XXXXXXXXX		      PART20200819		     TBS_FM_XXXXXXXS		    2020-11-08 22:38:49
XXUSER			       TFA_XXXXXXXXX		      PART20200820		     TBS_FM_XXXXXXXS		    2020-11-08 22:41:10
XXUSER			       TFA_XXXXXXXXX		      PART20200821		     TBS_FM_XXXXXXXS		    2020-11-08 22:43:43
XXUSER			       TFA_XXXXXXXXX		      PART20200822		     TBS_FM_XXXXXXXS		    2020-11-08 22:46:11
XXUSER			       TFA_XXXXXXXXX		      PART20200823		     TBS_FM_XXXXXXXS		    2020-11-08 22:48:38


select distinct  table_owner,table_name,tablespace_name  from dba_tab_partitions where table_name ='TFA_XXXXXXXXX'   and table_owner='XXUSER'

SQL>select distinct  table_owner,table_name,tablespace_name  from dba_tab_partitions where table_name ='TFA_XXXXXXXXX'   and table_owner='XXUSER';

TABLE_OWNER		       TABLE_NAME		      TABLESPACE_NAME
------------------------------ ------------------------------ ------------------------------
XXUSER			       TFA_XXXXXXXXX		      TBS_FM_XXXXXXXS

SQL> select tablespace_name ,segment_space_management from dba_tablespaces    where  tablespace_name='TBS_FM_XXXXXXXS';

TABLESPACE_NAME 	       SEGMEN
------------------------------ ------
TBS_FM_XXXXXXXS 	       AUTO
--表空间使用率,可用96GB
TBS_FM_XXXXXXXS 		  1884160    1787182	  96978 95

问题已经逐渐明朗了,数据库drop了大量表没有释放空间,insert的时候分配segment,没有足够的空间导致触发delete recyclebin操作,而delete recyclebin又是全表SQL秒,执行效率很低,导致insert逻辑读很高。仔细推敲仍需证明: 即使delete效率很差,也不至于insert逻辑读达到20万,回收站是影响原因,但一定不是主要原因。
我们从mos中可以看到那么一篇文章Bug 19791273 - Poor UPDATE SQL performance due to space search cache for updates on ASSM segment (Doc ID 19791273.8)
其中修复的bug 13641076关于bug的描述是:
INSERT operations have a high amount of buffer gets when there is a concurrent uncommitted large DELETE for ASSM segments.
Note:
It is expected in ASSM that a first attempt to find space in a segment may need to visit many blocks in the case of an uncommitted concurrent delete, but subsequent executions of the cursor should use a “reject” list implemented in bug 4188324 and so skip reading of blocks already rejected. Prior to this fix the “rejection” list is cursor based, and so if the DML cursor is closed and a new cursor used the reject list has to be rebuilt.
This fix changes the rejection list to be session based rather than cursor based.

在ASSM段管理中当同时发生大量的uncommited的delete操作时,那么insert操作就会有一个很高的buffer获取。
在发生大量的UNcommited的delete操作时,在ASSM段管理中需要尝试寻找空间,这可能会扫描更多的block,在bug 4188324中针对这个操作修复了一个"reject" list通过cursor保存,在后续的insert时会跳过扫描block这个操作,然而dml操作的游标是在执行完之后就关闭了,在新的造作中会重建新的游标,使得insert在频繁重复的查找block导致很高的逻辑读

针对mos这边文章所叙述的环境跟故障环境极其相似,delete from recyclebin就是大量的delete,查看数据库补丁 [oracle@xxxxx ~] opatch lsinventory -bugs_fixed |grep 13641076
[oracle@xxxxx ~]$
数据库没有相关补丁也证实了此故障触发了bug

解决方案:
1.针对此bug安装修复patch
2.清空回收站,从业务侧推荐临时表使用temporary table 或删除表加purge。
3.可在recyclebin$表purgeobj和bo两个列上创建索引。

最后修改时间:2020-11-24 20:06:50
「喜欢这篇文章,您的关注和赞赏是给作者最好的鼓励」
关注作者
【版权声明】本文为墨天轮用户原创内容,转载时必须标注文章的来源(墨天轮),文章链接,文章作者等基本信息,否则作者和墨天轮有权追究责任。如果您发现墨天轮中有涉嫌抄袭或者侵权的内容,欢迎发送邮件至:contact@modb.pro进行举报,并提供相关证据,一经查实,墨天轮将立刻删除相关内容。

评论