IOS: Adjust IPC timing based on hardware tests

This adjusts IOS IPC timing to be closer to actual hardware:

* Emulate the IPC interrupt delay. On a real Wii, from the point of
  view of the PPC, the IPC interrupt appears to fire about 100 TB ticks
  after Y1/Y2 is seen.

* Fix the IPC acknowledgement delay. Dolphin was much, much too fast.

* Fix Device::GetDefaultReply to return more reasonable delays. Again,
  Dolphin was way too fast. We now use a more realistic, average reply
  time for most requests.

  Note: the previous result from https://dolp.in/pr6374 is flawed.
  GetTicketViews definitely takes more than 25µs to reply.
  The reason the reply delay was so low is because an invalid
  parameter was passed to the libogc wrapper, which causes it to
  immediately return an error code (-4100).

* Fix the response delay for various replies that come from the kernel:
  fd table full, unknown resource manager / device, invalid fd,
  unknown IPC command.

Source: https://github.com/leoetlino/hwtests/blob/af320e4/iostest/ipc_timing.cpp

Source/Core/Core/HW/WII_IPC.cpp

@@ -213,7 +213,9 @@ void GenerateAck(u32 _Address)
   ctrl.Y2 = 1;
   DEBUG_LOG(WII_IPC, "GenerateAck: %08x | %08x [R:%i A:%i E:%i]", ppc_msg, _Address, ctrl.Y1,
             ctrl.Y2, ctrl.X1);
-  CoreTiming::ScheduleEvent(1000, updateInterrupts, 0);
+  // Based on a hardware test, the IPC interrupt takes approximately 100 TB ticks to fire
+  // after Y2 is seen in the control register.
+  CoreTiming::ScheduleEvent(100 * SystemTimers::TIMER_RATIO, updateInterrupts);
 }
 
 void GenerateReply(u32 _Address)
@@ -222,7 +224,9 @@ void GenerateReply(u32 _Address)
   ctrl.Y1 = 1;
   DEBUG_LOG(WII_IPC, "GenerateReply: %08x | %08x [R:%i A:%i E:%i]", ppc_msg, _Address, ctrl.Y1,
             ctrl.Y2, ctrl.X1);
-  UpdateInterrupts();
+  // Based on a hardware test, the IPC interrupt takes approximately 100 TB ticks to fire
+  // after Y1 is seen in the control register.
+  CoreTiming::ScheduleEvent(100 * SystemTimers::TIMER_RATIO, updateInterrupts);
 }
 
 bool IsReady()

Source/Core/Core/IOS/Device.cpp

@@ -184,10 +184,18 @@ IPCCommandResult Device::Unsupported(const Request& request)
   return GetDefaultReply(IPC_EINVAL);
 }
 
-// Returns an IPCCommandResult for a reply that takes 25 us (based on ES::GetTicketViews)
+// Returns an IPCCommandResult for a reply with an average reply time for devices
+// Please avoid using this function if more accurate timings are known.
 IPCCommandResult Device::GetDefaultReply(const s32 return_value)
 {
-  return {return_value, true, SystemTimers::GetTicksPerSecond() / 40000};
+  // Based on a hardware test, a device takes at least ~2700 ticks to reply to an IPC request.
+  // Depending on how much work a command performs, this can take much longer (10000+)
+  // especially if the NAND filesystem is accessed.
+  //
+  // Because we currently don't emulate timing very accurately, we should not return
+  // the minimum possible reply time (~960 ticks from the kernel or ~2700 from devices)
+  // but an average time, otherwise we are going to be much too fast in most cases.
+  return {return_value, true, 4000 * SystemTimers::TIMER_RATIO};
 }
 
 // Returns an IPCCommandResult with no reply. Useful for async commands that will generate a reply

Source/Core/Core/IOS/IOS.cpp

@@ -475,7 +475,7 @@ IPCCommandResult Kernel::OpenDevice(OpenRequest& request)
   if (new_fd < 0 || new_fd >= IPC_MAX_FDS)
   {
     ERROR_LOG(IOS, "Couldn't get a free fd, too many open files");
-    return Device::Device::GetDefaultReply(FS_EFDEXHAUSTED);
+    return IPCCommandResult{FS_EFDEXHAUSTED, true, 5000 * SystemTimers::TIMER_RATIO};
   }
   request.fd = new_fd;
 
@@ -497,7 +497,7 @@ IPCCommandResult Kernel::OpenDevice(OpenRequest& request)
   if (!device)
   {
     ERROR_LOG(IOS, "Unknown device: %s", request.path.c_str());
-    return Device::Device::GetDefaultReply(IPC_ENOENT);
+    return {IPC_ENOENT, true, 3700 * SystemTimers::TIMER_RATIO};
   }
 
   IPCCommandResult result = device->Open(request);
@@ -511,6 +511,9 @@ IPCCommandResult Kernel::OpenDevice(OpenRequest& request)
 
 IPCCommandResult Kernel::HandleIPCCommand(const Request& request)
 {
+  if (request.command < IPC_CMD_OPEN || request.command > IPC_CMD_IOCTLV)
+    return IPCCommandResult{IPC_EINVAL, true, 978 * SystemTimers::TIMER_RATIO};
+
   if (request.command == IPC_CMD_OPEN)
   {
     OpenRequest open_request{request.address};
@@ -519,7 +522,7 @@ IPCCommandResult Kernel::HandleIPCCommand(const Request& request)
 
   const auto device = (request.fd < IPC_MAX_FDS) ? m_fdmap[request.fd] : nullptr;
   if (!device)
-    return Device::Device::GetDefaultReply(IPC_EINVAL);
+    return IPCCommandResult{IPC_EINVAL, true, 550 * SystemTimers::TIMER_RATIO};
 
   IPCCommandResult ret;
   u64 wall_time_before = Common::Timer::GetTimeUs();
@@ -547,7 +550,7 @@ IPCCommandResult Kernel::HandleIPCCommand(const Request& request)
     break;
   default:
     ASSERT_MSG(IOS, false, "Unexpected command: %x", request.command);
-    ret = Device::Device::GetDefaultReply(IPC_EINVAL);
+    ret = IPCCommandResult{IPC_EINVAL, true, 978 * SystemTimers::TIMER_RATIO};
     break;
   }
 
@@ -582,7 +585,11 @@ void Kernel::ExecuteIPCCommand(const u32 address)
 // Happens AS SOON AS IPC gets a new pointer!
 void Kernel::EnqueueIPCRequest(u32 address)
 {
-  CoreTiming::ScheduleEvent(1000, s_event_enqueue, address | ENQUEUE_REQUEST_FLAG);
+  // Based on hardware tests, IOS takes between 5µs and 10µs to acknowledge an IPC request.
+  // Console 1: 456 TB ticks before ACK
+  // Console 2: 658 TB ticks before ACK
+  CoreTiming::ScheduleEvent(500 * SystemTimers::TIMER_RATIO, s_event_enqueue,
+                            address | ENQUEUE_REQUEST_FLAG);
 }
 
 // Called to send a reply to an IOS syscall