From fa89614b076174e23aab747a229ae0cd5f736f9d Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?L=C3=A9o=20Lam?= Date: Sun, 25 Feb 2018 23:51:06 +0100 Subject: [PATCH 1/6] IOS: Adjust IPC timing based on hardware tests MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 | 8 ++++++-- Source/Core/Core/IOS/Device.cpp | 12 ++++++++++-- Source/Core/Core/IOS/IOS.cpp | 17 ++++++++++++----- 3 files changed, 28 insertions(+), 9 deletions(-) diff --git a/Source/Core/Core/HW/WII_IPC.cpp b/Source/Core/Core/HW/WII_IPC.cpp index 1e190f9ac0..ca5b15d7bf 100644 --- a/Source/Core/Core/HW/WII_IPC.cpp +++ b/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() diff --git a/Source/Core/Core/IOS/Device.cpp b/Source/Core/Core/IOS/Device.cpp index b0301205aa..d14c8cf06a 100644 --- a/Source/Core/Core/IOS/Device.cpp +++ b/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 diff --git a/Source/Core/Core/IOS/IOS.cpp b/Source/Core/Core/IOS/IOS.cpp index 975bdd8268..dda0ac955f 100644 --- a/Source/Core/Core/IOS/IOS.cpp +++ b/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 From 35e3775a7713a7d70b201f4edfc31bebfc535434 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?L=C3=A9o=20Lam?= Date: Sun, 25 Feb 2018 23:55:33 +0100 Subject: [PATCH 2/6] IOS: Remove outdated comment --- Source/Core/Core/IOS/IOS.cpp | 2 -- 1 file changed, 2 deletions(-) diff --git a/Source/Core/Core/IOS/IOS.cpp b/Source/Core/Core/IOS/IOS.cpp index dda0ac955f..90d63c0f4f 100644 --- a/Source/Core/Core/IOS/IOS.cpp +++ b/Source/Core/Core/IOS/IOS.cpp @@ -622,8 +622,6 @@ void Kernel::HandleIPCEvent(u64 userdata) UpdateIPC(); } -// This is called every IPC_HLE_PERIOD from SystemTimers.cpp -// Takes care of routing ipc <-> ipc HLE void Kernel::UpdateIPC() { if (!IsReady()) From b9f7d67667643bb237c313cbd80f3a688f5a04a3 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?L=C3=A9o=20Lam?= Date: Tue, 27 Feb 2018 15:57:07 +0100 Subject: [PATCH 3/6] IPC: Fix missing interrupt when writing to Y1/Y2 The IPC interrupt is triggered when IY1/IY2 is set and Y1/Y2 is written to even when this results in clearing the bit. This shouldn't change anything in practice but it's a difference that Dolphin wasn't taking into account, which made me waste some time when I was writing a hwtest :/ --- Source/Core/Core/HW/WII_IPC.cpp | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/Source/Core/Core/HW/WII_IPC.cpp b/Source/Core/Core/HW/WII_IPC.cpp index ca5b15d7bf..3ba154b46d 100644 --- a/Source/Core/Core/HW/WII_IPC.cpp +++ b/Source/Core/Core/HW/WII_IPC.cpp @@ -153,6 +153,10 @@ void RegisterMMIO(MMIO::Mapping* mmio, u32 base) mmio->Register(base | IPC_PPCCTRL, MMIO::ComplexRead([](u32) { return ctrl.ppc(); }), MMIO::ComplexWrite([](u32, u32 val) { ctrl.ppc(val); + // The IPC interrupt is triggered when IY1/IY2 is set and + // Y1/Y2 is written to -- even when this results in clearing the bit. + if ((val >> 2 & 1 && ctrl.IY1) || (val >> 1 & 1 && ctrl.IY2)) + ppc_irq_flags |= INT_CAUSE_IPC_BROADWAY; if (ctrl.X1) HLE::GetIOS()->EnqueueIPCRequest(ppc_msg); HLE::GetIOS()->UpdateIPC(); From 1a71076e50dbf4fd33fc5834cfc61367d5a19ea6 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?L=C3=A9o=20Lam?= Date: Wed, 28 Feb 2018 16:52:26 +0100 Subject: [PATCH 4/6] IPC: Remove incorrect guess about acks A very basic hardware test shows that the ARMMSG doesn't change until IOS replies. (People could have disassembled IOS to verify this too...) Console: sending request at 00034640 - ARMMSG 133e0fa0 00000000000000000000000000000010(ack) - ARMMSG 133e0fa0 00000000000000000000000000000100(reply) - ARMMSG 00034640 Dolphin, prior to this fix: sending request (00034640) - ARMMSG 133e0fa0 00000000000000000000000000000011(ack) - ARMMSG 00034640 00000000000000000000000000000100(reply) - ARMMSG 00034640 Dolphin, after this fix: sending request at 00034640 - ARMMSG 133e0fa0 00000000000000000000000000000011(ack) - ARMMSG 133e0fa0 00000000000000000000000000000100(reply) - ARMMSG 00034640 (Yes, note that the X1 bit is still set. This is a bug that I will fix in the next commit.) --- Source/Core/Core/HW/WII_IPC.cpp | 1 - 1 file changed, 1 deletion(-) diff --git a/Source/Core/Core/HW/WII_IPC.cpp b/Source/Core/Core/HW/WII_IPC.cpp index 3ba154b46d..5a60b0f04f 100644 --- a/Source/Core/Core/HW/WII_IPC.cpp +++ b/Source/Core/Core/HW/WII_IPC.cpp @@ -213,7 +213,6 @@ static void UpdateInterrupts(u64 userdata, s64 cyclesLate) void GenerateAck(u32 _Address) { - arm_msg = _Address; // dunno if it's really set here, but HLE needs to stay in context 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); From d029f2a7b6544933fcd35befceae456da29cf280 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?L=C3=A9o=20Lam?= Date: Wed, 28 Feb 2018 17:00:26 +0100 Subject: [PATCH 5/6] IPC: Clear X1 when acknowledging a reply Hardware tests indicate that IOS clears X1 when it acknowledges an IPC request. --- Source/Core/Core/HW/WII_IPC.cpp | 5 +++++ Source/Core/Core/HW/WII_IPC.h | 1 + Source/Core/Core/IOS/IOS.cpp | 1 + 3 files changed, 7 insertions(+) diff --git a/Source/Core/Core/HW/WII_IPC.cpp b/Source/Core/Core/HW/WII_IPC.cpp index 5a60b0f04f..d231adcfd2 100644 --- a/Source/Core/Core/HW/WII_IPC.cpp +++ b/Source/Core/Core/HW/WII_IPC.cpp @@ -211,6 +211,11 @@ static void UpdateInterrupts(u64 userdata, s64 cyclesLate) !!(ppc_irq_flags & ppc_irq_masks)); } +void ClearX1() +{ + ctrl.X1 = 0; +} + void GenerateAck(u32 _Address) { ctrl.Y2 = 1; diff --git a/Source/Core/Core/HW/WII_IPC.h b/Source/Core/Core/HW/WII_IPC.h index d97e7eab0c..34419b8988 100644 --- a/Source/Core/Core/HW/WII_IPC.h +++ b/Source/Core/Core/HW/WII_IPC.h @@ -42,6 +42,7 @@ void DoState(PointerWrap& p); void RegisterMMIO(MMIO::Mapping* mmio, u32 base); +void ClearX1(); void GenerateAck(u32 _Address); void GenerateReply(u32 _Address); diff --git a/Source/Core/Core/IOS/IOS.cpp b/Source/Core/Core/IOS/IOS.cpp index 90d63c0f4f..cd94693723 100644 --- a/Source/Core/Core/IOS/IOS.cpp +++ b/Source/Core/Core/IOS/IOS.cpp @@ -629,6 +629,7 @@ void Kernel::UpdateIPC() if (m_request_queue.size()) { + ClearX1(); GenerateAck(m_request_queue.front()); u32 command = m_request_queue.front(); m_request_queue.pop_front(); From a63aaeecee0d9a6c7b1670f9c77886c5ad44825a Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?L=C3=A9o=20Lam?= Date: Wed, 28 Feb 2018 19:49:05 +0100 Subject: [PATCH 6/6] IOS: Fix "kernel FD table full" error code --- Source/Core/Core/IOS/IOS.cpp | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/Source/Core/Core/IOS/IOS.cpp b/Source/Core/Core/IOS/IOS.cpp index cd94693723..4abd2312a5 100644 --- a/Source/Core/Core/IOS/IOS.cpp +++ b/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 IPCCommandResult{FS_EFDEXHAUSTED, true, 5000 * SystemTimers::TIMER_RATIO}; + return IPCCommandResult{IPC_EMAX, true, 5000 * SystemTimers::TIMER_RATIO}; } request.fd = new_fd;