Android平台：Android7.1
先从shutdown thread 入手，出现两个时间比较久
看这份打印 “开机慢打印 serial_com5_2020-01-11_11-43-06.log”
从这行打印开始
[2020/1/11 13:44:43] [ 147.932572@3] input input1: key 116 up
01-01 08:02:31.332 4233 5219 I ShutdownThread: Sending shutdown broadcast...
01-01 08:02:32.024 4233 5219 I ShutdownThread: Shutting down activity manager...
01-01 08:02:32.185 4233 5219 I ShutdownThread: Shutting down package manager...
01-01 08:02:32.200 4233 5226 W ShutdownThread: Disabling Bluetooth...
01-01 08:02:32.200 4233 5226 I ShutdownThread: Waiting for NFC, Bluetooth and Radio...
01-01 08:02:35.711 4233 5226 I ShutdownThread: Bluetooth turned off.
01-01 08:02:35.711 4233 5226 I ShutdownThread: NFC, Radio and Bluetooth shutdown complete.
01-01 08:02:35.713 4233 5219 I ShutdownThread: Shutting down MountService
01-01 08:02:42.033 4233 4268 W ShutdownThread: Result code 0 from MountService.shutdown
01-01 . 08:02:42.539 4233 5219 I ShutdownThread: Performing low-level shutdown...
这里面两个时间比较异常，是蓝牙关闭和mount serveice关机时间
蓝牙关闭函数这个时间随便是开了个线程在跑，但其实是阻塞的，注释将其改为非阻塞
+ /* My Patch Start */
+ /*
try {
t.join(timeout);
} catch (InterruptedException ex) {
@@ -661,6 +681,8 @@ public final class ShutdownThread extends Thread {
if (!done[0]) {
Log.w(TAG, "Timed out waiting for NFC, Radio and Bluetooth shutdown.");
}
+ */
+ /* My Patch End */
这样子蓝牙关闭时间是和mountservice shutdown 并行的，然后在mountservice shutdown后判断蓝牙是否关闭完再看是否阻塞等待
在Shutdown Thread 中
@@ -517,6 +520,14 @@ public final class ShutdownThread extends Thread {
// 在mountservice shutdown后判断蓝牙是否关闭完
+ /* My Patch Start */
+ int shutdownRadiosDelay = 0;
+ while (!mShutdownRadiosDone && shutdownRadiosDelay < MAX_RADIO_WAIT_TIME) {
+ SystemClock.sleep(PHONE_STATE_POLL_SLEEP_MSEC);
+ shutdownRadiosDelay += PHONE_STATE_POLL_SLEEP_MSEC;
+ }
+ /* My Patch End */
+
if (mRebootHasProgressBar) {
sInstance.setRebootProgress(MOUNT_SERVICE_STOP_PERCENT, null);
@@ -650,10 +661,19 @@ public final class ShutdownThread extends Thread {
delay = endTime - SystemClock.elapsedRealtime();
}
//蓝牙是否关闭置位
+ /* My Patch Start */
+ /* while loop timeout to shutdown */
+ mShutdownRadiosDone = true;
+ if (!done[0]) {
+ Log.w(TAG, "Timed out waiting for NFC, Radio and Bluetooth shutdown.");
+ }
+ /* My Patch End */
}
};
第二个时间是mountservice关闭时间比较久，通过flow trace 到 vold这边做unmount的时候耗时久，下面是加的一些打印 diff
tmp log debug
diff --git a/Disk.cpp b/Disk.cpp
index 7b0c149..d0cbe59 100644
--- a/Disk.cpp
+++ b/Disk.cpp
@@ -233,10 +233,13 @@ void Disk::createPrivateVolume(dev_t device, const std::string& partGuid) {
}
void Disk::destroyAllVolumes() {
+ LOG(ERROR) << "Horace Enter " << __FUNCTION__;
for (auto vol : mVolumes) {
+ LOG(ERROR) << "Horace Enter " << __FUNCTION__ << vol;
vol->destroy();
}
mVolumes.clear();
+ LOG(ERROR) << "Horace Leave " << __FUNCTION__;
}
status_t Disk::readMetadata() {
diff --git a/EmulatedVolume.cpp b/EmulatedVolume.cpp
index 581c322..34b5a29 100644
--- a/EmulatedVolume.cpp
+++ b/EmulatedVolume.cpp
@@ -111,7 +111,9 @@ status_t EmulatedVolume::doUnmount() {
// the FUSE process first, most file system operations will return
// ENOTCONN until the unmount completes. This is an exotic and unusual
// error code and might cause broken behaviour in applications.
+ LOG(ERROR) << "Horace Enter " << __FILE__ << " " <<__FUNCTION__ << " " << __LINE__;
KillProcessesUsingPath(getPath());
+ LOG(ERROR) << "Horace Enter " << __FILE__ << " " <<__FUNCTION__ << " " << __LINE__;
ForceUnmount(mFuseDefault);
ForceUnmount(mFuseRead);
ForceUnmount(mFuseWrite);
diff --git a/PrivateVolume.cpp b/PrivateVolume.cpp
index e5809fb..b9f7102 100644
--- a/PrivateVolume.cpp
+++ b/PrivateVolume.cpp
@@ -87,6 +87,7 @@ status_t PrivateVolume::doDestroy() {
if (cryptfs_revert_ext_volume(getId().c_str())) {
LOG(ERROR) << getId() << " failed to revert cryptfs";
}
+ LOG(ERROR) << "Horace Enter " << __FILE__ << " " <<__FUNCTION__ << " " << __LINE__;
return DestroyDeviceNode(mRawDevPath);
}
@@ -163,11 +164,14 @@ status_t PrivateVolume::doMount() {
}
status_t PrivateVolume::doUnmount() {
+ LOG(ERROR) << "Horace Enter " << __FILE__ << " " <<__FUNCTION__ << " " << __LINE__;
ForceUnmount(mPath);
+ LOG(ERROR) << "Horace Enter " << __FILE__ << " " <<__FUNCTION__ << " " << __LINE__;
if (TEMP_FAILURE_RETRY(rmdir(mPath.c_str()))) {
PLOG(ERROR) << getId() << " failed to rmdir mount point " << mPath;
}
+ LOG(ERROR) << "Horace Enter " << __FILE__ << " " <<__FUNCTION__ << " " << __LINE__;
return OK;
}
diff --git a/PublicVolume.cpp b/PublicVolume.cpp
index d4dfc8c..0aa7168 100644
--- a/PublicVolume.cpp
+++ b/PublicVolume.cpp
@@ -114,6 +114,7 @@ status_t PublicVolume::doCreate() {
status_t PublicVolume::doDestroy() {
if (mJustPhysicalDev) return 0;
+ LOG(ERROR) << "Horace Enter " << __FUNCTION__ << __LINE__;
return DestroyDeviceNode(mDevPath);
}
@@ -329,6 +330,7 @@ status_t PublicVolume::doUnmount() {
// ENOTCONN until the unmount completes. This is an exotic and unusual
// error code and might cause broken behaviour in applications.
KillProcessesUsingPath(getPath());
+ LOG(ERROR) << "Horace Enter " << __FILE__ << " " <<__FUNCTION__ << " " << __LINE__;
#ifdef HAS_VIRTUAL_CDROM
std::string stableName = getId();
@@ -346,22 +348,26 @@ status_t PublicVolume::doUnmount() {
ForceUnmount(mFuseRead);
ForceUnmount(mFuseWrite);
ForceUnmount(mRawPath);
+ LOG(ERROR) << "Horace Enter " << __FILE__ << " " <<__FUNCTION__ << " " << __LINE__;
if (mFusePid > 0) {
kill(mFusePid, SIGTERM);
TEMP_FAILURE_RETRY(waitpid(mFusePid, nullptr, 0));
mFusePid = 0;
}
+ LOG(ERROR) << "Horace Enter " << __FILE__ << " " <<__FUNCTION__ << " " << __LINE__;
rmdir(mFuseDefault.c_str());
rmdir(mFuseRead.c_str());
rmdir(mFuseWrite.c_str());
rmdir(mRawPath.c_str());
+ LOG(ERROR) << "Horace Enter " << __FILE__ << " " <<__FUNCTION__ << " " << __LINE__;
mFuseDefault.clear();
mFuseRead.clear();
mFuseWrite.clear();
mRawPath.clear();
+ LOG(ERROR) << "Horace Enter " << __FILE__ << " " <<__FUNCTION__ << " " << __LINE__;
return OK;
}
diff --git a/Utils.cpp b/Utils.cpp
index 260e77e..2c58d73 100644
--- a/Utils.cpp
+++ b/Utils.cpp
@@ -120,27 +120,33 @@ status_t PrepareDir(const std::string& path, mode_t mode, uid_t uid, gid_t gid)
status_t ForceUnmount(const std::string& path) {
const char* cpath = path.c_str();
+ LOG(ERROR) << "Horace Enter " << __FILE__ << " " <<__FUNCTION__ << " " << __LINE__ << path;
if (!umount2(cpath, UMOUNT_NOFOLLOW) || errno == EINVAL || errno == ENOENT) {
return OK;
}
+ LOG(ERROR) << "Horace Enter " << __FILE__ << " " <<__FUNCTION__ << " " << __LINE__;
// Apps might still be handling eject request, so wait before
// we start sending signals
sleep(5);
+ LOG(ERROR) << "Horace Enter " << __FILE__ << " " <<__FUNCTION__ << " " << __LINE__;
Process::killProcessesWithOpenFiles(cpath, SIGINT);
sleep(5);
+ LOG(ERROR) << "Horace Enter " << __FILE__ << " " <<__FUNCTION__ << " " << __LINE__;
if (!umount2(cpath, UMOUNT_NOFOLLOW) || errno == EINVAL || errno == ENOENT) {
return OK;
}
Process::killProcessesWithOpenFiles(cpath, SIGTERM);
sleep(5);
+ LOG(ERROR) << "Horace Enter " << __FILE__ << " " <<__FUNCTION__ << " " << __LINE__;
if (!umount2(cpath, UMOUNT_NOFOLLOW) || errno == EINVAL || errno == ENOENT) {
return OK;
}
Process::killProcessesWithOpenFiles(cpath, SIGKILL);
sleep(5);
+ LOG(ERROR) << "Horace Enter " << __FILE__ << " " <<__FUNCTION__ << " " << __LINE__;
if (!umount2(cpath, UMOUNT_NOFOLLOW) || errno == EINVAL || errno == ENOENT) {
return OK;
}
@@ -150,20 +156,24 @@ status_t ForceUnmount(const std::string& path) {
status_t KillProcessesUsingPath(const std::string& path) {
const char* cpath = path.c_str();
+ LOG(ERROR) << "Horace Enter " << __FILE__ << " " <<__FUNCTION__ << " " << __LINE__ << path;
if (Process::killProcessesWithOpenFiles(cpath, SIGINT) == 0) {
return OK;
}
sleep(5);
+ LOG(ERROR) << "Horace Enter " << __FILE__ << " " <<__FUNCTION__ << " " << __LINE__;
if (Process::killProcessesWithOpenFiles(cpath, SIGTERM) == 0) {
return OK;
}
sleep(5);
+ LOG(ERROR) << "Horace Enter " << __FILE__ << " " <<__FUNCTION__ << " " << __LINE__;
if (Process::killProcessesWithOpenFiles(cpath, SIGKILL) == 0) {
return OK;
}
sleep(5);
+ LOG(ERROR) << "Horace Enter " << __FILE__ << " " <<__FUNCTION__ << " " << __LINE__;
// Send SIGKILL a second time to determine if we've
// actually killed everyone with open files
diff --git a/VolumeBase.cpp b/VolumeBase.cpp
index ea4d372..0bb99d6 100644
--- a/VolumeBase.cpp
+++ b/VolumeBase.cpp
@@ -177,13 +177,17 @@ status_t VolumeBase::doCreate() {
status_t VolumeBase::destroy() {
CHECK(mCreated);
+ LOG(ERROR) << "Horace Enter " << __FILE__ << " " <<__FUNCTION__ << " " << __LINE__;
if (mState == State::kMounted) {
+
+ LOG(ERROR) << "Horace Enter " << __FILE__ << " " <<__FUNCTION__ << " " << __LINE__;
unmount();
setState(State::kBadRemoval);
} else {
setState(State::kRemoved);
}
+ LOG(ERROR) << "Horace Enter " << __FILE__ << " " <<__FUNCTION__ << " " << __LINE__;
notifyEvent(ResponseCode::VolumeDestroyed);
status_t res = doDestroy();
@@ -217,6 +221,7 @@ status_t VolumeBase::unmount() {
LOG(WARNING) << getId() << " unmount requires state mounted";
return -EBUSY;
}
+ LOG(ERROR) << "Horace Enter " << __FILE__ << " " <<__FUNCTION__ << " " << __LINE__;
setState(State::kEjecting);
for (auto vol : mVolumes) {
@@ -226,8 +231,10 @@ status_t VolumeBase::unmount() {
}
}
mVolumes.clear();
+ LOG(ERROR) << "Horace Enter " << __FILE__ << " " <<__FUNCTION__ << " " << __LINE__;
status_t res = doUnmount();
+ LOG(ERROR) << "Horace Enter " << __FILE__ << " " <<__FUNCTION__ << " " << __LINE__;
setState(State::kUnmounted);
return res;
}
diff --git a/VolumeManager.cpp b/VolumeManager.cpp
index 746551f..3948772 100644
--- a/VolumeManager.cpp
+++ b/VolumeManager.cpp
@@ -210,7 +210,7 @@ VolumeManager *VolumeManager::Instance() {
}
VolumeManager::VolumeManager() {
- mDebug = false;
+ mDebug = true;
mActiveContainers = new AsecIdCollection();
mBroadcaster = NULL;
mUmsSharingCount = 0;
@@ -648,11 +648,14 @@ int VolumeManager::reset() {
}
int VolumeManager::shutdown() {
+ LOG(ERROR) << "Horace Enter " << __FILE__ << " " <<__FUNCTION__ << " " << __LINE__;
mInternalEmulated->destroy();
for (auto disk : mDisks) {
+ LOG(ERROR) << "Horace Enter " << __FILE__ << " " <<__FUNCTION__ << " " << __LINE__;
disk->destroy();
}
mDisks.clear();
+ LOG(ERROR) << "Horace Enter " << __FILE__ << " " <<__FUNCTION__ << " " << __LINE__;
return 0;
}
在做unmount的时候有个sleep 5 s给应用做eject的延时，不过这个修改在An8 后有优化，这边是An7.1的代码，所以会有这个问题，从master上找对应修改导入过来即可
- Various sleep(5) for vold shutdown can increase shutdown time a lot.
- If it is shutting down, do not sleep at all. init will take care of
active partitions if not unmounted.
bug: 64143519
Test: reboot and check logs from vold, check if "ShutdownThread: Shutdown wait timed out" happens.
Change-Id: I7cb91427ad2205fe23a054d255caf7ffdfd9f6c3
diff --git a/Utils.cpp b/Utils.cpp
index 260e77e..6e1d4b8 100644
--- a/Utils.cpp
+++ b/Utils.cpp
@@ -17,6 +17,7 @@
#include "sehandle.h"
#include "Utils.h"
#include "Process.h"
+#include "VolumeManager.h"
#include <android-base/file.h>
#include <android-base/logging.h>
@@ -125,22 +126,22 @@ status_t ForceUnmount(const std::string& path) {
}
// Apps might still be handling eject request, so wait before
// we start sending signals
- sleep(5);
+ if (!VolumeManager::shutting_down) sleep(5);
Process::killProcessesWithOpenFiles(cpath, SIGINT);
- sleep(5);
+ if (!VolumeManager::shutting_down) sleep(5);
if (!umount2(cpath, UMOUNT_NOFOLLOW) || errno == EINVAL || errno == ENOENT) {
return OK;
}
Process::killProcessesWithOpenFiles(cpath, SIGTERM);
- sleep(5);
+ if (!VolumeManager::shutting_down) sleep(5);
if (!umount2(cpath, UMOUNT_NOFOLLOW) || errno == EINVAL || errno == ENOENT) {
return OK;
}
Process::killProcessesWithOpenFiles(cpath, SIGKILL);
- sleep(5);
+ if (!VolumeManager::shutting_down) sleep(5);
if (!umount2(cpath, UMOUNT_NOFOLLOW) || errno == EINVAL || errno == ENOENT) {
return OK;
}
@@ -153,18 +154,18 @@ status_t KillProcessesUsingPath(const std::string& path) {
if (Process::killProcessesWithOpenFiles(cpath, SIGINT) == 0) {
return OK;
}
- sleep(5);
+ if (!VolumeManager::shutting_down) sleep(5);
if (Process::killProcessesWithOpenFiles(cpath, SIGTERM) == 0) {
return OK;
}
- sleep(5);
+ if (!VolumeManager::shutting_down) sleep(5);
if (Process::killProcessesWithOpenFiles(cpath, SIGKILL) == 0) {
return OK;
}
- sleep(5);
+ if (!VolumeManager::shutting_down) sleep(5);
// Send SIGKILL a second time to determine if we've
// actually killed everyone with open files
if (Process::killProcessesWithOpenFiles(cpath, SIGKILL) == 0) {
diff --git a/VolumeManager.cpp b/VolumeManager.cpp
index 746551f..bb98e9a 100644
--- a/VolumeManager.cpp
+++ b/VolumeManager.cpp
@@ -94,6 +94,8 @@ const char *VolumeManager::ASECDIR = "/mnt/asec";
*/
const char *VolumeManager::LOOPDIR = "/mnt/obb";
+bool VolumeManager::shutting_down = false;
+
static const char* kUserMountPath = "/mnt/user";
static const unsigned int kMajorBlockMmc = 179;
@@ -648,11 +650,13 @@ int VolumeManager::reset() {
}
int VolumeManager::shutdown() {
+ shutting_down = true;
mInternalEmulated->destroy();
for (auto disk : mDisks) {
disk->destroy();
}
mDisks.clear();
+ shutting_down = false;
return 0;
}
diff --git a/VolumeManager.h b/VolumeManager.h
index 4f1e6cf..ffcb8d9 100644
--- a/VolumeManager.h
+++ b/VolumeManager.h
@@ -73,6 +73,9 @@ public:
char *mLoopPath;
#endif
+ //TODO remove this with better solution, b/64143519
+ static bool shutting_down;
+
private:
static VolumeManager *sInstance;
网友评论