|
This is not a complaint, but a request for information... The following console log shows what happens when 3G worth of updates (6M rows) have to be rolled back during a restart, for a database containing not much more than 3G of data. The displayed console log reaches "... recovery 100% complete" fairly quickly and then sits there for 14 minutes. Clearly, it's not complete complete... what is it doing? ...well, I know what it's doing from a physical point of view, it's pounding the hard drive to death... but what is it doing from higher-level point of view? Should the "Rollback log..." message be displayed earlier? This is on a Windows 7 HP laptop. I. 07/28 06:18:43. SQL Anywhere Network Server Version 12.0.1.3298 I. 07/28 06:18:43. Developer edition, not licensed for deployment. I. 07/28 06:18:43. I. 07/28 06:18:43. Copyright © 2001-2011, iAnywhere Solutions, Inc. I. 07/28 06:18:43. Portions copyright © 1988-2011, Sybase, Inc. All rights reserved. I. 07/28 06:18:43. Use of this software is governed by the Sybase License Agreement. I. 07/28 06:18:43. Refer to http://www.sybase.com/softwarelicenses. I. 07/28 06:18:43. I. 07/28 06:18:43. Connection limit (licensed seats): 3 I. 07/28 06:18:43. Processors detected: 1 (containing 8 logical processors) I. 07/28 06:18:43. Maximum number of physical processors the server will use: 1 I. 07/28 06:18:43. This server is licensed to: I. 07/28 06:18:43. Developer Edition I. 07/28 06:18:43. Restricted Use I. 07/28 06:18:43. Running Windows 7 Build 7601 Service Pack 1 on X86_64 I. 07/28 06:18:43. Server built for X86_64 processor architecture I. 07/28 06:18:43. 2080200K of memory used for caching I. 07/28 06:18:43. Minimum cache size: 2080200K, maximum cache size: 4160440K I. 07/28 06:18:43. Using a maximum page size of 8192 bytes I. 07/28 06:18:43. Multiprogramming level: minimum:8, current:120, maximum:480 I. 07/28 06:18:43. Automatic tuning of multiprogramming level is disabled I. 07/28 06:18:43. Starting database "f" (C:\ProgramData\RisingRoad\Foxhound1\foxhound1.db) at Thu Jul 28 2011 06:18 I. 07/28 06:18:43. Performance warning: Database file "C:\ProgramData\RisingRoad\Foxhound1\foxhound1.db" consists of 106 disk fragments I. 07/28 06:18:43. Database recovery in progress I. 07/28 06:18:43. Last checkpoint at Thu Jul 28 2011 06:04 I. 07/28 06:18:43. Checkpoint log... I. 07/28 06:18:48. ... recovery 14% complete I. 07/28 06:18:53. ... recovery 31% complete I. 07/28 06:18:58. ... recovery 47% complete I. 07/28 06:19:03. ... recovery 63% complete I. 07/28 06:19:08. ... recovery 78% complete I. 07/28 06:19:13. ... recovery 94% complete I. 07/28 06:19:18. ... recovery 96% complete I. 07/28 06:19:23. ... recovery 97% complete I. 07/28 06:19:28. ... recovery 99% complete I. 07/28 06:21:57. Transaction log: foxhound1.log... I. 07/28 06:22:02. ... recovery 0% complete I. 07/28 06:22:07. ... recovery 1% complete I. 07/28 06:22:12. ... recovery 2% complete I. 07/28 06:22:17. ... recovery 3% complete I. 07/28 06:22:27. ... recovery 4% complete I. 07/28 06:22:33. ... recovery 5% complete I. 07/28 06:22:38. ... recovery 6% complete I. 07/28 06:22:48. ... recovery 7% complete I. 07/28 06:22:53. ... recovery 8% complete I. 07/28 06:22:58. ... recovery 9% complete I. 07/28 06:23:03. ... recovery 10% complete I. 07/28 06:23:13. ... recovery 11% complete I. 07/28 06:23:18. ... recovery 12% complete I. 07/28 06:23:23. ... recovery 13% complete I. 07/28 06:23:28. ... recovery 14% complete I. 07/28 06:23:38. ... recovery 15% complete I. 07/28 06:23:43. ... recovery 16% complete I. 07/28 06:23:48. ... recovery 17% complete I. 07/28 06:23:53. ... recovery 18% complete I. 07/28 06:24:03. ... recovery 19% complete I. 07/28 06:24:08. ... recovery 20% complete I. 07/28 06:24:13. ... recovery 21% complete I. 07/28 06:24:23. ... recovery 22% complete I. 07/28 06:24:28. ... recovery 23% complete I. 07/28 06:24:33. ... recovery 24% complete I. 07/28 06:24:38. ... recovery 25% complete I. 07/28 06:24:48. ... recovery 26% complete I. 07/28 06:24:53. ... recovery 27% complete I. 07/28 06:24:58. ... recovery 28% complete I. 07/28 06:25:03. ... recovery 29% complete I. 07/28 06:25:13. ... recovery 30% complete I. 07/28 06:25:18. ... recovery 31% complete I. 07/28 06:25:23. ... recovery 32% complete I. 07/28 06:25:33. ... recovery 33% complete I. 07/28 06:25:38. ... recovery 34% complete I. 07/28 06:25:43. ... recovery 35% complete I. 07/28 06:25:48. ... recovery 36% complete I. 07/28 06:25:58. ... recovery 37% complete I. 07/28 06:26:03. ... recovery 38% complete I. 07/28 06:26:09. ... recovery 39% complete I. 07/28 06:26:14. ... recovery 40% complete I. 07/28 06:26:24. ... recovery 41% complete I. 07/28 06:26:29. ... recovery 42% complete I. 07/28 06:26:34. ... recovery 43% complete I. 07/28 06:26:39. ... recovery 44% complete I. 07/28 06:26:49. ... recovery 45% complete I. 07/28 06:26:54. ... recovery 46% complete I. 07/28 06:26:59. ... recovery 47% complete I. 07/28 06:27:04. ... recovery 48% complete I. 07/28 06:27:14. ... recovery 49% complete I. 07/28 06:27:19. ... recovery 50% complete I. 07/28 06:27:24. ... recovery 51% complete I. 07/28 06:27:34. ... recovery 52% complete I. 07/28 06:27:39. ... recovery 53% complete I. 07/28 06:27:44. ... recovery 54% complete I. 07/28 06:27:54. ... recovery 55% complete I. 07/28 06:27:59. ... recovery 56% complete I. 07/28 06:28:04. ... recovery 57% complete I. 07/28 06:28:09. ... recovery 58% complete I. 07/28 06:28:19. ... recovery 59% complete I. 07/28 06:28:24. ... recovery 60% complete I. 07/28 06:28:29. ... recovery 61% complete I. 07/28 06:28:34. ... recovery 62% complete I. 07/28 06:28:44. ... recovery 63% complete I. 07/28 06:28:49. ... recovery 64% complete I. 07/28 06:28:54. ... recovery 65% complete I. 07/28 06:28:59. ... recovery 66% complete I. 07/28 06:29:09. ... recovery 67% complete I. 07/28 06:29:14. ... recovery 68% complete I. 07/28 06:29:19. ... recovery 69% complete I. 07/28 06:29:24. ... recovery 70% complete I. 07/28 06:29:34. ... recovery 71% complete I. 07/28 06:29:39. ... recovery 72% complete I. 07/28 06:29:45. ... recovery 73% complete I. 07/28 06:29:50. ... recovery 74% complete I. 07/28 06:30:00. ... recovery 75% complete I. 07/28 06:30:05. ... recovery 76% complete I. 07/28 06:30:10. ... recovery 77% complete I. 07/28 06:30:20. ... recovery 78% complete I. 07/28 06:30:25. ... recovery 79% complete I. 07/28 06:30:30. ... recovery 80% complete I. 07/28 06:30:35. ... recovery 81% complete I. 07/28 06:30:45. ... recovery 82% complete I. 07/28 06:30:50. ... recovery 83% complete I. 07/28 06:30:55. ... recovery 84% complete I. 07/28 06:31:00. ... recovery 85% complete I. 07/28 06:31:10. ... recovery 86% complete I. 07/28 06:31:15. ... recovery 87% complete I. 07/28 06:31:20. ... recovery 88% complete I. 07/28 06:31:30. ... recovery 89% complete I. 07/28 06:31:35. ... recovery 90% complete I. 07/28 06:31:40. ... recovery 91% complete I. 07/28 06:31:45. ... recovery 92% complete I. 07/28 06:31:55. ... recovery 93% complete I. 07/28 06:32:00. ... recovery 94% complete I. 07/28 06:32:05. ... recovery 95% complete I. 07/28 06:32:10. ... recovery 96% complete I. 07/28 06:32:20. ... recovery 97% complete I. 07/28 06:32:25. ... recovery 98% complete I. 07/28 06:32:30. ... recovery 99% complete I. 07/28 06:32:40. ... recovery 100% complete I. 07/28 06:46:15. Rollback log... I. 07/28 06:46:15. Checkpointing... I. 07/28 06:46:15. Starting checkpoint of "f" (foxhound1.db) at Thu Jul 28 2011 06:46 I. 07/28 06:47:39. Finished checkpoint of "f" (foxhound1.db) at Thu Jul 28 2011 06:47 I. 07/28 06:47:39. Recovery complete I. 07/28 06:47:39. Database "f" (foxhound1.db) started at Thu Jul 28 2011 06:47 I. 07/28 06:47:39. Database server started at Thu Jul 28 2011 06:47 I. 07/28 06:47:39. Trying to start SharedMemory link ... I. 07/28 06:47:39. SharedMemory link started successfully I. 07/28 06:47:39. Trying to start TCPIP link ... I. 07/28 06:47:39. Starting on port 49155 I. 07/28 06:47:41. Starting checkpoint of "f" (foxhound1.db) at Thu Jul 28 2011 06:47 I. 07/28 06:47:41. Finished checkpoint of "f" (foxhound1.db) at Thu Jul 28 2011 06:47 I. 07/28 06:47:44. TCPIP link started successfully I. 07/28 06:47:44. HTTP listener starting on port 80 I. 07/28 06:47:44. Now accepting requests |
|
In my simple repro, I saw the "Rollback log..." message right away after transaction log recovery was complete (actually 99% was displayed in my case); however, I also then immediately saw a subsequent "... recovery 100% complete" message even though it goes on grinding for a long while. I turns out that the 100% message actually applies to the completion of the transaction log recovery but wasn't supressed by the fact that we had moved on to the rollback phase. That's a bug. Also, we don't display progress percentages for the undo log. I can't definitively explain the behaviour you saw. Certainly the actual rollback should have taken some time and your output log makes it look instantaneous. Perhaps the "Rollback log..." message was somehow, um, lost in the ether for a while. |
|
Notice that the progress percentage restarts for the transaction log phase: the checkpoint log recovery phase went from 0 to 100%, then the transaction log did the same. It would appear that there are no progress messages for the rollback log. I'm surprised that wasn't put in -- I don't think it would be hard to implement. Are you saying that the rollback took the 14 minutes, but the one single "Rollback..." message wasn't produced until the rollback was complete?
(28 Jul '11, 09:05)
Breck Carter
Replies hidden
I think I misread your original question. I thought the long time was being taken after the "Rollback Log..." was displayed (yeah, I didn't actually look at the timestamps in your posting, sorry). There's truly very little that happens in the server after the transaction log is applied and before "Rollback log..." is printed. It is possible that the %complete was rounded to 100% (since it is just based on log page number) but wasn't quite complete and the last few operations in the log took forever to execute. It seems a bit of a long shot though. BTW, do you have multiple dbspaces?
(28 Jul '11, 09:51)
John Smirnios
Just one dbspace.
(28 Jul '11, 11:05)
Breck Carter
I don't suppose you have a saved copy of the file in the pre-recovery state, do you? Or perhaps you could translate the log and see what entries are on the last page of the transaction log at the time of that recovery? Or maybe you at least know exactly what operations were performed before the server, um, crashed?
(28 Jul '11, 13:46)
John Smirnios
Comment Text Removed
It was a single UPDATE statement that affected 6,133,762 rows of a single table, followed by a ROLLBACK that I got bored waiting for so I (stupidly) killed the engine... of course, it's gotta do the same thing when it restarts. So I'm guessing the transaction log isn't important to this, the rollback log is... but wow, I am on shaky ground here :) FWIW tomorrow's 3AM blog post shows the "test harness" for this question... not the 3PM Friday File, the earlier one :)
(28 Jul '11, 17:09)
Breck Carter
...in other words, I can probably reproduce it... but it is 3G, and it is from a client, sigh.
(28 Jul '11, 17:11)
Breck Carter
Maybe I'll just give it an "obvious" repro in a script and see what happens.
(02 Aug '11, 09:43)
John Smirnios
|