一个普通的Java项目,如果想对某些类织入额外的代码,一个比较好的选择是Aspectj,它对项目的侵入最小,只需要写一个Aspectj的切面文件,然后使用构建工具引入Aspectj的插件(gradle、maven),它就能在编译时织入你想要的代码。

我们项目中有一个使用quartz定时任务的工程,有很多的job,现在想要将这些job监控起来,job执行否?job执行成功否?基本思想是在每个job执行开始记录,执行结束记录,抛异常记录。有两种方案。一种是写一个抽象类,所有的job继承于此类,此类中在job真正执行方法之前之后和抛异常的时候进行处理。

/**
 * @author xiongshiyan at 2018/3/2
 */
public class JobExecute extends Model<JobExecute> {
    public static final String ID                   = "id";
    public static final String DAY                  = "day";
    public static final String START                = "start";
    public static final String END                  = "end";
    public static final String JOB_NAME             = "jobName";
    public static final String IS_SUCCESS_FINISHED  = "isSuccessFinished";

    public static final int SUCCESS = 1;
    public static final int FAIL = 0;

    public static final JobExecute dao = new JobExecute();

    /**
     * job开始的时候记录,说明开始执行了
     * @param day 哪一天
     * @param start 开始时间
     * @param jobName jobName
     * @return JobExecute 后面更新此model的某些字段
     */
    public JobExecute insertStart(Date day, Date start, String jobName){
        JobExecute execute = new JobExecute();
        execute.set(JobExecute.DAY,day);
        execute.set(JobExecute.START,start);
        execute.set(JobExecute.JOB_NAME,jobName);
        execute.set(JobExecute.IS_SUCCESS_FINISHED,FAIL);
        execute.save();
        return execute;
    }

    /**
     * 正常结束的时候更新字段
     */
    public void updateEnd(){
        this.set(END,new Date());
        this.set(IS_SUCCESS_FINISHED,SUCCESS);
        this.update();
    }

}
/**
 * @author xiongshiyan at 2018/3/2
 * 在开始和结束的时候增加日志记录
 * id day start_time end_time is_success_finished job_name 
 */
public abstract class AbstractLoggingJob implements Job{
    private static final Logger logger  = LoggerFactory.getLogger(AbstractLoggingJob.class);
    @Override
    public void execute(JobExecutionContext context) throws JobExecutionException {
        //1.开始的时候记录
        Date start = new Date();
        JobExecute execute = JobExecute.dao.insertStart(start, start, jobName());
        //2.开始Job
        try {
            exe(context);
        } catch (Exception e) {
            logger.error(jobName() + " 发生异常:" + e.getMessage() , e);
            //发生了异常就往外抛,3就不会执行,end时间就会为空
            throw new JobExecutionException(e);
        }
        //3.结束的时候更新这条记录
        execute.updateEnd();
    }

    /**
     * 真正执行的Job方法,子类复写
     */
    protected abstract void exe(JobExecutionContext context) throws Exception;

    /**
     * 子类返回JobName,默认就是类名
     * @return job's name
     */
    protected String jobName(){
        return this.getClass().getName();
    }
}

这种方案比较简单,但是需要改每个job,容易出错。实际我们采用了第二种方案--采用Aspectj进行织入。

首先我们需要满足jdk和gradle的条件,1.8.0_121以上的JDK版本,gradle4.1以上。最开始我的jdk版本是1.8.0_65都编译不通过,老在下载依赖的时候报错。

其次,我们需要在gradle的编译文件中引入gradle-aspectj插件和aspectj的依赖。

buildscript {
    repositories {
        maven {
            url "https://maven.eveoh.nl/content/repositories/releases"
        }
    }

    dependencies {
        classpath "nl.eveoh:gradle-aspectj:2.0"
    }
}

ext.aspectjVersion = '1.8.13'
apply plugin: 'aspectj'
compileAspect {
	additionalAjcArgs = ['encoding': 'UTF-8', 'source': '1.8', 'target': '1.8']
}
compile 'org.aspectj:aspectjrt:1.8.13'



非常注意:设置文件编码,否则出现乱码。

然后,编写aspectj的切面文件,引入切面代码,这其中最重要的是表达式的编写,参见

/**
 * @author xiongshiyan at 2018/3/6
 * 切面文件
 */
public aspect LoggingAspectJ {
    private static final Logger logger = LoggerFactory.getLogger(LoggingAspectJ.class);
    public pointcut jobs(JobExecutionContext context) : execution(public void cn.esstx.dzg.runner.tinyrunner.job..*.execute(org.quartz.JobExecutionContext)) && args(context);

    private JobExecute execute = null;

    before(JobExecutionContext context): jobs(context){
        logger.info("[before]"
                        + thisJoinPoint.getTarget().getClass()
                        .getCanonicalName() + "."
                        + thisJoinPoint.getSignature().getName());
        Date start = new Date();
        String jobName = thisJoinPoint.getTarget().getClass().getName();
        execute = JobExecute.dao.insertStart(start, start, jobName);
    }

    //有成功返回,说明执行成功了,如果异常就不会执行
    after(JobExecutionContext context) returning() : jobs(context) {
        logger.info("[after returning]"
                + thisJoinPoint.getTarget().getClass().getCanonicalName() + "."
                + thisJoinPoint.getSignature().getName());
        execute.updateEnd();
    }

    //抛不抛出异常都会执行
    after(JobExecutionContext context) : jobs(context){
        logger.info("[after]"
                        + thisJoinPoint.getTarget().getClass()
                        .getCanonicalName() + "."
                        + thisJoinPoint.getSignature().getName());
    }

    //抛异常的时候
    after(JobExecutionContext context) throwing(java.lang.Exception e) : jobs(context){
        logger.error("[after throwing]"
                + thisJoinPoint.getTarget().getClass().getCanonicalName() + "."
                + thisJoinPoint.getSignature().getName() + " throwing="
                + e.getMessage());
    }
}

最后,执行gradle clean build 得到植入后的class文件,测试类为EveryMinuteTestJob,执行两次之后抛异常,反编译之后的代码如下。

public class EveryMinuteTestJob implements Job {
    private static int xx;
    private static final Logger logger;

    static {
        ajc$preClinit();
        xx = 0;
        logger = LoggerFactory.getLogger(EveryMinuteTestJob.class);
    }

    public EveryMinuteTestJob() {
    }

    public void execute(JobExecutionContext context) throws JobExecutionException {
        JobExecutionContext var2 = context;
        JoinPoint var3 = Factory.makeJP(ajc$tjp_0, this, this, context);

        try {
            try {
                LoggingAspectJ.aspectOf().ajc$before$cn_esstx_dzg_runner_tinyrunner_LoggingAspectJ$1$ddb27cec(var2, var3);
                logger.info("execute method invoked-------");
                ++xx;
                if (xx == 2) {
                    throw new RuntimeException("simulation throw a exception");
                }

                LoggingAspectJ.aspectOf().ajc$afterReturning$cn_esstx_dzg_runner_tinyrunner_LoggingAspectJ$2$ddb27cec(var2, var3);
            } catch (Throwable var6) {
                LoggingAspectJ.aspectOf().ajc$after$cn_esstx_dzg_runner_tinyrunner_LoggingAspectJ$3$ddb27cec(var2, var3);
                throw var6;
            }

            LoggingAspectJ.aspectOf().ajc$after$cn_esstx_dzg_runner_tinyrunner_LoggingAspectJ$3$ddb27cec(var2, var3);
        } catch (Exception var7) {
            LoggingAspectJ.aspectOf().ajc$afterThrowing$cn_esstx_dzg_runner_tinyrunner_LoggingAspectJ$4$ddb27cec(context, var7, var3);
            throw var7;
        }
    }
}

从反编译文件中,我们能够看出,每种通知的执行位置。before是目标方法之前,afterReturning是有返回值的时候,说明方法正常执行了可以得到执行的结果,after是目标方法执行之后,不管抛不抛出异常,afterThrowing是抛异常之后执行,around可以完全控制。


我们根据日志打印,可以清楚地看见这个执行顺序。


dzg-server-runner-prod: 2018-03-06 20:41:00.009 [DefaultQuartzScheduler_Worker-1] INFO  (LoggingAspectJ.aj:19) - [before]cn.esstx.dzg.runner.tinyrunner.job.EveryMinuteTestJob.execute
dzg-server-runner-prod: 2018-03-06 20:41:00.047 [DefaultQuartzScheduler_Worker-1] INFO  (EveryMinuteTestJob.java:17) - execute method invoked-------
dzg-server-runner-prod: 2018-03-06 20:41:00.049 [DefaultQuartzScheduler_Worker-1] INFO  (LoggingAspectJ.aj:30) - [after returning]cn.esstx.dzg.runner.tinyrunner.job.EveryMinuteTestJob.execute
dzg-server-runner-prod: 2018-03-06 20:41:00.057 [DefaultQuartzScheduler_Worker-1] INFO  (LoggingAspectJ.aj:38) - [after]cn.esstx.dzg.runner.tinyrunner.job.EveryMinuteTestJob.execute
dzg-server-runner-prod: 2018-03-06 20:42:00.001 [DefaultQuartzScheduler_Worker-2] INFO  (LoggingAspectJ.aj:19) - [before]cn.esstx.dzg.runner.tinyrunner.job.EveryMinuteTestJob.execute
dzg-server-runner-prod: 2018-03-06 20:42:00.010 [DefaultQuartzScheduler_Worker-2] INFO  (EveryMinuteTestJob.java:17) - execute method invoked-------
dzg-server-runner-prod: 2018-03-06 20:42:00.011 [DefaultQuartzScheduler_Worker-2] INFO  (LoggingAspectJ.aj:38) - [after]cn.esstx.dzg.runner.tinyrunner.job.EveryMinuteTestJob.execute
dzg-server-runner-prod: 2018-03-06 20:42:00.011 [DefaultQuartzScheduler_Worker-2] ERROR (LoggingAspectJ.aj:46) - [after throwing]cn.esstx.dzg.runner.tinyrunner.job.EveryMinuteTestJob.execute throwing=simulation throw a exception
dzg-server-runner-prod: 2018-03-06 20:42:00.014 [DefaultQuartzScheduler_Worker-2] ERROR (JobRunShell.java:211) - Job cn.esstx.dzg.runner.tinyrunner.job.EveryMinuteTestJob.cn.esstx.dzg.runner.tinyrunner.job.EveryMinuteTestJob threw an unhandled Exception: 
java.lang.RuntimeException: simulation throw a exception
	at cn.esstx.dzg.runner.tinyrunner.job.EveryMinuteTestJob.execute(EveryMinuteTestJob.java:20)
	at org.quartz.core.JobRunShell.run(JobRunShell.java:202)
	at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573)
dzg-server-runner-prod: 2018-03-06 20:42:00.014 [DefaultQuartzScheduler_Worker-2] ERROR (QuartzScheduler.java:2425) - Job (cn.esstx.dzg.runner.tinyrunner.job.EveryMinuteTestJob.cn.esstx.dzg.runner.tinyrunner.job.EveryMinuteTestJob threw an exception.
org.quartz.SchedulerException: Job threw an unhandled exception.
	at org.quartz.core.JobRunShell.run(JobRunShell.java:213)
	at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573)
Caused by: java.lang.RuntimeException: simulation throw a exception
	at cn.esstx.dzg.runner.tinyrunner.job.EveryMinuteTestJob.execute(EveryMinuteTestJob.java:20)
	at org.quartz.core.JobRunShell.run(JobRunShell.java:202)
	... 1 common frames omitted
dzg-server-runner-prod: 2018-03-06 20:43:00.002 [DefaultQuartzScheduler_Worker-3] INFO  (LoggingAspectJ.aj:19) - [before]cn.esstx.dzg.runner.tinyrunner.job.EveryMinuteTestJob.execute
dzg-server-runner-prod: 2018-03-06 20:43:00.010 [DefaultQuartzScheduler_Worker-3] INFO  (EveryMinuteTestJob.java:17) - execute method invoked-------
dzg-server-runner-prod: 2018-03-06 20:43:00.011 [DefaultQuartzScheduler_Worker-3] INFO  (LoggingAspectJ.aj:30) - [after returning]cn.esstx.dzg.runner.tinyrunner.job.EveryMinuteTestJob.execute
dzg-server-runner-prod: 2018-03-06 20:43:00.022 [DefaultQuartzScheduler_Worker-3] INFO  (LoggingAspectJ.aj:38) - [after]cn.esstx.dzg.runner.tinyrunner.job.EveryMinuteTestJob.execute

以上的实际上会有非常严重的线程安全问题。因为切面是个单例,所以其成员变量在不同的通知中有修改的话,就可能造成某个job1插入一条记录之后,又被另外的一个job2插入一条记录,成员变量execute就变为另外一个了,job1在方法调用完成后去更新其字段,实际就不是更新原来的记录的字段了。所以如果需要跨通知保存修改变量的话,就有安全问题。必须使用around通知。

public aspect LoggingAspectAround {
    private static final Logger logger = LoggerFactory.getLogger(LoggingAspectAround.class);
    public pointcut jobs() : execution(public void cn.esstx.dzg.runner.tinyrunner.job..*.execute(org.quartz.JobExecutionContext));

    void around(): jobs(){
        JobExecute execute = null;
        try {
            logger.info("[before]"+ this + ":"
                    + thisJoinPoint.getTarget().getClass()
                    .getCanonicalName() + "."
                    + thisJoinPoint.getSignature().getName());
            Date start = new Date();
            String jobName = thisJoinPoint.getTarget().getClass().getName();
            String simpleName = thisJoinPoint.getTarget().getClass().getSimpleName();
            execute = JobExecute.dao.insertStart(start, start, jobName,simpleName);

            proceed();

            logger.info("[after returning]" + this + ":"
                    + thisJoinPoint.getTarget().getClass().getCanonicalName() + "."
                    + thisJoinPoint.getSignature().getName());
            execute.updateEnd();
        } catch (Exception e) {
            logger.error("[after throwing]"+ this + ":"
                    + thisJoinPoint.getTarget().getClass().getCanonicalName() + "."
                    + thisJoinPoint.getSignature().getName() , e);
            execute.updateException(e);
        }
    }
}