Repository: bazelbuild/bazel
Issue: Show debug information about multiplex worker vs regular persistent worker
Labels: type: feature request
P3
team-Local-Exec

### Description of the problem / feature request:

Currently when we replace our persistent worker with [multiplex worker](https://docs.bazel.build/versions/master/multiplex-worker.html), it is unclear which one is being used. `--worker_verbose` shows "Create new ... worker (id #)", but does not display the debug information for multiplex worker.

### Feature requests: what underlying problem are you trying to solve with this feature?

Add additional debug information for better developer experience.

### Any other information, logs, or outputs that you want to share?

It sounds to me we could add additional information in [WorkerKey](https://github.com/bazelbuild/bazel/blob/8c96c0614684243b0a51d0ad8ddc27b0258b4af1/src/main/java/com/google/devtools/build/lib/worker/WorkerKey.java) and then print this debug information in [WorkerFactory](https://github.com/bazelbuild/bazel/blob/8c96c0614684243b0a51d0ad8ddc27b0258b4af1/src/main/java/com/google/devtools/build/lib/worker/WorkerFactory.java)?

Issue comments:
@borkaehw @SrodriguezO 
Sounds like a good suggestion. I will check if I have bandwidth in the following few weeks. Anyone is welcome to implement this as well. Thanks.

Pull request review comments:
It looks like a bad idea. Can someone help?
Yes, I don't think this will work (reliably), because the WorkerSpawnRunner instance is shared for all worker strategy executions (multiplex and non-multiplex). I think this might cause the name of all running worker actions to change to "multiplex-worker" or "worker", depending on whether the most recently executed action was a multiplexed one or not.

I can't immediately think of a good solution for this, except maybe instantiating two WorkerSpawnRunners (one for multiplexed workers, one for non-multiplexed workers). But it might make the code much more complex.

Maybe @susinmotion or @jmmv have a good idea.
What about appending 'multiplex' to the existing name of the worker if it's multiplex?
I'm also pretty happy with the logging only solution... what do you think?
I think the challenge is that when `WorkerSpawnRunner` is constructed, we don't have `Spawn` object to know if it's multiplex or not. I don't think we should set it in `exec()` since `this.supportsMultiplexWorkers` could be undefined in a certain period of time.

@susinmotion do you mean we could undo the change in `getName()`? It's nice to see information when build is in progress though, like
```
<Mnemonic> <Target> 10s multiplex-worker
```

I also notice the message is generated in `UiStateTracker.java`. Is there anything we could do there?
Yes, I did mean undoing the change in getName(), but I also see why that'd be nice info to have.
Let me take a closer look!
What we care about is the name that is used for logging, right?

If so, why not just change the `context.report()` calls in this file to specify the exec-specific name instead of calling `getName()`? They all happen within `exec()`, so at that point we have the right context information.
Sounds like a great idea. Just force-pushed, please take another look.
nit: Should be something like `Returns a user-friendly name for this worker type.`

https://google.github.io/styleguide/javaguide.html#s7.2-summary-fragment
This logic is duplicated in `WorkerKey`. Maybe it can be reused?
nit: This name is a bit confusing given that the return value may not be related to multiplexing at all. Maybe `getNameForReporting` or something? And add a docstring to indicate what this does and why it's separate from `getName`.
Done.
Good idea, done.
Sounds reasonable. I think we have no choice but to keep the logic in `WorkerSpawnRunner` since there is no `WorkerKey` yet when we call the first `context.report()`. But in order to get rid of the duplicate logic, we will have to use a new member variable.

Some explanation of design choices:
1. We could replace the second `context.report()` by
```
context.report(ProgressStatus.EXECUTING, key.getWorkerTypeName());
```
But I like it to be consistent calling the same function `getNameForReporting()` in the same file. What do you think?

2. It looks like `Spawns.supportsMultiplexWorkers(spawn)` has been called multiple times in `WorkerSpawnRunner`. We could store it in a variable in `exec()` and pass it all the way down to `actuallyExec()` and `execInWorker()`. It may look cleaner. If you like it, what would be the variable name? `isSupportsMultiplexWorkers`?
What do you think?
This comment doesn't make a lot of sense here. Where do these magic strings come from? If they are important, they should be part of the docstring. And if they must be these specific values, there should be some validation. I would remove this.
Have a static function `WorkerKey#makeWorkerTypeName(String name)` that builds the name, and then call it from wherever you need. No need for member fields.
Thanks, I think it will work. Just to verify, would the function be `WorkerKey#makeWorkerTypeName(boolean proxied)` instead? Passing `String name` to the function doesn't make sense to me, would you mind to elaborate more?
I assume `boolean` makes more sense, just updated. Let me know if you have different thought.
This is computed twice in this function. Add a `proxiedKey` local variable to reuse the result?
I think it'd be better if this took a key as input instead of a boolean, given that the input seems to always come from a key.

But humm... hold on. Given that `WorkerKey` knows whether it's proxied or not already, shouldn't this be a `getWorkerTypeName` member function without arguments?
> given that the input seems to always come from a key

Not always, the input on this line comes from `Spawn`.
https://github.com/bazelbuild/bazel/pull/10732/files#diff-4ebed75948b31f1a40fc7f782b6d31ceR127

I think since this is a static function, we don't always have the information about proxy.

Like on the same line https://github.com/bazelbuild/bazel/pull/10732/files#diff-4ebed75948b31f1a40fc7f782b6d31ceR127, we can only tell by passing argument to the static function.

If we prefer to take a key as argument, I would like to know what would the key look like. Previously you suggested `String name`, what is a `name`?
I assume you meant the entire `WorkerKey.makeWorkerTypeName(key.getProxied())` statement, not just the `key.getProxied()`, since `key.getProxied()` is used three times in this functoin.

Let me know if you have more concerns. Thanks.
All usages of `makeWorkerTypeName` are of the form: `WorkerKey.makeWorkerTypeName(key.getProxied())`, which is a very strange way of saying `key.getProxiedWorkerTypeName()`.

There is only once exception, which is `WorkerKey.makeWorkerTypeName(Spawns.supportsMultiplexWorkers(spawn))`. Maybe that one just needs special-casing: make the two strings constants and duplicate the conditional at that call site? Or add a `WorkerKey.getProxiedWorkerTypeName` member function that calls the static `makeWorkerTypeName`?

I guess it doesn't matter much and any of these "solutions" are actually worse. So I think this is good enough; can't see of an easy way to handle this single corner case.
Sounds good, thanks! Let's keep it in mind, I am happy to improve this when we have better solution.

Patch that resolved the issue:
diff --git a/src/main/java/com/google/devtools/build/lib/worker/WorkerFactory.java b/src/main/java/com/google/devtools/build/lib/worker/WorkerFactory.java
index be835737dfa77f..7e879f1afbb2a5 100644
--- a/src/main/java/com/google/devtools/build/lib/worker/WorkerFactory.java
+++ b/src/main/java/com/google/devtools/build/lib/worker/WorkerFactory.java
@@ -54,8 +54,9 @@ public void setOptions(WorkerOptions workerOptions) {
   @Override
   public Worker create(WorkerKey key) throws Exception {
     int workerId = pidCounter.getAndIncrement();
+    String workTypeName = WorkerKey.makeWorkerTypeName(key.getProxied());
     Path logFile =
-        workerBaseDir.getRelative("worker-" + workerId + "-" + key.getMnemonic() + ".log");
+        workerBaseDir.getRelative(workTypeName + "-" + workerId + "-" + key.getMnemonic() + ".log");
 
     Worker worker;
     boolean sandboxed = workerOptions.workerSandboxing || key.mustBeSandboxed();
@@ -77,9 +78,10 @@ public Worker create(WorkerKey key) throws Exception {
       reporter.handle(
           Event.info(
               String.format(
-                  "Created new %s %s worker (id %d), logging to %s",
+                  "Created new %s %s %s (id %d), logging to %s",
                   sandboxed ? "sandboxed" : "non-sandboxed",
                   key.getMnemonic(),
+                  workTypeName,
                   workerId,
                   logFile)));
     }
@@ -89,7 +91,7 @@ public Worker create(WorkerKey key) throws Exception {
   Path getSandboxedWorkerPath(WorkerKey key, int workerId) {
     String workspaceName = key.getExecRoot().getBaseName();
     return workerBaseDir
-        .getRelative("worker-" + workerId + "-" + key.getMnemonic())
+        .getRelative(WorkerKey.makeWorkerTypeName(key.getProxied()) + "-" + workerId + "-" + key.getMnemonic())
         .getRelative(workspaceName);
   }
 
@@ -110,7 +112,7 @@ public void destroyObject(WorkerKey key, PooledObject<Worker> p) throws Exceptio
       reporter.handle(
           Event.info(
               String.format(
-                  "Destroying %s worker (id %d)", key.getMnemonic(), p.getObject().getWorkerId())));
+                  "Destroying %s %s (id %d)", key.getMnemonic(), WorkerKey.makeWorkerTypeName(key.getProxied()), p.getObject().getWorkerId())));
     }
     p.getObject().destroy();
   }
@@ -126,8 +128,8 @@ public boolean validateObject(WorkerKey key, PooledObject<Worker> p) {
       StringBuilder msg = new StringBuilder();
       msg.append(
           String.format(
-              "%s worker (id %d) can no longer be used, because its files have changed on disk:",
-              key.getMnemonic(), worker.getWorkerId()));
+              "%s %s (id %d) can no longer be used, because its files have changed on disk:",
+              key.getMnemonic(), WorkerKey.makeWorkerTypeName(key.getProxied()), worker.getWorkerId()));
       TreeSet<PathFragment> files = new TreeSet<>();
       files.addAll(key.getWorkerFilesWithHashes().keySet());
       files.addAll(worker.getWorkerFilesWithHashes().keySet());
diff --git a/src/main/java/com/google/devtools/build/lib/worker/WorkerKey.java b/src/main/java/com/google/devtools/build/lib/worker/WorkerKey.java
index ab96192d18105a..5aa7bc70c0bab3 100644
--- a/src/main/java/com/google/devtools/build/lib/worker/WorkerKey.java
+++ b/src/main/java/com/google/devtools/build/lib/worker/WorkerKey.java
@@ -110,6 +110,15 @@ public boolean getProxied() {
     return proxied;
   }
 
+  /** Returns a user-friendly name for this worker type. */
+  public static String makeWorkerTypeName(boolean proxied) {
+    if (proxied) {
+      return "multiplex-worker";
+    } else {
+      return "worker";
+    }
+  }
+
   @Override
   public boolean equals(Object o) {
     if (this == o) {
diff --git a/src/main/java/com/google/devtools/build/lib/worker/WorkerSpawnRunner.java b/src/main/java/com/google/devtools/build/lib/worker/WorkerSpawnRunner.java
index a11fb631f98b3e..580151d244e496 100644
--- a/src/main/java/com/google/devtools/build/lib/worker/WorkerSpawnRunner.java
+++ b/src/main/java/com/google/devtools/build/lib/worker/WorkerSpawnRunner.java
@@ -124,7 +124,7 @@ public SpawnResult exec(Spawn spawn, SpawnExecutionContext context)
       return fallbackRunner.exec(spawn, context);
     }
 
-    context.report(ProgressStatus.SCHEDULING, getName());
+    context.report(ProgressStatus.SCHEDULING, WorkerKey.makeWorkerTypeName(Spawns.supportsMultiplexWorkers(spawn)));
     return actuallyExec(spawn, context);
   }
 
@@ -335,7 +335,7 @@ private WorkResponse execInWorker(
 
       try (ResourceHandle handle =
           resourceManager.acquireResources(owner, spawn.getLocalResources())) {
-        context.report(ProgressStatus.EXECUTING, getName());
+        context.report(ProgressStatus.EXECUTING, WorkerKey.makeWorkerTypeName(key.getProxied()));
         try {
           worker.prepareExecution(inputFiles, outputs, key.getWorkerFilesWithHashes().keySet());
         } catch (IOException e) {


Test patch:
diff --git a/src/test/java/com/google/devtools/build/lib/worker/WorkerKeyTest.java b/src/test/java/com/google/devtools/build/lib/worker/WorkerKeyTest.java
index a0a0fe2feae249..83bbc01ad11e58 100644
--- a/src/test/java/com/google/devtools/build/lib/worker/WorkerKeyTest.java
+++ b/src/test/java/com/google/devtools/build/lib/worker/WorkerKeyTest.java
@@ -48,6 +48,8 @@ public class WorkerKeyTest {
   public void testWorkerKeyGetter() {
     assertThat(workerKey.mustBeSandboxed()).isEqualTo(true);
     assertThat(workerKey.getProxied()).isEqualTo(true);
+    assertThat(WorkerKey.makeWorkerTypeName(false)).isEqualTo("worker");
+    assertThat(WorkerKey.makeWorkerTypeName(true)).isEqualTo("multiplex-worker");
     // Hash code contains args, env, execRoot, and mnemonic.
     assertThat(workerKey.hashCode()).isEqualTo(322455166);
   }
diff --git a/src/test/shell/integration/bazel_worker_multiplexer_test.sh b/src/test/shell/integration/bazel_worker_multiplexer_test.sh
index d64c3ec097c26b..564bffea232692 100755
--- a/src/test/shell/integration/bazel_worker_multiplexer_test.sh
+++ b/src/test/shell/integration/bazel_worker_multiplexer_test.sh
@@ -371,8 +371,8 @@ EOF
 
   bazel build --worker_quit_after_build :hello_world_1 &> $TEST_log \
     || fail "build failed"
-  expect_log "Created new ${WORKER_TYPE_LOG_STRING} Work worker (id [0-9]\+)"
-  expect_log "Destroying Work worker (id [0-9]\+)"
+  expect_log "Created new ${WORKER_TYPE_LOG_STRING} Work multiplex-worker (id [0-9]\+)"
+  expect_log "Destroying Work multiplex-worker (id [0-9]\+)"
   expect_log "Build completed, shutting down worker pool..."
 }
 
@@ -389,9 +389,9 @@ EOF
   bazel build --worker_quit_after_build :hello_world_1 &> $TEST_log \
     || fail "build failed"
 
-  expect_log "Created new ${WORKER_TYPE_LOG_STRING} Work worker (id [0-9]\+)"
+  expect_log "Created new ${WORKER_TYPE_LOG_STRING} Work multiplex-worker (id [0-9]\+)"
 
-  worker_log=$(egrep -o -- 'logging to .*/b(azel|laze)-workers/worker-[0-9]-Work.log' "$TEST_log" | sed 's/^logging to //')
+  worker_log=$(egrep -o -- 'logging to .*/b(azel|laze)-workers/multiplex-worker-[0-9]-Work.log' "$TEST_log" | sed 's/^logging to //')
 
   [ -e "$worker_log" ] \
     || fail "Worker log was not found"
@@ -420,8 +420,8 @@ EOF
   bazel build --worker_quit_after_build :hello_world &> $TEST_log \
     || fail "build failed"
 
-  expect_not_log "Created new ${WORKER_TYPE_LOG_STRING} Work worker (id [0-9]\+)"
-  expect_not_log "Destroying Work worker (id [0-9]\+)"
+  expect_not_log "Created new ${WORKER_TYPE_LOG_STRING} Work multiplex-worker (id [0-9]\+)"
+  expect_not_log "Destroying Work multiplex-worker (id [0-9]\+)"
 
   # WorkerSpawnStrategy falls back to standalone strategy, so we still expect the output to be generated.
   [ -e "$BINS/hello_world.out" ] \
@@ -460,12 +460,12 @@ EOF
   bazel build :hello_clean &> $TEST_log \
     || fail "build failed"
   assert_equals "hello clean" "$(cat $BINS/hello_clean.out)"
-  expect_log "Created new ${WORKER_TYPE_LOG_STRING} Work worker (id [0-9]\+)"
+  expect_log "Created new ${WORKER_TYPE_LOG_STRING} Work multiplex-worker (id [0-9]\+)"
 
   bazel clean &> $TEST_log \
     || fail "clean failed"
   expect_log "Clean command is running, shutting down worker pool..."
-  expect_log "Destroying Work worker (id [0-9]\+)"
+  expect_log "Destroying Work multiplex-worker (id [0-9]\+)"
 }
 
 function test_crashed_worker_causes_log_dump() {