Slow CI thread Pants #development

Join Slack

Slow CI thread:

# development

happy-kitchen-89482

10/10/2022, 5:42 PM

Slow CI thread:

happy-kitchen-89482

10/10/2022, 5:42 PM

This job is repeatedly timing out: https://github.com/pantsbuild/pants/actions/runs/3217018124/jobs/5267336055

happy-kitchen-89482

10/10/2022, 5:43 PM

This is “Build wheels and fs_util (macOS11-x86_64)”

happy-kitchen-89482

10/10/2022, 5:43 PM

here is the raw log: https://pipelines.actions.githubusercontent.com/serviceHosts/c6f2310f-2191-4df9-ab0d-b9d2413b7ed6/_apis/pipelines/1/runs/25384/signedlogcontent/16?urlExpires=2022-10-10T17%3A20%3A45.8756757Z&urlSigningMethod=HMACV1&urlSignature=%2FNelJfEVL%2Fxo4mWcMBdqHtOeWdUSJDrfqjKEwGgLGno%3D

happy-kitchen-89482

10/10/2022, 5:44 PM

Note that this is on a GitHub-hosted runner, not one of our MacStadium ones

happy-kitchen-89482

10/10/2022, 5:44 PM

It is excruciatingly slow

happy-kitchen-89482

10/10/2022, 5:44 PM

E.g., pantsd taking ~30 seconds to start, and having to start on every pants invocation for some reason

happy-kitchen-89482

10/10/2022, 5:46 PM

It’s doing a lot of work it shouldn’t need to (see https://github.com/pantsbuild/pants/pull/17172 for why)

happy-kitchen-89482

10/10/2022, 5:46 PM

But also the work is very slow

happy-kitchen-89482

10/10/2022, 5:47 PM

and we’ve been seeing this happen a lot, I think

busy-vase-39202

10/10/2022, 6:28 PM

Is there any reason to suspect GitHub is responsible? They have reps in my devrel slack. I can ping someone if needed.

enough-analyst-54434

10/10/2022, 6:30 PM

Reading the log, TC is ~responsible:

Copy code

PS C:\Users\John Sirois\Downloads\CI_logs_benjy_slow> grep "Failed to load Toolchain token" '.\1_Build wheels and fs_util (macOS11-x86_64).txt' | wc -l
33
PS C:\Users\John Sirois\Downloads\CI_logs_benjy_slow> grep -B1 "Failed to load Toolchain token" '.\1_Build wheels and fs_util (macOS11-x86_64).txt' | cut -dT -f2- | sed -r -e 's|\.[0-9]+Z | |'
15:46:14 15:46:14.65 [INFO] Scheduler initialized.
15:46:18 15:46:18.45 [WARN] [rules] Failed to load Toolchain token from env var 'TOOLCHAIN_AUTH_TOKEN'. Please make sure the env var is set in your environment.
--
15:47:24 Use `*ToolchainSetup.rules()` instead.
15:48:45 15:48:45.50 [WARN] [rules] Failed to load Toolchain token from env var 'TOOLCHAIN_AUTH_TOKEN'. Please make sure the env var is set in your environment.
--
15:51:16 Use `*ToolchainSetup.rules()` instead.
15:52:57 15:52:57.60 [WARN] [rules] Failed to load Toolchain token from env var 'TOOLCHAIN_AUTH_TOKEN'. Please make sure the env var is set in your environment.
--
15:54:19 Use `*ToolchainSetup.rules()` instead.
15:56:02 15:56:02.42 [WARN] [rules] Failed to load Toolchain token from env var 'TOOLCHAIN_AUTH_TOKEN'. Please make sure the env var is set in your environment.
--
15:56:51 Use `*ToolchainSetup.rules()` instead.
15:58:24 15:58:24.10 [WARN] [rules] Failed to load Toolchain token from env var 'TOOLCHAIN_AUTH_TOKEN'. Please make sure the env var is set in your environment.
--
16:03:00 16:03:00.68 [INFO] Scheduler initialized.
16:03:02 16:03:02.49 [WARN] [rules] Failed to load Toolchain token from env var 'TOOLCHAIN_AUTH_TOKEN'. Please make sure the env var is set in your environment.
--
16:03:54 Use `*ToolchainSetup.rules()` instead.
16:05:06 16:05:06.88 [WARN] [rules] Failed to load Toolchain token from env var 'TOOLCHAIN_AUTH_TOKEN'. Please make sure the env var is set in your environment.
--
16:07:14 Use `*ToolchainSetup.rules()` instead.
16:08:39 16:08:39.05 [WARN] [rules] Failed to load Toolchain token from env var 'TOOLCHAIN_AUTH_TOKEN'. Please make sure the env var is set in your environment.
--
16:10:39 Use `*ToolchainSetup.rules()` instead.
16:10:39 16:10:39.13 [WARN] [rules] Failed to load Toolchain token from env var 'TOOLCHAIN_AUTH_TOKEN'. Please make sure the env var is set in your environment.
--
16:11:10 Use `*ToolchainSetup.rules()` instead.
16:12:12 16:12:12.28 [WARN] [rules] Failed to load Toolchain token from env var 'TOOLCHAIN_AUTH_TOKEN'. Please make sure the env var is set in your environment.
--
16:13:11 Use `*ToolchainSetup.rules()` instead.
16:14:02 16:14:02.07 [WARN] [rules] Failed to load Toolchain token from env var 'TOOLCHAIN_AUTH_TOKEN'. Please make sure the env var is set in your environment.
--
16:14:05 16:14:05.43 [WARN] WorkUnitConverter: Fallback on hard coded config
16:14:05 16:14:05.44 [WARN] [rules] Failed to load Toolchain token from env var 'TOOLCHAIN_AUTH_TOKEN'. Please make sure the env var is set in your environment.
--
16:14:31 Use `*ToolchainSetup.rules()` instead.
16:15:21 16:15:21.96 [WARN] [rules] Failed to load Toolchain token from env var 'TOOLCHAIN_AUTH_TOKEN'. Please make sure the env var is set in your environment.
--
16:15:29 16:15:29.39 [WARN] WorkUnitConverter: Fallback on hard coded config
16:15:29 16:15:29.42 [WARN] [rules] Failed to load Toolchain token from env var 'TOOLCHAIN_AUTH_TOKEN'. Please make sure the env var is set in your environment.
--
16:19:39 16:19:39.47 [INFO] Scheduler initialized.
16:19:40 16:19:40.55 [WARN] [rules] Failed to load Toolchain token from env var 'TOOLCHAIN_AUTH_TOKEN'. Please make sure the env var is set in your environment.
--
16:20:32 Use `*ToolchainSetup.rules()` instead.
16:21:34 16:21:34.25 [WARN] [rules] Failed to load Toolchain token from env var 'TOOLCHAIN_AUTH_TOKEN'. Please make sure the env var is set in your environment.
--
16:23:50 Use `*ToolchainSetup.rules()` instead.
16:24:52 16:24:52.02 [WARN] [rules] Failed to load Toolchain token from env var 'TOOLCHAIN_AUTH_TOKEN'. Please make sure the env var is set in your environment.
--
16:25:44 Use `*ToolchainSetup.rules()` instead.
16:26:46 16:26:46.44 [WARN] [rules] Failed to load Toolchain token from env var 'TOOLCHAIN_AUTH_TOKEN'. Please make sure the env var is set in your environment.
--
16:27:18 Use `*ToolchainSetup.rules()` instead.
16:28:19 16:28:19.47 [WARN] [rules] Failed to load Toolchain token from env var 'TOOLCHAIN_AUTH_TOKEN'. Please make sure the env var is set in your environment.
--
16:29:23 Use `*ToolchainSetup.rules()` instead.
16:30:14 16:30:14.59 [WARN] [rules] Failed to load Toolchain token from env var 'TOOLCHAIN_AUTH_TOKEN'. Please make sure the env var is set in your environment.
--
16:30:17 16:30:17.90 [WARN] WorkUnitConverter: Fallback on hard coded config
16:30:17 16:30:17.92 [WARN] [rules] Failed to load Toolchain token from env var 'TOOLCHAIN_AUTH_TOKEN'. Please make sure the env var is set in your environment.
--
16:30:44 Use `*ToolchainSetup.rules()` instead.
16:31:35 16:31:35.86 [WARN] [rules] Failed to load Toolchain token from env var 'TOOLCHAIN_AUTH_TOKEN'. Please make sure the env var is set in your environment.
--
16:31:43 16:31:43.02 [WARN] WorkUnitConverter: Fallback on hard coded config
16:31:43 16:31:43.05 [WARN] [rules] Failed to load Toolchain token from env var 'TOOLCHAIN_AUTH_TOKEN'. Please make sure the env var is set in your environment.
--
16:35:42 16:35:42.12 [INFO] Scheduler initialized.
16:35:43 16:35:43.35 [WARN] [rules] Failed to load Toolchain token from env var 'TOOLCHAIN_AUTH_TOKEN'. Please make sure the env var is set in your environment.
--
16:36:30 Use `*ToolchainSetup.rules()` instead.
16:37:31 16:37:31.38 [WARN] [rules] Failed to load Toolchain token from env var 'TOOLCHAIN_AUTH_TOKEN'. Please make sure the env var is set in your environment.
--
16:39:35 Use `*ToolchainSetup.rules()` instead.
16:40:36 16:40:36.06 [WARN] [rules] Failed to load Toolchain token from env var 'TOOLCHAIN_AUTH_TOKEN'. Please make sure the env var is set in your environment.
--
16:41:29 Use `*ToolchainSetup.rules()` instead.
16:42:31 16:42:31.15 [WARN] [rules] Failed to load Toolchain token from env var 'TOOLCHAIN_AUTH_TOKEN'. Please make sure the env var is set in your environment.
--
16:43:02 Use `*ToolchainSetup.rules()` instead.
16:44:04 16:44:04.04 [WARN] [rules] Failed to load Toolchain token from env var 'TOOLCHAIN_AUTH_TOKEN'. Please make sure the env var is set in your environment.
--
16:45:06 Use `*ToolchainSetup.rules()` instead.
16:45:58 16:45:58.20 [WARN] [rules] Failed to load Toolchain token from env var 'TOOLCHAIN_AUTH_TOKEN'. Please make sure the env var is set in your environment.
--
16:46:01 16:46:01.40 [WARN] WorkUnitConverter: Fallback on hard coded config
16:46:01 16:46:01.41 [WARN] [rules] Failed to load Toolchain token from env var 'TOOLCHAIN_AUTH_TOKEN'. Please make sure the env var is set in your environment.
--
16:46:28 Use `*ToolchainSetup.rules()` instead.
16:47:18 16:47:18.50 [WARN] [rules] Failed to load Toolchain token from env var 'TOOLCHAIN_AUTH_TOKEN'. Please make sure the env var is set in your environment.
--
16:47:25 16:47:25.52 [WARN] WorkUnitConverter: Fallback on hard coded config
16:47:25 16:47:25.54 [WARN] [rules] Failed to load Toolchain token from env var 'TOOLCHAIN_AUTH_TOKEN'. Please make sure the env var is set in your environment.
--
16:50:38 16:50:38.08 [INFO] Scheduler initialized.
16:50:39 16:50:39.64 [WARN] [rules] Failed to load Toolchain token from env var 'TOOLCHAIN_AUTH_TOKEN'. Please make sure the env var is set in your environment.
PS C:\Users\John Sirois\Downloads\CI_logs_benjy_slow>

33 * ~30s is 15 minutes of time failing to auth.

polite-garden-50641

10/10/2022, 6:34 PM

hmmm... not sure why this code is called so many times.

polite-garden-50641

10/10/2022, 6:34 PM

👀

enough-analyst-54434

10/10/2022, 6:34 PM

Agreed. The timeout limit also seems high in practice perhaps.

polite-garden-50641

10/10/2022, 6:39 PM

this gets called once (the call is coming from a rule that pants runs):

Copy code

@rule
async def construct_auth_store(
    auth_store_config: AuthStoreOptions,
    global_options: GlobalOptions,
    toolchain_setup: ToolchainSetup,
) -> AuthStore:
    environment = await Get(Environment, EnvironmentRequest(AuthStore.relevant_env_vars(auth_store_config)))
    return AuthStore(
        context="rules",
        options=auth_store_config,
        pants_bin_name=global_options.options.pants_bin_name,
        env=dict(environment),
        repo=toolchain_setup.safe_get_repo_name(),
        base_url=toolchain_setup.base_url,
    )``

polite-garden-50641

10/10/2022, 6:40 PM

this should be called once per pants run. not sure why this is called so many times.

polite-garden-50641

10/10/2022, 6:40 PM

still looking at logs.

polite-garden-50641

10/10/2022, 6:43 PM

there seems to be a lot of pantsd restarts,,, might be due to memory... there is a limited beta of larger GHA instances... I got TC into it late last week (not using it yet) might be worth taking a look for this account too. https://docs.github.com/en/actions/using-github-hosted-runners/using-larger-runners https://github.com/features/github-hosted-runners/signup

happy-kitchen-89482

10/10/2022, 6:44 PM

Yeah, I think the TC thing is a red herring

happy-kitchen-89482

10/10/2022, 6:44 PM

But pantsd being killed is an interesting hypothesis

polite-garden-50641

10/10/2022, 6:44 PM

@enough-analyst-54434 can u send the full log?

Copy code

16:47:25 16:47:25.52 [WARN] WorkUnitConverter: Fallback on hard coded config
16:47:25 16:47:25.54 [WARN] [rules] Failed to load Toolchain token from env var 'TOOLCHAIN_AUTH_TOKEN'. Please make sure the env var is set in your environment.

this race condition is worrisome and I the link benjy sent an hour ago doesn't work anymore.

enough-analyst-54434

10/10/2022, 6:45 PM

I just followed benjys links and downloaded from GH: https://pantsbuild.slack.com/archives/C0D7TNJHL/p1665423775596879?thread_ts=1665423763.385309&cid=C0D7TNJHL

enough-analyst-54434

10/10/2022, 6:46 PM

That link does still work - go to gear icon, download log archive is what I did and just did again.

polite-garden-50641

10/10/2022, 6:47 PM

got it. thanks.

enough-analyst-54434

10/10/2022, 6:49 PM

My technique here was just to browse the logs for big timestamp gaps. The pants re-link pyo3 steps stood out, consistently 1 minutes there - but that's required as we switch PY to the different supported pythons that we need to compile the Rust code against. Next I saw the 30-60s TC Auth gaps to prior lines. Stopped there.

happy-kitchen-89482

10/11/2022, 5:23 AM

The hosted macOS runners have 14 GB of RAM, you’d think that would be plenty

Open in Slack

Previous Next