database recovery has never finsihed

Discussion:

(too old to reply)

Peter Lo

2007-08-23 17:52:30 UTC

HI!

This morning, I restarted my Sybase server (running on a Windows
machine). I found
that a database was under recovery. But, the recovery has never
finished. I examined
the errorlog and found this:

Adaptive Server Enterprise/12.5.3/EBF 12461 ESD#2/P/NT (IX86)/OS
4.0/ase1253/1904/32-bit/OPT
....
server Recovering database 'DEV_eni_trade_new'.
server Started estimating recovery log boundaries for database
'DEV_eni_trade_new'.
server Database 'DEV_eni_trade_new', checkpoint=(1737723, 3),
first=(1737723, 3), last=(1738214, 19).
server Completed estimating recovery log boundaries for database
'DEV_eni_trade_new'.
server Started ANALYSIS pass for database 'DEV_eni_trade_new'.
server Completed ANALYSIS pass for database 'DEV_eni_trade_new'.
kernel timeslice -500, current process infected
kernel SQL Server system exception (0xe0000001) generated by a process
exceeding its time slice allotment.
kernel Symbolic stack trace information is successfully loaded
kernel pc: 0x7C57E592 KERNEL32.dll (0xE0000001, 0x00000001, 0x00000000,
0x00000000)
kernel pc: 0x7C57E592 KERNEL32.dll (0x00000000, 0x00000000, 0x00000000,
0x232E9800)
kernel pc: 0x00BC2B55 kpntraise+ 0x1b (0x00000001, 0x21579160, 0x2365E800,
0x23662800)
kernel [Handler pc: 0x006C2720 rec_handle installed by the following
function:-]
kernel pc: 0x006C0192 rec_analyze_log+ 0x7a4 (0x00000001, 0x00000000,
0x0264FB54, 0x00000001)
kernel [Handler pc: 0x006C2720 rec_handle installed by the following
function:-]
kernel pc: 0x006BDADF recovery+ 0x771 (0x232E3000, 0x00000000, 0x00000000,
0x2172A96C)
kernel pc: 0x006BAADE boot__recover_and_online+ 0x113 (0x232E3000,
0x0264FC98, 0x00000002, 0x004DFA12)
kernel [Handler pc: 0x006C66EB rec__caller_hdlr installed by the following
function:-]
kernel pc: 0x006BCB80 rec__boot_recover_dbs+ 0x33d (0x232E3000, 0x0264FC98,
0x0264FE89, 0x00000001)
kernel pc: 0x006B966E rec_run_parallel_recovery+ 0x8ee (0x00000001,
0x21508560, 0x00000000, 0x2172AEFC)
kernel [Handler pc: 0x006C66EB rec__caller_hdlr installed by the following
function:-]
kernel pc: 0x006BC50F dorecover+ 0x1a2 (0x00000000, 0x00690062, 0x003B006E,
0x00000001)
kernel pc: 0x0040AE7D ds__recoverdbs+ 0x792 (0x00000000, 0x00690062,
0x003B006E, 0x229852E8)
kernel pc: 0x00405C67 dsinit+ 0x1277 (0x229852E8, 0x00690062, 0x003B006E,
0x229852E8)
kernel pc: 0x00BC2A97 kpntwrapper+ 0x84 (0x00000000, 0x00000000,
0x00000000, 0x00000000)
kernel pc: 0x7C57438B KERNEL32.dll (0x828BB855, 0x00000478, 0x8502E083,
0x6A1074C0)
kernel pc: 0x7C571608 KERNEL32.dll (0x00000000, 0x00000000, 0x00000000,
0x00000000)
kernel end of stack trace, spid 1, kpid 131074, suid 0
kernel ************************************
kernel SQL causing error :
kernel ************************************
server SQL Text:
kernel curdb = 26 tempdb = 2 pstat = 0x1000
kernel lasterror = 3454 preverror = 2812 transtate = 1
kernel curcmd = 0 program =
kernel pc: 0x00C4C4D8 os_get_cur_stk_desc+ 0x170 (0x0264EC2C, 0x7C57E597,
0x7C574E58, 0xFFFFFFFF)
kernel pc: 0x00C4C4D8 os_get_cur_stk_desc+ 0x170 (0x0264EC2C, 0x0264E9E4,
0x0000270F, 0x00000002)
kernel pc: 0x00C22875 pcstkwalk+ 0x204 (0x00020002, 0x00000002, 0x0000270F,
0x00000000)
kernel pc: 0x00C224FF ucstkgentrace+ 0x25f (0x00020002, 0x00000001,
0x00F71380, 0x00000000)
kernel pc: 0x00BCD73B ucbacktrace+ 0xab (0x00020002, 0xFFFFFFFF,
0x0264F1D4, 0xE0000001)
kernel pc: 0x0040755D terminate_process+ 0xc78 (0xE0000001, 0x7800BDB5,
0x0264F208, 0x00000000)
kernel pc: 0x00BC1F14 kiexception+ 0x4b9 (0x229852E8, 0x00690062,
0x003B006E, 0x229852E8)
kernel pc: 0x00BC2B17 kpntwrapper+ 0x104 (0x00000000, 0x00000000,
0x00000000, 0x00000000)
kernel pc: 0x7C57438B KERNEL32.dll (0x828BB855, 0x00000478, 0x8502E083,
0x6A1074C0)
kernel pc: 0x7C571608 KERNEL32.dll (0x00000000, 0x00000000, 0x00000000,
0x00000000)
kernel end of stack trace, spid 1, kpid 131074, suid 0
server Recovery has restored the value of 'local async prefetch limit' for
'2K' pool in 'default data cache' from '80' to ''.

I could drop this database and restore it from db dump. However, there are
data entered after the last db dump was
taken. Therefore, I want to recover them so that my users do not need to
reenter them again.

My question is
Is there a hope to recover this database ? If there is one, how ?

-- Peter Lo

Bret Halford

2007-08-23 19:09:37 UTC

Permalink

The timeslice is being raised because the recovery process has exceeded
it's time slice without voluntarily yielding. You can try giving it more time
to complete by increasing the sp_configure "cpu grace" setting to a considerably

larger value.

There is a known related bug, CR 416044, where having an unusually large
number of transactions to deal with can result in such a timeslice. The bug was

fixed in 12.5.4 by adding a yield point within a loop processing the transaction
table.
So applying 12.5.4 or higher (or 15.0.2 or higher) is another option.

-bret

Post by Peter Lo
HI!
This morning, I restarted my Sybase server (running on a Windows
machine). I found
that a database was under recovery. But, the recovery has never
finished. I examined
Adaptive Server Enterprise/12.5.3/EBF 12461 ESD#2/P/NT (IX86)/OS
4.0/ase1253/1904/32-bit/OPT
....
server Recovering database 'DEV_eni_trade_new'.
server Started estimating recovery log boundaries for database
'DEV_eni_trade_new'.
server Database 'DEV_eni_trade_new', checkpoint=(1737723, 3),
first=(1737723, 3), last=(1738214, 19).
server Completed estimating recovery log boundaries for database
'DEV_eni_trade_new'.
server Started ANALYSIS pass for database 'DEV_eni_trade_new'.
server Completed ANALYSIS pass for database 'DEV_eni_trade_new'.
kernel timeslice -500, current process infected
kernel SQL Server system exception (0xe0000001) generated by a process
exceeding its time slice allotment.
kernel Symbolic stack trace information is successfully loaded
kernel pc: 0x7C57E592 KERNEL32.dll (0xE0000001, 0x00000001, 0x00000000,
0x00000000)
kernel pc: 0x7C57E592 KERNEL32.dll (0x00000000, 0x00000000, 0x00000000,
0x232E9800)
kernel pc: 0x00BC2B55 kpntraise+ 0x1b (0x00000001, 0x21579160, 0x2365E800,
0x23662800)
kernel [Handler pc: 0x006C2720 rec_handle installed by the following
function:-]
kernel pc: 0x006C0192 rec_analyze_log+ 0x7a4 (0x00000001, 0x00000000,
0x0264FB54, 0x00000001)
kernel [Handler pc: 0x006C2720 rec_handle installed by the following
function:-]
kernel pc: 0x006BDADF recovery+ 0x771 (0x232E3000, 0x00000000, 0x00000000,
0x2172A96C)
kernel pc: 0x006BAADE boot__recover_and_online+ 0x113 (0x232E3000,
0x0264FC98, 0x00000002, 0x004DFA12)
kernel [Handler pc: 0x006C66EB rec__caller_hdlr installed by the following
function:-]
kernel pc: 0x006BCB80 rec__boot_recover_dbs+ 0x33d (0x232E3000, 0x0264FC98,
0x0264FE89, 0x00000001)
kernel pc: 0x006B966E rec_run_parallel_recovery+ 0x8ee (0x00000001,
0x21508560, 0x00000000, 0x2172AEFC)
kernel [Handler pc: 0x006C66EB rec__caller_hdlr installed by the following
function:-]
kernel pc: 0x006BC50F dorecover+ 0x1a2 (0x00000000, 0x00690062, 0x003B006E,
0x00000001)
kernel pc: 0x0040AE7D ds__recoverdbs+ 0x792 (0x00000000, 0x00690062,
0x003B006E, 0x229852E8)
kernel pc: 0x00405C67 dsinit+ 0x1277 (0x229852E8, 0x00690062, 0x003B006E,
0x229852E8)
kernel pc: 0x00BC2A97 kpntwrapper+ 0x84 (0x00000000, 0x00000000,
0x00000000, 0x00000000)
kernel pc: 0x7C57438B KERNEL32.dll (0x828BB855, 0x00000478, 0x8502E083,
0x6A1074C0)
kernel pc: 0x7C571608 KERNEL32.dll (0x00000000, 0x00000000, 0x00000000,
0x00000000)
kernel end of stack trace, spid 1, kpid 131074, suid 0
kernel ************************************
kernel ************************************
kernel curdb = 26 tempdb = 2 pstat = 0x1000
kernel lasterror = 3454 preverror = 2812 transtate = 1
kernel curcmd = 0 program =
kernel pc: 0x00C4C4D8 os_get_cur_stk_desc+ 0x170 (0x0264EC2C, 0x7C57E597,
0x7C574E58, 0xFFFFFFFF)
kernel pc: 0x00C4C4D8 os_get_cur_stk_desc+ 0x170 (0x0264EC2C, 0x0264E9E4,
0x0000270F, 0x00000002)
kernel pc: 0x00C22875 pcstkwalk+ 0x204 (0x00020002, 0x00000002, 0x0000270F,
0x00000000)
kernel pc: 0x00C224FF ucstkgentrace+ 0x25f (0x00020002, 0x00000001,
0x00F71380, 0x00000000)
kernel pc: 0x00BCD73B ucbacktrace+ 0xab (0x00020002, 0xFFFFFFFF,
0x0264F1D4, 0xE0000001)
kernel pc: 0x0040755D terminate_process+ 0xc78 (0xE0000001, 0x7800BDB5,
0x0264F208, 0x00000000)
kernel pc: 0x00BC1F14 kiexception+ 0x4b9 (0x229852E8, 0x00690062,
0x003B006E, 0x229852E8)
kernel pc: 0x00BC2B17 kpntwrapper+ 0x104 (0x00000000, 0x00000000,
0x00000000, 0x00000000)
kernel pc: 0x7C57438B KERNEL32.dll (0x828BB855, 0x00000478, 0x8502E083,
0x6A1074C0)
kernel pc: 0x7C571608 KERNEL32.dll (0x00000000, 0x00000000, 0x00000000,
0x00000000)
kernel end of stack trace, spid 1, kpid 131074, suid 0
server Recovery has restored the value of 'local async prefetch limit' for
'2K' pool in 'default data cache' from '80' to ''.
I could drop this database and restore it from db dump. However, there are
data entered after the last db dump was
taken. Therefore, I want to recover them so that my users do not need to
reenter them again.
My question is
Is there a hope to recover this database ? If there is one, how ?
-- Peter Lo

Peter Lo

2007-08-29 22:53:49 UTC

Permalink

Hi! I changed the configuration variable 'cpu grace time' to a large value,

1> sp_configure 'cpu grace time'
2> go
Parameter Name Default Memory Used Config Value
Run Value Unit Type
------------------------------ ----------- ----------- ------------
----------- -------------------- ----------
cpu grace time 500 0 100000
100000 clock ticks dynamic

(1 row affected)

and still got error shown below:

Recovering database 'DEV_eni_trade_new'.
.. server Started estimating recovery log boundaries for database
'DEV_eni_trade_new'.
.. server Database 'DEV_eni_trade_new', checkpoint=(1737723, 3),
first=(1737723, 3), last=(1738214, 19).
.. server Completed estimating recovery log boundaries for database
'DEV_eni_trade_new'.
.. server Started ANALYSIS pass for database 'DEV_eni_trade_new'.
.. server Completed ANALYSIS pass for database 'DEV_eni_trade_new'.
.. kernel timeslice -100000, current process infected
.. kernel SQL Server system exception (0xe0000001) generated by a process
exceeding its time slice allotment.
.. kernel Symbolic stack trace information is successfully loaded
.. kernel pc: 0x7C57E592 KERNEL32.dll (0xE0000001, 0x00000001, 0x00000000,
0x00000000)
.. kernel pc: 0x7C57E592 KERNEL32.dll (0x023FFA60, 0x00000000, 0x00000000,
0x00000000)
.. kernel pc: 0x00BC2B55 kpntraise+ 0x1b (0x00000001, 0x21579160,
0x2365E800, 0x23662800)
.. kernel [Handler pc: 0x006C2720 rec_handle installed by the following
function:-]
.. kernel pc: 0x006C017F rec_analyze_log+ 0x791 (0x00000001, 0x00000000,
0x023FFB54, 0x00000001)
.. kernel [Handler pc: 0x006C2720 rec_handle installed by the following
function:-]
.. kernel pc: 0x006BDADF recovery+ 0x771 (0x232E3000, 0x00000000,
0x00000000, 0x2172A96C)
.. kernel pc: 0x006BAADE boot__recover_and_online+ 0x113 (0x232E3000,
0x023FFC98, 0x00000002, 0x004DFA12)
.. kernel [Handler pc: 0x006C66EB rec__caller_hdlr installed by the
following function:-]
.. kernel pc: 0x006BCB80 rec__boot_recover_dbs+ 0x33d (0x232E3000,
0x023FFC98, 0x023FFE89, 0x00000001)
.. kernel pc: 0x006B966E rec_run_parallel_recovery+ 0x8ee (0x00000001,
0x21508560, 0x00000000, 0x2172AEFC)
.. kernel [Handler pc: 0x006C66EB rec__caller_hdlr installed by the
following function:-]
.. kernel pc: 0x006BC50F dorecover+ 0x1a2 (0x00000000, 0x005C0065,
0x00440041, 0x00000001)
.. kernel pc: 0x0040AE7D ds__recoverdbs+ 0x792 (0x00000000, 0x005C0065,
0x00440041, 0x229852E8)
.. kernel pc: 0x00405C67 dsinit+ 0x1277 (0x229852E8, 0x005C0065,
0x00440041, 0x229852E8)
.. kernel pc: 0x00BC2A97 kpntwrapper+ 0x84 (0x00000000, 0x00000000,
0x00000000, 0x00000000)
.. kernel pc: 0x7C57438B KERNEL32.dll (0x00000000, 0x00000000, 0x00000000,
0x00000000)
.. kernel end of stack trace, spid 1, kpid 131074, suid 0
.. kernel ************************************
.. kernel SQL causing error :
.. kernel ************************************
.. kernel SQL Text:
.. kernel curdb = 26 tempdb = 2 pstat = 0x1000
.. kernel lasterror = 3454 preverror = 2812 transtate = 1
.. kernel curcmd = 0 program =
.. kernel pc: 0x00C4C4D8 os_get_cur_stk_desc+ 0x170 (0x023FEC28,
0x7C57E597, 0x7C574E58, 0xFFFFFFFF)
.. kernel pc: 0x00C4C4D8 os_get_cur_stk_desc+ 0x170 (0x023FEC28,
0x023FE9E0, 0x0000270F, 0x00000002)
.. kernel pc: 0x00C22875 pcstkwalk+ 0x204 (0x00020002, 0x00000002,
0x0000270F, 0x00000000)
.. kernel pc: 0x00C224FF ucstkgentrace+ 0x25f (0x00020002, 0x00000001,
0x00F71380, 0x00000000)
.. kernel pc: 0x00BCD73B ucbacktrace+ 0xab (0x00020002, 0xFFFFFFFF,
0x023FF1D0, 0xE0000001)
.. kernel pc: 0x0040755D terminate_process+ 0xc78 (0xE0000001, 0x7800BDB5,
0x023FF204, 0x00000000)
.. kernel pc: 0x00BC1F14 kiexception+ 0x4b9 (0x229852E8, 0x005C0065,
0x00440041, 0x229852E8)
.. kernel pc: 0x00BC2B17 kpntwrapper+ 0x104 (0x00000000, 0x00000000,
0x00000000, 0x00000000)
.. kernel pc: 0x7C57438B KERNEL32.dll (0x00000000, 0x00000000, 0x00000000,
0x00000000)
.. kernel end of stack trace, spid 1, kpid 131074, suid 0
.. server Recovery has restored the value of 'local async prefetch limit'
for '2K' pool in 'default data cache' from '80' to ''.

It does not look like that I can successfully recover this database, any
suggestion for the next move?

-- Peter Lo

Post by Bret Halford
The timeslice is being raised because the recovery process has exceeded
it's time slice without voluntarily yielding. You can try giving it more time
to complete by increasing the sp_configure "cpu grace" setting to a considerably
larger value.
There is a known related bug, CR 416044, where having an unusually large
number of transactions to deal with can result in such a timeslice. The bug was
fixed in 12.5.4 by adding a yield point within a loop processing the transaction
table.
So applying 12.5.4 or higher (or 15.0.2 or higher) is another option.
-bret

Mark K

2007-08-30 02:36:45 UTC

Permalink

Well, that is officially the largest timeslice error I've personally seen.
If you are able to run other commands while this is going on, you might try
running "dbcc showrecovery" every minute or so and see if anything is
changing.

You should also configure for a shared memdump on timeslice and open a case
with Tech Support.
sp_shmdumpconfig
'add','timeslice',null,1,'/work',null,include_proc,include_page
go
sp_configure 'dump on conditions',1
go

Mark Kusma

Post by Peter Lo
Hi! I changed the configuration variable 'cpu grace time' to a large value,
1> sp_configure 'cpu grace time'
2> go
Parameter Name Default Memory Used Config Value
Run Value Unit Type
------------------------------ ----------- ----------- ------------
----------- -------------------- ----------
cpu grace time 500 0 100000
100000 clock ticks dynamic
(1 row affected)
Recovering database 'DEV_eni_trade_new'.
.. server Started estimating recovery log boundaries for database
'DEV_eni_trade_new'.
.. server Database 'DEV_eni_trade_new', checkpoint=(1737723, 3),
first=(1737723, 3), last=(1738214, 19).
.. server Completed estimating recovery log boundaries for database
'DEV_eni_trade_new'.
.. server Started ANALYSIS pass for database 'DEV_eni_trade_new'.
.. server Completed ANALYSIS pass for database 'DEV_eni_trade_new'.
.. kernel timeslice -100000, current process infected
.. kernel SQL Server system exception (0xe0000001) generated by a process
exceeding its time slice allotment.
.. kernel Symbolic stack trace information is successfully loaded
.. kernel pc: 0x7C57E592 KERNEL32.dll (0xE0000001, 0x00000001,
0x00000000, 0x00000000)
.. kernel pc: 0x7C57E592 KERNEL32.dll (0x023FFA60, 0x00000000,
0x00000000, 0x00000000)
.. kernel pc: 0x00BC2B55 kpntraise+ 0x1b (0x00000001, 0x21579160,
0x2365E800, 0x23662800)
.. kernel [Handler pc: 0x006C2720 rec_handle installed by the following
function:-]
.. kernel pc: 0x006C017F rec_analyze_log+ 0x791 (0x00000001, 0x00000000,
0x023FFB54, 0x00000001)
.. kernel [Handler pc: 0x006C2720 rec_handle installed by the following
function:-]
.. kernel pc: 0x006BDADF recovery+ 0x771 (0x232E3000, 0x00000000,
0x00000000, 0x2172A96C)
.. kernel pc: 0x006BAADE boot__recover_and_online+ 0x113 (0x232E3000,
0x023FFC98, 0x00000002, 0x004DFA12)
.. kernel [Handler pc: 0x006C66EB rec__caller_hdlr installed by the
following function:-]
.. kernel pc: 0x006BCB80 rec__boot_recover_dbs+ 0x33d (0x232E3000,
0x023FFC98, 0x023FFE89, 0x00000001)
.. kernel pc: 0x006B966E rec_run_parallel_recovery+ 0x8ee (0x00000001,
0x21508560, 0x00000000, 0x2172AEFC)
.. kernel [Handler pc: 0x006C66EB rec__caller_hdlr installed by the
following function:-]
.. kernel pc: 0x006BC50F dorecover+ 0x1a2 (0x00000000, 0x005C0065,
0x00440041, 0x00000001)
.. kernel pc: 0x0040AE7D ds__recoverdbs+ 0x792 (0x00000000, 0x005C0065,
0x00440041, 0x229852E8)
.. kernel pc: 0x00405C67 dsinit+ 0x1277 (0x229852E8, 0x005C0065,
0x00440041, 0x229852E8)
.. kernel pc: 0x00BC2A97 kpntwrapper+ 0x84 (0x00000000, 0x00000000,
0x00000000, 0x00000000)
.. kernel pc: 0x7C57438B KERNEL32.dll (0x00000000, 0x00000000,
0x00000000, 0x00000000)
.. kernel end of stack trace, spid 1, kpid 131074, suid 0
.. kernel ************************************
.. kernel ************************************
.. kernel curdb = 26 tempdb = 2 pstat = 0x1000
.. kernel lasterror = 3454 preverror = 2812 transtate = 1
.. kernel curcmd = 0 program =
.. kernel pc: 0x00C4C4D8 os_get_cur_stk_desc+ 0x170 (0x023FEC28,
0x7C57E597, 0x7C574E58, 0xFFFFFFFF)
.. kernel pc: 0x00C4C4D8 os_get_cur_stk_desc+ 0x170 (0x023FEC28,
0x023FE9E0, 0x0000270F, 0x00000002)
.. kernel pc: 0x00C22875 pcstkwalk+ 0x204 (0x00020002, 0x00000002,
0x0000270F, 0x00000000)
.. kernel pc: 0x00C224FF ucstkgentrace+ 0x25f (0x00020002, 0x00000001,
0x00F71380, 0x00000000)
.. kernel pc: 0x00BCD73B ucbacktrace+ 0xab (0x00020002, 0xFFFFFFFF,
0x023FF1D0, 0xE0000001)
.. kernel pc: 0x0040755D terminate_process+ 0xc78 (0xE0000001,
0x7800BDB5, 0x023FF204, 0x00000000)
.. kernel pc: 0x00BC1F14 kiexception+ 0x4b9 (0x229852E8, 0x005C0065,
0x00440041, 0x229852E8)
.. kernel pc: 0x00BC2B17 kpntwrapper+ 0x104 (0x00000000, 0x00000000,
0x00000000, 0x00000000)
.. kernel pc: 0x7C57438B KERNEL32.dll (0x00000000, 0x00000000,
0x00000000, 0x00000000)
.. kernel end of stack trace, spid 1, kpid 131074, suid 0
.. server Recovery has restored the value of 'local async prefetch limit'
for '2K' pool in 'default data cache' from '80' to ''.
It does not look like that I can successfully recover this database, any
suggestion for the next move?
-- Peter Lo