We might be building cube now… But not if you scheduled it for half-past!

In support we frequently have those moments that make us smile.  Often they aren’t things I would choose to blog about – but I will share this one.  I certainly don’t mean to trivialize bugs – and I do appreciate that they can cause a great deal of inconvenience to our customers (One particular customer I am thinking of in this case) but they can have their amusing moments!

For those that just want the short story – always schedule your cube builds on the hour.  If you choose 12:30, 1:30 etc it will not build when you want it.  If you want the long version then read on…

For this particular support incident we were troubleshooting a cube building issue where the customer was scheduling a cube build and it wasn’t happening on time – but sometime later – that seemed variable but in some cases looked like it was using Universal Coordinated Time (UCT or GMT).  I set my cube build for 4:30pm that afternoon, set my ULS logs to give verbose output for the Analysis Cube Build and started SQL Profiler traces to see what was going on in the database.  My usual steps for “following the data”.  I saw that the cube build didn’t happen at 4:30pm so thought I might have a repro so left it all running overnight.

The following morning I could see the cube had built at 2:30am – which fitted the pattern as I am in PST (GMT-8), so I started through the logs and traces to see what was going on.  Only 3 million rows in my SQL traces so shouldn’t take long…  I also set another cube build for 8:00 while I worked through the logs – and this worked.  Then set one for 8:30 – which failed, 9:00 worked.  I could see the pattern, and having this information and the logs I managed to find the bug.

The amusing part was looking in the ULS logs for the previous afternoon and at a few milliseconds past 4:30 seeing this entry.

Cube building timer job invoked and we might be building cube now

It was as if the SharePoint timer service (which was the process that gave this message) wasn’t going to take any accountability for what happened next!  Or more correctly the developer coding the message!  If you are a regular reader you will know that the cube build can fail for a number of reasons, so perhaps I shouldn’t have been surprised that the message was a little evasive.  It did however make me dig deeper to understand this part of the cube build process which I hadn’t investigated in depth before.

It follows a similar path to the provisioning of a PWA site, and for similar reasons.  It is going to use a WSS Timer job, but the SSP account does not have permissions to create one – so this is what happens.  When you click save on the cube build settings page for a periodical update it saves the information to the MSP_WEB_CUBE_ADMIN table in the _Published database and also puts a row into the SharedServices1_DB (your name may vary) in the MIPScheduledJob table.  This is the timer job request. This is read by the SharePoint timer service after a minute or so and it gets put into the Objects table of the SharePoint_Config database – and is seen as a timer job in timer job definitions.  At the appointed time it will run and you will see a job in the TimerRunningJobs table and this is when the message to the ULS logs gets posted.  If all works well this would be followed by another couple of messages saying the cube building job has started.  In my case I didn’t see these messages in my log until 2:30am – even though they referred back to the requested time of 4:30pm.

Cube building job has started for scheduled time: 3/25/2008 4:30 PM

[CBS] Status message: Cube build request message has been added to the Project Server queue

In fact you will see the “might be building cube” message at every 30 minutes past – even after it builds the cube – once the timer job is in place.  So the real reason it says “might” is that only once during the day (if you have daily builds) will it actually be building when that message appears!

A couple of other interesting points about this process is that the times in the SharePoint databases are held in UCT (which is by design and not the reason for the strange build times).  However the requested build time in the MSP_WEB_CUBE_ADMIN table is held as an integer defining at how many half hours past midnight the cube should be built.  12:30 would be 1, 3:00am would be 6 etc.  It is the decoding of this for the odd number that appears to be at the root of this bug.

For the main issue though – that cubes scheduled for the half hours do not get built on time – we do have a hotfix in the pipeline.  We might release this in April :).