Investigating the SCN intrinsic growth rate

Investigating the SCN intrinsic growth rate

Published on: Category: IT development and operations

Some time ago we had a warning about the intrinsic growth of the SCN (system change number)  in our Oracle 12.2 database alert file. This situation occurred several times within a few weeks.

"Warning: The SCN intrinsic growth rate has been consistently
higher than system default 16384 per sec. for last 60 mins.
Current SCN intrinsic growth rate is 25867 per sec., zas 200fffff!
The Current SCN value is  46747726691, SCN Compat value is 1"

My initial reaction was that SCNs are related to commits. So the load on the database was just very high, or the application logic should be changed. Maybe a commit was done after every update, instead of using batch commits.

But it was a little more complicated than I expected. Where to look when you want to find the relation between SCNs and commits? And how serious is this warning anyway? This blog is mainly about the various ways I used to investigate this problem and identify the potential impact.

Oracle Support notes

The first place to look for information about warnings in the alert file is the Oracle Support website. I found several related notes:

  • ORA-19706 and Related Alert Log Messages (Doc ID 1393360.1)
    The note suggests that this actual message is specific to database version 12.2, but in older versions we might have similar warnings like “Warning: The SCN headroom for this database is only NN days!”

    If you encounter an alert log message like any of the entries you are advised to follow the instructions in ID 1388639.1 to log a Service Request with Oracle support.
     
  • Evidence to collect when reporting "high SCN rate" issues to Oracle Support (Doc ID 1388639.1)
    This note has information on what information you should deliver when logging a service request.
     
  • System Change Number (SCN), Headroom, Security and Patch Information (Doc ID 1376995.1)
    This note gives more information about the usage of the SCN. The system change number (SCN) is a logical, internal timestamp used by the Oracle Database. SCNs order events that occur within the database. The database uses SCNs to query and track changes. When a transaction commits, the database records a SCN for this commit.

    There is an upper limit to how many SCNs an Oracle Database can use. The limit is currently 281 trillion (2^48) SCN values.

    Given that there is an upper limit, it is important that any given Oracle Database does not run out of available SCNs.

    The note also explains when the warning is raised. The Oracle Database calculates a "not to exceed" limit for the number of SCNs a database can have used, based on the number of seconds since 1988 multiplied by 16384. Doing this ensures that Oracle Databases will ration SCNs over time.

How serious is this warning?

The warning is raised at a rate of 2^14 = 16384 SCNs per second for the last 60 minutes.
The maximum SCN is 2^48 = 281.474.976.710.656.

At a rate of 16348 SCNs per second, we will have 2^(48-14) seconds, or 544 years to reach that maximum. That should be enough in a normal situation.

But the upper limit of 2^48 is only the maximum absolute value the database can store. The limit is also related to the number of seconds since 1988. The limit of 2^48 is the maximum in the year 2532 (1988+544). But in 2018 the maximum is (2018-1988)*365*24*60*60*2^14 = 1.550.057.472.000.

The warning is not something that should be ignored. When you reach the limit you will get ora-600 [2252] errors, and when reaching the absolute upper limit SCN the database will just stop working.

The good news is that in our situation the warning was that the SCN growth rate was 25867 per second in that specific hour, so in that hour we came a little closer (25867-16384=9483) to the limit. We don’t come closer to the limit in every hour, the normal growth rate is lower than 16384.

Oracle Support

We raised a call with Oracle Support. At the moment Oracle Development is working at this issue.

Oracle Support confirmed that the SCN headroom looks good. Based on AWR report, Oracle Support noticed a high number of commits, and suggested to check with application team to commit by increasing the transaction size.

Investigation with AWR

The warning in the alert file told us the SCN intrinsic growth rate has been consistently higher than system default 16384 per second for last 60 mins. If we are looking at a time frame from an hour, an AWR report might be a good place to start. We have AWR configured to make snapshots very hour.

In the AWR report I noticed the number of user commits was 210 per second. Yes, that is a lot of commits, but not really different from the normal load of this database. And if a commit is related to a SCN, it’s also much lower than 16384 per second.

The AWR report also contained an ADDM finding: Waits on event "log file sync" while performing COMMIT and ROLLBACK operations were consuming significant database time. Investigate application logic for possible reduction in the number of  COMMIT operations by increasing the size of transactions.

This reduction of the commits in the ADDM finding was something that was also suggested by Oracle Support. But from my point of view it wasn’t really that high.

Shorter timeframe

Because the AWR wasn’t really helping me in finding the cause I needed to investigate a shorter timeframe. I wanted to know a more specific timeframe so I could create an ASH report. The default for ASH is 15 minutes.

So, the next challenge was to find the 15 minute timeframe in which the SCN growth rate was the highest.

Doc ID 1388639.1 suggested to query v$archived_log. That view has information about all the log switches on the database, including a timestamp and the SCN. Although it is a way to map timestamps to SCNs, it is not really better than then AWR report. We’re still stuck to random timestamps, in this case the timestamp of the logswitch.

Using the timestamp_to_scn function

A better way is to use the function timestamp_to_scn. This function returns a SCN based on a timestamp, like the current timestamp:

  1. SQL> SELECT timestamp_to_scn(sysdate) FROM dual ;
  2.  
  3. TIMESTAMP_TO_SCN(SYSDATE)
  4. -------------------------
  5. 91903104563
  6.  
  7. SQL>

Next step was to make a list of timestamps, together with the matching SCN, and the matching SCN upper limit, based on the number of seconds since 1988 multiplied by 16,384.

This shows the timestamps and SCNs for the last day:
 

  1. SELECT sysdate - (rownum/24) datetimestamp
  2. , timestamp_to_scn(sysdate - (rownum/24)) SCN
  3. , ((sysdate - (rownum/24)) - to_date('01-01-1988','DD-MM-YYYY' ))
  4. * 24 * 60 * 60 * 16384 upper_lmt
  5. FROM dual
  6. CONNECT BY rownum <= 24
  7. /
  1. DATETIMESTAMP SCN UPPER_LMT
  2. ------------------- -------------------- --------------------
  3. 09-07-2018-13:23:39 95423916508 15780233527296
  4. 09-07-2018-12:23:39 95380086165 15780174544896
  5. 09-07-2018-11:23:39 95338871931 15780115562496
  6. 09-07-2018-10:23:39 95303437600 15780056580096
  7. 09-07-2018-09:23:39 95265573942 15779997597696
  8. 09-07-2018-08:23:39 95226645452 15779938615296
  9. 09-07-2018-07:23:39 95186822906 15779879632896
  10. 09-07-2018-06:23:39 95147382509 15779820650496
  11. 09-07-2018-05:23:39 95115474008 15779761668096
  12. 09-07-2018-04:23:39 95079712219 15779702685696
  13. 09-07-2018-03:23:39 95041469231 15779643703296
  14. 09-07-2018-02:23:39 95006499794 15779584720896
  15. 09-07-2018-01:23:39 94975060529 15779525738496
  16. 09-07-2018-00:23:39 94945771055 15779466756096
  17. 08-07-2018-23:23:39 94907451372 15779407773696
  18. 08-07-2018-22:23:39 94875158341 15779348791296
  19. 08-07-2018-21:23:39 94838756696 15779289808896
  20. 08-07-2018-20:23:39 94800190958 15779230826496
  21. 08-07-2018-19:23:39 94757984611 15779171844096
  22. 08-07-2018-18:23:39 94724548846 15779112861696
  23. 08-07-2018-17:23:39 94685506947 15779053879296
  24. 08-07-2018-16:23:39 94646644945 15778994896896
  25. 08-07-2018-15:23:39 94605003069 15778935914496
  26. 08-07-2018-14:23:39 94572205685 15778876932096
  27.  
  28. 24 rows selected.

The current SCN is about 0,57% of the current upper limit.

Finding the top SCN rate

Based on this idea I created a query that gives me the 15 minute timeframe with highest growth in SCNs in the last 3 days.

Every minute a new timeframe starts, and because we have 1440 minutes in a days, we have 4320 timeframes to investigate. For each of them we have to calculate the growth of the SCN within that 15 minute timeframe.

We only want to show the top results, in this case only the timeframes with a rate of over 14000 per second.

  1. ALTER SESSION SET nls_date_format='MM/DD/YY HH24:MI' ;
  2.  
  3. WITH datelist AS
  4. ( SELECT sysdate - (rownum/1440) - (15/1440) starttime -- 15 minute interval
  5. , sysdate - (rownum/1440) endtime
  6. FROM dual
  7. CONNECT BY rownum <= (3*1440) -- 3 days history
  8. )
  9. SELECT starttime
  10. , endtime
  11. , timestamp_to_scn(endtime) - timestamp_to_scn(starttime) scngrowth
  12. , round((timestamp_to_scn(endtime) - timestamp_to_scn(starttime)) /
  13. (((24*60*60)*(endtime-starttime )))) scnrate
  14. FROM datelist
  15. WHERE round((timestamp_to_scn(endtime) - timestamp_to_scn(starttime)) /
  16. (((24*60*60)*(endtime-starttime )))) >= 14000
  17. ORDER BY 4 DESC
  18. /
  1. STARTTIME ENDTIME SCNGROWTH SCNRATE
  2. -------------- -------------- -------------------- --------------------
  3. 07/06/18 18:09 07/06/18 18:24 12761928 14180
  4. 07/07/18 05:20 07/07/18 05:35 12742537 14158
  5. 07/09/18 13:59 07/09/18 14:14 12705077 14117
  6. 07/09/18 12:57 07/09/18 13:12 12672507 14081
  7. 07/09/18 07:06 07/09/18 07:21 12654287 14060

So, now we have found the (sometimes overlapping) 15 minute time frames with the highest SCN rate (SCN growth per second) for the last 3 days. And even in those time frames the SCN rate is still under 16384. No warnings in the alert file this week….

Running the ASH report

The date format I used in the query above is the same as used by the ASH report, so you can just copy/paste the start time. For the duration we enter 15 minutes.

  1. SQL> @@$ORACLE_HOME/rdbms/admin/ashrpt.sql
  2.  
  3. ASH Samples IN this Workload Repository schema
  4. ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
  5.  
  6. Oldest ASH sample available: 01-Jul-18 00:00:01 [ 12379 mins IN the past]
  7. Latest ASH sample available: 09-Jul-18 14:18:58 [ 0 mins IN the past]
  8.  
  9.  
  10. Specify the timeframe TO generate the ASH report
  11. ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
  12. Enter BEGIN TIME FOR report:
  13.  
  14. -- Valid input formats:
  15. -- To specify absolute begin time:
  16. -- [MM/DD[/YY]] HH24:MI[:SS]
  17. -- Examples: 02/23/03 14:30:15
  18. -- 02/23 14:30:15
  19. -- 14:30:15
  20. -- 14:30
  21. -- To specify relative begin time: (start with '-' sign)
  22. -- -[HH24:]MI
  23. -- Examples: -1:15 (SYSDATE - 1 Hr 15 Mins)
  24. -- -25 (SYSDATE - 25 Mins)
  25.  
  26. Defaults TO -15 mins
  27. Enter VALUE FOR begin_time: 07/06/18 18:09
  28. Report BEGIN TIME specified: 07/06/18 18:09
  29.  
  30. Enter duration IN minutes starting FROM BEGIN TIME:
  31. Defaults TO SYSDATE - begin_time
  32. Press Enter TO analyze till CURRENT TIME
  33. Enter VALUE FOR duration: 15
  34. Report duration specified: 15
  35.  
  36. USING 06-Jul-18 18:09:00 AS report BEGIN TIME
  37. USING 06-Jul-18 18:24:00 AS report END TIME
  38.  
  39. Specify the Report Name
  40. ~~~~~~~~~~~~~~~~~~~~~~~
  41. The DEFAULT report file name IS ashrpt_1_0706_1824.html. TO USE this name,
  42. press <return> TO continue, otherwise enter an alternative.
  43. Enter VALUE FOR report_name:
  44.  
  45. USING the report name ashrpt_1_0706_1824.html
  46.  
  47. Summary OF ALL USER INPUT
  48. -------------------------
  49. Format : HTML
  50. DB Id : 2019395491
  51. Inst num : 1
  52. BEGIN TIME : 06-Jul-18 18:09:00
  53. END TIME : 06-Jul-18 18:24:00
  54. Slot width : DEFAULT
  55. Report targets : 0
  56. Report name : ashrpt_1_0706_1824.html

Finding SCN in AWR

The AWR report didn’t show us much information about the current SCN, but it has some information about the growth rate, if you know where to find it.

Under “Instance Activity Stats” you can find the number of “calls to kcmgas”. In the Oracle documentation this is described as the “Number of calls to routine kcmgas to get a new SCN”.

The value of these calls per second in the AWR report is very close to the SCN rate as calculated with the timestamp_to_scn function.

V$SESSTAT view

The number of “calls to kcmgas” used to create a new SCN can also be found in the views V$SESSTAT and V$SYSSTAT.

We can use V$SESSTAT to find the sessions that cause a high SCN rate. We can also test the impact on the SCN number of specific actions.

For example, when I do a select on a big table that’s also in use by other sessions, my session will do another 7 calls to kcmgas. So, my query will cause a higher SCN. This is caused by the read consistency of the database, that also uses a SCN.

  1. SQL> CONNECT <user>/<pass>@<service>
  2. Connected.
  3. SQL> SELECT ses.value
  4. FROM v$sesstat ses
  5. , v$statname stat
  6. WHERE stat.statistic#=ses.statistic#
  7. AND ses.sid IN (SELECT sid FROM v$mystat)
  8. AND stat.name = 'calls to kcmgas'
  9. /
  10.  
  11. VALUE
  12. --------------------
  13. 2
  14.  
  15. SQL> SELECT COUNT(*) FROM mybigtable ;
  16.  
  17. COUNT(*)
  18. --------------------
  19. 12198814
  20.  
  21. SQL> SELECT ses.value
  22. FROM v$sesstat ses
  23. , v$statname stat
  24. WHERE stat.statistic#=ses.statistic#
  25. AND ses.sid IN (SELECT sid FROM v$mystat)
  26. AND stat.name = 'calls to kcmgas'
  27. /
  28.  
  29. VALUE
  30. --------------------
  31. 9
  32.  
  33. SQL>

Comparing the SCN and commit rate

With V$SESSTAT we can query the statistics for all sessions currently connected to the database. In this way we can find sessions that are responsible for a high SCN rate. We can compare this to the commit rate for that session.

The results of the query below showed us that on our database the high SCN rate was mainly caused by background processes. For most user sessions there is a relation between a high SCN rate and a high commit rate, for background sessions the commit rate is always empty.

  1. SELECT ses.sid
  2. , decode(ses.username ,NULL,'background','user' ) session_type
  3. , (sysdate - logon_time) * 24 * 60 * 60 connect_seconds
  4. , sstat1.value SCN#
  5. , sstat2.value COMMIT#
  6. , round(sstat1.value / ((sysdate - logon_time ) * 24 * 60 * 60),2) scn_rate
  7. , round(sstat2.value / ((sysdate - logon_time ) * 24 * 60 * 60),2) commit_rate
  8. FROM v$sesstat sstat1
  9. , v$sesstat sstat2
  10. , v$statname sn1
  11. , v$statname sn2
  12. , v$session ses
  13. WHERE sstat1.statistic# = sn1.statistic#
  14. AND sstat2.statistic# = sn2.statistic#
  15. AND sn1.name = 'calls to kcmgas'
  16. AND sn2.name = 'user commits'
  17. AND ses.sid = sstat1.sid
  18. AND ses.sid = sstat2.sid
  19. ORDER BY 6 DESC
  20. /
  21.  
  22. SID SESSION_TY CONNECT_SECONDS SCN# COMMIT# SCN_RATE COMMIT_RATE
  23. ---------- ---------- --------------- ---------- ---------- ---------- -----------
  24. 8478 background 459572 214506344 0 466.75 0
  25. 7551 background 452395 209729934 0 463.6 0
  26. 3776 background 290389 133863489 0 460.98 0
  27. 8496 background 121201 55685740 0 459.45 0
  28. 8729 background 286773 128180386 0 446.98 0
  29. 12009 background 290392 128867329 0 443.77 0
  30. 13173 background 196775 87268032 0 443.49 0
  31. 12004 background 103166 45681480 0 442.8 0
  32. 8735 background 275980 121563094 0 440.48 0
  33. 3096 background 430810 185436599 0 430.44 0
  34. 8027 background 95990 40912187 0 426.21 0
  35. 7529 background 193218 81367643 0 421.12 0
  36. 2370 background 527978 219521415 0 415.78 0
  37. 14604 background 283216 117052382 0 413.3 0
  38. 14132 background 113965 46586388 0 408.78 0
  39. 7552 background 294009 119775077 0 407.39 0
  40. 13172 background 182423 73865595 0 404.91 0
  41. 14592 background 74414 29767705 0 400.03 0
  42. 3802 background 268804 107486102 0 399.87 0
  43. 9910 background 117582 46596720 0 396.29 0
  44. 12021 background 49182 19321676 0 392.86 0
  45. 974 background 160816 59996495 0 373.08 0
  46. 12723 background 74450 25455559 0 341.91 0
  47. 3310 background 193215 65915175 0 341.15 0
  48. 12963 background 49179 15687084 0 318.98 0
  49. 6111 background 3584090 1031139557 0 287.7 0
  50. 6829 USER 303 1267 1123 4.18 3.71
  51. 9665 USER 904 1845 1691 2.04 1.87
  52. 8022 USER 898 1677 1520 1.87 1.69
  53. 3323 USER 898 1406 1260 1.57 1.4
  54. 2839 USER 7503 10822 9813 1.44 1.31
  55. 11060 USER 3892 5334 4781 1.37 1.23
  56. 13184 USER 1765 2359 2038 1.34 1.15
  57. 9199 USER 898 1135 935 1.26 1.04
  58. 2130 USER 8105 9548 8518 1.18 1.05
  59. 11525 USER 898 1054 944 1.17 1.05
  60. 6130 USER 3895 4453 4199 1.14 1.08
  61. 8012 USER 7503 8576 7774 1.14 1.04
  62. 4497 USER 898 962 882 1.07 .98
  63. 5201 USER 7220 7551 6226 1.05 .86
  64. 11317 USER 12906 13371 11997 1.04 .93
  65.  
  66. [...]
  67. 1979 ROWS selected.

Conclusion

Be aware that there are limits to the SCN, so when you find warnings in the alert file, you need to investigate the problem. If you find an issue you should work with Oracle Support. By uploading information they can check if there is enough room between the current and maximum SCN.

Problems can be caused by a bug, like 12371955: Hot Backup can cause increased SCN growth rate leading to ORA-600 [2252] errors (Doc ID 12371955.8).

If you want to find the exact moment there is a high growth of SCNs you need to convert timestamps to SCNs. You get the best results using the functions SCN_TO_TIMESTAMP and TIMESTAMP_TO_SCN.

A high commit rate is always related to user processes, but SCNs are also related to background processes. Even sessions that don’t commit can have an impact on the SCN.

Bastiaan Bak
About the author Bastiaan Bak

DBA with over 15 years of experience. Experience in various branches, with several modules. Including: Oracle database, Oracle RAC, Oracle EBS and PL/SQL.

More posts by Bastiaan Bak
Comments
Reply