Android11编译内核实时输出日志

安卓编译内核时如何让日志实时输出？

[android 11]
[qcom 8155 gvmq]
[ninja 1.10.2.git]
[android ninja 1.9.0.git]

背景

做开发 make bootimage 编译时，需要十多二十分钟，期间有很长段时间无日志实时输出，看起来像是编译完才一下输出，
这个等待的时间实在太长了，你也不知道究竟是出问题了？有没有编译？卡住了？还是啥，所以就想让日志实时输出下。

调查过程

make -> ninja

想从编译系统入手的，但一时又没头绪，就顺着make看看，

make bootimage -j4
  + make() build/envsetup.sh
    + _wrap_build $(get_make_command "$@") "$@"
      + _wrap_build build/soong/soong_ui.bash --make-mode bootimage -j4
        + exec "$(getoutdir)/soong_ui" "$@"
          + out/soong_ui --make-mode bootimage -j4

上一步的 soong_ui 是由

build/soong/cmd/soong_ui/Android.bp:16:    name: "soong_ui",

生成, 所以可继续看soong_ui流程:

soong_ui(build/soong/cmd/soong_ui/main.go)
  + main()
    + c, args := getCommand(os.Args)
    |  + for _, c := range commands {
    |  |   if inList(makeModeFlagName, args)
    |  +     return &c, args[1:]
    |    // 也就是说getCommand()返回的是如下方法
    |    /*
    |     var commands []command = []command{
    |     {
    |             flag:        makeModeFlagName,
    |             description: "build the modules by the target name (i.e. soong_docs)",
    |             config: func(ctx build.Context, args ...string) build.Config {
    |                     return build.NewConfig(ctx, args...)
    |             },
    |             stdio: stdio,
    |             run:   make, // run方法
    |     }, {
    |     */
    |
    +  c.run(buildCtx, config, args, logsDir) //即make()
        + make()
          + build.Build(ctx, config, toBuild)
            + Build() (build/soong/ui/build/build.go)
              + runNinja(ctx, config)
                + runNinja (build/soong/ui/build/ninja.go)
                    + fifo := filepath.Join(config.OutDir(), ".ninja_fifo")
                    | nr := status.NewNinjaReader(ctx, ctx.Status.StartTool(), fifo)
                    | // prebuilts/build-tools/linux-x86/bin/ninja
                    | executable := config.PrebuiltBuildTool("ninja")
                    | args := []string{
                    |         "-d", "keepdepfile",
                    |         "-d", "keeprsp",
                    |         "--frontend_file", fifo,
                    | }
                    |
                    | args = append(args, config.NinjaArgs()...)
                    | // 其它参数省略……
                    | // Command 定义在 build/soong/ui/build/exec.go
                    | // 注意其中的 executable，即为运行prebuilts的ninja
                    + cmd := Command(ctx, config, "ninja", executable, args...)
                    |
                    + ctx.Status.Status("Starting ninja...")
                    + cmd.RunAndStreamOrFatal() // 最终会运行命令，分析略

对soong_ui的分析，发现最终通过封装的Command(...), 最终执行 prebuilts/build-tools/linux-x86/bin/ninja ,

加上参数，我们最终可以将 make bootimage -j 转化为命令

prebuilts/build-tools/linux-x86/bin/ninja -d keepdepfile -d keeprsp --frontend_file out/.ninja_fifo bootimage -j 4 -f out/combined-msmnile_gvmq.ninja -w dupbuild=err -w missingdepfile=err

需要说明的是，--frontend_file 是安卓添加的特性，原始的ninja是没有这个功能的，

其目的是将输出重定向为流存储，

其实现主要是通过pipe和protobuff, 有兴趣的可以看看，

https://www.cnblogs.com/sande...

4.4. frontend_file参数

官方代码：

https://android.googlesource....

官方Frontend文档：

https://android.googlesource....

总之，我们可以用

prebuilts/build-tools/linux-x86/bin/ninja bootimage -j 4 -f out/combined-msmnile_gvmq.ninja

来编译内核和进行后续实验,

注意：

-f 参数后面的文件 out/combined-msmnile_gvmq.ninja是编译生成的ninja输入文件，各平台不一样，里面可通过subninja包含别的文件

ninja console

用ninja编译发现也是得编译完成才输出日志(这是ninja的特性，一个编译edge完成后才统一输出日志)，

ninja的用法帮助里似乎哪个参数都不能控制日志实时输出。

那怎么办呢？

这时候要么撸代码，要么看文档，要么两者同时进行看有啥发现。

通过查看文档，网上找方法，顺便看/修改/实验代码，最终发现可将pool改为console将日志实时输出，

官网对其描述 https://ninja-build.org/manua...

The console pool
Available since Ninja 1.5.

There exists a pre-defined pool named console with a depth of 1. It has the special property that any task in the pool has direct access to the standard input, output and error streams provided to Ninja, which are normally connected to the user’s console (hence the name) but could be redirected. This can be useful for interactive tasks or long-running tasks which produce status updates on the console (such as test suites).

While a task in the console pool is running, Ninja’s regular output (such as progress status and output from concurrent tasks) is buffered until it completes.

也就是说console pool对交互式或者长期运行任务比较有用，

注意在运行console编译edge时，别的edge也会在后台编译，但是其日志会缓存起来，等console 任务完成后才会输出

那么，

• 如果我们直接用ninja编译，可以找到编译内核的edge，然后添加上console pool即可，

  例如：

out/build-msmnile_gvmq.ninja

 rule rule86890
  description = build $out
  command = /bin/bash -c "echo \"Building the requested kernel..\"; ......
 build out/target/product/msmnile_gvmq/obj/kernel/msm-5.4/arch/arm64/boot/Image: rule86890 ......
+   pool = console

然后运行

prebuilts/build-tools/linux-x86/bin/ninja bootimage -j 4 -f out/combined-msmnile_gvmq.ninja

编译

• 如果是用make bootimage 编译

  安卓会修改生成的out/build-msmnile_gvmq.ninja，就需要在安卓编译时将makefile -> ninja 过程中找到方法，

  通过查看资料

  Android高版本P/Q/R源码编译指南

  https://my.oschina.net/u/3897...

  Kati详解-Android10.0编译系统（五）

  https://blog.csdn.net/mafei85...

得知转换过程是kati完成的，那这个时候继续撸代码？

目前kati得下载源码了，代码里是预编译的了。

还好搜索 grep -rin pool build 时, 发现个 .KATI_NINJA_POOL 很奇怪，照着一实验，果然能达到目的，

所以需要在编译内核的地方加上如下代码:

device/qcom/kernelscripts/kernel_definitions.mk

@@ -292,6 +292,8 @@ $(KERNEL_USR): | $(KERNEL_HEADERS_INSTALL)
        ln -s kernel/$(TARGET_KERNEL) $(KERNEL_SYMLINK); \
        fi

+$(TARGET_PREBUILT_KERNEL): .KATI_NINJA_POOL := console
 $(TARGET_PREBUILT_KERNEL): $(KERNEL_OUT) $(DTC) $(KERNEL_USR)
        echo "Building the requested kernel.."; \
        $(call build-kernel,$(KERNEL_DEFCONFIG),$(KERNEL_OUT),$(KERNEL_MODULES_OUT),$(KERNEL_HEADERS_INSTALL),0,$(TARGET_PREBUILT_INT_KERNEL))

其它

• ninja pool console 代码分析笔记

  源码可从 https://ninja-build.org/ 下载, 我下载时的版本为 1.10.2.git

  当edge使用console时，其会将终端锁住

  src/status.cc
  void StatusPrinter::BuildEdgeStarted(...) {
    ......
    if (edge->use_console())
      printer_.SetConsoleLocked(true);
  }
  
  void LinePrinter::SetConsoleLocked(bool locked) {
    ......
    console_locked_ = locked;
    // 终端解锁时，将缓存的日志输出
    if (!locked) {
      PrintOnNewLine(output_buffer_);
      if (!line_buffer_.empty()) {
        Print(line_buffer_, line_type_);
      }
      output_buffer_.clear();
      line_buffer_.clear();
    }
  }

  如果此时有别的edge输出，会将其日志缓存，等到终端解锁时（console edge完成或者全编译完）再输出

  void LinePrinter::Print(string to_print, LineType type) {
    // 如果终端被锁，输出信息给line_buffer
    if (console_locked_) {
      line_buffer_ = to_print;
      line_type_ = type;
      return;
    }
    ......
  }
  
  void LinePrinter::PrintOrBuffer(const char* data, size_t size) {
    // 如果终端被锁，将输出缓存起来
    if (console_locked_) {
      output_buffer_.append(data, size);
    } else {
      // Avoid printf and C strings, since the actual output might contain null
      // bytes like UTF-16 does (yuck).
      // 否则输出到标准输出
      fwrite(data, 1, size, stdout);
    }
  }
  
  void LinePrinter::PrintOnNewLine(const string& to_print) {
    // 终端被锁，缓存输出
    if (console_locked_ && !line_buffer_.empty()) {
      output_buffer_.append(line_buffer_);
      output_buffer_.append(1, '\n');
      line_buffer_.clear();
    }
    ......
  }

• console和非console日志输出区别？

  从上面来看，console被锁时，日志都会被缓存起来，那使用console的进程是如何做到实时输出的呢？

  答案就是非console的输出日志，标准输出，标准错误被重定向到pipe了，当编译完时才通过pipe读取日志。

  代码笔记：

  main() (src/ninja.cc)
   + real_main(argc, argv);
     + ninja.RunBuild(argc, argv, status)
       + // NinjaMain::RunBuild(...)
       + Builder builder(...
       + if (!builder.Build(&err)) -->
  
  Builder::Build(string* err) (src/build.cc)
    + while (plan_.more_to_do()) {// 执行所有任务
    | + // 1. 执行命令，如果没使用console,将标准输出，标准错误重定向
    | + if (!StartEdge(edge, err))
    | | + if (!command_runner_->StartCommand(edge)) // RealCommandRunner::StartCommand(Edge* edge)
    | |   + subprocs_.Add(command, edge->use_console()) // edge 是否使用console
    | |     + Subprocess *SubprocessSet::Add(...) (src/subprocess-posix.cc)
    | |       + new Subprocess(use_console);
    | |       + if (!subprocess->Start(this, command)) // Subprocess::Start(SubprocessSet* set, const string& command)
    | |         + if (pipe(output_pipe) < 0) // 生成读写pipe
    | |         |   Fatal("pipe: %s", strerror(errno));
    | |         + fd_ = output_pipe[0]; // 读pipe给fd_
    | |         |
    | |         + if (!use_console_) {
    | |         | // 如果没用console，将标准输出，标准错误重定向到写pipe
    | |         +   err = posix_spawn_file_actions_adddup2(&action, output_pipe[1], 1);
    | |         +   err = posix_spawn_file_actions_adddup2(&action, output_pipe[1], 2);
    | |         + }
    | |         |
    | |         | // 创建子进程，执行编译规则里的shell命令，pid_为返回的子进程号
    | |         + err = posix_spawn(&pid_, "/bin/sh", &action, &attr,
    | |                 const_cast<char**>(spawned_args), environ);
    | |
    | | // 2. 等edge执行完，获取日志
    | + if (!command_runner_->WaitForCommand(&result) ||  // RealCommandRunner::WaitForCommand(Result* result)
    | | +    subprocs_.DoWork()
    | | |    + // bool SubprocessSet::DoWork() (subprocess-posix.cc)
    | | |    + for (vector<Subprocess*>::iterator i = running_.begin();
    | | |    |   (*i)->OnPipeReady()
    | | |    |   +  ssize_t len = read(fd_, buf, sizeof(buf)); // 从output_pipe[0] 读日志
    | | |    +   +  buf_.append(buf, len); // 日志给buf_
    | | |
    | | +  result->output = subproc->GetOutput(); //日志给result->output
    | |             + // Subprocess::GetOutput()
    | |             + return buf_; // 返回日志
    | |
    | + // 3. 如果有编译命令完成，根据console锁状态输出/缓存日志
    | + if (!FinishCommand(&result, err))
    | | + // Builder::FinishCommand(CommandRunner::Result* result, string* err)
    | | + status_->BuildEdgeFinished(edge, end_time_millis, result->success(),
    | | |                            result->output); // 日志
    | | | + // StatusPrinter::BuildEdgeFinished(...) (src/status.cc)
    | | | + // 如果是console edge结束，则如之前代码所示，会解锁终端，并输出缓存的日志
    | | | + if (edge->use_console())
    | | | |   printer_.SetConsoleLocked(false);
    | | | |
    | | | + // 提示信息，也就是ninja编译文件里的"description"或者"command"
    | | | + if (!edge->use_console())
    | | | |   PrintStatus(edge, end_time_millis);
    | | | |
    | | | + // 输出或者缓存日志
    | + + + printer_.PrintOnNewLine(final_output);
    + }

• 安卓frontend定制

  frontend前面也提到过，主要是将日志重定向为流，实现采用了Protocol Buffer。

  原生的ninja编译采用console时，其他edge输出会缓存起来，等console pool的edge完成时再一块输出，

  但是因为安卓定制原因，console的edge会和其它edge输出混合。

  其日志读取则在soog-ui侧，并实现了一些比较花样的显示，有兴趣的可以看看。

  代码笔记(1.9.0.git https://android.googlesource....):

  1. 如果参数里有frontend，那么则采用谷歌实现的新类 StatusSerializer()
  // <<ninja>>/src/ninja.cc
  NORETURN void real_main(int argc, char** argv) {
      ....
      if (status == NULL) {
  #ifndef _WIN32
        if (config.frontend != NULL || config.frontend_file != NULL)
          // 新实现
          status = new StatusSerializer(config);
        else
  #endif
          status = new StatusPrinter(config);
      }
  
  2. 编译完成输出日志
  // src/status.cc
  void StatusSerializer::BuildEdgeFinished(Edge* edge, int64_t end_time_millis,
                                           const CommandRunner::Result* result) {
    ninja::Status::EdgeFinished* edge_finished = proto_.mutable_edge_finished();
  
    // id, 结束时间，状态等信息
    edge_finished->set_id(edge->id_);
    edge_finished->set_end_time(end_time_millis);
    edge_finished->set_status(result->status);
    // 日志
    edge_finished->set_output(result->output);
    ...
    Send(); // 序列化日志
  }
  // Send() 其实就是对日志序列化为流
  void StatusSerializer::Send() {
    // Send the proto as a length-delimited message
    WriteVarint32NoTag(out_, proto_.ByteSizeLong());
    proto_.SerializeToOstream(out_); // 序列化
    proto_.Clear();
    out_->flush();
  }
  
  3. 日志读取
  // <<Android 11>>/build/soong/ui/build/ninja.go
  func runNinja(ctx Context, config Config) {
      ......
      fifo := filepath.Join(config.OutDir(), ".ninja_fifo")
      nr := status.NewNinjaReader(ctx, ctx.Status.StartTool(), fifo)
  
  //  build/soong/ui/status/ninja.go
  func NewNinjaReader(ctx logger.Logger, status ToolStatus, fifo string) *NinjaReader {
      ...
      n := &NinjaReader{...
      }
  
      go n.run()
      ...
  }
  
  func (n *NinjaReader) run() {
          ...
          // 打开 fifo
          f, err := os.Open(n.fifo)
      ...
      // bufio方式读
      r := bufio.NewReader(f)
      ...
      for {...
          // 读取长度
          size, err := readVarInt(r)
          ...
          // 读size个长度数据给buf
          buf := make([]byte, size)
          _, err = io.ReadFull(r, buf)
          ...
          // 反序列化
          msg := &ninja_frontend.Status{}
          err = proto.Unmarshal(buf, msg)
          ...
          // 根据反序列化信息做不同操作
          if msg.TotalEdges != nil {
              n.status.SetTotalActions(int(msg.TotalEdges.GetTotalEdges()))
          }
          if msg.EdgeStarted != nil {
              action := &Action{
                  Description: msg.EdgeStarted.GetDesc(),
                  ...
              }
              n.status.StartAction(action)
              running[msg.EdgeStarted.GetId()] = action
          }
          if msg.EdgeFinished != nil {
              ...
                  n.status.FinishAction(ActionResult{
                      Action: started,
                      Output: msg.EdgeFinished.GetOutput(),
                      Error:  err,
                  })
              ...
          }
          ...
          if msg.BuildFinished != nil {
              n.status.Finish()
          }
      }
  }

• 安卓编译时底部的状态显示实现

            1:31 build out/target/product/msmnile_gvmq/obj/kernel/msm-5.4/arch/arm64/boot/Image
            0:02 //frameworks/base/services/appwidget:services.appwidget turbine [common]
            0:01 //frameworks/base/services/appwidget:services.appwidget javac [common]
            0:01 //frameworks/base/services/autofill:services.autofill turbine [common]

  代码

  main() (build/soong/cmd/soong_ui/main.go)
   + output := terminal.NewStatusOutput(c.stdio().Stdout(), os.Getenv("NINJA_STATUS")
   | + // NewStatusOutput(...) build/soong/ui/terminal/status.go
   | + return NewSmartStatusOutput(w, formatter)
   |   + // NewSmartStatusOutput(...) build/soong/ui/terminal/smart_status.go
   |   + s.startActionTableTick() -->
   + log := logger.New(output)
   + stat.AddOutput(output)
  
  func (s *smartStatusOutput) startActionTableTick() {
    s.ticker = time.NewTicker(time.Second) // 每秒计时
    go func() {
        for {
            select {
            case <-s.ticker.C:
                s.lock.Lock()
                s.actionTable() // 刷新action表
                s.lock.Unlock()
            case <-s.done:
                return
            }
        }
    }()
  }
  
  func (s *smartStatusOutput) actionTable() {
    ...
    // Write as many status lines as fit in the table
        fmt.Fprint(s.writer, ansi.setCursor(scrollingHeight+1+tableLine, 1))
  
        if tableLine < len(s.runningActions) {
            runningAction := s.runningActions[tableLine]
            // 更新action持续时间
            seconds := int(time.Since(runningAction.startTime).Round(time.Second).Seconds())
            // 得到编译edge的描述
            desc := runningAction.action.Description
            ...
            // 如果持续时间大于规定时间，着色粗体
            if seconds >= 60 {
                color = ansi.red() + ansi.bold()
            } else if seconds >= 30 {
                color = ansi.yellow() + ansi.bold()
            }
            // 显示信息
            durationStr := fmt.Sprintf("   %2d:%02d ", seconds/60, seconds%60)
            desc = elide(desc, s.termWidth-len(durationStr))
            durationStr = color + durationStr + ansi.regular()
            fmt.Fprint(s.writer, durationStr, desc)
        }
        fmt.Fprint(s.writer, ansi.clearToEndOfLine())
    }
  
    // Move the cursor back to the last line of the scrolling region
    fmt.Fprint(s.writer, ansi.setCursor(scrollingHeight, 1))
  }