Create metrics to track Scheduled->Queued->Running task state transition times #30612

vandonr-amz · 2023-04-12T22:31:43Z

The goal of this PR is to provide metrics that are more insightful than the often-misunderstood and very wide "task landing time"

I made a little graph to illustrate the different timings we currently have access to:

the landing time in purple is only available in the airflow UI. In black are the metrics currently being sent, and I'm proposing to add the orange one in this PR (actually it's not adoption time and it'll be 2 metrics but I don't want to re-do the graph).

airflow/models/taskinstance.py

ferruzzi · 2023-04-12T22:41:36Z

I want to suggest finding a home for that diagram in the docs, I really like that.

[EDIT] Just saw this brought up on the Slack server. +1

jedcunningham · 2023-04-12T23:19:05Z

I think adding this metric is a good idea. However, that's not "adoption" time. Adoption refers to tasks a scheduler adopts from a no-longer-running scheduler.

It also may make sense to be more granular here and tract scheduled -> queued and queued -> running separately.

potiuk · 2023-04-13T10:40:30Z

I want to suggest finding a home for that diagram in the docs, I really like that.

Big +1 (of course it should be "correct" version). As mentioned on slack I am advocating for more similar diagrams describing our code/architecture/decisions following the diagrams that can be generated automatically from sources with mermaid being at clear advantage as being supported by GitHub natively (See https://github.com/apache/airflow/blob/main/airflow/jobs/JOB_LIFECYCLE.md)

ferruzzi · 2023-04-13T16:46:45Z

However, that's not "adoption" time. Adoption refers to tasks a scheduler adopts from a no-longer-running scheduler.

Sometimes it feels like naming things is the hardest part of the job. Do you have any suggestions?

jedcunningham · 2023-04-13T16:57:20Z

Absolutely! I've been involved with discussions recently around caching and now naming. Makes me think of two things.

If we split them, maybe scheduled_duration and queued_duration?

potiuk · 2023-04-13T17:27:59Z

Absolutely! I've been involved with discussions recently around caching and now naming. Makes me think of two things.

I think @jedcunningham you meant THREE things (or was it off-by-one?)

vandonr-amz · 2023-04-13T17:44:26Z

I need to check, but I think splitting this into 2 metrics might make the job a tad harder...
I'm not really sure where the scheduled -> queued transition takes place, I need to insert some code there, and also "remember" when it happens and carry that date to where the "running" transition happen.
I was really happy to see that TaskInstance already saved the date where it was scheduled here 😬

shubham22 · 2023-04-14T00:30:16Z

I am personally inclined towards one metric. Users generally care about the lag between when there task was ready for execution and when the task actually started executing, not about time it took at each stage inside Airflow. We can have one metric task_execution_latency or task_start_delay that conveys the meaning without requiring knowledge about what is scheduled state and what is queued state. Not a strong opinion!

I know cost is not something that we like to talk about when deciding, but having 1 metric does reduce the cost incurred in half :)

potiuk · 2023-04-14T17:44:15Z

Yeah. I think scheduled -> queued and queued -> RUNNING would both be useful as @jedcunningham mentioned. They indicate two different transitions and they might indicate different kind of problems.

BTW. One more thing that we should have is a nice description of "What might be the likely reason when you see this and that metrics high". It would be really great (of coure not now) to see not only production of the metrics and their description but also educated guess on what could be likely causes and where to look, even if we cannot have a good and perfect answer but some kind of "usually when this metrics is high it means that there are not enough workers etc. etc." . I think that would help not only the users, but also us - maintainers to be able to reason better on what's going on when we got queries from users.

vandonr-amz · 2023-04-21T23:29:08Z

I'm working on splitting this in 2, and I have a question:
in case a state is skipped, for instance here:

airflow/airflow/jobs/backfill_job_runner.py

Lines 530 to 534 in 4403419

    
           self.log.debug("Sending %s to executor", ti) 
        
           # Skip scheduled state, we are executing immediately 
        
           ti.state = TaskInstanceState.QUEUED 
        
           ti.queued_by_job_id = self.job.id 
        
           ti.queued_dttm = timezone.utcnow()

should we emit a metric that the task spent 0s in scheduled state ? Or should we not emit at all ?
I'm taking the "no metric" approach for now, but I'm not convinced it's the best.

potiuk · 2023-04-22T21:11:06Z

No metrics would be my choice too.

o-nikolas

Looks good, left a few nits 👍

airflow/models/taskinstance.py

o-nikolas · 2023-04-26T23:37:30Z

airflow/models/taskinstance.py

+                return
+            timing = (timezone.utcnow() - self.start_date).total_seconds()
+        else:
+            raise NotImplementedError


Maybe add a string to the error that provides a bit more context and info. you can add which state was provided and which states are supported.

I'll add a bit more context, but it's an error for developers, not for customers, so I don't think too much info is needed.

As a developer I appreciate helpful tracebacks 🙂

o-nikolas · 2023-04-26T23:38:47Z

airflow/models/taskinstance.py

+        Stats.timing(f"dag.{self.dag_id}.{self.task_id}.{metric_name}", timing)
+        Stats.timing(f"task.{metric_name}", timing, tags={"task_id": self.task_id, "dag_id": self.dag_id})


ferruzzi

Left a question out of curiosity, but no blocking requests.

ferruzzi · 2023-04-27T03:04:49Z

docs/apache-airflow/administration-and-deployment/logging-monitoring/metrics.rst

+``dag.<dag_id>.<task_id>.duration``                 Seconds taken to run a task
+``dag.<dag_id>.<task_id>.scheduled_duration``       Seconds a task spends in the Scheduled state, before being Queued
+``dag.<dag_id>.<task_id>.queued_duration``          Seconds a task spends in the Queued state, before being Running


(Non-blocking) Just curious, are these lines manual changes or from some automated change?

I added them manually, there is nothing enforcing sync between this doc and the code.

Alright, that was what I thought. I went looking for something like this when I started on the OTel work and didn't find it. That's buried pretty deep. 👍

Co-authored-by: Niko Oliveira <[email protected]>

htpawel · 2024-03-06T14:23:56Z

@vandonr-amz @potiuk Hi,
Above change has two bugs. One is that Stats.timing expects milliseconds instead of seconds (PR with fix: 37936) and second one is that scheduled_duration metric does not work as self.start_date is always None at time of execution of this. It is because self.start_date is not corresponding to time of schedule (real start) but to actual running start (after scheduled and queued states), see comment here: 34771#discussion_r1432601056. I think something with naming convention should be done as it can be very misleading, and also we need some scheduled_dttm variable like stated in the comment.

ferruzzi · 2024-03-06T22:19:16Z

@htpawel This is quite old, would you please open a new Issue with your bug report?

@ohaibbq

…iviz/recidiviz-data#29712) ## Description of the change Recidiviz/recidiviz-data#27852 upgraded to `composer-2.6.2-airflow-2.6.3` which failed during the tf step and was reverted in Recidiviz/recidiviz-data#29696 The commits in this PR are as follows -- 1. un-reverts Recidiviz/recidiviz-data#27852 2. upgrades to `composer-2.7.1-airflow-2.7.3`, copying requirements over from [version page](https://cloud.google.com/composer/docs/concepts/versioning/composer-versions#images) 3. airflow pipenv lock workflow 4. removes a few imports and checks since [Recidiviz/recidiviz-data#32731](apache/airflow#32731) opened by our very own @ohaibbq is included in 2.7.1 read through the [release notes](https://airflow.apache.org/docs/apache-airflow/stable/release_notes.html#airflow-2-7-0-2023-08-18), nothing in our usage seems to be deprecated; there are a few things that might be of interest to folks: - _Create metrics to track Scheduled->Queued->Running task state transition times ([Recidiviz/recidiviz-data#30612](apache/airflow#30612 will be nice for us to be able to see this re: k8s spin up time - _Add OpenTelemetry to Airflow ([AIP-49](https://github.com/apache/airflow/pulls?q=is%3Apr+is%3Amerged+label%3AAIP-49+milestone%3A%22Airflow+2.7.0%22))_ - _The trigger UI form is skipped in web UI if no parameters are defined in a DAG ([Recidiviz/recidiviz-data#33351](apache/airflow#33351: not sure if folks run ad-hoc dags using the UI instead of `trigger_state_specific_calculation/ingest_dag` but we need to add `show_trigger_form_if_no_params` if we want to still be able to trigger via the UI would love a second set of eyes around these warning logs that occur after tests run, see [here](https://github.com/Recidiviz/recidiviz-data/actions/runs/9071731702/job/24926024866?pr=29712#step:6:53). also occurred locally but i couldn't isolate the cause of the issue ``` Traceback (most recent call last): File "/opt/hostedtoolcache/Python/3.11.8/x64/lib/python3.11/logging/__init__.py", line 1113, in emit stream.write(msg + self.terminator) ValueError: I/O operation on closed file. Call stack: File "/home/runner/.local/share/virtualenvs/airflow-jCIRjM3K/lib/python3.11/site-packages/sqlalchemy/pool/base.py", line 509, in <lambda> and _finalize_fairy( File "/home/runner/.local/share/virtualenvs/airflow-jCIRjM3K/lib/python3.11/site-packages/sqlalchemy/pool/base.py", line 791, in _finalize_fairy pool.logger.error( Message: 'Exception during reset or similar' Arguments: () --- Logging error --- Traceback (most recent call last): File "/home/runner/.local/share/virtualenvs/airflow-jCIRjM3K/lib/python3.11/site-packages/sqlalchemy/pool/base.py", line 763, in _finalize_fairy fairy._reset(pool, transaction_was_reset) File "/home/runner/.local/share/virtualenvs/airflow-jCIRjM3K/lib/python3.11/site-packages/sqlalchemy/pool/base.py", line 1038, in _reset pool._dialect.do_rollback(self) File "/home/runner/.local/share/virtualenvs/airflow-jCIRjM3K/lib/python3.11/site-packages/sqlalchemy/engine/default.py", line 683, in do_rollback dbapi_connection.rollback() psycopg2.OperationalError: server closed the connection unexpectedly This probably means the server terminated abnormally before or while processing the request. During handling of the above exception, another exception occurred: Traceback (most recent call last): File "/opt/hostedtoolcache/Python/3.11.8/x64/lib/python3.11/logging/__init__.py", line 1113, in emit stream.write(msg + self.terminator) ValueError: I/O operation on closed file. Call stack: File "/home/runner/.local/share/virtualenvs/airflow-jCIRjM3K/lib/python3.11/site-packages/sqlalchemy/pool/base.py", line 509, in <lambda> and _finalize_fairy( File "/home/runner/.local/share/virtualenvs/airflow-jCIRjM3K/lib/python3.11/site-packages/sqlalchemy/pool/base.py", line 791, in _finalize_fairy pool.logger.error( Message: 'Exception during reset or similar' Arguments: () ``` ## Type of change > All pull requests must have at least one of the following labels applied (otherwise the PR will fail): | Label | Description | |----------------------------- |----------------------------------------------------------------------------------------------------------- | | Type: Bug | non-breaking change that fixes an issue | | Type: Feature | non-breaking change that adds functionality | | Type: Breaking Change | fix or feature that would cause existing functionality to not work as expected | | Type: Non-breaking refactor | change addresses some tech debt item or prepares for a later change, but does not change functionality | | Type: Configuration Change | adjusts configuration to achieve some end related to functionality, development, performance, or security | | Type: Dependency Upgrade | upgrades a project dependency - these changes are not included in release notes | ## Related issues Closes Recidiviz/recidiviz-data#29554 ## Checklists ### Development **This box MUST be checked by the submitter prior to merging**: - [x] **Double- and triple-checked that there is no Personally Identifiable Information (PII) being mistakenly added in this pull request** These boxes should be checked by the submitter prior to merging: - [ ] Tests have been written to cover the code changed/added as part of this pull request ### Code review These boxes should be checked by reviewers prior to merging: - [x] This pull request has a descriptive title and information useful to a reviewer - [x] Potential security implications or infrastructural changes have been considered, if relevant --------- Co-authored-by: Helper Bot <[email protected]> GitOrigin-RevId: 355d050265f490df1779ff773533f5aefd41de6b

@ohaibbq

…iviz/recidiviz-data#29712) ## Description of the change Recidiviz/recidiviz-data#27852 upgraded to `composer-2.6.2-airflow-2.6.3` which failed during the tf step and was reverted in Recidiviz/recidiviz-data#29696 The commits in this PR are as follows -- 1. un-reverts Recidiviz/recidiviz-data#27852 2. upgrades to `composer-2.7.1-airflow-2.7.3`, copying requirements over from [version page](https://cloud.google.com/composer/docs/concepts/versioning/composer-versions#images) 3. airflow pipenv lock workflow 4. removes a few imports and checks since [Recidiviz/recidiviz-data#32731](apache/airflow#32731) opened by our very own @ohaibbq is included in 2.7.1 read through the [release notes](https://airflow.apache.org/docs/apache-airflow/stable/release_notes.html#airflow-2-7-0-2023-08-18), nothing in our usage seems to be deprecated; there are a few things that might be of interest to folks: - _Create metrics to track Scheduled->Queued->Running task state transition times ([Recidiviz/recidiviz-data#30612](apache/airflow#30612 will be nice for us to be able to see this re: k8s spin up time - _Add OpenTelemetry to Airflow ([AIP-49](https://github.com/apache/airflow/pulls?q=is%3Apr+is%3Amerged+label%3AAIP-49+milestone%3A%22Airflow+2.7.0%22))_ - _The trigger UI form is skipped in web UI if no parameters are defined in a DAG ([Recidiviz/recidiviz-data#33351](apache/airflow#33351: not sure if folks run ad-hoc dags using the UI instead of `trigger_state_specific_calculation/ingest_dag` but we need to add `show_trigger_form_if_no_params` if we want to still be able to trigger via the UI would love a second set of eyes around these warning logs that occur after tests run, see [here](https://github.com/Recidiviz/recidiviz-data/actions/runs/9071731702/job/24926024866?pr=29712#step:6:53). also occurred locally but i couldn't isolate the cause of the issue ``` Traceback (most recent call last): File "/opt/hostedtoolcache/Python/3.11.8/x64/lib/python3.11/logging/__init__.py", line 1113, in emit stream.write(msg + self.terminator) ValueError: I/O operation on closed file. Call stack: File "/home/runner/.local/share/virtualenvs/airflow-jCIRjM3K/lib/python3.11/site-packages/sqlalchemy/pool/base.py", line 509, in <lambda> and _finalize_fairy( File "/home/runner/.local/share/virtualenvs/airflow-jCIRjM3K/lib/python3.11/site-packages/sqlalchemy/pool/base.py", line 791, in _finalize_fairy pool.logger.error( Message: 'Exception during reset or similar' Arguments: () --- Logging error --- Traceback (most recent call last): File "/home/runner/.local/share/virtualenvs/airflow-jCIRjM3K/lib/python3.11/site-packages/sqlalchemy/pool/base.py", line 763, in _finalize_fairy fairy._reset(pool, transaction_was_reset) File "/home/runner/.local/share/virtualenvs/airflow-jCIRjM3K/lib/python3.11/site-packages/sqlalchemy/pool/base.py", line 1038, in _reset pool._dialect.do_rollback(self) File "/home/runner/.local/share/virtualenvs/airflow-jCIRjM3K/lib/python3.11/site-packages/sqlalchemy/engine/default.py", line 683, in do_rollback dbapi_connection.rollback() psycopg2.OperationalError: server closed the connection unexpectedly This probably means the server terminated abnormally before or while processing the request. During handling of the above exception, another exception occurred: Traceback (most recent call last): File "/opt/hostedtoolcache/Python/3.11.8/x64/lib/python3.11/logging/__init__.py", line 1113, in emit stream.write(msg + self.terminator) ValueError: I/O operation on closed file. Call stack: File "/home/runner/.local/share/virtualenvs/airflow-jCIRjM3K/lib/python3.11/site-packages/sqlalchemy/pool/base.py", line 509, in <lambda> and _finalize_fairy( File "/home/runner/.local/share/virtualenvs/airflow-jCIRjM3K/lib/python3.11/site-packages/sqlalchemy/pool/base.py", line 791, in _finalize_fairy pool.logger.error( Message: 'Exception during reset or similar' Arguments: () ``` ## Type of change > All pull requests must have at least one of the following labels applied (otherwise the PR will fail): | Label | Description | |----------------------------- |----------------------------------------------------------------------------------------------------------- | | Type: Bug | non-breaking change that fixes an issue | | Type: Feature | non-breaking change that adds functionality | | Type: Breaking Change | fix or feature that would cause existing functionality to not work as expected | | Type: Non-breaking refactor | change addresses some tech debt item or prepares for a later change, but does not change functionality | | Type: Configuration Change | adjusts configuration to achieve some end related to functionality, development, performance, or security | | Type: Dependency Upgrade | upgrades a project dependency - these changes are not included in release notes | ## Related issues Closes Recidiviz/recidiviz-data#29554 ## Checklists ### Development **This box MUST be checked by the submitter prior to merging**: - [x] **Double- and triple-checked that there is no Personally Identifiable Information (PII) being mistakenly added in this pull request** These boxes should be checked by the submitter prior to merging: - [ ] Tests have been written to cover the code changed/added as part of this pull request ### Code review These boxes should be checked by reviewers prior to merging: - [x] This pull request has a descriptive title and information useful to a reviewer - [x] Potential security implications or infrastructural changes have been considered, if relevant --------- Co-authored-by: Helper Bot <[email protected]> GitOrigin-RevId: 355d050265f490df1779ff773533f5aefd41de6b

vandonr-amz added 2 commits April 12, 2023 13:38

add a metric for task adoption time

67b4637

update doc accordingly

1ec9c3b

vandonr-amz requested review from potiuk, kaxil, XD-DENG and ashb as code owners April 12, 2023 22:31

boring-cyborg bot added the kind:documentation label Apr 12, 2023

ferruzzi reviewed Apr 12, 2023

View reviewed changes

airflow/models/taskinstance.py Outdated Show resolved Hide resolved

vandonr-amz added 2 commits April 21, 2023 16:37

split metric in two

160b246

I didn't mean to commit this before

bcf115b

vandonr-amz changed the title ~~Create a metric for task adoption time~~ Create a metrics to track Scheduled->Queued->Running task state transition times Apr 21, 2023

vandonr-amz changed the title ~~Create a metrics to track Scheduled->Queued->Running task state transition times~~ Create metrics to track Scheduled->Queued->Running task state transition times Apr 21, 2023

Merge remote-tracking branch 'origin/main' into vandonr/fix

8f2cfb3

vandonr-amz added 2 commits April 24, 2023 11:01

Merge remote-tracking branch 'origin/main' into vandonr/fix

931b5f6

add some guardrails when we compute time spent

5c58f89

o-nikolas reviewed Apr 26, 2023

View reviewed changes

ferruzzi approved these changes Apr 27, 2023

View reviewed changes

vandonr-amz and others added 2 commits April 27, 2023 11:31

reword comment

e4c640b

Co-authored-by: Niko Oliveira <[email protected]>

add a bit more info on notimplementedexception

72bbdbf

Merge remote-tracking branch 'origin/main' into vandonr/fix

a50d857

o-nikolas approved these changes Apr 27, 2023

View reviewed changes

potiuk approved these changes Apr 28, 2023

View reviewed changes

potiuk merged commit 093174d into apache:main Apr 28, 2023

ephraimbuddy added the type:new-feature Changelog: New Features label May 8, 2023

ephraimbuddy added this to the Airflow 2.7.0 milestone May 8, 2023

kzosabe mentioned this pull request Sep 20, 2023

emit_state_change_metric produces many warnings even in standard use cases #34493

Closed

2 tasks

uranusjr mentioned this pull request Jan 22, 2024

Suppress false warning when TI state is QUEUED and TI doesn't have a start_date #34771

Closed

This was referenced Mar 26, 2024

Update log level to debug from warning about scheduled_duration metric #38180

Merged

Fix dag task scheduled and queued duration metrics #37936

Merged

kzosabe mentioned this pull request Mar 30, 2024

States of the time field corresponding to ti.state is not clear #38632

Closed

2 tasks

jscheffl mentioned this pull request Jan 25, 2025

Enable already existing "task.scheduled_duration" metric #46009

Merged

		Stats.timing(f"dag.{self.dag_id}.{self.task_id}.{metric_name}", timing)
		Stats.timing(f"task.{metric_name}", timing, tags={"task_id": self.task_id, "dag_id": self.dag_id})

Create metrics to track Scheduled->Queued->Running task state transition times #30612

Create metrics to track Scheduled->Queued->Running task state transition times #30612

Uh oh!

Conversation

vandonr-amz commented Apr 12, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Uh oh!

ferruzzi commented Apr 12, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

jedcunningham commented Apr 12, 2023

Uh oh!

potiuk commented Apr 13, 2023

Uh oh!

ferruzzi commented Apr 13, 2023

Uh oh!

jedcunningham commented Apr 13, 2023

Uh oh!

potiuk commented Apr 13, 2023

Uh oh!

vandonr-amz commented Apr 13, 2023

Uh oh!

shubham22 commented Apr 14, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

potiuk commented Apr 14, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

vandonr-amz commented Apr 21, 2023

Uh oh!

potiuk commented Apr 22, 2023

Uh oh!

o-nikolas left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

o-nikolas Apr 26, 2023

Choose a reason for hiding this comment

Uh oh!

vandonr-amz Apr 27, 2023

Choose a reason for hiding this comment

Uh oh!

o-nikolas Apr 27, 2023

Choose a reason for hiding this comment

Uh oh!

o-nikolas Apr 26, 2023

Choose a reason for hiding this comment

Uh oh!

ferruzzi left a comment

Choose a reason for hiding this comment

Uh oh!

ferruzzi Apr 27, 2023

Choose a reason for hiding this comment

Uh oh!

vandonr-amz Apr 27, 2023

Choose a reason for hiding this comment

Uh oh!

ferruzzi Apr 28, 2023

Choose a reason for hiding this comment

Uh oh!

htpawel commented Mar 6, 2024

Uh oh!

ferruzzi commented Mar 6, 2024

Uh oh!

Uh oh!

vandonr-amz commented Apr 12, 2023 •

edited

Loading

ferruzzi commented Apr 12, 2023 •

edited

Loading

shubham22 commented Apr 14, 2023 •

edited

Loading

potiuk commented Apr 14, 2023 •

edited

Loading