Блог

Наши сборки bazel иногда зависают и получают тайм-ауты, поэтому мы теряем все журналы сборки, когда виртуальная машина уничтожается. Чтобы найти причину, мы хотим использовать протокол событий сборки, чтобы увидеть, какие правила начали выполняться, но не завершились (обычно это тесты с нехваткой памяти).

Этот график из официальных документов показывает, что события TargetConfigured и TargetCompleted являются единственными событиями между началом и завершением правила.

Но на самом деле bazel настраивает все цели одновременно, поэтому мы не можем просто вычесть TargetCompleted время из TargetConfigured времени.

Более того, оба события не содержат никаких временных меток. Вот файл события сборки из образца репозитория (усеченный):

     {"id":{"targetConfigured":{"label":"//:B"}},"children":[{"targetCompleted":{"label":"//:B","configuration":{"id":"f157fdcaf05e7672fa1bf535fbb2c3edb004ce9e9a7f6d84d9bf031454e2fb64"}}}],"configured":{"targetKind":"java_binary rule","tag":["__JAVA_RULES_MIGRATION_DO_NOT_USE_WILL_BREAK__"]}}
    {"id":{"targetConfigured":{"label":"//:main"}},"children":[{"targetCompleted":{"label":"//:main","configuration":{"id":"f157fdcaf05e7672fa1bf535fbb2c3edb004ce9e9a7f6d84d9bf031454e2fb64"}}}],"configured":{"targetKind":"java_library rule","tag":["__JAVA_RULES_MIGRATION_DO_NOT_USE_WILL_BREAK__"]}}
    {"id":{"targetConfigured":{"label":"//:step1"}},"children":[{"targetCompleted":{"label":"//:step1","configuration":{"id":"f157fdcaf05e7672fa1bf535fbb2c3edb004ce9e9a7f6d84d9bf031454e2fb64"}}}],"configured":{"targetKind":"genrule rule"}}
    {"id":{"progress":{"opaqueCount":2}},"children":[{"progress":{"opaqueCount":3}},{"namedSet":{"id":"0"}}],"progress":{"stderr":"ru001b[1Au001b[Ku001b[32mAnalyzing:u001b[0m 3 targets (0 packages loaded, 0 targets configured)nru001b[1Au001b[Ku001b[32mINFO: u001b[0mAnalyzed 3 targets (0 packages loaded, 0 targets configured).nnru001b[1Au001b[Ku001b[32mINFO: u001b[0mFound 3 targets...nnru001b[1Au001b[Ku001b[32m[0 / 1]u001b[0m [Prepa] BazelWorkspaceStatusAction stable-status.txtn"}}
    {"id":{"workspaceStatus":{}},"workspaceStatus":{"item":[{"key":"BUILD_EMBED_LABEL"},{"key":"BUILD_HOST","value":"mtymchuk"},{"key":"BUILD_TIMESTAMP","value":"1598888970"},{"key":"BUILD_USER","value":"mikhailtymchuk"}]}}
    {"id":{"namedSet":{"id":"0"}},"namedSetOfFiles":{"files":[{"name":"B.jar","uri":"file:///private/var/tmp/_bazel_mikhailtymchuk/3bd90847b9f03e9e5c46f99d542eb754/execroot/__main__/bazel-out/darwin-fastbuild/bin/B.jar","pathPrefix":["bazel-out","darwin-fastbuild","bin"]},{"name":"B","uri":"file:///private/var/tmp/_bazel_mikhailtymchuk/3bd90847b9f03e9e5c46f99d542eb754/execroot/__main__/bazel-out/darwin-fastbuild/bin/B","pathPrefix":["bazel-out","darwin-fastbuild","bin"]}]}}
    {"id":{"targetCompleted":{"label":"//:B","configuration":{"id":"f157fdcaf05e7672fa1bf535fbb2c3edb004ce9e9a7f6d84d9bf031454e2fb64"}}},"completed":{"success":true,"outputGroup":[{"name":"default","fileSets":[{"id":"0"}]}],"tag":["__JAVA_RULES_MIGRATION_DO_NOT_USE_WILL_BREAK__"],"importantOutput":[{"name":"B.jar","uri":"file:///private/var/tmp/_bazel_mikhailtymchuk/3bd90847b9f03e9e5c46f99d542eb754/execroot/__main__/bazel-out/darwin-fastbuild/bin/B.jar","pathPrefix":["bazel-out","darwin-fastbuild","bin"]},{"name":"B","uri":"file:///private/var/tmp/_bazel_mikhailtymchuk/3bd90847b9f03e9e5c46f99d542eb754/execroot/__main__/bazel-out/darwin-fastbuild/bin/B","pathPrefix":["bazel-out","darwin-fastbuild","bin"]}]}}
    {"id":{"progress":{"opaqueCount":3}},"children":[{"progress":{"opaqueCount":4}},{"namedSet":{"id":"1"}}],"progress":{}}
    {"id":{"namedSet":{"id":"1"}},"namedSetOfFiles":{"files":[{"name":"libmain.jar","uri":"file:///private/var/tmp/_bazel_mikhailtymchuk/3bd90847b9f03e9e5c46f99d542eb754/execroot/__main__/bazel-out/darwin-fastbuild/bin/libmain.jar","pathPrefix":["bazel-out","darwin-fastbuild","bin"]}]}}
    {"id":{"targetCompleted":{"label":"//:main","configuration":{"id":"f157fdcaf05e7672fa1bf535fbb2c3edb004ce9e9a7f6d84d9bf031454e2fb64"}}},"completed":{"success":true,"outputGroup":[{"name":"default","fileSets":[{"id":"1"}]}],"tag":["__JAVA_RULES_MIGRATION_DO_NOT_USE_WILL_BREAK__"],"importantOutput":[{"name":"libmain.jar","uri":"file:///private/var/tmp/_bazel_mikhailtymchuk/3bd90847b9f03e9e5c46f99d542eb754/execroot/__main__/bazel-out/darwin-fastbuild/bin/libmain.jar","pathPrefix":["bazel-out","darwin-fastbuild","bin"]}]}}
    {"id":{"progress":{"opaqueCount":4}},"children":[{"progress":{"opaqueCount":5}},{"namedSet":{"id":"2"}}],"progress":{}}
    {"id":{"namedSet":{"id":"2"}},"namedSetOfFiles":{"files":[{"name":"step1_output.txt","uri":"file:///private/var/tmp/_bazel_mikhailtymchuk/3bd90847b9f03e9e5c46f99d542eb754/execroot/__main__/bazel-out/darwin-fastbuild/bin/step1_output.txt","pathPrefix":["bazel-out","darwin-fastbuild","bin"]}]}}
    {"id":{"targetCompleted":{"label":"//:step1","configuration":{"id":"f157fdcaf05e7672fa1bf535fbb2c3edb004ce9e9a7f6d84d9bf031454e2fb64"}}},"completed":{"success":true,"outputGroup":[{"name":"default","fileSets":[{"id":"2"}]}],"importantOutput":[{"name":"step1_output.txt","uri":"file:///private/var/tmp/_bazel_mikhailtymchuk/3bd90847b9f03e9e5c46f99d542eb754/execroot/__main__/bazel-out/darwin-fastbuild/bin/step1_output.txt","pathPrefix":["bazel-out","darwin-fastbuild","bin"]}]}}
  

Итак, возможно ли извлечь время начала целевой сборки из протокола событий сборки (или с помощью другого метода)?

На консоли, если это поможет, вы сможете получить эту информацию, объединяющую --subcommands (или -s ), которая выводит команды по мере их выполнения. И --show_timestamps который добавляет временные метки ко всем отправляемым сообщениям.

Это не то же самое, о чем вы просите (я не уверен, что добавление времени для построения протокола событий может быть тривиально достигнуто только с помощью конфигурации), но это может помочь с поиском отладки.