Repository navigation
Expand file tree
/
Copy pathscheduler_job_runner.py
More file actions
2625 lines (2299 loc) · 117 KB
/
Copy pathscheduler_job_runner.py
File metadata and controls
2625 lines (2299 loc) · 117 KB
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
351
352
353
354
355
356
357
358
359
360
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
377
378
379
380
381
382
383
384
385
386
387
388
389
390
391
392
393
394
395
396
397
398
399
400
401
402
403
404
405
406
407
408
409
410
411
412
413
414
415
416
417
418
419
420
421
422
423
424
425
426
427
428
429
430
431
432
433
434
435
436
437
438
439
440
441
442
443
444
445
446
447
448
449
450
451
452
453
454
455
456
457
458
459
460
461
462
463
464
465
466
467
468
469
470
471
472
473
474
475
476
477
478
479
480
481
482
483
484
485
486
487
488
489
490
491
492
493
494
495
496
497
498
499
500
501
502
503
504
505
506
507
508
509
510
511
512
513
514
515
516
517
518
519
520
521
522
523
524
525
526
527
528
529
530
531
532
533
534
535
536
537
538
539
540
541
542
543
544
545
546
547
548
549
550
551
552
553
554
555
556
557
558
559
560
561
562
563
564
565
566
567
568
569
570
571
572
573
574
575
576
577
578
579
580
581
582
583
584
585
586
587
588
589
590
591
592
593
594
595
596
597
598
599
600
601
602
603
604
605
606
607
608
609
610
611
612
613
614
615
616
617
618
619
620
621
622
623
624
625
626
627
628
629
630
631
632
633
634
635
636
637
638
639
640
641
642
643
644
645
646
647
648
649
650
651
652
653
654
655
656
657
658
659
660
661
662
663
664
665
666
667
668
669
670
671
672
673
674
675
676
677
678
679
680
681
682
683
684
685
686
687
688
689
690
691
692
693
694
695
696
697
698
699
700
701
702
703
704
705
706
707
708
709
710
711
712
713
714
715
716
717
718
719
720
721
722
723
724
725
726
727
728
729
730
731
732
733
734
735
736
737
738
739
740
741
742
743
744
745
746
747
748
749
750
751
752
753
754
755
756
757
758
759
760
761
762
763
764
765
766
767
768
769
770
771
772
773
774
775
776
777
778
779
780
781
782
783
784
785
786
787
788
789
790
791
792
793
794
795
796
797
798
799
800
801
802
803
804
805
806
807
808
809
810
811
812
813
814
815
816
817
818
819
820
821
822
823
824
825
826
827
828
829
830
831
832
833
834
835
836
837
838
839
840
841
842
843
844
845
846
847
848
849
850
851
852
853
854
855
856
857
858
859
860
861
862
863
864
865
866
867
868
869
870
871
872
873
874
875
876
877
878
879
880
881
882
883
884
885
886
887
888
889
890
891
892
893
894
895
896
897
898
899
900
901
902
903
904
905
906
907
908
909
910
911
912
913
914
915
916
917
918
919
920
921
922
923
924
925
926
927
928
929
930
931
932
933
934
935
936
937
938
939
940
941
942
943
944
945
946
947
948
949
950
951
952
953
954
955
956
957
958
959
960
961
962
963
964
965
966
967
968
969
970
971
972
973
974
975
976
977
978
979
980
981
982
983
984
985
986
987
988
989
990
991
992
993
994
995
996
997
998
999
1000
#
# Licensed to the Apache Software Foundation (ASF) under one
# or more contributor license agreements. See the NOTICE file
# distributed with this work for additional information
# regarding copyright ownership. The ASF licenses this file
# to you under the Apache License, Version 2.0 (the
# "License"); you may not use this file except in compliance
# with the License. You may obtain a copy of the License at
#
# http://www.apache.org/licenses/LICENSE-2.0
#
# Unless required by applicable law or agreed to in writing,
# software distributed under the License is distributed on an
# "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
# KIND, either express or implied. See the License for the
# specific language governing permissions and limitations
# under the License.
from __future__ import annotations
import itertools
import multiprocessing
import operator
import os
import signal
import sys
import time
from collections import Counter, defaultdict, deque
from collections.abc import Callable, Collection, Iterable, Iterator
from contextlib import ExitStack
from datetime import date, datetime, timedelta
from functools import lru_cache, partial
from itertools import groupby
from typing import TYPE_CHECKING, Any, cast
from sqlalchemy import and_, delete, desc, exists, func, inspect, or_, select, text, tuple_, update
from sqlalchemy.exc import OperationalError
from sqlalchemy.orm import joinedload, lazyload, load_only, make_transient, selectinload
from sqlalchemy.sql import expression
from airflow import settings
from airflow._shared.timezones import timezone
from airflow.api_fastapi.execution_api.datamodels.taskinstance import DagRun as DRDataModel, TIRunContext
from airflow.callbacks.callback_requests import (
DagCallbackRequest,
DagRunContext,
EmailNotificationRequest,
TaskCallbackRequest,
)
from airflow.configuration import conf
from airflow.dag_processing.bundles.base import BundleUsageTrackingManager
from airflow.executors import workloads
from airflow.jobs.base_job_runner import BaseJobRunner
from airflow.jobs.job import Job, JobState, perform_heartbeat
from airflow.models import Deadline, Log
from airflow.models.asset import (
AssetActive,
AssetAliasModel,
AssetDagRunQueue,
AssetEvent,
AssetModel,
DagScheduleAssetAliasReference,
DagScheduleAssetReference,
TaskOutletAssetReference,
asset_trigger_association_table,
)
from airflow.models.backfill import Backfill
from airflow.models.dag import DagModel, get_next_data_interval, get_run_data_interval
from airflow.models.dag_version import DagVersion
from airflow.models.dagbag import DBDagBag
from airflow.models.dagrun import DagRun
from airflow.models.dagwarning import DagWarning, DagWarningType
from airflow.models.serialized_dag import SerializedDagModel
from airflow.models.taskinstance import TaskInstance
from airflow.models.trigger import TRIGGER_FAIL_REPR, Trigger, TriggerFailureReason
from airflow.stats import Stats
from airflow.ti_deps.dependencies_states import EXECUTION_STATES
from airflow.timetables.simple import AssetTriggeredTimetable
from airflow.traces import utils as trace_utils
from airflow.traces.tracer import DebugTrace, Trace, add_debug_span
from airflow.utils.dates import datetime_to_nano
from airflow.utils.event_scheduler import EventScheduler
from airflow.utils.log.logging_mixin import LoggingMixin
from airflow.utils.retries import MAX_DB_RETRIES, retry_db_transaction, run_with_db_retries
from airflow.utils.session import NEW_SESSION, create_session, provide_session
from airflow.utils.span_status import SpanStatus
from airflow.utils.sqlalchemy import is_lock_not_available_error, prohibit_commit, with_row_locks
from airflow.utils.state import DagRunState, State, TaskInstanceState
from airflow.utils.thread_safe_dict import ThreadSafeDict
from airflow.utils.types import DagRunTriggeredByType, DagRunType
if TYPE_CHECKING:
from types import FrameType
from pendulum.datetime import DateTime
from sqlalchemy.orm import Query, Session
from airflow._shared.logging.types import Logger
from airflow.executors.base_executor import BaseExecutor
from airflow.executors.executor_utils import ExecutorName
from airflow.models.mappedoperator import MappedOperator
from airflow.models.taskinstance import TaskInstanceKey
from airflow.serialization.serialized_objects import SerializedBaseOperator, SerializedDAG
from airflow.utils.sqlalchemy import CommitProhibitorGuard
TI = TaskInstance
DR = DagRun
DM = DagModel
TASK_STUCK_IN_QUEUED_RESCHEDULE_EVENT = "stuck in queued reschedule"
""":meta private:"""
def _get_current_dag(dag_id: str, session: Session) -> SerializedDAG | None:
serdag = SerializedDagModel.get(dag_id=dag_id, session=session) # grabs the latest version
if not serdag:
return None
serdag.load_op_links = False
return serdag.dag
class ConcurrencyMap:
"""
Dataclass to represent concurrency maps.
It contains a map from (dag_id, task_id) to # of task instances, a map from (dag_id, task_id)
to # of task instances in the given state list and a map from (dag_id, run_id, task_id)
to # of task instances in the given state list in each DAG run.
"""
def __init__(self):
self.dag_run_active_tasks_map: Counter[tuple[str, str]] = Counter()
self.task_concurrency_map: Counter[tuple[str, str]] = Counter()
self.task_dagrun_concurrency_map: Counter[tuple[str, str, str]] = Counter()
def load(self, session: Session) -> None:
self.dag_run_active_tasks_map.clear()
self.task_concurrency_map.clear()
self.task_dagrun_concurrency_map.clear()
query = session.execute(
select(TI.dag_id, TI.task_id, TI.run_id, func.count("*"))
.where(TI.state.in_(EXECUTION_STATES))
.group_by(TI.task_id, TI.run_id, TI.dag_id)
)
for dag_id, task_id, run_id, c in query:
self.dag_run_active_tasks_map[dag_id, run_id] += c
self.task_concurrency_map[(dag_id, task_id)] += c
self.task_dagrun_concurrency_map[(dag_id, run_id, task_id)] += c
def _is_parent_process() -> bool:
"""
Whether this is a parent process.
Return True if the current process is the parent process.
False if the current process is a child process started by multiprocessing.
"""
return multiprocessing.current_process().name == "MainProcess"
class SchedulerJobRunner(BaseJobRunner, LoggingMixin):
"""
SchedulerJobRunner runs for a specific time interval and schedules jobs that are ready to run.
It figures out the latest runs for each task and sees if the dependencies
for the next schedules are met.
If so, it creates appropriate TaskInstances and sends run commands to the
executor. It does this for each task in each DAG and repeats.
:param num_runs: The number of times to run the scheduling loop. If you
have a large number of DAG files this could complete before each file
has been parsed. -1 for unlimited times.
:param scheduler_idle_sleep_time: The number of seconds to wait between
polls of running processors
:param log: override the default Logger
"""
job_type = "SchedulerJob"
# For a dagrun span
# - key: dag_run.run_id | value: span
# - dagrun keys will be prefixed with 'dr:'.
# For a ti span
# - key: ti.id | value: span
# - taskinstance keys will be prefixed with 'ti:'.
active_spans = ThreadSafeDict()
def __init__(
self,
job: Job,
num_runs: int = conf.getint("scheduler", "num_runs"),
scheduler_idle_sleep_time: float = conf.getfloat("scheduler", "scheduler_idle_sleep_time"),
log: Logger | None = None,
):
super().__init__(job)
self.num_runs = num_runs
self._scheduler_idle_sleep_time = scheduler_idle_sleep_time
# How many seconds do we wait for tasks to heartbeat before timeout.
self._task_instance_heartbeat_timeout_secs = conf.getint(
"scheduler", "task_instance_heartbeat_timeout"
)
self._dag_stale_not_seen_duration = conf.getint("scheduler", "dag_stale_not_seen_duration")
self._task_queued_timeout = conf.getfloat("scheduler", "task_queued_timeout")
self._enable_tracemalloc = conf.getboolean("scheduler", "enable_tracemalloc")
# this param is intentionally undocumented
self._num_stuck_queued_retries = conf.getint(
section="scheduler",
key="num_stuck_in_queued_retries",
fallback=2,
)
if self._enable_tracemalloc:
import tracemalloc
tracemalloc.start()
if log:
self._log = log
self.scheduler_dag_bag = DBDagBag(load_op_links=False)
@provide_session
def heartbeat_callback(self, session: Session = NEW_SESSION) -> None:
Stats.incr("scheduler_heartbeat", 1, 1)
def register_signals(self) -> ExitStack:
"""Register signals that stop child processes."""
resetter = ExitStack()
prev_int = signal.signal(signal.SIGINT, self._exit_gracefully)
prev_term = signal.signal(signal.SIGTERM, self._exit_gracefully)
prev_usr2 = signal.signal(signal.SIGUSR2, self._debug_dump)
resetter.callback(signal.signal, signal.SIGINT, prev_int)
resetter.callback(signal.signal, signal.SIGTERM, prev_term)
resetter.callback(signal.signal, signal.SIGUSR2, prev_usr2)
if self._enable_tracemalloc:
prev = signal.signal(signal.SIGUSR1, self._log_memory_usage)
resetter.callback(signal.signal, signal.SIGUSR1, prev)
return resetter
def _exit_gracefully(self, signum: int, frame: FrameType | None) -> None:
"""Clean up processor_agent to avoid leaving orphan processes."""
if self._is_tracing_enabled():
self._end_active_spans()
if not _is_parent_process():
# Only the parent process should perform the cleanup.
return
if self._enable_tracemalloc:
import tracemalloc
tracemalloc.stop()
self.log.info("Exiting gracefully upon receiving signal %s", signum)
sys.exit(os.EX_OK)
def _log_memory_usage(self, signum: int, frame: FrameType | None) -> None:
import tracemalloc
snapshot = tracemalloc.take_snapshot()
top_stats = snapshot.statistics("lineno")
n = 10
self.log.error(
"scheduler memory usage:\n Top %d\n %s",
n,
"\n\t".join(map(str, top_stats[:n])),
)
def _debug_dump(self, signum: int, frame: FrameType | None) -> None:
import threading
from traceback import extract_stack
if not _is_parent_process():
# Only the parent process should perform the debug dump.
return
try:
sig_name = signal.Signals(signum).name
except Exception:
sig_name = str(signum)
self.log.info("%s\n%s received, printing debug\n%s", "-" * 80, sig_name, "-" * 80)
for executor in self.job.executors:
self.log.info("Debug dump for the executor %s", executor)
executor.debug_dump()
self.log.info("-" * 80)
id2name = {th.ident: th.name for th in threading.enumerate()}
for threadId, stack in sys._current_frames().items():
self.log.info("Stack Trace for Scheduler Job Runner on thread: %s", id2name[threadId])
callstack = extract_stack(f=stack, limit=10)
self.log.info("\n\t".join(map(repr, callstack)))
self.log.info("-" * 80)
def _executable_task_instances_to_queued(self, max_tis: int, session: Session) -> list[TI]:
"""
Find TIs that are ready for execution based on conditions.
Conditions include:
- pool limits
- DAG max_active_tasks
- executor state
- priority
- max active tis per DAG
- max active tis per DAG run
:param max_tis: Maximum number of TIs to queue in this loop.
:return: list[airflow.models.TaskInstance]
"""
from airflow.models.pool import Pool
from airflow.utils.db import DBLocks
executable_tis: list[TI] = []
if session.get_bind().dialect.name == "postgresql":
# Optimization: to avoid littering the DB errors of "ERROR: canceling statement due to lock
# timeout", try to take out a transactional advisory lock (unlocks automatically on
# COMMIT/ROLLBACK)
lock_acquired = session.execute(
text("SELECT pg_try_advisory_xact_lock(:id)").bindparams(
id=DBLocks.SCHEDULER_CRITICAL_SECTION.value
)
).scalar()
if not lock_acquired:
# Throw an error like the one that would happen with NOWAIT
raise OperationalError(
"Failed to acquire advisory lock", params=None, orig=RuntimeError("55P03")
)
# Get the pool settings. We get a lock on the pool rows, treating this as a "critical section"
# Throws an exception if lock cannot be obtained, rather than blocking
pools = Pool.slots_stats(lock_rows=True, session=session)
# If the pools are full, there is no point doing anything!
# If _somehow_ the pool is overfull, don't let the limit go negative - it breaks SQL
pool_slots_free = sum(max(0, pool["open"]) for pool in pools.values())
if pool_slots_free == 0:
self.log.debug("All pools are full!")
return []
max_tis = min(max_tis, pool_slots_free)
starved_pools = {pool_name for pool_name, stats in pools.items() if stats["open"] <= 0}
# dag_id to # of running tasks and (dag_id, task_id) to # of running tasks.
concurrency_map = ConcurrencyMap()
concurrency_map.load(session=session)
# Number of tasks that cannot be scheduled because of no open slot in pool
num_starving_tasks_total = 0
# dag and task ids that can't be queued because of concurrency limits
starved_dags: set[str] = set()
starved_tasks: set[tuple[str, str]] = set()
starved_tasks_task_dagrun_concurrency: set[tuple[str, str, str]] = set()
pool_num_starving_tasks: dict[str, int] = Counter()
for loop_count in itertools.count(start=1):
num_starved_pools = len(starved_pools)
num_starved_dags = len(starved_dags)
num_starved_tasks = len(starved_tasks)
num_starved_tasks_task_dagrun_concurrency = len(starved_tasks_task_dagrun_concurrency)
query = (
select(TI)
.with_hint(TI, "USE INDEX (ti_state)", dialect_name="mysql")
.join(TI.dag_run)
.where(DR.state == DagRunState.RUNNING)
.join(TI.dag_model)
.where(~DM.is_paused)
.where(TI.state == TaskInstanceState.SCHEDULED)
.where(DM.bundle_name.is_not(None))
.options(selectinload(TI.dag_model))
.order_by(-TI.priority_weight, DR.logical_date, TI.map_index)
)
if starved_pools:
query = query.where(TI.pool.not_in(starved_pools))
if starved_dags:
query = query.where(TI.dag_id.not_in(starved_dags))
if starved_tasks:
query = query.where(tuple_(TI.dag_id, TI.task_id).not_in(starved_tasks))
if starved_tasks_task_dagrun_concurrency:
query = query.where(
tuple_(TI.dag_id, TI.run_id, TI.task_id).not_in(starved_tasks_task_dagrun_concurrency)
)
query = query.limit(max_tis)
timer = Stats.timer("scheduler.critical_section_query_duration")
timer.start()
try:
query = with_row_locks(query, of=TI, session=session, skip_locked=True)
task_instances_to_examine: list[TI] = session.scalars(query).all()
timer.stop(send=True)
except OperationalError as e:
timer.stop(send=False)
raise e
# TODO[HA]: This was wrong before anyway, as it only looked at a sub-set of dags, not everything.
# Stats.gauge('scheduler.tasks.pending', len(task_instances_to_examine))
if not task_instances_to_examine:
self.log.debug("No tasks to consider for execution.")
break
# Put one task instance on each line
task_instance_str = "\n".join(f"\t{x!r}" for x in task_instances_to_examine)
self.log.info("%s tasks up for execution:\n%s", len(task_instances_to_examine), task_instance_str)
executor_slots_available: dict[ExecutorName, int] = {}
# First get a mapping of executor names to slots they have available
for executor in self.job.executors:
if TYPE_CHECKING:
# All executors should have a name if they are initted from the executor_loader.
# But we need to check for None to make mypy happy.
assert executor.name
executor_slots_available[executor.name] = executor.slots_available
for task_instance in task_instances_to_examine:
pool_name = task_instance.pool
pool_stats = pools.get(pool_name)
if not pool_stats:
self.log.warning("Tasks using non-existent pool '%s' will not be scheduled", pool_name)
starved_pools.add(pool_name)
continue
# Make sure to emit metrics if pool has no starving tasks
pool_num_starving_tasks.setdefault(pool_name, 0)
pool_total = pool_stats["total"]
open_slots = pool_stats["open"]
if open_slots <= 0:
self.log.info(
"Not scheduling since there are %s open slots in pool %s", open_slots, pool_name
)
# Can't schedule any more since there are no more open slots.
pool_num_starving_tasks[pool_name] += 1
num_starving_tasks_total += 1
starved_pools.add(pool_name)
continue
if task_instance.pool_slots > pool_total:
self.log.warning(
"Not executing %s. Requested pool slots (%s) are greater than "
"total pool slots: '%s' for pool: %s.",
task_instance,
task_instance.pool_slots,
pool_total,
pool_name,
)
pool_num_starving_tasks[pool_name] += 1
num_starving_tasks_total += 1
starved_tasks.add((task_instance.dag_id, task_instance.task_id))
continue
if task_instance.pool_slots > open_slots:
self.log.info(
"Not executing %s since it requires %s slots "
"but there are %s open slots in the pool %s.",
task_instance,
task_instance.pool_slots,
open_slots,
pool_name,
)
pool_num_starving_tasks[pool_name] += 1
num_starving_tasks_total += 1
starved_tasks.add((task_instance.dag_id, task_instance.task_id))
# Though we can execute tasks with lower priority if there's enough room
continue
# Check to make sure that the task max_active_tasks of the DAG hasn't been
# reached.
dag_id = task_instance.dag_id
dag_run_key = (dag_id, task_instance.run_id)
current_active_tasks_per_dag_run = concurrency_map.dag_run_active_tasks_map[dag_run_key]
dag_max_active_tasks = task_instance.dag_model.max_active_tasks
self.log.info(
"DAG %s has %s/%s running and queued tasks",
dag_id,
current_active_tasks_per_dag_run,
dag_max_active_tasks,
)
if current_active_tasks_per_dag_run >= dag_max_active_tasks:
self.log.info(
"Not executing %s since the number of tasks running or queued "
"from DAG %s is >= to the DAG's max_active_tasks limit of %s",
task_instance,
dag_id,
dag_max_active_tasks,
)
starved_dags.add(dag_id)
continue
if task_instance.dag_model.has_task_concurrency_limits:
# Many dags don't have a task_concurrency, so where we can avoid loading the full
# serialized DAG the better.
serialized_dag = self.scheduler_dag_bag.get_dag_for_run(
dag_run=task_instance.dag_run, session=session
)
# If the dag is missing, fail the task and continue to the next task.
if not serialized_dag:
self.log.error(
"DAG '%s' for task instance %s not found in serialized_dag table",
dag_id,
task_instance,
)
session.execute(
update(TI)
.where(TI.dag_id == dag_id, TI.state == TaskInstanceState.SCHEDULED)
.values(state=TaskInstanceState.FAILED)
.execution_options(synchronize_session="fetch")
)
continue
task_concurrency_limit: int | None = None
if serialized_dag.has_task(task_instance.task_id):
task_concurrency_limit = serialized_dag.get_task(
task_instance.task_id
).max_active_tis_per_dag
if task_concurrency_limit is not None:
current_task_concurrency = concurrency_map.task_concurrency_map[
(task_instance.dag_id, task_instance.task_id)
]
if current_task_concurrency >= task_concurrency_limit:
self.log.info(
"Not executing %s since the task concurrency for this task has been reached.",
task_instance,
)
starved_tasks.add((task_instance.dag_id, task_instance.task_id))
continue
task_dagrun_concurrency_limit: int | None = None
if serialized_dag.has_task(task_instance.task_id):
task_dagrun_concurrency_limit = serialized_dag.get_task(
task_instance.task_id
).max_active_tis_per_dagrun
if task_dagrun_concurrency_limit is not None:
current_task_dagrun_concurrency = concurrency_map.task_dagrun_concurrency_map[
(task_instance.dag_id, task_instance.run_id, task_instance.task_id)
]
if current_task_dagrun_concurrency >= task_dagrun_concurrency_limit:
self.log.info(
"Not executing %s since the task concurrency per DAG run for"
" this task has been reached.",
task_instance,
)
starved_tasks_task_dagrun_concurrency.add(
(task_instance.dag_id, task_instance.run_id, task_instance.task_id)
)
continue
if executor_obj := self._try_to_load_executor(task_instance.executor):
if TYPE_CHECKING:
# All executors should have a name if they are initted from the executor_loader.
# But we need to check for None to make mypy happy.
assert executor_obj.name
if executor_slots_available[executor_obj.name] <= 0:
self.log.debug(
"Not scheduling %s since its executor %s does not currently have any more "
"available slots"
)
starved_tasks.add((task_instance.dag_id, task_instance.task_id))
continue
executor_slots_available[executor_obj.name] -= 1
else:
# This is a defensive guard for if we happen to have a task who's executor cannot be
# found. The check in the dag parser should make this not realistically possible but the
# loader can fail if some direct DB modification has happened or another as yet unknown
# edge case. _try_to_load_executor will log an error message explaining the executor
# cannot be found.
starved_tasks.add((task_instance.dag_id, task_instance.task_id))
continue
executable_tis.append(task_instance)
open_slots -= task_instance.pool_slots
concurrency_map.dag_run_active_tasks_map[dag_run_key] += 1
concurrency_map.task_concurrency_map[(task_instance.dag_id, task_instance.task_id)] += 1
concurrency_map.task_dagrun_concurrency_map[
(task_instance.dag_id, task_instance.run_id, task_instance.task_id)
] += 1
pool_stats["open"] = open_slots
is_done = executable_tis or len(task_instances_to_examine) < max_tis
# Check this to avoid accidental infinite loops
found_new_filters = (
len(starved_pools) > num_starved_pools
or len(starved_dags) > num_starved_dags
or len(starved_tasks) > num_starved_tasks
or len(starved_tasks_task_dagrun_concurrency) > num_starved_tasks_task_dagrun_concurrency
)
if is_done or not found_new_filters:
break
self.log.info(
"Found no task instances to queue on query iteration %s "
"but there could be more candidate task instances to check.",
loop_count,
)
for pool_name, num_starving_tasks in pool_num_starving_tasks.items():
Stats.gauge(f"pool.starving_tasks.{pool_name}", num_starving_tasks)
# Same metric with tagging
Stats.gauge("pool.starving_tasks", num_starving_tasks, tags={"pool_name": pool_name})
Stats.gauge("scheduler.tasks.starving", num_starving_tasks_total)
Stats.gauge("scheduler.tasks.executable", len(executable_tis))
if executable_tis:
task_instance_str = "\n".join(f"\t{x!r}" for x in executable_tis)
self.log.info("Setting the following tasks to queued state:\n%s", task_instance_str)
# set TIs to queued state
filter_for_tis = TI.filter_for_tis(executable_tis)
session.execute(
update(TI)
.where(filter_for_tis)
.values(
# TODO[ha]: should we use func.now()? How does that work with DB timezone
# on mysql when it's not UTC?
state=TaskInstanceState.QUEUED,
queued_dttm=timezone.utcnow(),
queued_by_job_id=self.job.id,
)
.execution_options(synchronize_session=False)
)
for ti in executable_tis:
ti.emit_state_change_metric(TaskInstanceState.QUEUED)
for ti in executable_tis:
make_transient(ti)
return executable_tis
def _enqueue_task_instances_with_queued_state(
self, task_instances: list[TI], executor: BaseExecutor, session: Session
) -> None:
"""
Enqueue task_instances which should have been set to queued with the executor.
:param task_instances: TaskInstances to enqueue
:param executor: The executor to enqueue tasks for
:param session: The session object
"""
# actually enqueue them
for ti in task_instances:
if ti.dag_run.state in State.finished_dr_states:
ti.set_state(None, session=session)
continue
workload = workloads.ExecuteTask.make(ti, generator=executor.jwt_generator)
executor.queue_workload(workload, session=session)
def _critical_section_enqueue_task_instances(self, session: Session) -> int:
"""
Enqueues TaskInstances for execution.
There are three steps:
1. Pick TIs by priority with the constraint that they are in the expected states
and that we do not exceed max_active_runs or pool limits.
2. Change the state for the TIs above atomically.
3. Enqueue the TIs in the executor.
HA note: This function is a "critical section" meaning that only a single scheduler process can
execute this function at the same time. This is achieved by doing
``SELECT ... from pool FOR UPDATE``. For DBs that support NOWAIT, a "blocked" scheduler will skip
this and continue on with other tasks (creating new DAG runs, progressing TIs from None to SCHEDULED
etc.); DBs that don't support this (such as MariaDB or MySQL 5.x) the other schedulers will wait for
the lock before continuing.
:param session:
:return: Number of task instance with state changed.
"""
# The user can either request a certain number of tis to schedule per main scheduler loop (default
# is non-zero). If that value has been set to zero, that means use the value of core.parallelism (or
# however many free slots are left). core.parallelism represents the max number of running TIs per
# scheduler. Historically this value was stored in the executor, who's job it was to control/enforce
# it. However, with multiple executors, any of which can run up to core.parallelism TIs individually,
# we need to make sure in the scheduler now that we don't schedule more than core.parallelism totally
# across all executors.
num_occupied_slots = sum([executor.slots_occupied for executor in self.job.executors])
parallelism = conf.getint("core", "parallelism")
if self.job.max_tis_per_query == 0:
max_tis = parallelism - num_occupied_slots
else:
max_tis = min(self.job.max_tis_per_query, parallelism - num_occupied_slots)
if max_tis <= 0:
self.log.debug("max_tis query size is less than or equal to zero. No query will be performed!")
return 0
queued_tis = self._executable_task_instances_to_queued(max_tis, session=session)
# Sort queued TIs to their respective executor
executor_to_queued_tis = self._executor_to_tis(queued_tis)
for executor, queued_tis_per_executor in executor_to_queued_tis.items():
self.log.info(
"Trying to enqueue tasks: %s for executor: %s",
queued_tis_per_executor,
executor,
)
self._enqueue_task_instances_with_queued_state(queued_tis_per_executor, executor, session=session)
return len(queued_tis)
@staticmethod
def _process_task_event_logs(log_records: deque[Log], session: Session):
objects = (log_records.popleft() for _ in range(len(log_records)))
session.bulk_save_objects(objects=objects, preserve_order=False)
@staticmethod
def _is_metrics_enabled():
return any(
[
conf.getboolean("metrics", "statsd_datadog_enabled", fallback=False),
conf.getboolean("metrics", "statsd_on", fallback=False),
conf.getboolean("metrics", "otel_on", fallback=False),
]
)
@staticmethod
def _is_tracing_enabled():
return conf.getboolean("traces", "otel_on")
def _process_executor_events(self, executor: BaseExecutor, session: Session) -> int:
return SchedulerJobRunner.process_executor_events(
executor=executor,
job_id=self.job.id,
scheduler_dag_bag=self.scheduler_dag_bag,
session=session,
)
@classmethod
def process_executor_events(
cls, executor: BaseExecutor, job_id: str | None, scheduler_dag_bag: DBDagBag, session: Session
) -> int:
"""
Process task completion events from the executor and update task instance states.
This method handles task state transitions reported by executors, ensuring proper
state management, callback execution, and notification processing. It maintains
scheduler architectural principles by delegating user code execution to appropriate
isolated processes.
The method handles several key scenarios:
1. **Normal task completion**: Updates task states for successful/failed tasks
2. **External termination**: Detects tasks killed outside Airflow and marks them as failed
3. **Task requeuing**: Handles tasks that were requeued by other schedulers or executors
4. **Callback processing**: Sends task callback requests to DAG Processor for execution
5. **Email notifications**: Sends email notification requests to DAG Processor
:param executor: The executor reporting task completion events
:param job_id: The scheduler job ID, used to detect task requeuing by other schedulers
:param scheduler_dag_bag: Serialized DAG bag for retrieving task definitions
:param session: Database session for task instance updates
:return: Number of events processed from the executor event buffer
:raises Exception: If DAG retrieval or task processing fails, logs error and continues
This is a classmethod because this is also used in `dag.test()`.
`dag.test` execute DAGs with no scheduler, therefore it needs to handle the events pushed by the
executors as well.
"""
ti_primary_key_to_try_number_map: dict[tuple[str, str, str, int], int] = {}
event_buffer = executor.get_event_buffer()
tis_with_right_state: list[TaskInstanceKey] = []
# Report execution
for ti_key, (state, _) in event_buffer.items():
# We create map (dag_id, task_id, logical_date) -> in-memory try_number
ti_primary_key_to_try_number_map[ti_key.primary] = ti_key.try_number
cls.logger().info("Received executor event with state %s for task instance %s", state, ti_key)
if state in (
TaskInstanceState.FAILED,
TaskInstanceState.SUCCESS,
TaskInstanceState.QUEUED,
TaskInstanceState.RUNNING,
TaskInstanceState.RESTARTING,
):
tis_with_right_state.append(ti_key)
# Return if no finished tasks
if not tis_with_right_state:
return len(event_buffer)
# Check state of finished tasks
filter_for_tis = TI.filter_for_tis(tis_with_right_state)
query = (
select(TI)
.where(filter_for_tis)
.options(selectinload(TI.dag_model))
.options(joinedload(TI.dag_run).selectinload(DagRun.consumed_asset_events))
.options(joinedload(TI.dag_run).selectinload(DagRun.created_dag_version))
.options(joinedload(TI.dag_version))
)
# row lock this entire set of taskinstances to make sure the scheduler doesn't fail when we have
# multi-schedulers
tis_query: Query = with_row_locks(query, of=TI, session=session, skip_locked=True)
tis: Iterator[TI] = session.scalars(tis_query)
for ti in tis:
try_number = ti_primary_key_to_try_number_map[ti.key.primary]
buffer_key = ti.key.with_try_number(try_number)
state, info = event_buffer.pop(buffer_key)
if state in (TaskInstanceState.QUEUED, TaskInstanceState.RUNNING):
ti.external_executor_id = info
cls.logger().info("Setting external_executor_id for %s to %s", ti, info)
continue
msg = (
"TaskInstance Finished: dag_id=%s, task_id=%s, run_id=%s, map_index=%s, "
"run_start_date=%s, run_end_date=%s, "
"run_duration=%s, state=%s, executor=%s, executor_state=%s, try_number=%s, max_tries=%s, "
"pool=%s, queue=%s, priority_weight=%d, operator=%s, queued_dttm=%s, scheduled_dttm=%s,"
"queued_by_job_id=%s, pid=%s"
)
cls.logger().info(
msg,
ti.dag_id,
ti.task_id,
ti.run_id,
ti.map_index,
ti.start_date,
ti.end_date,
ti.duration,
ti.state,
executor,
state,
try_number,
ti.max_tries,
ti.pool,
ti.queue,
ti.priority_weight,
ti.operator,
ti.queued_dttm,
ti.scheduled_dttm,
ti.queued_by_job_id,
ti.pid,
)
if (active_ti_span := cls.active_spans.get("ti:" + str(ti.id))) is not None:
cls.set_ti_span_attrs(span=active_ti_span, state=state, ti=ti)
# End the span and remove it from the active_spans dict.
active_ti_span.end(end_time=datetime_to_nano(ti.end_date))
cls.active_spans.delete("ti:" + str(ti.id))
ti.span_status = SpanStatus.ENDED
else:
if ti.span_status == SpanStatus.ACTIVE:
# Another scheduler has started the span.
# Update the SpanStatus to let the process know that it must end it.
ti.span_status = SpanStatus.SHOULD_END
# There are two scenarios why the same TI with the same try_number is queued
# after executor is finished with it:
# 1) the TI was killed externally and it had no time to mark itself failed
# - in this case we should mark it as failed here.
# 2) the TI has been requeued after getting deferred - in this case either our executor has it
# or the TI is queued by another job. Either ways we should not fail it.
# All of this could also happen if the state is "running",
# but that is handled by the scheduler detecting task instances without heartbeats.
ti_queued = ti.try_number == buffer_key.try_number and ti.state in (
TaskInstanceState.SCHEDULED,
TaskInstanceState.QUEUED,
TaskInstanceState.RUNNING,
TaskInstanceState.RESTARTING,
)
ti_requeued = (
ti.queued_by_job_id != job_id # Another scheduler has queued this task again
or executor.has_task(ti) # This scheduler has this task already
)
if ti_queued and not ti_requeued:
Stats.incr(
"scheduler.tasks.killed_externally",
tags={"dag_id": ti.dag_id, "task_id": ti.task_id},
)
msg = (
"Executor %s reported that the task instance %s finished with state %s, but the task instance's state attribute is %s. " # noqa: RUF100, UP031, flynt
"Learn more: https://airflow.apache.org/docs/apache-airflow/stable/troubleshooting.html#task-state-changed-externally"
% (executor, ti, state, ti.state)
)
if info is not None:
msg += " Extra info: %s" % info # noqa: RUF100, UP031, flynt
session.add(Log(event="state mismatch", extra=msg, task_instance=ti.key))
# Get task from the Serialized DAG
try:
dag = scheduler_dag_bag.get_dag_for_run(dag_run=ti.dag_run, session=session)
cls.logger().error(
"DAG '%s' for task instance %s not found in serialized_dag table",
ti.dag_id,
ti,
)
if TYPE_CHECKING:
assert dag
# TODO (GH-52141): get_task in scheduler needs to return scheduler types
# instead, but currently it inherits SDK's DAG.
task = cast("MappedOperator | SerializedBaseOperator", dag.get_task(ti.task_id))
except Exception:
cls.logger().exception("Marking task instance %s as %s", ti, state)
ti.set_state(state)
continue
ti.task = task
if task.has_on_retry_callback or task.has_on_failure_callback:
# Only log the error/extra info here, since the `ti.handle_failure()` path will log it
# too, which would lead to double logging
cls.logger().error(msg)
request = TaskCallbackRequest(
filepath=ti.dag_model.relative_fileloc,
bundle_name=ti.dag_version.bundle_name,
bundle_version=ti.dag_version.bundle_version,
ti=ti,
msg=msg,
context_from_server=TIRunContext(
dag_run=DRDataModel.model_validate(ti.dag_run, from_attributes=True),
max_tries=ti.max_tries,
variables=[],
connections=[],
xcom_keys_to_clear=[],
),
)
executor.send_callback(request)
# Handle cleared tasks that were successfully terminated by executor
if ti.state == TaskInstanceState.RESTARTING and state == TaskInstanceState.SUCCESS:
cls.logger().info(
"Task %s was cleared and successfully terminated. Setting to scheduled for retry.", ti
)
# Adjust max_tries to allow retry beyond normal limits (like clearing does)
ti.max_tries = ti.try_number + ti.task.retries
ti.set_state(None)
continue
# Send email notification request to DAG processor via DB
if task.email and (task.email_on_failure or task.email_on_retry):
cls.logger().info(
"Sending email request for task %s to DAG Processor",
ti,
)
email_request = EmailNotificationRequest(
filepath=ti.dag_model.relative_fileloc,
bundle_name=ti.dag_version.bundle_name,
bundle_version=ti.dag_version.bundle_version,
ti=ti,
msg=msg,
email_type="retry" if ti.is_eligible_to_retry() else "failure",
context_from_server=TIRunContext(
dag_run=DRDataModel.model_validate(ti.dag_run, from_attributes=True),
max_tries=ti.max_tries,
variables=[],
connections=[],
xcom_keys_to_clear=[],
),
)
executor.send_callback(email_request)
# Update task state - emails are handled by DAG processor now
ti.handle_failure(error=msg, session=session)
return len(event_buffer)
@classmethod
def set_ti_span_attrs(cls, span, state, ti):
span.set_attributes(
{
"airflow.category": "scheduler",
"airflow.task.id": ti.id,
"airflow.task.task_id": ti.task_id,
"airflow.task.dag_id": ti.dag_id,
"airflow.task.state": ti.state,
"airflow.task.error": state == TaskInstanceState.FAILED,
"airflow.task.start_date": str(ti.start_date),
"airflow.task.end_date": str(ti.end_date),
"airflow.task.duration": ti.duration,
"airflow.task.executor_config": str(ti.executor_config),
"airflow.task.logical_date": str(ti.logical_date),