Log more timing information from init.

Also make important events in init's life NOTICE rather than INFO,
and ensure that NOTICE events actually make it to the kernel log.

Also fix the logging so that if you have a printf format string
error, the compiler now catches it.

Also give messages from init, ueventd, and watchdogd distinct tags.
(Previously they'd all call themselves "init", and dmesg doesn't
include pids, so you couldn't untangle them.)

Also include the tag in SELinux messages.

Bug: 19544788
Change-Id: Ica6daea065bfdb80155c52c0b06f346a7df208fe
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 @@
 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 @@
     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 @@
     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 @@
 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 @@
         }
     }
 
-    NOTICE("starting '%s'\n", svc->name);
+    NOTICE("Starting service '%s'...\n", svc->name);
 
     pid_t pid = fork();
     if (pid == 0) {
@@ -256,7 +256,7 @@
         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 @@
     }
 
     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 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 @@
         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 @@
     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;
 
-static void selinux_initialize(void)
-{
+    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);
+
     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 @@
     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 @@
     // 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 @@
     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 <fcntl.h>
+#include <inttypes.h>
+#include <stdarg.h>
+#include <stddef.h>
 #include <stdio.h>
 #include <stdlib.h>
-#include <unistd.h>
-#include <fcntl.h>
-#include <stdarg.h>
 #include <string.h>
-#include <stddef.h>
-#include <ctype.h>
+#include <unistd.h>
 
 #include "init.h"
 #include "parser.h"
@@ -351,7 +352,7 @@
     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 @@
 
 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 @@
 
     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 @@
     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 @@
     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;
+void property_init() {
+    if (property_area_initialized) {
+        return;
+    }
 
-    if(__system_property_area_init())
-        return -1;
+    property_area_initialized = true;
 
-    if(init_workspace(&pa_workspace, 0))
-        return -1;
+    if (__system_property_area_init()) {
+        return;
+    }
 
-    fcntl(pa_workspace.fd, F_SETFD, FD_CLOEXEC);
-
-    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 @@
  * 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 @@
     }
 }
 
-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 @@
     }
 }
 
-
 /* 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 @@
     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 @@
     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 @@
 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 @@
     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 @@
     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 @@
 
     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;
+    NOTICE("ueventd started!\n");
+
+    selinux_callback cb;
+    cb.func_log = selinux_klog_callback;
     selinux_set_callback(SELINUX_CB_LOG, cb);
 
-    INFO("starting ueventd\n");
-
+    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 @@
     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;
+time_t gettime() {
+    timespec now;
+    clock_gettime(CLOCK_MONOTONIC, &now);
+    return now.tv_sec;
+}
 
-    ret = clock_gettime(CLOCK_MONOTONIC, &ts);
-    if (ret < 0) {
-        ERROR("clock_gettime(CLOCK_MONOTONIC) failed: %s\n", strerror(errno));
-        return 0;
-    }
-
-    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 @@
 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");
+    int interval = 10;
+    if (argc >= 2) interval = atoi(argv[1]);
 
-    if (argc >= 2)
-        interval = atoi(argv[1]);
+    int margin = 10;
+    if (argc >= 3) margin = atoi(argv[2]);
 
-    if (argc >= 3)
-        margin = atoi(argv[2]);
+    NOTICE("watchdogd started (interval %d, margin %d)!\n", interval, margin);
 
-    timeout = 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);
     }
 }
-