tequilaOS/platform_system_core
2
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity

Replace the "coldboot" timeout with a property.

Browse source 
Also rename init's existing boot-time related properties so they're
all "ro.*" properties.

Example result:

  # Three properties showing when init started...
  [ro.boottime.init]: [5294587604]
  # ...how long it waited for ueventd...
  [ro.boottime.init.cold_boot_wait]: [646956470]
  # ...and how long SELinux initialization took...
  [ro.boottime.init.selinux]: [45742921]

  # Plus one property for each service, showing when it first started.
  [ro.boottime.InputEventFind]: [10278767840]
  [ro.boottime.adbd]: [8359267180]
  [ro.boottime.atfwd]: [10338554773]
  [ro.boottime.audioserver]: [10298157478]
  [ro.boottime.bootanim]: [9323670089]
  [ro.boottime.cameraserver]: [10299402321]
  [ro.boottime.cnd]: [10335931856]
  [ro.boottime.debuggerd]: [7001352774]
  [ro.boottime.debuggerd64]: [7002261785]
  [ro.boottime.drm]: [10301082113]
  [ro.boottime.fingerprintd]: [10331443314]
  [ro.boottime.flash-nanohub-fw]: [6995265534]
  [ro.boottime.gatekeeperd]: [10340355242]
  [ro.boottime.healthd]: [7856893380]
  [ro.boottime.hwservicemanager]: [7856051088]
  [ro.boottime.imscmservice]: [10290530758]
  [ro.boottime.imsdatadaemon]: [10358136702]
  [ro.boottime.imsqmidaemon]: [10289084872]
  [ro.boottime.installd]: [10303296020]
  [ro.boottime.irsc_util]: [10279807632]
  [ro.boottime.keystore]: [10305034093]
  [ro.boottime.lmkd]: [7863506714]
  [ro.boottime.loc_launcher]: [10324525241]
  [ro.boottime.logd]: [6526221633]
  [ro.boottime.logd-reinit]: [7850662702]
  [ro.boottime.mcfg-sh]: [10337268315]
  [ro.boottime.media]: [10312152687]
  [ro.boottime.mediacodec]: [10306852530]
  [ro.boottime.mediadrm]: [10308707999]
  [ro.boottime.mediaextractor]: [10310681177]
  [ro.boottime.msm_irqbalance]: [7862451974]
  [ro.boottime.netd]: [10313523104]
  [ro.boottime.netmgrd]: [10285009351]
  [ro.boottime.oem_qmi_server]: [10293329092]
  [ro.boottime.per_mgr]: [7857915776]
  [ro.boottime.per_proxy]: [8335121605]
  [ro.boottime.perfd]: [10283443101]
  [ro.boottime.qcamerasvr]: [10329644772]
  [ro.boottime.qmuxd]: [10282346643]
  [ro.boottime.qseecomd]: [6855708593]
  [ro.boottime.qti]: [10286196851]
  [ro.boottime.ril-daemon]: [10314933677]
  [ro.boottime.rmt_storage]: [7859105047]
  [ro.boottime.servicemanager]: [7864555881]
  [ro.boottime.ss_ramdump]: [8337634938]
  [ro.boottime.ssr_setup]: [8336268324]
  [ro.boottime.surfaceflinger]: [7866921402]
  [ro.boottime.thermal-engine]: [10281249924]
  [ro.boottime.time_daemon]: [10322006542]
  [ro.boottime.ueventd]: [5618663938]
  [ro.boottime.vold]: [7003493920]
  [ro.boottime.wificond]: [10316641073]
  [ro.boottime.wpa_supplicant]: [18959816881]
  [ro.boottime.zygote]: [10295295029]
  [ro.boottime.zygote_secondary]: [10296637269]

Bug: http://b/31800756
Test: boots
Change-Id: I094cce0c1bab9406d950ca94212689dc2e15dba5
This commit is contained in:
Elliott Hughes 2016-11-29 19:20:58 +00:00
parent f35b5e1976
commit 4d6cfbcd85
11 changed files with 114 additions and 66 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

2
init/action.cpp
View file

@ -121,7 +121,7 @@ void Action::ExecuteCommand(const Command& command) const {
Timer t;
int result = command.InvokeFunc();
double duration_ms = t.duration() * 1000;
double duration_ms = t.duration_s() * 1000;
// Any action longer than 50ms will be warned to user as slow operation
if (duration_ms > 50.0 ||
android::base::GetMinimumLogSeverity() <= android::base::DEBUG) {

10
init/builtins.cpp
View file

@ -146,8 +146,7 @@ static int wipe_data_via_recovery(const std::string& reason) {
LOG(ERROR) << "failed to set bootloader message: " << err;
return -1;
}
android_reboot(ANDROID_RB_RESTART2, 0, "recovery");
while (1) { pause(); } // never reached
reboot("recovery");
}
static void unmount_and_fsck(const struct mntent *entry) {
@ -732,7 +731,7 @@ static int do_powerctl(const std::vector<std::string>& args) {
ServiceManager::GetInstance().ForEachService(
[] (Service* s) { s->Terminate(); });
while (t.duration() < delay) {
while (t.duration_s() < delay) {
ServiceManager::GetInstance().ReapAnyOutstandingChildren();
int service_count = 0;
@ -756,11 +755,10 @@ static int do_powerctl(const std::vector<std::string>& args) {
// Wait a bit before recounting the number or running services.
std::this_thread::sleep_for(50ms);
}
LOG(VERBOSE) << "Terminating running services took " << t.duration() << " seconds";
LOG(VERBOSE) << "Terminating running services took " << t;
}
return android_reboot_with_callback(cmd, 0, reboot_target,
callback_on_ro_remount);
return android_reboot_with_callback(cmd, 0, reboot_target, callback_on_ro_remount);
}
static int do_trigger(const std::vector<std::string>& args) {

4
init/devices.cpp
View file

@ -868,7 +868,7 @@ static void handle_firmware_event(uevent* uevent) {
if (pid == 0) {
Timer t;
process_firmware_event(uevent);
LOG(INFO) << "loading " << uevent->path << " took " << t.duration() << "s";
LOG(INFO) << "loading " << uevent->path << " took " << t;
_exit(EXIT_SUCCESS);
} else if (pid == -1) {
PLOG(ERROR) << "could not fork to process firmware event for " << uevent->firmware;
@ -1043,7 +1043,7 @@ void device_init() {
coldboot("/sys/block");
coldboot("/sys/devices");
close(open(COLDBOOT_DONE, O_WRONLY|O_CREAT|O_CLOEXEC, 0000));
LOG(INFO) << "Coldboot took " << t.duration() << "s.";
LOG(INFO) << "Coldboot took " << t;
}
int get_device_fd() {

35
init/init.cpp
View file

@ -43,7 +43,6 @@
#include <android-base/file.h>
#include <android-base/stringprintf.h>
#include <android-base/strings.h>
#include <cutils/android_reboot.h>
#include <cutils/fs.h>
#include <cutils/iosched_policy.h>
#include <cutils/list.h>
@ -164,14 +163,21 @@ static int wait_for_coldboot_done_action(const std::vector<std::string>& args) {
Timer t;
LOG(VERBOSE) << "Waiting for " COLDBOOT_DONE "...";
// Any longer than 1s is an unreasonable length of time to delay booting.
// If you're hitting this timeout, check that you didn't make your
// sepolicy regular expressions too expensive (http://b/19899875).
if (wait_for_file(COLDBOOT_DONE, 1s)) {
// 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();
}
LOG(VERBOSE) << "Waiting for " COLDBOOT_DONE " took " << t.duration() << "s.";
property_set("ro.boottime.init.cold_boot_wait", std::to_string(t.duration_ns()).c_str());
return 0;
}
@ -252,9 +258,8 @@ ret:
}
static void security_failure() {
LOG(ERROR) << "Security failure; rebooting into recovery mode...";
android_reboot(ANDROID_RB_RESTART2, 0, "recovery");
while (true) { pause(); } // never reached
LOG(ERROR) << "Security failure...";
panic();
}
#define MMAP_RND_PATH "/proc/sys/vm/mmap_rnd_bits"
@ -545,8 +550,8 @@ static void selinux_initialize(bool in_kernel_domain) {
security_failure();
}
LOG(INFO) << "(Initializing SELinux " << (is_enforcing ? "enforcing" : "non-enforcing")
<< " took " << t.duration() << "s.)";
// init's first stage can't set properties, so pass the time to the second stage.
setenv("INIT_SELINUX_TOOK", std::to_string(t.duration_ns()).c_str(), 1);
} else {
selinux_init_all_handles();
}
@ -752,7 +757,13 @@ int main(int argc, char** argv) {
export_kernel_boot_props();
// Make the time that init started available for bootstat to log.
property_set("init.start", getenv("INIT_STARTED_AT"));
property_set("ro.boottime.init", getenv("INIT_STARTED_AT"));
property_set("ro.boottime.init.selinux", getenv("INIT_SELINUX_TOOK"));
// Clean up our environment.
unsetenv("INIT_SECOND_STAGE");
unsetenv("INIT_STARTED_AT");
unsetenv("INIT_SELINUX_TOOK");
// Now set up SELinux for second stage.
selinux_initialize(false);

2
init/init_parser.cpp
View file

@ -110,7 +110,7 @@ bool Parser::ParseConfigFile(const std::string& path) {
// Nexus 9 boot time, so it's disabled by default.
if (false) DumpState();
LOG(VERBOSE) << "(Parsing " << path << " took " << t.duration() << "s.)";
LOG(VERBOSE) << "(Parsing " << path << " took " << t << ".)";
return true;
}

56
init/property_service.cpp
View file

@ -169,11 +169,18 @@ bool is_legal_property_name(const std::string &name)
return true;
}
static int property_set_impl(const char* name, const char* value) {
int property_set(const char* name, const char* value) {
size_t valuelen = strlen(value);
if (!is_legal_property_name(name)) return -1;
if (valuelen >= PROP_VALUE_MAX) return -1;
if (!is_legal_property_name(name)) {
LOG(ERROR) << "property_set(\"" << name << "\", \"" << value << "\") failed: bad name";
return -1;
}
if (valuelen >= PROP_VALUE_MAX) {
LOG(ERROR) << "property_set(\"" << name << "\", \"" << value << "\") failed: "
<< "value too long";
return -1;
}
if (strcmp("selinux.restorecon_recursive", name) == 0 && valuelen > 0) {
if (restorecon(value, SELINUX_ANDROID_RESTORECON_RECURSE) != 0) {
@ -182,49 +189,42 @@ static int property_set_impl(const char* name, const char* value) {
}
prop_info* pi = (prop_info*) __system_property_find(name);
if(pi != 0) {
/* ro.* properties may NEVER be modified once set */
if(!strncmp(name, "ro.", 3)) return -1;
if (pi != nullptr) {
// ro.* properties are actually "write-once".
if (!strncmp(name, "ro.", 3)) {
LOG(ERROR) << "property_set(\"" << name << "\", \"" << value << "\") failed: "
<< "property already set";
return -1;
}
__system_property_update(pi, value, valuelen);
} else {
int rc = __system_property_add(name, strlen(name), value, valuelen);
if (rc < 0) {
LOG(ERROR) << "property_set(\"" << name << "\", \"" << value << "\") failed: "
<< "__system_property_add failed";
return rc;
}
}
/* If name starts with "net." treat as a DNS property. */
// If name starts with "net." treat as a DNS property.
if (strncmp("net.", name, strlen("net.")) == 0) {
if (strcmp("net.change", name) == 0) {
return 0;
}
/*
* The 'net.change' property is a special property used track when any
* 'net.*' property name is updated. It is _ONLY_ updated here. Its value
* contains the last updated 'net.*' property.
*/
// The 'net.change' property is a special property used track when any
// 'net.*' property name is updated. It is _ONLY_ updated here. Its value
// contains the last updated 'net.*' property.
property_set("net.change", name);
} else if (persistent_properties_loaded &&
strncmp("persist.", name, strlen("persist.")) == 0) {
/*
* Don't write properties to disk until after we have read all default properties
* to prevent them from being overwritten by default values.
*/
} else if (persistent_properties_loaded && strncmp("persist.", name, strlen("persist.")) == 0) {
// Don't write properties to disk until after we have read all default properties
// to prevent them from being overwritten by default values.
write_persistent_property(name, value);
}
property_changed(name, value);
return 0;
}
int property_set(const char* name, const char* value) {
int rc = property_set_impl(name, value);
if (rc == -1) {
LOG(ERROR) << "property_set(\"" << name << "\", \"" << value << "\") failed";
}
return rc;
}
static void handle_property_set_fd()
{
prop_msg msg;
@ -388,7 +388,7 @@ static void load_properties_from_file(const char* filename, const char* filter)
}
data.push_back('\n');
load_properties(&data[0], filter);
LOG(VERBOSE) << "(Loading properties from " << filename << " took " << t.duration() << "s.)";
LOG(VERBOSE) << "(Loading properties from " << filename << " took " << t << ".)";
}
static void load_persistent_properties() {

23
init/readme.txt
View file

@ -443,16 +443,27 @@ Properties
Init provides information about the services that it is responsible
for via the below properties.
init.start
Time after boot in ns (via the CLOCK_BOOTTIME clock) at which the first
stage of init started.
init.svc.<name>
State of a named service ("stopped", "stopping", "running", "restarting")
init.svc.<name>.start
Boot timing
-----------
Init records some boot timing information in system properties.
ro.boottime.init
Time after boot in ns (via the CLOCK_BOOTTIME clock) at which the first
stage of init started.
ro.boottime.init.selinux
How long it took the first stage to initialize SELinux.
ro.boottime.init.cold_boot_wait
How long init waited for ueventd's coldboot phase to end.
ro.boottime.<service-name>
Time after boot in ns (via the CLOCK_BOOTTIME clock) that the service was
most recently started.
first started.
Bootcharting

11
init/service.cpp
View file

@ -36,7 +36,6 @@
#include <android-base/parseint.h>
#include <android-base/stringprintf.h>
#include <android-base/strings.h>
#include <cutils/android_reboot.h>
#include <system/thread_defs.h>
#include <processgroup/processgroup.h>
@ -190,9 +189,9 @@ void Service::NotifyStateChange(const std::string& new_state) const {
property_set(prop_name.c_str(), new_state.c_str());
if (new_state == "running") {
prop_name += ".start";
uint64_t start_ns = time_started_.time_since_epoch().count();
property_set(prop_name.c_str(), StringPrintf("%" PRIu64, start_ns).c_str());
property_set(StringPrintf("ro.boottime.%s", name_.c_str()).c_str(),
StringPrintf("%" PRIu64, start_ns).c_str());
}
}
@ -283,10 +282,8 @@ bool Service::Reap() {
if ((flags_ & SVC_CRITICAL) && !(flags_ & SVC_RESTART)) {
if (now < time_crashed_ + 4min) {
if (++crash_count_ > 4) {
LOG(ERROR) << "critical process '" << name_ << "' exited 4 times in 4 minutes; "
<< "rebooting into recovery mode";
android_reboot(ANDROID_RB_RESTART2, 0, "recovery");
return false;
LOG(ERROR) << "critical process '" << name_ << "' exited 4 times in 4 minutes";
panic();
}
} else {
time_crashed_ = now;

1
init/signal_handler.cpp
View file

@ -24,7 +24,6 @@
#include <unistd.h>
#include <android-base/stringprintf.h>
#include <cutils/android_reboot.h>
#include <cutils/list.h>
#include <cutils/sockets.h>

21
init/util.cpp
View file

@ -41,6 +41,8 @@
#include <android-base/stringprintf.h>
#include <android-base/strings.h>
#include <android-base/unique_fd.h>
#include <cutils/android_reboot.h>
/* for ANDROID_SOCKET_* */
#include <cutils/sockets.h>
@ -472,3 +474,22 @@ bool expand_props(const std::string& src, std::string* dst) {
return true;
}
void reboot(const char* destination) {
android_reboot(ANDROID_RB_RESTART2, 0, destination);
// We're init, so android_reboot will actually have been a syscall so there's nothing
// to wait for. If android_reboot returns, just abort so that the kernel will reboot
// itself when init dies.
PLOG(FATAL) << "reboot failed";
abort();
}
void panic() {
LOG(ERROR) << "panic: rebooting to bootloader";
reboot("bootloader");
}
std::ostream& operator<<(std::ostream& os, const Timer& t) {
os << t.duration_s() << " seconds";
return os;
}

15
init/util.h
View file

@ -21,8 +21,9 @@
#include <sys/types.h>
#include <chrono>
#include <string>
#include <functional>
#include <ostream>
#include <string>
#define COLDBOOT_DONE "/dev/.coldboot_done"
@ -51,15 +52,21 @@ class Timer {
Timer() : start_(boot_clock::now()) {
}
double duration() {
double duration_s() const {
typedef std::chrono::duration<double> double_duration;
return std::chrono::duration_cast<double_duration>(boot_clock::now() - start_).count();
}
int64_t duration_ns() const {
return (boot_clock::now() - start_).count();
}
private:
boot_clock::time_point start_;
};
std::ostream& operator<<(std::ostream& os, const Timer& t);
unsigned int decode_uid(const char *s);
int mkdir_recursive(const char *pathname, mode_t mode);
@ -72,4 +79,8 @@ int restorecon(const char *pathname, int flags = 0);
std::string bytes_to_hex(const uint8_t *bytes, size_t bytes_len);
bool is_dir(const char* pathname);
bool expand_props(const std::string& src, std::string* dst);
void reboot(const char* destination) __attribute__((__noreturn__));
void panic() __attribute__((__noreturn__));
#endif