Home » RDBMS Server » Performance Tuning » snapshot skipped in between the scheduled time (AWR) (11g, 11.2.0.1, window server 2008)
snapshot skipped in between the scheduled time (AWR) [message #595514] Wed, 11 September 2013 08:11 Go to next message
ishika_20
Messages: 339
Registered: December 2006
Location: delhi
Senior Member
Dear All,

Yesterday, there were performance issue at server. So today, when i am generating report for that particular period, found snapshot id sequence is serially but with skipped hourly timed. Instead of generating report at 15:30, it generated at 16:30.

Enter value for num_days: 2

Listing the last 2 days of Completed Snapshots

                                                        Snap
Instance     DB Name        Snap Id    Snap Started    Level
------------ ------------ --------- ------------------ -----
tagidev      TAGIDEV           2857 10 Sep 2013 00:30      1
                               2858 10 Sep 2013 01:30      1
                               2859 10 Sep 2013 02:30      1
                               2860 10 Sep 2013 03:30      1
                               2861 10 Sep 2013 04:30      1
                               2862 10 Sep 2013 05:31      1
                               2863 10 Sep 2013 06:30      1
                               2864 10 Sep 2013 07:30      1
                               2865 10 Sep 2013 08:30      1
                               2866 10 Sep 2013 09:30      1
                               2867 10 Sep 2013 10:30      1
                               2868 10 Sep 2013 11:30      1
                               2869 10 Sep 2013 12:30      1
                               2870 10 Sep 2013 13:30      1
                               2871 10 Sep 2013 14:30      1

                               2872 10 Sep 2013 16:32      1
                               2873 10 Sep 2013 17:30      1
                               2874 10 Sep 2013 18:30      1
                               2875 10 Sep 2013 19:30      1
                               2876 10 Sep 2013 20:30      1
                               2877 10 Sep 2013 21:30      1

                               2878 11 Sep 2013 10:09      1
                               2879 11 Sep 2013 11:30      1
                               2880 11 Sep 2013 12:30      1
                               2881 11 Sep 2013 13:30      1
                               2882 11 Sep 2013 14:30      1
                               2883 11 Sep 2013 15:30      1



Below are the details at alert log -

Tue Sep 10 14:28:20 2013
Thread 1 cannot allocate new log, sequence 7029
Checkpoint not complete
  Current log# 2 seq# 7028 mem# 0: E:\APP\ORACLE\ORADATA\TAGIDEV\REDO02.LOG
Thread 1 advanced to log sequence 7029 (LGWR switch)
  Current log# 3 seq# 7029 mem# 0: E:\APP\ORACLE\ORADATA\TAGIDEV\REDO03.LOG
Tue Sep 10 14:28:54 2013
Immediate Kill Session#: 451, Serial#: 1870
Immediate Kill Session: sess: 000007FFC4652730  OS pid: 10784
Immediate Kill Session#: 486, Serial#: 470
Immediate Kill Session: sess: 000007FFC45ECDE0  OS pid: 12592
Immediate Kill Session#: 502, Serial#: 246
Immediate Kill Session: sess: 000007FFC45BE6E0  OS pid: 5136
Immediate Kill Session#: 456, Serial#: 338
Immediate Kill Session: sess: 000007FFC4643F00  OS pid: 5608
Immediate Kill Session#: 119, Serial#: 251
Immediate Kill Session: sess: 000007FFC41556B0  OS pid: 4216
Immediate Kill Session#: 42, Serial#: 2765
Immediate Kill Session: sess: 000007FFC4234E60  OS pid: 6488
Immediate Kill Session#: 473, Serial#: 356
Immediate Kill Session: sess: 000007FFC4612990  OS pid: 11908
Immediate Kill Session#: 29, Serial#: 1341
Immediate Kill Session: sess: 000007FFC425AA10  OS pid: 4868
Immediate Kill Session#: 460, Serial#: 1021
Immediate Kill Session: sess: 000007FFC4638540  OS pid: 12184
Tue Sep 10 14:29:08 2013
Thread 1 cannot allocate new log, sequence 7030
Checkpoint not complete
  Current log# 3 seq# 7029 mem# 0: E:\APP\ORACLE\ORADATA\TAGIDEV\REDO03.LOG
Thread 1 advanced to log sequence 7030 (LGWR switch)
  Current log# 1 seq# 7030 mem# 0: E:\APP\ORACLE\ORADATA\TAGIDEV\REDO01.LOG
Tue Sep 10 14:29:35 2013
Thread 1 cannot allocate new log, sequence 7031
Checkpoint not complete
  Current log# 1 seq# 7030 mem# 0: E:\APP\ORACLE\ORADATA\TAGIDEV\REDO01.LOG
Thread 1 advanced to log sequence 7031 (LGWR switch)
  Current log# 2 seq# 7031 mem# 0: E:\APP\ORACLE\ORADATA\TAGIDEV\REDO02.LOG
Tue Sep 10 14:30:25 2013
Thread 1 cannot allocate new log, sequence 7032
Checkpoint not complete
  Current log# 2 seq# 7031 mem# 0: E:\APP\ORACLE\ORADATA\TAGIDEV\REDO02.LOG
Thread 1 advanced to log sequence 7032 (LGWR switch)
  Current log# 3 seq# 7032 mem# 0: E:\APP\ORACLE\ORADATA\TAGIDEV\REDO03.LOG
Tue Sep 10 14:31:02 2013
kewastUnPackStats(): bad magic 1 (0x0000000039099665, 0)
kewastUnPackStats(): bad magic 1 (0x0000000039099665, 0)
kewastUnPackStats(): bad magic 1 (0x000000003909966D, 0)
kewastUnPackStats(): bad magic 1 (0x000000003909966D, 0)
kewastUnPackStats(): bad magic 1 (0x000000003909966D, 0)
kewastUnPackStats(): bad magic 1 (0x000000003909966D, 0)
kewastUnPackStats(): bad magic 1 (0x0000000039099665, 0)
kewastUnPackStats(): bad magic 1 (0x0000000039099665, 0)
Tue Sep 10 14:42:32 2013
Thread 1 advanced to log sequence 7033 (LGWR switch)
  Current log# 1 seq# 7033 mem# 0: E:\APP\ORACLE\ORADATA\TAGIDEV\REDO01.LOG
Tue Sep 10 15:19:22 2013
opidcl aborting process unknown ospid (3644) as a result of ORA-28
Tue Sep 10 15:19:22 2013
opidcl aborting process unknown ospid (1924) as a result of ORA-28
Tue Sep 10 16:17:20 2013
kewastUnPackStats(): bad magic 1 (0x000000001B3CF7DD, 0)
....
....
kewastUnPackStats(): bad magic 1 (0x000000001B3CE475, 0)
Tue Sep 10 15:19:22 2013
opidcl aborting process unknown ospid (6616) as a result of ORA-28
Tue Sep 10 15:19:22 2013
opidcl aborting process unknown ospid (2540) as a result of ORA-28
Tue Sep 10 15:26:21 2013


***********************************************************************
Tue Sep 10 15:13:18 2013


***********************************************************************
Tue Sep 10 15:37:33 2013
kewastUnPackStats(): bad magic 1 (0x000000001A8C5955, 0)
Tue Sep 10 15:19:22 2013
opidcl aborting process unknown ospid (14188) as a result of ORA-28
Tue Sep 10 15:19:22 2013
opidcl aborting process unknown ospid (7224) as a result of ORA-28
Tue Sep 10 15:33:48 2013
opidcl aborting process unknown ospid (12008) as a result of ORA-28
Tue Sep 10 15:42:24 2013
opidcl aborting process unknown ospid (2292) as a result of ORA-28
Tue Sep 10 15:42:24 2013
opidcl aborting process unknown ospid (6228) as a result of ORA-28
Tue Sep 10 16:08:19 2013
Process 0x000007FFC6B6D220 appears to be hung while dumping
Current time = 211426557, process death time = 211365920 interval = 60000
Attempting to kill process 0x000007FFC6B6D220 with OS pid = 11212
Tue Sep 10 16:17:26 2013
AUD: OS Error = 1717 encountered while writing audit record
opidcl aborting process unknown ospid (7196) as a result of ORA-28056
Tue Sep 10 16:17:26 2013
Errors in file e:\app\oracle\diag\rdbms\tagidev\tagidev\trace\tagidev_cjq0_12588.trc:
ORA-27300: OS system dependent operation:SuspendThread failed with status: 5
ORA-27301: OS failure message: Access is denied.
ORA-27302: failure occurred at: sssxcpttcs6
Tue Sep 10 16:17:26 2013
Errors in file e:\app\oracle\diag\rdbms\tagidev\tagidev\trace\tagidev_ora_13308.trc:
OSD-04503: Message 4503 not found; No message file for product=RDBMS, facility=SOSD
Image consistency checking encountered an error, checking disabled
Tue Sep 10 16:17:26 2013
Errors in file e:\app\oracle\diag\rdbms\tagidev\tagidev\trace\tagidev_ora_4984.trc:
OSD-04503: Message 4503 not found; No message file for product=RDBMS, facility=SOSD
Image consistency checking encountered an error, checking disabled
Tue Sep 10 16:17:26 2013
Errors in file e:\app\oracle\diag\rdbms\tagidev\tagidev\trace\tagidev_ora_11064.trc:
OSD-04503: Message 4503 not found; No message file for product=RDBMS, facility=SOSD
Image consistency checking encountered an error, checking disabled
Tue Sep 10 16:17:26 2013
Errors in file e:\app\oracle\diag\rdbms\tagidev\tagidev\trace\tagidev_ora_5096.trc:
OSD-04503: Message 4503 not found; No message file for product=RDBMS, facility=SOSD
Image consistency checking encountered an error, checking disabled
Tue Sep 10 16:17:26 2013
Errors in file e:\app\oracle\diag\rdbms\tagidev\tagidev\trace\tagidev_ora_10600.trc:
OSD-04503: Message 4503 not found; No message file for product=RDBMS, facility=SOSD
Image consistency checking encountered an error, checking disabled
Tue Sep 10 16:17:26 2013
Errors in file e:\app\oracle\diag\rdbms\tagidev\tagidev\trace\tagidev_ora_13560.trc:
OSD-04503: Message 4503 not found; No message file for product=RDBMS, facility=SOSD
Image consistency checking encountered an error, checking disabled
Tue Sep 10 16:17:26 2013
Errors in file e:\app\oracle\diag\rdbms\tagidev\tagidev\trace\tagidev_ora_1124.trc:
OSD-04503: Message 4503 not found; No message file for product=RDBMS, facility=SOSD
Image consistency checking encountered an error, checking disabled
kewastUnPackStats(): bad magic 1 (0x000000001A8C5955, 0)
Tue Sep 10 16:21:17 2013
Starting ORACLE instance (normal)
LICENSE_MAX_SESSION = 0
LICENSE_SESSIONS_WARNING = 0
Picked latch-free SCN scheme 3
Using LOG_ARCHIVE_DEST_1 parameter default value as E:\app\oracle\product\11.2.0\db_1\RDBMS
Autotune of undo retention is turned on. 
IMODE=BR
ILAT =84
Tue Sep 10 16:21:29 2013
LICENSE_MAX_USERS = 0
SYS auditing is disabled
Starting up:
Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options.
Using parameter settings in server-side spfile E:\APP\ORACLE\PRODUCT\11.2.0\DB_1\DATABASE\SPFILETAGIDEV.ORA
System parameters with non-default values:
  processes                = 500
  sessions                 = 772
  nls_date_format          = "dd/MM/yyyy"
  memory_target            = 3216M
  control_files            = "E:\APP\ORACLE\ORADATA\TAGIDEV\CONTROL01.CTL"
  control_files            = "E:\APP\ORACLE\ORADATA\TAGIDEV\CONTROL02.CTL"
  db_block_size            = 8192
  compatible               = "11.2.0.0.0"
  undo_tablespace          = "UNDOTBS1"
  remote_login_passwordfile= "EXCLUSIVE"
  db_domain                = ""
  dispatchers              = "(PROTOCOL=TCP) (SERVICE=TAGIDEVXDB)"
  local_listener           = "(ADDRESS = (PROTOCOL = TCP)(HOST =192.168.30.26)(PORT = 1521))"
  cursor_sharing           = "similar"
  audit_file_dest          = "E:\APP\ORACLE\ADMIN\TAGIDEV\ADUMP"
  audit_trail              = "DB"
  db_name                  = "TAGIDEV"
  open_cursors             = 6000
  diagnostic_dest          = "E:\APP\ORACLE"
Tue Sep 10 16:21:35 2013
PMON started with pid=2, OS id=3192 
Tue Sep 10 16:21:35 2013
VKTM started with pid=3, OS id=3196 at elevated priority
VKTM running at (10)millisec precision with DBRM quantum (100)ms
Tue Sep 10 16:21:35 2013
GEN0 started with pid=4, OS id=3200 
Tue Sep 10 16:21:36 2013
DIAG started with pid=5, OS id=3204 
Tue Sep 10 16:21:36 2013
DBRM started with pid=6, OS id=3208 
Tue Sep 10 16:21:36 2013
PSP0 started with pid=7, OS id=3212 
Tue Sep 10 16:21:36 2013
DIA0 started with pid=8, OS id=3216 
Tue Sep 10 16:21:36 2013
MMAN started with pid=9, OS id=3220 
Tue Sep 10 16:21:36 2013
DBW0 started with pid=10, OS id=3224 
Tue Sep 10 16:21:36 2013
LGWR started with pid=11, OS id=3228 
Tue Sep 10 16:21:36 2013
CKPT started with pid=12, OS id=3232 
Tue Sep 10 16:21:36 2013
SMON started with pid=13, OS id=3236 
Tue Sep 10 16:21:36 2013
RECO started with pid=14, OS id=3240 
Tue Sep 10 16:21:36 2013
MMON started with pid=15, OS id=3244 
starting up 1 dispatcher(s) for network address '(ADDRESS=(PARTIAL=YES)(PROTOCOL=TCP))'...
starting up 1 shared server(s) ...
ORACLE_BASE from environment = E:\app\oracle
Tue Sep 10 16:21:36 2013
MMNL started with pid=16, OS id=3248 
Tue Sep 10 16:21:42 2013
alter database mount exclusive
Tue Sep 10 16:21:49 2013
Successful mount of redo thread 1, with mount id 2075178134
Database mounted in Exclusive Mode
Lost write protection disabled
Tue Sep 10 16:21:52 2013
Completed: alter database mount exclusive
alter database open
Beginning crash recovery of 1 threads
 parallel recovery started with 2 processes
Started redo scan
Completed redo scan
 read 7 KB redo, 14 data blocks need recovery
Started redo application at
 Thread 1: logseq 7033, block 31923
Recovery of Online Redo Log: Thread 1 Group 1 Seq 7033 Reading mem 0
  Mem# 0: E:\APP\ORACLE\ORADATA\TAGIDEV\REDO01.LOG
Completed redo application of 0.00MB
Completed crash recovery at
 Thread 1: logseq 7033, block 31937, scn 8261833345070
 14 data blocks read, 14 data blocks written, 7 redo k-bytes read
Tue Sep 10 16:22:02 2013
Thread 1 advanced to log sequence 7034 (thread open)
Thread 1 opened at log sequence 7034
  Current log# 2 seq# 7034 mem# 0: E:\APP\ORACLE\ORADATA\TAGIDEV\REDO02.LOG
Successful open of redo thread 1
MTTR advisory is disabled because FAST_START_MTTR_TARGET is not set
Tue Sep 10 16:22:02 2013
SMON: enabling cache recovery
Tue Sep 10 16:22:11 2013
Successfully onlined Undo Tablespace 2.
Verifying file header compatibility for 11g tablespace encryption..
Verifying 11g file header compatibility for tablespace encryption completed
SMON: enabling tx recovery
Database Characterset is WE8MSWIN1252
No Resource Manager plan active
replication_dependency_tracking turned off (no async multimaster replication found)
Tue Sep 10 16:22:23 2013
Starting background process QMNC
Tue Sep 10 16:22:23 2013
QMNC started with pid=22, OS id=3092 
Tue Sep 10 16:22:34 2013
Completed: alter database open
Tue Sep 10 16:22:47 2013
Starting background process CJQ0
Tue Sep 10 16:22:47 2013
CJQ0 started with pid=19, OS id=528 
Tue Sep 10 16:29:44 2013
Starting background process SMCO
Tue Sep 10 16:29:45 2013
SMCO started with pid=50, OS id=4484 
Tue Sep 10 16:42:41 2013




Here, i have 2 doubts -
1) why snap didn't started at 15:30?
2) since database just started at the scheduled time of AWR snap time. But generated at 16:32 instead of 16:30, though last services "SMCO" is started at 16:42. How it snap id generated for this particular time?
3) what does "kewastUnPackStats(): bad magic 1 (0x000000001B3CE48D, 0)" mean?

Regards,
Ishika

[Updated on: Wed, 11 September 2013 08:17] by Moderator

Report message to a moderator

Re: snapshot skipped in between the scheduled time (AWR) [message #595515 is a reply to message #595514] Wed, 11 September 2013 08:18 Go to previous messageGo to next message
BlackSwan
Messages: 22786
Registered: January 2009
Senior Member
[oracle@localhost ~]$ oerr ora 28056
28056, 00000, "Writing audit records to Windows Event Log failed"
// *Cause:  Unable to write an audit entry to the Windows event log
//          used as the audit trail.
// *Action: Check the error number for a possible operating system error.
//          If there is no error, contact Oracle Support Services.
Re: snapshot skipped in between the scheduled time (AWR) [message #595517 is a reply to message #595514] Wed, 11 September 2013 08:21 Go to previous messageGo to next message
Mahesh Rajendran
Messages: 10625
Registered: March 2002
Location: oracleDocoVille
Senior Member
Account Moderator
>>3) what does "kewastUnPackStats(): bad magic 1 (0x000000001B3CE48D, 0)" mean?
Known bug.
Check metalink for available patches.
Re: snapshot skipped in between the scheduled time (AWR) [message #595518 is a reply to message #595514] Wed, 11 September 2013 08:30 Go to previous messageGo to next message
John Watson
Messages: 4557
Registered: January 2010
Location: Global Village
Senior Member
Your database is in a very sad state, and rather than trying to fix individual problems I would make some general changes:

Replace your online logfile groups with new groups that are twenty times as big. So if they are currently 50M, replace them with 1G groups.
Truncate your sus.aud$ table. It probably has millions of rows that you never look at.
Adjust cursor_sharing from similar to force. Similar is known to cause problems, you should rely on adaptive cursor sharing instead.
Apply the 11.2.0.3 patchset, 11.2.0.1 is known to have many issues.

Now run your application for a while. I promise you it will run faster and more reliably.
--
update: and, I forgot: delete everything from your Windows event logs.

[Updated on: Wed, 11 September 2013 08:31]

Report message to a moderator

Re: snapshot skipped in between the scheduled time (AWR) [message #595533 is a reply to message #595518] Wed, 11 September 2013 09:28 Go to previous messageGo to next message
Michel Cadot
Messages: 59113
Registered: March 2007
Location: Nanterre, France, http://...
Senior Member
Account Moderator
Quote:
Adjust cursor_sharing from similar to force. Similar is known to cause problems,


And FORCE maybe even more.
There is only one correct value: EXACT.

Regards
Michel
Re: snapshot skipped in between the scheduled time (AWR) [message #595563 is a reply to message #595518] Wed, 11 September 2013 14:26 Go to previous messageGo to next message
Lalit Kumar B
Messages: 2324
Registered: May 2013
Location: World Wide on the Web
Senior Member
Quote:
Adjust cursor_sharing from similar to force. Similar is known to cause problems, you should rely on adaptive cursor sharing instead.


When I read this, the first thing that struck my mind is the T.Kyte's presentation on CURSOR_SHARING. I then experimented in my local environment, and finally got convinced on what he explained(with a set of extremely skewed data and varying literals in the column). I can't explain as beautifully as he did, so here is it
Re: snapshot skipped in between the scheduled time (AWR) [message #595570 is a reply to message #595563] Wed, 11 September 2013 14:46 Go to previous messageGo to next message
Michel Cadot
Messages: 59113
Registered: March 2007
Location: Nanterre, France, http://...
Senior Member
Account Moderator
Tom intentionally left out the bugs issue, it is not his point in this article.
But in the real world, you should fix your application and use cursor_sharing=exact, ALWAYS.
If you don't believe me (and I encourage to), search in MOS database bug for "cursor_sharing force" or "cursor_sharing similar" and you will see the number of returned bugs (the last time I did it, there were too much bugs so they can't be all displayed).

Regards
Michel
Re: snapshot skipped in between the scheduled time (AWR) [message #595844 is a reply to message #595570] Sat, 14 September 2013 10:48 Go to previous message
trantuananh24hg
Messages: 608
Registered: January 2007
Location: Ha Noi, Viet Nam
Senior Member
M.Cadot, Mr! I agree with you!
In fact, we faced to the problem caused direct path from sql literal transforming by java without close cursor. Memory was lack, database not hang but no-more connection was signed up. When I changed the cursor_sharing from SIMILAR to FORCE, the cached buffer chained decreased. Of course, re-write SQL is the best performance tuning, but, indeed, decreasing the lack memory at this time was the good plan.
Previous Topic: Need your help in tuning the query
Next Topic: Howto avoid virtual circuit wait as application developer?
Goto Forum:
  


Current Time: Wed Sep 17 13:07:44 CDT 2014

Total time taken to generate the page: 0.08676 seconds