调试----程序员理解程序的必备核心技能

    今天一直纠结在网上看到的一个关于Redis数据库Pub/Sub模式demo,但是这个demo并不是用通常的客户端、服务端模式来完成的,而是用到了一个以前没怎么接触过的CountDownLatch线程阻塞类来完成该操作的。这个类形容起来可能与很久之前接触过的wait/notify有点像,但又不完全相同,但是通过这个实例可以很清楚的看出“调试”对于我们理解一个程序有着多么重要的影响。下面先来简单介绍一个我说的这个CountDownPatch class把:

JDK官方文档对这个类是这样结实的:

A synchronization aid that allows one or more threads to wait until a set of operations being performed in other threads completes
这个其实看原文档确实是挺烦人的,我也看了好久才看懂一点点,后来看了一些github上的项目才看懂这个类的执行过程,跟很久之前接触过的wait、notify有一拼,因为我最终的example可能很难理解,所以先拿一个CountDownLatch来预热一下把:

package cn.crabime;

import java.util.concurrent.CountDownLatch;

public class CountDownLatchTest {
	private static CountDownLatch cStartLatch = new CountDownLatch(10);
	private static CountDownLatch cEndLatch = new CountDownLatch(3);
	
	public static void main(String[] args) {
		System.out.println("all excution has started");
		new CountDownLatchTest().new Thread1(cStartLatch, cEndLatch).start();
		new CountDownLatchTest().new Thread2(cStartLatch, cEndLatch).start();
		new CountDownLatchTest().new Thread3(cStartLatch, cEndLatch).start();
		
		//这里开启了三个线程那还不行,线程都不能执行结束
		//因为cStartLatch线程还一直处于阻塞状态,必须要全部结束每个子线程才能执行开始StartLatch
		for(int i = 0; i < 5; i++){
			try {
				Thread.sleep(1000);
			} catch (InterruptedException e) {
				// TODO Auto-generated catch block
				e.printStackTrace();
			}
			System.out.println("wait this five procession, and there will be next five");
			cStartLatch.countDown();
		}
		for(int i = 5; i < 10; i++){
			try {
				Thread.sleep(2000);
			} catch (InterruptedException e) {
				// TODO Auto-generated catch block
				e.printStackTrace();
			}
			System.out.println("this five procession maybe time using, so please wait...");
			cStartLatch.countDown();
		}
		
		//这个步骤会一直阻塞状态,知道前面的三个线程全部执行结束后把所有的sEndLatch都执行完
		//这个才会被释放
		try {
			cEndLatch.await();
		} catch (InterruptedException e) {
			// TODO Auto-generated catch block
			e.printStackTrace();
		}
		System.out.println("all excution has ended");
	}
	class Thread1 extends Thread{
		private CountDownLatch sStartLatch;
		private CountDownLatch sEndLatch;
		public Thread1(CountDownLatch sStartLatch, CountDownLatch sEndLatch) {
			this.sStartLatch = sStartLatch;
			this.sEndLatch = sEndLatch;
		}
		@Override
		public void run() {
			System.out.println(this.getName() + " is now invoking");
			
			try {
				//这里你不能直接执行到await的下一步,因为前面传入的cStartLatch还在占用
				//线程总共是十个,还在执行中,所以这里你这个线程还需要等一会儿
				sStartLatch.await();
			} catch (InterruptedException e) {
				e.printStackTrace();
			}
			//这个run方法的执行就是该线程被占用的原因,测试一下很简单,只需要将这里再写一个
			//等待线程,然后比较每个线程被占用的时间就验证了上面的理论,Thread1占用1s
			try {
				Thread.sleep(1000);
			} catch (InterruptedException e) {
				// TODO Auto-generated catch block
				e.printStackTrace();
			}
			System.out.println(this.getName() + " has invoked");
			
			sEndLatch.countDown();
		}
	}
	class Thread2 extends Thread{
		private CountDownLatch sStartLatch;
		private CountDownLatch sEndLatch;
		public Thread2(CountDownLatch sStartLatch, CountDownLatch sEndLatch) {
			this.sStartLatch = sStartLatch;
			this.sEndLatch = sEndLatch;
		}
		@Override
		public void run() {
			System.out.println(this.getName() + " is now invoking");
			
			try {
				//这里你不能直接执行到await的下一步,因为前面传入的cStartLatch还在占用
				//线程总共是十个,还在执行中,所以这里你这个线程还需要等一会儿
				sStartLatch.await();
			} catch (InterruptedException e) {
				e.printStackTrace();
			}
			//这个run方法的执行就是该线程被占用的原因,测试一下很简单,只需要将这里再写一个
			//等待线程,然后比较每个线程被占用的时间就验证了上面的理论,Thread1占用5s
			try {
				Thread.sleep(5000);
			} catch (InterruptedException e) {
				// TODO Auto-generated catch block
				e.printStackTrace();
			}
			System.out.println(this.getName() + " has invoked");
			
			sEndLatch.countDown();
		}
	}
	class Thread3 extends Thread{
		private CountDownLatch sStartLatch;
		private CountDownLatch sEndLatch;
		public Thread3(CountDownLatch sStartLatch, CountDownLatch sEndLatch) {
			this.sStartLatch = sStartLatch;
			this.sEndLatch = sEndLatch;
		}
		@Override
		public void run() {
			System.out.println(this.getName() + " is now invoking");
			
			try {
				//这里你不能直接执行到await的下一步,因为前面传入的cStartLatch还在占用
				//线程总共是十个,还在执行中,所以这里你这个线程还需要等一会儿
				sStartLatch.await();
			} catch (InterruptedException e) {
				e.printStackTrace();
			}
			//这个run方法的执行就是该线程被占用的原因,测试一下很简单,只需要将这里再写一个
			//等待线程,然后比较每个线程被占用的时间就验证了上面的理论,Thread1占用15s
			try {
				Thread.sleep(15000);
			} catch (InterruptedException e) {
				// TODO Auto-generated catch block
				e.printStackTrace();
			}
			System.out.println(this.getName() + " has invoked");
			
			sEndLatch.countDown();
		}
	}
}
理解完了这个CountDownLatch class之后可以进入正题(“简单了解Redis Pub/Sub模式工作原理”),下面是我的要展示的demo:

package se.wendt.statoil.mastercard;

import java.util.ArrayList;
import java.util.concurrent.CountDownLatch;

import redis.clients.jedis.Jedis;
import redis.clients.jedis.JedisPubSub;

public class JedisTest {

	private static final String JEDIS_SERVER = "localhost";

	private ArrayList<String> messageContainer = new ArrayList<String>();

	private CountDownLatch messageReceivedLatch = new CountDownLatch(1);
	private CountDownLatch publishLatch = new CountDownLatch(1);

	public static void main(String[] args) throws InterruptedException {
		new JedisTest().run();
	}

	private void run() throws InterruptedException {
		setupPublisher();
		JedisPubSub jedisPubSub = setupSubscriber();

		// publish away!
		publishLatch.countDown();

		messageReceivedLatch.await();
		log("Got message: %s", messageContainer.iterator().next());

		jedisPubSub.unsubscribe();
	}

	private void setupPublisher() {
		new Thread(new Runnable() {
			public void run() {
				try {
					log("Connecting");
					Jedis jedis = new Jedis(JEDIS_SERVER);
					log("Waiting to publish");
					publishLatch.await();
					log("Ready to publish, waiting one sec");
					Thread.sleep(1000);
					log("publishing");
					jedis.publish("test", "This is a message");
					log("published, closing publishing connection");
					jedis.quit();
					log("publishing connection closed");
				} catch (Exception e) {
					log(">>> OH NOES Pub, " + e.getMessage());
					// e.printStackTrace();
				}
			}
		}, "publisherThread").start();
	}

	private JedisPubSub setupSubscriber() {
		final JedisPubSub jedisPubSub = new JedisPubSub() {
			@Override
			public void onUnsubscribe(String channel, int subscribedChannels) {
				log("onUnsubscribe");
			}

			@Override
			public void onSubscribe(String channel, int subscribedChannels) {
				log("onSubscribe");
			}

			@Override
			public void onPUnsubscribe(String pattern, int subscribedChannels) {
			}

			@Override
			public void onPSubscribe(String pattern, int subscribedChannels) {
			}

			@Override
			public void onPMessage(String pattern, String channel, String message) {
			}

			@Override
			public void onMessage(String channel, String message) {
				messageContainer.add(message);
				log("Message received");
				messageReceivedLatch.countDown();
			}
		};
		new Thread(new Runnable() {
			public void run() {
				try {
					log("Connecting");
					Jedis jedis = new Jedis(JEDIS_SERVER);
					log("subscribing");
					jedis.subscribe(jedisPubSub, "test");
					log("subscribe returned, closing down");
					jedis.quit();
				} catch (Exception e) {
					log(">>> OH NOES Sub - " + e.getMessage());
					// e.printStackTrace();
				}
			}
		}, "subscriberThread").start();
		return jedisPubSub;
	}

	static final long startMillis = System.currentTimeMillis();

	private static void log(String string, Object... args) {
		long millisSinceStart = System.currentTimeMillis() - startMillis;
		System.out.printf("%20s %6d %s\n", Thread.currentThread().getName(), millisSinceStart,
				String.format(string, args));
	}
}

上面JedisTest运行结果如下:

     publisherThread     17 Connecting
    subscriberThread     20 Connecting
    subscriberThread     79 subscribing
     publisherThread     79 Waiting to publish
     publisherThread     80 Ready to publish, waiting one sec
    subscriberThread    149 onSubscribe
     publisherThread   1080 publishing
     publisherThread   1102 published, closing publishing connection
    subscriberThread   1102 Message received
     publisherThread   1105 publishing connection closed
                main   1106 Got message: This is a message
    subscriberThread   1110 onUnsubscribe
    subscriberThread   1110 subscribe returned, closing down

对这个结果我想了很久,setupSubscriber返回的是一个JedisPubSub对象,不就是new一个对象就可以吗?为什么在执行中Waiting to publish输出结果竟然在subscribing后面,还有就是明明先运行的方法是setupPublisher,那么必然先执行这个方法只不过运行在.await()方法时出现线程挂起,下一步才开始执行setupSubscriber()方法,此时出现的输出结果才是connecting----subscribing----onSubscribe。在没用调试之前我手动梳理了一下过程,但是怎么梳理发现最后程序执行起来都是无序的,为什么呢?

后来开始逐步调试,发现执行顺序与现在这个顺序有很大的差别,执行过程还是CountDownLatch所应该的那样,即countDown()最后结果为0是,await()才开始释放,在这里也就是如下理想情形:

     publisherThread  17596 Connecting
     publisherThread  17727 Waiting to publish
    subscriberThread 467829 Connecting
    subscriberThread 467830 subscribing
    subscriberThread 467927 onSubscribe
     publisherThread 485329 Ready to publish, waiting one sec
     publisherThread 486333 publishing
     publisherThread 486357 published, closing publishing connection
    subscriberThread 486357 Message received
     publisherThread 486359 publishing connection closed
                main 506922 Got message: This is a message
    subscriberThread 512982 onUnsubscribe
    subscriberThread 512983 subscribe returned, closing down

这里时间差为什么这么大,是我估计等待很长一段时间再进行调试下一步。那么现在问题来了,为什么两者差别这么大呢? 如果不调试,你根本就看不出来,或者说你根本就不知道程序是怎样执行的。分析原因可以发现setupPublisher方法执行是在一个线程中,setupSubscriber方法中也执行一个必不可少的线程,那么在执行setupPublisher()、JedisPubSub jedisPubSub = setupSubscriber();就相当于是在main函数中同时开启两个线程,并且这两个线程中还会掺杂一个main线程,此时为什么看不懂就差不多明白了吧,线程之间执行的无序性。但是因为有这么一个CountDownLatch类似于Synchronized,并不会真正影响我们观察pub/sub式结果。

总结:在碰到很多麻烦的程序时,如果一时半会看不明白程序的执行过程,调试是一种非常好的选择,Eclipse、Visual Studio都有很完美的debug tool。所以千万不要忘了自己还拥有一个无敌的利器。


评论
添加红包

请填写红包祝福语或标题

红包个数最小为10个

红包金额最低5元

当前余额3.43前往充值 >
需支付:10.00
成就一亿技术人!
领取后你会自动成为博主和红包主的粉丝 规则
hope_wisdom
发出的红包
实付
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明:

1.余额是钱包充值的虚拟货币,按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载,可以购买VIP、付费专栏及课程。

余额充值