4 Replies Latest reply: Nov 3, 2007 8:12 AM by Jonathan Lewis RSS

    deferred (CURRENT) block cleanout

    LEARNING_ORACLE
      Hi,

      My statspack report is showing following deferred (CURRENT) block cleanout but I dont understand what this event is for.

      Can any one explan.




      Load Profile
      ~~~~~~~~~~~~ Per Second Per Transaction
      --------------- ---------------
      Redo size: 1,777,820.76 74,607.12
      Logical reads: 302,410.22 12,690.79
      Block changes: 7,934.31 332.97
      Physical reads: 612.85 25.72
      Physical writes: 304.10 12.76
      User calls: 404.57 16.98
      Parses: 140.56 5.90
      Hard parses: 5.22 0.22
      Sorts: 101.99 4.28
      Logons: 1.07 0.04
      Executes: 4,689.26 196.79
      Transactions: 23.83

      % Blocks changed per Read: 2.62 Recursive Call %: 93.86
      Rollback per transaction %: 3.91 Rows per Sort: 527.88

      Instance Efficiency Percentages (Target 100%)
      ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
      Buffer Nowait %: 100.00 Redo NoWait %: 100.00
      Buffer Hit %: 99.82 In-memory Sort %: 100.00
      Library Hit %: 99.80 Soft Parse %: 96.28
      Execute to Parse %: 97.00 Latch Hit %: 99.94
      Parse CPU to Parse Elapsd %: 90.41 % Non-Parse CPU: 99.38

      Shared Pool Statistics Begin End
      ------ ------
      Memory Usage %: 75.22 78.62
      % SQL with executions>1: 57.57 10.43
      % Memory for SQL w/exec>1: 40.08 23.16

      Top 5 Timed Events
      ~~~~~~~~~~~~~~~~~~ % Total
      Event Waits Time (s) Ela Time
      -------------------------------------------- ------------ ----------- --------
      CPU time 27,357 65.41
      db file sequential read 1,631,469 5,374 12.85
      PL/SQL lock timer 59 3,067 7.33
      db file scattered read 926,620 3,021 7.22
      ARCH wait on SENDREQ 31,767 896 2.14
      -------------------------------------------------------------
      Wait Events for DB:
      -> s - second
      -> cs - centisecond - 100th of a second
      -> ms - millisecond - 1000th of a second
      -> us - microsecond - 1000000th of a second
      -> ordered by wait time desc, waits desc (idle events last)

      Avg
      Total Wait wait Waits
      Event Waits Timeouts Time (s) (ms) /txn
      ---------------------------- ------------ ---------- ---------- ------ --------
      db file sequential read 1,631,469 0 5,374 3 3.9
      PL/SQL lock timer 59 59 3,067 51980 0.0
      db file scattered read 926,620 0 3,021 3 2.2
      ARCH wait on SENDREQ 31,767 0 896 28 0.1
      log file parallel write 455,833 0 497 1 1.1
      log file sync 350,666 2 292 1 0.8
      log file sequential read 31,827 0 279 9 0.1
      buffer busy waits 64,462 11 239 4 0.2
      log file switch (checkpoint 369 167 221 600 0.0
      enqueue 629 39 138 219 0.0
      local write wait 445 62 75 170 0.0
      SQL*Net more data to client 2,648,440 0 61 0 6.3
      control file sequential read 139,776 0 48 0 0.3
      latch free 46,477 14,278 48 1 0.1
      log file switch completion 1,194 21 40 34 0.0
      process startup 213 0 38 177 0.0
      SQL*Net break/reset to clien 710 0 28 40 0.0
      control file parallel write 11,478 0 11 1 0.0
      log buffer space 83 1 4 47 0.0
      library cache pin 45 0 1 31 0.0
      direct path read 187,714 0 0 0 0.4
      direct path write 103,520 0 0 0 0.2
      db file parallel read 27 0 0 16 0.0
      db file parallel write 12,184 0 0 0 0.0
      LGWR wait for redo copy 7,998 1 0 0 0.0
      async disk IO 59,637 0 0 0 0.1
      log file single write 618 0 0 0 0.0
      row cache lock 28 0 0 3 0.0
      library cache load lock 8 0 0 5 0.0
      undo segment extension 15,917 15,878 0 0 0.0
      buffer deadlock 548 548 0 0 0.0
      SQL*Net message from client 5,067,429 0 737,649 146 12.1
      jobq slave wait 7,530 7,336 21,971 2918 0.0
      SQL*Net more data from clien 386,335 0 31 0 0.9
      SQL*Net message to client 5,067,477 0 7 0 12.1
      -------------------------------------------------------------
      Background Wait Events for DB:
      -> ordered by wait time desc, waits desc (idle events last)

      Avg
      Total Wait wait Waits
      Event Waits Timeouts Time (s) (ms) /txn
      ---------------------------- ------------ ---------- ---------- ------ --------
      ARCH wait on SENDREQ 31,767 0 896 28 0.1
      log file parallel write 455,835 0 497 1 1.1
      log file sequential read 31,827 0 279 9 0.1
      control file sequential read 137,603 0 47 0 0.3
      control file parallel write 11,475 0 11 1 0.0
      log buffer space 17 0 1 84 0.0
      db file scattered read 136 0 1 10 0.0
      enqueue 54 0 1 19 0.0
      db file sequential read 86 0 1 7 0.0
      rdbms ipc reply 2,192 0 1 0 0.0
      db file parallel write 12,184 0 0 0 0.0
      LGWR wait for redo copy 7,998 1 0 0 0.0
      async disk IO 59,637 0 0 0 0.1
      log file single write 618 0 0 0 0.0
      latch free 253 25 0 1 0.0
      buffer busy waits 225 0 0 0 0.0
      direct path read 10,472 0 0 0 0.0
      direct path write 10,472 0 0 0 0.0
      rdbms ipc message 571,199 16,499 196,632 344 1.4
      pmon timer 5,916 5,836 17,146 2898 0.0
      smon timer 669 0 17,094 25551 0.0
      -------------------------------------------------------------
      SQL ordered by Gets for DB:
      -> End Buffer Gets Threshold: 10000
      -> Note that resources reported for PL/SQL includes the resources used by
      all SQL statements called within the PL/SQL code. As individual SQL
      statements are also reported, it is possible and valid for the summed
      total % to exceed 100

      Instance Activity Stats for DB:

      Statistic Total per Second per Trans
      --------------------------------- ------------------ -------------- ------------
      CPU used by this session 2,735,663 155.7 6.5
      CPU used when call started 2,251,064 128.2 5.4
      CR blocks created 1,159,055 66.0 2.8
      Cached Commit SCN referenced 6,362,600 362.2 15.2
      Commit SCN cached 266 0.0 0.0
      DBWR buffers scanned 2,986,958 170.0 7.1
      DBWR checkpoint buffers written 3,121,667 177.7 7.5
      DBWR checkpoints 312 0.0 0.0
      DBWR free buffers found 2,652,625 151.0 6.3
      DBWR lru scans 6,574 0.4 0.0
      DBWR make free requests 10,260 0.6 0.0
      DBWR revisited being-written buff 3 0.0 0.0
      DBWR summed scan depth 2,986,958 170.0 7.1
      DBWR transaction table writes 2,455 0.1 0.0
      DBWR undo block writes 895,360 51.0 2.1
      OS Involuntary context switches 0 0.0 0.0
      OS Page faults 0 0.0 0.0
      OS Page reclaims 0 0.0 0.0
      OS System time used 0 0.0 0.0
      OS User time used 0 0.0 0.0
      OS Voluntary context switches 0 0.0 0.0
      Parallel operations downgraded to 0 0.0 0.0
      SQL*Net roundtrips to/from client 5,012,671 285.4 12.0
      active txn count during cleanout 1,588,954 90.5 3.8
      background checkpoints completed 309 0.0 0.0
      background checkpoints started 309 0.0 0.0
      background timeouts 21,314 1.2 0.1
      branch node splits 290 0.0 0.0
      buffer is not pinned count 4,335,674,710 246,822.0 10,358.0
      buffer is pinned count 6,234,655,659 354,927.5 14,894.7
      bytes received via SQL*Net from c 6,984,841,612 397,634.2 16,686.9
      bytes sent via SQL*Net to client 6,842,372,166 389,523.6 16,346.6
      calls to get snapshot scn: kcmgss 101,962,373 5,804.5 243.6
      calls to kcmgas 2,773,369 157.9 6.6
      calls to kcmgcs 320,699 18.3 0.8
      change write time 34,824 2.0 0.1
      cleanout - number of ktugct calls 1,695,395 96.5 4.1
      cleanouts and rollbacks - consist 1,073,360 61.1 2.6
      cleanouts only - consistent read 67,598 3.9 0.2
      cluster key scan block gets 225,433 12.8 0.5
      cluster key scans 109,148 6.2 0.3
      commit cleanout failures: block l 1,768 0.1 0.0
      commit cleanout failures: buffer 26,766 1.5 0.1
      commit cleanout failures: callbac 1,767 0.1 0.0
      commit cleanout failures: cannot 161 0.0 0.0
      commit cleanouts 4,248,953 241.9 10.2
      commit cleanouts successfully com 4,218,491 240.2 10.1
      commit txn count during cleanout 331,513 18.9 0.8
      consistent changes 370,514,284 21,092.7 885.2
      consistent gets 5,154,868,696 293,457.2 12,315.1
      consistent gets - examination 4,070,961,740 231,752.4 9,725.6
      current blocks converted for CR 1,246 0.1 0.0
      cursor authentications 5,177 0.3 0.0
      data blocks consistent reads - un 370,495,603 21,091.6 885.1
      db block changes 139,374,164 7,934.3 333.0
      db block gets 157,332,412 8,956.6 375.9
      Instance Activity Stats for DB:

      Statistic Total per Second per Trans
      --------------------------------- ------------------ -------------- ------------
      deferred (CURRENT) block cleanout 2,255,479 128.4 5.4
      dirty buffers inspected 57,293 3.3 0.1
      enqueue conversions 1,681 0.1 0.0
      enqueue deadlocks 0 0.0 0.0
      enqueue releases 2,052,166 116.8 4.9
      enqueue requests 2,052,330 116.8 4.9
      enqueue timeouts 175 0.0 0.0
      enqueue waits 453 0.0 0.0
      exchange deadlocks 548 0.0 0.0
      execute count 82,371,601 4,689.3 196.8
      free buffer inspected 91,172 5.2 0.2
      free buffer requested 12,602,651 717.5 30.1
      hot buffers moved to head of LRU 1,594,202 90.8 3.8
      immediate (CR) block cleanout app 1,140,958 65.0 2.7
      immediate (CURRENT) block cleanou 1,014,568 57.8 2.4
      index fast full scans (full) 228,929 13.0 0.6
      index fetch by key 1,721,496,074 98,001.6 4,112.7
      index scans kdiixs1 261,286,766 14,874.6 624.2
      leaf node 90-10 splits 10,907 0.6 0.0
      leaf node splits 163,066 9.3 0.4
      logons cumulative 18,765 1.1 0.0
      messages received 480,257 27.3 1.2
      messages sent 480,257 27.3 1.2
      no buffer to keep pinned count 0 0.0 0.0
      no work - consistent read gets 849,970,495 48,387.3 2,030.6
      opened cursors cumulative 2,438,475 138.8 5.8
      parse count (failures) 59 0.0 0.0
      parse count (hard) 91,782 5.2 0.2
      parse count (total) 2,469,137 140.6 5.9
      parse time cpu 16,894 1.0 0.0
      parse time elapsed 18,687 1.1 0.0
      physical reads 10,765,347 612.9 25.7
      physical reads direct 1,348,027 76.7 3.2
      physical reads direct (lob) 0 0.0 0.0
      physical writes 5,341,877 304.1 12.8
      physical writes direct 1,824,636 103.9 4.4
      physical writes non checkpoint 3,484,780 198.4 8.3
      pinned buffers inspected 30 0.0 0.0
      prefetched blocks 6,859,211 390.5 16.4
      prefetched blocks aged out before 37,671 2.1 0.1
      process last non-idle time 17,565 1.0 0.0
      recursive calls 108,579,088 6,181.2 259.4
      recursive cpu usage 2,436,167 138.7 5.8
      redo blocks written 63,205,732 3,598.2 151.0
      redo buffer allocation retries 1,086 0.1 0.0
      redo entries 70,732,252 4,026.7 169.0
      redo log space requests 1,649 0.1 0.0
      redo log space wait time 26,772 1.5 0.1
      redo ordering marks 11,394 0.7 0.0
      redo size 31,229,199,536 1,777,820.8 74,607.1
      redo synch time 30,135 1.7 0.1
      redo synch writes 352,143 20.1 0.8
      redo wastage 116,861,368 6,652.7 279.2
      redo write time 51,151 2.9 0.1
      redo writer latching time 35 0.0 0.0
      redo writes 455,842 26.0 1.1
      Instance Activity Stats for DB:

      Statistic Total per Second per Trans
      --------------------------------- ------------------ -------------- ------------
      rollback changes - undo records a 19,834 1.1 0.1
      rollbacks only - consistent read 87,233 5.0 0.2
      rows fetched via callback 1,697,733,524 96,648.8 4,055.9
      session connect time 0 0.0 0.0
      session cursor cache count 1,260 0.1 0.0
      session cursor cache hits 1,893,895 107.8 4.5
      session logical reads 5,312,137,841 302,410.2 12,690.8
      session pga memory 1,143,956,712 65,123.4 2,732.9
      session pga memory max 2,275,628,984 129,547.4 5,436.5
      session uga memory 159,198,924,544 9,062,901.3 380,329.1
      session uga memory max 15,827,255,904 901,016.5 37,811.6
      shared hash latch upgrades - no w 212,980,657 12,124.6 508.8
      shared hash latch upgrades - wait 3,194 0.2 0.0
      sorts (disk) 64 0.0 0.0
      sorts (memory) 1,791,559 102.0 4.3
      sorts (rows) 945,769,170 53,840.9 2,259.5
      summed dirty queue length 937,561 53.4 2.2
      switch current to new buffer 801,070 45.6 1.9
      table fetch by rowid 4,239,050,900 241,321.4 10,127.2
      table fetch continued row 4,406,497 250.9 10.5
      table scan blocks gotten 181,682,958 10,342.9 434.0
      table scan rows gotten 14,670,091,608 835,141.3 35,047.1
      table scans (cache partitions) 0 0.0 0.0
      table scans (direct read) 34 0.0 0.0
      table scans (long tables) 1,457 0.1 0.0
      table scans (short tables) 9,314,629 530.3 22.3
      transaction rollbacks 8,211 0.5 0.0
      transaction tables consistent rea 29 0.0 0.0
      transaction tables consistent rea 16,420 0.9 0.0
      user calls 7,106,602 404.6 17.0
      user commits 402,195 22.9 1.0
      user rollbacks 16,387 0.9 0.0
      workarea executions - multipass 0 0.0 0.0
      workarea executions - onepass 329 0.0 0.0
      workarea executions - optimal 1,935,028 110.2 4.6
      write clones created in backgroun 36 0.0 0.0
      write clones created in foregroun 181,911 10.4 0.4
      -------------------------------------------------------------


      Thanks in advance
      MMU
        • 1. Re: deferred (CURRENT) block cleanout
          damorgan
          Oracle is very lazy.

          Jonathan Lewis discusses deferred block cleanout in his book and on his website.

          http://www.jlcomp.demon.co.uk/faq/ind_faq.html
          • 2. Re: deferred (CURRENT) block cleanout
            108476
            Hi,

            First, paste-in your statspack report in this tool and see the rport, which may help:

            http://www.statspackanalyzer.com
            deferred (CURRENT) block cleanout but I dont understand what this event is for.
            The commit cleanouts successfully completed Oracle metric is the number of times the cleanout block at commit time function successfully completed.

            Steve Adams notes:

            "Oracle's row-level locking mechanism maintains transaction and row lock information together with the data in the data blocks. After a transaction has committed, that row-level locking information can be cleaned out.
            The cleanout can be delayed indefinitely, but it is most efficient if it is done at commit time. Therefore, when a transaction commits, it revisits the blocks that it has modified most recently and attempts to clean out its row-level locking information in those blocks. This commit cleanout is limited to 10% of the cache and is subject to numerous restrictions. In particular, the blocks must not yet have been written to disk by DBWn or modified by another transaction.

            While commit cleanouts are more efficient than delayed block cleanouts, their cost in terms of CPU usage and buffer cache concurrency control is far from trivial. If frequent commits cause the same blocks to be cleaned out repeatedly by the commit cleanout mechanism, then the total cost of the commit cleanouts can easily exceed the cost of equivalent delayed block cleanouts.

            In the 1,000 row test above we used PL/SQL to avoid extra log file sync delays, and an otherwise idle system to avoid redo allocation latch contention. Thus much of the delay observed in that test was due to the CPU cost of additional commit cleanout activity."

            The Oracle Documents also note that in Oracle 10g, the commit cleanouts successfully completed metric is stored in "V$SESSTAT and V$SYSSTAT views"


            Hope this helps. . .

            Don Burleson
            Oracle Press author
            Author of “Oracle Tuning: The Definitive Reference”
            http://www.dba-oracle.com/bp/s_oracle_tuning_book.htm
            • 3. Re: deferred (CURRENT) block cleanout
              400137
              If you have Metalink access, refer to Note#40689.1

              It is very well explained. There is an example that will help you to better understand block cleanout.
              • 4. Re: deferred (CURRENT) block cleanout
                Jonathan Lewis
                Hi,

                First, paste-in your statspack report in this tool
                and see the report, which may help:

                http://www.statspackanalyzer.com
                deferred (CURRENT) block cleanout but I dont
                understand what this event is for.


                The commit cleanouts successfully completed Oracle
                metric is the number of times the cleanout block at
                commit time function successfully completed.

                Steve Adams notes:

                ... (explanation of commit cleanout removed)

                Hope this helps. . .

                Don Burleson
                Oracle Press author
                Author of “Oracle Tuning: The Definitive Reference”
                http://www.dba-oracle.com/bp/s_oracle_tuning_book.htm
                The original question asking specifically about the meaning of the statistic "deferred (CURRENT) block cleanout applications", not about the statistic "commit cleanouts successfully completed". Neither Steve's notes, nor your advert for your statspack analyzer seem to be particularly relevant - although Steve's notes do supply some useful background information.

                A "deferred (CURRENT)" cleanout occurs when a DML statement wants to modify the contents of a block and all the available ITLs are showing recent commit cleanouts. The process cleans out the block (incrementing the statistic once) and then uses the ITL slot with the lowest commit SCN.

                There are variations on this basic theme. For example if there are some ITL slots available for use (empty, or showing older, cleaned commits) but the process wants to modify a row that is still marked as locked by a commit cleanout (which don't clear lock bytes), then the process does a full cleanout (again incrementing the statistic) to get the row's lock byte cleared. It won't use the newly cleaned ITL, though if there are more appropriate ITLs (lower commit SCN) available in the block.

                Without careful examination of several associated stats, and a knowledge of what the application is supposed to be doing, it's not really possible to say whether you could (or should) try to do anything about them. They're essentially a side effect of inserting or updating date when you have many rows per block and execute very small transactions - and if they seem to be a significant threat, there's probably something much more important to resolve first.

                For some background reading on commits and ITL states, the article that Daniel Morgan was trying to link to is: http://www.jlcomp.demon.co.uk/cleanout.html

                Regards
                Jonathan Lewis
                http://jonathanlewis.wordpress.com
                http://www.jlcomp.demon.co.uk