1 // Copyright (c) 2012- PPSSPP Project.
2
3 // This program is free software: you can redistribute it and/or modify
4 // it under the terms of the GNU General Public License as published by
5 // the Free Software Foundation, version 2.0 or later versions.
6
7 // This program is distributed in the hope that it will be useful,
8 // but WITHOUT ANY WARRANTY; without even the implied warranty of
9 // MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
10 // GNU General Public License 2.0 for more details.
11
12 // A copy of the GPL 2.0 should have been included with the program.
13 // If not, see http://www.gnu.org/licenses/
14
15 // Official git repository and contact information can be found at
16 // https://github.com/hrydgard/ppsspp and http://www.ppsspp.org/.
17
18 #include <cstdarg>
19 #include <map>
20 #include <vector>
21 #include <string>
22
23 #include "Common/Profiler/Profiler.h"
24
25 #include "Common/Log.h"
26 #include "Common/Serialize/SerializeFuncs.h"
27 #include "Common/TimeUtil.h"
28 #include "Core/Config.h"
29 #include "Core/Core.h"
30 #include "Core/CoreTiming.h"
31 #include "Core/Host.h"
32 #include "Core/MemMapHelpers.h"
33 #include "Core/Reporting.h"
34 #include "Core/System.h"
35 #include "Core/MIPS/MIPS.h"
36 #include "Core/MIPS/MIPSCodeUtils.h"
37 #include "Core/HLE/HLETables.h"
38 #include "Core/HLE/sceDisplay.h"
FinalizeFilename(const wxString filename)39 #include "Core/HLE/sceIo.h"
40 #include "Core/HLE/sceAudio.h"
41 #include "Core/HLE/sceKernelMemory.h"
42 #include "Core/HLE/sceKernelThread.h"
43 #include "Core/HLE/sceKernelInterrupt.h"
44 #include "Core/HLE/HLE.h"
45
46 enum
47 {
48 // Do nothing after the syscall.
49 HLE_AFTER_NOTHING = 0x00,
50 // Reschedule immediately after the syscall.
51 HLE_AFTER_RESCHED = 0x01,
52 // Call current thread's callbacks after the syscall.
53 HLE_AFTER_CURRENT_CALLBACKS = 0x02,
54 // Reschedule and process current thread's callbacks after the syscall.
55 HLE_AFTER_RESCHED_CALLBACKS = 0x08,
56 // Run interrupts (and probably reschedule) after the syscall.
57 HLE_AFTER_RUN_INTERRUPTS = 0x10,
58 // Switch to CORE_STEPPING after the syscall (for debugging.)
59 HLE_AFTER_DEBUG_BREAK = 0x20,
60 // Don't fill temp regs with 0xDEADBEEF.
61 HLE_AFTER_SKIP_DEADBEEF = 0x40,
62 // Execute pending mips calls.
63 HLE_AFTER_QUEUED_CALLS = 0x80,
64 };
65
66 static std::vector<HLEModule> moduleDB;
67 static int delayedResultEvent = -1;
68 static int hleAfterSyscall = HLE_AFTER_NOTHING;
69 static const char *hleAfterSyscallReschedReason;
70 static const HLEFunction *latestSyscall = nullptr;
71 static int idleOp;
72
ReadHash(const wxString & key,CMD4Hash * hash)73 struct HLEMipsCallInfo {
74 u32 func;
75 PSPAction *action;
76 std::vector<u32> args;
77 };
78
79 struct HLEMipsCallStack {
80 u32_le nextOff;
81 union {
82 struct {
83 u32_le func;
84 u32_le actionIndex;
85 u32_le argc;
86 };
87 struct {
88 u32_le ra;
89 u32_le v0;
90 u32_le v1;
91 };
92 };
WriteHash(const wxString & key,const CMD4Hash & hash)93 };
94
95 // No need to save state, always flushed at a syscall end.
96 static std::vector<HLEMipsCallInfo> enqueuedMipsCalls;
97 // Does need to be saved, referenced by the stack and owned.
98 static std::vector<PSPAction *> mipsCallActions;
99
100 void hleDelayResultFinish(u64 userdata, int cycleslate)
101 {
102 u32 error;
103 SceUID threadID = (SceUID) userdata;
104 SceUID verify = __KernelGetWaitID(threadID, WAITTYPE_HLEDELAY, error);
105 // The top 32 bits of userdata are the top 32 bits of the 64 bit result.
106 // We can't just put it all in userdata because we need to know the threadID...
107 u64 result = (userdata & 0xFFFFFFFF00000000ULL) | __KernelGetWaitValue(threadID, error);
108
109 if (error == 0 && verify == 1)
110 {
111 __KernelResumeThreadFromWait(threadID, result);
112 __KernelReSchedule("woke from hle delay");
113 }
114 else
115 WARN_LOG(HLE, "Someone else woke up HLE-blocked thread %d?", threadID);
116 }
117
118 void HLEInit() {
119 RegisterAllModules();
120 delayedResultEvent = CoreTiming::RegisterEvent("HLEDelayedResult", hleDelayResultFinish);
121 idleOp = GetSyscallOp("FakeSysCalls", NID_IDLE);
122 }
123
124 void HLEDoState(PointerWrap &p) {
125 auto s = p.Section("HLE", 1, 2);
126 if (!s)
127 return;
128
129 // Can't be inside a syscall, reset this so errors aren't misleading.
130 latestSyscall = nullptr;
131 Do(p, delayedResultEvent);
132 CoreTiming::RestoreRegisterEvent(delayedResultEvent, "HLEDelayedResult", hleDelayResultFinish);
133
134 if (s >= 2) {
135 int actions = (int)mipsCallActions.size();
136 Do(p, actions);
137 if (actions != (int)mipsCallActions.size()) {
138 mipsCallActions.resize(actions);
139 }
140
141 for (auto &action : mipsCallActions) {
142 int actionTypeID = action != nullptr ? action->actionTypeID : -1;
143 Do(p, actionTypeID);
144 if (actionTypeID != -1) {
145 if (p.mode == p.MODE_READ)
146 action = __KernelCreateAction(actionTypeID);
147 action->DoState(p);
148 }
149 }
150 }
151 }
152
153 void HLEShutdown() {
154 hleAfterSyscall = HLE_AFTER_NOTHING;
155 latestSyscall = nullptr;
156 moduleDB.clear();
157 enqueuedMipsCalls.clear();
158 for (auto p : mipsCallActions) {
159 delete p;
160 }
161 mipsCallActions.clear();
162 }
163
164 void RegisterModule(const char *name, int numFunctions, const HLEFunction *funcTable)
165 {
166 HLEModule module = {name, numFunctions, funcTable};
167 moduleDB.push_back(module);
168 }
169
170 int GetModuleIndex(const char *moduleName)
171 {
172 for (size_t i = 0; i < moduleDB.size(); i++)
173 if (strcmp(moduleName, moduleDB[i].name) == 0)
174 return (int)i;
175 return -1;
176 }
177
178 int GetFuncIndex(int moduleIndex, u32 nib)
179 {
180 const HLEModule &module = moduleDB[moduleIndex];
181 for (int i = 0; i < module.numFunctions; i++)
182 {
183 if (module.funcTable[i].ID == nib)
184 return i;
185 }
186 return -1;
187 }
188
189 u32 GetNibByName(const char *moduleName, const char *function)
190 {
191 int moduleIndex = GetModuleIndex(moduleName);
192 if (moduleIndex == -1)
193 return -1;
194
195 const HLEModule &module = moduleDB[moduleIndex];
196 for (int i = 0; i < module.numFunctions; i++)
197 {
198 if (!strcmp(module.funcTable[i].name, function))
199 return module.funcTable[i].ID;
200 }
201 return -1;
202 }
203
204 const HLEFunction *GetFunc(const char *moduleName, u32 nib)
205 {
206 int moduleIndex = GetModuleIndex(moduleName);
207 if (moduleIndex != -1)
208 {
209 int idx = GetFuncIndex(moduleIndex, nib);
210 if (idx != -1)
211 return &(moduleDB[moduleIndex].funcTable[idx]);
212 }
213 return 0;
214 }
215
216 const char *GetFuncName(const char *moduleName, u32 nib)
217 {
218 _dbg_assert_msg_(moduleName != nullptr, "Invalid module name.");
219
220 const HLEFunction *func = GetFunc(moduleName,nib);
221 if (func)
222 return func->name;
223
224 static char temp[256];
225 sprintf(temp,"[UNK: 0x%08x]", nib);
226 return temp;
227 }
228
229 u32 GetSyscallOp(const char *moduleName, u32 nib) {
230 // Special case to hook up bad imports.
231 if (moduleName == NULL) {
232 return (0x03FFFFCC); // invalid syscall
233 }
234
235 int modindex = GetModuleIndex(moduleName);
236 if (modindex != -1) {
237 int funcindex = GetFuncIndex(modindex, nib);
238 if (funcindex != -1) {
239 return (0x0000000c | (modindex<<18) | (funcindex<<6));
240 } else {
241 INFO_LOG(HLE, "Syscall (%s, %08x) unknown", moduleName, nib);
242 return (0x0003FFCC | (modindex<<18)); // invalid syscall
243 }
244 }
245 else
246 {
247 ERROR_LOG(HLE, "Unknown module %s!", moduleName);
248 return (0x03FFFFCC); // invalid syscall
249 }
250 }
251
252 bool FuncImportIsSyscall(const char *module, u32 nib)
253 {
254 return GetFunc(module, nib) != NULL;
255 }
256
257 void WriteFuncStub(u32 stubAddr, u32 symAddr)
258 {
259 // Note that this should be J not JAL, as otherwise control will return to the stub..
260 Memory::Write_U32(MIPS_MAKE_J(symAddr), stubAddr);
261 // Note: doing that, we can't trace external module calls, so maybe something else should be done to debug more efficiently
262 // Perhaps a syscall here (and verify support in jit), marking the module by uid (debugIdentifier)?
263 Memory::Write_U32(MIPS_MAKE_NOP(), stubAddr + 4);
264 }
265
266 void WriteFuncMissingStub(u32 stubAddr, u32 nid)
267 {
268 // Write a trap so we notice this func if it's called before resolving.
269 Memory::Write_U32(MIPS_MAKE_JR_RA(), stubAddr); // jr ra
270 Memory::Write_U32(GetSyscallOp(NULL, nid), stubAddr + 4);
271 }
272
273 bool WriteSyscall(const char *moduleName, u32 nib, u32 address)
274 {
275 if (nib == 0)
276 {
277 WARN_LOG_REPORT(HLE, "Wrote patched out nid=0 syscall (%s)", moduleName);
278 Memory::Write_U32(MIPS_MAKE_JR_RA(), address); //patched out?
279 Memory::Write_U32(MIPS_MAKE_NOP(), address+4); //patched out?
280 return true;
281 }
282 int modindex = GetModuleIndex(moduleName);
283 if (modindex != -1)
284 {
285 Memory::Write_U32(MIPS_MAKE_JR_RA(), address); // jr ra
286 Memory::Write_U32(GetSyscallOp(moduleName, nib), address + 4);
287 return true;
288 }
289 else
290 {
291 ERROR_LOG_REPORT(HLE, "Unable to write unknown syscall: %s/%08x", moduleName, nib);
292 return false;
293 }
294 }
295
296 const char *GetFuncName(int moduleIndex, int func)
297 {
298 if (moduleIndex >= 0 && moduleIndex < (int)moduleDB.size())
299 {
300 const HLEModule &module = moduleDB[moduleIndex];
301 if (func >= 0 && func < module.numFunctions)
302 {
303 return module.funcTable[func].name;
304 }
305 }
306 return "[unknown]";
307 }
308
309 void hleCheckCurrentCallbacks()
310 {
311 hleAfterSyscall |= HLE_AFTER_CURRENT_CALLBACKS;
312 }
313
314 void hleReSchedule(const char *reason)
315 {
316 #ifdef _DEBUG
317 _dbg_assert_msg_(reason != nullptr && strlen(reason) < 256, "hleReSchedule: Invalid or too long reason.");
318 #endif
319
320 hleAfterSyscall |= HLE_AFTER_RESCHED;
321
322 if (!reason)
323 hleAfterSyscallReschedReason = "Invalid reason";
324 else
325 hleAfterSyscallReschedReason = reason;
326 }
327
328 void hleReSchedule(bool callbacks, const char *reason)
329 {
330 hleReSchedule(reason);
331 if (callbacks)
332 hleAfterSyscall |= HLE_AFTER_RESCHED_CALLBACKS;
333 }
334
335 void hleRunInterrupts()
336 {
337 hleAfterSyscall |= HLE_AFTER_RUN_INTERRUPTS;
338 }
339
340 void hleDebugBreak()
341 {
342 hleAfterSyscall |= HLE_AFTER_DEBUG_BREAK;
343 }
344
345 void hleSkipDeadbeef()
346 {
347 hleAfterSyscall |= HLE_AFTER_SKIP_DEADBEEF;
348 }
349
350 // Pauses execution after an HLE call.
351 bool hleExecuteDebugBreak(const HLEFunction &func)
352 {
353 const u32 NID_SUSPEND_INTR = 0x092968F4, NID_RESUME_INTR = 0x5F10D406;
354
355 // Never break on these, they're noise.
356 u32 blacklistedNIDs[] = {NID_SUSPEND_INTR, NID_RESUME_INTR, NID_IDLE};
357 for (size_t i = 0; i < ARRAY_SIZE(blacklistedNIDs); ++i)
358 {
359 if (func.ID == blacklistedNIDs[i])
360 return false;
361 }
362
363 Core_EnableStepping(true);
364 host->SetDebugMode(true);
365 return true;
366 }
367
368 u32 hleDelayResult(u32 result, const char *reason, int usec) {
369 if (!__KernelIsDispatchEnabled()) {
370 WARN_LOG(HLE, "%s: Dispatch disabled, not delaying HLE result (right thing to do?)", latestSyscall ? latestSyscall->name : "?");
371 } else {
372 SceUID thread = __KernelGetCurThread();
373 if (KernelIsThreadWaiting(thread))
374 ERROR_LOG(HLE, "%s: Delaying a thread that's already waiting", latestSyscall ? latestSyscall->name : "?");
375 CoreTiming::ScheduleEvent(usToCycles(usec), delayedResultEvent, thread);
376 __KernelWaitCurThread(WAITTYPE_HLEDELAY, 1, result, 0, false, reason);
377 }
378 return result;
379 }
380
381 u64 hleDelayResult(u64 result, const char *reason, int usec) {
382 if (!__KernelIsDispatchEnabled()) {
383 WARN_LOG(HLE, "%s: Dispatch disabled, not delaying HLE result (right thing to do?)", latestSyscall ? latestSyscall->name : "?");
384 } else {
385 SceUID thread = __KernelGetCurThread();
386 if (KernelIsThreadWaiting(thread))
387 ERROR_LOG(HLE, "%s: Delaying a thread that's already waiting", latestSyscall ? latestSyscall->name : "?");
388 u64 param = (result & 0xFFFFFFFF00000000) | thread;
389 CoreTiming::ScheduleEvent(usToCycles(usec), delayedResultEvent, param);
390 __KernelWaitCurThread(WAITTYPE_HLEDELAY, 1, (u32)result, 0, false, reason);
391 }
392 return result;
393 }
394
395 void hleEatCycles(int cycles) {
396 // Maybe this should Idle, at least for larger delays? Could that cause issues?
397 currentMIPS->downcount -= cycles;
398 }
399
400 void hleEatMicro(int usec) {
401 hleEatCycles((int) usToCycles(usec));
402 }
403
404 bool hleIsKernelMode() {
405 return latestSyscall && (latestSyscall->flags & HLE_KERNEL_SYSCALL) != 0;
406 }
407
408 void hleEnqueueCall(u32 func, int argc, const u32 *argv, PSPAction *afterAction) {
409 std::vector<u32> args;
410 args.resize(argc);
411 memcpy(args.data(), argv, argc * sizeof(u32));
412
413 enqueuedMipsCalls.push_back({ func, afterAction, args });
414
415 hleAfterSyscall |= HLE_AFTER_QUEUED_CALLS;
416 }
417
418 void hleFlushCalls() {
419 u32 &sp = currentMIPS->r[MIPS_REG_SP];
420 PSPPointer<HLEMipsCallStack> stackData;
421 VERBOSE_LOG(HLE, "Flushing %d HLE mips calls from %s, sp=%08x", (int)enqueuedMipsCalls.size(), latestSyscall ? latestSyscall->name : "?", sp);
422
423 // First, we'll add a marker for the final return.
424 sp -= sizeof(HLEMipsCallStack);
425 stackData.ptr = sp;
426 stackData->nextOff = 0xFFFFFFFF;
427 stackData->ra = currentMIPS->pc;
428 stackData->v0 = currentMIPS->r[MIPS_REG_V0];
429 stackData->v1 = currentMIPS->r[MIPS_REG_V1];
430
431 // Now we'll set up the first in the chain.
432 currentMIPS->pc = enqueuedMipsCalls[0].func;
433 currentMIPS->r[MIPS_REG_RA] = HLEMipsCallReturnAddress();
434 for (int i = 0; i < (int)enqueuedMipsCalls[0].args.size(); i++) {
435 currentMIPS->r[MIPS_REG_A0 + i] = enqueuedMipsCalls[0].args[i];
436 }
437
438 // For stack info, process the first enqueued call last, so we run it first.
439 // We don't actually need to store 0's args, but keep it consistent.
440 for (int i = (int)enqueuedMipsCalls.size() - 1; i >= 0; --i) {
441 auto &info = enqueuedMipsCalls[i];
442 u32 stackRequired = (int)info.args.size() * sizeof(u32) + sizeof(HLEMipsCallStack);
443 u32 stackAligned = (stackRequired + 0xF) & ~0xF;
444
445 sp -= stackAligned;
446 stackData.ptr = sp;
447 stackData->nextOff = stackAligned;
448 stackData->func = info.func;
449 if (info.action) {
450 stackData->actionIndex = (int)mipsCallActions.size();
451 mipsCallActions.push_back(info.action);
452 } else {
453 stackData->actionIndex = 0xFFFFFFFF;
454 }
455 stackData->argc = (int)info.args.size();
456 for (int j = 0; j < (int)info.args.size(); ++j) {
457 Memory::Write_U32(info.args[j], sp + sizeof(HLEMipsCallStack) + j * sizeof(u32));
458 }
459 }
460 enqueuedMipsCalls.clear();
461
462 DEBUG_LOG(HLE, "Executing HLE mips call at %08x, sp=%08x", currentMIPS->pc, sp);
463 }
464
465 void HLEReturnFromMipsCall() {
466 u32 &sp = currentMIPS->r[MIPS_REG_SP];
467 PSPPointer<HLEMipsCallStack> stackData;
468
469 // At this point, we may have another mips call to run, or be at the end...
470 stackData.ptr = sp;
471
472 if ((stackData->nextOff & 0x0000000F) != 0 || !Memory::IsValidAddress(sp + stackData->nextOff)) {
473 ERROR_LOG(HLE, "Corrupt stack on HLE mips call return: %08x", stackData->nextOff);
474 Core_UpdateState(CORE_RUNTIME_ERROR);
475 return;
476 }
477
478 if (stackData->actionIndex != 0xFFFFFFFF && stackData->actionIndex < (u32)mipsCallActions.size()) {
479 PSPAction *&action = mipsCallActions[stackData->actionIndex];
480 VERBOSE_LOG(HLE, "Executing action for HLE mips call at %08x, sp=%08x", stackData->func, sp);
481
482 // Search for the saved v0/v1 values, to preserve the PSPAction API...
483 PSPPointer<HLEMipsCallStack> finalMarker = stackData;
484 while ((finalMarker->nextOff & 0x0000000F) == 0 && Memory::IsValidAddress(finalMarker.ptr + finalMarker->nextOff)) {
485 finalMarker.ptr += finalMarker->nextOff;
486 }
487
488 if (finalMarker->nextOff != 0xFFFFFFFF) {
489 ERROR_LOG(HLE, "Corrupt stack on HLE mips call return action: %08x", finalMarker->nextOff);
490 Core_UpdateState(CORE_RUNTIME_ERROR);
491 return;
492 }
493
494 MipsCall mc;
495 mc.savedV0 = finalMarker->v0;
496 mc.savedV1 = finalMarker->v1;
497 action->run(mc);
498 finalMarker->v0 = mc.savedV0;
499 finalMarker->v1 = mc.savedV1;
500
501 delete action;
502 action = nullptr;
503
504 // Note: the action could actually enqueue more, adding another layer on stack after this.
505 }
506
507 sp += stackData->nextOff;
508 stackData.ptr = sp;
509
510 if (stackData->nextOff == 0xFFFFFFFF) {
511 // We're done. Grab the HLE result's v0/v1 and return from the syscall.
512 currentMIPS->pc = stackData->ra;
513 currentMIPS->r[MIPS_REG_V0] = stackData->v0;
514 currentMIPS->r[MIPS_REG_V1] = stackData->v1;
515
516 sp += sizeof(HLEMipsCallStack);
517
518 bool canClear = true;
519 for (auto p : mipsCallActions) {
520 canClear = canClear && p == nullptr;
521 }
522 if (canClear) {
523 mipsCallActions.clear();
524 }
525
526 VERBOSE_LOG(HLE, "Finished HLE mips calls, v0=%08x, sp=%08x", currentMIPS->r[MIPS_REG_V0], sp);
527 return;
528 }
529
530 // Alright, we have another to call.
531 hleSkipDeadbeef();
532 currentMIPS->pc = stackData->func;
533 currentMIPS->r[MIPS_REG_RA] = HLEMipsCallReturnAddress();
534 for (int i = 0; i < (int)stackData->argc; i++) {
535 currentMIPS->r[MIPS_REG_A0 + i] = Memory::Read_U32(sp + sizeof(HLEMipsCallStack) + i * sizeof(u32));
536 }
537 DEBUG_LOG(HLE, "Executing next HLE mips call at %08x, sp=%08x", currentMIPS->pc, sp);
538 }
539
540 const static u32 deadbeefRegs[12] = {0xDEADBEEF, 0xDEADBEEF, 0xDEADBEEF, 0xDEADBEEF, 0xDEADBEEF, 0xDEADBEEF, 0xDEADBEEF, 0xDEADBEEF, 0xDEADBEEF, 0xDEADBEEF, 0xDEADBEEF, 0xDEADBEEF};
541 inline static void SetDeadbeefRegs()
542 {
543 if (g_Config.bSkipDeadbeefFilling)
544 return;
545
546 currentMIPS->r[MIPS_REG_COMPILER_SCRATCH] = 0xDEADBEEF;
547 // Set all the arguments and temp regs.
548 memcpy(¤tMIPS->r[MIPS_REG_A0], deadbeefRegs, sizeof(deadbeefRegs));
549 currentMIPS->r[MIPS_REG_T8] = 0xDEADBEEF;
550 currentMIPS->r[MIPS_REG_T9] = 0xDEADBEEF;
551
552 currentMIPS->lo = 0xDEADBEEF;
553 currentMIPS->hi = 0xDEADBEEF;
554 }
555
556 inline void hleFinishSyscall(const HLEFunction &info)
557 {
558 if ((hleAfterSyscall & HLE_AFTER_SKIP_DEADBEEF) == 0)
559 SetDeadbeefRegs();
560
561 if ((hleAfterSyscall & HLE_AFTER_QUEUED_CALLS) != 0)
562 hleFlushCalls();
563 if ((hleAfterSyscall & HLE_AFTER_CURRENT_CALLBACKS) != 0 && (hleAfterSyscall & HLE_AFTER_RESCHED_CALLBACKS) == 0)
564 __KernelForceCallbacks();
565
566 if ((hleAfterSyscall & HLE_AFTER_RUN_INTERRUPTS) != 0)
567 __RunOnePendingInterrupt();
568
569 if ((hleAfterSyscall & HLE_AFTER_RESCHED_CALLBACKS) != 0)
570 __KernelReSchedule(true, hleAfterSyscallReschedReason);
571 else if ((hleAfterSyscall & HLE_AFTER_RESCHED) != 0)
572 __KernelReSchedule(hleAfterSyscallReschedReason);
573
574 if ((hleAfterSyscall & HLE_AFTER_DEBUG_BREAK) != 0)
575 {
576 if (!hleExecuteDebugBreak(info))
577 {
578 // We'll do it next syscall.
579 hleAfterSyscall = HLE_AFTER_DEBUG_BREAK;
580 hleAfterSyscallReschedReason = 0;
581 return;
582 }
583 }
584
585 hleAfterSyscall = HLE_AFTER_NOTHING;
586 hleAfterSyscallReschedReason = 0;
587 }
588
589 static void updateSyscallStats(int modulenum, int funcnum, double total)
590 {
591 const char *name = moduleDB[modulenum].funcTable[funcnum].name;
592 // Ignore this one, especially for msInSyscalls (although that ignores CoreTiming events.)
593 if (0 == strcmp(name, "_sceKernelIdle"))
594 return;
595
596 if (total > kernelStats.slowestSyscallTime)
597 {
598 kernelStats.slowestSyscallTime = total;
599 kernelStats.slowestSyscallName = name;
600 }
601 kernelStats.msInSyscalls += total;
602
603 KernelStatsSyscall statCall(modulenum, funcnum);
604 auto summedStat = kernelStats.summedMsInSyscalls.find(statCall);
605 if (summedStat == kernelStats.summedMsInSyscalls.end())
606 {
607 kernelStats.summedMsInSyscalls[statCall] = total;
608 if (total > kernelStats.summedSlowestSyscallTime)
609 {
610 kernelStats.summedSlowestSyscallTime = total;
611 kernelStats.summedSlowestSyscallName = name;
612 }
613 }
614 else
615 {
616 double newTotal = kernelStats.summedMsInSyscalls[statCall] += total;
617 if (newTotal > kernelStats.summedSlowestSyscallTime)
618 {
619 kernelStats.summedSlowestSyscallTime = newTotal;
620 kernelStats.summedSlowestSyscallName = name;
621 }
622 }
623 }
624
625 inline void CallSyscallWithFlags(const HLEFunction *info)
626 {
627 latestSyscall = info;
628 const u32 flags = info->flags;
629
630 if (flags & HLE_CLEAR_STACK_BYTES) {
631 u32 stackStart = __KernelGetCurThreadStackStart();
632 if (currentMIPS->r[MIPS_REG_SP] - info->stackBytesToClear >= stackStart) {
633 Memory::Memset(currentMIPS->r[MIPS_REG_SP] - info->stackBytesToClear, 0, info->stackBytesToClear, "HLEStackClear");
634 }
635 }
636
637 if ((flags & HLE_NOT_DISPATCH_SUSPENDED) && !__KernelIsDispatchEnabled()) {
638 RETURN(hleLogDebug(HLE, SCE_KERNEL_ERROR_CAN_NOT_WAIT, "dispatch suspended"));
639 } else if ((flags & HLE_NOT_IN_INTERRUPT) && __IsInInterrupt()) {
640 RETURN(hleLogDebug(HLE, SCE_KERNEL_ERROR_ILLEGAL_CONTEXT, "in interrupt"));
641 } else {
642 info->func();
643 }
644
645 if (hleAfterSyscall != HLE_AFTER_NOTHING)
646 hleFinishSyscall(*info);
647 else
648 SetDeadbeefRegs();
649 }
650
651 inline void CallSyscallWithoutFlags(const HLEFunction *info)
652 {
653 latestSyscall = info;
654 info->func();
655
656 if (hleAfterSyscall != HLE_AFTER_NOTHING)
657 hleFinishSyscall(*info);
658 else
659 SetDeadbeefRegs();
660 }
661
662 const HLEFunction *GetSyscallFuncPointer(MIPSOpcode op)
663 {
664 u32 callno = (op >> 6) & 0xFFFFF; //20 bits
665 int funcnum = callno & 0xFFF;
666 int modulenum = (callno & 0xFF000) >> 12;
667 if (funcnum == 0xfff) {
668 ERROR_LOG(HLE, "Unknown syscall: Module: %s (module: %d func: %d)", modulenum > (int)moduleDB.size() ? "(unknown)" : moduleDB[modulenum].name, modulenum, funcnum);
669 return NULL;
670 }
671 if (modulenum >= (int)moduleDB.size()) {
672 ERROR_LOG(HLE, "Syscall had bad module number %d - probably executing garbage", modulenum);
673 return NULL;
674 }
675 if (funcnum >= moduleDB[modulenum].numFunctions) {
676 ERROR_LOG(HLE, "Syscall had bad function number %d in module %d - probably executing garbage", funcnum, modulenum);
677 return NULL;
678 }
679 return &moduleDB[modulenum].funcTable[funcnum];
680 }
681
682 void *GetQuickSyscallFunc(MIPSOpcode op) {
683 if (coreCollectDebugStats)
684 return nullptr;
685
686 const HLEFunction *info = GetSyscallFuncPointer(op);
687 if (!info || !info->func)
688 return nullptr;
689 DEBUG_LOG(HLE, "Compiling syscall to %s", info->name);
690
691 // TODO: Do this with a flag?
692 if (op == idleOp)
693 return (void *)info->func;
694 if (info->flags != 0)
695 return (void *)&CallSyscallWithFlags;
696 return (void *)&CallSyscallWithoutFlags;
697 }
698
699 static double hleSteppingTime = 0.0;
700 void hleSetSteppingTime(double t) {
701 hleSteppingTime += t;
702 }
703
704 static double hleFlipTime = 0.0;
705 void hleSetFlipTime(double t) {
706 hleFlipTime = t;
707 }
708
709 void CallSyscall(MIPSOpcode op)
710 {
711 PROFILE_THIS_SCOPE("syscall");
712 double start = 0.0; // need to initialize to fix the race condition where coreCollectDebugStats is enabled in the middle of this func.
713 if (coreCollectDebugStats) {
714 start = time_now_d();
715 }
716
717 const HLEFunction *info = GetSyscallFuncPointer(op);
718 if (!info) {
719 RETURN(SCE_KERNEL_ERROR_LIBRARY_NOT_YET_LINKED);
720 return;
721 }
722
723 if (info->func) {
724 if (op == idleOp)
725 info->func();
726 else if (info->flags != 0)
727 CallSyscallWithFlags(info);
728 else
729 CallSyscallWithoutFlags(info);
730 }
731 else {
732 RETURN(SCE_KERNEL_ERROR_LIBRARY_NOT_YET_LINKED);
733 ERROR_LOG_REPORT(HLE, "Unimplemented HLE function %s", info->name ? info->name : "(\?\?\?)");
734 }
735
736 if (coreCollectDebugStats) {
737 u32 callno = (op >> 6) & 0xFFFFF; //20 bits
738 int funcnum = callno & 0xFFF;
739 int modulenum = (callno & 0xFF000) >> 12;
740 double total = time_now_d() - start - hleSteppingTime;
741 if (total >= hleFlipTime)
742 total -= hleFlipTime;
743 _dbg_assert_msg_(total >= 0.0, "Time spent in syscall became negative");
744 hleSteppingTime = 0.0;
745 hleFlipTime = 0.0;
746 updateSyscallStats(modulenum, funcnum, total);
747 }
748 }
749
750 size_t hleFormatLogArgs(char *message, size_t sz, const char *argmask) {
751 char *p = message;
752 size_t used = 0;
753
754 #define APPEND_FMT(...) do { \
755 if (used < sz) { \
756 size_t c = snprintf(p, sz - used, __VA_ARGS__); \
757 used += c; \
758 p += c; \
759 } \
760 } while (false)
761
762 int reg = 0;
763 int regf = 0;
764 for (size_t i = 0, n = strlen(argmask); i < n; ++i, ++reg) {
765 u32 regval;
766 if (reg < 8) {
767 regval = PARAM(reg);
768 } else {
769 u32 sp = currentMIPS->r[MIPS_REG_SP];
770 // Goes upward on stack.
771 // NOTE: Currently we only support > 8 for 32-bit integer args.
772 regval = Memory::Read_U32(sp + (reg - 8) * 4);
773 }
774
775 switch (argmask[i]) {
776 case 'p':
777 if (Memory::IsValidAddress(regval)) {
778 APPEND_FMT("%08x[%08x]", regval, Memory::Read_U32(regval));
779 } else {
780 APPEND_FMT("%08x[invalid]", regval);
781 }
782 break;
783
784 case 'P':
785 if (Memory::IsValidAddress(regval)) {
786 APPEND_FMT("%08x[%016llx]", regval, Memory::Read_U64(regval));
787 } else {
788 APPEND_FMT("%08x[invalid]", regval);
789 }
790 break;
791
792 case 's':
793 if (Memory::IsValidAddress(regval)) {
794 const char *s = Memory::GetCharPointer(regval);
795 if (strnlen(s, 64) >= 64) {
796 APPEND_FMT("%.64s...", Memory::GetCharPointer(regval));
797 } else {
798 APPEND_FMT("%s", Memory::GetCharPointer(regval));
799 }
800 } else {
801 APPEND_FMT("(invalid)");
802 }
803 break;
804
805 case 'x':
806 APPEND_FMT("%08x", regval);
807 break;
808
809 case 'i':
810 APPEND_FMT("%d", regval);
811 break;
812
813 case 'X':
814 case 'I':
815 // 64-bit regs are always aligned.
816 if ((reg & 1))
817 ++reg;
818 APPEND_FMT("%016llx", PARAM64(reg));
819 ++reg;
820 break;
821
822 case 'f':
823 APPEND_FMT("%f", PARAMF(regf++));
824 // This doesn't consume a gp reg.
825 --reg;
826 break;
827
828 // TODO: Double? Does it ever happen?
829
830 default:
831 _dbg_assert_msg_(false, "Invalid argmask character: %c", argmask[i]);
832 APPEND_FMT(" -- invalid arg format: %c -- %08x", argmask[i], regval);
833 break;
834 }
835 if (i + 1 < n) {
836 APPEND_FMT(", ");
837 }
838 }
839
840 if (used > sz) {
841 message[sz - 1] = '\0';
842 } else {
843 message[used] = '\0';
844 }
845
846 #undef APPEND_FMT
847 return used;
848 }
849
850 void hleDoLogInternal(LogTypes::LOG_TYPE t, LogTypes::LOG_LEVELS level, u64 res, const char *file, int line, const char *reportTag, char retmask, const char *reason, const char *formatted_reason) {
851 char formatted_args[4096];
852 const char *funcName = "?";
853 u32 funcFlags = 0;
854 if (latestSyscall) {
855 _dbg_assert_(latestSyscall->argmask != nullptr);
856 hleFormatLogArgs(formatted_args, sizeof(formatted_args), latestSyscall->argmask);
857
858 // This acts as an override (for error returns which are usually hex.)
859 if (retmask == '\0')
860 retmask = latestSyscall->retmask;
861
862 funcName = latestSyscall->name;
863 funcFlags = latestSyscall->flags;
864 }
865
866 const char *fmt;
867 if (retmask == 'x') {
868 fmt = "%s%08llx=%s(%s)%s";
869 // Truncate the high bits of the result (from any sign extension.)
870 res = (u32)res;
871 } else if (retmask == 'i' || retmask == 'I') {
872 fmt = "%s%lld=%s(%s)%s";
873 } else if (retmask == 'f') {
874 // TODO: For now, floats are just shown as bits.
875 fmt = "%s%08x=%s(%s)%s";
876 } else {
877 _dbg_assert_msg_(false, "Invalid return format: %c", retmask);
878 fmt = "%s%08llx=%s(%s)%s";
879 }
880
881 const char *kernelFlag = (funcFlags & HLE_KERNEL_SYSCALL) != 0 ? "K " : "";
882 GenericLog(level, t, file, line, fmt, kernelFlag, res, funcName, formatted_args, formatted_reason);
883
884 if (reportTag != nullptr) {
885 // A blank string means always log, not just once.
886 if (reportTag[0] == '\0' || Reporting::ShouldLogNTimes(reportTag, 1)) {
887 // Here we want the original key, so that different args, etc. group together.
888 std::string key = std::string(kernelFlag) + std::string("%08x=") + funcName + "(%s)";
889 if (reason != nullptr)
890 key += std::string(": ") + reason;
891
892 char formatted_message[8192];
893 snprintf(formatted_message, sizeof(formatted_message), fmt, kernelFlag, res, funcName, formatted_args, formatted_reason);
894 Reporting::ReportMessageFormatted(key.c_str(), formatted_message);
895 }
896 }
897 }
898