commit 7bc7a0ca2609a62d389ac0a73c84e2a6807f6614
author Keun-young Park <keunyoung@google.com> Thu Apr 27 16:25:06 2017 -0700
committer Keun-young Park <keunyoung@google.com> Fri Apr 28 11:20:12 2017 -0700
tree 7e9d6fb49aab4220af4387fb58b99f4e72a68eb5
parent 323e2dffb2e122465f363c5fc7f36e833cb3f113

combine wait for exec log with service exit log

- allows easier tracking of wait time from monitoring tools
- this change also reduces unnecessary log spam
- service exit log looks like this:
  init: Service 'exec 4 (/system/bin/otapreopt_slot)' (pid 611) exited with status 0 waiting took 0.060771 seconds

bug: 37752410
Test: reboot and check log
Change-Id: I122902538697f33939eede548e39f155ec419e03

init/service.cpp

diff --git a/init/service.cpp b/init/service.cpp
index 2284a21..39f6709 100644
--- a/init/service.cpp
+++ b/init/service.cpp
@@ -274,10 +274,6 @@
     std::for_each(descriptors_.begin(), descriptors_.end(),
                   std::bind(&DescriptorInfo::Clean, std::placeholders::_1));
 
-    if (flags_ & SVC_EXEC) {
-        LOG(INFO) << "SVC_EXEC pid " << pid_ << " finished...";
-    }
-
     if (flags_ & SVC_TEMPORARY) {
         return;
     }
@@ -1047,21 +1043,26 @@
     Service* svc = FindServiceByPid(pid);
 
     std::string name;
+    std::string wait_string;
     if (svc) {
         name = android::base::StringPrintf("Service '%s' (pid %d)",
                                            svc->name().c_str(), pid);
+        if (svc->flags() & SVC_EXEC) {
+            wait_string =
+                android::base::StringPrintf(" waiting took %f seconds", exec_waiter_->duration_s());
+        }
     } else {
         name = android::base::StringPrintf("Untracked pid %d", pid);
     }
 
     if (WIFEXITED(status)) {
-        LOG(INFO) << name << " exited with status " << WEXITSTATUS(status);
+        LOG(INFO) << name << " exited with status " << WEXITSTATUS(status) << wait_string;
     } else if (WIFSIGNALED(status)) {
-        LOG(INFO) << name << " killed by signal " << WTERMSIG(status);
+        LOG(INFO) << name << " killed by signal " << WTERMSIG(status) << wait_string;
     } else if (WIFSTOPPED(status)) {
-        LOG(INFO) << name << " stopped by signal " << WSTOPSIG(status);
+        LOG(INFO) << name << " stopped by signal " << WSTOPSIG(status) << wait_string;
     } else {
-        LOG(INFO) << name << " state changed";
+        LOG(INFO) << name << " state changed" << wait_string;
     }
 
     if (!svc) {
@@ -1071,7 +1072,6 @@
     svc->Reap();
 
     if (svc->flags() & SVC_EXEC) {
-        LOG(INFO) << "Wait for exec took " << *exec_waiter_;
         exec_waiter_.reset();
     }
     if (svc->flags() & SVC_TEMPORARY) {