Merge pull request #22930 from hrydgard/vblank-timing

sceDisplay/sceCtrl: Charge the vblank interrupt's and ctrl peeks' CPU time, as measured on hardware

Core/HLE/sceCtrl.cpp

@@ -625,16 +625,18 @@ static int sceCtrlReadBufferNegative(u32 ctrlDataPtr, u32 nBufs)
 static int sceCtrlPeekBufferPositive(u32 ctrlDataPtr, u32 nBufs)
 {
 	int done = __CtrlReadBuffer(ctrlDataPtr, nBufs, false, true);
+	// ~0.2us more for each sample copied: 15us for 64 on hardware.
+	hleEatCycles(330 + 45 * std::max(done, 0));
 	// Some homebrew call this in a tight loop - so VERBOSE it is.
-	hleEatCycles(330);
 	return hleLogVerbose(Log::sceCtrl, done);
 }
 
 static int sceCtrlPeekBufferNegative(u32 ctrlDataPtr, u32 nBufs)
 {
 	int done = __CtrlReadBuffer(ctrlDataPtr, nBufs, true, true);
+	// ~0.2us more for each sample copied: 15us for 64 on hardware.
+	hleEatCycles(330 + 45 * std::max(done, 0));
 	// Some homebrew call this in a tight loop - so VERBOSE it is.
-	hleEatCycles(330);
 	return hleLogVerbose(Log::sceCtrl, done);
 }
 

Core/HLE/sceDisplay.cpp

@@ -94,7 +94,8 @@ static bool framebufIsLatched;
 
 static int enterVblankEvent = -1;
 static int leaveVblankEvent = -1;
-// Threads whose vblank wait is over, released a little after the vblank (see hleEnterVblank).
+// Threads whose vblank wait is over, released a little after the vblank. They're released inside
+// the interrupt now (see hleEnterVblank), so this only fills from a state saved with some pending.
 static int vblankWakeEvent = -1;
 static std::vector<SceUID> vblankWakePending;
 static int afterFlipEvent = -1;
@@ -147,10 +148,9 @@ std::map<SceUID, int> vblankPausedWaits;
 
 // STATE END
 
-// tests/display/vblanklen measures 730-770us from sceDisplayWaitVblankStart returning until
-// vblank ends, and an hcount of up to 14 inside it. The wait's own latency is in that, so this is
-// the upper end.
-const double vblankMs = 0.770;
+// The vblank ends ~818us after its interrupt, early in line 14 (pspautotests display/vblankphase;
+// display/vblanklen measures 730-740us from sceDisplayWaitVblankStart returning).
+const double vblankMs = 0.818;
 // These are guesses based on tests.
 const double vsyncStartMs = 0.5925;
 const double vsyncEndMs = 0.7265;
@@ -161,6 +161,12 @@ enum {
 	PSP_DISPLAY_SETBUF_NEXTFRAME = 1
 };
 
+// What the vblank interrupt costs the CPU: with no handler, and around the handlers when there are
+// some (pspautotests display/vblankphase).
+static const int VBLANK_NO_HANDLER_US = 66;
+static const int VBLANK_HANDLER_ENTRY_US = 29;
+static const int VBLANK_HANDLER_EXIT_US = 40;
+
 // For the "max 60 fps" setting.
 static int lastFlipsTooFrequent = 0;
 static u64 lastFlipCycles = 0;
@@ -588,28 +594,35 @@ void hleEnterVblank(u64 userdata, int cyclesLate) {
 
 	CoreTiming::ScheduleEvent(msToCycles(vblankMs) - cyclesLate, leaveVblankEvent, vbCount + 1);
 
-	// Threads waiting for this vblank are released about 48us after it, plus ~9us for each one
-	// beyond the first: on hardware a lone waiter returns ~53us after a vblank handler would run,
-	// and with four the first to run does so ~85us after the handler (pspautotests
-	// threads/scheduling/vblankwake). Which vblank a wait is for is still decided here, so a
-	// thread that starts waiting in between waits for the next one.
-	// TODO: The vblank itself takes ~62us of CPU on hardware (~70us with a handler, which runs
-	// ~28us in), and a waiter back ~90us after it still reads hcount 1. Both fit only if the
-	// interrupt comes ~40us before the line count wraps, which we don't model yet, so that cost
-	// isn't charged either.
+	// The interrupt comes as the last line ends (the counters wrap inside it) and takes ~66us of
+	// CPU, or ~78us with a handler, which runs ~29us in. It also releases the threads waiting for
+	// this vblank, after the handlers: a lone waiter gets the CPU ~81us after the interrupt, or ~91us
+	// with a handler, and each extra waiter holds the first back ~3us more (pspautotests
+	// display/vblankphase). Which vblank a wait is for is decided here, so a thread that starts
+	// waiting in between waits a whole frame.
+	int released = 0;
 	for (size_t i = 0; i < vblankWaitingThreads.size(); i++) {
 		if (--vblankWaitingThreads[i].vcountUnblock == 0) {
-			vblankWakePending.push_back(vblankWaitingThreads[i].threadID);
+			const SceUID threadID = vblankWaitingThreads[i].threadID;
 			vblankWaitingThreads.erase(vblankWaitingThreads.begin() + i--);
+			u32 error;
+			if (__KernelGetWaitID(threadID, WAITTYPE_VBLANK, error) == 1) {
+				__KernelResumeThreadFromWait(threadID, 0);
+				released++;
+			}
 		}
 	}
-	if (!vblankWakePending.empty()) {
-		const int releaseUs = 48 + 9 * ((int)vblankWakePending.size() - 1);
-		CoreTiming::ScheduleEvent(usToCycles(releaseUs) - cyclesLate, vblankWakeEvent, 0);
-	}
+	const int wakeUs = released > 0 ? 7 + 3 * (released - 1) : 0;
+	__SetIntrHandlerCosts(PSP_VBLANK_INTR, (int)usToCycles(VBLANK_HANDLER_ENTRY_US), (int)usToCycles(VBLANK_HANDLER_EXIT_US + wakeUs));
 
-	// Trigger VBlank interrupt handlers.
-	__TriggerInterrupt(PSP_INTR_IMMEDIATE | PSP_INTR_ONLY_IF_ENABLED | PSP_INTR_ALWAYS_RESCHED, PSP_VBLANK_INTR, PSP_INTR_SUB_ALL);
+	const bool taken = __InterruptsEnabled() && !__IsInInterrupt();
+	const int handlers = __TriggerInterrupt(PSP_INTR_IMMEDIATE | PSP_INTR_ONLY_IF_ENABLED | PSP_INTR_ALWAYS_RESCHED, PSP_VBLANK_INTR, PSP_INTR_SUB_ALL);
+	if (taken && handlers == 0) {
+		currentMIPS->downcount -= (int)usToCycles(VBLANK_NO_HANDLER_US + wakeUs);
+	} else if (released && !taken) {
+		// No interrupt to return from, so nothing else will hand them the CPU.
+		__KernelReSchedule("vblank waiters released");
+	}
 
 	// We use the emulation timebase here, for auto movements to be smooth as seen from the game.
 	g_controlMapper.UpdateAutoMovements(CoreTiming::GetGlobalTimeUs() / 1000000.0);
@@ -897,6 +910,8 @@ void __DisplayWaitForVblanks(const char *reason, int vblanks, bool callbacks) {
 	}
 
 	vblankWaitingThreads.push_back(WaitVBlankInfo(__KernelGetCurThread(), vblanks));
+	// Threads that wait again straight after a vblank take turns ~12us apart (display/vblankphase).
+	hleEatMicro(6);
 	__KernelWaitCurThread(WAITTYPE_VBLANK, 1, 0, 0, callbacks, reason);
 }
 

Core/HW/Display.cpp

@@ -160,9 +160,10 @@ uint64_t DisplayFrameStartTicks() {
 
 uint32_t __DisplayGetCurrentHcount() {
 	const int ticksIntoFrame = (int)(CoreTiming::GetTicks(currentMIPS) - frameStartTicks);
-	const int ticksPerVblank = CoreTiming::GetClockFrequencyHz() / 60 / hCountPerVblank;
-	// Can't seem to produce a 0 on real hardware, offsetting by 1 makes things look right.
-	return 1 + (ticksIntoFrame / ticksPerVblank);
+	// A frame is 1001/60 ms, and lines 0-285 fill it. Line 0 starts at the vblank, and is rarely
+	// seen outside a vblank handler: the interrupt takes most of it (pspautotests display/vblankphase).
+	const s64 ticksPerFrame = (s64)CoreTiming::GetClockFrequencyHz() * 1001 / 60000;
+	return (u32)((s64)ticksIntoFrame * hCountPerVblank / ticksPerFrame);
 }
 
 uint32_t __DisplayGetAccumulatedHcount() {

test.py

@@ -200,12 +200,14 @@ tests_good = [
   "ctrl/sampling/sampling",
   "ctrl/sampling2/sampling2",
   "ctrl/vblank",
+  "ctrl/peekcost",
   "display/display",
   "display/hcount",
   "display/vblankmulti",
   "display/isstate",
   "display/setframebuf",
   "display/setmode",
+  "display/vblankphase",
   "dmac/dmactest",
   "font/altcharcode",
   "font/charglyphimage",
@@ -487,6 +489,7 @@ tests_good = [
   "threads/scheduling/vblankwake",
   "threads/scheduling/readyqueue",
   "threads/scheduling/waittimeouts",
+  "threads/scheduling/alarmcosts",
   "threads/semaphores/semaphores",
   "threads/semaphores/cancel",
   "threads/semaphores/create",