Merge "Log more timing information from init."

17 files changed, 275 insertions, 240 deletions

diff --git a/include/cutils/klog.h b/include/cutils/klog.h
index d5ae6d7..295d62b 100644
--- a/include/cutils/klog.h
+++ b/include/cutils/klog.h
@@ -18,6 +18,7 @@
 #define _CUTILS_KLOG_H_
 
 #include <sys/cdefs.h>
+#include <sys/uio.h>
 #include <stdarg.h>
 
 __BEGIN_DECLS
@@ -26,9 +27,10 @@ void klog_init(void);
 int  klog_get_level(void);
 void klog_set_level(int level);
 /* TODO: void klog_close(void); - and make klog_fd users thread safe. */
+
 void klog_write(int level, const char *fmt, ...)
     __attribute__ ((format(printf, 2, 3)));
-void klog_vwrite(int level, const char *fmt, va_list ap);
+void klog_writev(int level, const struct iovec* iov, int iov_count);
 
 __END_DECLS
 
diff --git a/init/Android.mk b/init/Android.mk
index 5b8094f..cb4cb11 100644
--- a/init/Android.mk
+++ b/init/Android.mk
@@ -24,6 +24,7 @@ include $(CLEAR_VARS)
 LOCAL_CPPFLAGS := $(init_cflags)
 LOCAL_SRC_FILES:= \
     init_parser.cpp \
+    log.cpp \
     parser.cpp \
     util.cpp \
 
diff --git a/init/devices.cpp b/init/devices.cpp
index 9bce39a..c32eb4f 100644
--- a/init/devices.cpp
+++ b/init/devices.cpp
@@ -364,13 +364,6 @@ static int find_pci_device_prefix(const char *path, char *buf, ssize_t buf_sz)
     return 0;
 }
 
-static inline suseconds_t get_usecs(void)
-{
-    struct timeval tv;
-    gettimeofday(&tv, 0);
-    return tv.tv_sec * (suseconds_t) 1000000 + tv.tv_usec;
-}
-
 static void parse_event(const char *msg, struct uevent *uevent)
 {
     uevent->action = "";
@@ -1011,18 +1004,15 @@ void device_init(void)
     fcntl(device_fd, F_SETFL, O_NONBLOCK);
 
     if (stat(COLDBOOT_DONE, &info) < 0) {
-        t0 = get_usecs();
+        Timer t;
         coldboot("/sys/class");
         coldboot("/sys/block");
         coldboot("/sys/devices");
-        t1 = get_usecs();
         fd = open(COLDBOOT_DONE, O_WRONLY|O_CREAT|O_CLOEXEC, 0000);
         close(fd);
-        if (LOG_UEVENTS) {
-            INFO("coldboot %ld uS\n", ((long) (t1 - t0)));
-        }
-    } else if (LOG_UEVENTS) {
-        INFO("skipping coldboot, already done\n");
+        NOTICE("Coldboot took %.2fs.\n", t.duration());
+    } else {
+        NOTICE("Skipping coldboot, already done!\n");
     }
 }
 
diff --git a/init/init.cpp b/init/init.cpp
index 1449bc6..b1d65db 100644
--- a/init/init.cpp
+++ b/init/init.cpp
@@ -83,7 +83,7 @@ static const char *ENV[32];
 bool waiting_for_exec = false;
 
 void service::NotifyStateChange(const char* new_state) {
-    if (!properties_inited()) {
+    if (!properties_initialized()) {
         // If properties aren't available yet, we can't set them.
         return;
     }
@@ -246,7 +246,7 @@ void service_start(struct service *svc, const char *dynamic_args)
         }
     }
 
-    NOTICE("starting '%s'\n", svc->name);
+    NOTICE("Starting service '%s'...\n", svc->name);
 
     pid_t pid = fork();
     if (pid == 0) {
@@ -256,7 +256,7 @@ void service_start(struct service *svc, const char *dynamic_args)
         int fd, sz;
 
         umask(077);
-        if (properties_inited()) {
+        if (properties_initialized()) {
             get_property_workspace(&fd, &sz);
             snprintf(tmp, sizeof(tmp), "%d,%d", dup(fd), sz);
             add_environment("ANDROID_PROPERTY_WORKSPACE", tmp);
@@ -397,7 +397,7 @@ static void service_stop_or_reset(struct service *svc, int how)
     }
 
     if (svc->pid) {
-        NOTICE("service '%s' is being killed\n", svc->name);
+        NOTICE("Service '%s' is being killed...\n", svc->name);
         kill(-svc->pid, SIGKILL);
         svc->NotifyStateChange("stopping");
     } else {
@@ -559,17 +559,18 @@ void build_triggers_string(char *name_str, int length, struct action *cur_action
     }
 }
 
-void execute_one_command(void)
-{
-    int ret, i;
+void execute_one_command() {
+    Timer t;
+
     char cmd_str[256] = "";
     char name_str[256] = "";
 
     if (!cur_action || !cur_command || is_last_command(cur_action, cur_command)) {
         cur_action = action_remove_queue_head();
         cur_command = NULL;
-        if (!cur_action)
+        if (!cur_action) {
             return;
+        }
 
         build_triggers_string(name_str, sizeof(name_str), cur_action);
 
@@ -579,20 +580,26 @@ void execute_one_command(void)
         cur_command = get_next_command(cur_action, cur_command);
     }
 
-    if (!cur_command)
+    if (!cur_command) {
         return;
+    }
 
-    ret = cur_command->func(cur_command->nargs, cur_command->args);
+    int result = cur_command->func(cur_command->nargs, cur_command->args);
     if (klog_get_level() >= KLOG_INFO_LEVEL) {
-        for (i = 0; i < cur_command->nargs; i++) {
+        for (int i = 0; i < cur_command->nargs; i++) {
             strlcat(cmd_str, cur_command->args[i], sizeof(cmd_str));
             if (i < cur_command->nargs - 1) {
                 strlcat(cmd_str, " ", sizeof(cmd_str));
             }
         }
-        INFO("command '%s' action=%s status=%d (%s:%d)\n",
-             cmd_str, cur_action ? name_str : "", ret, cur_command->filename,
-             cur_command->line);
+        char source[256];
+        if (cur_command->filename) {
+            snprintf(source, sizeof(source), " (%s:%d)", cur_command->filename, cur_command->line);
+        } else {
+            *source = '\0';
+        }
+        INFO("Command '%s' action=%s%s returned %d took %.2fs\n",
+             cmd_str, cur_action ? name_str : "", source, result, t.duration());
     }
 }
 
@@ -928,40 +935,25 @@ int selinux_reload_policy(void)
     return 0;
 }
 
-static int audit_callback(void *data, security_class_t /*cls*/, char *buf, size_t len)
-{
+static int audit_callback(void *data, security_class_t /*cls*/, char *buf, size_t len) {
     snprintf(buf, len, "property=%s", !data ? "NULL" : (char *)data);
     return 0;
 }
 
-int log_callback(int type, const char *fmt, ...)
-{
-    int level;
-    va_list ap;
-    switch (type) {
-    case SELINUX_WARNING:
-        level = KLOG_WARNING_LEVEL;
-        break;
-    case SELINUX_INFO:
-        level = KLOG_INFO_LEVEL;
-        break;
-    default:
-        level = KLOG_ERROR_LEVEL;
-        break;
-    }
-    va_start(ap, fmt);
-    klog_vwrite(level, fmt, ap);
-    va_end(ap);
-    return 0;
-}
+static void selinux_initialize() {
+    Timer t;
+
+    selinux_callback cb;
+    cb.func_log = selinux_klog_callback;
+    selinux_set_callback(SELINUX_CB_LOG, cb);
+    cb.func_audit = audit_callback;
+    selinux_set_callback(SELINUX_CB_AUDIT, cb);
 
-static void selinux_initialize(void)
-{
     if (selinux_is_disabled()) {
         return;
     }
 
-    INFO("loading selinux policy\n");
+    INFO("Loading SELinux policy...\n");
     if (selinux_android_load_policy() < 0) {
         ERROR("SELinux: Failed to load policy; rebooting into recovery mode\n");
         android_reboot(ANDROID_RB_RESTART2, 0, "recovery");
@@ -972,14 +964,18 @@ static void selinux_initialize(void)
     bool is_enforcing = selinux_is_enforcing();
     INFO("SELinux: security_setenforce(%d)\n", is_enforcing);
     security_setenforce(is_enforcing);
+
+    NOTICE("(Initializing SELinux took %.2fs.)\n", t.duration());
 }
 
 int main(int argc, char** argv) {
-    if (!strcmp(basename(argv[0]), "ueventd"))
+    if (!strcmp(basename(argv[0]), "ueventd")) {
         return ueventd_main(argc, argv);
+    }
 
-    if (!strcmp(basename(argv[0]), "watchdogd"))
+    if (!strcmp(basename(argv[0]), "watchdogd")) {
         return watchdogd_main(argc, argv);
+    }
 
     // Clear the umask.
     umask(0);
@@ -1008,36 +1004,32 @@ int main(int argc, char** argv) {
     // to the outside world.
     open_devnull_stdio();
     klog_init();
+    klog_set_level(KLOG_NOTICE_LEVEL);
+
+    NOTICE("init started!\n");
+
     property_init();
 
+    // If arguments are passed both on the command line and in DT,
+    // properties set in DT always have priority over the command-line ones.
     process_kernel_dt();
-    /* in case one is passing arguments both on the command line and in DT
-     * Properties set in DT always have priority over the command-line ones
-     */
     process_kernel_cmdline();
 
-    /* now propogate the kernel variables to internal variables
-     * used by init as well as the current required properties
-     */
+    // Propogate the kernel variables to internal variables
+    // used by init as well as the current required properties.
     export_kernel_boot_props();
 
-    selinux_callback cb;
-    cb.func_log = log_callback;
-    selinux_set_callback(SELINUX_CB_LOG, cb);
-    cb.func_audit = audit_callback;
-    selinux_set_callback(SELINUX_CB_AUDIT, cb);
-
     selinux_initialize();
 
     // These directories were necessarily created before initial policy load
     // and therefore need their security context restored to the proper value.
     // This must happen before /dev is populated by ueventd.
+    INFO("Running restorecon...\n");
     restorecon("/dev");
     restorecon("/dev/socket");
     restorecon("/dev/__properties__");
     restorecon_recursive("/sys");
 
-    INFO("property init\n");
     property_load_boot_defaults();
 
     init_parse_config_file("/init.rc");
@@ -1049,7 +1041,7 @@ int main(int argc, char** argv) {
     queue_builtin_action(keychord_init_action, "keychord_init");
     queue_builtin_action(console_init_action, "console_init");
 
-    // Execute all the boot actions to get us started.
+    // Trigger all the boot actions to get us started.
     action_for_each_trigger("init", action_add_queue_tail);
 
     // Repeat mix_hwrng_into_linux_rng in case /dev/hw_random or /dev/random
diff --git a/init/init_parser.cpp b/init/init_parser.cpp
index 57eb299..294dc19 100644
--- a/init/init_parser.cpp
+++ b/init/init_parser.cpp
@@ -14,15 +14,16 @@
  * limitations under the License.
  */
 
+#include <ctype.h>
 #include <errno.h>
-#include <stdio.h>
-#include <stdlib.h>
-#include <unistd.h>
 #include <fcntl.h>
+#include <inttypes.h>
 #include <stdarg.h>
-#include <string.h>
 #include <stddef.h>
-#include <ctype.h>
+#include <stdio.h>
+#include <stdlib.h>
+#include <string.h>
+#include <unistd.h>
 
 #include "init.h"
 #include "parser.h"
@@ -351,7 +352,7 @@ static void parse_import(struct parse_state *state, int nargs, char **args)
     struct import* import = (struct import*) calloc(1, sizeof(struct import));
     import->filename = strdup(conf_file);
     list_add_tail(import_list, &import->list);
-    INFO("found import '%s', adding to import list", import->filename);
+    INFO("Added '%s' to import list\n", import->filename);
 }
 
 static void parse_new_section(struct parse_state *state, int kw,
@@ -439,6 +440,7 @@ parser_done:
 
 int init_parse_config_file(const char* path) {
     INFO("Parsing %s...\n", path);
+    Timer t;
     std::string data;
     if (!read_file(path, &data)) {
         return -1;
@@ -446,6 +448,8 @@ int init_parse_config_file(const char* path) {
 
     parse_config(path, data);
     dump_parser_state();
+
+    NOTICE("(Parsing %s took %.2fs.)\n", path, t.duration());
     return 0;
 }
 
diff --git a/init/keychords.cpp b/init/keychords.cpp
index 2e996ea..27894a2 100644
--- a/init/keychords.cpp
+++ b/init/keychords.cpp
@@ -109,7 +109,7 @@ void handle_keychord()
     if (!strcmp(adb_enabled, "running")) {
         svc = service_find_by_keychord(id);
         if (svc) {
-            INFO("starting service %s from keychord\n", svc->name);
+            INFO("Starting service %s from keychord\n", svc->name);
             service_start(svc, NULL);
         } else {
             ERROR("service for keychord %d not found\n", id);
diff --git a/init/log.cpp b/init/log.cpp
new file mode 100644
index 0000000..d32f2da
--- /dev/null
+++ b/init/log.cpp
@@ -0,0 +1,62 @@
+/*
+ * Copyright (C) 2015 The Android Open Source Project
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+#include <stdlib.h>
+#include <string.h>
+#include <sys/uio.h>
+
+#include <selinux/selinux.h>
+
+#include "log.h"
+
+static void init_klog_vwrite(int level, const char* fmt, va_list ap) {
+    static const char* tag = basename(getprogname());
+
+    char prefix[64];
+    snprintf(prefix, sizeof(prefix), "<%d>%s: ", level, tag);
+
+    char msg[512];
+    vsnprintf(msg, sizeof(msg), fmt, ap);
+
+    iovec iov[2];
+    iov[0].iov_base = prefix;
+    iov[0].iov_len = strlen(prefix);
+    iov[1].iov_base = msg;
+    iov[1].iov_len = strlen(msg);
+
+    klog_writev(level, iov, 2);
+}
+
+void init_klog_write(int level, const char* fmt, ...) {
+    va_list ap;
+    va_start(ap, fmt);
+    init_klog_vwrite(level, fmt, ap);
+    va_end(ap);
+}
+
+int selinux_klog_callback(int type, const char *fmt, ...) {
+    int level = KLOG_ERROR_LEVEL;
+    if (type == SELINUX_WARNING) {
+        level = KLOG_WARNING_LEVEL;
+    } else if (type == SELINUX_INFO) {
+        level = KLOG_INFO_LEVEL;
+    }
+    va_list ap;
+    va_start(ap, fmt);
+    init_klog_vwrite(level, fmt, ap);
+    va_end(ap);
+    return 0;
+}
diff --git a/init/log.h b/init/log.h
index e9cb65a..b804d1f 100644
--- a/init/log.h
+++ b/init/log.h
@@ -19,10 +19,11 @@
 
 #include <cutils/klog.h>
 
-#define ERROR(x...)   KLOG_ERROR("init", x)
-#define NOTICE(x...)  KLOG_NOTICE("init", x)
-#define INFO(x...)    KLOG_INFO("init", x)
+#define ERROR(x...)   init_klog_write(KLOG_ERROR_LEVEL, x)
+#define NOTICE(x...)  init_klog_write(KLOG_NOTICE_LEVEL, x)
+#define INFO(x...)    init_klog_write(KLOG_INFO_LEVEL, x)
 
-extern int log_callback(int type, const char *fmt, ...);
+void init_klog_write(int level, const char* fmt, ...) __printflike(2, 3);
+int selinux_klog_callback(int level, const char* fmt, ...) __printflike(2, 3);
 
 #endif
diff --git a/init/property_service.cpp b/init/property_service.cpp
index 363b377..2fa81d4 100644
--- a/init/property_service.cpp
+++ b/init/property_service.cpp
@@ -54,7 +54,7 @@
 #define PERSISTENT_PROPERTY_DIR  "/data/property"
 
 static int persistent_properties_loaded = 0;
-static int property_area_inited = 0;
+static bool property_area_initialized = false;
 
 static int property_set_fd = -1;
 
@@ -63,34 +63,25 @@ struct workspace {
     int fd;
 };
 
-static int init_workspace(workspace *w, size_t size)
-{
-    int fd = open(PROP_FILENAME, O_RDONLY | O_NOFOLLOW);
-    if (fd < 0)
-        return -1;
-
-    w->size = size;
-    w->fd = fd;
-    return 0;
-}
-
 static workspace pa_workspace;
 
-static int init_property_area(void)
-{
-    if (property_area_inited)
-        return -1;
-
-    if(__system_property_area_init())
-        return -1;
+void property_init() {
+    if (property_area_initialized) {
+        return;
+    }
 
-    if(init_workspace(&pa_workspace, 0))
-        return -1;
+    property_area_initialized = true;
 
-    fcntl(pa_workspace.fd, F_SETFD, FD_CLOEXEC);
+    if (__system_property_area_init()) {
+        return;
+    }
 
-    property_area_inited = 1;
-    return 0;
+    pa_workspace.size = 0;
+    pa_workspace.fd = open(PROP_FILENAME, O_RDONLY | O_NOFOLLOW | O_CLOEXEC);
+    if (pa_workspace.fd == -1) {
+        ERROR("Failed to open %s: %s\n", PROP_FILENAME, strerror(errno));
+        return;
+    }
 }
 
 static int check_mac_perms(const char *name, char *sctx)
@@ -419,12 +410,13 @@ static void load_properties(char *data, const char *filter)
  * Filter is used to decide which properties to load: NULL loads all keys,
  * "ro.foo.*" is a prefix match, and "ro.foo.bar" is an exact match.
  */
-static void load_properties_from_file(const char *fn, const char *filter)
-{
+static void load_properties_from_file(const char* filename, const char* filter) {
+    Timer t;
     std::string data;
-    if (read_file(fn, &data)) {
+    if (read_file(filename, &data)) {
         load_properties(&data[0], filter);
     }
+    NOTICE("(Loading properties from %s took %.2fs.)\n", filename, t.duration());
 }
 
 static void load_persistent_properties() {
@@ -485,19 +477,12 @@ static void load_persistent_properties() {
     }
 }
 
-void property_init(void)
-{
-    init_property_area();
-}
-
-void property_load_boot_defaults(void)
-{
+void property_load_boot_defaults() {
     load_properties_from_file(PROP_PATH_RAMDISK_DEFAULT, NULL);
 }
 
-int properties_inited(void)
-{
-    return property_area_inited;
+bool properties_initialized() {
+    return property_area_initialized;
 }
 
 static void load_override_properties() {
@@ -510,21 +495,18 @@ static void load_override_properties() {
     }
 }
 
-
 /* When booting an encrypted system, /data is not mounted when the
  * property service is started, so any properties stored there are
  * not loaded.  Vold triggers init to load these properties once it
  * has mounted /data.
  */
-void load_persist_props(void)
-{
+void load_persist_props(void) {
     load_override_properties();
     /* Read persistent properties after all default values have been loaded. */
     load_persistent_properties();
 }
 
-void load_all_props(void)
-{
+void load_all_props() {
     load_properties_from_file(PROP_PATH_SYSTEM_BUILD, NULL);
     load_properties_from_file(PROP_PATH_SYSTEM_DEFAULT, NULL);
     load_properties_from_file(PROP_PATH_VENDOR_BUILD, NULL);
@@ -537,12 +519,10 @@ void load_all_props(void)
     load_persistent_properties();
 }
 
-void start_property_service(void)
-{
-    int fd;
+void start_property_service() {
+    int fd = create_socket(PROP_SERVICE_NAME, SOCK_STREAM, 0666, 0, 0, NULL);
+    if (fd == -1) return;
 
-    fd = create_socket(PROP_SERVICE_NAME, SOCK_STREAM, 0666, 0, 0, NULL);
-    if(fd < 0) return;
     fcntl(fd, F_SETFD, FD_CLOEXEC);
     fcntl(fd, F_SETFL, O_NONBLOCK);
 
@@ -550,7 +530,6 @@ void start_property_service(void)
     property_set_fd = fd;
 }
 
-int get_property_set_fd()
-{
+int get_property_set_fd() {
     return property_set_fd;
 }
diff --git a/init/property_service.h b/init/property_service.h
index 6e7fc00..825a7dd 100644
--- a/init/property_service.h
+++ b/init/property_service.h
@@ -29,7 +29,7 @@ extern void start_property_service(void);
 void get_property_workspace(int *fd, int *sz);
 extern int __property_get(const char *name, char *value);
 extern int property_set(const char *name, const char *value);
-extern int properties_inited();
+extern bool properties_initialized();
 int get_property_set_fd(void);
 
 #ifndef __clang__
diff --git a/init/signal_handler.cpp b/init/signal_handler.cpp
index c428b96..8be4af5 100644
--- a/init/signal_handler.cpp
+++ b/init/signal_handler.cpp
@@ -18,18 +18,23 @@
 #include <fcntl.h>
 #include <signal.h>
 #include <stdio.h>
-#include <unistd.h>
-#include <sys/types.h>
 #include <sys/socket.h>
+#include <sys/types.h>
 #include <sys/wait.h>
-#include <cutils/sockets.h>
+#include <unistd.h>
+
+#include <base/stringprintf.h>
 #include <cutils/android_reboot.h>
 #include <cutils/list.h>
+#include <cutils/sockets.h>
 
 #include "init.h"
 #include "log.h"
 #include "util.h"
 
+#define CRITICAL_CRASH_THRESHOLD    4       /* if we crash >4 times ... */
+#define CRITICAL_CRASH_WINDOW       (4*60)  /* ... in 4 minutes, goto recovery */
+
 static int signal_fd = -1;
 static int signal_recv_fd = -1;
 
@@ -37,8 +42,17 @@ static void sigchld_handler(int s) {
     write(signal_fd, &s, 1);
 }
 
-#define CRITICAL_CRASH_THRESHOLD    4       /* if we crash >4 times ... */
-#define CRITICAL_CRASH_WINDOW       (4*60)  /* ... in 4 minutes, goto recovery */
+std::string DescribeStatus(int status) {
+    if (WIFEXITED(status)) {
+        return android::base::StringPrintf("exited with status %d", WEXITSTATUS(status));
+    } else if (WIFSIGNALED(status)) {
+        return android::base::StringPrintf("killed by signal %d", WTERMSIG(status));
+    } else if (WIFSTOPPED(status)) {
+        return android::base::StringPrintf("stopped by signal %d", WSTOPSIG(status));
+    } else {
+        return "state changed";
+    }
+}
 
 static int wait_for_one_process() {
     int status;
@@ -46,28 +60,26 @@ static int wait_for_one_process() {
     if (pid <= 0) {
         return -1;
     }
-    INFO("waitpid returned pid %d, status = %08x\n", pid, status);
 
     service* svc = service_find_by_pid(pid);
+
+    std::string name;
+    if (svc) {
+        name = android::base::StringPrintf("Service '%s' (pid %d)", svc->name, pid);
+    } else {
+        name = android::base::StringPrintf("Untracked pid %d", pid);
+    }
+
+    NOTICE("%s %s\n", name.c_str(), DescribeStatus(status).c_str());
+
     if (!svc) {
-        if (WIFEXITED(status)) {
-            ERROR("untracked pid %d exited with status %d\n", pid, WEXITSTATUS(status));
-        } else if (WIFSIGNALED(status)) {
-            ERROR("untracked pid %d killed by signal %d\n", pid, WTERMSIG(status));
-        } else if (WIFSTOPPED(status)) {
-            ERROR("untracked pid %d stopped by signal %d\n", pid, WSTOPSIG(status));
-        } else {
-            ERROR("untracked pid %d state changed\n", pid);
-        }
         return 0;
     }
 
     // TODO: all the code from here down should be a member function on service.
 
-    NOTICE("process '%s', pid %d exited\n", svc->name, pid);
-
     if (!(svc->flags & SVC_ONESHOT) || (svc->flags & SVC_RESTART)) {
-        NOTICE("process '%s' killing any children in process group\n", svc->name);
+        NOTICE("Service '%s' (pid %d) killing any children in process group\n", svc->name, pid);
         kill(-pid, SIGKILL);
     }
 
diff --git a/init/ueventd.cpp b/init/ueventd.cpp
index 5af6e3d..c63fdaa 100644
--- a/init/ueventd.cpp
+++ b/init/ueventd.cpp
@@ -14,16 +14,17 @@
  * limitations under the License.
  */
 
-#include <poll.h>
-#include <fcntl.h>
-#include <string.h>
-#include <stdlib.h>
-#include <stdio.h>
 #include <ctype.h>
+#include <fcntl.h>
+#include <poll.h>
 #include <signal.h>
-#include <selinux/selinux.h>
+#include <stdio.h>
+#include <stdlib.h>
+#include <string.h>
 
+#include <base/stringprintf.h>
 #include <private/android_filesystem_config.h>
+#include <selinux/selinux.h>
 
 #include "ueventd.h"
 #include "log.h"
@@ -34,11 +35,6 @@
 
 int ueventd_main(int argc, char **argv)
 {
-    struct pollfd ufd;
-    int nr;
-    char hardware[PROP_VALUE_MAX];
-    char tmp[32];
-
     /*
      * init sets the umask to 077 for forked processes. We need to
      * create files with exact permissions, without modification by
@@ -55,38 +51,35 @@ int ueventd_main(int argc, char **argv)
 
     open_devnull_stdio();
     klog_init();
-    if (LOG_UEVENTS) {
-        /* Ensure we're at a logging level that will show the events */
-        if (klog_get_level() < KLOG_INFO_LEVEL) {
-            klog_set_level(KLOG_INFO_LEVEL);
-        }
-    }
+    klog_set_level(KLOG_NOTICE_LEVEL);
 
-    union selinux_callback cb;
-    cb.func_log = log_callback;
-    selinux_set_callback(SELINUX_CB_LOG, cb);
+    NOTICE("ueventd started!\n");
 
-    INFO("starting ueventd\n");
+    selinux_callback cb;
+    cb.func_log = selinux_klog_callback;
+    selinux_set_callback(SELINUX_CB_LOG, cb);
 
+    char hardware[PROP_VALUE_MAX];
     property_get("ro.hardware", hardware);
 
     ueventd_parse_config_file("/ueventd.rc");
-
-    snprintf(tmp, sizeof(tmp), "/ueventd.%s.rc", hardware);
-    ueventd_parse_config_file(tmp);
+    ueventd_parse_config_file(android::base::StringPrintf("/ueventd.%s.rc", hardware).c_str());
 
     device_init();
 
+    pollfd ufd;
     ufd.events = POLLIN;
     ufd.fd = get_device_fd();
 
-    while(1) {
+    while (true) {
         ufd.revents = 0;
-        nr = poll(&ufd, 1, -1);
-        if (nr <= 0)
+        int nr = poll(&ufd, 1, -1);
+        if (nr <= 0) {
             continue;
-        if (ufd.revents & POLLIN)
-               handle_device_fd();
+        }
+        if (ufd.revents & POLLIN) {
+            handle_device_fd();
+        }
     }
 
     return 0;
diff --git a/init/util.cpp b/init/util.cpp
index 8b238d4..3b49b30 100644
--- a/init/util.cpp
+++ b/init/util.cpp
@@ -258,22 +258,16 @@ int mtd_name_to_number(const char *name)
     return -1;
 }
 
-/*
- * gettime() - returns the time in seconds of the system's monotonic clock or
- * zero on error.
- */
-time_t gettime(void)
-{
-    struct timespec ts;
-    int ret;
-
-    ret = clock_gettime(CLOCK_MONOTONIC, &ts);
-    if (ret < 0) {
-        ERROR("clock_gettime(CLOCK_MONOTONIC) failed: %s\n", strerror(errno));
-        return 0;
-    }
+time_t gettime() {
+    timespec now;
+    clock_gettime(CLOCK_MONOTONIC, &now);
+    return now.tv_sec;
+}
 
-    return ts.tv_sec;
+uint64_t gettime_ns() {
+    timespec now;
+    clock_gettime(CLOCK_MONOTONIC, &now);
+    return static_cast<uint64_t>(now.tv_sec) * UINT64_C(1000000000) + now.tv_nsec;
 }
 
 int mkdir_recursive(const char *pathname, mode_t mode)
diff --git a/init/util.h b/init/util.h
index e0b3c69..8fec7a8 100644
--- a/init/util.h
+++ b/init/util.h
@@ -33,7 +33,22 @@ int create_socket(const char *name, int type, mode_t perm,
 bool read_file(const char* path, std::string* content);
 int write_file(const char* path, const char* content);
 
-time_t gettime(void);
+time_t gettime();
+uint64_t gettime_ns();
+
+class Timer {
+ public:
+  Timer() : t0(gettime_ns()) {
+  }
+
+  double duration() {
+    return static_cast<double>(gettime_ns() - t0) / 1000000000.0;
+  }
+
+ private:
+  uint64_t t0;
+};
+
 unsigned int decode_uid(const char *s);
 
 int mkdir_recursive(const char *pathname, mode_t mode);
diff --git a/init/watchdogd.cpp b/init/watchdogd.cpp
index 0790811..881a4df 100644
--- a/init/watchdogd.cpp
+++ b/init/watchdogd.cpp
@@ -27,52 +27,45 @@
 
 #define DEV_NAME "/dev/watchdog"
 
-int watchdogd_main(int argc, char **argv)
-{
-    int fd;
-    int ret;
-    int interval = 10;
-    int margin = 10;
-    int timeout;
-
+int watchdogd_main(int argc, char **argv) {
     open_devnull_stdio();
     klog_init();
+    klog_set_level(KLOG_NOTICE_LEVEL);
 
-    INFO("Starting watchdogd\n");
-
-    if (argc >= 2)
-        interval = atoi(argv[1]);
+    int interval = 10;
+    if (argc >= 2) interval = atoi(argv[1]);
 
-    if (argc >= 3)
-        margin = atoi(argv[2]);
+    int margin = 10;
+    if (argc >= 3) margin = atoi(argv[2]);
 
-    timeout = interval + margin;
+    NOTICE("watchdogd started (interval %d, margin %d)!\n", interval, margin);
 
-    fd = open(DEV_NAME, O_RDWR|O_CLOEXEC);
-    if (fd < 0) {
+    int fd = open(DEV_NAME, O_RDWR|O_CLOEXEC);
+    if (fd == -1) {
         ERROR("watchdogd: Failed to open %s: %s\n", DEV_NAME, strerror(errno));
         return 1;
     }
 
-    ret = ioctl(fd, WDIOC_SETTIMEOUT, &timeout);
+    int timeout = interval + margin;
+    int ret = ioctl(fd, WDIOC_SETTIMEOUT, &timeout);
     if (ret) {
         ERROR("watchdogd: Failed to set timeout to %d: %s\n", timeout, strerror(errno));
         ret = ioctl(fd, WDIOC_GETTIMEOUT, &timeout);
         if (ret) {
             ERROR("watchdogd: Failed to get timeout: %s\n", strerror(errno));
         } else {
-            if (timeout > margin)
+            if (timeout > margin) {
                 interval = timeout - margin;
-            else
+            } else {
                 interval = 1;
+            }
             ERROR("watchdogd: Adjusted interval to timeout returned by driver: timeout %d, interval %d, margin %d\n",
                   timeout, interval, margin);
         }
     }
 
-    while(1) {
+    while (true) {
         write(fd, "", 1);
         sleep(interval);
     }
 }
-
diff --git a/libcutils/klog.c b/libcutils/klog.c
index fbb7b72..fad2a8b 100644
--- a/libcutils/klog.c
+++ b/libcutils/klog.c
@@ -14,13 +14,14 @@
  * limitations under the License.
  */
 
-#include <sys/stat.h>
-#include <sys/types.h>
+#include <errno.h>
 #include <fcntl.h>
 #include <stdarg.h>
 #include <stdio.h>
 #include <stdlib.h>
 #include <string.h>
+#include <sys/stat.h>
+#include <sys/types.h>
 #include <unistd.h>
 
 #include <cutils/klog.h>
@@ -36,41 +37,39 @@ void klog_set_level(int level) {
     klog_level = level;
 }
 
-void klog_init(void)
-{
-    static const char *name = "/dev/__kmsg__";
-
+void klog_init(void) {
     if (klog_fd >= 0) return; /* Already initialized */
 
+    static const char *name = "/dev/__kmsg__";
     if (mknod(name, S_IFCHR | 0600, (1 << 8) | 11) == 0) {
-        klog_fd = open(name, O_WRONLY);
-        if (klog_fd < 0)
-                return;
-        fcntl(klog_fd, F_SETFD, FD_CLOEXEC);
+        klog_fd = open(name, O_WRONLY | O_CLOEXEC);
+        if (klog_fd == -1) {
+            return;
+        }
         unlink(name);
     }
 }
 
 #define LOG_BUF_MAX 512
 
-void klog_vwrite(int level, const char *fmt, va_list ap)
-{
-    char buf[LOG_BUF_MAX];
-
+void klog_writev(int level, const struct iovec* iov, int iov_count) {
     if (level > klog_level) return;
     if (klog_fd < 0) klog_init();
     if (klog_fd < 0) return;
-
-    vsnprintf(buf, LOG_BUF_MAX, fmt, ap);
-    buf[LOG_BUF_MAX - 1] = 0;
-
-    write(klog_fd, buf, strlen(buf));
+    TEMP_FAILURE_RETRY(writev(klog_fd, iov, iov_count));
 }
 
-void klog_write(int level, const char *fmt, ...)
-{
+void klog_write(int level, const char* fmt, ...) {
+    char buf[LOG_BUF_MAX];
     va_list ap;
     va_start(ap, fmt);
-    klog_vwrite(level, fmt, ap);
+    vsnprintf(buf, sizeof(buf), fmt, ap);
     va_end(ap);
+
+    buf[LOG_BUF_MAX - 1] = 0;
+
+    struct iovec iov[1];
+    iov[0].iov_base = buf;
+    iov[0].iov_len = strlen(buf);
+    klog_writev(level, iov, 1);
 }
diff --git a/rootdir/init.rc b/rootdir/init.rc
index bc36c3e..3ae0954 100644
--- a/rootdir/init.rc
+++ b/rootdir/init.rc
@@ -32,8 +32,6 @@ on early-init
 on init
     sysclktz 0
 
-    loglevel 3
-
     # Backward compatibility.
     symlink /system/etc /etc
     symlink /sys/kernel/debug /d