How to get action results?

[SinOverCos]

I'm trying to debug why certain actions on my remote build is slower.

In the logs I can see something like this:

build.buildfarm.metrics.log.LogMetricsPublisher publishRequestMetadata - 
{
  "operationName": "shard/operations/1984d052-f52d-4a01-8d1c-f451d307c9de",
  "done": true,
  "requestMetadata": {
    "toolDetails": {
      "toolName": "bazel",
      "toolVersion": "6.3.2"
    },
    "actionId": "156090d320e7bda56574431c22b474eb1e8bd1587bd731676e5d2e4c75bebff4",
    "toolInvocationId": "019659db-e52e-46a7-8e19-18fcc553ca3a",
    "correlatedInvocationsId": "7d6ddba7-2916-43d9-818b-ad7533146381",
    "actionMnemonic": "ImageLayer",
    "targetId": "//my:target",
    "configurationId": "47f8144c91ebe12384311a4e8054b45aefc83e3491c35e80bd01367be71f85aa"
  },
  "executeOperationMetadata": {
    "stage": "COMPLETED",
    "actionDigest": {
      "hash": "156090d320e7bda56574431c22b474eb1e8bd1587bd731676e5d2e4c75bebff4",
      "sizeBytes": "144"
    },
    "stdoutStreamName": "shard/operations/1984d052-f52d-4a01-8d1c-f451d307c9de/streams/stdout",
    "stderrStreamName": "shard/operations/1984d052-f52d-4a01-8d1c-f451d307c9de/streams/stderr"
  },
  "executeResponse": {
    "result": {
      "outputFiles": [
        {
          "path": "bazel-out/k8-fastbuild/bin/my/target",
          "digest": {
            "hash": "c8c4dde475316afe54558666eac9eae3cfbc6d09bb6e416a872b8a7cc926299a",
            "sizeBytes": "379176960"
          }
        }
      ],
      "executionMetadata": {
        "worker": "localhost:8981",
        "queuedTimestamp": "2023-10-06T17:54:34.760Z",
        "workerStartTimestamp": "2023-10-06T17:54:34.792Z",
        "workerCompletedTimestamp": "2023-10-06T17:54:42.637Z",
        "inputFetchStartTimestamp": "2023-10-06T17:54:34.792Z",
        "inputFetchCompletedTimestamp": "2023-10-06T17:54:37.295Z",
        "executionStartTimestamp": "2023-10-06T17:54:37.298Z",
        "executionCompletedTimestamp": "2023-10-06T17:54:37.834Z",
        "outputUploadStartTimestamp": "2023-10-06T17:54:37.834Z",
        "outputUploadCompletedTimestamp": "2023-10-06T17:54:42.637Z"
      }
    },
    "status": {}
  }
}

I want to look at this file:

shard/operations/1984d052-f52d-4a01-8d1c-f451d307c9de/streams/stdout

But /tmp/worker/shard/operations is empty:

~> tree /tmp/worker/shard/operations/
/tmp/worker/shard/operations/

0 directories, 0 files

(but I do see it populating while execution is happening, so it's just getting removed (?) at the end).

Interestingly,

~> bazel run //src/main/java/build/buildfarm/tools:bf-find-operations localhost:8980 shard SHA256 | grep 1984d052-f52d-4a01-8d1c-f451d307c9de
shard/operations/1984d052-f52d-4a01-8d1c-f451d307c9de

bf-find-operations can see this operation. I'm just not sure how it's doing that. Me grepping or finding for 1984d052-f52d-4a01-8d1c-f451d307c9de doesn't return any results.

[werkt]

That file is empty. If there were any content there, the ActionResult in the ExecuteResponse would contain either the raw content, or its digest.

The start of information you want to understand is already printed out there:

      "executionMetadata": {
        "worker": "localhost:8981",
        "queuedTimestamp": "2023-10-06T17:54:34.760Z",
        "workerStartTimestamp": "2023-10-06T17:54:34.792Z",
        "workerCompletedTimestamp": "2023-10-06T17:54:42.637Z",
        "inputFetchStartTimestamp": "2023-10-06T17:54:34.792Z",
        "inputFetchCompletedTimestamp": "2023-10-06T17:54:37.295Z",
        "executionStartTimestamp": "2023-10-06T17:54:37.298Z",
        "executionCompletedTimestamp": "2023-10-06T17:54:37.834Z",
        "outputUploadStartTimestamp": "2023-10-06T17:54:37.834Z",
        "outputUploadCompletedTimestamp": "2023-10-06T17:54:42.637Z"
      }

Line up those timestamps, and you find that your operation took 2.4s to fetch, ~500ms to execute, and 4.8s to upload outputs. If you were running this against a very recent commit, you may have been subject to a revert that @80degreeswest rolled out in #1489, and I recommend you post what version of buildfarm you're running against in general if we're to pursue performance further.

[SinOverCos]

Thanks @werkt

Is there useful debug information inside /tmp/worker/shard/operations? It seems that it gets deleted after the operation ends (which makes sense).

I'm trying to debug an action that does have a much longer gap between executionStartTimestamp and executionCompletedTimestamp when executing remotely vs. locally. I'm trying to get more debug information about that specific command.

        "executionStartTimestamp":        "2023-10-13T13:21:15.991Z",
        "executionCompletedTimestamp":    "2023-10-13T13:21:24.665Z",

• when executing locally, this libgoogle_longrunning_operations_proto-speed.jar takes closer to 500ms vs. 5s

https://pastebin.com/FG8DDu9i