Adventures with SQL Server & perfmon Part 2: TokenAndPermUserStore & spinlock suspects

Sick day from work, so I just might finish two blog posts in one day :-)

This is the same system from the previous post about query memory.
Adventures with SQL Server & perfmon Part 1: Resource Governor & Query Memory

Its from the following week, with a very similar query batch executing on the system.  Because the cores are licensed for SQL Server, and part of my job is making sure the system delivers value for its cost, I want to make sure that: 1) the cores are doing meaningful work 2) the cores are kept busy.  In the last post, I looked at a few timeperiods where CPU busy percent slacked off a bit, and it was easy to see that at that point, pending query memory grants was limiting the query concurrency.  And I put the other concern off to the side... two obvious timeperiods that SQL Server %CPU busy seriously broke away from the number of logical IOs performed in query execution.

Lets take a look at that now, in this later day on the same system. 







CPU (Red) = \Process(sqlservr)\% Processor Time
Buffer Page Lookups (Blue) = \SQLServer:Buffer Manager\Page lookups/sec

Still two extended periods, highlighted in green above, where CPU utilization by SQL Server is trending far above the logical IO performed by query worker threads.

When I see that for an extended period of time, I first try to determine if spinlock contention is the culprit.  I've often heard from others that "spinlock contention is rarely the cause of extended high CPU utilization."  That may be true on most SQL Server systems... maybe even almost all SQL Server systems.  But I'll tell ya... I've had a pretty good run at finding and addressing spinlock issues.  And the first sign I look for is timeperiods with significant disconnect between CPU utilization and database logical IO as indicated in the graph above.

As luck would have it, over the last year many of the spinlock contention situations I've looked at have been accompanied by CMEMTHREAD waits.  Fortunately for me, these can actually be trended via the perfmon "SQLServer:Wait Statistics" object, which refers to them as "Thread-safe memory objects waits".  For lots of good information about CMEMTHREAD waits, see this CSS Engineers Blog Post from Rohit Nayak:
How It Works: CMemThread and Debugging Them

This particular system already has trace flag 8048 active, to mitigate query memory allocation spinlock contention by promoting the memory serialization resource to per-CPU rather than per NUMA node/scheduler group. 





CPU (Red) = \Process(sqlservr)\% Processor Time
CMEMTHREAD (Medium Blue)= \SQLServer:Wait Statistics(Waits started per second)\Thread-safe memory objects waits
Requests Completed  (Dark Blue) = \SQLServer:Workload Group Stats(RG1)\Requests completed/sec, cumulative
Object Plan Pages (Light Blue) = \SQLServer:Plan Cache(Object Plans)\Cache Pages

So this is the part where I omit a lot of the bumbling and fumbling I do while trying to find out which measurements just might be relevant to the behavior I'm trying to understand. Trust me, there's a lot of bumbling.  But I eventually settled in this case for including CMEMTHREAD waits started, cumulative requests completed for the Resource Governor workload group, and Plan Cache object pages.

In the first timeperiod, from 9:00 am to almost 10:15 am, there is a ton of CMEMTHREAD wait starts.  I know that they often accompany spinlock activity.  And in the recesses of my mind I remember... wasn't this the system that I'd always heard rumors about server restarts, SQL Server restarts, and sometimes failovers to address an undiagnosed performance concern?  That's why I decided to throw the object plan pages into the graph, after looking at how other components of "\SQLServer:Plan Cache" fit the mold.

So a significant drop in object plan pages seems to accompany a better fit (for a while) of CPU utilization to database logical IO.  Hmmmm...

My first thought was that we should monitor the workload after running "dbcc freeproccache" next time around.  But I also did a lot of research.  And what I came up with was TokenAndPermUserStore cache.

Queries take a longer time to finish running when the size of the TokenAndPermUserStore cache grows in SQL Server 2005

http://support.microsoft.com/kb/927396
Potential workarounds suggested:
FORCE PARAMETERIZATION database option
Add user account to sysadmin server group
Periodic DBCC FREESYSTEMCACHE ('TokenAndPermUserStore')

A gradual increase in memory consumption for the USERSTORE_TOKENPERM cache store occurs in SQL Server 2005
http://support.microsoft.com/kb/933564
This KBa introduces trace flag 4618, which can be used to limit the size of the TokenAndPermUserStore cache.

How to customize the quota for the TokenAndPermUserStore cache store in SQL Server 2005 Service Pack 3
http://support.microsoft.com/kb/959823
This KBa introduces trace flag 4610.  Alone, trace flag 4618 limits TokenAndPermUserStore to 1024 entries.  Add trace flag 4610, and that increases to 8192 entries.
This KBa also introduces trace flag 4621, which works with Windows registry setting "TokenPermQuota" to control the size of TokenAndPermUserStore.  Add trace flag 4610 to 4621, and the "TokenPermQuota" should increase by a factor of 8.

Query Performance issues associated with a large sized security cache
http://blogs.msdn.com/b/psssql/archive/2008/06/16/query-performance-issues-associated-with-a-large-sized-security-cache.aspx
I always love reading what the CSS engineers have to say :-)

How is anyone supposed to know how to use trace flag 4621?

http://www.techurbia.com/2009/03/how-is-anyone-supposed-to-know-how-to-use-trace-flag-4621.html
This is a great blog post... my favorite line being:
"Oh wow is this not easy stuff to wade through.."

Finally... 
Description of the "access check cache bucket count" and "access check cache quota" options that are available in the sp_configure stored procedure
http://support.microsoft.com/kb/955644
OK... this is the most relevant to SQL Server 2008R2, 2012, & 2014... the versions I spend most of my time with.  Those versions are actually listed in the "Applies to" section.

So what to do?  In this case, we'll start with monitoring the cache size from the DMVs over time.  After getting some baseline data of the cache size and additional perfmon similar to that above, we'll put in some timed executions of the following and see how that changes the mix:
DBCC FREESYSTEMCACHE ('TokenAndPermUserStore')

Hopefully by doing that, we can find a reasonable size limit for TokenAndPermUserStore.  In the worst case, clearing this cache will not improve performance and then I'll have to come up with a new theory.  But if my theory holds and we find a reasonable limit, should be able to use "access check cache bucket count" and "access check cache quota" in order to implement the limit, rather than the Windows registry setting and/or any of the trace flags.  Bet you thought you'd never find me looking for a way NOT to implement a trace flag! :-)

Lets look at this graph again - because it was a long ways up there in this blog post and I've got a bit more to talk about.



All things considered, I feel really good about my hunch for the approximately 9:00 am - 10:05 am query slowdown.  If it turns out I'm wrong I'll fess up and share what I learn.

But what about 11:00 am - 11:15 am? (For some reason blogger would move the green box over if I tried to box only 11:00 - 11:15, so the box is a little bigger than the timeperiod I'm concerned with.)  Way fewer CMEMTHREAD waits at that time.  And even though Object Plan pages is now just a proxy for TokenAndPermUserStore, which I suspect to be more closely related... I think that when we monitor TokenAndPermUserStore size, we'll see its not involved in that second slowdown.

My first rule of spinlocks - get the big ones out of the way before setting your heart on diagnosing secondary conditions :)  But I'd better come up with some ideas now, that I can pursue once the first spinlock issue is out of the way.  If by some miracle solving the first timeperiod also gets rid of the second - great!  If not, I'll have a hunch to pursue from the get-go.

OK... I added the cumulative "requests completed" to the graph for this reason.  From 11:00 am to 11:15 am the pace of request completion is noticeably higher than the pace of request completion from 9:00 am to 10:05 am.

To me, this suggests two things: the rate of incoming connections was greater, and the rate of plan compilation was greater.  Unfortunately I didn't capture "Logins/sec".

That's too bad.  Its a pretty good suspect because of this:
Performance problems occur when database lock activity increases in SQL Server
http://support.microsoft.com/kb/2926217
This SQL Server 2012 KBa introduces trace flag 1236 (SQL Server 2012 SP1 CU9 & beyond), which partitions the previously global resource used for SH-DATABASE locks when establishing database context.

But plan compiles are also a potential suspect, because of this SQL Server 2012 SP1 CU10 fix.
Intense query compilation workload does not scale with growing number of cores on NUMA hardware and results in CPU saturation in SQL Server 2012
http://support.microsoft.com/kb/2928300

So if I get rid of "Object Plan Pages", which was really just a proxy anyways, and the "Requests Completed", which was another proxy... I can add "\SQLServer:SQL Statistics\SQL Compilations/sec" to the graph, hopefully without the graph becoming too busy to be useful.  

 

Uh-huh.  During 11:00 am to 11:15 am, there certainly is a decrease in CMEMTHREAD wait activity. But its still present to a degree.  And there is more compile activity.  So on this system, we'll address the TokenAndPermUserStore - or end up exonerating it and looking for another suspect.  And once SQL Server 2012 SP1 CU10 is in place, concurrent query compiles will benefit from kb2928300, and trace flag 1236 can be used to reduce spinlock contention during heavy concurrent logins to the same database.

I'll let you know how it goes. 

****
Same day update :-)

Might as well throw these graphs in here, too.  Differential spinlock information is captured every 5 minutes.  These are the only spinlocks of interest numerically from the data.  Not that the primary and secondary axes for the spins graph are different by a factor of 2000, while the backoffs are only different in scale by a factor of 40. 

 





 

Adventures with SQL Server & perfmon Part 1: Resource Governor & Query Memory

CPU cores are the licensing metric for SQL Server.  So, some of my goals are to keep 'em busy, and to make sure they are busy with meaningful work. :-)

I always look at graphs of CPU busy against logical IO, regardless of the database platform, to get an idea of performance and resource utilization. Perfmon supplies most of what I look at for SQL Server, although sometimes I scrape the DM views/tables/functions/whatsits and sometimes I have to resort to extraordinary measures (like monitoring in-memory transaction log buffers).

The system in this post has 48 logical CPUs.  Resource governor is enabled, and workload group RG1 is associated with resource pool RG1.  There's more to the Resource Governor config... maybe I'll get into the goals and the rest of the config another day.


The graph below shows two types of time periods that are concerning to me.  In green are time periods of very high CPU utilization by SQL Server, but relatively low logical IOs, or buffer page lookups.  I want to investigate those areas for "management overhead" - maybe spinlock or latch contention that can be avoided somehow.  On the systems I watch, that can be especially fruitful.  That's because in general, query compile/recompile total cost is typically low, and there isn't much XML shredding or other high CPU-cost instruction sets specified within most of the queries.  But lets save spinlock and latch contention hunting for another day. :-)  Sorry @sqltrooper!!

In orange are time periods of fairly low CPU utilization.  I know the workload context - this was all part of a batch workload that should have a fairly constant number of concurrent requests/queries executing at all times.  That can be verified, among other ways, by checking activity logs for the client(s) that submit the queries.  So if there is low CPU utilization at some point... maybe query concurrency is lower than expected, or maybe the parallelism of the queries is lower than expected (eg maybe some of the queries expected to be parallel are forced to serial).

SQL Server %CPU = \Process(sqlservr)\% Processor Time
Buffer Page Lookups = \SQLServer:Buffer Manager\Page lookups/sec


When checking query concurrency within a Resource Governor group, the graph below has the items I like to check first.







RG1 Grants (Dark Blue) = \SQLServer:Resource Pool Stats(RG1)\Active memory grants count
RG1 Pending (Light Blue) = \SQLServer:Resource Pool Stats(RG1)\Pending memory grants count
RG1 Qx Mem Target (Dark Red) = \SQLServer:Resource Pool Stats(RG1)\Query exec memory target (KB)
RG1 Qx Mem (Light Red) = \SQLServer:Resource Pool Stats(RG1)\Active memory grant amount (KB)

From 9:00 am to 10:00 am there are a high number of grants, but not much aggregate granted query memory.

Between 10:30 am and 11:00 am, though, a problem crops up (not that there wasn't a problem from 9:00 - 10:30... I guess I should say that's when the problem I want to talk about today crops up).  The granted memory has climbed, even though the number of outstanding grants has dropped.  The number of potential queries is still roughly the same... but the pending grants have increased and outstanding grants have dropped.  Active query concurrency has dropped.

The granted query memory in this pool peaks at about the same time the query exec memory target drops.  That's unfortunate.

The same thing happens for a shorter period of time right around noon.  Fewer queries with high total granted query memory, and at peak aggregate query memory the target drops.  Pending query memory grants are high throughout, and the peak of pending grants is correlated to the peak in granted query memory and the attending drop in query memory target.

So... identify the queries running during those time periods.  They are asking for a lot of query memory - so much that its limiting query concurrency and keeping the CPUs from doing as much work as they could.

Are these queries suffering from "eyes bigger than stomach"?  In such cases, they request far bigger grants than they would EVER use.  Additional help can be pulled in by polling sys.dm_exec_query_memory_grants.
http://msdn.microsoft.com/en-us/library/ms365393.aspx
In cases like this, I poll for the following and associate with plan_handles: 
ideal_memory_kb - how much would it put in a grant request if RAM on the system were absolutely gargantuan? 
max_used_memory_kb - what's the most its used in this execution of the query? 
used_memory_kb - how much is it using right now?

Then I can grab the plan from plan cache, and start poking around.  Honestly... I'm not much good for tuning individual queries.  :-)  I'm a systems guy... at least for now.  Sometimes I can tell that a missing index will make all the difference in the world.  Sometimes I can tell a scalar udf is causing the ideal memory/memory grant request to explode.  If its a stats problem... maybe I can figure out what the problem is.

But, at any rate, this is how I can find problem queries, then hand them over to folks that are wwwaaayyy better than me at query tuning.  With data to show the system cost of current behavior.  :-)


 

Windows Wait Queue & Emulex FC HBA Service Queue Depth

So... either I use ASCII art for a few illustrations or it might be another year before any of this appears on my blog :)

Operating systems and storage device drivers track storage IO requests in wait and service queues, in order to properly acknowledgement success (for writes) or return data (for reads).


t0 - there are no outstanding IO requests but 3 process threads are ready to submit disk IOs.

The wait queue and the service queue are empty.



\W   R   W/    <=Threads submitting disk IO requests
 \       /

    | |
    | |
    | |
    | |        <= Wait Queue
    | |
    | |
    | |
    | |

  --------
               <= Service Queue
  --------

t1 - the disk IOs are submitted.  Because there were slots in the servie queue free, the requests went right into the service queue.
The application threads don't just forget about their IO requests, even if the read or write was asynchronous.  For a synchronous read or write, thread progress is at a standstill until the request is answered.
For an asynchronous read or write, the thread will poll for the answer.  Various activities will have limits on the number of outstanding async IOs they will will tolerate while still allowing additional work to be done by the thread.
As an example, the SQL Server transaction log writer will allow 32 inflight writes per transaction log, or at total of 3840k of inflight writes across all transaction logs.  
Anyway... the service queue has a "queue depth" but conceptually I usually think of it as wide.

\w   r   w/    <=Threads submitting disk IO requests
 \       /

    | |
    | |
    | |
    | |        <= Wait Queue
    | |
    | |
    | |
    | |

  --------
       WRW     <= Service Queue
  --------
t2 - the writes completed more quickly than the read - as is often the case.  The ack of success has already been returned.  So now there is only 1 outstanding IO request - its the in-flight read.
But - goodness! Query spill!  Lots of threads are getting ready to submit writes to tempdb!

\WWW r  WW/    <=Threads submitting disk IO requests
 \       /

    | |
    | |
    | |
    | |        <= Wait Queue
    | |
    | |
    | |
    | |

  --------
        R      <= Service Queue
  --------

t3 - All of the outstanding IO requests are in the service queue - the newly submitted writes and the hold-over read.
\www r  ww/    <=Threads submitting disk IO requests
 \       /

    | |
    | |
    | |
    | |        <= Wait Queue
    | |
    | |
    | |
    | |

  --------
    WWWWRW     <= Service Queue
  --------
t4 - Thank goodness!  All of the outstanding IOs have completed.  Back to normal, and all quiet for disk IO.

\         /    <=Threads submitting disk IO requests
 \       /

    | |
    | |
    | |
    | |        <= Wait Queue
    | |
    | |
    | |
    | |

  --------
               <= Service Queue
  --------


But there's always another day!

Lets join this day in progress - due to a few concurrent parallel queries there are plenty of reads!


t0 - the service queue is full of reads - with more in the pipeline ready to be submitted!
\RrR rR Rr/    <=Threads submitting disk IO requests
 \rrrRrrR/

    | |
    | |
    | |
    | |        <= Wait Queue
    | |
    | |
    | |
    | |

  --------
  RRRRRRRR     <= Service Queue
  --------
t1 - an instant later, and the app threads have submitted the read requests.
But the previous reads haven't returned yet, and they've filled the service queue.  So into the wait queue they go.

\rrr rr rr/    <=Threads submitting disk IO requests
 \rrrrrrr/

    | |
    | |
    |R|
    |R|        <= Wait Queue
    |R|
    |R|
    |R|
    |R|

  --------
  RRRRRRRR     <= Service Queue
  --------

t2 - the first 8 Reads have all returned, and the 6 Reads previously in the wait queue are now in the service queue.

\r r  r r /    <=Threads submitting disk IO requests
 \   r  r/

    | |
    | |
    | |
    | |        <= Wait Queue
    | |
    | |
    | |
    | |

  --------
    RRRRRR     <= Service Queue
  --------
t3 - all quiet again, nothing left outstanding in the wait or service queue.  But... let's talk latency.  The last 6 reads to complete in this scenario had some amount of time spent in the wait queue.
In fact, adding their wait queue time (which is determined by how long it took for a service queue slot to open up) and their service time, these reads may have taken twice as long as they would have on an uncongested system.
That's because the reads were wiating for other reads to complete - assuming a constant average read latency - which is never actually the case ;-) - these unfortunate reads may have spent the same amount of time in the wait queue as they did in the service queue.
Hmmmm


That brings to the penultimate scenario I wanted to share today.

In the scenario below, the service queue is full of reads that were just submitted (queues were empty previously).  Writes have also been submitted - they are in the wait queue.  Assuming all of these disk IOs were submitted within microseconds of each other, and assuming a 15 ms average read service time and 1 ms average write service time... what will the resulting average read and write latency be?

\rrrrrrrrw/    <=Threads submitting disk IO requests
 \wwwwwww/

    |W|
    |W|
    |W|
    |W|        <= Wait Queue
    |W|
    |W|
    |W|
    |W|

  --------
  RRRRRRRR     <= Service Queue
  --------
The read latency average will be 15 ms.  None of the reads spent any time in the wait queue.

The write latency is a different story however.  The average write latency will be 16 ms.  Why?  Each write spent 15 ms - the read service time - in the wait queue before getting into the service queue.  Service time once in the service queue took 1 ms, so each of the 8 writes experienced the average latency of 16 ms.


On a system with write cache, Write latency greater than read latency for any sustained period of time is always a sign of a performance concern.  Its generally one of four things:
1. overhead due to storage level replication
2. Write cache saturation
3. SAN CPU saturation
4. IO queuing

In this case it was IO queuing that lead to average write latency greater than average read latency.

OK... now for me to explain just how inadequate my ASCII art really is :)
If there is an Emulex fibre channel HBA on the Windows server, it allows setting a per LUN service queue depth.  (Default LUN queue depth for Emulex is typically 32.)
The Windows wait queue is interesting - rather than a one-size fits all, the wait queue is defined such that the sum of service queue depth and wait queue depth is 256.
If you watch "Current Queue Length" numbers in perfmon long enough... you'll believe me even if right now you are skeptical. :-)
That number just won't go above 256.

So what is the absolute worst case latency for a write, assuming constant read service time of 15 ms and constant write service time of 1 ms?

Well, lets assume a service queue depth of 32 - and fill it with reads.  Lets put another 6*32=192 reads in the wait queue, followed by 32 writes in the wait queue, with all 256 of these IOs submitted within microseconds of each other.  That fills not only the service queue, but the wait queue as well.
The writes are the last to finally make it into the service queue.
But they have waited for 7 rounds of reads at 15 ms each to complete - they've spent 105 ms in the wait queue.  Their service time is as expected - 1 ms.  But average latency is 106 ms.  For writes, that's horrible.

OK... here's a kicker: this matters even if you are using SSDs.  If the service queue depth is still 32 and there are 256 total outstanding IOs to the drive... those last IOs in the wait queue have some time to wait before they finally get into the service queue.
I've seen all flash systems deliver a level of performance that is easy to obtain with hard drives because of host queuing issues.
Try not to to let that happen to you :-)

OK... now sometime soon when I'm feeling brave I'll come back to this and take on QLogic and the execution throttle.  Its similar to LUN queue depth, but has a set of considerations all its own.  And I haven't figured out how to represent it in ASCII art yet :)

SQL Server Resource Governor Resource Pools and Perfmon

Wow... add some Resource Governor Resource Pools with memory partitioning, and there can be some wild swing in "Query exec memory target (KB)" values.  So I'll stumble around until I understand the relationships among some of these perfmon counters and the stuff reported by the DMVs.


SQL Server, Resource Pool Stats Object
http://technet.microsoft.com/en-us/library/cc645958.aspx?ppud=4


SQL Server 2008 R2
For Resource Governor resource pool ssmypool, if neither of the counters are changing due to broker  grow/shrink hints, "SQLServer:Resource Pool Stats(ssmypool)\Query exec memory target (KB)":"SQLServer:Resource Pool Stats(ssmypool)\Cache memory target (KB)" will settle to a .9375 ratio.



"SQLServer:Resource Pool Stats(ssmypool)\Query exec memory target (KB)":"SQLServer:Resource Pool Stats(ssmypool)\Target memory (KB)" ratio will be nearly 80%* and stable when the previous ratio is .9375.






*I was actually observing a 0.791015625 ratio while stable.  Go figure.

Database Performance Investigation/Intervention, MTPoD, Last Resorts

In business continuity and disaster recovery planning, one of my favorite foundational ideas is Maximum Tolerable Period of Disruption, or MTPoD. Although most effort and budget will be invested in defining and implementing RPO and RTO, during a crisis having a settled MTPoD can guide the team and resources, and there can be some level of confidence if a last resort is considered or employed.

Although most of my work these days focuses on performance and scalability rather than BC or DR, I'm a "last resort" kinda guy - and this is a "last resort" kinda blog. I didn't plan for this to be my position, but I ain't complainin' either :-)

See, there is room - even a need, I believe - in performance and scalability work for "last resorts". In order to be confident when considering performance/scalability last resorts, I believe MTPoD is very important.

An ideal performance/scalability investigation and intervention may look like this:

1. User feedback, task monitoring, or system monitoring triggers investigation

2. Activity, performance, resource utilization, error, and change logs are reviewed and compared between baseline and problem contexts.

3. Potential suspects are identified, and additional diagnostic monitoring may be put in place in production.

4. Problem recreation attempted in nonproduction environment.

5. If initial nonprod recreation attempts are unsuccessful, the additional production diagnostics may give more insight into reproducing the problem.

6. If problem is reproduced in nonproduction, further diagnostics can be performed there. That's important because sometimes conclusive diagnostics are too invasive or consume too many resources for production environments.

7. At this point, production or nonprod diagnostics may have a tentative, or even conclusive diagnosis.  Corrective actions can then be implemented and validated in nonproduction.

8. Even if the issue cannot be reproduced in nonproduction, the absence of harmful side effects of potential correctives, such as a SQL Server sp or cu install, can be tested in nonprod.

9. Correctives can be promoted to production per change control processes.

10. Correctives in nonprod and prod are evaluated against expectations. Process iterates to step 2 if necessary.

But... sometimes it's even uglier than that.  Sometimes, system behavior is truly unhealthy... despite pulling in experts for weeks... gathering lots of diagnostic data... addressing evident tuning opportunities... the system is still unhealthy.

I'm an advocate for understanding database system behavior - healthy and unhealthy.  But I also know that there are times for last resorts... sometimes service disruption comes near to MTPoD. I've been there. And I've called for action... sometimes in a room of folks who look at my whiteboard scribbles and think I may not be in my right mind... and sometimes while other experts are voicing the protest that they have never "seen that work".  

I haven't always been right in those situations. I believe in stating my level of confidence, and not sugar-coating the risks.  But often, when I'm involved its because the situation is already kinda desperate.

And, if I've had access to the diagnostics I ask for... I feel pretty good about my track record of being right :-)

Database erformance and scalability investigation/intervention is tough work.  It's complex, in both breadth and depth.  It's risky.  Ask for a downtime to implement a "fix"... and if the benefit isn't evident afterward you may have burned a lot of trust.  (That's one reason I believe in expressing confidence level for both diagnoses and remedies.)  And if MTPoD is approaching, standard process may need to be suspended: maybe possible correctives need to be implemented even though potential diagnoses are highly speculative, maybe exceptions to normal change control need to be employed.  Having a sense of MTPoD can minimize regret when performance investigation/intervention deviates from standard operating procedure.*

*When an extraordinary "fix" resolves an issue that had no strong suspect for diagnosis, I do recommend continuing to pursue diagnosis in post-Mortem analysis.  Sometimes, though, the nature of the previous problem won't be uncovered without an unreasonable cost.