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 -j4Soong 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 omittedRight 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)
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)) }