|
17.0.9.4882 What would cause a 10 minute delay between the last "Finished checkpoint" message and the subsequent "Database server stopped"? I. 12/05 13:49:32. Finished checkpoint of "f" (foxhound5.db) at Sat Dec 05 2020 13:49 I. 12/05 13:59:13. Database server stopped at Sat Dec 05 2020 13:59 As far as I can tell, dbsrv17.exe was pounding the *.db file for the whole time... is it possible the last "Finished checkpoint" message is sent long before the disk I/O is complete? Here's more of the log... I. 11/26 11:14:26. SQL Anywhere Network Server Version 17.0.9.4882 ... I. 11/26 11:14:26. Running Windows 10 Build 18362 on X86_64 I. 11/26 11:14:26. Server built for X86_64 processor architecture I. 11/26 11:14:26. 4192032K of memory used for caching I. 11/26 11:14:26. Minimum cache size: 4187960K, maximum cache size: 8363632K I. 11/26 11:14:26. Using a maximum page size of 8192 bytes I. 11/26 11:14:26. Multiprogramming level: minimum:8, current:220, maximum:880 I. 11/26 11:14:26. Automatic tuning of multiprogramming level is disabled I. 11/26 11:14:26. Starting database "f" (C:\ProgramData\RisingRoad\Foxhound5\foxhound5.db) at Thu Nov 26 2020 11:14 I. 11/26 11:14:27. Performance warning: Database file "C:\ProgramData\RisingRoad\Foxhound5\foxhound5.db" consists of 148 disk fragments I. 11/26 11:14:27. Transaction log: foxhound5.log I. 11/26 11:14:28. Starting checkpoint of "f" (foxhound5.db) at Thu Nov 26 2020 11:14 I. 11/26 11:14:28. Finished checkpoint of "f" (foxhound5.db) at Thu Nov 26 2020 11:14 I. 11/26 11:14:28. Database "f" (foxhound5.db) started at Thu Nov 26 2020 11:14 I. 11/26 11:14:28. Database server started at Thu Nov 26 2020 11:14 I. 11/26 11:14:28. Trying to start SharedMemory link ... I. 11/26 11:14:28. SharedMemory link started successfully I. 11/26 11:14:28. Trying to start TCPIP link ... I. 11/26 11:14:28. Starting on port 49152 I. 11/26 11:14:33. TCPIP link started successfully I. 11/26 11:14:33. HTTP listener starting on port 80 I. 11/26 11:14:33. Now accepting requests I. 11/26 11:14:35. --------------------------------------- I. 11/26 11:14:35. Foxhound Version 5.0 by RisingRoad - Extended Edition 5.0.5500a built at 2020 11 07 14:32 in a SQL Anywhere 17.0.9.4882 database created at 2020 11 07 14:32 I. 11/26 11:14:35. --------------------------------------- I. 11/26 11:14:37. No patches were processed. I. 11/26 11:14:49. Foxhound folder: C:\ProgramData\RisingRoad\Foxhound5 I. 11/26 11:14:49. Foxhound command line: "C:\Program Files\SQL Anywhere 17\Bin64\dbsrv17.exe" -c 25p -ch 50p -cr- -gk all -gl all -gn 220 -gna 0 -m -n foxhound5 -o foxhound5_debug.txt -oe foxhound5_debug_startup.txt -on 1M -sb 0 -ufd restart -x tcpip -xd -xs http(port=80;maxsize=0;to=600;kto=600) foxhound5.db -n f "-hn0,60368:512" I. 11/26 11:14:49. Foxhound server name: foxhound5 I. 11/26 11:14:49. Foxhound database name: f I. 11/26 11:14:49. Foxhound Windows API support DLL: rroad5_sa17_bin64.dll I. 11/26 11:14:49. SQL Anywhere startup time: 6.7s I. 11/26 11:14:49. Foxhound startup time: 16.3s I. 11/26 11:14:49. Total startup time: 23s I. 11/26 11:14:49. Foxhound now accepting requests. I. 11/26 11:41:33. Starting checkpoint of "f" (foxhound5.db) at Thu Nov 26 2020 11:41 I. 11/26 11:41:35. Finished checkpoint of "f" (foxhound5.db) at Thu Nov 26 2020 11:41 ... I. 12/05 13:28:04. Starting checkpoint of "f" (foxhound5.db) at Sat Dec 05 2020 13:28 I. 12/05 13:28:06. Finished checkpoint of "f" (foxhound5.db) at Sat Dec 05 2020 13:28 I. 12/05 13:49:20. Database server shutdown requested by DBSTOP W. 12/05 13:49:22. TCPIP listener on IP address 0.0.0.0:49152 is exiting W. 12/05 13:49:22. HTTP listener on IP address (::):80 is exiting W. 12/05 13:49:22. HTTP listener on IP address 0.0.0.0:80 is exiting W. 12/05 13:49:22. TCPIP listener on IP address (::):49152 is exiting E. 12/05 13:49:27. Handler for event 'rroad_monitor_sample_loop' caused SQLSTATE '57014' E. 12/05 13:49:27. Handler for event 'rroad_monitor_sample_loop' caused SQLSTATE '57014' E. 12/05 13:49:27. Handler for event 'rroad_monitor_sample_loop' caused SQLSTATE '57014' E. 12/05 13:49:27. Handler for event 'rroad_monitor_sample_loop' caused SQLSTATE '57014' E. 12/05 13:49:27. Handler for event 'rroad_monitor_sample_loop' caused SQLSTATE '57014' E. 12/05 13:49:27. Handler for event 'rroad_monitor_main_loop' caused SQLSTATE '57014' E. 12/05 13:49:27. Handler for event 'rroad_monitor_sample_loop' caused SQLSTATE '57014' E. 12/05 13:49:27. Handler for event 'rroad_monitor_sample_loop' caused SQLSTATE '57014' E. 12/05 13:49:27. Handler for event 'rroad_monitor_sample_loop' caused SQLSTATE '57014' E. 12/05 13:49:27. Handler for event 'rroad_monitor_sample_loop' caused SQLSTATE '57014' E. 12/05 13:49:27. Statement interrupted by user E. 12/05 13:49:27. Statement interrupted by user E. 12/05 13:49:27. Statement interrupted by user E. 12/05 13:49:27. Statement interrupted by user E. 12/05 13:49:27. Statement interrupted by user E. 12/05 13:49:27. Statement interrupted by user E. 12/05 13:49:27. Statement interrupted by user E. 12/05 13:49:28. Statement interrupted by user E. 12/05 13:49:28. Statement interrupted by user E. 12/05 13:49:28. Statement interrupted by user I. 12/05 13:49:30. Starting checkpoint of "f" (foxhound5.db) at Sat Dec 05 2020 13:49 I. 12/05 13:49:32. Finished checkpoint of "f" (foxhound5.db) at Sat Dec 05 2020 13:49 I. 12/05 13:59:13. Database server stopped at Sat Dec 05 2020 13:59 |
|
In recent versions of the database server (17.0.9.4937 or later), the -z option causes a lot more shutdown messages to appear in the server log. I realize the horse has already left the barn, but for the future, this may be a useful thing to enable. This enhancement should appear under the title "database server subsystem shutdown logging" in the release notes. 1
Thank you! > 17.0.9.4937 That supports my personal motto "Nothing is easy"... I waited a very long time before freezing the requirements for Foxhound 5 at "SQL Anywhere 17.0.9.4882 or better"... so of course I was outlasted by SAP :)
(07 Dec '20, 10:33)
Breck Carter
|
FWIW, here's a similar case with a v16 (16.0.0.2798) database shutdown via the Windows Service utitliy - log is in German but the pattern is similar: There's also a 6 minute delay between last checkpoint and shutdown:
From what I can tell, that database server usually shuts down way faster, usually the "Database server stopped" is within seconds after the final checkpoint.