Slow query log? Db load? B.
Verstuurd vanaf mijn iPad > Op 23 jan. 2017 om 21:59 heeft Chris Riccomini <[email protected]> het > volgende geschreven: > > Note: 6.5 million TIs in the task_instance table. > > On Mon, Jan 23, 2017 at 12:58 PM, Chris Riccomini <[email protected]> > wrote: > >> Hey Bolke, >> >> Re: system usage, it's pretty quiet <5% CPU usage. Mem is almost all free >> as well. >> >> I am thinking that this is DB related, given that it's pausing when >> executing an update. Was looking at the update_state method in models.py, >> which logs right before the 15s pause. >> >> Cheers, >> Chris >> >> On Mon, Jan 23, 2017 at 12:51 PM, Bolke de Bruin <[email protected]> >> wrote: >> >>> Hi Chris, >>> >>> What is the load on your machine? (CPU/IO/MEM) It seems that the executor >>> is faster in checking the state than the TaskInstance is able to exit >>> itself. No, I don’t consider it normal, but it was sometimes reported ( >>> https://github.com/apache/incubator-airflow/pull/1821) though not really >>> replicable as of yet. >>> >>> Parsing seems exceptionally slow, it might be worth looking at it with a >>> debugger. Very faint guess might be that something with the multiprocessing >>> part could do something with memory that is costly, but then we need to >>> know more about what is running on the system. Never clue of system metrics >>> could be helpful here. >>> >>> Bolke >>> >>>> On 23 Jan 2017, at 21:34, Chris Riccomini <[email protected]> >>> wrote: >>>> >>>> Also, seeing this in EVERY task that runs: >>>> >>>> [2017-01-23 20:26:13,777] {jobs.py:2112} WARNING - State of this >>>> instance has been externally set to queued. Taking the poison pill. So >>>> long. >>>> [2017-01-23 20:26:13,841] {jobs.py:2051} INFO - Task exited with return >>> code 0 >>>> >>>> >>>> All successful tasks are showing this at the end of their logs. Is this >>>> normal? >>>> >>>> On Mon, Jan 23, 2017 at 12:27 PM, Chris Riccomini < >>> [email protected]> >>>> wrote: >>>> >>>>> Hey all, >>>>> >>>>> I've upgraded on production. Things seem to be working so far (only >>> been >>>>> an hour), but I am seeing this in the scheduler logs: >>>>> >>>>> File Path >>> PID >>>>> Runtime Last Runtime Last Run >>>>> ------------------------------------------------------------------ >>> ----- >>>>> --------- -------------- ------------------- >>>>> ... >>>>> /etc/airflow/dags/dags/elt/el/db.py >>> 24793 >>>>> 43.41s 986.63s 2017-01-23T20:04:09 >>>>> ... >>>>> >>>>> It seems to be taking more than 15 minutes to parse this DAG. Any idea >>>>> what's causing this? Scheduler config: >>>>> >>>>> [scheduler] >>>>> job_heartbeat_sec = 5 >>>>> scheduler_heartbeat_sec = 5 >>>>> max_threads = 2 >>>>> child_process_log_directory = /var/log/airflow/scheduler >>>>> >>>>> The db.py file, itself, doesn't interact with any outside systems, so I >>>>> would have expected this to not take so long. It does, however, >>>>> programmatically generate many DAGs within the single .py file. >>>>> >>>>> A snippet of the scheduler log is here: >>>>> >>>>> https://gist.github.com/criccomini/a2b2762763c8ba65fefcdd669e8ffd65 >>>>> >>>>> Note how there are 10-15 second gaps occasionally. Any idea what's >>> going >>>>> on? >>>>> >>>>> Cheers, >>>>> Chris >>>>> >>>>> On Sun, Jan 22, 2017 at 4:42 AM, Bolke de Bruin <[email protected]> >>> wrote: >>>>> >>>>>> I created: >>>>>> >>>>>> - AIRFLOW-791: At start up all running dag_runs are being checked, but >>>>>> not fixed >>>>>> - AIRFLOW-790: DagRuns do not exist for certain tasks, but don’t get >>> fixed >>>>>> - AIRFLOW-788: Context unexpectedly added to hive conf >>>>>> - AIRFLOW-792: Allow fixing of schedule when wrong start_date / >>> interval >>>>>> was specified >>>>>> >>>>>> I created AIRFLOW-789 to update UPDATING.md, it is also out as a PR. >>>>>> >>>>>> Please note that I don't consider any of these blockers for a release >>> of >>>>>> 1.8.0 and can be fixed in 1.8.1 - so we are still on track for an RC >>> on Feb >>>>>> 2. However if people are using a restarting scheduler (run_duration >>> is set) >>>>>> and have a lot of running dag runs they won’t like AIRFLOW-791. So a >>>>>> workaround for this would be nice (we just updated dag_runs directly >>> in the >>>>>> database to say ‘finished’ before a certain date, but we are also not >>> using >>>>>> the run_duration). >>>>>> >>>>>> Bolke >>>>>> >>>>>> >>>>>> >>>>>>> On 20 Jan 2017, at 23:55, Bolke de Bruin <[email protected]> wrote: >>>>>>> >>>>>>> Will do. And thanks. >>>>>>> >>>>>>> Adding another issue: >>>>>>> >>>>>>> * Some of our DAGs are not getting scheduled for some unknown reason. >>>>>>> Need to investigate why. >>>>>>> >>>>>>> Related but not root cause: >>>>>>> * Logging is so chatty that it gets really hard to find the real >>> issue >>>>>>> >>>>>>> Bolke. >>>>>>> >>>>>>>> On 20 Jan 2017, at 23:45, Dan Davydov <[email protected] >>> .INVALID> >>>>>> wrote: >>>>>>>> >>>>>>>> I'd be happy to lend a hand fixing these issues and hopefully some >>>>>> others >>>>>>>> are too. Do you mind creating jiras for these since you have the >>> full >>>>>>>> context? I have created a JIRA for (1) and have assigned it to >>> myself: >>>>>>>> https://issues.apache.org/jira/browse/AIRFLOW-780 >>>>>>>> >>>>>>>> On Fri, Jan 20, 2017 at 1:01 AM, Bolke de Bruin <[email protected]> >>>>>> wrote: >>>>>>>> >>>>>>>>> This is to report back on some of the (early) experiences we have >>> with >>>>>>>>> Airflow 1.8.0 (beta 1 at the moment): >>>>>>>>> >>>>>>>>> 1. The UI does not show faulty DAG, leading to confusion for >>>>>> developers. >>>>>>>>> When a faulty dag is placed in the dags folder the UI would report >>> a >>>>>>>>> parsing error. Now it doesn’t due to the separate parising (but not >>>>>>>>> reporting back errors) >>>>>>>>> >>>>>>>>> 2. The hive hook sets ‘airflow.ctx.dag_id’ in hive >>>>>>>>> We run in a secure environment which requires this variable to be >>>>>>>>> whitelisted if it is modified (needs to be added to UPDATING.md) >>>>>>>>> >>>>>>>>> 3. DagRuns do not exist for certain tasks, but don’t get fixed >>>>>>>>> Log gets flooded without a suggestion what to do >>>>>>>>> >>>>>>>>> 4. At start up all running dag_runs are being checked, we seemed to >>>>>> have a >>>>>>>>> lot of “left over” dag_runs (couple of thousand) >>>>>>>>> - Checking was logged to INFO -> requires a fsync for every log >>>>>> message >>>>>>>>> making it very slow >>>>>>>>> - Checking would happen at every restart, but dag_runs’ states were >>>>>> not >>>>>>>>> being updated >>>>>>>>> - These dag_runs would never er be marked anything else than >>> running >>>>>> for >>>>>>>>> some reason >>>>>>>>> -> Applied work around to update all dag_run in sql before a >>> certain >>>>>> date >>>>>>>>> to -> finished >>>>>>>>> -> need to investigate why dag_runs did not get marked >>>>>> “finished/failed” >>>>>>>>> >>>>>>>>> 5. Our umask is set to 027 >>>>>>>>> >>>>>>>>> >>>>>>> >>>>>> >>>>>> >>>>> >>> >>> >>
