we're trying to debug some performance issues with running PEXs, and this is leading us into questions about graph and process_execution code that I'd like to get @witty-crayon-22786’s and maybe @average-vr-56795’s input on

I doubt that all of that* is overhead, rather than just "contention"

this is more about, what information is helpful to show to pants users running the v2 UI normally

I think this is indeed contention

Ok

I think that we have the intuition that what the v2 UI actions pane should be indicating, is what work items are running right now

The heavy hitters stuff is pretty naive .. if you wanted special handling for processes, could do that with a new method on the Node trait, for example

We're also not sure what, if anything,

process_execution_local_parallelism

is doing in practice.

specifically it looks like that option is getting set as the

bound

for

BoundedCommandRunner

, but I'm not sure what that type is meant to do to begin with

It's limiting the number of subprocesses we'll spawn at once

I mean actual end-to-end real and user

time

If you only have 2 cores, increasing it a lot beyond 2 won't do much

I have 4 cores

What Greg said

Hmm, so I'm seeing the same end-to-end user/real/sys time whatever I set that to.

so I think that implies that

BoundedCommandRunner

might not be the limiting factor in the use case we're debugging

It is only for processes

Right

And it defaults to "number of cores"... 2 was just an example

@witty-crayon-22786 one thing that i don't have a great sense of is how the futures executor that pants uses maps spawned futures to actual threads

but the time here is completely dominated by long-running EPRs (requirement pex resolution)

my understanding is that the details of this are something that the futures library basically takes care of, but can be fine-tuned

Yes, we're using the tokio runtime... No, it can't really be fine tuned afaik

so that's calling stuff in our

task_executor

crate, and that's proxying to

tokio

?

"all" of the futures might effectively be executing concurrently

so I think this still comes down the duration of time between when a future was scheduled and when it runs not being a helpful thing to use to decide what to display to users

@happy-kitchen-89482: if all of the time is in EPR, then there is your answer... Would tease that apart by adding debug output or additional workunits in the LocalCommandRunner

but I'm not sure what is useful

So in terms of user experience, we probably only want to display heavy hitters that have actually been spawned (so their number would never exceed process_execution_local_parallelism, which is also probably what the user expects)

@hundreds-breakfast-49010: probably none of it. If your time is in EPR, add more debug output to LocalProcessRunner

we're not just trying to debug our own workflow, we're also trying to think about how to construct a v2 UI output that is useful for end users

Could add something to the node trait to "check whether the node should be rendered/considered" or something

sure, but that also means that the v2 UI output is misleading, for us as well as end users

Understood... But scheduling is measured in the nanoseconds. So if you are seeing delays that make it look like processes are taking a long time, the most likely thing is that... They are taking a long time

creating the future is quick, but the delay between when that future is created and when it actually runs might not be, depending on what else the engine is doing

Sure. Priorities is all I'm saying.

@witty-crayon-22786 re "they are taking a long time" - the processes in question take ~60 seconds each, when we run on a single target. When we run on 10 targets we see a total runtime of somewhat under 600 seconds, so it looks like we're not getting much parallelism benefit. Could be contention, could be something else. That remains to debug. But putting that to one side, what we display to the user is that one process took 60 seconds, one took 120 seconds, and so on (the numbers aren't so precise, but you get the idea). So this is bad UX IMO.

ah, got it. sure.

Does that make sense?

yep.

@witty-crayon-22786 does it make sense to rewrite the heavy_hitters code to only start counting time from when this

run

call happens: https://github.com/pantsbuild/pants/blob/master/src/rust/engine/graph/src/entry.rs#L265

Changing that UX would also make the performance issue easier to debug, as we could see at a glance what is truly running.

@hundreds-breakfast-49010: no... it's still async code

hm yeah

one approach would be to remove timing for any nodes that are truly async

those are the things that are likely to take a long time in any case

that's roughly what i was suggesting, yea.

I agree with Stu that the interface shouldn’t be used to gauge performance bottlenecks, and I see its primary goal to be “make sure the user sees that we’re doing something”. Ideally, the output should change fast enough that the user can’t actually read it for a lot of operations. However, if this is a priority for you folks, the place where we have decided that we’ll start recording real duration time is in the implementations of

WrappedNode::run

. In particular, for EPRs we use the v2 notion of

workunits

for that. While I don’t think we can use workunits for this (because they are recorded at the end of an EPRs execution), we can probably implement something similar to that for heavy_hitters. This could be as easy as keeping a

Map<UserDisplayNameForNode, RealStartTime>

in the

Context

, or maybe `Session`: - Nodes would optionally add themselves to that map as part of executing the Future returned by the

run

method. - We would only render things from that map. - At the end of the execution of a node, we could make it remove itself from the map. Alternatively, we could create another method in the trait

WrappedNode

, something like

run_impl

, and rename all the current implementations of

run

to

run_impl

. Then, we can implement

run

as a method in the trait that will do all the map finagling for us, something like (totally bogus syntax):

fn run(self, context: Context) -> NodeFuture<Value> {
  future::create(move |_| { // register start time now in context, if I have a user_readable_name })
  .and_then(|_| {
    self.run(context)
  })
  .inspect(|_| { // de-register myself from the map })
}

This way, we leave

run

unchanged, and we center this recording of times to one particular function.

(Thank you @red-balloon-89377 for taking the time to write this all out!)

@red-balloon-89377: that runs afoul of what i was mentioning to Greg above though: moving the tracking within the async code won't really affect this

Hmmm, that’s fair. I guess with EPRs specifically, each relevant

CommandRunner

does have to decide when something is started.

one issue that occurs to me

afaik that was just an arbitrary heuristic. In an ideal world, we would display exactly what each CPU was running at that time. I don’t really think that’s practical though.

I haven’t read through this whole thread - should I, or did this get sufficiently resolved? 🙂

I haven’t read through this whole thread - should I, or did this get sufficiently resolved?

@average-vr-56795 If you have the time to spare, it would help to get your input. tl;dr we’ve been finding that resolving the requirements Pex is really slow in V2. One of the problems is that we believe

--v2-ui

reports timing in a way that doesn’t exactly reflect reality and makes the user believe things are slower than they really are. We’re trying to think of a way to improve the timing output for

--v2-ui

Cool, I’ll catch up after reviewing Greg’s PR 🙂

Yea, definitely.

@average-vr-56795 I think that some of the code around Workunits already does this or at least attempts to do this correctly

Yeah, that all sounds reasonable 🙂