Perl学习笔记 — 书到用时方恨少

Posted on 四月 11, 2008 by arrowpig1979

现在是晚上10点，我还在单位里面，为什么会这么晚呢，因为自己太弱了！！4月10号凌晨一台机器Machine Restart，祸不单行，重启以后由于NTP服务也down 掉了，搞得系统时间比正确时间快了1个小时。由于我们在这台机器上面部署的Application运行的时候都依赖于系统时间，搞得应用进程跳过当前时间，不停的试图处理将来的数据。为了恢复这个问题，需要找到系统时间出错前应用进程的所有任务的时间戳，然后从那些时间戳replay所有任务。

1. 每个物理服务器上可以部署多个进程，进程是由VCS监控的，所以进程是可以从一台机器“飘移”到另外一台机器的。
2. 每个进程启动的时候，都会打印"Process Started"到logging 文件。
3. 每个进程都并发多个任务，每个任务由一个线程执行，线程启动时会记录任务名称和线程ID到logging文件。
4. 每个任务都是执行N个步骤，每个步骤调用一个函数，函数调用也都logging。
5. 每个任务都是循环执行的，执行完本轮的所有步骤以后，休息一段时间，下一轮继续执行。

关于以上4点的说明：

1. 所有进程漂移的动作都由VCS的系统日志记录。
2. 由于各种原因应用进程会重新启动，这时每个任务重新初始化，线程ID很有可能会变动。
3. 假设任务名称是Task1,线程ID是35,当前系统时间是Thu Apr 10 01:44:29 2008，logging格式为：{Task1} [TID: 35] Init at (Thu Apr 10 01:44:29 2008)
4. 假设步骤名称（函数名称）是Step1,当前系统时间是Thu Apr 10 01:56:30 2008, logging格式为: [TID: 35] Step1 at (Thu Apr 10 01:56:30 2008)

早上看到这个问题的时候，我就回了一下说Hi Guys, I will look into this issue。Edward说Todd有一个脚本可以完成这个工作的，找到Todd,Todd找不到以前的脚本了，而且他很忙，我只能自己干了。呀呀的，早知道前些日子把Perl学学好了，而且我Unix的Shell也不熟。后来我们想象，还是有一些地方是要注意的。

 

 

什么是任务的时间戳，就是任务的步骤1的时间戳，可是标志步骤的log上面并没有任务的名字，所以只能用线程ID来标识。

my $block = `grep Task1 logfile.log | head -1`;  #找到Task启动的那一行，那里有Task1对应的线程ID
$block=~/[(TID:.*)]/;                                #得到表示Task1的线程ID,保存在$1中 

$block = `grep ‘$1′ logfile.log | grep Step1 |  tail -1`; #找到任务最后一次执行Step1的时间

$block=~/((d+))$/;  #得到时间戳，保存在$1中

对吗，对吗？？错啦！！错啦！！为什么呀？

• 假设应用进程跑了10个小时了，head -1拿到的是该进程第一次启动的log记录，接着我们拿到了那个时候Task对应的线程ID，我们试图用这个线程ID去匹配所有该线程运行的步骤，然后认为最后一个匹配的log 记录上的时间戳就是我们要的。但是如果应用线程在运行了5个小时的时候就Restart了呢？这个时候会重新启动，Task1对应的线程ID或许已经改变了。结果是我们拿到的时间戳不是Task1的了，或许是Task2的，或许仍然是Task1的，但是是5个小时以前应用进程还没有崩溃之前的时间戳了，这个信息对我们是没有意义的。

那好，如果把找寻Task1的线程ID的代码这样改一下呢：

my $block = `grep Task1 logfile.log | tail -1`;  我们拿最后一个匹配的Task1的记录，还是错啦，因为我们的问题是要找到问题发生前的所有任务的时间戳，不是从当前时间往前找寻所有任务的时间戳啊。系统时间被篡改是4月10号临晨00：56分。所有被VCS在00:56分以后漂移到该物理节点的应用进程都会受到影响。每次漂移应用进程都会重新启动的。所以正确的做法是先要找到4月临晨00:56分以后应用进程第一次启动的log，假设该事件点是T，从那个点往前找Task1启动的记录，找到线程ID，再用那个线程ID再次从T往前找Step1的时间戳！

my $timestamp="Thu Apr 10 00:56:00 2008";
my $logfile = "logfile.log";
my $linescan=500; #向"过去"扫描的行数

my $line = ` grep -n "$timestamp" $logfile| grep  ‘Process Started’ | tail -1`;
$line =~/^(d+):/;   #找到系统出问题之后应用进程第一次启动的地点
$my linenum=$1;

my $block = `head -$linenum $logfile | tail -$linescan | grep Task1| head -1`;
$block=~/[(TID:.*)]/;

$block = `head -$linenum $logfile | tail -$linescan | grep ‘$1′ | grep Step1 | tail -1`;

$block=~/((d+))$/;
print "Task1::Step1 : ",$1,"n"; #打印时间戳

*********************************************************************************

一共就几行代码啊，搞了我好几个小时！真TMD衰。而且这个脚本用起来一点也不爽，因为我们有很多很多的任务，还有很多很多的log文件，后来Todd写了一个自动化程度比较高的脚本，可以自动找到所有的log文件，然后打印所有的问题出现前的时间戳，并且生成应用进程可以直接读的文件。