Android 11 compiles the kernel real-time output log

Keywords: Android build

How to make the log output in real time when Android compiles the kernel?

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

background

It takes more than ten or twenty minutes to compile make bootimage for development. During this period, there is no log real-time output for a long time. It looks like it is output after compilation,
The waiting time is too long. You don't know what's wrong? Did you compile it? Get stuck? Or something, so I want the log to be output in real time.

Investigation process

make -> ninja

I want to start with compiling the system, but I don't have a clue. Just follow 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 in the previous step_ UI is by

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

Generated, so you can continue to see soong_ui process:

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:]
    |    // That is, getCommand() returns the following method
    |    /*
    |     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 method
    |     }, {
    |     */
    |
    +  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()...)
                    | // Other parameters are omitted
                    | // Command is defined in build/soong/ui/build/exec.go
                    | // Note that the executable is the ninja running prebuilds
                    + cmd := Command(ctx, config, "ninja", executable, args...)
                    |
                    + ctx.Status.Status("Starting ninja...")
                    + cmd.RunAndStreamOrFatal() // Finally, the command will be run, and the analysis will be omitted

Right Soong_ Through the analysis of UI, it is found that through the encapsulated Command(...), prebuilds / build tools / Linux x86 / bin / Ninja is finally executed,

With parameters, we can finally convert make bootimage -j into a command

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

It should be noted that, - frontend_file is a feature added by Android. The original ninja does not have this function,

The purpose is to redirect the output to streaming storage,

The implementation is mainly through pipe and protobuff. You can see if you are interested,

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

4.4. frontend_file parameter

Official Code:

https://android.googlesource....

Official Frontend documentation:

https://android.googlesource....

In short, we can use

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

To compile the kernel and conduct subsequent experiments,

be careful:

-The file after the f parameter is out / combined msmfile_ Gvmq.ninja is the Ninja input file generated by compilation. Different platforms can contain other files through subninja

ninja console

When compiling with ninja, it is found that the log is not output until the compilation is completed (this is a feature of ninja. The log is output uniformly after a compiled edge is completed),

It seems that none of the parameters in the usage help of ninja can control the real-time log output.

Then what shall I do?

At this time, either run the code, or look at the documents, or both at the same time to see what you find.

By checking the documents, looking for methods on the Internet, and looking at / modifying / experimenting with the code, it is finally found that the pool can be changed to console to output the log in real time,

It is described on the official website 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.

That is, the console pool is useful for interactive or long-running tasks,

Note that when you run the console to compile the edge, other edges will also be compiled in the background, but their logs will be cached and will not be output until the console task is completed

So,

  • If we directly compile with ninja, we can find the edge of compiling the kernel, and then add the console pool,

    For example:

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

Then run

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

compile

  • If it is compiled with make bootimage

    Android will modify the generated out / build msmfile_ Gvmq.ninja, you need to find a method in the process of makefile - > Ninja during Android compilation,

    By viewing information

    Android high version P/Q/R source code compilation Guide

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

    Kati detailed explanation - Android 10.0 compilation system (V)

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

Knowing that the conversion process is completed by kati, continue to run the code at this time?

At present, kati has to download the source code, which is precompiled.

Fortunately, when searching grep -rin pool build, I found a. KATI_NINJA_POOL is very strange. According to an experiment, it can really achieve its goal,

Therefore, you need to add the following code where the kernel is compiled:

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))

other

  • ninja pool console code analysis notes

    Source code available from https://ninja-build.org/ Download. The version I downloaded was 1.10.2.git

    When edge uses console, it locks the terminal

    src/status.cc
    void StatusPrinter::BuildEdgeStarted(...) {
      ......
      if (edge->use_console())
        printer_.SetConsoleLocked(true);
    }
    
    void LinePrinter::SetConsoleLocked(bool locked) {
      ......
      console_locked_ = locked;
      // When the terminal is unlocked, the cached log will be output
      if (!locked) {
        PrintOnNewLine(output_buffer_);
        if (!line_buffer_.empty()) {
          Print(line_buffer_, line_type_);
        }
        output_buffer_.clear();
        line_buffer_.clear();
      }
    }

    If there is another edge output at this time, its log will be cached and output when the terminal is unlocked (console edge is completed or fully compiled)

    void LinePrinter::Print(string to_print, LineType type) {
      // If the terminal is locked, output information to line_buffer
      if (console_locked_) {
        line_buffer_ = to_print;
        line_type_ = type;
        return;
      }
      ......
    }
    
    void LinePrinter::PrintOrBuffer(const char* data, size_t size) {
      // If the terminal is locked, the output is cached
      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).
        // Otherwise output to standard output
        fwrite(data, 1, size, stdout);
      }
    }
    
    void LinePrinter::PrintOnNewLine(const string& to_print) {
      // The terminal is locked and the output is cached
      if (console_locked_ && !line_buffer_.empty()) {
        output_buffer_.append(line_buffer_);
        output_buffer_.append(1, '\n');
        line_buffer_.clear();
      }
      ......
    }
  • What is the difference between console and non console log output?

    From the above, when the console is locked, the logs will be cached. How does the process using the console achieve real-time output?

    The answer is the non console output log, standard output, and standard errors are redirected to pipe. The log is read through pipe after compilation.

    Code Notes:

    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()) {// Perform all tasks
      | + // 1. Execute the command. If the console is not used, redirect the standard output and standard error
      | + if (!StartEdge(edge, err))
      | | + if (!command_runner_->StartCommand(edge)) // RealCommandRunner::StartCommand(Edge* edge)
      | |   + subprocs_.Add(command, edge->use_console()) // Does edge use 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) // Generate read / write pipe
      | |         |   Fatal("pipe: %s", strerror(errno));
      | |         + fd_ = output_pipe[0]; // Read pipe to fd_
      | |         |
      | |         + if (!use_console_) {
      | |         | // If the console is not used, redirect the standard output and standard error to the write pipe
      | |         +   err = posix_spawn_file_actions_adddup2(&action, output_pipe[1], 1);
      | |         +   err = posix_spawn_file_actions_adddup2(&action, output_pipe[1], 2);
      | |         + }
      | |         |
      | |         | // Create a sub process, execute the shell command in the Compilation Rules, pid_ Is the child process number returned
      | |         + err = posix_spawn(&pid_, "/bin/sh", &action, &attr,
      | |                 const_cast<char**>(spawned_args), environ);
      | |
      | | // 2. After the edge is executed, obtain the log
      | + 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)); // From output_pipe[0] read log
      | | |    +   +  buf_.append(buf, len); // Log to buf_
      | | |           
      | | +  result->output = subproc->GetOutput(); //Log result - > output
      | |             + // Subprocess::GetOutput()
      | |             + return buf_; // Return log
      | |
      | + // 3. If a compilation command is completed, output / cache the log according to the console lock status
      | + if (!FinishCommand(&result, err))
      | | + // Builder::FinishCommand(CommandRunner::Result* result, string* err)
      | | + status_->BuildEdgeFinished(edge, end_time_millis, result->success(),
      | | |                            result->output); // journal
      | | | + // StatusPrinter::BuildEdgeFinished(...) (src/status.cc)
      | | | + // If the console edge ends, as shown in the previous code, the terminal will be unlocked and the cached log will be output
      | | | + if (edge->use_console())
      | | | |   printer_.SetConsoleLocked(false);
      | | | |
      | | | + // Prompt information, that is, "description" or "command" in the ninja compiled file
      | | | + if (!edge->use_console())
      | | | |   PrintStatus(edge, end_time_millis);
      | | | |
      | | | + // Output or cache logs
      | + + + printer_.PrintOnNewLine(final_output);
      + }
  • Android frontend customization

    frontend also mentioned earlier that it mainly redirects logs to streams, and the implementation adopts Protocol Buffer.

    When console is used for native ninja compilation, other edge outputs will be cached and output again when the edge of console pool is completed,

    However, because of Android customization, the edge of console will be mixed with other edge outputs.

    The log reading is on the soog UI side, and some patterns are displayed. Those who are interested can have a look.

    Code Notes (1.9.0.git) https://android.googlesource....):

    1. If there is in the parameter frontend,Then use the new class implemented by Google 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)
            // New implementation
            status = new StatusSerializer(config);
          else
    #endif
            status = new StatusPrinter(config);
        }
    
    2. Compile complete output log
    // 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, end time, status and other information
      edge_finished->set_id(edge->id_);
      edge_finished->set_end_time(end_time_millis);
      edge_finished->set_status(result->status);
      // journal
      edge_finished->set_output(result->output);
      ...
      Send(); // Serialization log
    }
    // Send() is actually serializing the log into a stream
    void StatusSerializer::Send() {
      // Send the proto as a length-delimited message
      WriteVarint32NoTag(out_, proto_.ByteSizeLong());
      proto_.SerializeToOstream(out_); // serialize
      proto_.Clear();
      out_->flush();
    }
    
    3. Log read
    // <<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() {
        ...
            // Open fifo
            f, err := os.Open(n.fifo)
            ...
        // read
        r := bufio.NewReader(f)
        ...
        for {
            ...
            // Deserialization
            msg := &ninja_frontend.Status{}
            err = proto.Unmarshal(buf, msg)
            ...
            // Do different operations according to the deserialization information
            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()
            }
        }
    }
  • Implementation of status display at the bottom of Android compilation

              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]

    code

    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) // Timing per second
      go func() {
          for {
              select {
              case <-s.ticker.C:
                  s.lock.Lock()
                  s.actionTable() // Refresh action table
                  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]
              // Update action duration
              seconds := int(time.Since(runningAction.startTime).Round(time.Second).Seconds())
              // Get a description of the compiled edge
              desc := runningAction.action.Description
              ...
              // If the duration is greater than the specified time, color bold
              if seconds >= 60 {
                  color = ansi.red() + ansi.bold()
              } else if seconds >= 30 {
                  color = ansi.yellow() + ansi.bold()
              }
              // display information
              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))
    }

Posted by pkSML on Tue, 16 Nov 2021 04:07:56 -0800