Guarantee Restore Point Leads to High DB File Sequential Read Waits on Undo Tablespace in 11gR2

Guarantee restore points are useful to have in test environments which allows easy rollback of the database so test could be run again without having to have a new data sets for inserts that can cause primary key violation.
However it seems having a guarantee restore point can cause excessive db file sequential read waits on the undo tablespace for insert statements. This could alter the performance characteristics of test.
Following test case could be used to recreate this behavior. The test environment used here is 11gR2 (11.2.0.3.3).
Create the table for the test case

create table ses_lock (sid varchar2(100) primary key);

Open 3 sql plus session (called 1,2 and 3 from now on) and run the following pl/sql blocks on each one.
On session 1 create and hold a lock to start the concurrent insert process

declare
    i pls_integer;
begin
    i := dbms_lock.request(10);
end;
/

On session 2 run the PL/SQL for the insert statment

declare
    i pls_integer;
begin
    i := dbms_lock.request(10,DBMS_LOCK.S_MODE);

    for i in 1 .. 100000
    loop
     insert into ses_lock values (dbms_random.string('x',36));
     commit;
    end loop;
     i := dbms_lock.release(10);
end;
/

Run the same on sesison 3

declare
    i pls_integer;
begin
    i := dbms_lock.request(10,DBMS_LOCK.S_MODE);

    for i in 1 .. 100000
    loop
     insert into ses_lock values (dbms_random.string('x',36));
     commit;
    end loop;
     i := dbms_lock.release(10);
end;
/

and finaly on session 1 release the lock

declare
    j pls_integer;
begin
    j := dbms_lock.release(10);
end;
/

This will start concurrent insert into the table.
Investigating the active session history during this period for the insert sql shows that db file sequential reads are on datafile 14 which is the datafile where the table resides.

select inst_id,p1,p1text,sql_id,count(*)
from gv$active_session_history
where sample_time >  to_date('2012-09-17 11:37','YYYY-MM-DD HH24:MI')
and event ='db file sequential read'
group by inst_id, p1, p1text, sql_id
order by 5 desc,1 ,2;

INST_ID  P1  P1TEXT SQL_ID        COUNT(*)         
-------- --- ------ ------------- ---------
1        14  file#  7pj2bbx25m1rf 30                     

SQL> select sql_id,sql_text from v$sql where sql_id='7pj2bbx25m1rf';

SQL_ID        SQL_TEXT
------------- ------------------------------------------------------------
7pj2bbx25m1rf INSERT INTO SES_LOCK VALUES (DBMS_RANDOM.STRING('x',36))

SQL> select file_id,tablespace_name from dba_data_files where file_id=14;

FILE_ID TABLESPACE_NAME
------- -----------------
14      BX2KTBS

Delete the rows in the table and create a guarantee restore point

SQL> delete from ses_lock;
200000 rows deleted.

SQL> commit;

It is possible to create a guarantee restore point in 11gR2 without having flashback on. Before guarantee restore point is created

SQL> select flashback_on from v$database;

FLASHBACK_ON
-------------
NO

After guarantee restore point

SQL> create restore point first_restore guarantee flashback database;

SQL> select flashback_on from v$database;

FLASHBACK_ON
------------------
RESTORE POINT ONLY

Create 3 sql*plus sessions mentioned above and run the insert again.
Querying the active session history afterwards shows that during this test the db file sequential read waits were on the data file used for the undo tablespace and much higher number of waits compared to test without the guarantee restore point.

select inst_id,p1,p1text,sql_id,count(*)
from gv$active_session_history
where sample_time >  to_date('2012-09-17 12:02','YYYY-MM-DD HH24:MI')
and event ='db file sequential read'
group by inst_id, p1, p1text, sql_id
order by 5 desc,1 ,2;

INST_ID  P1  P1TEXT SQL_ID        COUNT(*)         
-------- --- ------ ------------- ---------
1        3   file#  7pj2bbx25m1rf 266    

SQL> select file_id,tablespace_name from dba_data_files where file_id in (3,14);

FILE_ID  TABLESPACE_NAME
-------- ---------------
3        UNDOTBS1
14       BX2KTBS

Dropped the restore point and ran the test again and this time there was no db file sequential waits and as soon as the restore point is created and test carried out see lots of db file sequential read waits on undo tablespace data file. Below is the output of querying active session history for the second test with restore point thus confirming that observed behavior is repeatable with the test case

select inst_id,p1,p1text,sql_id,count(*)
from gv$active_session_history
where sample_time >  to_date('2012-09-17 12:20','YYYY-MM-DD HH24:MI')
and event ='db file sequential read'
group by inst_id, p1, p1text, sql_id
order by 5 desc,1 ,2;

INST_ID  P1  P1TEXT SQL_ID        COUNT(*)         
-------- --- ------ ------------- ---------
1        3   file#  7pj2bbx25m1rf 193    

-->


SQL tracing could also be used to demonstrate this problem. This is useful if the database is standard edition where use of active session history view is not an option because of license restrictions.
Enable sql tracing for the session

alter session set max_dump_file_size=UNLIMITED;
alter session set  tracefile_identifier='before_grp';
alter session set events '10046 trace name context forever, level 12';

Run the insert statement, this time only using on session

declare
    i pls_integer;
begin
    i := dbms_lock.request(10,DBMS_LOCK.S_MODE);

    for i in 1 .. 100000
    loop
     insert into ses_lock values (dbms_random.string('x',36));
     commit;
    end loop;
     i := dbms_lock.release(10);
end;
/

Formatted trace file output shows no waits for db file sequential read wait event

SQL ID: dqhz25akp92bp Plan Hash: 0

INSERT INTO SES_LOCK VALUES (DBMS_RANDOM.STRING('x',36))

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute 100000     14.95      14.77          0       2746     517465      100000
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   100001     14.95      14.77          0       2746     517465      100000

Misses in library cache during parse: 1
Optimizer mode: FIRST_ROWS
Parsing user id: 84     (recursive depth: 1)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         0          0          0  LOAD TABLE CONVENTIONAL  (cr=155 pr=5 pw=0 time=35733 us)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  Disk file operations I/O                        2        0.00          0.00
  latch: In memory undo latch                     1        0.00          0.00
  log file switch completion                      2        0.00          0.01
  latch free                                      1        0.00          0.00
********************************************************************************

Delete all rows from the table and create restore point

SQL> delete from ses_lock;
100000 rows deleted.

SQL>commit;
Commit complete.

SQL> create restore point first_restore guarantee flashback database;

Run the test again

alter session set max_dump_file_size=UNLIMITED;
alter session set  tracefile_identifier='after_grp';
alter session set events '10046 trace name context forever, level 12';

declare
    i pls_integer;
begin
    i := dbms_lock.request(10,DBMS_LOCK.S_MODE);

    for i in 1 .. 100000
    loop
     insert into ses_lock values (dbms_random.string('x',36));
     commit;
    end loop;
     i := dbms_lock.release(10);
end;
/

and formatted output of trace file shows high number of db file sequential read waits compared to previous test

SQL ID: dqhz25akp92bp Plan Hash: 0

INSERT INTO SES_LOCK VALUES (DBMS_RANDOM.STRING('x',36))

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute 100000     20.71      22.50       3507        107     513257      100000
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   100001     20.71      22.50       3507        107     513257      100000

Misses in library cache during parse: 1
Optimizer mode: FIRST_ROWS
Parsing user id: 84     (recursive depth: 1)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         0          0          0  LOAD TABLE CONVENTIONAL  (cr=1 pr=0 pw=0 time=1844 us)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  Disk file operations I/O                        2        0.00          0.00
  db file sequential read                      3507        0.11          3.78
  log file switch (checkpoint incomplete)         3        0.00          0.00
  latch: redo allocation                          1        0.00          0.00
  log file switch completion                      1        0.06          0.06
********************************************************************************

Inspecting trace file itself could see details of the wait event and wait is on file#=3

WAIT #46953194410944: nam='db file sequential read' ela= 277 file#=3 block#=16505 blocks=1 obj#=0 tim=1349341486136362
WAIT #46953194410944: nam='db file sequential read' ela= 263 file#=3 block#=17317 blocks=1 obj#=0 tim=1349341486138981
WAIT #46953194410944: nam='db file sequential read' ela= 330 file#=3 block#=16955 blocks=1 obj#=0 tim=1349341486149736
WAIT #46953194410944: nam='db file sequential read' ela= 387 file#=3 block#=17076 blocks=1 obj#=0 tim=1349341486152818
WAIT #46953194410944: nam='db file sequential read' ela= 15 file#=3 block#=16839 blocks=1 obj#=0 tim=1349341486161143

File#=3 is the datafile used with the undo tablespace.
Drop the restore point and the db file sequential read event disappear, output below after restore point is dropped

SQL ID: dqhz25akp92bp Plan Hash: 0

INSERT INTO SES_LOCK VALUES (DBMS_RANDOM.STRING('x',36))

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute 100000     15.44      14.60          0         67     593197      100000
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   100001     15.44      14.60          0         67     593197      100000

Misses in library cache during parse: 0
Optimizer mode: FIRST_ROWS
Parsing user id: 84     (recursive depth: 1)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         0          0          0  LOAD TABLE CONVENTIONAL  (cr=1 pr=0 pw=0 time=1613 us)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  log file switch (checkpoint incomplete)         4        0.00          0.01
  latch: cache buffers chains                     1        0.00          0.00
  Disk file operations I/O                        1        0.00          0.00
********************************************************************************

SR was raised with Oracle and response was that "this is similar to Bug 12921374 : GURANTEED RESTORE POINT CAUSES MANY PHYSICAL READS." However there has not been any movement on this bug since Feb 2012 and there's no solution or workaround. As a result of this SR a new bug report has been created which is available under "Bug 14671654 : GUARANTEE RESTORE POINT PROVOKES HIGH"
The same test was carried out on 11.1.0.7 (11.1.0.7.12) and it didn't have the same behavior as 11gR2. So the issue is localized to 11gR2.(Update 2014/11/21-11.1 also exhibit the same behavior. Depending on when the table is created and when the restore point is created the location of the wait event on the trace file differ. Looking only at the insert statement may result in missing the high waits shown under the commit. Either way total number of waits for the test case on 11.1 is not different to that of 11.2)

Update 15 July 2013
The issue is also there on 12c (12.1.0.1). Below is the tkprof output after the same test done on a 12c.Before restore point creation

SQL ID: dqhz25akp92bp Plan Hash: 0

INSERT INTO SES_LOCK
VALUES
 (DBMS_RANDOM.STRING('x',36))


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute 100000     41.03      40.49          1       3272     515757      100000
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   100001     41.03      40.50          1       3272     515757      100000

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 103     (recursive depth: 1)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         0          0          0  LOAD TABLE CONVENTIONAL  (cr=783 pr=7 pw=0 time=195740 us)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  Disk file operations I/O                        6        0.00          0.00
  db file sequential read                         3        0.00          0.00
  latch: shared pool                              8        0.00          0.00
  log file switch (private strand flush incomplete)
                                                  1        0.01          0.01
  control file sequential read                   20        0.00          0.00
  Data file init write                           12        0.00          0.00
  db file single write                            1        0.00          0.00
  control file parallel write                     3        0.00          0.00
  rdbms ipc reply                                 1        0.00          0.00
********************************************************************************

After restore point created

SQL ID: dqhz25akp92bp Plan Hash: 0

INSERT INTO SES_LOCK
VALUES
 (DBMS_RANDOM.STRING('x',36))


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute 100000     43.42      42.15       3484        660     512898      100000
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   100001     43.43      42.16       3484        660     512898      100000

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 103     (recursive depth: 1)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         0          0          0  LOAD TABLE CONVENTIONAL  (cr=226 pr=0 pw=0 time=56775 us)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  Disk file operations I/O                        2        0.00          0.00
  db file sequential read                      3484        0.28          0.47
  log file switch (checkpoint incomplete)         1        0.01          0.01
  log file switch completion                      1        0.01          0.01
********************************************************************************

All the waits were on the undo tablespace same as before.

Update 14 July 2014
Same behavior is also observed on 11.2.0.4. Before guarantee restore point

SQL ID: dqhz25akp92bp Plan Hash: 0

INSERT INTO SES_LOCK
VALUES
 (DBMS_RANDOM.STRING('x',36))


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.01       0.01          0          0          0           0
Execute 100000     72.74      81.65          6       3595     426842      100000
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   100001     72.75      81.66          6       3595     426842      100000

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 50     (recursive depth: 1)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         0          0          0  LOAD TABLE CONVENTIONAL  (cr=164 pr=8 pw=0 time=103136 us)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  enq: IV -  contention                          10        0.00          0.00
  db file sequential read                         6        0.00          0.02
  Disk file operations I/O                        1        0.00          0.00
  row cache lock                                  7        0.00          0.00
  latch: shared pool                              4        0.00          0.00
  latch: enqueue hash chains                      3        0.00          0.00
  latch free                                      3        0.00          0.00
  latch: redo allocation                          1        0.00          0.00
  log file switch (checkpoint incomplete)         1        0.00          0.00
  log file switch completion                      1        0.00          0.00
********************************************************************************

After guarantee restore point created

SQL ID: dqhz25akp92bp Plan Hash: 0

INSERT INTO SES_LOCK
VALUES
 (DBMS_RANDOM.STRING('x',36))


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute 100000     82.15      94.40       5143       3615     434964      100000
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   100001     82.16      94.41       5143       3615     434964      100000

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 50     (recursive depth: 1)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         0          0          0  LOAD TABLE CONVENTIONAL  (cr=5 pr=3 pw=0 time=13633 us)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  row cache lock                                  3        0.00          0.00
  Disk file operations I/O                        3        0.00          0.00
  db file sequential read                      5143        0.52          2.31
  KSV master wait                                 2        0.00          0.00
  ASM file metadata operation                     1        0.00          0.00
  latch free                                      1        0.00          0.00
  log file switch (checkpoint incomplete)         2        0.01          0.02
********************************************************************************

Update 21 November 2014
Final reply from Oracle "this is not a bug but expected behavior when restore point is in use".

Use of WM_CONCAT Can Exhaust Temporary Tablespace in 11gR2 & 10gR2

WM_CONCAT function could be used aggregate multiple row values into single row. Below is a short example

create table x (a number, b varchar2(10));

SQL> insert into x values(1,'a');
1 row created.
SQL> insert into x values (2,'b');
1 row created.
SQL> insert into x values(1,'c');
1 row created.
SQL> insert into x values(2,'d');
1 row created.
SQL> commit;

SQL> select a,wm_concat(b) as concats from x group by a;

         A CONCATS
---------- ----------
         1 a,c
         2 b,d

However wm_concat is an undocumented function not for direct use by customers (more on this later on) but that doesn't prevent developers from using this function.
However there's a danger that extensive invocation of this function could exhaust the temporary tablespace. Primary reason for this is that wm_concat has a sort aggregation in it that result in temporary tablespace segments being used

SQL> explain plan for select wm_concat('abc'||'def') from dual;

SQL>  select * from table(dbms_xplan.display);

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------
Plan hash value: 3910148636

-----------------------------------------------------------------
| Id  | Operation        | Name | Rows  | Cost (%CPU)| Time     |
-----------------------------------------------------------------
|   0 | SELECT STATEMENT |      |     1 |     2   (0)| 00:00:01 |
|   1 |  SORT AGGREGATE  |      |     1 |            |          |
|   2 |   FAST DUAL      |      |     1 |     2   (0)| 00:00:01 |
-----------------------------------------------------------------

(no matter what, tested db instance had 7G SGA, 3G PGA and this was the only test case running, plenty of memory to do the sort in memory) but these are not released until the connection is physically close, which means exit from sql*plus or closing a connection pool in a the case of jdbc connection pools. This effect could be demonstrated with following test case using 11gR2 (11.2.0.3.3) Linux 64-bit instance.
Create a temporary tablespace of 5M and assign it as the default temporary tablespace for the test user

create temporary tablespace temp5m TEMPFILE size 5m autoextend on next 1m maxsize 5m;
alter user asanga temporary tablespace temp5m;

Run the sql with wm_concat from 5 different sql*plus session and monitor the temporary tablespace segment usage.
Temporary tablespace usage before test starts

SELECT A.inst_id,
  A.tablespace_name TABLESPACE,
  D.mb_total,
  SUM (A.used_blocks * D.block_size) / 1024 / 1024 mb_used,
  D.mb_total         - SUM (A.used_blocks * D.block_size) / 1024 / 1024 mb_free
FROM gv$sort_segment A,
  (SELECT B.INST_ID,
    B.name,
    C.block_size,
    SUM (C.bytes) / 1024 / 1024 mb_total
  FROM gv$tablespace B,
    gv$tempfile C
  WHERE B.ts#  = C.ts#
  AND c.inst_id=b.inst_id
  GROUP BY B.INST_ID,
    B.name,
    C.block_size
  ) D
WHERE A.tablespace_name = D.name
and a.tablespace_name='TEMP5M'
AND A.inst_id           =D.inst_id
GROUP BY a.inst_id,
  A.tablespace_name,
  D.mb_total
ORDER BY 1,2;

 INST_ID TABLESPACE   MB_TOTAL    MB_USED    MB_FREE
-------- ---------- ---------- ---------- ----------
       1 TEMP5M              5          0          5

Run sql on first sql*plus session

SQL> select wm_concat('abc'||'def') as X from dual;

X
--------
abcdef

Temporary segment usage

 INST_ID TABLESPACE   MB_TOTAL    MB_USED    MB_FREE
-------- ---------- ---------- ---------- ----------
       1 TEMP5M              5          1          4

The above sql could be run on the same sql*plus session multiple times without increasing the temporary segment usage. As soon as the sql is run from a different sql*plus session the temporary segment usage increase. After running on second sql*plus session

 INST_ID TABLESPACE   MB_TOTAL    MB_USED    MB_FREE
-------- ---------- ---------- ---------- ----------
       1 TEMP5M              5          2         3

Similarly 4 sql*plus session could be used to run the above mentioned sql and at the end of running the sql on 4th sqlplus session temporary segment usage will be

 INST_ID TABLESPACE   MB_TOTAL    MB_USED    MB_FREE
-------- ---------- ---------- ---------- ----------
       1 TEMP5M              5          4          1

Running on the 5th sql*plus session will result in the following error

SQL> select wm_concat('abc'||'def') as X from dual;
ERROR:
ORA-01652: unable to extend temp segment by 128 in tablespace TEMP5M
ORA-06512: at "WMSYS.WM_CONCAT_IMPL", line 31

Use the following sql to verify the sql statments using temporary segments (SQL from 317441.1)

SQL> SELECT a.username,
  2    a.sid,
  3    a.serial#,
  4    a.osuser,
  5    b.tablespace,
  6    b.blocks,
  7    b.segtype,
  8    c.sql_text
  9  FROM v$session a,
 10    v$tempseg_usage b,
 11    v$sqlarea c
 12  WHERE a.saddr    = b.session_addr
 13  AND c.address    = a.sql_address
 14  AND c.hash_value = a.sql_hash_value
 15  ORDER BY b.tablespace,
 16    b.blocks;

USERNA        SID    SERIAL# OSUSER TABLESPACE     BLOCKS SEGTYPE   SQL_TEXT
------ ---------- ---------- ------ ---------- ---------- --------- --------------------------------------------------
ASANGA          9       6487 oracle TEMP5M            128 LOB_DATA  select wm_concat('abc'||'def') as X from dual
ASANGA        202        209 oracle TEMP5M            128 LOB_DATA   select wm_concat('abc'||'def') as X from dual
ASANGA        136       3207 oracle TEMP5M            128 LOB_DATA  select wm_concat('abc'||'def') as X from dual
ASANGA         78        377 oracle TEMP5M            128 LOB_DATA  select wm_concat('abc'||'def') as X from dual

The temporary segments will not be released until sql*plus session is close (by exit). Even though the table has no LOB column the temp segments are shown as LOB_DATA. Lobs are used within the wm_concat it is why the temp segment appear as LOB_DATA.


On java applications that use connection pool, (UCP or DataSource) connections are not physically closed when the connection close function is called. The close is a logical close and physical connection remains open in the connection pool ready to be used by another session. As such the temporary segment usage will keep on increasing until the temporary tablespace is exhausted since connection pool is never closed except when the application (or application server in most cases) is restarted,dies or crashed.
Following java code could be used to demonstrate how this could affect java application using connection pool. Class imports are not shown

public class DBConnection {

    private PoolDataSource pds = null;

    public DBConnection(String username,String password, String host,String port, String sid) {
        try {
            pds = PoolDataSourceFactory.getPoolDataSource();
            pds.setUser(username);
            pds.setPassword(password);
            pds.setURL("jdbc:oracle:thin:@"+host+":"+port+":"+sid);
            pds.setConnectionFactoryClassName("oracle.jdbc.pool.OracleDataSource");
            pds.setInitialPoolSize(10);
            pds.setMinPoolSize(10);
            pds.setMaxPoolSize(15);
            
        } catch (SQLException ex) {
            ex.printStackTrace();
        }
    }

    public Connection getConnection() throws SQLException {

         return pds.getConnection();
    }
}


public class TempSegThread extends Thread {

    private DBConnection pool;

    public TempSegThread(DBConnection pool) {
        this.pool = pool;
    }

    @Override
    public void run() {
        try {
            for (int i = 0; i < 1; i++) {

                int j = 0;
                Connection con = pool.getConnection();
                PreparedStatement pr = con.prepareStatement("select wm_concat('abc'||'def') from dual");
                ResultSet rs = pr.executeQuery();
                while (rs.next()) {
                    System.out.println(getName() +" "+ rs.getString(1));
                }
                rs.close();
                pr.close();
                con.close();
            }
        } catch (SQLException ex) {
            Logger.getLogger(TempSegThread.class.getName()).log(Level.SEVERE, null, ex);
        }
    }
}


public class ThreadExec {

    public static void main(String[] args) {

//       if (args.length != 5) {
//
//            System.out.println("usage: java ThreadExec username password host port sid");
//        } else {

            try {

                DBConnection pool = new DBConnection("asanga","asa","192.168.0.66","1521","ent11g2");
                //Change to TempSegThread[4] to run without unable to extend temp segment
                TempSegThread [] tempThread = new TempSegThread[5];

                for(int i = 0 ; i < tempThread.length; i++){
                    tempThread[i] = new TempSegThread(pool);
                    tempThread[i].start();
                }

                for(TempSegThread t : tempThread){
                    t.join();
                }
                Thread.sleep(5 * 60 * 60 * 1000);

            } catch (Exception ex) {
                ex.printStackTrace();
            }
//        }
    }
}

Program run the same sql used in sql*plus test and run it in 5 threads using 5 different connections. One of the threads will fail with unable to extend temporary segment while others finish without error. Changing the thread count to 4 will allow 4 threads to run without error and at the end of their execution program will sleep for 5 minutes giving enough time to execute temporary segment usage SQL to see that temporary segments are still being held and usage hasn't gone down even after connections are closed.
As mentioned in metalink note 1384829.1 using "60025 trace name context forever" is of no help in this case even though temporary segments are classified as lob_data.
Oracle has mentioned in many documents that wm_concat "is not meant to be used by customers directly, and could be changed/updated without notice by Oracle Development. Do not use the WMSYS.WM_CONCAT view in your application" (From 1300595.1). So the best case is not to use it as if there's any issue it's unlikely this would qualify for support. (When a SR was raised this is exactly what Oracle said, wm_concat is not for end users).
The other versions tested 11gR1 (11.1.0.7.12) didn't have this issue but 10gR2 (10.2.0.5.8) did have the same issue as 11gR2.

Useful metalink notes
WMSYS.WM_CONCAT Should Not Be Used For Customer Applications, It Is An Internal Function [ID 1336219.1]
Problem with WMSYS.WM_CONCAT Function after Upgrading [ID 1300595.1]
SQL USING WM_CONCAT RUNS SLOWER IN 10.2.0.5 and 11.2.0.2 [ID 1393596.1]
How to Release Temporary LOB Segments without Closing the JDBC Connection [ID 1384829.1]
How to Release the Temp LOB Space and Avoid Hitting ORA-1652 [ID 802897.1]

Related Post
WM_CONCAT Removed From 12c Workspace Manager?

Log File Sync and Log File Parallel Write Waits

On a routine database health check it was discovered the that the log file sync waits events have increased 10-20 times than the base line values. Graphs generated with ADMon

Log File Sync Waits

Metalink note 34592.1 list the usual causes for high log file sync waits. Assuming all else (meaning hardware related parameters) remains the same and constants the main reason is the high user commit rates. But in this case the user commit rates were consistent throughout the problem period.

User Commits

Same was true for user rollbacks (the drop is due to instance restart) and transaction rollbacks.

User Rollbacks

Transaction Rollback

DB CPU was also consistent throughout the problem period which indicated there was no increase in the system load.

DB CPU

Metalink note 34592.1 show how the log file sync wait time could be broken down. Two metrics related to this case are the "redo write time" metric which is the time taken by lgwr process gathering redo to be written and issuing IO. The second statistic is the log file parallel write (refer 34583.1) wait time which is the "time taken for all the outstanding I/O requests to complete". Log file parallel write wait time graph was similar to the log file sync wait time graph.

Log File Parallel Write

34592.1 also mention several statistics that are related to lgwr performance. These are redo writes,redo blocks written,redo write time,redo wastage and redo size. Definitions of these statistics are from the Oracle Reference guide.
Redo writes is the total number of writes by LGWR to the redo log files and it was also consistent throughout the problem period.

Redo Writes

Redo blocks written is the total number of redo blocks written and it is also consistent and hold the same pattern as before the problem period.

Redo Blocks Written

Redo write time is the total elapsed time of the write from the redo log buffer to the current redo log file in 10s of milliseconds. There a increase in redo write time corresponding to log file sync and log file parallel write graphs indicating more time spent on writing redo to log file.

Redo Write Time

Redo wastage is the number of bytes wasted because redo blocks needed to be written before they are completely full. This statistic was also also consistent throughout the problem period.

Redo Wastage

The last is the redo size which is the total amount of redo generated in bytes. This statistics is also an indication of the system load, if there are more DML then amount of redo size would also increase. However in this case the redo size is also consistent throughout the problem period.

Redo Size

Next redo log space and redo log buffer statistics were looked at. Redo buffer allocation retries are the total number of retries necessary to allocate space in the redo buffer. Though there hasn't been any reduction in redo buffer size the amount of redo buffer allocation retries have gone up indicating lgwr is not clearing the log buffer fast enough.

Redo Buffer Allocation Retries

Redo Buffers

Increase in redo log space requests and redo log space wait time indicates that the wait is not memory bound but IO (or disk) bound. Redo log space requests is the number of times the active log file is full and Oracle must wait for disk space to be allocated for the redo log entries. Increase in this means slow IO. Redo log space wait time is the total elapsed waiting time for "redo log space requests" in 10s of milliseconds. Both these statistics have increased in value over the problem period.

Redo Log Space Requests

Redo Log Space Wait Time

Considering all of the above it seems the traffic is the same (system load, redo generation) but some of the lanes (IO bandwidth) "might be" closed. Looking at the IO time on the OS statistics showed a increased IO time which corresponds with log file sync increase. So the assumption that "all else remains the same" may not be correct.

IO Time

Therefore at this point assumption was that cause for increase in these wait events might be due to "something" in the IO sub system rather than the database or application. The system was a two node cluster using a SAN with RAID 5. Both 34583.1 and 34592.1 advise against placing redo logs on RAID 5 but in this case even with RAID 5 the log file *(sync/parallel write) waits were low. So RAID 5 is not the root cause here.
On further investigating the SAN it was discovered the it had two RAID controllers and battery on one of them has failed (thus closing one lane of traffic).

Replacing the dead battery and bringing the RAID controller online (opening up the lane) made the waits to go back to previous level.

Log File Parallel Write

Below is a different system's log file *(sync/parallel write) waits and in this case the increase in waits is caused by a burst of user commits.

Log File Sync

Log File Parallel Write

User Commits

Increase in these two wait events could happen due to user activity as well as due to change in IO related hardware (partial failure as in this case). Having a base line taken when the performance is optimal, to compare with the problem period could help in diagnosing and identifying the reason for the increase.

Useful metalink notes
WAITEVENT: "log file sync" Reference Note [ID 34592.1]
WAITEVENT: "log file parallel write" Reference Note [ID 34583.1]