Fracturing QuickBooks Desktop
Someone wrote in asking if I knew what was going on during the process of upgrading a QuickBooks Company file from one version to another.
I could have just written a little something stupid, like, "Well, the file is being migrated," but I chose to delve a little deeper to give an earnest reply.
After sending a relatively brief explanation, the response back was, "Murph, that sounds like you just wrote an article."
Sure enough, the reply made me think that perhaps I should publish an article on this topic. It really fits into the series I've been writing on "Fracturing QuickBooks Desktop."
I can't actually upgrade thousands of files reviewing the various logs created during each one, nor do I have the time or interest in seeing if every detail remains identical from one file to the next. Since the initial inquiry was centered on why the file seemed to pause and wait, and wait, and wait at the 27 percent mark, that's where I started my Data Detective work.
I had a fairly healthy sized QuickBooks Company (*.QBW) file I could upgrade to the newest version of QuickBooks, so that was my first capture of data during the version upgrade process. If I track down our old friend, the QBWin.log file, it has some very clear indicators of the behind the scenes goings on during the process.
For example, here's the first entry in the log after I start the upgrade process:
- load.c (4121) : CHECKPOINT: 8812: Mon Feb 27 12:56:43 CFU: Begin of company file update 2017-02-27.12:56:43
You can see that we began at 12:56:43. That's 43 seconds into the 56th minute of the 12th hour. I noted some of the progress bar movements during this upgrade process. It took less than one minute for the progress bar to move from 0 percent to 20 percent after I started.
In that period of time, QuickBooks began making a copy of the data to a "safety directory," after first assessing the amount of cache memory available to the QuickBooks Database Server. Here are three interesting lines from the QBWin.log file:
- load.c (4695) : CHECKPOINT: 8812: Mon Feb 27 12:57:54 CFU: Time taken for back up is 33883 milliseconds.
- load.c (4696) : CHECKPOINT: 8812: Mon Feb 27 12:57:54 CFU: End of Backup 2017-02-27.12:57:54
- load.c (4751) : CHECKPOINT: 8812: Mon Feb 27 12:57:54 CFU: Begin of Verification 2017-02-27.12:57:54
You can see it took less than one minute from the start of the process for the backup to be made. In fact, QuickBooks actually reports the process as 33,833-milliseconds (aka: 33.833 seconds).
QuickBooks then begins verification and validation of the QuickBooks Company file. The express validation process was completed without any errors being detected – only 17 seconds later.
- dbsqlfilemanager.cpp (3357) : CHECKPOINT: 8812: Mon Feb 27 12:58:11 Database validation completed. No error detected
- load.c (4928) : CHECKPOINT: 8812: Mon Feb 27 12:58:11 CFU: Time taken for verification is 16739 milliseconds.
As I said earlier, by this point in the time line, the Progress Bar was reporting 20 percent.
The point at which the Progress Bar reported 27 percent, which the inquiry had asked about, was noted on my system clock at 12:58. Sure enough, it seems as though 27 percent is the magical point on the Progress Bar, when the actual upgrade process begins, because the QBWin.log reports:
- load.c (5503) : CHECKPOINT: 8812: Mon Feb 27 12:58:11 InitSystem: Convert to the latest Sybase version
The next significant event does not occur for another four minutes and 30 seconds, at which time the log shows:
- load.c (5510) : CHECKPOINT: 8812: Mon Feb 27 13:02:41 InitSystem: Convert to the latest Sybase version succeeded
- load.c (5548) : CHECKPOINT: 8812: Mon Feb 27 13:02:41 Current System version 27, Current major release 4 . Current File Schema is 107.23
This also happens to be exactly when the Progress Bar changed from sitting idle at 27 percent and started moving up quickly toward 45 percent. At the same time, the log shows that QuickBooks has begun a process called "schema upgrade":
- upgradeengine.cpp (179) : CHECKPOINT: 8812: Mon Feb 27 13:02:42 CFU: Begin of Schema upgrade 2017-02-27.13:02:42
- upgradeengine.cpp (372) : CHECKPOINT: 8812: Mon Feb 27 13:02:42 Inside UpgradeSchema start...
- DMSQLSchemaPreUpgrade.cpp (127) : CHECKPOINT: 8812: Mon Feb 27 13:02:42 S2S QB_PreUpgrade_Cleanup: Starting update function ...
This includes a pre-upgrade clean-up, which should be associated with clearing out resident data slots from the old Sybase format by making use of the new Sybase format. All of that takes place over the next minute (or so). And there are hundreds of "step" entries in the log during that very short time frame. Finally the log writes:
- DMSQLSchemaPostUpgrade.cpp (51913) : CHECKPOINT: 8812: Mon Feb 27 13:03:09 S2S QB_PostUpgrade_Create: Finishing update function ...
- upgradeengine.cpp (390) : CHECKPOINT: 8812: Mon Feb 27 13:03:09 Inside UpgradeSchema. Upgrade Schema is Finished with result status code value is 0
- upgradeengine.cpp (193) : CHECKPOINT: 8812: Mon Feb 27 13:03:09 CFU: End of Schema upgrade 2017-02-27.13:03:09
At this point in my "clocking the Progress Bar," the 45 percent mark has been reached.
Within the same second in the log, QuickBooks also is updating "permissions." I recently wrote a couple of articles about the importance of "permissions" and how that process impacts the overall integrity and security of the file.
Well, why would such an important issue be left out of the upgrade process? You can clearly see here that it isn't:
- urpstore.cpp (1965) : CHECKPOINT: 8812: Mon Feb 27 13:03:09 Update Permission Data to Version 23
- permissionmanager.cpp (4388) : CHECKPOINT: 8812: Mon Feb 27 13:03:09 A new permission context is added for QuickBooks
Near the very end of the process, as the Progress Meter has been speeding from 60 percent to 100 percent, the log is recording the following:
- upgradeengine.cpp (511) : CHECKPOINT: 8812: Mon Feb 27 13:03:15 Inside PostMajorAndMinorPrefsUpgrade start...
- upgradeengine.cpp (523) : CHECKPOINT: 8812: Mon Feb 27 13:03:15 Inside PostMajorAndMinorPrefsUpgrade. PostMajorAndMinorPrefsUpgrade function is Finished with result status code value is 0
- upgradeengine.cpp (655) : CHECKPOINT: 8812: Mon Feb 27 13:03:15 Inside UpdateDataVersion start...
- upgradeengine.cpp (664) : CHECKPOINT: 8812: Mon Feb 27 13:03:15 Inside UpdateDataVersion. UpdateDataVersion function is Finished with result status code value is 0
- upgradeengine.cpp (680) : CHECKPOINT: 8812: Mon Feb 27 13:03:15 Inside UpdateReleaseNumber start...
- upgradeengine.cpp (692) : CHECKPOINT: 8812: Mon Feb 27 13:03:15 Inside UpdateReleaseNumber. release number 4 is written and result status code value is 0
- upgradeengine.cpp (703) : CHECKPOINT: 8812: Mon Feb 27 13:03:15 Inside UpdateReleaseNumber. UpdateReleaseNumber function is Finished with result status code value is 0
These steps are associated with publishing the update status to the file and logs.
Just two seconds later, the log records the following entry:
- load.c (6434) : CHECKPOINT: 8812: Mon Feb 27 13:03:17 CFU: End of Update and Rebuild 2017-02-27.13:03:17
The Progress Bar has reached 100 percent, and QuickBooks is beginning to open in a normal fashion. It has taken less than seven minutes total to upgrade this file to QuickBooks Enterprise 2017 from an earlier version of Enterprise.
I suspect from years of working with QuickBooks files that this process pretty much remains the same, unless some problems are encountered during the process. In such cases, QuickBooks may attempt to resolve those by applying some of the "rebuild data" routines within the arsenal of file utilities stored in the application.
The other things that could drastically change this process in terms of the "time-line" are either the speed (or lack thereof) of the equipment upon which the upgrade is taking place (including the amount of available RAM) or. the size of the file. This will alter the amount of work and speed with which each step of the upgrade process can occur.
As it relates to the initial inquiry, when it comes to the Progress Bar that displays during the update process, remember that this bar, like many progress bars in QuickBooks (past and present), approximate activities occurring in the background. Some programmer configured the bar according to where he viewed that activity was in the overall task(s) to be accomplished.
When it comes to the Progress Bar, I don't think there's any direct relationship between the number of tasks. But there maybe some degree of relationship to the overall time frame, since obviously the majority of time spent in this example was the conversion to the new Sybase format while the tax bar appeared frozen at 27 percent.
Feel free to memorize the contents of this article. That way, when one of your clients asks, "Hey, what all goes on during this version upgrade business?" you can give them the details I've laid out here.
On the other hand, you may just want to tell them, "Well, the file is being migrated."