The Value of Testing

This is one of those posts where I wish I could show actual code snippets, but since it involves a 3rd party vendor for one of my clients and I don’t have permission, I can’t.

So, I’m forced unfortunately to talk about the issue in a roundabout way.

My client uses a 3rd party tool to track documents. I’ve mentioned this before. They’ve been growing fairly fast and running into performance issues. I suppose growing fast is a good thing, but having performance issues is not.

In any case, using Query Store, I was able to send the vendor a list of queries and stats about them for them to review and to ideally improve the queries that needed work.

Yesterday they got back to me. The email was essentially we took this first query (let’s call it Doubly-Joined) and rewrote it as this second query (let’s call it Singly-Joined). I looked at the two queries, which join 4 tables. They’re very similar to each other, but the first one did join in the main table a second time (hence why I’m calling it Doubly-Joined). It’s not clear why this was done. The second query basically removed the second join and in the select clause, changed the aliases to the second join to the first join. This does give them a slightly different query plan, but ultimately, they return the same number of rows.

The first query plan
The second query plan

As you can see, the 2nd query plan is definitely a bit simpler (ignore the one warning, it’s not something that appears to be fixable here).

So, a naive take would be “we removed an unnecessary join, so of course it should be faster!” But is it?

Sometimes intuition can be correct, sometimes not so much. In this case though, it’s easy to confirm by seeing exactly how many rows are being read in each query.

I wrapped each query in a

Set Statistics IO ON/OFF
Set Statistics TIME ON/OFF

block and ran it. Here are the results

The Doubly-Joined

Table 'Table1'. Scan count 0, logical reads 337264, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'Table2'. Scan count 0, logical reads 3, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'Table3'. Scan count 0, logical reads 3, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'Table4'. Scan count 1, logical reads 396, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.

The Singly-joined

Table 'Table1'. Scan count 0, logical reads 337260, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'Table2'. Scan count 0, logical reads 3, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'Table3'. Scan count 0, logical reads 3, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'Table4'. Scan count 1, logical reads 396, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.

I’ve highlighted the relevant change. The single-joined query consistently performed with 4 fewer logical reads. Now, if the original number had been 8 and had dropped in half to 4, I’d be happy. But the change from 337264 to 337260 leaves me a bit underwhelmed. Furthermore, under multiple runs, the second query did not consistently use less CPU time, sometimes it took faster to run. Further testing was consistent in the lack of apparent improvement.

Needless to say, I don’t think this query improvement will help much. I’ve reached out to the vendor to see if they can provide more details, but honestly, I’m not hoping for much.

Query Store Saves the Day

It’s never a good thing when you get an impromptu meeting invite on the weekend and the subject line is “Sync Error”. I honestly didn’t even see the invite until the meeting had been going on for over an hour.

I called in and was brought up to speed. A 3rd party tool one of my client uses was having major timeout issues. Normally it’s fine, but my client was taking advantage of the weekend to do a very large import of data and the tool wasn’t keeping up.

I both love and hate being thrown into situations like this. I hate it because often I have very little information to go on, but also love it, because it can be a good challenge. So, I wanted to collect some data. Fortunately the database in question runs on SQL Server 2016. This blog post covers a bit of what we did and ends with why I am so grateful for Query Store.

Query Store and the First Graphs

I quickly enabled Query Store and grabbed a quick report. Based on help with the 3rd party support, I was able to focus on a particular query.

Query Store first graph

Initial Query Store screen grab

So, right away, I knew that at times this query could flip to a pretty bad query plan. I was curious as to why. But while poking around, I noticed something else going on. The database was at the SQL Server 2008 compatibility level, despite running on SQL Server 2016. Now I know when we upgraded the server a year ago the 3rd party vendor didn’t guarantee compatibility with 2016, so we had left it in its old compatibility level. Since then apparently the vendor had qualified it and I confirmed with their support who was on the line that I could change the compatibility level to SQL Server 2016. Of course, I wanted to see if this would make a difference, so I grabbed another one of the problematic queries and looked at the query plan both before and after.

Compatibility level 100

Query Plan at SQL Server 2008 Level

Compatibility level 130

Query Plan at SQL Server 2016 Level

As you’ll note, the 2008 plan uses 2 hash matches, the 2016 uses two merge joins. That’s interesting by itself, but after collecting a bit of data, I saw the 2016 plan was running in an average of 45ms. The 2008 plan had been averaging 1434ms. That’s quite the improvement, simply by a single change!

That said, I still wasn’t entirely comfortable with what was going on and dug a bit deeper.

Digging Deeper

The change to the compatibility level had essentially eliminated the green bar in the above graph. This was good. But the blue bar to the left of it was still an issue. It also had a similar issue with flipping between two different query plans, but this was even worse.

Query Store second graph

Better, but not that one query really stands out!

I find this particular chart to be the most useful. I set a custom time frame (in this case 3 hours) and looked at the total duration of 25 queries that had accumulated the most time running. It’s pretty clear that one query dominates and working on this is probably where I want to spend my efforts. It’s also very hard to pick out, but the query (#12) from the first graph that I had looked at, has improved so much that it’s now moved to 12th on the list from the 2nd position.  That’s quite an improvement and simply by changing the compatibility level! More on my thoughts on that below.

The more I thought about it, the more I started to focus on statistics. This was an educated guess based on the fact that my client was doing a LOT of inserts and updates into a particular table. There’s another issue I’ll also discuss. This one I couldn’t fix unfortunately, but if the 3rd party can, I think they’ll see a HUGE improvement in performance.

Slow query plan

Slow version of the query

Fast version of the query

Fast version of the query

These look VERY similar, except the position of the Key lookups and the Index Seeks are swapped. That may not seem like much but the slow version was on average taking about 93.95 ms and the fast version was on average taking about .11ms. That’s a HUGE difference, about 850x difference! It took me a bit to realize what was going on, but let’s talk about that Key lookup. Even with the faster version, it’s obvious that if I can eliminate that, I could get things to be even faster!  The problem is that the query wants to return some columns not covered in the IX_FileID index. That’s generally easy to fix and while I’m loathe to make updates to 3rd party packages, I was willing to test this one out by making it a covering index. Unfortunately, this is where I was stymied. One of the columns is an IMAGE datatype and you can’t throw those into an index. I’ve recommended to the 3rd party vendor they try to change this. It wouldn’t be easy, but it could have dramatic performance improvements here and elsewhere (I had run into this problem last year while trying to tackle another performance issue).

I should note, that even though this query is actually very fast, it is executed so much that its total time dominates in the system. This is one reason why any improvement here would have a dramatic impact.

Statistics

In any case, looking at these two query plans and doing some further testing confirmed my hypothesis and also suggests why changing the compatibility level helped so much: statistics were very quickly getting out of whack.

I was able to confirm this by grabbing some data from the query store for just the last hour and it showed only the slow version of the query was running. I then forced an update of stats on the table in question and immediately saw the query flip over to the faster plan. This continued for awhile before it flipped back to the slower version.

We developed a plan, which I’ll admit upfront didn’t work. We decided that updating the stats on that particular table every hour might give us tremendous performance gains. And in fact it did initially. BUT, what we found was that after an hour of inserts, running the update stats for that table took about 45-60 seconds and the vendors tool has a hard-coded 30 second timeout. And because of the way this particular tool works, it means after a failure you have to start from scratch on every run. Since the job can take 4-6 hours to run, we couldn’t update stats every hour, even though I would have liked to.

Query Store third graph

The graph that should our plan wasn’t working

Above shows how at the time the update stats was running (that particular column of the query story graphic is cut off) the query times jumped to 30 seconds.  So while overall updating the stats is a good thing, here it was definitely killing our process.

Above I mentioned that changing the compatibility level still had an impact here. What I didn’t show here was that I was also looking at a bunch of statistics histograms and could see how badly things had gotten in some cases. But this is an area where SQL Server 2016 makes a difference! It can do more in the background better to help keep statistics a bit more accurate (still not as good as a full update, but it can dramatically help.) This is a hug part I believe of why the first query addressed above improved AND stayed improved.

Loving Query Store

They say a picture is worth a 1000 words. Honestly, I probably could have figured out the above issues with running a bunch of queries, looking at some DMVs, statistics histograms and the like. But it would have taken longer. Note too you can query the query store. But, the ability to instantly look at a graph, see what’s taking the most time, or executing the most, or a variety of other parameters makes the graphical interface to Query store EXTREMELY valuable. I was able to instantly zero in on a couple of key queries and focus my energies there. By varying the timeframes I was looking at, I could try changes and see the impact within minutes. I could also look at the stored query plans and make judgments based on what they showed.

If you’re NOT using Query Store to debug performance issues, start doing it. To be honest, I haven’t used it much. I wouldn’t call myself an expert in it by any means. But, I was able to pull it up and almost instantly have insight into my client’s issues and was able to make actionable suggestions.

And to quote the product manager there after I fixed the first query simply by changing compatibility mode, “A good DBA is like having a good mechanic to work on your car.” That one made me smile.

Oh and I’ve been known to swap out the alternator on my old Subaru in under 10 minutes and have replaced the brakes a number of times. So if this DBA thing doesn’t work out, I guess I’ve got another career I can look into!

Final Note

Per my NDA, I obviously haven’t named my client. But also, simply out of respect, I haven’t named the third party tool. I don’t want folks thinking I’m trying to besmirch their name. Their product is a fine one and I’d recommend it if asked. But my client is one of their larger users and sometimes pushes it to the limits so we sometimes find some of the edge cases. So nothing here is meant to disparage the 3rd party tool in an way (though they should replace that image field since it really doesn’t need to be one!)

 

 

Trust but Verify

This is one of those posts where you’ll just have to trust me. Honestly.

I want to talk about indexes.

About a week ago, a friend on a chat system I use mentioned how one of their colleagues had mentioned, “oh, we don’t have to optimize the database, the server is fast enough” or words to those effect. All of us in the discussion blanched a bit. Yes, when I started in the business a 10GB database was considered large and because of the memory limit with 32-bit SQL, we were limited to 2GB (or 3GB if you took the right steps) of memory so it was literally impossible to keep a large database in memory. Of course now we routinely deal with databases 100s of GB in size with machines that can easily have .5TB of memory or more. This means except for writes, an entire database can easily be kept in memory.

But that said, optimization still matters. Last week I was debugging an ETL process that I’ve helped a client with. I’d love to show screen shots, but my NDA won’t allow me (hence my asking you to trust me). Ok, that’s partly a lie. I couldn’t provide too many details if I wanted to, but the bigger issue is, I’ve since closed the windows I that showed the scripts in questions and the results of my changes.

One of the last things each step in the ETL does is write back to the source table an updated Sales Force id. It’s actually a bit more complicated because what it really does is write to either a Success table or an Error table and depending on a factor or two, a trigger will then update the source table. I had previously debugged and improved the performance of the trigger. But something was still bothering me about the performance. I looked a bit deeper and one of the things that trigger does if there’s a success is make sure to remove the row from the Error table. This was taking longer than I suspected it should, so I dug into it and I noticed that the Error table had no index.  

I can’t show the original queries I used, but I can show an example of the impact of adding a simple clustered index. (See, you can’t even trust me to say I won’t show any examples! You’d better read the entire post to verify what I’m really writing!)

Here’s an example query (with some changes to hide client specific data)

select * from ErrorTable where SF__External_Id__c='005A000022IouWqIAX'

It’s a very simple query (and simpler than the actual one I was dealing with) but is enough to show the value of a proper index.

Now, in my original query, the Query Tuning Advisor actually suggested an index on SF__External_ID__c. In the example above it didn’t. There’s a canard among many DBAs that the QTA is generally useless and often it is, though I think it’s gotten better. As a consultant, I can often come into a new client and can tell when someone has gone crazy with the QTA and adopted EVERY SINGLE suggestion. In other words, they trusted it, but they never verified it. Why is this a problem? Well at times the QTA can be overly aggressive in my experience, suggesting indices that really provide little benefit, or if you add an index in response to a select query that is run say once a day, but where there are 1000s of updates a day, you might actually slow down your updates (since now the update also has to update the index). And as mentioned above, sometimes it might fail to suggest an index. (I think in this case, it didn’t suggest one on my example because the size of the underlying table was far smaller than before).

So, I like to verify that the index I’ll add will make a difference. In cases like this, I often go old school and simply bracket my test queries

set statistics IO ON
set statistics Time ON
select * from ErrorTable where SF__External_Id__c='005A000022IouWqIAX'
set statistics IO OFF
set statistics Time OFF

And then I enable Actual Execution Plan.

The results I received without any sort of index are below. Some key numbers are highlighted in red.

SQL Server parse and compile time: 
   CPU time = 0 ms, elapsed time = 0 ms.
SQL Server parse and compile time: 
   CPU time = 47 ms, elapsed time = 63 ms.
SQL Server parse and compile time: 
   CPU time = 0 ms, elapsed time = 0 ms.

(2 rows affected)
Table 'ErrorTable'. Scan count 1, logical reads 3570, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.

(1 row affected)

SQL Server Execution Times:
   CPU time = 16 ms,  elapsed time = 15 ms.
SQL Server Execution Times:
   CPU time = 0 ms,  elapsed time = 0 ms.

You’ll notice the physical reads are 0. This is nice. This means everything is in memory.

In this case, because I’m familiar with how the ErrorTable is accessed I decided a clustered index on SF__External_Id__c would be ideal. (all my updates, inserts, deletes, and selects use that to access this table).

I added the index and my reran the query:

SQL Server parse and compile time: 
   CPU time = 0 ms, elapsed time = 0 ms.
SQL Server parse and compile time: 
   CPU time = 0 ms, elapsed time = 1 ms.
SQL Server parse and compile time: 
   CPU time = 0 ms, elapsed time = 0 ms.

(2 rows affected)
Table 'ErrorTable'. Scan count 1, logical reads 3, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.

(1 row affected)

SQL Server Execution Times:
   CPU time = 0 ms,  elapsed time = 0 ms.

SQL Server Execution Times:
   CPU time = 0 ms,  elapsed time = 0 ms.

Note the number of logical reads dropped by about a factor of 1000. My elapsed time dropped from 15 ms to 0 ms (or rather less than .05 ms so SQL Server rounded down).

If we look at the graphical query plan results we something similar:

First, without the index:

Trust_but_Verify_Query Table Scan

Table scan to find 2 rows

Trust_but_Verify_Query Table Seek

Table Seek to find 2 rows

That’s nice, I now know I’m doing a seek rather than a scan, but is that enough? I mean if the ErrorTable only has 2 rows, a seek is exactly the same as a scan!

So let’s dig deeper:

Trust_but_Verify_Query Table Scan Details

Query plan showing details for a scan

Trust_but_Verify_Query Table Seek Details

Query plan showing details for a seek

Here you can definitely see the dramatic improvement. Instead of reading in over 100,00 rows (at a bit over 2.5 KB per row, or over 270MB) we only need to read in 2 rows, for a total of just over 5 KB of data.

Now wonder it’s faster. In fact, in the ETL process where it was originally taking about 1 minute to process 1000 rows, my query with the index was now executing 3000 rows in under 10 seconds.

The above is a bit of a contrived example, but it’s based on actual performance tuning I did last week. And this isn’t meant to be a lesson in actual performance tuning, but more to show that if you make a chance (in this case adding an index) you can’t just trust it will work, but you should VERIFY that it has made a difference, and more importantly, that it makes a difference for your workload. I’ve seen GTA often make valid, but useless index suggestions because someone ran an uncommonly used query against it and assumed the recommendation was good. Or, they’ve made assumptions about the size of the table.

So never just trust an index will help, but actually VERIFY it will help.

 

“It’s a Jump to the left…

… and then a double-hop to the right.” Or something like that.

I’ve commented before on the fact that I’m a consultant. I enjoy it. People will ask me what I do, and it varies. At one client they refer to their VB app as “the database” and because they found an ad of mine on Google where I talked about database administration, they hired me. About 80% of the work I do for them is actually on the VB app or related, very little is actually what I’d consider traditional database work. But that’s ok, they’re a pleasure to work with and I enjoy the work. Another client I recently worked with, asked me to help them conduct an audit of their web based product and help them with some steps to make it more secure. I was more than happy to help.

And then there’s my largest, by far, client. I actually get to do a fair amount of work that most of my #sqlfamily would recognize as “database work”. But there, perhaps more than any other, I describe my duties as “DBA and other duties as assigned.”  So between the work at this client and all my other clients, I’m often jumping or stepping around stuff.

The Double-Hop

This time though I was asked to double-hop. What is that exactly? It’s an issue that has to do with how Windows can pass security credentials from one server to another. This article, while old, describes it well. This was essentially the situation my client was trying to solve: Users needed to use their Active Directory (AD) Credentials to log into the Reporting Server (RS_Server) and run a report that in turn accessed data on a separate database server (DB_Server), and thus, the double-hop. Now, from my point of view, this isn’t really database work, but since the reporting server talks to the database server it was dropped in my lap under “other duties as assigned.”

Now, honestly, this SHOULD be simple to solve. It wasn’t. One reason was in part because, like many companies, this client has a separate team that handles much of their infrastructure needs, such as AD requests. And they have to go through tickets. To be clear, I support this concept, in theory. In practice, it can often take 2-3 weeks for even simple requests to go through. This meant that my first attempt at solving the double-hop failed. Their IT department did exactly what I requested. Unfortunately there was a typo in my ticket. So it failed. So round two. And round two didn’t work. Nor did round three. At this point though it wasn’t due to typos or mistakes on my end.

I started reading every article I could. My great editor at Red-Gate, Kathi Kellenberger has one, and trust me I wasn’t too shy to ask at that point! But nothing was working. I even asked another DBA at the client (they actually head up a different group and is their lead DBA). She pointed me to one of her people saying, “talk to him, he solved it.” I did, and he hadn’t. His solution was the one we were trying to avoid (basically using a fixed user in the datasource).

Frustration Sets In

I was getting frustrated. Fortunately at this point I started to exploit a loophole in the ticketing process. Since the problem wasn’t being fixed, I was able to keep it open and ended up getting assigned someone from their IT group who was as interested in fixing this as I was. This meant rather than “open a ticket, wait 1-2 weeks, have ticket be closed as complete, test, find out it failed, rinse” we could now actually schedule Zoom sessions and make changes in real-time. AND…. nothing we tried worked.

At this point you’re probably saying, “Yeah, yeah, get to the point. Did you solve it?”  The answer is yes, but I wanted you to feel a bit of my pain first, and I needed to make this post long enough to make it worth posting.

A Solution!

Now, let me say, I wish I could write out an exact recipe card solution for you. For various reasons, I can’t. But bear with me.

Finally, we found an additional resource in the IT group who had solved this before. His first recommendation was yet again, the solutions I mentioned above. He saw they didn’t work, agreed we were trying the right thing. So he said, “well let’s try a solution known as “Resource-based Kerberos Constrained Delegation“. This didn’t work at first either.

But then he suggested that we turn on 128 and 256 bit encryption on the DB_Server SQL account. Bingo that worked. Mostly. More on that in a second.

So here’s the setup we ended up with.

  1. RS_Server – running reporting services under an account domain\RS_Server_Service
  2. DB_Server – running SQL Server under an account domain\DB_Server_Service
  3. Setup some SPNs
    1. MSSQLsvc/DB_Server domain\DB_Server_Service
    2. MSSQLsvc/DB_Server.domain.com domain\DB_Server_Service
    3. Note in this case you do not appear to need one on the RS_Server side.
  4. Run a Powershell script
    1. $FEIdentity1 = Get-ADUser -Identity domain\RS_Server_Service
    2. $BEIdentity = Get-ADUser -Identity domain\DB_Server_Service
    3. Set-ADuser $BEIdentity -PrincipalsAllowedToDelegateToAccount $FEIdentitity1
  5. At this point things should have worked, but they didn’t until we then enabled the encryption options:

    encryption options for Kerberos

    Kerberos Encryption

  6. Then on our test box, things magically worked! Ok, not quite magically, but things worked. We had a solution.

And I was even more ecstatic when later that day, I tested this on a second report server box we had and it too suddenly was working without any changes. And this was a box where we had NOT even setup an SPN for the original double-hop solution, so I was pretty confident that the Resource-based Kerberos Constrained Delegation was working. In addition, in the rsserver.config file, the only authentication enabled was NTLM.

The next step was to try this on a production server. In that case, I did have to reconfigure the service it was running under to use the domain account domain\RS_Server_Service.

And… my test failed.

I was at wit’s end. I couldn’t quite figure out what was different. I checked my service names, my SPNs, the rsserver.config file, and more. Nothing was working. I took a break and came back and had an idea. In the datasource I changed it from:

Data source=DB_Server;Initial Catalog=TestDB

to

Data source=DB_Server.domain.com;Initial Catalog=TestDB

Bingo, it worked! A little digging confirmed my suspicion. This client actually has multiple DNS domains and the ordering and like under the TCP/IP settings was different on this box from the other two boxes. And that made the difference.

Sure enough when I tried deploying to a fourth box, I had the same issue, but changing it to the Fully Qualified Domain Name (FQDN) solved my issue.

So, my take-aways for this week:

  •  Resource-based Kerberos Constrained Delegation may be a better solution at solving the Double-Hop solution than the solution generally proposed.
  • Once you’ve setup the “target” SQL Server service account and source Reporting Server Service accounts, additional reporting servers can be added to the mix without needing assistance from a domain admin.
  • It appears you still need an SPN (well multiple) for the SQL Server itself.
  • You need to run a PowerShell Script to setup the accounts. Note that if you run it again, it overwrites the old settings, so you need to add ALL of the source accounts in a single step.
  • Depending on your domains security setup, you may need to enable 128/256 bit Kerberos authentication.
  • DNS resolution may determine if you can use just the NetBIOS name or the FQDN in your data sources.
  • This solution will NOT work if you need to cross domains or have more complex setups, but in general, it can be simpler to setup and to maintain, especially if you have limited access to making changes to AD in the first place.
  • My reading indicates this only works on Windows 2012 and beyond. But you shouldn’t be running older versions of Windows in any case!

If I get the time and energy, I may setup a test environment in my home lab to further experiment with this and write up better demos, but for now, use this as you can. Hopefully it’ll save you some of the stress I experienced.

And that’s it from here, back to other duties as assigned.

 

 

Quiet Time and Errors

I wrote last week about finally taking apart our dryer to solve the loud thumping issue it had. The dryer noise had become an example of what is often called normalization of deviance. I’ve written about this before more than once. This is a very common occurrence and one I would argue is at times acceptable. If we reacted to every change in our lives, we’d be overwhelmed.

That said, like the dryer, some things shouldn’t be allowed to deviate too far from the norm and some things are more important than others. If I get a low gas warning, I can probably drive another 50 miles in my car. If I get an overheated engine warning, I probably shouldn’t try to drive another 50 miles. The trick is knowing that’s acceptable and what’s not.

Yesterday I wrote about some scripting I had done. This was in response to an issue that came up at a customer site. Nightly a script runs to restore a database from one server to a second server. Every morning we’d get an email saying it was successful. But, there was a separate email about a separate task that was designed to run against that database that indicated a failure. And that particular failure was actually pretty innocuous. In theory.

You can see where I’m going here. Because we were trusting the email of the restore job over the email from the second job, we assumed the restore was fine. It wasn’t. The restore was failing every night but sending us an email indicating a success.

We had unwittingly accepted a deviance from the norm. Fortunately the production need for this database hadn’t started yet. But it will soon. This is what lead my drive to rewrite and redeploy the scripts on Friday and on Monday.

And here’s the kicker. With the new script, we discovered the restore had also been failing on a second server (for a completely different reason!)

Going back to our dryer here, it really is amazing how much we had come to expect the thunking sound and how much quieter it is. I’ve done nearly a half-dozen loads since I finally put in the new rollers and every time I push the start button I still cringe, waiting to hear the first thunk. I had lived with the sound so long I had internalized the sounds as normal. It’s going to take awhile to overcome that reaction.

And it’s going to take a few days or even weeks before I fully trust the restore scripts and don’t cringe a bit every morning when I open my email for that client and check for the status of overnight jobs.

But I’m happy now. I have a very quiet dryer and I have a better set of scripts and setup for deploying them. So the world is better. On to the next problems!

Getting My Hands Dirty…

… and my clothes cleaned. Or more importantly, dried.

Before I was a programmer I worked for my dad in construction over the summers of high school. It was good solid work. I enjoy working with my hands at times. For one thing, you see and feel the results of your accomplishments in a very tangible manner. For another, you generally can measure the impact of your effort.

After my dad died, I wrote about using a drill of his to work on the addition that was to become my office. I liked the heft and feel of it. I knew I was accomplishing something with it. Being a programmer, sometimes it’s hard to experience that. Currently for example I’m working on an ETL script using PowerShell to SFTP down a file, extract it to some tables and then feed it into Salesforce. For me, it’s just a bunch of data. Yeah, there’s some fun challenges; learning how to setup and deal with GPG and designing a robust and secure information because some of the data is sensitive. But, once the project is finished, it’ll run silently and other than an occasional email, I won’t think much about it. It won’t impact my day to day life in any way and I won’t be able to point to it and say, “See, THERE is something I did.”

But, my dryer on the other hand, now that’s different. For awhile now (say at least a year or two) whenever I’ve run a load it’s made a fearsome rumbling sound. It’s been annoying, but we’ve managed to live with it up until 6 or 7 weeks ago. Generally I’d do most of the laundry on Sundays and if there was a load or two left, on Monday while everyone else was out of the house or at school. But obviously things changed. My wife’s office is in the room next to the laundry room. Whereas for me the rumbling was faint and simply background noise, for her it was quite noticeable.  I tried to work the loads around her work schedule, especially since she’s on so many conference calls for her job, but it was getting less and less practical.

It was finally time for me to do something about it. Now, had I been smart, I’d have started the project on a Monday. But, I’m not always that smart. So, Saturday came around and I disassembled the dryer.

I was fairly confident I knew what the problem was. I assumed that either something had wrapped around one of the rollers for the drum, or a bearing in a roller had seized. If it was the former, the fix would be trivial and I’d have the whole thing back together before dinner. If it was the latter, I figured a shot of silicone or other lubricant and I could at least get a few more weeks out of it while I ordered the parts. And since the tight screws were now loosened and I knew how to take it apart, the final fix would go quickly.

Well, as they say, you know what happens when one assumes. I was wrong about the first guess, it was not something as simple as something wrapped around the roller. And I was even more wrong about it being a seized or flattened bearing. See for that assumption to be valid the bearing assembly inside the wheel has to actually exist.

20200502_162747

Bearing Assembly? What Bearing Assembly?

It’s a bit hard to make out, but inside the blue part of the wheel above, and behind the plastic triangle, there is supposed to be a nice little bearing assembly.  There is none.

20200502_163501

Better view of the roller

You can see the wear on the inner hub.  This is what in the trade is called “less than optimal.”

More seriously though, it unfortunately meant that this was not going to be a quick fix. I had been planning on ordering the parts, but this made it a bit more of a rush. The dryer contains four of these rollers and as such I ordered a four pack, since generally my assumption on items like this is is that if one has worn, all four are worn. Now, none of the other three have shown nearly the damage, but figure, I’m in there, I might as well make it right.

What’s most interesting to me, is that there’s literally NO sign of the roller assembly in the dryer. However it got destroyed, it was pretty cataclysmic.

I also took the time to clean out the rest of the interior space and correctly deduced that the moisture sensor was covered with lint. Now that I know where it is, I can keep that clean in the future.

In any case, sometime later this week, I’ll get my package, swap out the rollers and reassemble the dryer and start doing laundry again. Quietly.

But, unlike the ETL I’m writing above, this change will have a direct noticeable impact on my life I’ll be aware of every time I do a load of clothes. I like that.

This week’s takeaway? I do enjoy my job and the challenges that come with it, but there’s something to be said for doing work you can touch and feel and experience the tangible impact.

20200505_090057

My best sourdough yet!

And perhaps I shouldn’t be posting pictures of homemade bread after talking about dirty hands. Don’t worry, I washed my hands!

An Ounce of Prevention?

There’s an old saying in medicine, “when you hear hoof beats, think horses, not zebras.”  Contrary to what one might think after watching House the truth is, when you get presented a set of symptoms, you start with the most likely, well because it is most likely! But as House illustrates, sometimes it can be the unlikely.

In First Aid, especially wilderness or backcountry medicine, there’s an acronym that is often used called SAMPLE. This is a mnemonic to help rescuers remember what data to gather:

  • S – Signs/Symptoms – What do you see, observe? (i.e. what’s going on).
  • A – Allergies – Perhaps the problem is an allergic reaction, or they might be allergic to whatever drug you want to give them.
  • M – Medicines – What medications are they on? Perhaps they’re diabetic and haven’t taken their insulin, or they’re on an anti-seizure medicine and need some.
  • – Past, pertinent medical history. You don’t care they broke their ankle when they were 5. But perhaps they just underwent surgery a few weeks ago? Or perhaps they have a history of dislocating their shoulder.
  • L – Last oral intake. Have they eaten or drunk anything recently. This will drive your decision tree in a number of ways.
  • E – Events leading up to the injury.  Were they climbing to the top of the cliff and fell, or did they simply collapse at the bottom? The former may suggest you look for a possible spinal injury, the latter probably indicates something else.

I’m reminded of this because of how I spent my Presidents’ Day.  I woke up and checked a few emails and noticed that two I were expecting from a client’s servers never arrived. I logged in to see what was going on.  It turns out there was nothing going on. No, not as in, “nothing wrong going on” but more as in “nothing at all was happening, the databases weren’t operating right.”  The alert system could connect to the database server, so no alerts had been sent, but actually accessing several of the databases, including the master resulted in errors.

Master.mdf corruption

Not an error you want to wake up to!

And what was worse, was the DR server was exhibiting similar symptoms!

So modifying SAMPLE a bit:

  • S – Signs/Symptoms – Well, databases are throwing corruption errors on two servers.  This was extended to the ERRORLOG files on both servers.
  • A – Allergies – Well, servers don’t have allergies, but how about known bugs? That’s close enough.  Nope, nothing that seems to apply here.
  • M – Medicines – I’ll call this antivirus software and <redacted>. (For client privacy reasons I can’t specify the other piece of software I want to specify, but I’ll come back to it.)
  • – Past, pertinent medical history.  Nothing, these servers had been running great up until now. One has been in production for over 2 years, the other, up for about 2 months, being brought up as a DR box for the first.
  • L – Last oral intake. Let’s make this last data intake. Due to forensics, we determined the corruption on both servers occurred around 3:00 AM EST.  Checking our logs, jobs, and other processes, there’s nothing special about the data the primary server took in at this time. If anything, disk I/O was lower than average.  And, fortunately, we can easily recreate any data that was sent to the server after the failure.
  • E – Events leading up to the injury. This is where things get interesting.
    • There were some zero-day patches applied to both servers over the weekend.
    • On Saturday, I had finally setup log-shipping between the two servers

So, we’ve got three possibilities, well four really.

  1. The zero day patches caused an issue about 48 hours later.  Possible, but unlikely, given the client has about 1600 servers that were also patched and have not had issues.
  2. Log-shipping somehow caused problems.  But again, the new log-shipping setup had run for about 36 hours without issue. And, best we can tell, the corruption occurred on the secondary BEFORE the primary. And log-shipping doesn’t apply to the Master database or the ERRORLOG file.
  3. Some unknown interaction.  This I think is the most likely and is where the <redacted> from the M above comes into play.
  4. Pure Random, and it’ll never happen again. I hate this option because it just leaves me awake at night.  This I added only for completeness.

Without going into detail, our current theory is that some weird interaction between <redacted> and log-shipping is our cause. Of course the vendor of <redacted> is going to deny this (and has) but it’s the only combination of factors that seems to explain everything. (I’ve left out a number of additional details that also helped us get to this conclusion).

So for now, we’ve disabled log-shipping and are going to make some changes to the environment before we try log-shipping again.

Normally I think horses, but we might have a herd of zebras on this one. And ironically, setting up for DR, may have actually caused a Sev 1 outage. So the ounce of prevention here may not have been worth it!

And who said my Wilderness First Aid wouldn’t come in handy?

 

 

Brake (sic) it to Fix it!

Last week I wrote about getting my brakes fixed. Turns out I made the right choice, besides shoes and pads, I needed new calipers.  Replacing them was a bigger job than I would have wanted to deal with. Of course it cost a bit more than I preferred, but I figure being able to make my car stop is a good thing. I had actually suspected I’d need new calipers because one of the signs of my brakes needing to be replaced was the terrible grinding and shrieking sound my left front brake was making. That’s never a good sign.

As a result I started to try to brake less if I could help it. And I cringed a bit every time I did brake. It became very much a Pavlovian response.

About two weeks ago, a colleague of mine said, “Hey, did you notice the number of errors for that process went way up?” I had to admit, nope, I had not. I had stopped looking at the emails in detail. They were for an ETL process that I had written well over a year ago. About 6 months ago, due to new, and bad, data being put into the source system, the ETL started to have about a half dozen rows it couldn’t process.  As designed, it sent out an email to the critical parties and I received copies.  We talked about the errors and decided that they weren’t worth tracking down at the time.  I objected because I figure if you have an error, you really should fix it. But I got outvoted and figured it wasn’t my concern at that point. As a result, we simply accepted that we’d get an email every morning with a list of rows in error.

But, as my colleague pointed out, about 3 months ago, the number of errors had gone up. This time it wasn’t about a half dozen, it was close to 300. And no one had noticed.  We had become so used to the error emails, our Pavlovian response was to ignore them.

But, this number was too large to ignore. I ended up doing two things. The first, and one I could deploy without jumping through hoops was to update the error email. Instead of simply showing the rows of errors, it now included a query that placed a table at the top that showed how many errors and in which tables. This was much more effective because now a single glance can easily show if the number of errors has increased or gone down (if we get no email that means we’ve eliminated all the errors, the ultimate goal in my mind.)

I was able to track down the bulk of the 300 new errors to a data dictionary disagreement (everyone raise their hands who has had a customer tell you one thing about data only to discover that really the details are different) that popped up when a large amount of new data was added to the source system.

I’ve since deployed that change to the DEV environment and now that we’re out of the end of the month code freeze for this particular product, will be deploying to production this week.

Hopefully though the parties that really care about the data will then start paying attention to the new email and squawking when they see a change in the number of bad rows.

In the meantime, it’s going to take me awhile to stop cringing every time I press my brakes. They no longer make any bad sounds and I like that, but I’m not used to to absence of grinding noises again.  Yet. In both cases, I and my client had accepted the normalization of deviance and internalized it.

I wrote most of this post in my head last week while remembering some other past events that are in part related to the same concept.  As a result this post is dedicated to the 17 American Astronauts who have perished directly in the service of the space program (not to diminish the loss of the others who died in other ways).

  • Apollo 1 – January 27th, 1967
  • Challenger – STS-51L – January 28th, 1986
  • Columbia – STS-107 – Launch January 16th, 2003, break-up, February 1st, 2003.

 

 

Them’s the brakes…

I need brake work done on my car.  I scheduled an appointment with my mechanic for Thursday.

Now normally brake work might not be worth writing about, but this time it got me thinking. About 9 years ago I taught myself to change the brakes on my Subaru. It wasn’t that hard, but it definitely took longer than I would have liked. I’ve learned how to do it much faster since then.

Back then I did it because I was between jobs and had more time than money. It made sense at the time. Since then I’ve generally continued to do them myself. It doesn’t take long and as I’ve said in the past, sometimes I like working with my hands. It reminds me not all of life is simply databases and servers.

So why this time? The simple answer is, my garage floor is cold!  Ayup, it’s a funny thing, but in the winter, things get cold! And honestly, I just don’t feel like sitting/laying on the concrete while I do the work. So, I’ll pay an expert who can pop it up on a lift and do the work in probably half the time I can.  I remind myself it’s why I work, so I can pay others to do work I don’t care to do, or that they can do better than I can.

Years back, at my last job as the Director, and later VP of IT, I changed our email provider from one company to another (don’t ask me who they were, I can’t recall over a decade later).  My team didn’t like this. They kept insisting they could run the mail servers themselves. I had no doubt that they could. Running an Exchange server isn’t the most difficult thing in the world. That said, I kept saying no.  For a simple reason: “we weren’t an email company!” Providing reliable email for a business like we were meant at the very least strong spam protection and of course high-availability with ideally geographic redundancy. This meant at least two Exchange servers, spam filters and more. This alone would have cost more than what we paid annually. Now add in the time my team would have spent on email issues, it just wasn’t going to be worth it.

And, we’re seeing that more and more with services such as Azure. Sure, many businesses run change their own brakes, err, run their own SQL Server. But more and more are outsourcing to platforms such as Azure. But there are still a number of companies that for various reasons don’t do that. Fortunately for them, there are consultants like me to help them with their servers. SQL Server has always been easier to maintain than some of its competition, especially when it was first available. But that has never meant it needed no intervention. Someone still needs to make sure that jobs are being run, that backups are available and more.

So, some days I change my own brakes because it’s fun and easy, some days I pay someone.  Some days my clients handle their own SQL Server issues, and other days, they pay me.

No real revelation here. No real advice on when to draw the line on outsourcing, just an observation. But in my case, my concrete is too cold, so I’ll pay someone else to do the dirty work.

Fixing a “Simple” Leak

I was reminded of the 80/20 rule yesterday as I was briefing my team on a project I needed them to work on.  Ok, actually I was telling my kids about this, but it was still for a project.

In this case, I was pointing out that 80% of the effort for a project often is used on completing only 20% of the project. Researching this a bit further, there’s an actual name for this rule: the Pareto Principle. We’ve probably all come across this rule or some variation of it in our lives.

While not exactly the situation here, the point I was trying to make with them is that sometimes when fixing a simple problem, the issues and work that spin off easily take 10 times as much time and effort as the original problem.

In this specific case, I was asking them to do what was essentially an annoying and dirty job, clean up some edges to sheetrock before I finally re-enclosed a portion of the basement ceiling. They started later in the day than I would have preferred, but honestly, as this project has been sitting on hold for a few months, a couple more hours didn’t really matter. That said, I think the actual work took them longer than they thought it would.

So what prompted yesterday’s work was a small leak that I fixed over a year ago.

Over the years, we had noticed a slight leak in the downstairs bathroom. It wasn’t always apparent, but it was slowly getting worse. Essentially water was soaking into the sheetrock and walls of the finished portion of our basement.

Now, I’m a fairly handy guy, I spent several summers in high school and a bit of college working for my father in the construction trade. While he’d point out my finish work needed more work, in general, if it’s involved in residential construction, I’ve done it and I can feel comfortable doing it. But, besides learning how to use the tools, I also learned an important lesson: no project is ever as simple as it appears. This is actually one reason I hate starting home-improvement projects. I know that it’s going to turn into a lot more work than it originally looks like. It isn’t exactly the 80/20 rule, but I’m reminded of it. So let me dive a bit into what was and still is involved in fixing this simple leak.

First, I had to identify where it was.  From lots of inspection, guesswork and experience, I guessed in the wall behind the tiles.  Ok, so that means, rip out the tiles and the plaster and lathe underneath.  That’s simple enough, and honestly fun, albeit it dusty.

Second, once the leak was found, replace the plumbing.  With modern Pex plumbing, that’s actually the quickest part of the work. So yes, actually FIXING the leak, took maybe an hour. I will note I also took the opportunity to move the showerhead up by about 9″. One thing I hate are low showerheads!

WP_20181223_001

New Pex plumbing to showerhead

But, hey, while I’m in here, I might as well run the wiring for a fan for the bathroom because it’s always needed one.  And given a weird quirk of construction in this house, the easiest way is to run it into the long wall of the bathtub/shower, then over to the outside wall and then up to the approximate location of where the fan will go.  So there’s another hour or two for a project to was started to fix a leak.

Oh and while I’m at it, let me take some photos with a tape measure in them of where the pipes are for future reference. So there’s a bit more work.

Great, the leak is fixed.

Except, obviously the shower can’t be used as is with open walls. So now it’s a matter of getting backerboard and putting that in, and sealing it.  What I used is waterproof as it is, so we left it at that. And I say we, because for much of this product both the kids were helping with it. And quite honestly, that’s where this part of the  project sat for months. The shower was usable, though a bit ugly.

But, we still had the basement to deal with. That meant ripping out the damaged sheetrock and studs that had rotted. That was fun. Not! For that I actually used a full respirator, body suit, and sprayed anti-fungal stuff liberally. Some of the water damage here was actually older than the bathroom leak and was due to poor grading and then more recently, runoff from the roof of my addition (a problem that gutters finally solved).

But hey, if we’re putting in new walls, might as well put in better insulation and if we can seal the old concrete (hint that went poorly) and oh, put in a couple of dimmable lights for a work area and some network jacks.

WP_20190106_001

Basement wall in progress

Once that was all roughed in, it was time to at least sheetrock the walls.

WP_20190106_004

Sheetrocked walls

And that is basically where the basement project sat until yesterday. I’ll come back to that in a minute.

As for the bathroom, there was only so long I wanted to look at the backerboard. It was time to finally tile it.  Oh, but before I could do that, I had to put that fan in. Besides finding just enough room in the outside wall between the framing for the 2nd floor and the window and other vagaries, it just fit. Of course that was just 1/2 the battle. The other 1/2 was then wiring up the switch. Oh and while I’m at it, might as well run a circuit for a GFCI outlet since the bathroom was lacking one.  Once all that was done, THEN, I could tile.

WP_20190804_001

Tiled and Grouted

And yes, you may note the window does intrude into the shower space. Hey, I didn’t build the house!  What you can’t see is the replaced trim on the top edge and left edge of the tile that my daughter literally spent hours sanding and resealing. It looks great.

Oh and I still have to find replacement cones for behind the handles! So that’s another thing to do for the project.

But back to the basement. The area in front of the wall has become my son’s de facto computer space when he’s home from college. It was ‘good enough’.  But the ceiling still needed its sheetrock replaced and I needed to tape and paint the new wall.  This has waited until now.

The problem with the ceiling is when I pulled down the old stuff, I didn’t have nice clean edges to butt the new sheetrock against.  It was ragged where it had broken, or broke at awkward places so I couldn’t easily put in new sheetrock.

But I also took advantage of this time to reroute all my network drops so they will be hidden in the ceiling and come out nicely to my rack.

So yesterday, the kids did the dirty work of trimming the edges, cleaning stuff up, etc. It looks great and will make my job of sheetrocking much easier.

20200121_081823

Open basement ceiling

By the way, I should note that the board you see sticking out is what I had used in the past when I had to slide in here to do some wiring or other work. This was sort of my own private Jefferies Tube. This should now be relatively easy to sheetrock, right?

Well, except for one small detail.

20200121_081837

Houston, we have a problem.

Yes, that is a piece of electrical cable that was run OUTSIDE the studs and essentially between the join of where two pieces of sheetrock met at an inside corner.  I absolutely HAVE to move this before I can sheetrock.

So that’s going to be a few more hours of work before I can even start to sheetrock. I have to identify which circuit this is, cut power, cut the wire, reroute it, put the ends in a junction box (which code says can’t be hidden!) and then make sure it’s safe.

After all that work, I can finally get around to sheetrocking the ceiling. Then I’ll have to mud and tape all the joints, sand, mud again, prime and then finally get the walls and ceiling painted.

But the good news is, the leak is fixed. That was the easy party!

Does this “simple” project of fixing a leak remind you of any projects at work? It does for me!