Coskan’s Approach to Oracle

January 24, 2011

Analysing Temp usage on 11GR2 when Temp space is not released

Filed under: Bugs — coskan @ 2:47 pm

We had an interesting issue on our 3 node cluster about the temp usage. One night one of the critical batch operation which never used high temp suddenly hit “ORA-01652: unable to extend temp segment by string in tablespace string tips”. Once we check the system we saw some “inactive sessions” were using very high amount of temp like below which were allocating most of the temp space causing batch operations fail even with very small temp request.

—The picture of temp usage right after the issue

PROD1> @temp_usageg

#####################################################################
#######################GLOBAL TEMP USAGE#############################
#####################################################################

   INST_ID TABLESPACE         MB_TOTAL     MB_USED    MB_FREE
---------- --------------- ----------- ----------- ----------
         3 TEMP              22528.000       7.000      22521
         2 TEMP              22528.000      56.000      22472
         1 TEMP              22528.000   19102.000       3426

#####################################################################
#######################GLOBAL TEMP USERS-over 10MB ##################
#####################################################################

   INST_ID SID_SERIAL USERNAME     OSUSER     SPID   SERVICE            MB_USED TABLESPACE
---------- ---------- ------------ ---------- ------ -------------------------- ---------------
         1 620,4322   USER_1      osusr1   21712  WEB_USER_SERVICE         16.000 TEMP
         1 41,35454   USER_1      osusr1   20334  WEB_USER_SERVICE         19.000 TEMP
         1 529,21034  USER_1      osusr1   5776   WEB_USER_SERVICE         20.000 TEMP
         1 538,54672  USER_1      osusr1   30383  WEB_USER_SERVICE         27.000 TEMP
         1 1258,36144 USER_1      osusr1   5745   WEB_USER_SERVICE         31.000 TEMP
         1 1351,56539 USER_2       root      29910  WEB_USER_SERVICE         67.000 TEMP
         1 1113,59480 USER_2       root      11397  WEB_USER_SERVICE         78.000 TEMP
         1 30,4102    USER_2       root      15244  WEB_USER_SERVICE         78.000 TEMP
         1 892,14168  USER_2       root      19971  WEB_USER_SERVICE         79.000 TEMP
         1 699,56288  USER_1      osusr1   11240  WEB_USER_SERVICE        668.000 TEMP
         1 1501,55691 USER_1      osusr1   11236  WEB_USER_SERVICE        685.000 TEMP
         1 1396,7154  USER_1      osusr1   12526  WEB_USER_SERVICE        808.000 TEMP
         1 233,46662  USER_1      osusr1   11334  WEB_USER_SERVICE        810.000 TEMP
         1 1004,14127 USER_1      osusr1   24287  WEB_USER_SERVICE        832.000 TEMP
         1 1196,820   USER_1      osusr1   12530  WEB_USER_SERVICE        868.000 TEMP
         1 1121,1990  USER_1      osusr1   24290  WEB_USER_SERVICE        893.000 TEMP
         1 297,2940   USER_1      osusr1   8910   WEB_USER_SERVICE        903.000 TEMP
         1 294,39051  USER_1      osusr1   15116  WEB_USER_SERVICE        924.000 TEMP
         1 37,46739   USER_1      osusr1   15118  WEB_USER_SERVICE        932.000 TEMP
         1 414,31439  USER_1      osusr1   8877   WEB_USER_SERVICE        935.000 TEMP
         1 913,40598  USER_1      osusr1   9710   WEB_USER_SERVICE       1064.000 TEMP
         1 710,44883  USER_1      osusr1   9703   WEB_USER_SERVICE       1115.000 TEMP
         1 147,16701  USER_1      osusr1   9295   WEB_USER_SERVICE       1137.000 TEMP
         1 1446,25613 USER_1      osusr1   12372  WEB_USER_SERVICE       1139.000 TEMP
         1 721,5152   USER_1      osusr1   12728  WEB_USER_SERVICE       1183.000 TEMP
         1 1295,31011 USER_1      osusr1   32078  WEB_USER_SERVICE       1208.000 TEMP
         1 14,60566   USER_1      osusr1   8236   WEB_USER_SERVICE       1209.000 TEMP
         1 29,64998   USER_1      osusr1   9292   WEB_USER_SERVICE       1318.000 TEMP

28 rows selected.

PROD1> check active sessions

PROD1> @swact

    SID STATE   EVENT                                     SEQ# SEC_IN_STATE         P1         P2         P3 SQL_ID         CHN
------- ------- ---------------------------------------- ----- ------------ ---------- ---------- ---------- ------------- ----
   1082 WAITING Streams AQ: waiting for messages in the  34587            1       8560 2.2692E+10          5
    390 WAITING wait for unread message on broadcast cha 52505            0 2.2570E+10 2.3036E+10          0 2b064ybzkwf1y    0
    888 WORKING On CPU / runqueue                        10058            0 1413697536          1          0 dgcp1b9y4h89a    0

PROD1> --none of the sessions were active

According to my Oracle knowledge, this should not has happened once the operation finishes (commit rollback) ,Oracle should has released the space. All of these sessions were all specific to one product group and service. Question was if this was a permanent problem which we never realized or something was going wrong ?
I checked back my old spool files for temporary checks (thanks to Tanel Poder who thought us how to spool every action- check init.sql from his script library) and saw that sessions with same username and service name were also holding big temp back in september and November like below. (These checks were probably done when we hit temp issue on node-1 or when I was checking the script so I did not pay attention if those sessions were active or not (this can be counted as invalid dba exception for me :))

From november – before 11.2.0.1 upgrade from 10.2.0.4


PROD3> @temp_usageg

#####################################################################
#######################GLOBAL TEMP USAGE#############################
#####################################################################

   INST_ID TABLESPACE         MB_TOTAL     MB_USED    MB_FREE
---------- --------------- ----------- ----------- ----------
         1 TEMP              20480.000     119.000      20361
         2 TEMP              20480.000        .000      20480
         3 TEMP              20480.000    8029.000      12451 ==>right node

#####################################################################
#######################GLOBAL TEMP USERS-over 10MB ##################
#####################################################################

   INST_ID SID_SERIAL USERNAME   OSUSER     SPID   PROGRAM             MB_USED TABLESPACE
---------- ---------- ---------- ---------- ------ --------------------------- ------------

         3 484,26686  USER_1       osusr1   6798    WEB_USER_SERVICE        109.000 TEMP
         3 898,53562  USER_1       osusr1   7272    WEB_USER_SERVICE        127.000 TEMP
         3 986,27409  USER_1       osusr1   5644    WEB_USER_SERVICE        147.000 TEMP
         3 771,4399   USER_1       osusr1   23613   WEB_USER_SERVICE        148.000 TEMP
         3 946,18709  USER_1       osusr1   12065   WEB_USER_SERVICE        163.000 TEMP
         3 378,20452  USER_1       osusr1   5646    WEB_USER_SERVICE        163.000 TEMP
         3 1007,23777 USER_1       osusr1   23413   WEB_USER_SERVICE        200.000 TEMP
         3 391,37179  USER_1       osusr1   9245    WEB_USER_SERVICE        701.000 TEMP
	 3 768,23493  USER_1       osusr1   12829   WEB_USER_SERVICE        904.000 TEMP
         3 607,13902  USER_1       osusr1   26307   WEB_USER_SERVICE       1000.000 TEMP
         3 475,32196  USER_1       osusr1   8460    WEB_USER_SERVICE       1010.000 TEMP
         3 593,58443  USER_1       osusr1   31126   WEB_USER_SERVICE       1063.000 TEMP
         3 879,51688  USER_1       osusr1   12831   WEB_USER_SERVICE       1113.000 TEMP
         3 664,40877  USER_1       osusr1   8470    WEB_USER_SERVICE       1136.000 TEMP

18 rows selected.

From October – before 11.2.0.1 upgrade from 10.2.0.4


PROD3> @temp_usage

TABLESPACE         MB_TOTAL     MB_USED    MB_FREE
--------------- ----------- ----------- ----------
TEMP              20480.000    7899.000      12581

#####################################################################
#######################GLOBAL TEMP USERS-over 10MB ##################
#####################################################################

SID_SERIAL USERNAME        OSUSER          SPID    PROGRAM             MB_USED TABLESPACE
---------- --------------- --------------- ------- --------------------------- -----------

463,42814  USER_1            osusr1        1447     WEB_USER_SERVICE         17.000 TEMP
1008,59864 USER_1            osusr1        16932    WEB_USER_SERVICE         17.000 TEMP
594,37070  USER_1            osusr1        6451     WEB_USER_SERVICE         20.000 TEMP
512,40923  USER_1            osusr1        16934    WEB_USER_SERVICE         25.000 TEMP
789,37294  USER_1            osusr1        9483     WEB_USER_SERVICE        731.000 TEMP
893,63174  USER_1            osusr1        6018     WEB_USER_SERVICE        815.000 TEMP
583,54040  USER_1            osusr1        23859    WEB_USER_SERVICE        933.000 TEMP
675,37736  USER_1            osusr1        9487     WEB_USER_SERVICE        984.000 TEMP
737,58648  USER_1            osusr1        25274    WEB_USER_SERVICE       1035.000 TEMP
831,46843  USER_1            osusr1        25272    WEB_USER_SERVICE       1062.000 TEMP
973,64549  USER_1            osusr1        10270    WEB_USER_SERVICE       1109.000 TEMP
774,18708  USER_1            osusr1        6625     WEB_USER_SERVICE       1133.000 TEMP

As you can see USER_1 from WEB_USER_SERVICE on the 3th (preferred) node was always using high temp.

Next question is why we did not have this issue before on Node-1? Once we check in detail we saw services of this product group were running on the wrong node (relocated due to a failure just before change freeze) which is our main OLTP and batch node. We already knew the issue (thanks to our service check script) but it was change freeze time and we did not have chance to move service to the right nodes. When I check with the product developer, I have been told they usually reboot their web servers every 3 weeks for maintenance. This was the obvious answer to the question why we did not have the issue before. We never run this service on the OLTP node and we never let web servers hit the limits even when they are running on their own node.

Since we gave answer to our curiosity questions, now it was time for the real question “Why was Oracle not releasing the temp space back ?” On 11GR2 we have a nice column called temp_space_allocated in V$ACTIVE_SESSION_HISTORY and DBA_HIST_ACTIVE_SESS_HISTORY tables and I am lucky that we have diagnostics pack license.

Let see what the trend is and see if some sqls are the main cause. The output below is taken when the issue happened.


SQL> select sample_time,event,sql_id,is_sqlid_current,temp_space_allocated/1024/1024 TEMP_MB
 1 from v$active_session_history where session_id=29;

SAMPLE_TIME             EVENT                     SQL_ID        I TEMP_MB
----------------------- ------------------------- ------------- - -----
04-JAN-11 10.18.09.591                            akgmrn2bww2p5 Y  1319
04-JAN-11 09.50.31.125  db file sequential read   73adfqhtsd909 Y  1319
04-JAN-11 09.46.29.488                            0gaghgkkb4qyc Y  1318
04-JAN-11 08.58.14.930  db file sequential read   73adfqhtsd909 Y  1318
04-JAN-11 08.13.09.845                            0gaghgkkb4qyc Y  1318
04-JAN-11 07.46.01.586  db file sequential read   ds7zkf3vhtms0 Y  1318
04-JAN-11 07.33.05.592  row cache lock            4tcbsv32h1xh9 Y  1317
04-JAN-11 06.49.49.772  db file sequential read   9s48k84m7kt36 Y  1317
04-JAN-11 06.49.48.772  db file sequential read   734fasjm6rfu8 Y  1316
04-JAN-11 06.49.47.762  db file sequential read   734fasjm6rfu8 Y  1316
04-JAN-11 06.49.45.762  db file sequential read   9s48k84m7kt36 Y  1315
04-JAN-11 06.49.44.762  log file sync                           Y  1314
04-JAN-11 06.18.09.894                            0gaghgkkb4qyc Y  1314
04-JAN-11 06.03.21.508                            akgmrn2bww2p5 Y  1314
04-JAN-11 04.18.20.232                            11chc5v8rkusd Y  1313
04-JAN-11 02.28.14.858                            73adfqhtsd909 Y  1312
04-JAN-11 02.08.13.726                            54hw5asg19hpt Y  1312
04-JAN-11 01.00.25.381                            akgmrn2bww2p5 Y  1312
04-JAN-11 00.58.15.042  db file sequential read   9s48k84m7kt36 Y  1312
04-JAN-11 00.00.02.040  direct path read temp     9tgtnsr31xsv5 Y  1312
03-JAN-11 23.52.33.856                            ds7zkf3vhtms0 Y  1301
03-JAN-11 22.33.14.607                            g7sy7a6ynn9r1 Y  1295
03-JAN-11 22.30.07.101  direct path read          9tgtnsr31xsv5 Y  1295

Because we did not sort the issue yet I also have the current picture of our system with a better script which accepts session sid and serial and uses lag function for the temp_space_allocated differences between sample times. (output is truncated)


PROD3> set echo on
PROD3> @temp_hist 603 8375
DBA_HIST_ACTIVE_SESS_HISTORY

PROD3>  select sample_time,session_id,session_serial#,sql_id,temp_space_allocated/1024/1024 temp_mb,
  2   temp_space_allocated/1024/1024-lag(temp_space_allocated/1024/1024,1,0) over (order by sample_time) as temp_diff
  3   from dba_hist_active_sess_history
  4   --from v$active_session_history
  5   where
  6   session_id=&1
  7   and session_serial#=&2
  8   order by sample_time asc
  9   /

SAMPLE_TIME               SESSION_ID SESSION_SERIAL# SQL_ID          TEMP_MB  TEMP_DIFF
------------------------- ---------- --------------- ------------- --------- ----------
22-JAN-11 13.00.51.214           603            8375                       1          1
22-JAN-11 15.14.29.430           603            8375 29kz43xq2s5xc         1          0
22-JAN-11 15.14.39.450           603            8375 734fasjm6rfu8         3          2
22-JAN-11 15.14.49.470           603            8375 734fasjm6rfu8         8          5
22-JAN-11 15.14.59.490           603            8375 734fasjm6rfu8        13          5
22-JAN-11 15.15.09.520           603            8375 9s48k84m7kt36        18          5
22-JAN-11 15.15.19.540           603            8375 734fasjm6rfu8        23          5
22-JAN-11 15.15.29.567           603            8375 9s48k84m7kt36        29          6
22-JAN-11 16.35.50.566           603            8375 bx5zxp1a5wb55        29          0
22-JAN-11 19.45.45.831           603            8375 73adfqhtsd909        32          3
22-JAN-11 21.40.40.613           603            8375 g7sy7a6ynn9r1        32          0
23-JAN-11 06.30.35.544           603            8375 ds7zkf3vhtms0        33          1
23-JAN-11 15.18.37.539           603            8375 9d618ka6h2hvz        35          2
23-JAN-11 15.18.47.583           603            8375 2du821ps20a4c        35          0
23-JAN-11 15.18.57.593           603            8375 29kz43xq2s5xc        35          0
23-JAN-11 15.19.07.623           603            8375                      39          4
23-JAN-11 15.19.17.643           603            8375 734fasjm6rfu8        44          5
23-JAN-11 15.19.27.663           603            8375 ds7zkf3vhtms0        49          5
23-JAN-11 15.19.37.683           603            8375 734fasjm6rfu8        55          6
23-JAN-11 15.19.47.713           603            8375 9s48k84m7kt36        61          6
23-JAN-11 15.19.57.733           603            8375 7902sa7n37sv9        62          1
23-JAN-11 22.00.39.071           603            8375 basj9jchbmu4q        63          1
24-JAN-11 05.00.45.895           603            8375 apmkt8bvrpyk0        70          7
24-JAN-11 13.00.11.180           603            8375 9tgtnsr31xsv5        86         16

24 rows selected.

ACTIVE_SESS_HIST

PROD3>  select sample_time,session_id,session_serial#,sql_id,temp_space_allocated/1024/1024 temp_mb,
  2   temp_space_allocated/1024/1024-lag(temp_space_allocated/1024/1024,1,0) over (order by sample_time) as temp_diff
  3   --from dba_hist_active_sess_history
  4   from v$active_session_history
  5   where
  6   session_id=&1
  7   and session_serial#=&2
  8   order by sample_time asc
  9   /

SAMPLE_TIME               SESSION_ID SESSION_SERIAL# SQL_ID          TEMP_MB  TEMP_DIFF
------------------------- ---------- --------------- ------------- --------- ----------
23-JAN-11 05.30.39.251           603            8375                      33         33
23-JAN-11 06.00.35.429           603            8375 73adfqhtsd909        33          0
23-JAN-11 06.10.45.871           603            8375 g7sy7a6ynn9r1        33          0
23-JAN-11 06.30.35.544           603            8375 ds7zkf3vhtms0        33          0
23-JAN-11 06.40.50.971           603            8375                      33          0
23-JAN-11 07.00.40.613           603            8375 g7sy7a6ynn9r1        33          0
23-JAN-11 07.01.21.713           603            8375 ds7zkf3vhtms0        33          0
23-JAN-11 07.10.45.941           603            8375 1rsg7wva9pyxd        33          0
23-JAN-11 08.00.45.805           603            8375 73adfqhtsd909        33          0
23-JAN-11 08.15.35.931           603            8375 ds7zkf3vhtms0        33          0
23-JAN-11 09.15.39.009           603            8375                      34          1
23-JAN-11 14.15.50.763           603            8375 g7sy7a6ynn9r1        34          0
23-JAN-11 14.20.35.388           603            8375 g7sy7a6ynn9r1        34          0
23-JAN-11 14.45.45.800           603            8375 4awcvxgvdauy6        35          1
23-JAN-11 15.15.39.123           603            8375 6ubavp8u2k7xa        35          0
23-JAN-11 15.18.36.539           603            8375 d042b4z3hnra4        35          0
23-JAN-11 15.18.37.539           603            8375 9d618ka6h2hvz        35          0
23-JAN-11 15.18.38.539           603            8375 4vwy3jp3wmmz5        35          0
23-JAN-11 15.18.39.539           603            8375 4vwy3jp3wmmz5        35          0
23-JAN-11 15.18.40.549           603            8375 5jf1jgqnp993z        35          0
23-JAN-11 15.18.41.549           603            8375 5jf1jgqnp993z        35          0
23-JAN-11 15.18.42.549           603            8375 37fxhfs1p44p6        35          0
23-JAN-11 15.18.43.549           603            8375 29kz43xq2s5xc        35          0
23-JAN-11 15.18.44.559           603            8375 2du821ps20a4c        35          0
23-JAN-11 15.18.45.573           603            8375 5jf1jgqnp993z        35          0
23-JAN-11 15.18.46.573           603            8375 5jf1jgqnp993z        35          0
23-JAN-11 15.18.47.583           603            8375 2du821ps20a4c        35          0
23-JAN-11 15.18.48.583           603            8375 67kpwgzpd4qam        35          0
23-JAN-11 15.18.49.583           603            8375 5jf1jgqnp993z        35          0
23-JAN-11 15.18.50.583           603            8375 7htn6x6s336f7        35          0
23-JAN-11 15.18.51.583           603            8375 29kz43xq2s5xc        35          0
23-JAN-11 15.18.52.593           603            8375 29kz43xq2s5xc        35          0
23-JAN-11 15.18.53.593           603            8375 29kz43xq2s5xc        35          0
23-JAN-11 15.18.54.593           603            8375 29kz43xq2s5xc        35          0
23-JAN-11 15.18.55.593           603            8375 29kz43xq2s5xc        35          0
23-JAN-11 15.18.56.593           603            8375 29kz43xq2s5xc        35          0
23-JAN-11 15.18.57.593           603            8375 29kz43xq2s5xc        35          0
23-JAN-11 15.18.58.603           603            8375 2du821ps20a4c        35          0
23-JAN-11 15.18.59.603           603            8375 9s48k84m7kt36        35          0
23-JAN-11 15.19.00.603           603            8375 9s48k84m7kt36        36          1

.....
.....
.....
129 rows selected.

PROD3>

Bear in mind relying on DBA_HIST data, for detecting the sqls which caused big jumps, will not be that realistic because of the sample frequency so it is better to focus on v$active_session_history.

When we look at the v$active_session_history it like there is no obvious reason. There are some sqlids which certainly increase the temp usage but not big jumps.I did one more check before I raise the question to Oracle support and checked what type of segments these TEMP segments are ? To do this I tweaked the temp_usage.sql and add segtype column to the scripts.


PROD1> @temp_usageg

#####################################################################
#######################GLOBAL TEMP USAGE#############################
#####################################################################

   INST_ID TABLESPACE         MB_TOTAL     MB_USED    MB_FREE
---------- --------------- ----------- ----------- ----------
         3 TEMP              22528.000       7.000      22521
         2 TEMP              22528.000      56.000      22472
         1 TEMP              22528.000   19102.000       3426

#####################################################################
#######################GLOBAL TEMP USERS-over 10MB###################
#####################################################################

   INST_ID SID_SERIAL USERNAME        OSUSER          SPID   SERVICE		   SEGTYPE	MB_USED TABLESPACE
---------- ---------- --------------- --------------- ------ ---------------------------------- ---------------
         1 620,4322   USER_1         osusr1        21712  WEB_USER_SERVICE       LOB_DATA     16.000 TEMP
         1 41,35454   USER_1         osusr1        20334  WEB_USER_SERVICE       LOB_DATA     19.000 TEMP
         1 529,21034  USER_1         osusr1        5776   WEB_USER_SERVICE       LOB_DATA     20.000 TEMP
         1 538,54672  USER_1         osusr1        30383  WEB_USER_SERVICE       LOB_DATA     27.000 TEMP
         1 1258,36144 USER_1         osusr1        5745   WEB_USER_SERVICE       LOB_DATA     31.000 TEMP
         1 1351,56539 USER_2          root           29910  WEB_USER_SERVICE       LOB_DATA     67.000 TEMP
         1 1113,59480 USER_2          root           11397  WEB_USER_SERVICE       LOB_DATA     78.000 TEMP
         1 30,4102    USER_2          root           15244  WEB_USER_SERVICE       LOB_DATA     78.000 TEMP
         1 892,14168  USER_2          root           19971  WEB_USER_SERVICE       LOB_DATA     79.000 TEMP
         1 699,56288  USER_1         osusr1        11240  WEB_USER_SERVICE       LOB_DATA    668.000 TEMP
         1 1501,55691 USER_1         osusr1        11236  WEB_USER_SERVICE       LOB_DATA    685.000 TEMP
         1 1396,7154  USER_1         osusr1        12526  WEB_USER_SERVICE       LOB_DATA    808.000 TEMP
         1 233,46662  USER_1         osusr1        11334  WEB_USER_SERVICE       LOB_DATA    810.000 TEMP
         1 1004,14127 USER_1         osusr1        24287  WEB_USER_SERVICE       LOB_DATA    832.000 TEMP
         1 1196,820   USER_1         osusr1        12530  WEB_USER_SERVICE       LOB_DATA    868.000 TEMP
         1 1121,1990  USER_1         osusr1        24290  WEB_USER_SERVICE       LOB_DATA    893.000 TEMP
         1 297,2940   USER_1         osusr1        8910   WEB_USER_SERVICE       LOB_DATA    903.000 TEMP
         1 294,39051  USER_1         osusr1        15116  WEB_USER_SERVICE       LOB_DATA    924.000 TEMP
         1 37,46739   USER_1         osusr1        15118  WEB_USER_SERVICE       LOB_DATA    932.000 TEMP
         1 414,31439  USER_1         osusr1        8877   WEB_USER_SERVICE       LOB_DATA    935.000 TEMP
         1 913,40598  USER_1         osusr1        9710   WEB_USER_SERVICE       LOB_DATA   1064.000 TEMP
         1 710,44883  USER_1         osusr1        9703   WEB_USER_SERVICE       LOB_DATA   1115.000 TEMP
         1 147,16701  USER_1         osusr1        9295   WEB_USER_SERVICE       LOB_DATA   1137.000 TEMP
         1 1446,25613 USER_1         osusr1        12372  WEB_USER_SERVICE       LOB_DATA   1139.000 TEMP
         1 721,5152   USER_1         osusr1        12728  WEB_USER_SERVICE       LOB_DATA   1183.000 TEMP
         1 1295,31011 USER_1         osusr1        32078  WEB_USER_SERVICE       LOB_DATA   1208.000 TEMP
         1 14,60566   USER_1         osusr1        8236   WEB_USER_SERVICE       LOB_DATA   1209.000 TEMP
         1 29,64998   USER_1         osusr1        9292   WEB_USER_SERVICE       LOB_DATA   1318.000 TEMP

28 rows selected.

My initial thought was temp tablespaces but I was wrong, it looks like all temp allocators which do not release the space are LOB segments. I also checked the sqls in the ash trend and it reveals sql_id’s which has got lob operations (some of them are packages). Double checked with developer and got the answer that they use dbms_lob.

Now it is time to look for bug, First hit on metalink “How to Release the Temp LOB Space and Avoid Hitting ORA-1652 [ID 802897.1]”. It says issue is for releases 8.1.5.0 to 11.1.0.7 but we are on 11.2.0.1. This document says there are 2 workarounds for versions above 10.2.0.4, first workaround is basically use
dbms_lob.freetemporary(a) but still drop the connection which is not a workaround at all.

Second solution is using the event 60025 to force session to freed space. The event information is like below

Cause
Temp LOB segments used for temporary LOBs are deleted only on session exit which may lead to large amounts of memory being held across multiple sessions.

Action
Setting this event will cause temporary LOB segments to be freed when there are no active temporary LOBs in the session. Setting this event will have a significant performance impact as it can cause temporary lob segments to be allocated and deleted many times during a session rather than once per session. Use this event only when temporary LOB segment memory use is an issue.

When I try the event it works (not immediately but when you call the allocation again) like below. I raised a call with Oracle before we implement the event change (probably with logon trigger) and still working with them to see if there is a one-off patch for the issue. If Oracle could not come up with one-off patch we will use the event.


---Before the session runs

14:23:00 SYS@ORACOS> @temp_usage

#####################################################################
#######################LOCAL TEMP USAGE#############################
#####################################################################

TABLESPACE         MB_TOTAL     MB_USED    MB_FREE
--------------- ----------- ----------- ----------
TEMP               2697.000        .000       2697

#####################################################################
#######################LOCAL TEMP USERS#############################
#####################################################################

no rows selected

---Session runs the dbms_lob

HR@ORACOS> @temp_test
14:23:10 HR@ORACOS>
14:23:10 HR@ORACOS> DECLARE
14:23:10   2  a clob;
14:23:10   3  BEGIN
14:23:10   4  dbms_lob.createtemporary(a, TRUE,dbms_lob.call);
14:23:10   5  END;
14:23:10   6  /

PL/SQL procedure successfully completed.

14:23:10 HR@ORACOS>
14:23:10 HR@ORACOS> commit;

Commit complete.

14:23:10 HR@ORACOS>
14:23:10 HR@ORACOS> ---check the temp usage on another session
14:23:10 HR@ORACOS> exec dbms_lock.sleep(15);

---monitoring session

14:23:01 SYS@ORACOS> @temp_usage

#####################################################################
#######################LOCAL TEMP USAGE#############################
#####################################################################

TABLESPACE         MB_TOTAL     MB_USED    MB_FREE
--------------- ----------- ----------- ----------
TEMP               2697.000       1.000       2696

#####################################################################
#######################LOCAL TEMP USERS#############################
#####################################################################

SID_SERIAL USERNAME          OSUSER          SPID  SERVICE_NAME        MB_USED TABLESPACE      STATEMENTS
---------- ----------------- --------------- --------------------- ----------- --------------- ----------
200,7236   HR                coskan          22101 SYS$USERS             1.000 TEMP                     1

---session activates the event

14:23:25 HR@ORACOS> ---enable the event
14:23:25 HR@ORACOS> alter session set events '60025 trace name context forever';

Session altered.

14:23:25 HR@ORACOS>
14:23:25 HR@ORACOS> ---check the temp usage on another session
14:23:25 HR@ORACOS> exec dbms_lock.sleep(15);

---monitoring session

14:23:15 SYS@ORACOS> @temp_usage

#####################################################################
#######################LOCAL TEMP USAGE#############################
#####################################################################

TABLESPACE         MB_TOTAL     MB_USED    MB_FREE
--------------- ----------- ----------- ----------
TEMP               2697.000       1.000       2696

#####################################################################
#######################LOCAL TEMP USERS#############################
#####################################################################

SID_SERIAL USERNAME          OSUSER          SPID   SERVICE_NAME        MB_USED TABLESPACE      STATEMENTS
---------- ----------------- --------------- ------ --------------- ----------- --------------- ----------
200,7236   HR                coskan          22101  SYS$USERS             1.000 TEMP                     1

---session activates the event and run the dbms_lob again

14:23:40 HR@ORACOS> ---re run the procedure
14:23:40 HR@ORACOS> DECLARE
14:23:40   2  a clob;
14:23:40   3  BEGIN
14:23:40   4  dbms_lob.createtemporary(a, TRUE,dbms_lob.call);
14:23:40   5  END;
14:23:40   6  /

PL/SQL procedure successfully completed.

14:23:40 HR@ORACOS>
14:23:40 HR@ORACOS> commit;

Commit complete.

14:23:40 HR@ORACOS>
14:23:40 HR@ORACOS> ---check the temp usage on another session
14:23:40 HR@ORACOS> exec dbms_lock.sleep(15);

--monitoring session
14:23:29 SYS@ORACOS> @temp_usage

#####################################################################
#######################LOCAL TEMP USAGE#############################
#####################################################################

TABLESPACE         MB_TOTAL     MB_USED    MB_FREE
--------------- ----------- ----------- ----------
TEMP               2697.000        .000       2697

#####################################################################
#######################LOCAL TEMP USERS#############################
#####################################################################

no rows selected

no rows selected

14:23:44 SYS@ORACOS>

In summary With this post I walk through how you can diagnose a temp issue and how new temp_allocated column of v$session and history tables can be very helpful during your diagnose.
Hope it will help some of you guys.

Scripts I used for this post

temp_usageg.sql for global temp usage info in RAC
temp_usage.sql for global temp usage info
temp_history.sqlto get historic information for a spesific sid,serial

Information about bug for sqlid column of V$TEMPSEG_USAGE / v$sort_usage by Kerry Osborne

Update 08/10/2012

Related info on another blog is also here for usage of WMSYS.WM_CONCAT and temp allocation

 

http://asanga-pradeep.blogspot.co.uk/2012/10/use-of-wmconcat-can-exhaust-temporary.html

13 Comments »

  1. Thanks for sharing

    Comment by Eugene — January 24, 2011 @ 6:09 pm

  2. Good post.But there’s not new temp_allocated column of v$session.Using v$tempseg_usage is better in the scripts.

    Comment by johnwuwuwu — March 17, 2011 @ 9:20 am

  3. I mean the last statement:
    “how new temp_allocated column of v$session “

    Comment by johnwuwuwu — March 21, 2011 @ 2:22 am

  4. We are facing the exact same issue. Your post was helpful. Did you receive a patch from oracle ?

    Comment by Deepa — June 14, 2011 @ 7:54 pm

  5. Facing same issue, but Oracle Support blames JDBC. Any idea?

    Comment by Alexo — October 4, 2012 @ 3:27 pm

  6. […] the temp space. A quick web search shows that most people seem to be querying current tables. Coskan Gundogar bloggeed about a historical monitoring script he wrote, but only drilling down into a specific […]

    Pingback by Sleuthing for temporary space spendthrifts | The Pythian Blog — December 21, 2012 @ 2:44 am

  7. Coskan,

    Did you get fix for this issue from oracle? we are also facing this issue in 11.2.0.3 .

    Comment by Gaurav — February 14, 2013 @ 9:10 am

  8. […] Coskan Gundogar gave a nice example related to a temp space issue, for a particular session into this blog post. […]

    Pingback by Link huge PGA or TEMP consumption to sql_id over a period of time | bdt's oracle blog — March 19, 2013 @ 6:33 pm

  9. Came across the link when facing similar issue. The description here is very descriptive and helpful. Exactly same as issue which I faced. Thanks for the blog.

    Comment by Harish — June 12, 2017 @ 9:57 am

  10. Hi, thanks for the very useful post also now in 2018! Where did you find event information for 60025?

    Comment by Riccardo — September 17, 2018 @ 9:23 am


RSS feed for comments on this post. TrackBack URI

Leave a reply to Link huge PGA or TEMP consumption to sql_id over a period of time | bdt's oracle blog Cancel reply

Create a free website or blog at WordPress.com.