一次查找sqlserver死锁的经历

查找bug是程序员的家常便饭，我身边的人喜欢让用户来重现问题。当然他们也会从正式服务器上下载错误log，然后尝试分析log，不过当错误不是那种不经思考就可识别的情况，他们就会将问题推向用户，甚至怪罪程序依赖的平台。他们常用的借口就是“这个问题很难重现，需要持续监控，而且不知道要监控几天”。下次出现，同样是这个说法。

编程珠玑一书的作者说，“对付问题而不是程序”，这是方向。程序员一旦有了方向就是全世界最聪明的人，反之则会用最聪明的头脑做最蠢的事情，说最蠢的话。查找错误的方向就是基于科学的方法理解问题、解决问题。

查找错误的一般方法

列出问题出现的可能原因(清单)。

针对问题发现的可能性进行排序清单。

假设问题就如清单其中一项所述，然后(编写程序)去重现问题。

循环3，并且在不可能出现的行画上一条删除线。

你可以说，这是穷举法。以下是查找问题的过程简述。

问题描述

前几天被突然叫到会议室，老板让暂停所有的工作，优先处理一个紧急问题。然后屏幕上出现了以下的一段log：

“事务(进程 ID 78)与另一个进程被死锁在 锁 资源上，并且已被选作死锁牺牲品。请重新运行该事务。; nested exception is com.microsoft.sqlserver.jdbc.SQLServerException: 事务(进程 ID 78)与另一个进程被死锁在 锁 资源上，并且已被选作死锁牺牲品。请重新运行该事务。” (后面的几乎类似，除了ID编号和时间，所以就省略了)

看完了log，老板接着说明这个问题的紧急性--系统正处于验收阶段。

列出可能的清单

针对这个问题，我google了一下，发现大部分文章描述sqlserver的死锁时，经常谈到两种场景。

场景1：

事务A: delele from table1 where id= 1; select * from table2; 事务B: delele from table2 where id= 1; select * from table1;

要理解这个场景，首先要了解两种锁的区别：X锁和S锁。简单的说，就是当试图删除、更新表时，我们会在该表上加一个X锁，这个X锁是排他锁，影响是除非表上的X锁被释放，不然其它人无法再加如何锁；而S锁是一个共享锁，它允许同一时间有多个共享锁存在，但是除了X锁以外。

假设场景1是并行执行的，事务1开始对table1加上了X锁，同时事务2也对table2加上了X锁。接下来它们又分别试图请求，在对方已经加上了X锁的表上加上S锁。从前面得知，X锁是排他锁，而事务的特性是，所有的锁资源都会在事务完成以后才释放。 这时候事务间各自拥有对方请求的资源，又同时请求对方拥有的资源，并且要释放自身的资源，先要请求到对方的资源，就发生死锁了。

场景2：

事务A：delete from table1 where id =(1,..,n); 事务B：select c1,c2,c3 from table1 where id = (1,..,n)； table1的索引如下，物理索引id，逻辑索引c1,c2。

据说这个场景的死锁比较普遍，但是很难理解，因为它们由始至终只操作一个表。要理解这个，还需从sqlserver中的bookmark search说起:如果select 语句中，查询的栏位不包含在逻辑索引中，比如c3，那么sqlserver将试图在使用物理索引id来查找c3的值。

现在再来看一下过程中发生的锁，select语句会在逻辑索引(c1,c2)上加上S锁，然后为了返回不在逻辑索引的栏位(c3)，它还需要在物理索引(id)上加上S锁；而更新呢？我们都知道，更新表时，我们需要对物理索引(id)加上排他锁以完成表的更新，并且随后还会被要求更新逻辑索引(c1,c2)。所以事务A先请求对id列的X锁，随后请求c1,c2列的X锁；而事务B会先请求c1,c2的S锁，接着请求id的S锁来返回c3的值。死锁就这样发生了。

幸亏这个场景发生的前提是频繁查询以及频繁更新表。

至此，我们的清单中有了两项场景1与场景2。根据2/8原则，先尝试最有可能的往往事半功倍。我随之放弃了猜测，马上进入验证阶段。开始先给它们排个序，我将场景1放在第一项，原因是它比场景2更容易被发现。因为场景2的特点是随机，即使有这样的两个事务并发(这种情况太普遍了)，死锁也是很难出现。

重现问题

假设清单第一项(场景1)是问题的原因，那么它应该是这样的：系统中肯定存在这样的两个事务，一个事务对产生死锁的表(暂时称为deadlockedtable)读取，并且对另外的表(暂时称为causelockedtable)更新；而另一事务对deadlockedtable更新，对causelockedtable读取。

以此，我查找了项目的所有事务代码，没有找到。

接下来，我在这个选项上划上一条删除线。

开始选择清单的下一项，然后继续

关于场景2在系统中的确存在，这要从系统的业务谈起，出现错误的系统是一个考勤管理系统，客户公司有大约2000人使用系统，系统每天凌晨都会计算2000人当天的考勤排配表。由于公司严格的考勤机制，员工上班前都会查看自己当天的考勤排配表；对于那些请假、出差的员工，他们在系统中请假被批准后，系统需要重新计算其考勤。这里一直提到考勤结果，是因为出现死锁的表就是考勤结果表，而出现死锁的时间刚好为员工上班高峰期及凌晨计算全公司员工排配表两个时段，并且很随机及短暂。

这和场景2描述的很类似--频繁更新和查询。

问题时如何重新这个异常。

2000人的公司，由于三班倒的机制，我按照大约只有二分之一的员工在某个点上班，1/10的并发几率，100个并发。该公司的员工总有5%左右的人需要申请请假、调休或者出差等等。他们经常被统一时间批准申请。所以计算的并发可能为50。

模拟代码如下

public class PerformanceTest extends BaseTestCase { private int logLevel = 0; private int nrIterations = 5; public void setLogLevel(int i) { logLevel = i; } private static class TaskStats { public int waiting = 0; public int complete = 0; public long totalcalcTime = 0; public long totalqueryTime = 0; public int nrSamples = 0; } class PerfTask implements Callable<TaskStats> { TaskStats taskStats = new TaskStats(); long calcTime; long queryTime; public void runOnce() { try { taskStats.waiting++; if (logLevel >= 3) { String name = "thread" + Thread.currentThread().getName(); System.out.println(name + " waiting: " + taskStats.waiting + " complete: " + taskStats.complete); } long rbegin = System.currentTimeMillis(); //calc result.. long rend = System.currentTimeMillis(); if (logLevel >= 5) { String name = "thread" + Thread.currentThread().getName(); System.out.println(name + " waiting: " + taskStats.waiting + " complete: " + taskStats.complete); } long bbegin = System.currentTimeMillis(); //requery result by employee long bend = System.currentTimeMillis(); taskStats.waiting--; Thread.yield(); taskStats.complete++; calcTime = (bend-bbegin); queryTime = (rend-rbegin); } catch (Exception e) { e.printStackTrace(); } } @Override public TaskStats call() throws Exception { runOnce(); // warmup for (int i = 0; i < nrIterations; i++) { runOnce(); taskStats.totalcalcTime += calcTime; taskStats.totalqueryTime += queryTime; taskStats.nrSamples++; if (logLevel >= 2) { String name = "thread" + Thread.currentThread().getName(); System.out.println("result " + taskStats.nrSamples + "\t" + name + "\t" + "borrow time: " + calcTime + "\t" + "return time: " + queryTime + "\t" + "waiting: " + taskStats.waiting + "\t" + "complete: " + taskStats.complete); } } return taskStats; } } private void run(int nrIterations, int nrThreads) { this.nrIterations = nrIterations; ExecutorService threadPool = Executors.newFixedThreadPool(nrThreads); List<Callable<TaskStats>> tasks = new ArrayList<Callable<TaskStats>>(); for (int i = 0; i < nrThreads; i++) { tasks.add(new PerfTask()); Thread.yield(); } if (logLevel >= 1) { System.out.println("created"); } Thread.yield(); List<Future<TaskStats>> futures = null; try { futures = threadPool.invokeAll(tasks); } catch (InterruptedException e) { e.printStackTrace(); } if (logLevel >= 1) { System.out.println("started"); } Thread.yield(); if (logLevel >= 1) { System.out.println("go"); } Thread.yield(); if (logLevel >= 1) { System.out.println("finish"); } TaskStats aggregate = new TaskStats(); if (futures != null) { for (Future<TaskStats> future : futures) { TaskStats taskStats = null; try { taskStats = future.get(); } catch (InterruptedException e) { e.printStackTrace(); } catch (ExecutionException e) { e.printStackTrace(); } if (taskStats != null) { aggregate.complete += taskStats.complete; aggregate.nrSamples += taskStats.nrSamples; aggregate.totalcalcTime += taskStats.totalcalcTime; aggregate.totalqueryTime += taskStats.totalqueryTime; aggregate.waiting += taskStats.waiting; } } } System.out.println("-----------------------------------------"); System.out.println("nrIterations: " + nrIterations); System.out.println("nrThreads: " + nrThreads); System.out.println("nrSamples: " + aggregate.nrSamples); System.out.println("totalcalcTime: " + aggregate.totalcalcTime); System.out.println("totalqueryTime: " + aggregate.totalqueryTime); System.out.println("avg calcTime: " + aggregate.totalcalcTime/aggregate.nrSamples); System.out.println("avg queryTime: " + aggregate.totalqueryTime/aggregate.nrSamples); threadPool.shutdown(); } @Test public void testDeadLocked() { setLogLevel(0); System.out.println("Increase threads"); run(10, 20); run(10, 30); run(10, 40); } }

为了尽可能的接近真实情况，这个代码最好在两台以上的电脑上运行，并且要注意避免sql共享机制，这点可以让参数随机产生。

程序跑了10分钟后，死锁果真出现了，如log错误描述一般。