dbvalid.exe unable to start database

When replaying logs on a standby database and then validating it in (in read only mode) we occasionally come across this oddity.

DBValid is unable to start the database even though the previous log application process reports Recovery Complete. After an initial panic, we found that we could start the database directly in read only mode, close it down and then dbvalid was quite happy. Also, the log application process would continue without error on a database that dbvalid said it could not open.

It only happens occasionally, maybe one validation in ten. It's as though when dbvalid starts the database it does something slightly different (that only matters sometimes) from when you start the database directly with the engine, even when you specify all the same start-up parameters.

We tried all sorts of variations on the dbvalid settings without it making any difference. These are the command lines used in the process in the log below:

dbsrv16.exe -o c:\replay.log -a E:\DatabaseLogs\IQX\LiveLog\pearsCopy.log f:\databases\iqx\pears.db

dbvalid -o c:\validate.log -c "start=dbsrv16 -z -o c:\validate_eng.log ;eng=Valid;dbn=Valid;dbf=f:\databases\iqx\pears.db;dbs=-r;uid=XXXX;pwd=XXXX"

It's noticeable that dbvalid adds some extra switches to the engine and the database

-ga to shut down after the last disconnection
-h undocumented
-hn0,5828:208 undocumented

Could these extra switches be the difference?

Engine window logs showing three successful log applications followed by dbvalid failing to start the database:

time 808 date 22-01-2016

I. 01/22 08:08:00. SQL Anywhere Network Server Version 16.0.0.2076

I. 01/22 08:08:00. Workgroup Edition I. 01/22 08:08:00.

I. 01/22 08:08:00. Copyright © 2014 SAP SE or an SAP affiliate company. I. 01/22 08:08:00. All rights reserved. I. 01/22 08:08:00. Use of this software is governed by the Sybase License Agreement. I. 01/22 08:08:00. Refer to http://www.sybase.com/softwarelicenses. I. 01/22 08:08:00.

I. 01/22 08:08:00. Processors detected: 2 (containing 24 logical processors) I. 01/22 08:08:00. Processor limit (Workgroup Edition): 2 I. 01/22 08:08:00. Processor limit (licensed processors): 2 I. 01/22 08:08:00. Maximum number of processors the server will use: 2 physical processor(s), 12 core(s) I. 01/22 08:08:00. This server is licensed to: I. 01/22 08:08:00. System Administrator I. 01/22 08:08:00. **** I. 01/22 08:08:00. Running Windows 2008R2 Build 7601 Service Pack 1 on X86_64 I. 01/22 08:08:00. Server built for X86_64 processor architecture I. 01/22 08:08:00. 37746200K of memory used for caching I. 01/22 08:08:00. Minimum cache size: 159552K, maximum cache size: 135882628K I. 01/22 08:08:00. Using a maximum page size of 4096 bytes I. 01/22 08:08:00. Multiprogramming level: minimum:24, current:52, maximum:80 I. 01/22 08:08:00. Automatic tuning of multiprogramming level is enabled I. 01/22 08:08:01. Starting database "pears" (f:\databases\iqx\pears.db) at Fri Jan 22 2016 08:08 I. 01/22 08:08:01. Performance warning: Database file "f:\databases\iqx\pears.db" consists of 3 disk fragments I. 01/22 08:08:02. Database recovery in progress I. 01/22 08:08:02. Last checkpoint at Fri Jan 22 2016 00:01 I. 01/22 08:08:02. Transaction log: E:\DatabaseLogs\IQX\LiveLog\pearsCopy.log... I. 01/22 08:08:07. ... recovery 0% complete I. 01/22 08:08:17. ... recovery 4% complete I. 01/22 08:08:19. Starting checkpoint of "pears" (pears.db) at Fri Jan 22 2016 08:08 I. 01/22 08:08:20. Finished checkpoint of "pears" (pears.db) at Fri Jan 22 2016 08:08 I. 01/22 08:08:22. ... recovery 12% complete I. 01/22 08:08:24. Starting checkpoint of "pears" (pears.db) at Fri Jan 22 2016 08:08 I. 01/22 08:08:24. Finished checkpoint of "pears" (pears.db) at Fri Jan 22 2016 08:08 I. 01/22 08:08:27. ... recovery 23% complete I. 01/22 08:08:27. Starting checkpoint of "pears" (pears.db) at Fri Jan 22 2016 08:08 I. 01/22 08:08:28. Finished checkpoint of "pears" (pears.db) at Fri Jan 22 2016 08:08 I. 01/22 08:08:32. ... recovery 31% complete I. 01/22 08:08:35. Starting checkpoint of "pears" (pears.db) at Fri Jan 22 2016 08:08 I. 01/22 08:08:36. Finished checkpoint of "pears" (pears.db) at Fri Jan 22 2016 08:08 I. 01/22 08:08:37. ... recovery 38% complete I. 01/22 08:08:42. ... recovery 43% complete I. 01/22 08:08:47. ... recovery 49% complete I. 01/22 08:08:49. Starting checkpoint of "pears" (pears.db) at Fri Jan 22 2016 08:08 I. 01/22 08:08:50. Finished checkpoint of "pears" (pears.db) at Fri Jan 22 2016 08:08 I. 01/22 08:08:52. ... recovery 53% complete I. 01/22 08:08:57. ... recovery 58% complete I. 01/22 08:09:02. Starting checkpoint of "pears" (pears.db) at Fri Jan 22 2016 08:09 I. 01/22 08:09:02. ... recovery 65% complete I. 01/22 08:09:03. Finished checkpoint of "pears" (pears.db) at Fri Jan 22 2016 08:09 I. 01/22 08:09:07. Starting checkpoint of "pears" (pears.db) at Fri Jan 22 2016 08:09 I. 01/22 08:09:08. ... recovery 73% complete I. 01/22 08:09:08. Finished checkpoint of "pears" (pears.db) at Fri Jan 22 2016 08:09 I. 01/22 08:09:13. ... recovery 81% complete I. 01/22 08:09:17. Starting checkpoint of "pears" (pears.db) at Fri Jan 22 2016 08:09 I. 01/22 08:09:18. ... recovery 87% complete I. 01/22 08:09:19. Finished checkpoint of "pears" (pears.db) at Fri Jan 22 2016 08:09 I. 01/22 08:09:23. ... recovery 92% complete I. 01/22 08:09:28. ... recovery 99% complete I. 01/22 08:09:29. Checkpointing... I. 01/22 08:09:29. Starting checkpoint of "pears" (pears.db) at Fri Jan 22 2016 08:09 I. 01/22 08:09:30. Finished checkpoint of "pears" (pears.db) at Fri Jan 22 2016 08:09 I. 01/22 08:09:30. Recovery complete I. 01/22 08:09:31. Database server shutdown automatically after log applied I. 01/22 08:09:33. Database server stopped at Fri Jan 22 2016 08:09

time 838 date 22-01-2016

I. 01/22 08:38:00. SQL Anywhere Network Server Version 16.0.0.2076

I. 01/22 08:38:00. Workgroup Edition I. 01/22 08:38:00.

I. 01/22 08:38:00. Copyright © 2014 SAP SE or an SAP affiliate company. I. 01/22 08:38:00. All rights reserved. I. 01/22 08:38:00. Use of this software is governed by the Sybase License Agreement. I. 01/22 08:38:00. Refer to http://www.sybase.com/softwarelicenses. I. 01/22 08:38:00.

I. 01/22 08:38:00. Processors detected: 2 (containing 24 logical processors) I. 01/22 08:38:00. Processor limit (Workgroup Edition): 2 I. 01/22 08:38:00. Processor limit (licensed processors): 2 I. 01/22 08:38:00. Maximum number of processors the server will use: 2 physical processor(s), 12 core(s) I. 01/22 08:38:00. This server is licensed to: I. 01/22 08:38:00. System Administrator I. 01/22 08:38:00. * I. 01/22 08:38:00. Running Windows 2008R2 Build 7601 Service Pack 1 on X86_64 I. 01/22 08:38:00. Server built for X86_64 processor architecture I. 01/22 08:38:00. 37746200K of memory used for caching I. 01/22 08:38:00. Minimum cache size: 159552K, maximum cache size: 135882628K I. 01/22 08:38:00. Using a maximum page size of 4096 bytes I. 01/22 08:38:00. Multiprogramming level: minimum:24, current:52, maximum:80 I. 01/22 08:38:00. Automatic tuning of multiprogramming level is enabled I. 01/22 08:38:01. Starting database "pears" (f:\databases\iqx\pears.db) at Fri Jan 22 2016 08:38 I. 01/22 08:38:01. Performance warning: Database file "f:\databases\iqx\pears.db" consists of 3 disk fragments I. 01/22 08:38:02. Database recovery in progress I. 01/22 08:38:02. Last checkpoint at Fri Jan 22 2016 08:09 I. 01/22 08:38:02. Transaction log: E:\DatabaseLogs\IQX\LiveLog\pearsCopy.log... I. 01/22 08:38:07. ... recovery 0% complete I. 01/22 08:38:12. ... recovery 1% complete I. 01/22 08:38:17. ... recovery 12% complete I. 01/22 08:38:22. ... recovery 29% complete I. 01/22 08:38:27. ... recovery 47% complete I. 01/22 08:38:32. ... recovery 63% complete I. 01/22 08:38:37. ... recovery 77% complete I. 01/22 08:38:42. ... recovery 96% complete I. 01/22 08:38:43. Checkpointing... I. 01/22 08:38:43. Starting checkpoint of "pears" (pears.db) at Fri Jan 22 2016 08:38 I. 01/22 08:38:45. Finished checkpoint of "pears" (pears.db) at Fri Jan 22 2016 08:38 I. 01/22 08:38:45. Recovery complete I. 01/22 08:38:45. Database server shutdown automatically after log applied I. 01/22 08:38:48. Database server stopped at Fri Jan 22 2016 08:38

time 908 date 22-01-2016

I. 01/22 09:08:14. SQL Anywhere Network Server Version 16.0.0.2076

I. 01/22 09:08:14. Workgroup Edition I. 01/22 09:08:14.

I. 01/22 09:08:14. Copyright © 2014 SAP SE or an SAP affiliate company. I. 01/22 09:08:14. All rights reserved. I. 01/22 09:08:14. Use of this software is governed by the Sybase License Agreement. I. 01/22 09:08:14. Refer to http://www.sybase.com/softwarelicenses. I. 01/22 09:08:14.

I. 01/22 09:08:14. Processors detected: 2 (containing 24 logical processors) I. 01/22 09:08:14. Processor limit (Workgroup Edition): 2 I. 01/22 09:08:14. Processor limit (licensed processors): 2 I. 01/22 09:08:14. Maximum number of processors the server will use: 2 physical processor(s), 12 core(s) I. 01/22 09:08:14. This server is licensed to: I. 01/22 09:08:14. System Administrator I. 01/22 09:08:14. * I. 01/22 09:08:14. Running Windows 2008R2 Build 7601 Service Pack 1 on X86_64 I. 01/22 09:08:14. Server built for X86_64 processor architecture I. 01/22 09:08:15. 37746200K of memory used for caching I. 01/22 09:08:15. Minimum cache size: 159552K, maximum cache size: 135882628K I. 01/22 09:08:15. Using a maximum page size of 4096 bytes I. 01/22 09:08:15. Multiprogramming level: minimum:24, current:52, maximum:80 I. 01/22 09:08:15. Automatic tuning of multiprogramming level is enabled I. 01/22 09:08:15. Starting database "pears" (f:\databases\iqx\pears.db) at Fri Jan 22 2016 09:08 I. 01/22 09:08:15. Performance warning: Database file "f:\databases\iqx\pears.db" consists of 3 disk fragments I. 01/22 09:08:17. Database recovery in progress I. 01/22 09:08:17. Last checkpoint at Fri Jan 22 2016 08:38 I. 01/22 09:08:17. Transaction log: E:\DatabaseLogs\IQX\LiveLog\pearsCopy.log... I. 01/22 09:08:22. ... recovery 0% complete I. 01/22 09:08:32. ... recovery 8% complete I. 01/22 09:08:51. Starting checkpoint of "pears" (pears.db) at Fri Jan 22 2016 09:08 I. 01/22 09:08:52. ... recovery 11% complete I. 01/22 09:08:53. Finished checkpoint of "pears" (pears.db) at Fri Jan 22 2016 09:08 I. 01/22 09:08:57. ... recovery 18% complete I. 01/22 09:09:02. ... recovery 29% complete I. 01/22 09:09:07. ... recovery 42% complete I. 01/22 09:09:12. ... recovery 52% complete I. 01/22 09:09:17. ... recovery 64% complete I. 01/22 09:09:22. ... recovery 81% complete I. 01/22 09:09:27. ... recovery 96% complete I. 01/22 09:09:29. Checkpointing... I. 01/22 09:09:29. Starting checkpoint of "pears" (pears.db) at Fri Jan 22 2016 09:09 I. 01/22 09:09:32. Finished checkpoint of "pears" (pears.db) at Fri Jan 22 2016 09:09 I. 01/22 09:09:32. Recovery complete I. 01/22 09:09:32. Database server shutdown automatically after log applied I. 01/22 09:09:34. Database server stopped at Fri Jan 22 2016 09:09

I. 01/22 09:21:45. 1: -z I. 01/22 09:21:45. 2: -o I. 01/22 09:21:45. 3: c:\validate_eng.log I. 01/22 09:21:45. 4: -ha I. 01/22 09:21:45. 5: -ga I. 01/22 09:21:45. 6: -n I. 01/22 09:21:45. 7: Valid I. 01/22 09:21:45. 8: f:\databases\iqx\pears.db I. 01/22 09:21:45. 9: -r I. 01/22 09:21:45. 10: -n I. 01/22 09:21:45. 11: Valid I. 01/22 09:21:45. 12: -hn0,5828:208 I. 01/22 09:21:45.

I. 01/22 09:21:45. SQL Anywhere Network Server Version 16.0.0.2076

I. 01/22 09:21:45. Workgroup Edition I. 01/22 09:21:45.

I. 01/22 09:21:45. Copyright © 2014 SAP SE or an SAP affiliate company. I. 01/22 09:21:45. All rights reserved. I. 01/22 09:21:45. Use of this software is governed by the Sybase License Agreement. I. 01/22 09:21:45. Refer to http://www.sybase.com/softwarelicenses. I. 01/22 09:21:45.

I. 01/22 09:21:45. Processors detected: 2 (containing 24 logical processors) I. 01/22 09:21:45. Processor limit (Workgroup Edition): 2 I. 01/22 09:21:45. Processor limit (licensed processors): 2 I. 01/22 09:21:45. Maximum number of processors the server will use: 2 physical processor(s), 12 core(s) I. 01/22 09:21:45. This server is licensed to: I. 01/22 09:21:45. System Administrator I. 01/22 09:21:45. **** I. 01/22 09:21:45. Running Windows 2008R2 Build 7601 Service Pack 1 on X86_64 I. 01/22 09:21:45. Server built for X86_64 processor architecture I. 01/22 09:21:46. 37746200K of memory used for caching I. 01/22 09:21:46. Minimum cache size: 159552K, maximum cache size: 135882628K I. 01/22 09:21:46. Using a maximum page size of 4096 bytes I. 01/22 09:21:46. Multiprogramming level: minimum:24, current:52, maximum:80 I. 01/22 09:21:46. Automatic tuning of multiprogramming level is enabled I. 01/22 09:21:46. TCP using Winsock version 2.2 I. 01/22 09:21:46. IPv6 support enabled I. 01/22 09:21:46. Database server started at Fri Jan 22 2016 09:21 I. 01/22 09:21:46. Trying to start SharedMemory link ... I. 01/22 09:21:46. SharedMemory link started successfully I. 01/22 09:21:46. Trying to start TCPIP link ... I. 01/22 09:21:46. Starting on port 2638 I. 01/22 09:21:46. Starting UDP listener on IP address 10.200.128.67:2638 I. 01/22 09:21:46. Starting UDP listener on IP address (::1):2638 I. 01/22 09:21:46. Starting UDP listener on IP address 127.0.0.1:2638 I. 01/22 09:21:46. Looking for server with name valid I. 01/22 09:21:46. Sending broadcast to find server I. 01/22 09:21:46. Using broadcast address of: 10.200.128.255 I. 01/22 09:21:46. Looking for server with name valid I. 01/22 09:21:46. Sending broadcast to find server I. 01/22 09:21:46. Using broadcast address of: ff02::1 I. 01/22 09:21:46. Looking for server with name valid I. 01/22 09:21:46. Sending broadcast to find server I. 01/22 09:21:46. Using broadcast address of: 127.255.255.255 E. 01/22 09:21:46. TCP/IP link, function WSASendTo, error code 1214 I. 01/22 09:21:46. TCP/IP link, function send, error code 997 I. 01/22 09:21:46. Broadcast send failed I. 01/22 09:21:51. Server not found (no reply received) I. 01/22 09:21:51. TCPIP link started successfully I. 01/22 09:21:51. Now accepting requests I. 01/22 09:21:51. Starting TCPIP listener on IP address (::):2638 I. 01/22 09:21:51. Starting TCPIP listener on IP address 0.0.0.0:2638 I. 01/22 09:21:51. Starting database "Valid" (f:\databases\iqx\pears.db) at Fri Jan 22 2016 09:21 I. 01/22 09:21:51. Performance warning: Database file "f:\databases\iqx\pears.db" consists of 3 disk fragments E. 01/22 09:21:53. Error: Database cannot be started -- unable to start database "f:\databases\iqx\pears.db"

E. 01/22 09:21:53. Connection ID 1: Connection error '08W09': Unable to start specified database: unable to start database "f:\databases\iqx\pears.db" I. 01/22 09:21:53. Database server shutdown requested by DBSTOP I. 01/22 09:21:53. Disallowing new connections W. 01/22 09:21:55. TCPIP listener on IP address (::):2638 is exiting I. 01/22 09:21:55. Shutting down databases E. 01/22 09:21:55. TCP/IP link, function WSARecvFrom, error code 995 W. 01/22 09:21:55. TCPIP listener on IP address 0.0.0.0:2638 is exiting E. 01/22 09:21:55. TCP/IP link, function WSARecvFrom, error code 995 E. 01/22 09:21:55. TCP/IP link, function WSARecvFrom, error code 995 I. 01/22 09:21:55. Completing server shutdown I. 01/22 09:21:56. Database server stopped at Fri Jan 22 2016 09:21

asked 22 Jan '16, 11:08

Justin Willey
7.7k●137●179●252
accept rate: 20%

The -ga and -ha switches are always used when the database server is auto-started (the engine needs to knows it's being auto-started as opposed to a normal -ga). The -hn is added by dbvalid the coordinate the delivery of the return code.

I wonder if this failure would occur when auto-starting the database using dbisql? Maybe try with and without the dbs=r to narrow it down.

(22 Jan '16, 11:57) Mikel Rychliski

Replies hidden

Thanks Mikel, I'll try that when it next happens.

(25 Jan '16, 13:08) Justin Willey

flat view

2 Answers:

active answers oldest answers newest answers popular answers

The answer turned out to be because of transactions that span multiple transaction logs. In read only mode the database server cannot carry out the roll back necessary to recover the database to a usable state. This was identified by Reg Domaratzki in his very helpful and detailed answer here to a follow-up question.

permanent link

answered 09 Feb '16, 08:26

Justin Willey
7.7k●137●179●252
accept rate: 20%

edited 09 Feb '16, 08:27

flat view

The two -h* switches are not relevant here. The -ha switch is added by the client to tell the database engine that the server was autostarted and that a connection will be autostarting a database (and when this connection disconnect do not auto-shutdown the server... this is needed just in case autostop was enabled). The -hn switch is used to tell the database engine to notify the client (through the pipe identified by the -hn value) when it is ready to accept connections.

The issue may be that the autostarted database engine is attempting to start the database before the database file has been fully "released" from the previous command's (i.e. dbsrv16). This should not ever happen since the previous command (dbsrv) should have completely closed the file before it stopped... but perhaps you have the database on a SAN or NAS and network latency issues is causing the file to appeared locked (on the SAN/NAS) when it is not.

Try putting a short delay (of a few seconds) between the dbsrv16 and dbvalid commands and see if that resolves the issue.

permanent link

answered 22 Jan '16, 13:16

Mark Culp
25.0k●10●142●298
accept rate: 41%

Many thanks for the explanation of the -h* switches.

I don't think that in this case the issue can be the files being locked by the SAN etc. In this example there was 12 minutes between the last log replay finishing with the server engine stopped, and dbvalid running. During the testing we also copied the database to another machine and tried validating it there, with the same result.

It looks like a workaround is to just start and stop the database in read-only mode immediately before running dbvalid (or starting the database separately, and then running dbvalid against a running database). It does seem odd though!

The next time it happens, I'll try Mikel's suggestion and see if we can narrow down what is upsetting dbvalid.

(25 Jan '16, 13:07) Justin Willey

Replies hidden

Starting the database in read-only mode shouldn't change any part of there database file. "certutil -hashfile pears.db" should return the exact same result before and after the read-only start, so something else in the environment must be changed by the read-only start

(25 Jan '16, 14:17) Mikel Rychliski

Yes - this is what is so confusing :) Certainly the log offset doesn't get changed - as we can continue applying logs happily.

Unfortunately we don't seem to be able to get any information about why dbvalid can't start the database - there's nothing in the Windows logs where you usually see messages if any of the the normal things - missing log file etc - are wrong.

The next time it happens I'll see if I can confirm the checksum is unchanged.

(25 Jan '16, 14:33) Justin Willey

Following on from what you say about the environment - I wonder if it could be something to do with the network side of things. Could the existence of a database engine with that name and a database of that name be being cached somehow and that stops the dbvalid from starting in a way that it doesn't stop dbsrv directly?

I'm clutching at straws here, I fear!

(25 Jan '16, 14:58) Justin Willey

flat view

Your answer

toggle preview

community wiki:

Follow this question

By Email:

Once you sign in you will be able to subscribe for any updates here

By RSS:

Answers

Answers and Comments

Markdown Basics

*italic* or _italic_
**bold** or __bold__
link:[text](http://url.com/ "title")
image?![alt text](/path/img.jpg "title")
numbered list: 1. Foo 2. Bar
to add a line break simply add two spaces to where you would like the new line to be.
basic HTML tags are also supported

learn more about Markdown

Question tags:

sa-16 ×261
validation ×30
databasestart ×16
failure ×12
dbvalid ×11

question asked: 22 Jan '16, 11:08

question was seen: 3,479 times

last updated: 09 Feb '16, 08:27

SAP SQL Anywhere

dbvalid.exe unable to start database

Follow this question

Related questions