设置quartz的日志打印，为完整日志
引入p6spy ：
配置spy.properties：
# 指定应用的日志拦截模块,默认为com.p6spy.engine.spy.P6SpyFactory #modulelist=com.p6spy.engine.spy.P6SpyFactory,com.p6spy.engine.logging.P6LogFactory,com.p6spy.engine.outage.P6OutageFactory # 真实JDBC driver , 多个以 逗号 分割 默认为空,比如：com.mysql.jdbc.Driver,oracle.jdbc.driver.OracleDriver #driverlist= # 是否自动刷新 默认 flase #autoflush=false # 配置SimpleDateFormat日期格式 默认为空 #dateformat=yyyy-MM-dd HH:mm:ss # 打印堆栈跟踪信息 默认flase #stacktrace=false # 如果 stacktrace=true，则可以指定具体的类名来进行过滤。 #stacktraceclass= # 监测属性配置文件是否进行重新加载 #reloadproperties=false # 属性配置文件重新加载的时间间隔，单位:秒 默认60s #reloadpropertiesinterval=60 # 指定 Log 的 appender，取值：分别是使用Log4j日志系统，打印控制台，打印到文件 #appender=com.p6spy.engine.spy.appender.Slf4JLogger #appender=com.p6spy.engine.spy.appender.StdoutLogger #appender=com.p6spy.engine.spy.appender.FileLogger # 指定 Log 的文件名 默认 spy.log #logfile=spy.log # 指定是否每次是增加 Log，设置为 false 则每次都会先进行清空 默认true #append=true # 指定日志输出样式 默认为com.p6spy.engine.spy.appender.SingleLineFormat , 单行输出 不格式化语句 #logMessageFormat=com.p6spy.engine.spy.appender.SingleLineFormat # 也可以采用 com.p6spy.engine.spy.appender.CustomLineFormat 来自定义输出样式, 默认值是%(currentTime)|%(executionTime)|%(category)|connection%(connectionId)|%(sqlSingleLine) # 可用的变量为: # %(connectionId) connection id # %(currentTime) 当前时间 # %(executionTime) 执行耗时 # %(category) 执行分组 # %(effectiveSql) 提交的SQL 换行 # %(effectiveSqlSingleLine) 提交的SQL 不换行显示 # %(sql) 执行的真实SQL语句，已替换占位 # %(sqlSingleLine) 执行的真实SQL语句，已替换占位 不换行显示 #customLogMessageFormat=%(currentTime)|%(executionTime)|%(category)|connection%(connectionId)|%(sqlSingleLine) #举例 #logMessageFormat=com.p6spy.engine.spy.appender.CustomLineFormat #customLogMessageFormat=%(currentTime) | SQL耗时： %(executionTime) ms | 连接信息： %(category)-%(connectionId) | 执行语句： %(sql) # date类型字段记录日志时使用的日期格式 默认dd-MMM-yy #databaseDialectDateFormat=dd-MMM-yy # boolean类型字段记录日志时使用的日期格式 默认boolean 可选值numeric #databaseDialectBooleanFormat=boolean # 是否通过jmx暴露属性 默认true #jmx=true # 如果jmx设置为true 指定通过jmx暴露属性时的前缀 默认为空 # com.p6spy(.<jmxPrefix>)?:name=<optionsClassName> #jmxPrefix= # 是否显示纳秒 默认false #useNanoTime=false # 实际数据源 JNDI #realdatasource=/RealMySqlDS # 实际数据源 datasource class #realdatasourceclass=com.mysql.jdbc.jdbc2.optional.MysqlDataSource # 实际数据源所携带的配置参数 以 k=v 方式指定 以 分号 分割 #realdatasourceproperties=port;3306,serverName;myhost,databaseName;jbossdb,foo;bar # jndi数据源配置 # 设置 JNDI 数据源的 NamingContextFactory。 #jndicontextfactory=org.jnp.interfaces.NamingContextFactory # 设置 JNDI 数据源的提供者的 URL。 #jndicontextproviderurl=localhost:1099 # 设置 JNDI 数据源的一些定制信息，以分号分隔。 #jndicontextcustom=java.naming.factory.url.pkgs;org.jboss.naming:org.jnp.interfaces # 是否开启日志过滤 默认false， 这项配置是否生效前提是配置了 include/exclude/sqlexpression #filter=false # 过滤 Log 时所包含的表名列表，以逗号分隔 默认为空 #include= # 过滤 Log 时所排除的表名列表，以逗号分隔 默认为空 #exclude= # 过滤 Log 时的 SQL 正则表达式名称 默认为空 #sqlexpression= #显示指定过滤 Log 时排队的分类列表，取值: error, info, batch, debug, statement, #commit, rollback, result and resultset are valid values # (默认 info,debug,result,resultset,batch) #excludecategories=info,debug,result,resultset,batch # 是否过滤二进制字段 # (default is false) #excludebinary=false # P6Log 模块执行时间设置，整数值 (以毫秒为单位)，只有当超过这个时间才进行记录 Log。 默认为0 #executionThreshold= # P6Outage 模块是否记录较长时间运行的语句 默认false # outagedetection=true|false # P6Outage 模块执行时间设置，整数值 （以秒为单位)），只有当超过这个时间才进行记录 Log。 默认30s # outagedetectioninterval=integer time (seconds) module.log=com.p6spy.engine.logging.P6LogFactory,com.p6spy.engine.outage.P6OutageFactory # 自定义日志打印 #logMessageFormat=com.wjy.log.P6SpyLogger #logMessageFormat=com.p6spy.engine.spy.appender.SingleLineFormat logMessageFormat=com.p6spy.engine.spy.appender.CustomLineFormat #customLogMessageFormat=%(currentTime) | SQL耗时： %(executionTime) ms | 连接信息： %(category)-%(connectionId) | 执行语句： %(sql) customLogMessageFormat=%(currentTime) | Time %(executionTime) ms | %(category)-%(connectionId) | %(sql) # 使用控制台记录sql appender=com.p6spy.engine.spy.appender.StdoutLogger ## 配置记录Log例外 excludecategories=info,debug,result,batc,resultset # 设置使用p6spy driver来做代理 deregisterdrivers=true # 日期格式 dateformat=yyyy-MM-dd HH:mm:ss # 实际驱动 driverlist=com.mysql.jdbc.Driver # 是否开启慢SQL记录 outagedetection=true # 慢SQL记录标准 秒 outagedetectioninterval=2
修改数据库配置quartz.properties：
org.quartz.dataSource.qzDS.driver:com.mysql.jdbc.Driver org.quartz.dataSource.qzDS.URL:jdbc:mysql://localhost:3306/aa #org.quartz.dataSource.qzDS.driver:com.p6spy.engine.spy.P6SpyDriver #org.quartz.dataSource.qzDS.URL:jdbc:p6spy:mysql://localhost:3306/aa org.quartz.dataSource.qzDS.user:root org.quartz.dataSource.qzDS.password:root org.quartz.dataSource.qzDS.maxConnection:10
quartz启动日志观察分析
首先是 把所有的TRIGGER_STATE = 'ACQUIRED' OR TRIGGER_STATE = 'BLOCKED') 的触发器 qrtz_TRIGGERS 的状态更新为WAITING， 表示我们准备好了去执行它。
2021-07-25 13:25:06 | Time 8 ms | statement-1 | UPDATE qrtz_TRIGGERS SET TRIGGER_STATE = 'WAITING' WHERE SCHED_NAME = 'dufy_test' AND (TRIGGER_STATE = 'ACQUIRED' OR TRIGGER_STATE = 'BLOCKED')
把TRIGGER_STATE = 'PAUSED_BLOCKED 的触发器 qrtz_TRIGGERS 的状态更新为PAUSED， 表示 准备去 恢复它。
2021-07-25 13:25:06 | Time 1 ms | statement-1 | UPDATE qrtz_TRIGGERS SET TRIGGER_STATE = 'PAUSED' WHERE SCHED_NAME = 'dufy_test' AND (TRIGGER_STATE = 'PAUSED_BLOCKED' OR TRIGGER_STATE = 'PAUSED_BLOCKED')
13:25:06.873 [main] INFO o.q.impl.jdbcjobstore.JobStoreTX - Freed 1 triggers from 'acquired' / 'blocked' state.
Freed 1 triggers from 'acquired' / 'blocked' state. 表示 上面sql 返回1，从而“自由”了一个blocked 状态的触发器
查询 时间窗口的 TRIGGER_STATE = 'WAITING' 的触发器
2021-07-25 13:25:06 | Time 8 ms | statement-1 | SELECT TRIGGER_NAME, TRIGGER_GROUP FROM qrtz_TRIGGERS WHERE SCHED_NAME = 'dufy_test' AND NOT (MISFIRE_INSTR = -1) AND NEXT_FIRE_TIME < 1627190646874 AND TRIGGER_STATE = 'WAITING' ORDER BY NEXT_FIRE_TIME ASC, PRIORITY DESC
13:25:06.905 [main] DEBUG o.q.impl.jdbcjobstore.JobStoreTX - Found 0 triggers that missed their scheduled fire-time.
-1 是表示 忽略， 也就是； not 则表示 不能忽略的 misfire
public static final int MISFIRE_INSTRUCTION_IGNORE_MISFIRE_POLICY = -1;
Found 0 triggers that missed their scheduled fire-time. 表示 没有misfire 的调度
查询 需要恢复的job，即REQUESTS_RECOVERY = true，什么情况需要恢复呢？ 程序关闭了， 重启之间 的misfire 部分？
2021-07-25 13:25:06 | Time 1 ms | statement-1 | SELECT * FROM qrtz_FIRED_TRIGGERS WHERE SCHED_NAME = 'dufy_test' AND INSTANCE_NAME = 'NON_CLUSTERED' AND REQUESTS_RECOVERY = true
13:25:06.911 [main] INFO o.q.impl.jdbcjobstore.JobStoreTX - Recovering 0 jobs that were in-progress at the time of the last shut-down. —— 0 表示没有找到
13:25:06.911 [main] INFO o.q.impl.jdbcjobstore.JobStoreTX - Recovery complete.
查询已经全部执行完毕的触发器： TRIGGER_STATE = 'COMPLETE'， 然后准备把它删除。
2021-07-25 13:25:06 | Time 0 ms | statement-1 | SELECT TRIGGER_NAME, TRIGGER_GROUP FROM qrtz_TRIGGERS WHERE SCHED_NAME = 'dufy_test' AND TRIGGER_STATE = 'COMPLETE'
13:25:06.914 [main] INFO o.q.impl.jdbcjobstore.JobStoreTX - Removed 0 'complete' triggers.—— 0个触发器需要删除
删除所有当前SCHED_NAME = 'dufy_test'下的 qrtz_FIRED_TRIGGERS ， 为什么要在 启动的时候删除所有的？ 因为那个是 已经完成的部分
2021-07-25 13:25:06 | Time 1 ms | statement-1 | DELETE FROM qrtz_FIRED_TRIGGERS WHERE SCHED_NAME = 'dufy_test'
13:25:06.917 [main] INFO o.q.impl.jdbcjobstore.JobStoreTX - Removed 1 stale fired job entries.
2021-07-25 13:25:06 | Time 7 ms | commit-1 | —— 删除了一条 entry
为什么要锁住呢
13:25:06.926 [main] DEBUG o.q.i.jdbcjobstore.SimpleSemaphore - Lock 'TRIGGER_ACCESS' retuned by: main
启动 job存储线程 JobStore background threads
13:25:06.931 [main] DEBUG o.q.impl.jdbcjobstore.JobStoreTX - JobStore background threads started (as scheduler was started).
启动调度器 QuartzScheduler
13:25:06.931 [main] INFO org.quartz.core.QuartzScheduler - Scheduler dufy_test_$_NON_CLUSTERED started.
13:25:06.932 [QuartzScheduler_dufy_test-NON_CLUSTERED_MisfireHandler] DEBUG o.q.impl.jdbcjobstore.JobStoreTX - MisfireHandler: scanning for misfires...
desired obtained given 锁 TRIGGER_ACCESS
13:25:06.934 [main] DEBUG o.q.i.jdbcjobstore.SimpleSemaphore - Lock 'TRIGGER_ACCESS' is desired by: main
13:25:06.935 [main] DEBUG o.q.i.jdbcjobstore.SimpleSemaphore - Lock 'TRIGGER_ACCESS' is being obtained: main
13:25:06.935 [main] DEBUG o.q.i.jdbcjobstore.SimpleSemaphore - Lock 'TRIGGER_ACCESS' given to: main
获取状态为等待的 窗口内的 不能忽略misfre 的部分，总的数量：
2021-07-25 13:25:06 | Time 0 ms | statement-1 | SELECT COUNT(TRIGGER_NAME) FROM qrtz_TRIGGERS WHERE SCHED_NAME = 'dufy_test' AND NOT (MISFIRE_INSTR = -1) AND NEXT_FIRE_TIME < 1627190646934 AND TRIGGER_STATE = 'WAITING'
—— 又一次查询是否有 misfire
13:25:06.939 [QuartzScheduler_dufy_test-NON_CLUSTERED_MisfireHandler] DEBUG o.q.impl.jdbcjobstore.JobStoreTX - Found 0 triggers that missed their scheduled fire-time.
根据 job_key 查询 job 详情
2021-07-25 13:25:06 | Time 0 ms | statement-2 | SELECT JOB_NAME FROM qrtz_JOB_DETAILS WHERE SCHED_NAME = 'dufy_test' AND JOB_NAME = 'job1_1' AND JOB_GROUP = 'jGroup1'
====== 准备执行定时任务。==============
查询 窗口内的 触发器行，并且MISFIRE_INSTR = -1 OR (MISFIRE_INSTR != -1 AND NEXT_FIRE_TIME >= 1627190646937) ，即 被忽略的 或者下一次的 fire时间超过了窗口。
2021-07-25 13:25:06 | Time 1 ms | statement-0 | SELECT TRIGGER_NAME, TRIGGER_GROUP, NEXT_FIRE_TIME, PRIORITY FROM qrtz_TRIGGERS WHERE SCHED_NAME = 'dufy_test' AND TRIGGER_STATE = 'WAITING' AND NEXT_FIRE_TIME <= 1627190736931 AND (MISFIRE_INSTR = -1 OR (MISFIRE_INSTR != -1 AND NEXT_FIRE_TIME >= 1627190646937)) ORDER BY NEXT_FIRE_TIME ASC, PRIORITY DESC
2021-07-25 13:25:06 | Time 2 ms | commit-1 |
根据 trigger_key 查询 trigger
2021-07-25 13:25:06 | Time 6 ms | statement-0 | SELECT * FROM qrtz_TRIGGERS WHERE SCHED_NAME = 'dufy_test' AND TRIGGER_NAME = 'trigger1' AND TRIGGER_GROUP = 'group1'
新增一条数据到 qrtz_JOB_DETAILS
2021-07-25 13:25:06 | Time 1 ms | statement-2 | INSERT INTO qrtz_JOB_DETAILS (SCHED_NAME, JOB_NAME, JOB_GROUP, DESCRIPTION, JOB_CLASS_NAME, IS_DURABLE, IS_NONCONCURRENT, IS_UPDATE_DATA, REQUESTS_RECOVERY, JOB_DATA) VALUES('dufy_test', 'job1_1', 'jGroup1', NULL, 'com.dufy.jdbctest.MyJob', false, false, false, false, '230D0A2353756E204A756C2032352031333A32353A30362043535420323032310D0A')
又从qrtz_TRIGGERS 查询
2021-07-25 13:25:06 | Time 0 ms | statement-2 | SELECT TRIGGER_NAME FROM qrtz_TRIGGERS WHERE SCHED_NAME = 'dufy_test' AND TRIGGER_NAME = 'trigge rser1_1' AND TRIGGER_GROUP = 'tGro udsgfsp1'
从qrtz_CRON_TRIGGERS 查询
2021-07-25 13:25:06 | Time 0 ms | statement-0 | SELECT * FROM qrtz_CRON_TRIGGERS WHERE SCHED_NAME = 'dufy_test' AND TRIGGER_NAME = 'trigger1' AND TRIGGER_GROUP = 'group1'
从qrtz_PAUSED_TRIGGER_GRPS查询 两次， 第二次是 查询 '_$_ALL_GROUPS_PAUSED_$_'
2021-07-25 13:25:06 | Time 2 ms | statement-2 | SELECT TRIGGER_GROUP FROM qrtz_PAUSED_TRIGGER_GRPS WHERE SCHED_NAME = 'dufy_test' AND TRIGGER_GROUP = 'tGro udsgfsp1'
2021-07-25 13:25:06 | Time 0 ms | statement-2 | SELECT TRIGGER_GROUP FROM qrtz_PAUSED_TRIGGER_GRPS WHERE SCHED_NAME = 'dufy_test' AND TRIGGER_GROUP = '_$_ALL_GROUPS_PAUSED_$_'
新增一条数据到 qrtz_TRIGGERS 状态为WAITING，misfire策略函数为 -1
2021-07-25 13:25:06 | Time 1 ms | statement-2 | INSERT INTO qrtz_TRIGGERS (SCHED_NAME, TRIGGER_NAME, TRIGGER_GROUP, JOB_NAME, JOB_GROUP, DESCRIPTION, NEXT_FIRE_TIME, PREV_FIRE_TIME, TRIGGER_STATE, TRIGGER_TYPE, START_TIME, END_TIME, CALENDAR_NAME, MISFIRE_INSTR, JOB_DATA, PRIORITY) VALUES('dufy_test', 'trigge rser1_1', 'tGro udsgfsp1', 'job1_1', 'jGroup1', NULL, 1627190702886, -1, 'WAITING', 'SIMPLE', 1627190702886, 0, NULL, 0, '', 5)
新增一条数据到 qrtz_SIMPLE_TRIGGERS
2021-07-25 13:25:06 | Time 1 ms | statement-2 | INSERT INTO qrtz_SIMPLE_TRIGGERS (SCHED_NAME, TRIGGER_NAME, TRIGGER_GROUP, REPEAT_COUNT, REPEAT_INTERVAL, TIMES_TRIGGERED) VALUES('dufy_test', 'trigge rser1_1', 'tGro udsgfsp1', 49, 1000, 0)
又从qrtz_JOB_DETAILS 查询 job
2021-07-25 13:25:06 | Time 0 ms | statement-0 | SELECT * FROM qrtz_JOB_DETAILS WHERE SCHED_NAME = 'dufy_test' AND JOB_NAME = 'job1' AND JOB_GROUP = 'group1'
2021-07-25 13:25:06 | Time 7 ms | commit-2 |
更新qrtz_TRIGGERS 的状态为WAITING
2021-07-25 13:25:06 | Time 1 ms | statement-0 | UPDATE qrtz_TRIGGERS SET TRIGGER_STATE = 'ACQUIRED' WHERE SCHED_NAME = 'dufy_test' AND TRIGGER_NAME = 'trigger1' AND TRIGGER_GROUP = 'group1' AND TRIGGER_STATE = 'WAITING'
13:25:06.992 [main] DEBUG o.q.i.jdbcjobstore.SimpleSemaphore - Lock 'TRIGGER_ACCESS' retuned by: main
又新增行到 qrtz_FIRED_TRIGGERS
2021-07-25 13:25:06 | Time 1 ms | statement-0 | INSERT INTO qrtz_FIRED_TRIGGERS (SCHED_NAME, ENTRY_ID, TRIGGER_NAME, TRIGGER_GROUP, INSTANCE_NAME, FIRED_TIME, SCHED_TIME, STATE, JOB_NAME, JOB_GROUP, IS_NONCONCURRENT, REQUESTS_RECOVERY, PRIORITY) VALUES('dufy_test', 'NON_CLUSTERED1627190703397', 'trigger1', 'group1', 'NON_CLUSTERED', 1627190706994, 1627190700000, 'ACQUIRED', NULL, NULL, false, false, 5)
发放 锁
2021-07-25 13:25:07 | Time 7 ms | commit-0 |
13:25:07.005 [dufy_test_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread - batch acquisition of 1 triggers
13:25:07.008 [dufy_test_QuartzSchedulerThread] DEBUG o.q.i.jdbcjobstore.SimpleSemaphore - Lock 'TRIGGER_ACCESS' is desired by: dufy_test_QuartzSchedulerThread
13:25:07.008 [dufy_test_QuartzSchedulerThread] DEBUG o.q.i.jdbcjobstore.SimpleSemaphore - Lock 'TRIGGER_ACCESS' is being obtained: dufy_test_QuartzSchedulerThread
13:25:07.008 [dufy_test_QuartzSchedulerThread] DEBUG o.q.i.jdbcjobstore.SimpleSemaphore - Lock 'TRIGGER_ACCESS' given to: dufy_test_QuartzSchedulerThread
又查询qrtz_TRIGGERS
2021-07-25 13:25:07 | Time 0 ms | statement-0 | SELECT TRIGGER_STATE FROM qrtz_TRIGGERS WHERE SCHED_NAME = 'dufy_test' AND TRIGGER_NAME = 'trigger1' AND TRIGGER_GROUP = 'group1'
查询 qrtz_JOB_DETAILS
2021-07-25 13:25:07 | Time 0 ms | statement-0 | SELECT * FROM qrtz_JOB_DETAILS WHERE SCHED_NAME = 'dufy_test' AND JOB_NAME = 'job1' AND JOB_GROUP = 'group1'
更新 qrtz_FIRED_TRIGGERS
2021-07-25 13:25:07 | Time 1 ms | statement-0 | UPDATE qrtz_FIRED_TRIGGERS SET INSTANCE_NAME = 'NON_CLUSTERED', FIRED_TIME = 1627190707032, SCHED_TIME = 1627190700000, STATE = 'EXECUTING', JOB_NAME = 'job1', JOB_GROUP = 'group1', IS_NONCONCURRENT = false, REQUESTS_RECOVERY = false WHERE SCHED_NAME = 'dufy_test' AND ENTRY_ID = 'NON_CLUSTERED1627190703397'
查询qrtz_TRIGGERS
2021-07-25 13:25:07 | Time 0 ms | statement-0 | SELECT TRIGGER_NAME FROM qrtz_TRIGGERS WHERE SCHED_NAME = 'dufy_test' AND TRIGGER_NAME = 'trigger1' AND TRIGGER_GROUP = 'group1'
更新qrtz_TRIGGERS 状态为 WAITING
2021-07-25 13:25:07 | Time 1 ms | statement-0 | UPDATE qrtz_TRIGGERS SET JOB_NAME = 'job1', JOB_GROUP = 'group1', DESCRIPTION = NULL, NEXT_FIRE_TIME = 1627190702000, PREV_FIRE_TIME = 1627190700000, TRIGGER_STATE = 'WAITING', TRIGGER_TYPE = 'CRON', START_TIME = 1626598030000, END_TIME = 0, CALENDAR_NAME = NULL, MISFIRE_INSTR = 0, PRIORITY = 5 WHERE SCHED_NAME = 'dufy_test' AND TRIGGER_NAME = 'trigger1' AND TRIGGER_GROUP = 'group1'
更新qrtz_CRON_TRIGGERS 的CRON_EXPRESSION
2021-07-25 13:25:07 | Time 5 ms | statement-0 | UPDATE qrtz_CRON_TRIGGERS SET CRON_EXPRESSION = '0/2 * * * * ?', TIME_ZONE_ID = 'Asia/Shanghai' WHERE SCHED_NAME = 'dufy_test' AND TRIGGER_NAME = 'trigger1' AND TRIGGER_GROUP = 'group1'
2021-07-25 13:25:07 | Time 10 ms | commit-0 |
13:25:07.070 [dufy_test_QuartzSchedulerThread] DEBUG o.q.i.jdbcjobstore.SimpleSemaphore - Lock 'TRIGGER_ACCESS' retuned by: dufy_test_QuartzSchedulerThread
13:25:07.078 [dufy_test_QuartzSchedulerThread] DEBUG o.q.simpl.PropertySettingJobFactory - Producing instance of Job 'group1.job1', class="com".dufy.learn.HelloCronJob
真正的 执行job
13:25:07.111 [dufy_test_Worker-1] DEBUG org.quartz.core.JobRunShell - Calling execute on job group1.job1
13:25:07.113 [dufy_test_Worker-1] INFO com.dufy.learn.HelloCronJob - Hello Cron Trigger World! - Sun Jul 25 13:25:07 CST 2021
查询qrtz_TRIGGERS 新的 窗口
2021-07-25 13:25:07 | Time 6 ms | statement-0 | SELECT TRIGGER_NAME, TRIGGER_GROUP, NEXT_FIRE_TIME, PRIORITY FROM qrtz_TRIGGERS WHERE SCHED_NAME = 'dufy_test' AND TRIGGER_STATE = 'WAITING' AND NEXT_FIRE_TIME <= 1627190737083 AND (MISFIRE_INSTR = -1 OR (MISFIRE_INSTR != -1 AND NEXT_FIRE_TIME >= 1627190647111)) ORDER BY NEXT_FIRE_TIME ASC, PRIORITY DESC
java.lang.NullPointerException
at com.dufy.learn.HelloCronJob.execute(HelloCronJob.java:71)
at org.quartz.core.JobRunShell.run(JobRunShell.java:202)
at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573)
13:25:07.124 [dufy_test_Worker-1] INFO com.dufy.learn.HelloCronJob - Hello Cron size --- ! - null
13:25:07.124 [dufy_test_Worker-1] INFO com.dufy.learn.HelloCronJob - Hello Cron end ! -
13:25:07.126 [dufy_test_Worker-1] DEBUG o.q.i.jdbcjobstore.SimpleSemaphore - Lock 'TRIGGER_ACCESS' is desired by: dufy_test_Worker-1
2021-07-25 13:25:07 | Time 1 ms | statement-0
完整如下
Connected to the target VM, address: '127.0.0.1:36317', transport: 'socket' trigger = Trigger 'tGro udsgfsp1.trigge rser1_1': triggerClass: 'org.quartz.impl.triggers.SimpleTriggerImpl calendar: 'null' misfireInstruction: 0 nextFireTime: null 七月 25, 2021 2:10:02 下午 com.mchange.v2.log.MLog <clinit> 信息: MLog clients using java 1.4+ standard logging. 七月 25, 2021 2:10:04 下午 com.mchange.v2.c3p0.C3P0Registry banner 信息: Initializing c3p0-0.9.1.1 [built 15-March-2007 01:32:31; debug? true; trace: 10] 14:10:05.049 [main] INFO org.quartz.impl.StdSchedulerFactory - Using default implementation for ThreadExecutor 14:10:05.064 [main] INFO org.quartz.simpl.SimpleThreadPool - Job execution threads will use class loader of thread: main 14:10:05.092 [main] INFO o.quartz.core.SchedulerSignalerImpl - Initialized Scheduler Signaller of type: class org.quartz.core.SchedulerSignalerImpl 14:10:05.095 [main] INFO org.quartz.core.QuartzScheduler - Quartz Scheduler v.2.2.1 created. 14:10:05.097 [main] INFO o.q.impl.jdbcjobstore.JobStoreTX - Using thread monitor-based data access locking (synchronization). 14:10:05.098 [main] INFO o.q.impl.jdbcjobstore.JobStoreTX - JobStoreTX initialized. 14:10:05.100 [main] INFO org.quartz.core.QuartzScheduler - Scheduler meta-data: Quartz Scheduler (v2.2.1) 'dufy_test' with instanceId 'NON_CLUSTERED' Scheduler class: 'org.quartz.core.QuartzScheduler' - running locally. NOT STARTED. Currently in standby mode. Number of jobs executed: 0 Using thread pool 'org.quartz.simpl.SimpleThreadPool' - with 10 threads. Using job-store 'org.quartz.impl.jdbcjobstore.JobStoreTX' - which supports persistence. and is not clustered. 14:10:05.100 [main] INFO org.quartz.impl.StdSchedulerFactory - Quartz scheduler 'dufy_test' initialized from default resource file in Quartz package: 'quartz.properties' 14:10:05.100 [main] INFO org.quartz.impl.StdSchedulerFactory - Quartz scheduler version: 2.2.1 scheduler = org.quartz.impl.StdScheduler@dd8ba08 14:10:05.102 [main] DEBUG o.q.i.jdbcjobstore.SimpleSemaphore - Lock 'TRIGGER_ACCESS' is desired by: main 14:10:05.102 [main] DEBUG o.q.i.jdbcjobstore.SimpleSemaphore - Lock 'TRIGGER_ACCESS' is being obtained: main 14:10:05.102 [main] DEBUG o.q.i.jdbcjobstore.SimpleSemaphore - Lock 'TRIGGER_ACCESS' given to: main 七月 25, 2021 2:10:05 下午 com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource getPoolManager 信息: Initializing c3p0 pool... com.mchange.v2.c3p0.ComboPooledDataSource [ acquireIncrement -> 3, acquireRetryAttempts -> 30, acquireRetryDelay -> 1000, autoCommitOnClose -> false, automaticTestTable -> null, breakAfterAcquireFailure -> false, checkoutTimeout -> 0, connectionCustomizerClassName -> null, connectionTesterClassName -> com.mchange.v2.c3p0.impl.DefaultConnectionTester, dataSourceName -> 1hgeby9ai1p4d2mf1tody8v|8b96fde, debugUnreturnedConnectionStackTraces -> false, description -> null, driverClass -> com.p6spy.engine.spy.P6SpyDriver, factoryClassLocation -> null, forceIgnoreUnresolvedTransactions -> false, identityToken -> 1hgeby9ai1p4d2mf1tody8v|8b96fde, idleConnectionTestPeriod -> 0, initialPoolSize -> 3, jdbcUrl -> jdbc:p6spy:mysql://localhost:3306/elppmdb, lastAcquisitionFailureDefaultUser -> null, maxAdministrativeTaskTime -> 0, maxConnectionAge -> 0, maxIdleTime -> 0, maxIdleTimeExcessConnections -> 0, maxPoolSize -> 10, maxStatements -> 0, maxStatementsPerConnection -> 120, minPoolSize -> 1, numHelperThreads -> 3, numThreadsAwaitingCheckoutDefaultUser -> 0, preferredTestQuery -> null, properties -> {user=******, password=******}, propertyCycle -> 0, testConnectionOnCheckin -> false, testConnectionOnCheckout -> false, unreturnedConnectionTimeout -> 0, usesTraditionalReflectiveProxies -> false ] 14:10:06.072 [main] DEBUG o.q.impl.jdbcjobstore.JobStoreTX - Adding TriggerPersistenceDelegate of type: org.quartz.impl.jdbcjobstore.SimpleTriggerPersistenceDelegate 14:10:06.074 [main] DEBUG o.q.impl.jdbcjobstore.JobStoreTX - Adding TriggerPersistenceDelegate of type: org.quartz.impl.jdbcjobstore.CronTriggerPersistenceDelegate 14:10:06.078 [main] DEBUG o.q.impl.jdbcjobstore.JobStoreTX - Adding TriggerPersistenceDelegate of type: org.quartz.impl.jdbcjobstore.CalendarIntervalTriggerPersistenceDelegate 14:10:06.081 [main] DEBUG o.q.impl.jdbcjobstore.JobStoreTX - Adding TriggerPersistenceDelegate of type: org.quartz.impl.jdbcjobstore.DailyTimeIntervalTriggerPersistenceDelegate 14:10:06.094 [Timer-0] DEBUG org.quartz.utils.UpdateChecker - Checking for available updated version of Quartz... 2021-07-25 14:10:06 | Time 9 ms | statement-0 | UPDATE qrtz_TRIGGERS SET TRIGGER_STATE = 'WAITING' WHERE SCHED_NAME = 'dufy_test' AND (TRIGGER_STATE = 'ACQUIRED' OR TRIGGER_STATE = 'BLOCKED') 2021-07-25 14:10:06 | Time 1 ms | statement-0 | UPDATE qrtz_TRIGGERS SET TRIGGER_STATE = 'PAUSED' WHERE SCHED_NAME = 'dufy_test' AND (TRIGGER_STATE = 'PAUSED_BLOCKED' OR TRIGGER_STATE = 'PAUSED_BLOCKED') 14:10:06.150 [main] INFO o.q.impl.jdbcjobstore.JobStoreTX - Freed 1 triggers from 'acquired' / 'blocked' state. 2021-07-25 14:10:06 | Time 10 ms | statement-0 | SELECT TRIGGER_NAME, TRIGGER_GROUP FROM qrtz_TRIGGERS WHERE SCHED_NAME = 'dufy_test' AND NOT (MISFIRE_INSTR = -1) AND NEXT_FIRE_TIME < 1627193346151 AND TRIGGER_STATE = 'WAITING' ORDER BY NEXT_FIRE_TIME ASC, PRIORITY DESC 14:10:06.184 [main] INFO o.q.impl.jdbcjobstore.JobStoreTX - Handling 2 trigger(s) that missed their scheduled fire-time. 2021-07-25 14:10:06 | Time 6 ms | statement-0 | SELECT * FROM qrtz_TRIGGERS WHERE SCHED_NAME = 'dufy_test' AND TRIGGER_NAME = 'trigge rser1_1' AND TRIGGER_GROUP = 'tGro udsgfsp1' 2021-07-25 14:10:06 | Time 3 ms | statement-0 | SELECT * FROM qrtz_SIMPLE_TRIGGERS WHERE SCHED_NAME = 'dufy_test' AND TRIGGER_NAME = 'trigge rser1_1' AND TRIGGER_GROUP = 'tGro udsgfsp1' 2021-07-25 14:10:06 | Time 0 ms | statement-0 | SELECT TRIGGER_NAME FROM qrtz_TRIGGERS WHERE SCHED_NAME = 'dufy_test' AND TRIGGER_NAME = 'trigge rser1_1' AND TRIGGER_GROUP = 'tGro udsgfsp1' 2021-07-25 14:10:06 | Time 3 ms | statement-0 | SELECT TRIGGER_GROUP FROM qrtz_PAUSED_TRIGGER_GRPS WHERE SCHED_NAME = 'dufy_test' AND TRIGGER_GROUP = 'tGro udsgfsp1' 2021-07-25 14:10:06 | Time 0 ms | statement-0 | SELECT TRIGGER_GROUP FROM qrtz_PAUSED_TRIGGER_GRPS WHERE SCHED_NAME = 'dufy_test' AND TRIGGER_GROUP = '_$_ALL_GROUPS_PAUSED_$_' 2021-07-25 14:10:06 | Time 0 ms | statement-0 | SELECT * FROM qrtz_JOB_DETAILS WHERE SCHED_NAME = 'dufy_test' AND JOB_NAME = 'job1_1' AND JOB_GROUP = 'jGroup1' 2021-07-25 14:10:06 | Time 1 ms | statement-0 | UPDATE qrtz_TRIGGERS SET JOB_NAME = 'job1_1', JOB_GROUP = 'jGroup1', DESCRIPTION = NULL, NEXT_FIRE_TIME = 1627193406232, PREV_FIRE_TIME = 1627190709886, TRIGGER_STATE = 'WAITING', TRIGGER_TYPE = 'SIMPLE', START_TIME = 1627193406232, END_TIME = 0, CALENDAR_NAME = NULL, MISFIRE_INSTR = 0, PRIORITY = 5 WHERE SCHED_NAME = 'dufy_test' AND TRIGGER_NAME = 'trigge rser1_1' AND TRIGGER_GROUP = 'tGro udsgfsp1' 2021-07-25 14:10:06 | Time 1 ms | statement-0 | UPDATE qrtz_SIMPLE_TRIGGERS SET REPEAT_COUNT = 41, REPEAT_INTERVAL = 1000, TIMES_TRIGGERED = 0 WHERE SCHED_NAME = 'dufy_test' AND TRIGGER_NAME = 'trigge rser1_1' AND TRIGGER_GROUP = 'tGro udsgfsp1' 2021-07-25 14:10:06 | Time 0 ms | statement-0 | SELECT * FROM qrtz_TRIGGERS WHERE SCHED_NAME = 'dufy_test' AND TRIGGER_NAME = 'trigger1' AND TRIGGER_GROUP = 'group1' 2021-07-25 14:10:06 | Time 2 ms | statement-0 | SELECT * FROM qrtz_CRON_TRIGGERS WHERE SCHED_NAME = 'dufy_test' AND TRIGGER_NAME = 'trigger1' AND TRIGGER_GROUP = 'group1' 2021-07-25 14:10:06 | Time 0 ms | statement-0 | SELECT TRIGGER_NAME FROM qrtz_TRIGGERS WHERE SCHED_NAME = 'dufy_test' AND TRIGGER_NAME = 'trigger1' AND TRIGGER_GROUP = 'group1' 2021-07-25 14:10:06 | Time 0 ms | statement-0 | SELECT TRIGGER_GROUP FROM qrtz_PAUSED_TRIGGER_GRPS WHERE SCHED_NAME = 'dufy_test' AND TRIGGER_GROUP = 'group1' 2021-07-25 14:10:06 | Time 0 ms | statement-0 | SELECT TRIGGER_GROUP FROM qrtz_PAUSED_TRIGGER_GRPS WHERE SCHED_NAME = 'dufy_test' AND TRIGGER_GROUP = '_$_ALL_GROUPS_PAUSED_$_' 2021-07-25 14:10:06 | Time 1 ms | statement-0 | SELECT * FROM qrtz_JOB_DETAILS WHERE SCHED_NAME = 'dufy_test' AND JOB_NAME = 'job1' AND JOB_GROUP = 'group1' 2021-07-25 14:10:06 | Time 1 ms | statement-0 | UPDATE qrtz_TRIGGERS SET JOB_NAME = 'job1', JOB_GROUP = 'group1', DESCRIPTION = NULL, NEXT_FIRE_TIME = 1627193406279, PREV_FIRE_TIME = 1627190710000, TRIGGER_STATE = 'WAITING', TRIGGER_TYPE = 'CRON', START_TIME = 1626598030000, END_TIME = 0, CALENDAR_NAME = NULL, MISFIRE_INSTR = 0, PRIORITY = 5 WHERE SCHED_NAME = 'dufy_test' AND TRIGGER_NAME = 'trigger1' AND TRIGGER_GROUP = 'group1' 2021-07-25 14:10:06 | Time 1 ms | statement-0 | UPDATE qrtz_CRON_TRIGGERS SET CRON_EXPRESSION = '0/2 * * * * ?', TIME_ZONE_ID = 'Asia/Shanghai' WHERE SCHED_NAME = 'dufy_test' AND TRIGGER_NAME = 'trigger1' AND TRIGGER_GROUP = 'group1' 2021-07-25 14:10:06 | Time 0 ms | statement-0 | SELECT * FROM qrtz_FIRED_TRIGGERS WHERE SCHED_NAME = 'dufy_test' AND INSTANCE_NAME = 'NON_CLUSTERED' AND REQUESTS_RECOVERY = true 14:10:06.306 [main] INFO o.q.impl.jdbcjobstore.JobStoreTX - Recovering 0 jobs that were in-progress at the time of the last shut-down. 14:10:06.307 [main] INFO o.q.impl.jdbcjobstore.JobStoreTX - Recovery complete. 2021-07-25 14:10:06 | Time 0 ms | statement-0 | SELECT TRIGGER_NAME, TRIGGER_GROUP FROM qrtz_TRIGGERS WHERE SCHED_NAME = 'dufy_test' AND TRIGGER_STATE = 'COMPLETE' 14:10:06.309 [main] INFO o.q.impl.jdbcjobstore.JobStoreTX - Removed 0 'complete' triggers. 2021-07-25 14:10:06 | Time 1 ms | statement-0 | DELETE FROM qrtz_FIRED_TRIGGERS WHERE SCHED_NAME = 'dufy_test' 14:10:06.312 [main] INFO o.q.impl.jdbcjobstore.JobStoreTX - Removed 1 stale fired job entries. 2021-07-25 14:10:06 | Time 11 ms | commit-0 | 14:10:06.329 [main] DEBUG o.q.i.jdbcjobstore.SimpleSemaphore - Lock 'TRIGGER_ACCESS' retuned by: main 14:10:06.334 [main] DEBUG o.q.impl.jdbcjobstore.JobStoreTX - JobStore background threads started (as scheduler was started). 14:10:06.334 [main] INFO org.quartz.core.QuartzScheduler - Scheduler dufy_test_$_NON_CLUSTERED started. 14:10:06.334 [QuartzScheduler_dufy_test-NON_CLUSTERED_MisfireHandler] DEBUG o.q.impl.jdbcjobstore.JobStoreTX - MisfireHandler: scanning for misfires... 14:10:06.336 [main] DEBUG o.q.i.jdbcjobstore.SimpleSemaphore - Lock 'TRIGGER_ACCESS' is desired by: main 14:10:06.337 [main] DEBUG o.q.i.jdbcjobstore.SimpleSemaphore - Lock 'TRIGGER_ACCESS' is being obtained: main 14:10:06.337 [main] DEBUG o.q.i.jdbcjobstore.SimpleSemaphore - Lock 'TRIGGER_ACCESS' given to: main 2021-07-25 14:10:06 | Time 0 ms | statement-0 | SELECT COUNT(TRIGGER_NAME) FROM qrtz_TRIGGERS WHERE SCHED_NAME = 'dufy_test' AND NOT (MISFIRE_INSTR = -1) AND NEXT_FIRE_TIME < 1627193346336 AND TRIGGER_STATE = 'WAITING' 14:10:06.342 [QuartzScheduler_dufy_test-NON_CLUSTERED_MisfireHandler] DEBUG o.q.impl.jdbcjobstore.JobStoreTX - Found 0 triggers that missed their scheduled fire-time. 2021-07-25 14:10:06 | Time 0 ms | commit-0 | 2021-07-25 14:10:06 | Time 1 ms | statement-2 | SELECT TRIGGER_NAME, TRIGGER_GROUP, NEXT_FIRE_TIME, PRIORITY FROM qrtz_TRIGGERS WHERE SCHED_NAME = 'dufy_test' AND TRIGGER_STATE = 'WAITING' AND NEXT_FIRE_TIME <= 1627193436334 AND (MISFIRE_INSTR = -1 OR (MISFIRE_INSTR != -1 AND NEXT_FIRE_TIME >= 1627193346340)) ORDER BY NEXT_FIRE_TIME ASC, PRIORITY DESC 2021-07-25 14:10:06 | Time 3 ms | statement-1 | SELECT JOB_NAME FROM qrtz_JOB_DETAILS WHERE SCHED_NAME = 'dufy_test' AND JOB_NAME = 'job1_1' AND JOB_GROUP = 'jGroup1' 2021-07-25 14:10:06 | Time 0 ms | rollback-1 | 14:10:06.348 [main] DEBUG o.q.i.jdbcjobstore.SimpleSemaphore - Lock 'TRIGGER_ACCESS' retuned by: main 2021-07-25 14:10:06 | Time 2 ms | statement-2 | SELECT * FROM qrtz_TRIGGERS WHERE SCHED_NAME = 'dufy_test' AND TRIGGER_NAME = 'trigge rser1_1' AND TRIGGER_GROUP = 'tGro udsgfsp1' org.quartz.ObjectAlreadyExistsException: Unable to store Job : 'jGroup1.job1_1', because one already exists with this identification. at org.quartz.impl.jdbcjobstore.JobStoreSupport.storeJob(JobStoreSupport.java:1108) at org.quartz.impl.jdbcjobstore.JobStoreSupport$2.executeVoid(JobStoreSupport.java:1062) at org.quartz.impl.jdbcjobstore.JobStoreSupport$VoidTransactionCallback.execute(JobStoreSupport.java:3703) at org.quartz.impl.jdbcjobstore.JobStoreSupport$VoidTransactionCallback.execute(JobStoreSupport.java:3701) at org.quartz.impl.jdbcjobstore.JobStoreSupport.executeInNonManagedTXLock(JobStoreSupport.java:3787) at org.quartz.impl.jdbcjobstore.JobStoreTX.executeInLock(JobStoreTX.java:93) at org.quartz.impl.jdbcjobstore.JobStoreSupport.storeJobAndTrigger(JobStoreSupport.java:1058) at org.quartz.core.QuartzScheduler.scheduleJob(QuartzScheduler.java:886) at org.quartz.impl.StdScheduler.scheduleJob(StdScheduler.java:249) at com.dufy.jdbctest.QuartzJdbcTest.startSchedule(QuartzJdbcTest.java:59) at com.dufy.jdbctest.QuartzJdbcTest.main(QuartzJdbcTest.java:23) 2021-07-25 14:10:06 | Time 20 ms | statement-2 | SELECT * FROM qrtz_SIMPLE_TRIGGERS WHERE SCHED_NAME = 'dufy_test' AND TRIGGER_NAME = 'trigge rser1_1' AND TRIGGER_GROUP = 'tGro udsgfsp1' 2021-07-25 14:10:06 | Time 0 ms | statement-2 | SELECT * FROM qrtz_JOB_DETAILS WHERE SCHED_NAME = 'dufy_test' AND JOB_NAME = 'job1_1' AND JOB_GROUP = 'jGroup1' 2021-07-25 14:10:06 | Time 1 ms | statement-2 | UPDATE qrtz_TRIGGERS SET TRIGGER_STATE = 'ACQUIRED' WHERE SCHED_NAME = 'dufy_test' AND TRIGGER_NAME = 'trigge rser1_1' AND TRIGGER_GROUP = 'tGro udsgfsp1' AND TRIGGER_STATE = 'WAITING' 2021-07-25 14:10:06 | Time 1 ms | statement-2 | INSERT INTO qrtz_FIRED_TRIGGERS (SCHED_NAME, ENTRY_ID, TRIGGER_NAME, TRIGGER_GROUP, INSTANCE_NAME, FIRED_TIME, SCHED_TIME, STATE, JOB_NAME, JOB_GROUP, IS_NONCONCURRENT, REQUESTS_RECOVERY, PRIORITY) VALUES('dufy_test', 'NON_CLUSTERED1627193402779', 'trigge rser1_1', 'tGro udsgfsp1', 'NON_CLUSTERED', 1627193406410, 1627193406232, 'ACQUIRED', NULL, NULL, false, false, 5) 2021-07-25 14:10:06 | Time 13 ms | commit-2 | 14:10:06.431 [dufy_test_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread - batch acquisition of 1 triggers 14:10:06.434 [dufy_test_QuartzSchedulerThread] DEBUG o.q.i.jdbcjobstore.SimpleSemaphore - Lock 'TRIGGER_ACCESS' is desired by: dufy_test_QuartzSchedulerThread 14:10:06.435 [dufy_test_QuartzSchedulerThread] DEBUG o.q.i.jdbcjobstore.SimpleSemaphore - Lock 'TRIGGER_ACCESS' is being obtained: dufy_test_QuartzSchedulerThread 14:10:06.435 [dufy_test_QuartzSchedulerThread] DEBUG o.q.i.jdbcjobstore.SimpleSemaphore - Lock 'TRIGGER_ACCESS' given to: dufy_test_QuartzSchedulerThread 2021-07-25 14:10:06 | Time 0 ms | statement-2 | SELECT TRIGGER_STATE FROM qrtz_TRIGGERS WHERE SCHED_NAME = 'dufy_test' AND TRIGGER_NAME = 'trigge rser1_1' AND TRIGGER_GROUP = 'tGro udsgfsp1' 2021-07-25 14:10:06 | Time 0 ms | statement-2 | SELECT * FROM qrtz_JOB_DETAILS WHERE SCHED_NAME = 'dufy_test' AND JOB_NAME = 'job1_1' AND JOB_GROUP = 'jGroup1' 2021-07-25 14:10:06 | Time 1 ms | statement-2 | UPDATE qrtz_FIRED_TRIGGERS SET INSTANCE_NAME = 'NON_CLUSTERED', FIRED_TIME = 1627193406440, SCHED_TIME = 1627193406232, STATE = 'EXECUTING', JOB_NAME = 'job1_1', JOB_GROUP = 'jGroup1', IS_NONCONCURRENT = false, REQUESTS_RECOVERY = false WHERE SCHED_NAME = 'dufy_test' AND ENTRY_ID = 'NON_CLUSTERED1627193402779' 2021-07-25 14:10:06 | Time 0 ms | statement-2 | SELECT TRIGGER_NAME FROM qrtz_TRIGGERS WHERE SCHED_NAME = 'dufy_test' AND TRIGGER_NAME = 'trigge rser1_1' AND TRIGGER_GROUP = 'tGro udsgfsp1' 2021-07-25 14:10:06 | Time 5 ms | statement-2 | UPDATE qrtz_TRIGGERS SET JOB_NAME = 'job1_1', JOB_GROUP = 'jGroup1', DESCRIPTION = NULL, NEXT_FIRE_TIME = 1627193407232, PREV_FIRE_TIME = 1627193406232, TRIGGER_STATE = 'WAITING', TRIGGER_TYPE = 'SIMPLE', START_TIME = 1627193406232, END_TIME = 0, CALENDAR_NAME = NULL, MISFIRE_INSTR = 0, PRIORITY = 5 WHERE SCHED_NAME = 'dufy_test' AND TRIGGER_NAME = 'trigge rser1_1' AND TRIGGER_GROUP = 'tGro udsgfsp1' 2021-07-25 14:10:06 | Time 4 ms | statement-2 | UPDATE qrtz_SIMPLE_TRIGGERS SET REPEAT_COUNT = 41, REPEAT_INTERVAL = 1000, TIMES_TRIGGERED = 1 WHERE SCHED_NAME = 'dufy_test' AND TRIGGER_NAME = 'trigge rser1_1' AND TRIGGER_GROUP = 'tGro udsgfsp1' 2021-07-25 14:10:06 | Time 8 ms | commit-2 | 14:10:06.481 [dufy_test_QuartzSchedulerThread] DEBUG o.q.i.jdbcjobstore.SimpleSemaphore - Lock 'TRIGGER_ACCESS' retuned by: dufy_test_QuartzSchedulerThread 14:10:06.486 [dufy_test_QuartzSchedulerThread] DEBUG o.q.simpl.PropertySettingJobFactory - Producing instance of Job 'jGroup1.job1_1', class=com.dufy.jdbctest.MyJob 14:10:06.493 [dufy_test_Worker-1] DEBUG org.quartz.core.JobRunShell - Calling execute on job jGroup1.job1_1 14:10:06.493 [dufy_test_Worker-1] INFO com.dufy.jdbctest.MyJob - MyJob is start .................. 14:10:06.493 [dufy_test_Worker-1] INFO com.dufy.jdbctest.MyJob - Hello quzrtz 2021-07-25 14:10:06 14:10:06.493 [dufy_test_Worker-1] INFO com.dufy.jdbctest.MyJob - MyJob is end ..................... 2021-07-25 14:10:06 | Time 1 ms | statement-2 | SELECT TRIGGER_NAME, TRIGGER_GROUP, NEXT_FIRE_TIME, PRIORITY FROM qrtz_TRIGGERS WHERE SCHED_NAME = 'dufy_test' AND TRIGGER_STATE = 'WAITING' AND NEXT_FIRE_TIME <= 1627193436492 AND (MISFIRE_INSTR = -1 OR (MISFIRE_INSTR != -1 AND NEXT_FIRE_TIME >= 1627193346493)) ORDER BY NEXT_FIRE_TIME ASC, PRIORITY DESC 14:10:06.495 [dufy_test_Worker-1] DEBUG o.q.i.jdbcjobstore.SimpleSemaphore - Lock 'TRIGGER_ACCESS' is desired by: dufy_test_Worker-1 14:10:06.495 [dufy_test_Worker-1] DEBUG o.q.i.jdbcjobstore.SimpleSemaphore - Lock 'TRIGGER_ACCESS' is being obtained: dufy_test_Worker-1 14:10:06.495 [dufy_test_Worker-1] DEBUG o.q.i.jdbcjobstore.SimpleSemaphore - Lock 'TRIGGER_ACCESS' given to: dufy_test_Worker-1 2021-07-25 14:10:06 | Time 1 ms | statement-2 | SELECT * FROM qrtz_TRIGGERS WHERE SCHED_NAME = 'dufy_test' AND TRIGGER_NAME = 'trigger1' AND TRIGGER_GROUP = 'group1' 2021-07-25 14:10:06 | Time 1 ms | statement-1 | DELETE FROM qrtz_FIRED_TRIGGERS WHERE SCHED_NAME = 'dufy_test' AND ENTRY_ID = 'NON_CLUSTERED1627193402779' 2021-07-25 14:10:06 | Time 0 ms | statement-2 | SELECT * FROM qrtz_CRON_TRIGGERS WHERE SCHED_NAME = 'dufy_test' AND TRIGGER_NAME = 'trigger1' AND TRIGGER_GROUP = 'group1' 2021-07-25 14:10:06 | Time 0 ms | statement-2 | SELECT * FROM qrtz_JOB_DETAILS WHERE SCHED_NAME = 'dufy_test' AND JOB_NAME = 'job1' AND JOB_GROUP = 'group1' 2021-07-25 14:10:06 | Time 1 ms | statement-2 | UPDATE qrtz_TRIGGERS SET TRIGGER_STATE = 'ACQUIRED' WHERE SCHED_NAME = 'dufy_test' AND TRIGGER_NAME = 'trigger1' AND TRIGGER_GROUP = 'group1' AND TRIGGER_STATE = 'WAITING' 2021-07-25 14:10:06 | Time 1 ms | statement-2 | INSERT INTO qrtz_FIRED_TRIGGERS (SCHED_NAME, ENTRY_ID, TRIGGER_NAME, TRIGGER_GROUP, INSTANCE_NAME, FIRED_TIME, SCHED_TIME, STATE, JOB_NAME, JOB_GROUP, IS_NONCONCURRENT, REQUESTS_RECOVERY, PRIORITY) VALUES('dufy_test', 'NON_CLUSTERED1627193402780', 'trigger1', 'group1', 'NON_CLUSTERED', 1627193406507, 1627193406279, 'ACQUIRED', NULL, NULL, false, false, 5) 2021-07-25 14:10:06 | Time 7 ms | commit-2 | 2021-07-25 14:10:06 | Time 15 ms | commit-1 | 14:10:06.516 [dufy_test_Worker-1] DEBUG o.q.i.jdbcjobstore.SimpleSemaphore - Lock 'TRIGGER_ACCESS' retuned by: dufy_test_Worker-1 14:10:06.516 [dufy_test_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread - batch acquisition of 1 triggers 14:10:06.517 [dufy_test_QuartzSchedulerThread] DEBUG o.q.i.jdbcjobstore.SimpleSemaphore - Lock 'TRIGGER_ACCESS' is desired by: dufy_test_QuartzSchedulerThread 14:10:06.517 [dufy_test_QuartzSchedulerThread] DEBUG o.q.i.jdbcjobstore.SimpleSemaphore - Lock 'TRIGGER_ACCESS' is being obtained: dufy_test_QuartzSchedulerThread 14:10:06.517 [dufy_test_QuartzSchedulerThread] DEBUG o.q.i.jdbcjobstore.SimpleSemaphore - Lock 'TRIGGER_ACCESS' given to: dufy_test_QuartzSchedulerThread 2021-07-25 14:10:06 | Time 0 ms | statement-1 | SELECT TRIGGER_STATE FROM qrtz_TRIGGERS WHERE SCHED_NAME = 'dufy_test' AND TRIGGER_NAME = 'trigger1' AND TRIGGER_GROUP = 'group1' 2021-07-25 14:10:06 | Time 0 ms | statement-1 | SELECT * FROM qrtz_JOB_DETAILS WHERE SCHED_NAME = 'dufy_test' AND JOB_NAME = 'job1' AND JOB_GROUP = 'group1' 2021-07-25 14:10:06 | Time 1 ms | statement-1 | UPDATE qrtz_FIRED_TRIGGERS SET INSTANCE_NAME = 'NON_CLUSTERED', FIRED_TIME = 1627193406523, SCHED_TIME = 1627193406279, STATE = 'EXECUTING', JOB_NAME = 'job1', JOB_GROUP = 'group1', IS_NONCONCURRENT = false, REQUESTS_RECOVERY = false WHERE SCHED_NAME = 'dufy_test' AND ENTRY_ID = 'NON_CLUSTERED1627193402780' 2021-07-25 14:10:06 | Time 2 ms | statement-1 | SELECT TRIGGER_NAME FROM qrtz_TRIGGERS WHERE SCHED_NAME = 'dufy_test' AND TRIGGER_NAME = 'trigger1' AND TRIGGER_GROUP = 'group1' 2021-07-25 14:10:06 | Time 3 ms | statement-1 | UPDATE qrtz_TRIGGERS SET JOB_NAME = 'job1', JOB_GROUP = 'group1', DESCRIPTION = NULL, NEXT_FIRE_TIME = 1627193408000, PREV_FIRE_TIME = 1627193406279, TRIGGER_STATE = 'WAITING', TRIGGER_TYPE = 'CRON', START_TIME = 1626598030000, END_TIME = 0, CALENDAR_NAME = NULL, MISFIRE_INSTR = 0, PRIORITY = 5 WHERE SCHED_NAME = 'dufy_test' AND TRIGGER_NAME = 'trigger1' AND TRIGGER_GROUP = 'group1' 2021-07-25 14:10:06 | Time 2 ms | statement-1 | UPDATE qrtz_CRON_TRIGGERS SET CRON_EXPRESSION = '0/2 * * * * ?', TIME_ZONE_ID = 'Asia/Shanghai' WHERE SCHED_NAME = 'dufy_test' AND TRIGGER_NAME = 'trigger1' AND TRIGGER_GROUP = 'group1' 2021-07-25 14:10:06 | Time 6 ms | commit-1 | 14:10:06.556 [dufy_test_QuartzSchedulerThread] DEBUG o.q.i.jdbcjobstore.SimpleSemaphore - Lock 'TRIGGER_ACCESS' retuned by: dufy_test_QuartzSchedulerThread 14:10:06.557 [dufy_test_QuartzSchedulerThread] DEBUG o.q.simpl.PropertySettingJobFactory - Producing instance of Job 'group1.job1', class=com.dufy.learn.HelloCronJob 14:10:06.563 [dufy_test_Worker-2] DEBUG org.quartz.core.JobRunShell - Calling execute on job group1.job1 2021-07-25 14:10:06 | Time 5 ms | statement-1 | SELECT TRIGGER_NAME, TRIGGER_GROUP, NEXT_FIRE_TIME, PRIORITY FROM qrtz_TRIGGERS WHERE SCHED_NAME = 'dufy_test' AND TRIGGER_STATE = 'WAITING' AND NEXT_FIRE_TIME <= 1627193436563 AND (MISFIRE_INSTR = -1 OR (MISFIRE_INSTR != -1 AND NEXT_FIRE_TIME >= 1627193346565)) ORDER BY NEXT_FIRE_TIME ASC, PRIORITY DESC 2021-07-25 14:10:06 | Time 1 ms | statement-1 | SELECT * FROM qrtz_TRIGGERS WHERE SCHED_NAME = 'dufy_test' AND TRIGGER_NAME = 'trigge rser1_1' AND TRIGGER_GROUP = 'tGro udsgfsp1' 14:10:06.579 [dufy_test_Worker-2] INFO com.dufy.learn.HelloCronJob - Hello Cron Trigger World! - Sun Jul 25 14:10:06 CST 2021 java.lang.NullPointerException at com.dufy.learn.HelloCronJob.execute(HelloCronJob.java:71) at org.quartz.core.JobRunShell.run(JobRunShell.java:202) at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573) 14:10:06.580 [dufy_test_Worker-2] INFO com.dufy.learn.HelloCronJob - Hello Cron size --- ! - null 14:10:06.580 [dufy_test_Worker-2] INFO com.dufy.learn.HelloCronJob - Hello Cron end ! - 14:10:06.580 [dufy_test_Worker-2] DEBUG o.q.i.jdbcjobstore.SimpleSemaphore - Lock 'TRIGGER_ACCESS' is desired by: dufy_test_Worker-2 14:10:06.580 [dufy_test_Worker-2] DEBUG o.q.i.jdbcjobstore.SimpleSemaphore - Lock 'TRIGGER_ACCESS' is being obtained: dufy_test_Worker-2 14:10:06.580 [dufy_test_Worker-2] DEBUG o.q.i.jdbcjobstore.SimpleSemaphore - Lock 'TRIGGER_ACCESS' given to: dufy_test_Worker-2
quartz执行日志分析
启动的时候
执行过程- 扫描数据库：
准备真正的执行，
