全部日志

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 加入一行。 退出的时候， 删除一行。

 

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