quartz 日志观察

全部日志

06:58:18.802 [main] DEBUG o.q.i.j.StdRowLockSemaphore - Lock 'STATE_ACCESS' is desired by: main

06:58:18.887 [main] DEBUG o.q.i.j.StdRowLockSemaphore - Lock 'STATE_ACCESS' is being obtained: main

2021-07-29 06:58:18 | Time  26 ms | statement-1 | SELECT * FROM qrtz_LOCKS WHERE SCHED_NAME = 'dufy_test' AND LOCK_NAME = 'STATE_ACCESS' FOR UPDATE

06:58:18.942 [main] DEBUG o.q.i.j.StdRowLockSemaphore - Inserting new lock row for lock: 'STATE_ACCESS' being obtained by thread: main

2021-07-29 06:58:18 | Time  2 ms | statement-1 | INSERT INTO qrtz_LOCKS(SCHED_NAME, LOCK_NAME) VALUES ('dufy_test', 'STATE_ACCESS')

06:58:18.956 [main] DEBUG o.q.i.j.StdRowLockSemaphore - Lock 'STATE_ACCESS' given to: main

06:59:36.830 [main] DEBUG o.q.impl.jdbcjobstore.JobStoreTX - Adding TriggerPersistenceDelegate of type: org.quartz.impl.jdbcjobstore.SimpleTriggerPersistenceDelegate

06:59:36.838 [main] DEBUG o.q.impl.jdbcjobstore.JobStoreTX - Adding TriggerPersistenceDelegate of type: org.quartz.impl.jdbcjobstore.CronTriggerPersistenceDelegate

06:59:36.849 [main] DEBUG o.q.impl.jdbcjobstore.JobStoreTX - Adding TriggerPersistenceDelegate of type: org.quartz.impl.jdbcjobstore.CalendarIntervalTriggerPersistenceDelegate

06:59:36.856 [main] DEBUG o.q.impl.jdbcjobstore.JobStoreTX - Adding TriggerPersistenceDelegate of type: org.quartz.impl.jdbcjobstore.DailyTimeIntervalTriggerPersistenceDelegate

2021-07-29 06:59:36 | Time  1 ms | statement-1 | SELECT * FROM qrtz_SCHEDULER_STATE WHERE SCHED_NAME = 'dufy_test'

2021-07-29 06:59:36 | Time  1 ms | statement-1 | SELECT DISTINCT INSTANCE_NAME FROM qrtz_FIRED_TRIGGERS WHERE SCHED_NAME = 'dufy_test'

2021-07-29 06:59:36 | Time  2 ms | statement-1 | UPDATE qrtz_SCHEDULER_STATE SET LAST_CHECKIN_TIME = 1627513176882 WHERE SCHED_NAME = 'dufy_test' AND INSTANCE_NAME = 'DESKTOP-MBMDPHH1627513038976'

2021-07-29 06:59:36 | Time  2 ms | statement-1 | INSERT INTO qrtz_SCHEDULER_STATE (SCHED_NAME, INSTANCE_NAME, LAST_CHECKIN_TIME, CHECKIN_INTERVAL) VALUES('dufy_test', 'DESKTOP-MBMDPHH1627513038976', 1627513176882, 7500)

06:59:53.547 [main] DEBUG o.q.i.j.StdRowLockSemaphore - Lock 'TRIGGER_ACCESS' is desired by: main

06:59:53.549 [main] DEBUG o.q.i.j.StdRowLockSemaphore - Lock 'TRIGGER_ACCESS' is being obtained: main

2021-07-29 06:59:53 | Time  1 ms | statement-1 | SELECT * FROM qrtz_LOCKS WHERE SCHED_NAME = 'dufy_test' AND LOCK_NAME = 'TRIGGER_ACCESS' FOR UPDATE

06:59:53.558 [main] DEBUG o.q.i.j.StdRowLockSemaphore - Inserting new lock row for lock: 'TRIGGER_ACCESS' being obtained by thread: main

2021-07-29 06:59:53 | Time  1 ms | statement-1 | INSERT INTO qrtz_LOCKS(SCHED_NAME, LOCK_NAME) VALUES ('dufy_test', 'TRIGGER_ACCESS')

06:59:53.567 [main] DEBUG o.q.i.j.StdRowLockSemaphore - Lock 'TRIGGER_ACCESS' given to: main

 

分析

 

需要 STATE_ACCESS 锁

06:58:18.802 [main] DEBUG o.q.i.j.StdRowLockSemaphore - Lock 'STATE_ACCESS' is desired by: main

 

获取成功 STATE_ACCESS 锁

 

06:58:18.887 [main] DEBUG o.q.i.j.StdRowLockSemaphore - Lock 'STATE_ACCESS' is being obtained: main

 

执行Select sql ， 真正去 获取 STATE_ACCESS 锁

2021-07-29 06:58:18 | Time 26 ms | statement-1 | SELECT * FROM qrtz_LOCKS WHERE SCHED_NAME = 'dufy_test' AND LOCK_NAME = 'STATE_ACCESS' FOR UPDATE

 

真正获取成功 STATE_ACCESS 锁 ！！

06:58:18.942 [main] DEBUG o.q.i.j.StdRowLockSemaphore - Inserting new lock row for lock: 'STATE_ACCESS' being obtained by thread: main

 

执行 insert sql ，

2021-07-29 06:58:18 | Time 2 ms | statement-1 | INSERT INTO qrtz_LOCKS(SCHED_NAME, LOCK_NAME) VALUES ('dufy_test', 'STATE_ACCESS')

 

真正的 分配 锁

06:58:18.956 [main] DEBUG o.q.i.j.StdRowLockSemaphore - Lock 'STATE_ACCESS' given to: main

 

06:59:36.830 [main] DEBUG o.q.impl.jdbcjobstore.JobStoreTX - Adding TriggerPersistenceDelegate of type: org.quartz.impl.jdbcjobstore.SimpleTriggerPersistenceDelegate

06:59:36.838 [main] DEBUG o.q.impl.jdbcjobstore.JobStoreTX - Adding TriggerPersistenceDelegate of type: org.quartz.impl.jdbcjobstore.CronTriggerPersistenceDelegate

06:59:36.849 [main] DEBUG o.q.impl.jdbcjobstore.JobStoreTX - Adding TriggerPersistenceDelegate of type: org.quartz.impl.jdbcjobstore.CalendarIntervalTriggerPersistenceDelegate

06:59:36.856 [main] DEBUG o.q.impl.jdbcjobstore.JobStoreTX - Adding TriggerPersistenceDelegate of type:

 

查询qrtz_SCHEDULER_STATE

org.quartz.impl.jdbcjobstore.DailyTimeIntervalTriggerPersistenceDelegate

2021-07-29 06:59:36 | Time 1 ms | statement-1 | SELECT * FROM qrtz_SCHEDULER_STATE WHERE SCHED_NAME = 'dufy_test'

 

2021-07-29 06:59:36 | Time 1 ms | statement-1 | SELECT DISTINCT INSTANCE_NAME FROM qrtz_FIRED_TRIGGERS WHERE SCHED_NAME = 'dufy_test'

 

发现已经存在 相应记录，修改 qrtz_SCHEDULER_STATE 的LAST_CHECKIN_TIME

2021-07-29 06:59:36 | Time 2 ms | statement-1 | UPDATE qrtz_SCHEDULER_STATE SET LAST_CHECKIN_TIME = 1627513176882 WHERE SCHED_NAME = 'dufy_test' AND INSTANCE_NAME = 'DESKTOP-MBMDPHH1627513038976'

 

再新增qrtz_SCHEDULER_STATE

2021-07-29 06:59:36 | Time 2 ms | statement-1 | INSERT INTO qrtz_SCHEDULER_STATE (SCHED_NAME, INSTANCE_NAME, LAST_CHECKIN_TIME, CHECKIN_INTERVAL) VALUES('dufy_test', 'DESKTOP-MBMDPHH1627513038976', 1627513176882, 7500)

 

同STATE_ACCESS 的过程， 需要 TRIGGER_ACCESS锁

06:59:53.547 [main] DEBUG o.q.i.j.StdRowLockSemaphore - Lock 'TRIGGER_ACCESS' is desired by: main

06:59:53.549 [main] DEBUG o.q.i.j.StdRowLockSemaphore - Lock 'TRIGGER_ACCESS' is being obtained: main

 

2021-07-29 06:59:53 | Time 1 ms | statement-1 | SELECT * FROM qrtz_LOCKS WHERE SCHED_NAME = 'dufy_test' AND LOCK_NAME = 'TRIGGER_ACCESS' FOR UPDATE

 

 

06:59:53.558 [main] DEBUG o.q.i.j.StdRowLockSemaphore - Inserting new lock row for lock: 'TRIGGER_ACCESS' being obtained by thread: main

 

新增

2021-07-29 06:59:53 | Time 1 ms | statement-1 | INSERT INTO qrtz_LOCKS(SCHED_NAME, LOCK_NAME) VALUES ('dufy_test', 'TRIGGER_ACCESS')

 

分配

06:59:53.567 [main] DEBUG o.q.i.j.StdRowLockSemaphore - Lock 'TRIGGER_ACCESS' given to: main

 

这里应该是 发现 restarted 的instance

06:59:56.409 [main] INFO o.q.impl.jdbcjobstore.JobStoreTX - ClusterManager: detected 1 failed or restarted instances.

 

扫描其failed in-progress jobs

06:59:56.410 [main] INFO o.q.impl.jdbcjobstore.JobStoreTX - ClusterManager: Scanning for instance "DESKTOP-MBMDPHH1627512767937"'s failed in-progress jobs.

2021-07-29 06:59:56 | Time 2 ms | statement-1 | SELECT * FROM qrtz_FIRED_TRIGGERS WHERE SCHED_NAME = 'dufy_test' AND INSTANCE_NAME = 'DESKTOP-MBMDPHH1627512767937'

 

把 qrtz_TRIGGERS 的所有行，从WAITING 更新为BLOCKED

2021-07-29 06:59:56 | Time 3 ms | statement-1 | UPDATE qrtz_TRIGGERS SET TRIGGER_STATE = 'WAITING' WHERE SCHED_NAME = 'dufy_test' AND JOB_NAME = 'job1_3' AND JOB_GROUP = 'jGroup1' AND TRIGGER_STATE = 'BLOCKED'

 

 

从PAUSED_BLOCKED 更新为 PAUSED

2021-07-29 06:59:56 | Time 2 ms | statement-1 | UPDATE qrtz_TRIGGERS SET TRIGGER_STATE = 'PAUSED' WHERE SCHED_NAME = 'dufy_test' AND JOB_NAME = 'job1_3' AND JOB_GROUP = 'jGroup1' AND TRIGGER_STATE = 'PAUSED_BLOCKED'

 

删除

2021-07-29 06:59:56 | Time 2 ms | statement-1 | DELETE FROM qrtz_FIRED_TRIGGERS WHERE SCHED_NAME = 'dufy_test' AND INSTANCE_NAME = 'DESKTOP-MBMDPHH1627512767937'

 

 

2021-07-29 06:59:56 | Time 1 ms | statement-1 | SELECT TRIGGER_STATE FROM qrtz_TRIGGERS WHERE SCHED_NAME = 'dufy_test' AND TRIGGER_NAME = 'triggerser1_3' AND TRIGGER_GROUP = 'tGroudsgfsp1'

06:59:56.487 [main] DEBUG o.q.impl.jdbcjobstore.JobStoreTX - ClusterManager: ......Freed 0 acquired trigger(s).

06:59:56.488 [main] DEBUG o.q.impl.jdbcjobstore.JobStoreTX - ClusterManager: ......Deleted 0 complete triggers(s).

06:59:56.488 [main] DEBUG o.q.impl.jdbcjobstore.JobStoreTX - ClusterManager: ......Scheduled 0 recoverable job(s) for recovery.

06:59:56.489 [main] INFO o.q.impl.jdbcjobstore.JobStoreTX - ClusterManager: ......Cleaned-up 1 other failed job(s).

2021-07-29 06:59:56 | Time 2 ms | statement-1 | DELETE FROM qrtz_SCHEDULER_STATE WHERE SCHED_NAME = 'dufy_test' AND INSTANCE_NAME = 'DESKTOP-MBMDPHH1627512767937'

2021-07-29 07:00:07 | Time 8 ms | commit-1 |

07:00:17.194 [main] DEBUG o.q.i.j.StdRowLockSemaphore - Lock 'TRIGGER_ACCESS' returned by: main

07:00:22.225 [main] DEBUG o.q.i.j.StdRowLockSemaphore - Lock 'STATE_ACCESS' returned by: main

07:01:03.665 [main] DEBUG o.q.impl.jdbcjobstore.JobStoreTX - ClusterManager: Check-in complete.

07:01:03.666 [main] DEBUG o.q.impl.jdbcjobstore.JobStoreTX - JobStore background threads started (as scheduler was started).

07:01:03.666 [main] INFO org.quartz.core.QuartzScheduler - Scheduler dufy_test_$_DESKTOP-MBMDPHH1627513038976 started.

07:01:03.667 [QuartzScheduler_dufy_test-DESKTOP-MBMDPHH1627513038976_MisfireHandler] DEBUG o.q.impl.jdbcjobstore.JobStoreTX - MisfireHandler: scanning for misfires...

2021-07-29 07:01:08 | Time 1 ms | statement-1 | SELECT COUNT(TRIGGER_NAME) FROM qrtz_TRIGGERS WHERE SCHED_NAME = 'dufy_test' AND NOT (MISFIRE_INSTR = -1) AND NEXT_FIRE_TIME < 1627513203672 AND TRIGGER_STATE = 'WAITING'

2021-07-29 07:01:08 | 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 <= 1627513293667 AND (MISFIRE_INSTR = -1 OR (MISFIRE_INSTR != -1 AND NEXT_FIRE_TIME >= 1627513203671)) ORDER BY NEXT_FIRE_TIME ASC, PRIORITY DESC

07:01:08.333 [QuartzScheduler_dufy_test-DESKTOP-MBMDPHH1627513038976_MisfireHandler] DEBUG o.q.i.j.StdRowLockSemaphore - Lock 'TRIGGER_ACCESS' is desired by: QuartzScheduler_dufy_test-DESKTOP-MBMDPHH1627513038976_MisfireHandler

07:01:08.334 [QuartzScheduler_dufy_test-DESKTOP-MBMDPHH1627513038976_MisfireHandler] DEBUG o.q.i.j.StdRowLockSemaphore - Lock 'TRIGGER_ACCESS' is being obtained: QuartzScheduler_dufy_test-DESKTOP-MBMDPHH1627513038976_MisfireHandler

2021-07-29 07:01:08 | Time 0 ms | commit-0 |

2021-07-29 07:01:08 | Time 0 ms | statement-1 | SELECT * FROM qrtz_LOCKS WHERE SCHED_NAME = 'dufy_test' AND LOCK_NAME = 'TRIGGER_ACCESS' FOR UPDATE

07:01:08.336 [dufy_test_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread - batch acquisition of 0 triggers

07:01:08.336 [QuartzScheduler_dufy_test-DESKTOP-MBMDPHH1627513038976_MisfireHandler] DEBUG o.q.i.j.StdRowLockSemaphore - Lock 'TRIGGER_ACCESS' given to: QuartzScheduler_dufy_test-DESKTOP-MBMDPHH1627513038976_MisfireHandler

2021-07-29 07:01:21 | Time 2 ms | statement-2 | SELECT * FROM qrtz_SCHEDULER_STATE WHERE SCHED_NAME = 'dufy_test'

2021-07-29 07:01:22 | Time 12763 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 < 1627513208337 AND TRIGGER_STATE = 'WAITING' ORDER BY NEXT_FIRE_TIME ASC, PRIORITY DESC

07:01:22.982 [main] DEBUG o.q.i.j.StdRowLockSemaphore - Lock 'TRIGGER_ACCESS' is desired by: main

07:01:22.983 [QuartzScheduler_dufy_test-DESKTOP-MBMDPHH1627513038976_MisfireHandler] INFO o.q.impl.jdbcjobstore.JobStoreTX - Handling 3 trigger(s) that missed their scheduled fire-time.

07:01:30.624 [main] DEBUG o.q.i.j.StdRowLockSemaphore - Lock 'TRIGGER_ACCESS' is being obtained: main

2021-07-29 07:01:30 | Time 1 ms | statement-2 | UPDATE qrtz_SCHEDULER_STATE SET LAST_CHECKIN_TIME = 1627513282982 WHERE SCHED_NAME = 'dufy_test' AND INSTANCE_NAME = 'DESKTOP-MBMDPHH1627513038976'

2021-07-29 07:01:30 | Time 4 ms | statement-1 | SELECT * FROM qrtz_TRIGGERS WHERE SCHED_NAME = 'dufy_test' AND TRIGGER_NAME = 'triggerser1_1' AND TRIGGER_GROUP = 'tGroudsgfsp1'

2021-07-29 07:01:30 | Time 8 ms | commit-2 |

2021-07-29 07:01:30 | Time 0 ms | statement-1 | SELECT * FROM qrtz_CRON_TRIGGERS WHERE SCHED_NAME = 'dufy_test' AND TRIGGER_NAME = 'triggerser1_1' AND TRIGGER_GROUP = 'tGroudsgfsp1'

2021-07-29 07:01:30 | Time 1 ms | commit-2 |

 

=============================================

启动的时候，

SELECT * FROM qrtz_LOCKS WHERE SCHED_NAME = 'dufy_test' AND LOCK_NAME = 'STATE_ACCESS' FOR UPDATE

 

 

执行trigger的时候：

SELECT * FROM qrtz_LOCKS WHERE SCHED_NAME = 'dufy_test' AND LOCK_NAME = 'TRIGGER_ACCESS' FOR UPDATE

 

qrtz_SCHEDULER_STATE 会不断的被更新， 在启动的时候 插入一次，

 

也会删除

2021-07-29 07:17:18 | Time 1 ms | statement-1 | DELETE FROM qrtz_SCHEDULER_STATE WHERE SCHED_NAME = 'dufy_test' AND INSTANCE_NAME = 'DESKTOP-MBMDPHH1627513038976'

 

 

如果多个实例， 就会在 qrtz_SCHEDULER_STATE 存在多行；；

 

 

数据库表的变化

第一个节点会在 qrtz_lock 表 新增两行：

 

 

每次有集群的节点启动的时候， 会在表QRTZ_SCHEDULER_STATE 加入一行。 退出的时候， 删除一行。

但是最后一个节点退出不会删除， 因为 它 可能来不及 自己删除。