The anonymous-telemetry subsystem ~doubles Pants no-op latency when non-async callbacks are enabled.

[jsirois]

$ hyperfine -w 2 './pants --no-anonymous-telemetry-enabled -V' './pants -V'
Benchmark #1: ./pants --no-anonymous-telemetry-enabled -V
  Time (mean ± σ):     697.6 ms ±   9.0 ms    [User: 486.5 ms, System: 43.7 ms]
  Range (min … max):   684.8 ms … 710.4 ms    10 runs
 
Benchmark #2: ./pants -V
  Time (mean ± σ):      1.317 s ±  0.087 s    [User: 485.8 ms, System: 50.3 ms]
  Range (min … max):    1.257 s …  1.553 s    10 runs
 
Summary
  './pants --no-anonymous-telemetry-enabled -V' ran
    1.89 ± 0.13 times faster than './pants -V'

Since user and system times did not budge, this is all IO latency.

[jsirois]

There is a tangle of issues making this slow.

Even though we mark the anonymous telemetry workunit callback as having an async finish:

pants/src/python/pants/goal/anonymous_telemetry.py

Lines 81 to 84 in 2b412db

	@property
	def can_finish_async(self) -> bool:
	# Because we don't log anything, it's safe to finish in the background.
	return True

We still block on workunit callback completion since there are other callbacks in the system - not all capable of async finish:

pants/src/python/pants/engine/streaming_workunit_handler.py

Lines 273 to 274 in e64cf31

	if self.block_until_complete:
	super().join()

pants/src/python/pants/engine/streaming_workunit_handler.py

Lines 241 to 245 in e64cf31

	# TODO: Have a thread per callback so that some callbacks can always finish async even
	# if others must be finished synchronously.
	self.block_until_complete = not pantsd or any(
	callback.can_finish_async is False for callback in self.callbacks
	)

That aside, the anonymous telemetry callback is not actually asynchronous anyhow since:

pants/src/python/pants/goal/anonymous_telemetry.py

Lines 141 to 143 in 2b412db

	# We don't want to spawn a thread in the engine, and we're
	# already running in a background thread in pantsd.
	mode=Modes.SYNCHRONOUS,

Some added timing measurement shows this join takes ~550ms with telemetry turned on.

[Eric-Arellano]

Are you using BuildSense / Toolchain plugin? If so, that is currently not async, so you are right that it will cause this to be sync.

I use this to disable the plugin:

export PANTS_VERIFY_CONFIG=false
export PANTS_PLUGINS="-['toolchain.pants.plugin==0.7.0']"
export PANTS_BACKEND_PACKAGES="-['toolchain.pants.auth', 'toolchain.pants.buildsense', 'toolchain.pants.common']"

[jsirois]

Are you using BuildSense / Toolchain plugin?

No. See the hyperfine, but the slowdown is isolated with just toggling the --no-anonymous-telemetry-enabled flag.

[jsirois]

And - there is plenty more than the tc plugin in our WorkunitCallback list that is not async.

[Eric-Arellano]

No. See the hyperfine, but the slowdown is isolated with just toggling the --no-anonymous-telemetry-enabled flag.

Yes, but whether BuildSense is enabled impacts if --anonymous-telemetry will be async or not. Note that BuildSense is enabled by default in pantsbuild/pants, so you would have to go out of your way to disable it.

there is plenty more than the tc plugin in our WorkunitCallback list that is not async.

Nack, the only other one should be --stats-log, which is set to be async if the option is not configured. Are you seeing other things making this not true?

--

It would be good to try this again with BuildSense disabled to see the impact when it can complete async. We knew it would impact non-async times - the more important case is when async is possible.

[jsirois]

OK. What you say appears to be true. I am using BuildSense since these are measurements in the Pants repo where that is enabled. So I think my conclusion and this bug still stand. I'll highlight from the tangle I pointed out above:

pants/src/python/pants/engine/streaming_workunit_handler.py

Lines 241 to 245 in e64cf31

	# TODO: Have a thread per callback so that some callbacks can always finish async even
	# if others must be finished synchronously.
	self.block_until_complete = not pantsd or any(
	callback.can_finish_async is False for callback in self.callbacks
	)

That TODO is on-target. Not having it implemented has this real-world impact.

[Eric-Arellano]

Agreed. Although note that the upcoming Toolchain plugin is marked async, so this won't be a problem then.

[stuhood]

#11618 is fixed (and I'll cherrypick it to 2.4.x), so the TC plugin should be unblocked to be async in the next release.

It's possible that when that lands we should close this ticket, and open a new one for the TODO above.

[stuhood]

#12209 will fix this issue: I've updated the title of #10092 to account for the remainder of the above TODO.

[asherf]

When running in CI, and a particular check fails (lint/typecheck) the pants process exits when a non-zero exist code, which causes CI to kill the container and not allowing pantsd to continue to run and allow plugins to complete async.