From dev-return-9210-archive-asf-public=cust-asf.ponee.io@airflow.apache.org Sun Aug 18 11:08:48 2019 Return-Path: X-Original-To: archive-asf-public@cust-asf.ponee.io Delivered-To: archive-asf-public@cust-asf.ponee.io Received: from mail.apache.org (hermes.apache.org [207.244.88.153]) by mx-eu-01.ponee.io (Postfix) with SMTP id 139A3180608 for ; Sun, 18 Aug 2019 13:08:47 +0200 (CEST) Received: (qmail 11160 invoked by uid 500); 18 Aug 2019 11:08:47 -0000 Mailing-List: contact dev-help@airflow.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@airflow.apache.org Delivered-To: mailing list dev@airflow.apache.org Received: (qmail 11147 invoked by uid 99); 18 Aug 2019 11:08:46 -0000 Received: from pnap-us-west-generic-nat.apache.org (HELO spamd2-us-west.apache.org) (209.188.14.142) by apache.org (qpsmtpd/0.29) with ESMTP; Sun, 18 Aug 2019 11:08:46 +0000 Received: from localhost (localhost [127.0.0.1]) by spamd2-us-west.apache.org (ASF Mail Server at spamd2-us-west.apache.org) with ESMTP id 575C31A3279 for ; Sun, 18 Aug 2019 11:08:46 +0000 (UTC) X-Virus-Scanned: Debian amavisd-new at spamd2-us-west.apache.org X-Spam-Flag: NO X-Spam-Score: 1.8 X-Spam-Level: * X-Spam-Status: No, score=1.8 tagged_above=-999 required=6.31 tests=[DKIM_SIGNED=0.1, DKIM_VALID=-0.1, DKIM_VALID_AU=-0.1, DKIM_VALID_EF=-0.1, HTML_MESSAGE=2, RCVD_IN_DNSWL_NONE=-0.0001, SPF_HELO_NONE=0.001, SPF_PASS=-0.001] autolearn=disabled Authentication-Results: spamd2-us-west.apache.org (amavisd-new); dkim=pass (2048-bit key) header.d=gmail.com Received: from mx1-he-de.apache.org ([10.40.0.8]) by localhost (spamd2-us-west.apache.org [10.40.0.9]) (amavisd-new, port 10024) with ESMTP id qK4lcsvmJ2P9 for ; Sun, 18 Aug 2019 11:08:43 +0000 (UTC) Received-SPF: Pass (mailfrom) identity=mailfrom; client-ip=2607:f8b0:4864:20::529; helo=mail-pg1-x529.google.com; envelope-from=bdbruin@gmail.com; receiver= Received: from mail-pg1-x529.google.com (mail-pg1-x529.google.com [IPv6:2607:f8b0:4864:20::529]) by mx1-he-de.apache.org (ASF Mail Server at mx1-he-de.apache.org) with ESMTPS id AB1717D3FA for ; Sun, 18 Aug 2019 11:08:42 +0000 (UTC) Received: by mail-pg1-x529.google.com with SMTP id u17so5257500pgi.6 for ; Sun, 18 Aug 2019 04:08:42 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=mime-version:references:in-reply-to:from:date:message-id:subject:to; bh=CxGqGXYlOVW3mctwJaANnWpWW394rTfYw8jTyHVuk0E=; b=FIhChr18paKvCYOK8DaJkNUtPhJheGlIAhS92ID25kwRITpHVOUuAP/z8y00yTkh66 ogNatxFhOvRQon3eukpreM3sfvmTPnYLdXE4y4PutDZGj4+ZU91m2toILZLuEHNpbjQz +FE2eotf0LR9OPmaKqvhejL9Xhycg0SBBFpQ/B5OXQ3itsQ93UxQk2LT+w6f1hJij8gi g7JpYKG+yOTgNoBj3PAHmtfXRReVSgqi1PO4AuzhzdbqXIFhPOuO6dUntvGcdLHTEPPK KjCIAaWOdMLGf+2Hb6yyVwJI47k7hjJe+s53b9zCfEK6BDACH2JHS8Yv2BALBcgrkTkk WYsA== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:mime-version:references:in-reply-to:from:date :message-id:subject:to; bh=CxGqGXYlOVW3mctwJaANnWpWW394rTfYw8jTyHVuk0E=; b=ndASNWOE1p0Jd2s9NUwlojMSpUn05GFkXn40A1KJa36/573fKPBWkzxt7vpWW2IODt QBO+mFi+Ix7W749u5S/JmDXWMSlQLn52EhdlFFoWLG0H4ZS63brW9AS0HWPKr2SvM+9D xvRQQcgTZTB0b4YZMCRH3u3gkNmHk+VmnFpIKClEzYvHkXG84FQMo3A2DFHKiOxgDNtv jibbJurzFU7QbtyUg6/XgxEVvud8orUTSCDqSQVRm/Hw44LVEspbXXUNDEYP/VZvwVak Q+gVGast7mRHn2DGh43AoECI7E1Qz6jqUxh2/7sIRBf2HySrQlkhV48pplaSmSwhf1Qo ZXhA== X-Gm-Message-State: APjAAAWoOxg26wY5YICROobntnJJh+0uTG5mmhmJFm3YsOqZeqI2l4i2 pgUwh82OLkn4mnNVaP/sZPsFeo9HNI3CqQLRiB3SpUsfehVR X-Google-Smtp-Source: APXvYqx+KaI4rFM1v+zpfPEKMs1aL6TIbTbUGQaoBm8rBqvzuOn+W0gPPbC3VLcKsSRg8eAmDyZjxXl7hr0Eyf+f8Kc= X-Received: by 2002:a65:4844:: with SMTP id i4mr15515898pgs.113.1566126520342; Sun, 18 Aug 2019 04:08:40 -0700 (PDT) MIME-Version: 1.0 References: <9BA9748A-C2EF-4BF7-BCFE-D3621229F4FE@apache.org> <4C32CF2F-BFF8-4F99-858F-3E5DB1232C8F@gmail.com> In-Reply-To: From: Bolke de Bruin Date: Sun, 18 Aug 2019 13:08:29 +0200 Message-ID: Subject: Re: Removal of "run_duration" and its impact on orphaned tasks To: dev@airflow.apache.org Content-Type: multipart/alternative; boundary="000000000000eb1d9a0590623eed" --000000000000eb1d9a0590623eed Content-Type: text/plain; charset="UTF-8" James Could you log this with debug on for SchedulerJob? There is only one place where the number of tasks can go lower and thats when the executor reports having the task. That's logged at debug level. Are you collecting metrics from Airflow? If so I can create a small patch that will track tasks up for execution, tasks at executor, and tasks executed. cheers Bolke Op wo 31 jul. 2019 om 23:08 schreef James Meickle : > Yes, we use the Celery executor. > > To clarify, the tasks hadn't been running on workers for a long time, or > even successfully submitted to Celery, so it's not a case where they got > queued and then lost after some period of time. > > This happened shortly after UTC midnight, when we launch most of our tasks > (note the UTC timestamp of the server having recently rolled over, vs. the > execution date on the tasks _mostly_ being the previous date, which would > be just launching at rollover) > > [2019-07-31 01:54:15,783] {{scheduler_job.py:889}} INFO - 21 tasks up for > execution: > > > > > > > > > > > [scheduled]> > [scheduled]> > [scheduled]> > [scheduled]> > [scheduled]> > [scheduled]> > > > > > > [2019-07-31 01:54:15,790] {{scheduler_job.py:921}} INFO - Figuring out > tasks to run in Pool(name=default_pool) with 90 open slots and 14 task > instances ready to be queued > (snip) > [2019-07-31 01:54:15,807] {{scheduler_job.py:921}} INFO - Figuring out > tasks to run in Pool(name=short_volume) with 7 open slots and 7 task > instances ready to be queued > (snip) > [2019-07-31 01:54:15,818] {{scheduler_job.py:992}} INFO - Setting the > follow tasks to queued state: > > (blank newline and nothing else, then the log starts repeating) > > On Wed, Jul 31, 2019 at 2:51 PM Bolke de Bruin wrote: > > > Is this all with celery? Afaik Lyft runs with celery? Also if I remember > > correctly the Google guys had a fix for this but that hasn't been > > upstreamed yet? > > > > With celery task do get "lost" after a while with a certain setting (on a > > phone so don't have it handy, we do set a higher default) > > > > Can you check when those tasks got into "scheduled" and what the time > > difference is with "now"? > > > > B. > > > > Sent from my iPhone > > > > > On 31 Jul 2019, at 20:56, James Meickle .invalid> > > wrote: > > > > > > Ash: > > > > > > We definitely don't run thousands of tasks. Looks like it's closer to > 300 > > > per execution date (and then retries), if I'm using the TI browser > right. > > > > > > In my case, I found 21 tasks in "scheduled" state after 1 day of not > > > restarting. One of our hourly "canary" DAGs got included in the > pile-up - > > > so it didn't run that hour as expected, so I got paged. (But it wasn't > > just > > > canary tasks, the other 20 tasks were all real and important workflows > > that > > > were not getting scheduled.) > > > > > > If we do change the scheduler to have a "cleanup" step within the loop > > > instead of pre/post loop, I'd suggest we should: > > > - Make the time between cleanups a configurable parameter > > > - Log what cleanup steps are being taken and how long they take > > > - Add new statsd metrics around cleanups (like "number of orphans > > reset"), > > > to help us understand when and why this happens > > > > > > > > > > > >> On Wed, Jul 31, 2019 at 1:25 PM Tao Feng wrote: > > >> > > >> Late in the game as I was't aware of `run_duration` option been > removed. > > >> But just want to point out that Lyft also did very similar with James' > > >> setup that we run the scheduler in a fix internal instead of infinite > > loop > > >> and let the runit/supervisor to restart the scheduler process. This is > > to > > >> solve: 1. orphaned tasks not getting clean up successfully when it > runs > > on > > >> infinite loop; 2. Make sure stale / deleted DAG will get clean up( > > >> > > >> > > > https://github.com/apache/airflow/blob/master/airflow/jobs/scheduler_job.py#L1438 > > >> ? > > >> < > > > https://github.com/apache/airflow/blob/master/airflow/jobs/scheduler_job.py#L1438 > > ?> > > >> ) > > >> properly. > > >> > > >> I think if it goes with removing this option and let scheduler runs in > > an > > >> infinite loop, we need to change the schedule loop to handle the clean > > up > > >> process if it hasn't been done. > > >> > > >>> On Wed, Jul 31, 2019 at 10:10 AM Ash Berlin-Taylor > > wrote: > > >>> > > >>> Thanks for testing this out James, shame to discover we still have > > >>> problems in that area. Do you have an idea of how many tasks per day > we > > >> are > > >>> talking about here? > > >>> > > >>> Your cluster schedules quite a large number of tasks over the day (in > > the > > >>> 1k-10k range?) right? > > >>> > > >>> I'd say whatever causes a task to become orphaned _while_ the > scheduler > > >> is > > >>> still running is the actual bug, and running the orphan detection > more > > >>> often may just be replacing one patch (the run duration) with another > > one > > >>> (running the orphan detection more than at start up). > > >>> > > >>> -ash > > >>> > > >>>> On 31 Jul 2019, at 16:43, James Meickle > >> .INVALID> > > >>> wrote: > > >>>> > > >>>> In my testing of 1.10.4rc3, I discovered that we were getting hit > by a > > >>>> process leak bug (which Ash has since fixed in 1.10.4rc4). This > > process > > >>>> leak was minimal impact for most users, but was exacerbated in our > > case > > >>> by > > >>>> using "run_duration" to restart the scheduler every 10 minutes. > > >>>> > > >>>> To mitigate that issue while remaining on the RC, we removed the use > > of > > >>>> "run_duration", since it is deprecated as of master anyways: > > >>>> > > >>> > > >> > > > https://github.com/apache/airflow/blob/master/UPDATING.md#remove-run_duration > > >>>> > > >>>> Unfortunately, testing on our cluster (1.10.4rc3 plus no > > >> "run_duration") > > >>>> has revealed that while the process leak issue was mitigated, that > > >> we're > > >>>> now facing issues with orphaned tasks. These tasks are marked as > > >>>> "scheduled" by the scheduler, but _not_ successfully queued in > Celery > > >>> even > > >>>> after multiple scheduler loops. Around ~24h after last restart, we > > >> start > > >>>> having enough stuck tasks that the system starts paging and > requires a > > >>>> manual restart. > > >>>> > > >>>> Rather than generic "scheduler instability", this specific issue was > > >> one > > >>> of > > >>>> the reasons why we'd originally added the scheduler restart. But it > > >>> appears > > >>>> that on master, the orphaned task detection code still only runs on > > >>>> scheduler start despite removing "run_duration": > > >>>> > > >>> > > >> > > > https://github.com/apache/airflow/blob/master/airflow/jobs/scheduler_job.py#L1328 > > >>>> > > >>>> Rather than immediately filing an issue I wanted to inquire a bit > more > > >>>> about why this orphan detection code is only run on scheduler start, > > >>>> whether it would be safe to send in a PR to run it more often > (maybe a > > >>>> tunable parameter?), and if there's some other configuration issue > > with > > >>>> Celery (in our case, backed by AWS Elasticache) that would cause us > to > > >>> see > > >>>> orphaned tasks frequently. > > >>> > > >>> > > >> > > > -- -- Bolke de Bruin bdbruin@gmail.com --000000000000eb1d9a0590623eed--