Sybase log /sybase/SID/ASE-15_0/install

[Former Member]

Hi Experts,

My /sybase/SID/ filesystem is keep on getting fill up with large log files. As for now i zip the log files to save space.

Is there a way to stop this log? any advice will be appreciated.

The log path is /sybase/SID/ASE-15_0/install

These are the logs name & size:

66M     SID.log.20141104_214102

68M     SID.log.20141203_131516

106M    SID.log.20141204_074034

108M    SID.log.20141205_074034

111M    SID.log.20141206_153431

112M    SID.log.20141206_211901

112M    SID.log.20141207_091354

112M    SID.log.20141207_125034

112M    SID.log.20141208_061633

112M    SID.log.20141209_073533

113M    SID.log.20141210_073534

114M    SID.log.20141211_073534

115M    SID.log.20141212_073534

116M    SID.log.20141215_073534

117M    SID.log.20141216_073534

117M    SID.log.20141217_073533

R,

AM

[Former Member]

Hi Mark,

the logs full with this entries. Roll forward transaction '$chained_transaction'.

Seems the log only created during DB startup.

00:0004:00000:00015:2014/12/18 09:36:19.07 server  Database 'saptempdb' is now online.

00:0003:00000:00014:2014/12/18 09:38:51.82 server  Database 'SID', checkpoint=(7373526, 122), first=(7373526, 121), last=(7307817, 65).

00:0003:00000:00014:2014/12/18 09:38:51.82 server  Completed estimating recovery log boundaries for database 'SID'.

00:0003:00000:00014:2014/12/18 09:38:51.82 server  Started ANALYSIS pass for database 'SID'.

00:0002:00000:00014:2014/12/18 09:41:36.49 server  Completed ANALYSIS pass for database 'SID'.

00:0002:00000:00014:2014/12/18 09:41:36.49 server  Log contains all committed transactions until 2014/12/18 03:55:02.67 for database SID.

00:0002:00000:00014:2014/12/18 09:41:36.49 server  Started REDO pass for database 'SID'. The total number of log records to process is 53351544.

00:0004:00000:00014:2014/12/18 09:41:43.02 server  Roll forward transaction '$dmpxact'.

00:0004:00000:00014:2014/12/18 09:41:43.02 server  Roll forward transaction '$systsflush'.

00:0004:00000:00014:2014/12/18 09:41:43.02 server  Roll forward transaction '$chained_transaction'.

00:0004:00000:00014:2014/12/18 09:41:43.02 server  Roll forward transaction '$chained_transaction'.

00:0004:00000:00014:2014/12/18 09:41:43.02 server  Roll forward transaction '$chained_transaction'.

00:0004:00000:00014:2014/12/18 09:41:43.02 server  Roll forward transaction '$chained_transaction'.

00:0004:00000:00014:2014/12/18 09:41:43.02 server  Roll forward transaction '$chained_transaction'.

00:0004:00000:00014:2014/12/18 09:41:43.02 server  Roll forward transaction '$chained_transaction'.

00:0004:00000:00014:2014/12/18 09:41:43.02 server  Roll forward transaction '$chained_transaction'.

00:0004:00000:00014:2014/12/18 09:41:43.02 server  Roll forward transaction '$chained_transaction'.

00:0004:00000:00014:2014/12/18 09:41:43.02 server  Roll forward transaction '$chained_transaction'.

00:0004:00000:00014:2014/12/18 09:41:43.02 server  Roll forward transaction '$chained_transaction'.

00:0004:00000:00014:2014/12/18 09:41:43.02 server  Roll forward transaction '$chained_transaction'.

00:0004:00000:00014:2014/12/18 09:41:43.02 server  Roll forward transaction '$chained_transaction'.

00:0004:00000:00014:2014/12/18 09:41:43.02 server  Roll forward transaction '$chained_transaction'.

00:0004:00000:00014:2014/12/18 09:41:43.02 server  Roll forward transaction '$chained_transaction'.

00:0004:00000:00014:2014/12/18 09:41:43.02 server  Roll forward transaction '$chained_transaction'.

00:0004:00000:00014:2014/12/18 09:41:43.02 server  Roll forward transaction '$chained_transaction'.

00:0004:00000:00014:2014/12/18 09:41:43.02 server  Roll forward transaction '$chained_transaction'.

00:0004:00000:00014:2014/12/18 09:41:43.02 server  Roll forward transaction '$chained_transaction'.

00:0004:00000:00014:2014/12/18 09:41:43.02 server  Roll forward transaction '$chained_transaction'.

00:0004:00000:00014:2014/12/18 09:41:43.02 server  Roll forward transaction '$chained_transaction'.

00:0004:00000:00014:2014/12/18 09:41:43.02 server  Roll forward transaction '$chained_transaction'.

00:0004:00000:00014:2014/12/18 09:41:43.02 server  Roll forward transaction '$chained_transaction'.

00:0004:00000:00014:2014/12/18 09:41:43.02 server  Roll forward transaction '$chained_transaction'.

00:0004:00000:00014:2014/12/18 09:41:43.02 server  Roll forward transaction '$chained_transaction'.

..

.. [lines removed]

..

00:0003:00000:00014:2014/12/18 09:46:30.70 server  Roll forward transaction '$chained_transaction'.

00:0003:00000:00014:2014/12/18 09:46:30.70 server  Roll forward transaction '$chained_transaction'.

00:0003:00000:00014:2014/12/18 09:46:30.70 server  Roll forward transaction '$chained_transaction'.

00:0003:00000:00014:2014/12/18 09:46:30.70 server  Roll forward transaction '$chained_transaction'.

00:0003:00000:00014:2014/12/18 09:46:30.70 server  Roll forward transaction '$chained_transaction'.

00:0003:00000:00014:2014/12/18 09:46:30.70 server  Redo pass of recovery has processed 1235377 committed and 10726 aborted transactions.

00:0003:00000:00014:2014/12/18 09:46:30.70 server  Completed REDO pass for database 'SID'.

00:0004:00000:00014:2014/12/18 09:46:43.71 server  Timestamp for database 'SID' is (0x0000, 0x2309da6f).

00:0004:00000:00014:2014/12/18 09:46:43.71 server  Recovery of database 'SID' will undo incomplete nested top actions.

00:0004:00000:00014:2014/12/18 09:46:43.77 server  Started filling free space info for database 'SID'.

00:0004:00000:00014:2014/12/18 09:51:31.32 server  Completed filling free space info for database 'SID'.

00:0004:00000:00014:2014/12/18 09:46:43.77 server  Started filling free space info for database 'SID'.

00:0004:00000:00014:2014/12/18 09:51:31.32 server  Completed filling free space info for database 'SID'.

00:0004:00000:00014:2014/12/18 09:51:31.36 server  Started cleaning up the default data cache for database 'SID'.

00:0004:00000:00014:2014/12/18 09:51:31.41 server  Completed cleaning up the default data cache for database 'SID'.

00:0004:00000:00014:2014/12/18 09:51:31.42 server  Checking external objects.

00:0004:00000:00014:2014/12/18 09:51:31.69 server  The transaction log in the database 'SID' will use I/O size of 16 Kb.

00:0004:00000:00014:2014/12/18 09:51:31.69 server  Database 'SID' is now online.

00:0002:00000:00001:2014/12/18 09:51:31.74 server  Recovery has restored the value of 'local async prefetch limit' for '128K' pool in 'default data cache' from '80' to 'DEFAULT'.

00:0002:00000:00001:2014/12/18 09:51:31.74 server  Recovery has restored the value of 'local async prefetch limit' for '16K' pool in 'default data cache' from '80' to 'DEFAULT'.

00:0002:00000:00001:2014/12/18 09:51:31.84 server  Recovery has restored the original size for '128K' pool and '16K' pool in 'default data cache'.

00:0002:00000:00001:2014/12/18 09:51:31.85 server  Recovery complete.

00:0002:00000:00001:2014/12/18 09:51:31.85 server  ASE's default unicode sort order is 'binary'.

00:0002:00000:00001:2014/12/18 09:51:31.85 server  Recovery complete.

00:0002:00000:00001:2014/12/18 09:51:31.85 server  ASE's default unicode sort order is 'binary'.

00:0002:00000:00001:2014/12/18 09:51:31.86 server  ASE's default sort order is:

00:0002:00000:00001:2014/12/18 09:51:31.86 server       'binary' (ID = 25)

00:0002:00000:00001:2014/12/18 09:51:31.86 server  on top of default character set:

00:0002:00000:00001:2014/12/18 09:51:31.86 server       'utf8' (ID = 190).

00:0002:00000:00001:2014/12/18 09:51:31.86 server  Master SIDice size: 400 megabytes, or 204800 virtual pages. (A virtual page is 2048 bytes.)

00:0003:00000:00016:2014/12/18 09:51:31.93 kernel  Initializing Job Scheduler Task

00:0002:00000:00016:2014/12/18 09:51:32.07 kernel  Installed Job Scheduler sequencer code version 0.29 - 29 tokens

00:0002:00000:00016:2014/12/18 09:51:32.79 kernel  Job Scheduler Task state set to running, startcount 1.

00:0002:00000:00016:2014/12/18 09:51:33.72 kernel  Job Scheduler Task connected with Agent on port 4903

00:0002:00000:00001:2014/12/18 09:51:33.73 kernel  Warning: Cannot set console to nonblocking mode, switching to blocking mode.

00:0002:00000:00001:2014/12/18 09:51:33.73 kernel  Console logging is disabled. This is controlled via the 'enable console logging' configuration parameter.

[former_member207908]

Dear Alamsyah,

"Roll forward transaction '$chained_transaction'"

The above mentioned messages are logged to the ASE errorlog while starting ASE as part of recovery process.

I think it is not the one which is filling up your ASE errorlog.

Hint: There might be some continous Job scheduler messages or probably some error which needs to be addressed to stop filling the ASe errorlog. Look for those messages

The following will let you if there are continous ASE errors

more /sybase/SID/ASE-15_0/install/SID.log |grep -i error |wc-l

The following will let you if there are continous job scheduler messages

more /sybase/SID/ASE-15_0/install/SID.log |grep JS |wc-l

You can send the errorlog attached which helps in finding the root cause

Regards,

Rajesh

[Former Member]

Hi Rajesh,

the log is attached. Kindly assist analyze this log.

*rename file extention from .txt to .rar

XYZ.txt.zip

[Mark_A_Parsons]

99.97% of the log file entries consist of single-line messages regarding the recovery of 1,224,202 committed/aborted transactions.

I'd recommend you try Brett's sp_configure suggestion for suppressing these messages.

=================== additional details ...

From the log file:

========================================

00:0003:00000:00014:2014/12/16 07:38:15.31 server  Database 'XYZ', checkpoint=(7373526, 122), first=(7373526, 121), last=(7301015, 73).

00:0003:00000:00014:2014/12/16 07:38:15.31 server  Completed estimating recovery log boundaries for database 'XYZ'.

00:0003:00000:00014:2014/12/16 07:38:15.31 server  Started ANALYSIS pass for database 'XYZ'.

00:0003:00000:00014:2014/12/16 07:40:55.62 server  Completed ANALYSIS pass for database 'XYZ'.

00:0003:00000:00014:2014/12/16 07:40:55.62 server  Log contains all committed transactions until 2014/12/16 03:55:03.12 for database XYZ.

00:0003:00000:00014:2014/12/16 07:40:55.62 server  Started REDO pass for database 'XYZ'. The total number of log records to process is 52764219.

00:0003:00000:00014:2014/12/16 07:41:04.27 server  Roll forward transaction '$dmpxact'.

00:0003:00000:00014:2014/12/16 07:41:04.27 server  Roll forward transaction '$systsflush'.

00:0003:00000:00014:2014/12/16 07:41:04.27 server  Roll forward transaction '$chained_transaction'.

... snip ...

00:0002:00000:00014:2014/12/16 07:45:21.09 server  Redo pass of recovery has processed 1213512 committed and 10690 aborted transactions.

00:0002:00000:00014:2014/12/16 07:45:21.09 server  Completed REDO pass for database 'XYZ'.

00:0002:00000:00014:2014/12/16 07:45:38.53 server  Timestamp for database 'XYZ' is (0x0000, 0x2300629a).

00:0002:00000:00014:2014/12/16 07:45:38.53 server  Recovery of database 'XYZ' will undo incomplete nested top actions.

00:0002:00000:00014:2014/12/16 07:45:38.59 server  Started filling free space info for database 'XYZ'.

00:0002:00000:00014:2014/12/16 07:50:15.16 server  Completed filling free space info for database 'XYZ'.

00:0002:00000:00014:2014/12/16 07:50:15.23 server  Started cleaning up the default data cache for database 'XYZ'.

00:0004:00000:00014:2014/12/16 07:50:15.29 server  Completed cleaning up the default data cache for database 'XYZ'.

00:0004:00000:00014:2014/12/16 07:50:15.30 server  Checking external objects.

00:0004:00000:00014:2014/12/16 07:50:15.50 server  The transaction log in the database 'XYZ' will use I/O size of 16 Kb.

00:0004:00000:00014:2014/12/16 07:50:15.51 server  Database 'XYZ' is now online.

========================================

Some log file stats:

# lines in log file:     1,224,579

# lines "Roll forward":  1,213,512    = number of committed txns mentioned in log file

# lines "was aborted":      10,690    = number of aborted txns mentioned in log file

So, 99.9% of the log file entries consist of single-line messages regarding the recovery of 1,224,202 (1,213,512 + 10,690) committed/aborted transactions.

[victoria_normand]

Hi Alamsyah,

As Bret mentioned, the "print recovery information" is returning those messages. It is recommended to be configured to 1 on Business Suite environment (SAP Note 1749935 - SYB: Configuration Guide for SAP ASE 15.7) , but you can disable it to 0. That change can be done from DBA Cockpit -> Configuration -> Server Configuration -> under "Backup/Recovery" folder , use the "Change" buttom.

Besides that, I would say that on a "normal situation" you shouldn't have so many committed/aborted transaction during recovery process of a startup if your database was stopped correctly (no abruptally).

I agree with Rajesh, is the same kind of message also repeated on your others "old" ASE error log or is there anything else ?

Best regards,
Victoria.

[former_member188958]

The "Roll forward transaction '$chained_transaction'." messages are being output because sp_configure "print recovery information" is set to 1.  If you are frequently rebooting ASE or frequently loading database or transaction log dump files, this configuration option can write a lot out lines of output to the errorlog.

[former_member3043]

Hello,

could you get a tail for the last 2000 lines of your current errorlog SID.log and pipe it into a new file ? This should give us a hint what might fill up the log.

You can compress this output and attach it, that would make it easier, to attach file the max size is 1 MB.

Regards

Stefan

PS: Could you also post the full version string for your ASE ? (select @@sbssav).

[victoria_normand]

Hi Alamsyah,

The ASE error log size shouldn't grow up so quickly unless there are specific messages non taken into consideration waiting for some action. Did you checked the content ?

Best regards,

Victoria