Switch thread's cgroup during spin-on-suspend.
Dalvik uses a safe-point suspend mechanism, in which threads are asked
to suspend and do so at their earliest convenience. The thread doing
the asking will sleep-spin until all threads have complied. If a thread
keeps on running, we get a "spin on suspend" situation.
The VM tries to correct matters by raising the priority of the spinning
thread if it's below normal. Until now it was just fiddling with the
"nice" value, but it appears that isn't enough (e.g. bug 2467653). We
now also change the thread's process group from "background" to
"foreground" in an attempt to get it some CPU.
Also includes some changes as part of the Log Reduction Act:
- Don't log the thread stacks on the first spin-on-suspend iteration.
The act of logging can itself be quite a drag.
- Removed the redundant and unnecessary "dumping state" line, as well
as some dead glibc-only code.
- While waiting for daemon threads to shut down, only show the "not
ready yet" message on the first iteration.
diff --git a/vm/Thread.c b/vm/Thread.c
index 3874ea9..1e210b4 100644
--- a/vm/Thread.c
+++ b/vm/Thread.c
@@ -681,6 +681,8 @@
dvmUnlockThreadList();
if (doWait) {
+ bool complained = false;
+
usleep(200 * 1000);
dvmLockThreadList(self);
@@ -701,9 +703,10 @@
}
if (target->status == THREAD_RUNNING && !target->isSuspended) {
- LOGD("threadid=%d not ready yet\n", target->threadId);
+ if (!complained)
+ LOGD("threadid=%d not ready yet\n", target->threadId);
allSuspended = false;
- break;
+ /* keep going so we log each running daemon once */
}
target = target->next;
@@ -713,7 +716,12 @@
LOGD("threadid=%d: all daemons have suspended\n", threadId);
break;
} else {
- LOGD("threadid=%d: waiting for daemons to suspend\n", threadId);
+ if (!complained) {
+ complained = true;
+ LOGD("threadid=%d: waiting briefly for daemon suspension\n",
+ threadId);
+ // TODO: JIT can get stuck, dvmJitUnchainAll doesn't help?
+ }
}
usleep(200 * 1000);
@@ -2473,35 +2481,104 @@
*/
static void dumpWedgedThread(Thread* thread)
{
- char exePath[1024];
-
- /*
- * The "executablepath" function in libutils is host-side only.
- */
- strcpy(exePath, "-");
-#ifdef HAVE_GLIBC
- {
- char proc[100];
- sprintf(proc, "/proc/%d/exe", getpid());
- int len;
-
- len = readlink(proc, exePath, sizeof(exePath)-1);
- exePath[len] = '\0';
- }
-#endif
-
- LOGW("dumping state: process %s %d\n", exePath, getpid());
dvmDumpThread(dvmThreadSelf(), false);
printBackTrace();
// dumping a running thread is risky, but could be useful
dvmDumpThread(thread, true);
-
// stop now and get a core dump
//abort();
}
+/* "change flags" values for next two functions */
+enum { kChangedPriority = 0x01, kChangedPolicy = 0x02 };
+
+/*
+ * If the thread is running at below-normal priority, temporarily elevate
+ * it to "normal".
+ *
+ * Returns zero if no changes were made. Otherwise, returns bit flags
+ * indicating what was changed, storing the previous values in the
+ * provided locations.
+ */
+static int raiseThreadPriorityIfNeeded(Thread* thread, int* pSavedThreadPrio,
+ SchedPolicy* pSavedThreadPolicy)
+{
+ errno = 0;
+ *pSavedThreadPrio = getpriority(PRIO_PROCESS, thread->systemTid);
+ if (errno != 0) {
+ LOGW("Unable to get priority for threadid=%d sysTid=%d\n",
+ thread->threadId, thread->systemTid);
+ return 0;
+ }
+ if (get_sched_policy(thread->systemTid, pSavedThreadPolicy) != 0) {
+ LOGW("Unable to get policy for threadid=%d sysTid=%d\n",
+ thread->threadId, thread->systemTid);
+ return 0;
+ }
+
+ int changeFlags = 0;
+
+ /*
+ * Change the priority if we're in the background group.
+ */
+ if (*pSavedThreadPolicy == SP_BACKGROUND) {
+ if (set_sched_policy(thread->systemTid, SP_FOREGROUND) != 0) {
+ LOGW("Couldn't set fg policy on tid %d\n", thread->systemTid);
+ } else {
+ changeFlags |= kChangedPolicy;
+ LOGD("Temporarily moving tid %d to fg (was %d)\n",
+ thread->systemTid, *pSavedThreadPolicy);
+ }
+ }
+
+ /*
+ * getpriority() returns the "nice" value, so larger numbers indicate
+ * lower priority, with 0 being normal.
+ */
+ if (*pSavedThreadPrio > 0) {
+ const int kHigher = 0;
+ if (setpriority(PRIO_PROCESS, thread->systemTid, kHigher) != 0) {
+ LOGW("Couldn't raise priority on tid %d to %d\n",
+ thread->systemTid, kHigher);
+ } else {
+ changeFlags |= kChangedPriority;
+ LOGD("Temporarily raised priority on tid %d (%d -> %d)\n",
+ thread->systemTid, *pSavedThreadPrio, kHigher);
+ }
+ }
+
+ return changeFlags;
+}
+
+/*
+ * Reset the priority values for the thread in question.
+ */
+static void resetThreadPriority(Thread* thread, int changeFlags,
+ int savedThreadPrio, SchedPolicy savedThreadPolicy)
+{
+ if ((changeFlags & kChangedPolicy) != 0) {
+ if (set_sched_policy(thread->systemTid, savedThreadPolicy) != 0) {
+ LOGW("NOTE: couldn't reset tid %d to (%d)\n",
+ thread->systemTid, savedThreadPolicy);
+ } else {
+ LOGD("Restored policy of %d to %d\n",
+ thread->systemTid, savedThreadPolicy);
+ }
+ }
+
+ if ((changeFlags & kChangedPriority) != 0) {
+ if (setpriority(PRIO_PROCESS, thread->systemTid, savedThreadPrio) != 0)
+ {
+ LOGW("NOTE: couldn't reset priority on thread %d to %d\n",
+ thread->systemTid, savedThreadPrio);
+ } else {
+ LOGD("Restored priority on %d to %d\n",
+ thread->systemTid, savedThreadPrio);
+ }
+ }
+}
/*
* Wait for another thread to see the pending suspension and stop running.
@@ -2534,8 +2611,9 @@
const int kMaxRetries = 10;
int spinSleepTime = FIRST_SLEEP;
bool complained = false;
- bool needPriorityReset = false;
+ int priChangeFlags = 0;
int savedThreadPrio = -500;
+ SchedPolicy savedThreadPolicy = SP_FOREGROUND;
int sleepIter = 0;
int retryCount = 0;
@@ -2552,30 +2630,11 @@
* After waiting for a bit, check to see if the target thread is
* running at a reduced priority. If so, bump it up temporarily
* to give it more CPU time.
- *
- * getpriority() returns the "nice" value, so larger numbers
- * indicate lower priority.
- *
- * (Not currently changing the cgroup. Wasn't necessary in some
- * simple experiments.)
*/
if (retryCount == 2) {
assert(thread->systemTid != 0);
- errno = 0;
- int threadPrio = getpriority(PRIO_PROCESS, thread->systemTid);
- if (errno == 0 && threadPrio > 0) {
- const int kHigher = 0;
- if (setpriority(PRIO_PROCESS, thread->systemTid, kHigher) < 0)
- {
- LOGW("Couldn't raise priority on tid %d to %d\n",
- thread->systemTid, kHigher);
- } else {
- savedThreadPrio = threadPrio;
- needPriorityReset = true;
- LOGD("Temporarily raising priority on tid %d (%d -> %d)\n",
- thread->systemTid, threadPrio, kHigher);
- }
- }
+ priChangeFlags = raiseThreadPriorityIfNeeded(thread,
+ &savedThreadPrio, &savedThreadPolicy);
}
}
@@ -2588,7 +2647,7 @@
*/
if (gDvmJit.pJitEntryTable && retryCount > 0 &&
gDvmJit.hasNewChain && thread->inJitCodeCache) {
- LOGD("JIT unchain all for tid %d", thread->threadId);
+ LOGD("JIT unchain all for threadid=%d", thread->threadId);
dvmJitUnchainAll();
}
#endif
@@ -2599,10 +2658,13 @@
*/
if (!dvmIterativeSleep(sleepIter++, spinSleepTime, startWhen)) {
if (spinSleepTime != FIRST_SLEEP) {
- LOGW("threadid=%d: spin on suspend #%d threadid=%d (h=%d)\n",
+ LOGW("threadid=%d: spin on suspend #%d threadid=%d (pcf=%d)\n",
self->threadId, retryCount,
- thread->threadId, (int)thread->handle);
- dumpWedgedThread(thread);
+ thread->threadId, priChangeFlags);
+ if (retryCount > 1) {
+ /* stack trace logging is slow; skip on first iter */
+ dumpWedgedThread(thread);
+ }
complained = true;
}
@@ -2625,14 +2687,9 @@
(dvmGetRelativeTimeUsec() - firstStartWhen) / 1000);
//dvmDumpThread(thread, false); /* suspended, so dump is safe */
}
- if (needPriorityReset) {
- if (setpriority(PRIO_PROCESS, thread->systemTid, savedThreadPrio) < 0) {
- LOGW("NOTE: couldn't reset priority on thread %d to %d\n",
- thread->systemTid, savedThreadPrio);
- } else {
- LOGV("Restored priority on %d to %d\n",
- thread->systemTid, savedThreadPrio);
- }
+ if (priChangeFlags != 0) {
+ resetThreadPriority(thread, priChangeFlags, savedThreadPrio,
+ savedThreadPolicy);
}
}