安卓go平台启动时间发现如下ueventd耗时1.907s问题:

01-11 00:20:02.854     0     0 I init    : Parsing file /odm/etc/init...
01-11 00:20:02.854 0 0 E init : Unable to open '/odm/etc/init': No such file or directory
01-11 00:20:02.854 0 0 I init : processing action (early-init) from (/init.rc:14)
01-11 00:20:02.855 0 0 D SELinux : initialized (dev cgroup, type cgroup), uses genfs_contexts
01-11 00:20:02.856 0 0 I init : starting service 'ueventd'...
01-11 00:20:02.857 0 0 W cgroup : init (1) created nested cgroup for controller "memory" which has incomplete hierarchy support. Nested cgroups may change behavior in the future.
01-11 00:20:02.857 0 0 W cgroup : "memory" requires setting use_hierarchy to 1 on the root
01-11 00:20:02.857 0 0 I init : processing action (early-init) from (/vendor/etc/init/hw/init.qcom.rc:35)
01-11 00:20:02.858 0 0 I init : processing action (early-init) from (/vendor/etc/init/hw/init.target.rc:32)
01-11 00:20:02.859 0 0 I init : processing action (wait_for_coldboot_done) from (<Builtin Action>:0)
01-11 00:20:02.861 0 0 I ueventd : ueventd started!
01-11 00:20:02.861 0 0 I ueventd : Parsing file /ueventd.rc...
01-11 00:20:02.867 0 0 I ueventd : Parsing file /vendor/ueventd.rc...
01-11 00:20:02.871 0 0 I ueventd : Parsing file /odm/ueventd.rc...
01-11 00:20:02.871 0 0 E ueventd : Unable to open '/odm/ueventd.rc': No such file or directory
01-11 00:20:02.871 0 0 I ueventd : Parsing file /ueventd.qcom.rc...
01-11 00:20:02.871 0 0 E ueventd : Unable to open '/ueventd.qcom.rc': No such file or directory
01-11 00:20:02.881 0 0 I selinux : SELinux: Loaded file_contexts
01-11 00:20:03.137 0 0 I chatty : uid=0(root) logd identical 4 lines
01-11 00:20:03.168 0 0 I selinux : SELinux: Loaded file_contexts
01-11 00:20:04.789 0 0 I ueventd : Coldboot took 1.907 seconds
01-11 00:20:04.791 0 0 I init : Command 'wait_for_coldboot_done' action=wait_for_coldboot_done (<Builtin Action>:0) returned 0 took 1932ms.
01-11 00:20:04.792 0 0 I init : processing action (mix_hwrng_into_linux_rng) from (<Builtin Action>:0)

对应code在system/core/init/ueventd.cpp:

void ColdBoot::Run() {
android::base::Timer cold_boot_timer;

RegenerateUevents();

ForkSubProcesses();

DoRestoreCon();

WaitForSubProcesses();

close(open(COLDBOOT_DONE, O_WRONLY | O_CREAT | O_CLOEXEC, 0000));
LOG(INFO) << "Coldboot took " << cold_boot_timer.duration().count() / 1000.0f << " seconds";
}

在ueventd main中运行:

int ueventd_main(int argc, char** argv) {
/*
* init sets the umask to 077 for forked processes. We need to
* create files with exact permissions, without modification by
* the umask.
*/
umask(000);

InitKernelLogging(argv);

LOG(INFO) << "ueventd started!";

selinux_callback cb;
cb.func_log = selinux_klog_callback;
selinux_set_callback(SELINUX_CB_LOG, cb);

DeviceHandler device_handler = CreateDeviceHandler();
UeventListener uevent_listener;

if (access(COLDBOOT_DONE, F_OK) != 0) {
ColdBoot cold_boot(uevent_listener, device_handler);
cold_boot.Run();
}

init.rc会触发ueventd启动:

on early-init
...
start ueventd

system/core/init/init.cpp会解析init.rc:

int main(int argc, char** argv) {
...
std::string bootscript = GetProperty("ro.boot.init_rc", "");
if (bootscript.empty()) {
parser.ParseConfig("/init.rc");
parser.set_is_system_etc_init_loaded(
parser.ParseConfig("/system/etc/init"));
parser.set_is_vendor_etc_init_loaded(
parser.ParseConfig("/vendor/etc/init"));
parser.set_is_odm_etc_init_loaded(parser.ParseConfig("/odm/etc/init"));
} else {
parser.ParseConfig(bootscript);
parser.set_is_system_etc_init_loaded(true);
parser.set_is_vendor_etc_init_loaded(true);
parser.set_is_odm_etc_init_loaded(true);
}

解析完后会继续触发boot actions,首先是early-init:

am.QueueEventTrigger("early-init");

// Queue an action that waits for coldboot done so we know ueventd has set up all of /dev...
am.QueueBuiltinAction(wait_for_coldboot_done_action, "wait_for_coldboot_done");
// ... so that we can start queuing up actions that require stuff from /dev.
am.QueueBuiltinAction(mix_hwrng_into_linux_rng_action, "mix_hwrng_into_linux_rng");
am.QueueBuiltinAction(set_mmap_rnd_bits_action, "set_mmap_rnd_bits");
am.QueueBuiltinAction(set_kptr_restrict_action, "set_kptr_restrict");
am.QueueBuiltinAction(keychord_init_action, "keychord_init");
am.QueueBuiltinAction(console_init_action, "console_init");

// Trigger all the boot actions to get us started.
am.QueueEventTrigger("init");

builtin action入队看下:

void ActionManager::QueueEventTrigger(const std::string& trigger) {
event_queue_.emplace(trigger);
}

void Action::AddCommand(BuiltinFunction f, const std::vector<std::string>& args, int line) {
commands_.emplace_back(f, args, line);
}

void ActionManager::QueueBuiltinAction(BuiltinFunction func, const std::string& name) {
auto action = std::make_unique<Action>(true, "<Builtin Action>", 0);
std::vector<std::string> name_vector{name};

if (!action->InitSingleTrigger(name)) {
return;
}

action->AddCommand(func, name_vector, 0);

event_queue_.emplace(action.get()); //也queue event
actions_.emplace_back(std::move(action));
}

由上可见,最先处理action是early-init,然后是wait_for_coldboot_done:

入队以后会执行命令了:

while (true) {
// By default, sleep until something happens.
int epoll_timeout_ms = -1;

if (do_shutdown && !shutting_down) {
do_shutdown = false;
if (HandlePowerctlMessage(shutdown_command)) {
shutting_down = true;
}
}

if (!(waiting_for_prop || sm.IsWaitingForExec())) {
am.ExecuteOneCommand();
}

am执行命令接口,先从queue里找到最先入队action,就是early-init了:

void ActionManager::ExecuteOneCommand() {
// Loop through the event queue until we have an action to execute
while (current_executing_actions_.empty() && !event_queue_.empty()) {
for (const auto& action : actions_) {
if (std::visit([&action](const auto& event) { return action->CheckEvent(event); },
event_queue_.front())) {
current_executing_actions_.emplace(action.get());
}
}
event_queue_.pop();
}

if (current_executing_actions_.empty()) {
return;
}

auto action = current_executing_actions_.front();

if (current_command_ == 0) {
std::string trigger_name = action->BuildTriggersString();
LOG(INFO) << "processing action (" << trigger_name << ") from (" << action->filename()
<< ":" << action->line() << ")";
}

action->ExecuteOneCommand(current_command_);

action的执行命令,超过50ms才会报个log,从log看显然early-init没有,是wait_for_coldboot_done超时了:

void Action::ExecuteCommand(const Command& command) const {
android::base::Timer t;
int result = command.InvokeFunc(); //这里

auto duration = t.duration();
// Any action longer than 50ms will be warned to user as slow operation
if (duration > 50ms || android::base::GetMinimumLogSeverity() <= android::base::DEBUG) {
std::string trigger_name = BuildTriggersString();
std::string cmd_str = command.BuildCommandString();

LOG(INFO) << "Command '" << cmd_str << "' action=" << trigger_name << " (" << filename_
<< ":" << command.line() << ") returned " << result << " took "
<< duration.count() << "ms.";
}
}
int Command::InvokeFunc() const {
std::vector<std::string> expanded_args;
expanded_args.resize(args_.size());
expanded_args[0] = args_[0];
for (std::size_t i = 1; i < args_.size(); ++i) {
if (!expand_props(args_[i], &expanded_args[i])) {
LOG(ERROR) << args_[0] << ": cannot expand '" << args_[i] << "'";
return -EINVAL;
}
}

return func_(expanded_args);
}

这里的func_就先是do_start了,这个command就是一开始解析init.rc时add command了:

bool Action::AddCommand(const std::vector<std::string>& args, int line, std::string* err) {
if (!function_map_) {
*err = "no function map available";
return false;
}

auto function = function_map_->FindFunction(args, err); //从function map找到start命令对应的func:do_start
if (!function) {
return false;
}

AddCommand(function, args, line);
return true;
}

bool ActionParser::ParseLineSection(std::vector<std::string>&& args, int line, std::string* err) {
return action_ ? action_->AddCommand(std::move(args), line, err) : false;
}

function map里start命令对应的接口是do_start:

const BuiltinFunctionMap::Map& BuiltinFunctionMap::map() const {
constexpr std::size_t kMax = std::numeric_limits<std::size_t>::max();
// clang-format off
static const Map builtin_functions = {
...
{"start", {1, 1, do_start}},

do_start:

static int do_start(const std::vector<std::string>& args) {
Service* svc = ServiceManager::GetInstance().FindServiceByName(args[1]);
if (!svc) {
LOG(ERROR) << "do_start: Service " << args[1] << " not found";
return -1;
}
if (!svc->Start())
return -1;
return 0;
}

服务启动入口:

bool Service::Start() {
// Starting a service removes it from the disabled or reset state and
// immediately takes it out of the restarting state if it was in there.
flags_ &= (~(SVC_DISABLED|SVC_RESTARTING|SVC_RESET|SVC_RESTART|SVC_DISABLED_START));

// Running processes require no additional work --- if they're in the
// process of exiting, we've ensured that they will immediately restart
// on exit, unless they are ONESHOT.
if (flags_ & SVC_RUNNING) {
return false;
}
...
LOG(INFO) << "starting service '" << name_ << "'...";

这个service就是ueventd了,入口是ueventd_main:

int ueventd_main(int argc, char** argv) {
/*
* init sets the umask to 077 for forked processes. We need to
* create files with exact permissions, without modification by
* the umask.
*/
umask(000);

InitKernelLogging(argv);

LOG(INFO) << "ueventd started!";

ok,接下来就会从queue里取出coldboot_done_action:

static int wait_for_coldboot_done_action(const std::vector<std::string>& args) {
Timer t;

LOG(ERROR) << "Waiting for " COLDBOOT_DONE "...";

// Historically we had a 1s timeout here because we weren't otherwise
// tracking boot time, and many OEMs made their sepolicy regular
// expressions too expensive (http://b/19899875).

// Now we're tracking boot time, just log the time taken to a system
// property. We still panic if it takes more than a minute though,
// because any build that slow isn't likely to boot at all, and we'd
// rather any test lab devices fail back to the bootloader.
if (wait_for_file(COLDBOOT_DONE, 60s) < 0) {
LOG(ERROR) << "Timed out waiting for " COLDBOOT_DONE;
panic();
}

property_set("ro.boottime.init.cold_boot_wait", std::to_string(t.duration().count()));
return 0;
}

他会等待COLDBOOT_DONE文件生成,看log就是下面这个文件了:

[    2.180281] init: Waiting for /dev/.coldboot_done...

也就是等待ueventd ColdBoot跑完:

void ColdBoot::Run() {
...
LOG(INFO) << "Coldboot took " << cold_boot_timer.duration().count() / 1000.0f << " seconds";
}

最后发现竟然是DoRestoreCon()耗时,看来是我们自家的sepolicy file_context太多了?

ps: 编译boot.img烧录验证。