What would cause long delay after final checkpoint?

[Breck_Carter]

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

[VolkerBarth]

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:

I. 04.12 08:15:01. Herunterfahren des Datenbankservers über Server-Konsole angefordert
W. 04.12 08:15:03. TCPIP-Listener an IP-Adresse (::):2638 wird beendet
W. 04.12 08:15:03. TCPIP-Listener an IP-Adresse 0.0.0.0:2638 wird beendet
E. 04.12 08:15:08. Verarbeitungsroutine für Ereignis 'EV_...' bewirkte SQLSTATE '57014'
E. 04.12 08:15:08. Anweisung vom Benutzer unterbrochen
I. 04.12 08:15:09. Start des Checkpoints von "A..." (A.db) am/um Freitag, 04. Dezember 2020 08:15
I. 04.12 08:15:09. Checkpoint von "A..." (A.db) fertig gestellt um Freitag, 04. Dezember 2020 08:15
I. 04.12 08:21:19. Datenbankserver gestoppt am/um Freitag, 04. Dezember 2020 08:21.

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.

[jack_schueler · Accepted solution]

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.

[Breck_Carter · Accepted solution]

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 🙂